Bug #117354 Test main.log_components failing with a result diff under Valgrind
Submitted: 31 Jan 14:08 Modified: 31 Jan 14:37
Reporter: Laurynas Biveinis (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Tests Severity:S7 (Test Cases)
Version:9.2.0 OS:Ubuntu (22.04.5)
Assigned to: CPU Architecture:x86

[31 Jan 14:08] Laurynas Biveinis 
Description:
Test main.log_components fails with a result diff under Valgrind:

./mtr main.log_components --valgrind
...
 33%] main.log_components                       [ fail ]
        Test ended at 2025-01-31 12:01:39

CURRENT_TEST: main.log_components
==333171== Memcheck, a memory error detector
==333171== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==333171== Using Valgrind-3.18.1 and LibVEX; rerun with -h for copyright info
==333171== Command: /home/laurynas/vilniusdb/mysql-9.2.0/_build-debug-valgrind/runtime_output_directory//mysqltest --defaults-file=/home/laurynas/vilniusdb/mysql-9.2.0/_build-debug-valgrind/mysql-test/var/my.cnf --silent --tmpdir=/tmp/mtr-ygLx --character-sets-dir=/home/laurynas/vilniusdb/mysql-9.2.0/share/charsets --logdir=/home/laurynas/vilniusdb/mysql-9.2.0/_build-debug-valgrind/mysql-test/var/log --database=test --plugin_dir=/home/laurynas/vilniusdb/mysql-9.2.0/_build-debug-valgrind/plugin_output_directory --timer-file=/home/laurynas/vilniusdb/mysql-9.2.0/_build-debug-valgrind/mysql-test/var/log/timer --test-file=/home/laurynas/vilniusdb/mysql-9.2.0/mysql-test/t/log_components.test --tail-lines=20 --result-file=/home/laurynas/vilniusdb/mysql-9.2.0/mysql-test/r/log_components.result
==333171== 
--- /home/laurynas/vilniusdb/mysql-9.2.0/mysql-test/r/log_components.result	2025-01-29 18:18:13.005623161 +0300
+++ /home/laurynas/vilniusdb/mysql-9.2.0/_build-debug-valgrind/mysql-test/var/log/log_components.reject	2025-01-31 15:01:28.483408150 +0300
@@ -125,92 +125,93 @@
 { "prio" : 3, "err_code" : 10000, "subsystem" : "Server", "source_file" : "sql_parse.cc", "function" : "dispatch_command", "msg" : "Parser saw: SET @@global.log_error_services=\"log_filter_internal log_sink_internal\"", "time" : "1970-01-01T00:00:00.000012Z", "ts" : 0, "thread" : 0, "err_symbol" : "ER_PARSER_TRACE", "SQL_state" : "XX999", "label" : "Note" }
 { "prio" : 3, "err_code" : 10000, "subsystem" : "Server", "source_file" : "sql_parse.cc", "function" : "dispatch_command", "msg" : "Parser saw: SHOW WARNINGS", "time" : "1970-01-01T00:00:00.000013Z", "ts" : 0, "thread" : 0, "err_symbol" : "ER_PARSER_TRACE", "SQL_state" : "XX999", "label" : "Note" }

... lots of output ...

How to repeat:
Server built with -DCMAKE_BUILD_TYPE=Debug -DWITH_DEBUG=ON -DMYSQL_MAINTAINER_MODE=ON -DWITH_SYSTEM_LIBS=ON -DWITH_NDBCLUSTER_STORAGE_ENGINE=OFF -DFORCE_COLORED_OUTPUT=ON -DCMAKE_CXX_FLAGS=-g -Wno-documentation -DCMAKE_CXX_FLAGS_DEBUG=-g -Wno-documentation -DCMAKE_CXX_FLAGS_RELEASE=-g -O2 -DNDEBUG -Wno-documentation -DWITH_VALGRIND=ON
[31 Jan 14:37] MySQL Verification Team 
Hello Laurynas,

Thank you for the report and feedback.

regards,
Umesh
[11 Feb 13:55] MySQL Verification Team 
--

~/src/mysql-9.2.0/Bug117358/mysql-test]$ ./mtr main.log_components --valgrind
Logging: ./mtr  main.log_components --valgrind
MySQL Version 9.2.0
Turning on valgrind for all executables
Running valgrind with options " --tool=memcheck --num-callers=16 --show-reachable=yes --suppressions=/home/umshastr/src/mysql-9.2.0/Bug117358/mysql-test/valgrind.supp "
Turning off --check-testcases to save time when valgrinding
Checking supported features
 - Binaries are debug compiled
Using 'all' suites
Collecting tests
Checking leftover processes
Removing old var directory
Creating var directory '/home/umshastr/src/mysql-9.2.0/Bug117358/mysql-test/var'
Installing system database
Using parallel: 1

