tests/dlog_test.in

   1 #!/bin/sh
   2
   3 # stuff for tracking test case counts
   4 FAILS=0
   5 OKS=0
   6 TOTAL=0
   7 LOG_DETAILS=
   8
   9 #relevant pids default vals
  10 UTIL_PID=-1
  11 DLOGSEND_PID=-1
  12 MT_TEST=-1
  13 LOGGER=-1
  14
  15 TEST_DYNAMIC_FILTERS="@DYNAMIC_FILTERS@"
  16 TESTDIR=/var/lib/dlog-tests
  17
  18 extract_timestamp() {
  19         ts=0
  20         case "$1" in
  21                 "threadtime")
  22                         time=$(echo "$2" | awk -F '[ +]' '{print $2}')
  23                         ts=$(date +%s%N -d "$time")
  24                 ;;
  25                 "long")
  26                         time=$(echo "$2" | awk -F '[ +.]' '{print $3}')
  27                         ms=$(echo "$2" | awk -F '[ +.]' '{print $4}')
  28                         sec=$(date +%s%N -d "$time")
  29                         ns=$((10#$ms * 1000000))
  30                         ts=$((sec + ns))
  31                 ;;
  32                 "rwtime")
  33                         time=$(echo "$2" | awk -F '[ +.]' '{print $2}')
  34                         ts=$(date +%s%N -d "$time")
  35                 ;;
  36                 "recv_realtime")
  37                         time=$(echo "$2" | awk -F '[ +.]' '{print $2}')
  38                         ts=$(date +%s%N -d "$time")
  39                 ;;
  40                 "time")
  41                         time=$(echo "$2" | awk -F '[ +.]' '{print $2}')
  42                         ts=$(date +%s%N -d "$time")
  43                 ;;
  44                 "kerneltime")
  45                         ts=$(echo "$2" | awk -F '[ +]' '{print $1}' | sed -e 's/\.//g')
  46                 ;;
  47         esac
  48         echo "$ts"
  49 }
  50
  51 cleanup() {
  52         [ "$UTIL_PID" -ne -1 ] && kill "$UTIL_PID" > /dev/null 2>&1
  53         [ "$MT_TEST"  -ne -1 ] && kill "$MT_TEST"  > /dev/null 2>&1
  54         [ "$LOGGER"   -ne -1 ] && kill "$LOGGER"   > /dev/null 2>&1
  55         [ -d "$TESTDIR" ] && rm -rf "$TESTDIR"/*
  56         [ -d "$RUNTIME_FILTERS_DIR" ] && rm -rf "$RUNTIME_FILTERS_DIR"
  57 }
  58
  59 trap cleanup 0
  60
  61 check_daemon() {
  62         ret=1
  63         if [ "$LOGGER" -ne -1 ] && [ -z "$(ps -o pid= -p "$LOGGER")" ]; then
  64                 ret=0
  65         fi
  66         return "$ret"
  67 }
  68
  69 fail() {
  70         check_daemon && daemon_status="[logger daemon not running]"
  71
  72         FAILS=$((FAILS + 1))
  73         TOTAL=$((TOTAL + 1))
  74         printf "[%02d] FAILED: %s %s\n" "$TOTAL" "$LOG_DETAILS" "$daemon_status"
  75         LOG_DETAILS=
  76 }
  77
  78 ok() {
  79         check_daemon && daemon_status="[logger daemon not running]"
  80
  81         OKS=$((OKS + 1))
  82         TOTAL=$((TOTAL + 1))
  83         printf "[%02d] PASSED: %s %s\n" "$TOTAL" "$LOG_DETAILS" "$daemon_status"
  84         LOG_DETAILS=
  85 }
  86
  87 # supress stderr messages from subcommands
  88 exec 2> /dev/null
  89
  90 USAGE_MESSAGE="usage: $0 pipe|logger|pipe_quick|logger_quick"
  91
  92 if [ "$#" -ne 1 ]; then
  93         echo "$USAGE_MESSAGE"
  94         exit 1
  95 fi
  96
  97 if [ "$1" = "pipe" ]; then
  98         type="pipe"
  99         quick=0
 100 elif [ "$1" = "logger" ]; then
 101         type="logger"
 102         quick=0
 103 elif [ "$1" = "pipe_quick" ]; then
 104         type="pipe"
 105         quick=1
 106 elif [ "$1" = "logger_quick" ]; then
 107         type="logger"
 108         quick=1
 109 else
 110         echo "$USAGE_MESSAGE"
 111         exit 1
 112 fi
 113
 114 NEEDS_TO_QUIT=0
 115 capsh --print | grep Current | grep cap_syslog > /dev/null || { echo "*** ERROR: cap_syslog missing"; NEEDS_TO_QUIT=1; }
 116 mount | grep ' / ' | grep rw > /dev/null || { echo "*** ERROR: root not mounted read-write"; NEEDS_TO_QUIT=1; }
 117 [ "$NEEDS_TO_QUIT" -eq 0 ] || exit 1
 118
 119 if [ -z "$DLOG_CONFIG_PATH" ]; then
 120         ORIGINAL_CONFIG_PATH="/etc/dlog.conf"
 121 else
 122         ORIGINAL_CONFIG_PATH="$DLOG_CONFIG_PATH"
 123 fi
 124
 125 export DLOG_CONFIG_PATH="@datadir@/dlog-$type.conf.test"
 126 PATH=$PATH:@libexecdir@/libdlog/
 127
 128 #create dir for runtime filters
 129 RUNTIME_FILTERS_DIR="/tmp/dlog-filters/"
 130 mkdir -p "$RUNTIME_FILTERS_DIR"
 131
 132 # Start the daemon
 133 if [ "$type" = "pipe" ]; then
 134         dlog_logger &
 135         dlog_logger -b 99 -t 0 &
 136         LOGGER=$!
 137         sleep 1
 138 fi
 139
 140 if [ "$TEST_DYNAMIC_FILTERS" = "true" ]; then
 141         dlogctl -c
 142         dlogctl --enable
 143         dlogutil -c -b radio -b system -b main
 144         LOG_DETAILS="dlogctl --disable (no args)"
 145         dlogctl --disable
 146         [ "$(dlogctl -g | grep ENABLED | wc -l)" -eq 0 ] && ok || fail
 147         LOG_DETAILS="testing if filters were applied"
 148         dlogsend -b system -t TEST test
 149         dlogsend -b main -t TEST test
 150         dlogsend -b radio -t TEST test
 151         [ "$(dlogutil -d -b radio -b system -b main | wc -l)" -eq 0 ] && ok || fail
 152
 153         LOG_DETAILS="dlogctl --enable (no args)"
 154         dlogctl --enable
 155         [ "$(dlogctl -g | grep DISABLED | wc -l)" -eq 0 ] && ok || fail
 156         LOG_DETAILS="testing if filters were applied"
 157         dlogutil -c -b radio -b system -b main
 158         dlogsend -b system -t TEST test
 159         dlogsend -b main -t TEST test
 160         dlogsend -b radio -t TEST test
 161         [ "$(dlogutil -d -b radio -b system -b main | wc -l)" -eq 3 ] && ok || fail
 162
 163         LOG_DETAILS="dlogctl --disable (1 arg)"
 164         dlogctl --disable -b system
 165         [ "$(dlogctl -g | grep DISABLED | grep system | wc -l)" -eq 1 ] &&
 166         [ "$(dlogctl -g | grep DISABLED               | wc -l)" -eq 1 ] && ok || fail
 167         LOG_DETAILS="testing if filters were applied"
 168         dlogutil -c -b radio -b system -b main
 169         dlogsend -b system -t TEST test
 170         dlogsend -b main -t TEST test
 171         dlogsend -b radio -t TEST test
 172         [ "$(dlogutil -d -b radio -b system -b main | wc -l)" -eq 2 ] && ok || fail
 173
 174         LOG_DETAILS="dlogctl --disable (multiple args)"
 175         dlogctl --disable -b main -b radio
 176         [ "$(dlogctl -g | grep DISABLED | grep -v system | wc -l)" -eq 2 ] &&
 177         [ "$(dlogctl -g | grep DISABLED | grep     radio | wc -l)" -eq 1 ] &&
 178         [ "$(dlogctl -g | grep DISABLED | grep      main | wc -l)" -eq 1 ] && ok || fail
 179         LOG_DETAILS="testing if filters were applied"
 180         dlogutil -c -b radio -b system -b main
 181         dlogsend -b system -t TEST test
 182         dlogsend -b main -t TEST test
 183         dlogsend -b radio -t TEST test
 184         [ "$(dlogutil -d -b radio -b system -b main | wc -l)" -eq 0 ] && ok || fail
 185
 186         LOG_DETAILS="dlogctl --enable (multiple args)"
 187         dlogctl --enable -b radio -b system
 188         [ "$(dlogctl -g | grep DISABLED               | wc -l)" -eq 1 ] &&
 189         [ "$(dlogctl -g | grep DISABLED | grep   main | wc -l)" -eq 1 ] &&
 190         [ "$(dlogctl -g | grep  ENABLED | grep system | wc -l)" -eq 1 ] &&
 191         [ "$(dlogctl -g | grep  ENABLED | grep  radio | wc -l)" -eq 1 ] && ok || fail
 192         LOG_DETAILS="testing if filters were applied"
 193         dlogutil -c -b radio -b system -b main
 194         dlogsend -b system -t TEST test
 195         dlogsend -b main -t TEST test
 196         dlogsend -b radio -t TEST test
 197         [ "$(dlogutil -d -b radio -b system -b main | wc -l)" -eq 2 ] && ok || fail
 198
 199         LOG_DETAILS="dlogctl --enable (1 arg)"
 200         dlogctl --enable -b main
 201         [ "$(dlogctl -g | grep DISABLED | wc -l)" -eq 0 ] && ok || fail
 202         LOG_DETAILS="testing if filters were applied"
 203         dlogutil -c -b radio -b system -b main
 204         dlogsend -b system -t TEST test
 205         dlogsend -b main -t TEST test
 206         dlogsend -b radio -t TEST test
 207         [ "$(dlogutil -d -b radio -b system -b main | wc -l)" -eq 3 ] && ok || fail
 208
 209         LOG_DETAILS="dlogctl -s allow"
 210         dlogutil -c -b radio -b system -b main
 211         dlogctl -c
 212         dlogctl -s deny
 213         dlogctl -t TEST_TAG -s allow
 214         dlogsend -b main -t TEST_TAG test
 215         dlogsend -b main -t TEST test
 216         [ "$(dlogutil -d -b main | wc -l)" -eq 1 ] && ok || fail
 217
 218         LOG_DETAILS="dlogctl -s [N]"
 219         dlogutil -c -b radio -b system -b main
 220         dlogctl -c
 221         dlogctl -s deny
 222         dlogctl -t TEST_TAG -s 3
 223         dlogsend -b main -c 10 -t TEST_TAG test
 224         dlogsend -b main -c 10 -t TEST test
 225         [ "$(dlogutil -d -b main | wc -l)" -eq 4 ] && ok || fail
 226
 227         LOG_DETAILS="testing invalid parameters for dlogctl (1/13)"
 228         dlogctl -s invalid > /dev/null && fail || ok
 229
 230         LOG_DETAILS="testing invalid parameters for dlogctl (2/13)"
 231         dlogctl -p X -g > /dev/null && fail || ok
 232
 233         LOG_DETAILS="testing invalid parameters for dlogctl (3/13)"
 234         dlogctl -b invalid --disable > /dev/null && fail || ok
 235
 236         LOG_DETAILS="testing invalid parameters for dlogctl (4/13)"
 237         dlogctl -s allow -g -t xyz -p E > /dev/null && fail || ok
 238
 239         LOG_DETAILS="testing invalid parameters for dlogctl (5/13)"
 240         dlogctl -s allow -c > /dev/null && fail || ok
 241
 242         LOG_DETAILS="testing invalid parameters for dlogctl (6/13)"
 243         dlogctl -c -g -t xyz -p E > /dev/null && fail || ok
 244
 245         # -s out of range
 246         LOG_DETAILS="testing invalid parameters for dlogctl (7/13)"
 247         dlogctl -s -10 > /dev/null && fail || ok
 248
 249         LOG_DETAILS="testing invalid parameters for dlogctl (8/13)"
 250         dlogctl -s 999999 > /dev/null && fail || ok
 251
 252         # -s correctness
 253         LOG_DETAILS="testing invalid parameters for dlogctl (9/13)"
 254         dlogctl -s 100 && ok || fail
 255
 256         LOG_DETAILS="testing invalid parameters for dlogctl (10/13)"
 257         [ $(cat "$RUNTIME_FILTERS_DIR/05-logctl.conf" | grep -E 'limiter\|\*\|\*=100' | wc -l) -eq 1 ] && ok || fail
 258
 259         # -g correctness
 260         LOG_DETAILS="testing invalid parameters for dlogctl (11/13)"
 261         [ "$(dlogctl -g | grep '*:*' | grep 100 | wc -l)" -eq 1 ] && ok || fail
 262
 263         # -c correctness
 264         LOG_DETAILS="testing invalid parameters for dlogctl (12/13)"
 265         dlogctl -c -t '*' -p '*' && ok || fail
 266
 267         LOG_DETAILS="testing invalid parameters for dlogctl (13/13)"
 268         [ $(cat "$RUNTIME_FILTERS_DIR/05-logctl.conf" | grep -E 'limiter\|\*\|\*=100' | wc -l) -eq 0 ] && ok || fail
 269         dlogctl -c
 270
 271         LOG_DETAILS="testing if the whole dynamic config directory is respected"
 272         dlogctl -s deny
 273         cp $RUNTIME_FILTERS_DIR/05-logctl.conf $RUNTIME_FILTERS_DIR/10-other.conf
 274         dlogctl -c
 275         dlogutil -c -b radio -b system -b main
 276         dlogsend -b system -t TEST test
 277         dlogsend -b main -t TEST test
 278         dlogsend -b radio -t TEST test
 279         [ "$(dlogutil -d -b radio -b system -b main | wc -l)" -eq 0 ] && ok || fail
 280         rm $RUNTIME_FILTERS_DIR/10-other.conf
 281 fi
 282
 283 SEED=$(head -c 6 /dev/urandom | base64)
 284 dlogsend -k "$SEED"
 285 # -k is async, unlike normal mode; therefore we have to wait until the logging process actually finishes
 286 while ps -o args | grep "dlogsend" | grep -v grep > /dev/null || ps -o args | grep "dlog-log-critical" | grep -v grep > /dev/null; do :; done
 287 CRIT_PATH="@DLOG_CRITICAL_LOGFILE_PATH@"
 288 LOG_DETAILS="testing if critical logging works"
 289 cat "$CRIT_PATH".a "$CRIT_PATH".b | grep -F "$SEED" > /dev/null && ok || fail
 290
 291 # put 100 log entries in the "main" buffer
 292 dlogutil -c
 293 test_libdlog 100
 294 sleep 1
 295
 296
 297 LOG_DETAILS="testing if dlogutil -d exits with success after printing logs"
 298 dlogutil -d > /dev/null && ok || fail
 299
 300 LOG_DETAILS="testing if -t argument is parsed properly"
 301 dlogutil -t dummy > /dev/null && fail || ok
 302
 303 LOG_DETAILS="testing if -u argument is parsed properly"
 304 dlogutil -du dummy > /dev/null && fail || ok
 305
 306 LOG_DETAILS="testing if limiting printed log entries to less than exists in the buffer returns proper value"
 307 [ "$(dlogutil -b main -t  20 | wc -l)" -eq  20 ] && ok || fail # less logs than currently in buffer
 308
 309 LOG_DETAILS="testing if limiting printed log entries to more than exists in the buffer returns proper value"
 310 [ "$(dlogutil -b main -t 200 | wc -l)" -eq 100 ] && ok || fail # more
 311
 312 LOG_DETAILS="testing if dlogutil returns exact amount of entries as there is in the buffer"
 313 [ "$(dlogutil -b main -d     | wc -l)" -eq 100 ] && ok || fail # exactly
 314
 315 LOG_DETAILS="testing if reading from  dummy buffer returns an error as expected"
 316 dlogutil -b nonexistent_buffer > /dev/null && fail || ok
 317
 318 LOG_DETAILS="testing if reading from \"system\" buffer returns zero entries (logs are in the \"main\" buffer)"
 319 [ "$(dlogutil -d -b system | wc -l)" -eq 0 ] && ok || fail
 320
 321 LOG_DETAILS="testing if dlogutil -c empties all buffers"
 322 dlogutil -cb main && ok || fail
 323
 324 LOG_DETAILS="testing if writing entries to empty buffer and reading them returns proper amount of entries"
 325 test_libdlog 10
 326 [ "$(dlogutil -b main -d | wc -l)" -eq 10 ] && ok || fail # should be 10, not 110
 327
 328 LOG_DETAILS="testing if filters work (1/3)"
 329 [ "$(dlogutil -b main -d *:E | wc -l)" -eq 5 ] && ok || fail # half of current logs (test_libdlog alternates between error and info log levels)
 330
 331 LOG_DETAILS="testing if filters work (2/3)"
 332 [ "$(dlogutil -b main -d *:W | wc -l)" -eq 5 ] && ok || fail
 333
 334 LOG_DETAILS="testing if filters work (3/3)"
 335 [ "$(dlogutil -b main -d *:I | wc -l)" -eq 10 ] && ok || fail
 336
 337 LOG_DETAILS="testing if exact filters work (1/3)"
 338 [ "$(dlogutil -b main -d *:=E | wc -l)" -eq 5 ] && ok || fail
 339
 340 LOG_DETAILS="testing if exact filters work (2/3)"
 341 [ "$(dlogutil -b main -d *:=W | wc -l)" -eq 0 ] && ok || fail
 342
 343 LOG_DETAILS="testing if exact filters work (3/3)"
 344 [ "$(dlogutil -b main -d *:=I | wc -l)" -eq 5 ] && ok || fail
 345
 346 LOG_DETAILS="testing if adding \"silent\" filter works"
 347 [ "$(dlogutil -b main -s -d | wc -l)" -eq 0 ] && ok || fail
 348
 349 LOG_DETAILS="testing if reading buffer size returns proper exit code"
 350 dlogutil -gb main > /dev/null && ok || fail
 351
 352 LOG_DETAILS="testing if writing all entries to single file works (-f)"
 353 dlogutil -f $TESTDIR/dlog_test_file -d > /dev/null && ok || fail
 354
 355 if [ "$quick" -ne 1 ]; then
 356         LOG_DETAILS="testing if the continuous mode works as expected (1/2)"
 357         dlogutil -b main -f $TESTDIR/dlog_continuous1_file &
 358         UTIL_PID=$!
 359         sleep 1
 360         kill $UTIL_PID && WAS_ALIVE=1 || WAS_ALIVE=0
 361         UTIL_PID=-1
 362         [[ $WAS_ALIVE -eq 1 && `wc -l < $TESTDIR/dlog_continuous1_file` -eq 10 ]] && ok || fail
 363
 364         LOG_DETAILS="testing if the continuous mode works as expected (2/2)"
 365         dlogutil -b main -f $TESTDIR/dlog_continuous2_file &
 366         UTIL_PID=$!
 367         sleep 1
 368         dlogsend -b main "Hi!"
 369         sleep 1
 370         kill $UTIL_PID && WAS_ALIVE=1 || WAS_ALIVE=0
 371         UTIL_PID=-1
 372         [[ $WAS_ALIVE -eq 1 && `wc -l < $TESTDIR/dlog_continuous2_file` -eq 11 ]] && ok || fail
 373
 374         LOG_DETAILS="testing if the monitor mode works as expected (1/2)"
 375         dlogutil -mb main -f $TESTDIR/dlog_monitor1_file &
 376         UTIL_PID=$!
 377         sleep 1
 378         kill $UTIL_PID && WAS_ALIVE=1 || WAS_ALIVE=0
 379         UTIL_PID=-1
 380         [[ $WAS_ALIVE -eq 1 && `wc -l < $TESTDIR/dlog_monitor1_file` -eq 0 ]] && ok || fail
 381
 382         LOG_DETAILS="testing if the monitor mode works as expected (2/2)"
 383         dlogutil -mb main -f $TESTDIR/dlog_monitor2_file &
 384         UTIL_PID=$!
 385         sleep 1
 386         dlogsend -b main "Hi!"
 387         sleep 1
 388         kill $UTIL_PID && WAS_ALIVE=1 || WAS_ALIVE=0
 389         UTIL_PID=-1
 390         [[ $WAS_ALIVE -eq 1 && `wc -l < $TESTDIR/dlog_monitor2_file` -eq 1 ]] && ok || fail
 391 fi
 392
 393 LOG_DETAILS="testing if writing entries to rotating files works (-r/-n)"
 394 dlogutil -f $TESTDIR/dlog_rotating_file -r 12 -n 3 & # 3 files at 12 KB each
 395 UTIL_PID=$!
 396
 397 test_libdlog 100000 &
 398 LIBDLOGUTIL_CORRECT_PID=$!
 399 wait $LIBDLOGUTIL_CORRECT_PID
 400
 401 LOG_DETAILS="testing if single file is properly created"
 402 if [ -e $TESTDIR/dlog_test_file ]; then ok; else fail; fi
 403
 404 LOG_DETAILS="testing if rotating file is properly created (1/4)"
 405 if [ -e $TESTDIR/dlog_rotating_file.1 ]; then ok; else fail; fi
 406
 407 LOG_DETAILS="testing if rotating file is properly created (2/4)"
 408 if [ -e $TESTDIR/dlog_rotating_file.2 ]; then ok; else fail; fi
 409
 410 LOG_DETAILS="testing if rotating file is properly created (3/4)"
 411 if [ -e $TESTDIR/dlog_rotating_file.3 ]; then ok; else fail; fi
 412
 413 LOG_DETAILS="testing if rotating file is properly created (4/4)"
 414 if [ -e $TESTDIR/dlog_rotating_file.4 ]; then fail; else ok; fi
 415
 416 LOG_DETAILS="testing the size of log files"
 417 if [ $(du $TESTDIR/dlog_rotating_file.3 | sed "s#$TESTDIR/dlog_rotating_file.3##g") -eq 16 ]; then ok; else fail; fi # the actual size is one sector more (so 12 -> 16) because the limit is checked after reaching it, not before
 418
 419 kill $UTIL_PID
 420 UTIL_PID=-1
 421
 422 LOG_DETAILS="testing if libdlogutil works correctly in the dump mode"
 423 test_libdlogutil dump $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 424 if [ "$quick" -ne 1 ]; then
 425         LOG_DETAILS="testing if libdlogutil works correctly if processing the logs takes some time"
 426         test_libdlogutil timer $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 427 fi
 428 LOG_DETAILS="testing if libdlogutil works correctly in the continuous mode"
 429 test_libdlogutil continuous $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 430 LOG_DETAILS="testing if libdlogutil skips all the logs in the monitor mode correctly"
 431 test_libdlogutil monitor $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 432 LOG_DETAILS="testing if libdlogutil priority filter works correctly"
 433 test_libdlogutil priority $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 434 LOG_DETAILS="testing if libdlogutil exact priority filter works correctly"
 435 test_libdlogutil priority_exact $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 436 LOG_DETAILS="testing if libdlogutil limits the log amount correctly"
 437 test_libdlogutil limit $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 438 LOG_DETAILS="testing if libdlogutil PID filter works correctly (1/2)"
 439 test_libdlogutil pid_correct $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 440 LOG_DETAILS="testing if libdlogutil PID filter works correctly (2/2)"
 441 test_libdlogutil pid_wrong $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 442 LOG_DETAILS="testing if libdlogutil TID filter works correctly (1/2)"
 443 test_libdlogutil tid_correct $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 444 LOG_DETAILS="testing if libdlogutil TID filter works correctly (2/2)"
 445 test_libdlogutil tid_wrong $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 446 LOG_DETAILS="testing if libdlogutil tag filter works correctly (1/2)"
 447 test_libdlogutil tag_correct $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 448 LOG_DETAILS="testing if libdlogutil tag filter works correctly (2/2)"
 449 test_libdlogutil tag_wrong $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 450 LOG_DETAILS="testing if libdlogutil prefix filter works correctly (1/2)"
 451 test_libdlogutil prefix_correct $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 452 LOG_DETAILS="testing if libdlogutil prefix filter works correctly (2/2)"
 453 test_libdlogutil prefix_wrong $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 454 LOG_DETAILS="testing if libdlogutil returns the correct buffer traits"
 455 test_libdlogutil traits $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 456 LOG_DETAILS="testing if libdlogutil aliasing works"
 457 if [ "$type" = "pipe" ]; then
 458         test_libdlogutil alias $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 459 else
 460         DLOG_CONFIG_PATH="@datadir@/dlog-logger.conf.alias" test_libdlogutil alias $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 461 fi
 462 LOG_DETAILS="testing if libdlogutil errors out correctly if used improperly"
 463 test_libdlogutil negative $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 464
 465 cmd_prefix="dlogutil -t 1 -u 0 -v"
 466
 467 format="process"
 468 regex_prio="[VDIWEFS]{1}"
 469 regex_pidtid="P[0-9[:space:]]{5,},\s{1}T[0-9[:space:]]{5,}"
 470 regex_time="[0-9]{2}-[0-9]{2}\s{1}[0-9]{2}:[0-9]{2}:[0-9]{2}"
 471 regex_timezone="[\+-]{1}[0-9]{4}"
 472
 473 for PARAM in always auto none never; do
 474         for PRIO in info error; do
 475                 for OUTPUT in pipe tty; do
 476                         if [[ "$PARAM" == "always" ]]; then
 477                                 COLOR_EXPECTED=1
 478                         elif [[ "$PARAM" == "never" ]]; then
 479                                 COLOR_EXPECTED=0
 480                         elif [[ "$OUTPUT" == "tty" ]]; then
 481                                 COLOR_EXPECTED=1
 482                         else
 483                                 COLOR_EXPECTED=0
 484                         fi
 485
 486                         if [[ "$PRIO" == "info" ]]; then
 487                                 REGEX="s/^I\([0-9[:space:]]{5,}\)[[:print:]]*\([[:print:]]*\)@$/1/g"
 488                         elif [[ "$COLOR_EXPECTED" -eq 0 ]]; then
 489                                 REGEX="s/^E\([0-9[:space:]]{5,}\)[[:print:]]*\([[:print:]]*\)@$/1/g"
 490                         else
 491                                 REGEX="s/^~\[31;1mE\([0-9[:space:]]{5,}\) ~\[0m[[:print:]]*~\[31;1m  \([[:print:]]*\)@~\[0m$/1/g"
 492                         fi
 493
 494                         # -t 1 instead of | head -n 1 because the `script` command can't cope with SIGPIPE.
 495                         COMMAND="$cmd_prefix $format"
 496
 497                         if [[ "$PARAM" == "none" ]]; then
 498                                 LOG_DETAILS="testing if color output is correct (implicit --color=auto/$PRIO priority/$OUTPUT output)"
 499                         else
 500                                 COMMAND="$COMMAND --color=$PARAM"
 501                                 LOG_DETAILS="testing if color output is correct (--color=$PARAM/$PRIO priority/$OUTPUT output)"
 502                         fi
 503
 504                         if [[ "$PRIO" == "info" ]]; then
 505                                 COMMAND="$COMMAND '*:=I'"
 506                         else
 507                                 COMMAND="$COMMAND '*:=E'"
 508                         fi
 509
 510                         if [[ "$OUTPUT" == "tty" ]]; then
 511                                 # This emulates a TTY. The sed call is because `script` likes to mess up the output for some reason.
 512                                 COMMAND="script -qc\"$COMMAND\" /dev/null | sed 's/\r$//'"
 513                         fi
 514
 515                         # $(eval) is needed since $($COMMAND) may contain $(")
 516                         line=$(eval $COMMAND | tr '\033\n' '~@')
 517                         [[ $(echo "$line" | sed -re "$REGEX") == "1" ]] && ok || fail
 518                 done
 519         done
 520 done
 521 # TODO: It would be cool to also test warning messages (which have a different color),
 522 # but this would require deeper changes to this script, which is already janky enough.
 523
 524 REGEX="s/^$regex_prio\([0-9[:space:]]{5,}\)[[:print:]]*\([[:print:]]*\)$/1/g"
 525 LOG_DETAILS="testing if \"$format\" print format works"
 526 line=$($cmd_prefix $format)
 527 [[ $(echo "$line" | sed -re $REGEX) == "1" ]] && ok || fail
 528
 529 format="tag"
 530 REGEX="s/^$regex_prio\/[[:print:]]{9,}:\s{1}[[:print:]]*$/1/g"
 531 LOG_DETAILS="testing if \"$format\" print format works"
 532 line=$($cmd_prefix $format)
 533 [[ $(echo "$line" | sed -re $REGEX) == "1" ]] && ok || fail
 534
 535 format="thread"
 536 REGEX="s/^$regex_prio\($regex_pidtid\)\s{1}[[:print:]]*$/1/g"
 537 LOG_DETAILS="testing if \"$format\" print format works"
 538 line=$($cmd_prefix $format)
 539 [[ $(echo "$line" | sed -re $REGEX) == "1" ]] && ok || fail
 540
 541 format="time"
 542 REGEX="s/^$regex_time.[0-9]{3}$regex_timezone\s{1}$regex_prio\/[[:print:]]{8,}\([0-9[:space:]]{5,}\):\s{1}[[:print:]]*$/1/g"
 543 LOG_DETAILS="testing if \"$format\" print format works"
 544 line=$($cmd_prefix $format)
 545 [[ $(echo "$line" | sed -re $REGEX) == "1" ]] && ok || fail
 546
 547 format="threadtime"
 548 REGEX="s/^$regex_time.[0-9]{3}$regex_timezone\s{1}$regex_prio\/[[:print:]]{8,}\($regex_pidtid\):\s{1}[[:print:]]*$/1/g"
 549 LOG_DETAILS="testing if \"$format\" print format works"
 550 line=$($cmd_prefix $format)
 551 [[ $(echo "$line" | sed -re $REGEX) == "1" ]] && ok || fail
 552
 553 format="kerneltime"
 554 REGEX="s/^[0-9[:space:]]{1,}.[0-9]{3,}\s{1}$regex_prio\/[[:print:]]{8,}\($regex_pidtid\):\s{1}[[:print:]]*$/1/g"
 555 LOG_DETAILS="testing if \"$format\" print format works"
 556 line=$($cmd_prefix $format)
 557 [[ $(echo "$line" | sed -re $REGEX) == "1" ]] && ok || fail
 558
 559 format="recv_realtime"
 560 REGEX="s/^$regex_time.[0-9]{3}\s{1}$regex_prio\/[[:print:]]{8,}\($regex_pidtid\):\s{1}[[:print:]]*$/1/g"
 561 LOG_DETAILS="testing if \"$format\" print format works"
 562 line=$($cmd_prefix $format)
 563 [[ $(echo "$line" | sed -re $REGEX) == "1" ]] && ok || fail
 564
 565 format="rwtime"
 566 REGEX="s/^$regex_time\s{1}\[[0-9[:space:]]{3,}.[0-9[:space:]]{3,}\]\s{1}$regex_prio\/[[:print:]]{8,}\($regex_pidtid\):\s{1}[[:print:]]*$/1/g"
 567 LOG_DETAILS="testing if \"$format\" print format works"
 568 line=$($cmd_prefix $format)
 569 [[ $(echo "$line" | sed -re $REGEX) == "1" ]] && ok || fail
 570
 571 format="long"
 572 REGEX="s/^\[\s{1}$regex_time.[0-9]{3,}\s{1}$regex_prio\/[[:print:]]{8,}\s{1}$regex_pidtid\]@[[:print:]]+@$/1/g"
 573 LOG_DETAILS="testing if \"$format\" print format works"
 574 line=$($cmd_prefix $format)
 575 [[ $(echo "$line" | tr '\n' '@' | sed -re $REGEX) == "1" ]] && ok || fail
 576
 577 format="brief"
 578 REGEX="s/^$regex_prio\/[[:print:]]{8,}\([0-9[:space:]]{5,}\):\s{1}[[:print:]]*$/1/g"
 579 LOG_DETAILS="testing if \"$format\" print format works"
 580 line=$($cmd_prefix $format)
 581 [[ $(echo "$line" | sed -re $REGEX) == "1" ]] && ok || fail
 582
 583 format="json"
 584 if [[ "$type" == "pipe" ]]; then
 585         REGEX="s/^\{\"priority\":\"(verbose|debug|info|warning|error|fatal|silent)\",\"pid\":[1-9][0-9]*,\"tid\":[1-9][0-9]*,\"recv_real\":\"[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}$regex_timezone\",\"recv_mono\":[1-9][0-9]+\.[0-9]{9},\"sent_real\":\"[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}$regex_timezone\",\"sent_mono\":[1-9][0-9]+\.[0-9]{9},\"tag\":\"[[:print:]]*\",\"msg\":\"[[:print:]]*\"\}$/1/g"
 586 else
 587         REGEX="s/^\{\"priority\":\"(verbose|debug|info|warning|error|fatal|silent)\",\"pid\":[1-9][0-9]*,\"tid\":[1-9][0-9]*,\"sent_real\":\"[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}$regex_timezone\",\"tag\":\"[[:print:]]*\",\"msg\":\"[[:print:]]*\"\}$/1/g"
 588 fi
 589 LOG_DETAILS="testing if \"$format\" print format works"
 590 line=$($cmd_prefix $format)
 591 [[ $(echo "$line" | sed -re $REGEX) == "1" ]] && ok || fail
 592
 593 format="raw"
 594 LOG_DETAILS="testing if \"$format\" print format works"
 595 dlogutil -c
 596 dlogsend -b main -t DLOG_TESTSUITE rawformatTEST
 597 line=$($cmd_prefix $format)
 598 [[ "$line" == "rawformatTEST" ]] && ok || fail
 599
 600 if [ "$quick" -ne 1 ]; then
 601         LOG_DETAILS="testing if dlogsend -d works"
 602         dlogutil -c
 603         dlogsend -b main -c 9999 -d 4 -f 7 -t DLOG_TESTSUITE "hi" &
 604         DLOGSEND_PID=$!
 605         sleep 10
 606         kill $DLOGSEND_PID
 607         # In 10 seconds, 3 cycles 7 logs each should have happened.
 608         [ "$(dlogutil -d DLOG_TESTSUITE | wc -l)" -eq 21 ] && ok || fail
 609 fi
 610
 611 if [ "$type" = "pipe" ]; then
 612         for format in raw brief long; do
 613                 for i in {1..8} 10 15 20 25 {513..520}; do
 614                         LOG_DETAILS="testing if padding works correctly (format $format/count $i)"
 615                         log=$(printf '%0.s&' $(seq 1 $i)) # Print the '&' character $i times
 616
 617                         dlogutil -c
 618                         dlogsend -b main $log
 619                         line=$($cmd_prefix $format | tr '\n' '@')
 620
 621                         case $format in
 622                                 raw)
 623                                         REGEX="s/$log@/1/g"
 624                                         ;;
 625                                 brief)
 626                                         REGEX="s/I\/DLOG_SEND\([0-9[:space:]]{5,}\):\s{1}$log@$/1/g"
 627                                         ;;
 628                                 long)
 629                                         REGEX="s/\[\s{1}$regex_time.[0-9]{3,}\s{1}I\/DLOG_SEND\s{1}$regex_pidtid\]@$log@@/1/g"
 630                                         ;;
 631                         esac
 632
 633                         [[ $(echo "$line" | sed -re $REGEX) == "1" ]] && ok || fail
 634                 done
 635         done
 636 fi
 637
 638 LOG_DETAILS="testing if KMSG works in the default format"
 639 # We check if the command returns at least 100 logs. This seems to be a safe value.
 640 # Feel free to change it to a reasonable yet lower value if the test happens to fail otherwise.
 641 [ "$(dlogutil -db kmsg | wc -l)" -gt 100 ] && ok || fail
 642
 643 if [ "$quick" -ne 1 ]; then
 644         LOG_DETAILS="testing if KMSG works in the raw format"
 645         last_dmesg=$(dmesg | tail -n1 | sed -re "s/^\[[ 0-9]{5,}\.[0-9]{6}\] (.*)$/\1/g")
 646         sleep 1 # To make sure dlog has already parsed the log
 647         dlogutil -db kmsg -v raw | grep -Fm1 "$last_dmesg" >/dev/null && ok || fail
 648
 649         LOG_DETAILS="testing if pid filtering works"
 650         dlogsend -b main -t DLOG_TESTSUITE pidTEST &
 651         sleep 1
 652         line=$(dlogutil -v raw -d --pid $!)
 653         [ "$line" = "pidTEST" ] && ok || fail
 654
 655         LOG_DETAILS="testing if tid filtering works"
 656         dlogsend -b main -t DLOG_TESTSUITE tidTEST &
 657         sleep 1
 658         line=$(dlogutil -v raw -d --tid $!) #dlogsend is a single threaded app so tid is the same as pid
 659         [ "$line" = "tidTEST" ] && ok || fail
 660
 661         mv $DLOG_CONFIG_PATH $DLOG_CONFIG_PATH.1
 662         LOG_DETAILS="testing if secure logging works (1/2)"
 663         grep -v enable_secure_logs $DLOG_CONFIG_PATH.1 > $DLOG_CONFIG_PATH
 664         echo "enable_secure_logs=1" >> $DLOG_CONFIG_PATH
 665         dlogutil -c
 666         dlogsend -zb main -t DLOG_TESTSUITE secure &
 667         sleep 1
 668         dlogsend -b main -t DLOG_TESTSUITE insecure &
 669         sleep 1
 670         line=$(dlogutil -v raw -d | head -n1)
 671         [ "$line" = "secure" ] && ok || fail
 672         LOG_DETAILS="testing if secure logging works (2/2)"
 673         grep -v enable_secure_logs $DLOG_CONFIG_PATH.1 > $DLOG_CONFIG_PATH
 674         echo "enable_secure_logs=0" >> $DLOG_CONFIG_PATH
 675         dlogutil -c
 676         dlogsend -zb main -t DLOG_TESTSUITE secure &
 677         sleep 1
 678         dlogsend -b main -t DLOG_TESTSUITE insecure &
 679         sleep 1
 680         line=$(dlogutil -v raw -d | head -n1)
 681         [ "$line" = "insecure" ] && ok || fail
 682         mv $DLOG_CONFIG_PATH.1 $DLOG_CONFIG_PATH
 683 fi
 684
 685 dlogsend -b main -t DLOG_TESTSUITE_TAG0 -pI tagTEST0
 686 dlogsend -b main -t DLOG_TESTSUITE_TAG1 -pI tagTEST1
 687 dlogsend -b main -t DLOG_TESTSUITE_TAG2 -pF tagTEST2
 688
 689 LOG_DETAILS="testing if tag filtering works (1/8)"
 690 [ "$(dlogutil -dv raw 'DLOG_TESTSUITE_TAG0' | wc -l)" -eq 1 ] && ok || fail
 691 LOG_DETAILS="testing if tag filtering works (2/8)"
 692 [ "$(dlogutil -dv raw 'DLOG_TESTSUITE_TAG1' | wc -l)" -eq 1 ] && ok || fail
 693 LOG_DETAILS="testing if tag filtering works (3/8)"
 694 [ "$(dlogutil -dv raw 'DLOG_TESTSUITE_TAG' | wc -l)" -eq 0 ] && ok || fail
 695 LOG_DETAILS="testing if tag filtering works (4/8)"
 696 [ "$(dlogutil -dv raw 'DLOG_TESTSUITE_TAG*' | wc -l)" -eq 3 ] && ok || fail
 697 LOG_DETAILS="testing if tag filtering works (5/8)"
 698 [ "$(dlogutil -dv raw 'DLOG_TESTSUITE_TAG*:I' | wc -l)" -eq 3 ] && ok || fail
 699 LOG_DETAILS="testing if tag filtering works (6/8)"
 700 [ "$(dlogutil -dv raw 'DLOG_TESTSUITE_TAG*:W' | wc -l)" -eq 1 ] && ok || fail
 701 LOG_DETAILS="testing if tag filtering works (7/8)"
 702 [ "$(dlogutil -dv raw 'DLOG_TESTSUITE_SAMSUNG' | wc -l)" -eq 0 ] && ok || fail
 703 LOG_DETAILS="testing if tag filtering works (8/8)"
 704 [ "$(dlogutil -dv raw 'DLOG_TESTSUITE_SAMSUNG*' | wc -l)" -eq 0 ] && ok || fail
 705
 706 if [ "$TEST_DYNAMIC_FILTERS" = "true" ]; then
 707         LOG_DETAILS="testing if limiter and runtime filtering works"
 708         dlogutil -c -b radio
 709         test_filters
 710         [ "$(dlogutil -d -b radio | wc -l)" -eq 12 ] && ok || fail
 711
 712         LOG_DETAILS="testing proper SMACK label for dynamic config file location"
 713         ORIG_FILTERS_DIR=$(cat $ORIGINAL_CONFIG_PATH | grep dynamic_config_path | awk -F "=" '{print $2}')
 714         [ `ls -dZ $ORIG_FILTERS_DIR | awk -F " " '{print $1}'` = "System::Shared" ] && ok || fail
 715
 716         if [ "$quick" -ne 1 ]; then
 717                 # This creates a process which will wait for SIGCONT and then spam logs. We know its PID, so we can add
 718                 # PID-based limits and see what happens.
 719                 sh -c 'kill -s STOP $$; exec dlogsend -b main -c 100 "Pid test"' &
 720                 DLOGSEND_PID=$!
 721                 while [ "$(cut -d ' ' -f 3 < /proc/$DLOGSEND_PID/stat)" != "T" ]; do :; done
 722                 dlogctl --pid $DLOGSEND_PID -s deny
 723                 kill -s CONT $DLOGSEND_PID
 724                 wait $DLOGSEND_PID
 725                 LOG_DETAILS="testing if PID limiting works (1/14)"
 726                 [ "$(dlogutil --pid $DLOGSEND_PID -d | grep -v blocked | wc -l)" -eq 0 ] && ok || fail
 727                 LOG_DETAILS="testing if PID limiting works (2/14)"
 728                 [ "$(dlogutil --pid $DLOGSEND_PID -d | grep blocked | wc -l)" -eq 1 ] && ok || fail
 729                 LOG_DETAILS="testing if PID limiting works (3/14)"
 730                 [ "$(dlogctl --pid $DLOGSEND_PID -g)" = "Denied" ] && ok || fail
 731                 LOG_DETAILS="testing if PID limiting works (4/14)"
 732                 dlogctl -g | grep -q "Denied for $DLOGSEND_PID" && ok || fail
 733
 734                 sh -c 'kill -s STOP $$; exec dlogsend -b main -c 100 "Pid test"' &
 735                 DLOGSEND_PID=$!
 736                 while [ "$(cut -d ' ' -f 3 < /proc/$DLOGSEND_PID/stat)" != "T" ]; do :; done
 737                 dlogctl --pid $DLOGSEND_PID -s 25
 738                 kill -s CONT $DLOGSEND_PID
 739                 wait $DLOGSEND_PID
 740                 LOG_DETAILS="testing if PID limiting works (5/14)"
 741                 [ "$(dlogutil --pid $DLOGSEND_PID -d | grep -v blocked | wc -l)" -eq 25 ] && ok || fail
 742                 LOG_DETAILS="testing if PID limiting works (6/14)"
 743                 [ "$(dlogutil --pid $DLOGSEND_PID -d | grep blocked | wc -l)" -eq 1 ] && ok || fail
 744                 LOG_DETAILS="testing if PID limiting works (7/14)"
 745                 [ "$(dlogctl --pid $DLOGSEND_PID -g)" = '25 logs/min' ] && ok || fail
 746                 LOG_DETAILS="testing if PID limiting works (8/14)"
 747                 dlogctl -g | grep -q "25 logs/min for $DLOGSEND_PID" && ok || fail
 748
 749                 sh -c 'kill -s STOP $$; exec dlogsend -b main -c 100 "Pid test"' &
 750                 DLOGSEND_PID=$!
 751                 while [ "$(cut -d ' ' -f 3 < /proc/$DLOGSEND_PID/stat)" != "T" ]; do :; done
 752                 dlogctl --pid $DLOGSEND_PID -s allow
 753                 kill -s CONT $DLOGSEND_PID
 754                 wait $DLOGSEND_PID
 755                 LOG_DETAILS="testing if PID limiting works (9/14)"
 756                 [ "$(dlogutil --pid $DLOGSEND_PID -d | grep -v blocked | wc -l)" -eq 100 ] && ok || fail
 757                 LOG_DETAILS="testing if PID limiting works (10/14)"
 758                 [ "$(dlogutil --pid $DLOGSEND_PID -d | grep blocked | wc -l)" -eq 0 ] && ok || fail
 759                 LOG_DETAILS="testing if PID limiting works (11/14)"
 760                 [ "$(dlogctl --pid $DLOGSEND_PID -g)" = 'Unlimited' ] && ok || fail
 761                 LOG_DETAILS="testing if PID limiting works (12/14)"
 762                 dlogctl -g | grep -q "Unlimited for $DLOGSEND_PID" && ok || fail
 763
 764                 echo "qos_refresh_rate_s=5" > "$RUNTIME_FILTERS_DIR/69-refresh-rate.conf"
 765                 sh -c 'kill -s STOP $$; exec dlogsend -b main -c 15 -d 1 "Pid test"' &
 766                 DLOGSEND_PID=$!
 767                 while [ "$(cut -d ' ' -f 3 < /proc/$DLOGSEND_PID/stat)" != "T" ]; do :; done
 768                 dlogctl --pid $DLOGSEND_PID -s 2
 769                 kill -s CONT $DLOGSEND_PID
 770                 wait $DLOGSEND_PID
 771                 rm "$RUNTIME_FILTERS_DIR/69-refresh-rate.conf"
 772                 LOG_DETAILS="testing if PID limiting works (13/14)"
 773                 # In each 5 second period, 5 logs are sent, so there are 3 periods.
 774                 # 2 logs from each period are allowed.
 775                 [ "$(dlogutil --pid $DLOGSEND_PID -d | grep -v blocked | wc -l)" -eq 6 ] && ok || fail
 776                 LOG_DETAILS="testing if PID limiting works (14/14)"
 777                 [ "$(dlogutil --pid $DLOGSEND_PID -d | grep blocked | wc -l)" -eq 3 ] && ok || fail
 778
 779                 # TODO: HACK ALERT!
 780                 # The following QoS tests make perfect sense for the pipe backend, since we kill the already
 781                 # existing dlog_logger and then start the new one, configured with QoS. However, on the logger
 782                 # backend this is impossible, as dlog_test uses the global service started by systemd then.
 783                 # This means that we have to just launch the second instance and hope nothing breaks.
 784                 # This can be improved by not using the global service in the logger backend, and by having it
 785                 # completely disabled in the config file -- this way, the tests would be completely uniform.
 786                 PREQOS_CONFIG_PATH=$DLOG_CONFIG_PATH
 787                 DLOG_CONFIG_PATH="@datadir@/dlog-$type.conf.qos"
 788                 if [ "$type" = "pipe" ]; then
 789                         kill $LOGGER > /dev/null
 790                         sleep 1
 791                 fi
 792                 dlog_logger -b 99 -t 0 &
 793                 LOGGER=$!
 794                 sleep 1
 795
 796                 dlogsend -b main -t DLOG_QOS_TEST0 -c 30 -d 1 -f 2 "A normal app that just wants to log"
 797                 LOG_DETAILS="testing if QoS works (1/4)"
 798                 [ "$(dlogutil -d DLOG_QOS_TEST0 | grep -v blocked | wc -l)" -eq 30 ] && ok || fail
 799                 kill $LOGGER > /dev/null
 800                 sleep 1
 801                 if [ "$type" = "logger" ]; then
 802                         dlogutil -cb main
 803                 fi
 804                 dlog_logger -b 99 -t 0 &
 805                 LOGGER=$!
 806                 sleep 1
 807
 808                 dlogsend -b main -t DLOG_QOS_TEST1 -c 300 -d 1 -f 20 "Some log spam"
 809                 LOG_DETAILS="testing if QoS works (2/4)"
 810                 [ "$(dlogutil -d DLOG_QOS_TEST1 | grep -v blocked | wc -l)" -le 180 ] && ok || fail
 811                 kill $LOGGER > /dev/null
 812                 sleep 1
 813                 if [ "$type" = "logger" ]; then
 814                         dlogutil -cb main
 815                 fi
 816                 dlog_logger -b 99 -t 0 &
 817                 LOGGER=$!
 818                 sleep 1
 819
 820                 dlogsend -b main -t DLOG_QOS_TEST2 -c 30 -d 1 -f 2 "A normal app that just wants to log" &
 821                 DLOGSEND_PID=$!
 822                 dlogsend -b main -t DLOG_QOS_TEST3 -c 270 -d 1 -f 18 "Some log spam"
 823                 wait $DLOGSEND_PID
 824                 LOG_DETAILS="testing if QoS works (3/4)"
 825                 [ "$(dlogutil -d DLOG_QOS_TEST2 DLOG_QOS_TEST3 | grep -v blocked | wc -l)" -le 180 ] && ok || fail
 826                 LOG_DETAILS="testing if QoS works (4/4)"
 827                 [ "$(dlogutil -d DLOG_QOS_TEST2 | grep -v blocked | wc -l)" -gt 24 ] && ok || fail
 828
 829                 DLOG_CONFIG_PATH=$PREQOS_CONFIG_PATH
 830                 kill $LOGGER > /dev/null
 831                 sleep 1
 832                 if [ "$type" = "pipe" ]; then
 833                         dlog_logger -b 99 -t 0 &
 834                         LOGGER=$!
 835                         sleep 1
 836                 else
 837                         LOGGER=-1
 838                 fi
 839         fi
 840 fi
 841
 842 LOG_DETAILS="testing if libdlogutil clears the buffer correctly"
 843 test_libdlogutil clear $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 844
 845 if [ "$quick" -ne 1 ]; then
 846         LOG_DETAILS="testing if the library works with multithreaded app"
 847         dlogutil -f $TESTDIR/dlog_mt_test &
 848         MT_TEST=$!
 849         test_libdlog && ok || fail
 850
 851         sleep 1
 852         kill $MT_TEST
 853         MT_TEST=-1
 854
 855         dlogutil -c
 856         SPAWN_CNT=1000
 857
 858         # Spawn logging scripts and wait for them to finish.
 859         # We launch all the $SPAWN_CNT scripts in a subshell, and then use the wait command in order to
 860         # wait for all the jobs of the subshell, which means all the logging scripts.
 861         # Each of the logging scripts is a new subsubshell which waits a random amount of seconds and then logs
 862         # a single message. This gets us 5 groups of logs separated by a second; there are about 200 logs in each
 863         # group, sent about at the same time.
 864         (
 865                 for i in $(seq 1 $SPAWN_CNT); do
 866                         delay=$(( (RANDOM) % 5 ))
 867                         ( sleep $delay && dlogsend -b main -t DLOG_TESTSUITE $delay ) &
 868                 done
 869                 wait
 870         )
 871
 872         LOG_DETAILS="testing if libdlogutil sorts by the timestamp correctly"
 873
 874         test_libdlogutil sorting $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 875
 876         sort_formats="kerneltime time recv_realtime rwtime threadtime long"
 877
 878         for format in $sort_formats; do
 879                 LOG_DETAILS="testing if sorting by timestamp from random sources on heavy load works ($format format)"
 880                 prev_ts=0
 881                 unsorted=""
 882                 prev_line=""
 883
 884                 # collect data and analyze timestamps
 885                 lines=$(dlogutil -b main -d -v $format)
 886                 while read line; do
 887                         # filter out empty lines in "long" format
 888                         [ -z "$line" ] && continue
 889                         # filter out non-timestamp lines in "long" format
 890                         if [ "$format" = "long" ] && [ "$(echo "$line" | sed -re 's/^\[[:print:]*\]$/line_ok/g')" != "line_ok" ]; then
 891                                 continue
 892                         fi
 893
 894                         [ "$line" -eq "$line" ] 2>/dev/null && continue
 895
 896                         ts=$(extract_timestamp "$format" "$line")
 897
 898                         if [ "$ts" -ge "$prev_ts" ]; then
 899                                 prev_ts=$ts
 900                         else
 901                                 printf -v unsorted '%s\n\n%s\n%s' "$unsorted" "$prev_line" "$line"
 902                                 break
 903                         fi
 904                         prev_line=$line
 905                 done <<< "$lines"
 906
 907                 [ -z "$unsorted" ] && ok || fail
 908         done
 909 fi
 910
 911 # show results, clean up and return an exit code
 912
 913 echo "$OKS / $TOTAL tests passed"
 914 echo "$FAILS / $TOTAL tests failed"
 915
 916 if [ "$quick" -eq 1 ]; then
 917         echo "WARNING: quick mode!"
 918         echo "About 20% slowest running tests are disabled. Some functionality might be untested."
 919         echo "Rerun with '$type' instead of '${type}_quick' to run all tests."
 920 fi
 921
 922 [ "$FAILS" -eq 0 ]
 923 # THE LINE ABOVE MUST STAY THE LAST COMMAND IN THE FILE!
 924 # This is because it is used to pass the exit code. If another command
 925 # is executed after it, its exit code will be propagated instead.