MAAS2: UnicodeDecodeError: 'ascii' codec can't decode byte 0xe2 in position 277: ordinal not in range(128)

Can you attach the target file contents?

etc/sysctl.d/10-ipv6-privacy.conf

What image was being deployed?

I saw the same thing when deploying Ubuntu 16.04 LTS using MAAS 2.

MAAS deployment workflow makes it hard to grab the etc/sysctl.d/10-ipv6-privacy.conf file. However, from a commissioning environment I grabbed: http://paste.ubuntu.com/23511486/

Note the fancy ' on line 9 (AKA position 277)

Is somehow the default encoding getting changed? Out of the box Python 3 should use UTF-8 for file I/O.

$ python3
Python 3.5.2 (default, Sep 10 2016, 08:21:44)
[GCC 5.4.0 20160609] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> x = open("/etc/sysctl.d/10-ipv6-privacy.conf", "r").read()
>>> x
"# IPv6 Privacy Extensions (RFC 4941)\n# ---\n# IPv6 typically uses a device's MAC address when choosing an IPv6 address\n# to use in autoconfiguration. Privacy extensions allow using a randomly\n# generated IPv6 address, which increases privacy.\n#\n# Acceptable values:\n# 0 - don’t use privacy extensions.\n# 1 - generate privacy addresses\n# 2 - prefer privacy addresses and use them over the normal addresses.\nnet.ipv6.conf.all.use_tempaddr = 2\nnet.ipv6.conf.default.use_tempaddr = 2\n"
>>> x = open("/etc/sysctl.d/10-ipv6-privacy.conf", "r", encoding="ascii").read()
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/lib/python3.5/encodings/ascii.py", line 26, in decode
    return codecs.ascii_decode(input, self.errors)[0]
UnicodeDecodeError: 'ascii' codec can't decode byte 0xe2 in position 277: ordinal not in range(128)

On Mon, Nov 21, 2016 at 6:45 AM, Adam Collard <email address hidden>
wrote:

> I saw the same thing when deploying Ubuntu 16.04 LTS using MAAS 2.
>
> MAAS deployment workflow makes it hard to grab the
> etc/sysctl.d/10-ipv6-privacy.conf file. However, from a commissioning
> environment I grabbed: http://paste.ubuntu.com/23511486/
>
> Note the fancy ' on line 9 (AKA position 277)
>

Hrm, this has been in the file for quite some time (at least wily, probably
longer)

So, not quite sure how this is triggered when clearly in out test
environments we
will have the same file.

> Is somehow the default encoding getting changed? Out of the box Python 3
> should use UTF-8 for file I/O.
>

OK, looks like this is LANG related.

(foudres) trunk % echo $LANG
en_US.UTF-8
(foudres) trunk % python3 -c
"open('target/etc/sysctl.d/10-ipv6-privacy.conf', 'r').read()"(foudres)
trunk % LANG=C python3 -c "open('target/etc/sysctl.d/10-ipv6-privacy.conf',
'r').read()"
Traceback (most recent call last):
  File "<string>", line 1, in <module>
  File "/usr/lib/python3.5/encodings/ascii.py", line 26, in decode
    return codecs.ascii_decode(input, self.errors)[0]
UnicodeDecodeError: 'ascii' codec can't decode byte 0xe2 in position 277:
ordinal not in range(128)

I've a fix for handling the decode, however, I'm interested in how LANG
gets set or reset.
We've close to 950 installs run which never trip this today, so something
is different in the environment.

Can we get an installation log and curtin configuration? I assume this is
100% reproducible at this point.

> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1635560
>
> Title:
> MAAS2: UnicodeDecodeError: 'ascii' codec can't decode byte 0xe2 in
> position 277: ordinal not in range(128)
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/curtin/+bug/1635560/+subscriptions
>

On Mon, 21 Nov 2016 at 15:30 Ryan Harper <email address hidden> wrote:

