app crashes when object has no attribute 'reply_uuid'

[redshiftzero]

STR

1. Use diff in Replies are sometimes displayed out of order #653 not necessary
2. Send a reply
3. If it fails, click retry until it succeeds

Expected behavior

I repro that bug

Actual behavior

Traceback (most recent call last):
  File "/Users/redshiftzero/Documents/Github/securedrop-client/securedrop_client/logic.py", line 815, in on_reply_failure
    logger.debug('{} failed to send'.format(exception.reply_uuid))
AttributeError: 'ObjectDeletedError' object has no attribute 'reply_uuid'

[redshiftzero]

I don't know how this could occur right now, but am putting here so someone else can comment if they've seen it

[sssoleileraaa]

I just came across a similar error, looks like the same underlying issue:

STR

1. Apply this diff

--- a/securedrop_client/api_jobs/uploads.py
+++ b/securedrop_client/api_jobs/uploads.py
@@ -96,7 +96,7 @@ class SendReplyJob(ApiJob):
         # TODO: Once https://github.com/freedomofpress/securedrop-client/issues/648, we will want to
         # pass the default request timeout to reply_source instead of setting it on the api object
         # directly.
-        api_client.default_request_timeout = 5
+        api_client.default_request_timeout = 0.01
         return api_client.reply_source(sdk_source, encrypted_reply, self.reply_uuid)
 

2. Send a reply and see it fail
3. Wait until next sync

Expected

For the reply to fail, the sync to succeed, the reply to retry and fail again (because the timeout is 0.01s)

Actual

(.venv) ~/workspace/freedomofpress/securedrop-client(master⚡) » ./run.sh --sdc-home ~/.securedrop_client
Running app with home directory: /home/creviera/.securedrop_client

Current OS is *not* Qubes, disabling DispVM support...
gpg: key CC40EF1228271441: "SecureDrop Test/Development (DO NOT USE IN PRODUCTION)" not changed
gpg: key CC40EF1228271441: secret key imported
gpg: Total number processed: 1
gpg:              unchanged: 1
gpg:       secret keys read: 1
gpg:  secret keys unchanged: 1
QWidget::setTabOrder: 'first' and 'second' must be in the same window
QWidget::setTabOrder: 'first' and 'second' must be in the same window
QWidget::setTabOrder: 'first' and 'second' must be in the same window
Traceback (most recent call last):
  File "/home/creviera/workspace/freedomofpress/securedrop-client/securedrop_client/logic.py", line 815, in on_reply_failure
    logger.debug('{} failed to send'.format(exception.reply_uuid))
AttributeError: 'UnboundLocalError' object has no attribute 'reply_uuid'

Qt has caught an exception thrown from an event handler. Throwing
exceptions from an event handler is not supported in Qt.
You must not let any exception whatsoever propagate through Qt code.
If that is not possible, in Qt 5 you must at least reimplement
QCoreApplication::notify() and catch all exceptions there.


(python:411): GLib-CRITICAL **: g_source_unref_internal: assertion 'source != NULL' failed

[sssoleileraaa]

Interestingly, these changes fix the issue:

Fix 1

diff --git a/securedrop_client/api_jobs/uploads.py b/securedrop_client/api_jobs/uploads.py
index d5b451f..bbb5d5d 100644
--- a/securedrop_client/api_jobs/uploads.py
+++ b/securedrop_client/api_jobs/uploads.py
@@ -70,11 +70,11 @@ class SendReplyJob(ApiJob):
                 id=self.source_uuid, error=e)
 
             # Update draft reply send status to FAILED
-            reply_status = session.query(ReplySendStatus).filter_by(
-                name=ReplySendStatusCodes.FAILED.value).one()
-            draft_reply_db_object.send_status_id = reply_status.id
-            session.add(draft_reply_db_object)
-            session.commit()
+            # reply_status = session.query(ReplySendStatus).filter_by(
+            #     name=ReplySendStatusCodes.FAILED.value).one()
+            # draft_reply_db_object.send_status_id = reply_status.id
+            # session.add(draft_reply_db_object)
+            # session.commit()
 
             raise SendReplyJobTimeoutError(message, self.reply_uuid)
         except Exception as e:
@@ -96,7 +96,7 @@ class SendReplyJob(ApiJob):
         # TODO: Once https://github.com/freedomofpress/securedrop-client/issues/648, we will want to
         # pass the default request timeout to reply_source instead of setting it on the api object
         # directly.
-        api_client.default_request_timeout = 5
+        api_client.default_request_timeout = 0.01
         return api_client.reply_source(sdk_source, encrypted_reply, self.reply_uuid)

If you uncomment those lines ^ then you'll see the issue again.

Fix 2

--- a/securedrop_client/api_jobs/uploads.py
+++ b/securedrop_client/api_jobs/uploads.py
@@ -76,7 +76,7 @@ class SendReplyJob(ApiJob):
             session.add(draft_reply_db_object)
             session.commit()
 
-            raise SendReplyJobTimeoutError(message, self.reply_uuid)
+            raise SendReplyJobError(message, self.reply_uuid)
         except Exception as e:
             message = "Failed to send reply for source {id} due to Exception: {error}".format(
                 id=self.source_uuid, error=e)
@@ -96,7 +96,7 @@ class SendReplyJob(ApiJob):
         # TODO: Once https://github.com/freedomofpress/securedrop-client/issues/648, we will want to
         # pass the default request timeout to reply_source instead of setting it on the api object
         # directly.
-        api_client.default_request_timeout = 5
+        api_client.default_request_timeout = 0.01
         return api_client.reply_source(sdk_source, encrypted_reply, self.reply_uuid)

for some reason we don't see the same error when raising SendReplyJobError instead of SendReplyJobTimeoutError, which made me try this next fix:

Fix 3

--- a/securedrop_client/api_jobs/uploads.py
+++ b/securedrop_client/api_jobs/uploads.py
@@ -96,7 +96,7 @@ class SendReplyJob(ApiJob):
         # TODO: Once https://github.com/freedomofpress/securedrop-client/issues/648, we will want to
         # pass the default request timeout to reply_source instead of setting it on the api object
         # directly.
-        api_client.default_request_timeout = 5
+        api_client.default_request_timeout = 0.01
         return api_client.reply_source(sdk_source, encrypted_reply, self.reply_uuid)
 
 
@@ -106,7 +106,7 @@ class SendReplyJobError(Exception):
         self.reply_uuid = reply_uuid
 
 
-class SendReplyJobTimeoutError(RequestTimeoutError):
+class SendReplyJobTimeoutError(Exception):
     def __init__(self, message: str, reply_uuid: str) -> None:
         super().__init__()
         self.reply_uuid = reply_uuid

[redshiftzero]

at least two issues to resolve:

1. Exceptions in jobs shouldn't crash the app
2. Why are these errors happening to begin with?

