[MDEV-28898] InnoDB: Assertion failure in file fil0fil.cc line 4318 Created: 2022-06-20  Updated: 2024-01-02  Resolved: 2024-01-02

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.4.12
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: jeonghun Assignee: Vladislav Vaintroub
Resolution: Cannot Reproduce Votes: 0
Labels: None
Environment:

windows 10 pro 20H2 x64
Intel(R) Core(TM) i7-10700 CPU @ 2.90GHz 2.90 GHz
RAM : 32.0GB


 Description   

We use MariaDB Server for local file management (Log File Manager)
So the PC is not connected to Internet.
Server is OK for about a month after the first start. But After about a month, Server is forced to shut down. Then, we restart the Server, and It's okay for about a month. And then the same thing happens again..
The log message when server is shut down is as follows.
>>>>------------------------------------------------------------------------------
InnoDB: using atomic writes.
2022-05-19 16:40:18 0 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2022-05-19 16:40:18 0 [Note] InnoDB: Uses event mutexes
2022-05-19 16:40:18 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2022-05-19 16:40:18 0 [Note] InnoDB: Number of pools: 1
2022-05-19 16:40:18 0 [Note] InnoDB: Using SSE2 crc32 instructions
2022-05-19 16:40:18 0 [Note] InnoDB: Initializing buffer pool, total size = 4G, instances = 8, chunk size = 128M
2022-05-19 16:40:18 0 [Note] InnoDB: Completed initialization of buffer pool
2022-05-19 16:40:18 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2022-05-19 16:40:18 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2022-05-19 16:40:18 0 [Note] InnoDB: Setting file '.\ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2022-05-19 16:40:18 0 [Note] InnoDB: File '.\ibtmp1' size is now 12 MB.
2022-05-19 16:40:18 0 [Note] InnoDB: Waiting for purge to start
2022-05-19 16:40:18 0 [Note] InnoDB: 10.4.12 started; log sequence number 60972; transaction id 21
2022-05-19 16:40:18 0 [Note] Plugin 'FEEDBACK' is disabled.
2022-05-19 16:40:18 0 [Note] InnoDB: Loading buffer pool(s) from C:\Program Files\MariaDB 10.4\data\ib_buffer_pool
2022-05-19 16:40:18 0 [Note] InnoDB: Buffer pool(s) load completed at 220519 16:40:18
2022-05-19 16:40:18 0 [Note] Server socket created on IP: '::'.
2022-05-19 16:40:18 0 [Note] Reading of all Master_info entries succeeded
2022-05-19 16:40:18 0 [Note] Added new Master_info '' to hash table
2022-05-19 16:40:18 0 [Note] C:\Program Files\MariaDB 10.4\bin\mysqld.exe: ready for connections.
Version: '10.4.12-MariaDB' socket: '' port: 3306 mariadb.org binary distribution
2022-05-20 0:41:00 9 [Warning] Aborted connection 9 to db: 'my_info' user: 'root' host: 'localhost' (Got timeout reading communication packets)
2022-05-20 18:02:56 11 [Warning] Aborted connection 11 to db: 'my_info' user: 'root' host: 'localhost' (Got timeout reading communication packets)
2022-05-23 21:33:39 12 [Warning] Aborted connection 12 to db: 'my_info' user: 'root' host: 'localhost' (Got timeout reading communication packets)
2022-05-28 19:05:13 13 [Warning] Aborted connection 13 to db: 'my_info' user: 'root' host: 'localhost' (Got timeout reading communication packets)
2022-05-30 22:25:26 14 [Warning] Aborted connection 14 to db: 'my_info' user: 'root' host: 'localhost' (Got timeout reading communication packets)
2022-05-31 10:50:57 10 [Warning] Aborted connection 10 to db: 'my_info' user: 'root' host: 'localhost' (Got an error reading communication packets)
2022-05-31 10:51:12 16 [Warning] Aborted connection 16 to db: 'my_info' user: 'root' host: 'localhost' (Got an error reading communication packets)
2022-05-31 22:21:25 20 [Warning] Aborted connection 20 to db: 'my_info' user: 'root' host: 'localhost' (Got timeout reading communication packets)
2022-06-01 8:00:00 22 [Warning] Aborted connection 22 to db: 'my_info' user: 'root' host: 'localhost' (Got timeout reading communication packets)
2022-06-03 9:43:44 23 [Warning] Aborted connection 23 to db: 'my_info' user: 'root' host: 'localhost' (Got timeout reading communication packets)
2022-06-07 6:22:44 24 [Warning] Aborted connection 24 to db: 'my_info' user: 'root' host: 'localhost' (Got timeout reading communication packets)
2022-06-08 14:30:34 21 [Warning] Aborted connection 21 to db: 'my_info' user: 'root' host: 'localhost' (Got timeout reading communication packets)
2022-06-09 2:44:30 25 [Warning] Aborted connection 25 to db: 'my_info' user: 'root' host: 'localhost' (Got timeout reading communication packets)
2022-06-09 20:16:54 27 [Warning] Aborted connection 27 to db: 'my_info' user: 'root' host: 'localhost' (Got timeout reading communication packets)
2022-06-16 1:25:43 28 [Warning] Aborted connection 28 to db: 'my_info' user: 'root' host: 'localhost' (Got timeout reading communication packets)
InnoDB: using atomic writes.
2022-06-16 8:10:22 0 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2022-06-16 8:10:22 0 [Note] InnoDB: Uses event mutexes
2022-06-16 8:10:22 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2022-06-16 8:10:22 0 [Note] InnoDB: Number of pools: 1
2022-06-16 8:10:22 0 [Note] InnoDB: Using SSE2 crc32 instructions
2022-06-16 8:10:22 0 [Note] InnoDB: Initializing buffer pool, total size = 4G, instances = 8, chunk size = 128M
2022-06-16 8:10:22 0 [Note] InnoDB: Completed initialization of buffer pool
2022-06-16 8:10:22 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=522135963
2022-06-16 8:10:22 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2022-06-16 8:10:22 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2022-06-16 8:10:22 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2022-06-16 8:10:22 0 [Note] InnoDB: Setting file '.\ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2022-06-16 8:10:22 0 [Note] InnoDB: File '.\ibtmp1' size is now 12 MB.
2022-06-16 8:10:22 0 [Note] InnoDB: Waiting for purge to start
2022-06-16 8:10:22 0 [Note] InnoDB: 10.4.12 started; log sequence number 522135972; transaction id 1198874
2022-06-16 8:10:22 0 [Note] InnoDB: Loading buffer pool(s) from C:\Program Files\MariaDB 10.4\data\ib_buffer_pool
2022-06-16 8:10:22 0 [Note] Plugin 'FEEDBACK' is disabled.
2022-06-16 8:10:22 0 [Note] InnoDB: Buffer pool(s) load completed at 220616 8:10:22
2022-06-16 8:10:22 0 [Note] Server socket created on IP: '::'.
2022-06-16 8:10:22 0 [Note] Reading of all Master_info entries succeeded
2022-06-16 8:10:22 0 [Note] Added new Master_info '' to hash table
2022-06-16 8:10:22 0 [Note] C:\Program Files\MariaDB 10.4\bin\mysqld.exe: ready for connections.
Version: '10.4.12-MariaDB' socket: '' port: 3306 mariadb.org binary distribution
2022-06-16 16:30:06 9 [Warning] Aborted connection 9 to db: 'my_info' user: 'root' host: 'localhost' (Got timeout reading communication packets)
2022-06-17 18:03:12 10 [Warning] Aborted connection 10 to db: 'my_info' user: 'root' host: 'localhost' (Got timeout reading communication packets)
2022-06-19 4:21:48 0 [ERROR] InnoDB: Operating system error number 5 in a file operation.
2022-06-19 4:21:48 0 [ERROR] InnoDB: The error means mysqld does not have the access rights to the directory. It may also be you have created a subdirectory of the same name as a data file.
2022-06-19 04:21:48 0x1750 InnoDB: Assertion failure in file D:\winx64-packages\build\src\storage\innobase\fil\fil0fil.cc line 4318
InnoDB: Failing assertion: req_type.is_dblwr_recover() || err == DB_SUCCESS
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
InnoDB: about forcing recovery.
220619 4:21:48 [ERROR] mysqld got exception 0x80000003 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.

