Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

binlog-server: Error while waiting MySQL applied binlogs #1665

Closed
bmday opened this issue Mar 20, 2024 · 1 comment · Fixed by #1692
Closed

binlog-server: Error while waiting MySQL applied binlogs #1665

bmday opened this issue Mar 20, 2024 · 1 comment · Fixed by #1692
Assignees
@ostinru
Labels
mysql MySQL issue

Comments

@bmday
Copy link

bmday commented Mar 20, 2024

Database name

wal-g mysql version v3.0.0 4689e3a 2024.03.17_10:04:49
MySQL 5.7.44-48-log Percona Server

Issue description

Describe your problem

We want to restore a MySQL backup in PiTR mode.

First we do backup-fetch stream_20240320T010002Z. After which we run binlog-server --until "2024-03-20T06:21:00Z".
The MySQL instance is configured in accordance with the documentation https://wal-g.readthedocs.io/MySQL/, chapter MySQL - PiTR with wal-g binlog-server.

After synchronizing the last binlog file, wal-g gives an INFO level message:
INFO: 2024/03/20 13:59:09.022755 Error while waiting MySQL applied binlogs: default addr for network '127.0.0.1:3306' unknown. See "Logs". Is this normal behavior, or is there some kind of bug and we should be concerned about our database?

Logs:

wal-g --turbo --config=/etc/wal-g/prd-db03.db.tech.env binlog-server --until "2024-03-20T06:21:00Z"
WARNING: 2024/03/20 13:52:36.570312 WALG_FAILOVER_STORAGES_CACHE_LIFETIME is unknown
WARNING: 2024/03/20 13:52:36.570358 WALG_FAILOVER_STORAGES_CHECK_TIMEOUT is unknown
WARNING: 2024/03/20 13:52:36.570388 We found that some variables in your config file detected as 'Unknown'.
  If this is not right, please create issue https://github.com/wal-g/wal-g/issues/new
DEBUG: 2024/03/20 13:52:36.571621 --- COMPILED ENVIRONMENT VARS ---
        SSH_PORT=22
        SSH_PRIVATE_KEY_PATH=/root/.ssh/id_rsa
        SSH_USERNAME=root
        TOTAL_BG_UPLOADED_LIMIT=32
        WALG_BACKUP_DOWNLOAD_MAX_RETRY=1
        WALG_COMPRESSION_METHOD=zstd
        WALG_DELTA_MAX_STEPS=0
        WALG_DOWNLOAD_CONCURRENCY=10
        WALG_DOWNLOAD_FILE_RETRIES=15
        WALG_ENVELOPE_CACHE_EXPIRATION=0
        WALG_FAILOVER_STORAGES_CACHE_LIFETIME=15m
        WALG_FAILOVER_STORAGES_CHECK_TIMEOUT=30s
        WALG_INTEGRITY_MAX_DELAYED_WALS=0
        WALG_LIBSODIUM_KEY_TRANSFORM=none
        WALG_LOG_LEVEL=DEVEL
        WALG_MYSQL_BACKUP_PREPARE_COMMAND=xtrabackup --prepare --target-dir=/var/lib/mysql/data
        WALG_MYSQL_BINLOG_DST=/var/lib/mysql/data/my-binlogs
        WALG_MYSQL_BINLOG_REPLAY_COMMAND=mysqlbinlog --stop-datetime="$WALG_MYSQL_BINLOG_END_TS" "$WALG_MYSQL_CURRENT_BINLOG" | mysql
        WALG_MYSQL_BINLOG_SERVER_HOST=localhost
        WALG_MYSQL_BINLOG_SERVER_ID=99
        WALG_MYSQL_BINLOG_SERVER_PASSWORD=walgpwd
        WALG_MYSQL_BINLOG_SERVER_PORT=9306
        WALG_MYSQL_BINLOG_SERVER_REPLICA_SOURCE=user:pass@127.0.0.1:3306/db
        WALG_MYSQL_BINLOG_SERVER_USER=walg
        WALG_MYSQL_CHECK_GTIDS=true
        WALG_MYSQL_DATASOURCE_NAME=user:pass@127.0.0.1/db
        WALG_MYSQL_INCREMENTAL_BACKUP_DST=/tmp
        WALG_PREVENT_WAL_OVERWRITE=false
        WALG_SERIALIZER_TYPE=json_default
        WALG_SKIP_REDUNDANT_TARS=false
        WALG_SSH_PREFIX=ssh://backup02.db.tech/mnt/backups/db_backups/mysql/my-db-server
        WALG_STORE_ALL_CORRUPT_BLOCKS=false
        WALG_STREAM_CREATE_COMMAND=/usr/bin/xtrabackup --defaults-extra-file=/root/.my.cnf --lock-ddl-per-table --backup --stream=xbstream --datadir=/var/lib/mysql/data --parallel=1 --no-timestamp --slave-info
        WALG_STREAM_RESTORE_COMMAND=xbstream -x -C /var/lib/mysql/data
        WALG_STREAM_SPLITTER_BLOCK_SIZE=1048576
        WALG_TAR_DISABLE_FSYNC=false
        WALG_TAR_SIZE_THRESHOLD=1073741823
        WALG_UPLOAD_CONCURRENCY=16
        WALG_UPLOAD_DISK_CONCURRENCY=1
        WALG_UPLOAD_QUEUE=2
        WALG_UPLOAD_WAL_METADATA=NOMETADATA
        WALG_USE_COPY_COMPOSER=false
        WALG_USE_DATABASE_COMPOSER=false
        WALG_USE_RATING_COMPOSER=false
        WALG_USE_REVERSE_UNPACK=false
        WALG_USE_WAL_DELTA=false
        WALG_VERIFY_PAGE_CHECKSUMS=false
        WALG_WITHOUT_FILES_METADATA=false
