[artix-general] [s6] not booting/rebooting laptop

Javier je-vv at e.email
Sun Sep 27 23:35:25 CEST 2020


On 9/27/20 9:56 AM, Dudemanguy via artix-general wrote:
> Do the dhcpcd logs in /var/log/dhcpcd say anything interesting here? It
> should say something like "received SIGTERM, stopping" when it shuts
> down.

The dhcpcd service actually receives the SIGTERM, and actually does exits.  So that part is good, but as soon as it does, then it starts again.  I believe the issue is not on the dhcpcd side though, since it seems to do things fine.  What makes it start again is what's faulting.  Please remember when there's no wpa_supplicant, dhcpcd dies fine.  On the console:

> % sudo s6-rc -d -v2 change dhcpcd
> [sudo] password for vasqueja: 
> s6-rc: info: service wpa_supplicant-srv: stopping
> s6-rc: info: service wpa_supplicant-srv successfully stopped
> s6-rc: info: service dhcpcd-srv: stopping

There the dhcpcd service just hangs.  The corresponding /var/log/dhcpcd/current (including its start at boot):

> 2020-09-27 14:36:36.037374263  dhcpcd-9.2.0 starting
> 2020-09-27 14:36:36.048819381  dev: loaded udev
> 2020-09-27 14:36:36.050056676  DUID 00:04:59:12:9a:dd:f0:4f:11:e5:b9:11:62:cb:f2:00:40:19
> 2020-09-27 14:36:36.152177882  no interfaces have a carrier
> 2020-09-27 14:36:36.565768987  in-wired-0: waiting for carrier
> 2020-09-27 14:36:36.565775437  in-wireless-0: waiting for carrier
> 2020-09-27 14:36:36.565777742  in-wireless-0: carrier acquired
> 2020-09-27 14:36:36.574231978  in-wireless-0: IAID 00:bb:a5:3f
> 2020-09-27 14:36:36.580133950  in-wireless-0: adding address fe80::55a:5374:22a4:4ce2
> 2020-09-27 14:36:36.580142432  in-wireless-0: carrier lost
> 2020-09-27 14:36:36.621093633  in-wireless-0: deleting address fe80::55a:5374:22a4:4ce2
> 2020-09-27 14:36:40.125047310  in-wireless-0: carrier acquired
> 2020-09-27 14:36:40.126338416  in-wireless-0: connected to Access Point `sanctuary'
> 2020-09-27 14:36:40.131870236  in-wireless-0: IAID 00:bb:a5:3f
> 2020-09-27 14:36:40.131876653  in-wireless-0: adding address fe80::19db:fef7:609f:47ff
> 2020-09-27 14:36:40.867502547  in-wireless-0: soliciting an IPv6 router
> 2020-09-27 14:36:41.082659588  in-wireless-0: rebinding lease of 192.168.0.24
> 2020-09-27 14:36:42.097383244  in-wireless-0: Router Advertisement from fe80::1
> 2020-09-27 14:36:42.097784202  in-wireless-0: adding default route via fe80::1
> 2020-09-27 14:36:42.118390071  in-wireless-0: requesting DHCPv6 information
> 2020-09-27 14:36:43.241524408  in-wireless-0: REPLY6 received from fe80::1
> 2020-09-27 14:36:43.241531694  in-wireless-0: refresh in 86400 seconds
> 2020-09-27 14:36:45.167755509  in-wireless-0: probing address 192.168.0.24/24
> 2020-09-27 14:36:46.961029631  in-wired-0: carrier acquired
> 2020-09-27 14:36:46.966393068  in-wired-0: IAID fd:a9:93:88
> 2020-09-27 14:36:46.966422087  in-wired-0: adding address fe80::ae2b:a054:4551:ee66
> 2020-09-27 14:36:47.807487628  in-wired-0: soliciting an IPv6 router
> 2020-09-27 14:36:48.151709417  in-wired-0: rebinding lease of 192.168.0.16
> 2020-09-27 14:36:48.203744307  in-wired-0: probing address 192.168.0.16/24
> 2020-09-27 14:36:48.551086720  in-wired-0: Router Advertisement from fe80::1
> 2020-09-27 14:36:48.551094161  in-wired-0: adding default route via fe80::1
> 2020-09-27 14:36:48.578354631  in-wired-0: requesting DHCPv6 information
> 2020-09-27 14:36:49.629098160  in-wired-0: REPLY6 received from fe80::1
> 2020-09-27 14:36:49.629111372  in-wired-0: refresh in 86400 seconds
> 2020-09-27 14:36:50.042137747  in-wireless-0: leased 192.168.0.24 for 259200 seconds
> 2020-09-27 14:36:50.043180344  in-wireless-0: adding route to 192.168.0.0/24
> 2020-09-27 14:36:50.043187700  in-wireless-0: adding default route via 192.168.0.1
> 2020-09-27 14:36:53.670796782  in-wired-0: leased 192.168.0.16 for 259200 seconds
> 2020-09-27 14:36:53.670804843  in-wired-0: adding route to 192.168.0.0/24
> 2020-09-27 14:36:53.670806712  in-wired-0: adding default route via 192.168.0.1
> 2020-09-27 14:45:10.658332393  in-wireless-0: carrier lost
> 2020-09-27 14:45:10.755923527  ps_bpf_recvbpf: Network is down
> 2020-09-27 14:45:10.757974343  in-wireless-0: deleting default route via fe80::1
> 2020-09-27 14:45:10.781556944  in-wireless-0: deleting address fe80::19db:fef7:609f:47ff
> 2020-09-27 14:45:10.784978177  in-wireless-0: deleting route to 192.168.0.0/24
> 2020-09-27 14:45:10.785189038  in-wireless-0: deleting default route via 192.168.0.1
> 2020-09-27 14:47:16.819264626  received SIGTERM, stopping
> 2020-09-27 14:47:16.819315805  in-wireless-0: removing interface
> 2020-09-27 14:47:16.824369106  in-wired-0: removing interface
> 2020-09-27 14:47:16.831387371  dhcpcd exited
> 2020-09-27 14:48:50.220665342  dhcpcd-9.2.0 starting
> 2020-09-27 14:48:50.235339511  dev: loaded udev
> 2020-09-27 14:48:50.237413093  DUID 00:04:59:12:9a:dd:f0:4f:11:e5:b9:11:62:cb:f2:00:40:19
> 2020-09-27 14:48:50.634904515  no interfaces have a carrier
> 2020-09-27 14:48:50.843336281  in-wired-0: waiting for carrier
> 2020-09-27 14:48:50.843343025  in-wireless-0: waiting for carrier
> 2020-09-27 14:48:50.843345737  in-wireless-0: carrier acquired
> 2020-09-27 14:48:50.849938976  in-wireless-0: IAID 00:bb:a5:3f
> 2020-09-27 14:48:50.850530481  in-wireless-0: adding address fe80::55a:5374:22a4:4ce2
> 2020-09-27 14:48:50.850534593  in-wireless-0: carrier lost
> 2020-09-27 14:48:50.886479451  in-wireless-0: deleting address fe80::55a:5374:22a4:4ce2
> 2020-09-27 14:48:54.349958769  in-wireless-0: carrier acquired
> 2020-09-27 14:48:54.351216664  in-wireless-0: connected to Access Point `sanctuary'
> 2020-09-27 14:48:54.359568194  in-wireless-0: IAID 00:bb:a5:3f
> 2020-09-27 14:48:54.359574334  in-wireless-0: adding address fe80::19db:fef7:609f:47ff
> 2020-09-27 14:48:54.500045235  in-wireless-0: rebinding lease of 192.168.0.24
> 2020-09-27 14:48:54.759697179  in-wireless-0: soliciting an IPv6 router
> 2020-09-27 14:48:56.130927029  in-wireless-0: Router Advertisement from fe80::1
> 2020-09-27 14:48:56.131129536  in-wireless-0: adding default route via fe80::1
> 2020-09-27 14:48:56.144578620  in-wireless-0: requesting DHCPv6 information
> 2020-09-27 14:48:57.260937736  in-wireless-0: REPLY6 received from fe80::1
> 2020-09-27 14:48:57.260945305  in-wireless-0: refresh in 86400 seconds
> 2020-09-27 14:48:59.446024892  in-wireless-0: probing address 192.168.0.24/24
> 2020-09-27 14:49:01.106600972  in-wired-0: carrier acquired
> 2020-09-27 14:49:01.110397758  in-wired-0: IAID fd:a9:93:88
> 2020-09-27 14:49:01.110405281  in-wired-0: adding address fe80::ae2b:a054:4551:ee66
> 2020-09-27 14:49:01.141445535  in-wired-0: rebinding lease of 192.168.0.16
> 2020-09-27 14:49:01.199099942  in-wired-0: probing address 192.168.0.16/24
> 2020-09-27 14:49:01.547882733  in-wired-0: soliciting an IPv6 router
> 2020-09-27 14:49:03.034853761  in-wired-0: Router Advertisement from fe80::1
> 2020-09-27 14:49:03.035200754  in-wired-0: adding default route via fe80::1
> 2020-09-27 14:49:03.044935642  in-wired-0: requesting DHCPv6 information
> 2020-09-27 14:49:04.092221763  in-wired-0: REPLY6 received from fe80::1
> 2020-09-27 14:49:04.092249974  in-wired-0: refresh in 86400 seconds
> 2020-09-27 14:49:04.384681565  in-wireless-0: leased 192.168.0.24 for 259200 seconds
> 2020-09-27 14:49:04.385289662  in-wireless-0: adding route to 192.168.0.0/24
> 2020-09-27 14:49:04.385411907  in-wireless-0: adding default route via 192.168.0.1
> 2020-09-27 14:49:06.745315169  in-wired-0: leased 192.168.0.16 for 259200 seconds
> 2020-09-27 14:49:06.745964771  in-wired-0: adding route to 192.168.0.0/24
> 2020-09-27 14:49:06.745971033  in-wired-0: adding default route via 192.168.0.1
> 2020-09-27 14:50:31.666498911  in-wireless-0: carrier lost
> 2020-09-27 14:50:31.694642076  in-wireless-0: deleting default route via fe80::1
> 2020-09-27 14:50:31.708662121  in-wireless-0: deleting address fe80::19db:fef7:609f:47ff
> 2020-09-27 14:50:31.734671244  in-wireless-0: deleting route to 192.168.0.0/24
> 2020-09-27 14:50:31.734760375  in-wireless-0: deleting default route via 192.168.0.1
> 2020-09-27 14:57:54.284007333  in-wireless-0: carrier acquired
> 2020-09-27 14:57:54.308508721  in-wireless-0: IAID 00:bb:a5:3f
> 2020-09-27 14:57:54.308637041  in-wireless-0: adding address fe80::19db:fef7:609f:47ff
> 2020-09-27 14:57:54.388030157  in-wireless-0: soliciting an IPv6 router
> 2020-09-27 14:57:55.313265473  in-wireless-0: rebinding lease of 192.168.0.24
> 2020-09-27 14:57:55.500301187  in-wireless-0: Router Advertisement from fe80::1
> 2020-09-27 14:57:55.500718178  in-wireless-0: adding default route via fe80::1
> 2020-09-27 14:57:55.518591827  in-wireless-0: requesting DHCPv6 information
> 2020-09-27 14:57:56.610665164  in-wireless-0: REPLY6 received from fe80::1
> 2020-09-27 14:57:56.610852349  in-wireless-0: refresh in 86400 seconds
> 2020-09-27 14:57:59.665253280  in-wireless-0: probing address 192.168.0.24/24
> 2020-09-27 14:58:04.671481023  in-wireless-0: leased 192.168.0.24 for 259200 seconds
> 2020-09-27 14:58:04.676816082  in-wireless-0: adding route to 192.168.0.0/24
> 2020-09-27 14:58:04.676852041  in-wireless-0: adding default route via 192.168.0.1
> 2020-09-27 14:59:26.705880261  in-wireless-0: carrier lost
> 2020-09-27 14:59:26.730262529  in-wireless-0: deleting default route via fe80::1
> 2020-09-27 14:59:26.741923912  in-wireless-0: deleting address fe80::19db:fef7:609f:47ff
> 2020-09-27 14:59:26.747137774  in-wireless-0: deleting route to 192.168.0.0/24
> 2020-09-27 14:59:26.747151400  in-wireless-0: deleting default route via 192.168.0.1
> 2020-09-27 14:59:30.704560862  received SIGTERM, stopping
> 2020-09-27 14:59:30.704568449  in-wireless-0: removing interface
> 2020-09-27 14:59:30.711468054  in-wired-0: removing interface
> 2020-09-27 14:59:30.721546523  dhcpcd exited
> 2020-09-27 15:00:08.554239015  dhcpcd-9.2.0 starting
> 2020-09-27 15:00:08.565005127  dev: loaded udev
> 2020-09-27 15:00:08.565925381  DUID 00:04:59:12:9a:dd:f0:4f:11:e5:b9:11:62:cb:f2:00:40:19
> 2020-09-27 15:00:08.683340454  no interfaces have a carrier
> 2020-09-27 15:00:09.081804702  in-wired-0: waiting for carrier
> 2020-09-27 15:00:09.081810466  in-wireless-0: waiting for carrier
> 2020-09-27 15:00:09.081812892  in-wireless-0: carrier acquired
> 2020-09-27 15:00:09.086944245  in-wireless-0: IAID 00:bb:a5:3f
> 2020-09-27 15:00:09.087203079  in-wireless-0: adding address fe80::55a:5374:22a4:4ce2
> 2020-09-27 15:00:09.087208134  in-wireless-0: carrier lost
> 2020-09-27 15:00:09.116553908  in-wireless-0: deleting address fe80::55a:5374:22a4:4ce2
> 2020-09-27 15:00:12.616721111  in-wireless-0: carrier acquired
> 2020-09-27 15:00:12.617974561  in-wireless-0: connected to Access Point `sanctuary'
> 2020-09-27 15:00:12.625571903  in-wireless-0: IAID 00:bb:a5:3f
> 2020-09-27 15:00:12.625578571  in-wireless-0: adding address fe80::19db:fef7:609f:47ff
> 2020-09-27 15:00:12.791590558  in-wireless-0: soliciting an IPv6 router
> 2020-09-27 15:00:13.927112004  in-wireless-0: Router Advertisement from fe80::1
> 2020-09-27 15:00:13.927490413  in-wireless-0: adding default route via fe80::1
> 2020-09-27 15:00:13.944574191  in-wireless-0: requesting DHCPv6 information
> 2020-09-27 15:00:14.028123094  in-wireless-0: rebinding lease of 192.168.0.24
> 2020-09-27 15:00:15.062150872  in-wireless-0: REPLY6 received from fe80::1
> 2020-09-27 15:00:15.062163229  in-wireless-0: refresh in 86400 seconds
> 2020-09-27 15:00:18.645953696  in-wireless-0: probing address 192.168.0.24/24
> 2020-09-27 15:00:19.677716854  in-wired-0: carrier acquired
> 2020-09-27 15:00:19.682969338  in-wired-0: IAID fd:a9:93:88
> 2020-09-27 15:00:19.683044595  in-wired-0: adding address fe80::ae2b:a054:4551:ee66
> 2020-09-27 15:00:20.062651977  in-wired-0: soliciting an IPv6 router
> 2020-09-27 15:00:20.773309148  in-wired-0: rebinding lease of 192.168.0.16
> 2020-09-27 15:00:20.832364989  in-wired-0: probing address 192.168.0.16/24
> 2020-09-27 15:00:21.153244886  in-wired-0: Router Advertisement from fe80::1
> 2020-09-27 15:00:21.153516617  in-wired-0: adding default route via fe80::1
> 2020-09-27 15:00:21.169834594  in-wired-0: requesting DHCPv6 information
> 2020-09-27 15:00:22.286498945  in-wired-0: REPLY6 received from fe80::1
> 2020-09-27 15:00:22.286533090  in-wired-0: refresh in 86400 seconds
> 2020-09-27 15:00:23.837636173  in-wireless-0: leased 192.168.0.24 for 259200 seconds
> 2020-09-27 15:00:23.841740790  in-wireless-0: adding route to 192.168.0.0/24
> 2020-09-27 15:00:23.841769460  in-wireless-0: adding default route via 192.168.0.1
> 2020-09-27 15:00:25.433243781  in-wired-0: leased 192.168.0.16 for 259200 seconds
> 2020-09-27 15:00:25.434557803  in-wired-0: adding route to 192.168.0.0/24
> 2020-09-27 15:00:25.434565015  in-wired-0: adding default route via 192.168.0.1

The key part of the log is:

> 2020-09-27 14:59:30.704560862  received SIGTERM, stopping
> 2020-09-27 14:59:30.704568449  in-wireless-0: removing interface
> 2020-09-27 14:59:30.711468054  in-wired-0: removing interface
> 2020-09-27 14:59:30.721546523  dhcpcd exited
> 2020-09-27 15:00:08.554239015  dhcpcd-9.2.0 starting
> 2020-09-27 15:00:08.565005127  dev: loaded udev

As you can see dhcpcd got shut down.  It's weird that it was started up again, and of course, as it starts again, and remains enabled afterwords it seems, then the shutdown process hangs.

> One thought would be to remove the dhcpcd dependency from
> wpa_supplicant, but I would rather not do that because you do need
> dhcpcd running for wpa_supplicant to work correctly. It might be
> possible to add a finish script that will solve your problem. For
> example, "wpa_cli terminate" being run when wpa_supplicant gets
> brought down might possibly prevent dhcpcd from hanging for you.
> Alternatively, dhcpcd may need a finish script itself.

Perhaps you're right about adding something on the finish script.  I can tell the wpa_supplicant service actually dies when the dhcpcd one shuts it down, since afterwords, the wireless interface is never brought up back, unless I manually start the wpa_supplicant service.  But let me get the logs on the wpa_supplicant service later, just to confirm.

BTW, to break the shut down hang, I do:

> ^C
> s6-rc: warning: received INT, aborting longrun transitions and exiting asap
> s6-rc: warning: unable to stop service dhcpcd-srv: command crashed with signal 2

And then dhcp, as alive, tries to bring the wireless interfaces up, but as wpa_supplicant is down, it can't.  On the log, we get additionally:

> 2020-09-27 15:02:23.288184126  in-wireless-0: carrier lost
> 2020-09-27 15:02:23.313193548  in-wireless-0: deleting default route via fe80::1
> 2020-09-27 15:02:23.325320899  in-wireless-0: deleting address fe80::19db:fef7:609f:47ff
> 2020-09-27 15:02:23.329582421  in-wireless-0: deleting route to 192.168.0.0/24
> 2020-09-27 15:02:23.329591237  in-wireless-0: deleting default route via 192.168.0.1

And the log doesn't move from there, even if I manually start the dhccpcd service, which for some reason can be done and doesn't fail, even though dhcp is up and running, perhaps because for S6 it should be dead already, and calling the dhcpcd daemon twice doesn't provoke any failure, just gets ignored, but I'm not sure...

Let me get some logs from wpa_supplicant to complement all this.

-- 
Javier

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 228 bytes
Desc: OpenPGP digital signature
URL: <https://lists.artixlinux.org/archives/artix-general/attachments/20200927/81f70557/attachment.sig>


More information about the artix-general mailing list