SP under IIS with TCP connection to shibd socket errors

[Paul Henson]

We have a deployment of the SP under Windows using IIS in which the 
shibd process is running on a different system than the web server and 
communicating via TCP.

We are somewhat frequently seen this error message in the native log:

2022-07-07 15:46:39 ERROR Shibboleth.Listener [9612] iis_shib [default]: 
error reading size of output message

That error comes from this code in the 
shibsp/remoting/impl/SocketListener.cpp file:

     while (recv(sock,(char*)&len,sizeof(len)) != sizeof(len)) {
         if (errno == EINTR) continue;   // Apparently this happens when 
a signal interrupts the blocking call.
         log->error("error reading size of output message");
         this->close(sock);
         throw ListenerException("Failure receiving response to remoted 
message ($1).", params(1,in.name()));
     }

The root cause is clearly that recv failed to read the four bytes of the 
unsigned long with an error code that was not EINTR. However, this code 
does not log what the actual error was 8-/. Also, with debugging logging 
enabled, the initial connection log includes the socket identifier:

2022-07-07 15:26:28 DEBUG Shibboleth.Listener [9612] iis_shib [default]: 
socket (2484) connected successfully
2022-07-07 15:26:33 DEBUG Shibboleth.Listener [9612] iis_shib [default]: 
socket (2548) connected successfully
2022-07-07 15:40:58 DEBUG Shibboleth.Listener [9612] iis_shib [default]: 
socket (2940) connected successfully

But the logs for using the socket or detailing an error on it do not:

2022-07-07 15:46:20 DEBUG Shibboleth.Listener [9612] iis_shib [default]: 
sending message (default/Login::run::SAML2SI)
2022-07-07 15:46:20 DEBUG Shibboleth.Listener [9612] iis_shib [default]: 
send completed, reading response message
2022-07-07 15:46:37 DEBUG Shibboleth.Listener [9612] iis_shib [default]: 
sending message (default/Login::run::SAML2SI)
2022-07-07 15:46:37 DEBUG Shibboleth.Listener [9612] iis_shib [default]: 
send completed, reading response message
2022-07-07 15:46:39 ERROR Shibboleth.Listener [9612] iis_shib [default]: 
error reading size of output message
2022-07-07 15:47:10 DEBUG Shibboleth.Listener [9612] iis_shib [default]: 
sending message (default/SAML2/POST)
2022-07-07 15:47:10 DEBUG Shibboleth.Listener [9612] iis_shib [default]: 
send completed, reading response message

Then the socket is closed when the error occurs, but again the error 
message does not include the socket identifier which makes it difficult 
to match up.

I do not as yet have corresponding debug logs from the shibd side to 
correlate with the errors, but hopefully will soon.

However, until then, I was wondering if anyone had any thoughts on this 
failure, or if there would be any objections to a pull request enhancing 
the debugging and error messages in this code to include the socket 
identifier to match the one logged in the initial connect message and 
the errno? With that in place, it would be easier to sniff the traffic 
on the wire and see if anything suspicious is occurring when the failure 
happens, and knowing specifically what error occurred might also be 
useful in narrowing down the issue.

Thanks much…


-- 
Signet - The Art of Access
https://www.signet.id/