Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

https-dns-proxy: ubus command failed #22674

Closed
systemcrash opened this issue Nov 16, 2023 · 19 comments · Fixed by #22737
Closed

https-dns-proxy: ubus command failed #22674

systemcrash opened this issue Nov 16, 2023 · 19 comments · Fixed by #22737
Assignees

Comments

@systemcrash
Copy link
Contributor

@stangri ?

Just upgraded to 23.05.2, logread shows this:

# logread | grep https-dns-
Tue Nov 14 14:38:58 2023 user.notice https-dns-proxy: Starting service instances on_boot ✓✓✓
Tue Nov 14 14:39:25 2023 user.notice https-dns-proxy: Restarting dnsmasq on_boot ✓
Tue Nov 14 14:39:26 2023 daemon.info https-dns-proxy[5301]: [F] 1699969166.206376 https-dns-proxy-2023-10-25/src/dns_server.c:51 Error binding 127.0.0.1:5055: Address in use (-1)
Tue Nov 14 14:39:26 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: Command failed: ubus call service add { "type": "config.change", "data": { "package": "firewall" } } (Invalid argument)
Tue Nov 14 14:39:26 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: Usage: ubus [<options>] <command> [arguments...]
Tue Nov 14 14:39:26 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: Options:
Tue Nov 14 14:39:26 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -s <socket>:		Set the unix domain socket to connect to
Tue Nov 14 14:39:26 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -t <timeout>:		Set the timeout (in seconds) for a command to complete
Tue Nov 14 14:39:26 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -S:			Use simplified output (for scripts)
Tue Nov 14 14:39:26 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -v:			More verbose output
Tue Nov 14 14:39:26 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -m <type>:		(for monitor): include a specific message type
Tue Nov 14 14:39:26 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: 			(can be used more than once)
Tue Nov 14 14:39:26 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -M <r|t>		(for monitor): only capture received or transmitted traffic
Tue Nov 14 14:39:26 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:
Tue Nov 14 14:39:26 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: Commands:
Tue Nov 14 14:39:26 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - list [<path>]			List objects
Tue Nov 14 14:39:26 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - call <path> <method> [<message>]	Call an object method
Tue Nov 14 14:39:26 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - subscribe <path> [<path>...]	Subscribe to object(s) notifications
Tue Nov 14 14:39:26 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - listen [<path>...]			Listen for events
Tue Nov 14 14:39:26 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - send <type> [<message>]		Send an event
Tue Nov 14 14:39:26 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - wait_for <object> [<object>...]	Wait for multiple objects to appear on ubus
Tue Nov 14 14:39:26 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - monitor				Monitor ubus traffic
Tue Nov 14 14:39:26 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:
Tue Nov 14 14:39:31 2023 daemon.info https-dns-proxy[5536]: [F] 1699969171.290357 https-dns-proxy-2023-10-25/src/dns_server.c:51 Error binding 127.0.0.1:5055: Address in use (-1)
Tue Nov 14 14:39:36 2023 daemon.info https-dns-proxy[5765]: [F] 1699969176.339692 https-dns-proxy-2023-10-25/src/dns_server.c:51 Error binding 127.0.0.1:5055: Address in use (-1)
Tue Nov 14 14:39:41 2023 daemon.info https-dns-proxy[6243]: [F] 1699969181.403159 https-dns-proxy-2023-10-25/src/dns_server.c:51 Error binding 127.0.0.1:5055: Address in use (-1)
Thu Nov 16 17:15:27 2023 daemon.info https-dns-proxy[6773]: [F] 1700151327.784367 https-dns-proxy-2023-10-25/src/dns_server.c:51 Error binding 127.0.0.1:5055: Address in use (-1)
Thu Nov 16 17:15:32 2023 daemon.info https-dns-proxy[7015]: [F] 1700151332.858614 https-dns-proxy-2023-10-25/src/dns_server.c:51 Error binding 127.0.0.1:5055: Address in use (-1)
Thu Nov 16 17:15:32 2023 daemon.info procd: Instance https-dns-proxy::instance2 s in a crash loop 6 crashes, 0 seconds since last crash

Here be my config:

config main 'config'
	option dnsmasq_config_update '*'
	option force_dns '1'
	list force_dns_port '53'
	list force_dns_port '853'

config https-dns-proxy
	option listen_addr '127.0.0.1'
	option user 'nobody'
	option group 'nogroup'
	option bootstrap_dns '74.82.42.42,2001:470:20::2'
	option resolver_url 'https://ordns.he.net/dns-query'
	option listen_port '5054'

config https-dns-proxy
	option bootstrap_dns '116.202.176.26,1.1.1.1'
	option resolver_url 'https://doh.libredns.gr/dns-query'
	option listen_port '5055'

config https-dns-proxy
	option resolver_url 'https://cloudflare-dns.com/dns-query'
	option bootstrap_dns '1.1.1.1,1.0.0.1,2606:4700:4700::1111,2606:4700:4700::1001'

@systemcrash systemcrash changed the title https-dns-proxy: command error https-dns-proxy: ubus command failed Nov 16, 2023
@stangri
Copy link
Member

stangri commented Nov 16, 2023

Looks like there's something else already running on port 5055.

@stangri stangri self-assigned this Nov 16, 2023
@systemcrash
Copy link
Contributor Author

It does from the log messages. But I find nothing other than this daemon. Weird:

/etc/init.d/https-dns-proxy stop
...
ps | grep https-d
16907 root      1372 S    grep https-d
netstat -a | grep -i 505

nothing.

/etc/init.d/https-dns-proxy restart
Command failed: Not found
Starting https-dns-proxy 2023-10-25-1 instances ✓✓✓
Updating dnsmasq config ✓
Restarting dnsmasq on_config_update ✓

ps | grep https-d
17566 nobody    3488 S    /usr/sbin/https-dns-proxy -r https://ordns.he.net/dns-query -a 127.0.0.1 -p 5054 -b 74.82.42.42 -4 -u nobody -g nogroup
17567 nobody    3488 S    /usr/sbin/https-dns-proxy -r https://doh.libredns.gr/dns-query -a 127.0.0.1 -p 5055 -b 116.202.176.26,1.1.1.1 -4 -u nobody -g nogroup
17568 nobody    3484 S    /usr/sbin/https-dns-proxy -r https://cloudflare-dns.com/dns-query -a 127.0.0.1 -p 5053 -b 1.1.1.1,1.0.0.1 -4 -u nobody -g nogroup
17597 root      1372 S    grep https-d

netstat -a | grep -i 505
udp        0      0 localhost:5053          0.0.0.0:*
udp        0      0 localhost:5054          0.0.0.0:*
udp        0      0 localhost:5055          0.0.0.0:*

Then it seems OK.

Reboot router and I see the logs above anew. So the error is consistent. Possibly related to the on_config_update?

@systemcrash
Copy link
Contributor Author

systemcrash commented Nov 16, 2023

At least on this boot I only got:

Thu Nov 16 17:56:50 2023 user.notice https-dns-proxy: Starting service instances on_boot ✓✓✓
Thu Nov 16 17:56:52 2023 user.notice https-dns-proxy: Updating dnsmasq config ✓
Thu Nov 16 17:57:20 2023 user.notice https-dns-proxy: Restarting dnsmasq on_config_update ✓
Thu Nov 16 17:57:22 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: Command failed: ubus call service add { "type": "config.change", "data": { "package": "firewall" } } (Invalid argument)
Thu Nov 16 17:57:22 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: Usage: ubus [<options>] <command> [arguments...]
Thu Nov 16 17:57:22 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: Options:
Thu Nov 16 17:57:22 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -s <socket>:		Set the unix domain socket to connect to
Thu Nov 16 17:57:22 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -t <timeout>:		Set the timeout (in seconds) for a command to complete
Thu Nov 16 17:57:22 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -S:			Use simplified output (for scripts)
Thu Nov 16 17:57:22 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -v:			More verbose output
Thu Nov 16 17:57:22 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -m <type>:		(for monitor): include a specific message type
Thu Nov 16 17:57:22 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: 			(can be used more than once)
Thu Nov 16 17:57:22 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -M <r|t>		(for monitor): only capture received or transmitted traffic
Thu Nov 16 17:57:22 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:
Thu Nov 16 17:57:22 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: Commands:
Thu Nov 16 17:57:22 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - list [<path>]			List objects
Thu Nov 16 17:57:22 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - call <path> <method> [<message>]	Call an object method
Thu Nov 16 17:57:22 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - subscribe <path> [<path>...]	Subscribe to object(s) notifications
Thu Nov 16 17:57:22 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - listen [<path>...]			Listen for events
Thu Nov 16 17:57:22 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - send <type> [<message>]		Send an event
Thu Nov 16 17:57:22 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - wait_for <object> [<object>...]	Wait for multiple objects to appear on ubus
Thu Nov 16 17:57:22 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - monitor				Monitor ubus traffic
Thu Nov 16 17:57:22 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:
Thu Nov 16 17:57:51 2023 user.notice https-dns-proxy: Stopping service on_boot ✓

