kmsg01: fix race in SEEK_SET 0 test

PATCH New Jan Stancek 2 participants 4 messages Mar 2, 2017 – Mar 6, 2017

Share & tools

Jan Stancek

author

2017-03-02 09:42 UTC #0 lore raw

PATCH 1/1 kmsg01: fix race in SEEK_SET 0 test

This test does following:
1. open /dev/kmsg
2. read seqno
3. calls SEEK_SET 0
4. read seqno again
5. compare if they match

Problem is that SEEK_SET resets index and sequence number to first record stored in the buffer (see devkmsg_llseek() in kernel/printk.c). So, if first record gets overwritten between 2) and 3) we don't get EPIPE from second read, test doesn't retry and fails.

This patch opens one more file descriptor (fd2) at the beginning of test, solely for the purpose to check if first record went away.

Signed-off-by Jan Stancek <[email protected]>

---
 testcases/kernel/logging/kmsg/kmsg01.c | 98 +++++++++++++++++++++-------------
 1 file changed, 61 insertions(+), 37 deletions(-)

testcases/kernel/logging/kmsg/kmsg01.c +61 ~~-37~~

index 07419da05de0..bc418660e9eb 100644
@@ -473,63 +473,87 @@ static void test_messages_overwritten(void)
 	SAFE_CLOSE(cleanup, fd);
 }
 
