Project

General

Profile

Feature #4311

blocking stderr output inhibits the program?

Added by neels over 1 year ago. Updated 20 days ago.

Status:
Stalled
Priority:
Normal
Assignee:
Category:
libosmocore
Target version:
-
Start date:
12/06/2019
Due date:
% Done:

90%

Spec Reference:

Description

I'm currently using urxvt (rxvt-unicode) as terminal program (not sure why, but...)
and I am every now and then seeing odd behavior when the terminal is scrolled up into scrollback, so that new output lines are not seen.

It seems to me that after a while urxvt stops reading from stdout/stderr. That is weird enough in itself, but the Osmocom related problem:
Apparently the server program stops interacting when the log output stops reading?

Even though stderr (or any other log target) is not writable, IMO we should still continue to serve all protocols as usual.
A blocking log target should not affect server operation.

Investigate whether my vague impression is correct and find ways to fix that in logging.c.

Associated revisions

Revision 433005c8 (diff)
Added by laforge 2 months ago

initial support for static userspace probes via systemtap

This adds a --enable-systemtap configure option, which will then
add static tracepoints to the generated libosmocore binary.

At this point, only two tracepoints are supported: log_start
and log_done. They can be used to trace the amount of time
a libosmocore-using application spends in potentiall blocking calls to
log to stderr or to files.

Related: OS#4311
Change-Id: I7e1ab664241deb524c9582cbd1bec31af46c747e

Revision 79147db7 (diff)
Added by laforge 2 months ago

logging: Change stderr + file target to use non-blocking write

So far, we used blocking, buffered fwrite() to write to stderr
and file targets. This causes problems if there are [slow] consumers
causing delays, such as gnome-terminal (when the program is started
interactively) or systemd/journald (where we observe 64..128ms blocks on
stderr).

This patch introduces stderr/file based logging via write_queue
and osmo_select_main(), i.e. switch from glibc-buffered, blocking
to internally buffered, non-blocking writes.

  • when osmo_stderr_target is created via application.c, we create it
    in blocking stream mode for backwards compatibility, particularly
    for [smaller] programs that don't use osmo_select_main()
  • when the VTY code encounters 'log stderr' or 'log file FILENAME',
    we switch that respective target to non-blocking write-queue mode,
    as this means the application is in fact using osmo_select_main()
  • The config file can now state 'log stderr blocking-io' or
    'log file FILENAME blocking-io' to explicitly enforce using blocking
    stream based I/O
  • The application can at any time use API functions to switch either way

Closes: OS#4311
Change-Id: Ia58fd78535c41b3da3aeb7733aadc785ace610da

Revision e01de122 (diff)
Added by laforge 2 months ago

logging: Avoid memcpy from stack to msgb in _file_output()

For file and stderr output, the existing code always generates
the log string on a stack buffer, and then (in case of non-blocking
write via write_queue) copies it over to a msgb.

Let's optimize this by turning _file_output() into a raw_output
callback which first allocates the msgb and then format-prints
directly to that msgb instaed of stack + memcpy.

This has the disadvantage that we don't know how long the buffer
has to be in order to print the entire string to it. As a result
we always have to allocate a 4k-sized buffer (plus msgb overhead).

The write_queue length for log file output has been decreased from
1024 entries to 156 entries in order to stay within the same
memory requirements for each log target memory pool (about 648 kBytes).

Related: OS#4311
Change-Id: I0d10b0199576d2e7ff6421a6dba19ae5ffafd946

Revision 4fc0add6 (diff)
Added by laforge 2 months ago

logging: Attempt a synchronous, non-blocking write first (file, stderr)

In the old days, we performed synchronous, blocking writes to the log
file or stderr. This was replaced by code that turned all log
file/stderr writes into non-blocking writes behind a write_queue.

This patch now introduces a further optimization: If we currently
don't have any log messages pending in the write queue, we are not
back-logged and assume we have a fair chance of writing the log message
right now, synchronously. So we try that first, and only enqueue
the log message if the write fails (no bytes or insufficient number
of bytes written).

