Add json logger (#497)

* add dependency

* add json formatter

* update format for formatter_json

* update log messages

* change formatter to json

* Update datameta/api/files.py

Co-authored-by: Leon Kuchenbecker <[email protected]>

* Update datameta/api/files.py

Co-authored-by: Leon Kuchenbecker <[email protected]>

* Update datameta/api/files.py

Co-authored-by: Leon Kuchenbecker <[email protected]>

* Update datameta/api/files.py

Co-authored-by: Leon Kuchenbecker <[email protected]>

* Update datameta/api/files.py

Co-authored-by: Leon Kuchenbecker <[email protected]>

* Update datameta/siteid.py

Co-authored-by: Leon Kuchenbecker <[email protected]>

* Update datameta/siteid.py

Co-authored-by: Leon Kuchenbecker <[email protected]>

* Update datameta/siteid.py

Co-authored-by: Leon Kuchenbecker <[email protected]>

* Update datameta/views/login.py

Co-authored-by: Leon Kuchenbecker <[email protected]>

* Update datameta/views/tfa.py

Co-authored-by: Leon Kuchenbecker <[email protected]>

* Update datameta/api/register.py

Co-authored-by: Leon Kuchenbecker <[email protected]>

* Apply suggestions from code review

log messages

Co-authored-by: Leon Kuchenbecker <[email protected]>

* remove setting `datameta.logging.log_token_urls`

* fix linting

Co-authored-by: Leon Kuchenbecker <[email protected]>

Author: ckaipf

conf/ci.ini

@@ -29,7 +29,6 @@ datameta.site_id_prefix.metadatasets  = DMR-
 datameta.site_id_prefix.files         = DMF-
 datameta.site_id_prefix.services      = DMP-
 
-datameta.logging.log_token_urls = false
 
 # ApiKeys:
 datameta.apikeys.max_expiration_period = 30
@@ -92,7 +91,7 @@ keys = root, datameta, sqlalchemy
 keys = console
 
 [formatters]
-keys = generic
+keys = generic, json
 
 [logger_root]
 level = INFO
@@ -115,7 +114,11 @@ qualname = sqlalchemy.engine
 class = StreamHandler
 args = (sys.stderr,)
 level = NOTSET
-formatter = generic
+formatter = json
+
+[formatter_json]
+format = %(asctime)s %(levelname)s %(name)s %(threadName)s %(message)s
+class = pythonjsonlogger.jsonlogger.JsonFormatter
 
 [formatter_generic]
 format = %(asctime)s %(levelname)-5.5s [%(name)s:%(lineno)s][%(threadName)s] %(message)s

conf/development.ini

@@ -29,7 +29,6 @@ datameta.site_id_prefix.metadatasets  = DMR-
 datameta.site_id_prefix.files         = DMF-
 datameta.site_id_prefix.services      = DMP-
 
-datameta.logging.log_token_urls = false
 
 # ApiKeys:
 datameta.apikeys.max_expiration_period = 30
@@ -93,7 +92,7 @@ keys = root, datameta, sqlalchemy
 keys = console
 
 [formatters]
-keys = generic
+keys = generic, json
 
 [logger_root]
 level = INFO
@@ -116,7 +115,11 @@ qualname = sqlalchemy.engine
 class = StreamHandler
 args = (sys.stderr,)
 level = NOTSET
-formatter = generic
+formatter = json
+
+[formatter_json]
+format = %(asctime)s %(levelname)s %(name)s %(threadName)s %(message)s
+class = pythonjsonlogger.jsonlogger.JsonFormatter
 
 [formatter_generic]
 format = %(asctime)s %(levelname)-5.5s [%(name)s:%(lineno)s][%(threadName)s] %(message)s

conf/docker_development.ini

@@ -29,7 +29,6 @@ datameta.site_id_prefix.metadatasets  = DMR-
 datameta.site_id_prefix.files         = DMF-
 datameta.site_id_prefix.services      = DMP-
 
-datameta.logging.log_token_urls = false
 
 # ApiKeys:
 datameta.apikeys.max_expiration_period = 30
@@ -87,7 +86,7 @@ keys = root, datameta, sqlalchemy
 keys = console
 
 [formatters]
-keys = generic
+keys = generic, json
 
 [logger_root]
 level = WARN
@@ -110,7 +109,11 @@ qualname = sqlalchemy.engine
 class = StreamHandler
 args = (sys.stderr,)
 level = NOTSET
-formatter = generic
+formatter = json
+
+[formatter_json]
+format = %(asctime)s %(levelname)s %(name)s %(threadName)s %(message)s
+class = pythonjsonlogger.jsonlogger.JsonFormatter
 
 [formatter_generic]
 format = %(asctime)s %(levelname)-5.5s [%(name)s:%(lineno)s][%(threadName)s] %(message)s

conf/docker_production.ini

@@ -29,7 +29,6 @@ datameta.site_id_prefix.metadatasets  = $DATAMETA_SITE_ID_PREFIX_METADATASETS
 datameta.site_id_prefix.files         = $DATAMETA_SITE_ID_PREFIX_FILES
 datameta.site_id_prefix.services      = $DATAMETA_SITE_ID_PREFIX_SERVICES
 
-datameta.logging.log_token_urls = false
 
 # ApiKeys:
 datameta.apikeys.max_expiration_period = $DATAMETA_API_KEYS_MAX_EXPIRE_DAYS
@@ -91,7 +90,7 @@ keys = root, datameta, sqlalchemy
 keys = console
 
 [formatters]
-keys = generic
+keys = generic, json
 
 [logger_root]
 level = WARN
@@ -114,7 +113,11 @@ qualname = sqlalchemy.engine
 class = StreamHandler
 args = (sys.stderr,)
 level = NOTSET
-formatter = generic
+formatter = json
+
+[formatter_json]
+format = %(asctime)s %(levelname)s %(name)s %(threadName)s %(message)s
+class = pythonjsonlogger.jsonlogger.JsonFormatter
 
 [formatter_generic]
 format = %(asctime)s %(levelname)-5.5s [%(name)s:%(lineno)s][%(threadName)s] %(message)s

conf/production.ini

@@ -29,7 +29,6 @@ datameta.site_id_prefix.metadatasets  = DMR-
 datameta.site_id_prefix.files         = DMF-
 datameta.site_id_prefix.services      = DMP-
 
-datameta.logging.log_token_urls = false
 
 # ApiKeys:
 datameta.apikeys.max_expiration_period = 30
@@ -82,11 +81,12 @@ listen = *:6543
 
 [loggers]
 keys = root, datameta, sqlalchemy
+
 [handlers]
 keys = console
 
 [formatters]
-keys = generic
+keys = generic, json
 
 [logger_root]
 level = WARN
@@ -109,7 +109,11 @@ qualname = sqlalchemy.engine
 class = StreamHandler
 args = (sys.stderr,)
 level = NOTSET
-formatter = generic
+formatter = json
+
+[formatter_json]
+format = %(asctime)s %(levelname)s %(name)s %(threadName)s %(message)s
+class = pythonjsonlogger.jsonlogger.JsonFormatter
 
 [formatter_generic]
 format = %(asctime)s %(levelname)-5.5s [%(name)s:%(lineno)s][%(threadName)s] %(message)s

datameta/api/files.py

@@ -119,12 +119,11 @@ def delete_files(request: Request) -> HTTPNoContent:
 
     # Log the deletions from db
     for user_uuid, file_uuid, storage_uri in deleted_files:
-        log.info(f"[DB_FILE][DELETE][user={user_uuid}][file={file_uuid}]")
-
+        log.info("File record deleted from the database.", extra={"user_uuid": user_uuid, "file_uuid": file_uuid})
     # Delete the files from storage
     for user_uuid, file_uuid, storage_uri in deleted_files:
         storage.rm(request, storage_uri)
-        log.info(f"[STORAGE][DELETE][user={user_uuid}][file={file_uuid}]")
+        log.info("File deleted from storage.", extra={"user_uuid": user_uuid, "file_uuid": file_uuid})
 
     return HTTPNoContent()
 
@@ -261,7 +260,7 @@ def update_file(request: Request) -> HTTPOk:
         except storage.ChecksumMismatchError:
             # Checksum of uploaded data does not match announcement
             raise HTTPConflict(json=None)  # 409
-        log.info(f"[STORAGE][FREEZE][user={db_file.user.uuid}][file={db_file.uuid}]")
+        log.info("Storage file frozen.", extra={"user_uuid": db_file.user.uuid, "file_uuid": db_file.uuid})
 
     return FileResponse(
             id                = resource.get_identifier(db_file),
@@ -317,10 +316,9 @@ def delete_file(request: Request) -> HTTPNoContent:
     # Commit transaction
     request.tm.commit()
     request.tm.begin()
-    log.info(f"[DB_FILE][DELETE][user={user_uuid}][file={file_uuid}]")
-
+    log.info("File record deleted from the database.", extra={"user_uuid": user_uuid, "file_uuid": file_uuid})
     # Delete the file in storage if exists
     storage.rm(request, storage_uri)
-    log.info(f"[STORAGE][DELETE][user={user_uuid}][file={file_uuid}]")
+    log.info("File deleted from storage.", extra={"user_uuid": user_uuid, "file_uuid": file_uuid})
 
     return HTTPNoContent()

datameta/api/register.py

@@ -153,8 +153,7 @@ def post(request):
             )
 
     if org_create:
-        log.info(f"REGISTRATION REQUEST [email='{req_email}', name='{name}', new_org='{org_new_name}']")
+        log.info("New registration request.", extra={"email": req_email, "name": name, "group": org_new_name, "is_new_group": True})
     else:
-        log.info(f"REGISTRATION REQUEST [email='{req_email}', name='{name}', group='{group.name}']")
-
+        log.info("New registration request.", extra={"email": req_email, "name": name, "group": group.name, "is_new_group": False})
     return HTTPNoContent()

datameta/api/ui/admin.py

@@ -53,7 +53,7 @@ def v_admin_put_request(request):
         else:
             raise SyntaxError()
     except Exception as e:
-        log.error(f"MALFORMED API REQUEST AT /api/ui/admin/request: {e}")
+        log.error("Malformed API request.", extra={"error": e})
         raise HTTPBadRequest()
 
     # Check if the request exists
@@ -113,8 +113,7 @@ def v_admin_put_request(request):
                     'token_url' : token_url
                     }
                 )
