diff --git a/tools/acrn-crashlog/acrnprobe/android_events.c b/tools/acrn-crashlog/acrnprobe/android_events.c index a867c8fca..d88f4a288 100644 --- a/tools/acrn-crashlog/acrnprobe/android_events.c +++ b/tools/acrn-crashlog/acrnprobe/android_events.c @@ -130,11 +130,13 @@ static int get_vms_history(const struct sender_t *sender) vm->datafs = NULL; continue; } + + e2fs_close(vm->datafs); + vm->datafs = NULL; + if (!size) { LOGE("empty vm_history from (%s).\n", vm->name); vm->history_data = NULL; - e2fs_close(vm->datafs); - vm->datafs = NULL; continue; } @@ -153,7 +155,15 @@ static int get_vms_history(const struct sender_t *sender) return 0; } -static void sync_lines_stage1(struct sender_t *sender) +/** + * There are 2 stages in vm events sync. + * Stage1: detect new vm events and record them into log_vmrecordid file. + * Stage2: push the recorded events to event_queue, the senders will do + * the corresponding process. + * + * The design reason is giving UOS some time to get log stored. + */ +static void detect_new_events(struct sender_t *sender) { int id; struct vm_t *vm; @@ -170,7 +180,7 @@ static void sync_lines_stage1(struct sender_t *sender) data = vm->history_data; data_size = vm->history_size[sender->id]; - last_key = &vm->last_synced_line_key[sender->id][0]; + last_key = &vm->last_evt_detected[sender->id][0]; if (*last_key) { start = strstr(data, last_key); if (start == NULL) { @@ -201,12 +211,12 @@ static void sync_lines_stage1(struct sender_t *sender) if (len == -1) break; + start = strchr(line_to_sync, '\n'); if (str_split_ere(line_to_sync, len + 1, vm_format, strlen(vm_format), vmkey, sizeof(vmkey)) != 1) { LOGE("get an invalid line from (%s), skip\n", vm->name); - start = strchr(line_to_sync, '\n'); continue; } @@ -215,12 +225,11 @@ static void sync_lines_stage1(struct sender_t *sender) !strcmp(vmkey, "00000000000000000000")) { LOGE("invalid key (%s) from (%s)\n", vmkey, vm->name); - start = strchr(line_to_sync, '\n'); continue; } LOGD("stage1 %s\n", vmkey); - *(char *)(mempcpy(vm->last_synced_line_key[sender->id], + *(char *)(mempcpy(vm->last_evt_detected[sender->id], vmkey, ANDROID_EVT_KEY_LEN)) = '\0'; if (vmrecord_new(&sender->vmrecord, vm->name, vmkey) == -1) @@ -239,7 +248,7 @@ static char *next_record(const struct mm_file_t *file, const char *fstart, return get_line(tag, tlen, file->begin, file->size, fstart, len); } -static void sync_lines_stage2(struct sender_t *sender, +static void fire_detected_events(struct sender_t *sender, int (*fn)(const char*, size_t, const struct vm_t *)) { struct mm_file_t *recos; @@ -298,10 +307,7 @@ static void sync_lines_stage2(struct sender_t *sender, res = fn(hist_line, len + 1, vm); if (res == VMEVT_HANDLED) vmrecord_mark(&sender->vmrecord, vmkey, - strnlen(vmkey, sizeof(vmkey)), SUCCESS); - else if (res == VMEVT_MISSLOG) - vmrecord_mark(&sender->vmrecord, vmkey, - strnlen(vmkey, sizeof(vmkey)), MISS_LOG); + strnlen(vmkey, sizeof(vmkey)), ON_GOING); } out: @@ -310,7 +316,7 @@ out: } /* This function only for initialization */ -static void get_last_line_synced(struct sender_t *sender) +static void get_last_evt_detected(struct sender_t *sender) { int id; struct vm_t *vm; @@ -322,7 +328,7 @@ static void get_last_line_synced(struct sender_t *sender) continue; /* generally only exec for each vm once */ - if (vm->last_synced_line_key[sender->id][0]) + if (vm->last_evt_detected[sender->id][0]) continue; if (vmrecord_last(&sender->vmrecord, vm->name, vm->name_len, @@ -335,7 +341,7 @@ static void get_last_line_synced(struct sender_t *sender) continue; } - *(char *)(mempcpy(vm->last_synced_line_key[sender->id], vmkey, + *(char *)(mempcpy(vm->last_evt_detected[sender->id], vmkey, ANDROID_EVT_KEY_LEN)) = '\0'; } @@ -358,6 +364,11 @@ static char *setup_loop_dev(void) } devnr = loopdev_num_get_free(); + if (devnr < 0) { + LOGE("failed to get free loop device\n"); + return NULL; + } + for (i = 0; i < devnr; i++) { res = snprintf(loop_dev_tmp, ARRAY_SIZE(loop_dev_tmp), "/dev/loop%d", i); @@ -419,11 +430,15 @@ void refresh_vm_history(struct sender_t *sender, return; } - get_last_line_synced(sender); + get_last_evt_detected(sender); get_vms_history(sender); - sync_lines_stage2(sender, fn); - sync_lines_stage1(sender); + /* read events from vmrecords and mark them as ongoing */ + fire_detected_events(sender, fn); + + /* add events to vmrecords */ + detect_new_events(sender); + for_each_vm(id, vm, conf) { if (!vm) continue; @@ -431,9 +446,5 @@ void refresh_vm_history(struct sender_t *sender, free(vm->history_data); vm->history_data = NULL; } - if (vm->datafs) { - e2fs_close(vm->datafs); - vm->datafs = NULL; - } } } diff --git a/tools/acrn-crashlog/acrnprobe/channels.c b/tools/acrn-crashlog/acrnprobe/channels.c index 98dc79571..91bbca09b 100644 --- a/tools/acrn-crashlog/acrnprobe/channels.c +++ b/tools/acrn-crashlog/acrnprobe/channels.c @@ -23,6 +23,7 @@ #include "startupreason.h" #include "probeutils.h" #include "log_sys.h" +#include "android_events.h" #define POLLING_TIMER_SIG 0xCEAC @@ -174,16 +175,40 @@ static struct polling_job_t { void (*fn)(union sigval v); } vm_job; +static int create_vm_event(const char *msg, size_t len, const struct vm_t *vm) +{ + struct vm_event_t *vme = malloc(sizeof(*vme)); + struct event_t *e; + + if (!vme) + return VMEVT_DEFER; + + vme->vm_msg = strndup(msg, len); + if (!vme->vm_msg) { + free(vme); + return VMEVT_DEFER; + } + + vme->vm_msg_len = len; + vme->vm = vm; + + e = create_event(VM, "polling", (void *)vme, 0, NULL, 0); + if (e) { + event_enqueue(e); + return VMEVT_HANDLED; + } + + free(vme->vm_msg); + free(vme); + return VMEVT_DEFER; +} + /** * Callback thread of a polling job. */ static void polling_vm(union sigval v __attribute__((unused))) { - - struct event_t *e = create_event(VM, "polling", NULL, 0, NULL, 0); - - if (e) - event_enqueue(e); + refresh_vm_history(get_sender_by_name("crashlog"), create_vm_event); } /** diff --git a/tools/acrn-crashlog/acrnprobe/event_handler.c b/tools/acrn-crashlog/acrnprobe/event_handler.c index 19b085570..9fa227bed 100644 --- a/tools/acrn-crashlog/acrnprobe/event_handler.c +++ b/tools/acrn-crashlog/acrnprobe/event_handler.c @@ -17,6 +17,7 @@ #include "log_sys.h" #include "event_handler.h" #include "startupreason.h" +#include "android_events.h" /* Watchdog timeout in second*/ #define WDT_TIMEOUT 300 @@ -135,6 +136,7 @@ static void *event_handle(void *unused __attribute__((unused))) int id; struct sender_t *sender; struct event_t *e; + struct vm_event_t *vme; while ((e = event_dequeue())) { /* here we only handle internal event */ @@ -173,6 +175,13 @@ static void *event_handle(void *unused __attribute__((unused))) break; } + if (e->event_type == VM) { + vme = (struct vm_event_t *)e->private; + if (vme->vm_msg) + free(vme->vm_msg); + if (vme) + free(vme); + } if ((e->dir)) free(e->dir); free(e); diff --git a/tools/acrn-crashlog/acrnprobe/include/android_events.h b/tools/acrn-crashlog/acrnprobe/include/android_events.h index c1009f67e..292998033 100644 --- a/tools/acrn-crashlog/acrnprobe/include/android_events.h +++ b/tools/acrn-crashlog/acrnprobe/include/android_events.h @@ -11,7 +11,12 @@ extern char *loop_dev; #define VMEVT_HANDLED 0 #define VMEVT_DEFER -1 -#define VMEVT_MISSLOG -2 + +struct vm_event_t { + char *vm_msg; + size_t vm_msg_len; + const struct vm_t *vm; +}; #define ANDROID_LOGS_DIR "/logs/" #define IGN_SPACES "%*[[[:space:]]*]" diff --git a/tools/acrn-crashlog/acrnprobe/include/load_conf.h b/tools/acrn-crashlog/acrnprobe/include/load_conf.h index 19ec6425d..7956d9277 100644 --- a/tools/acrn-crashlog/acrnprobe/include/load_conf.h +++ b/tools/acrn-crashlog/acrnprobe/include/load_conf.h @@ -48,7 +48,7 @@ struct vm_t { ext2_filsys datafs; unsigned long history_size[SENDER_MAX]; char *history_data; - char last_synced_line_key[SENDER_MAX][SHORT_KEY_LENGTH + 1]; + char last_evt_detected[SENDER_MAX][SHORT_KEY_LENGTH + 1]; }; struct log_t { diff --git a/tools/acrn-crashlog/acrnprobe/sender.c b/tools/acrn-crashlog/acrnprobe/sender.c index 81fe3278a..dd60756cf 100644 --- a/tools/acrn-crashlog/acrnprobe/sender.c +++ b/tools/acrn-crashlog/acrnprobe/sender.c @@ -586,8 +586,7 @@ static void telemd_send_reboot(void) free(class); } -static int telemd_new_vmevent(const char *line_to_sync, - size_t len, const struct vm_t *vm) +static void telemd_send_vmevent(struct event_t *e) { char event[ANDROID_WORD_LEN]; char longtime[ANDROID_WORD_LEN]; @@ -603,26 +602,20 @@ static int telemd_new_vmevent(const char *line_to_sync, int i; uint32_t severity; int res; - int ret = VMEVT_HANDLED; + struct vm_event_t *vme; - /* VM events in history_event look like this: - * - * "CRASH xxxxxxxxxxxxxxxxxxxx 2017-11-11/03:12:59 JAVACRASH - * /data/logs/crashlog0_xxxxxxxxxxxxxxxxxxxx" - * "REBOOT xxxxxxxxxxxxxxxxxxxx 2011-11-11/11:20:51 POWER-ON - * 0000:00:00" - */ const char * const vm_format = ANDROID_ENEVT_FMT ANDROID_KEY_FMT ANDROID_LONGTIME_FMT ANDROID_TYPE_FMT ANDROID_LINE_REST_FMT; - res = str_split_ere(line_to_sync, len, vm_format, strlen(vm_format), - event, sizeof(event), vmkey, sizeof(vmkey), - longtime, sizeof(longtime), + vme = (struct vm_event_t *)e->private; + res = str_split_ere(vme->vm_msg, vme->vm_msg_len, vm_format, + strlen(vm_format), event, sizeof(event), + vmkey, sizeof(vmkey), longtime, sizeof(longtime), type, sizeof(type), rest, sizeof(rest)); if (res != 5) { - LOGE("get an invalid line from (%s), skip\n", vm->name); - return VMEVT_HANDLED; + LOGE("get an invalid line from (%s), skip\n", vme->vm->name); + return; } if (strcmp(event, "CRASH") == 0) @@ -633,30 +626,18 @@ static int telemd_new_vmevent(const char *line_to_sync, /* if line contains log, fill vmlogpath */ log = strstr(rest, ANDROID_LOGS_DIR); if (log) { - struct sender_t *crashlog = get_sender_by_name("crashlog"); const char *logf; - size_t logflen; - int res; - - if (!crashlog) - return VMEVT_HANDLED; + if (!e->dir) + return; logf = log + sizeof(ANDROID_LOGS_DIR) - 1; - logflen = &rest[0] + strnlen(rest, PATH_MAX) - logf; - res = find_file(crashlog->outdir, crashlog->outdir_len, logf, - logflen, 1, &vmlogpath, 1); - if (res == -1) { - LOGE("failed to find (%s) in (%s)\n", - logf, crashlog->outdir); - return VMEVT_DEFER; - } else if (res == 0) - return VMEVT_DEFER; + if (asprintf(&vmlogpath, "%s/%s", e->dir, logf) == -1) + return; } - res = asprintf(&class, "%s/%s/%s", vm->name, event, type); + res = asprintf(&class, "%s/%s/%s", vme->vm->name, event, type); if (res < 0) { LOGE("compute string failed, out of memory\n"); - ret = VMEVT_DEFER; goto free_vmlogpath; } @@ -664,15 +645,12 @@ static int telemd_new_vmevent(const char *line_to_sync, KEY_LONG); if (eventid == NULL) { LOGE("generate eventid failed, error (%s)\n", strerror(errno)); - ret = VMEVT_DEFER; goto free_class; } if (!vmlogpath) { - res = telemd_send_data("no logs", eventid, severity, class); - if (res == -1) - ret = VMEVT_DEFER; - + telemd_send_data("vm event doesn't contain logs", eventid, + severity, class); goto free; } @@ -682,33 +660,15 @@ static int telemd_new_vmevent(const char *line_to_sync, for (i = 0; i < count; i++) { if (!strstr(files[i], "/.") && !strstr(files[i], "/..")) { - res = telemd_send_data(files[i], eventid, - severity, class); - if (res == -1) - ret = VMEVT_DEFER; + telemd_send_data(files[i], eventid, severity, + class); } } - } else if (count == 2) { - char *content; - - res = asprintf(&content, "no logs under (%s)", vmlogpath); - if (res > 0) { - res = telemd_send_data(content, eventid, severity, - class); - if (res == -1) - ret = VMEVT_DEFER; - free(content); - } else { - LOGE("compute string failed, out of memory\n"); - ret = VMEVT_DEFER; - } } else if (count < 0) { LOGE("lsdir (%s) failed, error (%s)\n", vmlogpath, strerror(-count)); - ret = VMEVT_DEFER; } else { LOGE("get (%d) files in (%s) ???\n", count, vmlogpath); - ret = VMEVT_DEFER; } while (count > 0) @@ -722,7 +682,7 @@ free_vmlogpath: if (vmlogpath) free(vmlogpath); - return ret; + return; } static void telemd_send(struct event_t *e) @@ -751,8 +711,7 @@ static void telemd_send(struct event_t *e) telemd_send_reboot(); break; case VM: - refresh_vm_history(get_sender_by_name("telemd"), - telemd_new_vmevent); + telemd_send_vmevent(e); break; default: LOGE("unsupoorted event type %d\n", e->event_type); @@ -946,8 +905,7 @@ static void crashlog_send_reboot(void) free(key); } -static int crashlog_new_vmevent(const char *line_to_sync, - size_t len, const struct vm_t *vm) +static void crashlog_send_vmevent(struct event_t *e) { char event[ANDROID_WORD_LEN]; char longtime[ANDROID_WORD_LEN]; @@ -957,29 +915,28 @@ static int crashlog_new_vmevent(const char *line_to_sync, char *vmlogpath = NULL; char *key; char *log; - int ret = VMEVT_HANDLED; int res; int cnt; - char *dir; + ext2_filsys datafs; + struct sender_t *crashlog = get_sender_by_name("crashlog"); + struct vm_event_t *vme; + enum vmrecord_mark_t mark = SUCCESS; - /* VM events in history_event like this: - * - * "CRASH xxxxxxxxxxxxxxxxxxxx 2017-11-11/03:12:59 JAVACRASH - * /data/logs/crashlog0_xxxxxxxxxxxxxxxxxxxx" - * "REBOOT xxxxxxxxxxxxxxxxxxxx 2011-11-11/11:20:51 POWER-ON - * 0000:00:00" - */ const char * const vm_format = ANDROID_ENEVT_FMT ANDROID_KEY_FMT ANDROID_LONGTIME_FMT ANDROID_TYPE_FMT ANDROID_LINE_REST_FMT; - res = str_split_ere(line_to_sync, len, vm_format, strlen(vm_format), - event, sizeof(event), vmkey, sizeof(vmkey), - longtime, sizeof(longtime), + if (!crashlog) + return; + + vme = (struct vm_event_t *)e->private; + res = str_split_ere(vme->vm_msg, vme->vm_msg_len, vm_format, + strlen(vm_format), event, sizeof(event), + vmkey, sizeof(vmkey), longtime, sizeof(longtime), type, sizeof(type), rest, sizeof(rest)); if (res != 5) { - LOGE("get an invalid line from (%s), skip\n", vm->name); - return ret; + LOGE("get an invalid line from (%s), skip\n", vme->vm->name); + return; } key = generate_event_id("SOS", 3, (const char *)vmkey, @@ -987,64 +944,72 @@ static int crashlog_new_vmevent(const char *line_to_sync, if (key == NULL) { LOGE("generate event id failed, error (%s)\n", strerror(errno)); - return VMEVT_DEFER; + mark = WAITING_SYNC; + goto mark_record; } if (crashlog_check_space() == -1) { - hist_raise_event(vm->name, type, "SPACE_FULL", "", key); + hist_raise_event(vme->vm->name, type, "SPACE_FULL", "", key); goto free_key; } - dir = generate_log_dir(MODE_VMEVENT, key); - if (dir == NULL) { + e->dir = generate_log_dir(MODE_VMEVENT, key); + if (e->dir == NULL) { LOGE("generate crashlog dir failed\n"); - ret = VMEVT_DEFER; + mark = WAITING_SYNC; goto free_key; } - generate_crashfile(dir, event, strnlen(event, ANDROID_WORD_LEN), + generate_crashfile(e->dir, event, strnlen(event, ANDROID_WORD_LEN), key, SHORT_KEY_LENGTH, type, strnlen(type, ANDROID_WORD_LEN), - vm->name, vm->name_len, + vme->vm->name, vme->vm->name_len, vmkey, strnlen(vmkey, ANDROID_WORD_LEN), NULL, 0); - /* if line contains log, we need dump each file in the logdir - */ - log = strstr(rest, "/logs/"); - if (log) { - vmlogpath = log + 1; - res = e2fs_dump_dir_by_dpath(vm->datafs, vmlogpath, dir, &cnt); - if (res == -1) { - if (cnt) { - LOGE("dump (%s) abort at (%d)\n", vmlogpath, - cnt); - ret = VMEVT_DEFER; - } else { - LOGW("(%s) is missing\n", vmlogpath); - ret = VMEVT_MISSLOG; /* missing logdir */ - } - if (remove_r(dir) == -1) - LOGE("failed to remove %s (%d)\n", dir, -errno); - goto free_dir; - } - if (cnt == 1) { - LOGW("(%s) is empty, will sync it in the next loop\n", - vmlogpath); - ret = VMEVT_DEFER; - if (remove_r(dir) == -1) - LOGE("failed to remove %s (%d)\n", dir, -errno); - goto free_dir; - } + log = strstr(rest, ANDROID_LOGS_DIR); + if (!log) + goto raise_e; + + /* if line contains log, we need dump each file in the logdir */ + vmlogpath = log + 1; + + if (e2fs_open(loop_dev, &datafs) == -1) { + mark = WAITING_SYNC; + goto free_key; } - hist_raise_event(vm->name, type, dir, "", key); + res = e2fs_dump_dir_by_dpath(datafs, vmlogpath, e->dir, &cnt); + e2fs_close(datafs); + if (res == -1) { + if (cnt) { + LOGE("dump (%s) abort at (%d)\n", vmlogpath, cnt); + mark = WAITING_SYNC; + } else { + LOGW("(%s) doesn't exsit\n", vmlogpath); + mark = MISS_LOG; + } + } + if (cnt == 1) { + LOGW("%s is empty, will sync it in the next loop\n", vmlogpath); + mark = WAITING_SYNC; + } + if (res == -1 || cnt == -1) { + if (remove_r(e->dir) == -1) + LOGE("failed to remove %s, %s\n", e->dir, + strerror(errno)); + free(e->dir); + e->dir = NULL; + goto free_key; + } -free_dir: - free(dir); +raise_e: + hist_raise_event(vme->vm->name, type, e->dir, "", key); free_key: free(key); - - return ret; +mark_record: + vmrecord_open_mark(&crashlog->vmrecord, vmkey, + strnlen(vmkey, sizeof(vmkey)), mark); + return; } static void crashlog_send(struct event_t *e) @@ -1073,8 +1038,7 @@ static void crashlog_send(struct event_t *e) crashlog_send_reboot(); break; case VM: - refresh_vm_history(get_sender_by_name("crashlog"), - crashlog_new_vmevent); + crashlog_send_vmevent(e); break; default: LOGE("unsupoorted event type %d\n", e->event_type); @@ -1083,7 +1047,6 @@ static void crashlog_send(struct event_t *e) int init_sender(void) { - int ret; int id; int fd; struct sender_t *sender; @@ -1093,25 +1056,16 @@ int init_sender(void) if (!sender) continue; - ret = asprintf(&sender->vmrecord.path, "%s/VM_eventsID.log", - sender->outdir); - if (ret < 0) { - LOGE("compute string failed, out of memory\n"); - return -ENOMEM; - } - pthread_mutex_init(&sender->vmrecord.mtx, NULL); - if (!directory_exists(sender->outdir)) if (mkdir_p(sender->outdir) < 0) { LOGE("mkdir (%s) failed, error (%s)\n", sender->outdir, strerror(errno)); - return -errno; + return -1; } - ret = init_properties(sender); - if (ret) { + if (init_properties(sender)) { LOGE("init sender failed\n"); - exit(-1); + return -1; } /* touch uptime file, to add inotify */ @@ -1121,16 +1075,23 @@ int init_sender(void) if (fd < 0) { LOGE("failed to open (%s), error (%s)\n", uptime->path, strerror(errno)); - return -errno; + return -1; } close(fd); } if (!strcmp(sender->name, "crashlog")) { sender->send = crashlog_send; - ret = prepare_history(); - if (ret) + if (prepare_history()) return -1; + if (asprintf(&sender->vmrecord.path, + "%s/VM_eventsID.log", + sender->outdir) == -1) { + LOGE("failed to asprintf\n"); + return -1; + } + pthread_mutex_init(&sender->vmrecord.mtx, NULL); + #ifdef HAVE_TELEMETRICS_CLIENT } else if (!strcmp(sender->name, "telemd")) { sender->send = telemd_send;