Signed-off-by: Nikola Pajkovsky npajkovs@redhat.com --- examples/oops-with-jiffies.right | 45 ++--- examples/oops-with-jiffies.test | 23 +++ src/include/libabrt.h | 2 + src/lib/kernel.c | 347 +++++++++++++++++++++++++++++++++++++ src/plugins/abrt-dump-oops.c | 352 +------------------------------------- tests/koops-parser.at | 38 ++++ 6 files changed, 435 insertions(+), 372 deletions(-) create mode 100644 examples/oops-with-jiffies.test
diff --git a/examples/oops-with-jiffies.right b/examples/oops-with-jiffies.right index 7bcc728..369793e 100644 --- a/examples/oops-with-jiffies.right +++ b/examples/oops-with-jiffies.right @@ -1,23 +1,24 @@ -[178856.137422] WARNING: at /builddir/build/BUILD/kernel-3.2.fc16/compat-wireless-3.3-rc1-2/include/net/mac80211.h:3618 rate_control_send_low+0x23e/0x250 [mac80211]() -[178856.137437] Hardware name: 4177CTO -[178856.137438] Modules linked in: usb_storage tcp_lp ppdev parport_pc lp parport fuse ipt_MASQUERADE iptable_nat nf_nat xt_CHECKSUM be2iscsi iscsi_boot_sysfs bnx2i iptable_mangle cnic uio cxgb4i cxgb4 cxgb3i bridge stp llc libcxgbi cxgb3 mdio ib_iser rdma_cm ib_cm iw_cm ib_sa ib_mad ib_core ib_addr iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi ip6t_REJECT nf_conntrack_ipv4 nf_conntrack_ipv6 nf_defrag_ipv6 nf_defrag_ipv4 xt_state ip6table_filter nf_conntrack ip6_tables sha256_generic dm_crypt snd_hda_codec_hdmi snd_hda_codec_conexant snd_hda_intel snd_hda_codec snd_hwdep arc4 vhost_net macvtap macvlan tun snd_seq snd_seq_device virtio_net snd_pcm kvm_intel snd_timer kvm thinkpad_acpi iwlwifi snd mac80211 e1000e tpm_tis tpm tpm_bios nfsd lockd snd_page_alloc soundcore cfg80211 rfkill nfs_acl auth_rpcgss i2c_i801 sunrpc uinput joydev iTCO_wdt iTCO_vendor_support microcode firewire_ohci firewire_core crc_itu_t sdhci_pci sdhci mmc_core wmi i915 drm_kms_helper drm i2c_alg! o_bit i2 +3.2.5-3.fc16.x86_64 +WARNING: at /builddir/build/BUILD/kernel-3.2.fc16/compat-wireless-3.3-rc1-2/include/net/mac80211.h:3618 rate_control_send_low+0x23e/0x250 [mac80211]() +Hardware name: 4177CTO +Modules linked in: usb_storage tcp_lp ppdev parport_pc lp parport fuse ipt_MASQUERADE iptable_nat nf_nat xt_CHECKSUM be2iscsi iscsi_boot_sysfs bnx2i iptable_mangle cnic uio cxgb4i cxgb4 cxgb3i bridge stp llc libcxgbi cxgb3 mdio ib_iser rdma_cm ib_cm iw_cm ib_sa ib_mad ib_core ib_addr iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi ip6t_REJECT nf_conntrack_ipv4 nf_conntrack_ipv6 nf_defrag_ipv6 nf_defrag_ipv4 xt_state ip6table_filter nf_conntrack ip6_tables sha256_generic dm_crypt snd_hda_codec_hdmi snd_hda_codec_conexant snd_hda_intel snd_hda_codec snd_hwdep arc4 vhost_net macvtap macvlan tun snd_seq snd_seq_device virtio_net snd_pcm kvm_intel snd_timer kvm thinkpad_acpi iwlwifi snd mac80211 e1000e tpm_tis tpm tpm_bios nfsd lockd snd_page_alloc soundcore cfg80211 rfkill nfs_acl auth_rpcgss i2c_i801 sunrpc uinput joydev iTCO_wdt iTCO_vendor_support microcode firewire_ohci firewire_core crc_itu_t sdhci_pci sdhci mmc_core wmi i915 drm_kms_helper drm i2c_algo_bit i2 c_core video [last unloaded: scsi_wait_scan] -[178856.137482] Pid: 22695, comm: ksoftirqd/2 Not tainted 3.2.5-3.fc16.x86_64 #1 -[178856.137484] Call Trace: -[178856.137490] [<ffffffff8106dd4f>] warn_slowpath_common+0x7f/0xc0 -[178856.137493] [<ffffffff8106ddaa>] warn_slowpath_null+0x1a/0x20 -[178856.137500] [<ffffffffa02a344e>] rate_control_send_low+0x23e/0x250 [mac80211] -[178856.137506] [<ffffffffa0336d15>] rs_get_rate+0x65/0x1d0 [iwlwifi] -[178856.137513] [<ffffffffa02a37c6>] rate_control_get_rate+0x96/0x170 [mac80211] -[178856.137522] [<ffffffffa02af59f>] invoke_tx_handlers+0x6ff/0x13e0 [mac80211] -[178856.137528] [<ffffffffa028edac>] ? sta_info_get+0x6c/0x80 [mac80211] -[178856.137536] [<ffffffffa02b03d0>] ieee80211_tx+0x60/0xc0 [mac80211] -[178856.137543] [<ffffffffa02b1352>] ieee80211_tx_pending+0x162/0x270 [mac80211] -[178856.137546] [<ffffffff81074d18>] tasklet_action+0x78/0x140 -[178856.137548] [<ffffffff81075378>] __do_softirq+0xb8/0x230 -[178856.137550] [<ffffffff810755aa>] run_ksoftirqd+0xba/0x170 -[178856.137552] [<ffffffff810754f0>] ? __do_softirq+0x230/0x230 -[178856.137556] [<ffffffff8108fb9c>] kthread+0x8c/0xa0 -[178856.137559] [<ffffffff815eb8f4>] kernel_thread_helper+0x4/0x10 -[178856.137561] [<ffffffff8108fb10>] ? kthread_worker_fn+0x190/0x190 -[178856.137563] [<ffffffff815eb8f0>] ? gs_change+0x13/0x13 +Pid: 22695, comm: ksoftirqd/2 Not tainted 3.2.5-3.fc16.x86_64 #1 +Call Trace: + [<ffffffff8106dd4f>] warn_slowpath_common+0x7f/0xc0 + [<ffffffff8106ddaa>] warn_slowpath_null+0x1a/0x20 + [<ffffffffa02a344e>] rate_control_send_low+0x23e/0x250 [mac80211] + [<ffffffffa0336d15>] rs_get_rate+0x65/0x1d0 [iwlwifi] + [<ffffffffa02a37c6>] rate_control_get_rate+0x96/0x170 [mac80211] + [<ffffffffa02af59f>] invoke_tx_handlers+0x6ff/0x13e0 [mac80211] + [<ffffffffa028edac>] ? sta_info_get+0x6c/0x80 [mac80211] + [<ffffffffa02b03d0>] ieee80211_tx+0x60/0xc0 [mac80211] + [<ffffffffa02b1352>] ieee80211_tx_pending+0x162/0x270 [mac80211] + [<ffffffff81074d18>] tasklet_action+0x78/0x140 + [<ffffffff81075378>] __do_softirq+0xb8/0x230 + [<ffffffff810755aa>] run_ksoftirqd+0xba/0x170 + [<ffffffff810754f0>] ? __do_softirq+0x230/0x230 + [<ffffffff8108fb9c>] kthread+0x8c/0xa0 + [<ffffffff815eb8f4>] kernel_thread_helper+0x4/0x10 + [<ffffffff8108fb10>] ? kthread_worker_fn+0x190/0x190 + [<ffffffff815eb8f0>] ? gs_change+0x13/0x13 diff --git a/examples/oops-with-jiffies.test b/examples/oops-with-jiffies.test new file mode 100644 index 0000000..7bcc728 --- /dev/null +++ b/examples/oops-with-jiffies.test @@ -0,0 +1,23 @@ +[178856.137422] WARNING: at /builddir/build/BUILD/kernel-3.2.fc16/compat-wireless-3.3-rc1-2/include/net/mac80211.h:3618 rate_control_send_low+0x23e/0x250 [mac80211]() +[178856.137437] Hardware name: 4177CTO +[178856.137438] Modules linked in: usb_storage tcp_lp ppdev parport_pc lp parport fuse ipt_MASQUERADE iptable_nat nf_nat xt_CHECKSUM be2iscsi iscsi_boot_sysfs bnx2i iptable_mangle cnic uio cxgb4i cxgb4 cxgb3i bridge stp llc libcxgbi cxgb3 mdio ib_iser rdma_cm ib_cm iw_cm ib_sa ib_mad ib_core ib_addr iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi ip6t_REJECT nf_conntrack_ipv4 nf_conntrack_ipv6 nf_defrag_ipv6 nf_defrag_ipv4 xt_state ip6table_filter nf_conntrack ip6_tables sha256_generic dm_crypt snd_hda_codec_hdmi snd_hda_codec_conexant snd_hda_intel snd_hda_codec snd_hwdep arc4 vhost_net macvtap macvlan tun snd_seq snd_seq_device virtio_net snd_pcm kvm_intel snd_timer kvm thinkpad_acpi iwlwifi snd mac80211 e1000e tpm_tis tpm tpm_bios nfsd lockd snd_page_alloc soundcore cfg80211 rfkill nfs_acl auth_rpcgss i2c_i801 sunrpc uinput joydev iTCO_wdt iTCO_vendor_support microcode firewire_ohci firewire_core crc_itu_t sdhci_pci sdhci mmc_core wmi i915 drm_kms_helper drm i2c_alg! o_bit i2 +c_core video [last unloaded: scsi_wait_scan] +[178856.137482] Pid: 22695, comm: ksoftirqd/2 Not tainted 3.2.5-3.fc16.x86_64 #1 +[178856.137484] Call Trace: +[178856.137490] [<ffffffff8106dd4f>] warn_slowpath_common+0x7f/0xc0 +[178856.137493] [<ffffffff8106ddaa>] warn_slowpath_null+0x1a/0x20 +[178856.137500] [<ffffffffa02a344e>] rate_control_send_low+0x23e/0x250 [mac80211] +[178856.137506] [<ffffffffa0336d15>] rs_get_rate+0x65/0x1d0 [iwlwifi] +[178856.137513] [<ffffffffa02a37c6>] rate_control_get_rate+0x96/0x170 [mac80211] +[178856.137522] [<ffffffffa02af59f>] invoke_tx_handlers+0x6ff/0x13e0 [mac80211] +[178856.137528] [<ffffffffa028edac>] ? sta_info_get+0x6c/0x80 [mac80211] +[178856.137536] [<ffffffffa02b03d0>] ieee80211_tx+0x60/0xc0 [mac80211] +[178856.137543] [<ffffffffa02b1352>] ieee80211_tx_pending+0x162/0x270 [mac80211] +[178856.137546] [<ffffffff81074d18>] tasklet_action+0x78/0x140 +[178856.137548] [<ffffffff81075378>] __do_softirq+0xb8/0x230 +[178856.137550] [<ffffffff810755aa>] run_ksoftirqd+0xba/0x170 +[178856.137552] [<ffffffff810754f0>] ? __do_softirq+0x230/0x230 +[178856.137556] [<ffffffff8108fb9c>] kthread+0x8c/0xa0 +[178856.137559] [<ffffffff815eb8f4>] kernel_thread_helper+0x4/0x10 +[178856.137561] [<ffffffff8108fb10>] ? kthread_worker_fn+0x190/0x190 +[178856.137563] [<ffffffff815eb8f0>] ? gs_change+0x13/0x13 diff --git a/src/include/libabrt.h b/src/include/libabrt.h index c7d2bae..bb23ec3 100644 --- a/src/include/libabrt.h +++ b/src/include/libabrt.h @@ -71,6 +71,8 @@ char *koops_extract_version(const char *line); char *kernel_tainted_short(const char *kernel_bt); #define koops_hash_str abrt_koops_hash_str void koops_hash_str(char hash_str[SHA1_RESULT_LEN*2 + 1], char *oops_buf, const char *oops_ptr); +#define koops_extract_oopses abrt_koops_extract_oopses +void koops_extract_oopses(GList **oops_list, char *buffer, size_t buflen);
#ifdef __cplusplus } diff --git a/src/lib/kernel.c b/src/lib/kernel.c index 25fab21..ed7c754 100644 --- a/src/lib/kernel.c +++ b/src/lib/kernel.c @@ -19,6 +19,353 @@
#include "libabrt.h"
+/* + * extract_oops tries to find oops signatures in a log + */ + +struct line_info { + char *ptr; + char level; +}; + +static void record_oops(GList **oops_list, struct line_info* lines_info, int oopsstart, int oopsend) +{ + int q; + int len; + int rv = 1; + + len = 2; + for (q = oopsstart; q <= oopsend; q++) + len += strlen(lines_info[q].ptr) + 1; + + /* too short oopses are invalid */ + if (len > 100) + { + char *oops = (char*)xzalloc(len); + char *dst = oops; + char *version = NULL; + for (q = oopsstart; q <= oopsend; q++) + { + if (!version) + version = koops_extract_version(lines_info[q].ptr); + if (lines_info[q].ptr[0]) + { + dst = stpcpy(dst, lines_info[q].ptr); + dst = stpcpy(dst, "\n"); + } + } + if ((dst - oops) > 100) + { + *oops_list = g_list_append( + *oops_list, + xasprintf("%s\n%s", (version ? version : "undefined"), oops) + ); + } + else + { + /* too short oopses are invalid */ + rv = 0; + } + free(oops); + free(version); + } + + VERB3 if (rv == 0) log("Dropped oops: too short"); +} + +void koops_extract_oopses(GList **oops_list, char *buffer, size_t buflen) +{ + char *c; + int linecount = 0; + int lines_info_size = 0; + struct line_info *lines_info = NULL; + + /* Split buffer into lines */ + + if (buflen != 0) + buffer[buflen - 1] = '\n'; /* the buffer usually ends with \n, but let's make sure */ + c = buffer; + while (c < buffer + buflen) + { + char linelevel; + char *c9; + char *colon; + + linecount++; + c9 = (char*)memchr(c, '\n', buffer + buflen - c); /* a \n will always be found */ + assert(c9); + *c9 = '\0'; /* turn the \n into a string termination */ + if (c9 == c) + goto next_line; + + /* Is it a syslog file (/var/log/messages or similar)? + * Even though _usually_ it looks like "Nov 19 12:34:38 localhost kernel: xxx", + * some users run syslog in non-C locale: + * "2010-02-22T09:24:08.156534-08:00 gnu-4 gnome-session[2048]: blah blah" + * ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ !!! + * We detect it by checking for N:NN:NN pattern in first 15 chars + * (and this still is not good enough... false positive: "pci 0000:15:00.0: PME# disabled") + */ + colon = strchr(c, ':'); + if (colon && colon > c && colon < c + 15 + && isdigit(colon[-1]) /* N:... */ + && isdigit(colon[1]) /* ...N:NN:... */ + && isdigit(colon[2]) + && colon[3] == ':' + && isdigit(colon[4]) /* ...N:NN:NN... */ + && isdigit(colon[5]) + ) { + /* It's syslog file, not a bare dmesg */ + + /* Skip non-kernel lines */ + char *kernel_str = strstr(c, "kernel: "); + if (!kernel_str) + { + /* if we see our own marker: + * "hostname abrt: Kerneloops: Reported 1 kernel oopses to Abrt" + * we know we submitted everything upto here already */ + if (strstr(c, "kernel oopses to Abrt")) + { + VERB3 log("Found our marker at line %d", linecount); + free(lines_info); + lines_info = NULL; + lines_info_size = 0; + list_free_with_free(*oops_list); + *oops_list = NULL; + } + goto next_line; + } + c = kernel_str + sizeof("kernel: ")-1; + } + + linelevel = 0; + /* store and remove kernel log level */ + if (*c == '<' && c[1] && c[2] == '>') + { + linelevel = c[1]; + c += 3; + } + /* remove jiffies time stamp counter if present + * jiffies are unsigned long, so it can be 2^64 long, which is + * 20 decimal digits*/ + if (*c == '[') + { + char *c2 = strchr(c, '.'); + char *c3 = strchr(c, ']'); + if (c2 && c3 && (c2 < c3) && (c3-c) < 21 && (c2-c) < 8) + { + c = c3 + 1; + if (*c == ' ') + c++; + } + } + if ((lines_info_size & 0xfff) == 0) + { + lines_info = xrealloc(lines_info, (lines_info_size + 0x1000) * sizeof(lines_info[0])); + } + lines_info[lines_info_size].ptr = c; + lines_info[lines_info_size].level = linelevel; + lines_info_size++; +next_line: + c = c9 + 1; + } + + /* Analyze lines */ + + int i; + char prevlevel = 0; + int oopsstart = -1; + int inbacktrace = 0; + + i = 0; + while (i < lines_info_size) + { + char *curline = lines_info[i].ptr; + + if (curline == NULL) + { + i++; + continue; + } + while (*curline == ' ') + curline++; + + if (oopsstart < 0) + { + /* Find start-of-oops markers */ + /* In some comparisons, we skip 1st letter, to avoid dealing with + * changes in capitalization in kernel. For example, I see that + * current kernel git (at 2011-01-01) has both "kernel BUG at ..." + * and "Kernel BUG at ..." messages, and I don't want to change + * the code below whenever kernel is changed to use "K" (or "k") + * uniformly. + */ + if (strstr(curline, /*g*/ "eneral protection fault:")) + oopsstart = i; + else if (strstr(curline, "BUG:")) + oopsstart = i; + else if (strstr(curline, /*k*/ "ernel BUG at")) + oopsstart = i; + /* WARN_ON() generated message */ + else if (strstr(curline, "WARNING: at ")) + oopsstart = i; + else if (strstr(curline, /*u*/ "nable to handle kernel")) + oopsstart = i; + else if (strstr(curline, /*d*/ "ouble fault:")) + oopsstart = i; + else if (strstr(curline, "do_IRQ: stack overflow:")) + oopsstart = i; + else if (strstr(curline, "RTNL: assertion failed")) + oopsstart = i; + else if (strstr(curline, /*e*/ "eek! page_mapcount(page) went negative!")) + oopsstart = i; + else if (strstr(curline, /*n*/ "ear stack overflow (cur:")) + oopsstart = i; + else if (strstr(curline, /*b*/ "adness at")) + oopsstart = i; + else if (strstr(curline, "NETDEV WATCHDOG")) + oopsstart = i; + else if (strstr(curline, /*s*/ "ysctl table check failed")) + oopsstart = i; + else if (strstr(curline, "INFO: possible recursive locking detected")) + oopsstart = i; + // Not needed: "--[ cut here ]--" is always followed + // by "Badness at", "kernel BUG at", or "WARNING: at" string + //else if (strstr(curline, "------------[ cut here ]------------")) + // oopsstart = i; + else if (strstr(curline, "list_del corruption")) + oopsstart = i; + else if (strstr(curline, "list_add corruption")) + oopsstart = i; + /* "irq NN: nobody cared..." */ + else if (strstr(curline, ": nobody cared")) + oopsstart = i; + else if (strstr(curline, "IRQ handler type mismatch")) + oopsstart = i; + + if (oopsstart >= 0) + { + /* debug information */ + VERB3 { + log("Found oops at line %d: '%s'", oopsstart, lines_info[oopsstart].ptr); + if (oopsstart != i) + log("Trigger line is %d: '%s'", i, c); + } + /* try to find the end marker */ + int i2 = i + 1; + while (i2 < lines_info_size && i2 < (i+50)) + { + if (strstr(lines_info[i2].ptr, "---[ end trace")) + { + inbacktrace = 1; + i = i2; + break; + } + i2++; + } + } + } + + /* Are we entering a call trace part? */ + /* a call trace starts with "Call Trace:" or with the " [<.......>] function+0xFF/0xAA" pattern */ + if (oopsstart >= 0 && !inbacktrace) + { + if (strstr(curline, "Call Trace:")) + inbacktrace = 1; + else + if (strnlen(curline, 9) > 8 + && curline[0] == '[' && curline[1] == '<' + && strstr(curline, ">]") + && strstr(curline, "+0x") + && strstr(curline, "/0x") + ) { + inbacktrace = 1; + } + } + + /* Are we at the end of an oops? */ + else if (oopsstart >= 0 && inbacktrace) + { + int oopsend = INT_MAX; + + /* line needs to start with " [" or have "] [" if it is still a call trace */ + /* example: "[<ffffffffa006c156>] radeon_get_ring_head+0x16/0x41 [radeon]" */ + if (curline[0] != '[' + && !strstr(curline, "] [") + && !strstr(curline, "--- Exception") + && !strstr(curline, "LR =") + && !strstr(curline, "<#DF>") + && !strstr(curline, "<IRQ>") + && !strstr(curline, "<EOI>") + && !strstr(curline, "<<EOE>>") + && strncmp(curline, "Code: ", 6) != 0 + && strncmp(curline, "RIP ", 4) != 0 + && strncmp(curline, "RSP ", 4) != 0 + ) { + oopsend = i-1; /* not a call trace line */ + } + /* oops lines are always more than 8 chars long */ + else if (strnlen(curline, 8) < 8) + oopsend = i-1; + /* single oopses are of the same loglevel */ + else if (lines_info[i].level != prevlevel) + oopsend = i-1; + else if (strstr(curline, "Instruction dump:")) + oopsend = i; + /* if a new oops starts, this one has ended */ + else if (strstr(curline, "WARNING: at ") && oopsstart != i) /* WARN_ON() generated message */ + oopsend = i-1; + else if (strstr(curline, "Unable to handle") && oopsstart != i) + oopsend = i-1; + /* kernel end-of-oops marker (not including marker itself) */ + else if (strstr(curline, "---[ end trace")) + oopsend = i-1; + + if (oopsend <= i) + { + VERB3 log("End of oops at line %d (%d): '%s'", oopsend, i, lines_info[oopsend].ptr); + record_oops(oops_list, lines_info, oopsstart, oopsend); + oopsstart = -1; + inbacktrace = 0; + } + } + + prevlevel = lines_info[i].level; + i++; + + if (oopsstart >= 0) + { + /* Do we have a suspiciously long oops? Cancel it. + * Bumped from 60 to 80 (see examples/oops_recursive_locking1.test) + */ + if (i - oopsstart > 80) + { + inbacktrace = 0; + oopsstart = -1; + VERB3 log("Dropped oops, too long"); + continue; + } + if (!inbacktrace && i - oopsstart > 40) + { + /*inbacktrace = 0; - already is */ + oopsstart = -1; + VERB3 log("Dropped oops, too long"); + continue; + } + } + } /* while (i < lines_info_size) */ + + /* process last oops if we have one */ + if (oopsstart >= 0 && inbacktrace) + { + int oopsend = i-1; + VERB3 log("End of oops at line %d (end of file): '%s'", oopsend, lines_info[oopsend].ptr); + record_oops(oops_list, lines_info, oopsstart, oopsend); + } + + free(lines_info); +} + void koops_hash_str(char hash_str[SHA1_RESULT_LEN*2 + 1], char *oops_buf, const char *oops_ptr) { // Example of call trace part of oops: diff --git a/src/plugins/abrt-dump-oops.c b/src/plugins/abrt-dump-oops.c index 006c801..60b84fa 100644 --- a/src/plugins/abrt-dump-oops.c +++ b/src/plugins/abrt-dump-oops.c @@ -22,354 +22,6 @@ #include "libabrt.h"
-/* - * extract_oops tries to find oops signatures in a log - */ - -struct line_info { - char *ptr; - char level; -}; - -static void record_oops(GList **oops_list, struct line_info* lines_info, int oopsstart, int oopsend) -{ - int q; - int len; - int rv = 1; - - len = 2; - for (q = oopsstart; q <= oopsend; q++) - len += strlen(lines_info[q].ptr) + 1; - - /* too short oopses are invalid */ - if (len > 100) - { - char *oops = (char*)xzalloc(len); - char *dst = oops; - char *version = NULL; - for (q = oopsstart; q <= oopsend; q++) - { - if (!version) - version = koops_extract_version(lines_info[q].ptr); - if (lines_info[q].ptr[0]) - { - dst = stpcpy(dst, lines_info[q].ptr); - dst = stpcpy(dst, "\n"); - } - } - if ((dst - oops) > 100) - { - *oops_list = g_list_append( - *oops_list, - xasprintf("%s\n%s", (version ? version : "undefined"), oops) - ); - } - else - { - /* too short oopses are invalid */ - rv = 0; - } - free(oops); - free(version); - } - - VERB3 if (rv == 0) log("Dropped oops: too short"); -} - -static void extract_oopses(GList **oops_list, char *buffer, size_t buflen) -{ - char *c; - int linecount = 0; - int lines_info_size = 0; - struct line_info *lines_info = NULL; - - /* Split buffer into lines */ - - if (buflen != 0) - buffer[buflen - 1] = '\n'; /* the buffer usually ends with \n, but let's make sure */ - c = buffer; - while (c < buffer + buflen) - { - char linelevel; - char *c9; - char *colon; - - linecount++; - c9 = (char*)memchr(c, '\n', buffer + buflen - c); /* a \n will always be found */ - assert(c9); - *c9 = '\0'; /* turn the \n into a string termination */ - if (c9 == c) - goto next_line; - - /* Is it a syslog file (/var/log/messages or similar)? - * Even though _usually_ it looks like "Nov 19 12:34:38 localhost kernel: xxx", - * some users run syslog in non-C locale: - * "2010-02-22T09:24:08.156534-08:00 gnu-4 gnome-session[2048]: blah blah" - * ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ !!! - * We detect it by checking for N:NN:NN pattern in first 15 chars - * (and this still is not good enough... false positive: "pci 0000:15:00.0: PME# disabled") - */ - colon = strchr(c, ':'); - if (colon && colon > c && colon < c + 15 - && isdigit(colon[-1]) /* N:... */ - && isdigit(colon[1]) /* ...N:NN:... */ - && isdigit(colon[2]) - && colon[3] == ':' - && isdigit(colon[4]) /* ...N:NN:NN... */ - && isdigit(colon[5]) - ) { - /* It's syslog file, not a bare dmesg */ - - /* Skip non-kernel lines */ - char *kernel_str = strstr(c, "kernel: "); - if (!kernel_str) - { - /* if we see our own marker: - * "hostname abrt: Kerneloops: Reported 1 kernel oopses to Abrt" - * we know we submitted everything upto here already */ - if (strstr(c, "kernel oopses to Abrt")) - { - VERB3 log("Found our marker at line %d", linecount); - free(lines_info); - lines_info = NULL; - lines_info_size = 0; - list_free_with_free(*oops_list); - *oops_list = NULL; - } - goto next_line; - } - c = kernel_str + sizeof("kernel: ")-1; - } - - linelevel = 0; - /* store and remove kernel log level */ - if (*c == '<' && c[1] && c[2] == '>') - { - linelevel = c[1]; - c += 3; - } - /* remove jiffies time stamp counter if present - * jiffies are unsigned long, so it can be 2^64 long, which is - * 20 decimal digits*/ - if (*c == '[') - { - char *c2 = strchr(c, '.'); - char *c3 = strchr(c, ']'); - if (c2 && c3 && (c2 < c3) && (c3-c) < 21 && (c2-c) < 8) - { - c = c3 + 1; - if (*c == ' ') - c++; - } - } - if ((lines_info_size & 0xfff) == 0) - { - lines_info = xrealloc(lines_info, (lines_info_size + 0x1000) * sizeof(lines_info[0])); - } - lines_info[lines_info_size].ptr = c; - lines_info[lines_info_size].level = linelevel; - lines_info_size++; -next_line: - c = c9 + 1; - } - - /* Analyze lines */ - - int i; - char prevlevel = 0; - int oopsstart = -1; - int inbacktrace = 0; - - i = 0; - while (i < lines_info_size) - { - char *curline = lines_info[i].ptr; - - if (curline == NULL) - { - i++; - continue; - } - while (*curline == ' ') - curline++; - - if (oopsstart < 0) - { - /* Find start-of-oops markers */ - /* In some comparisons, we skip 1st letter, to avoid dealing with - * changes in capitalization in kernel. For example, I see that - * current kernel git (at 2011-01-01) has both "kernel BUG at ..." - * and "Kernel BUG at ..." messages, and I don't want to change - * the code below whenever kernel is changed to use "K" (or "k") - * uniformly. - */ - if (strstr(curline, /*g*/ "eneral protection fault:")) - oopsstart = i; - else if (strstr(curline, "BUG:")) - oopsstart = i; - else if (strstr(curline, /*k*/ "ernel BUG at")) - oopsstart = i; - /* WARN_ON() generated message */ - else if (strstr(curline, "WARNING: at ")) - oopsstart = i; - else if (strstr(curline, /*u*/ "nable to handle kernel")) - oopsstart = i; - else if (strstr(curline, /*d*/ "ouble fault:")) - oopsstart = i; - else if (strstr(curline, "do_IRQ: stack overflow:")) - oopsstart = i; - else if (strstr(curline, "RTNL: assertion failed")) - oopsstart = i; - else if (strstr(curline, /*e*/ "eek! page_mapcount(page) went negative!")) - oopsstart = i; - else if (strstr(curline, /*n*/ "ear stack overflow (cur:")) - oopsstart = i; - else if (strstr(curline, /*b*/ "adness at")) - oopsstart = i; - else if (strstr(curline, "NETDEV WATCHDOG")) - oopsstart = i; - else if (strstr(curline, /*s*/ "ysctl table check failed")) - oopsstart = i; - else if (strstr(curline, "INFO: possible recursive locking detected")) - oopsstart = i; - // Not needed: "--[ cut here ]--" is always followed - // by "Badness at", "kernel BUG at", or "WARNING: at" string - //else if (strstr(curline, "------------[ cut here ]------------")) - // oopsstart = i; - else if (strstr(curline, "list_del corruption")) - oopsstart = i; - else if (strstr(curline, "list_add corruption")) - oopsstart = i; - /* "irq NN: nobody cared..." */ - else if (strstr(curline, ": nobody cared")) - oopsstart = i; - else if (strstr(curline, "IRQ handler type mismatch")) - oopsstart = i; - - if (oopsstart >= 0) - { - /* debug information */ - VERB3 { - log("Found oops at line %d: '%s'", oopsstart, lines_info[oopsstart].ptr); - if (oopsstart != i) - log("Trigger line is %d: '%s'", i, c); - } - /* try to find the end marker */ - int i2 = i + 1; - while (i2 < lines_info_size && i2 < (i+50)) - { - if (strstr(lines_info[i2].ptr, "---[ end trace")) - { - inbacktrace = 1; - i = i2; - break; - } - i2++; - } - } - } - - /* Are we entering a call trace part? */ - /* a call trace starts with "Call Trace:" or with the " [<.......>] function+0xFF/0xAA" pattern */ - if (oopsstart >= 0 && !inbacktrace) - { - if (strstr(curline, "Call Trace:")) - inbacktrace = 1; - else - if (strnlen(curline, 9) > 8 - && curline[0] == '[' && curline[1] == '<' - && strstr(curline, ">]") - && strstr(curline, "+0x") - && strstr(curline, "/0x") - ) { - inbacktrace = 1; - } - } - - /* Are we at the end of an oops? */ - else if (oopsstart >= 0 && inbacktrace) - { - int oopsend = INT_MAX; - - /* line needs to start with " [" or have "] [" if it is still a call trace */ - /* example: "[<ffffffffa006c156>] radeon_get_ring_head+0x16/0x41 [radeon]" */ - if (curline[0] != '[' - && !strstr(curline, "] [") - && !strstr(curline, "--- Exception") - && !strstr(curline, "LR =") - && !strstr(curline, "<#DF>") - && !strstr(curline, "<IRQ>") - && !strstr(curline, "<EOI>") - && !strstr(curline, "<<EOE>>") - && strncmp(curline, "Code: ", 6) != 0 - && strncmp(curline, "RIP ", 4) != 0 - && strncmp(curline, "RSP ", 4) != 0 - ) { - oopsend = i-1; /* not a call trace line */ - } - /* oops lines are always more than 8 chars long */ - else if (strnlen(curline, 8) < 8) - oopsend = i-1; - /* single oopses are of the same loglevel */ - else if (lines_info[i].level != prevlevel) - oopsend = i-1; - else if (strstr(curline, "Instruction dump:")) - oopsend = i; - /* if a new oops starts, this one has ended */ - else if (strstr(curline, "WARNING: at ") && oopsstart != i) /* WARN_ON() generated message */ - oopsend = i-1; - else if (strstr(curline, "Unable to handle") && oopsstart != i) - oopsend = i-1; - /* kernel end-of-oops marker (not including marker itself) */ - else if (strstr(curline, "---[ end trace")) - oopsend = i-1; - - if (oopsend <= i) - { - VERB3 log("End of oops at line %d (%d): '%s'", oopsend, i, lines_info[oopsend].ptr); - record_oops(oops_list, lines_info, oopsstart, oopsend); - oopsstart = -1; - inbacktrace = 0; - } - } - - prevlevel = lines_info[i].level; - i++; - - if (oopsstart >= 0) - { - /* Do we have a suspiciously long oops? Cancel it. - * Bumped from 60 to 80 (see examples/oops_recursive_locking1.test) - */ - if (i - oopsstart > 80) - { - inbacktrace = 0; - oopsstart = -1; - VERB3 log("Dropped oops, too long"); - continue; - } - if (!inbacktrace && i - oopsstart > 40) - { - /*inbacktrace = 0; - already is */ - oopsstart = -1; - VERB3 log("Dropped oops, too long"); - continue; - } - } - } /* while (i < lines_info_size) */ - - /* process last oops if we have one */ - if (oopsstart >= 0 && inbacktrace) - { - int oopsend = i-1; - VERB3 log("End of oops at line %d (end of file): '%s'", oopsend, lines_info[oopsend].ptr); - record_oops(oops_list, lines_info, oopsstart, oopsend); - } - - free(lines_info); -} - - static bool world_readable_dump = false; static const char *debug_dumps_dir = ".";
@@ -387,7 +39,7 @@ static void scan_dmesg(GList **oops_list) */ char *buffer = xzalloc(16*1024); syscall(__NR_syslog, 3, buffer, 16*1024 - 1); /* always NUL terminated */ - extract_oopses(oops_list, buffer, strlen(buffer)); + koops_extract_oopses(oops_list, buffer, strlen(buffer)); free(buffer); }
@@ -446,7 +98,7 @@ static int scan_syslog_file(GList **oops_list, int fd, struct stat *statbuf, int if (partial_line_len > 500) /* cap it */ partial_line_len = 500;
- extract_oopses(oops_list, buffer, r); + koops_extract_oopses(oops_list, buffer, r); cur_pos += r; } while (cur_pos < statbuf->st_size);
diff --git a/tests/koops-parser.at b/tests/koops-parser.at index f6b2f63..493098b 100644 --- a/tests/koops-parser.at +++ b/tests/koops-parser.at @@ -148,3 +148,41 @@ int main(void) }
]]) + +AT_TESTFUN([koops_remove_jiffies_timestamp], +[[ +#include "libabrt.h" +#include "koops-test.h" + +int run_test(const struct test_struct *test) +{ + char *oops_jiffies = fread_full(test->filename); + char *oops_no_jiffies = fread_full(test->expected_results); + + /* for testing purpose, I will record only one koops */ + GList *oops_list = NULL; + koops_extract_oopses(&oops_list, oops_jiffies, strlen(oops_jiffies)); + + if (oops_list && !strcmp((char *)oops_list->data, oops_no_jiffies)) + return 0; + + log("'%s' \n '%s'", (char *)oops_list->data, oops_no_jiffies); + + return 1; +} + +int main(void) +{ + struct test_struct all_same_hashes[] = { + { EXAMPLE_PFX"/oops-with-jiffies.test", EXAMPLE_PFX"/oops-with-jiffies.right" }, + { EXAMPLE_PFX"/oops_recursive_locking1.test", EXAMPLE_PFX"/oops_recursive_locking1-no-jiffies.test"}, + }; + + int ret = 0; + for (int i = 0; i < ARRAY_SIZE(all_same_hashes); ++i) + ret |= run_test(&all_same_hashes[i]); + + return ret; +} + +]])
crash-catcher@lists.fedorahosted.org