ErrLocked in some cases

[olivere]

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?

[olivere]

It's very probably a mistake on my side. Sorry for the confusion.

[josephbuchma]

@olivere can you please describe what was a mistake and how you resolved it ?

[olivere]

@josephbuchma Oh, I can't quite remember the details, sorry. Maybe it was due to a missing &multiStatements=true in the connection string (see here), but I'm not sure. Just skimmed the related commit on our side, but there are no details, I'm afraid.