Parse error when applying config changes

[Laurent Sesquès]

Mojo fails to apply config changes on an environment for no apparent reason. The failure is:
2017-03-15 15:38:20 [INFO] Applying config changes, if any.
2017-03-15 15:38:20 [INFO] Pulling secrets from /srv/mojo/LOCAL/[...]
2017-03-15 15:38:23 [ERROR] Unknown error
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/mojo/cli.py", line 606, in run_with_args
    args.func(args)
  File "/usr/lib/python2.7/dist-packages/mojo/utils.py", line 305, in wrapped
    return method(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/mojo/cli.py", line 334, in run_from_manifest
    manifest.run(project, workspace, args.stage)
  File "/usr/lib/python2.7/dist-packages/mojo/manifest.py", line 96, in run
    auto_secrets=auto_secrets)
  File "/usr/lib/python2.7/dist-packages/mojo/phase.py", line 806, in run
    diff_processor=lambda d: process_config_changes_from_diff(
  File "/usr/lib/python2.7/dist-packages/mojo/phase.py", line 677, in diff
    diff_processor(diff)
  File "/usr/lib/python2.7/dist-packages/mojo/phase.py", line 807, in <lambda>
    d, preview=False),
  File "/usr/lib/python2.7/dist-packages/mojo/phase.py", line 438, in process_config_changes_from_diff
    diffs = yaml.safe_load(deployer_diff)
  File "/usr/lib/python2.7/dist-packages/yaml/__init__.py", line 93, in safe_load
    return load(stream, SafeLoader)
  File "/usr/lib/python2.7/dist-packages/yaml/__init__.py", line 71, in load
    return loader.get_single_data()
  File "/usr/lib/python2.7/dist-packages/yaml/constructor.py", line 37, in get_single_data
    node = self.get_single_node()
  File "/usr/lib/python2.7/dist-packages/yaml/composer.py", line 39, in get_single_node
    if not self.check_event(StreamEndEvent):
  File "/usr/lib/python2.7/dist-packages/yaml/parser.py", line 98, in check_event
    self.current_event = self.state()
  File "/usr/lib/python2.7/dist-packages/yaml/parser.py", line 174, in parse_document_start
    self.peek_token().start_mark)
ParserError: expected '<document start>', but found '<block mapping start>'
  in "<string>", line 2, column 1:
    relations:
    ^

I couldn't identify any problem with the services or with the secrets file.
The manifest calls:
deploy config=services local=secrets delay=0 apply-config-changes=True

fwiw, very similar configurations were used on a juju-1 environment successfully, and this is a juju 2 environment.

[Tom Haddon (mthaddon)]

I tested this with a juju 2 environment locally and it seemed to work okay, so I don't think it's something that's juju 2 specific.

I've been able to reproduce in the same environment, and have added some debugging information to show what it's trying to parse but failing on yaml.safe_load and I see this:

2017-03-16 09:31:19 [ERROR] Unable to parse:
{'last-known-access': 'login', 'user': 'REDACTED', 'password': 'REDACTED'}
relations:
  unknown:
  - - - haproxy:juju-info
      - livepatch:juju-info
  - - - apache-sign:juju-info
      - logstash-forwarder:juju-info
[...]

Will keep investigating.

[Tom Haddon (mthaddon)]

This is reproducible with "juju-deployer -c $someconfig --diff $sometarget" in the environment in question (in the sense that we get the {'last-known-access': 'login', 'user': 'REDACTED', 'password': 'REDACTED'} string first, which I believe is causing the problems).

Will check with juju-deployers.

[Ryan Finnie (fo0bar)]

Seeing this on a the esm production environment (wekufe), but not on staging (wendigo). AFAICT, the only difference is we had mucked with the model-config logging-config on production. Default is:

<root>=WARNING;unit=DEBUG

But production was once changed to:

<root>=WARNING;juju.txn=TRACE;unit=DEBUG

I tried changing that back to default and e.g. '<root>=WARNING;juju.txn=WARN;unit=DEBUG', without effect.

[Andreas Hasenack (ahasenack)]

We also just hit this in another juju2 model, and model-config shows its logging-config to be "<root>=WARNING;juju.txn=TRACE;unit=DEBUG". That TRACE seems relevant, but updating that config key to '<root>=WARNING;unit=DEBUG' didn't get rid of the extra debugging output and mojo still failed.

[Andreas Hasenack (ahasenack)]

oops, almost concurrent bug updates, sorry :)

[Nick Moffitt (nick-moffitt)]

I get the last-known-access line twice now:

2017-06-02 08:39:18 [INFO] deployer.cli: Deployment complete in 46.94 seconds
{'user': 'REDACTED', 'password': 'REDACTED', 'last-known-access': 'login'}
{'user': 'REDACTED', 'password': 'REDACTED', 'last-known-access': 'login'}
2017-06-02 08:39:19 [INFO] Checking Juju status (timeout=1800)
2017-06-02 08:39:26 [INFO] Applying config changes, if any.
2017-06-02 08:39:26 [INFO] Pulling secrets from /srv/mojo/LOCAL/REDACTED to /srv/mojo/REDACTED
2017-06-02 08:39:31 [ERROR] Unknown error
Traceback (most recent call last):

[Andreas Hasenack (ahasenack)]

This is still happening with the mojo-cdo-ubuntu-esm prodstack environment and is preventing us from dealing with that environment using mojo.

Sometimes we can workaround it by using juju directly instead of mojo, but that takes a lot of time and is "manual work", prone to errors.

[John A Meinel (jameinel)]

Given the traceback is on the Mojo side. Is it that Juju is replying a YAML response that mojo doesn't understand or is mojo not parsing your configuration correctly to apply it to us?

[Paul Collins (pjdc)]

The mystery output was due to a debugging print added by a python3-jujuclient patch that was cowboyed on wekufe. I've removed the print statement in question and tested --preview-config-changes with an environment where it failed formerly, and it works now. The patch is not present on wendigo.

[Launchpad Janitor (janitor)]

[Expired for juju because there has been no activity for 60 days.]