After Upgrade from Grafana 5 to 6, dashboard keeps logging out

Please read https://grafana.com/docs/auth/overview/#login-and-short-lived-tokens

If your changing:

[auth]
token_rotation_interval_minutes=600

You probably also want to change login_maximum_inactive_lifetime_days to something greater than 1 day.

do you know how long it took before the logout occurred?

I don’t specifically, but can say it was many hours (12+) and doesn’t seem to happen consistently on any “schedule”.

I’ve opened an issue for this scenario: https://github.com/grafana/grafana/issues/16757

@bkgann, i’ve the same problem, can u look my log?

##Error 25/04 - 03:08
t=2019-04-25T03:08:43-0300 lvl=eror msg=“failed to look up user based on cookie” logger=context error=“database is locked”

t=2019-04-25T03:08:43-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=POST path=/api/tsdb/query status=401 remote_addr=192.168.3.154 time_ms=5009 size=26 referer=“htt p://192.168.3.171:3000/d/FQMrmF3mz/manutencao?orgId=1&kiosk”

t=2019-04-25T03:08:43-0300 lvl=eror msg=“failed to look up user based on cookie” logger=context error=“database is locked”

t=2019-04-25T03:08:43-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=POST path=/api/tsdb/query status=401 remote_addr=192.168.3.154 time_ms=5008 size=26 referer=“h ttp://192.168.3.171:3000/d/FQMrmF3mz/manutencao?orgId=1&kiosk”

t=2019-04-25T03:08:43-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=GET path=/api/login/ping status=401 remote_addr=192.168.3.154 time_ms=0 size=26 referer=“h ttp://192.168.3.171:3000/d/FQMrmF3mz/manutencao?orgId=1&kiosk”

t=2019-04-25T03:08:43-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=GET path=/api/login/ping status=401 remote_addr=192.168.3.154 time_ms=0 size=26 referer=“h ttp://192.168.3.171:3000/d/FQMrmF3mz/manutencao?orgId=1&kiosk”

t=2019-04-25T03:08:43-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=GET path=/logout status=302 remote_addr=192.168.3.154 time_ms=0 size=29 referer=“h ttp://192.168.3.171:3000/d/FQMrmF3mz/manutencao?orgId=1&kiosk”

##Info 25/04 - 05:15
t=2019-04-25T05:15:10-0300 lvl=info msg=“cleanup of expired auth tokens done” logger=auth count=1

##Error 25/04 - 08:09
t=2019-04-25T08:09:03-0300 lvl=eror msg=“failed to look up user based on cookie” logger=context error=“database is locked”

t=2019-04-25T08:09:03-0300 lvl=eror msg=“failed to look up user based on cookie” logger=context error=“database is locked”

t=2019-04-25T08:09:03-0300 lvl=eror msg=“failed to look up user based on cookie” logger=context error=“database is locked”

t=2019-04-25T08:09:03-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=POST path=/api/tsdb/query status=401 remote_addr=192.168.3.110 time_ms=5008 size=26 referer=“h ttp://192.168.3.171:3000/d/JvUfgBRWz/central-de-atendimento?orgId=1”

t=2019-04-25T08:09:03-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=POST path=/api/tsdb/query status=401 remote_addr=192.168.3.110 time_ms=5009 size=26 referer=“h ttp://192.168.3.171:3000/d/JvUfgBRWz/central-de-atendimento?orgId=1”

t=2019-04-25T08:09:03-0300 lvl=eror msg=“failed to look up user based on cookie” logger=context error=“database is locked”

t=2019-04-25T08:09:03-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=POST path=/api/tsdb/query status=401 remote_addr=192.168.3.110 time_ms=5009 size=26 referer=“h ttp://192.168.3.171:3000/d/JvUfgBRWz/central-de-atendimento?orgId=1”

t=2019-04-25T08:09:03-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=POST path=/api/tsdb/query status=401 remote_addr=192.168.3.110 time_ms=5010 size=26 referer=“h ttp://192.168.3.171:3000/d/JvUfgBRWz/central-de-atendimento?orgId=1”

##Error 25/04 - 08:09
t=2019-04-25T08:09:03-0300 lvl=eror msg=“failed to look up user based on cookie” logger=context error=“database is locked”

