[MDEV-18382] Server crashes upon shutdown after unsuccessful start with wrong innodb_page_size - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Cannot Reproduce
Affects Version/s: 10.2(EOL), 10.3(EOL), 10.4(EOL)
Fix Version/s: N/A
Component/s: Storage Engine - InnoDB
Labels:
None

Description

~~MDEV-13093~~, still reproducible

--disable_abort_on_error

--source include/have_innodb.inc

 --let $restart_parameters= --innodb-page-size=4K --innodb-buffer-pool-size=2G

--source include/restart_mysqld.inc

select 1;

10.2 37ffdb44ef96
2019-01-25 18:17:43 140093980502208 [ERROR] InnoDB: Data file './ibdata1' uses page size 16384, but the innodb_page_size start-up parameter is 4096
2019-01-25 18:17:43 140093980502208 [ERROR] InnoDB: Corrupted page [page id: space=0, page number=0] of datafile './ibdata1' could not be found in the doublewrite buffer.
2019-01-25 18:17:43 140093980502208 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1895] with error Generic error
2019-01-25 18:17:45 140093980502208 [ERROR] Plugin 'InnoDB' init function returned error.
2019-01-25 18:17:45 140093980502208 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.

2019-01-23 20:24:27 0 [ERROR] InnoDB: mmap(154927104 bytes) failed; errno 12

2019-01-23 20:24:27 0 [ERROR] InnoDB: Cannot allocate memory for the buffer pool

2019-01-23 20:24:27 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1489] with error Generic error

2019-01-23 20:24:27 0 [Note] InnoDB: Starting shutdown...

=================================================================

==32145==ERROR: AddressSanitizer: attempting free on address which was not malloc()-ed: 0x628000008170 in thread T0

    #0 0x7fa60fc5fb2a in operator delete(void*) (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x99b2a)

    #1 0x563b4a3ff15a in LatchCounter::~LatchCounter() /10.4/storage/innobase/include/sync0types.h:580

    #2 0x563b4a403611 in LatchMeta<LatchCounter>::~LatchMeta() /10.4/storage/innobase/include/sync0types.h:759

    #3 0x563b4a3fea59 in sync_latch_meta_destroy /10.4/storage/innobase/sync/sync0debug.cc:1541

    #4 0x563b4a3fee70 in sync_check_close() /10.4/storage/innobase/sync/sync0debug.cc:1744

    #5 0x563b4a3e70ec in innodb_shutdown() /10.4/storage/innobase/srv/srv0start.cc:2528

    #6 0x563b4a063a74 in innodb_init /10.4/storage/innobase/handler/ha_innodb.cc:4256

    #7 0x563b4983f2a2 in ha_initialize_handlerton(st_plugin_int*) /10.4/sql/handler.cc:523

    #8 0x563b4916be6a in plugin_initialize /10.4/sql/sql_plugin.cc:1437

    #9 0x563b4916d6d7 in plugin_init(int*, char**, int) /10.4/sql/sql_plugin.cc:1719

    #10 0x563b48ead3e7 in init_server_components /10.4/sql/mysqld.cc:5333

    #11 0x563b48eaf328 in mysqld_main(int, char**) /10.4/sql/mysqld.cc:5862

    #12 0x563b48e9945f in main /10.4/sql/main.cc:25

    #13 0x7fa60e2ee82f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f)

    #14 0x563b48e99338 in _start (/10.4/sql/mysqld+0xe61338)

0x628000008170 is located 112 bytes inside of 14976-byte region [0x628000008100,0x62800000bb80)

freed by thread T0 here:

    #0 0x7fa60fc5e2ca in __interceptor_free (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x982ca)

    #1 0x563b4a530139 in buf_pool_free(unsigned long) /10.4/storage/innobase/buf/buf0buf.cc:2062

    #2 0x563b4a530046 in buf_pool_init(unsigned long, unsigned long) /10.4/storage/innobase/buf/buf0buf.cc:2031

    #3 0x563b4a3e2025 in srv_start(bool) /10.4/storage/innobase/srv/srv0start.cc:1484

    #4 0x563b4a063a60 in innodb_init /10.4/storage/innobase/handler/ha_innodb.cc:4253

    #5 0x563b4983f2a2 in ha_initialize_handlerton(st_plugin_int*) /10.4/sql/handler.cc:523

    #6 0x563b4916be6a in plugin_initialize /10.4/sql/sql_plugin.cc:1437

    #7 0x563b4916d6d7 in plugin_init(int*, char**, int) /10.4/sql/sql_plugin.cc:1719

    #8 0x563b48ead3e7 in init_server_components /10.4/sql/mysqld.cc:5333

    #9 0x563b48eaf328 in mysqld_main(int, char**) /10.4/sql/mysqld.cc:5862

    #10 0x563b48e9945f in main /10.4/sql/main.cc:25

    #11 0x7fa60e2ee82f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f)

