[2.0a3] maas-regiond not available right after install.

Bug #1560233 reported by Andres Rodriguez on 2016-03-21
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
MAAS
Critical
Gavin Panella

Bug Description

I installed a fresh MAAS, created a new user, and tried to log-in via the WebUI, unfortunately, I was unable to do so. It wouldn't access the UI at all.

What I did after that was to actually restart maas-regiond and I continue to see the issue. It wasn't until after a couple minutes that MAAS regiond WebUI became available.

1. First, installed maas and created the user. Tried to connect via the WebUI but I was unable, so I taled the logs:
#############################################################################

========
==> /var/log/maas/maas.log <==
Mar 21 18:14:35 maas00 maas.rpc.rackcontrollers: [INFO] Registering existing rack controller maas00.
Mar 21 18:14:36 maas00 maas.rpc.rackcontrollers: [INFO] Registering existing rack controller maas00.
Mar 21 18:14:36 maas00 maas.rpc.rackcontrollers: [INFO] Registering existing rack controller maas00.
Mar 21 18:14:36 maas00 maas.rpc.rackcontrollers: message repeated 2 times: [ [INFO] Registering existing rack controller maas00.]
Mar 21 18:14:36 maas00 maas.rpc.rackcontrollers: [INFO] Registering existing rack controller maas00.
Mar 21 18:14:36 maas00 maas.boot_image_download_service: [ERROR] Failed to download images: (b'UNHANDLED', 'Unknown Error [maas00:pid=21716:cmd=
GetProxies:ask=4]')
Mar 21 18:14:37 maas00 maas.rpc.rackcontrollers: [INFO] Registering existing rack controller maas00.
Mar 21 18:14:38 maas00 maas.bootsources: [INFO] Updated boot sources cache.
Mar 21 18:17:21 maas00 maas.tftp: [WARNING] No boot images have been imported from the region.
Mar 21 18:19:31 maas00 maas.import-images: [INFO] Started importing boot images.

2. Second, since I couldn't connect, I restarted the maas-regiond process and saw the following output (I run maas-regiond restart at some point around 18:19)
#############################################################################

==> /var/log/maas/rackd.log <==
            yield self._start_download()
          File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1126, in _inlineCallbacks
            result = result.throwExceptionIntoGenerator(g)
          File "/usr/lib/python3/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
            return g.throw(self.type, self.value, self.tb)
          File "/usr/lib/python3/dist-packages/provisioningserver/pserv_services/image_download_service.py", line 104, in _start_download
            proxies = yield client(GetProxies)
        twisted.protocols.amp.UnhandledCommand: (b'UNHANDLED', 'Unknown Error [maas00:pid=21716:cmd=GetProxies:ask=4]')

2016-03-21 18:14:36-0400 [ClusterClient,client] Rack controller '4y3h7n' registered (via maas00:pid=21712).

