Add optional logging to a log file for debugging purposes

[Adda0]

Problem

If any errors occur, it is important to have a good debugging tools to identify the issue and be able to find a solution as quickly as possible.

Issue #41 shows that we lack such tools as of now, which would allow our users to easily send us reliable and useful information about the bugs they encounter.

Solution

We should have a new application mode (verbose, debug or something similar). This debug mode would, except for a normal handling of key events, output every such operation in a nicely formatted way to a log file. The log file would provide a debugging information which could be shared with the developers to make their life easier when trying to fix an issue.

The basics are already present in the code in a form of commented out prints (e.g., this or this one). These prints should be redirected to a log file, and other prints could be added to provide even more information about the state of the program.

Of course, such verbose logging should be active only when specifically requested by the user when they run into any issues. I believe the logging mode could be activated by a specific parameter passed to make or even as a parameter passed to systemctl. Other variants are possible as well.

Steps

• Add debug prints,
• Create log file if needed,
• Specify a way of activating and deactivating verbose logging mode and
• Redirect logs to a log file.

[donniebreve]

I'm on board. I think this has to be a configuration file option if we want users to be able to take advantage of it. Trying to explain to people to recompile might be tough. That means all the logging will probably be wrapped in if statements.

[Adda0]

I think this has to be a configuration file option

I agree that this sounds better from a usability perspective of the user. However, if the bug is in the config file itself (or earlier in the initialization process of the service), the logging configuration option might not be read properly (due to config parsing problems and/or key binding issues).

This would work if the logging was active by default and the option in the config file was merely turning it off again. This is not a well-designed solution, though.

Ideally, we need to be able to turn logging on independently of everything else, especially everything which can be changed by the users and as soon as possible in the initialization process, to be able to log bugs early on after the service starts. It could be even set as an environment variable, for example. But for this reason, I like the systemctl parameter option the most. It would be added to the systemctl --user restart touchcursor.service command.

I think we need to think about this a bit, consider our options. For now, config file parameter might be the simplest solution for both users and development.

[donniebreve]