previously allocated by thread T0 here:

    #0 0x7fa60fc5e79a in __interceptor_calloc (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x9879a)

    #1 0x563b4a52ffa6 in buf_pool_init(unsigned long, unsigned long) /10.4/storage/innobase/buf/buf0buf.cc:2020

    #2 0x563b4a3e2025 in srv_start(bool) /10.4/storage/innobase/srv/srv0start.cc:1484

    #3 0x563b4a063a60 in innodb_init /10.4/storage/innobase/handler/ha_innodb.cc:4253

    #4 0x563b4983f2a2 in ha_initialize_handlerton(st_plugin_int*) /10.4/sql/handler.cc:523

    #5 0x563b4916be6a in plugin_initialize /10.4/sql/sql_plugin.cc:1437

    #6 0x563b4916d6d7 in plugin_init(int*, char**, int) /10.4/sql/sql_plugin.cc:1719

    #7 0x563b48ead3e7 in init_server_components /10.4/sql/mysqld.cc:5333

    #8 0x563b48eaf328 in mysqld_main(int, char**) /10.4/sql/mysqld.cc:5862

    #9 0x563b48e9945f in main /10.4/sql/main.cc:25

    #10 0x7fa60e2ee82f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f)

SUMMARY: AddressSanitizer: bad-free ??:0 operator delete(void*)

==32145==ABORTING

Attachments

Issue Links

duplicates

MDEV-13093 Leak of Datafile::m_crypt_info on shutdown after failed startup

Closed

Activity

Ascending order - Click to sort in descending order

Marko Mäkelä added a comment - 2019-01-28 09:48

alice, I cannot reproduce a crash in either 10.2 or 10.4. I even tried the 10.2 revision that you indicated: 37ffdb44ef96bacac8981cf180bb47be5da486df.
I used the following command:

ASAN_OPTIONS=abort_on_error=1,disable_coredump=0 ./mtr innodb.MDEV-18382

after writing the test case to that file.

You are posting an AddressSanitizer stack trace from "10.4". Which revision is that? Can you post the exact steps to reproduce?

Marko Mäkelä added a comment - 2019-01-28 09:48 alice , I cannot reproduce a crash in either 10.2 or 10.4. I even tried the 10.2 revision that you indicated: 37ffdb44ef96bacac8981cf180bb47be5da486df. I used the following command: ASAN_OPTIONS=abort_on_error=1,disable_coredump=0 ./mtr innodb.MDEV-18382 after writing the test case to that file. You are posting an AddressSanitizer stack trace from "10.4". Which revision is that? Can you post the exact steps to reproduce?

Alice Sherepa added a comment - 2019-01-28 10:05

10.2 built as -DPLUGIN_TOKUDB=NO -DCMAKE_BUILD_TYPE=Debug -DWITH_ASAN=ON

10.2 3fb6d2587d6498c50c82aac
2019-01-28 11:00:15 140389001128192 [ERROR] InnoDB: Data file './ibdata1' uses page size 16384, but the innodb_page_size start-up parameter is 4096
2019-01-28 11:00:15 140389001128192 [ERROR] InnoDB: Corrupted page [page id: space=0, page number=0] of datafile './ibdata1' could not be found in the doublewrite buffer.
2019-01-28 11:00:15 140389001128192 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1895] with error Generic error
2019-01-28 11:00:16 140389001128192 [ERROR] Plugin 'InnoDB' init function returned error.
2019-01-28 11:00:16 140389001128192 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.

I added 10.4 as I got it initially with rqg, but after that I could not get it, while I was tryiing to reproduce it. Currently, on 10.4 4007eaba91ace6f10a20df, built as -DPLUGIN_TOKUDB=NO -DCMAKE_BUILD_TYPE=Debug -DWITH_ASAN=ON I get:

2019-01-28 10:57:53 0 [ERROR] InnoDB: Data file './ibdata1' uses page size 16384, but the innodb_page_size start-up parameter is 4096

