Article 5Q9SQ Unmounting USB disk after successful Rsync led to data loss

Unmounting USB disk after successful Rsync led to data loss

by
oneleaf
from LinuxQuestions.org on (#5Q9SQ)
Hello,

I had a strange issue happen yesterday that I am trying to figure out what happened.

I am on Linux Mint Mate 19.1, and I ran a regular rsync script. Here's what happened:
  • At 1:13:00, Rsync finished successfully
  • At 1:13:10, I unmounted the hard disk from the file manager, and it gave no error.
  • I then proceeded to disconnect the USB hard disk.
  • 24 hours later, I ran the same rsync script and was surprised to see a file copied again that already successfully copied the day before.
  • Since I use hard-links for versioning, I was able to go back and see that in the prior day, the file in question was only partially there (instead of 5.3GB file, it was only 4.0GB).
  • However, the Rsync log indicated a successful transfer the day before, so I found this puzzling.
So I went into /var/log/syslog.1 (which had the events from the initial rsync job). I was surprised to find the following:
  • As expected, at 1:13:10, it does show the attempted unmounting of the disk.
  • However, at 1:13:19, it is littered with I/O errors on the disk.
The output of the pertinent section of the log is below. Any ideas what happened? Is there still some disk activity that occurs after the rsync job is done? And is it possible the file manager falsely indicates a successful unmounting while this is still happening? Thanks for any insight!

Code:Oct 2 01:13:10 mintmate systemd[1]: Stopping Clean the /media/yudy/MovieBackup mount point...
Oct 2 01:13:10 mintmate systemd[1]: Stopped Clean the /media/yudy/MovieBackup mount point.
Oct 2 01:13:13 mintmate dhclient[2782]: XMT: Solicit on enp0s31f6, interval 123960ms.
Oct 2 01:13:19 mintmate kernel: [1431446.560051] usb 1-9: USB disconnect, device number 12
Oct 2 01:13:19 mintmate kernel: [1431446.576008] sd 6:0:0:0: [sdd] tag#0 FAILED Result: hostbyte=DID_NO_CONNECT driverbyte=DRIVER_OK
Oct 2 01:13:19 mintmate kernel: [1431446.576010] sd 6:0:0:0: [sdd] tag#0 CDB: Write(10) 2a 00 0d e6 8f 80 00 00 f0 00
Oct 2 01:13:19 mintmate kernel: [1431446.576011] print_req_error: I/O error, dev sdd, sector 233213824
Oct 2 01:13:19 mintmate kernel: [1431446.576072] EXT4-fs warning (device sdd1): ext4_end_bio:323: I/O error 10 writing to inode 40894678 (offset 4169138176 size 8388608 starting block 29152512)
Oct 2 01:13:19 mintmate kernel: [1431446.576074] buffer_io_error: 8182 callbacks suppressed
Oct 2 01:13:19 mintmate kernel: [1431446.576074] Buffer I/O error on device sdd1, logical block 29151744
Oct 2 01:13:19 mintmate kernel: [1431446.576077] Buffer I/O error on device sdd1, logical block 29151745
Oct 2 01:13:19 mintmate kernel: [1431446.576078] Buffer I/O error on device sdd1, logical block 29151746
Oct 2 01:13:19 mintmate kernel: [1431446.576079] Buffer I/O error on device sdd1, logical block 29151747
Oct 2 01:13:19 mintmate kernel: [1431446.576080] Buffer I/O error on device sdd1, logical block 29151748
Oct 2 01:13:19 mintmate kernel: [1431446.576081] Buffer I/O error on device sdd1, logical block 29151749
Oct 2 01:13:19 mintmate kernel: [1431446.576082] Buffer I/O error on device sdd1, logical block 29151750
Oct 2 01:13:19 mintmate kernel: [1431446.576083] Buffer I/O error on device sdd1, logical block 29151751
Oct 2 01:13:19 mintmate kernel: [1431446.576084] Buffer I/O error on device sdd1, logical block 29151752
Oct 2 01:13:19 mintmate kernel: [1431446.576085] Buffer I/O error on device sdd1, logical block 29151753
Oct 2 01:13:19 mintmate kernel: [1431446.576290] EXT4-fs warning (device sdd1): ext4_end_bio:323: I/O error 10 writing to inode 40894678 (offset 4169138176 size 8388608 starting block 29153024)
Oct 2 01:13:19 mintmate kernel: [1431446.576515] EXT4-fs warning (device sdd1): ext4_end_bio:323: I/O error 10 writing to inode 40894678 (offset 4169138176 size 8388608 starting block 29153536)
Oct 2 01:13:19 mintmate kernel: [1431446.576704] EXT4-fs warning (device sdd1): ext4_end_bio:323: I/O error 10 writing to inode 40894678 (offset 4177526784 size 8388608 starting block 29154048)
Oct 2 01:13:19 mintmate kernel: [1431446.576871] EXT4-fs warning (device sdd1): ext4_end_bio:323: I/O error 10 writing to inode 40894678 (offset 4177526784 size 8388608 starting block 29154560)
Oct 2 01:13:19 mintmate kernel: [1431446.577039] EXT4-fs warning (device sdd1): ext4_end_bio:323: I/O error 10 writing to inode 40894678 (offset 4177526784 size 8388608 starting block 29155072)
Oct 2 01:13:19 mintmate kernel: [1431446.577216] EXT4-fs warning (device sdd1): ext4_end_bio:323: I/O error 10 writing to inode 40894678 (offset 4177526784 size 8388608 starting block 29155584)
Oct 2 01:13:19 mintmate kernel: [1431446.577374] sd 6:0:0:0: [sdd] tag#0 FAILED Result: hostbyte=DID_NO_CONNECT driverbyte=DRIVER_OK
Oct 2 01:13:19 mintmate kernel: [1431446.577375] sd 6:0:0:0: [sdd] tag#0 CDB: Write(10) 2a 00 0d e6 90 70 00 00 f0 00
Oct 2 01:13:19 mintmate kernel: [1431446.577375] print_req_error: I/O error, dev sdd, sector 233214064
Oct 2 01:13:19 mintmate kernel: [1431446.577377] EXT4-fs warning (device sdd1): ext4_end_bio:323: I/O error 10 writing to inode 40894678 (offset 4169138176 size 8388608 starting block 29152000)
Oct 2 01:13:19 mintmate kernel: [1431446.577673] EXT4-fs warning (device sdd1): ext4_end_bio:323: I/O error 10 writing to inode 40894678 (offset 4185915392 size 4198400 starting block 29156096)
Oct 2 01:13:19 mintmate kernel: [1431446.578112] EXT4-fs warning (device sdd1): ext4_end_bio:323: I/O error 10 writing to inode 40894678 (offset 4185915392 size 6295552 starting block 29156608)
Oct 2 01:13:19 mintmate kernel: [1431446.579199] JBD2: Detected IO errors while flushing file data on sdd1-8
Oct 2 01:13:19 mintmate kernel: [1431446.579202] Aborting journal on device sdd1-8.
Oct 2 01:13:19 mintmate kernel: [1431446.579210] JBD2: Error -5 detected when updating journal superblock for sdd1-8.
Oct 2 01:13:19 mintmate kernel: [1431446.580009] EXT4-fs error (device sdd1) in ext4_reserve_inode_write:5875: Journal has aborted
Oct 2 01:13:19 mintmate kernel: [1431446.580122] EXT4-fs error (device sdd1): mpage_map_and_submit_extent:2594: comm kworker/u8:2: Failed to mark inode 40894678 dirty
Oct 2 01:13:19 mintmate kernel: [1431446.580124] EXT4-fs (sdd1): previous I/O error to superblock detected
Oct 2 01:13:19 mintmate kernel: [1431446.580130] EXT4-fs error (device sdd1) in ext4_writepages:2923: Journal has aborted
Oct 2 01:13:19 mintmate kernel: [1431446.580132] EXT4-fs (sdd1): previous I/O error to superblock detected
Oct 2 01:13:19 mintmate kernel: [1431446.580374] JBD2: Detected IO errors while flushing file data on sdd1-8
Oct 2 01:13:19 mintmate kernel: [1431446.583085] EXT4-fs (sdd1): previous I/O error to superblock detected
Oct 2 01:13:19 mintmate kernel: [1431446.583098] EXT4-fs error (device sdd1): ext4_journal_check_start:61: Detected aborted journal
Oct 2 01:13:19 mintmate kernel: [1431446.583099] EXT4-fs (sdd1): Remounting filesystem read-only
Oct 2 01:13:19 mintmate kernel: [1431446.583100] EXT4-fs (sdd1): previous I/O error to superblock detected
Oct 2 01:13:19 mintmate kernel: [1431446.583107] EXT4-fs (sdd1): ext4_writepages: jbd2_start: 9223372036854775807 pages, ino 40894678; err -30
Oct 2 01:13:20 mintmate udisksd[959]: Unmounted /dev/sdd1 on behalf of uid 1000
Oct 2 01:13:20 mintmate upowerd[2378]: unhandled action 'unbind' on /sys/devices/pci0000:00/0000:00:14.0/usb1/1-9/1-9:1.0
Oct 2 01:13:20 mintmate upowerd[2378]: unhandled action 'unbind' on /sys/devices/pci0000:00/0000:00:14.0/usb1/1-9latest?d=yIl2AUoC8zA latest?i=leLShZGAMDs:hZJ565nZsz4:F7zBnMy latest?i=leLShZGAMDs:hZJ565nZsz4:V_sGLiP latest?d=qj6IDK7rITs latest?i=leLShZGAMDs:hZJ565nZsz4:gIN9vFwleLShZGAMDs
External Content
Source RSS or Atom Feed
Feed Location https://feeds.feedburner.com/linuxquestions/latest
Feed Title LinuxQuestions.org
Feed Link https://www.linuxquestions.org/questions/
Reply 0 comments