search

AsahiLinux / linux

Linux kernel source tree
Other
2.25k stars 87 forks source link

Power gating PCIe does not work properly #18

Open kit-ty-kate opened 2 years ago

kit-ty-kate commented 2 years ago

Machine: macbook air 2020

In a few cases the wifi pcie device is not detected by the kernel. There seems to be a common (rather odd) pattern:

This is rather odd but it happend on the two times I booted the machine after having left it for a few hours, but never in the 50-ish reboot or poweroff+wait+boot I tried during the couple of hours after the first time it happened.

Here is the diff of dmesg output between a boot which detected the wifi pcie device and a boot that did not:

--- dmesg-20220305-1.log    2022-03-05 22:44:35.000000000 +0000
+++ dmesg-20220305-4.log    2022-03-05 22:44:42.000000000 +0000
@@ -10,11 +10,11 @@
   Normal   empty
 Movable zone start for each node
 Early memory node ranges
-  node   0: [mem 0x0000000801cbc000-0x0000000802827fff]
-  node   0: [mem 0x0000000802828000-0x00000008028e7fff]
-  node   0: [mem 0x00000008028e8000-0x000000080437ffff]
-  node   0: [mem 0x0000000804380000-0x000000080439bfff]
-  node   0: [mem 0x000000080439c000-0x0000000bd9f6ffff]
+  node   0: [mem 0x0000000801cbc000-0x0000000802c3ffff]
+  node   0: [mem 0x0000000802c40000-0x0000000802cfffff]
+  node   0: [mem 0x0000000802d00000-0x000000080477ffff]
+  node   0: [mem 0x0000000804780000-0x000000080479bfff]
+  node   0: [mem 0x000000080479c000-0x0000000bd9f6ffff]
   node   0: [mem 0x0000000bd9f70000-0x0000000bd9f7bfff]
   node   0: [mem 0x0000000bd9f7c000-0x0000000bdefaffff]
   node   0: [mem 0x0000000bdefb0000-0x0000000bdefbffff]
@@ -85,12 +85,12 @@
 x26: 0000000000000000 x25: 0000000000000000 x24: 0000000000000000
 x23: 0000000000000000 x22: 0000000000000000 x21: ffff8000092cc000
 x20: ffff800009270a20 x19: ffff0003731bd388 x18: 0000000000000050
-x17: 00000000aa9d7b42 x16: 000000003fc4a5b8 x15: fffffffffffc1488
-x14: 000000009f4d7c9d x13: ffff80000914e240 x12: 00000000000000de
+x17: 000000009e275909 x16: 00000000cefee570 x15: fffffffffffc1488
+x14: 000000006dd3b4dc x13: ffff80000914e240 x12: 00000000000000de
 x11: 000000000000004a x10: ffff8000091fe930 x9 : ffff80000914e240
 x8 : 00000000ffffdfff x7 : ffff8000091fe240 x6 : 00000000000006f0
 x5 : 0000000000017ff4 x4 : 00000000ffffe04a x3 : 0000000000000000
-x2 : 0000000000000000 x1 : 0000000000000000 x0 : ffff000001e34040
+x2 : 0000000000000000 x1 : 0000000000000000 x0 : ffff000001e2e4c0
 Call trace:
  efi_create_mapping+0x7c/0x16c
  arm_enable_runtime_services+0x12c/0x1e0
@@ -207,7 +207,7 @@
 nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering...
 NET: Registered PF_ALG protocol family
 xor: measuring software checksum speed
-   8regs           : 13168 MB/sec
+   8regs           : 13199 MB/sec
    32regs          : 26794 MB/sec
    arm64_neon      : 27584 MB/sec
 xor: using function: arm64_neon (27584 MB/sec)
@@ -269,24 +269,24 @@
 apple-gpio-pinctrl 23c100000.pinctrl: No cache defaults, reading back from HW
 apple-gpio-pinctrl 23d1f0000.pinctrl: No cache defaults, reading back from HW
 macsmc-rtkit 23e400000.smc: RTKit: Initializing (protocol version 12)
-apple-gpio-pinctrl 23e820000.pinctrl: No cache defaults, reading back from HW
 nvme-apple 27bcc0000.nvme: RTKit: Initializing (protocol version 12)
-apple-gpio-pinctrl 24a820000.pinctrl: No cache defaults, reading back from HW
+apple-gpio-pinctrl 23e820000.pinctrl: No cache defaults, reading back from HW
 macsmc-rtkit 23e400000.smc: Initialized (1378 keys #KEY (0x234b4559)..zETM (0x7a45544d))
-OF: Bad cell count for /soc/spmi@23d0d9300/pmu@f
-OF: Bad cell count for /soc/spmi@23d0d9300/pmu@f
-OF: Bad cell count for /soc/spmi@23d0d9300/pmu@f
-OF: Bad cell count for /soc/spmi@23d0d9300/pmu@f
-OF: Bad cell count for /soc/spmi@23d0d9300/pmu@f
-OF: Bad cell count for /soc/spmi@23d0d9300/pmu@f
+apple-gpio-pinctrl 24a820000.pinctrl: No cache defaults, reading back from HW
 nvme-apple 27bcc0000.nvme: RTKit: syslog message: cmd.c:6025:  boot mode normal
 nvme-apple 27bcc0000.nvme: RTKit: syslog message: nvme_admin_ans2.c:2880: Invalid namespace 0
 nvme nvme0: Identify NS List failed (status=0xb)
 nvme-apple 27bcc0000.nvme: RTKit: syslog message: nvme_admin_ans2.c:2880: Invalid namespace 0
  nvme0n1: p1 p2 p3 p4 p5 p6
 spi-hid-apple-of spi0.0: spihid_apple_of_probe:74
+OF: Bad cell count for /soc/spmi@23d0d9300/pmu@f
+OF: Bad cell count for /soc/spmi@23d0d9300/pmu@f
+OF: Bad cell count for /soc/spmi@23d0d9300/pmu@f
+OF: Bad cell count for /soc/spmi@23d0d9300/pmu@f
+OF: Bad cell count for /soc/spmi@23d0d9300/pmu@f
+OF: Bad cell count for /soc/spmi@23d0d9300/pmu@f
 macsmc-rtc macsmc-rtc: registered as rtc0
-macsmc-rtc macsmc-rtc: setting system clock to 2022-03-05T13:25:28 UTC (1646486728)
+macsmc-rtc macsmc-rtc: setting system clock to 2022-03-05T22:15:50 UTC (1646518550)
 dwc3 382280000.usb: Adding to iommu group 0
 spi-hid-apple-of spi0.0: limiting the number of devices to mngt, kbd and mouse
 dwc3 502280000.usb: Adding to iommu group 1
@@ -298,7 +298,6 @@
 apple 001C:05AC:0281.0001: input,hidraw0: SPI HID v9.35 Keyboard [Apple Internal Keyboard / Trackpad] on spi0.0 (1)
 input: Apple Internal Keyboard / Trackpad as /devices/platform/soc/23510c000.spi/spi_master/spi0/spi0.0/001C:05AC:0281.0002/input/input6
 magicmouse 001C:05AC:0281.0002: input,hidraw1: SPI HID v9.35 Mouse [Apple Internal Keyboard / Trackpad] on spi0.0 (2)
-EXT4-fs (nvme0n1p5): mounted filesystem with ordered data mode. Quota mode: none.
 xhci-hcd xhci-hcd.0.auto: xHCI Host Controller
 xhci-hcd xhci-hcd.0.auto: new USB bus registered, assigned bus number 1
 xhci-hcd xhci-hcd.0.auto: hcc params 0x0238ffcd hci version 0x110 quirks 0x0000000000010010
@@ -321,6 +320,7 @@
 usb usb2: SerialNumber: xhci-hcd.0.auto
 hub 2-0:1.0: USB hub found
 hub 2-0:1.0: 1 port detected
+EXT4-fs (nvme0n1p5): mounted filesystem with ordered data mode. Quota mode: none.
 xhci-hcd xhci-hcd.1.auto: xHCI Host Controller
 xhci-hcd xhci-hcd.1.auto: new USB bus registered, assigned bus number 3
 xhci-hcd xhci-hcd.1.auto: hcc params 0x0238ffcd hci version 0x110 quirks 0x0000000000010010
@@ -346,8 +346,6 @@
 systemd[1]: systemd 250.3-4-arch running in system mode (+PAM +AUDIT -SELINUX -APPARMOR -IMA +SMACK +SECCOMP +GCRYPT +GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBFDISK +PCRE2 -PWQUALITY +P11KIT -QRENCODE +BZIP2 +LZ4 +XZ +ZLIB +ZSTD -BPF_FRAMEWORK +XKBCOMMON +UTMP -SYSVINIT default-hierarchy=unified)
 systemd[1]: Detected architecture arm64.
 systemd[1]: Hostname set to <alarm>.
-systemd[1]: Condition check resulted in Root Slice being skipped.
-systemd[1]: Condition check resulted in System Slice being skipped.
 systemd[1]: Queued start job for default target Graphical Interface.
 random: systemd: uninitialized urandom read (16 bytes read)
 systemd[1]: Created slice Slice /system/getty.
@@ -390,6 +388,7 @@
 systemd[1]: Starting Generate network units from Kernel command line...
 systemd[1]: Starting Remount Root and Kernel File Systems...
 systemd[1]: Repartition Root Disk was skipped because all trigger condition checks failed.
+fuse: init (API version 7.36)
 systemd[1]: Starting Coldplug udev Block Devices...
 systemd[1]: Mounted Huge Pages File System.
 systemd[1]: Mounted POSIX Message Queue File System.
@@ -397,30 +396,29 @@
 systemd[1]: Mounted Temporary Directory /tmp.
 systemd[1]: Finished Create List of Static Device Nodes.
 systemd[1]: modprobe@configfs.service: Deactivated successfully.
-fuse: init (API version 7.36)
 systemd[1]: Finished Load Kernel Module configfs.
 systemd[1]: modprobe@drm.service: Deactivated successfully.
 systemd[1]: Finished Load Kernel Module drm.
-systemd[1]: Finished Load Kernel Modules.
 systemd[1]: modprobe@fuse.service: Deactivated successfully.
+EXT4-fs (nvme0n1p5): re-mounted. Quota mode: none.
 systemd[1]: Finished Load Kernel Module fuse.
-systemd[1]: Mounting FUSE Control File System...
-systemd[1]: Mounting Kernel Configuration File System...
-systemd[1]: Starting Apply Kernel Variables...
+systemd[1]: Finished Load Kernel Modules.
 systemd[1]: Finished Generate network units from Kernel command line.
-systemd[1]: Finished Coldplug udev Block Devices.
-EXT4-fs (nvme0n1p5): re-mounted. Quota mode: none.
-systemd[1]: Mounted FUSE Control File System.
-systemd[1]: Mounted Kernel Configuration File System.
 systemd[1]: Finished Remount Root and Kernel File Systems.
+systemd[1]: Finished Coldplug udev Block Devices.
 systemd[1]: Reached target Preparation for Network.
+systemd[1]: Mounting FUSE Control File System...
+systemd[1]: Mounting Kernel Configuration File System...
 systemd[1]: First Boot Wizard was skipped because of a failed condition check (ConditionFirstBoot=yes).
 systemd[1]: Starting Grow File System on /...
 systemd[1]: Rebuild Hardware Database was skipped because of a failed condition check (ConditionNeedsUpdate=/etc).
 systemd[1]: Platform Persistent Storage Archival was skipped because of a failed condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore).
 systemd[1]: Starting Load/Save Random Seed...