==============================================================================
                  TEST NAME                       RESULT  TIME (ms) COMMENT
------------------------------------------------------------------------------
[ 33%] main.log_components                       [ fail ]
        Test ended at 2025-02-11 14:52:12

CURRENT_TEST: main.log_components
==83087== Memcheck, a memory error detector
==83087== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==83087== Using Valgrind-3.18.1 and LibVEX; rerun with -h for copyright info
==83087== Command: /home/umshastr/src/mysql-9.2.0/Bug117358/bin/mysqltest --defaults-file=/home/umshastr/src/mysql-9.2.0/Bug117358/mysql-test/var/my.cnf --silent --tmpdir=/home/umshastr/src/mysql-9.2.0/Bug117358/mysql-test/var/tmp --character-sets-dir=/home/umshastr/src/mysql-9.2.0/Bug117358/share/charsets --logdir=/home/umshastr/src/mysql-9.2.0/Bug117358/mysql-test/var/log --database=test --plugin_dir=/home/umshastr/src/mysql-9.2.0/Bug117358/lib/plugin --timer-file=/home/umshastr/src/mysql-9.2.0/Bug117358/mysql-test/var/log/timer --test-file=/home/umshastr/src/mysql-9.2.0/Bug117358/mysql-test/t/log_components.test --tail-lines=20 --result-file=/home/umshastr/src/mysql-9.2.0/Bug117358/mysql-test/r/log_components.result
==83087==
--- /home/umshastr/src/mysql-9.2.0/Bug117358/mysql-test/r/log_components.result	2024-12-15 23:00:33.000000000 +0300
+++ /home/umshastr/src/mysql-9.2.0/Bug117358/mysql-test/var/log/log_components.reject	2025-02-11 16:52:01.581567622 +0300
@@ -111,6 +111,7 @@
 ### error log file
 ###

+2025-02-11T13:51:57.646350Z 9 [Note] [MY-010000] [Server] Parser saw: SET @@session.debug="+d,parser_stmt_to_error_log"
 1970-01-01T00:00:00.000001Z 0 [Note] [MY-010000] [Server] Parser saw: SET @@session.debug="+d,log_error_normalize"
 1970-01-01T00:00:00.000002Z 0 [Note] [MY-010000] [Server] Parser saw: SELECT @@global.log_error_services
 1970-01-01T00:00:00.000003Z 0 [Note] [MY-010000] [Server] Parser saw: SELECT "*** SWITCHING ERROR LOG TO JSON ***"

mysqltest: Result content mismatch

