MariaDB reproducibility issue

OpenSubmitted by Josh.
Details
3 participants
  • Ludovic Courtès
  • Marius Bakke
  • Josh
Owner
unassigned
Severity
normal
J
(address . bug-guix@gnu.org)
f48564ea-f58e-41e1-a29d-faaa68ee1d8f@www.fastmail.com
Hi Guix,
I ran into this issue when building mariadb 10.1.38. I've attached the
last 300 lines of the log. Thanks
-SET INSERT_ID=2/*!*/;
-SET TIMESTAMP=1579609942/*!*/;
-insert into t1 values(null, "b")
-/*!*/;
-SET TIMESTAMP=1579609942/*!*/;
-COMMIT
-/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
@@ -680,11 +670,8 @@
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
ROLLBACK/*!*/;
-BEGIN
-/*!*/;
-SET INSERT_ID=3/*!*/;
use `test`/*!*/;
-SET TIMESTAMP=1579609944/*!*/;
+SET TIMESTAMP=1579609942/*!*/;
SET @@session.pseudo_thread_id=999999999/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
@@ -693,6 +680,30 @@
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
+create table t1 (a int auto_increment not null primary key, b char(3))
+/*!*/;
+BEGIN
+/*!*/;
+SET INSERT_ID=1/*!*/;
+SET TIMESTAMP=1579609942/*!*/;
+insert into t1 values(null, "a")
+/*!*/;
+SET TIMESTAMP=1579609942/*!*/;
+COMMIT
+/*!*/;
+BEGIN
+/*!*/;
+SET INSERT_ID=2/*!*/;
+SET TIMESTAMP=1579609942/*!*/;
+insert into t1 values(null, "b")
+/*!*/;
+SET TIMESTAMP=1579609942/*!*/;
+COMMIT
+/*!*/;
+BEGIN
+/*!*/;
+SET INSERT_ID=3/*!*/;
+SET TIMESTAMP=1579609944/*!*/;
insert into t1 values(null, "c")
/*!*/;
SET TIMESTAMP=1579609944/*!*/;
@@ -747,37 +758,6 @@
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
-ROLLBACK/*!*/;
-use `test`/*!*/;
-SET TIMESTAMP=1579609942/*!*/;
-SET @@session.pseudo_thread_id=999999999/*!*/;
-SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
-SET @@session.sql_mode=0/*!*/;
-SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
-/*!\C latin1 *//*!*/;
-SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
-SET @@session.lc_time_names=0/*!*/;
-SET @@session.collation_database=DEFAULT/*!*/;
-create table t1 (a int auto_increment not null primary key, b char(3))
-/*!*/;
-BEGIN
-/*!*/;
-SET INSERT_ID=1/*!*/;
-SET TIMESTAMP=1579609942/*!*/;
-insert into t1 values(null, "a")
-/*!*/;
-SET TIMESTAMP=1579609942/*!*/;
-COMMIT
-/*!*/;
-BEGIN
-/*!*/;
-SET INSERT_ID=2/*!*/;
-SET TIMESTAMP=1579609942/*!*/;
-insert into t1 values(null, "b")
-/*!*/;
-SET TIMESTAMP=1579609942/*!*/;
-COMMIT
-/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
@@ -1040,11 +1020,8 @@
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
ROLLBACK/*!*/;
-BEGIN
-/*!*/;
-SET INSERT_ID=3/*!*/;
use `test`/*!*/;
-SET TIMESTAMP=1579609944/*!*/;
+SET TIMESTAMP=1579609942/*!*/;
SET @@session.pseudo_thread_id=999999999/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
@@ -1053,6 +1030,30 @@
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
+create table t1 (a int auto_increment not null primary key, b char(3))
+/*!*/;
+BEGIN
+/*!*/;
+SET INSERT_ID=1/*!*/;
+SET TIMESTAMP=1579609942/*!*/;
+insert into t1 values(null, "a")
+/*!*/;
+SET TIMESTAMP=1579609942/*!*/;
+COMMIT
+/*!*/;
+BEGIN
+/*!*/;
+SET INSERT_ID=2/*!*/;
+SET TIMESTAMP=1579609942/*!*/;
+insert into t1 values(null, "b")
+/*!*/;
+SET TIMESTAMP=1579609942/*!*/;
+COMMIT
+/*!*/;
+BEGIN
+/*!*/;
+SET INSERT_ID=3/*!*/;
+SET TIMESTAMP=1579609944/*!*/;
insert into t1 values(null, "c")
/*!*/;
SET TIMESTAMP=1579609944/*!*/;
@@ -1087,37 +1088,6 @@
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
-ROLLBACK/*!*/;
-use `test`/*!*/;
-SET TIMESTAMP=1579609942/*!*/;
-SET @@session.pseudo_thread_id=999999999/*!*/;
-SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
-SET @@session.sql_mode=0/*!*/;
-SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
-/*!\C latin1 *//*!*/;
-SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
-SET @@session.lc_time_names=0/*!*/;
-SET @@session.collation_database=DEFAULT/*!*/;
-create table t1 (a int auto_increment not null primary key, b char(3))
-/*!*/;
-BEGIN
-/*!*/;
-SET INSERT_ID=1/*!*/;
-SET TIMESTAMP=1579609942/*!*/;
-insert into t1 values(null, "a")
-/*!*/;
-SET TIMESTAMP=1579609942/*!*/;
-COMMIT
-/*!*/;
-BEGIN
-/*!*/;
-SET INSERT_ID=2/*!*/;
-SET TIMESTAMP=1579609942/*!*/;
-insert into t1 values(null, "b")
-/*!*/;
-SET TIMESTAMP=1579609942/*!*/;
-COMMIT
-/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
@@ -1443,11 +1413,8 @@
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
ROLLBACK/*!*/;
-BEGIN
-/*!*/;
-SET INSERT_ID=3/*!*/;
use `test`/*!*/;
-SET TIMESTAMP=1579609944/*!*/;
+SET TIMESTAMP=1579609942/*!*/;
SET @@session.pseudo_thread_id=999999999/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
@@ -1456,6 +1423,30 @@
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
+create table t1 (a int auto_increment not null primary key, b char(3))
+/*!*/;
+BEGIN
+/*!*/;
+SET INSERT_ID=1/*!*/;
+SET TIMESTAMP=1579609942/*!*/;
+insert into t1 values(null, "a")
+/*!*/;
+SET TIMESTAMP=1579609942/*!*/;
+COMMIT
+/*!*/;
+BEGIN
+/*!*/;
+SET INSERT_ID=2/*!*/;
+SET TIMESTAMP=1579609942/*!*/;
+insert into t1 values(null, "b")
+/*!*/;
+SET TIMESTAMP=1579609942/*!*/;
+COMMIT
+/*!*/;
+BEGIN
+/*!*/;
+SET INSERT_ID=3/*!*/;
+SET TIMESTAMP=1579609944/*!*/;
insert into t1 values(null, "c")
/*!*/;
SET TIMESTAMP=1579609944/*!*/;
@@ -1510,37 +1501,6 @@
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
-ROLLBACK/*!*/;
-use `test`/*!*/;
-SET TIMESTAMP=1579609942/*!*/;
-SET @@session.pseudo_thread_id=999999999/*!*/;
-SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
-SET @@session.sql_mode=0/*!*/;
-SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
-/*!\C latin1 *//*!*/;
-SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
-SET @@session.lc_time_names=0/*!*/;
-SET @@session.collation_database=DEFAULT/*!*/;
-create table t1 (a int auto_increment not null primary key, b char(3))
-/*!*/;
-BEGIN
-/*!*/;
-SET INSERT_ID=1/*!*/;
-SET TIMESTAMP=1579609942/*!*/;
-insert into t1 values(null, "a")
-/*!*/;
-SET TIMESTAMP=1579609942/*!*/;
-COMMIT
-/*!*/;
-BEGIN
-/*!*/;
-SET INSERT_ID=2/*!*/;
-SET TIMESTAMP=1579609942/*!*/;
-insert into t1 values(null, "b")
-/*!*/;
-SET TIMESTAMP=1579609942/*!*/;
-COMMIT
-/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;

