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