/** * @file log.c * @author Radek Krejci * @author Michal Vasko * @brief Logger routines implementations * * Copyright (c) 2015 - 2022 CESNET, z.s.p.o. * * This source code is licensed under BSD 3-Clause License (the "License"). * You may not use this file except in compliance with the License. * You may obtain a copy of the License at * * https://opensource.org/licenses/BSD-3-Clause */ #define _GNU_SOURCE /* asprintf, strdup */ #include "log.h" #include #include #include #include #include #include #include #include #include "common.h" #include "compat.h" #include "in_internal.h" #include "plugins_exts.h" #include "set.h" #include "tree_data.h" #include "tree_data_internal.h" #include "tree_schema.h" #include "tree_schema_internal.h" ATOMIC_T ly_ll = (uint_fast32_t)LY_LLWRN; ATOMIC_T ly_log_opts = (uint_fast32_t)(LY_LOLOG | LY_LOSTORE_LAST); THREAD_LOCAL uint32_t *temp_ly_log_opts; static ly_log_clb log_clb; static ATOMIC_T path_flag = 1; #ifndef NDEBUG ATOMIC_T ly_ldbg_groups = 0; #endif THREAD_LOCAL struct ly_log_location_s log_location = {0}; /* how many bytes add when enlarging buffers */ #define LY_BUF_STEP 128 LIBYANG_API_DEF LY_ERR ly_errcode(const struct ly_ctx *ctx) { struct ly_err_item *i; i = ly_err_last(ctx); if (i) { return i->no; } return LY_SUCCESS; } LIBYANG_API_DEF LY_VECODE ly_vecode(const struct ly_ctx *ctx) { struct ly_err_item *i; i = ly_err_last(ctx); if (i) { return i->vecode; } return LYVE_SUCCESS; } LIBYANG_API_DEF const char * ly_errmsg(const struct ly_ctx *ctx) { struct ly_err_item *i; LY_CHECK_ARG_RET(NULL, ctx, NULL); i = ly_err_last(ctx); if (i) { return i->msg; } return NULL; } LIBYANG_API_DEF const char * ly_errpath(const struct ly_ctx *ctx) { struct ly_err_item *i; LY_CHECK_ARG_RET(NULL, ctx, NULL); i = ly_err_last(ctx); if (i) { return i->path; } return NULL; } LIBYANG_API_DEF const char * ly_errapptag(const struct ly_ctx *ctx) { struct ly_err_item *i; LY_CHECK_ARG_RET(NULL, ctx, NULL); i = ly_err_last(ctx); if (i) { return i->apptag; } return NULL; } LIBYANG_API_DEF LY_ERR ly_err_new(struct ly_err_item **err, LY_ERR ecode, LY_VECODE vecode, char *path, char *apptag, const char *err_format, ...) { char *msg = NULL; struct ly_err_item *e; if (!err || (ecode == LY_SUCCESS)) { /* nothing to do */ return ecode; } e = malloc(sizeof *e); LY_CHECK_ERR_RET(!e, LOGMEM(NULL), LY_EMEM); e->prev = (*err) ? (*err)->prev : e; e->next = NULL; if (*err) { (*err)->prev->next = e; } /* fill in the information */ e->level = LY_LLERR; e->no = ecode; e->vecode = vecode; e->path = path; e->apptag = apptag; if (err_format) { va_list print_args; va_start(print_args, err_format); if (vasprintf(&msg, err_format, print_args) == -1) { /* we don't have anything more to do, just set msg to NULL to avoid undefined content, * still keep the information about the original error instead of LY_EMEM or other printf's error */ msg = NULL; } va_end(print_args); } e->msg = msg; if (!(*err)) { *err = e; } return e->no; } LIBYANG_API_DEF struct ly_err_item * ly_err_first(const struct ly_ctx *ctx) { LY_CHECK_ARG_RET(NULL, ctx, NULL); return pthread_getspecific(ctx->errlist_key); } LIBYANG_API_DEF struct ly_err_item * ly_err_last(const struct ly_ctx *ctx) { const struct ly_err_item *e; LY_CHECK_ARG_RET(NULL, ctx, NULL); e = pthread_getspecific(ctx->errlist_key); return e ? e->prev : NULL; } LIBYANG_API_DEF void ly_err_free(void *ptr) { struct ly_err_item *i, *next; /* clean the error list */ for (i = (struct ly_err_item *)ptr; i; i = next) { next = i->next; free(i->msg); free(i->path); free(i->apptag); free(i); } } LIBYANG_API_DEF void ly_err_clean(struct ly_ctx *ctx, struct ly_err_item *eitem) { struct ly_err_item *i, *first; first = ly_err_first(ctx); if (first == eitem) { eitem = NULL; } if (eitem) { /* disconnect the error */ for (i = first; i && (i->next != eitem); i = i->next) {} assert(i); i->next = NULL; first->prev = i; /* free this err and newer */ ly_err_free(eitem); } else { /* free all err */ ly_err_free(first); pthread_setspecific(ctx->errlist_key, NULL); } } LIBYANG_API_DEF LY_LOG_LEVEL ly_log_level(LY_LOG_LEVEL level) { LY_LOG_LEVEL prev = ATOMIC_LOAD_RELAXED(ly_ll); ATOMIC_STORE_RELAXED(ly_ll, level); return prev; } LIBYANG_API_DEF uint32_t ly_log_options(uint32_t opts) { uint32_t prev = ATOMIC_LOAD_RELAXED(ly_log_opts); ATOMIC_STORE_RELAXED(ly_log_opts, opts); return prev; } LIBYANG_API_DEF void ly_temp_log_options(uint32_t *opts) { temp_ly_log_opts = opts; } LIBYANG_API_DEF uint32_t ly_log_dbg_groups(uint32_t dbg_groups) { #ifndef NDEBUG uint32_t prev = ATOMIC_LOAD_RELAXED(ly_ldbg_groups); ATOMIC_STORE_RELAXED(ly_ldbg_groups, dbg_groups); return prev; #else (void)dbg_groups; return 0; #endif } LIBYANG_API_DEF void ly_set_log_clb(ly_log_clb clb, ly_bool path) { log_clb = clb; ATOMIC_STORE_RELAXED(path_flag, path); } LIBYANG_API_DEF ly_log_clb ly_get_log_clb(void) { return log_clb; } void ly_log_location(const struct lysc_node *scnode, const struct lyd_node *dnode, const char *path, const struct ly_in *in, uint64_t line) { if (scnode) { ly_set_add(&log_location.scnodes, (void *)scnode, 1, NULL); } if (dnode) { ly_set_add(&log_location.dnodes, (void *)dnode, 1, NULL); } if (path) { char *s = strdup(path); LY_CHECK_ERR_RET(!s, LOGMEM(NULL), ); ly_set_add(&log_location.paths, s, 1, NULL); } if (in) { ly_set_add(&log_location.inputs, (void *)in, 1, NULL); } if (line) { log_location.line = line; } } void ly_log_location_revert(uint32_t scnode_steps, uint32_t dnode_steps, uint32_t path_steps, uint32_t in_steps) { for (uint32_t i = scnode_steps; i && log_location.scnodes.count; i--) { log_location.scnodes.count--; } for (uint32_t i = dnode_steps; i && log_location.dnodes.count; i--) { log_location.dnodes.count--; } for (uint32_t i = path_steps; i && log_location.paths.count; i--) { ly_set_rm_index(&log_location.paths, log_location.paths.count - 1, free); } for (uint32_t i = in_steps; i && log_location.inputs.count; i--) { log_location.inputs.count--; } /* deallocate the empty sets */ if (scnode_steps && !log_location.scnodes.count) { ly_set_erase(&log_location.scnodes, NULL); } if (dnode_steps && !log_location.dnodes.count) { ly_set_erase(&log_location.dnodes, NULL); } if (path_steps && !log_location.paths.count) { ly_set_erase(&log_location.paths, free); } if (in_steps && !log_location.inputs.count) { ly_set_erase(&log_location.inputs, NULL); } } static LY_ERR log_store(const struct ly_ctx *ctx, LY_LOG_LEVEL level, LY_ERR no, LY_VECODE vecode, char *msg, char *path, char *apptag) { struct ly_err_item *eitem, *last; assert(ctx && (level < LY_LLVRB)); eitem = pthread_getspecific(ctx->errlist_key); if (!eitem) { /* if we are only to fill in path, there must have been an error stored */ assert(msg); eitem = malloc(sizeof *eitem); LY_CHECK_GOTO(!eitem, mem_fail); eitem->prev = eitem; eitem->next = NULL; pthread_setspecific(ctx->errlist_key, eitem); } else if (!msg) { /* only filling the path */ assert(path); /* find last error */ eitem = eitem->prev; do { if (eitem->level == LY_LLERR) { /* fill the path */ free(eitem->path); eitem->path = path; return LY_SUCCESS; } eitem = eitem->prev; } while (eitem->prev->next); /* last error was not found */ assert(0); } else if ((temp_ly_log_opts && ((*temp_ly_log_opts & LY_LOSTORE_LAST) == LY_LOSTORE_LAST)) || (!temp_ly_log_opts && ((ATOMIC_LOAD_RELAXED(ly_log_opts) & LY_LOSTORE_LAST) == LY_LOSTORE_LAST))) { /* overwrite last message */ free(eitem->msg); free(eitem->path); free(eitem->apptag); } else { /* store new message */ last = eitem->prev; eitem->prev = malloc(sizeof *eitem); LY_CHECK_GOTO(!eitem->prev, mem_fail); eitem = eitem->prev; eitem->prev = last; eitem->next = NULL; last->next = eitem; } /* fill in the information */ eitem->level = level; eitem->no = no; eitem->vecode = vecode; eitem->msg = msg; eitem->path = path; eitem->apptag = apptag; return LY_SUCCESS; mem_fail: LOGMEM(NULL); free(msg); free(path); free(apptag); return LY_EMEM; } static void log_vprintf(const struct ly_ctx *ctx, LY_LOG_LEVEL level, LY_ERR no, LY_VECODE vecode, char *path, const char *apptag, const char *format, va_list args) { char *msg = NULL; ly_bool free_strs, lolog, lostore; /* learn effective logger options */ if (temp_ly_log_opts) { lolog = *temp_ly_log_opts & LY_LOLOG; lostore = *temp_ly_log_opts & LY_LOSTORE; } else { lolog = ATOMIC_LOAD_RELAXED(ly_log_opts) & LY_LOLOG; lostore = ATOMIC_LOAD_RELAXED(ly_log_opts) & LY_LOSTORE; } if (level > ATOMIC_LOAD_RELAXED(ly_ll)) { /* do not print or store the message */ free(path); return; } if (no == LY_EMEM) { /* just print it, anything else would most likely fail anyway */ if (lolog) { if (log_clb) { log_clb(level, LY_EMEM_MSG, path); } else { fprintf(stderr, "libyang[%d]: ", level); vfprintf(stderr, format, args); if (path) { fprintf(stderr, " (path: %s)\n", path); } else { fprintf(stderr, "\n"); } } } free(path); return; } /* store the error/warning (if we need to store errors internally, it does not matter what are the user log options) */ if ((level < LY_LLVRB) && ctx && lostore) { assert(format); if (vasprintf(&msg, format, args) == -1) { LOGMEM(ctx); free(path); return; } if (((no & ~LY_EPLUGIN) == LY_EVALID) && (vecode == LYVE_SUCCESS)) { /* assume we are inheriting the error, so inherit vecode as well */ vecode = ly_vecode(ctx); } if (log_store(ctx, level, no, vecode, msg, path, apptag ? strdup(apptag) : NULL)) { return; } free_strs = 0; } else { if (vasprintf(&msg, format, args) == -1) { LOGMEM(ctx); free(path); return; } free_strs = 1; } /* if we are only storing errors internally, never print the message (yet) */ if (lolog) { if (log_clb) { log_clb(level, msg, path); } else { fprintf(stderr, "libyang[%d]: %s%s", level, msg, path ? " " : "\n"); if (path) { fprintf(stderr, "(path: %s)\n", path); } } } if (free_strs) { free(path); free(msg); } } #ifndef NDEBUG void ly_log_dbg(uint32_t group, const char *format, ...) { char *dbg_format; const char *str_group; va_list ap; if (!(ATOMIC_LOAD_RELAXED(ly_ldbg_groups) & group)) { return; } switch (group) { case LY_LDGDICT: str_group = "DICT"; break; case LY_LDGXPATH: str_group = "XPATH"; break; case LY_LDGDEPSETS: str_group = "DEPSETS"; break; default: LOGINT(NULL); return; } if (asprintf(&dbg_format, "%s: %s", str_group, format) == -1) { LOGMEM(NULL); return; } va_start(ap, format); log_vprintf(NULL, LY_LLDBG, 0, 0, NULL, NULL, dbg_format, ap); va_end(ap); } #endif void ly_log(const struct ly_ctx *ctx, LY_LOG_LEVEL level, LY_ERR no, const char *format, ...) { va_list ap; va_start(ap, format); log_vprintf(ctx, level, no, 0, NULL, NULL, format, ap); va_end(ap); } /** * @brief Append a schema node name to a generated data path, only if it fits. * * @param[in,out] str Generated path to update. * @param[in] snode Schema node to append. * @param[in] parent Last printed data node. * @return LY_ERR value. */ static LY_ERR ly_vlog_build_path_append(char **str, const struct lysc_node *snode, const struct lyd_node *parent) { const struct lys_module *mod, *prev_mod; uint32_t len, new_len; void *mem; if (snode->nodetype & (LYS_CHOICE | LYS_CASE)) { /* schema-only node */ return LY_SUCCESS; } else if (lysc_data_parent(snode) != parent->schema) { /* not a direct descendant node */ return LY_SUCCESS; } /* get module to print, if any */ mod = snode->module; prev_mod = (parent->schema) ? parent->schema->module : lyd_owner_module(parent); if (prev_mod == mod) { mod = NULL; } /* realloc string */ len = strlen(*str); new_len = len + 1 + (mod ? strlen(mod->name) + 1 : 0) + strlen(snode->name); mem = realloc(*str, new_len + 1); LY_CHECK_ERR_RET(!mem, LOGMEM(LYD_CTX(parent)), LY_EMEM); *str = mem; /* print the last schema node */ sprintf(*str + len, "/%s%s%s", mod ? mod->name : "", mod ? ":" : "", snode->name); return LY_SUCCESS; } /** * @brief Build log path from the stored log location information. * * @param[in] ctx Context to use. * @param[out] path Generated log path. * @return LY_ERR value. */ static LY_ERR ly_vlog_build_path(const struct ly_ctx *ctx, char **path) { int r; char *str = NULL, *prev = NULL; const struct lyd_node *dnode; *path = NULL; if (log_location.paths.count && ((const char *)(log_location.paths.objs[log_location.paths.count - 1]))[0]) { /* simply get what is in the provided path string */ *path = strdup((const char *)log_location.paths.objs[log_location.paths.count - 1]); LY_CHECK_ERR_RET(!(*path), LOGMEM(ctx), LY_EMEM); } else { /* data/schema node */ if (log_location.dnodes.count) { dnode = log_location.dnodes.objs[log_location.dnodes.count - 1]; if (dnode->parent || !lysc_data_parent(dnode->schema)) { /* data node with all of its parents */ str = lyd_path(log_location.dnodes.objs[log_location.dnodes.count - 1], LYD_PATH_STD, NULL, 0); LY_CHECK_ERR_RET(!str, LOGMEM(ctx), LY_EMEM); } else { /* data parsers put all the parent nodes in the set, but they are not connected */ str = lyd_path_set(&log_location.dnodes, LYD_PATH_STD); LY_CHECK_ERR_RET(!str, LOGMEM(ctx), LY_EMEM); } /* sometimes the last node is not created yet and we only have the schema node */ if (log_location.scnodes.count) { ly_vlog_build_path_append(&str, log_location.scnodes.objs[log_location.scnodes.count - 1], dnode); } r = asprintf(path, "Data location \"%s\"", str); free(str); LY_CHECK_ERR_RET(r == -1, LOGMEM(ctx), LY_EMEM); } else if (log_location.scnodes.count) { str = lysc_path(log_location.scnodes.objs[log_location.scnodes.count - 1], LYSC_PATH_LOG, NULL, 0); LY_CHECK_ERR_RET(!str, LOGMEM(ctx), LY_EMEM); r = asprintf(path, "Schema location \"%s\"", str); free(str); LY_CHECK_ERR_RET(r == -1, LOGMEM(ctx), LY_EMEM); } /* line */ prev = *path; if (log_location.line) { r = asprintf(path, "%s%sine number %" PRIu64, prev ? prev : "", prev ? ", l" : "L", log_location.line); free(prev); LY_CHECK_ERR_RET(r == -1, LOGMEM(ctx), LY_EMEM); log_location.line = 0; } else if (log_location.inputs.count) { r = asprintf(path, "%s%sine number %" PRIu64, prev ? prev : "", prev ? ", l" : "L", ((struct ly_in *)log_location.inputs.objs[log_location.inputs.count - 1])->line); free(prev); LY_CHECK_ERR_RET(r == -1, LOGMEM(ctx), LY_EMEM); } if (*path) { prev = *path; r = asprintf(path, "%s.", prev); free(prev); LY_CHECK_ERR_RET(r == -1, LOGMEM(ctx), LY_EMEM); } } return LY_SUCCESS; } void ly_vlog(const struct ly_ctx *ctx, const char *apptag, LY_VECODE code, const char *format, ...) { va_list ap; char *path = NULL; if (ATOMIC_LOAD_RELAXED(path_flag) && ctx) { ly_vlog_build_path(ctx, &path); } va_start(ap, format); log_vprintf(ctx, LY_LLERR, LY_EVALID, code, path, apptag, format, ap); /* path is spent and should not be freed! */ va_end(ap); } /** * @brief Print a log message from an extension plugin callback. * * @param[in] ctx libyang context to store the error record. If not provided, the error is just printed. * @param[in] plugin_name Name of the plugin generating the message. * @param[in] level Log message level (error, warning, etc.) * @param[in] err_no Error type code. * @param[in] path Optional path of the error. * @param[in] format Format string to print. * @param[in] ap Var arg list for @p format. */ static void ly_ext_log(const struct ly_ctx *ctx, const char *plugin_name, LY_LOG_LEVEL level, LY_ERR err_no, const char *path, const char *format, va_list ap) { char *plugin_msg; if (ATOMIC_LOAD_RELAXED(ly_ll) < level) { return; } if (asprintf(&plugin_msg, "Ext plugin \"%s\": %s", plugin_name, format) == -1) { LOGMEM(ctx); return; } log_vprintf(ctx, level, (level == LY_LLERR ? LY_EPLUGIN : 0) | err_no, LYVE_OTHER, path ? strdup(path) : NULL, NULL, plugin_msg, ap); free(plugin_msg); } LIBYANG_API_DEF void lyplg_ext_parse_log(const struct lysp_ctx *pctx, const struct lysp_ext_instance *ext, LY_LOG_LEVEL level, LY_ERR err_no, const char *format, ...) { va_list ap; char *path = NULL; if (ATOMIC_LOAD_RELAXED(path_flag)) { ly_vlog_build_path(PARSER_CTX(pctx), &path); } va_start(ap, format); ly_ext_log(PARSER_CTX(pctx), ext->record->plugin.id, level, err_no, path, format, ap); va_end(ap); free(path); } LIBYANG_API_DEF void lyplg_ext_compile_log(const struct lysc_ctx *cctx, const struct lysc_ext_instance *ext, LY_LOG_LEVEL level, LY_ERR err_no, const char *format, ...) { va_list ap; va_start(ap, format); ly_ext_log(ext->module->ctx, ext->def->plugin->id, level, err_no, cctx ? cctx->path : NULL, format, ap); va_end(ap); } LIBYANG_API_DEF void lyplg_ext_compile_log_path(const char *path, const struct lysc_ext_instance *ext, LY_LOG_LEVEL level, LY_ERR err_no, const char *format, ...) { va_list ap; va_start(ap, format); ly_ext_log(ext->module->ctx, ext->def->plugin->id, level, err_no, path, format, ap); va_end(ap); } /** * @brief Exact same functionality as ::ly_err_print() but has variable arguments so log_vprintf() can be called. */ static void _ly_err_print(const struct ly_ctx *ctx, struct ly_err_item *eitem, const char *format, ...) { va_list ap; char *path_dup = NULL; LY_CHECK_ARG_RET(ctx, eitem, ); if (eitem->path) { /* duplicate path because it will be freed */ path_dup = strdup(eitem->path); LY_CHECK_ERR_RET(!path_dup, LOGMEM(ctx), ); } va_start(ap, format); log_vprintf(ctx, eitem->level, eitem->no, eitem->vecode, path_dup, eitem->apptag, format, ap); va_end(ap); } LIBYANG_API_DEF void ly_err_print(const struct ly_ctx *ctx, struct ly_err_item *eitem) { /* String ::ly_err_item.msg cannot be used directly because it may contain the % character */ _ly_err_print(ctx, eitem, "%s", eitem->msg); }