Ubuntu
subiquity package

subiquitycore exception in controller.run

Bug #1652262 reported by Simon Eisenmann on 2016-12-23

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	Snappy	Fix Released	Undecided	Unassigned
	subiquity (Ubuntu)	Fix Released	Undecided	Unassigned

Bug Description

I just built a snappy image with edge channel, and the initial configuration is not possible and fails with

2016-12-23 08:05:59,789 subiquitycore.core:159 Exception in controller.run():
Traceback (most recent call last):
  File "/usr/share/subiquity/subiquitycore/core.py", line 154, in run
    self.common['controllers'][k] = klass(self.common)
  File "/usr/share/subiquity/subiquitycore/controllers/network.py", line 327, in __init__
    self.observer.start()
  File "/usr/share/subiquity/subiquitycore/controllers/network.py", line 226, in start
    fds = super().start()
  File "/usr/lib/python3/dist-packages/probert/network.py", line 319, in start
    self.wlan_listener.start()
RuntimeError: nl_get_multicast_ids failed: -2

Full log:
2016-12-23 08:05:58,832 console_conf:74 Starting console-conf v0.0.5
2016-12-23 08:05:58,833 console_conf:75 Arguments passed: ['/usr/bin/console-conf', '--serial']
2016-12-23 08:05:58,833 subiquitycore.utils:33 Checking environment for installer requirements...
2016-12-23 08:05:58,845 subiquitycore.prober:41 Prober() init finished, data:{}
2016-12-23 08:05:58,871 subiquitycore.core:145 Running event loop: <urwid.main_loop.TornadoEventLoop object at 0x7f85bf0dd8>
2016-12-23 08:05:58,872 subiquitycore.core:150 Importing controller: Network
2016-12-23 08:05:59,298 probert.network:331 link_change NEW {'family': 0, 'ifindex': 1, 'arptype': 772, 'flags': 65609, 'name': b'lo'}
2016-12-23 08:05:59,417 probert.network:331 link_change NEW {'family': 0, 'ifindex': 2, 'arptype': 1, 'flags': 130, 'name': b'dummy0'}
2016-12-23 08:05:59,537 probert.network:331 link_change NEW {'family': 0, 'ifindex': 3, 'arptype': 1, 'flags': 69699, 'name': b'eth0'}
2016-12-23 08:05:59,659 subiquitycore.models.network:413 new_link 3 eth0 with config {'dhcp4': True}
2016-12-23 08:05:59,660 probert.network:331 link_change NEW {'family': 0, 'ifindex': 4, 'arptype': 776, 'flags': 128, 'name': b'sit0'}
2016-12-23 08:05:59,777 probert.network:368 addr_change NEW {'local': b'127.0.0.1/8', 'ifindex': 1, 'family': 2, 'flags': 128}
2016-12-23 08:05:59,778 probert.network:368 addr_change NEW {'local': b'192.168.1.84/24', 'ifindex': 3, 'family': 2, 'flags': 0}
2016-12-23 08:05:59,779 probert.network:368 addr_change NEW {'local': b'::1', 'ifindex': 1, 'family': 10, 'flags': 128}
2016-12-23 08:05:59,779 probert.network:368 addr_change NEW {'local': b'fe80::9c73:8eff:fe85:cd72/64', 'ifindex': 3, 'family': 10, 'flags': 128}
2016-12-23 08:05:59,780 probert.network:388 route_change NEW {'table': 254, 'ifindex': 3, 'dst': b'default', 'family': 2, 'type': 1}
2016-12-23 08:05:59,780 subiquitycore.controller.network:255 default routes {3}
2016-12-23 08:05:59,789 subiquitycore.core:159 Exception in controller.run():
Traceback (most recent call last):
  File "/usr/share/subiquity/subiquitycore/core.py", line 154, in run
    self.common['controllers'][k] = klass(self.common)
  File "/usr/share/subiquity/subiquitycore/controllers/network.py", line 327, in __init__
    self.observer.start()
  File "/usr/share/subiquity/subiquitycore/controllers/network.py", line 226, in start
    fds = super().start()
  File "/usr/lib/python3/dist-packages/probert/network.py", line 319, in start
    self.wlan_listener.start()
RuntimeError: nl_get_multicast_ids failed: -2
2016-12-23 08:06:10,856 console_conf:74 Starting console-conf v0.0.5
2016-12-23 08:06:10,857 console_conf:75 Arguments passed: ['/usr/bin/console-conf', '--serial']
2016-12-23 08:06:10,857 subiquitycore.utils:33 Checking environment for installer requirements...
2016-12-23 08:06:10,870 subiquitycore.prober:41 Prober() init finished, data:{}
2016-12-23 08:06:10,885 subiquitycore.core:145 Running event loop: <urwid.main_loop.TornadoEventLoop object at 0x7fa9325be0>
2016-12-23 08:06:10,886 subiquitycore.core:150 Importing controller: Identity
2016-12-23 08:06:11,101 subiquitycore.core:150 Importing controller: Network
2016-12-23 08:06:11,121 probert.network:331 link_change NEW {'ifindex': 1, 'name': b'lo', 'arptype': 772, 'family': 0, 'flags': 65609}
2016-12-23 08:06:11,237 probert.network:331 link_change NEW {'ifindex': 2, 'name': b'dummy0', 'arptype': 1, 'family': 0, 'flags': 130}
2016-12-23 08:06:11,357 probert.network:331 link_change NEW {'ifindex': 3, 'name': b'eth0', 'arptype': 1, 'family': 0, 'flags': 69699}
2016-12-23 08:06:11,480 subiquitycore.models.network:413 new_link 3 eth0 with config {'dhcp4': True}
2016-12-23 08:06:11,481 probert.network:331 link_change NEW {'ifindex': 4, 'name': b'sit0', 'arptype': 776, 'family': 0, 'flags': 128}
2016-12-23 08:06:11,597 probert.network:368 addr_change NEW {'local': b'127.0.0.1/8', 'ifindex': 1, 'family': 2, 'flags': 128}
2016-12-23 08:06:11,597 probert.network:368 addr_change NEW {'local': b'192.168.1.84/24', 'ifindex': 3, 'family': 2, 'flags': 0}
2016-12-23 08:06:11,599 probert.network:368 addr_change NEW {'local': b'::1', 'ifindex': 1, 'family': 10, 'flags': 128}
2016-12-23 08:06:11,599 probert.network:368 addr_change NEW {'local': b'fe80::9c73:8eff:fe85:cd72/64', 'ifindex': 3, 'family': 10, 'flags': 128}
2016-12-23 08:06:11,599 probert.network:388 route_change NEW {'type': 1, 'dst': b'default', 'table': 254, 'family': 2, 'ifindex': 3}
2016-12-23 08:06:11,600 subiquitycore.controller.network:255 default routes {3}
2016-12-23 08:06:11,609 subiquitycore.core:159 Exception in controller.run():
Traceback (most recent call last):
  File "/usr/share/subiquity/subiquitycore/core.py", line 154, in run
    self.common['controllers'][k] = klass(self.common)
  File "/usr/share/subiquity/subiquitycore/controllers/network.py", line 327, in __init__
    self.observer.start()
  File "/usr/share/subiquity/subiquitycore/controllers/network.py", line 226, in start
    fds = super().start()
  File "/usr/lib/python3/dist-packages/probert/network.py", line 319, in start
    self.wlan_listener.start()
RuntimeError: nl_get_multicast_ids failed: -2
2016-12-23 08:06:26,634 console_conf:74 Starting console-conf v0.0.5
2016-12-23 08:06:26,635 console_conf:75 Arguments passed: ['/usr/bin/console-conf', '--serial']
2016-12-23 08:06:26,638 subiquitycore.utils:33 Checking environment for installer requirements...
2016-12-23 08:06:26,651 subiquitycore.prober:41 Prober() init finished, data:{}
2016-12-23 08:06:26,666 subiquitycore.core:145 Running event loop: <urwid.main_loop.TornadoEventLoop object at 0x7fa474ec50>
2016-12-23 08:06:26,667 subiquitycore.core:150 Importing controller: Identity
2016-12-23 08:06:26,882 subiquitycore.core:150 Importing controller: Welcome
2016-12-23 08:06:26,883 subiquitycore.core:150 Importing controller: Network
2016-12-23 08:06:26,903 probert.network:331 link_change NEW {'arptype': 772, 'flags': 65609, 'ifindex': 1, 'name': b'lo', 'family': 0}
2016-12-23 08:06:27,017 probert.network:331 link_change NEW {'arptype': 1, 'flags': 130, 'ifindex': 2, 'name': b'dummy0', 'family': 0}
2016-12-23 08:06:27,137 probert.network:331 link_change NEW {'arptype': 1, 'flags': 69699, 'ifindex': 3, 'name': b'eth0', 'family': 0}
2016-12-23 08:06:27,259 subiquitycore.models.network:413 new_link 3 eth0 with config {'dhcp4': True}
2016-12-23 08:06:27,260 probert.network:331 link_change NEW {'arptype': 776, 'flags': 128, 'ifindex': 4, 'name': b'sit0', 'family': 0}
2016-12-23 09:28:16,076 probert.network:368 addr_change NEW {'local': b'127.0.0.1/8', 'family': 2, 'flags': 128, 'ifindex': 1}
2016-12-23 09:28:16,077 probert.network:368 addr_change NEW {'local': b'192.168.1.84/24', 'family': 2, 'flags': 0, 'ifindex': 3}
2016-12-23 09:28:16,077 probert.network:368 addr_change NEW {'local': b'::1', 'family': 10, 'flags': 128, 'ifindex': 1}
2016-12-23 09:28:16,078 probert.network:368 addr_change NEW {'local': b'fe80::9c73:8eff:fe85:cd72/64', 'family': 10, 'flags': 128, 'ifindex': 3}
2016-12-23 09:28:16,078 probert.network:388 route_change NEW {'dst': b'default', 'family': 2, 'ifindex': 3, 'type': 1, 'table': 254}
2016-12-23 09:28:16,078 subiquitycore.controller.network:255 default routes {3}
2016-12-23 09:28:16,087 subiquitycore.core:159 Exception in controller.run():
Traceback (most recent call last):
  File "/usr/share/subiquity/subiquitycore/core.py", line 154, in run
    self.common['controllers'][k] = klass(self.common)
  File "/usr/share/subiquity/subiquitycore/controllers/network.py", line 327, in __init__
    self.observer.start()
  File "/usr/share/subiquity/subiquitycore/controllers/network.py", line 226, in start
    fds = super().start()
  File "/usr/lib/python3/dist-packages/probert/network.py", line 319, in start
    self.wlan_listener.start()
RuntimeError: nl_get_multicast_ids failed: -2
2016-12-23 09:28:49,319 console_conf:74 Starting console-conf v0.0.5
2016-12-23 09:28:49,320 console_conf:75 Arguments passed: ['/usr/bin/console-conf', '--serial']
2016-12-23 09:28:49,320 subiquitycore.utils:33 Checking environment for installer requirements...
2016-12-23 09:28:49,332 subiquitycore.prober:41 Prober() init finished, data:{}
2016-12-23 09:28:49,348 subiquitycore.core:145 Running event loop: <urwid.main_loop.TornadoEventLoop object at 0x7f93357c50>
2016-12-23 09:28:49,349 subiquitycore.core:150 Importing controller: Identity
2016-12-23 09:28:49,564 subiquitycore.core:150 Importing controller: Network
2016-12-23 09:28:49,584 probert.network:331 link_change NEW {'family': 0, 'flags': 65609, 'name': b'lo', 'arptype': 772, 'ifindex': 1}
2016-12-23 09:28:49,696 probert.network:331 link_change NEW {'family': 0, 'flags': 130, 'name': b'dummy0', 'arptype': 1, 'ifindex': 2}
2016-12-23 09:28:49,816 probert.network:331 link_change NEW {'family': 0, 'flags': 69699, 'name': b'eth0', 'arptype': 1, 'ifindex': 3}
2016-12-23 09:28:49,938 subiquitycore.models.network:413 new_link 3 eth0 with config {'dhcp4': True}
2016-12-23 09:28:49,939 probert.network:331 link_change NEW {'family': 0, 'flags': 128, 'name': b'sit0', 'arptype': 776, 'ifindex': 4}
2016-12-23 09:28:50,056 probert.network:368 addr_change NEW {'family': 2, 'flags': 128, 'local': b'127.0.0.1/8', 'ifindex': 1}
2016-12-23 09:28:50,057 probert.network:368 addr_change NEW {'family': 2, 'flags': 0, 'local': b'192.168.1.84/24', 'ifindex': 3}
2016-12-23 09:28:50,058 probert.network:368 addr_change NEW {'family': 10, 'flags': 128, 'local': b'::1', 'ifindex': 1}
2016-12-23 09:28:50,058 probert.network:368 addr_change NEW {'family': 10, 'flags': 128, 'local': b'fe80::9c73:8eff:fe85:cd72/64', 'ifindex': 3}
2016-12-23 09:28:50,058 probert.network:388 route_change NEW {'family': 2, 'dst': b'default', 'type': 1, 'table': 254, 'ifindex': 3}
2016-12-23 09:28:50,059 subiquitycore.controller.network:255 default routes {3}
2016-12-23 09:28:50,068 subiquitycore.core:159 Exception in controller.run():
Traceback (most recent call last):
  File "/usr/share/subiquity/subiquitycore/core.py", line 154, in run
    self.common['controllers'][k] = klass(self.common)
  File "/usr/share/subiquity/subiquitycore/controllers/network.py", line 327, in __init__
    self.observer.start()
  File "/usr/share/subiquity/subiquitycore/controllers/network.py", line 226, in start
    fds = super().start()
  File "/usr/lib/python3/dist-packages/probert/network.py", line 319, in start
    self.wlan_listener.start()
RuntimeError: nl_get_multicast_ids failed: -2

Tags:

Revision history for this message

Simon Eisenmann (longsleep) wrote on 2016-12-23:

Also happens with candidate channel. I tried without wi-fi and without connected network - both times same issue.

Revision history for this message

Simon Eisenmann (longsleep) wrote on 2017-01-01:

This seems to have been fixed in https://github.com/CanonicalLtd/probert/commit/09c449104c15f7c4518eff77055d70af08bcc42a - please anyone add some priority to this so it ends up in edge asap for testing.

Revision history for this message

Gaël THEROND (fl1nt-renamed) wrote on 2017-01-04:

Same issue here, I would greatly appreciate it to be merged on the edge channel.

Please Ubuntu, have a quick review on this issue as it block new ARM Gadget to be released.

Revision history for this message

Simon Eisenmann (longsleep) wrote on 2017-01-07:

Now that probert is updated in edge i could finally check why this problem appears in the first place. So the wifi listener from probert does not start when the cfg80211 kernel module is not loaded. This module gets usually pulled in with whatever wifi driver module gets loaded by other means. On Pine64 case where wifi is connected by sdio that driver is not loaded automatically.

This issue can be closed, as soon as probert 0.0.14~16.04.1 is availble in stable channel.

Michael Hudson-Doyle (mwhudson) on 2017-09-15

Changed in subiquity (Ubuntu):
status:	New → Fix Released
Changed in snappy:
status:	New → 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.

Ubuntusubiquity package

subiquitycore exception in controller.run

Bug Description

Other bug subscribers

Remote bug watches

Ubuntu
subiquity package