error logs when "dog vdi delete" deletes VDI

[Yuichi Bando]

Sheep outputs error logs such "No Object Found" and "remove object <OID> fail" when "dog vdi delete" deletes VDI.
I found this bug in the long-term stability test which repeats snapshot and rollback.

[Possible cause]
When I delete 2 snapshots and original VDI,
sheep attempts to delete a deleted data object.
But the data object has already been deleted in the first "dog vdi delete".

[How to reproduce]
I give 3 scripts for reproduction.
Please execute "108_failed-to-remove-object-log-output.sh"
I confirmed this scripts both in stable-0.7 master and mainline.

################ 108_failed-to-remove-object-log-output.sh ##################
#!/bin/bash

SHDIR=`cd $(dirname $0); pwd`
. ${SHDIR}/common_functions.sh
. ${SHDIR}/assert_functions.sh

echo "### sheep & tgtd restart."
_env_format

_start_sheep 1

tgtd -d 1

echo "### wait startup sheep,tgtd"
_wait_sheep_running_with_format || exit 1
_wait_tgtd_running || exit 1

echo "##### (1) create vdi and target(lu, acl)."
dog vdi create testvdi 1G
sleep 2
tgtadm -m target -o new --tid 1 --targetname iqn.2014-03.powder.osrg.net:testvdi
tgtadm -m logicalunit -o new --tid 1 --lun 1 --backing-store unix:/tmp/sheepdog0/sock:testvdi --bstype sheepdog
sleep 1
tgtadm -m target -o bind --tid 1 --initiator-address ALL
tgtadm -m target -o show
sleep 3

echo "##### (2) initiator login"
iscsiadm -m discovery -t sendtargets -p 127.0.0.1
sleep 2
iscsiadm -m node -T iqn.2014-03.powder.osrg.net:testvdi --login
_wait_exist_symboliclink /dev/disk/by-path/ip-127.0.0.1:3260-iscsi-iqn.2014-03.powder.osrg.net:testvdi-lun-1

echo "##### (3) disk format"
fdisk /dev/disk/by-path/ip-127.0.0.1:3260-iscsi-iqn.2014-03.powder.osrg.net:testvdi-lun-1 << EOF
n
p
1

w
EOF
sleep 2
ls -l /dev/disk/by-path/ip-*

mkfs.ext4 /dev/disk/by-path/ip-127.0.0.1:3260-iscsi-iqn.2014-03.powder.osrg.net:testvdi-lun-1-part1
sleep 3

echo "##### (4) iSCSI disk mount"

mkdir -p /mnt/test

mount /dev/disk/by-path/ip-127.0.0.1:3260-iscsi-iqn.2014-03.powder.osrg.net:testvdi-lun-1-part1 /mnt/test
sleep 3

echo "##### (5) create file1 to mount disk"

touch /mnt/test/file1
sync

echo "##### (6) create snapshot"

dog vdi snapshot testvdi

echo "##### (7) create file2 to mount disk"

touch /mnt/test/file2
sync

echo "##### (8) create snapshot"

dog vdi snapshot testvdi

echo "##### (9) create file3 to mount disk"

touch /mnt/test/file3
sync

ls -la /mnt/test

echo "##### (10) iSCSI disk umount"

umount /mnt/test

echo "##### (11) initiator logout"

iscsiadm -m node -T iqn.2014-03.powder.osrg.net:testvdi --logout
sleep 3

echo "##### (12) target delete"

tgtadm --lld iscsi --op unbind --mode target --tid 1 -I ALL
tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1
tgtadm --lld iscsi --op delete --mode target --tid 1

echo "##### (13) vdi rollback"

dog vdi rollback -f -s 1 testvdi

echo "##### (14) target recreate"

tgtadm -m target -o new --tid 1 --targetname iqn.2014-03.powder.osrg.net:testvdi
tgtadm -m logicalunit -o new --tid 1 --lun 1 --backing-store unix:/tmp/sheepdog0/sock:testvdi --bstype sheepdog
tgtadm -m target -o bind --tid 1 -I ALL
tgtadm -m target -o show

echo "##### (15) initiator login"
iscsiadm -m node -T iqn.2014-03.powder.osrg.net:testvdi --login
sleep 3

echo "##### (16) iSCSI disk mount"