+systemd[1]: Starting Apply Kernel Variables...
 systemd[1]: Create System Users was skipped because of a failed condition check (ConditionNeedsUpdate=/etc).
 systemd[1]: Starting Create Static Device Nodes in /dev...
+systemd[1]: Mounted FUSE Control File System.
+systemd[1]: Mounted Kernel Configuration File System.
 systemd[1]: Finished Apply Kernel Variables.
 EXT4-fs (nvme0n1p5): resizing filesystem from 23704490 to 23704490 blocks
 systemd[1]: Finished Grow File System on /.
@@ -433,35 +431,37 @@
 systemd[1]: Entropy Daemon based on the HAVEGE algorithm was skipped because of a failed condition check (ConditionKernelVersion=<5.6).
 systemd[1]: Starting Journal Service...
 systemd[1]: Starting Rule-based Manager for Device Events and Files...
+systemd[1]: Started Rule-based Manager for Device Events and Files.
+audit: type=1130 audit(1646518550.811:2): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-udevd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
+audit: type=1334 audit(1646518550.812:3): prog-id=12 op=LOAD
+systemd[1]: Starting Network Configuration...
 systemd[1]: Started Journal Service.
-audit: type=1130 audit(1646486728.775:2): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-journald comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
-systemd-journald[322]: Received client request to flush runtime journal.
-audit: type=1130 audit(1646486728.787:3): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-udevd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
-audit: type=1334 audit(1646486728.787:4): prog-id=12 op=LOAD
-audit: type=1130 audit(1646486728.811:5): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-journal-flush comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
+audit: type=1130 audit(1646518550.819:4): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-journald comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
+systemd-journald[319]: Received client request to flush runtime journal.
 cfg80211: Loading compiled-in X.509 certificates for regulatory database
