[OpenWrt-Devel] ubus and/or libubox upgrades today cause problems: some services do not start, logread hangs

Hannu Nyman hannu.nyman at iki.fi
Sat Dec 28 05:53:27 EST 2019


Petr Štetiar kirjoitti 27.12.2019 klo 16.04:
> Petr Štetiar <ynezz at true.cz> [2019-12-27 13:25:41]:
>
>> Hannu Nyman <hannu.nyman at iki.fi> [2019-12-27 11:33:46]:
>>
>>> Hopefully you/somebody will revert the ubus changes in master until then.
>> can you confirm, that following fix[1] actually fixes the issues you're
>> seeing? Thanks.
> This should be hopefully proper fix https://patchwork.ozlabs.org/patch/1215719/
>
> -- ynezz


Your (now merged) patch fixes the logread problem, but does not fix the more 
serious bug of not starting all services.

Services not starting is pretty serious, so I really do think that a revert 
to the situation before these "tests, fuzzing, fixes and improvements" 
changes in ubus and libubox might be a proper solution until a real fix is 
found for the breakage.


For me, at least collectd and nlbwmon do not start. Based on forum 
discussion, also samba4 does not start (link below). I suspect that quite 
many services do not start, but those two are the ones that I recognise 
easily from my own build.  (Could it be that core services from the main 
OpenWrt sources (like hostad, odhcp6c, dropbear,..) do start, but the others 
from feeds do not start???? Strange if that is true, as everything is built 
in one run.)  Forum discussion: 
https://forum.openwrt.org/t/logread-blank-on-master/51224/5

I did a full rebuild of everything (after "make dirclean") at 
r11826-9941edc724, and still I have the same problem with ipq806x/R7800.


I suspect that somehow your changes on ubus have made procd and ubus to not 
be in sync.

Like I wrote yesterday, the (now fixed) system log shows the procd error for 
collectd:
Sat Dec 28 11:54:14 2019 daemon.info procd: Not starting instance 
collectd::instance1, command not set

I have compared the ubus debug output in "ubus monitor" before the ubus and 
libubox changes, and the situation after. Below is the comparison. In the 
current situation, two messages are missing, as apparently procd determines 
that there are no such instances/services/commands to be launched.

These two lines from ubus messaging are currently missing:

<- b3f2e7fd #6f8d7a5c         notify: 
{"objid":1871542876,"method":"instance.start","data":{"service":"collectd","instance":"instance1"},"no_reply":true}
<- b3f2e7fd #6f8d7a5c         notify: 
{"objid":1871542876,"method":"service.start","data":{"service":"collectd"},"no_reply":true}


Below is the result of "/etc/init.d/collectd start" command:


Before (ubus and libubox changes reverted yesterday):

OpenWrt SNAPSHOT, r11816-d5ede68f8b
  -----------------------------------------------------

  Collectd starts ok

