Details
-
Task
-
Status: Closed (View Workflow)
-
Minor
-
Resolution: Fixed
-
None
Description
As stated in description MTR should report in that cases the last test that was executed.
That information can be extracted from CURRENT_TEST that is written in log file.
In attachment is suggested patch, that works in case tests are not completed.
Patch - bb-10.6-anel-MDEV-25506.
However, in case of shutdown on Windows environment, result is visible in verbose mode mtr --verbose. Without the flag verbose I couldn't obtain the same result.
Note: the patch contains some information for debugging purposes only and to show you here i description. I will remove them after review. Does it mean that mtr_report_test doesn't work in Windows?
Invoke mtr with test case encryption.innodb-bad-key-change4 on branch bb-10.6-anel-MDEV-25506
Results in Windows without the patch and with the patch without verbose flag - test not visible:
==============================================================================
|
TEST RESULT TIME (ms) or COMMENT
|
--------------------------------------------------------------------------
|
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
|
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 17188, winpid: 17188, exit: 512] died after mysql-test-run waited 0.42 seconds for D:/server/bld_10.6/mysql-test/var/run/mysqld.1.pid to be created.
|
worker[1] mysql-test-run: *** ERROR: Failed to start mysqld mysqld.1 with command D:/server/bld_10.6/sql//Debug/mariadbd.exe
|
Result with verbose mode - test visible
worker[1] > mysqld_start restart: [' --plugin-load-add=file_key_management.so', '--file-key-management', '--file-key-management-filename=D:/server/mysql-test/std_data/keys2.txt ']
|
worker[1] > Started [mysqld.1 - pid: 17452, winpid: 17452]
|
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 17452, winpid: 17452, exit: 512] died after mysql-test-run waited 0.43 seconds for D:/server/bld_10.6/mysql-test/var/run/mysqld.1.pid to be created.
|
worker[1] Ovdje sam
|
worker[1] D:/server/bld_10.6/mysql-test/var/log/current_test
|
worker[1] Ovdje sam
|
worker[1] encryption.innodb-bad-key-change4
|
safe_process[8548]: parent_pid: 16212
|
safe_process[8548]: Started child 9996
|
worker[1] [ fail ]
|
Test ended at 2021-06-03 13:45:41
|
worker[1]
|
D:/server/bld_10.6/mysql-test/var/log/current_test
|
worker[1] mysql-test-run: *** ERROR: Failed to start mysqld mysqld.1 with command D:/server/bld_10.6/sql//Debug/mariadbd.exe
|
Note that this line - mtr_report_test is not executed and I don't see how to fix this on Windows.
Any idea wlad ?
Attachments
Issue Links
- causes
-
MDEV-30186 Use of uninitialized value $test_name in substitution
-
- Closed
-
Activity
Ok have debugged and indeed verbose is needed for mtr_report_test/mtr_report_test_names/mtr_report functions.
With the new patch failure looks like:
|
|
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
|
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 8756, winpid: 8756, exit: 512] died after mysql-test-run waited 0.4 seconds for D:/server/bld_10.6/mysql-test/var/run/mysqld.1.pid to be created.
|
worker[1] encryption.innodb-bad-key-change4
|
worker[1] [ fail ]
|
Test ended at 2021-06-05 16:42:01
|
worker[1]
|
D:/server/bld_10.6/mysql-test/var/log/current_test
|
|
|
worker[1] mysql-test-run: *** ERROR: Failed to start mysqld mysqld.1 with command D:/server/bld_10.6/sql//Debug/mariadbd.exe
|
Note: I couldn't reproduce the same failure on Linux, so no similar test to compare.
Addressed marko demand for having failed test in Windows buildbot
http://buildbot.askmonty.org/buildbot/builders/winx64-debug/builds/25598/steps/test/logs/stdio
I am not too familliar with mtr internals, so I do not feel capable to review this.
I think that it would be good to copy all lines from the server error log output starting from the latest CURRENT_TEST: line, so that:
- the actual reason for failure is visible without searching for the server error logs
- the server error log messages will be available in the cross-reference (which only stores the test output logs, not the server error logs)
With the new patch c44a7052216661d2server log is extracted.
Please review Marko.
D:\server\bld_10.6\mysql-test>perl mysql-test-run.pl encryption.innodb-bad-key-change4
|
Logging: D:/server/mysql-test/mysql-test-run.pl encryption.innodb-bad-key-change4
|
VS config: Debug
|
vardir: D:/server/bld_10.6/mysql-test/var
|
Checking leftover processes...
|
Removing old var directory...
|
Creating var directory 'D:/server/bld_10.6/mysql-test/var'...
|
Checking supported features...
|
MariaDB Version 10.6.2-MariaDB-debug
|
- SSL connections supported
|
- binaries are debug compiled
|
Collecting tests...
|
Installing system database...
|
|
|
==============================================================================
|
|
|
TEST RESULT TIME (ms) or COMMENT
|
--------------------------------------------------------------------------
|
|
|
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
|
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 14684, winpid: 14684, exit: 512] died after mysql-test-run waited 0.41 seconds for D:/server/bld_10.6/mysql-test/var/run/mysqld.1.pid to be created.
|
Terminating on signal SIGINT(2)
|
|
|
D:\server\bld_10.6\mysql-test>perl mysql-test-run.pl encryption.innodb-bad-key-change4mysql-test-run: *** ERROR: Got ^C signal
|
|
|
Logging: D:/server/mysql-test/mysql-test-run.pl encryption.innodb-bad-key-change4
|
VS config: Debug
|
vardir: D:/server/bld_10.6/mysql-test/var
|
Checking leftover processes...
|
Removing old var directory...
|
Creating var directory 'D:/server/bld_10.6/mysql-test/var'...
|
Checking supported features...
|
MariaDB Version 10.6.2-MariaDB-debug
|
- SSL connections supported
|
- binaries are debug compiled
|
Collecting tests...
|
Installing system database...
|
|
|
==============================================================================
|
|
|
TEST RESULT TIME (ms) or COMMENT
|
--------------------------------------------------------------------------
|
|
|
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
|
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 2388, winpid: 2388, exit: 512] died after mysql-test-run waited 0.39 seconds for D:/server/bld_10.6/mysql-test/var/run/mysqld.1.pid to be created.
|
worker[1] encryption.innodb-bad-key-change4
|
worker[1] [ fail ]
|
Test ended at 2021-06-07 17:31:12
|
worker[1]
|
|
|
Server log from this test:
|
----------SERVER LOG START-----------
|
2021-06-07 17:31:08 0 [Note] D:/server/bld_10.6/sql//Debug/mariadbd.exe (mysqld 10.6.2-MariaDB-debug-log) starting as process 15376 ...
|
2021-06-07 17:31:08 0 [Note] Plugin 'partition' is disabled.
|
2021-06-07 17:31:08 0 [Note] Plugin 'SEQUENCE' is disabled.
|
2021-06-07 17:31:08 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
|
2021-06-07 17:31:08 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
|
2021-06-07 17:31:08 0 [Note] InnoDB: Number of pools: 1
|
2021-06-07 17:31:08 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
|
2021-06-07 17:31:08 0 [Note] InnoDB: Initializing buffer pool, total size = 8388608, chunk size = 8388608
|
2021-06-07 17:31:08 0 [Note] InnoDB: Completed initialization of buffer pool
|
2021-06-07 17:31:09 0 [Note] InnoDB: 128 rollback segments are active.
|
2021-06-07 17:31:09 0 [Note] InnoDB: Creating shared tablespace for temporary tables
|
2021-06-07 17:31:09 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
|
2021-06-07 17:31:09 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
|
2021-06-07 17:31:09 0 [Note] InnoDB: 10.6.2 started; log sequence number 44901; transaction id 23
|
2021-06-07 17:31:09 0 [Note] InnoDB: Loading buffer pool(s) from D:\server\bld_10.6\mysql-test\var\mysqld.1\data\ib_buffer_pool
|
2021-06-07 17:31:09 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
|
2021-06-07 17:31:09 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
|
2021-06-07 17:31:09 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
|
2021-06-07 17:31:09 0 [Note] Plugin 'INNODB_CMP' is disabled.
|
2021-06-07 17:31:09 0 [Note] Plugin 'THREAD_POOL_WAITS' is disabled.
|
2021-06-07 17:31:09 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
|
2021-06-07 17:31:09 0 [Note] Plugin 'THREAD_POOL_QUEUES' is disabled.
|
2021-06-07 17:31:09 0 [Note] Plugin 'FEEDBACK' is disabled.
|
2021-06-07 17:31:09 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
|
2021-06-07 17:31:09 0 [Note] Plugin 'THREAD_POOL_GROUPS' is disabled.
|
2021-06-07 17:31:09 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
|
2021-06-07 17:31:09 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
|
2021-06-07 17:31:09 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
|
2021-06-07 17:31:09 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
|
2021-06-07 17:31:09 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
|
2021-06-07 17:31:09 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
|
2021-06-07 17:31:09 0 [Note] Plugin 'user_variables' is disabled.
|
2021-06-07 17:31:09 0 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
|
2021-06-07 17:31:09 0 [Note] Plugin 'THREAD_POOL_STATS' is disabled.
|
2021-06-07 17:31:09 0 [Warning] D:/server/bld_10.6/sql//Debug/mariadbd.exe: unknown option '--loose-pam-debug'
|
2021-06-07 17:31:09 0 [Warning] D:/server/bld_10.6/sql//Debug/mariadbd.exe: unknown option '--loose-aria'
|
2021-06-07 17:31:09 0 [Note] InnoDB: Buffer pool(s) load completed at 210607 17:31:09
|
2021-06-07 17:31:10 0 [Note] Server socket created on IP: '::'.
|
2021-06-07 17:31:10 0 [Note] Server socket created on IP: '0.0.0.0'.
|
2021-06-07 17:31:10 0 [Note] D:/server/bld_10.6/sql//Debug/mariadbd.exe: ready for connections.
|
Version: '10.6.2-MariaDB-debug-log' socket: '' port: 16000 Source distribution
|
2021-06-07 17:31:10 0 [Note] D:/server/bld_10.6/sql//Debug/mariadbd.exe (initiated by: root[root] @ localhost [::1]): Normal shutdown
|
2021-06-07 17:31:10 0 [Note] InnoDB: FTS optimize thread exiting.
|
2021-06-07 17:31:10 0 [Note] InnoDB: Starting shutdown...
|
2021-06-07 17:31:10 0 [Note] InnoDB: Dumping buffer pool(s) to D:\server\bld_10.6\mysql-test\var\mysqld.1\data\ib_buffer_pool
|
2021-06-07 17:31:10 0 [Note] InnoDB: Restricted to 126 pages due to innodb_buf_pool_dump_pct=25
|
2021-06-07 17:31:10 0 [Note] InnoDB: Buffer pool(s) dump completed at 210607 17:31:10
|
2021-06-07 17:31:10 0 [Note] InnoDB: Removed temporary tablespace data file: "./ibtmp1"
|
2021-06-07 17:31:10 0 [Note] InnoDB: Shutdown completed; log sequence number 45169; transaction id 23
|
2021-06-07 17:31:10 0 [Note] Debug sync points hit: 1397
|
2021-06-07 17:31:10 0 [Note] Debug sync points executed: 0
|
2021-06-07 17:31:10 0 [Note] Debug sync points max active per thread: 0
|
2021-06-07 17:31:10 0 [Note] D:/server/bld_10.6/sql//Debug/mariadbd.exe: Shutdown complete
|
|
|
2021-06-07 17:31:11 0 [Note] D:/server/bld_10.6/sql//Debug/mariadbd.exe (mysqld 10.6.2-MariaDB-debug-log) starting as process 16752 ...
|
2021-06-07 17:31:11 0 [ERROR] mariadbd.exe: Can't open shared library 'D:\server\bld_10.6\mysql-test\var\plugins\file_key_management.so.dll' (errno: 2, The specified module could not be found. )
|
2021-06-07 17:31:11 0 [ERROR] Couldn't load plugins from 'file_key_management.so.dll'.
|
2021-06-07 17:31:11 0 [Note] Plugin 'partition' is disabled.
|
2021-06-07 17:31:11 0 [Note] Plugin 'SEQUENCE' is disabled.
|
2021-06-07 17:31:11 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
|
2021-06-07 17:31:11 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
|
2021-06-07 17:31:11 0 [Note] InnoDB: Number of pools: 1
|
2021-06-07 17:31:11 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
|
2021-06-07 17:31:11 0 [Note] InnoDB: Initializing buffer pool, total size = 8388608, chunk size = 8388608
|
2021-06-07 17:31:11 0 [Note] InnoDB: Completed initialization of buffer pool
|
2021-06-07 17:31:12 0 [Note] InnoDB: 128 rollback segments are active.
|
2021-06-07 17:31:12 0 [Note] InnoDB: Creating shared tablespace for temporary tables
|
2021-06-07 17:31:12 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
|
2021-06-07 17:31:12 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
|
2021-06-07 17:31:12 0 [Note] InnoDB: 10.6.2 started; log sequence number 45169; transaction id 23
|
2021-06-07 17:31:12 0 [Note] InnoDB: Loading buffer pool(s) from D:\server\bld_10.6\mysql-test\var\mysqld.1\data\ib_buffer_pool
|
2021-06-07 17:31:12 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
|
2021-06-07 17:31:12 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
|
2021-06-07 17:31:12 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
|
2021-06-07 17:31:12 0 [Note] Plugin 'INNODB_CMP' is disabled.
|
2021-06-07 17:31:12 0 [Note] Plugin 'THREAD_POOL_WAITS' is disabled.
|
2021-06-07 17:31:12 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
|
2021-06-07 17:31:12 0 [Note] Plugin 'THREAD_POOL_QUEUES' is disabled.
|
2021-06-07 17:31:12 0 [Note] Plugin 'FEEDBACK' is disabled.
|
2021-06-07 17:31:12 0 [Note] InnoDB: Buffer pool(s) load completed at 210607 17:31:12
|
2021-06-07 17:31:12 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
|
2021-06-07 17:31:12 0 [Note] Plugin 'THREAD_POOL_GROUPS' is disabled.
|
2021-06-07 17:31:12 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
|
2021-06-07 17:31:12 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
|
2021-06-07 17:31:12 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
|
2021-06-07 17:31:12 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
|
2021-06-07 17:31:12 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
|
2021-06-07 17:31:12 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
|
2021-06-07 17:31:12 0 [Note] Plugin 'user_variables' is disabled.
|
2021-06-07 17:31:12 0 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
|
2021-06-07 17:31:12 0 [Note] Plugin 'THREAD_POOL_STATS' is disabled.
|
2021-06-07 17:31:12 0 [Warning] D:/server/bld_10.6/sql//Debug/mariadbd.exe: unknown option '--loose-pam-debug'
|
2021-06-07 17:31:12 0 [Warning] D:/server/bld_10.6/sql//Debug/mariadbd.exe: unknown option '--loose-aria'
|
2021-06-07 17:31:12 0 [ERROR] D:/server/bld_10.6/sql//Debug/mariadbd.exe: unknown option '--file-key-management'
|
2021-06-07 17:31:12 0 [ERROR] Aborting
|
----------SERVER LOG END-------------
|
|
|
|
|
worker[1] mysql-test-run: *** ERROR: Failed to start mysqld mysqld.1 with command D:/server/bld_10.6/sql//Debug/mariadbd.exe
|
feel free to push.
As far as I see, there is no whatever Windows specific code in there, it and it the most portable perl (and I do not really know that code really well) . If that fixes some of the silent exits on buildbot, the patch is very much welcome.
Pushed with https://github.com/MariaDB/server/commit/29e8c154172bd6b9dccd9757fddace93be6ad194.
Thanks wlad, marko.
Frankly, I'm not sure what it is supposed to do, and how it happened some functionality on Windows was never noticed for the over decade long existence of the mtr.
But I suggest to apply usually debugging techniques to find out what happens, when you enter mtr_report_whatever, with verbose printouts, if necessary on each line (I for one , have no other experience debugging perl, than verbose printouts)
Clearly, there is some way that mtr prints to stdout, and stderr, even on Windows, or we would never ever see the verbose outputs on buildbots.