Merge pull request #39 from ingenerator/1.x-log-request-memory

Improve request logging - memory usage & max user-agent length

Author: acoulton

CHANGELOG.md

@@ -1,5 +1,10 @@
 ### Unreleased
 
+### v1.14.0 (2021-11-19)
+
+* StackdriverApplicationLogger: limit length of user-agent string in request logs to a maximum of 500 bytes.
+* Now requires the `mbstring` PHP extension to be present.
+* StackdriverApplicationLogger: add the peak memory usage to the context info of the request logger (context.mem_mb).
 
 ### v1.13.0 (2021-11-04)
 

composer.json

@@ -16,6 +16,7 @@
   ],
   "require": {
     "ext-json": "*",
+    "ext-mbstring": "^7 || ~8.0.0",
     "ext-pdo": "^7 || ~8.0.0",
     "ext-sodium": "^7.4 || ~8.0.0",
     "php": "^7.4 || ~8.0.0",

src/Logging/StackdriverApplicationLogger.php

@@ -17,8 +17,10 @@
 use function http_response_code;
 use function is_callable;
 use function json_encode;
+use function mb_strcut;
 use function microtime;
 use function sprintf;
+use function strlen;
 use function strtoupper;
 use function substr;
 
@@ -377,14 +379,17 @@ public function logRequest(?array $server, ?float $request_start_time = NULL): v
                 'severity'            => strtoupper($this->getLogPriorityForHttpCode($http_code)),
                 self::PROP_INGEN_TYPE => 'rqst',
                 'httpRequest'         => $meta['context']['httpRequest'] ?? [],
+                'context' => [
+                    'mem_mb' => sprintf('%.2f',\memory_get_peak_usage() / 1_000_000),
+                ],
             ],
             $meta,
             [
                 'httpRequest' => [
                     // requestMethod, requestUrl, remoteIp are expected to come from metadata provider as they are
                     // shared with application log entry context
                     'status'    => $http_code,
-                    'userAgent' => $server['HTTP_USER_AGENT'] ?? NULL,
+                    'userAgent' => $this->truncate($server['HTTP_USER_AGENT'] ?? NULL, 500),
                     'latency'   => $this->calculateRequestLatency($request_start_time),
                 ],
             ]
@@ -395,6 +400,22 @@ public function logRequest(?array $server, ?float $request_start_time = NULL): v
         $this->writeLog($log_entry);
     }
 
+    private function truncate(?string $value, int $max_byte_length): ?string
+    {
+        if ($value === NULL) {
+            return NULL;
+        }
+
+        if (strlen($value) <= $max_byte_length) {
+            return $value;
+        }
+
+        // Use mb_strcut because we want to limit the byte size but keep a utf-8 valid string:
+        // * substr might split a utf8 character and cause an encoding error.
+        // * mb_substr could allow a much longer byte length if the string was entirely composed of unicode characters.
+        return trim(mb_strcut($value, 0, $max_byte_length)).'…';
+    }
+
     protected function getLogPriorityForHttpCode(string $code): string
     {
         $map = [

test/unit/Logging/StackdriverApplicationLoggerTest.php

@@ -543,10 +543,8 @@ public function test_its_request_logger_logs_custom_metadata()
         $logger = $this->newSubject();
         $logger->logRequest([]);
         $entry = $this->assertLoggedOneLine();
-        $this->assertSame(
-            ['user' => 'john@do.com'],
-            $entry['context']
-        );
+        $this->assertSame(['mem_mb', 'user'], array_keys($entry['context']));
+        $this->assertSame('john@do.com', $entry['context']['user']);
     }
 
     public function test_its_request_logger_logs_http_response_code()
@@ -571,6 +569,16 @@ public function test_its_request_logger_logs_user_agent_from_global_array($serve
         $this->assertSame($expect, $entry['httpRequest']['userAgent']);
     }
 
+    public function test_its_request_logger_truncates_long_user_agents()
+    {
+        $ua_val = 'abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 long ※ note the utf8 safe truncation and trimming';
+        $expect = 'abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 abcdefghijklmnopqrstuvwxyz 1234567890 long…';
+        $logger = $this->newSubject();
+        $logger->logRequest(['HTTP_USER_AGENT' => $ua_val]);
+        $entry = $this->assertLoggedOneLine();
+        $this->assertSame($expect, $entry['httpRequest']['userAgent']);
+    }
+
     public function test_its_request_logger_logs_latency_since_start_time_if_provided()
     {
         $start  = \microtime(TRUE);
@@ -591,6 +599,31 @@ public function test_its_request_logger_logs_null_latency_if_no_start_time()
         $this->assertNull($entry['httpRequest']['latency']);
     }
 
+    public function test_its_request_logger_logs_peak_memory_usage_in_mb()
+    {
+        $logger      = $this->newSubject();
+        $peak_before = \memory_get_peak_usage();
+        $logger->logRequest([]);
+        $peak_after = \memory_get_peak_usage();
+        $entry      = $this->assertLoggedOneLine();
+        $this->assertIsString(
+            $entry['context']['mem_mb'],
+            'Encode memory as string to avoid risk of JSON serialization precision increasing payload size'
+        );
+        $this->assertMatchesRegularExpression('/^\d+\.\d{2}$/', $entry['context']['mem_mb']);
+
+        $logged_meg = $entry['context']['mem_mb'];
+        // Sanity check that it's definitely logging in megabytes. This is tricky as there's no way to stub the actual
+        // memory usage that the logger saw - but it must be no less than the value before we called it, and no more
+        // than the value immediately after we called it
+        $this->assertTrue(
+            ($logged_meg >= round($peak_before / 1000 / 1000, 2))
+            and
+            ($logged_meg <= round($peak_after / 1000 / 1000, 2)),
+            "Logged value should be within $peak_before and $peak_after and in the right units"
+        );
+    }
+
     /**
      * @return array
      */