From aebb1ce32d9be9e08f392ee8dc154a5ef685a4b8 Mon Sep 17 00:00:00 2001 From: James Titcumb Date: Mon, 9 Sep 2019 17:06:37 +0100 Subject: [PATCH 1/6] Grab arguments from extension --- src/Agent.php | 3 ++- src/Extension/RecordedCall.php | 23 ++++++++++++++++++++--- 2 files changed, 22 insertions(+), 4 deletions(-) diff --git a/src/Agent.php b/src/Agent.php index 65080187..4b7cd923 100644 --- a/src/Agent.php +++ b/src/Agent.php @@ -184,7 +184,8 @@ private function addSpansFromExtension() : void } foreach ($this->phpExtension->getCalls() as $recordedCall) { - $this->request->startSpan($recordedCall->functionName(), $recordedCall->timeEntered()); + $callSpan = $this->request->startSpan($recordedCall->functionName(), $recordedCall->timeEntered()); + $callSpan->tag('arguments', $recordedCall->arguments()); $this->request->stopSpan($recordedCall->timeExited()); } } diff --git a/src/Extension/RecordedCall.php b/src/Extension/RecordedCall.php index 01517e1d..7e0e7657 100644 --- a/src/Extension/RecordedCall.php +++ b/src/Extension/RecordedCall.php @@ -20,12 +20,21 @@ final class RecordedCall /** @var float */ private $timeExited; - private function __construct(string $function, float $timeTakenInSeconds, float $timeEntered, float $timeExited) - { + /** @var mixed[] */ + private $arguments; + + private function __construct( + string $function, + float $timeTakenInSeconds, + float $timeEntered, + float $timeExited, + array $arguments + ) { $this->function = $function; $this->timeTakenInSeconds = $timeTakenInSeconds; $this->timeEntered = $timeEntered; $this->timeExited = $timeExited; + $this->arguments = $arguments; } /** @@ -39,12 +48,15 @@ public static function fromExtensionLoggedCallArray(array $extensionCall) : self Assert::keyExists($extensionCall, 'entered'); Assert::keyExists($extensionCall, 'exited'); Assert::keyExists($extensionCall, 'time_taken'); + Assert::keyExists($extensionCall, 'argv'); + Assert::isArray($extensionCall['argv']); return new self( (string) $extensionCall['function'], (float) $extensionCall['time_taken'], (float) $extensionCall['entered'], - (float) $extensionCall['exited'] + (float) $extensionCall['exited'], + $extensionCall['argv'] ); } @@ -67,4 +79,9 @@ public function timeExited() : float { return $this->timeExited; } + + public function arguments() : array + { + return $this->arguments; + } } From e313d0b82567736d8151ebff56edf05fa2da6a43 Mon Sep 17 00:00:00 2001 From: James Titcumb Date: Wed, 11 Sep 2019 14:52:24 +0100 Subject: [PATCH 2/6] Updated AgentTest to verify FGC spans are tagged with arguments --- tests/Integration/AgentTest.php | 4 ++++ tests/Unit/Extension/RecordedCallTest.php | 2 ++ 2 files changed, 6 insertions(+) diff --git a/tests/Integration/AgentTest.php b/tests/Integration/AgentTest.php index 5e140716..67b11318 100644 --- a/tests/Integration/AgentTest.php +++ b/tests/Integration/AgentTest.php @@ -129,6 +129,7 @@ public function testLoggingIsSent() : void if (TestHelper::scoutApmExtensionAvailable()) { $fileGetContentsSpanId = $this->assertUnserializedCommandContainsPayload('StartSpan', ['operation' => 'file_get_contents', 'parent_id' => $controllerSpanId], next($commands), 'span_id'); + $this->assertUnserializedCommandContainsPayload('TagSpan', ['span_id' => $fileGetContentsSpanId, 'tag' => 'arguments', 'value' => [__FILE__]], next($commands), null); $this->assertUnserializedCommandContainsPayload('StopSpan', ['span_id' => $fileGetContentsSpanId], next($commands), null); } @@ -136,6 +137,7 @@ public function testLoggingIsSent() : void if (TestHelper::scoutApmExtensionAvailable()) { $fileGetContentsSpanId = $this->assertUnserializedCommandContainsPayload('StartSpan', ['operation' => 'file_get_contents', 'parent_id' => $fooSpanId], next($commands), 'span_id'); + $this->assertUnserializedCommandContainsPayload('TagSpan', ['span_id' => $fileGetContentsSpanId, 'tag' => 'arguments', 'value' => [__FILE__]], next($commands), null); $this->assertUnserializedCommandContainsPayload('StopSpan', ['span_id' => $fileGetContentsSpanId], next($commands), null); } @@ -143,6 +145,7 @@ public function testLoggingIsSent() : void if (TestHelper::scoutApmExtensionAvailable()) { $fileGetContentsSpanId = $this->assertUnserializedCommandContainsPayload('StartSpan', ['operation' => 'file_get_contents', 'parent_id' => $barSpanId], next($commands), 'span_id'); + $this->assertUnserializedCommandContainsPayload('TagSpan', ['span_id' => $fileGetContentsSpanId, 'tag' => 'arguments', 'value' => [__FILE__]], next($commands), null); $this->assertUnserializedCommandContainsPayload('StopSpan', ['span_id' => $fileGetContentsSpanId], next($commands), null); } @@ -154,6 +157,7 @@ public function testLoggingIsSent() : void if (TestHelper::scoutApmExtensionAvailable()) { $fileGetContentsSpanId = $this->assertUnserializedCommandContainsPayload('StartSpan', ['operation' => 'file_get_contents', 'parent_id' => $controllerSpanId], next($commands), 'span_id'); + $this->assertUnserializedCommandContainsPayload('TagSpan', ['span_id' => $fileGetContentsSpanId, 'tag' => 'arguments', 'value' => [__FILE__]], next($commands), null); $this->assertUnserializedCommandContainsPayload('StopSpan', ['span_id' => $fileGetContentsSpanId], next($commands), null); } diff --git a/tests/Unit/Extension/RecordedCallTest.php b/tests/Unit/Extension/RecordedCallTest.php index eabb69af..25b698a2 100644 --- a/tests/Unit/Extension/RecordedCallTest.php +++ b/tests/Unit/Extension/RecordedCallTest.php @@ -27,11 +27,13 @@ public function testFromExtensionLoggedCallArray() : void 'entered' => $entered, 'exited' => $exited, 'time_taken' => $timeTaken, + 'argv' => [], ]); self::assertSame($entered, $call->timeEntered()); self::assertSame($exited, $call->timeExited()); self::assertSame($timeTaken, $call->timeTakenInSeconds()); self::assertSame($function, $call->functionName()); + self::assertSame([], $call->arguments()); } } From de8d0bfe72355d1bdf35c4518f2d50409aef2e60 Mon Sep 17 00:00:00 2001 From: James Titcumb Date: Wed, 11 Sep 2019 13:48:51 +0100 Subject: [PATCH 3/6] Ensure recorded calls are cleared at the start of test case to ensure the results are not skewed --- tests/Integration/AgentTest.php | 3 +++ 1 file changed, 3 insertions(+) diff --git a/tests/Integration/AgentTest.php b/tests/Integration/AgentTest.php index 67b11318..24d3dbd6 100644 --- a/tests/Integration/AgentTest.php +++ b/tests/Integration/AgentTest.php @@ -10,6 +10,7 @@ use Scoutapm\Agent; use Scoutapm\Config; use Scoutapm\Connector\SocketConnector; +use Scoutapm\Extension\PotentiallyAvailableExtensionCapabilities; use function file_get_contents; use function getenv; use function gethostname; @@ -69,6 +70,8 @@ public function testLoggingIsSent() : void $agent->connect(); + (new PotentiallyAvailableExtensionCapabilities())->clearRecordedCalls(); + $agent->webTransaction('Yay', static function () use ($agent) : void { file_get_contents(__FILE__); $agent->instrument('Test', 'foo', static function () use ($agent) : void { From ea75dd1082ef32ad1545ecaf031168d5d1cc1a85 Mon Sep 17 00:00:00 2001 From: James Titcumb Date: Wed, 11 Sep 2019 15:08:18 +0100 Subject: [PATCH 4/6] CS and static analysis fixes for mixed[] arguments from extension --- src/Extension/RecordedCall.php | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/src/Extension/RecordedCall.php b/src/Extension/RecordedCall.php index 7e0e7657..f592f06e 100644 --- a/src/Extension/RecordedCall.php +++ b/src/Extension/RecordedCall.php @@ -23,6 +23,7 @@ final class RecordedCall /** @var mixed[] */ private $arguments; + /** @param mixed[] $arguments */ private function __construct( string $function, float $timeTakenInSeconds, @@ -38,9 +39,11 @@ private function __construct( } /** - * @param string[]|float[]|array $extensionCall + * @param string[]|float[]|array $extensionCall * * @return RecordedCall + * + * @psalm-param array{function:string, entered:float, exited: float, time_taken: float, argv: mixed[]} $extensionCall */ public static function fromExtensionLoggedCallArray(array $extensionCall) : self { @@ -49,7 +52,6 @@ public static function fromExtensionLoggedCallArray(array $extensionCall) : self Assert::keyExists($extensionCall, 'exited'); Assert::keyExists($extensionCall, 'time_taken'); Assert::keyExists($extensionCall, 'argv'); - Assert::isArray($extensionCall['argv']); return new self( (string) $extensionCall['function'], @@ -80,6 +82,7 @@ public function timeExited() : float return $this->timeExited; } + /** @return mixed[] */ public function arguments() : array { return $this->arguments; From 8a048528d7a4250a639f61967529321d5b5b3043 Mon Sep 17 00:00:00 2001 From: James Titcumb Date: Fri, 13 Sep 2019 14:27:40 +0100 Subject: [PATCH 5/6] Ensure arguments from RecordedCall are filtered sufficiently so we don't send PII up to core-agent --- src/Agent.php | 2 +- src/Extension/RecordedCall.php | 17 ++++++++-- tests/Integration/AgentTest.php | 8 ++--- tests/Unit/Extension/RecordedCallTest.php | 40 ++++++++++++++++++++++- 4 files changed, 58 insertions(+), 9 deletions(-) diff --git a/src/Agent.php b/src/Agent.php index 4b7cd923..ab6a538e 100644 --- a/src/Agent.php +++ b/src/Agent.php @@ -185,7 +185,7 @@ private function addSpansFromExtension() : void foreach ($this->phpExtension->getCalls() as $recordedCall) { $callSpan = $this->request->startSpan($recordedCall->functionName(), $recordedCall->timeEntered()); - $callSpan->tag('arguments', $recordedCall->arguments()); + $callSpan->tag('desc', $recordedCall->filteredArguments()); $this->request->stopSpan($recordedCall->timeExited()); } } diff --git a/src/Extension/RecordedCall.php b/src/Extension/RecordedCall.php index f592f06e..b8e338c4 100644 --- a/src/Extension/RecordedCall.php +++ b/src/Extension/RecordedCall.php @@ -82,9 +82,20 @@ public function timeExited() : float return $this->timeExited; } - /** @return mixed[] */ - public function arguments() : array + /** + * We should never return the full set of arguments, only specific arguments for specific functions. This is to + * avoid potentially spilling personally identifiable information. + * + * @return mixed[] + */ + public function filteredArguments() : array { - return $this->arguments; + if ($this->function === 'file_get_contents') { + return [ + 'url' => (string) $this->arguments[0], + ]; + } + + return []; } } diff --git a/tests/Integration/AgentTest.php b/tests/Integration/AgentTest.php index 24d3dbd6..7358b427 100644 --- a/tests/Integration/AgentTest.php +++ b/tests/Integration/AgentTest.php @@ -132,7 +132,7 @@ public function testLoggingIsSent() : void if (TestHelper::scoutApmExtensionAvailable()) { $fileGetContentsSpanId = $this->assertUnserializedCommandContainsPayload('StartSpan', ['operation' => 'file_get_contents', 'parent_id' => $controllerSpanId], next($commands), 'span_id'); - $this->assertUnserializedCommandContainsPayload('TagSpan', ['span_id' => $fileGetContentsSpanId, 'tag' => 'arguments', 'value' => [__FILE__]], next($commands), null); + $this->assertUnserializedCommandContainsPayload('TagSpan', ['span_id' => $fileGetContentsSpanId, 'tag' => 'desc', 'value' => ['url' => __FILE__]], next($commands), null); $this->assertUnserializedCommandContainsPayload('StopSpan', ['span_id' => $fileGetContentsSpanId], next($commands), null); } @@ -140,7 +140,7 @@ public function testLoggingIsSent() : void if (TestHelper::scoutApmExtensionAvailable()) { $fileGetContentsSpanId = $this->assertUnserializedCommandContainsPayload('StartSpan', ['operation' => 'file_get_contents', 'parent_id' => $fooSpanId], next($commands), 'span_id'); - $this->assertUnserializedCommandContainsPayload('TagSpan', ['span_id' => $fileGetContentsSpanId, 'tag' => 'arguments', 'value' => [__FILE__]], next($commands), null); + $this->assertUnserializedCommandContainsPayload('TagSpan', ['span_id' => $fileGetContentsSpanId, 'tag' => 'desc', 'value' => ['url' => __FILE__]], next($commands), null); $this->assertUnserializedCommandContainsPayload('StopSpan', ['span_id' => $fileGetContentsSpanId], next($commands), null); } @@ -148,7 +148,7 @@ public function testLoggingIsSent() : void if (TestHelper::scoutApmExtensionAvailable()) { $fileGetContentsSpanId = $this->assertUnserializedCommandContainsPayload('StartSpan', ['operation' => 'file_get_contents', 'parent_id' => $barSpanId], next($commands), 'span_id'); - $this->assertUnserializedCommandContainsPayload('TagSpan', ['span_id' => $fileGetContentsSpanId, 'tag' => 'arguments', 'value' => [__FILE__]], next($commands), null); + $this->assertUnserializedCommandContainsPayload('TagSpan', ['span_id' => $fileGetContentsSpanId, 'tag' => 'desc', 'value' => ['url' => __FILE__]], next($commands), null); $this->assertUnserializedCommandContainsPayload('StopSpan', ['span_id' => $fileGetContentsSpanId], next($commands), null); } @@ -160,7 +160,7 @@ public function testLoggingIsSent() : void if (TestHelper::scoutApmExtensionAvailable()) { $fileGetContentsSpanId = $this->assertUnserializedCommandContainsPayload('StartSpan', ['operation' => 'file_get_contents', 'parent_id' => $controllerSpanId], next($commands), 'span_id'); - $this->assertUnserializedCommandContainsPayload('TagSpan', ['span_id' => $fileGetContentsSpanId, 'tag' => 'arguments', 'value' => [__FILE__]], next($commands), null); + $this->assertUnserializedCommandContainsPayload('TagSpan', ['span_id' => $fileGetContentsSpanId, 'tag' => 'desc', 'value' => ['url' => __FILE__]], next($commands), null); $this->assertUnserializedCommandContainsPayload('StopSpan', ['span_id' => $fileGetContentsSpanId], next($commands), null); } diff --git a/tests/Unit/Extension/RecordedCallTest.php b/tests/Unit/Extension/RecordedCallTest.php index 25b698a2..1cd68867 100644 --- a/tests/Unit/Extension/RecordedCallTest.php +++ b/tests/Unit/Extension/RecordedCallTest.php @@ -34,6 +34,44 @@ public function testFromExtensionLoggedCallArray() : void self::assertSame($exited, $call->timeExited()); self::assertSame($timeTaken, $call->timeTakenInSeconds()); self::assertSame($function, $call->functionName()); - self::assertSame([], $call->arguments()); + self::assertSame([], $call->filteredArguments()); + } + + public function filteredArgumentsDataProvider() : array + { + return [ + 'file_get_contents' => [ + 'recordedFunctionName' => 'file_get_contents', + 'expectedFilteredArguments' => ['url' => 'a'], + ], + 'password_hash' => [ + 'recordedFunctionName' => 'password_hashj', + 'expectedFilteredArguments' => [], + ], + ]; + } + + /** + * @param mixed[] $expectedFilteredArguments + * @dataProvider filteredArgumentsDataProvider + * @throws \Exception + */ + public function testOnlyFilteredArgumentsAreReturned( + string $recordedFunctionName, + array $expectedFilteredArguments + ) : void { + $entered = microtime(true) + random_int(1, 5); + $exited = microtime(true) + random_int(6, 10); + + self::assertEquals( + $expectedFilteredArguments, + RecordedCall::fromExtensionLoggedCallArray([ + 'function' => $recordedFunctionName, + 'entered' => $entered, + 'exited' => $exited, + 'time_taken' => $exited - $entered, + 'argv' => ['a', 'b', 'c', 'd', 'e', 'f'], + ])->filteredArguments() + ); } } From 2114ff453957486dcab8e3ac444733cdd71a4577 Mon Sep 17 00:00:00 2001 From: James Titcumb Date: Fri, 13 Sep 2019 14:30:03 +0100 Subject: [PATCH 6/6] Updated extensions required/suggested as per #56 --- composer.json | 5 ++++- composer.lock | 6 ++++-- tests/Unit/Extension/RecordedCallTest.php | 11 ++++++++--- 3 files changed, 16 insertions(+), 6 deletions(-) diff --git a/composer.json b/composer.json index ebe23301..f8c29c5f 100644 --- a/composer.json +++ b/composer.json @@ -9,6 +9,8 @@ "php": ">=7.1.0,<7.5.0", "ext-json": "*", "ext-sockets": "*", + "ext-zlib": "*", + "ext-openssl": "*", "ocramius/package-versions": "^1.4", "psr/log": "^1.0", "ralouphie/getallheaders": "^2.0.5|^3.0", @@ -24,7 +26,8 @@ "vimeo/psalm": "^3.4" }, "suggest": { - "ext-xdebug": "Required for processing of request headers" + "ext-xdebug": "Required for processing of request headers", + "ext-scoutapm": "Recommended for additional recording capability of IO-bound PHP internal functions" }, "autoload": { "psr-4": { diff --git a/composer.lock b/composer.lock index d0b5f04a..970855e5 100644 --- a/composer.lock +++ b/composer.lock @@ -4,7 +4,7 @@ "Read more about it at https://getcomposer.org/doc/01-basic-usage.md#installing-dependencies", "This file is @generated automatically" ], - "content-hash": "8f65a1f4fb12631669304baea15e3e31", + "content-hash": "fdca33732dd56bfc62f395cc59df48bb", "packages": [ { "name": "ocramius/package-versions", @@ -3498,7 +3498,9 @@ "platform": { "php": ">=7.1.0,<7.5.0", "ext-json": "*", - "ext-sockets": "*" + "ext-sockets": "*", + "ext-zlib": "*", + "ext-openssl": "*" }, "platform-dev": [], "platform-overrides": { diff --git a/tests/Unit/Extension/RecordedCallTest.php b/tests/Unit/Extension/RecordedCallTest.php index 1cd68867..a928d269 100644 --- a/tests/Unit/Extension/RecordedCallTest.php +++ b/tests/Unit/Extension/RecordedCallTest.php @@ -37,6 +37,9 @@ public function testFromExtensionLoggedCallArray() : void self::assertSame([], $call->filteredArguments()); } + /** + * @return string[][]|string[][][]|array)>> + */ public function filteredArgumentsDataProvider() : array { return [ @@ -53,15 +56,17 @@ public function filteredArgumentsDataProvider() : array /** * @param mixed[] $expectedFilteredArguments + * + * @throws Exception + * * @dataProvider filteredArgumentsDataProvider - * @throws \Exception */ public function testOnlyFilteredArgumentsAreReturned( string $recordedFunctionName, array $expectedFilteredArguments ) : void { - $entered = microtime(true) + random_int(1, 5); - $exited = microtime(true) + random_int(6, 10); + $entered = microtime(true) + random_int(1, 5); + $exited = microtime(true) + random_int(6, 10); self::assertEquals( $expectedFilteredArguments,