Booting NT 4 disk causes /home/rjones/d/qemu/cpus.c:1580:qemu_mutex_lock_iothread: assertion failed: (!qemu_mutex_iothread_locked())

[Richard Jones]

Grab the NT 4 disk from https://archive.org/details/Microsoft_Windows_NT_Server_Version_4.0_227-075-385_CD-KEY_419-1343253_1996

Try to boot it as follows:

qemu-system-x86_64 -hda disk.img -cdrom Microsoft_Windows_NT_Server_Version_4.0_227-075-385_CD-KEY_419-1343253_1996.iso -m 2048 -boot d -machine pc,accel=tcg
WARNING: Image format was not specified for 'disk.img' and probing guessed raw.
         Automatically detecting the format is dangerous for raw images, write operations on block 0 will be restricted.
         Specify the 'raw' format explicitly to remove the restrictions.
**
ERROR:/home/rjones/d/qemu/cpus.c:1580:qemu_mutex_lock_iothread: assertion failed: (!qemu_mutex_iothread_locked())
Aborted (core dumped)

The stack trace in the failing thread is:

Thread 4 (Thread 0x7fffb0418700 (LWP 21979)):
#0 0x00007fffdd89b64b in raise () at /lib64/libc.so.6
#1 0x00007fffdd89d450 in abort () at /lib64/libc.so.6
#2 0x00007fffdff8c75d in g_assertion_message () at /lib64/libglib-2.0.so.0
#3 0x00007fffdff8c7ea in g_assertion_message_expr ()
    at /lib64/libglib-2.0.so.0
#4 0x00005555557a7d00 in qemu_mutex_lock_iothread ()
    at /home/rjones/d/qemu/cpus.c:1580
#5 0x00005555557cb429 in io_writex (env=env@entry=0x555556751400, iotlbentry=0x55555675b678,
    iotlbentry@entry=0x5aaaaae40c918, val=val@entry=8, addr=addr@entry=2148532220, retaddr=0, retaddr@entry=93825011136120, size=size@entry=4)
    at /home/rjones/d/qemu/accel/tcg/cputlb.c:795
#6 0x00005555557ce0f7 in io_writel (retaddr=93825011136120, addr=2148532220, val=8, index=255, mmu_idx=21845, env=0x555556751400)
    at /home/rjones/d/qemu/softmmu_template.h:265
#7 0x00005555557ce0f7 in helper_le_stl_mmu (env=env@entry=0x555556751400, addr=addr@entry=2148532220, val=val@entry=8, oi=<optimized out>, retaddr=93825011136120, retaddr@entry=0) at /home/rjones/d/qemu/softmmu_template.h:300
#8 0x000055555587c0a4 in cpu_stl_kernel_ra (env=0x555556751400, ptr=2148532220, v=8, retaddr=0) at /home/rjones/d/qemu/include/exec/cpu_ldst_template.h:182
#9 0x0000555555882610 in do_interrupt_protected (is_hw=<optimized out>, next_eip=<optimized out>, error_code=2, is_int=<optimized out>, intno=<optimized out>, env=0x555556751400) at /home/rjones/d/qemu/target/i386/seg_helper.c:758
#10 0x0000555555882610 in do_interrupt_all (cpu=cpu@entry=0x555556749170, intno=<optimized out>, is_int=<optimized out>, error_code=2, next_eip=<optimized out>, is_hw=is_hw@entry=0) at /home/rjones/d/qemu/target/i386/seg_helper.c:1252
#11 0x00005555558839d3 in x86_cpu_do_interrupt (cs=0x555556749170)
    at /home/rjones/d/qemu/target/i386/seg_helper.c:1298
#12 0x00005555557d2ccb in cpu_handle_exception (ret=<synthetic pointer>, cpu=0x5555566a4590) at /home/rjones/d/qemu/accel/tcg/cpu-exec.c:465
#13 0x00005555557d2ccb in cpu_exec (cpu=cpu@entry=0x555556749170)
    at /home/rjones/d/qemu/accel/tcg/cpu-exec.c:670
#14 0x00005555557a855a in tcg_cpu_exec (cpu=0x555556749170)
    at /home/rjones/d/qemu/cpus.c:1270
