ffi: allow to change tracing level and callback more than once #1111

kssenii · 2025-07-25T17:11:08Z

new feature PR: "ffi: allow to change event tracing level more than once"

What changes are proposed in this pull request?

#1109

How was this change tested?

Added a new test change_event_tracking_level.

zachschuermann · 2025-08-11T16:18:36Z

hi @kssenii just checking on this PR - it's still marked as draft, do you need reviews, etc.?

kssenii · 2025-08-12T19:35:38Z

@zachschuermann, hi, no, I will undraft when ready for review.

OussamaSaoudi · 2025-09-23T19:24:16Z

ffi/src/ffi_tracing.rs

+        match set_global_default(dispatch.clone()) {
+            Ok(()) => {
+                *locked_state = Some(GlobalTracingState {
+                    dispatch,
+                    reload_handle,
+                    event_callback: Some(event_callback),
+                    log_line_callback: None,
+                });
+                Ok(())
+            }
+            Err(e) => Err(Error::generic(format!(
+                "Unable to set default subscriber: {e}"
+            ))),
+        }


Suggested change

match set_global_default(dispatch.clone()) {

Ok(()) => {

*locked_state = Some(GlobalTracingState {

dispatch,

reload_handle,

event_callback: Some(event_callback),

log_line_callback: None,

});

Ok(())

}

Err(e) => Err(Error::generic(format!(

"Unable to set default subscriber: {e}"

))),

}

