Skip to content

Commit

Permalink
Moved Span Metadata into a class for consistancy and clarity
Browse files Browse the repository at this point in the history
  • Loading branch information
@enobrev
enobrev committed May 3, 2019
1 parent 56f863a commit 857ca0b
Show file tree
Hide file tree
Showing 2 changed files with 99 additions and 60 deletions.
17 changes: 17 additions & 0 deletions dev/log.php
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,17 @@
<?php
namespace Enobrev;

require __DIR__ . '/../vendor/autoload.php';

Log::setPurpose('Testing Log!');
$oTimer = Log::startTimer('test');
Log::justAddContext(['#persist' => '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();
142 changes: 82 additions & 60 deletions src/Log.php
View file
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
<?php
namespace Enobrev;

use DateTime;
use Adbar\Dot;
use Monolog;
use Monolog\Formatter\LineFormatter;
Expand All @@ -27,19 +28,18 @@ class Log {
/** @var array */
private static $aSpans = [];

/** @var array */
private static $aSettings = [];
/** @var SpanMeta[] */
private static $aSpanMetas = [];

/** @var int */
private static $iGlobalIndex = 0;

/** @var array */
private static $aDisabled = [
'd' => false,
'dt' => false
];

const TIMESTAMP_FORMAT = DATE_RFC3339_EXTENDED;

/**
* @return Monolog\Logger
*/
Expand Down Expand Up @@ -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) {
Expand All @@ -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();
}

Expand 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 {
Expand All @@ -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;
}
Expand Down Expand Up @@ -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);
}

/**
Expand All @@ -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);
}

/**
Expand All @@ -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);
}

/**
Expand Down Expand Up @@ -410,15 +396,15 @@ 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;
}
}

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;
}
Expand Down Expand Up @@ -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();
Expand All @@ -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');
Expand All @@ -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;
Expand All @@ -551,8 +530,6 @@ public static function initSpan(ServerRequestInterface $oRequest, array $aContex
$aSpan['--p'] = $sParentHash;
}

$aUser = [];

if ($sIP) {
$aUser['ip'] = $sIP;
}
Expand All @@ -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;
Expand All @@ -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()
Expand All @@ -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());

0 comments on commit 857ca0b

Please sign in to comment.