audit log wrong behaviour when encrypting nameid fails

Audit log does not show a failure in some cases, and instead logs that a name idenfier was sent even though only a saml error is sent to SP.

I created a fresh, minimal install of shibboleth idp 2.2.1 and configured it against google apps, with these instructions: http://code.google.com/apis/apps/articles/shibboleth2.0.html (had to add lots of namespace declarations, though)

First a successful authentication in audit log (I have replaced some semi-sensitive strings with *'s)

20110406T071940Z|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect|ohopnkahkbgnhjnfdangaonoooefdnndlijcoili|google.com/a/***.fi|urn:mace:shibboleth:2.0:profiles:saml2:sso|https://****.jyu.fi/idp/shibboleth|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST|_f0e27ad5531bfe140477bf9cea05cdef|vihevivi|urn:oasis:names:tc:SAML:2.0:ac:classes:InternetProtocol||vihevivi|_40b319330437578aa0d3f9fdc6942dc9,|

Then, an unsuccesful one, due to changing relying party encryptNameIds="never" to encryptNameIds="conditional"

20110406T072216Z|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect|eflliahbllcmbeikjdjpfkogfbihednjdfidjklf|google.com/a/****.fi|urn:mace:shibboleth:2.0:profiles:saml2:sso|https://****.jyu.fi/idp/shibboleth|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST|_76cd321153cab01e808dba74d0e9816e|vihevivi|urn:oasis:names:tc:SAML:2.0:ac:classes:InternetProtocol||vihevivi||

Note only the last field is empty, authentication method and nameid are logged as being sent.

the saml sent in the latter case:

10:22:16.504 - DEBUG [PROTOCOL_MESSAGE:64] -
<?xml version="1.0" encoding="UTF-8"?><saml2p:Response xmlns:saml2p="urn:oasis:names:tc:SAML:2.0:protocol" Destination="https://www.google.com/a/****.fi/acs" ID="_76cd321153cab01e808dba74d0e9816e" InResponseTo="eflliahbllcmbeikjdjpfkogfbihednjdfidjklf" IssueInstant="2011-04-06T07:22:16.465Z" Version="2.0">
<saml2:Issuer xmlns:saml2="urn:oasis:names:tc:SAML:2.0:assertion" Format="urn:oasis:names:tc:SAML:2.0:nameid-format:entity">https://***.jyu.fi/idp/shibboleth&lt;/saml2:Issuer>
<saml2p:Status>
<saml2p:StatusCode Value="urn:oasis:names:tc:SAML:2.0:status:Responder"/>
<saml2p:StatusMessage>Unable to encrypt NameID</saml2p:StatusMessage>
</saml2p:Status>
</saml2p:Response>

Other related log entries:

10:22:16.457 - ERROR [edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:890] - Could not resolve a key encryption credential for peer entity: google.com/a/****.fi
10:22:16.462 - ERROR [edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:708] - Unable to construct encrypter
org.opensaml.xml.security.SecurityException: Could not resolve key encryption credential
[...]

Discussed on the shibboleth-users list on 5th Apr 2011.