github/acrn-hypervisor
1
0
Fork 0
mirror of https://github.com/projectacrn/acrn-hypervisor.git synced 2025-06-29 16:58:10 +00:00
Code Issues Projects Releases Wiki Activity

tools:acrn-crashlog: separate the detection and collection of vm events

Browse Source 
Push the recorded vm events to event_queue, and let senders do the
collecting job in the event_handler thread.

Tracked-On: #1024
Signed-off-by: Liu, Xinwu <xinwu.liu@intel.com>
Reviewed-by: Liu, Xiaojing <xiaojing.liu@intel.com>
Acked-by: Chen, Gang <gang.c.chen@intel.com>
This commit is contained in:
Liu, Xinwu 2019-04-18 16:44:16 +08:00 committed by ACRN System Integration
parent 84cf7156ae
commit fa1216325b
6 changed files with 173 additions and 162 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

55
tools/acrn-crashlog/acrnprobe/android_events.c
View File

@ -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;
}
}
}

35
tools/acrn-crashlog/acrnprobe/channels.c
View File

@ -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);
}
/**

9
tools/acrn-crashlog/acrnprobe/event_handler.c
View File

@ -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);

7
tools/acrn-crashlog/acrnprobe/include/android_events.h
View File

@ -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:]]*]"

2
tools/acrn-crashlog/acrnprobe/include/load_conf.h
View File

@ -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 {

227
tools/acrn-crashlog/acrnprobe/sender.c
View File

@ -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;