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

@@ -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) {