Error Logging In - "user token not found"

Last Friday, I made a configuration update enabling disable_sanitize_html. I restarted the server after the change and didn’t have a problem all weekend. I tried logging in this morning, but I can’t be authenticated. Here’s a clip of what’s happening on the UI:

As you can see, the message indicates that I have been authenticated and have successfully logged in. However, I’m redirected back to the login page. I checked the server after changing the mode to development and trying again. Here are the logs since the server restart:

t=2019-03-04T12:49:11-0800 lvl=info msg="Starting Grafana" logger=server version=6.0.0 commit=34a9a62 branch=HEAD compiled=2019-02-25T06:47:26-0800
t=2019-03-04T12:49:11-0800 lvl=info msg="Config loaded from" logger=settings file=/usr/share/grafana/conf/defaults.ini
t=2019-03-04T12:49:11-0800 lvl=info msg="Config loaded from" logger=settings file=/etc/grafana/grafana.ini
t=2019-03-04T12:49:11-0800 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.data=/var/lib/grafana"
t=2019-03-04T12:49:11-0800 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.logs=/var/log/grafana"
t=2019-03-04T12:49:11-0800 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.plugins=/var/lib/grafana/plugins"
t=2019-03-04T12:49:11-0800 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.provisioning=/etc/grafana/provisioning"
t=2019-03-04T12:49:11-0800 lvl=info msg="Path Home" logger=settings path=/usr/share/grafana
t=2019-03-04T12:49:11-0800 lvl=info msg="Path Data" logger=settings path=/var/lib/grafana
t=2019-03-04T12:49:11-0800 lvl=info msg="Path Logs" logger=settings path=/var/log/grafana
t=2019-03-04T12:49:11-0800 lvl=info msg="Path Plugins" logger=settings path=/var/lib/grafana/plugins
t=2019-03-04T12:49:11-0800 lvl=info msg="Path Provisioning" logger=settings path=/etc/grafana/provisioning
t=2019-03-04T12:49:11-0800 lvl=info msg="App mode development" logger=settings
t=2019-03-04T12:49:11-0800 lvl=info msg="Writing PID file" logger=server path=/var/run/grafana/grafana-server.pid pid=6794
t=2019-03-04T12:49:11-0800 lvl=info msg="Initializing HTTPServer" logger=server
t=2019-03-04T12:49:11-0800 lvl=info msg="Initializing SqlStore" logger=server
t=2019-03-04T12:49:11-0800 lvl=info msg="Connecting to DB" logger=sqlstore dbtype=sqlite3
t=2019-03-04T12:49:11-0800 lvl=info msg="Starting DB migration" logger=migrator
t=2019-03-04T12:49:11-0800 lvl=info msg="Initializing InternalMetricsService" logger=server
t=2019-03-04T12:49:11-0800 lvl=info msg="Initializing SearchService" logger=server
t=2019-03-04T12:49:11-0800 lvl=info msg="Initializing PluginManager" logger=server
t=2019-03-04T12:49:11-0800 lvl=info msg="Starting plugin search" logger=plugins
t=2019-03-04T12:49:11-0800 lvl=info msg="Registering plugin" logger=plugins name=DarkSky
t=2019-03-04T12:49:11-0800 lvl=info msg="Registering plugin" logger=plugins name="D3 Gauge"
t=2019-03-04T12:49:11-0800 lvl=info msg="Registering plugin" logger=plugins name=GeoLoop
t=2019-03-04T12:49:11-0800 lvl=info msg="Registering plugin" logger=plugins name=Breadcrumb
t=2019-03-04T12:49:11-0800 lvl=info msg="Registering plugin" logger=plugins name=WindRose
t=2019-03-04T12:49:11-0800 lvl=info msg="Registering plugin" logger=plugins name="Sun and Moon"
t=2019-03-04T12:49:11-0800 lvl=info msg="Registering plugin" logger=plugins name="Simple Annotations"
t=2019-03-04T12:49:11-0800 lvl=info msg="Registering plugin" logger=plugins name="Pie Chart"
t=2019-03-04T12:49:11-0800 lvl=info msg="Registering plugin" logger=plugins name=SimpleJson
t=2019-03-04T12:49:11-0800 lvl=info msg="Registering plugin" logger=plugins name="Worldmap Panel"
t=2019-03-04T12:49:11-0800 lvl=info msg="Registering plugin" logger=plugins name=Candlestick
t=2019-03-04T12:49:11-0800 lvl=info msg="Registering plugin" logger=plugins name=Histogram
t=2019-03-04T12:49:11-0800 lvl=info msg="Registering plugin" logger=plugins name=Plotly
t=2019-03-04T12:49:11-0800 lvl=info msg="Registering plugin" logger=plugins name="USGS Water Services"
t=2019-03-04T12:49:11-0800 lvl=eror msg="Plugins: Failed to load plugin json file: /var/lib/grafana/plugins/raintank-worldping-app/dist/grafana-worldmap-panel/plugin.json,  err: Plugin with same id already exists"
t=2019-03-04T12:49:11-0800 lvl=info msg="Registering plugin" logger=plugins name="worldPing CTA"
t=2019-03-04T12:49:11-0800 lvl=info msg="Registering plugin" logger=plugins name="worldPing Endpoint List"
t=2019-03-04T12:49:11-0800 lvl=info msg="Registering plugin" logger=plugins name="worldPing Endpoint Nav"
t=2019-03-04T12:49:11-0800 lvl=info msg="Registering plugin" logger=plugins name=worldPing
t=2019-03-04T12:49:11-0800 lvl=info msg="Registering plugin" logger=plugins name="Radar Graph"
t=2019-03-04T12:49:11-0800 lvl=info msg="Initializing RenderingService" logger=server
t=2019-03-04T12:49:11-0800 lvl=info msg="Initializing AlertingService" logger=server
t=2019-03-04T12:49:11-0800 lvl=info msg="Initializing DatasourceCacheService" logger=server
t=2019-03-04T12:49:11-0800 lvl=info msg="Initializing HooksService" logger=server
t=2019-03-04T12:49:11-0800 lvl=info msg="Initializing LoginService" logger=server
t=2019-03-04T12:49:11-0800 lvl=info msg="Initializing QuotaService" logger=server
t=2019-03-04T12:49:11-0800 lvl=info msg="Initializing ServerLockService" logger=server
t=2019-03-04T12:49:11-0800 lvl=info msg="Initializing UserAuthTokenService" logger=server
t=2019-03-04T12:49:11-0800 lvl=info msg="Initializing CleanUpService" logger=server
t=2019-03-04T12:49:11-0800 lvl=info msg="Initializing NotificationService" logger=server
t=2019-03-04T12:49:11-0800 lvl=info msg="Initializing ProvisioningService" logger=server
t=2019-03-04T12:49:11-0800 lvl=info msg="Initializing TracingService" logger=server
t=2019-03-04T12:49:11-0800 lvl=info msg="Initializing Stream Manager"
t=2019-03-04T12:49:11-0800 lvl=info msg="HTTP Server Listen" logger=http.server address=0.0.0.0:3000 protocol=http subUrl=//[server-url]:3000 socket=
t=2019-03-04T12:49:26-0800 lvl=eror msg="failed to look up user based on cookie" logger=context error="user token not found"
t=2019-03-04T12:49:26-0800 lvl=info msg="new token" logger=context unhashed token=
t=2019-03-04T12:49:29-0800 lvl=eror msg="failed to look up user based on cookie" logger=context error="user token not found"
t=2019-03-04T12:49:29-0800 lvl=info msg="new token" logger=context unhashed token=
t=2019-03-04T12:49:29-0800 lvl=info msg="new token" logger=context userId=0 orgId=0 uname= unhashed token=[token]
t=2019-03-04T12:49:29-0800 lvl=eror msg="failed to look up user based on cookie" logger=context error="user token not found"
t=2019-03-04T12:49:29-0800 lvl=info msg="new token" logger=context unhashed token=
t=2019-03-04T12:49:29-0800 lvl=info msg="Request Completed" logger=context userId=0 orgId=0 uname= method=GET path=/ status=302 remote_addr=216.221.230.82 time_ms=0 size=53 referer=http://[server-url]:3000/login
t=2019-03-04T12:49:29-0800 lvl=eror msg="failed to look up user based on cookie" logger=context error="user token not found"
t=2019-03-04T12:49:29-0800 lvl=info msg="new token" logger=context unhashed token=

