[lttng-tools.git] / tests / regression / ust / java-log4j / test_java_log4j

#!/bin/bash
#
# Copyright (C) 2014 David Goulet <dgoulet@efficios.com>
#
# SPDX-License-Identifier: GPL-2.0-only

TEST_DESC="Java LOG4J support"

CURDIR=$(dirname "$0")/
TESTDIR=$CURDIR/../../..

NR_ITER=6
NR_MSEC_WAIT=100

TESTAPP_NAME="JTestLTTngLog4j"
TESTAPP_PATH="$CURDIR/$TESTAPP_NAME"

SESSION_NAME="log4j"
EVENT_NAME="log4j-event"
EVENT_NAME2="log4j-event-2"

JAVA_CP="$CURDIR:$CLASSPATH"

NUM_TESTS=196

# shellcheck source=../../../utils/utils.sh
source "$TESTDIR/utils/utils.sh"

function run_app
{
	local debug_tp=$1
	local fire_second_tp=$2

	if [ "$debug_tp" = "" ]; then
		debug_tp=0
	fi

	if [ "$fire_second_tp" = "" ]; then
		fire_second_tp=0
	fi

	# FIXME: test app should have synchro.
	diag "java -cp $JAVA_CP -Djava.library.path=\"$LD_LIBRARY_PATH:/usr/local/lib:/usr/lib\" $TESTAPP_NAME $NR_ITER $NR_MSEC_WAIT $debug_tp $fire_second_tp"
	java -cp "$JAVA_CP" -Djava.library.path="$LD_LIBRARY_PATH:/usr/local/lib:/usr/lib" $TESTAPP_NAME $NR_ITER $NR_MSEC_WAIT "$debug_tp" "$fire_second_tp" >"$OUTPUT_DEST" 2>"$ERROR_OUTPUT_DEST"
}

function run_app_background
{
	run_app "${@}" &
}


# MUST set TESTDIR before calling those functions

function test_log4j_before_start ()
{
	local file_sync_after_first
	local file_sync_before_last

	file_sync_after_first=$(mktemp --tmpdir -u "tmp.${FUNCNAME[0]}_sync_after_first.XXXXXX")
	file_sync_before_last=$(mktemp --tmpdir -u "tmp.${FUNCNAME[0]}_sync_before_last.XXXXXX")

	diag "Test LOG4J application BEFORE tracing starts"
	create_lttng_session_ok $SESSION_NAME "$TRACE_PATH"
	enable_log4j_lttng_event $SESSION_NAME $EVENT_NAME

	# Run 5 times with a 1 second delay
	run_app_background

	start_lttng_tracing_ok $SESSION_NAME

	touch "${file_sync_before_last}"

	# Wait for the applications started in background
	wait

	stop_lttng_tracing_ok $SESSION_NAME
	destroy_lttng_session_ok $SESSION_NAME

	rm -f "${file_sync_after_first}"
	rm -f "${file_sync_before_last}"

	# Validate test. Expecting all events.
	trace_match_only $EVENT_NAME $NR_ITER "$TRACE_PATH"
}

function test_log4j_after_start ()
{
	diag "Test LOG4J application AFTER tracing starts"

	create_lttng_session_ok $SESSION_NAME "$TRACE_PATH"
	enable_log4j_lttng_event $SESSION_NAME $EVENT_NAME
	start_lttng_tracing_ok $SESSION_NAME

	# Run 5 times with a 1 second delay
	run_app

	stop_lttng_tracing_ok $SESSION_NAME
	destroy_lttng_session_ok $SESSION_NAME

	# Validate test. Expecting all events.
	trace_match_only $EVENT_NAME $NR_ITER "$TRACE_PATH"
}

