Shibboleth SP v 3.2.2.2 crashes randomly on Windows

Fri Jul 2 08:47:25 UTC 2021

After updating SP from V 3.1.0 to V 3.2.2.2 on Windows 2012 R2, there have
been random crashes a few times a day.
This happens in two systems: one development server and one production
server. 

Both systems initially had SP v 2.6.4 installed, and have been upgraded
in-place via several versions and now recently to version 3.2.2.2 and
therefore were using the old isapi_shib.dll plugin.
When the crashes started happening, I first thought it was because of the
old plugin. But the problems persisted after I upgraded to use the new IIS7
module. For legacy reasons we were using HTTP headers and I thought crashes
might have something to do with them, but after upgrading to use Server
Variables instead, there are still random crashes.

The crashes happen at random times, and I fail to see any correlation to
Shibboleth or web application usage, i.e. there are no HTTP requests logged
by IIS around the time of the crashes. 

The following is found in the Event Log:

* Event Time: 02 Jul 2021 10:28:47    
* Source: Application Error    
* Event Log: Application    
* Type: Error    
* Event ID: 1000    
* Event User: N/A    
* Faulting application name: w3wp.exe, version: 8.5.9600.16384, time stamp:
0x52157ba0    
Faulting module name: shibsp-lite3_2.dll, version: 3.2.2.0, time stamp:
0x6082000a    
Exception code: 0xc0000005    
Fault offset: 0x000430f6    
Faulting process id: 0xd08    
Faulting application start time: 0x01d76ee544549926    
Faulting application path: C:\Windows\SysWOW64\inetsrv\w3wp.exe    
Faulting module path: C:\Program Files
(x86)\Shibboleth\SP\lib\shibsp-lite3_2.dll    
Report Id: 22ced2af-db07-11eb-811e-005056010874    
Faulting package full name:     
Faulting package-relative application ID:     

I have raised logging levels to DEBUG, but nothing really helpful shows up
there. 

shibd.log:

2021-07-02 10:24:59 DEBUG XMLTooling.XMLObjectBuilder : located
XMLObjectBuilder for element name:
{urn:oasis:names:tc:SAML:2.0:metadata}ContactPerson
2021-07-02 10:24:59 DEBUG XMLTooling.XMLObjectBuilder : located
XMLObjectBuilder for element name:
{urn:oasis:names:tc:SAML:2.0:metadata}EmailAddress
2021-07-02 10:24:59 DEBUG XMLTooling.XMLObjectBuilder : located
XMLObjectBuilder for element name:
{urn:oasis:names:tc:SAML:2.0:metadata}TelephoneNumber
2021-07-02 10:30:32 ERROR Shibboleth.Listener [1]: error reading size of
input message
2021-07-02 10:30:32 ERROR Shibboleth.Listener [1]: failed socket call
(unknown), result (183): Unknown error
2021-07-02 10:30:32 ERROR Shibboleth.Listener [1]: I/O failure processing
request on socket (956)
2021-07-02 10:39:57 INFO XMLTooling.StorageService : purged 6 expired
record(s) from storage

native.log:

2021-07-02 10:25:03 DEBUG Shibboleth.IISNative [3336] iis_shib: mapped
https://www.{REDACTED}
2021-07-02 10:25:14 DEBUG Shibboleth.IISNative [3336] iis_shib: mapped
https://www.{REDACTED}
2021-07-02 10:25:37 DEBUG Shibboleth.IISNative [3336] iis_shib: mapped
https://www.{REDACTED}
2021-07-02 10:26:17 DEBUG Shibboleth.IISNative [3336] iis_shib: mapped
https://www.{REDACTED}
2021-07-02 10:26:32 DEBUG Shibboleth.IISNative [3336] iis_shib: mapped
https://www.{REDACTED}
2021-07-02 10:26:46 DEBUG Shibboleth.IISNative [3336] iis_shib: mapped
https://www.{REDACTED}
2021-07-02 10:30:33 DEBUG Shibboleth.Config : shibboleth 3.2.2 library
initialization started
2021-07-02 10:30:33 DEBUG XMLTooling.Config : library initialization started
2021-07-02 10:30:33 DEBUG XMLTooling.Config : Xerces 3.2.3 initialization
complete
2021-07-02 10:30:33 INFO XMLTooling.Config : xmltooling 3.2.0 library
initialization complete
2021-07-02 10:30:33 DEBUG XMLTooling.ParserPool : loading XML catalog from
C:\ProgramData/Shibboleth/SP/xml/xmltooling/catalog.xml
2021-07-02 10:30:33 DEBUG XMLTooling.ParserPool : loading XML catalog from
C:\ProgramData/Shibboleth/SP/xml/opensaml/saml20-catalog.xml
2021-07-02 10:30:33 DEBUG XMLTooling.ParserPool : loading XML catalog from
C:\ProgramData/Shibboleth/SP/xml/opensaml/saml11-catalog.xml
2021-07-02 10:30:33 DEBUG XMLTooling.ParserPool : loading XML catalog from
C:\ProgramData/Shibboleth/SP/xml/shibboleth/catalog.xml
2021-07-02 10:30:33 INFO Shibboleth.Config : shibboleth 3.2.2 library
initialization complete
transaction.log:

2021-07-02 10:23:26 INFO Shibboleth-TRANSACTION [1] [default]: New session
(ID: _54762bb29551257b5ff15991061b2878) with (applicationId: default) for
principal from (IdP: http://{REDACTED}) at (ClientAddress: {REDACTED}) with
(NameIdentifier: {REDACTED}) using (Protocol:
urn:oasis:names:tc:SAML:2.0:protocol) from (AssertionID:
_907e747a-fc28-489b-8f7f-f86b2b9b2d28)
2021-07-02 10:23:26 INFO Shibboleth-TRANSACTION [1] [default]: Cached the
following attributes with session (ID: _54762bb29551257b5ff15991061b2878)
for (applicationId: default) {
2021-07-02 10:23:26 INFO Shibboleth-TRANSACTION [1] [default]:
SHIB_mail (1 values)
2021-07-02 10:23:26 INFO Shibboleth-TRANSACTION [1] [default]:
SHIB_givenname (1 values)
2021-07-02 10:23:26 INFO Shibboleth-TRANSACTION [1] [default]:
SHIB_surname (1 values)
2021-07-02 10:23:26 INFO Shibboleth-TRANSACTION [1] [default]: }
2021-07-02 10:53:58 INFO Shibboleth-TRANSACTION [2] [default]: New session
(ID: _f056dd5a0dd0c38cb902cdcfd3b643ba) with (applicationId: default) for
principal from (IdP: https://{REDACTED}) at (ClientAddress: {REDACTED}) with
(NameIdentifier: {REDACTED}) using (Protocol:
urn:oasis:names:tc:SAML:2.0:protocol) from (AssertionID:
_13110148-0023-4053-b952-150187b08401)
2021-07-02 10:53:58 INFO Shibboleth-TRANSACTION [2] [default]: Cached the
following attributes with session (ID: _f056dd5a0dd0c38cb902cdcfd3b643ba)
for (applicationId: default) {
2021-07-02 10:53:58 INFO Shibboleth-TRANSACTION [2] [default]:
SHIB_tenantid (1 values)
2021-07-02 10:53:58 INFO Shibboleth-TRANSACTION [2] [default]:
SHIB_eppn (1 values)
2021-07-02 10:53:58 INFO Shibboleth-TRANSACTION [2] [default]:
SHIB_givenname (1 values)
2021-07-02 10:53:58 INFO Shibboleth-TRANSACTION [2] [default]:
SHIB_surname (1 values)
2021-07-02 10:53:58 INFO Shibboleth-TRANSACTION [2] [default]:
SHIB_mail (1 values)
2021-07-02 10:53:58 INFO Shibboleth-TRANSACTION [2] [default]:
SHIB_name (1 values)
2021-07-02 10:53:58 INFO Shibboleth-TRANSACTION [2] [default]: }

Any ideas of what is actually happening and how to approach solving this
problem?

As you can see, the native log is still going to a file and not the windows
event log. The release notes for version 3.0 mentions potential file handle
leaks and recommends logging to the event log instead. However, we have not
had any problems with version 3.1.0 with this configuration, so I don't
think this is the cause. However, I will change the native logging to the
new default settings and see if the problems will go away. 

--
 <mailto:Kai.Risku at arrak.fi> Kai.Risku at arrak.fi     GSM  +358-40-767 8282
Oy Arrak Software Ab    <http://www.arrak.fi> http://www.arrak.fi

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://shibboleth.net/pipermail/users/attachments/20210702/9b6cda83/attachment.htm>