From f4b2c2438096661261410edf6f799896324d5d4d Mon Sep 17 00:00:00 2001 From: Liu Xinwu Date: Thu, 10 May 2018 09:38:01 +0800 Subject: [PATCH] tools: acrn-crashlog: android events module for acrnprobe Sync events detected by android crashlog. In android system, android crashlog is a log collection mechanism, it will generate a history_event file to record android system events. Acrnprobe will detect these events by scanning android history_event file. This module mainly contains two functions: 1. setup loop device for android.img. 2. detect new event occursing in android. Signed-off-by: Liu Xinwu Reviewed-by: Zhang Yanmin Reviewed-by: Liu Chuansheng Reviewed-by: Zhao Yakui Reviewed-by: Geoffroy Van Cutsem Acked-by: Eddie Dong --- tools/acrn-crashlog/acrnprobe/Makefile | 3 +- .../acrn-crashlog/acrnprobe/android_events.c | 589 ++++++++++++++++++ .../acrnprobe/include/android_events.h | 15 + 3 files changed, 606 insertions(+), 1 deletion(-) create mode 100644 tools/acrn-crashlog/acrnprobe/android_events.c create mode 100644 tools/acrn-crashlog/acrnprobe/include/android_events.h diff --git a/tools/acrn-crashlog/acrnprobe/Makefile b/tools/acrn-crashlog/acrnprobe/Makefile index e174d8d91..8c5ff1e3c 100644 --- a/tools/acrn-crashlog/acrnprobe/Makefile +++ b/tools/acrn-crashlog/acrnprobe/Makefile @@ -29,7 +29,8 @@ $(BUILDDIR)/acrnprobe/bin/acrnprobe: $(BUILDDIR)/acrnprobe/obj/main.o \ $(BUILDDIR)/acrnprobe/obj/startupreason.o \ $(BUILDDIR)/acrnprobe/obj/property.o \ $(BUILDDIR)/acrnprobe/obj/probeutils.o \ - $(BUILDDIR)/acrnprobe/obj/history.o + $(BUILDDIR)/acrnprobe/obj/history.o \ + $(BUILDDIR)/acrnprobe/obj/android_events.o $(CC) -o $@ $^ $(LDFLAGS) clean: diff --git a/tools/acrn-crashlog/acrnprobe/android_events.c b/tools/acrn-crashlog/acrnprobe/android_events.c new file mode 100644 index 000000000..e49a32fff --- /dev/null +++ b/tools/acrn-crashlog/acrnprobe/android_events.c @@ -0,0 +1,589 @@ +/* + * Copyright (C) 2018 Intel Corporation + * SPDX-License-Identifier: BSD-3-Clause + */ + +#include +#include +#include +#include +#include +#include +#include +#include "android_events.h" +#include "strutils.h" +#include "cmdutils.h" +#include "log_sys.h" +#include "fsutils.h" +#include "history.h" + +#define VM_WARNING_LINES 2000 +#define LOOP_DEV_MAX 8 + +static char *android_img = "/data/android/android.img"; +char *loop_dev; + +/* Find the head of str, caller must guarantee that 'str' is not in + * the first line. + */ +static char *line_head(char *str) +{ + while (*str != '\n') + str--; + + return str + 1; +} + +/* Find the next event that needs to be synced. + * There is a history_event file in UOS side, it records UOS's events in + * real-time. Generally, the cursor point to the first unsynchronized line. + */ +static char *vm_next_event_to_sync(char *cursor, struct vm_t *vm) +{ + char *line_to_sync = (char *)~(0); + char *syncevent; + char *p; + char *type; + char *subtype; + char *target; + int ret; + int id; + + if (!cursor || !vm) + return NULL; + + /* find all syncing types start from cursor, + * focus the event with smaller address. + */ + for_each_syncevent_vm(id, syncevent, vm) { + if (!syncevent) + continue; + + ret = asprintf(&type, "\n%s ", syncevent); + if (ret < 0) { + LOGE("calculate vm event failed, out of memory\n"); + return NULL; + } + /* a sync event may configured as type/subtype */ + p = strchr(type, '/'); + if (p) { + *p = 0; + subtype = p + 1; + } else { + subtype = NULL; + } + + if (subtype) + p = strstr(cursor, subtype); + else + p = strstr(cursor, type); + + if (p) { + target = line_head(p); + line_to_sync = MIN(line_to_sync, target); + } + + free(type); + } + + if (line_to_sync == (char *)~(0)) + return NULL; + else + return line_to_sync; + +} + +static int generate_log_vmrecord(char *path) +{ + char *head = "/* This file records vm id synced/will-sync from VMs,\n" + " * the tag \"<==\" indicates the events waiting to sync.\n" + " */\n\n"; + + LOGD("generate log_vmrecordid in (%s)\n", path); + return overwrite_file(path, head); +} + +enum refresh_type_t { + MM_ONLY, + MM_FILE +}; + +/** + * There are 2 stages in vm events sync. + * Stage1: record events to log_vmrecordid file. + * Stage2: call sender's callback for each recorded events. + * + * The design reason is to give UOS some time to log to storage. + */ +static int refresh_key_synced_stage1(struct sender_t *sender, struct vm_t *vm, + char *key, enum refresh_type_t type) +{ + char log_new[64]; + char *log_vmrecordid = sender->log_vmrecordid; + + if (!key || !sender || !vm) + return -1; + + /* the length of key must be 20, and its value can not be + * 00000000000000000000. + */ + if ((strlen(key) == 20) && + strcmp(key, "00000000000000000000")) { + sprintf(vm->last_synced_line_key[sender_id(sender)], + "%s", key); + if (type == MM_ONLY) + return 0; + + /* create a log file, so we can locate + * the right place in case of reboot + */ + if (!file_exists(log_vmrecordid)) + generate_log_vmrecord(log_vmrecordid); + + sprintf(log_new, "%s %s <==\n", vm->name, key); + append_file(log_vmrecordid, log_new); + return 0; + } + + LOGE("try to record a invalid key (%s) for (%s)\n", + key, vm->name); + return -1; +} + +static int refresh_key_synced_stage2(struct mm_file_t *m_vm_records, char *key) +{ + char *begin, *end; + char *p; + + if (*key) { + begin = strstr(m_vm_records->begin, " <=="); + end = strrstr(m_vm_records->begin, key); + end = strchr(end, '\n'); + + for (p = begin; p < end; p++) { + if (*p == '<' || *p == '=') + *p = ' '; + } + + return 0; + } + + return -1; +} + +static int get_vm_history(struct vm_t *vm, struct sender_t *sender, + void **data) +{ + char vm_history[PATH_MAX]; + unsigned long size; + int ret; + int sid; + + if (!vm || !sender) + return -1; + + sid = sender_id(sender); + + snprintf(vm_history, sizeof(vm_history), "/tmp/%s_%s", + "vm_hist", vm->name); + + if (get_file_size(vm_history) == (int)vm->history_size[sid]) + return 0; + + if (*data) + free(*data); + ret = read_full_binary_file(vm_history, &size, data); + if (ret) { + LOGE("read (%s) with error (%s)\n", vm_history, + strerror(errno)); + return ret; + } + + ret = strcnt(*data, '\n'); + if (ret > VM_WARNING_LINES) { + LOGW("File too large, (%d) lines in (%s)\n", + ret, vm_history); + } + + vm->history_size[sid] = size; + + return size; +} + +static void sync_lines_stage1(struct sender_t *sender, void *data[]) +{ + int id, sid; + int ret; + struct vm_t *vm; + char *start; + char *line_to_sync; + char vmkey[SHA_DIGEST_LENGTH + 1] = {0}; + char *vm_format = "%*[^ ]%*[ ]%[^ ]%*c"; + + sid = sender_id(sender); + for_each_vm(id, vm, conf) { + if (!vm) + continue; + + if (!vm->online) + continue; + + if (vm->last_synced_line_key[sid][0]) { + start = strstr(data[id], + vm->last_synced_line_key[sid]); + if (start == NULL) { + LOGW("no synced id (%s), sync from head\n", + vm->last_synced_line_key[sid]); + start = (char *)data[id]; + } else { + start = next_line(start); + } + } else { + start = (char *)data[id]; + } + + while ((line_to_sync = vm_next_event_to_sync(start, vm))) { + /* It's possible that log's content isn't ready + * at this moment, so we postpone the fn until + * the next loop + */ + //fn(line_to_sync, vm); + + vmkey[0] = 0; + ret = sscanf(line_to_sync, vm_format, vmkey); + if (ret != 1) { + LOGE("get a invalid line from (%s), skip\n", + vm->name); + start = next_line(line_to_sync); + continue; + } + + LOGD("stage1 %s\n", vmkey); + if (vmkey[0]) + refresh_key_synced_stage1(sender, vm, + vmkey, MM_FILE); + start = next_line(line_to_sync); + } + } + +} + +static void sync_lines_stage2(struct sender_t *sender, void *data[], + void (*fn)(char*, struct vm_t *)) +{ + struct mm_file_t *m_vm_records; + char *line; + char *cursor; + char *record_fmt = "%[^ ]%*[ ]%[^ ]%*c"; + char vm_name[64]; + char vmkey[SHA_DIGEST_LENGTH + 1] = {0}; + int id; + struct vm_t *vm; + int ret; + + m_vm_records = mmap_file(sender->log_vmrecordid); + if (!m_vm_records) { + LOGE("mmap %s failed, strerror(%s)\n", sender->log_vmrecordid, + strerror(errno)); + return; + } + + cursor = strstr(m_vm_records->begin, " <=="); + if (!cursor) + goto out; + + line = line_head(cursor); + while (line) { + char *vm_hist_line; + /* VMNAME xxxxxxxxxxxxxxxxxxxx <== */ + ret = sscanf(line, record_fmt, vm_name, vmkey); + if (ret != 2) { + LOGE("parse vm record failed\n"); + goto out; + } + + for_each_vm(id, vm, conf) { + if (!vm) + continue; + + if (!vm->online) + continue; + + if (strcmp(vm->name, vm_name)) + continue; + + vm_hist_line = strstr(data[id], vmkey); + if (!vm_hist_line) { + LOGE("not find (%s) in (%s),", vmkey, vm->name); + LOGE("history_event in UOS was deleted?\n"); + break; + } + + fn(line_head(vm_hist_line), vm); + } + + line = next_line(line); + } + +out: + refresh_key_synced_stage2(m_vm_records, vmkey); + unmap_file(m_vm_records); +} + +/* This function only for initialization */ +static void get_last_line_synced(struct sender_t *sender) +{ + int id; + int ret; + struct vm_t *vm; + char vmkey[SHA_DIGEST_LENGTH + 10] = {0}; + char word[256]; + + for_each_vm(id, vm, conf) { + if (!vm) + continue; + + if (!vm->online) + continue; + + /* generally only exec for each vm once */ + if (vm->last_synced_line_key[sender_id(sender)][0]) + continue; + + snprintf(word, sizeof(word), "%s ", vm->name); + ret = file_read_key_value_r(sender->log_vmrecordid, + word, vmkey); + if (ret == -ENOENT) { + LOGD("no log_vmrecordid under (%s), will generete\n", + sender->log_vmrecordid); + generate_log_vmrecord(sender->log_vmrecordid); + continue; + } else if (ret == -ENOMSG) { + LOGD("no vm record id for (%s)\n", vm->name); + continue; + } else if (ret < 0) { + LOGE("read key-value in (%s) for (%s), error (%s)\n", + sender->log_vmrecordid, vm->name, + strerror(errno)); + continue; + } + + vmkey[SHA_DIGEST_LENGTH] = 0; + ret = refresh_key_synced_stage1(sender, vm, vmkey, MM_ONLY); + if (ret < 0) { + LOGE("get a non-key vm event (%s) for (%s)\n", + vmkey, vm->name); + continue; + } + } +} + +static int is_data_partition(char *loop_dev) +{ + int ret = 0; + char *out = exec_out2mem("debugfs -R \"ls\" %s", loop_dev); + + if (!out) { + LOGE("debugfs -R ls %s failed, error (%s)\n", loop_dev, + strerror(errno)); + return 0; + } + + if (strstr(out, "app-lib") && + strstr(out, "tombstones") && + strstr(out, "dalvik-cache")) { + ret = 1; + } + + free(out); + return ret; +} + +static char *setup_loop_dev(void) +{ + + /* Currently UOS image(/data/android/android.img) mounted by + * launch_UOS.sh, we need mount its data partition to loop device + */ + char *out; + char loop_dev_tmp[32]; + int i; + + if (!file_exists(android_img)) { + LOGW("img(%s) is not available\n", android_img); + return NULL; + } + + loop_dev = exec_out2mem("losetup -f"); + if (!loop_dev) { + /* get cmd out fail */ + LOGE("losetup -f failed, error (%s)\n", + strerror(errno)); + return NULL; + } else if (strncmp(loop_dev, "/dev/loop", strlen("/dev/loop"))) { + /* it's not a loop dev */ + LOGE("get error loop dev (%s)\n", loop_dev); + goto free_loop_dev; + } else if (strncmp(loop_dev, "/dev/loop0", strlen("/dev/loop0"))) { + /* it's not loop0, was img mounted? */ + for (i = 0; i < LOOP_DEV_MAX; i++) { + snprintf(loop_dev_tmp, ARRAY_SIZE(loop_dev_tmp), + "/dev/loop%d", i); + if (is_data_partition(loop_dev_tmp)) { + free(loop_dev); + loop_dev = strdup(loop_dev_tmp); + if (!loop_dev) { + LOGE("out of memory\n"); + return NULL; + } + return loop_dev; + } + } + } + *strchr(loop_dev, '\n') = 0; + + out = exec_out2mem("fdisk -lu %s", android_img); + if (!out) { + LOGE("fdisk -lu %s failed, error (%s)\n", android_img, + strerror(errno)); + goto free_loop_dev; + } + + /* find data partition, sector unit = 512 bytes */ + char patition_start[32] = {0}; + char sectors[32] = {0}; + unsigned long pstart; + char *partition; + char *partition_fmt = "%*[^ ]%*[ ]%[^ ]%*[ ]%*[^ ]%*[ ]%[^ ]%*c"; + char *cursor = out; + int ret; + + while (cursor && + (partition = strstr(cursor, android_img))) { + cursor = strchr(partition, '\n'); + memset(patition_start, 0, sizeof(patition_start)); + memset(sectors, 0, sizeof(sectors)); + + ret = sscanf(partition, partition_fmt, patition_start, sectors); + if (ret != 2) + continue; + + LOGD("start (%s) sectors(%s)\n", patition_start, sectors); + /* size < 1G */ + if (atoi(sectors) < 1 * 2 * 1024 * 1024) + continue; + + pstart = atol(patition_start) * 512; + if (pstart == 0) + continue; + + ret = exec_out2file(NULL, "losetup -o %lu %s %s", + pstart, loop_dev, android_img); + /* if error occurs, is_data_partition will return false, + * only print error message here. + */ + if (ret != 0) + LOGE("(losetup -o %lu %s %s) failed, return %d\n", + pstart, loop_dev, android_img, ret); + + if (is_data_partition(loop_dev)) { + goto success; + } else { + ret = exec_out2file(NULL, "losetup -d %s", loop_dev); + /* may lose a loop dev */ + if (ret != 0) + LOGE("(losetup -d %s) failed, return %d\n", + loop_dev, ret); + } + } + + free(out); +free_loop_dev: + free(loop_dev); + + return NULL; + +success: + free(out); + return loop_dev; +} + +static int ping_vm_fs(char *loop_dev) +{ + int id; + int count = 0; + struct vm_t *vm; + struct mm_file_t *vm_hist; + char vm_history[PATH_MAX]; + char cmd[512]; + char prefix[] = "#V1.0 CURRENTUPTIME"; + + /* ensure history_event in uos available */ + for_each_vm(id, vm, conf) { + if (!vm) + continue; + + snprintf(vm_history, sizeof(vm_history), "/tmp/%s_%s", + "vm_hist", vm->name); + snprintf(cmd, sizeof(cmd), + "dump logs/history_event %s", vm_history); + + debugfs_cmd(loop_dev, cmd, NULL); + + vm_hist = mmap_file(vm_history); + if (vm_hist == NULL) { + vm->online = 0; + LOGE("%s(%s) unavailable\n", vm->name, vm_history); + continue; + } + + if (vm_hist->size && + !strncmp(vm_hist->begin, prefix, strlen(prefix))) { + vm->online = 1; + count++; + } else { + vm->online = 0; + LOGE("%s(%s) unavailable\n", vm->name, vm_history); + } + + unmap_file(vm_hist); + } + return count; +} + +void refresh_vm_history(struct sender_t *sender, + void (*fn)(char*, struct vm_t *)) +{ + int ret; + int id; + struct vm_t *vm; + static void *data[VM_MAX]; + + if (!loop_dev) { + loop_dev = setup_loop_dev(); + if (!loop_dev) + return; + LOGI("setup loop dev successful\n"); + } + + if (sender_id(sender) == 0) { + ret = ping_vm_fs(loop_dev); + if (!ret) + return; + } + + get_last_line_synced(sender); + + for_each_vm(id, vm, conf) { + if (!vm) + continue; + + if (!vm->online) + continue; + + get_vm_history(vm, sender, &data[id]); + } + + sync_lines_stage2(sender, data, fn); + sync_lines_stage1(sender, data); +} diff --git a/tools/acrn-crashlog/acrnprobe/include/android_events.h b/tools/acrn-crashlog/acrnprobe/include/android_events.h new file mode 100644 index 000000000..b005783fd --- /dev/null +++ b/tools/acrn-crashlog/acrnprobe/include/android_events.h @@ -0,0 +1,15 @@ +/* + * Copyright (C) 2018 Intel Corporation + * SPDX-License-Identifier: BSD-3-Clause + */ + +#ifndef __ANDROID_EVENTS_H__ +#define __ANDROID_EVENTS_H__ +#include "load_conf.h" + +extern char *loop_dev; + +void refresh_vm_history(struct sender_t *sender, + void (*fn)(char*, struct vm_t *)); + +#endif