function test_log4j_loglevel ()
{
	diag "Test LOG4J application with loglevel"

	create_lttng_session_ok $SESSION_NAME "$TRACE_PATH"
	enable_log4j_lttng_event_loglevel $SESSION_NAME $EVENT_NAME "LOG4J_INFO"
	start_lttng_tracing_ok $SESSION_NAME

	# Run 5 times with a 1 second delay
	run_app

	stop_lttng_tracing_ok $SESSION_NAME
	destroy_lttng_session_ok $SESSION_NAME

	# Validate test. Expecting all events.
	trace_match_only $EVENT_NAME $NR_ITER "$TRACE_PATH"

	diag "Test LOG4J applications with lower loglevel"

	create_lttng_session_ok $SESSION_NAME "$TRACE_PATH"
	enable_log4j_lttng_event_loglevel $SESSION_NAME $EVENT_NAME "LOG4J_FATAL"
	start_lttng_tracing_ok $SESSION_NAME

	# Run 5 times with a 1 second delay
	run_app

	stop_lttng_tracing_ok $SESSION_NAME
	destroy_lttng_session_ok $SESSION_NAME

	# Validate test. Expecting 0 events.
	trace_match_only $EVENT_NAME 0 "$TRACE_PATH"

	diag "Test LOG4J applications with higher loglevel"

	create_lttng_session_ok $SESSION_NAME "$TRACE_PATH"
	enable_log4j_lttng_event_loglevel $SESSION_NAME $EVENT_NAME "LOG4J_TRACE"
	start_lttng_tracing_ok $SESSION_NAME

	# Run 5 times with a 1 second delay
	run_app

	stop_lttng_tracing_ok $SESSION_NAME
	destroy_lttng_session_ok $SESSION_NAME

	# Validate test. Expecting all events.
	trace_match_only $EVENT_NAME $NR_ITER "$TRACE_PATH"
}

function test_log4j_loglevel_multiple ()
{
	diag "Test LOG4J application with multiple loglevel"

	create_lttng_session_ok $SESSION_NAME "$TRACE_PATH"
	enable_log4j_lttng_event_loglevel $SESSION_NAME $EVENT_NAME "LOG4J_INFO"
	enable_log4j_lttng_event_loglevel $SESSION_NAME $EVENT_NAME "LOG4J_DEBUG"
	start_lttng_tracing_ok $SESSION_NAME

	# Run 5 times with a 1 second delay and fire two TP.
	run_app 1

	stop_lttng_tracing_ok $SESSION_NAME
	destroy_lttng_session_ok $SESSION_NAME

	# Validate test. Expecting all events times two.
	trace_match_only $EVENT_NAME $((NR_ITER * 2)) "$TRACE_PATH"

	create_lttng_session_ok $SESSION_NAME "$TRACE_PATH"
	enable_log4j_lttng_event_loglevel $SESSION_NAME '*' "LOG4J_INFO"
	enable_log4j_lttng_event_loglevel $SESSION_NAME '*' "LOG4J_DEBUG"
	start_lttng_tracing_ok $SESSION_NAME

	# Run 5 times with a 1 second delay and fire two TP.
	run_app 1

	stop_lttng_tracing_ok $SESSION_NAME
	destroy_lttng_session_ok $SESSION_NAME

	# Validate test. Expecting all events times two.
	trace_match_only $EVENT_NAME $((NR_ITER * 2)) "$TRACE_PATH"
}

function test_log4j_multi_session_loglevel()
{
	diag "Test LOG4J with multiple session"

	create_lttng_session_ok $SESSION_NAME-1 "$TRACE_PATH"/$SESSION_NAME-1
	enable_log4j_lttng_event_loglevel_only $SESSION_NAME-1 '*' "LOG4J_INFO"
	start_lttng_tracing_ok $SESSION_NAME-1

	create_lttng_session_ok $SESSION_NAME-2 "$TRACE_PATH"/$SESSION_NAME-2
	enable_log4j_lttng_event_loglevel_only $SESSION_NAME-2 '*' "LOG4J_DEBUG"
	start_lttng_tracing_ok $SESSION_NAME-2

	# Run 5 times with a 1 second delay and fire second TP.
	run_app 1 1

	stop_lttng_tracing_ok $SESSION_NAME-1
	stop_lttng_tracing_ok $SESSION_NAME-2
	destroy_lttng_session_ok $SESSION_NAME-1
	destroy_lttng_session_ok $SESSION_NAME-2

	# Expecting 6 events being the main event plus the second tp.
	trace_match_only $EVENT_NAME $((NR_ITER + 1)) "$TRACE_PATH"/$SESSION_NAME-1

	# Expectin 5 events being the debug TP.
	trace_match_only $EVENT_NAME $NR_ITER "$TRACE_PATH"/$SESSION_NAME-2
}

