juju-core

debug-log and boolean options are broken in trunk

Bug #1229286 reported by Francesco Banconi on 2013-09-23

This bug affects 2 people

Affects		Status	Importance	Assigned to	Milestone
	juju-core	Fix Released	High	Unassigned	juju-core 1.15.0

Bug Description

`juju debug-log` no longer includes the hooks output.
ISTM also that the boolean settings options are always set to false in the hooks context, both when they are true by default and when they are explicitly set to true using `juju-set`.

I feel I should file two separate bugs for these problems I encountered trying to deploy juju-gui in an environment set up using the current juju-core trunk.
I'll eventually do that if required. In the meanwhile, since I am not sure this is not a problem in my local configuration, I'll leave the instruction to dupe below.

To dupe (revno 1870):

- bootstrap an environment: `juju bootstrap --upload-tools`;
- in another terminal, run `juju debug-log`;
- deploy and expose the GUI:

juju deploy cs:~juju-gui/precise/juju-gui
juju expose juju-gui

You should see that the debug-log console does not include the hooks output.
Please find below the complete debug log.

- wait for the unit to be ready/started;
- use the browser to visit the GUI (run `juju status` to obtain the GUI address).

You should not be redirected to HTTPS: this indicates that the secure option is set to False. Note that by default secure is True, and the GUI itself shows the correct value in the inspector.

- change some options:

juju set juju-gui sandbox=true login-help=foo

Again: no output from the config-changed hook.

The first of the options above configures the GUI to run in sandbox mode (detached from the real environment, like in jujucharms.com) the second one changes the login help message (displayed at the bottom of the login form).

Visiting the GUI with the browser, while the login mask correctly shows the string "foo", the GUI is still connected to the real env (the GUI service block is visible): this behavior indicates that the config-changed hook was executed but, again, the boolean value was not correctly parsed.

Reverting juju-core to a previous revision (I used 1750), everything works as usual.

=== debug-log ===

$ juju debug-log
Warning: Permanently added 'ec2-54-227-57-18.compute-1.amazonaws.com,54.227.57.18' (ECDSA) to the list of known hosts.
ip-10-158-91-115:2013-09-23 15:56:21 DEBUG juju.worker.logger logger.go:35 initial log config: "<root>=DEBUG"
ip-10-158-91-115:2013-09-23 15:56:21 DEBUG juju.worker.logger logger.go:60 logger setup
ip-10-158-91-115:2013-09-23 15:56:21 INFO juju runner.go:253 worker: start "deployer"
ip-10-158-91-115:2013-09-23 15:56:21 DEBUG juju codec.go:104 rpc/jsoncodec: <- {"RequestId":4,"Type":"Machiner","Request":"Life","Params":{"Entities":[{"Tag":"machine-0"}]}}
ip-10-158-91-115:2013-09-23 15:56:21 DEBUG juju codec.go:104 rpc/jsoncodec: <- {"RequestId":5,"Type":"Upgrader","Request":"SetTools","Params":{"AgentTools":[{"Tag":"machine-0","Tools":{"Version":"1.15.0.1-precise-amd64","URL":"https://s3.amazonaws.com/juju-4192ce9daf0b4620b1338b46781-ec2/tools/releases/juju-1.15.0.1-precise-amd64.tgz?AWSAccessKeyId=AKIAINNXFGK7N2CNJ65Q&Expires=1695484332&Signature=Z2YOtjMSoxi38ysguf4Sd61o0xw%3D","SHA256":"","Size":0}}]}}
ip-10-158-91-115:2013-09-23 15:56:21 DEBUG juju codec.go:104 rpc/jsoncodec: <- {"RequestId":6,"Type":"Logger","Request":"LoggingConfig","Params":{"Entities":[{"Tag":"machine-0"}]}}
ip-10-158-91-115:2013-09-23 15:56:21 DEBUG juju codec.go:104 rpc/jsoncodec: <- {"RequestId":7,"Type":"Deployer","Request":"WatchUnits","Params":{"Entities":[{"Tag":"machine-0"}]}}
ip-10-158-91-115:2013-09-23 15:56:21 DEBUG juju codec.go:169 rpc/jsoncodec: -> {"RequestId":4,"Response":{"Results":[{"Life":"alive","Error":null}]}}
ip-10-158-91-115:2013-09-23 15:56:21 DEBUG juju codec.go:169 rpc/jsoncodec: -> {"RequestId":6,"Response":{"Results":[{"Error":null,"Result":"\u003croot\u003e=WARNING"}]}}
ip-10-158-91-115:2013-09-23 15:56:21 DEBUG juju.worker.logger logger.go:45 reconfiguring logging from "<root>=DEBUG" to "<root>=WARNING"

