From 4f6d16bd37e46eb10b99713f539c52b28ec951cb Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Thu, 27 May 2021 20:28:26 +0000 Subject: [PATCH 1/9] logger: catch out of bounds e->params[i] access ... when there are too many % characters in format string. Spotted by routine valgrind run. Signed-off-by: Marc Herbert --- tools/logger/convert.c | 24 ++++++++++++++++++------ 1 file changed, 18 insertions(+), 6 deletions(-) diff --git a/tools/logger/convert.c b/tools/logger/convert.c index c181b4b26012..13a98cb4b114 100644 --- a/tools/logger/convert.c +++ b/tools/logger/convert.c @@ -198,7 +198,7 @@ static const char *asprintf_entry_text(uint32_t entry_address) * ldc_entry_header from input to output. * * @param[out] pe copy of the header + formatted output - * @param[in] e copy of the dictionary entry with unformatted, + * @param[in] e copy of the dictionary entry where unformatted, uint32_t params have been inserted. @param[in] use_colors whether to use ANSI terminal codes */ @@ -223,9 +223,19 @@ static void process_params(struct proc_ldc_entry *pe, * For decoding log entry text from pointer %pQ is used. */ while ((p = strchr(p, '%'))) { + uint32_t raw_param; + + if (i >= e->header.params_num) { + /* Don't read e->params[] out of bounds. */ + log_err("Too many %% conversion specifiers in '%s'\n", + e->text); + break; + } + raw_param = e->params[i]; + /* % can't be the last char */ if (p + 1 >= t_end) { - log_err("Invalid format string"); + log_err("Invalid format string\n"); break; } @@ -237,14 +247,14 @@ static void process_params(struct proc_ldc_entry *pe, /* %s format specifier */ /* check for string printing, because it leads to logger crash */ log_err("String printing is not supported\n"); - pe->params[i] = (uintptr_t)asprintf("", e->params[i]); + pe->params[i] = (uintptr_t)asprintf("", raw_param); pe->subst_mask |= 1 << i; ++i; p += 2; } else if (p + 2 < t_end && p[1] == 'p' && p[2] == 'U') { /* %pUx format specifier */ /* substitute UUID entry address with formatted string pointer from heap */ - pe->params[i] = (uintptr_t)asprintf_uuid(p, e->params[i], use_colors, + pe->params[i] = (uintptr_t)asprintf_uuid(p, raw_param, use_colors, &uuid_fmt_len); pe->subst_mask |= 1 << i; ++i; @@ -256,7 +266,7 @@ static void process_params(struct proc_ldc_entry *pe, } else if (p + 2 < t_end && p[1] == 'p' && p[2] == 'Q') { /* %pQ format specifier */ /* substitute log entry address with formatted entry text */ - pe->params[i] = (uintptr_t)asprintf_entry_text(e->params[i]); + pe->params[i] = (uintptr_t)asprintf_entry_text(raw_param); pe->subst_mask |= 1 << i; ++i; @@ -269,11 +279,13 @@ static void process_params(struct proc_ldc_entry *pe, /* arguments different from %pU and %pQ should be passed without * modification */ - pe->params[i] = e->params[i]; + pe->params[i] = raw_param; ++i; p += 2; } } + if (i < e->header.params_num) + log_err("Too few %% conversion specifiers in '%s'\n", e->text); } static void free_proc_ldc_entry(struct proc_ldc_entry *pe) From 4dae1496d2f4a2b1c1b179f8b5ff9708f2b4dee5 Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Fri, 7 May 2021 05:10:15 +0000 Subject: [PATCH 2/9] logger: print INFO and DEBUG prefixes, not just ERROR and WARN It's not long and more consistent. Signed-off-by: Marc Herbert --- tools/logger/convert.c | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/tools/logger/convert.c b/tools/logger/convert.c index 13a98cb4b114..0580b41396f0 100644 --- a/tools/logger/convert.c +++ b/tools/logger/convert.c @@ -386,8 +386,12 @@ static const char *get_level_name(uint32_t level) return "ERROR "; case LOG_LEVEL_WARNING: return "WARN "; + case LOG_LEVEL_INFO: + return "INFO "; + case LOG_LEVEL_DEBUG: + return "DEBUG "; default: - return ""; /* info is usual, do not print anything */ + return "UNKNOWN "; } } From d5d92785e314353232872a6f8519a0ce685918d4 Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Thu, 27 May 2021 00:42:02 +0000 Subject: [PATCH 3/9] dma-trace.c: add some comments Connect the DMA initialization dots. Signed-off-by: Marc Herbert --- src/include/sof/trace/trace.h | 10 +++++++--- src/trace/dma-trace.c | 8 ++++++++ 2 files changed, 15 insertions(+), 3 deletions(-) diff --git a/src/include/sof/trace/trace.h b/src/include/sof/trace/trace.h index d0c2df28a173..437dbd388b40 100644 --- a/src/include/sof/trace/trace.h +++ b/src/include/sof/trace/trace.h @@ -161,7 +161,7 @@ int trace_filter_update(const struct trace_filter *elem); /** The start of this linker output MUST match the 'ldc_entry_header' * struct defined in the logger program running in user space. */ -#define _DECLARE_LOG_ENTRY(lvl, format, comp_class, params) \ +#define _DECLARE_LOG_ENTRY(lvl, format, comp_class, n_params) \ __section(".static_log." #lvl) \ static const struct { \ uint32_t level; \ @@ -175,7 +175,7 @@ int trace_filter_update(const struct trace_filter *elem); } log_entry = { \ lvl, \ comp_class, \ - params, \ + n_params, \ __LINE__, \ sizeof(RELATIVE_FILE), \ sizeof(format), \ @@ -306,9 +306,13 @@ static inline int trace_filter_update(const struct trace_filter *filter) #endif /* CONFIG_TRACEE, CONFIG_TRACE */ +/** Default value when there is no specific pipeline, dev, dai, etc. */ +#define _TRACE_INV_ID -1 +/** This has been replaced in commits 6ce635aa82 and earlier by the + * DECLARE_TR_CTX, tr_ctx and component UUID system below + */ #define _TRACE_INV_CLASS TRACE_CLASS_DEPRECATED -#define _TRACE_INV_ID -1 /** * Trace context. diff --git a/src/trace/dma-trace.c b/src/trace/dma-trace.c index efabc75c00c3..1949022e7b0e 100644 --- a/src/trace/dma-trace.c +++ b/src/trace/dma-trace.c @@ -120,6 +120,10 @@ static enum task_state trace_work(void *data) return SOF_TASK_STATE_RESCHEDULE; } +/** Do this early so we can log at initialization time even before the + * DMA runs. The rest happens later in dma_trace_init_complete() and + * dma_trace_enable() + */ int dma_trace_init_early(struct sof *sof) { sof->dmat = rzalloc(SOF_MEM_ZONE_SYS_SHARED, 0, SOF_MEM_CAPS_RAM, sizeof(*sof->dmat)); @@ -135,6 +139,7 @@ int dma_trace_init_early(struct sof *sof) return 0; } +/** Run after dma_trace_init_early() and before dma_trace_enable() */ int dma_trace_init_complete(struct dma_trace_data *d) { int ret = 0; @@ -317,6 +322,9 @@ static int dma_trace_get_avail_data(struct dma_trace_data *d, #endif /* CONFIG_DMA_GW */ +/** Invoked remotely by SOF_IPC_TRACE_DMA_PARAMS* Depends on + * dma_trace_init_complete() + */ int dma_trace_enable(struct dma_trace_data *d) { int err; From 915800d3aff05a8ee7c6cb7334506a5f1c3bc802 Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Tue, 1 Jun 2021 05:09:11 +0000 Subject: [PATCH 4/9] dma-trace.c: remove misunderstood trace_flush() after FW ABI banner Fixes commit 6c14e76c0d983 ("trace: Log FW ABI and hash numbers"). In June 2020, PR #3195 added a tr_info() "banner" immediately after to make sure tracing works. That commit included a likely misunderstood trace_flush() call immediately after the tr_info(). The very poorly named trace_flush() function sounds like earlier scheduling of something that would the same later anyway but that's absolutely not what it does. Instead it copies pending DMA traces to the shared mailbox. This was most likely why the FW ABI banner is randomly duplicated in the etrace from time to time, see for instance: https://sof-ci.01.org/linuxpr/PR2954/build5823/devicetest/?model=BYT_MB_NOCODEC&testcase=test-speaker https://sof-ci.01.org/softestpr/PR666/build721/devicetest/?model=TGLH_RVP_HDA&testcase=check-sof-logger Note this test failure is unrelated. For now this CI does not read etrace unless there's a failure. In August 2020, commit 67a0a6937c87 ("trace: Trace initial message as error logs") upgraded this banner from tr_info() to tr_err(). That made sure it gets to both the mailbox and the DMA trace but it didn't remove the trace_flush(). Remove it now. Signed-off-by: Marc Herbert --- src/trace/dma-trace.c | 3 --- 1 file changed, 3 deletions(-) diff --git a/src/trace/dma-trace.c b/src/trace/dma-trace.c index 1949022e7b0e..a75aa3d34c8f 100644 --- a/src/trace/dma-trace.c +++ b/src/trace/dma-trace.c @@ -352,9 +352,6 @@ int dma_trace_enable(struct dma_trace_data *d) goto out; #endif - /* flush fw description message */ - trace_flush(); - /* validate DMA context */ if (!d->dc.dmac || !d->dc.chan) { tr_err_atomic(&dt_tr, "dma_trace_enable(): not valid"); From 75020b93233c4910a396798001a766a8377c4304 Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Tue, 1 Jun 2021 05:15:32 +0000 Subject: [PATCH 5/9] trace: rename trace_flush() to trace_flush_dma_to_mbox() Pure rename, zero functional change. The very poorly named trace_flush() function sounds like earlier scheduling of something that would the same later anyway but that's absolutely not what it does. Instead it copies pending DMA traces to the shared mailbox. As an example, in June 2020, PR #3195 commit 6c14e76c0d983 ("trace: Log FW ABI and hash numbers") added a tr_info() "banner" immediately after to make sure tracing works. That included a likely misunderstood trace_flush() call immediately after the tr_info(). Signed-off-by: Marc Herbert --- src/debug/panic.c | 3 +-- src/include/sof/trace/dma-trace.h | 2 +- src/include/sof/trace/trace.h | 4 ++-- src/trace/trace.c | 2 +- test/cmocka/src/common_mocks.c | 2 +- 5 files changed, 6 insertions(+), 7 deletions(-) diff --git a/src/debug/panic.c b/src/debug/panic.c index b866f5991c37..22c6003ac2ee 100644 --- a/src/debug/panic.c +++ b/src/debug/panic.c @@ -81,9 +81,8 @@ void panic_dump(uint32_t p, struct sof_ipc_panic_info *panic_info, count = MAILBOX_EXCEPTION_SIZE - (size_t)(ext_offset - (char *)mailbox_get_exception_base()); - /* flush last trace messages */ #if CONFIG_TRACE - trace_flush(); + trace_flush_dma_to_mbox(); #endif /* dump stack frames */ diff --git a/src/include/sof/trace/dma-trace.h b/src/include/sof/trace/dma-trace.h index bb47133506f0..659ba33843c3 100644 --- a/src/include/sof/trace/dma-trace.h +++ b/src/include/sof/trace/dma-trace.h @@ -52,7 +52,7 @@ int dma_trace_host_buffer(struct dma_trace_data *d, struct dma_sg_elem_array *elem_array, uint32_t host_size); int dma_trace_enable(struct dma_trace_data *d); -void dma_trace_flush(void *t); +void dma_trace_flush(void *destination); void dma_trace_on(void); void dma_trace_off(void); diff --git a/src/include/sof/trace/trace.h b/src/include/sof/trace/trace.h index 437dbd388b40..7e7fb4eafe14 100644 --- a/src/include/sof/trace/trace.h +++ b/src/include/sof/trace/trace.h @@ -137,7 +137,7 @@ struct trace_filter { ctx, id_1, id_2, \ format, ##__VA_ARGS__) -void trace_flush(void); +void trace_flush_dma_to_mbox(void); void trace_on(void); void trace_off(void); void trace_init(struct sof *sof); @@ -253,7 +253,7 @@ do { \ #define trace_point(x) do {} while (0) -static inline void trace_flush(void) { } +static inline void trace_flush_dma_to_mbox(void) { } static inline void trace_on(void) { } static inline void trace_off(void) { } static inline void trace_init(struct sof *sof) { } diff --git a/src/trace/trace.c b/src/trace/trace.c index 9c17cf982cd8..4a6462ea48bf 100644 --- a/src/trace/trace.c +++ b/src/trace/trace.c @@ -463,7 +463,7 @@ int trace_filter_update(const struct trace_filter *filter) } /** Sends all pending DMA messages to mailbox (for emergencies) */ -void trace_flush(void) +void trace_flush_dma_to_mbox(void) { struct trace *trace = trace_get(); volatile uint64_t *t; diff --git a/test/cmocka/src/common_mocks.c b/test/cmocka/src/common_mocks.c index 5607db0caf54..05a168575aa4 100644 --- a/test/cmocka/src/common_mocks.c +++ b/test/cmocka/src/common_mocks.c @@ -111,7 +111,7 @@ void WEAK trace_log_filtered(bool send_atomic, const void *log_entry, const stru (void) arg_count; } -void WEAK trace_flush(void) +void WEAK trace_flush_dma_to_mbox(void) { } From 555e82c8606bbba104a2f8a4c1180863380c4131 Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Tue, 1 Jun 2021 07:21:04 +0000 Subject: [PATCH 6/9] dma-trace: new dma_trace_initialized() function Avoids duplication and potential divergence. Signed-off-by: Marc Herbert --- src/include/sof/trace/dma-trace.h | 5 +++++ src/trace/dma-trace.c | 7 +++---- 2 files changed, 8 insertions(+), 4 deletions(-) diff --git a/src/include/sof/trace/dma-trace.h b/src/include/sof/trace/dma-trace.h index 659ba33843c3..53cd8bac2fb8 100644 --- a/src/include/sof/trace/dma-trace.h +++ b/src/include/sof/trace/dma-trace.h @@ -59,6 +59,11 @@ void dma_trace_off(void); void dtrace_event(const char *e, uint32_t size); void dtrace_event_atomic(const char *e, uint32_t length); +static inline bool dma_trace_initialized(const struct dma_trace_data *d) +{ + return d && d->dmatb.addr; +} + static inline struct dma_trace_data *dma_trace_data_get(void) { return sof_get()->dmat; diff --git a/src/trace/dma-trace.c b/src/trace/dma-trace.c index a75aa3d34c8f..5313a1346aa4 100644 --- a/src/trace/dma-trace.c +++ b/src/trace/dma-trace.c @@ -379,9 +379,8 @@ void dma_trace_flush(void *t) int32_t wrap_count; int ret; - if (!trace_data || !trace_data->dmatb.addr) { + if (!dma_trace_initialized(trace_data)) return; - } buffer = &trace_data->dmatb; avail = buffer->avail; @@ -553,7 +552,7 @@ void dtrace_event(const char *e, uint32_t length) struct dma_trace_buf *buffer = NULL; unsigned long flags; - if (!trace_data || !trace_data->dmatb.addr || + if (!dma_trace_initialized(trace_data) || length > DMA_TRACE_LOCAL_SIZE / 8 || length == 0) { return; } @@ -591,7 +590,7 @@ void dtrace_event_atomic(const char *e, uint32_t length) { struct dma_trace_data *trace_data = dma_trace_data_get(); - if (!trace_data || !trace_data->dmatb.addr || + if (!dma_trace_initialized(trace_data) || length > DMA_TRACE_LOCAL_SIZE / 8 || length == 0) { return; } From 5d893ce6a4fb2e332357dea3ecdec946b4d12b5b Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Tue, 1 Jun 2021 07:22:44 +0000 Subject: [PATCH 7/9] trace: initialize DMA trace _after_ mailbox The DMA trace is optional, the mailbox is not. This lets use the mailbox when initializing the DMA trace. Signed-off-by: Marc Herbert --- src/trace/trace.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/trace/trace.c b/src/trace/trace.c index 4a6462ea48bf..a71a6eec7433 100644 --- a/src/trace/trace.c +++ b/src/trace/trace.c @@ -508,8 +508,6 @@ void trace_off(void) void trace_init(struct sof *sof) { - dma_trace_init_early(sof); - sof->trace = rzalloc(SOF_MEM_ZONE_SYS_SHARED, 0, SOF_MEM_CAPS_RAM, sizeof(*sof->trace)); sof->trace->enable = 1; sof->trace->pos = 0; @@ -521,4 +519,6 @@ void trace_init(struct sof *sof) bzero((void *)MAILBOX_TRACE_BASE, MAILBOX_TRACE_SIZE); dcache_writeback_invalidate_region((void *)MAILBOX_TRACE_BASE, MAILBOX_TRACE_SIZE); + + dma_trace_init_early(sof); } From 37e4aac1dbfae8a00aabe93eb404c175e28eddeb Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Thu, 10 Jun 2021 01:42:18 +0000 Subject: [PATCH 8/9] trace.c: put_header(): make sof->timer optional for early tracing Avoids crashes when trying to use put_header() early. Learned the hard way because put_header() has also a timestamp argument. Signed-off-by: Marc Herbert --- src/trace/trace.c | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/trace/trace.c b/src/trace/trace.c index a71a6eec7433..f62c554e9186 100644 --- a/src/trace/trace.c +++ b/src/trace/trace.c @@ -75,6 +75,8 @@ static void put_header(uint32_t *dst, const struct sof_uuid_entry *uid, uint32_t entry, uint64_t timestamp) { struct timer *timer = timer_get(); + /* Support very early tracing */ + uint64_t delta = timer ? timer->delta : 0; struct log_entry_header header; int ret; @@ -82,7 +84,7 @@ static void put_header(uint32_t *dst, const struct sof_uuid_entry *uid, header.id_0 = id_1 & TRACE_ID_MASK; header.id_1 = id_2 & TRACE_ID_MASK; header.core_id = cpu_get_id(); - header.timestamp = timestamp + timer->delta; + header.timestamp = timestamp + delta; header.log_entry_address = entry; ret = memcpy_s(dst, sizeof(header), &header, sizeof(header)); From 3418dbb8d1e20d2c7c6a15b4180734a32be3d212 Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Mon, 31 May 2021 20:00:52 +0000 Subject: [PATCH 9/9] logger: prefix and pad "task add 0xbe05ba30 " Before: WARN task add 0xbe05ba30 After: WARN task add 0xbe05ba30 Signed-off-by: Marc Herbert --- tools/logger/convert.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tools/logger/convert.c b/tools/logger/convert.c index 0580b41396f0..3fee8d7c20eb 100644 --- a/tools/logger/convert.c +++ b/tools/logger/convert.c @@ -60,7 +60,7 @@ struct proc_ldc_entry { uintptr_t params[TRACE_MAX_PARAMS_COUNT]; }; -static const char *BAD_PTR_STR = ""; +static const char *BAD_PTR_STR = ""; #define UUID_LOWER "%s%s%s<%08x-%04x-%04x-%02x%02x-%02x%02x%02x%02x%02x%02x>%s%s%s" #define UUID_UPPER "%s%s%s<%08X-%04X-%04X-%02X%02X-%02X%02X%02X%02X%02X%02X>%s%s%s"