the port in use things seemed absent: possibly owing to the time-change (ntp update)?

in any case, a manual restart with /etc/init.d/https-dns-proxy restart does not produce the ubus message.

@systemcrash
Copy link
Contributor Author

Let me know if you need more info.

@stangri
Copy link
Member

stangri commented Nov 16, 2023

Given that ubus error, I suspect it's caused by either this line: https://github.com/stangri/source.openwrt.melmac.net/blob/master/https-dns-proxy/files/etc/init.d/https-dns-proxy#L324 or explicit call here: https://github.com/stangri/source.openwrt.melmac.net/blob/master/https-dns-proxy/files/etc/init.d/https-dns-proxy#L139

I have no idea why it's not reproducible here tho.

Are the logs above complete logs, so the service does not recover by itself at the end of the boot process?

@systemcrash
Copy link
Contributor Author

systemcrash commented Nov 16, 2023 via email

@voron00
Copy link

voron00 commented Nov 16, 2023

I have the same problem (device - Archer C7):

Fri Nov 17 01:42:00 2023 daemon.notice hostapd: Fallback to 20 MHz
Fri Nov 17 01:42:00 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: Command failed: ubus call service add { "type": "config.change", "data": { "package": "firewall" } } (Invalid argument)
Fri Nov 17 01:42:00 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: Usage: ubus [<options>] <command> [arguments...]
Fri Nov 17 01:42:00 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: Options:
Fri Nov 17 01:42:00 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -s <socket>:		Set the unix domain socket to connect to
Fri Nov 17 01:42:00 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -t <timeout>:		Set the timeout (in seconds) for a command to complete
Fri Nov 17 01:42:00 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -S:			Use simplified output (for scripts)
Fri Nov 17 01:42:00 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -v:			More verbose output
Fri Nov 17 01:42:00 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -m <type>:		(for monitor): include a specific message type
Fri Nov 17 01:42:00 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: 			(can be used more than once)
Fri Nov 17 01:42:00 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -M <r|t>		(for monitor): only capture received or transmitted traffic
Fri Nov 17 01:42:00 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:
Fri Nov 17 01:42:00 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: Commands:
Fri Nov 17 01:42:00 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - list [<path>]			List objects
Fri Nov 17 01:42:00 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - call <path> <method> [<message>]	Call an object method
Fri Nov 17 01:42:00 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - subscribe <path> [<path>...]	Subscribe to object(s) notifications
Fri Nov 17 01:42:00 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - listen [<path>...]			Listen for events
Fri Nov 17 01:42:00 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - send <type> [<message>]		Send an event
Fri Nov 17 01:42:00 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - wait_for <object> [<object>...]	Wait for multiple objects to appear on ubus
Fri Nov 17 01:42:00 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - monitor				Monitor ubus traffic
Fri Nov 17 01:42:00 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:
Fri Nov 17 01:42:01 2023 daemon.notice netifd: Wireless device 'radio0' is now up

@stangri
Copy link
Member

stangri commented Nov 16, 2023

@voron00
Copy link

voron00 commented Nov 17, 2023

@systemcrash @voron00 can you see if commenting out this line: https://github.com/stangri/source.openwrt.melmac.net/blob/master/https-dns-proxy/files/etc/init.d/https-dns-proxy#L138 and rebooting helps?

Sadly no, with on_boot_trigger=1 removed behaviour is exactly the same. Here is a full log, maybe it will be more helpful: https://gist.github.com/voron00/5b24e20fd670ec57a7cc52fa7a97f835

@stangri
Copy link
Member

stangri commented Nov 17, 2023

@systemcrash @voron00 can you see if commenting out this line: https://github.com/stangri/source.openwrt.melmac.net/blob/master/https-dns-proxy/files/etc/init.d/https-dns-proxy#L138 and rebooting helps?

