src/tests/logprint.c

   1 // C
   2 #include <assert.h>
   3 #include <time.h>
   4
   5 // DLog
   6 #include <dlogutil-internal.h>
   7 #include <logprint.h>
   8 #include <ptrs_list.h>
   9
  10 static char buffer[10240];
  11 static size_t buffer_count = 0;
  12 static bool fake_write;
  13 static int partial_write;
  14 ssize_t __real_write(int fd, const void *buf, size_t count);
  15 ssize_t __wrap_write(int fd, const void *buf, size_t count)
  16 {
  17         if (partial_write)
  18                 return partial_write;
  19
  20         if (!fake_write)
  21                 return __real_write(fd, buf, count);
  22
  23         assert(count < sizeof buffer);
  24         memcpy(buffer, buf, count);
  25         buffer[count] = '\0';
  26         buffer_count = count;
  27
  28         return count;
  29 }
  30
  31 static bool fail_localtime_r;
  32 struct tm *__real_localtime_r(const time_t *timep, struct tm *result);
  33 struct tm *__wrap_localtime_r(const time_t *timep, struct tm *result)
  34 {
  35         return fail_localtime_r ? NULL : __real_localtime_r(timep, result);
  36 }
  37
  38 static int fail_alloc;
  39 void *__real_malloc(size_t size);
  40 void *__real_calloc(size_t nmemb, size_t size);
  41 void *__wrap_malloc(size_t size)
  42 {
  43         if (fail_alloc) {
  44                 assert(size > 512);
  45                 return NULL;
  46         }
  47
  48         return __real_malloc(size);
  49 }
  50 void *__wrap_calloc(size_t nmemb, size_t size)
  51 {
  52         return fail_alloc ? NULL : __real_calloc(nmemb, size);
  53 }
  54
  55 static bool fail_strndup;
  56 char *__real_strndup(const char *s, size_t n);
  57 char *__wrap_strndup(const char *s, size_t n)
  58 {
  59         return fail_strndup ? NULL : __real_strndup(s, n);
  60 }
  61
  62 static bool fail_strdup;
  63 char *__real_strdup(const char *s);
  64 char *__wrap_strdup(const char *s)
  65 {
  66         return fail_strdup ? NULL : __real_strdup(s);
  67 }
  68
  69 static bool fail_list_add;
  70 bool __real_list_add(list_head *head, elem_value value);
  71 bool __wrap_list_add(list_head *head, elem_value value)
  72 {
  73         return fail_list_add ? false : __real_list_add(head, value);
  74 }
  75
  76 /* Timestamps are shown in the everyday format so
  77  * it's good to be able to work with those numbers
  78  * where possible instead of the underlying single
  79  * integer (but see below). */
  80
  81 #define SECONDS 1 // the base unit of the sec timestamp
  82 #define MINUTES (60 * SECONDS)
  83 #define HOURS   (60 * MINUTES)
  84 #define DAYS    (24 * HOURS)
  85
  86 #define JANUARY  (-1 * DAYS) // dates start from Jan 01, not Jan 00
  87 #define FEBRUARY (JANUARY  + 31 * DAYS)
  88 #define MARCH    (FEBRUARY + 28 * DAYS) // 1970, so no 29th
  89
  90 /* The nano timestamp is a bit more of a monolith,
  91  * but can still be meaningfully split up into the
  92  * milliseconds part and the remainder since all
  93  * timestamps seem to only show the former. */
  94
  95 #define  NANOSECONDS 1
  96 #define MICROSECONDS (1000 * NANOSECONDS)
  97 #define MILLISECONDS (1000 * MICROSECONDS)
  98
  99 static void standard_test_msg(struct dlogutil_entry_with_msg *entry, const char *msg, size_t msg_len)
 100 {
 101         *entry = (struct dlogutil_entry_with_msg) {
 102                 .header = {
 103                         .len            = sizeof entry->header + msg_len,
 104                         .priority       = DLOG_INFO,
 105                         .pid            = 4228,
 106                         .tid            = 4567,
 107                         .sec_sent_mono  = 3205048,
 108                         .sec_sent_real  =    MARCH + 14*DAYS + 23*HOURS + 22*MINUTES + 51*SECONDS,
 109                         .sec_recv_mono  = 365467,
 110                         .sec_recv_real  = FEBRUARY +  1*DAYS +  0*HOURS +  5*MINUTES + 17*SECONDS,
 111                         .nsec_sent_mono = 235*MILLISECONDS + 123*MICROSECONDS + 213*NANOSECONDS,
 112                         .nsec_sent_real = 451*MILLISECONDS + 435*MICROSECONDS + 135*NANOSECONDS,
 113                         .nsec_recv_mono = 346*MILLISECONDS + 253*MICROSECONDS + 662*NANOSECONDS,
 114                         .nsec_recv_real = 734*MILLISECONDS + 543*MICROSECONDS + 254*NANOSECONDS,
 115                         .tag_len        = -1,
 116                 },
 117         };
 118
 119         memcpy(entry->msg, msg, msg_len); // strcpy won't do because msg has an embedded \0 as the tag delimiter
 120         for (size_t i = 0; i < msg_len; ++i)
 121                 if (!msg[i]) {
 122                         entry->header.tag_len = i;
 123                         break;
 124                 }
 125         assert(entry->header.tag_len >= 0);
 126
 127         /* Despite the comment about the single int above,
 128          * sometimes we still have to work with it. Make
 129          * sure we know the other representation in each
 130          * case so that we can easily identify failures. */
 131         assert(entry->header.sec_sent_mono == FEBRUARY +  7*DAYS +  2*HOURS + 17*MINUTES + 28*SECONDS);
 132         assert(entry->header.sec_sent_real == 6304971);
 133         assert(entry->header.sec_recv_mono ==  JANUARY +  5*DAYS +  5*HOURS + 31*MINUTES +  7*SECONDS);
 134         assert(entry->header.sec_recv_real == 2678717);
 135 }
 136
 137 static void invalid_test_msg(struct dlogutil_entry_with_msg *entry, const char *msg, size_t msg_len)
 138 {
 139         standard_test_msg(entry, msg, msg_len);
 140
 141         entry->header.pid = -123;
 142         entry->header.tid = -456;
 143         entry->header.nsec_sent_mono = -78;
 144         entry->header.nsec_sent_real = -90;
 145
 146         fixup_pipe_msg(entry, msg_len);
 147 }
 148
 149 struct logprint_test_case {
 150         log_print_format format;
 151         log_priority priority;
 152         bool color_enabled;
 153         const char *result;
 154 };
 155
 156 void check_logprint_testcases(struct dlogutil_entry_with_msg *entry, const struct logprint_test_case *tests, size_t tests_n)
 157 {
 158         fake_write = true;
 159
 160         for (size_t i = 0; i < tests_n; ++i) {
 161                 entry->header.priority = tests[i].priority;
 162                 assert(log_print_log_line((struct log_format){
 163                         .format = tests[i].format,
 164                         .color = tests[i].color_enabled,
 165                 }, 0, &entry->header) > 0);
 166                 fprintf(stderr, "format=%d, expected %s<, got %s<", tests[i].format, tests[i].result, buffer);
 167                 assert(!strcmp(tests[i].result, buffer));
 168         }
 169
 170         fake_write = false;
 171 }
 172
 173 void check_logprint_testcases_standard(const char *msg, size_t msg_len, const struct logprint_test_case *tests, size_t tests_n)
 174 {
 175         struct dlogutil_entry_with_msg entry;
 176         standard_test_msg(&entry, msg, msg_len);
 177
 178         check_logprint_testcases(&entry, tests, tests_n);
 179 }
 180
 181 void check_logprint_testcases_invalid(const char *msg, size_t msg_len, const struct logprint_test_case *tests, size_t tests_n)
 182 {
 183         struct dlogutil_entry_with_msg entry;
 184         invalid_test_msg(&entry, msg, msg_len);
 185
 186         check_logprint_testcases(&entry, tests, tests_n);
 187 }
 188
 189 #define CHECK_LOGPRINT_TESTCASES(MSG, TESTS) check_logprint_testcases_standard(MSG, sizeof MSG, TESTS, NELEMS(TESTS))
 190 #define CHECK_LOGPRINT_TESTCASES_INVALID(MSG, TESTS) check_logprint_testcases_invalid(MSG, sizeof MSG, TESTS, NELEMS(TESTS))
 191
 192 void check_log_print_log_line()
 193 {
 194         static const struct logprint_test_case tests_basic[] = {
 195                 // formats using the SENT timestamp
 196                 {FORMAT_TIME         , DLOG_INFO, false, "03-14 23:22:51.451+0000 I/BASIC TAG( 4228): Basic message.\n"             },
 197                 {FORMAT_LONG         , DLOG_INFO, false, "[ 03-14 23:22:51.451 I/BASIC TAG P 4228, T 4567]\nBasic message.\n\n"     },
 198                 {FORMAT_THREADTIME   , DLOG_INFO, false, "03-14 23:22:51.451+0000 I/BASIC TAG(P 4228, T 4567): Basic message.\n"    },
 199                 {FORMAT_KERNELTIME   , DLOG_INFO, false, "3205048.235 I/BASIC TAG(P 4228, T 4567): Basic message.\n"                },
 200
 201                 // formats using the RECV timestamp
 202                 {FORMAT_RECV_REALTIME, DLOG_INFO, false, "02-01 00:05:17.734 I/BASIC TAG(P 4228, T 4567): Basic message.\n"         },
 203                 {FORMAT_RWTIME       , DLOG_INFO, false, "02-01 00:05:17 [3205048.235] I/BASIC TAG(P 4228, T 4567): Basic message.\n"},
 204
 205                 // formats without a timestamp
 206                 {FORMAT_BRIEF        , DLOG_INFO, false, "I/BASIC TAG( 4228): Basic message.\n"                                     },
 207                 {FORMAT_PROCESS      , DLOG_INFO, false, "I( 4228) Basic message.  (BASIC TAG)\n"                                   },
 208                 {FORMAT_TAG          , DLOG_INFO, false, "I/BASIC TAG: Basic message.\n"                                            },
 209                 {FORMAT_THREAD       , DLOG_INFO, false, "I(P 4228, T 4567) Basic message.\n"                                       },
 210                 {FORMAT_RAW          , DLOG_INFO, false, "Basic message.\n"                                                         },
 211                 // JSON
 212                 {FORMAT_JSON         , DLOG_INFO, false, "{" \
 213                         "\"priority\":\"info\"," \
 214                         "\"pid\":4228," \
 215                         "\"tid\":4567," \
 216                         "\"recv_real\":\"1970-02-01T00:05:17+0000\"," \
 217                         "\"recv_mono\":365467.346253662," \
 218                         "\"sent_real\":\"1970-03-14T23:22:51+0000\"," \
 219                         "\"sent_mono\":3205048.235123213," \
 220                         "\"tag\":\"BASIC TAG\"," \
 221                         "\"msg\":\"Basic message.\"" \
 222                 "}\n"},
 223         };
 224         CHECK_LOGPRINT_TESTCASES("BASIC TAG\0Basic message.", tests_basic);
 225
 226         // Color coded headers
 227         static const struct logprint_test_case tests_colors[] = {
 228                 // Fatal
 229                 {FORMAT_TIME         , DLOG_FATAL, true, "\033[35;1m03-14 23:22:51.451+0000 F/COLORFUL TAG( 4228): \033[0mBasic message.\n"             },
 230                 {FORMAT_LONG         , DLOG_FATAL, true, "\033[35;1m[ 03-14 23:22:51.451 F/COLORFUL TAG P 4228, T 4567]\n\033[0mBasic message.\n\n"     },
 231                 {FORMAT_THREADTIME   , DLOG_FATAL, true, "\033[35;1m03-14 23:22:51.451+0000 F/COLORFUL TAG(P 4228, T 4567): \033[0mBasic message.\n"    },
 232                 {FORMAT_KERNELTIME   , DLOG_FATAL, true, "\033[35;1m3205048.235 F/COLORFUL TAG(P 4228, T 4567): \033[0mBasic message.\n"                },
 233                 {FORMAT_RECV_REALTIME, DLOG_FATAL, true, "\033[35;1m02-01 00:05:17.734 F/COLORFUL TAG(P 4228, T 4567): \033[0mBasic message.\n"         },
 234                 {FORMAT_RWTIME       , DLOG_FATAL, true, "\033[35;1m02-01 00:05:17 [3205048.235] F/COLORFUL TAG(P 4228, T 4567): \033[0mBasic message.\n"},
 235                 {FORMAT_BRIEF        , DLOG_FATAL, true, "\033[35;1mF/COLORFUL TAG( 4228): \033[0mBasic message.\n"                                     },
 236                 {FORMAT_PROCESS      , DLOG_FATAL, true, "\033[35;1mF( 4228) \033[0mBasic message.\033[35;1m  (COLORFUL TAG)\n\033[0m"                  },
 237                 {FORMAT_TAG          , DLOG_FATAL, true, "\033[35;1mF/COLORFUL TAG: \033[0mBasic message.\n"                                            },
 238                 {FORMAT_THREAD       , DLOG_FATAL, true, "\033[35;1mF(P 4228, T 4567) \033[0mBasic message.\n"                                          },
 239                 {FORMAT_RAW          , DLOG_FATAL, true, "Basic message.\n"                                                                             },
 240
 241                 // Error
 242                 {FORMAT_TIME         , DLOG_ERROR, true, "\033[31;1m03-14 23:22:51.451+0000 E/COLORFUL TAG( 4228): \033[0mBasic message.\n"             },
 243                 {FORMAT_LONG         , DLOG_ERROR, true, "\033[31;1m[ 03-14 23:22:51.451 E/COLORFUL TAG P 4228, T 4567]\n\033[0mBasic message.\n\n"     },
 244                 {FORMAT_THREADTIME   , DLOG_ERROR, true, "\033[31;1m03-14 23:22:51.451+0000 E/COLORFUL TAG(P 4228, T 4567): \033[0mBasic message.\n"    },
 245                 {FORMAT_KERNELTIME   , DLOG_ERROR, true, "\033[31;1m3205048.235 E/COLORFUL TAG(P 4228, T 4567): \033[0mBasic message.\n"                },
 246                 {FORMAT_RECV_REALTIME, DLOG_ERROR, true, "\033[31;1m02-01 00:05:17.734 E/COLORFUL TAG(P 4228, T 4567): \033[0mBasic message.\n"         },
 247                 {FORMAT_RWTIME       , DLOG_ERROR, true, "\033[31;1m02-01 00:05:17 [3205048.235] E/COLORFUL TAG(P 4228, T 4567): \033[0mBasic message.\n"},
 248                 {FORMAT_BRIEF        , DLOG_ERROR, true, "\033[31;1mE/COLORFUL TAG( 4228): \033[0mBasic message.\n"                                     },
 249                 {FORMAT_PROCESS      , DLOG_ERROR, true, "\033[31;1mE( 4228) \033[0mBasic message.\033[31;1m  (COLORFUL TAG)\n\033[0m"                  },
 250                 {FORMAT_TAG          , DLOG_ERROR, true, "\033[31;1mE/COLORFUL TAG: \033[0mBasic message.\n"                                            },
 251                 {FORMAT_THREAD       , DLOG_ERROR, true, "\033[31;1mE(P 4228, T 4567) \033[0mBasic message.\n"                                          },
 252                 {FORMAT_RAW          , DLOG_ERROR, true, "Basic message.\n"                                                                             },
 253
 254                 // Warning
 255                 {FORMAT_TIME         , DLOG_WARN , true, "\033[33;1m03-14 23:22:51.451+0000 W/COLORFUL TAG( 4228): \033[0mBasic message.\n"             },
 256                 {FORMAT_LONG         , DLOG_WARN , true, "\033[33;1m[ 03-14 23:22:51.451 W/COLORFUL TAG P 4228, T 4567]\n\033[0mBasic message.\n\n"     },
 257                 {FORMAT_THREADTIME   , DLOG_WARN , true, "\033[33;1m03-14 23:22:51.451+0000 W/COLORFUL TAG(P 4228, T 4567): \033[0mBasic message.\n"    },
 258                 {FORMAT_KERNELTIME   , DLOG_WARN , true, "\033[33;1m3205048.235 W/COLORFUL TAG(P 4228, T 4567): \033[0mBasic message.\n"                },
 259                 {FORMAT_RECV_REALTIME, DLOG_WARN , true, "\033[33;1m02-01 00:05:17.734 W/COLORFUL TAG(P 4228, T 4567): \033[0mBasic message.\n"         },
 260                 {FORMAT_RWTIME       , DLOG_WARN , true, "\033[33;1m02-01 00:05:17 [3205048.235] W/COLORFUL TAG(P 4228, T 4567): \033[0mBasic message.\n"},
 261                 {FORMAT_BRIEF        , DLOG_WARN , true, "\033[33;1mW/COLORFUL TAG( 4228): \033[0mBasic message.\n"                                     },
 262                 {FORMAT_PROCESS      , DLOG_WARN , true, "\033[33;1mW( 4228) \033[0mBasic message.\033[33;1m  (COLORFUL TAG)\n\033[0m"                  },
 263                 {FORMAT_TAG          , DLOG_WARN , true, "\033[33;1mW/COLORFUL TAG: \033[0mBasic message.\n"                                            },
 264                 {FORMAT_THREAD       , DLOG_WARN , true, "\033[33;1mW(P 4228, T 4567) \033[0mBasic message.\n"                                          },
 265                 {FORMAT_RAW          , DLOG_WARN , true, "Basic message.\n"                                                                             },
 266
 267                 // Information -- no color coding needed
 268                 {FORMAT_TIME         , DLOG_INFO , true , "03-14 23:22:51.451+0000 I/COLORFUL TAG( 4228): Basic message.\n"             },
 269                 {FORMAT_LONG         , DLOG_INFO , true , "[ 03-14 23:22:51.451 I/COLORFUL TAG P 4228, T 4567]\nBasic message.\n\n"     },
 270                 {FORMAT_THREADTIME   , DLOG_INFO , true , "03-14 23:22:51.451+0000 I/COLORFUL TAG(P 4228, T 4567): Basic message.\n"    },
 271                 {FORMAT_KERNELTIME   , DLOG_INFO , true , "3205048.235 I/COLORFUL TAG(P 4228, T 4567): Basic message.\n"                },
 272                 {FORMAT_RECV_REALTIME, DLOG_INFO , true , "02-01 00:05:17.734 I/COLORFUL TAG(P 4228, T 4567): Basic message.\n"         },
 273                 {FORMAT_RWTIME       , DLOG_INFO , true , "02-01 00:05:17 [3205048.235] I/COLORFUL TAG(P 4228, T 4567): Basic message.\n"},
 274                 {FORMAT_BRIEF        , DLOG_INFO , true , "I/COLORFUL TAG( 4228): Basic message.\n"                                     },
 275                 {FORMAT_PROCESS      , DLOG_INFO , true , "I( 4228) Basic message.  (COLORFUL TAG)\n"                                   },
 276                 {FORMAT_TAG          , DLOG_INFO , true , "I/COLORFUL TAG: Basic message.\n"                                            },
 277                 {FORMAT_THREAD       , DLOG_INFO , true , "I(P 4228, T 4567) Basic message.\n"                                          },
 278                 {FORMAT_RAW          , DLOG_INFO , true , "Basic message.\n"                                                            },
 279
 280                 // Color coding disabled
 281                 {FORMAT_TIME         , DLOG_FATAL, false, "03-14 23:22:51.451+0000 F/COLORFUL TAG( 4228): Basic message.\n"             },
 282         };
 283         CHECK_LOGPRINT_TESTCASES("COLORFUL TAG\0Basic message.", tests_colors);
 284
 285         // Empty tag has special handling and gets replaced.
 286         static const struct logprint_test_case tests_tagless[] = {
 287                 // formats using the SENT timestamp
 288                 {FORMAT_RECV_REALTIME, DLOG_INFO, false, "02-01 00:05:17.734 I/DLOG_ERROR_NOTAG(P 4228, T 4567): Tagless\n"},
 289                 {FORMAT_BRIEF        , DLOG_INFO, false, "I/DLOG_ERROR_NOTAG( 4228): Tagless\n"                            },
 290                 {FORMAT_PROCESS      , DLOG_INFO, false, "I( 4228) Tagless  (DLOG_ERROR_NOTAG)\n"                          },
 291         };
 292         CHECK_LOGPRINT_TESTCASES("\0Tagless", tests_tagless);
 293
 294         /* Some formats insert the extra info (timestamp, tag etc) every time they
 295          * find a line break. The tag itself is never broken up though. */
 296         static const struct logprint_test_case tests_linebreak[] = {
 297                 {FORMAT_LONG, DLOG_INFO, false,
 298                         "[ 03-14 23:22:51.451 I/THIS\nTAG\nTAKES\nMULTIPLE\nLINES P 4228, T 4567]\n"
 299                         "And\nso\ndoes\nthis\nmessage.\n\n" },
 300                 {FORMAT_KERNELTIME, DLOG_INFO, false,
 301                         "3205048.235 I/THIS\nTAG\nTAKES\nMULTIPLE\nLINES(P 4228, T 4567): And\n"
 302                         "3205048.235 I/THIS\nTAG\nTAKES\nMULTIPLE\nLINES(P 4228, T 4567): so\n"
 303                         "3205048.235 I/THIS\nTAG\nTAKES\nMULTIPLE\nLINES(P 4228, T 4567): does\n"
 304                         "3205048.235 I/THIS\nTAG\nTAKES\nMULTIPLE\nLINES(P 4228, T 4567): this\n"
 305                         "3205048.235 I/THIS\nTAG\nTAKES\nMULTIPLE\nLINES(P 4228, T 4567): message.\n" },
 306                 {FORMAT_RECV_REALTIME, DLOG_INFO, false,
 307                         "02-01 00:05:17.734 I/THIS\nTAG\nTAKES\nMULTIPLE\nLINES(P 4228, T 4567): And\n"
 308                         "02-01 00:05:17.734 I/THIS\nTAG\nTAKES\nMULTIPLE\nLINES(P 4228, T 4567): so\n"
 309                         "02-01 00:05:17.734 I/THIS\nTAG\nTAKES\nMULTIPLE\nLINES(P 4228, T 4567): does\n"
 310                         "02-01 00:05:17.734 I/THIS\nTAG\nTAKES\nMULTIPLE\nLINES(P 4228, T 4567): this\n"
 311                         "02-01 00:05:17.734 I/THIS\nTAG\nTAKES\nMULTIPLE\nLINES(P 4228, T 4567): message.\n" },
 312                 {FORMAT_PROCESS, DLOG_INFO, false,
 313                         "I( 4228) And  (THIS\nTAG\nTAKES\nMULTIPLE\nLINES)\n"
 314                         "I( 4228) so  (THIS\nTAG\nTAKES\nMULTIPLE\nLINES)\n"
 315                         "I( 4228) does  (THIS\nTAG\nTAKES\nMULTIPLE\nLINES)\n"
 316                         "I( 4228) this  (THIS\nTAG\nTAKES\nMULTIPLE\nLINES)\n"
 317                         "I( 4228) message.  (THIS\nTAG\nTAKES\nMULTIPLE\nLINES)\n" },
 318         };
 319         CHECK_LOGPRINT_TESTCASES("THIS\nTAG\nTAKES\nMULTIPLE\nLINES\0And\nso\ndoes\nthis\nmessage.", tests_linebreak);
 320
 321         /* The extras' length gets to be capped (regardless
 322          * of which side of the message they are put on). */
 323         static const struct logprint_test_case tests_long_metadata[] = {
 324                 // Uncolored
 325                 {FORMAT_LONG, DLOG_INFO, false,
 326                         "[ 03-14 23:22:51.451 I/THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS"
 327                         "foo1\nfoo2\n\n" },
 328                 {FORMAT_KERNELTIME, DLOG_INFO, false,
 329                         "3205048.235 I/THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTfoo1\n"
 330                         "3205048.235 I/THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTfoo2\n" },
 331                 {FORMAT_RECV_REALTIME, DLOG_INFO, false,
 332                         "02-01 00:05:17.734 I/THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS Ifoo1\n"
 333                         "02-01 00:05:17.734 I/THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS Ifoo2\n" },
 334                 {FORMAT_PROCESS, DLOG_INFO, false,
 335                         "I( 4228) foo1  (THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TA"
 336                         "I( 4228) foo2  (THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TA" },
 337
 338                 // Colored
 339                 {FORMAT_LONG, DLOG_WARN, true,
 340                         "\033[33;1m[ 03-14 23:22:51.451 W/THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS\033[0m"
 341                         "foo1\nfoo2\n\n" },
 342                 {FORMAT_KERNELTIME, DLOG_WARN, true,
 343                         "\033[33;1m3205048.235 W/THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGT\033[0mfoo1\n"
 344                         "\033[33;1m3205048.235 W/THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGT\033[0mfoo2\n" },
 345                 {FORMAT_RECV_REALTIME, DLOG_WARN, true,
 346                         "\033[33;1m02-01 00:05:17.734 W/THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS I\033[0mfoo1\n"
 347                         "\033[33;1m02-01 00:05:17.734 W/THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS I\033[0mfoo2\n" },
 348                 {FORMAT_PROCESS, DLOG_WARN, true,
 349                         "\033[33;1mW( 4228) \033[0mfoo1\033[33;1m  (THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TA\033[0m"
 350                         "\033[33;1mW( 4228) \033[0mfoo2\033[33;1m  (THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TA\033[0m" },
 351         };
 352         CHECK_LOGPRINT_TESTCASES("THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH ~ THIS TAG IS OVER 128 CHARS IN LENGTH\0foo1\nfoo2", tests_long_metadata);
 353
 354         static const struct logprint_test_case tests_no_msg[] = {
 355                 {FORMAT_BRIEF  , DLOG_INFO, false, "I/SOME_TAG( 4228): DLOG_ERROR_NOMSG\n"                                    },
 356                 {FORMAT_RAW    , DLOG_INFO, false, "DLOG_ERROR_NOMSG\n"                                                       },
 357                 {FORMAT_PROCESS, DLOG_INFO, false, "I( 4228) DLOG_ERROR_NOMSG  (SOME_TAG)\n"                                  },
 358                 {FORMAT_LONG   , DLOG_INFO, false, "[ 03-14 23:22:51.451 I/SOME_TAG P 4228, T 4567]\n"
 359                                                    "DLOG_ERROR_NOMSG\n\n"                                                     },
 360
 361                 {FORMAT_BRIEF  , DLOG_WARN,  true, "\033[33;1mW/SOME_TAG( 4228): \033[0mDLOG_ERROR_NOMSG\n"                   },
 362                 {FORMAT_RAW    , DLOG_WARN,  true, "DLOG_ERROR_NOMSG\n"                                                       },
 363                 {FORMAT_PROCESS, DLOG_WARN,  true, "\033[33;1mW( 4228) \033[0mDLOG_ERROR_NOMSG\033[33;1m  (SOME_TAG)\n\033[0m"},
 364                 {FORMAT_LONG   , DLOG_WARN,  true, "\033[33;1m[ 03-14 23:22:51.451 W/SOME_TAG P 4228, T 4567]\n\033[0m"
 365                                                    "DLOG_ERROR_NOMSG\n\n"                                                     },
 366         };
 367         CHECK_LOGPRINT_TESTCASES("SOME_TAG\0", tests_no_msg);
 368
 369         static const struct logprint_test_case tests_no_nothing[] = {
 370                 {FORMAT_BRIEF  , DLOG_INFO, false, "I/DLOG_ERROR_NOTAG( 4228): DLOG_ERROR_NOMSG\n"                            },
 371                 {FORMAT_RAW    , DLOG_INFO, false, "DLOG_ERROR_NOMSG\n"                                                       },
 372                 {FORMAT_PROCESS, DLOG_INFO, false, "I( 4228) DLOG_ERROR_NOMSG  (DLOG_ERROR_NOTAG)\n"                          },
 373                 {FORMAT_LONG   , DLOG_INFO, false, "[ 03-14 23:22:51.451 I/DLOG_ERROR_NOTAG P 4228, T 4567]\n"
 374                                                    "DLOG_ERROR_NOMSG\n\n"                                                     },
 375
 376                 {FORMAT_BRIEF  , DLOG_WARN,  true, "\033[33;1mW/DLOG_ERROR_NOTAG( 4228): \033[0mDLOG_ERROR_NOMSG\n"           },
 377                 {FORMAT_RAW    , DLOG_WARN,  true, "DLOG_ERROR_NOMSG\n"                                                       },
 378                 {FORMAT_PROCESS, DLOG_WARN,  true, "\033[33;1mW( 4228) \033[0mDLOG_ERROR_NOMSG\033[33;1m  "
 379                                                    "(DLOG_ERROR_NOTAG)\n\033[0m"},
 380                 {FORMAT_LONG   , DLOG_WARN,  true, "\033[33;1m[ 03-14 23:22:51.451 W/DLOG_ERROR_NOTAG P 4228, T 4567]\n\033[0m"
 381                                                    "DLOG_ERROR_NOMSG\n\n"                                                     },
 382         };
 383         CHECK_LOGPRINT_TESTCASES("\0", tests_no_nothing);
 384
 385         static const struct logprint_test_case tests_two_zeros[] = {
 386                 {FORMAT_BRIEF  , DLOG_INFO, false, "I/DLOG_ERROR_NOTAG( 4228): DLOG_ERROR_NOMSG\n"                            },
 387                 {FORMAT_RAW    , DLOG_INFO, false, "DLOG_ERROR_NOMSG\n"                                                       },
 388                 {FORMAT_PROCESS, DLOG_INFO, false, "I( 4228) DLOG_ERROR_NOMSG  (DLOG_ERROR_NOTAG)\n"                          },
 389                 {FORMAT_LONG   , DLOG_INFO, false, "[ 03-14 23:22:51.451 I/DLOG_ERROR_NOTAG P 4228, T 4567]\n"
 390                                                    "DLOG_ERROR_NOMSG\n\n"                                                     },
 391
 392                 {FORMAT_BRIEF  , DLOG_WARN,  true, "\033[33;1mW/DLOG_ERROR_NOTAG( 4228): \033[0mDLOG_ERROR_NOMSG\n"           },
 393                 {FORMAT_RAW    , DLOG_WARN,  true, "DLOG_ERROR_NOMSG\n"                                                       },
 394                 {FORMAT_PROCESS, DLOG_WARN,  true, "\033[33;1mW( 4228) \033[0mDLOG_ERROR_NOMSG\033[33;1m  "
 395                                                    "(DLOG_ERROR_NOTAG)\n\033[0m"},
 396                 {FORMAT_LONG   , DLOG_WARN,  true, "\033[33;1m[ 03-14 23:22:51.451 W/DLOG_ERROR_NOTAG P 4228, T 4567]\n\033[0m"
 397                                                    "DLOG_ERROR_NOMSG\n\n"                                                     },
 398         };
 399         CHECK_LOGPRINT_TESTCASES("\0\0", tests_two_zeros);
 400
 401         static const struct logprint_test_case tests_garbage[] = {
 402                 {FORMAT_BRIEF  , DLOG_INFO, false, "I/DLOG_ERROR_NOTAG( 4228): DLOG_ERROR_NOMSG\n"                            },
 403                 {FORMAT_RAW    , DLOG_INFO, false, "DLOG_ERROR_NOMSG\n"                                                       },
 404                 {FORMAT_PROCESS, DLOG_INFO, false, "I( 4228) DLOG_ERROR_NOMSG  (DLOG_ERROR_NOTAG)\n"                          },
 405                 {FORMAT_LONG   , DLOG_INFO, false, "[ 03-14 23:22:51.451 I/DLOG_ERROR_NOTAG P 4228, T 4567]\n"
 406                                                    "DLOG_ERROR_NOMSG\n\n"                                                     },
 407
 408                 {FORMAT_BRIEF  , DLOG_WARN,  true, "\033[33;1mW/DLOG_ERROR_NOTAG( 4228): \033[0mDLOG_ERROR_NOMSG\n"           },
 409                 {FORMAT_RAW    , DLOG_WARN,  true, "DLOG_ERROR_NOMSG\n"                                                       },
 410                 {FORMAT_PROCESS, DLOG_WARN,  true, "\033[33;1mW( 4228) \033[0mDLOG_ERROR_NOMSG\033[33;1m  "
 411                                                    "(DLOG_ERROR_NOTAG)\n\033[0m"},
 412                 {FORMAT_LONG   , DLOG_WARN,  true, "\033[33;1m[ 03-14 23:22:51.451 W/DLOG_ERROR_NOTAG P 4228, T 4567]\n\033[0m"
 413                                                    "DLOG_ERROR_NOMSG\n\n"                                                     },
 414         };
 415         CHECK_LOGPRINT_TESTCASES("\0\0GARBAGE", tests_garbage);
 416
 417         static const struct logprint_test_case tests_only_one_zero[] = {
 418                 {FORMAT_BRIEF  , DLOG_INFO, false, "I/THIS_IS_WEIRD( 4228): DLOG_ERROR_NOMSG\n"                               },
 419                 {FORMAT_RAW    , DLOG_INFO, false, "DLOG_ERROR_NOMSG\n"                                                       },
 420                 {FORMAT_PROCESS, DLOG_INFO, false, "I( 4228) DLOG_ERROR_NOMSG  (THIS_IS_WEIRD)\n"                             },
 421                 {FORMAT_LONG   , DLOG_INFO, false, "[ 03-14 23:22:51.451 I/THIS_IS_WEIRD P 4228, T 4567]\n"
 422                                                    "DLOG_ERROR_NOMSG\n\n"                                                     },
 423
 424                 {FORMAT_BRIEF  , DLOG_WARN,  true, "\033[33;1mW/THIS_IS_WEIRD( 4228): \033[0mDLOG_ERROR_NOMSG\n"              },
 425                 {FORMAT_RAW    , DLOG_WARN,  true, "DLOG_ERROR_NOMSG\n"                                                       },
 426                 {FORMAT_PROCESS, DLOG_WARN,  true, "\033[33;1mW( 4228) \033[0mDLOG_ERROR_NOMSG\033[33;1m  "
 427                                                    "(THIS_IS_WEIRD)\n\033[0m"},
 428                 {FORMAT_LONG   , DLOG_WARN,  true, "\033[33;1m[ 03-14 23:22:51.451 W/THIS_IS_WEIRD P 4228, T 4567]\n\033[0m"
 429                                                    "DLOG_ERROR_NOMSG\n\n"                                                     },
 430         };
 431         CHECK_LOGPRINT_TESTCASES("THIS_IS_WEIRD", tests_only_one_zero);
 432
 433         static const struct logprint_test_case tests_fixup_pipe[] = {
 434                 // formats using the SENT timestamp (nominally)
 435                 {FORMAT_TIME         , DLOG_INFO, false, "02-01 00:05:17.734+0000 I/BASIC TAG(    0): Basic message.\n"
 436                                                          "[dlog inline warning: modified invalid timestamp]\n"              },
 437                 {FORMAT_LONG         , DLOG_INFO, false, "[ 02-01 00:05:17.734 I/BASIC TAG P    0, T    0]\n"
 438                                                          "Basic message.\n"
 439                                                          "[dlog inline warning: modified invalid timestamp]\n\n"                                                        },
 440                 {FORMAT_THREADTIME   , DLOG_INFO, false, "02-01 00:05:17.734+0000 I/BASIC TAG(P    0, T    0): Basic message.\n"
 441                                                          "[dlog inline warning: modified invalid timestamp]\n"     },
 442                 {FORMAT_KERNELTIME   , DLOG_INFO, false, "365467.346 I/BASIC TAG(P    0, T    0): Basic message.\n"
 443                                                          "365467.346 I/BASIC TAG(P    0, T    0): [dlog inline warning: modified invalid timestamp]\n"                  },
 444
 445                 // formats using the RECV timestamp
 446                 {FORMAT_RECV_REALTIME, DLOG_INFO, false, "02-01 00:05:17.734 I/BASIC TAG(P    0, T    0): Basic message.\n"
 447                                                          "02-01 00:05:17.734 I/BASIC TAG(P    0, T    0): [dlog inline warning: modified invalid timestamp]\n"          },
 448                 {FORMAT_RWTIME       , DLOG_INFO, false, "02-01 00:05:17 [365467.346] I/BASIC TAG(P    0, T    0): Basic message.\n"
 449                                                          "[dlog inline warning: modified invalid timestamp]\n" },
 450
 451                 // formats without a timestamp
 452                 {FORMAT_BRIEF        , DLOG_INFO, false, "I/BASIC TAG(    0): Basic message.\n"
 453                                                          "[dlog inline warning: modified invalid timestamp]\n"                                      },
 454                 {FORMAT_PROCESS      , DLOG_INFO, false, "I(    0) Basic message.  (BASIC TAG)\n"
 455                                                          "I(    0) [dlog inline warning: modified invalid timestamp]  (BASIC TAG)\n"                                    },
 456                 {FORMAT_TAG          , DLOG_INFO, false, "I/BASIC TAG: Basic message.\n"
 457                                                          "[dlog inline warning: modified invalid timestamp]\n"                                             },
 458                 {FORMAT_THREAD       , DLOG_INFO, false, "I(P    0, T    0) Basic message.\n"
 459                                                          "[dlog inline warning: modified invalid timestamp]\n"                                        },
 460                 {FORMAT_RAW          , DLOG_INFO, false, "Basic message.\n"
 461                                                          "[dlog inline warning: modified invalid timestamp]\n"                                                          },
 462                 // JSON
 463                 {FORMAT_JSON         , DLOG_INFO, false, "{" \
 464                         "\"priority\":\"info\"," \
 465                         "\"pid\":0," \
 466                         "\"tid\":0," \
 467                         "\"recv_real\":\"1970-02-01T00:05:17+0000\"," \
 468                         "\"recv_mono\":365467.346253662," \
 469                         "\"sent_real\":\"1970-02-01T00:05:17+0000\"," \
 470                         "\"sent_mono\":365467.346253662," \
 471                         "\"tag\":\"BASIC TAG\"," \
 472                         "\"msg\":\"Basic message.\\n" \
 473                                   "[dlog inline warning: modified invalid timestamp]\"" \
 474                 "}\n" },
 475         };
 476         CHECK_LOGPRINT_TESTCASES_INVALID("BASIC TAG\0Basic message.", tests_fixup_pipe);
 477 }
 478
 479 char *json_escape_string(char *in);
 480 void check_json_escape_string_testcase(char *in, char *correct)
 481 {
 482         char *out = json_escape_string(in);
 483         assert(out);
 484         assert(!strcmp(out, correct));
 485         free(out);
 486 }
 487
 488 enum ts_type {
 489         TS_SENT,
 490         TS_RECV,
 491 };
 492 const char *json_priority_name(log_priority prio);
 493 struct timespec entry_get_ts(const dlogutil_entry_s *entry, bool sent, bool mono);
 494 char *log_format_json(char *default_buffer, size_t default_buffer_size, const dlogutil_entry_s *entry, size_t *p_outLength, char *tag, char *msg);
 495 void check_json()
 496 {
 497         // TODO: Failure testing
 498         check_json_escape_string_testcase("abc/def", "abc/def");
 499         check_json_escape_string_testcase("\x01\x02\x03", "\\u0001\\u0002\\u0003");
 500         check_json_escape_string_testcase("\x1A\x1B\x1C", "\\u001A\\u001B\\u001C");
 501         check_json_escape_string_testcase("\x1D\x1E\x1F", "\\u001D\\u001E\\u001F");
 502         check_json_escape_string_testcase("\"\\\b\f\n\r\t", "\\\"\\\\\\b\\f\\n\\r\\t");
 503         check_json_escape_string_testcase("zażółć gęślą jaźń", "zażółć gęślą jaźń");
 504         check_json_escape_string_testcase("삼성", "삼성");
 505         check_json_escape_string_testcase("タイゼン", "タイゼン");
 506         check_json_escape_string_testcase("🏀", "🏀");
 507
 508         assert(!strcmp(json_priority_name(DLOG_VERBOSE), "verbose"));
 509         assert(!strcmp(json_priority_name(DLOG_DEBUG),   "debug"));
 510         assert(!strcmp(json_priority_name(DLOG_INFO),    "info"));
 511         assert(!strcmp(json_priority_name(DLOG_WARN),    "warning"));
 512         assert(!strcmp(json_priority_name(DLOG_ERROR),   "error"));
 513         assert(!strcmp(json_priority_name(DLOG_FATAL),   "fatal"));
 514         assert(!strcmp(json_priority_name(DLOG_SILENT),  "silent"));
 515         assert(!strcmp(json_priority_name(DLOG_UNKNOWN), "unknown"));
 516         assert(!strcmp(json_priority_name(123),          "unknown"));
 517
 518         char data[] = "tag\0important message";
 519         dlogutil_entry_s *ent = calloc(1, sizeof(dlogutil_entry_s) + sizeof data);
 520         assert(ent);
 521         ent->len = sizeof data;
 522         ent->tag_len = 3;
 523         strncpy(ent->msg, data, ent->len);
 524         ent->priority = DLOG_DEBUG;
 525         ent->pid = 17;
 526         ent->tid = 18;
 527
 528         struct timespec ts;
 529
 530 #define TEST_EMPTY_TIMESTAMP() \
 531         ent->nsec_sent_mono = ent->nsec_recv_mono = ent->nsec_sent_real = ent->nsec_recv_real = -1; \
 532         ts = entry_get_ts(ent, CURRENT_SENT, CURRENT_MONO); \
 533         assert(ts.tv_sec == 0); \
 534         assert(ts.tv_nsec == 0)
 535 #define TEST_SINGLE_TIMESTAMP(which, to_set, expected) \
 536         ent->sec_##which = ent->nsec_##which = to_set; \
 537         ts = entry_get_ts(ent, CURRENT_SENT, CURRENT_MONO); \
 538         assert(ts.tv_sec == expected); \
 539         assert(ts.tv_nsec == expected)
 540
 541  #define CURRENT_MONO true
 542   #define CURRENT_SENT true
 543         TEST_EMPTY_TIMESTAMP();
 544         TEST_SINGLE_TIMESTAMP(recv_real, 1, 1);
 545         TEST_SINGLE_TIMESTAMP(sent_real, 2, 2);
 546         TEST_SINGLE_TIMESTAMP(recv_mono, 3, 3);
 547         TEST_SINGLE_TIMESTAMP(sent_mono, 4, 4);
 548   #undef CURRENT_SENT
 549
 550   #define CURRENT_SENT false
 551         TEST_EMPTY_TIMESTAMP();
 552         TEST_SINGLE_TIMESTAMP(sent_real, 1, 1);
 553         TEST_SINGLE_TIMESTAMP(recv_real, 2, 2);
 554         TEST_SINGLE_TIMESTAMP(sent_mono, 3, 3);
 555         TEST_SINGLE_TIMESTAMP(recv_mono, 4, 4);
 556   #undef CURRENT_SENT
 557  #undef CURRENT_MONO
 558
 559  #define CURRENT_MONO false
 560   #define CURRENT_SENT true
 561         TEST_EMPTY_TIMESTAMP();
 562         TEST_SINGLE_TIMESTAMP(recv_mono, 1, 0);
 563         TEST_SINGLE_TIMESTAMP(sent_mono, 2, 0);
 564         TEST_SINGLE_TIMESTAMP(recv_real, 3, 3);
 565         TEST_SINGLE_TIMESTAMP(sent_real, 4, 4);
 566   #undef CURRENT_SENT
 567
 568   #define CURRENT_SENT false
 569         TEST_EMPTY_TIMESTAMP();
 570         TEST_SINGLE_TIMESTAMP(sent_mono, 1, 0);
 571         TEST_SINGLE_TIMESTAMP(recv_mono, 2, 0);
 572         TEST_SINGLE_TIMESTAMP(sent_real, 3, 3);
 573         TEST_SINGLE_TIMESTAMP(recv_real, 4, 4);
 574   #undef CURRENT_SENT
 575  #undef CURRENT_MONO
 576
 577 #undef TEST_EMPTY_TIMESTAMP
 578 #undef TEST_SINGLE_TIMESTAMP
 579
 580         char buf[512] = {};
 581         size_t out_len;
 582
 583         ent->nsec_sent_mono = ent->nsec_recv_mono = ent->nsec_sent_real = ent->nsec_recv_real = -1;
 584         assert(log_format_json(buf, sizeof(buf), ent, &out_len, "tag", "message") == buf);
 585         assert(strlen(buf) == out_len);
 586         assert(!strcmp(buf, "{" \
 587                 "\"priority\":\"debug\"," \
 588                 "\"pid\":17," \
 589                 "\"tid\":18," \
 590                 "\"tag\":\"tag\"," \
 591                 "\"msg\":\"message\"" \
 592         "}\n"));
 593
 594         char *target;
 595         target = log_format_json(NULL, out_len, ent, &out_len, "tag", "message");
 596         assert(target);
 597         assert(target != buf);
 598         assert(strlen(target) == out_len);
 599         assert(!strcmp(buf, target));
 600         free(target);
 601
 602         ent->sec_sent_mono = ent->nsec_sent_mono = 21;
 603         ent->sec_recv_mono = ent->nsec_recv_mono = 22;
 604         ent->sec_sent_real = ent->nsec_sent_real = 23242527;
 605         ent->sec_recv_real = ent->nsec_recv_real = 28293031;
 606         assert(log_format_json(buf, sizeof(buf), ent, &out_len, "tag", "message") == buf);
 607         assert(strlen(buf) == out_len);
 608         assert(!strcmp(buf, "{"\
 609                 "\"priority\":\"debug\","\
 610                 "\"pid\":17,"\
 611                 "\"tid\":18,"\
 612                 "\"recv_real\":\"1970-11-24T11:10:31+0000\","\
 613                 "\"recv_mono\":22.000000022,"\
 614                 "\"sent_real\":\"1970-09-27T00:15:27+0000\","\
 615                 "\"sent_mono\":21.000000021,"\
 616                 "\"tag\":\"tag\","\
 617                 "\"msg\":\"message\""\
 618         "}\n"));
 619
 620         char data2[] = "∫\0\x01\x02\x03\x14\x15\x16\"\\\b\f\n\r\t🤔";
 621         assert(sizeof data == sizeof data2);
 622         strncpy(ent->msg, data2, ent->len);
 623         assert(log_format_json(buf, sizeof(buf), ent, &out_len, "∫", "\x01\x02\x03\x14\x15\x16\"\\\b\f\n\r\t🤔") == buf);
 624         assert(strlen(buf) == out_len);
 625         assert(!strcmp(buf, "{"\
 626                 "\"priority\":\"debug\","\
 627                 "\"pid\":17,"\
 628                 "\"tid\":18,"\
 629                 "\"recv_real\":\"1970-11-24T11:10:31+0000\","\
 630                 "\"recv_mono\":22.000000022,"\
 631                 "\"sent_real\":\"1970-09-27T00:15:27+0000\","\
 632                 "\"sent_mono\":21.000000021,"\
 633                 "\"tag\":\"∫\","\
 634                 "\"msg\":\"\\u0001\\u0002\\u0003\\u0014\\u0015\\u0016\\\"\\\\\\b\\f\\n\\r\\t🤔\""\
 635         "}\n"));
 636
 637         free(ent);
 638 }
 639
 640 void check_syscall_failure_handling()
 641 {
 642         dlogutil_filter_options_s *const filter = log_filter_new();
 643         assert(filter);
 644         assert(!dlogutil_filter_options_set_tid(filter, 123));
 645         assert(!dlogutil_filter_options_set_pid(filter, 456));
 646         assert(!log_add_filter_rule(filter, "FOO:E"));
 647
 648         dlogutil_filter_options_s *const clone = log_filter_from_filter(filter);
 649         assert(clone);
 650         log_filter_free(clone);
 651
 652         fail_alloc = true;
 653         assert(!log_filter_new());
 654         assert(!log_filter_from_filter(filter));
 655         assert(TIZEN_ERROR_OUT_OF_MEMORY == dlogutil_filter_options_set_tid(filter, 123));
 656         assert(TIZEN_ERROR_OUT_OF_MEMORY == dlogutil_filter_options_set_pid(filter, 456));
 657         fail_alloc = false;
 658
 659         // Not really a syscall, but eh
 660         fail_list_add = true;
 661         assert(TIZEN_ERROR_OUT_OF_MEMORY == log_add_filter_rule(filter, "FOO:E"));
 662         fail_list_add = false;
 663
 664         fail_strdup = true;
 665         assert(!log_filter_from_filter(filter));
 666         assert(TIZEN_ERROR_OUT_OF_MEMORY == dlogutil_filter_options_set_filterspec(filter, "FOO:E"));
 667         assert(TIZEN_ERROR_OUT_OF_MEMORY == log_add_filter_rule(filter, "FOO:E"));
 668         fail_strdup = false;
 669
 670         fail_strndup = true; // N
 671         assert(TIZEN_ERROR_OUT_OF_MEMORY == dlogutil_filter_options_set_filterspec(filter, "FOO:E"));
 672         fail_strndup = false;
 673
 674         /* the array size is an arbitrary value between 512, i.e. the size of the default buffer,
 675          * and 4096, i.e. LOG_MAX_PAYLOAD_SIZE (higher should also work but would be pointless). */
 676         char msg[666] = {
 677                 [0 ... 41] = 'A', // tag
 678                 [42] = '\0',
 679                 [43 ... sizeof msg - 2] = 'a',  // msg
 680                 [sizeof msg - 1] = '\0'
 681         };
 682         struct dlogutil_entry_with_msg entry;
 683         standard_test_msg(&entry, msg, sizeof msg);
 684
 685         struct log_format format = {
 686                         .format = FORMAT_TIME,
 687                         .color = false,
 688         };
 689
 690         fail_alloc = true;
 691         assert(-1 == log_print_log_line(format, 0, &entry.header));
 692         fail_alloc = false;
 693
 694         fail_localtime_r = true;
 695         assert(-1 == log_print_log_line(format, 0, &entry.header));
 696         fail_localtime_r = false;
 697
 698         partial_write = -1;
 699         assert(0 == log_print_log_line(format, 0, &entry.header));
 700
 701         partial_write = 17;
 702         assert(17 == log_print_log_line(format, 0, &entry.header));
 703
 704         partial_write = 0;
 705         log_filter_free(filter);
 706 }
 707
 708 void check_invalid_input()
 709 {
 710         const dlogutil_entry_s entry = { .len = 1 };
 711         const char *data;
 712
 713         assert(dlogutil_entry_get_message(&entry, &data) == TIZEN_ERROR_NO_DATA);
 714         assert(!data);
 715
 716         assert(dlogutil_entry_get_tag(&entry, &data) == TIZEN_ERROR_NO_DATA);
 717         assert(!data);
 718
 719         dlogutil_filter_options_s *const filter = log_filter_new();
 720         assert(filter);
 721         assert(TIZEN_ERROR_INVALID_PARAMETER == log_add_filter_rule(filter, ":D")); // >mfw tagless rule gets processed correctly
 722         log_filter_free(filter);
 723 }
 724
 725 void check_log_format_from_string()
 726 {
 727         static const struct {
 728                 char const *string;
 729                 log_print_format format;
 730         } expected_formats[] = {
 731                 {"brief"          , FORMAT_BRIEF     },
 732                 {"  brief"        , FORMAT_OFF       },
 733                 {"tag"            , FORMAT_TAG       },
 734                 {"tagging up turf", FORMAT_OFF       },
 735                 {"process"        , FORMAT_PROCESS   },
 736                 {"long"           , FORMAT_LONG      },
 737                 {"thien long"     , FORMAT_OFF       },
 738                 {"threadtime"     , FORMAT_THREADTIME},
 739                 {"kerneltime"     , FORMAT_KERNELTIME},
 740                 {"hammertime"     , FORMAT_OFF       },
 741         };
 742
 743         for (size_t i = 0; i < NELEMS(expected_formats); ++i)
 744                 assert(log_format_from_string(expected_formats[i].string) == expected_formats[i].format);
 745 }
 746
 747 void check_get_format_sorting()
 748 {
 749         static const struct {
 750                 log_print_format format;
 751                 dlogutil_sorting_order_e sorting;
 752         } expected_sorting[] = {
 753                 {FORMAT_TAG          , DLOGUTIL_SORT_DEFAULT  },
 754                 {FORMAT_PROCESS      , DLOGUTIL_SORT_DEFAULT  },
 755                 {FORMAT_THREAD       , DLOGUTIL_SORT_DEFAULT  },
 756                 {FORMAT_RAW          , DLOGUTIL_SORT_DEFAULT  },
 757                 {FORMAT_BRIEF        , DLOGUTIL_SORT_DEFAULT  },
 758                 {FORMAT_TIME         , DLOGUTIL_SORT_SENT_REAL},
 759                 {FORMAT_THREADTIME   , DLOGUTIL_SORT_SENT_REAL},
 760                 {FORMAT_KERNELTIME   , DLOGUTIL_SORT_SENT_MONO},
 761                 {FORMAT_LONG         , DLOGUTIL_SORT_SENT_REAL},
 762                 {FORMAT_RWTIME       , DLOGUTIL_SORT_RECV_REAL},
 763                 {FORMAT_RECV_REALTIME, DLOGUTIL_SORT_RECV_REAL},
 764         };
 765
 766         for (size_t i = 0; i < NELEMS(expected_sorting); ++i) {
 767                 assert(get_format_sorting(expected_sorting[i].format) == expected_sorting[i].sorting);
 768         }
 769 }
 770
 771 void check_filter_pri_to_char()
 772 {
 773         static const struct {
 774                 log_priority pri;
 775                 char c;
 776         } convertibles[] = {
 777                 {DLOG_VERBOSE    , 'V' },
 778                 {DLOG_DEBUG      , 'D' },
 779                 {DLOG_INFO       , 'I' },
 780                 {DLOG_WARN       , 'W' },
 781                 {DLOG_ERROR      , 'E' },
 782                 {DLOG_FATAL      , 'F' },
 783                 {DLOG_SILENT     , 'S' },
 784         }, expected_pris[] = {
 785                 {DLOG_UNKNOWN    , '0' },
 786                 {DLOG_DEFAULT    , '1' },
 787                 {DLOG_VERBOSE    , '2' },
 788                 {DLOG_DEBUG      , '3' },
 789                 {DLOG_INFO       , '4' },
 790                 {DLOG_WARN       , '5' },
 791                 {DLOG_ERROR      , '6' },
 792                 {DLOG_FATAL      , '7' },
 793                 {DLOG_VERBOSE    , '8' }, // makes little sense but ok
 794                 {DLOG_VERBOSE    , '9' }, // ditto
 795
 796                 {DLOG_VERBOSE    , 'v' },
 797                 {DLOG_DEBUG      , 'd' },
 798                 {DLOG_INFO       , 'i' },
 799                 {DLOG_WARN       , 'w' },
 800                 {DLOG_ERROR      , 'e' },
 801                 {DLOG_FATAL      , 'f' },
 802                 {DLOG_SILENT     , 's' },
 803                 {DLOG_DEFAULT    , '*' },
 804
 805                 {DLOG_UNKNOWN    , 'l' },
 806                 {DLOG_UNKNOWN    , 'L' },
 807                 {DLOG_UNKNOWN    , ' ' },
 808                 {DLOG_UNKNOWN    , '\a'},
 809                 {DLOG_UNKNOWN    , '\0'},
 810         }, expected_chars[] = {
 811                 {DLOG_DEFAULT    , '?' },
 812                 {DLOG_UNKNOWN    , '?' },
 813                 {(log_priority)42, '?' },
 814                 {(log_priority)-9, '?' },
 815         };
 816
 817         for (size_t i = 0; i < NELEMS(convertibles); ++i) {
 818                 assert(filter_pri_to_char(convertibles[i].pri) == convertibles[i].c);
 819                 assert(filter_char_to_pri(convertibles[i].c) == convertibles[i].pri);
 820         }
 821
 822         for (size_t i = 0; i < NELEMS(expected_pris); ++i)
 823                 assert(filter_char_to_pri(expected_pris[i].c) == expected_pris[i].pri);
 824
 825         for (size_t i = 0; i < NELEMS(expected_chars); ++i)
 826                 assert(filter_pri_to_char(expected_chars[i].pri) == expected_chars[i].c);
 827 }
 828
 829 void log_filter_default()
 830 {
 831         dlogutil_filter_options_s *const filter = log_filter_new();
 832         bool ret = log_filter_need_apply_default(filter);
 833         assert(ret);
 834         log_filter_free(filter);
 835 }
 836
 837 int main()
 838 {
 839         check_log_format_from_string();
 840         check_get_format_sorting();
 841         check_filter_pri_to_char();
 842         check_log_print_log_line();
 843         check_invalid_input();
 844         check_syscall_failure_handling();
 845         check_json();
 846         log_filter_default();
 847 }