Remaining problems with Open-ZFS update to 2.2.3 rc5

[guenther-alka]

Win 11 Pro newest, german

I just updated from rc4 to rc5. Installation went through up to "restart now" with rebooting screen.
After that I had a BSOD with message rcp1.sys system service interception.

As rcp1.sys belongs to the Realtek audio driver, I reloaded newest Realtek audio driver from Lenovo and retried installer.

This time I also had a BSOD after installation but with message page fault in nonpaged area.

As you asumed Avira may be involved, I disabled Avira and retried installer but with same resutt (page fault)

Beside the crash, rc5 is installed with ZFS pool shown as disk type zfs

memory dump
https://drive.google.com/file/d/1MUBG1EAN26DFxmCtK3AjllAj8TEt8Z2a/view?usp=sharing

[lundman]

Thanks, I will take a look. Wasn't rcp1 belonging to Norton? It does seem like something you have installed makes ZFS angry, if we can figure out which one, I can fix it.

[guenther-alka]

Sorry, a typo. The related driver was rtp1.sys

To rule out that Avira is the problem, i deinstalled Avira and retried rc5 installer.
It crashed again after setup (quite hard, came up with OS repair) and message
"kernel security check failure"

As this is a new message, I have added memory.dmp
https://drive.google.com/file/d/1MKC6HZQlmZOAFxqUHAlJxM7veiqlrixf/view?usp=sharing

[lundman]

You willing to try out https://openzfsonosx.org/wiki/Windows_BSOD to print the stack?
Or the script https://github.com/openzfsonwindows/openzfs/tree/development/contrib/windows/parsedump

would be faster in the long run.

[guenther-alka]

I cannot help with debugging. Unless it helps you, a simple upload of dump files is the easier option for me.

[lundman]

Last one is

     : 00000000`00000139 00000000`00000003 ffff888e`52ce22a0 ffff888e`52ce21f8 : nt!KeBugCheckEx
     : ffffc389`a9802140 00000000`00000000 00000000`00000000 fffff807`55455f89 : nt!KiBugCheckDispatch+0x69
     : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : nt!KiFastFailDispatch+0xb2
     : ffffc389`a9eee040 00000000`00000000 00000000`00000000 00000000`00000000 : nt!KiRaiseSecurityCheckFailure+0x346
     : ffffc389`a9802380 ffffc389`a98047c0 00000000`00000002 00000000`000000e0 : nt!RtlpHpLfhSlotAllocate+0x2256f8
     : 00000000`00000002 ffffc389`bf723c00 fffff807`54645750 00000000`00001001 : nt!ExAllocateHeapPool+0x2af
     : 00000000`00000040 00000000`00000001 00000000`00000600 fffff807`00000000 : nt!ExpAllocatePoolWithTagFromNode+0x5f
     : 00000000`00000000 ffff6ce1`22ba4c56 ffffc389`00000000 ffffc389`a9e90180 : nt!ExAllocatePool2+0xdd
     : 00000000`00000000 fffff807`55cad68d 00000000`00000040 00000000`00000001 : nt!WdtpAllocateTimer+0x1d
     : 00000000`00000000 00000000`00000000 ffff888e`52ce2830 00000000`00000240 : nt!PnpWatchdogTimerAllocate+0x40
     : 00000000`00000000 00000000`00000001 00000000`00000000 ffff898f`638565c0 : nt!PnpAllocateWatchdog+0x6a
     : 00000000`00000000 ffff898f`638565c0 ffffc389`a9ea2c00 00000000`00000000 : nt!PnpEnableWatchdog+0x1c
     : ffff898f`638565c0 ffffc389`a9ea2c00 ffffc389`a9e90040 ffffc389`a9ea2c00 : nt!PnpAllocateAndEnableEventWatchdog+0x6f
     : ffffc389`a9ea2cf0 ffffc389`a9e90040 ffff888e`52ce2a00 ffffc389`00000000 : nt!PnpDeviceEventWorker+0x116
     : ffffc389`a9e90040 00000000`0000026d ffffc389`a9e90040 fffff807`55553510 : nt!ExpWorkerThread+0x155
     : ffffe581`c8891180 ffffc389`a9e90040 fffff807`554ed700 00000000`00000000 : nt!PspSystemThreadStartup+0x57
     : ffff888e`52ce3000 ffff888e`52cdc000 00000000`00000000 00000000`00000000 : nt!KiStartSystemThread+0x34

