[MDEV-26325] mysqld process hangs when stopped after executing mysql_upgrade Created: 2021-08-09  Updated: 2021-11-29  Resolved: 2021-08-12

Status: Closed
Project: MariaDB Server
Component/s: Server
Affects Version/s: 10.5.12
Fix Version/s: 10.5.13, 10.6.5

Type: Bug Priority: Blocker
Reporter: Anton Serbulov Assignee: Vladislav Vaintroub
Resolution: Fixed Votes: 0
Labels: hang
Environment:

Windows

Issue Links:
Blocks
Duplicate
is duplicated by MDEV-26932 upgrade wizard never finishes at Phas... Closed
Problem/Incident
is caused by MDEV-18353 Shutdown may miss to wait for connect... Closed
Relates
relates to MDEV-11499 mysqltest, Windows : improve diagnost... Closed

 Description   

Steps to reproduce

  1. Initializing the MariaDB data directory 

    C:\Users\Administrator>C:\mariadb-10.5.12-winx64\bin\mysql_install_db.exe --datadir=C:\db --service=MyDB --password=secret
    		 
    Running bootstrap
    		 
    2021-08-09 17:56:17 0 [Note] C:\mariadb-10.5.12-winx64\bin\mysqld.exe (mysqld 10.5.12-MariaDB) starting as process 1212 ...
    		 
    Removing default user
    		 
    Setting root password
    		 
    Creating my.ini file
    		 
    Registering service 'MyDB'
    		 
    Creation of the database was successful

  2. Upload the C:\db\my.ini file 

    [mysqld]
    		 
    datadir=C:/db
    		 
    skip-grant-tables
    		 
    skip-networking
    		 
    enable-named-pipe
    		 
    [client]
    		 
    plugin-dir=C:/mariadb-10.5.12-winx64/lib/plugin

  3. Start service 

    C:\Users\Administrator>sc start MyDB

  4. Start mysql_upgrade 

    C:\Users\Administrator>C:\mariadb-10.5.12-winx64\bin\mysql_upgrade.exe --force --host=. --protocol=pipe
    		 
    Phase 1/7: Checking and upgrading mysql database
    		 
    Processing databases
    		 
    mysql
    		 
    mysql.column_stats                                 OK
    		 
    mysql.columns_priv                                 OK
    		 
    mysql.db                                           OK
    		 
    mysql.event                                        OK
    		 
    mysql.func                                         OK
    		 
    mysql.global_priv                                  OK
    		 
    mysql.gtid_slave_pos                               OK
    		 
    mysql.help_category                                OK
    		 
    mysql.help_keyword                                 OK
    		 
    mysql.help_relation                                OK
    		 
    mysql.help_topic                                   OK
    		 
    mysql.index_stats                                  OK
    		 
    mysql.innodb_index_stats                           OK
    		 
    mysql.innodb_table_stats                           OK
    		 
    mysql.plugin                                       OK
    		 
    mysql.proc                                         OK
    		 
    mysql.procs_priv                                   OK
    		 
    mysql.proxies_priv                                 OK
    		 
    mysql.roles_mapping                                OK
    		 
    mysql.servers                                      OK
    		 
    mysql.table_stats                                  OK
    		 
    mysql.tables_priv                                  OK
    		 
    mysql.time_zone                                    OK
    		 
    mysql.time_zone_leap_second                        OK
    		 
    mysql.time_zone_name                               OK
    		 
    mysql.time_zone_transition                         OK
    		 
    mysql.time_zone_transition_type                    OK
    		 
    mysql.transaction_registry                         OK
    		 
    Phase 2/7: Installing used storage engines... Skipped
    		 
    Phase 3/7: Fixing views
    		 
    mysql.user                                         OK
    		 
    Phase 4/7: Running 'mysql_fix_privilege_tables'
    		 
    Phase 5/7: Fixing table and database names
    		 
    Phase 6/7: Checking and upgrading tables
    		 
    Processing databases
    		 
    information_schema
    		 
    performance_schema
    		 
    test
    		 
    Phase 7/7: Running 'FLUSH PRIVILEGES'
    		 
    OK

  5. Stop service 

    C:\Users\Administrator>sc stop MyDB

Actual result
mysqld process hands.
In the log file:

2021-08-09 17:56:17 0 [Note] InnoDB: The first innodb_system data file 'ibdata1' did not exist. A new tablespace will be created!
 
