From 9828d66bdb1d74d3ae4985ed84815d374672f621 Mon Sep 17 00:00:00 2001
From: Pan Xiuli <xiuli.pan@linux.intel.com>
Date: Fri, 23 Oct 2020 11:09:40 +0000
Subject: [PATCH 01/16] test: verify-sof-firmware-load: use journalctl to get
 kernel logs

Directly use journalctl in the testcase to avoid kernel log missing
issues.

Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>
---
 test-case/verify-sof-firmware-load.sh | 22 ++++++++--------------
 1 file changed, 8 insertions(+), 14 deletions(-)

diff --git a/test-case/verify-sof-firmware-load.sh b/test-case/verify-sof-firmware-load.sh
index 428159c1..f6a601de 100755
--- a/test-case/verify-sof-firmware-load.sh
+++ b/test-case/verify-sof-firmware-load.sh
@@ -20,13 +20,11 @@ source "$(dirname "${BASH_SOURCE[0]}")"/../case-lib/lib.sh
 
 func_opt_parse_option "$@"
 
-if ! alias | grep -q 'Sub-Test'; then
-    # hijack DMESG_LOG_START_LINE which refer dump kernel log in exit function
-    DMESG_LOG_START_LINE=$(sof-get-kernel-line.sh|tail -n 1 |awk '{print $1;}')
-    cmd="sof-kernel-dump.sh"
-else
-    cmd="journalctl --dmesg --no-pager"
-fi
+# hijack DMESG_LOG_START_LINE to dump kernel from file start is not Sub-Test
+# TODO: clean up Sub-Test feature
+alias | grep -q 'Sub-Test' || DMESG_LOG_START_LINE=$(sof-get-kernel-line.sh | tail -n 1 | awk '{print $1;}' )
+
+cmd="journalctl -k -q --no-pager --utc --output=short-monotonic --no-hostname"
 
 dlogi "Checking SOF Firmware load info in kernel log"
 if $cmd | grep -q " sof-audio.*Firmware.*version"; then
@@ -36,12 +34,8 @@ if $cmd | grep -q " sof-audio.*Firmware.*version"; then
     $cmd | grep "Firmware debug build" -A3 | head -n 12
     exit 0
 else
-    printf ' ------\n  debuging with /var/log/kern.log  \n ---- \n'
-    ls -alht /var/log/kern.log
-    grep -na "Linux version" /var/log/kern.log || true
-    printf ' ------\n  cmd was %s, DMESG_LOG_START_LINE was %s  \n ---- \n' \
-            "$cmd" "$DMESG_LOG_START_LINE"
-    journalctl --dmesg --lines 50 --no-pager
-    journalctl --dmesg | grep -C 1 " sof-audio.*Firmware.*version" || true
+    journalctl -k -q --no-pager --utc --output=short-monotonic --no-hostname --lines 50 || true
+    printf ' ------\n  debugging with systemd journalctl  \n ---- \n'
+    systemctl status systemd-journald* || true
     die "Cannot find the sof audio version"
 fi

From 99e1a97ab40132fffae21c1dc3e26a47f9a49c18 Mon Sep 17 00:00:00 2001
From: Pan Xiuli <xiuli.pan@linux.intel.com>
Date: Thu, 22 Oct 2020 09:50:31 +0000
Subject: [PATCH 02/16] tools: sof-get-default-tplg: use journalctl as default
 kernel log reader

use journalctl by default for any kernel log reader usage.
Also add header for the file.

Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>
---
 tools/sof-get-default-tplg.sh | 20 +++++++++-----------
 1 file changed, 9 insertions(+), 11 deletions(-)

diff --git a/tools/sof-get-default-tplg.sh b/tools/sof-get-default-tplg.sh
index 84c3bc2d..0b2e85e9 100755
--- a/tools/sof-get-default-tplg.sh
+++ b/tools/sof-get-default-tplg.sh
@@ -1,14 +1,12 @@
 #!/bin/bash
+#
+# read kernel log to get topology file loaded by SOF driver
+# Example from an apl up2 pcm512x device:
+#
+# sof-audio-pci 0000:00:0e.0: loading topology:intel/sof-tplg/sof-apl-pcm512x.tplg
+#
+# sof-apl-pcm512x.tplg will be returned
+#
 
-# Current: load TPLG file order:
-# dmesg
-# journalctl
-# /var/log/syslog (sof-kernel-dump.sh)
-# Future: possibly be loaded from elsewhere
-# Notice: Only verified on Ubuntu 18.04
-tplg_file=$(dmesg |grep -i topology|awk -F ':' '/tplg/ {print $NF;}'|tail -n 1)
-[[ ! "$tplg_file" ]] && \
-    tplg_file=$(journalctl -k |grep -i topology |awk -F ':' '/tplg/ {print $NF;}'|tail -n 1)
-[[ ! "$tplg_file" ]] && \
-    tplg_file=$(sof-kernel-dump.sh |grep -i topology|awk -F ':' '/tplg/ {print $NF;}'|tail -n 1)
+tplg_file=$(journalctl -k |grep -i topology |awk -F ':' '/tplg/ {print $NF;}'|tail -n 1)
 [[ "$tplg_file" ]] && basename $tplg_file || echo ""

From 0d8bd70db462792d936629fdcb9bbfb4543b0ecf Mon Sep 17 00:00:00 2001
From: Pan Xiuli <xiuli.pan@linux.intel.com>
Date: Fri, 23 Oct 2020 09:14:20 +0000
Subject: [PATCH 03/16] tools: sof-kernel-log-check: fix script direct run

Add path for the sof-dump-status.py to avoid error:
sof-dump-status.py: command not found

Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>
---
 tools/sof-kernel-log-check.sh | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tools/sof-kernel-log-check.sh b/tools/sof-kernel-log-check.sh
index 2fe11ae8..c734648c 100755
--- a/tools/sof-kernel-log-check.sh
+++ b/tools/sof-kernel-log-check.sh
@@ -130,7 +130,7 @@
 begin_line=${1:-1}
 declare err_str ignore_str
 
-platform=$(sof-dump-status.py -p)
+platform=$($(dirname "$0")/sof-dump-status.py -p)
 
 err_str="error|failed|timed out|panic|oops"
 

From e69b36b8ff678388ac2ff1651c97a8386134e45f Mon Sep 17 00:00:00 2001
From: Pan Xiuli <xiuli.pan@linux.intel.com>
Date: Fri, 23 Oct 2020 10:51:41 +0000
Subject: [PATCH 04/16] tools: sof-kernel-log-check: use journalctl to get
 kernel logs

