Log messages can be interrupted between the end of the string and the newline

[rocallahan]

On Linux at least, logging to stderr redirected to a file by the shell, logs emitted by multiple threads can race so that one thread's message is printed between another thread's message and its newline. I guess the newline is printed with a separate syscall, but it shouldn't be.

[KodrAus]

Hi @rocallahan, is this something you're observing on the master branch of env_logger? If not do you want to give that a go and see if it fixes your issue? We're explicitly buffering the log record, including the newline, now before writing to the output.

[rocallahan]

I'm observing it in 0.4.3.

[rocallahan]

I guess 1508458#diff-80398c5faae3c069e4e6aa2ed11b28c0 might have fixed this. I'll try it.

[rocallahan]

Yes, it's fixed. Thanks! Hope you can get this released on crates.io soon :-)

[KodrAus]

Thanks for looking into that @rocallahan. I'm glad to hear the buffering is actually doing its job.

We're just waiting on a new release of the log crate then we can get master on crates.io.

[ia0]

I'm still seeing this issue. Is it worth trying to do a repro-case?

[epage]

We should be locking stdout/stderr and then writing all at once followed by a flush. Reproduction steps would be good to see where things might be going wrong.

[ia0]

# Cargo.toml
[package]
name = "bug"
version = "0.1.0"
edition = "2021"

[dependencies]
anyhow = "1.0.86"
env_logger = "0.11.3"
tokio = { version = "1.40.0", features = ["full"] }
usb-device = "0.3.2"
usbip-device = "0.2.0"

// src/main.rs
use anyhow::{ensure, Result};
use tokio::process::{Child, Command};
use usb_device::class_prelude::UsbBusAllocator;
use usb_device::device::StringDescriptors;
use usb_device::prelude::{UsbDevice, UsbDeviceBuilder, UsbVidPid};
use usbip_device::UsbIpBus;

#[tokio::main]
async fn main() -> Result<()> {
    env_logger::init();
    let mut state = Usb::default();
    ensure!(
        spawn(&["sudo", "modprobe", "vhci-hcd"])
            .wait()
            .await?
            .code()
            == Some(0),
        "failed to load kernel module for USB/IP"
    );
    let mut usbip = spawn(&["sudo", "usbip", "attach", "-r", "localhost", "-b", "1-1"]);
    loop {
        state.poll();
        match usbip.try_wait().unwrap() {
            None => continue,
            Some(e) => ensure!(e.code() == Some(0), "failed to attach remote USB/IP device"),
        }
        break;
    }
    println!("Board initialized. Starting scheduler.");
    Ok(())
}

fn spawn(cmd: &[&str]) -> Child {
    Command::new(cmd[0]).args(&cmd[1..]).spawn().unwrap()
}

pub struct Usb {
    pub usb_dev: UsbDevice<'static, UsbIpBus>,
}

impl Default for Usb {
    fn default() -> Self {
        let usb_bus = Box::leak(Box::new(UsbBusAllocator::new(UsbIpBus::new())));
        let usb_dev = UsbDeviceBuilder::new(usb_bus, UsbVidPid(0x16c0, 0x27dd))
            .strings(&[StringDescriptors::new(usb_device::LangID::EN).product("Wasefire")])
            .unwrap()
            .build();
        Self { usb_dev }
    }
}

impl Usb {
    pub fn poll(&mut self) -> bool {
        self.usb_dev.poll(&mut [])
    }
}

When running RUST_LOG=info cargo run, I get:

    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.04s
     Running `target/debug/bug`
[2024-10-02T08:34:38Z INFO  usbip_device] usb device is being enabled
[2024-10-02T08:34:38Z INFO  usbip_device::handler] new connection from: 127.0.0.1:58088
                                                                                       [2024-10-02T08:34:38Z INFO  usbip_device::op] received request to connect device 1-1
                                                         [2024-10-02T08:34:38Z INFO  usbip_device::handler] device is leaving reset state
                       Board initialized. Starting scheduler.

Can you confirm you can reproduce?

Also, is this example small enough or should I try to remove the USB dependencies?

(Note that the missing newline is temporary, when hammering with logs, the newlines are initially present, then they are absent, and then they are back.)

[epage]

It'd be nice to run a code sample hat does not call sudo.

[ia0]

This is sadly not possible, which actually means the problem is sudo (in particular it's not env_logger, sorry). I managed to remove all dependencies:

use std::process::{Child, Command, Stdio};

fn main() {
    let skip = std::env::var_os("NO_SUDO").is_some() as usize;
    let mut child = spawn(&["sudo", "sleep", ".3"][skip..]);
    println!("x");
    while child.try_wait().unwrap().is_none() {
        std::thread::sleep(std::time::Duration::from_millis(100));
        println!("y");
    }
    println!("z");
}

fn spawn(cmd: &[&str]) -> Child {
    let mut command = Command::new(cmd[0]);
    if std::env::var_os("NO_STDIN").is_some() {
        command.stdin(Stdio::null());
    }
    command.args(&cmd[1..]).spawn().unwrap()
}

The issue is exactly when using sudo and inheriting stdin.

% cargo run   
   Compiling bug v0.1.0 (/home/julien/tmp/foo)
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.14s
     Running `target/debug/bug`
x
y
 y
  y
   y
z
% NO_SUDO= cargo run
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.00s
     Running `target/debug/bug`
x
y
y
y
y
z
% NO_STDIN= cargo run
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.00s
     Running `target/debug/bug`
x
y
y
y
y
z

I'm sorry for the noise and thanks for the rubberducking.