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