mysqltest: Result length mismatch

safe_process[22541]: Got signal 17, child_pid: 22542
safe_process[22541]: Killing child: 22542
safe_process[22541]: Child exit: 1

- saving '/tmp/guix-build-mariadb-10.1.38.drv-0/build/mysql-test/var/2/log/binlog.binlog_mysqlbinlog2-mix/' to '/tmp/guix-build-mariadb-10.1.38.drv-0/build/mysql-test/var/log/binlog.binlog_mysqlbinlog2-mix/'
worker[2] > Stopping all servers...

Only 2357 of 6894 completed.
--------------------------------------------------------------------------
The servers were restarted 504 times
Spent 1764.770 of 874 seconds executing testcases

Failure: Failed 1/1034 tests, 99.90% were successful.

Failing test(s): binlog.binlog_mysqlbinlog2

The log files in var/log may give you some hint of what went wrong.

If you want to report this error, please read first the documentation

484 tests were skipped, 72 by the test itself.

mysql-test-run: *** ERROR: there were failing test cases
Backtrace:
6 (primitive-load "/gnu/store/yzksam4xs36zdhicldvmdd42gvr…")
In ice-9/eval.scm:
191:35 5 (_ _)
In srfi/srfi-1.scm:
863:16 4 (every1 #<procedure 91ce40 at /gnu/store/6bwkbm3a80v0x…> …)
In /gnu/store/6bwkbm3a80v0xab5qsicij7bjvmn5yna-module-import/guix/build/gnu-build-system.scm:
799:28 3 (_ _)
In ice-9/eval.scm:
619:8 2 (_ #(#(#<directory (guile-user) 5ce140>) #t))
In ice-9/boot-9.scm:
142:2 1 (dynamic-wind #<procedure 5637e0 at ice-9/eval.scm:330…> …)
In /gnu/store/6bwkbm3a80v0xab5qsicij7bjvmn5yna-module-import/guix/build/utils.scm:
616:6 0 (invoke _ . _)

/gnu/store/6bwkbm3a80v0xab5qsicij7bjvmn5yna-module-import/guix/build/utils.scm:616:6: In procedure invoke:
Throw to key `srfi-34' with args `(#<condition &invoke-error [program: "./mtr" arguments: ("--verbose" "--retry=3" "--testcase-timeout=40" "--suite-timeout=600" "--parallel" "4" "--skip-test-list=unstable-tests") exit-status: 1 term-signal: #f stop-signal: #f] 5d2640>)'.
M
M
Marius Bakke wrote on 27 Jan 2020 20:21
87pnf4so1u.fsf@devup.no
Josh <randomenduser@fastmail.com> writes:

Toggle quote (5 lines)
> Hi Guix,
>
> I ran into this issue when building mariadb 10.1.38. I've attached the
> last 300 lines of the log. Thanks

I can reproduce this failure by checking out Guix 1.0.1 in a "time
machine" and trying to build MariaDB. The problem is that the failing test
expects the current time to be earlier than 2020-01-21 15:32:22.

This was properly fixed in 10.1.39[0], at least until the year 2038.

Unfortunately there is little we can do about it now. If you are
hitting this problem while trying to install Guix 1.0.1, I recommend to
either:

1) enable binary substitutes
2) set the system clock to some time last year while building MariaDB
3) install a minimal configuration that does not pull in MariaDB, and
reconfigure with the "full" configuration once you have 'guix pull'd.

Will that work for you?

Thanks for the report, and sorry for the inconvenience!

-----BEGIN PGP SIGNATURE-----

iQEzBAEBCgAdFiEEu7At3yzq9qgNHeZDoqBt8qM6VPoFAl4vOD0ACgkQoqBt8qM6
VPonoQgAknVOpA2VHfuWo6rwOf1WNARc7PyknReSwZ70yM/+LDRbeCeiFVha1acx
C3GGv/VDLluQV86+JvOcK52LZsPam/N53aUAeXPCnMyZzH5pQTlmJ3emHWJqUsYp
Whq5nItaVbba7OinKSSBKjTWlDxf7NIQGhISg5Va/3vAvjs2SXgv1Q2xRg6NiqH1
Bok8iQl9ULPZD7p2O14XH+pxxxtjN2lbYOIjOZtviZiNWI3nRKnyG2hHA6vyDCpZ
nS5o9E/JZ9FJuKd99yNyB10hkO4uTb7S5A1JV02IsAufjNjUwI08i7j6lq6wMsLi
l2BBJrpo9KZAUohxk7QtzhuqOml9Dw==
=ItLZ
-----END PGP SIGNATURE-----

L
L
Ludovic Courtès wrote on 24 Jan 2021 17:12
(name . Marius Bakke)(address . mbakke@fastmail.com)
87k0s271qx.fsf@gnu.org
Hi!

Marius Bakke <mbakke@fastmail.com> skribis:

Toggle quote (11 lines)
> Josh <randomenduser@fastmail.com> writes:
>
>> Hi Guix,
>>
>> I ran into this issue when building mariadb 10.1.38. I've attached the
>> last 300 lines of the log. Thanks
>
> I can reproduce this failure by checking out Guix 1.0.1 in a "time
> machine" and trying to build MariaDB. The problem is that the failing test
> expects the current time to be earlier than 2020-01-21 15:32:22.

I was trying to run:

guix time-machine --commit=0791437 -- build mariadb

where commit 0791437f972caa7e48de91ad5cb150a614f617c2 is from Jan. 2019,
and stumbled upon the test failure that Josh reported.

Following your advice on IRC, Marius, I built that derivation,
/gnu/store/p2d7i5258vi0rd9ydbpr9c1vb3sxcz6h-mariadb-10.1.37.drv, on a
machine whose clocked I had switched back to 2018… and it worked!

(I used one of the berlin build machines, so now there are substitutes
for this particular derivation.)

Thanks!

Ludo’.
?