search

grafana / grafana-image-renderer

A Grafana backend plugin that handles rendering of panels & dashboards to PNGs using headless browser (Chromium/Chrome)
Apache License 2.0
361 stars 151 forks source link

v3.8.2 shows only the login screen #464

Open hjpotter92 opened 9 months ago

hjpotter92 commented 9 months ago

What happened:

After bumping our grafana-image-renderer deployment (in kubernetes); the images rendered are of the login screen only:

image

What you expected to happen:

Expecting the charts to be rendered instead

How to reproduce it (as minimally and precisely as possible): not sure. we had given up on image renderer working since feb. and were surprised to see the rendering happen at all with the recent 3.8.2 bump.

Anything else we need to know?: env vars. configured for grafana:

GF_AUTH_ANONYMOUS_ENABLED:                                       false
GF_AUTH_ANONYMOUS_ORG_ROLE:                                      Viewer
GF_PLUGIN_GRAFANA_IMAGE_RENDERER_RENDERING_IGNORE_HTTPS_ERRORS:  true
GF_RENDERING_CALLBACK_URL:                                       http://localhost:3000/
GF_RENDERING_RENDERER_TOKEN:                                     glsa_XXXXXXXXXXXXXXXXXXXXX
GF_RENDERING_SERVER_URL:                                         http://localhost:8081/render

and env vars. for grafana-image-renderer container (on same pod as grafana; hence localhost callback url):

AUTH_TOKEN:                 glsa_XXXXXXXXXXXXXXXXXXXXX
ENABLE_METRICS:             true
LOG_LEVEL:                  debug
RENDERING_CLUSTERING_MODE:  context
RENDERING_MODE:             clustered
TZ:                         Etc/UTC

the values for AUTH_TOKEN and GF_RENDERING_RENDERER_TOKEN is the same, generated through a service account with viewer role:

image

Environment:

AgnesToulet commented 8 months ago

Hello!

Do you have some logs to share from both the Grafana server side and the image renderer side please?

hjpotter92 commented 8 months ago

sure @AgnesToulet. attaching those below:

grafana server logs 
logger=rendering renderer=http t=2023-10-16T07:07:48.88877651Z level=info msg=Rendering path="d-solo/L7BdzGh4z/app-versions?orgId=1&refresh=5s&from=1697418463466&to=1697440063466&panelId=16&width=1000&height=500&tz=Asia%2FCalcutta"

logger=context userId=0 orgId=0 uname= t=2023-10-16T07:07:48.957577377Z level=info msg="Request Completed" method=GET path=/d-solo/L7BdzGh4z/app-versions status=302 remote_addr=10.92.1.39 time_ms=0 duration=112.01µs size=37 referer= handler=/d-solo/:uid/:slug

logger=context userId=0 orgId=0 uname= t=2023-10-16T07:07:52.72595268Z level=info msg="Request Completed" method=GET path=/ status=302 remote_addr=209.58.139.193 time_ms=0 duration=91.36µs size=37 referer= handler=/
grafana-image-renderer server logs 
{"level":"debug","message":"Render request received","url":"http://localhost:3000/d-solo/L7BdzGh4z/app-versions?orgId=1&refresh=5s&from=1697418463466&to=1697440063466&panelId=16&width=1000&height=500&tz=Asia%2FCalcutta&render=1"}
{"file":"/tmp/e82ee6b1.png","level":"debug","message":"Deleting temporary file"}
{"level":"debug","message":"::ffff:127.0.0.1 - - [16/Oct/2023:07:07:50 +0000] \"GET /render?deviceScaleFactor=1.000000&domain=localhost&encoding=&height=500&renderKey=bxdGl8eTJIXkCRSeBFvds675YPFSy0zR&timeout=60&timezone=Asia%2FCalcutta&url=http%3A%2F%2Flocalhost%3A3000%2Fd-solo%2FL7BdzGh4z%2Fapp-versions%3ForgId%3D1%26refresh%3D5s%26from%3D1697418463466%26to%3D1697440063466%26panelId%3D16%26width%3D1000%26height%3D500%26tz%3DAsia%252FCalcutta%26render%3D1&width=1000 HTTP/1.1\" 200 62351 \"-\" \"Grafana/10.1.2\"\n"}
{"level":"debug","message":"Connection closed","url":"http://localhost:3000/d-solo/L7BdzGh4z/app-versions?orgId=1&refresh=5s&from=1697418463466&to=1697440063466&panelId=16&width=1000&height=500&tz=Asia%2FCalcutta&render=1"}
AgnesToulet commented 8 months ago

Thank you. Could you also enable verbose logging (RENDERING_VERBOSE_LOGGING = true) and dumpio (RENDERING_DUMPIO = true) for the image renderer so we can get a bit more information on what's happening please?

hjpotter92 commented 8 months ago

sure:

grafana server logs 
logger=rendering renderer=http t=2023-10-16T07:33:37.063550222Z level=info msg=Rendering path="d-solo/L7BdzGh4z/app-versions?orgId=1&refresh=5s&from=1697438015780&to=1697441615781&panelId=5&width=1000&height=500&tz=Asia%2FCalcutta"

logger=context userId=0 orgId=0 uname= t=2023-10-16T07:33:37.135030934Z level=info msg="Request Completed" method=GET path=/d-solo/L7BdzGh4z/app-versions status=302 remote_addr=10.92.5.35 time_ms=0 duration=105.39µs size=37 referer= handler=/d-solo/:uid/:slug
grafana-image-renderer server logs 
{"level":"debug","message":"Render request received","url":"http://localhost:3000/d-solo/L7BdzGh4z/app-versions?orgId=1&refresh=5s&from=1697438015780&to=1697441615781&panelId=5&width=1000&height=500&tz=Asia%2FCalcutta&render=1"}
[1016/073337.075822:ERROR:zygote_host_impl_linux.cc(273)] Failed to adjust OOM score of renderer with pid 591: Permission denied (13)
{"deviceScaleFactor":1,"height":"500","level":"debug","message":"Setting viewport for page","width":"1000"}
{"domain":"localhost","level":"debug","message":"Setting cookie for page","renderKey":"LUxPUCf1d6Ft5jCGgecye5nuK7DvD5IP"}
{"level":"debug","message":"Moving mouse on page","x":1000,"y":500}
{"level":"debug","message":"Navigating and waiting for all network requests to finish","url":"http://localhost:3000/d-solo/L7BdzGh4z/app-versions?orgId=1&refresh=5s&from=1697438015780&to=1697441615781&panelId=5&width=1000&height=500&tz=Asia%2FCalcutta&render=1"}
{"level":"debug","message":"Browser request","method":"GET","url":"http://localhost:3000/d-solo/L7BdzGh4z/app-versions?orgId=1&refresh=5s&from=1697438015780&to=1697441615781&panelId=5&width=1000&height=500&tz=Asia%2FCalcutta&render=1"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"http://localhost:3000/d-solo/L7BdzGh4z/app-versions?orgId=1&refresh=5s&from=1697438015780&to=1697441615781&panelId=5&width=1000&height=500&tz=Asia%2FCalcutta&render=1"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/d-solo/L7BdzGh4z/app-versions?orgId=1&refresh=5s&from=1697438015780&to=1697441615781&panelId=5&width=1000&height=500&tz=Asia%2FCalcutta&render=1"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/d-solo/L7BdzGh4z/app-versions?orgId=1&refresh=5s&from=1697438015780&to=1697441615781&panelId=5&width=1000&height=500&tz=Asia%2FCalcutta&render=1"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/login"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/grafana.dark.886efb710af4d17a895d.css"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/runtime.7e82923cb533bc3576d2.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/147.73fef960675c84aa9a84.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/1486.9f5c58b5413b0650af69.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/1537.caf8c5d1430033307ef5.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/226.6820fd439963e5465b6a.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/app.5134ec4fafe46667d3cf.js"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/login"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/grafana.dark.886efb710af4d17a895d.css"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/runtime.7e82923cb533bc3576d2.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/img/grafana_icon.svg"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/fonts/inter/UcC73FwrK3iLTeHuS_fvQtMwCp50KnMa1ZL7.woff2"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/1537.caf8c5d1430033307ef5.js"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/147.73fef960675c84aa9a84.js"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/app.5134ec4fafe46667d3cf.js"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/img/grafana_icon.svg"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/fonts/inter/UcC73FwrK3iLTeHuS_fvQtMwCp50KnMa1ZL7.woff2"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/226.6820fd439963e5465b6a.js"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/1486.9f5c58b5413b0650af69.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/7424.afad9d5bcb701f31d890.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"blob:https://eu-metrics-monitoring.livepeer.monster/5c258dde-0ad4-4160-b88a-4f0b4569d4e9"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/7424.afad9d5bcb701f31d890.js"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"blob:https://eu-metrics-monitoring.livepeer.monster/5c258dde-0ad4-4160-b88a-4f0b4569d4e9"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/1189.846540cbca3eb55c18a1.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/8695.c23c9961ab344f38b174.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/3633.acef4a1394f4c10cf087.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/AngularApp.cd93fabea0d7a3dbc811.js"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/AngularApp.cd93fabea0d7a3dbc811.js"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/8695.c23c9961ab344f38b174.js"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/3633.acef4a1394f4c10cf087.js"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/1189.846540cbca3eb55c18a1.js"}
{"level":"debug","line":224,"message":"Browser console warning","msg":"The keyword 'inner-spin-button' specified to an 'appearance' property is not standardized. It will be removed in the future.","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/1486.9f5c58b5413b0650af69.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/img/g8_login_dark.svg"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/img/icons/unicons/google.svg"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/img/icons/unicons/github.svg"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/img/g8_login_dark.svg"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/img/icons/unicons/google.svg"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/img/icons/unicons/github.svg"}
{"level":"debug","message":"Waiting for dashboard/panel to load","timeout":"60s"}
{"level":"debug","message":"Setting zoom level","zoomLevel":1}
{"filePath":"/tmp/58f5bb1f.png","level":"debug","message":"Taking screenshot"}
{"file":"/tmp/58f5bb1f.png","level":"debug","message":"Deleting temporary file"}
{"level":"debug","message":"::ffff:127.0.0.1 - - [16/Oct/2023:07:33:38 +0000] \"GET /render?deviceScaleFactor=1.000000&domain=localhost&encoding=&height=500&renderKey=LUxPUCf1d6Ft5jCGgecye5nuK7DvD5IP&timeout=60&timezone=Asia%2FCalcutta&url=http%3A%2F%2Flocalhost%3A3000%2Fd-solo%2FL7BdzGh4z%2Fapp-versions%3ForgId%3D1%26refresh%3D5s%26from%3D1697438015780%26to%3D1697441615781%26panelId%3D5%26width%3D1000%26height%3D500%26tz%3DAsia%252FCalcutta%26render%3D1&width=1000 HTTP/1.1\" 200 62351 \"-\" \"Grafana/10.1.2\"\n"}
{"level":"debug","message":"Connection closed","url":"http://localhost:3000/d-solo/L7BdzGh4z/app-versions?orgId=1&refresh=5s&from=1697438015780&to=1697441615781&panelId=5&width=1000&height=500&tz=Asia%2FCalcutta&render=1"}
AgnesToulet commented 8 months ago

Thanks! This is surprising to have nothing more in the Grafana server logs but it looks like an authentication issue (the grafana-image-renderer can't login to Grafana when taking the screenshot).

Sorry for the back and forth but could you also enable debug logging on the Grafana server (GF_LOG_LEVEL = debug) and share these logs?

Also, after getting the logs with the current configuration, could you try enabling JWT authentication for the rendering feature (GF_FEATURE_TOGGLES = renderAuthJWT)? This a new feature (still in public preview) and this would make the rendering work if there is anything wrong in the remote cache configuration.

hjpotter92 commented 8 months ago

Logs after enabling debug logs in grafana:

logger=ngalert.state.manager rule_uid=dEuXr9v4k org_id=1 t=2023-10-16T08:51:40.005566545Z level=debug msg="Saving alert states" count=1 max_state_save_concurrency=1
logger=ngalert.state.manager rule_uid=dEuXr9v4k org_id=1 t=2023-10-16T08:51:40.009531384Z level=debug msg="Saving alert states done" count=1 max_state_save_concurrency=1 duration=3.963669ms
logger=accesscontrol.service t=2023-10-16T08:51:40.225111478Z level=debug msg="using cached permissions" key=rbac-permissions-1-user-2
logger=rendering renderer=http t=2023-10-16T08:51:40.225275218Z level=info msg=Rendering path="d-solo/L7BdzGh4z/app-versions?orgId=1&refresh=5s&from=1697442694384&to=1697446294384&panelId=14&width=1000&height=500&tz=Asia%2FCalcutta"
logger=rendering renderer=http t=2023-10-16T08:51:40.225448438Z level=debug msg="calling remote rendering service" url="http://localhost:8081/render?deviceScaleFactor=1.000000&domain=localhost&encoding=&height=500&renderKey=eyJhbGciOiJIUzUxMiIsInR5cCI6IkpXVCJ9.eyJSZW5kZXJVc2VyIjp7Im9yZ19pZCI6MSwidXNlcl9pZCI6Miwib3JnX3JvbGUiOiJBZG1pbiJ9LCJleHAiOjE2OTc0NDY2MDB9.SKlILocddAq7T_2koyko7WkIJkL26xAPsuxDRp4Oog_6b-_F7-YfmbbaXwil_SGv2wcvdyicK4MJxEt0HKEAWg&timeout=60&timezone=Asia%2FCalcutta&url=http%3A%2F%2Flocalhost%3A3000%2Fd-solo%2FL7BdzGh4z%2Fapp-versions%3ForgId%3D1%26refresh%3D5s%26from%3D1697442694384%26to%3D1697446294384%26panelId%3D14%26width%3D1000%26height%3D500%26tz%3DAsia%252FCalcutta%26render%3D1&width=1000"
logger=context userId=0 orgId=0 uname= t=2023-10-16T08:51:40.331670905Z level=info msg="Request Completed" method=GET path=/d-solo/L7BdzGh4z/app-versions status=302 remote_addr=10.92.5.36 time_ms=0 duration=100.251µs size=37 referer= handler=/d-solo/:uid/:slug
logger=provisioning.dashboard type=file name=default t=2023-10-16T08:51:41.312258884Z level=debug msg="Start walking disk" path=/etc/grafana/provisioning/dashboards
logger=provisioning.dashboard type=file name=default t=2023-10-16T08:51:41.312329044Z level=debug msg="Start walking disk" path=/etc/grafana/provisioning/dashboards
logger=datasources rule_uid=oqU5n3v4k org_id=1 t=2023-10-16T08:51:45.003614592Z level=debug msg="Querying for data source via SQL store" uid=PBFA97CFB590B2093 orgId=1
logger=secrets.kvstore t=2023-10-16T08:51:45.009686162Z level=debug msg="got secret value" orgId=1 type=datasource namespace=Prometheus
logger=tsdb.prometheus rule_uid=oqU5n3v4k org_id=1 t=2023-10-16T08:51:45.009838072Z level=debug msg="Sending query" start=2023-10-16T07:51:40Z end=2023-10-16T08:51:40Z step=15s query="count(mist_cpu{catalyst=\"true\"})"
logger=expr rule_uid=oqU5n3v4k org_id=1 datasourceType=prometheus queryRefId=A datasourceUid=PBFA97CFB590B2093 datasourceVersion=1 t=2023-10-16T08:51:45.015936652Z level=debug msg="Handling SSE data source query through dataplane" datatype=timeseries-multi
logger=expr rule_uid=oqU5n3v4k org_id=1 datasourceType=prometheus queryRefId=A datasourceUid=PBFA97CFB590B2093 datasourceVersion=1 t=2023-10-16T08:51:45.016024822Z level=debug msg="Data source queried" responseType=dataplane-timeseries-multi
logger=ngalert.scheduler rule_uid=oqU5n3v4k org_id=1 version=8 fingerprint=fa36d98d75d4c2d4 attempt=0 now=2023-10-16T08:51:40Z rule_uid=oqU5n3v4k org_id=1 t=2023-10-16T08:51:45.016071262Z level=debug msg="Alert rule evaluated" results="[{Instance: State:Normal Error:<nil> Results:map[] Values:map[] EvaluatedAt:2023-10-16 08:51:40 +0000 UTC EvaluationDuration:5.016065912s EvaluationString:}]" duration=12.57681ms
logger=ngalert.state.manager rule_uid=oqU5n3v4k org_id=1 t=2023-10-16T08:51:45.016117302Z level=debug msg="State manager processing evaluation results" resultCount=1
logger=ngalert.state.manager rule_uid=oqU5n3v4k org_id=1 instance= t=2023-10-16T08:51:45.016147102Z level=debug msg="Setting next state" handler=resultNormal
logger=ngalert.state.manager rule_uid=oqU5n3v4k org_id=1 instance= t=2023-10-16T08:51:45.016153362Z level=debug msg="Keeping state" state=Normal
logger=ngalert.state.manager rule_uid=oqU5n3v4k org_id=1 t=2023-10-16T08:51:45.016162171Z level=debug msg="Saving alert states" count=1 max_state_save_concurrency=1
logger=ngalert.state.manager rule_uid=oqU5n3v4k org_id=1 t=2023-10-16T08:51:45.020045321Z level=debug msg="Saving alert states done" count=1 max_state_save_concurrency=1 duration=3.87623ms
logger=ngalert.state.manager t=2023-10-16T08:51:46.183503886Z level=debug msg="Recording state cache metrics" now=2023-10-16T08:51:46.183490466Z
logger=accesscontrol.service t=2023-10-16T08:51:47.010894261Z level=debug msg="using cached permissions" key=rbac-permissions-1-user-2
logger=query_data t=2023-10-16T08:51:47.011098541Z level=debug msg="Processing metrics query" query="unsupported value type"
logger=secrets.kvstore t=2023-10-16T08:51:47.011152201Z level=debug msg="got secret value from cache" orgId=1 type=datasource namespace=Prometheus
logger=tsdb.prometheus t=2023-10-16T08:51:47.011308541Z level=debug msg="Sending query" start=2023-10-16T07:51:46.895Z end=2023-10-16T08:51:46.895Z step=1m0s query="sum(version{app=\"MistServer\", pod!=\"canary-catalyst-0\"}) by (version)"
logger=accesscontrol.service t=2023-10-16T08:51:47.013414551Z level=debug msg="using cached permissions" key=rbac-permissions-1-user-2
logger=query_data t=2023-10-16T08:51:47.013618131Z level=debug msg="Processing metrics query" query="unsupported value type"
logger=secrets.kvstore t=2023-10-16T08:51:47.013678341Z level=debug msg="got secret value from cache" orgId=1 type=datasource namespace=Prometheus
logger=tsdb.prometheus t=2023-10-16T08:51:47.013850731Z level=debug msg="Sending query" start=2023-10-16T07:51:46.895Z end=2023-10-16T08:51:46.895Z step=1m0s query="sum by(version) (version{app=\"catalyst-api\", version!=\"\", pod!=\"canary-catalyst-0\"})"
logger=accesscontrol.service t=2023-10-16T08:51:47.014395191Z level=debug msg="using cached permissions" key=rbac-permissions-1-user-2
logger=accesscontrol.service t=2023-10-16T08:51:47.02083525Z level=debug msg="using cached permissions" key=rbac-permissions-1-user-2
logger=query_data t=2023-10-16T08:51:47.020968441Z level=debug msg="Processing metrics query" query="unsupported value type"
logger=secrets.kvstore t=2023-10-16T08:51:47.021004791Z level=debug msg="got secret value from cache" orgId=1 type=datasource namespace=Prometheus
logger=tsdb.prometheus t=2023-10-16T08:51:47.021079761Z level=debug msg="Sending query" start=2023-10-16T07:51:46.895Z end=2023-10-16T08:51:46.895Z step=5m0s query="sum by (version) (version{app=\"studio-api\"})"
logger=accesscontrol.service t=2023-10-16T08:51:47.022351811Z level=debug msg="using cached permissions" key=rbac-permissions-1-user-2
logger=query_data t=2023-10-16T08:51:47.02266897Z level=debug msg="Processing metrics query" query="unsupported value type"
logger=secrets.kvstore t=2023-10-16T08:51:47.02277245Z level=debug msg="got secret value from cache" orgId=1 type=datasource namespace=Prometheus
logger=tsdb.prometheus t=2023-10-16T08:51:47.02298139Z level=debug msg="Sending query" start=2023-10-16T07:51:46.895Z end=2023-10-16T08:51:46.895Z step=5m0s query="sum by (version) (livepeer_task_runner_version{livepeer_live_app=~\".+-task-runner\"})"
logger=accesscontrol.service t=2023-10-16T08:51:47.213744745Z level=debug msg="using cached permissions" key=rbac-permissions-1-user-2
logger=query_data t=2023-10-16T08:51:47.213949655Z level=debug msg="Processing metrics query" query="unsupported value type"
logger=secrets.kvstore t=2023-10-16T08:51:47.213998435Z level=debug msg="got secret value from cache" orgId=1 type=datasource namespace=Prometheus
logger=tsdb.prometheus t=2023-10-16T08:51:47.214106535Z level=debug msg="Sending query" start=2023-10-16T07:51:46.895Z end=2023-10-16T08:51:46.895Z step=1m0s query="sum(livepeer_versions{catalyst=\"true\", pod != \"canary-catalyst-0\"}) by (livepeerversion)"
logger=accesscontrol.service t=2023-10-16T08:51:47.218670815Z level=debug msg="using cached permissions" key=rbac-permissions-1-user-2
logger=query_data t=2023-10-16T08:51:47.218834535Z level=debug msg="Processing metrics query" query="unsupported value type"
logger=secrets.kvstore t=2023-10-16T08:51:47.218871475Z level=debug msg="got secret value from cache" orgId=1 type=datasource namespace=Prometheus
logger=tsdb.prometheus t=2023-10-16T08:51:47.218989775Z level=debug msg="Sending query" start=2023-10-16T07:51:46.895Z end=2023-10-16T08:51:46.895Z step=1m0s query="sum(livepeer_versions{catalyst!=\"true\", node_type=\"bctr\", livepeer_node_type!=\"prod-livepeer-recording\", }) by (livepeerversion)"
logger=accesscontrol.service t=2023-10-16T08:51:47.38812958Z level=debug msg="using cached permissions" key=rbac-permissions-1-user-2
logger=query_data t=2023-10-16T08:51:47.400753819Z level=debug msg="Processing metrics query" query="unsupported value type"
logger=secrets.kvstore t=2023-10-16T08:51:47.400863509Z level=debug msg="got secret value from cache" orgId=1 type=datasource namespace=Prometheus
logger=tsdb.prometheus t=2023-10-16T08:51:47.401040919Z level=debug msg="Sending query" start=2023-10-16T07:51:46.895Z end=2023-10-16T08:51:46.895Z step=1m0s query="sum(livepeer_versions{catalyst!=\"true\", node_type=\"bctr\", livepeer_node_type=~\".+-livepeer-recording\"}) by (livepeerversion)"
logger=accesscontrol.service t=2023-10-16T08:51:47.403705649Z level=debug msg="using cached permissions" key=rbac-permissions-1-user-2
logger=query_data t=2023-10-16T08:51:47.403880989Z level=debug msg="Processing metrics query" query="unsupported value type"
logger=secrets.kvstore t=2023-10-16T08:51:47.403913979Z level=debug msg="got secret value from cache" orgId=1 type=datasource namespace=Prometheus
logger=tsdb.prometheus t=2023-10-16T08:51:47.403992129Z level=debug msg="Sending query" start=2023-10-16T07:51:46.895Z end=2023-10-16T08:51:46.895Z step=1m0s query="sum(livepeer_versions{node_type=\"orch\"}) by (livepeerversion)"

and from image-renderer:

{"level":"debug","message":"Render request received","url":"http://localhost:3000/d-solo/L7BdzGh4z/app-versions?orgId=1&refresh=5s&from=1697442694384&to=1697446294384&panelId=14&width=1000&height=500&tz=Asia%2FCalcutta&render=1"}
[1016/085140.246932:ERROR:zygote_host_impl_linux.cc(273)] Failed to adjust OOM score of renderer with pid 119: Permission denied (13)
{"deviceScaleFactor":1,"height":"500","level":"debug","message":"Setting viewport for page","width":"1000"}
{"domain":"localhost","level":"debug","message":"Setting cookie for page","renderKey":"eyJhbGciOiJIUzUxMiIsInR5cCI6IkpXVCJ9.eyJSZW5kZXJVc2VyIjp7Im9yZ19pZCI6MSwidXNlcl9pZCI6Miwib3JnX3JvbGUiOiJBZG1pbiJ9LCJleHAiOjE2OTc0NDY2MDB9.SKlILocddAq7T_2koyko7WkIJkL26xAPsuxDRp4Oog_6b-_F7-YfmbbaXwil_SGv2wcvdyicK4MJxEt0HKEAWg"}
{"level":"debug","message":"Moving mouse on page","x":1000,"y":500}
{"level":"debug","message":"Navigating and waiting for all network requests to finish","url":"http://localhost:3000/d-solo/L7BdzGh4z/app-versions?orgId=1&refresh=5s&from=1697442694384&to=1697446294384&panelId=14&width=1000&height=500&tz=Asia%2FCalcutta&render=1"}
{"level":"debug","message":"Browser request","method":"GET","url":"http://localhost:3000/d-solo/L7BdzGh4z/app-versions?orgId=1&refresh=5s&from=1697442694384&to=1697446294384&panelId=14&width=1000&height=500&tz=Asia%2FCalcutta&render=1"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"http://localhost:3000/d-solo/L7BdzGh4z/app-versions?orgId=1&refresh=5s&from=1697442694384&to=1697446294384&panelId=14&width=1000&height=500&tz=Asia%2FCalcutta&render=1"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/d-solo/L7BdzGh4z/app-versions?orgId=1&refresh=5s&from=1697442694384&to=1697446294384&panelId=14&width=1000&height=500&tz=Asia%2FCalcutta&render=1"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/d-solo/L7BdzGh4z/app-versions?orgId=1&refresh=5s&from=1697442694384&to=1697446294384&panelId=14&width=1000&height=500&tz=Asia%2FCalcutta&render=1"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/login"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/grafana.dark.886efb710af4d17a895d.css"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/runtime.7e82923cb533bc3576d2.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/147.73fef960675c84aa9a84.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/1486.9f5c58b5413b0650af69.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/1537.caf8c5d1430033307ef5.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/226.6820fd439963e5465b6a.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/app.5134ec4fafe46667d3cf.js"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/login"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/grafana.dark.886efb710af4d17a895d.css"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/runtime.7e82923cb533bc3576d2.js"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/1537.caf8c5d1430033307ef5.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/img/grafana_icon.svg"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/fonts/inter/UcC73FwrK3iLTeHuS_fvQtMwCp50KnMa1ZL7.woff2"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/147.73fef960675c84aa9a84.js"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/app.5134ec4fafe46667d3cf.js"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/img/grafana_icon.svg"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/fonts/inter/UcC73FwrK3iLTeHuS_fvQtMwCp50KnMa1ZL7.woff2"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/226.6820fd439963e5465b6a.js"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/1486.9f5c58b5413b0650af69.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/7424.afad9d5bcb701f31d890.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"blob:https://eu-metrics-monitoring.livepeer.monster/7da67e69-1be8-456c-be0a-5c32762869b4"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/7424.afad9d5bcb701f31d890.js"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"blob:https://eu-metrics-monitoring.livepeer.monster/7da67e69-1be8-456c-be0a-5c32762869b4"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/1189.846540cbca3eb55c18a1.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/8695.c23c9961ab344f38b174.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/3633.acef4a1394f4c10cf087.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/AngularApp.cd93fabea0d7a3dbc811.js"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/AngularApp.cd93fabea0d7a3dbc811.js"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/8695.c23c9961ab344f38b174.js"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/3633.acef4a1394f4c10cf087.js"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/1189.846540cbca3eb55c18a1.js"}
{"level":"debug","line":224,"message":"Browser console warning","msg":"The keyword 'inner-spin-button' specified to an 'appearance' property is not standardized. It will be removed in the future.","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/build/1486.9f5c58b5413b0650af69.js"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/img/g8_login_dark.svg"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/img/icons/unicons/google.svg"}
{"level":"debug","message":"Browser request","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/img/icons/unicons/github.svg"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/img/g8_login_dark.svg"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/img/icons/unicons/google.svg"}
{"level":"debug","message":"Browser request finished","method":"GET","url":"https://eu-metrics-monitoring.livepeer.monster/grafana/public/img/icons/unicons/github.svg"}
{"level":"debug","message":"Waiting for dashboard/panel to load","timeout":"60s"}
{"level":"debug","message":"Setting zoom level","zoomLevel":1}
{"filePath":"/tmp/f75fa494.png","level":"debug","message":"Taking screenshot"}
{"file":"/tmp/f75fa494.png","level":"debug","message":"Deleting temporary file"}
{"level":"debug","message":"::ffff:127.0.0.1 - - [16/Oct/2023:08:51:41 +0000] \"GET /render?deviceScaleFactor=1.000000&domain=localhost&encoding=&height=500&renderKey=eyJhbGciOiJIUzUxMiIsInR5cCI6IkpXVCJ9.eyJSZW5kZXJVc2VyIjp7Im9yZ19pZCI6MSwidXNlcl9pZCI6Miwib3JnX3JvbGUiOiJBZG1pbiJ9LCJleHAiOjE2OTc0NDY2MDB9.SKlILocddAq7T_2koyko7WkIJkL26xAPsuxDRp4Oog_6b-_F7-YfmbbaXwil_SGv2wcvdyicK4MJxEt0HKEAWg&timeout=60&timezone=Asia%2FCalcutta&url=http%3A%2F%2Flocalhost%3A3000%2Fd-solo%2FL7BdzGh4z%2Fapp-versions%3ForgId%3D1%26refresh%3D5s%26from%3D1697442694384%26to%3D1697446294384%26panelId%3D14%26width%3D1000%26height%3D500%26tz%3DAsia%252FCalcutta%26render%3D1&width=1000 HTTP/1.1\" 200 64828 \"-\" \"Grafana/10.1.2\"\n"}
{"level":"debug","message":"Connection closed","url":"http://localhost:3000/d-solo/L7BdzGh4z/app-versions?orgId=1&refresh=5s&from=1697442694384&to=1697446294384&panelId=14&width=1000&height=500&tz=Asia%2FCalcutta&render=1"}
hjpotter92 commented 8 months ago

Enabled feature toggles now:

GF_FEATURE_TOGGLES_ENABLE: panelTitleSearch topnav lokiDataframeApi accessTokenExpirationCheck dataConnectionsConsole autoMigrateOldPanels publicDashboards correlations autoMigrateOldPanels nestedFolders live-service-web-worker lokiLive canvasPanelNesting traceToMetrics scenes renderAuthJWT
AgnesToulet commented 8 months ago

Hi, did the feature toggle change anything? This is really weird that the logs on the Grafana server side indicate nothing going wrong.

hjpotter92 commented 8 months ago

Hi, did the feature toggle change anything? This is really weird that the logs on the Grafana server side indicate nothing going wrong.

hey, no! the logs provided above were from after both GF_LOG_LEVEL and the renderAuthJWT feature enabled. the image being rendered is still of the login page.

AgnesToulet commented 8 months ago

Sorry as there is nothing indicating something going wrong in the logs and I can't reproduce this locally, I don't know how to help. I think it's related to your configuration though as nobody else has reported this issue. Can you maybe share your whole setup configuration so I can try to reproduce?

atanunq commented 3 months ago

Hi! Adding another data point as we're seeing the very same issue and logs after upgrading Grafana from 9.5.2 to 10.2.3. It was working before even without setting a renderer token. We are running the Grafana Helm chart with Okta auth enabled through the following config:

grafana.ini:
  users:
    viewers_can_edit: true
    auto_assign_org_role: Viewer
  database:
    # Host, database and credentials defined using a secret
    type: "postgres"
  server:
    domain: "grafana.example.com"
    root_url: "https://%(domain)s/grafana"
    protocol: "http"
    serve_from_sub_path: true
  auth.okta:
      name: Okta
      enabled: true
      allow_sign_up: true
      skip_org_role_sync: true
      client_id: ""
      scopes: ""
      auth_url: ""
      token_url: ""
      api_url: ""

imageRenderer:
  enabled: true
  image:
    tag: 3.8.4

A peculiarity I noticed was that the link that the [Direct link rendered image] button points to was without the /grafana subpath and we had to manually add it to links. Not sure if it's related but thought I should mention.

bossjie commented 3 months ago

Sorry as there is nothing indicating something going wrong in the logs and I can't reproduce this locally, I don't know how to help. I think it's related to your configuration though as nobody else has reported this issue. Can you maybe share your whole setup configuration so I can try to reproduce?

Dear @AgnesToulet , I met similar issue, got the login pic file using curl cmd to download pic. See here to learn details and reproduce https://github.com/grafana/grafana/issues/84797 . it was working on grafana 9.4.7 with apikey, but failed once I migrate apikey to service account& token in 9.4.7. same symptom on grafana 10.4 as newest version force migrate apikey to SA

bossjie commented 3 months ago

@AgnesToulet May I know if we have any progres/plan on it? thanks in advance.

hjpotter92 commented 1 week ago

i think i've figured out the cause. it seems that when grafana is deployed behind a reverse proxy, with the value of GF_SERVER_ROOT_URL set, it issues a 302 redirect for the request received from image-renderer (which uses the callback_url parameter).

GF_RENDERING_CALLBACK_URL:                                       http://localhost:3000/

the 302 redirect is missing X-Auth-Token header in request, leading to the login page being rendered. i've now fixed it by setting GF_RENDERING_CALLBACK_URL value to be same as GF_SERVER_ROOT_URL.

atanunq commented 1 week ago

In the Helm chart, the above translates to setting the following value, which fixed the issue for me. Thank you, @hjpotter92!

imageRenderer:
  grafanaSubPath: grafana # must match grafana.ini.server.root_url