Bug: sporadic termination in a subscription read call

[artemsheinacn]

Description

I found an issue that com terminates sporadically without any error message on com api call. In my com integration in FEO it always terminates on a read call and never on a write call.

Error Occurrence Rate

Highly Intermittent

How to reproduce

1. In com-api-example increase the number of cycles to 50_000_000 (5mil is enough in 90% of cases), like so:

for i in 0..50000000 {
        monitor
            .write_tire_data(Tire {
                pressure: tire_pressure + i as f32,
            })
            .unwrap();
        let tire_data = monitor.read_tire_data().unwrap();
        println!("{tire_data}");
    }

2. Add config file for com-api-example binary, like so:

rust_binary(
    name = "com-api-example",
    srcs = ["basic-consumer-producer.rs"],
    features = ["link_std_cpp_lib"],
    data = ["etc/config.json"],

3. Run with bazelisk run //score/mw/com/example/com-api-example:com-api-example
   It almost always terminates before the full testing cycle without any error message, like so:

Tire data sent
1 samples received: sample[0] = Tire { pressure: 1859653.0 }(base) user@host:~/p/score/communication$

Supporting Information

No response

Classification

minor

Affected Version

0.5

Expected Closure Version

0.5

Category

• Safety Related
• Security Related

[bharatGoswami8]

Hi @artemsheinacn ,

When you have tight loops iterating millions of times, avoid any I/O operations (especially println!). Each I/O operation is expensive at the OS level because it involves system calls to write data to stdout.

This massive I/O overhead caused slowdown, which likely triggered Bazel timeout (or may be OS Timeout due to I/O overhead) that terminated the application before it could complete all iterations.

I checked without println! and able to iterate 50000000 times.

=== Running with Lola runtime ===
Setting tire pressure to 5
Progress: 1000000/50000000 iterations
Progress: 2000000/50000000 iterations
Progress: 3000000/50000000 iterations
Progress: 4000000/50000000 iterations
Progress: 5000000/50000000 iterations
Progress: 6000000/50000000 iterations
Progress: 7000000/50000000 iterations
Progress: 8000000/50000000 iterations
Progress: 9000000/50000000 iterations
Progress: 10000000/50000000 iterations
Progress: 11000000/50000000 iterations
Progress: 12000000/50000000 iterations
Progress: 13000000/50000000 iterations
Progress: 14000000/50000000 iterations
Progress: 15000000/50000000 iterations
Progress: 16000000/50000000 iterations
Progress: 17000000/50000000 iterations
Progress: 18000000/50000000 iterations
Progress: 19000000/50000000 iterations
Progress: 20000000/50000000 iterations
Progress: 21000000/50000000 iterations
Progress: 22000000/50000000 iterations
Progress: 23000000/50000000 iterations
Progress: 24000000/50000000 iterations
Progress: 25000000/50000000 iterations
Progress: 26000000/50000000 iterations
Progress: 27000000/50000000 iterations
Progress: 28000000/50000000 iterations
Progress: 29000000/50000000 iterations
Progress: 30000000/50000000 iterations
Progress: 31000000/50000000 iterations
Progress: 32000000/50000000 iterations
Progress: 33000000/50000000 iterations
Progress: 34000000/50000000 iterations
Progress: 35000000/50000000 iterations
Progress: 36000000/50000000 iterations
Progress: 37000000/50000000 iterations
Progress: 38000000/50000000 iterations
Progress: 39000000/50000000 iterations
Progress: 40000000/50000000 iterations
Progress: 41000000/50000000 iterations
Progress: 42000000/50000000 iterations
Progress: 43000000/50000000 iterations
Progress: 44000000/50000000 iterations
Progress: 45000000/50000000 iterations
Progress: 46000000/50000000 iterations
Progress: 47000000/50000000 iterations
Progress: 48000000/50000000 iterations
Progress: 49000000/50000000 iterations
Completed all 50000000 iterations in 273.09s
Successfully unoffered the service
=== Lola runtime completed ===

[artemsheinacn]

Hi @bharatGoswami8,
I tried to run it with only println and without any com api calls and it still fails, so I made an example where I just initialize the api and then make 50mil println calls and it fails:

fn main() {
    let lola_runtime_builder = init_lola_runtime_builder();
    let lola_runtime = lola_runtime_builder.build().unwrap();
    for i in 0..50000000 {
        println!("Successfully {i}");
    }
    println!("Done");
}

It terminates sporadically like so:

Successfully 6747
Successfully 6748(base) user@host:~/p/score/communication$

If I don't initialize com runtime it works fine:

Successfully 49999999
Done
(base) user@host:~/p/score/communication$

The same in the real integration of com into feo, it works fine without com and it doesn't do any intense IO, but it still failing.
So, it doesn't seem to have anything to do with OS or bazel.

[bharatGoswami8]

Hi @bharatGoswami8, I tried to run it with only println and without any com api calls and it still fails, so I made an example where I just initialize the api and then make 50mil println calls and it fails:

fn main() {
    let lola_runtime_builder = init_lola_runtime_builder();
    let lola_runtime = lola_runtime_builder.build().unwrap();
    for i in 0..50000000 {
        println!("Successfully {i}");
    }
    println!("Done");
}

It terminates sporadically like so:

Successfully 6747
Successfully 6748(base) user@host:~/p/score/communication$

If I don't initialize com runtime it works fine:

Successfully 49999999
Done
(base) user@host:~/p/score/communication$

The same in the real integration of com into feo, it works fine without com and it doesn't do any intense IO, but it still failing. So, it doesn't seem to have anything to do with OS or bazel.

@artemsheinacn , I think ,it is mostly with I/O overhead

thread 'main' (2702488) panicked at library/std/src/io/stdio.rs:1165:9:
failed printing to stdout: Resource temporarily unavailable (os error 11)
note: run with RUST_BACKTRACE=1 environment variable to display a backtrace

If you remove println!("Successfully {i}"); this line then it should work fine.

[artemsheinacn]

@bharatGoswami8 it never happens without mw com runtime initialized, and it also happens when not much I/O is happening in mini-adas feo example, so I'm not sure what do you suggest.
I found info that setting stdout to non-blocking may lead to this error, rust expects it to be blocking and when rust tries to write to stdout it gets the error. Do you know the details on how mw com works with stdout?

[artemsheinacn]

@bharatGoswami8 Does it mean mw com logger is incompatible with Rust standard println APIs and also with score_logging implementation? It seems they can't work together in the same app.

[bharatGoswami8]

@bharatGoswami8 Does it mean mw com logger is incompatible with Rust standard println APIs and also with score_logging implementation? It seems they can't work together in the same app.

No, since you are using the COM‑API, using Rust’s println! within the application is perfectly fine. score_logging can also be used at the application level.
At the moment, the COM‑API itself does not provide any logging support.

[artemsheinacn]

@bharatGoswami8 how is it perfectly fine if it leads to sporadic panics in Rust std? I'm not sure what should I do about it.

[darkwisebear]

@artemsheinacn I had a look at this issue. The panic happens due to println! getting an EAGAIN from the os, and it is designed to panic (TIL!) in case of errors. The reason for the error is the logging framework which configures any file descriptor it is supposed to log to (stdout in this case) to NONBLOCKING.

Workaround for this is to either

• Configure logging to log to a file. In that case, stdout will be blocking, not returning an error
• Replace println! with writeln!, as the latter returns an error instead of panicking.

[artemsheinacn]

Hi @darkwisebear, thanks for the help. When you say the logging framework, it means the logging framework mw com uses internally and that's configured as part of the com runtime initialization, right? If so, I think configuring it to dump to a file is the right way for us to work-around the issue as we're using the official score logging implementation from baselibs_rust and we can't change its implementation. Could you share a snippet with me on how to switch the logging to a file? I wasn't able to find it in docs.