> On Mon, Nov 21, 2016 at 6:45 AM, Adam Collard <email address hidden>
> wrote:
>
> > I saw the same thing when deploying Ubuntu 16.04 LTS using MAAS 2.
> >
> > MAAS deployment workflow makes it hard to grab the
> > etc/sysctl.d/10-ipv6-privacy.conf file. However, from a commissioning
> > environment I grabbed: http://paste.ubuntu.com/23511486/
> >
> > Note the fancy ' on line 9 (AKA position 277)
> >
>
> Hrm, this has been in the file for quite some time (at least wily, probably
> longer)
>
> So, not quite sure how this is triggered when clearly in out test
> environments we
> will have the same file.
>
>
> > Is somehow the default encoding getting changed? Out of the box Python 3
> > should use UTF-8 for file I/O.
> >
>
>
> OK, looks like this is LANG related.
>
>
> (foudres) trunk % echo $LANG
> en_US.UTF-8
> (foudres) trunk % python3 -c
> "open('target/etc/sysctl.d/10-ipv6-privacy.conf', 'r').read()"(foudres)
> trunk % LANG=C python3 -c "open('target/etc/sysctl.d/10-ipv6-privacy.conf',
> 'r').read()"
> Traceback (most recent call last):
> File "<string>", line 1, in <module>
> File "/usr/lib/python3.5/encodings/ascii.py", line 26, in decode
> return codecs.ascii_decode(input, self.errors)[0]
> UnicodeDecodeError: 'ascii' codec can't decode byte 0xe2 in position 277:
> ordinal not in range(128)
>
> I've a fix for handling the decode, however, I'm interested in how LANG
> gets set or reset.
> We've close to 950 installs run which never trip this today, so something
> is different in the environment.
>
> Can we get an installation log and curtin configuration? I assume this is
> 100% reproducible at this point.
>

You assume incorrectly :/

Given the nature of the code though it's not that surprising - the code is
explicitly trying to cope with the results of a losing race.

