[#MDEV-28188] Database initialization commands can be written into binary log with Docker

Comment by Daniel Black [ 2022-03-29 ]

10.2.41
$ podman run --rm --env MARIADB_ROOT_PASSWORD=bob --name m102 mariadb:10.2 --log-bin
2022-03-29 01:52:42+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.2.41+maria~bionic started.
2022-03-29 01:52:42+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2022-03-29 01:52:42+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.2.41+maria~bionic started.
2022-03-29 01:52:42+00:00 [Note] [Entrypoint]: Initializing database files
2022-03-29 1:52:42 139975221388992 [Warning] No argument was provided to --log-bin and neither --log-basename or --log-bin-index where used; This may cause repliction to break when this server acts as a master and has its hostname changed! Please use '--log-basename=5270321299e5' or '--log-bin=mysqld-bin' to avoid this problem.
2022-03-29 1:52:42 139975064966912 [Warning] Failed to load slave replication state from table mysql.gtid_slave_pos: 1146: Table 'mysql.gtid_slave_pos' doesn't exist
...

$ podman exec m102 mysqlbinlog /var/lib/mysql/mysqld-bin.000001 \| more
/!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1/;
/!40019 SET @@session.max_insert_delayed_threads=0/;
/!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0/;
DELIMITER /!/;
# at 4
#220329 1:52:42 server id 1 end_log_pos 256 CRC32 0x9d05935e Start: binlog v 4, server v 10.2.41-MariaDB-1:10.2.41+maria~bionic-log created 220329 1:52:42 a
t startup
ROLLBACK/!/;
BINLOG '
amZCYg8BAAAA/AAAAAABAAAAAAQAMTAuMi40MS1NYXJpYURCLTE6MTAuMi40MSttYXJpYX5iaW9u
aWMtbG9nAAAAAAAAAABqZkJiEzgNAAgAEgAEBAQEEgAA5AAEGggAAAAICAgCAAAACgoKAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAEEwQADQgICAoKCgFekwWd
'/!/;
# at 256
#220329 1:52:42 server id 1 end_log_pos 285 CRC32 0xb51dc449 Gtid list []
# at 285
#220329 1:52:42 server id 1 end_log_pos 329 CRC32 0x81d7e607 Binlog checkpoint mysqld-bin.000001
# at 329
#220329 1:52:42 server id 1 end_log_pos 371 CRC32 0x0959e18f GTID 0-1-1 ddl
/!100101 SET @@session.skip_parallel_replication=0//!/;
/!100001 SET @@session.gtid_domain_id=0//!/;
/!100001 SET @@session.server_id=1//!/;
/!100001 SET @@session.gtid_seq_no=1//!/;
# at 371
#220329 1:52:42 server id 1 end_log_pos 475 CRC32 0xcb785691 Query thread_id=7 exec_time=0 error_code=0
SET TIMESTAMP=1648518762/!/;
SET @@session.pseudo_thread_id=7/!/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1, @@session.check_constraint_checks=1/!/;
SET @@session.sql_mode=1411383296/!/;
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 database if not exists mysql;

The container is using --skip-log-bin as a mysql_install_db argument, which should be passed to mysqld directly.

So it looks like the the skip-log-bin argument isn't taking precidence over earlier args, or configuration file options.

Comment by Daniel Black [ 2022-03-29 ]

10.2.43
$ podman run --rm --env MARIADB_ROOT_PASSWORD=bob --name m102 mariadb:10.2 --log-bin
2022-03-29 02:03:07+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.2.43+maria~bionic started.
2022-03-29 02:03:07+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2022-03-29 02:03:07+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.2.43+maria~bionic started.
2022-03-29 02:03:07+00:00 [Note] [Entrypoint]: Initializing database files


PLEASE REMEMBER TO SET A PASSWORD FOR THE MariaDB root USER !
To do so, start the server, then issue the following command:

'/usr/bin/mysql_secure_installation'

which will also give you the option of removing the test
databases and anonymous user created by default. This is
strongly recommended for production servers.

See the MariaDB Knowledgebase at http://mariadb.com/kb

Please report any problems at http://mariadb.org/jira

The latest information about MariaDB is available at http://mariadb.org/.

Consider joining MariaDB's strong and vibrant community:
https://mariadb.org/get-involved/

2022-03-29 02:03:09+00:00 [Note] [Entrypoint]: Database files initialized
2022-03-29 02:03:09+00:00 [Note] [Entrypoint]: Starting temporary server
2022-03-29 02:03:09+00:00 [Note] [Entrypoint]: Waiting for server startup
2022-03-29 2:03:09 140241407575744 [Note] mysqld (mysqld 10.2.43-MariaDB-1:10.2.43+maria~bionic-log) starting as process 111 ...
2022-03-29 2:03:09 140241407575744 [Warning] No argument was provided to --log-bin and neither --log-basename or --log-bin-index where used; This may cause repliction to break when this server acts as a master and has its hostname changed! Please use '--log-basename=40682046b7a1' or '--log-b
....

$ podman exec m102 mysqlbinlog /var/lib/mysql/mysqld-bin.000001 \| more
/!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1/;
/!40019 SET @@session.max_insert_delayed_threads=0/;
/!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0/;
DELIMITER /!/;
# at 4
#220329 2:03:09 server id 1 end_log_pos 256 CRC32 0x9d5d1183 Start: binlog v 4, server v 10.2.43-MariaDB-1:10.2.43+maria~bionic-log created 220329 2:03:09 a
t startup
ROLLBACK/!/;
BINLOG '
3WhCYg8BAAAA/AAAAAABAAAAAAQAMTAuMi40My1NYXJpYURCLTE6MTAuMi40MyttYXJpYX5iaW9u
aWMtbG9nAAAAAAAAAADdaEJiEzgNAAgAEgAEBAQEEgAA5AAEGggAAAAICAgCAAAACgoKAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAEEwQADQgICAoKCgGDEV2d
'/!/;
# at 256
#220329 2:03:09 server id 1 end_log_pos 285 CRC32 0x5c6e0e0e Gtid list []
# at 285
#220329 2:03:09 server id 1 end_log_pos 329 CRC32 0x12d279db Binlog checkpoint mysqld-bin.000001
# at 329
#220329 2:03:10 server id 1 end_log_pos 371 CRC32 0x92eb5423 GTID 0-1-1 ddl
/!100101 SET @@session.skip_parallel_replication=0//!/;
/!100001 SET @@session.gtid_domain_id=0//!/;
/!100001 SET @@session.server_id=1//!/;
/!100001 SET @@session.gtid_seq_no=1//!/;
# at 371
#220329 2:03:10 server id 1 end_log_pos 463 CRC32 0x9835e4a5 Query thread_id=10 exec_time=0 error_code=0
use `mysql`/!/;
SET TIMESTAMP=1648519390/!/;
SET @@session.pseudo_thread_id=10/!/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1, @@session.check_constraint_checks=1/!/;
SET @@session.sql_mode=1411383296/!/;
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/!/;
TRUNCATE TABLE time_zone

So its just mysql_tzinfo_to_sql --skip-write-binlog that's broken.

Comment by Daniel Black [ 2022-03-29 ]

~~MDEV-27074~~ added --skip-log-bin to mysql_install_db. From the above 10.2.43 test, this appears to having an effect as the mysql_install_db initialization isn't in the binary log.

Testing anel's work/config:

start master
$ podman run -v ./config-files/primarycnf/:/etc/mysql/conf.d:z -v ./primaryinit/:/docker-entrypoint-initdb.d:z -e MARIADB_ROOT_PASSWORD=bob -e MARIADB_INITDB_SKIP_TZINFO=1 --name mariadbprimary --rm mariadb:10.2
2022-03-29 03:59:42+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.2.43+maria~bionic started.
2022-03-29 03:59:43+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2022-03-29 03:59:43+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.2.43+maria~bionic started.
2022-03-29 03:59:43+00:00 [Note] [Entrypoint]: Initializing database files
...

binary logs of primary
$ podman exec mariadbprimary mysqlbinlog /var/lib/mysql/my-mariadb-bin.000001
/!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1/;
/!40019 SET @@session.max_insert_delayed_threads=0/;
/!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0/;
DELIMITER /!/;
# at 4
#220329 3:59:45 server id 3000 end_log_pos 256 CRC32 0xec3bcb60 Start: binlog v 4, server v 10.2.43-MariaDB-1:10.2.43+maria~bionic-log created 220329 3:59:45 at startup
ROLLBACK/!/;
BINLOG '
MYRCYg+4CwAA/AAAAAABAAAAAAQAMTAuMi40My1NYXJpYURCLTE6MTAuMi40MyttYXJpYX5iaW9u
aWMtbG9nAAAAAAAAAAAxhEJiEzgNAAgAEgAEBAQEEgAA5AAEGggAAAAICAgCAAAACgoKAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAEEwQADQgICAoKCgFgyzvs
'/!/;
# at 256
#220329 3:59:45 server id 3000 end_log_pos 285 CRC32 0xc0c9ad4a Gtid list []
# at 285
#220329 3:59:45 server id 3000 end_log_pos 333 CRC32 0xd9ad19bd Binlog checkpoint my-mariadb-bin.000001
# at 333
#220329 3:59:46 server id 3000 end_log_pos 375 CRC32 0x18db44a1 GTID 0-3000-1 ddl
/!100101 SET @@session.skip_parallel_replication=0//!/;
/!100001 SET @@session.gtid_domain_id=0//!/;
/!100001 SET @@session.server_id=3000//!/;
/!100001 SET @@session.gtid_seq_no=1//!/;
# at 375
#220329 3:59:46 server id 3000 end_log_pos 491 CRC32 0x7789589f Query thread_id=11 exec_time=0 error_code=0
SET TIMESTAMP=1648526386/!/;
SET @@session.pseudo_thread_id=11/!/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1, @@session.check_constraint_checks=1/!/;
SET @@session.sql_mode=1411383296/!/;
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 USER 'repluser'@'%' IDENTIFIED BY 'replsecret'
/!/;
# at 491
#220329 3:59:46 server id 3000 end_log_pos 533 CRC32 0x78f69858 GTID 0-3000-2 ddl
/!100001 SET @@session.gtid_seq_no=2//!/;
# at 533
#220329 3:59:46 server id 3000 end_log_pos 660 CRC32 0x5c35147c Query thread_id=11 exec_time=0 error_code=0
SET TIMESTAMP=1648526386/!/;
GRANT REPLICATION SLAVE ON . TO 'repluser'@'%'
/!/;
# at 660
#220329 3:59:46 server id 3000 end_log_pos 683 CRC32 0x2803a6b6 Stop
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE/;
/!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0/;

config difference to repo
diff --git a/anel/docker-files/replication-example/secondaryinit/replinit.sql b/anel/docker-files/replication-example/secondaryinit/replinit.sql
index 6513721..011e614 100644
--- a/anel/docker-files/replication-example/secondaryinit/replinit.sql
+++ b/anel/docker-files/replication-example/secondaryinit/replinit.sql
@@ -2,14 +2,10 @@

# Change master related settings
CHANGE MASTER TO
- MASTER_HOST='172.17.0.2', # or containerID
+ MASTER_HOST='mariadbprimary', # or containerID
MASTER_USER='repluser',
MASTER_PASSWORD='replsecret',
MASTER_PORT=3306,
- MASTER_CONNECT_RETRY=10;
- #MASTER_LOG_FILE='my-mariadb-bin.000096', # this is needed only after doing mariadbdump
- #MASTER_LOG_POS=568,# this is needed only after doing mariadbdump
-
-# Start slave and show status
-#START SLAVE;
-#SHOW SLAVE STATUS\G
\ No newline at end of file
+ MASTER_CONNECT_RETRY=10,
+ MASTER_LOG_FILE='my-mariadb-bin.000001',
+ MASTER_LOG_POS=4;

start replica
$ podman run -v ./config-files/secondarycnf/:/etc/mysql/conf.d:z -v ./secondaryinit/:/docker-entrypoint-initdb.d:z -e MARIADB_ROOT_PASSWORD=bob -e MARIADB_INITDB_SKIP_TZINFO=1 --name mariadbreplica --network=container:mariadbprimary --rm mariadb:10.2 --port 3307
2022-03-29 04:00:34+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.2.43+maria~bionic started.
2022-03-29 04:00:34+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2022-03-29 04:00:34+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.2.43+maria~bionic started.
2022-03-29 04:00:34+00:00 [Note] [Entrypoint]: Initializing database files

2022-03-29 4:00:37 139875209799424 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='', master_port='3306', master_log_file='', master_log_pos='4'. New state master_host='mariadbprimary', master_port='3306', master_log_file='my-mariadb-bin.000001', master_log_pos='4'.
2022-03-29 4:00:37 139875207128832 [Note] Slave SQL thread initialized, starting replication in log 'my-mariadb-bin.000001' at position 4, relay log './my-mariadb-relay-bin.000001' position: 4
************************* 1. row *************************
Slave_IO_State: Connecting to master
Master_Host: mariadbprimary
Master_User: repluser
Master_Port: 3306
Connect_Retry: 10
Master_Log_File: my-mariadb-bin.000001
Read_Master_Log_Pos: 4
Relay_Log_File: my-mariadb-relay-bin.000001
Relay_Log_Pos: 4
Relay_Master_Log_File: my-mariadb-bin.000001
Slave_IO_Running: Connecting
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 4
Relay_Log_Space: 256
Until_Condition: None
Until_Log_File:
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File:
Master_SSL_CA_Path:
Master_SSL_Cert:
Master_SSL_Cipher:
Master_SSL_Key:
Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 0
Last_SQL_Error:
Replicate_Ignore_Server_Ids:
Master_Server_Id: 0
Master_SSL_Crl:
Master_SSL_Crlpath:
Using_Gtid: No
Gtid_IO_Pos:
Replicate_Do_Domain_Ids:
Replicate_Ignore_Domain_Ids:
Parallel_Mode: conservative
SQL_Delay: 0
SQL_Remaining_Delay: NULL
Slave_SQL_Running_State: Waiting for the next event in relay log


2022-03-29 4:00:37 139875207436032 [Note] Slave I/O thread: connected to master 'repluser@mariadbprimary:3306',replication started in log 'my-mariadb-bin.000001' at position 4
...
2022-03-29 4:00:39 140646240114368 [Note] Server socket created on IP: '::'.
2022-03-29 4:00:39 140646240114368 [Note] Reading of all Master_info entries succeeded
2022-03-29 4:00:39 140646240114368 [Note] Added new Master_info '' to hash table
2022-03-29 4:00:39 140645482858240 [Note] Slave SQL thread initialized, starting replication in log 'my-mariadb-bin.000001' at position 4, relay log './my-mariadb-relay-bin.000001' position: 4
2022-03-29 4:00:39 140646240114368 [Note] mysqld: ready for connections.
Version: '10.2.43-MariaDB-1:10.2.43+maria~bionic' socket: '/var/run/mysqld/mysqld.sock' port: 3307 mariadb.org binary distribution
2022-03-29 4:00:39 140645604837120 [Note] Slave I/O thread: connected to master 'repluser@mariadbprimary:3306',replication started in log 'my-mariadb-bin.000001' at position 4

So binary logging of mysql_install_db already resolved in ~~MDEV-27074~~. I just need to fix the TZ initialization under --skip-write-binlog (which only does so under galera).

Comment by Daniel Black [ 2022-03-29 ]

tz in binary logs - ~~MDEV-28189~~

Comment by Daniel Black [ 2022-03-29 ]

Closing as was a bug, before ~~MDEV-27074~~ fixed it incidently

[MDEV-28188] Database initialization commands can be written into binary log with Docker Created: 2022-03-29 Updated: 2022-03-29 Resolved: 2022-03-29
Status:	Closed
Project:	MariaDB Server
Component/s:	Docker
Affects Version/s:	10.2.41, 10.4, 10.5, 10.6, 10.7
Fix Version/s:	N/A

[MDEV-28188] Database initialization commands can be written into binary log with Docker Created: 2022-03-29 Updated: 2022-03-29 Resolved: 2022-03-29