Sadly no, with on_boot_trigger=1 removed behaviour is exactly the same. Here is a full log, maybe it will be more helpful: https://gist.github.com/voron00/5b24e20fd670ec57a7cc52fa7a97f835

The last message in that log is that service is stopped. Does it auto-recover/start later?

@voron00
Copy link

voron00 commented Nov 17, 2023

@systemcrash @voron00 can you see if commenting out this line: https://github.com/stangri/source.openwrt.melmac.net/blob/master/https-dns-proxy/files/etc/init.d/https-dns-proxy#L138 and rebooting helps?

Sadly no, with on_boot_trigger=1 removed behaviour is exactly the same. Here is a full log, maybe it will be more helpful: https://gist.github.com/voron00/5b24e20fd670ec57a7cc52fa7a97f835

The last message in that log is that service is stopped. Does it auto-recover/start later?

Hmm, no it did not auto-recover. I have to manually restart it in order to get it working again.

@stangri
Copy link
Member

stangri commented Nov 17, 2023

I can reintroduce the procd_boot_wait variable -- can you try inserting sleep command and try it with 5, 10, 20, 30 second wait, just below the https://github.com/stangri/source.openwrt.melmac.net/blob/master/https-dns-proxy/files/etc/init.d/https-dns-proxy#L138, above rc_procd commands.

@tkso1997
Copy link

tkso1997 commented Nov 18, 2023

Adding sleep 5 or 30 does not solve the problem.

boot() {                                                                                                                                 
        ubus -t 30 wait_for network.interface 2>/dev/null                                                                                
        on_boot_trigger=1                                                                                                                
        sleep 30                                                                                                                         
        rc_procd start_service 'on_boot' && rc_procd service_started 'on_boot'                                                           
        resolver_health_check || rc_procd stop_service 'on_boot' 
at Nov 18 12:45:50 2023 user.notice https-dns-proxy: Restarting dnsmasq on_config_update ✓
Sat Nov 18 12:45:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: Command failed: ubus call service add { "type": "config.change", "data": { "package": "firewall" } } (Invalid argument)
Sat Nov 18 12:45:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: Usage: ubus [<options>] <command> [arguments...]
Sat Nov 18 12:45:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: Options:
Sat Nov 18 12:45:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -s <socket>:		Set the unix domain socket to connect to
Sat Nov 18 12:45:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -t <timeout>:		Set the timeout (in seconds) for a command to complete
Sat Nov 18 12:45:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -S:			Use simplified output (for scripts)
Sat Nov 18 12:45:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -v:			More verbose output
Sat Nov 18 12:45:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -m <type>:		(for monitor): include a specific message type
Sat Nov 18 12:45:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: 			(can be used more than once)
Sat Nov 18 12:45:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -M <r|t>		(for monitor): only capture received or transmitted traffic
Sat Nov 18 12:45:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:
Sat Nov 18 12:45:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: Commands:
Sat Nov 18 12:45:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - list [<path>]			List objects
Sat Nov 18 12:45:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - call <path> <method> [<message>]	Call an object method
Sat Nov 18 12:45:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - subscribe <path> [<path>...]	Subscribe to object(s) notifications
Sat Nov 18 12:45:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - listen [<path>...]			Listen for events
Sat Nov 18 12:45:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - send <type> [<message>]		Send an event
Sat Nov 18 12:45:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - wait_for <object> [<object>...]	Wait for multiple objects to appear on ubus
Sat Nov 18 12:45:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  - monitor				Monitor ubus traffic
Sat Nov 18 12:45:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:
Sat Nov 18 12:45:50 2023 daemon.info dnsmasq[1]: exiting on receipt of SIGTERM

@stangri
Copy link
Member

stangri commented Nov 19, 2023

@matjon
Copy link

matjon commented Nov 23, 2023

Hello,
I also have this issue and have been investigating.
Curiously, in the debug log is ubus call service add , while in _procd_set_config_changed is ubus call service event.

The second variant succeeds:

root@archer-c59:~# ubus -v call service add  '{ "type": "config.change", "data": { "package": "firewall" } }' 
Command failed: Invalid argument
root@archer-c59:~# ubus -v call service event '{ "type": "config.change", "data": { "package": "firewall" } }' 

@systemcrash
Copy link
Contributor Author

service event syntax looks identical to what service add is trying to call.

ubus -v list service
'service' @3fe5e78c
	"set":{"name":"String","script":"String","instances":"Table","triggers":"Array","validate":"Array","autostart":"Boolean","data":"Table"}
	"add":{"name":"String","script":"String","instances":"Table","triggers":"Array","validate":"Array","autostart":"Boolean","data":"Table"}
	"list":{"name":"String","verbose":"Boolean"}
	"delete":{"name":"String","instance":"String"}
	"signal":{"name":"String","instance":"String","signal":"Integer"}
	"update_start":{"name":"String"}
	"update_complete":{"name":"String"}
	"event":{"type":"String","data":"Table"}
	"validate":{"package":"String","type":"String","service":"String"}
	"get_data":{"name":"String","instance":"String","type":"String"}
	"state":{"spawn":"Boolean","name":"String"}
	"watchdog":{"mode":"Integer","timeout":"Integer","name":"String","instance":"String"}

@matjon
Copy link

matjon commented Nov 23, 2023

I think I have found a solution.

Commenting out:

#service_started() { procd_set_config_changed firewall; }                            
service_started() { true; }                                             
#service_stopped() { procd_set_config_changed firewall; }                     
service_stopped() { true; }            

helps and fixes the issue.

I have inserted some debugging statements:

--- /rom/etc/rc.common	2023-11-14 14:38:11.000000000 +0100
+++ /etc/rc.common	2023-11-23 15:35:09.000000000 +0100
@@ -131,10 +131,13 @@
 	. $IPKG_INSTROOT/lib/functions/procd.sh
 	basescript=$(readlink "$initscript")
 	rc_procd() {
+		echo "rc_procd" _start "$*"
 		local method="set"
 		[ -n "$2" ] && method="add"
+		echo "rc_procd" procd_open_service "$(basename ${basescript:-$initscript})" "$initscript"
 		procd_open_service "$(basename ${basescript:-$initscript})" "$initscript"
 		"$@"
+		echo "rc_procd" procd_close_service "$method"
 		procd_close_service "$method"
 	}
 
--- /rom/lib/functions/procd.sh	2023-11-14 14:38:11.000000000 +0100
+++ /lib/functions/procd.sh	2023-11-23 13:59:31.000000000 +0100
@@ -79,6 +79,7 @@
 	local cmd="$1"
 
 	[ -n "$PROCD_DEBUG" ] && json_dump >&2
+	echo _procd_ubus_call ubus call service "$cmd" "$(json_dump)"
 	ubus call service "$cmd" "$(json_dump)"
 	json_cleanup
 }
