syscalls/syslog: mitigate reading syslog issue in multiple files

PATCH New Jakub Racek 2 participants 3 messages Apr 4, 2017 – May 31, 2017

Share & tools

Jakub Racek

author

2017-04-04 14:55 UTC #0 lore raw

PATCH 1/1 syscalls/syslog: mitigate reading syslog issue in multiple files

Syslog bash testcases grep syslog file right after writing to it. Since there's only 2 second delay, the file might be checked too soon, making the testcase fail.

There's currently no way to force syslog flush. This patch mitigates the issue by polling the file repeatedly and outputs more info if grepping fails.

Signed-off-by Jakub Racek <[email protected]>

---
 testcases/kernel/syscalls/syslog/syslog-lib.sh | 31 ++++++++++++
 testcases/kernel/syscalls/syslog/syslog01      |  8 ++--
 testcases/kernel/syscalls/syslog/syslog02      | 10 ++--
 testcases/kernel/syscalls/syslog/syslog03      |  6 +--
 testcases/kernel/syscalls/syslog/syslog04      |  7 ++-
 testcases/kernel/syscalls/syslog/syslog05      |  7 +--
 testcases/kernel/syscalls/syslog/syslog07      | 65 ++++++++------------------
 testcases/kernel/syscalls/syslog/syslog08      | 27 ++++++-----
 testcases/kernel/syscalls/syslog/syslog09      | 13 +++---
 testcases/kernel/syscalls/syslog/syslog10      | 13 +++---
 10 files changed, 96 insertions(+), 91 deletions(-)

testcases/kernel/syscalls/syslog/syslog-lib.sh +31 -0

index e166d3a..3afd80f 100755
@@ -151,6 +151,37 @@ restart_syslog_daemon()
 	fi
 }
 
+check_syslog_content()
+{
+	logfile=$1
+	newvalue_getter=$2
+	oldvalue_getter=$3
+	cond=$4
+	attempts=$5
+
+	for i in `seq 1 $attempts`;
+	do
+		tst_resm TINFO "reading $logfile, attempt $i"
+
+		if [ $(( `eval $newvalue_getter` - `eval $oldvalue_getter` )) $cond ]; then
+			return 0
+		fi
+		sleep 1
+	done
+
+	tst_resm TFAIL "expected line is not in syslog - giving up."
+	get_info_on_fail "$logfile"
+	return 1
+}
+
+get_info_on_fail()
+{
+	status_daemon systemd-journald
+	status_daemon rsyslog
+	cat $1
+	set -x
+}
+
 export TST_TOTAL=${TST_TOTAL:=1}
 export TST_COUNT=1
 export TCID=${TCID:="$(basename "$0")"}

testcases/kernel/syscalls/syslog/syslog01 +3 -5

index 2f3aea0..ca9edd2 100755
@@ -78,16 +78,14 @@ syslog_case1()
 
 	# Call syslogtst executable with case number as argument
 	if syslogtst 1 2>/dev/null; then
-
-		sleep 2
-
 		if [ ! -e $MAILLOG ]; then
 			tst_resm TBROK "$MAILLOG no such log file"
 			cleanup 1
 		fi
+		newvalue_getter="grep -c \"syslogtst: mail info test\" $MAILLOG"
+		check_syslog_content "$MAILLOG" "$newvalue_getter" "echo $oldvalue1" "-eq 1" 25
 
-		newvalue1=`grep -c "syslogtst: mail info test" $MAILLOG`
-		if [ "x$(( $newvalue1 - $oldvalue1 ))" != "x1" ]; then
+		if [ $? -ne 0 ]; then
 			status_flag=1
 		fi
 	else

testcases/kernel/syscalls/syslog/syslog02 +5 -5

index 2213ce3..a7e98db 100755
@@ -79,7 +79,6 @@ syslog_case2()
 		if ! syslogtst 2 $level_no 2>/dev/null; then
 			cleanup 1
 		fi
-		sleep 2
 
 		# check if $MAILLOG script exists
 		if [ ! -e "$MAILLOG" ]; then