#15 0x00005555557a855a in qemu_tcg_rr_cpu_thread_fn (arg=<optimized out>)
    at /home/rjones/d/qemu/cpus.c:1365
#16 0x00007fffddc3d36d in start_thread () at /lib64/libpthread.so.0
#17 0x00007fffdd975b9f in clone () at /lib64/libc.so.6

[Alex Bennée (ajbennee)]

Thomas Huth <email address hidden> writes:

> On 25.07.2017 11:30, Richard Jones wrote:
>> ERROR:/home/rjones/d/qemu/cpus.c:1580:qemu_mutex_lock_iothread: assertion failed: (!qemu_mutex_iothread_locked())
>> Aborted (core dumped)
>>
>> The stack trace in the failing thread is:
>>
>> Thread 4 (Thread 0x7fffb0418700 (LWP 21979)):
>> #0 0x00007fffdd89b64b in raise () at /lib64/libc.so.6
>> #1 0x00007fffdd89d450 in abort () at /lib64/libc.so.6
>> #2 0x00007fffdff8c75d in g_assertion_message () at /lib64/libglib-2.0.so.0
>> #3 0x00007fffdff8c7ea in g_assertion_message_expr ()
>> at /lib64/libglib-2.0.so.0
>> #4 0x00005555557a7d00 in qemu_mutex_lock_iothread ()
>> at /home/rjones/d/qemu/cpus.c:1580
>> #5 0x00005555557cb429 in io_writex (env=env@entry=0x555556751400, iotlbentry=0x55555675b678,
>> iotlbentry@entry=0x5aaaaae40c918, val=val@entry=8, addr=addr@entry=2148532220, retaddr=0, retaddr@entry=93825011136120, size=size@entry=4)
>> at /home/rjones/d/qemu/accel/tcg/cputlb.c:795
>> #6 0x00005555557ce0f7 in io_writel (retaddr=93825011136120, addr=2148532220, val=8, index=255, mmu_idx=21845, env=0x555556751400)
>> at /home/rjones/d/qemu/softmmu_template.h:265
>> #7 0x00005555557ce0f7 in helper_le_stl_mmu (env=env@entry=0x555556751400, addr=addr@entry=2148532220, val=val@entry=8, oi=<optimized out>, retaddr=93825011136120, retaddr@entry=0) at /home/rjones/d/qemu/softmmu_template.h:300
>> #8 0x000055555587c0a4 in cpu_stl_kernel_ra (env=0x555556751400, ptr=2148532220, v=8, retaddr=0) at /home/rjones/d/qemu/include/exec/cpu_ldst_template.h:182
>> #9 0x0000555555882610 in do_interrupt_protected (is_hw=<optimized
>> out>, next_eip=<optimized out>, error_code=2, is_int=<optimized out>,
>> intno=<optimized out>, env=0x555556751400) at
>> /home/rjones/d/qemu/target/i386/seg_helper.c:758

Erm, what is happening here? I think the seg_helper is writing a stack
frame but for some reason to io memory, triggering the BQL. This just
seems weird.

>> #10 0x0000555555882610 in do_interrupt_all (cpu=cpu@entry=0x555556749170, intno=<optimized out>, is_int=<optimized out>, error_code=2, next_eip=<optimized out>, is_hw=is_hw@entry=0) at /home/rjones/d/qemu/target/i386/seg_helper.c:1252
>> #11 0x00005555558839d3 in x86_cpu_do_interrupt (cs=0x555556749170)
>> at /home/rjones/d/qemu/target/i386/seg_helper.c:1298
>> #12 0x00005555557d2ccb in cpu_handle_exception (ret=<synthetic pointer>, cpu=0x5555566a4590) at /home/rjones/d/qemu/accel/tcg/cpu-exec.c:465
>> #13 0x00005555557d2ccb in cpu_exec (cpu=cpu@entry=0x555556749170)
>> at /home/rjones/d/qemu/accel/tcg/cpu-exec.c:670
>> #14 0x00005555557a855a in tcg_cpu_exec (cpu=0x555556749170)
>> at /home/rjones/d/qemu/cpus.c:1270
>> #15 0x00005555557a855a in qemu_tcg_rr_cpu_thread_fn (arg=<optimized out>)
>> at /home/rjones/d/qemu/cpus.c:1365
>> #16 0x00007fffddc3d36d in start_thread () at /lib64/libpthread.so.0
>> #17 0x00007fffdd975b9f in clone () at /lib64/libc.so.6
>
> Looks like the iothread lock is taken twice here, one time in
> accel/tcg/cpu-exec.c around line 465 and one time in
> accel/tcg/cputlb.c:795 again.
>
> If I've get that right, the locks have been added by this commit here...