+audit: type=1130 audit(1646518550.856:5): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-journal-flush comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
 cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
 platform regulatory.0: Direct firmware load for regulatory.db failed with error -2
 cfg80211: failed to load regulatory.db
-audit: type=1130 audit(1646486728.859:6): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-networkd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
+audit: type=1130 audit(1646518550.864:6): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-networkd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
 FAT-fs (nvme0n1p4): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
-audit: type=1130 audit(1646486728.897:7): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=update-vendor-firmware comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
-audit: type=1130 audit(1646486728.902:8): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-boot-update comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
-audit: type=1130 audit(1646486728.925:9): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-tmpfiles-setup comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
-audit: type=1334 audit(1646486728.926:10): prog-id=13 op=LOAD
+audit: type=1130 audit(1646518550.925:7): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=update-vendor-firmware comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
+audit: type=1130 audit(1646518550.930:8): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-boot-update comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
+audit: type=1130 audit(1646518550.954:9): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-tmpfiles-setup comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
+audit: type=1334 audit(1646518550.955:10): prog-id=13 op=LOAD
 alg: No test for hmac(md4) (hmac(md4-generic))
-cs42l42 2-0048: No cache used with register defaults set!
-cs42l42 2-0048: supply VA not found, using dummy regulator
-cs42l42 2-0048: supply VP not found, using dummy regulator
-cs42l42 2-0048: supply VCP not found, using dummy regulator
-cs42l42 2-0048: supply VD_FILT not found, using dummy regulator
-cs42l42 2-0048: supply VL not found, using dummy regulator
+cs42l42 0-0048: No cache used with register defaults set!
+cs42l42 0-0048: supply VA not found, using dummy regulator
+cs42l42 0-0048: supply VP not found, using dummy regulator
+cs42l42 0-0048: supply VCP not found, using dummy regulator
+cs42l42 0-0048: supply VD_FILT not found, using dummy regulator
+cs42l42 0-0048: supply VL not found, using dummy regulator
+cs42l42 0-0048: CS42L42 Device ID (42A83). Expected 42A42
+cs42l42 0-0048: Cirrus Logic CS42L42, Revision: B0
 macsmc-gpio macsmc-gpio: First GPIO key: gP01 (0x67503031)
-cs42l42 2-0048: CS42L42 Device ID (42A83). Expected 42A42
 pcie-apple 690000000.pcie: host bridge /soc/pcie@690000000 ranges:
 pcie-apple 690000000.pcie:      MEM 0x06a0000000..0x06bfffffff -> 0x06a0000000
 pcie-apple 690000000.pcie:      MEM 0x06c0000000..0x06ffffffff -> 0x00c0000000
