Enable relaying log events via FFI #542

nicklan · 2024-11-26T20:07:40Z

What changes are proposed in this pull request?

This PR provides 3 ways for engines to hook into our logging:

getting a struct Event type with relevant information that they can format
A very simple call that will just pick some defaults and give them a string
A slightly more complex one that lets them control the string formatting a little, but still ultimately just hands over a string

Note that the Compact format seems a bit broken upstream. I've filled tokio-rs/tracing#3157 for that.

Adds 3 new public ffi APIs

How was this change tested?

Running in read_table, and unit tests

codecov · 2024-11-26T21:02:16Z

Codecov Report

Attention: Patch coverage is 85.15152% with 49 lines in your changes missing coverage. Please review.

Project coverage is 81.63%. Comparing base (695b841) to head (61a274a).
Report is 1 commits behind head on main.

Files with missing lines	Patch %	Lines
ffi/src/ffi_tracing.rs	85.15%	40 Missing and 9 partials ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##             main     #542      +/-   ##
==========================================
+ Coverage   81.54%   81.63%   +0.08%     
==========================================
  Files          67       68       +1     
  Lines       14544    14874     +330     
  Branches    14544    14874     +330     
==========================================
+ Hits        11860    12142     +282     
- Misses       2107     2145      +38     
- Partials      577      587      +10

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

ffi/examples/read-table/read_table.c

ffi/src/ffi_tracing.rs

ffi/examples/read-table/read_table.c

scovich · 2024-11-26T23:04:09Z

ffi/src/ffi_tracing.rs

+    /// `2022-02-15T18:40:14.289898Z  INFO fmt: preparing to shave yaks number_of_yaks=3`
+    FULL,
+    /// A variant of the FULL formatter, optimized for short line lengths. Fields from the context
+    /// are appended to the fields of the formatted event, and targets are not shown.
+    /// Example:
+    /// `2022-02-17T19:51:05.809287Z  INFO fmt_compact: preparing to shave yaks number_of_yaks=3`


