POSIX: Improved logging

The warnx and warn calls map to PX4_WARN.
Calls to errx or err genrtate a compile error.

The px4_log.h file implements a new log format:

For DEBUG and INFO:
<level> <msg>

For ERROR and WARN:
<level> <msg> (file filepath line linenum)

The verbosity can be changed by setting the macro to use
either linux_log or linux_log_verbose in px4_log.h

Signed-off-by: Mark Charlebois <charlebm@gmail.com>

src/drivers/device/device_posix.cpp

@@ -83,7 +83,7 @@ Device::log(const char *fmt, ...)
 {
 	va_list	ap;
 
-	printf("[%s] ", _name);
+	PX4_INFO("[%s] ", _name);
 	va_start(ap, fmt);
 	vprintf(fmt, ap);
 	va_end(ap);

src/drivers/device/sim.cpp

@@ -63,7 +63,7 @@ SIM::SIM(const char *name,
 	_devname(devname)
 {
 
-	PX4_DBG("SIM::SIM name = %s devname = %s", name, devname);
+	PX4_DEBUG("SIM::SIM name = %s devname = %s", name, devname);
 	// fill in _device_id fields for a SIM device
 	_device_id.devid_s.bus_type = DeviceBusType_SIM;
 	_device_id.devid_s.bus = bus;
@@ -99,16 +99,16 @@ int
 SIM::transfer(const uint8_t *send, unsigned send_len, uint8_t *recv, unsigned recv_len)
 {
 	if (send_len > 0) {
-		PX4_DBG("SIM: sending %d bytes", send_len);
+		PX4_DEBUG("SIM: sending %d bytes", send_len);
 	}
 
 	if (recv_len > 0) {
-		PX4_DBG("SIM: receiving %d bytes", recv_len);
+		PX4_DEBUG("SIM: receiving %d bytes", recv_len);
 		
 		// TODO - write data to recv;
 	}
 
-	PX4_DBG("I2C SIM: transfer_4 on %s", _devname);
+	PX4_DEBUG("I2C SIM: transfer_4 on %s", _devname);
 
 	return PX4_OK;
 }

src/drivers/device/vdev.cpp

@@ -84,12 +84,14 @@ VDev::VDev(const char *name,
 	_registered(false),
 	_open_count(0)
 {
+	PX4_DEBUG("VDev::VDev");
 	for (unsigned i = 0; i < _max_pollwaiters; i++)
 		_pollset[i] = nullptr;
 }
 
 VDev::~VDev()
 {
+	PX4_DEBUG("VDev::~VDev");
 	if (_registered)
 		unregister_driver(_devname);
 }
@@ -97,6 +99,7 @@ VDev::~VDev()
 int
 VDev::register_class_devname(const char *class_devname)
 {
+	PX4_DEBUG("VDev::register_class_devname");
 	if (class_devname == nullptr) {
 		return -EINVAL;
 	}
@@ -121,6 +124,7 @@ VDev::register_class_devname(const char *class_devname)
 int
 VDev::register_driver(const char *name, void *data)
 {
+	PX4_DEBUG("VDev::register_driver");
 	int ret = -ENOSPC;
 
 	if (name == NULL || data == NULL)
@@ -136,7 +140,7 @@ VDev::register_driver(const char *name, void *data)
 	for (int i=0;i<PX4_MAX_DEV; ++i) {
 		if (devmap[i] == NULL) {
 			devmap[i] = new px4_dev_t(name, (void *)data);
-			debug("Registered DEV %s", name);
+			PX4_DEBUG("Registered DEV %s", name);
 			ret = PX4_OK;
 			break;
 		}
@@ -147,6 +151,7 @@ VDev::register_driver(const char *name, void *data)
 int
 VDev::unregister_driver(const char *name)
 {
+	PX4_DEBUG("VDev::unregister_driver");
 	int ret = -ENOSPC;
 
 	if (name == NULL)
@@ -156,7 +161,7 @@ VDev::unregister_driver(const char *name)
 		if (devmap[i] && (strcmp(name, devmap[i]->name) == 0)) {
 			delete devmap[i];
 			devmap[i] = NULL;
-			debug("Unregistered DEV %s", name);
+			PX4_DEBUG("Unregistered DEV %s", name);
 			ret = PX4_OK;
 			break;
 		}
@@ -167,12 +172,13 @@ VDev::unregister_driver(const char *name)
 int
 VDev::unregister_class_devname(const char *class_devname, unsigned class_instance)
 {
+	PX4_DEBUG("VDev::unregister_class_devname");
 	char name[32];
 	snprintf(name, sizeof(name), "%s%u", class_devname, class_instance);
 	for (int i=0;i<PX4_MAX_DEV; ++i) {
 		if (devmap[i] && strcmp(devmap[i]->name,name) == 0) {
 			delete devmap[i];
-			debug("Unregistered class DEV %s", name);
+			PX4_DEBUG("Unregistered class DEV %s", name);
 			devmap[i] = NULL;
 			return PX4_OK;
 		}
@@ -183,6 +189,8 @@ VDev::unregister_class_devname(const char *class_devname, unsigned class_instanc
 int
 VDev::init()
 {
+	PX4_DEBUG("VDev::init");
+
 	// base class init first
 	int ret = Device::init();
 
@@ -209,9 +217,9 @@ out:
 int
 VDev::open(file_t *filep)
 {
+	PX4_DEBUG("VDev::open");
 	int ret = PX4_OK;
 
-	debug("VDev::open");
 	lock();
 	/* increment the open count */
 	_open_count++;
@@ -233,14 +241,14 @@ VDev::open(file_t *filep)
 int
 VDev::open_first(file_t *filep)
 {
-	debug("VDev::open_first");
+	PX4_DEBUG("VDev::open_first");
 	return PX4_OK;
 }
 
 int
 VDev::close(file_t *filep)
 {
-	debug("VDev::close");
+	PX4_DEBUG("VDev::close");
 	int ret = PX4_OK;
 
 	lock();
@@ -265,36 +273,37 @@ VDev::close(file_t *filep)
 int
 VDev::close_last(file_t *filep)
 {
-	debug("VDev::close_last");
+	PX4_DEBUG("VDev::close_last");
 	return PX4_OK;
 }
 
 ssize_t
 VDev::read(file_t *filep, char *buffer, size_t buflen)
 {
-	debug("VDev::read");
+	PX4_DEBUG("VDev::read");
 	return -ENOSYS;
 }
 
 ssize_t
 VDev::write(file_t *filep, const char *buffer, size_t buflen)
 {
-	debug("VDev::write");
+	PX4_DEBUG("VDev::write");
 	return -ENOSYS;
 }
 
 off_t
 VDev::seek(file_t *filep, off_t offset, int whence)
 {
+	PX4_DEBUG("VDev::seek");
 	return -ENOSYS;
 }
 
 int
 VDev::ioctl(file_t *filep, int cmd, unsigned long arg)
 {
+	PX4_DEBUG("VDev::ioctl");
 	int ret = -ENOTTY;
 
-	debug("VDev::ioctl");
 	switch (cmd) {
 
 		/* fetch a pointer to the driver's private data */
@@ -311,7 +320,7 @@ VDev::ioctl(file_t *filep, int cmd, unsigned long arg)
 		break;
         case DEVIOCGDEVICEID:
                 ret = (int)_device_id.devid;
-		printf("IOCTL DEVIOCGDEVICEID %d\n", ret);
+		PX4_INFO("IOCTL DEVIOCGDEVICEID %d", ret);
 	default:
 		break;
 	}
@@ -322,8 +331,8 @@ VDev::ioctl(file_t *filep, int cmd, unsigned long arg)
 int
 VDev::poll(file_t *filep, px4_pollfd_struct_t *fds, bool setup)
 {
+	PX4_DEBUG("VDev::Poll %s", setup ? "setup" : "teardown");
 	int ret = PX4_OK;
-	debug("VDev::Poll %s", setup ? "setup" : "teardown");
 
 	/*
 	 * Lock against pollnotify() (and possibly other callers)
@@ -336,7 +345,7 @@ VDev::poll(file_t *filep, px4_pollfd_struct_t *fds, bool setup)
 		 * benefit.
 		 */
 		fds->priv = (void *)filep;
-		debug("VDev::poll: fds->priv = %p", filep);
+		PX4_DEBUG("VDev::poll: fds->priv = %p", filep);
 
 		/*
 		 * Handle setup requests.
@@ -371,7 +380,7 @@ VDev::poll(file_t *filep, px4_pollfd_struct_t *fds, bool setup)
 void
 VDev::poll_notify(pollevent_t events)
 {
-	debug("VDev::poll_notify events = %0x", events);
+	PX4_DEBUG("VDev::poll_notify events = %0x", events);
 
 	/* lock against poll() as well as other wakeups */
 	lock();
@@ -386,14 +395,14 @@ VDev::poll_notify(pollevent_t events)
 void
 VDev::poll_notify_one(px4_pollfd_struct_t *fds, pollevent_t events)
 {
-	debug("VDev::poll_notify_one");
+	PX4_DEBUG("VDev::poll_notify_one");
 	int value;
 	sem_getvalue(fds->sem, &value);
 
 	/* update the reported event set */
 	fds->revents |= fds->events & events;
 
-	debug(" Events fds=%p %0x %0x %0x %d",fds, fds->revents, fds->events, events, value);
+	PX4_DEBUG(" Events fds=%p %0x %0x %0x %d",fds, fds->revents, fds->events, events, value);
 
 	/* if the state is now interesting, wake the waiter if it's still asleep */
 	/* XXX semcount check here is a vile hack; counting semphores should not be abused as cvars */
@@ -404,7 +413,7 @@ VDev::poll_notify_one(px4_pollfd_struct_t *fds, pollevent_t events)
 pollevent_t
 VDev::poll_state(file_t *filep)
 {
-	debug("VDev::poll_notify");
+	PX4_DEBUG("VDev::poll_notify");
 	/* by default, no poll events to report */
 	return 0;
 }
@@ -415,7 +424,7 @@ VDev::store_poll_waiter(px4_pollfd_struct_t *fds)
 	/*
 	 * Look for a free slot.
 	 */
-	debug("VDev::store_poll_waiter");
+	PX4_DEBUG("VDev::store_poll_waiter");
 	for (unsigned i = 0; i < _max_pollwaiters; i++) {
 		if (nullptr == _pollset[i]) {
 
@@ -432,7 +441,7 @@ VDev::store_poll_waiter(px4_pollfd_struct_t *fds)
 int
 VDev::remove_poll_waiter(px4_pollfd_struct_t *fds)
 {
-	debug("VDev::remove_poll_waiter");
+	PX4_DEBUG("VDev::remove_poll_waiter");
 	for (unsigned i = 0; i < _max_pollwaiters; i++) {
 		if (fds == _pollset[i]) {
 
@@ -442,13 +451,13 @@ VDev::remove_poll_waiter(px4_pollfd_struct_t *fds)
 		}
 	}
 
-	puts("poll: bad fd state");
+	PX4_WARN("poll: bad fd state");
 	return -EINVAL;
 }
 
 VDev *VDev::getDev(const char *path)
 {
-	printf("VDev::getDev\n");
+	PX4_DEBUG("VDev::getDev");
 	int i=0;
 	for (; i<PX4_MAX_DEV; ++i) {
 		//if (devmap[i]) {
@@ -464,7 +473,7 @@ VDev *VDev::getDev(const char *path)
 void VDev::showDevices()
 {
 	int i=0;
-	printf("Devices:\n");
+	PX4_INFO("Devices:\n");
 	for (; i<PX4_MAX_DEV; ++i) {
 		if (devmap[i] && strncmp(devmap[i]->name, "/dev/", 5) == 0) {
 			printf("   %s\n", devmap[i]->name);
@@ -475,7 +484,7 @@ void VDev::showDevices()
 void VDev::showTopics()
 {
 	int i=0;
-	printf("Devices:\n");
+	PX4_INFO("Devices:\n");
 	for (; i<PX4_MAX_DEV; ++i) {
 		if (devmap[i] && strncmp(devmap[i]->name, "/obj/", 5) == 0) {
 			printf("   %s\n", devmap[i]->name);
@@ -486,7 +495,7 @@ void VDev::showTopics()
 void VDev::showFiles()
 {
 	int i=0;
-	printf("Files:\n");
+	PX4_INFO("Files:\n");
 	for (; i<PX4_MAX_DEV; ++i) {
 		if (devmap[i] && strncmp(devmap[i]->name, "/obj/", 5) != 0 &&
 				 strncmp(devmap[i]->name, "/dev/", 5) != 0) {

src/drivers/device/vdev_posix.cpp

@@ -71,7 +71,7 @@ static void *timer_handler(void *data)
 	usleep(td->ts.tv_nsec/1000);
 	sem_post(&(td->sem));
 
-	PX4_DEBUG("timer_handler: Timer expired\n");
+	PX4_DEBUG("timer_handler: Timer expired");
 	return 0;
 }
 
@@ -87,7 +87,7 @@ inline bool valid_fd(int fd)
 
 int px4_open(const char *path, int flags, ...)
 {
-	printf("px4_open\n");
+	PX4_DEBUG("px4_open");
 	VDev *dev = VDev::getDev(path);
 	int ret = 0;
 	int i;
@@ -103,7 +103,7 @@ int px4_open(const char *path, int flags, ...)
 		va_end(p);
 
 		// Create the file
-		warnx("Creating virtual file %s\n", path);
+		PX4_DEBUG("Creating virtual file %s", path);
 		dev = VFile::createFile(path, mode);
 	}
 	if (dev) {
@@ -136,7 +136,7 @@ int px4_close(int fd)
 	int ret;
 	if (valid_fd(fd)) {
 		VDev *dev = (VDev *)(filemap[fd]->vdev);
-		PX4_DEBUG("px4_close fd = %d\n", fd);
+		PX4_DEBUG("px4_close fd = %d", fd);
 		ret = dev->close(filemap[fd]);
 		filemap[fd] = NULL;
 	}
@@ -155,7 +155,7 @@ ssize_t px4_read(int fd, void *buffer, size_t buflen)
 	int ret;
 	if (valid_fd(fd)) {
 		VDev *dev = (VDev *)(filemap[fd]->vdev);
-		PX4_DEBUG("px4_read fd = %d\n", fd);
+		PX4_DEBUG("px4_read fd = %d", fd);
 		ret = dev->read(filemap[fd], (char *)buffer, buflen);
 	}
 	else { 
@@ -173,7 +173,7 @@ ssize_t px4_write(int fd, const void *buffer, size_t buflen)
 	int ret;
         if (valid_fd(fd)) {
 		VDev *dev = (VDev *)(filemap[fd]->vdev);
-		PX4_DEBUG("px4_write fd = %d\n", fd);
+		PX4_DEBUG("px4_write fd = %d", fd);
 		ret = dev->write(filemap[fd], (const char *)buffer, buflen);
 	}
 	else { 
@@ -188,7 +188,7 @@ ssize_t px4_write(int fd, const void *buffer, size_t buflen)
 
 int px4_ioctl(int fd, int cmd, unsigned long arg)
 {
-	PX4_DEBUG("px4_ioctl fd = %d\n", fd);
+	PX4_DEBUG("px4_ioctl fd = %d", fd);
 	int ret = 0;
         if (valid_fd(fd)) {
 		VDev *dev = (VDev *)(filemap[fd]->vdev);
@@ -212,7 +212,7 @@ int px4_poll(px4_pollfd_struct_t *fds, nfds_t nfds, int timeout)
 	unsigned int i;
 	struct timespec ts;
 
-	PX4_DEBUG("Called px4_poll timeout = %d\n", timeout);
+	PX4_DEBUG("Called px4_poll timeout = %d", timeout);
 	sem_init(&sem, 0, 0);
 
 	// For each fd 
@@ -226,7 +226,7 @@ int px4_poll(px4_pollfd_struct_t *fds, nfds_t nfds, int timeout)
 		if (valid_fd(fds[i].fd))
 		{
 			VDev *dev = (VDev *)(filemap[fds[i].fd]->vdev);;
-			PX4_DEBUG("px4_poll: VDev->poll(setup) %d\n", fds[i].fd);
+			PX4_DEBUG("px4_poll: VDev->poll(setup) %d", fds[i].fd);
 			ret = dev->poll(filemap[fds[i].fd], &fds[i], true);
 
 			if (ret < 0)
@@ -270,7 +270,7 @@ int px4_poll(px4_pollfd_struct_t *fds, nfds_t nfds, int timeout)
 			if (valid_fd(fds[i].fd))
 			{
 				VDev *dev = (VDev *)(filemap[fds[i].fd]->vdev);;
-				PX4_DEBUG("px4_poll: VDev->poll(teardown) %d\n", fds[i].fd);
+				PX4_DEBUG("px4_poll: VDev->poll(teardown) %d", fds[i].fd);
 				ret = dev->poll(filemap[fds[i].fd], &fds[i], false);
 	
 				if (ret < 0)