PPA Uploads are seemingly (but not actually) rejected

Almost the same problem here, except it doesn't always process the upload. Seems random (Task Coach project).

If the upload isn't processed, its something else.

On Sunday 26 June 2011 08:41:45 you wrote:
> Almost the same problem here, except it doesn't always process the
> upload. Seems random (Task Coach project).

If the upload is not processed then either your GPG signature is genuinely
invalid or your package has a problem which stops the code from sending a
rejection email (which is a bug on the LP side as well).

I wonder if this could be caused by a skewed client clock causing a
signature that seems invalid only for a certain time ...?
On Jun 27, 2011 7:05 PM, "Julian Edwards" <email address hidden> wrote:
> On Sunday 26 June 2011 08:41:45 you wrote:
>> Almost the same problem here, except it doesn't always process the
>> upload. Seems random (Task Coach project).
>
> If the upload is not processed then either your GPG signature is genuinely

> invalid or your package has a problem which stops the code from sending a
> rejection email (which is a bug on the LP side as well).
>
> --
> You received this bug notification because you are subscribed to
> Launchpad itself.
> https://bugs.launchpad.net/bugs/798957
>
> Title:
> Uploads are seemingly (but not actually) rejected
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/launchpad/+bug/798957/+subscriptions

More info:

It happened again today (26th) so I had a look at it. Poppy was last restarted on the 20th but the gpg.conf in /tmp was dated today. Its contents look normal:

keyserver hkp://keyserver.internal
keyserver-options auto-key-retrieve
no-auto-check-trustdb

So I'm no closer to figuring this out :(

Here too. If it's any help, my apparently rejected (but in reality accepted and I have the email to say so; that and the fact that it built successfully) upload was a diff-only upload. Not sure if that has any relevance. I re-built, re-signed and tried another couple of uploads which failed due to previous attempts still lying around (of course) then read the response emails, searched and came here. ntpdc -s" and "ntpq -p" show the following, admittedly 15 mins after the failed upload or the build :

 $ ntpdc -s
      remote local st poll reach delay offset disp
 =======================================================================
 *net2.uni-paderb 192.168.23.104 1 128 377 0.04312 -0.001316 0.05391
 .europium.canoni 192.168.23.104 2 128 377 0.01704 0.002393 0.07401
 .82.113.154.206 192.168.23.104 2 128 377 0.01651 0.001478 0.07042
  gamma.h3x.no 192.168.23.104 3 128 377 0.01506 -0.001573 0.06778
 .95-90-41-119-dy 192.168.23.104 1 128 377 0.06410 0.000584 0.04811

 $ ntpq -p
      remote refid st t when poll reach delay offset jitter
 ==============================================================================
 +95-90-41-119-dy .DCFi. 1 u 33 128 377 64.112 0.584 117.209
 *net2.uni-paderb .DCF. 1 u 97 128 377 43.128 -1.316 14.012
 +gamma.h3x.no 195.234.155.123 3 u 69 128 377 15.075 -1.573 1.959
 +82.113.154.206 193.62.22.82 2 u 28 128 377 16.694 0.334 5.586
 +europium.canoni 193.79.237.14 2 u 35 128 377 15.665 0.828 15.723

So possibly not that. No guarantee my client clock was synced *before* I signed though.

Ok, so things that could be wrong:
 - the upload service may have gotten utterly confused (e.g. the gpg dir in .tmp that julian found might have been for a script that was just running or some such)
 - some clients might be suffering timestamp skew
 - the server might be suffering timestamp skew

Things we can do to debug and correct this:
 - check whether a known good client (e.g. whomever is responding) can sign and upload something and have it accepted by the ppa upload service
 - change the code to capture more details about what went wrong - expand that General Error message in some fashion
 - check the server timestamp

I think the first thing we need to do is to have a quick test ready to run that will exercise the code path. e.g. a branch with hello world packaged in it that someone can branch, bzr bd, and deb-release all in a minute.

Another occurence. Multiple users reporting the issue.

ls -lR of tmpdir:
https://devpad.canonical.com/~robertc/bug-798957-tmp-lslR.gz

poppy-sftp runs as lp_upload.

There is one lp_upload owned gpg tempdir:
2011-11-06 14:56 gpg-c46Huv

which contains (ls -la explicitly done)
https://pastebin.canonical.com/55345/

