From 857ca0b0abe4e90cf166ef70fee685af72c68b3f Mon Sep 17 00:00:00 2001 From: Mark Armendariz Date: Fri, 3 May 2019 17:58:12 -0500 Subject: [PATCH] Moved Span Metadata into a class for consistancy and clarity --- dev/log.php | 17 +++++++ src/Log.php | 142 ++++++++++++++++++++++++++++++---------------------- 2 files changed, 99 insertions(+), 60 deletions(-) create mode 100644 dev/log.php diff --git a/dev/log.php b/dev/log.php new file mode 100644 index 0000000..90fff2a --- /dev/null +++ b/dev/log.php @@ -0,0 +1,17 @@ + 'persisted']); + Log::d('Debug!', ['context' => 'whatever']); + Log::i('Info!', ['context' => 'whatever']); + Log::n('Notice!', ['context' => 'whatever']); + Log::w('Warning!', ['context' => 'whatever']); + Log::setProcessIsError(true); + Log::e('Error!', ['context' => 'whatever']); + Log::c('Critical!', ['context' => 'whatever']); + Log::dt($oTimer); + Log::summary(); diff --git a/src/Log.php b/src/Log.php index e355b2a..7b8eff9 100644 --- a/src/Log.php +++ b/src/Log.php @@ -1,6 +1,7 @@ false, 'dt' => false ]; - const TIMESTAMP_FORMAT = DATE_RFC3339_EXTENDED; - /** * @return Monolog\Logger */ @@ -99,7 +99,6 @@ private static function prepareContext(string $sMessage, array $aContext = []): ]); $sRequestHash = self::getCurrentRequestHash(); - $oLocalContext = new Dot(self::$aSettings[$sRequestHash]['context']); if ($aContext && is_array($aContext) && count($aContext)) { foreach ($aContext as $sKey => $mValue) { @@ -117,16 +116,16 @@ private static function prepareContext(string $sMessage, array $aContext = []): $aContext[$sStrippedKey] = $mValue; unset($aContext[$sKey]); - $oLocalContext->mergeRecursiveDistinct($sStrippedKey, $mValue); + self::$aSpanMetas[$sRequestHash]->Context->mergeRecursiveDistinct($sStrippedKey, $mValue); } } + /** @noinspection NotOptimalIfConditionsInspection */ if (count($aContext)) { $oLog->mergeRecursiveDistinct($sMessage, $aContext); } } - self::$aSettings[$sRequestHash]['context'] = $oLocalContext->all(); return $oLog->all(); } @@ -144,33 +143,25 @@ public static function justAddContext(array $aContext): void { self::prepareContext('', $aContext); } - /** - * @param string $sTag - * @param mixed $mValue - */ - public static function addTag(string $sTag, $mValue): void { - self::$aSettings[self::getCurrentRequestHash()]['tags'][$sTag] = $mValue; - } - /** * @param bool $bIsError */ public static function setProcessIsError(bool $bIsError): void { - self::$aSettings[self::getCurrentRequestHash()]['error'] = $bIsError; + self::$aSpanMetas[self::getCurrentRequestHash()]->setError($bIsError); } /** * @param string $sPurpose */ public static function setPurpose(string $sPurpose): void { - self::$aSettings[self::getCurrentRequestHash()]['name'] = $sPurpose; + self::$aSpanMetas[self::getCurrentRequestHash()]->setName($sPurpose); } /** * @return bool */ public static function hasPurpose(): bool { - return !empty(self::$aSettings[self::getCurrentRequestHash()]['name']); + return self::$aSpanMetas[self::getCurrentRequestHash()]->hasName(); } private static function incrementCurrentIndex(): void { @@ -190,10 +181,6 @@ private static function getCurrentSpan(): array { return self::$aSpans[count(self::$aSpans) - 1]; } - private static function getCurrentSettings(): array { - return self::$aSettings[self::getCurrentRequestHash()]; - } - public static function enableJSON(): void { self::$bJSONLogs = true; } @@ -319,7 +306,7 @@ public static function dt(TimeKeeper $oTimer, array $aContext = []): void { * @return TimeKeeper */ public static function startTimer(string $sLabel): TimeKeeper { - return self::$aSettings[self::getCurrentRequestHash()]['metrics']->start($sLabel); + return self::$aSpanMetas[self::getCurrentRequestHash()]->Timer->start($sLabel); } /** @@ -328,7 +315,7 @@ public static function startTimer(string $sLabel): TimeKeeper { * @return float */ public static function stopTimer(string $sLabel): float { - return self::$aSettings[self::getCurrentRequestHash()]['metrics']->stop($sLabel); + return self::$aSpanMetas[self::getCurrentRequestHash()]->Timer->stop($sLabel); } /** @@ -349,13 +336,12 @@ public static function getThreadHashForOutput(): string { * Sets the Parent Hash to the current Hash, and then resets the Request Hash */ public static function startChildRequest(): void { - $aContext = []; - $aSettings = self::getCurrentSettings(); - if (isset($aSettings['context']['user'])) { - $aContext['user'] = $aSettings['context']['user']; + $aUser = []; + if (self::$aSpanMetas[self::getCurrentRequestHash()]->Context->has('user')) { + $aUser = self::$aSpanMetas[self::getCurrentRequestHash()]->Context->get('user'); } - self::initSpan(self::$oServerRequest, $aContext); + self::initSpan(self::$oServerRequest, $aUser); } /** @@ -410,7 +396,7 @@ private static function getThreadHash(): string { $aServerParams = self::$oServerRequest->getServerParams(); if ($aServerParams && isset($aServerParams['NGINX_REQUEST_ID'])) { // NGINX Request ID should be last because that should always be set, but - // We prefer to use any thread hash sent in from another proces + // We prefer to use any thread hash sent in from another process self::$sThreadHash = $aServerParams['NGINX_REQUEST_ID']; return self::$sThreadHash; } @@ -418,7 +404,7 @@ private static function getThreadHash(): string { if (isset($_SERVER['NGINX_REQUEST_ID'])) { // NGINX Request ID should be last because that should always be set, but - // We prefer to use any thread hash sent in from another proces + // We prefer to use any thread hash sent in from another process self::$sThreadHash = $_SERVER['NGINX_REQUEST_ID']; return self::$sThreadHash; } @@ -501,9 +487,9 @@ private static function getParentHash(): ?string { /** * @param ServerRequestInterface $oRequest - * @param array $aContext + * @param array $aUser */ - public static function initSpan(ServerRequestInterface $oRequest, array $aContext = []): void { + public static function initSpan(ServerRequestInterface $oRequest, array $aUser = []): void { self::$oServerRequest = $oRequest; $oStartTime = notNowButRightNow(); @@ -518,7 +504,7 @@ public static function initSpan(ServerRequestInterface $oRequest, array $aContex if (isset($aServerParams['REQUEST_URI'])) { $aRequestDetails['uri'] = $aServerParams['REQUEST_URI']; } if (isset($aServerParams['HTTP_HOST'])) { $aRequestDetails['host'] = $aServerParams['HTTP_HOST']; } if (isset($aServerParams['HTTP_USER_AGENT'])) { $aRequestDetails['agent'] = $aServerParams['HTTP_USER_AGENT']; } - if ($sIP != 'unknown') { $aRequestDetails['ip'] = $sIP; } + if ($sIP !== 'unknown') { $aRequestDetails['ip'] = $sIP; } /* $aPath = array_column(self::$aSpans, '--r'); @@ -532,14 +518,7 @@ public static function initSpan(ServerRequestInterface $oRequest, array $aContex '--r' => $sRequestHash ]; - self::$aSettings[$sRequestHash] = [ - 'name' => '', - 'start_timestamp' => $oStartTime->format(self::TIMESTAMP_FORMAT), - 'error' => false, - 'tags' => [], - 'context' => $aContext, - 'metrics' => new Timer() - ]; + self::$aSpanMetas[$sRequestHash] = new SpanMeta($oStartTime); if ($sThreadHash = Log::getThreadHash()) { $aSpan['--t'] = $sThreadHash; @@ -551,8 +530,6 @@ public static function initSpan(ServerRequestInterface $oRequest, array $aContex $aSpan['--p'] = $sParentHash; } - $aUser = []; - if ($sIP) { $aUser['ip'] = $sIP; } @@ -562,7 +539,7 @@ public static function initSpan(ServerRequestInterface $oRequest, array $aContex } if (count($aUser)) { - self::$aSettings[$sRequestHash]['context']['user'] = isset(self::$aSettings[$sRequestHash]['context']['user']) ? array_merge(self::$aSettings[$sRequestHash]['context']['user'], $aUser) : $aUser; + self::$aSpanMetas[$sRequestHash]->Context->mergeRecursiveDistinct(['user' => $aUser]); } self::$aSpans[] = $aSpan; @@ -576,25 +553,14 @@ public static function initSpan(ServerRequestInterface $oRequest, array $aContex */ public static function summary(string $sOverrideName = 'Summary'): void { self::incrementCurrentIndex(); - $iTimer = self::stopTimer('_REQUEST'); - $aSettings = self::getCurrentSettings(); - $aSettings['metrics'] = json_encode($aSettings['metrics']->stats()); - + $iTimer = self::stopTimer('_REQUEST'); $aMessage = array_merge( self::prepareContext( self::$sService . '.' . $sOverrideName, [ - '--ms' => $iTimer, - '--summary' => true, - '--span' => array_merge( - [ - '_format' => 'SSFSpan.DashedTrace', - 'version' => 1, - 'end_timestamp' => notNowButRightNow()->format(self::TIMESTAMP_FORMAT), - 'service' => self::$sService - ], - $aSettings - ) + '--ms' => $iTimer, + '--summary' => true, + '--span' => self::$aSpanMetas[self::getCurrentRequestHash()]->getMessage(self::$sService) ] ), self::getCurrentSpan() @@ -604,4 +570,60 @@ public static function summary(string $sOverrideName = 'Summary'): void { } } + class SpanMeta { + const TIMESTAMP_FORMAT = DATE_RFC3339_EXTENDED; + + // const VERSION = 1: included tags, which were not used + const VERSION = 2; + + /** @var string */ + private $sName; + + /** @var DateTime */ + private $oStart; + + /** @var bool */ + private $bError; + + /** @var Dot */ + public $Context; + + /** @var Timer */ + public $Timer; + + public function __construct(DateTime $oStart) { + $this->sName = ''; + $this->oStart = $oStart; + $this->bError = false; + $this->Context = new Dot(); + $this->Timer = new Timer(); + } + + public function setName(string $sName):void { + $this->sName = $sName; + } + + public function setError(bool $bError):void { + $this->bError = $bError; + } + + public function hasName():bool { + return !empty($this->sName); + } + + public function getMessage(string $sService) { + return [ + '_format' => 'SSFSpan.DashedTrace', + 'version' => self::VERSION, + 'service' => $sService, + 'name' => $this->sName, + 'start_timestamp' => $this->oStart->format(self::TIMESTAMP_FORMAT), + 'end_timestamp' => notNowButRightNow()->format(self::TIMESTAMP_FORMAT), + 'error' => $this->bError, + 'context' => $this->Context->all(), + 'metrics' => json_encode($this->Timer->stats()) + ]; + } + } + Log::initSpan(ServerRequestFactory::fromGlobals()); \ No newline at end of file