feat: Add support for logging

[kylebarron]

Change list

• Adds support for logging via a global log_init function.
• Vendors instrumented_object_store from https://github.com/datafusion-contrib/datafusion-tracing/blob/main/instrumented-object-store/src/instrumented_object_store.rs. If we go ahead with this approach, I'll make a PR there upstream with a couple changes (allowing T: ObjectStore instead of Arc<dyn ObjectStore> and adding an inner(&self) -> &T method).
• Adds Python init_log function for creating a global tracing subscriber.
• This init_log function can only be called once because it initiates into a
  • Perhaps we could instead have a Logger class that holds the guard and avoids dropping it? We don't necessarily need to instantiate the tracing subscriber into global scope.
  • This would also allow multiple logging outputs to different locations based on trace/debug/etc level.
  • Edit: I tried this but even with a Logger class, it sets one logger at a time to be the thread default. I think it's easiest for now to just have a global logger.
• For now, it's only possible to log to files. I think this is simpler (and more performant) than trying to log back into Python because otherwise we get GIL contention across the threads.
• The tracing store wrapper is always used, whether or not logging has been requested. This simplifies code a lot (otherwise we'd need to store enums of whether the user has requested logging or not). I think that the performance impact will be negligible when logging has not been opted-into via init_log.

Downsides:

• Only one global logger possible. Can't mix and match multiple loggers at the same time.

To test

Install with

pip install git+https://github.com/developmentseed/obstore.git@45dc474f0ca1e77a73155c9afc536fadf2a39d91#subdirectory=obstore

(replace git rev if more commits have been pushed)

from obstore import init_log
from pathlib import Path

log_dir = Path() / "logs"
log_file = "test_trace.log"

init_log(log_dir, log_file, rotation="never", level="trace")

Then use any obstore functions. I think only S3/GCP/Azure work with logging, not local file access.

Closes #93

[geospatial-jeff]

@kylebarron A few comments. It's best practice in cloud-native systems to log to stdout and stderr instead of a log file, the twelve factor app has some guidance here. There are several reasons for this:

• Containers are ephemeral. Writing logs to local files within a container ties those logs to a specific container instance and can be lost when the container is terminated or replaced.
• Containers, in many cases, don't necessarily have full control over underlying disk storage due to separation of concerns.
• Most importantly, platforms like kubernetes provide log shippers such as FluentD which listen to stdout on each node and forward logs to a centralized logging solution. This could be a file, a database like elasticsearch, or a managed logging solution like AWS CloudWatch. This provides good separation of concerns between the thing responsible for emitting logs (the container) and the thing responsible for determining where those logs go, and how they are analyzed. The result is an application that is simpler, more portable, and compatible with modern observability tools.

Another common anti-pattern in logging is not structuring log statements in a way that is easily interpretable by machines. The assumption here is that the volume of logs in cloud-native systems quickly gets to the point where machines are mainly responsible for understanding and interpreting them, not humans. The logs created here are well structured for the most part, but a few NITs:

2025-08-27T17:45:01.311335Z TRACE put_opts: hyper_util::client::legacy::pool: checkout waiting for idle connection:
("https", s3.us-east-1.amazonaws.com) otel.name="S3Store.put_opts" object_store.location=test.txt
object_store.content_length=13

Some pieces of the log are well structured as key=value (for example - otel.name="S3Store.put_opts"), but this is not done consistently throughout the log. For example the message should ideally be structured as message=checkout waiting for idle connection: ("https", s3.us-east-1.amazonaws.com). This provides consistent parsing across the entire log message. Ideally we do the same thing for the log level. Instead of starting the log with TRACE we'd represent this as level=TRACE. And the same for the log timestamp as well timestamp=2025-08-27T17:45:01.311335Z.

That being said, JSON is the recommended format for structured logging, something like below. The log format is less important than having a consistent log structure within a log format, so if key=value is a lot easier to implement in rust than JSON then it's totally fine.

{
  "level": "TRACE",
  "timestamp": "2025-08-27T17:45:01.311335Z",
  "message": "checkout waiting for idle connection: ('https', s3.us-east-1.amazonaws.com)",
  "otel": {
    "name": "S3Store.put_opts"
  },
  "object_store": {
    "location": "test.txt",
    "content_length": 13
  }
}

Ideally we just expose the log level to python, and the rust code emits logs from there. But I'm not totally sure if that is possible given I'm not familiar with binding rust into python.

[kylebarron]

687fc9a (#544) switches to use a JSON-based log format (it was just a one-line change that I didn't know to look for), so a single event from test_tracing.py now looks like (formatting added):

{
  "timestamp": "2025-08-28T20:57:08.773915Z",
  "level": "TRACE",
  "fields": {
    "message": "checkout waiting for idle connection: (\"http\", 127.0.0.1:57907)"
  },
  "target": "hyper_util::client::legacy::pool",
  "span": {
    "object_store.prefix": "",
    "otel.name": "S3Store.list",
    "name": "list"
  },
  "spans": [
    { "object_store.prefix": "", "otel.name": "S3Store.list", "name": "list" }
  ]
}

and all logs in the file look like:

{"timestamp":"2025-08-28T20:57:08.773915Z","level":"TRACE","fields":{"message":"checkout waiting for idle connection: (\"http\", 127.0.0.1:57907)"},"target":"hyper_util::client::legacy::pool","span":{"object_store.prefix":"","otel.name":"S3Store.list","name":"list"},"spans":[{"object_store.prefix":"","otel.name":"S3Store.list","name":"list"}]}
{"timestamp":"2025-08-28T20:57:08.774080Z","level":"DEBUG","fields":{"message":"starting new connection: http://127.0.0.1:57907/","log.target":"reqwest::connect","log.module_path":"reqwest::connect","log.file":"/Users/kyle/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/reqwest-0.12.22/src/connect.rs","log.line":789},"target":"reqwest::connect","span":{"object_store.prefix":"","otel.name":"S3Store.list","name":"list"},"spans":[{"object_store.prefix":"","otel.name":"S3Store.list","name":"list"}]}
{"timestamp":"2025-08-28T20:57:08.774138Z","level":"TRACE","fields":{"message":"Http::connect; scheme=Some(\"http\"), host=Some(\"127.0.0.1\"), port=Some(Port(57907))"},"target":"hyper_util::client::legacy::connect::http","span":{"object_store.prefix":"","otel.name":"S3Store.list","name":"list"},"spans":[{"object_store.prefix":"","otel.name":"S3Store.list","name":"list"}]}
{"timestamp":"2025-08-28T20:57:08.774190Z","level":"DEBUG","fields":{"message":"connecting to 127.0.0.1:57907"},"target":"hyper_util::client::legacy::connect::http","span":{"object_store.prefix":"","otel.name":"S3Store.list","name":"list"},"spans":[{"object_store.prefix":"","otel.name":"S3Store.list","name":"list"}]}
{"timestamp":"2025-08-28T20:57:08.774399Z","level":"DEBUG","fields":{"message":"connected to 127.0.0.1:57907"},"target":"hyper_util::client::legacy::connect::http","span":{"object_store.prefix":"","otel.name":"S3Store.list","name":"list"},"spans":[{"object_store.prefix":"","otel.name":"S3Store.list","name":"list"}]}
{"timestamp":"2025-08-28T20:57:08.774475Z","level":"TRACE","fields":{"message":"http1 handshake complete, spawning background dispatcher task"},"target":"hyper_util::client::legacy::client","span":{"object_store.prefix":"","otel.name":"S3Store.list","name":"list"},"spans":[{"object_store.prefix":"","otel.name":"S3Store.list","name":"list"}]}
{"timestamp":"2025-08-28T20:57:08.774502Z","level":"TRACE","fields":{"message":"waiting for connection to be ready"},"target":"hyper_util::client::legacy::client","span":{"object_store.prefix":"","otel.name":"S3Store.list","name":"list"},"spans":[{"object_store.prefix":"","otel.name":"S3Store.list","name":"list"}]}
{"timestamp":"2025-08-28T20:57:08.774591Z","level":"TRACE","fields":{"message":"connection is ready"},"target":"hyper_util::client::legacy::client","span":{"object_store.prefix":"","otel.name":"S3Store.list","name":"list"},"spans":[{"object_store.prefix":"","otel.name":"S3Store.list","name":"list"}]}
{"timestamp":"2025-08-28T20:57:08.774653Z","level":"TRACE","fields":{"message":"checkout dropped for (\"http\", 127.0.0.1:57907)"},"target":"hyper_util::client::legacy::pool","span":{"object_store.prefix":"","otel.name":"S3Store.list","name":"list"},"spans":[{"object_store.prefix":"","otel.name":"S3Store.list","name":"list"}]}

[kylebarron]

Latest commits let you mix and match stdout/stderr/file, so you can choose different configurations for each output destination

This config:

stderr_config = {
    "format": "json",
    "show_ansi": False,
    "show_target": False,
    "show_level": False,
}
stdout_config = {
    "format": "pretty",
    "show_ansi": True,
    "show_target": True,
    "show_level": True,
}
init_log(stderr=stderr_config, stdout=stdout_config, level="trace")

produces:

[kylebarron]

And I added support for destination-specific levels, so here stdout gets only debug events while stderr gets trace and debug events:

stderr_config = {
    "format": "json",
    "show_ansi": False,
    "show_target": False,
    "show_level": False,
    "level": "trace",
}
stdout_config = {
    "format": "pretty",
    "show_ansi": True,
    "show_target": True,
    "show_level": True,
    "level": "debug",
}

[kylebarron]

@geospatial-jeff Should I support file-based logging still? Or do you think I should only give an option of stderr and stdout?

[geospatial-jeff]

No just do stderr and stdout, let end user decide where to send the logs.

[aabed-aa]

I think integrating with https://www.structlog.org/en/stable/ would be great

[kylebarron]

Any Python based logging will be relatively slow because it requires the multithreaded Rust code to acquire the GIL to emit a log. That's why right now this PR only supports stdout, stderr, and files. Those still need a small lock on the Rust side, but it should be much less overhead than acquiring the GIL.

[vincentsarago]

@kylebarron I may need this feature soon 🙈

let me know if I can be of any help

[kylebarron]

@vincentsarago would you be interested in testing from this branch