search

MariaDB / mariadb-docker

Docker Official Image packaging for MariaDB
https://mariadb.org
GNU General Public License v2.0
770 stars 438 forks source link

mariadb:latest Connection failure #281

Closed windstep closed 4 years ago

windstep commented 4 years ago

Hey there!

I have a trouble in mariadb connection. I'm connecting via command mysql -u root -P 13306 -h 127.0.0.1 and it says to me back ERROR 2013 (HY000): Lost connection to MySQL server at 'reading initial communication packet', system error: 0

My docker-compose fragment looks like this

  db:
    image: "mariadb:latest"
    ports:
      - "13306:3306"
    environment:
      MYSQL_ALLOW_EMPTY_PASSWORD: "yes"
    volumes:
      - "./mariadb/my.cnf:/etc/mysql/my.cnf"

My my.cnf looks like this

[mysqld]
innodb_data_file_path = ibdata2:10M:autoextend:max:2048M
tmp_table_size=2G
max_heap_table_size=2G
skip_name_resolve=0

Logs of container (we can actually connect to mariadb inside of container) says this:

db_1              | 2019-12-24 14:29:17+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 1:10.4.11+maria~bionic started.
db_1              | 2019-12-24 14:29:17+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
db_1              | 2019-12-24 14:29:17+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 1:10.4.11+maria~bionic started.
db_1              | 2019-12-24 14:29:17 0 [Note] mysqld (mysqld 10.4.11-MariaDB-1:10.4.11+maria~bionic) starting as process 1 ...
db_1              | 2019-12-24 14:29:17 0 [Note] InnoDB: Using Linux native AIO
db_1              | 2019-12-24 14:29:17 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
db_1              | 2019-12-24 14:29:17 0 [Note] InnoDB: Uses event mutexes
db_1              | 2019-12-24 14:29:17 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
db_1              | 2019-12-24 14:29:17 0 [Note] InnoDB: Number of pools: 1
db_1              | 2019-12-24 14:29:17 0 [Note] InnoDB: Using SSE2 crc32 instructions
db_1              | 2019-12-24 14:29:17 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
db_1              | 2019-12-24 14:29:18 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
db_1              | 2019-12-24 14:29:18 0 [Note] InnoDB: Completed initialization of buffer pool
db_1              | 2019-12-24 14:29:18 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
db_1              | 2019-12-24 14:29:18 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=6861688
db_1              | 2019-12-24 14:29:18 0 [Note] InnoDB: Starting final batch to recover 69 pages from redo log.
db_1              | 2019-12-24 14:29:18 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
db_1              | 2019-12-24 14:29:18 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
db_1              | 2019-12-24 14:29:18 0 [Note] InnoDB: Creating shared tablespace for temporary tables
db_1              | 2019-12-24 14:29:18 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
db_1              | 2019-12-24 14:29:18 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
db_1              | 2019-12-24 14:29:18 0 [Note] InnoDB: Waiting for purge to start
db_1              | 2019-12-24 14:29:18 0 [Note] InnoDB: 10.4.11 started; log sequence number 6878876; transaction id 7594
db_1              | 2019-12-24 14:29:18 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
db_1              | 2019-12-24 14:29:18 0 [Note] Plugin 'FEEDBACK' is disabled.
db_1              | 2019-12-24 14:29:18 0 [Note] InnoDB: Buffer pool(s) load completed at 191224 14:29:18
db_1              | 2019-12-24 14:29:18 0 [Note] Server socket created on IP: '::'.
db_1              | 2019-12-24 14:29:18 0 [Warning] 'user' entry 'root@32496261ad2a' ignored in --skip-name-resolve mode.
db_1              | 2019-12-24 14:29:18 0 [Warning] 'user' entry '@32496261ad2a' ignored in --skip-name-resolve mode.
db_1              | 2019-12-24 14:29:18 0 [Warning] 'proxies_priv' entry '@% root@32496261ad2a' ignored in --skip-name-resolve mode.
db_1              | 2019-12-24 14:29:18 0 [Note] Reading of all Master_info entries succeeded
db_1              | 2019-12-24 14:29:18 0 [Note] Added new Master_info '' to hash table
db_1              | 2019-12-24 14:29:18 0 [Note] mysqld: ready for connections.
db_1              | Version: '10.4.11-MariaDB-1:10.4.11+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
db_1              | 2019-12-24 14:29:19 8 [Warning] Aborted connection 8 to db: 'unconnected' user: 'unauthenticated' host: '192.168.80.1' (This connection closed normally without authentication)

BTW: I have second container with all the same, but it uses TMPFS instead of not using volumes and it actually works fine. I don't even understand why. If I'm using any other volume file system, including directory with 777 permissions mounts - it didn't work.

wglambert commented 4 years ago

Are you using Docker for Mac/Windows?

Using your my.cnf works fine

