DEBUG messages show when only INFO was asked for

[Aaron Bentley]

As seen here:
http://data.vapour.ws/juju-ci/products/version-2328/azure-upgrade-trusty-amd64/build-3526/consoleText

We issue "juju --show-log bootstrap -e azure-upgrade-trusty-amd64 --constraints mem=2G" but we get DEBUG messages.

This is a security issue because DEBUG messages often contain credentials. It is a regression because we used to only get INFO messages, and our credentials used to be safe.

[Tim Penhey (thumper)]

No I disagree. This has been the behaviour since it was implemented.

All agents, machine and unit are started with logging set to the debug level. This is until the logging worker starts and gets told what the logging level should be.

This was a design decision at the time and most certainly isn't a regression.

Can you please show old and new logs? This behaviour hasn't changed, so I'm curious as to what has changed.

[Dimiter Naydenov (dimitern)]

As for the security side of things - absolutely! We shouldn't be logging sensitive info like keys or credentials even at DEBUG level. We might need a dedicated feature flag like "full on debug" though, in case developers want to see all.

[Aaron Bentley (abentley)]

Normally, we don't see DEBUG messages when we do --show-log

Here are some examples from http://reports.vapour.ws/releases/2335
http://data.vapour.ws/juju-ci/products/version-2312/aws-deploy-precise-amd64/build-2260/consoleText
http://data.vapour.ws/juju-ci/products/version-2335/azure-deploy-trusty-amd64/build-3064/consoleText
http://data.vapour.ws/juju-ci/products/version-2335/canonistack-deploy-trusty-amd64/build-2681/consoleText
http://data.vapour.ws/juju-ci/products/version-2335/hp-deploy-trusty-amd64/build-2335/consoleText
http://data.vapour.ws/juju-ci/products/version-2335/joyent-deploy-trusty-amd64/build-208/consoleText
http://data.vapour.ws/juju-ci/products/version-2335/kvm-deploy-trusty-amd64/build-672/consoleText
http://data.vapour.ws/juju-ci/products/version-2335/local-deploy-precise-amd64/build-2414/consoleText
http://data.vapour.ws/juju-ci/products/version-2335/maas-1_7-deploy-trusty-amd64/build-597/consoleText
http://data.vapour.ws/juju-ci/products/version-2335/manual-deploy-precise-amd64/build-1732/consoleText

Note: this isn't just bootstrap, this is a whole lifecycle from bootstrap to destroy-environment, without any DEBUG messages.

So this appears to be a change in behaviour. It may be that the POLICY is old, but no DEBUG messages were actually emitted until recently.

If it is not, it is at least surprising behaviour. If the messages are valuable for more than debugging, then they should be logged at the INFO level. If the info is only useful for debugging, then it should not be shown by default.

[Dimiter Naydenov (dimitern)]

Is this azure-specific or other substrates seem affected as well?

[Aaron Bentley (abentley)]

Other substrates are affected:
http://data.vapour.ws/juju-ci/products/version-2328/local-upgrade-trusty-amd64/build-820/consoleText
http://data.vapour.ws/juju-ci/products/version-2328/kvm-upgrade-trusty-amd64/build-436/consoleText
http://data.vapour.ws/juju-ci/products/version-2328/manual-deploy-trusty-ppc64/build-1118/consoleText
http://data.vapour.ws/juju-ci/products/version-2328/manual-deploy-trusty-ppc64/build-1117/consoleText

[Dimiter Naydenov (dimitern)]

http://data.vapour.ws/juju-ci/products/version-2328/local-upgrade-trusty-amd64/build-820/consoleText actually uses "juju --debug bootstrap .." (unlike the --show-log otherwise used), so debug logs are expected. As for the others it seems the extra logging is related to how certain jobs are run (kvm, manual-deploy, etc.) as none of the lines coming from apt, like:

Ign http://ports.ubuntu.com trusty InRelease
Ign http://ports.ubuntu.com trusty-updates InRelease
Ign http://ports.ubuntu.com trusty-proposed InRelease
Ign http://ports.ubuntu.com trusty-security InRelease
Hit http://ports.ubuntu.com trusty Release.gpg
Hit http://ports.ubuntu.com trusty-updates Release.gpg
Hit http://ports.ubuntu.com trusty-proposed Release.gpg
Hit http://ports.ubuntu.com trusty-security Release.gpg
Hit http://ports.ubuntu.com trusty Release
...

are coming from juju (even with --debug we don't print these directly on stderr but with log prefixes). Maybe ppc64 lxc/kvm tests are poorly isolated from the host? I've seen the recent commits in ~juju-qa repos, some of these look like possible causes (e.g. added --debug to all tests jobs, adding/removing set +x in some bash scripts, implementing async bootstrap - i.e. if something else is dumping to stderr while bootstrap does not).

In any case - going through all recent jobs in the past 2 weeks or so (way before version-2328 quoted as the first time this started happening) I can see a mixture of DEBUG logs being present or not in different job types, and combined with a detailed analysis of recent commits across all the main branches of juju/juju and anything related to logging, I'd say this is not a juju issue but a CI setup one.

[Tim Penhey (thumper)]

I'm confused, because I checked the 1.20 source tree, and found this:

  c.AddScripts(
   // The bootstrapping is always run with debug on.
   cfg.jujuTools() + "/jujud bootstrap-state" +
    " --data-dir " + shquote(cfg.DataDir) +
    " --env-config " + shquote(base64yaml(cfg.Config)) +
    " --instance-id " + shquote(string(cfg.InstanceId)) +
    hardware +
    cons +
    " --debug",
  )

Which clearly shows that bootstrap-state is called with --debug.

[Aaron Bentley (abentley)]

Tim, you're probably right about the internal state. But I am reporting this bug from a user perspective. DEBUG appears in unit test runs, but it doesn't appear in any other logs for:

http://reports.vapour.ws/releases/2148
http://reports.vapour.ws/releases/2146

Those are the only builds of 1.20.x that we still have console logs for. Can you give us a counterexample where DEBUG messages were emitted in the 1.20 series?

[Tim Penhey (thumper)]

Aaron, I'm guessing it is environmental.

The JUJU_LOGGING_CONFIG environment variable is the default if '--logging-config' is not specified.

Can you please try adding "--logging-config=<root>=INFO" to the command line?

[Aaron Bentley (abentley)]

We do not set JUJU_LOGGING_CONFIG. You can see all the environment variables we *do* set in the log.