Env variable or systemctl command line argument (not sure if that's possible) are fine as well.

[auouymous]

The following patch implements debug logging. make DEBUG=0 builds a binary without any support for those who want the lowest input latency. make DEBUG=1 builds a binary with debugging forced on for developers. With neither of those make flags, exporting TOUCHCURSOR_DEBUGGING to environment will turn it on at runtime. This patch doesn't implement it, but it would also be possible to have SIGUSR1 toggle enable_debugging. Then pkill -USR1 /usr/bin/touchcursor could be used to toggle debugging without restarting touchcursor.

There are only a few sample debug lines, more would need to be added to make it useful.

diff --git a/Makefile b/Makefile
index 45fe99d..45fa668 100644
--- a/Makefile
+++ b/Makefile
@@ -3,6 +3,16 @@ INSTALLPATH ?= /usr/bin
 SERVICEPATH ?= $(HOME)/.config/systemd/user
 CONFIGPATH ?= $(HOME)/.config/touchcursor
 
+make_flags = 
+ifeq ($(DEBUG),1)
+	# Force logging of debug information, overriding runtime settings
+	make_flags := $(make_flags) -DFORCE_DEBUG
+endif
+ifeq ($(DEBUG),0)
+	# Remove support for runtime logging of debug information
+	make_flags := $(make_flags) -DDISABLE_DEBUG
+endif
+
 # Application variables
 service = touchcursor.service
 config = touchcursor.conf
@@ -31,7 +41,7 @@ $(out_path)/$(binary): $(objects)
 # Each .o file depends on its .c file and .h file (we include all headers)
 $(obj_path)/%.o: $(src_path)/%.c $(headers)
 	@mkdir --parents $(obj_path)
-	$(cc) $(cflags) -c $< -o $@
+	$(cc) $(cflags) $(make_flags) -c $< -o $@
 
 clean:
 	-rm --force obj/*.o
diff --git a/src/buffers.c b/src/buffers.c
new file mode 100644
index 0000000..8f68112
--- /dev/null
+++ b/src/buffers.c
@@ -0,0 +1 @@
+int enable_debugging = 0;
diff --git a/src/buffers.h b/src/buffers.h
index 0f48e63..012ee94 100644
--- a/src/buffers.h
+++ b/src/buffers.h
@@ -11,4 +11,25 @@
     fprintf(stderr, __VA_ARGS__); \
     fflush(stderr);
 
+#if defined(DISABLE_DEBUG)
+#define debug(...)
+#elif defined(FORCE_DEBUG)
+#define debug(...)                         \
+    fprintf(stderr, "debug: "__VA_ARGS__); \
+    fflush(stderr);
+#else
+#define debug(...)                             \
+    if (enable_debugging)                      \
+    {                                          \
+        fprintf(stderr, "debug: "__VA_ARGS__); \
+        fflush(stderr);                        \
+    }
+#endif
+
+/**
+ * Enables runtime debugging logs.
+ * Ignored if built with DEBUG or NODEBUG.
+ * */
+extern int enable_debugging;
+
 #endif
diff --git a/src/main.c b/src/main.c
index 2911a24..7420c16 100644
--- a/src/main.c
+++ b/src/main.c
@@ -187,6 +187,14 @@ static void clean_up()
  * */
 int main(int argc, char* argv[])
 {
+    if (getenv("TOUCHCURSOR_DEBUGGING") != NULL)
+    {
+        enable_debugging = 1;
+#if defined(DISABLE_DEBUG)
+        error("error: TOUCHCURSOR_DEBUGGING was disabled by build system\n");
+#endif
+    }
+
     main_thread_identifier = pthread_self();
     if (attach_signal_handlers() != EXIT_SUCCESS)
     {
diff --git a/src/mapper.c b/src/mapper.c
index 90d3b2b..f5c785e 100644
--- a/src/mapper.c
+++ b/src/mapper.c
@@ -2,6 +2,7 @@
 #include <linux/uinput.h>
 #include <stdio.h>
 
+#include "buffers.h"
 #include "config.h"
 #include "emit.h"
 #include "keys.h"
@@ -94,6 +95,7 @@ void processKey(int type, int code, int value)
         {
             if (isHyper(code) && isDown(value))
             {
+                debug("hyper key %s in idle state\n", (value ? "PRESSED" : "RELEASED"));
                 state = hyper;
                 hyperEmitted = 0;
                 clearQueue();
@@ -108,6 +110,7 @@ void processKey(int type, int code, int value)
         {
             if (isHyper(code))
             {
+                debug("hyper key %s in hyper state\n", (value ? "PRESSED" : "RELEASED"));
                 if (!isDown(value))
                 {
                     state = idle;
@@ -120,6 +123,7 @@ void processKey(int type, int code, int value)
             }
             else if (isMapped(code))
             {
+                debug("mapped key %d %s in hyper state\n", code, (value ? "PRESSED" : "RELEASED"));
                 if (isDown(value))
                 {
                     state = delay;
@@ -148,6 +152,7 @@ void processKey(int type, int code, int value)
         {
             if (isHyper(code))
             {
+                debug("hyper key %s in delay state\n", (value ? "PRESSED" : "RELEASED"));
                 if (!isDown(value))
                 {
                     state = idle;
@@ -161,6 +166,7 @@ void processKey(int type, int code, int value)
             }
             else if (isMapped(code))
             {
+                debug("mapped key %d %s in delay state\n", code, (value ? "PRESSED" : "RELEASED"));
                 state = map;
                 if (isDown(value))
                 {
@@ -188,6 +194,7 @@ void processKey(int type, int code, int value)
         {
             if (isHyper(code))
             {
+                debug("hyper key %s in map state\n", (value ? "PRESSED" : "RELEASED"));
                 if (!isDown(value))
                 {
                     state = idle;
@@ -196,6 +203,7 @@ void processKey(int type, int code, int value)
             }
             else if (isMapped(code))
             {
+                debug("mapped key %d %s in map state\n", code, (value ? "PRESSED" : "RELEASED"));
                 if (isDown(value))
                 {
                     enqueue(code);

[auouymous]

I forgot to mention that the patch automatically prepends "debug: " to messages, is there a reason warn() and error() don't do that?