ip-10-181-142-55:2013-09-23 16:01:09 DEBUG juju.agent agent.go:241 Reading agent config, format: format 1.16
ip-10-181-142-55:2013-09-23 16:01:09 INFO juju.jujud unit.go:73 unit agent unit-juju-gui-0 start
ip-10-181-142-55:2013-09-23 16:01:09 INFO juju runner.go:253 worker: start "api"
ip-10-181-142-55:2013-09-23 16:01:09 INFO juju apiclient.go:111 state/api: dialing "wss://ec2-54-227-57-18.compute-1.amazonaws.com:17070/"
ip-10-181-142-55:2013-09-23 16:01:09 INFO juju apiclient.go:121 state/api: connection established
ip-10-181-142-55:2013-09-23 16:01:09 INFO juju runner.go:253 worker: start "upgrader"
ip-10-181-142-55:2013-09-23 16:01:09 INFO juju runner.go:253 worker: start "logger"
ip-10-181-142-55:2013-09-23 16:01:09 DEBUG juju.worker.logger logger.go:35 initial log config: "<root>=DEBUG"
ip-10-181-142-55:2013-09-23 16:01:09 INFO juju runner.go:253 worker: start "uniter"
ip-10-181-142-55:2013-09-23 16:01:09 DEBUG juju.worker.logger logger.go:60 logger setup
ip-10-181-142-55:2013-09-23 16:01:09 DEBUG juju.worker.logger logger.go:45 reconfiguring logging from "<root>=DEBUG" to "<root>=WARNING"
ip-10-181-142-55:2013-09-23 16:01:04 INFO juju runner.go:253 worker: start "state"
ip-10-158-91-115:2013-09-23 16:13:02 ERROR juju server.go:423 rpc: error writing response: EOF
ip-10-158-91-115:2013-09-23 16:13:05 ERROR juju server.go:423 rpc: error writing response: EOF
ip-10-158-91-115:2013-09-23 16:13:09 ERROR juju server.go:423 rpc: error writing response: EOF
ip-10-158-91-115:2013-09-23 16:13:49 ERROR juju server.go:423 rpc: error writing response: EOF

=== unit log ===

$ juju ssh 1 cat /var/log/juju/unit-juju-gui-0.log
Warning: Permanently added 'ec2-107-20-121-220.compute-1.amazonaws.com,107.20.121.220' (ECDSA) to the list of known hosts.
2013-09-23 16:01:09 DEBUG juju.agent agent.go:241 Reading agent config, format: format 1.16
2013-09-23 16:01:09 INFO juju.jujud unit.go:73 unit agent unit-juju-gui-0 start
2013-09-23 16:01:09 INFO juju runner.go:253 worker: start "api"
2013-09-23 16:01:09 INFO juju apiclient.go:111 state/api: dialing "wss://ec2-54-227-57-18.compute-1.amazonaws.com:17070/"
2013-09-23 16:01:09 INFO juju apiclient.go:121 state/api: connection established
2013-09-23 16:01:09 INFO juju runner.go:253 worker: start "upgrader"
2013-09-23 16:01:09 INFO juju runner.go:253 worker: start "logger"
2013-09-23 16:01:09 DEBUG juju.worker.logger logger.go:35 initial log config: "<root>=DEBUG"
2013-09-23 16:01:09 INFO juju runner.go:253 worker: start "uniter"
2013-09-23 16:01:09 DEBUG juju.worker.logger logger.go:60 logger setup
2013-09-23 16:01:09 DEBUG juju.worker.logger logger.go:45 reconfiguring logging from "<root>=DEBUG" to "<root>=WARNING"
Connection to ec2-107-20-121-220.compute-1.amazonaws.com closed.