t=2019-04-25T08:09:03-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=POST path=/api/tsdb/query status=401 remote_addr=192.168.3.110 time_ms=0 size=26 referer=“h ttp://192.168.3.171:3000/d/JvUfgBRWz/central-de-atendimento?orgId=1”

t=2019-04-25T08:09:03-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=GET path=/api/login/ping status=401 remote_addr=192.168.3.110 time_ms=0 size=26 referer=“h ttp://192.168.3.171:3000/d/JvUfgBRWz/central-de-atendimento?orgId=1”

t=2019-04-25T08:09:03-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=GET path=/api/login/ping status=401 remote_addr=192.168.3.110 time_ms=0 size=26 referer=“h ttp://192.168.3.171:3000/d/JvUfgBRWz/central-de-atendimento?orgId=1”

t=2019-04-25T08:09:03-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=GET path=/api/login/ping status=401 remote_addr=192.168.3.110 time_ms=0 size=26 referer=“h ttp://192.168.3.171:3000/d/JvUfgBRWz/central-de-atendimento?orgId=1”

t=2019-04-25T08:09:03-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=GET path=/api/login/ping status=401 remote_addr=192.168.3.110 time_ms=0 size=26 referer=“h ttp://192.168.3.171:3000/d/JvUfgBRWz/central-de-atendimento?orgId=1”

t=2019-04-25T08:09:03-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=GET path=/api/login/ping status=401 remote_addr=192.168.3.110 time_ms=0 size=26 referer=“h ttp://192.168.3.171:3000/d/JvUfgBRWz/central-de-atendimento?orgId=1”

t=2019-04-25T08:09:03-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=GET path=/logout status=302 remote_addr=192.168.3.110 time_ms=0 size=29 referer=“h ttp://192.168.3.171:3000/d/JvUfgBRWz/central-de-atendimento?orgId=1”

t=2019-04-25T08:09:03-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=GET path=/logout status=302 remote_addr=192.168.3.110 time_ms=0 size=29 referer=“h ttp://192.168.3.171:3000/d/JvUfgBRWz/central-de-atendimento?orgId=1”

Just providing more logs from recent crashes:

0-t=2019-04-23T08:12:00-0400 lvl=info msg=“cleanup of expired auth tokens done” logger=auth count=0

98:t=2019-04-23T14:57:02-0400 lvl= eror msg=“Invalid username or password” logger=context userId=0 orgId=0 uname= error=“Invalid Username or Password”

245-t=2019-04-23T14:57:02-0400 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=POST path=/login status=401 remote_addr=172.21.5.50 time_ms=37 size=42 referer=http://zabbix.vtcri.local:3000/login

467:t=2019-04-23T14:57:09-0400 lvl= eror msg=“Invalid username or password” logger=context userId=0 orgId=0 uname= error=“Invalid Username or Password”

614-t=2019-04-23T14:57:09-0400 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=POST path=/login status=401 remote_addr=172.21.5.50 time_ms=1 size=42 referer=http://zabbix.vtcri.local:3000/login

835-t=2019-04-23T15:48:41-0400 lvl=info msg=“Shutdown started” logger=server reason=“System signal: terminated”

943-t=2019-04-23T15:48:41-0400 lvl=info msg=“Stopped UsageStatsService” logger=server reason=“context canceled”

1051-t=2019-04-23T15:48:41-0400 lvl=info msg=“Stopped CleanUpService” logger=server reason=“context canceled”

1156-t=2019-04-23T15:48:41-0400 lvl=info msg=“Stopped InternalMetricsService” logger=server reason=“context canceled”

–

1620-t=2019-04-23T15:48:41-0400 lvl=info msg=“Stopped AlertingService” logger=server reason=“context canceled”

1726-t=2019-04-23T15:48:41-0400 lvl=info msg=“Stopped UserAuthTokenService” logger=server reason=“context canceled”

1837-t=2019-04-23T15:48:41-0400 lvl=info msg=“Stopped ProvisioningService” logger=server reason=“context canceled”

1947-t=2019-04-23T15:48:41-0400 lvl=info msg=“Stopped NotificationService” logger=server reason=“context canceled”

2057-t=2019-04-23T15:48:41-0400 lvl=info msg=“Stopped HTTPServer” logger=server reason=nil

2143:t=2019-04-23T15:48:41-0400 lvl= eror msg=“Server shutdown” logger=server reason=“System signal: terminated”

