From ad3ccd8139a0cc9e8883fdc9a8fa990ced099ec7 Mon Sep 17 00:00:00 2001 From: Tobias Bachert Date: Tue, 13 Sep 2022 04:34:52 +0200 Subject: [PATCH] Add debug scope to warn on incorrect scope usage (#823) * Add debug scope to warn on incorrect scope usage * Enable assertions in unit tests --- .github/workflows/php.yml | 2 +- src/Context/Context.php | 8 ++- src/Context/DebugScope.php | 94 +++++++++++++++++++++++++++ tests/Unit/Context/ContextTest.php | 33 +++++++--- tests/Unit/Context/DebugScopeTest.php | 68 +++++++++++++++++++ tests/Unit/Context/ScopeTest.php | 8 ++- 6 files changed, 198 insertions(+), 15 deletions(-) create mode 100644 src/Context/DebugScope.php create mode 100644 tests/Unit/Context/DebugScopeTest.php diff --git a/.github/workflows/php.yml b/.github/workflows/php.yml index 5f9c0ae60..7c34d2d23 100644 --- a/.github/workflows/php.yml +++ b/.github/workflows/php.yml @@ -63,7 +63,7 @@ jobs: run: vendor/bin/phpstan analyse --error-format=github - name: Run PHPUnit (unit tests) - run: vendor/bin/phpunit --coverage-text --coverage-clover=coverage.clover --testsuite unit + run: php -dzend.assertions=1 vendor/bin/phpunit --coverage-text --coverage-clover=coverage.clover --testsuite unit - name: Run PHPUnit (integration tests) run: vendor/bin/phpunit --testsuite integration diff --git a/src/Context/Context.php b/src/Context/Context.php index 85833084b..8c57bc3ba 100644 --- a/src/Context/Context.php +++ b/src/Context/Context.php @@ -4,6 +4,8 @@ namespace OpenTelemetry\Context; +use function assert; + /** * @see https://github.com/open-telemetry/opentelemetry-specification/blob/v1.6.1/specification/context/context.md#overview */ @@ -92,7 +94,11 @@ public function withContextValue(ImplicitContextKeyedInterface $value): self */ public function activate(): ScopeInterface { - return self::storage()->attach($this); + $scope = self::storage()->attach($this); + /** @psalm-suppress RedundantCondition */ + assert((bool) $scope = new DebugScope($scope)); + + return $scope; } /** diff --git a/src/Context/DebugScope.php b/src/Context/DebugScope.php new file mode 100644 index 000000000..e9e4d53c5 --- /dev/null +++ b/src/Context/DebugScope.php @@ -0,0 +1,94 @@ +scope = $node; + $this->scope[self::DEBUG_TRACE_CREATE] = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS); + } + + public function detach(): int + { + $this->scope[self::DEBUG_TRACE_DETACH] ??= debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS); + + $flags = $this->scope->detach(); + + if (($flags & ScopeInterface::DETACHED) !== 0) { + trigger_error(sprintf( + 'Scope: unexpected call to Scope::detach() for scope #%d, scope was already detached %s', + spl_object_id($this), + self::formatBacktrace($this->scope[self::DEBUG_TRACE_DETACH]), + )); + } elseif (($flags & ScopeInterface::MISMATCH) !== 0) { + trigger_error(sprintf( + 'Scope: unexpected call to Scope::detach() for scope #%d, scope successfully detached but another scope should have been detached first', + spl_object_id($this), + )); + } elseif (($flags & ScopeInterface::INACTIVE) !== 0) { + trigger_error(sprintf( + 'Scope: unexpected call to Scope::detach() for scope #%d, scope successfully detached from different execution context', + spl_object_id($this), + )); + } + + return $flags; + } + + public function __destruct() + { + if (!isset($this->scope[self::DEBUG_TRACE_DETACH])) { + trigger_error(sprintf( + 'Scope: missing call to Scope::detach() for scope #%d, created %s', + spl_object_id($this->scope), + self::formatBacktrace($this->scope[self::DEBUG_TRACE_CREATE]), + )); + } + } + + private static function formatBacktrace(array $trace): string + { + $s = ''; + for ($i = 0, $n = count($trace) + 1; ++$i < $n;) { + $s .= "\n\t"; + $s .= 'at '; + if (isset($trace[$i]['class'])) { + $s .= strtr($trace[$i]['class'], ['\\' => '.']); + $s .= '.'; + } + $s .= strtr($trace[$i]['function'] ?? '{main}', ['\\' => '.']); + $s .= '('; + if (isset($trace[$i - 1]['file'])) { + $s .= basename($trace[$i - 1]['file']); + if (isset($trace[$i - 1]['line'])) { + $s .= ':'; + $s .= $trace[$i - 1]['line']; + } + } else { + $s .= 'Unknown Source'; + } + $s .= ')'; + } + + return $s . "\n"; + } +} diff --git a/tests/Unit/Context/ContextTest.php b/tests/Unit/Context/ContextTest.php index 60c814525..538e83803 100644 --- a/tests/Unit/Context/ContextTest.php +++ b/tests/Unit/Context/ContextTest.php @@ -17,8 +17,13 @@ public function test_activate(): void { $context = Context::getRoot(); - $context->activate(); - $this->assertSame($context, Context::getCurrent()); + $scope = $context->activate(); + + try { + $this->assertSame($context, Context::getCurrent()); + } finally { + $scope->detach(); + } } public function test_ctx_can_store_values_by_key(): void @@ -132,13 +137,17 @@ public function test_ctx_value_not_found_returns_null(): void public function test_attach_and_detach_set_current_ctx(): void { $key = new ContextKey(); - Context::getRoot()->with($key, '111')->activate(); + $scope = Context::getRoot()->with($key, '111')->activate(); - $token = Context::getRoot()->with($key, '222')->activate(); - $this->assertSame(Context::getValue($key), '222'); + try { + $token = Context::getRoot()->with($key, '222')->activate(); + $this->assertSame(Context::getValue($key), '222'); - $token->detach(); - $this->assertSame(Context::getValue($key), '111'); + $token->detach(); + $this->assertSame(Context::getValue($key), '111'); + } finally { + $scope->detach(); + } } public function test_instance_set_and_static_get_use_same_ctx(): void @@ -147,9 +156,13 @@ public function test_instance_set_and_static_get_use_same_ctx(): void $val = 'foobar'; $ctx = Context::getRoot()->with($key, $val); - $ctx->activate(); + $scope = $ctx->activate(); - $this->assertSame(Context::getValue($key, $ctx), $val); - $this->assertSame(Context::getValue($key, null), $val); + try { + $this->assertSame(Context::getValue($key, $ctx), $val); + $this->assertSame(Context::getValue($key, null), $val); + } finally { + $scope->detach(); + } } } diff --git a/tests/Unit/Context/DebugScopeTest.php b/tests/Unit/Context/DebugScopeTest.php new file mode 100644 index 000000000..2f26dddd7 --- /dev/null +++ b/tests/Unit/Context/DebugScopeTest.php @@ -0,0 +1,68 @@ +activate(); + + $scope1->detach(); + + $this->expectNotice(); + $this->expectNoticeMessage('already detached'); + $scope1->detach(); + } + + public function test_order_mismatch_scope_detach(): void + { + $scope1 = Context::getCurrent()->activate(); + $scope2 = Context::getCurrent()->activate(); + + try { + $this->expectNotice(); + $this->expectNoticeMessage('another scope'); + $scope1->detach(); + } finally { + $scope2->detach(); + } + } + + public function test_inactive_scope_detach(): void + { + $scope1 = Context::getCurrent()->activate(); + + Context::storage()->fork(1); + Context::storage()->switch(1); + + try { + $this->expectNotice(); + $this->expectNoticeMessage('different execution context'); + $scope1->detach(); + } finally { + Context::storage()->switch(0); + Context::storage()->destroy(1); + } + } + + public function test_missing_scope_detach(): void + { + try { + $this->expectNotice(); + $this->expectNoticeMessage('missing call'); + Context::getCurrent()->activate(); + } finally { + /** @psalm-suppress PossiblyNullReference */ + Context::storage()->scope()->detach(); + } + } +} diff --git a/tests/Unit/Context/ScopeTest.php b/tests/Unit/Context/ScopeTest.php index a21debc01..becd1a9a6 100644 --- a/tests/Unit/Context/ScopeTest.php +++ b/tests/Unit/Context/ScopeTest.php @@ -51,7 +51,8 @@ public function test_detached_scope_detach(): void $scope1 = Context::getCurrent()->activate(); $this->assertSame(0, $scope1->detach()); - $this->assertSame(ScopeInterface::DETACHED, $scope1->detach() & ScopeInterface::DETACHED); + /** @phpstan-ignore-next-line */ + $this->assertSame(ScopeInterface::DETACHED, @$scope1->detach() & ScopeInterface::DETACHED); } public function test_order_mismatch_scope_detach(): void @@ -59,7 +60,7 @@ public function test_order_mismatch_scope_detach(): void $scope1 = Context::getCurrent()->activate(); $scope2 = Context::getCurrent()->activate(); - $this->assertSame(ScopeInterface::MISMATCH, $scope1->detach() & ScopeInterface::MISMATCH); + $this->assertSame(ScopeInterface::MISMATCH, @$scope1->detach() & ScopeInterface::MISMATCH); $this->assertSame(0, $scope2->detach()); } @@ -78,13 +79,14 @@ public function test_order_mismatch_scope_detach_depth(): void $this->assertSame(0, $scope4->detach()); $this->assertSame(0, $scope1->detach()); } + public function test_inactive_scope_detach(): void { $scope1 = Context::getCurrent()->activate(); Context::storage()->fork(1); Context::storage()->switch(1); - $this->assertSame(ScopeInterface::INACTIVE, $scope1->detach() & ScopeInterface::INACTIVE); + $this->assertSame(ScopeInterface::INACTIVE, @$scope1->detach() & ScopeInterface::INACTIVE); Context::storage()->switch(0); Context::storage()->destroy(1);