The only thing that stands out to me besides one of the plugins appearing to be a duplicate is that it is saying “user token not found” and “failed to look up user based on cookie”. So, I tried logging in with the browser in private mode and tried using a different browser. I’m getting the same issue. I’m not sure what has changed from my configuration edit until now, but I’m a little stumped as to what I need to do.

Any ideas?

Envinfo

  System:
    OS: Linux 4.15 Ubuntu 18.04.2 LTS (Bionic Beaver)
    CPU: (2) x64 Intel(R) Core(TM)2 Duo CPU     E8400  @ 3.00GHz
    Memory: 5.36 GB / 7.63 GB
    Container: Yes
    Shell: 4.4.19 - /bin/bash
  Binaries:
    Node: 10.15.0 - /usr/local/bin/node
    Yarn: 1.13.0 - /usr/local/bin/yarn
    npm: 6.7.0 - /usr/local/bin/npm
  Utilities:
    Make: 4.1 - /usr/bin/make
    GCC: 7.3.0 - /usr/bin/gcc
    Git: 2.17.1 - /usr/bin/git
  IDEs:
    Nano: 2.9.3 - /bin/nano
    Vim: 8.0 - /usr/bin/vim
  Languages:
    Bash: 4.4.19 - /bin/bash
    Perl: 5.26.1 - /usr/bin/perl
    Python: 2.7.15 - /usr/bin/python
    Ruby: 2.5.1 - /usr/bin/ruby
  Databases:
    MongoDB: 3.4.15 - /usr/bin/mongo