lp_upload@germanium:~$ ls -la /tmp/gpg-c46Huv
total 3476
drwx------ 2 lp_upload lp_upload 4096 2011-11-06 14:56 .
drwxrwxrwt 347 root root 155648 2011-11-06 21:43 ..
-rw-r--r-- 1 lp_upload lp_upload 93 2011-11-06 14:56 gpg.conf
-rw------- 1 lp_upload lp_upload 1687882 2011-11-06 14:56 pubring.gpg
-rw------- 1 lp_upload lp_upload 1686967 2011-11-06 14:56 pubring.gpg~
-rw------- 1 lp_upload lp_upload 0 2011-11-06 14:56 secring.gpg
-rw------- 1 lp_upload lp_upload 1200 2011-11-06 14:56 trustdb.gpg

so no lock files.

Next step - manually try a verify.

@lifeless on IRC has asked for a copy of the failing packages..

$ dput ppa:managedit/openstack *.changes
Checking signature on .changes
gpg: Signature made Sun 06 Nov 2011 21:45:32 GMT using RSA key ID 172C4C9D
gpg: Good signature from "Kiall Mac Innes <email address hidden>"
Good signature on /home/kiall/Packaging/build-area/keystone_1.0~d4+20111106-0mit1_source.changes.
Checking signature on .dsc
gpg: Signature made Sun 06 Nov 2011 21:45:32 GMT using RSA key ID 172C4C9D
gpg: Good signature from "Kiall Mac Innes <email address hidden>"
Good signature on /home/kiall/Packaging/build-area/keystone_1.0~d4+20111106-0mit1.dsc.
Package includes an .orig.tar.gz file although the debian revision suggests
that it might not be required. Multiple uploads of the .orig.tar.gz may be
rejected by the upload queue management software.
Uploading to ppa (via ftp to ppa.launchpad.net):
  Uploading keystone_1.0~d4+20111106-0mit1.dsc: done.
  Uploading keystone_1.0~d4+20111106.orig.tar.gz: done.
  Uploading keystone_1.0~d4+20111106-0mit1.debian.tar.gz: done.
  Uploading keystone_1.0~d4+20111106-0mit1_source.changes: 2k/3k550 Changes file must be signed with a valid GPG signature: Verification failed 3 times: ['General error', 'General error', 'General error'] : Permission denied.
Note: This error might indicate a problem with your passive_ftp setting.
      Please consult dput.cf(5) for details on this configuration option.

Ok, I have a copy of the gnupg home dir

I get this:
gpg --verify --homedir $(pwd)/tmp/gpg-c46Huv keystone_1.0~d4+20111106-0mit1_source.changes
gpg: Signature made Sun 06 Nov 2011 21:45:32 UTC using RSA key ID 172C4C9D
gpg: please do a --check-trustdb
gpg: Good signature from "....."
gpg: WARNING: This key is not certified with a trusted signature!
gpg: There is no indication that the signature belongs to the owner.
Primary key fingerprint: D22F 2D03 3AEA 6450 0586 4895 0E9B BCD5 172C 4C9D

using the sample failed upload + a copy of the gnupg working dir from germanium. So the config itself seems ok.

On germanium itself:
11:00 < spm> lp_upload@germanium:~$ gpg --verify --homedir /tmp/gpg-c46Huv ~spm/keystone_1.0~d4+20111106-0mit1_source.changes
11:00 < spm> gpg: Signature made Sun 06 Nov 2011 21:45:32 UTC using RSA key ID 172C4C9D
11:00 < spm> gpg: please do a --check-trustdb
11:00 < spm> gpg: Good signature from "........"
11:00 < spm> gpg: WARNING: This key is not certified with a trusted signature!
11:00 < spm> gpg: There is no indication that the signature belongs to the owner.
11:00 < spm> Primary key fingerprint: D22F 2D03 3AEA 6450 0586 4895 0E9B BCD5 172C 4C9D

so, gpg dir is good, if its the one being used.
https://pastebin.canonical.com/55346/ is the environment of the running process, and it has no child processes.

no gnupghome in the environ.

We probably need to get more info from the gpgme failure rather than just stringifying.

lsof: https://pastebin.canonical.com/55347/ Nothing interesting that I can see.

Current log https://pastebin.canonical.com/55348/

(not useful)

https://pastebin.canonical.com/55349/ - an error. Looks like an OOPS issue :( - probably one I caused, which may be interfering with analysis.

