1 // SPDX-License-Identifier: GPL-2.0-or-later
2 /*
3 * Copyright (C) 2013 Linux Test Project
4 */
5 /*
6 * Test /dev/kmsg based on kernel doc: Documentation/ABI/testing/dev-kmsg
7 * - read() blocks
8 * - non-blocking read() fails with EAGAIN
9 * - partial read fails (buffer smaller than message)
10 * - can write to /dev/kmsg and message seqno grows
11 * - first read() after open() returns same message
12 * - if messages get overwritten, read() returns -EPIPE
13 * - device supports SEEK_SET, SEEK_END, SEEK_DATA
14 */
15 #define _GNU_SOURCE
16 #include <sys/types.h>
17 #include <sys/stat.h>
18 #include <sys/syscall.h>
19 #include <sys/wait.h>
20 #include <errno.h>
21 #include <fcntl.h>
22 #include <stdio.h>
23 #include <stdlib.h>
24 #include <string.h>
25 #include <unistd.h>
26 #include "config.h"
27 #include "tst_test.h"
28 #include "lapi/syscalls.h"
29
30 #define MSG_PREFIX "LTP kmsg01 "
31 #define MAX_MSGSIZE 4096
32 #define NUM_READ_MSGS 3
33 #define NUM_READ_RETRY 10
34 #define NUM_OVERWRITE_MSGS 1024
35 #define PRINTK "/proc/sys/kernel/printk"
36 #define CONSOLE_LOGLEVEL_QUIET 4
37
38 static int console_loglevel = -1;
39
40 /*
41 * inject_msg - write message to /dev/kmsg
42 * @msg: null-terminated message to inject, should end with \n
43 *
44 * RETURNS:
45 * 0 on success
46 * -1 on failure, errno reflects write() errno
47 */
inject_msg(const char * msg)48 static int inject_msg(const char *msg)
49 {
50 int f;
51 f = SAFE_OPEN("/dev/kmsg", O_WRONLY);
52 TEST(write(f, msg, strlen(msg)));
53 SAFE_CLOSE(f);
54 errno = TST_ERR;
55 return TST_RET;
56 }
57
58 /*
59 * find_msg - find message in kernel ring buffer
60 * @fd: fd to use, if < 0 function opens /dev/kmsg itself
61 * @text_to_find: substring to look for in messages
62 * @buf: buf to store found message
63 * @bufsize: size of 'buf'
64 * @first: 1 - return first matching message
65 * 0 - return last matching message
66 * RETURNS:
67 * 0 on success
68 * -1 on failure
69 */
find_msg(int fd,const char * text_to_find,char * buf,int bufsize,int first)70 static int find_msg(int fd, const char *text_to_find, char *buf, int bufsize,
71 int first)
72 {
73 int f, msg_found = 0;
74 char msg[MAX_MSGSIZE + 1];
75
76 if (fd < 0) {
77 f = SAFE_OPEN("/dev/kmsg", O_RDONLY | O_NONBLOCK);
78 } else {
79 f = fd;
80 }
81
82 while (1) {
83 TEST(read(f, msg, MAX_MSGSIZE));
84 if (TST_RET < 0) {
85 if (TST_ERR == EAGAIN)
86 /* there are no more messages */
87 break;
88 else if (TST_ERR == EPIPE)
89 /* current message was overwritten */
90 continue;
91 else
92 tst_brk(TBROK|TTERRNO, "err reading /dev/kmsg");
93 } else if (TST_RET < bufsize) {
94 /* lines from kmsg are not NULL terminated */
95 msg[TST_RET] = '\0';
96 if (strstr(msg, text_to_find) != NULL) {
97 strncpy(buf, msg, bufsize);
98 msg_found = 1;
99 if (first)
100 break;
101 }
102 }
103 }
104 if (fd < 0)
105 SAFE_CLOSE(f);
106
107 if (msg_found)
108 return 0;
109 else
110 return -1;
111 }
112
get_msg_fields(const char * msg,unsigned long * prio,unsigned long * seqno)113 static int get_msg_fields(const char *msg, unsigned long *prio,
114 unsigned long *seqno)
115 {
116 unsigned long s, p;
117 if (sscanf(msg, "%lu,%lu,", &p, &s) == 2) {
118 if (prio)
119 *prio = p;
120 if (seqno)
121 *seqno = s;
122 return 0;
123 } else {
124 return 1;
125 }
126 }
127
128 /*
129 * timed_read - if possible reads from fd or times out
130 * @fd: fd to read from
131 * @timeout_usec: timeout in useconds
132 *
133 * RETURNS:
134 * read bytes on successful read
135 * -1 on read() error, errno reflects read() errno
136 * -2 on timeout
137 */
timed_read(int fd,long timeout_usec)138 static int timed_read(int fd, long timeout_usec)
139 {
140 int ret, tmp;
141 struct timeval timeout;
142 fd_set read_fds;
143
144 FD_ZERO(&read_fds);
145 FD_SET(fd, &read_fds);
146 timeout.tv_sec = timeout_usec / 1000000;
147 timeout.tv_usec = timeout_usec % 1000000;
148
149 ret = select(fd + 1, &read_fds, 0, 0, &timeout);
150 switch (ret) {
151 case -1:
152 tst_brk(TBROK|TERRNO, "select failed");
153 case 0:
154 /* select timed out */
155 return -2;
156 }
157
158 return read(fd, &tmp, 1);
159 }
160
161 /*
162 * timed_read_kmsg - reads file until it reaches end of file,
163 * read fails or times out. This ignores any
164 * EPIPE errors.
165 * @fd: fd to read from
166 * @timeout_usec: timeout in useconds for every read attempt
167 *
168 * RETURNS:
169 * 0 on read reaching eof
170 * -1 on read error, errno reflects read() errno
171 * -2 on timeout
172 */
timed_read_kmsg(int fd,long timeout_usec)173 static int timed_read_kmsg(int fd, long timeout_usec)
174 {
175 int child, status, ret = 0;
176 int pipefd[2];
177 char msg[MAX_MSGSIZE];
178
179 if (pipe(pipefd) != 0)
180 tst_brk(TBROK|TERRNO, "pipe failed");
181
182 child = fork();
183 switch (child) {
184 case -1:
185 tst_brk(TBROK|TERRNO, "failed to fork");
186 case 0:
187 /* child does all the reading and keeps writing to
188 * pipe to let parent know that it didn't block */
189 close(pipefd[0]);
190 while (1) {
191 if (write(pipefd[1], "", 1) == -1)
192 tst_brk(TBROK|TERRNO, "write to pipe");
193 TEST(read(fd, msg, MAX_MSGSIZE));
194 if (TST_RET == 0)
195 break;
196 if (TST_RET == -1 && TST_ERR != EPIPE) {
197 ret = TST_ERR;
198 break;
199 }
200 }
201
202 close(pipefd[1]);
203 exit(ret);
204 }
205 SAFE_CLOSE(pipefd[1]);
206
207 /* parent reads pipe until it reaches eof or until read times out */
208 do {
209 TEST(timed_read(pipefd[0], timeout_usec));
210 } while (TST_RET > 0);
211 SAFE_CLOSE(pipefd[0]);
212
213 /* child is blocked, kill it */
214 if (TST_RET == -2)
215 kill(child, SIGTERM);
216 SAFE_WAITPID(child, &status, 0);
217 if (WIFEXITED(status)) {
218 if (WEXITSTATUS(status) == 0) {
219 return 0;
220 } else {
221 errno = WEXITSTATUS(status);
222 return -1;
223 }
224 }
225 return -2;
226 }
227
test_read_nonblock(void)228 static void test_read_nonblock(void)
229 {
230 int fd;
231
232 tst_res(TINFO, "TEST: nonblock read");
233 fd = SAFE_OPEN("/dev/kmsg", O_RDONLY | O_NONBLOCK);
234
235 TEST(timed_read_kmsg(fd, 5000000));
236 if (TST_RET == -1 && TST_ERR == EAGAIN)
237 tst_res(TPASS, "non-block read returned EAGAIN");
238 else
239 tst_res(TFAIL|TTERRNO, "non-block read returned: %ld",
240 TST_RET);
241 SAFE_CLOSE(fd);
242 }
243
test_read_block(void)244 static void test_read_block(void)
245 {
246 int fd;
247
248 tst_res(TINFO, "TEST: blocking read");
249 fd = SAFE_OPEN("/dev/kmsg", O_RDONLY);
250
251 TEST(timed_read_kmsg(fd, 500000));
252 if (TST_RET == -2)
253 tst_res(TPASS, "read blocked");
254 else
255 tst_res(TFAIL|TTERRNO, "read returned: %ld", TST_RET);
256 SAFE_CLOSE(fd);
257 }
258
test_partial_read(void)259 static void test_partial_read(void)
260 {
261 char msg[MAX_MSGSIZE];
262 int fd;
263
264 tst_res(TINFO, "TEST: partial read");
265 fd = SAFE_OPEN("/dev/kmsg", O_RDONLY | O_NONBLOCK);
266
267 TEST(read(fd, msg, 1));
268 if (TST_RET < 0)
269 tst_res(TPASS|TTERRNO, "read failed as expected");
270 else
271 tst_res(TFAIL, "read returned: %ld", TST_RET);
272 SAFE_CLOSE(fd);
273 }
274
test_inject(void)275 static void test_inject(void)
276 {
277 char imsg[MAX_MSGSIZE], imsg_prefixed[MAX_MSGSIZE];
278 char tmp[MAX_MSGSIZE];
279 unsigned long prefix, seqno, seqno_last = 0;
280 int i, facility, prio;
281
282 tst_res(TINFO, "TEST: injected messages appear in /dev/kmsg");
283
284 srand(time(NULL));
285 /* test all combinations of prio 0-7, facility 0-15 */
286 for (i = 0; i < 127; i++) {
287 prio = (i & 7);
288 facility = (i >> 3);
289 sprintf(imsg, MSG_PREFIX"TEST MESSAGE %ld prio: %d, "
290 "facility: %d\n", random(), prio, facility);
291 sprintf(imsg_prefixed, "<%d>%s", i, imsg);
292
293 if (inject_msg(imsg_prefixed) == -1) {
294 tst_res(TFAIL|TERRNO, "inject failed");
295 return;
296 }
297
298 /* check that message appears in log */
299 if (find_msg(-1, imsg, tmp, sizeof(tmp), 0) == -1) {
300 tst_res(TFAIL, "failed to find: %s", imsg);
301 return;
302 }
303
304 /* check that facility is not 0 (LOG_KERN). */
305 if (get_msg_fields(tmp, &prefix, &seqno) != 0) {
306 tst_res(TFAIL, "failed to parse seqid: %s", tmp);
307 return;
308 }
309 if (prefix >> 3 == 0) {
310 tst_res(TFAIL, "facility 0 found: %s", tmp);
311 return;
312 }
313
314 /* check that seq. number grows */
315 if (seqno > seqno_last) {
316 seqno_last = seqno;
317 } else {
318 tst_res(TFAIL, "seqno doesn't grow: %lu, "
319 "last: %lu", seqno, seqno_last);
320 return;
321 }
322 }
323
324 tst_res(TPASS, "injected messages found in log");
325 tst_res(TPASS, "sequence numbers grow as expected");
326 }
327
test_read_returns_first_message(void)328 static void test_read_returns_first_message(void)
329 {
330 unsigned long seqno[NUM_READ_MSGS + 1];
331 char msg[MAX_MSGSIZE];
332 int msgs_match = 1;
333 int i, fd, j = NUM_READ_RETRY;
334
335 /* Open extra fd, which we try to read after reading NUM_READ_MSGS.
336 * If this read fails with EPIPE, first message was overwritten and
337 * we should retry the whole test. If it still fails after
338 * NUM_READ_RETRY attempts, report TWARN */
339 tst_res(TINFO, "TEST: mult. readers will get same first message");
340 while (j) {
341 fd = SAFE_OPEN("/dev/kmsg", O_RDONLY | O_NONBLOCK);
342
343 for (i = 0; i < NUM_READ_MSGS; i++) {
344 if (find_msg(-1, "", msg, sizeof(msg), 1) != 0)
345 tst_res(TFAIL, "failed to find any message");
346 if (get_msg_fields(msg, NULL, &seqno[i]) != 0)
347 tst_res(TFAIL, "failed to parse seqid: %s",
348 msg);
349 }
350
351 TEST(read(fd, msg, sizeof(msg)));
352 SAFE_CLOSE(fd);
353 if (TST_RET != -1)
354 break;
355
356 if (TST_ERR == EPIPE)
357 tst_res(TINFO, "msg overwritten, retrying");
358 else
359 tst_res(TFAIL|TTERRNO, "read failed");
360
361 /* give a moment to whoever overwrote first message to finish */
362 usleep(100000);
363 j--;
364 }
365
366 if (!j) {
367 tst_res(TWARN, "exceeded: %d attempts", NUM_READ_RETRY);
368 return;
369 }
370
371 for (i = 0; i < NUM_READ_MSGS - 1; i++)
372 if (seqno[i] != seqno[i + 1])
373 msgs_match = 0;
374 if (msgs_match) {
375 tst_res(TPASS, "all readers got same message on first read");
376 } else {
377 tst_res(TFAIL, "readers got different messages");
378 for (i = 0; i < NUM_READ_MSGS; i++)
379 tst_res(TINFO, "msg%d: %lu\n", i, seqno[i]);
380 }
381 }
382
test_messages_overwritten(void)383 static void test_messages_overwritten(void)
384 {
385 int i, fd;
386 char msg[MAX_MSGSIZE];
387 unsigned long first_seqno, seqno;
388 char filler_str[] = "<7>"MSG_PREFIX"FILLER MESSAGE TO OVERWRITE OTHERS\n";
389
390 /* Keep injecting messages until we overwrite first one.
391 * We know first message is overwritten when its seqno changes */
392 tst_res(TINFO, "TEST: read returns EPIPE when messages get "
393 "overwritten");
394 fd = SAFE_OPEN("/dev/kmsg", O_RDONLY | O_NONBLOCK);
395
396 if (find_msg(-1, "", msg, sizeof(msg), 1) == 0
397 && get_msg_fields(msg, NULL, &first_seqno) == 0) {
398 tst_res(TINFO, "first seqno: %lu", first_seqno);
399 } else {
400 tst_brk(TBROK, "failed to get first seq. number");
401 }
402
403 while (1) {
404 if (find_msg(-1, "", msg, sizeof(msg), 1) != 0
405 || get_msg_fields(msg, NULL, &seqno) != 0) {
406 tst_res(TFAIL, "failed to get first seq. number");
407 break;
408 }
409 if (first_seqno != seqno) {
410 /* first message was overwritten */
411 tst_res(TINFO, "first seqno now: %lu", seqno);
412 break;
413 }
414 for (i = 0; i < NUM_OVERWRITE_MSGS; i++) {
415 if (inject_msg(filler_str) == -1)
416 tst_brk(TBROK|TERRNO, "err write to /dev/kmsg");
417 }
418 }
419
420 /* first message is overwritten, so this next read should fail */
421 TEST(read(fd, msg, sizeof(msg)));
422 if (TST_RET == -1 && TST_ERR == EPIPE)
423 tst_res(TPASS, "read failed with EPIPE as expected");
424 else
425 tst_res(TFAIL|TTERRNO, "read returned: %ld", TST_RET);
426
427 /* seek position is updated to the next available record */
428 tst_res(TINFO, "TEST: Subsequent reads() will return available "
429 "records again");
430 if (find_msg(fd, "", msg, sizeof(msg), 1) != 0)
431 tst_res(TFAIL|TTERRNO, "read returned: %ld", TST_RET);
432 else
433 tst_res(TPASS, "after EPIPE read returned next record");
434
435 SAFE_CLOSE(fd);
436 }
437
read_msg_seqno(int fd,unsigned long * seqno)438 static int read_msg_seqno(int fd, unsigned long *seqno)
439 {
440 char msg[MAX_MSGSIZE];
441
442 TEST(read(fd, msg, sizeof(msg)));
443 if (TST_RET == -1 && TST_ERR != EPIPE)
444 tst_brk(TBROK|TTERRNO, "failed to read /dev/kmsg");
445
446 if (TST_ERR == EPIPE)
447 return -1;
448
449 if (get_msg_fields(msg, NULL, seqno) != 0) {
450 tst_res(TFAIL, "failed to parse seqid: %s", msg);
451 return -1;
452 }
453
454 return 0;
455 }
456
test_seek(void)457 static void test_seek(void)
458 {
459 int j, fd, fd2;
460 char msg[MAX_MSGSIZE];
461 unsigned long seqno[2], tmp;
462 int ret = 0;
463
464 /* 1. read() after SEEK_SET 0 returns same (first) message */
465 tst_res(TINFO, "TEST: seek SEEK_SET 0");
466
467 for (j = 0; j < NUM_READ_RETRY && !ret; j++) {
468 /*
469 * j > 0 means we are trying again, because we most likely
470 * failed on read returning EPIPE - first message in buffer
471 * has been overwrittern. Give a moment to whoever overwrote
472 * first message to finish.
473 */
474 if (j)
475 usleep(100000);
476
477 /*
478 * Open 2 fds. Use fd1 to read seqno1, then seek to
479 * begininng and read seqno2. Use fd2 to check if
480 * first entry in buffer got overwritten. If so,
481 * we'll have to repeat the test.
482 */
483 fd = SAFE_OPEN("/dev/kmsg", O_RDONLY | O_NONBLOCK);
484 fd2 = SAFE_OPEN("/dev/kmsg", O_RDONLY | O_NONBLOCK);
485
486 if (read_msg_seqno(fd, &seqno[0]))
487 goto close_fds;
488
489 if (lseek(fd, 0, SEEK_SET) == -1) {
490 tst_res(TFAIL|TERRNO, "SEEK_SET 0 failed");
491 ret = -1;
492 goto close_fds;
493 }
494
495 if (read_msg_seqno(fd, &seqno[1]))
496 goto close_fds;
497
498 if (read_msg_seqno(fd2, &tmp))
499 goto close_fds;
500
501 ret = 1;
502 close_fds:
503 SAFE_CLOSE(fd);
504 SAFE_CLOSE(fd2);
505 }
506
507 if (j == NUM_READ_RETRY) {
508 tst_res(TWARN, "exceeded: %d attempts", NUM_READ_RETRY);
509 } else if (ret > 0) {
510 if (seqno[0] != seqno[1]) {
511 tst_res(TFAIL, "SEEK_SET 0, %lu != %lu",
512 seqno[0], seqno[1]);
513 } else {
514 tst_res(TPASS, "SEEK_SET 0");
515 }
516 }
517
518 /* 2. messages after SEEK_END 0 shouldn't contain MSG_PREFIX */
519 fd = SAFE_OPEN("/dev/kmsg", O_RDONLY | O_NONBLOCK);
520 tst_res(TINFO, "TEST: seek SEEK_END 0");
521 if (lseek(fd, 0, SEEK_END) == -1)
522 tst_res(TFAIL|TERRNO, "lseek SEEK_END 0 failed");
523 if (find_msg(fd, MSG_PREFIX, msg, sizeof(msg), 0) != 0)
524 tst_res(TPASS, "SEEK_END 0");
525 else
526 tst_res(TFAIL, "SEEK_END 0 found: %s", msg);
527
528 #ifdef SEEK_DATA
529 /* 3. messages after SEEK_DATA 0 shouldn't contain MSG_PREFIX */
530 tst_res(TINFO, "TEST: seek SEEK_DATA 0");
531
532 /* clear ring buffer */
533 if (tst_syscall(__NR_syslog, 5, NULL, 0) == -1)
534 tst_brk(TBROK|TERRNO, "syslog clear failed");
535 if (lseek(fd, 0, SEEK_DATA) == -1)
536 tst_res(TFAIL|TERRNO, "lseek SEEK_DATA 0 failed");
537 if (find_msg(fd, MSG_PREFIX, msg, sizeof(msg), 0) != 0)
538 tst_res(TPASS, "SEEK_DATA 0");
539 else
540 tst_res(TFAIL, "SEEK_DATA 0 found: %s", msg);
541 #endif
542 SAFE_CLOSE(fd);
543 }
544
test_kmsg(void)545 static void test_kmsg(void)
546 {
547 /* run test_inject first so log isn't empty for other tests */
548 test_inject();
549 test_read_nonblock();
550 test_read_block();
551 test_partial_read();
552 test_read_returns_first_message();
553 test_messages_overwritten();
554 test_seek();
555 }
556
setup(void)557 static void setup(void)
558 {
559 if (access(PRINTK, F_OK) == 0) {
560 SAFE_FILE_SCANF(PRINTK, "%d", &console_loglevel);
561 SAFE_FILE_PRINTF(PRINTK, "%d", CONSOLE_LOGLEVEL_QUIET);
562 }
563 }
564
cleanup(void)565 static void cleanup(void)
566 {
567 if (console_loglevel != -1)
568 SAFE_FILE_PRINTF(PRINTK, "%d", console_loglevel);
569 }
570
571 static struct tst_test test = {
572 .setup = setup,
573 .cleanup = cleanup,
574 .needs_root = 1,
575 .test_all = test_kmsg,
576 .min_kver = "3.5.0"
577 };
578