Fix: sessiond: preserve jul/log4j domain loglevels
authorKienan Stewart <kstewart@efficios.com>
Wed, 28 Jun 2023 15:28:55 +0000 (11:28 -0400)
committerJérémie Galarneau <jeremie.galarneau@efficios.com>
Wed, 19 Jul 2023 17:43:48 +0000 (13:43 -0400)
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 <kstewart@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Iac653157190b61b44d5ff18ac968fef58330a106

src/bin/lttng-sessiond/cmd.cpp
src/common/event.cpp
tests/regression/Makefile.am
tests/regression/tools/client/Makefile.am
tests/regression/tools/client/test_bug1373_events_differ_only_by_loglevel [new file with mode: 0755]
tests/utils/utils.sh

index 60ae7fe6aa7632057962a1172fc2b571032bc075..c1588bc3a37dc3dc1dd9b0facf981a33707b4111 100644 (file)
@@ -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) {
index d989bfc7c979c1e71c6c81113eb7b1d6036272d9..a6d48eaf7f80e2001226aba7467394e34793183b 100644 (file)
@@ -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;
index fc7dfc17e725f27926a077598883b0cf16042d55..ccceefb9a9ccac284e99d058d54c1ca8ad994017 100644 (file)
@@ -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
index 4cc740ec071108f48acee302c8171526077bc773..5a85480fd9cabb5fedb9deaa532645a88dfc313e 100644 (file)
@@ -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 (executable)
index 0000000..1508583
--- /dev/null
@@ -0,0 +1,60 @@
+#!/bin/bash
+#
+# Copyright (C) 2023 Kienan Stewart <kstewart@efficios.com>
+#
+# 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}"
index 3e1a81ce5f03e3c7a8aa405b7e2ce29ead2abfb3..4fa31952cb6719a20567ae86152c3350c8377303 100644 (file)
@@ -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"
 }
 
This page took 0.033378 seconds and 4 git commands to generate.