2019-01-28 10:57:53 0 [ERROR] InnoDB: Corrupted page [page id: space=0, page number=0] of datafile './ibdata1' could not be found in the doublewrite buffer.

2019-01-28 10:57:53 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1576] with error Generic error

2019-01-28 10:57:55 0 [ERROR] Plugin 'InnoDB' init function returned error.

2019-01-28 10:57:55 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.

Alice Sherepa added a comment - 2019-01-28 10:05 10.2 built as -DPLUGIN_TOKUDB=NO -DCMAKE_BUILD_TYPE=Debug -DWITH_ASAN=ON 10.2 3fb6d2587d6498c50c82aac 2019-01-28 11:00:15 140389001128192 [ERROR] InnoDB: Data file './ibdata1' uses page size 16384, but the innodb_page_size start-up parameter is 4096 2019-01-28 11:00:15 140389001128192 [ERROR] InnoDB: Corrupted page [page id: space=0, page number=0] of datafile './ibdata1' could not be found in the doublewrite buffer. 2019-01-28 11:00:15 140389001128192 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1895] with error Generic error 2019-01-28 11:00:16 140389001128192 [ERROR] Plugin 'InnoDB' init function returned error. 2019-01-28 11:00:16 140389001128192 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed. I added 10.4 as I got it initially with rqg, but after that I could not get it, while I was tryiing to reproduce it. Currently, on 10.4 4007eaba91ace6f10a20df, built as -DPLUGIN_TOKUDB=NO -DCMAKE_BUILD_TYPE=Debug -DWITH_ASAN=ON I get: 2019-01-28 10:57:53 0 [ERROR] InnoDB: Data file './ibdata1' uses page size 16384, but the innodb_page_size start-up parameter is 4096 2019-01-28 10:57:53 0 [ERROR] InnoDB: Corrupted page [page id: space=0, page number=0] of datafile './ibdata1' could not be found in the doublewrite buffer. 2019-01-28 10:57:53 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1576] with error Generic error 2019-01-28 10:57:55 0 [ERROR] Plugin 'InnoDB' init function returned error. 2019-01-28 10:57:55 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.

Marko Mäkelä added a comment - 2019-01-28 12:05

That InnoDB refuses to start up on invalid parameters is not a bug.
However, the claim about corrupted page is likely wrong, and we could also omit the redundant message about plugin initialization being aborted. Feel free to file separate bugs about that.

For this issue, I’d be interested in crash, like the bug title (and the stack trace in Description) claims.
(Note: Before 10.2, the entire server could crash on shutdown if InnoDB refused to start up. This explains most if not all occasional failures of the test innodb.doublewrite on 10.1. This is a known bug and not easily fixable in 10.1.)

Marko Mäkelä added a comment - 2019-01-28 12:05 That InnoDB refuses to start up on invalid parameters is not a bug. However, the claim about corrupted page is likely wrong, and we could also omit the redundant message about plugin initialization being aborted. Feel free to file separate bugs about that. For this issue, I’d be interested in crash, like the bug title (and the stack trace in Description) claims. (Note: Before 10.2, the entire server could crash on shutdown if InnoDB refused to start up. This explains most if not all occasional failures of the test innodb.doublewrite on 10.1. This is a known bug and not easily fixable in 10.1.)

Alice Sherepa added a comment - 2019-07-25 11:13

Got that crash again, seems not related to innodb_page_size.
10.4 17794fb9aac9ca4fcb0b1e5

2019-07-25 12:10:33 0 [ERROR] InnoDB: mmap(134217728 bytes) failed; errno 12

2019-07-25 12:10:33 0 [ERROR] InnoDB: Cannot allocate memory for the buffer pool

2019-07-25 12:10:33 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1516] with error Generic error

2019-07-25 12:10:33 0 [Note] InnoDB: Starting shutdown...

=================================================================