INFO: 2024/03/20 13:52:37.188823 LATEST backup is: 'stream_20240320T010002Z'
INFO: 2024/03/20 13:52:37.200508 Backup sentinel: {"Tool":"WALG_XTRABACKUP_TOOL","BinLogStart":"mysql-bin.006584","BinLogEnd":"mysql-bin.006584","StartLocalTime":"2024-03-20T04:00:02.756611+03:00","StopLocalTime":"2024-03-20T06:32:23.886436+03:00","UncompressedSize":1096302751593,"CompressedSize":146216128982,"Hostname":"my-db-server","ServerUUID":"d4fde908-6f73-11ed-9b46-86a5be8d69f3","ServerVersion":"5.7.39-42-log","IsPermanent":false,"IsIncremental":false,"LSN":39276491566328,"DeltaLSN":0,"DeltaCount":0}
INFO: 2024/03/20 13:52:37.204454 Backup sentinel file: stream_20240320T010002Z_backup_stop_sentinel.json (2024-03-20 06:32:23 +0300 MSK)
INFO: 2024/03/20 13:52:37.208278 Backup start binlog: mysql-bin.006584.zst (2024-03-19 06:32:16 +0300 MSK)
INFO: 2024/03/20 13:52:37.208313 Starting binlog server
INFO: 2024/03/20 13:52:37.212128 Listening on 127.0.0.1:9306, wait connection
INFO: 2024/03/20 13:53:20.144075 connection accepted
INFO: 2024/03/20 13:53:20.145038 connection created
DEBUG: 2024/03/20 13:53:20.145259 Unhandled query: SELECT UNIX_TIMESTAMP()
DEBUG: 2024/03/20 13:53:20.145867 Unhandled query: SET @master_heartbeat_period= 30000001024
DEBUG: 2024/03/20 13:53:20.145984 Unhandled query: SET @master_binlog_checksum= @@global.binlog_checksum
DEBUG: 2024/03/20 13:53:20.146509 Unhandled query: SET @slave_uuid= 'f4483e66-e6a7-11ee-be19-fee5f9df3a3a'
INFO: 2024/03/20 13:53:20.307155 downloading mysql-bin.006584 into /var/lib/mysql/data/my-binlogs/mysql-bin.006584
DEBUG: 2024/03/20 13:53:20.312839 No crypter has been selected
INFO: 2024/03/20 13:53:26.624845 Synced binlog file mysql-bin.006584
INFO: 2024/03/20 13:53:26.624921 downloading mysql-bin.006605 into /var/lib/mysql/data/my-binlogs/mysql-bin.006605
DEBUG: 2024/03/20 13:53:26.670129 No crypter has been selected
INFO: 2024/03/20 13:54:05.899785 Synced binlog file mysql-bin.006605
INFO: 2024/03/20 13:54:05.899948 downloading mysql-bin.006606 into /var/lib/mysql/data/my-binlogs/mysql-bin.006606
DEBUG: 2024/03/20 13:54:05.953114 No crypter has been selected
INFO: 2024/03/20 13:54:16.279963 Synced binlog file mysql-bin.006606
INFO: 2024/03/20 13:54:16.280176 downloading mysql-bin.006607 into /var/lib/mysql/data/my-binlogs/mysql-bin.006607
DEBUG: 2024/03/20 13:54:16.335369 No crypter has been selected
INFO: 2024/03/20 13:54:27.681420 Synced binlog file mysql-bin.006607
INFO: 2024/03/20 13:54:27.681622 downloading mysql-bin.006608 into /var/lib/mysql/data/my-binlogs/mysql-bin.006608
DEBUG: 2024/03/20 13:54:27.740449 No crypter has been selected
INFO: 2024/03/20 13:54:54.567288 Synced binlog file mysql-bin.006608
INFO: 2024/03/20 13:54:54.567642 downloading mysql-bin.006609 into /var/lib/mysql/data/my-binlogs/mysql-bin.006609
DEBUG: 2024/03/20 13:54:54.654111 No crypter has been selected
INFO: 2024/03/20 13:55:50.322166 Synced binlog file mysql-bin.006609
INFO: 2024/03/20 13:55:50.322394 downloading mysql-bin.006610 into /var/lib/mysql/data/my-binlogs/mysql-bin.006610
DEBUG: 2024/03/20 13:55:50.398869 No crypter has been selected
INFO: 2024/03/20 13:56:39.174900 Synced binlog file mysql-bin.006610
INFO: 2024/03/20 13:56:39.175118 downloading mysql-bin.006611 into /var/lib/mysql/data/my-binlogs/mysql-bin.006611
DEBUG: 2024/03/20 13:56:39.256189 No crypter has been selected
INFO: 2024/03/20 13:57:22.974991 downloading mysql-bin.006612 into /var/lib/mysql/data/my-binlogs/mysql-bin.006612
INFO: 2024/03/20 13:57:22.975310 Synced binlog file mysql-bin.006611
DEBUG: 2024/03/20 13:57:23.039696 No crypter has been selected
INFO: 2024/03/20 13:58:09.552842 Synced binlog file mysql-bin.006612
INFO: 2024/03/20 13:58:09.552976 downloading mysql-bin.006613 into /var/lib/mysql/data/my-binlogs/mysql-bin.006613
DEBUG: 2024/03/20 13:58:09.633490 No crypter has been selected
INFO: 2024/03/20 13:58:42.238244 Synced binlog file mysql-bin.006613
INFO: 2024/03/20 13:59:09.022755 Error while waiting MySQL applied binlogs:  default addr for network '127.0.0.1:3306' unknown

After that, we tried to restart binlog-server, then when the Mysql server accesses binlog-server, wal-g crashes with the message
fatal error: runtime: out of memory. Are we doing something wrong, or is this a bug in the wal-g code?

Traceback:

INFO: 2024/03/19 16:14:11.296660 Backup sentinel file: stream_20240319T010002Z_backup_stop_sentinel.json (2024-03-19 06:31:20 +0300 MSK)
INFO: 2024/03/19 16:14:11.300223 Backup start binlog: mysql-bin.006574.zst (2024-03-18 06:31:16 +0300 MSK)
INFO: 2024/03/19 16:14:11.300239 Starting binlog server
INFO: 2024/03/19 16:14:11.300593 Listening on 127.0.0.1:9306, wait connection
INFO: 2024/03/19 16:15:06.333026 connection accepted
INFO: 2024/03/19 16:15:06.333410 connection created
DEBUG: 2024/03/19 16:15:06.333477 Unhandled query: SET NAMES utf8
DEBUG: 2024/03/19 16:15:06.333654 Unhandled query: SELECT UNIX_TIMESTAMP()
DEBUG: 2024/03/19 16:15:06.333844 Unhandled query: SET @master_heartbeat_period= 30000001024
DEBUG: 2024/03/19 16:15:06.333919 Unhandled query: SET @master_binlog_checksum= @@global.binlog_checksum
DEBUG: 2024/03/19 16:15:06.334241 Unhandled query: SET @slave_uuid= '48596ac1-e5eb-11ee-a7af-fee5f9df3a3a'
fatal error: runtime: out of memory

runtime stack:
runtime.throw({0x2071ee1?, 0x20000?})
        /opt/hostedtoolcache/go/1.20.14/x64/src/runtime/panic.go:1047 +0x5d fp=0x7fca64ff8c00 sp=0x7fca64ff8bd0 pc=0x43e5dd
runtime.sysMapOS(0xc005800000, 0xdd00000000?)
        /opt/hostedtoolcache/go/1.20.14/x64/src/runtime/mem_linux.go:187 +0x11b fp=0x7fca64ff8c48 sp=0x7fca64ff8c00 pc=0x41da7b
runtime.sysMap(0x3b7d660?, 0xc3ffffffff?, 0x3b8d7f8?)
        /opt/hostedtoolcache/go/1.20.14/x64/src/runtime/mem.go:142 +0x35 fp=0x7fca64ff8c78 sp=0x7fca64ff8c48 pc=0x41d455
runtime.(*mheap).grow(0x3b7d660, 0x6e80000?)
        /opt/hostedtoolcache/go/1.20.14/x64/src/runtime/mheap.go:1522 +0x252 fp=0x7fca64ff8cf0 sp=0x7fca64ff8c78 pc=0x42f4b2
runtime.(*mheap).allocSpan(0x3b7d660, 0x6e80000, 0x0, 0x61?)
        /opt/hostedtoolcache/go/1.20.14/x64/src/runtime/mheap.go:1243 +0x1b7 fp=0x7fca64ff8d88 sp=0x7fca64ff8cf0 pc=0x42ebf7
runtime.(*mheap).alloc.func1()
        /opt/hostedtoolcache/go/1.20.14/x64/src/runtime/mheap.go:961 +0x65 fp=0x7fca64ff8dd0 sp=0x7fca64ff8d88 pc=0x42e6a5
runtime.systemstack()
        /opt/hostedtoolcache/go/1.20.14/x64/src/runtime/asm_amd64.s:496 +0x49 fp=0x7fca64ff8dd8 sp=0x7fca64ff8dd0 pc=0x473469

goroutine 1 [running]:
runtime.systemstack_switch()
        /opt/hostedtoolcache/go/1.20.14/x64/src/runtime/asm_amd64.s:463 fp=0xc000561840 sp=0xc000561838 pc=0x473400
runtime.(*mheap).alloc(0xdd00000000?, 0x6e80000?, 0xe0?)
        /opt/hostedtoolcache/go/1.20.14/x64/src/runtime/mheap.go:955 +0x65 fp=0xc000561888 sp=0xc000561840 pc=0x42e5e5
runtime.(*mcache).allocLarge(0x0?, 0xdd00000000, 0x0)
        /opt/hostedtoolcache/go/1.20.14/x64/src/runtime/mcache.go:234 +0x85 fp=0xc0005618d0 sp=0xc000561888 pc=0x41c4e5
runtime.mallocgc(0xdd00000000, 0x1d4e160, 0x1)
        /opt/hostedtoolcache/go/1.20.14/x64/src/runtime/malloc.go:1053 +0x4fe fp=0xc000561938 sp=0xc0005618d0 pc=0x4131fe
runtime.newarray(0x0?, 0xc000561990?)
        /opt/hostedtoolcache/go/1.20.14/x64/src/runtime/malloc.go:1276 +0x52 fp=0xc000561960 sp=0xc000561938 pc=0x413772
runtime.makeBucketArray(0xc000014178?, 0x0?, 0xc0005619d8?)
        /opt/hostedtoolcache/go/1.20.14/x64/src/runtime/map.go:363 +0x18e fp=0xc0005619a0 sp=0xc000561960 pc=0x4145ce
runtime.makemap(0xc00047c000?, 0xc00047c000?, 0x41016d?)
        /opt/hostedtoolcache/go/1.20.14/x64/src/runtime/map.go:329 +0xe9 fp=0xc0005619e8 sp=0xc0005619a0 pc=0x414369
github.com/go-mysql-org/go-mysql/mysql.DecodeMysqlGTIDSet({0xc00010f397, 0x40, 0x49})
        /home/runner/work/wal-g/wal-g/vendor/github.com/go-mysql-org/go-mysql/mysql/mysql_gtid.go:428 +0x5f fp=0xc000561a50 sp=0xc0005619e8 pc=0x17e903f
github.com/go-mysql-org/go-mysql/server.parseBinlogDumpGTID({0xc00010f381?, 0x2409b30?, 0x3b952d8?})
        /home/runner/work/wal-g/wal-g/vendor/github.com/go-mysql-org/go-mysql/server/replication.go:29 +0x59 fp=0xc000561a78 sp=0xc000561a50 pc=0x1819d99
github.com/go-mysql-org/go-mysql/server.(*Conn).dispatch(0xc00084b8c0, {0xc00010f380?, 0x57, 0x60})
        /home/runner/work/wal-g/wal-g/vendor/github.com/go-mysql-org/go-mysql/server/command.go:164 +0x91d fp=0xc000561bc8 sp=0xc000561a78 pc=0x181749d
github.com/go-mysql-org/go-mysql/server.(*Conn).HandleCommand(0xc00084b8c0)
        /home/runner/work/wal-g/wal-g/vendor/github.com/go-mysql-org/go-mysql/server/command.go:53 +0xb5 fp=0xc000561c20 sp=0xc000561bc8 pc=0x1816ab5
github.com/wal-g/wal-g/internal/databases/mysql.HandleBinlogServer({0x20568c1, 0x6}, {0x7ffc7f6597ca, 0x14})
        /home/runner/work/wal-g/wal-g/internal/databases/mysql/binlog_server_handler.go:290 +0x914 fp=0xc000561d68 sp=0xc000561c20 pc=0x1844674
github.com/wal-g/wal-g/cmd/mysql.glob..func15(0x3965480?, {0xc0004de740?, 0x0?, 0x4?})
        /home/runner/work/wal-g/wal-g/cmd/mysql/binlog_server.go:39 +0x35 fp=0xc000561d98 sp=0xc000561d68 pc=0x185cb75
github.com/spf13/cobra.(*Command).execute(0x3965480, {0xc0004de700, 0x4, 0x4})
        /home/runner/work/wal-g/wal-g/vendor/github.com/spf13/cobra/command.go:860 +0x663 fp=0xc000561e70 sp=0xc000561d98 pc=0x5d0903
github.com/spf13/cobra.(*Command).ExecuteC(0x3964080)
        /home/runner/work/wal-g/wal-g/vendor/github.com/spf13/cobra/command.go:974 +0x3bd fp=0xc000561f28 sp=0xc000561e70 pc=0x5d0f9d
github.com/spf13/cobra.(*Command).Execute(...)
        /home/runner/work/wal-g/wal-g/vendor/github.com/spf13/cobra/command.go:902
github.com/wal-g/wal-g/cmd/mysql.Execute()
        /home/runner/work/wal-g/wal-g/cmd/mysql/mysql.go:40 +0x25 fp=0xc000561f70 sp=0xc000561f28 pc=0x185db05
main.main()
        /home/runner/work/wal-g/wal-g/main/mysql/main.go:8 +0x17 fp=0xc000561f80 sp=0xc000561f70 pc=0x185e557
runtime.main()
        /opt/hostedtoolcache/go/1.20.14/x64/src/runtime/proc.go:250 +0x207 fp=0xc000561fe0 sp=0xc000561f80 pc=0x440f07
runtime.goexit()
        /opt/hostedtoolcache/go/1.20.14/x64/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc000561fe8 sp=0xc000561fe0 pc=0x475621
@bmday
Copy link
Author

bmday commented Mar 21, 2024 •
edited

We have sorted it out regarding the INFO message: 2024/03/20 13:59:09.022755 Error while waiting MySQL applies binlogs: default network address '127.0.0.1:3306'. This is due to an incorrect recommendation in the documentation for setting the WALG_MYSQL_BINLOG_SERVER_REPLICA_SOURCE variable.
The documentation states that the variable should look like this: WALG_MYSQL_BINLOG_SERVER_REPLICA_SOURCE="user:password@127.0.0.1:3306/db".

In reality, most likely, it should look like this: WALG_MYSQL_BINLOG_SERVER_REPLICA_SOURCE="user:password@tcp(localhost:3306)/db". The same goes for WALG_MYSQL_DATASOURCE_NAME.

@ostinru ostinru added the mysql MySQL issue label Mar 24, 2024
@ostinru ostinru self-assigned this Mar 24, 2024
@ostinru ostinru mentioned this issue Apr 21, 2024
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@ostinru ostinru

Labels
mysql MySQL issue
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

WALG-1665. User proper DSNs in MySQL documentation & validate DSN format it earlier wal-g/wal-g
2 participants
@ostinru @bmday