Merge pull request #1272 from GSA/notify-api-1271

Read over Python 3.12's Logging Guide and see if there's anything else we could be leveraging/configuring to improve how logging is structured throughout our applications

app/__init__.py

@@ -265,7 +265,7 @@ def after_request(response):
 
     @app.errorhandler(Exception)
     def exception(error):
-        app.logger.exception(error)
+        app.logger.exception(f"Handling error: {error}")
         # error.code is set for our exception types.
         msg = getattr(error, "message", str(error))
         code = getattr(error, "code", 500)
@@ -353,7 +353,9 @@ def checkout(dbapi_connection, connection_record, connection_proxy):  # noqa
                         "url_rule": "unknown",
                     }
             except Exception:
-                current_app.logger.exception("Exception caught for checkout event.")
+                current_app.logger.exception(
+                    "Exception caught for checkout event.",
+                )
 
         @event.listens_for(db.engine, "checkin")
         def checkin(dbapi_connection, connection_record):  # noqa
@@ -403,7 +405,7 @@ def on_failure(self, exc, task_id, args, kwargs, einfo):  # noqa
                     "Celery task {task_name} (queue: {queue_name}) failed".format(
                         task_name=self.name,
                         queue_name=self.queue_name,
-                    )
+                    ),
                 )
 
         def __call__(self, *args, **kwargs):

app/aws/s3.py

@@ -76,9 +76,9 @@ def list_s3_objects():
                 )
             else:
                 break