-        log.info(f"NEW USER '{new_user.email}' [GROUP '{new_user.group.name}'] CONFIRMED BY '{req_user.email}'")
-        log.info(f"NEW USER PWTOKEN URL '{token_url}'")
+        log.info("Registation request accepted.", extra={"email": new_user.email, "group": new_user.group.name, "admin_email": req_user.email})
     else:
         # Denote email and name before request deletion
         reg_req_email = reg_req.email
@@ -132,7 +131,7 @@ def v_admin_put_request(request):
                     'fullname' : reg_req_fullname,
                     }
                 )
-        log.info(f"REGISTRATION REQUEST BY '{reg_req_email}' REJECTED BY '{req_user.email}'")
+        log.info("Registation request rejected.", extra={"email": reg_req_email, "admin_email": req_user.email})
 
     return HTTPNoContent()
 

datameta/api/ui/convert.py

@@ -61,7 +61,7 @@ def convert_samplesheet(db, file_like_obj, filename, user):
         reader = get_samplesheet_reader(file_like_obj)
         submitted_metadata = reader(file_like_obj)
     except Exception as e:
-        log.info(f"submitted sample sheet '{filename}' triggered exception {e}")
+        log.info("Sample sheet conversion failed.", extra={"file_name": filename, "error": e})
         raise samplesheet.SampleSheetReadError("Unable to parse the sample sheet.")
 
     # Query column names that we expect to see in the sample sheet (intra-submission duplicates)