use journalctl to get kernl logs.
use timestamp to split logs for each test case.
replace all test case to use the timestamp

Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>
---
 case-lib/config.sh                            |  6 +--
 case-lib/lib.sh                               |  4 +-
 test-case/check-capture.sh                    |  4 +-
 test-case/check-fw-echo-reference.sh          |  4 +-
 test-case/check-ipc-flood.sh                  |  4 +-
 test-case/check-keyword-detection.sh          |  4 +-
 test-case/check-kmod-load-unload.sh           | 10 ++---
 .../check-pause-release-suspend-resume.sh     |  4 +-
 test-case/check-pause-resume.sh               |  4 +-
 test-case/check-playback.sh                   |  4 +-
 test-case/check-runtime-pm-double-active.sh   |  4 +-
 test-case/check-runtime-pm-status.sh          |  4 +-
 test-case/check-signal-stop-start.sh          |  4 +-
 test-case/check-smart-amplifier.sh            |  4 +-
 test-case/check-suspend-resume-with-audio.sh  |  4 +-
 test-case/check-suspend-resume.sh             |  4 +-
 test-case/check-xrun-injection.sh             |  4 +-
 test-case/multiple-pause-resume.sh            |  4 +-
 test-case/multiple-pipeline-capture.sh        |  4 +-
 test-case/multiple-pipeline-playback.sh       |  4 +-
 test-case/simultaneous-playback-capture.sh    |  4 +-
 test-case/test-speaker.sh                     |  4 +-
 test-case/volume-basic-test.sh                |  4 +-
 tools/sof-kernel-log-check.sh                 | 39 ++++++-------------
 24 files changed, 61 insertions(+), 78 deletions(-)

diff --git a/case-lib/config.sh b/case-lib/config.sh
index f859f168..9c6ba288 100644
--- a/case-lib/config.sh
+++ b/case-lib/config.sh
@@ -20,9 +20,9 @@ declare -A TPLG_IGNORE_LST
 TPLG_IGNORE_LST['pcm']='HDA Digital'
 
 # Will be set by the lib function, don't need to set
-# Catches the last line of /var/log/kern.log, which will be used by
-#   sof-kernel-log-check.
-# KERNEL_LAST_LINE
+# Catches the timestamp for a test case start used by
+# sof-kernel-log-check with journalctl
+# KERNEL_LAST_TIMESTAMP
 
 # If not set will be automatically set by logging_ctl function
 # Test case log root
diff --git a/case-lib/lib.sh b/case-lib/lib.sh
index de53bc2c..0b780843 100644
--- a/case-lib/lib.sh
+++ b/case-lib/lib.sh
@@ -38,10 +38,10 @@ if [ ! "$SOFCARD" ]; then
     SOFCARD=$(grep 'sof-[a-z]' /proc/asound/cards|awk '{print $1;}')
 fi
 
-func_lib_setup_kernel_last_line()
+func_lib_setup_kernel_last_timestamp()
 {
     # shellcheck disable=SC2034 # external script will use it
-    KERNEL_LAST_LINE=$(wc -l /var/log/kern.log|awk '{print $1;}')
+    KERNEL_LAST_TIMESTAMP=$(date +%s)
 }
 
 # This function adds a fake error to dmesg (which is always saved by
diff --git a/test-case/check-capture.sh b/test-case/check-capture.sh
index 2370cb3c..fb719fe3 100755
--- a/test-case/check-capture.sh
+++ b/test-case/check-capture.sh
@@ -59,7 +59,7 @@ file_prefix=${OPT_VALUE_lst['f']}
 
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
 
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 func_lib_check_sudo
 func_pipeline_export $tplg "type:capture & ${OPT_VALUE_lst['S']}"
 
@@ -106,5 +106,5 @@ do
     done
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_LINE
+sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
 exit $?
diff --git a/test-case/check-fw-echo-reference.sh b/test-case/check-fw-echo-reference.sh
index ee9df0fa..d8459e2c 100755
--- a/test-case/check-fw-echo-reference.sh
+++ b/test-case/check-fw-echo-reference.sh
@@ -44,7 +44,7 @@ frequency=${OPT_VALUE_lst['f']}
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
 
 func_pipeline_export $tplg "echo:any"
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 if [ "$PIPELINE_COUNT" != "2" ]; then
     die "Only detect $PIPELINE_COUNT pipeline(s) from topology, but two are needed"
@@ -93,4 +93,4 @@ do
     done
 done
 
-sof-kernel-log-check.sh "$KERNEL_LAST_LINE"
+sof-kernel-log-check.sh "$KERNEL_LAST_TIMESTAMP"
diff --git a/test-case/check-ipc-flood.sh b/test-case/check-ipc-flood.sh
index 0a1ec794..a34f808f 100755
--- a/test-case/check-ipc-flood.sh
+++ b/test-case/check-ipc-flood.sh
@@ -32,7 +32,7 @@ loop_cnt=${OPT_VALUE_lst['l']}
 
 [[ ! "$(sof-kernel-dump.sh|grep 'sof-audio'|grep 'Firmware debug build')" ]] && dlogw "${BASH_SOURCE[0]} need debug version firmware" && exit 2
 
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 func_lib_check_sudo
 
 dlogi "Check sof debug fs environment"
@@ -54,5 +54,5 @@ do
     dmesg | grep "IPC Flood count" -A 2
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_LINE
+sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
 exit 0
diff --git a/test-case/check-keyword-detection.sh b/test-case/check-keyword-detection.sh
index fecfd6c8..96d79bef 100755
--- a/test-case/check-keyword-detection.sh
+++ b/test-case/check-keyword-detection.sh
@@ -55,7 +55,7 @@ duration=${OPT_VALUE_lst['d']}
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
 
 func_pipeline_export $tplg "kpbm:any"
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 if test "$PIPELINE_COUNT" != "1"; then
     die "detected $PIPELINE_COUNT wov pipeline(s) from topology, but 1 is needed"
@@ -154,4 +154,4 @@ do
     done
 done
 
-sof-kernel-log-check.sh "$KERNEL_LAST_LINE"
+sof-kernel-log-check.sh "$KERNEL_LAST_TIMESTAMP"
diff --git a/test-case/check-kmod-load-unload.sh b/test-case/check-kmod-load-unload.sh
index fd3d683a..c006cfbd 100755
--- a/test-case/check-kmod-load-unload.sh
+++ b/test-case/check-kmod-load-unload.sh
@@ -33,7 +33,7 @@ OPT_OPT_lst['p']='pulseaudio'   OPT_DESC_lst['p']='disable pulseaudio on the tes
 OPT_PARM_lst['p']=0             OPT_VALUE_lst['p']=1
 
 func_opt_parse_option "$@"
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 loop_cnt=${OPT_VALUE_lst['l']}
 
@@ -48,7 +48,7 @@ for idx in $(seq 1 $loop_cnt)
 do
     dlogi "===== Starting iteration $idx of $loop_cnt ====="
     ## - 1: remove module section
-    func_lib_setup_kernel_last_line
+    func_lib_setup_kernel_last_timestamp
 
     # After module removal, it takes about 10s for "aplay -l" to show
     # device list, within this 10s, it shows "no soundcard found". Here
@@ -75,10 +75,10 @@ do
 
     ## - 1a: check for errors after removal
     dlogi "checking for general errors after kmod unload with sof-kernel-log-check tool"
-    sof-kernel-log-check.sh "$KERNEL_LAST_LINE" ||
+    sof-kernel-log-check.sh "$KERNEL_LAST_TIMESTAMP" ||
         die "error found after kmod unload is real error, failing"
 