-    except Exception as e:
-        current_app.logger.error(
-            f"An error occurred while regenerating cache #notify-admin-1200 {e}"
+    except Exception:
+        current_app.logger.exception(
+            "An error occurred while regenerating cache #notify-admin-1200",
         )
 
 
@@ -111,9 +111,8 @@ def cleanup_old_s3_objects():
             else:
                 break
     except Exception:
-        current_app.logger.error(
+        current_app.logger.exception(
             "#delete-old-s3-objects An error occurred while cleaning up old s3 objects",
-            exc_info=True,
         )
 
 
@@ -141,9 +140,9 @@ def get_s3_files():
                 )
                 if "phone number" in object.lower():
                     JOBS[job_id] = object
-        except LookupError as le:
+        except LookupError:
             # perhaps our key is not formatted as we expected.  If so skip it.
-            current_app.logger.error(f"LookupError {le} #notify-admin-1200")
+            current_app.logger.exception("LookupError #notify-admin-1200")
 
     current_app.logger.info(
         f"JOBS cache length after regen: {len(JOBS)} #notify-admin-1200"
@@ -165,14 +164,14 @@ def download_from_s3(
         result = s3.download_file(bucket_name, s3_key, local_filename)
         current_app.logger.info(f"File downloaded successfully to {local_filename}")
     except botocore.exceptions.NoCredentialsError as nce:
-        current_app.logger.error("Credentials not found")
+        current_app.logger.exception("Credentials not found")
         raise Exception(nce)
     except botocore.exceptions.PartialCredentialsError as pce:
-        current_app.logger.error("Incomplete credentials provided")
+        current_app.logger.exception("Incomplete credentials provided")
         raise Exception(pce)
-    except Exception as e:
-        current_app.logger.error(f"An error occurred {e}")
-        text = f"EXCEPTION {e} local_filename {local_filename}"
+    except Exception:
+        current_app.logger.exception("An error occurred")
+        text = f"EXCEPTION local_filename {local_filename}"
         raise Exception(text)
     return result
 
@@ -183,8 +182,8 @@ def get_s3_object(bucket_name, file_location, access_key, secret_key, region):
     try:
         return s3.Object(bucket_name, file_location)
     except botocore.exceptions.ClientError:
-        current_app.logger.error(
-            f"Can't retrieve S3 Object from {file_location}", exc_info=True
+        current_app.logger.exception(
+            f"Can't retrieve S3 Object from {file_location}",
         )
 
 
@@ -258,32 +257,28 @@ def get_job_from_s3(service_id, job_id):
                 "RequestTimeout",
                 "SlowDown",
             ]:
-                current_app.logger.error(
+                current_app.logger.exception(
                     f"Retrying job fetch {FILE_LOCATION_STRUCTURE.format(service_id, job_id)} retry_count={retries}",
-                    exc_info=True,
                 )
                 retries += 1
                 sleep_time = backoff_factor * (2**retries)  # Exponential backoff
                 time.sleep(sleep_time)
                 continue
             else:
                 # Typically this is "NoSuchKey"
-                current_app.logger.error(
+                current_app.logger.exception(
                     f"Failed to get job {FILE_LOCATION_STRUCTURE.format(service_id, job_id)}",
-                    exc_info=True,
                 )
                 return None
 
         except Exception:
-            current_app.logger.error(
+            current_app.logger.exception(
                 f"Failed to get job {FILE_LOCATION_STRUCTURE.format(service_id, job_id)} retry_count={retries}",
-                exc_info=True,
             )
             return None
 
     current_app.logger.error(
         f"Never retrieved job {FILE_LOCATION_STRUCTURE.format(service_id, job_id)}",
-        exc_info=True,
     )
     return None
 
@@ -322,7 +317,7 @@ def extract_phones(job):
         if phone_index >= len(row):
             phones[job_row] = "Unavailable"
             current_app.logger.error(
-                "Corrupt csv file, missing columns or possibly a byte order mark in the file"
+                "Corrupt csv file, missing columns or possibly a byte order mark in the file",
             )
 
         else:

app/celery/nightly_tasks.py

@@ -54,8 +54,8 @@ def cleanup_unfinished_jobs():
         try:
             acceptable_finish_time = job.processing_started + timedelta(minutes=5)
         except TypeError:
-            current_app.logger.error(
-                f"Job ID {job.id} processing_started is {job.processing_started}."
+            current_app.logger.exception(
+                f"Job ID {job.id} processing_started is {job.processing_started}.",
             )
             raise
         if now > acceptable_finish_time:

app/celery/process_ses_receipts_tasks.py

@@ -113,8 +113,8 @@ def process_ses_results(self, response):
     except Retry:
         raise
 
-    except Exception as e:
-        current_app.logger.exception("Error processing SES results: {}".format(type(e)))
+    except Exception:
+        current_app.logger.exception("Error processing SES results")
         self.retry(queue=QueueNames.RETRY)
 
 
@@ -204,9 +204,9 @@ def handle_complaint(ses_message):
     )
     try:
         reference = ses_message["mail"]["messageId"]
-    except KeyError as e:
+    except KeyError:
         current_app.logger.exception(
-            f"Complaint from SES failed to get reference from message with error: {e}"
+            "Complaint from SES failed to get reference from message"
         )
         return
     notification = dao_get_notification_history_by_reference(reference)

app/celery/provider_tasks.py

@@ -144,11 +144,10 @@ def deliver_sms(self, notification_id):
         if isinstance(e, SmsClientResponseException):
             current_app.logger.warning(
                 "SMS notification delivery for id: {} failed".format(notification_id),
-                exc_info=True,
             )
         else:
             current_app.logger.exception(
-                "SMS notification delivery for id: {} failed".format(notification_id)
+                "SMS notification delivery for id: {} failed".format(notification_id),
             )
 
         try:
@@ -186,10 +185,8 @@ def deliver_email(self, notification_id):
 
         notification.personalisation = json.loads(personalisation)
         send_to_providers.send_email_to_provider(notification)
-    except EmailClientNonRetryableException as e:
-        current_app.logger.exception(
-            f"Email notification {notification_id} failed: {e}"
-        )
+    except EmailClientNonRetryableException:
+        current_app.logger.exception(f"Email notification {notification_id} failed")
         update_notification_status_by_id(notification_id, "technical-failure")
     except Exception as e:
         try:

app/celery/tasks.py

@@ -158,10 +158,10 @@ def __total_sending_limits_for_job_exceeded(service, job, job_id):
         job.job_status = "sending limits exceeded"
         job.processing_finished = utc_now()
         dao_update_job(job)
-        current_app.logger.error(
+        current_app.logger.exception(
             "Job {} size {} error. Total sending limits {} exceeded".format(
                 job_id, job.notification_count, service.message_limit
-            )
+            ),
         )
         return True
 
@@ -360,8 +360,8 @@ def save_api_email_or_sms(self, encrypted_notification):
         try:
             self.retry(queue=QueueNames.RETRY)
         except self.MaxRetriesExceededError:
-            current_app.logger.error(
-                f"Max retry failed Failed to persist notification {notification['id']}"
+            current_app.logger.exception(
+                f"Max retry failed Failed to persist notification {notification['id']}",
             )
 
 
@@ -381,7 +381,7 @@ def handle_exception(task, notification, notification_id, exc):
         try:
             task.retry(queue=QueueNames.RETRY, exc=exc)
         except task.MaxRetriesExceededError:
-            current_app.logger.error("Max retry failed" + retry_msg)
+            current_app.logger.exception("Max retry failed" + retry_msg)
 
 
 @notify_celery.task(
@@ -430,7 +430,7 @@ def send_inbound_sms_to_service(self, inbound_sms_id, service_id):
             try:
                 self.retry(queue=QueueNames.RETRY)
             except self.MaxRetriesExceededError:
-                current_app.logger.error(
+                current_app.logger.exception(
                     "Retry: send_inbound_sms_to_service has retried the max number of"
                     + f"times for service: {service_id} and inbound_sms {inbound_sms_id}"
                 )

app/clients/sms/aws_sns.py

@@ -80,10 +80,10 @@ def send_sms(self, to, content, reference, sender=None, international=False):
                     PhoneNumber=to, Message=content, MessageAttributes=attributes
                 )
             except botocore.exceptions.ClientError as e:
-                self.current_app.logger.error(e)
+                self.current_app.logger.exception("An error occurred sending sms")
                 raise str(e)
             except Exception as e:
-                self.current_app.logger(e)
+                self.current_app.logger.exception("An error occurred sending sms")
                 raise str(e)
             finally:
                 elapsed_time = monotonic() - start_time