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