KDL (network related) when booting on a Hades Canyon NUC8.

[bga]

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.

[bga]

Spinlock KDL

[waddlesplash]

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.)

[waddlesplash]

hrev53085 may help with this.

[bga]

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.

[waddlesplash]

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.

[bga]

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).

[bga]

Also, I booted disabling ipro1000 and forcibly entered KDL. Keyboard did not work. :(

[waddlesplash]

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.

[bga]

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.

[bga]

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. :)

[bga]

Double free KDL.

[waddlesplash]

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.

[bga]

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?

[bga]

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.

[waddlesplash]

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.

[waddlesplash]

Note that the "parent" its freeing here is really the "child", see towards the top of the function where it swaps them out.

[bga]

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.

[bga]

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.

[waddlesplash]

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.

[bga]

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?

[bga]

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

[bga]

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.

[bga]

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.

[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

[bga]

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.

[bga]

I think I found it:

​http://xref.plausible.coop/source/xref/haiku/src/libs/compat/freebsd_network/shared.h#20

[korli]

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.

[bga]

Replying to korli:

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.

Sure, but in this case it was just an alias. :)

[bga]

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?

[korli]

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.

[bga]

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.

[bga]

Also, the bus_space_read_4() storm seems to be happening here:

​http://xref.plausible.coop/source/xref/haiku/src/add-ons/kernel/drivers/network/ipro1000/dev/e1000/e1000_mac.c#2192

Also, another error message I noticed:

Driver can't access device - SMBI bit is set.

[korli]

Did you check that the driver works in FreeBSD? You probably did, but the info isn't in the ticket.

[korli]

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.

[bga]

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.

[korli]

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.

[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)?

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.

[korli]

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)

[bga]

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?

[waddlesplash]

Yes, this is where the guarded heap would be immensely helpful. Trying to fix it on your machine may be worthwhile...

[bga]

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?

[waddlesplash]

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.

[waddlesplash]

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.

[bga]

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.

[waddlesplash]

KDL possibly fixed in hrev53152. Separate tickets should be opened for the different cards if that commit indeed gets things moving further.

[bga]

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.

[waddlesplash]

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.

[bga]

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:

​http://xref.plausible.coop/source/xref/haiku/src/add-ons/kernel/drivers/network/ipro1000/dev/e1000/e1000_ich8lan.c#1404

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:

​http://xref.plausible.coop/source/xref/haiku/src/add-ons/kernel/drivers/network/ipro1000/dev/e1000/e1000_ich8lan.c#1429

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?

[bga]

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.

[waddlesplash]

It's possible, yes, however virtually all other in tree drivers do something very similar to this to attach PCI devices.

[bga]

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?

[bga]

Figured it out! It was a stupid bug. It is now working for me. Fix coming soon.

[bga]

​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!).

[bga]

FYI, this also fixed the igb driver. So both network cards are now working on my machine.

[bga]

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.

[waddlesplash]

Fixed in hrev53174. (The device count bug is now #15095.)

[nielx]

Assign tickets with status=closed and resolution=fixed within the R1/beta2 development window to the R1/beta2 Milestone