Issue #2561: format logs as json (on getgov-ms) #2705

Matt-Spence · 2024-09-04T18:29:08Z

Ticket

Resolves Alter log formatting so that multiline messages and tracebacks display on a single line #2561

Changes

Adds two new logger formatters, one for normal logs and one for django server logs
swaps out the old server and verbose formatters for the new json and json.server formatters.
Added a dummy exception that triggers when saving anything on a domain request, just to make it easy to test.

Context for reviewers

Right now logs are janky in that multi-line logs get read into kibana as a new log for each new line, which is especially painful for tracebacks. This PR fixes that by formatting all logs as json objects, which kibana is configured to parse correctly.

Setup

Code Review Verification Steps

Open getgov-ms and do some stuff that will trigger logs, especially but not limited to saving a few elements of a domain request (a fake error log has been placed there for review purposes).
go to logs.fr.cloud.gov and filter by space for ms plus whatever log type you want to see
observe that logs are still functioning properly
Filter for error logs and check that tracebacks are printing as a singular message
Make sure Matthew removes the fake exception so that it doesn't accidentally end up in prod :)

As the original developer, I have

Satisfied acceptance criteria and met development standards

Met the acceptance criteria, or will meet them in a subsequent PR
Created/modified automated tests
Added at least 2 developers as PR reviewers (only 1 will need to approve)
Messaged on Slack or in standup to notify the team that a PR is ready for review
Changes to “how we do things” are documented in READMEs and or onboarding guide
If any model was updated to modify/add/delete columns, makemigrations was ran and the associated migrations file has been commited.

Ensured code standards are met (Original Developer)

All new functions and methods are commented using plain language
Did dependency updates in Pipfile also get changed in requirements.txt?
Interactions with external systems are wrapped in try/except
Error handling exists for unusual or missing values

Validated user-facing changes (if applicable)

New pages have been added to .pa11yci file so that they will be tested with our automated accessibility testing
Checked keyboard navigability
Tested general usability, landmarks, page header structure, and links with a screen reader (such as Voiceover or ANDI)
Add at least 1 designer as PR reviewer

As a code reviewer, I have

Reviewed, tested, and left feedback about the changes

Pulled this branch locally and tested it
Reviewed this code and left comments
Checked that all code is adequately covered by tests
Made it clear which comments need to be addressed before this work is merged
If any model was updated to modify/add/delete columns, makemigrations was ran and the associated migrations file has been commited.

Ensured code standards are met (Code reviewer)

All new functions and methods are commented using plain language
Interactions with external systems are wrapped in try/except
Error handling exists for unusual or missing values
(Rarely needed) Did dependency updates in Pipfile also get changed in requirements.txt?

Validated user-facing changes as a developer

Note: Multiple code reviewers can share the checklists above, a second reviewers should not make a duplicate checklist

As a designer reviewer, I have

Verified that the changes match the design intention

Checked that the design translated visually
Checked behavior
Checked different states (empty, one, some, error)
Checked for landmarks, page heading structure, and links
Tried to break the intended flow

Validated user-facing changes as a designer

Checked keyboard navigability
Tested general usability, landmarks, page header structure, and links with a screen reader (such as Voiceover or ANDI)
Tested with multiple browsers (check off which ones were used)
- Chrome
- Microsoft Edge
- FireFox
- Safari
(Rarely needed) Tested as both an analyst and applicant user

Screenshots

github-actions · 2024-09-04T19:09:53Z

🥳 Successfully deployed to developer sandbox ms.

github-actions · 2024-09-04T20:33:29Z

🥳 Successfully deployed to developer sandbox ms.

github-actions · 2024-09-04T20:47:25Z

🥳 Successfully deployed to developer sandbox ms.

github-actions · 2024-09-04T20:56:39Z

🥳 Successfully deployed to developer sandbox ms.

github-actions · 2024-09-04T21:02:59Z

🥳 Successfully deployed to developer sandbox ms.

zandercymatics · 2024-09-09T20:07:43Z

@Matt-Spence FYI: Looks like the linting check is failing on this one

zandercymatics

Great work on this, very elegant.