>
>
> > --
> > You received this bug notification because you are subscribed to the bug
> > report.
> > https://bugs.launchpad.net/bugs/1635560
> >
> > Title:
> > MAAS2: UnicodeDecodeError: 'ascii' codec can't decode byte 0xe2 in
> > position 277: ordinal not in range(128)
> >
> > To manage notifications about this bug go to:
> > https://bugs.launchpad.net/curtin/+bug/1635560/+subscriptions
> >
>
>
> ** Changed in: curtin
> Status: New => Incomplete
>
> --
> You received this bug notification because you are a member of
> Landscape, which is subscribed to the bug report.
> https://bugs.launchpad.net/bugs/1635560
>
> Title:
> MAAS2: UnicodeDecodeError: 'ascii' codec can't decode byte 0xe2 in
> position 277: ordinal not in range(128)
>
> Status in curtin:
> Incomplete
> Status in MAAS:
> Invalid
>
> Bug description:
> When deploying a node via juju2 and maas2, I see on
> /var/log/cloud-init-output.log
> """
> Creating config file /etc/default/grub with new version
> Generating grub configuration file ...
> Found linux image: /boot/vmlinuz-4.4.0-45-generic
> Found initrd image: /boot/initrd.img-4.4.0-45-generic
> /run/lvm/lvmetad.socket: connect failed: No such file or directory
> WARNING: Failed to connect to lvmetad. Falling back to internal...

Just seen it again on the same MAAS controller but with a different machine.

Full installation log from a successful deploy (~08:XX) and an unsuccessful one (~10:XX) at https://pastebin.canonical.com/171386/ with ureadahead entries grepped out - https://pastebin.canonical.com/171385/ if you're feeling brave.

Left them on the canonical pastebin because I believe they contain secrets.

Moved ureadahead spam to bug 1643838

Both look like failures (or success)?

Nov 22 08:33:42 faraday cloud-init[2313]: Disabling IPv6 privacy
extensions config may not apply.
/tmp/tmpwncjuxwe/target/etc/sysctl.d/10-ipv6-privacy.conf exists, but
could not be read.
Nov 22 08:33:42 faraday cloud-init[2313]: Traceback (most recent call last):
Nov 22 08:33:42 faraday cloud-init[2313]: File
"/curtin/curtin/commands/apply_net.py", line 140, in
_disable_ipv6_privacy_extensions
Nov 22 08:33:42 faraday cloud-init[2313]: contents = util.load_file(cfg)
Nov 22 08:33:42 faraday cloud-init[2313]: File
"/curtin/curtin/util.py", line 322, in load_file
Nov 22 08:33:42 faraday cloud-init[2313]: return fp.read(read_len)
if read_len else fp.read()
Nov 22 08:33:42 faraday cloud-init[2313]: File
"/usr/lib/python3.5/encodings/ascii.py", line 26, in decode
Nov 22 08:33:42 faraday cloud-init[2313]: return
codecs.ascii_decode(input, self.errors)[0]
Nov 22 08:33:42 faraday cloud-init[2313]: UnicodeDecodeError: 'ascii'
codec can't decode byte 0xe2 in position 277: ordinal not in
range(128)

Nov 22 08:33:50 faraday cloud-init[2313]: curtin: Installation finished.

vs.

Nov 22 10:13:02 faraday cloud-init[2318]: Disabling IPv6 privacy
extensions config may not apply.
/tmp/tmp8s4ib1df/target/etc/sysctl.d/10-ipv6-privacy.conf exists, but
could not be read.
Nov 22 10:13:02 faraday cloud-init[2318]: Traceback (most recent call last):
Nov 22 10:13:02 faraday cloud-init[2318]: File
"/curtin/curtin/commands/apply_net.py", line 140, in
_disable_ipv6_privacy_extensions
Nov 22 10:13:02 faraday cloud-init[2318]: contents = util.load_file(cfg)
Nov 22 10:13:02 faraday cloud-init[2318]: File
"/curtin/curtin/util.py", line 322, in load_file
Nov 22 10:13:02 faraday cloud-init[2318]: return fp.read(read_len)
if read_len else fp.read()
Nov 22 10:13:02 faraday cloud-init[2318]: File
"/usr/lib/python3.5/encodings/ascii.py", line 26, in decode
Nov 22 10:13:02 faraday cloud-init[2318]: return
codecs.ascii_decode(input, self.errors)[0]
Nov 22 10:13:02 faraday cloud-init[2318]: UnicodeDecodeError: 'ascii'
codec can't decode byte 0xe2 in position 277: ordinal not in
range(128)

Nov 22 10:13:16 faraday cloud-init[2318]: curtin: Installation finished.

On Tue, Nov 22, 2016 at 4:58 AM, Adam Collard <email address hidden>
wrote:

> Moved ureadahead spam to bug 1643838
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1635560
>
> Title:
> MAAS2: UnicodeDecodeError: 'ascii' codec can't decode byte 0xe2 in
> position 277: ordinal not in range(128)
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/curtin/+bug/1635560/+subscriptions
>

I have 3 identical hosts in my environment. All 3 show this error and it appears to be 100% repeatable in my environment.

I have not been able to determine what the LANG variable is set to at this point in the install. It would be nice if I could inject an "echo $LANG" command right before and right after the Disabling IPv6 privacy extensions file is processed.

Running this command with other, possibly garbage, langs will also cause the traceback:

$ LANG=en_US python3 -c "open('/etc/sysctl.d/10-ipv6-privacy.conf', 'r').read()"
Traceback (most recent call last):
  File "<string>", line 1, in <module>
  File "/usr/lib/python3.5/encodings/ascii.py", line 26, in decode
    return codecs.ascii_decode(input, self.errors)[0]
UnicodeDecodeError: 'ascii' codec can't decode byte 0xe2 in position 277: ordinal not in range(128)

> Both look like failures (or success)?

Nov 22 08:33:53 faraday [CLOUDINIT] handlers.py[DEBUG]: finish: modules-final: SUCCESS: running modules for final

✂✂✂

Nov 22 10:13:23 faraday [CLOUDINIT] handlers.py[DEBUG]: finish: modules-final: FAIL: running modules for final

I wonder if this isn't a red-herring then, and there's some other reason for the failure?

Ahh I think this looks like a disguised traceback

Nov 22 10:13:21 faraday [CLOUDINIT] util.py[DEBUG]: Cloud-init 0.7.8 received SIGTERM, exiting...#012 Filename: /usr/lib/python3.5/socket.py#012 Function: readinto#012 Line number: 575#012 Filename: /usr/lib/python3.5/http/client.py#012 Function: _read_status#012 Line number: 258#012 Filename: /usr/lib/python3.5/http/client.py#012 Function: begin#012 Line number: 297

From what I can see so far, while curtin is throwing a stacktrace when encountering the utf-8 char in the ipv6-privacy.conf file, this is _NON_FATAL_ to the curtin install; we complete installation fine.

IIUC Adam is looking into the other stacktrace emitted (Comment #1) in the during the cloud-final stage; given it's socket IO, I'd suggest it may be related to posting the results back to maas; but we'd need to examine /var/log/cloud-init*.log and /var/lib/cloud/ dir for errors. Attaching those log files here would be helpful for helping root cause the failure.

On the curtin side, I've now published the linked branch which addresses the decoding error seen when LANG is somehow unset or reset to LANG=C.

ppa:raharper/bugfixes

- curtin 0.1.0~bzr433-0ubuntu1

This should help eliminate the curtin stacktrace from the list of possible causes of this failure.

Another failed deploy, I don't want this to be noise. If the theory about a hidden stack trace in the log is correct, this one had the following stack trace:

Nov 29 22:18:21 galileo [CLOUDINIT] util.py[WARNING]: Running module apt-configure (<module 'cloudinit.config.cc_apt_configure' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_apt_configure.py'>) failed

Nov 29 22:18:21 galileo [CLOUDINIT] util.py[DEBUG]: Running module apt-configure (<module 'cloudinit.config.cc_apt_configure' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_apt_configure.py'>) failed
Traceback (most recent call last):#013 File "/usr/lib/python3/dist-packages/cloudinit/stages.py", line 792, in _run_modules
    freq=freq)
  File "/usr/lib/python3/dist-packages/cloudinit/cloud.py", line 70, in run
    return self._runners.run(name, functor, args, freq, clear_on_fail)
  File "/usr/lib/python3/dist-packages/cloudinit/helpers.py", line 199, in run
    results = functor(*args)
  File "/usr/lib/python3/dist-packages/cloudinit/config/cc_apt_configure.py", line 284, in handle
    ocfg = convert_to_v3_apt_format(ocfg)
  File "/usr/lib/python3/dist-packages/cloudinit/config/cc_apt_configure.py", line 748, in convert_to_v3_apt_format
    cfg = convert_v2_to_v3_apt_format(cfg)
  File "/usr/lib/python3/dist-packages/cloudinit/config/cc_apt_configure.py", line 714, in convert_v2_to_v3_apt_format
    oldkey))
ValueError: Old and New apt format defined with unequal values True vs False @ apt_preserve_sources_list

> Old and New apt format defined with unequal values True vs False @
apt_preserve_sources_list

That's an issue with the user-data sent for apt_source.

Can you tar up /var/lib/cloud ? That should have the user-data that was
sent from MAAS.

Looking at the cloud-init.log I think this is the 'maas isn't responding to
HTTP puts'

% grep WARNING var/log/cloud-init.log
Nov 29 22:18:04 galileo [CLOUDINIT] handlers.py[WARNING]: failed posting
event: start: init-local/check-cache: attempting to read from cache [trust]
Nov 29 22:18:04 galileo [CLOUDINIT] handlers.py[WARNING]: failed posting
event: finish: init-local/check-cache: SUCCESS: no cache found
Nov 29 22:18:04 galileo [CLOUDINIT] handlers.py[WARNING]: failed posting
event: finish: init-local: SUCCESS: searching for local datasources
Nov 29 22:18:04 galileo [CLOUDINIT] handlers.py[WARNING]: failed posting
event: start: init-network/check-cache: attempting to read from cache
[trust]

syslog shows wonky network:

<rharper> I think network is wonky
<rharper> your eno1 link is going up and down
<rharper> during execution
<rharper> Nov 29 22:18:04 galileo cloud-init[1027]: 2016-11-29 22:17:22,191
- handlers.py[WARNING]: failed posting event: start:
init-network/check-cache: attempting to read from cache [trust]
<rharper> Nov 29 22:18:04 galileo kernel: [ 6.693729] IPv6:
ADDRCONF(NETDEV_UP): eno1: link is not ready
<rharper> Nov 29 22:18:04 galileo kernel: [ 9.481423] ax88179_178a
2-1.6:1.0 enx0023554c9836: ax88179 - Link status is: 1
<rharper> we fail to post to maas at the same time the link is marked not
ready (after already being up for cloud-init)
<dpb> that is the second interface
<rharper> cloud-init[1027]: ci-info: | eno1 | True | 10.2.0.86
| 255.255.0.0 | . | ec:a8:6b:f9:95:a3 |
<dpb> interesting
<rharper> it's the *primary* interface
<rharper> 0 | 0.0.0.0 | 10.2.0.1 | 0.0.0.0 | eno1 | UG
<rharper> your USB nic isn't
<rharper> enx0023554c9836 | True | . | . | . |
00:23:55:4c:98:36
<rharper> it's up, but not configured
<rharper> can you get /var/lib/cloud off of a failure ? I'd like to
examine the cloud-init results.json
<-- slashd has quit (Ping timeout: 121 seconds)
<dpb> hm
<rharper> I don't think the posts are failures ... also I'd like to examine
the user-data sent for apt-source; your stack indicates it's misconfigured

On Tue, Nov 29, 2016 at 4:39 PM, David Britton <email address hidden>
wrote:

> Another failed deploy, I don't want this to be noise. If the theory
> about a hidden stack trace in the log is correct, this one had the
> following stack trace:
>
> Nov 29 22:18:21 galileo [CLOUDINIT] util.py[WARNING]: Running module
> apt-configure (<module 'cloudinit.config.cc_apt_configure' from
> '/usr/lib/python3/dist-packages/cloudinit/config/cc_apt_configure.py'>)
> failed
>
> Nov 29 22:18:21 galileo [CLOUDINIT] util.py[DEBUG]: Running module
> apt-configure (<module 'cloudinit.config.cc_apt_configure' from
> '/usr/lib/python3/dist-packages/cloudinit/config/cc_apt_configure.py'>)
> failed
> Traceback (most recent call last):#013 File "/usr/lib/python3/dist-packages/cloudinit/stages.py",
> line 792, in _run_mod...

New kepler logs with /var/lib/cloud inside.

Thanks for the logs;

1) not sure why, but posting to MAAS isn't reliable; that's clearly an
issue; maybe look at the maas apache logs and sync timestamps to see
what's up
2) MAAS sends both v2 and v3 format for apt source configuration, however,
in this case, it has an error; the user-data doesn't seem to be written so
I can't point it out for sure
but the error message points to this bug

https://bugs.launchpad.net/cloud-init/+bug/1616831

On Tue, Nov 29, 2016 at 11:03 PM, David Britton <<email address hidden>
> wrote:

> New kepler logs with /var/lib/cloud inside.
>
> ** Attachment added: "kepler-logs.tgz"
> https://bugs.launchpad.net/maas/+bug/1635560/+attachment/
> 4785046/+files/kepler-logs.tgz
>
> ** Changed in: curtin
> Status: Incomplete => New
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1635560
>
> Title:
> MAAS2: UnicodeDecodeError: 'ascii' codec can't decode byte 0xe2 in
> position 277: ordinal not in range(128)
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/curtin/+bug/1635560/+subscriptions
>

David, the logs you collected were from a boot where maas just told the node to power down.
possibly after a fail already occurred.

The 2 things taht stick out in the log are the posting events failing, and what cloud-init is complaining about invalid config.

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/cloudinit/stages.py", line 792, in _run_modules
    freq=freq)
  File "/usr/lib/python3/dist-packages/cloudinit/cloud.py", line 70, in run
    return self._runners.run(name, functor, args, freq, clear_on_fail)
  File "/usr/lib/python3/dist-packages/cloudinit/helpers.py", line 199, in run
    results = functor(*args)
  File "/usr/lib/python3/dist-packages/cloudinit/config/cc_apt_configure.py", line 284, in handle
    ocfg = convert_to_v3_apt_format(ocfg)
  File "/usr/lib/python3/dist-packages/cloudinit/config/cc_apt_configure.py", line 748, in convert_to_v3_apt_format
    cfg = convert_v2_to_v3_apt_format(cfg)
  File "/usr/lib/python3/dist-packages/cloudinit/config/cc_apt_configure.py", line 714, in convert_v2_to_v3_apt_format
    oldkey))
ValueError: Old and New apt format defined with unequal values True vs False @ apt_preserve_sources_list

I'm marking the curtin task as invalid; At this point I feel we can see *real* failure is related to two things:
1) cloud-init is unable to post messages via HTTP back to maas (not cloud-init's fault AFAICT)
2) the apt-source config being provided is invalid, cc_apt_source module fails, and thus cloud-init result is failed, hence failed deployment.

Please modify the curtin status if you find sufficient data to target curtin as the source of the bug. Curtin will still work on landing a fix for the stacktrace shown, as well as ensuring curtin fails the install (it shouldn't ignore the failure to disable ipv6 privacy setting).

It has been discovered this is simply a small failure (non-blocking). Please keep the comments focused on:

UnicodeDecodeError: 'ascii' codec can't decode byte 0xe2 in position 277: ordinal not in range(128)

that occurs in logs, not about other failures. If you see this message, it shouldn't be blocking your boot or anything like that.

fix commited in trunk at revno 446.

This will be fixed in the curtin upload that is in ubuntu at any revision > 446 (yakkety and xenial have 460 in their queue).

This bug is believed to be fixed in curtin in 17.1. If this is still a problem for you, please make a comment and set the state back to New

Thank you.