examples/kprobetcp shows no output

Question

examples/kprobetcp shows no output

Closed this issue 2 years ago · 9 comments

Hi,

I try to run examples/kprobetcp and it compiles well, but it shows no output. I can only cancel it with Ctrl-C. Am I overseeing some logging configuration?
I did not do any modifications to this program. I suspect that the program is working, but the Terminal output is not shown properly, see also below.

Background:
I actually try to develop a uprobe. This works so far well and I can run it, but I do not use env_logger::init();, but instead

  TermLogger::init(
        LevelFilter::Debug,
        ConfigBuilder::new()
            .set_target_level(LevelFilter::Error)
            .set_location_level(LevelFilter::Error)
            .build(),
        TerminalMode::Mixed,
        ColorChoice::Auto,
    )?;

Then I can see log message from my application (if I use env_logger::init(); I do not see anything). However, everything from the eBPF program is not visible except the log level:

23:12:10 [INFO] uprobe_libcall_filter_app: [src/main.rs:67] Configuring operation filter
23:12:10 [INFO] uprobe_libcall_filter_app: [src/main.rs:69] Configuring application: curl
23:12:10 [INFO] uprobe_libcall_filter_app: [src/main.rs:70] Configuring application cmd: /usr/bin/curl
23:12:10 [INFO] uprobe_libcall_filter_app: [src/main.rs:71] Configuring application cmd args: ["-6", "https://example.org"]
23:12:10 [INFO] uprobe_libcall_filter_app: [src/main.rs:72] Configuring application openssl_lib: /usr/lib64/libssl.so.1.1
23:12:10 [INFO] uprobe_libcall_filter_app: [src/main.rs:88] Waiting for Ctrl-C...
23:12:17 [INFO] uprobe_libcall_filter: [src/main.rs:17] 
23:12:17 [INFO] uprobe_libcall_filter: [src/main.rs:17] 
23:12:17 [INFO] uprobe_libcall_filter: [src/main.rs:17] 
23:12:17 [INFO] uprobe_libcall_filter: [src/main.rs:17] 
23:12:17 [INFO] uprobe_libcall_filter: [src/main.rs:17] 
23:12:17 [INFO] uprobe_libcall_filter: [src/main.rs:17] 
23:12:17 [INFO] uprobe_libcall_filter: [src/main.rs:17] 
23:12:17 [INFO] uprobe_libcall_filter: [src/main.rs:17] 
^C23:12:20 [INFO] uprobe_libcall_filter_app: [src/main.rs:90] Exiting...

It should actually display for the lines

23:12:17 [INFO] uprobe_libcall_filter: [src/main.rs:17]

A log message from the uprobe:

/// returns 0 if probe successfully executed, 1 if not
#[uprobe(name = "osslreadprobe")]
pub fn openssl_read_probe(ctx: ProbeContext) -> u32 {
   info!(
        &ctx,
        "UProbe OpenSSL Read"
    ); 
   return 0;
}

Any idea why? Am I missing some Terminal configuration.

Answer 1 · 2023-01-23T23:25:29.000Z

Edit, ok solved the issue with the kprobe: You need to execute it as follows:

RUST_LOG=info cargo xtask run --release

See: https://github.com/aya-rs/book/pull/84/files

Answer 2 · 2023-01-23T23:25:34.000Z

When you run the program using env_logger rather than TermLogger, how are you running it? What is the value of the RUST_LOG environment variable during execution?

Answer 3 · 2023-01-23T23:25:53.000Z

Whoops never mind, glad you found your solution 🖖

Answer 4 · 2023-01-23T23:36:20.000Z

