add documentation about clearing migrations lock (w/ FAQ/Troubleshooting entry for Heroku)

[julianriedelsheimer]

I hosted metabase on heroku and it has been working fine for 1 or 2 weeks. sometimes I got the following error:

2016-02-10T08:42:12.782052+00:00 app[web.1]: 2016-02-10 08:42:12,782 [ERROR] metabase.middleware :: GET /api/health 503 (0 ms) 2016-02-10T08:42:12.782055+00:00 app[web.1]: {:status "initializing", :progress 0.3}

after heroku restart -a APP_NAME it worked again. But since 2 or 3 days restarting heroku does not fix it anymore. I keep getting the error.

Do you know what this could be? thank you!

[agilliland]

Hi @julianriedelsheimer , can you post more of the application log that is written when the application loads up? I'm guessing there is something in there that can give us a clue about what's going on.

[julianriedelsheimer]

thx for getting back. sure. heroku restart -a APP_name gives me the following:

2016-02-10T21:52:06.384525+00:00 heroku[web.1]: State changed from down to starting
2016-02-10T21:52:12.499147+00:00 heroku[web.1]: Starting process with command `./bin/start`
2016-02-10T21:52:13.863332+00:00 app[web.1]: Picked up JAVA_TOOL_OPTIONS: -Xmx350m -Xss512k -Dfile.encoding=UTF-8
2016-02-10T21:52:13.845802+00:00 app[web.1]: Setting JAVA_TOOL_OPTIONS defaults based on dyno size. Custom settings will override them.
2016-02-10T21:52:17.069679+00:00 app[web.1]: 2016-02-10 21:52:17,068 [INFO ] org.eclipse.jetty.util.log :: Logging initialized @3204ms
2016-02-10T21:52:22.260137+00:00 app[web.1]: WARNING: update already refers to: #'clojure.core/update in namespace: clj-http.client, being replaced by: #'clj-http.client/update
2016-02-10T21:52:22.534579+00:00 app[web.1]: 2016-02-10 21:52:22,534 [INFO ] metabase.core :: Starting Metabase in STANDALONE mode
2016-02-10T21:52:22.618599+00:00 app[web.1]: 2016-02-10 21:52:22,618 [INFO ] org.eclipse.jetty.server.ServerConnector :: Started ServerConnector@35c00c{HTTP/1.1}{0.0.0.0:34043}
2016-02-10T21:52:22.618788+00:00 app[web.1]: 2016-02-10 21:52:22,618 [INFO ] org.eclipse.jetty.server.Server :: Started @8755ms
2016-02-10T21:52:22.628188+00:00 app[web.1]: 2016-02-10 21:52:22,628 [INFO ] metabase.core :: Starting Metabase version v0.13.2 (c9afde0 HEAD)...
2016-02-10T21:52:22.560862+00:00 app[web.1]: 2016-02-10 21:52:22,560 [INFO ] metabase.core :: Launching Embedded Jetty Webserver with config:
2016-02-10T21:52:22.560865+00:00 app[web.1]:  {:port 34043}
2016-02-10T21:52:22.560867+00:00 app[web.1]:
2016-02-10T21:52:22.578368+00:00 app[web.1]: 2016-02-10 21:52:22,578 [INFO ] org.eclipse.jetty.server.Server :: jetty-9.2.z-SNAPSHOT
2016-02-10T21:52:22.650471+00:00 heroku[web.1]: State changed from starting to up
2016-02-10T21:52:23.158846+00:00 app[web.1]: 2016-02-10 21:52:23,157 [INFO ] metabase.driver :: loading driver namespace:  metabase.driver.h2
2016-02-10T21:52:23.263356+00:00 app[web.1]: 2016-02-10 21:52:23,263 [INFO ] metabase.driver :: loading driver namespace:  metabase.driver.mongo
2016-02-10T21:52:23.259406+00:00 app[web.1]: 2016-02-10 21:52:23,259 [DEBUG] metabase.driver :: Registered driver :h2.
2016-02-10T21:52:23.635066+00:00 app[web.1]: 2016-02-10 21:52:23,635 [INFO ] metabase.driver :: loading driver namespace:  metabase.driver.mysql
2016-02-10T21:52:23.649662+00:00 app[web.1]: 2016-02-10 21:52:23,649 [INFO ] metabase.driver :: loading driver namespace:  metabase.driver.postgres
2016-02-10T21:52:23.671066+00:00 app[web.1]: 2016-02-10 21:52:23,670 [INFO ] metabase.driver :: loading driver namespace:  metabase.driver.redshift
2016-02-10T21:52:23.682010+00:00 app[web.1]: 2016-02-10 21:52:23,681 [INFO ] metabase.driver :: loading driver namespace:  metabase.driver.sqlite
2016-02-10T21:52:23.696209+00:00 app[web.1]: 2016-02-10 21:52:23,696 [INFO ] metabase.driver :: loading driver namespace:  metabase.driver.sqlserver
2016-02-10T21:52:23.717039+00:00 app[web.1]: 2016-02-10 21:52:23,716 [INFO ] metabase.driver :: loading driver namespace:  metabase.driver.sync
2016-02-10T21:52:23.633983+00:00 app[web.1]: 2016-02-10 21:52:23,633 [DEBUG] metabase.driver :: Registered driver :mongo.
2016-02-10T21:52:23.648676+00:00 app[web.1]: 2016-02-10 21:52:23,648 [DEBUG] metabase.driver :: Registered driver :mysql.
2016-02-10T21:52:23.665456+00:00 app[web.1]: 2016-02-10 21:52:23,665 [DEBUG] metabase.driver :: Registered driver :postgres.
2016-02-10T21:52:23.681028+00:00 app[web.1]: 2016-02-10 21:52:23,680 [DEBUG] metabase.driver :: Registered driver :redshift.
2016-02-10T21:52:23.695332+00:00 app[web.1]: 2016-02-10 21:52:23,695 [DEBUG] metabase.driver :: Registered driver :sqlite.
2016-02-10T21:52:23.709205+00:00 app[web.1]: 2016-02-10 21:52:23,709 [DEBUG] metabase.driver :: Registered driver :sqlserver.
2016-02-10T21:52:24.284869+00:00 app[web.1]: 2016-02-10 21:52:24,284 [INFO ] metabase.db :: Verifying Database Connection ...
2016-02-10T21:52:24.502886+00:00 app[web.1]: 2016-02-10 21:52:24,502 [INFO ] metabase.db :: Verify Database Connection ... CHECK

after opening the url in the browser I get the following:

2016-02-10T21:53:46.763119+00:00 heroku[router]: at=info method=GET path="/" host=dwh-99chairs.herokuapp.com request_id=aafd573c-ff59-46fc-b47c-42440bde79f6 fwd="95.91.212.81" dyno=web.1 connect=0ms service=52ms status=200 bytes=3371
2016-02-10T21:53:47.072005+00:00 heroku[router]: at=info method=GET path="/api/health" host=dwh-99chairs.herokuapp.com request_id=ba133ff9-3b49-407d-908e-5c6971c42834 fwd="95.91.212.81" dyno=web.1 connect=1ms service=27ms status=503 bytes=414
2016-02-10T21:53:47.046446+00:00 app[web.1]: 2016-02-10 21:53:47,046 [DEBUG] metabase.middleware :: GET /api/health
2016-02-10T21:53:47.062487+00:00 app[web.1]: 2016-02-10 21:53:47,062 [ERROR] metabase.middleware :: GET /api/health 503 (2 ms)
2016-02-10T21:53:47.062492+00:00 app[web.1]: {:status "initializing", :progress 0.3}
2016-02-10T21:53:47.062493+00:00 app[web.1]:
2016-02-10T21:53:47.803847+00:00 heroku[router]: at=info method=GET path="/api/health" host=dwh-99chairs.herokuapp.com request_id=326d47c9-9ce9-49d6-9f4c-e0b426405412 fwd="95.91.212.81" dyno=web.1 connect=0ms service=20ms status=503 bytes=414
2016-02-10T21:53:47.788554+00:00 app[web.1]: 2016-02-10 21:53:47,788 [DEBUG] metabase.middleware :: GET /api/health
2016-02-10T21:53:47.796124+00:00 app[web.1]: 2016-02-10 21:53:47,796 [ERROR] metabase.middleware :: GET /api/health 503 (0 ms)
2016-02-10T21:53:47.796127+00:00 app[web.1]: {:status "initializing", :progress 0.3}
2016-02-10T21:53:47.796129+00:00 app[web.1]:
2016-02-10T21:53:48.352006+00:00 app[web.1]: 2016-02-10 21:53:48,351 [DEBUG] metabase.middleware :: GET /api/health
2016-02-10T21:53:48.356950+00:00 app[web.1]: 2016-02-10 21:53:48,356 [ERROR] metabase.middleware :: GET /api/health 503 (0 ms)

repeating every second.

[whatthewhat]

Seeing this with our setup as well, restarting does not seem to help though.
Tried running on different dyno sizes (1X, 2X, even Pm) - no changes, so does not seem to be connected to limited resources on heroku.

For us this started happening yesterday, about a week after we upgraded to 0.14.1.

2016-02-17T16:40:56.431975+00:00 app[web.1]: 2016-02-17 16:40:56,431 [ERROR] metabase.middleware :: �[31mGET /api/health 503 (229 ?s)�[0m
2016-02-17T16:40:56.431979+00:00 app[web.1]: {:status "initializing", :progress 0.4}
2016-02-17T16:40:57.443832+00:00 heroku[router]: at=info method=GET path="/api/health" host=visible-metabase.herokuapp.com request_id=d85b4838-edcb-4131-8136-3a34804ad525 fwd="46.73.150.78" dyno=web.1 connect=1ms service=20ms status=503 bytes=414
2016-02-17T16:40:57.437554+00:00 app[web.1]: {:status "initializing", :progress 0.4}
2016-02-17T16:40:58.422213+00:00 heroku[router]: at=info method=GET path="/api/health" host=visible-metabase.herokuapp.com request_id=d6c06787-9bba-42b8-95b5-4e5e730545b1 fwd="46.73.150.78" dyno=web.1 connect=5ms service=9ms status=503 bytes=414
2016-02-17T16:40:58.415050+00:00 app[web.1]: 2016-02-17 16:40:58,414 [ERROR] metabase.middleware :: �[31mGET /api/health 503 (273 ?s)�[0m
2016-02-17T16:40:58.415054+00:00 app[web.1]: {:status "initializing", :progress 0.4}
2016-02-17T16:40:58.415056+00:00 app[web.1]: 2016-02-17T16:40:58.415056+00:00 app[web.1]: 
2016-02-17T16:40:59.433293+00:00 heroku[router]: at=info method=GET path="/api/health" host=visible-metabase.herokuapp.com request_id=2046dc30-fc66-47ec-be2b-45744e83d195 fwd="46.73.150.78" dyno=web.1 connect=2ms service=23ms status=503 bytes=414
2016-02-17T16:40:59.434477+00:00 app[web.1]: 2016-02-17 16:40:59,434 [ERROR] metabase.middleware :: �[31mGET /api/health 503 (195 ?s)�[0m

[whatthewhat]

@agilliland Some more info about the issue:

Tried a clean install on heroku - it worked fine, but after pointing it to the database from our original install it hangs on {:status "initializing", :progress 0.4}.

So it looks like Metabase's db might be corrupted/has some weird data, is there a way to debug what exactly is going wrong during the initialization process?

[agilliland]

@whatthewhat are you able to directly connect to the postgres database which contains the Metabase application data? i'm curious what you see if you do select * from DATABASECHANGELOGLOCK

[whatthewhat]

@agilliland

id	locked	lockgranted	lockedby
1	true	2016-02-16 08:29:34.762	cc2542bd-dc99-41c7-b003-3f1bb9f2983b.prvt.dyno.rt.heroku.com (172.18.94.114)

Should I just delete this record?

[agilliland]

Yes. go ahead and delete that row and then restart the Metabase instance and lets see if it starts up properly.

[whatthewhat]

Yep, that worked! Thanks a lot for the help! :)

[agilliland]

good hear. i've updated this ticket to capture a task around adding some more documentation about this particular issue and how to resolve it.

[camsaul]

We have a command to release the migration lock automatically. java -jar metabase.jar migrate release-locks or lein run migrate release-locks. I added it in #1085