gnupg IMPORT_OK error on first submission after Xenial upgrade

[zenmonkeykstop]

Description

With source interface logging turned on, the following error is recorded on the first submission after a Xenial upgrade-in-place:

[Tue Feb 26 14:25:54.508513 2019] [wsgi:error] [pid 6541:tid 4015837193984] Exception in thread Thread-11:
[Tue Feb 26 14:25:54.508548 2019] [wsgi:error] [pid 6541:tid 4015837193984] Traceback (most recent call last):
[Tue Feb 26 14:25:54.508557 2019] [wsgi:error] [pid 6541:tid 4015837193984]   File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
[Tue Feb 26 14:25:54.508565 2019] [wsgi:error] [pid 6541:tid 4015837193984]     self.run()
[Tue Feb 26 14:25:54.508572 2019] [wsgi:error] [pid 6541:tid 4015837193984]   File "/usr/lib/python2.7/threading.py", line 754, in run
[Tue Feb 26 14:25:54.508580 2019] [wsgi:error] [pid 6541:tid 4015837193984]     self.__target(*self.__args, **self.__kwargs)
[Tue Feb 26 14:25:54.508588 2019] [wsgi:error] [pid 6541:tid 4015837193984]   File "/usr/local/lib/python2.7/dist-packages/pretty_bad_protocol/_meta.py", line 670, in _read_response
[Tue Feb 26 14:25:54.508596 2019] [wsgi:error] [pid 6541:tid 4015837193984]     result._handle_status(keyword, value)
[Tue Feb 26 14:25:54.508604 2019] [wsgi:error] [pid 6541:tid 4015837193984]   File "/usr/local/lib/python2.7/dist-packages/pretty_bad_protocol/_parsers.py", line 995, in _handle_status
[Tue Feb 26 14:25:54.508612 2019] [wsgi:error] [pid 6541:tid 4015837193984]     raise ValueError("Unknown status message: %r" % key)
[Tue Feb 26 14:25:54.508619 2019] [wsgi:error] [pid 6541:tid 4015837193984] ValueError: Unknown status message: u'IMPORT_OK'
[Tue Feb 26 14:25:54.508630 2019] [wsgi:error] [pid 6541:tid 4015837193984] 

(This was seen on NUCs, but there's nothing obviously HW-specific about it)

It doesn't seem to have any functional impact, messages are decryptable.

Steps to Reproduce

• Create a 0.12.0 Trusty instance, submit a document via the Source Interface, and verify that a GPG key has been created for the source (either by checking directly or replying to the source via the Journalist Interface)
• Follow the upgrade-in-place procedure to upgrade the instance to Xenial 0.12.0
• enable logging for the source interface (replace log config in /etc/apache2/sites-enabled/source.conf)
• submit a test message while tailing the source interface apache2 error log

Expected Behavior

No errors recorded in log

Actual Behavior

Above errors recorded in log

Please provide screenshots where appropriate.

[redshiftzero]

I think I know why this happens... the fix sidestepping this (fortunately harmless) exception added in #4151 doesn't work in the upgrade in place scenario because it's an action in 0.12.0's securedrop-app-code postinst which assumes that the system is on gpg 2.1. For the upgrade in place scenario, the postinst will run while the system is on trusty, which does not have gpg 2.1.

[zenmonkeykstop]

Wouldn't the postint run again when the xenial version of that package is installed after do-release-upgrade+reboot is done?

[redshiftzero]

hmmm you're right, and the logic in https://github.com/freedomofpress/securedrop/blob/develop/install_files/securedrop-app-code/debian/postinst#L120 runs if the priv key directory used by gpg-agent is not present (private-keys-v1.d) in which case i would expect it to be executed... 🤔

[emkll]

What loglevel is set in the config?
Setting the following in /etc/apache2/sites-enabled/source.conf and restarting apache2 does not produce the error described in the ticket

[...snip...]
ErrorLog /var/log/apache2/source-error.log
LogLevel info

[kushaldas]

@zenmonkeykstop can you please reply to @emkll's question here? I will try to reproduce it on Monday morning.

[zenmonkeykstop]

I had it set to info as well. You may need a source key to be present from the Trusty install for it to show - I'll update the ticket to add that step in.

[kushaldas]

Tried twice from the morning, could not reproduce the error.

[eloquence]

Per discussion at standup today, since we've not been able to reproduce it and it appears harmless even if it does occur, we're closing this issue for now; please re-open if you see it again.