@@ -85,7 +85,7 @@ def convert_samplesheet(db, file_like_obj, filename, user):
         # string value is not possible through the convert API.
         return [ { mdname : None if not row[mdname] else formatted_mrec_value_str(row[mdname], metadata_datetimefmt[mdname]) for mdname in metadata_names } for _, row in submitted_metadata.iterrows() ]
     except Exception as e:
-        log.error(e)
+        log.error("Unexpected error during sample sheet conversion.", extra={"file_name": filename, "error": e})
         raise samplesheet.SampleSheetReadError("Unknown error")
 
 
@@ -113,5 +113,5 @@ def post(request: Request) -> HTTPOk:
     try:
         return convert_samplesheet(db, input_file.file, input_file.filename, auth_user)
     except samplesheet.SampleSheetReadError as e:
-        log.warning(f"Sample sheet '{input_file.filename}' could not be read: {e}")
+        log.warning("Unable to read sample sheet.", extra={"file_name": input_file.filename, "error": e})
         raise errors.get_validation_error(messages = [ str(e) ])

datameta/api/ui/forgot.py

@@ -13,8 +13,6 @@
 # limitations under the License.
 
 from pyramid.view import view_config
-from pyramid import threadlocal
-from pyramid.settings import asbool
 
 from ... import security, email
 from ...settings import get_setting