root at OpenWrt:~# ubus monitor
-> 33c383da #00000003         status: {"status":0}
-> 8051051e #8051051e          hello: {}
<- 8051051e #00000000         lookup: {"objpath":"service"}
-> 8051051e #00000000           data: 
{"objpath":"service","objid":1871542876,"objtype":-1561500561,"signature":{"set":{"name":3,"script":3,"instances":2,"triggers":1,"validate":1,"autostart":7,"data":2},"add":{"name":3,"script":3,"instances":2,"triggers":1,"validate":1,"autostart":7,"data":2},"list":{"name":3,"verbose":7},"delete":{"name":3,"instance":3},"signal":{"name":3,"instance":3,"signal":5},"update_start":{"name":3},"update_complete":{"name":3},"event":{"type":3,"data":2},"validate":{"package":3,"type":3,"service":3},"get_data":{"name":3,"instance":3,"type":3},"state":{"spawn":7,"name":3}}}
-> 8051051e #00000000         status: {"status":0}
<- 8051051e #6f8d7a5c         invoke: 
{"objid":1871542876,"method":"set","data":{"name":"collectd","script":"/etc/init.d/collectd","instances":{"instance1":{"command":["/usr/sbin/collectd","-C","/tmp/collectd.conf","-f"],"nice":5,"stderr":true,"respawn":["3600","5","5"]}},"triggers":[["config.change",["if",["eq","package","collectd"],["run_script","/etc/init.d/collectd","reload"]],1000]],"data":{}}}
-> b3f2e7fd #8051051e         invoke: 
{"objid":1871542876,"method":"set","data":{"name":"collectd","script":"/etc/init.d/collectd","instances":{"instance1":{"command":["/usr/sbin/collectd","-C","/tmp/collectd.conf","-f"],"nice":5,"stderr":true,"respawn":["3600","5","5"]}},"triggers":[["config.change",["if",["eq","package","collectd"],["run_script","/etc/init.d/collectd","reload"]],1000]],"data":{}},"user":"root","group":"root"}
<- b3f2e7fd #6f8d7a5c         notify: 
{"objid":1871542876,"method":"instance.start","data":{"service":"collectd","instance":"instance1"},"no_reply":true}
<- b3f2e7fd #6f8d7a5c         notify: 
{"objid":1871542876,"method":"service.start","data":{"service":"collectd"},"no_reply":true}
<- b3f2e7fd #8051051e         status: {"status":0,"objid":1871542876}
-> 8051051e #6f8d7a5c         status: {"status":0,"objid":1871542876}
-> 91c6d62e #91c6d62e          hello: {}
<- 91c6d62e #00000000         lookup: {"objpath":"service"}
-> 91c6d62e #00000000           data: 
{"objpath":"service","objid":1871542876,"objtype":-1561500561,"signature":{"set":{"name":3,"script":3,"instances":2,"triggers":1,"validate":1,"autostart":7,"data":2},"add":{"name":3,"script":3,"instances":2,"triggers":1,"validate":1,"autostart":7,"data":2},"list":{"name":3,"verbose":7},"delete":{"name":3,"instance":3},"signal":{"name":3,"instance":3,"signal":5},"update_start":{"name":3},"update_complete":{"name":3},"event":{"type":3,"data":2},"validate":{"package":3,"type":3,"service":3},"get_data":{"name":3,"instance":3,"type":3},"state":{"spawn":7,"name":3}}}
-> 91c6d62e #00000000         status: {"status":0}
<- 91c6d62e #6f8d7a5c         invoke: 
{"objid":1871542876,"method":"list","data":{"name":"collectd"}}
-> b3f2e7fd #91c6d62e         invoke: 
{"objid":1871542876,"method":"list","data":{"name":"collectd"},"user":"root","group":"root"}
<- b3f2e7fd #91c6d62e           data: 
{"objid":1871542876,"data":{"collectd":{"instances":{"instance1":{"running":true,"pid":9053,"command":["/usr/sbin/collectd","-C","/tmp/collectd.conf","-f"],"term_timeout":5,"respawn":{"threshold":3600,"timeout":5,"retry":5}}}}}}
-> 91c6d62e #6f8d7a5c           data: 
{"objid":1871542876,"data":{"collectd":{"instances":{"instance1":{"running":true,"pid":9053,"command":["/usr/sbin/collectd","-C","/tmp/collectd.conf","-f"],"term_timeout":5,"respawn":{"threshold":3600,"timeout":5,"retry":5}}}}}}
<- b3f2e7fd #91c6d62e         status: {"status":0,"objid":1871542876}
-> 91c6d62e #6f8d7a5c         status: {"status":0,"objid":1871542876}


After (the current system):

  OpenWrt SNAPSHOT, r11826-9941edc724
  -----------------------------------------------------
