"No key for source" error when replying to brand new source

[eloquence]

• server environment: Qubes staging env based on RC2 debs built from branch
• workstation: prod RPM 0.2.3
• client/proxy: 20200507 nightly, 0.2.8 prod debs otherwise

Steps to reproduce

1. Submit as a new source via the Source Interface
2. Sync with the client and go back to step 1 unless you see the grayed out reply area with "Awaiting encryption key from server"
3. Wait for the reply area to become active on the next sync
4. Send a reply

Expected behavior

The reply sends.

Actual behavior

Reply fails to send. Client log shows "Could not encrypt reply: no key four source <id>" SendReplyJobError. Meanwhile, replying to other sources still works.

[eloquence]

For the source this happened with, even a client restart does not resolve. For another new source that's not hitting the "Awaiting the encryption key" issue, I'm able to reply immediately. Same with older sources.

The most urgent question here is likely whether there's anything in 1.3.0 (e.g., key cache changes) that could contribute to this behavior. So here's how I plan to drill further into this:

1. Revert client packages to prod state and attempt to repro. If I can still repro,
2. Switch to a 1.2.2 prod server and attempt to repro.

[conorsch]

Just checked in a Qubes-staging environment, and was not able to reproduce. Reply was sent successfully, and confirmed receipt on the source side. Package version details:

• /usr/share/securedrop-workstation-dom0-config/config.json shows "environment": "staging"
• securedrop-client=0.1.6-dev-20200512-060120+buster
• securedrop-proxy=0.2.1-dev-20200512-060322+buster
• securedrop-app-code=1.3.0~rc2

[conorsch]

On a subsequent attempt, was indeed able to reproduce the error! Replies from the client failed to send. Even after restarting the client, was not able to send replies to that particular source.

Relevant logs from the client failure

--
May 12 15:09:10 localhost 2020-05-12 15:09:10,023 - securedrop_client.storage:101(get_remote_data) INFO: Fetched 94 remote replies.
May 12 15:09:10 localhost 2020-05-12 15:09:10,031 - securedrop_client.storage:91(chronometer) INFO: update_sources duration: 0.0074s
May 12 15:09:10 localhost 2020-05-12 15:09:10,034 - securedrop_client.storage:91(chronometer) INFO: update_files duration: 0.0034s
May 12 15:09:10 localhost 2020-05-12 15:09:10,039 - securedrop_client.storage:91(chronometer) INFO: update_messages duration: 0.0044s
May 12 15:09:10 localhost 2020-05-12 15:09:10,047 - securedrop_client.storage:91(chronometer) INFO: update_replies duration: 0.0076s
May 12 15:09:10 localhost 2020-05-12 15:09:10,391 - securedrop_client.api_jobs.base:84(_do_call_api) ERROR: SendReplyJob API call error: Traceback (most recent call last):#012  File "/opt/venvs/securedrop-client/lib/python3.7/site-packages/securedrop_client/api_jobs/uploads.py", line 56, in call_api#012    encrypted_reply = self.gpg.encrypt_to_source(self.source_uuid, self.message)#012  File "/opt/venvs/securedrop-client/lib/python3.7/site-packages/securedrop_client/crypto.py", line 192, in encrypt_to_source#012    raise CryptoError(f'Could not encrypt reply: no key for source {source_uuid}')#012securedrop_client.crypto.CryptoError: Could not encrypt reply: no key for source 85633300-b656-4b9d-866d-91bff5f0e15f#012#012During handling of the above exception, another exception occurred:#012#012Traceback (most recent call last):#012  File "/opt/venvs/securedrop-client/lib/python3.7/site-packages/securedrop_client/api_jobs/base.py", line 72, in _do_call_api#012    result = self.call_api(api_client, session)#012  File "/opt/venvs/securedrop-client/lib/python3.7/site-packages/securedrop_client/api_jobs/uploads.py", line 101, in call_api#012    raise SendReplyJobError(message, self.reply_uuid)#012securedrop_client.api_jobs.uploads.SendReplyJobError: #012                Failed to send reply 3b1935d6-eaef-4f27-a2ce-bfcb3392b6aa for source 85633300-b656-4b9d-866d-91bff5f0e15f due to Exception: Could not encrypt reply: no key for source 85633300-b656-4b9d-866d-91bff5f0e15f#012            
May 12 15:09:10 localhost 2020-05-12 15:09:10,392 - securedrop_client.queue:131(process) ERROR: SendReplyJobError: #012                Failed to send reply 3b1935d6-eaef-4f27-a2ce-bfcb3392b6aa for source 85633300-b656-4b9d-866d-91bff5f0e15f due to Exception: Could not encrypt reply: no key for source 85633300-b656-4b9d-866d-91bff5f0e15f#012            
May 12 15:09:30 localhost 2020-05-12 15:09:30,401 - securedrop_client.storage:98(get_remote_data) INFO: Fetched 30 remote sources.
May 12 15:09:30 localhost 2020-05-12 15:09:30,401 - securedrop_client.storage:100(get_remote_data) INFO: Fetched 131 remote submissions.
May 12 15:09:30 localhost 2020-05-12 15:09:30,401 - securedrop_client.storage:101(get_remote_data) INFO: Fetched 94 remote replies.
May 12 15:09:30 localhost 2020-05-12 15:09:30,408 - securedrop_client.storage:91(chronometer) INFO: update_sources duration: 0.0070s
--
May 12 15:10:51 localhost 2020-05-12 15:10:51,546 - securedrop_client.storage:101(get_remote_data) INFO: Fetched 94 remote replies.
May 12 15:10:51 localhost 2020-05-12 15:10:51,552 - securedrop_client.storage:91(chronometer) INFO: update_sources duration: 0.0063s
May 12 15:10:51 localhost 2020-05-12 15:10:51,556 - securedrop_client.storage:91(chronometer) INFO: update_files duration: 0.0034s
May 12 15:10:51 localhost 2020-05-12 15:10:51,561 - securedrop_client.storage:91(chronometer) INFO: update_messages duration: 0.0050s
May 12 15:10:51 localhost 2020-05-12 15:10:51,568 - securedrop_client.storage:91(chronometer) INFO: update_replies duration: 0.0074s
May 12 15:11:00 localhost 2020-05-12 15:11:00,740 - securedrop_client.api_jobs.base:84(_do_call_api) ERROR: SendReplyJob API call error: Traceback (most recent call last):#012  File "/opt/venvs/securedrop-client/lib/python3.7/site-packages/securedrop_client/api_jobs/uploads.py", line 56, in call_api#012    encrypted_reply = self.gpg.encrypt_to_source(self.source_uuid, self.message)#012  File "/opt/venvs/securedrop-client/lib/python3.7/site-packages/securedrop_client/crypto.py", line 192, in encrypt_to_source#012    raise CryptoError(f'Could not encrypt reply: no key for source {source_uuid}')#012securedrop_client.crypto.CryptoError: Could not encrypt reply: no key for source 85633300-b656-4b9d-866d-91bff5f0e15f#012#012During handling of the above exception, another exception occurred:#012#012Traceback (most recent call last):#012  File "/opt/venvs/securedrop-client/lib/python3.7/site-packages/securedrop_client/api_jobs/base.py", line 72, in _do_call_api#012    result = self.call_api(api_client, session)#012  File "/opt/venvs/securedrop-client/lib/python3.7/site-packages/securedrop_client/api_jobs/uploads.py", line 101, in call_api#012    raise SendReplyJobError(message, self.reply_uuid)#012securedrop_client.api_jobs.uploads.SendReplyJobError: #012                Failed to send reply b0def047-7916-4774-8e6a-30f30beb5c52 for source 85633300-b656-4b9d-866d-91bff5f0e15f due to Exception: Could not encrypt reply: no key for source 85633300-b656-4b9d-866d-91bff5f0e15f#012            
May 12 15:11:00 localhost 2020-05-12 15:11:00,740 - securedrop_client.queue:131(process) ERROR: SendReplyJobError: #012                Failed to send reply b0def047-7916-4774-8e6a-30f30beb5c52 for source 85633300-b656-4b9d-866d-91bff5f0e15f due to Exception: Could not encrypt reply: no key for source 85633300-b656-4b9d-866d-91bff5f0e15f#012            
May 12 15:11:12 localhost 2020-05-12 15:11:12,664 - securedrop_client.storage:98(get_remote_data) INFO: Fetched 30 remote sources.
May 12 15:11:12 localhost 2020-05-12 15:11:12,664 - securedrop_client.storage:100(get_remote_data) INFO: Fetched 131 remote submissions.
May 12 15:11:12 localhost 2020-05-12 15:11:12,664 - securedrop_client.storage:101(get_remote_data) INFO: Fetched 94 remote replies.
May 12 15:11:12 localhost 2020-05-12 15:11:12,672 - securedrop_client.storage:91(chronometer) INFO: update_sources duration: 0.0077s