This way we should get the best of both worlds: No delay/re-ordering
(and lower select syscall load) for the "normal" case (benefits of
the old synchronous writes) while at the same time never risking to
block on log output.

Related: OS#4311
Change-Id: I08469a7e4be9bc5bbd39140457bb582f4a0b1703

Revision 2bd05c04 (diff)
Added by laforge 2 months ago

WIP: add rate_ctr_group to log_target

This way we account for the number of dropped log messages at
write_queue overflow. However, log targets have no numerical
ID and hence we're not able to extract them in a reasonable manner.

Related: OS#4311
Change-Id: I89b696311b823267e05d6a3e85b92c1784b220ed

Revision dbb3c723 (diff)
Added by Neels Hofmeyr 2 months ago

msc_vlr_tests: make independent of libosmocore talloc

The msc_vlr_tests verify whether any of the tests run contain msgb or
talloc memory leaks. So far they did so by fixating a specific number of
talloc blocks, which may break by library implementations changing.

Instead, verify that the test leaks no allocations by comparing talloc
blocks before and after each test.

When a leak is detected, print the full talloc report to stderr, which
makes the expected output mismatch the actual output and fails the test.

Related: OS#4311
Change-Id: I8537fa76d460c951302932a1bad4299f7fe398c9

Revision 3217d518 (diff)
Added by laforge about 2 months ago

support for stats static userspace probes via systemtap

We currently only have probes for the logging sub-system.

This patch adds two tracepoints for tracing the performance
impact of statistics reporting: stat_start and stat_done.

They can be used to trace the amount of time a libosmocore-using
application spends in reporting/exporting statistics. This includes
both the CPU time for encoding the statistics, as well as the system
calls for sending them.

Change-Id: I7208c45f6d051505dd2435305c67b4d26c0b1dd2
Related: OS#4311
Related: SYS#4877

History

#1 Updated by fixeria over 1 year ago

