login context vs session

[Paul Hethmon]

On 4/9/13 10:12 AM, "Tom Zeller" <tzeller at dragonacea.biz> wrote:

>> My theory is that the storage sweeper comes through
>> occasionally timing with my login process and kills the session and I
>>lose
>> the principal.
>>
>> Thoughts? Other things I should look at?
>
>To test that theory, maybe turn on trace logging for the storage sweeper ?
>
>It looks like the default sweeper will log when it expires entries.
>
>Of course, caveat utilitor (user beware), I have no idea what your
>production environment is like.
>

Doesn't look like the storage sweeper is the culprit. Here's a transaction
from this morning. In this case, I have session time set to 2.5 minutes
and I'm using my storage service.

08:08:53.997 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:700] -
[http-18780-3:] [1.2.3.4] [CD02440B9F5EEEFDF582B092A0554DBD] - Creating
shibboleth session for principal USERIDHERE
08:08:53.997 - DEBUG
[com.clareity.shibboleth.storage.DbStorageService:344] - [http-18780-3:]
[1.2.3.4] [CD02440B9F5EEEFDF582B092A0554DBD] - Using systemName of [XXX]
for index 
[1e40fe0804a35abdad06588883b9ed0574efe55dd5a51b227a014ae7a2c1cf06]
08:08:53.998 - DEBUG
[com.clareity.shibboleth.storage.DbStorageService:353] - [http-18780-3:]
[1.2.3.4] [CD02440B9F5EEEFDF582B092A0554DBD] - Key is a string =
[1e40fe0804a35abdad06588883b9ed0574efe55dd5a51b227a014ae7a2c1cf06]
08:08:53.998 - DEBUG [com.clareity.shibboleth.db.SessionObjectDAOImpl:254]
- [http-18780-3:] [1.2.3.4] [CD02440B9F5EEEFDF582B092A0554DBD] - Searching
for [1e40fe0804a35abdad06588883b9ed0574efe55dd5a51b227a014ae7a2c1cf06] in
system [XXX]
08:08:53.999 - DEBUG [com.clareity.shibboleth.db.SessionObjectDAOImpl:46]
- [http-18780-3:] [1.2.3.4] [CD02440B9F5EEEFDF582B092A0554DBD] - No
session object found, performing insert on
[1e40fe0804a35abdad06588883b9ed0574efe55dd5a51b227a014ae7a2c1cf06].
08:08:54.001 - DEBUG [com.clareity.shibboleth.db.SessionObjectDAOImpl:74]
- [http-18780-3:] [1.2.3.4] [CD02440B9F5EEEFDF582B092A0554DBD] - New
persistent session save to db [null]
08:08:54.002 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:814] -
[http-18780-3:] [1.2.3.4] [CD02440B9F5EEEFDF582B092A0554DBD] - Adding IdP
session cookie to HTTP response
08:08:54.003 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:715] -
[http-18780-3:] [1.2.3.4] [CD02440B9F5EEEFDF582B092A0554DBD] - Recording
authentication and service information in Shibboleth session for
principal: USERIDHERE
08:08:54.003 - DEBUG
[com.clareity.shibboleth.storage.DbStorageService:344] - [http-18780-3:]
[1.2.3.4] [CD02440B9F5EEEFDF582B092A0554DBD] - Using systemName of [XXX]
for index [USERIDHERE]
08:08:54.003 - DEBUG
[com.clareity.shibboleth.storage.DbStorageService:353] - [http-18780-3:]
[1.2.3.4] [CD02440B9F5EEEFDF582B092A0554DBD] - Key is a string =
[USERIDHERE]
08:08:54.003 - DEBUG [com.clareity.shibboleth.db.SessionObjectDAOImpl:254]
- [http-18780-3:] [1.2.3.4] [CD02440B9F5EEEFDF582B092A0554DBD] - Searching
for [USERIDHERE] in system [XXX]
08:08:54.004 - DEBUG [com.clareity.shibboleth.db.SessionObjectDAOImpl:46]
- [http-18780-3:] [1.2.3.4] [CD02440B9F5EEEFDF582B092A0554DBD] - No
session object found, performing insert on [USERIDHERE].
08:08:54.006 - DEBUG [com.clareity.shibboleth.db.SessionObjectDAOImpl:102]
- [http-18780-3:] [1.2.3.4] [CD02440B9F5EEEFDF582B092A0554DBD] - New
persistent session save to db [null]

The 2 log lines showing:


New persistent session save to db [null]

Are showing the SessionManagerEntry object as my storage service gets it.
The "null" is trying to get the principal value:

    if (object instanceof SessionManagerEntry) {
        // pull out the login id and expire time when storing
        SessionManagerEntry sme = (SessionManagerEntry) object;
        String loginId = sme.getSession().getPrincipalName();

So when it's passed to the storage service, something appears to be wrong
with the object already, though later lines in the log file still show the
principal name. When it gets to attribute resolution, it has the null
value.

So maybe turn up to TRACE on the session code? Maybe authentication engine?

Paul