diff --git a/doc/ChangeLog.md b/doc/ChangeLog.md index 543556c67..66654f51d 100644 --- a/doc/ChangeLog.md +++ b/doc/ChangeLog.md @@ -19,6 +19,12 @@ All notable changes to the project are documented in this file. ### Added +- Add a `log` RPC to `infix-syslog`, and a matching admin-exec `log` + command in the CLI, for injecting messages in the system log over + NETCONF/RESTCONF, issue #1639. The full RFC 5424 header is supported: + severity, facility, app-name, msgid, and structured data. Messages + are time stamped on arrival and follow the configured syslog filtering + and forwarding rules, like any locally generated message - Add `/system/advanced` for low-level system customization, issue #463: - `rc.d`: user scripts stored in the configuration, run once at boot after the startup configuration has been applied, in the order listed diff --git a/doc/syslog.md b/doc/syslog.md index ead621bd5..d0715ee2b 100644 --- a/doc/syslog.md +++ b/doc/syslog.md @@ -138,6 +138,64 @@ admin@example:/config/syslog/…/file:foobar/> leave admin@example:/> +## Logging Messages + +Scripts and test systems can add their own messages to the system log, +e.g., to mark the start and end of a test run. Messages are handed to +the local syslog daemon as if generated on the device: they are time +stamped on arrival and follow the same filtering and forwarding rules +as any other message. So where a message ends up, a log file, a remote +server, or both, is decided by the syslog configuration, not the +caller. + +From the CLI, the admin-exec `log` command takes the message text, with +optional `severity`, `facility`, and `msgid` keywords before it: + +
admin@example:/> log Kilroy was here
+admin@example:/> log severity warning facility daemon msgid test-start Test 42 starting
+admin@example:/> show log tail 2
+Sep 15 15:29:01 example admin: Kilroy was here
+Sep 15 15:29:07 example admin: Test 42 starting
+
+ +Over NETCONF and RESTCONF the same operation is available as the +`infix-syslog:log` RPC, which also exposes RFC 5424 structured data: + +```bash +~$ curl -k -u admin:admin -X POST \ + -H "Content-Type: application/yang-data+json" \ + https://example.local/restconf/operations/infix-syslog:log \ + -d '{"infix-syslog:input": { + "message": "Test 42 starting", + "severity": "warning", + "facility": "ietf-syslog:daemon", + "app-name": "infamy", + "msgid": "test-start", + "structured-data": [{ + "id": "test@32473", + "param": [{"name": "name", "value": "syslog/rpc_log"}] + }] + }}' +``` + +| **Field** | **Default** | **Description** | +|-------------------|--------------|--------------------------------------------------------------| +| `message` | *mandatory* | Free-form message text | +| `severity` | `notice` | Same levels as in the facility filters, `emergency`..`debug` | +| `facility` | `user` | Any facility from the table at the end of this document | +| `app-name` | calling user | RFC 5424 APP-NAME, shown as the tag in log files | +| `msgid` | none | RFC 5424 MSGID, e.g., `test-start` | +| `structured-data` | none | RFC 5424 SD elements, each an `id` with `name`/`value` params | + +In an [RFC5424][] formatted log file the message above is logged as: + +``` +2026-09-15T15:29:07.123456+02:00 example infamy - test-start [test@32473 name="syslog/rpc_log"] Test 42 starting +``` + +The `msgid` property filter, see [Property-Based Filtering](#property-based-filtering), +can be used to route such messages to a dedicated log file. + ## Log to Remote Server Logging to a remote syslog server is the recommended way of supervising diff --git a/package/confd/confd.mk b/package/confd/confd.mk index 53d2eed89..5fd3fc006 100644 --- a/package/confd/confd.mk +++ b/package/confd/confd.mk @@ -10,7 +10,7 @@ CONFD_SITE = $(BR2_EXTERNAL_INFIX_PATH)/src/confd CONFD_LICENSE = BSD-3-Clause CONFD_LICENSE_FILES = LICENSE CONFD_REDISTRIBUTE = NO -CONFD_DEPENDENCIES = host-sysrepo sysrepo rousette netopeer2 jansson libite sysrepo libsrx libglib2 libev +CONFD_DEPENDENCIES = host-sysrepo sysrepo rousette netopeer2 jansson libite sysrepo libsrx libglib2 libev sysklogd CONFD_AUTORECONF = YES CONFD_CONF_OPTS += --disable-silent-rules --with-crypt=$(BR2_PACKAGE_CONFD_DEFAULT_CRYPT) CONFD_SYSREPO_SHM_PREFIX = sr_buildroot$(subst /,_,$(CONFIG_DIR))_confd diff --git a/src/bin/copy.c b/src/bin/copy.c index 2fcc8584a..177b04071 100644 --- a/src/bin/copy.c +++ b/src/bin/copy.c @@ -12,6 +12,7 @@ #include #include +#include #include #include #include @@ -341,6 +342,9 @@ static int sysrepo_init(sr_conn_ctx_t **conn, sr_session_ctx_t **sess, goto fail; } + /* Like klish-plugin-sysrepo, lets RPC callbacks see who called */ + sr_session_set_orig_name(*sess, user); + return SR_ERR_OK; fail: sysrepo_print_error(*sess); @@ -859,7 +863,7 @@ static int usage_rpc(int rc) "Arguments:\n" " rpc-xpath RPC XPath (e.g., /ietf-system:set-current-datetime)\n" " key value Pairs of RPC argument names and values\n" - " Values can be comma-separated for lists/leaf-lists\n" + " Leaf-list values can be comma-separated\n" "\n" "Examples:\n" " %s /ietf-system:set-current-datetime current-datetime \"2025-01-01T00:00:00Z\"\n" @@ -870,6 +874,22 @@ static int usage_rpc(int rc) return rc; } +static bool is_leaflist(sr_conn_ctx_t *conn, const char *rpc_xpath, const char *key) +{ + char xpath[strlen(rpc_xpath) + strlen(key) + 2]; + const struct lysc_node *node; + const struct ly_ctx *ctx; + bool rc; + + snprintf(xpath, sizeof(xpath), "%s/%s", rpc_xpath, key); + ctx = sr_acquire_context(conn); + node = lys_find_path(ctx, NULL, xpath, 0); + rc = node && node->nodetype == LYS_LEAFLIST; + sr_release_context(conn); + + return rc; +} + /* Execute RPC from CLI arguments: xpath and key-value pairs */ static int rpc_exec(const char *rpc_xpath, int argc, char *argv[]) { @@ -892,8 +912,8 @@ static int rpc_exec(const char *rpc_xpath, int argc, char *argv[]) const char *val = argv[i + 1]; char *val_copy, *token, *saveptr; - /* Check if value contains commas - split into multiple values */ - if (strchr(val, ',')) { + /* Comma-separated values are only a list for leaf-lists */ + if (strchr(val, ',') && is_leaflist(conn, rpc_xpath, key)) { val_copy = strdup(val); if (!val_copy) { warnx("Memory allocation failed"); diff --git a/src/confd/configure.ac b/src/confd/configure.ac index 7747ea530..4930b00b4 100644 --- a/src/confd/configure.ac +++ b/src/confd/configure.ac @@ -110,6 +110,7 @@ PKG_CHECK_MODULES([libite], [libite >= 2.6.1]) PKG_CHECK_MODULES([sysrepo], [sysrepo >= 4.2.10]) PKG_CHECK_MODULES([libyang], [libyang >= 4.2.2]) PKG_CHECK_MODULES([libsrx], [libsrx >= 1.0.0]) +PKG_CHECK_MODULES([libsyslog], [libsyslog >= 2.7.0]) PKG_CHECK_MODULES([libcrypto], [libcrypto]) AC_CHECK_HEADER([ev.h], diff --git a/src/confd/src/Makefile.am b/src/confd/src/Makefile.am index 7e9a8b74f..d656c0c86 100644 --- a/src/confd/src/Makefile.am +++ b/src/confd/src/Makefile.am @@ -20,6 +20,7 @@ confd_plugin_la_CFLAGS = \ $(libcrypto_CFLAGS) \ $(sysrepo_CFLAGS) \ $(libsrx_CFLAGS) \ + $(libsyslog_CFLAGS) \ $(CFLAGS) confd_plugin_la_LIBADD = \ @@ -29,7 +30,8 @@ confd_plugin_la_LIBADD = \ $(libite_LIBS) \ $(libcrypto_LIBS) \ $(sysrepo_LIBS) \ - $(libsrx_LIBS) + $(libsrx_LIBS) \ + $(libsyslog_LIBS) confd_plugin_la_SOURCES = \ base64.c base64.h \ diff --git a/src/confd/src/core.c b/src/confd/src/core.c index 99fd04c14..adbf84ae1 100644 --- a/src/confd/src/core.c +++ b/src/confd/src/core.c @@ -900,6 +900,10 @@ int sr_plugin_init_cb(sr_session_ctx_t *session, void **priv) if (rc) goto err; + rc = syslog_rpc_init(&confd); + if (rc) + goto err; + /* Candidate infer configurations */ rc = interfaces_cand_init(&confd); if (rc) diff --git a/src/confd/src/core.h b/src/confd/src/core.h index 38c80873e..057a8d796 100644 --- a/src/confd/src/core.h +++ b/src/confd/src/core.h @@ -133,6 +133,10 @@ typedef enum { if ((rc = register_rpc(s, x, c, a, u))) \ goto fail +#define REGISTER_RPC_TREE(s,x,c,a,u) \ + if ((rc = register_rpc_tree(s, x, c, a, u))) \ + goto fail + struct confd { sr_session_ctx_t *session; /* running datastore */ sr_session_ctx_t *startup; /* startup datastore */ @@ -192,6 +196,15 @@ static inline int register_rpc(sr_session_ctx_t *session, const char *xpath, return rc; } +static inline int register_rpc_tree(sr_session_ctx_t *session, const char *xpath, + sr_rpc_tree_cb cb, void *arg, sr_subscription_ctx_t **sub) +{ + int rc = sr_rpc_subscribe_tree(session, xpath, cb, arg, 0, SR_SUBSCR_NO_THREAD, sub); + if (rc) + ERROR("failed subscribing to %s rpc: %s", xpath, sr_strerror(rc)); + return rc; +} + /* core.c */ int finit_enable(const char *svc); @@ -211,6 +224,7 @@ int interfaces_cand_init(struct confd *confd); /* syslog.c */ int syslog_change(sr_session_ctx_t *session, struct lyd_node *config, struct lyd_node *diff, sr_event_t event, struct confd *confd); +int syslog_rpc_init(struct confd *confd); /* system.c */ int system_rpc_init (struct confd *confd); diff --git a/src/confd/src/syslog.c b/src/confd/src/syslog.c index 8f621dce3..a9f3201c3 100644 --- a/src/confd/src/syslog.c +++ b/src/confd/src/syslog.c @@ -6,6 +6,8 @@ #include "core.h" +#include /* sysklogd syslogp_r() API */ + #define XPATH_BASE_ "/ietf-syslog:syslog" #define XPATH_FILE_ XPATH_BASE_"/actions/file" #define XPATH_LOG_FILE XPATH_BASE_"/actions/file/log-file" @@ -478,3 +480,192 @@ int syslog_change(sr_session_ctx_t *session, struct lyd_node *config, struct lyd return SR_ERR_OK; } + +/* + * RPC: /infix-syslog:log + */ + +static int log_facility(const char *name) +{ + static const struct { + const char *name; + int facility; + } map[] = { + { "kern", LOG_KERN }, + { "user", LOG_USER }, + { "mail", LOG_MAIL }, + { "daemon", LOG_DAEMON }, + { "auth", LOG_AUTH }, + { "syslog", LOG_SYSLOG }, + { "lpr", LOG_LPR }, + { "news", LOG_NEWS }, + { "uucp", LOG_UUCP }, + { "cron", LOG_CRON }, + { "authpriv", LOG_AUTHPRIV }, + { "ftp", LOG_FTP }, + { "ntp", LOG_NTP }, + { "audit", LOG_AUDIT }, + { "console", LOG_CONSOLE }, + { "cron2", LOG_CRON2 }, + { "local0", LOG_LOCAL0 }, + { "local1", LOG_LOCAL1 }, + { "local2", LOG_LOCAL2 }, + { "local3", LOG_LOCAL3 }, + { "local4", LOG_LOCAL4 }, + { "local5", LOG_LOCAL5 }, + { "local6", LOG_LOCAL6 }, + { "local7", LOG_LOCAL7 }, + /* infix-syslog local facilities */ + { "rauc", LOG_LOCAL0 }, + { "container", LOG_LOCAL1 }, + { "web", LOG_LOCAL7 }, + }; + const char *ptr; + + if (!name) + return LOG_USER; + + /* identityref, strip module prefix */ + ptr = strchr(name, ':'); + if (ptr) + name = ptr + 1; + + for (size_t i = 0; i < NELEMS(map); i++) { + if (!strcmp(map[i].name, name)) + return map[i].facility; + } + + return LOG_USER; +} + +static int log_severity(const char *name) +{ + static const char *map[] = { + "emergency", "alert", "critical", "error", + "warning", "notice", "info", "debug", + }; + + if (!name) + return LOG_NOTICE; + + for (size_t i = 0; i < NELEMS(map); i++) { + if (!strcmp(map[i], name)) + return (int)i; + } + + return LOG_NOTICE; +} + +/* + * The event session runs as confd, the calling user is only known from + * the originator: netopeer2 pushes [nc-sid, username], the CLI and the + * rpc tool set their originator name to the user. + */ +static const char *log_user(sr_session_ctx_t *session) +{ + const char *orig = sr_session_get_orig_name(session); + const void *data; + uint32_t size; + + if (orig && !strcmp(orig, "netopeer2")) { + if (!sr_session_get_orig_data(session, 1, &size, &data) && size > 1) + return data; + } + + if (orig && orig[0]) + return orig; + + return sr_session_get_user(session); +} + +/* RFC 5424 PARAM-VALUE: escape '"', '\\', and ']' */ +static char *sd_escape(char *ptr, const char *value) +{ + for (; *value; value++) { + if (*value == '"' || *value == '\\' || *value == ']') + *ptr++ = '\\'; + *ptr++ = *value; + } + + return ptr; +} + +/* Render structured-data list as [id name="value" ...][id2 ...] */ +static char *sd_build(const struct lyd_node *input) +{ + struct lyd_node *elem, *param; + char *sd, *ptr; + size_t len = 1; + + LYX_LIST_FOR_EACH(lyd_child(input), elem, "structured-data") { + len += strlen(lydx_get_cattr(elem, "id")) + 2; + LYX_LIST_FOR_EACH(lyd_child(elem), param, "param") { + len += strlen(lydx_get_cattr(param, "name")) + 4; + len += strlen(lydx_get_cattr(param, "value")) * 2; + } + } + + if (len == 1) + return NULL; + + sd = ptr = malloc(len); + if (!sd) + return NULL; + + LYX_LIST_FOR_EACH(lyd_child(input), elem, "structured-data") { + ptr += sprintf(ptr, "[%s", lydx_get_cattr(elem, "id")); + LYX_LIST_FOR_EACH(lyd_child(elem), param, "param") { + ptr += sprintf(ptr, " %s=\"", lydx_get_cattr(param, "name")); + ptr = sd_escape(ptr, lydx_get_cattr(param, "value")); + *ptr++ = '"'; + } + *ptr++ = ']'; + } + *ptr = 0; + + return sd; +} + +static int rpc_log(sr_session_ctx_t *session, uint32_t sub_id, const char *op_path, + const struct lyd_node *input, sr_event_t event, uint32_t request_id, + struct lyd_node *output, void *priv) +{ + struct syslog_data log = SYSLOG_DATA_INIT; + struct lyd_node *in = (struct lyd_node *)input; + const char *msg, *tag, *msgid; + char *sd; + int pri; + + msg = lydx_get_cattr(in, "message"); + if (!msg) + return SR_ERR_INVAL_ARG; + + pri = log_facility(lydx_get_cattr(in, "facility")) | log_severity(lydx_get_cattr(in, "severity")); + msgid = lydx_get_cattr(in, "msgid"); + tag = lydx_get_cattr(in, "app-name"); + if (!tag) + tag = log_user(session); + + log.log_tag = tag; + sd = sd_build(in); + if (sd) + syslogp_r(pri, &log, msgid, "%s", "%s", sd, msg); + else + syslogp_r(pri, &log, msgid, NULL, "%s", msg); + closelog_r(&log); + free(sd); + + return SR_ERR_OK; +} + +int syslog_rpc_init(struct confd *confd) +{ + int rc; + + REGISTER_RPC_TREE(confd->session, "/infix-syslog:log", rpc_log, NULL, &confd->sub); + + return SR_ERR_OK; +fail: + ERROR("init failed: %s", sr_strerror(rc)); + return rc; +} diff --git a/src/confd/yang/confd.inc b/src/confd/yang/confd.inc index 62ba37b9d..ff12f884d 100644 --- a/src/confd/yang/confd.inc +++ b/src/confd/yang/confd.inc @@ -24,7 +24,7 @@ MODULES=( # NOTE: ietf-tls-client must be version matched with ietf-tls-server, used by netopeer2! # "ietf-tls-client@2023-12-28.yang" "ietf-syslog@2024-03-21.yang -e file-action -e file-limit-size -e remote-action -e select-adv-compare -e select-match" - "infix-syslog@2025-11-17.yang" + "infix-syslog@2026-09-15.yang" "iana-hardware@2018-03-13.yang" "ietf-hardware@2018-03-13.yang -e hardware-state -e hardware-sensor" "infix-hardware@2026-07-02.yang" diff --git a/src/confd/yang/confd/infix-syslog.yang b/src/confd/yang/confd/infix-syslog.yang index 981f498d8..394b94146 100644 --- a/src/confd/yang/confd/infix-syslog.yang +++ b/src/confd/yang/confd/infix-syslog.yang @@ -16,6 +16,11 @@ module infix-syslog { contact "kernelkit@googlegroups.com"; description "Infix augments and deviations to ietf-syslog, draft 32."; + revision 2026-09-15 { + description "Add log RPC for injecting messages in the system log."; + reference "internal"; + } + revision 2025-11-17 { description "Add hostname-filter support."; reference "internal"; @@ -77,6 +82,19 @@ module infix-syslog { description "Latest format, better time granularity, structured data, etc."; } + /* + * Typedefs + */ + + typedef sd-name { + type string { + length "1..32"; + pattern '[!#-<>-\\^-~]+'; + } + description "RFC 5424 SD-NAME: printable US-ASCII, except '=', ']', and '\"'."; + reference "RFC 5424: The Syslog Protocol, Section 6.3.2"; + } + /* * Shared settings */ @@ -285,4 +303,85 @@ module infix-syslog { description "Not yet supported by underlying daemon."; deviate not-supported; } + + /* + * RPCs + */ + + rpc log { + description "Log a message via the local system logger. + + The message is handed to the system log daemon like any + locally generated message, i.e., it is time stamped on + arrival and subject to the same filtering and forwarding + rules as configured in /syslog."; + reference "RFC 5424: The Syslog Protocol"; + + input { + leaf message { + type string { + length "1..2048"; + } + mandatory true; + description "Free-form message text."; + } + + leaf severity { + type syslog:syslog-severity; + default notice; + description "Message severity."; + } + + leaf facility { + type identityref { + base syslog:syslog-facility; + } + default syslog:user; + description "Message facility."; + } + + leaf app-name { + type string { + length "1..48"; + pattern '[!-~]+'; + } + description "Originating application name, or tag, RFC 5424 APP-NAME. + Default: name of the calling user."; + } + + leaf msgid { + type string { + length "1..32"; + pattern '[!-~]+'; + } + description "Message type identifier, RFC 5424 MSGID, e.g., 'test-start'."; + } + + list structured-data { + key "id"; + description "RFC 5424 structured data, rendered as [id name=\"value\" ...]."; + + leaf id { + type sd-name; + description "SD-ID, private identifiers use the form name@enterprise-number."; + } + + list param { + key "name"; + description "SD-PARAM, name and value pair."; + + leaf name { + type sd-name; + description "Parameter name."; + } + + leaf value { + type string; + mandatory true; + description "Parameter value, any '\"', '\\', and ']' are escaped on output."; + } + } + } + } + } } diff --git a/src/confd/yang/confd/infix-syslog@2025-11-17.yang b/src/confd/yang/confd/infix-syslog@2026-09-15.yang similarity index 100% rename from src/confd/yang/confd/infix-syslog@2025-11-17.yang rename to src/confd/yang/confd/infix-syslog@2026-09-15.yang diff --git a/src/klish-plugin-infix/xml/infix.xml b/src/klish-plugin-infix/xml/infix.xml index 60b8f670a..8196192f8 100644 --- a/src/klish-plugin-infix/xml/infix.xml +++ b/src/klish-plugin-infix/xml/infix.xml @@ -227,6 +227,81 @@ + + + + + + emergency + alert + critical + error + warning + notice + info + debug + + + + + + + auth + authpriv + console + cron + daemon + ftp + kern + local0 + local1 + local2 + local3 + local4 + local5 + local6 + local7 + lpr + mail + news + ntp + syslog + user + uucp + + + + + + + + + + set -- /infix-syslog:log + if [ -n "$KLISH_PARAM_severity" ]; then + set -- "$@" severity "$KLISH_PARAM_severity" + fi + if [ -n "$KLISH_PARAM_msgid" ]; then + set -- "$@" msgid "$KLISH_PARAM_msgid" + fi + if [ -n "$KLISH_PARAM_facility" ]; then + case "$KLISH_PARAM_facility" in + rauc|container|web) set -- "$@" facility "infix-syslog:$KLISH_PARAM_facility" ;; + *) set -- "$@" facility "ietf-syslog:$KLISH_PARAM_facility" ;; + esac + fi + msg="" + i=0 + while :; do + eval "word=\${KLISH_PARAM_message_$i}" + [ -n "$word" ] || break + msg="${msg:+$msg }$word" + i=$((i + 1)) + done + rpc "$@" message "$msg" + + + /ietf-system:system-shutdown diff --git a/test/case/services/mdns/mdns_allow_deny/test.py b/test/case/services/mdns/mdns_allow_deny/test.py index 6feea7cbf..5fb6ab986 100755 --- a/test/case/services/mdns/mdns_allow_deny/test.py +++ b/test/case/services/mdns/mdns_allow_deny/test.py @@ -22,7 +22,7 @@ def mdns_scan(): pcap3 = ns3.pcap("host 10.0.3.1 and port 5353") with pcap1, pcap2, pcap3: - ssh.runsh("logger -t scan 'calling avahi-browse ...'") + dut.log("calling avahi-browse ...", app_name="scan") ssh.runsh("avahi-browse -lat") def has_packets(output): diff --git a/test/case/syslog/advanced_compare/test.py b/test/case/syslog/advanced_compare/test.py index c83bbe657..d82584e24 100755 --- a/test/case/syslog/advanced_compare/test.py +++ b/test/case/syslog/advanced_compare/test.py @@ -11,14 +11,14 @@ from infamy.util import parallel, until TEST_MESSAGES = [ - ("daemon.emerg", "Emergency: system is unusable"), - ("daemon.alert", "Alert: immediate action required"), - ("daemon.crit", "Critical: critical condition"), - ("daemon.err", "Error: error condition"), - ("daemon.warning", "Warning: warning condition"), - ("daemon.notice", "Notice: normal but significant"), - ("daemon.info", "Info: informational message"), - ("daemon.debug", "Debug: debug-level message"), + ("emergency", "Emergency: system is unusable"), + ("alert", "Alert: immediate action required"), + ("critical", "Critical: critical condition"), + ("error", "Error: error condition"), + ("warning", "Warning: warning condition"), + ("notice", "Notice: normal but significant"), + ("info", "Info: informational message"), + ("debug", "Debug: debug-level message"), ] with infamy.Test() as test: @@ -76,8 +76,8 @@ until(lambda: tgtssh.runsh("test -f /var/log/exact-errors").returncode == 0, attempts=10) with test.step("Send test messages at all severity levels"): - for priority, message in TEST_MESSAGES: - tgtssh.runsh(f"logger -t advtest -p {priority} '{message}'") + for severity, message in TEST_MESSAGES: + target.log(message, severity=severity, facility="daemon", app_name="advtest") until(lambda: "Error: error condition" in tgtssh.runsh("cat /var/log/exact-errors 2>/dev/null").stdout, attempts=10) with test.step("Verify exact-errors log contains only error messages"): diff --git a/test/case/syslog/all.yaml b/test/case/syslog/all.yaml index 01be9dd42..e6d6853a9 100644 --- a/test/case/syslog/all.yaml +++ b/test/case/syslog/all.yaml @@ -16,3 +16,6 @@ - name: Syslog Property Filtering case: property_filter/test.py + +- name: Syslog Log RPC + case: rpc_log/test.py diff --git a/test/case/syslog/pattern_match/test.py b/test/case/syslog/pattern_match/test.py index daf046a8a..4328788ae 100755 --- a/test/case/syslog/pattern_match/test.py +++ b/test/case/syslog/pattern_match/test.py @@ -66,7 +66,7 @@ with test.step("Send test messages with various patterns"): for message in TEST_MESSAGES: - tgtssh.runsh(f"logger -t test -p daemon.info '{message}'") + target.log(message, severity="info", facility="daemon", app_name="test") time.sleep(2) with test.step("Verify errors log contains ERROR and CRITICAL messages"): diff --git a/test/case/syslog/property_filter/test.py b/test/case/syslog/property_filter/test.py index 7f7d7fd9d..e0c55bff0 100755 --- a/test/case/syslog/property_filter/test.py +++ b/test/case/syslog/property_filter/test.py @@ -94,7 +94,7 @@ with test.step("Send test messages"): for tag, msg in TEST_MESSAGES: - tgtssh.runsh(f"logger -t {tag} -p daemon.info '{msg}'") + target.log(msg, severity="info", facility="daemon", app_name=tag) until(lambda: "Application startup" in tgtssh.runsh("cat /var/log/baseline 2>/dev/null").stdout, attempts=10) with test.step("Verify myapp log contains only myapp messages"): diff --git a/test/case/syslog/rpc_log/Readme.adoc b/test/case/syslog/rpc_log/Readme.adoc new file mode 120000 index 000000000..ae32c8412 --- /dev/null +++ b/test/case/syslog/rpc_log/Readme.adoc @@ -0,0 +1 @@ +test.adoc \ No newline at end of file diff --git a/test/case/syslog/rpc_log/test.adoc b/test/case/syslog/rpc_log/test.adoc new file mode 100644 index 000000000..7f056cb23 --- /dev/null +++ b/test/case/syslog/rpc_log/test.adoc @@ -0,0 +1,27 @@ +=== Syslog Log RPC + +ifdef::topdoc[:imagesdir: {topdoc}../../test/case/syslog/rpc_log] + +==== Description + +Verify the infix-syslog:log RPC, used by the test system to inject +markers in a DUT's system log. A message logged with the full RFC 5424 +header must show up in an RFC 5424 formatted log file with the given +app-name, msgid, and structured data. A message logged with only the +mandatory text must fall back to the documented defaults. + +==== Topology + +image::topology.svg[Syslog Log RPC topology, align=center, scaledwidth=75%] + +==== Sequence + +. Set up topology and attach to target DUT +. Clean up old log file from previous test runs +. Configure an RFC 5424 formatted log file for all facilities +. Log message with severity, facility, app-name, msgid, and structured data +. Verify RFC 5424 header fields of the logged message +. Log message with only the mandatory text +. Verify default app-name is set and msgid and structured data are empty + + diff --git a/test/case/syslog/rpc_log/test.py b/test/case/syslog/rpc_log/test.py new file mode 100755 index 000000000..2026694ab --- /dev/null +++ b/test/case/syslog/rpc_log/test.py @@ -0,0 +1,83 @@ +#!/usr/bin/env python3 +"""Syslog Log RPC + +Verify the infix-syslog:log RPC, used by the test system to inject +markers in a DUT's system log. A message logged with the full RFC 5424 +header must show up in an RFC 5424 formatted log file with the given +app-name, msgid, and structured data. A message logged with only the +mandatory text must fall back to the documented defaults. + +""" + +import re + +import infamy +from infamy.util import parallel, until + +LOG_FILE = "/var/log/rpc-log" + + +def logfile(): + """Return contents of the RFC 5424 test log file, or empty string""" + rc = tgtssh.runsh(f"cat {LOG_FILE} 2>/dev/null") + return rc.stdout if rc.returncode == 0 else "" + + +with infamy.Test() as test: + with test.step("Set up topology and attach to target DUT"): + env = infamy.Env() + target, tgtssh = parallel(lambda: env.attach("target", "mgmt"), + lambda: env.attach("target", "mgmt", "ssh")) + + with test.step("Clean up old log file from previous test runs"): + tgtssh.runsh(f"sudo rm -f {LOG_FILE}") + + with test.step("Configure an RFC 5424 formatted log file for all facilities"): + target.put_config_dicts({ + "ietf-syslog": { + "syslog": { + "actions": { + "file": { + "log-file": [{ + "name": f"file:{LOG_FILE}", + "infix-syslog:log-format": "rfc5424", + "facility-filter": { + "facility-list": [{ + "facility": "all", + "severity": "info" + }] + } + }] + } + } + } + } + }) + until(lambda: tgtssh.runsh(f"test -f {LOG_FILE}").returncode == 0, attempts=10) + + with test.step("Log message with severity, facility, app-name, msgid, and structured data"): + target.log("Kilroy was here", severity="warning", facility="daemon", + app_name="infamy", msgid="test-start", + sd={"test@32473": {"name": "rpc_log", "step": "3"}}) + until(lambda: "Kilroy was here" in logfile(), attempts=10) + + with test.step("Verify RFC 5424 header fields of the logged message"): + line = [ln for ln in logfile().splitlines() if "Kilroy was here" in ln][0] + if not re.search(r"\binfamy - test-start \[test@32473 [^]]*\] Kilroy was here$", line): + test.fail(f"Unexpected app-name, msgid, or structured data: {line}") + for param in ('name="rpc_log"', 'step="3"'): + if param not in line: + test.fail(f"Missing structured data param {param}: {line}") + + with test.step("Log message with only the mandatory text"): + target.log("Plain message, no frills") + until(lambda: "Plain message" in logfile(), attempts=10) + + with test.step("Verify default app-name is set and msgid and structured data are empty"): + line = [ln for ln in logfile().splitlines() if "Plain message" in ln][0] + if not re.search(r" \S+ - - - Plain message, no frills$", line): + test.fail(f"Unexpected header for default message: {line}") + if re.search(r" - - - - Plain message", line): + test.fail(f"Default app-name should not be empty: {line}") + + test.succeed() diff --git a/test/case/syslog/rpc_log/topology.dot b/test/case/syslog/rpc_log/topology.dot new file mode 100644 index 000000000..e6a0d803b --- /dev/null +++ b/test/case/syslog/rpc_log/topology.dot @@ -0,0 +1,23 @@ +graph "1x1" { + layout="neato"; + overlap="false"; + esep="+80"; + + node [shape=record, fontname="DejaVu Sans Mono, Book"]; + edge [color="cornflowerblue", penwidth="2", fontname="DejaVu Serif, Book"]; + + host [ + label="host | { mgmt }", + pos="0,12!", + requires="controller", + ]; + + target [ + label="{ mgmt } | target", + pos="10,12!", + + requires="infix", + ]; + + host:mgmt -- target:mgmt [requires="mgmt", color="lightgray"] +} diff --git a/test/case/syslog/rpc_log/topology.svg b/test/case/syslog/rpc_log/topology.svg new file mode 100644 index 000000000..6fc6f47a8 --- /dev/null +++ b/test/case/syslog/rpc_log/topology.svg @@ -0,0 +1,33 @@ + + + + + + +1x1 + + + +host + +host + +mgmt + + + +target + +mgmt + +target + + + +host:mgmt--target:mgmt + + + + diff --git a/test/infamy/restconf.py b/test/infamy/restconf.py index ad004a8dc..1fe45343b 100644 --- a/test/infamy/restconf.py +++ b/test/infamy/restconf.py @@ -411,8 +411,24 @@ def patch_config(self, xpath, edit, retries=3): raise last_error def call_dict(self, model, call): + """Call RPC, Python dictionary version: {"rpc-name": {input leaves}}""" coverage.track_dict(model, call) - pass # Need implementation + if len(call) != 1: + raise ValueError("call_dict() expects a single RPC: {name: input}") + + (name, data), = call.items() + url = f"{self.rpc_url}/{model}:{name}" + body = {f"{model}:input": data} if data else None + response = requests_workaround_post( + url, + json=body, + headers=self.headers, + auth=self.auth, + verify=False + ) + response.raise_for_status() + + return response.content def call_rpc(self, rpc): """Actually send a POST to RESTCONF server""" diff --git a/test/infamy/transport.py b/test/infamy/transport.py index fec58fd5c..5b89d78fb 100644 --- a/test/infamy/transport.py +++ b/test/infamy/transport.py @@ -107,3 +107,30 @@ def test_reset(self): def startup_override(self): self.call_action("/infix-test:test/override-startup") + + def log(self, message, severity=None, facility=None, app_name=None, + msgid=None, sd=None): + """Log a message on the target, using the infix-syslog:log RPC. + + Defaults to user.notice with app-name set to the calling user. + `facility` is a plain name, e.g. "daemon", the module prefix is + added here. `sd` is RFC 5424 structured data, given as a dict + of dicts: {"sd-id": {"name": "value", ...}}. + """ + rpc = {"message": message} + if severity: + rpc["severity"] = severity + if facility: + module = "infix-syslog" if facility in ("rauc", "container", "web") else "ietf-syslog" + rpc["facility"] = f"{module}:{facility}" + if app_name: + rpc["app-name"] = app_name + if msgid: + rpc["msgid"] = msgid + if sd: + rpc["structured-data"] = [{ + "id": sdid, + "param": [{"name": name, "value": value} for name, value in params.items()] + } for sdid, params in sd.items()] + + return self.call_dict("infix-syslog", {"log": rpc})