[Peter Maydell (pmaydell)]

On 25 July 2017 at 15:54, Alex Bennée <email address hidden> wrote:
>
> Thomas Huth <email address hidden> writes:
>
>> On 25.07.2017 11:30, Richard Jones wrote:
>>> ERROR:/home/rjones/d/qemu/cpus.c:1580:qemu_mutex_lock_iothread: assertion failed: (!qemu_mutex_iothread_locked())
>>> Aborted (core dumped)
>>>
>>> The stack trace in the failing thread is:
>>>
>>> Thread 4 (Thread 0x7fffb0418700 (LWP 21979)):
>>> #0 0x00007fffdd89b64b in raise () at /lib64/libc.so.6
>>> #1 0x00007fffdd89d450 in abort () at /lib64/libc.so.6
>>> #2 0x00007fffdff8c75d in g_assertion_message () at /lib64/libglib-2.0.so.0
>>> #3 0x00007fffdff8c7ea in g_assertion_message_expr ()
>>> at /lib64/libglib-2.0.so.0
>>> #4 0x00005555557a7d00 in qemu_mutex_lock_iothread ()
>>> at /home/rjones/d/qemu/cpus.c:1580
>>> #5 0x00005555557cb429 in io_writex (env=env@entry=0x555556751400, iotlbentry=0x55555675b678,
>>> iotlbentry@entry=0x5aaaaae40c918, val=val@entry=8, addr=addr@entry=2148532220, retaddr=0, retaddr@entry=93825011136120, size=size@entry=4)
>>> at /home/rjones/d/qemu/accel/tcg/cputlb.c:795
>>> #6 0x00005555557ce0f7 in io_writel (retaddr=93825011136120, addr=2148532220, val=8, index=255, mmu_idx=21845, env=0x555556751400)
>>> at /home/rjones/d/qemu/softmmu_template.h:265
>>> #7 0x00005555557ce0f7 in helper_le_stl_mmu (env=env@entry=0x555556751400, addr=addr@entry=2148532220, val=val@entry=8, oi=<optimized out>, retaddr=93825011136120, retaddr@entry=0) at /home/rjones/d/qemu/softmmu_template.h:300
>>> #8 0x000055555587c0a4 in cpu_stl_kernel_ra (env=0x555556751400, ptr=2148532220, v=8, retaddr=0) at /home/rjones/d/qemu/include/exec/cpu_ldst_template.h:182
>>> #9 0x0000555555882610 in do_interrupt_protected (is_hw=<optimized
>>> out>, next_eip=<optimized out>, error_code=2, is_int=<optimized out>,
>>> intno=<optimized out>, env=0x555556751400) at
>>> /home/rjones/d/qemu/target/i386/seg_helper.c:758
>
> Erm, what is happening here? I think the seg_helper is writing a stack
> frame but for some reason to io memory, triggering the BQL. This just
> seems weird.

Even if this happens because the guest is going haywire,
if the guest can provoke it then we need to handle it
without asserting...

thanks
-- PMM

[Dr. David Alan Gilbert (dgilbert-h)]

* Alex Bennée (<email address hidden>) wrote:
>
> Thomas Huth <email address hidden> writes:
>
> > On 25.07.2017 11:30, Richard Jones wrote:
> >> ERROR:/home/rjones/d/qemu/cpus.c:1580:qemu_mutex_lock_iothread: assertion failed: (!qemu_mutex_iothread_locked())
> >> Aborted (core dumped)
> >>
> >> The stack trace in the failing thread is:
> >>
> >> Thread 4 (Thread 0x7fffb0418700 (LWP 21979)):
> >> #0 0x00007fffdd89b64b in raise () at /lib64/libc.so.6
> >> #1 0x00007fffdd89d450 in abort () at /lib64/libc.so.6
> >> #2 0x00007fffdff8c75d in g_assertion_message () at /lib64/libglib-2.0.so.0
> >> #3 0x00007fffdff8c7ea in g_assertion_message_expr ()
> >> at /lib64/libglib-2.0.so.0
> >> #4 0x00005555557a7d00 in qemu_mutex_lock_iothread ()
> >> at /home/rjones/d/qemu/cpus.c:1580
> >> #5 0x00005555557cb429 in io_writex (env=env@entry=0x555556751400, iotlbentry=0x55555675b678,
> >> iotlbentry@entry=0x5aaaaae40c918, val=val@entry=8, addr=addr@entry=2148532220, retaddr=0, retaddr@entry=93825011136120, size=size@entry=4)
> >> at /home/rjones/d/qemu/accel/tcg/cputlb.c:795
> >> #6 0x00005555557ce0f7 in io_writel (retaddr=93825011136120, addr=2148532220, val=8, index=255, mmu_idx=21845, env=0x555556751400)
> >> at /home/rjones/d/qemu/softmmu_template.h:265
> >> #7 0x00005555557ce0f7 in helper_le_stl_mmu (env=env@entry=0x555556751400, addr=addr@entry=2148532220, val=val@entry=8, oi=<optimized out>, retaddr=93825011136120, retaddr@entry=0) at /home/rjones/d/qemu/softmmu_template.h:300
> >> #8 0x000055555587c0a4 in cpu_stl_kernel_ra (env=0x555556751400, ptr=2148532220, v=8, retaddr=0) at /home/rjones/d/qemu/include/exec/cpu_ldst_template.h:182
> >> #9 0x0000555555882610 in do_interrupt_protected (is_hw=<optimized
> >> out>, next_eip=<optimized out>, error_code=2, is_int=<optimized out>,
> >> intno=<optimized out>, env=0x555556751400) at
> >> /home/rjones/d/qemu/target/i386/seg_helper.c:758
>
> Erm, what is happening here? I think the seg_helper is writing a stack
> frame but for some reason to io memory, triggering the BQL. This just
> seems weird.

addr=2148532220 doesn't seem fun; that's 800FFFFC maybe a missing mask
somewhere?
(or cpu in completely the wrong mode).

Dave

>
> >> #10 0x0000555555882610 in do_interrupt_all (cpu=cpu@entry=0x555556749170, intno=<optimized out>, is_int=<optimized out>, error_code=2, next_eip=<optimized out>, is_hw=is_hw@entry=0) at /home/rjones/d/qemu/target/i386/seg_helper.c:1252
> >> #11 0x00005555558839d3 in x86_cpu_do_interrupt (cs=0x555556749170)
> >> at /home/rjones/d/qemu/target/i386/seg_helper.c:1298
> >> #12 0x00005555557d2ccb in cpu_handle_exception (ret=<synthetic pointer>, cpu=0x5555566a4590) at /home/rjones/d/qemu/accel/tcg/cpu-exec.c:465
> >> #13 0x00005555557d2ccb in cpu_exec (cpu=cpu@entry=0x555556749170)
> >> at /home/rjones/d/qemu/accel/tcg/cpu-exec.c:670
> >> #14 0x00005555557a855a in tcg_cpu_exec (cpu=0x555556749170)
> >> at /home/rjones/d/qemu/cpus.c:1270
> >> #15 0x00005555557a855a in qemu_tcg_rr_cpu_thread_fn (arg=<optimized out>)
> >> at /home/rjones/d/qemu/cpus.c:1365
> >> #16 0x00007fffddc3d36d in start_thread () at /lib64/libpthread.so.0
> >> #17 0x00007fffdd...

[Paolo Bonzini (bonzini)]

There are three possibilities:

1) push qemu_mutex_lock_iothread down to cc->do_interrupt

2) change the condition in io_readx/io_writex to mr->global_locking && !qemu_mutex_iothread_locked()

3) both

We can do (2) for 2.10 and later ponder on doing the first.

[John Arbuckle (programmingkidx)]

