[Bug stdio/31137] New: Regression vfprintf + setbuf (no buffering)

[Bug stdio/31137] New: Regression vfprintf + setbuf (no buffering)

[david.marchand at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=31137

            Bug ID: 31137
           Summary: Regression vfprintf + setbuf (no buffering)
           Product: glibc
           Version: 2.37
            Status: NEW
          Severity: normal
          Priority: P2
         Component: stdio
          Assignee: unassigned at sourceware dot org
          Reporter: david.marchand at redhat dot com
  Target Milestone: ---

Created attachment 15252
  --> https://sourceware.org/bugzilla/attachment.cgi?id=15252&action=edit
log.c

For the context, OVS has its logging framework (which writes to file, console,
syslog etc...). DPDK is a library for networking datapath in userspace, and its
components generate log messages through its own framework. DPDK provides a way
to redirect those logs by passing a FILE * from fopencookie.
OVS does this and disables buffering.

After updating from f37 to f38 (glibc-2.36-17.fc37.x86_64 to
glibc-2.37-13.fc38.x86_64), I noticed a change in how the logs are written for
dpdk messages in OVS.

Example of output:
2023-11-17T12:50:38.137Z|00059|dpdk|INFO|VHOST_CONFIG:
(/home/dmarchan/git/pub/ovs/master/build/tests/system-dpdk-testsuite.dir/003/dpdkvhostclient0)
Linear buffers requ
2023-11-17T12:50:38.137Z|00060|dpdk|INFO|ested without external buffers,

The log message has been split in 128 bytes chunks (if I count correctly).

I attached a simple reproducer (to mimick what is done in OVS, which
takes over DPDK logs with a similar fopencookie + setbuf in non
buffering mode).

# From a f37 container:
[root@cb7d749e838f ~]# gcc -o log -Wall -Werror log.c; ./log
no setbuf
=========

Calling fprintf
idx=0 size=511

Calling vfprintf
idx=0 size=511


setbuf _IONBF
=============

Calling fprintf
idx=0 size=511

Calling vfprintf
idx=0 size=511


# From a f38 container:
[root@3fbf304e6894 ~]# gcc -o log -Wall -Werror log.c; ./log
no setbuf
=========

Calling fprintf
idx=0 size=511

Calling vfprintf
idx=0 size=511


setbuf _IONBF
=============

Calling fprintf
idx=0 size=511

Calling vfprintf
idx=0 size=128
idx=1 size=128
idx=2 size=128
idx=3 size=127

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug stdio/31137] Regression vfprintf + setbuf (no buffering)

[fweimer at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=31137

Florian Weimer <fweimer at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |fweimer at redhat dot com

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug stdio/31137] Regression vfprintf + setbuf (no buffering)

[schwab@linux-m68k.org]

https://sourceware.org/bugzilla/show_bug.cgi?id=31137

--- Comment #1 from Andreas Schwab <schwab@linux-m68k.org> ---
That doesn't look like a bug.  You are requesting unbuffered output, so the
output appears as soon as possible.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug stdio/31137] Regression vfprintf + setbuf (no buffering)

[fweimer at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=31137

--- Comment #2 from Florian Weimer <fweimer at redhat dot com> ---
The reproducer is misleading because GCC translates the fprintf call into an
fputs call. With -fno-builtin, I get this instead:

“
no setbuf
=========

Calling fprintf
idx=0 size=511

Calling vfprintf
idx=0 size=511


setbuf _IONBF
=============

Calling fprintf
idx=0 size=128
idx=1 size=128
idx=2 size=128
idx=3 size=127

Calling vfprintf
idx=0 size=128
idx=1 size=128
idx=2 size=128
idx=3 size=127
”

So at least it's consistent.

Echoing what Andreas said, I think you are just observing the effect of a
reduced buffer size. It was always there, except that we used to have a large
on-stack buffer in vfprintf (8192 bytes, I believe), which probably papered
over it.

The 128 bytes fallback buffer size is arbitrary. We can probably increase it
somewhat if it reduces the compatibility impact of this change. But fopencookie
is inherently a byte stream interface, so there is no guarantee that one
fprintf call will be translated into one cookie write call.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug stdio/31137] Regression vfprintf + setbuf (no buffering)

[schwab@linux-m68k.org]

https://sourceware.org/bugzilla/show_bug.cgi?id=31137

--- Comment #3 from Andreas Schwab <schwab@linux-m68k.org> ---
%s used to write the string directly to the stream.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug stdio/31137] Regression vfprintf + setbuf (no buffering)

[fweimer at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=31137

--- Comment #4 from Florian Weimer <fweimer at redhat dot com> ---
I'm pretty sure the actual application has a more elaborate format string here.
If we don't have a large enough buffer, that will still result in multiple
writes even if we can handle arbitrarily large %s strings directly (because we
need to flush the previous buffer contents due to lack of vectored writes, and
write the subsequent format bits from the buffer).

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug stdio/31137] Regression vfprintf + setbuf (no buffering)

[carlos at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=31137

Carlos O'Donell <carlos at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
         Resolution|---                         |NOTABUG
             Status|NEW                         |RESOLVED
                 CC|                            |carlos at redhat dot com

--- Comment #5 from Carlos O'Donell <carlos at redhat dot com> ---
Given Andreas and Florian's responses I'm marking this closed as not a bug.

If you think that we need to increase the fallback buffer size for the purposes
of compatibility then please reopen the issue.

-- 
You are receiving this mail because:
You are on the CC list for the bug.