tests/dlog_test.in

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