=== status ===

$ juju status
environment: ec2
machines:
  "0":
    agent-state: started
    agent-version: 1.15.0.1
    dns-name: ec2-54-227-57-18.compute-1.amazonaws.com
    instance-id: i-ea6bc78e
    instance-state: running
    series: precise
    hardware: arch=amd64 cpu-cores=1 cpu-power=100 mem=1740M root-disk=8192M
  "1":
    agent-state: started
    agent-version: 1.15.0.1
    dns-name: ec2-107-20-121-220.compute-1.amazonaws.com
    instance-id: i-d64085ab
    instance-state: running
    series: precise
    hardware: arch=amd64 cpu-cores=1 cpu-power=100 mem=1740M root-disk=8192M
services:
  juju-gui:
    charm: cs:~juju-gui/precise/juju-gui-106
    exposed: true
    units:
      juju-gui/0:
        agent-state: started
        agent-version: 1.15.0.1
        machine: "1"
        open-ports:
        - 80/tcp
        - 443/tcp
        public-address: ec2-107-20-121-220.compute-1.amazonaws.com

Revision history for this message

Tim Penhey (thumper) wrote on 2013-09-26:

Download full text (3.5 KiB)

Sorry, part of this is by design, and poorly communicated by me.

For a long time (all of juju-core up to now), all the machine agents
logged everything at debug. Logging at the debug level is used
primarily by developers. Warnings and errors are of more interest to
the users, and sometimes the informational messages. Some time back, a
new hierarchical logging facility was added. This allows logging to be
grouped and potentially have different groups of log messages output at
different severity levels. These groups are dotted names that should be
familiar to people that have used log4j, python logging or many other
logging frameworks. We call these logical groups "modules". Modules
have parents, being those the next level up, and there is a <root> which
is the parent of all first level modules.

For example:
  juju.agent is the parent of juju.agent.tools
  juju is the parent of juju.agent
  <root> is the parent of juju

The default logging configuration is:
<root>=WARNING

This means that only warnings and above (error and critical) are logged
by default.

On the command line, there are two ways to change this. You can specify
an environment variable "JUJU_LOGGING_CONFIG", or you can specify
--log-config on the command line. The default for --log-config is the
JUJU_LOGGING_CONFIG environment variable, so if you specify --log-config
you override what the environment has set.

The environment variable gives developers a simple way to have the
default logging set to what they are currently working on. For example,
if I cared about the provisioner and the azure provider, I could do the
following:
export
JUJU_LOGGING_CONFIG=juju.provider.azure=DEBUG;juju.worker.provisioner=DEBUG

This would get combined with the default of <root>=WARNING.

NOTE: setting --log-config doesn't show the log file on the command
line, but does propagate the logging configuration into the environment,
so all agents that start up get that logging config.

To show the log on the command line, now use --show-log. The --debug
has been kept to be short-hand for "--log-config=<root>=DEBUG
--show-log", and --verbose has been deprecated with its current meaning
(we intend to have --verbose mean 'show me more output for the command I
am running', as logging and command output have different audiences
almost all the time).

If you are looking at the agent log files, or the debug-log command, you
will notice that the agents all start logging at the DEBUG level, but
once the internal workers are up and running, you'll see a line like this:

2013-09-23 15:56:21 DEBUG juju.worker.logger logger.go:45 reconfiguring
logging from "<root>=DEBUG" to "<root>=WARNING"

