Issue #209: SAML2SessionStore cleanup task not scheduled - ipsilon

ipsilon

#209 SAML2SessionStore cleanup task not scheduled

Closed: Fixed None Opened 8 years ago by jgainerdewar.

We're using ipsilon-1.1.1 with saml2 provider on Fedora21, backed by SQLite, and recently noticed that the database cleanup task has not been running on the SAML2SessionStore. There are sessions in the database with expirations dates going back to when we first started using this instance in production. This is resulting in very frequent errors when users try to log out, as the IdP attempts to send logout requests for long-expired sessions to SP's.

After adding additional debug messages, I determined that the cleanup isn't being started because during the time that SAML2SessionStore is initialized, Store._is_upgrade is True.

Here's the state of the code I changed to add debug messages:

ipsilon/util/plugin.py

class PluginObject(log):

    ...

    def enable(self):
        if self.is_enabled:
            return
        self.debug("Enabling %s" % self.name)
        self.refresh_plugin_config()
        is_upgrade = Store._is_upgrade  # pylint: disable=protected-access
        self.debug("Initially Store._is_upgrade is %s" % is_upgrade)
        try:
            Store._is_upgrade = True  # pylint: disable=protected-access
            self.debug("Setting Store._is_upgrade to True")
            self.on_enable()
            self._data.create_plugin_data_table(self.name)
            for store in self.used_datastores():
                store.upgrade_database()
        finally:
            Store._is_upgrade = is_upgrade  # pylint: disable=protected-access
            self.debug("Setting Store._is_upgrade back to %s" % is_upgrade)
        self.is_enabled = True
        self.debug('Plugin enabled: %s' % self.name)

ipsilon/util/data.py

class Store(Log):
    # Static, Store-level variables
    _is_upgrade = False
    __cleanups = {}

    # Static, class-level variables
    # Either set this to False, or implement _cleanup, in child classes
    _should_cleanup = True

    def __init__(self, config_name=None, database_url=None):
        if config_name is None and database_url is None:
            raise ValueError('config_name or database_url must be provided')
        if config_name:
            if config_name not in cherrypy.config:
                raise NameError('Unknown database %s' % config_name)
            name = cherrypy.config[config_name]
        else:
            name = database_url
        if name.startswith('configfile://'):
            _, filename = name.split('://')
            self._db = FileStore(filename)
            self._query = FileQuery
        else:
            self._db = SqlStore.get_connection(name)
            self._query = SqlQuery

        if not self._is_upgrade:
            self._check_database()
            if self._should_cleanup:
                self._schedule_cleanup()
            else:
                self.debug('Not scheduling cleanup for %s due to shouldnt' % self.__class__.__name__)
        else:
            self.debug('Not scheduling cleanup for %s due to upgrade' % self.__class__.__name__)

    def _schedule_cleanup(self):
        store_name = self.__class__.__name__
        if self.is_readonly:
            # No use in cleanups on a readonly database
            self.debug('Not scheduling cleanup for %s due to readonly' %
                       store_name)
            return
        if store_name in Store.__cleanups:
            # This class was already scheduled, skip
            self.debug('Not scheduling cleanup for %s due to in __cleanups' % self.__class__.__name__)
            return
        self.debug('Scheduling cleanups for %s' % store_name)
        # Check once every minute whether we need to clean
        task = cherrypy.process.plugins.BackgroundTask(
            60, self._maybe_run_cleanup)
        task.start()
        Store.__cleanups[store_name] = task

Here is the log output related to this issue after a restart, covering the first login via web interface. Timestamps removed for brevity. TranStore is the only data store that cleanups are scheduled for.

DEBUG(ipsilon/util/plugin.py:155 IdpProvider.enable()): Initially saml2._is_upgrade is False
DEBUG(ipsilon/util/plugin.py:158 IdpProvider.enable()): Setting Store._is_upgrade to True
DEBUG(ipsilon/util/data.py:336 SAML2SessionStore.__init__()): Not scheduling cleanup for SAML2SessionStore due to upgrade
DEBUG(ipsilon/util/plugin.py:165 IdpProvider.enable()): Setting saml2._is_upgrade back to False
ENGINE Started monitor thread 'Session cleanup'.
DEBUG(ipsilon/util/data.py:349 TranStore._schedule_cleanup()): Scheduling cleanups for TranStore
DEBUG(ipsilon/util/data.py:347 TranStore._schedule_cleanup()): Not scheduling cleanup for TranStore due to in __cleanups
DEBUG(ipsilon/util/data.py:364 TranStore._maybe_run_cleanup()): Considering cleanup for TranStore: {u'timestamp': u'1456178710', u'removed_entries': u'0'}. Next at: 1456178351

It looks like things are designed so that we schedule cleanups for SAML2SessionStore later when it is next initialized, but this never happens.