function test_log4j_multi_session_disable()
{
	diag "Test LOG4J with multiple session with disabled event"

	create_lttng_session_ok $SESSION_NAME-1 "$TRACE_PATH"/$SESSION_NAME-1
	enable_log4j_lttng_event $SESSION_NAME-1 $EVENT_NAME
	enable_log4j_lttng_event $SESSION_NAME-1 $EVENT_NAME2
	disable_log4j_lttng_event $SESSION_NAME-1 $EVENT_NAME
	start_lttng_tracing_ok $SESSION_NAME-1

	create_lttng_session_ok $SESSION_NAME-2 "$TRACE_PATH"/$SESSION_NAME-2
	enable_log4j_lttng_event $SESSION_NAME-2 $EVENT_NAME2
	start_lttng_tracing_ok $SESSION_NAME-2

	# Run 5 times with a 1 second delay and fire second TP.
	run_app 0 1

	stop_lttng_tracing_ok $SESSION_NAME-1
	stop_lttng_tracing_ok $SESSION_NAME-2
	destroy_lttng_session_ok $SESSION_NAME-1
	destroy_lttng_session_ok $SESSION_NAME-2

	# Validate test. Expecting one event of the second TP.
	trace_match_only $EVENT_NAME2 1 "$TRACE_PATH"/$SESSION_NAME-1

	# Validate test. Expecting one event of the second TP.
	trace_match_only $EVENT_NAME2 1 "$TRACE_PATH"/$SESSION_NAME-2
}

function test_log4j_multi_session_disable_wildcard()
{
	diag "Test LOG4J with multiple session with disabled wildcard event"

	create_lttng_session_ok $SESSION_NAME-1 "$TRACE_PATH"/$SESSION_NAME-1
	enable_log4j_lttng_event $SESSION_NAME-1 '*'

	create_lttng_session_ok $SESSION_NAME-2 "$TRACE_PATH"/$SESSION_NAME-2
	enable_log4j_lttng_event $SESSION_NAME-2 '*'

	disable_log4j_lttng_event $SESSION_NAME-1 '*'

	start_lttng_tracing_ok $SESSION_NAME-1
	start_lttng_tracing_ok $SESSION_NAME-2

	run_app

	stop_lttng_tracing_ok $SESSION_NAME-1
	stop_lttng_tracing_ok $SESSION_NAME-2
	destroy_lttng_session_ok $SESSION_NAME-1
	destroy_lttng_session_ok $SESSION_NAME-2

	# Validate test. Expecting NO event of the first TP.
	trace_match_only $EVENT_NAME 0 "$TRACE_PATH"/$SESSION_NAME-1

	# Validate test. Expecting all events of the first TP.
	trace_match_only $EVENT_NAME $NR_ITER "$TRACE_PATH"/$SESSION_NAME-2
}

function test_log4j_multi_session_disable_wildcard_begin()
{
	ev_name='*-event'
	diag "Test LOG4J with multiple session with disabled wildcard (at the beginning) event"

	create_lttng_session_ok $SESSION_NAME-1 "$TRACE_PATH"/$SESSION_NAME-1
	enable_log4j_lttng_event $SESSION_NAME-1 "$ev_name"

	create_lttng_session_ok $SESSION_NAME-2 "$TRACE_PATH"/$SESSION_NAME-2
	enable_log4j_lttng_event $SESSION_NAME-2 "$ev_name"

	disable_log4j_lttng_event $SESSION_NAME-1 "$ev_name"

	start_lttng_tracing_ok $SESSION_NAME-1
	start_lttng_tracing_ok $SESSION_NAME-2

	run_app 0 1

	stop_lttng_tracing_ok $SESSION_NAME-1
	stop_lttng_tracing_ok $SESSION_NAME-2
	destroy_lttng_session_ok $SESSION_NAME-1
	destroy_lttng_session_ok $SESSION_NAME-2

	# Validate test. Expecting NO event of the first TP.
	trace_match_only $EVENT_NAME 0 "$TRACE_PATH"/$SESSION_NAME-1

	# Validate test. Expecting all events of the first TP.
	trace_match_only $EVENT_NAME $NR_ITER "$TRACE_PATH"/$SESSION_NAME-2
}