-    func_lib_setup_kernel_last_line
+    func_lib_setup_kernel_last_timestamp
     dlogi "run kmod/sof_insert.sh"
     sudo sof_insert.sh || {
         # FIXME: don't exit the status of dloge(). Use die()
@@ -87,7 +87,7 @@ do
 
     ## - 2a: check for errors after insertion
     dlogi "checking for general errors after kmod insert with sof-kernel-log-check tool"
-    sof-kernel-log-check.sh "$KERNEL_LAST_LINE" ||
+    sof-kernel-log-check.sh "$KERNEL_LAST_TIMESTAMP" ||
         die "Found error(s) in kernel log after module insertion"
 
     dlogi "checking if firmware is loaded successfully"
diff --git a/test-case/check-pause-release-suspend-resume.sh b/test-case/check-pause-release-suspend-resume.sh
index 954301f7..561f5609 100755
--- a/test-case/check-pause-release-suspend-resume.sh
+++ b/test-case/check-pause-release-suspend-resume.sh
@@ -110,7 +110,7 @@ esac
 
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
 
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 dlogi "Entering audio stream expect script with: $cmd -D $pcm -r $rate -c $channel -f $fmt -vv -i $dummy_file -q"
 dlogi "Will enter suspend-resume cycle during paused period of audio stream process"
@@ -180,5 +180,5 @@ if [ $ret -ne 0 ]; then
     [[ $? -ne 0 ]] && dlogw "Kill process catch error"
     exit $ret
 fi
-sof-kernel-log-check.sh $KERNEL_LAST_LINE
+sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
 exit $?
diff --git a/test-case/check-pause-resume.sh b/test-case/check-pause-resume.sh
index 4daca33a..66ca8256 100755
--- a/test-case/check-pause-resume.sh
+++ b/test-case/check-pause-resume.sh
@@ -75,7 +75,7 @@ esac
 [[ -z $file_name ]] && file_name=$dummy_file
 
 func_pipeline_export $tplg "type:$test_mode & ${OPT_VALUE_lst['S']}"
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1))
 do
     channel=$(func_pipeline_parse_value $idx channel)
@@ -126,5 +126,5 @@ END
     sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_LINE
+sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
 exit $?
diff --git a/test-case/check-playback.sh b/test-case/check-playback.sh
index c05df2e8..9a2c91dc 100755
--- a/test-case/check-playback.sh
+++ b/test-case/check-playback.sh
@@ -67,7 +67,7 @@ else
     dlogi "using $file as playback source"
 fi
 
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 func_lib_check_sudo
 func_pipeline_export $tplg "type:playback & ${OPT_VALUE_lst['S']}"
 
@@ -104,4 +104,4 @@ do
     done
 done
 
-sof-kernel-log-check.sh "$KERNEL_LAST_LINE"
+sof-kernel-log-check.sh "$KERNEL_LAST_TIMESTAMP"
diff --git a/test-case/check-runtime-pm-double-active.sh b/test-case/check-runtime-pm-double-active.sh
index 7d0f5453..165d8df3 100755
--- a/test-case/check-runtime-pm-double-active.sh
+++ b/test-case/check-runtime-pm-double-active.sh
@@ -71,7 +71,7 @@ DEV_LST['capture']='/dev/null'
 
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
 func_pipeline_export $tplg "type:any"
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1))
 do
@@ -141,5 +141,5 @@ do
     sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_LINE
+sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
 exit $?
diff --git a/test-case/check-runtime-pm-status.sh b/test-case/check-runtime-pm-status.sh
index d959574f..b8006a68 100755
--- a/test-case/check-runtime-pm-status.sh
+++ b/test-case/check-runtime-pm-status.sh
@@ -65,7 +65,7 @@ DEV_LST['capture']='/dev/null'
 
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
 func_pipeline_export $tplg "type:any"
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1))
 do
@@ -127,5 +127,5 @@ do
     sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_LINE
+sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
 exit $?