ACK. I observed the described behaviour in tmux while being in "scroll" (Ctrl + Mod + [) mode. Maybe we can solve this problem by introducing write queues?

#2 Updated by laforge over 1 year ago

This is pretty much the expected behavior for virtually any program, I would say.

If the program logs to stdout/stderr, then it relies on those file descriptors to be
writable everyy so often. If they are blocked on the reader side, then (after filling some glibc buffering)
things will stall.

I don't really see this as an Osmocom specific problem, or as a problem at all. I mean, what are
we supposed to do? Allocate ever-growing buffers until we are OOM? Throw away output messages
despite file descriptor / pipe / stream semantics don't normally do that?

If you don't disable stdout/stderr, or don't redirect it to /dev/null, you better keep reading from it.

#3 Updated by laforge over 1 year ago

On Fri, Dec 06, 2019 at 01:40:46PM +0000, fixeria [REDMINE] wrote:

ACK. I observed the described behaviour in tmux while being in "scroll" (Ctrl + Mod + [) mode. Maybe we can solve this problem by introducing write queues?

but then how do you size those queues and prevent against OOM? Without
knowing what is stopping to make stdout/stderr writable, you cannot
really know what the best solution is. If somebody wants to discard the
output, let's have them do that discarding based on their
preference/policy outside of osmo-* ?

#4 Updated by neels over 1 year ago

well, if we "crash" the entire core network just because we can't log to stderr at the moment, then I'd rather drop logging to stderr (and keep logging to gsmtap anyway, in that sense).
It's also a dangerous / non-recoverable situation, in that osmo-x doesn't really crash and gets restarted, it just sits there and hogs the space doing nothing.
Granted, in a systemd service environment that's probably not going to happen (is it?).

It is also often an inconvenience when testing. I would prefer losing stderr logging to the test not working from forgetting to scroll the terminal window.
The current way keeps a sword over your head of "how long am I allowed to read this backscroll before everything breaks down"

Todo: Is there a simple shell magic workaround that could prevent blocking? like '| tee' or something?
(I still always want stderr to also see MNCC domain socket communication,
and a "live" pipe, not cat to file and tail that other file, to see whether the program is still running)

#5 Updated by laforge over 1 year ago

Hi Neels,

On Tue, Dec 10, 2019 at 12:42:07PM +0000, neels [REDMINE] wrote:

well, if we "crash" the entire core network just because we can't log to stderr at the moment, then I'd rather drop logging to stderr (and keep logging to gsmtap anyway, in that sense).

I think this is flawed, sorry. If you configure to write log to any type of output, and that output then
stalls for some reason, then the process stalls. I would consider this the expected behavior of virtually
any 'daemon' style of software.

A logging subsystem that looses events on high system I/O load or otherwise is not worth anything.

How would you ever want to debug anything if you don't know if your debug log contains everything?

Or what if you want to use the log postprocessing for accounting? Or for investigating security incidents?

It's also a dangerous / non-recoverable situation, in that osmo-x doesn't really crash and gets restarted, it just sits there and hogs the space doing nothing.

I would like to invite you to do a test on other 'daemon' style software that is configured to write to stdout (or any file descriptor) for that matter. I would consider this to be perfectly normal behavior for multiple decades.

If a user doesn't want to log to a filedescriptor (with related blocking semantics), he should simply not
configure it and use a non-blocking mechanism like syslog (or GSMTAP) in our case.

Granted, in a systemd service environment that's probably not going to happen (is it?).

I don't know systemd in detail, but I would suppose at some point there could be back-pressure if journald
cannot write sufficiently fast to disk?

It is also often an inconvenience when testing. I would prefer losing stderr logging to the test not working from forgetting to scroll the terminal window.

Once again, I think this argument is (extermely) flawed. If you don't want logging on stdout/stderr, simply disable it.

If you want to ever test or debug or analyze anything, and you cannot know if your log is complete, how would you ever get to any type of reliable result?

The current way keeps a sword over your head of "how long am I allowed to read this backscroll before everything breaks down"

I'm not really following you here. Why would scrolling back in a terminal window block the ability of the
program to write to stdout/stderr? And if so, why would you ever blame anything but said terminal emulator for the results of the actions/

Todo: Is there a simple shell magic workaround that could prevent blocking?

I still don't really understand where the problem is? Why would you (or tools you use) intentionally block the stdout/stderr in the first place? I use 'uxterm' here and I don't recall any situation where I would have accidentially blocked stdout/stderr?

#6 Updated by laforge over 1 year ago

On Tue, Dec 10, 2019 at 12:42:07PM +0000, neels [REDMINE] wrote:

I still believe your argument is in favor of fundamentally breaking unix stream / file semantics.

Todo: Is there a simple shell magic workaround that could prevent blocking? like '| tee' or something?

'buffer' is likely what you want, also see
https://stackoverflow.com/questions/8554568/add-a-big-buffer-to-a-pipe-between-two-commands

#7 Updated by neels over 1 year ago

On Tue, Dec 10, 2019 at 03:33:36PM +0000, laforge [REDMINE] wrote:

I'm not really following you here. Why would scrolling back in a terminal window block the ability of the
program to write to stdout/stderr? And if so, why would you ever blame anything but said terminal emulator for the results of the actions/

I think that indeed this ends up being the cause, which is why I mentioned
urxvt at the start. Probably this terminal fails to do buffer forwards properly
and that's all that I need to fix... using a proper terminal.

I still don't really understand where the problem is? Why would you (or tools you use) intentionally block the stdout/stderr in the first place? I use 'uxterm' here and I don't recall any situation where I would have accidentially blocked stdout/stderr?

Will try uxterm...

#8 Updated by laforge 9 months ago

So when a program is started interactively on a shell, the STDOUT + STDERR go through a pty (virtual tty).

The size of the buffer inside any PTY on Linux is not configurable. It is a hard-coded default of 8192 bytes (see drivers/tty/pty.c:pty_common_install() which calls tty_buffer_set_limit(.., 8192)

So this means, if stderr is in blocking mode (which it is by default, and contrary to other I/O, we don't change this in the Osmocom univers), and we have written 8kBytes of log output, there is a chance that the process blocks until the consumer of the PTY (your xterm, ...) is reading the data.

If I/O redirection is used, there's no PTY at the stderr, but typically a pipe. The size of pipe buffers is configurable, and there are both a soft and a hard system-wide limit on the buffer size. How large that buffer is entirely depends on who creates that pipe, wich is happening outside of the respective osmocom program, for example in the shell. The default size is PIPE_DEF_BUFFERS (16) number of pages (typically 4kByte), so 16*4 = 64kBytes.

Once the amount of log data exceeds 64kBytes, stderr will stall until the consumer has been scheduled to read the data.

#9 Updated by laforge 9 months ago

For the log file target if libosmocore, we are using the default size of the stdio buffered I/O system of glibc, which is a default of only 8kByte. However, we as the application can easily increase it by using setvbuf, and I will be submitting a related patch to libosmocore shortly. I guess file based logging has not yet caused any stalling problems (that we know of) as the kernel I/O system (which has its own buffers) and modern SSD are very fast in consuming the data, so it's much less likely to ever stall.

Related link: https://stackoverflow.com/questions/10904067/in-c-whats-the-size-of-stdout-buffer/36139638#36139638

We could start to buffer log output inside libosmocore it self (put log messages in msgb and put them in a osmo_wqueue, just like we deal with any other data going to sockets or the like. The disadvantages would be:
  • if we crash, whatever log messages happened ahead of the crash may not yet have been written to stderr, and one would have to always manually inspect the log buffer by some kind of gdb scripts. So if you crash without coredump+gdb in place, you will never know what actually happened prior to the crash
  • unless we introduce some kind of queue limit, there is a risk of going out-of-memory.
I would still argue we should not change the stderr logging, but
  • use setvbuf() to configure large amount of buffering for log file logging
  • advise users to generally prefer file (or gsmtap) based logging over stderr, particularly when configuring a lot of log output and particularly in production setup

#10 Updated by laforge 9 months ago

  • Status changed from New to In Progress
  • Assignee set to laforge
  • % Done changed from 0 to 10

#11 Updated by laforge 7 months ago

  • % Done changed from 10 to 70

See also https://lists.osmocom.org/pipermail/openbsc/2020-September/013265.html for a more detailed discussion (with analysis of latencies in various use cases) and https://lists.osmocom.org/pipermail/openbsc/2020-September/013267.html for the very promising results of doing write_queue based non-blocking output on stderr/file log targets

#12 Updated by laforge 7 months ago

  • % Done changed from 70 to 90

#13 Updated by laforge 6 months ago

  • Status changed from In Progress to Stalled

currently blocked as various osmocom applications (at least MSC and BSC) appear to be making assumptions on the quantity of talloc contexts libosmocore allocates internally, which is something this patch series changes.

neels volunteered to resolve those in osmo-msc, as far as I remember.

#14 Updated by laforge 2 months ago

laforge wrote:

currently blocked as various osmocom applications (at least MSC and BSC) appear to be making assumptions on the quantity of talloc contexts libosmocore allocates internally, which is something this patch series changes.

neels volunteered to resolve those in osmo-msc, as far as I remember.

neels, I'd like to get back to this. It's been several months and still the merge of those patches is blocked due to [at least] osmo-msc making assumptions on the number of talloc contexts libosmocore allocates.

#15 Updated by neels 2 months ago

Ah yes, I completely forgot about this. See https://gerrit.osmocom.org/c/osmo-msc/+/22785

#16 Updated by laforge 20 days ago

  • Category set to libosmocore

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)