+static int read_msg_seqno(int fd, unsigned long *seqno)
+{
+	char msg[MAX_MSGSIZE];
+
+	TEST(read(fd, msg, sizeof(msg)));
+	if (TEST_RETURN == -1 && TEST_ERRNO != EPIPE) {
+		tst_brkm(TBROK|TTERRNO, cleanup,
+			"failed to read /dev/kmsg");
+	}
+
+	if (get_msg_fields(msg, NULL, seqno) != 0) {
+		tst_resm(TFAIL, "failed to parse seqid: %s", msg);
+		return -1;
+	}
+
+	return 0;
+}
+
 static void test_seek(void)
 {
-	int k, j = NUM_READ_RETRY, fd;
+	int j, fd, fd2;
 	char msg[MAX_MSGSIZE];
-	unsigned long seqno[2];
+	unsigned long seqno[2], tmp;
+	int done = 0;
 
 	/* 1. read() after SEEK_SET 0 returns same (first) message */
 	tst_resm(TINFO, "TEST: seek SEEK_SET 0");
 
-	fd = open("/dev/kmsg", O_RDONLY | O_NONBLOCK);
-	if (fd < 0)
-		tst_brkm(TBROK|TERRNO, cleanup,	"failed to open /dev/kmsg");
-
-	while (j) {
-		for (k = 0; k < 2; k++) {
-			TEST(read(fd, msg, sizeof(msg)));
-			if (TEST_RETURN == -1) {
-				if (errno == EPIPE)
-					break;
-				else
-					tst_brkm(TBROK|TTERRNO, cleanup,
-						"failed to read /dev/kmsg");
-			}
-			if (get_msg_fields(msg, NULL, &seqno[k]) != 0)
-				tst_resm(TFAIL, "failed to parse seqid: %s",
-					msg);
-			if (k == 0)
-				if (lseek(fd, 0, SEEK_SET) == -1)
-					tst_resm(TFAIL|TERRNO,
-						"SEEK_SET 0 failed");
+	for (j = 0; j < NUM_READ_RETRY && !done; j++) {
+		/*
+		 * j > 0 means we are trying again, because we most likely
+		 * failed on read returning EPIPE - first message in buffer
+		 * has been overwrittern. Give a second to whoever overwrote
+		 * first message to finish.
+		 */
+		if (j)
+			sleep(1);
+
+		/*
+		 * Open 2 fds. Use fd1 to read seqno1, then seek to
+		 * begininng and read seqno2. Use fd2 to check if
+		 * first entry in buffer got overwritten. If so,
+		 * we'll have to repeat the test.
+		 */
+		fd = SAFE_OPEN(cleanup, "/dev/kmsg", O_RDONLY | O_NONBLOCK);
+		fd2 = SAFE_OPEN(cleanup, "/dev/kmsg", O_RDONLY | O_NONBLOCK);
+
+		if (read_msg_seqno(fd, &seqno[0]))
+			goto close_fds;
+
+		if (lseek(fd, 0, SEEK_SET) == -1) {
+			tst_resm(TFAIL|TERRNO, "SEEK_SET 0 failed");
+			goto done;
 		}
 
-		if (TEST_RETURN != -1)
-			break;
+		if (read_msg_seqno(fd, &seqno[1]))
+			goto close_fds;
 
-		/* give a second to whoever overwrote first message to finish */
-		sleep(1);
-		j--;
+		if (read_msg_seqno(fd2, &tmp))
+			goto close_fds;
 
-		/* read above has returned EPIPE, reopen fd and try again */
+done:
+		done = 1;
+close_fds:
 		SAFE_CLOSE(cleanup, fd);
-		fd = open("/dev/kmsg", O_RDONLY | O_NONBLOCK);
-		if (fd < 0)
-			tst_brkm(TBROK|TERRNO, cleanup,
-				"failed to open /dev/kmsg");
+		SAFE_CLOSE(cleanup, fd2);
 	}
 
-	if (!j) {
+	if (j == NUM_READ_RETRY) {
 		tst_resm(TWARN, "exceeded: %d attempts", NUM_READ_RETRY);
 	} else {
-		if (seqno[0] != seqno[1])
-			tst_resm(TFAIL, "SEEK_SET 0");
-		else
+		if (seqno[0] != seqno[1]) {
+			tst_resm(TFAIL, "SEEK_SET 0, %lu != %lu",
+				seqno[0], seqno[1]);
+		} else {
 			tst_resm(TPASS, "SEEK_SET 0");
+		}
 	}
 
 	/* 2. messages after SEEK_END 0 shouldn't contain MSG_PREFIX */
+	fd = SAFE_OPEN(cleanup, "/dev/kmsg", O_RDONLY | O_NONBLOCK);
 	tst_resm(TINFO, "TEST: seek SEEK_END 0");
 	if (lseek(fd, 0, SEEK_END) == -1)
 		tst_resm(TFAIL|TERRNO, "lseek SEEK_END 0 failed");

Signature · 1 line

1.8.3.1

Cyril Hrubis

2017-03-03 14:36 UTC #1 lore raw

PATCH 1/1 kmsg01: fix race in SEEK_SET 0 test

Hi!

testcases/kernel/logging/kmsg/kmsg01.c static void test_messages_overwritten(void) · line 484

Quoted 9 lines

testcases/kernel/logging/kmsg/kmsg01.c +9 -0

+static int read_msg_seqno(int fd, unsigned long *seqno)
+{
+	char msg[MAX_MSGSIZE];
+
+	TEST(read(fd, msg, sizeof(msg)));
+	if (TEST_RETURN == -1 && TEST_ERRNO != EPIPE) {
+		tst_brkm(TBROK|TTERRNO, cleanup,
+			"failed to read /dev/kmsg");
+	}

Shouldn't we return -1 here on EPIPE as well?

	if (TEST_ERRNO == EPIPE)
		return -1;

Quoted 40 lines

testcases/kernel/logging/kmsg/kmsg01.c +11 ~~-22~~

+	if (get_msg_fields(msg, NULL, seqno) != 0) {
+		tst_resm(TFAIL, "failed to parse seqid: %s", msg);
+		return -1;
+	}
+
+	return 0;
+}
+
 static void test_seek(void)
 {
-	int k, j = NUM_READ_RETRY, fd;
+	int j, fd, fd2;
 	char msg[MAX_MSGSIZE];
-	unsigned long seqno[2];
+	unsigned long seqno[2], tmp;
+	int done = 0;
 
 	/* 1. read() after SEEK_SET 0 returns same (first) message */
 	tst_resm(TINFO, "TEST: seek SEEK_SET 0");
 
-	fd = open("/dev/kmsg", O_RDONLY | O_NONBLOCK);
-	if (fd < 0)
-		tst_brkm(TBROK|TERRNO, cleanup,	"failed to open /dev/kmsg");
-
-	while (j) {
-		for (k = 0; k < 2; k++) {
-			TEST(read(fd, msg, sizeof(msg)));
-			if (TEST_RETURN == -1) {
-				if (errno == EPIPE)
-					break;
-				else
-					tst_brkm(TBROK|TTERRNO, cleanup,
-						"failed to read /dev/kmsg");
-			}
-			if (get_msg_fields(msg, NULL, &seqno[k]) != 0)
-				tst_resm(TFAIL, "failed to parse seqid: %s",
-					msg);
-			if (k == 0)
-				if (lseek(fd, 0, SEEK_SET) == -1)
-					tst_resm(TFAIL|TERRNO,

testcases/kernel/logging/kmsg/kmsg01.c static void test_messages_overwritten(void) · line 512

Quoted 10 lines

testcases/kernel/logging/kmsg/kmsg01.c +9 -1

-						"SEEK_SET 0 failed");
+	for (j = 0; j < NUM_READ_RETRY && !done; j++) {
+		/*
+		 * j > 0 means we are trying again, because we most likely
+		 * failed on read returning EPIPE - first message in buffer
+		 * has been overwrittern. Give a second to whoever overwrote
+		 * first message to finish.
+		 */
+		if (j)
+			sleep(1);

What about changing it to 0.1s here? Or are there processes that keeps feeding the kernel log buffer for a second or more?

Quoted 5 lines

testcases/kernel/logging/kmsg/kmsg01.c +5 -0

+		/*
+		 * Open 2 fds. Use fd1 to read seqno1, then seek to
+		 * begininng and read seqno2. Use fd2 to check if
+		 * first entry in buffer got overwritten. If so,
+		 * we'll have to repeat the test.

testcases/kernel/logging/kmsg/kmsg01.c static void test_messages_overwritten(void) · line 528

Quoted 10 lines

testcases/kernel/logging/kmsg/kmsg01.c +10 -0

+		 */
+		fd = SAFE_OPEN(cleanup, "/dev/kmsg", O_RDONLY | O_NONBLOCK);
+		fd2 = SAFE_OPEN(cleanup, "/dev/kmsg", O_RDONLY | O_NONBLOCK);
+
+		if (read_msg_seqno(fd, &seqno[0]))
+			goto close_fds;
+
+		if (lseek(fd, 0, SEEK_SET) == -1) {
+			tst_resm(TFAIL|TERRNO, "SEEK_SET 0 failed");
+			goto done;

I wonder if this should be tst_brkm() rather than tst_resm(), since as it is we would end up printing the TFAIL message below, or am I mistaken?

Quoted 35 lines

testcases/kernel/logging/kmsg/kmsg01.c +12 ~~-14~~

 		}
 
-		if (TEST_RETURN != -1)
-			break;
+		if (read_msg_seqno(fd, &seqno[1]))
+			goto close_fds;
 
-		/* give a second to whoever overwrote first message to finish */
-		sleep(1);
-		j--;
+		if (read_msg_seqno(fd2, &tmp))
+			goto close_fds;
 
-		/* read above has returned EPIPE, reopen fd and try again */
+done:
+		done = 1;
+close_fds:
 		SAFE_CLOSE(cleanup, fd);
-		fd = open("/dev/kmsg", O_RDONLY | O_NONBLOCK);
-		if (fd < 0)
-			tst_brkm(TBROK|TERRNO, cleanup,
-				"failed to open /dev/kmsg");
+		SAFE_CLOSE(cleanup, fd2);
 	}
 
-	if (!j) {
+	if (j == NUM_READ_RETRY) {
 		tst_resm(TWARN, "exceeded: %d attempts", NUM_READ_RETRY);
 	} else {
-		if (seqno[0] != seqno[1])
-			tst_resm(TFAIL, "SEEK_SET 0");
-		else
+		if (seqno[0] != seqno[1]) {
+			tst_resm(TFAIL, "SEEK_SET 0, %lu != %lu",
+				seqno[0], seqno[1]);

testcases/kernel/logging/kmsg/kmsg01.c static void test_messages_overwritten(void) · line 559

Quoted 10 lines

testcases/kernel/logging/kmsg/kmsg01.c +3 -0

+		} else {
 			tst_resm(TPASS, "SEEK_SET 0");
+		}
 	}
 
 	/* 2. messages after SEEK_END 0 shouldn't contain MSG_PREFIX */
+	fd = SAFE_OPEN(cleanup, "/dev/kmsg", O_RDONLY | O_NONBLOCK);
 	tst_resm(TINFO, "TEST: seek SEEK_END 0");
 	if (lseek(fd, 0, SEEK_END) == -1)
 		tst_resm(TFAIL|TERRNO, "lseek SEEK_END 0 failed");

Otherwise it looks OK.

Signature · 2 lines

Cyril Hrubis
[email protected]

Jan Stancek

author

2017-03-06 08:18 UTC #2 lore raw

PATCH 1/1 kmsg01: fix race in SEEK_SET 0 test

----- Original Message -----

Quoted 19 lines

From: "Cyril Hrubis" <[email protected]>
To: "Jan Stancek" <[email protected]>
Cc: [email protected]
Sent: Friday, 3 March, 2017 3:36:44 PM
Subject: Re: [LTP] [PATCH] kmsg01: fix race in SEEK_SET 0 test
Hi!
testcases/kernel/logging/kmsg/kmsg01.c static void test_messages_overwritten(void) · line 484
Quoted 9 lines
testcases/kernel/logging/kmsg/kmsg01.c +9 -0
+static int read_msg_seqno(int fd, unsigned long *seqno)
+{
+	char msg[MAX_MSGSIZE];
+
+	TEST(read(fd, msg, sizeof(msg)));
+	if (TEST_RETURN == -1 && TEST_ERRNO != EPIPE) {
+		tst_brkm(TBROK|TTERRNO, cleanup,
+			"failed to read /dev/kmsg");
+	}
Shouldn't we return -1 here on EPIPE as well?

Quoted 2 lines

	if (TEST_ERRNO == EPIPE)
		return -1;

Yes, you're right. I had it returning -1 by default, but then switched it to 0 and missed this case.

Quoted 46 lines

testcases/kernel/logging/kmsg/kmsg01.c +15 ~~-23~~

+	if (get_msg_fields(msg, NULL, seqno) != 0) {
+		tst_resm(TFAIL, "failed to parse seqid: %s", msg);
+		return -1;
+	}
+
+	return 0;
+}
+
 static void test_seek(void)
 {
-	int k, j = NUM_READ_RETRY, fd;
+	int j, fd, fd2;
 	char msg[MAX_MSGSIZE];
-	unsigned long seqno[2];
+	unsigned long seqno[2], tmp;
+	int done = 0;
 
 	/* 1. read() after SEEK_SET 0 returns same (first) message */
 	tst_resm(TINFO, "TEST: seek SEEK_SET 0");
 
-	fd = open("/dev/kmsg", O_RDONLY | O_NONBLOCK);
-	if (fd < 0)
-		tst_brkm(TBROK|TERRNO, cleanup,	"failed to open /dev/kmsg");
-
-	while (j) {
-		for (k = 0; k < 2; k++) {
-			TEST(read(fd, msg, sizeof(msg)));
-			if (TEST_RETURN == -1) {
-				if (errno == EPIPE)
-					break;
-				else
-					tst_brkm(TBROK|TTERRNO, cleanup,
-						"failed to read /dev/kmsg");
-			}
-			if (get_msg_fields(msg, NULL, &seqno[k]) != 0)
-				tst_resm(TFAIL, "failed to parse seqid: %s",
-					msg);
-			if (k == 0)
-				if (lseek(fd, 0, SEEK_SET) == -1)
-					tst_resm(TFAIL|TERRNO,
-						"SEEK_SET 0 failed");
+	for (j = 0; j < NUM_READ_RETRY && !done; j++) {
+		/*
+		 * j > 0 means we are trying again, because we most likely
+		 * failed on read returning EPIPE - first message in buffer

Quoted 8 lines

testcases/kernel/logging/kmsg/kmsg01.c static void test_messages_overwritten(void) · line 512
Quoted 5 lines
testcases/kernel/logging/kmsg/kmsg01.c +5 -0
+		 * has been overwrittern. Give a second to whoever overwrote
+		 * first message to finish.
+		 */
+		if (j)
+			sleep(1);
What about changing it to 0.1s here? Or are there processes that keeps feeding the kernel log buffer for a second or more?

Yes, we can go with 0.1.

Quoted 12 lines

testcases/kernel/logging/kmsg/kmsg01.c +11 -0

+		/*
+		 * Open 2 fds. Use fd1 to read seqno1, then seek to
+		 * begininng and read seqno2. Use fd2 to check if
+		 * first entry in buffer got overwritten. If so,
+		 * we'll have to repeat the test.
+		 */
+		fd = SAFE_OPEN(cleanup, "/dev/kmsg", O_RDONLY | O_NONBLOCK);
+		fd2 = SAFE_OPEN(cleanup, "/dev/kmsg", O_RDONLY | O_NONBLOCK);
+
+		if (read_msg_seqno(fd, &seqno[0]))
+			goto close_fds;

Quoted 8 lines

testcases/kernel/logging/kmsg/kmsg01.c static void test_messages_overwritten(void) · line 528
Quoted 4 lines
testcases/kernel/logging/kmsg/kmsg01.c +4 -0
+
+		if (lseek(fd, 0, SEEK_SET) == -1) {
+			tst_resm(TFAIL|TERRNO, "SEEK_SET 0 failed");
+			goto done;
I wonder if this should be tst_brkm() rather than tst_resm(), since as it is we would end up printing the TFAIL message below, or am I mistaken?

I can skip the TFAIL message below, but I find TFAIL here more fitting, because it is directly related to what's being tested.

Quoted 53 lines

Quoted 36 lines

testcases/kernel/logging/kmsg/kmsg01.c +12 ~~-14~~

 		}
 
-		if (TEST_RETURN != -1)
-			break;
+		if (read_msg_seqno(fd, &seqno[1]))
+			goto close_fds;
 
-		/* give a second to whoever overwrote first message to finish */
-		sleep(1);
-		j--;
+		if (read_msg_seqno(fd2, &tmp))
+			goto close_fds;
 
-		/* read above has returned EPIPE, reopen fd and try again */
+done:
+		done = 1;
+close_fds:
 		SAFE_CLOSE(cleanup, fd);
-		fd = open("/dev/kmsg", O_RDONLY | O_NONBLOCK);
-		if (fd < 0)
-			tst_brkm(TBROK|TERRNO, cleanup,
-				"failed to open /dev/kmsg");
+		SAFE_CLOSE(cleanup, fd2);
 	}
 
-	if (!j) {
+	if (j == NUM_READ_RETRY) {
 		tst_resm(TWARN, "exceeded: %d attempts", NUM_READ_RETRY);
 	} else {
-		if (seqno[0] != seqno[1])
-			tst_resm(TFAIL, "SEEK_SET 0");
-		else
+		if (seqno[0] != seqno[1]) {
+			tst_resm(TFAIL, "SEEK_SET 0, %lu != %lu",
+				seqno[0], seqno[1]);

testcases/kernel/logging/kmsg/kmsg01.c static void test_messages_overwritten(void) · line 559

Quoted 10 lines

testcases/kernel/logging/kmsg/kmsg01.c +3 -0

+		} else {
 			tst_resm(TPASS, "SEEK_SET 0");
+		}
 	}
 
 	/* 2. messages after SEEK_END 0 shouldn't contain MSG_PREFIX */
+	fd = SAFE_OPEN(cleanup, "/dev/kmsg", O_RDONLY | O_NONBLOCK);
 	tst_resm(TINFO, "TEST: seek SEEK_END 0");
 	if (lseek(fd, 0, SEEK_END) == -1)
 		tst_resm(TFAIL|TERRNO, "lseek SEEK_END 0 failed");

Otherwise it looks OK.

--
Cyril Hrubis
[email protected]

Cyril Hrubis

2017-03-06 08:29 UTC #3 lore raw

PATCH 1/1 kmsg01: fix race in SEEK_SET 0 test

Hi!

Quoted 20 lines

Quoted 11 lines
Quoted 11 lines
testcases/kernel/logging/kmsg/kmsg01.c +11 -0
+		/*
+		 * Open 2 fds. Use fd1 to read seqno1, then seek to
+		 * begininng and read seqno2. Use fd2 to check if
+		 * first entry in buffer got overwritten. If so,
+		 * we'll have to repeat the test.
+		 */
+		fd = SAFE_OPEN(cleanup, "/dev/kmsg", O_RDONLY | O_NONBLOCK);
+		fd2 = SAFE_OPEN(cleanup, "/dev/kmsg", O_RDONLY | O_NONBLOCK);
+
+		if (read_msg_seqno(fd, &seqno[0]))
+			goto close_fds;
Quoted 8 lines
testcases/kernel/logging/kmsg/kmsg01.c static void test_messages_overwritten(void) · line 528
Quoted 4 lines
testcases/kernel/logging/kmsg/kmsg01.c +4 -0
+
+		if (lseek(fd, 0, SEEK_SET) == -1) {
+			tst_resm(TFAIL|TERRNO, "SEEK_SET 0 failed");
+			goto done;
I wonder if this should be tst_brkm() rather than tst_resm(), since as it is we would end up printing the TFAIL message below, or am I mistaken?

Quoted 2 lines

I can skip the TFAIL message below, but I find TFAIL here more fitting, because it is directly related to what's being tested.

Sounds reasonable, let's go with that.

Signature · 2 lines

Cyril Hrubis
[email protected]