set_global_default(dispatch.clone()).map_err(|e| Error::generic(format!(

"Unable to set default subscriber: {e}"

))?;

*locked_state = Some(GlobalTracingState {

dispatch,

reload_handle,

event_callback: Some(event_callback),

log_line_callback: None,

});

Ok(())

OussamaSaoudi · 2025-09-23T20:24:08Z

ffi/src/ffi_tracing.rs

+static TRACING_STATE: LazyLock<Mutex<Option<GlobalTracingState>>> =
+    LazyLock::new(|| Mutex::new(None));
+
+fn get_event_dispatcher(


It seems like this is creating a new one rather than getting an existing one.

Suggested change

fn get_event_dispatcher(

fn create_event_dispatcher(

OussamaSaoudi · 2025-09-23T20:52:55Z

ffi/src/ffi_tracing.rs

+    if let Some(state) = locked_state.as_mut() {
+        if let Some(event_callback) = &state.event_callback {
+            *event_callback.lock().unwrap() = callback;
+        } else {
+            state.event_callback = Some(Arc::new(Mutex::new(callback)));
+        }
+        return state
+            .reload_handle
+            .reload(LevelFilter::from(max_level))
+            .map_err(|e| {
+                warn!("Failed to reload tracing level: {e}");
+                Error::generic(format!("Unable to reload subscriber: {e}"))
+            });
+    } else {
+        let (dispatch, reload_handle, event_callback) = get_event_dispatcher(callback, max_level);
+        match set_global_default(dispatch.clone()) {
+            Ok(()) => {
+                *locked_state = Some(GlobalTracingState {
+                    dispatch,
+                    reload_handle,
+                    event_callback: Some(event_callback),
+                    log_line_callback: None,
+                });
+                Ok(())
+            }
+            Err(e) => Err(Error::generic(format!(
+                "Unable to set default subscriber: {e}"
+            ))),
+        }


We're duplicating the logic to do the following in both setup_event_subscriber and setup_log_line_subscriber:

Get state

If it hasn't been initialized, then initialized it using get_.*_dispatcher. Update state.

If it has been initialized, set callback, perform a reload.

We're also manipulating GlobalTracingState a bunch here. I'd propose to:

Make this functionality part of GlobalTracingState. GlobalTracingState.register_new_callback(event_callback, max_level)

I'd prefer if possible to make GlobalTracingState internally handle the Option. ie:

static TRACING_STATE: LazyLock<Mutex<GlobalTracingState>> = LazyLock::new(|| Mutex::new(GlobalTracingState::uninitiaziled()));

This way, all the tracing handling is done in GlobalTracingState, and we can track where the global state is being modified.

OussamaSaoudi · 2025-09-23T20:56:44Z

ffi/src/ffi_tracing.rs

+        let ok = expected_log_lines.is_empty()
+            || expected_log_lines.iter().any(|expected_log_line| {
+                let res = line_str.ends_with(expected_log_line);
+                //println!("Line: {line_str}, expected: {expected_log_line}, res: {res}");


Suggested change

//println!("Line: {line_str}, expected: {expected_log_line}, res: {res}");

OussamaSaoudi · 2025-09-23T21:06:29Z

ffi/src/ffi_tracing.rs

+
+        // ensure we can setup again with a new callback and a new tracing level
+        unsafe {
+            enable_event_tracing(event_callback_2, Level::DEBUG);


Can we do the following?

enable_event_tracing() enable_log_line_tracing()

From what I gather, this isn't possible.

Yes, not possible (or at least I did not manage to make it work though I tried), I also added related comment here

delta-kernel-rs/ffi/src/ffi_tracing.rs

Lines 810 to 812 in 00aab70

#[test]

#[ignore] // We cannot run this test if test_enable_log_line_tracing was run before - see comment there, however this test works if run individually.

fn test_enable_event_tracing() {

…nt-tracing-level

codecov · 2025-09-29T22:42:05Z

Codecov Report

❌ Patch coverage is 65.23438% with 89 lines in your changes missing coverage. Please review.
✅ Project coverage is 84.64%. Comparing base (1bb3365) to head (ad7b29a).

Files with missing lines	Patch %	Lines
ffi/src/ffi_tracing.rs	65.23%	79 Missing and 10 partials ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #1111      +/-   ##
==========================================
- Coverage   84.86%   84.64%   -0.22%     
==========================================
  Files         119      119              
  Lines       30880    31075     +195     
  Branches    30880    31075     +195     
==========================================
+ Hits        26206    26304      +98     
- Misses       3395     3485      +90     
- Partials     1279     1286       +7

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:

❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

nicklan

thanks! took an initial pass and had a few comments. will look more deeply in the next day or so

nicklan · 2025-08-18T23:43:50Z

ffi/src/ffi_tracing.rs

+use tracing::warn;
+use tracing::trace;


nit:

Suggested change

use tracing::warn;

use tracing::trace;

use tracing::{trace, warn};

nicklan · 2025-10-02T23:38:24Z

ffi/src/ffi_tracing.rs

                file: kernel_string_slice!(file),
            };
-            (self.callback)(event);
+            let cb = self.callback.lock().unwrap();


We should not call unwrap as it panics and can crash the engine. This is a gross situation because we can't really inform the engine that something went wrong :) Maybe we can just error! log in that case and hope that something else on the rust side is logging.

nicklan · 2025-10-02T23:39:55Z

ffi/src/ffi_tracing.rs

+        }
+
+        if let (Some(reload), Some(event_cb)) = (&self.reload_handle, &self.event_callback) {
+            *event_cb.lock().unwrap() = callback;


ditto on unwrap here

ffi/src/ffi_tracing.rs

nicklan · 2025-10-02T23:41:46Z

ffi/src/ffi_tracing.rs

                let message = String::from_utf8_lossy(&buf);
                let message = kernel_string_slice!(message);
-                (self.callback)(message);
+                let cb = self.callback.lock().unwrap();


nicklan · 2025-10-02T23:41:50Z

ffi/src/ffi_tracing.rs

                let message = "INTERNAL KERNEL ERROR: Could not lock message buffer.";
                let message = kernel_string_slice!(message);
-                (self.callback)(message);
+                let cb = self.callback.lock().unwrap();


…nt-tracing-level

OussamaSaoudi

Getting close!

OussamaSaoudi · 2025-09-29T22:59:58Z

ffi/src/ffi_tracing.rs

+        if let Some(ref msgs) = *lock {
+            assert_eq!(msgs.len(), expected_lines.len());
+            for (got, expect) in msgs.iter().zip(expected_lines) {
+                println!("Got: {got}");
+                assert!(got.ends_with(expect));
+                assert!(got.contains(expected_level_str));
+                assert!(got.contains("delta_kernel_ffi::ffi_tracing::tests"));
+                if let Some(ref tstr) = expected_time_str {
+                    assert!(got.contains(tstr));
+                }
+            }
+        } else {
+            panic!("Messages wasn't Some");
+        }


Suggested change

if let Some(ref msgs) = *lock {

assert_eq!(msgs.len(), expected_lines.len());

for (got, expect) in msgs.iter().zip(expected_lines) {

println!("Got: {got}");

assert!(got.ends_with(expect));

assert!(got.contains(expected_level_str));

assert!(got.contains("delta_kernel_ffi::ffi_tracing::tests"));

if let Some(ref tstr) = expected_time_str {

assert!(got.contains(tstr));

}

}

} else {

panic!("Messages wasn't Some");

}

let Some(ref msgs) = *lock else {

panic!("Messages wasn't Some");

}

assert_eq!(msgs.len(), expected_lines.len());

for (got, expect) in msgs.iter().zip(expected_lines) {

println!("Got: {got}");

assert!(got.ends_with(expect));

assert!(got.contains(expected_level_str));

assert!(got.contains("delta_kernel_ffi::ffi_tracing::tests"));

if let Some(ref tstr) = expected_time_str {

assert!(got.contains(tstr));

}

}

OussamaSaoudi · 2025-10-10T23:13:37Z

ffi/src/ffi_tracing.rs

-    }
-    let dispatch = get_event_dispatcher(callback, max_level);
-    set_global_default(dispatch)
+    let mut state = TRACING_STATE.lock().unwrap();


Suggested change

let mut state = TRACING_STATE.lock().unwrap();

let mut state = TRACING_STATE.lock().map_err(|e| Error::generic("Poisoned mutex while setting up event subscriber");

OussamaSaoudi · 2025-10-10T23:14:12Z

ffi/src/ffi_tracing.rs

-        return Err(Error::generic("max_level out of range"));
-    }
-    let dispatch = get_log_line_dispatch(
+    let mut state = TRACING_STATE.lock().unwrap();


Suggested change

let mut state = TRACING_STATE.lock().unwrap();

let mut state = TRACING_STATE.lock().map_err(|e| Error::generic("Poisoned mutex while setting up log_line_subscriber")?;

OussamaSaoudi · 2025-10-10T23:16:22Z

ffi/src/ffi_tracing.rs

+            if let Ok(mut event_cb) = event_cb.lock() {
+                *event_cb = callback;
+            } else {
+                error!("Failed to acquire lock for event callback (mutex poisoned).");
+            }


Let the caller know something went wrong

Suggested change

if let Ok(mut event_cb) = event_cb.lock() {

*event_cb = callback;

} else {

error!("Failed to acquire lock for event callback (mutex poisoned).");

}

let (mut event_cb) = event_cb.lock().map_err(|e| Error::generic("Failed to acquire lock for event callback (mutex poisoned).")?;

*event_cb = callback;

OussamaSaoudi · 2025-10-10T23:17:53Z

ffi/src/ffi_tracing.rs

+            if let Ok(mut log_cb) = log_cb.lock() {
+                *log_cb = callback;
+            } else {
+                error!("Failed to acquire lock for log callback (mutex poisoned).");
+            }


Suggested change

if let Ok(mut log_cb) = log_cb.lock() {

*log_cb = callback;

} else {

error!("Failed to acquire lock for log callback (mutex poisoned).");

}

let mut log_cb = log_cb.lock().map_err(|e| Error::generic("Failed to acquire lock for log callback (mutex poisoned)."))?;

*log_cb = callback;

…nt-tracing-level

github-actions bot assigned kssenii Jul 25, 2025

zachschuermann requested review from nicklan and zachschuermann July 25, 2025 17:56

kssenii mentioned this pull request Jul 28, 2025

Allow to change tracing level in delta-kernel-rs per query ClickHouse/ClickHouse#84559

Draft

1 task

kssenii marked this pull request as draft July 29, 2025 17:17

kssenii force-pushed the allow-to-change-event-tracing-level branch from 4a69e1f to ba6df41 Compare July 29, 2025 20:00

kssenii force-pushed the allow-to-change-event-tracing-level branch 4 times, most recently from 7e72421 to fdc0610 Compare August 27, 2025 13:02

Allow to change tracing callback and level

c1778ef

kssenii force-pushed the allow-to-change-event-tracing-level branch 2 times, most recently from 8bd28ca to af406cb Compare August 27, 2025 15:35

github-actions bot added the breaking-change Change that require a major version bump label Aug 27, 2025

kssenii marked this pull request as ready for review August 27, 2025 15:39

kssenii force-pushed the allow-to-change-event-tracing-level branch 2 times, most recently from f7b8814 to 8ac86aa Compare August 27, 2025 15:55

Refactor

007e76c

kssenii force-pushed the allow-to-change-event-tracing-level branch from 8ac86aa to 007e76c Compare August 27, 2025 15:58

kssenii changed the title ~~ffi: allow to change event tracing level more than once~~ ffi: allow to change tracing level and callback more than once Aug 27, 2025

OussamaSaoudi reviewed Sep 23, 2025

View reviewed changes

Merge remote-tracking branch 'delta-io/main' into allow-to-change-eve…

f72ace8

…nt-tracing-level

kssenii force-pushed the allow-to-change-event-tracing-level branch from 3ccd287 to 00aab70 Compare September 24, 2025 14:17

Review fixes

9e7b4f0

kssenii force-pushed the allow-to-change-event-tracing-level branch from 00aab70 to 9e7b4f0 Compare September 24, 2025 14:26

kssenii requested a review from OussamaSaoudi September 25, 2025 09:47

OussamaSaoudi removed the request for review from zachschuermann September 29, 2025 22:40

nicklan reviewed Oct 2, 2025

View reviewed changes

kssenii added 2 commits October 8, 2025 13:24

Merge remote-tracking branch 'delta-io/main' into allow-to-change-eve…

ad5bd14

…nt-tracing-level

Fix review comments; fix CI

7a0c019

kssenii requested a review from nicklan October 8, 2025 15:33

OussamaSaoudi reviewed Oct 10, 2025

View reviewed changes

kssenii added 2 commits October 27, 2025 14:31

Review fixes

95672f9

Merge remote-tracking branch 'delta-io/main' into allow-to-change-eve…

ad7b29a

…nt-tracing-level

kssenii requested a review from OussamaSaoudi October 27, 2025 13:34

	#[test]
	#[ignore] // We cannot run this test if test_enable_log_line_tracing was run before - see comment there, however this test works if run individually.
	fn test_enable_event_tracing() {

	use tracing::warn;
	use tracing::trace;
	use tracing::{trace, warn};

	let mut state = TRACING_STATE.lock().unwrap();
	let mut state = TRACING_STATE.lock().map_err(\|e\| Error::generic("Poisoned mutex while setting up event subscriber");

Uh oh!

ffi: allow to change tracing level and callback more than once #1111

Are you sure you want to change the base?

ffi: allow to change tracing level and callback more than once #1111

Uh oh!

Conversation

kssenii commented Jul 25, 2025

What changes are proposed in this pull request?

How was this change tested?

Uh oh!

zachschuermann commented Aug 11, 2025

Uh oh!

kssenii commented Aug 12, 2025

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

codecov bot commented Sep 29, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

nicklan left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

OussamaSaoudi left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

codecov bot commented Sep 29, 2025 •

edited

Loading