Report-staged gives two double events when file comes online

[hailihu]

This could be a dCache issue.

Output for ada --report-staged .... --debug:

NEARLINE  tape  /pnfs/grid.sara.nl/data/users/hailih/tape/testdir//testfile1

{"event":{"name":"testfile1","mask":["IN_ATTRIB"]},"subscription":"https://dcacheview.grid.surfsara.nl:22880/api/v1/events/channels/Du6LhaKQ3iZYvW-qinN6tw/subscriptions/inotify/AADB1PsWdCNHXaprNH_4vc5E"}
urlencoding '/pnfs/grid.sara.nl/data/users/hailih/tape/testdir//testfile1' to '%2Fpnfs%2Fgrid.sara.nl%2Fdata%2Fusers%2Fhailih%2Ftape%2Ftestdir%2F%2Ftestfile1'
++++ curl --config /Users/hu000001/.ada/headers/authorization_header_SjVayGTjCXc4 -H 'accept: application/json' --silent -X GET https://dcacheview.grid.surfsara.nl:22880/api/v1/namespace/%2Fpnfs%2Fgrid.sara.nl%2Fdata%2Fusers%2Fhailih%2Ftape%2Ftestdir%2F%2Ftestfile1
urlencoding '/pnfs/grid.sara.nl/data/users/hailih/tape/testdir//testfile1' to '%2Fpnfs%2Fgrid.sara.nl%2Fdata%2Fusers%2Fhailih%2Ftape%2Ftestdir%2F%2Ftestfile1'
+ curl --config /Users/hu000001/.ada/headers/authorization_header_SjVayGTjCXc4 -H 'accept: application/json' --fail --silent --show-error --ipv4 -X GET 'https://dcacheview.grid.surfsara.nl:22880/api/v1/namespace/%2Fpnfs%2Fgrid.sara.nl%2Fdata%2Fusers%2Fhailih%2Ftape%2Ftestdir%2F%2Ftestfile1?locality=true&qos=true'
+ jq -r '[ .fileLocality ,
                                   if .targetQos then (.currentQos + "→" + .targetQos) else .currentQos end ,
                                   "/pnfs/grid.sara.nl/data/users/hailih/tape/testdir//testfile1" ]
                                 | @tsv'
+ sed -e 's/\t/  /g'
ONLINE_AND_NEARLINE  tape  /pnfs/grid.sara.nl/data/users/hailih/tape/testdir//testfile1

{"event":{"name":"testfile1","mask":["IN_ATTRIB"]},"subscription":"https://dcacheview.grid.surfsara.nl:22880/api/v1/events/channels/Du6LhaKQ3iZYvW-qinN6tw/subscriptions/inotify/AADB1PsWdCNHXaprNH_4vc5E"}
urlencoding '/pnfs/grid.sara.nl/data/users/hailih/tape/testdir//testfile1' to '%2Fpnfs%2Fgrid.sara.nl%2Fdata%2Fusers%2Fhailih%2Ftape%2Ftestdir%2F%2Ftestfile1'
++++ curl --config /Users/hu000001/.ada/headers/authorization_header_SjVayGTjCXc4 -H 'accept: application/json' --silent -X GET https://dcacheview.grid.surfsara.nl:22880/api/v1/namespace/%2Fpnfs%2Fgrid.sara.nl%2Fdata%2Fusers%2Fhailih%2Ftape%2Ftestdir%2F%2Ftestfile1
urlencoding '/pnfs/grid.sara.nl/data/users/hailih/tape/testdir//testfile1' to '%2Fpnfs%2Fgrid.sara.nl%2Fdata%2Fusers%2Fhailih%2Ftape%2Ftestdir%2F%2Ftestfile1'
+ curl --config /Users/hu000001/.ada/headers/authorization_header_SjVayGTjCXc4 -H 'accept: application/json' --fail --silent --show-error --ipv4 -X GET 'https://dcacheview.grid.surfsara.nl:22880/api/v1/namespace/%2Fpnfs%2Fgrid.sara.nl%2Fdata%2Fusers%2Fhailih%2Ftape%2Ftestdir%2F%2Ftestfile1?locality=true&qos=true'
+ jq -r '[ .fileLocality ,
                                   if .targetQos then (.currentQos + "→" + .targetQos) else .currentQos end ,
                                   "/pnfs/grid.sara.nl/data/users/hailih/tape/testdir//testfile1" ]
                                 | @tsv'
+ sed -e 's/\t/  /g'
ONLINE_AND_NEARLINE  tape  /pnfs/grid.sara.nl/data/users/hailih/tape/testdir//testfile1

[hailihu]

After testing, it appears that not always two events are returned. Sometimes it is just one. Looking at line

SpiderScripts/ada/ada

Line 1741 in c899e42

if grep --silent -e IN_ATTRIB -e IN_MOVED_TO <<<"$mask" ; then

and adding before this line:

echo -e "$event_type  ${path}/${object_name}  ${mask}${cookie_string}"

the output is:

Listening for file status changes...
inotify  /pnfs/grid.sara.nl/data/users/hailih/tape/100filesx2GB/2GBfile94  IN_ATTRIB
ONLINE_AND_NEARLINE  tape  /pnfs/grid.sara.nl/data/users/hailih/tape/100filesx2GB/2GBfile94
inotify  /pnfs/grid.sara.nl/data/users/hailih/tape/100filesx2GB/2GBfile97  IN_ATTRIB
ONLINE_AND_NEARLINE  tape  /pnfs/grid.sara.nl/data/users/hailih/tape/100filesx2GB/2GBfile97
inotify  /pnfs/grid.sara.nl/data/users/hailih/tape/100filesx2GB/2GBfile97  IN_ATTRIB
ONLINE_AND_NEARLINE  tape  /pnfs/grid.sara.nl/data/users/hailih/tape/100filesx2GB/2GBfile97
inotify  /pnfs/grid.sara.nl/data/users/hailih/tape/100filesx2GB/2GBfile91  IN_ATTRIB
ONLINE_AND_NEARLINE  tape  /pnfs/grid.sara.nl/data/users/hailih/tape/100filesx2GB/2GBfile91
inotify  /pnfs/grid.sara.nl/data/users/hailih/tape/100filesx2GB/2GBfile91  IN_ATTRIB
ONLINE_AND_NEARLINE  tape  /pnfs/grid.sara.nl/data/users/hailih/tape/100filesx2GB/2GBfile91

I suspect that if events take long to process, then dCache returns the event message multiple times, since for example when listening to write events during file transfer IN_MODIFY is returned many times. @onnozweers should ada be adapted to deal with this?

[onnozweers]

When writing a large file and listening with --events, there are indeed multiple IN_MODIFY events, as listed below:

[onno@mylaptop ~/git/SpiderScripts] % ada/ada --api https://dcacheview.grid.surfsara.nl:22880/api/v1 --events myeventstest /pnfs/grid.sara.nl/data/users/onno/tape/test-events
...
inotify  /pnfs/grid.sara.nl/data/users/onno/tape/test-events/testfile1  IN_CREATE
inotify  /pnfs/grid.sara.nl/data/users/onno/tape/test-events/testfile1  IN_OPEN
inotify  /pnfs/grid.sara.nl/data/users/onno/tape/test-events/testfile1  IN_MODIFY
inotify  /pnfs/grid.sara.nl/data/users/onno/tape/test-events/testfile1  IN_MODIFY
inotify  /pnfs/grid.sara.nl/data/users/onno/tape/test-events/testfile1  IN_MODIFY
inotify  /pnfs/grid.sara.nl/data/users/onno/tape/test-events/testfile1  IN_ATTRIB
inotify  /pnfs/grid.sara.nl/data/users/onno/tape/test-events/testfile1  IN_CLOSE_WRITE
inotify  /pnfs/grid.sara.nl/data/users/onno/tape/test-events/testfile1  IN_ATTRIB

It is however the IN_CLOSE_WRITE event that really matters in this case. A file can be modified in dCache as long it is still open. When the file is closed, it is final, and then it can be processed. In this case, the IN_MODIFY events can be ignored.

With --report-staged, this is shown when a file is purged from a stage pool:

[onno@mylaptop ~/git/SpiderScripts] % ada/ada --api https://dcacheview.grid.surfsara.nl:22880/api/v1 --report-staged myeventstest /pnfs/grid.sara.nl/data/users/onno/tape/test-events --resume
...
NEARLINE  tape  /pnfs/grid.sara.nl/data/users/onno/tape/test-events/testfile1

And this when the file is staged:

ONLINE_AND_NEARLINE  tape  /pnfs/grid.sara.nl/data/users/onno/tape/test-events/testfile1
ONLINE_AND_NEARLINE  tape  /pnfs/grid.sara.nl/data/users/onno/tape/test-events/testfile1

Indeed a double entry. I checked again with --debug, and saw this twice:

{"event":{"name":"testfile1","mask":["IN_ATTRIB"]},"subscription":"https://dcacheview.grid.surfsara.nl:22880/api/v1/events/channels/Vkbu3MZJtNKclUq6SA9uVA/subscriptions/inotify/AAB-7IJV18BOL7h2uEbPn1Va"}

I guess that dCache internally changed file attributes twice, not sure why that is. For each event, Ada looks up the current locality (ONLINE_AND_NEARLINE).

Not sure how to handle this gracefully. The events don't contain any details. Piping the Ada output through uniq seems clumsy and may cause delays (because a line will only be printed if the next line is different).

Perhaps we can request the dCache developers to make an extra event for files coming online.

[onnozweers]

I tested uniq on both Alma 9 and MacOS. It prints out a new line immediately, and doesn't wait to see if the next line is identical. So if we use it, there would be no delay. So that might be a viable solution.

When using uniq, if a single file would come online, get offline and come online again before any other file comes online, then a event listener might get only one event where it should get two. But the changes of that happening are probably negligible.

[hailihu]

The use case of listening to events when a file come online, is for example to start processing the file. In this case, it is troublesome if the event is reported twice as it could result in multiple jobs. I think we should indeed apply uniq. In the unlikely case a file goes offline and comes online again, wouldn't there be a 'NEARLLINE' event in between?

[onnozweers]

Indeed in such a case there would be a NEARLINE event.