-cs42l42 2-0048: Cirrus Logic CS42L42, Revision: B0
 macsmc-reboot macsmc-reboot: Handling reboot and poweroff requests via SMC
 pcie-apple 690000000.pcie: Link up on /soc/pcie@690000000/pci@0,0
 pcie-apple 690000000.pcie: ECAM at [mem 0x690000000-0x690ffffff] for [bus 00-03]
@@ -472,64 +472,21 @@
 pci 0000:00:00.0: [106b:100c] type 01 class 0x060400
 pci 0000:00:00.0: PME# supported from D0 D3hot D3cold
 pci 0000:00:00.0: bridge configuration invalid ([bus 00-00]), reconfiguring
-pci 0000:01:00.0: [14e4:4425] type 00 class 0x028000
-pci 0000:01:00.0: reg 0x10: [mem 0x00000000-0x0000ffff 64bit]
-pci 0000:01:00.0: reg 0x18: [mem 0x00000000-0x007fffff 64bit]
-pci 0000:01:00.0: supports D1 D2
-pci 0000:01:00.0: PME# supported from D0 D1 D2 D3hot D3cold
-pci 0000:01:00.0: 2.000 Gb/s available PCIe bandwidth, limited by 2.5 GT/s PCIe x1 link at 0000:00:00.0 (capable of 4.000 Gb/s with 5.0 GT/s PCIe x1 link)
-pci 0000:01:00.1: [14e4:5f69] type 00 class 0x028000
-pci 0000:01:00.1: reg 0x10: [mem 0x00000000-0x00007fff 64bit]
-pci 0000:01:00.1: reg 0x18: [mem 0x00000000-0x003fffff 64bit]
-pci 0000:01:00.1: supports D1 D2
-pci 0000:01:00.1: PME# supported from D0 D1 D2 D3hot D3cold
 pci_bus 0000:01: busn_res: [bus 01-03] end is updated to 01
-pci 0000:00:00.0: BAR 14: assigned [mem 0x6c0000000-0x6c0dfffff]
-pci 0000:01:00.0: BAR 2: assigned [mem 0x6c0000000-0x6c07fffff 64bit]
-pci 0000:01:00.1: BAR 2: assigned [mem 0x6c0800000-0x6c0bfffff 64bit]
-pci 0000:01:00.0: BAR 0: assigned [mem 0x6c0c00000-0x6c0c0ffff 64bit]
-pci 0000:01:00.1: BAR 0: assigned [mem 0x6c0c10000-0x6c0c17fff 64bit]
 pci 0000:00:00.0: PCI bridge to [bus 01]
-pci 0000:00:00.0:   bridge window [mem 0x6c0000000-0x6c0dfffff]
 OF: /soc/pcie@690000000: no iommu-map translation for id 0x0 on (null)
-pcieport 0000:00:00.0: enabling device (0000 -> 0002)
 pcieport 0000:00:00.0: PME: Signaling with IRQ 103
 pcieport 0000:00:00.0: AER: enabled with IRQ 103
-usbcore: registered new interface driver brcmfmac
-brcmfmac 0000:01:00.0: Adding to iommu group 2
-brcmfmac 0000:01:00.0: enabling device (0000 -> 0002)
-brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac4378b1-pcie for chip BCM4378/3
-brcmfmac 0000:01:00.0: Direct firmware load for brcm/brcmfmac4378b1-pcie.apple,shikoku-RASP-u-6.5-X3.bin failed with error -2
-brcmfmac 0000:01:00.0: Direct firmware load for brcm/brcmfmac4378b1-pcie.apple,shikoku-RASP-u-6.5.bin failed with error -2
-brcmfmac 0000:01:00.0: Direct firmware load for brcm/brcmfmac4378b1-pcie.apple,shikoku-RASP-u.bin failed with error -2
-brcmfmac 0000:01:00.0: Direct firmware load for brcm/brcmfmac4378b1-pcie.apple,shikoku-RASP.bin failed with error -2
-brcmfmac 0000:01:00.0: Direct firmware load for brcm/brcmfmac4378b1-pcie.apple,shikoku-X3.bin failed with error -2
-brcmfmac: brcmf_c_process_txcap_blob: TxCap blob found, loading
-brcmfmac: brcmf_c_process_cal_blob: Calibration blob provided by platform, loading
-brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4378/3 wl0: Oct 26 2021 16:10:41 version 18.20.310.15.7.8.120 FWID 01-5d6c3867
 random: crng init done
 random: 7 urandom warning(s) missed due to ratelimiting
-systemd-journald[322]: Time jumped backwards, rotating.
-kauditd_printk_skb: 21 callbacks suppressed
-audit: type=1100 audit(1646486729.772:32): pid=431 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_securetty,pam_shells,pam_faillock,pam_permit,pam_faillock acct="root" exe="/usr/bin/login" hostname=alarm addr=? terminal=/dev/tty1 res=success'
-audit: type=1101 audit(1646486729.773:33): pid=431 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_permit,pam_time acct="root" exe="/usr/bin/login" hostname=alarm addr=? terminal=/dev/tty1 res=success'
-audit: type=1103 audit(1646486729.773:34): pid=431 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_securetty,pam_shells,pam_faillock,pam_permit,pam_faillock acct="root" exe="/usr/bin/login" hostname=alarm addr=? terminal=/dev/tty1 res=success'
-audit: type=1006 audit(1646486729.774:35): pid=431 uid=0 old-auid=4294967295 auid=0 tty=tty1 old-ses=4294967295 ses=1 res=1
-audit: type=1300 audit(1646486729.774:35): arch=c00000b7 syscall=64 success=yes exit=1 a0=4 a1=fffff4e29250 a2=1 a3=ffff87b4cc60 items=0 ppid=1 pid=431 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=tty1 ses=1 comm="login" exe="/usr/bin/login" key=(null)
-audit: type=1327 audit(1646486729.774:35): proctitle=2F62696E2F6C6F67696E002D70002D2D
-audit: type=1130 audit(1646486729.791:36): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=user-runtime-dir@0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
-audit: type=1101 audit(1646486729.796:37): pid=436 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_permit,pam_time acct="root" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
-audit: type=1103 audit(1646486729.796:38): pid=436 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=? acct="root" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
-audit: type=1006 audit(1646486729.796:39): pid=436 uid=0 old-auid=4294967295 auid=0 tty=(none) old-ses=4294967295 ses=2 res=1
-kauditd_printk_skb: 15 callbacks suppressed
-audit: type=1130 audit(1646487092.269:49): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=getty@tty2 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
-audit: type=1100 audit(1646487101.735:50): pid=509 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_securetty,pam_shells,pam_faillock,pam_permit,pam_faillock acct="kit_ty_kate" exe="/usr/bin/login" hostname=alarm addr=? terminal=/dev/tty2 res=success'
-audit: type=1101 audit(1646487101.735:51): pid=509 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_permit,pam_time acct="kit_ty_kate" exe="/usr/bin/login" hostname=alarm addr=? terminal=/dev/tty2 res=success'
-audit: type=1103 audit(1646487101.736:52): pid=509 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_securetty,pam_shells,pam_faillock,pam_permit,pam_faillock acct="kit_ty_kate" exe="/usr/bin/login" hostname=alarm addr=? terminal=/dev/tty2 res=success'
-audit: type=1006 audit(1646487101.736:53): pid=509 uid=0 old-auid=4294967295 auid=1001 tty=tty2 old-ses=4294967295 ses=3 res=1
-audit: type=1300 audit(1646487101.736:53): arch=c00000b7 syscall=64 success=yes exit=4 a0=5 a1=ffffea2dc530 a2=4 a3=ffff22b6cc60 items=0 ppid=1 pid=509 auid=1001 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=1001 fsgid=0 tty=tty2 ses=3 comm="login" exe="/usr/bin/login" key=(null)
-audit: type=1327 audit(1646487101.736:53): proctitle=2F62696E2F6C6F67696E002D70002D2D
-audit: type=1130 audit(1646487101.742:54): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=user-runtime-dir@1001 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
-audit: type=1101 audit(1646487101.748:55): pid=511 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_permit,pam_time acct="kit_ty_kate" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
-audit: type=1103 audit(1646487101.748:56): pid=511 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=? acct="kit_ty_kate" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
-audit: type=1006 audit(1646487101.748:57): pid=511 uid=0 old-auid=4294967295 auid=1001 tty=(none) old-ses=4294967295 ses=4 res=1
+kauditd_printk_skb: 20 callbacks suppressed
+audit: type=1100 audit(1646518557.550:31): pid=427 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_securetty,pam_shells,pam_faillock,pam_permit,pam_faillock acct="root" exe="/usr/bin/login" hostname=alarm addr=? terminal=/dev/tty1 res=success'
+audit: type=1101 audit(1646518557.552:32): pid=427 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_permit,pam_time acct="root" exe="/usr/bin/login" hostname=alarm addr=? terminal=/dev/tty1 res=success'
+audit: type=1103 audit(1646518557.552:33): pid=427 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_securetty,pam_shells,pam_faillock,pam_permit,pam_faillock acct="root" exe="/usr/bin/login" hostname=alarm addr=? terminal=/dev/tty1 res=success'
+audit: type=1006 audit(1646518557.552:34): pid=427 uid=0 old-auid=4294967295 auid=0 tty=tty1 old-ses=4294967295 ses=1 res=1
+audit: type=1300 audit(1646518557.552:34): arch=c00000b7 syscall=64 success=yes exit=1 a0=4 a1=fffff1c9b820 a2=1 a3=ffff651ecc60 items=0 ppid=1 pid=427 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=tty1 ses=1 comm="login" exe="/usr/bin/login" key=(null)
+audit: type=1327 audit(1646518557.552:34): proctitle=2F62696E2F6C6F67696E002D70002D2D
+audit: type=1130 audit(1646518557.574:35): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=user-runtime-dir@0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
+audit: type=1101 audit(1646518557.580:36): pid=429 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_permit,pam_time acct="root" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
+audit: type=1103 audit(1646518557.580:37): pid=429 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=? acct="root" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
+audit: type=1006 audit(1646518557.580:38): pid=429 uid=0 old-auid=4294967295 auid=0 tty=(none) old-ses=4294967295 ses=2 res=1

"as expected" by such a diff, when this behaviour happens, lspci only returns:

00:00.0 PCI bridge: Apple Inc. Device 100c (rev 01)

Complete dmesg and diff here: https://gist.github.com/kit-ty-kate/348689e9b460b7267a5153bb12a5064b

kaferka commented 2 years ago

Machine: MacBook Air M1 2020

I am having a similar issue, however in my case the device does not get detected no matter how many cold/warm boots the computer gets. This is dual booting with macOS 12.2.1 right now. I'm using a USB-C hub with an ASIX AX88179 ethernet chip for temporary network access.

I've attempted to build the kernel with the newest commit for unrelated testing reasons (read: my curiosity) (a0ce482af27aaf2ed4f90dfa961a57fc54ed2f68) from github.com/AsahiLinux/linux which is what the attached dmesg and iomem are from but the issue happens in both my build and the reference package from the "asahi" repo (5.17.rc6.20220301-4).

07-03-2022-dmesg-a0ce482af27aaf2ed4f90dfa961a57fc54ed2f68.txt 07-03-2022-iomem-a0ce482af27aaf2ed4f90dfa961a57fc54ed2f68.txt

zamadatix commented 2 years ago

Same issue on MacBook Pro with M1 Max and the reference distro kernel. Like @kaferka it doesn't seem to matter how many warm/cold boots I do.

marcan commented 2 years ago

This should be fixed. Turns out power gating the PCIe peripheral makes everything randomly explode.

marcan commented 2 years ago

I'll leave this open since this needs investigation, but for now I just marked the PCIe domain as always-on so this won't break any more in the kernel packages.