Seems like you’ve upgraded to Grafana v6.0 stable - is that correct?

If so, please start by reading release notes and upgrade notes.

Please verify if cookie being set when logging in using chrome developer tools or similar. I think you may have an issue with the cookie SameSite attribute

Thanks for your reply, @mefraimsson!

Yes, I this is for Grafana v6.0.

I’ve checked out the release notes and the upgrade notes. I’m not sure how much of that applies. I’m not running it with SSL. So, I don’t think I should be setting my cookie_secure to true.

I think you’re on to something. No cookies are being set at all. Nothing is being saved to session storage either. My config has the default setting though: ;cookie_samesite = lax

What root_url have you configured and what url are you using for logging in? Please also try

[security]
cookie_samesite = none
1 Like

Ah! My domain is my NoIP redirect to my home server while my root_url was still the default:

;root_url = http://localhost:3000.

I changed the root_url to reflect my domain, and that fixed it. I left it as it was commented out when I set it up because I assumed the domain would just bring rendered if I changed only the domain since the default.ini is configured like this:

root_url = %(protocol)s://%(domain)s:%(http_port)s/

Did something change?

We’re writing cookies with HttpOnly attribute. But we’ve also added the SameSite attribute. Lots of changes :slight_smile:

I’m having the same problem with LDAP auth. When I log in, it flashes the green popup saying I’m in, but then goes to the home page and I’m still not actually logged in. Log file has:

… lots of ldap stuff… lvl=dbug msg=“user auth token created” logger=auth tokenId=20 userId=3 clientIP=1.2.3.4 userAgent=“Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/72.0.3626.121 Safari/537.36” authToken=0a4d29ddaf15e40dd12141410cfe0ea9f4ad763
t=2019-03-13T12:00:45+0000 lvl=eror msg=“failed to look up user based on cookie” logger=context error=“user token not found”

My installation is using grafana 6.0.1-1. We have been running 5.4.3 and the config file started from there. We use nginx as a proxy to redirect from port 443 to 3000. cookie_secure was false (I tried both true and false). Tried cookie_samesite = lax and none. We had not changed the root_url but I tried setting it to localhost:3000 - no luck…

Results seem to be the same regardless of what settings I’ve used. I’m unfortunately not an LDAP expert - but LDAP doesn’t seem to be the problem (we can log in fine with the previous release, and it finds the user info in this release). So what do I need to do to get logged in with the new version? Thanks very much…

nbc

1 Like

@nbcohen seems like the cookie are not persisted correctly in browser. Could you use chrome developer tools, network tab + preserve log. Then go to login page. Clear all request in the network tab. Then log in and check the request corresponding to your login post request. Mine looks like this:

Are you by any chance using a reverse proxy and a sub path to access grafana? What’s your root_url configured to?

Tried what you suggested… Definitely not processing cookies correctly. I see this:

  1. Request URL: https://mysystem.mysite.com/login

  2. Request Method: POST

  3. Status Code: 200 OK

  4. Remote Address: 1.2.3.4:443

  5. Referrer Policy: no-referrer-when-downgrade

  6. Response Headers

  7. Connection: keep-alive

  8. Content-Length 23

  9. Content-Type: application/json

  10. Date: Mon, 25 Mar 2019 16:13:17 GMT

  11. Server: nginx

  12. Strict-Transport-Security: max-age=15768000

We are front-ending grafana with nginx. The nginx config redirects from port 443 to localhost:3000

In the grafana.ini file, I have not modified the root_url. It is set to be:
;root_url = %(protocol)s://%(domain)s:%(http_port)s/

We are upgrading from version 5.4.3. I left the 5.4.3 config file more or less untouched from what we were using. I added an [auth] section that looks like:

[auth]
login_maximum_inactive_lifetime_days = 1
login_maximum_lifetime_days = 1
login_cookie_name = grafana_sess_DEV

We had defined
cookie_name = grafana_sess_DEV

in the [session] section and I left that there.

We have cookie_secure = false (default) so I did not add that to the security section.

I just rebuilt my system using grafana 6.0.2-1

I’m guessing I’m missing something in the config file - but I’m not sure what that would be…

Thanks

nbc

In general you shouldn’t change Grafana’s default config since it makes upgrades hard. Instead add an custom config file where you override your changes, see configuration documentation.

The leading ; means that the line is commented out, refer to configuration documentation. But since you’re public facing url is you should configure root_url in the following way, refer to configuration documentation:

root_url = https://mysystem.mysite.com

Since you’re public facing url is using SSL/https you should configure secure cookies for security reasons. Please refer to upgrade notes for v6.0 and grafana auth v6.0 documentation.

That was the first thing I tried last week - I added the secure cookies and changed the root url. Didn’t work. I had to delete and re-install 5.4.3 last Friday for someone’s testing, but I rebuilt the tenant today with 6.0.2. I will go through that documentation again and try with the revised URL and secure cookie entries again tomorrow morning. I’ll let you know what happens. Thanks.

nbc

1 Like

It has been a while since I tried working with v6.x. Am trying to get back to it. I installed v6.2.5. If have secure cookies set, the root url points at the host, nginx is relaying to port 3000 and I get this from the chrome developer tools:

  1. Request URL:

https://myhostname.mydomain.com/login

  1. Request Method:

GET

  1. Status Code:

200 OK

  1. Remote Address:

10.123.456.789:443

  1. Referrer Policy:

no-referrer-when-downgrade

  1. Response Headersview source

  2. Cache-Control:

no-cache

  1. Connection:

keep-alive

  1. Content-Encoding:

gzip

  1. Content-Type:

text/html; charset=UTF-8

  1. Date:

Tue, 06 Aug 2019 12:33:56 GMT

  1. Expires:

-1

  1. Pragma:

no-cache

  1. Server:

nginx

  1. Strict-Transport-Security:

max-age=15768000

  1. Transfer-Encoding:

chunked

  1. Vary:

Accept-Encoding

  1. X-Frame-Options:

deny

  1. Request Headersview source

  2. Accept:

text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,/;q=0.8,application/signed-exchange;v=b3

  1. Accept-Encoding:

gzip, deflate, br

  1. Accept-Language:

en-US,en;q=0.9

  1. Connection:

keep-alive

  1. Cookie:

_ga=GA1.2.1919278016.1553859088; s_fid=4D3971EE51B9D211-200E179C024E4AD6; s_ev25=%5B%5B%27Direct%27%2C%271554120380651%27%5D%5D; s_vnum=1567605751909%26vn%3D1; s_getNewRepeat=1565013754809-New; s_lv=1565013754811; redirect_to=%252F

  1. Host:

myhost.mydomain.com

  1. Referer:

https://myhost.mydomain.com/login

  1. Upgrade-Insecure-Requests:

1

  1. User-Agent:

Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/75.0.3770.80 Safari/537.36

I enabled LDAP debug logging and it finds my username and authenticates me. But there is no reference to setting a cookie like you showed in the image above. I get the green flash indicating that I’m authenticated and then I remain on the login page. Where should I be looking for info on what is happening (or not happening) with cookies? I have cookie_secure set to true, and cookie_samesite set to none (tried it with lax as well).

Thanks

nbc

@nbcohen You should look at the POST request of login for a Set-Cookie header in the response. Are you using Safari? Can you try with Chrome?

We tried with both Firefox and Chrome without success.

nbc

We are not certain, but it appears that our problem may be related to the fact that we are using a Percona database. We stood up a standalone system using ‘mariadb’ and it worked. We repointed our cluster to the mariadb instance and that worked as well. For some reason, when we tried running inserts into the user_auth_token table (even from the command line) they would hang or time out, and we got indications that tables were locked, when they obviously were not.

For now, I am not going to continue down this road. We are (from a corporate perspective) starting to migrate our some of our mysql/maria/percona databases to postgres where that is possible. I am going to attempt to migrate my grafana environment to postgres and see if our login problems go away…

Thanks for the various suggestions…

nbc

I was also facing same issue with mysql galera cluster. Moved to single node mysql server , it worked fine.
While doing more debugging , i found that grafana was trying to read auth token without committing the write transection. I Enabled global auto-commit in galera cluster, which fixed this issue for me.