FFFFC389AA0E3040: dprintf: zfs_vnops_windows.c:7395:dispatcher(): dispatcher: en
ter: major 15: minor 240: IRP_MJ_INTERNAL_DEVICE_CONTROL: type 0x6: fo 000000000
0000000
FFFFC389AA0E3040: dprintf: zfs_vnops_windows.c:7395:dispatcher(): dispatcher: en
ter: major 15: minor 240: IRP_MJ_INTERNAL_DEVICE_CONTROL: type 0x6: fo 000000000
0000000
FFFFC389AA0E3040: dprintf: zfs_vnops_windows.c:7395:dispatcher(): dispatcher: en
ter: major 15: minor 240: IRP_MJ_INTERNAL_DEVICE_CONTROL: type 0x6: fo 000000000
0000000
FFFFC389AA0E3040: dprintf: zfs_vnops_windows.c:7395:dispatcher(): dispatcher: en
ter: major 15: minor 240: IRP_MJ_INTERNAL_DEVICE_CONTROL: type 0x6: fo 000000000
0000000
FFFFC389AA0E3040: dprintf: zfs_vnops_windows.c:7395:dispatcher(): dispatcher: en
ter: major 15: minor 240: IRP_MJ_INTERNAL_DEVICE_CONTROL: type 0x6: fo 000000000
0000000
FFFFC389AA0E3040: dprintf: zfs_vnops_windows.c:7395:dispatcher(): dispatcher: en
ter: major 27: minor 0: IRP_MJ_PNP(IRP_MN_START_DEVICE): type 0x6: fo 0000000000
000000
FFFFC389AA0E3040: dprintf: zfs_vnops_windows.c:7395:dispatcher(): dispatcher: en
ter: major 27: minor 8: IRP_MJ_PNP(IRP_MN_QUERY_INTERFACE): type 0x6: fo 0000000
000000000
FFFFC389AA0E3040: dprintf: zfs_vnops_windows.c:7395:dispatcher(): dispatcher: en
ter: major 27: minor 8: IRP_MJ_PNP(IRP_MN_QUERY_INTERFACE): type 0x6: fo 0000000
000000000
FFFFC389AA0E3040: dprintf: zfs_windows_zvol.c:187:wzvol_HwFindAdapter(): wzvol_H
wFindAdapter: entry
FFFFC389AA0E3040: dprintf: zfs_windows_zvol.c:205:wzvol_HwFindAdapter(): wzvol_H
wFindAdapter: pHBAExt = 0xFFFFC389AE238170, pConfigInfo = 0xFFFFC389BF49C2F8
FFFFC389AA0E3040: dprintf: zfs_windows_zvol.c:256:wzvol_HwFindAdapter(): wzvol_H
wFindAdapter: pHBAExt = 0xFFFFC389AE238170, NbBuses/MaxTargets/MaxLuns=1/13/31.
FFFFC389AA0E3040: dprintf: zfs_windows_zvol.c:795:wzvol_HwAdapterControl(): MpHw
AdapterControl:  ControlType = 0
FFFFC389AA0E3040: dprintf: zfs_windows_zvol.c:801:wzvol_HwAdapterControl(): MpHw
AdapterControl: ScsiQuerySupportedControlTypes
FFFFC389AA0E3040: dprintf: zfs_windows_zvol.c:848:wzvol_HwAdapterControl(): MpHw
AdapterControl - OUT
FFFFC389AA0E3040: dprintf: zfs_windows_zvol.c:170:wzvol_HwInitialize(): wzvol_Hw
Initialize: entry
FFFFC389AA0E3040: dprintf: zfs_vnops_windows.c:7395:dispatcher(): dispatcher: en
ter: major 14: minor 0: IRP_MJ_DEVICE_CONTROL: type 0x6: fo 0000000000000000
FFFFC389AA0E3040: dprintf: zfs_vnops_windows.c:7395:dispatcher(): dispatcher: en
ter: major 14: minor 0: IRP_MJ_DEVICE_CONTROL: type 0x6: fo 0000000000000000
-EB-

[lundman]

It is curious that HwFindAdapter() is called 6 times in a row, then we die. I wonder if that is normal

[guenther-alka]

Propably because I see 6 x OpenZFS controller in device manager Storage Volumes
(I asume a side effect of crashes during setup)

[lundman]

Oh that is interesting. I could do a version without zvol for you to try, would help narrow the problem down.

[lundman]

There is a OpenZFSOnWindows-debug-.99-147-g8629f178fd.exe which is rc5 with zvol code commented out.

[guenther-alka]

two points
I tried sort of a clean install

• rename zfs driver, reboot
• remove all 6 zfs entries in device manager storage volumes
• install rc5. That worked without crash

