MySQL Bugs: #78957: MySQL docker container fails to start if my.cnf contains log-bin

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:	None
Category:	MySQL Package Repos	Severity:	S2 (Serious)
Version:	5.7.9	OS:	Any
Assigned to:	Lars Tangvald	CPU Architecture:	Any

Description:
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

[mysqld]
user=mysql
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

updated the title

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 :)

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).

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.

We have updated the mysql/mysql-server image with the workaround mentioned above. Can you verify it fixes the problem for you?

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
629eb35a24c61d62c2b5a46dd6fde398a6a274030539e8cc065f1b79acca525a

$ docker exec -it boxedmysql bash
Error response from daemon: Container boxedmysql is not running

I'm unable to reproduce this error.

Could you give the output of 
 docker logs boxedmysql
and
 docker info
?

$ 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
ID: Z4BU:43UZ:E72J:UGWY:MWT5:7MYG:IP6C:GAEX:HM7D:5TYF:N2SS:43VX
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
Labels:
 provider=virtualbox

Did you run docker pull mysql/mysql-server?
Docker doesn't automatically check for updates when using run, I think.

yes, I did.

$ docker images
REPOSITORY           TAG                 IMAGE ID            CREATED             VIRTUAL SIZE
mysql/mysql-server   latest              dda9d0aa2a51        5 hours ago         278.2 MB

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?

I am on the road. I will do it when I am back behind a better connection

No problem, and thanks :)

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.

Your docker info output reported 25 containers and 110 images, so that might be it. Containers especially can fill up a drive fast.

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!

Glad to hear it! Then we'll keep the workaround until the server bug is fixed.

Filed Bug#78986 about the server behavior

A workaround has been added to the Docker image, pending fixing of #78986.

Bug#78986 is now fixed.
The workaround for this bug could be removed.

Posted by developer:
 
Underlying server bug has been fixed