RE: [PATCH 00/24] Thunderbolt security levels and NVM firmware upgrade

[Mario.Limonciello]

> 
> It happens occasionally when you reboot the machine when a device is
> connected but seems to be dependent on the BIOS version. Since it is the
> BIOS who is supposed to enumerated these devices, I suspect that it is
> either problem in BIOS or our PCI enumeration code does something wrong.
> 

I'm fairly certain it's an issue somewhere with Linux PCI enumeration.  I took 
the exact same HW and switched it out the SSD to one w/ Win10 1607.
I set the dock and cable to "always allow" in TBT settings applet.

I don't reproduce any problems with enumeration with the dock plugged in
on cold boot.  All the devices hanging off the bridge show up properly.

> > [    7.428542] pci_bus 0000:02: Allocating resources
> > [    7.428544] pcieport 0000:02:02.0: can't claim BAR 14 [mem 0xd9f00000-
> 0xd9ffffff]: no compatible bridge window
> > [    7.451018] Bluetooth: RFCOMM TTY layer initialized
> > [    7.451022] Bluetooth: RFCOMM socket layer initialized
> > [    7.451026] Bluetooth: RFCOMM ver 1.11
> > [   11.958457] wlp58s0: authenticate with 50:6a:03:a7:1c:27
> > [   11.969167] wlp58s0: send auth to 50:6a:03:a7:1c:27 (try 1/3)
> > [   11.975768] wlp58s0: authenticated
> > [   11.976386] wlp58s0: associate with 50:6a:03:a7:1c:27 (try 1/3)
> > [   11.984817] wlp58s0: RX AssocResp from 50:6a:03:a7:1c:27 (capab=0x1411
> status=0 aid=2)
> > [   12.001864] wlp58s0: associated
> > [   12.001913] IPv6: ADDRCONF(NETDEV_CHANGE): wlp58s0: link becomes ready
> > [   27.616672] thunderbolt 0000:03:00.0: timeout reading config space 2 from 0x5
> > [   27.616674] thunderbolt 0000:03:00.0: 301: cannot find
> TB_VSEC_CAP_PLUG_EVENTS aborting
> >
> > If I then unplug the cable and plug it back in the dock does show up and authorize
> properly, but is a traceback
> > along the way.
> > ---
> > [ 1653.226296] pcieport 0000:02:02.0: Refused to change power state, currently
> in D3
> > [ 1653.729116] thunderbolt 0000:03:00.0: stopping RX ring 0
> > [ 1653.729130] thunderbolt 0000:03:00.0: disabling interrupt at register 0x38200
> bit 12 (0xffffffff -> 0xffffefff)
> > [ 1653.729159] thunderbolt 0000:03:00.0: stopping TX ring 0
> > [ 1653.729168] thunderbolt 0000:03:00.0: disabling interrupt at register 0x38200
> bit 0 (0xffffffff -> 0xfffffffe)
> > [ 1653.729195] thunderbolt 0000:03:00.0: control channel stopped
> > [ 1653.729362] thunderbolt 0000:03:00.0: freeing RX ring 0
> > [ 1653.729381] thunderbolt 0000:03:00.0: freeing TX ring 0
> > [ 1653.729407] thunderbolt 0000:03:00.0: shutdown
> > [ 1653.753091] pcieport 0000:02:00.0: Refused to change power state, currently
> in D3
> > [ 1653.756383] pci_bus 0000:03: busn_res: [bus 03] is released
> > [ 1653.756676] pci_bus 0000:04: busn_res: [bus 04] is released
> > [ 1653.757479] pci_bus 0000:02: busn_res: [bus 02-05] is released
> > [ 1660.846964] ACPI Error: [SPRT] Namespace lookup failure,
> AE_ALREADY_EXISTS (20170303/dswload2-330)
> > [ 1660.846979] ACPI Exception: AE_ALREADY_EXISTS, During name
> lookup/catalog (20170303/psobject-241)
> > [ 1660.846985] ACPI Error: Method parse/execution failed [\_GPE._E42] (Node
> ffff8ba73016b488), AE_ALREADY_EXISTS (20170303/psparse-543)
> > [ 1660.846996] ACPI Error: Method parse/execution failed [\_GPE._E42] (Node
> ffff8ba73016b488), AE_ALREADY_EXISTS (20170303/psparse-543)
> > [ 1660.847009] ACPI Exception: AE_ALREADY_EXISTS, while evaluating GPE
> method [_E42] (20170303/evgpe-646)
> > [ 1660.893399] pci 0000:01:00.0: [8086:1576] type 01 class 0x060400
> > [ 1660.893529] pci 0000:01:00.0: supports D1 D2
> > [ 1660.893530] pci 0000:01:00.0: PME# supported from D0 D1 D2 D3hot D3cold
> > [ 1660.893625] pci 0000:01:00.0: System wakeup disabled by ACPI
> > [ 1660.893776] pci 0000:02:00.0: [8086:1576] type 01 class 0x060400
> > [ 1660.894047] pci 0000:02:00.0: supports D1 D2
> > [ 1660.894049] pci 0000:02:00.0: PME# supported from D0 D1 D2 D3hot D3cold
> > [ 1660.894178] pci 0000:02:01.0: [8086:1576] type 01 class 0x060400
> > [ 1660.894320] pci 0000:02:01.0: supports D1 D2
> > [ 1660.894321] pci 0000:02:01.0: PME# supported from D0 D1 D2 D3hot D3cold
> > [ 1660.894409] pci 0000:02:02.0: [8086:1576] type 01 class 0x060400
> > [ 1660.894542] pci 0000:02:02.0: supports D1 D2
> > [ 1660.894543] pci 0000:02:02.0: PME# supported from D0 D1 D2 D3hot D3cold
> > [ 1660.894637] pci 0000:01:00.0: PCI bridge to [bus 02-39]
> > [ 1660.894646] pci 0000:01:00.0:   bridge window [mem 0xc4000000-0xda0fffff]
> > [ 1660.894652] pci 0000:01:00.0:   bridge window [mem 0xa0000000-0xc1ffffff
> 64bit pref]
> > [ 1660.894716] pci 0000:03:00.0: [8086:1575] type 00 class 0x088000
> > [ 1660.894744] pci 0000:03:00.0: reg 0x10: [mem 0xda000000-0xda03ffff]
> > [ 1660.894756] pci 0000:03:00.0: reg 0x14: [mem 0xda040000-0xda040fff]
> > [ 1660.894910] pci 0000:03:00.0: supports D1 D2
> > [ 1660.894911] pci 0000:03:00.0: PME# supported from D0 D1 D2 D3hot D3cold
> > [ 1660.895079] pci 0000:02:00.0: PCI bridge to [bus 03]
> > [ 1660.895089] pci 0000:02:00.0:   bridge window [mem 0xda000000-0xda0fffff]
> > [ 1660.895152] pci 0000:02:01.0: PCI bridge to [bus 04-38]
> > [ 1660.895161] pci 0000:02:01.0:   bridge window [mem 0xc4000000-0xd9efffff]
> > [ 1660.895168] pci 0000:02:01.0:   bridge window [mem 0xa0000000-0xc1ffffff
> 64bit pref]
> > [ 1660.895222] pci 0000:02:02.0: PCI bridge to [bus 39]
> > [ 1660.895231] pci 0000:02:02.0:   bridge window [mem 0xd9f00000-0xd9ffffff]
> > [ 1660.895263] pci_bus 0000:02: Allocating resources
> > [ 1660.895296] pci 0000:02:01.0: bridge window [io  0x1000-0x0fff] to [bus 04-
> 38] add_size 1000
> > [ 1660.895314] pci 0000:01:00.0: bridge window [io  0x1000-0x0fff] to [bus 02-
> 39] add_size 1000
> > [ 1660.895318] pci 0000:01:00.0: BAR 13: assigned [io  0x2000-0x2fff]
> > [ 1660.895321] pci 0000:02:01.0: BAR 13: assigned [io  0x2000-0x2fff]
> > [ 1660.895322] pci 0000:02:00.0: PCI bridge to [bus 03]
> > [ 1660.895329] pci 0000:02:00.0:   bridge window [mem 0xda000000-0xda0fffff]
> > [ 1660.895338] pci 0000:02:01.0: PCI bridge to [bus 04-38]
> > [ 1660.895341] pci 0000:02:01.0:   bridge window [io  0x2000-0x2fff]
> > [ 1660.895346] pci 0000:02:01.0:   bridge window [mem 0xc4000000-0xd9efffff]
> > [ 1660.895351] pci 0000:02:01.0:   bridge window [mem 0xa0000000-0xc1ffffff
> 64bit pref]
> > [ 1660.895357] pci 0000:02:02.0: PCI bridge to [bus 39]
> > [ 1660.895363] pci 0000:02:02.0:   bridge window [mem 0xd9f00000-0xd9ffffff]
> > [ 1660.895372] pci 0000:01:00.0: PCI bridge to [bus 02-39]
> > [ 1660.895374] pci 0000:01:00.0:   bridge window [io  0x2000-0x2fff]
> > [ 1660.895379] pci 0000:01:00.0:   bridge window [mem 0xc4000000-0xda0fffff]
> > [ 1660.895383] pci 0000:01:00.0:   bridge window [mem 0xa0000000-0xc1ffffff
> 64bit pref]
> > [ 1661.283910] pcieport 0000:01:00.0: enabling device (0006 -> 0007)
> > [ 1661.284659] pcieport 0000:02:01.0: enabling device (0006 -> 0007)
> > [ 1661.285546] thunderbolt 0000:03:00.0: NHI initialized, starting thunderbolt
> > [ 1661.285550] thunderbolt 0000:03:00.0: allocating TX ring 0 of size 10
> > [ 1661.285565] thunderbolt 0000:03:00.0: allocating RX ring 0 of size 10
> > [ 1661.285582] thunderbolt 0000:03:00.0: control channel created
> > [ 1661.285583] thunderbolt 0000:03:00.0: control channel starting...
> > [ 1661.285584] thunderbolt 0000:03:00.0: starting TX ring 0
> > [ 1661.285591] thunderbolt 0000:03:00.0: enabling interrupt at register 0x38200
> bit 0 (0x0 -> 0x1)
> > [ 1661.285592] thunderbolt 0000:03:00.0: starting RX ring 0
> > [ 1661.285599] thunderbolt 0000:03:00.0: enabling interrupt at register 0x38200
> bit 12 (0x1 -> 0x1001)
> > [ 1661.731122] ACPI Error: Cannot release Mutex [PATM], not acquired
> (20170303/exmutex-393)
> > [ 1661.731143] ACPI Error: Method parse/execution failed
> [\_SB.PCI0.LPCB.ECDV._Q66] (Node ffff8ba73017bf00),
> AE_AML_MUTEX_NOT_ACQUIRED (20170303/psparse-543)
> > [ 1662.538307] thunderbolt 0000:03:00.0: current switch config:
> > [ 1662.538315] thunderbolt 0000:03:00.0:  Switch: 8086:1576 (Revision: 4, TB
> Version: 2)
> > [ 1662.538319] thunderbolt 0000:03:00.0:   Max Port Number: 11
> > [ 1662.538322] thunderbolt 0000:03:00.0:   Config:
> > [ 1662.538329] thunderbolt 0000:03:00.0:    Upstream Port Number: 5 Depth: 0
> Route String: 0x0 Enabled: 1, PlugEventsDelay: 254ms
> > [ 1662.538333] thunderbolt 0000:03:00.0:    unknown1: 0x0 unknown4: 0x0
> > [ 1662.561266] thunderbolt 0000:03:00.0: 0: uid: 0x8086a3422131ea10
> > [ 1662.561856] thunderbolt 0000:03:00.0:  Port 0: 8086:1576 (Revision: 4, TB
> Version: 1, Type: Port (0x1))
> > [ 1662.561860] thunderbolt 0000:03:00.0:   Max hop id (in/out): 7/7
> > [ 1662.561864] thunderbolt 0000:03:00.0:   Max counters: 8
> > [ 1662.561868] thunderbolt 0000:03:00.0:   NFC Credits: 0x800000
> > [ 1662.562078] thunderbolt 0000:03:00.0:  Port 1: 8086:1576 (Revision: 4, TB
> Version: 1, Type: Port (0x1))
> > [ 1662.562082] thunderbolt 0000:03:00.0:   Max hop id (in/out): 15/15
> > [ 1662.562086] thunderbolt 0000:03:00.0:   Max counters: 16
> > [ 1662.562090] thunderbolt 0000:03:00.0:   NFC Credits: 0x7800000
> > [ 1662.562323] thunderbolt 0000:03:00.0:  Port 2: 8086:1576 (Revision: 4, TB
> Version: 1, Type: Port (0x1))
> > [ 1662.562328] thunderbolt 0000:03:00.0:   Max hop id (in/out): 15/15
> > [ 1662.562331] thunderbolt 0000:03:00.0:   Max counters: 16
> > [ 1662.562335] thunderbolt 0000:03:00.0:   NFC Credits: 0x0
> > [ 1662.562568] thunderbolt 0000:03:00.0:  Port 3: 8086:1576 (Revision: 4, TB
> Version: 1, Type: Port (0x1))
> > [ 1662.562575] thunderbolt 0000:03:00.0:   Max hop id (in/out): 15/15
> > [ 1662.562579] thunderbolt 0000:03:00.0:   Max counters: 16
> > [ 1662.562583] thunderbolt 0000:03:00.0:   NFC Credits: 0x3c00000
> > [ 1662.562797] thunderbolt 0000:03:00.0:  Port 4: 8086:1576 (Revision: 4, TB
> Version: 1, Type: Port (0x1))
> > [ 1662.562801] thunderbolt 0000:03:00.0:   Max hop id (in/out): 15/15
> > [ 1662.562805] thunderbolt 0000:03:00.0:   Max counters: 16
> > [ 1662.562808] thunderbolt 0000:03:00.0:   NFC Credits: 0x3c00000
> > [ 1662.562813] thunderbolt 0000:03:00.0: 0:5: disabled by eeprom
> > [ 1662.562873] thunderbolt 0000:03:00.0:  Port 6: 8086:1576 (Revision: 4, TB
> Version: 1, Type: PCIe (0x100101))
> > [ 1662.562877] thunderbolt 0000:03:00.0:   Max hop id (in/out): 8/8
> > [ 1662.562880] thunderbolt 0000:03:00.0:   Max counters: 2
> > [ 1662.562884] thunderbolt 0000:03:00.0:   NFC Credits: 0x800000
> > [ 1662.562938] thunderbolt 0000:03:00.0:  Port 7: 8086:1576 (Revision: 4, TB
> Version: 1, Type: PCIe (0x100101))
> > [ 1662.562942] thunderbolt 0000:03:00.0:   Max hop id (in/out): 8/8
> > [ 1662.562945] thunderbolt 0000:03:00.0:   Max counters: 2
> > [ 1662.562949] thunderbolt 0000:03:00.0:   NFC Credits: 0x800000
> > [ 1662.563005] thunderbolt 0000:03:00.0:  Port 8: 8086:1576 (Revision: 4, TB
> Version: 1, Type: DP/HDMI (0xe0102))
> > [ 1662.563009] thunderbolt 0000:03:00.0:   Max hop id (in/out): 9/9
> > [ 1662.563012] thunderbolt 0000:03:00.0:   Max counters: 2
> > [ 1662.563016] thunderbolt 0000:03:00.0:   NFC Credits: 0x800000
> > [ 1662.563019] thunderbolt 0000:03:00.0: 0:9: disabled by eeprom
> > [ 1662.563082] thunderbolt 0000:03:00.0:  Port 10: 8086:1576 (Revision: 4, TB
> Version: 1, Type: DP/HDMI (0xe0101))
> > [ 1662.563085] thunderbolt 0000:03:00.0:   Max hop id (in/out): 9/9
> > [ 1662.563089] thunderbolt 0000:03:00.0:   Max counters: 2
> > [ 1662.563092] thunderbolt 0000:03:00.0:   NFC Credits: 0x1000000
> > [ 1662.563096] thunderbolt 0000:03:00.0: 0:b: disabled by eeprom
> > [ 1662.564973] thunderbolt 0000:03:00.0: current switch config:
> > [ 1662.564983] thunderbolt 0000:03:00.0:  Switch: 8086:1578 (Revision: 4, TB
> Version: 2)
> > [ 1662.564989] thunderbolt 0000:03:00.0:   Max Port Number: 11
> > [ 1662.564994] thunderbolt 0000:03:00.0:   Config:
> > [ 1662.565004] thunderbolt 0000:03:00.0:    Upstream Port Number: 1 Depth: 1
> Route String: 0x1 Enabled: 1, PlugEventsDelay: 254ms
> > [ 1662.565011] thunderbolt 0000:03:00.0:    unknown1: 0x0 unknown4: 0x0
> > [ 1662.586185] thunderbolt 0000:03:00.0: 1: reading drom (length: 0x6e)
> > [ 1662.685656] thunderbolt 0000:03:00.0: 1: drom data crc32 mismatch
> (expected: 0xaf438340, got: 0xaf4383c0), continuing
> > [ 1662.685923] thunderbolt 0000:03:00.0: 1: uid: 0xd40f7a7928c300
> > [ 1662.685970] thunderbolt 0000:03:00.0:  Port 0: 8086:1578 (Revision: 4, TB
> Version: 1, Type: Port (0x1))
> > [ 1662.685972] thunderbolt 0000:03:00.0:   Max hop id (in/out): 7/7
> > [ 1662.685974] thunderbolt 0000:03:00.0:   Max counters: 8
> > [ 1662.685976] thunderbolt 0000:03:00.0:   NFC Credits: 0x800000
> > [ 1662.686163] thunderbolt 0000:03:00.0:  Port 1: 8086:1578 (Revision: 4, TB
> Version: 1, Type: Port (0x1))
> > [ 1662.686165] thunderbolt 0000:03:00.0:   Max hop id (in/out): 15/15
> > [ 1662.686167] thunderbolt 0000:03:00.0:   Max counters: 16
> > [ 1662.686169] thunderbolt 0000:03:00.0:   NFC Credits: 0x7800000
> > [ 1662.686346] thunderbolt 0000:03:00.0:  Port 2: 8086:1578 (Revision: 4, TB
> Version: 1, Type: Port (0x1))
> > [ 1662.686348] thunderbolt 0000:03:00.0:   Max hop id (in/out): 15/15
> > [ 1662.686350] thunderbolt 0000:03:00.0:   Max counters: 16
> > [ 1662.686351] thunderbolt 0000:03:00.0:   NFC Credits: 0x0
> > [ 1662.686520] thunderbolt 0000:03:00.0:  Port 3: 8086:1578 (Revision: 4, TB
> Version: 1, Type: Port (0x1))
> > [ 1662.686522] thunderbolt 0000:03:00.0:   Max hop id (in/out): 15/15
> > [ 1662.686523] thunderbolt 0000:03:00.0:   Max counters: 16
> > [ 1662.686525] thunderbolt 0000:03:00.0:   NFC Credits: 0x7800000
> > [ 1662.686697] thunderbolt 0000:03:00.0:  Port 4: 8086:1578 (Revision: 4, TB
> Version: 1, Type: Port (0x1))
> > [ 1662.686698] thunderbolt 0000:03:00.0:   Max hop id (in/out): 15/15
> > [ 1662.686700] thunderbolt 0000:03:00.0:   Max counters: 16
> > [ 1662.686702] thunderbolt 0000:03:00.0:   NFC Credits: 0x0
> > [ 1662.686704] thunderbolt 0000:03:00.0: 1:5: disabled by eeprom
> > [ 1662.686757] thunderbolt 0000:03:00.0:  Port 6: 8086:1578 (Revision: 4, TB
> Version: 1, Type: PCIe (0x100102))
> > [ 1662.686758] thunderbolt 0000:03:00.0:   Max hop id (in/out): 8/8
> > [ 1662.686760] thunderbolt 0000:03:00.0:   Max counters: 2
> > [ 1662.686762] thunderbolt 0000:03:00.0:   NFC Credits: 0x800000
> > [ 1662.686816] thunderbolt 0000:03:00.0:  Port 7: 8086:1578 (Revision: 4, TB
> Version: 1, Type: PCIe (0x100101))
> > [ 1662.686818] thunderbolt 0000:03:00.0:   Max hop id (in/out): 8/8
> > [ 1662.686820] thunderbolt 0000:03:00.0:   Max counters: 2
> > [ 1662.686822] thunderbolt 0000:03:00.0:   NFC Credits: 0x800000
> > [ 1662.686825] thunderbolt 0000:03:00.0: 1:8: disabled by eeprom
> > [ 1662.686827] thunderbolt 0000:03:00.0: 1:9: disabled by eeprom
> > [ 1662.686830] thunderbolt 0000:03:00.0: 1:a: disabled by eeprom
> > [ 1662.686832] thunderbolt 0000:03:00.0: 1:b: disabled by eeprom
> > [ 1662.688262] thunderbolt 0000:03:00.0: current switch config:
> > [ 1662.688271] thunderbolt 0000:03:00.0:  Switch: 8086:1578 (Revision: 4, TB
> Version: 2)
> > [ 1662.688273] thunderbolt 0000:03:00.0:   Max Port Number: 11
> > [ 1662.688275] thunderbolt 0000:03:00.0:   Config:
> > [ 1662.688284] thunderbolt 0000:03:00.0:    Upstream Port Number: 1 Depth: 2
> Route String: 0x301 Enabled: 1, PlugEventsDelay: 254ms
> > [ 1662.688287] thunderbolt 0000:03:00.0:    unknown1: 0x0 unknown4: 0x0
> > [ 1666.261728] pci 0000:04:00.0: [8086:1578] type 01 class 0x060400
> > [ 1666.262033] pci 0000:04:00.0: supports D1 D2
> > [ 1666.262034] pci 0000:04:00.0: PME# supported from D0 D1 D2 D3hot D3cold
> > [ 1666.262442] sysfs: cannot create duplicate filename '/class/pci_bus/0000:05'
> 
> This is probably due the previous problem of the PCI device being hidden
> behind a bridge.
> 
> If you shutdown the machine and boot it without devices connected and
> then when the OS is up, connect the device, do you see the same issue?
> 

The kernel traceback doesn't happen in this scenario, but if I follow these steps:
1) Boot
2) Plugin dock, make sure fully enumerated
3) Unplug
4) Replug

I get the trackeback warning about duplicate filenames again.

The second time I unplug I also get tracebacks related to a NULL pointer dereference
In kernfs_find_ns.

> Also can you try so that you power off the machine completely, connect
> the device and power it on. Do you see the issue?
> 

Yes, I do see error from the first syslog snippet about being stuck behind a host bridge.