Now I see another problem with pool tank and zfs get all tank
It startet property listing and stops with an error
https://drive.google.com/file/d/1jyrDDXwJ4GVTnGpqERzNUVFLsEvNbHmW/view?usp=sharing

When I press retry, it shows the missing properties

When I retry a zfs get all tank, there are no properties returned.

[lundman]

OK so you can get it to work, by removing the multiple instances? No need to try -nozvol?
The -nozvol has the fix to stop the multiple entries as well, so in theory, that shouldn't happen again from that version onwards.

I'll take a look at the properties later, the BSOD is more important I think :)

[guenther-alka]

I tried if a zpool export/import may solve the problem but zpool export -f didn't work (pool remains imported), with any zfs commands like zfs get mounted without a return value.

btw.
Is there something like /etc/zfs/zpool.cache where ZFS remembers last configuration.
On Solaris I sometimes deleted that file on problems.

[lundman]

No not yet, there is no automatic import, you have to manually import (or set up automatic import).

[lundman]

But you are still not using -nozvol?

The "properties get" might be connected to fixing mimic, which is why you can't get properties including getting mount.

[guenther-alka]

I did an update from rc5 to newest ..8fd debug release
After setup it crashed with a BSOD and message "System thread exception not handled", see
https://drive.google.com/file/d/1euq1Q9u-S53rWJni5KkA7_UzdjPhTcc9/view?usp=sharing

I then imported my testpool and retried the pool export - still didn't work
zfs get all or get mounted did not work (no results)

I can set and get other zfs properties.

If I create a file and a snapshot, then delete the file, I am still not able to access the /pool/.zfs/snapshot/snap folder via Windows file explorer (does not open snap folder, explorer hangs/no return). I can access a snapshot folder only when empty.

[lundman]

That memory.dmp is from rc5, not the latest and does seem to die in the zvol init code.

[guenther-alka]

I have set windows_zvol_enabled to 1, rebooted and created a zvol
Is this ok?

[lundman]

OK, and reinstalling .f74 crashes, no crash?

[guenther-alka]

Reinstalling .f74 ended with a BSOD "Bad Pool Caller"
https://drive.google.com/file/d/1EcnHLUtQSRcyslFboyLTb85w5NwVZCpA/view?usp=sharing

btw
type filename | zfs load-key -L prompt tank/enc
worked. Echo on Windows has no options for newline suppress. Need to see what options I have from scripts without a temp file.

update: type filename worked but only under cmd, not with powershell, weird

[lundman]

Hmmm, so does reinstalling crash if windows_zvol_enabled is set to "0" ?

[lundman]

(after a reboot, the change does onto take effect on boot)

[guenther-alka]

I set zvol_enabled to 0, rebooted and restarted installer.
Setup went through without problem.

[lundman]

OK so - the issue does appear to be in zvol init code, but the changes I did for this version did not fix it.

No rush, with zvol_enabled at "1" and with a reinstall crash, can you send the mempry.dmp. But when convenient, I'm sure it is tedious to have to help debug.

[guenther-alka]

Should it be different from my above upload?

Reinstalling .f74 ended with a BSOD "Bad Pool Caller"
https://drive.google.com/file/d/1EcnHLUtQSRcyslFboyLTb85w5NwVZCpA/view?usp=sharing

[lundman]