function test_log4j_multi_session_disable_wildcard_middle()
{
	ev_name='log*nt'
	diag "Test LOG4J with multiple session with disabled wildcard (at the middle) event"

	create_lttng_session_ok $SESSION_NAME-1 "$TRACE_PATH"/$SESSION_NAME-1
	enable_log4j_lttng_event $SESSION_NAME-1 "$ev_name"

	create_lttng_session_ok $SESSION_NAME-2 "$TRACE_PATH"/$SESSION_NAME-2
	enable_log4j_lttng_event $SESSION_NAME-2 "$ev_name"

	disable_log4j_lttng_event $SESSION_NAME-1 "$ev_name"

	start_lttng_tracing_ok $SESSION_NAME-1
	start_lttng_tracing_ok $SESSION_NAME-2

	run_app 0 1

	stop_lttng_tracing_ok $SESSION_NAME-1
	stop_lttng_tracing_ok $SESSION_NAME-2
	destroy_lttng_session_ok $SESSION_NAME-1
	destroy_lttng_session_ok $SESSION_NAME-2

	# Validate test. Expecting NO event of the first TP.
	trace_match_only $EVENT_NAME 0 "$TRACE_PATH"/$SESSION_NAME-1

	# Validate test. Expecting all events of the first TP.
	trace_match_only $EVENT_NAME $NR_ITER "$TRACE_PATH"/$SESSION_NAME-2
}

function test_log4j_multi_session_disable_wildcard_end()
{
	ev_name='log4j-ev*'
	diag "Test LOG4J with multiple session with disabled wildcard (at the end) event"

	create_lttng_session_ok $SESSION_NAME-1 "$TRACE_PATH"/$SESSION_NAME-1
	enable_log4j_lttng_event $SESSION_NAME-1 "$ev_name"

	create_lttng_session_ok $SESSION_NAME-2 "$TRACE_PATH"/$SESSION_NAME-2
	enable_log4j_lttng_event $SESSION_NAME-2 "$ev_name"

	disable_log4j_lttng_event $SESSION_NAME-1 "$ev_name"

	start_lttng_tracing_ok $SESSION_NAME-1
	start_lttng_tracing_ok $SESSION_NAME-2

	run_app 0 1

	stop_lttng_tracing_ok $SESSION_NAME-1
	stop_lttng_tracing_ok $SESSION_NAME-2
	destroy_lttng_session_ok $SESSION_NAME-1
	destroy_lttng_session_ok $SESSION_NAME-2

	# Validate test. Expecting NO event of the first TP.
	trace_match_only $EVENT_NAME 0 "$TRACE_PATH"/$SESSION_NAME-1

	# Validate test. Expecting all events of the first TP.
	trace_matches $EVENT_NAME $(( NR_ITER + 1 )) "$TRACE_PATH"/$SESSION_NAME-2

	trace_matches $EVENT_NAME2 1 "$TRACE_PATH"/$SESSION_NAME-2
}

function test_log4j_disable_all()
{
	diag "Test LOG4J with multiple session with disabled all event"

	create_lttng_session_ok $SESSION_NAME "$TRACE_PATH"/$SESSION_NAME
	enable_log4j_lttng_event $SESSION_NAME '*'
	enable_log4j_lttng_event $SESSION_NAME $EVENT_NAME
	enable_log4j_lttng_event $SESSION_NAME $EVENT_NAME2

	disable_log4j_lttng_event $SESSION_NAME -a

	start_lttng_tracing_ok $SESSION_NAME

	run_app 0 1

	stop_lttng_tracing_ok $SESSION_NAME
	destroy_lttng_session_ok $SESSION_NAME

	# Validate test. Expecting NO event of the first TP and second TP.
	trace_match_only $EVENT_NAME 0 "$TRACE_PATH"/$SESSION_NAME
	trace_match_only $EVENT_NAME2 0 "$TRACE_PATH"/$SESSION_NAME
}

