System Hang Due to Backup Failure

Hi all,

(#22039954 Raised)

Today my ReadynasPRO 6 hung upon accidently starting a backup job and the drive being removed from the system. The system was hung hard and had to be hard shutdown (held power button for 5 seconds) to resume operation. In this state, the green light above the backup button was also on.

Upon inspecting the logs, the last operation was the backup job and the next is when I got on site to perform the hard reload:

Oct 7 15:58:53 despair RAIDiator: Backup button jobs started.
Oct 7 15:58:54 despair rsyncd[20050]: connect from despair (192.168.1.200)
Oct 7 15:58:54 despair rsyncd[20050]: rsync on PREMIER/. from admin@despair (192.168.1.200)
Oct 7 15:58:55 despair rsyncd[20050]: building file list
Oct 7 15:58:56 despair kernel: usb 1-2: USB disconnect, address 6
Oct 7 15:58:56 despair kernel: scsi 10:0:0:0: [sde] Unhandled error code
Oct 7 15:58:56 despair kernel: scsi 10:0:0:0: [sde] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
Oct 7 15:58:56 despair kernel: scsi 10:0:0:0: [sde] CDB: Read(10): 28 00 08 10 91 d7 00 00 f0 00
Oct 7 15:58:56 despair kernel: end_request: I/O error, dev sde, sector 135303639
Oct 7 15:58:56 despair kernel: scsi 10:0:0:0: rejecting I/O to offline device
Oct 7 15:58:56 despair kernel: scsi 10:0:0:0: [sde] Unhandled error code
Oct 7 15:58:56 despair kernel: scsi 10:0:0:0: [sde] Result: hostbyte=DID_NO_CONNECT driverbyte=DRIVER_OK
Oct 7 15:58:56 despair kernel: scsi 10:0:0:0: [sde] CDB: Read(10): 28 00 08 10 92 c7 00 00 10 00
Oct 7 15:58:56 despair kernel: end_request: I/O error, dev sde, sector 135303879
Oct 7 15:58:57 despair udevd-event[20072]: unlink_secure: chown(/dev/sde1, 0, 0) failed: No such file or directory
Oct 7 15:58:57 despair udevd-event[20072]: unlink_secure: chmod(/dev/sde1, 0000) failed: No such file or directory
Oct 7 15:58:57 despair kernel: EXT3-fs error (device sde1): ext3_find_entry: reading directory #1011713 offset 0
Oct 7 15:58:57 despair kernel: EXT3-fs (sde1): I/O error while writing superblock
Oct 7 15:58:57 despair kernel: EXT3-fs error (device sde1): ext3_find_entry: reading directory #1011713 offset 0
Oct 7 15:58:57 despair kernel: EXT3-fs (sde1): I/O error while writing superblock
Oct 7 15:58:57 despair kernel: EXT3-fs error (device sde1): read_inode_bitmap: Cannot read inode bitmap - block_group = 494, inode_bitmap = 16187393
Oct 7 15:58:57 despair kernel: EXT3-fs (sde1): I/O error while writing superblock
Oct 7 15:58:57 despair kernel: EXT3-fs (sde1): error in ext3_new_inode: IO failure
Oct 7 15:58:57 despair rsyncd[20050]: rsync: connection unexpectedly closed (61433 bytes received so far) [sender]
Oct 7 15:58:57 despair rsyncd[20050]: rsync error: error in rsync protocol data stream (code 12) at io.c(605) [sender=3.0.9]
Oct 7 15:58:57 despair rsyncd[20050]: rsync: writefd_unbuffered failed to write 91 bytes to socket [sender]: Broken pipe (32)
Oct 7 15:58:57 despair kernel: EXT3-fs (sde1): I/O error while writing superblock
Oct 7 15:58:58 despair kernel: journal_bmap: journal block not found at offset 23284 on sde1
Oct 7 15:58:58 despair kernel: Aborting journal on device sde1.
Oct 7 15:58:58 despair kernel: JBD: I/O error detected when updating journal superblock for sde1.
Oct 7 15:58:58 despair kernel: journal commit I/O error
Oct 7 15:58:58 despair rsyncd[20100]: connect from despair (192.168.1.200)
Oct 7 15:58:58 despair rsyncd[20100]: rsync on PREMIER/. from admin@despair (192.168.1.200)
Oct 7 15:58:58 despair kernel: EXT3-fs (sde1): error: ext3_put_super: Couldn't clean up the journal
Oct 7 15:58:58 despair rsyncd[20100]: building file list
Oct 7 15:58:58 despair kernel: EXT3-fs (sde1): error: remounting filesystem read-only
Oct 7 15:58:58 despair kernel: scsi: killing requests for dead queue
Oct 7 15:58:58 despair rsyncd[20100]: rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]: Connection reset by peer (104)
Oct 7 15:58:58 despair rsyncd[20100]: rsync error: error in rsync protocol data stream (code 12) at io.c(1532) [sender=3.0.9]
Oct 7 15:58:58 despair rsyncd[20106]: connect from despair (192.168.1.200)
Oct 7 15:58:58 despair rsyncd[20106]: rsync on PREMIER/. from admin@despair (192.168.1.200)
Oct 7 15:58:58 despair rsyncd[20106]: building file list
Oct 7 15:58:58 despair rsyncd[20106]: rsync: writefd_unbuffered failed to write 959 bytes to socket [sender]: Connection reset by peer (104)
Oct 7 15:58:58 despair rsyncd[20106]: rsync error: error in rsync protocol data stream (code 12) at io.c(1532) [sender=3.0.9]
Oct 7 15:58:58 despair RAIDiator: Error encountered copying data from remote source path 192.168.1.200::PREMIER ==> /USB_HDD_2/PREMIER due to empty source d
Oct 7 18:43:38 despair syslogd 1.4.1#18: restart.
Oct 7 18:43:38 despair kernel: klogd 1.4.1#18, log source = /proc/kmsg started.
Oct 7 18:43:38 despair kernel: Initializing cgroup subsys cpu


So here are 2 questions...

1) How do you remove the drive from he Pro6 using and holding the backup button. I have held for 5 seconds and then generally it comes up saying disconnected but other times it starts the backup again. It's not me personally doing this operation and on this (and other occasions) the person doing this opts to remove the drive mid backup.

2) Could taking the drive out mid operation reasonably cause he ReadyNAS to hang like this? The job it was running was an rsync job where we use localhost and the USB drive as the source and desination as USB port 1.

Look forward to your feedback...

Thanks.