Bug #78957 MySQL docker container fails to start if my.cnf contains log-bin
Submitted: 25 Oct 2015 23:54 Modified: 16 Dec 2015 8:45
Reporter: Giuseppe Maxia (OCA) Email Updates:
Status: Closed Impact on me:
Category:MySQL Package Repos Severity:S2 (Serious)
Version:5.7.9 OS:Any
Assigned to: Lars Tangvald CPU Architecture:Any

[25 Oct 2015 23:54] Giuseppe Maxia
Using MySQL 5.7.9 image from Docker, the container fails to start if it is using a configuration file that includes log-bin.

How to repeat:
cat my-minimal.cnf

log-bin		= mysql-bin
server-id	= 100

docker run --name boxedmysql    \
     -e MYSQL_ROOT_PASSWORD=secret  \
    -v $PWD/my-minimal.cnf:/etc/my.cnf   -d mysql/mysql-server

Suggested fix:
The reason for the failure is in this line from entrypoint.sh

DATADIR="$("$@" --verbose --help --innodb-read-only 2>/dev/null | awk '$1 == "datadir" { print $2; exit }')"

When the configuration file passed as a volume contains "log-bin", the server creates mysql-bin.index in the data directory, and the next call to mysqld --initialize-insecure fails because the directory is not empty.

A possible fix is to modify the line above to include --no-defaults
[25 Oct 2015 23:55] Giuseppe Maxia
updated the title
[26 Oct 2015 9:52] Lars Tangvald
Unfortunately, we can't add --no-defaults, since the point of the command is to extract any non-default datadir that might be specified by the user on the command line or in a custom config file.

Adding --log-bin-index=/tmp/something to the command would fix it, but we'll see if we can think of something that's less of a hack.

This issue will also affect the Docker-maintained image if a custom datadir is used, so we'll also pass it along to them.

Thanks for the report :)
[26 Oct 2015 13:39] Giuseppe Maxia
I think the real bug here is the server creating the binary log index before anything else is available.

In the instance maintained by Docker this problem does not occur, because they use the deprecated mysql_install_db (which can overwrite contents in a populated data directory).
[26 Oct 2015 14:04] Lars Tangvald
The Docker-maintained image was a few days late to get updated to default/latest, but overall we keep them mostly in sync: https://github.com/docker-library/mysql/blob/master/5.7/docker-entrypoint.sh

The same issue will exist there, with the added requirement that datadir needs to be mapped to somewhere writeable. This is because in the Debian base image used /var/lib/mysql won't actually be writeable when mysqld --verbose --help is run.

We had a similar issue a while back with the innodb initialization for the same command also locking files in datadir: http://bugs.mysql.com/bug.php?id=75995.

As you say, the real issue is that the server is creating these files when running --verbose --help, but until that gets fixed we'll probably add the workaround.
[27 Oct 2015 8:21] Lars Tangvald
We have updated the mysql/mysql-server image with the workaround mentioned above. Can you verify it fixes the problem for you?
[27 Oct 2015 12:34] Giuseppe Maxia
Now the installation fails always, with or without the added volume.
I can't debug it right now, but the added option has a dangerous side effect.

$ docker run --name boxedmysql  -e MYSQL_ROOT_PASSWORD=secret   -d mysql/mysql-server:latest

$ docker exec -it boxedmysql bash
Error response from daemon: Container boxedmysql is not running
[27 Oct 2015 12:53] Lars Tangvald
I'm unable to reproduce this error.

Could you give the output of 
 docker logs boxedmysql
 docker info
[27 Oct 2015 13:02] Giuseppe Maxia
$ docker logs -f boxedmysql
Initializing database
2015-10-27T12:59:12.225949Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2015-10-27T12:59:12.227115Z 0 [ERROR] --initialize specified but the data directory has files in it. Aborting.
2015-10-27T12:59:12.227166Z 0 [ERROR] Aborting

$ docker info
Containers: 25
Images: 110
Storage Driver: aufs
 Root Dir: /mnt/sda1/var/lib/docker/aufs
 Backing Filesystem: extfs
 Dirs: 160
 Dirperm1 Supported: true