@@ -104,6 +105,7 @@
 	_procd_open_data
 	service_data
 	_procd_close_data
+	echo _procd_close_service _procd_ubus_call "$1"
 	_procd_ubus_call ${1:-set}
 }
 
@@ -566,6 +568,7 @@
 	json_add_string package "$package"
 	json_close_object
 
+	echo _procd_set_config_changed ubus call service event "$(json_dump)"
 	ubus call service event "$(json_dump)"
 }
 

and with them the output is:

Thu Nov 23 15:35:45 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: rc_procd _start start_service on_boot
Thu Nov 23 15:35:45 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: rc_procd procd_open_service https-dns-proxy /etc/rc.d/S90https-dns-proxy
Thu Nov 23 15:35:45 2023 user.notice https-dns-proxy: Starting service instances on_boot ✓
Thu Nov 23 15:35:46 2023 daemon.info dnsmasq[1]: exiting on receipt of SIGTERM
[...]
[... dnsmasq restarts ]
Thu Nov 23 15:35:49 2023 daemon.info dnsmasq[1]: read /etc/hosts - 12 names
Thu Nov 23 15:35:49 2023 daemon.info dnsmasq[1]: read /tmp/hosts/dhcp.cfg01411c - 4 names
Thu Nov 23 15:35:49 2023 daemon.info dnsmasq-dhcp[1]: read /etc/ethers - 0 addresses
Thu Nov 23 15:35:49 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: rc_procd procd_close_service add
Thu Nov 23 15:35:49 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: _procd_close_service _procd_ubus_call add
Thu Nov 23 15:35:49 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: { "name": "https-dns-proxy", "script": "\/etc\/rc.d\/S90https-dns-proxy", "instances": { "instance1": { "command": [ "\/usr\/sbin\/https-dns-proxy", "-r", "https:\/\/doh.familyshield.opendns.com\/dns-query", "-a", "127.0.0.1", "-p", "5053", "-b", "208.67.222.123,208.67.220.123", "-4", "-u", "nobody", "-g", "nogroup" ], "stderr": true, "stdout": true, "respawn": [ "3600", "5", "5" ], "data": { "mdns": { "https-dns-proxy_5053": { "service": "_https-dns-proxy._udp.local", "port": 5053, "txt": [ "DNS over HTTPS proxy" ] } } } } }, "triggers": [ [ "interface.*.up", [ [ "run_script", "\/etc\/init.d\/https-dns-proxy", "restart", "on_interface_up" ] ], 3000 ], [ "config.change", [ "if", [ "eq", "package", "https-dns-proxy" ], [ "run_script", "\/etc\/init.d\/https-dns-proxy", "reload", "on_config_change" ] ], 1000 ] ], "data": { } }
Thu Nov 23 15:35:49 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: _procd_ubus_call ubus call service add { "name": "https-dns-proxy", "script": "\/etc\/rc.d\/S90https-dns-proxy", "instances": { "instance1": { "command": [ "\/usr\/sbin\/https-dns-proxy", "-r", "https:\/\/doh.familyshield.opendns.com\/dns-query", "-a", "127.0.0.1", "-p", "5053", "-b", "208.67.222.123,208.67.220.123", "-4", "-u", "nobody", "-g", "nogroup" ], "stderr": true, "stdout": true, "respawn": [ "3600", "5", "5" ], "data": { "mdns": { "https-dns-proxy_5053": { "service": "_https-dns-proxy._udp.local", "port": 5053, "txt": [ "DNS over HTTPS proxy" ] } } } } }, "triggers": [ [ "interface.*.up", [ [ "run_script", "\/etc\/init.d\/https-dns-proxy", "restart", "on_interface_up" ] ], 3000 ], [ "config.change", [ "if", [ "eq", "package", "https-dns-proxy" ], [ "run_script", "\/etc\/init.d\/https-dns-proxy", "reload", "on_config_change" ] ], 1000 ] ], "data": { } }
Thu Nov 23 15:35:49 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: rc_procd _start service_started on_boot
Thu Nov 23 15:35:49 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: rc_procd procd_open_service https-dns-proxy /etc/rc.d/S90https-dns-proxy
Thu Nov 23 15:35:49 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: _procd_set_config_changed ubus call service event { "type": "config.change", "data": { "package": "firewall" } }
Thu Nov 23 15:35:49 2023 daemon.notice procd: /etc/init.d/dnsmasq: Failed to parse json data: unexpected character
Thu Nov 23 15:35:49 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: rc_procd procd_close_service add
Thu Nov 23 15:35:49 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: _procd_close_service _procd_ubus_call add
Thu Nov 23 15:35:49 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: { "type": "config.change", "data": { "package": "firewall" } }
Thu Nov 23 15:35:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: _procd_ubus_call ubus call service add { "type": "config.change", "data": { "package": "firewall" } }
Thu Nov 23 15:35:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: Command failed: ubus call service add { "type": "config.change", "data": { "package": "firewall" } } (Invalid argument)
Thu Nov 23 15:35:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: Usage: ubus [<options>] <command> [arguments...]
Thu Nov 23 15:35:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy: Options:
Thu Nov 23 15:35:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -s <socket>:		Set the unix domain socket to connect to
Thu Nov 23 15:35:50 2023 daemon.notice procd: /etc/rc.d/S90https-dns-proxy:  -t <timeout>:		Set the timeout (in seconds) for a command to complete
[...]