root at OpenWrt:~# ubus monitor
-> 9fdc704a #00000003         status: {"status":0}
-> 7a865230 #7a865230          hello: {}
<- 7a865230 #00000000         lookup: {"objpath":"service"}
-> 7a865230 #00000000           data: 
{"objpath":"service","objid":1565828036,"objtype":-1441295836,"signature":{"set":{"name":3,"script":3,"instances":2,"triggers":1,"validate":1,"autostart":7,"data":2},"add":{"name":3,"script":3,"instances":2,"triggers":1,"validate":1,"autostart":7,"data":2},"list":{"name":3,"verbose":7},"delete":{"name":3,"instance":3},"signal":{"name":3,"instance":3,"signal":5},"update_start":{"name":3},"update_complete":{"name":3},"event":{"type":3,"data":2},"validate":{"package":3,"type":3,"service":3},"get_data":{"name":3,"instance":3,"type":3},"state":{"spawn":7,"name":3}}}
-> 7a865230 #00000000         status: {"status":0}
<- 7a865230 #5d54a3c4         invoke: 
{"objid":1565828036,"method":"set","data":{"name":"collectd","script":"/etc/init.d/collectd","instances":{"instance1":{"command":["/usr/sbin/collectd","-C","/tmp/collectd.conf","-f"],"nice":5,"stderr":true,"respawn":["3600","5","5"]}},"triggers":[["config.change",["if",["eq","package","collectd"],["run_script","/etc/init.d/collectd","reload"]],1000]],"data":{}}}
-> 5a86d6d9 #7a865230         invoke: 
{"objid":1565828036,"method":"set","data":{"name":"collectd","script":"/etc/init.d/collectd","instances":{"instance1":{"command":["/usr/sbin/collectd","-C","/tmp/collectd.conf","-f"],"nice":5,"stderr":true,"respawn":["3600","5","5"]}},"triggers":[["config.change",["if",["eq","package","collectd"],["run_script","/etc/init.d/collectd","reload"]],1000]],"data":{}},"user":"root","group":"root"}
<- 5a86d6d9 #7a865230         status: {"status":0,"objid":1565828036}
-> 7a865230 #5d54a3c4         status: {"status":0,"objid":1565828036}
-> 5c5a8fe3 #5c5a8fe3          hello: {}
<- 5c5a8fe3 #00000000         lookup: {"objpath":"service"}
-> 5c5a8fe3 #00000000           data: 
{"objpath":"service","objid":1565828036,"objtype":-1441295836,"signature":{"set":{"name":3,"script":3,"instances":2,"triggers":1,"validate":1,"autostart":7,"data":2},"add":{"name":3,"script":3,"instances":2,"triggers":1,"validate":1,"autostart":7,"data":2},"list":{"name":3,"verbose":7},"delete":{"name":3,"instance":3},"signal":{"name":3,"instance":3,"signal":5},"update_start":{"name":3},"update_complete":{"name":3},"event":{"type":3,"data":2},"validate":{"package":3,"type":3,"service":3},"get_data":{"name":3,"instance":3,"type":3},"state":{"spawn":7,"name":3}}}
-> 5c5a8fe3 #00000000         status: {"status":0}
<- 5c5a8fe3 #5d54a3c4         invoke: 
{"objid":1565828036,"method":"list","data":{"name":"collectd"}}
-> 5a86d6d9 #5c5a8fe3         invoke: 
{"objid":1565828036,"method":"list","data":{"name":"collectd"},"user":"root","group":"root"}
<- 5a86d6d9 #5c5a8fe3           data: 
{"objid":1565828036,"data":{"collectd":{"instances":{}}}}
-> 5c5a8fe3 #5d54a3c4           data: 
{"objid":1565828036,"data":{"collectd":{"instances":{}}}}
<- 5a86d6d9 #5c5a8fe3         status: {"status":0,"objid":1565828036}
-> 5c5a8fe3 #5d54a3c4         status: {"status":0,"objid":1565828036}


_______________________________________________
openwrt-devel mailing list
openwrt-devel at lists.openwrt.org
https://lists.openwrt.org/mailman/listinfo/openwrt-devel


More information about the openwrt-devel mailing list