A lot of reconfigurations cause confd to crash

[mattiaswal]

Current Behavior

Running a test in a loop result i confd failure, after 251 loops:

e=0; while [ $? -eq 0  ]; do e=$((e+1)); echo "Loop $e"; ./case/ietf_system/hostname/test.py -t restconf; done

RESTCONF/NETCONF doesn't matter, it is the same behavior with both.

Dec  9 10:21:15 ix-00-02-00 rousette[17872]: [2024-12-09 10:21:15.823] [rousette] [info] [::1]:50156: POST /restconf/data/infix-test:test/reset 
Dec  9 10:21:15 ix-00-02-00 confd[17849]: libyang[1]: Obsolete schema node "meta" instantiated in data.
Dec  9 10:21:15 ix-00-02-00 confd[17849]: Recursive reader limit 255 reached, possibly because of missing unlocks.
Dec  9 10:21:15 ix-00-02-00 confd[17849]: failed sr_subscription_process_events(), ret:7
Dec  9 10:21:15 ix-00-02-00 finit[1]: Stopping netopeer[17858], sending SIGTERM ...
Dec  9 10:21:15 ix-00-02-00 finit[1]: Stopping statd[17868], sending SIGTERM ...
Dec  9 10:21:15 ix-00-02-00 finit[1]: Stopping rousette[17872], sending SIGTERM ...
Dec  9 10:21:15 ix-00-02-00 finit[1]: Service confd[17849] died, restarting in 2000 msec (1/10)
Dec  9 10:21:15 ix-00-02-00 finit[1]: Starting confd[6308]
Dec  9 10:21:15 ix-00-02-00 sysrepo-plugind[6308]: Connection with CID 10 is dead.
Dec  9 10:21:15 ix-00-02-00 sysrepo-plugind[6308]: Recovering module "sysrepo-plugind" running change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 last message buffered 1 times
Dec  9 10:21:15 ix-00-02-00 sysrepo-plugind[6308]: Recovering module "sysrepo-plugind" operational get subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "ietf-interfaces" running change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 last message buffered 2 times
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "ietf-interfaces" startup change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "ietf-interfaces" candidate change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovered a read-lock of CID 10 (sr_module_change_subscribe).
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "ietf-keystore" running change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 last message buffered 3 times
Dec  9 10:21:15 ix-00-02-00 confd[6308]: ietf_keystore_init failed: Operation succeeded
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "ietf-syslog" running change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 last message buffered 11 times
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "ietf-syslog" startup change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 last message buffered 3 times
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovered a read-lock of CID 10 (sr_module_change_subscribe).
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "ietf-system" running change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 last message buffered 22 times
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Connection with CID 12 is dead.
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "ietf-system" operational get subscription of CID 12.
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "ietf-system" operational get subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 last message buffered 4 times
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "ietf-netconf-acm" running change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "ietf-system" startup change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 last message buffered 6 times
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering RPC/action "/ietf-system:system-restart" subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering RPC/action "/ietf-system:system-shutdown" subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering RPC/action "/ietf-system:set-current-datetime" subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "infix-dhcp-client" running change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 last message buffered 2 times
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "infix-dhcp-client" startup change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "infix-dhcp-client" candidate change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering RPC/action "/infix-factory-default:factory-default" subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering RPC/action "/ietf-factory-default:factory-reset" subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "ietf-routing" running change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 last message buffered 2 times
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "ietf-routing" startup change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "infix-meta" running change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering RPC/action "/infix-system:install-bundle" subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "infix-services" running change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 last message buffered 17 times
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "infix-services" startup change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 last message buffered 5 times
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "ieee802-dot1ab-lldp" running change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 last message buffered 2 times
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "ieee802-dot1ab-lldp" startup change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "ietf-keystore" startup change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "ietf-hardware" running change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 last message buffered 2 times
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "ietf-hardware" startup change subscription of CID 10.
Dec  9 10:21:15 ix-00-02-00 confd[6308]: Recovering module "ietf-hardware" candidate change subscription of CID 10.
Dec  9 10:21:18 ix-00-02-00 finit[1]: Stopping rousette[17872], sending SIGKILL ...

[mattiaswal]

This seems to be fixed with later CESNET packages, i am using latest (devel:2012-12-20) version of libyang,sysrepo,netopeer2, libnetconf2, rousette, libyang-cpp, sysrepo-cpp and the bug can not be seen.

[mattiaswal]

This seems to be fixed with later CESNET packages, i am using latest (devel:2012-12-20) version of libyang,sysrepo,netopeer2, libnetconf2, rousette, libyang-cpp, sysrepo-cpp and the bug can not be seen.

That is a lie, not fixed. I think this is something we are responsible to. Start checking that all sr_get_data objects
get freed correctly.

[mattiaswal]

Our sysrepo patches are not the problem, run with only bare minimum patchset, still fails:

diff --git a/src/executables/sysrepo-plugind.c b/src/executables/sysrepo-plugind.c
index 3b66cfa6..c531ca60 100644
--- a/src/executables/sysrepo-plugind.c
+++ b/src/executables/sysrepo-plugind.c
@@ -100,6 +100,7 @@ help_print(void)
             "                       Change verbosity to a level (none, error, warning, info, debug) or\n"
             "                       number (0, 1, 2, 3, 4).\n"
             "  -d, --debug          Debug mode - is not daemonized and logs to stderr instead of syslog.\n"
+            "  -n, --foreground     Run in foreground and log to syslog.\n"
             "  -P, --plugin-install \n"
             "                       Install a sysrepo-plugind plugin. The plugin is simply copied\n"
             "                       to the designated plugin directory.\n"
@@ -214,6 +215,8 @@ daemon_init(int debug, sr_log_level_t log_level)
 
     if (debug) {
         handle_signals();
+        if (debug < 0)
+            goto done;
         sr_log_stderr(log_level);
         return;
     }
@@ -254,6 +257,7 @@ daemon_init(int debug, sr_log_level_t log_level)
         close(fd);
     }
 
+done:
     /* set verbosity */
     sr_log_syslog("sysrepo-plugind", log_level);
 }
@@ -479,6 +483,7 @@ main(int argc, char **argv)
         {"version",           no_argument,       NULL, 'V'},
         {"verbosity",         required_argument, NULL, 'v'},
         {"debug",             no_argument,       NULL, 'd'},
+        {"foreground",        no_argument,       NULL, 'n'},
         {"plugin-install",    required_argument, NULL, 'P'},
         {"pid-file",          required_argument, NULL, 'p'},
         {"fatal-plugin-fail", no_argument,       NULL, 'f'},
@@ -487,7 +492,7 @@ main(int argc, char **argv)
 
     /* process options */
     opterr = 0;
-    while ((opt = getopt_long(argc, argv, "hVv:dP:p:f", options, NULL)) != -1) {
+    while ((opt = getopt_long(argc, argv, "hVv:dnP:p:f", options, NULL)) != -1) {
         switch (opt) {
         case 'h':
             version_print();
@@ -519,6 +524,9 @@ main(int argc, char **argv)
         case 'd':
             debug = 1;
             break;
+        case 'n':
+            debug = -1;
+            break;
         case 'P':
             /* plugin-install */
             if (get_plugins_dir(&plugins_dir)) {

[mattiaswal]

This was not a problem in the real world, only when using test mode, the callback did not release the context it has aquired.