Re: init scripts problems ?

denis bonnenfant <[email protected]> Wed, 07 Dec 2005 15:23:33 +0100
Newsgroups gmane.linux.enbd.general
Message-ID <[email protected]>
just some other (useful?) infos :

i just started 2 enbd links just by rebooting the client, so it starts automatically via cstatd, and the result was quite strange (there is no md 
involved here) :

first everything semmed ok. But, after 30 seconds, there was errors, and client is blocked again :

ps axf opid,wchan:20,state,cmd  :

  3004 -                    D [enbd-client]
  3005 -                    D [enbd-client]
  3009 -                    S enbd-client se3-croise 12360 -i B-2 -e -n 2 -m -b 512 /dev/ndb
  3013 sync_page            D  \_ enbd-client se3-croise 12360 -i B-2 -e -n 2 -m -b 512 /dev/ndb
  3014 -                    D  \_ enbd-client se3-croise 12360 -i B-2 -e -n 2 -m -b 512 /dev/ndb
  3010 -                    S enbd-client se3-croise 12355 -i A-2 -e -n 2 -m -b 512 /dev/nda
  3011 sync_page            D  \_ enbd-client se3-croise 12355 -i A-2 -e -n 2 -m -b 512 /dev/nda
  3012 -                    D  \_ enbd-client se3-croise 12355 -i A-2 -e -n 2 -m -b 512 /dev/nda


dmesg :