Every agent now has a worker that allows the logging configuration to be
changed on a running environment. The "<root>=WARNING" that the
configuration is being changed to is the default log-config specified at
environment bootstrap time, and if one isn't specified, it defaults to
warnings.

To change the logging config of a running environment, you can use the
existing "set-environment" (or "set-env") command.

juju set-env 'logging-config=<root>=INFO;juju.provider=DEBUG'

and this is then propagated through to ...

Sorry, part of this is by design, and poorly communicated by me.

For a long time (all of juju-core up to now), all the machine agents
logged everything at debug.  Logging at the debug level is used
primarily by developers.  Warnings and errors are of more interest to
the users, and sometimes the informational messages.  Some time back, a
new hierarchical logging facility was added.  This allows logging to be
grouped and potentially have different groups of log messages output at
different severity levels.  These groups are dotted names that should be
familiar to people that have used log4j, python logging or many other
logging frameworks.  We call these logical groups "modules".  Modules
have parents, being those the next level up, and there is a <root> which
is the parent of all first level modules.

For example:
  juju.agent is the parent of juju.agent.tools
  juju is the parent of juju.agent
  <root> is the parent of juju

The default logging configuration is:
  <root>=WARNING

This means that only warnings and above (error and critical) are logged
by default.

On the command line, there are two ways to change this.  You can specify
an environment variable "JUJU_LOGGING_CONFIG", or you can specify
--log-config on the command line.  The default for --log-config is the
JUJU_LOGGING_CONFIG environment variable, so if you specify --log-config
you override what the environment has set.

The environment variable gives developers a simple way to have the
default logging set to what they are currently working on.  For example,
if I cared about the provisioner and the azure provider, I could do the
following:
  export
JUJU_LOGGING_CONFIG=juju.provider.azure=DEBUG;juju.worker.provisioner=DEBUG

This would get combined with the default of <root>=WARNING.

NOTE: setting --log-config doesn't show the log file on the command
line, but does propagate the logging configuration into the environment,
so all agents that start up get that logging config.

To show the log on the command line, now use --show-log.  The --debug
has been kept to be short-hand for "--log-config=<root>=DEBUG
--show-log", and --verbose has been deprecated with its current meaning
(we intend to have --verbose mean 'show me more output for the command I
am running', as logging and command output have different audiences
almost all the time).

2013-09-23 15:56:21 DEBUG juju.worker.logger logger.go:45 reconfiguring
logging from "<root>=DEBUG" to "<root>=WARNING"

Every agent now has a worker that allows the logging configuration to be
changed on a running environment.  The "<root>=WARNING" that the
configuration is being changed to is the default log-config specified at
environment bootstrap time, and if one isn't specified, it defaults to
warnings.

To change the logging config of a running environment, you can use the
existing "set-environment" (or "set-env") command.

juju set-env 'logging-config=<root>=INFO;juju.provider=DEBUG'

and this is then propagated through to all the running agents.  Note
that this is NOT additive.  So if the existing logging config was
"juju.provider.azure=DEBUG", and it was changed to "juju.agent=DEBUG",
the juju.provider.azure would default back to the parent's level, which
would be WARNING.

You only need to specify the root logger if you want to change it from
WARNING to something else, as by default it is set to WARNING.

Revision history for this message

Francesco Banconi (frankban) wrote on 2013-09-27:

Thank you Tim for your very helpful clarification! It seems that the other problem I reported in this bug (boolean config options) was also fixed yesterday (Dimiter?), so I am setting this as fix committed.

Changed in juju-core:
status:	New → Fix Committed
importance:	Undecided → High

Tim Penhey (thumper) on 2013-09-30

Changed in juju-core:
milestone:	none → 1.15.0

Curtis Hovey (sinzui) on 2013-10-05

Changed in juju-core:
status:	Fix Committed → Fix Released

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.