mount /dev/disk/by-path/ip-127.0.0.1:3260-iscsi-iqn.2014-03.powder.osrg.net:testvdi-lun-1-part1 /mnt/test
sleep 2

echo "##### (17) check file exist"

ls -la /mnt/test

echo "##### (18) initiator logout"

iscsiadm -m node -T iqn.2014-03.powder.osrg.net:testvdi --logout
sleep 3

echo "##### (19) target delete"

tgtadm --lld iscsi --op unbind --mode target --tid 1 -I ALL
tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1
tgtadm --lld iscsi --op delete --mode target --tid 1

echo "##### (20) vdi(id:0) delete"

VDIID=`dog vdi list -r | grep "testvdi 0" | cut -d' ' -f8`
dog vdi delete testvdi
sleep 2

echo "##### (21) vdi(id:1) delete"

dog vdi delete -s 1 testvdi
sleep 2

echo "##### (22) vdi(id:2) delete"

dog vdi delete -s 2 testvdi
sleep 2

echo "##### (23) assert ERROR message"
MSG=`grep ERROR /tmp/sheepdog0/sheep.log`
_assert_null "${MSG}" "error message output"
if [ $? -ne 0 ]; then
  echo "-------------------"
  echo "$MSG"
  echo "-------------------"
  exit 1
fi

exit 0

################ common_functions.sh ##################
#!/bin/bash

## COMMANDS
DOG='/usr/sbin/dog'
SHEEP='/usr/sbin/sheep'
TGTD='/sbin/tgtd'

## COMMON LIBRARY PARAM
TIMEOUT=60 # sec

## COMMON LIBRARY
function _env_format() {
  umount /mnt/* >/dev/null 2>&1
  iscsiadm -m node --logout >/dev/null 2>&1
  pkill -9 sheep
  pkill -9 tgtd
  pkill -9 iscsid
  rm -rf /tmp/sheepdog*
  rm -rf /var/lib/iscsi
  service corosync restart
}

function _start_sheep() {
  ## param[1]: exec sheep proc num
  test $# != 1 && echo "specific param[1]:exec sheep proc num" && return 1
  for i in `seq 0 $(expr $1 - 1)`; do
    mkdir -p /tmp/sheepdog${i}
    if [ `${SHEEP} -v | cut -d' ' -f4 | grep 0.7 | wc -l` == 1 ]; then
      ${SHEEP} -z ${i} -p 700${i} -l 7 /tmp/sheepdog${i}
    else
      ${SHEEP} -z ${i} -p 700${i} -l level=debug /tmp/sheepdog${i}
    fi
  done
  return 0
}

function _wait_sheep_running() {
  for i in `seq 1 ${TIMEOUT}`; do
    test `${DOG} cluster info | grep "Cluster status" | cut -d, -f1 | cut -d: -f2 | sed "s/ //g"`x == "running"x && return 0
    sleep 1
  done
  echo "[ERROR] sheep start timeout (${TIMEOUT}s)."
  return 1
}

function _wait_sheep_running_with_format() {
  for i in `seq 1 ${TIMEOUT}`; do
    yes yes | ${DOG} cluster format 2>/dev/null
    test `${DOG} cluster info | grep "Cluster status" | cut -d, -f1 | cut -d: -f2 | sed "s/ //g"`x == "running"x && return 0
    sleep 1
  done
  echo "[ERROR] sheep start timeout (${TIMEOUT}s)."
  return 1
}

function _wait_tgtd_running() {
  for i in `seq 1 ${TIMEOUT}`; do
    test `tgtadm -m system -o show | grep State | cut -d: -f2 | sed "s/ //g"`x == "ready"x && return 0
    sleep 1
  done
  echo "[ERROR] tgtd start timeout (${TIMEOUT}s)."
  return 1
}

function _wait_exist_symboliclink() {
  ## param[1]: check syncboliclink path
  test $# != 1 && echo "specific param[1]:check syncboliclink path" && return 1
  for i in `seq 1 ${TIMEOUT}`; do
    test -h $1 && return 0
    sleep 1
  done
  echo "[ERROR] symboliclink exist check timeout (${TIMEOUT}s)."
  return 1

}

################ assert_functions.sh ##################
#!/bin/bash

##
## ASSERT FUNCTIONS
##

#-----------------------------------
# func : _assert_equal
# desc : Asserts that two objects are equal.
# param: $1: inspection
# $2: expect
# $3: output error message
#-----------------------------------
function _assert_equal() {
  if [ "$1"x == "$2"x ]; then
    return 0
  else
    echo "[ERROR] $3, \"$1\" expect equals \"$2\"."
    return 1
  fi
}

#-----------------------------------
# func : _assert_not_equal
# desc : Asserts that two objects does not equal.
# param: $1: inspection
# $2: expect
# $3: output error message
#-----------------------------------
function _assert_not_equal() {
  if [ "$1"x != "$2"x ]; then
    return 0
  else
    echo "[ERROR] $3, \"$1\" expect not equals \"$2\"."
    return 1
  fi
}

#-----------------------------------
# func : _assert_null
# desc : Asserts that an object is null.
# param: $1: inspection
# $2: output error message
#-----------------------------------
function _assert_null() {
  ret=`printf "$1" | wc -c`
  if [ $ret == 0 ]; then
    return 0
  else
    echo "[ERROR] $2, \"$1\" expect equals null."
    return 1
  fi
}

#-----------------------------------
# func : _assert_not_null
# desc : Asserts that an object isn't null.
# param: $1: inspection
# $2: output error message
#-----------------------------------
function _assert_not_null() {
  ret=`printf "$1" | wc -c`
  if [ $ret != 0 ]; then
    return 0
  else
    echo "[ERROR] $2, expect equals not null."
    return 1
  fi
}

#-----------------------------------
# func : _assert_zero
# desc : Asserts that an object is zero(0).
# param: $1: inspection
# $2: output error message
#-----------------------------------
function _assert_zero() {
  if [ "$1"x == "0"x ]; then
    return 0
  else
    echo "[ERROR] $2, \"$1\" expect equals zero."
    return 1
  fi
}

#-----------------------------------
# func : _assert_not_zero
# desc : Asserts that an object isn't zero(0).
# param: $1: inspection
# $2: output error message
#-----------------------------------
function _assert_not_zero() {
  if [ "$1"x != "0"x ]; then
    return 0
  else
    echo "[ERROR] $2, \"$1\" expect not equals zero."
    return 1
  fi
}

#-----------------------------------
# func : _assert_contain
# desc : Asserts that a keyword contain at object.
# param: $1: inspection
# $2: keyword to expect
# $3: output error message
# ($4): if specify "1", don't print a inspection to message.
#-----------------------------------
function _assert_contain() {
  ret=`echo "$1" | grep "$2" | wc -l`
  if [ $ret -ge 1 ]; then
    return 0
  else
    test "$4"x == "1"x && echo "[ERROR] $3, expect contain \"$2\"."
    test "$4"x != "1"x && echo "[ERROR] $3, \"$1\" expect contain \"$2\"."
    return 1
  fi
}

#-----------------------------------
# func : _assert_not_contain
# desc : Asserts that a keyword does not contain at object.
# param: $1: inspection
# $2: keyword not to expect
# $3: output error message
# ($4): if specify "1", don't print a inspection to message.
#-----------------------------------
function _assert_not_contain() {
  ret=`echo "$1" | grep "$2" | wc -l`
  if [ $ret -eq 0 ]; then
    return 0
  else
    test "$4"x == "1"x && echo "[ERROR] $3, expect not contain \"$2\"."
    test "$4"x != "1"x && echo "[ERROR] $3, \"$1\" expect not contain \"$2\"."
    return 1
  fi
}

#-----------------------------------
# func : _assert_file_exist
# desc : Asserts that a file exist.
# param: $1: inspection filepath
# $2: output error message
#-----------------------------------
function _assert_file_exist() {
  if [ -f "$1" ]; then
    return 0
  else
    echo "[ERROR] $2, \"$1\" expect file exist."
    return 1
  fi
}

#-----------------------------------
# func : _assert_file_not_exist
# desc : Asserts that a file does not exist.
# param: $1: inspection filepath
# $2: output error message
#-----------------------------------
function _assert_file_not_exist() {
  if [ ! -f "$1" ]; then
    return 0
  else
    echo "[ERROR] $2, \"$1\" expact file not exist."
    return 1
  fi
}

Thanks
Yuichi Bando