juju unit logging defaults to WARNING and no python tracebacks at any log level

[Corey Bryant]

It appears that juju is currently only logging WARNING and ERROR messages by default in 2.8.1.

Additionally, it appears that tracebacks resulting from python hook exceptions are no longer being logged by juju, no matter what the log level is set to.

This might be related to the 2.8.0 change "The default logging level has increased to INFO." https://discourse.juju.is/t/juju-2-8-0-release-notes/3180

[Corey Bryant (corey.bryant)]

Please see attached document with details.

[Frode Nordahl (fnordahl)]

I see this problem too, I just had a 7 hour test run stop on an error without giving me any details, this was all I got:

    2020-09-03 13:17:27 ERROR juju.worker.uniter.operation runhook.go:132 hook "install" failed: exit status 100.

While I surely can control the logging-config of the model used for testing I am pretty sure we will loose valuable information from end users running charms in the wild with the new defaults.

[Pen Gale (pengale)]

Logging warning by default is intentional. Skipping tracebacks is not, though I don't know whether that's due to an error in the logs, or a missing log level on the model or charms in question.

You can turn on debug logging for everything at bootstrap time with:

    juju bootstrap --debug

If you do that in the Gate, you should get back to the log levels that you were seeing before.

With existing controllers, you can set a root logger level on a running model (including a controller model) with the following:

    juju model-config "logging-config=<root>=DEBUG"

Other useful strings include <juju> and <unit>. Those are both covered by <root>, but can be configured individually for control of everything juju logs, or everything a unit lots, etc.

This is all documented here: https://discourse.juju.is/t/juju-logs/1184

(There are probably improvements to be made to the docs -- please comment here or on discourse if you have suggestions!)

[Pen Gale (pengale)]

Marking as "incomplete" for now, as we're not certain about the tracebacks being a bug or misconfiguration.

If the tracebacks don't appear after setting the root log level, either at bootstrap time or after, please comment here, and we'll officially open this as a bug.

[Corey Bryant (corey.bryant)]

This is unfortunately going to cause a lot of rework in the openstack charms if we want to capture useful logs on first-failure. Otherwise, the vast majority of bugs that get filed now are going to need recreation a second time with debug or info enabled. So it will most likely result in a whole lot more frustrating time spent on issues for juju users.

I'll check on the tracebacks after setting debug at bootstrap time.

[Corey Bryant (corey.bryant)]

Is it possible that commit 828c78df02 unintentially set the default log level for units to WARNING? Here's the commit message:

    Change the default log level to INFO everywhere.

    Rather than being unit=DEBUG, let operators set DEBUG if they really
    want it. We don't seem to have any log messages that we generate that
    should be INFO instead of DEBUG.

But the code seems to have dropped the code that defaulted units to DEBUG. Also I wonder if the removed 'return err' path explains the missing python tracebacks, as python logs tracebacks to stderr.

--- a/environs/config/config.go
+++ b/environs/config/config.go
@@ -519,14 +519,6 @@ func (c *Config) ensureUnitLogging() error {
                        loggingConfig = loggo.LoggerInfo()
                }
        }
- levels, err := loggo.ParseConfigString(loggingConfig)
- if err != nil {
- return err
- }
- // If there is is no specified level for "unit", then set one.
- if _, ok := levels["unit"]; !ok {
- loggingConfig = loggingConfig + ";unit=DEBUG"
- }
        c.defined["logging-config"] = loggingConfig
        return nil
 }

[Corey Bryant (corey.bryant)]

Btw, I retested a python exception in a hook with: juju model-config "logging-config=<root>=DEBUG"
and didn't see anything in the juju log.

[Michael Skalka (mskalka)]

This has bit us in CI as well. It's fairly trivial to set the logging config however anywhere we miss it results in hours of wasted test time.

[Pen Gale (pengale)]

Just to clarify: reverting to the old DEBUG-as-default behavior is a WONTFIX. Logs shouldn't be set to debug in production instances without an operator explicitly setting them to be so. I understand that this is annoying for test gates, but it is the right thing to do long term.

Tracebacks disappearing isn't intended behavior, though. We should definitely fix that!

[Corey Bryant (corey.bryant)]

@Pete, The unit logging is currently defaulting to WARNING.

[Heather Lanigan (hmlanigan)]

@corey.bryant,

Regarding #7, use "<unit>=DEBUG" as well:

logging-config="<root>=DEBUG;<unit>=DEBUG"

[Corey Bryant (corey.bryant)]

Hi Heather, the problem I'm seeing with defaults is that unit defaults to WARNING. Is that expected?

[Corey Bryant (corey.bryant)]

In other words, if I create a new controller without changing any juju logging defaults, unit logging defaults to WARNINGS.

[John A Meinel (jameinel)]

It wouldn't be <unit>=DEBUG but "unit=DEBUG" (no brackets, brackets are
only for 'root' because there isn't a way to express the empty value).

However <root> should definitely encompass unit, the most common prefixes
are "juju" and "unit" for our logging. So you *could* do:

"logging-config=juju=DEBUG;unit=DEBUG"
but
"logging-config=<root>=DEBUG" should cover that already.

On Fri, Sep 4, 2020 at 4:10 PM Corey Bryant <email address hidden>
wrote:

