Merge pull request #1090 from freedomofpress/cryptoerro-logs

Cryptoerror logs

securedrop_client/api_jobs/base.py

@@ -1,5 +1,4 @@
 import logging
-import traceback
 
 from PyQt5.QtCore import QObject, pyqtSignal
 from sdclientapi import API, AuthError, RequestTimeoutError, ServerConnectionError
@@ -78,11 +77,6 @@ def _do_call_api(self, api_client: API, session: Session) -> None:
                     raise
             except Exception as e:
                 self.failure_signal.emit(e)
-                logger.error(
-                    "%s API call error: %s",
-                    self.__class__.__name__,
-                    traceback.format_exc()
-                )
                 raise
             else:
                 self.success_signal.emit(result)

securedrop_client/api_jobs/downloads.py

@@ -167,7 +167,6 @@ def _download(self,
             logger.info("File downloaded to {}".format(destination))
             return destination
         except BaseError as e:
-            logger.debug("Failed to download file: {}".format(db_object.filename))
             raise e
 
     def _decrypt(self,
@@ -181,21 +180,17 @@ def _decrypt(self,
             original_filename = self.call_decrypt(filepath, session)
             db_object.download_error = None
             mark_as_decrypted(
-                type(db_object), db_object.uuid, session, original_filename=original_filename
-            )
-            logger.info("File decrypted: {} (decrypted file in: {})".format(
-                os.path.basename(filepath), os.path.dirname(filepath))
-            )
+                type(db_object), db_object.uuid, session, original_filename=original_filename)
+            logger.info(f'File decrypted to {os.path.dirname(filepath)}')
         except CryptoError as e:
             mark_as_decrypted(type(db_object), db_object.uuid, session, is_decrypted=False)
             download_error = session.query(DownloadError).filter_by(
                 name=DownloadErrorCodes.DECRYPTION_ERROR.name
             ).one()
             db_object.download_error = download_error
             session.commit()
-            logger.debug("Failed to decrypt file: {}".format(os.path.basename(filepath)))
             raise DownloadDecryptionException(
-                "Downloaded file could not be decrypted.",
+                f'Failed to decrypt file: {os.path.basename(filepath)}',
                 type(db_object),
                 db_object.uuid
             ) from e
@@ -270,21 +265,19 @@ def call_decrypt(self, filepath: str, session: Session = None) -> str:
         The return value is an empty string; replies have no original filename.
         '''
         with NamedTemporaryFile('w+') as plaintext_file:
-            self.gpg.decrypt_submission_or_reply(filepath, plaintext_file.name, is_doc=False)
             try:
+                self.gpg.decrypt_submission_or_reply(filepath, plaintext_file.name, is_doc=False)
                 set_message_or_reply_content(
                     model_type=Reply,
                     uuid=self.uuid,
                     session=session,
                     content=plaintext_file.read())
             finally:
-                # clean up directory where decryption happened
                 try:
                     os.rmdir(os.path.dirname(filepath))
-                except Exception as e:
-                    logger.warning(
-                        "Error deleting decryption directory of message %s: %s", self.uuid, e
-                    )
+                except OSError:
+                    msg = f'Could not delete decryption directory: {os.path.dirname(filepath)}'
+                    logger.debug(msg)
 
         return ""
 
@@ -335,13 +328,12 @@ def call_decrypt(self, filepath: str, session: Session = None) -> str:
                     session=session,
                     content=plaintext_file.read())
             finally:
-                # clean up directory where decryption happened
                 try:
                     os.rmdir(os.path.dirname(filepath))
-                except Exception as e:
-                    logger.warning(
-                        "Error deleting decryption directory of message %s: %s", self.uuid, e
-                    )
+                except OSError:
+                    msg = f'Could not delete decryption directory: {os.path.dirname(filepath)}'
+                    logger.debug(msg)
+
         return ""
 
 
@@ -386,6 +378,4 @@ def call_decrypt(self, filepath: str, session: Session = None) -> str:
         original_filename = self.gpg.decrypt_submission_or_reply(
             filepath, plaintext_filepath, is_doc=True
         )
-        logger.info("Decrypted file '{}' to folder '{}'".format(
-            os.path.basename(filepath), os.path.dirname(filepath)))
         return original_filename

securedrop_client/crypto.py

@@ -109,7 +109,6 @@ def decrypt_submission_or_reply(self,
                 with open(err.name) as e:
                     msg = "GPG Error: {}".format(e.read())
 
-                logger.error(msg)
                 os.unlink(err.name)
 
                 raise CryptoError(msg)
@@ -173,8 +172,7 @@ def _import(self, key_data: str) -> None:
                 subprocess.check_call(cmd, stdout=stdout, stderr=stderr)
             except subprocess.CalledProcessError as e:
                 stderr.seek(0)
-                logger.error('Could not import key: {}\n{}'.format(e, stderr.read()))
-                raise CryptoError('Could not import key.')
+                raise CryptoError('Could not import key: {}\n{}'.format(e, stderr.read()))
 
     def encrypt_to_source(self, source_uuid: str, data: str) -> str:
         '''
@@ -220,9 +218,8 @@ def encrypt_to_source(self, source_uuid: str, data: str) -> str:
                 subprocess.check_call(cmd, stdout=stdout, stderr=stderr)
             except subprocess.CalledProcessError as e:
                 stderr.seek(0)
-                logger.error(
-                    'Could not encrypt to source {}: {}\n{}'.format(source_uuid, e, stderr.read()))
-                raise CryptoError('Could not encrypt to source: {}.'.format(source_uuid))
+                err = stderr.read()
+                raise CryptoError(f'Could not encrypt to source {source_uuid}: {e}\n{err}')
 
             stdout.seek(0)
             return stdout.read()

securedrop_client/logic.py

@@ -658,8 +658,6 @@ def on_message_download_failure(self, exception: DownloadException) -> None:
         """
         Called when a message fails to download.
         """
-        logger.info('Failed to download message: {}'.format(exception))
-
         if isinstance(exception, DownloadChecksumMismatchException):
             # Keep resubmitting the job if the download is corrupted.
             logger.warning('Failure due to checksum mismatch, retrying {}'.format(exception.uuid))
@@ -694,8 +692,6 @@ def on_reply_download_failure(self, exception: DownloadException) -> None:
         """
         Called when a reply fails to download.
         """
-        logger.info('Failed to download reply: {}'.format(exception))
-
         if isinstance(exception, DownloadChecksumMismatchException):
             # Keep resubmitting the job if the download is corrupted.
             logger.warning('Failure due to checksum mismatch, retrying {}'.format(exception.uuid))
@@ -828,8 +824,6 @@ def on_file_download_failure(self, exception: Exception) -> None:
         """
         Called when a file fails to download.
         """
-        logger.info('Failed to download file: {}'.format(exception))
-
         # Keep resubmitting the job if the download is corrupted.
         if isinstance(exception, DownloadChecksumMismatchException):
             logger.warning('Failure due to checksum mismatch, retrying {}'.format(exception.uuid))

tests/api_jobs/test_downloads.py

@@ -520,14 +520,9 @@ def fake_download(sdk_obj: SdkSubmission, timeout: int) -> Tuple[str, str]:
         gpg,
     )
 
-    mock_logger = mocker.patch('securedrop_client.api_jobs.downloads.logger')
-
     with pytest.raises(DownloadDecryptionException):
         job.call_api(api_client, session)
 
-    log_msg = mock_logger.debug.call_args_list[0][0][0]
-    assert log_msg.startswith('Failed to decrypt file')
-
     # ensure mocks aren't stale
     assert mock_decrypt.called
 

tests/test_logic.py

@@ -1187,12 +1187,10 @@ def test_Controller_on_reply_downloaded_failure(mocker, homedir, session_maker):
     reply_ready = mocker.patch.object(co, 'reply_ready')
     reply = factory.Reply(source=factory.Source())
     mocker.patch('securedrop_client.storage.get_reply', return_value=reply)
-    info_logger = mocker.patch('securedrop_client.logic.logger.info')
     co._submit_download_job = mocker.MagicMock()
 
     co.on_reply_download_failure(Exception('mock_exception'))
 
-    info_logger.assert_called_once_with('Failed to download reply: mock_exception')
     reply_ready.emit.assert_not_called()
 
     # Job should not get automatically resubmitted if the failure was generic
@@ -1208,13 +1206,11 @@ def test_Controller_on_reply_downloaded_checksum_failure(mocker, homedir, sessio
     reply = factory.Reply(source=factory.Source())
     mocker.patch('securedrop_client.storage.get_reply', return_value=reply)
     warning_logger = mocker.patch('securedrop_client.logic.logger.warning')
-    info_logger = mocker.patch('securedrop_client.logic.logger.info')
     co._submit_download_job = mocker.MagicMock()
 
     co.on_reply_download_failure(DownloadChecksumMismatchException('bang!',
                                  type(reply), reply.uuid))
 
-    info_logger.call_args_list[0][0][0] == 'Failed to download reply: bang!'
     reply_ready.emit.assert_not_called()
 
     # Job should get resubmitted and we should log this is happening
@@ -1232,12 +1228,10 @@ def test_Controller_on_reply_downloaded_decryption_failure(mocker, homedir, sess
     reply_download_failed = mocker.patch.object(co, 'reply_download_failed')
     reply = factory.Reply(source=factory.Source())
     mocker.patch('securedrop_client.storage.get_reply', return_value=reply)
-    info_logger = mocker.patch('securedrop_client.logic.logger.info')
 
     decryption_exception = DownloadDecryptionException('bang!', type(reply), reply.uuid)
     co.on_reply_download_failure(decryption_exception)
 
-    info_logger.call_args_list[0][0][0] == 'Failed to download reply: bang!'
     reply_ready.emit.assert_not_called()
     reply_download_failed.emit.assert_called_with(reply.source.uuid, reply.uuid, str(reply))
 
@@ -1376,11 +1370,9 @@ def test_Controller_on_message_downloaded_failure(mocker, homedir, session_maker
     message = factory.Message(source=factory.Source())
     mocker.patch('securedrop_client.storage.get_message', return_value=message)
     co._submit_download_job = mocker.MagicMock()
-    info_logger = mocker.patch('securedrop_client.logic.logger.info')
 
     co.on_message_download_failure(Exception('mock_exception'))
 
-    info_logger.assert_called_once_with('Failed to download message: mock_exception')
     message_ready.emit.assert_not_called()
 
     # Job should not get automatically resubmitted if the failure was generic
@@ -1396,19 +1388,14 @@ def test_Controller_on_message_downloaded_checksum_failure(mocker, homedir, sess
     message = factory.Message(source=factory.Source())
     mocker.patch('securedrop_client.storage.get_message', return_value=message)
     co._submit_download_job = mocker.MagicMock()
-    warning_logger = mocker.patch('securedrop_client.logic.logger.warning')
-    info_logger = mocker.patch('securedrop_client.logic.logger.info')
 
     co.on_message_download_failure(DownloadChecksumMismatchException('bang!',
                                    type(message), message.uuid))
 
-    info_logger.call_args_list[0][0][0] == 'Failed to download message: bang!'
     message_ready.emit.assert_not_called()
 
     # Job should get resubmitted and we should log this is happening
     co._submit_download_job.call_count == 1
-    warning_logger.call_args_list[0][0][0] == \
-        'Failure due to checksum mismatch, retrying {}'.format(message.uuid)
 
 
 def test_Controller_on_message_downloaded_decryption_failure(mocker, homedir, session_maker):
@@ -1420,12 +1407,10 @@ def test_Controller_on_message_downloaded_decryption_failure(mocker, homedir, se
     message_download_failed = mocker.patch.object(co, 'message_download_failed')
     message = factory.Message(source=factory.Source())
     mocker.patch('securedrop_client.storage.get_message', return_value=message)
-    info_logger = mocker.patch('securedrop_client.logic.logger.info')
 
     decryption_exception = DownloadDecryptionException('bang!', type(message), message.uuid)
     co.on_message_download_failure(decryption_exception)
 
-    info_logger.call_args_list[0][0][0] == 'Failed to download message: bang!'
     message_ready.emit.assert_not_called()
     message_download_failed.emit.assert_called_with(message.source.uuid, message.uuid, str(message))