Logging

You turn on the SDK’s log events, choose which targets are loud, and learn which failures are returned to you and which are only ever logged.

cargo run -p vrobots-examples --bin ex20_logging_tour
./target/cpp-build/ex20_logging_tour
python examples/python/ex20_logging_tour.py
RUST_LOG=vrobots_sdk=debug cargo run -p vrobots-examples --bin ex20_logging_tour

If a connect hangs, RUST_LOG=vrobots_sdk=debug is the answer. The rest of this page is why that works and what else the setting is good for.

RUST_LOG is read by the Rust crate’s init_logging, so the other two surfaces turn the volume up in their own idiom instead. Python routes the same events into the standard logging module, so vrsdk.init_logging("debug") (or raising the vrobots_sdk logger’s level yourself) is the equivalent. C++ registers a handler with vrsdk::set_log_callback and then calls vrsdk::set_log_level(vrsdk::LogLevel::Debug).

Turning it on

One function, and the only thing about it worth memorising is that it can decline to act:

crates/vrobots-sdk/src/logging.rs:

#![allow(unused)]
fn main() {
pub fn init_logging(filter: &str)
}

include/vrobots_sdk.hpp:

using LogHandler = void (*)(LogLevel level, const char* target, const char* message);

inline void set_log_callback(LogHandler handler)

inline void set_log_level(LogLevel level)

vrsdk/__init__.py:

def init_logging(
    level: _Union[str, int] = "info",
    *,
    format: str = _LOG_FORMAT,  # noqa: A002 - mirrors logging.basicConfig
) -> None:

This is where the three surfaces diverge most. Rust registers a handler that prints each event to standard output. Python needs nothing of the kind: importing vrsdk already bridges the core’s events into the standard logging module, so init_logging is logging.basicConfig plus raising the vrobots_sdk logger’s level, and an application that configures logging itself can skip it entirely. C++ has no logging framework to plug into, so you register a function pointer with set_log_callback and set the floor with set_log_level; registration is process-wide and nullptr unregisters.

In Rust, init_logging returns nothing and cannot fail. It registers its printing handler with the filter you pass, and does nothing if a handler is already registered, whether by an earlier call or by set_log_callback. That matters twice: a handler of your own always wins over the one-liner, and calling it a second time from somewhere else in your program cannot fight the first call.

examples/rust/src/bin/ex20_logging_tour.rs:

#![allow(unused)]
fn main() {
    vrobots_sdk::init_logging(FILTER);
    println!("log filter: {FILTER:?} (RUST_LOG overrides it)\n");

    // Calling it twice is harmless: the second call finds a handler already
    // registered and returns. Same reason it is safe to call from a library
    // consumer's main.
    vrobots_sdk::init_logging("error");
}

examples/cpp/ex20_logging_tour.cpp:

        // Register BEFORE connecting: connect is the noisiest and most
        // diagnostic moment, and a hang with no log is the hardest thing to
        // debug.
        vrsdk::set_log_callback(on_log);
        vrsdk::set_log_level(vrsdk::LogLevel::Debug);
        std::printf("log callback registered at level %s\n\n",
                    vrsdk::to_string(vrsdk::LogLevel::Debug));

examples/python/ex20_logging_tour.py:

# zenoh's crates log under several sibling roots; hold them at WARNING before turning the SDK up.
for name in ("zenoh", "zenoh_transport", "zenoh_config", "zenoh_codec", "iceoryx2", "tracing"):
    logging.getLogger(name).setLevel(logging.WARNING)

# logging.basicConfig(level=...) plus raising the vrobots_sdk logger's level.
vrsdk.init_logging("debug")

init_logging ends by clearing the extension’s cache of each Python logger’s level, which the bridge keeps so it can filter records without taking the GIL. The script sets the transport loggers’ levels first and calls init_logging last, so the cache is cleared after every level change and all of them are in force before connect.

Only Rust’s call is idempotent by declining to act. C++ and Python are both last-write-wins: a second set_log_callback replaces the handler, and a second init_logging re-raises the level. Both examples configure logging before connect, which is the noisiest and most diagnostic moment.

The second call has no effect at all, and the filter stays at the first one.

Three ways to decide where events go:

Way	When to use it
`init_logging("info")`	Binaries and examples. One line, and it yields to a handler already registered.
`RUST_LOG` in the environment	Changing the volume of a program you do not want to edit. It overrides the argument entirely.
`set_log_callback` with a handler of your own, registered before the SDK is used	Production. Skip `init_logging` and forward each `LogEvent` wherever you like: the `log` or `tracing` crates, JSON, a file. The handler runs on SDK threads, so keep it quick and never call back into the SDK from it.

The filters worth knowing

The filter syntax is RUST_LOG’s, per target, comma separated.

Setting	Use
`vrobots_sdk=debug`	A `connect` that hangs. Shows the session opening, the probe and the wait for the first sample.
`vrobots_sdk=debug,zenoh=warn`	What ex20 uses: the SDK’s debug lines plus zenoh’s warnings, which a filter naming only `vrobots_sdk` would switch off. The library holds zenoh and iceoryx2 at `warn` whatever you ask, so `zenoh=info` adds nothing.
`vrobots_sdk=trace`	Every publish, one line per command.
`off`	Silence.
`warn`	The `vrobots` CLI’s default.

