Prevent the SimpleSAML_Logger class from creating loops while trying to get the track ID from the session. It must now be set manually by calling SimpleSAML_Logger::setTrackID(). Also allow SimpleSAML_Memcache to differentiate between a key not found in memcache and a request to memcache failed. If all servers are down, an exception is thrown and the user informed about the internal error. This hopefully resolves #264.

3 files changed, 172 insertions, 69 deletions

diff --git a/lib/SimpleSAML/Logger.php b/lib/SimpleSAML/Logger.php
index ea20881..7cfe442 100644
--- a/lib/SimpleSAML/Logger.php
+++ b/lib/SimpleSAML/Logger.php
@@ -6,6 +6,7 @@
  *
  * @author Lasse Birnbaum Jensen, SDU.
  * @author Andreas Åkre Solberg, UNINETT AS. <andreas.solberg@uninett.no>
+ * @author Jaime Pérez Crespo, UNINETT AS <jaime.perez@uninett.no>
  * @package SimpleSAMLphp
  * @version $ID$
  */
@@ -44,13 +45,13 @@ class SimpleSAML_Logger
      * This constant defines the string we set the track ID to while we are fetching the track ID from the session
      * class. This is used to prevent infinite recursion.
      */
-    private static $TRACKID_FETCHING = '_NOTRACKIDYET_';
+    const NO_TRACKID = '_NOTRACKIDYET_';
 
     /**
      * This variable holds the track ID we have retrieved from the session class. It can also be NULL, in which case
-     * we haven't fetched the track ID yet, or TRACKID_FETCHING, which means that we are fetching the track ID now.
+     * we haven't fetched the track ID yet, or self::NO_TRACKID, which means that we are fetching the track ID now.
      */
-    private static $trackid = null;
+    private static $trackid = self::NO_TRACKID;
 
     /**
      * This variable holds the format used to log any message. Its use varies depending on the log handler used (for
@@ -81,6 +82,20 @@ class SimpleSAML_Logger
      */
     private static $format = '%date{%b %d %H:%M:%S} %process %level %stat[%trackid] %msg';
 
+    /**
+     * This variable tells if we have a shutdown function registered or not.
+     *
+     * @var bool
+     */
+    private static $shutdownRegistered = false;
+
+    /**
+     * This variable tells if we are shutting down.
+     *
+     * @var bool
+     */
+    private static $shuttingDown = false;
+
     const EMERG = 0;
     const ALERT = 1;
     const CRIT = 2;
@@ -211,6 +226,55 @@ class SimpleSAML_Logger
     }
 
 
+    /**
+     * Set the track identifier to use in all logs.
+     *
+     * @param $trackId string The track identifier to use during this session.
+     */
+    public static function setTrackId($trackId)
+    {
+        self::$trackid = $trackId;
+    }
+
+
+    /**
+     * Flush any pending log messages to the logging handler.
+     *
+     * 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.
+     *
+     */
+    public static function flush()
+    {
+        $s = SimpleSAML_Session::getSessionFromRequest();
+        self::$trackid = $s->getTrackID();
+
+        self::$shuttingDown = true;
+        foreach (self::$earlyLog as $msg) {
+            self::log($msg['level'], $msg['string'], $msg['statsLog']);
+        }
+    }
+
+
+    /**
+     * Defer a message for later logging.
+     *
+     * @param int $level The log level corresponding to this message.
+     * @param string $message The message itself to log.
+     * @param boolean $stats Whether this is a stats message or a regular one.
+     */
+    private static function defer($level, $message, $stats)
+    {
+        // save the message for later
+        self::$earlyLog[] = array('level' => $level, 'string' => $message, 'statsLog' => $stats);
+
+        // register a shutdown handler if needed
+        if (!self::$shutdownRegistered) {
+            register_shutdown_function(array('SimpleSAML_Logger', 'flush'));
+            self::$shutdownRegistered = true;
+        }
+    }
+
     private static function createLoggingHandler()
     {
         // set to FALSE to indicate that it is being initialized
@@ -274,7 +338,7 @@ class SimpleSAML_Logger
             }
             error_log($string);
 
-            self::$earlyLog[] = array('level' => $level, 'string' => $string, 'statsLog' => $statsLog);
+            self::defer($level, $string, $statsLog);
             return;
         }
 
@@ -291,7 +355,7 @@ class SimpleSAML_Logger
             }
 
             $formats = array('%trackid', '%msg', '%srcip', '%stat');
-            $replacements = array(self::getTrackId(), $string, $_SERVER['REMOTE_ADDR']);
+            $replacements = array(self::$trackid, $string, $_SERVER['REMOTE_ADDR']);
 
             $stat = '';
             if ($statsLog) {
@@ -299,39 +363,19 @@ class SimpleSAML_Logger
             }
             array_push($replacements, $stat);
 
