Skip to content

Commit 3cc9632

Browse files
daniel-sanchedaniel-sanche
authored
fix: structured log handler formatting issues (#319)
1 parent 8d4ba09 commit 3cc9632

4 files changed

Lines changed: 120 additions & 13 deletions

File tree

‎packages/google-cloud-logging/google/cloud/logging_v2/handlers/structured_log.py‎

Lines changed: 12 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -14,13 +14,13 @@
1414

1515
"""Logging handler for printing formatted structured logs to standard output.
1616
"""
17-
17+
import json
1818
import logging.handlers
1919

2020
from google.cloud.logging_v2.handlers.handlers import CloudLoggingFilter
2121

2222
GCP_FORMAT = (
23-
'{"message": "%(_msg_str)s", '
23+
'{"message": %(_formatted_msg)s, '
2424
'"severity": "%(levelname)s", '
2525
'"logging.googleapis.com/labels": %(_labels_str)s, '
2626
'"logging.googleapis.com/trace": "%(_trace_str)s", '
@@ -50,7 +50,7 @@ def __init__(self, *, labels=None, stream=None, project_id=None):
5050
self.addFilter(log_filter)
5151

5252
# make logs appear in GCP structured logging format
53-
self.formatter = logging.Formatter(GCP_FORMAT)
53+
self._gcp_formatter = logging.Formatter(GCP_FORMAT)
5454

5555
def format(self, record):
5656
"""Format the message into structured log JSON.
@@ -59,6 +59,12 @@ def format(self, record):
5959
Returns:
6060
str: A JSON string formatted for GKE fluentd.
6161
"""
62-
63-
payload = self.formatter.format(record)
64-
return payload
62+
# let other formatters alter the message
63+
super_payload = None
64+
if record.msg:
65+
super_payload = super(StructuredLogHandler, self).format(record)
66+
# properly break any formatting in string to make it json safe
67+
record._formatted_msg = json.dumps(super_payload or "")
68+
# convert to GCP structred logging format
69+
gcp_payload = self._gcp_formatter.format(record)
70+
return gcp_payload

‎packages/google-cloud-logging/tests/unit/handlers/test_handlers.py‎

Lines changed: 53 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -291,7 +291,9 @@ def test_emit(self):
291291
)
292292
logname = "loggername"
293293
message = "hello world"
294-
record = logging.LogRecord(logname, logging, None, None, message, None, None)
294+
record = logging.LogRecord(
295+
logname, logging.INFO, None, None, message, None, None
296+
)
295297
handler.handle(record)
296298
self.assertEqual(
297299
handler.transport.send_called_with,
@@ -315,7 +317,9 @@ def test_emit_manual_field_override(self):
315317
)
316318
logname = "loggername"
317319
message = "hello world"
318-
record = logging.LogRecord(logname, logging, None, None, message, None, None)
320+
record = logging.LogRecord(
321+
logname, logging.INFO, None, None, message, None, None
322+
)
319323
# set attributes manually
320324
expected_trace = "123"
321325
setattr(record, "trace", expected_trace)
@@ -350,6 +354,53 @@ def test_emit_manual_field_override(self):
350354
),
351355
)
352356

357+
def test_emit_with_custom_formatter(self):
358+
"""
359+
Handler should respect custom formatters attached
360+
"""
361+
from google.cloud.logging_v2.logger import _GLOBAL_RESOURCE
362+
363+
client = _Client(self.PROJECT)
364+
handler = self._make_one(
365+
client, transport=_Transport, resource=_GLOBAL_RESOURCE,
366+
)
367+
logFormatter = logging.Formatter(fmt="%(name)s :: %(levelname)s :: %(message)s")
368+
handler.setFormatter(logFormatter)
369+
message = "test"
370+
expected_result = "logname :: INFO :: test"
371+
record = logging.LogRecord(
372+
"logname", logging.INFO, None, None, message, None, None
373+
)
374+
handler.handle(record)
375+
376+
self.assertEqual(
377+
handler.transport.send_called_with,
378+
(record, expected_result, _GLOBAL_RESOURCE, None, None, None, None, None,),
379+
)
380+
381+
def test_format_with_arguments(self):
382+
"""
383+
Handler should support format string arguments
384+
"""
385+
from google.cloud.logging_v2.logger import _GLOBAL_RESOURCE
386+
387+
client = _Client(self.PROJECT)
388+
handler = self._make_one(
389+
client, transport=_Transport, resource=_GLOBAL_RESOURCE,
390+
)
391+
message = "name: %s"
392+
name_arg = "Daniel"
393+
expected_result = "name: Daniel"
394+
record = logging.LogRecord(
395+
None, logging.INFO, None, None, message, name_arg, None
396+
)
397+
handler.handle(record)
398+
399+
self.assertEqual(
400+
handler.transport.send_called_with,
401+
(record, expected_result, _GLOBAL_RESOURCE, None, None, None, None, None,),
402+
)
403+
353404

354405
class TestSetupLogging(unittest.TestCase):
355406
def _call_fut(self, handler, excludes=None):

‎packages/google-cloud-logging/tests/unit/handlers/test_structured_log.py‎

Lines changed: 54 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -109,17 +109,67 @@ def test_format_with_quotes(self):
109109
When logging a message containing quotes, escape chars should be added
110110
"""
111111
import logging
112-
import json
113112

114113
handler = self._make_one()
115114
message = '"test"'
116115
expected_result = '\\"test\\"'
117116
record = logging.LogRecord(None, logging.INFO, None, None, message, None, None,)
118117
record.created = None
119118
handler.filter(record)
120-
result = json.loads(handler.format(record))
121-
result["message"] = expected_result
122-
self.assertEqual(result["message"], expected_result)
119+
result = handler.format(record)
120+
self.assertIn(expected_result, result)
121+
122+
def test_format_with_line_break(self):
123+
"""
124+
When logging a message containing \n, it should be properly escaped
125+
"""
126+
import logging
127+
128+
handler = self._make_one()
129+
message = "test\ntest"
130+
expected_result = "test\\ntest"
131+
record = logging.LogRecord(None, logging.INFO, None, None, message, None, None,)
132+
record.created = None
133+
handler.filter(record)
134+
result = handler.format(record)
135+
self.assertIn(expected_result, result)
136+
137+
def test_format_with_custom_formatter(self):
138+
"""
139+
Handler should respect custom formatters attached
140+
"""
141+
import logging
142+
143+
handler = self._make_one()
144+
logFormatter = logging.Formatter(fmt="%(name)s :: %(levelname)s :: %(message)s")
145+
handler.setFormatter(logFormatter)
146+
message = "test"
147+
expected_result = "logname :: INFO :: test"
148+
record = logging.LogRecord(
149+
"logname", logging.INFO, None, None, message, None, None,
150+
)
151+
record.created = None
152+
handler.filter(record)
153+
result = handler.format(record)
154+
self.assertIn(expected_result, result)
155+
156+
def test_format_with_arguments(self):
157+
"""
158+
Handler should support format string arguments
159+
"""
160+
import logging
161+
162+
handler = self._make_one()
163+
message = "name: %s"
164+
name_arg = "Daniel"
165+
expected_result = "name: Daniel"
166+
record = logging.LogRecord(
167+
None, logging.INFO, None, None, message, name_arg, None,
168+
)
169+
record.created = None
170+
handler.filter(record)
171+
result = handler.format(record)
172+
self.assertIn(expected_result, result)
123173

124174
def test_format_with_request(self):
125175
import logging

‎tests/environment‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1 +1 @@
1-
Subproject commit 30d6a80838a1cae6fb3945f41f3e1d90e815c0c9
1+
Subproject commit a0af8d102a3c711cdff0dd12e01c8bfd357b7a83

0 commit comments

Comments
 (0)