Print

Print

Copy-pasting Elvin's description of the problem:

I've implemented the async response on close in EOS and this works perfectly fine. The only thing which is a bit wired is that I get no feedback on the client side whatsoever concerning this. The kXR_waitresp values are respected in the client but it's impossible to track or to understand from the logs this thing.

Therefore, could you add some more debug concerning this? Otherwise this will be a nightmare to debug such a scenario in production.

Below you have an example of the client logs when such a response is received from the server. (you actually don't see anything but look at the timestamps and you'll see the client waits around 80 seconds for the response to come from the server).

Thanks,
Elvin

[3.167kB/3.167kB][100%][==================================================][3.167kB/s] [2018-10-29 22:36:21.573011 +0100][Dump ][AsyncSock ] [esdss000.cern.ch:2001 #0.0] WroteV a message: kXR_w
rite (handle: 0x00000000, offset: 0, size: 3243) (0x147e440), 24 bytes
[2018-10-29 22:36:21.573023 +0100][Dump ][AsyncSock ] [esdss000.cern.ch:2001 #0.0] WroteV raw data: 3243 bytes
[2018-10-29 22:36:21.573036 +0100][Dump ][AsyncSock ] [esdss000.cern.ch:2001 #0.0] Successfully sent message: kXR_write (handle: 0x00000000, offset: 0, size: 3243) (0x147e440).
[2018-10-29 22:36:21.573045 +0100][Dump ][XRootD ] [esdss000.cern.ch:2001] Message kXR_write (handle: 0x00000000, offset: 0, size: 3243) has been successfully sent.
[2018-10-29 22:36:21.573054 +0100][Dump ][PostMaster ] [esdss000.cern.ch:2001 #0.0] All messages consumed, disable uplink
[2018-10-29 22:36:21.573257 +0100][Dump ][XRootDTransport ] [msg: 0x8c002eb0] Expecting 0 bytes of message body
[2018-10-29 22:36:21.573265 +0100][Dump ][AsyncSock ] [esdss000.cern.ch:2001 #0.0] Received message header for 0x8c002eb0 size: 8
[2018-10-29 22:36:21.573270 +0100][Dump ][AsyncSock ] [esdss000.cern.ch:2001 #0.0] Received message 0x8c002eb0 of 8 bytes
[2018-10-29 22:36:21.573274 +0100][Dump ][PostMaster ] [esdss000.cern.ch:2001 #0] Handling received message: 0x8c002eb0.
[2018-10-29 22:36:21.573325 +0100][Dump ][XRootD ] [esdss000.cern.ch:2001] Got a kXR_ok response to request kXR_write (handle: 0x00000000, offset: 0, size: 3243)
[2018-10-29 22:36:21.573338 +0100][Dump ][File ] [0x147e540@root://localhost:1094//eos/dev/plain/file1.dat?oss.asize=3243] Got state response for message kXR_write (handle: 0x00000000, offs
et: 0, size: 3243)
[2018-10-29 22:36:21.573386 +0100][Debug ][File ] [0x147e540@root://localhost:1094//eos/dev/plain/file1.dat?oss.asize=3243] Sending a close command for handle 0x0 to esdss000.cern.ch:2001
[2018-10-29 22:36:21.573400 +0100][Dump ][XRootD ] [esdss000.cern.ch:2001] Sending message kXR_close (handle: 0x00000000)
[2018-10-29 22:36:21.573409 +0100][Dump ][PostMaster ] [esdss000.cern.ch:2001 #0] Sending message kXR_close (handle: 0x00000000) (0x147e440) through substream 0 expecting answer at 0
[2018-10-29 22:36:21.573432 +0100][Dump ][AsyncSock ] [esdss000.cern.ch:2001 #0.0] Wrote a message: kXR_close (handle: 0x00000000) (0x147e440), 24 bytes
[2018-10-29 22:36:21.573441 +0100][Dump ][AsyncSock ] [esdss000.cern.ch:2001 #0.0] Successfully sent message: kXR_close (handle: 0x00000000) (0x147e440).
[2018-10-29 22:36:21.573449 +0100][Dump ][XRootD ] [esdss000.cern.ch:2001] Message kXR_close (handle: 0x00000000) has been successfully sent.
[2018-10-29 22:36:21.573458 +0100][Dump ][PostMaster ] [esdss000.cern.ch:2001 #0.0] All messages consumed, disable uplink
[2018-10-29 22:36:21.574555 +0100][Dump ][XRootDTransport ] [msg: 0x8c003ba0] Expecting 4 bytes of message body
[2018-10-29 22:36:21.574569 +0100][Dump ][AsyncSock ] [esdss000.cern.ch:2001 #0.0] Received message header for 0x8c003ba0 size: 8
[2018-10-29 22:36:21.574580 +0100][Dump ][AsyncSock ] [esdss000.cern.ch:2001 #0.0] Received message 0x8c003ba0 of 12 bytes
[2018-10-29 22:36:21.574588 +0100][Dump ][PostMaster ] [esdss000.cern.ch:2001 #0] Handling received message: 0x8c003ba0.
[2018-10-29 22:36:21.574593 +0100][Dump ][PostMaster ] [esdss000.cern.ch:2001 #0] Ignoring the processing handler for: 0x6153f8.
[2018-10-29 22:36:22.552094 +0100][Dump ][TaskMgr ] Running task: "FileTimer task"
[2018-10-29 22:36:22.552204 +0100][Dump ][TaskMgr ] Will rerun task "FileTimer task" at [2018-10-29 22:36:37 +0100]
[2018-10-29 22:36:36.554529 +0100][Dump ][TaskMgr ] Running task: "TickGeneratorTask for: localhost:1094"
[2018-10-29 22:36:36.554616 +0100][Dump ][TaskMgr ] Will rerun task "TickGeneratorTask for: localhost:1094" at [2018-10-29 22:36:51 +0100]
[2018-10-29 22:36:36.554635 +0100][Dump ][TaskMgr ] Running task: "TickGeneratorTask for: esdss000.cern.ch:2001"
[2018-10-29 22:36:36.554653 +0100][Dump ][TaskMgr ] Will rerun task "TickGeneratorTask for: esdss000.cern.ch:2001" at [2018-10-29 22:36:51 +0100]
[2018-10-29 22:36:36.589808 +0100][Dump ][XRootDTransport ] [localhost:1094 #0.0] Stream inactive since 15 seconds, TTL: 1200, allocated SIDs: 0, open files: 0
[2018-10-29 22:36:36.589879 +0100][Dump ][XRootDTransport ] [localhost:1094 #0.0] Stream inactive since 15 seconds, stream timeout: 60, allocated SIDs: 0, wait barrier: 2018-10-29 22:36:21 +0100
[2018-10-29 22:36:36.589903 +0100][Dump ][XRootDTransport ] [esdss000.cern.ch:2001 #0.0] Stream inactive since 15 seconds, TTL: 300, allocated SIDs: 1, open files: 1
[2018-10-29 22:36:36.589922 +0100][Dump ][XRootDTransport ] [esdss000.cern.ch:2001 #0.0] Stream inactive since 15 seconds, stream timeout: 60, allocated SIDs: 1, wait barrier: 2018-10-29 22:38:21 +010
0
[2018-10-29 22:36:37.554816 +0100][Dump ][TaskMgr ] Running task: "FileTimer task"
[2018-10-29 22:36:37.554893 +0100][Dump ][TaskMgr ] Will rerun task "FileTimer task" at [2018-10-29 22:36:52 +0100]
[2018-10-29 22:36:51.557665 +0100][Dump ][TaskMgr ] Running task: "TickGeneratorTask for: localhost:1094"
[2018-10-29 22:36:51.557740 +0100][Dump ][TaskMgr ] Will rerun task "TickGeneratorTask for: localhost:1094" at [2018-10-29 22:37:06 +0100]
[2018-10-29 22:36:51.557758 +0100][Dump ][TaskMgr ] Running task: "TickGeneratorTask for: esdss000.cern.ch:2001"
[2018-10-29 22:36:51.557776 +0100][Dump ][TaskMgr ] Will rerun task "TickGeneratorTask for: esdss000.cern.ch:2001" at [2018-10-29 22:37:06 +0100]
[2018-10-29 22:36:51.605160 +0100][Dump ][XRootDTransport ] [localhost:1094 #0.0] Stream inactive since 30 seconds, TTL: 1200, allocated SIDs: 0, open files: 0
[2018-10-29 22:36:51.605219 +0100][Dump ][XRootDTransport ] [localhost:1094 #0.0] Stream inactive since 30 seconds, stream timeout: 60, allocated SIDs: 0, wait barrier: 2018-10-29 22:36:21 +0100
[2018-10-29 22:36:51.605239 +0100][Dump ][XRootDTransport ] [esdss000.cern.ch:2001 #0.0] Stream inactive since 30 seconds, TTL: 300, allocated SIDs: 1, open files: 1
[2018-10-29 22:36:51.605253 +0100][Dump ][XRootDTransport ] [esdss000.cern.ch:2001 #0.0] Stream inactive since 30 seconds, stream timeout: 60, allocated SIDs: 1, wait barrier: 2018-10-29 22:38:21 +010
0
[2018-10-29 22:36:52.557945 +0100][Dump ][TaskMgr ] Running task: "FileTimer task"
[2018-10-29 22:36:52.558023 +0100][Dump ][TaskMgr ] Will rerun task "FileTimer task" at [2018-10-29 22:37:07 +0100]
[2018-10-29 22:37:06.560138 +0100][Dump ][TaskMgr ] Running task: "TickGeneratorTask for: localhost:1094"
[2018-10-29 22:37:06.560213 +0100][Dump ][TaskMgr ] Will rerun task "TickGeneratorTask for: localhost:1094" at [2018-10-29 22:37:21 +0100]
[2018-10-29 22:37:06.560232 +0100][Dump ][TaskMgr ] Running task: "TickGeneratorTask for: esdss000.cern.ch:2001"
[2018-10-29 22:37:06.560250 +0100][Dump ][TaskMgr ] Will rerun task "TickGeneratorTask for: esdss000.cern.ch:2001" at [2018-10-29 22:37:21 +0100]
[2018-10-29 22:37:06.620444 +0100][Dump ][XRootDTransport ] [localhost:1094 #0.0] Stream inactive since 45 seconds, TTL: 1200, allocated SIDs: 0, open files: 0
[2018-10-29 22:37:06.620504 +0100][Dump ][XRootDTransport ] [localhost:1094 #0.0] Stream inactive since 45 seconds, stream timeout: 60, allocated SIDs: 0, wait barrier: 2018-10-29 22:36:21 +0100
[2018-10-29 22:37:06.620525 +0100][Dump ][XRootDTransport ] [esdss000.cern.ch:2001 #0.0] Stream inactive since 45 seconds, TTL: 300, allocated SIDs: 1, open files: 1
[2018-10-29 22:37:06.620540 +0100][Dump ][XRootDTransport ] [esdss000.cern.ch:2001 #0.0] Stream inactive since 45 seconds, stream timeout: 60, allocated SIDs: 1, wait barrier: 2018-10-29 22:38:21 +010
0
[2018-10-29 22:37:07.560543 +0100][Dump ][TaskMgr ] Running task: "FileTimer task"
[2018-10-29 22:37:07.560620 +0100][Dump ][TaskMgr ] Will rerun task "FileTimer task" at [2018-10-29 22:37:22 +0100]
[2018-10-29 22:37:21.563398 +0100][Dump ][TaskMgr ] Running task: "TickGeneratorTask for: localhost:1094"
[2018-10-29 22:37:21.563478 +0100][Dump ][TaskMgr ] Will rerun task "TickGeneratorTask for: localhost:1094" at [2018-10-29 22:37:36 +0100]
[2018-10-29 22:37:21.563495 +0100][Dump ][TaskMgr ] Running task: "TickGeneratorTask for: esdss000.cern.ch:2001"
[2018-10-29 22:37:21.563513 +0100][Dump ][TaskMgr ] Will rerun task "TickGeneratorTask for: esdss000.cern.ch:2001" at [2018-10-29 22:37:36 +0100]
[2018-10-29 22:37:21.634247 +0100][Dump ][XRootDTransport ] [localhost:1094 #0.0] Stream inactive since 60 seconds, TTL: 1200, allocated SIDs: 0, open files: 0
[2018-10-29 22:37:21.634315 +0100][Dump ][XRootDTransport ] [localhost:1094 #0.0] Stream inactive since 60 seconds, stream timeout: 60, allocated SIDs: 0, wait barrier: 2018-10-29 22:36:21 +0100
[2018-10-29 22:37:21.634340 +0100][Dump ][XRootDTransport ] [esdss000.cern.ch:2001 #0.0] Stream inactive since 60 seconds, TTL: 300, allocated SIDs: 1, open files: 1
[2018-10-29 22:37:21.634358 +0100][Dump ][XRootDTransport ] [esdss000.cern.ch:2001 #0.0] Stream inactive since 60 seconds, stream timeout: 60, allocated SIDs: 1, wait barrier: 2018-10-29 22:38:21 +010
0
[2018-10-29 22:37:22.563764 +0100][Dump ][TaskMgr ] Running task: "FileTimer task"
[2018-10-29 22:37:22.563843 +0100][Dump ][TaskMgr ] Will rerun task "FileTimer task" at [2018-10-29 22:37:37 +0100]
[2018-10-29 22:37:36.565991 +0100][Dump ][TaskMgr ] Running task: "TickGeneratorTask for: localhost:1094"
[2018-10-29 22:37:36.566087 +0100][Dump ][TaskMgr ] Will rerun task "TickGeneratorTask for: localhost:1094" at [2018-10-29 22:37:51 +0100]
[2018-10-29 22:37:36.566106 +0100][Dump ][TaskMgr ] Running task: "TickGeneratorTask for: esdss000.cern.ch:2001"
[2018-10-29 22:37:36.566124 +0100][Dump ][TaskMgr ] Will rerun task "TickGeneratorTask for: esdss000.cern.ch:2001" at [2018-10-29 22:37:51 +0100]
[2018-10-29 22:37:36.647272 +0100][Dump ][XRootDTransport ] [localhost:1094 #0.0] Stream inactive since 75 seconds, TTL: 1200, allocated SIDs: 0, open files: 0
[2018-10-29 22:37:36.647343 +0100][Dump ][XRootDTransport ] [localhost:1094 #0.0] Stream inactive since 75 seconds, stream timeout: 60, allocated SIDs: 0, wait barrier: 2018-10-29 22:36:21 +0100
[2018-10-29 22:37:36.647368 +0100][Dump ][XRootDTransport ] [esdss000.cern.ch:2001 #0.0] Stream inactive since 75 seconds, TTL: 300, allocated SIDs: 1, open files: 1
[2018-10-29 22:37:36.647386 +0100][Dump ][XRootDTransport ] [esdss000.cern.ch:2001 #0.0] Stream inactive since 75 seconds, stream timeout: 60, allocated SIDs: 1, wait barrier: 2018-10-29 22:38:21 +010
0
[2018-10-29 22:37:37.566273 +0100][Dump ][TaskMgr ] Running task: "FileTimer task"
[2018-10-29 22:37:37.566347 +0100][Dump ][TaskMgr ] Will rerun task "FileTimer task" at [2018-10-29 22:37:52 +0100]
[2018-10-29 22:37:41.575147 +0100][Dump ][XRootDTransport ] [msg: 0x8c003ba0] Expecting 16 bytes of message body
[2018-10-29 22:37:41.575199 +0100][Dump ][AsyncSock ] [esdss000.cern.ch:2001 #0.0] Received message header for 0x8c003ba0 size: 8
[2018-10-29 22:37:41.575227 +0100][Dump ][AsyncSock ] [esdss000.cern.ch:2001 #0.0] Received message 0x8c003ba0 of 24 bytes
[2018-10-29 22:37:41.575246 +0100][Dump ][PostMaster ] [esdss000.cern.ch:2001 #0] Queuing received message: 0x8c003ba0.
[2018-10-29 22:37:41.575304 +0100][Dump ][XRootD ] [esdss000.cern.ch:2001] Got an async response to message kXR_close (handle: 0x00000000), processing it
[2018-10-29 22:37:41.575358 +0100][Dump ][XRootD ] [esdss000.cern.ch:2001] Got a kXR_ok response to request kXR_close (handle: 0x00000000)
[2018-10-29 22:37:41.575387 +0100][Debug ][File ] [0x147e540@root://localhost:1094//eos/dev/plain/file1.dat?oss.asize=3243] Close returned from esdss000.cern.ch:2001 with: [SUCCESS]
[2018-10-29 22:37:41.575405 +0100][Dump ][File ] [0x147e540@root://localhost:1094//eos/dev/plain/file1.dat?oss.asize=3243] Items in the fly 0, queued for recovery 0
[2018-10-29 22:37:41.575509 +0100][Debug ][File ] [0x147db90@file://localhost/etc/passwd] Sending a close command for handle 0xb to localhost
[2018-10-29 22:37:41.575691 +0100][Debug ][File ] [0x147db90@file://localhost/etc/passwd] Close returned from localhost with: [SUCCESS]
[2018-10-29 22:37:41.575729 +0100][Dump ][File ] [0x147db90@file://localhost/etc/passwd] Items in the fly 0, queued for recovery 0
[3.167kB/3.167kB][100%][==================================================][40B/s]
[2018-10-29 22:37:41.576092 +0100][Debug ][JobMgr ] Stopping the job manager...
[2018-10-29 22:37:41.576124 +0100][Dump ][JobMgr ] Stopping worker #0...
[2018-10-29 22:37:41.576456 +0100][Dump ][JobMgr ] Worker #0 stopped
[2018-10-29 22:37:41.576476 +0100][Dump ][JobMgr ] Stopping worker #1...
[2018-10-29 22:37:41.576563 +0100][Dump ][JobMgr ] Worker #1 stopped
[2018-10-29 22:37:41.576580 +0100][Dump ][JobMgr ] Stopping worker #2...
[2018-10-29 22:37:41.576674 +0100][Dump ][JobMgr ] Worker #2 stopped
[2018-10-29 22:37:41.576691 +0100][Debug ][JobMgr ] Job manager stopped
[2018-10-29 22:37:41.576706 +0100][Debug ][TaskMgr ] Stopping the task manager...
[2018-10-29 22:37:41.576935 +0100][Debug ][TaskMgr ] Task manager stopped
[2018-10-29 22:37:41.576960 +0100][Debug ][Poller ] Stopping the poller...
[2018-10-29 22:37:41.577110 +0100][Debug ][TaskMgr ] Requesting unregistration of: "TickGeneratorTask for: esdss000.cern.ch:2001"
[2018-10-29 22:37:41.577143 +0100][Debug ][AsyncSock ] [esdss000.cern.ch:2001 #0.0] Closing the socket
[2018-10-29 22:37:41.577345 +0100][Debug ][Poller ] <[2001:1458:202:229:💯3f]:50856><--><[2001:1458:202:229:💯3f]:2001> Removing socket from the poller
[2018-10-29 22:37:41.577451 +0100][Debug ][PostMaster ] [esdss000.cern.ch:2001 #0] Destroying stream
[2018-10-29 22:37:41.577478 +0100][Debug ][AsyncSock ] [esdss000.cern.ch:2001 #0.0] Closing the socket
[2018-10-29 22:37:41.577509 +0100][Debug ][TaskMgr ] Requesting unregistration of: "TickGeneratorTask for: localhost:1094"
[2018-10-29 22:37:41.577526 +0100][Debug ][AsyncSock ] [localhost:1094 #0.0] Closing the socket
[2018-10-29 22:37:41.577541 +0100][Debug ][Poller ] <[::1]:50164><--><[::1]:1094> Removing socket from the poller
[2018-10-29 22:37:41.577600 +0100][Debug ][PostMaster ] [localhost:1094 #0] Destroying stream
[2018-10-29 22:37:41.577620 +0100][Debug ][AsyncSock ] [localhost:1094 #0.0] Closing the socket

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub, or mute the thread.

{"api_version":"1.0","publisher":{"api_key":"05dde50f1d1a384dd78767c55493e4bb","name":"GitHub"},"entity":{"external_key":"github/xrootd/xrootd","title":"xrootd/xrootd","subtitle":"GitHub repository","main_image_url":"https://assets-cdn.github.com/images/email/message_cards/header.png","avatar_image_url":"https://assets-cdn.github.com/images/email/message_cards/avatar.png","action":{"name":"Open in GitHub","url":"https://github.com/xrootd/xrootd"}},"updates":{"snippets":[{"icon":"DESCRIPTION","message":"[XrdCl] Enhanced logging for kXR_waitresp (#852)"}],"action":{"name":"View Issue","url":"https://github.com/xrootd/xrootd/issues/852"}}} [ { "@context": "http://schema.org", "@type": "EmailMessage", "potentialAction": { "@type": "ViewAction", "target": "https://github.com/xrootd/xrootd/issues/852", "url": "https://github.com/xrootd/xrootd/issues/852", "name": "View Issue" }, "description": "View this Issue on GitHub", "publisher": { "@type": "Organization", "name": "GitHub", "url": "https://github.com" } }, { "@type": "MessageCard", "@context": "http://schema.org/extensions", "hideOriginalBody": "false", "originator": "AF6C5A86-E920-430C-9C59-A73278B5EFEB", "title": "[XrdCl] Enhanced logging for kXR_waitresp (#852)", "sections": [ { "text": "", "activityTitle": "**simonmichal**", "activityImage": "https://assets-cdn.github.com/images/email/message_cards/avatar.png", "activitySubtitle": "@simonmichal", "facts": [ { "name": "Repository: ", "value": "xrootd/xrootd" }, { "name": "Issue #: ", "value": 852 } ] } ], "potentialAction": [ { "name": "Add a comment", "@type": "ActionCard", "inputs": [ { "isMultiLine": true, "@type": "TextInput", "id": "IssueComment", "isRequired": false } ], "actions": [ { "name": "Comment", "@type": "HttpPOST", "target": "https://api.github.com", "body": "{\n\"commandName\": \"IssueComment\",\n\"repositoryFullName\": \"xrootd/xrootd\",\n\"issueId\": 852,\n\"IssueComment\": \"{{IssueComment.value}}\"\n}" } ] }, { "name": "Close issue", "@type": "HttpPOST", "target": "https://api.github.com", "body": "{\n\"commandName\": \"IssueClose\",\n\"repositoryFullName\": \"xrootd/xrootd\",\n\"issueId\": 852\n}" }, { "targets": [ { "os": "default", "uri": "https://github.com/xrootd/xrootd/issues/852" } ], "@type": "OpenUri", "name": "View on GitHub" }, { "name": "Unsubscribe", "@type": "HttpPOST", "target": "https://api.github.com", "body": "{\n\"commandName\": \"MuteNotification\",\n\"threadId\": 405779521\n}" } ], "themeColor": "26292E" } ]

Use REPLY-ALL to reply to list

To unsubscribe from the XROOTD-DEV list, click the following link:
https://listserv.slac.stanford.edu/cgi-bin/wa?SUBED1=XROOTD-DEV&A=1