2250-t=2019-04-23T15:48:46-0400 lvl=info msg=“Starting Grafana” logger=server version=6.0.1 commit=0c44a04 branch=HEAD compiled=2019-03-06T09:21:49-0500

2398-t=2019-04-23T15:48:46-0400 lvl=info msg=“Config loaded from” logger=settings file=/usr/share/grafana/conf/defaults.ini

2517-t=2019-04-23T15:48:46-0400 lvl=info msg=“Config loaded from” logger=settings file=/etc/grafana/grafana.ini

2624-t=2019-04-23T15:48:46-0400 lvl=info msg=“Config overridden from command line” logger=settings arg=“default.paths.data=/var/lib/grafana”

2760-t=2019-04-23T15:48:46-0400 lvl=info msg=“Config overridden from command line” logger=settings arg=“default.paths.logs=/var/log/grafana”

–

5781-t=2019-04-23T15:48:46-0400 lvl=info msg=“Initializing UsageStatsService” logger=server

5868-t=2019-04-23T15:48:46-0400 lvl=info msg=“Initializing UserAuthTokenService” logger=server

5958-t=2019-04-23T15:48:46-0400 lvl=info msg=“Initializing CleanUpService” logger=server

6042-t=2019-04-23T15:48:46-0400 lvl=info msg=“Initializing NotificationService” logger=server

6131-t=2019-04-23T15:48:46-0400 lvl=info msg=“Initializing ProvisioningService” logger=server

6220:t=2019-04-23T15:48:46-0400 lvl= eror msg=“can’t read datasource provisioning files from directory” logger=provisioning.datasources path=/etc/grafana/provisioning/datasources error=“open /etc/grafana/provisioning/datasources: no such file or directory”

6471:t=2019-04-23T15:48:46-0400 lvl= eror msg=“Can’t read alert notification provisioning files from directory” logger=provisioning.notifiers path=/etc/grafana/provisioning/notifiers error=“open /etc/grafana/provisioning/notifiers: no such file or directory”

6724-t=2019-04-23T15:48:46-0400 lvl=info msg=“Initializing TracingService” logger=server

6808:t=2019-04-23T15:48:46-0400 lvl= eror msg=“can’t read dashboard provisioning files from directory” logger=provisioning.dashboard path=/etc/grafana/provisioning/dashboards error=“open /etc/grafana/provisioning/dashboards: no such file or directory”

7054-t=2019-04-23T15:48:46-0400 lvl=info msg=“Initializing Stream Manager”

7124-t=2019-04-23T15:48:46-0400 lvl=info msg=“HTTP Server Listen” logger=http.server address=0.0.0.0:3000 protocol=http subUrl= socket=

7255:t=2019-04-23T16:25:36-0400 lvl= eror msg=“failed to look up user based on cookie” logger=context error=“user token not found”

7380-t=2019-04-23T16:25:36-0400 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=GET path=/ status=302 remote_addr=172.21.4.204 time_ms=1 size=29 referer=

7560-t=2019-04-23T16:25:57-0400 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=GET path=/d/000000049/vtcri-riverside-2-data-center-core-switch-vtcl2sw-9 status=302 remote_addr=172.21.5.55 time_ms=0 size=29 referer=

7802-t=2019-04-23T17:27:43-0400 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=GET path=/d/BiuPIfTmk/datacenter-1 status=302 remote_addr=172.21.6.53 time_ms=0 size=29 referer=

8005-t=2019-04-23T20:48:46-0400 lvl=info msg=“cleanup of expired auth tokens done” logger=auth count=0

Another logout… =/

##Time 11:18 in Brazil

t=2019-04-25T11:18:40-0300 lvl=eror msg=“failed to look up user based on cookie” logger=context error=“database is locked”

t=2019-04-25T11:18:40-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=POST path=/api/tsdb/query status=401 remote_addr=192.168.3.110 time_ms=5008 size=26 referer=“h ttp://192.168.3.171:3000/d/JvUfgBRWz/central-de-atendimento?orgId=1”

t=2019-04-25T11:18:40-0300 lvl=eror msg=“failed to look up user based on cookie” logger=context error=“database is locked”

