silently refusing to log additional arguments

[funkyshoc]

In some cases the compile fails due to hitting a maximum number of arguments, which tells you there is a problem.

However in this example (v1 is an int, v4 is a double) the first two log statements silently fail to log, which is a bit scary. Is this a bug?

log_trace("try too many args {}, {}, {}, {}, {}, {}, {}, {}, {}, {}, {}", v1, v4, v1, v4, v1, v4, v1, v4, v1, v4, v1);
log_trace("try too many args {}, {}, {}, {}, {}, {}, {}, {}, {}, {}", v1, v4, v1, v4, v1, v4, v1, v4, v1, v4);
log_trace("try too many args {}, {}, {}, {}, {}, {}, {}, {}, {}", v1, v4, v1, v4, v1, v4, v1, v4, v1);
log_trace("try too many args {}, {}, {}, {}, {}, {}, {}, {}", v1, v4, v1, v4, v1, v4, v1, v4);
log_trace("try too many args {}, {}, {}, {}, {}, {}, {}", v1, v4, v1, v4, v1, v4, v1);
log_trace("try too many args {}, {}, {}, {}, {}, {}", v1, v4, v1, v4, v1, v4);

[RafaGago]

My first guess is that you need to read here:
https://github.com/RafaGago/mini-async-log/blob/master/include/mal_log/mal_interface.hpp#L67

Note that the functions have a return value, so they aren't failing silently.

[RafaGago]

Now the first entry on the feature oveview program highlights that:

1002d97

[RafaGago]

Wronk link on the previous answer, I wanted to paste this
https://github.com/RafaGago/mini-async-log/blob/master/include/mal_log/cfg.hpp#L96

[funkyshoc]

Perhaps I'm missing something, but the examples I give (the first two longer entries above) do not log and yet also return a value of true (success).

I was already using the example program so it already said "mal_cfg.queue.can_use_heap_q = true".

[RafaGago]

I'll have a look then

[RafaGago]

I realized one thing, the example has these two lines at the beggining:

fe.set_file_severity (sev::notice);
fe.set_console_severity (sev::notice);

Which means that "notice" is the minimum severity. "trace" and "debug" severities are filtered out. The return value is true because this isn't an error.

[funkyshoc]

Tried setting to sev::debug in example program. Still return value is true/success on the first two entries yet no prints (only the 3rd, 4th, 5th, 6th -- not the 1st and 2nd ones get logged):

00000000000.022666596 [err_] good value on first: true
00000000000.022670603 [err_] good value on second: true
00000000000.022674553 [err_] try too many args 42, 3.14, 42, 3.14, 42, 3.14, 42, 3.14, 42
00000000000.022692554 [err_] good value on third: true
00000000000.022696464 [err_] try too many args 42, 3.14, 42, 3.14, 42, 3.14, 42, 3.14
00000000000.022709377 [err_] good value on fourth: true
00000000000.022713318 [err_] try too many args 42, 3.14, 42, 3.14, 42, 3.14, 42
00000000000.022724806 [err_] good value on fifth: true
00000000000.022728645 [err_] try too many args 42, 3.14, 42, 3.14, 42, 3.14
00000000000.022738948 [err_] good value on sixth: true

int v1 = 42;
double v4 = 3.14;
int v1_2 = 42;
int v1_3 = 42;
int v1_4 = 42;
int v1_5 = 42;
int v1_6 = 42;
double v4_2 = 3.14;
double v4_3 = 3.14;
double v4_4 = 3.14;
double v4_5 = 3.14;

printf("Bool before: %d\n", good);
good = log_error("try too many args {}, {}, {}, {}, {}, {}, {}, {}, {}, {}, {}", v1, v4, v1_2, v4_2, v1_3, v4_3, v1_4, v4_4, v1_5, v4_5, v1_6);
printf("Bool after 1st: %d\n", good);
log_error("good value on first: {}", good);
good = log_error("try too many args {}, {}, {}, {}, {}, {}, {}, {}, {}, {}", v1, v4, v1, v4, v1, v4, v1, v4, v1, v4);
log_error("good value on second: {}", good);
good = log_error("try too many args {}, {}, {}, {}, {}, {}, {}, {}, {}", v1, v4, v1, v4, v1, v4, v1, v4, v1);
log_error("good value on third: {}", good);
good = log_error("try too many args {}, {}, {}, {}, {}, {}, {}, {}", v1, v4, v1, v4, v1, v4, v1, v4);
log_error("good value on fourth: {}", good);
good = log_error("try too many args {}, {}, {}, {}, {}, {}, {}", v1, v4, v1, v4, v1, v4, v1);
log_error("good value on fifth: {}", good);
good = log_error("try too many args {}, {}, {}, {}, {}, {}", v1, v4, v1, v4, v1, v4);
log_error("good value on sixth: {}", good);

[RafaGago]

Looks like I will have to look at it this evening then. Looks scary.

[RafaGago]

This bug was very ugly. It was the heap queue losing the ordering against the bounded one. The entries weren't lost, but printed at the bottom.

After fixing it I had to check where does this came from, because this bug would mean that the logger never worked, which is scary considering that it's running in some devices for some years. Fortunately the issue was a line that went missing during a recent refactor. This is the offending commit:

701173f

Which inocently erased the line

n->pos = pos

The fix is just to add it again:

c585042

I wish I'd had time to develop some kind of automated testing for this project back when I developed it (under time pressure). This wasn't an obscure race condition.

[funkyshoc]

Cool where can I ship you a nice bottle of wine or two for helping out so much on the reported issues?

[RafaGago]

Don't worry :), actually you helped me out by discovering legitimate bugs.

Actually I'm not very proud of this one. I'm doing a rewrite that will hopefully be even faster (I'll use thread local storage and wait-free producers on the fastpath) and more importantly it will be coded in a more straightforward way (C) and will have some kind of unit + smoke testing to catch big bugs like this one.