pserv continually failing: address already in use

[Jeroen T. Vermeulen]

On a system that I've been upgrading between development systems, pserv.log fills up with these errors, about one round per second:

«
2014-09-26 08:55:40+0700 [-] Unhandled Error
        Traceback (most recent call last):
          File "/usr/lib/python2.7/dist-packages/twisted/application/service.py", line 282, in startService
            service.startService()
          File "/usr/lib/python2.7/dist-packages/twisted/application/internet.py", line 273, in startService
            self._loopFinished = self._loop.start(self.step, now=True)
          File "/usr/lib/python2.7/dist-packages/twisted/internet/task.py", line 173, in start
            self()
          File "/usr/lib/python2.7/dist-packages/twisted/internet/task.py", line 218, in __call__
            d = defer.maybeDeferred(self.f, *self.a, **self.kw)
        --- <exception caught here> ---
          File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 139, in maybeDeferred
            result = f(*args, **kw)
          File "/usr/lib/python2.7/dist-packages/provisioningserver/pserv_services/tftp.py", line 321, in updateServers
            tftp_service.setServiceParent(self)
          File "/usr/lib/python2.7/dist-packages/twisted/application/service.py", line 186, in setServiceParent
            self.parent.addService(self)
          File "/usr/lib/python2.7/dist-packages/twisted/application/service.py", line 308, in addService
            service.privilegedStartService()
          File "/usr/lib/python2.7/dist-packages/twisted/application/internet.py", line 105, in privilegedStartService
            self._port = self._getPort()
          File "/usr/lib/python2.7/dist-packages/provisioningserver/pserv_services/tftp.py", line 245, in _getPort
            return self._listenUDP(*self.args, **self.kwargs)
          File "/usr/lib/python2.7/dist-packages/provisioningserver/pserv_services/tftp.py", line 251, in _listenUDP
            p.startListening()
          File "/usr/lib/python2.7/dist-packages/twisted/internet/udp.py", line 171, in startListening
            self._bindSocket()
          File "/usr/lib/python2.7/dist-packages/twisted/internet/udp.py", line 191, in _bindSocket
            raise error.CannotListenError(self.interface, self.port, le)
        twisted.internet.error.CannotListenError: Couldn't listen on 192.168.1.113:69: [Errno 98] Address already in use.

2014-09-26 08:55:40+0700 [-] Warning: No permission to delete pid file
2014-09-26 08:55:40+0700 [-] Warning: No permission to delete pid file
2014-09-26 08:55:40+0700 [-] Traceback (most recent call last):
2014-09-26 08:55:40+0700 [-] File "/usr/bin/twistd", line 14, in <module>
2014-09-26 08:55:40+0700 [-] run()
2014-09-26 08:55:40+0700 [-] File "/usr/lib/python2.7/dist-packages/twisted/scripts/twistd.py", line 27, in run
2014-09-26 08:55:40+0700 [-] app.run(runApp, ServerOptions)
2014-09-26 08:55:40+0700 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/app.py", line 642, in run
2014-09-26 08:55:40+0700 [-] runApp(config)
2014-09-26 08:55:40+0700 [-] File "/usr/lib/python2.7/dist-packages/twisted/scripts/twistd.py", line 23, in runApp
2014-09-26 08:55:40+0700 [-] _SomeApplicationRunner(config).run()
2014-09-26 08:55:40+0700 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/app.py", line 380, in run
2014-09-26 08:55:40+0700 [-] self.postApplication()
2014-09-26 08:55:40+0700 [-] File "/usr/lib/python2.7/dist-packages/twisted/scripts/_twistd_unix.py", line 193, in postApplication
2014-09-26 08:55:40+0700 [-] self.startApplication(self.application)
2014-09-26 08:55:40+0700 [-] File "/usr/lib/python2.7/dist-packages/twisted/scripts/_twistd_unix.py", line 390, in startApplication
2014-09-26 08:55:40+0700 [-] app.startApplication(application, not self.config['no_save'])
2014-09-26 08:55:40+0700 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/app.py", line 658, in startApplication
2014-09-26 08:55:40+0700 [-] service.IService(application).startService()
2014-09-26 08:55:40+0700 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/service.py", line 282, in startService
2014-09-26 08:55:40+0700 [-] service.startService()
2014-09-26 08:55:40+0700 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/service.py", line 282, in startService
2014-09-26 08:55:40+0700 [-] service.startService()
2014-09-26 08:55:40+0700 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/service.py", line 282, in startService
2014-09-26 08:55:40+0700 [-] service.startService()
2014-09-26 08:55:40+0700 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/internet.py", line 111, in startService
2014-09-26 08:55:40+0700 [-] self._port = self._getPort()
2014-09-26 08:55:40+0700 [-] File "/usr/lib/python2.7/dist-packages/provisioningserver/pserv_services/tftp.py", line 245, in _getPort
2014-09-26 08:55:40+0700 [-] return self._listenUDP(*self.args, **self.kwargs)
2014-09-26 08:55:40+0700 [-] File "/usr/lib/python2.7/dist-packages/provisioningserver/pserv_services/tftp.py", line 251, in _listenUDP
2014-09-26 08:55:40+0700 [-] p.startListening()
2014-09-26 08:55:40+0700 [-] File "/usr/lib/python2.7/dist-packages/twisted/internet/udp.py", line 171, in startListening
2014-09-26 08:55:40+0700 [-] self._bindSocket()
2014-09-26 08:55:40+0700 [-] File "/usr/lib/python2.7/dist-packages/twisted/internet/udp.py", line 191, in _bindSocket
2014-09-26 08:55:40+0700 [-] raise error.CannotListenError(self.interface, self.port, le)
2014-09-26 08:55:40+0700 [-] twisted.internet.error.CannotListenError: Couldn't listen on 192.168.1.113:69: [Errno 98] Address already in use.
»

