src/test/test-log.c

   1 /* SPDX-License-Identifier: LGPL-2.1-or-later */
   2
   3 #include "format-util.h"
   4 #include "iovec-util.h"
   5 #include "iovec-wrapper.h"
   6 #include "log.h"
   7 #include "log-context.h"
   8 #include "process-util.h"
   9 #include "string-util.h"
  10 #include "strv.h"
  11 #include "tests.h"
  12
  13 #define X10(x) x x x x x x x x x x
  14 #define X100(x) X10(X10(x))
  15 #define X1000(x) X100(X10(x))
  16
  17 TEST(synthetic_errno) {
  18         ASSERT_TRUE(IS_SYNTHETIC_ERRNO(SYNTHETIC_ERRNO(EINVAL)));
  19         ASSERT_TRUE(IS_SYNTHETIC_ERRNO(SYNTHETIC_ERRNO(-EINVAL)));
  20         assert_cc(!IS_SYNTHETIC_ERRNO(EINVAL));
  21         assert_cc(!IS_SYNTHETIC_ERRNO(-EINVAL));
  22         ASSERT_TRUE(IS_SYNTHETIC_ERRNO(SYNTHETIC_ERRNO(0)));
  23         assert_cc(!IS_SYNTHETIC_ERRNO(0));
  24         ASSERT_EQ(ERRNO_VALUE(EINVAL), EINVAL);
  25         ASSERT_EQ(ERRNO_VALUE(SYNTHETIC_ERRNO(-EINVAL)), EINVAL);
  26
  27         ASSERT_ERROR(log_info_errno(SYNTHETIC_ERRNO(EUCLEAN), "foo"), EUCLEAN);
  28 }
  29
  30 static int fail_with_EINVAL(void) {
  31         assert_return(false, -EINVAL);
  32         return 0;
  33 }
  34
  35 TEST(assert_return_is_critical) {
  36         SAVE_ASSERT_RETURN_IS_CRITICAL;
  37
  38         log_set_assert_return_is_critical(false);
  39         ASSERT_ERROR(fail_with_EINVAL(), EINVAL);
  40
  41         log_set_assert_return_is_critical(true);
  42         ASSERT_RETURN_IS_CRITICAL(false, ASSERT_ERROR(fail_with_EINVAL(), EINVAL));
  43         ASSERT_TRUE(log_get_assert_return_is_critical());
  44         ASSERT_RETURN_EXPECTED(ASSERT_ERROR(fail_with_EINVAL(), EINVAL));
  45         ASSERT_TRUE(log_get_assert_return_is_critical());
  46         ASSERT_RETURN_EXPECTED_SE(fail_with_EINVAL() == -EINVAL);
  47         ASSERT_TRUE(log_get_assert_return_is_critical());
  48 }
  49
  50 TEST(file) {
  51         log_info("__FILE__: %s", __FILE__);
  52         log_info("RELATIVE_SOURCE_PATH: %s", RELATIVE_SOURCE_PATH);
  53         log_info("PROJECT_FILE: %s", PROJECT_FILE);
  54
  55         ASSERT_NOT_NULL(startswith(__FILE__, RELATIVE_SOURCE_PATH "/"));
  56 }
  57
  58 static void test_log_once_impl(void) {
  59         log_once(LOG_INFO, "This should be logged in LOG_INFO at first, then in LOG_DEBUG later.");
  60         log_once(LOG_DEBUG, "This should be logged only once in LOG_DEBUG.");
  61         ASSERT_ERROR(log_once_errno(LOG_INFO, SYNTHETIC_ERRNO(ENOANO),
  62                                  "This should be logged with errno in LOG_INFO at first, then in LOG_DEBUG later: %m"),
  63                      ENOANO);
  64         ASSERT_ERROR(log_once_errno(LOG_DEBUG, SYNTHETIC_ERRNO(EBADMSG),
  65                                     "This should be logged only once with errno in LOG_DEBUG: %m"),
  66                      EBADMSG);
  67 }
  68
  69 TEST(log_once) {
  70         for (unsigned i = 0; i < 4; i++)
  71                 test_log_once_impl();
  72 }
  73
  74 _sentinel_
  75 static void test_log_format_iovec_sentinel(
  76                 char * const *expected,
  77                 const char *format,
  78                 ...) {
  79
  80         size_t iovec_len = 20, n = 0;
  81         struct iovec *iovec = newa(struct iovec, iovec_len);
  82         va_list ap;
  83
  84         log_debug("/* %s(%s) */", __func__, strnull(format));
  85
  86         char **v = STRV_MAKE("SYSLOG_FACILITY=3",
  87                              "SYSLOG_IDENTIFIER=systemd-journald",
  88                              "_TRANSPORT=driver",
  89                              "PRIORITY=6");
  90         size_t m = strv_length(v);
  91
  92         STRV_FOREACH(s, v)
  93                 iovec[n++] = IOVEC_MAKE_STRING(*s);
  94
  95         ASSERT_EQ(n, m);
  96
  97         va_start(ap, format);
  98         DISABLE_WARNING_FORMAT_NONLITERAL;
  99         ASSERT_OK(log_format_iovec(iovec, iovec_len, &n, /* newline_separator= */ false, ENOANO, format, ap));
 100         REENABLE_WARNING;
 101         va_end(ap);
 102
 103         ASSERT_EQ(n, m + strv_length(expected));
 104
 105         for (size_t i = 0; i < n; i++)
 106                 if (i < m)
 107                         ASSERT_EQ(iovec_memcmp(&iovec[i], &IOVEC_MAKE_STRING(v[i])), 0);
 108                 else {
 109                         ASSERT_EQ(iovec_memcmp(&iovec[i], &IOVEC_MAKE_STRING(expected[i - m])), 0);
 110                         free(iovec[i].iov_base);
 111                 }
 112
 113         n = m;
 114
 115         va_start(ap, format);
 116         DISABLE_WARNING_FORMAT_NONLITERAL;
 117         ASSERT_OK(log_format_iovec(iovec, iovec_len, &n, /* newline_separator= */ true, ENOANO, format, ap));
 118         REENABLE_WARNING;
 119         va_end(ap);
 120
 121         ASSERT_EQ(n, m + strv_length(expected) * 2);
 122
 123         for (size_t i = 0; i < n; i++)
 124                 if (i < m)
 125                         ASSERT_EQ(iovec_memcmp(&iovec[i], &IOVEC_MAKE_STRING(v[i])), 0);
 126                 else if ((i - m) % 2 == 0) {
 127                         ASSERT_EQ(iovec_memcmp(&iovec[i], &IOVEC_MAKE_STRING(expected[(i - m) / 2])), 0);
 128                         free(iovec[i].iov_base);
 129                 } else
 130                         ASSERT_EQ(iovec_memcmp(&iovec[i], &IOVEC_MAKE_STRING("\n")), 0);
 131 }
 132
 133 #define test_log_format_iovec_one(...)                 \
 134         test_log_format_iovec_sentinel(__VA_ARGS__, NULL)
 135
 136 TEST(log_format_iovec) {
 137         test_log_format_iovec_one(NULL, NULL);
 138         test_log_format_iovec_one(STRV_MAKE("MESSAGE=hoge"),
 139                                   LOG_MESSAGE("hoge"));
 140         test_log_format_iovec_one(STRV_MAKE("MESSAGE=hoge: 10"),
 141                                   LOG_MESSAGE("hoge: %i", 10));
 142         test_log_format_iovec_one(STRV_MAKE("MESSAGE=hoge: 10-a", "HOGEHOGE=100-string", "FOOFOO=4-3"),
 143                                   LOG_MESSAGE("hoge: %i-%c", 10, 'a'),
 144                                   LOG_ITEM("HOGEHOGE=%zu-%s", (size_t) 100, "string"),
 145                                   LOG_ITEM("FOOFOO=%hu-%llu", (unsigned short) 4, (long long unsigned) 3));
 146 }
 147
 148 static void test_log_struct(void) {
 149         log_struct(LOG_INFO,
 150                    "MESSAGE=Waldo PID="PID_FMT" (no errno)", getpid_cached(),
 151                    "SERVICE=piepapo");
 152
 153         /* The same as above, just using LOG_MESSAGE() and LOG_ITEM(), which is generally recommended */
 154         log_struct(LOG_INFO,
 155                    LOG_MESSAGE("Waldo PID="PID_FMT" (no errno)", getpid_cached()),
 156                    LOG_ITEM("SERVICE=piepapo"));
 157
 158         log_struct_errno(LOG_INFO, EILSEQ,
 159                          LOG_MESSAGE("Waldo PID="PID_FMT": %m (normal)", getpid_cached()),
 160                          LOG_ITEM("SERVICE=piepapo"));
 161
 162         log_struct_errno(LOG_INFO, SYNTHETIC_ERRNO(EILSEQ),
 163                          LOG_MESSAGE("Waldo PID="PID_FMT": %m (synthetic)", getpid_cached()),
 164                          LOG_ITEM("SERVICE=piepapo"));
 165
 166         log_struct(LOG_INFO,
 167                    LOG_MESSAGE("Foobar PID="PID_FMT, getpid_cached()),
 168                    LOG_ITEM("FORMAT_STR_TEST=1=%i A=%c 2=%hi 3=%li 4=%lli 1=%p foo=%s 2.5=%g 3.5=%g 4.5=%Lg",
 169                             (int) 1, 'A', (short) 2, (long) 3, (long long) 4, (void*) 1, "foo", (float) 2.5f, (double) 3.5, (long double) 4.5),
 170                    LOG_ITEM("SUFFIX=GOT IT"));
 171 }
 172
 173 static void test_long_lines(void) {
 174         log_object_internal(LOG_NOTICE,
 175                             EUCLEAN,
 176                             X1000("abcd_") ".txt",
 177                             1000000,
 178                             X1000("fff") "unc",
 179                             "OBJECT=",
 180                             X1000("obj_") "ect",
 181                             "EXTRA=",
 182                             X1000("ext_") "tra",
 183                             "asdfasdf %s asdfasdfa", "foobar");
 184 }
 185
 186 static void test_log_syntax(void) {
 187         ASSERT_ERROR(log_syntax("unit", LOG_ERR, "filename", 10, EINVAL, "EINVAL: %s: %m", "hogehoge"), EINVAL);
 188         ASSERT_ERROR(log_syntax("unit", LOG_ERR, "filename", 10, -ENOENT, "ENOENT: %s: %m", "hogehoge"), ENOENT);
 189         ASSERT_ERROR(log_syntax("unit", LOG_ERR, "filename", 10, SYNTHETIC_ERRNO(ENOTTY), "ENOTTY: %s: %m", "hogehoge"), ENOTTY);
 190 }
 191
 192 static void test_log_context(void) {
 193         {
 194                 char **strv = STRV_MAKE("FIRST=abc", "SECOND=qrs");
 195
 196                 LOG_CONTEXT_PUSH("THIRD=pfs");
 197                 LOG_CONTEXT_PUSH("FOURTH=def");
 198                 LOG_CONTEXT_PUSH_STRV(strv);
 199                 LOG_CONTEXT_PUSH_STRV(strv);
 200
 201                 /* Test that the log context was set up correctly. The strv we pushed twice should only
 202                  * result in one log context which is reused. */
 203                 ASSERT_EQ(log_context_num_contexts(), 3U);
 204                 ASSERT_EQ(log_context_num_fields(), 4U);
 205
 206                 /* Test that everything still works with modifications to the log context. */
 207                 test_log_struct();
 208                 test_long_lines();
 209                 test_log_syntax();
 210
 211                 {
 212                         LOG_CONTEXT_PUSH("FIFTH=123");
 213                         LOG_CONTEXT_PUSH_STRV(strv);
 214
 215                         /* Check that our nested fields got added correctly. */
 216                         ASSERT_EQ(log_context_num_contexts(), 4U);
 217                         ASSERT_EQ(log_context_num_fields(), 5U);
 218
 219                         /* Test that everything still works in a nested block. */
 220                         test_log_struct();
 221                         test_long_lines();
 222                         test_log_syntax();
 223                 }
 224
 225                 /* Check that only the fields from the nested block got removed. */
 226                 ASSERT_EQ(log_context_num_contexts(), 3U);
 227                 ASSERT_EQ(log_context_num_fields(), 4U);
 228         }
 229
 230         ASSERT_EQ(log_context_num_contexts(), 0U);
 231         ASSERT_EQ(log_context_num_fields(), 0U);
 232
 233         {
 234                 _cleanup_(log_context_unrefp) LogContext *ctx = NULL;
 235
 236                 char **strv = STRV_MAKE("SIXTH=ijn", "SEVENTH=PRP");
 237                 ASSERT_NOT_NULL(ctx = log_context_new_strv(strv, /* owned= */ false));
 238
 239                 ASSERT_EQ(log_context_num_contexts(), 1U);
 240                 ASSERT_EQ(log_context_num_fields(), 2U);
 241
 242                 /* Test that everything still works with a manually configured log context. */
 243                 test_log_struct();
 244                 test_long_lines();
 245                 test_log_syntax();
 246         }
 247
 248         {
 249                 char **strv = NULL;
 250
 251                 ASSERT_NOT_NULL(strv = strv_new("ABC", "DEF"));
 252                 LOG_CONTEXT_CONSUME_STRV(strv);
 253
 254                 ASSERT_EQ(log_context_num_contexts(), 1U);
 255                 ASSERT_EQ(log_context_num_fields(), 2U);
 256         }
 257
 258         {
 259                 /* Test that everything still works with a mixed strv and iov. */
 260                 struct iovec iov[] = {
 261                         IOVEC_MAKE_STRING("ABC=def"),
 262                         IOVEC_MAKE_STRING("GHI=jkl"),
 263                 };
 264                 _cleanup_free_ struct iovec_wrapper *iovw = NULL;
 265                 ASSERT_NOT_NULL(iovw = iovw_new());
 266                 ASSERT_OK(iovw_consume(iovw, strdup("MNO=pqr"), STRLEN("MNO=pqr") + 1));
 267
 268                 LOG_CONTEXT_PUSH_IOV(iov, ELEMENTSOF(iov));
 269                 LOG_CONTEXT_PUSH_IOV(iov, ELEMENTSOF(iov));
 270                 LOG_CONTEXT_CONSUME_IOV(iovw->iovec, iovw->count);
 271                 LOG_CONTEXT_PUSH("STU=vwx");
 272
 273                 ASSERT_EQ(log_context_num_contexts(), 3U);
 274                 ASSERT_EQ(log_context_num_fields(), 4U);
 275
 276                 test_log_struct();
 277                 test_long_lines();
 278                 test_log_syntax();
 279         }
 280
 281         {
 282                 LOG_CONTEXT_PUSH_KEY_VALUE("ABC=", "QED");
 283                 LOG_CONTEXT_PUSH_KEY_VALUE("ABC=", "QED");
 284                 ASSERT_EQ(log_context_num_contexts(), 1U);
 285                 ASSERT_EQ(log_context_num_fields(), 1U);
 286
 287                 test_log_struct();
 288                 test_long_lines();
 289                 test_log_syntax();
 290         }
 291
 292         ASSERT_EQ(log_context_num_contexts(), 0U);
 293         ASSERT_EQ(log_context_num_fields(), 0U);
 294 }
 295
 296 static void test_log_prefix(void) {
 297         {
 298                 LOG_SET_PREFIX("ABC");
 299
 300                 test_log_struct();
 301                 test_long_lines();
 302                 test_log_syntax();
 303
 304                 {
 305                         LOG_SET_PREFIX("QED");
 306
 307                         test_log_struct();
 308                         test_long_lines();
 309                         test_log_syntax();
 310                 }
 311
 312                 test_log_struct();
 313                 test_long_lines();
 314                 test_log_syntax();
 315         }
 316
 317         test_log_struct();
 318         test_long_lines();
 319         test_log_syntax();
 320 }
 321
 322 TEST(log_target) {
 323         for (int target = 0; target < _LOG_TARGET_MAX; target++) {
 324                 log_set_target(target);
 325                 log_open();
 326
 327                 test_log_struct();
 328                 test_long_lines();
 329                 test_log_syntax();
 330                 test_log_context();
 331                 test_log_prefix();
 332         }
 333 }
 334
 335 DEFINE_TEST_MAIN(LOG_DEBUG);