how to use within dynamic libraries ?

[XopheD]

Hi,

I develop an application based on dynamic loading. I don’t understand how to do to display log messages generated by the loaded modules. I misunderstood probably stg.

To play with the joined example :

• go to dynlib, then cargo build
• go to main, then cargo run

The main program loads the dynamic library libdynlib and launches f(), the loaded function.
Unfortunately, the log::info! message inside f() is not displayed.

Rusty regards,

dynlog.zip

[KodrAus]

Hi @XopheD 👋

Are you happy to upload your sample as a GitHub Gist or public repository?

Are you initializing your app with a call to log::set_boxed_logger?

[ratijas]

Since the question was about using log with dynamic libraries, not implementing your own logger, I removed custom logger implementation from your example and replaced it with a popular simple_logger backend.

Also, I packed two crates into a workspace, so it can be built and run with a single cargo command. Now, because they are members of the same workspace, we can replace complex relative paths with a simple let path = "libdynlib.so"; Or, if you want to be extra paranoid, use std::env::current_exe():

let exe = std::env::current_exe().unwrap();

#[cfg(any(target_os = "unix", target_os = "linux"))]
let path = "libdynlib.so";
#[cfg(target_os = "macos")]
let path = "libdynlib.dylib";

let lib_full_path = exe.parent().expect("executable must be in a parent directory").join(path);

dynlog - stripped but still doesn't work.zip (update: repository link)

Alter all that trouble, we can verify, that logging is indeed does not work in cdylib:

❯ cargo run --bin main
    Finished dev [unoptimized + debuginfo] target(s) in 0.06s
     Running `target/debug/main`
INFO  [main] Hello, world!
INFO  [main] dyn lib is loaded
INFO  [main] f() is loaded
f() is called...
INFO  [main] all is done...

This line in dynlib/src/lib.rs does nothing:

// this is not printed... unfortunately
log::info!("log is working... yes !!");

There's a good reason for that. They are being compiled absolutely separately, with very little in common. In fact, compiler pulls libraries and generates duplicate code for all types, functions and other stuff. Thus, log in lib has nothing to do with log in main. If you don't initialize logging in lib with some backend, it won't automagically cross FFI and dlsym boundaries and won't print anything.

Take a look here:

log/src/lib.rs

Lines 347 to 367 in 9d42067

	// The LOGGER static holds a pointer to the global logger. It is protected by
	// the STATE static which determines whether LOGGER has been initialized yet.
	static mut LOGGER: &dyn Log = &NopLogger;
	static STATE: AtomicUsize = AtomicUsize::new(0);
	// There are three different states that we care about: the logger's
	// uninitialized, the logger's initializing (set_logger's been called but
	// LOGGER hasn't actually been set yet), or the logger's active.
	const UNINITIALIZED: usize = 0;
	const INITIALIZING: usize = 1;
	const INITIALIZED: usize = 2;
	static MAX_LOG_LEVEL_FILTER: AtomicUsize = AtomicUsize::new(0);
	static LOG_LEVEL_NAMES: [&str; 6] = ["OFF", "ERROR", "WARN", "INFO", "DEBUG", "TRACE"];
	static SET_LOGGER_ERROR: &str = "attempted to set a logger after the logging system \
	was already initialized";
	static LEVEL_PARSE_ERROR: &str =
	"attempted to convert a string that doesn't match an existing log level";

If these variables were global/exported/no mangle, only then it would be possible to share runtime logging preferences among shared and dlopen-loaded libraries. But then it would've created various compatibility issues between different versions of log crate and between incompatible (undocumented and non-existent) rust ABIs.

Note that such problems do not exist e.g. in Java world, where everything runs on the same instance of JVM, and a mere idea of separately loading packages with all their dependencies into their own memory and address space is absurd. Unless you manage to spin off a second JVM instance (perhaps a different implementation, since VMs often do use global variables). In which case we would be back at square one: not only logging, but any objects would be impossible to pass back and forth without marshaling through JNI (Java Native Interface) glue.