$ docker run -d --rm --name mariadb --network=net -v "$PWD"/my.cnf:/etc/mysql/my.cnf -p 13306:3306 -e MYSQL_ALLOW_EMPTY_PASSWORD=yes mariadb
483e87405d5a020346ea2b8728b509a99b0f88d909c259f30b01ff7a76643fd8

$ docker run -it --rm --network=net mariadb mysql -h mariadb
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 8
Server version: 10.4.11-MariaDB-1:10.4.11+maria~bionic mariadb.org binary distribution

Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

MariaDB [(none)]>
windstep commented 4 years ago

Are you using Docker for Mac/Windows?

Actually not! Ubuntu 19.10. docker version - 19.03.5, docker-compose 1.21.

Inside docker container it works fine, I can get access there the way you do, but outside of it I can't. I'm just trying to figure out, is it any "feature" of my own PC, or is it a bug may be.

tianon commented 4 years ago

It sounds like you might have a pre-initialized volume -- did you start up this stack (or one like it) previously before you added the empty password environment variable? You could try stopping it, deleting the volume, and recreating it (otherwise, docker-compose is very aggressive about trying to keep the volume around and connected).

windstep commented 4 years ago

I've already cleaned out all of volumes, images and containers and recreated them, but It didn't worked out. May be I'm doing something wrong. What should I do?

windstep commented 4 years ago

Command set of docker system prune, docker volume prune, docker rmi $(docker images -q), docker rm $(docker ps -a -q) did nothing to this image to work.

windstep commented 4 years ago