To report this bug, see https://mariadb.com/kb/en/reporting-bugs

We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.

Server version: 10.4.12-MariaDB
key_buffer_size=134217728
read_buffer_size=131072
max_used_connections=2
max_threads=65537
thread_count=7
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 136388 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
mysqld.exe!my_sigabrt_handler()[my_thr_init.c:485]
ucrtbase.dll!raise()
ucrtbase.dll!abort()
mysqld.exe!ut_dbg_assertion_failed()[ut0dbg.cc:60]
mysqld.exe!fil_io()[fil0fil.cc:4318]
mysqld.exe!buf_dblwr_write_block_to_datafile()[buf0dblwr.cc:950]
mysqld.exe!buf_dblwr_flush_buffered_writes()[buf0dblwr.cc:1091]
mysqld.exe!buf_flush_do_batch()[buf0flu.cc:1998]
mysqld.exe!buf_flush_lists()[buf0flu.cc:2096]
mysqld.exe!buf_flush_page_cleaner_coordinator()[buf0flu.cc:3254]
KERNEL32.DLL!BaseThreadInitThunk()
ntdll.dll!RtlUserThreadStart()
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
Writing a core file at C:\Program Files\MariaDB 10.4\data\
InnoDB: using atomic writes.
2022-06-19 4:40:14 0 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2022-06-19 4:40:14 0 [Note] InnoDB: Uses event mutexes
2022-06-19 4:40:14 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2022-06-19 4:40:14 0 [Note] InnoDB: Number of pools: 1
2022-06-19 4:40:14 0 [Note] InnoDB: Using SSE2 crc32 instructions
2022-06-19 4:40:14 0 [Note] InnoDB: Initializing buffer pool, total size = 4G, instances = 8, chunk size = 128M
2022-06-19 4:40:14 0 [Note] InnoDB: Completed initialization of buffer pool
2022-06-19 4:40:14 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=585767634
2022-06-19 4:40:15 0 [Note] InnoDB: Starting final batch to recover 11 pages from redo log.
2022-06-19 4:40:15 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2022-06-19 4:40:15 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2022-06-19 4:40:15 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2022-06-19 4:40:15 0 [Note] InnoDB: Setting file '.\ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2022-06-19 4:40:15 0 [Note] InnoDB: File '.\ibtmp1' size is now 12 MB.
2022-06-19 4:40:15 0 [Note] InnoDB: Waiting for purge to start
2022-06-19 4:40:15 0 [Note] InnoDB: 10.4.12 started; log sequence number 585774303; transaction id 1350708
2022-06-19 4:40:15 0 [Note] InnoDB: Loading buffer pool(s) from C:\Program Files\MariaDB 10.4\data\ib_buffer_pool
2022-06-19 4:40:15 0 [Note] Plugin 'FEEDBACK' is disabled.
2022-06-19 4:40:15 0 [Note] InnoDB: Buffer pool(s) load completed at 220619 4:40:15
2022-06-19 4:40:15 0 [Note] Server socket created on IP: '::'.
2022-06-19 4:40:15 0 [Note] Reading of all Master_info entries succeeded
2022-06-19 4:40:15 0 [Note] Added new Master_info '' to hash table
2022-06-19 4:40:15 0 [Note] C:\Program Files\MariaDB 10.4\bin\mysqld.exe: ready for connections.
Version: '10.4.12-MariaDB' socket: '' port: 3306 mariadb.org binary distribution
<<<<------------------------------------------------------------------------------

 Comments   
Comment by Marko Mäkelä [ 2022-06-20 ]

The problem would seem to be that the operating system is returning ERROR_ACCESS_DENIED for a write to the InnoDB system tablespace, where the 128 pages of the doublewrite buffer are located.

wlad, do you know under which circumstances this error could be reported? On POSIX, I would expect access control to take place only when files are being opened, and I think that the system tablespace should remain open for the entire lifetime of InnoDB.

Comment by Vladislav Vaintroub [ 2022-06-20 ]

I do not think access denied can even come when trying to write. I think the error belongs to file opening, but the error reporting is incomplete and confusing. "in a file operation" without reporting the actual operation is slightly confusing.
lim , could you please attach the error log in full, I there is hopefully more context to the error.

Comment by jeonghun [ 2022-06-30 ]

wlad, I'm sorry for the late reply. I added the full log to the body. (File cannot be uploaded due to company policy.)
As shown in the log, the server first started in 2022-05-19 16:40:18 0, error occurred in 2022-06-16 8:10:22.

Comment by Vladislav Vaintroub [ 2022-09-23 ]

Thank you lim

marko, I have not yet seen ERROR_ACCESS_DENIED during WriteFile myself. From https://stackoverflow.com/questions/4312568/what-causes-writefile-to-return-error-access-denied I gather it is not common elsewhere either. The answers on stackoverflow does not clear the situation, "ERROR_ACCESS_DENIED could indicate that the file is on a network volume" does not fit here either. A third party software that hooks WriteFile is a possibility, but that's rather uncommon. Is it possible that the memory pointed to by the buffer is not accessible?

Comment by Vladislav Vaintroub [ 2022-09-23 ]

I conducted an experiment using invalid pointer as buffer for WriteFile, and the last error is not ERROR_ACCESS_DENIED, but ERROR_INVALID_USER_BUFFER (The supplied user buffer is not valid for the requested operation). lim, If the error persists, it would make sense to record it using procmon.exe , as described in https://mariadb.com/kb/en/how-to-use-procmon-to-trace-mysqldexe-filesystem-access/ , and attach here. but otherwise I' switching off 3rd party antivirus or backup tool, if active might suddenly fix the error. I do not know any better advice.

Comment by Elena Stepanova [ 2022-10-22 ]

lim,
Did you manage to either record the procmon trace, or get rid of the error?

Comment by jeonghun [ 2022-10-24 ]

wlad and elenst, I couldn't record the procmon trace. Instead, I have experimented using 10.6 version. The error didn't occur in computer that 10.6 version was installed for about two months while it happened twice on computer with 10.4 version. I think It's better to use 10.6 version or higher.

Comment by Vladislav Vaintroub [ 2024-01-02 ]

We did not get any way to reproduce nor procmon traces. Thus, closing the report.

Generated at Thu Feb 08 10:04:19 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.