Thanks a lot though! Also it solves the example, I have not solved my uprobe issue :(
I have the following uprobe:

 ![no_std]
#![no_main]

#[allow(non_upper_case_globals)]
#[allow(non_snake_case)]
#[allow(non_camel_case_types)]
#[allow(dead_code)]

use aya_bpf::{
    macros::uprobe, macros::uretprobe, programs::ProbeContext,
};
use aya_log_ebpf::{info,warn};

/// returns 0 if probe successfully executed, 1 if not
#[uprobe(name = "osslreadprobe")]
pub fn openssl_read_probe(ctx: ProbeContext) -> u32 {
   info!(
        &ctx,
        "UProbe OpenSSL Read"
    ); 
   return 0;
}

And the following application loading it:


    env_logger::init();
 #[cfg(debug_assertions)]
    let mut bpf = Bpf::load(include_bytes_aligned!(
        "../../uprobe-libcall-filter-ebpf/target/bpfel-unknown-none/debug/uprobe-libcall-filter"
    ))?;
    #[cfg(not(debug_assertions))]
    let mut bpf = Bpf::load(include_bytes_aligned!(
        "../../uprobe-libcall-filter-ebpf/target/bpfel-unknown-none/release/uprobe-libcall-filter"
    ))?;
    if let Err(e) = BpfLogger::init(&mut bpf) {
        // This can happen if you remove all log statements from your eBPF program.
        warn!("failed to initialize eBPF logger: {}", e);
    }
[..]
                let program: &mut UProbe =
                bpf.program_mut("osslreadprobe").unwrap().try_into()?;
                program.load()?;
                program.attach(Some("SSL_read"), 0,application_definition.openssl_lib, None)?;

While now the logging output is shown - I do get only the log level from the EBPF - not the log message. Running it with RUST_INFO before now:

23:12:10 [INFO] uprobe_libcall_filter_app: [src/main.rs:67] Configuring operation filter
23:12:10 [INFO] uprobe_libcall_filter_app: [src/main.rs:69] Configuring application: curl
23:12:10 [INFO] uprobe_libcall_filter_app: [src/main.rs:70] Configuring application cmd: /usr/bin/curl
23:12:10 [INFO] uprobe_libcall_filter_app: [src/main.rs:71] Configuring application cmd args: ["-6", "https://example.org"]
23:12:10 [INFO] uprobe_libcall_filter_app: [src/main.rs:72] Configuring application openssl_lib: /usr/lib64/libssl.so.1.1
23:12:10 [INFO] uprobe_libcall_filter_app: [src/main.rs:88] Waiting for Ctrl-C...
23:12:17 [INFO] uprobe_libcall_filter: [src/main.rs:17] 
23:12:17 [INFO] uprobe_libcall_filter: [src/main.rs:17] 
23:12:17 [INFO] uprobe_libcall_filter: [src/main.rs:17] 
23:12:17 [INFO] uprobe_libcall_filter: [src/main.rs:17] 
23:12:17 [INFO] uprobe_libcall_filter: [src/main.rs:17] 
23:12:17 [INFO] uprobe_libcall_filter: [src/main.rs:17] 
23:12:17 [INFO] uprobe_libcall_filter: [src/main.rs:17] 
23:12:17 [INFO] uprobe_libcall_filter: [src/main.rs:17] 
^C23:12:20 [INFO] uprobe_libcall_filter_app: [src/main.rs:90] Exiting...

So I can confirm that the uprobe is triggered ( I trigger curl and the INFO messages show up and the right times), but the message is not displayed.

Maybe I should create the issue under the aya project?

Answer 5 · 2023-01-24T00:14:53.000Z

Just wanted to share in case it is helpful that you can use ```rust when creating code blocks to get syntax highting:

#[uprobe(name = "osslreadprobe")]
pub fn openssl_read_probe(ctx: ProbeContext) -> u32 {
   info!(
        &ctx,
        "UProbe OpenSSL Read"
    ); 
   return 0;
}

On first glance it's not clear to me why it's omitting the contents from your info!() logs though 🤔

Once sec I'll go try the example out locally too...

Answer 6 · 2023-01-24T00:48:16.000Z

Alright, so first I just tried the example and it was logging properly, then I converted it to a uprobe with this eBPF code:

#![no_std]
#![no_main]

#[allow(non_upper_case_globals)]
#[allow(non_snake_case)]
#[allow(non_camel_case_types)]
#[allow(dead_code)]
mod binding;

use aya_bpf::{macros::uprobe, programs::ProbeContext};
use aya_log_ebpf::info;

#[uprobe(name = "osslreadprobe")]
pub fn openssl_read_probe(ctx: ProbeContext) -> u32 {
    info!(&ctx, "UProbe OpenSSL Read");
    return 0;
}

#[panic_handler]
fn panic(_info: &core::panic::PanicInfo) -> ! {
    unsafe { core::hint::unreachable_unchecked() }
}

And this loader code:

use aya::{include_bytes_aligned, programs::UProbe, Bpf};
use aya_log::BpfLogger;
use clap::Parser;
use log::{info, warn};
use tokio::signal;

#[derive(Debug, Parser)]
struct Opt {}

#[tokio::main]
async fn main() -> Result<(), anyhow::Error> {
    let _opt = Opt::parse();

    env_logger::init();

    // This will include your eBPF object file as raw bytes at compile-time and load it at
    // runtime. This approach is recommended for most real-world use cases. If you would
    // like to specify the eBPF program at runtime rather than at compile-time, you can
    // reach for `Bpf::load_file` instead.
    #[cfg(debug_assertions)]
    let mut bpf = Bpf::load(include_bytes_aligned!(
        "../../target/bpfel-unknown-none/debug/kprobetcp"
    ))?;
    #[cfg(not(debug_assertions))]
    let mut bpf = Bpf::load(include_bytes_aligned!(
        "../../target/bpfel-unknown-none/release/kprobetcp"
    ))?;
    if let Err(e) = BpfLogger::init(&mut bpf) {
        // This can happen if you remove all log statements from your eBPF program.
        warn!("failed to initialize eBPF logger: {}", e);
    }
    let program: &mut UProbe =
        bpf.program_mut("osslreadprobe").unwrap().try_into()?;
    program.load()?;
    program.attach(Some("SSL_read"), 0, "/usr/lib64/libssl.so.3", None)?;

    info!("Waiting for Ctrl-C...");
    signal::ctrl_c().await?;
    info!("Exiting...");

    Ok(())
}

(note: I just left the name as kprobetcp 🤷)

And then ran it:

$ RUST_LOG=info cargo xtask run --release

and then ran curl:

$ curl https://kernel.org

And I did get the expected log output:

$ RUST_LOG=info cargo xtask run --release
    Finished release [optimized] target(s) in 1.84s
   Compiling kprobetcp v0.1.0 (/home/shane/Code/book/examples/kprobetcp/kprobetcp)
    Finished release [optimized] target(s) in 1.80s
[2023-01-24T00:37:28Z INFO  kprobetcp] Waiting for Ctrl-C...
[2023-01-24T00:37:30Z INFO  kprobetcp] UProbe OpenSSL Read
[2023-01-24T00:37:30Z INFO  kprobetcp] UProbe OpenSSL Read
[2023-01-24T00:37:30Z INFO  kprobetcp] UProbe OpenSSL Read
[2023-01-24T00:37:30Z INFO  kprobetcp] UProbe OpenSSL Read
[2023-01-24T00:37:30Z INFO  kprobetcp] UProbe OpenSSL Read
^C[2023-01-24T00:37:33Z INFO  kprobetcp] Exiting...

So unless I'm missing something, it's not entirely clear to me yet why yours is not logging 🤔

If you'd like to try it, I pushed the entire program up into a branch here: https://github.com/shaneutt/book/tree/uprobe

If you continue to run into trouble and can't get it to work: yeah I think maybe putting another separate issue into the main repository make sense.

Answer 7 · 2023-01-24T19:05:10.000Z

thanks a lot for testing and all the effort. I am sure it is only related to some of my settings and will probably start from scratch again...

After that I will add it to my experiences with Aya and eBPF in general: https://github.com/ZuInnoTe/rust-ebpf-localnet-kernel-filter-study

Answer 8 · 2023-01-24T19:43:26.000Z

I found the issue. I used as a dependency in Cargo.lock: git+https://github\.com/aya-rs/aya\?branch=main#1899d5f4fd3ec5d91e40a94d671a7756125a4487

You used an older version: git+https://github.com/aya-rs/aya?branch=main#b3ae7786d335fd0294a6ddecf3f31ef28d56af9d

I think some of the commits in-between corrupted something.

Will create an issue in the aya project.

Thanks a lot again!

Answer 9 · 2023-01-24T21:37:24.000Z

Np, glad you found the problem! 🥂