rc_procd() in /etc/rc.common calls procd_close_service add. The parameter "add" of _procd_close_service causes _procd_ubus_call add to be executed.

There is a whole mess involved with calling rc_procd service_started 'on_boot' in function boot() in /etc/init.d/https-dns-proxy.
Instead, restarting firewall directly

--- etc/init.d/https-dns-proxy	2023-11-23 16:27:58.832918503 +0100
+++ https-dns-proxy	2023-11-23 16:43:25.966124231 +0100
@@ -139,7 +139,7 @@
 boot() {
 	ubus -t 30 wait_for network.interface 2>/dev/null
 	on_boot_trigger=1
-	rc_procd start_service 'on_boot' && rc_procd service_started 'on_boot'
+	rc_procd start_service 'on_boot' && procd_set_config_changed firewall
 	resolver_health_check || rc_procd stop_service 'on_boot'
 }
 

causes the program to run well:

root@archer-c59:~# service https-dns-proxy status
{ "name": "https-dns-proxy" }
running
root@archer-c59:~# 

@stangri
Copy link
Member

stangri commented Nov 23, 2023

-	rc_procd start_service 'on_boot' && rc_procd service_started 'on_boot'
+	rc_procd start_service 'on_boot' && procd_set_config_changed firewall

Can you test if

