This repository was archived by the owner on Jun 28, 2018. It is now read-only.
This repository was archived by the owner on Jun 28, 2018. It is now read-only.
ErrLocked in some cases #220
Description
I have some inconsistent results when applying migrations. I tracked it down to GET_LOCK sometimes returning false.
First, I created one migration which sets up all the initial tables. That failed (well, tables are correctly set up, but there is an error returned):
$ make && ./content drop && ./content migrate
go build -o content github.com/meplato/mall/content/cmd/content
2017/05/10 13:08:27 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:165: Lock: aid="14967765"
2017/05/10 13:08:27 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:174: Lock: success=true
2017/05/10 13:08:27 .../github.com/meplato/mall/content/mysql/migrate.go:38: Start buffering 1/u initial
2017/05/10 13:08:27 .../github.com/meplato/mall/content/mysql/migrate.go:38: Read and execute 1/u initial
2017/05/10 13:08:27 .../github.com/meplato/mall/content/mysql/migrate.go:38: Finished 1/u initial (read 2.705766ms, ran 39.73851ms)
2017/05/10 13:08:27 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:165: Lock: aid="14967765"
2017/05/10 13:08:28 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:174: Lock: success=false
2017/05/10 13:08:28 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:165: Lock: aid="14967765"
2017/05/10 13:08:29 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:174: Lock: success=false
2017/05/10 13:08:29 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:165: Lock: aid="14967765"
2017/05/10 13:08:30 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:174: Lock: success=false
2017/05/10 13:08:30 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:165: Lock: aid="14967765"
2017/05/10 13:08:32 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:174: Lock: success=false
2017/05/10 13:08:32 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:165: Lock: aid="14967765"
2017/05/10 13:08:33 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:174: Lock: success=false
Error: cannot migrate MySQL: DB migration failed: can't acquire lock
Next, I simply removed the last table create statement and put it into a 2nd migration. That worked:
$ make && ./content drop && ./content migrate
go build -o content github.com/meplato/mall/content/cmd/content
2017/05/10 13:09:22 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:165: Lock: aid="14967765"
2017/05/10 13:09:22 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:174: Lock: success=true
2017/05/10 13:09:22 .../github.com/meplato/mall/content/mysql/migrate.go:38: Start buffering 1/u initial
2017/05/10 13:09:22 .../github.com/meplato/mall/content/mysql/migrate.go:38: Start buffering 2/u create_journal
2017/05/10 13:09:22 .../github.com/meplato/mall/content/mysql/migrate.go:38: Read and execute 1/u initial
2017/05/10 13:09:22 .../github.com/meplato/mall/content/mysql/migrate.go:38: Finished 1/u initial (read 2.433246ms, ran 31.332144ms)
2017/05/10 13:09:22 .../github.com/meplato/mall/content/mysql/migrate.go:38: Read and execute 2/u create_journal
2017/05/10 13:09:22 .../github.com/meplato/mall/content/mysql/migrate.go:38: Finished 2/u create_journal (read 35.907396ms, ran 9.923508ms)
2017/05/10 13:09:22 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:165: Lock: aid="14967765"
2017/05/10 13:09:22 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:174: Lock: success=true
Okay, I thought, maybe a single migration file turns out to be a problem. But no, if I create all tables in separate migration files, it fails again:
$ make && ./content drop && ./content migrate
go build -o content github.com/meplato/mall/content/cmd/content
2017/05/10 13:15:44 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:165: Lock: aid="14967765"
2017/05/10 13:15:44 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:174: Lock: success=true
2017/05/10 13:15:44 .../github.com/meplato/mall/content/mysql/migrate.go:38: Start buffering 2017051001/u create_pipelines
2017/05/10 13:15:44 .../github.com/meplato/mall/content/mysql/migrate.go:38: Start buffering 2017051002/u create_projects
2017/05/10 13:15:44 .../github.com/meplato/mall/content/mysql/migrate.go:38: Start buffering 2017051003/u create_catalogs
2017/05/10 13:15:44 .../github.com/meplato/mall/content/mysql/migrate.go:38: Start buffering 2017051004/u create_archives
2017/05/10 13:15:44 .../github.com/meplato/mall/content/mysql/migrate.go:38: Start buffering 2017051005/u create_journal
2017/05/10 13:15:44 .../github.com/meplato/mall/content/mysql/migrate.go:38: Read and execute 2017051001/u create_pipelines
2017/05/10 13:15:44 .../github.com/meplato/mall/content/mysql/migrate.go:38: Finished 2017051001/u create_pipelines (read 26.546006ms, ran 11.728339ms)
2017/05/10 13:15:44 .../github.com/meplato/mall/content/mysql/migrate.go:38: Read and execute 2017051002/u create_projects
2017/05/10 13:15:44 .../github.com/meplato/mall/content/mysql/migrate.go:38: Finished 2017051002/u create_projects (read 41.221642ms, ran 9.393328ms)
2017/05/10 13:15:44 .../github.com/meplato/mall/content/mysql/migrate.go:38: Read and execute 2017051003/u create_catalogs
2017/05/10 13:15:44 .../github.com/meplato/mall/content/mysql/migrate.go:38: Finished 2017051003/u create_catalogs (read 52.979497ms, ran 10.750591ms)
2017/05/10 13:15:44 .../github.com/meplato/mall/content/mysql/migrate.go:38: Read and execute 2017051004/u create_archives
2017/05/10 13:15:44 .../github.com/meplato/mall/content/mysql/migrate.go:38: Finished 2017051004/u create_archives (read 65.188885ms, ran 11.061517ms)
2017/05/10 13:15:44 .../github.com/meplato/mall/content/mysql/migrate.go:38: Read and execute 2017051005/u create_journal
2017/05/10 13:15:44 .../github.com/meplato/mall/content/mysql/migrate.go:38: Finished 2017051005/u create_journal (read 78.233239ms, ran 10.624991ms)
2017/05/10 13:15:44 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:165: Lock: aid="14967765"
2017/05/10 13:15:45 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:174: Lock: success=false
2017/05/10 13:15:45 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:165: Lock: aid="14967765"
2017/05/10 13:15:47 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:174: Lock: success=false
2017/05/10 13:15:47 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:165: Lock: aid="14967765"
2017/05/10 13:15:48 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:174: Lock: success=false
2017/05/10 13:15:48 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:165: Lock: aid="14967765"
2017/05/10 13:15:49 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:174: Lock: success=false
2017/05/10 13:15:49 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:165: Lock: aid="14967765"
2017/05/10 13:15:50 .../github.com/meplato/mall/vendor/github.com/mattes/migrate/database/mysql/mysql.go:174: Lock: success=false
Error: cannot migrate MySQL: DB migration failed: can't acquire lock
I tried to extract a reproducible test, but I couldn't reproduce it yet in a test case.
BTW: I'm using MariaDB from homebrew.
$ mysql -V
mysql Ver 15.1 Distrib 10.1.23-MariaDB, for osx10.12 (x86_64) using readline 5.1
Do you have any idea why this might happen? Does this look somehow familiar to you?