2011-11-06 22:11:34+0000 [-] INFO:poppy:Stopping factory <twisted.protocols.ftp.DTPFactory instance at 0xb5c4d40>
2011-11-06 22:11:34+0000 [-] Stopping factory <twisted.protocols.ftp.DTPFactory instance at 0xb5c4d40>
2011-11-06 22:11:36+0000 [-] Log observer <bound method OOPSLoggingObserver.emit of <lp.services.twistedsupport.loggingsupport.OOPSLoggingObserver object at 0x42b2c50>> failed.
        Traceback (most recent call last):
          File "/usr/lib/python2.6/logging/__init__.py", line 1212, in callHandlers
            hdlr.handle(record)
          File "/usr/lib/python2.6/logging/__init__.py", line 673, in handle
            self.emit(record)
          File "/usr/lib/python2.6/logging/__init__.py", line 789, in emit
            stream.write(fs % msg)
          File "/srv/launchpad.net/codelines/ppa-rev-14189/eggs/Twisted-11.1.0pre1-py2.6-linux-x86_64.egg/twisted/python/log.py", line 594, in write
            msg(message, printed=1, isError=self.isError)
        --- <exception caught here> ---
          File "/srv/launchpad.net/codelines/ppa-rev-14189/eggs/Twisted-11.1.0pre1-py2.6-linux-x86_64.egg/twisted/python/log.py", line 284, in msg
            self.observers[i](actualEventDict)
          File "/srv/launchpad.net/codelines/ppa-rev-14189/lib/lp/services/twistedsupport/loggingsupport.py", line 57, in emit
            log.PythonLoggingObserver.emit(self, eventDict)
          File "/srv/launchpad.net/codelines/ppa-rev-14189/eggs/Twisted-11.1.0pre1-py2.6-linux-x86_64.egg/twisted/python/log.py", line 532, in emit
            self.logger.log(level, text)
          File "/usr/lib/python2.6/logging/__init__.py", line 1111, in log
            self._log(level, msg, args, **kwargs)
          File "/usr/lib/python2.6/logging/__init__.py", line 1165, in _log
            self.handle(record)
          File "/usr/lib/python2.6/logging/__init__.py", line 1175, in handle
            self.callHandlers(record)
          File "/usr/lib/python2.6/logging/__init__.py", line 1212, in callHandlers
            hdlr.handle(record)
          File "/usr/lib/python2.6/logging/__init__.py", line 673, in handle
            self.emit(record)
          File "/usr/lib/python2.6/logging/__init__.py", line 796, in emit
            self.handleError(record)
          File "/usr/lib/python2.6/logging/__init__.py", line 725, in handleError
            traceback.print_exception(ei[0], ei[1], ei[2], None, sys.stderr)
          File "/usr/lib/python2.6/traceback.py", line 124, in print_exception
            _print(file, 'Traceback (most recent call last):')
          File "/usr/lib/python2.6/traceback.py", line 13, in _print
            file.write(str+terminator)
          File "/srv/launchpad.net/codelines/ppa-rev-14189/eggs/Twisted-11.1.0pre1-py2.6-linux-x86_64.egg/twisted/python/log.py", line 588, in write
            if isinstance(data, unicode):
        exceptions.RuntimeError: maximum recursion depth exceeded while calling a Python object

This just happened again:

    https://jenkins.openstack.org/job/swift-milestone-ppa/label=swift,series=lucid/17/console

The gpgme engine has more info in the exception returned than we are displaying, in particular the error's source. I'll try and hack the code to store more of this data.

Fixed in stable r14492 <http://bazaar.launchpad.net/~launchpad-pqm/launchpad/stable/revision/14492>.

I just got this error with a package I uploaded to my PPA:

philpem@cheetah:~/debpkg/gutenprint-cvs$ dput ppa:philpem/ppa gutenprint_5.2.8-pre1-philpem1_source.changes
Checking signature on .changes
gpg: Signature made Sun 25 Dec 2011 00:26:10 GMT using RSA key ID 6C5E710A
gpg: Good signature from "Philip Pemberton (Debian package signing key) <email address hidden>"
Good signature on /home/philpem/debpkg/gutenprint-cvs/gutenprint_5.2.8-pre1-philpem1_source.changes.
Checking signature on .dsc
gpg: Signature made Sun 25 Dec 2011 00:26:08 GMT using RSA key ID 6C5E710A
gpg: Good signature from "Philip Pemberton (Debian package signing key) <email address hidden>"
Good signature on /home/philpem/debpkg/gutenprint-cvs/gutenprint_5.2.8-pre1-philpem1.dsc.
Uploading to ppa (via ftp to ppa.launchpad.net):
  Uploading gutenprint_5.2.8-pre1-philpem1.dsc: done.
  Uploading gutenprint_5.2.8-pre1.orig.tar.bz2: done.
  Uploading gutenprint_5.2.8-pre1-philpem1.debian.tar.gz: done.
  Uploading gutenprint_5.2.8-pre1-philpem1_source.changes: 3k/4k550 Changes file must be signed with a valid GPG signature: Verification failed 3 times: ["(7, 1, u'General error')", "(7, 1, u'General error')", "(7, 1, u'General error')"] : Permission denied.
