[PATCH v8 27/35] selftests-dyndbg: test dyndbg-to-tracefs

[Jim Cromie <jim.cromie@gmail.com>]

Add a series of trace-tests: test_actual_trace() etc, to validate that
the dyndbg-to-tracefs feature (using +T flag) works as intended.  The
1st test uses the global tracebuf, the rest use/excercise private
tracebufs.

These tests are currently optional, via "TRACE" arg1, because the
feature code is in-the-lab.  But its an objective test, and pretty
user-interface oriented.

IOW this passes:
  :#> ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
but this fails:
  :#> ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh TRACE

So its won't break selftests success.

This allows the patch to be committed now w/o inducing selftest
failures, and the tests enabled later, with the promised code.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
Co-developed-by: Łukasz Bartosik <ukaszb@chromium.org>
Signed-off-by: Łukasz Bartosik <ukaszb@chromium.org>
---
 .../dynamic_debug/dyndbg_selftest.sh          | 435 ++++++++++++++++++
 1 file changed, 435 insertions(+)

diff --git a/tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh b/tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
index 54acee58cb4e..65f31418870f 100755
--- a/tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
+++ b/tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
@@ -308,6 +308,405 @@ function test_mod_submod {
     check_match_ct =p 14 -v
 }
 
+# tests below here are all actually using dyndbg->trace,
+# and verifying the writes
+
+function test_actual_trace {
+    echo -e "${GREEN}# TEST_ACTUAL_TRACE ${NC}"
+    ddcmd =_
+    echo > /sys/kernel/tracing/trace
+    echo 1 >/sys/kernel/tracing/tracing_on
+    echo 1 >/sys/kernel/tracing/events/dyndbg/enable
+    modprobe test_dynamic_debug dyndbg=class,D2_CORE,+T:0
+    search_trace "D2_CORE msg"
+    search_trace_name 0 1 "D2_CORE msg"
+    check_match_ct =T 1
+    tmark "trace-mark"
+    search_trace "trace-mark"
+    doprints
+    search_trace "D2_CORE msg"
+    ifrmmod test_dynamic_debug
+}
+
+function self_start {
+    echo \# open, modprobe +T:selftest
+    ddcmd open selftest
+    check_trace_instance_dir selftest 1
+    is_trace_instance_opened selftest
+    modprobe test_dynamic_debug dyndbg=+T:selftest.mf
+    check_match_ct =T:selftest.mf 5
+}
+
+function self_end_normal {
+    echo \# disable -T:selftest, rmmod, close
+    ddcmd module test_dynamic_debug -T:selftest # leave mf
+    check_match_ct =:selftest.mf 5 -v
+    ddcmd module test_dynamic_debug +:0
+    ddcmd close selftest
+    is_trace_instance_closed selftest
+    ifrmmod test_dynamic_debug
+}
+
+function self_end_disable_anon {
+    echo \# disable, close, rmmod
+    ddcmd module test_dynamic_debug -T
+    check_match_ct =:selftest.mf 5
+    ddcmd module test_dynamic_debug +:0
+    ddcmd close selftest
+    is_trace_instance_closed selftest
+    ifrmmod test_dynamic_debug
+}
+
+function self_end_disable_anon_mf {
+    echo \# disable, close, rmmod
+    ddcmd module test_dynamic_debug -Tf
+    check_match_ct =:selftest.m 5
+    ddcmd module test_dynamic_debug +:0
+    ddcmd close selftest
+    is_trace_instance_closed selftest
+    ifrmmod test_dynamic_debug
+}
+
+function self_end_nodisable {
+    echo \# SKIPPING: ddcmd module test_dynamic_debug -T:selftest
+    ddcmd close selftest fail # close fails because selftest is still being used
+    check_err_msg "Device or resource busy"
+    check_match_ct =T:selftest.mf 5
+    rmmod test_dynamic_debug
+    ddcmd close selftest # now selftest can be closed because rmmod removed
+                         # all callsites which were using it
+    is_trace_instance_closed selftest
+}
+
+function self_end_delete_directory {
+    del_trace_instance_dir selftest 0
+    check_err_msg "Device or resource busy"
+    ddcmd module test_dynamic_debug -mT:selftest
+    check_match_ct =:selftest.f 5
+    del_trace_instance_dir selftest 0
+    check_err_msg "Device or resource busy"
+    ddcmd module test_dynamic_debug +:0
+    ddcmd close selftest
+    check_trace_instance_dir selftest 1
+    is_trace_instance_closed selftest
+    del_trace_instance_dir selftest 1
+    check_trace_instance_dir selftest 0
+}
+
+function test_early_close () {
+    ddcmd open kparm_stream
+    ddcmd module usbcore +T:kparm_stream.mf
+    check_match_ct =T:usb_stream.mf 161
+    echo ":not-running # ddcmd module usbcore -T:kparm_stream.mf"
+    ddcmd close kparm_stream
+}
+
+function self_test_ {
+    echo "# SELFTEST $1"
+    self_start
+    self_end_$1
+}
+
+function cycle_tests_normal {
+    echo -e "${GREEN}# CYCLE_TESTS_NORMAL ${NC}"
+    self_test_ normal           # ok
+    self_test_ disable_anon     # ok
+    self_test_ normal           # ok
+    self_test_ disable_anon_mf  # ok
+}
+
+function cycle_not_best_practices {
+    echo -e "${GREEN}# CYCLE_TESTS_PROBLEMS ${NC}"
+    self_test_ nodisable
+    self_test_ normal
+    self_test_ delete_directory
+}
+
+# proper life cycle - open, enable:named, disable:named, close
+function test_private_trace_simple_proper {
+    echo -e "${GREEN}# TEST_PRIVATE_TRACE_1 ${NC}"
+    # ddcmd close kparm_stream
+    ddcmd open kparm_stream
+    ddcmd module params +T:kparm_stream.mf
+    check_match_ct =T:kparm_stream.mf 4
+    ddcmd module params -T:kparm_stream.mf
+    check_match_ct =T:kparm_stream.mf 0
+    is_trace_instance_opened kparm_stream
+    ddcmd module params +:0
+    ddcmd close kparm_stream
+    is_trace_instance_closed kparm_stream
+    ddcmd =_
+    check_trace_instance_dir kparm_stream 1
+    is_trace_instance_closed kparm_stream
+    del_trace_instance_dir kparm_stream 1
+    check_trace_instance_dir kparm_stream 0
+}
+
+function test_private_trace_2 {
+    echo -e "${GREEN}# TEST_PRIVATE_TRACE_2 ${NC}"
+    ddcmd =_
+    echo > /sys/kernel/tracing/trace
+    echo 1 >/sys/kernel/tracing/tracing_on
+    echo 1 >/sys/kernel/tracing/events/dyndbg/enable
+    ddcmd open foo
+    is_trace_instance_opened foo
+    check_trace_instance_dir foo 1
+
+    modprobe test_dynamic_debug
+    ddcmd class,D2_CORE,+T:foo.l,%class,D2_KMS,+fT:foo.ml
+    check_match_ct =T:foo.l 1
+    check_match_ct =T:foo.mfl 1
+
+    # purpose ?
+    echo 1 >/sys/kernel/tracing/tracing_on
+    echo 1 >/sys/kernel/tracing/events/dyndbg/enable
+
+    tmark test_private_trace about to do_prints
+    search_trace "test_private_trace about to do_prints"
+    search_trace_name "0" 1 "test_private_trace about to do_prints"
+
+    doprints
+    ddcmd class,D2_CORE,-T:foo
+    ddcmd close foo fail
+    check_err_msg "Device or resource busy"
+    ddcmd class,D2_KMS,-T:foo
+    ddcmd close foo
+    check_trace_instance_dir foo 1
+    is_trace_instance_closed foo
+    ddcmd close bar fail
+    check_err_msg "No such file or directory"
+    ifrmmod test_dynamic_debug
+    search_trace_name foo 2 "D2_CORE msg"
+    search_trace_name foo 1 "D2_KMS msg"
+    del_trace_instance_dir foo 1
+    check_trace_instance_dir foo 0
+}
+
+function test_private_trace_3 {
+    echo -e "${GREEN}# TEST_PRIVATE_TRACE_3 ${NC}"
+    ddcmd =_
+    echo > /sys/kernel/tracing/trace
+    echo 1 >/sys/kernel/tracing/tracing_on
+    echo 1 >/sys/kernel/tracing/events/dyndbg/enable
+    ddcmd open foo \; open bar
+    is_trace_instance_opened foo
+    is_trace_instance_opened bar
+    modprobe test_dynamic_debug
+    ddcmd class,D2_CORE,+T:foo
+    ddcmd class,D2_KMS,+T:foo
+    ddcmd class D2_CORE +T:foo \; class D2_KMS +T:foo
+    ddcmd "class,D2_CORE,+T:foo;,class,D2_KMS,+T:foo"
+    ddcmd class,D2_CORE,+T:foo\;class,D2_KMS,+T:foo
+    check_match_ct =T 2 -v
+    check_match_ct =Tl 0
+    check_match_ct =Tmf 0
+    echo 1 >/sys/kernel/tracing/tracing_on
+    echo 1 >/sys/kernel/tracing/events/dyndbg/enable
+    tmark test_private_trace_2 about to do_prints
+    doprints
+    rmmod test_dynamic_debug
+    ddcmd "close bar;close foo"
+    is_trace_instance_closed bar
+    is_trace_instance_closed foo
+    search_trace_name foo 2 "D2_CORE msg"
+    search_trace_name foo 1 "D2_KMS msg"
+    del_trace_instance_dir foo 1
+    check_trace_instance_dir foo 0
+    search_trace "test_private_trace_2 about to do_prints"
+    del_trace_instance_dir bar 1
+    check_trace_instance_dir bar 0
+}
+
+function test_private_trace_4 {
+    echo -e "${GREEN}# TEST_PRIVATE_TRACE_4 ${NC}"
+    ddcmd =_
+    echo > /sys/kernel/tracing/trace
+    echo 1 >/sys/kernel/tracing/tracing_on
+    echo 1 >/sys/kernel/tracing/events/dyndbg/enable
+
+    ddcmd open foo
+    modprobe test_dynamic_debug dyndbg=class,D2_CORE,+T:foo%class,D2_KMS,+T:foo
+    check_match_ct =Tl 0
+    check_match_ct =Tmf 0
+    check_match_ct =T 2
+
+    # are these 2 doing anything ?
+    echo 1 >/sys/kernel/tracing/tracing_on
+    echo 1 >/sys/kernel/tracing/events/dyndbg/enable
+
+    tmark should be ready
+    search_trace_name "0" 0 "should be ready"	# in global trace
+
+    doprints
+    search_trace_name foo 2 "D2_CORE msg"	# in private buf
+    search_trace_name foo 1 "D2_KMS msg"
+
+    # premature delete
+    del_trace_instance_dir foo 0
+    check_trace_instance_dir foo 1	# doesn't delete
+    ifrmmod test_dynamic_debug
+
+    ddcmd "close foo"
+    is_trace_instance_closed foo
+    del_trace_instance_dir foo 1	# delete works now
+
+    check_trace_instance_dir foo 0
+    search_trace "should be ready"
+}
+
+# $1 - trace-buf-name (or "0")
+# $2 - reference-buffer
+function search_in_trace_for {
+    bufname=$1; shift;
+    ref=$2;
+    ref2=$(echo $ref | cut -c20-)
+    echo $ref2
+}
+
+function test_private_trace_mixed_class {
+    echo -e "${GREEN}# TEST_PRIVATE_TRACE_5 ${NC}"
+    ddcmd =_
+    ddcmd module,params,+T:unopened fail
+    check_err_msg "Invalid argument"
+    is_trace_instance_closed unopened
+    check_trace_instance_dir unopened 0
+
+    ddcmd open bupkus
+    is_trace_instance_opened bupkus
+    check_trace_instance_dir bupkus 1
+    modprobe test_dynamic_debug \
+	     dyndbg=class,D2_CORE,+T:bupkus.mf%class,D2_KMS,+T:bupkus.mf%class,V3,+T:bupkus.mf
+
+    # test various name misses
+    ddcmd "module params =T:bupkus1" fail	# miss on name
+    check_err_msg "Invalid argument"
+    ddcmd "module params =T:unopened" fail	# unopened
+    check_err_msg "Invalid argument"
+
+    ddcmd "module params =mlfT:bupkus."		# we allow dot at the end of flags
+    ddcmd "module params =T:bupkus."
+    ddcmd "module params =:bupkus."
+    ddcmd "module params =:0."
+
+    check_match_ct =T:bupkus.mf 3		# the 3 classes enabled above
+    # enable the 5 non-class'd pr_debug()s
+    ddcmd "module test_dynamic_debug =T:bupkus"
+    check_match_ct =T:bupkus 8 -r		# 8=5+3
+
+    doprints
+    ddcmd close,bupkus fail
+    check_err_msg "Device or resource busy"
+    ddcmd "module * -T:0"			# misses class'd ones
+    ddcmd close,bupkus fail
+
+    ddcmd class,D2_CORE,-T:0%class,D2_KMS,-T:0%class,V3,-T:0 # turn off class'd and set dest to 0
+    ddcmd close,bupkus
+    is_trace_instance_closed bupkus
+
+    # check results
+    eyeball_ref=<<EOD
+        modprobe-1173    [001] .....   7.781008: 0: test_dynamic_debug:do_cats: test_dd: D2_CORE msg
+        modprobe-1173    [001] .....   7.781010: 0: test_dynamic_debug:do_cats: test_dd: D2_KMS msg
+        modprobe-1173    [001] .....   7.781010: 0: test_dynamic_debug:do_levels: test_dd: V3 msg
+             cat-1214    [001] .....   7.905494: 0: test_dd: doing categories
+             cat-1214    [001] .....   7.905495: 0: test_dynamic_debug:do_cats: test_dd: D2_CORE msg
+             cat-1214    [001] .....   7.905496: 0: test_dynamic_debug:do_cats: test_dd: D2_KMS msg
+             cat-1214    [001] .....   7.905497: 0: test_dd: doing levels
+             cat-1214    [001] .....   7.905498: 0: test_dynamic_debug:do_levels: test_dd: V3 msg
+EOD
+
+    # validate the 3 enabled class'd sites, with mf prefix
+    search_trace_name bupkus 0 "test_dynamic_debug:do_cats: test_dd: D2_CORE msg"
+    search_trace_name bupkus 0 "test_dynamic_debug:do_cats: test_dd: D2_KMS msg"
+    search_trace_name bupkus 0 "test_dynamic_debug:do_levels: test_dd: V3 msg"
+
+    search_trace_name bupkus 0 "test_dd: doing levels"
+    search_trace_name bupkus 0 "test_dd: doing categories"
+
+    # reopen wo error
+    ddcmd open bupkus
+    is_trace_instance_opened bupkus
+    check_trace_instance_dir bupkus 1
+
+    ddcmd "module test_dynamic_debug =T:bupkus"	# rearm the 5 plain-old prdbgs
+    check_match_ct =T:bupkus 5
+
+    doprints # 2nd time
+    search_trace_name bupkus 0 "test_dd: doing categories"
+    search_trace_name bupkus 0 "test_dd: doing levels""
+    search_trace_name bupkus 2 "test_dd: doing categories"
+    search_trace_name bupkus 1 "test_dd: doing levels""
+
+    ddcmd close,bupkus fail
+    check_err_msg "Device or resource busy"
+    del_trace_instance_dir bupkus 0
+    check_err_msg "Device or resource busy"
+    check_trace_instance_dir bupkus 1
+    is_trace_instance_opened bupkus
+    check_trace_instance_dir bupkus 1
+
+    # drop last users, now delete works
+    ddcmd "module * -T:0"
+    ddcmd close,bupkus
+    is_trace_instance_closed bupkus
+    del_trace_instance_dir bupkus 1
+    check_trace_instance_dir bupkus 0
+    ifrmmod test_dynamic_debug
+}
+
+function test_private_trace_overlong_name {
+    echo -e "${GREEN}# TEST_PRIVATE_TRACE_overlong_name ${NC}"
+    ddcmd =_
+    name="A_bit_lengthy_trace_instance_name"
+    ddcmd open $name
+    is_trace_instance_opened $name
+    check_trace_instance_dir $name 1
+
+    ddcmd "file kernel/module/main.c +T:$name.mf "
+    check_match_ct =T:A_bit_lengthy_trace_....mf 14
+
+    ddcmd "module * -T"
+    check_match_ct =:A_bit_lengthy_trace_....mf 14
+    check_match_ct kernel/module/main.c 14 -r		# to be certain
+
+    ddcmd "module * -T:0"
+    ddcmd close,$name
+    is_trace_instance_closed $name
+    del_trace_instance_dir $name 1
+    check_trace_instance_dir $name 0
+}
+
+function test_private_trace_fill_trace_index {
+    echo -e "${GREEN}# TEST_PRIVATE_TRACE_fill_trace_index ${NC}"
+    ddcmd =_
+    name="trace_instance_"
+    for i in {1..63}
+    do
+        ddcmd open $name$i
+	is_trace_instance_opened $name$i
+        check_trace_instance_dir $name$i 1
+    done
+    # catch the 1-too-many err
+    ddcmd "open too_many" fail
+    check_err_msg "No space left on device"
+
+    ddcmd 'file kernel/module/main.c =T:trace_instance_63.m'
+    check_match_ct =T:trace_instance_63.m 14
+
+    for i in {1..62}
+    do
+        ddcmd close $name$i
+        is_trace_instance_closed $name$i
+        del_trace_instance_dir $name$i 1
+        check_trace_instance_dir $name$i 0
+    done
+    ddcmd "module * -T:0"
+    ddcmd close,trace_instance_63
+    is_trace_instance_closed trace_instance_63
+    del_trace_instance_dir trace_instance_63 1
+    check_trace_instance_dir trace_instance_63 0
+}
+
 tests_list=(
     basic_tests
     # these require test_dynamic_debug*.ko
@@ -315,9 +714,28 @@ tests_list=(
     test_percent_splitting
     test_mod_submod
 )
+trace_tests=(
+    # these tests write to tracebuf, and check its contents
+    test_actual_trace
+    cycle_tests_normal
+    cycle_not_best_practices
+    test_private_trace_1
+    test_private_trace_simple_proper
+    test_private_trace_2
+    test_private_trace_3
+    test_private_trace_4
+    test_private_trace_mixed_class
+    test_private_trace_mixed_class  # again, to test pre,post conditions
+
+    test_private_trace_overlong_name
+
+    # works, takes 30 sec
+    test_private_trace_fill_trace_index
+)
 
 # Run tests
 
+# rmmod modules to clear their possibly modified state
 ifrmmod test_dynamic_debug_submod
 ifrmmod test_dynamic_debug
 
@@ -326,5 +744,22 @@ do
     $test
     echo ""
 done
+
+if [[ "$1" = "TRACE" ]] ; then
+
+    # rmmod modules to clear their possibly modified state
+    ifrmmod test_dynamic_debug_submod
+    ifrmmod test_dynamic_debug
+
+    for test in "${trace_tests[@]}"
+    do
+	$test
+	echo ""
+    done
+fi
+
+# leave modules in place at end
+# so that evidence of mishap is present
+
 echo -en "${GREEN}# Done on: "
 date
-- 
2.44.0