Feature bootstrap trace/debug log output by cotox · Pull Request #895 · TokTok/c-toxcore

cotox · 2018-05-21T17:53:38Z

A meanful logger for bootstrap. It outputs trace or debug log only.

Build with default options, the bootstrap outputs nothing more.

Build with DEBUG=ON, tox-bootstrapd outputs as,

Running "tox-bootstrapd" version 2016010100.
Successfully read:
...
General config read successfully
[DEBUG] /home/cotox/tox-stuff/c-toxcore/toxcore/network.c:959(new_networking_ex) Bound successfully to 0.0.0.0:33445
Set MOTD successfully.
Keys are managed successfully.
Initialized Tox TCP server successfully.
Successfully added bootstrap node #0: node.tox.biribiri.org:33445 F404ABAA1C99A9D37D61AB54898F56793E1DEF8BD46B1038B9D822E8460FAB67
List of bootstrap nodes read successfully.
Public Key: F5B0095E6C4AD95A3C1B87C452DF6427C3CB2D2A12135B9EBDDE1A979668811E
Initialized LAN discovery successfully.
Connected to another bootstrap node successfully.
[ERROR] /home/cotox/tox-stuff/c-toxcore/toxcore/network.c:562(sendpacket) attempted to send message with network family 0 (probably IPv6) on IPv4 socket
[ERROR] /home/cotox/tox-stuff/c-toxcore/toxcore/network.c:562(sendpacket) attempted to send message with network family 0 (probably IPv6) on IPv4 socket
[ERROR] /home/cotox/tox-stuff/c-toxcore/toxcore/network.c:562(sendpacket) attempted to send message with network family 0 (probably IPv6) on IPv4 socket
...

Build with TRACE=ON, tox-bootstrapd outputs as,

Running "tox-bootstrapd" version 2016010100.
Successfully read:
...
General config read successfully
[DEBUG] /home/cotox/tox-stuff/c-toxcore/toxcore/network.c:959(new_networking_ex) Bound successfully to 0.0.0.0:33445
Set MOTD successfully.
Keys are managed successfully.
Initialized Tox TCP server successfully.
[TRACE] /home/cotox/tox-stuff/c-toxcore/toxcore/network.c:515(loglogdata) [ 2] O=> 113= 67.215.253.85:33445 (0: OK) | f5b0095e6c4ad95a
Successfully added bootstrap node #0: node.tox.biribiri.org:33445 F404ABAA1C99A9D37D61AB54898F56793E1DEF8BD46B1038B9D822E8460FAB67
List of bootstrap nodes read successfully.
Public Key: F5B0095E6C4AD95A3C1B87C452DF6427C3CB2D2A12135B9EBDDE1A979668811E
Initialized LAN discovery successfully.
[TRACE] /home/cotox/tox-stuff/c-toxcore/toxcore/network.c:515(loglogdata) [33] O=>  33= 192.168.0.255:33445 (0: OK) | f5b0095e6c4ad95a
[TRACE] /home/cotox/tox-stuff/c-toxcore/toxcore/network.c:515(loglogdata) [33] O=>  33= 172.17.255.255:33445 (0: OK) | f5b0095e6c4ad95a
[TRACE] /home/cotox/tox-stuff/c-toxcore/toxcore/network.c:515(loglogdata) [33] O=>  33= 192.168.100.255:33445 (0: OK) | f5b0095e6c4ad95a
[TRACE] /home/cotox/tox-stuff/c-toxcore/toxcore/network.c:515(loglogdata) [33] O=>  33= 192.168.122.255:33445 (0: OK) | f5b0095e6c4ad95a
[TRACE] /home/cotox/tox-stuff/c-toxcore/toxcore/network.c:515(loglogdata) [33] O=>  33= 255.255.255.255:33445 (0: OK) | f5b0095e6c4ad95a
[TRACE] /home/cotox/tox-stuff/c-toxcore/toxcore/network.c:515(loglogdata) [33] =>O  33< 192.168.0.63:33445 (0: OK) | f5b0095e6c4ad95a
[TRACE] /home/cotox/tox-stuff/c-toxcore/toxcore/network.c:515(loglogdata) [33] =>O  33< 172.17.0.1:33445 (0: OK) | f5b0095e6c4ad95a
...

This change is

cotox · 2018-05-21T17:59:26Z

@nurupo I added the logger. It outputs something maybe interesting like, some log taged as error. I'm new in tox. Not sure is this feature useful. Any suggestion?

cotox · 2018-05-22T06:12:27Z

I moved comment lines into commit to keep source code clean.

iphydf · 2018-06-24T11:41:31Z

This function is now replicated 3 times in our codebase. Can we make that only 1 and include it in all 3 places?

I found only 2 print_log().

other/DHT_bootstrap.c: 98: void print_log(...)

other/bootstrap_daemon/src/tox-bootstrapd.c: 178: void print_log(...)

Where's the 3rd?

Found the 3rd, in IRC chat. note it here.

c-toxcore/auto_tests/helpers.h

Line 48 in ae7899c

static void print_debug_log(Tox *m, TOX_LOG_LEVEL level, const char *file, uint32_t line, const char *func,

nurupo · 2018-06-26T15:31:58Z

Note that tox-bootstrapd has two logging options

send all logs to the syslog daemon, which supposedly stores it in a log file or does something else
send log to stdout/stderr

The way you have added toxcore logging to tox-bootstrapd makes it always be sent to stderr. I think that debug/trace logging should use the same logging backend that the rest of tox-bootstrapd does, so that when user makes it log to syslog, debug/trace output is logged to syslog too.

CLAassistant · 2018-06-29T01:05:20Z

Thank you for your submission! We really appreciate it. Like many open source projects, we ask that you all sign our Contributor License Agreement before we can accept your contribution.
1 out of 2 committers have signed the CLA.

✅ cotox
❌ nurupo
_{You have signed the CLA already but the status is still pending? Let us recheck it.}

nurupo · 2018-06-29T01:09:58Z

Added a commit that does proper logging of toxcore's logs in tox-bootstrapd.

Also removed 2 of your "Merge branch 'master' into bootstrap-logger" commits and instead rebased your branch on top of the master (no conflicts were found), as that's what you should have done instead of the merges.

nurupo · 2018-06-29T01:16:57Z

Why do we want to log only if MIN_LOGGER_LEVEL is LOG_TRACE or LOG_DEBUG, why not log in all of the cases?

Also, isn't that check redundant? Doesn't logger check for MIN_LOGGER_LEVEL on its own before calling the logger callback?

nurupo · 2018-06-29T01:21:53Z

Hm, I see. By default toxcore uses LOG_INFO log level and we don't want bootstrap programs to spit INFO+WARNING+ERROR logs by default, is that correct?

cotox · 2018-06-29T18:34:09Z

~~Can we use the already exist argument level here? So that we don't need to declare a new variable.~~

My bad. The level is in type LOGGER_LEVEL not LOG_LEVEL. Sorry for bother.

Right, LOGGER_LEVEL is toxcore's log level from toxcore/logger.h, but LOG_LEVEL is tox-bootstrap's log level from other/bootstrap_daemon/src/log.h.

cotox · 2018-06-29T18:38:28Z

Hi @nurupo,

By default toxcore uses LOG_INFO log level and we don't want bootstrap programs to spit INFO+WARNING+ERROR logs by default, is that correct?

Yes.

Also removed 2 of your "Merge branch 'master' into bootstrap-logger" commits and...

Thank you, nurupo :-)

I made this "mistake" by click on "Update branch" button on GitHub web. Which I want to make a response to @iphydf that I've read his message.

I need more time to find the suitable file to place the logger function. That's why I didn't commit yet.

BTW, your c1bd6d0 is every cool :)

nurupo · 2018-06-29T19:35:16Z

BTW, your c1bd6d0 is every cool :)

c1bd6d0 is your commit though, I have made no changes to the code contents of it, only metadata has changed. It has changed the hash, added me as the commiter (and still has you as the author) and got my gpg signature because I have rebased it on top of the master branch.

Feel free to squash commits before getting this PR merged. I kept your original commit in case there was some disagreement about the modification I have done, which is very easy to undo if it's in its own separate commit on top of your separate commit, and because it's easier to see what I have modified exactly that way.

iphydf · 2018-07-25T00:00:00Z

Is this done? @cotox did you deduplicate the functions?

nurupo · 2018-08-19T22:26:48Z

Was it rebased on master? Afaik there was a refactor in the toxcore's logger, so logger constant names and such would need to be changed.

nurupo · 2018-08-19T22:52:51Z

I think I have fixed the build now (it's still building...). The deduplication issue is still not addressed though.

nurupo · 2018-08-19T22:55:19Z

Huh, I'm confused. I thought I had made changes and pushed them, but apparently not? Will redo it again.

nurupo · 2018-08-19T23:03:01Z

Should be good now.

iphydf

Reviewable status: complete! 1 of 1 approvals obtained (waiting on @cotox and @nurupo)

other/DHT_bootstrap.c, line 97 at r4 (raw file):

}