==13541==ERROR: AddressSanitizer: attempting free on address which was not malloc()-ed: 0x61c00000f8f0 in thread T0

    #0 0x7f56c7b67b2a in operator delete(void*) (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x99b2a)

    #1 0x1d16b25 in LatchCounter::~LatchCounter() /10.4/storage/innobase/include/sync0types.h:579

    #2 0x1d1b415 in LatchMeta<LatchCounter>::~LatchMeta() /10.4/storage/innobase/include/sync0types.h:758

    #3 0x1d163dd in sync_latch_meta_destroy /10.4/storage/innobase/sync/sync0debug.cc:1541

    #4 0x1d1682b in sync_check_close() /10.4/storage/innobase/sync/sync0debug.cc:1744

    #5 0x1cfe8bf in innodb_shutdown() /10.4/storage/innobase/srv/srv0start.cc:2534

    #6 0x1970d5c in innodb_init /10.4/storage/innobase/handler/ha_innodb.cc:4281

    #7 0x11064e9 in ha_initialize_handlerton(st_plugin_int*) /10.4/sql/handler.cc:557

    #8 0x9de248 in plugin_initialize /10.4/sql/sql_plugin.cc:1438

    #9 0x9dfac9 in plugin_init(int*, char**, int) /10.4/sql/sql_plugin.cc:1720

    #10 0x705f0e in init_server_components /10.4/sql/mysqld.cc:5203

    #11 0x707d4f in mysqld_main(int, char**) /10.4/sql/mysqld.cc:5726

    #12 0x6f2055 in main /10.4/sql/main.cc:25

    #13 0x7f56c573082f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f)

    #14 0x6f1f68 in _start (/10.4/sql/mysqld+0x6f1f68)

0x61c00000f8f0 is located 112 bytes inside of 1672-byte region [0x61c00000f880,0x61c00000ff08)

freed by thread T0 here:

    #0 0x7f56c7b662ca in __interceptor_free (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x982ca)

    #1 0x1e4cf20 in buf_pool_free(unsigned long) /10.4/storage/innobase/buf/buf0buf.cc:2178

    #2 0x1e4ce2d in buf_pool_init(unsigned long, unsigned long) /10.4/storage/innobase/buf/buf0buf.cc:2147

    #3 0x1cf984c in srv_start(bool) /10.4/storage/innobase/srv/srv0start.cc:1511

    #4 0x1970d48 in innodb_init /10.4/storage/innobase/handler/ha_innodb.cc:4278

    #5 0x11064e9 in ha_initialize_handlerton(st_plugin_int*) /10.4/sql/handler.cc:557

    #6 0x9de248 in plugin_initialize /10.4/sql/sql_plugin.cc:1438

    #7 0x9dfac9 in plugin_init(int*, char**, int) /10.4/sql/sql_plugin.cc:1720

    #8 0x705f0e in init_server_components /10.4/sql/mysqld.cc:5203

    #9 0x707d4f in mysqld_main(int, char**) /10.4/sql/mysqld.cc:5726

    #10 0x6f2055 in main /10.4/sql/main.cc:25

    #11 0x7f56c573082f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f)

previously allocated by thread T0 here:

    #0 0x7f56c7b6679a in __interceptor_calloc (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x9879a)

    #1 0x1e4cd9b in buf_pool_init(unsigned long, unsigned long) /10.4/storage/innobase/buf/buf0buf.cc:2136

    #2 0x1cf984c in srv_start(bool) /10.4/storage/innobase/srv/srv0start.cc:1511

    #3 0x1970d48 in innodb_init /10.4/storage/innobase/handler/ha_innodb.cc:4278

    #4 0x11064e9 in ha_initialize_handlerton(st_plugin_int*) /10.4/sql/handler.cc:557

    #5 0x9de248 in plugin_initialize /10.4/sql/sql_plugin.cc:1438

    #6 0x9dfac9 in plugin_init(int*, char**, int) /10.4/sql/sql_plugin.cc:1720

    #7 0x705f0e in init_server_components /10.4/sql/mysqld.cc:5203

    #8 0x707d4f in mysqld_main(int, char**) /10.4/sql/mysqld.cc:5726

    #9 0x6f2055 in main /10.4/sql/main.cc:25

    #10 0x7f56c573082f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f)

SUMMARY: AddressSanitizer: bad-free ??:0 operator delete(void*)

==13541==ABORTING

