/* * Copyright (c) 2018 Nordic Semiconductor * * SPDX-License-Identifier: Apache-2.0 */ /** * @file * @brief Test log message */ #include #include #include #include #include #include #include #include #if CONFIG_NO_OPTIMIZATIONS #define EXP_MODE(name) Z_LOG_MSG_MODE_RUNTIME #else #define EXP_MODE(name) Z_LOG_MSG_MODE_##name #endif #define TEST_TIMESTAMP_INIT_VALUE \ COND_CODE_1(CONFIG_LOG_TIMESTAMP_64BIT, (0x1234123412), (0x11223344)) static log_timestamp_t timestamp; log_timestamp_t get_timestamp(void) { return timestamp; } static void test_init(void) { timestamp = TEST_TIMESTAMP_INIT_VALUE; z_log_msg_init(); log_set_timestamp_func(get_timestamp, 0); } void print_msg(struct log_msg *msg) { printk("-----------------------printing message--------------------\n"); printk("message %p\n", msg); printk("package len: %d, data len: %d\n", msg->hdr.desc.package_len, msg->hdr.desc.data_len); for (int i = 0; i < msg->hdr.desc.package_len; i++) { printk("%02x ", msg->data[i]); } printk("\n"); printk("source: %p\n", msg->hdr.source); printk("timestamp: %d\n", (int)msg->hdr.timestamp); printk("-------------------end of printing message-----------------\n"); } struct test_buf { char *buf; int idx; }; int out(int c, void *ctx) { struct test_buf *t = ctx; t->buf[t->idx++] = c; return c; } static void basic_validate(struct log_msg *msg, const struct log_source_const_data *source, uint8_t domain, uint8_t level, log_timestamp_t t, const void *data, size_t data_len, char *str) { int rv; uint8_t *d; size_t len = 0; char buf[256]; struct test_buf tbuf = { .buf = buf, .idx = 0 }; zassert_equal(log_msg_get_source(msg), (void *)source); zassert_equal(log_msg_get_domain(msg), domain); zassert_equal(log_msg_get_level(msg), level); zassert_equal(log_msg_get_timestamp(msg), t); d = log_msg_get_data(msg, &len); zassert_equal(len, data_len); if (len) { rv = memcmp(d, data, data_len); zassert_equal(rv, 0); } d = log_msg_get_package(msg, &len); if (str) { rv = cbpprintf(out, &tbuf, d); zassert_true(rv > 0); buf[rv] = '\0'; rv = strncmp(buf, str, sizeof(buf)); zassert_equal(rv, 0, "expected:\n%s,\ngot:\n%s", str, buf); } } union log_msg_generic *msg_copy_and_free(union log_msg_generic *msg, uint8_t *buf, size_t buf_len) { size_t len = sizeof(int) * log_msg_generic_get_wlen((union mpsc_pbuf_generic *)msg); zassert_true(len < buf_len); memcpy(buf, msg, len); z_log_msg_free(msg); return (union log_msg_generic *)buf; } void clear_pkg_flags(struct log_msg *msg) { #ifdef CONFIG_CBPRINTF_PACKAGE_HEADER_STORE_CREATION_FLAGS /* * The various tests create cbprintf packages differently * for the same log message. This results in different * package flags stored in those packages. These package * flags can be ignored as we only want to make sure * the remaining header bits, the format string, and * the format arguments are all the same. */ uint8_t *d; size_t len; d = log_msg_get_package(msg, &len); if (len > 0) { union cbprintf_package_hdr *hdr = (void *)d; hdr->desc.pkg_flags = 0U; } #else ARG_UNUSED(msg); #endif } void validate_base_message_set(const struct log_source_const_data *source, uint8_t domain, uint8_t level, log_timestamp_t t, const void *data, size_t data_len, char *str) { uint8_t __aligned(Z_LOG_MSG_ALIGNMENT) buf0[256]; uint8_t __aligned(Z_LOG_MSG_ALIGNMENT) buf1[256]; uint8_t __aligned(Z_LOG_MSG_ALIGNMENT) buf2[256]; size_t len0, len1, len2; union log_msg_generic *msg0, *msg1, *msg2; msg0 = z_log_msg_claim(NULL); zassert_true(msg0, "Unexpected null message"); len0 = log_msg_generic_get_wlen((union mpsc_pbuf_generic *)msg0); msg0 = msg_copy_and_free(msg0, buf0, sizeof(buf0)); clear_pkg_flags(&msg0->log); msg1 = z_log_msg_claim(NULL); zassert_true(msg1, "Unexpected null message"); len1 = log_msg_generic_get_wlen((union mpsc_pbuf_generic *)msg1); msg1 = msg_copy_and_free(msg1, buf1, sizeof(buf1)); clear_pkg_flags(&msg1->log); msg2 = z_log_msg_claim(NULL); zassert_true(msg2, "Unexpected null message"); len2 = log_msg_generic_get_wlen((union mpsc_pbuf_generic *)msg2); msg2 = msg_copy_and_free(msg2, buf2, sizeof(buf2)); clear_pkg_flags(&msg2->log); print_msg(&msg0->log); print_msg(&msg1->log); print_msg(&msg2->log); /* Messages created with static packaging should have same output. * Runtime created message (msg2) may have strings copied in and thus * different length. */ zassert_equal(len0, len1); int rv = memcmp(msg0, msg1, sizeof(int) * len0); zassert_equal(rv, 0, "Unexpected memcmp result: %d", rv); /* msg1 is not validated because it should be the same as msg0. */ basic_validate(&msg0->log, source, domain, level, t, data, data_len, str); basic_validate(&msg2->log, source, domain, level, t, data, data_len, str); } ZTEST(log_msg, test_log_msg_0_args_msg) { #undef TEST_MSG #define TEST_MSG "0 args" static const uint8_t domain = 3; static const uint8_t level = 2; const void *source = (const void *)123; int mode; test_init(); printk("Test string:%s\n", TEST_MSG); Z_LOG_MSG_CREATE3(1, mode, 0, domain, source, level, NULL, 0, TEST_MSG); zassert_equal(mode, EXP_MODE(ZERO_COPY)); Z_LOG_MSG_CREATE3(0, mode, 0, domain, source, level, NULL, 0, TEST_MSG); zassert_equal(mode, EXP_MODE(FROM_STACK)); z_log_msg_runtime_create(domain, source, level, NULL, 0, 0, TEST_MSG); validate_base_message_set(source, domain, level, TEST_TIMESTAMP_INIT_VALUE, NULL, 0, TEST_MSG); } ZTEST(log_msg, test_log_msg_various_args) { #undef TEST_MSG #define TEST_MSG "%d %d %lld %p %lld %p" static const uint8_t domain = 3; static const uint8_t level = 2; const void *source = (const void *)123; int mode; uint8_t u = 0x45; signed char s8 = -5; long long lld = 0x12341234563412; char str[256]; static const int iarray[] = {1, 2, 3, 4}; test_init(); printk("Test string:%s\n", TEST_MSG); Z_LOG_MSG_CREATE3(1, mode, 0, domain, source, level, NULL, 0, TEST_MSG, s8, u, lld, (void *)str, lld, (void *)iarray); zassert_equal(mode, EXP_MODE(ZERO_COPY)); Z_LOG_MSG_CREATE3(0, mode, 0, domain, source, level, NULL, 0, TEST_MSG, s8, u, lld, (void *)str, lld, (void *)iarray); zassert_equal(mode, EXP_MODE(FROM_STACK)); z_log_msg_runtime_create(domain, (void *)source, level, NULL, 0, 0, TEST_MSG, s8, u, lld, str, lld, iarray); snprintfcb(str, sizeof(str), TEST_MSG, s8, u, lld, str, lld, iarray); validate_base_message_set(source, domain, level, TEST_TIMESTAMP_INIT_VALUE, NULL, 0, str); } ZTEST(log_msg, test_log_msg_only_data) { static const uint8_t domain = 3; static const uint8_t level = 2; const void *source = (const void *)123; int mode; static const uint8_t array[] = {1, 2, 3, 4}; test_init(); Z_LOG_MSG_CREATE3(1, mode, 0, domain, source, level, array, sizeof(array)); zassert_equal(mode, EXP_MODE(FROM_STACK)); Z_LOG_MSG_CREATE3(0, mode, 0, domain, source, level, array, sizeof(array)); zassert_equal(mode, EXP_MODE(FROM_STACK)); z_log_msg_runtime_create(domain, (void *)source, level, array, sizeof(array), 0, NULL); validate_base_message_set(source, domain, level, TEST_TIMESTAMP_INIT_VALUE, array, sizeof(array), NULL); } ZTEST(log_msg, test_log_msg_string_and_data) { #undef TEST_MSG #define TEST_MSG "test" static const uint8_t domain = 3; static const uint8_t level = 2; const void *source = (const void *)123; int mode; static const uint8_t array[] = {1, 2, 3, 4}; test_init(); Z_LOG_MSG_CREATE3(1, mode, 0, domain, source, level, array, sizeof(array), TEST_MSG); zassert_equal(mode, EXP_MODE(FROM_STACK)); Z_LOG_MSG_CREATE3(0, mode, 0, domain, source, level, array, sizeof(array), TEST_MSG); zassert_equal(mode, EXP_MODE(FROM_STACK)); z_log_msg_runtime_create(domain, (void *)source, level, array, sizeof(array), 0, TEST_MSG); validate_base_message_set(source, domain, level, TEST_TIMESTAMP_INIT_VALUE, array, sizeof(array), TEST_MSG); } ZTEST(log_msg, test_log_msg_fp) { if (!(IS_ENABLED(CONFIG_CBPRINTF_FP_SUPPORT) && IS_ENABLED(CONFIG_FPU))) { return; } #undef TEST_MSG #define TEST_MSG "%d %lld %f %p %f %p" static const uint8_t domain = 3; static const uint8_t level = 2; const void *source = (const void *)123; int mode; long long lli = 0x1122334455; float f = 1.234f; double d = 11.3434; char str[256]; int i = -100; test_init(); Z_LOG_MSG_CREATE3(1, mode, 0, domain, source, level, NULL, 0, TEST_MSG, i, lli, (double)f, &i, d, source); zassert_equal(mode, EXP_MODE(ZERO_COPY)); Z_LOG_MSG_CREATE3(0, mode, 0, domain, source, level, NULL, 0, TEST_MSG, i, lli, (double)f, &i, d, source); zassert_equal(mode, EXP_MODE(FROM_STACK)); z_log_msg_runtime_create(domain, (void *)source, level, NULL, 0, 0, TEST_MSG, i, lli, (double)f, &i, d, source); snprintfcb(str, sizeof(str), TEST_MSG, i, lli, (double)f, &i, d, source); validate_base_message_set(source, domain, level, TEST_TIMESTAMP_INIT_VALUE, NULL, 0, str); } static void get_msg_validate_length(uint32_t exp_len) { uint32_t len; union log_msg_generic *msg; msg = z_log_msg_claim(NULL); len = log_msg_generic_get_wlen((union mpsc_pbuf_generic *)msg); zassert_equal(len, exp_len, "Unexpected message length %d (exp:%d)", len, exp_len); z_log_msg_free(msg); } ZTEST(log_msg, test_mode_size_plain_string) { static const uint8_t domain = 3; static const uint8_t level = 2; const void *source = (const void *)123; uint32_t exp_len; int mode; Z_LOG_MSG_CREATE3(1, mode, 0, domain, source, level, NULL, 0, "test str"); zassert_equal(mode, EXP_MODE(ZERO_COPY), "Unexpected creation mode"); Z_LOG_MSG_CREATE3(0, mode, 0, domain, source, level, NULL, 0, "test str"); zassert_equal(mode, EXP_MODE(FROM_STACK), "Unexpected creation mode"); /* Calculate expected message length. Message consists of: * - header * - package of plain string header + string pointer * * Message size is rounded up to the required alignment. */ exp_len = offsetof(struct log_msg, data) + /* package */sizeof(struct cbprintf_package_hdr_ext); exp_len = ROUND_UP(exp_len, Z_LOG_MSG_ALIGNMENT) / sizeof(int); get_msg_validate_length(exp_len); get_msg_validate_length(exp_len); } ZTEST(log_msg, test_mode_size_data_only) { static const uint8_t domain = 3; static const uint8_t level = 2; const void *source = (const void *)123; uint32_t exp_len; int mode; /* If data is present then message is created from stack, even though * _from_stack is 0. */ uint8_t data[] = {1, 2, 3}; Z_LOG_MSG_CREATE3(1, mode, 0, domain, source, level, data, sizeof(data)); zassert_equal(mode, EXP_MODE(FROM_STACK), "Unexpected creation mode"); /* Calculate expected message length. Message consists of: * - header * - data * * Message size is rounded up to the required alignment. */ exp_len = offsetof(struct log_msg, data) + sizeof(data); exp_len = ROUND_UP(exp_len, Z_LOG_MSG_ALIGNMENT) / sizeof(int); get_msg_validate_length(exp_len); } ZTEST(log_msg, test_mode_size_plain_str_data) { static const uint8_t domain = 3; static const uint8_t level = 2; const void *source = (const void *)123; uint32_t exp_len; int mode; /* If data is present then message is created from stack, even though * _from_stack is 0. */ uint8_t data[] = {1, 2, 3}; Z_LOG_MSG_CREATE3(1, mode, 0, domain, source, level, data, sizeof(data), "test"); zassert_equal(mode, EXP_MODE(FROM_STACK), "Unexpected creation mode"); /* Calculate expected message length. Message consists of: * - header * - data * * Message size is rounded up to the required alignment. */ exp_len = offsetof(struct log_msg, data) + sizeof(data) + /* package */sizeof(struct cbprintf_package_hdr_ext); exp_len = ROUND_UP(exp_len, Z_LOG_MSG_ALIGNMENT) / sizeof(int); get_msg_validate_length(exp_len); } ZTEST(log_msg, test_mode_size_str_with_strings) { static const uint8_t domain = 3; static const uint8_t level = 2; const void *source = (const void *)123; uint32_t exp_len; int mode; static const char *prefix = "prefix"; Z_LOG_MSG_CREATE3(1, mode, 1 /* accept one string pointer*/, domain, source, level, NULL, 0, "test %s", prefix); zassert_equal(mode, EXP_MODE(ZERO_COPY), "Unexpected creation mode"); Z_LOG_MSG_CREATE3(0, mode, 1 /* accept one string pointer*/, domain, source, level, NULL, 0, "test %s", prefix); zassert_equal(mode, EXP_MODE(FROM_STACK), "Unexpected creation mode"); /* Calculate expected message length. Message consists of: * - header * - package: header + fmt pointer + pointer * * Message size is rounded up to the required alignment. */ exp_len = offsetof(struct log_msg, data) + /* package */sizeof(struct cbprintf_package_hdr_ext) + sizeof(const char *); exp_len = ROUND_UP(exp_len, Z_LOG_MSG_ALIGNMENT) / sizeof(int); get_msg_validate_length(exp_len); get_msg_validate_length(exp_len); } ZTEST(log_msg, test_mode_size_str_with_2strings) { #undef TEST_STR #define TEST_STR "%s test %s" static const uint8_t domain = 3; static const uint8_t level = 2; const void *source = (const void *)123; uint32_t exp_len; int mode; static const char *prefix = "prefix"; char sufix[] = "sufix"; Z_LOG_MSG_CREATE3(1, mode, 1 /* accept one string pointer*/, domain, source, level, NULL, 0, TEST_STR, prefix, sufix); zassert_equal(mode, EXP_MODE(FROM_STACK), "Unexpected creation mode"); Z_LOG_MSG_CREATE3(0, mode, 1 /* accept one string pointer*/, domain, source, level, NULL, 0, TEST_STR, prefix, sufix); zassert_equal(mode, EXP_MODE(FROM_STACK), "Unexpected creation mode"); /* Calculate expected message length. Message consists of: * - header * - package: header + fmt pointer + 2 pointers * - index location of read only string * * Message size is rounded up to the required alignment. */ exp_len = offsetof(struct log_msg, data) + /* package */sizeof(struct cbprintf_package_hdr_ext) + 2 * sizeof(const char *) + 2 + strlen(sufix); exp_len = ROUND_UP(exp_len, Z_LOG_MSG_ALIGNMENT) / sizeof(int); get_msg_validate_length(exp_len); get_msg_validate_length(exp_len); } static log_timestamp_t timestamp_get_inc(void) { return timestamp++; } ZTEST(log_msg, test_saturate) { if (IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW)) { return; } uint32_t exp_len = ROUND_UP(offsetof(struct log_msg, data) + 2 * sizeof(void *), Z_LOG_MSG_ALIGNMENT); uint32_t exp_capacity = CONFIG_LOG_BUFFER_SIZE / exp_len; int mode; union log_msg_generic *msg; test_init(); timestamp = 0; log_set_timestamp_func(timestamp_get_inc, 0); for (int i = 0; i < exp_capacity; i++) { Z_LOG_MSG_CREATE3(1, mode, 0, 0, (void *)1, 2, NULL, 0, "test"); } zassert_equal(z_log_dropped_read_and_clear(), 0, "No dropped messages."); /* Message should not fit in and be dropped. */ Z_LOG_MSG_CREATE3(1, mode, 0, 0, (void *)1, 2, NULL, 0, "test"); Z_LOG_MSG_CREATE3(0, mode, 0, 0, (void *)1, 2, NULL, 0, "test"); z_log_msg_runtime_create(0, (void *)1, 2, NULL, 0, 0, "test"); zassert_equal(z_log_dropped_read_and_clear(), 3, "No dropped messages."); for (int i = 0; i < exp_capacity; i++) { msg = z_log_msg_claim(NULL); zassert_equal(log_msg_get_timestamp(&msg->log), i, "Unexpected timestamp used for message id"); z_log_msg_free(msg); } msg = z_log_msg_claim(NULL); zassert_equal(msg, NULL, "Expected no pending messages"); } /*test case main entry*/ ZTEST_SUITE(log_msg, NULL, NULL, NULL, NULL, NULL);