/*
* Copyright (C) 2013 Linux Test Project
*
* This program is free software; you can redistribute it and/or
* modify it under the terms of version 2 of the GNU General Public
* License as published by the Free Software Foundation.
*
* This program is distributed in the hope that it would be useful,
* but WITHOUT ANY WARRANTY; without even the implied warranty of
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
*
* Further, this software is distributed without any warranty that it
* is free of the rightful claim of any third person regarding
* infringement or the like. Any license provided herein, whether
* implied or otherwise, applies only to this software file. Patent
* licenses, if any, provided herein do not apply to combinations of
* this program with other software, or any other product whatsoever.
*
* You should have received a copy of the GNU General Public License
* along with this program; if not, write the Free Software
* Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
* 02110-1301, USA.
*/
/*
* Test /dev/kmsg based on kernel doc: Documentation/ABI/testing/dev-kmsg
* - read() blocks
* - non-blocking read() fails with EAGAIN
* - partial read fails (buffer smaller than message)
* - can write to /dev/kmsg and message seqno grows
* - first read() after open() returns same message
* - if messages get overwritten, read() returns -EPIPE
* - device supports SEEK_SET, SEEK_END, SEEK_DATA
*/
#define _GNU_SOURCE
#include <sys/types.h>
#include <sys/stat.h>
#include <sys/syscall.h>
#include <sys/wait.h>
#include <errno.h>
#include <fcntl.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <unistd.h>
#include "config.h"
#include "tst_test.h"
#include "lapi/syscalls.h"
#define MSG_PREFIX "LTP kmsg01 "
#define MAX_MSGSIZE 4096
#define NUM_READ_MSGS 3
#define NUM_READ_RETRY 10
#define NUM_OVERWRITE_MSGS 1024
#define PRINTK "/proc/sys/kernel/printk"
#define CONSOLE_LOGLEVEL_QUIET 4
static int console_loglevel = -1;
/*
* inject_msg - write message to /dev/kmsg
* @msg: null-terminated message to inject, should end with \n
*
* RETURNS:
* 0 on success
* -1 on failure, errno reflects write() errno
*/
static int inject_msg(const char *msg)
{
int f;
f = SAFE_OPEN("/dev/kmsg", O_WRONLY);
TEST(write(f, msg, strlen(msg)));
SAFE_CLOSE(f);
errno = TEST_ERRNO;
return TEST_RETURN;
}
/*
* find_msg - find message in kernel ring buffer
* @fd: fd to use, if < 0 function opens /dev/kmsg itself
* @text_to_find: substring to look for in messages
* @buf: buf to store found message
* @bufsize: size of 'buf'
* @first: 1 - return first matching message
* 0 - return last matching message
* RETURNS:
* 0 on success
* -1 on failure
*/
static int find_msg(int fd, const char *text_to_find, char *buf, int bufsize,
int first)
{
int f, msg_found = 0;
char msg[MAX_MSGSIZE + 1];
if (fd < 0) {
f = SAFE_OPEN("/dev/kmsg", O_RDONLY | O_NONBLOCK);
} else {
f = fd;
}
while (1) {
TEST(read(f, msg, MAX_MSGSIZE));
if (TEST_RETURN < 0) {
if (TEST_ERRNO == EAGAIN)
/* there are no more messages */
break;
else if (TEST_ERRNO == EPIPE)
/* current message was overwritten */
continue;
else
tst_brk(TBROK|TTERRNO, "err reading /dev/kmsg");
} else if (TEST_RETURN < bufsize) {
/* lines from kmsg are not NULL terminated */
msg[TEST_RETURN] = '\0';
if (strstr(msg, text_to_find) != NULL) {
strncpy(buf, msg, bufsize);
msg_found = 1;
if (first)
break;
}
}
}
if (fd < 0)
SAFE_CLOSE(f);
if (msg_found)
return 0;
else
return -1;
}
static int get_msg_fields(const char *msg, unsigned long *prio,
unsigned long *seqno)
{
unsigned long s, p;
if (sscanf(msg, "%lu,%lu,", &p, &s) == 2) {
if (prio)
*prio = p;
if (seqno)
*seqno = s;
return 0;
} else {
return 1;
}
}
/*
* timed_read - if possible reads from fd or times out
* @fd: fd to read from
* @timeout_usec: timeout in useconds
*
* RETURNS:
* read bytes on successful read
* -1 on read() error, errno reflects read() errno
* -2 on timeout
*/
static int timed_read(int fd, long timeout_usec)
{
int ret, tmp;
struct timeval timeout;
fd_set read_fds;
FD_ZERO(&read_fds);
FD_SET(fd, &read_fds);
timeout.tv_sec = timeout_usec / 1000000;
timeout.tv_usec = timeout_usec % 1000000;
ret = select(fd + 1, &read_fds, 0, 0, &timeout);
switch (ret) {
case -1:
tst_brk(TBROK|TERRNO, "select failed");
case 0:
/* select timed out */
return -2;
}
return read(fd, &tmp, 1);
}
/*
* timed_read_kmsg - reads file until it reaches end of file,
* read fails or times out. This ignores any
* EPIPE errors.
* @fd: fd to read from
* @timeout_usec: timeout in useconds for every read attempt
*
* RETURNS:
* 0 on read reaching eof
* -1 on read error, errno reflects read() errno
* -2 on timeout
*/
static int timed_read_kmsg(int fd, long timeout_usec)
{
int child, status, ret = 0;
int pipefd[2];
char msg[MAX_MSGSIZE];
if (pipe(pipefd) != 0)
tst_brk(TBROK|TERRNO, "pipe failed");
child = fork();
switch (child) {
case -1:
tst_brk(TBROK|TERRNO, "failed to fork");
case 0:
/* child does all the reading and keeps writing to
* pipe to let parent know that it didn't block */
close(pipefd[0]);
while (1) {
if (write(pipefd[1], "", 1) == -1)
tst_brk(TBROK|TERRNO, "write to pipe");
TEST(read(fd, msg, MAX_MSGSIZE));
if (TEST_RETURN == 0)
break;
if (TEST_RETURN == -1 && TEST_ERRNO != EPIPE) {
ret = TEST_ERRNO;
break;
}
}
close(pipefd[1]);
exit(ret);
}
SAFE_CLOSE(pipefd[1]);
/* parent reads pipe until it reaches eof or until read times out */
do {
TEST(timed_read(pipefd[0], timeout_usec));
} while (TEST_RETURN > 0);
SAFE_CLOSE(pipefd[0]);
/* child is blocked, kill it */
if (TEST_RETURN == -2)
kill(child, SIGTERM);
SAFE_WAITPID(child, &status, 0);
if (WIFEXITED(status)) {
if (WEXITSTATUS(status) == 0) {
return 0;
} else {
errno = WEXITSTATUS(status);
return -1;
}
}
return -2;
}
static void test_read_nonblock(void)
{
int fd;
tst_res(TINFO, "TEST: nonblock read");
fd = SAFE_OPEN("/dev/kmsg", O_RDONLY | O_NONBLOCK);
TEST(timed_read_kmsg(fd, 5000000));
if (TEST_RETURN == -1 && TEST_ERRNO == EAGAIN)
tst_res(TPASS, "non-block read returned EAGAIN");
else
tst_res(TFAIL|TTERRNO, "non-block read returned: %ld",
TEST_RETURN);
SAFE_CLOSE(fd);
}
static void test_read_block(void)
{
int fd;
tst_res(TINFO, "TEST: blocking read");
fd = SAFE_OPEN("/dev/kmsg", O_RDONLY);
TEST(timed_read_kmsg(fd, 500000));
if (TEST_RETURN == -2)
tst_res(TPASS, "read blocked");
else
tst_res(TFAIL|TTERRNO, "read returned: %ld", TEST_RETURN);
SAFE_CLOSE(fd);
}
static void test_partial_read(void)
{
char msg[MAX_MSGSIZE];
int fd;
tst_res(TINFO, "TEST: partial read");
fd = SAFE_OPEN("/dev/kmsg", O_RDONLY | O_NONBLOCK);
TEST(read(fd, msg, 1));
if (TEST_RETURN < 0)
tst_res(TPASS|TTERRNO, "read failed as expected");
else
tst_res(TFAIL, "read returned: %ld", TEST_RETURN);
SAFE_CLOSE(fd);
}
static void test_inject(void)
{
char imsg[MAX_MSGSIZE], imsg_prefixed[MAX_MSGSIZE];
char tmp[MAX_MSGSIZE];
unsigned long prefix, seqno, seqno_last = 0;
int i, facility, prio;
tst_res(TINFO, "TEST: injected messages appear in /dev/kmsg");
srand(time(NULL));
/* test all combinations of prio 0-7, facility 0-15 */
for (i = 0; i < 127; i++) {
prio = (i & 7);
facility = (i >> 3);
sprintf(imsg, MSG_PREFIX"TEST MESSAGE %ld prio: %d, "
"facility: %d\n", random(), prio, facility);
sprintf(imsg_prefixed, "<%d>%s", i, imsg);
if (inject_msg(imsg_prefixed) == -1) {
tst_res(TFAIL|TERRNO, "inject failed");
return;
}
/* check that message appears in log */
if (find_msg(-1, imsg, tmp, sizeof(tmp), 0) == -1) {
tst_res(TFAIL, "failed to find: %s", imsg);
return;
}
/* check that facility is not 0 (LOG_KERN). */
if (get_msg_fields(tmp, &prefix, &seqno) != 0) {
tst_res(TFAIL, "failed to parse seqid: %s", tmp);
return;
}
if (prefix >> 3 == 0) {
tst_res(TFAIL, "facility 0 found: %s", tmp);
return;
}
/* check that seq. number grows */
if (seqno > seqno_last) {
seqno_last = seqno;
} else {
tst_res(TFAIL, "seqno doesn't grow: %lu, "
"last: %lu", seqno, seqno_last);
return;
}
}
tst_res(TPASS, "injected messages found in log");
tst_res(TPASS, "sequence numbers grow as expected");
}
static void test_read_returns_first_message(void)
{
unsigned long seqno[NUM_READ_MSGS + 1];
char msg[MAX_MSGSIZE];
int msgs_match = 1;
int i, fd, j = NUM_READ_RETRY;
/* Open extra fd, which we try to read after reading NUM_READ_MSGS.
* If this read fails with EPIPE, first message was overwritten and
* we should retry the whole test. If it still fails after
* NUM_READ_RETRY attempts, report TWARN */
tst_res(TINFO, "TEST: mult. readers will get same first message");
while (j) {
fd = SAFE_OPEN("/dev/kmsg", O_RDONLY | O_NONBLOCK);
for (i = 0; i < NUM_READ_MSGS; i++) {
if (find_msg(-1, "", msg, sizeof(msg), 1) != 0)
tst_res(TFAIL, "failed to find any message");
if (get_msg_fields(msg, NULL, &seqno[i]) != 0)
tst_res(TFAIL, "failed to parse seqid: %s",
msg);
}
TEST(read(fd, msg, sizeof(msg)));
SAFE_CLOSE(fd);
if (TEST_RETURN != -1)
break;
if (TEST_ERRNO == EPIPE)
tst_res(TINFO, "msg overwritten, retrying");
else
tst_res(TFAIL|TTERRNO, "read failed");
/* give a moment to whoever overwrote first message to finish */
usleep(100000);
j--;
}
if (!j) {
tst_res(TWARN, "exceeded: %d attempts", NUM_READ_RETRY);
return;
}
for (i = 0; i < NUM_READ_MSGS - 1; i++)
if (seqno[i] != seqno[i + 1])
msgs_match = 0;
if (msgs_match) {
tst_res(TPASS, "all readers got same message on first read");
} else {
tst_res(TFAIL, "readers got different messages");
for (i = 0; i < NUM_READ_MSGS; i++)
tst_res(TINFO, "msg%d: %lu\n", i, seqno[i]);
}
}
static void test_messages_overwritten(void)
{
int i, fd;
char msg[MAX_MSGSIZE];
unsigned long first_seqno, seqno;
char filler_str[] = "<7>"MSG_PREFIX"FILLER MESSAGE TO OVERWRITE OTHERS\n";
/* Keep injecting messages until we overwrite first one.
* We know first message is overwritten when its seqno changes */
tst_res(TINFO, "TEST: read returns EPIPE when messages get "
"overwritten");
fd = SAFE_OPEN("/dev/kmsg", O_RDONLY | O_NONBLOCK);
if (find_msg(-1, "", msg, sizeof(msg), 1) == 0
&& get_msg_fields(msg, NULL, &first_seqno) == 0) {
tst_res(TINFO, "first seqno: %lu", first_seqno);
} else {
tst_brk(TBROK, "failed to get first seq. number");
}
while (1) {
if (find_msg(-1, "", msg, sizeof(msg), 1) != 0
|| get_msg_fields(msg, NULL, &seqno) != 0) {
tst_res(TFAIL, "failed to get first seq. number");
break;
}
if (first_seqno != seqno) {
/* first message was overwritten */
tst_res(TINFO, "first seqno now: %lu", seqno);
break;
}
for (i = 0; i < NUM_OVERWRITE_MSGS; i++) {
if (inject_msg(filler_str) == -1)
tst_brk(TBROK|TERRNO, "err write to /dev/kmsg");
}
}
/* first message is overwritten, so this next read should fail */
TEST(read(fd, msg, sizeof(msg)));
if (TEST_RETURN == -1 && TEST_ERRNO == EPIPE)
tst_res(TPASS, "read failed with EPIPE as expected");
else
tst_res(TFAIL|TTERRNO, "read returned: %ld", TEST_RETURN);
/* seek position is updated to the next available record */
tst_res(TINFO, "TEST: Subsequent reads() will return available "
"records again");
if (find_msg(fd, "", msg, sizeof(msg), 1) != 0)
tst_res(TFAIL|TTERRNO, "read returned: %ld", TEST_RETURN);
else
tst_res(TPASS, "after EPIPE read returned next record");
SAFE_CLOSE(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_brk(TBROK|TTERRNO, "failed to read /dev/kmsg");
if (TEST_ERRNO == EPIPE)
return -1;
if (get_msg_fields(msg, NULL, seqno) != 0) {
tst_res(TFAIL, "failed to parse seqid: %s", msg);
return -1;
}
return 0;
}
static void test_seek(void)
{
int j, fd, fd2;
char msg[MAX_MSGSIZE];
unsigned long seqno[2], tmp;
int ret = 0;
/* 1. read() after SEEK_SET 0 returns same (first) message */
tst_res(TINFO, "TEST: seek SEEK_SET 0");
for (j = 0; j < NUM_READ_RETRY && !ret; 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 moment to whoever overwrote
* first message to finish.
*/
if (j)
usleep(100000);
/*
* 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("/dev/kmsg", O_RDONLY | O_NONBLOCK);
fd2 = SAFE_OPEN("/dev/kmsg", O_RDONLY | O_NONBLOCK);
if (read_msg_seqno(fd, &seqno[0]))
goto close_fds;
if (lseek(fd, 0, SEEK_SET) == -1) {
tst_res(TFAIL|TERRNO, "SEEK_SET 0 failed");
ret = -1;
goto close_fds;
}
if (read_msg_seqno(fd, &seqno[1]))
goto close_fds;
if (read_msg_seqno(fd2, &tmp))
goto close_fds;
ret = 1;
close_fds:
SAFE_CLOSE(fd);
SAFE_CLOSE(fd2);
}
if (j == NUM_READ_RETRY) {
tst_res(TWARN, "exceeded: %d attempts", NUM_READ_RETRY);
} else if (ret > 0) {
if (seqno[0] != seqno[1]) {
tst_res(TFAIL, "SEEK_SET 0, %lu != %lu",
seqno[0], seqno[1]);
} else {
tst_res(TPASS, "SEEK_SET 0");
}
}
/* 2. messages after SEEK_END 0 shouldn't contain MSG_PREFIX */
fd = SAFE_OPEN("/dev/kmsg", O_RDONLY | O_NONBLOCK);
tst_res(TINFO, "TEST: seek SEEK_END 0");
if (lseek(fd, 0, SEEK_END) == -1)
tst_res(TFAIL|TERRNO, "lseek SEEK_END 0 failed");
if (find_msg(fd, MSG_PREFIX, msg, sizeof(msg), 0) != 0)
tst_res(TPASS, "SEEK_END 0");
else
tst_res(TFAIL, "SEEK_END 0 found: %s", msg);
#ifdef SEEK_DATA
/* 3. messages after SEEK_DATA 0 shouldn't contain MSG_PREFIX */
tst_res(TINFO, "TEST: seek SEEK_DATA 0");
/* clear ring buffer */
if (tst_syscall(__NR_syslog, 5, NULL, 0) == -1)
tst_brk(TBROK|TERRNO, "syslog clear failed");
if (lseek(fd, 0, SEEK_DATA) == -1)
tst_res(TFAIL|TERRNO, "lseek SEEK_DATA 0 failed");
if (find_msg(fd, MSG_PREFIX, msg, sizeof(msg), 0) != 0)
tst_res(TPASS, "SEEK_DATA 0");
else
tst_res(TFAIL, "SEEK_DATA 0 found: %s", msg);
#endif
SAFE_CLOSE(fd);
}
static void test_kmsg(void)
{
/* run test_inject first so log isn't empty for other tests */
test_inject();
test_read_nonblock();
test_read_block();
test_partial_read();
test_read_returns_first_message();
test_messages_overwritten();
test_seek();
}
static void setup(void)
{
if (access(PRINTK, F_OK) == 0) {
SAFE_FILE_SCANF(PRINTK, "%d", &console_loglevel);
SAFE_FILE_PRINTF(PRINTK, "%d", CONSOLE_LOGLEVEL_QUIET);
}
}
static void cleanup(void)
{
if (console_loglevel != -1)
SAFE_FILE_PRINTF(PRINTK, "%d", console_loglevel);
}
static struct tst_test test = {
.setup = setup,
.cleanup = cleanup,
.needs_root = 1,
.test_all = test_kmsg,
.min_kver = "3.5.0"
};