1 is happening because if an exception is raised in this code, an exception will not be handled. We should ensure that we handle exceptions here too (wip diff in https://github.com/freedomofpress/securedrop-client/compare/exc-reply-crasher resolving). That diff will also handle the cases @creviera found above where the timeout being set very short, since the root issue there is also the lack of exception handling when setting the reply status to failed.

2 ... still investigating. It makes sense that an ObjectDeletedError could occur in the following scenario:

1. User sends reply A.
2. Reply A sends successfully, but user doesn't get the 201 response.
3. Sync happens, reply A is fetched. Corresponding draft is deleted.
4. Meanwhile the queue is still trying to send the reply. It will fail because the draft has been deleted.

This is uncovered due to #825, causing replies to continually be resent even when successful

[sssoleileraaa]

1. Exceptions in jobs shouldn't crash the app

I think we can avoid this by making sure to only ever raise SendReplyJobError and SendReplyJobTimeoutError exceptions. Our code right now allows exceptions that are not SendReplyJobTimeoutError or SendReplyJobError to be thrown from our catch-block here:

        except (RequestTimeoutError, ServerConnectionError) as e:
            message = "Failed to send reply for source {id} due to Exception: {error}".format(
                id=self.source_uuid, error=e)

            # Update draft reply send status to FAILED
            reply_status = session.query(ReplySendStatus).filter_by(
                name=ReplySendStatusCodes.FAILED.value).one()
            draft_reply_db_object.send_status_id = reply_status.id
            session.add(draft_reply_db_object)
            session.commit()

            raise SendReplyJobTimeoutError(message, self.reply_uuid)
        except Exception as e:
            message = "Failed to send reply for source {id} due to Exception: {error}".format(
                id=self.source_uuid, error=e)

            # Update draft reply send status to FAILED
            reply_status = session.query(ReplySendStatus).filter_by(
                name=ReplySendStatusCodes.FAILED.value).one()
            draft_reply_db_object.send_status_id = reply_status.id
            session.add(draft_reply_db_object)
            session.commit()

            raise SendReplyJobError(message, self.reply_uuid)

As you pointed out, our code that updates the draft reply send status to FAILED in the catch block can raise other errors, e.g. ObjectDeletedError can be raised, but the Controller expects only SendReplyJobError or SendReplyTimeoutJobError with a reply_uuid.

Catching the errors that can occur when updating the draft reply send status to FAILED is only part of the solution though, because this error also happens AttributeError: 'UnboundLocalError' object has no attribute 'reply_uuid' and crashes the app.

1 is happening because if an exception is raised in this code, an exception will not be handled.

It looks like it's also happening when no exception is raised in that code, because another exception, e.g. UnboundLocalError, is raised outside of that code. If you just change the request timeout to something really short and comment out the code that updates the draft reply send status to FAILED, you'll see that an exception happens and crashes the app.

So for followup I'll look into why that UnboundLocalError is happening. My solution to derive from Exception fixes this, but I don't understand why still. I'll dig in further.

[sssoleileraaa]

So for followup I'll look into why that UnboundLocalError is happening. My solution to derive from Exception fixes this, but I don't understand why still. I'll dig in further.

Results from further digging:

1. Start the client (on master with SendReplyJob timeout = 0.01s)

2. Send one reply. See from the logs that the job is added to the queue, then the job fails as expected, and on_reply_failure successfully logs the reply_uuid (it exists! as expected):

2020-02-26 13:11:11,353 - securedrop_client.queue:236(enqueue) DEBUG: Added SendReplyJob to main queue
2020-02-26 13:11:11,537 - securedrop_client.queue:127(process) DEBUG: SendReplyJobTimeoutError: Failed to send reply for source 573b7939-8c71-49ab-8cd9-379ba648bf66 due to Exception: The request timed out.
2020-02-26 13:11:11,537 - securedrop_client.logic:815(on_reply_failure) DEBUG: c3bd7d9b-a3c4-49dd-ac6e-8e2c85e6fe17 failed to send
2020-02-26 13:11:11,542 - securedrop_client.queue:201(on_main_queue_paused) DEBUG: Paused main queue
...

3. Nothing logged for a few seconds until next sync.

4. Next sync occurs and see the following log before the queue resumes:

2020-02-26 13:11:19,136 - securedrop_client.storage:328(update_replies) DEBUG: Added new reply c3bd7d9b-a3c4-49dd-ac6e-8e2c85e6fe17

We shouldn't be doing this. It doesn't make sense for us to insert a new Reply into the local database because the reply is already stored as a DraftReply and needs to be resent, but this is what we're doing along with deleting the DraftReply that the job in the queue still expects to exist.

--

My next step is to investigate the storage.update_replies code.

[redshiftzero]

closing this since the crashing was fixed in PR #829 and the other bug is captured in #833