From 6afa580fbfd08a881e81ed1db788fa9fa6e01162 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 --- src/bin/lttng-sessiond/cmd.cpp | 8 --- src/common/event.cpp | 3 +- tests/regression/Makefile.am | 3 +- tests/regression/tools/client/Makefile.am | 6 +- ...est_bug1373_events_differ_only_by_loglevel | 60 +++++++++++++++++++ tests/utils/utils.sh | 14 ++++- 6 files changed, 79 insertions(+), 15 deletions(-) create mode 100755 tests/regression/tools/client/test_bug1373_events_differ_only_by_loglevel diff --git a/src/bin/lttng-sessiond/cmd.cpp b/src/bin/lttng-sessiond/cmd.cpp index 60ae7fe6a..c1588bc3a 100644 --- a/src/bin/lttng-sessiond/cmd.cpp +++ b/src/bin/lttng-sessiond/cmd.cpp @@ -2095,14 +2095,6 @@ static int _cmd_enable_event(struct ltt_session *session, } } - /* Normalize loglevel value to simplify comparisons. */ - if (event->loglevel_type == LTTNG_EVENT_LOGLEVEL_ALL) { - /* Ignore the user-specified value; it has no meaning. */ - event->loglevel = -1; - } - - DBG("Enable event command for event \'%s\'", event->name); - lttng::urcu::read_lock_guard read_lock; switch (domain->type) { diff --git a/src/common/event.cpp b/src/common/event.cpp index d989bfc7c..a6d48eaf7 100644 --- a/src/common/event.cpp +++ b/src/common/event.cpp @@ -367,8 +367,7 @@ ssize_t lttng_event_create_from_payload(struct lttng_payload_view *view, local_event->type = (enum lttng_event_type) event_comm->event_type; local_event->loglevel_type = (enum lttng_loglevel_type) event_comm->loglevel_type; - local_event->loglevel = - local_event->loglevel_type == LTTNG_EVENT_LOGLEVEL_ALL ? -1 : event_comm->loglevel; + local_event->loglevel = event_comm->loglevel; local_event->enabled = !!event_comm->enabled; local_event->pid = event_comm->pid; local_event->flags = (enum lttng_event_flag) event_comm->flags; diff --git a/tests/regression/Makefile.am b/tests/regression/Makefile.am index fc7dfc17e..ccceefb9a 100644 --- a/tests/regression/Makefile.am +++ b/tests/regression/Makefile.am @@ -66,7 +66,8 @@ TESTS = tools/base-path/test_ust \ tools/trigger/hidden/test_hidden_trigger \ tools/context/test_ust.py \ tools/client/test_session_commands.py \ - tools/client/test_event_rule_listing.py + tools/client/test_event_rule_listing.py \ + tools/client/test_bug1373_events_differ_only_by_loglevel # Only build kernel tests on Linux. if IS_LINUX diff --git a/tests/regression/tools/client/Makefile.am b/tests/regression/tools/client/Makefile.am index 4cc740ec0..5a85480fd 100644 --- a/tests/regression/tools/client/Makefile.am +++ b/tests/regression/tools/client/Makefile.am @@ -1,7 +1,9 @@ # SPDX-License-Identifier: GPL-2.0-only -noinst_SCRIPTS = test_session_commands.py test_event_rule_listing.py -EXTRA_DIST = test_session_commands.py test_event_rule_listing.py +noinst_SCRIPTS = test_session_commands.py test_event_rule_listing.py \ + test_bug1373_events_differ_only_by_loglevel +EXTRA_DIST = test_session_commands.py test_event_rule_listing.py \ + test_bug1373_events_differ_only_by_loglevel all-local: @if [ x"$(srcdir)" != x"$(builddir)" ]; then \ 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 3e1a81ce5..4fa31952c 100644 --- a/tests/utils/utils.sh +++ b/tests/utils/utils.sh @@ -1514,9 +1514,14 @@ 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 _run_lttng_cmd "$OUTPUT_DEST" "$ERROR_OUTPUT_DEST" \ - enable-event "$event_name" -s $sess_name -u --loglevel $loglevel + enable-event "${chan[@]}" "$event_name" -s "${sess_name}" -u --loglevel="${loglevel}" ok $? "Enable event $event_name with loglevel $loglevel" } @@ -1525,9 +1530,14 @@ 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 _run_lttng_cmd "$OUTPUT_DEST" "$ERROR_OUTPUT_DEST" \ - enable-event "$event_name" -s $sess_name -u --loglevel-only $loglevel + enable-event "${chan[@]}" "$event_name" -s "${sess_name}" -u --loglevel-only "${loglevel}" ok $? "Enable event $event_name with loglevel-only $loglevel" } -- 2.34.1