@@ -39,8 +37,7 @@ def send_forgot_token(request, db_token_obj, clear_token):
             }
         )
 
-    if asbool(threadlocal.get_current_registry().settings['datameta.logging.log_token_urls']):
-        log.debug(f"USER REQUESTED RECOVERY TOKEN: '{token_url}'")
+    log.debug("User requested recovery token.", extra={"clear_token": clear_token})
 
 
 @view_config(route_name='forgot_api', renderer='json')
@@ -60,10 +57,10 @@ def v_forgot_api(request):
         db_token_obj, clear_token = security.get_new_password_reset_token_from_email(db, req_email)
     except KeyError:
         # User not found
-        log.debug(f"DURING RECOVERY TOKEN REQUEST: USER COULD NOT BE RESOLVED FROM EMAIL: {req_email}")
+        log.debug("Recovery token request. User could not be resolved.", extra={"req_email": req_email})
     else:
         # Generate a new forgot token and send it to the user
         send_forgot_token(request, db_token_obj, clear_token)
-        log.debug(f"USER REQUESTED RECOVERY TOKEN: {clear_token}")
+        log.debug("User requested recovery token.", extra={"clear_token": clear_token})
 
     return { 'success' : True }

datameta/email/__init__.py

@@ -49,4 +49,4 @@ def send(recipients, subject, template, values, bcc=None, rec_header_only=False)
     try:
         __smtp.sendMessage(__smtp_from, recipients, subject, message, bcc=bcc, rec_header_only=rec_header_only)
     except Exception as e:
-        log.error(f"An error occurred when sending an email: {e}")
+        log.error("SMTP error.", extra={"error": e})

datameta/samplesheet.py

@@ -47,7 +47,7 @@ def datetime_iso_or_empty(x):
     try:
         return "" if pd.isna(x) else x.isoformat()
     except Exception as e:
-        log.error(f"Unexpected exception: {e}")
+        log.error("Failed to convert datetime.", extra={"error": e})
         return ""
 
 

datameta/security/__init__.py

@@ -176,11 +176,11 @@ def register_failed_login_attempt(db, user):
         for attempt in db.query(LoginAttempt).filter(LoginAttempt.user_id == user.id).all()
     )
 
-    log.warning(f"FAILED LOGIN ATTEMPT USER id={user.id} n={n_failed_logins} within one hour.")
+    log.warning("Failed login attempt.", extra={"user_id": user.id, "failed_logins_last_hour": n_failed_logins})
     if n_failed_logins >= max_allowed_failed_logins:
         db.query(User).filter(user.id == User.id).update({User.enabled: False})
         db.flush()
-        log.warning(f"BLOCKED USER id={user.id} enabled={user.enabled} reason={n_failed_logins} failed login attempts within one hour.")
+        log.warning("User blocked due to repeated failed login attempts.", extra={"user_id": user.id, "user_enabled": user.enabled, "failed_logins_last_hour": n_failed_logins})
 
     return None
 
