refactor: Add file/line to tox-bootstrapd stdout/stderr logging.

[iphydf]

Also, allow trace logging in bootstrapd (disabled by default, but enabled on the websockify docker image so we can debug things there).

---

This change is 

[codecov]

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 72.22%. Comparing base (7c9fa37) to head (8a4f72b).
Report is 16 commits behind head on master.

Additional details and impacted files

@@            Coverage Diff             @@
##           master    #2855      +/-   ##
==========================================
+ Coverage   72.14%   72.22%   +0.08%     
==========================================
  Files         152      153       +1     
  Lines       31182    31182              
==========================================
+ Hits        22496    22522      +26     
+ Misses       8686     8660      -26     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[nurupo]

Some notes on behavioral changes made by this PR:

1. MIN_LOGGER_LEVEL change

   before: -DMIN_LOGGER_LEVEL=DEBUG
   now: -DMIN_LOGGER_LEVEL=TRACE

   This enables trace logging in toxcore by default for everyone who uses that Dockerfile and the container image, which is published on our Dockerhub for users to use.

   Q1: What is the overhead of having trace logging always be enabled in toxcore? Is it safe to have trace logging always by enabled in toxcore on production bootstrap nodes, in comparison to enabling it only when debugging issues? As in, is it easier to DoS tox-bootstrapd with trace logging enabled? I do understand that tox-bootstrapd discards it unless --trace/-t is passed, so I'm not talking about DoS caused by log file writing or anything else inside tox-bootstrapd codebase, but rather about the code-paths taken within libtoxcore to produce the trace output when TRACE log level is enabled.

   Q2: Also, how well is toxcore with the trace level logging enabled is tested? Do our static and dynamic analyzers have the trace logging enabled?

2. stdout log output change

   before: "Info: Successfully added bootstrap node ..."
   now: "[15:02:46.433 UTC] (tox.bootstrap) config.c:444 : Info: Successfully added bootstrap node ..."

   Having source code : line number in non-trace output looks a bit weird. I have only seen it being used in other software when something fails, so in error (and maybe debug) outputs. Tough I'm not very opposed to this, so I let's keep it.

3. syslog

   before: It printed the trace toxcore output with -DMIN_LOGGER_LEVEL=TRACE
   now: It never prints the trace output

   Probably fine?

4. toxcore logger callback

   before: syslog log entries coming from toxcore were indicated in the way of %s:%u(%s)
   now: There is no way to differentiate between toxcore and tox-bootstrapd log entries in syslog

   Perhaps prefix syslog log entries with the category to be able to tell apart if it's tox-bootstrapd log entry or toxcore's? Or maybe even the whole (category) src:line shebang? I do see some log entries in my syslog that do similar, though as I mentioned in (2) - I only see it for failures:

   Jan 24 20:10:42 laptop avahi-daemon[729]: chroot.c: open() failed: No such file or directory
   Jan 24 20:10:43 laptop bluetoothd[877]: profiles/sap/server.c:sap_server_register() Sap driver initialization failed.
   Jan 24 20:10:44 laptop NetworkManager[688]: (src/core/devices/wifi/nm-device-wifi.c:3395):activation_success_handler: runtime check failed: (priv->current_ap)
   

   I have noticed that those also include function names, but our log entries don't - the func argument from toxcore's callback is ignored and LOG_WRITE doesn't record the function name. Maybe add the function names that and print "(category) src:line:function_name" or something like that?

5. tox-bootstrapd

   before: It disabled toxcore logging if MIN_LOGGER_LEVEL was set to above DEBUG (i.e. INFO, WARNING or ERROR). However, it had toxcore logging enabled by default as it was set to -DMIN_LOGGER_LEVEL=DEBUG
   now: Always has toxcore logging enabled up to and including MIN_LOGGER_LEVEL, except TRACE unless explicitly enabled at run-time and then for stdout only. Same default behavior though

   Probably fine.

[nurupo]

Actually, let me make these separate reviews instead of a single giant one, would be probably easier to track progress/replies.

[nurupo]

Reviewed 33 of 33 files at r1, all commit messages.
Reviewable status: 1 change requests, 0 of 1 approvals obtained (waiting on @iphydf)

---

other/bootstrap_daemon/src/log_backend_stdout.c line 54 at r1 (raw file):

// Output bootstrap node log messages in the standard Tox log format:
// [15:02:46.433 UTC] (tox.bootstrap) config.c:444 : Info: Successfully added bootstrap node ...

Before it was just "Info: Successfully added bootstrap node ...". Having source code : line number in non-trace output looks a bit weird. I have only seen it being used in other software when something fails, so in error (and maybe debug) outputs. Tough I'm not very opposed to this, so I guess let's keep it.

