logging subsystem rewrite #5451
Conversation
This comment has been minimized.
This comment has been minimized.
This comment has been minimized.
This comment has been minimized.
This comment has been minimized.
This comment has been minimized.
This comment has been minimized.
This comment has been minimized.
|
@louberger need info on failure here. As a guess I'd say you need to remove an |
|
@eqvinox you're right, looking at this now... |
|
entered into the ci rerun queue.... |
This comment has been minimized.
This comment has been minimized.
|
is there a replacement for vzlog_test? |
This comment has been minimized.
This comment has been minimized.
|
looks like there's a leak/unfreed object: ==32594== by 0x27FF8F: qcalloc (memory.c:110) |
No; there is considerably more fine-grained control over logging output coming in follow-up PRs which makes it semantically ill-defined to give a generic answer to "is this log level enabled?" |
This is intentional, please add a valgrind suppression. The builtin memtype leak tracking has [Add:] Do you use |
|
Also, to extend on ( |
There was a problem hiding this comment.
Thanks for your contribution to FRR!
Click for style suggestions
To apply these suggestions:
curl -s https://gist.githubusercontent.com/polychaeta/f4f341c7e15ace38c4f2aaac905a4500/raw/02c4830843e9abf98768a28ec38fb5119364cf1d/cr_5451_1576584679.diff | git apply
diff --git a/lib/command.c b/lib/command.c
index 4cb26c5bb..1164b6f9d 100644
--- a/lib/command.c
+++ b/lib/command.c
@@ -2164,7 +2164,8 @@ DEFUN (config_logmsg,
int level;
char *message;
- if ((level = log_level_match(argv[idx_log_level]->arg)) == ZLOG_DISABLED)
+ if ((level = log_level_match(argv[idx_log_level]->arg))
+ == ZLOG_DISABLED)
return CMD_ERR_NO_MATCH;
zlog(level, "%s",
diff --git a/lib/log.c b/lib/log.c
index 77981b6aa..c2f481aa0 100644
--- a/lib/log.c
+++ b/lib/log.c
@@ -321,8 +321,9 @@ void _zlog_assert_failed(const char *assertion, const char *file,
void memory_oom(size_t size, const char *name)
{
- zlog(LOG_CRIT, "out of memory: failed to allocate %zu bytes for %s object",
- size, name);
+ zlog(LOG_CRIT,
+ "out of memory: failed to allocate %zu bytes for %s object", size,
+ name);
zlog_backtrace(LOG_CRIT);
log_memstats(stderr, "log");
abort();
diff --git a/lib/log_vty.c b/lib/log_vty.c
index 8a7346499..7e0feea02 100644
--- a/lib/log_vty.c
+++ b/lib/log_vty.c
@@ -52,9 +52,10 @@ static struct zlog_cfg_file zt_stdout = {
.prio_min = ZLOG_DISABLED,
};
static struct zlog_cfg_filterfile zt_filterfile = {
- .parent = {
- .prio_min = ZLOG_DISABLED,
- },
+ .parent =
+ {
+ .prio_min = ZLOG_DISABLED,
+ },
};
static const char *zlog_progname;
@@ -146,11 +147,8 @@ void log_show_syslog(struct vty *vty)
zlog_progname);
}
-DEFUN (show_logging,
- show_logging_cmd,
- "show logging",
- SHOW_STR
- "Show current logging configuration\n")
+DEFUN(show_logging, show_logging_cmd, "show logging",
+ SHOW_STR "Show current logging configuration\n")
{
log_show_syslog(vty);
@@ -158,8 +156,7 @@ DEFUN (show_logging,
if (zt_stdout.prio_min == ZLOG_DISABLED)
vty_out(vty, "disabled");
else
- vty_out(vty, "level %s",
- zlog_priority[zt_stdout.prio_min]);
+ vty_out(vty, "level %s", zlog_priority[zt_stdout.prio_min]);
vty_out(vty, "\n");
vty_out(vty, "File logging: ");
@@ -197,12 +194,10 @@ DEFUN (show_logging,
return CMD_SUCCESS;
}
-DEFPY (config_log_stdout,
- config_log_stdout_cmd,
- "log stdout [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>$levelarg]",
- "Logging control\n"
- "Set stdout logging level\n"
- LOG_LEVEL_DESC)
+DEFPY(config_log_stdout, config_log_stdout_cmd,
+ "log stdout [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>$levelarg]",
+ "Logging control\n"
+ "Set stdout logging level\n" LOG_LEVEL_DESC)
{
int level;
@@ -214,45 +209,41 @@ DEFPY (config_log_stdout,
level = log_default_lvl;
log_config_stdout_lvl = level;
- zt_stdout.prio_min = ZLOG_MAXLVL(log_config_stdout_lvl,
- log_cmdline_stdout_lvl);
+ zt_stdout.prio_min =
+ ZLOG_MAXLVL(log_config_stdout_lvl, log_cmdline_stdout_lvl);
zlog_file_set_other(&zt_stdout);
return CMD_SUCCESS;
}
-DEFUN (no_config_log_stdout,
- no_config_log_stdout_cmd,
- "no log stdout [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>]",
- NO_STR
- "Logging control\n"
- "Cancel logging to stdout\n"
- LOG_LEVEL_DESC)
+DEFUN(no_config_log_stdout, no_config_log_stdout_cmd,
+ "no log stdout [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>]",
+ NO_STR
+ "Logging control\n"
+ "Cancel logging to stdout\n" LOG_LEVEL_DESC)
{
log_config_stdout_lvl = ZLOG_DISABLED;
- zt_stdout.prio_min = ZLOG_MAXLVL(log_config_stdout_lvl,
- log_cmdline_stdout_lvl);
+ zt_stdout.prio_min =
+ ZLOG_MAXLVL(log_config_stdout_lvl, log_cmdline_stdout_lvl);
zlog_file_set_other(&zt_stdout);
return CMD_SUCCESS;
}
-DEFUN_HIDDEN (config_log_monitor,
- config_log_monitor_cmd,
- "log monitor [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>]",
- "Logging control\n"
- "Set terminal line (monitor) logging level\n"
- LOG_LEVEL_DESC)
+DEFUN_HIDDEN(
+ config_log_monitor, config_log_monitor_cmd,
+ "log monitor [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>]",
+ "Logging control\n"
+ "Set terminal line (monitor) logging level\n" LOG_LEVEL_DESC)
{
vty_out(vty, "%% \"log monitor\" is deprecated and does nothing.\n");
return CMD_SUCCESS;
}
-DEFUN_HIDDEN (no_config_log_monitor,
- no_config_log_monitor_cmd,
- "no log monitor [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>]",
- NO_STR
- "Logging control\n"
- "Disable terminal line (monitor) logging\n"
- LOG_LEVEL_DESC)
+DEFUN_HIDDEN(
+ no_config_log_monitor, no_config_log_monitor_cmd,
+ "no log monitor [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>]",
+ NO_STR
+ "Logging control\n"
+ "Disable terminal line (monitor) logging\n" LOG_LEVEL_DESC)
{
return CMD_SUCCESS;
}
@@ -342,35 +333,31 @@ void command_setup_early_logging(const char *dest, const char *level)
exit(1);
}
-DEFUN (clear_log_cmdline,
- clear_log_cmdline_cmd,
- "clear log cmdline-targets",
- CLEAR_STR
- "Logging control\n"
- "Disable log targets specified at startup by --log option\n")
+DEFUN(clear_log_cmdline, clear_log_cmdline_cmd, "clear log cmdline-targets",
+ CLEAR_STR
+ "Logging control\n"
+ "Disable log targets specified at startup by --log option\n")
{
zt_file_cmdline.prio_min = ZLOG_DISABLED;
zlog_file_set_other(&zt_file_cmdline);
log_cmdline_syslog_lvl = ZLOG_DISABLED;
- zlog_syslog_set_prio_min(ZLOG_MAXLVL(log_config_syslog_lvl,
- log_cmdline_syslog_lvl));
+ zlog_syslog_set_prio_min(
+ ZLOG_MAXLVL(log_config_syslog_lvl, log_cmdline_syslog_lvl));
log_cmdline_stdout_lvl = ZLOG_DISABLED;
- zt_stdout.prio_min = ZLOG_MAXLVL(log_config_stdout_lvl,
- log_cmdline_stdout_lvl);
+ zt_stdout.prio_min =
+ ZLOG_MAXLVL(log_config_stdout_lvl, log_cmdline_stdout_lvl);
zlog_file_set_other(&zt_stdout);
return CMD_SUCCESS;
}
-DEFPY (config_log_file,
- config_log_file_cmd,
- "log file FILENAME [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>$levelarg]",
- "Logging control\n"
- "Logging to file\n"
- "Logging filename\n"
- LOG_LEVEL_DESC)
+DEFPY(config_log_file, config_log_file_cmd,
+ "log file FILENAME [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>$levelarg]",
+ "Logging control\n"
+ "Logging to file\n"
+ "Logging filename\n" LOG_LEVEL_DESC)
{
int level = log_default_lvl;
@@ -382,26 +369,23 @@ DEFPY (config_log_file,
return set_log_file(&zt_file, vty, filename, level);
}
-DEFUN (no_config_log_file,
- no_config_log_file_cmd,
- "no log file [FILENAME [LEVEL]]",
- NO_STR
- "Logging control\n"
- "Cancel logging to file\n"
- "Logging file name\n"
- "Logging level\n")
+DEFUN(no_config_log_file, no_config_log_file_cmd,
+ "no log file [FILENAME [LEVEL]]",
+ NO_STR
+ "Logging control\n"
+ "Cancel logging to file\n"
+ "Logging file name\n"
+ "Logging level\n")
{
zt_file.prio_min = ZLOG_DISABLED;
zlog_file_set_other(&zt_file);
return CMD_SUCCESS;
}
-DEFPY (config_log_syslog,
- config_log_syslog_cmd,
- "log syslog [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>$levelarg]",
- "Logging control\n"
- "Set syslog logging level\n"
- LOG_LEVEL_DESC)
+DEFPY(config_log_syslog, config_log_syslog_cmd,
+ "log syslog [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>$levelarg]",
+ "Logging control\n"
+ "Set syslog logging level\n" LOG_LEVEL_DESC)
{
int level;
@@ -414,32 +398,27 @@ DEFPY (config_log_syslog,
level = log_default_lvl;
log_config_syslog_lvl = level;
- zlog_syslog_set_prio_min(ZLOG_MAXLVL(log_config_syslog_lvl,
- log_cmdline_syslog_lvl));
+ zlog_syslog_set_prio_min(
+ ZLOG_MAXLVL(log_config_syslog_lvl, log_cmdline_syslog_lvl));
return CMD_SUCCESS;
}
-DEFUN (no_config_log_syslog,
- no_config_log_syslog_cmd,
- "no log syslog [<kern|user|mail|daemon|auth|syslog|lpr|news|uucp|cron|local0|local1|local2|local3|local4|local5|local6|local7>] [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>]",
- NO_STR
- "Logging control\n"
- "Cancel logging to syslog\n"
- LOG_FACILITY_DESC
- LOG_LEVEL_DESC)
+DEFUN(no_config_log_syslog, no_config_log_syslog_cmd,
+ "no log syslog [<kern|user|mail|daemon|auth|syslog|lpr|news|uucp|cron|local0|local1|local2|local3|local4|local5|local6|local7>] [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>]",
+ NO_STR
+ "Logging control\n"
+ "Cancel logging to syslog\n" LOG_FACILITY_DESC LOG_LEVEL_DESC)
{
log_config_syslog_lvl = ZLOG_DISABLED;
- zlog_syslog_set_prio_min(ZLOG_MAXLVL(log_config_syslog_lvl,
- log_cmdline_syslog_lvl));
+ zlog_syslog_set_prio_min(
+ ZLOG_MAXLVL(log_config_syslog_lvl, log_cmdline_syslog_lvl));
return CMD_SUCCESS;
}
-DEFPY (config_log_facility,
- config_log_facility_cmd,
- "log facility <kern|user|mail|daemon|auth|syslog|lpr|news|uucp|cron|local0|local1|local2|local3|local4|local5|local6|local7>$facilityarg",
- "Logging control\n"
- "Facility parameter for syslog messages\n"
- LOG_FACILITY_DESC)
+DEFPY(config_log_facility, config_log_facility_cmd,
+ "log facility <kern|user|mail|daemon|auth|syslog|lpr|news|uucp|cron|local0|local1|local2|local3|local4|local5|local6|local7>$facilityarg",
+ "Logging control\n"
+ "Facility parameter for syslog messages\n" LOG_FACILITY_DESC)
{
int facility = facility_match(facilityarg);
@@ -447,23 +426,20 @@ DEFPY (config_log_facility,
return CMD_SUCCESS;
}
-DEFUN (no_config_log_facility,
- no_config_log_facility_cmd,
- "no log facility [<kern|user|mail|daemon|auth|syslog|lpr|news|uucp|cron|local0|local1|local2|local3|local4|local5|local6|local7>]",
- NO_STR
- "Logging control\n"
- "Reset syslog facility to default (daemon)\n"
- LOG_FACILITY_DESC)
+DEFUN(no_config_log_facility, no_config_log_facility_cmd,
+ "no log facility [<kern|user|mail|daemon|auth|syslog|lpr|news|uucp|cron|local0|local1|local2|local3|local4|local5|local6|local7>]",
+ NO_STR
+ "Logging control\n"
+ "Reset syslog facility to default (daemon)\n" LOG_FACILITY_DESC)
{
zlog_syslog_set_facility(LOG_DAEMON);
return CMD_SUCCESS;
}
-DEFUN (config_log_record_priority,
- config_log_record_priority_cmd,
- "log record-priority",
- "Logging control\n"
- "Log the priority of the message within the message\n")
+DEFUN(config_log_record_priority, config_log_record_priority_cmd,
+ "log record-priority",
+ "Logging control\n"
+ "Log the priority of the message within the message\n")
{
zt_file.record_priority = true;
zlog_file_set_other(&zt_file);
@@ -474,12 +450,11 @@ DEFUN (config_log_record_priority,
return CMD_SUCCESS;
}
-DEFUN (no_config_log_record_priority,
- no_config_log_record_priority_cmd,
- "no log record-priority",
- NO_STR
- "Logging control\n"
- "Do not log the priority of the message within the message\n")
+DEFUN(no_config_log_record_priority, no_config_log_record_priority_cmd,
+ "no log record-priority",
+ NO_STR
+ "Logging control\n"
+ "Do not log the priority of the message within the message\n")
{
zt_file.record_priority = false;
zlog_file_set_other(&zt_file);
@@ -490,13 +465,12 @@ DEFUN (no_config_log_record_priority,
return CMD_SUCCESS;
}
-DEFPY (config_log_timestamp_precision,
- config_log_timestamp_precision_cmd,
- "log timestamp precision (0-6)",
- "Logging control\n"
- "Timestamp configuration\n"
- "Set the timestamp precision\n"
- "Number of subsecond digits\n")
+DEFPY(config_log_timestamp_precision, config_log_timestamp_precision_cmd,
+ "log timestamp precision (0-6)",
+ "Logging control\n"
+ "Timestamp configuration\n"
+ "Set the timestamp precision\n"
+ "Number of subsecond digits\n")
{
zt_file.ts_subsec = precision;
zlog_file_set_other(&zt_file);
@@ -507,14 +481,13 @@ DEFPY (config_log_timestamp_precision,
return CMD_SUCCESS;
}
-DEFUN (no_config_log_timestamp_precision,
- no_config_log_timestamp_precision_cmd,
- "no log timestamp precision [(0-6)]",
- NO_STR
- "Logging control\n"
- "Timestamp configuration\n"
- "Reset the timestamp precision to the default value of 0\n"
- "Number of subsecond digits\n")
+DEFUN(no_config_log_timestamp_precision, no_config_log_timestamp_precision_cmd,
+ "no log timestamp precision [(0-6)]",
+ NO_STR
+ "Logging control\n"
+ "Timestamp configuration\n"
+ "Reset the timestamp precision to the default value of 0\n"
+ "Number of subsecond digits\n")
{
zt_file.ts_subsec = 0;
zlog_file_set_other(&zt_file);
@@ -525,13 +498,11 @@ DEFUN (no_config_log_timestamp_precision,
return CMD_SUCCESS;
}
-DEFPY (config_log_filterfile,
- config_log_filterfile_cmd,
- "log filtered-file FILENAME [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>$levelarg]",
- "Logging control\n"
- "Logging to file with string filter\n"
- "Logging filename\n"
- LOG_LEVEL_DESC)
+DEFPY(config_log_filterfile, config_log_filterfile_cmd,
+ "log filtered-file FILENAME [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>$levelarg]",
+ "Logging control\n"
+ "Logging to file with string filter\n"
+ "Logging filename\n" LOG_LEVEL_DESC)
{
int level = log_default_lvl;
@@ -543,14 +514,13 @@ DEFPY (config_log_filterfile,
return set_log_file(&zt_filterfile.parent, vty, filename, level);
}
-DEFUN (no_config_log_filterfile,
- no_config_log_filterfile_cmd,
- "no log filtered-file [FILENAME [LEVEL]]",
- NO_STR
- "Logging control\n"
- "Cancel logging to file with string filter\n"
- "Logging file name\n"
- "Logging level\n")
+DEFUN(no_config_log_filterfile, no_config_log_filterfile_cmd,
+ "no log filtered-file [FILENAME [LEVEL]]",
+ NO_STR
+ "Logging control\n"
+ "Cancel logging to file with string filter\n"
+ "Logging file name\n"
+ "Logging level\n")
{
zt_filterfile.parent.prio_min = ZLOG_DISABLED;
zlog_file_set_other(&zt_filterfile.parent);
@@ -690,8 +660,7 @@ void log_config_write(struct vty *vty)
vty_out(vty, "log record-priority\n");
if (zt_file.ts_subsec > 0)
- vty_out(vty, "log timestamp precision %d\n",
- zt_file.ts_subsec);
+ vty_out(vty, "log timestamp precision %d\n", zt_file.ts_subsec);
}
void zlog_init(const char *progname, const char *protoname,
diff --git a/lib/memory.h b/lib/memory.h
index 9b9772b35..4c35e87b9 100644
--- a/lib/memory.h
+++ b/lib/memory.h
@@ -81,14 +81,12 @@ struct memgroup {
#define DECLARE_MGROUP(name) extern struct memgroup _mg_##name;
#define _DEFINE_MGROUP(mname, desc, ...) \
struct memgroup _mg_##mname \
- __attribute__((section(".data.mgroups"))) = { \
- .name = desc, \
- .types = NULL, \
- .next = NULL, \
- .insert = NULL, \
- .ref = NULL, \
- __VA_ARGS__ \
- }; \
+ __attribute__((section(".data.mgroups"))) = {.name = desc, \
+ .types = NULL, \
+ .next = NULL, \
+ .insert = NULL, \
+ .ref = NULL, \
+ __VA_ARGS__}; \
static void _mginit_##mname(void) __attribute__((_CONSTRUCTOR(1000))); \
static void _mginit_##mname(void) \
{ \
@@ -106,9 +104,8 @@ struct memgroup {
} \
/* end */
-#define DEFINE_MGROUP(mname, desc) \
- _DEFINE_MGROUP(mname, desc, )
-#define DEFINE_MGROUP_ACTIVEATEXIT(mname, desc) \
+#define DEFINE_MGROUP(mname, desc) _DEFINE_MGROUP(mname, desc, )
+#define DEFINE_MGROUP_ACTIVEATEXIT(mname, desc) \
_DEFINE_MGROUP(mname, desc, .active_at_exit = true)
#define DECLARE_MTYPE(name) \
diff --git a/watchfrr/watchfrr_vty.c b/watchfrr/watchfrr_vty.c
index eda4f5d51..9cd53fd06 100644
--- a/watchfrr/watchfrr_vty.c
+++ b/watchfrr/watchfrr_vty.c
@@ -138,11 +138,8 @@ DEFUN (show_watchfrr,
/* we don't have the other logging commands since watchfrr only accepts
* log config through command line options
*/
-DEFUN_NOSH (show_logging,
- show_logging_cmd,
- "show logging",
- SHOW_STR
- "Show current logging configuration\n")
+DEFUN_NOSH(show_logging, show_logging_cmd, "show logging",
+ SHOW_STR "Show current logging configuration\n")
{
log_show_syslog(vty);
return CMD_SUCCESS;
If you are a new contributor to FRR, please see our contributing guidelines.
This comment has been minimized.
This comment has been minimized.
This comment has been minimized.
This comment has been minimized.
|
@louberger need info on your CI failures here |
|
@eqvinox failures are memory free on exit related: 7.28.1 7.0.0.130 Memory leak on exit, 1 errors 0 1 |
|
@louberger these are intentional, and the exit status from |
This comment has been minimized.
This comment has been minimized.
This comment has been minimized.
This comment has been minimized.
|
CC lib/distribute.lo |
💚 Basic BGPD CI results: SUCCESS, 0 tests failedResults table
For details, please contact louberger |
Continuous Integration Result: SUCCESSFULCongratulations, this patch passed basic tests Tested-by: NetDEF / OpenSourceRouting.org CI System CI System Testrun URL: https://ci1.netdef.org/browse/FRR-FRRPULLREQ-11535/ This is a comment from an automated CI system. Warnings Generated during build:Checkout code: Successful with additional warningsCLANG Static Analyzer Summary
2 Static Analyzer issues remaining.See details at |
This is a full rewrite of the "back end" logging code. It now uses a lock-free list to iterate over logging targets, and the targets themselves are as lock-free as possible. (syslog() may have a hidden internal mutex in the C library; the file/fd targets use a single write() call which should ensure atomicity kernel-side.) Note that some functionality is lost in this patch: - Solaris printstack() backtraces are ditched (unlikely to come back) - the `log-filter` machinery is gone (re-added in followup commit) - `terminal monitor` is temporarily stubbed out. The old code had a race condition with VTYs going away. It'll likely come back rewritten and with vtysh support. - The `zebra_ext_log` hook is gone. Instead, it's now much easier to add a "proper" logging target. v2: TLS buffer to get some actual performance Signed-off-by: David Lamparter <equinox@diac24.net>
In some cases we really don't want to clean up things even when exiting (i.e. to keep the logging subsystem going.) This adds a flag on MGROUPs to indicate that. [v2: add "(active at exit)" marker text to debug memstats-at-exit] Signed-off-by: David Lamparter <equinox@diac24.net>
These bits of memory are intentionally kept alive at exit so logging still works. Signed-off-by: David Lamparter <equinox@diac24.net>
Signed-off-by: David Lamparter <equinox@diac24.net>
This is most of the old code bolted on top of the new "backend" infrastructure. It just wraps around zlog_fd() with the string search. Originally-by: Stephen Worley <sworley@cumulusnetworks.com> Signed-off-by: David Lamparter <equinox@diac24.net>
hook_register() invocations generally are in some initialization function and not looped over or similar. We can use a static struct hookent variable for the hook list entry in 99.999% of cases, so let's do that and not malloc() memory. Signed-off-by: David Lamparter <equinox@diac24.net>
Already fixed, I just typo'd while fixing a style warning |
💚 Basic BGPD CI results: SUCCESS, 0 tests failedResults table
For details, please contact louberger |
Continuous Integration Result: FAILEDSee below for issues. This is a comment from an automated CI system. Get source / Pull Request: SuccessfulBuilding Stage: SuccessfulBasic Tests: FailedTopology tests on Ubuntu 16.04 amd64: Failed (click for details)Topology Test Results are at https://ci1.netdef.org/browse/FRR-FRRPULLREQ-TOPOU1604-11538/test Topology Tests failed for Topology tests on Ubuntu 16.04 amd64: see full log at https://ci1.netdef.org/browse/FRR-FRRPULLREQ-11538/artifact/TOPOU1604/ErrorLog/log_topotests.txt Successful on other platforms/tests
Warnings Generated during build:Checkout code: Successful with additional warningsTopology tests on Ubuntu 16.04 amd64: Failed (click for details)Topology Test Results are at https://ci1.netdef.org/browse/FRR-FRRPULLREQ-TOPOU1604-11538/test Topology Tests failed for Topology tests on Ubuntu 16.04 amd64: see full log at https://ci1.netdef.org/browse/FRR-FRRPULLREQ-11538/artifact/TOPOU1604/ErrorLog/log_topotests.txt |
|
CI:rerun |
Continuous Integration Result: SUCCESSFULCongratulations, this patch passed basic tests Tested-by: NetDEF / OpenSourceRouting.org CI System CI System Testrun URL: https://ci1.netdef.org/browse/FRR-FRRPULLREQ-11556/ This is a comment from an automated CI system. Warnings Generated during build:Checkout code: Successful with additional warningsWarnings Generated during build:Debian 10 amd64 build: Successful with additional warningsDebian Package lintian failed for Debian 10 amd64 build: |
@Spantik only one day left on your self-imposed deadline 😄 |
| * Any higher-priority message causes the entire buffer to be flushed, thus | ||
| message ordering is preserved properly. | ||
| * The buffers are only ever accessed by the thread they are created by. This | ||
| means no locking is necessary. |
There was a problem hiding this comment.
Just to clarify -- if I have multiple threads logging to separate buffers, and one thread pushes a higher priority log message, will the buffers for "all" threads be flushed, or only for the one thread which pushed the higher priority log message? If only the single thread is flushed, it seems like the message ordering is preserved per thread, but not between threads, correct?
There was a problem hiding this comment.
Indeed, the flush is only local and thus only ordering for that particular thread is preserved.
The way I look at it is, ordering of log messages from different threads is arbitrary either way unless the code manually imposes some locks, and if it does that it might as well call zlog_tls_buffer_flush().
That said, I should probably add this to the docs 😄
There was a problem hiding this comment.
This is not a big concern IMHO. Since we have timestamp with every log clock_gettime(CLOCK_REALTIME, &msg->ts); we can always use offline tool to sort the file to get right order.
Log buffer flushing is thread-local. Signed-off-by: David Lamparter <equinox@diac24.net>
💚 Basic BGPD CI results: SUCCESS, 0 tests failedResults table
For details, please contact louberger |
Continuous Integration Result: SUCCESSFULCongratulations, this patch passed basic tests Tested-by: NetDEF / OpenSourceRouting.org CI System CI System Testrun URL: https://ci1.netdef.org/browse/FRR-FRRPULLREQ-11688/ This is a comment from an automated CI system. Warnings Generated during build:Checkout code: Successful with additional warningsWarnings Generated during build:Debian 10 amd64 build: Successful with additional warningsDebian Package lintian failed for Debian 10 amd64 build: |
| * Any higher-priority message causes the entire buffer to be flushed, thus | ||
| message ordering is preserved properly. | ||
| * The buffers are only ever accessed by the thread they are created by. This | ||
| means no locking is necessary. |
There was a problem hiding this comment.
This is not a big concern IMHO. Since we have timestamp with every log clock_gettime(CLOCK_REALTIME, &msg->ts); we can always use offline tool to sort the file to get right order.
|
|
||
| Write out any pending log messages that the calling thread may have in its | ||
| buffer. This function is safe to call regardless of the per-thread log | ||
| buffer being set up / in use or not. |
There was a problem hiding this comment.
Should there be no time limit which can ensure we log if max(buffer, time) which every event happens first? If buffer is of 64 and we have only 50 logs in the buffer and there are no major events then we don't seem to log here?
There was a problem hiding this comment.
I've thought about it and doing an explicit timeout is somewhat complicated... however, there is a zlog_tls_buffer_flush() in the thread_master code so it's not possible for a thread to go idle with log messages still in the buffer.
The major case where this would matter is an infinite loop somewhere after printing some debug messages. In this case, buffered messages can be read from /var/tmp like in the SEGV case.
| crash, these may contain unwritten buffered log messages. To show the contents | ||
| of these buffers, pipe their contents through ``tr '\0' '\n'``. A blank line | ||
| marks the end of valid unwritten data (it will generally be followed by | ||
| garbled, older log messages since the buffer is not cleared.) |
There was a problem hiding this comment.
How do we handle lagged/buffered logs not flushed and SEGV received?
There was a problem hiding this comment.
The buffer is mmap'ed, i.e. file contents are automatically kept up to date by the kernel. If a SEGV happens, the user can directly read from the buffer, which will contain whatever was last written. That's specifically what this block in the doc notes, with tr '\0' '\n' being a helpful command to convert NUL in the buffer to newline.
| if (!zlog_tls->nmsgs) | ||
| return; | ||
|
|
||
| rcu_read_lock(); |
There was a problem hiding this comment.
what if we create log file per thread with thread_id as suffix? If that is an option give to user to enable that feature then we do not need to lock in case of log to file and we can use offline utility to sort the logs and dump in one file. This would completely avoid locking?
There was a problem hiding this comment.
rcu_read_lock() is a very strange member of the "lock" family: it never blocks, the worst-case cost is a non-blocking syscall. That's why it's lock-free: it can't be made to block by other threads.
If you haven't looked at RCU before, rcu_read_lock() is basically the R side of a RW lock, except the W side is replaced by a ordered / barrier list (rcu_enqueue()) and does not block the R side.
So, I don't think we need a log file per thread, locking is already avoided :)
|
|
||
| size_t nmsgs; | ||
| struct zlog_msg msgs[TLS_LOG_MAXMSG]; | ||
| struct zlog_msg *msgp[TLS_LOG_MAXMSG]; |
There was a problem hiding this comment.
IVO_MAX is 1024 so why do we have fixed 64 blocks of log storage? Is this something we can control with hidden CLI.
There was a problem hiding this comment.
Yes, the 64 is an arbitrary limit, but... it only needs to be large enough to "diminish" the cost of the syscall to write out the messages. I don't think there is much gain by increasing it further, but it can be tested by changing the #define. And if it really helps, we should change it for everyone. Not much point to make it configurable IMHO :).
| /* messages written later need to take the formatting cost | ||
| * immediately since we can't hold a reference on varargs | ||
| */ | ||
| zlog_msg_text(msg, NULL); |
There was a problem hiding this comment.
Log formatting is done here right? When zlog_fd calls it again there is no formatting required right?
There was a problem hiding this comment.
Yes, zlog_msg_text() formats the message once, the formatted result is stored and other calls to zlog_msg_text() (e.g. from other log targets) reuse the result.
- This is needed due to FRRouting#5451
- This is needed due to FRRouting#5451
|
Hi David, I encountered this issue when registering to rtrlib libary with that puill request : #5015 this said, here is the crash that presumably is due to the change of zlogs. |
This is a full rewrite of the logging pieces in
libfrr; the old code was... old. The new code uses a lock-free linked list + RCU to maintain the log targets, meaning it's possible for the entire logging system to be lock free. (Individual logging targets may still need a lock, but none of file/fd/syslog have one.)Note that some functionality is lost in this patch:
there-added.log-filtermachinery is gone (also unlikely to come back... I have a better mechanism queued up)terminal monitoris temporarily stubbed out. The old code had a race condition with VTYs going away. It'll likely come back rewritten and with vtysh support.zebra_ext_loghook is gone. Instead, it's now much easier to add a "proper" logging target.I have further logging infrastructure pending which builds on top of this, this is just the first chunk.
The new logging code is permissively licensed like all other
libpieces that I did a full rewrite on.