Introduce logging functionality

[txgk]

Hello @adsr

Another PR from me. Please take a look when you have time :)

So currently there's no logging in termbox2 at all. I'd like to propose a simple implementation of logging functionality into the library to make it easier to maintain. Just to justify introduction of this functionality, here are my points regarding usual argument of bloat vs utility in this case:

• when user of application based on termbox2 reports a bug with interface failing to initialize, all what I can do as a maintainer of application is to ask them to debug termbox2 code on their side themselves via either debugger or manual printf logging (case study: https://codeberg.org/newsraft/newsraft/issues/212). This is not nice as it raises the required effort and time for bug reporting, which makes the user not want to reveal the problem fully, with a risk of losing sight of potential bugs that users did not want to spend too much of their time on;

• there are some places in the source code of termbox2 where errors can happen but they're not handled because their handling is too tedious and their possibility of occurrence is so negligible small that it's considered to never fail in this case anyways. But it still essential to at least have information about abnormal states like this. For example:

@@ -3464,7 +3474,9 @@ static int wait_event(struct tb_event *event, int timeout) {
 
         if (resize_has_events) {
             int ignore = 0;
-            read(global.resize_pipefd[0], &ignore, sizeof(ignore));
+            if (read(global.resize_pipefd[0], &ignore, sizeof(ignore)) < 0) {
+                tb_log("Couldn't read data from resize pipe even though file descriptor was set!");
+            }
             // TODO: Harden against errors encountered mid-resize
             if_err_return(rv, update_term_size());
             if_err_return(rv, resize_cellbufs());

@@ -3775,7 +3787,9 @@ static int resize_cellbufs(void) {
 
 static void handle_resize(int sig) {
     int errno_copy = errno;
-    write(global.resize_pipefd[1], &sig, sizeof(sig));
+    if (write(global.resize_pipefd[1], &sig, sizeof(sig)) < 0) {
+        tb_log("Couldn't write to resize pipe to notify about resize signal!");
+    }
     errno = errno_copy;
 }

By the way, currently these unhandled calls to read and write yield a warning when compiled with strict rules:

src/termbox2.h: In function ‘handle_resize’:
src/termbox2.h:3057:5: warning: ignoring return value of ‘write’ declared with attribute ‘warn_unused_result’ [-Wunused-result]
 3057 |     write(global.resize_pipefd[1], &sig, sizeof(sig));
      |     ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
src/termbox2.h: In function ‘wait_event’:
src/termbox2.h:2743:13: warning: ignoring return value of ‘read’ declared with attribute ‘warn_unused_result’ [-Wunused-result]
 2743 |             read(global.resize_pipefd[0], &ignore, sizeof(ignore));
      |             ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

• some places in code can be commented with log messages instead of comments. That obviously is more useful as it makes our precious context information be visible not just when reading the code but also when reading the logs after the incident of bug occurrence. For example:

@@ -3410,8 +3410,7 @@ static const char *get_terminfo_string(int16_t offsets_pos, int16_t offsets_len,
 
     int str_offset = (int)table_pos + (int)table_offset;
     if (str_offset >= (int)global.nterminfo) {
-        // string beyond end of terminfo entry
-        // Truncated/corrupt terminfo entry?
+        tb_log("Offset %d is beyond end of terminfo data. Is terminfo corrupted?", str_offset);
         return NULL;
     }

• it's just nice to have as much information about processes going on in termbox2 as possible when you go through another bug report. It's good to know that some subsystem of your application worked fine and there's a log message about it. This reduces the level of uncertainty when analyzing reports about bugs in your application and makes the maintenance of the application based on termbox2 much faster and easier (see point 1). Just look at this pretty:

[TERMBOX] Couldn't find term screen in terminfo database ./newsraft-test-terminfo
[TERMBOX] Couldn't find term screen in terminfo database /home/txgk/.terminfo
[TERMBOX] Couldn't find term screen in terminfo database /usr/local/etc/terminfo
[TERMBOX] Couldn't find term screen in terminfo database /usr/local/share/terminfo
[TERMBOX] Couldn't find term screen in terminfo database /usr/local/lib/terminfo
[TERMBOX] Couldn't find term screen in terminfo database /etc/terminfo
[TERMBOX] Successfully read terminfo from /usr/share/terminfo/s/screen (1607 bytes)

I most certainly missed some places worthy of logging with tb_log() but I believe it's best to first have the functionality introduced and then iteratively arrange log statements around the codebase based on the practical criticality of particular places in code. I'm open to suggestions where you'd also want to put tb_log() calls.

The patch I propose here is already present in Newsraft and works wonderful. Here's how it's used: https://codeberg.org/newsraft/newsraft/src/commit/fd4c58b9436d3f081c9c79025ebcc613dc2fc29b/src/interface.c#L44

Best regards, Grigory

[adsr]

Thank you @txgk. I'm not personally convinced as I think the debugging scenarios you illustrate could be investigated in higher fidelity via strace or dtrace. For example, the terminfo search routine is easy to pick out in strace output:

...
openat(AT_FDCWD, "/home/adam/.terminfo/x/xterm-256color", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/local/etc/terminfo/x/xterm-256color", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/local/share/terminfo/x/xterm-256color", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/local/lib/terminfo/x/xterm-256color", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/terminfo/x/xterm-256color", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/terminfo/x/xterm-256color", O_RDONLY) = 4
...

Of course strace doesn't come without cons. Your end-user may need to install the tool, and you'll collect more than just termbox syscalls, including maybe private things that the end-user shouldn't share. That latter can be somewhat mitigated by collecting only certain syscalls (e.g., -e trace=openat).

I'll leave this open for others to leave opinions.

[AnErrupTion]

I'm not personally convinced as I think the debugging scenarios you illustrate could be investigated in higher fidelity via strace or dtrace.

Some, but not all. For example, this is currently simply ignored even though it could potentially be useful to know:

@@ -3410,8 +3410,7 @@ static const char *get_terminfo_string(int16_t offsets_pos, int16_t offsets_len,
 
     int str_offset = (int)table_pos + (int)table_offset;
     if (str_offset >= (int)global.nterminfo) {
         // string beyond end of terminfo entry
         // Truncated/corrupt terminfo entry?
         return NULL;
     }

And while I haven't looked at the code extensively, I doubt this is the only place where this happens. This is where logging is useful, in my opinion.

Of course strace doesn't come without cons. Your end-user may need to install the tool, and you'll collect more than just termbox syscalls, including maybe private things that the end-user shouldn't share. That latter can be somewhat mitigated by collecting only certain syscalls (e.g., -e trace=openat).

Also, even if you manage to mitigate this fully (which I guess you could if you let the user go through the trace first to remove all occurences of things they don't want the developers to see), this'd be much more tedious for a user than just uploading a separate log file that they know only contains termbox2 logs. Just my 2 cents though.

[txgk]

Recently we have found another place worthy of logging to ease bug finding when handling user bug reports. The thing is that some terminal emulator setups start IO on /dev/tty before graphical window is actually drawn which makes obtaining terminal width/height prone to yielding zeroes. I believe that not all developers of terminal applications handle this special case of zero-size terminal and finding the reason why their app behaves strangely in this circumstance is not quite trivial (I was in this situation because I never had this problem occurred before). Fortunately, I've had a very dependable bug reporter, @BryceVandegrift, thanks to whom after several iterations we got to the essence of the problem - specifically because we had logs at the point of retrieving the terminal size (communication took place via email).

I am by no means saying that this problem couldn't be found using a more sophisticated debugging tool. I just sincerely believe that application users already have to overcome a lot within themselves just to write a bug report (I can easily relate that to myself). Additional requests to install gdb/strace/dtrace on their machine and learn how to use these tools to add context to the report not only slows down the entire feedback exchange process but also poses a risk of the bug not being fixed at all because the user could lose interest, while the issue was reproducible only on their end.

[adsr]

Thanks for the additional example. I remain on the fence about it, not because I don't think it's useful, but because I'm trying to keep a close guard on the API. As I've stated I have regrets about certain API additions I made several years back.

That said if it's broadly desired by library users, we should merge. Otherwise we should collect more feedback. termbox is a niche library, so it takes a while to collect feedback. This is why I've left tb_get_cell in PR for a year. (I think I'll merge that one soon as it's come up pretty consistently.)

In the mean time I'll offer some other alternatives. What do you think about controlling debug output via env var? Something like TB_DEBUG=1 ./program 2>tb.log or TB_DEBUG=1 TB_DEBUG_LOG_PATH=tb.log ./program.

Or as a compile-time option. With this route library users could swap in any function (similar to tb_malloc etc).

Coupled with either of the above, we could include a diagnostic tool in this repo that has logging explicitly enabled and exercises some basic library features. We could optionally host static binaries here so end-users don't have to install anything else to run them.

Thanks again @txgk.

[AnErrupTion]

Or as a compile-time option. With this route library users could swap in any function (similar to tb_malloc etc).

I like this solution, personally!

we could include a diagnostic tool

What would this tool be about, though? Would it allow redirecting termbox2 logs somewhere? If so, I'm not sure how that'd work for a compile-time option, given the library would likely be statically compiled into the application.

[txgk]

@adsr

Thanks for the additional example. I remain on the fence about it, not because I don't think it's useful, but because I'm trying to keep a close guard on the API. As I've stated I have regrets about certain API additions I made several years back.

I understand it and I'm not trying to push it just for the sake of it being added. I'm up for constructive discussion, of course! Just thought it'd be useful to provide one more use case in favor of this functionality :)

That said if it's broadly desired by library users, we should merge. Otherwise we should collect more feedback. termbox is a niche library, so it takes a while to collect feedback. This is why I've left tb_get_cell in PR for a year. (I think I'll merge that one soon as it's come up pretty consistently.)

I agree that this is a good strategy to adhere to for a library like termbox2. Perhaps we can request opinions from some recently active authors of termbox2-based apps from the examples list in README.md file.

In the mean time I'll offer some other alternatives. What do you think about controlling debug output via env var? Something like TB_DEBUG=1 ./program 2>tb.log or TB_DEBUG=1 TB_DEBUG_LOG_PATH=tb.log ./program.

This is not a very nice approach in my opinion as it doesn't allow for seamless integration with the existing logging system of the application. Limiting logging output to stderr or file forces user to do something like this:

TB_DEBUG=1 ./app --log=app.log 2>tb.log

TB_DEBUG_LOG_PATH=tb.log ./app --log=app.log

As a developer who reads the logs, I'd like to have a sequential chronology of events in the log, rather than two separate timelines stored in different files. Also, this reveals the intricacies of the logging internals to the user, making it harder to use for regular people.

Or as a compile-time option. With this route library users could swap in any function (similar to tb_malloc etc).

This I like more. In this PR it's done like this (logging function is set at runtime with tb_set_log_function() call):

--- a/termbox2.h
+++ b/termbox2.h
@@ -389,6 +389,8 @@ extern "C" {
 #define tb_free    free
 #endif
 
+#define tb_log(...) if (global.fn_print_log_msg) global.fn_print_log_msg(__VA_ARGS__)
+
 #if TB_OPT_ATTR_W == 64
 typedef uint64_t uintattr_t;
 #elif TB_OPT_ATTR_W == 32

but you may want to go static (logging function is set at compile-time with tb_log macro):

--- a/termbox2.h
+++ b/termbox2.h
@@ -389,7 +389,9 @@ extern "C" {
 #define tb_free    free
 #endif
 
+#ifndef tb_log
+#define tb_log(...)
+#endif
+
 #if TB_OPT_ATTR_W == 64
 typedef uint64_t uintattr_t;

Macro approach requires less code, but runtime approach makes logging configurable in cases when termbox2 is provided as a shared library, so I'm in favor of tb_set_log_function() here as it's more flexible. It's pity we already have this macro-based interface for overriding allocator as it makes it unconfigurable in shared library case.

Coupled with either of the above, we could include a diagnostic tool in this repo that has logging explicitly enabled and exercises some basic library features. We could optionally host static binaries here so end-users don't have to install anything else to run them.

I didn't understand the aim of this tool. I also didn't get why end-users would need binaries like that if all logging is configured in their applications individually. Can you elaborate?

Best regards, Grigory

[rofl0r]

Macro approach requires less code

it would also make the library slimmer by not including code and strings of the log calls if it's defined to e.g. #define tb_log(...) do {} while(0)

[adsr]

#127 proposes a new variadic init function tb_init_ex which we could extend to accept a log function, custom allocator functions, escape code handlers, etc without adding lots of setter functions to the API. We could also deprecate the other tb_init_* functions.