[LU-8247] sanity-hsm test_72: Copytool failed to send restore start event to FIFO

• Type: Bug
• Resolution: Unresolved
• Priority: Minor
• Severity: 3
• Assignee: WC Triage
• Reporter: Maloo

Description

This issue was created by maloo for parinay <[e-mail]>

This issue relates to the following test suite run: https://testing.hpdd.intel.com/test_sets/87f7f2c4-2a0c-11e6-80b9-5254006e85c2.

The sub-test test_72 failed with the following error:

Copytool failed to send restore start event to FIFO

Please provide additional information about the failure here.

CMD: trevis-4vm6 lhsmtool_posix  --daemon --hsm-root /tmp/arc1/shsm --update-interval 5 --event-fifo /tmp/sanity-hsm.test_72.3AyM/fifo --bandwidth 1 /mnt/lustre2 < /dev/null > /logdir/test_logs/2016-06-03/lustre-reviews-el7-x86_64--review-zfs-part-1--1_8_1__39425__-70227050226240-224530/sanity-hsm.test_72.copytool_log.trevis-4vm6.log 2>&1
CMD: trevis-4vm6 dd if=/dev/urandom of=/tmp/sanity-hsm.test_72.3AyM/file count=16 bs=1000000 conv=fsync
trevis-4vm6: 16+0 records in
trevis-4vm6: 16+0 records out
trevis-4vm6: 16000000 bytes (16 MB) copied, 1.2602 s, 12.7 MB/s
CMD: trevis-4vm6 mkdir -p /tmp/arc1/shsm/d72.sanity-hsm
CMD: trevis-4vm6 cp -p /tmp/sanity-hsm.test_72.3AyM/file /tmp/arc1/shsm/d72.sanity-hsm/f72.sanity-hsm
CMD: trevis-4vm6 lhsmtool_posix --archive 2 --hsm-root /tmp/arc1/shsm		--import d72.sanity-hsm/f72.sanity-hsm /mnt/lustre/d72.sanity-hsm/f72.sanity-hsm /mnt/lustre
trevis-4vm6: 1465012875.021822 lhsmtool_posix[24497]: action=1 src=d72.sanity-hsm/f72.sanity-hsm dst=/mnt/lustre/d72.sanity-hsm/f72.sanity-hsm mount_point=/mnt/lustre
trevis-4vm6: 1465012875.024252 lhsmtool_posix[24497]: importing '/mnt/lustre/d72.sanity-hsm/f72.sanity-hsm' from '/tmp/arc1/shsm/d72.sanity-hsm/f72.sanity-hsm'
trevis-4vm6: 1465012875.041548 lhsmtool_posix[24497]: imported '/mnt/lustre/d72.sanity-hsm/f72.sanity-hsm' from '/tmp/arc1/shsm/019c/0000/0404/0000/0002/0000/0x200000404:0x19c:0x0'=='/tmp/arc1/shsm/d72.sanity-hsm/f72.sanity-hsm'
trevis-4vm6: 1465012875.041591 lhsmtool_posix[24497]: process finished, errs: 0 major, 0 minor, rc=0 (Success)
Verifying released state: 
CMD: trevis-4vm12 /usr/sbin/lctl get_param -n mdt.lustre-MDT0000.hsm.actions | awk '/'0x200000404:0x19c:0x0'.*action='RESTORE'/ {print \$13}' | cut -f2 -d=
CMD: trevis-4vm12 /usr/sbin/lctl get_param -n mdt.lustre-MDT0000.hsm.actions | awk '/'0x200000404:0x19c:0x0'.*action='RESTORE'/ {print \$13}' | cut -f2 -d=
Waiting 200 secs for update
CMD: trevis-4vm12 /usr/sbin/lctl get_param -n mdt.lustre-MDT0000.hsm.actions | awk '/'0x200000404:0x19c:0x0'.*action='RESTORE'/ {print \$13}' | cut -f2 -d=
CMD: trevis-4vm12 /usr/sbin/lctl get_param -n mdt.lustre-MDT0000.hsm.actions | awk '/'0x200000404:0x19c:0x0'.*action='RESTORE'/ {print \$13}' | cut -f2 -d=
CMD: trevis-4vm12 /usr/sbin/lctl get_param -n mdt.lustre-MDT0000.hsm.actions | awk '/'0x200000404:0x19c:0x0'.*action='RESTORE'/ {print \$13}' | cut -f2 -d=
CMD: trevis-4vm12 /usr/sbin/lctl get_param -n mdt.lustre-MDT0000.hsm.actions | awk '/'0x200000404:0x19c:0x0'.*action='RESTORE'/ {print \$13}' | cut -f2 -d=
CMD: trevis-4vm12 /usr/sbin/lctl get_param -n mdt.lustre-MDT0000.hsm.actions | awk '/'0x200000404:0x19c:0x0'.*action='RESTORE'/ {print \$13}' | cut -f2 -d=
CMD: trevis-4vm12 /usr/sbin/lctl get_param -n mdt.lustre-MDT0000.hsm.actions | awk '/'0x200000404:0x19c:0x0'.*action='RESTORE'/ {print \$13}' | cut -f2 -d=
CMD: trevis-4vm12 /usr/sbin/lctl get_param -n mdt.lustre-MDT0000.hsm.actions | awk '/'0x200000404:0x19c:0x0'.*action='RESTORE'/ {print \$13}' | cut -f2 -d=
CMD: trevis-4vm12 /usr/sbin/lctl get_param -n mdt.lustre-MDT0000.hsm.actions | awk '/'0x200000404:0x19c:0x0'.*action='RESTORE'/ {print \$13}' | cut -f2 -d=
CMD: trevis-4vm12 /usr/sbin/lctl get_param -n mdt.lustre-MDT0000.hsm.actions | awk '/'0x200000404:0x19c:0x0'.*action='RESTORE'/ {print \$13}' | cut -f2 -d=
CMD: trevis-4vm12 /usr/sbin/lctl get_param -n mdt.lustre-MDT0000.hsm.actions | awk '/'0x200000404:0x19c:0x0'.*action='RESTORE'/ {print \$13}' | cut -f2 -d=
Waiting 190 secs for update
CMD: trevis-4vm12 /usr/sbin/lctl get_param -n mdt.lustre-MDT0000.hsm.actions | awk '/'0x200000404:0x19c:0x0'.*action='RESTORE'/ {print \$13}' | cut -f2 -d=
CMD: trevis-4vm12 /usr/sbin/lctl get_param -n mdt.lustre-MDT0000.hsm.actions | awk '/'0x200000404:0x19c:0x0'.*action='RESTORE'/ {print \$13}' | cut -f2 -d=
Updated after 12s: wanted 'SUCCEED' got 'SUCCEED'
CMD: trevis-4vm6 cat /tmp/sanity-hsm.test_72.3AyM/events
 sanity-hsm test_72: @@@@@@ FAIL: Copytool failed to send restore start event to FIFO 
  Trace dump:
  = /usr/lib64/lustre/tests/test-framework.sh:4790:error()
  = /usr/lib64/lustre/tests/sanity-hsm.sh:3404:test_72()
  = /usr/lib64/lustre/tests/test-framework.sh:5055:run_one()
  = /usr/lib64/lustre/tests/test-framework.sh:5094:run_one_logged()
  = /usr/lib64/lustre/tests/test-framework.sh:4940:run_test()
  = /usr/lib64/lustre/tests/sanity-hsm.sh:3419:main()