iceoryx2 has a logger of its own

iceoryx2’s native logger writes to stderr, apart from the SDK’s events, and no RUST_LOG setting touches it. The SDK turns it down to Error when it creates its node, because iceoryx2 is chatty about conditions the SDK already handles: a service that is not published yet, a stale registry record.

IOX2_LOG_LEVEL is the environment variable that turns it back up, and the SDK honours it rather than overriding it. Set it when a camera stream will not pair and you need to see the version and QoS negotiation that failed.

Gotcha. RUST_LOG=trace produces nothing at all from iceoryx2, and IOX2_LOG_LEVEL produces nothing from the SDK. They are two separate systems writing to two separate places. Set both when debugging a camera.

Two channels, and they mean different things

The distinction the SDK draws is between what you asked for and what it did on your behalf.

Channel	Carries	How you see it
Returned errors	Things you did or asked for that could not be done: a pulse width outside the band, a camera that does not exist, a service with no responder.	A `Result<_, VrError>` value. Never only in a log.
Log events	Things the SDK did for you: opening a session, waiting for a first sample, retrying a service, dropping a malformed payload, reconfiguring a camera that was already mounted.	Log lines, once something receives them: `init_logging` or your own handler in Rust, the `logging` module in Python, your callback in C++.

Nothing in the SDK waits, retries or drops silently, and the events are where that shows up. Ignore them and a hang has no explanation.

The Rust and C++ examples demonstrate the first channel with an argument that is refused rather than clamped:

#![allow(unused)]
fn main() {
    match robot.set_mr_pwm([0.7; 4]) {
        // 0.7 is a normalised throttle, not a pulse width. The SDK refuses it
        // before publishing rather than clamping, because a clamped 0.7 would
        // look like a valid idle command.
        Ok(()) => println!("   unexpected: 0.7 us was accepted"),
        Err(e) => println!("   [{}] {} -- {}", e.code(), e.kind(), e.detail()),
    }
}

examples/cpp/ex20_logging_tour.cpp:

        std::printf("\n-- an error is thrown, not logged:\n");
        try {
            // 0.7 is a normalised throttle, not a pulse width. The SDK refuses
            // it before publishing rather than clamping, because a clamped 0.7
            // would look like a valid idle command.
            robot.set_mr_pwm({0.7, 0.7, 0.7, 0.7});
            std::printf("   unexpected: 0.7 us was accepted\n");
        } catch (const vrsdk::Error& e) {
            std::printf("   [%d] %s -- %s\n", e.code(), e.name(), e.what());
        }

The channel is the same; the delivery is not. Rust returns the refusal as a Result you match on, while C++ throws vrsdk::Error, so its example wraps the call in a try. Both pass the four pulse widths as an array.

-- an error is returned, not logged:
   [2] invalid_argument -- pwm[0] = 0.7 is outside the 1100-2000 us pulse-width band (neutral is 1500; values look like microseconds, not normalised units)

Nothing about that appears in the log at any filter level. It is a value, and the only place a value can go is your match.

The third case: counted, never raised

A malformed state payload is neither of the two. It is logged as a warning, counted in stats(), stored in last_error(), and not returned from states(), because one bad frame must not end a flight.

#![allow(unused)]
fn main() {
    let stats = robot.stats();
    println!(
        "\n-- counted rather than raised: received={} decode_errors={} last_error={}",
        stats.received,
        stats.decode_errors,
        match robot.last_error() {
            Some(e) => format!("[{}] {e}", e.code()),
            None => "none".to_string(),
        }
    );
}

examples/cpp/ex20_logging_tour.cpp:

        const vrsdk_state_stats_t st = robot.stats();
        const std::optional<vrsdk::Error> err = robot.last_error();
        std::printf("\n-- counted rather than thrown: received=%llu decode_errors=%llu ",
                    static_cast<unsigned long long>(st.received),
                    static_cast<unsigned long long>(st.decode_errors));
        std::printf("last_error=%s\n", err ? err->what() : "none");

examples/python/ex20_logging_tour.py:

# Malformed payloads are logged and counted, never raised from `states`.
st = mr.stats
err = mr.last_error
print(
    f"received={st.received} decode_errors={st.decode_errors} last_error="
    + ("none" if err is None else f"[{err.code}] {err.detail}")
)

stats and last_error are methods in Rust and C++ and properties in Python. The absent error is Option in Rust, std::optional<vrsdk::Error> in C++ and None in Python, and in none of the three does reading it raise.

-- counted rather than raised: received=10 decode_errors=0 last_error=none

The Python script prints the same fields without the -- counted rather than raised: prefix, then two lines counting the log records its own CountingHandler saw, by level and by logger.

A non-zero decode_errors beside a non-empty last_error() is almost always schema drift between this build and the simulator’s, which is Versions and pins.

Next: Measuring rates

Keyboard shortcuts

VRobots Book

Logging

Turning it on

The filters worth knowing

iceoryx2 has a logger of its own

Two channels, and they mean different things

The third case: counted, never raised