I have one comment just regarding local logging (for local dev). Interested in your thoughts on it!

zandercymatics · 2024-09-09T20:11:53Z

src/registrar/config/settings.py

+class JsonFormatter(logging.Formatter):
+    def __init__(self):
+        super().__init__(datefmt="%d/%b/%Y %H:%M:%S")
+
+    def format(self, record):
+        log_record = {
+            "timestamp": self.formatTime(record, self.datefmt),
+            "level": record.levelname,
+            "name": record.name,
+            "lineno": record.lineno,
+            "message": record.getMessage(),
+        }
+        return json.dumps(log_record)
+
+class JsonServerFormatter(ServerFormatter):
+    def format(self, record):
+        formatted_record = super().format(record)
+        log_entry = {
+            "server_time": record.server_time,
+            "level": record.levelname,
+            "message": formatted_record
+        }
+        return json.dumps(log_entry)


(Q) Whats the difference between JsonServerFormatter and JsonFormatter?

JsonServerFormatter inherits from ServerFormatter which provides access to fields like record.server_time as well as providing messages based on the error code. In practice I don't think it makes all that much difference, but I wanted to keep things in line with how they were done previously, so I split it out into two formatters.

That makes sense!

zandercymatics · 2024-09-09T20:12:14Z

src/registrar/config/settings.py

@@ -445,6 +448,30 @@
 #   logger.error("Can't do this important task. Something is very wrong.")
 #   logger.critical("Going to crash now.")

+class JsonFormatter(logging.Formatter):


Can you add some brief class comments to both of these?

zandercymatics · 2024-09-09T21:21:12Z

src/registrar/config/settings.py

+class JsonFormatter(logging.Formatter):
+    def __init__(self):
+        super().__init__(datefmt="%d/%b/%Y %H:%M:%S")
+
+    def format(self, record):
+        log_record = {
+            "timestamp": self.formatTime(record, self.datefmt),
+            "level": record.levelname,
+            "name": record.name,
+            "lineno": record.lineno,
+            "message": record.getMessage(),
+        }
+        return json.dumps(log_record)


Personally, I think this level of detail for running the app locally may be a bit much - but I am in total agreement with running this on the server. Just making a guess - but I'd assume that is the distinction between JsonFormatter vs JsonServerFormatter right?

Not at all blocking though if this is the requirement for both. This just makes reading logs harder during local dev for me, though it may just be because messages is the last item in this array

@Matt-Spence / @abroddrick What do you guys think? Personally I am for keeping our old logging in console, but outputting the json for JsonServerFormatter

I think this is a fair point, there's no requirement to use JSON in console and looking at it I don't think it's worth it. Plus, using the old console logger eliminates the need for the jsonFormatter which is a nice simplification. I'll go ahead and revert this.

zandercymatics · 2024-09-09T21:23:59Z

src/registrar/models/domain_request.py

+        try:
+            raise Exception("TEST TEST TEST")
+        except Exception:
+            logger.error(traceback.format_exc())


Remember to remove this before merging!

github-actions · 2024-09-11T15:39:14Z

🥳 Successfully deployed to developer sandbox ms.

github-actions · 2024-09-11T15:46:49Z

🥳 Successfully deployed to developer sandbox ms.

github-actions · 2024-09-11T15:53:56Z

🥳 Successfully deployed to developer sandbox ms.

github-actions · 2024-09-11T16:01:28Z

🥳 Successfully deployed to developer sandbox ms.

github-actions · 2024-09-11T18:15:03Z

🥳 Successfully deployed to developer sandbox ms.

github-actions · 2024-09-11T18:38:44Z

🥳 Successfully deployed to developer sandbox ms.

github-actions · 2024-09-12T15:26:29Z

🥳 Successfully deployed to developer sandbox ms.

github-actions · 2024-09-12T17:59:41Z

🥳 Successfully deployed to developer sandbox ms.

Matt-Spence added 2 commits September 4, 2024 12:37

initial stab at a new json formatter

7a77cb8

fix imports

e2fde1f

Matt-Spence requested a review from abroddrick as a code owner September 4, 2024 18:29