Note: This error might indicate a problem with your passive_ftp setting.
      Please consult dput.cf(5) for details on this configuration option.
philpem@cheetah:~/debpkg/gutenprint-cvs$ dput ppa:philpem/ppa gutenprint_5.2.8-pre1-philpem1_source.changes
Checking signature on .changes
gpg: Signature made Sun 25 Dec 2011 00:26:10 GMT using RSA key ID 6C5E710A
gpg: Good signature from "Philip Pemberton (Debian package signing key) <email address hidden>"
Good signature on /home/philpem/debpkg/gutenprint-cvs/gutenprint_5.2.8-pre1-philpem1_source.changes.
Checking signature on .dsc
gpg: Signature made Sun 25 Dec 2011 00:26:08 GMT using RSA key ID 6C5E710A
gpg: Good signature from "Philip Pemberton (Debian package signing key) <email address hidden>"
Good signature on /home/philpem/debpkg/gutenprint-cvs/gutenprint_5.2.8-pre1-philpem1.dsc.
Uploading to ppa (via ftp to ppa.launchpad.net):
  Uploading gutenprint_5.2.8-pre1-philpem1.dsc: done.
  Uploading gutenprint_5.2.8-pre1.orig.tar.bz2: done.
  Uploading gutenprint_5.2.8-pre1-philpem1.debian.tar.gz: done.
  Uploading gutenprint_5.2.8-pre1-philpem1_source.changes: 3k/4k550 Changes file must be signed with a valid GPG signature: Verification failed 3 times: ["(7, 1, u'General error')", "(7, 1, u'General error')", "(7, 1, u'General error')"] : Permission denied.
Note: This error might indicate a problem with your passive_ftp setting.
      Please consult dput.cf(5) for details on this configuration option.

So it looks like it's not fixed after all :-(

I just got the same behavior while uploading to my own PPA

Everyone, please report further occurrences on #launchpad on Freenode. We know this is not fixed yet but when it happens we have to restart the FTP server to make the error go away.

I just had this happen to me 5 minutes ago:

dput ppa:eighthave/pd-extended ../pd-extended_0.42.5-1~lucid3_source.changes
Checking signature on .changes
gpg: Signature made Sun 08 Jan 2012 09:59:42 PM EST using RSA key ID 374BBE81
gpg: Good signature from "Hans-Christoph Steiner <email address hidden>"
gpg: aka "[jpeg image of size 5408]"
gpg: aka "Hans-Christoph Steiner <email address hidden>"
gpg: aka "Hans-Christoph Steiner <email address hidden>"
gpg: aka "Hans-Christoph Steiner <email address hidden>"
gpg: aka "Hans-Christoph Steiner <email address hidden>"
gpg: aka "Hans-Christoph Steiner <email address hidden>"
Good signature on ../pd-extended_0.42.5-1~lucid3_source.changes.
Checking signature on .dsc
gpg: Signature made Sun 08 Jan 2012 09:59:42 PM EST using RSA key ID 374BBE81
gpg: Good signature from "Hans-Christoph Steiner <email address hidden>"
gpg: aka "[jpeg image of size 5408]"
gpg: aka "Hans-Christoph Steiner <email address hidden>"
gpg: aka "Hans-Christoph Steiner <email address hidden>"
gpg: aka "Hans-Christoph Steiner <email address hidden>"
gpg: aka "Hans-Christoph Steiner <email address hidden>"
gpg: aka "Hans-Christoph Steiner <email address hidden>"
Good signature on ../pd-extended_0.42.5-1~lucid3.dsc.
Uploading to ppa (via ftp to ppa.launchpad.net):
  Uploading pd-extended_0.42.5-1~lucid3.dsc: done.
  Uploading pd-extended_0.42.5-1~lucid3.debian.tar.gz: done.
  Uploading pd-extended_0.42.5-1~lucid3_source.changes: 1k/2k550 Changes file must be signed with a valid GPG signature: Verification failed 3 times: ["(7, 1, u'General error')", "(7, 1, u'General error')", "(7, 1, u'General error')"] : Permission denied.
Note: This error might indicate a problem with your passive_ftp setting.
      Please consult dput.cf(5) for details on this configuration option.

r14736 in stable (http://bazaar.launchpad.net/~launchpad-pqm/launchpad/stable/revision/14736) is part of this bug's fix.

Fixed in stable r15023 (http://bazaar.launchpad.net/~launchpad-pqm/launchpad/stable/revision/15023) by a commit, but not testable.