http://buildbot.askmonty.org/buildbot/builders/qa-kvm-linux/builds/1658/steps/stable_tests/logs/stdio
tokudb_bugs.xa-3 'innodb' w2 [ fail ]
|
Test ended at 2017-07-05 13:24:51
|
|
CURRENT_TEST: tokudb_bugs.xa-3
|
|
|
Server [mysqld.1 - pid: 2997, winpid: 2997, exit: 256] failed during test run
|
Server log from this test:
|
----------SERVER LOG START-----------
|
SIGKILL myself
|
2017-07-05 13:24:49 140090411992896 [Note] /home/buildbot/build/sql/mysqld (mysqld 10.2.7-MariaDB-debug-log) starting as process 2998 ...
|
2017-07-05 13:24:49 140090411992896 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
|
2017-07-05 13:24:49 140090411992896 [Note] Plugin 'SEQUENCE' is disabled.
|
Wed Jul 5 13:24:49 2017 PerconaFT recovery starting in env /home/buildbot/build/mysql-test/var/2/mysqld.1/data/
|
Wed Jul 5 13:24:49 2017 PerconaFT recovery scanning backward from 545
|
Wed Jul 5 13:24:49 2017 PerconaFT recovery bw_end_checkpoint at 12 timestamp 1499275474701350 xid 8 (bw_newer)
|
Wed Jul 5 13:24:49 2017 PerconaFT recovery bw_begin_checkpoint at 8 timestamp 1499275474700634 (bw_between)
|
Wed Jul 5 13:24:49 2017 PerconaFT recovery turning around at begin checkpoint 8 time 716
|
Wed Jul 5 13:24:49 2017 PerconaFT recovery starts scanning forward to 545 from 8 left 537 (fw_between)
|
Wed Jul 5 13:24:49 2017 PerconaFT recovery closing 2 dictionaries
|
Wed Jul 5 13:24:49 2017 PerconaFT recovery making a checkpoint
|
Wed Jul 5 13:24:49 2017 PerconaFT recovery done
|
2017-07-05 13:24:49 140090411992896 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
|
2017-07-05 13:24:49 140090411992896 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
2017-07-05 13:24:49 140090411992896 [Note] InnoDB: Uses event mutexes
|
2017-07-05 13:24:49 140090411992896 [Note] InnoDB: Compressed tables use zlib 1.2.8
|
2017-07-05 13:24:49 140090411992896 [Note] InnoDB: Using Linux native AIO
|
2017-07-05 13:24:49 140090411992896 [Note] InnoDB: Number of pools: 1
|
2017-07-05 13:24:49 140090411992896 [Note] InnoDB: Using generic crc32 instructions
|
2017-07-05 13:24:49 140090411992896 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
|
2017-07-05 13:24:49 140090411992896 [Note] InnoDB: Completed initialization of buffer pool
|
2017-07-05 13:24:49 140089241872128 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
|
2017-07-05 13:24:49 140090411992896 [Note] InnoDB: Highest supported file format is Barracuda.
|
2017-07-05 13:24:49 140090411992896 [Note] InnoDB: Starting crash recovery from checkpoint LSN=2785956
|
2017-07-05 13:24:49 140090411992896 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 14, since the redo log references ./test/t1.ibd with space ID 7.
|
2017-07-05 13:24:49 140090411992896 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 14, since the redo log references ./test/t1.ibd with space ID 13.
|
2017-07-05 13:24:49 140090411992896 [Note] InnoDB: Starting a batch to recover 179 pages from redo log.
|
mysqld: /home/buildbot/build/storage/innobase/mtr/mtr0mtr.cc:603: void mtr_t::commit_checkpoint(lsn_t, bool): Assertion `!recv_no_log_write' failed.
|
170705 13:24:50 [ERROR] mysqld got signal 6 ;
|
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.2.7-MariaDB-debug-log
|
key_buffer_size=1048576
|
read_buffer_size=131072
|
max_used_connections=0
|
max_threads=153
|
thread_count=0
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63068 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...
|
stack_bottom = 0x0 thread_stack 0x49000
|
/home/buildbot/build/sql/mysqld(my_print_stacktrace+0x38)[0x7f6956b6c3c8]
|
/home/buildbot/build/sql/mysqld(handle_fatal_signal+0x3a3)[0x7f6956404810]
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf890)[0x7f69557bd890]
|
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7f6953af3067]
|
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7f6953af4448]
|
/lib/x86_64-linux-gnu/libc.so.6(+0x2e266)[0x7f6953aec266]
|
/lib/x86_64-linux-gnu/libc.so.6(+0x2e312)[0x7f6953aec312]
|
/home/buildbot/build/sql/mysqld(+0xac51ae)[0x7f69566b31ae]
|
/home/buildbot/build/sql/mysqld(+0xd21f62)[0x7f695690ff62]
|
/home/buildbot/build/sql/mysqld(+0xab8f30)[0x7f69566a6f30]
|
/home/buildbot/build/sql/mysqld(+0xbcef01)[0x7f69567bcf01]
|
/home/buildbot/build/sql/mysqld(+0xa0f039)[0x7f69565fd039]
|
/home/buildbot/build/sql/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0xfc)[0x7f6956406849]
|
mysys/stacktrace.c:267(my_print_stacktrace)[0x7f69561b14f8]
|
/home/buildbot/build/sql/mysqld(_Z11plugin_initPiPPci+0x912)[0x7f69561b2101]
|
sql/signal_handler.cc:168(handle_fatal_signal)[0x7f69560bef35]
|
/home/buildbot/build/sql/mysqld(_Z11mysqld_mainiPPc+0x5f4)[0x7f69560bffba]
|
fil/fil0fil.cc:6580(fil_names_clear(unsigned long, bool))[0x7f69560b4ee0]
|
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5)[0x7f6953adfb45]
|
log/log0recv.cc:3351(recv_recovery_from_checkpoint_start(unsigned long))[0x7f69560b4db9]
|
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
|
----------SERVER LOG END-------------
|
mysqltest failed but provided no output
|
The result from queries just before the failure was:
|
< snip >
|
drop table if exists t1, t2;
|
CREATE TABLE t1 (a INT PRIMARY KEY) ENGINE=innodb;
|
CREATE TABLE t2 (b INT PRIMARY KEY) ENGINE=tokudb;
|
BEGIN;
|
SELECT @@log_bin;
|
@@log_bin
|
0
|
INSERT INTO t1 VALUES (1);
|
INSERT INTO t2 VALUES (2);
|
SET SESSION debug_dbug="d,crash_commit_before";
|
COMMIT;
|
ERROR HY000: Lost connection to MySQL server during query
|
|
|
|
- saving '/home/buildbot/build/mysql-test/var/2/log/tokudb_bugs.xa-3-innodb/' to '/home/buildbot/build/mysql-test/var/log/tokudb_bugs.xa-3-innodb/'
|
worker[2] > Restart - not started
|
***Warnings generated in error logs during shutdown after running tests: tokudb_bugs.xa-3
|
I also had the same assertion failure with tokudb_bugs.xa-4 on a local debug build.
{"report":{"fcp":2886.5999999046326,"ttfb":1387.2999999523163,"pageVisibility":"visible","entityId":62186,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":32,"apdex":0.5,"journeyId":"85917ba0-5c04-4a06-97fa-8caf6be68104","navigationType":0,"readyForUser":3058.2999999523163,"redirectCount":0,"resourceLoadedEnd":3512.2999999523163,"resourceLoadedStart":1402.5999999046326,"resourceTiming":[{"duration":708.1000001430511,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":1402.5999999046326,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":1402.5999999046326,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":2110.7000000476837,"responseStart":0,"secureConnectionStart":0},{"duration":708.0999999046326,"initiatorType":"link","name":"https://jira.mariadb.org/s/7ebd35e77e471bc30ff0eba799ebc151-CDN/lu2cib/820016/12ta74/494e4c556ecbb29f90a3d3b4f09cb99c/_/download/contextbatch/css/jira.browse.project,project.issue.navigator,jira.view.issue,jira.general,jira.global,atl.general,-_super/batch.css?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&slack-enabled=true&whisper-enabled=true","startTime":1403,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":1403,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":2111.0999999046326,"responseStart":0,"secureConnectionStart":0},{"duration":745,"initiatorType":"script","name":"https://jira.mariadb.org/s/0917945aaa57108d00c5076fea35e069-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":1403.2000000476837,"connectEnd":1403.2000000476837,"connectStart":1403.2000000476837,"domainLookupEnd":1403.2000000476837,"domainLookupStart":1403.2000000476837,"fetchStart":1403.2000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":1403.2000000476837,"responseEnd":2148.2000000476837,"responseStart":2148.2000000476837,"secureConnectionStart":1403.2000000476837},{"duration":983.7999999523163,"initiatorType":"script","name":"https://jira.mariadb.org/s/2d8175ec2fa4c816e8023260bd8c1786-CDN/lu2cib/820016/12ta74/494e4c556ecbb29f90a3d3b4f09cb99c/_/download/contextbatch/js/jira.browse.project,project.issue.navigator,jira.view.issue,jira.general,jira.global,atl.general,-_super/batch.js?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&locale=en&slack-enabled=true&whisper-enabled=true","startTime":1403.7999999523163,"connectEnd":1403.7999999523163,"connectStart":1403.7999999523163,"domainLookupEnd":1403.7999999523163,"domainLookupStart":1403.7999999523163,"fetchStart":1403.7999999523163,"redirectEnd":0,"redirectStart":0,"requestStart":1403.7999999523163,"responseEnd":2387.5999999046326,"responseStart":2387.5999999046326,"secureConnectionStart":1403.7999999523163},{"duration":988.1000001430511,"initiatorType":"script","name":"https://jira.mariadb.org/s/a9324d6758d385eb45c462685ad88f1d-CDN/lu2cib/820016/12ta74/c92c0caa9a024ae85b0ebdbed7fb4bd7/_/download/contextbatch/js/atl.global,-_super/batch.js?locale=en","startTime":1404.0999999046326,"connectEnd":1404.0999999046326,"connectStart":1404.0999999046326,"domainLookupEnd":1404.0999999046326,"domainLookupStart":1404.0999999046326,"fetchStart":1404.0999999046326,"redirectEnd":0,"redirectStart":0,"requestStart":1404.0999999046326,"responseEnd":2392.2000000476837,"responseStart":2392.2000000476837,"secureConnectionStart":1404.0999999046326},{"duration":989.2000000476837,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-en/jira.webresources:calendar-en.js","startTime":1404.2000000476837,"connectEnd":1404.2000000476837,"connectStart":1404.2000000476837,"domainLookupEnd":1404.2000000476837,"domainLookupStart":1404.2000000476837,"fetchStart":1404.2000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":1404.2000000476837,"responseEnd":2393.4000000953674,"responseStart":2393.4000000953674,"secureConnectionStart":1404.2000000476837},{"duration":990.1000001430511,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-localisation-moment/jira.webresources:calendar-localisation-moment.js","startTime":1404.2999999523163,"connectEnd":1404.2999999523163,"connectStart":1404.2999999523163,"domainLookupEnd":1404.2999999523163,"domainLookupStart":1404.2999999523163,"fetchStart":1404.2999999523163,"redirectEnd":0,"redirectStart":0,"requestStart":1404.2999999523163,"responseEnd":2394.4000000953674,"responseStart":2394.4000000953674,"secureConnectionStart":1404.2999999523163},{"duration":1000.2000000476837,"initiatorType":"link","name":"https://jira.mariadb.org/s/b04b06a02d1959df322d9cded3aeecc1-CDN/lu2cib/820016/12ta74/a2ff6aa845ffc9a1d22fe23d9ee791fc/_/download/contextbatch/css/jira.global.look-and-feel,-_super/batch.css","startTime":1404.5999999046326,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":1404.5999999046326,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":2404.7999999523163,"responseStart":0,"secureConnectionStart":0},{"duration":991.1000001430511,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":1404.5999999046326,"connectEnd":1404.5999999046326,"connectStart":1404.5999999046326,"domainLookupEnd":1404.5999999046326,"domainLookupStart":1404.5999999046326,"fetchStart":1404.5999999046326,"redirectEnd":0,"redirectStart":0,"requestStart":1404.5999999046326,"responseEnd":2395.7000000476837,"responseStart":2395.7000000476837,"secureConnectionStart":1404.5999999046326},{"duration":1000.2000000476837,"initiatorType":"link","name":"https://jira.mariadb.org/s/3ac36323ba5e4eb0af2aa7ac7211b4bb-CDN/lu2cib/820016/12ta74/d176f0986478cc64f24226b3d20c140d/_/download/contextbatch/css/com.atlassian.jira.projects.sidebar.init,-_super,-project.issue.navigator,-jira.view.issue/batch.css?jira.create.linked.issue=true","startTime":1404.7999999523163,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":1404.7999999523163,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":2405,"responseStart":0,"secureConnectionStart":0},{"duration":992.6000001430511,"initiatorType":"script","name":"https://jira.mariadb.org/s/5d5e8fe91fbc506585e83ea3b62ccc4b-CDN/lu2cib/820016/12ta74/d176f0986478cc64f24226b3d20c140d/_/download/contextbatch/js/com.atlassian.jira.projects.sidebar.init,-_super,-project.issue.navigator,-jira.view.issue/batch.js?jira.create.linked.issue=true&locale=en","startTime":1405.0999999046326,"connectEnd":1405.0999999046326,"connectStart":1405.0999999046326,"domainLookupEnd":1405.0999999046326,"domainLookupStart":1405.0999999046326,"fetchStart":1405.0999999046326,"redirectEnd":0,"redirectStart":0,"requestStart":1405.0999999046326,"responseEnd":2397.7000000476837,"responseStart":2397.7000000476837,"secureConnectionStart":1405.0999999046326},{"duration":1817.7999999523163,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-js/jira.webresources:bigpipe-js.js","startTime":1420.2999999523163,"connectEnd":1420.2999999523163,"connectStart":1420.2999999523163,"domainLookupEnd":1420.2999999523163,"domainLookupStart":1420.2999999523163,"fetchStart":1420.2999999523163,"redirectEnd":0,"redirectStart":0,"requestStart":1420.2999999523163,"responseEnd":3238.0999999046326,"responseStart":3238.0999999046326,"secureConnectionStart":1420.2999999523163},{"duration":2090.7000000476837,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-init/jira.webresources:bigpipe-init.js","startTime":1421.5999999046326,"connectEnd":1421.5999999046326,"connectStart":1421.5999999046326,"domainLookupEnd":1421.5999999046326,"domainLookupStart":1421.5999999046326,"fetchStart":1421.5999999046326,"redirectEnd":0,"redirectStart":0,"requestStart":1421.5999999046326,"responseEnd":3512.2999999523163,"responseStart":3512.2999999523163,"secureConnectionStart":1421.5999999046326},{"duration":844.7999999523163,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":2327.9000000953674,"connectEnd":2327.9000000953674,"connectStart":2327.9000000953674,"domainLookupEnd":2327.9000000953674,"domainLookupStart":2327.9000000953674,"fetchStart":2327.9000000953674,"redirectEnd":0,"redirectStart":0,"requestStart":2327.9000000953674,"responseEnd":3172.7000000476837,"responseStart":3172.7000000476837,"secureConnectionStart":2327.9000000953674},{"duration":664.7999999523163,"initiatorType":"script","name":"https://www.google-analytics.com/analytics.js","startTime":2876.7999999523163,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":2876.7999999523163,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":3541.5999999046326,"responseStart":0,"secureConnectionStart":0}],"fetchStart":1,"domainLookupStart":1,"domainLookupEnd":1,"connectStart":1,"connectEnd":1,"requestStart":924,"responseStart":1388,"responseEnd":1422,"domLoading":1398,"domInteractive":3546,"domContentLoadedEventStart":3546,"domContentLoadedEventEnd":3653,"domComplete":4350,"loadEventStart":4350,"loadEventEnd":4351,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":3516.5},{"name":"bigPipe.sidebar-id.end","time":3517.7000000476837},{"name":"bigPipe.activity-panel-pipe-id.start","time":3518.5},{"name":"bigPipe.activity-panel-pipe-id.end","time":3520.2000000476837},{"name":"activityTabFullyLoaded","time":3682.9000000953674}],"measures":[],"correlationId":"bf3055fd1b89d1","effectiveType":"4g","downlink":9.3,"rtt":0,"serverDuration":96,"dbReadsTimeInMs":10,"dbConnsTimeInMs":19,"applicationHash":"9d11dbea5f4be3d4cc21f03a88dd11d8c8687422","experiments":[]}}
Bug
Major
There were no server logs for the reported failure. Luckily, I ran into this very same assertion failure when testing a merge into 10.3 locally. For me, it failed for two tests that performed InnoDB crash recovery:
innodb.innodb-alter-tempfile
gcol.gcol_rollback
In all the 3 crashes (the first test also with innodb_page_size=4k), the stack trace was like this:
#8 0x000055fa2f7d41f6 in mtr_t::commit_checkpoint (this=0x7ffe265635f0,checkpoint_lsn=732924, write_mlog_checkpoint=true)at /mariadb/10.3/storage/innobase/mtr/mtr0mtr.cc:603#9 0x000055fa2fa5ab92 in fil_names_clear (lsn=732924, do_write=true)at /mariadb/10.3/storage/innobase/fil/fil0fil.cc:6580#10 0x000055fa2f7c6396 in recv_recovery_from_checkpoint_start (flush_lsn=732225) at /mariadb/10.3/storage/innobase/log/log0recv.cc:3412#11 0x000055fa2f8f2d99 in innobase_start_or_create_for_mysql ()at /mariadb/10.3/storage/innobase/srv/srv0start.cc:2197When it comes to the MariaDB server, this is a bogus debug assertion failure. While generating page-change redo log records is strictly out of the question during tat certain parts of crash recovery, the fil_names_clear() is only emitting informational MLOG_FILE_NAME records to guarantee that if the server is killed during or soon after the crash recovery, the subsequent crash recovery will succeed.
The metadata buffer that fil_names_clear() is flushing to the redo log is being filled by recv_init_crash_recovery_spaces(), right before starting to apply redo log, by invoking fil_names_dirty() on every dirty tablespace that was found.
When it comes to Mariabackup (xtrabackup --prepare), it is strictly out of the question to generate any redo log whatsoever, because that could break the restore of incremental backups by causing LSN deviation. So, the fil_names_dirty() call must be skipped when restoring backups.