Matt-Spence changed the title ~~[WIP] format logs as json~~ [WIP] Issue #2561: format logs as json Sep 4, 2024

temp: add error message to test logs

afd941e

more temp changes

a61e8a1

moar testing!!!

d9898e3

forgot parentheses :(

bdec43e

Matt-Spence changed the title ~~[WIP] Issue #2561: format logs as json~~ Issue #2561: format logs as json (on getgov-ms) Sep 4, 2024

zandercymatics approved these changes Sep 9, 2024

View reviewed changes

zandercymatics self-assigned this Sep 9, 2024

Don't use json locally, plus review changes

eb3cb1e

linter fixes

ed4eeb4

Matt-Spence added 2 commits September 11, 2024 10:49

remove test log

0488b45

remove unused import

635d848

conditionally set log format

180a024

linter errors

d33f9ae

Remove type checking that was causing linter issues

519ca82

linter error fixes

529178c

Matt-Spence merged commit 00e784e into main Sep 12, 2024
10 checks passed

Matt-Spence deleted the ms/2561-alter-log-format branch September 12, 2024 18:02

zandercymatics mentioned this pull request Nov 25, 2024

Make log output on sandboxes human readable #3125

Open

2 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Issue #2561: format logs as json (on getgov-ms) #2705

Issue #2561: format logs as json (on getgov-ms) #2705

Matt-Spence commented Sep 4, 2024 •

edited by h-m-f-t

Loading

github-actions bot commented Sep 4, 2024

github-actions bot commented Sep 4, 2024

github-actions bot commented Sep 4, 2024

github-actions bot commented Sep 4, 2024

github-actions bot commented Sep 4, 2024

zandercymatics commented Sep 9, 2024

zandercymatics left a comment

zandercymatics Sep 9, 2024

Matt-Spence Sep 11, 2024

zandercymatics Sep 11, 2024

zandercymatics Sep 9, 2024

Matt-Spence Sep 11, 2024

zandercymatics Sep 11, 2024

zandercymatics Sep 9, 2024

zandercymatics Sep 9, 2024

Matt-Spence Sep 11, 2024 •

edited

Loading

zandercymatics Sep 9, 2024

github-actions bot commented Sep 11, 2024

github-actions bot commented Sep 11, 2024

github-actions bot commented Sep 11, 2024

github-actions bot commented Sep 11, 2024

github-actions bot commented Sep 11, 2024

github-actions bot commented Sep 11, 2024

github-actions bot commented Sep 12, 2024

github-actions bot commented Sep 12, 2024

Issue #2561: format logs as json (on getgov-ms) #2705

Issue #2561: format logs as json (on getgov-ms) #2705

Conversation

Matt-Spence commented Sep 4, 2024 • edited by h-m-f-t Loading

Ticket

Changes

Context for reviewers

Setup

Code Review Verification Steps

As the original developer, I have

Satisfied acceptance criteria and met development standards

Ensured code standards are met (Original Developer)

Validated user-facing changes (if applicable)

As a code reviewer, I have

Reviewed, tested, and left feedback about the changes

Ensured code standards are met (Code reviewer)

Validated user-facing changes as a developer

As a designer reviewer, I have

Verified that the changes match the design intention

Validated user-facing changes as a designer

Screenshots

github-actions bot commented Sep 4, 2024

github-actions bot commented Sep 4, 2024

github-actions bot commented Sep 4, 2024

github-actions bot commented Sep 4, 2024

github-actions bot commented Sep 4, 2024

zandercymatics commented Sep 9, 2024

zandercymatics left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Matt-Spence Sep 11, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

github-actions bot commented Sep 11, 2024

github-actions bot commented Sep 11, 2024

github-actions bot commented Sep 11, 2024

github-actions bot commented Sep 11, 2024

github-actions bot commented Sep 11, 2024

github-actions bot commented Sep 11, 2024

github-actions bot commented Sep 12, 2024

github-actions bot commented Sep 12, 2024

Matt-Spence commented Sep 4, 2024 •

edited by h-m-f-t

Loading

Matt-Spence Sep 11, 2024 •

edited

Loading