DB cleanup

[Janet Gainer-Dewar]

Hi all,

We're running Ipsilon 1.1.1 on Fedora 21 and have been dealing with
increasingly-frequent errors on logout (SP doesn't recognize session index)
that we've traced to a lack of SAML session db cleanup. Old sessions are
never removed from the database, so when a user logs out, the IdP attempts
to log them out of every session ever left in "logged in" state by that
user. The SP doesn't recognize the expired session indexes and throws an
error.

Reading through the code, it looks like the SAML2SessionStore should have
expired sessions removed from it regularly by a CherryPy background task.
As far as we can tell, this task has never run. I opened up the
saml2.sessions SQLite file and the dbinfo table has no data besides the
schema version. The rows tracking the last cleanup run are not there.

We haven't had any luck figuring out why cleanup isn't running - can you
think of anything obvious we should check? I'm confirmed that our config
file has the default value of 30 for cleanup_interval.

We've been running in debug mode looking for messages about scheduling, or
not scheduling, cleanup, and haven't seen anything. I'm not confident we're
looking at the right logs - does CherryPy debug logging go something other
than the Apache logs dir?

Let me know if there's anything else I can tell you.

Thanks,
Janet

[Patrick Uiterwijk]

Hi,
> Hi all,

...
> We've been running in debug mode looking for messages about scheduling, or
> not scheduling, cleanup, and haven't seen anything. I'm not confident we're
> looking at the right logs - does CherryPy debug logging go something other
> than the Apache logs dir?

The logs will go to the Apache Error Log if you set debug = True in
/etc/ipsilon/idp/ipsilon.conf.

The cleanups should be scheduled once, on the very first request that happens
to Ipsilon, so if you tail the error log, you should see the Scheduling messages
as part of the very first request.

What database backend are you using? Sqlite or another type of database server?
> Let me know if there's anything else I can tell you.
>
> Thanks,
> Janet

With kind regards,
Patrick Uiterwijk
Ipsilon Contributor
Fedora Infra

[Janet Gainer-Dewar]

Hi Patrick,

I've set debug=True in /etc/ipsilon/idp/ipsilon.conf and don't see any
Ipsilon-generated debug messages in the Apache error logs on restart.

$ head -n 3 /etc/ipsilon/idp/ipsilon.conf
[global]
debug = True
tools.log_request_response.on = False

$ sudo systemctl restart httpd

$ tail -f /etc/httpd/logs/error_log
[Sun Feb 21 18:20:40.036535 2016] [mpm_prefork:notice] [pid 1662] AH00170:
caught SIGWINCH, shutting down gracefully
[Sun Feb 21 18:20:41.140473 2016] [suexec:notice] [pid 32618] AH01232:
suEXEC mechanism enabled (wrapper: /usr/sbin/suexec)
[Sun Feb 21 18:20:41.159765 2016] [auth_digest:notice] [pid 32618] AH01757:
generating secret for digest authentication ...
[Sun Feb 21 18:20:41.160488 2016] [lbmethod_heartbeat:notice] [pid 32618]
AH02282: No slotmem from mod_heartmonitor
[Sun Feb 21 18:20:41.167307 2016] [mpm_prefork:notice] [pid 32618] AH00163:
Apache/2.4.16 (Fedora) OpenSSL/1.0.1k-fips mod_auth_gssapi/1.3.0
mod_wsgi/4.4.1 Python/2.7.8 configured -- resuming normal operations
[Sun Feb 21 18:20:41.167392 2016] [core:notice] [pid 32618] AH00094:
Command line: '/usr/sbin/httpd -D FOREGROUND'

That log output includes the time during which I was logging in and out via
the web interface. I did see the full request/response bodies logged to
that file when I had tools.log_request_response.on set to True, so I'm
pretty sure I'm looking at the right file.

We're using SQLite. Should have mentioned before, I believe cleanup has not
run not just because dbinfo doesn't have the expected information, but
because we have sessions in the database with expiration dates going back
to when we first started using this Ipsilon instance in production this
past December.

Thanks,
Janet

On Sun, Feb 21, 2016 at 5:43 AM, Patrick Uiterwijk 
wrote:
> Hi,
> > Hi all,
>
> ...
> > We've been running in debug mode looking for messages about scheduling,
>
> or
> > not scheduling, cleanup, and haven't seen anything. I'm not confident
>
> we're
> > looking at the right logs - does CherryPy debug logging go something
>
> other
> > than the Apache logs dir?
>
> The logs will go to the Apache Error Log if you set debug = True in
> /etc/ipsilon/idp/ipsilon.conf.
>
> The cleanups should be scheduled once, on the very first request that
> happens
> to Ipsilon, so if you tail the error log, you should see the Scheduling
> messages
> as part of the very first request.
>
> What database backend are you using? Sqlite or another type of database
> server?
> > Let me know if there's anything else I can tell you.
> >
> > Thanks,
> > Janet
>
> With kind regards,
> Patrick Uiterwijk
> Ipsilon Contributor
> Fedora Infra
> _______________________________________________
> ipsilon mailing list
> [e-mail]
> https://lists.fedorahosted.org/admin/lists/[e-mail]

[Rob Crittenden]

Janet Gainer-Dewar wrote:
> Hi Patrick,
>
> I've set debug=True in /etc/ipsilon/idp/ipsilon.conf and don't see any
> Ipsilon-generated debug messages in the Apache error logs on restart.
>
> $ head -n 3 /etc/ipsilon/idp/ipsilon.conf
> [global]
> debug = True
> tools.log_request_response.on = False

Try adding this to ipsilon.conf:

cherrypy.log.screen = True

Then restart httpd.

rob
> $ sudo systemctl restart httpd
>
> $ tail -f /etc/httpd/logs/error_log
> [Sun Feb 21 18:20:40.036535 2016] [mpm_prefork:notice] [pid 1662]
> AH00170: caught SIGWINCH, shutting down gracefully
> [Sun Feb 21 18:20:41.140473 2016] [suexec:notice] [pid 32618] AH01232:
> suEXEC mechanism enabled (wrapper: /usr/sbin/suexec)
> [Sun Feb 21 18:20:41.159765 2016] [auth_digest:notice] [pid 32618]
> AH01757: generating secret for digest authentication ...
> [Sun Feb 21 18:20:41.160488 2016] [lbmethod_heartbeat:notice] [pid
> 32618] AH02282: No slotmem from mod_heartmonitor
> [Sun Feb 21 18:20:41.167307 2016] [mpm_prefork:notice] [pid 32618]
> AH00163: Apache/2.4.16 (Fedora) OpenSSL/1.0.1k-fips
> mod_auth_gssapi/1.3.0 mod_wsgi/4.4.1 Python/2.7.8 configured -- resuming
> normal operations
> [Sun Feb 21 18:20:41.167392 2016] [core:notice] [pid 32618] AH00094:
> Command line: '/usr/sbin/httpd -D FOREGROUND'
>
> That log output includes the time during which I was logging in and out
> via the web interface. I did see the full request/response bodies logged
> to that file when I had tools.log_request_response.on set to True, so
> I'm pretty sure I'm looking at the right file.
>
> We're using SQLite. Should have mentioned before, I believe cleanup has
> not run not just because dbinfo doesn't have the expected information,
> but because we have sessions in the database with expiration dates going
> back to when we first started using this Ipsilon instance in production
> this past December.
>
> Thanks,
> Janet
>
> On Sun, Feb 21, 2016 at 5:43 AM, Patrick Uiterwijk
> <[e-mail] > wrote:
> Hi,
> > Hi all,
> >
> ...
> >
> > We've been running in debug mode looking for messages about scheduling, or
> > not scheduling, cleanup, and haven't seen anything. I'm not confident we're
> > looking at the right logs - does CherryPy debug logging go something other
> > than the Apache logs dir?
>
> The logs will go to the Apache Error Log if you set debug = True in
> /etc/ipsilon/idp/ipsilon.conf.
>
> The cleanups should be scheduled once, on the very first request
> that happens
> to Ipsilon, so if you tail the error log, you should see the
> Scheduling messages
> as part of the very first request.
>
> What database backend are you using? Sqlite or another type of
> database server?
>
> >
> > Let me know if there's anything else I can tell you.
> >
> > Thanks,
> > Janet
> >
>
> With kind regards,
> Patrick Uiterwijk
> Ipsilon Contributor
> Fedora Infra
> _______________________________________________
> ipsilon mailing list
> [e-mail] <mailto:[e-mail]>
> https://lists.fedorahosted.org/admin/lists/[e-mail]
>
>
>
>
> ipsilon mailing list
> [e-mail]
> https://lists.fedorahosted.org/admin/lists/[e-mail]

[Janet Gainer-Dewar]

Thanks, Rob, that's what I was missing!

Now that I have the debug output, I can see that cleanup is never scheduled
for SAML2SessionStore. I added a few additional debug messages and
determined that this is because _is_upgrade=True on that data store.

It looks like the SAML2SessionStore is first initialized, and its cleanup
is scheduled (or not), during the saml2 plugin enabling process.
Store._is_upgrade is set to True before the plugin is enabled, then set
back to its original value when enabling is complete
(ipsilon/util/plugin.py, lines 156-162). Since SAML2SessionStore is created
during plugin enabling when Store._is_upgrade is True, cleanup is not
scheduled.

This seems like a bug, but I could be missing something. I'm happy to file
a ticket if you like.

Janet

On Mon, Feb 22, 2016 at 9:36 AM, Rob Crittenden  wrote:
> Janet Gainer-Dewar wrote:
> > Hi Patrick,
> >
> > I've set debug=True in /etc/ipsilon/idp/ipsilon.conf and don't see any
> > Ipsilon-generated debug messages in the Apache error logs on restart.
> >
> > $ head -n 3 /etc/ipsilon/idp/ipsilon.conf
> > [global]
> > debug = True
> > tools.log_request_response.on = False
>
> Try adding this to ipsilon.conf:
>
> cherrypy.log.screen = True
>
> Then restart httpd.
>
> rob
> > $ sudo systemctl restart httpd
> >
> > $ tail -f /etc/httpd/logs/error_log
> > [Sun Feb 21 18:20:40.036535 2016] [mpm_prefork:notice] [pid 1662]
> > AH00170: caught SIGWINCH, shutting down gracefully
> > [Sun Feb 21 18:20:41.140473 2016] [suexec:notice] [pid 32618] AH01232:
> > suEXEC mechanism enabled (wrapper: /usr/sbin/suexec)
> > [Sun Feb 21 18:20:41.159765 2016] [auth_digest:notice] [pid 32618]
> > AH01757: generating secret for digest authentication ...
> > [Sun Feb 21 18:20:41.160488 2016] [lbmethod_heartbeat:notice] [pid
> > 32618] AH02282: No slotmem from mod_heartmonitor
> > [Sun Feb 21 18:20:41.167307 2016] [mpm_prefork:notice] [pid 32618]
> > AH00163: Apache/2.4.16 (Fedora) OpenSSL/1.0.1k-fips
> > mod_auth_gssapi/1.3.0 mod_wsgi/4.4.1 Python/2.7.8 configured -- resuming
> > normal operations
> > [Sun Feb 21 18:20:41.167392 2016] [core:notice] [pid 32618] AH00094:
> > Command line: '/usr/sbin/httpd -D FOREGROUND'
> >
> > That log output includes the time during which I was logging in and out
> > via the web interface. I did see the full request/response bodies logged
> > to that file when I had tools.log_request_response.on set to True, so
> > I'm pretty sure I'm looking at the right file.
> >
> > We're using SQLite. Should have mentioned before, I believe cleanup has
> > not run not just because dbinfo doesn't have the expected information,
> > but because we have sessions in the database with expiration dates going
> > back to when we first started using this Ipsilon instance in production
> > this past December.
> >
> > Thanks,
> > Janet
> >
> > On Sun, Feb 21, 2016 at 5:43 AM, Patrick Uiterwijk
> > <[e-mail] > wrote:
> > Hi,
> > > Hi all,
> > >
> > ...
> > >
> > > We've been running in debug mode looking for messages about
>
> scheduling, or
> > > not scheduling, cleanup, and haven't seen anything. I'm not
>
> confident we're
> > > looking at the right logs - does CherryPy debug logging go
>
> something other
> > > than the Apache logs dir?
> >
> > The logs will go to the Apache Error Log if you set debug = True in
> > /etc/ipsilon/idp/ipsilon.conf.
> >
> > The cleanups should be scheduled once, on the very first request
> > that happens
> > to Ipsilon, so if you tail the error log, you should see the
> > Scheduling messages
> > as part of the very first request.
> >
> > What database backend are you using? Sqlite or another type of
> > database server?
> >
> > >
> > > Let me know if there's anything else I can tell you.
> > >
> > > Thanks,
> > > Janet
> > >
> >
> > With kind regards,
> > Patrick Uiterwijk
> > Ipsilon Contributor
> > Fedora Infra
> > _______________________________________________
> > ipsilon mailing list
> > [e-mail] <mailto:
>
> [e-mail]>
> >
>
> https://lists.fedorahosted.org/admin/lists/[e-mail]
> > ipsilon mailing list
> > [e-mail]
>
> https://lists.fedorahosted.org/admin/lists/[e-mail]
> >
>
> ipsilon mailing list
> [e-mail]
> https://lists.fedorahosted.org/admin/lists/[e-mail]

[Rob Crittenden]

Janet Gainer-Dewar wrote:
> Thanks, Rob, that's what I was missing!
>
> Now that I have the debug output, I can see that cleanup is never
> scheduled for SAML2SessionStore. I added a few additional debug messages
> and determined that this is because _is_upgrade=True on that data store.
>
> It looks like the SAML2SessionStore is first initialized, and its
> cleanup is scheduled (or not), during the saml2 plugin enabling process.
> Store._is_upgrade is set to True before the plugin is enabled, then set
> back to its original value when enabling is complete
> (ipsilon/util/plugin.py, lines 156-162). Since SAML2SessionStore is
> created during plugin enabling when Store._is_upgrade is True, cleanup
> is not scheduled.
>
> This seems like a bug, but I could be missing something. I'm happy to
> file a ticket if you like.

Sure. It might be interesting to see some of the logging too.

rob
> Janet
>
> On Mon, Feb 22, 2016 at 9:36 AM, Rob Crittenden <[e-mail]
> > wrote:
> Janet Gainer-Dewar wrote:
> > Hi Patrick,
> >
> > I've set debug=True in /etc/ipsilon/idp/ipsilon.conf and don't see any
> > Ipsilon-generated debug messages in the Apache error logs on restart.
> >
> > $ head -n 3 /etc/ipsilon/idp/ipsilon.conf
> > [global]
> > debug = True
> > tools.log_request_response.on = False
>
> Try adding this to ipsilon.conf:
>
> cherrypy.log.screen = True
>
> Then restart httpd.
>
> rob
>
> >
> > $ sudo systemctl restart httpd
> >
> > $ tail -f /etc/httpd/logs/error_log
> > [Sun Feb 21 18:20:40.036535 2016] [mpm_prefork:notice] [pid 1662]
> > AH00170: caught SIGWINCH, shutting down gracefully
> > [Sun Feb 21 18:20:41.140473 2016] [suexec:notice] [pid 32618] AH01232:
> > suEXEC mechanism enabled (wrapper: /usr/sbin/suexec)
> > [Sun Feb 21 18:20:41.159765 2016] [auth_digest:notice] [pid 32618]
> > AH01757: generating secret for digest authentication ...
> > [Sun Feb 21 18:20:41.160488 2016] [lbmethod_heartbeat:notice] [pid
> > 32618] AH02282: No slotmem from mod_heartmonitor
> > [Sun Feb 21 18:20:41.167307 2016] [mpm_prefork:notice] [pid 32618]
> > AH00163: Apache/2.4.16 (Fedora) OpenSSL/1.0.1k-fips
> > mod_auth_gssapi/1.3.0 mod_wsgi/4.4.1 Python/2.7.8 configured --
> resuming
> > normal operations
> > [Sun Feb 21 18:20:41.167392 2016] [core:notice] [pid 32618] AH00094:
> > Command line: '/usr/sbin/httpd -D FOREGROUND'
> >
> > That log output includes the time during which I was logging in
> and out
> > via the web interface. I did see the full request/response bodies
> logged
> > to that file when I had tools.log_request_response.on set to True, so
> > I'm pretty sure I'm looking at the right file.
> >
> > We're using SQLite. Should have mentioned before, I believe
> cleanup has
> > not run not just because dbinfo doesn't have the expected information,
> > but because we have sessions in the database with expiration dates
> going
> > back to when we first started using this Ipsilon instance in
> production
> > this past December.
> >
> > Thanks,
> > Janet
> >
> > On Sun, Feb 21, 2016 at 5:43 AM, Patrick Uiterwijk
> > <[e-mail] <mailto:[e-mail]>
> <mailto:[e-mail] <mailto:[e-mail]>>> wrote:
> >
> >     Hi,
> >     > Hi all,
> >     >
> >     ...
> >     >
> >     > We've been running in debug mode looking for messages about
> scheduling, or
> >     > not scheduling, cleanup, and haven't seen anything. I'm not
> confident we're
> >     > looking at the right logs - does CherryPy debug logging go
> something other
> >     > than the Apache logs dir?
> >
> >     The logs will go to the Apache Error Log if you set debug =
> True in
> >     /etc/ipsilon/idp/ipsilon.conf.
> >
> >     The cleanups should be scheduled once, on the very first request
> >     that happens
> >     to Ipsilon, so if you tail the error log, you should see the
> >     Scheduling messages
> >     as part of the very first request.
> >
> >     What database backend are you using? Sqlite or another type of
> >     database server?
> >
> >     >
> >     > Let me know if there's anything else I can tell you.
> >     >
> >     > Thanks,
> >     > Janet
> >     >
> >
> >     With kind regards,
> >     Patrick Uiterwijk
> >     Ipsilon Contributor
> >     Fedora Infra
> >     _______________________________________________
> >     ipsilon mailing list
> >     [e-mail]
> <mailto:[e-mail]>
> <mailto:[e-mail]
> <mailto:[e-mail]>>
> >   
>  https://lists.fedorahosted.org/admin/lists/[e-mail]
> >
> >
> >
> >
> > _______________________________________________
> > ipsilon mailing list
> > [e-mail] <mailto:[e-mail]>
> >
> https://lists.fedorahosted.org/admin/lists/[e-mail]
> >
> _______________________________________________
> ipsilon mailing list
> [e-mail] <mailto:[e-mail]>
> https://lists.fedorahosted.org/admin/lists/[e-mail]
>
>
>
>
> ipsilon mailing list
> [e-mail]
> https://lists.fedorahosted.org/admin/lists/[e-mail]