Found one thing by telnet`ing this address.

telnet 127.0.0.1 13306 outputs EHost '172.19.0.1' is not allowed to connect to this MariaDB serverConnection closed by foreign host

It seems strange and not looks like problem with image, but it could be. May be it is because of "skip_name_resolve" enabled by default and not overwriting by config

windstep commented 4 years ago

Second server, which is TMPFS mounted outputs logs like this

db-test_1         | 2019-12-25 05:53:49+00:00 [Note] [Entrypoint]: Database files initialized
db-test_1         | 2019-12-25 05:53:49+00:00 [Note] [Entrypoint]: Starting temporary server
db-test_1         | 2019-12-25 05:53:49+00:00 [Note] [Entrypoint]: Waiting for server startup
db-test_1         | 2019-12-25  5:53:49 0 [Note] mysqld (mysqld 10.4.11-MariaDB-1:10.4.11+maria~bionic) starting as process 109 ...
db-test_1         | 2019-12-25  5:53:49 0 [Note] InnoDB: Using Linux native AIO
db-test_1         | 2019-12-25  5:53:49 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
db-test_1         | 2019-12-25  5:53:49 0 [Note] InnoDB: Uses event mutexes
db-test_1         | 2019-12-25  5:53:49 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
db-test_1         | 2019-12-25  5:53:49 0 [Note] InnoDB: Number of pools: 1
db-test_1         | 2019-12-25  5:53:49 0 [Note] InnoDB: Using SSE2 crc32 instructions
db-test_1         | 2019-12-25  5:53:49 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
db-test_1         | 2019-12-25  5:53:49 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
db-test_1         | 2019-12-25  5:53:49 0 [Note] InnoDB: Completed initialization of buffer pool
db-test_1         | 2019-12-25  5:53:49 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
db-test_1         | 2019-12-25  5:53:49 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
db-test_1         | 2019-12-25  5:53:49 0 [Note] InnoDB: Creating shared tablespace for temporary tables
db-test_1         | 2019-12-25  5:53:49 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
db-test_1         | 2019-12-25  5:53:49 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
db-test_1         | 2019-12-25  5:53:49 0 [Note] InnoDB: Waiting for purge to start
db-test_1         | 2019-12-25  5:53:49 0 [Note] InnoDB: 10.4.11 started; log sequence number 60979; transaction id 21
db-test_1         | 2019-12-25  5:53:49 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
db-test_1         | 2019-12-25  5:53:49 0 [Note] Plugin 'FEEDBACK' is disabled.
db-test_1         | 2019-12-25  5:53:49 0 [Note] InnoDB: Buffer pool(s) load completed at 191225  5:53:49
db-test_1         | 2019-12-25  5:53:49 0 [Warning] 'user' entry 'root@69a230064cae' ignored in --skip-name-resolve mode.
db-test_1         | 2019-12-25  5:53:49 0 [Warning] 'user' entry '@69a230064cae' ignored in --skip-name-resolve mode.
db-test_1         | 2019-12-25  5:53:49 0 [Warning] 'proxies_priv' entry '@% root@69a230064cae' ignored in --skip-name-resolve mode.
db-test_1         | 2019-12-25  5:53:49 0 [Note] Reading of all Master_info entries succeeded
db-test_1         | 2019-12-25  5:53:49 0 [Note] Added new Master_info '' to hash table
db-test_1         | 2019-12-25  5:53:49 0 [Note] mysqld: ready for connections.
db-test_1         | Version: '10.4.11-MariaDB-1:10.4.11+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  mariadb.org binary distribution
db-test_1         | 2019-12-25 05:53:50+00:00 [Note] [Entrypoint]: Temporary server started.
db-test_1         | Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.list' as time zone. Skipping it.
db-test_1         | 2019-12-25  5:53:57 10 [Warning] 'proxies_priv' entry '@% root@69a230064cae' ignored in --skip-name-resolve mode.
db-test_1         | 
db-test_1         | 2019-12-25 05:53:57+00:00 [Note] [Entrypoint]: Stopping temporary server
db-test_1         | 2019-12-25  5:53:57 0 [Note] mysqld (initiated by: root[root] @ localhost []): Normal shutdown
db-test_1         | 2019-12-25  5:53:57 0 [Note] Event Scheduler: Purging the queue. 0 events
db-test_1         | 2019-12-25  5:53:57 0 [Note] InnoDB: FTS optimize thread exiting.
db-test_1         | 2019-12-25  5:53:57 0 [Note] InnoDB: Starting shutdown...
db-test_1         | 2019-12-25  5:53:57 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
db-test_1         | 2019-12-25  5:53:57 0 [Note] InnoDB: Buffer pool(s) dump completed at 191225  5:53:57
db-test_1         | 2019-12-25  5:53:59 0 [Note] InnoDB: Shutdown completed; log sequence number 19875577; transaction id 14604
db-test_1         | 2019-12-25  5:53:59 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
db-test_1         | 2019-12-25  5:53:59 0 [Note] mysqld: Shutdown complete
db-test_1         | 
db-test_1         | 2019-12-25 05:53:59+00:00 [Note] [Entrypoint]: Temporary server stopped
db-test_1         | 
db-test_1         | 2019-12-25 05:53:59+00:00 [Note] [Entrypoint]: MySQL init process done. Ready for start up.
db-test_1         | 
db-test_1         | 2019-12-25  5:53:59 0 [Note] mysqld (mysqld 10.4.11-MariaDB-1:10.4.11+maria~bionic) starting as process 1 ...
db-test_1         | 2019-12-25  5:53:59 0 [Note] InnoDB: Using Linux native AIO
db-test_1         | 2019-12-25  5:53:59 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
db-test_1         | 2019-12-25  5:53:59 0 [Note] InnoDB: Uses event mutexes
db-test_1         | 2019-12-25  5:53:59 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
db-test_1         | 2019-12-25  5:53:59 0 [Note] InnoDB: Number of pools: 1
db-test_1         | 2019-12-25  5:53:59 0 [Note] InnoDB: Using SSE2 crc32 instructions
db-test_1         | 2019-12-25  5:53:59 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
db-test_1         | 2019-12-25  5:53:59 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
db-test_1         | 2019-12-25  5:53:59 0 [Note] InnoDB: Completed initialization of buffer pool
db-test_1         | 2019-12-25  5:53:59 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
db-test_1         | 2019-12-25  5:53:59 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
db-test_1         | 2019-12-25  5:53:59 0 [Note] InnoDB: Creating shared tablespace for temporary tables
db-test_1         | 2019-12-25  5:53:59 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
db-test_1         | 2019-12-25  5:53:59 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
db-test_1         | 2019-12-25  5:53:59 0 [Note] InnoDB: Waiting for purge to start
db-test_1         | 2019-12-25  5:53:59 0 [Note] InnoDB: 10.4.11 started; log sequence number 19875577; transaction id 14604
db-test_1         | 2019-12-25  5:53:59 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
db-test_1         | 2019-12-25  5:53:59 0 [Note] Plugin 'FEEDBACK' is disabled.
db-test_1         | 2019-12-25  5:53:59 0 [Note] InnoDB: Buffer pool(s) load completed at 191225  5:53:59
db-test_1         | 2019-12-25  5:53:59 0 [Note] Server socket created on IP: '::'.
db-test_1         | 2019-12-25  5:53:59 0 [Warning] 'proxies_priv' entry '@% root@69a230064cae' ignored in --skip-name-resolve mode.
db-test_1         | 2019-12-25  5:53:59 0 [Note] Reading of all Master_info entries succeeded
db-test_1         | 2019-12-25  5:53:59 0 [Note] Added new Master_info '' to hash table
db-test_1         | 2019-12-25  5:53:59 0 [Note] mysqld: ready for connections.
db-test_1         | Version: '10.4.11-MariaDB-1:10.4.11+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution

And it is available for outside connections

windstep commented 4 years ago

Hey there, finally figured out, what was that fail.

The one and only major difference between these instances, at least in logs, was that the first one instance contains InnoDB: Starting crash recovery from checkpoint LSN=6861688. I've opened full logs and found out, that the first time instance of first containers was started as a temporary server on port 0 and didn't accepted any connections. That caused me shut down the container and recreate it. It started as usual, but corrupted. Therefore, I've cleaned up my volumes and containers and recreated them without shutting 'em down. It took at least couple of minutes to container to start, but now it works just fine.

So, for future researches. Try to delete volumes, start a container and w8 for 10 or so minutes for system to start.