[#LU-4093] sanity-hsm test_24d: wanted 'SUCCEED' got 'WAITING'

_ in fact cdt_purge only clear actions but not requests ... Thus need to cdt_[shutdown+enable] (or better cdt_restart!) to clear orphan requests immediately.

_ orphan requests can also clear after timeout, this is confirmed by the timings found in the test suite run that caused this ticket to be created, and where I found that some point of time (around 1 hour/3600s later than test_24c ran and test_24d 1st triggered the WAITING hsm_archive requests state) during test_30 hsm_archive requests restarted to be handled ... :

.......
 [/usr/bin/lfs] [hsm_archive] [/mnt/lustre/d0.sanity-hsm/d24/f.sanity-hsm.24c]
2+0 records in
2+0 records out
2097152 bytes (2.1 MB) copied, 2.39885 s, 874 kB/s
0x200008101:0x1e:0x0
CMD: wtm-21vm3 /usr/sbin/lctl set_param -n mdt.lustre-MDT0000.hsm.other_request_mask
running as uid/gid/euid/egid 500/500/500/500, groups:
 [/usr/bin/lfs] [hsm_archive] [/mnt/lustre/d0.sanity-hsm/d24/f.sanity-hsm.24c]
Cannot send HSM request (use of /mnt/lustre/d0.sanity-hsm/d24/f.sanity-hsm.24c): Operation not permitted
CMD: wtm-21vm3 /usr/sbin/lctl set_param -n mdt.lustre-MDT0000.hsm.other_request_mask=archive
running as uid/gid/euid/egid 500/500/500/500, groups:
 [/usr/bin/lfs] [hsm_archive] [/mnt/lustre/d0.sanity-hsm/d24/f.sanity-hsm.24c]  <<<<<< last archive request in test_24c

CMD: wtm-21vm5 pkill -INT -x lhsmtool_posix  <<<<<< immediate copytool_cleanup
Copytool is stopped on wtm-21vm5
CMD: wtm-21vm3 /usr/sbin/lctl set_param -n mdt.lustre-MDT0000.hsm.user_request_mask=RESTORE
CMD: wtm-21vm3 /usr/sbin/lctl set_param -n mdt.lustre-MDT0000.hsm.group_request_mask=RESTORE
CMD: wtm-21vm3 /usr/sbin/lctl set_param -n mdt.lustre-MDT0000.hsm.other_request_mask=RESTORE
Resetting fail_loc on all nodes...CMD: wtm-21vm3,wtm-21vm4,wtm-21vm5,wtm-21vm6.rosso.whamcloud.com lctl set_param -n fail_loc=0 2>/dev/null || true
done.
CMD: wtm-21vm3,wtm-21vm4,wtm-21vm5 rc=\$([ -f /proc/sys/lnet/catastrophe ] &&
		echo \$(< /proc/sys/lnet/catastrophe) || echo 0);
		if [ \$rc -ne 0 ]; then echo \$(hostname): \$rc; fi
		exit \$rc
PASS 24c (11s)

== sanity-hsm test 24d: check that read-only mounts are respected == 23:38:25 (1381473505)
CMD: wtm-21vm5 pkill -CONT -x lhsmtool_posix
Wakeup copytool agt1 on wtm-21vm5
2+0 records in
2+0 records out
2097152 bytes (2.1 MB) copied, 1.79625 s, 1.2 MB/s
Cannot send HSM request (use of /mnt/lustre2/d0.sanity-hsm/d24/f.sanity-hsm.24d): Read-only file system
CMD: wtm-21vm3 /usr/sbin/lctl get_param -n mdt.lustre-MDT0000.hsm.agent_actions | awk '/'0x200008101:0x1f:0x0'.*action='ARCHIVE'/ {print \$13}' | cut -f2 -d=
Changed after 0s: from '' to 'WAITING'  <<<<< 1st valid archive request in test_24d is WAITING direct!!!
Waiting 100 secs for update
CMD: wtm-21vm3 /usr/sbin/lctl get_param -n mdt.lustre-MDT0000.hsm.agent_actions | awk '/'0x200008101:0x1f:0x0'.*action='ARCHIVE'/ {print \$13}' | cut -f2 -d=

.......

Update not seen after 100s: wanted 'SUCCEED' got 'WAITING'
 sanity-hsm test_24d: @@@@@@ FAIL: request on 0x200008101:0x1f:0x0 is not SUCCEED  <<<<< test_24d fails at 1st archive

.......

Same for test_26/27b/28 (only following tests with archives...) at their 1st archive request !!!

.......

== sanity-hsm test 30b: Restore at exec (release case) == 00:38:49 (1381477129)
CMD: wtm-21vm5 pkill -CONT -x lhsmtool_posix
Purging archive on wtm-21vm5
CMD: wtm-21vm5 rm -rf /home/cgearing/.autotest/shared_dir/2013-10-10/082939-69981897718180/arc1/*
Starting copytool agt1 on wtm-21vm5
CMD: wtm-21vm5 mkdir -p /home/cgearing/.autotest/shared_dir/2013-10-10/082939-69981897718180/arc1
CMD: wtm-21vm5 lhsmtool_posix  --daemon --hsm-root /home/cgearing/.autotest/shared_dir/2013-10-10/082939-69981897718180/arc1 --bandwidth 1 /mnt/lustre < /dev/null > /logdir/test_logs/2013-10-10/lustre-reviews-el6-x86_64--review-zfs--1_3_1__18725__-69981897718180-082939/sanity-hsm.test_30b.copytool_log.wtm-21vm5.log 2>&1
CMD: wtm-21vm3 /usr/sbin/lctl get_param -n mdt.lustre-MDT0000.hsm.agent_actions | awk '/'0x200008101:0x24:0x0'.*action='ARCHIVE'/ {print \$13}' | cut -f2 -d=
Changed after 0s: from '' to 'WAITING'
Waiting 100 secs for update

.......

CMD: wtm-21vm3 /usr/sbin/lctl get_param -n mdt.lustre-MDT0000.hsm.agent_actions | awk '/'0x200008101:0x24:0x0'.*action='ARCHIVE'/ {print \$13}' | cut -f2 -d=
CMD: wtm-21vm3 /usr/sbin/lctl get_param -n mdt.lustre-MDT0000.hsm.agent_actions | awk '/'0x200008101:0x24:0x0'.*action='ARCHIVE'/ {print \$13}' | cut -f2 -d=
Changed after 96s: from 'WAITING' to 'STARTED'  <<<<<< archives only restarted during test_30b about 1h/3600s (default timeout!)
CMD: wtm-21vm3 /usr/sbin/lctl get_param -n mdt.lustre-MDT0000.hsm.agent_actions | awk '/'0x200008101:0x24:0x0'.*action='ARCHIVE'/ {print \$13}' | cut -f2 -d=
Updated after 97s: wanted 'SUCCEED' got 'SUCCEED'

........

_ what is the best way to fix this ? As I already thought and commented "add a systematic cdt_shutdown/cdt_enable (or cdt_restart) in copytool_cleanup()" or only ensure to allow copytool to get enough time to handle requests before cleanup (like in test_24c) ?

_ also I need to check, if it is it allowed to kill/end copytool when there are requests being processed and thus if it is expected for these requests to stay orphan until they reach their timeout or CDT restarts ? BTW, running tests in this configuration causes CDT to complain with these (normal/expected?) msgs :

LustreError: 22856:0:(mdt_coordinator.c:338:mdt_coordinator_cb()) lustrez-MDT0000: Cannot cleanup timeouted request: [0x200000401:0x2590:0x0] for cookie 0x52678bbd action=ARCHIVE
LustreError: 22856:0:(mdt_coordinator.c:338:mdt_coordinator_cb()) Skipped 1 previous similar message
LustreError: 22856:0:(mdt_coordinator.c:1448:mdt_hsm_update_request_state()) lustrez-MDT0000: Cannot find running request for cookie 0x52678e26 on fid=[0x200000401:0x25a2:0x0]
LustreError: 22856:0:(mdt_coordinator.c:1448:mdt_hsm_update_request_state()) Skipped 1 previous similar message
LustreError: 22856:0:(mdt_coordinator.c:338:mdt_coordinator_cb()) lustrez-MDT0000: Cannot cleanup timeouted request: [0x200000401:0x25a2:0x0] for cookie 0x52678e26 action=ARCHIVE
LustreError: 22856:0:(mdt_coordinator.c:338:mdt_coordinator_cb()) Skipped 1 previous similar message
LustreError: 22856:0:(mdt_coordinator.c:1448:mdt_hsm_update_request_state()) lustrez-MDT0000: Cannot find running request for cookie 0x5267908a on fid=[0x200000401:0x25b4:0x0]
LustreError: 22856:0:(mdt_coordinator.c:1448:mdt_hsm_update_request_state()) Skipped 1 previous similar message
LustreError: 22856:0:(mdt_coordinator.c:338:mdt_coordinator_cb()) lustrez-MDT0000: Cannot cleanup timeouted request: [0x200000401:0x25b4:0x0] for cookie 0x5267908a action=ARCHIVE
LustreError: 22856:0:(mdt_coordinator.c:338:mdt_coordinator_cb()) Skipped 1 previous similar message

[LU-4093] sanity-hsm test_24d: wanted 'SUCCEED' got 'WAITING' Created: 11/Oct/13 Updated: 15/Sep/14 Resolved: 10/Dec/13
Status:	Resolved
Project:	Lustre
Component/s:	None
Affects Version/s:	Lustre 2.5.0
Fix Version/s:	Lustre 2.6.0, Lustre 2.5.1

[LU-4093] sanity-hsm test_24d: wanted 'SUCCEED' got 'WAITING' Created: 11/Oct/13 Updated: 15/Sep/14 Resolved: 10/Dec/13