Move logging to a callback. #46

iphydf · 2016-08-19T12:11:06Z

This removes the global logger (which by the way was deleted when the first tox
was killed, so other toxes would then stop logging). Various bits of the code
now carry a logger or pass it around. It's a bit less transparent now, but now
there is no need to have a global logger, and clients can decide what to log and
where.

This change is

iphydf · 2016-08-19T23:13:33Z

@linux-modder you were talking about community reviews. This change is a good one to test your process on.

mannol · 2016-08-20T00:19:49Z

OK. First time using reviewable... Anyways, seems like it will require more effort to write them log messages but an overall a positive change.

Comments from Reviewable

tux3 · 2016-08-20T17:31:10Z

toxdns/toxdns.c

@@ -144,7 +144,8 @@ int tox_generate_dns3_string(void *dns3_object, uint8_t *string, uint16_t string
    }

    if (end_len != string - old_str) {
-        LOGGER_ERROR("tox_generate_dns3_string Fail, %u != %lu\n", end_len, string - old_str);
+        // This currently has no access to a logger.


It would be nice to add a "FIXME:" for easier grepability

tux3 · 2016-08-20T18:11:06Z

Reviewed 38 of 38 files at r1, 6 of 6 files at r2, 3 of 3 files at r3.
Review status: all files reviewed at latest revision, 2 unresolved discussions.

Comments from Reviewable

nurupo · 2016-08-21T01:17:28Z

Review status: 31 of 37 files reviewed at latest revision, 5 unresolved discussions.

toxav/bwcontroller.c, line 158 [r1] (raw file):

        if (bwc->cycle.lost) {
            LOGGER_DEBUG(bwc->m->log, "%p Sent update rcv: %u lost: %u",
                         bwc, bwc->cycle.recv, bwc->cycle.lost);

Why is messenger's logger used in here? Does this function run in messenger's thread? Is the log callback in tox.h thread-safe? Does the tox.h log callback get called only while inside tox_iterate()?

toxcore/logger.c, line 67 [r1] (raw file):
Why limit debug message to 1024 characters? We could make msg arbitrarily long. It would have to be allocated on heap though, which would result in rather big performance penalty if called very often. To mitigate the performance overhead, we could keep the 1024 char msg on the stack and vsnprintf() into it, but if vsnprintf() tells us that these 1024 bytes weren't enough, only then allocate a buffer on heap and vsnprintf() into it? vnsprintf() returns

The number of characters that would have been written if n had been sufficiently large, not counting the terminating null character.

so we would know exactly how much space to allcoate on the heap.

toxcore/tox.c, line 133 [r1] (raw file):

    _Bool load_savedata_sk = 0, load_savedata_tox = 0;

    Logger *log = logger_new(random_int());

Should it really be random? We could keep a global counter ourselves, or let the user pass an integer to tox_new(). Making the user pick it makes sense, that way user would know which Tox instance the Id corresponds to.

Actually, do we even need that integer? What is the purpose of it? A user would be able to know which Tox instance is calling the log callback because the callback would have the userdata argument that the user has passed to that instance's `tox_iterate()', so I don't see a point in that integer.

Comments from Reviewable

nurupo · 2016-08-21T01:23:47Z

Reviewed 38 of 38 files at r1.
Review status: 31 of 37 files reviewed at latest revision, 5 unresolved discussions.

toxav/bwcontroller.c, line 158 [r1] (raw file):

Previously, nurupo wrote…

Why is messenger's logger used in here? Does this function run in messenger's thread? Is the log callback in tox.h thread-safe? Does the tox.h log callback get called only while inside tox_iterate()?

Hm, I see there is really no toxav's logger, it's the same logger used in messenger and av. Doesn't that result in any threading issues as far as the log callback from the `tox.h` is called?

Comments from Reviewable

nurupo · 2016-08-21T01:33:06Z

Reviewed 6 of 6 files at r2, 3 of 3 files at r3, 6 of 6 files at r4.
Review status: all files reviewed at latest revision, 5 unresolved discussions.

Comments from Reviewable

iphydf · 2016-08-22T08:06:10Z

Review status: all files reviewed at latest revision, 5 unresolved discussions, some commit checks failed.

toxav/bwcontroller.c, line 158 [r1] (raw file):

Previously, nurupo wrote…

Hm, I see there is really no toxav's logger, it's the same logger used in messenger and av. Doesn't that result in any threading issues as far as the log callback from the tox.h is called?

Yes, it does. I've added a comment about this to the callback docs.

toxcore/logger.c, line 67 [r1] (raw file):

Previously, nurupo wrote…

Why limit debug message to 1024 characters? We could make msg arbitrarily long. It would have to be allocated on heap though, which would result in rather big performance penalty if called very often. To mitigate the performance overhead, we could keep the 1024 char msg on the stack and vsnprintf() into it, but if vsnprintf() tells us that these 1024 bytes weren't enough, only then allocate a buffer on heap and vsnprintf() into it? vnsprintf() returns

The number of characters that would have been written if n had been sufficiently large, not counting the terminating null character.

so we would know exactly how much space to allcoate on the heap.

The limit used to be 4096. I could make it 4096 again, but it seemed a bit pointless to support huge log messages. I'd like to keep it this way and reconsider if someone comes up with a good reason to write huge log messages. Right now, none of the logger calls write large messages.

toxcore/tox.c, line 133 [r1] (raw file):

Previously, nurupo wrote…

Should it really be random? We could keep a global counter ourselves, or let the user pass an integer to tox_new(). Making the user pick it makes sense, that way user would know which Tox instance the Id corresponds to.

Actually, do we even need that integer? What is the purpose of it? A user would be able to know which Tox instance is calling the log callback because the callback would have the userdata argument that the user has passed to that instance's `tox_iterate()', so I don't see a point in that integer.

Removed the id.

Comments from Reviewable

nurupo · 2016-08-23T08:48:11Z

toxcore/logger.c, line 67 [r1] (raw file):

Previously, iphydf wrote…

The limit used to be 4096. I could make it 4096 again, but it seemed a bit pointless to support huge log messages. I'd like to keep it this way and reconsider if someone comes up with a good reason to write huge log messages. Right now, none of the logger calls write large messages.

Ok.

Comments from Reviewable

nurupo · 2016-08-23T08:55:21Z

toxcore/tox.c, line 133 [r1] (raw file):

Previously, iphydf wrote…

Removed the id.

Didn't realize the log callback in `tox.h` didn't have `userdata` as an argument. Given the threading complications `userdata` imposes, I now get a glimpse of the possible idea you had behind having that integer.

Comments from Reviewable

mannol · 2016-08-26T21:10:16Z

merge it

nurupo · 2016-08-26T23:53:33Z

Reviewed 4 of 4 files at r6.
Review status: all files reviewed at latest revision, 4 unresolved discussions.

toxcore/logger.h, line 66 [r6] (raw file):

#define LOGGER_WRITE(log, level, format, ...) \
    do { \
        if (level >= MIN_LOGGER_LEVEL) { \

MIN_LOGGER_LEVEL is a compile-time option, but this check is done at run-time. Any way to make this check compile-time too?

Alternatively, why not make the log level a run-time option, so that a client could select the logging level, since no code seems to be compiled-out anyway and also because with the way this PR is now, the same client would have different logs depending on how the toxcore was built. Also, what about a getter function for the client to know the logging level toxcore uses, would that be useful?

Comments from Reviewable

This removes the global logger (which by the way was deleted when the first tox was killed, so other toxes would then stop logging). Various bits of the code now carry a logger or pass it around. It's a bit less transparent now, but now there is no need to have a global logger, and clients can decide what to log and where.

iphydf · 2016-08-27T00:22:32Z

Review status: all files reviewed at latest revision, 4 unresolved discussions.

toxcore/logger.h, line 66 [r6] (raw file):

Previously, nurupo wrote…

MIN_LOGGER_LEVEL is a compile-time option, but this check is done at run-time. Any way to make this check compile-time too?

Alternatively, why not make the log level a run-time option, so that a client could select the logging level, since no code seems to be compiled-out anyway and also because with the way this PR is now, the same client would have different logs depending on how the toxcore was built. Also, what about a getter function for the client to know the logging level toxcore uses, would that be useful?

I made it an option at all because there was a concern about TRACE being too computationally intensive. This is effectively a compile time option now, because compilers are permitted to (and do) remove the compile time constant `if (false)` branch.

I can make it a runtime option. The performance probably wouldn't be degraded a lot, it would just turn those compile time branches into runtime ones.

Opinions?

Comments from Reviewable

nurupo · 2016-08-27T01:08:02Z

Review status: all files reviewed at latest revision, 4 unresolved discussions.

toxcore/logger.h, line 66 [r6] (raw file):

This is effectively a compile time option now, because compilers are permitted to (and do) remove the compile time constant if (false) branch.

Ok, didn't realize that. Then it's good.

Opinions?

I don't have a strong opinion about it being a compile-time or run-time. I guess compile-time is somewhat mobile-friendly, less cpu cycles and battery usage (and tux3 has this dead-slow laptop he likes to run stuff on :P), so I'm more inclined for compile-time.

Comments from Reviewable

nurupo · 2016-08-27T03:54:27Z

Review status: all files reviewed at latest revision, 4 unresolved discussions.

Comments from Reviewable

nurupo · 2016-08-27T07:44:28Z

Review status: all files reviewed at latest revision, 5 unresolved discussions.

toxcore/logger.h, line 67 [r7] (raw file):

    do { \
        if (level >= MIN_LOGGER_LEVEL) { \
            logger_write(log, level, __FILE__, __LINE__, __func__, format, ##__VA_ARGS__); \

##__VA_ARGS__ is a gcc extension, do we want to use it?

Comments from Reviewable

iphydf · 2016-08-27T10:14:16Z

Review status: all files reviewed at latest revision, 5 unresolved discussions.

toxcore/logger.h, line 67 [r7] (raw file):

Previously, nurupo wrote…

##__VA_ARGS__ is a gcc extension, do we want to use it?

This is not a change. It was done like this before, so I kept it. Fixing it would involve a bit of effort I'd like to avoid in this PR. Feel free to make a followup PR to get rid of the gcc extension.

Comments from Reviewable

Diadlo · 2016-08-27T11:08:13Z

Reviewed 1 of 4 files at r6.
Review status: all files reviewed at latest revision, 5 unresolved discussions.

Comments from Reviewable

Diadlo · 2016-08-27T11:09:15Z

Reviewed 23 of 38 files at r1, 1 of 3 files at r3, 1 of 6 files at r4, 8 of 9 files at r5, 3 of 4 files at r6.
Review status: all files reviewed at latest revision, 5 unresolved discussions.

Comments from Reviewable

JFreegman · 2016-08-27T14:37:16Z

Reviewed 1 of 3 files at r3, 1 of 6 files at r4, 8 of 9 files at r5, 4 of 4 files at r6.
Review status: all files reviewed at latest revision, 5 unresolved discussions.

Comments from Reviewable

mannol · 2016-08-27T14:39:38Z

Review status: all files reviewed at latest revision, 5 unresolved discussions.

Comments from Reviewable

iphydf assigned GrayHatter, JFreegman, nurupo, zetok, tux3, sudden6, linux-modder and Diadlo Aug 19, 2016

iphydf force-pushed the logging branch 3 times, most recently from 04941f8 to b868b27 Compare August 19, 2016 14:02

iphydf force-pushed the logging branch from b868b27 to 2facef0 Compare August 20, 2016 10:53

tux3 reviewed Aug 20, 2016
View reviewed changes

iphydf force-pushed the logging branch from 2facef0 to e038d9f Compare August 20, 2016 18:05

iphydf force-pushed the logging branch from e038d9f to f66bace Compare August 20, 2016 18:16

iphydf unassigned zetok Aug 20, 2016

iphydf force-pushed the logging branch from f66bace to 5f9d38c Compare August 20, 2016 19:47

iphydf force-pushed the logging branch 3 times, most recently from 8d26cb6 to d3a1537 Compare August 22, 2016 18:17

iphydf force-pushed the logging branch from ec091eb to 13ae9e9 Compare August 27, 2016 00:16

iphydf assigned JFreegman, Diadlo, nurupo and mannol and unassigned GrayHatter, JFreegman, nurupo, tux3, linux-modder and Diadlo Aug 27, 2016

iphydf closed this Aug 27, 2016

iphydf merged commit 13ae9e9 into TokTok:master Aug 27, 2016

iphydf deleted the logging branch August 27, 2016 14:40

iphydf modified the milestone: v0.0.1 Nov 6, 2016

nurupo mentioned this pull request Nov 17, 2017

core log messages are limited to 1024 bytes #614

Closed

emdee-is mentioned this pull request Dec 13, 2023

ipv6 disabled on kernel cmdline disrupts Tox = most tests fail #2335

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Move logging to a callback. #46

Move logging to a callback. #46

iphydf commented Aug 19, 2016 •

edited

Loading

iphydf commented Aug 19, 2016

mannol commented Aug 20, 2016

tux3 Aug 20, 2016

iphydf Aug 20, 2016

tux3 commented Aug 20, 2016

nurupo commented Aug 21, 2016

nurupo commented Aug 21, 2016

nurupo commented Aug 21, 2016

iphydf commented Aug 22, 2016

nurupo commented Aug 23, 2016

nurupo commented Aug 23, 2016

mannol commented Aug 26, 2016

nurupo commented Aug 26, 2016

iphydf commented Aug 27, 2016

nurupo commented Aug 27, 2016

nurupo commented Aug 27, 2016

nurupo commented Aug 27, 2016

iphydf commented Aug 27, 2016

Diadlo commented Aug 27, 2016

Diadlo commented Aug 27, 2016

JFreegman commented Aug 27, 2016

mannol commented Aug 27, 2016

Move logging to a callback. #46

Move logging to a callback. #46

Conversation

iphydf commented Aug 19, 2016 • edited Loading

iphydf commented Aug 19, 2016

mannol commented Aug 20, 2016

tux3 Aug 20, 2016

Choose a reason for hiding this comment

iphydf Aug 20, 2016

Choose a reason for hiding this comment

tux3 commented Aug 20, 2016

nurupo commented Aug 21, 2016

nurupo commented Aug 21, 2016

nurupo commented Aug 21, 2016

iphydf commented Aug 22, 2016

nurupo commented Aug 23, 2016

nurupo commented Aug 23, 2016

mannol commented Aug 26, 2016

nurupo commented Aug 26, 2016

iphydf commented Aug 27, 2016

nurupo commented Aug 27, 2016

nurupo commented Aug 27, 2016

nurupo commented Aug 27, 2016

iphydf commented Aug 27, 2016

Diadlo commented Aug 27, 2016

Diadlo commented Aug 27, 2016

JFreegman commented Aug 27, 2016

mannol commented Aug 27, 2016

iphydf commented Aug 19, 2016 •

edited

Loading