C-API: All calls to clicon_log_xml() changed to new function `clicon_debug_xml()\

Debugging, moved many detailed debugs from level 1 to 2

.gitignore

@@ -15,6 +15,7 @@ docker/*/Makefile
 etc/Makefile
 example/Makefile
 example/*/Makefile
+example/main/example.xml
 lib/Makefile
 lib/*/Makefile
 test/Makefile
@@ -51,6 +52,7 @@ build-root/rpmbuild
 build-root/debbuild
 
 util/clixon_util_datastore
+util/clixon_util_dispatcher
 util/clixon_util_grpc
 util/clixon_util_insert
 util/clixon_util_json
@@ -58,12 +60,14 @@ util/clixon_util_path
 util/clixon_util_regexp
 util/clixon_util_socket
 util/clixon_util_stream
+util/clixon_util_validate
 util/clixon_util_xml
 util/clixon_util_xml_mod
 util/clixon_util_xpath
 util/clixon_util_yang
 util/clixon_netconf_ssh_callhome
 util/clixon_netconf_ssh_callhome_client
+util/clixon_restconf_callhome_client
 
 test/config.sh
 test/site.sh

CHANGELOG.md

@@ -75,6 +75,7 @@ Developers may need to change their code
     * Added netconf ssh subsystem
     * Renamed from `clixon` built in `docker/base`
 * C-API
+  * All calls to `clicon_log_xml()` changed to new function `clicon_debug_xml()`
   * Changed type of `veclen` parameter to `size_t` in `xpath_vec_flag()`
   * Added `with-defaults` parameter (default 0) to `xmldb_get0()`
   * Added `sock_flags` parameter to `clixon_proc_socket()`

apps/backend/backend_client.c

@@ -1529,7 +1529,7 @@ from_client_msg(clicon_handle        h,
     char                *namespace = NULL;
     int                  nr = 0;
     
-    clicon_debug(1, "%s", __FUNCTION__);
+    clicon_debug(2, "%s", __FUNCTION__);
     yspec = clicon_dbspec_yang(h); 
     /* Return netconf message. Should be filled in by the dispatch(sub) functions 
      * as wither rpc-error or by positive response.
@@ -1699,7 +1699,7 @@ from_client_msg(clicon_handle        h,
     if (cbuf_len(cbret) == 0)
         if (netconf_operation_failed(cbret, "application", clicon_errno?clicon_err_reason:"unknown")< 0)
             goto done;
-    clicon_debug(1, "%s cbret:%s", __FUNCTION__, cbuf_get(cbret));
+    clicon_debug(2, "%s cbret:%s", __FUNCTION__, cbuf_get(cbret));
     /* XXX problem here is that cbret has not been parsed so may contain 
        parse errors */
     if (send_msg_reply(ce->ce_s, cbuf_get(cbret), cbuf_len(cbret)+1) < 0){
@@ -1759,7 +1759,7 @@ from_client(int   s,
     clicon_handle        h = ce->ce_handle;
     int                  eof = 0;
 
-    clicon_debug(1, "%s", __FUNCTION__);
+    clicon_debug(2, "%s", __FUNCTION__);
     if (s != ce->ce_s){
         clicon_err(OE_NETCONF, EINVAL, "Internal error: s != ce->ce_s");
         goto done;

apps/backend/backend_get.c

@@ -751,8 +751,7 @@ get_list_pagination(clicon_handle        h,
         if ((ret = xml_bind_yang(xret, YB_MODULE, yspec, &xerr)) < 0)
             goto done;
         if (ret == 0){
-            if (clicon_debug_get() && xret)
+            clicon_debug_xml(1, xret, "Yang bind pagination state");
-                clicon_log_xml(LOG_DEBUG, xret, "Yang bind pagination state");
             if (clixon_netconf_internal_error(xerr,
                                               ". Internal error, state callback returned invalid XML",
                                               NULL) < 0)
@@ -860,8 +859,7 @@ get_common(clicon_handle        h,
 #else
     wdef = WITHDEFAULTS_EXPLICIT;
 #endif
-    
+    clicon_debug(2, "%s", __FUNCTION__);
-    clicon_debug(1, "%s", __FUNCTION__);
     username = clicon_username_get(h);
     if ((yspec =  clicon_dbspec_yang(h)) == NULL){
         clicon_err(OE_YANG, ENOENT, "No yang spec9");
@@ -1007,8 +1005,7 @@ get_common(clicon_handle        h,
             (ret = xml_yang_validate_add(h, xret, &xerr)) < 0)
             goto done;
         if (ret == 0){
-            if (clicon_debug_get())
+            clicon_debug_xml(1, xret, "VALIDATE_STATE");
-                clicon_log_xml(LOG_DEBUG, xret, "VALIDATE_STATE");
             if (clixon_netconf_internal_error(xerr,
                                               ". Internal error, state callback returned invalid XML",
                                               NULL) < 0)
@@ -1039,7 +1036,7 @@ get_common(clicon_handle        h,
  ok:
     retval = 0;
  done:
-    clicon_debug(1, "%s retval:%d", __FUNCTION__, retval);
+    clicon_debug(2, "%s retval:%d", __FUNCTION__, retval);
     if (xvec)
         free(xvec);
     if (xret)

apps/backend/backend_plugin.c

@@ -368,8 +368,7 @@ clixon_plugin_statedata_all(clicon_handle   h,
             x = NULL;
             continue;
         }
-        if (clicon_debug_get())
+        clicon_debug_xml(2, x, "%s %s STATE:", __FUNCTION__, clixon_plugin_name_get(cp));
-            clicon_log_xml(LOG_DEBUG, x, "%s %s STATE:", __FUNCTION__, clixon_plugin_name_get(cp));
         /* XXX: ret == 0 invalid yang binding should be handled as internal error */
         if ((ret = xml_bind_yang(x, YB_MODULE, yspec, &xerr)) < 0)
             goto done;

apps/restconf/restconf_err.c

@@ -238,8 +238,7 @@ api_return_err(clicon_handle  h,
         }
     }
 #if 1
-    if (clicon_debug_get())
+    clicon_debug_xml(1, xerr, "%s Send error:", __FUNCTION__);
-        clicon_log_xml(LOG_DEBUG, xerr, "%s Send error:", __FUNCTION__);
 #endif
     if (xml_name_set(xerr, "error") < 0)
         goto done;

apps/restconf/restconf_methods.c

@@ -490,7 +490,7 @@ api_data_write(clicon_handle h,
                 goto done;
             }
             if (namespace == NULL){
-                clicon_log_xml(LOG_DEBUG, xparent, "%s xparent:", __FUNCTION__);
+                clicon_debug_xml(1, xparent, "%s xparent:", __FUNCTION__);
                 /* XXX */
             }
             /* Set xmlns="" default namespace attribute (if diff from default) */

apps/restconf/restconf_methods_get.c

@@ -215,7 +215,7 @@ api_data_get2(clicon_handle  h,
      */
 #if 0 /* DEBUG */
     if (clicon_debug_get())
-        clicon_log_xml(LOG_DEBUG, xret, "%s xret:", __FUNCTION__);
+        clicon_debug_xml(1, xret, "%s xret:", __FUNCTION__);
 #endif
     /* Check if error return  */
     if ((xe = xpath_first(xret, NULL, "//rpc-error")) != NULL){
@@ -502,8 +502,7 @@ api_data_pagination(clicon_handle  h,
      * We need to cut that tree to only the object.
      */
 #if 0 /* DEBUG */
-    if (clicon_debug_get())
+    clicon_debug_xml(1, xret, "%s xret:", __FUNCTION__);
-        clicon_log_xml(LOG_DEBUG, xret, "%s xret:", __FUNCTION__);
 #endif
     /* Check if error return  */
     if ((xe = xpath_first(xret, NULL, "//rpc-error")) != NULL){

apps/restconf/restconf_methods_patch.c

@@ -622,8 +622,7 @@ yang_patch_do_edit(clicon_handle  h,
     yang_stmt *ybot = NULL;
     yang_stmt *ymod;
 
-    
+    clicon_debug_xml(1, xn, "%s %d xn:", __FUNCTION__, __LINE__);
-    clicon_log_xml(LOG_DEBUG, xn, "%s %d xn:", __FUNCTION__, __LINE__);
     /* Create cbufs:s */
     if ((simple_patch_request_uri = cbuf_new()) == NULL){
         clicon_err(OE_UNIX, errno, "cbuf_new");

apps/restconf/restconf_methods_post.c

@@ -326,8 +326,7 @@ api_data_post(clicon_handle h,
     if (restconf_insert_attributes(xdata, qvec) < 0)
         goto done;
 #if 1
-    if (clicon_debug_get())
+    clicon_debug_xml(1, xdata, "%s xdata:", __FUNCTION__);
-        clicon_log_xml(LOG_DEBUG, xdata, "%s xdata:", __FUNCTION__);
 #endif
 
     /* Create text buffer for transfer to backend */
@@ -487,8 +486,7 @@ api_operations_post_input(clicon_handle h,
      * <data><input xmlns="urn:example:clixon">...</input></data>
      */
 #if 1
-    if (clicon_debug_get())
+    clicon_debug_xml(1, xdata, "%s xdata:", __FUNCTION__);
-        clicon_log_xml(LOG_DEBUG, xdata, "%s xdata:", __FUNCTION__);
 #endif
     /* Validate that exactly only <input> tag */
     if ((xinput = xml_child_i_type(xdata, 0, CX_ELMNT)) == NULL ||
@@ -585,8 +583,7 @@ api_operations_post_output(clicon_handle h,
     xml_name_set(xoutput, "output");
     /* xoutput should now look: <output><x xmlns="uri">0</x></output> */
 #if 1
-    if (clicon_debug_get())
+    clicon_debug_xml(1, xoutput, "%s xoutput:", __FUNCTION__);
-        clicon_log_xml(LOG_DEBUG, xoutput, "%s xoutput:", __FUNCTION__);
 #endif
     /* Remove original netconf default namespace. Somewhat unsure what "output" belongs to? */
     if ((xa = xml_find_type(xoutput, NULL, "xmlns", CX_ATTR)) != NULL)
@@ -798,8 +795,7 @@ api_operations_post(clicon_handle h,
     /* Here xtop is: 
       <rpc username="foo"><myfn xmlns="uri"><x>42</x></myfn></rpc> */
 #if 1
-    if (clicon_debug_get())
+    clicon_debug_xml(1, xtop, "%s 5. Translate input args:", __FUNCTION__);
-        clicon_log_xml(LOG_DEBUG, xtop, "%s 5. Translate input args:", __FUNCTION__);
 #endif
     /* 6. Validate outgoing RPC and fill in defaults */
     if ((ret = xml_bind_yang_rpc(xtop, yspec, &xerr)) < 0) /*  */
@@ -820,8 +816,7 @@ api_operations_post(clicon_handle h,
      * <rpc username="foo"><myfn xmlns="uri"><x>42</x><y>99</y></myfn></rpc>
     */
 #if 0
-    if (clicon_debug_get())
+    clicon_debug_xml(1, xtop, "%s 6. Validate and defaults:", __FUNCTION__);
-        clicon_log_xml(LOG_DEBUG, xtop, "%s 6. Validate and defaults:", __FUNCTION__);
 #endif
     /* 7. Send to RPC handler, either local or backend
      * Note (1) xtop is <rpc><method> xbot is <method>
@@ -862,8 +857,7 @@ api_operations_post(clicon_handle h,
      *       <rpc-reply><x xmlns="uri">0</x></rpc-reply>
      */
 #if 1
-    if (clicon_debug_get())
+    clicon_debug_xml(1, xret, "%s Receive reply:", __FUNCTION__);
-        clicon_log_xml(LOG_DEBUG, xret, "%s Receive reply:", __FUNCTION__);
 #endif
     youtput = yang_find(yrpc, Y_OUTPUT, NULL);
     if ((ret = api_operations_post_output(h, req, xret, yspec, youtput, namespace,

include/clixon_custom.h

@@ -32,7 +32,7 @@
   ***** END LICENSE BLOCK *****
 
   Custom file as boilerplate appended by clixon_config.h 
-  These are compile-time options. RUntime options are in clixon-config.yang.
+  These are compile-time options. Runtime options are in clixon-config.yang.
   In general they are kludges and "should be removed" when code is improved
   and not proper system config options.
   Note that clixon_config.h is only included by clixon system files, not automatically by examples

lib/clixon/clixon_netconf_lib.h

@@ -52,7 +52,10 @@
 #define NETCONF_BASE_NAMESPACE "urn:ietf:params:xml:ns:netconf:base:1.0"
 #define NETCONF_BASE_PREFIX "nc"
 
-/* In cases where message-id is not given by external client, use this */
+/* In cases where message-id is not given by external client, use this 
+ * Note hardcoded message-id, which is ok for server, but a client should
+ * eg assign message-id:s incrementally
+ */
 #define NETCONF_MESSAGE_ID_DEFAULT "42"
 #define NETCONF_MESSAGE_ID_ATTR "message-id=\"42\""
 

lib/clixon/clixon_xml.h

@@ -281,6 +281,7 @@ char     *xml_operation2str(enum operation_type op);
 int       xml_attr_insert2val(char *instr, enum insert_type *ins);
 int       xml_add_attr(cxobj *xn, char *name, char *value, char *prefix, char *ns);
 int       clicon_log_xml(int level, cxobj *x, const char *format, ...)  __attribute__ ((format (printf, 3, 4)));
+int       clicon_debug_xml(int dbglevel, cxobj *x, const char *format, ...)  __attribute__ ((format (printf, 3, 4)));
 
 #ifdef XML_EXPLICIT_INDEX
 int       xml_search_index_p(cxobj *x);

lib/src/clixon_log.c

@@ -372,6 +372,7 @@ clicon_debug_get(void)
  *                       1 default level if passed -D
  *                       2.. Higher debug levels
  * @param[in] format     Message to print as argv.
+ * @see clicon_debug_xml Specialization for XML tree
  */
 int
 clicon_debug(int         dbglevel, 
@@ -383,7 +384,7 @@ clicon_debug(int         dbglevel,
     int     retval = -1;
     size_t  trunc;
     
-    if (dbglevel > _clixon_debug) /* compare debug mask with global variable */
+    if (dbglevel > clicon_debug_get()) /* compare debug level with global variable */
         return 0;
     /* first round: compute length of debug message */
     va_start(args, format);

lib/src/clixon_proto.c

@@ -194,7 +194,7 @@ clicon_msg_decode(struct clicon_msg *msg,
         *id = ntohl(msg->op_id);
     /* body */
     xmlstr = msg->op_body;
-    clicon_debug(1, "%s %s", __FUNCTION__, xmlstr);
+    clicon_debug(2, "%s %s", __FUNCTION__, xmlstr);
     if ((ret = clixon_xml_parse_string(xmlstr, yspec?YB_RPC:YB_NONE, yspec, xml, xerr)) < 0)
         goto done;
     if (ret == 0)

lib/src/clixon_xml.c

@@ -1401,8 +1401,7 @@ xml_purge(cxobj *xc)
  * @param[in]   i      Number of xml child node (to remove)
  * @retval      0      OK
  * @retval      -1
- * @note you should not remove xchild in loop (unless yoy keep track of xprev)
+ * @note you should not remove xchild in loop (unless you keep track of xprev)
- *
  * @see xml_rootchild
  * @see xml_rm     Remove the node itself from parent
  */
@@ -2368,10 +2367,13 @@ xml_add_attr(cxobj *xn,
     return retval;
 }
 
-/*! Specialization of clicon_debug with xml tree 
+/*! Specialization of clicon_log with xml tree 
+ *
+ * @param[in]  dbglevel 
  * @param[in]  level    log level, eg LOG_DEBUG,LOG_INFO,...,LOG_EMERG. 
  * @param[in]  x        XML tree that is logged without prettyprint
  * @param[in]  format   Message to print as argv.
+ * @see clicon_debug_xml  which uses debug setting instead of direct syslog
  */
 int
 clicon_log_xml(int         level, 
@@ -2428,6 +2430,71 @@ clicon_log_xml(int         level,
     return retval;
 }
 
+/*! Specialization of clicon_debug with xml tree 
+ *
+ * @param[in]  dbglevel 
+ * @param[in]  x        XML tree that is logged without prettyprint
+ * @param[in]  format   Message to print as argv.
+ * @see clicon_log_xml  For syslog
+ * @see clicon_debug    base function
+*/
+int
+clicon_debug_xml(int         dbglevel, 
+                 cxobj      *x,
+                 const char *format, ...)
+{
+    va_list args;
+    size_t  len;
+    char   *msg = NULL;
+    cbuf   *cb = NULL;
+    int     retval = -1;
+    size_t  trunc;
+
+    if (dbglevel > clicon_debug_get()) /* compare debug level with global variable */
+        return 0;
+    /* Print xml as cbuf */
+    if ((cb = cbuf_new()) == NULL){
+        clicon_err(OE_XML, errno, "cbuf_new");
+        goto done;
+    }
+    if (clixon_xml2cbuf(cb, x, 0, 0, -1, 0) < 0)
+        goto done;
+    /* first round: compute length of debug message */
+    va_start(args, format);
+    len = vsnprintf(NULL, 0, format, args);
+    va_end(args);
+    
+    /* Truncate long debug strings */
+    if ((trunc = clicon_log_string_limit_get()) && trunc < len)
+        len = trunc;
+
+    /* allocate a message string exactly fitting the message length */
+    if ((msg = malloc(len+1)) == NULL){
+        fprintf(stderr, "malloc: %s\n", strerror(errno)); /* dont use clicon_err here due to recursion */
+        goto done;
+    }
+
+    /* second round: compute write message from format and args */
+    va_start(args, format);
+    if (vsnprintf(msg, len+1, format, args) < 0){
+        va_end(args);
+        fprintf(stderr, "vsnprintf: %s\n", strerror(errno)); /* dont use clicon_err here due to recursion */
+        goto done;
+    }
+    va_end(args);
+
+    /* Actually log it */
+    clicon_debug(dbglevel, "%s: %s", msg, cbuf_get(cb));
+
+    retval = 0;
+  done:
+    if (cb)
+        cbuf_free(cb);
+    if (msg)
+        free(msg);
+    return retval;
+}
+
 #ifdef XML_EXPLICIT_INDEX
 /*
  *

lib/src/clixon_xml_map.c

@@ -575,7 +575,7 @@ xml_tree_prune_flagged(cxobj *xt,
  * @param[in]   mask    Which flags to test for
  * The function removes all branches that does pass test
  * @code
- *    xml_tree_prune_flaggs(xt, XML_FLAG_MARK, XML_FLAG_MARK|XML_FLAG_DEFAULT);
+ *    xml_tree_prune_flags(xt, XML_FLAG_MARK, XML_FLAG_MARK|XML_FLAG_DEFAULT);
  * @endcode
  */
 int

lib/src/clixon_xpath.c

@@ -531,6 +531,7 @@ xpath_parse(const char  *xpath,
     clixon_xpath_yacc xpy = {0,};
     cbuf             *cb = NULL;    
 
+    clicon_debug(2, "%s", __FUNCTION__);
     if (xpath == NULL){
         clicon_err(OE_XML, EINVAL, "XPath is NULL");
         goto done;
@@ -542,7 +543,6 @@ xpath_parse(const char  *xpath,
         goto done;
     if (xpath_parse_init(&xpy) < 0)
         goto done;
-    clicon_debug(2,"%s",__FUNCTION__);
     if (clixon_xpath_parseparse(&xpy) != 0) { /* yacc returns 1 on error */
         clicon_log(LOG_NOTICE, "XPATH error: on line %d", xpy.xpy_linenum);
         if (clicon_errno == 0)
@@ -602,6 +602,7 @@ xpath_vec_ctx(cxobj      *xcur,
     xpath_tree *xptree = NULL;
     xp_ctx      xc = {0,};
     
+    clicon_debug(2, "%s", __FUNCTION__);
     if (xpath_parse(xpath, &xptree) < 0)
         goto done;
     xc.xc_type = XT_NODESET;
@@ -1081,6 +1082,7 @@ xpath2canonical(const char *xpath0,
     cbuf       *xcb = NULL;
     int         ret;
 
+    clicon_debug(2, "%s", __FUNCTION__);
     /* Parse input xpath into an xpath-tree */
     if (xpath_parse(xpath0, &xpt) < 0)
         goto done;

lib/src/clixon_xpath_eval.c

@@ -1128,8 +1128,7 @@ xp_eval(xp_ctx     *xc,
     xp_ctx    *xr2 = NULL;
     int        use_xr0 = 0; /* In 2nd child use transitively result of 1st child */
     
-    if (clicon_debug_get() > 1)
+    // ctx_print(stderr, xc, xpath_tree_int2str(xs->xs_type));
-        ctx_print(stderr, xc, xpath_tree_int2str(xs->xs_type));
     /* Pre-actions before check first child c0
      */
     switch (xs->xs_type){
@@ -1368,8 +1367,7 @@ xp_eval(xp_ctx     *xc,
             xr0 = NULL;
         }
  ok:
-    if (clicon_debug_get() > 1)
+    // ctx_print(stderr, *xrp, xpath_tree_int2str(xs->xs_type));
-        ctx_print(stderr, *xrp, xpath_tree_int2str(xs->xs_type));
     retval = 0;
  done:
     if (xr2)

lib/src/clixon_xpath_yang.c

@@ -466,6 +466,7 @@ yang_path_arg(yang_stmt  *ys,
     xp_yang_ctx *xyr = NULL;
     xp_yang_ctx *xy = NULL;
 
+    clicon_debug(2, "%s", __FUNCTION__);
     if (path_arg == NULL){
         clicon_err(OE_XML, EINVAL, "path-arg is NULL");
         goto done;

lib/src/clixon_yang.c

@@ -2909,7 +2909,7 @@ yang_features(clicon_handle h,
             ret = 0;
             if (yang_subparse(yang_argument_get(ys), ys, YA_IF_FEATURE, mainfile, 1, &ret) < 0)
                 goto done;
-            clicon_debug(1, "%s %s %d", __FUNCTION__, yang_argument_get(ys), ret);
+            clicon_debug(2, "%s %s %d", __FUNCTION__, yang_argument_get(ys), ret);
             if (ret == 0)
                 goto disabled;
         }

lib/src/clixon_yang_sub_parse.c

@@ -120,7 +120,7 @@ yang_schema_nodeid_subparse(char                      *str,
     int                         retval = -1;
     clixon_yang_schemanode_yacc ife = {0,};
 
-    clicon_debug(2, "%s %s", __FUNCTION__, str);
+    clicon_debug(3, "%s %s", __FUNCTION__, str);
     ife.if_parse_string = str;
     ife.if_linenum = linenum;
     ife.if_mainfile = mainfile;