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 LOG_DETAILS="testing if writing entries to rotating files works (-r/-n)"
 427 dlogutil -f $TESTDIR/dlog_rotating_file -r 12 -n 3 & # 3 files at 12 KB each
 428 UTIL_PID=$!
 429
 430 test_libdlog 100000 &
 431 LIBDLOGUTIL_CORRECT_PID=$!
 432 wait $LIBDLOGUTIL_CORRECT_PID
 433
 434 LOG_DETAILS="testing if single file is properly created"
 435 if [ -e $TESTDIR/dlog_test_file ]; then ok; else fail; fi
 436
 437 LOG_DETAILS="testing if rotating file is properly created (1/4)"
 438 if [ -e $TESTDIR/dlog_rotating_file.1 ]; then ok; else fail; fi
 439
 440 LOG_DETAILS="testing if rotating file is properly created (2/4)"
 441 if [ -e $TESTDIR/dlog_rotating_file.2 ]; then ok; else fail; fi
 442
 443 LOG_DETAILS="testing if rotating file is properly created (3/4)"
 444 if [ -e $TESTDIR/dlog_rotating_file.3 ]; then ok; else fail; fi
 445
 446 LOG_DETAILS="testing if rotating file is properly created (4/4)"
 447 if [ -e $TESTDIR/dlog_rotating_file.4 ]; then fail; else ok; fi
 448
 449 LOG_DETAILS="testing the size of log files"
 450 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
 451
 452 kill $UTIL_PID
 453 UTIL_PID=-1
 454
 455 LOG_DETAILS="testing if libdlogutil works correctly in the dump mode"
 456 test_libdlogutil dump $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 457 if [ "$quick" -ne 1 ]; then
 458         LOG_DETAILS="testing if libdlogutil works correctly if processing the logs takes some time"
 459         test_libdlogutil timer $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 460 fi
 461 LOG_DETAILS="testing if libdlogutil works correctly in the continuous mode"
 462 test_libdlogutil continuous $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 463 LOG_DETAILS="testing if libdlogutil skips all the logs in the monitor mode correctly"
 464 test_libdlogutil monitor $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 465 LOG_DETAILS="testing if libdlogutil priority filter works correctly"
 466 test_libdlogutil priority $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 467 LOG_DETAILS="testing if libdlogutil exact priority filter works correctly"
 468 test_libdlogutil priority_exact $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 469 LOG_DETAILS="testing if libdlogutil limits the log amount correctly"
 470 test_libdlogutil limit $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 471 LOG_DETAILS="testing if libdlogutil PID filter works correctly (1/2)"
 472 test_libdlogutil pid_correct $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 473 LOG_DETAILS="testing if libdlogutil PID filter works correctly (2/2)"
 474 test_libdlogutil pid_wrong $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 475 LOG_DETAILS="testing if libdlogutil TID filter works correctly (1/2)"
 476 test_libdlogutil tid_correct $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 477 LOG_DETAILS="testing if libdlogutil TID filter works correctly (2/2)"
 478 test_libdlogutil tid_wrong $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 479 LOG_DETAILS="testing if libdlogutil tag filter works correctly (1/2)"
 480 test_libdlogutil tag_correct $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 481 LOG_DETAILS="testing if libdlogutil tag filter works correctly (2/2)"
 482 test_libdlogutil tag_wrong $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 483 LOG_DETAILS="testing if libdlogutil prefix filter works correctly (1/2)"
 484 test_libdlogutil prefix_correct $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 485 LOG_DETAILS="testing if libdlogutil prefix filter works correctly (2/2)"
 486 test_libdlogutil prefix_wrong $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 487 LOG_DETAILS="testing if libdlogutil returns the correct buffer traits"
 488 test_libdlogutil traits $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 489 LOG_DETAILS="testing if libdlogutil aliasing works"
 490 if [ "$type" = "pipe" ]; then
 491         test_libdlogutil alias $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 492 else
 493         DLOG_CONFIG_PATH="@datadir@/dlog-logger.conf.alias" test_libdlogutil alias $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 494 fi
 495 LOG_DETAILS="testing if libdlogutil errors out correctly if used improperly"
 496 test_libdlogutil negative $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 497
 498 cmd_prefix="dlogutil -t 1 -u 0 -v"
 499
 500 format="process"
 501 regex_prio="[VDIWEFS]{1}"
 502 regex_pidtid="P[0-9[:space:]]{5,},\s{1}T[0-9[:space:]]{5,}"
 503 regex_time="[0-9]{2}-[0-9]{2}\s{1}[0-9]{2}:[0-9]{2}:[0-9]{2}"
 504 regex_timezone="[\+-]{1}[0-9]{4}"
 505
 506 for PARAM in always auto none never; do
 507         for PRIO in info error; do
 508                 for OUTPUT in pipe tty; do
 509                         if [ "$PARAM" = "always" ]; then
 510                                 COLOR_EXPECTED=1
 511                         elif [ "$PARAM" = "never" ]; then
 512                                 COLOR_EXPECTED=0
 513                         elif [ "$OUTPUT" = "tty" ]; then
 514                                 COLOR_EXPECTED=1
 515                         else
 516                                 COLOR_EXPECTED=0
 517                         fi
 518
 519                         if [ "$PRIO" = "info" ]; then
 520                                 REGEX="s/^I\([0-9[:space:]]{5,}\)[[:print:]]*\([[:print:]]*\)@$/1/g"
 521                         elif [ "$COLOR_EXPECTED" -eq 0 ]; then
 522                                 REGEX="s/^E\([0-9[:space:]]{5,}\)[[:print:]]*\([[:print:]]*\)@$/1/g"
 523                         else
 524                                 REGEX="s/^~\[31;1mE\([0-9[:space:]]{5,}\) ~\[0m[[:print:]]*~\[31;1m  \([[:print:]]*\)@~\[0m$/1/g"
 525                         fi
 526
 527                         # -t 1 instead of | head -n 1 because the `script` command can't cope with SIGPIPE.
 528                         COMMAND="$cmd_prefix $format"
 529
 530                         if [ "$PARAM" = "none" ]; then
 531                                 LOG_DETAILS="testing if color output is correct (implicit --color=auto/$PRIO priority/$OUTPUT output)"
 532                         else
 533                                 COMMAND="$COMMAND --color=$PARAM"
 534                                 LOG_DETAILS="testing if color output is correct (--color=$PARAM/$PRIO priority/$OUTPUT output)"
 535                         fi
 536
 537                         if [ "$PRIO" = "info" ]; then
 538                                 COMMAND="$COMMAND '*:=I'"
 539                         else
 540                                 COMMAND="$COMMAND '*:=E'"
 541                         fi
 542
 543                         if [ "$OUTPUT" = "tty" ]; then
 544                                 # This emulates a TTY. The sed call is because `script` likes to mess up the output for some reason.
 545                                 COMMAND="script -qc\"$COMMAND\" /dev/null | sed 's/\r$//'"
 546                         fi
 547
 548                         # $(eval) is needed since `$COMMAND` may contain `"`
 549                         line=$(eval $COMMAND | tr '\033\n' '~@')
 550                         [[ $(echo "$line" | sed -re "$REGEX") == "1" ]] && ok || fail
 551                 done
 552         done
 553 done
 554 # TODO: It would be cool to also test warning messages (which have a different color),
 555 # but this would require deeper changes to this script, which is already janky enough.
 556
 557 REGEX="s/^$regex_prio\([0-9[:space:]]{5,}\)[[:print:]]*\([[:print:]]*\)$/1/g"
 558 LOG_DETAILS="testing if \"$format\" print format works"
 559 line=$($cmd_prefix $format)
 560 [ "$(echo "$line" | sed -re "$REGEX")" = "1" ] && ok || fail
 561
 562 format="tag"
 563 REGEX="s/^$regex_prio\/[[:print:]]{9,}:\s{1}[[:print:]]*$/1/g"
 564 LOG_DETAILS="testing if \"$format\" print format works"
 565 line=$($cmd_prefix $format)
 566 [ "$(echo "$line" | sed -re "$REGEX")" = "1" ] && ok || fail
 567
 568 format="thread"
 569 REGEX="s/^$regex_prio\($regex_pidtid\)\s{1}[[:print:]]*$/1/g"
 570 LOG_DETAILS="testing if \"$format\" print format works"
 571 line=$($cmd_prefix $format)
 572 [ "$(echo "$line" | sed -re "$REGEX")" = "1" ] && ok || fail
 573
 574 format="time"
 575 REGEX="s/^$regex_time.[0-9]{3}$regex_timezone\s{1}$regex_prio\/[[:print:]]{8,}\([0-9[:space:]]{5,}\):\s{1}[[:print:]]*$/1/g"
 576 LOG_DETAILS="testing if \"$format\" print format works"
 577 line=$($cmd_prefix $format)
 578 [ "$(echo "$line" | sed -re "$REGEX")" = "1" ] && ok || fail
 579
 580 format="threadtime"
 581 REGEX="s/^$regex_time.[0-9]{3}$regex_timezone\s{1}$regex_prio\/[[:print:]]{8,}\($regex_pidtid\):\s{1}[[:print:]]*$/1/g"
 582 LOG_DETAILS="testing if \"$format\" print format works"
 583 line=$($cmd_prefix $format)
 584 [ "$(echo "$line" | sed -re "$REGEX")" = "1" ] && ok || fail
 585
 586 format="kerneltime"
 587 REGEX="s/^[0-9[:space:]]{1,}.[0-9]{3,}\s{1}$regex_prio\/[[:print:]]{8,}\($regex_pidtid\):\s{1}[[:print:]]*$/1/g"
 588 LOG_DETAILS="testing if \"$format\" print format works"
 589 line=$($cmd_prefix $format)
 590 [ "$(echo "$line" | sed -re "$REGEX")" = "1" ] && ok || fail
 591
 592 format="recv_realtime"
 593 REGEX="s/^$regex_time.[0-9]{3}\s{1}$regex_prio\/[[:print:]]{8,}\($regex_pidtid\):\s{1}[[:print:]]*$/1/g"
 594 LOG_DETAILS="testing if \"$format\" print format works"
 595 line=$($cmd_prefix $format)
 596 [ "$(echo "$line" | sed -re "$REGEX")" = "1" ] && ok || fail
 597
 598 format="rwtime"
 599 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"
 600 LOG_DETAILS="testing if \"$format\" print format works"
 601 line=$($cmd_prefix $format)
 602 [ "$(echo "$line" | sed -re "$REGEX")" = "1" ] && ok || fail
 603
 604 format="long"
 605 REGEX="s/^\[\s{1}$regex_time.[0-9]{3,}\s{1}$regex_prio\/[[:print:]]{8,}\s{1}$regex_pidtid\]@[[:print:]]+@$/1/g"
 606 LOG_DETAILS="testing if \"$format\" print format works"
 607 line=$($cmd_prefix $format)
 608 [[ $(echo "$line" | tr '\n' '@' | sed -re "$REGEX") == "1" ]] && ok || fail
 609
 610 format="brief"
 611 REGEX="s/^$regex_prio\/[[:print:]]{8,}\([0-9[:space:]]{5,}\):\s{1}[[:print:]]*$/1/g"
 612 LOG_DETAILS="testing if \"$format\" print format works"
 613 line=$($cmd_prefix $format)
 614 [ "$(echo "$line" | sed -re "$REGEX")" = "1" ] && ok || fail
 615
 616 format="json"
 617 if [ "$type" = "pipe" ]; then
 618         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"
 619 else
 620         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"
 621 fi
 622 LOG_DETAILS="testing if \"$format\" print format works"
 623 line=$($cmd_prefix $format)
 624 [ "$(echo "$line" | sed -re "$REGEX")" = "1" ] && ok || fail
 625
 626 format="raw"
 627 LOG_DETAILS="testing if \"$format\" print format works"
 628 dlogutil -c
 629 dlogsend -b main -t DLOG_TESTSUITE rawformatTEST
 630 line=$($cmd_prefix $format)
 631 [ "$line" = "rawformatTEST" ] && ok || fail
 632
 633 if [ "$quick" -ne 1 ]; then
 634         LOG_DETAILS="testing if dlogsend -d works"
 635         dlogutil -c
 636         dlogsend -b main -c 9999 -d 4 -f 7 -t DLOG_TESTSUITE "hi" &
 637         DLOGSEND_PID=$!
 638         sleep 10
 639         kill $DLOGSEND_PID
 640         # In 10 seconds, 3 cycles 7 logs each should have happened.
 641         [ "$(dlogutil -d DLOG_TESTSUITE | wc -l)" -eq 21 ] && ok || fail
 642 fi
 643
 644 if [ "$type" = "pipe" ]; then
 645         for format in raw brief long; do
 646                 for i in 1 2 3 4 5 6 7 8 10 15 20 25 513 514 515 516 517 518 519 520; do
 647                         LOG_DETAILS="testing if padding works correctly (format $format/count $i)"
 648                         log=$(printf '%0.s&' $(seq 1 $i)) # Print the '&' character $i times
 649
 650                         dlogutil -c
 651                         dlogsend -b main $log
 652                         line=$($cmd_prefix $format | tr '\n' '@')
 653
 654                         case $format in
 655                                 raw)
 656                                         REGEX="s/$log@/1/g"
 657                                         ;;
 658                                 brief)
 659                                         REGEX="s/I\/DLOG_SEND\([0-9[:space:]]{5,}\):\s{1}$log@$/1/g"
 660                                         ;;
 661                                 long)
 662                                         REGEX="s/\[\s{1}$regex_time.[0-9]{3,}\s{1}I\/DLOG_SEND\s{1}$regex_pidtid\]@$log@@/1/g"
 663                                         ;;
 664                         esac
 665
 666                         [ "$(echo "$line" | sed -re "$REGEX")" = "1" ] && ok || fail
 667                 done
 668         done
 669 fi
 670
 671 LOG_DETAILS="testing if KMSG works in the default format"
 672 # We check if the command returns at least 100 logs. This seems to be a safe value.
 673 # Feel free to change it to a reasonable yet lower value if the test happens to fail otherwise.
 674 [ "$(dlogutil -db kmsg | wc -l)" -gt 100 ] && ok || fail
 675
 676 if [ "$quick" -ne 1 ]; then
 677         LOG_DETAILS="testing if KMSG works in the raw format"
 678         last_dmesg=$(dmesg | tail -n1 | sed -re "s/^\[[ 0-9]{5,}\.[0-9]{6}\] (.*)$/\1/g")
 679         sleep 1 # To make sure dlog has already parsed the log
 680         dlogutil -db kmsg -v raw | grep -Fm1 "$last_dmesg" >/dev/null && ok || fail
 681
 682         LOG_DETAILS="testing if pid filtering works"
 683         dlogsend -b main -t DLOG_TESTSUITE pidTEST &
 684         sleep 1
 685         line=$(dlogutil -v raw -d --pid $!)
 686         [ "$line" = "pidTEST" ] && ok || fail
 687
 688         LOG_DETAILS="testing if tid filtering works"
 689         dlogsend -b main -t DLOG_TESTSUITE tidTEST &
 690         sleep 1
 691         line=$(dlogutil -v raw -d --tid $!) #dlogsend is a single threaded app so tid is the same as pid
 692         [ "$line" = "tidTEST" ] && ok || fail
 693
 694         mv $DLOG_CONFIG_PATH $DLOG_CONFIG_PATH.1
 695         LOG_DETAILS="testing if secure logging works (1/2)"
 696         grep -v enable_secure_logs $DLOG_CONFIG_PATH.1 > $DLOG_CONFIG_PATH
 697         echo "enable_secure_logs=1" >> $DLOG_CONFIG_PATH
 698         dlogutil -c
 699         dlogsend -zb main -t DLOG_TESTSUITE secure &
 700         sleep 1
 701         dlogsend -b main -t DLOG_TESTSUITE insecure &
 702         sleep 1
 703         line=$(dlogutil -v raw -d | head -n1)
 704         [ "$line" = "secure" ] && ok || fail
 705         LOG_DETAILS="testing if secure logging works (2/2)"
 706         grep -v enable_secure_logs $DLOG_CONFIG_PATH.1 > $DLOG_CONFIG_PATH
 707         echo "enable_secure_logs=0" >> $DLOG_CONFIG_PATH
 708         dlogutil -c
 709         dlogsend -zb main -t DLOG_TESTSUITE secure &
 710         sleep 1
 711         dlogsend -b main -t DLOG_TESTSUITE insecure &
 712         sleep 1
 713         line=$(dlogutil -v raw -d | head -n1)
 714         [ "$line" = "insecure" ] && ok || fail
 715         mv $DLOG_CONFIG_PATH.1 $DLOG_CONFIG_PATH
 716 fi
 717
 718 dlogsend -b main -t DLOG_TESTSUITE_TAG0 -pI tagTEST0
 719 dlogsend -b main -t DLOG_TESTSUITE_TAG1 -pI tagTEST1
 720 dlogsend -b main -t DLOG_TESTSUITE_TAG2 -pF tagTEST2
 721
 722 LOG_DETAILS="testing if tag filtering works (1/8)"
 723 [ "$(dlogutil -dv raw 'DLOG_TESTSUITE_TAG0' | wc -l)" -eq 1 ] && ok || fail
 724 LOG_DETAILS="testing if tag filtering works (2/8)"
 725 [ "$(dlogutil -dv raw 'DLOG_TESTSUITE_TAG1' | wc -l)" -eq 1 ] && ok || fail
 726 LOG_DETAILS="testing if tag filtering works (3/8)"
 727 [ "$(dlogutil -dv raw 'DLOG_TESTSUITE_TAG' | wc -l)" -eq 0 ] && ok || fail
 728 LOG_DETAILS="testing if tag filtering works (4/8)"
 729 [ "$(dlogutil -dv raw 'DLOG_TESTSUITE_TAG*' | wc -l)" -eq 3 ] && ok || fail
 730 LOG_DETAILS="testing if tag filtering works (5/8)"
 731 [ "$(dlogutil -dv raw 'DLOG_TESTSUITE_TAG*:I' | wc -l)" -eq 3 ] && ok || fail
 732 LOG_DETAILS="testing if tag filtering works (6/8)"
 733 [ "$(dlogutil -dv raw 'DLOG_TESTSUITE_TAG*:W' | wc -l)" -eq 1 ] && ok || fail
 734 LOG_DETAILS="testing if tag filtering works (7/8)"
 735 [ "$(dlogutil -dv raw 'DLOG_TESTSUITE_SAMSUNG' | wc -l)" -eq 0 ] && ok || fail
 736 LOG_DETAILS="testing if tag filtering works (8/8)"
 737 [ "$(dlogutil -dv raw 'DLOG_TESTSUITE_SAMSUNG*' | wc -l)" -eq 0 ] && ok || fail
 738
 739 if [ "$TEST_DYNAMIC_FILTERS" = "true" ]; then
 740         LOG_DETAILS="testing if limiter and runtime filtering works"
 741         dlogutil -c -b radio
 742         test_filters
 743         [ "$(dlogutil -d -b radio | wc -l)" -eq 12 ] && ok || fail
 744
 745         LOG_DETAILS="testing proper SMACK label for dynamic config file location"
 746         ORIG_FILTERS_DIR=$(cat "$ORIGINAL_CONFIG_PATH" | grep dynamic_config_path | awk -F "=" '{print $2}')
 747         [ "$(ls -dZ "$ORIG_FILTERS_DIR" | awk -F ' ' '{print $1}')" = "System::Shared" ] && ok || fail
 748
 749         if [ "$quick" -ne 1 ]; then
 750                 # This creates a process which will wait for SIGCONT and then spam logs. We know its PID, so we can add
 751                 # PID-based limits and see what happens.
 752                 sh -c 'kill -s STOP $$; exec dlogsend -b main -c 100 "Pid test"' &
 753                 DLOGSEND_PID=$!
 754                 while [ "$(cut -d ' ' -f 3 < /proc/$DLOGSEND_PID/stat)" != "T" ]; do :; done
 755                 dlogctl --pid $DLOGSEND_PID -s deny
 756                 kill -s CONT $DLOGSEND_PID
 757                 wait $DLOGSEND_PID
 758                 LOG_DETAILS="testing if PID limiting works (1/14)"
 759                 [ "$(dlogutil --pid $DLOGSEND_PID -d | grep -cv blocked)" -eq 0 ] && ok || fail
 760                 LOG_DETAILS="testing if PID limiting works (2/14)"
 761                 [ "$(dlogutil --pid $DLOGSEND_PID -d | grep -c  blocked)" -eq 1 ] && ok || fail
 762                 LOG_DETAILS="testing if PID limiting works (3/14)"
 763                 [ "$(dlogctl --pid $DLOGSEND_PID -g)" = "Denied" ] && ok || fail
 764                 LOG_DETAILS="testing if PID limiting works (4/14)"
 765                 dlogctl -g | grep -q "Denied for $DLOGSEND_PID" && ok || fail
 766
 767                 sh -c 'kill -s STOP $$; exec dlogsend -b main -c 100 "Pid test"' &
 768                 DLOGSEND_PID=$!
 769                 while [ "$(cut -d ' ' -f 3 < /proc/$DLOGSEND_PID/stat)" != "T" ]; do :; done
 770                 dlogctl --pid $DLOGSEND_PID -s 25
 771                 kill -s CONT $DLOGSEND_PID
 772                 wait $DLOGSEND_PID
 773                 LOG_DETAILS="testing if PID limiting works (5/14)"
 774                 [ "$(dlogutil --pid $DLOGSEND_PID -d | grep -cv blocked)" -eq 25 ] && ok || fail
 775                 LOG_DETAILS="testing if PID limiting works (6/14)"
 776                 [ "$(dlogutil --pid $DLOGSEND_PID -d | grep -c  blocked)" -eq 1 ] && ok || fail
 777                 LOG_DETAILS="testing if PID limiting works (7/14)"
 778                 [ "$(dlogctl --pid $DLOGSEND_PID -g)" = '25 logs/min' ] && ok || fail
 779                 LOG_DETAILS="testing if PID limiting works (8/14)"
 780                 dlogctl -g | grep -q "25 logs/min for $DLOGSEND_PID" && ok || fail
 781
 782                 sh -c 'kill -s STOP $$; exec dlogsend -b main -c 100 "Pid test"' &
 783                 DLOGSEND_PID=$!
 784                 while [ "$(cut -d ' ' -f 3 < /proc/$DLOGSEND_PID/stat)" != "T" ]; do :; done
 785                 dlogctl --pid $DLOGSEND_PID -s allow
 786                 kill -s CONT $DLOGSEND_PID
 787                 wait $DLOGSEND_PID
 788                 LOG_DETAILS="testing if PID limiting works (9/14)"
 789                 [ "$(dlogutil --pid $DLOGSEND_PID -d | grep -cv blocked)" -eq 100 ] && ok || fail
 790                 LOG_DETAILS="testing if PID limiting works (10/14)"
 791                 [ "$(dlogutil --pid $DLOGSEND_PID -d | grep -c  blocked)" -eq 0 ] && ok || fail
 792                 LOG_DETAILS="testing if PID limiting works (11/14)"
 793                 [ "$(dlogctl --pid $DLOGSEND_PID -g)" = 'Unlimited' ] && ok || fail
 794                 LOG_DETAILS="testing if PID limiting works (12/14)"
 795                 dlogctl -g | grep -q "Unlimited for $DLOGSEND_PID" && ok || fail
 796
 797                 echo "qos_refresh_rate_s=5" > "$RUNTIME_FILTERS_DIR/69-refresh-rate.conf"
 798                 sh -c 'kill -s STOP $$; exec dlogsend -b main -c 15 -d 1 "Pid test"' &
 799                 DLOGSEND_PID=$!
 800                 while [ "$(cut -d ' ' -f 3 < /proc/$DLOGSEND_PID/stat)" != "T" ]; do :; done
 801                 dlogctl --pid $DLOGSEND_PID -s 2
 802                 kill -s CONT $DLOGSEND_PID
 803                 wait $DLOGSEND_PID
 804                 rm "$RUNTIME_FILTERS_DIR/69-refresh-rate.conf"
 805                 LOG_DETAILS="testing if PID limiting works (13/14)"
 806                 # In each 5 second period, 5 logs are sent, so there are 3 periods.
 807                 # 2 logs from each period are allowed.
 808                 [ "$(dlogutil --pid $DLOGSEND_PID -d | grep -cv blocked)" -eq 6 ] && ok || fail
 809                 LOG_DETAILS="testing if PID limiting works (14/14)"
 810                 [ "$(dlogutil --pid $DLOGSEND_PID -d | grep -c  blocked)" -eq 3 ] && ok || fail
 811
 812                 # TODO: HACK ALERT!
 813                 # The following QoS tests make perfect sense for the pipe backend, since we kill the already
 814                 # existing dlog_logger and then start the new one, configured with QoS. However, on the logger
 815                 # backend this is impossible, as dlog_test uses the global service started by systemd then.
 816                 # This means that we have to just launch the second instance and hope nothing breaks.
 817                 # This can be improved by not using the global service in the logger backend, and by having it
 818                 # completely disabled in the config file -- this way, the tests would be completely uniform.
 819                 PREQOS_CONFIG_PATH=$DLOG_CONFIG_PATH
 820                 DLOG_CONFIG_PATH="@datadir@/dlog-$type.conf.qos"
 821                 if [ "$type" = "pipe" ]; then
 822                         kill $LOGGER > /dev/null
 823                         sleep 1
 824                 fi
 825                 dlog_logger &
 826                 LOGGER=$!
 827                 sleep 1
 828
 829                 dlogsend -b main -t DLOG_QOS_TEST0 -c 30 -d 1 -f 2 "A normal app that just wants to log"
 830                 LOG_DETAILS="testing if QoS works (1/4)"
 831                 [ "$(dlogutil -d DLOG_QOS_TEST0 | grep -cv blocked)" -eq 30 ] && ok || fail
 832                 kill $LOGGER > /dev/null
 833                 sleep 1
 834                 if [ "$type" = "logger" ]; then
 835                         dlogutil -cb main
 836                 fi
 837                 dlog_logger &
 838                 LOGGER=$!
 839                 sleep 1
 840
 841                 dlogsend -b main -t DLOG_QOS_TEST1 -c 300 -d 1 -f 20 "Some log spam"
 842                 LOG_DETAILS="testing if QoS works (2/4)"
 843                 [ "$(dlogutil -d DLOG_QOS_TEST1 | grep -cv blocked)" -le 180 ] && ok || fail
 844                 kill $LOGGER > /dev/null
 845                 sleep 1
 846                 if [ "$type" = "logger" ]; then
 847                         dlogutil -cb main
 848                 fi
 849                 dlog_logger &
 850                 LOGGER=$!
 851                 sleep 1
 852
 853                 dlogsend -b main -t DLOG_QOS_TEST2 -c 30 -d 1 -f 2 "A normal app that just wants to log" &
 854                 DLOGSEND_PID=$!
 855                 dlogsend -b main -t DLOG_QOS_TEST3 -c 270 -d 1 -f 18 "Some log spam"
 856                 wait $DLOGSEND_PID
 857                 LOG_DETAILS="testing if QoS works (3/4)"
 858                 [ "$(dlogutil -d DLOG_QOS_TEST2 DLOG_QOS_TEST3 | grep -cv blocked)" -le 180 ] && ok || fail
 859                 LOG_DETAILS="testing if QoS works (4/4)"
 860                 [ "$(dlogutil -d DLOG_QOS_TEST2 | grep -cv blocked)" -gt 24 ] && ok || fail
 861
 862                 DLOG_CONFIG_PATH=$PREQOS_CONFIG_PATH
 863                 kill $LOGGER > /dev/null
 864                 sleep 1
 865                 if [ "$type" = "pipe" ]; then
 866                         dlog_logger -b 99 -t 0 &
 867                         LOGGER=$!
 868                         sleep 1
 869                 else
 870                         LOGGER=-1
 871                 fi
 872         fi
 873 fi
 874
 875 LOG_DETAILS="testing if libdlogutil clears the buffer correctly"
 876 test_libdlogutil clear $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 877
 878 if [ "$quick" -ne 1 ]; then
 879         if [ "$type" = "pipe" ]; then
 880                 dlogsend -b main -t DLOG_LOGGER_TEST0 -c 100 "hi"
 881                 sleep 1
 882                 LOG_DETAILS="testing if logger daemon persistent logging works"
 883                 [ "$(grep -c DLOG_LOGGER_TEST0 "$TESTDIR"/main)" -eq 100 ] && ok || fail
 884
 885                 dlogsend -b main -t DLOG_LOGGER_TEST1 -c 500000 "hi"
 886                 sleep 1
 887                 RESULT=$(du -c "$TESTDIR"/main* | tail -n 1 | cut -f 1)
 888                 LOG_DETAILS="testing if logger daemon log rotating works (1/2)"
 889                 [ "$RESULT" -gt 4096 ] && ok || fail # Min 4 MB
 890                 LOG_DETAILS="testing if logger daemon log rotating works (2/2)"
 891                 [ "$RESULT" -lt 6144 ] && ok || fail # Max 6 MB
 892
 893                 dlogutil -cb main
 894         fi
 895
 896         LOG_DETAILS="testing if the library works with multithreaded app"
 897         dlogutil -f $TESTDIR/dlog_mt_test &
 898         MT_TEST=$!
 899         test_libdlog && ok || fail
 900
 901         sleep 1
 902         kill $MT_TEST
 903         MT_TEST=-1
 904
 905         dlogutil -c
 906         SPAWN_CNT=1000
 907
 908         # Spawn logging scripts and wait for them to finish.
 909         # We launch all the $SPAWN_CNT scripts in a subshell, and then use the wait command in order to
 910         # wait for all the jobs of the subshell, which means all the logging scripts.
 911         # Each of the logging scripts is a new subsubshell which waits a random amount of seconds and then logs
 912         # a single message. This gets us 5 groups of logs separated by a second; there are about 200 logs in each
 913         # group, sent about at the same time.
 914         (
 915                 for i in $(seq 1 $SPAWN_CNT); do
 916                         delay=$(shuf -i 1-5 -n 1)
 917                         ( sleep $delay && dlogsend -b main -t DLOG_TESTSUITE $delay ) &
 918                 done
 919                 wait
 920         )
 921
 922         LOG_DETAILS="testing if libdlogutil sorts by the timestamp correctly"
 923
 924         test_libdlogutil sorting $LIBDLOGUTIL_CORRECT_PID $type && ok || fail
 925
 926         sort_formats="kerneltime time recv_realtime rwtime threadtime long"
 927
 928         for format in $sort_formats; do
 929                 LOG_DETAILS="testing if sorting by timestamp from random sources on heavy load works ($format format)"
 930                 prev_ts=0
 931                 unsorted=""
 932                 prev_line=""
 933
 934                 # collect data and analyze timestamps
 935                 lines=$(dlogutil -b main -d -v $format)
 936                 while read line; do
 937                         # filter out empty lines in "long" format
 938                         [ -z "$line" ] && continue
 939                         # filter out non-timestamp lines in "long" format
 940                         if [ "$format" = "long" ] && [ "$(echo "$line" | sed -re 's/^\[[:print:]*\]$/line_ok/g')" != "line_ok" ]; then
 941                                 continue
 942                         fi
 943
 944                         [ "$line" -eq "$line" ] 2>/dev/null && continue
 945
 946                         ts=$(extract_timestamp "$format" "$line")
 947
 948                         if [ "$ts" -ge "$prev_ts" ]; then
 949                                 prev_ts=$ts
 950                         else
 951                                 printf -v unsorted '%s\n\n%s\n%s' "$unsorted" "$prev_line" "$line"
 952                                 break
 953                         fi
 954                         prev_line=$line
 955                 done <<< "$lines"
 956
 957                 [ -z "$unsorted" ] && ok || fail
 958         done
 959 fi
 960
 961 # show results, clean up and return an exit code
 962
 963 echo "$OKS / $TOTAL tests passed"
 964 echo "$FAILS / $TOTAL tests failed"
 965
 966 if [ "$quick" -eq 1 ]; then
 967         echo "WARNING: quick mode!"
 968         echo "About 20% slowest running tests are disabled. Some functionality might be untested."
 969         echo "Rerun without '--quick' to run all tests."
 970 fi
 971
 972 [ "$FAILS" -eq 0 ]
 973 # THE LINE ABOVE MUST STAY THE LAST COMMAND IN THE FILE!
 974 # This is because it is used to pass the exit code. If another command
 975 # is executed after it, its exit code will be propagated instead.