I don't think I understand the difference between these two?
(the example doesn't seem to show any meaningful difference)

Yes, I've filled an upstream issue: tokio-rs/tracing#3157

scovich · 2024-11-26T23:12:34Z

ffi/src/ffi_tracing.rs

+                None => KernelStringSlice {
+                    ptr: std::ptr::null(),
+                    len: 0,
+                },


We should ideally define a KernelStringSlice::empty() method and use that instead?
(apparently this is the first time we need an empty string slice in the code)

Doing that would allow simply:

let file = metadata.file().map_or(KernelSlice::empty(), |f| kernel_string_slice!(f));

Could also just do:

let file = metadata.file().unwrap_or("");

and then

let event = Event { ... file: kernel_string_slice!(file), };

I think having empty is probably good

ffi/src/ffi_tracing.rs

scovich · 2024-11-26T23:22:19Z

ffi/src/ffi_tracing.rs

+    S: Subscriber + for<'a> LookupSpan<'a>,
+{
+    fn on_event(&self, _: &TracingEvent<'_>, _context: Context<'_, S>) {
+        let mut buf = self.buf.lock().unwrap();


panic in tracing code... not fun to debug
(again below)

good call, fixed. not sure if spamming the log of the engine with an error is good, but it feels better than silent failure.

scovich · 2024-11-26T23:31:17Z

ffi/src/ffi_tracing.rs

+    // This repeats some code, but avoids some insane generic wrangling if we try to abstract the
+    // type of `fmt_layer` over the formatter


Problem being, that e.g. Layer::compact returns Format<Compact, _>, so we need a different return type for each call? (but everything else is the same)?

It's also when we call things like without_time which effects the second generic for Format.

The real issue is, we want to return this. Really we just need an impl Subscriber, but because the concrete types all differ it gets really messy.

I can play around a bit more, but this felt overall more understandable and actually cleaner

Also note that the tracing_core crate introduces Dispatch exactly to abstract over all this where they erase the type. But we can't do that so easily because we want to retain methods like with_filter and pretty(), etc.

ffi/src/ffi_tracing.rs

nicklan · 2024-11-27T19:08:33Z

Thanks for the review. I've updated some stuff to remove a bad panic when setting global subscriber. Will address the rest of the comments when I'm back from Thanksgiving.

nicklan · 2024-12-03T00:56:42Z

ffi/src/handle.rs

@@ -176,7 +176,6 @@ mod private {
    {
        /// Obtains a mutable reference to the handle's underlying object. Unsafe equivalent to
        /// [`AsMut::as_mut`].
-


scovich

Generally looks good, just a couple of small (but important) items:

NULL pointer in string slice is UB
Deceptively unprotective use of kernel_string_slice!

ffi/examples/read-table/read_table.c

scovich · 2024-12-03T21:53:09Z

ffi/src/ffi_tracing.rs

+    fn is_valid(value: u32) -> bool {
+        static VALID_VALUES: &[u32] = &[0, 1, 2, 3, 4];
+        VALID_VALUES.contains(&value)


Would this be easier to use?

Suggested change

fn is_valid(value: u32) -> bool {

static VALID_VALUES: &[u32] = &[0, 1, 2, 3, 4];

VALID_VALUES.contains(&value)

fn is_valid(self) -> bool {

static VALID_VALUES: &[u32] = &[0, 1, 2, 3, 4];

VALID_VALUES.contains(&(self as u32))

(e.g. max_level.is_valid()?)

(ok to consume self because Copy)

yep, that's nicer, thanks

scovich · 2024-12-03T21:57:26Z

ffi/src/ffi_tracing.rs

-                file,
+                file: metadata
+                    .file()
+                    .map_or(KernelStringSlice::empty(), |f| kernel_string_slice!(f)),


FYI: This kernel_string_slice invocation is not obviously (syntactically) safe, because the identifier f goes out of scope immediately after the slice is created. In this specific case, f has lifetime of metadata so we're ok... but the macro didn't help enforce that at all.

I still wonder why not just use "" as the empty string slice?

let file = metadata.file().unwrap_or(""); let event = Event { ... file: kernel_string_slice!(file),

That's fair. I liked the idea of empty for string slice, but you're probably right that just having it be the actual empty string makes the most sense. I'll switch to that

scovich · 2024-12-03T22:06:07Z

ffi/src/ffi_tracing.rs

-                    .expect("Failed to set global subscriber");
-            }
-        };
+        ($($transform:ident()).*) => {{


oh clever -- I didn't realize we could capture () and . like that!

(only works for these no-arg invocations tho...)

Yeah, macros are pretty nice. You can handle arg cases too with nested and repeated args but the macro will get really ugly. I initially wrote a pretty complex macro because I was using the with_ansi(ansi) call, and then realized you can simplify a lot if you get rid of the arg and the need to have a call at all.

scovich · 2024-12-03T22:15:58Z

ffi/src/lib.rs

+    /// Create a new empty `KernelStringSlice`. `len` will be 0, and `ptr` will be `null`.
+    pub(crate) fn empty() -> Self {
+        Self {
+            ptr: std::ptr::null(),


The TryFromSlice docs specifically state:

The slice must be a valid (non-null) pointer

... which is required because we're going to turn the pointer into a reference, and a null reference is UB even if never accessed. We should really use NonNull and its associated dangling() instead -- see e.g. KernelBoolSlice). Tho I suspect that ptr: NonNull::from("") would work just as well for this specific case.

Ahh, good catch! I've actually just removed this and we can just use "" since it avoids all the mess

ffi/examples/read-table/read_table.c

scovich · 2024-12-03T22:21:19Z

ffi/src/ffi_tracing.rs

+    }
+}
+
+impl From<&tracing::Level> for Level {


is tracing::Level not Copy, that we have to consume a ref instead?

Or does it just so happen all the call sites already have a reference and this avoids the need for (*level).into()?

yeah, I use this only as metadata.level().into(), and metadata.level() returns &Level, so this makes it a little cleaner at the usage site.

scovich · 2024-12-03T22:23:25Z

ffi/src/ffi_tracing.rs

+/// Note that setting up such a call back can only be done ONCE. Calling any of
+/// `enable_event_tracing`, `enable_log_line_tracing`, or `enable_formatted_log_line_tracing` more
+/// than once is a no-op.


Should this also be part of the safety contract?
(seems like an unusually sharp edge to have inherited from rust code)

Ah, I didn't read very carefully... the error case becomes a no-op, so no safety issues whatsoever.

Yeah. We should probably discuss if we should do anything other than just "return false" if you call twice, but for now it's safe. I could turn it into a proper ExternResult with more info, but had the feeling that was just more overhead for the engine which probably just wants to know if it set up logging okay or not.

ffi/src/ffi_tracing.rs

zachschuermann

just a little question but LGTM and i ran locally to take all those pretty colors for a spin! looks awesome!!

zachschuermann · 2024-12-06T04:13:58Z

ffi/src/ffi_tracing.rs

+
+// utility code below for setting up the tracing subscriber for events
+
+pub fn set_global_default(dispatch: tracing_core::Dispatch) -> DeltaResult<()> {


is this supposed to be pub? is it just if consumers want to do something different than enable_event_tracing?

nope, good catch, removed

nicklan added 5 commits November 25, 2024 16:42

checkpoint

d441c19

works :)

e66118c

add file/line and COLORS

9150a0d

proper log line formatting

9107d04

feature flag it all

41c08bf

github-actions bot assigned nicklan Nov 26, 2024

remove comment

1ee3092

github-actions bot added the breaking-change Change that will require a version bump label Nov 26, 2024

update docs a bit

c84e02d

nicklan requested review from scovich and zachschuermann November 26, 2024 20:21

nicklan added 2 commits November 26, 2024 12:58

minor fixes

ca674d2

Merge branch 'main' into ffi-logging-take-1

6e8c3e5

scovich reviewed Nov 27, 2024

View reviewed changes

nicklan added 2 commits November 26, 2024 16:25

add a test

34e53f6

cleanups for docs and tests

7ad2c09

nicklan added 8 commits December 2, 2024 15:27

Merge branch 'main' into ffi-logging-take-1

2716128

print target + don't allocate

cb272a9

validate max_level

43435c2

address comments

7378cfe

update macro

130ece6

fmt

679556e

Merge branch 'main' into ffi-logging-take-1

819a54b

clippy fix

dc7a2e4

nicklan commented Dec 3, 2024

View reviewed changes

nicklan requested a review from scovich December 3, 2024 00:57

nicklan added 2 commits December 2, 2024 17:01

macro cleanup

973eed1

actually is even more simple

76743da

scovich reviewed Dec 3, 2024

View reviewed changes

nicklan added 3 commits December 3, 2024 16:33

address comments

f5716cf

Merge branch 'main' into ffi-logging-take-1

013491c

moar testing

cee2caa

nicklan requested a review from scovich December 5, 2024 01:35

scovich approved these changes Dec 5, 2024

View reviewed changes

ffi/src/ffi_tracing.rs Outdated Show resolved Hide resolved

ffi/src/ffi_tracing.rs Outdated Show resolved Hide resolved

nicklan added 6 commits December 5, 2024 16:03

address nit

eab8105

address nit

9918bb0

printlns for windwos

20de800

fix windows test

ef50fe9

Merge branch 'main' into ffi-logging-take-1

baacea6

fmt

07de218

nicklan removed the breaking-change Change that will require a version bump label Dec 6, 2024

zachschuermann approved these changes Dec 6, 2024

View reviewed changes

nicklan added 2 commits December 6, 2024 12:32

don't need set_global_default to be pub

4f3429d

Merge branch 'main' into ffi-logging-take-1

61a274a

nicklan merged commit eb95c5b into delta-io:main Dec 6, 2024
20 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Enable relaying log events via FFI #542

Enable relaying log events via FFI #542

nicklan commented Nov 26, 2024 •

edited

Loading

codecov bot commented Nov 26, 2024 •

edited

Loading

scovich Nov 26, 2024

nicklan Nov 27, 2024

scovich Nov 26, 2024

scovich Nov 26, 2024

nicklan Dec 3, 2024

scovich Nov 26, 2024

nicklan Dec 3, 2024

scovich Nov 26, 2024

nicklan Nov 27, 2024

nicklan Nov 27, 2024

nicklan commented Nov 27, 2024

nicklan Dec 3, 2024

scovich left a comment

scovich Dec 3, 2024

nicklan Dec 4, 2024

scovich Dec 3, 2024

nicklan Dec 4, 2024

scovich Dec 3, 2024

nicklan Dec 4, 2024

scovich Dec 3, 2024

nicklan Dec 4, 2024

scovich Dec 3, 2024

nicklan Dec 4, 2024

scovich Dec 3, 2024

scovich Dec 3, 2024

nicklan Dec 4, 2024

zachschuermann left a comment

zachschuermann Dec 6, 2024

nicklan Dec 6, 2024

		// This repeats some code, but avoids some insane generic wrangling if we try to abstract the
		// type of `fmt_layer` over the formatter


		// utility code below for setting up the tracing subscriber for events

		pub fn set_global_default(dispatch: tracing_core::Dispatch) -> DeltaResult<()> {

Enable relaying log events via FFI #542

Enable relaying log events via FFI #542

Conversation

nicklan commented Nov 26, 2024 • edited Loading

What changes are proposed in this pull request?

How was this change tested?

codecov bot commented Nov 26, 2024 • edited Loading

Codecov Report

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nicklan commented Nov 27, 2024

Choose a reason for hiding this comment

scovich left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

zachschuermann left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nicklan commented Nov 26, 2024 •

edited

Loading

codecov bot commented Nov 26, 2024 •

edited

Loading