Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Docker Image won't start - Starting DB Migration #13630

Closed
B3DTech opened this issue Oct 11, 2018 · 28 comments
Closed

Docker Image won't start - Starting DB Migration #13630

B3DTech opened this issue Oct 11, 2018 · 28 comments
Labels
needs more info Issue needs more information, like query results, dashboard or panel json, grafana version etc

Comments

@B3DTech
Copy link

B3DTech commented Oct 11, 2018

What Grafana version are you using? 5.1.0

What OS are you running grafana on? Docker Image

Using a sqlite3 database. Everything was up and running and working fine for weeks. I went back to it today to pick up where I left off, and I couldn't access anything. Since I am using persistent storage, I reset the container, and now it's stuck "Starting DB Migration". I see that the persistent volume is still mounted to /var/lib/grafana

-rw-r--r-- 1 104 107 1.9M Sep 10 13:36 grafana.db

10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Starting Grafana" logger=server version=5.1.0 commit=844bdc53a compiled=2018-04-26T15:09:23+0000
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Config loaded from" logger=settings file=/usr/share/grafana/conf/defaults.ini
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Config loaded from" logger=settings file=/etc/grafana/grafana.ini
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.data=/var/lib/grafana"
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.logs=/var/log/grafana"
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.plugins=/var/lib/grafana/plugins"
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.provisioning=/etc/grafana/provisioning"
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Config overridden from command line" logger=settings arg="default.log.mode=console"
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_PATHS_DATA=/var/lib/grafana"
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_PATHS_LOGS=/var/log/grafana"
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_PATHS_PLUGINS=/var/lib/grafana/plugins"
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_PATHS_PROVISIONING=/etc/grafana/provisioning"
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_SECURITY_ADMIN_USER=admin"
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_SECURITY_ADMIN_PASSWORD=*********"
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_AUTH_ANONYMOUS_ENABLED=true"
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_AUTH_BASIC_ENABLED=true"
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Path Home" logger=settings path=/usr/share/grafana
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Path Data" logger=settings path=/var/lib/grafana
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Path Logs" logger=settings path=/var/log/grafana
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Path Plugins" logger=settings path=/var/lib/grafana/plugins
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Path Provisioning" logger=settings path=/etc/grafana/provisioning
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="App mode production" logger=settings
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Initializing DB" logger=sqlstore dbtype=sqlite3
10/11/2018 12:21:29 PM t=2018-10-11T16:21:29+0000 lvl=info msg="Starting DB migration" logger=migrator
@B3DTech
Copy link
Author

B3DTech commented Oct 11, 2018

Additional info - I did see a forum thread about permissions to the files. I updated the permissions to the folder and files so they are now Grafana:grafana again. Still stuck Starting DB Migration

@B3DTech
Copy link
Author

B3DTech commented Oct 11, 2018

Looks like I have another container behaving the same. Grafana becomes unavailable. If I log into the container:

service grafana-server status

[FAIL] grafana is not running ... failed!

If I start it, it says it starts successfully, but I have the exact same "Starting DB Migration" status it's stuck on too.

@torkelo
Copy link
Member

torkelo commented Oct 11, 2018

Must be some issue with the volume, either the sqlite3 db is locked or corrupt or something is blocking access. We have no other reports like this:

Check out this guide:
http://docs.grafana.org/installation/docker/#migration-from-a-previous-version-of-the-docker-container-to-5-1-or-later

Also try upgrading to v5.3

@torkelo torkelo added the needs more info Issue needs more information, like query results, dashboard or panel json, grafana version etc label Oct 11, 2018
@MaxDiOrio
Copy link

Not sure where a lock would possibly come from. The database is stored in a persistent volume, only mounted to this container. I highly doubt two different Grafana databases would go corrupt at the same time. And one of the Grafana containers is only running 5.0.0, and has never been restarted since it was brought online 8/29/18, so nothing has changed there. In both instances, everything was working fine, then it wasn't. When I investigated, the logs showed no errors at all, but the service was stopped and marked failed.