warning: process `enbd-client' used the obsolete bdflush system call
Fix your initscripts?
warning: process `enbd-client' used the obsolete bdflush system call
Fix your initscripts?
warning: process `enbd-client' used the obsolete bdflush system call
Fix your initscripts?
warning: process `enbd-client' used the obsolete bdflush system call
Fix your initscripts?
warning: process `enbd-client' used the obsolete bdflush system call
Fix your initscripts?
ENBD #3922[0]: fixup_slot failed to find slot for pid 3002 ioctl MY_NBD_SET_SIG arg bff3b7f0 (322d42)
ENBD #3922[1]: fixup_slot failed to find slot for pid 3001 ioctl MY_NBD_SET_SIG arg bfb9cb10 (322d41)
ENBD #2813[0]: enbd_set_sock increased socket count on ndb to 1
ENBD #2817[0]: enbd_set_sock upping openers count on ndb
ENBD #2606[0]: enbd_enable set ENABLED on ndb
ENBD #2813[1]: enbd_set_sock increased socket count on nda to 2
ENBD #2606[1]: enbd_enable set ENABLED on nda
ENBD #2813[2]: enbd_set_sock increased socket count on ndb to 2
ENBD #876[0]: enbd_open DISK CHECK wanted in open on device ndb
ENBD #4631[0]: enbd_media_changed MEDIA CHANGED called
ENBD #4687[0]: enbd_media_changed REMOTE CHECK still has REMOTE VALID on ndb
ENBD #876[1]: enbd_open DISK CHECK wanted in open on device nda
ENBD #4631[1]: enbd_media_changed MEDIA CHANGED called
ENBD #4687[1]: enbd_media_changed REMOTE CHECK still has REMOTE VALID on nda
ENBD #4461[0]: enbd_release (0): erasing slot pid 3003
ENBD #4461[1]: enbd_release (1): erasing slot pid 3006
ENBD #3922[2]: fixup_slot failed to find slot for pid 3010 ioctl MY_NBD_SET_SIG arg bfb9cb10 (322d41)
ENBD #3814[0]: print_slot_pids device nda1 has pid 3005
ENBD #3814[1]: print_slot_pids device nda2 has pid 0
ENBD #3922[3]: fixup_slot failed to find slot for pid 3009 ioctl MY_NBD_SET_SIG arg bff3b7f0 (322d42)
ENBD #3814[2]: print_slot_pids device ndb1 has pid 0
ENBD #3814[3]: print_slot_pids device ndb2 has pid 3004
ENBD #876[2]: enbd_open DISK CHECK wanted in open on device nda
ENBD #4631[2]: enbd_media_changed MEDIA CHANGED called
ENBD #876[3]: enbd_open DISK CHECK wanted in open on device ndb
ENBD #4631[3]: enbd_media_changed MEDIA CHANGED called
ENBD #3626[1]: enbd_wait_on_ioctl_timeout remote ioctl timed out (-1 remaining)
ENBD #3710[1]: do_enbd_remote_ioctl timed out remote ioctl cfb8d618 lost
ENBD #3626[2]: enbd_wait_on_ioctl_timeout remote ioctl timed out (-1 remaining)
ENBD #3710[2]: do_enbd_remote_ioctl timed out remote ioctl cfb8d45c lost
ENBD #1092[0]: enbd_error error out req cfb8d618 from slot 0!
ENBD #1098[0]: enbd_error erroring and putting ioctl req cfb8d618
ENBD #1092[1]: enbd_error error out req cfb8d45c from slot 1!
ENBD #1098[1]: enbd_error erroring and putting ioctl req cfb8d45c
ENBD #3626[3]: enbd_wait_on_ioctl_timeout remote ioctl timed out (-1 remaining)
ENBD #3715[0]: do_enbd_remote_ioctl remote ioctl cf667868 found on dev queue
ENBD #3735[0]: do_enbd_remote_ioctl timed out remote ioctl cf667868 cleaned up
ENBD #4656[0]: enbd_media_changed REMOTE CHECK remote is down!
ENBD #4735[0]: enbd_revalidate REVALIDATE called on nda
ENBD #4767[0]: enbd_revalidate set VALID on nda
ENBD #4735[1]: enbd_revalidate REVALIDATE called on nda
  nda:remote ioctl timed out (-1 remaining)
ENBD #3715[1]: do_enbd_remote_ioctl remote ioctl cf6670e4 found on dev queue
ENBD #3735[1]: do_enbd_remote_ioctl timed out remote ioctl cf6670e4 cleaned up
ENBD #4656[1]: enbd_media_changed REMOTE CHECK remote is down!
ENBD #4735[2]: enbd_revalidate REVALIDATE called on ndb
ENBD #4767[1]: enbd_revalidate set VALID on ndb
ENBD #4735[3]: enbd_revalidate REVALIDATE called on ndb
  ndb:

echo 0 solves the problem :

  3009 -                    S enbd-client se3-croise 12360 -i B-2 -e -n 2 -m -b 512 /dev/ndb
  3013 enbd_get_req         S  \_ enbd-client se3-croise 12360 -i B-2 -e -n 2 -m -b 512 /dev/ndb
  3014 enbd_get_req         S  \_ enbd-client se3-croise 12360 -i B-2 -e -n 2 -m -b 512 /dev/ndb
  3010 -                    S enbd-client se3-croise 12355 -i A-2 -e -n 2 -m -b 512 /dev/nda
  3011 enbd_get_req         S  \_ enbd-client se3-croise 12355 -i A-2 -e -n 2 -m -b 512 /dev/nda
  3012 enbd_get_req         S  \_ enbd-client se3-croise 12355 -i A-2 -e -n 2 -m -b 512 /dev/nda

now the links are up and ok

maybe something interesting : previous dmesg ends with
ndb:
So it seems that output was really blocked at this point :
(is dmesg synchonous ?)
echo 0 unlocks it :

  ndb:<1>ENBD #3217[0]: enbd_disable disabled device nda
ENBD #3225[0]: enbd_disable INVALIDATEd device nda
Buffer I/O error on device nda, logical block 7
Buffer I/O error on device nda, logical block 6
Buffer I/O error on device nda, logical block 5
Buffer I/O error on device nda, logical block 4
Buffer I/O error on device nda, logical block 3
Buffer I/O error on device nda, logical block 2
Buffer I/O error on device nda, logical block 1
Buffer I/O error on device nda, logical block 0
ENBD #2252[0]: enbd_clr_queue unqueued 8 reqs
ENBD #2252[1]: enbd_clr_queue unqueued 0 reqs
ENBD #3313[0]: enbd_soft_reset INVALIDATE DEVICE nda BEGIN
ENBD #3327[0]: enbd_soft_reset INVALIDATE DEVICE nda DONE
ENBD #3340[0]: enbd_soft_reset run enbd_request on nda
ENBD #3217[1]: enbd_disable disabled device ndb
ENBD #3225[1]: enbd_disable INVALIDATEd device ndb
Buffer I/O error on device ndb, logical block 7
Buffer I/O error on device ndb, logical block 6
ENBD #2252[2]: enbd_clr_queue unqueued 8 reqs
ENBD #2252[3]: enbd_clr_queue unqueued 0 reqs
ENBD #3313[1]: enbd_soft_reset INVALIDATE DEVICE ndb BEGIN
ENBD #3327[1]: enbd_soft_reset INVALIDATE DEVICE ndb DONE
ENBD #3340[1]: enbd_soft_reset run enbd_request on ndb
ENBD #2470[1]: do_enbd_request device not enabled.
  unable to read partition table
ENBD #2252[4]: enbd_clr_queue unqueued 0 reqs
ENBD #3313[2]: enbd_soft_reset INVALIDATE DEVICE nda BEGIN
ENBD #3327[2]: enbd_soft_reset INVALIDATE DEVICE nda DONE
ENBD #3340[2]: enbd_soft_reset run enbd_request on nda
ENBD #4461[2]: enbd_release (0): erasing slot pid 3005
  unable to read partition table
ENBD #2252[5]: enbd_clr_queue unqueued 0 reqs
ENBD #3313[3]: enbd_soft_reset INVALIDATE DEVICE ndb BEGIN
ENBD #3327[3]: enbd_soft_reset INVALIDATE DEVICE ndb DONE
ENBD #3340[3]: enbd_soft_reset run enbd_request on ndb
ENBD #4461[3]: enbd_release (1): erasing slot pid 3004
ENBD #2606[2]: enbd_enable set ENABLED on nda
ENBD #2606[3]: enbd_enable set ENABLED on ndb

so let's see syslog   :
Dec  7 14:59:18 ldap kernel: ENBD #4631[3]: enbd_media_changed MEDIA CHANGED called
Dec  7 14:59:28 ldap kernel: ENBD #3626[1]: enbd_wait_on_ioctl_timeout remote ioctl timed out (-1 remaining)
Dec  7 14:59:28 ldap kernel: ENBD #3710[1]: do_enbd_remote_ioctl timed out remote ioctl cfb8d618 lost
Dec  7 14:59:28 ldap kernel: ENBD #3626[2]: enbd_wait_on_ioctl_timeout remote ioctl timed out (-1 remaining)
Dec  7 14:59:28 ldap kernel: ENBD #3710[2]: do_enbd_remote_ioctl timed out remote ioctl cfb8d45c lost
Dec  7 14:59:29 ldap kernel: ENBD #1092[0]: enbd_error error out req cfb8d618 from slot 0!
Dec  7 14:59:29 ldap kernel: ENBD #1098[0]: enbd_error erroring and putting ioctl req cfb8d618
Dec  7 14:59:29 ldap kernel: ENBD #1092[1]: enbd_error error out req cfb8d45c from slot 1!
Dec  7 14:59:29 ldap kernel: ENBD #1098[1]: enbd_error erroring and putting ioctl req cfb8d45c
Dec  7 14:59:38 ldap kernel: ENBD #3626[3]: enbd_wait_on_ioctl_timeout remote ioctl timed out (-1 remaining)
Dec  7 14:59:38 ldap kernel: ENBD #3715[0]: do_enbd_remote_ioctl remote ioctl cf667868 found on dev queue
Dec  7 14:59:38 ldap kernel: ENBD #3735[0]: do_enbd_remote_ioctl timed out remote ioctl cf667868 cleaned up
Dec  7 14:59:38 ldap kernel: ENBD #4656[0]: enbd_media_changed REMOTE CHECK remote is down!
Dec  7 14:59:38 ldap kernel: ENBD #4735[0]: enbd_revalidate REVALIDATE called on nda
Dec  7 14:59:38 ldap kernel: ENBD #4767[0]: enbd_revalidate set VALID on nda
Dec  7 14:59:38 ldap kernel: ENBD #4735[1]: enbd_revalidate REVALIDATE called on nda
Dec  7 14:59:38 ldap kernel:  nda:remote ioctl timed out (-1 remaining)
Dec  7 14:59:38 ldap kernel: ENBD #3715[1]: do_enbd_remote_ioctl remote ioctl cf6670e4 found on dev queue
Dec  7 14:59:38 ldap kernel: ENBD #3735[1]: do_enbd_remote_ioctl timed out remote ioctl cf6670e4 cleaned up
Dec  7 14:59:38 ldap kernel: ENBD #4656[1]: enbd_media_changed REMOTE CHECK remote is down!
Dec  7 14:59:38 ldap kernel: ENBD #4735[2]: enbd_revalidate REVALIDATE called on ndb
Dec  7 14:59:38 ldap kernel: ENBD #4767[1]: enbd_revalidate set VALID on ndb
Dec  7 14:59:38 ldap kernel: ENBD #4735[3]: enbd_revalidate REVALIDATE called on ndb
Dec  7 15:05:47 ldap kernel:  ndb:<1>ENBD #3217[0]: enbd_disable disabled device nda
Dec  7 15:05:47 ldap kernel: ENBD #3225[0]: enbd_disable INVALIDATEd device nda
Dec  7 15:05:47 ldap kernel: Buffer I/O error on device nda, logical block 7
Dec  7 15:05:47 ldap kernel: Buffer I/O error on device nda, logical block 6
Dec  7 15:05:47 ldap kernel: Buffer I/O error on device nda, logical block 5
Dec  7 15:05:47 ldap kernel: Buffer I/O error on device nda, logical block 4
Dec  7 15:05:47 ldap kernel: Buffer I/O error on device nda, logical block 3
Dec  7 15:05:47 ldap kernel: Buffer I/O error on device nda, logical block 2
Dec  7 15:05:47 ldap kernel: Buffer I/O error on device nda, logical block 1
Dec  7 15:05:47 ldap kernel: Buffer I/O error on device nda, logical block 0
Dec  7 15:05:47 ldap kernel: ENBD #2252[0]: enbd_clr_queue unqueued 8 reqs
Dec  7 15:05:47 ldap kernel: ENBD #2252[1]: enbd_clr_queue unqueued 0 reqs
Dec  7 15:05:47 ldap kernel: ENBD #3313[0]: enbd_soft_reset INVALIDATE DEVICE nda BEGIN
Dec  7 15:05:47 ldap kernel: ENBD #3327[0]: enbd_soft_reset INVALIDATE DEVICE nda DONE