t=2019-04-25T11:18:40-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=POST path=/api/tsdb/query status=401 remote_addr=192.168.3.110 time_ms=0 size=26 referer=“h ttp://192.168.3.171:3000/d/JvUfgBRWz/central-de-atendimento?orgId=1”

t=2019-04-25T11:18:40-0300 lvl=eror msg=“failed to look up user based on cookie” logger=context error=“database is locked”

t=2019-04-25T11:18:40-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=POST path=/api/tsdb/query status=401 remote_addr=192.168.3.110 time_ms=0 size=26 referer=“h ttp://192.168.3.171:3000/d/JvUfgBRWz/central-de-atendimento?orgId=1”

t=2019-04-25T11:18:40-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=GET path=/api/login/ping status=401 remote_addr=192.168.3.110 time_ms=0 size=26 referer=“h ttp://192.168.3.171:3000/d/JvUfgBRWz/central-de-atendimento?orgId=1”

t=2019-04-25T11:18:40-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=GET path=/api/login/ping status=401 remote_addr=192.168.3.110 time_ms=0 size=26 referer=“h ttp://192.168.3.171:3000/d/JvUfgBRWz/central-de-atendimento?orgId=1”

t=2019-04-25T11:18:40-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=GET path=/api/login/ping status=401 remote_addr=192.168.3.110 time_ms=0 size=26 referer=“h ttp://192.168.3.171:3000/d/JvUfgBRWz/central-de-atendimento?orgId=1”

t=2019-04-25T11:18:40-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=GET path=/logout status=302 remote_addr=192.168.3.110 time_ms=0 size=29 referer=“h ttp://192.168.3.171:3000/d/JvUfgBRWz/central-de-atendimento?orgId=1”

t=2019-04-25T11:18:40-0300 lvl=info msg=“Request Completed” logger=context userId=0 orgId=0 uname= method=GET path=/logout status=302 remote_addr=192.168.3.110 time_ms=0 size=29 referer=“h ttp://192.168.3.171:3000/d/JvUfgBRWz/central-de-atendimento?orgId=1”

@joaogvr you have a sqlite problem -> database is locked

How can i see sqlite log?

And what could be causing this lock in the db?

You can’t see any sqlite log as far as I know. One cause could be using NFS as underlying storage of Grafana/sqlite which seems common in Kubernetes/docker setups. Another cause could be too high load on the sqlite from users and alert rule evaluations. One other cause may be a bug in Grafana which I’m going to investigate.

Thanks again guys!

JFYI, our instance of Zabbix and Grafana run on the same VM and has local storage. There is no NFS involved inside the VM.

Thanks!
Jed

Hello everyone, I have exactly the same problem, can you give us a solution? The screens of my operating room close unexpectedly, it becomes complicated to manage.

Someone here got fix this ‘database is locked’?

My dashboards keeps logging out =/

We just released 6.2-beta1. Would recommend trying that out since it includes a fix that we hope should fix some of the reported problems here.

Thanks, i’ll try this version

Thank you for the update!

I installed the beta without error, and now I receive this on all existing and new dashboards:

Zabbix plugin failed

Error: Fetch error: 404 Not Found Instantiating http://zabbix.vtcri.local:3000/public/app/core/utils/datemath Loading http://zabbix.vtcri.local:3000/public/plugins/alexanderzobnin-zabbix-app/datasource-zabbix/module.js Loading plugins/alexanderzobnin-zabbix-app/datasource-zabbix/module

I updated the Zabbix plugin to the latest as well and have restarted all related services. The error still persists.

Thanks!

Assuming the two paths share the same “root”, I have no “apps” directory as lusted in the path.

For “apps” I have /usr/share/grafana/public/

For the plugins/alexanderzobnin-zabbix/ I have /var/lib/grafana/plugins

The path to the plugins works via URL / web browser.

Seems like we unintentionally introduced a breaking change in Grafana. Going to open an issue to be fixed to v6.2 stable.

Oh…

JFYI, I have no ‘datemath’ in /var/lib/grafana/app/core/utils

Any idea on ETA? Thanks for all your attention to this!!!

For reference https://github.com/grafana/grafana/issues/16962. Should hopefully be fixed in master tomorrow and then you can run from a nightly build. If you don’t want to run a nightly build you have to wait for a new beta or stable v6.2 release. Or revert to your earlier version (I suppose you have a backup?).