It does look as if the cluster controller itself is listening on that socket, because the node event log shows endlessly repeated TFTP requests when I attempt to deploy a node. Deployment never times out, I guess because activity keeps occurring.

[Jeroen T. Vermeulen (jtv)]

I thought “chown maas:maas /run/maas-cluster.pid” might fix it. But the file just keeps getting rewritten, about once a second, always with root:root ownership! And it holds a new process ID every time.

[Jeroen T. Vermeulen (jtv)]

The problem seems to be /etc/init/maas-cluster-celery.conf and /etc/init/maas-pserv.conf were still around, even though we should now only have /etc/init/maas-cluster-register.conf and /etc/init/maas-cluster.conf.

I thought we'd already landed a packaging change that renamed those files? This was with packaging r312 and trunk r3095.

[Raphaël Badin (rvb)]

I'm seeing this bug as well, it seems the upgrade left the old daemon running.

[Jeroen T. Vermeulen (jtv)]

I can't find anything in the logs that would indicate any kind of failure of the update logic introduced in packaging r312. And yet, I still had those two Upstart files!

[Graham Binns (gmb)]

Andres, I've assigned this to you as it seems like a packaging problem… moreover it may be a *solved* packaging problem, but I don't know for sure.

[Andres Rodriguez (andreserl)]

From what version did you upgrade? Can you paste De upgrade log?
On Oct 1, 2014 8:16 AM, "Launchpad Bug Tracker" <email address hidden>
wrote:

> Graham Binns (gmb) has assigned this bug to you for MAAS:
>
> On a system that I've been upgrading between development systems,
> pserv.log fills up with these errors, about one round per second:
>
> «
> 2014-09-26 08:55:40+0700 [-] Unhandled Error
> Traceback (most recent call last):
> File
> "/usr/lib/python2.7/dist-packages/twisted/application/service.py", line
> 282, in startService
> service.startService()
> File
> "/usr/lib/python2.7/dist-packages/twisted/application/internet.py", line
> 273, in startService
> self._loopFinished = self._loop.start(self.step, now=True)
> File
> "/usr/lib/python2.7/dist-packages/twisted/internet/task.py", line 173, in
> start
> self()
> File
> "/usr/lib/python2.7/dist-packages/twisted/internet/task.py", line 218, in
> __call__
> d = defer.maybeDeferred(self.f, *self.a, **self.kw)
> --- <exception caught here> ---
> File
> "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 139, in
> maybeDeferred
> result = f(*args, **kw)
> File
> "/usr/lib/python2.7/dist-packages/provisioningserver/pserv_services/tftp.py",
> line 321, in updateServers
> tftp_service.setServiceParent(self)
> File
> "/usr/lib/python2.7/dist-packages/twisted/application/service.py", line
> 186, in setServiceParent
> self.parent.addService(self)
> File
> "/usr/lib/python2.7/dist-packages/twisted/application/service.py", line
> 308, in addService
> service.privilegedStartService()
> File
> "/usr/lib/python2.7/dist-packages/twisted/application/internet.py", line
> 105, in privilegedStartService
> self._port = self._getPort()
> File
> "/usr/lib/python2.7/dist-packages/provisioningserver/pserv_services/tftp.py",
> line 245, in _getPort
> return self._listenUDP(*self.args, **self.kwargs)
> File
> "/usr/lib/python2.7/dist-packages/provisioningserver/pserv_services/tftp.py",
> line 251, in _listenUDP
> p.startListening()
> File "/usr/lib/python2.7/dist-packages/twisted/internet/udp.py",
> line 171, in startListening
> self._bindSocket()
> File "/usr/lib/python2.7/dist-packages/twisted/internet/udp.py",
> line 191, in _bindSocket
> raise error.CannotListenError(self.interface, self.port, le)
> twisted.internet.error.CannotListenError: Couldn't listen on
> 192.168.1.113:69: [Errno 98] Address already in use.
>
> 2014-09-26 08:55:40+0700 [-] Warning: No permission to delete pid file
> 2014-09-26 08:55:40+0700 [-] Warning: No permission to delete pid file
> 2014-09-26 08:55:40+0700 [-] Traceback (most recent call last):
> 2014-09-26 08:55:40+0700 [-] File "/usr/bin/twistd", line 14, in <module>
> 2014-09-26 08:55:40+0700 [-] run()
> 2014-09-26 08:55:40+0700 [-] File
> "/usr/lib/python2.7/dist-packages/twisted/scripts/twistd.py", line 27, in
> run
> 2014-09-26 08:55:40+0700 [-]...

