This is merely a historical archive of years 2008-2021, before the migration to mailman3.
A maintained and still updated list archive can be found at https://lists.osmocom.org/hyperkitty/list/gerrit-log@lists.osmocom.org/.
Neels Hofmeyr gerrit-no-reply at lists.osmocom.orgNeels Hofmeyr has submitted this change and it was merged. ( https://gerrit.osmocom.org/10631 )
Change subject: log: add 'last' option to 'logging print file'
......................................................................
log: add 'last' option to 'logging print file'
Allow printing the source file information *after* the log information.
Add target->print_filename_pos, log_set_print_filename_pos() and enum
log_filename_pos, and the optional 'last' keyword to the 'logging print file'
vty command. (An enum in case we want to add other positions later.)
Rationale: on log lines, the logging context is usually printed first in the
logging text. Without the source file information, this logging context pretty
much aligns in an easily readable way. When adding the source file information,
each line's logging context info is shifted right by a pretty much random
amount and it is hard to spot recurring logging contexts.
One solution is to switch off source file info, of course, but that's not an
option when actively hacking on bugs and new features.
For example, it is unnecessarily hard to spot lchan FSM related log lines in
this osmo-bsc log snippet:
DRSL NOTICE mgw_endpoint_fsm.c:603 mgw-endpoint(conn0){WAIT_MGW_RESPONSE}: Freeing instance
DRSL NOTICE fsm.c:381 mgw-endpoint(conn0){WAIT_MGW_RESPONSE}: Deallocated
DMSC NOTICE mgw_endpoint_fsm.c:603 SUBSCR_CONN(conn0){CLEARING}: Received Event FORGET_MGW_ENDPOINT
DCHAN DEBUG lchan_rtp_fsm.c:741 lchan(0-0-1-TCH_F-0){WAIT_RLL_RTP_ESTABLISH}: Received Event LCHAN_EV_RTP_RELEASED
DCHAN DEBUG lchan_rtp_fsm.c:520 lchan_rtp(0-0-1-TCH_F-0){ROLLBACK}: Freeing instance
DCHAN DEBUG fsm.c:381 lchan_rtp(0-0-1-TCH_F-0){ROLLBACK}: Deallocated
DCHAN DEBUG lchan_rtp_fsm.c:520 lchan(0-0-1-TCH_F-0){WAIT_RLL_RTP_ESTABLISH}: Received Event LCHAN_EV_RTP_RELEASED
DCHAN DEBUG lchan_fsm.c:1232 lchan(0-0-1-TCH_F-0){WAIT_RLL_RTP_ESTABLISH}: state_chg to WAIT_RF_RELEASE_ACK
DRSL NOTICE handover_fsm.c:762 handover(interBSCin_conn0){WAIT_RR_HO_DETECT}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
DRSL NOTICE handover_fsm.c:762 handover(interBSCin_conn0){WAIT_RR_HO_DETECT}: Freeing instance
DRSL NOTICE fsm.c:381 handover(interBSCin_conn0){WAIT_RR_HO_DETECT}: Deallocated
DCHAN DEBUG lchan_fsm.c:1196 lchan(0-0-1-TCH_F-0){WAIT_RF_RELEASE_ACK}: state_chg to BORKEN
DCHAN DEBUG lchan_fsm.c:354 lchan(0-0-1-TCH_F-0){BORKEN}: (type=TCH_F) Clearing lchan state
DLMGCP DEBUG mgcp_client.c:741 Tx MGCP msg to MGCP GW: 'DLCX 3 2 at mgw MGCP 1.0'
DLMGCP DEBUG mgcp_client.c:743 Sending msg to MGCP GW size: 66
DRLL NOTICE mgcp_client_fsm.c:422 MGCP_CONN(to-BTS){ST_DLCX_RESP}: Received Event EV_DLCX_RESP
Placing the source file info behind the log text makes it much easier to
follow, while the source file info is still available:
DRSL NOTICE mgw-endpoint(conn0){WAIT_MGW_RESPONSE}: Freeing instance (mgw_endpoint_fsm.c:603)
DRSL NOTICE mgw-endpoint(conn0){WAIT_MGW_RESPONSE}: Deallocated (fsm.c:381)
DMSC NOTICE SUBSCR_CONN(conn0){CLEARING}: Received Event FORGET_MGW_ENDPOINT (mgw_endpoint_fsm.c:603)
DCHAN DEBUG lchan(0-0-1-TCH_F-0){WAIT_RLL_RTP_ESTABLISH}: Received Event LCHAN_EV_RTP_RELEASED (lchan_rtp_fsm.c:741)
DCHAN DEBUG lchan_rtp(0-0-1-TCH_F-0){ROLLBACK}: Freeing instance (lchan_rtp_fsm.c:520)
DCHAN DEBUG lchan_rtp(0-0-1-TCH_F-0){ROLLBACK}: Deallocated (fsm.c:381)
DCHAN DEBUG lchan(0-0-1-TCH_F-0){WAIT_RLL_RTP_ESTABLISH}: Received Event LCHAN_EV_RTP_RELEASED (lchan_rtp_fsm.c:520)
DCHAN DEBUG lchan(0-0-1-TCH_F-0){WAIT_RLL_RTP_ESTABLISH}: state_chg to WAIT_RF_RELEASE_ACK (lchan_fsm.c:1232)
DRSL NOTICE handover(interBSCin_conn0){WAIT_RR_HO_DETECT}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (handover_fsm.c:745)
DRSL NOTICE handover(interBSCin_conn0){WAIT_RR_HO_DETECT}: Freeing instance (handover_fsm.c:745)
DRSL NOTICE handover(interBSCin_conn0){WAIT_RR_HO_DETECT}: Deallocated (fsm.c:381)
DCHAN DEBUG lchan(0-0-1-TCH_F-0){WAIT_RF_RELEASE_ACK}: state_chg to BORKEN (lchan_fsm.c:1196)
DCHAN DEBUG lchan(0-0-1-TCH_F-0){BORKEN}: (type=TCH_F) Clearing lchan state (lchan_fsm.c:354)
DLMGCP DEBUG Tx MGCP msg to MGCP GW: 'DLCX 3 12 at mgw MGCP 1.0' (mgcp_client.c:741)
DLMGCP DEBUG Sending msg to MGCP GW size: 67 (mgcp_client.c:743)
DRLL NOTICE MGCP_CONN(to-BTS){ST_DLCX_RESP}: Received Event EV_DLCX_RESP (mgcp_client_fsm.c:422)
Implementation: for 'last', insert source file info only when an '\n' is found
at the end of the log line composition buffer, so that LOGP()...LOGPC()
constructs also print source file info only when a log line actually ends.
Change-Id: I393907b3c9e0cc1145e102328adad0a83ee13a9f
---
M include/osmocom/core/logging.h
M src/logging.c
M src/vty/logging_vty.c
3 files changed, 71 insertions(+), 17 deletions(-)
Approvals:
Jenkins Builder: Verified
Harald Welte: Looks good to me, approved
diff --git a/include/osmocom/core/logging.h b/include/osmocom/core/logging.h
index 3cae63d..8464043 100644
--- a/include/osmocom/core/logging.h
+++ b/include/osmocom/core/logging.h
@@ -228,6 +228,12 @@
LOG_FILENAME_BASENAME,
};
+/*! Where on a log line source file and line should be logged. */
+enum log_filename_pos {
+ LOG_FILENAME_POS_HEADER_END,
+ LOG_FILENAME_POS_LINE_END,
+};
+
/*! structure representing a logging target */
struct log_target {
struct llist_head entry; /*!< linked list */
@@ -313,6 +319,8 @@
bool print_category_hex;
/* Should we print the source file and line, and in which way? */
enum log_filename_type print_filename2;
+ /* Where on a log line to put the source file info. */
+ enum log_filename_pos print_filename_pos;
};
/* use the above macros */
@@ -335,6 +343,7 @@
void log_set_print_timestamp(struct log_target *target, int);
void log_set_print_filename(struct log_target *target, int);
void log_set_print_filename2(struct log_target *target, enum log_filename_type lft);
+void log_set_print_filename_pos(struct log_target *target, enum log_filename_pos pos);
void log_set_print_category(struct log_target *target, int);
void log_set_print_category_hex(struct log_target *target, int);
void log_set_print_level(struct log_target *target, int);
diff --git a/src/logging.c b/src/logging.c
index edb2b56..de0f2b0 100644
--- a/src/logging.c
+++ b/src/logging.c
@@ -406,21 +406,24 @@
goto err;
OSMO_SNPRINTF_RET(ret, rem, offset, len);
}
- switch (target->print_filename2) {
- case LOG_FILENAME_NONE:
- break;
- case LOG_FILENAME_PATH:
- ret = snprintf(buf + offset, rem, "%s:%d ", file, line);
- if (ret < 0)
- goto err;
- OSMO_SNPRINTF_RET(ret, rem, offset, len);
- break;
- case LOG_FILENAME_BASENAME:
- ret = snprintf(buf + offset, rem, "%s:%d ", const_basename(file), line);
- if (ret < 0)
- goto err;
- OSMO_SNPRINTF_RET(ret, rem, offset, len);
- break;
+
+ if (target->print_filename_pos == LOG_FILENAME_POS_HEADER_END) {
+ switch (target->print_filename2) {
+ case LOG_FILENAME_NONE:
+ break;
+ case LOG_FILENAME_PATH:
+ ret = snprintf(buf + offset, rem, "%s:%d ", file, line);
+ if (ret < 0)
+ goto err;
+ OSMO_SNPRINTF_RET(ret, rem, offset, len);
+ break;
+ case LOG_FILENAME_BASENAME:
+ ret = snprintf(buf + offset, rem, "%s:%d ", const_basename(file), line);
+ if (ret < 0)
+ goto err;
+ OSMO_SNPRINTF_RET(ret, rem, offset, len);
+ break;
+ }
}
}
ret = vsnprintf(buf + offset, rem, format, ap);
@@ -428,6 +431,31 @@
goto err;
OSMO_SNPRINTF_RET(ret, rem, offset, len);
+ /* For LOG_FILENAME_POS_LAST, print the source file info only when the caller ended the log
+ * message in '\n'. If so, nip the last '\n' away, insert the source file info and re-append an
+ * '\n'. All this to allow LOGP("start..."); LOGPC("...end\n") constructs. */
+ if (target->print_filename_pos == LOG_FILENAME_POS_LINE_END
+ && offset > 0 && buf[offset-1] == '\n') {
+ switch (target->print_filename2) {
+ case LOG_FILENAME_NONE:
+ break;
+ case LOG_FILENAME_PATH:
+ offset --;
+ ret = snprintf(buf + offset, rem, " (%s:%d)\n", file, line);
+ if (ret < 0)
+ goto err;
+ OSMO_SNPRINTF_RET(ret, rem, offset, len);
+ break;
+ case LOG_FILENAME_BASENAME:
+ offset --;
+ ret = snprintf(buf + offset, rem, " (%s:%d)\n", const_basename(file), line);
+ if (ret < 0)
+ goto err;
+ OSMO_SNPRINTF_RET(ret, rem, offset, len);
+ break;
+ }
+ }
+
if (target->use_color) {
ret = snprintf(buf + offset, rem, "\033[0;m");
if (ret < 0)
@@ -677,6 +705,17 @@
target->print_filename2 = lft;
}
+/*! Set the position where on a log line the source file info should be logged.
+ * \param[in] target Log target to be affected.
+ * \param[in] pos A LOG_FILENAME_POS_* enum value.
+ * LOG_FILENAME_POS_DEFAULT logs just before the caller supplied log message.
+ * LOG_FILENAME_POS_LAST logs only at the end of a log line, where the caller issued an '\n' to end the
+ */
+void log_set_print_filename_pos(struct log_target *target, enum log_filename_pos pos)
+{
+ target->print_filename_pos = pos;
+}
+
/*! Enable or disable printing of the category name
* \param[in] target Log target to be affected
* \param[in] print_catname Enable (1) or disable (0) filenames
diff --git a/src/vty/logging_vty.c b/src/vty/logging_vty.c
index 1194914..8c8a332 100644
--- a/src/vty/logging_vty.c
+++ b/src/vty/logging_vty.c
@@ -246,12 +246,14 @@
DEFUN(logging_prnt_file,
logging_prnt_file_cmd,
- "logging print file (0|1|basename)",
+ "logging print file (0|1|basename) [last]",
LOGGING_STR "Log output settings\n"
"Configure log message\n"
"Don't prefix each log message\n"
"Prefix each log message with the source file and line\n"
- "Prefix each log message with the source file's basename (strip leading paths) and line\n")
+ "Prefix each log message with the source file's basename (strip leading paths) and line\n"
+ "Log source file info at the end of a log line. If omitted, log source file info just"
+ " before the log text.\n")
{
struct log_target *tgt = osmo_log_vty2tgt(vty);
@@ -259,6 +261,10 @@
return CMD_WARNING;
log_set_print_filename2(tgt, get_string_value(logging_print_file_args, argv[0]));
+ if (argc > 1)
+ log_set_print_filename_pos(tgt, LOG_FILENAME_POS_LINE_END);
+ else
+ log_set_print_filename_pos(tgt, LOG_FILENAME_POS_HEADER_END);
return CMD_SUCCESS;
}
--
To view, visit https://gerrit.osmocom.org/10631
To unsubscribe, or for help writing mail filters, visit https://gerrit.osmocom.org/settings
Gerrit-Project: libosmocore
Gerrit-Branch: master
Gerrit-MessageType: merged
Gerrit-Change-Id: I393907b3c9e0cc1145e102328adad0a83ee13a9f
Gerrit-Change-Number: 10631
Gerrit-PatchSet: 1
Gerrit-Owner: Neels Hofmeyr <nhofmeyr at sysmocom.de>
Gerrit-Reviewer: Harald Welte <laforge at gnumonks.org>
Gerrit-Reviewer: Jenkins Builder (1000002)
Gerrit-Reviewer: Neels Hofmeyr <nhofmeyr at sysmocom.de>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.osmocom.org/pipermail/gerrit-log/attachments/20180828/58748838/attachment.htm>