@@ -87,12 +86,13 @@ syslog_case2()
 			cleanup 1
 		fi
 
-		newvalue=`grep -c "syslogtst: mail $level test" $MAILLOG`
-		diff=$(( $newvalue - $oldvalue ))
-		if [ $diff -eq 0 ]; then
+		newvalue_getter="grep -c \"syslogtst: mail $level test\" $MAILLOG"
+		check_syslog_content "$MAILLOG" "$newvalue_getter" "echo $oldvalue" "-ne 0" 25
+
+		if [ $? -ne 0 ] ; then
 			tst_resm TFAIL "***** Level $level failed *****"
 			status_flag=1
-		elif [ $diff -ge 1 ]; then
+		else
 			tst_resm TPASS "***** Level $level passed *****"
 		fi
 		# Increment the level_no for next level...

testcases/kernel/syscalls/syslog/syslog03 +3 -3

index 31b7fd6..e90040f 100755
@@ -65,16 +65,16 @@ syslog_case3()
 	if ! syslogtst 3 2>/dev/null; then
 		cleanup 1
 	fi
-	sleep 2
 
 	# check if /var/log/messages exists
 	if [ ! -e /var/log/messages ]; then
 		tst_resm TBROK "/var/log/messages no such log file"
 		cleanup 1
 	fi
+	newvalue_getter="grep -c \"SYSLOG_CASE3\" /var/log/messages"
+	check_syslog_content "/var/log/messages" "$newvalue_getter" "echo $oldvalue4" "-eq 1" 25
 
-	newvalue4=`grep -c "SYSLOG_CASE3" /var/log/messages`
-	if [ "x$(( $newvalue4 - $oldvalue4 ))" != x1 ]; then
+	if [ $? -ne 0 ]; then
 		status_flag=1
 	fi
 }

testcases/kernel/syscalls/syslog/syslog04 +3 -4

index d1739d3..45ed809 100755
@@ -61,16 +61,15 @@ syslog_case4()
 		cleanup 1
 	fi
 
-	sleep 2
-
 	# check if /var/log/messages script exists
 	if [ ! -e /var/log/messages ]; then
 		tst_resm TBROK "/var/log/messages no such log file"
 		cleanup 1
 	fi
+	newvalue_getter="grep -c \"\[$log_pid\]: syslogtst: user info test.\" /var/log/messages"
+	check_syslog_content "/var/log/messages" "$newvalue_getter" "echo 0" "-eq 1" 25
 
-	found=`grep -c "\[$log_pid\]: syslogtst: user info test." /var/log/messages`
-	if [ $found -ne 1 ]; then
+	if [ $? -ne 0 ]; then
 		status_flag=1
 	fi
 }

testcases/kernel/syscalls/syslog/syslog05 +4 -3

index 40dd1fa..4d9f036 100755
@@ -70,16 +70,17 @@ syslog_case5()
 	if ! syslogtst 5 2>/dev/null; then
 		cleanup 1
 	fi
-	sleep 2
 
 	# check if /var/log/messages script exists
 	if [ ! -e /var/log/messages ]; then
 		tst_resm TBROK "/var/log/messages no such log file"
 		cleanup 1
 	fi
-	newvalue=`grep -c "syslogtst: info to console test." /var/log/messages`
 
-	if [ "x$(( $newvalue - $oldvalue ))" != "x1" ]; then
+	newvalue_getter="grep -c \"syslogtst: info to console test.\" /var/log/messages"
+	check_syslog_content "/var/log/messages" "$newvalue_getter" "echo $oldvalue" "-eq 1" 25
+
+	if [ $? -ne 0 ]; then
 		status_flag=1
 	fi
 }

testcases/kernel/syscalls/syslog/syslog07 +20 ~~-45~~

95 lines not on this page · raw message

testcases/kernel/syscalls/syslog/syslog08 +15 ~~-12~~

index 5388620..4f69f28 100755
@@ -87,7 +87,7 @@ syslog_case8()
 			status_flag=1
 			return
 		fi
-		sleep 2
+
 		# check if /var/log/maillog script exists
 		for logf in messages maillog
 		do

@@ -97,23 +97,26 @@ syslog_case8()
 			fi
 		done
 
-		new_mail_check=`grep -c "syslogtst: $facility info test." /var/log/maillog`
-		newvalue=`grep -c "syslogtst: $facility info test." /var/log/messages`
-		diff=$(( $newvalue - $oldvalue ))
-		mail_check=$(( $new_mail_check - $old_mail_check ))
-
 		if [ $facility = "mail" ]; then
-			if [ $mail_check -ne 1 ]; then
+			newvalue_getter="grep -c \"syslogtst: $facility info test.\" /var/log/maillog"
+			check_syslog_content "/var/log/maillog" "$newvalue_getter" "echo $old_mail_check" "-eq 1" 25
+
+			if [ $? -ne 0 ]; then
 				tst_resm TFAIL " Facility $facility failed"
 				status_flag=1
-			elif [ $mail_check -eq 1 ]; then
+			else
 				tst_resm TPASS " Facility $facility passed"
 			fi
-		elif [ $diff -ne 1 ]; then
-			tst_resm TFAIL " Facility $facility failed"
-			status_flag=1
 		else
-			tst_resm TPASS " Facility $facility passed"
+			newvalue_getter="grep -c \"syslogtst: $facility info test.\" /var/log/messages"
+			check_syslog_content "/var/log/messages" "$newvalue_getter" "echo $oldvalue" "-eq 1" 25
+
+			if [ $? -ne 0 ]; then
+				tst_resm TFAIL " Facility $facility failed"
+				status_flag=1
+			else
+				tst_resm TPASS " Facility $facility passed"
+			fi
 		fi
 		# Increment the facility_no for next...
 		: $(( facility_no += 1 ))

testcases/kernel/syscalls/syslog/syslog09 +6 -7

index 9cfafa8..3e44524 100755
@@ -67,7 +67,6 @@ syslog_case9()
 	if ! syslogtst 9 2>/dev/null; then
 		cleanup 1
 	fi
-	sleep 2
 
 	# check if /var/log/messages script exists
 	if [ ! -e /var/log/messages ]; then

@@ -75,18 +74,18 @@ syslog_case9()
 		cleanup 1
 	fi
 
-	allow2=`grep -c "syslogtst: error level is logged" /var/log/messages`
-	donot_allow2=`grep -c "syslogtst: warning level not to be logged" /var/log/messages`
+	allow2="grep -c \"syslogtst: error level is logged\" /var/log/messages"
+	donot_allow2="grep -c \"syslogtst: warning level not to be logged\" /var/log/messages"
 
-	diff1=$(( $allow2 - $allow1 ))
-	if [ $diff1 -ne 1 ]; then
+	check_syslog_content "/var/log/messages" "$allow2" "echo $allow1" "-eq 1" 25
+	if [ $? -ne 0 ]; then
 		tst_resm TFAIL "Expected message was not logged...."
 		status_flag=1
 		return
 	fi
 
-	diff2=$(( $donot_allow2 - $donot_allow1 ))
-	if [ $diff2 -ne 0 ]; then
+	check_syslog_content "/var/log/messages" "$donot_allow2" "echo $donot_allow1" "-eq 0" 25
+	if [ $? -ne 0 ]; then
 		tst_resm TFAIL "Unexpected message was logged..."
 		status_flag=1
 	fi

testcases/kernel/syscalls/syslog/syslog10 +6 -7

index 573ab75..e743ec7 100755
@@ -69,7 +69,6 @@ syslog_case10()
 		status_flag=1
 		return
 	fi
-	sleep 2
 
 	# check if /var/log/messages script exists
 	if [ ! -e /var/log/messages ]; then

@@ -77,18 +76,18 @@ syslog_case10()
 		cleanup 1
 	fi
 
-	allow2=`grep -c "syslogtst:10 error level is logged" /var/log/messages`
-	donot_allow2=`grep -c "syslogtst:10 warning level not to be logged" /var/log/messages`
+	allow2="grep -c \"syslogtst:10 error level is logged\" /var/log/messages"
+	donot_allow2="grep -c \"syslogtst:10 warning level not to be logged\" /var/log/messages"
 
-	diff1=$(( $allow2 - $allow1 ))
-	if [ $diff1 -ne 1 ]; then
+	check_syslog_content "/var/log/messages" "$allow2" "echo $allow1" "-eq 1" 25
+	if [ $? -ne 0 ]; then
 		tst_resm TFAIL "Expected message was not logged...."
 		status_flag=1
 		return
 	fi
 
-	diff2=$(( $donot_allow2 - $donot_allow1 ))
-	if [ $diff2 -ne 0 ]; then
+	check_syslog_content "/var/log/messages" "$donot_allow2" "echo $donot_allow1" "-eq 0" 25
+	if [ $? -ne 0 ]; then
 		tst_resm TFAIL "Unexpected message was logged..."
 		status_flag=1
 	fi

Signature · 1 line

1.8.3.1

Cyril Hrubis

2017-05-29 15:51 UTC #1 lore raw

PATCH 1/1 syscalls/syslog: mitigate reading syslog issue in multiple files

Hi!

testcases/kernel/syscalls/syslog/syslog-lib.sh restart_syslog_daemon() · line 158

Quoted 13 lines

testcases/kernel/syscalls/syslog/syslog-lib.sh +5 -0

index e166d3a..3afd80f 100755
@@ -151,6 +151,37 @@ restart_syslog_daemon()
 	fi
 }
 
+check_syslog_content()
+{
+	logfile=$1
+	newvalue_getter=$2
+	oldvalue_getter=$3

The oldvalue seems to be constant, at least I haven't noticed any different getter than 'echo $value', why don't we pass it as constant instead?

testcases/kernel/syscalls/syslog/syslog-lib.sh restart_syslog_daemon() · line 160

Quoted 2 lines

testcases/kernel/syscalls/syslog/syslog-lib.sh +2 -0
+	cond=$4
+	attempts=$5

The 'attempts' value seems to be 25 in all cases, why do we pass it as a parameter in the first place.

testcases/kernel/syscalls/syslog/syslog-lib.sh restart_syslog_daemon() · line 167

Quoted 6 lines

testcases/kernel/syscalls/syslog/syslog-lib.sh +6 -0

+	for i in `seq 1 $attempts`;
+	do
+		tst_resm TINFO "reading $logfile, attempt $i"
+
+		if [ $(( `eval $newvalue_getter` - `eval $oldvalue_getter` )) $cond ]; then
+			return 0

What about returning the difference instead of passing the $cond to this fucntion, then we could do something as:

res=check_syslog_content "$LOG" "$getter" "$oldval" if [ $res -ge 1 ]; then
tst_resm TPASS ...
else
tst_resm TFAIL ...

testcases/kernel/syscalls/syslog/syslog-lib.sh restart_syslog_daemon() · line 169

Quoted 2 lines

testcases/kernel/syscalls/syslog/syslog-lib.sh +2 -0
+		fi
+		sleep 1

Can we shorten the sleep (use tst_sleep with subsecond interval) and increase number of attempts accordingly?

testcases/kernel/syscalls/syslog/syslog-lib.sh restart_syslog_daemon() · line 179

Quoted 10 lines

testcases/kernel/syscalls/syslog/syslog-lib.sh +10 -0

+	done
+
+	tst_resm TFAIL "expected line is not in syslog - giving up."
+	get_info_on_fail "$logfile"
+	return 1
+}
+
+get_info_on_fail()
+{
+	status_daemon systemd-journald

We should first check that systemd-journal is even installed, possibly with command if systemd-journal is a binary that is present in one of the directories in $PATH.

testcases/kernel/syscalls/syslog/syslog-lib.sh restart_syslog_daemon() · line 180

Quoted 1 line

testcases/kernel/syscalls/syslog/syslog-lib.sh +1 -0
+	status_daemon rsyslog

This should use $SYSLOG_DAEMON instead of rsyslog.

Quoted 4 lines

testcases/kernel/syscalls/syslog/syslog-lib.sh +4 -0
+	cat $1
+	set -x
+}
+

Signature · 2 lines

Cyril Hrubis
[email protected]

Jakub Raček

author

2017-05-31 08:39 UTC #2 lore raw

PATCH 1/1 syscalls/syslog: mitigate reading syslog issue in multiple files

Hi,

thanks for the review on this patch, but after some consideration of opinion from someone more experienced, I think this patch shouldn't be applied at all.

We don't know for sure why the test is sporadically failing. And even though I really don't like that busy waiting (e.g. sleep 1 - why 1?), if we apply the patch I posted, we may never know what was wrong and could theoretically miss/mask a worse issue.

I think it would be best to leave this be and write different patch, merely to get more info when failure occurs.

Of course, if you want this patch, then I can make the changes that you suggested and post V2.

Thanks!

Best regards,

Jakub Racek

Quoted 71 lines · Cyril Hrubis

Hi!
testcases/kernel/syscalls/syslog/syslog-lib.sh restart_syslog_daemon() · line 158
Quoted 13 lines
testcases/kernel/syscalls/syslog/syslog-lib.sh +5 -0
index e166d3a..3afd80f 100755
@@ -151,6 +151,37 @@ restart_syslog_daemon()
 	fi
 }
 
+check_syslog_content()
+{
+	logfile=$1
+	newvalue_getter=$2
+	oldvalue_getter=$3
The oldvalue seems to be constant, at least I haven't noticed any different getter than 'echo $value', why don't we pass it as constant instead?
testcases/kernel/syscalls/syslog/syslog-lib.sh restart_syslog_daemon() · line 160
Quoted 2 lines
testcases/kernel/syscalls/syslog/syslog-lib.sh +2 -0
+	cond=$4
+	attempts=$5
The 'attempts' value seems to be 25 in all cases, why do we pass it as a parameter in the first place.
testcases/kernel/syscalls/syslog/syslog-lib.sh restart_syslog_daemon() · line 167
Quoted 6 lines
testcases/kernel/syscalls/syslog/syslog-lib.sh +6 -0
+	for i in `seq 1 $attempts`;
+	do
+		tst_resm TINFO "reading $logfile, attempt $i"
+
+		if [ $(( `eval $newvalue_getter` - `eval $oldvalue_getter` )) $cond ]; then
+			return 0
What about returning the difference instead of passing the $cond to this fucntion, then we could do something as:
res=check_syslog_content "$LOG" "$getter" "$oldval" if [ $res -ge 1 ]; then
tst_resm TPASS ...
else
tst_resm TFAIL ...
testcases/kernel/syscalls/syslog/syslog-lib.sh restart_syslog_daemon() · line 169
Quoted 2 lines
testcases/kernel/syscalls/syslog/syslog-lib.sh +2 -0
+		fi
+		sleep 1
Can we shorten the sleep (use tst_sleep with subsecond interval) and increase number of attempts accordingly?
testcases/kernel/syscalls/syslog/syslog-lib.sh restart_syslog_daemon() · line 179
Quoted 10 lines
testcases/kernel/syscalls/syslog/syslog-lib.sh +10 -0
+	done
+
+	tst_resm TFAIL "expected line is not in syslog - giving up."
+	get_info_on_fail "$logfile"
+	return 1
+}
+
+get_info_on_fail()
+{
+	status_daemon systemd-journald
We should first check that systemd-journal is even installed, possibly with command if systemd-journal is a binary that is present in one of the directories in $PATH.
testcases/kernel/syscalls/syslog/syslog-lib.sh restart_syslog_daemon() · line 180
Quoted 1 line
testcases/kernel/syscalls/syslog/syslog-lib.sh +1 -0
+	status_daemon rsyslog
This should use $SYSLOG_DAEMON instead of rsyslog.
Quoted 4 lines
testcases/kernel/syscalls/syslog/syslog-lib.sh +4 -0
+	cat $1
+	set -x
+}
+