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

[Mika Westerberg]

On Fri, May 19, 2017 at 05:54:37PM +0000, Mario.Limonciello@xxxxxxxx wrote:
> > 
> > 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.

You mean in Windows you don't reproduce the problem, right? Even when
you reboot the machine with devices connected.

I tried on Intel Skull Canyon NUC so that I disabled the thunderbolt
driver and after reboot (warm) I can see the PCI scan error about bus
being partially hidden behind a bridge.

When this happens PCIe ports of the thunderbolt device/host seem to be
unconfigured and Linux then decides to reconfigure them which leads to
the problem. When it works we get ACPI hotplug event to the PCIe root
port and the PCIe upstream/downstream ports are properly configured by
the BIOS.

I guess Windows does something differently here than what we do when PCI
devices are enumerated.

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

Can you send me full dmesg when you do the above steps?

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

Yes, it starts to break down when the PCI device is left there and tried
to be added back after hotplug.