diff --git a/src/Events/Request/Request.php b/src/Events/Request/Request.php index a1b477c3..a3e27a66 100644 --- a/src/Events/Request/Request.php +++ b/src/Events/Request/Request.php @@ -4,6 +4,7 @@ namespace Scoutapm\Events\Request; +use DateInterval; use Exception; use Scoutapm\Connector\Command; use Scoutapm\Connector\CommandWithChildren; @@ -81,6 +82,41 @@ private function determineRequestPathFromServerGlobal() : string return '/'; } + /** + * Convert an ambiguous float timestamp that could be in nanoseconds, microseconds, milliseconds, or seconds to + * nanoseconds. Return 0.0 for values in the more than 10 years ago. + * + * @throws Exception + */ + private function convertAmbiguousTimestampToSeconds(float $timestamp, float $currentTimestamp) : float + { + $tenYearsAgo = Timer::utcDateTimeFromFloatTimestamp($currentTimestamp) + ->sub(new DateInterval('P10Y')); + + $cutoffTimestamp = (float) $tenYearsAgo + ->setDate((int) $tenYearsAgo->format('Y'), 1, 1) + ->format('U.u'); + + if ($timestamp > ($cutoffTimestamp * 1000000000.0)) { + return $timestamp / 1000000000; + } + + if ($timestamp > ($cutoffTimestamp * 1000000.0)) { + return $timestamp / 1000000; + } + + if ($timestamp > ($cutoffTimestamp * 1000.0)) { + return $timestamp / 1000.0; + } + + if ($timestamp > $cutoffTimestamp) { + return $timestamp; + } + + return 0.0; + } + + /** @throws Exception */ private function tagRequestIfRequestQueueTimeHeaderExists(float $currentTimeInSeconds) : void { $headers = FetchRequestHeaders::fromServerGlobal(); @@ -96,8 +132,11 @@ private function tagRequestIfRequestQueueTimeHeaderExists(float $currentTimeInSe $headerValue = substr($headerValue, 2); } - // Header comes in as milliseconds, so divide by 1,000 to get value in seconds - $headerValueInSeconds = (float) $headerValue / 1000; + $headerValueInSeconds = $this->convertAmbiguousTimestampToSeconds((float) $headerValue, $currentTimeInSeconds); + + if ($headerValueInSeconds === 0.0) { + continue; + } // Time tags should be in nanoseconds, so multiply seconds by 1e9 (1,000,000,000) $this->tag( diff --git a/src/Helper/Timer.php b/src/Helper/Timer.php index 8291a3eb..ae925dee 100644 --- a/src/Helper/Timer.php +++ b/src/Helper/Timer.php @@ -4,7 +4,7 @@ namespace Scoutapm\Helper; -use DateTime; +use DateTimeImmutable; use DateTimeZone; use function microtime; use function sprintf; @@ -42,6 +42,15 @@ public function stop(?float $override = null) : void $this->stop = $override ?? microtime(true); } + public static function utcDateTimeFromFloatTimestamp(float $timestamp) : DateTimeImmutable + { + return DateTimeImmutable::createFromFormat( + self::MICROTIME_FLOAT_FORMAT, + sprintf(self::FORMAT_FLOAT_TO_6_DECIMAL_PLACES, $timestamp), + new DateTimeZone('UTC') + ); + } + /** * Formats the stop time as a timestamp suitable for sending to CoreAgent */ @@ -51,13 +60,8 @@ public function getStop() : ?string return null; } - $timestamp = DateTime::createFromFormat( - self::MICROTIME_FLOAT_FORMAT, - sprintf(self::FORMAT_FLOAT_TO_6_DECIMAL_PLACES, $this->stop), - new DateTimeZone('UTC') - ); - - return $timestamp->format(self::FORMAT_FOR_CORE_AGENT); + return self::utcDateTimeFromFloatTimestamp($this->stop) + ->format(self::FORMAT_FOR_CORE_AGENT); } /** @@ -65,13 +69,8 @@ public function getStop() : ?string */ public function getStart() : ?string { - $timestamp = DateTime::createFromFormat( - self::MICROTIME_FLOAT_FORMAT, - sprintf(self::FORMAT_FLOAT_TO_6_DECIMAL_PLACES, $this->start), - new DateTimeZone('UTC') - ); - - return $timestamp->format(self::FORMAT_FOR_CORE_AGENT); + return self::utcDateTimeFromFloatTimestamp($this->start) + ->format(self::FORMAT_FOR_CORE_AGENT); } public function getStartAsMicrotime() : float diff --git a/tests/Unit/Events/Request/RequestTest.php b/tests/Unit/Events/Request/RequestTest.php index 06046982..a1013380 100644 --- a/tests/Unit/Events/Request/RequestTest.php +++ b/tests/Unit/Events/Request/RequestTest.php @@ -14,12 +14,15 @@ use function json_encode; use function next; use function reset; +use function sprintf; use function str_repeat; use function time; /** @covers \Scoutapm\Events\Request\Request */ final class RequestTest extends TestCase { + private const FIXED_POINT_UNIX_EPOCH_SECONDS = 1000000000.0; + public function testCanBeInitialized() : void { $request = new Request(); @@ -165,31 +168,31 @@ public function queueTimeRequestHeadersProvider() : array return [ 'requestStartMilliseconds' => [ 'headerName' => 'HTTP_X_REQUEST_START', - 'headerValue' => '2', - 'currentTimeSeconds' => 0.0, - 'requestStartTimeSeconds' => 0.005, - 'expectedQueueTimeNanoseconds' => 3000000.0, + 'headerValue' => sprintf('%d', (self::FIXED_POINT_UNIX_EPOCH_SECONDS * 1000) + 2), ], 'requestStartTEqualsMilliseconds' => [ 'headerName' => 'HTTP_X_REQUEST_START', - 'headerValue' => 't=2', - 'currentTimeSeconds' => 0.0, - 'requestStartTimeSeconds' => 0.005, - 'expectedQueueTimeNanoseconds' => 3000000.0, + 'headerValue' => sprintf('t=%d', (self::FIXED_POINT_UNIX_EPOCH_SECONDS * 1000) + 2), ], 'queueStartMilliseconds' => [ 'headerName' => 'HTTP_X_QUEUE_START', - 'headerValue' => '2', - 'currentTimeSeconds' => 0.0, - 'requestStartTimeSeconds' => 0.005, - 'expectedQueueTimeNanoseconds' => 3000000.0, + 'headerValue' => sprintf('%d', (self::FIXED_POINT_UNIX_EPOCH_SECONDS * 1000) + 2), ], 'queueStartTEqualsMilliseconds' => [ 'headerName' => 'HTTP_X_QUEUE_START', - 'headerValue' => 't=2', - 'currentTimeSeconds' => 0.0, - 'requestStartTimeSeconds' => 0.005, - 'expectedQueueTimeNanoseconds' => 3000000.0, + 'headerValue' => sprintf('t=%d', (self::FIXED_POINT_UNIX_EPOCH_SECONDS * 1000) + 2), + ], + 'requestStartSeconds' => [ + 'headerName' => 'HTTP_X_REQUEST_START', + 'headerValue' => sprintf('%.3f', self::FIXED_POINT_UNIX_EPOCH_SECONDS + 0.002), + ], + 'requestStartMicroseconds' => [ + 'headerName' => 'HTTP_X_REQUEST_START', + 'headerValue' => sprintf('%d', (self::FIXED_POINT_UNIX_EPOCH_SECONDS * 1000000) + 2000), + ], + 'requestStartNanoseconds' => [ + 'headerName' => 'HTTP_X_REQUEST_START', + 'headerValue' => sprintf('%d', (self::FIXED_POINT_UNIX_EPOCH_SECONDS * 1000000000) + 2000000), ], ]; } @@ -199,19 +202,14 @@ public function queueTimeRequestHeadersProvider() : array * * @dataProvider queueTimeRequestHeadersProvider */ - public function testRequestIsTaggedWithQueueTime( - string $headerName, - string $headerValue, - float $currentTimeSeconds, - float $requestStartTimeSeconds, - float $expectedQueueTimeNanoseconds - ) : void { + public function testRequestIsTaggedWithQueueTime(string $headerName, string $headerValue) : void + { // 2 = 2ms after epoch $_SERVER[$headerName] = $headerValue; // 0.005 = 5ms after epoch - $request = new Request($requestStartTimeSeconds); - $request->stop(null, $currentTimeSeconds); + $request = new Request(self::FIXED_POINT_UNIX_EPOCH_SECONDS + 0.005); + $request->stop(null, self::FIXED_POINT_UNIX_EPOCH_SECONDS); $f = $request->jsonSerialize(); @@ -221,7 +219,8 @@ public function testRequestIsTaggedWithQueueTime( continue; } - self::assertSame($expectedQueueTimeNanoseconds, $command['TagRequest']['value']); + // float rounding errors, yay! + self::assertSame(3000020, (int) $command['TagRequest']['value']); $foundTag = true; }