Getting "invalid connection" error on refresh after 60 seconds of initial load


#1

What Grafana version are you using?

5.2.4

What OS are you running grafana on?

Fedora release 28 (Twenty Eight)

What did you do?

The db server is configured with the wait_timeout set to 60 seconds.
Grafana is configured with conn_max_lifetime set to 30 seconds…

[database]
conn_max_lifetime = 30

Not sure that it matters but, I’ve got an nodejs based (http-proxy) auth proxy that I’m using to authorize against the user being logged into our web site in front of an instance of Grafana running in a docker container.

Seems like I have things set up correctly but I continue to get the error.

Many thanks for any advice!


#2

what does the grafana server log say?


#3

@torkel

t=2018-10-03T19:41:47+0000 lvl=info msg="Request Completed" logger=context userId=2 orgId=2 uname=<OBFUSCATED> method=GET path=/api/dashboards/uid/YgIdmmAmk status=200 remote_addr=127.0.0.1 time_ms=2 size=11709 referer=<OBFUSCATED>
[mysql] 2018/10/03 19:41:47 packets.go:36: unexpected EOF

#4

Another batch that has invalid connection alerts in it…

t=2018-10-03T21:30:19+0000 lvl=info msg="Request Completed" logger=context userId=2 orgId=2 uname=<OBFUSCATED> method=GET path=/d/YgIdmmAmk/data-explorer status=200 remote_addr=127.0.0.1 time_ms=2 size=12972 referer=<OBFUSCATED>
t=2018-10-03T21:30:19+0000 lvl=info msg="Request Completed" logger=context userId=2 orgId=2 uname=<OBFUSCATED> method=GET path=/api/dashboards/uid/YgIdmmAmk status=200 remote_addr=127.0.0.1 time_ms=2 size=11709 referer="<OBFUSCATED>"
t=2018-10-03T21:30:19+0000 lvl=info msg="Request Completed" logger=context userId=2 orgId=2 uname=<OBFUSCATED> method=GET path=/avatar/192cf8979b96cda040e1f148394f3767 status=200 remote_addr=127.0.0.1 time_ms=5 size=697 referer="<OBFUSCATED>"
[mysql] 2018/10/03 21:30:20 packets.go:36: unexpected EOF
t=2018-10-03T21:30:20+0000 lvl=eror msg="Request Completed" logger=context userId=2 orgId=2 uname=<OBFUSCATED> method=POST path=/api/tsdb/query status=500 remote_addr=127.0.0.1 time_ms=1 size=288 referer="<OBFUSCATED>"
[mysql] 2018/10/03 21:30:20 packets.go:36: unexpected EOF
[mysql] 2018/10/03 21:30:20 connection.go:372: invalid connection
[mysql] 2018/10/03 21:30:20 connection.go:372: invalid connection

#5

something is not right with the connection to mysql, not sure what i can be. Never seen this reported before


#6

@torkel I also tried dropping conn_max_lifetime = 5 but I still get the invalid connection error after 60 seconds. I also tried dropping the max_idle_conn = 0 to see if I could get it to build a fresh connection everytime but that didn’t work either.