Execution Driver: native-0.2
Logging Driver: json-file
Kernel Version: 4.1.10-boot2docker
Operating System: Boot2Docker 1.8.3 (TCL 6.4); master : af8b089 - Mon Oct 12 18:56:54 UTC 2015
CPUs: 1
Total Memory: 1.956 GiB
Name: default
Debug mode (server): true
File Descriptors: 13
Goroutines: 18
System Time: 2015-10-27T13:01:57.054931788Z
EventsListeners: 0
Init SHA1:
Init Path: /usr/local/bin/docker
Docker Root Dir: /mnt/sda1/var/lib/docker
[27 Oct 2015 13:08] Lars Tangvald
Did you run docker pull mysql/mysql-server?
Docker doesn't automatically check for updates when using run, I think.
[27 Oct 2015 13:26] Giuseppe Maxia
yes, I did.

$ docker images
REPOSITORY           TAG                 IMAGE ID            CREATED             VIRTUAL SIZE
mysql/mysql-server   latest              dda9d0aa2a51        5 hours ago         278.2 MB
[27 Oct 2015 13:54] Lars Tangvald
Thought maybe it had to do with boot2docker, but still works for me using that.

Do you think you could upload the image ("docker commit" the container to a new image, then "docker save" the image to a file) to us?
[27 Oct 2015 14:29] Giuseppe Maxia
I am on the road. I will do it when I am back behind a better connection
[27 Oct 2015 14:35] Lars Tangvald
No problem, and thanks :)
[27 Oct 2015 14:42] Giuseppe Maxia
I made another pass. I removed all other images except mysql/mysql-server, and I got a different error in the logs.

$ docker logs boxed
Initializing database
2015-10-27T14:35:41.198712Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2015-10-27T14:35:41.227928Z 0 [Warning] InnoDB: Retry attempts for writing partial data failed.
2015-10-27T14:35:41.228050Z 0 [ERROR] InnoDB: Write to file ./ibdata1failed at offset 0, 1048576 bytes should have been written, only 0 were written. Operating system error number 28. Check that your OS and file system support files of this size. Check also that the disk is not full or a disk quota exceeded.
2015-10-27T14:35:41.228213Z 0 [ERROR] InnoDB: Error number 28 means 'No space left on device'
2015-10-27T14:35:41.228258Z 0 [ERROR] InnoDB: Could not set the file size of './ibdata1'. Probably out of disk space
2015-10-27T14:35:41.228293Z 0 [ERROR] InnoDB: InnoDB Database creation was aborted with error Generic error. You may need to delete the ibdata1 file before trying to start up again.
2015-10-27T14:35:41.833299Z 0 [ERROR] Plugin 'InnoDB' init function returned error.
2015-10-27T14:35:41.833395Z 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2015-10-27T14:35:41.833466Z 0 [ERROR] Failed to initialize plugins.
2015-10-27T14:35:41.833495Z 0 [ERROR] Aborting

This could be an issue with boot2docker. Once I go back to a Linux machine, I might be able to analyse things better.
[27 Oct 2015 15:47] Lars Tangvald
Your docker info output reported 25 containers and 110 images, so that might be it. Containers especially can fill up a drive fast.
[27 Oct 2015 16:47] Giuseppe Maxia
The problem was that the space for volumes was exhausted. I don't have this problem when running on Linux, because I can use external volumes for data directories. With boot2docker, the volumes stay inside the VM.
Sorry for the unnecessary lengthy exchange.

Summing up: Your patch fixes the issue.  Many thanks!
[27 Oct 2015 19:52] Lars Tangvald
Glad to hear it! Then we'll keep the workaround until the server bug is fixed.
[27 Oct 2015 20:31] Giuseppe Maxia
Filed Bug#78986 about the server behavior
[28 Oct 2015 8:41] Lars Tangvald
A workaround has been added to the Docker image, pending fixing of #78986.
[8 Dec 2015 22:07] Giuseppe Maxia
Bug#78986 is now fixed.
The workaround for this bug could be removed.
[16 Dec 2015 8:45] Lars Tangvald
Posted by developer:
Underlying server bug has been fixed