Frequent "Failed to call resource" and "Plugin unavailable" messages when loading dashboards

[smd75jr]

Describe the bug
When loading a dashboard I frequently (but not always) encounter "Failed to call resource" and "Plugin unavailable" warnings along with the dashboard failing to load.

The following items have been set in grafana.ini:

enable_alpha = true
allow_loading_unsigned_plugins = alexanderzobnin-zabbix-datasource

Expected behavior
Dashboard should load and work consistently without warnings.

Screenshots

Logs
debug_log_9-29-20_1_trimmed_1.txt

Software versions

OS	Grafana	Zabbix	Grafana-Zabbix Plugin
Ubuntu 20.04	7.2.0	5.0.4	4.0.1

[alexanderzobnin]

Hi! If there's a backend error, something should be in the grafana-server logs. Enable debug logging to see more.

[smd75jr]

Hi! The debug log is attached to the original post.

The last few lines are:

t=2020-09-29T19:57:10+0000 lvl=info msg=Profiler logger=plugins.backend pluginId=alexanderzobnin-zabbix-datasource enabled=false
t=2020-09-29T19:57:10+0000 lvl=dbug msg="Could not read environment variable" logger=plugins.backend pluginId=alexanderzobnin-zabbix-datasource GFX_ZABBIX_DATA_PATH=<unknown>
t=2020-09-29T19:57:10+0000 lvl=dbug msg="Starting Zabbix datasource" logger=plugins.backend pluginId=alexanderzobnin-zabbix-datasource
t=2020-09-29T19:57:10+0000 lvl=dbug msg="Serving plugin" logger=plugins.backend pluginId=alexanderzobnin-zabbix-datasource plugins="[diagnostics resource data]"
t=2020-09-29T19:57:10+0000 lvl=dbug msg="plugin address" logger=plugins.backend pluginId=alexanderzobnin-zabbix-datasource network=unix address=/tmp/plugin760668640
t=2020-09-29T19:57:10+0000 lvl=dbug msg="using plugin" logger=plugins.backend pluginId=alexanderzobnin-zabbix-datasource version=2
t=2020-09-29T19:57:10+0000 lvl=dbug msg="Plugin restarted" logger=plugins.backend pluginId=alexanderzobnin-zabbix-datasource

[alexanderzobnin]

But there's an answer:
increase the mlock limit (ulimit -l) or update your kernel to 5.3.15+, 5.4.2+, or 5.5+

t=2020-09-29T19:57:09+0000 lvl=dbug msg="runtime: mlock of signal stack failed: 12" logger=plugins.backend pluginId=alexanderzobnin-zabbix-datasource
t=2020-09-29T19:57:09+0000 lvl=dbug msg="runtime: increase the mlock limit (ulimit -l) or" logger=plugins.backend pluginId=alexanderzobnin-zabbix-datasource
t=2020-09-29T19:57:09+0000 lvl=dbug msg="runtime: update your kernel to 5.3.15+, 5.4.2+, or 5.5+" logger=plugins.backend pluginId=alexanderzobnin-zabbix-datasource
t=2020-09-29T19:57:09+0000 lvl=dbug msg="fatal error: mlock failed" logger=plugins.backend pluginId=alexanderzobnin-zabbix-datasource

[smd75jr]

I have no idea how I missed that.

After a bit more research this seems to actually be related to a hack implemented in Go to workaround and issue. Since the hack was no longer needed it was patched out of a recent version (see golang/go#37436 and golang/go#40184) as the main issue was fixed for kernel 5.4.0 (which is the most recent kernel available for Ubuntu 20.04). It looks like Grafana is using Go 1.14. (I could be completely wrong about all of this. Kernel-level stuff starts to get above my level)

I am not familiar with ulimit or how to increase it. Can you please advise?

[alexanderzobnin]

I don't remember exact command/config, but I'm pretty sure it's easy to google.

[sibrahimov]

I don't remember exact command/config, but I'm pretty sure it's easy to google.

Hi Alex,
Could you please help with the same problem. Logs below

t=2021-09-06T09:49:12+0400 lvl=info msg=Profiler logger=plugins.backend pluginId=alexanderzobnin-zabbix-datasource enabled=false
t=2021-09-06T09:49:14+0400 lvl=warn msg="Request Origin is not authorized" logger=live origin=http://xxxxxxxxxxxappUrl=http://localhost:3000/ allowedOrigins=
t=2021-09-06T09:49:14+0400 lvl=info msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=GET path=/api/live/ws status=403 remote_addr=xxxxxxxxxxx time_ms=1 size=10 referer=
t=2021-09-06T09:49:33+0400 lvl=warn msg="Request Origin is not authorized" logger=live origin=http://xxxxxxxxxxxappUrl=http://localhost:3000/ allowedOrigins=
t=2021-09-06T09:49:33+0400 lvl=info msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=GET path=/api/live/ws status=403 remote_addr=xxxxxxxxxxx time_ms=8 size=10 referer=
t=2021-09-06T09:49:46+0400 lvl=warn msg="Request Origin is not authorized" logger=live origin=http://xxxxxxxxxxxappUrl=http://localhost:3000/ allowedOrigins=
t=2021-09-06T09:49:46+0400 lvl=info msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=GET path=/api/live/ws status=403 remote_addr=xxxxxxxxxxx time_ms=0 size=10 referer=
t=2021-09-06T09:49:57+0400 lvl=warn msg="Request Origin is not authorized" logger=live origin=http://xxxxxxxxxxxappUrl=http://localhost:3000/ allowedOrigins=
t=2021-09-06T09:49:57+0400 lvl=info msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=GET path=/api/live/ws status=403 remote_addr=xxxxxxxxxxx time_ms=1 size=10 referer=
t=2021-09-06T09:50:10+0400 lvl=warn msg="Request Origin is not authorized" logger=live origin=http://xxxxxxxxxxxappUrl=http://localhost:3000/ allowedOrigins=
t=2021-09-06T09:50:10+0400 lvl=info msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=GET path=/api/live/ws status=403 remote_addr=xxxxxxxxxxx time_ms=1 size=10 referer=
t=2021-09-06T09:50:21+0400 lvl=warn msg="Request Origin is not authorized" logger=live origin=http://xxxxxxxxxxxappUrl=http://localhost:3000/ allowedOrigins=
t=2021-09-06T09:50:21+0400 lvl=info msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=GET path=/api/live/ws status=403 remote_addr=xxxxxxxxxxx time_ms=1 size=10 referer=
t=2021-09-06T09:50:35+0400 lvl=warn msg="Request Origin is not authorized" logger=live origin=http://xxxxxxxxxxxappUrl=http://localhost:3000/ allowedOrigins=
t=2021-09-06T09:50:35+0400 lvl=info msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=GET path=/api/live/ws status=403 remote_addr=xxxxxxxxxxx time_ms=13 size=10 referer=
t=2021-09-06T09:50:47+0400 lvl=warn msg="Request Origin is not authorized" logger=live origin=http://xxxxxxxxxxxappUrl=http://localhost:3000/ allowedOrigins=
t=2021-09-06T09:50:47+0400 lvl=info msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=GET path=/api/live/ws status=403 remote_addr=xxxxxxxxxxx time_ms=1 size=10 referer=
t=2021-09-06T09:51:05+0400 lvl=warn msg="Request Origin is not authorized" logger=live origin=http://xxxxxxxxxxxappUrl=http://localhost:3000/ allowedOrigins=
t=2021-09-06T09:51:05+0400 lvl=info msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=GET path=/api/live/ws status=403 remote_addr=xxxxxxxxxxx time_ms=1 size=10 referer=
t=2021-09-06T09:51:23+0400 lvl=warn msg="Request Origin is not authorized" logger=live origin=http://xxxxxxxxxxxappUrl=http://localhost:3000/ allowedOrigins=
t=2021-09-06T09:51:23+0400 lvl=info msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=GET path=/api/live/ws status=403 remote_addr=xxxxxxxxxxx time_ms=1 size=10 referer=
t=2021-09-06T09:51:41+0400 lvl=warn msg="Request Origin is not authorized" logger=live origin=http://xxxxxxxxxxxappUrl=http://localhost:3000/ allowedOrigins=
t=2021-09-06T09:51:41+0400 lvl=info msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=GET path=/api/live/ws status=403 remote_addr=xxxxxxxxxxx time_ms=7 size=10 referer=
t=2021-09-06T09:51:57+0400 lvl=info msg="Shutdown started" logger=server reason="System signal: terminated"
t=2021-09-06T09:51:57+0400 lvl=info msg="Starting Grafana" logger=server version=8.1.2 commit=103f8fa094 branch=HEAD compiled=2021-08-19T22:19:17+0400
t=2021-09-06T09:51:57+0400 lvl=info msg="Config loaded from" logger=settings file=/usr/share/grafana/conf/defaults.ini
t=2021-09-06T09:51:57+0400 lvl=info msg="Config loaded from" logger=settings file=/etc/grafana/grafana.ini
t=2021-09-06T09:51:57+0400 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.data=/var/lib/grafana"
t=2021-09-06T09:51:57+0400 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.logs=/var/log/grafana"
t=2021-09-06T09:51:57+0400 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.plugins=/var/lib/grafana/plugins"
t=2021-09-06T09:51:57+0400 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.provisioning=/etc/grafana/provisioning"
t=2021-09-06T09:51:57+0400 lvl=info msg="Path Provisioning" logger=settings path=/etc/grafana/provisioning
t=2021-09-06T09:51:57+0400 lvl=info msg="App mode production" logger=settings
t=2021-09-06T09:51:57+0400 lvl=info msg="Writing PID file" logger=server path=/var/run/grafana/grafana-server.pid pid=25583
t=2021-09-06T09:51:57+0400 lvl=info msg="Connecting to DB" logger=sqlstore dbtype=sqlite3
t=2021-09-06T09:51:57+0400 lvl=info msg="Starting DB migrations" logger=migrator
t=2021-09-06T09:51:57+0400 lvl=info msg="migrations completed" logger=migrator performed=0 skipped=385 duration=1.055477ms
t=2021-09-06T09:51:57+0400 lvl=info msg="Validated license token" logger=licensing appURL=http://localhost:3000/ source=disk status=NotFound
t=2021-09-06T09:51:57+0400 lvl=info msg="Starting plugin search" logger=plugins
t=2021-09-06T09:51:57+0400 lvl=info msg="Registering plugin" logger=plugins id=input
t=2021-09-06T09:51:58+0400 lvl=info msg="Registering plugin" logger=plugins id=alexanderzobnin-zabbix-triggers-panel
t=2021-09-06T09:51:58+0400 lvl=info msg="Registering plugin" logger=plugins id=alexanderzobnin-zabbix-app
t=2021-09-06T09:51:58+0400 lvl=info msg=Profiler logger=plugins.backend pluginId=alexanderzobnin-zabbix-datasource enabled=false
t=2021-09-06T09:51:58+0400 lvl=info msg="Registering plugin" logger=plugins id=alexanderzobnin-zabbix-datasource
t=2021-09-06T09:51:58+0400 lvl=info msg="Live Push Gateway initialization" logger=live.push_http
t=2021-09-06T09:51:58+0400 lvl=info msg="HTTP Server Listen" logger=http.server address=[::]:3000 protocol=http subUrl= socket=
t=2021-09-06T09:51:58+0400 lvl=warn msg="Scheduling and sending of reports disabled, SMTP is not configured and enabled. Configure SMTP to enable." logger=report
t=2021-09-06T09:52:01+0400 lvl=warn msg="Request Origin is not authorized" logger=live origin=http://xxxxxxxxxxx appUrl=http://localhost:3000/ allowedOrigins=
t=2021-09-06T09:52:01+0400 lvl=info msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=GET path=/api/live/ws status=403 remote_addr=xxxxxxxxxxx time_ms=1 size=10 referer=
t=2021-09-06T09:52:02+0400 lvl=warn msg="Request Origin is not authorized" logger=live origin=http://xxxxxxxxxxx appUrl=http://localhost:3000/ allowedOrigins=
t=2021-09-06T09:52:02+0400 lvl=info msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=GET path=/api/live/ws status=403 remote_addr=xxxxxxxxxxx time_ms=1 size=10 referer=
t=2021-09-06T09:52:04+0400 lvl=eror msg="Failed to call resource" logger=context userId=1 orgId=1 uname=admin error="failed to receive call resource response: rpc error: code = Unavailable desc = error reading from server: EOF"
t=2021-09-06T09:52:04+0400 lvl=eror msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=POST path=/api/datasources/4/resources/db-connection-post status=500 remote_addr=xxxxxxxxxxx time_ms=20 size=37 referer="http://10
.10.17.206:3000/d/0S2R9L4nk/zabbix-server-dashboard?orgId=1"
t=2021-09-06T09:52:04+0400 lvl=warn msg="Request Origin is not authorized" logger=live origin=http://xxxxxxxxxxx appUrl=http://localhost:3000/ allowedOrigins=
t=2021-09-06T09:52:04+0400 lvl=info msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=GET path=/api/live/ws status=403 remote_addr=xxxxxxxxxxx time_ms=1 size=10 referer=
t=2021-09-06T09:52:05+0400 lvl=info msg=Profiler logger=plugins.backend pluginId=alexanderzobnin-zabbix-datasource enabled=false
t=2021-09-06T09:52:07+0400 lvl=warn msg="Request Origin is not authorized" logger=live origin=http://xxxxxxxxxxx appUrl=http://localhost:3000/ allowedOrigins=
t=2021-09-06T09:52:07+0400 lvl=info msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=GET path=/api/live/ws status=403 remote_addr=xxxxxxxxxxx time_ms=0 size=10 referer=
t=2021-09-06T09:52:09+0400 lvl=eror msg="Failed to call resource" logger=context userId=1 orgId=1 uname=admin error="failed to receive call resource response: rpc error: code = Unavailable desc = error reading from server: EOF"
t=2021-09-06T09:52:09+0400 lvl=eror msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=POST path=/api/datasources/4/resources/db-connection-post status=500 remote_addr=xxxxxxxxxxx time_ms=22 size=37 referer="http://10
.10.17.206:3000/d/0S2R9L4nk/zabbix-server-dashboard?orgId=1"
t=2021-09-06T09:52:10+0400 lvl=info msg=Profiler logger=plugins.backend pluginId=alexanderzobnin-zabbix-datasource enabled=false
t=2021-09-06T09:52:11+0400 lvl=warn msg="Request Origin is not authorized" logger=live origin=http://xxxxxxxxxxx appUrl=http://localhost:3000/ allowedOrigins=
t=2021-09-06T09:52:11+0400 lvl=info msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=GET path=/api/live/ws status=403 remote_addr=xxxxxxxxxxx time_ms=1 size=10 referer=
t=2021-09-06T09:52:24+0400 lvl=warn msg="Request Origin is not authorized" logger=live origin=http://xxxxxxxxxxx appUrl=http://localhost:3000/ allowedOrigins=
t=2021-09-06T09:52:24+0400 lvl=info msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=GET path=/api/live/ws status=403 remote_addr=xxxxxxxxxxx time_ms=0 size=10 referer=
t=2021-09-06T09:52:44+0400 lvl=warn msg="Request Origin is not authorized" logger=live origin=http://xxxxxxxxxxx appUrl=http://localhost:3000/ allowedOrigins=
t=2021-09-06T09:52:44+0400 lvl=info msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=GET path=/api/live/ws status=403 remote_addr=xxxxxxxxxxx time_ms=7 size=10 referer=
t=2021-09-06T09:53:01+0400 lvl=warn msg="Request Origin is not authorized" logger=live origin=http://xxxxxxxxxxx appUrl=http://localhost:3000/ allowedOrigins=
t=2021-09-06T09:53:01+0400 lvl=info msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=GET path=/api/live/ws status=403 remote_addr=xxxxxxxxxxx time_ms=1 size=10 referer=
t=2021-09-06T09:53:19+0400 lvl=warn msg="Request Origin is not authorized" logger=live origin=http://xxxxxxxxxxx appUrl=http://localhost:3000/ allowedOrigins=
t=2021-09-06T09:53:19+0400 lvl=info msg="Request Completed" logger=context userId=1 orgId=1 uname=admin method=GET path=/api/live/ws status=403 remote_addr=xxxxxxxxxxx time_ms=1 size=10 referer=

[sibrahimov]