@@ -192,7 +192,7 @@ def get_user_by_credentials(request, email: str, password: str):
     if user:
         if check_password_by_hash(password, user.pwhash):
             if not is_2fa_enabled():
-                log.warning(f"CLEARING FAILED LOGIN ATTEMPTS FOR gubc USER {user}")
+                log.warning("Clearing failed login attempts.", extra={"user_id": user.id, "credential": "password"})
                 user.login_attempts.clear()
             return user
 
@@ -247,7 +247,7 @@ def revalidate_user_token_based(request, token):
             request.tm.commit()
             request.tm.begin()
         else:
-            log.warning(f"CLEARING FAILED LOGIN ATTEMPTS FOR APIKEY.USER {user.id}")
+            log.warning("Clearing failed login attempts.", extra={"user_id": user.id, "credential": "api_key"})
             user.login_attempts.clear()
             return user
 
@@ -277,7 +277,7 @@ def revalidate_user_session_based(request):
     request.session['site_admin'] = user.site_admin
     request.session['group_admin'] = user.group_admin
 
-    log.warning(f"CLEARING FAILED LOGIN ATTEMPTS FOR USER {user}")
+    log.warning("Clearing failed login attempts.", extra={"user_id": user.id})
     user.login_attempts.clear()
     return user
 

datameta/settings.py

@@ -131,4 +131,4 @@ def includeme(config):
         for key, value in defaults.items():
             if key not in existing:
                 db.add(ApplicationSetting(key=key, **value))
-                log.info(f"No application setting found for '{key}'. Inserting default value.")
+                log.info("No application setting found, inserting default value", extra={"key": key})

datameta/siteid.py

@@ -28,13 +28,13 @@
     try:
         _prefix[entity] = threadlocal.get_current_registry().settings[f'datameta.site_id_prefix.{entity}']
     except Exception as e:
-        raise
-        log.warning(f"Site ID prefix for {entity} not found in configuration file ({e}).")
+        log.warning("Site ID prefix not found in configuration file", extra={"entity": entity, "error": e})
+        raise e
     try:
         _digits[entity] = int(threadlocal.get_current_registry().settings[f'datameta.site_id_digits.{entity}'])
     except Exception as e:
-        raise
-        log.warning(f"Site ID digits for {entity} not found in configuration file ({e}).")
+        log.warning("Site ID prefix not found in configuration file", extra={"entity": entity, "error": e})
+        raise e
 
 
 def generate(request, BaseClass):
@@ -44,6 +44,6 @@ def generate(request, BaseClass):
     for _ in range(10):
         new_id = prefix + str(random.randint(0, pow(10, digits))).rjust(digits, "0")
         if request.dbsession.query(BaseClass).filter(BaseClass.site_id == new_id).first():
-            log.warning(f"Site ID collision for {BaseClass.__tablename__}. Your ID space may be saturating.")
+            log.warning("Site ID collision, ID space may be saturating.", extra={"tablename": BaseClass.__tablename__})
         else:
             return new_id

datameta/storage.py

@@ -50,7 +50,7 @@ def rm(request, storage_path):
         else:
             raise NotImplementedError()
     else:
-        log.debug("DID NOT DELETE. DEMO MODE.")
+        log.debug("Did not delete, demo mode.")
 
 
 def get_local_storage_path(request, storage_uri):
@@ -99,9 +99,9 @@ def write_file(request, db_file, file):
         file.seek(0)
         with open(out_path, 'wb') as outfile:
             shutil.copyfileobj(file, outfile)
-        log.info(f"[STORAGE][NEWFILE][user={db_file.user.uuid}][file={db_file.uuid}]")
+        log.info("New file in storage.", extra={"user_uuid": db_file.user.uuid, "file_uuid": db_file.uuid})
     else:
-        log.info(f"[!!DEMOMODE!!][STORAGE][NEWFILE][user={db_file.user.uuid}][file={db_file.uuid}]")
+        log.info("Demomode. New file in storage.", extra={"user_uuid": db_file.user.uuid, "file_uuid": db_file.uuid})
 
 
 def _freeze_local(request, db_file):