+            if (self::$trackid === self::NO_TRACKID && !self::$shuttingDown) {
+                // we have a log without track ID and we are not still shutting down, so defer logging
+                self::defer($level, $string, $statsLog);
+                return;
+            } elseif (self::$trackid === self::NO_TRACKID) {
+                // shutting down without a track ID, prettify it
+                array_shift($replacements);
+                array_unshift($replacements, 'N/A');
+            }
+
+            // we either have a track ID or we are shutting down, so just log the message
             $string = str_replace($formats, $replacements, self::$format);
             self::$loggingHandler->log($level, $string);
         }
     }
-
-
-    /**
-     * Retrieve the track ID we should use for logging. It is used to avoid infinite recursion between the logger class
-     * and the session class.
-     *
-     * @return string The track ID we should use for logging, or 'NA' if we detect recursion.
-     */
-    private static function getTrackId()
-    {
-        if (self::$trackid === self::$TRACKID_FETCHING) {
-            // recursion detected!
-            return 'NA';
-        }
-
-        if (self::$trackid === null) {
-            // no track ID yet, fetch it from the session class
-
-            // mark it as currently being fetched
-            self::$trackid = self::$TRACKID_FETCHING;
-
-            // get the current session. This could cause recursion back to the logger class
-            $session = SimpleSAML_Session::getSessionFromRequest();
-
-            // update the track ID
-            self::$trackid = $session->getTrackID();
-        }
-
-        assert('is_string(self::$trackid)');
-        return self::$trackid;
-    }
 }
diff --git a/lib/SimpleSAML/Memcache.php b/lib/SimpleSAML/Memcache.php
index d6f1e51..5200073 100644
--- a/lib/SimpleSAML/Memcache.php
+++ b/lib/SimpleSAML/Memcache.php
@@ -43,6 +43,7 @@ class SimpleSAML_Memcache
         $latestTime = 0.0;
         $latestData = null;
         $mustUpdate = false;
+        $allDown = true;
 
         // search all the servers for the given id
         foreach (self::getMemcacheServers() as $server) {
@@ -50,8 +51,13 @@ class SimpleSAML_Memcache
             if ($serializedInfo === false) {
                 // either the server is down, or we don't have the value stored on that server
                 $mustUpdate = true;
+                $up = $server->getstats();
+                if ($up !== false) {
+                    $allDown = false;
+                }
                 continue;
             }
+            $allDown = false;
 
             // unserialize the object
             $info = unserialize($serializedInfo);
@@ -105,6 +111,11 @@ class SimpleSAML_Memcache
         }
 
         if ($latestData === null) {
+            if ($allDown) {
+                // all servers are down, panic!
+                $e = new SimpleSAML_Error_Error('MEMCACHEDOWN', null, 503);
+                throw new SimpleSAML_Error_Exception('All memcache servers are down', 503, $e);
+            }
             // we didn't find any data matching the key
             SimpleSAML_Logger::debug("key $key not found in memcache");
             return null;
@@ -266,7 +277,7 @@ class SimpleSAML_Memcache
         }
 
         // add this server to the Memcache object
-        $memcache->addServer($hostname, $port, true, $weight, $timeout);
+        $memcache->addServer($hostname, $port, true, $weight, $timeout, $timeout, true);
     }
 
 
diff --git a/lib/SimpleSAML/Session.php b/lib/SimpleSAML/Session.php
index a8ef4b2..d0a5214 100644
--- a/lib/SimpleSAML/Session.php
+++ b/lib/SimpleSAML/Session.php
@@ -8,6 +8,7 @@
  * Single-Log-Out.
  *
  * @author Andreas Åkre Solberg, UNINETT AS. <andreas.solberg@uninett.no>
+ * @author Jaime Pérez Crespo, UNINETT AS <jaime.perez@uninett.no>
  * @package SimpleSAMLphp
  */
 class SimpleSAML_Session
@@ -32,6 +33,8 @@ class SimpleSAML_Session
 
     /**
      * This variable holds the instance of the session - Singleton approach.
+     *
+     * Warning: do not set the instance manually, call SimpleSAML_Session::load() instead.
      */
     private static $instance = null;
 
@@ -57,9 +60,9 @@ class SimpleSAML_Session
      * This is used in the debug logs and error messages to easily track more information
      * about what went wrong.
      *
-     * @var string|int
+     * @var string|null
      */
-    private $trackid = 0;
+    private $trackid = null;
 
 
     private $rememberMeExpire = null;
@@ -136,34 +139,45 @@ class SimpleSAML_Session
     {
         $this->authData = array();
 
-        if ($transient) {
-            $this->trackid = 'XXXXXXXXXX';
+        if ($transient) { // transient session
+            $sh = SimpleSAML_SessionHandler::getSessionHandler();
+            $this->trackid = 'TR'.bin2hex(openssl_random_pseudo_bytes(4));
+            SimpleSAML_Logger::setTrackId($this->trackid);
             $this->transient = true;
-            return;
-        }
 
-        $sh = SimpleSAML_SessionHandler::getSessionHandler();
-        $this->sessionId = $sh->newSessionId();
+            /*
+             * Initialize the session ID. It might be that we have a session cookie but we couldn't load the session.
+             * If that's the case, use that ID. If not, create a new ID.
+             */
+            $this->sessionId = $sh->getCookieSessionId();
+            if ($this->sessionId === null) {
+                $this->sessionId = $sh->newSessionId();
+            }
 
-        $this->trackid = bin2hex(openssl_random_pseudo_bytes(5));
+        } else { // regular session
+            $sh = SimpleSAML_SessionHandler::getSessionHandler();
+            $this->sessionId = $sh->newSessionId();
 
-        $this->markDirty();
+            $this->trackid = bin2hex(openssl_random_pseudo_bytes(5));
+            SimpleSAML_Logger::setTrackId($this->trackid);
 
-        // initialize data for session check function if defined
-        $globalConfig = SimpleSAML_Configuration::getInstance();
-        $checkFunction = $globalConfig->getArray('session.check_function', null);
-        if (isset($checkFunction)) {
-            assert('is_callable($checkFunction)');
-            call_user_func($checkFunction, $this, true);
+            $this->markDirty();
+
+            // initialize data for session check function if defined
+            $globalConfig = SimpleSAML_Configuration::getInstance();
+            $checkFunction = $globalConfig->getArray('session.check_function', null);
+            if (isset($checkFunction)) {
+                assert('is_callable($checkFunction)');
+                call_user_func($checkFunction, $this, true);
+            }
         }
     }
 
     /**
-     * Retrieves the current session. Will create a new session if there isn't a session.
+     * Retrieves the current session. Creates a new session if there's not one.
      *
      * @return SimpleSAML_Session The current session.
-     * @throws Exception When session couldn't be initialized and
-     * the session fallback is disabled by configuration.
+     * @throws Exception When session couldn't be initialized and the session fallback is disabled by configuration.
      */
     public static function getSessionFromRequest()
     {
@@ -173,35 +187,47 @@ class SimpleSAML_Session
         }
 
         // check if we have stored a session stored with the session handler
+        $prev = (self::$instance !== null);
         try {
-            self::$instance = self::getSession();
+            $session = self::getSession();
+
         } catch (Exception $e) {
             // for some reason, we were unable to initialize this session, use a transient session instead
             self::useTransientSession();
 
+            SimpleSAML_Logger::error('Error loading session: '.$e->getMessage());
             if ($e instanceof SimpleSAML_Error_Exception) {
-                SimpleSAML_Logger::error('Error loading session:');
-                $e->logError();
-            } else {
-                SimpleSAML_Logger::error('Error loading session: '.$e->getMessage());
+                $cause = $e->getCause();
+                if ($cause instanceof Exception) {
+                    throw $cause;
+                }
             }
-
             throw $e;
         }
 
-        if (self::$instance !== null) {
+        // if getSession() found it, use it
+        if ($session !== null) {
+            return self::load($session);
+        }
+
+        /*
+         * We didn't have a session loaded when we started, but we have it now. At this point, getSession() failed but
+         * it must have triggered the creation of a session at some point during the process (e.g. while logging an
+         * error message). This means we don't need to create a new session again, we can use the one that's loaded now
+         * instead.
+         */
+        if (self::$instance !== null && !$prev) {
             return self::$instance;
         }
 
         // create a new session
-        self::$instance = new SimpleSAML_Session();
-        return self::$instance;
+        return self::load(new SimpleSAML_Session());
     }
 
     /**
-     * Load a session from the session handler.
+     * Get a session from the session handler.
      *
-     * @param string|null $sessionId The session we should load, or null to load the current session.
+     * @param string|null $sessionId The session we should get, or null to get the current session.
      *
      * @return SimpleSAML_Session The session that is stored in the session handler, or null if the session wasn't
      * found.
@@ -268,6 +294,24 @@ class SimpleSAML_Session
         return $session;
     }
 
+
+    /**
+     * Load a given session as the current one.
+     *
+     * This method will also set the track ID in the logger to the one in the given session.
+     *
+     * Warning: never set self::$instance yourself, call this method instead.
+     *
+     * @param SimpleSAML_Session $session The session to load.
+     * @return SimpleSAML_Session The session we just loaded, just for convenience.
+     */
+    private static function load(SimpleSAML_Session $session)
+    {
+        SimpleSAML_Logger::setTrackId($session->getTrackID());
+        self::$instance = $session;
+        return self::$instance;
+    }
+
     /**
      * Use a transient session.
      *
@@ -281,7 +325,7 @@ class SimpleSAML_Session
             return;
         }
 
-        self::$instance = new SimpleSAML_Session(true);
+        self::load(new SimpleSAML_Session(true));
     }
 
     /**
@@ -333,6 +377,10 @@ class SimpleSAML_Session
      */
     public function markDirty()
     {
+        if ($this->isTransient()) {
+            return;
+        }
+
         $this->dirty = true;
 
         if (!function_exists('header_register_callback')) {
@@ -383,7 +431,7 @@ class SimpleSAML_Session
      * Get a unique ID that will be permanent for this session.
      * Used for debugging and tracing log files related to a session.
      *
-     * @return string The unique ID.
+     * @return string|null The unique ID.
      */
     public function getTrackID()
     {