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

mefraimsson · April 23, 2019, 2:58pm

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.

bkgann · April 23, 2019, 4:50pm

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

jedthehead · April 23, 2019, 5:08pm

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

bkgann · April 25, 2019, 5:30am

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

joaogvr · April 25, 2019, 11:57am

@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=/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=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=/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”

jedthehead · April 25, 2019, 2:29pm

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

joaogvr · April 25, 2019, 2:40pm

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=/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”

mefraimsson · April 25, 2019, 3:18pm

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

joaogvr · April 25, 2019, 8:07pm

How can i see sqlite log?

And what could be causing this lock in the db?

mefraimsson · April 26, 2019, 7:18am

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.

jedthehead · April 26, 2019, 8:38pm

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

tchicken · April 29, 2019, 10:05am

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.

joaogvr · May 7, 2019, 5:16pm

Someone here got fix this ‘database is locked’?

My dashboards keeps logging out =/

mefraimsson · May 7, 2019, 5:24pm

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.

joaogvr · May 7, 2019, 6:51pm

Thanks, i’ll try this version

jedthehead · May 8, 2019, 7:12pm

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!

jedthehead · May 8, 2019, 7:28pm

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.

mefraimsson · May 8, 2019, 7:38pm

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

jedthehead · May 8, 2019, 7:39pm

Oh…

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

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

mefraimsson · May 8, 2019, 7:46pm

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?).

Topic		Replies	Views
User auto logout Grafana	13	17322	April 30, 2021
GRAFANA log me out	2	2253	March 14, 2019
Grafana dashboard timing out on iPad frequently Grafana	4	512	May 21, 2022
Dashboard Page Timeout Configuration	0	1355	February 10, 2020
Grafana Labs automatically gets log out Grafana logout	1	384	June 7, 2023

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

Related topics