OK that is interesting. The stack is

     : 00000000`000000c2 00000000`00000099 ffffb987`15a43360 00000000`00000000 : nt!KeBugCheckEx
     : ffffb987`15a43360 00000000`00000200 00000000`00000070 00000000`00000000 : nt!VerifierBugCheckIfAppropriate+0x14d
     : ffffb987`15a43350 00000000`00000000 00000000`00000200 00000000`00000001 : nt!VerifierFreeTrackedPool+0x41
     : 00000000`fffff807 ffffb987`0460b720 00000000`00000070 00000000`00000200 : nt!ExFreePoolWithTag+0xdd2
     : ffffb987`0460b938 ffffb987`0460b050 ffffb987`048be030 ffffb987`1c710010 : storport!RaidDeleteDeferredQueue+0x20
     : ffffb987`0460b1a0 ffffb987`0460b050 ffffb987`048be030 ffffb987`1c710010 : storport!RaidDeleteAdapter+0x12e
     : ffffb987`1c710010 00000000`00000002 00000000`00000000 ffffb987`09c821f8 : storport!RaidAdapterRemoveDeviceIrp+0x8e
     : 00000030`00000002 00000001`00000097 ffffb987`1c7101b8 fffff807`7d7252f5 : storport!RaidAdapterPnpIrp+0x16100
     : ffffb987`1c7101b8 ffffb987`1c710010 ffffb987`1c710010 ffffb987`00000004 : storport!RaDriverPnpIrp+0x94
     : 00000000`00040246 fffff807`7021cf2b ffffb987`0487dd78 ffffb987`00000000 : OpenZFS!dispatcher+0x313 [C:\src\openzfs\module\os\windows\zfs\zfs_vnops_windows.c @ 7429] 
     : ffffb987`0487dd80 ffffb987`01fead30 ffff3c93`00f0c566 ffffb987`04648e60 : nt!IofCallDriver+0x55
     : 00000000`00000000 ffffb987`0487dad0 ffffb987`04610030 ffffb987`048c0180 : ambakdrv+0x16da
     : ffffb987`1c710200 00000000`00000001 ffffb987`1c710010 ffffb987`0487dad0 : ambakdrv+0x15b4
     : ffffb987`0487dad0 00000000`00000001 ffffb987`1c710010 ffffb987`04610180 : ambakdrv+0x1478
     : ffffb987`0487dad0 00000000`00000001 ffffb987`1c710010 fffff807`7020d84a : nt!IofCallDriver+0x55
     : ffffb987`04610030 00000000`00000000 ffffc984`121475e0 ffffc984`12147504 : volsnap!VolSnapPnp+0xa3
     : ffffb987`04610030 00000000`00000000 ffffc984`121475e0 ffffb987`1c710010 : nt!IofCallDriver+0x55
     : 00000000`00000002 ffffb987`004e9df0 ffffb987`004d3aa0 ffffb987`004e9df0 : nt!IopSynchronousCall+0xf8
     : ffffa604`f53d3b30 ffffb987`004d3aa0 00000000`00000200 00000000`0000000a : nt!IopRemoveDevice+0x108
     : ffffb987`004e9df0 ffffb987`004d3aa0 00000000`00000000 cb3a4008`00200001 : nt!PnpRemoveLockedDeviceNode+0x1a8
     : ffffb987`004d3aa0 ffffc984`12147730 ffffb987`004e9df0 00000000`00000000 : nt!PnpDeleteLockedDeviceNode+0x52
     : ffffb987`004e9df0 00000000`00000002 ffffb987`004e9df0 00000000`00000000 : nt!PnpDeleteLockedDeviceNodes+0xd3
     : ffffc984`121478b0 ffffb987`004d3a00 ffffb987`1e6f5200 ffffa604`00000002 : nt!PnpProcessQueryRemoveAndEject+0x3b3
     : ffffa604`f53d3b30 ffffa604`f4310110 ffffb987`002aac00 00000000`00000000 : nt!PnpProcessTargetDeviceEvent+0x109
     : ffffb987`002aac00 ffffb987`1e25e0c0 ffffc984`12147a00 ffffb987`00000000 : nt!PnpDeviceEventWorker+0x2ca
     : ffffb987`1e25e0c0 00000000`0000054d ffffb987`1e25e0c0 fffff807`70353510 : nt!ExpWorkerThread+0x155
     : fffff807`6ab21180 ffffb987`1e25e0c0 fffff807`702ed700 badbad00`badbad00 : nt!PspSystemThreadStartup+0x57
     : ffffc984`12148000 ffffc984`12141000 00000000`00000000 00000000`00000000 : nt!KiStartSystemThread+0x34

And cbuf has

