Bug 4670

Summary: fopencookie custom IO stream behaviour without buffering differs from GNU C
Product: uClibc Reporter: Tomi <farago1>
Component: stdioAssignee: unassigned
Status: NEW ---    
Severity: normal CC: uclibc-cvs
Priority: P5    
Version: 0.9.32   
Target Milestone: ---   
Hardware: PC   
OS: Linux   
Host: Target:
Build:
Attachments: small example file; expected behaviour as in GNU C lib.

Description Tomi 2012-01-04 15:48:18 UTC
Created attachment 3944 [details]
small example file; expected behaviour as in GNU C lib.

I use a custom stream writer. Under uClibc every parameter is output to a new line in syslog if buffering is turned off[*]. See attachment for a short example. The same code on a GNU C library works as expected. If buffering is kept on, behaviour is as expected.

[*] setvbuf(stream, NULL, _IONBF, 0);

On GNU C after a call to fprintf() the expanded string is passed to the write function.
Output is:
size '16'; buffer 'TEST::test::TEST'

See stacktrace:
#0  log_writer (cookie=0x804a060, buffer=0xbfffd0c0 "TEST::test::TEST", size=16) at test2.c:12
#1  0xb7ebaaf4 in ?? () from /lib/i386-linux-gnu/libc.so.6
#2  0xb7ec5514 in ?? () from /lib/i386-linux-gnu/libc.so.6
#3  0xb7ec624a in _IO_file_xsputn () from /lib/i386-linux-gnu/libc.so.6
#4  0xb7ea1137 in ?? () from /lib/i386-linux-gnu/libc.so.6
#5  0xb7e9c383 in vfprintf () from /lib/i386-linux-gnu/libc.so.6
#6  0xb7ea619f in fprintf () from /lib/i386-linux-gnu/libc.so.6
#7  0x080485a9 in main () at test2.c:28

on uClibc-0.9.32 on my ARM machine after a call to fprintf() the non-expanded string is passed to the write function, with several calls for each section of the string.
Output is:
size '6'; buffer 'TEST::%s::TEST'
size '4'; buffer 'test'
size '6'; buffer '::TEST'

See stacktrace:
#0  log_writer (cookie=0x107e8, buffer=0x86b0 "TEST::%s::TEST", size=6) at test2.c:12
#1  0x400386a4 in ?? () from /ffp/lib/libc.so.0
...
#0  log_writer (cookie=0x107e8, buffer=0x86c0 "test", size=4) at test2.c:12
#1  0x400386a4 in ?? () from /ffp/lib/libc.so.0
...
#0  log_writer (cookie=0x107e8, buffer=0x86b8 "::TEST", size=6) at test2.c:12
#1  0x400386a4 in ?? () from /ffp/lib/libc.so.0
Comment 1 Leonid 2012-01-05 07:55:35 UTC
If you will rework log_writer() function from your sample to not to print bytes/symbols after "size" buffer length, than you discover that functionality not broken in uClibc:

Output is:
size '6'; buffer 'TEST::'
size '4'; buffer 'test'
size '6'; buffer '::TEST'

i.e. complete output will be 'TEST::test::TEST', as expected.


P.S. fopencookie man pages never promise that input buffer "buf" must have '\0' after "size" bytes.
Comment 2 Tomi 2012-01-05 08:48:12 UTC
My apologies, I might not have been complete on my report.
Yes, you are right, output is indeed the following when you take size into account as I have in the actual code. Sorry I did not do it for the example. However, when passing these strings to syslog each of the calls is output to a new line.

So let's take the following example with the a newline added after the string, and log_writer function properly only writing as many characters as specified by size.

teststring: fprintf(log_stream, "TEST::%s::TEST\n", "param");

output on GNU C Lib:
1 function call:
log_writer(cookie, buffer="TEST::param::TEST\n", size=18)
syslog("%s", "TEST::param::TEST\n")

output:
Jan  5 09:43:09 syslogd: TEST::param::TEST


output on uClibC lib:
3 functions calls:
log_writer(cookie, buffer="TEST::%s::TEST\n", size=6)
syslog("%s", "TEST::")
log_writer(cookie, buffer="param", size=5)
syslog("%s", "param")
log_writer(cookie, buffer="::TEST\n", size=7)
syslog("%s", "::TEST\n")

output:
Jan  5 09:43:09 syslogd: TEST::
Jan  5 09:43:09 syslogd: param
Jan  5 09:43:09 syslogd: ::TEST

This is different behaviour from GNU C. However if uClib's buffering is expected to be different from GNU C, I accept that. I can work around this issue which I found in davfs2's SSL library calls.