Consider contextual, structured logging

[KevinMGranger]

Right now, there's a lot of manual adding of contextual information to log statements. We'll commonly see the current namespace passed around just for logging purposes. We also repeat a lot of information while only inspecting one resource at a time.

We could have a context that we fill and then remove information from, that's put before all log messages. Context vars would be kept in a dict and would be added to any log line (by changing the format we use).\

For example, taking a snippet from the committime base:

class Foo:
    def generate_metrics(self):
        for namespace in self._namespaces:
            with update_log_context(namespace=namespace):
                # note no namespace is passed!
                self.get_metrics_from_apps(builds_by_app)

    def get_metrics_from_apps(self, builds_by_app):
        for app in builds_by_app:
            with update_log_context(app=app):
                for build in code_builds:
                    with update_log_context(kind="Build", name=build.metadata.name):
                        metric = self.get_metric_from_build(build, app)

    def get_metric_from_build(self, build, app):
        ...
        if errors:
            # note how namespace, name, and app are handled elsewhere-- no need for additional work.
            logging.warning(
                "Missing data for CommitTime metric: %s",
                ".".join(str(e) for e in errors),
            )

Unfortunately, we do see additional levels of nesting with each update. Some ideas for that:

• make the class itself carry some of these context variables. After all, an object is meant to be a bundle of contextual variables!
• be very careful with each try/catch and unset the context vars in the finally.
• separate querying data and processing data more strictly, so contexts can be set up all at once.
• refactor nested loops out into separate methods.
• create decorators for functions that set the context from their input and reset it upon exit.

I will admit, there's some level of "magic" happening here, which can be confusing. But we're seeing lots of debugging issues that would be solved with richer logs, and manual solutions are error-prone.

[mateusoliveira43]

Can you print a terminal output of the idea?

Can it happen to have parallel logging? (two namespaces, for example)

[KevinMGranger]

I can make a small proof of concept, yes.

Right now we don't do any processing in parallel. Even if we did, we could use ContextVars to make sure they're kept separate.

[KevinMGranger]

I've been playing with structlog and it's really, really cool. It might just be a good choice for this.