static void print_log(void *context, LOGGER_LEVEL level, const char *file, int line,

Logger_Level

other/bootstrap_daemon/src/tox-bootstrapd.c, line 183 at r4 (raw file):

// Logs toxcore logger message using our logger facility

static void toxcore_logger_callback(void *context, LOGGER_LEVEL level, const char *file, int line,

Logger_Level

other/bootstrap_daemon/src/tox-bootstrapd.c, line 186 at r4 (raw file):

                                    const char *func, const char *message, void *userdata)
{
    char *strlevel;

I don't think we need strlevel, given that we translate it to a LOG_LEVEL already. Yes, we lose a bit of information on whether it's debug or info or trace, but I think that's acceptable.

codecov · 2018-08-20T00:19:35Z

Codecov Report

Merging #895 into master will decrease coverage by 0.1%.
The diff coverage is n/a.

@@           Coverage Diff            @@
##           master    #895     +/-   ##
========================================
- Coverage    82.7%   82.5%   -0.2%     
========================================
  Files          82      81      -1     
  Lines       14478   14437     -41     
========================================
- Hits        11980   11924     -56     
- Misses       2498    2513     +15

Impacted Files	Coverage Δ
toxav/audio.c	`65.7% <0%> (-7.8%)`	⬇️
auto_tests/network_test.c	`90.3% <0%> (-7.3%)`	⬇️
toxcore/LAN_discovery.c	`82% <0%> (-2.9%)`	⬇️
toxcore/TCP_client.c	`64.3% <0%> (-2.8%)`	⬇️
toxcore/TCP_server.c	`75% <0%> (-2.8%)`	⬇️
toxcore/DHT.c	`76.6% <0%> (-0.2%)`	⬇️
toxcore/Messenger.c	`85.8% <0%> (-0.1%)`	⬇️
toxcore/mono_time.c	`92.8% <0%> (ø)`	⬆️
auto_tests/reconnect_test.c
toxcore/net_crypto.c	`93.6% <0%> (+0.7%)`	⬆️
... and 4 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 36f0caa...2e4cae6. Read the comment docs.

iphydf

Reviewed 1 of 2 files at r5, 1 of 1 files at r6.
Reviewable status: 1 change requests, 0 of 1 approvals obtained (waiting on @cotox and @nurupo)

other/bootstrap_daemon/src/tox-bootstrapd.c, line 186 at r4 (raw file):

Previously, iphydf wrote…

I don't think we need strlevel, given that we translate it to a LOG_LEVEL already. Yes, we lose a bit of information on whether it's debug or info or trace, but I think that's acceptable.

@nurupo what do you think?

nurupo

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

other/bootstrap_daemon/src/tox-bootstrapd.c, line 186 at r4 (raw file):

Previously, iphydf wrote…

@nurupo what do you think?

It depends on whether you want to know the [LOG|LOGGER]_LEVEL_ of log messages when users eventually submit bug reports with log messages to toxcore. By default LOG_LEVEL information is not available when reading the log text, it gets stripped down at the log filtering stage.

rsyslog uses the log level information primary for filtering log messages when creating custom logging rules, but by default, at least on Debian, log messages are not prefixed with the log level or anything like that. By default, all of tox-bootstrapd's log messages will be written to /var/log/syslog file with the log level information being lost. You could, of course, create a custom rsyslog config file that tells rsyslog to prefix log messages with the log level or split which log levels get written to which files, e.g. write tox-boostrapd errors to /var/log/tox-bootstrapd-errors.log and such. However, this is something tox-bootstrapd user would need to configure themselves if they want to, this won't happen in a default setup, so expect the bug reports you see not to contain any log level information in them.

stdout backend is similar, it splits log level in stdout and stderr, so best you can distinguish between INFO (stdout) and WARNING/ERROR (stderr), but that's only if you redirected two of the two streams into different places, otherwise you get them all together with no way to tell what log level they are.

I think we are the ones who will get affected by the change the most. Users wouldn't be affected by either lack or presence of strlevel, as they will be able to filter the logs with rsyslog/stdout backends in any case. So whether we want strlevel or not depends on whether the log/logger level information is useful for us when a tox-bootstrapd user sends their logs in a bug report.

Btw, strlevel has been removed right after you made that comment 6 days ago. I can re-add it if you want.

iphydf · 2018-08-26T20:52:53Z

Feel free to merge.

Don't know why codes with macro dosen't work. As it's only a few expensive, just code it without macro for now. \#if (MIN_LOGGER_LEVEL == LOG_TRACE) || (MIN_LOGGER_LEVEL == LOG_DEBUG) fprintf(stderr, "[%s] %s:%d(%s) %s\n", strlevel, file, line, func, message); \#endif

cotox requested review from iphydf and nurupo May 21, 2018 17:53

cotox force-pushed the bootstrap-logger branch from 262ef12 to d74310c Compare May 22, 2018 06:03

cotox force-pushed the bootstrap-logger branch 3 times, most recently from 95b8fca to 8ba7cb6 Compare May 23, 2018 17:47

iphydf requested changes Jun 24, 2018

View reviewed changes

iphydf added this to the v0.2.x milestone Jun 24, 2018

cotox force-pushed the bootstrap-logger branch from 6aebd07 to 4065638 Compare June 25, 2018 12:34

nurupo force-pushed the bootstrap-logger branch from 4e2ce7e to 5f50532 Compare June 29, 2018 01:05

nurupo force-pushed the bootstrap-logger branch from 5f50532 to 8d08bff Compare June 29, 2018 01:12

nurupo force-pushed the bootstrap-logger branch from 8d08bff to b4eb7af Compare June 29, 2018 02:45

cotox commented Jun 29, 2018

View reviewed changes

iphydf force-pushed the bootstrap-logger branch from b4eb7af to 6e0f94c Compare August 19, 2018 21:51

iphydf approved these changes Aug 19, 2018

View reviewed changes

nurupo force-pushed the bootstrap-logger branch 2 times, most recently from b4eb7af to 9b56841 Compare August 19, 2018 22:50

nurupo force-pushed the bootstrap-logger branch from 9b56841 to d9b4148 Compare August 19, 2018 23:01

iphydf requested changes Aug 19, 2018

View reviewed changes

nurupo force-pushed the bootstrap-logger branch 3 times, most recently from 968b7d6 to ad3d1c9 Compare August 20, 2018 00:19

nurupo force-pushed the bootstrap-logger branch from ad3d1c9 to 1954501 Compare August 20, 2018 00:24

iphydf requested changes Aug 26, 2018

View reviewed changes

nurupo approved these changes Aug 26, 2018

View reviewed changes

iphydf approved these changes Aug 26, 2018

View reviewed changes

iphydf force-pushed the bootstrap-logger branch 2 times, most recently from 1ea6e43 to 6d83572 Compare August 27, 2018 12:43

cotox and others added 2 commits August 30, 2018 22:44

Use our own logging facility to log toxcore's logs

2e4cae6

iphydf force-pushed the bootstrap-logger branch from 6d83572 to 2e4cae6 Compare August 30, 2018 22:44

iphydf merged commit 2e4cae6 into TokTok:master Aug 30, 2018

robinlinden modified the milestones: v0.2.x, v0.2.8 Oct 7, 2018

Uh oh!

Conversation

cotox commented May 21, 2018 • edited by iphydf Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

cotox commented May 21, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

cotox commented May 22, 2018

Uh oh!

iphydf Jun 24, 2018

Choose a reason for hiding this comment

Uh oh!

cotox Jun 25, 2018

Choose a reason for hiding this comment

Uh oh!

cotox Jun 26, 2018

Choose a reason for hiding this comment

Uh oh!

nurupo commented Jun 26, 2018

Uh oh!

CLAassistant commented Jun 29, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

nurupo commented Jun 29, 2018

Uh oh!

nurupo commented Jun 29, 2018

Uh oh!

nurupo commented Jun 29, 2018

Uh oh!

cotox Jun 29, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

nurupo Jun 29, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

cotox commented Jun 29, 2018

Uh oh!

nurupo commented Jun 29, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

iphydf commented Jul 25, 2018

Uh oh!

nurupo commented Aug 19, 2018

Uh oh!

nurupo commented Aug 19, 2018

Uh oh!

nurupo commented Aug 19, 2018

Uh oh!

nurupo commented Aug 19, 2018

Uh oh!

iphydf left a comment

Choose a reason for hiding this comment

Uh oh!

codecov Bot commented Aug 20, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

iphydf left a comment

Choose a reason for hiding this comment

Uh oh!

nurupo left a comment

Choose a reason for hiding this comment

Uh oh!

iphydf commented Aug 26, 2018

Uh oh!

Reviewers

Assignees

Labels

Milestone

Development

Uh oh!

5 participants

cotox commented May 21, 2018 •

edited by iphydf

Loading

cotox commented May 21, 2018 •

edited

Loading

CLAassistant commented Jun 29, 2018 •

edited

Loading

cotox Jun 29, 2018 •

edited

Loading

nurupo Jun 29, 2018 •

edited

Loading

nurupo commented Jun 29, 2018 •

edited

Loading

codecov Bot commented Aug 20, 2018 •

edited

Loading