FFFFB9871E25E0C0: dprintf: zfs_vnops_windows.c:7395:dispatcher(): dispatcher: en
ter: major 27: minor 1: IRP_MJ_PNP(IRP_MN_QUERY_REMOVE_DEVICE): type 0x6: fo 0000000000000000
FFFFB9871E25E0C0: dprintf: zfs_vnops_windows.c:7395:dispatcher(): dispatcher: en
ter: major 27: minor 2: IRP_MJ_PNP(IRP_MN_REMOVE_DEVICE): type 0x6: fo 0000000000000000
FFFFB9871E25E0C0: dprintf: zfs_vnops_windows.c:7395:dispatcher(): dispatcher: en
ter: major 27: minor 2: IRP_MJ_PNP(IRP_MN_REMOVE_DEVICE): type 0x6: fo 0000000000000000
FFFFB9871E25E0C0: dprintf: zfs_windows_zvol.c:1104:wzvol_CompServReq(): MpHwCompServReq entered
FFFFB9871E25E0C0: dprintf: zfs_windows_zvol.c:1077:wzvol_QueueServiceIrp(): MpQueueServiceIrp entered
FFFFB9871E25E0C0: dprintf: zfs_windows_zvol.c:673:wzvol_HwHandlePnP(): wzvol_HwHandlePnP: entry
FFFFB9871DF05080: dprintf: txg.c:641:txg_quiesce_thread(): txg=1720 quiesce_txg=1721 sync_txg=1468
FFFFB9871DF05080: dprintf: txg.c:652:txg_quiesce_thread(): quiesce done, handing off txg 1720
FFFFB9871DF04080: dprintf: txg.c:588:txg_sync_thread(): txg=1720 quiesce_txg=1721 sync_txg=1468
FFFFB9871DF04080: dprintf: dbuf.c:3322:dbuf_create(): ds=mos obj=258 lvl=0 blkid=0 db=FFFFB9870999E6E8
FFFFB9871E25E0C0: dprintf: zfs_windows_zvol.c:808:wzvol_HwAdapterControl(): MpHwAdapterControl:  ControlType = 1
FFFFB9871E25E0C0: dprintf: zfs_windows_zvol.c:831:wzvol_HwAdapterControl(): MpHwAdapterControl:  ScsiStopAdapter
FFFFB9871E25E0C0: dprintf: zfs_windows_zvol.c:880:wzvol_StopAdapter(): wzvol_StopAdapter: entry
FFFFB9871E25E0C0: dprintf: zfs_windows_zvol.c:861:wzvol_HwAdapterControl(): MpHwAdapterControl - OUT
FFFFB9871E25E0C0: dprintf: zfs_windows_zvol.c:808:wzvol_HwAdapterControl(): MpHwAdapterControl:  ControlType = 3
FFFFB9871E25E0C0: dprintf: zfs_windows_zvol.c:846:wzvol_HwAdapterControl(): MpHwAdapterControl:  ScsiSetBootConfig
FFFFB9871E25E0C0: dprintf: zfs_windows_zvol.c:861:wzvol_HwAdapterControl(): MpHwAdapterControl - OUT
FFFFB9871E25E0C0: dprintf: zfs_windows_zvol.c:1002:wzvol_HwFreeAdapterResources(): MpHwFreeAdapterResources entered, pHBAExt = 0xFFFFB987045B7E30
-EB-

So some part comes along and tells ZFS to remove the zvol device/driver? ambakdrv (AOMEI) Perhaps I need code to ensure it really means us, or, we are sending along something to be freed which isn't allocated.
Which AOMEI software is that, wonder if I can install it to trigger the issue.

[guenther-alka]

Aomei Backupper Plus 7.3.4
with Aomei Backupper Schedule task service (32bit) running in the background

[lundman]

Thanks, I have that as well, although not on the debug VM - I will give it a go though

[lundman]

Ah yes - crashed on boot with AOMEI installed. It is completely random area, presumably because we return something we shouldn't.

[sskras]

What an interesting test case!

It also would be nice (even if tangent) to check if WinBtrfs alone is doing well with AOMEI driver running along.

[lundman]

Best guess is that we warm up as we get loaded, and they call about 6 functions probing us - so we perhaps reply incorrectly (not ready?) in one of those. I need to breakpoint those places and see what happens. Just trying to figure out how to breakpoint when it's not yet loaded :)

[lundman]

I'm on day three trying to debug this, it is a great mystery, but I can trigger it reliably

[guenther-alka]

Another problem with latest

I had problems with previous Open-ZFS builds and replication over netcat to/from Windows and errors like checksum error
but now zfs replication seems broken at all (on newest Windows 11 Pro)

PS C:\Users\me> zfs list -t snapshot
NAME USED AVAIL REFER MOUNTPOINT
tank@1 76K - 112K -
tank@2 80K - 116K -
tank/data@last 0B - 100K -

PS C:\Users\me> zfs list -t filesystem
NAME USED AVAIL REFER MOUNTPOINT
tank 453M 4.36G 172K /tank
tank/data 100K 3.92G 100K /tank/data
tank/data2 100K 3.92G 100K /tank/data2

PS C:\Users\me> zfs send tank/data@last | zfs receive -Fv tank/test1
11:58:55 312B tank/data@last
11:58:55 46.8K tank/data@last
cannot receive: invalid stream (bad magic number)

PS C:\Users\me> zfs --version
zfs-2.2.99-149-gf9ec771f74
zfs-kmod-zfs-2.2.99-149-gf9ec771f74

seems to happen at the end of the replication as there is some data transferred.

[lundman]

So no answer for Aomei per se, but trying a temporary work around for now. Can you check rc6 ?