Using '-cpu 486' gets past the assertion error. I guess Windows NT 4.0 is not compatible with newer Intel processors.

Currently I can install Windows NT 4.0, but booting from the installation has its problems. It won't boot unless you use the NTFS file system. Even with this file system I still see a BSOD that states INACCESSIBLE_BOOT_DEVICE. Not sure what is wrong. Switching to a SCSI controller didn't help.

[John Arbuckle (programmingkidx)]

If you forget to add -cpu 486 or -cpu pentium your disk image will be corrupted and the display will display random characters.

[John Arbuckle (programmingkidx)]

This workaround should help you avoid problems with Windows NT 4.0.

Create the disk image for the hard drive that is 4GB or less in size:
qemu-img create -f qcow2 <HD image file name>.qcow2 4G

Run QEMU booting from the CD-ROM. I assume you used the Windows NT 4.0 workstation CD.
qemu-system-i386 -cpu pentium -vga cirrus -hda <HD image file name>.qcow2 -cdrom <path to iso> -boot c

Note: I used QEMU 2.10 RC3, Commit 1f296733876434118fd766cfef5eb6f29ecab6a8. I know the boot arguments says it will boot from the hard drive but it will still work. The BIOS will see the hard drive can't be booted and will look for another boot device. After the initial install of Windows NT 4.0 you will be required to reboot to continue with more installation. The above command-line allows you to continue with installation without having to quit QEMU. If you choose to use an older version of QEMU you may run into more problems. For example under QEMU 2.8.0 Windows NT 4.0 will think the hard drive is twice the size it really is. This will lead to an unbootable installation.

[Alex Bennée (ajbennee)]

John Arbuckle <email address hidden> writes:

> Using '-cpu 486' gets past the assertion error. I guess Windows NT 4.0
> is not compatible with newer Intel processors.

It might be related. The assertion error is caused by the fact an
exception has occurred and processor is trying to dump a stack frame that
overlaps from RAM into device memory. As the IRQ/exception handling is
already under the BQL (as it changes machine state) we get the assertion
when it tries to take the BQL a second time when accessing device
memory.

We can drop the lock in the stack frame writing code but I don't know
what effect that would have as the guest still might crash having tried
to write a stack frame to device memory....

>
> Currently I can install Windows NT 4.0, but booting from the
> installation has its problems. It won't boot unless you use the NTFS
> file system. Even with this file system I still see a BSOD that states
> INACCESSIBLE_BOOT_DEVICE. Not sure what is wrong. Switching to a SCSI
> controller didn't help.

--
Alex Bennée

[Peter Maydell (pmaydell)]

On 18 August 2017 at 09:40, Alex Bennée <email address hidden> wrote:
>
> John Arbuckle <email address hidden> writes:
>
>> Using '-cpu 486' gets past the assertion error. I guess Windows NT 4.0
>> is not compatible with newer Intel processors.
>
> It might be related. The assertion error is caused by the fact an
> exception has occurred and processor is trying to dump a stack frame that
> overlaps from RAM into device memory. As the IRQ/exception handling is
> already under the BQL (as it changes machine state) we get the assertion
> when it tries to take the BQL a second time when accessing device
> memory.

This sounds worrying -- lots and lots of target backend code
does writes to memory. Is it all going to cause assertions if
it happens to be pointing at a device?

thanks
-- PMM

[Alex Bennée (ajbennee)]

Peter Maydell <email address hidden> writes:

> On 18 August 2017 at 09:40, Alex Bennée <email address hidden> wrote:
>>
>> John Arbuckle <email address hidden> writes:
>>
>>> Using '-cpu 486' gets past the assertion error. I guess Windows NT 4.0
>>> is not compatible with newer Intel processors.
>>
>> It might be related. The assertion error is caused by the fact an
>> exception has occurred and processor is trying to dump a stack frame that
>> overlaps from RAM into device memory. As the IRQ/exception handling is
>> already under the BQL (as it changes machine state) we get the assertion
>> when it tries to take the BQL a second time when accessing device
>> memory.
>
> This sounds worrying -- lots and lots of target backend code
> does writes to memory. Is it all going to cause assertions if
> it happens to be pointing at a device?

Currently yes.