> In other words, if I create a new controller without changing any juju
> logging defaults, unit logging defaults to WARNINGS.
>
> ** Summary changed:
>
> - juju only logging WARNING and ERROR by default for units and no python
> tracebacks
> + juju unit logging defaults to WARNING and no python tracebacks at any
> log level
>
> --
> You received this bug notification because you are subscribed to juju.
> Matching subscriptions: juju bugs
> https://bugs.launchpad.net/bugs/1893993
>
> Title:
> juju unit logging defaults to WARNING and no python tracebacks at any
> log level
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/juju/+bug/1893993/+subscriptions
>

[Rodrigo Barbieri (rodrigo-barbieri2010)]

even with DEBUG logging I'm still not seeing stack traces, only:

2020-09-08 14:55:42 DEBUG juju.worker.logger logger.go:64 initial log config: "<root>=DEBUG"
2020-09-08 14:55:42 DEBUG juju.worker.logger logger.go:92 reconfiguring logging from "<root>=DEBUG" to "<root>=WARNING"
2020-09-08 15:03:14 ERROR juju.worker.uniter.operation runhook.go:136 hook "peer-relation-joined" (via explicit, bespoke hook script) failed: exit status 1

Curiously something is overriding the logging back to WARNING during runtime. That was a new model I deployed while already having the model-config set to <root>=DEBUG. Checking the model-config again, I see the model-config changed itself back to <root>=WARNING. That is not what I want and certainly not expected to happen, logging level shouldn't simply change itself automatically.

[Pen Gale (pengale)]

@rodrigo-barbieri2010 Thank you for the additional information on the issue. What was the command that you used to set the logging level to DEBUG initially? Did you pass "--debug" to the bootstrap command, or do something else?

@corey.bryant The changed to WARNING level logging by default everywhere, including in units, was an intentional change. Squelching tracebacks for ERROR level debugging was *not* an intentional change.

[Corey Bryant (corey.bryant)]

I didn't realize defaulting unit logging to WARNING was intentional. I'd have to double check but I'm pretty sure that not all logging is defaulting to WARNING. Also I'm somewhat confused because the change that introduced this says "Change the default log level to INFO everywhere.". INFO seems like a more reasonable default.

[John A Meinel (jameinel)]

INFO was the intentional default, and when I was bootstrapping and testing it, it is what I was seeing. I'm not sure where WARNING vs INFO is coming into play, but we can investigate.

As far as the log messages:
2020-09-08 14:55:42 DEBUG juju.worker.logger logger.go:92 reconfiguring logging from "<root>=DEBUG" to "<root>=WARNING"

All Agents default to DEBUG until the point they can connect to the controller and determine what their logging should be.
If you are seeing that exact message, that means that for that agent, its configured logging is <root>=WARNING and not <root>=DEBUG.

Note that each model has a separate logging configuration. I can't tell from those messages what agent is running, and it what model. (eg, the *controller itself* runs in the 'controller' model, while the applications you are deploying probably run in a different model.)
If you are reusing a controller, and want each newly created model to have a default logging config, you would use:

juju model-defaults logging-config="<root>=DEBUG"

(or if you 'juju bootstrap' with --debug, it will also set all the logging defaults to DEBUG.)

For the issues with "not showing python tracebacks". Juju has code that all stdout and stderr from a hook gets logged at DEBUG level.
https://github.com/juju/juju/blob/fa71c7819f2203f8d71fd9987eb38a630bcdddb1/worker/uniter/runner/runner.go#L582
https://github.com/juju/juju/blob/fa71c7819f2203f8d71fd9987eb38a630bcdddb1/worker/uniter/runner/runner.go#L475

It wouldn't be hard to change that up and have the loggerAdaptor take a parameter of the logging level, and have 2 pipes, one for stdout and one for stderr.

We already do that if we are running an action, we could just do it always and have stderr logging at a different level.

[John A Meinel (jameinel)]

A plausible solution (though needs explicit exercising and tests):
https://github.com/juju/juju/pull/11980

[Corey Bryant (corey.bryant)]

On Wed, Sep 9, 2020 at 1:25 PM John A Meinel <email address hidden>
wrote:

> INFO was the intentional default, and when I was bootstrapping and
> testing it, it is what I was seeing. I'm not sure where WARNING vs INFO
> is coming into play, but we can investigate.
>
> As far as the log messages:
> 2020-09-08 14:55:42 DEBUG juju.worker.logger logger.go:92 reconfiguring
> logging from "<root>=DEBUG" to "<root>=WARNING"
>
> All Agents default to DEBUG until the point they can connect to the
> controller and determine what their logging should be.
> If you are seeing that exact message, that means that for that agent, its
> configured logging is <root>=WARNING and not <root>=DEBUG.
>
>
I'm seeing that same log message. I'm not sure where it's getting set to
WARNING though.

[John A Meinel (jameinel)]

If the logging configuration in the model where the agent is "<root>=WARNING" you will see that message in all the agent logs. Because they always start up in DEBUG until they get told by the controller what their logging should be. If the logging configuration is something else they will report it.

You should also see in 'agent.conf' what it thinks the logging config should be. (Once the agent has managed to talk to the controller, it writes the logging config from its last conversation to agent.conf so it can start the next time with the 'best' logging that it knows about.)

[Corey Bryant (corey.bryant)]

Ok so the logging-config for model-defaults was set to the following:
$ juju model-defaults|grep logging-config
logging-config "" -

But agent.conf had:
loggingconfig: <root>=WARNING