@torkelo
Copy link
Member

torkelo commented Oct 11, 2018

well something is causing io timeouts for trying to read or write to DB.

@MaxDiOrio
Copy link

Well I can take the NFS mount that the grafana.db file is living on, which is currently mounted in the container and supposedly being used by grafana (service is started), mount the nfs volume on my Mac, open the database, read it and write to it without a problem.

So nothing is locking it.

@marefr
Copy link
Member

marefr commented Oct 12, 2018

Sqlite3 and NFS is knows for creating locking issues, see https://www.sqlite.org/faq.html#q5.

@MaxDiOrio
Copy link

So proving the dB is valid and not being locked by something else doesn't mean anything to you. The article you point to references not being able to lock the dB for writing which has never been an issue since there has only ever been a single process accessing the database. I can see that there is no help here.

@marefr
Copy link
Member

marefr commented Oct 12, 2018

Did you use a different version of Grafana before v5.1.0? Was thinking of the docker changes we did for v5.1.0, see documentation.

@MaxDiOrio
Copy link

One one, yes, I upgraded from 5.0 and fixed the permissions issues on the persistent volume.

The other hasn't changed from 5.0 from the day it was brought up. The container was never restarted, uptime is 35 days. No network, hardware or storage interruptions. It just randomly stopped after the container was up and working for a few weeks.

@marefr
Copy link
Member

marefr commented Oct 12, 2018

Thanks. You're sure that your Grafana containers not are using the same persistent volume and basically reading/writing to the same sqlite database?

Would suggest you to turn on debug logging and see if you get any more information from the Grafana server log.

@MaxDiOrio
Copy link

I'm 100% positive. They are in separate volumes. They serve different applications.

I'll have to figure out how to get the debug logging on. There's no way to edit the file from within the container.

@MaxDiOrio
Copy link

Well isn't this fun. I set the environment variable GF_LOG_LEVEL=debug per documentation. The log says:

lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_LOG_LEVEL=debug"

I can echo the variable from the console.

Yet it's still only giving Info level messages.

@MaxDiOrio
Copy link

Not sure it helps, but if I run Grafana-server from the console, wait for it to "hang" then terminate the process, here's the output:

grafana-server --homepath="$GF_PATHS_HOME" --config="$GF_PATHS_CONFIG" -test.v
INFO[10-12|18:39:19] Starting Grafana logger=server version=5.1.0 commit=844bdc53a compiled=2018-04-26T15:09:23+0000
INFO[10-12|18:39:19] Config loaded from logger=settings file=/usr/share/grafana/conf/defaults.ini
INFO[10-12|18:39:19] Config loaded from logger=settings file=/etc/grafana/grafana.ini
INFO[10-12|18:39:19] Config overridden from Environment variable logger=settings var="GF_PATHS_DATA=/var/lib/grafana"
INFO[10-12|18:39:19] Config overridden from Environment variable logger=settings var="GF_PATHS_LOGS=/var/log/grafana"
INFO[10-12|18:39:19] Config overridden from Environment variable logger=settings var="GF_PATHS_PLUGINS=/var/lib/grafana/plugins"
INFO[10-12|18:39:19] Config overridden from Environment variable logger=settings var="GF_PATHS_PROVISIONING=/etc/grafana/provisioning"
INFO[10-12|18:39:19] Config overridden from Environment variable logger=settings var="GF_SECURITY_ADMIN_USER=admin"
INFO[10-12|18:39:19] Config overridden from Environment variable logger=settings var="GF_SECURITY_ADMIN_PASSWORD=*********"
INFO[10-12|18:39:19] Config overridden from Environment variable logger=settings var="GF_AUTH_ANONYMOUS_ENABLED=true"
INFO[10-12|18:39:19] Config overridden from Environment variable logger=settings var="GF_AUTH_BASIC_ENABLED=true"
INFO[10-12|18:39:19] Config overridden from Environment variable logger=settings var="GF_LOG_LEVEL=debug"
INFO[10-12|18:39:19] Path Home logger=settings path=/usr/share/grafana
INFO[10-12|18:39:19] Path Data logger=settings path=/var/lib/grafana
INFO[10-12|18:39:19] Path Logs logger=settings path=/var/log/grafana
INFO[10-12|18:39:19] Path Plugins logger=settings path=/var/lib/grafana/plugins
INFO[10-12|18:39:19] Path Provisioning logger=settings path=/etc/grafana/provisioning
INFO[10-12|18:39:19] App mode production logger=settings
INFO[10-12|18:39:19] Initializing DB logger=sqlstore dbtype=sqlite3
INFO[10-12|18:39:19] Starting DB migration logger=migrator
^CINFO[10-12|18:39:22] Shutdown started logger=server code=0 reason="system signal: interrupt"
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x38 pc=0xe590f6]

goroutine 9 [running]:
github.com/grafana/grafana/pkg/api.(*HTTPServer).Shutdown(0x0, 0x1518200, 0xc420276d00, 0xc420031580, 0x4)
/go/src/github.com/grafana/grafana/pkg/api/http_server.go:100 +0x26
main.(*GrafanaServerImpl).Shutdown(0xc420276d80, 0x0, 0xc420037080, 0x18)
/go/src/github.com/grafana/grafana/pkg/cmd/grafana-server/server.go:137 +0x196
main.listenToSystemSignals(0xc420276d80, 0xc4201800c0)
/go/src/github.com/grafana/grafana/pkg/cmd/grafana-server/main.go:113 +0x346
created by main.main
/go/src/github.com/grafana/grafana/pkg/cmd/grafana-server/main.go:84 +0x28b

@marefr
Copy link
Member

marefr commented Oct 15, 2018

Instead of running Grafana-server from the console can you run the grafana-cli and reset the admin password - that will also trigger the database migration and it will do it without anything else interfering. If you haven't changed admin password you can provide the default admin.

grafana-cli admin reset-admin-password <admin password>

@MaxDiOrio
Copy link

Hangs in exactly the same spot

$ grafana-cli admin reset-admin-password newpassword
INFO[10-15|17:16:22] Connecting to DB logger=sqlstore dbtype=sqlite3
INFO[10-15|17:16:22] Starting DB migration logger=migrator

@torkelo
Copy link
Member

torkelo commented Oct 15, 2018

Strange, something is locking your SQLite db file, can you download sqlite3 and try to open the db file and read from user table?

@MaxDiOrio
Copy link

Well I can take the NFS mount that the grafana.db file is living on, which is currently mounted in the container and supposedly being used by grafana (service is started), mount the nfs volume on my Mac, open the database, read it and write to it without a problem.

@torkelo
Copy link
Member

torkelo commented Oct 16, 2018

Can you do the same from within the container?

@MaxDiOrio
Copy link

The container doesn't have sqlite3 in it.

@DeDu
Copy link

DeDu commented Oct 31, 2018 •
edited

I also started a docker instance of the newest grafana 5.3. Yesterday it worked fine, today I can't reach the application anymore with the browser.

The container is still running, and when using docker logs grafana I get:

t=2018-10-31T08:39:15+0000 lvl=info msg="Starting Grafana" logger=server version=5.3.2 commit=0d821d0 compiled=2018-10-24T12:06:27+0000
t=2018-10-31T08:39:15+0000 lvl=info msg="Config loaded from" logger=settings file=/usr/share/grafana/conf/defaults.ini
t=2018-10-31T08:39:15+0000 lvl=info msg="Config loaded from" logger=settings file=/etc/grafana/grafana.ini
t=2018-10-31T08:39:15+0000 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.data=/var/lib/grafana"
t=2018-10-31T08:39:15+0000 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.logs=/var/log/grafana"
t=2018-10-31T08:39:15+0000 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.plugins=/var/lib/grafana/plugins"
t=2018-10-31T08:39:15+0000 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.provisioning=/etc/grafana/provisioning"
t=2018-10-31T08:39:15+0000 lvl=info msg="Config overridden from command line" logger=settings arg="default.log.mode=console"
t=2018-10-31T08:39:15+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_PATHS_DATA=/var/lib/grafana"
t=2018-10-31T08:39:15+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_PATHS_LOGS=/var/log/grafana"
t=2018-10-31T08:39:15+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_PATHS_PLUGINS=/var/lib/grafana/plugins"
t=2018-10-31T08:39:15+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_PATHS_PROVISIONING=/etc/grafana/provisioning"
t=2018-10-31T08:39:15+0000 lvl=info msg="Path Home" logger=settings path=/usr/share/grafana
t=2018-10-31T08:39:15+0000 lvl=info msg="Path Data" logger=settings path=/var/lib/grafana
t=2018-10-31T08:39:15+0000 lvl=info msg="Path Logs" logger=settings path=/var/log/grafana
t=2018-10-31T08:39:15+0000 lvl=info msg="Path Plugins" logger=settings path=/var/lib/grafana/plugins
t=2018-10-31T08:39:15+0000 lvl=info msg="Path Provisioning" logger=settings path=/etc/grafana/provisioning
t=2018-10-31T08:39:15+0000 lvl=info msg="App mode production" logger=settings
t=2018-10-31T08:39:15+0000 lvl=info msg="Initializing SqlStore" logger=server
t=2018-10-31T08:39:15+0000 lvl=info msg="Connecting to DB" logger=sqlstore dbtype=sqlite3
t=2018-10-31T08:39:15+0000 lvl=info msg="Starting DB migration" logger=migrator
t=2018-10-31T08:39:15+0000 lvl=info msg="Initializing HTTPServer" logger=server
t=2018-10-31T08:39:15+0000 lvl=info msg="Initializing SearchService" logger=server
t=2018-10-31T08:39:15+0000 lvl=info msg="Initializing PluginManager" logger=server
t=2018-10-31T08:39:15+0000 lvl=info msg="Starting plugin search" logger=plugins
t=2018-10-31T08:39:15+0000 lvl=info msg="Initializing InternalMetricsService" logger=server
t=2018-10-31T08:39:15+0000 lvl=info msg="Initializing AlertingService" logger=server
t=2018-10-31T08:39:15+0000 lvl=info msg="Initializing CleanUpService" logger=server
t=2018-10-31T08:39:15+0000 lvl=info msg="Initializing NotificationService" logger=server
t=2018-10-31T08:39:15+0000 lvl=info msg="Initializing ProvisioningService" logger=server
t=2018-10-31T08:39:15+0000 lvl=info msg="Initializing RenderingService" logger=server
t=2018-10-31T08:39:15+0000 lvl=info msg="Initializing TracingService" logger=server
t=2018-10-31T08:39:15+0000 lvl=info msg="Initializing Stream Manager"
t=2018-10-31T08:39:15+0000 lvl=info msg="HTTP Server Listen" logger=http.server address=0.0.0.0:3000 protocol=http subUrl= socket=

@MaxDiOrio
Copy link

That looks like it's up and running on port 3000.

@DeDu
Copy link

DeDu commented Oct 31, 2018 via email

@MaxDiOrio
Copy link

MaxDiOrio commented Oct 31, 2018 via email

@DeDu
Copy link

DeDu commented Oct 31, 2018 via email

@MaxDiOrio
Copy link

But the log time stamp is from the 31st, so the container must have restarted at some point today. Maybe restart the container. Either way, you should probably be posting this as a new question because it doesn't relate to my original question.

@MaxDiOrio
Copy link

So I found the issue with my original question. There was actually a bug we were running into with the NetApp firmware that was exhausting the locks allowed for the host. That's why it worked fine from another host. We upgraded the firmware per NetApp support and all is well again.

@bergquist
Copy link
Contributor

Closing this since the issue have been solved

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
needs more info Issue needs more information, like query results, dashboard or panel json, grafana version etc
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
6 participants
@torkelo @DeDu @bergquist @marefr @MaxDiOrio @B3DTech