diff --git a/test-case/check-signal-stop-start.sh b/test-case/check-signal-stop-start.sh
index a81c15a5..c3a0b6a0 100755
--- a/test-case/check-signal-stop-start.sh
+++ b/test-case/check-signal-stop-start.sh
@@ -56,7 +56,7 @@ case $test_mode in
     ;;
 esac
 
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 func_stop_start_pipeline()
 {
@@ -116,5 +116,5 @@ do
     kill -9 $pid && wait $pid 2>/dev/null
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_LINE
+sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
 exit $?
diff --git a/test-case/check-smart-amplifier.sh b/test-case/check-smart-amplifier.sh
index 214a3843..32e80bd2 100755
--- a/test-case/check-smart-amplifier.sh
+++ b/test-case/check-smart-amplifier.sh
@@ -59,7 +59,7 @@ tplg=${OPT_VALUE_lst['t']}
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
 
 func_pipeline_export $tplg "smart_amp:any"
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 [ "$PIPELINE_COUNT" == "2" ] || die "Only detect $PIPELINE_COUNT pipeline(s) from topology, but two are needed"
 
@@ -114,4 +114,4 @@ do
     done
 done
 
-sof-kernel-log-check.sh "$KERNEL_LAST_LINE"
+sof-kernel-log-check.sh "$KERNEL_LAST_TIMESTAMP"
diff --git a/test-case/check-suspend-resume-with-audio.sh b/test-case/check-suspend-resume-with-audio.sh
index 5368f884..2e79c3bd 100755
--- a/test-case/check-suspend-resume-with-audio.sh
+++ b/test-case/check-suspend-resume-with-audio.sh
@@ -53,7 +53,7 @@ OPT_PARM_lst['f']=1         OPT_VALUE_lst['f']=''
 
 func_opt_parse_option "$@"
 func_lib_check_sudo
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 tplg=${OPT_VALUE_lst['t']}
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
@@ -131,4 +131,4 @@ do
 done
 
 # check full log
-sof-kernel-log-check.sh $KERNEL_LAST_LINE
+sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
diff --git a/test-case/check-suspend-resume.sh b/test-case/check-suspend-resume.sh
index d62f6a93..43159028 100755
--- a/test-case/check-suspend-resume.sh
+++ b/test-case/check-suspend-resume.sh
@@ -41,7 +41,7 @@ OPT_PARM_lst['r']=0         OPT_VALUE_lst['r']=0
 
 func_opt_parse_option "$@"
 func_lib_check_sudo
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 type=${OPT_VALUE_lst['T']}
 # switch type
@@ -91,5 +91,5 @@ do
 done
 
 # check full log
-sof-kernel-log-check.sh $KERNEL_LAST_LINE
+sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
 exit $?
diff --git a/test-case/check-xrun-injection.sh b/test-case/check-xrun-injection.sh
index 803c5670..da05e1d5 100755
--- a/test-case/check-xrun-injection.sh
+++ b/test-case/check-xrun-injection.sh
@@ -43,7 +43,7 @@ interval=${OPT_VALUE_lst['i']}
 
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
 
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 func_lib_check_sudo
 
 case $test_mode in
@@ -122,5 +122,5 @@ do
     kill -9 $pid && wait $pid 2>/dev/null
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_LINE
+sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
 exit $?
diff --git a/test-case/multiple-pause-resume.sh b/test-case/multiple-pause-resume.sh
index 80407815..5b4377bf 100755
--- a/test-case/multiple-pause-resume.sh
+++ b/test-case/multiple-pause-resume.sh
@@ -58,7 +58,7 @@ func_pipeline_export $tplg "type:any"
 
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
 
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 declare -a pipeline_idx_lst
 declare -a cmd_idx_lst
@@ -190,5 +190,5 @@ do
     sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_LINE
+sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
 exit $?
diff --git a/test-case/multiple-pipeline-capture.sh b/test-case/multiple-pipeline-capture.sh
index 6ed9818d..713862e4 100755
--- a/test-case/multiple-pipeline-capture.sh
+++ b/test-case/multiple-pipeline-capture.sh
@@ -51,7 +51,7 @@ max_count=0
 func_pipeline_export $tplg "type:any" # this line will help to get $PIPELINE_COUNT
 # get the min value of TPLG:'pipeline count' with Case:'pipeline count'
 [[ $PIPELINE_COUNT -gt ${OPT_VALUE_lst['c']} ]] && max_count=${OPT_VALUE_lst['c']} || max_count=$PIPELINE_COUNT
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 # now small function define
 declare -A APP_LST DEV_LST
@@ -154,5 +154,5 @@ do
     sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_LINE >/dev/null
+sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP >/dev/null
 exit $?
diff --git a/test-case/multiple-pipeline-playback.sh b/test-case/multiple-pipeline-playback.sh
index e0b97d6d..7eae0e90 100755
--- a/test-case/multiple-pipeline-playback.sh
+++ b/test-case/multiple-pipeline-playback.sh
@@ -51,7 +51,7 @@ max_count=0
 func_pipeline_export $tplg "type:any" # this line will help to get $PIPELINE_COUNT
 # get the min value of TPLG:'pipeline count' with Case:'pipeline count'
 [[ $PIPELINE_COUNT -gt ${OPT_VALUE_lst['c']} ]] && max_count=${OPT_VALUE_lst['c']} || max_count=$PIPELINE_COUNT
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 # now small function define
 declare -A APP_LST DEV_LST
@@ -154,5 +154,5 @@ do
     sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_LINE >/dev/null
+sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP >/dev/null
 exit $?
diff --git a/test-case/simultaneous-playback-capture.sh b/test-case/simultaneous-playback-capture.sh
index e50f515f..28a7d12d 100755
--- a/test-case/simultaneous-playback-capture.sh
+++ b/test-case/simultaneous-playback-capture.sh
@@ -57,7 +57,7 @@ id_lst_str=${id_lst_str/,/} # remove 1st, which is not used
 [[ ${#id_lst_str} -eq 0 ]] && dlogw "no pipeline with both playback and capture capabilities found in $tplg" && exit 2
 func_pipeline_export $tplg "id:$id_lst_str"
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 func_error_exit()
 {
@@ -115,5 +115,5 @@ do
     sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_LINE > /dev/null
+sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP > /dev/null
 exit $?
diff --git a/test-case/test-speaker.sh b/test-case/test-speaker.sh
index 922a6149..e63cb9f6 100755
--- a/test-case/test-speaker.sh
+++ b/test-case/test-speaker.sh
@@ -32,7 +32,7 @@ tplg=${OPT_VALUE_lst['t']}
 
 func_pipeline_export $tplg "type:playback"
 tcnt=${OPT_VALUE_lst['l']}
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1))
 do
     channel=$(func_pipeline_parse_value $idx channel)
@@ -54,5 +54,5 @@ do
     fi
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_LINE
+sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
 exit $?
diff --git a/test-case/volume-basic-test.sh b/test-case/volume-basic-test.sh
index c9983ced..f651baa9 100755
--- a/test-case/volume-basic-test.sh
+++ b/test-case/volume-basic-test.sh
@@ -62,7 +62,7 @@ dlogi "pgalist number = ${#pgalist[@]}"
 
 for i in $(seq 1 $maxloop)
 do
-    func_lib_setup_kernel_last_line
+    func_lib_setup_kernel_last_timestamp
     dlogi "===== Round($i/$maxloop) ====="
     # TODO: need to check command effect
     for i in "${pgalist[@]}"
@@ -80,7 +80,7 @@ do
     sleep 1
 
     dlogi "check dmesg for error"
-    sof-kernel-log-check.sh $KERNEL_LAST_LINE
+    sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
     [[ $? -ne 0 ]] && func_error_exit "dmesg has errors!"
 done
 
diff --git a/tools/sof-kernel-log-check.sh b/tools/sof-kernel-log-check.sh
index c734648c..4476b4f4 100755
--- a/tools/sof-kernel-log-check.sh
+++ b/tools/sof-kernel-log-check.sh
@@ -126,14 +126,11 @@
 # Append some garbage to an ignore pattern to turn it off. Much easier
 # than deleting it.
 
-
-begin_line=${1:-1}
-declare err_str ignore_str
+begin_timestamp=${1:-0}
+declare ignore_str
 
 platform=$($(dirname "$0")/sof-dump-status.py -p)
 
-err_str="error|failed|timed out|panic|oops"
-
 # TODO explain
 # The first string cannot start by |
 ignore_str='error: debugfs write failed to idle -16'
@@ -241,32 +238,18 @@ case "$platform" in
         ;;
 esac
 
-[[ ! "$err_str" ]] && echo "Missing error keyword list" && exit 0
-# dmesg KB size buffer size
-#dmesg_config_define=$(awk -F '=' '/CONFIG_LOG_BUF_SHIFT/ {print $2;}' /boot/config-$(uname -r))
-#dmesg_buffer_size=$( echo $(( (1<<$dmesg_config_define) / 1024 )) )
-# kernel file log buffer size
-#kernel_buffer_size=$(du -k /var/log/kern.log |awk '{print $1;}')
-# now decide using which to catch the kernel log
-#[[ $kernel_buffer_size -lt $dmesg ]] && cmd="dmesg" || cmd="tail -n  +${begin_line}  /var/log/kern.log"
-
-# confirm begin_line is number, if it is not the number, direct using dmesg
-[[ "${begin_line//[0-9]/}" ]] && begin_line=0
-[[ "$begin_line" -eq 0 ]] && cmd="dmesg" || cmd="tail -n  +${begin_line}  /var/log/kern.log"
-
-#echo "run $0 with parameter '$*' for check kernel message error"
+# confirm begin_timestamp is in UNIX timestamp format, otherwise search full log
+journalctlflag="-k -q --no-pager --utc --output=short-iso --no-hostname"
+[[ $begin_timestamp =~ ^[0-9]{10} ]] && cmd="journalctl $journalctlflag --since=@$begin_timestamp" || cmd="journalctl $journalctlflag"
 
-# declare -p cmd
-if [ "$ignore_str" ]; then
-    err=$(   $cmd | grep 'Call Trace' -A5 -B3)$(     $cmd | grep -E "$err_str"|grep -vE "$ignore_str")
-else
-    err=$(   $cmd | grep 'Call Trace' -A5 -B3)$(     $cmd | grep -E "$err_str")
-fi
+declare -p cmd
+# check priority err for error message
+[[ "$ignore_str" ]] && err=$($cmd --priority=err | grep -vE "$ignore_str") || $($cmd --priority=err)
 
-if [ "$err" ]; then
-    echo "$(date -u '+%Y-%m-%d %T %Z')" "[ERROR]" "Caught dmesg error"
+[[ -z "$err" ]] || {
+    echo "$(date -u '+%Y-%m-%d %T %Z')" "[ERROR]" "Caught kernel log error"
     echo "===========================>>"
     echo "$err"
     echo "<<==========================="
     builtin exit 1
-fi
+}

From 23fa1ee5220342a6165a6ea9b398bf4ece62b748 Mon Sep 17 00:00:00 2001
From: Pan Xiuli <xiuli.pan@linux.intel.com>
Date: Wed, 28 Oct 2020 04:06:24 +0000
Subject: [PATCH 05/16] tools: sof-kernel-log-check: add some common error logs
 can be ignored

Add common error logs from systemd, initramfs, atkbd, i801_smbus,
ata3, genirq, DMAR, dw_dmac, proc_thermal, SDWm, touch pad

Those error level logs did not break functionality of the DUTs.

Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>
---
 tools/sof-kernel-log-check.sh | 62 ++++++++++++++++++++++++++++++++++-
 1 file changed, 61 insertions(+), 1 deletion(-)

diff --git a/tools/sof-kernel-log-check.sh b/tools/sof-kernel-log-check.sh
index 4476b4f4..4ab57ee7 100755
--- a/tools/sof-kernel-log-check.sh
+++ b/tools/sof-kernel-log-check.sh
@@ -238,8 +238,68 @@ case "$platform" in
         ;;
 esac
 
+# below are new error level kernel logs from journalctl --priority=err
+# that did not influcen system and can be ignored
+
+# systemd issues can be ignored
+# seen on mutiple platforms
+# systemd[1]: Failed to mount Mount unit for core.
+# systemd[1]: Failed to mount Mount unit for gnome-calculator.
+# systemd[1]: Failed to mount Mount unit for [UNIT].
+ignore_str="$ignore_str"'|systemd\[.\]: Failed to mount Mount unit for'
+
+# initramfs issues can be ignored
+ignore_str="$ignore_str"'|Initramfs unpacking failed'
+
+# keyboard issues can be ignored
+ignore_str="$ignore_str"'|atkbd serio0: Failed to deactivate keyboard on isa0060/serio0'
+ignore_str="$ignore_str"'|atkbd serio0: Failed to enable keyboard on isa0060/serio0'
+
+# smbus issues can be ignored
+ignore_str="$ignore_str"'|i801_smbus 0000:00:..\..: Transaction timeout'
+ignore_str="$ignore_str"'|i801_smbus 0000:00:..\..: Failed terminating the transaction'
+ignore_str="$ignore_str""|i801_smbus 0000:00:..\..: SMBus is busy, can't use it!"
+ignore_str="$ignore_str"'|i801_smbus 0000:00:..\..: Failed to allocate irq .: -16'
+
+# SATA related issue can be ignored is it did not break device
+ignore_str="$ignore_str"'|ata3: COMRESET failed \(errno=-16\)'
+
+# genirq issues can be ignored
+# origin logs seen on GLK platforms
+# genirq: Flags mismatch irq 0. 00000080 (i801_smbus) vs. 00015a00 (timer)
+ignore_str="$ignore_str"'|genirq: Flags mismatch irq .'
+
+# DMAR warnings can be ignored
+# origin logs seen on BDW platforms
+# DMAR: [Firmware Bug]: No firmware reserved region can cover this RMRR [0x00000000ad000000-0x00000000af7fffff], contact BIOS vendor for fixes
+ignore_str="$ignore_str"'|DMAR: \[Firmware Bug\]: No firmware reserved region can cover this RMRR .'
+
+# dw_dmac logs can be ignored
+# origin logs seen on BDW/BYT/CHT platforms
+# dw_dmac INTL9C60:00: Missing DT data
+# dw_dmac INTL9C60:01: Missing DT data
+ignore_str="$ignore_str"'|dw_dmac INTL9C60:..: Missing DT data'
+
+# proc_thermal logs can be ignored
+# origin logs seen on CHT platforms
+# proc_thermal 0000:00:0b.0: No auxiliary DTSs enabled
+ignore_str="$ignore_str"'|proc_thermal 0000:00:..\..: No auxiliary DTSs enabled'
+
+# touch pad logs can be ignored
+# origin logs seen on GLK platforms
+# elan_i2c i2c-ELAN0000:00: invalid report id data (ff)
+ignore_str="$ignore_str"'|elan_i2c i2c-ELAN0000:.*: invalid report id data'
+
+#
+# SDW related logs
+#
+
+# origin logs seen on CML with RT700 platforms
+# rt700 sdw:1:25d:700:0: Bus clash detected
+ignore_str="$ignore_str"'|rt700 sdw:.:.*:700:.: Bus clash detected'
+
 # confirm begin_timestamp is in UNIX timestamp format, otherwise search full log
-journalctlflag="-k -q --no-pager --utc --output=short-iso --no-hostname"
+journalctlflag="-k -q --no-pager --utc --output=short-monotonic --no-hostname"
 [[ $begin_timestamp =~ ^[0-9]{10} ]] && cmd="journalctl $journalctlflag --since=@$begin_timestamp" || cmd="journalctl $journalctlflag"
 
 declare -p cmd

From d4de5178575096d1781cade110e0379c82c8b27a Mon Sep 17 00:00:00 2001
From: Pan Xiuli <xiuli.pan@linux.intel.com>
Date: Wed, 28 Oct 2020 05:33:06 +0000
Subject: [PATCH 06/16] test-case: check-pause-resume: check kernel log in each
 iteration

remove the redundant kernel log check for all case.
enable kernel log check for each iteration.

Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>
---
 test-case/check-pause-resume.sh | 10 ++++------
 1 file changed, 4 insertions(+), 6 deletions(-)

diff --git a/test-case/check-pause-resume.sh b/test-case/check-pause-resume.sh
index 66ca8256..de0ebe92 100755
--- a/test-case/check-pause-resume.sh
+++ b/test-case/check-pause-resume.sh
@@ -75,9 +75,10 @@ esac
 [[ -z $file_name ]] && file_name=$dummy_file
 
 func_pipeline_export $tplg "type:$test_mode & ${OPT_VALUE_lst['S']}"
-func_lib_setup_kernel_last_timestamp
 for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1))
 do
+    # set up timestamp for each iteration
+    func_lib_setup_kernel_last_timestamp
     channel=$(func_pipeline_parse_value $idx channel)
     rate=$(func_pipeline_parse_value $idx rate)
     fmt=$(func_pipeline_parse_value $idx fmt)
@@ -122,9 +123,6 @@ END
         [[ $? -ne 0 ]] && dlogw "Kill process catch error"
         exit $ret
     fi
-    # sof-kernel-log-check script parameter number is 0/Non-Number will force check from dmesg
-    sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
+    # check kernel log for each iteration to catch issues
+    sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP || die "Catch error in kernel log"
 done
-
-sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
-exit $?

From e12e5ee33995476414bd758b6ad18d2f2696b1fe Mon Sep 17 00:00:00 2001
From: Pan Xiuli <xiuli.pan@linux.intel.com>
Date: Wed, 28 Oct 2020 05:43:32 +0000
Subject: [PATCH 07/16] test-case: check-runtime-pm-status: check kernel log in
 each iteration

remove the redundant kernel log check for all case.
enable kernel log check for each iteration.

Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>
---
 test-case/check-runtime-pm-status.sh | 9 ++++-----
 1 file changed, 4 insertions(+), 5 deletions(-)

diff --git a/test-case/check-runtime-pm-status.sh b/test-case/check-runtime-pm-status.sh
index b8006a68..3344dae7 100755
--- a/test-case/check-runtime-pm-status.sh
+++ b/test-case/check-runtime-pm-status.sh
@@ -65,7 +65,6 @@ DEV_LST['capture']='/dev/null'
 
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
 func_pipeline_export $tplg "type:any"
-func_lib_setup_kernel_last_timestamp
 
 for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1))
 do
