From patchwork Fri Apr 5 22:08:56 2024 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Ilya Maximets X-Patchwork-Id: 1920348 X-Patchwork-Delegate: i.maximets@samsung.com Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@legolas.ozlabs.org Authentication-Results: legolas.ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=openvswitch.org (client-ip=140.211.166.137; helo=smtp4.osuosl.org; envelope-from=ovs-dev-bounces@openvswitch.org; receiver=patchwork.ozlabs.org) Received: from smtp4.osuosl.org (smtp4.osuosl.org [140.211.166.137]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature ECDSA (secp384r1) server-digest SHA384) (No client certificate requested) by legolas.ozlabs.org (Postfix) with ESMTPS id 4VBCLC0tfmz1yYb for ; Sat, 6 Apr 2024 09:08:35 +1100 (AEDT) Received: from localhost (localhost [127.0.0.1]) by smtp4.osuosl.org (Postfix) with ESMTP id D86AA41876; Fri, 5 Apr 2024 22:08:32 +0000 (UTC) X-Virus-Scanned: amavis at osuosl.org Received: from smtp4.osuosl.org ([127.0.0.1]) by localhost (smtp4.osuosl.org [127.0.0.1]) (amavis, port 10024) with ESMTP id zVO27xUVrElf; Fri, 5 Apr 2024 22:08:23 +0000 (UTC) X-Comment: SPF check N/A for local connections - client-ip=140.211.9.56; helo=lists.linuxfoundation.org; envelope-from=ovs-dev-bounces@openvswitch.org; receiver= DKIM-Filter: OpenDKIM Filter v2.11.0 smtp4.osuosl.org 1C9B3400A5 Received: from lists.linuxfoundation.org (lf-lists.osuosl.org [140.211.9.56]) by smtp4.osuosl.org (Postfix) with ESMTPS id 1C9B3400A5; Fri, 5 Apr 2024 22:08:22 +0000 (UTC) Received: from lf-lists.osuosl.org (localhost [127.0.0.1]) by lists.linuxfoundation.org (Postfix) with ESMTP id 5EE7CC0072; Fri, 5 Apr 2024 22:08:22 +0000 (UTC) X-Original-To: ovs-dev@openvswitch.org Delivered-To: ovs-dev@lists.linuxfoundation.org Received: from smtp4.osuosl.org (smtp4.osuosl.org [IPv6:2605:bc80:3010::137]) by lists.linuxfoundation.org (Postfix) with ESMTP id 1BC66C0037 for ; Fri, 5 Apr 2024 22:08:21 +0000 (UTC) Received: from localhost (localhost [127.0.0.1]) by smtp4.osuosl.org (Postfix) with ESMTP id F11A241D82 for ; Fri, 5 Apr 2024 22:08:20 +0000 (UTC) X-Virus-Scanned: amavis at osuosl.org Received: from smtp4.osuosl.org ([127.0.0.1]) by localhost (smtp4.osuosl.org [127.0.0.1]) (amavis, port 10024) with ESMTP id Lv4Mzb6Lh-Bl for ; Fri, 5 Apr 2024 22:08:20 +0000 (UTC) Received-SPF: Pass (mailfrom) identity=mailfrom; client-ip=2001:4b98:dc4:8::226; helo=relay6-d.mail.gandi.net; envelope-from=i.maximets@ovn.org; receiver= DMARC-Filter: OpenDMARC Filter v1.4.2 smtp4.osuosl.org BBD2C40341 Authentication-Results: smtp4.osuosl.org; dmarc=none (p=none dis=none) header.from=ovn.org DKIM-Filter: OpenDKIM Filter v2.11.0 smtp4.osuosl.org BBD2C40341 Received: from relay6-d.mail.gandi.net (relay6-d.mail.gandi.net [IPv6:2001:4b98:dc4:8::226]) by smtp4.osuosl.org (Postfix) with ESMTPS id BBD2C40341 for ; Fri, 5 Apr 2024 22:08:19 +0000 (UTC) Received: by mail.gandi.net (Postfix) with ESMTPSA id 4F13FC0002; Fri, 5 Apr 2024 22:08:16 +0000 (UTC) From: Ilya Maximets To: ovs-dev@openvswitch.org Date: Sat, 6 Apr 2024 00:08:56 +0200 Message-ID: <20240405220857.2360287-1-i.maximets@ovn.org> X-Mailer: git-send-email 2.44.0 MIME-Version: 1.0 X-GND-Sasl: i.maximets@ovn.org Cc: Ilya Maximets Subject: [ovs-dev] [PATCH] vlog: Log stack trace on vlog_abort. X-BeenThere: ovs-dev@openvswitch.org X-Mailman-Version: 2.1.15 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: ovs-dev-bounces@openvswitch.org Sender: "dev" Currently, calls like ovs_assert() just print out a condition that caused assertion to fail. But it may be not enough to understand what exactly has happened, especially if assertion failed in some generic function like dp_packet_resize() or similar. Print the stack trace along with the abort message to give more context for the later debugging. This should be especially useful in case the issue happens in an environment with core dumps disabled. Adding the log to vlog_abort() to cover a little more cases where VLOG_ABORT is called and not only assertion failures. It would be nice to also have stack traces in case of reaching the OVS_NOT_REACHED(). But this macro is used in some places as a last resort and should not actually do more than just stopping the process immediately. And it also can be used in contexts without logging initialized. Such a change will need to be done more carefully. Better solution might be to use VLOG_ABORT() where appropriate instead. Signed-off-by: Ilya Maximets Acked-by: Kevin Traynor Acked-by: Simon Horman --- lib/vlog.c | 10 ++++++++-- tests/library.at | 4 +++- 2 files changed, 11 insertions(+), 3 deletions(-) diff --git a/lib/vlog.c b/lib/vlog.c index b2653142f..e78c785f7 100644 --- a/lib/vlog.c +++ b/lib/vlog.c @@ -29,6 +29,7 @@ #include #include #include "async-append.h" +#include "backtrace.h" #include "coverage.h" #include "dirs.h" #include "openvswitch/dynamic-string.h" @@ -1274,8 +1275,9 @@ vlog_fatal(const struct vlog_module *module, const char *message, ...) va_end(args); } -/* Logs 'message' to 'module' at maximum verbosity, then calls abort(). Always - * writes the message to stderr, even if the console destination is disabled. +/* Attempts to log a stack trace, logs 'message' to 'module' at maximum + * verbosity, then calls abort(). Always writes the message to stderr, even + * if the console destination is disabled. * * Choose this function instead of vlog_fatal_valist() if the daemon monitoring * facility should automatically restart the current daemon. */ @@ -1289,6 +1291,10 @@ vlog_abort_valist(const struct vlog_module *module_, * message written by the later ovs_abort_valist(). */ module->levels[VLF_CONSOLE] = VLL_OFF; + /* Printing the stack trace before the 'message', because the 'message' + * will flush the async log queue (VLL_EMER). With a different order we + * would need to flush the queue manually again. */ + log_backtrace(); vlog_valist(module, VLL_EMER, message, args); ovs_abort_valist(0, message, args); } diff --git a/tests/library.at b/tests/library.at index 7b4acebb8..d962e1b3f 100644 --- a/tests/library.at +++ b/tests/library.at @@ -230,7 +230,9 @@ AT_CHECK([ovstest test-util -voff -vfile:info '-vPATTERN:file:%c|%p|%m' --log-fi [$exit_status], [], [stderr]) AT_CHECK([sed 's/\(opened log file\) .*/\1/ -s/|[[^|]]*: /|/' test-util.log], [0], [dnl +s/|[[^|]]*: /|/ +/backtrace/d +/|.*|/!d' test-util.log], [0], [dnl vlog|INFO|opened log file util|EMER|assertion false failed in test_assert() ])