function test_log4j_multi_session()
{
	diag "Test LOG4J with multiple session"

	create_lttng_session_ok $SESSION_NAME-1 "$TRACE_PATH"/$SESSION_NAME-1
	enable_log4j_lttng_event $SESSION_NAME-1 $EVENT_NAME
	start_lttng_tracing_ok $SESSION_NAME-1

	create_lttng_session_ok $SESSION_NAME-2 "$TRACE_PATH"/$SESSION_NAME-2
	enable_log4j_lttng_event $SESSION_NAME-2 $EVENT_NAME2
	start_lttng_tracing_ok $SESSION_NAME-2

	# Run 5 times with a 1 second delay and fire second TP.
	run_app 0 1

	stop_lttng_tracing_ok $SESSION_NAME-1
	stop_lttng_tracing_ok $SESSION_NAME-2
	destroy_lttng_session_ok $SESSION_NAME-1
	destroy_lttng_session_ok $SESSION_NAME-2

	# Validate test. Expecting all events of first TP
	trace_match_only $EVENT_NAME $NR_ITER "$TRACE_PATH"/$SESSION_NAME-1

	# Validate test. Expecting one event of the second TP.
	trace_match_only $EVENT_NAME2 1 "$TRACE_PATH"/$SESSION_NAME-2
}

function test_log4j_destroy_session()
{
	diag "Test LOG4J two session with destroy"

	create_lttng_session_ok $SESSION_NAME "$TRACE_PATH"/first-sess
	enable_log4j_lttng_event $SESSION_NAME $EVENT_NAME
	start_lttng_tracing_ok $SESSION_NAME

	# Run 5 times with a 1 second delay
	run_app_background 0 1
	# Wait for the applications started in background
	wait

	stop_lttng_tracing_ok $SESSION_NAME
	destroy_lttng_session_ok $SESSION_NAME

	# Validate test. Expecting at least one event num 1
	validate_trace $EVENT_NAME "$TRACE_PATH"/first-sess

	create_lttng_session_ok $SESSION_NAME "$TRACE_PATH"/second-sess
	enable_log4j_lttng_event $SESSION_NAME $EVENT_NAME2
	start_lttng_tracing_ok $SESSION_NAME

	# Run 5 times with a 1 second delay
	run_app_background 0 1
	# Wait for the applications started in background
	wait

	stop_lttng_tracing_ok $SESSION_NAME
	destroy_lttng_session_ok $SESSION_NAME

	# Validate test. Expecting only one event num 2
	trace_match_only $EVENT_NAME2 1 "$TRACE_PATH"/second-sess
}

function test_log4j_filtering()
{
	diag "Test LOG4J filtering"

	create_lttng_session_ok $SESSION_NAME "$TRACE_PATH"/$SESSION_NAME
	# Enable all event with a filter.
	enable_log4j_lttng_event_filter $SESSION_NAME '*' 'msg == "LOG4J second logger fired"'
	start_lttng_tracing_ok $SESSION_NAME

	# Run 5 times with a 1 second delay and fire second TP.
	run_app 0 1

	stop_lttng_tracing_ok $SESSION_NAME
	destroy_lttng_session_ok $SESSION_NAME

	# Validate test. Expecting one event of the second TP only.
	trace_match_only $EVENT_NAME2 1 "$TRACE_PATH"/$SESSION_NAME

	create_lttng_session_ok $SESSION_NAME "$TRACE_PATH"/$SESSION_NAME
	# Enable first Logger but filter msg payload for the INFO one while
	# triggering the debug and second TP.
	enable_log4j_lttng_event_filter $SESSION_NAME $EVENT_NAME 'msg == "LOG4J tp fired!"'
	start_lttng_tracing_ok $SESSION_NAME

	# Run 5 times with a 1 second delay, fire debug and second TP.
	run_app 1 1

	stop_lttng_tracing_ok $SESSION_NAME
	destroy_lttng_session_ok $SESSION_NAME

	# Validate test. Expecting NR_ITER event of the main INFO tp.
	trace_match_only $EVENT_NAME $NR_ITER "$TRACE_PATH"/$SESSION_NAME
}