@@ -83,6 +82,8 @@ do
 
     for i in $(seq 1 $loop_count)
     do
+        # set up timestamp for each iteration
+        func_lib_setup_kernel_last_timestamp
         dlogi "===== Iteration $i of $loop_count for $pcm ====="
         # playback or capture device - check status
         dlogc "$cmd -D $dev -r $rate -c $channel -f $fmt $dummy_file -q"
@@ -122,10 +123,8 @@ do
             func_lib_lsof_error_dump $snd
             exit 1
         fi
+        # check kernel log for each iteration to catch issues
+        sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP || die "Catch error in kernel log"
     done
-
-    sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
-exit $?

From 0a022279d441c95c26a0e4f3e2f3ed2a27cbdca7 Mon Sep 17 00:00:00 2001
From: Pan Xiuli <xiuli.pan@linux.intel.com>
Date: Wed, 28 Oct 2020 05:50:24 +0000
Subject: [PATCH 08/16] test-case: check-ipc-flood: check kernel log in each
 iteration

remove the redundant kernel log check for all case.
enable kernel log check for each iteration.

Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>
---
 test-case/check-ipc-flood.sh | 14 +++++++-------
 1 file changed, 7 insertions(+), 7 deletions(-)

diff --git a/test-case/check-ipc-flood.sh b/test-case/check-ipc-flood.sh
index a34f808f..515917f7 100755
--- a/test-case/check-ipc-flood.sh
+++ b/test-case/check-ipc-flood.sh
@@ -39,20 +39,20 @@ dlogi "Check sof debug fs environment"
 [[ "$(sudo file $ipc_flood_dfs|grep 'No such file')" ]] && dlogw "${BASH_SOURCE[0]} need $ipc_flood_dfs to run the test case" && exit 2
 dlogi "Checking ipc flood test!"
 
-# cleanup dmesg buffer before test
-sudo dmesg -c > /dev/null
-
 for i in $(seq 1 $loop_cnt)
 do
+    # cleanup dmesg buffer for each iteration
+    sudo dmesg -c > /dev/null
+    # set up timestamp for each iteration
+    func_lib_setup_kernel_last_timestamp
     dlogi "===== [$i/$loop_cnt] loop Begin ====="
     dlogc "sudo bash -c 'echo $lpc_loop_cnt > $ipc_flood_dfs'"
     sudo bash -c "'echo $lpc_loop_cnt > $ipc_flood_dfs'"
 
-    sof-kernel-log-check.sh 0 || die "Catched error in dmesg"
+    # check kernel log for each iteration to catch issues
+    sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP || die "Catch error in kernel log"
 
     dlogi "Dumping test logs!"
     dmesg | grep "IPC Flood count" -A 2
-done
 
-sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
-exit 0
+done

From 2fffcb75cbb7041ed02e2de0cb8c984984bea610 Mon Sep 17 00:00:00 2001
From: Pan Xiuli <xiuli.pan@linux.intel.com>
Date: Wed, 28 Oct 2020 05:54:43 +0000
Subject: [PATCH 09/16] test-case: check-suspend-resume: check kernel log in
 each iteration

remove the redundant kernel log check for all case.
enable kernel log check for each iteration.

Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>
---
 test-case/check-suspend-resume.sh | 16 +++++++---------
 1 file changed, 7 insertions(+), 9 deletions(-)

diff --git a/test-case/check-suspend-resume.sh b/test-case/check-suspend-resume.sh
index 43159028..de5a8e15 100755
--- a/test-case/check-suspend-resume.sh
+++ b/test-case/check-suspend-resume.sh
@@ -74,8 +74,8 @@ fi
 for i in $(seq 1 $loop_count)
 do
     dlogi "===== Round($i/$loop_count) ====="
-    # cleanup dmesg befor run case
-    sudo dmesg --clear
+    # set up timestamp for each iteration
+    func_lib_setup_kernel_last_timestamp
     sleep_count=$(cat /sys/power/wakeup_count)
     dlogc "Run the command: rtcwake -m mem -s ${sleep_lst[$i]}"
     sudo rtcwake -m mem -s ${sleep_lst[$i]}
@@ -83,13 +83,11 @@ do
     dlogc "sleep for ${wait_lst[$i]}"
     sleep ${wait_lst[$i]}
     dlogi "Check for the kernel log status"
-    wake_count=$(cat /sys/power/wakeup_count)
-    # sof-kernel-log-check script parameter number is 0/Non-Number will force check from dmesg
-    sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
+    # check kernel log for each iteration to catch issues
+    sof-kernel-log-check.sh "$KERNEL_LAST_TIMESTAMP" || die "Catch error in kernel log"
     # check wakeup count correct
-    [[ $wake_count -le $sleep_count ]] && die "suspend/resume didn't happen, because /sys/power/wakeup_count does not increase"
+    wake_count=$(cat /sys/power/wakeup_count)
+    dlogi "Check for the wakeup_count"
+    [[ $wake_count -gt $sleep_count ]] || die "suspend/resume didn't happen, because /sys/power/wakeup_count does not increase"
 done
 
-# check full log
-sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
-exit $?

From d3b271408e45339b2c9edf6b985d09cc8c768dab Mon Sep 17 00:00:00 2001
From: Pan Xiuli <xiuli.pan@linux.intel.com>
Date: Wed, 28 Oct 2020 05:58:24 +0000
Subject: [PATCH 10/16] test-case: check-suspend-resume-with-audio: check
 kernel log in each iteration

remove the redundant kernel log check for all case.
enable kernel log check for each iteration.
also do some clean up for this script

Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>
---
 test-case/check-suspend-resume-with-audio.sh | 22 +++++++++-----------
 1 file changed, 10 insertions(+), 12 deletions(-)

diff --git a/test-case/check-suspend-resume-with-audio.sh b/test-case/check-suspend-resume-with-audio.sh
index 2e79c3bd..cc33e76c 100755
--- a/test-case/check-suspend-resume-with-audio.sh
+++ b/test-case/check-suspend-resume-with-audio.sh
@@ -53,7 +53,6 @@ OPT_PARM_lst['f']=1         OPT_VALUE_lst['f']=''
 
 func_opt_parse_option "$@"
 func_lib_check_sudo
-func_lib_setup_kernel_last_timestamp
 
 tplg=${OPT_VALUE_lst['t']}
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
@@ -88,6 +87,8 @@ fi
 
 for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1))
 do
+    # set up timestamp for each iteration
+    func_lib_setup_kernel_last_timestamp
     channel=$(func_pipeline_parse_value $idx channel)
     rate=$(func_pipeline_parse_value $idx rate)
     fmt=$(func_pipeline_parse_value $idx fmt)
@@ -111,12 +112,13 @@ do
         ps --ppid $$ -f
         exit 1
     fi
-    $(dirname ${BASH_SOURCE[0]})/check-suspend-resume.sh $(echo $opt)
-    ret=$?
-    [[ $ret -ne 0 ]] && dloge "suspend resume failed" && exit $ret
+    $(dirname ${BASH_SOURCE[0]})/check-suspend-resume.sh $(echo $opt) || die "suspend resume failed"
+
+    # check kernel log for each iteration to catch issues
+    sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP || die "Catch error in kernel log"
+
     # check process status is correct
-    sof-process-state.sh $process_id
-    if [ $? -ne 0 ]; then
+    sof-process-state.sh $process_id || {
         func_lib_lsof_error_dump $snd
         dloge "process status is abnormal"
         dlogi "dump ps for aplay & arecord"
@@ -124,11 +126,7 @@ do
         dlogi "dump ps for child process"
         ps --ppid $$ -f
         exit 1
-    fi
+    }
     dlogi "Killing $cmd_args"
-    kill -9 $process_id
-    sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
+    kill -9 $process_id || true
 done
-
-# check full log
-sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP

From 62a95c6ee48b8298b85294bdb204a0ed6949864f Mon Sep 17 00:00:00 2001
From: Pan Xiuli <xiuli.pan@linux.intel.com>
Date: Wed, 28 Oct 2020 06:04:59 +0000
Subject: [PATCH 11/16] test-case: check-runtime-pm-double-active: check kernel
 log in each iteration

remove the redundant kernel log check for all case.
enable kernel log check for each iteration.

Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>
---
 test-case/check-runtime-pm-double-active.sh | 11 ++++-------
 1 file changed, 4 insertions(+), 7 deletions(-)

diff --git a/test-case/check-runtime-pm-double-active.sh b/test-case/check-runtime-pm-double-active.sh
index 165d8df3..4e2f861b 100755
--- a/test-case/check-runtime-pm-double-active.sh
+++ b/test-case/check-runtime-pm-double-active.sh
@@ -71,7 +71,6 @@ DEV_LST['capture']='/dev/null'
 
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
 func_pipeline_export $tplg "type:any"
-func_lib_setup_kernel_last_timestamp
 
 for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1))
 do
@@ -87,10 +86,10 @@ do
     dummy_file="${DEV_LST[$type]}"
     [[ -z $cmd ]] && dloge "$type is not supported, $cmd, $dummy_file" && exit 2
 
-    # clean up dmesg before the test
-    sudo dmesg -C
     for i in $(seq 1 $loop_count)
     do
+        # set up timestamp for each iteration
+        func_lib_setup_kernel_last_timestamp
         dlogi "===== Iteration $i of $loop_count for $pcm ====="
         # playback or capture device - check status
         dlogc "$cmd -D $dev -r $rate -c $channel -f $fmt $dummy_file -q"
@@ -136,10 +135,8 @@ do
             func_lib_lsof_error_dump $snd
             die "playback/capture failed on $pcm, $dev at $i/$loop_cnt."
         fi
+        # check kernel log for each iteration to catch issues
+        sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP || die "Catch error in kernel log"
     done
-
-    sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
-exit $?

From 8db6f8c18a81d79b082284bc452d18132e2552e2 Mon Sep 17 00:00:00 2001
From: Pan Xiuli <xiuli.pan@linux.intel.com>
Date: Wed, 28 Oct 2020 06:06:21 +0000
Subject: [PATCH 12/16] test-case: multiple-pause-resume: check kernel log in
 each iteration

remove the redundant kernel log check for all case.
enable kernel log check for each iteration.

Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>
---
 test-case/multiple-pause-resume.sh | 14 +++++++-------
 1 file changed, 7 insertions(+), 7 deletions(-)

diff --git a/test-case/multiple-pause-resume.sh b/test-case/multiple-pause-resume.sh
index 5b4377bf..2427a0ee 100755
--- a/test-case/multiple-pause-resume.sh
+++ b/test-case/multiple-pause-resume.sh
@@ -12,7 +12,7 @@ set -e
 ##    expect sleep for sleep time then mocks spacebar keypresses ' ' to
 ##    cause resume action
 ## Case step:
-##    1. run 1st pipeline 
+##    1. run 1st pipeline
 ##    2. pickup any other pipeline
 ##    3. use expect to fake pause/resume in each pipeline
 ##    4. go through with tplg file
