[MDEV-25857] MTR should report at least last test that was executed in case of shutdown and not-completed Created: 2021-06-04  Updated: 2022-12-23  Resolved: 2021-06-09

Status: Closed
Project: MariaDB Server
Component/s: Platform Windows
Fix Version/s: 10.6.2, 10.2.40, 10.3.31, 10.4.21, 10.5.12, 10.6.4

Type: Task Priority: Minor
Reporter: Anel Husakovic Assignee: Anel Husakovic
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Problem/Incident
causes MDEV-30186 Use of uninitialized value $test_name... Closed

 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 ?

 Comments   
Comment by Vladislav Vaintroub [ 2021-06-04 ]

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.

Comment by Anel Husakovic [ 2021-06-05 ]

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.

Comment by Anel Husakovic [ 2021-06-05 ]

marko FYI

Comment by Anel Husakovic [ 2021-06-07 ]

Addressed marko demand for having failed test in Windows buildbot
http://buildbot.askmonty.org/buildbot/builders/winx64-debug/builds/25598/steps/test/logs/stdio

Comment by Marko Mäkelä [ 2021-06-07 ]

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:

  1. the actual reason for failure is visible without searching for the server error logs
  2. the server error log messages will be available in the cross-reference (which only stores the test output logs, not the server error logs)
Comment by Anel Husakovic [ 2021-06-07 ]

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

Comment by Vladislav Vaintroub [ 2021-06-07 ]

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.

Comment by Anel Husakovic [ 2021-06-09 ]

Pushed with https://github.com/MariaDB/server/commit/29e8c154172bd6b9dccd9757fddace93be6ad194.
Thanks wlad, marko.

Generated at Thu Feb 08 09:40:55 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.