[eloquence]

I was not able to reproduce using the production version of the securedrop-client package (0.1.6) against the same server (1.3.0~rc2). This suggests that a regression may have been introduced in master since the 0.1.6 release. Possibly related: #1035

[rmol]

I think I found it, and it's definitely a client-side problem, nothing to do with SecureDrop 1.3.0. If a source is downloaded before it has its keypair, its key fingerprint will never be updated, because that attribute is missing from those updated in storage.update_sources.

[sssoleileraaa]

Did you see the source surge message when generating the new sources during the repos?

[eloquence]

No, when I encountered this issue, the reply area was initially disabled, but enabled on the next sync (which is when it did not work). Note that the "source surge message" will only be displayed to the Source after the source is flagged for reply in the JUI, in any event.

I don't believe these intermittent issues were related to entropy pool exhaustion -- the first time I encountered this issue was on the first source submitted to the server, and it's generally quite hard to hit the entropy pool exhaustion scenario.

[sssoleileraaa]

So it sounds like there could be another reason the server doesn't generate a reply key for a new source. Note that during the client sync, we create new sources with the fingerprint and public_key provided by the server, so my thinking is that when you and Conor saw this issue, the server had returned a new source without a public key and fingerprint. I'm trying to understand all the cases where this could happen.

[eloquence]

Yes, but keep in mind that this bug was introduced since the 0.1.6 release of the client. The server will happily supply the key on the next sync. @rmol can clarify, but I think it may have been introduced by #1035.

[sssoleileraaa]

Understood. So the bug is fixed if we update the fingerprint and public key each time we sync. I'm just digging in because we should know all the reasons we could return a source without a key. It sounds like you and Conor might have hit this issue because for some reason other than the source surge scenario, you hit a condition where the server did not generate a source key for a new source.

[eloquence]

Yes, speculating, I would guess that the asynchronous key generation simply had not finished by the time of the sync. See #803 when we first discovered that this could be an issue in the client.

[sssoleileraaa]

That would make sense if it's asynchronous! I think maybe we should consider making it synchronous on the server, but I know there are a lot of other things happening right now so I'll just homer-sinks-into-bushes for now.