2021-08-09 17:56:17 0 [Note] InnoDB: Uses event mutexes
 
2021-08-09 17:56:17 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
2021-08-09 17:56:17 0 [Note] InnoDB: Number of pools: 1
 
2021-08-09 17:56:17 0 [Note] InnoDB: Using generic crc32 instructions
 
2021-08-09 17:56:17 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728
 
2021-08-09 17:56:17 0 [Note] InnoDB: Completed initialization of buffer pool
 
2021-08-09 17:56:17 0 [Note] InnoDB: Setting file '.\ibdata1' size to 12 MB. Physically writing the file full; Please wait ...
 
2021-08-09 17:56:17 0 [Note] InnoDB: File '.\ibdata1' size is now 12 MB.
 
2021-08-09 17:56:17 0 [Note] InnoDB: Setting log file .\ib_logfile101 size to 100663296 bytes
 
2021-08-09 17:56:18 0 [Note] InnoDB: Renaming log file .\ib_logfile101 to .\ib_logfile0
 
2021-08-09 17:56:18 0 [Note] InnoDB: New log file created, LSN=10317
 
2021-08-09 17:56:18 0 [Note] InnoDB: Doublewrite buffer not found: creating new
 
2021-08-09 17:56:18 0 [Note] InnoDB: Doublewrite buffer created
 
2021-08-09 17:56:18 0 [Note] InnoDB: 128 rollback segments are active.
 
2021-08-09 17:56:18 0 [Note] InnoDB: Creating foreign key constraint system tables.
 
2021-08-09 17:56:18 0 [Note] InnoDB: Creating tablespace and datafile system tables.
 
2021-08-09 17:56:18 0 [Note] InnoDB: Creating sys_virtual system tables.
 
2021-08-09 17:56:18 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2021-08-09 17:56:18 0 [Note] InnoDB: Setting file '.\ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2021-08-09 17:56:18 0 [Note] InnoDB: File '.\ibtmp1' size is now 12 MB.
 
2021-08-09 17:56:18 0 [Note] InnoDB: 10.5.12 started; log sequence number 0; transaction id 7
 
2021-08-09 17:56:18 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2021-08-09 18:00:41 0 [Note] InnoDB: Uses event mutexes
 
2021-08-09 18:00:41 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
2021-08-09 18:00:41 0 [Note] InnoDB: Number of pools: 1
 
2021-08-09 18:00:41 0 [Note] InnoDB: Using generic crc32 instructions
 
2021-08-09 18:00:41 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728
 
2021-08-09 18:00:41 0 [Note] InnoDB: Completed initialization of buffer pool
 
2021-08-09 18:00:41 0 [Note] InnoDB: 128 rollback segments are active.
 
2021-08-09 18:00:41 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2021-08-09 18:00:41 0 [Note] InnoDB: Setting file '.\ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2021-08-09 18:00:41 0 [Note] InnoDB: File '.\ibtmp1' size is now 12 MB.
 
2021-08-09 18:00:41 0 [Note] InnoDB: 10.5.12 started; log sequence number 45094; transaction id 20
 
2021-08-09 18:00:41 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2021-08-09 18:00:41 0 [Note] Reading of all Master_info entries succeeded
 
2021-08-09 18:00:41 0 [Note] Added new Master_info '' to hash table
 
2021-08-09 18:00:41 0 [Note] C:\mariadb-10.5.12-winx64\bin\mysqld.exe: ready for connections.
 
Version: '10.5.12-MariaDB'  socket: ''  port: 0  mariadb.org binary distribution
 
2021-08-09 18:00:41 0 [Note] InnoDB: Loading buffer pool(s) from C:\db\ib_buffer_pool
 
2021-08-09 18:00:41 0 [Note] InnoDB: Buffer pool(s) load completed at 210809 18:00:41
 
2021-08-09 18:02:13 15 [Warning] Access denied for user 'root'@'localhost' (using password: NO)
 
2021-08-09 18:04:09 0 [Note] C:\mariadb-10.5.12-winx64\bin\mysqld.exe (initiated by: unknown): Normal shutdown



 Comments   
Comment by Elena Stepanova [ 2021-08-09 ]

Would you be able to take a minidump from the hanging server?

Comment by Anton Serbulov [ 2021-08-09 ]