Dumping lctl log to /logdir/test_logs/2016-06-03/lustre-reviews-el7-x86_64--review-zfs-part-1--1_8_1__39425__-70227050226240-224530/sanity-hsm.test_72.*.1465012892.log
CMD: trevis-4vm12,trevis-4vm5.trevis.hpdd.intel.com,trevis-4vm6,trevis-4vm7 /usr/sbin/lctl dk > /logdir/test_logs/2016-06-03/lustre-reviews-el7-x86_64--review-zfs-part-1--1_8_1__39425__-70227050226240-224530/sanity-hsm.test_72.debug_log.\$(hostname -s).1465012892.log;
         dmesg > /logdir/test_logs/2016-06-03/lustre-reviews-el7-x86_64--review-zfs-part-1--1_8_1__39425__-70227050226240-224530/sanity-hsm.test_72.dmesg.\$(hostname -s).1465012892.log
CMD: trevis-4vm12,trevis-4vm7 /usr/sbin/lctl set_param debug=\"\"
trevis-4vm12: error: set_param: setting debug: no value
trevis-4vm7: error: set_param: setting debug: no value
Resetting fail_loc on all nodes...CMD: trevis-4vm12,trevis-4vm5.trevis.hpdd.intel.com,trevis-4vm6,trevis-4vm7 lctl set_param -n fail_loc=0 	    fail_val=0 2>/dev/null
done.
CMD: trevis-4vm6 kill \$(cat /tmp/sanity-hsm.test_72.3AyM/monitor_pid) 2>/dev/null || true
CMD: trevis-4vm6 rm -fr /tmp/sanity-hsm.test_72.3AyM

Info required for matching: sanity-hsm 72