From 2d74bedd0990c2ba606a7310063b0885c12aaa8a Mon Sep 17 00:00:00 2001 From: Kienan Stewart Date: Wed, 28 Jun 2023 11:28:55 -0400 Subject: [PATCH] Fix: sessiond: preserve jul/log4j domain loglevels MIME-Version: 1.0 Content-Type: text/plain; charset=utf8 Content-Transfer-Encoding: 8bit Issue observed ============== Following dcd24bbf7dbc74e3584d1d0d52715e749023c452, the lttng-ust-java-tests started failing with a number of errors such as the following [1]: ``` org.opentest4j.AssertionFailedError: expected: java.util.Collections$SingletonList@3270d194<[Event name = eventA, Log level selector = (LTTNG_EVENT_LOGLEVEL_ALL), Filter string = logger_name == "eventA"]> but was: java.util.ArrayList@235834f2<[Event name = eventA, Log level selector = (LTTNG_EVENT_LOGLEVEL_ALL), Filter string = logger_name == "eventA"]> at org.lttng.ust.agent.integration.client.TcpClientIT.testEnableEvent(TcpClientIT.java:187 ``` While the assertion failure print out looks like the events are the same, there is a difference in between the objects which is not printed: the loglevel integer value. For example: ``` eventA [level -2147483648, type 0]: logger_name == "eventA" eventB [level -2147483648, type 0]: logger_name == "eventB" eventA [level -1, type 0]: logger_name == "eventA" eventB [level -1, type 0]: logger_name == "eventB" ``` Cause ===== When events are created from payloads in `src/common/event.cpp:lttng_event_create_from_payload`, the loglevel value is coerced to `-1` when the loglevel_type is LTTNG_EVENT_LOGLEVEL_ALL. Consider the event created in `lttng enable-event --jul eventName`. The loglevel_type and loglevel will be set as follows: * loglevel_type: LTTNG_EVENT_LOGLEVEL_ALL (0) * loglevel: LTTNG_EVENT_LOGLEVEL_JUL_ALL (-2147483648) The event created is then serialized and sent to the sessiond which recreates it from the payload removing the value set initially. The normalization performed in `src/bin/lttng-sessiond/cmd.cpp` has the same effect. Solution ======== Remove the normalization of the the loglevel to -1 when events with loglevel_type LTTNG_EVENT_LOGLEVEL_ALL are created from payloads or processed via `_cmd_enable_event`. A test has been added to confirm that the modification doesn't regress on the issue flagged in https://bugs.lttng.org/issues/1373 which lead to the normalization changes being made. This change isn't an exhaustive audit of the packet outputs which may or may not leak the '-1' "unset" value. One potential change to the normalization may be to have the normalization be domain-aware and always default to the domain's "ALL" value. Note that not all domains have the concept of an "unset" level. References ========== [1] https://ci.lttng.org/job/lttng-ust-java-tests_master_build/java_version=java-11-openjdk,platform=bionic-amd64/3302/consoleFull Refs: #1373 Signed-off-by: Kienan Stewart Signed-off-by: Jérémie Galarneau Change-Id: Iac653157190b61b44d5ff18ac968fef58330a106 --- configure.ac | 1 + tests/regression/Makefile.am | 3 +- tests/regression/tools/Makefile.am | 1 + tests/regression/tools/client/Makefile.am | 18 ++++++ ...est_bug1373_events_differ_only_by_loglevel | 60 +++++++++++++++++++ tests/utils/utils.sh | 14 ++++- 6 files changed, 94 insertions(+), 3 deletions(-) create mode 100644 tests/regression/tools/client/Makefile.am create mode 100755 tests/regression/tools/client/test_bug1373_events_differ_only_by_loglevel diff --git a/configure.ac b/configure.ac index dbba02672..43d9d3933 100644 --- a/configure.ac +++ b/configure.ac @@ -1158,6 +1158,7 @@ AC_CONFIG_FILES([ tests/regression/tools/mi/Makefile tests/regression/tools/wildcard/Makefile tests/regression/tools/channel/Makefile + tests/regression/tools/client/Makefile tests/regression/tools/crash/Makefile tests/regression/tools/regen-metadata/Makefile tests/regression/tools/regen-statedump/Makefile diff --git a/tests/regression/Makefile.am b/tests/regression/Makefile.am index 7ac7e0974..e556223d8 100644 --- a/tests/regression/Makefile.am +++ b/tests/regression/Makefile.am @@ -55,7 +55,8 @@ TESTS = tools/base-path/test_ust \ tools/trigger/test_list_triggers_cli \ tools/trigger/test_remove_trigger_cli \ tools/trigger/name/test_trigger_name_backwards_compat \ - tools/trigger/hidden/test_hidden_trigger + tools/trigger/hidden/test_hidden_trigger \ + tools/client/test_bug1373_events_differ_only_by_loglevel if HAVE_LIBLTTNG_UST_CTL SUBDIRS += ust diff --git a/tests/regression/tools/Makefile.am b/tests/regression/tools/Makefile.am index fc39333c0..153dc036f 100644 --- a/tests/regression/tools/Makefile.am +++ b/tests/regression/tools/Makefile.am @@ -3,6 +3,7 @@ SUBDIRS = base-path \ channel \ clear \ + client \ crash \ exclusion \ filtering \ diff --git a/tests/regression/tools/client/Makefile.am b/tests/regression/tools/client/Makefile.am new file mode 100644 index 000000000..ee3ee0a38 --- /dev/null +++ b/tests/regression/tools/client/Makefile.am @@ -0,0 +1,18 @@ +# SPDX-License-Identifier: GPL-2.0-only + +noinst_SCRIPTS = test_bug1373_events_differ_only_by_loglevel +EXTRA_DIST = test_bug1373_events_differ_only_by_loglevel + +all-local: + @if [ x"$(srcdir)" != x"$(builddir)" ]; then \ + for script in $(EXTRA_DIST); do \ + cp -f $(srcdir)/$$script $(builddir); \ + done; \ + fi + +clean-local: + @if [ x"$(srcdir)" != x"$(builddir)" ]; then \ + for script in $(EXTRA_DIST); do \ + rm -f $(builddir)/$$script; \ + done; \ + fi diff --git a/tests/regression/tools/client/test_bug1373_events_differ_only_by_loglevel b/tests/regression/tools/client/test_bug1373_events_differ_only_by_loglevel new file mode 100755 index 000000000..150858388 --- /dev/null +++ b/tests/regression/tools/client/test_bug1373_events_differ_only_by_loglevel @@ -0,0 +1,60 @@ +#!/bin/bash +# +# Copyright (C) 2023 Kienan Stewart +# +# SPDX-License-Identifier: LGPL-2.1-only +# + +TEST_DESC="lttng-sessiond should not crash when activating rules that different by loglevel only" + +CURDIR=$(dirname "$0") +TESTDIR=$(realpath "${CURDIR}/../../../") + +# Test app for ust event +TESTAPP_PATH="${TESTDIR}/utils/testapp" +TESTAPP_NAME="gen-ust-events" +TESTAPP_BIN="${TESTAPP_PATH}/${TESTAPP_NAME}/${TESTAPP_NAME}" +NR_USEC_WAIT=1 +NR_ITER=100000 + +SESSION_NAME="test_session" +CHANNEL_NAME="test_channel" +EVENT_NAME="'l*'" + +OUTPUT_DIR=$(mktemp -d -t tmp.test_events_differ_only_by_loglevels.XXXXXX) + +NUM_TESTS=9 + +# shellcheck source-path=SCRIPTDIR/../../../ +source "${TESTDIR}/utils/utils.sh" + +if [ ! -x "${TESTAPP_BIN}" ] ; then + BAIL_OUT "No UST events binary detected" +fi + +plan_tests "${NUM_TESTS}" +print_test_banner "${TEST_DESC}" +bail_out_if_no_babeltrace + +# shellcheck disable=SC2119 +start_lttng_sessiond + +"${TESTAPP_BIN}" -i "${NR_ITER}" -w "${NR_USEC_WAIT}" & + TESTAPP_PID="${!}" + +create_lttng_session_ok "${SESSION_NAME}" "${OUTPUT_DIR}" +enable_ust_lttng_channel_ok "${SESSION_NAME}" "${CHANNEL_NAME}" +start_lttng_tracing_ok "${SESSION_NAME}" +enable_ust_lttng_event_loglevel "${SESSION_NAME}" "${EVENT_NAME}" TRACE_DEBUG_LINE "${CHANNEL_NAME}" +enable_ust_lttng_event_loglevel_only "${SESSION_NAME}" "${EVENT_NAME}" TRACE_DEBUG_LINE "${CHANNEL_NAME}" + +sleep 1 + +stop_lttng_tracing_ok "${SESSION_NAME}" +destroy_lttng_session_ok "${SESSION_NAME}" + +# shellcheck disable=SC2119 +stop_lttng_sessiond + +kill "${TESTAPP_PID}" +rm -rf "${OUTPUT_DIR}" diff --git a/tests/utils/utils.sh b/tests/utils/utils.sh index 949ed1311..3c6455e2c 100644 --- a/tests/utils/utils.sh +++ b/tests/utils/utils.sh @@ -1485,8 +1485,13 @@ function enable_ust_lttng_event_loglevel() local sess_name="$1" local event_name="$2" local loglevel="$3" + local channel_name="$4" + local chan=() + if [ -n "${channel_name}" ] ; then + chan=('-c' "${channel_name}") + fi - $TESTDIR/../src/bin/lttng/$LTTNG_BIN enable-event "$event_name" -s $sess_name -u --loglevel $loglevel 1> $OUTPUT_DEST 2> $ERROR_OUTPUT_DEST + $TESTDIR/../src/bin/lttng/$LTTNG_BIN enable-event "${chan[@]}" "$event_name" -s $sess_name -u --loglevel $loglevel 1> $OUTPUT_DEST 2> $ERROR_OUTPUT_DEST ok $? "Enable event $event_name with loglevel $loglevel" } @@ -1495,8 +1500,13 @@ function enable_ust_lttng_event_loglevel_only() local sess_name="$1" local event_name="$2" local loglevel="$3" + local channel_name="$4" + local chan=() + if [ -n "${channel_name}" ] ; then + chan=('-c' "${channel_name}") + fi - $TESTDIR/../src/bin/lttng/$LTTNG_BIN enable-event "$event_name" -s $sess_name -u --loglevel-only $loglevel 1> $OUTPUT_DEST 2> $ERROR_OUTPUT_DEST + $TESTDIR/../src/bin/lttng/$LTTNG_BIN enable-event "${chan[@]}" "$event_name" -s $sess_name -u --loglevel-only $loglevel 1> $OUTPUT_DEST 2> $ERROR_OUTPUT_DEST ok $? "Enable event $event_name with loglevel-only $loglevel" } -- 2.34.1