@@ -91,7 +91,7 @@ done
 [[ ${#pipeline_idx_lst[*]} -gt ${OPT_VALUE_lst['c']} ]] && max_count=${OPT_VALUE_lst['c']} || max_count=${#pipeline_idx_lst[*]}
 [[ $max_count -eq 1 ]] && dlogw "pipeline count is 1, don't need to run this case" && exit 2
 
-# create combination list 
+# create combination list
 declare -a pipeline_combine_lst
 for i in $(sof-combinatoric.py -n ${#pipeline_idx_lst[*]} -p $max_count)
 do
@@ -145,7 +145,8 @@ max_wait_time=$[ 10 * $repeat_count ]
 for i in $(seq 1 $loop_count)
 do
     dlogi "===== Loop count( $i / $loop_count ) ====="
-    sudo dmesg -c >/dev/null
+    # set up timestamp for each iteration
+    func_lib_setup_kernel_last_timestamp
     for pipeline_combine_str in "${pipeline_combine_lst[@]}"
     do
         unset pid_lst
@@ -165,7 +166,7 @@ do
             [[ ! "$(pidof expect)" ]] && break
         done
         # fix aplay/arecord last output
-        echo 
+        echo
         if [ "$(pidof expect)" ]; then
             dloge "Still have expect process not finished after wait for $max_wait_time"
             # now dump process
@@ -187,8 +188,7 @@ do
             [[ $? -ne 0 ]] && die "pause resume is exit status error"
         done
     done
-    sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
+    # check kernel log for each iteration to catch issues
+    sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP || die "Catch error in kernel log"
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
-exit $?

From 40b6cb84aa079f98a2bf7dd318fbd845691d93c9 Mon Sep 17 00:00:00 2001
From: Pan Xiuli <xiuli.pan@linux.intel.com>
Date: Wed, 28 Oct 2020 05:45:58 +0000
Subject: [PATCH 13/16] test-case: multiple-pipeline-playback: check kernel log
 in each iteration

remove the redundant kernel log check for all case.
enable kernel log check for each iteration.

Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>
---
 test-case/multiple-pipeline-playback.sh | 9 ++++-----
 1 file changed, 4 insertions(+), 5 deletions(-)

diff --git a/test-case/multiple-pipeline-playback.sh b/test-case/multiple-pipeline-playback.sh
index 7eae0e90..41048e42 100755
--- a/test-case/multiple-pipeline-playback.sh
+++ b/test-case/multiple-pipeline-playback.sh
@@ -51,7 +51,6 @@ max_count=0
 func_pipeline_export $tplg "type:any" # this line will help to get $PIPELINE_COUNT
 # get the min value of TPLG:'pipeline count' with Case:'pipeline count'
 [[ $PIPELINE_COUNT -gt ${OPT_VALUE_lst['c']} ]] && max_count=${OPT_VALUE_lst['c']} || max_count=$PIPELINE_COUNT
-func_lib_setup_kernel_last_timestamp
 
 # now small function define
 declare -A APP_LST DEV_LST
@@ -102,6 +101,8 @@ func_error_exit()
 
 for i in $(seq 1 $loop_cnt)
 do
+    # set up timestamp for each iteration
+    func_lib_setup_kernel_last_timestamp
     dlogi "===== Testing: (Loop: $i/$loop_cnt) ====="
     # clean up dmesg
     sudo dmesg -C
@@ -146,13 +147,11 @@ do
     sof-process-state.sh arecord >/dev/null
     [[ $? -eq 1 ]] && func_error_exit "Catch the abnormal process status of arecord"
 
-
     # kill all arecord
     pkill -9 aplay
     pkill -9 arecord
 
-    sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
+    # check kernel log for each iteration to catch issues
+    sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP || die "Catch error in kernel log"
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP >/dev/null
-exit $?

From 62c98eb9e51e6fa6c2dbfcb048f592ac62b9aa8f Mon Sep 17 00:00:00 2001
From: Pan Xiuli <xiuli.pan@linux.intel.com>
Date: Wed, 28 Oct 2020 05:53:02 +0000
Subject: [PATCH 14/16] test-case: multiple-pipeline-capture: check kernel log
 in each iteration

remove the redundant kernel log check for all case.
enable kernel log check for each iteration.

Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>
---
 test-case/multiple-pipeline-capture.sh | 10 ++++------
 1 file changed, 4 insertions(+), 6 deletions(-)

diff --git a/test-case/multiple-pipeline-capture.sh b/test-case/multiple-pipeline-capture.sh
index 713862e4..a4ce93a2 100755
--- a/test-case/multiple-pipeline-capture.sh
+++ b/test-case/multiple-pipeline-capture.sh
@@ -102,9 +102,9 @@ func_error_exit()
 
 for i in $(seq 1 $loop_cnt)
 do
+    # set up timestamp for each iteration
+    func_lib_setup_kernel_last_timestamp
     dlogi "===== Testing: (Loop: $i/$loop_cnt) ====="
-    # clean up dmesg
-    sudo dmesg -C
 
     # start capture:
     func_run_pipeline_with_type "capture"
@@ -146,13 +146,11 @@ do
     sof-process-state.sh aplay >/dev/null
     [[ $? -eq 1 ]] && func_error_exit "Catch the abnormal process status of aplay"
 
-
     # kill all arecord
     pkill -9 arecord
     pkill -9 aplay
 
-    sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
+    # check kernel log for each iteration to catch issues
+    sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP || die "Catch error in kernel log"
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP >/dev/null
-exit $?

From 91e411659d7012c719e8856b4c4257c972e8c845 Mon Sep 17 00:00:00 2001
From: Pan Xiuli <xiuli.pan@linux.intel.com>
Date: Wed, 28 Oct 2020 05:47:36 +0000
Subject: [PATCH 15/16] test-case: simultaneous-playback-capture: check kernel
 log in each iteration

remove the redundant kernel log check for all case.
enable kernel log check for each iteration.

Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>
---
 test-case/simultaneous-playback-capture.sh | 8 ++++----
 1 file changed, 4 insertions(+), 4 deletions(-)

diff --git a/test-case/simultaneous-playback-capture.sh b/test-case/simultaneous-playback-capture.sh
index 28a7d12d..d1d3deeb 100755
--- a/test-case/simultaneous-playback-capture.sh
+++ b/test-case/simultaneous-playback-capture.sh
@@ -57,7 +57,6 @@ id_lst_str=${id_lst_str/,/} # remove 1st, which is not used
 [[ ${#id_lst_str} -eq 0 ]] && dlogw "no pipeline with both playback and capture capabilities found in $tplg" && exit 2
 func_pipeline_export $tplg "id:$id_lst_str"
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
-func_lib_setup_kernel_last_timestamp
 
 func_error_exit()
 {
@@ -69,6 +68,8 @@ func_error_exit()
 
 for i in $(seq 1 $loop_cnt)
 do
+    # set up timestamp for each iteration
+    func_lib_setup_kernel_last_timestamp
     dlogi "===== Testing: (Loop: $i/$loop_cnt) ====="
     # clean up dmesg
     sudo dmesg -C
@@ -112,8 +113,7 @@ do
         kill -9 $arecord_pid && wait $arecord_pid 2>/dev/null
 
     done
-    sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
+    # check kernel log for each iteration to catch issues
+    sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP || die "Catch error in kernel log"
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP > /dev/null
-exit $?

From 43c3ca6a26c1033bb90a9ea0dfcc89c92ad8ebc4 Mon Sep 17 00:00:00 2001
From: Pan Xiuli <xiuli.pan@linux.intel.com>
Date: Wed, 28 Oct 2020 08:31:33 +0000
Subject: [PATCH 16/16] test: verify-sof-firmware-load: flush and sync
 journalctl logs

try to flush and sync journalctl to avoid empty logs.

Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>
---
 test-case/verify-sof-firmware-load.sh | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/test-case/verify-sof-firmware-load.sh b/test-case/verify-sof-firmware-load.sh
index f6a601de..ee0a8645 100755
--- a/test-case/verify-sof-firmware-load.sh
+++ b/test-case/verify-sof-firmware-load.sh
@@ -24,6 +24,9 @@ func_opt_parse_option "$@"
 # TODO: clean up Sub-Test feature
 alias | grep -q 'Sub-Test' || DMESG_LOG_START_LINE=$(sof-get-kernel-line.sh | tail -n 1 | awk '{print $1;}' )
 
+# flush and sync journalctl logs
+sudo journalctl --sync --flush || true
+
 cmd="journalctl -k -q --no-pager --utc --output=short-monotonic --no-hostname"
 
 dlogi "Checking SOF Firmware load info in kernel log"