MAAS

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

Bug #1560233 reported by Andres Rodriguez
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
MAAS
Fix Released
Critical
Gavin Panella
MAAS 2.0.0

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

lp:~allenap/maas/regiond-slow-to-start--bug-1560233
Blake Rouse (community): Approve
Diff: 293 lines (+83/-69)
6 files modified
src/maas/__init__.py (+9/-0)
src/maas/development.py (+2/-1)
src/maasserver/management/commands/dbupgrade.py (+20/-21)
src/maasserver/management/commands/tests/test_dbupgrade.py (+44/-16)
src/maasserver/tests/test_commands_dbupgrade.py (+4/-28)
utilities/check-imports (+4/-3)
Andres Rodriguez (andreserl)
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)
Changed in maas:
status: Confirmed → In Progress
assignee: nobody → Gavin Panella (allenap)
Andres Rodriguez (andreserl)
Changed in maas:
status: In Progress → Fix Committed
Andres Rodriguez (andreserl)
Changed in maas:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.