[Jeroen T. Vermeulen (jtv)]

The upgrade was from another dev build, not from a release — looks like r3067 but that's not necessarily exactly trunk. I'm attaching the portion of that day's dpkg.log leading up to the error.

[Julian Edwards (julian-edwards)]

I'm moving this out the way since nobody seems to have seen it for a while. Reopen if you do see it again.

[Chris Johnston (cjohnston)]

We have noticed this going from 1.6.0+bzr2545-0ubuntu1~ppa1 to 1.7.0+bzr3299-0ubuntu3~trusty1

It looks like it's possible that the original maas-pserv process wasn't properly killed, however it lost it's pid, and now there is a second maas-pserv process running which can't get the address.

[Barry Morrison (basketcase)]

I experienced this today with 1.7.0+bzr3299-0ubuntu3~trusty1

2015-02-12 14:08:45-0800 [-] Warning: No permission to delete pid file
2015-02-12 14:08:45-0800 [-] Warning: No permission to delete pid file
2015-02-12 14:08:45-0800 [-] Traceback (most recent call last):
2015-02-12 14:08:45-0800 [-] File "/usr/bin/twistd", line 14, in <module>
2015-02-12 14:08:45-0800 [-] run()
2015-02-12 14:08:45-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/scripts/twistd.py", line 27, in run
2015-02-12 14:08:45-0800 [-] app.run(runApp, ServerOptions)
2015-02-12 14:08:45-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/app.py", line 642, in run
2015-02-12 14:08:45-0800 [-] runApp(config)
2015-02-12 14:08:45-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/scripts/twistd.py", line 23, in runApp
2015-02-12 14:08:45-0800 [-] _SomeApplicationRunner(config).run()
2015-02-12 14:08:45-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/app.py", line 380, in run
2015-02-12 14:08:45-0800 [-] self.postApplication()
2015-02-12 14:08:45-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/scripts/_twistd_unix.py", line 193, in postApplication
2015-02-12 14:08:45-0800 [-] self.startApplication(self.application)
2015-02-12 14:08:45-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/scripts/_twistd_unix.py", line 390, in startApplication
2015-02-12 14:08:45-0800 [-] app.startApplication(application, not self.config['no_save'])
2015-02-12 14:08:45-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/app.py", line 658, in startApplication
2015-02-12 14:08:45-0800 [-] service.IService(application).startService()
2015-02-12 14:08:45-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/service.py", line 282, in startService
2015-02-12 14:08:45-0800 [-] service.startService()
2015-02-12 14:08:45-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/service.py", line 282, in startService
2015-02-12 14:08:45-0800 [-] service.startService()
2015-02-12 14:08:45-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/service.py", line 282, in startService
2015-02-12 14:08:45-0800 [-] service.startService()
2015-02-12 14:08:45-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/internet.py", line 111, in startService
2015-02-12 14:08:45-0800 [-] self._port = self._getPort()
2015-02-12 14:08:45-0800 [-] File "/usr/lib/python2.7/dist-packages/provisioningserver/pserv_services/tftp.py", line 250, in _getPort
2015-02-12 14:08:45-0800 [-] return self._listenUDP(*self.args, **self.kwargs)
2015-02-12 14:08:45-0800 [-] File "/usr/lib/python2.7/dist-packages/provisioningserver/pserv_services/tftp.py", line 256, in _listenUDP
2015-02-12 14:08:45-0800 [-] p.startListening()
2015-02-12 14:08:45-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/internet/udp.py", line 171, in startListening
2015-02-12 14:08:45-0800 [-] self._bindSocket()
2015-02-12 14:08:45-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/internet/udp.py", line 191, in _bindSocket
2015-02-12 14:08:45-0800 [-] raise error.CannotListenError(self.interface, self.port, le)
2015-02-12 14:08:45-080...

[Barry Morrison (basketcase)]

Still exists in 1.7.1+bzr3341-0ubuntu1~trusty1

2015-03-03 15:57:46-0800 [-] Warning: No permission to delete pid file
2015-03-03 15:57:46-0800 [-] Warning: No permission to delete pid file
2015-03-03 15:57:46-0800 [-] Traceback (most recent call last):
2015-03-03 15:57:46-0800 [-] File "/usr/bin/twistd", line 14, in <module>
2015-03-03 15:57:46-0800 [-] run()
2015-03-03 15:57:46-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/scripts/twistd.py", line 27, in run
2015-03-03 15:57:46-0800 [-] app.run(runApp, ServerOptions)
2015-03-03 15:57:46-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/app.py", line 642, in run
2015-03-03 15:57:46-0800 [-] runApp(config)
2015-03-03 15:57:46-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/scripts/twistd.py", line 23, in runApp
2015-03-03 15:57:46-0800 [-] _SomeApplicationRunner(config).run()
2015-03-03 15:57:46-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/app.py", line 380, in run
2015-03-03 15:57:46-0800 [-] self.postApplication()
2015-03-03 15:57:46-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/scripts/_twistd_unix.py", line 193, in postApplication
2015-03-03 15:57:46-0800 [-] self.startApplication(self.application)
2015-03-03 15:57:46-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/scripts/_twistd_unix.py", line 390, in startApplication
2015-03-03 15:57:46-0800 [-] app.startApplication(application, not self.config['no_save'])
2015-03-03 15:57:46-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/app.py", line 658, in startApplication
2015-03-03 15:57:46-0800 [-] service.IService(application).startService()
2015-03-03 15:57:46-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/service.py", line 282, in startService
2015-03-03 15:57:46-0800 [-] service.startService()
2015-03-03 15:57:46-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/service.py", line 282, in startService
2015-03-03 15:57:46-0800 [-] service.startService()
2015-03-03 15:57:46-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/service.py", line 282, in startService
2015-03-03 15:57:46-0800 [-] service.startService()
2015-03-03 15:57:46-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/internet.py", line 111, in startService
2015-03-03 15:57:46-0800 [-] self._port = self._getPort()
2015-03-03 15:57:46-0800 [-] File "/usr/lib/python2.7/dist-packages/provisioningserver/pserv_services/tftp.py", line 250, in _getPort
2015-03-03 15:57:46-0800 [-] return self._listenUDP(*self.args, **self.kwargs)
2015-03-03 15:57:46-0800 [-] File "/usr/lib/python2.7/dist-packages/provisioningserver/pserv_services/tftp.py", line 256, in _listenUDP
2015-03-03 15:57:46-0800 [-] p.startListening()
2015-03-03 15:57:46-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/internet/udp.py", line 171, in startListening
2015-03-03 15:57:46-0800 [-] self._bindSocket()
2015-03-03 15:57:46-0800 [-] File "/usr/lib/python2.7/dist-packages/twisted/internet/udp.py", line 191, in _bindSocket
2015-03-03 15:57:46-0800 [-] ra...

[Launchpad Janitor (janitor)]

[Expired for MAAS because there has been no activity for 60 days.]

[Samantha Jian-Pielak (samantha-jian)]

I saw this today with 1.7.4+bzr3366-0ubuntu1~trusty1.

2015-06-03 04:18:36+0530 [-] Unhandled Error
 Traceback (most recent call last):
   File "/usr/lib/python2.7/dist-packages/twisted/application/service.py", line 282, in startService
     service.startService()
   File "/usr/lib/python2.7/dist-packages/twisted/application/internet.py", line 273, in startService
     self._loopFinished = self._loop.start(self.step, now=True)
   File "/usr/lib/python2.7/dist-packages/twisted/internet/task.py", line 173, in start
     self()
   File "/usr/lib/python2.7/dist-packages/twisted/internet/task.py", line 218, in __call__
     d = defer.maybeDeferred(self.f, *self.a, **self.kw)
 --- <exception caught here> ---
   File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 139, in maybeDeferred
     result = f(*args, **kw)
   File "/usr/lib/python2.7/dist-packages/provisioningserver/pserv_services/tftp.py", line 326, in updateServers
     tftp_service.setServiceParent(self)
   File "/usr/lib/python2.7/dist-packages/twisted/application/service.py", line 186, in setServiceParent
     self.parent.addService(self)
   File "/usr/lib/python2.7/dist-packages/twisted/application/service.py", line 308, in addService
     service.privilegedStartService()
   File "/usr/lib/python2.7/dist-packages/twisted/application/internet.py", line 105, in privilegedStartService
     self._port = self._getPort()
   File "/usr/lib/python2.7/dist-packages/provisioningserver/pserv_services/tftp.py", line 250, in _getPort
     return self._listenUDP(*self.args, **self.kwargs)
   File "/usr/lib/python2.7/dist-packages/provisioningserver/pserv_services/tftp.py", line 256, in _listenUDP
     p.startListening()
   File "/usr/lib/python2.7/dist-packages/twisted/internet/udp.py", line 171, in startListening
     self._bindSocket()
   File "/usr/lib/python2.7/dist-packages/twisted/internet/udp.py", line 191, in _bindSocket
     raise error.CannotListenError(self.interface, self.port, le)
 twisted.internet.error.CannotListenError: Couldn't listen on 10.0.3.1:69: [Errno 98] Address already in use.

2015-06-03 04:18:37+0530 [-] Warning: No permission to delete pid file
2015-06-03 04:18:37+0530 [-] Traceback (most recent call last):
2015-06-03 04:18:37+0530 [-] File "/usr/bin/twistd", line 14, in <module>
2015-06-03 04:18:37+0530 [-] run()
2015-06-03 04:18:37+0530 [-] File "/usr/lib/python2.7/dist-packages/twisted/scripts/twistd.py", line 27, in run
2015-06-03 04:18:37+0530 [-] app.run(runApp, ServerOptions)
2015-06-03 04:18:37+0530 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/app.py", line 642, in run
2015-06-03 04:18:37+0530 [-] runApp(config)
2015-06-03 04:18:37+0530 [-] File "/usr/lib/python2.7/dist-packages/twisted/scripts/twistd.py", line 23, in runApp
2015-06-03 04:18:37+0530 [-] _SomeApplicationRunner(config).run()
2015-06-03 04:18:37+0530 [-] File "/usr/lib/python2.7/dist-packages/twisted/application/app.py", line 380, in run
2015-06-03 04:18:37+0530 [-] self.postApplication()
2015-06-03 04:18:37+0530 [-] File "/usr/lib/python2.7/dist-packages/twisted/scripts/_twistd_unix.py", line 193, in postApplication
2015-06-03 04...

[Andres Rodriguez (andreserl)]

@Samantha,

Can you please test against 1.7.5 ? TRhat being said. Please do:

ps faux | grep pserv and see if there';s a process that was left over. Once you kill that process that should fix the issue.

Did you upgrade from any 1.5 release to 1.7 ?

[Samantha Jian-Pielak (samantha-jian)]

I upgraded it from 1.7.2 to 1.7.4 last week. It was working fine the past few days.

$ ps faux|grep pserv
srini 13652 0.0 0.0 11740 928 pts/3 S+ 22:20 0:00 \_ grep --color=auto pserv
root 13643 31.0 0.0 98452 27688 ? Rs 22:20 0:00 /usr/bin/python /usr/bin/twistd --nodaemon --uid=maas --gid=maas --pidfile=/run/maas-cluster.pid --logfile=/dev/null maas-pserv --config-file=/etc/maas/pserv.yaml
$

Will kill it and check and upgrade to 1.7.5.

[Samantha Jian-Pielak (samantha-jian)]

I couldn't kill it, the new pserv process keeps coming up. I restarted the MAAS server, didn't help. Upgraded it to 1.7.5, still the same Errno 98 every second popping up on /var/log/maas/pserv.log.

[Christian Reis (kiko)]

Samantha's problem was that she had the tftpd package installed, which sets up an xinetd entry to launch tftpd; xinetd then binds to udp port 69 and as they say in the movies, "there can be only one".

[Christian Reis (kiko)]

Marking Incomplete as again we don't have solid evidence of there being an issue with MAAS, though it's suspected there's an issue upgrading from 1.5/1.6 to 1.7 which we will need to address with the SRU going ahead.

[Andres Rodriguez (andreserl)]

Samantha confirmed that tftpd was installed in the system, which caused this issue. tftpd is a conflicting package with MAAS. This was a manual installation by the administrator!