==> /var/log/maas/regiond.log <== [267/293]
2016-03-21 18:14:37 [sstreams] INFO: com.ubuntu.maas:v2:download/com.ubuntu.maas:v2:boot:14.04:ppc64el:hwe-w: to_add=['20160311'] to_remove=[]
2016-03-21 18:14:37 [-] /usr/lib/python3/dist-packages/piston3/authentication.py:314: django.utils.deprecation.RemovedInDjango19Warning: `reques
t.REQUEST` is deprecated, use `request.GET` or `request.POST` instead.
2016-03-21 18:14:37 [-] /usr/lib/python3/dist-packages/django/core/handlers/wsgi.py:126: django.utils.deprecation.RemovedInDjango19Warning: `Mer
geDict` is deprecated, use `dict.update()` instead.
2016-03-21 18:14:37 [-] 127.0.0.1 - - [21/Mar/2016:22:14:37 +0000] "POST /MAAS/metadata/status/4y3h7n/latest HTTP/1.1" 200 2 "-" "Python-urllib/
3.5"
2016-03-21 18:14:37 [-] /usr/lib/python3/dist-packages/piston3/authentication.py:314: django.utils.deprecation.RemovedInDjango19Warning: `reques
t.REQUEST` is deprecated, use `request.GET` or `request.POST` instead.
2016-03-21 18:14:37 [-] /usr/lib/python3/dist-packages/django/core/handlers/wsgi.py:126: django.utils.deprecation.RemovedInDjango19Warning: `Mer
geDict` is deprecated, use `dict.update()` instead.
2016-03-21 18:14:37 [-] 127.0.0.1 - - [21/Mar/2016:22:14:36 +0000] "POST /MAAS/metadata/status/4y3h7n/latest HTTP/1.1" 200 2 "-" "Python-urllib$
3.5"
2016-03-21 18:14:37 [-] /usr/lib/python3/dist-packages/piston3/authentication.py:314: django.utils.deprecation.RemovedInDjango19Warning: `reques
t.REQUEST` is deprecated, use `request.GET` or `request.POST` instead.
2016-03-21 18:14:37 [-] /usr/lib/python3/dist-packages/django/core/handlers/wsgi.py:126: django.utils.deprecation.RemovedInDjango19Warning: `Mer
geDict` is deprecated, use `dict.update()` instead.
2016-03-21 18:14:37 [-] 127.0.0.1 - - [21/Mar/2016:22:14:37 +0000] "POST /MAAS/metadata/status/4y3h7n/latest HTTP/1.1" 200 2 "-" "Python-urllib/
3.5"

==> /var/log/maas/rackd.log <==
2016-03-21 18:20:25-0400 [ClusterClient,client] ClusterClient connection lost (HOST:IPv4Address(TCP, '10.10.10.1', 40224) PEER:IPv4Address(TCP,
'10.10.10.1', 5251))
2016-03-21 18:20:25-0400 [ClusterClient,client] Failed to monitor services and update region.
        Traceback (most recent call last):
          File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 434, in errback
            self._startRunCallbacks(fail)
          File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 501, in _startRunCallbacks
            self._runCallbacks()
          File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 588, in _runCallbacks
            current.result = callback(current.result, *args, **kw)
          File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1184, in gotResult
            _inlineCallbacks(r, g, deferred)
        --- <exception caught here> ---
          File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1126, in _inlineCallbacks
            result = result.throwExceptionIntoGenerator(g)
          File "/usr/lib/python3/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
            return g.throw(self.type, self.value, self.tb) [227/293]
          File "/usr/lib/python3/dist-packages/provisioningserver/pserv_services/service_monitor_service.py", line 96, in _updateRegion
            services=services)
        twisted.internet.error.ConnectionDone: Connection was closed cleanly.

2016-03-21 18:20:25-0400 [ClusterClient,client] ClusterClient connection lost (HOST:IPv4Address(TCP, '192.168.1.20', 57390) PEER:IPv4Address(TCP
, '192.168.1.20', 5253))
2016-03-21 18:20:25-0400 [ClusterClient,client] ClusterClient connection lost (HOST:IPv4Address(TCP, '10.10.10.1', 40206) PEER:IPv4Address(TCP,
'10.10.10.1', 5251))
2016-03-21 18:20:25-0400 [ClusterClient,client] ClusterClient connection lost (HOST:IPv4Address(TCP, '10.10.10.1', 48416) PEER:IPv4Address(TCP,
'10.10.10.1', 5252))
2016-03-21 18:20:25-0400 [ClusterClient,client] ClusterClient connection lost (HOST:IPv4Address(TCP, '192.168.1.20', 57402) PEER:IPv4Address(TCP
, '192.168.1.20', 5253))
2016-03-21 18:20:25-0400 [ClusterClient,client] Querying node power states.
        Traceback (most recent call last):
          File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 434, in errback
            self._startRunCallbacks(fail)
          File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 501, in _startRunCallbacks
            self._runCallbacks()
          File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 588, in _runCallbacks
            current.result = callback(current.result, *args, **kw)
          File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1184, in gotResult
            _inlineCallbacks(r, g, deferred)
        --- <exception caught here> ---
          File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1126, in _inlineCallbacks
            result = result.throwExceptionIntoGenerator(g)
          File "/usr/lib/python3/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
            return g.throw(self.type, self.value, self.tb)
          File "/usr/lib/python3/dist-packages/provisioningserver/pserv_services/node_power_monitor_service.py", line 64, in query_nodes
            ListNodePowerParameters, uuid=client.localIdent)
        twisted.internet.error.ConnectionDone: Connection was closed cleanly.

==> /var/log/maas/maas.log <==
Mar 21 18:20:25 maas00 maas.power_monitor_service: [ERROR] Failed to query nodes' power status: Connection was closed cleanly.
Mar 21 18:20:46 maas00 maas.networks.monitor: [ERROR] Can't update rack controllers interface definition, no RPC connection to region.
Mar 21 18:21:02 maas00 maas.service_monitor_service: [ERROR] Can't update service statuses, no RPC connection to region.
Mar 21 18:21:16 maas00 maas.networks.monitor: [ERROR] Can't update rack controllers interface definition, no RPC connection to region.
Mar 21 18:21:46 maas00 maas.networks.monitor: [ERROR] Can't update rack controllers interface definition, no RPC connection to region.

==> /var/log/maas/rackd.log <==
2016-03-21 18:21:56-0400 [-] request to http://localhost:5240/MAAS/metadata/status/4y3h7n/latest failed. sleeping 1.: Remote end closed connecti
on without response

==> /var/log/maas/maas.log <==
Mar 21 18:21:56 maas00 maas.import-images: [WARNING] I/O error while syncing boot images. If this problem persists, verify network connectivity
and disk usage.
Mar 21 18:21:56 maas00 maas.import-images: [WARNING] Finished importing boot images, the region does not have any boot images available.
Mar 21 18:21:56 maas00 maas.tftp: [WARNING] No boot images have been imported from the region.

==> /var/log/maas/rackd.log <==
2016-03-21 18:21:56-0400 [ClusterClient,client] ClusterClient connection lost (HOST:IPv4Address(TCP, '192.168.1.20', 57370) PEER:IPv4Address(TCP
, '192.168.1.20', 5253))
2016-03-21 18:21:56-0400 [HTTPPageGetter,client] Unhandled Error
        Traceback (most recent call last):
          File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 588, in _runCallbacks
            current.result = callback(current.result, *args, **kw)
          File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1184, in gotResult
            _inlineCallbacks(r, g, deferred)
          File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1126, in _inlineCallbacks
            result = result.throwExceptionIntoGenerator(g)
          File "/usr/lib/python3/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
            return g.throw(self.type, self.value, self.tb)
        --- <exception caught here> ---
          File "/usr/lib/python3/dist-packages/provisioningserver/rpc/clusterservice.py", line 732, in update
            info = yield self._fetch_rpc_info(info_url)
        twisted.internet.error.ConnectionDone: Connection was closed cleanly.

2016-03-21 18:21:57-0400 [-] request to http://localhost:5240/MAAS/metadata/status/4y3h7n/latest failed. sleeping 1.: <urlopen error [Errno 111]
 Connection refused>
2016-03-21 18:21:57-0400 [Uninitialized] Region not available: Connection was refused by other side: 111: Connection refused. (While requesting
RPC info at b'http://localhost:5240/MAAS/rpc/').
2016-03-21 18:21:58-0400 [-] request to http://localhost:5240/MAAS/metadata/status/4y3h7n/latest failed. sleeping 2.: <urlopen error [E[155/293]
 Connection refused>

3. Third, regiond finally restarted. Note that I run the command at 18:19, but it actually didn't restart until around 18:21 , two minutes later
================================================================================================

==> /var/log/maas/regiond.log <==
2016-03-21 18:21:58 [-] Log opened.
2016-03-21 18:21:58 [-] twistd 16.0.0pre1 (/usr/bin/python3 3.5.1) starting up.
2016-03-21 18:21:58 [-] reactor class: twisted.internet.epollreactor.EPollReactor.
2016-03-21 18:21:58 [-] Log opened.
2016-03-21 18:21:58 [-] twistd 16.0.0pre1 (/usr/bin/python3 3.5.1) starting up.
2016-03-21 18:21:58 [-] reactor class: twisted.internet.epollreactor.EPollReactor.
2016-03-21 18:21:58 [-] Site starting on 5240
2016-03-21 18:21:58 [-] Site starting on 5240
2016-03-21 18:21:58 [-] Factory starting on 5250
2016-03-21 18:21:58 [-] Factory starting on 5251
2016-03-21 18:21:58 [-] Log opened.
2016-03-21 18:21:58 [-] twistd 16.0.0pre1 (/usr/bin/python3 3.5.1) starting up.
2016-03-21 18:21:58 [-] reactor class: twisted.internet.epollreactor.EPollReactor.
2016-03-21 18:21:58 [-] Site starting on 5240
2016-03-21 18:21:58 [-] Factory starting on 5252
2016-03-21 18:21:58 [maas.websocket.listener] Listening for database notifications.
2016-03-21 18:21:58 [-] Log opened.
2016-03-21 18:21:58 [-] twistd 16.0.0pre1 (/usr/bin/python3 3.5.1) starting up.
2016-03-21 18:21:58 [-] reactor class: twisted.internet.epollreactor.EPollReactor.
2016-03-21 18:21:58 [-] Site starting on 5240
2016-03-21 18:21:58 [-] Factory starting on 5253
2016-03-21 18:21:58 [requests.packages.urllib3.connectionpool] INFO: Starting new HTTP connection (1): maas.ubuntu.com
2016-03-21 18:21:58 [maas.websocket.listener] Listening for database notifications.
2016-03-21 18:21:59 [maas.websocket.listener] Listening for database notifications.
2016-03-21 18:22:00 [-] /usr/lib/python3/dist-packages/piston3/authentication.py:314: django.utils.deprecation.RemovedInDjango19Warning: `reques
t.REQUEST` is deprecated, use `request.GET` or `request.POST` instead.
2016-03-21 18:22:00 [-] /usr/lib/python3/dist-packages/django/core/handlers/wsgi.py:126: django.utils.deprecation.RemovedInDjango19Warning: `Mer
geDict` is deprecated, use `dict.update()` instead.
2016-03-21 18:22:00 [requests.packages.urllib3.connectionpool] INFO: Starting new HTTP connection (1): images.maas.io
2016-03-21 18:22:00 [-] 127.0.0.1 - - [21/Mar/2016:22:21:59 +0000] "POST /MAAS/metadata/status/4y3h7n/latest HTTP/1.1" 200 2 "-" "Python-urllib/
3.5"

4. After this point, I waas actually able to connect to the WebUI
====================================================

2016-03-21 18:22:00 [-] 192.168.1.72 - - [21/Mar/2016:22:21:59 +0000] "GET /MAAS HTTP/1.1" 302 - "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv
:45.0) Gecko/20100101 Firefox/45.0"
2016-03-21 18:22:00 [-] /usr/lib/python3/dist-packages/django/templatetags/future.py:25: django.utils.deprecation.RemovedInDjango19Warning: Load
ing the `url` tag from the `future` library is deprecated and will be removed in Django 1.9. Use the default `url` tag instead.
2016-03-21 18:22:00 [requests.packages.urllib3.connectionpool] INFO: Starting new HTTP connection (1): maas.ubuntu.com
2016-03-21 18:22:01 [-] 192.168.1.72 - - [21/Mar/2016:22:22:01 +0000] "GET /MAAS/accounts/login/?next=%2FMAAS%2F HTTP/1.1" 200 1629 "-" "Mozilla
/5.0 (X11; Ubuntu; Linux x86_64; rv:45.0) Gecko/20100101 Firefox/45.0"
2016-03-21 18:22:01 [-] 192.168.1.72 - - [21/Mar/2016:22:22:00 +0000] "GET /MAAS/static/css/base.css?v=2.0.0(alpha3+bzr4810) HTTP/1.1" 200 1268
"http://192.168.1.20:5240/MAAS/accounts/login/?next=%2FMAAS%2F" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:45.0) Gecko/20100101 Firefox/45.0"
2016-03-21 18:22:01 [requests.packages.urllib3.connectionpool] INFO: Starting new HTTP connection (1): images.maas.io
2016-03-21 18:22:01 [-] 192.168.1.72 - - [21/Mar/2016:22:22:01 +0000] "GET /MAAS/combo/ng-tags-input.js?v=2.0.0(alpha3+bzr4810) HTTP/1.1" 200 9$
99 "http://192.168.1.20:5240/MAAS/accounts/login/?next=%2FMAAS%2F" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:45.0) Gecko/20100101 Firefox/45.$
"
2016-03-21 18:22:01 [-] 192.168.1.72 - - [21/Mar/2016:22:22:01 +0000] "GET /MAAS/combo/angular.js?v=2.0.0(alpha3+bzr4810) HTTP/1.1" 200 58221 "$
ttp://192.168.1.20:5240/MAAS/accounts/login/?next=%2FMAAS%2F" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:45.0) Gecko/20100101 Firefox/45.0"
2016-03-21 18:22:01 [-] 192.168.1.72 - - [21/Mar/2016:22:22:00 +0000] "GET /MAAS/combo/maas-angular.js?v=2.0.0(alpha3+bzr4810) HTTP/1.1" 200 78$
90 "http://192.168.1.20:5240/MAAS/accounts/login/?next=%2FMAAS%2F" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:45.0) Gecko/20100101 Firefox/45.$
"
2016-03-21 18:22:01 [-] 192.168.1.72 - - [21/Mar/2016:22:22:00 +0000] "GET /MAAS/combo/yui.js?v=2.0.0(alpha3+bzr4810) HTTP/1.1" 200 12635 "http$
//192.168.1.20:5240/MAAS/accounts/login/?next=%2FMAAS%2F" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:45.0) Gecko/20100101 Firefox/45.0"
2016-03-21 18:22:01 [-] 192.168.1.72 - - [21/Mar/2016:22:22:01 +0000] "GET /MAAS/combo/maas-yui.js?v=2.0.0(alpha3+bzr4810) HTTP/1.1" 200 10556 $
http://192.168.1.20:5240/MAAS/accounts/login/?next=%2FMAAS%2F" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:45.0) Gecko/20100101 Firefox/45.0"
2016-03-21 18:22:01 [requests.packages.urllib3.connectionpool] INFO: Starting new HTTP connection (1): maas.ubuntu.com
2016-03-21 18:22:01 [-] 192.168.1.72 - - [21/Mar/2016:22:22:00 +0000] "GET /MAAS/static/img/favicon.png HTTP/1.1" 200 539 "-" "Mozilla/5.0 (X11$
 Ubuntu; Linux x86_64; rv:45.0) Gecko/20100101 Firefox/45.0"

==> /var/log/maas/maas.log <==
Mar 21 18:22:01 maas00 maas.service_monitor_service: [ERROR] Can't update service statuses, no RPC connection to region.

Related branches

summary: - [2.0a3] maas-regiond not available right after install
+ [2.0a3] maas-regiond not available right after install.
Changed in maas:
milestone: none → 2.0.0
importance: Undecided → Critical
status: New → Confirmed
Gavin Panella (allenap) on 2016-03-23
Changed in maas:
status: Confirmed → In Progress
assignee: nobody → Gavin Panella (allenap)
Changed in maas:
status: In Progress → Fix Committed
Changed in maas:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers