upload daemon poppy dies often

[James Troup]

The upload daemon poppy seems to die a lot, especially on germanium. Here's an example of the logs just after it died:

2009-08-16 16:19:59 DEBUG Processing session complete in /tmp/tmpJEfqJG-poppy
2009-08-16 16:19:59 DEBUG Upload was targetted at ubuntu
2009-08-16 16:19:59 ERROR Exception during client done hook
 -> http://launchpadlibrarian.net/30393780/qFzUl6hftTQeRzxKnUYIzGdlPs5.txt (Unable to find fsroot in client set)
2009-08-16 16:19:59 ERROR Exception during client done hook
 -> http://launchpadlibrarian.net/30393781/qFzUl6hftTQeRzxKnUYIzGdlPs5.txt (Unable to find fsroot in client set)
2009-08-16 16:19:59 ERROR Exception during client done hook
 -> http://launchpadlibrarian.net/30393782/qFzUl6hftTQeRzxKnUYIzGdlPs5.txt (Unable to find fsroot in client set)
2009-08-16 16:19:59 ERROR Exception during client done hook
 -> http://launchpadlibrarian.net/30393783/qFzUl6hftTQeRzxKnUYIzGdlPs5.txt (Unable to find fsroot in client set)
2009-08-16 16:19:59 ERROR Exception during client done hook
 -> http://launchpadlibrarian.net/30393784/qFzUl6hftTQeRzxKnUYIzGdlPs5.txt (Unable to find fsroot in client set)
2009-08-16 16:19:59 ERROR Exception during client done hook
 -> http://launchpadlibrarian.net/30393785/qFzUl6hftTQeRzxKnUYIzGdlPs5.txt (Unable to find fsroot in client set)
2009-08-16 16:19:59 DEBUG Processing session complete in /tmp/tmpf60lTm-poppy
2009-08-16 16:19:59 ERROR Exception during client done hook
 -> http://launchpadlibrarian.net/30393786/oMhBYhZmIvK3oZmXRdUQzgmyvkP.txt ([Errno 2] No such file or directory: '/tmp/tmpf60lTm-poppy')
2009-08-16 16:19:59 DEBUG Processing session complete in /tmp/tmpdSuNFD-poppy
2009-08-16 16:19:59 ERROR Exception during client done hook
 -> http://launchpadlibrarian.net/30393787/29wV83iL62chNlyX8uC6ejAD6N8.txt ([Errno 2] No such file or directory: '/tmp/tmpdSuNFD-poppy')
2009-08-16 16:19:59 ERROR Exception during client done hook
 -> http://launchpadlibrarian.net/30393788/qFzUl6hftTQeRzxKnUYIzGdlPs5.txt (Unable to find fsroot in client set)
2009-08-16 16:19:59 ERROR uncaptured python exception, closing channel <canonical.poppy.server.Server listening 0.0.0.0:21 at 0x4a09ed0> (socket.error:(104, 'Connection reset by peer') [/usr/lib/python2.4/asyncore.py|read|69] [/usr/lib/python2.4/asyncore.py|handle_read_event|385] [/srv/launchpad.net/codelines/ppa-rev-8312/lib/zope/server/serverbase.py|handle_accept|150] [/srv/launchpad.net/codelines/ppa-rev-8312/lib/canonical/poppy/server.py|__init__|36] [/srv/launchpad.net/codelines/ppa-rev-8312/lib/zope/server/ftp/server.py|__init__|141] [/srv/launchpad.net/codelines/ppa-rev-8312/lib/zope/server/linereceiver/lineserverchannel.py|reply|105] [/srv/launchpad.net/codelines/ppa-rev-8312/lib/zope/server/dualmodechannel.py|flush|127] [/srv/launchpad.net/codelines/ppa-rev-8312/lib/zope/server/dualmodechannel.py|_flush_some|187] [/usr/lib/python2.4/asyncore.py|send|332])

[Julian Edwards (julian-edwards)]

Celso, we talked about making this a twistd process instead of using the Zope FTP server, let's get that done after 3.0 is out.

[Steve McInerney (spm)]

Latest from cocoplum if of any additional help:

....
2009-08-24 02:19:01 DEBUG Processing session complete in /tmp/tmpjbqcm2-poppy
2009-08-24 02:24:01 DEBUG Processing session complete in /tmp/tmpovC_tV-poppy
2009-08-24 02:24:01 ERROR Exception during client done hook
 -> http://launchpadlibrarian.net/30709741/oJvWoBaogTRf9RSI8KGPZPbbdcK.txt ([Errno 2] No such file or directory: '/tmp/tmpovC_tV-poppy')
2009-08-24 02:24:17 ERROR Exception during client done hook
 -> http://launchpadlibrarian.net/30709743/pM0jYYfqryFRVHqUqtVRoAnkAYT.txt (Unable to find fsroot in client set)
2009-08-24 02:24:17 DEBUG Processing session complete in /tmp/tmpmYAlBU-poppy
2009-08-24 02:24:17 ERROR Exception during client done hook
 -> http://launchpadlibrarian.net/30709745/fRVZbpzI71iAe97adIvsQPvycnM.txt ([Errno 2] No such file or directory: '/tmp/tmpmYAlBU-poppy')
2009-08-24 02:24:17 ERROR uncaptured python exception, closing channel <canonical.poppy.server.Server listening 0.0.0.0:21 at 0x49c5810> (socket.error:(107, 'Transport endpoint is not connected') [/usr/lib/python2.4/asyncore.py|read|69] [/usr/lib/python2.4/asyncore.py|handle_read_event|385] [/srv/launchpad.net/codelines/soyuz-production-rev-8332/lib/zope/server/serverbase.py|handle_accept|150] [/srv/launchpad.net/codelines/soyuz-production-rev-8332/lib/canonical/poppy/server.py|__init__|37] [<string>|getpeername|1])

[Michael Nelson (michael.nelson)]

We have had a number users complaining about uploads not appearing:

{{{
<thomas> I tried sending a package up to ppa with dput yesterday and it seemed to go well but it never appeared in my ppa. I try now again to dput and it just says "Already uploaded to ppa on ppa.launchpad.net". What is my next step? My key is good because I was able to sign the "code of conduct"
<thomas> I never got an email either..
<noodles775> thomas: which PPA, and have you read:
<thomas> my dput command is "dput ppa:thomas-chaniel/ppachaniel lazy8ledger_2.24-0ubuntu1_source.changes
<thomas> "
<noodles775> https://answers.edge.launchpad.net/soyuz/+faq/227
<noodles775> ok, looking
<thomas> Thanks for the link. The guys yesterday gave me that link and I believe I have followed everything it says there.
<noodles775> thomas: great, I'll check the logs...
<noodles775> thomas: ok, we're getting exceptions after the upload finishes... I'm looking now and well get back to you. Sorry about that.
<thomas> ok..
<noodles775> losa: can you please restart poppy? we seem to have an occurrence of bug 414482
<ubottu> Launchpad bug 414482 in soyuz "upload daemon poppy dies often" [Medium,Triaged] https://launchpad.net/bugs/414482
}}}

The poppy.log seems to show a *lot* of
{{{
2009-12-22 09:04:06 ERROR Exception during client done hook
Traceback (most recent call last):
  File "/srv/launchpad.net/codelines/ppa-rev-8806/lib/canonical/poppy/server.py", line 141, in clientFinished
    self.client_done_hook(channel.fsroot, clienthost, clientport)
  File "/srv/launchpad.net/codelines/ppa-rev-8806/lib/lp/archiveuploader/poppyinterface.py", line 45, in client_done_hook
    raise PoppyInterfaceFailure("Unable to find fsroot in client set")
PoppyInterfaceFailure: Unable to find fsroot in client set
}}}

Scarily, poppy seems to have been in this state for a few days, looking at the logs. Tom restarted poppy and it seems to have gone back to normal.

Looking at the code, it seems that we should only be in this state if either:
1) client_hook_done was called before new_client_hook (we could update the log message during the poppy interface failure to print the fsroot, which would give us a way of checking), or
2) the internal state (PoppyInterface.clients) was being corrupted after new_client_hook.

As the irc comment above suggests, the users pkg has been uploaded, and cannot be re-uploaded, but there are no records on the PPA for it.

[Julian Edwards (julian-edwards)]

Just happened again:

2010-02-10 16:47:30 ERROR uncaptured python exception, closing channel <canonical.poppy.server.Server listening 0.0.0.0:21 at 0x205af50> (<class 'socket.error'>:(104, 'Connection reset by peer') [/usr/lib/python2.5/asyncore.py|read|68] [/usr/lib/python2.5/asyncore.py|handle_read_event|384] [/home/pqm/for_rollouts/production/eggs/zope.server-3.6.1-py2.5.egg/zope/server/serverbase.py|handle_accept|150] [/srv/launchpad.net/codelines/ppa-rev-8945/lib/canonical/poppy/server.py|__init__|29] [/home/pqm/for_rollouts/production/eggs/zope.server-3.6.1-py2.5.egg/zope/server/ftp/server.py|__init__|141] [/home/pqm/for_rollouts/production/eggs/zope.server-3.6.1-py2.5.egg/zope/server/linereceiver/lineserverchannel.py|reply|105] [/home/pqm/for_rollouts/production/eggs/zope.server-3.6.1-py2.5.egg/zope/server/dualmodechannel.py|flush|127] [/home/pqm/for_rollouts/production/eggs/zope.server-3.6.1-py2.5.egg/zope/server/dualmodechannel.py|_flush_some|187] [/usr/lib/python2.5/asyncore.py|send|331])

[Steve McInerney (spm)]

We've had 3 (recorded) failures recently:
2010-05-07 20:56 UTC
2010-05-08 12:15 UTC
2010-05-10 02:35 UTC

[Michael Nelson (michael.nelson)]

{{{
2010-05-17 09:37:51 ERROR Exception during client done hook
Traceback (most recent call last):
  File "/srv/launchpad.net/codelines/ppa-rev-9341/lib/lp/poppy/server.py", line 140, in clientFinished
    self.client_done_hook(channel.fsroot, clienthost, clientport)
  File "/srv/launchpad.net/codelines/ppa-rev-9341/lib/lp/poppy/hooks.py", line 55, in client_done_hook
    shutil.rmtree(fsroot)
  File "/usr/lib/python2.5/shutil.py", line 161, in rmtree
    onerror(os.listdir, path, sys.exc_info())
  File "/usr/lib/python2.5/shutil.py", line 159, in rmtree
    names = os.listdir(path)
OSError: [Errno 2] No such file or directory: '/tmp/tmpv8Dpmn-poppy'
}}}

[Cody A.W. Somerville (cody-somerville)]

Looking at /srv/launchpad.net-logs/soyuz/cocoplum/lp_upload/poppy-public.log, these errors appear to be occurring several times an hour. I dunno if that means poppy is dying or not though.

[Julian Edwards (julian-edwards)]

Since we now have a poppy-sftp written using Twisted Conch, it will be relatively easy to add one that does plain FTP. Then the old Poppy with this problem can die in fire.

[William Grant (wgrant)]

The old Poppy with this problem recently died in fire.