From 02fc9e89775fe7f16d0aa78e369fec6313fec411 Mon Sep 17 00:00:00 2001 From: Andreas Dilger Date: Thu, 7 Mar 2024 15:00:31 -0700 Subject: [PATCH] LU-17623 libcfs: save msg_fn pointer to avoid race Save msgdata->msg_fn pointer at the start of libcfs_debug_msg() to avoid a race condition if another thread calls CDEBUG_WITH_LOC() at the same time and has a different calling function name. The msg_file pointer was already being saved. Otherwise it is possible to fail the __LASSERT(debug_buf == string_buf) check if formatted string length changes between prep and write passes. Use existing header.ph_mask and .ph_line instead of duplicating them. Test-Parameters: testlist=sanity-scrub env=ONLY=4d,ONLY_REPEAT=25 Fixes: 1a9bd41846 ("LU-14518 libcfs: print CFS_FAIL_CHECK() location") Signed-off-by: Andreas Dilger Change-Id: I3fd30cc9eed2ec8dabd795e9622fe1908a3ebbe5 Reviewed-on: https://review.whamcloud.com/c/fs/lustre-release/+/54320 Tested-by: jenkins Tested-by: Maloo Reviewed-by: Alex Zhuravlev Reviewed-by: Aurelien Degremont Reviewed-by: Oleg Drokin --- libcfs/libcfs/tracefile.c | 49 +++++++++++++++++++++++------------------------ 1 file changed, 24 insertions(+), 25 deletions(-) diff --git a/libcfs/libcfs/tracefile.c b/libcfs/libcfs/tracefile.c index 1085e14..9c638a6b0 100644 --- a/libcfs/libcfs/tracefile.c +++ b/libcfs/libcfs/tracefile.c @@ -325,11 +325,12 @@ static void cfs_set_ptldebug_header(struct ptldebug_header *header, header->ph_extern_pid = 0; } -static void cfs_vprint_to_console(struct ptldebug_header *hdr, int mask, +static void cfs_vprint_to_console(struct ptldebug_header *hdr, struct va_format *vaf, const char *file, const char *fn) { char *prefix = "Lustre"; + int mask = hdr->ph_mask; if (hdr->ph_subsys == S_LND || hdr->ph_subsys == S_LNET) prefix = "LNet"; @@ -361,9 +362,8 @@ static void cfs_vprint_to_console(struct ptldebug_header *hdr, int mask, } } -static void cfs_print_to_console(struct ptldebug_header *hdr, int mask, - const char *file, const char *fn, - const char *fmt, ...) +static void cfs_print_to_console(struct ptldebug_header *hdr, const char *file, + const char *fn, const char *fmt, ...) { struct va_format vaf; va_list args; @@ -371,7 +371,7 @@ static void cfs_print_to_console(struct ptldebug_header *hdr, int mask, va_start(args, fmt); vaf.fmt = fmt; vaf.va = &args; - cfs_vprint_to_console(hdr, mask, &vaf, file, fn); + cfs_vprint_to_console(hdr, &vaf, file, fn); } #define DEBUG_FORMAT_BUFFER_SIZE (256 - sizeof(unsigned long)) @@ -565,8 +565,8 @@ void libcfs_debug_msg(struct libcfs_debug_msg_data *msgdata, int max_nob; va_list ap; int retry; - int mask = msgdata->msg_mask; - char *file = (char *)msgdata->msg_file; + const char *file = msgdata->msg_file; + const char *fn = msgdata->msg_fn; struct cfs_debug_limit_state *cdls = msgdata->msg_cdls; struct debug_format_buffer *dfb = NULL; @@ -596,8 +596,8 @@ void libcfs_debug_msg(struct libcfs_debug_msg_data *msgdata, } known_size = strlen(file) + 1; - if (msgdata->msg_fn) - known_size += strlen(msgdata->msg_fn) + 1; + if (fn) + known_size += strlen(fn) + 1; if (libcfs_debug_binary) known_size += sizeof(header); @@ -614,7 +614,7 @@ void libcfs_debug_msg(struct libcfs_debug_msg_data *msgdata, tage = cfs_trace_get_tage(tcd, needed + known_size + 1); if (!tage) { if (needed + known_size > PAGE_SIZE) - mask |= D_ERROR; + header.ph_mask |= D_ERROR; cfs_trace_put_tcd(tcd); tcd = NULL; @@ -628,7 +628,7 @@ void libcfs_debug_msg(struct libcfs_debug_msg_data *msgdata, if (max_nob <= 0) { pr_emerg("LustreError: negative max_nob: %d\n", max_nob); - mask |= D_ERROR; + header.ph_mask |= D_ERROR; cfs_trace_put_tcd(tcd); tcd = NULL; goto console; @@ -646,9 +646,9 @@ void libcfs_debug_msg(struct libcfs_debug_msg_data *msgdata, } /* `needed` is actual bytes written to string_buf */ - if (*(string_buf + needed - 1) != '\n') { + if (unlikely(*(string_buf + needed - 1) != '\n')) { pr_info("Lustre: format at %s:%d:%s doesn't end in newline\n", - file, msgdata->msg_line, msgdata->msg_fn); + file, header.ph_line_num, fn); } header.ph_len = known_size + needed; @@ -664,10 +664,10 @@ void libcfs_debug_msg(struct libcfs_debug_msg_data *msgdata, tage->used += strlen(file) + 1; debug_buf += strlen(file) + 1; - if (msgdata->msg_fn) { - strlcpy(debug_buf, msgdata->msg_fn, PAGE_SIZE - tage->used); - tage->used += strlen(msgdata->msg_fn) + 1; - debug_buf += strlen(msgdata->msg_fn) + 1; + if (fn) { + strlcpy(debug_buf, fn, PAGE_SIZE - tage->used); + tage->used += strlen(fn) + 1; + debug_buf += strlen(fn) + 1; } __LASSERT(debug_buf == string_buf); @@ -676,7 +676,7 @@ void libcfs_debug_msg(struct libcfs_debug_msg_data *msgdata, __LASSERT(tage->used <= PAGE_SIZE); console: - if ((mask & libcfs_printk) == 0) { + if ((header.ph_mask & libcfs_printk) == 0) { /* no console output requested */ if (tcd != NULL) cfs_trace_put_tcd(tcd); @@ -713,8 +713,7 @@ console: } if (tcd) { - cfs_print_to_console(&header, mask, file, msgdata->msg_fn, - "%s", string_buf); + cfs_print_to_console(&header, file, fn, "%s", string_buf); cfs_trace_put_tcd(tcd); } else { struct va_format vaf; @@ -722,14 +721,12 @@ console: va_start(ap, format); vaf.fmt = format; vaf.va = ≈ - cfs_vprint_to_console(&header, mask, - &vaf, file, msgdata->msg_fn); + cfs_vprint_to_console(&header, &vaf, file, fn); va_end(ap); } if (cdls != NULL && cdls->cdls_count != 0) { - cfs_print_to_console(&header, mask, file, - msgdata->msg_fn, + cfs_print_to_console(&header, file, fn, "Skipped %d previous similar message%s\n", cdls->cdls_count, (cdls->cdls_count > 1) ? "s" : ""); @@ -752,8 +749,9 @@ cfs_trace_assertion_failed(const char *str, smp_mb(); cfs_set_ptldebug_header(&hdr, msgdata); + hdr.ph_mask = D_EMERG; - cfs_print_to_console(&hdr, D_EMERG, msgdata->msg_file, msgdata->msg_fn, + cfs_print_to_console(&hdr, msgdata->msg_file, msgdata->msg_fn, "%s", str); panic("Lustre debug assertion failure\n"); @@ -854,6 +852,7 @@ void cfs_trace_debug_print(void) while (p < ((char *)page_address(page) + tage->used)) { struct ptldebug_header *hdr; int len; + hdr = (void *)p; p += sizeof(*hdr); file = p; -- 1.8.3.1