2018-09-11 17:13:38 twisted.scripts: [info] twistd 17.9.0 (/usr/bin/python3 3.6.5) starting up.
2018-09-11 17:13:38 twisted.scripts: [info] reactor class: twisted.internet.asyncioreactor.AsyncioSelectorReactor.
2018-09-11 17:13:40 maasserver.regiondservices.active_discovery: [info] Active network discovery: Discovery interval set to 10800 seconds.
2018-09-11 17:13:40 stderr: [error] --- Logging error ---
2018-09-11 17:13:40 stderr: [error] Traceback (most recent call last):
2018-09-11 17:13:40 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1386, in _inlineCallbacks
2018-09-11 17:13:40 stderr: [error] result = g.send(result)
2018-09-11 17:13:40 stderr: [error] File "/usr/lib/python3/dist-packages/provisioningserver/utils/service_monitor.py", line 524, in _loadSystemDServiceState
2018-09-11 17:13:40 stderr: [error] returnValue((active_state_enum, process_state))
2018-09-11 17:13:40 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1363, in returnValue
2018-09-11 17:13:40 stderr: [error] raise _DefGen_Return(val)
2018-09-11 17:13:40 stderr: [error] twisted.internet.defer._DefGen_Return: (<SERVICE_STATE.OFF: 'off'>, 'dead')
2018-09-11 17:13:40 stderr: [error]
2018-09-11 17:13:40 stderr: [error] During handling of the above exception, another exception occurred:
2018-09-11 17:13:40 stderr: [error]
2018-09-11 17:13:40 stderr: [error] Traceback (most recent call last):
2018-09-11 17:13:40 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1386, in _inlineCallbacks
2018-09-11 17:13:40 stderr: [error] result = g.send(result)
2018-09-11 17:13:40 stderr: [error] File "/usr/lib/python3/dist-packages/provisioningserver/utils/service_monitor.py", line 296, in getServiceState
2018-09-11 17:13:40 stderr: [error] returnValue(state)
2018-09-11 17:13:40 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1363, in returnValue
2018-09-11 17:13:40 stderr: [error] raise _DefGen_Return(val)
2018-09-11 17:13:40 stderr: [error] twisted.internet.defer._DefGen_Return: ServiceState(active_state=<SERVICE_STATE.OFF: 'off'>, process_state='dead')
2018-09-11 17:13:40 stderr: [error]
2018-09-11 17:13:40 stderr: [error] During handling of the above exception, another exception occurred:
2018-09-11 17:13:40 stderr: [error]
2018-09-11 17:13:40 stderr: [error] Traceback (most recent call last):
2018-09-11 17:13:40 stderr: [error] File "/usr/lib/python3.6/logging/handlers.py", line 936, in emit
2018-09-11 17:13:40 stderr: [error] self.socket.send(msg)
2018-09-11 17:13:40 stderr: [error] OSError: [Errno 9] Bad file descriptor
2018-09-11 17:13:40 stderr: [error]
2018-09-11 17:13:40 stderr: [error] During handling of the above exception, another exception occurred:
2018-09-11 17:13:40 stderr: [error]
2018-09-11 17:13:40 stderr: [error] Traceback (most recent call last):
2018-09-11 17:13:40 stderr: [error] File "/usr/lib/python3.6/logging/handlers.py", line 857, in _connect_unixsocket
2018-09-11 17:13:40 stderr: [error] self.socket.connect(address)
2018-09-11 17:13:40 stderr: [error] FileNotFoundError: [Errno 2] No such file or directory
2018-09-11 17:13:40 stderr: [error]
2018-09-11 17:13:40 stderr: [error] During handling of the above exception, another exception occurred:
2018-09-11 17:13:40 stderr: [error]
2018-09-11 17:13:40 stderr: [error] Traceback (most recent call last):
2018-09-11 17:13:40 stderr: [error] File "/usr/lib/python3.6/logging/handlers.py", line 939, in emit
2018-09-11 17:13:40 stderr: [error] self._connect_unixsocket(self.address)
2018-09-11 17:13:40 stderr: [error] File "/usr/lib/python3.6/logging/handlers.py", line 868, in _connect_unixsocket
2018-09-11 17:13:40 stderr: [error] self.socket.connect(address)
2018-09-11 17:13:40 stderr: [error] FileNotFoundError: [Errno 2] No such file or directory
2018-09-11 17:13:40 stderr: [error] Call stack:
2018-09-11 17:13:40 stderr: [error] File "/usr/sbin/regiond", line 8, in <module>
2018-09-11 17:13:40 stderr: [error] run()
2018-09-11 17:13:40 stderr: [error] File "/usr/lib/python3/dist-packages/maasserver/server.py", line 92, in run
2018-09-11 17:13:40 stderr: [error] runMasterServices()
2018-09-11 17:13:40 stderr: [error] File "/usr/lib/python3/dist-packages/maasserver/server.py", line 19, in runMasterServices
2018-09-11 17:13:40 stderr: [error] runService("maas-regiond-master")
2018-09-11 17:13:40 stderr: [error] File "/usr/lib/python3/dist-packages/provisioningserver/server.py", line 85, in runService
2018-09-11 17:13:40 stderr: [error] UnixApplicationRunner(config).run()
2018-09-11 17:13:40 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/application/app.py", line 384, in run
2018-09-11 17:13:40 stderr: [error] self.postApplication()
2018-09-11 17:13:40 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/scripts/_twistd_unix.py", line 262, in postApplication
2018-09-11 17:13:40 stderr: [error] self.startReactor(None, self.oldstdout, self.oldstderr)
2018-09-11 17:13:40 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/application/app.py", line 396, in startReactor
2018-09-11 17:13:40 stderr: [error] self.config, oldstdout, oldstderr, self.profiler, reactor)
2018-09-11 17:13:40 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/application/app.py", line 311, in runReactorWithLogging
2018-09-11 17:13:40 stderr: [error] reactor.run()
2018-09-11 17:13:40 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/asyncioreactor.py", line 267, in run
2018-09-11 17:13:40 stderr: [error] self._asyncioEventloop.run_forever()
2018-09-11 17:13:40 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/python/log.py", line 103, in callWithLogger
2018-09-11 17:13:40 stderr: [error] return callWithContext({"system": lp}, func, *args, **kw)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/python/log.py", line 86, in callWithContext
2018-09-11 17:13:41 stderr: [error] return context.call({ILogContext: newCtx}, func, *args, **kw)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/python/context.py", line 122, in callWithContext
2018-09-11 17:13:41 stderr: [error] return self.currentContext().callWithContext(ctx, func, *args, **kw)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/python/context.py", line 85, in callWithContext
2018-09-11 17:13:41 stderr: [error] return func(*args,**kw)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/asyncioreactor.py", line 141, in _readOrWrite
2018-09-11 17:13:41 stderr: [error] self._disconnectSelectable(selectable, why, read)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/posixbase.py", line 252, in _disconnectSelectable
2018-09-11 17:13:41 stderr: [error] selectable.readConnectionLost(f)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/abstract.py", line 313, in readConnectionLost
2018-09-11 17:13:41 stderr: [error] self.connectionLost(reason)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/process.py", line 312, in connectionLost
2018-09-11 17:13:41 stderr: [error] self.proc.childConnectionLost(self.name, reason)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/process.py", line 973, in childConnectionLost
2018-09-11 17:13:41 stderr: [error] self.maybeCallProcessEnded()
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/process.py", line 985, in maybeCallProcessEnded
2018-09-11 17:13:41 stderr: [error] self.reapProcess()
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/process.py", line 350, in reapProcess
2018-09-11 17:13:41 stderr: [error] self.processEnded(status)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/_baseprocess.py", line 52, in processEnded
2018-09-11 17:13:41 stderr: [error] self.maybeCallProcessEnded()
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/process.py", line 987, in maybeCallProcessEnded
2018-09-11 17:13:41 stderr: [error] _BaseProcess.maybeCallProcessEnded(self)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/_baseprocess.py", line 64, in maybeCallProcessEnded
2018-09-11 17:13:41 stderr: [error] proto.processEnded(Failure(reason))
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/utils.py", line 163, in processEnded
2018-09-11 17:13:41 stderr: [error] self.deferred.callback((out, err, code))
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 459, in callback
2018-09-11 17:13:41 stderr: [error] self._startRunCallbacks(result)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 567, in _startRunCallbacks
2018-09-11 17:13:41 stderr: [error] self._runCallbacks()
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 653, in _runCallbacks
2018-09-11 17:13:41 stderr: [error] current.result = callback(current.result, *args, **kw)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1442, in gotResult
2018-09-11 17:13:41 stderr: [error] _inlineCallbacks(r, g, deferred)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1429, in _inlineCallbacks
2018-09-11 17:13:41 stderr: [error] deferred.callback(e.value)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 459, in callback
2018-09-11 17:13:41 stderr: [error] self._startRunCallbacks(result)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 567, in _startRunCallbacks
2018-09-11 17:13:41 stderr: [error] self._runCallbacks()
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 653, in _runCallbacks
2018-09-11 17:13:41 stderr: [error] current.result = callback(current.result, *args, **kw)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1442, in gotResult
2018-09-11 17:13:41 stderr: [error] _inlineCallbacks(r, g, deferred)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1429, in _inlineCallbacks
2018-09-11 17:13:41 stderr: [error] deferred.callback(e.value)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 459, in callback
2018-09-11 17:13:41 stderr: [error] self._startRunCallbacks(result)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 567, in _startRunCallbacks
2018-09-11 17:13:41 stderr: [error] self._runCallbacks()
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 653, in _runCallbacks
2018-09-11 17:13:41 stderr: [error] current.result = callback(current.result, *args, **kw)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1442, in gotResult
2018-09-11 17:13:41 stderr: [error] _inlineCallbacks(r, g, deferred)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1386, in _inlineCallbacks
2018-09-11 17:13:41 stderr: [error] result = g.send(result)
2018-09-11 17:13:41 stderr: [error] File "/usr/lib/python3/dist-packages/provisioningserver/utils/service_monitor.py", line 605, in _ensureService
2018-09-11 17:13:41 stderr: [error] service.service_name, expected_state.value, log_action)
2018-09-11 17:13:41 stderr: [error] Message: "Service '%s' is not %s, it will be %s."
2018-09-11 17:13:41 stderr: [error] Arguments: ('maas-syslog', 'on', 'started')
2018-09-11 17:13:41 maasserver.listener: [info] Listening for database notifications.
2018-09-11 17:13:41 maasserver.regiondservices.active_discovery: [info] Active network discovery: Active scanning is not enabled on any subnet. Skipping periodic scan.
2018-09-11 17:13:41 stderr: [error] request to http://127.0.0.1:5240/MAAS/metadata/2012-03-01/ failed. sleeping 1.: <urlopen error [Errno 111] Connection refused>
2018-09-11 17:13:42 stderr: [error] request to http://127.0.0.1:5240/MAAS/metadata/2012-03-01/ failed. sleeping 1.: <urlopen error [Errno 111] Connection refused>
2018-09-11 17:13:42 maasserver.region_controller: [info] Successfully configured proxy.
2018-09-11 17:13:43 maasserver.region_controller: [info] Reloaded DNS configuration; regiond started.
2018-09-11 17:13:43 stderr: [error] request to http://127.0.0.1:5240/MAAS/metadata/2012-03-01/ failed. sleeping 2.: <urlopen error [Errno 111] Connection refused>
2018-09-11 17:13:45 stderr: [error] request to http://127.0.0.1:5240/MAAS/metadata/2012-03-01/ failed. sleeping 4.: <urlopen error [Errno 111] Connection refused>
2018-09-11 17:13:49 stderr: [error] request to http://127.0.0.1:5240/MAAS/metadata/2012-03-01/ failed. sleeping 8.: <urlopen error [Errno 111] Connection refused>
2018-09-11 17:13:52 twisted.scripts: [info] twistd 17.9.0 (/usr/bin/python3 3.6.5) starting up.
2018-09-11 17:13:52 twisted.scripts: [info] reactor class: twisted.internet.asyncioreactor.AsyncioSelectorReactor.
2018-09-11 17:13:52 -: [info] IPCWorker connection established (HOST:UNIXAddress(None) PEER:UNIXAddress('/var/lib/maas/maas-regiond.sock'))
2018-09-11 17:13:52 twisted.internet.protocol.Factory: [info] IPCMaster connection established (HOST:UNIXAddress('/var/lib/maas/maas-regiond.sock') PEER:UNIXAddress(None))
2018-09-11 17:13:52 maasserver.listener: [info] Listening for database notifications.
2018-09-11 17:13:52 maasserver.ipc: [info] Worker pid:11301 IPC connected.
2018-09-11 17:13:53 twisted.scripts: [info] twistd 17.9.0 (/usr/bin/python3 3.6.5) starting up.
2018-09-11 17:13:53 twisted.scripts: [info] reactor class: twisted.internet.asyncioreactor.AsyncioSelectorReactor.
2018-09-11 17:13:53 twisted.scripts: [info] twistd 17.9.0 (/usr/bin/python3 3.6.5) starting up.
2018-09-11 17:13:53 twisted.scripts: [info] reactor class: twisted.internet.asyncioreactor.AsyncioSelectorReactor.
2018-09-11 17:13:53 twisted.internet.protocol.Factory: [info] IPCMaster connection established (HOST:UNIXAddress('/var/lib/maas/maas-regiond.sock') PEER:UNIXAddress(None))
2018-09-11 17:13:53 -: [info] IPCWorker connection established (HOST:UNIXAddress(None) PEER:UNIXAddress('/var/lib/maas/maas-regiond.sock'))
2018-09-11 17:13:53 regiond: [info] 127.0.0.1 GET /MAAS/rpc/ HTTP/1.1 --> 404 NOT_FOUND (referrer: -; agent: provisioningserver.rpc.clusterservice.ClusterClientService)
2018-09-11 17:13:53 maasserver.ipc: [info] Worker pid:11301 opened RPC listener on port:5250.
2018-09-11 17:13:53 maasserver.ipc: [info] Worker pid:11302 IPC connected.
2018-09-11 17:13:53 maasserver.listener: [info] Listening for database notifications.
2018-09-11 17:13:53 -: [info] IPCWorker connection established (HOST:UNIXAddress(None) PEER:UNIXAddress('/var/lib/maas/maas-regiond.sock'))
2018-09-11 17:13:53 twisted.internet.protocol.Factory: [info] IPCMaster connection established (HOST:UNIXAddress('/var/lib/maas/maas-regiond.sock') PEER:UNIXAddress(None))
2018-09-11 17:13:53 maasserver.listener: [info] Listening for database notifications.
2018-09-11 17:13:53 maasserver.ipc: [info] Worker pid:11297 IPC connected.
2018-09-11 17:13:53 maasserver.ipc: [info] Worker pid:11302 opened RPC listener on port:5251.
2018-09-11 17:13:53 maasserver.ipc: [info] Worker pid:11297 opened RPC listener on port:5252.
2018-09-11 17:13:53 regiond: [info] 127.0.0.1 GET /MAAS/rpc/ HTTP/1.1 --> 404 NOT_FOUND (referrer: -; agent: provisioningserver.rpc.clusterservice.ClusterClientService)
2018-09-11 17:13:54 regiond: [info] 127.0.0.1 GET /MAAS/rpc/ HTTP/1.1 --> 404 NOT_FOUND (referrer: -; agent: provisioningserver.rpc.clusterservice.ClusterClientService)
2018-09-11 17:13:54 twisted.scripts: [info] twistd 17.9.0 (/usr/bin/python3 3.6.5) starting up.
2018-09-11 17:13:54 twisted.scripts: [info] reactor class: twisted.internet.asyncioreactor.AsyncioSelectorReactor.
2018-09-11 17:13:54 twisted.internet.protocol.Factory: [info] IPCMaster connection established (HOST:UNIXAddress('/var/lib/maas/maas-regiond.sock') PEER:UNIXAddress(None))
2018-09-11 17:13:54 -: [info] IPCWorker connection established (HOST:UNIXAddress(None) PEER:UNIXAddress('/var/lib/maas/maas-regiond.sock'))
2018-09-11 17:13:54 maasserver.listener: [info] Listening for database notifications.
2018-09-11 17:13:54 maasserver.ipc: [info] Worker pid:11298 IPC connected.
2018-09-11 17:13:54 maasserver.ipc: [info] Worker pid:11298 opened RPC listener on port:5253.
2018-09-11 17:13:54 twisted.internet.protocol.Factory: [info] RegionServer connection established (HOST:IPv6Address(TCP, '::ffff:10.245.136.6', 5251) PEER:IPv6Address(TCP, '::ffff:10.245.136.6', 54560))
2018-09-11 17:13:54 twisted.internet.protocol.Factory: [info] RegionServer connection established (HOST:IPv6Address(TCP, '::ffff:10.245.136.6', 5250) PEER:IPv6Address(TCP, '::ffff:10.245.136.6', 45708))
2018-09-11 17:13:54 twisted.internet.protocol.Factory: [info] RegionServer connection established (HOST:IPv6Address(TCP, '::ffff:10.245.136.6', 5253) PEER:IPv6Address(TCP, '::ffff:10.245.136.6', 57910))
2018-09-11 17:13:56 maasserver.rpc.regionservice: [info] Rack controller authenticated from '::ffff:10.245.136.6:45708'.
2018-09-11 17:13:56 maasserver.rpc.regionservice: [info] Rack controller authenticated from '::ffff:10.245.136.6:54560'.
2018-09-11 17:13:56 maasserver.rpc.regionservice: [info] Rack controller authenticated from '::ffff:10.245.136.6:57910'.
2018-09-11 17:13:56 twisted.internet.protocol.Factory: [info] RegionServer connection established (HOST:IPv6Address(TCP, '::ffff:10.245.136.6', 5252) PEER:IPv6Address(TCP, '::ffff:10.245.136.6', 32992))
2018-09-11 17:13:56 metadataserver.builtin_scripts.hooks: [error] autopkgtest: Unable to discover extended NIC information due to missing passed output from 00-maas-01-lshw
2018-09-11 17:13:56 metadataserver.builtin_scripts.hooks: [error] autopkgtest: Unable to discover extended NIC information due to missing passed output from 00-maas-01-lshw
2018-09-11 17:13:56 maasserver.ipc: [info] Worker pid:11301 registered RPC connection to ('tncd8s', '10.245.136.6', 5250).
2018-09-11 17:13:57 metadataserver.builtin_scripts.hooks: [error] autopkgtest: Unable to discover extended NIC information due to missing passed output from 00-maas-01-lshw
2018-09-11 17:13:57 maasserver.ipc: [info] Worker pid:11302 registered RPC connection to ('tncd8s', '10.245.136.6', 5251).
2018-09-11 17:13:57 maasserver.ipc: [info] Worker pid:11298 registered RPC connection to ('tncd8s', '10.245.136.6', 5253).
2018-09-11 17:13:59 regiond: [info] 127.0.0.1 GET /MAAS/rpc/ HTTP/1.1 --> 200 OK (referrer: -; agent: provisioningserver.rpc.clusterservice.ClusterClientService)
2018-09-11 17:14:00 metadataserver.builtin_scripts.hooks: [error] autopkgtest: Unable to discover extended NIC information due to missing passed output from 00-maas-01-lshw
2018-09-11 17:14:00 maasserver.dhcp: [info] Successfully configured DHCPv4 on rack controller 'tncd8s'.
2018-09-11 17:14:00 maasserver.dhcp: [info] Successfully configured DHCPv6 on rack controller 'tncd8s'.
2018-09-11 17:14:00 regiond: [info] 127.0.0.1 POST /MAAS/metadata/2012-03-01/ HTTP/1.1 --> 200 OK (referrer: -; agent: Python-urllib/3.6)
2018-09-11 17:14:01 regiond: [info] 127.0.0.1 GET /MAAS/rpc/ HTTP/1.1 --> 200 OK (referrer: -; agent: provisioningserver.rpc.clusterservice.ClusterClientService)
2018-09-11 17:14:01 maasserver.region_controller: [info] Reloaded DNS configuration; rack controller autopkgtest connected
On a CI run I saw this. This CI run also failed due to https:/ /bugs.launchpad .net/maas/ +bug/1791988
Logs:
http://<internal- ip>/job/ maas-bionic- master- git/48/ artifact/ results/ artifacts/ maas-logs/ var/log/ maas/regiond. log