So, unless you are willing to do some weird unsound ffi, it is totally up to a you as a developer to ensure consistent logging in Rust cdylibs.

The best you could do, it to add a normal Rust crate to your workspace, which contains all logging initialization. Add this crate as a dependency to each cdylib crate, and include an initialization routine. For example, in Qt QML extension plugin the initialization could be done at type registration time:

impl QQmlExtensionPlugin for QExampleQmlPlugin {
    fn register_types(&mut self, uri: &std::ffi::CStr) {
        my_shared_logging::init().unwrap();  // <- added initialization
        qml_register_type::<TimeModel>(uri, 1, 0, cstr!("Time"));
    }
}

Once final thought. We could go one layer deeper by factoring out common logging settings in an actual dcylib, while each plugin and exe would merely forward logging requests through well-defined FFI. Some research has been done in this direction already.

You gonna need:

• log forwarder with stable extern "C" API, and a Rust wrappers with log::Log implementation;
• micro crate (rlib) with initialization routine, which sets up (cdylib-local) log with a forwarder;
• actual shared cdylib which implements log forwarder extern functions, and initializes any fancy logger you want.

Now binary and plugins only need to dynamically (but not via dlopen) link to the shared logging cdylib. All the logic was extracted from them, and only forwarding stubs remain. Shared lib is, on the other hand, well, shared — along with its log preferences — once per process. The only trick is to design FFI-compatible log forwarder.

Let's try it out! With a project tree as follow:

.
├── Cargo.lock
├── Cargo.toml
├── dynlib
│   ├── Cargo.toml
│   └── src
│       └── lib.rs
├── ffi-log
│   ├── Cargo.toml
│   └── src
│       └── lib.rs
├── main
│   ├── Cargo.toml
│   └── src
│       └── main.rs
└── my-cdylib-log
    ├── Cargo.toml
    └── src
        └── lib.rs

Main app executes, sets up log forwarder for itself (which in turn sets up log receiver in "my-cdylib-log"), and then loads "dynlib" which also sets up log forwarder instance in its own memory space. Both forwarders are proxying messages through stable FFI thanks to "ffi-log" types and functions declarations.

❯ cargo build
❯ cd target/debug
❯ LD_LIBRARY_PATH=$(pwd) ./main
INFO  [my_cdylib_log] Initialized cdylib
INFO  [main] Hello, world!
INFO  [main] dyn lib is loaded
INFO  [main] f() is loaded
TRACE [dynlib] initialized logging in dynlib
f() is called...
INFO  [dynlib] log is working... yes !!
INFO  [main] all is done...

dynlog - just works.zip (update: repository link)

As a bonus, valgrind didn't detect any memory leaks.

I've also done some FFI forwarding myself between Rust and Qt in qmetaobject-rs crate. Feel free to check it out :)

PS Actually, it was discussed in #66.

[ratijas]

If my research and code implementation answers the original question, I'd like ask either OP or @rust-lang team — whoever comes first — to close this issue. 😶

I posted the code in my repository for easier browsing experience, and added links to my comment above:

• https://github.com/ratijas/rustc-issues/tree/dynlog-stripped
• https://github.com/ratijas/rustc-issues/tree/dynlog-works

[lazytiger]

If your application and dll are both written in Rust and compiled by the same compiler, you may use the following code.

Just put this file in your application project.

use log::{LevelFilter, Log, Metadata, Record};

#[repr(C)]
pub struct LogParam {
    pub enabled: extern "C" fn(&Metadata) -> bool,
    pub log: extern "C" fn(&Record),
    pub flush: extern "C" fn(),
    pub level: LevelFilter,
}

struct DLog;

static mut PARAM: Option<LogParam> = None;

pub fn init(param: LogParam) {
    let level = param.level;
    unsafe {
        if PARAM.is_some() {
            eprint!("log should only init once");
            return;
        }
        PARAM.replace(param);
    }
    if let Err(err) = log::set_logger(&LOGGER).map(|_| log::set_max_level(level)) {
        eprint!("set logger failed:{}", err);
    }
}

fn param() -> &'static LogParam {
    unsafe { PARAM.as_ref().unwrap() }
}

impl Log for DLog {
    fn enabled(&self, metadata: &Metadata) -> bool {
        (param().enabled)(metadata)
    }

    fn log(&self, record: &Record) {
        (param().log)(record)
    }

    fn flush(&self) {
        (param().flush)()
    }
}

static LOGGER: DLog = DLog;

#[no_mangle]
extern "C" fn enabled(meta: &Metadata) -> bool {
    log::logger().enabled(meta)
}

#[no_mangle]
extern "C" fn log(record: &Record) {
    log::logger().log(record)
}

#[no_mangle]
extern "C" fn flush() {
    log::logger().flush()
}

pub fn log_param() -> LogParam {
    LogParam {
        enabled,
        log,
        flush,
        level: log::max_level(),
    }
}

And then write a function like this in your dll project to be called in the application.

#[no_mangle]
extern "C" fn init_logger(param: LogParam) {
    init(param);
}

When the application opens the dll, just call the init_logger in the application domain like this

init_logger(log_param());

log_param function called in the application, so the function points to the application function.
init function called in the dll, but the param given from the application, so they are the same.

[ratijas]

@lazytiger please, don't advice that. Read my post carefully, and then edit/remove your post. It is very wrong for several reasons.

1. These structures are not extern "C" enabled. Compiler does NOT guarantee anything about their layout, and normally you should've received a warning about non-FFI types.

   #[no_mangle]
   extern "C" fn enabled(meta: &Metadata) -> bool {
       log::logger().enabled(meta)
   }

2. Mutable global, no synchronization primitives, unsafe modifications — this is just dangerous.

   static mut PARAM: Option<LogParam> = None;
   
   unsafe {
       // ...
       PARAM.replace(param);
   }

[lazytiger]

@ratijas Thanks for the reply.

1、If application and dll are both written in Rust, and compiled by the same compiler, it's ok, because Metadata is passed by reference, ie pointer, they are the same layout in memory.

2、Mutable global only used in initialize, so it's ok either

[JakkuSakura]

I have a perfect working solution, much simpler than above.
This is for tracing-log backend, and you can use any backend you want.

How to use

• call build_shared_logger() in your main crate
• call setup_shared_logger() in your dylib. You can call it directly or via dynamic dispatch

Idea

The idea is to forward log::Record and let the compiler address the global variable. To bridge different parts of program, use function pointer like for<'a> extern "C" fn(&'a log::Record<'_>) or vtable

use log::Metadata;
#[repr(C)]
pub struct SharedLogger {
    formatter: for<'a> extern "C" fn(&'a log::Record<'_>),
}
impl log::Log for SharedLogger {
    fn enabled(&self, _: &Metadata) -> bool {
        true
    }
    fn log(&self, record: &log::Record) {
        (self.formatter)(record)
    }
    fn flush(&self) {}
}

pub fn build_shared_logger() -> SharedLogger {
    extern "C" fn formatter(r: &log::Record<'_>) {
        tracing_log::format_trace(r).unwrap()
    }
    SharedLogger { formatter }
}
#[no_mangle]
pub extern "C" fn setup_shared_logger(logger: SharedLogger) {
    if let Err(err) = log::set_boxed_logger(Box::new(logger)) {
        log::warn!("{}", err)
    }
}

[KodrAus]

Thanks for investigating this @ratijas and @qiujiangkun!

I've added a note to the readme about dynamic libraries that links back here and suggests some FFI-safe wrapper.

[thinkphoebe]

I find a simple way. Crate log store a static reference of logger object, they are different viriables in main program and dynamic libraries. The viriables in dynamic libraries are probably uninitialized. Then, pass the value of logger in main program to dynamic libraries and initiate the logger in dynamic libraries will work.

In dynamic libraries file, define a method to initiate logger:

#[allow(dead_code)]
pub type SetupLogger = extern "Rust" fn(
    logger: &'static dyn Log,
    level: LevelFilter,
) -> Result<(), SetLoggerError>;


#[no_mangle]
pub extern "Rust" fn setup_logger(
    logger: &'static dyn Log,
    level: LevelFilter,
) -> Result<(), SetLoggerError> {
    log::set_max_level(level);
    log::set_logger(logger)
}

In main program, get current logger object value and pass to dynamic library:

    let ret = unsafe { lib.get::<SetupLogger>(b"setup_logger") };
    if let Ok(setup_logger) = ret {
        setup_logger(log::logger(), log::max_level())?;
    }

This should be called after logger object inited in main program.

[Bengreen]

I have been going a slightly different but closely related use case to describe above:
I want to have a .so file build in rust that can use the Log module but bind it to the calling parent exe (also written in rust) to make log write operations.
Based on the code from both @ratijas and @lazytiger comments I was initially able to create an 'FFI naughty' version then harden it down to create an 'FFI safe' version of the Logging integration across the FFI boundary.
Thank you to you both for your contributions to this post.

I have one query that I don't quite understand:
I was not able to use the .args() function for the RecordBuilder. I noted that the code here https://github.com/ratijas/rustc-issues/blob/dynlog-works/ffi-log/src/lib.rs#L177 also has this commented out. I had similar issues. Can you share what is driving this?

I followed on down the codebase and found this as the pattern to help solve the issue https://github.com/ratijas/rustc-issues/blob/dynlog-works/ffi-log/src/lib.rs#L195 . However, I don't quite understand what this is doing and why this is necessary to write it with this structure rather than returning the Record object that can be sent direct to the logging function.

Would you be able to provide some commentary to aid my learning.

My equivalent to the code is here.

https://github.com/Bengreen/rusty-microservice/blob/make-so/ffi-log2/src/lib.rs#L242

[ratijas]

Hi, @Bengreen

Thanks for the trip down the memory line. I can barely remember what it was all about about, but let's not waste any time.

I was not able to use the .args() function for the RecordBuilder. I noted that the code here https://github.com/ratijas/rustc-issues/blob/dynlog-works/ffi-log/src/lib.rs#L177 also has this commented out. I had similar issues. Can you share what is driving this?

Here, we are talking about a method on ExternCRecord

impl ExternCRecord {
    pub unsafe fn as_record(&self) -> RecordBuilder {/*...*/}

while ExternCRecord itself is defined above as follow:

#[repr(C)]
pub struct ExternCRecord {
    pub metadata: ExternCMetadata,
    /// fmt::Arguments<'a> are not FFI-safe, so we have no option but to format them beforehand.
    pub message: RustString,
    pub module_path: RustStr, // None points to null
    pub file: RustStr, // None points to null
    pub line: i64, // None maps to -1, everything else should fit in u32.
}

See the comment on pub message? That's it. You can't even store them, let alone pass outside of language boundary. The lifetimes don't really give you any choice but to use the match hack or something similar at the "call site", which is why I build as much of a Record as possible, and — as the final step — format message string as pass it down:

https://github.com/ratijas/rustc-issues/blob/6f39e8efc9023c7d3fbd7c5cea9072db79205b3a/my-cdylib-log/src/lib.rs#L15-L21

pub extern "C" fn rust_log_log(record: &ExternCRecord) {
    let mut builder = unsafe { record.as_record() };
    match format_args!("{}", unsafe { record.message.to_str() }) {
        args => {
            let record = builder.args(args).build();
            log::logger().log(&record);
        }
    }
}

If you inspect the code a bit more, you'll see the uses of as_record() method, as well as precaution measures taken to ensure correct usage of args.

And that's why I'm not a big fan of the other "lazy" approaches posted in this thread. Compiler just does not guarantee that any non-repr(C) structures will be compatible on both ends. You gotta take care, and manually expose yourself literally everything via FFI.