toolforge: puppet issue probably related to puppet-enc
Closed, ResolvedPublic
Actions

Assigned To

Authored By

	aborrero
	Jun 25 2019, 9:29 AM

Description

I just found out that mostly all of the Toolforge VMs have puppet issues:

aborrero@tools-k8s-master-01:~$ sudo puppet agent -tv
Warning: Unable to fetch my node definition, but the agent run will continue:
Warning: Error 500 on SERVER: Server Error: Failed to find tools-k8s-master-01.tools.eqiad.wmflabs via exec: Execution of '/usr/local/bin/puppet-enc tools-k8s-master-01.tools.eqiad.wmflabs' returned 1: 
Info: Retrieving pluginfacts
Info: Retrieving plugin
Info: Loading facts
Error: Could not retrieve catalog from remote server: Error 500 on SERVER: Server Error: Failed when searching for node tools-k8s-master-01.tools.eqiad.wmflabs: Failed to find tools-k8s-master-01.tools.eqiad.wmflabs via exec: Execution of '/usr/local/bin/puppet-enc tools-k8s-master-01.tools.eqiad.wmflabs' returned 1: 
Warning: Not using cache on failed catalog
Error: Could not retrieve catalog; skipping run

The error message mentions puppet-enc, which is the only clue I have by the time I'm creating this phab task.

Details

	Project	Branch	Lines +/-	Subject
	operations/puppet	production	+7 -0	cloud: add pin for jessie python3 broken package

Customize query in gerrit

Event Timeline

aborrero created this task.Jun 25 2019, 9:29 AM

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJun 25 2019, 9:29 AM

aborrero triaged this task as High priority.Jun 25 2019, 9:29 AM

aborrero moved this task from Inbox to Soon! on the cloud-services-team (Kanban) board.

Mentioned in SAL (#wikimedia-cloud) [2019-06-25T09:30:13Z] <arturo> detected puppet issue in all VMs: T226480

Looks like the tools puppetmaster ended up with a bit of a problem this morning

Jun 25 06:36:54 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/network/http/route.rb:87:in `process'
Jun 25 06:36:54 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/network/http/handler.rb:60:in `block in process'
Jun 25 06:36:54 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
Jun 25 06:36:54 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
Jun 25 06:36:54 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/network/http/handler.rb:58:in `process'
Jun 25 06:36:54 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/network/http/rack.rb:21:in `call'
Jun 25 06:36:54 tools-puppetmaster-01 puppet-master[31519]: config.ru:60:in `call'
Jun 25 06:36:54 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:74:in `process_request'
Jun 25 06:36:54 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:141:in `accept_and_process_next_request'
Jun 25 06:36:54 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:109:in `main_loop'
Jun 25 06:36:54 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler.rb:455:in `block (3 levels) in start_threads'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: Failed when searching for node tools-worker-1021.tools.eqiad.wmflabs: Failed to find tools-worker-1021.tools.eqiad.wmflabs via exec: Execution of '/usr/local/bin/puppet-enc tools-worker-1021.tools.eqiad.wmflabs' returned 1:
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: Server Error: Failed when searching for node tools-worker-1021.tools.eqiad.wmflabs: Failed to find tools-worker-1021.tools.eqiad.wmflabs via exec: Execution of '/usr/local/bin/puppet-enc tools-worker-1021.tools.eqiad.wmflabs' returned 1:
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/util/execution.rb:232:in `execute'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/indirector/node/exec.rb:33:in `execute'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/indirector/exec.rb:19:in `find'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/indirector/node/exec.rb:17:in `find'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/indirector/indirection.rb:194:in `find'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:297:in `block in find_node'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:294:in `find_node'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:334:in `node_from_request'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/indirector/catalog/compiler.rb:52:in `find'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/indirector/indirection.rb:194:in `find'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/network/http/api/indirected_routes.rb:121:in `do_find'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/network/http/api/indirected_routes.rb:48:in `block in call'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet.rb:241:in `override'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/network/http/api/indirected_routes.rb:47:in `call'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/network/http/route.rb:82:in `block in process'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/network/http/route.rb:81:in `each'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/network/http/route.rb:81:in `process'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/network/http/route.rb:87:in `process'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/network/http/route.rb:87:in `process'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/network/http/handler.rb:60:in `block in process'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/util/profiler/around_profiler.rb:58:in `profile'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/util/profiler.rb:51:in `profile'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/network/http/handler.rb:58:in `process'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: /usr/lib/ruby/vendor_ruby/puppet/network/http/rack.rb:21:in `call'
Jun 25 06:36:55 tools-puppetmaster-01 puppet-master[31519]: config.ru:60:in `call'

Not finding a good reason for it yet...

Something restarted it then: [Tue Jun 25 06:31:52.624395 2019] [mpm_prefork:notice] [pid 17003] AH00171: Graceful restart requested, doing restart

Notably puppet-enc will fail if the hostname isn't right. That needs to be noted when we look at updating the DNS names of our VMs.
It'll fail if the name doesn't end in wmflabs or labtests :)

Looks like the most likely place for this to fail is a urlopen on http://labs-puppetmaster.wikimedia.org:8100/v1/tools/node/tools-k8s-master-01.tools.eqiad.wmflabs (as an example) or if that comes back with invalid yaml. What's weird is that currently seems to result in valid yaml, but that isn't working nonetheless.

Looks like this is related to the python3.4 upgrade. I think it's blocking puppet-enc from running correctly.

More details at: https://www.mail-archive.com/debian-bugs-dist@lists.debian.org/msg1685477.html

tools-puppetmaster-01:/var/log/apt/history.log

Start-Date: 2019-06-25  06:31:45
Commandline: /usr/bin/unattended-upgrade
Upgrade: libpython2.7-stdlib:amd64 (2.7.9-2+deb8u2, 2.7.9-2+deb8u3), python3.4:amd64 (3.4.2-1+deb8u2, 3.4.2-1+deb8u3), python3.4-minimal:amd64 (3.4.2-1+deb8u2, 3.4.2-1+deb8u3), libbz2-1.0:amd64 (1.0.6-7+b3, 1.0.6-7+deb8u1), libpython3.4-stdlib:amd64 (3.4.2-1+d
eb8u2, 3.4.2-1+deb8u3), python2.7:amd64 (2.7.9-2+deb8u2, 2.7.9-2+deb8u3), libpython3.4:amd64 (3.4.2-1+deb8u2, 3.4.2-1+deb8u3), libpython3.4-minimal:amd64 (3.4.2-1+deb8u2, 3.4.2-1+deb8u3), bzip2:amd64 (1.0.6-7+b3, 1.0.6-7+deb8u1), libpython2.7:amd64 (2.7.9-2+de
b8u2, 2.7.9-2+deb8u3), python2.7-minimal:amd64 (2.7.9-2+deb8u2, 2.7.9-2+deb8u3), libpython2.7-minimal:amd64 (2.7.9-2+deb8u2, 2.7.9-2+deb8u3)
Error: Sub-process /usr/bin/dpkg returned an error code (1)
End-Date: 2019-06-25  06:31:50

tools-puppetmaster-01:/etc/puppet# dpkg --configure -a
Setting up python3.4 (3.4.2-1+deb8u3) ...
  File "/usr/lib/python3.4/http/client.py", line 1014
    raise InvalidURL(f"URL can't contain control characters. {url!r} "
                                                                     ^
SyntaxError: invalid syntax
dpkg: error processing package python3.4 (--configure):
 subprocess installed post-installation script returned error exit status 1
Errors were

Oh that's lovely.

Bstorm added a comment.Jun 25 2019, 2:09 PM

This comment was removed by Bstorm.

So that package is entirely broken, in other words. We probably will want to pin jessie to using the version before it.

Pin to 3.4.2-1+deb8u2 that is.

Confirmed it's due to the python3.4 upgrade. After applying this patch to tools-puppetmaster-01.tools.eqiad.wmflabs puppet agent is working again.

--- /usr/lib/python3.4/http/client.py   2019-06-25 14:41:35.000000000 +0200
+++ /usr/lib/python3.4/http/client.py   2019-06-25 14:41:55.000000000 +0200
@@ -1011,8 +1011,9 @@
         # Prevent CVE-2019-9740.
         match = _contains_disallowed_url_pchar_re.search(url)
         if match:
-            raise InvalidURL(f"URL can't contain control characters. {url!r} "
-                             f"(found at least {match.group()!r})")
+            raise InvalidURL("URL can't contain control characters. {url!r} "
+                             "(found at least {group!r})"
+                             .format(url=url, group=match.group()))
         request = '%s %s %s' % (method, url, self._http_vsn_str)

         # Non-ASCII characters should have been eliminated earlier

So the fun part is: where to put that pin in puppet...

New package is available python3.4/oldstable 3.4.2-1+deb8u4

https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=931044

Change 519035 had a related patch set uploaded (by Bstorm; owner: Bstorm):
[operations/puppet@production] cloud: add pin for jessie python3 broken package

https://gerrit.wikimedia.org/r/519035

gerritbot added a project: Patch-For-Review.Jun 25 2019, 2:41 PM

Change 519035 abandoned by Bstorm:
cloud: add pin for jessie python3 broken package

Reason:
Looks like the new version is already out.

https://gerrit.wikimedia.org/r/519035

I've confirmed the new 3.4.2-1+deb8u4 python3.4 package is working and reverted the patch on tools-puppetmaster-01.tools.eqiad.wmflabs.

Maintenance_bot removed a project: Patch-For-Review.Jun 25 2019, 3:10 PM

I pushed out the newer package on all Jessie vms.

Puppet is working again

(verified on tools-k8s-master-01, since I forgot to say how I know)

Mentioned in SAL (#wikimedia-cloud) [2019-06-26T14:29:18Z] <jeh> upgrade python3.4 on hound-app-01 and hound-puppet-02 T226480

toolforge: puppet issue probably related to puppet-encClosed, ResolvedPublicActions

Description

Details

Event Timeline

toolforge: puppet issue probably related to puppet-enc
Closed, ResolvedPublic
Actions