 |
 |
In an attempt to get eyes on this and make this easier to debug, here is some specific output ``` .065583 +0000][Dump ][XRootDTransport ] [fndca1.fnal.gov:1096.0] Stream inactive since 1001 seconds, TTL: 7200, allocated SIDs: 1, open files: 0 [2022-01-24 21:07:50.065648 +0000][Dump ][XRootDTransport ] [fndca1.fnal.gov:1096.0] Stream inactive since 1001 seconds, stream timeout: 7200, allocated SIDs: 1, wait barrier: 2022-01-24 19:44:30 +0000 [2022-01-24 21:07:52.240803 +0000][Error ][AsyncSock ] [fndca1.fnal.gov:1096.0] Socket error encountered: [ERROR] Internal error: connection timed out [2022-01-24 21:07:52.242016 +0000][Debug ][AsyncSock ] [fndca1.fnal.gov:1096.0] Closing the socket [2022-01-24 21:07:52.245735 +0000][Debug ][Poller ] <[2001:1458:301:4a::100:78]:57072><--><[2620:6a:0:4812:f0:0:69:121]:1096> Removing socket from the poller [2022-01-24 21:07:52.245827 +0000][Debug ][PostMaster ] [fndca1.fnal.gov:1096] Recovering error for stream #0: [ERROR] Internal error: connection timed out. [2022-01-24 21:07:52.246869 +0000][Debug ][PostMaster ] [fndca1.fnal.gov:1096] Reporting disconnection to queued message handlers. [2022-01-24 21:07:52.247233 +0000][Dump ][XRootD ] [fndca1.fnal.gov:1096] Stream event reported for msg kXR_open (file: pnfs/fnal.gov/usr/dune/tape_backed/dunepro/protodune-sp/full-reconstructed/2021/mc/out1/PDSPProd4a/45/65/94/31/PDSPProd4a_protoDUNE_sp_reco_stage1_p2GeV_35ms_sce_datadriven_45659431_184_20210607T104924Z.root?, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) [2022-01-24 21:07:52.247255 +0000][Debug ][XRootD ] [fndca1.fnal.gov:1096] Handling error while processing kXR_open (file: pnfs/fnal.gov/usr/dune/tape_backed/dunepro/protodune-sp/full-reconstructed/2021/mc/out1/PDSPProd4a/45/65/94/31/PDSPProd4a_protoDUNE_sp_reco_stage1_p2GeV_35ms_sce_datadriven_45659431_184_20210607T104924Z.root?, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ): [ERROR] Internal error: connection timed out. [2022-01-24 21:07:52.247589 +0000][Info ][XRootD ] [fndca1.fnal.gov:1096] Retrying request: kXR_open (file: pnfs/fnal.gov/usr/dune/tape_backed/dunepro/protodune-sp/full-reconstructed/2021/mc/out1/PDSPProd4a/45/65/94/31/PDSPProd4a_protoDUNE_sp_reco_stage1_p2GeV_35ms_sce_datadriven_45659431_184_20210607T104924Z.root?, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ). [2022-01-24 21:07:52.247666 +0000][Dump ][Utility ] URL: root://fndca1.fnal.gov:1096/pnfs/fnal.gov/usr/dune/tape_backed/dunepro/protodune-sp/full-reconstructed/2021/mc/out1/PDSPProd4a/45/65/94/31/PDSPProd4a_protoDUNE_sp_reco_stage1_p2GeV_35ms_sce_datadriven_45659431_184_20210607T104924Z.root [2022-01-24 21:07:52.247666 +0000][Dump ][Utility ] Protocol: root [2022-01-24 21:07:52.247666 +0000][Dump ][Utility ] User Name: [2022-01-24 21:07:52.247666 +0000][Dump ][Utility ] Password: [2022-01-24 21:07:52.247666 +0000][Dump ][Utility ] Host Name: fndca1.fnal.gov [2022-01-24 21:07:52.247666 +0000][Dump ][Utility ] Port: 1096 [2022-01-24 21:07:52.247666 +0000][Dump ][Utility ] Path: pnfs/fnal.gov/usr/dune/tape_backed/dunepro/protodune-sp/full-reconstructed/2021/mc/out1/PDSPProd4a/45/65/94/31/PDSPProd4a_protoDUNE_sp_reco_stage1_p2GeV_35ms_sce_datadriven_45659431_184_20210607T104924Z.root [2022-01-24 21:07:52.247706 +0000][Dump ][Utility ] URL: root://fndca1.fnal.gov:1096/pnfs/fnal.gov/usr/dune/tape_backed/dunepro/protodune-sp/full-reconstructed/2021/mc/out1/PDSPProd4a/45/65/94/31/PDSPProd4a_protoDUNE_sp_reco_stage1_p2GeV_35ms_sce_datadriven_45659431_184_20210607T104924Z.root [2022-01-24 21:07:52.247706 +0000][Dump ][Utility ] Protocol: root [2022-01-24 21:07:52.247706 +0000][Dump ][Utility ] User Name: [2022-01-24 21:07:52.247706 +0000][Dump ][Utility ] Password: [2022-01-24 21:07:52.247706 +0000][Dump ][Utility ] Host Name: fndca1.fnal.gov [2022-01-24 21:07:52.247706 +0000][Dump ][Utility ] Port: 1096 [2022-01-24 21:07:52.247706 +0000][Dump ][Utility ] Path: pnfs/fnal.gov/usr/dune/tape_backed/dunepro/protodune-sp/full-reconstructed/2021/mc/out1/PDSPProd4a/45/65/94/31/PDSPProd4a_protoDUNE_sp_reco_stage1_p2GeV_35ms_sce_datadriven_45659431_184_20210607T104924Z.root [2022-01-24 21:07:52.247737 +0000][Debug ][ExDbgMsg ] [fndca1.fnal.gov:1096] Retry at server MsgHandler: 0x3a4cf100 (message: kXR_open (file: pnfs/fnal.gov/usr/dune/tape_backed/dunepro/protodune-sp/full-reconstructed/2021/mc/out1/PDSPProd4a/45/65/94/31/PDSPProd4a_protoDUNE_sp_reco_stage1_p2GeV_35ms_sce_datadriven_45659431_184_20210607T104924Z.root?, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) ). [2022-01-24 21:07:52.247758 +0000][Dump ][PostMaster ] [fndca1.fnal.gov:1096] Sending message kXR_open (file: pnfs/fnal.gov/usr/dune/tape_backed/dunepro/protodune-sp/full-reconstructed/2021/mc/out1/PDSPProd4a/45/65/94/31/PDSPProd4a_protoDUNE_sp_reco_stage1_p2GeV_35ms_sce_datadriven_45659431_184_20210607T104924Z.root?, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) (0x77040190) through substream 0 expecting answer at 0 [2022-01-24 21:07:52.250308 +0000][Debug ][PostMaster ] [fndca1.fnal.gov:1096] Found 2 address(es): [::ffff:131.225.69.121]:1096, [2620:6a:0:4812:f0:0:69:121]:1096 [2022-01-24 21:07:52.250360 +0000][Debug ][AsyncSock ] [fndca1.fnal.gov:1096.0] Attempting connection to [2620:6a:0:4812:f0:0:69:121]:1096 [2022-01-24 21:07:52.250424 +0000][Debug ][Poller ] Adding socket 0xd04ef60 to the poller [2022-01-24 21:07:52.353082 +0000][Debug ][AsyncSock ] [fndca1.fnal.gov:1096.0] Async connection call returned [2022-01-24 21:07:52.353169 +0000][Debug ][XRootDTransport ] [fndca1.fnal.gov:1096.0] Sending out the initial hand shake + kXR_protocol [2022-01-24 21:07:52.353227 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Wrote a message: (0x770289e0), 44 bytes [2022-01-24 21:07:52.456422 +0000][Dump ][XRootDTransport ] [msg: 0x770289e0] Expecting 8 bytes of message body [2022-01-24 21:07:52.456482 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Received message header, size: 8 [2022-01-24 21:07:52.456525 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Received a message of 16 bytes [2022-01-24 21:07:52.456549 +0000][Debug ][XRootDTransport ] [fndca1.fnal.gov:1096.0] Got the server hand shake response (type: manager [], protocol version 500) [2022-01-24 21:07:52.456586 +0000][Dump ][XRootDTransport ] [msg: 0x770289e0] Expecting 8 bytes of message body [2022-01-24 21:07:52.456597 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Received message header, size: 8 [2022-01-24 21:07:52.456608 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Received a message of 16 bytes [2022-01-24 21:07:52.456623 +0000][Debug ][XRootDTransport ] [fndca1.fnal.gov:1096.0] kXR_protocol successful (type: manager [], protocol version 500) [2022-01-24 21:07:52.465822 +0000][Debug ][XRootDTransport ] [fndca1.fnal.gov:1096.0] Sending out kXR_login request, username: dune021, cgi: ?xrd.cc=ch&xrd.tz=0&xrd.appname=lar&xrd.info=&xrd.hostname=b7s11p6463.cern.ch&xrd.rn=v5.1.0, dual-stack: true, private IPv4: false, private IPv6: false [2022-01-24 21:07:52.465911 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Wrote a message: (0x77079860), 115 bytes [2022-01-24 21:07:52.584421 +0000][Dump ][XRootDTransport ] [msg: 0x77079860] Expecting 49 bytes of message body [2022-01-24 21:07:52.584482 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Received message header, size: 8 [2022-01-24 21:07:52.584501 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Received a message of 57 bytes [2022-01-24 21:07:52.584522 +0000][Debug ][XRootDTransport ] [fndca1.fnal.gov:1096.0] Logged in, session: 1147ac672d24fc30bca8ec5ba69a3bcb [2022-01-24 21:07:52.584533 +0000][Debug ][XRootDTransport ] [fndca1.fnal.gov:1096.0] Authentication is required: &P=gsi,v:10400,c:ssl,ca:f5f0dfc2 [2022-01-24 21:07:52.584548 +0000][Debug ][XRootDTransport ] [fndca1.fnal.gov:1096.0] Sending authentication data [2022-01-24 21:07:52.593089 +0000][Debug ][XRootDTransport ] [fndca1.fnal.gov:1096.0] Trying to authenticate using gsi [2022-01-24 21:07:52.616394 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Wrote a message: (0x537756c0), 136 bytes [2022-01-24 21:07:52.744731 +0000][Dump ][XRootDTransport ] [msg: 0x537756c0] Expecting 3309 bytes of message body [2022-01-24 21:07:52.744786 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Received message header, size: 8 [2022-01-24 21:07:52.744811 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Received a message of 3317 bytes [2022-01-24 21:07:52.744825 +0000][Debug ][XRootDTransport ] [fndca1.fnal.gov:1096.0] Sending more authentication data for gsi [2022-01-24 21:07:52.744906 +0000][Error ][XRootDTransport ] [fndca1.fnal.gov:1096.0] Auth protocol handler for gsi refuses to give us more credentials Secgsi: ErrParseBuffer: no common cipher algorithm: kXGS_cert [2022-01-24 21:07:52.745454 +0000][Error ][AsyncSock ] [fndca1.fnal.gov:1096.0] Socket error while handshaking: [FATAL] Auth failed [2022-01-24 21:07:52.745821 +0000][Debug ][AsyncSock ] [fndca1.fnal.gov:1096.0] Closing the socket [2022-01-24 21:07:52.745864 +0000][Debug ][Poller ] <[2001:1458:301:4a::100:78]:36296><--><[2620:6a:0:4812:f0:0:69:121]:1096> Removing socket from the poller [2022-01-24 21:07:52.745931 +0000][Error ][PostMaster ] [fndca1.fnal.gov:1096] elapsed = 0, pConnectionWindow = 30 seconds. [2022-01-24 21:07:52.746014 +0000][Debug ][AsyncSock ] [fndca1.fnal.gov:1096.0] Attempting connection to [::ffff:131.225.69.121]:1096 [2022-01-24 21:07:52.746080 +0000][Debug ][Poller ] Adding socket 0xd04ef60 to the poller [2022-01-24 21:07:52.851413 +0000][Debug ][AsyncSock ] [fndca1.fnal.gov:1096.0] Async connection call returned [2022-01-24 21:07:52.851490 +0000][Debug ][XRootDTransport ] [fndca1.fnal.gov:1096.0] Sending out the initial hand shake + kXR_protocol [2022-01-24 21:07:52.851558 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Wrote a message: (0x77025e00), 44 bytes [2022-01-24 21:07:52.956423 +0000][Dump ][XRootDTransport ] [msg: 0x77025e00] Expecting 8 bytes of message body [2022-01-24 21:07:52.956486 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Received message header, size: 8 [2022-01-24 21:07:52.956502 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Received a message of 16 bytes [2022-01-24 21:07:52.956528 +0000][Debug ][XRootDTransport ] [fndca1.fnal.gov:1096.0] Got the server hand shake response (type: manager [], protocol version 500) [2022-01-24 21:07:52.957499 +0000][Dump ][XRootDTransport ] [msg: 0x77025e00] Expecting 8 bytes of message body [2022-01-24 21:07:52.957539 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Received message header, size: 8 [2022-01-24 21:07:52.957551 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Received a message of 16 bytes [2022-01-24 21:07:52.957565 +0000][Debug ][XRootDTransport ] [fndca1.fnal.gov:1096.0] kXR_protocol successful (type: manager [], protocol version 500) [2022-01-24 21:07:52.958153 +0000][Debug ][XRootDTransport ] [fndca1.fnal.gov:1096.0] Sending out kXR_login request, username: dune021, cgi: ?xrd.cc=ch&xrd.tz=0&xrd.appname=lar&xrd.info=&xrd.hostname=b7s11p6463.cern.ch&xrd.rn=v5.1.0, dual-stack: true, private IPv4: false, private IPv6: false [2022-01-24 21:07:52.958192 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Wrote a message: (0x7705d4e0), 115 bytes [2022-01-24 21:07:53.061769 +0000][Dump ][XRootDTransport ] [msg: 0x7705d4e0] Expecting 49 bytes of message body [2022-01-24 21:07:53.061831 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Received message header, size: 8 [2022-01-24 21:07:53.061849 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Received a message of 57 bytes [2022-01-24 21:07:53.061871 +0000][Debug ][XRootDTransport ] [fndca1.fnal.gov:1096.0] Logged in, session: 5314a83cfdc9d3dd01bfe3e7ee8a939c [2022-01-24 21:07:53.061883 +0000][Debug ][XRootDTransport ] [fndca1.fnal.gov:1096.0] Authentication is required: &P=gsi,v:10400,c:ssl,ca:f5f0dfc2 [2022-01-24 21:07:53.061893 +0000][Debug ][XRootDTransport ] [fndca1.fnal.gov:1096.0] Sending authentication data [2022-01-24 21:07:53.061975 +0000][Debug ][XRootDTransport ] [fndca1.fnal.gov:1096.0] Trying to authenticate using gsi [2022-01-24 21:07:53.075381 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Wrote a message: (0x26cf75e0), 136 bytes [2022-01-24 21:07:53.203989 +0000][Dump ][XRootDTransport ] [msg: 0x26cf75e0] Expecting 3309 bytes of message body [2022-01-24 21:07:53.204047 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Received message header, size: 8 [2022-01-24 21:07:53.204070 +0000][Dump ][AsyncSock ] [fndca1.fnal.gov:1096.0] Received a message of 3317 bytes [2022-01-24 21:07:53.204083 +0000][Debug ][XRootDTransport ] [fndca1.fnal.gov:1096.0] Sending more authentication data for gsi [2022-01-24 21:07:53.204139 +0000][Error ][XRootDTransport ] [fndca1.fnal.gov:1096.0] Auth protocol handler for gsi refuses to give us more credentials Secgsi: ErrParseBuffer: no common cipher algorithm: kXGS_cert [2022-01-24 21:07:53.204178 +0000][Error ][AsyncSock ] [fndca1.fnal.gov:1096.0] Socket error while handshaking: [FATAL] Auth failed [2022-01-24 21:07:53.204188 +0000][Debug ][AsyncSock ] [fndca1.fnal.gov:1096.0] Closing the socket [2022-01-24 21:07:53.204205 +0000][Debug ][Poller ] <[::ffff:188.184.162.126]:51276><--><[::ffff:131.225.69.121]:1096> Removing socket from the poller [2022-01-24 21:07:53.204285 +0000][Error ][PostMaster ] [fndca1.fnal.gov:1096] elapsed = 1, pConnectionWindow = 30 seconds. [2022-01-24 21:07:53.204641 +0000][Error ][PostMaster ] [fndca1.fnal.gov:1096] Unable to recover: [FATAL] Auth failed. [2022-01-24 21:07:53.204655 +0000][Error ][XRootD ] [fndca1.fnal.gov:1096] Impossible to send message kXR_open (file: pnfs/fnal.gov/usr/dune/tape_backed/dunepro/protodune-sp/full-reconstructed/2021/mc/out1/PDSPProd4a/45/65/94/31/PDSPProd4a_protoDUNE_sp_reco_stage1_p2GeV_35ms_sce_datadriven_45659431_184_20210607T104924Z.root?, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ). Trying to recover. [2022-01-24 21:07:53.204677 +0000][Debug ][XRootD ] [fndca1.fnal.gov:1096] Handling error while processing kXR_open (file: pnfs/fnal.gov/usr/dune/tape_backed/dunepro/protodune-sp/full-reconstructed/2021/mc/out1/PDSPProd4a/45/65/94/31/PDSPProd4a_protoDUNE_sp_reco_stage1_p2GeV_35ms_sce_datadriven_45659431_184_20210607T104924Z.root?, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ): [FATAL] Auth failed. [2022-01-24 21:07:53.204891 +0000][Debug ][ExDbgMsg ] [fndca1.fnal.gov:1096] Passing to the thread-pool MsgHandler: 0x3a4cf100 (message: kXR_open (file: pnfs/fnal.gov/usr/dune/tape_backed/dunepro/protodune-sp/full-reconstructed/2021/mc/out1/PDSPProd4a/45/65/94/31/PDSPProd4a_protoDUNE_sp_reco_stage1_p2GeV_35ms_sce_datadriven_45659431_184_20210607T104924Z.root?, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) ). [2022-01-24 21:07:53.205507 +0000][Debug ][ExDbgMsg ] [fndca1.fnal.gov:1096] Calling MsgHandler: 0x3a4cf100 (message: kXR_open (file: pnfs/fnal.gov/usr/dune/tape_backed/dunepro/protodune-sp/full-reconstructed/2021/mc/out1/PDSPProd4a/45/65/94/31/PDSPProd4a_protoDUNE_sp_reco_stage1_p2GeV_35ms_sce_datadriven_45659431_184_20210607T104924Z.root?, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) ) with status: [FATAL] Auth failed. [2022-01-24 21:07:53.205612 +0000][Debug ][File ] [0x759cc730@root://fndca1.fnal.gov:1096/pnfs/fnal.gov/usr/dune/tape_backed/dunepro/protodune-sp/full-reconstructed/2021/mc/out1/PDSPProd4a/45/65/94/31/PDSPProd4a_protoDUNE_sp_reco_stage1_p2GeV_35ms_sce_datadriven_45659431_184_20210607T104924Z.root?xrdcl.requuid=1c4fa624-7019-4ea0-b736-fc677b8a06aa] Open has returned with status [FATAL] Auth failed [2022-01-24 21:07:53.205642 +0000][Debug ][File ] [0x759cc730@root://fndca1.fnal.gov:1096/pnfs/fnal.gov/usr/dune/tape_backed/dunepro/protodune-sp/full-reconstructed/2021/mc/out1/PDSPProd4a/45/65/94/31/PDSPProd4a_protoDUNE_sp_reco_stage1_p2GeV_35ms_sce_datadriven_45659431_184_20210607T104924Z.root?xrdcl.requuid=1c4fa624-7019-4ea0-b736-fc677b8a06aa] Error while opening at fndca1.fnal.gov:1096: [FATAL] Auth failed [2022-01-24 21:07:53.205977 +0000][Debug ][XRootD ] Redirect trace-back: [2022-01-24 21:07:53.205977 +0000][Debug ][XRootD ] 0. Retrying: root://fndca1.fnal.gov:1096/pnfs/fnal.gov/usr/dune/tape_backed/dunepro/protodune-sp/full-reconstructed/2021/mc/out1/PDSPProd4a/45/65/94/31/PDSPProd4a_protoDUNE_sp_reco_stage1_p2GeV_35ms_sce_datadriven_45659431_184_20210607T104924Z.root [2022-01-24 21:07:53.206003 +0000][Debug ][ExDbgMsg ] [fndca1.fnal.gov:1096] Destroying MsgHandler: 0x3a4cf100. ``` -- Reply to this email directly or view it on GitHub: https://github.com/xrootd/xrootd/issues/1593#issuecomment-1020563474 You are receiving this because you are subscribed to this thread. Message ID: <[log in to unmask]> ######################################################################## Use REPLY-ALL to reply to list To unsubscribe from the XROOTD-DEV list, click the following link: https://listserv.slac.stanford.edu/cgi-bin/wa?SUBED1=XROOTD-DEV&A=1