feat: record source locations (#254)

Author: daniel-sanche

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

@@ -126,6 +126,8 @@ def __init__(
         self.project_id = client.project
         self.resource = resource
         self.labels = labels
+        # add extra keys to log record
+        self.addFilter(CloudLoggingFilter(self.project_id))
 
     def emit(self, record):
         """Actually log the specified logging record.
@@ -138,25 +140,31 @@ def emit(self, record):
             record (logging.LogRecord): The record to be logged.
         """
         message = super(CloudLoggingHandler, self).format(record)
-        trace_id = getattr(record, "trace", None)
-        span_id = getattr(record, "span_id", None)
-        http_request = getattr(record, "http_request", None)
-        resource = getattr(record, "resource", self.resource)
         user_labels = getattr(record, "labels", {})
         # merge labels
         total_labels = self.labels if self.labels is not None else {}
         total_labels.update(user_labels)
         if len(total_labels) == 0:
             total_labels = None
+        # create source location object
+        if record.lineno and record.funcName and record.pathname:
+            source_location = {
+                "file": record.pathname,
+                "line": str(record.lineno),
+                "function": record.funcName,
+            }
+        else:
+            source_location = None
         # send off request
         self.transport.send(
             record,
             message,
-            resource=resource,
+            resource=getattr(record, "resource", self.resource),
             labels=(total_labels if total_labels else None),
-            trace=trace_id,
-            span_id=span_id,
-            http_request=http_request,
+            trace=(record.trace if record.trace else None),
+            span_id=getattr(record, "span_id", None),
+            http_request=(record.http_request if record.http_request else None),
+            source_location=source_location,
         )
 
 

packages/google-cloud-logging/tests/environment/deployable/python/snippets.py

@@ -53,6 +53,12 @@ def pylogging(log_text="pylogging", severity="WARNING", **kwargs):
     else:
         logging.critical(log_text)
 
+def pylogging_flask(log_text="pylogging_flask", path="/", base_url="http://google", agent="Chrome", trace="123", **kwargs):
+    import flask
+    app = flask.Flask(__name__)
+    with app.test_request_context(
+            path, base_url, headers={'User-Agent': agent, "X_CLOUD_TRACE_CONTEXT": trace}):
+        logging.info(log_text)
 
 def print_handlers(**kwargs):
     root_logger = logging.getLogger()

packages/google-cloud-logging/tests/environment/tests/common/common.py

@@ -70,13 +70,14 @@ def _trigger(self, function, **kwargs):
         args_str = ",".join([f'{k}="{v}"' for k, v in kwargs.items()])
         self._script.run_command(Command.Trigger, [function, args_str])
 
-    @RetryErrors(exception=(LogsNotFound, RpcError), delay=2)
+    @RetryErrors(exception=(LogsNotFound, RpcError), delay=2, max_tries=2)
     def trigger_and_retrieve(
         self, log_text, function="simplelog", append_uuid=True, max_tries=6, **kwargs
     ):
         if append_uuid:
             log_text = f"{log_text} {uuid.uuid1()}"
         self._trigger(function, log_text=log_text, **kwargs)
+        sleep(2)
         filter_str = self._add_time_condition_to_filter(log_text)
         # give the command time to be received
         tries = 0
@@ -86,7 +87,7 @@ def trigger_and_retrieve(
                 log_list = self._get_logs(filter_str)
                 return log_list
             except (LogsNotFound, RpcError) as e:
-                sleep(10)
+                sleep(5)
                 tries += 1
         # log not found
         raise LogsNotFound

packages/google-cloud-logging/tests/environment/tests/common/python.py

@@ -61,3 +61,50 @@ def test_severity_pylogging(self):
             found_severity = log_list[-1].severity
 
             self.assertEqual(found_severity.lower(), severity.lower())
+
+    def test_source_location_pylogging(self):
+        if self.environment == "kubernetes" or "appengine" in self.environment:
+            # disable these tests on environments with custom handlers
+            # todo: enable in v3.0.0
+            return
+        log_text = f"{inspect.currentframe().f_code.co_name}"
+        log_list = self.trigger_and_retrieve(log_text, function="pylogging")
+        found_source = log_list[-1].source_location
+
+        self.assertIsNotNone(found_source)
+        self.assertIsNotNone(found_source['file'])
+        self.assertIsNotNone(found_source['function'])
+        self.assertIsNotNone(found_source['line'])
+        self.assertIn("snippets.py", found_source['file'])
+        self.assertEqual(found_source['function'], "pylogging")
+        self.assertTrue(int(found_source['line']) > 0)
+
+    def test_flask_http_request_pylogging(self):
+        if self.environment == "kubernetes" or "appengine" in self.environment:
+            # disable these tests on environments with custom handlers
+            # todo: enable in v3.0.0
+            return
+        log_text = f"{inspect.currentframe().f_code.co_name}"
+
+        expected_agent = "test-agent"
+        expected_base_url = "http://test"
+        expected_path = "/pylogging"
+        expected_trace = "123"
+
+        log_list = self.trigger_and_retrieve(log_text, function="pylogging_flask",
+                path=expected_path, trace=expected_trace, base_url=expected_base_url, agent=expected_agent)
+        found_request = log_list[-1].http_request
+
+        self.assertIsNotNone(found_request)
+        self.assertIsNotNone(found_request['requestMethod'])
+        self.assertIsNotNone(found_request['requestUrl'])
+        self.assertIsNotNone(found_request['userAgent'])
+        self.assertIsNotNone(found_request['protocol'])
+        self.assertEqual(found_request['requestMethod'], 'GET')
+        self.assertEqual(found_request['requestUrl'], expected_base_url + expected_path)
+        self.assertEqual(found_request['userAgent'], expected_agent)
+        self.assertEqual(found_request['protocol'], 'HTTP/1.1')
+
+        found_trace = log_list[-1].trace
+        self.assertIsNotNone(found_trace)
+        self.assertIn("projects/", found_trace)

packages/google-cloud-logging/tests/environment/tests/python/test_cloudrun.py

@@ -37,3 +37,24 @@ class TestCloudRun(Common, CommonPython, unittest.TestCase):
         "location",
         "configuration_name",
     ]
+
+    def test_default_http_request_pylogging(self):
+        """
+        Cloud Run should automatically attach http request information
+        """
+        log_text = f"{inspect.currentframe().f_code.co_name}"
+
+        log_list = self.trigger_and_retrieve(log_text, function="pylogging")
+        found_request = log_list[-1].http_request
+        found_trace = log_list[-1].trace
+
+        self.assertIsNotNone(found_request)
+        self.assertIsNotNone(found_request['requestMethod'])
+        self.assertIsNotNone(found_request['requestUrl'])
+        self.assertIsNotNone(found_request['userAgent'])
+        self.assertIsNotNone(found_request['protocol'])
+        self.assertEqual(found_request['requestMethod'], 'POST')
+        self.assertEqual(found_request['protocol'], 'HTTP/1.1')
+
+        self.assertIsNotNone(found_trace)
+        self.assertIn("projects/", found_trace)

packages/google-cloud-logging/tests/environment/tests/python/test_functions.py

@@ -21,11 +21,31 @@
 from ..common.common import Common
 from ..common.python import CommonPython
 
-
 class TestCloudFunctions(Common, CommonPython, unittest.TestCase):
 
     environment = "functions"
     language = "python"
 
     monitored_resource_name = "cloud_function"
     monitored_resource_labels = ["region", "function_name"]
+
+    def test_default_http_request_pylogging(self):
+        """
+        Cloud Functions should automatically attach http request information
+        """
+        log_text = f"{inspect.currentframe().f_code.co_name}"
+
+        log_list = self.trigger_and_retrieve(log_text, function="pylogging")
+        found_request = log_list[-1].http_request
+        found_trace = log_list[-1].trace
+
+        self.assertIsNotNone(found_request)
+        self.assertIsNotNone(found_request['requestMethod'])
+        self.assertIsNotNone(found_request['requestUrl'])
+        self.assertIsNotNone(found_request['userAgent'])
+        self.assertIsNotNone(found_request['protocol'])
+        self.assertEqual(found_request['requestMethod'], 'POST')
+        self.assertEqual(found_request['protocol'], 'HTTP/1.1')
+
+        self.assertIsNotNone(found_trace)
+        self.assertIn("projects/", found_trace)

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

@@ -257,11 +257,11 @@ def test_emit(self):
         logname = "loggername"
         message = "hello world"
         record = logging.LogRecord(logname, logging, None, None, message, None, None)
+        handler.filter(record)
         handler.emit(record)
-
         self.assertEqual(
             handler.transport.send_called_with,
-            (record, message, _GLOBAL_RESOURCE, None, None, None, None),
+            (record, message, _GLOBAL_RESOURCE, None, None, None, None, None),
         )
 
     def test_emit_manual_field_override(self):
@@ -286,6 +286,15 @@ def test_emit_manual_field_override(self):
         setattr(record, "resource", expected_resource)
         expected_labels = {"test-label": "manual"}
         setattr(record, "labels", expected_labels)
+        expected_source = {
+            "file": "test-file",
+            "line": str(1),
+            "function": "test-func",
+        }
+        setattr(record, "lineno", int(expected_source["line"]))
+        setattr(record, "funcName", expected_source["function"])
+        setattr(record, "pathname", expected_source["file"])
+        handler.filter(record)
         handler.emit(record)
 
         self.assertEqual(
@@ -298,6 +307,7 @@ def test_emit_manual_field_override(self):
                 expected_trace,
                 expected_span,
                 expected_http,
+                expected_source,
             ),
         )
 
@@ -413,6 +423,7 @@ def send(
         trace=None,
         span_id=None,
         http_request=None,
+        source_location=None,
     ):
         self.send_called_with = (
             record,
@@ -422,4 +433,5 @@ def send(
             trace,
             span_id,
             http_request,
+            source_location,
         )

tests/environment

@@ -1 +1 @@
-Subproject commit f0e2726579ef96f8e6b3ceaed8145d2bfbfa32bc
+Subproject commit 273db6c60b8f39fa5092b01730ff4d2dffcca17e