[debug] Optionally include file/line/function info when logging to stderr

When debugging usb-moded it is time consuming to find where the
various debug messages originate from.

When logging to stderr, prefix the messages with source code
position info similar as gcc uses for reporting compilation
issues. This allows browsing usb-moded code with jump to the
next error functionality available in many text editors.

Since the amount of information passed to logging functions
is significantly increased, check whether the message would
be emitted or not before evaluating formatting parameters etc.

Also make variables relating to logging level, type, etc
available only via accessor functions.
Signed-off-by: Simo Piiroinen <simo.piiroinen@jollamobile.com>

src/usb_moded-log.c

@@ -34,9 +34,10 @@
 
 #include "usb_moded-log.h"
 
-const char *log_name = "<unset>";
-int log_level = LOG_WARNING;
-int log_type  = LOG_TO_STDERR;
+static const char *log_name = "<unset>";
+static int log_level = LOG_WARNING;
+static int log_type  = LOG_TO_STDERR;
+static bool log_lineinfo = false;
 
 static char *strip(char *str)
 {
@@ -71,10 +72,10 @@ static void log_gettime(struct timeval *tv)
  * @param fmt The message to be logged
  * @param va The stdarg variable list
  */
-void log_emit_va(int lev, const char *fmt, va_list va)
+void log_emit_va(const char *file, const char *func, int line, int lev, const char *fmt, va_list va)
 {
 	int saved = errno;
-        if( log_level >= lev )
+        if( log_p(lev) )
         {
                 switch( log_type )
                 {
@@ -85,7 +86,15 @@ void log_emit_va(int lev, const char *fmt, va_list va)
 
                 case LOG_TO_STDERR:
 
-                        fprintf(stderr, "%s: ", log_name);
+                        if( log_get_lineinfo() ) {
+                                /* Use gcc error like prefix for logging so
+                                 * that logs can be analyzed with jump to
+                                 * line parsing  available in editors. */
+                                fprintf(stderr, "%s:%d: %s(): ", file, line, func);
+                        }
+                        else {
+                                fprintf(stderr, "%s: ", log_get_name());
+                        }
 
 #if LOG_ENABLE_TIMESTAMPS
                         {
@@ -102,12 +111,12 @@ void log_emit_va(int lev, const char *fmt, va_list va)
                                 static const char *tag = "U:";
                                 switch( lev )
                                 {
-                                case 2: tag = "C:"; break;
-                                case 3: tag = "E:"; break;
-                                case 4: tag = "W:"; break;
-                                case 5: tag = "N:"; break;
-                                case 6: tag = "I:"; break;
-                                case 7: tag = "D:"; break;
+                                case LOG_CRIT:    tag = "C:"; break;
+                                case LOG_ERR:     tag = "E:"; break;
+                                case LOG_WARNING: tag = "W:"; break;
+                                case LOG_NOTICE:  tag = "N:"; break;
+                                case LOG_INFO:    tag = "I:"; break;
+                                case LOG_DEBUG:   tag = "D:"; break;
                                 }
                                 fprintf(stderr, "%s ", tag);
                         }
@@ -129,18 +138,18 @@ void log_emit_va(int lev, const char *fmt, va_list va)
 	errno = saved;
 }
 
-void log_emit(int lev, const char *fmt, ...)
+void log_emit_real(const char *file, const char *func, int line, int lev, const char *fmt, ...)
 {
         va_list va;
         va_start(va, fmt);
-        log_emit_va(lev, fmt, va);
+        log_emit_va(file, func, line, lev, fmt, va);
         va_end(va);
 }
 
 void log_debugf(const char *fmt, ...)
 {
         /* This goes always to stderr */
-        if( log_type == LOG_TO_STDERR && log_level >= LOG_DEBUG )
+        if( log_type == LOG_TO_STDERR && log_p(LOG_DEBUG) )
         {
                 va_list va;
                 va_start(va, fmt);
@@ -148,25 +157,90 @@ void log_debugf(const char *fmt, ...)
                 va_end(va);
         }
 }
-/**
- * returns the currently set log level
+
+/** Get the currently set logging level
  *
- * @return The current log level
+ * @return The current logging level
  */
-inline int log_get_level(void)
+int log_get_level(void)
 {
         return log_level;
 }
 
-/* Set the log level
+/** Set the logging level
  *
- * @param The wanted log level
+ * @param lev  The wanted logging level
  */
-inline void log_set_level(int lev)
+void log_set_level(int lev)
 {
         log_level = lev;
 }
 
+/** Test if logging should be done at given level
+ *
+ * @param lev  The logging level to query
+ *
+ * @return true if logging in the given level is allowed, false otherwise
+ */
+bool log_p(int lev)
+{
+        return lev <= log_level;
+}
+
+/** Get the currently set logging type
+ *
+ * @return The current logging type
+ */
+int log_get_type(void)
+{
+        return log_type;
+}
+
+/* Set the logging type
+ *
+ * @param type  The wanted logging type
+ */
+void log_set_type(int type)
+{
+        log_type = type;
+}
+
+/** Get the currently set logging name
+ *
+ * @return The current logging name
+ */
+const char *log_get_name(void)
+{
+        return log_name;
+}
+
+/** Set the logging name
+ *
+ * @param name  The wanted logging name
+ */
+void log_set_name(const char *name)
+{
+        log_name = name;
+}
+
+/** Enable/disable the logging line info
+ *
+ * @param lineinfo  true to enable line info, false to disable
+ */
+void log_set_lineinfo(bool lineinfo)
+{
+        log_lineinfo = lineinfo;
+}
+
+/** Test if line info should be included in logging
+ *
+ * @return true when line info should be emitted, false otherwise
+ */
+bool log_get_lineinfo(void)
+{
+        return log_lineinfo;
+}
+
 /** Initialize logging */
 void log_init(void)
 {

src/usb_moded-log.h

@@ -20,6 +20,7 @@
   02110-1301 USA
 */
 
+#include <stdbool.h>
 #include <stdlib.h>
 #include <unistd.h>
 #include <stdio.h>
@@ -28,9 +29,6 @@
 #include <syslog.h>
 
 /* Logging functionality */
-extern const char *log_name;
-extern int log_level;
-extern int log_type;
 
 #define LOG_ENABLE_DEBUG      01
 #define LOG_ENABLE_TIMESTAMPS 01
@@ -45,25 +43,38 @@ enum
              
 void log_set_level(int lev); 
 int log_get_level(void);
+int log_get_type(void);
+void log_set_type(int type);
+const char *log_get_name(void);
+void log_set_name(const char *name);
+void log_set_lineinfo(bool lineinfo);
+bool log_get_lineinfo(void);
 
 void log_init(void);
-void log_emit_va(int lev, const char *fmt, va_list va);
-void log_emit(int lev, const char *fmt, ...) __attribute__((format(printf,2,3)));
+void log_emit_va(const char *file, const char *func, int line, int lev, const char *fmt, va_list va);
+void log_emit_real(const char *file, const char *func, int line, int lev, const char *fmt, ...) __attribute__((format(printf,5,6)));
 void log_debugf(const char *fmt, ...) __attribute__((format(printf,1,2)));
+bool log_p(int lev);
 
-#define log_crit(...)      log_emit(2, __VA_ARGS__)
-#define log_err(...)       log_emit(3, __VA_ARGS__)
-#define log_warning(...)   log_emit(4, __VA_ARGS__)
+#define log_emit(LEV, FMT, ARGS...) do {\
+        if( log_p(LEV) ) {\
+                log_emit_real(__FILE__,__FUNCTION__,__LINE__, LEV, FMT, ##ARGS);\
+        }\
+} while(0)
+
+#define log_crit(    FMT, ARGS...)   log_emit(LOG_CRIT,    FMT, ##ARGS)
+#define log_err(     FMT, ARGS...)   log_emit(LOG_ERR,     FMT, ##ARGS)
+#define log_warning( FMT, ARGS...)   log_emit(LOG_WARNING, FMT, ##ARGS)
 
 #if LOG_ENABLE_DEBUG
-# define log_notice(...)   log_emit(5, __VA_ARGS__)
-# define log_info(...)     log_emit(6, __VA_ARGS__)
-# define log_debug(...)    log_emit(7, __VA_ARGS__)
+# define log_notice( FMT, ARGS...)   log_emit(LOG_NOTICE,  FMT, ##ARGS)
+# define log_info(   FMT, ARGS...)   log_emit(LOG_INFO,    FMT, ##ARGS)
+# define log_debug(  FMT, ARGS...)   log_emit(LOG_DEBUG,   FMT, ##ARGS)
 #else
-# define log_notice(...)   do{}while(0)
-# define log_info(...)     do{}while(0)
-# define log_debug(...)    do{}while(0)
+# define log_notice( FMT, ARGS...)   do{}while(0)
+# define log_info(   FMT, ARGS...)   do{}while(0)
+# define log_debug(  FMT, ARGS...)   do{}while(0)
 
-# define log_debugf(...)   do{}while(0)
+# define log_debugf( FMT, ARGS...)   do{}while(0)
 #endif
 

src/usb_moded.c

@@ -70,10 +70,6 @@
 static int usb_moded_exitcode = EXIT_FAILURE;
 static GMainLoop *usb_moded_mainloop = NULL;
 
-extern const char *log_name;
-extern int log_level;
-extern int log_type;
-
 gboolean rescue_mode = FALSE;
 gboolean diag_mode = FALSE;
 gboolean hw_fallback = FALSE;
@@ -782,6 +778,7 @@ static void usage(void)
 		  "  -f,  --fallback	  \tassume always connected\n"
                   "  -s,  --force-syslog  \t\tlog to syslog\n"
                   "  -T,  --force-stderr  \t\tlog to stderr\n"
+                  "  -l,  --log-line-info \t\tlog to stderr and show origin of logging\n"
                   "  -D,  --debug	  \t\tturn on debug printing\n"
 		  "  -d,  --diag	  \t\tturn on diag mode\n"
                   "  -h,  --help          \t\tdisplay this help and exit\n"
@@ -1198,6 +1195,7 @@ int main(int argc, char* argv[])
                 { "fallback", no_argument, 0, 'd' },
                 { "force-syslog", no_argument, 0, 's' },
                 { "force-stderr", no_argument, 0, 'T' },
+                { "log-line-info", no_argument, 0, 'l' },
                 { "debug", no_argument, 0, 'D' },
                 { "diag", no_argument, 0, 'd' },
                 { "help", no_argument, 0, 'h' },
@@ -1209,14 +1207,14 @@ int main(int argc, char* argv[])
         };
 
 	log_init();
-	log_name = basename(*argv);
+	log_set_name(basename(*argv));
 
 	/* - - - - - - - - - - - - - - - - - - - *
 	 * OPTIONS
 	 * - - - - - - - - - - - - - - - - - - - */
 
 	 /* Parse the command-line options */
-        while ((opt = getopt_long(argc, argv, "aifsTDdhrnvm:", options, &opt_idx)) != -1)
+        while ((opt = getopt_long(argc, argv, "aifsTlDdhrnvm:", options, &opt_idx)) != -1)
 	{
                 switch (opt) 
 		{
@@ -1230,17 +1228,22 @@ int main(int argc, char* argv[])
 				hw_fallback = TRUE;
 				break;
 		        case 's':
-                        	log_type = LOG_TO_SYSLOG;
+                        	log_set_type(LOG_TO_SYSLOG);
                         	break;
 
                 	case 'T':
-                        	log_type = LOG_TO_STDERR;
+                        	log_set_type(LOG_TO_STDERR);
                         	break;
 
                 	case 'D':
-                        	log_level = LOG_DEBUG;
+                        	log_set_level(LOG_DEBUG);
                         	break;
 
+			case 'l':
+				log_set_type(LOG_TO_STDERR);
+				log_set_lineinfo(true);
+				break;
+
 			case 'd':
 				diag_mode = TRUE;
 				break;
@@ -1279,7 +1282,7 @@ int main(int argc, char* argv[])
 	 * - - - - - - - - - - - - - - - - - - - */
 
 	/* silence usb_moded_system() calls */
-	if(log_type != LOG_TO_STDERR && log_level != LOG_DEBUG )
+	if( log_get_type() != LOG_TO_STDERR && log_get_level() != LOG_DEBUG )
 	{
 		freopen("/dev/null", "a", stdout);
 		freopen("/dev/null", "a", stderr);