Opened 5 weeks ago

Last modified 28 hours ago

#15016 new bug

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

Reported by: bga Owned by: nobody
Priority: normal Milestone: Unscheduled
Component: Drivers/Network/ipro1000 Version: R1/Development
Keywords: Cc:
Blocked By: Blocking:
Has a Patch: no 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)

kdl.jpg (4.3 MB) - added by bga 5 weeks ago.
Spinlock KDL
IMG_20190502_182017.jpg (4.4 MB) - added by bga 3 weeks ago.
Double free KDL.

Change History (47)

Changed 5 weeks ago by bga

Attachment: kdl.jpg added

Spinlock KDL

comment:1 Changed 5 weeks ago by 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.)

comment:2 Changed 5 weeks ago by waddlesplash

hrev53085 may help with this.

comment:3 Changed 4 weeks ago by 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.

comment:4 Changed 4 weeks ago by 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.

comment:5 Changed 4 weeks ago by 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).

comment:6 Changed 4 weeks ago by bga

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

comment:7 Changed 4 weeks ago by 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.

comment:8 Changed 4 weeks ago by 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.

comment:9 Changed 3 weeks ago by 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. :)

Changed 3 weeks ago by bga

Attachment: IMG_20190502_182017.jpg added

Double free KDL.

comment:10 Changed 3 weeks ago by 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.

comment:11 Changed 3 weeks ago by 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?

comment:12 Changed 3 weeks ago by 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.

comment:13 Changed 3 weeks ago by 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.

comment:14 Changed 3 weeks ago by waddlesplash

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 Changed 3 weeks ago by 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.

comment:16 Changed 3 weeks ago by 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.

comment:17 Changed 2 weeks ago by 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.

comment:18 Changed 2 weeks ago by 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?

Last edited 2 weeks ago by bga (previous) (diff)

comment:19 Changed 2 weeks ago by 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

comment:20 Changed 2 weeks ago by 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.

comment:21 Changed 2 weeks ago by 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.

comment:22 in reply to:  21 ; Changed 2 weeks ago by 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

comment:23 in reply to:  22 ; Changed 2 weeks ago by 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.

comment:25 in reply to:  23 ; Changed 2 weeks ago by 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.

comment:26 in reply to:  25 Changed 2 weeks ago by 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. :)

comment:27 Changed 11 days ago by 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?

comment:28 Changed 11 days ago by 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.

comment:29 Changed 10 days ago by 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.

comment:30 Changed 10 days ago by 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.

comment:31 Changed 10 days ago by korli

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

comment:32 Changed 10 days ago by 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.

comment:33 Changed 10 days ago by 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.

comment:34 Changed 10 days ago by 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.

comment:35 Changed 7 days ago by 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.

comment:36 in reply to:  35 Changed 7 days ago by 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)

comment:37 Changed 3 days ago by 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?

comment:38 Changed 3 days ago by waddlesplash

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

comment:39 Changed 3 days ago by 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?

comment:40 Changed 3 days ago by 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.

comment:41 Changed 3 days ago by 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.

comment:42 Changed 3 days ago by 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.

comment:43 Changed 40 hours ago by waddlesplash

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

comment:44 Changed 30 hours ago by 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.

comment:45 Changed 28 hours ago by 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.

Note: See TracTickets for help on using tickets.