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