That said from John's update it sounds very much like a symptom of not
emulating the right processor type rather than behaviour we are
incorrectly modelling. If we invert the lock before writing the stack
page is it just going to crash in a more esoteric way?

I'm not sure how you correctly emulate writing random stack pages to a
random device. Unless there is some sort of weird [un]documented behaviour
we should be doing?

--
Alex Bennée

[Peter Maydell (pmaydell)]

On 18 August 2017 at 11:23, Alex Bennée <email address hidden> wrote:
> Peter Maydell <email address hidden> writes:
>> On 18 August 2017 at 09:40, Alex Bennée <email address hidden> wrote:
>>> It might be related. The assertion error is caused by the fact an
>>> exception has occurred and processor is trying to dump a stack frame that
>>> overlaps from RAM into device memory. As the IRQ/exception handling is
>>> already under the BQL (as it changes machine state) we get the assertion
>>> when it tries to take the BQL a second time when accessing device
>>> memory.
>>
>> This sounds worrying -- lots and lots of target backend code
>> does writes to memory. Is it all going to cause assertions if
>> it happens to be pointing at a device?
>
> Currently yes.
>
> That said from John's update it sounds very much like a symptom of not
> emulating the right processor type rather than behaviour we are
> incorrectly modelling. If we invert the lock before writing the stack
> page is it just going to crash in a more esoteric way?
>
> I'm not sure how you correctly emulate writing random stack pages to a
> random device. Unless there is some sort of weird [un]documented behaviour
> we should be doing?

The desired behaviour is straightforward -- if the code calls
a function for "do a 4 byte write" then we do a 4 byte write
to the device. The only place where writing to a device has
to be special cased is when we're trying to execute code
from it (which is itself arguably a defect of our emulation).

It looks like we only get this double locking when the
target/ code does a write-by-virtual-address (which ends
up going via io_writex() which takes the lock again) --
write-by-physical-address, eg stl_phys and friends presumably
don't take the lock. That's a rather confusing mismatch of
semantics.

thanks
-- PMM

[Richard Jones (rjones-redhat)]

On Fri, Aug 18, 2017 at 10:23:25AM -0000, Alex Bennée wrote:
> That said from John's update it sounds very much like a symptom of not
> emulating the right processor type rather than behaviour we are
> incorrectly modelling.

FWIW I checked back with the original specs, and NT 4.0 minimally
required a Pentium processor (and 16 MB of RAM :-)

Rich.

--
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
virt-df lists disk usage of guests without needing to install any
software inside the virtual machine. Supports Linux and Windows.
http://people.redhat.com/~rjones/virt-df/

[Peter Maydell (pmaydell)]

On 18 August 2017 at 11:23, Alex Bennée <email address hidden> wrote:
> If we invert the lock before writing the stack
> page is it just going to crash in a more esoteric way?

Paolo suggested a straightforward fix for 2.10 (which we unfortunately
never did :-() which we could use to check this theory.

thanks
-- PMM

[John Arbuckle (programmingkidx)]

Actually Windows NT 4.0 requires a 486 or higher. https://en.wikipedia.org/wiki/Windows_NT

Found out that the qcow2 image format causes INACCESSIBLE_BOOT_DEVICE errors with Windows NT 4.0, so I am going to update my workaround to use the qcow format instead.

qemu-img create -f qcow <HD image file name>.qcow 4G

qemu-system-i386 -cpu pentium -vga cirrus -hda <HD image file name>.qcow -cdrom <path to iso> -boot c

[Thomas Huth (th-huth)]

Was this ever fixed in QEMU, or can the issue still be reproduced in the latest version?

[Peter Maydell (pmaydell)]

commit 8b81253332b5a3f claims in its subject line that it "fixes #1706296", and it implements Paolo's option (2) from comment #4. So I'd go with "already fixed". The bug has a simple reproducer in the report though, so it's also easy to test...

[Peter Maydell (pmaydell)]

With the original repro command line, the guest now crashes "cleanly", ie without triggering a QEMU assert. If you give the guest a CPU type it recognizes, eg '-cpu pentium' (as noted in comment 7) then it boots OK, at least to the point of user control in the installer. So I think this is fixed.