#15016 closed bug (fixed)
KDL (network related) when booting on a Hades Canyon NUC8.
| Reported by: | bga | Owned by: | nobody |
|---|---|---|---|
| Priority: | normal | Milestone: | R1/beta2 |
| Component: | Drivers/Network/ipro1000 | Version: | R1/Development |
| Keywords: | Cc: | ||
| Blocked By: | Blocking: | ||
| Platform: | All |
Description
When booting on the mentioned machine, the boot process go as far as starting the installation. At that point I needed to create a partition using drive setup but the DriveSetup window never showed up. I started the desktop and noticed DriveSetup had somewhat started (its icon showed in the Deskbar and I could see it in ProcessController. Even killing it with ProcessController didn't work (the KDL makes it obvious why.
It seems to be stuck in acquiring a spinlock in the ipro1000 driver and this ends up stalling DriveSetup (there are also a few unkillable bash instances running. probably running startup scripts.
Attachments (2)
Change History (57)
by , 6 years ago
comment:1 by , 6 years ago
The most likely cause would be that the lock is simply uninitialized. That happens here: https://github.com/haiku/haiku/blob/master/src/libs/compat/freebsd_iflib/iflib.c#L5111
And that's called from iflib_device_attach, which we call here: https://github.com/haiku/haiku/blob/master/src/libs/compat/freebsd_network/driver.c#L225
So ... I'm not sure what's going on. Can you add some prints to iflib.c to figure out if register() is getting called or not?
(If you manually enter KDL via Alt+PrntScrn+D before the actual KDL occurs, you can use your USB keyboard in it.)
comment:3 by , 6 years ago
It did not. I mean, I am not getting the KDL anymore (tried a few boots) but it is still stalling and stalling the system with it. Sometimes the boot stops before tracker/deskbar starts. Sometimes after. Sometimes the power button still responds and the machine starts to shutdown but then find some bash process that is in a modal dialog (!!) which probably just mean it is also stalled due to the lock issue.
comment:4 by , 6 years ago
OK. Checking the syslog in KDL, which should now be possible, and then grabbing backtraces of network and ipro1000 related threads may shed some insight.
comment:5 by , 6 years ago
Unfortunately, no. The only obvious constant is that if I do not disable the ipro1000 driver or disable the network cards in the BIOS, mouse and keyboard do not work at all. If I disable the pro1000 driver, mouse and keyboard works. Interesting enough, the mouse and keyboard are connected to the same port (through a hub) that the harddrive is connected to (and the disk obviously works even with the ipro1000 driver enabled).
comment:6 by , 6 years ago
Also, I booted disabling ipro1000 and forcibly entered KDL. Keyboard did not work. :(
comment:7 by , 6 years ago
How did you enter KDL? For USB keyboards, you *must* do it via the keyboard shortcut, not via the Terminal kernel_debugger command.
For ipro1000: yes, it's sounding more like a memory corruption issue. I saw something like that on VirtualBox but thought it was a fluke. Time to make a guarded heap build.
comment:8 by , 6 years ago
ALT + SysReq(Print Screen) + d
So, yes, using the keyboard shortcut.
If you want I can do it (what is the incantation?), although it is only worth me doing it if I can get the information I need from the onscreen debug output as everything else has a chance to not work due to the keyboard not working.
comment:9 by , 6 years ago
Ok, I guess I got something from enabling allocation debugging in the kernel. See attached KDL but it seem we are doing a double free in device_delete_child() (around https://github.com/haiku/haiku/blob/ab3e2cf4bc58c8cb63a554448b8df14a52869172/src/libs/compat/freebsd_network/compat.c#L445). The call chain is:
haiku_handle_fbsd_drivers_list() -> _fbsd_init_drivers() -> device_delete_child() -> panic()
I am trying to debug further but I am learning this while I go so feel free to beat me to it. :)
comment:10 by , 6 years ago
The fix should be to just set parent->description to NULL in that if() statement after the free(). Feel free to submit a patch on Gerrit, I'll get to it later if not.
comment:11 by , 6 years ago
Even if that fixes it (and I am not sure it would, as the crash might be on one of the other 2 free calls (I did not investigate further yet) this would just hide a possible bug. Are we really supposed to be destroying the same device (or child) twice?
comment:12 by , 6 years ago
I tried it anyway for the sake of it. Still crashed. Then I did the same with parent->softc, still crashed.
So parent is the only one left. it is not immediately obvious to me how that could happen.
comment:13 by , 6 years ago
OK, then the problem is _fbsd_init_drivers somehow not re-allocating the device after destroying it. I didn't look at that code, but it's very possibly broken in some obvious way.
comment:14 by , 6 years ago
Note that the "parent" its freeing here is really the "child", see towards the top of the function where it swaps them out.
comment:15 by , 6 years ago
Some more findings, although I am still puzzled by this:
1 - It appears that it was not the page guard thing that helped me get the double free KDL. The machine has 2 network cards. If I disable one, I get the double free KDL. If I keep both enabled, I get the deadlock.
2 - If I comment out all free() calls on the offending function (not a fix, bu I was ok with trading memory leaks for getting more information), then I get the original spinlock KDL! It looks like the recent changes to upgrade to a newer version of the BSD drivers introduced at least the double free issue.
3 - Setting the fields to NULL after freeing them does not help and we still get double frees. This leads me to believe that we we have move then one device with pointers to the same data (softc and/or description). I have no idea how that could happen yet.
comment:16 by , 6 years ago
Ok, a final summary for a while as I will not be able to look into this this weekend (and probably next week).
The actual double free is here:
http://xref.plausible.coop/source/xref/haiku/src/libs/compat/freebsd_network/compat.c#448
Somehow it looks like there are 2 devices pointing to the same memory for their softc (assuming it is not just some memory corruption going on, although I would expect it to be less deterministic on how the crash look like if this was the case).
I could not really use guarded pages to see if I could find anything else as it runs out of memory in my machine (64 bit build, 32 Gb of RAM).
I also went through the code to see if I could find a place where softc was being arbitrarily set but it looks like it is only allocated and set here:
http://xref.plausible.coop/source/xref/haiku/src/libs/compat/freebsd_network/compat.c#287
The other way I thought about debugging this was to keep track of all softc pointers and then panic if we found the same pointer in different devices. Depending on where the panic() was, we could figure out how this is happening (again, assuming it is not simply memory corruption.
If I simply comment out the free() call for softc, I am back to the original spinlock KDL. I *THINK* they might be related anyway as it looks like softc is related to both code paths affected.
comment:17 by , 6 years ago
Aha, it appears iflib calls device_set_softc(). So we need to keep track of when we own the softc vs. the driver owns the softc. I can take a look at fixing that.
comment:18 by , 6 years ago
ifc_flags seem to already rack this:
http://xref.plausible.coop/source/xref/haiku/src/libs/compat/freebsd_iflib/iflib.c#4459
Qestions are:
1 - Is it already set when we are creating the devices on our side?
2 - Can we accss those flas on our side?
comment:19 by , 6 years ago
Also, while looking at the code it is clear why ipro1000 has a problem. It sems to be the only driver that references iflib_device_attach() (which leads to the device_set_softc() calls down the cal path.
http://xref.plausible.coop/source/s?refs=iflib_device_attach&project=haiku
comment:20 by , 6 years ago
Added some debug to figure out the order things happen, for my own benefit, and this is what I got:
2019-05-05 15:02:35 KERN: pci_reserve_device(0, 31, 6, ipro1000) 2019-05-05 15:02:35 KERN: init_root_device(dev = 0xffffffffc0451cb0) 2019-05-05 15:02:35 KERN: init_root_device(): Setting softc. 2019-05-05 15:02:35 KERN: device_set_driver(dev = 0xffffffffc052a3b0) 2019-05-05 15:02:35 KERN: device_set_driver() : Allocating new softc. 2019-05-05 15:02:35 KERN: iflib_device_attach(dev = 0xffffffffc052a3b0) 2019-05-05 15:02:35 KERN: iflib_device_register(dev = 0xffffffffc052a3b0) 2019-05-05 15:02:35 KERN: iflib_device_register(): Setting device softc. 2019-05-05 15:02:35 KERN: if_initname(0xffffffff80cc5800, igb, 66) 2019-05-05 15:02:35 KERN: [ipro1000] ipro1000: /dev/net/ipro1000/0 2019-05-05 15:02:35 KERN: [ipro1000] (igb) attach_pre capping queues at 4 2019-05-05 15:02:35 KERN: [ipro1000] (igb) bus_alloc_resource(3, [16], 0x0, 0xffffffffffffffff, 0x1,0x2)
So it appears that we allocate the device and the pass it down to the iflib stuff. Because we allocate a new softc when setting up the device, we need a way to know if iflib will do it too to avoid allocating it in the first place.
Or as a hack, maybe device_set_softc() should free the memory if it is not NULL before assigning the new pointer.
follow-up: 22 comment:21 by , 6 years ago
In FreeBSD, device_set_soft() actually checks if softc was already allocated and frees it if ha s the case before assigning the new value, which makes sense.
http://xref.plausible.coop/source/xref/freebsd-11-stable/stand/kshim/bsd_kernel.c#1014
Where is device_t defined in Haiku? I could not find it.
follow-up: 23 comment:22 by , 6 years ago
Replying to bga:
Where is device_t defined in Haiku? I could not find it.
in src/libs/compat/freebsd_network/compat/sys/haiku-module.h
follow-up: 25 comment:23 by , 6 years ago
Replying to korli:
Replying to bga:
Where is device_t defined in Haiku? I could not find it.
in src/libs/compat/freebsd_network/compat/sys/haiku-module.h
I might be being obtuse, but I can not see it there. The closest is a typedef but that is not what I really want. I want to know what are the existing fields in the actual structure.
comment:24 by , 6 years ago
follow-up: 26 comment:25 by , 6 years ago
Replying to bga:
I might be being obtuse, but I can not see it there. The closest is a typedef but that
Well, a typedef is a definition and you asked for one.
comment:26 by , 6 years ago
comment:27 by , 6 years ago
I went a bit further with debugging. Note that this is with the 2 ipro1000 cards enabled (only one connected to the network) so I do not get the KDL. Instead the system just stalls. Now it is obvious that it is stuck in a loop doing bus_space_read_4(). Here is the full log with all debug I added plus enabling some debugging in the driver itself:
KERN: pci_reserve_device(5, 0, 0, ipro1000) KERN: pci_reserve_device(0, 31, 6, ipro1000) KERN: iflib_device_register(dev = 0xffffffffc03e5710, sc = 0x0000000000000000) KERN: iflib_device_register(): Allocated ctx = 0xffffffff80cfcc00 KERN: iflib_device_register(): NULL sc. KERN: iflib_device_register(): Allocated sc = 0xffffffff821f0000 KERN: iflib_device_register(): Calling device_set_softc(dev = 0xffffffffc03e5710, ctx = 0xffffffff80cfcc00). KERN: iflib_register(ctx = 0xffffffff80cfcc00) KERN: iflib_register(): Initialized lock iflib ctx lock. KERN: if_initname(0xffffffff80cc8000, igb, 66) KERN: [ipro1000] ipro1000: /dev/net/ipro1000/0 KERN: if_setsoftc(ifp = 0xffffffff80cc8000, softc = 0xffffffff80cfcc00) KERN: All if_* stuff set. KERN: Calling ifmedia_init() KERN: ifmedia_init() called KERN: em_if_attach_pre(ctx = 0xffffffff80cfcc00) KERN: em_if_attach_pre(): dev = 0xffffffffc03e5710 KERN: em_if_attach_pre(): adapter (iflib_softc) = 0xffffffffc03e5710 KERN: em_if_attach_pre(): 1 KERN: em_if_attach_pre(): 2 KERN: e1000_set_mac_type KERN: em_if_attach_pre(): 3 KERN: [ipro1000] (igb) attach_pre capping queues at 4 KERN: em_if_attach_pre(): 4 KERN: [ipro1000] (igb) bus_alloc_resource(3, [16], 0x0, 0xffffffffffffffff, 0x1,0x2) KERN: set MTRRs to: KERN: mtrr: 0: base: 0x72954000, size: 0x2000, type: 0 KERN: mtrr: 1: base: 0x7c000000, size: 0x800000, type: 0 KERN: mtrr: 2: base: 0xc0000000, size: 0x40000000, type: 0 KERN: mtrr: 3: base: 0x2fff010000, size: 0x10000, type: 0 KERN: mtrr: 4: base: 0x80000000, size: 0x80000000, type: 1 KERN: em_if_attach_pre(): 5 KERN: em_if_attach_pre(): 6 KERN: e1000_set_mac_type KERN: e1000_init_mac_ops_generic KERN: e1000_init_phy_ops_generic KERN: e1000_init_nvm_ops_generic KERN: e1000_init_function_pointers_82575 KERN: e1000_init_mac_params_82575 KERN: bus_space_read_4() KERN: Last message repeated 2 times. KERN: e1000_read_sfp_data_byte KERN: bus_space_read_4() KERN: I2CCMD Error bit set KERN: e1000_read_sfp_data_byte KERN: bus_space_read_4() KERN: I2CCMD Error bit set KERN: e1000_read_sfp_data_byte KERN: bus_space_read_4() KERN: I2CCMD Error bit set KERN: bus_space_read_4() Last message repeated 1 time KERN: e1000_init_nvm_params_i210 KERN: bus_space_read_4() KERN: e1000_init_nvm_params_82575 KERN: e1000_get_flash_presence_i210 KERN: bus_space_read_4() KERN: e1000_init_phy_params_82575 KERN: em_if_attach_pre(): 7 KERN: e1000_get_bus_info_pcie_generic KERN: bus_space_read_4() KERN: em_if_attach_pre(): 8 KERN: em_if_attach_pre(): 9 KERN: em_if_attach_pre(): 10 KERN: em_if_attach_pre(): 11 KERN: e1000_null_ops_generic KERN: em_if_attach_pre(): 12 KERN: e1000_reset_hw_82580 KERN: bus_space_read_4() KERN: e1000_disable_pcie_master_generic KERN: bus_space_read_4() KERN: Last message repeated 800 times. KERN: Master requests are pending. KERN: PCI-E Master disable polling has failed. KERN: Masking off all interrupts KERN: bus_space_read_4() Last message repeated 1 time KERN: e1000_get_auto_rd_done_generic KERN: bus_space_read_4() Last message repeated 1 time KERN: e1000_reset_mdicnfg_82580 KERN: e1000_check_alt_mac_addr_generic KERN: e1000_read_nvm_srrd_i210 KERN: e1000_acquire_nvm_i210 KERN: e1000_acquire_swfw_sync KERN: e1000_get_hw_semaphore KERN: bus_space_read_4() KERN: Last message repeated 17578 times. KERN: Highpoint-IDE: supports_device() KERN: bus_space_read_4() KERN: Last message repeated 92 times. KERN: Highpoint-IDE: supports_device() KERN: bus_space_read_4() KERN: Last message repeated 917 times. KERN: package_daemon [30258035: 2367] KERN: bus_space_read_4() KERN: Failed to open packages activation file: No such file or directory KERN: bus_space_read_4() KERN: package_daemon [30259203: 2367] KERN: bus_space_read_4() KERN: Failed to get activated packages info from activated packages file. Assuming all package files in package directory are activated. KERN: bus_space_read_4() KERN: package_daemon [30260781: 2367] bus_space_read_4() KERN: latest volume state: KERN: bus_space_read_4() KERN: package_daemon [30261456: 2367] KERN: bus_space_read_4() KERN: active package: "expat-2.2.6-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30262347: 2367] bus_space_read_4() KERN: active package: "xz_utils-5.2.4-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30263268: 2367] bus_space_read_4() KERN: active package: "lcms-2.9-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30264138: 2367] bus_space_read_4() KERN: active package: "libffi-3.2.1-4-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30265040: 2367] KERN: bus_space_read_4() KERN: active package: "ca_root_certificates-2018_10_17-1-any.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30266062: 2367] bus_space_read_4() KERN: active package: "flex-2.6.4-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30266948: 2367] bus_space_read_4() KERN: active package: "autoconf-2.69-8-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30267858: 2367] bus_space_read_4() KERN: active package: "libwebp-1.0.0-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30268769: 2367] KERN: bus_space_read_4() KERN: active package: "ffmpeg-4.1-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30269658: 2367] KERN: bus_space_read_4() KERN: active package: "bash-4.4.023-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30270561: 2367] bus_space_read_4() KERN: active package: "libxslt-1.1.32-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30271478: 2367] KERN: bus_space_read_4() KERN: active package: "openssl_devel-1.0.2q-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30272440: 2367] KERN: bus_space_read_4() KERN: active package: "libpcre-8.42-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30273342: 2367] bus_space_read_4() KERN: active package: "jam-2.5_2018_11_21-6-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30274284: 2367] bus_space_read_4() KERN: active package: "automake-1.16.1-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30275198: 2367] bus_space_read_4() KERN: active package: "mesa-17.1.10-4-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30276097: 2367] bus_space_read_4() KERN: active package: "findutils-4.6.0-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30277014: 2367] bus_space_read_4() KERN: active package: "bc-1.07.1-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30277901: 2367] bus_space_read_4() KERN: active package: "fontconfig-2.12.6-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30278833: 2367] bus_space_read_4() KERN: active package: "libpcre2-10.30-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30279740: 2367] bus_space_read_4() KERN: active package: "nghttp2-1.34.0-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30280659: 2367] bus_space_read_4() KERN: active package: "m4-1.4.18-3-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30281542: 2367] KERN: bus_space_read_4() KERN: active package: "perl-5.26.2-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30282436: 2367] bus_space_read_4() KERN: active package: "mesa_devel-17.1.10-4-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30283382: 2367] bus_space_read_4() KERN: active package: "gawk-4.2.1-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30284271: 2367] bus_space_read_4() KERN: active package: "coreutils-8.29-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30285187: 2367] bus_space_read_4() KERN: active package: "makefile_engine-r1~beta1_hrev53112_1_dirty-1-any.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30286291: 2367] bus_space_read_4() KERN: active package: "python-2.7.15-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30287199: 2367] bus_space_read_4() KERN: active package: "libexecinfo-1.1-5-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30288124: 2367] bus_space_read_4() KERN: active package: "libmodplug-0.8.9.0-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30289070: 2367] bus_space_read_4() KERN: active package: "make-4.1-3-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30289944: 2367] KERN: bus_space_read_4() KERN: active package: "texinfo-6.5-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30290841: 2367] KERN: bus_space_read_4() KERN: active package: "mesa_swpipe-17.1.10-4-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30291794: 2367] bus_space_read_4() KERN: active package: "glu-9.0.0-7-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30292675: 2367] bus_space_read_4() KERN: active package: "curl-7.62.0-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30293569: 2367] bus_space_read_4() KERN: active package: "libidn2-2.0.5-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30294474: 2367] bus_space_read_4() KERN: active package: "readline-7.0.3-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30295390: 2367] bus_space_read_4() KERN: active package: "libvpx3-1.5.0-3-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30296299: 2367] bus_space_read_4() KERN: active package: "pkgconfig-0.29.2-3-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30297233: 2367] bus_space_read_4() KERN: active package: "netcat-1.10-4-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30298133: 2367] bus_space_read_4() KERN: active package: "grep-3.3-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30299004: 2367] bus_space_read_4() KERN: active package: "freetype-2.9.1-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30299921: 2367] KERN: bus_space_read_4() KERN: active package: "webpositive-r1~beta1_hrev53112_1_dirty-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30301016: 2367] bus_space_read_4() KERN: active package: "mpc-1.1.0-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30301894: 2367] KERN: bus_space_read_4() KERN: active package: "libunistring-0.9.10-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30302848: 2367] bus_space_read_4() KERN: active package: "libogg-1.3.3-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30303750: 2367] KERN: bus_space_read_4() KERN: active package: "scons-2.5.1-3-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30304637: 2367] bus_space_read_4() KERN: active package: "openexr-2.2.1-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30305544: 2367] bus_space_read_4() KERN: active package: "gutenprint-5.2.14-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30306484: 2367] bus_space_read_4() KERN: active package: "icu-57.1-3-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30307355: 2367] bus_space_read_4() KERN: active package: "man-1.6g-6-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30308224: 2367] bus_space_read_4() KERN: active package: "openjpeg-2.3.0-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30309140: 2367] bus_space_read_4() KERN: active package: "gettext_libintl-0.19.8.1-5-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30310124: 2367] bus_space_read_4() KERN: active package: "gmp-6.1.2-3-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30310991: 2367] bus_space_read_4() KERN: active package: "mkdepend-1.7-5-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30311898: 2367] bus_space_read_4() KERN: active package: "curl_devel-7.62.0-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30312843: 2367] bus_space_read_4() KERN: active package: "sed-4.4-3-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30313707: 2367] bus_space_read_4() KERN: active package: "gzip-1.9-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30314580: 2367] bus_space_read_4() KERN: active package: "libsolv-0.3.0_haiku_2014_12_22-3-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30315617: 2367] KERN: bus_space_read_4() KERN: active package: "nano-3.2-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30316489: 2367] bus_space_read_4() KERN: active package: "haikuwebkit-1.6.8-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30317429: 2367] KERN: bus_space_read_4() KERN: active package: "speex-1.2.0-3-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30318324: 2367] bus_space_read_4() KERN: active package: "libtasn1-4.13-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30319234: 2367] KERN: bus_space_read_4() KERN: active package: "nasm-2.12.02-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30320138: 2367] KERN: bus_space_read_4() KERN: active package: "glu_devel-9.0.0-7-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30321063: 2367] KERN: bus_space_read_4() KERN: active package: "sharutils-4.15.2-3-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30321994: 2367] bus_space_read_4() KERN: active package: "ilmbase-2.2.1-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30322892: 2367] bus_space_read_4() KERN: active package: "zlib-1.2.11-3-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30323790: 2367] bus_space_read_4() KERN: active package: "noto-20170920-3-any.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30324681: 2367] bus_space_read_4() KERN: active package: "haiku_loader-r1~beta1_hrev53112_1_dirty-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30325785: 2367] KERN: bus_space_read_4() KERN: active package: "gnutls-3.6.4-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30326688: 2367] bus_space_read_4() KERN: active package: "libvorbis-1.3.6-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30327613: 2367] bus_space_read_4() KERN: active package: "libgpg_error-1.32-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30328552: 2367] bus_space_read_4() KERN: active package: "patch-2.7.6-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30329454: 2367] KERN: bus_space_read_4() KERN: active package: "jpeg_devel-9c-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30330354: 2367] bus_space_read_4() KERN: active package: "tar-1.30-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30331234: 2367] bus_space_read_4() KERN: active package: "jasper-2.0.14-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30332139: 2367] bus_space_read_4() KERN: active package: "openssh-7.6p1-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30333050: 2367] KERN: bus_space_read_4() KERN: active package: "tiff4-4.0.10-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30333962: 2367] KERN: bus_space_read_4() KERN: active package: "git-2.19.1-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30334837: 2367] bus_space_read_4() KERN: active package: "libpng16_devel-1.6.35-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30335813: 2367] bus_space_read_4() KERN: active package: "tcpdump-4.9.2-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30336706: 2367] KERN: bus_space_read_4() KERN: active package: "jpeg-9c-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30337580: 2367] bus_space_read_4() KERN: active package: "openssl-1.0.2q-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30338495: 2367] bus_space_read_4() KERN: active package: "giflib-5.1.4-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30339396: 2367] bus_space_read_4() KERN: active package: "git_daemon-2.19.1-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30340342: 2367] bus_space_read_4() KERN: active package: "zlib_devel-1.2.11-3-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30341283: 2367] bus_space_read_4() KERN: active package: "unzip-6.0-5-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30342166: 2367] bus_space_read_4() KERN: active package: "less-542-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30343023: 2367] bus_space_read_4() KERN: active package: "zstd-1.3.7-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30343919: 2367] KERN: bus_space_read_4() KERN: active package: "p7zip-9.20.1-7-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30344822: 2367] KERN: bus_space_read_4() KERN: active package: "haiku-r1~beta1_hrev53112_1_dirty-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30345880: 2367] KERN: bus_space_read_4() KERN: active package: "libtheora-1.1.1-7-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30346803: 2367] bus_space_read_4() KERN: active package: "llvm7_libs-7.0.1-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30347735: 2367] KERN: bus_space_read_4() KERN: active package: "binutils-2.31.1-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30348662: 2367] bus_space_read_4() KERN: active package: "wget-1.19.5-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30349564: 2367] KERN: bus_space_read_4() KERN: active package: "libedit-20180525_3.1-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30350514: 2367] bus_space_read_4() KERN: active package: "bzip2-1.0.6-8-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30351414: 2367] bus_space_read_4() KERN: active package: "pe-2.4.5-8-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30352284: 2367] bus_space_read_4() KERN: active package: "mpfr-3.1.6-3-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30353177: 2367] bus_space_read_4() KERN: active package: "noto_sans_cjk_jp-1.004-2-any.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30354130: 2367] KERN: bus_space_read_4() KERN: active package: "groff-1.22.3-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30355032: 2367] bus_space_read_4() KERN: active package: "gcc-7.3.0_2018_05_01-4-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30355994: 2367] bus_space_read_4() KERN: active package: "which-2.21-5-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30356882: 2367] bus_space_read_4() KERN: active package: "libicns-0.8.1-8-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30357792: 2367] bus_space_read_4() KERN: active package: "ctags-5.8-5-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30358670: 2367] KERN: bus_space_read_4() KERN: active package: "vision-0.10.3-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30359581: 2367] bus_space_read_4() KERN: active package: "nettle-3.4-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30360469: 2367] KERN: bus_space_read_4() KERN: active package: "libxml2-2.9.7-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30361381: 2367] KERN: bus_space_read_4() KERN: active package: "ncurses6-6.1-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30362282: 2367] bus_space_read_4() KERN: active package: "bison-3.0.5-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30363177: 2367] bus_space_read_4() KERN: active package: "zip-3.0-4-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30364023: 2367] bus_space_read_4() KERN: active package: "libpcap-1.8.1-3-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30364940: 2367] KERN: bus_space_read_4() KERN: active package: "diffutils-3.6-2-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30365850: 2367] bus_space_read_4() KERN: active package: "wpa_supplicant-2.7~devel.haiku.1-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30366889: 2367] KERN: bus_space_read_4() KERN: active package: "haiku_devel-r1~beta1_hrev53112_1_dirty-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30367986: 2367] KERN: bus_space_read_4() KERN: active package: "libgcrypt-1.8.4-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30368916: 2367] bus_space_read_4() KERN: active package: "sqlite-3.26.0.0-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30369830: 2367] KERN: bus_space_read_4() KERN: active package: "libiconv-1.15-4-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30370744: 2367] bus_space_read_4() KERN: active package: "cdrtools-3.02~a09-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30371683: 2367] bus_space_read_4() KERN: active package: "gcc_syslibs-7.3.0_2018_05_01-4-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30372703: 2367] KERN: bus_space_read_4() KERN: active package: "libpng16-1.6.35-1-x86_64.hpkg" KERN: bus_space_read_4() KERN: package_daemon [30373630: 2367] bus_space_read_4() KERN: The latest volume state is also the currently active one KERN: bus_space_read_4() KERN: package_daemon [30374632: 2367] KERN: bus_space_read_4() KERN: Volume::InitialVerify((nil), (nil)) KERN: bus_space_read_4() KERN: Last message repeated 884 times. KERN: package_daemon [30420574: 2367] KERN: bus_space_read_4() KERN: Volume::InitialVerify(): volume at "/boot/system" is consistent KERN: bus_space_read_4() KERN: Last message repeated 4 times. KERN: package_daemon [30422116: 2367] bus_space_read_4() KERN: Failed to open packages activation file: No such file or directory KERN: bus_space_read_4() KERN: package_daemon [30423265: 2367] KERN: bus_space_read_4() KERN: Failed to get activated packages info from activated packages file. Assuming all package files in package directory are activated. KERN: bus_space_read_4() KERN: package_daemon [30424803: 2367] bus_space_read_4() KERN: latest volume state: KERN: bus_space_read_4() KERN: package_daemon [30425527: 2367] KERN: bus_space_read_4() KERN: The latest volume state is also the currently active one KERN: bus_space_read_4() KERN: package_daemon [30426517: 2367] bus_space_read_4() KERN: Volume::InitialVerify(0xeb983903a0, (nil)) KERN: bus_space_read_4() KERN: Last message repeated 29 times. KERN: package_daemon [30429107: 2367] KERN: bus_space_read_4() KERN: Volume::InitialVerify(): volume at "/boot/home/config" is consistent KERN: bus_space_read_4() KERN: Last message repeated 12994 times. KERN: Driver can't access device - SMBI bit is set. KERN: e1000_put_hw_semaphore KERN: bus_space_read_4() KERN: Last message repeated 12526 times. KERN: slab memory manager: created area 0xffffffffd1801000 (18465) KERN: bus_space_read_4() KERN: Last message repeated 20245 times. KERN: e1000_put_hw_semaphore KERN: bus_space_read_4() KERN: e1000_get_hw_semaphore KERN: bus_space_read_4() KERN: Last message repeated 32768 times. KERN: Driver can't access device - SMBI bit is set. KERN: e1000_put_hw_semaphore KERN: bus_space_read_4() KERN: Last message repeated 32772 times. KERN: e1000_put_hw_semaphore KERN: bus_space_read_4() KERN: e1000_get_hw_semaphore KERN: bus_space_read_4() KERN: Last message repeated 32768 times. KERN: Driver can't access device - SMBI bit is set. KERN: e1000_put_hw_semaphore KERN: bus_space_read_4() KERN: Last message repeated 32772 times. KERN: e1000_put_hw_semaphore KERN: bus_space_read_4() KERN: e1000_get_hw_semaphore KERN: bus_space_read_4() KERN: Last message repeated 32768 times. KERN: Driver can't access device - SMBI bit is set. KERN: e1000_put_hw_semaphore KERN: bus_space_read_4() KERN: Last message repeated 32772 times. KERN: e1000_put_hw_semaphore KERN: bus_space_read_4() KERN: e1000_get_hw_semaphore KERN: bus_space_read_4() KERN: Last message repeated 32768 times. KERN: Driver can't access device - SMBI bit is set. KERN: e1000_put_hw_semaphore KERN: bus_space_read_4() KERN: Last message repeated 32772 times. KERN: e1000_put_hw_semaphore KERN: bus_space_read_4() KERN: e1000_get_hw_semaphore KERN: bus_space_read_4() KERN: Last message repeated 32222 times. KERN: package_daemon [47584271: 2564] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 544 times. KERN: Driver can't access device - SMBI bit is set. KERN: e1000_put_hw_semaphore KERN: bus_space_read_4() KERN: Last message repeated 258 times. KERN: package_daemon [47627025: 2566] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 739 times. KERN: package_daemon [47665855: 2568] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 1882 times. KERN: package_daemon [47762671: 2573] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 813 times. KERN: package_daemon [47805171: 2575] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 750 times. KERN: package_daemon [47844463: 2577] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 1876 times. KERN: package_daemon [47940857: 2582] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 817 times. KERN: package_daemon [47983531: 2584] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 748 times. KERN: package_daemon [48022770: 2586] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 1886 times. KERN: package_daemon [48119310: 2591] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 826 times. KERN: package_daemon [48162391: 2593] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 746 times. KERN: package_daemon [48201520: 2595] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 1886 times. KERN: package_daemon [48298311: 2600] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 823 times. KERN: package_daemon [48341387: 2602] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 751 times. KERN: package_daemon [48380630: 2604] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 1887 times. KERN: package_daemon [48477503: 2609] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 825 times. KERN: package_daemon [48520734: 2611] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 744 times. KERN: package_daemon [48559675: 2613] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 1881 times. KERN: package_daemon [48656338: 2618] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 813 times. KERN: package_daemon [48698641: 2620] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 750 times. KERN: package_daemon [48737963: 2622] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 1890 times. KERN: package_daemon [48834991: 2627] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 815 times. KERN: package_daemon [48877545: 2629] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 757 times. KERN: package_daemon [48917100: 2631] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 1884 times. KERN: package_daemon [49013658: 2636] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 812 times. KERN: package_daemon [49056090: 2638] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 744 times. KERN: package_daemon [49095103: 2640] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 1890 times. KERN: package_daemon [49192180: 2645] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 818 times. KERN: package_daemon [49234901: 2647] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 750 times. KERN: package_daemon [49274094: 2649] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 653 times. KERN: e1000_put_hw_semaphore KERN: bus_space_read_4() KERN: e1000_get_hw_semaphore KERN: bus_space_read_4() KERN: Last message repeated 1111 times. KERN: package_daemon [49370942: 2654] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 813 times. KERN: package_daemon [49413613: 2656] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 760 times. KERN: package_daemon [49453406: 2658] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 1880 times. KERN: package_daemon [49549815: 2663] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 809 times. KERN: package_daemon [49592143: 2665] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 750 times. KERN: package_daemon [49631219: 2667] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 1880 times. KERN: package_daemon [49727862: 2672] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 826 times. KERN: package_daemon [49770888: 2674] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 747 times. KERN: package_daemon [49809955: 2676] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 1876 times. KERN: package_daemon [49906431: 2681] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 811 times. KERN: package_daemon [49948749: 2683] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 741 times. KERN: package_daemon [49987737: 2685] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 1884 times. KERN: package_daemon [50084526: 2690] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 811 times. KERN: package_daemon [50126909: 2692] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 750 times. KERN: package_daemon [50166104: 2694] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 1892 times. KERN: package_daemon [50263024: 2699] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 815 times. KERN: package_daemon [50305632: 2701] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 755 times. KERN: package_daemon [50345038: 2703] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 1876 times. KERN: package_daemon [50441462: 2708] bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4() KERN: Last message repeated 816 times. KERN: package_daemon [50484295: 2710] KERN: bus_space_read_4() KERN: failed to init server application: System shutting down KERN: bus_space_read_4()
So, any ideas from anyone? Augustin?
comment:28 by , 6 years ago
Just tried with two e1000 network devices in Qemu (it seems to be em, not igb), it works nice. You could trigger a panic after 15000 calls to bus_space_read_4() and see what the driver is doing.
comment:29 by , 6 years ago
The driver is trying to reset the card. Before the bus_space_read() storm it appears there are some errors that are detected:
I2CCMD Error bit set
There si also this message:
PCI-E Master disable polling has failed.
comment:30 by , 6 years ago
Also, the bus_space_read_4() storm seems to be happening here:
Also, another error message I noticed:
Driver can't access device - SMBI bit is set.
comment:31 by , 6 years ago
Did you check that the driver works in FreeBSD? You probably did, but the info isn't in the ticket.
comment:32 by , 6 years ago
seems related https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=228202 but we already have the fix applied. You could try to disable the PXEBoot option in your BIOS.
comment:33 by , 6 years ago
Ethernet cards work on FreeBSD 12 on the same machine. Also, if I disable one of the cards, then I get a spinlock KDL (attached to this bug) so there is definitely something fishy going on.
And network boot is disabled in the BIOS.
comment:34 by , 6 years ago
I checked the Linux driver, it seems this commit is only partly applied https://github.com/torvalds/linux/commit/08c991297582114a6e1220f913eec91789c4eac6
the i210 register for EEMNGCTL is 0x12030 in Linux, 0x1010 in FreeBSD. The part in e1000_82575.c is also missing, which could explain why it doesn't appear in your log.
hope it helps.
follow-up: 36 comment:35 by , 6 years ago
Adding the Linux changes did not help (only tried with 2 cards, will try with one later today). Anyway, considering the symptoms, I would be impressed if this was the actual issue (why would it cause a KDL)?
That being said, probably should enable debug in FreeBSD and compare what is happening. The Haiku output seems a bit weird in the sense that there are references to both 82575 and i210 but not all i210 code seems to actually be in the callchain where they should.
comment:36 by , 6 years ago
Replying to bga:
Adding the Linux changes did not help (only tried with 2 cards, will try with one later today). Anyway, considering the symptoms, I would be impressed if this was the actual issue (why would it cause a KDL)?
I was more looking at the bus_space_read loop, but yeah as the code seems to work on FreeBSD, it would have been lucky.
That being said, probably should enable debug in FreeBSD and compare what is happening. The Haiku output seems a bit weird in the sense that there are references to both 82575 and i210 but not all i210 code seems to actually be in the callchain where they should.
It would also help to determine at what point things are going wrong (never tried it though)
comment:37 by , 6 years ago
I switched back to a single card just because it goes further (and also, a crash tends to be easier to track than a hang.
I added some debug and confirmed that the problem is simply that the data the code is trying to access is either not initialized or has been deleted under the hood. Basically the process seems to be something like this:
1 - Device is setup and added to gDevices. At this point, everything that is needed is there. 2 - compat_open() is called for the device in question (by iterating through gDevices and obtaining the device that was setup above). 3 - At this point, the required data is not there anymore. For one thing, the spinlock it tries to acquire in iflib_if_init() has trash (confirmed by trying to print the spinlock name and getting a segment violation).
My current theory is that at some point between 1 and 2, data is being deleted/overwritten for some reason. The data in question must be gDevices[n]->if_softc, which is supposed to be the driver state. Any insights?
comment:38 by , 6 years ago
Yes, this is where the guarded heap would be immensely helpful. Trying to fix it on your machine may be worthwhile...
comment:39 by , 6 years ago
I will take a look at getting the guarded heap to work. It appears that it is trying to map a huge area and failing.
Meanwhile, now that I know where and why it is crashing, I added an early return to compat_open() to prevent the KDL and be able to at least see debug output for the device initialization:
2019-05-19 17:10:39 KERN: pci_reserve_device(0, 31, 6, ipro1000) 2019-05-19 17:10:39 KERN: if_initname(0xffffffff80cf6800, em, 62) 2019-05-19 17:10:39 KERN: [ipro1000] ipro1000: /dev/net/ipro1000/0 2019-05-19 17:10:39 KERN: em_if_attach_pre: begin 2019-05-19 17:10:39 KERN: e1000_set_mac_type 2019-05-19 17:10:39 KERN: [ipro1000] (em) attach_pre capping queues at 1 2019-05-19 17:10:39 KERN: [ipro1000] (em) bus_alloc_resource(3, [16], 0x0, 0xffffffffffffffff, 0x1,0x2) 2019-05-19 17:10:39 KERN: set MTRRs to: 2019-05-19 17:10:39 KERN: mtrr: 0: base: 0x72954000, size: 0x2000, type: 0 2019-05-19 17:10:39 KERN: mtrr: 1: base: 0x7c000000, size: 0x800000, type: 0 2019-05-19 17:10:39 KERN: mtrr: 2: base: 0xc0000000, size: 0x40000000, type: 0 2019-05-19 17:10:39 KERN: mtrr: 3: base: 0x2fff010000, size: 0x10000, type: 0 2019-05-19 17:10:39 KERN: mtrr: 4: base: 0x80000000, size: 0x80000000, type: 1 2019-05-19 17:10:39 KERN: e1000_set_mac_type 2019-05-19 17:10:39 KERN: e1000_init_mac_ops_generic 2019-05-19 17:10:39 KERN: e1000_init_phy_ops_generic 2019-05-19 17:10:39 KERN: e1000_init_nvm_ops_generic 2019-05-19 17:10:39 KERN: e1000_init_function_pointers_ich8lan 2019-05-19 17:10:39 KERN: e1000_init_mac_params_ich8lan 2019-05-19 17:10:39 KERN: e1000_init_nvm_params_ich8lan 2019-05-19 17:10:39 KERN: e1000_init_phy_params_pchlan 2019-05-19 17:10:39 KERN: e1000_init_phy_workarounds_pchlan 2019-05-19 17:10:39 KERN: e1000_gate_hw_phy_config_ich8lan 2019-05-19 17:10:39 KERN: Error in ULP disable flow: -2 2019-05-19 17:10:39 KERN: e1000_acquire_swflag_ich8lan 2019-05-19 17:10:39 KERN: SW has already locked the resource. 2019-05-19 17:10:39 KERN: Failed to initialize PHY flow 2019-05-19 17:10:39 KERN: PHY Initialization Error 2019-05-19 17:10:39 KERN: [ipro1000] (em) Setup of Shared code failed, error -3 2019-05-19 17:10:39 KERN: set MTRRs to: 2019-05-19 17:10:39 KERN: mtrr: 0: base: 0x72954000, size: 0x2000, type: 0 2019-05-19 17:10:39 KERN: mtrr: 1: base: 0x7c000000, size: 0x800000, type: 0 2019-05-19 17:10:39 KERN: mtrr: 2: base: 0xc0000000, size: 0x40000000, type: 0 2019-05-19 17:10:39 KERN: mtrr: 3: base: 0x2fff010000, size: 0x10000, type: 0 2019-05-19 17:10:39 KERN: mtrr: 4: base: 0x80000000, size: 0x80000000, type: 1 2019-05-19 17:10:39 KERN: [ipro1000] (em) IFDI_ATTACH_PRE failed -2147454965 2019-05-19 17:10:39 KERN: loaded driver /boot/system/add-ons/kernel/drivers/dev/net/ipro1000
A few things strike me as odd here:
1 - When I have 2 cards enabled, somehow it tries to use the igb driver. With a single card it is trying to use em? (I am pretty sure OpenBSD uses igb for this card. I will double check). 2 - Although there are obviously errors during the initialization, the device is published anyway. This seem unexpected.
Just for completeness sake, here is compat_open() later in syslog with the simple debug I added:
2019-05-19 17:10:42 KERN: [net/ipro1000/0] compat_open(0x2) 2019-05-19 17:10:42 KERN: compat_open(): Would use ifp = 0xffffffff80cf6800. 2019-05-19 17:10:42 KERN: ifp->if_softc = 0xffffffff80ce9800.
Another weird thing here: Immediately after that last line above is printed, I return B_ERROR from compact_open(). Even with that, i still see the debug below:
2019-05-19 17:10:42 KERN: register_domain(4, link) 2019-05-19 17:10:42 DAEMON 'DHCP': /dev/net/ipro1000/0: Send DHCP_DISCOVER to 255.255.255.255:67
Again, why is it moving forward anyway?
And, at last, this is the PCI information for the card:
2019-05-19 17:10:39 KERN: PCI: [dom 0, bus 0] bus 0, device 31, function 6: vendor 8086, device 15b7, revision 31 2019-05-19 17:10:39 KERN: PCI: class_base 02, class_function 00, class_api 00 2019-05-19 17:10:39 KERN: PCI: vendor 8086: Intel Corporation 2019-05-19 17:10:39 KERN: PCI: device 15b7: Ethernet Connection (2) I219-LM 2019-05-19 17:10:39 KERN: PCI: info: Network controller (Ethernet controller) 2019-05-19 17:10:39 KERN: PCI: line_size 00, latency 00, header_type 00, BIST 00 2019-05-19 17:10:39 KERN: PCI: ROM base host 00000000, pci 00000000, size 00000000 2019-05-19 17:10:39 KERN: PCI: cardbus_CIS 00000000, subsystem_id 0000, subsystem_vendor_id 8086 2019-05-19 17:10:39 KERN: PCI: interrupt_line ff, interrupt_pin 01, min_grant 00, max_latency 00 2019-05-19 17:10:39 KERN: PCI: base reg 0: host dc200000, pci dc200000, size 00020000, flags 00 2019-05-19 17:10:39 KERN: PCI: base reg 1: host 00000000, pci 00000000, size 00000000, flags 00 2019-05-19 17:10:39 KERN: PCI: base reg 2: host 00000000, pci 00000000, size 00000000, flags 00 2019-05-19 17:10:39 KERN: PCI: base reg 3: host 00000000, pci 00000000, size 00000000, flags 00 2019-05-19 17:10:39 KERN: PCI: base reg 4: host 00000000, pci 00000000, size 00000000, flags 00 2019-05-19 17:10:39 KERN: PCI: base reg 5: host 00000000, pci 00000000, size 00000000, flags 00 2019-05-19 17:10:39 KERN: PCI: Capabilities: PM, MSI, AdvancedFeatures
Does it look sane?
comment:40 by , 6 years ago
2 - Although there are obviously errors during the initialization, the device is published anyway. This seem unexpected.
Yes, this is probably the issue here. Likely this is a bug in the compat code. As you can see, "init_drivers" checks the return value of device_attach() and should bail if it's not 0, and then subsequently not publish the device. But perhaps something goes wrong and it does so anyway. Fixing that should at least fix the panics.
comment:41 by , 6 years ago
The igb vs. em is also strange. But it could be that 1 of your 2 cards is igb, and the other is em, and you just disable the igb one, I don't know.
comment:42 by , 6 years ago
Ok, at least this mystery is solved. Yes, the 2 cards are different (I did not expect that). The igb one is the one that hangs (thus it explains why it was hanging when 2 cards were enabled. This just happened to be the first one initialized).
This means that this machine has 2 different ethernet cards and one wifi card. All supposedly supported and none working. That is luck for you. :)
Anyway, I guess I will focus on the em card as it does sound like a simpler issue at first.
comment:43 by , 6 years ago
KDL possibly fixed in hrev53152. Separate tickets should be opened for the different cards if that commit indeed gets things moving further.
comment:44 by , 6 years ago
Actually, the same issue persists. You improved the code but did not really address the problem. The problem is here:
http://xref.plausible.coop/source/xref/haiku/src/libs/compat/freebsd_network/driver.c#239
gDevices is > 0 even with your changes so it returns B_OK. It should not return an error.
comment:45 by , 6 years ago
No, what should happen now is that the root devices are destroyed and gDeviceCount should be decremented, so it should return an error because no devices initialized successfully.
If it isn't, then something isn't decrementing gDeviceCount correctly.
comment:46 by , 5 years ago
I managed to compile FreeBSD with debug enabled and compare what happens in it with what happens in Haiku. Up to the point where it fails, it seems the call chain is exactly the same. I also zeroed in in the actual failure. The problem is in this function here:
There is an associated comment, in case it might be relevant:
1389 /** 1390 * e1000_disable_ulp_lpt_lp - unconfigure Ultra Low Power mode for LynxPoint-LP 1391 * @hw: pointer to the HW structure 1392 * @force: boolean indicating whether or not to force disabling ULP 1393 * 1394 * Un-configure ULP mode when link is up, the system is transitioned from 1395 * Sx or the driver is unloaded. If on a Manageability Engine (ME) enabled 1396 * system, poll for an indication from ME that ULP has been un-configured. 1397 * If not on an ME enabled system, un-configure the ULP mode by software. 1398 * 1399 * During nominal operation, this function is called when link is acquired 1400 * to disable ULP mode (force=FALSE); otherwise, for example when unloading 1401 * the driver or during Sx->S0 transitions, this is called with force=TRUE 1402 * to forcibly disable ULP. 1403 */
The actual failure happens in this loop:
It pokes a register and checks a different one for a state change that never happens. I added reads (or extra reads) to registers in this function and notice all reads are returning FFFFFFFF. In fact, it probably only reached this point by chance (the if that contains it checks for a bit in a register which is set as all bits are set). It is even possible that the FreeBSD code does not get to this point (although I did not check for this specifically).
Augustin mentioned that registers returning FFFFFFFF probably indicated that the card was not correctly initialized. Any pointers on where this initialization would happen? Whould it be in the Haiku (maybe at the time of PCI initialization?) side of things or in the actual driver?
comment:47 by , 5 years ago
Any chance that there could be an issue with the implementation of bus_alloc_mem-resource()?
http://xref.plausible.coop/source/xref/haiku/src/libs/compat/freebsd_network/bus.cpp#113
It seems to me that if this is wrong somehow, it might result in reading/writing registers not having the expected effect.
comment:48 by , 5 years ago
It's possible, yes, however virtually all other in tree drivers do something very similar to this to attach PCI devices.
comment:49 by , 5 years ago
Ok, I guess this is my last update on debugging this issue. Now I know for sure what is happening but I do not know why and my attempts to fix it did not work. Here is a commented log of what is happening now:
2019-05-30 22:53:50 KERN: pci_reserve_device(0, 31, 6, ipro1000)
This is obviously sane. The code to figure pout the PCI device is pretty straight forward.
2019-05-30 22:53:50 KERN: if_initname(0xffffffff80a79800, em, 60) 2019-05-30 22:53:50 KERN: [ipro1000] ipro1000: /dev/net/ipro1000/0 2019-05-30 22:53:50 KERN: em_if_attach_pre: begin 2019-05-30 22:53:50 KERN: e1000_set_mac_type 2019-05-30 22:53:50 KERN: [ipro1000] (em) attach_pre capping queues at 1
Until here everything is exactly the same in FreeBSD and Haiku.
2019-05-30 22:53:50 KERN: [ipro1000] (em) bus_alloc_resource(3, [16], 0x0, 0xffffffffffffffff, 0x1,0x2)
For completeness, this was another red-herring I went after: The end parameter is set to 0xffffffffffffffff (~0). In the FreeBSD land this is just a hint to figure out the end position based on the size present in the PCI info. Haiku's code always use the PCi infor information anyway.
2019-05-30 22:53:50 KERN: map physical memory dc200000, size: 131072 }} We are mapping the right physical address and the size is also correct. Note that the code that does the mapping tries to compute an offset to align the address to a page size: http://xref.plausible.coop/source/xref/haiku/src/add-ons/kernel/busses/scsi/ahci/util.cpp#59 I noticed xhci does not do that and tried to do it the xhci way (calling map_physical_memory directly). Did not make a different because it seems the address was aligned anyway (but i was trying everything :) ).
2019-05-30 22:53:50 KERN: set MTRRs to: 2019-05-30 22:53:50 KERN: mtrr: 0: base: 0x72954000, size: 0x2000, type: 0 2019-05-30 22:53:50 KERN: mtrr: 1: base: 0x7c000000, size: 0x800000, type: 0 2019-05-30 22:53:50 KERN: mtrr: 2: base: 0xc0000000, size: 0x40000000, type: 0 2019-05-30 22:53:50 KERN: mtrr: 3: base: 0x2fff010000, size: 0x10000, type: 0 2019-05-30 22:53:50 KERN: mtrr: 4: base: 0x80000000, size: 0x80000000, type: 1
Business as usual.
2019-05-30 22:53:50 KERN: rid = 16
rid matches what I get in FreeBSD. It also looks sane as this points to the first register in the PCI address space for the card.
2019-05-30 22:53:50 KERN: adapter->osdep.mem_bus_space_tag=1 2019-05-30 22:53:50 KERN: adapter->osdep.mem_bus_space_handle=ffffffff825c0000
The tag is correct. The address is whatever is returned by map_physical_memory(). I assume it is also sane. A curiosity, the actual address returned in BSD has some prefix but ends in dc200000 (which is the physical address). I guess they might do this for easier debugging?
2019-05-30 22:53:50 KERN: e1000_set_mac_type 2019-05-30 22:53:50 KERN: e1000_init_mac_ops_generic 2019-05-30 22:53:50 KERN: e1000_init_phy_ops_generic 2019-05-30 22:53:50 KERN: e1000_init_nvm_ops_generic 2019-05-30 22:53:50 KERN: e1000_init_function_pointers_ich8lan 2019-05-30 22:53:50 KERN: e1000_init_mac_params_ich8lan 2019-05-30 22:53:50 KERN: e1000_init_nvm_params_ich8lan
All these calls match FreeBSD.
2019-05-30 22:53:50 KERN: bus_space_read_4(tag=1, handle=ffffffff825c0000, offset=12) = ffffffff
This is the actual problem and why everything fails. Reading any register (using bus_space_read_4()) is resulting in 0xFFFFFFFF being returned. This is obviously wrong. From here on even the calls that match probably are only by sheer luck as it uses the register values to take decisions and select code paths.
2019-05-30 22:53:50 KERN: e1000_init_phy_params_pchlan 2019-05-30 22:53:50 KERN: bus_space_read_4(tag=1, handle=ffffffff825c0000, offset=23380) = ffffffff 2019-05-30 22:53:50 KERN: e1000_init_phy_workarounds_pchlan 2019-05-30 22:53:50 KERN: e1000_gate_hw_phy_config_ich8lan 2019-05-30 22:53:50 KERN: bus_space_read_4(tag=1, handle=ffffffff825c0000, offset=3840) = ffffffff 2019-05-30 22:53:50 KERN: bus_space_read_4(tag=1, handle=ffffffff825c0000, offset=23380) = ffffffff 2019-05-30 22:53:50 KERN: bus_space_read_4(tag=1, handle=ffffffff825c0000, offset=23376) = ffffffff 2019-05-30 22:53:50 KERN: bus_space_read_4(tag=1, handle=ffffffff825c0000, offset=23380) = ffffffff 2019-05-30 22:53:50 KERN: Last message repeated 30 times.
As can be seen, it continues happening for any register read.
2019-05-30 22:53:50 KERN: Error in ULP disable flow: -2 2019-05-30 22:53:50 KERN: e1000_acquire_swflag_ich8lan 2019-05-30 22:53:50 KERN: bus_space_read_4(tag=1, handle=ffffffff825c0000, offset=3840) = ffffffff 2019-05-30 22:53:50 KERN: Last message repeated 99 times. 2019-05-30 22:53:50 KERN: SW has already locked the resource. 2019-05-30 22:53:50 KERN: Failed to initialize PHY flow 2019-05-30 22:53:50 KERN: PHY Initialization Error 2019-05-30 22:53:50 KERN: [ipro1000] (em) Setup of Shared code failed, error -3
And it finally notices that there is an issue and fails.
2019-05-30 22:53:50 KERN: set MTRRs to: 2019-05-30 22:53:50 KERN: mtrr: 0: base: 0x72954000, size: 0x2000, type: 0 2019-05-30 22:53:50 KERN: mtrr: 1: base: 0x7c000000, size: 0x800000, type: 0 2019-05-30 22:53:50 KERN: mtrr: 2: base: 0xc0000000, size: 0x40000000, type: 0 2019-05-30 22:53:50 KERN: mtrr: 3: base: 0x2fff010000, size: 0x10000, type: 0 2019-05-30 22:53:50 KERN: mtrr: 4: base: 0x80000000, size: 0x80000000, type: 1 2019-05-30 22:53:50 KERN: [ipro1000] (em) IFDI_ATTACH_PRE failed -2147454965 2019-05-30 22:53:50 KERN: pci_unreserve_device(0, 31, 6, ipro1000)
And the resources are released.
So, this is it. The question to be answered now is why reading registers is obviously failing. There is a hook for card initialization (reset) but it is only called after the calls above happened (even in FreeBSD). It works ok in FreeBSD so i guess it should work ok in Haiku.
Anyone has any other ideas? Augustin? Korli?
comment:50 by , 5 years ago
Figured it out! It was a stupid bug. It is now working for me. Fix coming soon.
comment:51 by , 5 years ago
https://review.haiku-os.org/c/haiku/+/1495 (under review) will fix the ipro1000 (em) driver not working. It does not fix the KDL when a device fails to initialize but I will work on this next (now from Haiku itself!).
comment:52 by , 5 years ago
FYI, this also fixed the igb driver. So both network cards are now working on my machine.
comment:53 by , 5 years ago
The change mentioned above was abandoned in favor of https://review.haiku-os.org/c/haiku/+/1497. When submitted, this will fix the bug in the send that the KDL should not happen anymore.
The gDevicesCount thing still need to be addressed, but I will open a different bug for it.
comment:54 by , 5 years ago
| Resolution: | → fixed |
|---|---|
| Status: | new → closed |
comment:55 by , 5 years ago
| Milestone: | Unscheduled → R1/beta2 |
|---|
Assign tickets with status=closed and resolution=fixed within the R1/beta2 development window to the R1/beta2 Milestone
Spinlock KDL