From b02dd7e082705662752919c9c750a5c0ba5f9b47 Mon Sep 17 00:00:00 2001 From: Albert Chen Date: Mon, 9 Sep 2024 21:09:09 +0800 Subject: [PATCH] feat: add context support for logger --- src/log/src/Events/MessageLogged.php | 18 +++ src/log/src/LogManager.php | 64 ++++++++- src/log/src/Logger.php | 103 ++++++++++++++- tests/Log/LogLoggerTest.php | 144 ++++++++++++++++++++ tests/Log/LogManagerTest.php | 188 ++++++++++++++++++++++++--- 5 files changed, 492 insertions(+), 25 deletions(-) create mode 100644 src/log/src/Events/MessageLogged.php create mode 100644 tests/Log/LogLoggerTest.php diff --git a/src/log/src/Events/MessageLogged.php b/src/log/src/Events/MessageLogged.php new file mode 100644 index 0000000..be25e1c --- /dev/null +++ b/src/log/src/Events/MessageLogged.php @@ -0,0 +1,18 @@ +createStackDriver(compact('channels', 'channel')) + $this->createStackDriver(compact('channels', 'channel')), + $this->app->get(EventDispatcherInterface::class) ); } @@ -107,7 +110,7 @@ protected function get(?string $name, ?array $config = null): LoggerInterface { try { return $this->channels[$name] ?? with($this->resolve($name, $config), function ($logger) use ($name) { - return $this->channels[$name] = $this->tap($name, new Logger($logger)); + return $this->channels[$name] = $this->tap($name, new Logger($logger, $this->app->get(EventDispatcherInterface::class))); }); } catch (Throwable $e) { return tap($this->createEmergencyLogger(), function ($logger) use ($e) { @@ -153,7 +156,8 @@ protected function createEmergencyLogger(): LoggerInterface ); return new Logger( - new Monolog('hyperf', $this->prepareHandlers([$handler])) + new Monolog('hyperf', $this->prepareHandlers([$handler])), + $this->app->get(EventDispatcherInterface::class) ); } @@ -406,6 +410,60 @@ protected function formatter(): \Monolog\Formatter\FormatterInterface return new LineFormatter(null, $this->dateFormat, true, true, true); } + /** + * Share context across channels and stacks. + * + * @return $this + */ + public function shareContext(array $context): self + { + foreach ($this->channels as $channel) { + $channel->withContext($context); + } + + Context::override('__logger.shared_context', function ($currentContext) use ($context) { + return array_merge($currentContext ?: [], $context); + }); + + return $this; + } + + /** + * The context shared across channels and stacks. + */ + public function sharedContext(): array + { + return (array) Context::get('__logger.shared_context', []); + } + + /** + * Flush the log context on all currently resolved channels. + * + * @return $this + */ + public function withoutContext(): self + { + foreach ($this->channels as $channel) { + if (method_exists($channel, 'withoutContext')) { + $channel->withoutContext(); + } + } + + return $this; + } + + /** + * Flush the shared context. + * + * @return $this + */ + public function flushSharedContext(): self + { + Context::destroy('__logger.shared_context'); + + return $this; + } + /** * Get fallback log channel name. */ diff --git a/src/log/src/Logger.php b/src/log/src/Logger.php index 370312c..0d6c298 100755 --- a/src/log/src/Logger.php +++ b/src/log/src/Logger.php @@ -4,23 +4,24 @@ namespace SwooleTW\Hyperf\Log; +use Closure; +use Hyperf\Context\Context; use Hyperf\Contract\Arrayable; use Hyperf\Contract\Jsonable; +use Psr\EventDispatcher\EventDispatcherInterface; use Psr\Log\LoggerInterface; +use RuntimeException; use Stringable; +use SwooleTW\Hyperf\Log\Events\MessageLogged; class Logger implements LoggerInterface { - /** - * Any context to be added to logs. - */ - protected array $context = []; - /** * Create a new log writer instance. */ public function __construct( - protected LoggerInterface $logger + protected LoggerInterface $logger, + protected ?EventDispatcherInterface $dispatcher = null ) { } @@ -136,8 +137,76 @@ protected function writeLog($level, string|Stringable $message, array $context): { $this->logger->{$level}( $message = $this->formatMessage($message), - $context = $context + $context = array_merge($this->getContext(), $context) ); + + $this->fireLogEvent($level, $message, $context); + } + + /** + * Add context to all future logs. + * + * @return $this + */ + public function withContext(array $context = []): self + { + Context::override('__logger.context', function ($currentContext) use ($context) { + return array_merge($currentContext ?: [], $context); + }); + + return $this; + } + + /** + * Flush the existing context array. + * + * @return $this + */ + public function withoutContext(): self + { + Context::destroy('__logger.context'); + + return $this; + } + + /** + * Get the existing context array. + * + * @return array + */ + public function getContext(): array + { + return (array) Context::get('__logger.context', []); + } + + /** + * Register a new callback handler for when a log event is triggered. + * + * @throws RuntimeException + */ + public function listen(Closure $callback): void + { + if (! isset($this->dispatcher)) { + throw new RuntimeException('Events dispatcher has not been set.'); + } + + if (! method_exists($this->dispatcher, 'listen')) { + throw new RuntimeException('Events dispatcher does not implement the listen method.'); + } + + /* @phpstan-ignore-next-line */ + $this->dispatcher->listen(MessageLogged::class, $callback); + } + + /** + * Fires a log event. + */ + protected function fireLogEvent(string $level, string $message, array $context = []): void + { + // If the event dispatcher is set, we will pass along the parameters to the + // log listeners. These are useful for building profilers or other tools + // that aggregate all of the log messages for a given "request" cycle. + $this->dispatcher?->dispatch(new MessageLogged($level, $message, $context)); } /** @@ -169,6 +238,26 @@ public function getLogger(): LoggerInterface return $this->logger; } + /** + * Get the event dispatcher instance. + */ + public function getEventDispatcher(): EventDispatcherInterface + { + return $this->dispatcher; + } + + /** + * Set the event dispatcher instance. + * + * @return $this + */ + public function setEventDispatcher(EventDispatcherInterface $dispatcher): self + { + $this->dispatcher = $dispatcher; + + return $this; + } + /** * Dynamically proxy method calls to the underlying logger. * diff --git a/tests/Log/LogLoggerTest.php b/tests/Log/LogLoggerTest.php new file mode 100644 index 0000000..5dd59af --- /dev/null +++ b/tests/Log/LogLoggerTest.php @@ -0,0 +1,144 @@ +shouldReceive('error')->once()->with('foo', []); + + $writer->error('foo'); + } + + public function testContextIsAddedToAllSubsequentLogs() + { + $writer = new Logger($monolog = m::mock(Monolog::class)); + $writer->withContext(['bar' => 'baz']); + + $monolog->shouldReceive('error')->once()->with('foo', ['bar' => 'baz']); + + $writer->error('foo'); + } + + public function testContextIsFlushed() + { + $writer = new Logger($monolog = m::mock(Monolog::class)); + $writer->withContext(['bar' => 'baz']); + $writer->withoutContext(); + + $monolog->expects('error')->with('foo', []); + + $writer->error('foo'); + } + + public function testLoggerFiresEventsDispatcher() + { + $writer = new Logger($monolog = m::mock(Monolog::class), $events = new Dispatcher()); + $monolog->shouldReceive('error')->once()->with('foo', []); + + $context = []; + + $events->listen(MessageLogged::class, function ($event) use (&$context) { + $context['__log.level'] = $event->level; + $context['__log.message'] = $event->message; + $context['__log.context'] = $event->context; + }); + + $writer->error('foo'); + $this->assertTrue(isset($context['__log.level'])); + $this->assertSame('error', $context['__log.level']); + $this->assertTrue(isset($context['__log.message'])); + $this->assertSame('foo', $context['__log.message']); + $this->assertTrue(isset($context['__log.context'])); + $this->assertEquals([], $context['__log.context']); + } + + public function testListenShortcutFailsWithNoDispatcher() + { + $this->expectException(RuntimeException::class); + $this->expectExceptionMessage('Events dispatcher has not been set.'); + + $writer = new Logger(m::mock(Monolog::class)); + $writer->listen(function () { + }); + } + + public function testListenShortcut() + { + $writer = new Logger(m::mock(Monolog::class), $events = m::mock(Dispatcher::class)); + + $callback = function () { + return 'success'; + }; + $events->shouldReceive('listen')->with(MessageLogged::class, $callback)->once(); + + $writer->listen($callback); + } + + public function testWithContext() + { + $writer = new Logger($monolog = m::mock(Monolog::class)); + + $writer->withContext(['foo' => 'bar']); + $writer->withContext(['baz' => 'qux']); + + $monolog->shouldReceive('error')->once()->with('test message', ['foo' => 'bar', 'baz' => 'qux']); + + $writer->error('test message'); + } + + public function testWithoutContext() + { + $writer = new Logger($monolog = m::mock(Monolog::class)); + + $writer->withContext(['foo' => 'bar']); + $writer->withoutContext(); + + $monolog->shouldReceive('error')->once()->with('test message', []); + + $writer->error('test message'); + } +} + +class Dispatcher implements EventDispatcherInterface +{ + protected $listener; + + public function dispatch(object $event) + { + if (! $this->listener) { + return; + } + + ($this->listener)($event); + } + + public function listen(string $event, Closure $listener) + { + $this->listener = $listener; + } +} diff --git a/tests/Log/LogManagerTest.php b/tests/Log/LogManagerTest.php index b707494..5d5e412 100644 --- a/tests/Log/LogManagerTest.php +++ b/tests/Log/LogManagerTest.php @@ -4,7 +4,9 @@ namespace SwooleTW\Hyperf\Tests\Log; +use Closure; use Hyperf\Config\Config; +use Hyperf\Context\Context; use Hyperf\Contract\ConfigInterface; use Hyperf\Di\Container; use Hyperf\Di\Definition\DefinitionSource; @@ -22,6 +24,7 @@ use Monolog\Processor\MemoryUsageProcessor; use Monolog\Processor\PsrLogMessageProcessor; use Monolog\Processor\UidProcessor; +use Psr\EventDispatcher\EventDispatcherInterface; use Psr\Log\LoggerInterface; use ReflectionProperty; use RuntimeException; @@ -36,9 +39,15 @@ */ class LogManagerTest extends TestCase { + public function tearDown(): void + { + parent::tearDown(); + Context::destroy('__logger.shared_context'); + } + public function testLogManagerCachesLoggerInstances() { - $manager = new LogManager($this->getContainer()); + $manager = new LogManager($this->getContainer(), new Dispatcher()); $logger1 = $manager->channel('single')->getLogger(); $logger2 = $manager->channel('single')->getLogger(); @@ -48,7 +57,7 @@ public function testLogManagerCachesLoggerInstances() public function testLogManagerGetDefaultDriver() { - $manager = new LogManager($container = $this->getContainer()); + $manager = new LogManager($container = $this->getContainer(), new Dispatcher()); $container->get(ConfigInterface::class) ->set('logging.default', 'single'); $this->assertEmpty($manager->getChannels()); @@ -61,7 +70,7 @@ public function testLogManagerGetDefaultDriver() public function testStackChannel() { - $manager = new LogManager($container = $this->getContainer()); + $manager = new LogManager($container = $this->getContainer(), new Dispatcher()); $config = $container->get(ConfigInterface::class); $config->set('logging.channels.stack', [ @@ -107,7 +116,7 @@ public function testStackChannel() public function testLogManagerCreatesConfiguredMonologHandler() { - $manager = new LogManager($container = $this->getContainer()); + $manager = new LogManager($container = $this->getContainer(), new Dispatcher()); $config = $container->get(ConfigInterface::class); $config->set('logging.channels.nonbubblingstream', [ 'driver' => 'monolog', @@ -154,7 +163,7 @@ public function testLogManagerCreatesConfiguredMonologHandler() public function testLogManagerCreatesMonologHandlerWithConfiguredFormatter() { - $manager = new LogManager($container = $this->getContainer()); + $manager = new LogManager($container = $this->getContainer(), new Dispatcher()); $config = $container->get(ConfigInterface::class); $config->set('logging.channels.newrelic', [ 'driver' => 'monolog', @@ -194,7 +203,7 @@ public function testLogManagerCreatesMonologHandlerWithConfiguredFormatter() public function testLogManagerCreatesMonologHandlerWithProperFormatter() { - $manager = new LogManager($container = $this->getContainer()); + $manager = new LogManager($container = $this->getContainer(), new Dispatcher()); $config = $container->get(ConfigInterface::class); $config->set('logging.channels.null', [ 'driver' => 'monolog', @@ -221,7 +230,7 @@ public function testLogManagerCreatesMonologHandlerWithProperFormatter() public function testLogManagerCreatesMonologHandlerWithProcessors() { - $manager = new LogManager($container = $this->getContainer()); + $manager = new LogManager($container = $this->getContainer(), new Dispatcher()); $config = $container->get(ConfigInterface::class); $config->set('logging.channels.memory', [ 'driver' => 'monolog', @@ -285,7 +294,7 @@ protected function createEmergencyLogger(): LoggerInterface public function testLogManagerCreateSingleDriverWithConfiguredFormatter() { - $manager = new LogManager($container = $this->getContainer()); + $manager = new LogManager($container = $this->getContainer(), new Dispatcher()); $config = $container->get(ConfigInterface::class); $config->set('logging.channels.defaultsingle', [ 'driver' => 'single', @@ -329,7 +338,7 @@ public function testLogManagerCreateSingleDriverWithConfiguredFormatter() public function testLogManagerCreateDailyDriverWithConfiguredFormatter() { - $manager = new LogManager($container = $this->getContainer()); + $manager = new LogManager($container = $this->getContainer(), new Dispatcher()); $config = $container->get(ConfigInterface::class); $config->set('logging.channels.defaultdaily', [ 'driver' => 'daily', @@ -373,7 +382,7 @@ public function testLogManagerCreateDailyDriverWithConfiguredFormatter() public function testLogManagerCreateSyslogDriverWithConfiguredFormatter() { - $manager = new LogManager($container = $this->getContainer()); + $manager = new LogManager($container = $this->getContainer(), new Dispatcher()); $config = $container->get(ConfigInterface::class); $config->set('logging.channels.defaultsyslog', [ 'driver' => 'syslog', @@ -447,7 +456,7 @@ public function testLogManagerCanBuildOnDemandChannel() public function testLogManagerCanUseOnDemandChannelInOnDemandStack() { - $manager = new LogManager($container = $this->getContainer()); + $manager = new LogManager($container = $this->getContainer(), new Dispatcher()); $container->get(ConfigInterface::class) ->set('logging.channels.test', [ 'driver' => 'single', @@ -483,7 +492,7 @@ public function __invoke() public function testWrappingHandlerInFingersCrossedWhenActionLevelIsUsed() { - $manager = new LogManager($container = $this->getContainer()); + $manager = new LogManager($container = $this->getContainer(), new Dispatcher()); $container->get(ConfigInterface::class) ->set('logging.channels.fingerscrossed', [ 'driver' => 'monolog', @@ -526,7 +535,7 @@ public function testWrappingHandlerInFingersCrossedWhenActionLevelIsUsed() public function testFingersCrossedHandlerStopsRecordBufferingAfterFirstFlushByDefault() { - $manager = new LogManager($container = $this->getContainer()); + $manager = new LogManager($container = $this->getContainer(), new Dispatcher()); $container->get(ConfigInterface::class) ->set('logging.channels.fingerscrossed', [ 'driver' => 'monolog', @@ -553,7 +562,7 @@ public function testFingersCrossedHandlerStopsRecordBufferingAfterFirstFlushByDe public function testFingersCrossedHandlerCanBeConfiguredToResumeBufferingAfterFlushing() { - $manager = new LogManager($container = $this->getContainer()); + $manager = new LogManager($container = $this->getContainer(), new Dispatcher()); $container->get(ConfigInterface::class) ->set('logging.channels.fingerscrossed', [ 'driver' => 'monolog', @@ -579,9 +588,138 @@ public function testFingersCrossedHandlerCanBeConfiguredToResumeBufferingAfterFl $this->assertFalse($stopBufferingValue); } + public function testItSharesContextWithAlreadyResolvedChannels() + { + $manager = new LogManager($container = $this->getContainer(), new Dispatcher()); + $config = $container->get(ConfigInterface::class); + $config->set('logging.default', null); + $config->set('logging.channels.null', [ + 'driver' => 'monolog', + 'handler' => NullHandler::class, + ]); + $channel = $manager->channel('null'); + $context = null; + + $channel->listen(function ($message) use (&$context) { + $context = $message->context; + }); + $manager->shareContext([ + 'invocation-id' => 'expected-id', + ]); + $channel->info('xxxx'); + + $this->assertSame(['invocation-id' => 'expected-id'], $context); + } + + public function testItSharesContextWithFreshlyResolvedChannels() + { + $manager = new LogManager($container = $this->getContainer(), new Dispatcher()); + $config = $container->get(ConfigInterface::class); + $config->set('logging.default', null); + $config->set('logging.channels.null', [ + 'driver' => 'monolog', + 'handler' => NullHandler::class, + ]); + $channel = $manager->channel('null'); + $context = null; + + $manager->shareContext([ + 'invocation-id' => 'expected-id', + ]); + $manager->channel('null')->listen(function ($message) use (&$context) { + $context = $message->context; + }); + $manager->channel('null')->info('xxxx'); + + $this->assertSame(['invocation-id' => 'expected-id'], $context); + } + + public function testContextCanBePubliclyAccessedByOtherLoggingSystems() + { + $manager = new LogManager($this->getContainer(), new Dispatcher()); + $manager->shareContext([ + 'invocation-id' => 'expected-id', + ]); + + $this->assertSame($manager->sharedContext(), ['invocation-id' => 'expected-id']); + } + + public function testItSharesContextWithStacksWhenTheyAreResolved() + { + $manager = new LogManager($container = $this->getContainer(), new Dispatcher()); + $config = $container->get(ConfigInterface::class); + $config->set('logging.default', null); + $config->set('logging.channels.null', [ + 'driver' => 'monolog', + 'handler' => NullHandler::class, + ]); + $channel = $manager->channel('null'); + $context = null; + + $manager->shareContext([ + 'invocation-id' => 'expected-id', + ]); + $stack = $manager->stack(['null']); + $stack->listen(function ($message) use (&$context) { + $context = $message->context; + }); + $stack->info('xxxx'); + + $this->assertSame(['invocation-id' => 'expected-id'], $context); + } + + public function testItMergesSharedContextRatherThanReplacing() + { + $manager = new LogManager($container = $this->getContainer(), new Dispatcher()); + $config = $container->get(ConfigInterface::class); + $config->set('logging.default', null); + $config->set('logging.channels.null', [ + 'driver' => 'monolog', + 'handler' => NullHandler::class, + ]); + $channel = $manager->channel('null'); + $context = null; + + $manager->shareContext([ + 'invocation-id' => 'expected-id', + ]); + $manager->shareContext([ + 'invocation-start' => 1651800456, + ]); + $manager->channel('null')->listen(function ($message) use (&$context) { + $context = $message->context; + }); + $manager->channel('null')->info('xxxx', [ + 'logged' => 'context', + ]); + + $this->assertSame([ + 'invocation-id' => 'expected-id', + 'invocation-start' => 1651800456, + 'logged' => 'context', + ], $context); + $this->assertSame([ + 'invocation-id' => 'expected-id', + 'invocation-start' => 1651800456, + ], $manager->sharedContext()); + } + + public function testFlushSharedContext() + { + $manager = new LogManager($this->getContainer(), new Dispatcher()); + + $manager->shareContext($context = ['foo' => 'bar']); + + $this->assertSame($context, $manager->sharedContext()); + + $manager->flushSharedContext(); + + $this->assertEmpty($manager->sharedContext()); + } + public function testLogManagerCreateCustomFormatterWithTap() { - $manager = new LogManager($container = $this->getContainer()); + $manager = new LogManager($container = $this->getContainer(), new Dispatcher()); $container->get(ConfigInterface::class) ->set('logging.channels.custom', [ 'driver' => 'single', @@ -618,6 +756,7 @@ protected function getContainer(array $logConfig = []) return new Container( new DefinitionSource([ ConfigInterface::class => fn () => $config, + EventDispatcherInterface::class => fn () => new Dispatcher(), ]) ); } @@ -634,3 +773,22 @@ public function __invoke($logger) } } } + +class Dispatcher implements EventDispatcherInterface +{ + protected $listener; + + public function dispatch(object $event) + { + if (! $this->listener) { + return; + } + + ($this->listener)($event); + } + + public function listen(string $event, Closure $listener) + { + $this->listener = $listener; + } +}