Hello, it's time for my periodical rant about debug log mess again. The example below is made using latest VirtualBox 3.
Suggestions and questions:
1. usbohci - it's left on intentionally to better aid debugging? Allright, however I think these lines (/srv/buildbot_cmake/full_cmake/build/drivers/usb/usbohci/hardware.cpp:1199) Waiting 0 milliseconds for port power up (/srv/buildbot_cmake/full_cmake/build/drivers/usb/usbohci/hardware.cpp:1145) Enabling status change repeated 8 times is a little bit too much.
Same about libusb listing statuses of all ports. Which goes on yet another time with EHCI controller.
2. What are these lines? Repeated 14 times (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/mm/ARM3/sysldr.c:2959) ZwOpenFile failed with status 0xc000003a
3. What happened to the floppy driver? (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c:1579) '\Driver\FLOPPY' initialization failed, status (0xc000000e) (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c:61) Deleting driver object '\Driver\FLOPPY' (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c:87) HACK: Not unloading the driver image due to critical bugs! (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c:1961) IopInitializeDriver() failed (Status c000000e) (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/mm/ARM3/sysldr.c:935) Leaking driver: floppy.sys
Fix it? Don't enable it in trunk builds if it's buggy and not fixed?
4. These lines repeated 20 times. (/srv/buildbot_cmake/full_cmake/build/dll/ntdll/ldr/ldrapi.c:811) NtCreateSection() failed (Status 0xc0000022). Why creating section in LdrpVerifyImageMatchesChecksum() failes now?
5. Win32 stage. (/srv/buildbot_cmake/full_cmake/build/win32ss/user/ntuser/winsta.c:208) err: Invalid window station handle (/srv/buildbot_cmake/full_cmake/build/win32ss/user/ntuser/ntuser.c:161) err: Enter NtUserInitialize(0, 00000000, 00000000) (/srv/buildbot_cmake/full_cmake/build/win32ss/user/ntuser/display.c:79) err: InitDisplayDriver (\Device\Video0, \Registry\Machine\System\CurrentControlSet\Hardware Profiles\Current\System\CurrentControlSet\Services\VBE\Device0);
What happens here? It's a normal bootup, everyone should see this. Why is invalid window station handle being passed, why do we need NtUserInitialize to produce ERR debug print, along with InitDisplayDriver. Are those errors? If not, then why the hell are they being printed? If yes, then I don't see any info about actual errors.
6. (/srv/buildbot_cmake/full_cmake/build/win32ss/user/ntuser/window.c:2416) err: DestroyWindow AOW AOW? ORLY?
7. MASSIVE portcls spam. I won't even count lines. (/srv/buildbot_cmake/full_cmake/build/drivers/wdm/audio/backpln/portcls/undoc.cpp:281) Calling Node 16 MajorTarget B01EF750 MinorTarget 00000000 PropertySet {45ffaaa0-6e1b-11d0-bcf2-444553540000} PropertyId 4 PropertyFlags 10000200 InstanceSize 0 ValueSize 40 Handler FB24E58A PropertyRequest FF55B5F8 PropertyItemFlags 203 PropertyItemId 4 A few pages of that stuff. Is it really useful for everyone, including automated testing systems?
8. A work queue deadlock. Not a good thing at all (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/ex/work.c:351) EX: Work Queue Deadlock detected: 1 (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/ex/work.c:353) Dynamic threads queued 2
9. ???
All that resulted from my desire to just compare logs attached to the bug report. New log is totally unreadable, I had to spend time figuring out where actually that Live Essentials app was started, what problems it shows, etc.
Best regards, Aleksey.
*disables debug logging*
"Hey aleksey, I fixed it!" On Jun 6, 2012 1:46 PM, "Aleksey Bragin" aleksey@reactos.org wrote:
Hello, it's time for my periodical rant about debug log mess again. The example below is made using latest VirtualBox 3.
Suggestions and questions:
- usbohci - it's left on intentionally to better aid debugging?
Allright, however I think these lines (/srv/buildbot_cmake/full_**cmake/build/drivers/usb/**usbohci/hardware.cpp:1199) Waiting 0 milliseconds for port power up (/srv/buildbot_cmake/full_** cmake/build/drivers/usb/**usbohci/hardware.cpp:1145) Enabling status change repeated 8 times is a little bit too much.
Same about libusb listing statuses of all ports. Which goes on yet another time with EHCI controller.
- What are these lines? Repeated 14 times
(/srv/buildbot_cmake/full_**cmake/build/ntoskrnl/mm/ARM3/**sysldr.c:2959) ZwOpenFile failed with status 0xc000003a
- What happened to the floppy driver?
(/srv/buildbot_cmake/full_**cmake/build/ntoskrnl/io/iomgr/**driver.c:1579) '\Driver\FLOPPY' initialization failed, status (0xc000000e) (/srv/buildbot_cmake/full_**cmake/build/ntoskrnl/io/iomgr/**driver.c:61) Deleting driver object '\Driver\FLOPPY' (/srv/buildbot_cmake/full_**cmake/build/ntoskrnl/io/iomgr/**driver.c:87) HACK: Not unloading the driver image due to critical bugs! (/srv/buildbot_cmake/full_**cmake/build/ntoskrnl/io/iomgr/**driver.c:1961) IopInitializeDriver() failed (Status c000000e) (/srv/buildbot_cmake/full_**cmake/build/ntoskrnl/mm/ARM3/**sysldr.c:935) Leaking driver: floppy.sys
Fix it? Don't enable it in trunk builds if it's buggy and not fixed?
- These lines repeated 20 times.
(/srv/buildbot_cmake/full_**cmake/build/dll/ntdll/ldr/**ldrapi.c:811) NtCreateSection() failed (Status 0xc0000022). Why creating section in LdrpVerifyImageMatchesChecksum**() failes now?
- Win32 stage.
(/srv/buildbot_cmake/full_**cmake/build/win32ss/user/**ntuser/winsta.c:208) err: Invalid window station handle (/srv/buildbot_cmake/full_**cmake/build/win32ss/user/**ntuser/ntuser.c:161) err: Enter NtUserInitialize(0, 00000000, 00000000) (/srv/buildbot_cmake/full_**cmake/build/win32ss/user/**ntuser/display.c:79) err: InitDisplayDriver (\Device\Video0, \Registry\Machine\System**CurrentControlSet\Hardware Profiles\Current\System**CurrentControlSet\Services**VBE\Device0);
What happens here? It's a normal bootup, everyone should see this. Why is invalid window station handle being passed, why do we need NtUserInitialize to produce ERR debug print, along with InitDisplayDriver. Are those errors? If not, then why the hell are they being printed? If yes, then I don't see any info about actual errors.
- (/srv/buildbot_cmake/full_**cmake/build/win32ss/user/**ntuser/window.c:2416)
err: DestroyWindow AOW AOW? ORLY?
- MASSIVE portcls spam. I won't even count lines.
(/srv/buildbot_cmake/full_**cmake/build/drivers/wdm/audio/**backpln/portcls/undoc.cpp:281) Calling Node 16 MajorTarget B01EF750 MinorTarget 00000000 PropertySet {45ffaaa0-6e1b-11d0-bcf2-**444553540000} PropertyId 4 PropertyFlags 10000200 InstanceSize 0 ValueSize 40 Handler FB24E58A PropertyRequest FF55B5F8 PropertyItemFlags 203 PropertyItemId 4 A few pages of that stuff. Is it really useful for everyone, including automated testing systems?
- A work queue deadlock. Not a good thing at all
(/srv/buildbot_cmake/full_**cmake/build/ntoskrnl/ex/work.**c:351) EX: Work Queue Deadlock detected: 1 (/srv/buildbot_cmake/full_** cmake/build/ntoskrnl/ex/work.**c:353) Dynamic threads queued 2
- ???
All that resulted from my desire to just compare logs attached to the bug report. New log is totally unreadable, I had to spend time figuring out where actually that Live Essentials app was started, what problems it shows, etc.
Best regards, Aleksey.
______________________________**_________________ Ros-dev mailing list Ros-dev@reactos.org http://www.reactos.org/**mailman/listinfo/ros-devhttp://www.reactos.org/mailman/listinfo/ros-dev
Kind regards, Sylvain Petreolle
De : Aleksey Bragin aleksey@reactos.org À : ReactOS Development List ros-dev@reactos.org Envoyé le : Mercredi 6 juin 2012 14h45 Objet : [ros-dev] Debug log problems
Hello, it's time for my periodical rant about debug log mess again. The example below is made using latest VirtualBox 3.
- What happened to the floppy driver?
(/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c:1579) '\Driver\FLOPPY' initialization failed, status (0xc000000e) (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c:61) Deleting driver object '\Driver\FLOPPY' (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c:87) HACK: Not unloading the driver image due to critical bugs! (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c:1961) IopInitializeDriver() failed (Status c000000e) (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/mm/ARM3/sysldr.c:935) Leaking driver: floppy.sys
Fix it? Don't enable it in trunk builds if it's buggy and not fixed?
All that resulted from my desire to just compare logs attached to the bug report. New log is totally unreadable, I had to spend time figuring out where actually that Live Essentials app was started, what problems it shows, etc.
Best regards, Aleksey.
Ros-dev mailing list Ros-dev@reactos.org http://www.reactos.org/mailman/listinfo/ros-dev
Works fine on VBox 4.1.16?
We kinda dont support Vbox 3 as its... old and having problems with com output?
On Wed, Jun 6, 2012, at 03:57 PM, Sylvain Petreolle wrote:
Kind regards, Sylvain Petreolle ____________________________________________________________
De : Aleksey Bragin aleksey@reactos.org À : ReactOS Development List ros-dev@reactos.org Envoyé le : Mercredi 6 juin 2012 14h45 Objet : [ros-dev] Debug log problems
Hello, it's time for my periodical rant about debug log mess again. The example below is made using latest VirtualBox 3.
3. What happened to the floppy driver? (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c: 1579) '\Driver\FLOPPY' initialization failed, status (0xc000000e) (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c: 61) Deleting driver object '\Driver\FLOPPY' (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c: 87) HACK: Not unloading the driver image due to critical bugs! (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c: 1961) IopInitializeDriver() failed (Status c000000e) (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/mm/ARM3/sysldr.c:9 35) Leaking driver: floppy.sys
Fix it? Don't enable it in trunk builds if it's buggy and not fixed?
All that resulted from my desire to just compare logs attached to the bug report. New log is totally unreadable, I had to spend time figuring out where actually that Live Essentials app was started, what problems it shows, etc. Best regards, Aleksey. _______________________________________________ Ros-dev mailing list [1]Ros-dev@reactos.org [2]http://www.reactos.org/mailman/listinfo/ros-dev
_______________________________________________
Ros-dev mailing list
[3]Ros-dev@reactos.org
[4]http://www.reactos.org/mailman/listinfo/ros-dev
--
With best regards
Caemyr
References
1. mailto:Ros-dev@reactos.org 2. http://www.reactos.org/mailman/listinfo/ros-dev 3. mailto:Ros-dev@reactos.org 4. http://www.reactos.org/mailman/listinfo/ros-dev
VBox 4.0.x was indeed broken, but 4.1.x is a lot better. It also is able to use extended CPU virtualisation functions, present from Nehalem upwards, thus its running on windows testbot.
On Thu, Jun 7, 2012, at 09:46 AM, Александр wrote:
07.06.2012, 01:53, "caemyr@myopera.com" caemyr@myopera.com:
Works fine on VBox 4.1.16?
We kinda dont support Vbox 3 as its... old and having problems with com output?
W00T?!
I used to be told by a lot of devs that Vbox 4 is buggy suxx, and VirtualBox 3.2.14 is a better one. So where is the truth?
On Wed, Jun 6, 2012, at 03:57 PM, Sylvain Petreolle wrote:
Kind regards, Sylvain Petreolle ____________________________________________________________
De : Aleksey Bragin <[1]aleksey@reactos.org> À : ReactOS Development List <[2]ros-dev@reactos.org> Envoyé le : Mercredi 6 juin 2012 14h45 Objet : [ros-dev] Debug log problems
--
With best regards
Caemyr
_______________________________________________
Ros-dev mailing list
[3]Ros-dev@reactos.org
[4]http://www.reactos.org/mailman/listinfo/ros-dev
--
С наилучшими пожеланиями, Александр.
_______________________________________________
Ros-dev mailing list
[5]Ros-dev@reactos.org
[6]http://www.reactos.org/mailman/listinfo/ros-dev
--
With best regards
Caemyr
References
1. mailto:aleksey@reactos.org 2. mailto:ros-dev@reactos.org 3. mailto:Ros-dev@reactos.org 4. http://www.reactos.org/mailman/listinfo/ros-dev 5. mailto:Ros-dev@reactos.org 6. http://www.reactos.org/mailman/listinfo/ros-dev
You don't have a floppy drive attached to your VM, do you ? Except the HACK thing this is the normal output when a device isn't there.
Kind regards, Sylvain Petreolle
De : Aleksey Bragin aleksey@reactos.org À : ReactOS Development List ros-dev@reactos.org Envoyé le : Mercredi 6 juin 2012 14h45 Objet : [ros-dev] Debug log problems
- What happened to the floppy driver?
(/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c:1579) '\Driver\FLOPPY' initialization failed, status (0xc000000e) (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c:61) Deleting driver object '\Driver\FLOPPY' (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c:87) HACK: Not unloading the driver image due to critical bugs! (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c:1961) IopInitializeDriver() failed (Status c000000e) (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/mm/ARM3/sysldr.c:935) Leaking driver: floppy.sys
Fix it? Don't enable it in trunk builds if it's buggy and not fixed?
Best regards,
Aleksey.
Maybe I can shed some light on the situation.
On Jun 6, 2012, at 5:45 AM, Aleksey Bragin wrote:
Hello, it's time for my periodical rant about debug log mess again. The example below is made using latest VirtualBox 3.
Suggestions and questions:
- usbohci - it's left on intentionally to better aid debugging?
Allright, however I think these lines (/srv/buildbot_cmake/full_cmake/build/drivers/usb/usbohci/hardware.cpp:1199) Waiting 0 milliseconds for port power up (/srv/buildbot_cmake/full_cmake/build/drivers/usb/usbohci/hardware.cpp:1145) Enabling status change repeated 8 times is a little bit too much.
Same about libusb listing statuses of all ports. Which goes on yet another time with EHCI controller.
We can turn these off but we'll be losing potentially valuable debugging information on systems with USB that we don't initialize correctly.
- What are these lines? Repeated 14 times
(/srv/buildbot_cmake/full_cmake/build/ntoskrnl/mm/ARM3/sysldr.c:2959) ZwOpenFile failed with status 0xc000003a
These are generated because in stage 0, the kernel tries to load drivers for child devices of the bus devices listed in the CriticalDeviceDatabase which is correct behavior. If the service is not marked boot start (and thus loaded by the boot loader), it will generate this error since the I/O subsystem isn't up until stage 1 where enumerating is repeated, properly loading the drivers.
- What happened to the floppy driver?
(/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c:1579) '\Driver\FLOPPY' initialization failed, status (0xc000000e) (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c:61) Deleting driver object '\Driver\FLOPPY' (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c:87) HACK: Not unloading the driver image due to critical bugs! (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c:1961) IopInitializeDriver() failed (Status c000000e) (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/mm/ARM3/sysldr.c:935) Leaking driver: floppy.sys
Fix it? Don't enable it in trunk builds if it's buggy and not fixed?
That's correct behavior. Failing DriverEntry makes the driver immediately unload. This is broken due to some incorrect memory typing in FreeLoader which results in invalid loader entries for boot start drivers after stage 1, which is why we currently act very cautiously and don't unload to avoid reading invalid memory. This isn't actually a broken case, but we don't unload anyway because we have no nice way of knowing whether our LDR entries are valid or not.
- These lines repeated 20 times.
(/srv/buildbot_cmake/full_cmake/build/dll/ntdll/ldr/ldrapi.c:811) NtCreateSection() failed (Status 0xc0000022). Why creating section in LdrpVerifyImageMatchesChecksum() failes now?
- Win32 stage.
(/srv/buildbot_cmake/full_cmake/build/win32ss/user/ntuser/winsta.c:208) err: Invalid window station handle (/srv/buildbot_cmake/full_cmake/build/win32ss/user/ntuser/ntuser.c:161) err: Enter NtUserInitialize(0, 00000000, 00000000) (/srv/buildbot_cmake/full_cmake/build/win32ss/user/ntuser/display.c:79) err: InitDisplayDriver (\Device\Video0, \Registry\Machine\System\CurrentControlSet\Hardware Profiles\Current\System\CurrentControlSet\Services\VBE\Device0);
What happens here? It's a normal bootup, everyone should see this. Why is invalid window station handle being passed, why do we need NtUserInitialize to produce ERR debug print, along with InitDisplayDriver. Are those errors? If not, then why the hell are they being printed? If yes, then I don't see any info about actual errors.
- (/srv/buildbot_cmake/full_cmake/build/win32ss/user/ntuser/window.c:2416) err: DestroyWindow AOW
AOW? ORLY?
- MASSIVE portcls spam. I won't even count lines.
(/srv/buildbot_cmake/full_cmake/build/drivers/wdm/audio/backpln/portcls/undoc.cpp:281) Calling Node 16 MajorTarget B01EF750 MinorTarget 00000000 PropertySet {45ffaaa0-6e1b-11d0-bcf2-444553540000} PropertyId 4 PropertyFlags 10000200 InstanceSize 0 ValueSize 40 Handler FB24E58A PropertyRequest FF55B5F8 PropertyItemFlags 203 PropertyItemId 4 A few pages of that stuff. Is it really useful for everyone, including automated testing systems?
I'd agree this is a huge amount of spam that needs to be turned off.
- A work queue deadlock. Not a good thing at all
(/srv/buildbot_cmake/full_cmake/build/ntoskrnl/ex/work.c:351) EX: Work Queue Deadlock detected: 1 (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/ex/work.c:353) Dynamic threads queued 2
This appears to be the caused by the USB stack. It may not be a direct work item deadlock but I think it may trigger one elsewhere.
- ???
All that resulted from my desire to just compare logs attached to the bug report. New log is totally unreadable, I had to spend time figuring out where actually that Live Essentials app was started, what problems it shows, etc.
Best regards, Aleksey.
Regards, Cameron
Ros-dev mailing list Ros-dev@reactos.org http://www.reactos.org/mailman/listinfo/ros-dev
Am 06.06.2012 17:42, schrieb Cameron Gutman:
- What happened to the floppy driver?
(/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c:1579) '\Driver\FLOPPY' initialization failed, status (0xc000000e) (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c:61) Deleting driver object '\Driver\FLOPPY' (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c:87) HACK: Not unloading the driver image due to critical bugs! (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/io/iomgr/driver.c:1961) IopInitializeDriver() failed (Status c000000e) (/srv/buildbot_cmake/full_cmake/build/ntoskrnl/mm/ARM3/sysldr.c:935) Leaking driver: floppy.sys
Fix it? Don't enable it in trunk builds if it's buggy and not fixed? That's correct behavior. Failing DriverEntry makes the driver immediately unload. This is broken due to some incorrect memory typing in FreeLoader which results in invalid loader entries for boot start drivers after stage 1, which is why we currently act very cautiously and don't unload to avoid reading invalid memory. This isn't actually a broken case, but we don't unload anyway because we have no nice way of knowing whether our LDR entries are valid or not.
Is there a bug report for that? If yes please assign to me.
- These lines repeated 20 times.
(/srv/buildbot_cmake/full_cmake/build/dll/ntdll/ldr/ldrapi.c:811) NtCreateSection() failed (Status 0xc0000022). Why creating section in LdrpVerifyImageMatchesChecksum() failes now?
- Win32 stage.
(/srv/buildbot_cmake/full_cmake/build/win32ss/user/ntuser/winsta.c:208) err: Invalid window station handle
This is probably due to the fact that certain parts of the win32k initialization are not being done correctly. So it's a real error and someone should investigate it.
(/srv/buildbot_cmake/full_cmake/build/win32ss/user/ntuser/ntuser.c:161) err: Enter NtUserInitialize(0, 00000000, 00000000) (/srv/buildbot_cmake/full_cmake/build/win32ss/user/ntuser/display.c:79) err: InitDisplayDriver (\Device\Video0, \Registry\Machine\System\CurrentControlSet\Hardware Profiles\Current\System\CurrentControlSet\Services\VBE\Device0);
What happens here? It's a normal bootup, everyone should see this. Why is invalid window station handle being passed, why do we need NtUserInitialize to produce ERR debug print, along with InitDisplayDriver. Are those errors? If not, then why the hell are they being printed? If yes, then I don't see any info about actual errors.
These should in fact be demoted to TRACEs
On 6/6/12, Aleksey Bragin aleksey@reactos.org wrote:
Hello, it's time for my periodical rant about debug log mess again. The example below is made using latest VirtualBox 3.
Suggestions and questions:
(/srv/buildbot_cmake/full_cmake/build/win32ss/user/ntuser/ntuser.c:161) err: Enter NtUserInitialize(0, 00000000, 00000000) (/srv/buildbot_cmake/full_cmake/build/win32ss/user/ntuser/display.c:79) err: InitDisplayDriver (\Device\Video0, \Registry\Machine\System\CurrentControlSet\Hardware Profiles\Current\System\CurrentControlSet\Services\VBE\Device0);
What happens here? It's a normal bootup, everyone should see this. Why is invalid window station handle being passed, why do we need NtUserInitialize to produce ERR debug print, along with InitDisplayDriver. Are those errors? If not, then why the hell are they being printed? If yes, then I don't see any info about actual errors.
NtUserInitialize when used with Automatic Regression Tests let's know where we are at during boot. Justin Case of a lockup.
(/srv/buildbot_cmake/full_cmake/build/win32ss/user/ntuser/window.c:2416) err: DestroyWindow AOW AOW? ORLY?
This one just snicked in...
There is the Release Build to play with, without the debugs....