Repository navigation
Conversation
68df7c1 to
5aedd2c
Compare
zaidoon1
changed the title
5aedd2c to
8eb6432
Compare
54917de to
1e09d4f
Compare
systemd connects a service's stdout and stderr to a journald socket and names it in JOURNAL_STREAM. If journald stops reading that socket but keeps it open, as systemd/systemd#44521 describes after a journald restart, every blocking write to it waits for good: the logging thread, then TelemetryDriver::shutdown_logger, and any thread that panics, because the default panic hook writes its message to stderr. When stdout or stderr is the stream JOURNAL_STREAM names, log output to it now goes through a writer that never waits. The writer buffers each record until the formatter flushes it, then sends it with MSG_DONTWAIT, so it doesn't wait even if something sharing the descriptor makes it blocking again. A record that doesn't fit is dropped and counted in logging_records_dropped{reason="journal_full"}. A full stream isn't an I/O error, so it never stops the logging thread, whatever ignore_io_errors is. Other send errors are reported as before and counted as journal_error. When a record is cut short, the next one starts with a newline, so journald doesn't join the two. A JSON record that fails to format is discarded rather than sent with the next one. slog-term flushes a text record even when formatting fails, so that one goes out cut short, on its own line. Initialization also makes those streams nonblocking, whatever the log output is, so the default panic hook and other writers can't wait for journald either. The flag is shared by every process holding the stream. When the stream is full, println! and eprintln! panic and the panic hook's message can be lost. allow_blocking_journal_stdio leaves the streams as they are.
1e09d4f to
83f8949
Compare
| let metadata = unsafe { metadata.assume_init() }; | ||
|
|
||
| metadata.st_mode & libc::S_IFMT == libc::S_IFSOCK | ||
| && journal_stream.as_encoded_bytes() |
There was a problem hiding this comment.
nit: OsStr and str can be compared, needs format().as_str()
There was a problem hiding this comment.
Good catch, it compares against format!(...).as_str() now. Fixed in 380fa72.
| impl<W: AsFd> io::Write for JournalWriter<W> { | ||
| fn write(&mut self, buf: &[u8]) -> io::Result<usize> { | ||
| if self.new_record.load(Ordering::Relaxed) { | ||
| self.new_record.store(false, Ordering::Relaxed); |
There was a problem hiding this comment.
I think this is okay in practice (write happens to be called immediately after store), but this code looks like oops-forgot-a-CAS, so it'd be nice to at least have a comment.
There was a problem hiding this comment.
Yeah fair, it does look like a forgotten CAS. Added a comment in 380fa72. Only the logging thread ever touches that flag: the drain sets it before formatting a record and the first write clears it, so nothing can get in between the load and the store. I kept load + store over a swap so every write after the first one in a record is just a plain read.
When JSON logs go to a stdout or stderr that isn't the journal stream, the drain writes through a File made from fd 1 or 2, and dropping it at shutdown closed the descriptor. The next file or socket opened took that number, so anything written to stderr afterwards, like a panic message, went into it. The writer wraps the File in ManuallyDrop, so dropping the drain leaves the descriptor open, the same as the journal writer does.
The journal writer sends with MSG_DONTWAIT, and send fails with ENOTSOCK if something replaces stdout or stderr with a regular file or a pipe after logging started. With ignore_io_errors off, that stopped the logging thread on the next record, so every log after the swap was lost. On ENOTSOCK the writer writes to the descriptor instead, the same way the other stdout and stderr writers do, so logs follow the redirect.
When the journal stream blocks, a panic on the logging thread can get stuck writing its message in the default panic hook, which holds the hook's lock. A failing assert! in the test then waits for that lock forever, and nextest has no timeout here, so CI would hang instead of reporting the failure. The checks that can run in that state go through fail_without_panicking, like the stalled journal test already does. Also test that the journal writer keeps the buffer of a normal record for the next one and frees the buffer of a huge one.
With ignore_io_errors off, the logging thread stops after the first journal_error, so the counter stays at 1 while every later record is lost. The metric's help text and the DropReason docs say so, so an alert can fire on any increase. ignore_io_errors also says that a full journal stream isn't an I/O error. The allow_blocking_journal_stdio docs say that a stream stays nonblocking until the service restarts, and which of foundations' seccomp allow lists has sendto and fcntl. The comment on the record reset says what each formatter does with a record it fails to finish: JSON never flushes it, so it's discarded, and text flushes it cut short, so it goes out on its own line.
OsStr compares with str directly, so is_journal doesn't need to go through encoded bytes. The record-start flag check in JournalWriter::write is a load followed by a store, which reads like a missing compare-and-swap. A comment explains that only the logging thread touches the flag, and that the load keeps every write after a record's first to a plain read.
aea4837 to
380fa72
Compare
|
@kornelski heads up, I pushed a few more commits after you approved and two of them change behaviour, so I wanted to make sure you saw them. 4c53856 fixes something that's already broken on main. When JSON logs go to stdout or stderr and it isn't the journal, the writer is a c8b7e50 covers stdout or stderr getting replaced after init. If something dup2's a regular file or a pipe over what was the journal stream, The rest is tests and docs. There's a test for the 64KiB buffer cap now, and the journal tests report failures without panicking, because if the nonblocking code ever regressed, a panic stuck in the hook on the full stream would make a test hang instead of fail. The docs now say that I also force pushed once to fix the first commit's message. It said a record that fails to format gets discarded, but that's only true for JSON, slog-term flushes a text one anyway. No code change from that. Would appreciate another look at those two commits when you get a chance. |
Summary
We had some services (not on foundations yet) hang when journald stopped reading their stdout/stderr stream. Once the socket buffer is full, every blocking write to it waits forever: the foundations logging thread (so
shutdown_logger()never returns), and any thread that panics, because the default panic hook writes to stderr. systemd/systemd#44521 fixed one way journald ends up like that, but any other bug that leaves the stream unread has the same effect.This applies when stdout or stderr is the stream named in
JOURNAL_STREAM:If a record only partly fits, the next one starts with a newline so journald doesn't merge them. A JSON record that fails to serialize is thrown away instead of being sent with the next one. A text record that fails goes out cut short on its own line, because slog-term flushes it anyway.
With
ignore_io_errorsoff, which is the default, the firstjournal_errorstops the logging thread like any other output error does. So that counter goes to 1 and stays there, and an alert should fire on any increase. The metric's help text says so.Logger shutdown leaves stdout and stderr open, for the JSON stdout/stderr writer outside the journal case too, so a panic message written after shutdown can't land in whatever file got fd 2 next. That one is its own commit.
Evidence
shutdown_logger()both wait for the journal until the test gives up after 10s. The two shutdown tests fail on main with EBADF.After: all of them pass, the stalled journal one in about 10ms.
println!panicked with EAGAIN like the docs say, a child process saw O_NONBLOCK on its stderr, and shutdown returned. Once journald woke up, the next record landed as its own JSON entry.Merge Danger
Door: two-way
O_NONBLOCK stays on a stream until the service restarts and systemd hands it a new one. Rolling back, or turning on
allow_blocking_journal_stdio, doesn't clear it on a stream that already has it.Blast Radius: services logging to the journal under systemd
O_NONBLOCK is set on the stream itself, so it also applies to
println!/eprintln!(they panic instead of waiting when the stream is full) and to child processes that inherit it.allow_blocking_journal_stdio: trueleaves the stream alone. If seccomp applies to the thread that initializes telemetry, the logging thread needssendtoand init needsfcntl.SERVICE_BASICSdoesn't allowsendto, and it only allowsfcntlin debug builds. The stdout/stderr fd fix applies to any service logging JSON to stdout or stderr.