Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

xrdcp does not send login token when it receives a kXR_redirected response to a kXR_open request #1533

Closed
paulmillar opened this issue Oct 12, 2021 · 12 comments
Assignees

Comments

@paulmillar
Copy link
Contributor

Hi,

I'm running this command xrdcp -v -d3 /bin/bash root://localhost/public/test-1 with a modified version of dCache that provides a login token as part of the redirection. I'm testing this with the current tip of the master branch (f1d4e89e22) however, I see the same behaviour with released versions of xrootd.

Here is the activity, from dCache's perspective:

level=INFO ts=2021-10-12T14:27:02.018+0200 event=org.dcache.xrootd.connection.start session=door:Xrootd-sprocket@dCacheDomain:AAXOJvZtOtA socket.remote=127.0.0.1:53898 socket.local=127.0.0.1:1094
level=INFO ts=2021-10-12T14:27:02.037+0200 event=org.dcache.xrootd.request session=door:Xrootd-sprocket@dCacheDomain:AAXOJvZtOtA request=protocol response=ok
level=INFO ts=2021-10-12T14:27:02.067+0200 event=org.dcache.xrootd.request session=door:Xrootd-sprocket@dCacheDomain:AAXOJvZtOtA request=login username=paul capver=5 pid=3597 token=?xrd.cc=de&xrd.tz=1&xrd.appname=xrdcp&xrd.info=&xrd.hostname=sprocket.desy.de&xrd.rn=v20211011-f1d4e89e2 response=ok sessionId=064D58193438155712E9505BD2E72402
level=ERROR ts=2021-10-12T14:27:02.107+0200 event=org.dcache.xrootd.request session=door:Xrootd-sprocket@dCacheDomain:AAXOJvZtOtA request=stat path=public/test-1 vfs=false response=error error.code=NotFound error.msg="No such file"
level=INFO ts=2021-10-12T14:27:02.340+0200 event=org.dcache.xrootd.request session=door:Xrootd-sprocket@dCacheDomain:AAXOJvZtOtA request=open path=public/test-1 opaque=oss.asize=1168776 mode=0644 options=0x468 response=redirect host=localhost port=33140 token=org.dcache.door=localhost:1094
level=INFO ts=2021-10-12T14:27:02.364+0200 event=org.dcache.xrootd.connection.start session=pool:pool_write@dCacheDomain:xrootd:464d6bb5 socket.remote=127.0.0.1:36418 socket.local=127.0.0.1:33140
level=INFO ts=2021-10-12T14:27:02.370+0200 event=org.dcache.xrootd.request session=pool:pool_write@dCacheDomain:xrootd:464d6bb5 request=protocol response=ok
level=INFO ts=2021-10-12T14:27:02.372+0200 event=org.dcache.xrootd.request session=pool:pool_write@dCacheDomain:xrootd:464d6bb5 request=login username=paul capver=5 pid=3597 token=?xrd.cc=de&xrd.tz=1&xrd.appname=xrdcp&xrd.info=&xrd.hostname=sprocket.desy.de&xrd.rn=v20211011-f1d4e89e2 response=ok sessionId=6454ED77F14760F6FABB3A19E430DF25
level=INFO ts=2021-10-12T14:27:02.379+0200 event=org.dcache.xrootd.request session=pool:pool_write@dCacheDomain:xrootd:464d6bb5 request=open path=public/test-1 opaque=org.dcache.uuid=6c8975d4-a045-4b39-8380-8998815463d6&org.dcache.xrootd.client=paul.3597@localhost&oss.asize=1168776 mode=0644 options=0x468 response=ok handle=0 flags=0 modtime=1970-01-01T00:00:00Z size=0
level=INFO ts=2021-10-12T14:27:02.478+0200 event=org.dcache.xrootd.request session=pool:pool_write@dCacheDomain:xrootd:464d6bb5 request=close handle=0 response=ok
level=INFO ts=2021-10-12T14:27:02.505+0200 event=org.dcache.xrootd.connection.end session=door:Xrootd-sprocket@dCacheDomain:AAXOJvZtOtA
level=INFO ts=2021-10-12T14:27:02.506+0200 event=org.dcache.xrootd.connection.end session=pool:pool_write@dCacheDomain:xrootd:464d6bb5

Perhaps the important parts are the door's replying (token=org.dcache.door=localhost:1094) and the subsequent token presented to the pool (token=?xrd.cc=de&xrd.tz=1&xrd.appname=[..etc...]).

Here are a few lines from client's perspective. First, here's the client receiving the redirection respond from the door:

[2021-10-12 14:27:02.341475 +0200][Dump   ][XRootD            ] [localhost:1094] Got kXR_redirect response to message kXR_open (file: public/test-1?oss.asize=1168776, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ): localhost?org.dcache.xrootd.client=paul.3597@localhost&oss.asize=1168776&org.dcache.uuid=6c8975d4-a045-4b39-8380-8998815463d6?org.dcache.door=localhost:1094, port 33140

Second, here is the client sending the kXR_login request to the pool:

[2021-10-12 14:27:02.370965 +0200][Debug  ][XRootDTransport   ] [localhost:33140.0] Sending out kXR_login request, username: paul, cgi: ?xrd.cc=de&xrd.tz=1&xrd.appname=xrdcp&xrd.info=&xrd.hostname=sprocket.desy.de&xrd.rn=v20211011-f1d4e89e2, dual-stack: false, private IPv4: true, private IPv6: false

There doesn't seem to be an error message, where xrdcp complains that the login token is invalid or rejected for some other reason, yet the kXR_login request to the pool, triggered by a redirection, does not contain the desired login token.

@simonmichal simonmichal self-assigned this Dec 1, 2021
@simonmichal
Copy link
Contributor

@paulmillar : sorry for the late replay, I will have a look!

@paulmillar
Copy link
Contributor Author

Thanks @simonmichal

Please let me know if I can be of any help.

@simonmichal
Copy link
Contributor

@paulmillar : yes, it seems you are right, the login token was not correctly passed from the redirect response to the login request, I just pushed a patch that should fix this: 3c87024

Could you give it a try?

@paulmillar
Copy link
Contributor Author

Thanks for the update.

Unfortunately, this doesn't look like it solves the problem. Rather, it looks like the client is using the file/CGI-opaque when building the login token.

I ran this command: xrdcp -v -d3 /bin/bash root://localhost/public/test-1

Execuative summary: dCache redirection targets:

localhost?org.dcache.xrootd.client=paul.19732@localhost&oss.asize=1234376&org.dcache.uuid=df739ef4-665c-4ab9-a67d-560fb3bb1c45?org.dcache.door=localhost:1094

The login token should be org.dcache.door=localhost:1094; however, the client sends a login token that includes the file-specific CGI elements:

xrd.cc=us&xrd.tz=1&xrd.appname=xrdcp&xrd.info=&xrd.hostname=sprocket.fritz.box&xrd.rn=v20220314-3c87024f8&org.dcache.uuid=df739ef4-665c-4ab9-a67d-560fb3bb1c45&org.dcache.xrootd.client=paul.19732@localhost&oss.asize=1234376

Here are all the details from the above command.

Here is what dCache says:

level=INFO ts=2022-03-14T12:47:22.435+0100 event=org.dcache.xrootd.connection.start session=door:Xrootd-sprocket@dCacheDomain:AAXaLD5QHFg socket.remote=127.0.0.1:56346 socket.local=127.0.0.1:1094
level=INFO ts=2022-03-14T12:47:22.500+0100 event=org.dcache.xrootd.request session=door:Xrootd-sprocket@dCacheDomain:AAXaLD5QHFg request=protocol response=ok
level=INFO ts=2022-03-14T12:47:22.519+0100 event=org.dcache.xrootd.request session=door:Xrootd-sprocket@dCacheDomain:AAXaLD5QHFg request=login username=paul capver=5 pid=19732 token=xrd.cc=us&xrd.tz=1&xrd.appname=xrdcp&xrd.info=&xrd.hostname=sprocket.fritz.box&xrd.rn=v20220314-3c87024f8 response=ok sessionId=A4573F2ACA7244C2C45494051BC63EFF
level=ERROR ts=2022-03-14T12:47:22.553+0100 event=org.dcache.xrootd.request session=door:Xrootd-sprocket@dCacheDomain:AAXaLD5QHFg request=stat path=public/test-1 vfs=false response=error error.code=NotFound error.msg="No such file"
level=INFO ts=2022-03-14T12:47:22.767+0100 event=org.dcache.xrootd.request session=door:Xrootd-sprocket@dCacheDomain:AAXaLD5QHFg request=open path=public/test-1 opaque=oss.asize=1234376 mode=0644 options=0x468 response=redirect host=localhost port=33137 token=org.dcache.door=localhost:1094
level=INFO ts=2022-03-14T12:47:22.787+0100 event=org.dcache.xrootd.connection.start session=pool:pool_write@dCacheDomain:xrootd:bf490e9a socket.remote=127.0.0.1:50554 socket.local=127.0.0.1:33137
level=INFO ts=2022-03-14T12:47:22.795+0100 event=org.dcache.xrootd.request session=pool:pool_write@dCacheDomain:xrootd:bf490e9a request=protocol response=ok
level=INFO ts=2022-03-14T12:47:22.798+0100 event=org.dcache.xrootd.request session=pool:pool_write@dCacheDomain:xrootd:bf490e9a request=login username=paul capver=5 pid=19732 token=xrd.cc=us&xrd.tz=1&xrd.appname=xrdcp&xrd.info=&xrd.hostname=sprocket.fritz.box&xrd.rn=v20220314-3c87024f8&org.dcache.uuid=df739ef4-665c-4ab9-a67d-560fb3bb1c45&org.dcache.xrootd.client=paul.19732@localhost&oss.asize=1234376 response=ok sessionId=F98807C604D1B7999DFAC86C38C70728
level=INFO ts=2022-03-14T12:47:22.803+0100 event=org.dcache.xrootd.request session=pool:pool_write@dCacheDomain:xrootd:bf490e9a request=open path=public/test-1 opaque=org.dcache.uuid=df739ef4-665c-4ab9-a67d-560fb3bb1c45&org.dcache.xrootd.client=paul.19732@localhost&oss.asize=1234376 mode=0644 options=0x468 response=ok handle=0 flags=0 modtime=1970-01-01T00:00:00Z size=0
level=INFO ts=2022-03-14T12:47:22.876+0100 event=org.dcache.xrootd.request session=pool:pool_write@dCacheDomain:xrootd:bf490e9a request=close handle=0 response=ok
level=INFO ts=2022-03-14T12:47:22.879+0100 event=org.dcache.xrootd.connection.end session=door:Xrootd-sprocket@dCacheDomain:AAXaLD5QHFg
level=INFO ts=2022-03-14T12:47:22.880+0100 event=org.dcache.xrootd.connection.end session=pool:pool_write@dCacheDomain:xrootd:bf490e9a

Here's what the xrdcp client reports back for the same transfer:

[2022-03-14 12:47:22.390700 +0100][Dump   ][App               ] Chunk size: 8388608, parallel chunks 4, streams: 1
[2022-03-14 12:47:22.390806 +0100][Dump   ][Utility           ] URL: root://localhost/public/test-1
[2022-03-14 12:47:22.390806 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-14 12:47:22.390806 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.390806 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.390806 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.390806 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-14 12:47:22.390806 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-14 12:47:22.390855 +0100][Dump   ][Utility           ] URL: root://localhost:1094/public/test-1
[2022-03-14 12:47:22.390855 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-14 12:47:22.390855 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.390855 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.390855 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.390855 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-14 12:47:22.390855 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-14 12:47:22.390909 +0100][Dump   ][Utility           ] URL: root://localhost:1094/public/test-1
[2022-03-14 12:47:22.390909 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-14 12:47:22.390909 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.390909 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.390909 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.390909 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-14 12:47:22.390909 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-14 12:47:22.390959 +0100][Dump   ][Utility           ] URL: root://localhost:1094/public/test-1
[2022-03-14 12:47:22.390959 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-14 12:47:22.390959 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.390959 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.390959 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.390959 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-14 12:47:22.390959 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-14 12:47:22.391041 +0100][Dump   ][FileSystem        ] [0xef5de7f0@localhost:1094] Sending kXR_stat (path: public/test-1, flags: none)
[2022-03-14 12:47:22.391064 +0100][Debug  ][Utility           ] Env: trying to get a non-existent string entry: pollerpreference
[2022-03-14 12:47:22.391080 +0100][Debug  ][Poller            ] Available pollers: built-in
[2022-03-14 12:47:22.391091 +0100][Debug  ][Poller            ] Attempting to create a poller according to preference: built-in
[2022-03-14 12:47:22.391101 +0100][Debug  ][Poller            ] Creating poller: built-in
[2022-03-14 12:47:22.391114 +0100][Debug  ][Poller            ] Creating and starting the built-in poller...
[2022-03-14 12:47:22.391241 +0100][Debug  ][Poller            ] Using 1 poller threads
[2022-03-14 12:47:22.391257 +0100][Debug  ][TaskMgr           ] Starting the task manager...
[2022-03-14 12:47:22.391298 +0100][Debug  ][TaskMgr           ] Task manager started
[2022-03-14 12:47:22.391307 +0100][Debug  ][JobMgr            ] Starting the job manager...
[2022-03-14 12:47:22.391371 +0100][Debug  ][JobMgr            ] Job manager started, 3 workers
[2022-03-14 12:47:22.391382 +0100][Debug  ][TaskMgr           ] Registering task: "FileTimer task" to be run at: [2022-03-14 12:47:22 +0100]
[2022-03-14 12:47:22.391388 +0100][Dump   ][XRootD            ] [localhost:1094] Sending message kXR_stat (path: public/test-1, flags: none)
[2022-03-14 12:47:22.391413 +0100][Debug  ][ExDbgMsg          ] [localhost:1094] MsgHandler created: 0xef5e3010 (message: kXR_stat (path: public/test-1, flags: none) ).
[2022-03-14 12:47:22.391443 +0100][Dump   ][Utility           ] URL: localhost:1094
[2022-03-14 12:47:22.391443 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-14 12:47:22.391443 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.391443 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.391443 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.391443 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-14 12:47:22.391443 +0100][Dump   ][Utility           ] Path:      
[2022-03-14 12:47:22.391467 +0100][Dump   ][Utility           ] URL: root://localhost:1094
[2022-03-14 12:47:22.391467 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-14 12:47:22.391467 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.391467 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.391467 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.391467 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-14 12:47:22.391467 +0100][Dump   ][Utility           ] Path:      
[2022-03-14 12:47:22.391481 +0100][Debug  ][PostMaster        ] Creating new channel to: root://localhost:1094
[2022-03-14 12:47:22.391497 +0100][Debug  ][PostMaster        ] [localhost:1094] Stream parameters: Network Stack: IPAuto, Connection Window: 120, ConnectionRetry: 5, Stream Error Window: 1800
[2022-03-14 12:47:22.391514 +0100][Debug  ][TaskMgr           ] Registering task: "TickGeneratorTask for: root://localhost:1094" to be run at: [2022-03-14 12:47:37 +0100]
[2022-03-14 12:47:22.391526 +0100][Dump   ][PostMaster        ] [localhost:1094] Sending message kXR_stat (path: public/test-1, flags: none) (0xef5dea80) through substream 0 expecting answer at 0
[2022-03-14 12:47:22.391673 +0100][Debug  ][PostMaster        ] [localhost:1094] Found 2 address(es): [::ffff:127.0.0.1]:1094, [::ffff:127.0.0.1]:1094
[2022-03-14 12:47:22.391699 +0100][Debug  ][AsyncSock         ] [localhost:1094.0] Attempting connection to [::ffff:127.0.0.1]:1094
[2022-03-14 12:47:22.391761 +0100][Debug  ][Poller            ] Adding socket 0xef5deb90 to the poller
[2022-03-14 12:47:22.391855 +0100][Debug  ][AsyncSock         ] [localhost:1094.0] Async connection call returned
[2022-03-14 12:47:22.391890 +0100][Debug  ][XRootDTransport   ] [localhost:1094.0] Sending out the initial hand shake + kXR_protocol
[2022-03-14 12:47:22.391931 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Wrote a message:  (0x38001370), 44 bytes
[2022-03-14 12:47:22.391992 +0100][Dump   ][TaskMgr           ] Running task: "FileTimer task"
[2022-03-14 12:47:22.392009 +0100][Dump   ][TaskMgr           ] Will rerun task "FileTimer task" at [2022-03-14 12:47:37 +0100]
[2022-03-14 12:47:22.490884 +0100][Dump   ][XRootDTransport   ] [msg: 0x38001570] Expecting 8 bytes of message body
[2022-03-14 12:47:22.490915 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Received message header, size: 8
[2022-03-14 12:47:22.490926 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Received a message of 16 bytes
[2022-03-14 12:47:22.490935 +0100][Debug  ][XRootDTransport   ] [localhost:1094.0] Got the server hand shake response (type: manager [], protocol version 500)
[2022-03-14 12:47:22.507617 +0100][Dump   ][XRootDTransport   ] [msg: 0x38001570] Expecting 8 bytes of message body
[2022-03-14 12:47:22.507646 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Received message header, size: 8
[2022-03-14 12:47:22.507654 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Received a message of 16 bytes
[2022-03-14 12:47:22.507667 +0100][Debug  ][XRootDTransport   ] [localhost:1094.0] kXR_protocol successful (type: manager [], protocol version 500)
[2022-03-14 12:47:22.507783 +0100][Debug  ][XRootDTransport   ] [localhost:1094.0] Sending out kXR_login request, username: paul, cgi: xrd.cc=us&xrd.tz=1&xrd.appname=xrdcp&xrd.info=&xrd.hostname=sprocket.fritz.box&xrd.rn=v20220314-3c87024f8, dual-stack: false, private IPv4: true, private IPv6: false
[2022-03-14 12:47:22.507808 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Wrote a message:  (0x38001830), 129 bytes
[2022-03-14 12:47:22.520314 +0100][Dump   ][XRootDTransport   ] [msg: 0x38001370] Expecting 16 bytes of message body
[2022-03-14 12:47:22.520347 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Received message header, size: 8
[2022-03-14 12:47:22.520357 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Received a message of 24 bytes
[2022-03-14 12:47:22.520371 +0100][Debug  ][XRootDTransport   ] [localhost:1094.0] Logged in, session: a4573f2aca7244c2c45494051bc63eff
[2022-03-14 12:47:22.520386 +0100][Debug  ][PostMaster        ] [localhost:1094] Stream 0 connected.
[2022-03-14 12:47:22.520396 +0100][Debug  ][Utility           ] Monitor library name not set. No monitoring
[2022-03-14 12:47:22.520423 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Wrote a message: kXR_stat (path: public/test-1, flags: none) (0xef5dea80), 37 bytes
[2022-03-14 12:47:22.520467 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Successfully sent message: kXR_stat (path: public/test-1, flags: none) (0xef5dea80).
[2022-03-14 12:47:22.520481 +0100][Dump   ][XRootD            ] [localhost:1094] Message kXR_stat (path: public/test-1, flags: none) has been successfully sent.
[2022-03-14 12:47:22.520487 +0100][Debug  ][ExDbgMsg          ] [localhost:1094] Moving MsgHandler: 0xef5e3010 (message: kXR_stat (path: public/test-1, flags: none) ) from out-queu to in-queue.
[2022-03-14 12:47:22.520498 +0100][Dump   ][PostMaster        ] [localhost:1094.0] All messages consumed, disable uplink
[2022-03-14 12:47:22.554163 +0100][Dump   ][XRootDTransport   ] [msg: 0x38002110] Expecting 17 bytes of message body
[2022-03-14 12:47:22.554190 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Received message header for 0x38002110 size: 8
[2022-03-14 12:47:22.554208 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Received message 0x38002110 of 25 bytes
[2022-03-14 12:47:22.554218 +0100][Dump   ][PostMaster        ] [localhost:1094] Handling received message: 0x38002110.
[2022-03-14 12:47:22.554302 +0100][Dump   ][XRootD            ] [localhost:1094] Got a kXR_error response to request kXR_stat (path: public/test-1, flags: none) [3011] No such file
[2022-03-14 12:47:22.554329 +0100][Debug  ][XRootD            ] [localhost:1094] Handling error while processing kXR_stat (path: public/test-1, flags: none): [ERROR] Error response: no such file or directory.
[2022-03-14 12:47:22.554346 +0100][Debug  ][ExDbgMsg          ] [localhost:1094] Calling MsgHandler: 0xef5e3010 (message: kXR_stat (path: public/test-1, flags: none) ) with status: [ERROR] Error response: no such file or directory.
[2022-03-14 12:47:22.554370 +0100][Debug  ][ExDbgMsg          ] [localhost:1094] Destroying MsgHandler: 0xef5e3010.
[2022-03-14 12:47:22.554400 +0100][Dump   ][App               ] Processing source entry: /bin/bash, type local file, target file: root://localhost/public/test-1
[2022-03-14 12:47:22.554487 +0100][Dump   ][Utility           ] Adding job with properties: 'checkSumMode' = 'none', 'checkSumPreset' = '', 'checkSumType' = '', 'chunkSize' = '8388608', 'coerce' = '0', 'continue' = '0', 'cpTimeout' = '0', 'delegate' = '0', 'dynamicSource' = '0', 'force' = '0', 'initTimeout' = '600', 'makeDir' = '0', 'parallelChunks' = '4', 'posc' = '0', 'preserveXAttr' = '0', 'rmOnBadCksum' = '0', 'source' = 'file:///bin/bash', 'target' = 'root://localhost/public/test-1', 'targetIsDir' = '0', 'thirdParty' = 'none', 'tpcTimeout' = '1800', 'xcp' = '0', 'xcpBlockSize' = '134217728', 'xrate' = '0', 'xrateThreashold' = '0', 'zipAppend' = '0', 'zipArchive' = '0'
[2022-03-14 12:47:22.554514 +0100][Debug  ][Utility           ] CopyProcess: 2 jobs to prepare
[2022-03-14 12:47:22.554530 +0100][Dump   ][Utility           ] URL: file:///bin/bash
[2022-03-14 12:47:22.554530 +0100][Dump   ][Utility           ] Protocol:  file
[2022-03-14 12:47:22.554530 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.554530 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.554530 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.554530 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-14 12:47:22.554530 +0100][Dump   ][Utility           ] Path:      /bin/bash
[2022-03-14 12:47:22.554548 +0100][Dump   ][Utility           ] URL: root://localhost/public/test-1
[2022-03-14 12:47:22.554548 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-14 12:47:22.554548 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.554548 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.554548 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.554548 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-14 12:47:22.554548 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-14 12:47:22.554572 +0100][Dump   ][Utility           ] URL: file:///bin/bash
[2022-03-14 12:47:22.554572 +0100][Dump   ][Utility           ] Protocol:  file
[2022-03-14 12:47:22.554572 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.554572 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.554572 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.554572 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-14 12:47:22.554572 +0100][Dump   ][Utility           ] Path:      /bin/bash
[2022-03-14 12:47:22.554589 +0100][Dump   ][Utility           ] URL: root://localhost/public/test-1
[2022-03-14 12:47:22.554589 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-14 12:47:22.554589 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.554589 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.554589 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.554589 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-14 12:47:22.554589 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-14 12:47:22.554601 +0100][Debug  ][Utility           ] Creating a classic copy job, from file://localhost/bin/bash to root://localhost:1094/public/test-1
[2022-03-14 12:47:22.554659 +0100][Debug  ][Utility           ] Opening file://localhost/bin/bash for reading
[2022-03-14 12:47:22.554673 +0100][Dump   ][Utility           ] URL: file://localhost/bin/bash
[2022-03-14 12:47:22.554673 +0100][Dump   ][Utility           ] Protocol:  file
[2022-03-14 12:47:22.554673 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.554673 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.554673 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.554673 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-14 12:47:22.554673 +0100][Dump   ][Utility           ] Path:      /bin/bash
[2022-03-14 12:47:22.554683 +0100][Dump   ][Utility           ] URL: file://localhost/bin/bash
[2022-03-14 12:47:22.554683 +0100][Dump   ][Utility           ] Protocol:  file
[2022-03-14 12:47:22.554683 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.554683 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.554683 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.554683 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-14 12:47:22.554683 +0100][Dump   ][Utility           ] Path:      /bin/bash
[2022-03-14 12:47:22.554693 +0100][Dump   ][Utility           ] URL: file://localhost/bin/bash
[2022-03-14 12:47:22.554693 +0100][Dump   ][Utility           ] Protocol:  file
[2022-03-14 12:47:22.554693 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.554693 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.554693 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.554693 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-14 12:47:22.554693 +0100][Dump   ][Utility           ] Path:      /bin/bash
[2022-03-14 12:47:22.554738 +0100][Debug  ][File              ] [0xef5e76e0@file://localhost/bin/bash?xrdcl.requuid=a156572d-bd3e-4245-ac5b-9cf131780f18] Sending an open command
[2022-03-14 12:47:22.554764 +0100][Dump   ][Utility           ] URL: file://localhost/bin/bash?xrdcl.requuid=a156572d-bd3e-4245-ac5b-9cf131780f18
[2022-03-14 12:47:22.554764 +0100][Dump   ][Utility           ] Protocol:  file
[2022-03-14 12:47:22.554764 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.554764 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.554764 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.554764 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-14 12:47:22.554764 +0100][Dump   ][Utility           ] Path:      /bin/bash
[2022-03-14 12:47:22.554806 +0100][Dump   ][Utility           ] URL: file://localhost/bin/bash?xrdcl.requuid=a156572d-bd3e-4245-ac5b-9cf131780f18
[2022-03-14 12:47:22.554806 +0100][Dump   ][Utility           ] Protocol:  file
[2022-03-14 12:47:22.554806 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.554806 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.554806 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.554806 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-14 12:47:22.554806 +0100][Dump   ][Utility           ] Path:      /bin/bash
[2022-03-14 12:47:22.554908 +0100][Debug  ][File              ] [0xef5e76e0@file://localhost/bin/bash?xrdcl.requuid=a156572d-bd3e-4245-ac5b-9cf131780f18] Open has returned with status [SUCCESS] 
[2022-03-14 12:47:22.554927 +0100][Debug  ][File              ] [0xef5e76e0@file://localhost/bin/bash?xrdcl.requuid=a156572d-bd3e-4245-ac5b-9cf131780f18] successfully opened at localhost, handle: 0xb, session id: 1
[2022-03-14 12:47:22.554966 +0100][Debug  ][Utility           ] Opening root://localhost:1094/public/test-1?oss.asize=1234376 for writing
[2022-03-14 12:47:22.554997 +0100][Dump   ][Utility           ] URL: root://localhost:1094/public/test-1?oss.asize=1234376
[2022-03-14 12:47:22.554997 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-14 12:47:22.554997 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.554997 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.554997 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.554997 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-14 12:47:22.554997 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-14 12:47:22.555024 +0100][Dump   ][Utility           ] URL: root://localhost:1094/public/test-1?oss.asize=1234376
[2022-03-14 12:47:22.555024 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-14 12:47:22.555024 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.555024 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.555024 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.555024 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-14 12:47:22.555024 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-14 12:47:22.555041 +0100][Dump   ][Utility           ] URL: root://localhost:1094/public/test-1?oss.asize=1234376
[2022-03-14 12:47:22.555041 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-14 12:47:22.555041 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.555041 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.555041 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.555041 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-14 12:47:22.555041 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-14 12:47:22.555076 +0100][Debug  ][File              ] [0xef5e8b60@root://localhost:1094/public/test-1?oss.asize=1234376&xrdcl.requuid=23bc11da-5836-4ae5-88bb-b214e44124d9] Sending an open command
[2022-03-14 12:47:22.555091 +0100][Dump   ][XRootD            ] [localhost:1094] Sending message kXR_open (file: public/test-1?oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat )
[2022-03-14 12:47:22.555102 +0100][Debug  ][ExDbgMsg          ] [localhost:1094] MsgHandler created: 0xef5e94a0 (message: kXR_open (file: public/test-1?oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) ).
[2022-03-14 12:47:22.555113 +0100][Dump   ][PostMaster        ] [localhost:1094] Sending message kXR_open (file: public/test-1?oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0xef5e7da0) through substream 0 expecting answer at 0
[2022-03-14 12:47:22.555160 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Wrote a message: kXR_open (file: public/test-1?oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0xef5e7da0), 55 bytes
[2022-03-14 12:47:22.555202 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Successfully sent message: kXR_open (file: public/test-1?oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0xef5e7da0).
[2022-03-14 12:47:22.555213 +0100][Dump   ][XRootD            ] [localhost:1094] Message kXR_open (file: public/test-1?oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) has been successfully sent.
[2022-03-14 12:47:22.555218 +0100][Debug  ][ExDbgMsg          ] [localhost:1094] Moving MsgHandler: 0xef5e94a0 (message: kXR_open (file: public/test-1?oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) ) from out-queu to in-queue.
[2022-03-14 12:47:22.555224 +0100][Dump   ][PostMaster        ] [localhost:1094.0] All messages consumed, disable uplink
[2022-03-14 12:47:22.768616 +0100][Dump   ][XRootDTransport   ] [msg: 0x38002650] Expecting 161 bytes of message body
[2022-03-14 12:47:22.768643 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Received message header for 0x38002650 size: 8
[2022-03-14 12:47:22.768654 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Received message 0x38002650 of 169 bytes
[2022-03-14 12:47:22.768661 +0100][Dump   ][PostMaster        ] [localhost:1094] Handling received message: 0x38002650.
[2022-03-14 12:47:22.768712 +0100][Dump   ][XRootD            ] [localhost:1094] Got kXR_redirect response to message kXR_open (file: public/test-1?oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ): localhost?org.dcache.xrootd.client=paul.19732@localhost&oss.asize=1234376&org.dcache.uuid=df739ef4-665c-4ab9-a67d-560fb3bb1c45?org.dcache.door=localhost:1094, port 33137
[2022-03-14 12:47:22.768724 +0100][Dump   ][XRootD            ] [localhost:1094] Current server has been assigned as a load-balancer for message kXR_open (file: public/test-1?oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat )
[2022-03-14 12:47:22.768742 +0100][Dump   ][Utility           ] URL: localhost:33137/
[2022-03-14 12:47:22.768742 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-14 12:47:22.768742 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.768742 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.768742 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.768742 +0100][Dump   ][Utility           ] Port:      33137
[2022-03-14 12:47:22.768742 +0100][Dump   ][Utility           ] Path:      
[2022-03-14 12:47:22.768772 +0100][Dump   ][Utility           ] URL: fake://fake:111//fake?org.dcache.xrootd.client=paul.19732@localhost&oss.asize=1234376&org.dcache.uuid=df739ef4-665c-4ab9-a67d-560fb3bb1c45&xrdcl.requuid=23bc11da-5836-4ae5-88bb-b214e44124d9&
[2022-03-14 12:47:22.768772 +0100][Dump   ][Utility           ] Protocol:  fake
[2022-03-14 12:47:22.768772 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.768772 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.768772 +0100][Dump   ][Utility           ] Host Name: fake
[2022-03-14 12:47:22.768772 +0100][Dump   ][Utility           ] Port:      111
[2022-03-14 12:47:22.768772 +0100][Dump   ][Utility           ] Path:      /fake
[2022-03-14 12:47:22.768802 +0100][Dump   ][Utility           ] URL: fake://fake:111/public/test-1?oss.asize=1234376
[2022-03-14 12:47:22.768802 +0100][Dump   ][Utility           ] Protocol:  fake
[2022-03-14 12:47:22.768802 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.768802 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.768802 +0100][Dump   ][Utility           ] Host Name: fake
[2022-03-14 12:47:22.768802 +0100][Dump   ][Utility           ] Port:      111
[2022-03-14 12:47:22.768802 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-14 12:47:22.768834 +0100][Dump   ][Utility           ] URL: root://localhost:1094/public/test-1
[2022-03-14 12:47:22.768834 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-14 12:47:22.768834 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.768834 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.768834 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.768834 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-14 12:47:22.768834 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-14 12:47:22.768848 +0100][Dump   ][Utility           ] URL: root://localhost:33137/
[2022-03-14 12:47:22.768848 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-14 12:47:22.768848 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.768848 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.768848 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.768848 +0100][Dump   ][Utility           ] Port:      33137
[2022-03-14 12:47:22.768848 +0100][Dump   ][Utility           ] Path:      
[2022-03-14 12:47:22.768868 +0100][Debug  ][ExDbgMsg          ] [localhost:33137] Retry at server MsgHandler: 0xef5e94a0 (message: kXR_open (file: public/test-1?org.dcache.uuid=df739ef4-665c-4ab9-a67d-560fb3bb1c45&org.dcache.xrootd.client=paul.19732@localhost&oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) ).
[2022-03-14 12:47:22.768879 +0100][Dump   ][Utility           ] URL: localhost:33137
[2022-03-14 12:47:22.768879 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-14 12:47:22.768879 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.768879 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.768879 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.768879 +0100][Dump   ][Utility           ] Port:      33137
[2022-03-14 12:47:22.768879 +0100][Dump   ][Utility           ] Path:      
[2022-03-14 12:47:22.768895 +0100][Dump   ][Utility           ] URL: root://localhost:33137
[2022-03-14 12:47:22.768895 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-14 12:47:22.768895 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.768895 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.768895 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.768895 +0100][Dump   ][Utility           ] Port:      33137
[2022-03-14 12:47:22.768895 +0100][Dump   ][Utility           ] Path:      
[2022-03-14 12:47:22.768907 +0100][Debug  ][PostMaster        ] Creating new channel to: root://localhost:33137
[2022-03-14 12:47:22.768925 +0100][Debug  ][PostMaster        ] [localhost:33137] Stream parameters: Network Stack: IPAuto, Connection Window: 120, ConnectionRetry: 5, Stream Error Window: 1800
[2022-03-14 12:47:22.768936 +0100][Debug  ][TaskMgr           ] Registering task: "TickGeneratorTask for: root://localhost:33137" to be run at: [2022-03-14 12:47:37 +0100]
[2022-03-14 12:47:22.768947 +0100][Dump   ][PostMaster        ] [localhost:33137] Sending message kXR_open (file: public/test-1?org.dcache.uuid=df739ef4-665c-4ab9-a67d-560fb3bb1c45&org.dcache.xrootd.client=paul.19732@localhost&oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0xef5e7da0) through substream 0 expecting answer at 0
[2022-03-14 12:47:22.769069 +0100][Debug  ][PostMaster        ] [localhost:33137] Found 2 address(es): [::ffff:127.0.0.1]:33137, [::ffff:127.0.0.1]:33137
[2022-03-14 12:47:22.769088 +0100][Debug  ][AsyncSock         ] [localhost:33137.0] Attempting connection to [::ffff:127.0.0.1]:33137
[2022-03-14 12:47:22.769139 +0100][Debug  ][Poller            ] Adding socket 0x2c002290 to the poller
[2022-03-14 12:47:22.769173 +0100][Debug  ][AsyncSock         ] [localhost:33137.0] Async connection call returned
[2022-03-14 12:47:22.769187 +0100][Debug  ][XRootDTransport   ] [localhost:33137.0] Sending out the initial hand shake + kXR_protocol
[2022-03-14 12:47:22.769206 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Wrote a message:  (0x38001570), 44 bytes
[2022-03-14 12:47:22.791419 +0100][Dump   ][XRootDTransport   ] [msg: 0x38001b00] Expecting 8 bytes of message body
[2022-03-14 12:47:22.791453 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Received message header, size: 8
[2022-03-14 12:47:22.791462 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Received a message of 16 bytes
[2022-03-14 12:47:22.791469 +0100][Debug  ][XRootDTransport   ] [localhost:33137.0] Got the server hand shake response (type: server [], protocol version 500)
[2022-03-14 12:47:22.795883 +0100][Dump   ][XRootDTransport   ] [msg: 0x38001b00] Expecting 8 bytes of message body
[2022-03-14 12:47:22.795913 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Received message header, size: 8
[2022-03-14 12:47:22.795922 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Received a message of 16 bytes
[2022-03-14 12:47:22.795932 +0100][Debug  ][XRootDTransport   ] [localhost:33137.0] kXR_protocol successful (type: server [], protocol version 500)
[2022-03-14 12:47:22.796041 +0100][Debug  ][XRootDTransport   ] [localhost:33137.0] Sending out kXR_login request, username: paul, cgi: xrd.cc=us&xrd.tz=1&xrd.appname=xrdcp&xrd.info=&xrd.hostname=sprocket.fritz.box&xrd.rn=v20220314-3c87024f8&org.dcache.uuid=df739ef4-665c-4ab9-a67d-560fb3bb1c45&org.dcache.xrootd.client=paul.19732@localhost&oss.asize=1234376, dual-stack: false, private IPv4: true, private IPv6: false
[2022-03-14 12:47:22.796067 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Wrote a message:  (0x38002640), 246 bytes
[2022-03-14 12:47:22.799125 +0100][Dump   ][XRootDTransport   ] [msg: 0x38001570] Expecting 16 bytes of message body
[2022-03-14 12:47:22.799155 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Received message header, size: 8
[2022-03-14 12:47:22.799165 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Received a message of 24 bytes
[2022-03-14 12:47:22.799176 +0100][Debug  ][XRootDTransport   ] [localhost:33137.0] Logged in, session: f98807c604d1b7999dfac86c38c70728
[2022-03-14 12:47:22.799189 +0100][Debug  ][PostMaster        ] [localhost:33137] Stream 0 connected.
[2022-03-14 12:47:22.799208 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Wrote a message: kXR_open (file: public/test-1?org.dcache.uuid=df739ef4-665c-4ab9-a67d-560fb3bb1c45&org.dcache.xrootd.client=paul.19732@localhost&oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0xef5e7da0), 154 bytes
[2022-03-14 12:47:22.799224 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Successfully sent message: kXR_open (file: public/test-1?org.dcache.uuid=df739ef4-665c-4ab9-a67d-560fb3bb1c45&org.dcache.xrootd.client=paul.19732@localhost&oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0xef5e7da0).
[2022-03-14 12:47:22.799233 +0100][Dump   ][XRootD            ] [localhost:33137] Message kXR_open (file: public/test-1?org.dcache.uuid=df739ef4-665c-4ab9-a67d-560fb3bb1c45&org.dcache.xrootd.client=paul.19732@localhost&oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) has been successfully sent.
[2022-03-14 12:47:22.799239 +0100][Debug  ][ExDbgMsg          ] [localhost:33137] Moving MsgHandler: 0xef5e94a0 (message: kXR_open (file: public/test-1?org.dcache.uuid=df739ef4-665c-4ab9-a67d-560fb3bb1c45&org.dcache.xrootd.client=paul.19732@localhost&oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) ) from out-queu to in-queue.
[2022-03-14 12:47:22.799248 +0100][Dump   ][PostMaster        ] [localhost:33137.0] All messages consumed, disable uplink
[2022-03-14 12:47:22.803989 +0100][Dump   ][XRootDTransport   ] [msg: 0x38002650] Expecting 20 bytes of message body
[2022-03-14 12:47:22.804023 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Received message header for 0x38002650 size: 8
[2022-03-14 12:47:22.804039 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Received message 0x38002650 of 28 bytes
[2022-03-14 12:47:22.804047 +0100][Dump   ][PostMaster        ] [localhost:33137] Handling received message: 0x38002650.
[2022-03-14 12:47:22.804073 +0100][Dump   ][XRootD            ] [localhost:33137] Got a kXR_ok response to request kXR_open (file: public/test-1?org.dcache.uuid=df739ef4-665c-4ab9-a67d-560fb3bb1c45&org.dcache.xrootd.client=paul.19732@localhost&oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat )
[2022-03-14 12:47:22.804086 +0100][Debug  ][ExDbgMsg          ] [localhost:33137] Calling MsgHandler: 0xef5e94a0 (message: kXR_open (file: public/test-1?org.dcache.uuid=df739ef4-665c-4ab9-a67d-560fb3bb1c45&org.dcache.xrootd.client=paul.19732@localhost&oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) ) with status: [SUCCESS] .
[2022-03-14 12:47:22.804096 +0100][Dump   ][XRootD            ] [localhost:33137] Parsing the response to kXR_open (file: public/test-1?org.dcache.uuid=df739ef4-665c-4ab9-a67d-560fb3bb1c45&org.dcache.xrootd.client=paul.19732@localhost&oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) as OpenInfo
[2022-03-14 12:47:22.804103 +0100][Dump   ][XRootD            ] [localhost:33137] Parsing StatInfo in response to kXR_open (file: public/test-1?org.dcache.uuid=df739ef4-665c-4ab9-a67d-560fb3bb1c45&org.dcache.xrootd.client=paul.19732@localhost&oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat )
[2022-03-14 12:47:22.804141 +0100][Debug  ][File              ] [0xef5e8b60@root://localhost:1094/public/test-1?oss.asize=1234376&xrdcl.requuid=23bc11da-5836-4ae5-88bb-b214e44124d9] Open has returned with status [SUCCESS] 
[2022-03-14 12:47:22.804151 +0100][Debug  ][File              ] [0xef5e8b60@root://localhost:1094/public/test-1?oss.asize=1234376&xrdcl.requuid=23bc11da-5836-4ae5-88bb-b214e44124d9] successfully opened at localhost:33137, handle: 0x0, session id: 1
[2022-03-14 12:47:22.804171 +0100][Debug  ][XRootD            ] Redirect trace-back:
[2022-03-14 12:47:22.804171 +0100][Debug  ][XRootD            ]         0. Redirected from: root://localhost:1094/public/test-1 to: root://localhost:33137/
[2022-03-14 12:47:22.804179 +0100][Debug  ][ExDbgMsg          ] [localhost:33137] Destroying MsgHandler: 0xef5e94a0.
[2022-03-14 12:47:22.804205 +0100][Dump   ][Utility           ] URL: localhost:33137
[2022-03-14 12:47:22.804205 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-14 12:47:22.804205 +0100][Dump   ][Utility           ] User Name: 
[2022-03-14 12:47:22.804205 +0100][Dump   ][Utility           ] Password:  
[2022-03-14 12:47:22.804205 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-14 12:47:22.804205 +0100][Dump   ][Utility           ] Port:      33137
[2022-03-14 12:47:22.804205 +0100][Dump   ][Utility           ] Path:      
[2022-03-14 12:47:22.804249 +0100][Debug  ][File              ] [0xef5e76e0@file://localhost/bin/bash?xrdcl.requuid=a156572d-bd3e-4245-ac5b-9cf131780f18] Sending a read command for handle 0xb to localhost
[2022-03-14 12:47:22.807264 +0100][Dump   ][File              ] [0xef5e76e0@file://localhost/bin/bash?xrdcl.requuid=a156572d-bd3e-4245-ac5b-9cf131780f18] Got state response for message kXR_read (handle: 0x0b000000, offset: 0, size: 1234376)
[2022-03-14 12:47:22.807325 +0100][Debug  ][File              ] [0xef5e8b60@root://localhost:1094/public/test-1?oss.asize=1234376&xrdcl.requuid=23bc11da-5836-4ae5-88bb-b214e44124d9] Sending a write command for handle 0x0 to localhost:33137
[2022-03-14 12:47:22.807353 +0100][Dump   ][XRootD            ] [localhost:33137] Sending message kXR_write (handle: 0x00000000, offset: 0, size: 1234376)
[2022-03-14 12:47:22.807365 +0100][Debug  ][ExDbgMsg          ] [localhost:33137] MsgHandler created: 0xef5ea910 (message: kXR_write (handle: 0x00000000, offset: 0, size: 1234376) ).
[2022-03-14 12:47:22.807378 +0100][Dump   ][PostMaster        ] [localhost:33137] Sending message kXR_write (handle: 0x00000000, offset: 0, size: 1234376) (0xef5e86e0) through substream 0 expecting answer at 0
[1.177MB/1.177MB][100%][==================================================][1.177MB/s]  [2022-03-14 12:47:22.807446 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Wrote a message: kXR_write (handle: 0x00000000, offset: 0, size: 1234376) (0xef5e86e0), 24 bytes
[2022-03-14 12:47:22.807700 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Wrote 1234376 bytes of raw data of message(0xef5e86e0) body.
[2022-03-14 12:47:22.807721 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Successfully sent message: kXR_write (handle: 0x00000000, offset: 0, size: 1234376) (0xef5e86e0).
[2022-03-14 12:47:22.807728 +0100][Dump   ][XRootD            ] [localhost:33137] Message kXR_write (handle: 0x00000000, offset: 0, size: 1234376) has been successfully sent.
[2022-03-14 12:47:22.807733 +0100][Debug  ][ExDbgMsg          ] [localhost:33137] Moving MsgHandler: 0xef5ea910 (message: kXR_write (handle: 0x00000000, offset: 0, size: 1234376) ) from out-queu to in-queue.
[2022-03-14 12:47:22.807739 +0100][Dump   ][PostMaster        ] [localhost:33137.0] All messages consumed, disable uplink
[2022-03-14 12:47:22.838835 +0100][Dump   ][XRootDTransport   ] [msg: 0x38002650] Expecting 0 bytes of message body
[2022-03-14 12:47:22.838866 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Received message header for 0x38002650 size: 8
[2022-03-14 12:47:22.838876 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Received message 0x38002650 of 8 bytes
[2022-03-14 12:47:22.838884 +0100][Dump   ][PostMaster        ] [localhost:33137] Handling received message: 0x38002650.
[2022-03-14 12:47:22.838904 +0100][Dump   ][XRootD            ] [localhost:33137] Got a kXR_ok response to request kXR_write (handle: 0x00000000, offset: 0, size: 1234376)
[2022-03-14 12:47:22.838923 +0100][Debug  ][ExDbgMsg          ] [localhost:33137] Calling MsgHandler: 0xef5ea910 (message: kXR_write (handle: 0x00000000, offset: 0, size: 1234376) ) with status: [SUCCESS] .
[2022-03-14 12:47:22.838930 +0100][Dump   ][File              ] [0xef5e8b60@root://localhost:1094/public/test-1?oss.asize=1234376&xrdcl.requuid=23bc11da-5836-4ae5-88bb-b214e44124d9] Got state response for message kXR_write (handle: 0x00000000, offset: 0, size: 1234376)
[2022-03-14 12:47:22.838944 +0100][Debug  ][ExDbgMsg          ] [localhost:33137] Destroying MsgHandler: 0xef5ea910.
[2022-03-14 12:47:22.839045 +0100][Debug  ][File              ] [0xef5e8b60@root://localhost:1094/public/test-1?oss.asize=1234376&xrdcl.requuid=23bc11da-5836-4ae5-88bb-b214e44124d9] Sending a close command for handle 0x0 to localhost:33137
[2022-03-14 12:47:22.839063 +0100][Dump   ][XRootD            ] [localhost:33137] Sending message kXR_close (handle: 0x00000000)
[2022-03-14 12:47:22.839071 +0100][Debug  ][ExDbgMsg          ] [localhost:33137] MsgHandler created: 0xef5eb170 (message: kXR_close (handle: 0x00000000) ).
[2022-03-14 12:47:22.839078 +0100][Dump   ][PostMaster        ] [localhost:33137] Sending message kXR_close (handle: 0x00000000) (0xef5ea910) through substream 0 expecting answer at 0
[2022-03-14 12:47:22.839103 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Wrote a message: kXR_close (handle: 0x00000000) (0xef5ea910), 24 bytes
[2022-03-14 12:47:22.839133 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Successfully sent message: kXR_close (handle: 0x00000000) (0xef5ea910).
[2022-03-14 12:47:22.839141 +0100][Dump   ][XRootD            ] [localhost:33137] Message kXR_close (handle: 0x00000000) has been successfully sent.
[2022-03-14 12:47:22.839146 +0100][Debug  ][ExDbgMsg          ] [localhost:33137] Moving MsgHandler: 0xef5eb170 (message: kXR_close (handle: 0x00000000) ) from out-queu to in-queue.
[2022-03-14 12:47:22.839152 +0100][Dump   ][PostMaster        ] [localhost:33137.0] All messages consumed, disable uplink
[2022-03-14 12:47:22.877626 +0100][Dump   ][XRootDTransport   ] [msg: 0x38002650] Expecting 0 bytes of message body
[2022-03-14 12:47:22.877658 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Received message header for 0x38002650 size: 8
[2022-03-14 12:47:22.877666 +0100][Dump   ][AsyncSock         ] [localhost:33137.0] Received message 0x38002650 of 8 bytes
[2022-03-14 12:47:22.877672 +0100][Dump   ][PostMaster        ] [localhost:33137] Handling received message: 0x38002650.
[2022-03-14 12:47:22.877697 +0100][Dump   ][XRootD            ] [localhost:33137] Got a kXR_ok response to request kXR_close (handle: 0x00000000)
[2022-03-14 12:47:22.877708 +0100][Debug  ][ExDbgMsg          ] [localhost:33137] Calling MsgHandler: 0xef5eb170 (message: kXR_close (handle: 0x00000000) ) with status: [SUCCESS] .
[2022-03-14 12:47:22.877717 +0100][Debug  ][File              ] [0xef5e8b60@root://localhost:1094/public/test-1?oss.asize=1234376&xrdcl.requuid=23bc11da-5836-4ae5-88bb-b214e44124d9] Close returned from localhost:33137 with: [SUCCESS] 
[2022-03-14 12:47:22.877722 +0100][Dump   ][File              ] [0xef5e8b60@root://localhost:1094/public/test-1?oss.asize=1234376&xrdcl.requuid=23bc11da-5836-4ae5-88bb-b214e44124d9] Items in the fly 0, queued for recovery 0
[2022-03-14 12:47:22.877735 +0100][Debug  ][ExDbgMsg          ] [localhost:33137] Destroying MsgHandler: 0xef5eb170.
[2022-03-14 12:47:22.877769 +0100][Debug  ][File              ] [0xef5e76e0@file://localhost/bin/bash?xrdcl.requuid=a156572d-bd3e-4245-ac5b-9cf131780f18] Sending a close command for handle 0xb to localhost
[2022-03-14 12:47:22.877800 +0100][Debug  ][File              ] [0xef5e76e0@file://localhost/bin/bash?xrdcl.requuid=a156572d-bd3e-4245-ac5b-9cf131780f18] Close returned from localhost with: [SUCCESS] 
[2022-03-14 12:47:22.877807 +0100][Dump   ][File              ] [0xef5e76e0@file://localhost/bin/bash?xrdcl.requuid=a156572d-bd3e-4245-ac5b-9cf131780f18] Items in the fly 0, queued for recovery 0
[1.177MB/1.177MB][100%][==================================================][1.177MB/s]  
[2022-03-14 12:47:22.878000 +0100][Debug  ][JobMgr            ] Stopping the job manager...
[2022-03-14 12:47:22.878014 +0100][Dump   ][JobMgr            ] Stopping worker #0...
[2022-03-14 12:47:22.878177 +0100][Dump   ][JobMgr            ] Worker #0 stopped
[2022-03-14 12:47:22.878192 +0100][Dump   ][JobMgr            ] Stopping worker #1...
[2022-03-14 12:47:22.878237 +0100][Dump   ][JobMgr            ] Worker #1 stopped
[2022-03-14 12:47:22.878246 +0100][Dump   ][JobMgr            ] Stopping worker #2...
[2022-03-14 12:47:22.878295 +0100][Dump   ][JobMgr            ] Worker #2 stopped
[2022-03-14 12:47:22.878304 +0100][Debug  ][JobMgr            ] Job manager stopped
[2022-03-14 12:47:22.878310 +0100][Debug  ][TaskMgr           ] Stopping the task manager...
[2022-03-14 12:47:22.878397 +0100][Debug  ][TaskMgr           ] Task manager stopped
[2022-03-14 12:47:22.878408 +0100][Debug  ][Poller            ] Stopping the poller...
[2022-03-14 12:47:22.878484 +0100][Debug  ][TaskMgr           ] Requesting unregistration of: "TickGeneratorTask for: root://localhost:1094"
[2022-03-14 12:47:22.878499 +0100][Debug  ][AsyncSock         ] [localhost:1094.0] Closing the socket
[2022-03-14 12:47:22.878507 +0100][Debug  ][Poller            ] <[::ffff:127.0.0.1]:56346><--><[::ffff:127.0.0.1]:1094> Removing socket from the poller
[2022-03-14 12:47:22.878547 +0100][Debug  ][PostMaster        ] [localhost:1094] Destroying stream
[2022-03-14 12:47:22.878557 +0100][Debug  ][AsyncSock         ] [localhost:1094.0] Closing the socket
[2022-03-14 12:47:22.878569 +0100][Debug  ][TaskMgr           ] Requesting unregistration of: "TickGeneratorTask for: root://localhost:33137"
[2022-03-14 12:47:22.878574 +0100][Debug  ][AsyncSock         ] [localhost:33137.0] Closing the socket
[2022-03-14 12:47:22.878579 +0100][Debug  ][Poller            ] <[::ffff:127.0.0.1]:50554><--><[::ffff:127.0.0.1]:33137> Removing socket from the poller
[2022-03-14 12:47:22.878603 +0100][Debug  ][PostMaster        ] [localhost:33137] Destroying stream
[2022-03-14 12:47:22.878610 +0100][Debug  ][AsyncSock         ] [localhost:33137.0] Closing the socket

@simonmichal
Copy link
Contributor

@paulmillar : thanks for testing, yes you might be right ^^ I will be back with another patch!

@simonmichal
Copy link
Contributor

@paulmillar : I pushed another one: 7aca32c and b2ca8fb, now you should see something like:

xrd.cc=us&xrd.tz=1&xrd.appname=xrdcp&xrd.info=&xrd.hostname=sprocket.fritz.box&xrd.rn=v20220314-3c87024f8&org.dcache.door=localhost:1094

Could you please give it a try?

@paulmillar
Copy link
Contributor Author

Sorry, doesn't look like it's working yet.

Here's the output from xrdcp -v -d3 /bin/bash root://localhost/public/test-1

[2022-03-16 11:24:25.648694 +0100][Dump   ][App               ] Chunk size: 8388608, parallel chunks 4, streams: 1
[2022-03-16 11:24:25.648784 +0100][Dump   ][Utility           ] URL: root://localhost/public/test-1
[2022-03-16 11:24:25.648784 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-16 11:24:25.648784 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.648784 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.648784 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.648784 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-16 11:24:25.648784 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-16 11:24:25.648818 +0100][Dump   ][Utility           ] URL: root://localhost:1094/public/test-1
[2022-03-16 11:24:25.648818 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-16 11:24:25.648818 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.648818 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.648818 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.648818 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-16 11:24:25.648818 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-16 11:24:25.648844 +0100][Dump   ][Utility           ] URL: root://localhost:1094/public/test-1
[2022-03-16 11:24:25.648844 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-16 11:24:25.648844 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.648844 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.648844 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.648844 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-16 11:24:25.648844 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-16 11:24:25.648867 +0100][Dump   ][Utility           ] URL: root://localhost:1094/public/test-1
[2022-03-16 11:24:25.648867 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-16 11:24:25.648867 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.648867 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.648867 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.648867 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-16 11:24:25.648867 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-16 11:24:25.648903 +0100][Dump   ][FileSystem        ] [0x55b4c7f0@localhost:1094] Sending kXR_stat (path: public/test-1, flags: none)
[2022-03-16 11:24:25.648918 +0100][Debug  ][Utility           ] Env: trying to get a non-existent string entry: pollerpreference
[2022-03-16 11:24:25.648929 +0100][Debug  ][Poller            ] Available pollers: built-in
[2022-03-16 11:24:25.648935 +0100][Debug  ][Poller            ] Attempting to create a poller according to preference: built-in
[2022-03-16 11:24:25.648940 +0100][Debug  ][Poller            ] Creating poller: built-in
[2022-03-16 11:24:25.648948 +0100][Debug  ][Poller            ] Creating and starting the built-in poller...
[2022-03-16 11:24:25.649064 +0100][Debug  ][Poller            ] Using 1 poller threads
[2022-03-16 11:24:25.649079 +0100][Debug  ][TaskMgr           ] Starting the task manager...
[2022-03-16 11:24:25.649121 +0100][Debug  ][TaskMgr           ] Task manager started
[2022-03-16 11:24:25.649133 +0100][Debug  ][JobMgr            ] Starting the job manager...
[2022-03-16 11:24:25.649227 +0100][Debug  ][JobMgr            ] Job manager started, 3 workers
[2022-03-16 11:24:25.649241 +0100][Debug  ][TaskMgr           ] Registering task: "FileTimer task" to be run at: [2022-03-16 11:24:25 +0100]
[2022-03-16 11:24:25.649249 +0100][Dump   ][XRootD            ] [localhost:1094] Sending message kXR_stat (path: public/test-1, flags: none)
[2022-03-16 11:24:25.649271 +0100][Debug  ][ExDbgMsg          ] [localhost:1094] MsgHandler created: 0x55b51010 (message: kXR_stat (path: public/test-1, flags: none) ).
[2022-03-16 11:24:25.649300 +0100][Dump   ][Utility           ] URL: localhost:1094
[2022-03-16 11:24:25.649300 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-16 11:24:25.649300 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.649300 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.649300 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.649300 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-16 11:24:25.649300 +0100][Dump   ][Utility           ] Path:      
[2022-03-16 11:24:25.649332 +0100][Dump   ][Utility           ] URL: root://localhost:1094
[2022-03-16 11:24:25.649332 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-16 11:24:25.649332 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.649332 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.649332 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.649332 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-16 11:24:25.649332 +0100][Dump   ][Utility           ] Path:      
[2022-03-16 11:24:25.649354 +0100][Debug  ][PostMaster        ] Creating new channel to: root://localhost:1094
[2022-03-16 11:24:25.649372 +0100][Debug  ][PostMaster        ] [localhost:1094] Stream parameters: Network Stack: IPAuto, Connection Window: 120, ConnectionRetry: 5, Stream Error Window: 1800
[2022-03-16 11:24:25.649390 +0100][Debug  ][TaskMgr           ] Registering task: "TickGeneratorTask for: root://localhost:1094" to be run at: [2022-03-16 11:24:40 +0100]
[2022-03-16 11:24:25.649403 +0100][Dump   ][PostMaster        ] [localhost:1094] Sending message kXR_stat (path: public/test-1, flags: none) (0x55b4ca80) through substream 0 expecting answer at 0
[2022-03-16 11:24:25.649562 +0100][Debug  ][PostMaster        ] [localhost:1094] Found 2 address(es): [::ffff:127.0.0.1]:1094, [::ffff:127.0.0.1]:1094
[2022-03-16 11:24:25.649591 +0100][Debug  ][AsyncSock         ] [localhost:1094.0] Attempting connection to [::ffff:127.0.0.1]:1094
[2022-03-16 11:24:25.649653 +0100][Debug  ][Poller            ] Adding socket 0x55b4cb90 to the poller
[2022-03-16 11:24:25.649744 +0100][Debug  ][AsyncSock         ] [localhost:1094.0] Async connection call returned
[2022-03-16 11:24:25.649799 +0100][Debug  ][XRootDTransport   ] [localhost:1094.0] Sending out the initial hand shake + kXR_protocol
[2022-03-16 11:24:25.649848 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Wrote a message:  (0xe0001370), 44 bytes
[2022-03-16 11:24:25.653241 +0100][Dump   ][XRootDTransport   ] [msg: 0xe0001570] Expecting 8 bytes of message body
[2022-03-16 11:24:25.653282 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Received message header, size: 8
[2022-03-16 11:24:25.653299 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Received a message of 16 bytes
[2022-03-16 11:24:25.653314 +0100][Debug  ][XRootDTransport   ] [localhost:1094.0] Got the server hand shake response (type: manager [], protocol version 500)
[2022-03-16 11:24:25.655076 +0100][Dump   ][XRootDTransport   ] [msg: 0xe0001570] Expecting 8 bytes of message body
[2022-03-16 11:24:25.655112 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Received message header, size: 8
[2022-03-16 11:24:25.655129 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Received a message of 16 bytes
[2022-03-16 11:24:25.655149 +0100][Debug  ][XRootDTransport   ] [localhost:1094.0] kXR_protocol successful (type: manager [], protocol version 500)
[2022-03-16 11:24:25.655360 +0100][Debug  ][XRootDTransport   ] [localhost:1094.0] Sending out kXR_login request, username: paul, cgi: xrd.cc=us&xrd.tz=1&xrd.appname=xrdcp&xrd.info=&xrd.hostname=sprocket.fritz.box&xrd.rn=v20220316-518fcdcca, dual-stack: false, private IPv4: true, private IPv6: false
[2022-03-16 11:24:25.655428 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Wrote a message:  (0xe0001830), 129 bytes
[2022-03-16 11:24:25.656443 +0100][Dump   ][XRootDTransport   ] [msg: 0xe0001370] Expecting 16 bytes of message body
[2022-03-16 11:24:25.656464 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Received message header, size: 8
[2022-03-16 11:24:25.656475 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Received a message of 24 bytes
[2022-03-16 11:24:25.656489 +0100][Debug  ][XRootDTransport   ] [localhost:1094.0] Logged in, session: 2a9e34bbd226b6069f1cfaa5a4803dce
[2022-03-16 11:24:25.656504 +0100][Debug  ][PostMaster        ] [localhost:1094] Stream 0 connected.
[2022-03-16 11:24:25.656515 +0100][Debug  ][Utility           ] Monitor library name not set. No monitoring
[2022-03-16 11:24:25.656539 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Wrote a message: kXR_stat (path: public/test-1, flags: none) (0x55b4ca80), 37 bytes
[2022-03-16 11:24:25.656562 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Successfully sent message: kXR_stat (path: public/test-1, flags: none) (0x55b4ca80).
[2022-03-16 11:24:25.656573 +0100][Dump   ][XRootD            ] [localhost:1094] Message kXR_stat (path: public/test-1, flags: none) has been successfully sent.
[2022-03-16 11:24:25.656581 +0100][Debug  ][ExDbgMsg          ] [localhost:1094] Moving MsgHandler: 0x55b51010 (message: kXR_stat (path: public/test-1, flags: none) ) from out-queu to in-queue.
[2022-03-16 11:24:25.656593 +0100][Dump   ][PostMaster        ] [localhost:1094.0] All messages consumed, disable uplink
[2022-03-16 11:24:25.659698 +0100][Dump   ][XRootDTransport   ] [msg: 0xe0002110] Expecting 17 bytes of message body
[2022-03-16 11:24:25.659723 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Received message header for 0xe0002110 size: 8
[2022-03-16 11:24:25.659741 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Received message 0xe0002110 of 25 bytes
[2022-03-16 11:24:25.659749 +0100][Dump   ][PostMaster        ] [localhost:1094] Handling received message: 0xe0002110.
[2022-03-16 11:24:25.659802 +0100][Dump   ][XRootD            ] [localhost:1094] Got a kXR_error response to request kXR_stat (path: public/test-1, flags: none) [3011] No such file
[2022-03-16 11:24:25.659818 +0100][Debug  ][XRootD            ] [localhost:1094] Handling error while processing kXR_stat (path: public/test-1, flags: none): [ERROR] Error response: no such file or directory.
[2022-03-16 11:24:25.659832 +0100][Debug  ][ExDbgMsg          ] [localhost:1094] Calling MsgHandler: 0x55b51010 (message: kXR_stat (path: public/test-1, flags: none) ) with status: [ERROR] Error response: no such file or directory.
[2022-03-16 11:24:25.659845 +0100][Debug  ][ExDbgMsg          ] [localhost:1094] Destroying MsgHandler: 0x55b51010.
[2022-03-16 11:24:25.659862 +0100][Dump   ][App               ] Processing source entry: /bin/bash, type local file, target file: root://localhost/public/test-1
[2022-03-16 11:24:25.659995 +0100][Dump   ][Utility           ] Adding job with properties: 'checkSumMode' = 'none', 'checkSumPreset' = '', 'checkSumType' = '', 'chunkSize' = '8388608', 'coerce' = '0', 'continue' = '0', 'cpTimeout' = '0', 'delegate' = '0', 'dynamicSource' = '0', 'force' = '0', 'initTimeout' = '600', 'makeDir' = '0', 'parallelChunks' = '4', 'posc' = '0', 'preserveXAttr' = '0', 'rmOnBadCksum' = '0', 'source' = 'file:///bin/bash', 'target' = 'root://localhost/public/test-1', 'targetIsDir' = '0', 'thirdParty' = 'none', 'tpcTimeout' = '1800', 'xcp' = '0', 'xcpBlockSize' = '134217728', 'xrate' = '0', 'xrateThreashold' = '0', 'zipAppend' = '0', 'zipArchive' = '0'
[2022-03-16 11:24:25.660026 +0100][Debug  ][Utility           ] CopyProcess: 2 jobs to prepare
[2022-03-16 11:24:25.660045 +0100][Dump   ][Utility           ] URL: file:///bin/bash
[2022-03-16 11:24:25.660045 +0100][Dump   ][Utility           ] Protocol:  file
[2022-03-16 11:24:25.660045 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.660045 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.660045 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.660045 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-16 11:24:25.660045 +0100][Dump   ][Utility           ] Path:      /bin/bash
[2022-03-16 11:24:25.660076 +0100][Dump   ][Utility           ] URL: root://localhost/public/test-1
[2022-03-16 11:24:25.660076 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-16 11:24:25.660076 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.660076 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.660076 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.660076 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-16 11:24:25.660076 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-16 11:24:25.660105 +0100][Dump   ][Utility           ] URL: file:///bin/bash
[2022-03-16 11:24:25.660105 +0100][Dump   ][Utility           ] Protocol:  file
[2022-03-16 11:24:25.660105 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.660105 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.660105 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.660105 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-16 11:24:25.660105 +0100][Dump   ][Utility           ] Path:      /bin/bash
[2022-03-16 11:24:25.660133 +0100][Dump   ][Utility           ] URL: root://localhost/public/test-1
[2022-03-16 11:24:25.660133 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-16 11:24:25.660133 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.660133 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.660133 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.660133 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-16 11:24:25.660133 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-16 11:24:25.660147 +0100][Debug  ][Utility           ] Creating a classic copy job, from file://localhost/bin/bash to root://localhost:1094/public/test-1
[2022-03-16 11:24:25.660207 +0100][Debug  ][Utility           ] Opening file://localhost/bin/bash for reading
[2022-03-16 11:24:25.660227 +0100][Dump   ][Utility           ] URL: file://localhost/bin/bash
[2022-03-16 11:24:25.660227 +0100][Dump   ][Utility           ] Protocol:  file
[2022-03-16 11:24:25.660227 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.660227 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.660227 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.660227 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-16 11:24:25.660227 +0100][Dump   ][Utility           ] Path:      /bin/bash
[2022-03-16 11:24:25.660247 +0100][Dump   ][Utility           ] URL: file://localhost/bin/bash
[2022-03-16 11:24:25.660247 +0100][Dump   ][Utility           ] Protocol:  file
[2022-03-16 11:24:25.660247 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.660247 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.660247 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.660247 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-16 11:24:25.660247 +0100][Dump   ][Utility           ] Path:      /bin/bash
[2022-03-16 11:24:25.660267 +0100][Dump   ][Utility           ] URL: file://localhost/bin/bash
[2022-03-16 11:24:25.660267 +0100][Dump   ][Utility           ] Protocol:  file
[2022-03-16 11:24:25.660267 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.660267 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.660267 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.660267 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-16 11:24:25.660267 +0100][Dump   ][Utility           ] Path:      /bin/bash
[2022-03-16 11:24:25.660317 +0100][Debug  ][File              ] [0x55b556e0@file://localhost/bin/bash?xrdcl.requuid=4bd95908-2021-4370-9247-1237836e41e1] Sending an open command
[2022-03-16 11:24:25.660351 +0100][Dump   ][Utility           ] URL: file://localhost/bin/bash?xrdcl.requuid=4bd95908-2021-4370-9247-1237836e41e1
[2022-03-16 11:24:25.660351 +0100][Dump   ][Utility           ] Protocol:  file
[2022-03-16 11:24:25.660351 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.660351 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.660351 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.660351 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-16 11:24:25.660351 +0100][Dump   ][Utility           ] Path:      /bin/bash
[2022-03-16 11:24:25.660404 +0100][Dump   ][Utility           ] URL: file://localhost/bin/bash?xrdcl.requuid=4bd95908-2021-4370-9247-1237836e41e1
[2022-03-16 11:24:25.660404 +0100][Dump   ][Utility           ] Protocol:  file
[2022-03-16 11:24:25.660404 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.660404 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.660404 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.660404 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-16 11:24:25.660404 +0100][Dump   ][Utility           ] Path:      /bin/bash
[2022-03-16 11:24:25.660482 +0100][Debug  ][File              ] [0x55b556e0@file://localhost/bin/bash?xrdcl.requuid=4bd95908-2021-4370-9247-1237836e41e1] Open has returned with status [SUCCESS] 
[2022-03-16 11:24:25.660495 +0100][Debug  ][File              ] [0x55b556e0@file://localhost/bin/bash?xrdcl.requuid=4bd95908-2021-4370-9247-1237836e41e1] successfully opened at localhost, handle: 0xb, session id: 1
[2022-03-16 11:24:25.660605 +0100][Debug  ][Utility           ] Opening root://localhost:1094/public/test-1?oss.asize=1234376 for writing
[2022-03-16 11:24:25.660632 +0100][Dump   ][Utility           ] URL: root://localhost:1094/public/test-1?oss.asize=1234376
[2022-03-16 11:24:25.660632 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-16 11:24:25.660632 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.660632 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.660632 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.660632 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-16 11:24:25.660632 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-16 11:24:25.660664 +0100][Dump   ][Utility           ] URL: root://localhost:1094/public/test-1?oss.asize=1234376
[2022-03-16 11:24:25.660664 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-16 11:24:25.660664 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.660664 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.660664 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.660664 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-16 11:24:25.660664 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-16 11:24:25.660688 +0100][Dump   ][Utility           ] URL: root://localhost:1094/public/test-1?oss.asize=1234376
[2022-03-16 11:24:25.660688 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-16 11:24:25.660688 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.660688 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.660688 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.660688 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-16 11:24:25.660688 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-16 11:24:25.660729 +0100][Debug  ][File              ] [0x55b56b60@root://localhost:1094/public/test-1?oss.asize=1234376&xrdcl.requuid=16376109-2e4d-4bc1-8436-a8fe04d3916c] Sending an open command
[2022-03-16 11:24:25.660746 +0100][Dump   ][XRootD            ] [localhost:1094] Sending message kXR_open (file: public/test-1?oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat )
[2022-03-16 11:24:25.660759 +0100][Debug  ][ExDbgMsg          ] [localhost:1094] MsgHandler created: 0x55b574a0 (message: kXR_open (file: public/test-1?oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) ).
[2022-03-16 11:24:25.660773 +0100][Dump   ][PostMaster        ] [localhost:1094] Sending message kXR_open (file: public/test-1?oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0x55b55da0) through substream 0 expecting answer at 0
[2022-03-16 11:24:25.660805 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Wrote a message: kXR_open (file: public/test-1?oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0x55b55da0), 55 bytes
[2022-03-16 11:24:25.660836 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Successfully sent message: kXR_open (file: public/test-1?oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0x55b55da0).
[2022-03-16 11:24:25.660845 +0100][Dump   ][XRootD            ] [localhost:1094] Message kXR_open (file: public/test-1?oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) has been successfully sent.
[2022-03-16 11:24:25.660850 +0100][Debug  ][ExDbgMsg          ] [localhost:1094] Moving MsgHandler: 0x55b574a0 (message: kXR_open (file: public/test-1?oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) ) from out-queu to in-queue.
[2022-03-16 11:24:25.660856 +0100][Dump   ][PostMaster        ] [localhost:1094.0] All messages consumed, disable uplink
[2022-03-16 11:24:25.684388 +0100][Dump   ][XRootDTransport   ] [msg: 0xe0002650] Expecting 162 bytes of message body
[2022-03-16 11:24:25.684416 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Received message header for 0xe0002650 size: 8
[2022-03-16 11:24:25.684427 +0100][Dump   ][AsyncSock         ] [localhost:1094.0] Received message 0xe0002650 of 170 bytes
[2022-03-16 11:24:25.684434 +0100][Dump   ][PostMaster        ] [localhost:1094] Handling received message: 0xe0002650.
[2022-03-16 11:24:25.684492 +0100][Dump   ][XRootD            ] [localhost:1094] Got kXR_redirect response to message kXR_open (file: public/test-1?oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ): localhost?org.dcache.xrootd.client=paul.208607@localhost&oss.asize=1234376&org.dcache.uuid=416e655a-e3c9-43a1-a04a-8603fadf3f5e?org.dcache.door=localhost:1094, port 33139
[2022-03-16 11:24:25.684507 +0100][Dump   ][XRootD            ] [localhost:1094] Current server has been assigned as a load-balancer for message kXR_open (file: public/test-1?oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat )
[2022-03-16 11:24:25.684527 +0100][Dump   ][Utility           ] URL: localhost:33139/
[2022-03-16 11:24:25.684527 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-16 11:24:25.684527 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.684527 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.684527 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.684527 +0100][Dump   ][Utility           ] Port:      33139
[2022-03-16 11:24:25.684527 +0100][Dump   ][Utility           ] Path:      
[2022-03-16 11:24:25.684566 +0100][Dump   ][Utility           ] URL: fake://fake:111//fake?org.dcache.xrootd.client=paul.208607@localhost&oss.asize=1234376&org.dcache.uuid=416e655a-e3c9-43a1-a04a-8603fadf3f5e&xrdcl.requuid=16376109-2e4d-4bc1-8436-a8fe04d3916c&
[2022-03-16 11:24:25.684566 +0100][Dump   ][Utility           ] Protocol:  fake
[2022-03-16 11:24:25.684566 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.684566 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.684566 +0100][Dump   ][Utility           ] Host Name: fake
[2022-03-16 11:24:25.684566 +0100][Dump   ][Utility           ] Port:      111
[2022-03-16 11:24:25.684566 +0100][Dump   ][Utility           ] Path:      /fake
[2022-03-16 11:24:25.684605 +0100][Dump   ][Utility           ] URL: fake://fake:111/public/test-1?oss.asize=1234376
[2022-03-16 11:24:25.684605 +0100][Dump   ][Utility           ] Protocol:  fake
[2022-03-16 11:24:25.684605 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.684605 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.684605 +0100][Dump   ][Utility           ] Host Name: fake
[2022-03-16 11:24:25.684605 +0100][Dump   ][Utility           ] Port:      111
[2022-03-16 11:24:25.684605 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-16 11:24:25.684640 +0100][Dump   ][Utility           ] URL: root://localhost:1094/public/test-1
[2022-03-16 11:24:25.684640 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-16 11:24:25.684640 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.684640 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.684640 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.684640 +0100][Dump   ][Utility           ] Port:      1094
[2022-03-16 11:24:25.684640 +0100][Dump   ][Utility           ] Path:      public/test-1
[2022-03-16 11:24:25.684657 +0100][Dump   ][Utility           ] URL: root://localhost:33139/
[2022-03-16 11:24:25.684657 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-16 11:24:25.684657 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.684657 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.684657 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.684657 +0100][Dump   ][Utility           ] Port:      33139
[2022-03-16 11:24:25.684657 +0100][Dump   ][Utility           ] Path:      
[2022-03-16 11:24:25.684681 +0100][Debug  ][ExDbgMsg          ] [localhost:33139] Retry at server MsgHandler: 0x55b574a0 (message: kXR_open (file: public/test-1?org.dcache.uuid=416e655a-e3c9-43a1-a04a-8603fadf3f5e&org.dcache.xrootd.client=paul.208607@localhost&oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) ).
[2022-03-16 11:24:25.684696 +0100][Dump   ][Utility           ] URL: localhost:33139
[2022-03-16 11:24:25.684696 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-16 11:24:25.684696 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.684696 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.684696 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.684696 +0100][Dump   ][Utility           ] Port:      33139
[2022-03-16 11:24:25.684696 +0100][Dump   ][Utility           ] Path:      
[2022-03-16 11:24:25.684717 +0100][Dump   ][Utility           ] URL: root://localhost:33139
[2022-03-16 11:24:25.684717 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-16 11:24:25.684717 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.684717 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.684717 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.684717 +0100][Dump   ][Utility           ] Port:      33139
[2022-03-16 11:24:25.684717 +0100][Dump   ][Utility           ] Path:      
[2022-03-16 11:24:25.684733 +0100][Debug  ][PostMaster        ] Creating new channel to: root://localhost:33139
[2022-03-16 11:24:25.684755 +0100][Debug  ][PostMaster        ] [localhost:33139] Stream parameters: Network Stack: IPAuto, Connection Window: 120, ConnectionRetry: 5, Stream Error Window: 1800
[2022-03-16 11:24:25.684768 +0100][Debug  ][TaskMgr           ] Registering task: "TickGeneratorTask for: root://localhost:33139" to be run at: [2022-03-16 11:24:40 +0100]
[2022-03-16 11:24:25.684777 +0100][Dump   ][PostMaster        ] [localhost:33139] Sending message kXR_open (file: public/test-1?org.dcache.uuid=416e655a-e3c9-43a1-a04a-8603fadf3f5e&org.dcache.xrootd.client=paul.208607@localhost&oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0x55b55da0) through substream 0 expecting answer at 0
[2022-03-16 11:24:25.684897 +0100][Debug  ][PostMaster        ] [localhost:33139] Found 2 address(es): [::ffff:127.0.0.1]:33139, [::ffff:127.0.0.1]:33139
[2022-03-16 11:24:25.684917 +0100][Debug  ][AsyncSock         ] [localhost:33139.0] Attempting connection to [::ffff:127.0.0.1]:33139
[2022-03-16 11:24:25.684980 +0100][Debug  ][Poller            ] Adding socket 0xd0002290 to the poller
[2022-03-16 11:24:25.685016 +0100][Debug  ][AsyncSock         ] [localhost:33139.0] Async connection call returned
[2022-03-16 11:24:25.685031 +0100][Debug  ][XRootDTransport   ] [localhost:33139.0] Sending out the initial hand shake + kXR_protocol
[2022-03-16 11:24:25.685052 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Wrote a message:  (0xe0001570), 44 bytes
[2022-03-16 11:24:25.689089 +0100][Dump   ][XRootDTransport   ] [msg: 0xe0001b00] Expecting 8 bytes of message body
[2022-03-16 11:24:25.689122 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Received message header, size: 8
[2022-03-16 11:24:25.689134 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Received a message of 16 bytes
[2022-03-16 11:24:25.689144 +0100][Debug  ][XRootDTransport   ] [localhost:33139.0] Got the server hand shake response (type: server [], protocol version 500)
[2022-03-16 11:24:25.689466 +0100][Dump   ][XRootDTransport   ] [msg: 0xe0001b00] Expecting 8 bytes of message body
[2022-03-16 11:24:25.689493 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Received message header, size: 8
[2022-03-16 11:24:25.689504 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Received a message of 16 bytes
[2022-03-16 11:24:25.689516 +0100][Debug  ][XRootDTransport   ] [localhost:33139.0] kXR_protocol successful (type: server [], protocol version 500)
[2022-03-16 11:24:25.689656 +0100][Debug  ][XRootDTransport   ] [localhost:33139.0] Sending out kXR_login request, username: paul, cgi: xrd.cc=us&xrd.tz=1&xrd.appname=xrdcp&xrd.info=&xrd.hostname=sprocket.fritz.box&xrd.rn=v20220316-518fcdcca, dual-stack: false, private IPv4: true, private IPv6: false
[2022-03-16 11:24:25.689712 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Wrote a message:  (0xe00028c0), 129 bytes
[2022-03-16 11:24:25.690662 +0100][Dump   ][XRootDTransport   ] [msg: 0xe0001570] Expecting 16 bytes of message body
[2022-03-16 11:24:25.690697 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Received message header, size: 8
[2022-03-16 11:24:25.690712 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Received a message of 24 bytes
[2022-03-16 11:24:25.690726 +0100][Debug  ][XRootDTransport   ] [localhost:33139.0] Logged in, session: 52c5443cff0cb3500426e323c10f3c20
[2022-03-16 11:24:25.690742 +0100][Debug  ][PostMaster        ] [localhost:33139] Stream 0 connected.
[2022-03-16 11:24:25.690772 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Wrote a message: kXR_open (file: public/test-1?org.dcache.uuid=416e655a-e3c9-43a1-a04a-8603fadf3f5e&org.dcache.xrootd.client=paul.208607@localhost&oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0x55b55da0), 155 bytes
[2022-03-16 11:24:25.690808 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Successfully sent message: kXR_open (file: public/test-1?org.dcache.uuid=416e655a-e3c9-43a1-a04a-8603fadf3f5e&org.dcache.xrootd.client=paul.208607@localhost&oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0x55b55da0).
[2022-03-16 11:24:25.690822 +0100][Dump   ][XRootD            ] [localhost:33139] Message kXR_open (file: public/test-1?org.dcache.uuid=416e655a-e3c9-43a1-a04a-8603fadf3f5e&org.dcache.xrootd.client=paul.208607@localhost&oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) has been successfully sent.
[2022-03-16 11:24:25.690831 +0100][Debug  ][ExDbgMsg          ] [localhost:33139] Moving MsgHandler: 0x55b574a0 (message: kXR_open (file: public/test-1?org.dcache.uuid=416e655a-e3c9-43a1-a04a-8603fadf3f5e&org.dcache.xrootd.client=paul.208607@localhost&oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) ) from out-queu to in-queue.
[2022-03-16 11:24:25.690842 +0100][Dump   ][PostMaster        ] [localhost:33139.0] All messages consumed, disable uplink
[2022-03-16 11:24:25.692206 +0100][Dump   ][XRootDTransport   ] [msg: 0xe0002650] Expecting 20 bytes of message body
[2022-03-16 11:24:25.692239 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Received message header for 0xe0002650 size: 8
[2022-03-16 11:24:25.692252 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Received message 0xe0002650 of 28 bytes
[2022-03-16 11:24:25.692262 +0100][Dump   ][PostMaster        ] [localhost:33139] Handling received message: 0xe0002650.
[2022-03-16 11:24:25.692288 +0100][Dump   ][XRootD            ] [localhost:33139] Got a kXR_ok response to request kXR_open (file: public/test-1?org.dcache.uuid=416e655a-e3c9-43a1-a04a-8603fadf3f5e&org.dcache.xrootd.client=paul.208607@localhost&oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat )
[2022-03-16 11:24:25.692310 +0100][Debug  ][ExDbgMsg          ] [localhost:33139] Calling MsgHandler: 0x55b574a0 (message: kXR_open (file: public/test-1?org.dcache.uuid=416e655a-e3c9-43a1-a04a-8603fadf3f5e&org.dcache.xrootd.client=paul.208607@localhost&oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) ) with status: [SUCCESS] .
[2022-03-16 11:24:25.692321 +0100][Dump   ][XRootD            ] [localhost:33139] Parsing the response to kXR_open (file: public/test-1?org.dcache.uuid=416e655a-e3c9-43a1-a04a-8603fadf3f5e&org.dcache.xrootd.client=paul.208607@localhost&oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) as OpenInfo
[2022-03-16 11:24:25.692329 +0100][Dump   ][XRootD            ] [localhost:33139] Parsing StatInfo in response to kXR_open (file: public/test-1?org.dcache.uuid=416e655a-e3c9-43a1-a04a-8603fadf3f5e&org.dcache.xrootd.client=paul.208607@localhost&oss.asize=1234376, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat )
[2022-03-16 11:24:25.692375 +0100][Debug  ][File              ] [0x55b56b60@root://localhost:1094/public/test-1?oss.asize=1234376&xrdcl.requuid=16376109-2e4d-4bc1-8436-a8fe04d3916c] Open has returned with status [SUCCESS] 
[2022-03-16 11:24:25.692388 +0100][Debug  ][File              ] [0x55b56b60@root://localhost:1094/public/test-1?oss.asize=1234376&xrdcl.requuid=16376109-2e4d-4bc1-8436-a8fe04d3916c] successfully opened at localhost:33139, handle: 0x0, session id: 1
[2022-03-16 11:24:25.692412 +0100][Debug  ][XRootD            ] Redirect trace-back:
[2022-03-16 11:24:25.692412 +0100][Debug  ][XRootD            ]         0. Redirected from: root://localhost:1094/public/test-1 to: root://localhost:33139/
[2022-03-16 11:24:25.692424 +0100][Debug  ][ExDbgMsg          ] [localhost:33139] Destroying MsgHandler: 0x55b574a0.
[2022-03-16 11:24:25.692424 +0100][Dump   ][Utility           ] URL: localhost:33139
[2022-03-16 11:24:25.692424 +0100][Dump   ][Utility           ] Protocol:  root
[2022-03-16 11:24:25.692424 +0100][Dump   ][Utility           ] User Name: 
[2022-03-16 11:24:25.692424 +0100][Dump   ][Utility           ] Password:  
[2022-03-16 11:24:25.692424 +0100][Dump   ][Utility           ] Host Name: localhost
[2022-03-16 11:24:25.692424 +0100][Dump   ][Utility           ] Port:      33139
[2022-03-16 11:24:25.692424 +0100][Dump   ][Utility           ] Path:      
[2022-03-16 11:24:25.692476 +0100][Debug  ][File              ] [0x55b556e0@file://localhost/bin/bash?xrdcl.requuid=4bd95908-2021-4370-9247-1237836e41e1] Sending a read command for handle 0xb to localhost
[2022-03-16 11:24:25.693240 +0100][Dump   ][File              ] [0x55b556e0@file://localhost/bin/bash?xrdcl.requuid=4bd95908-2021-4370-9247-1237836e41e1] Got state response for message kXR_read (handle: 0x0b000000, offset: 0, size: 1234376)
[2022-03-16 11:24:25.693298 +0100][Debug  ][File              ] [0x55b56b60@root://localhost:1094/public/test-1?oss.asize=1234376&xrdcl.requuid=16376109-2e4d-4bc1-8436-a8fe04d3916c] Sending a write command for handle 0x0 to localhost:33139
[2022-03-16 11:24:25.693320 +0100][Dump   ][XRootD            ] [localhost:33139] Sending message kXR_write (handle: 0x00000000, offset: 0, size: 1234376)
[2022-03-16 11:24:25.693333 +0100][Debug  ][ExDbgMsg          ] [localhost:33139] MsgHandler created: 0x55b58910 (message: kXR_write (handle: 0x00000000, offset: 0, size: 1234376) ).
[2022-03-16 11:24:25.693347 +0100][Dump   ][PostMaster        ] [localhost:33139] Sending message kXR_write (handle: 0x00000000, offset: 0, size: 1234376) (0x55b566e0) through substream 0 expecting answer at 0
[2022-03-16 11:24:25.693386 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Wrote a message: kXR_write (handle: 0x00000000, offset: 0, size: 1234376) (0x55b566e0), 24 bytes
[1.177MB/1.177MB][100%][==================================================][1.177MB/s]  [2022-03-16 11:24:25.693686 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Wrote 1234376 bytes of raw data of message(0x55b566e0) body.
[2022-03-16 11:24:25.693715 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Successfully sent message: kXR_write (handle: 0x00000000, offset: 0, size: 1234376) (0x55b566e0).
[2022-03-16 11:24:25.693723 +0100][Dump   ][XRootD            ] [localhost:33139] Message kXR_write (handle: 0x00000000, offset: 0, size: 1234376) has been successfully sent.
[2022-03-16 11:24:25.693729 +0100][Debug  ][ExDbgMsg          ] [localhost:33139] Moving MsgHandler: 0x55b58910 (message: kXR_write (handle: 0x00000000, offset: 0, size: 1234376) ) from out-queu to in-queue.
[2022-03-16 11:24:25.693743 +0100][Dump   ][PostMaster        ] [localhost:33139.0] All messages consumed, disable uplink
[2022-03-16 11:24:25.698465 +0100][Dump   ][XRootDTransport   ] [msg: 0xe0002650] Expecting 0 bytes of message body
[2022-03-16 11:24:25.698495 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Received message header for 0xe0002650 size: 8
[2022-03-16 11:24:25.698504 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Received message 0xe0002650 of 8 bytes
[2022-03-16 11:24:25.698510 +0100][Dump   ][PostMaster        ] [localhost:33139] Handling received message: 0xe0002650.
[2022-03-16 11:24:25.698530 +0100][Dump   ][XRootD            ] [localhost:33139] Got a kXR_ok response to request kXR_write (handle: 0x00000000, offset: 0, size: 1234376)
[2022-03-16 11:24:25.698548 +0100][Debug  ][ExDbgMsg          ] [localhost:33139] Calling MsgHandler: 0x55b58910 (message: kXR_write (handle: 0x00000000, offset: 0, size: 1234376) ) with status: [SUCCESS] .
[2022-03-16 11:24:25.698556 +0100][Dump   ][File              ] [0x55b56b60@root://localhost:1094/public/test-1?oss.asize=1234376&xrdcl.requuid=16376109-2e4d-4bc1-8436-a8fe04d3916c] Got state response for message kXR_write (handle: 0x00000000, offset: 0, size: 1234376)
[2022-03-16 11:24:25.698571 +0100][Debug  ][ExDbgMsg          ] [localhost:33139] Destroying MsgHandler: 0x55b58910.
[2022-03-16 11:24:25.698677 +0100][Debug  ][File              ] [0x55b56b60@root://localhost:1094/public/test-1?oss.asize=1234376&xrdcl.requuid=16376109-2e4d-4bc1-8436-a8fe04d3916c] Sending a close command for handle 0x0 to localhost:33139
[2022-03-16 11:24:25.698693 +0100][Dump   ][XRootD            ] [localhost:33139] Sending message kXR_close (handle: 0x00000000)
[2022-03-16 11:24:25.698701 +0100][Debug  ][ExDbgMsg          ] [localhost:33139] MsgHandler created: 0x55b59170 (message: kXR_close (handle: 0x00000000) ).
[2022-03-16 11:24:25.698709 +0100][Dump   ][PostMaster        ] [localhost:33139] Sending message kXR_close (handle: 0x00000000) (0x55b58910) through substream 0 expecting answer at 0
[2022-03-16 11:24:25.698733 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Wrote a message: kXR_close (handle: 0x00000000) (0x55b58910), 24 bytes
[2022-03-16 11:24:25.698757 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Successfully sent message: kXR_close (handle: 0x00000000) (0x55b58910).
[2022-03-16 11:24:25.698765 +0100][Dump   ][XRootD            ] [localhost:33139] Message kXR_close (handle: 0x00000000) has been successfully sent.
[2022-03-16 11:24:25.698769 +0100][Debug  ][ExDbgMsg          ] [localhost:33139] Moving MsgHandler: 0x55b59170 (message: kXR_close (handle: 0x00000000) ) from out-queu to in-queue.
[2022-03-16 11:24:25.698775 +0100][Dump   ][PostMaster        ] [localhost:33139.0] All messages consumed, disable uplink
[2022-03-16 11:24:25.715558 +0100][Dump   ][XRootDTransport   ] [msg: 0xe0002650] Expecting 0 bytes of message body
[2022-03-16 11:24:25.715587 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Received message header for 0xe0002650 size: 8
[2022-03-16 11:24:25.715597 +0100][Dump   ][AsyncSock         ] [localhost:33139.0] Received message 0xe0002650 of 8 bytes
[2022-03-16 11:24:25.715604 +0100][Dump   ][PostMaster        ] [localhost:33139] Handling received message: 0xe0002650.
[2022-03-16 11:24:25.715628 +0100][Dump   ][XRootD            ] [localhost:33139] Got a kXR_ok response to request kXR_close (handle: 0x00000000)
[2022-03-16 11:24:25.715638 +0100][Debug  ][ExDbgMsg          ] [localhost:33139] Calling MsgHandler: 0x55b59170 (message: kXR_close (handle: 0x00000000) ) with status: [SUCCESS] .
[2022-03-16 11:24:25.715649 +0100][Debug  ][File              ] [0x55b56b60@root://localhost:1094/public/test-1?oss.asize=1234376&xrdcl.requuid=16376109-2e4d-4bc1-8436-a8fe04d3916c] Close returned from localhost:33139 with: [SUCCESS] 
[2022-03-16 11:24:25.715656 +0100][Dump   ][File              ] [0x55b56b60@root://localhost:1094/public/test-1?oss.asize=1234376&xrdcl.requuid=16376109-2e4d-4bc1-8436-a8fe04d3916c] Items in the fly 0, queued for recovery 0
[2022-03-16 11:24:25.715667 +0100][Debug  ][ExDbgMsg          ] [localhost:33139] Destroying MsgHandler: 0x55b59170.
[2022-03-16 11:24:25.715698 +0100][Debug  ][File              ] [0x55b556e0@file://localhost/bin/bash?xrdcl.requuid=4bd95908-2021-4370-9247-1237836e41e1] Sending a close command for handle 0xb to localhost
[2022-03-16 11:24:25.715733 +0100][Debug  ][File              ] [0x55b556e0@file://localhost/bin/bash?xrdcl.requuid=4bd95908-2021-4370-9247-1237836e41e1] Close returned from localhost with: [SUCCESS] 
[2022-03-16 11:24:25.715740 +0100][Dump   ][File              ] [0x55b556e0@file://localhost/bin/bash?xrdcl.requuid=4bd95908-2021-4370-9247-1237836e41e1] Items in the fly 0, queued for recovery 0
[1.177MB/1.177MB][100%][==================================================][1.177MB/s]  
[2022-03-16 11:24:25.715930 +0100][Debug  ][JobMgr            ] Stopping the job manager...
[2022-03-16 11:24:25.715942 +0100][Dump   ][JobMgr            ] Stopping worker #0...
[2022-03-16 11:24:25.716065 +0100][Dump   ][JobMgr            ] Worker #0 stopped
[2022-03-16 11:24:25.716076 +0100][Dump   ][JobMgr            ] Stopping worker #1...
[2022-03-16 11:24:25.716117 +0100][Dump   ][JobMgr            ] Worker #1 stopped
[2022-03-16 11:24:25.716124 +0100][Dump   ][JobMgr            ] Stopping worker #2...
[2022-03-16 11:24:25.716160 +0100][Dump   ][JobMgr            ] Worker #2 stopped
[2022-03-16 11:24:25.716167 +0100][Debug  ][JobMgr            ] Job manager stopped
[2022-03-16 11:24:25.716173 +0100][Debug  ][TaskMgr           ] Stopping the task manager...
[2022-03-16 11:24:25.722337 +0100][Debug  ][TaskMgr           ] Task manager stopped
[2022-03-16 11:24:25.722373 +0100][Debug  ][Poller            ] Stopping the poller...
[2022-03-16 11:24:25.722479 +0100][Debug  ][TaskMgr           ] Requesting unregistration of: "TickGeneratorTask for: root://localhost:1094"
[2022-03-16 11:24:25.722499 +0100][Debug  ][AsyncSock         ] [localhost:1094.0] Closing the socket
[2022-03-16 11:24:25.722510 +0100][Debug  ][Poller            ] <[::ffff:127.0.0.1]:46722><--><[::ffff:127.0.0.1]:1094> Removing socket from the poller
[2022-03-16 11:24:25.722564 +0100][Debug  ][PostMaster        ] [localhost:1094] Destroying stream
[2022-03-16 11:24:25.722577 +0100][Debug  ][AsyncSock         ] [localhost:1094.0] Closing the socket
[2022-03-16 11:24:25.722591 +0100][Debug  ][TaskMgr           ] Requesting unregistration of: "TickGeneratorTask for: root://localhost:33139"
[2022-03-16 11:24:25.722597 +0100][Debug  ][AsyncSock         ] [localhost:33139.0] Closing the socket
[2022-03-16 11:24:25.722602 +0100][Debug  ][Poller            ] <[::ffff:127.0.0.1]:47436><--><[::ffff:127.0.0.1]:33139> Removing socket from the poller
[2022-03-16 11:24:25.722628 +0100][Debug  ][PostMaster        ] [localhost:33139] Destroying stream
[2022-03-16 11:24:25.722634 +0100][Debug  ][AsyncSock         ] [localhost:33139.0] Closing the socket

@simonmichal
Copy link
Contributor

@paulmillar : thanks for testing and the logs, I will get back to you soon ...

@simonmichal
Copy link
Contributor

@paulmillar : it seems that by accident missed one file in the previous commits, so here it is: 76b9c83

It should work now, could you please give it a try?
(I realise that this issues is not handled up to highest standards, I do apologise for that and appreciate your patience)

@paulmillar
Copy link
Contributor Author

Thanks @simonmichal

Yes, I can now see the login token being used when the client reacts to the redirection. 🎉

I've a couple of questions:

  1. I guess the token isn't an arbitrary format, but should follow a key=value format (perhaps key=value&key=value, more generally).

This isn't a problem, just something we should keep in mind if we want to pass more information this way.

  1. Do you have an idea which xrootd versions will have this fix? (Is it going to be back-ported?)

I don't think this is a big deal. Supporting login tokens on redirection will allow us (dCache) to provide a more robust xroot protocol implementation; however, this should only matter if there are changes in how the client behaves.

Cheers,
Paul.

@simonmichal
Copy link
Contributor

Thanks a lot for testing! :-)

I guess the token isn't an arbitrary format, but should follow a key=value format (perhaps key=value&key=value, more generally).

I don't think there are any specific restrictions on the format, that said it does make sense to follow the key=value semantics as it gets chained to other ci elements

Do you have an idea which xrootd versions will have this fix? (Is it going to be back-ported?)

We plan to have 5.5.0 at the beginning of May, it could be back ported to 5.4.x if there is a strong desire ;-)

@paulmillar
Copy link
Contributor Author

Thanks for the info. Right now, I don't think we need to back-port the fix.

Cheers,
Paul.

paulmillar added a commit to dCache/dcache that referenced this issue Jun 22, 2022
Motivation:

On the pool, the xrootd mover provides only limited support for the
possible operations in the xroot protocol.  If a client makes a request
that the pool doesn't support then it will try to redirect the client
back to the door.  To do this, the mover needs to know the door's
endpoint: the hostname and port number.

The door endpoint is provided as part of the ProtocolInfo.  However, the
ProtocolInfo is only available to the xroot handler if the client has
already made a valid kXR_open request.  If a client connects to the door
and makes an unsupported request (without first opening a file) then the
xrootd transfer service does not know to which xroot door is should
redirect the client, so must fail the request.

Although the door only redirects the client to the pool when that client
wishes to open a file, the xrootd client sometimes caches this
information and issues subsequent (unsupported) requests directly to the
pool.  If the client does so on a separate TCP connection then the pool
cannot know from which door the client came, so cannot redirect the
client.

Modification:

The door now provides the client with a "login token" when redirecting
the client to the pool.  This token is a simple encoding of the door's
public endpoint.

As per the xroot protocol, the client is required to present this token
when first connecting to the endpoint, as part of the kXR_login
procedure.  This means the xrootd transfer handler (on the pool) will
know the door's public endpoint, so will be able to redirect the client
back to the door.

Note that, due to a bug in the xrootd software, the login token from the
door is ignored.  This bug will be fixed with the anticipated 5.5.0
release of xrootd:

    xrootd/xrootd#1533

Result:

dCache provides a more robust implemntation of xroot protocol.

Target: master
Requires-notes: no
Requires-book: no
Patch: https://rb.dcache.org/r/13491/
Acked-by: Albert Rossi
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants