advice on a bisect

Tue Jun 29 14:02:01 EDT 2021

I have an old 686 machine, running fedora 30
(last fedora supporting 686)

processor : 1
vendor_id : GenuineIntel
cpu family : 6
model : 23
model name : Intel(R) Core(TM)2 Duo CPU     E7400  @ 2.80GHz
stepping : 10
microcode : 0xa0b
cpu MHz : 1614.044
cache size : 3072 KB

I generally keep it with a fresh kernel at least,

[jimc at popeye linux]$ uname -a
Linux popeye 5.13.0-rc5-j1-00030-g4c8684fe555e #210 SMP Tue Jun 15
16:56:40 MDT 2021 i686 i686 i386 GNU/Linux

recently, I found it wouldnt boot, so bisected.

[jimc at popeye linux]$ git bisect log
git bisect start
# bad: [009c9aa5be652675a06d5211e1640e02bbb1c33d] Linux 5.13-rc6
git bisect bad 009c9aa5be652675a06d5211e1640e02bbb1c33d
# good: [8124c8a6b35386f73523d27eacb71b5364a68c4c] Linux 5.13-rc4
git bisect good 8124c8a6b35386f73523d27eacb71b5364a68c4c
# good: [bd7b12aa6081c3755b693755d608f58e13798a60] Merge tag
'powerpc-5.13-5' of
git://git.kernel.org/pub/scm/linux/kernel/git/powerpc/linux
git bisect good bd7b12aa6081c3755b693755d608f58e13798a60
# bad: [fd2cd569a43635877771c00b8a2f4f26275e5562] Merge tag
'sound-5.13-rc6' of
git://git.kernel.org/pub/scm/linux/kernel/git/tiwai/sound
git bisect bad fd2cd569a43635877771c00b8a2f4f26275e5562
# good: [9b1111fa80df22c8cb6f9f8634693812cb958f4f] Merge tag
'regulator-fix-v5.13-rc4' of
git://git.kernel.org/pub/scm/linux/kernel/git/broonie/regulator
git bisect good 9b1111fa80df22c8cb6f9f8634693812cb958f4f
# bad: [cd1245d75ce93b8fd206f4b34eb58bcfe156d5e9] Merge tag
'platform-drivers-x86-v5.13-3' of
git://git.kernel.org/pub/scm/linux/kernel/git/pdx86/platform-drivers-x86
git bisect bad cd1245d75ce93b8fd206f4b34eb58bcfe156d5e9
# bad: [2f673816b2db30ce6122fe0e5e6a00de20e8d99a] Merge tag
'for-linus' of git://git.kernel.org/pub/scm/virt/kvm/kvm
git bisect bad 2f673816b2db30ce6122fe0e5e6a00de20e8d99a
# bad: [368094df48e680fa51cedb68537408cfa64b788e] Merge tag
'for-linus-5.13b-rc6-tag' of
git://git.kernel.org/pub/scm/linux/kernel/git/xen/tip
git bisect bad 368094df48e680fa51cedb68537408cfa64b788e
# good: [4c8684fe555e95100030bd330d0a2780ac27952e] Merge tag
'spi-fix-v5.13-rc4' of
git://git.kernel.org/pub/scm/linux/kernel/git/broonie/spi
git bisect good 4c8684fe555e95100030bd330d0a2780ac27952e
# good: [d4c6399900364facd84c9e35ce1540b6046c345f] vmlinux.lds.h:
Avoid orphan section with !SMP
git bisect good d4c6399900364facd84c9e35ce1540b6046c345f
# good: [374aeb91db48bb52216bb9308d611c816fb6cacb] Merge tag
'orphans-v5.13-rc6' of
git://git.kernel.org/pub/scm/linux/kernel/git/kees/linux
git bisect good 374aeb91db48bb52216bb9308d611c816fb6cacb
# good: [107866a8eb0b664675a260f1ba0655010fac1e08] xen-netback: take a
reference to the RX task thread
git bisect good 107866a8eb0b664675a260f1ba0655010fac1e08
# first bad commit: [368094df48e680fa51cedb68537408cfa64b788e] Merge
tag 'for-linus-5.13b-rc6-tag' of
git://git.kernel.org/pub/scm/linux/kernel/git/xen/tip
[jimc at popeye linux]$

after bisecting (long time, not much effort)
I booted the "bad" kernel to single user
(added 'S' to end of bootline - is this universal ?)
and poked around, so failure is more subtle than total.

by casual observation, boot hangs at dbus startup

the bad-booting kernel does manage to log its progress,
journalct -b-1 shows :

Jun 17 03:06:11 popeye kernel: Run /init as init process
Jun 17 03:06:11 popeye kernel:   with arguments:
Jun 17 03:06:11 popeye kernel:     /init
Jun 17 03:06:11 popeye kernel:     rhgb
Jun 17 03:06:11 popeye kernel:     2
Jun 17 03:06:11 popeye kernel:   with environment:
Jun 17 03:06:11 popeye kernel:     HOME=/
Jun 17 03:06:11 popeye kernel:     TERM=linux
Jun 17 03:06:11 popeye kernel:     BOOT_IMAGE=/vmlinuz-5.13.0-rc6-cln

Jun 17 03:06:14 popeye systemd[1]: Started Plymouth switch root service.
Jun 17 03:06:14 popeye audit[1]: SERVICE_START pid=1 uid=0
auid=4294967295 ses=4294967295 subj=kernel msg='unit=plymouth-switch>
Jun 17 03:06:14 popeye audit[1]: SERVICE_STOP pid=1 uid=0
auid=4294967295 ses=4294967295 subj=kernel msg='unit=plymouth-switch->
Jun 17 03:06:14 popeye systemd[1]: Starting Switch Root...
Jun 17 03:06:14 popeye systemd[1]: Switching root.
Jun 17 03:06:14 popeye systemd-journald[131]: Journal stopped
Jun 17 09:06:22 popeye systemd-journald[131]: Received SIGTERM from
PID 1 (systemd).
Jun 17 09:06:22 popeye kernel: printk: systemd: 18 output lines
suppressed due to ratelimiting
Jun 17 09:06:22 popeye kernel: kauditd_printk_skb: 21 callbacks suppressed
Jun 17 09:06:22 popeye kernel: audit: type=1404
audit(1623920776.499:32): enforcing=1 old_enforcing=0 auid=4294967295
ses=42949>
Jun 17 09:06:22 popeye kernel: SELinux:  Permission watch in class
filesystem not defined in policy.
Jun 17 09:06:22 popeye kernel: SELinux:  Permission watch in class
file not defined in policy.

(at end)

Jun 17 09:06:33 popeye systemd-logind[617]: Watching system buttons on
/dev/input/event0 (Power Button)
Jun 17 09:06:33 popeye systemd-logind[617]: Watching system buttons on
/dev/input/event2 (USB USB Keykoard)
Jun 17 09:06:33 popeye systemd-logind[617]: Watching system buttons on
/dev/input/event3 (USB USB Keykoard Consumer Control)
Jun 17 09:06:33 popeye systemd-logind[617]: Watching system buttons on
/dev/input/event4 (USB USB Keykoard System Control)
Jun 17 09:06:33 popeye rsyslogd[604]: [origin software="rsyslogd"
swVersion="8.2002.0" x-pid="604" x-info="https://www.rsyslog.>
Jun 17 09:06:33 popeye systemd[1]: Started System Logging Service.
Jun 17 09:06:33 popeye audit[1]: SERVICE_START pid=1 uid=0
auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg=>
Jun 17 09:06:33 popeye ModemManager[605]: <info>  ModemManager
(version 1.10.2-1.fc30) starting in system bus...
Jun 17 09:06:33 popeye rsyslogd[604]: imjournal: fscanf on state file
`/var/lib/rsyslog/imjournal.state' failed  [v8.2002.0 try>
Jun 17 09:06:33 popeye rsyslogd[604]: imjournal: ignoring invalid
state file /var/lib/rsyslog/imjournal.state [v8.2002.0]
Jun 17 09:06:33 popeye chronyd[625]: Frequency -3.051 +/- 0.183 ppm
read from /var/lib/chrony/drift
Jun 17 09:06:33 popeye chronyd[625]: Using right/UTC timezone to
obtain leap second data
Jun 17 09:06:34 popeye systemd[1]: Started NTP client/server.
Jun 17 09:06:34 popeye audit[1]: SERVICE_START pid=1 uid=0
auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg=>
Jun 17 09:06:34 popeye smartd[612]: smartd 7.1 2019-12-30 r5022
[i686-linux-5.13.0-rc6-cln] (local build)
Jun 17 09:06:34 popeye smartd[612]: Copyright (C) 2002-19, Bruce
Allen, Christian Franke, www.smartmontools.org
Jun 17 09:06:34 popeye smartd[612]: Opened configuration file
/etc/smartmontools/smartd.conf
Jun 17 09:06:34 popeye smartd[612]: Configuration file
/etc/smartmontools/smartd.conf was parsed, found DEVICESCAN, scanning
de>
Jun 17 09:06:34 popeye smartd[612]: Device: /dev/sda, type changed
from 'scsi' to 'sat'
Jun 17 09:06:34 popeye smartd[612]: Device: /dev/sda [SAT], opened
Jun 17 09:06:34 popeye smartd[612]: Device: /dev/sda [SAT],
ST3160318AS, S/N:9VY1J685, WWN:5-000c50-0159dbd9f, FW:CC44, 160 GB
Jun 17 09:06:34 popeye smartd[612]: Device: /dev/sda [SAT], found in
smartd database: Seagate Barracuda 7200.12
Jun 17 09:06:34 popeye smartd[612]: Device: /dev/sda [SAT], WARNING: A
firmware update for this drive may be available,
Jun 17 09:06:34 popeye smartd[612]: see the following Seagate web pages:
Jun 17 09:06:34 popeye smartd[612]:
http://knowledge.seagate.com/articles/en_US/FAQ/207931en
Jun 17 09:06:34 popeye smartd[612]:
http://knowledge.seagate.com/articles/en_US/FAQ/213891en
Jun 17 09:06:34 popeye smartd[612]: Device: /dev/sda [SAT], is SMART
capable. Adding to "monitor" list.
Jun 17 09:06:34 popeye smartd[612]: Monitoring 1 ATA/SATA, 0 SCSI/SAS
and 0 NVMe devices
Jun 17 09:06:35 popeye systemd[1]: Started Self Monitoring and
Reporting Technology (SMART) Daemon.
Jun 17 09:06:35 popeye audit[1]: SERVICE_START pid=1 uid=0
auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg=>
Jun 17 09:06:36 popeye systemd[1]: Started D-Bus System Message Bus.
Jun 17 09:06:36 popeye audit[1]: SERVICE_START pid=1 uid=0
auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg=>
Jun 17 09:06:36 popeye dbus-broker-launch[623]: ERROR
proc_get_seclabel @ ../src/util/proc.c +31: Permission denied
Jun 17 09:06:36 popeye dbus-broker-launch[623]:       broker_new @
../src/broker/broker.c +105
Jun 17 09:06:36 popeye dbus-broker-launch[623]:       run @
../src/broker/main.c +244
Jun 17 09:06:36 popeye dbus-broker-launch[623]:       main @
../src/broker/main.c +270
Jun 17 09:06:36 popeye dbus-broker-launch[623]: ERROR service_add @
../src/launch/service.c +545: Connection reset by peer
Jun 17 09:06:36 popeye dbus-broker-launch[623]:
launcher_add_services @ ../src/launch/launcher.c +809
Jun 17 09:06:36 popeye dbus-broker-launch[623]:       launcher_run @
../src/launch/launcher.c +1385
Jun 17 09:06:36 popeye dbus-broker-launch[623]:       run @
../src/launch/main.c +153
Jun 17 09:06:36 popeye dbus-broker-launch[623]:       main @
../src/launch/main.c +181
Jun 17 09:06:36 popeye dbus-broker-launch[623]: Exiting due to fatal error: -104
Jun 17 09:06:42 popeye rsyslogd[604]: imjournal from
<popeye:dhclient>: begin to drop messages due to rate-limiting
lines 1430-1473/1473 (END)

at this point, things hung & I powercycled to reboot.

I cant quite explain the logging around  9:06,  it looks more orderly
than the powercycle I recall.  Im gonna have to repeat this test,
noting times etc.

separately

Ive been wanting to find another distro which supports 686 and older hardware,
thats now arriving sooner, since box doesnt well serve its most common use.

any good distro reqs ?