Hello.

I'm have problems with a software called shibboleth which uses libcurl. It
seems it tries to use a dead connection sometimes and returns an error
without trying to reconnect. The libcurl debian package version is
7.15.5-1etch2.

This is the log on the SP part:

2009-08-18 05:02:41 INFO Shibboleth.Listener [26640]: detected socket
closure, shutting down worker thread
2009-08-18 05:03:22 INFO Shibboleth.Listener [26642]: detected socket
closure, shutting down worker thread
2009-08-18 05:07:01 DEBUG XMLTooling.libcurl [26646]: Connection 0 seems to
be dead!
2009-08-18 05:07:03 DEBUG XMLTooling.libcurl [26646]: Closing connection #0
2009-08-18 05:07:04 DEBUG XMLTooling.libcurl [26646]: SSLv3, TLS alert,
Client hello (1):
2009-08-18 05:07:14 WARN Shibboleth.SessionInitiator.SAML2 [26647]: unable
to locate SAML 2.0 identity provider role for provider (
https://login.sapo.pt/shibboleth)
2009-08-18 05:07:14 WARN Shibboleth.SessionInitiator.SAML2 [26647]: unable
to locate SAML 2.0 identity provider role for provider (
https://login.sapo.pt/shibboleth)
2009-08-18 05:07:42 DEBUG XMLTooling.libcurl [26646]: About to connect() to
login.sapo.pt port 8443
2009-08-18 05:07:43 DEBUG XMLTooling.libcurl [26646]: Connection time-out
2009-08-18 05:07:43 DEBUG XMLTooling.libcurl [26646]: Closing connection #0
2009-08-18 05:07:43 ERROR Shibboleth.ArtifactResolver [26646]: exception
resolving SAML 1.x artifact(s): CURLSOAPTransport failed while contacting
SOAP responder: Connection time-out
2009-08-18 05:08:34 DEBUG XMLTooling.libcurl [26648]: About to connect() to
login.sapo.pt port 8443
2009-08-18 05:08:35 DEBUG XMLTooling.libcurl [26648]: Trying
10.135.2.189...
2009-08-18 05:08:35 DEBUG XMLTooling.libcurl [26648]: connected
2009-08-18 05:08:35 DEBUG XMLTooling.libcurl [26648]: Connected to
login.sapo.pt (10.135.2.189) port 8443
2009-08-18 05:08:37 DEBUG XMLTooling.libcurl [26649]: About to connect() to
login.sapo.pt port 8443
2009-08-18 05:08:37 DEBUG XMLTooling.libcurl [26649]: Trying
10.135.2.189...
2009-08-18 05:08:37 DEBUG XMLTooling.libcurl [26649]: connected

And this is the network log:

48463 2009-08-18 04:55:53.890686 10.135.2.189 -> 10.135.64.117 SSLv3
Encrypted Alert
48464 2009-08-18 04:55:53.890696 10.135.64.117 -> 10.135.2.189 TCP 47793 >
pcsync-https [ACK] Seq=4733 Ack=5611 Win=17664 Len=0 TSV=2949595981
TSER=1193123681
48465 2009-08-18 04:55:53.890735 10.135.2.189 -> 10.135.64.117 TCP
pcsync-https > 47793 [FIN, ACK] Seq=5611 Ack=4733 Win=16768 Len=0
TSV=1193123681 TSER=2949594741
48466 2009-08-18 04:55:53.932345 10.135.64.117 -> 10.135.2.189 TCP 47793 >
pcsync-https [ACK] Seq=4733 Ack=5612 Win=17664 Len=0 TSV=2949595991
TSER=1193123681
48467 2009-08-18 05:07:04.370420 10.135.64.117 -> 10.135.2.189 SSLv3
Encrypted Alert
48468 2009-08-18 05:07:04.370636 10.135.2.189 -> 10.135.64.117 TCP
pcsync-https > 47793 [RST] Seq=5612 Len=0
48469 2009-08-18 05:07:42.990570 10.135.64.117 -> 10.135.2.189 TCP 47793 >
pcsync-https [RST, ACK] Seq=4770 Ack=5612 Win=17664 Len=0 TSV=2949773245
TSER=1193123681
48470 2009-08-18 05:08:35.028961 10.135.64.117 -> 10.135.2.189 TCP 42821 >
pcsync-https [SYN] Seq=0 Len=0 MSS=1460 TSV=2949786255 TSER=0 WS=8
48471 2009-08-18 05:08:35.029179 10.135.2.189 -> 10.135.64.117 TCP
pcsync-https > 42821 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1460
TSV=1193313985 TSER=2949786255 WS=7
48472 2009-08-18 05:08:35.029193 10.135.64.117 -> 10.135.2.189 TCP 42821 >
pcsync-https [ACK] Seq=1 Ack=1 Win=5888 Len=0 TSV=2949786255 TSER=1193313985
48473 2009-08-18 05:08:37.352107 10.135.64.117 -> 10.135.2.189 TCP [TCP
Previous segment lost] 42826 > pcsync-https [SYN] Seq=667891603 Len=0
MSS=1460 TSV=2949786835 TSER=0 WS=8
48474 2009-08-18 05:08:37.352445 10.135.2.189 -> 10.135.64.117 TCP
pcsync-https > 42826 [SYN, ACK] Seq=3887345758 Ack=667891604 Win=741376
Len=0 MSS=1460 TSV=1192227120 TSER=2949786835 WS=7
48475 2009-08-18 05:08:37.352463 10.135.64.117 -> 10.135.2.189 TCP 42826 >
pcsync-https [ACK] Seq=667891604 Ack=3887345759 Win=5888 Len=0
TSV=2949786835 TSER=1192227120
48476 2009-08-18 05:08:38.566239 10.135.64.117 -> 10.135.2.189 SSL Client
Hello
48477 2009-08-18 05:08:38.566627 10.135.2.189 -> 10.135.64.117 TCP
pcsync-https > 42821 [ACK] Seq=1 Ack=104 Win=5888 Len=0 TSV=1193314869
TSER=2949787139
48478 2009-08-18 05:08:38.569516 10.135.2.189 -> 10.135.64.117 SSLv3 Server
Hello, Certificate,
48479 2009-08-18 05:08:38.569524 10.135.64.117 -> 10.135.2.189 TCP 42821 >
pcsync-https [ACK] Seq=104 Ack=1449 Win=8960 Len=0 TSV=2949787140
TSER=1193314870
48480 2009-08-18 05:08:38.569528 10.135.2.189 -> 10.135.64.117 SSLv3 Server
Key Exchange
48481 2009-08-18 05:08:38.569531 10.135.64.117 -> 10.135.2.189 TCP 42821 >
pcsync-https [ACK] Seq=104 Ack=1484 Win=8960 Len=0 TSV=2949787140
TSER=1193314870
48482 2009-08-18 05:08:38.980657 10.135.64.117 -> 10.135.2.189 SSLv3 Client
Hello

It seems that libcurl tries to use an already dead connection and timeouts
instantly saying "trying to connect" because it receives a RST. Is this a
know problem with this curl version or is shibboleth using curl in a wrong
way?

Best regards,
André Cruz
Received on 2009-08-19