Alice Sherepa added a comment - 2019-07-25 11:13 Got that crash again, seems not related to innodb_page_size. 10.4 17794fb9aac9ca4fcb0b1e5 2019-07-25 12:10:33 0 [ERROR] InnoDB: mmap(134217728 bytes) failed; errno 12 2019-07-25 12:10:33 0 [ERROR] InnoDB: Cannot allocate memory for the buffer pool 2019-07-25 12:10:33 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1516] with error Generic error 2019-07-25 12:10:33 0 [Note] InnoDB: Starting shutdown... ================================================================= ==13541==ERROR: AddressSanitizer: attempting free on address which was not malloc()-ed: 0x61c00000f8f0 in thread T0 #0 0x7f56c7b67b2a in operator delete(void*) (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x99b2a) #1 0x1d16b25 in LatchCounter::~LatchCounter() /10.4/storage/innobase/include/sync0types.h:579 #2 0x1d1b415 in LatchMeta<LatchCounter>::~LatchMeta() /10.4/storage/innobase/include/sync0types.h:758 #3 0x1d163dd in sync_latch_meta_destroy /10.4/storage/innobase/sync/sync0debug.cc:1541 #4 0x1d1682b in sync_check_close() /10.4/storage/innobase/sync/sync0debug.cc:1744 #5 0x1cfe8bf in innodb_shutdown() /10.4/storage/innobase/srv/srv0start.cc:2534 #6 0x1970d5c in innodb_init /10.4/storage/innobase/handler/ha_innodb.cc:4281 #7 0x11064e9 in ha_initialize_handlerton(st_plugin_int*) /10.4/sql/handler.cc:557 #8 0x9de248 in plugin_initialize /10.4/sql/sql_plugin.cc:1438 #9 0x9dfac9 in plugin_init(int*, char**, int) /10.4/sql/sql_plugin.cc:1720 #10 0x705f0e in init_server_components /10.4/sql/mysqld.cc:5203 #11 0x707d4f in mysqld_main(int, char**) /10.4/sql/mysqld.cc:5726 #12 0x6f2055 in main /10.4/sql/main.cc:25 #13 0x7f56c573082f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f) #14 0x6f1f68 in _start (/10.4/sql/mysqld+0x6f1f68) 0x61c00000f8f0 is located 112 bytes inside of 1672-byte region [0x61c00000f880,0x61c00000ff08) freed by thread T0 here: #0 0x7f56c7b662ca in __interceptor_free (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x982ca) #1 0x1e4cf20 in buf_pool_free(unsigned long) /10.4/storage/innobase/buf/buf0buf.cc:2178 #2 0x1e4ce2d in buf_pool_init(unsigned long, unsigned long) /10.4/storage/innobase/buf/buf0buf.cc:2147 #3 0x1cf984c in srv_start(bool) /10.4/storage/innobase/srv/srv0start.cc:1511 #4 0x1970d48 in innodb_init /10.4/storage/innobase/handler/ha_innodb.cc:4278 #5 0x11064e9 in ha_initialize_handlerton(st_plugin_int*) /10.4/sql/handler.cc:557 #6 0x9de248 in plugin_initialize /10.4/sql/sql_plugin.cc:1438 #7 0x9dfac9 in plugin_init(int*, char**, int) /10.4/sql/sql_plugin.cc:1720 #8 0x705f0e in init_server_components /10.4/sql/mysqld.cc:5203 #9 0x707d4f in mysqld_main(int, char**) /10.4/sql/mysqld.cc:5726 #10 0x6f2055 in main /10.4/sql/main.cc:25 #11 0x7f56c573082f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f) previously allocated by thread T0 here: #0 0x7f56c7b6679a in __interceptor_calloc (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x9879a) #1 0x1e4cd9b in buf_pool_init(unsigned long, unsigned long) /10.4/storage/innobase/buf/buf0buf.cc:2136 #2 0x1cf984c in srv_start(bool) /10.4/storage/innobase/srv/srv0start.cc:1511 #3 0x1970d48 in innodb_init /10.4/storage/innobase/handler/ha_innodb.cc:4278 #4 0x11064e9 in ha_initialize_handlerton(st_plugin_int*) /10.4/sql/handler.cc:557 #5 0x9de248 in plugin_initialize /10.4/sql/sql_plugin.cc:1438 #6 0x9dfac9 in plugin_init(int*, char**, int) /10.4/sql/sql_plugin.cc:1720 #7 0x705f0e in init_server_components /10.4/sql/mysqld.cc:5203 #8 0x707d4f in mysqld_main(int, char**) /10.4/sql/mysqld.cc:5726 #9 0x6f2055 in main /10.4/sql/main.cc:25 #10 0x7f56c573082f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f) SUMMARY: AddressSanitizer: bad-free ??:0 operator delete(void*) ==13541==ABORTING

MariaDB Server

Server crashes upon shutdown after unsuccessful start with wrong innodb_page_size

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration