[PATCH blktests] Add use of logger so that syslog files show when each test starts

[PATCH blktests] Add use of logger so that syslog files show when each test starts

[Theodore Ts'o]

Signed-off-by: Theodore Ts'o <tytso@mit.edu>
---
 check | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/check b/check
index f6c3537..ebd87c0 100755
--- a/check
+++ b/check
@@ -319,6 +319,7 @@ _call_test() {
 		local dmesg_marker=""
 		CHECK_DMESG=0
 	fi
+	$LOGGER_PROG "run blktests $TEST_NAME"
 
 	trap _cleanup EXIT
 	if ! TMPDIR="$(mktemp --tmpdir -p "$OUTPUT" -d "tmpdir.${TEST_NAME//\//.}.XXX")"; then
@@ -578,6 +579,8 @@ fi
 eval set -- "$TEMP"
 unset TEMP
 
+LOGGER_PROG="$(type -P logger)" || LOGGER_PROG=true
+
 if [[ -r config ]]; then
 	# shellcheck disable=SC1091
 	. config
-- 
2.18.0.rc0

Re: [PATCH blktests] Add use of logger so that syslog files show when each test starts

[Theodore Y. Ts'o]

Ping?

					- Ted
					
On Mon, Oct 29, 2018 at 12:15:57PM -0400, Theodore Ts'o wrote:
> Signed-off-by: Theodore Ts'o <tytso@mit.edu>
> ---
>  check | 3 +++
>  1 file changed, 3 insertions(+)
> 
> diff --git a/check b/check
> index f6c3537..ebd87c0 100755
> --- a/check
> +++ b/check
> @@ -319,6 +319,7 @@ _call_test() {
>  		local dmesg_marker=""
>  		CHECK_DMESG=0
>  	fi
> +	$LOGGER_PROG "run blktests $TEST_NAME"
>  
>  	trap _cleanup EXIT
>  	if ! TMPDIR="$(mktemp --tmpdir -p "$OUTPUT" -d "tmpdir.${TEST_NAME//\//.}.XXX")"; then
> @@ -578,6 +579,8 @@ fi
>  eval set -- "$TEMP"
>  unset TEMP
>  
> +LOGGER_PROG="$(type -P logger)" || LOGGER_PROG=true
> +
>  if [[ -r config ]]; then
>  	# shellcheck disable=SC1091
>  	. config
> -- 
> 2.18.0.rc0
> 

Re: [PATCH blktests] Add use of logger so that syslog files show when each test starts

[Omar Sandoval]

On Thu, Nov 22, 2018 at 08:02:21PM -0500, Theodore Y. Ts'o wrote:
> Ping?
> 
> 					- Ted
> 					
> On Mon, Oct 29, 2018 at 12:15:57PM -0400, Theodore Ts'o wrote:
> > Signed-off-by: Theodore Ts'o <tytso@mit.edu>
> > ---
> >  check | 3 +++
> >  1 file changed, 3 insertions(+)
> > 
> > diff --git a/check b/check
> > index f6c3537..ebd87c0 100755
> > --- a/check
> > +++ b/check
> > @@ -319,6 +319,7 @@ _call_test() {
> >  		local dmesg_marker=""
> >  		CHECK_DMESG=0
> >  	fi
> > +	$LOGGER_PROG "run blktests $TEST_NAME"
> >  
> >  	trap _cleanup EXIT
> >  	if ! TMPDIR="$(mktemp --tmpdir -p "$OUTPUT" -d "tmpdir.${TEST_NAME//\//.}.XXX")"; then
> > @@ -578,6 +579,8 @@ fi
> >  eval set -- "$TEMP"
> >  unset TEMP
> >  
> > +LOGGER_PROG="$(type -P logger)" || LOGGER_PROG=true
> > +
> >  if [[ -r config ]]; then
> >  	# shellcheck disable=SC1091
> >  	. config
> > -- 
> > 2.18.0.rc0
> > 

Hey, Ted, sorry, I meant to ask you about this in person at LPC but
forgot to. Forgive my ignorance about syslog, but does syslog not pick
up the line we write to dmesg?

Re: [PATCH blktests] Add use of logger so that syslog files show when each test starts

[Theodore Y. Ts'o]

On Mon, Nov 26, 2018 at 09:50:57AM -0800, Omar Sandoval wrote:
> 
> Hey, Ted, sorry, I meant to ask you about this in person at LPC but
> forgot to. Forgive my ignorance about syslog, but does syslog not pick
> up the line we write to dmesg?

Unfortunately, it does not.

root@xfstests-ltm:~# echo foo testing >> /dev/kmsg 
root@xfstests-ltm:~# dmesg | tail
[    7.103899] random: crng init done
[    7.104759] random: 7 urandom warning(s) missed due to ratelimiting
[    7.154525] EDAC MC: Ver: 3.0.0
[    7.221973] EDAC sbridge: Seeking for: PCI ID 8086:2fa0
[    7.221977] EDAC sbridge:  Ver: 1.1.1 
[    7.259154] device-mapper: uevent: version 1.0.3
[    7.267252] device-mapper: ioctl: 4.35.0-ioctl (2016-06-23) initialised: dm-devel@redhat.com
[    7.762306] EXT4-fs (sda1): resizing filesystem from 2620928 to 13106683 blocks
[    8.541258] EXT4-fs (sda1): resized filesystem to 13106683
[840160.646340] foo testing
root@xfstests-ltm:~# tail /var/log/kern.log
root@xfstests-ltm:~# grep kern.log /etc/rsyslog.conf 
kern.*				-/var/log/kern.log

So as you can see nothing written to kern.log, even though we wrote to
/dev/kmsg.

To prove that kern.log will get kernel messages:

root@xfstests-ltm:~# mke2fs -t ext4 -Fq /tmp/foo.img 8M
root@xfstests-ltm:~# mount -t ext4 /tmp/foo.img /mnt
root@xfstests-ltm:~# echo testing > /sys/fs/ext4/loop0/trigger_fs_error 
root@xfstests-ltm:~# tail /var/log/kern.log
Nov 26 13:30:22 xfstests-ltm kernel: [840286.728296] loop: module loaded
Nov 26 13:30:22 xfstests-ltm kernel: [840286.752181] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null)
Nov 26 13:30:41 xfstests-ltm kernel: [840305.773418] EXT4-fs error (device loop0): trigger_test_error:123: comm bash: testing
root@xfstests-ltm:~# 

					- Ted

Re: [PATCH blktests] Add use of logger so that syslog files show when each test starts

[Omar Sandoval]

On Mon, Nov 26, 2018 at 01:32:11PM -0500, Theodore Y. Ts'o wrote:
> On Mon, Nov 26, 2018 at 09:50:57AM -0800, Omar Sandoval wrote:
> > 
> > Hey, Ted, sorry, I meant to ask you about this in person at LPC but
> > forgot to. Forgive my ignorance about syslog, but does syslog not pick
> > up the line we write to dmesg?
> 
> Unfortunately, it does not.
> 
> root@xfstests-ltm:~# echo foo testing >> /dev/kmsg 
> root@xfstests-ltm:~# dmesg | tail
> [    7.103899] random: crng init done
> [    7.104759] random: 7 urandom warning(s) missed due to ratelimiting
> [    7.154525] EDAC MC: Ver: 3.0.0
> [    7.221973] EDAC sbridge: Seeking for: PCI ID 8086:2fa0
> [    7.221977] EDAC sbridge:  Ver: 1.1.1 
> [    7.259154] device-mapper: uevent: version 1.0.3
> [    7.267252] device-mapper: ioctl: 4.35.0-ioctl (2016-06-23) initialised: dm-devel@redhat.com
> [    7.762306] EXT4-fs (sda1): resizing filesystem from 2620928 to 13106683 blocks
> [    8.541258] EXT4-fs (sda1): resized filesystem to 13106683
> [840160.646340] foo testing
> root@xfstests-ltm:~# tail /var/log/kern.log
> root@xfstests-ltm:~# grep kern.log /etc/rsyslog.conf 
> kern.*				-/var/log/kern.log
> 
> So as you can see nothing written to kern.log, even though we wrote to
> /dev/kmsg.
> 
> To prove that kern.log will get kernel messages:
> 
> root@xfstests-ltm:~# mke2fs -t ext4 -Fq /tmp/foo.img 8M
> root@xfstests-ltm:~# mount -t ext4 /tmp/foo.img /mnt
> root@xfstests-ltm:~# echo testing > /sys/fs/ext4/loop0/trigger_fs_error 
> root@xfstests-ltm:~# tail /var/log/kern.log
> Nov 26 13:30:22 xfstests-ltm kernel: [840286.728296] loop: module loaded
> Nov 26 13:30:22 xfstests-ltm kernel: [840286.752181] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null)
> Nov 26 13:30:41 xfstests-ltm kernel: [840305.773418] EXT4-fs error (device loop0): trigger_test_error:123: comm bash: testing
> root@xfstests-ltm:~# 

Hm, what if we output it as KERN_INFO?

diff --git a/check b/check
index f6c3537..9b4765f 100755
--- a/check
+++ b/check
@@ -314,7 +314,7 @@ _call_test() {
 
 	if [[ -w /dev/kmsg ]]; then
 		local dmesg_marker="run blktests $TEST_NAME at ${TEST_RUN["date"]}"
-		echo "$dmesg_marker" >> /dev/kmsg
+		echo "<6>$dmesg_marker" >> /dev/kmsg
 	else
 		local dmesg_marker=""
 		CHECK_DMESG=0

Re: [PATCH blktests] Add use of logger so that syslog files show when each test starts

[Theodore Y. Ts'o]

On Mon, Nov 26, 2018 at 10:37:23AM -0800, Omar Sandoval wrote:
> 
> Hm, what if we output it as KERN_INFO?
> 
> diff --git a/check b/check
> index f6c3537..9b4765f 100755
> --- a/check
> +++ b/check
> @@ -314,7 +314,7 @@ _call_test() {
>  
>  	if [[ -w /dev/kmsg ]]; then
>  		local dmesg_marker="run blktests $TEST_NAME at ${TEST_RUN["date"]}"
> -		echo "$dmesg_marker" >> /dev/kmsg
> +		echo "<6>$dmesg_marker" >> /dev/kmsg
>  	else
>  		local dmesg_marker=""
>  		CHECK_DMESG=0

Still not working, alas.   I tested it via:

root@xfstests-ltm:~# echo "<6>testing 123" >> /dev/kmsg 

It still didn't appear in /var/log/kern.log

				- Ted

Re: [PATCH blktests] Add use of logger so that syslog files show when each test starts

[Omar Sandoval]

On Mon, Nov 26, 2018 at 02:31:29PM -0500, Theodore Y. Ts'o wrote:
> On Mon, Nov 26, 2018 at 10:37:23AM -0800, Omar Sandoval wrote:
> > 
> > Hm, what if we output it as KERN_INFO?
> > 
> > diff --git a/check b/check
> > index f6c3537..9b4765f 100755
> > --- a/check
> > +++ b/check
> > @@ -314,7 +314,7 @@ _call_test() {
> >  
> >  	if [[ -w /dev/kmsg ]]; then
> >  		local dmesg_marker="run blktests $TEST_NAME at ${TEST_RUN["date"]}"
> > -		echo "$dmesg_marker" >> /dev/kmsg
> > +		echo "<6>$dmesg_marker" >> /dev/kmsg
> >  	else
> >  		local dmesg_marker=""
> >  		CHECK_DMESG=0
> 
> Still not working, alas.   I tested it via:
> 
> root@xfstests-ltm:~# echo "<6>testing 123" >> /dev/kmsg 
> 
> It still didn't appear in /var/log/kern.log
> 
> 				- Ted

Ok, well that's my due diligence, so applied. Thanks!