Some corruption in logger callback?

[winbatch]

Hi,

I'm finding that I'm occasionally getting some null characters when I'm logging to file the contents of the logger callback. My program is single threaded, yet I know librdkafka is multi-threaded. Do I have to do any locking while dealing with the logging callback? or are you locking while calling the callback handler?

Thanks.

[winbatch]

Quick update - I put a mutex around the logging and it didn't help - still getting some null characters sometimes. Hopefully you know what the problem is and have a quick fix?

[edenhill]

Can you provide an example of such logs?

[edenhill]

Are you holding on to the 'fac' or 'buf' from the log callback after your callback has returned?

[winbatch]

I'm passing them on to my own logger as effectively
printf/va_arg arguments. Should I make a copy?

On Monday, February 3, 2014, Magnus Edenhill notifications@github.com
wrote:

Are you holding on to the 'fac' or 'buf' from the log callback after your
callback has returned?

Reply to this email directly or view it on GitHubhttps://github.com//issues/70#issuecomment-33927235
.

[winbatch]

I'll see if I can get the logs to you (as you know that's a struggle).
Just wanted to confirm that those params are always null terminated?
Also, that you don't modify the values until the callback returns?

On Monday, February 3, 2014, Dan Hoffman hoffmandan@gmail.com wrote:

I'm passing them on to my own logger as effectively
printf/va_arg arguments. Should I make a copy?

On Monday, February 3, 2014, Magnus Edenhill <notifications@github.comjavascript:_e(%7B%7D,'cvml','notifications@github.com');>
wrote:

Are you holding on to the 'fac' or 'buf' from the log callback after your
callback has returned?

Reply to this email directly or view it on GitHubhttps://github.com//issues/70#issuecomment-33927235
.

[edenhill]

The log strings are always nul-terminated and they will be constant for the duration of the callback.
So it sounds very weird that they get messed up like this.

[winbatch]

I copied over the rdkafka_performance and added the logger callback. so far unable to reproduce it - will keep you posted.

[winbatch]

So far it's something funky with va_list/va_arg handling. Not sure why it only happens with logs coming from the logger callback. Might be getting lucky elsewhere.

[edenhill]

I can have a look at the piece of code and see if I can spot the problem.

[winbatch]

This is effectively what I'm doing (I've stripped off a bunch of useful stuff so it may look strange that I'm bothering to split it out into multiple functions, etc.). Assume that myfile is an int and has already been ::open()-ed to a file called myfile.txt. Also assume I registered for the logging callback and asked for 'all'.

char * writeit( const char * format, va_list ap )
{
        static char rLogBufFORCOLLECTOR_OOB[16384];
        size_t size = vsprintf( rLogBufFORCOLLECTOR_OOB, format, ap );
        va_end(ap);
        write( myfile, rLogBufFORCOLLECTOR_OOB, size);
        return rLogBufFORCOLLECTOR_OOB;
}
void experiment( const char * format, ... )
{
        va_list ap;
        va_start(ap, format);
        char * temp = writeit(format, ap );
        va_end(ap);

}
static void logger (const rd_kafka_t * rk, int level,
                    const char * fac, const char * buf)
{
        experiment( "[%s] fac:'%s' name:'%s' log:'%s'\n", "TEST", fac, rd_kafka_name(rk), buf );
}

On my host, If you run this for a long time and then grep 'meta' myfile.txt, it will tell you that it's binary. if you 'od -a myfile.txt | grep nul'. You'll see that there are null characters.

od -a mylog.txt | grep nul
0015020   w   i   t   h  sp   l   e   a   d   e   r  sp   1   '  nl nul
0015420   t   o   p   i   c   s   '  nl nul   i   o   n  sp   1  sp   L
5176140   p   s   '  nl nul   c   .   g   s   .   c   o   m   :   9   0
5272720   r   v   i   n   g  sp   2   7  sp   o   p   s   '  nl nul   c
7277040   v   i   n   g  sp   2  sp   o   p   s   '  nl nul   d   c   .
10106160   i   n   g  sp   2  sp   o   p   s   '  nl nul   .   d   c   .

Again - I'm not sure if there's anything wrong with librdkafka or that my va_list stuff is wrong. Either way, hope you can find it :)

[edenhill]

There is a stray va_end(ap) in writeit(), but I guess thats a cut'n'paste error (it doesnt matter though).

I think this is a thread race problem with your static buffer in writeit.
You said that you tried to add mutexes to no avail; that mutex would have to go around
the experiment() call in the logger callback to keep the static buffer from writeit() safe.
This because the logger callback may be called from any rdkafka thread at any time, which means that it most certainly will be called simultaneously from two threads more often than seems reasonable at first.
rdkafka uses one main thread per rd_kafka_t * and one thread per broker.

I think you can fix this issue by adding the __thread attribute to the static buffer (and any other static stuff you use in this callchain which is edited out):

static __thread char rLogBufFORCOLLECTOR_OOB[16384];

That will put rLogBufFORCOLL... in a thread local storage (TLS) and avoid two threads accessing it simultaneously.

[winbatch]

the va_end wasn't stray. I saw in the man pages that vsprintf doesn't call va_end so I thought it was the right thing to do. In any case, I'm trying the __thread thing now. appreciate the help.

[winbatch]

Making them non-static seemed to do the trick. Thanks very much for the help.

[edenhill]

Cool :) As long as you dont return a non-static from that writeit function.

[winbatch]

Yeah, didn't need a return to begin with so all good.

On Monday, February 3, 2014, Magnus Edenhill notifications@github.com
wrote:

Cool :) As long as you dont return a non-static from that writeit function.

Reply to this email directly or view it on GitHubhttps://github.com//issues/70#issuecomment-34018734
.