#7
[database]
max_idle_conn = 0
conn_max_lifetime = 0
max_open_conn = 0
mysql> show variables where variable_name like "%timeout%";
+-------------------------------------+----------+
| Variable_name                       | Value    |
+-------------------------------------+----------+
| connect_timeout                     | 10       |
| delayed_insert_timeout              | 300      |
| have_statement_timeout              | YES      |
| innodb_flush_log_at_timeout         | 1        |
| innodb_lock_wait_timeout            | 50       |
| innodb_print_lock_wait_timeout_info | OFF      |
| innodb_rollback_on_timeout          | OFF      |
| interactive_timeout                 | 28800    |
| lock_wait_timeout                   | 31536000 |
| net_read_timeout                    | 30       |
| net_write_timeout                   | 60       |
| rpl_stop_slave_timeout              | 31536000 |
| slave_net_timeout                   | 3600     |
| thread_pool_idle_timeout            | 60       |
| wait_timeout                        | 28800    |
+-------------------------------------+----------+
15 rows in set (0.00 sec)
[mysql] 2018/11/30 15:49:55 packets.go:36: unexpected EOF
t=2018-11-30T15:49:55+0000 lvl=eror msg="Request Completed" logger=context userId=1 orgId=71 uname=admin method=POST path=/api/tsdb/query status=500 remote_addr=<OBFUSCATED> time_ms=9 size=302 referer="http://<OBFUSCATED>/d/Wqd-imxmz/content-activity?orgId=71"
[mysql] 2018/11/30 15:49:55 packets.go:36: unexpected EOF
t=2018-11-30T15:49:55+0000 lvl=eror msg="Failed to get user with id" logger=context userId=1 error="User not found"
t=2018-11-30T15:49:55+0000 lvl=info msg="Request Completed" logger=context userId=0 orgId=0 uname= method=POST path=/api/tsdb/query status=401 remote_addr=<OBFUSCATED> time_ms=6 size=26 referer="http://<OBFUSCATED>/d/Wqd-imxmz/content-activity?orgId=71"
t=2018-11-30T15:49:55+0000 lvl=eror msg="Failed to get user with id" logger=context userId=1 error="User not found"
t=2018-11-30T15:49:55+0000 lvl=eror msg="Failed to get user with id" logger=context userId=1 error="User not found"
t=2018-11-30T15:49:55+0000 lvl=eror msg="Request Completed" logger=context userId=1 orgId=71 uname=admin method=POST path=/api/tsdb/query status=500 remote_addr=<OBFUSCATED> time_ms=8 size=301 referer="http://<OBFUSCATED>/d/Wqd-imxmz/content-activity?orgId=71"
t=2018-11-30T15:49:55+0000 lvl=info msg="Request Completed" logger=context userId=0 orgId=0 uname= method=POST path=/api/tsdb/query status=401 remote_addr=<OBFUSCATED> time_ms=7 size=26 referer="http://<OBFUSCATED>/d/Wqd-imxmz/content-activity?orgId=71"
t=2018-11-30T15:49:55+0000 lvl=info msg="Request Completed" logger=context userId=0 orgId=0 uname= method=POST path=/api/tsdb/query status=401 remote_addr=<OBFUSCATED> time_ms=11 size=26 referer="http://<OBFUSCATED>/d/Wqd-imxmz/content-activity?orgId=71"
t=2018-11-30T15:49:55+0000 lvl=eror msg="Failed to get user with id" logger=context userId=1 error="User not found"
t=2018-11-30T15:49:55+0000 lvl=info msg="Request Completed" logger=context userId=0 orgId=0 uname= method=POST path=/api/tsdb/query status=401 remote_addr=<OBFUSCATED> time_ms=4 size=26 referer="http://<OBFUSCATED>/d/Wqd-imxmz/content-activity?orgId=71"
t=2018-11-30T15:49:55+0000 lvl=eror msg="Failed to get user with id" logger=context userId=1 error="User not found"
t=2018-11-30T15:49:55+0000 lvl=info msg="Request Completed" logger=context userId=0 orgId=0 uname= method=POST path=/api/tsdb/query status=401 remote_addr=<OBFUSCATED> time_ms=0 size=26 referer="http://<OBFUSCATED>/d/Wqd-imxmz/content-activity?orgId=71"
t=2018-11-30T15:49:55+0000 lvl=eror msg="Failed to get user with id" logger=context userId=1 error="User not found"
t=2018-11-30T15:49:55+0000 lvl=info msg="Request Completed" logger=context userId=0 orgId=0 uname= method=POST path=/api/tsdb/query status=401 remote_addr=<OBFUSCATED> time_ms=1 size=26 referer="http://<OBFUSCATED>/d/Wqd-imxmz/content-activity?orgId=71"
[mysql] 2018/11/30 15:49:55 packets.go:36: unexpected EOF
[mysql] 2018/11/30 15:49:55 packets.go:36: unexpected EOF
t=2018-11-30T15:49:55+0000 lvl=eror msg="Request Completed" logger=context userId=1 orgId=71 uname=admin method=POST path=/api/tsdb/query status=500 remote_addr=<OBFUSCATED> time_ms=21 size=502 referer="http://<OBFUSCATED>/d/Wqd-imxmz/content-activity?orgId=71"
[mysql] 2018/11/30 15:49:55 packets.go:36: unexpected EOF
t=2018-11-30T15:49:55+0000 lvl=eror msg="Request Completed" logger=context userId=1 orgId=71 uname=admin method=POST path=/api/tsdb/query status=500 remote_addr=<OBFUSCATED> time_ms=3 size=1458 referer="http://<OBFUSCATED>/d/Wqd-imxmz/content-activity?orgId=71"
t=2018-11-30T15:49:55+0000 lvl=eror msg="Request Completed" logger=context userId=1 orgId=71 uname=admin method=POST path=/api/tsdb/query status=500 remote_addr=<OBFUSCATED> time_ms=3 size=1724 referer="http://<OBFUSCATED>/d/Wqd-imxmz/content-activity?orgId=71"
[mysql] 2018/11/30 15:49:55 packets.go:36: unexpected EOF
t=2018-11-30T15:49:55+0000 lvl=eror msg="Request Completed" logger=context userId=1 orgId=71 uname=admin method=POST path=/api/tsdb/query status=500 remote_addr=<OBFUSCATED> time_ms=1 size=941 referer="http://<OBFUSCATED>/d/Wqd-imxmz/content-activity?orgId=71"
[mysql] 2018/11/30 15:49:55 connection.go:372: invalid connection
[mysql] 2018/11/30 15:49:55 connection.go:372: invalid connection
[mysql] 2018/11/30 15:49:55 connection.go:372: invalid connection
[mysql] 2018/11/30 15:49:55 connection.go:372: invalid connection
[mysql] 2018/11/30 15:49:55 connection.go:372: invalid connection
[mysql] 2018/11/30 15:49:55 connection.go:372: invalid connection

Anything stand out to anyone as a problem?


#8

You have wait_timeout configured to 28800 seconds, i.e. 8 hours - then you should configure grafana to half of that 14400 seconds, i.e. 4 hours. Docs


#9

The strange thing is that the connection goes bad in 60 seconds. (based on my testing)

So I figured setting everything to zero in the grafana.ini file would work, and let me work my way back up to something reasonable… but it doesn’t even work when set to zero.

[database]
max_idle_conn = 0
conn_max_lifetime = 0
max_open_conn = 0

#10

I would suggest to leave the Grafana default settings and work from there. What MySQL version? MySQL HA setup? Any proxy in front of MySQL?


#11

No proxying, and we’re using Percona 5.6.


#12

Maybe you can find some pointers in this issue or its referenced links: https://github.com/go-sql-driver/mysql/issues/674