The full memory dump of the mysqld process: ftp://ftp.mariadb.org/private/mysqld.exe_210809_182646.dmp.zip

Comment by Vladislav Vaintroub [ 2021-08-09 ]

I can reproduce

That's how it hangs

 	ntdll.dll!NtDelayExecution()	Unknown
 
 	KernelBase.dll!SleepEx()	Unknown
 
>	server.dll!close_connections() Line 1719	C++
 
 	server.dll!win_main(int argc, char * * argv) Line 5682	C++
 
 	server.dll!mysql_service(void * p) Line 5728	C++
 
 	ucrtbase.dll!thread_start<void (__cdecl*)(void *),0>()	Unknown
 
 	kernel32.dll!BaseThreadInitThunk()	Unknown
 
 	ntdll.dll!RtlUserThreadStart()	Unknown

That's where it hangs in close_connections()

  while (CONNECT::count)
 
    my_sleep(100);

CONNECT::count is 0xfffffff3

Comment by Vladislav Vaintroub [ 2021-08-09 ]

serg, this is MDEV-18353, which breaks shutdown as soon as named pipe connections are involved. Helpful MTR won't tell, and would silently kill the server process, even if we have named_pipe test.

As consequence it breaks mysql_upgrade_service, which works somewhat like the reporter described.
This also breaks upgrade from 10.x to 10.5 in GUI , which uses named pipes and mysql_upgrade_service.

The reason for the bug is that there is a constructor for CONNECT that does not increment CONNECT::count, but destructor always decrements it.

below would fix it, but I let you decide whether there is a more elegant workaround,

diff --git a/sql/sql_connect.h b/sql/sql_connect.h
 
index 1a84cb56e5c..68bdb4a1a31 100644
 
--- a/sql/sql_connect.h
 
+++ b/sql/sql_connect.h
 
@@ -35,7 +35,10 @@ class CONNECT : public ilink {
 
 #ifdef _WIN32
 
   HANDLE pipe;
 
   CONNECT(HANDLE pipe_arg): pipe(pipe_arg), vio_type(VIO_TYPE_NAMEDPIPE),
 
-    scheduler(thread_scheduler), thread_id(0), prior_thr_create_utime(0) {}
 
+    scheduler(thread_scheduler), thread_id(0), prior_thr_create_utime(0)
 
+    {
 
+      count++;
 
+    }
 
 #endif
 
   enum enum_vio_type vio_type;
 
   scheduler_functions *scheduler;

Comment by Vladislav Vaintroub [ 2021-08-09 ]

To reproduce it more easily

start mysqld with 

mysqld --console --enable-named-pipe

and from another cmd window

C:\work\10.5\xxx\sql>mysql --host=. -uroot -e "select 1"
 
+---+
 
| 1 |
 
+---+
 
| 1 |
 
+---+
 
 
 
C:\work\10.5\xxx\sql>mysql --host=. -uroot -e "shutdown"

The server won't shutdown

--host=.

is an indicator that pipe should be used 

--protocol=pipe

would do the same

Comment by Vladislav Vaintroub [ 2021-08-10 ]

serg, what do you think of https://github.com/MariaDB/server/commit/236e7e964b79377717ac1237965f2d4bd51b5b36

I restored the idea of the generic templated object counter, so that we do not have THD_count and CONNECT_count classes

Comment by Sergei Golubchik [ 2021-08-12 ]

I'd prefer just one more count++ as you had in your comment above.

Template is kind of nice, but rather artificial, because it doesn't use the type T for anything. I'm not even sure it's guaranteed to work, given that the template doesn't depend on the type, what prevents a sufficiently smart compiler to "optimize" it into only one instance of the class?

Comment by Vladislav Vaintroub [ 2021-08-12 ]

I'm not sure it is guaranteed to work either, but a similar example is in Wikipedia, so it is more trustable than I would come up with that myself , and compiler writers maybe would not like to break that use of "curiously recurring template pattern" https://en.wikipedia.org/wiki/Curiously_recurring_template_pattern#Object_counter

Also, this is used in Scott Meyers' article from back 1998 about how to count objects in C++ ,and he perhaps can be trusted.

Thinking a little more, I'd guess templates with different template parameters can't legally be merged into the same object. Anyway, Scott Meyers, Wikipedia , and stackoverflow may be enough evidence.

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