The result from queries just before the failure was:
[log_type=1];[prio=3];[err_code=10000];[wl9651_val1=3];[wl9651_val2=4];[wl9651_val3a=1];[wl9651_val3b=2];[wl9651_val3c=0];[subsystem=log_sink_test];[component=log_sink_test];[msg=WL#9651 expected: r1-ELSE, r2-FAILURE, r3-FAILURE];[time=1970-01-01T00:00:00.000070Z];[ts=0];[thread=0];[err_symbol=ER_PARSER_TRACE];[SQL_state=XX999];[label=Note];
{ "log_type" : 1, "prio" : 3, "err_code" : 10000, "wl9651_val1" : 3, "wl9651_val2" : 4, "wl9651_val3a" : 1, "wl9651_val3b" : 2, "wl9651_val3c" : 0, "subsystem" : "log_sink_test", "component" : "log_sink_test", "msg" : "WL#9651 expected: r1-ELSE, r2-FAILURE, r3-FAILURE", "time" : "1970-01-01T00:00:00.000070Z", "ts" : 0, "thread" : 0, "err_symbol" : "ER_PARSER_TRACE", "SQL_state" : "XX999", "label" : "Note" }
[log_type=1];[prio=3];[err_code=10000];[wl9651_val1=-7];[wl9651_val2=1];[wl9651_val3a=1];[wl9651_val3c=3];[subsystem=log_sink_test];[component=log_sink_test];[msg=WL#9651 expected: r1-IF, r2-FAILURE, r3-FAILURE];[time=1970-01-01T00:00:00.000071Z];[ts=0];[thread=0];[err_symbol=ER_PARSER_TRACE];[SQL_state=XX999];[label=Note];
{ "log_type" : 1, "prio" : 3, "err_code" : 10000, "wl9651_val1" : -7, "wl9651_val2" : "1", "wl9651_val3a" : 1, "wl9651_val3c" : 3, "subsystem" : "log_sink_test", "component" : "log_sink_test", "msg" : "WL#9651 expected: r1-IF, r2-FAILURE, r3-FAILURE", "time" : "1970-01-01T00:00:00.000071Z", "ts" : 0, "thread" : 0, "err_symbol" : "ER_PARSER_TRACE", "SQL_state" : "XX999", "label" : "Note" }
[label=log_sink_test: broken item with class 3, type 131072];[err_code=10000];[prio=1];[time=1970-01-01T00:00:00.000072Z];[ts=0];[thread=0];[err_symbol=ER_PARSER_TRACE];[SQL_state=XX999];[subsystem=Server];[label=Error];
{ "label" : "log_sink_json: broken item with class 3, type 131072", "err_code" : 10000, "prio" : 1, "time" : "1970-01-01T00:00:00.000072Z", "ts" : 0, "thread" : 0, "err_symbol" : "ER_PARSER_TRACE", "SQL_state" : "XX999", "subsystem" : "Server", "label" : "Error" }
{ "prio" : 3, "err_code" : 10000, "subsystem" : "Server", "source_file" : "sql_parse.cc", "function" : "dispatch_command", "msg" : "Parser saw: SET @@global.log_error_services=\"log_filter_internal; log_sink_test; log_sink_json\"", "time" : "1970-01-01T00:00:00.000030Z", "ts" : 0, "thread" : 0, "err_symbol" : "ER_PARSER_TRACE", "SQL_state" : "XX999", "label" : "Note" }
{ "prio" : 3, "err_code" : 10000, "subsystem" : "Server", "source_file" : "sql_parse.cc", "function" : "dispatch_command", "msg" : "Parser saw: SELECT \"logging as traditional MySQL error log and as JSON\"", "time" : "1970-01-01T00:00:00.000073Z", "ts" : 0, "thread" : 0, "err_symbol" : "ER_PARSER_TRACE", "SQL_state" : "XX999", "label" : "Note" }
{ "prio" : 3, "err_code" : 10000, "subsystem" : "Server", "source_file" : "sql_parse.cc", "function" : "dispatch_command", "msg" : "Parser saw: SET @@global.log_error_filter_rules= DEFAULT", "time" : "1970-01-01T00:00:00.000074Z", "ts" : 0, "thread" : 0, "err_symbol" : "ER_PARSER_TRACE", "SQL_state" : "XX999", "label" : "Note" }
[prio=3];[err_code=10000];[subsystem=Server];[source_file=sql_parse.cc];[function=dispatch_command];[msg=Parser saw: FLUSH ERROR LOGS];[time=1970-01-01T00:00:00.000075Z];[ts=0];[thread=0];[err_symbol=ER_PARSER_TRACE];[SQL_state=XX999];[label=Note];
{ "prio" : 3, "err_code" : 10000, "subsystem" : "Server", "source_file" : "sql_parse.cc", "function" : "dispatch_command", "msg" : "Parser saw: FLUSH ERROR LOGS", "time" : "1970-01-01T00:00:00.000075Z", "ts" : 0, "thread" : 0, "err_symbol" : "ER_PARSER_TRACE", "SQL_state" : "XX999", "label" : "Note" }
[prio=3];[err_code=10000];[subsystem=Server];[source_file=sql_parse.cc];[function=dispatch_command];[msg=Parser saw: UNINSTALL COMPONENT "file://component_log_sink_test"];[time=1970-01-01T00:00:00.000076Z];[ts=0];[thread=0];[err_symbol=ER_PARSER_TRACE];[SQL_state=XX999];[label=Note];
{ "prio" : 3, "err_code" : 10000, "subsystem" : "Server", "source_file" : "sql_parse.cc", "function" : "dispatch_command", "msg" : "Parser saw: UNINSTALL COMPONENT \"file://component_log_sink_test\"", "time" : "1970-01-01T00:00:00.000076Z", "ts" : 0, "thread" : 0, "err_symbol" : "ER_PARSER_TRACE", "SQL_state" : "XX999", "label" : "Note" }
1970-01-01T00:00:00.000077Z 0 [Note] [MY-010000] [Server] Parser saw: SET @@global.log_error_services="log_filter_internal; log_sink_internal"
1970-01-01T00:00:00.000078Z 0 [Note] [MY-010000] [Server] Parser saw: UNINSTALL COMPONENT "file://component_log_sink_test"
1970-01-01T00:00:00.000079Z 0 [Note] [MY-010000] [Server] Parser saw: UNINSTALL COMPONENT "file://component_log_sink_json"

###
### done
###
==83087==
==83087== HEAP SUMMARY:
==83087==     in use at exit: 0 bytes in 0 blocks
==83087==   total heap usage: 176,004 allocs, 176,004 frees, 2,992,903 bytes allocated
==83087==
==83087== All heap blocks were freed -- no leaks are possible
==83087==
==83087== For lists of detected and suppressed errors, rerun with: -s
==83087== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)
safe_process[83086]: Child process: 83087, exit: 1