Enable relaying log events via FFI (#542)

<!--
Thanks for sending a pull request!  Here are some tips for you:
1. If this is your first time, please read our contributor guidelines:
https://github.com/delta-incubator/delta-kernel-rs/blob/main/CONTRIBUTING.md
2. Run `cargo t --all-features --all-targets` to get started testing,
and run `cargo fmt`.
  3. Ensure you have added or run the appropriate tests for your PR.
4. If the PR is unfinished, add '[WIP]' in your PR title, e.g., '[WIP]
Your PR title ...'.
  5. Be sure to keep the PR description updated to reflect all changes.
-->

## What changes are proposed in this pull request?
<!--
Please clarify what changes you are proposing and why the changes are
needed.
The purpose of this section is to outline the changes, why they are
needed, and how this PR fixes the issue.
If the reason for the change is already explained clearly in an issue,
then it does not need to be restated here.
1. If you propose a new API or feature, clarify the use case for a new
API or feature.
  2. If you fix a bug, you can clarify why it is a bug.
-->

This PR provides 3 ways for engines to hook into our logging:
1. getting a struct `Event` type with relevant information that they can
format
2. A very simple call that will just pick some defaults and give them a
string
3. 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.

<!--
Uncomment this section if there are any changes affecting public APIs:
### This PR affects the following public APIs

If there are breaking changes, please ensure the `breaking-changes`
label gets added by CI, and describe why the changes are needed.

Note that _new_ public APIs are not considered breaking.
-->

Adds 3 new public ffi APIs

## How was this change tested?
<!--
Please make sure to add test cases that check the changes thoroughly
including negative and positive cases if possible.
If it was tested in a way different from regular unit tests, please
clarify how you tested, ideally via a reproducible test documented in
the PR description.
-->

Running in `read_table`, and unit tests

Author: nicklan

.github/workflows/build.yml

@@ -145,7 +145,7 @@ jobs:
           cargo build
           popd
           pushd ffi
-          cargo b --features default-engine,sync-engine,test-ffi
+          cargo b --features default-engine,sync-engine,test-ffi,tracing
           popd
       - name: build and run read-table test
         run: |

ffi/Cargo.toml

@@ -15,6 +15,8 @@ crate-type = ["lib", "cdylib", "staticlib"]
 
 [dependencies]
 tracing = "0.1"
+tracing-core = { version = "0.1", optional = true }
+tracing-subscriber = { version = "0.3", optional = true, features = [ "json" ] }
 url = "2"
 delta_kernel = { path = "../kernel", default-features = false, features = [
   "developer-visibility",
@@ -51,6 +53,7 @@ default-engine = [
   "arrow-data",
   "arrow-schema",
 ]
+tracing = [ "tracing-core", "tracing-subscriber" ]
 sync-engine = ["delta_kernel/sync-engine"]
 developer-visibility = []
 test-ffi = []

ffi/examples/read-table/README.md

@@ -10,9 +10,9 @@ This example is built with [cmake]. Instructions below assume you start in the d
 Note that prior to building these examples you must build `delta_kernel_ffi` (see [the FFI readme] for details). TLDR:
 ```bash
 # from repo root
-$ cargo build -p delta_kernel_ffi [--release] [--features default-engine]
+$ cargo build -p delta_kernel_ffi [--release] [--features default-engine, tracing]
 # from ffi/ dir
-$ cargo build [--release] [--features default-engine]
+$ cargo build [--release] [--features default-engine, tracing]
 ```
 
 There are two configurations that can currently be configured in cmake:
@@ -62,4 +62,4 @@ If you don't want to have to install this, you can run `ccmake ..` (`cmake-gui.e
 from the `build` directory, and turn `OFF`/uncheckmark `PRINT_DATA`. Then "configure" and
 "generate" and follow the above instructions again.
 
-[cmake]: https://cmake.org/
+[cmake]: https://cmake.org/

ffi/examples/read-table/read_table.c

@@ -1,6 +1,7 @@
 #include <inttypes.h>
 #include <stdio.h>
 #include <string.h>
+#include <sys/time.h>
 
 #include "arrow.h"
 #include "read_table.h"
@@ -150,13 +151,68 @@ void free_partition_list(PartitionList* list) {
   free(list);
 }
 
+static const char *LEVEL_STRING[] = {
+  "ERROR", "WARN", "INFO", "DEBUG", "TRACE"
+};
+
+// define some ansi color escapes so we can have nice colored output in our logs
+#define RED   "\x1b[31m"
+#define BLUE  "\x1b[34m"
+#define DIM   "\x1b[2m"
+#define RESET "\x1b[0m"
+
+void tracing_callback(struct Event event) {
+  struct timeval tv;
+  char buffer[32];
+  gettimeofday(&tv, NULL);
+  struct tm *tm_info = gmtime(&tv.tv_sec);
+  strftime(buffer, 26, "%Y-%m-%dT%H:%M:%S", tm_info);
+  char* level_color = event.level < 3 ? RED : BLUE;
+  printf(
+    "%s%s.%06dZ%s [%sKernel %s%s] %s%.*s%s: %.*s\n",
+    DIM,
+    buffer,
+    (int)tv.tv_usec, // safe, microseconds are in int range
+    RESET,
+    level_color,
+    LEVEL_STRING[event.level],
+    RESET,
+    DIM,
+    (int)event.target.len,
+    event.target.ptr,
+    RESET,
+    (int)event.message.len,
+    event.message.ptr);
+  if (event.file.ptr) {
+    printf(
+      "  %sat%s %.*s:%i\n",
+      DIM,
+      RESET,
+      (int)event.file.len,
+      event.file.ptr,
+      event.line);
+  }
+}
+
+void log_line_callback(KernelStringSlice line) {
+  printf("%.*s", (int)line.len, line.ptr);
+}
+
 int main(int argc, char* argv[])
 {
   if (argc < 2) {
     printf("Usage: %s table/path\n", argv[0]);
     return -1;
   }
 
+#ifdef VERBOSE
+  enable_event_tracing(tracing_callback, TRACE);
+  // we could also do something like this if we want less control over formatting
+  // enable_formatted_log_line_tracing(log_line_callback, TRACE, FULL, true, true, false, false);
+#else
+  enable_event_tracing(tracing_callback, INFO);
+#endif
+
   char* table_path = argv[1];
   printf("Reading table at %s\n", table_path);