-	rc_procd start_service 'on_boot' && rc_procd service_started 'on_boot'
+	rc_procd start_service 'on_boot' && service_started 'on_boot'

Without modifying the service_started and service_stopped also works?

@matjon
Copy link

matjon commented Nov 23, 2023

Yes, it does work.

In syslog I got:

Thu Nov 23 19:58:04 2023 user.notice https-dns-proxy: Starting service instances on_boot ✓
Thu Nov 23 19:58:05 2023 daemon.info dnsmasq[1]: exiting on receipt of SIGTERM
[...]
[dnsmasq restarting]
Thu Nov 23 19:58:08 2023 daemon.info dnsmasq[1]: using only locally-known addresses for bind
Thu Nov 23 19:58:08 2023 daemon.info dnsmasq[1]: using only locally-known addresses for lan
Thu Nov 23 19:58:08 2023 daemon.info dnsmasq[1]: read /etc/hosts - 12 names
Thu Nov 23 19:58:08 2023 user.notice https-dns-proxy: Restarting dnsmasq on_boot ✓
Thu Nov 23 19:58:08 2023 daemon.info dnsmasq[1]: read /tmp/hosts/dhcp.cfg01411c - 4 names
Thu Nov 23 19:58:08 2023 daemon.info dnsmasq-dhcp[1]: read /etc/ethers - 0 addresses
Thu Nov 23 19:58:08 2023 user.notice https-dns-proxy: Stopping service on_boot ✓

The last message is "Stopping", but https-dns-proxy works and is used for DNS queries (which I verified by shutting it down manually - after it DNS queries stopped working).

root@archer-c59:~# diff https-dns-proxy_original  /etc/init.d/https-dns-proxy -U3
--- https-dns-proxy_original	2023-10-26 16:44:12.000000000 +0200
+++ /etc/init.d/https-dns-proxy	2023-11-23 19:57:28.000000000 +0100
@@ -136,7 +136,7 @@
 boot() {
 	ubus -t 30 wait_for network.interface 2>/dev/null
 	on_boot_trigger=1
-	rc_procd start_service 'on_boot' && rc_procd service_started 'on_boot'
+	rc_procd start_service 'on_boot' && service_started 'on_boot'
 	resolver_health_check || rc_procd stop_service 'on_boot'
 }
 
root@archer-c59:~# 

stangri added a commit to stangri/packages that referenced this issue Nov 23, 2023
* fixes openwrt#22674
* rename resolver_health_check to is_resolver_running for readability

Signed-off-by: Stan Grishin <stangri@melmac.ca>
stangri added a commit to stangri/packages that referenced this issue Nov 23, 2023
* fixes openwrt#22674
* rename resolver_health_check to is_resolver_running for readability
* reorder functions in the init file by name

Signed-off-by: Stan Grishin <stangri@melmac.ca>
stangri added a commit to stangri/packages that referenced this issue Nov 23, 2023
* fixes openwrt#22674
* rename resolver_health_check to is_resolver_running for readability
* reorder functions in the init file by name

Signed-off-by: Stan Grishin <stangri@melmac.ca>
(cherry picked from commit f519b68)
stangri added a commit to stangri/packages that referenced this issue Nov 23, 2023
* fixes openwrt#22674
* rename resolver_health_check to is_resolver_running for readability
* reorder functions in the init file by name

Signed-off-by: Stan Grishin <stangri@melmac.ca>
(cherry picked from commit f519b68)
tiagogaspar8 pushed a commit to tiagogaspar8/packages that referenced this issue Dec 20, 2023
* fixes openwrt#22674
* rename resolver_health_check to is_resolver_running for readability
* reorder functions in the init file by name

Signed-off-by: Stan Grishin <stangri@melmac.ca>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants