1 /*
2 * Copyright (C) 2018-2022 Intel Corporation.
3 *
4 * SPDX-License-Identifier: BSD-3-Clause
5 */
6
7 #include <stdio.h>
8 #include <stdlib.h>
9 #include <sys/types.h>
10 #include <linux/types.h>
11 #include <sys/stat.h>
12 #include <fcntl.h>
13 #include <unistd.h>
14 #include <string.h>
15 #include <limits.h>
16 #include <dirent.h>
17 #include <errno.h>
18 #include <pthread.h>
19
20 #define LOG_ELEMENT_SIZE 80
21 #define LOG_MSG_SIZE 480
22 #define DEFAULT_POLL_INTERVAL 100000
23 #define LOG_INCOMPLETE_WARNING "WARNING: logs missing here! "\
24 "Try reducing polling interval"
25
26 /* Count of /dev/acrn_hvlog_cur_xxx */
27 static int cur_cnt,last_cnt;
28 static unsigned long interval = DEFAULT_POLL_INTERVAL;
29
30 /* this is for log file */
31 #define LOG_FILE_SIZE (1024*1024)
32 #define LOG_FILE_NUM 4
33 static size_t hvlog_log_size = LOG_FILE_SIZE;
34 static unsigned short hvlog_log_num = LOG_FILE_NUM;
35
36 struct hvlog_file {
37 const char *path;
38 int fd;
39
40 size_t left_space;
41 unsigned short index;
42 unsigned short num;
43 };
44
45 static struct hvlog_file cur_log = {
46 .path = "/var/log/acrnlog/acrnlog_cur",
47 .fd = -1,
48 .left_space = 0,
49 .index = ~0,
50 .num = LOG_FILE_NUM
51 };
52
53 static struct hvlog_file last_log = {
54 .path = "/var/log/acrnlog/acrnlog_last",
55 .fd = -1,
56 .left_space = 0,
57 .index = ~0,
58 .num = LOG_FILE_NUM
59 };
60
61 struct hvlog_msg {
62 __u64 usec; /* timestamp, from tsc reset in usec */
63 int cpu; /* which physical cpu output the log */
64 int sev; /* log severity level */
65 __u64 seq; /* sequence num, used to reorder logs */
66
67 size_t len; /* length of message raw string */
68 char raw[0]; /* raw log string, end with '\0' */
69 };
70
71 /*
72 * describe the hvlog device, eg., /dev/acrn_hvlog_*
73 * Note: this is thread-unsafe!
74 */
75 struct hvlog_dev {
76 int fd;
77 struct hvlog_msg *msg; /* pointer to msg */
78
79 int latched; /* 1 if an sbuf element latched */
80 char entry_latch[LOG_ELEMENT_SIZE]; /* latch for an sbuf element */
81 struct hvlog_msg latched_msg; /* latch for parsed msg */
82 };
83
84 size_t write_log_file(struct hvlog_file * log, const char *buf, size_t len);
85
get_dev_cnt(char * prefix)86 static int get_dev_cnt(char *prefix)
87 {
88 struct dirent *pdir;
89 int cnt = 0;
90 char *ret;
91 DIR *dir;
92
93 dir = opendir("/dev");
94 if (!dir) {
95 printf("Error opening /dev: %s\n", strerror(errno));
96 return -1;
97 }
98
99 while ((pdir = readdir(dir)) != NULL) {
100 ret = strstr(pdir->d_name, prefix);
101 if (ret)
102 cnt++;
103 }
104
105 closedir(dir);
106
107 return cnt;
108 }
109
110 /*
111 * The function read a complete msg from acrnlog dev.
112 * read one more sbuf entry if read an entry doesn't end with '\0'
113 * however, if the new entry contains a new msg - which means the ending char
114 * is lost, it will be latched to be process next time.
115 */
hvlog_read_dev(struct hvlog_dev * dev)116 struct hvlog_msg *hvlog_read_dev(struct hvlog_dev *dev)
117 {
118 char *p = NULL;
119 int ret;
120 size_t len = 0;
121 struct hvlog_msg *msg[2];
122 int msg_num;
123 char warn_msg[LOG_MSG_SIZE] = {0};
124
125 msg[0] = dev->msg;
126 msg[1] = &dev->latched_msg;
127
128 memset(msg[0], 0, sizeof(struct hvlog_msg) + LOG_MSG_SIZE);
129 msg_num = 0;
130
131 do {
132 if (dev->latched) {
133 /* handle the latched msg first */
134 dev->latched = 0;
135 memcpy(&msg[0]->raw[msg[0]->len], dev->entry_latch,
136 LOG_ELEMENT_SIZE);
137 msg_num++;
138 memcpy(msg[0], msg[1], sizeof(struct hvlog_msg));
139 } else {
140 ret =
141 read(dev->fd, &msg[0]->raw[msg[0]->len],
142 LOG_ELEMENT_SIZE);
143 if (!ret)
144 break;
145 /* do we read a new meaasge?
146 * msg[0]->raw[msg[0]->len format: [%lluus][cpu=%d][sev=%d][seq=%llu]: */
147 p = strstr(&msg[0]->raw[msg[0]->len], "][seq=");
148 if (p) {
149 p = p + strlen("][seq=");
150 msg[msg_num]->seq = strtoull(p, NULL, 10);
151 if ((errno == ERANGE && (msg[msg_num]->seq == ULLONG_MAX))
152 || (errno != 0 && msg[msg_num]->seq == 0)) {
153 if (snprintf(warn_msg, LOG_MSG_SIZE, "\n\n\t%s[invalid seq]\n\n\n",
154 LOG_INCOMPLETE_WARNING) >= LOG_MSG_SIZE) {
155 printf("WARN: warning message is truncated\n");
156 }
157 write_log_file(&cur_log, warn_msg, strnlen(warn_msg, LOG_MSG_SIZE));
158 } else {
159 msg_num++;
160 /* if we read another new msg, latch it */
161 /* to process next time */
162 if (msg_num > 1) {
163 dev->latched = 1;
164 memcpy(dev->entry_latch,
165 &msg[0]->raw[msg[0]->len],
166 LOG_ELEMENT_SIZE);
167 break;
168 }
169 }
170 }
171 }
172
173 if (msg_num == 0) {
174 /* if head of a message lost, continue to read */
175 memset(msg[0], 0, sizeof(struct hvlog_msg)
176 + LOG_MSG_SIZE);
177 continue;
178 }
179
180 len = strnlen(&msg[0]->raw[msg[0]->len], LOG_MSG_SIZE);
181 msg[0]->len += len;
182 } while (len == LOG_ELEMENT_SIZE &&
183 msg[0]->len < LOG_MSG_SIZE - LOG_ELEMENT_SIZE);
184
185 if (!msg[0]->len)
186 return NULL;
187
188 msg[0]->raw[msg[0]->len] = '\n';
189 msg[0]->raw[msg[0]->len + 1] = 0;
190 msg[0]->len++;
191
192 return msg[0];
193 }
194
hvlog_open_dev(const char * path)195 struct hvlog_dev *hvlog_open_dev(const char *path)
196 {
197 struct hvlog_dev *dev;
198
199 dev = calloc(1, sizeof(struct hvlog_dev));
200 if (!dev) {
201 printf("%s %d\n", __FUNCTION__, __LINE__);
202 goto open_dev;
203 }
204
205 dev->fd = open(path, O_RDONLY);
206 if (dev->fd < 0) {
207 printf("%s %d\n", __FUNCTION__, __LINE__);
208 goto open_fd;
209 }
210
211 /* actual allocated size is 512B */
212 dev->msg = calloc(1, sizeof(struct hvlog_msg) + LOG_MSG_SIZE);
213 if (!dev->msg) {
214 printf("%s %d\n", __FUNCTION__, __LINE__);
215 goto alloc_msg;
216 }
217
218 return dev;
219
220 open_fd:
221 close(dev->fd);
222 alloc_msg:
223 free(dev);
224 open_dev:
225 return NULL;
226 }
227
hvlog_close_dev(struct hvlog_dev * dev)228 void hvlog_close_dev(struct hvlog_dev *dev)
229 {
230 if (!dev)
231 return;
232
233 if (dev->msg)
234 free(dev->msg);
235 if (dev->fd > 0)
236 close(dev->fd);
237 free(dev);
238 dev = NULL;
239 }
240
241 /* this is for reading msg from hvlog devices array */
242 static struct hvlog_data {
243 struct hvlog_dev *dev;
244 struct hvlog_msg *msg; /* clean it after use */
245 } *cur, *last;
246
247 /*
248 * read the earliest msg from each dev, to hvlog_data[].msg
249 * hvlog_data[] will be used for reordering
250 */
hvlog_dev_read_msg(struct hvlog_data * data,int num_dev)251 static int hvlog_dev_read_msg(struct hvlog_data *data, int num_dev)
252 {
253 int i, new_read;
254
255 new_read = 0;
256 for (i = 0; i < num_dev; i++) {
257 if (data[i].msg)
258 continue;
259 if (!data[i].dev)
260 continue;
261
262 data[i].msg = hvlog_read_dev(data[i].dev);
263 if (data[i].msg)
264 new_read++;
265 }
266
267 return new_read;
268 }
269
get_min_seq_msg(struct hvlog_data * data,int num_dev)270 static struct hvlog_msg *get_min_seq_msg(struct hvlog_data *data, int num_dev)
271 {
272 int i, index_min = -1;
273 __u64 min_seq = 0;
274 struct hvlog_msg *msg;
275
276 for (i = 0; i < num_dev; i++) {
277 if (!data[i].msg)
278 continue;
279
280 if (index_min == -1) {
281 index_min = i;
282 min_seq = data[i].msg->seq;
283 continue;
284 }
285
286 if (data[i].msg->seq > min_seq)
287 continue;
288 index_min = i;
289 min_seq = data[i].msg->seq;
290 }
291
292 if (index_min == -1)
293 return NULL;
294
295 msg = data[index_min].msg;
296 data[index_min].msg = NULL;
297
298 return msg;
299 }
300
new_log_file(struct hvlog_file * log)301 static int new_log_file(struct hvlog_file *log)
302 {
303 char file_name[32] = { };
304
305 if (log->fd >= 0) {
306 if (!hvlog_log_size)
307 return 0;
308 close(log->fd);
309 log->fd = -1;
310 }
311
312 if (snprintf(file_name, sizeof(file_name), "%s.%hu", log->path,
313 log->index + 1) >= sizeof(file_name)) {
314 printf("WARN: log path is truncated\n");
315 } else
316 remove(file_name);
317
318 log->fd = open(file_name, O_RDWR | O_CREAT | O_TRUNC, 0666);
319 if (log->fd < 0) {
320 perror(file_name);
321 return -1;
322 }
323
324 log->left_space = hvlog_log_size;
325 log->index++;
326 if (snprintf(file_name, sizeof(file_name), "%s.%hu", log->path,
327 log->index - hvlog_log_num) >= sizeof(file_name)) {
328 printf("WARN: log path is truncated\n");
329 } else
330 remove(file_name);
331
332 return 0;
333 }
334
write_log_file(struct hvlog_file * log,const char * buf,size_t len)335 size_t write_log_file(struct hvlog_file * log, const char *buf, size_t len)
336 {
337 int ret;
338
339 if (len >= log->left_space)
340 if (new_log_file(log))
341 return 0;
342
343 ret = write(log->fd, buf, len);
344 log->left_space -= ret;
345
346 return ret;
347 }
348
cur_read_func(void * arg)349 static void *cur_read_func(void *arg)
350 {
351 struct hvlog_msg *msg;
352 __u64 last_seq = 0;
353 char warn_msg[LOG_MSG_SIZE] = {0};
354
355 while (1) {
356 hvlog_dev_read_msg(cur, cur_cnt);
357 msg = get_min_seq_msg(cur, cur_cnt);
358 if (!msg) {
359 usleep(interval);
360 continue;
361 }
362
363 /* if msg->seq is not contineous, warn for logs missing */
364 if (last_seq + 1 < msg->seq) {
365 if (snprintf(warn_msg, LOG_MSG_SIZE,
366 "\n\n\t%s[%lu ms]\n\n\n",
367 LOG_INCOMPLETE_WARNING, interval) >= LOG_MSG_SIZE) {
368 printf("WARN: warning message is truncated\n");
369 }
370
371 write_log_file(&cur_log, warn_msg, strnlen(warn_msg, LOG_MSG_SIZE));
372 }
373
374 last_seq = msg->seq;
375
376 write_log_file(&cur_log, msg->raw, msg->len);
377 }
378
379 return NULL;
380 }
381
382 /* If dir *path does't exist, create a new one.
383 * Otherwise, remove all the old acrnlog files in the dir.
384 */
mk_dir(const char * path)385 static int mk_dir(const char *path)
386 {
387 char prefix[32] = "acrnlog_cur."; /* acrnlog file prefix */
388 char acrnlog_file[64] = { };
389 struct dirent *pdir;
390 struct stat st;
391 int index = 0;
392 char *find;
393 DIR *dir;
394
395 if (stat(path, &st)) {
396 if (mkdir(path, 0644))
397 return -1;
398 } else {
399 /* Remove all the old acrnlogs */
400 dir = opendir(path);
401 if (!dir) {
402 printf("Error opening directory %s. Error: %s\n",
403 path, strerror(errno));
404 return -1;
405 }
406 while ((pdir = readdir(dir)) != NULL) {
407 find = strstr(pdir->d_name, prefix);
408 if (!find)
409 continue;
410
411 if (snprintf(acrnlog_file, sizeof(acrnlog_file), "%s/%s%d",
412 path, prefix, index++) >= sizeof(acrnlog_file)) {
413 printf("WARN: acrnlog file path is truncated\n");
414 } else
415 remove(acrnlog_file);
416 }
417 closedir(dir);
418 }
419
420 return 0;
421 }
422
423 /* for user optinal args */
424 static const char optString[] = "s:n:t:h";
425
display_usage(void)426 static void display_usage(void)
427 {
428 printf("acrnlog - tool to collect ACRN hypervisor log\n"
429 "[Usage] acrnlog [-s size] [-n number] [-t interval] [-h]\n\n"
430 "[Options]\n"
431 "\t-h: print this message\n"
432 "\t-t: polling interval to collect logs, in ms\n"
433 "\t-s: size limitation for each log file, in MB.\n"
434 "\t 0 means no limitation.\n"
435 "\t-n: how many files you would like to keep on disk\n"
436 "[Output] capatured log files under /var/log/acrnlog/\n");
437 }
438
parse_opt(int argc,char * argv[])439 static int parse_opt(int argc, char *argv[])
440 {
441 int opt, ret;
442
443 while ((opt = getopt(argc, argv, optString)) != -1) {
444 switch (opt) {
445 case 's':
446 ret = strtoll(optarg, NULL, 10);
447 if ((errno == ERANGE && (ret == LLONG_MAX || ret == LLONG_MIN))
448 || (errno != 0 && ret == 0)) {
449 printf("'-s' invalid parameter: %s\n", optarg);
450 return -EINVAL;
451 }
452
453 hvlog_log_size = ret * 1024;
454 break;
455 case 'n':
456 ret = strtol(optarg, NULL, 10);
457 if ((errno == ERANGE && (ret == LONG_MAX || ret == LONG_MIN))
458 || (errno != 0 && ret == 0)) {
459 printf("'-n' invalid parameter: %s\n", optarg);
460 return -EINVAL;
461 }
462 if (ret > 3)
463 hvlog_log_num = ret;
464 break;
465 case 't':
466 ret = strtol(optarg, NULL, 10);
467 if (ret <= 0 || ret >=1000) {
468 printf("'-t' require integer between [1-999]\n");
469 return -EINVAL;
470 }
471 interval = ret * 1000;
472 printf("Polling interval is %u ms\n", ret);
473 break;
474 case 'h':
475 display_usage();
476 return -EINVAL;
477 default:
478 /* Undefined operation. */
479 display_usage();
480 return -EINVAL;
481 }
482 }
483 return 0;
484 }
485
486 static pthread_t cur_thread;
487
main(int argc,char * argv[])488 int main(int argc, char *argv[])
489 {
490 char name[32];
491 int i, ret;
492 int num_cur, num_last;
493 struct hvlog_msg *msg;
494
495 if (parse_opt(argc, argv))
496 return -1;
497
498 ret = mk_dir("/var/log/acrnlog");
499 if (ret) {
500 printf("Cannot create /var/log/acrnlog. Error: %s\n",
501 strerror(errno));
502 return ret;
503 }
504
505 cur_cnt = get_dev_cnt("acrn_hvlog_cur_");
506 last_cnt = get_dev_cnt("acrn_hvlog_last_");
507
508 if (cur_cnt == 0) {
509 printf("Failed to find acrn hvlog devices, please check whether module acrn_hvlog is inserted\n");
510 return -1;
511 } else if (cur_cnt == -1)
512 return -1;
513
514 cur = calloc(cur_cnt, sizeof(struct hvlog_data));
515 if (!cur) {
516 printf("Failed to allocate buf for cur log buf\n");
517 return -1;
518 }
519
520 if (last_cnt) {
521 last = calloc(cur_cnt, sizeof(struct hvlog_data));
522 if (!last) {
523 printf("Failed to allocate buf for last log buf\n");
524 free(cur);
525 return -1;
526 }
527 }
528
529 num_cur = 0;
530 for (i = 0; i < cur_cnt; i++) {
531 if (snprintf(name, sizeof(name), "/dev/acrn_hvlog_cur_%d", i) >= sizeof(name)) {
532 printf("ERROR: cur hvlog path is truncated\n");
533 return -1;
534 }
535 cur[i].dev = hvlog_open_dev(name);
536 if (!cur[i].dev)
537 perror(name);
538 else
539 num_cur++;
540 cur[i].msg = NULL;
541 }
542
543 num_last = 0;
544 if (last_cnt) {
545 for (i = 0; i < cur_cnt; i++) {
546 if (snprintf(name, sizeof(name), "/dev/acrn_hvlog_last_%d", i) >= sizeof(name)) {
547 printf("ERROR: last hvlog path is truncated\n");
548 return -1;
549 }
550 last[i].dev = hvlog_open_dev(name);
551 if (!last[i].dev)
552 perror(name);
553 else
554 num_last++;
555 last[i].msg = NULL;
556 }
557 }
558
559 printf("open cur:%d last:%d\n", num_cur, num_last);
560
561 /* create thread to read cur log */
562 if (num_cur) {
563 ret = pthread_create(&cur_thread, NULL, cur_read_func, cur);
564 if (ret) {
565 printf("%s %d\n", __FUNCTION__, __LINE__);
566 cur_thread = 0;
567 }
568 }
569
570 if (num_last) {
571 while (1) {
572 hvlog_dev_read_msg(last, cur_cnt);
573 msg = get_min_seq_msg(last, cur_cnt);
574 if (!msg)
575 break;
576 write_log_file(&last_log, msg->raw, msg->len);
577 }
578 }
579
580 if (cur_thread)
581 pthread_join(cur_thread, NULL);
582
583 for (i = 0; i < cur_cnt; i++) {
584 hvlog_close_dev(cur[i].dev);
585 }
586
587 for (i = 0; i < last_cnt; i++) {
588 hvlog_close_dev(last[i].dev);
589 }
590
591 free(cur);
592 if (last_cnt)
593 free(last);
594
595 return 0;
596 }
597