Fail to boot Ubuntu partition with VERR_IO_NOT_READY and BLKCACHE_IOERR
Posted: 8. Apr 2020, 00:20
I have an Ubuntu 18.04 virtual machine running from Disc 0, Partition 4 under Windows 10. It all worked fine until I tried to mount a SD Card in the VM, I couldn't get it to work and tried to install the VirtualBox extension packs 6.1.4. At some point the image stopped working, seems the partition is not writable anymore.
I've found some older posts regarding this issue but none of the methods seems to fix the problem.
I'm running as admin, the attributes looks fine in diskpart, enabling host I/O cache doesn't help. I also tried to recreate the vmdk but that didn't help either, creation is OK, but same write error. I also downgraded to 6.1.2 to try to fix the write problem, since the latest release has seemed less stable, but it didn't help. (That's why the log is from 6.1.2)
I've found some older posts regarding this issue but none of the methods seems to fix the problem.
I'm running as admin, the attributes looks fine in diskpart, enabling host I/O cache doesn't help. I also tried to recreate the vmdk but that didn't help either, creation is OK, but same write error. I also downgraded to 6.1.2 to try to fix the write problem, since the latest release has seemed less stable, but it didn't help. (That's why the log is from 6.1.2)
00:00:00.255203 VirtualBox VM 6.1.2 r135662 win.amd64 (Jan 15 2020 14:07:18) release log 00:00:00.255217 Build Type: release 00:00:00.255219 OS Product: Windows 10 00:00:00.255220 OS Release: 10.0.17763 00:00:00.255220 OS Service Pack: 00:00:00.287253 Firmware type: UEFI 00:00:00.288050 Secure Boot: Disabled 00:00:00.288070 Host RAM: 32527MB (31.7GB) total, 24134MB (23.5GB) available 00:00:00.288074 Executable: C:\Program Files\Oracle\VirtualBox\VBoxHeadless.exe 00:00:00.288075 Package type: WINDOWS_64BITS_GENERIC 00:00:00.288949 Installed Extension Packs: 00:00:00.289094 None installed! 00:00:00.289711 Console: Machine state changed to 'Starting' 00:00:01.065414 SUP: Loaded VMMR0.r0 (C:\Program Files\Oracle\VirtualBox\VMMR0.r0) at 0xXXXXXXXXXXXXXXXX - ModuleInit at XXXXXXXXXXXXXXXX and ModuleTerm at XXXXXXXXXXXXXXXX using the native ring-0 loader 00:00:01.065432 SUP: VMMR0EntryEx located at XXXXXXXXXXXXXXXX and VMMR0EntryFast at XXXXXXXXXXXXXXXX 00:00:01.065436 SUP: windbg> .reload /f C:\Program Files\Oracle\VirtualBox\VMMR0.r0=0xXXXXXXXXXXXXXXXX 00:00:01.066686 Guest OS type: 'Ubuntu_64' 00:00:01.067478 fHMForced=true - No raw-mode support in this build! 00:00:01.070617 File system of 'C:\tmp\Snapshots' (snapshots) is ntfs 00:00:01.070625 File system of 'C:\tmp\part4.vmdk' is ntfs 00:00:02.210998 Shared Clipboard: Service loaded 00:00:02.211011 Shared Clipboard: Mode: Bidirectional 00:00:02.211322 Shared Clipboard: Service running in headless mode 00:00:02.217563 Drag and drop service loaded 00:00:02.217573 Drag and drop mode: Bidirectional 00:00:02.650239 [/Devices/ahci/] (level 2) 00:00:02.650240 [/Devices/ahci/0/] (level 3) 00:00:02.650243 [/Devices/ahci/0/Config/] (level 4) 00:00:02.650245 [/Devices/ahci/0/Config/Port0/] (level 5) 00:00:02.650247 [/Devices/ahci/0/LUN#0/] (level 4) 00:00:02.650248 [/Devices/ahci/0/LUN#0/Config/] (level 5) 00:00:02.650252 [/Devices/ahci/0/LUN#999/] (level 4) 00:00:02.650253 [/Devices/ahci/0/LUN#999/Config/] (level 5) 00:00:02.650254 DeviceInstance <string> = "ahci/0" (cb=7) 00:00:02.650345 SataHardDiskDevice <string> = "ahci" (cb=5) 00:00:03.356485 AHCI: LUN#0: disk, PCHS=16383/16/63, total number of sectors 2000409264 00:00:03.356782 AHCI: Port1: No driver attached 00:00:03.356817 AHCI#0: Reset the HBA 00:00:03.681482 AHCI#0: Reset the HBA 00:00:03.681519 AHCI#0: Port 0 reset 00:00:03.682033 VMMDev: Guest Log: BIOS: AHCI 0-P#0: PCHS=16383/16/63 LCHS=1024/255/63 0x00000000773bd2b0 sectors 00:00:03.682068 AHCI#0: Port 1 reset 00:00:06.324148 VMMDev: Guest Log: BIOS: Booting from Hard Disk... 00:00:06.329592 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=0000000000000000 w=720 h=400 bpp=0 cbLine=0x0 flags=0x0 origin=0,0 00:00:06.487725 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=0000000009910000 w=640 h=480 bpp=32 cbLine=0xA00 flags=0x0 origin=0,0 00:00:07.147520 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=0000000000000000 w=720 h=400 bpp=0 cbLine=0x0 flags=0x0 origin=0,0 00:00:07.330772 GIM: KVM: VCPU 0: Enabled system-time struct. at 0x000000035354c000 - u32TscScale=0xb04ef9b6 i8TscShift=-1 uVersion=2 fFlags=0x1 uTsc=0x27c912fc5 uVirtNanoTS=0xdb3430cd 00:00:07.330894 TM: Switching TSC mode from 'VirtTscEmulated' to 'RealTscOffset' 00:00:08.091453 GIM: KVM: Enabled wall-clock struct. at 0x00000003535cc000 - u32Sec=1586289606 u32Nano=894124976 uVersion=2 00:00:08.100107 PIT: mode=2 count=0x12a5 (4773) - 249.98 Hz (ch=0) 00:00:08.100329 APIC0: Switched mode to x2APIC 00:00:08.272400 PIT: mode=0 count=0x10000 (65536) - 18.20 Hz (ch=0) 00:00:08.273228 APIC1: Switched mode to x2APIC 00:00:08.273231 GIM: KVM: VCPU 1: Enabled system-time struct. at 0x000000035354c040 - u32TscScale=0xb04ef9b6 i8TscShift=-1 uVersion=2 fFlags=0x1 uTsc=0x27c912fc5 uVirtNanoTS=0xdb3430cd 00:00:08.275794 APIC2: Switched mode to x2APIC 00:00:08.276016 GIM: KVM: VCPU 2: Enabled system-time struct. at 0x000000035354c080 - u32TscScale=0xb04ef9b6 i8TscShift=-1 uVersion=2 fFlags=0x1 uTsc=0x27c912fc5 uVirtNanoTS=0xdb3430cd 00:00:08.278491 APIC3: Switched mode to x2APIC 00:00:08.278501 GIM: KVM: VCPU 3: Enabled system-time struct. at 0x000000035354c0c0 - u32TscScale=0xb04ef9b6 i8TscShift=-1 uVersion=2 fFlags=0x1 uTsc=0x27c912fc5 uVirtNanoTS=0xdb3430cd 00:00:08.281028 APIC4: Switched mode to x2APIC 00:00:08.281033 GIM: KVM: VCPU 4: Enabled system-time struct. at 0x000000035354c100 - u32TscScale=0xb04ef9b6 i8TscShift=-1 uVersion=2 fFlags=0x1 uTsc=0x27c912fc5 uVirtNanoTS=0xdb3430cd 00:00:08.283496 APIC5: Switched mode to x2APIC 00:00:08.283497 GIM: KVM: VCPU 5: Enabled system-time struct. at 0x000000035354c140 - u32TscScale=0xb04ef9b6 i8TscShift=-1 uVersion=2 fFlags=0x1 uTsc=0x27c912fc5 uVirtNanoTS=0xdb3430cd 00:00:08.486101 OHCI: Software reset 00:00:09.475860 PIIX3 ATA: Ctl#0: RESET, DevSel=0 AIOIf=0 CmdIf0=0xa0 (-1 usec ago) CmdIf1=0x00 (-1 usec ago) 00:00:09.476045 PIIX3 ATA: Ctl#0: finished processing RESET 00:00:09.476632 OHCI: USB Reset 00:00:09.634542 OHCI: Software reset 00:00:09.634763 OHCI: USB Operational 00:00:09.812387 AHCI#0: Reset the HBA 00:00:09.812409 VD#0: Cancelling all active requests 00:00:09.813551 AHCI#0: Port 0 reset 00:00:09.820139 VD#0: Cancelling all active requests 00:00:09.829897 Enabling different vbva mode 00:00:09.878414 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=0000000009910000 w=800 h=600 bpp=32 cbLine=0xC80 flags=0x1 origin=0,0 00:00:12.911629 AioMgr0-N: Request 0x00000008a79ff0 failed with rc=VERR_IO_NOT_READY, migrating endpoint \\.\PhysicalDrive0 to failsafe manager. 00:00:12.914363 I/O cache: Error while writing entry at offset 433755594752 (4096 bytes) to medium "ahci-0-0" (rc=VERR_WRITE_ERROR) 00:00:12.914390 VM: Raising runtime error 'BLKCACHE_IOERR' (fFlags=0x6) 00:00:12.914450 Changing the VM state from 'RUNNING' to 'SUSPENDING' 00:00:12.914492 I/O cache: Error while writing entry at offset 433755553792 (16384 bytes) to medium "ahci-0-0" (rc=VERR_WRITE_ERROR) 00:00:12.955465 I/O cache: Error while writing entry at offset 841654214656 (1024 bytes) to medium "ahci-0-0" (rc=VERR_WRITE_ERROR) 00:00:12.957615 AIOMgr: Endpoint for file 'C:\tmp\part4.vmdk' (flags 00040781) created successfully 00:00:12.957866 AIOMgr: Endpoint for file 'C:\tmp\part4-pt.vmdk' (flags 000c0781) created successfully 00:00:12.958705 AIOMgr: Endpoint for file '\\.\PhysicalDrive0' (flags 000c0781) created successfully 00:00:13.005345 PDMR3Suspend: 90 816 909 ns run time 00:00:13.005359 Changing the VM state from 'SUSPENDING' to 'SUSPENDED' 00:00:13.005368 Console: Machine state changed to 'Paused' 00:00:13.005577 Console: VM runtime error: fatal=false, errorID=BLKCACHE_IOERR message="The I/O cache encountered an error while updating data in medium "ahci-0-0" (rc=VERR_WRITE_ERROR). Make sure there is enough free space on the disk and that the disk is working properly. Operation can be resumed afterwards"
DISKPART> attributes disk Current Read-only State : No Read-only : No Boot Disk : Yes Pagefile Disk : Yes Hibernation File Disk : No Crashdump Disk : Yes Clustered Disk : No DISKPART> list volume Volume ### Ltr Label Fs Type Size Status Info ---------- --- ----------- ----- ---------- ------- --------- -------- Volume 0 C WINDOWS NTFS Partition 366 GB Healthy Boot * Volume 1 Partition 585 GB Healthy Offline Volume 2 SYSTEM FAT32 Partition 1000 MB Healthy System DISKPART> attributes volume Read-only : No Hidden : No No Default Drive Letter: Yes Shadow Copy : No