function test_log4j_disable()
{
	diag "Test LOG4J disable event"

	create_lttng_session_ok $SESSION_NAME "$TRACE_PATH"/$SESSION_NAME
	# Enable all event with a filter.
	enable_log4j_lttng_event $SESSION_NAME $EVENT_NAME
	enable_log4j_lttng_event $SESSION_NAME $EVENT_NAME2
	disable_log4j_lttng_event $SESSION_NAME $EVENT_NAME
	start_lttng_tracing_ok $SESSION_NAME

	# Run 5 times with a 1 second delay and fire second TP.
	run_app 0 1

	stop_lttng_tracing_ok $SESSION_NAME
	destroy_lttng_session_ok $SESSION_NAME

	# Validate test. Expecting one event of the second TP only.
	trace_match_only $EVENT_NAME2 1 "$TRACE_PATH"/$SESSION_NAME
}

function test_log4j_disable_enable()
{
	diag "Test LOG4J disable event followed by an enable"

	create_lttng_session_ok $SESSION_NAME "$TRACE_PATH"/$SESSION_NAME
	# Enable all event with a filter.
	enable_log4j_lttng_event $SESSION_NAME $EVENT_NAME
	disable_log4j_lttng_event $SESSION_NAME $EVENT_NAME
	enable_log4j_lttng_event $SESSION_NAME $EVENT_NAME
	start_lttng_tracing_ok $SESSION_NAME

	# Run 5 times with a 1 second delay and fire second TP.
	run_app 0 1

	stop_lttng_tracing_ok $SESSION_NAME
	destroy_lttng_session_ok $SESSION_NAME

	# Validate test. Expecting NR_ITER event of the main INFO tp.
	trace_match_only $EVENT_NAME $NR_ITER "$TRACE_PATH"/$SESSION_NAME
}

function test_log4j_filter_loglevel()
{
	local BOGUS_EVENT_NAME="not_a_real_event"
	local FILTER="int_loglevel > 700 || int_loglevel < 700"
	local ALL_EVENTS="."

	diag "Test LOG4J a filter with a loglevel"

	create_lttng_session_ok $SESSION_NAME "$TRACE_PATH"/$SESSION_NAME
	# Enable an event with a filter and the loglevel-only option.
	enable_log4j_lttng_event_filter_loglevel_only $SESSION_NAME $BOGUS_EVENT_NAME "$FILTER" LOG4J_INFO
	disable_log4j_lttng_event $SESSION_NAME $BOGUS_EVENT_NAME
	enable_log4j_lttng_event_filter_loglevel_only $SESSION_NAME $BOGUS_EVENT_NAME "$FILTER" LOG4J_INFO
	start_lttng_tracing_ok $SESSION_NAME

	# Run 5 times with a 1 second delay and fire second TP.
	run_app 0 1

	stop_lttng_tracing_ok $SESSION_NAME
	destroy_lttng_session_ok $SESSION_NAME

	# Validate test. Expecting no events.
	trace_match_only $ALL_EVENTS 0 "$TRACE_PATH"/$SESSION_NAME
}

plan_tests $NUM_TESTS

print_test_banner "$TEST_DESC"

bail_out_if_no_babeltrace

test -f "$TESTAPP_PATH.class"
ok $? "Testapp '$TESTAPP_NAME' present"

start_lttng_sessiond

tests=(
	test_log4j_multi_session_disable_wildcard
	test_log4j_multi_session_disable_wildcard_begin
	test_log4j_multi_session_disable_wildcard_middle
	test_log4j_multi_session_disable_wildcard_end
	test_log4j_multi_session_disable
	test_log4j_disable
	test_log4j_disable_enable
	test_log4j_disable_all
	test_log4j_filtering
	test_log4j_multi_session_loglevel
	test_log4j_destroy_session
	test_log4j_loglevel
	test_log4j_loglevel_multiple
	test_log4j_before_start
	test_log4j_after_start
	test_log4j_multi_session
	test_log4j_filter_loglevel
)

for fct_test in "${tests[@]}";
do
	TRACE_PATH=$(mktemp --tmpdir -d tmp.test_java_log4j_trace_path.XXXXXX)

	${fct_test}

	rm -rf "$TRACE_PATH"
done

stop_lttng_sessiond