---

other/bootstrap_daemon/src/tox-bootstrapd.c line 206 at r1 (raw file):

                                    const char *func, const char *message, void *userdata)
{
    log_write(logger_level_to_log_level(level), "%s:%u(%s) %s\n", file, line, func, message);

Before, log entries coming from toxcore were indicated in the way of %s:%u(%s), but now there is no way to differentiate between toxcore and tox-bootstrapd log entries in syslog (you can in stdout as it prints the category).

Perhaps prefix syslog log entries with the category to be able to tell apart if it's tox-bootstrapd log entry or toxcore's? Or maybe even the whole (category) src:line shebang? I do see some log entries in my syslog that do similar, though as I mentioned in (2) - I only see it for failures:

Jan 24 20:10:42 laptop avahi-daemon[729]: chroot.c: open() failed: No such file or directory
Jan 24 20:10:43 laptop bluetoothd[877]: profiles/sap/server.c:sap_server_register() Sap driver initialization failed.
Jan 24 20:10:44 laptop NetworkManager[688]: (src/core/devices/wifi/nm-device-wifi.c:3395):activation_success_handler: runtime check failed: (priv->current_ap)

I have noticed that those also include function names, but our log entries don't - the func argument from toxcore's callback is ignored and LOG_WRITE doesn't record the function name. Maybe add the function names that and print "(category) src:line:function_name" or something like that?

---

other/bootstrap_daemon/src/log_backend_syslog.c line 56 at r1 (raw file):

    if (level == LOG_LEVEL_TRACE) {
        // Don't write trace messages to syslog.
        return;

I'm curious, any reason why we don't want to print trace log entries to syslog?

---

other/bootstrap_daemon/docker/Dockerfile line 42 at r1 (raw file):

  -DCMAKE_BUILD_TYPE=Release \
  -DFULLY_STATIC=ON \
  -DMIN_LOGGER_LEVEL=TRACE \

This enables trace logging in toxcore by default for everyone who uses that Dockerfile and the container image, which is published on our Dockerhub for users to use.

Q1: What is the overhead of having trace logging always be enabled in toxcore? Is it safe to have trace logging always by enabled in toxcore on production bootstrap nodes, in comparison to enabling it only when debugging issues? As in, is it easier to DoS tox-bootstrapd with trace logging enabled? I do understand that tox-bootstrapd discards it unless --trace/-t is passed, so I'm not talking about DoS caused by log file writing or anything else inside tox-bootstrapd codebase, but rather about the code-paths taken within libtoxcore to produce the trace output when TRACE log level is enabled.

Q2: Also, how well is toxcore with the trace level logging enabled is tested? Do our static and dynamic analyzers have the trace logging enabled?

[iphydf]

Reviewable status: 1 change requests, 0 of 1 approvals obtained (waiting on @nurupo)

---

other/bootstrap_daemon/docker/Dockerfile line 42 at r1 (raw file):

Previously, nurupo wrote…

This enables trace logging in toxcore by default for everyone who uses that Dockerfile and the container image, which is published on our Dockerhub for users to use.

Q1: What is the overhead of having trace logging always be enabled in toxcore? Is it safe to have trace logging always by enabled in toxcore on production bootstrap nodes, in comparison to enabling it only when debugging issues? As in, is it easier to DoS tox-bootstrapd with trace logging enabled? I do understand that tox-bootstrapd discards it unless --trace/-t is passed, so I'm not talking about DoS caused by log file writing or anything else inside tox-bootstrapd codebase, but rather about the code-paths taken within libtoxcore to produce the trace output when TRACE log level is enabled.

Q2: Also, how well is toxcore with the trace level logging enabled is tested? Do our static and dynamic analyzers have the trace logging enabled?

A1: The main overhead seems to be allocations, which #2857 has fixed.

A2: Very well tested. It's enabled on all CI tests, and I always run my qTox and toxic with trace logging enabled (filtered out by qtox and toxic).

---

other/bootstrap_daemon/src/log_backend_stdout.c line 54 at r1 (raw file):

Previously, nurupo wrote…

Before it was just "Info: Successfully added bootstrap node ...". Having source code : line number in non-trace output looks a bit weird. I have only seen it being used in other software when something fails, so in error (and maybe debug) outputs. Tough I'm not very opposed to this, so I guess let's keep it.

I guess we do see it in software sometimes (in your syslog example). I like this, and when people file bug reports with log outputs, this is quite helpful.

---

other/bootstrap_daemon/src/log_backend_syslog.c line 56 at r1 (raw file):

Previously, nurupo wrote…

I'm curious, any reason why we don't want to print trace log entries to syslog?

Removed. Now we do output it to syslog as well (with --trace).

---

other/bootstrap_daemon/src/tox-bootstrapd.c line 206 at r1 (raw file):

Previously, nurupo wrote…

Before, log entries coming from toxcore were indicated in the way of %s:%u(%s), but now there is no way to differentiate between toxcore and tox-bootstrapd log entries in syslog (you can in stdout as it prints the category).

Perhaps prefix syslog log entries with the category to be able to tell apart if it's tox-bootstrapd log entry or toxcore's? Or maybe even the whole (category) src:line shebang? I do see some log entries in my syslog that do similar, though as I mentioned in (2) - I only see it for failures:

Jan 24 20:10:42 laptop avahi-daemon[729]: chroot.c: open() failed: No such file or directory
Jan 24 20:10:43 laptop bluetoothd[877]: profiles/sap/server.c:sap_server_register() Sap driver initialization failed.
Jan 24 20:10:44 laptop NetworkManager[688]: (src/core/devices/wifi/nm-device-wifi.c:3395):activation_success_handler: runtime check failed: (priv->current_ap)

I have noticed that those also include function names, but our log entries don't - the func argument from toxcore's callback is ignored and LOG_WRITE doesn't record the function name. Maybe add the function names that and print "(category) src:line:function_name" or something like that?

I was trying to align it with the qTox log output, which doesn't output function names. What format would you like to see? We can't do file:line:function, because that breaks the format, but we could do file:line: Debug : (function) message.

[nurupo]

Reviewable status: 1 change requests, 0 of 1 approvals obtained (waiting on @iphydf)

---

other/bootstrap_daemon/src/tox-bootstrapd.c line 206 at r1 (raw file):

Previously, iphydf wrote…

I was trying to align it with the qTox log output, which doesn't output function names. What format would you like to see? We can't do file:line:function, because that breaks the format, but we could do file:line: Debug : (function) message.

I mainly just want users to be able to tell if it's tox-bootstrapd that generated the log entry or it's something within toxcore. Prefixing the log entry with the category would do the trick, but I'm open to other options.

Regarding including the function names, it's more if a wishlist item - just something I noticed other software do, and toxcore's logger callback already provides, we just ignore it when printing the log entries.

Regarding the format, file line function or maybe file function line, with whatever delimiters (looks like colon is a popular choice, with some tokens optionally enclosed in brackets or parentheses) seem the most logical to me. Sticking the verbosity level in the middle of the log message call site location, like in the suggested file:line: Debug : (function) message, while conveys the same information, doesn't look as good.

I'm not sure what "breaks the format" means. If it's that about qDebug(), its format can be tweaked via qSetMessagePattern() or QT_MESSAGE_PATTERN env variable. If it's about some log parsing tool, it could be made to expect an optional, or even required, function name. We are in control of these tools and we define the format, so it's whatever we want it to be. The "breaks the format" seems to actually mean "I don't want to add it to the format". If you think that adding function name to the log output provides no benefit then fine, I'm not gonna fight over it. It's more of a wishlist item anyway. I mainly just want to have the category be in the log output, the function name is whatever - just a nice to have.

[iphydf]

Reviewable status: 1 change requests, 0 of 1 approvals obtained (waiting on @nurupo)

---

other/bootstrap_daemon/src/tox-bootstrapd.c line 206 at r1 (raw file):

Previously, nurupo wrote…

I mainly just want users to be able to tell if it's tox-bootstrapd that generated the log entry or it's something within toxcore. Prefixing the log entry with the category would do the trick, but I'm open to other options.

Regarding including the function names, it's more if a wishlist item - just something I noticed other software do, and toxcore's logger callback already provides, we just ignore it when printing the log entries.

Regarding the format, file line function or maybe file function line, with whatever delimiters (looks like colon is a popular choice, with some tokens optionally enclosed in brackets or parentheses) seem the most logical to me. Sticking the verbosity level in the middle of the log message call site location, like in the suggested file:line: Debug : (function) message, while conveys the same information, doesn't look as good.

I'm not sure what "breaks the format" means. If it's that about qDebug(), its format can be tweaked via qSetMessagePattern() or QT_MESSAGE_PATTERN env variable. If it's about some log parsing tool, it could be made to expect an optional, or even required, function name. We are in control of these tools and we define the format, so it's whatever we want it to be. The "breaks the format" seems to actually mean "I don't want to add it to the format". If you think that adding function name to the log output provides no benefit then fine, I'm not gonna fight over it. It's more of a wishlist item anyway. I mainly just want to have the category be in the log output, the function name is whatever - just a nice to have.

Ok, done. Added category to the syslog output.

[nurupo]

Reviewed 3 of 3 files at r3, all commit messages.
Reviewable status: complete! 1 of 1 approvals obtained