From 014992c841072b2f4cd0cbeeb32f8ee6502efb49 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Jaime=20Pe=CC=81rez=20Crespo?= <jaime.perez@uninett.no>
Date: Thu, 29 Aug 2019 10:54:55 +0200
Subject: [PATCH] Make sure we respect log message order
When we are logging something and the logger hasn't been initialized, the messages are deferred and flushed by a shutdown handler. However, when we initialize a session, we set the track ID in the logger, effectively initializing it with everything we need. When we log something and then load the session (or create it), any subsequent logs will be dumped, but the deferred logs will wait until shutdown, changing the order in which they were emitted.
This patch makes sure we flush the deferred logs as soon as we have a track ID (can either be set manually or by, most typically, loading a session). That way, we get those logs out as soon as we can, and subsequent logs entries will be dumped afterwards, keeping their relative order.
This closes #1107
---
lib/SimpleSAML/Logger.php | 48 +++++++++++++++++++++++----------------
1 file changed, 28 insertions(+), 20 deletions(-)
diff --git a/lib/SimpleSAML/Logger.php b/lib/SimpleSAML/Logger.php
index 229522908..66173300e 100644
--- a/lib/SimpleSAML/Logger.php
+++ b/lib/SimpleSAML/Logger.php
@@ -283,32 +283,46 @@ class Logger
public static function setTrackId($trackId)
{
self::$trackid = $trackId;
+ self::flush();
}
/**
* Flush any pending log messages to the logging handler.
*
+ * @return void
+ */
+ public static function flush()
+ {
+ foreach (self::$earlyLog as $msg) {
+ self::log($msg['level'], $msg['string'], $msg['statsLog']);
+ }
+ self::$earlyLog = [];
+ }
+
+
+ /**
+ * Flush any pending deferred logs during shutdown.
+ *
* This method is intended to be registered as a shutdown handler, so that any pending messages that weren't sent
* to the logging handler at that point, can still make it. It is therefore not intended to be called manually.
*
* @return void
*/
- public static function flush()
+ public static function shutdown()
{
- try {
- $s = Session::getSessionFromRequest();
- } catch (\Exception $e) {
- // loading session failed. We don't care why, at this point we have a transient session, so we use that
- self::error('Cannot load or create session: '.$e->getMessage());
- $s = Session::getSessionFromRequest();
+ if (self::$trackid === self::NO_TRACKID) {
+ try {
+ $s = Session::getSessionFromRequest();
+ } catch (\Exception $e) {
+ // loading session failed. We don't care why, at this point we have a transient session, so we use that
+ self::error('Cannot load or create session: '.$e->getMessage());
+ $s = Session::getSessionFromRequest();
+ }
+ self::$trackid = $s->getTrackID();
}
- self::$trackid = $s->getTrackID();
-
self::$shuttingDown = true;
- foreach (self::$earlyLog as $msg) {
- self::log($msg['level'], $msg['string'], $msg['statsLog']);
- }
+ self::flush();
}
@@ -376,7 +390,7 @@ class Logger
// register a shutdown handler if needed
if (!self::$shutdownRegistered) {
- register_shutdown_function([self::class, 'flush']);
+ register_shutdown_function([self::class, 'shutdown']);
self::$shutdownRegistered = true;
}
}
@@ -455,13 +469,7 @@ class Logger
} elseif (self::$loggingHandler === null) {
// Initialize logging
self::createLoggingHandler();
-
- if (!empty(self::$earlyLog)) {
- // output messages which were logged before we properly initialized logging
- foreach (self::$earlyLog as $msg) {
- self::log($msg['level'], $msg['string'], $msg['statsLog']);
- }
- }
+ self::flush();
}
if (self::$captureLog) {
--
GitLab