Reporting generation vs timeout

Elastic Stack Kibana
1

Got a Kibana 7.4.2 instance behind a HAproxy which fails to generate PDF reports and wondering howto debug this issue further.

Seeing this in my kibana log:

{"type":"log","@timestamp":"2019-11-21T09:56:37Z","tags":["reporting","esqueue","queue-worker","warning"],"pid":2022,"message":"k38i5wsa01k6ff6300dx0l36 - Timeout processing job k38jbzsk01k6ff63004tgv7k"}
{"type":"log","@timestamp":"2019-11-21T09:56:37Z","tags":["reporting","esqueue","queue-worker","warning"],"pid":2022,"message":"k38i5wsa01k6ff6300dx0l36 - Timeout on job k38jbzsk01k6ff63004tgv7k"}
{"type":"log","@timestamp":"2019-11-21T09:56:37Z","tags":["reporting","esqueue","queue-worker","info"],"pid":2022,"message":"k38i5wsa01k6ff6300dx0l36 - Job execution completed successfully"}
{"type":"log","@timestamp":"2019-11-21T09:56:37Z","tags":["reporting","printable_pdf","execute","k38jbzsk01k6ff63004tgv7k","error"],"pid":2022,"message":"waitForSelector .application failed on http://kibana7:1080/perf7/s/tanium/app/canvas"}

Seems like the headless processes are just waiting for something and then the queue manager process (here pid 2022) eventually decides to do a timeout, but why...

Got this kibana settings:

server.port: 1080
server.host: "kibana7"
server.basePath: "/perf7"
server.rewriteBasePath: false

Wondering if using a basePath creates any issue for reporting...

2

Hey @stefws,

I wouldn't expect the base path to cause an issue for Reporting.
Since you're running behind a reverse-proxy, can you try configuring the Reporting Server Settings, as described here?: https://www.elastic.co/guide/en/kibana/current/reporting-settings-kb.html#reporting-kibana-server-settings

If that doesn't help, then we can try to debug further by enabling verbose logging (set logging.verbose: true in your kibana.yml)

3

doesn't seem to change much with the xpack.reporting.kibanaServer keys defined
With debug logging I get something like this:

{"type":"log","@timestamp":"2019-11-21T14:37:44Z","tags":["debug","plugins","security","basic"],"pid":10717,"message":"Trying to authenticate user request to /api/reporting/generate/printablePdf?jobParams=(browserTimezone%3AAmerica%2FPhoenix%2Clayout%3A(dimensions%3A(height%3A720%2Cwidth%3A1080)%2Cid%3Apreserve_layout)%2CobjectType%3A'canvas%20workpad'%2CrelativeUrls%3A!(%2Fapp%2Fcanvas%23%2Fexport%2Fworkpad%2Fpdf%2Fworkpad-5dd0a737-84b8-4a08-a2bd-a8bbb7a47fb7%2Fpage%2F1%2C%2Fapp%2Fcanvas%23%2Fexport%2Fworkpad%2Fpdf%2Fworkpad-5dd0a737-84b8-4a08-a2bd-a8bbb7a47fb7%2Fpage%2F2%2C%2Fapp%2Fcanvas%23%2Fexport%2Fworkpad%2Fpdf%2Fworkpad-5dd0a737-84b8-4a08-a2bd-a8bbb7a47fb7%2Fpage%2F3%2C%2Fapp%2Fcanvas%23%2Fexport%2Fworkpad%2Fpdf%2Fworkpad-5dd0a737-84b8-4a08-a2bd-a8bbb7a47fb7%2Fpage%2F4%2C%2Fapp%2Fcanvas%23%2Fexport%2Fworkpad%2Fpdf%2Fworkpad-5dd0a737-84b8-4a08-a2bd-a8bbb7a47fb7%2Fpage%2F5%2C%2Fapp%2Fcanvas%23%2Fexport%2Fworkpad%2Fpdf%2Fworkpad-5dd0a737-84b8-4a08-a2bd-a8bbb7a47fb7%2Fpage%2F6)%2Ctitle%3A'Test%20Report')."}
{"type":"log","@timestamp":"2019-11-21T14:37:44Z","tags":["debug","plugins","security","basic"],"pid":10717,"message":"Trying to authenticate via header."}
{"type":"log","@timestamp":"2019-11-21T14:37:44Z","tags":["debug","plugins","security","basic"],"pid":10717,"message":"Authorization header is not presented."}
{"type":"log","@timestamp":"2019-11-21T14:37:44Z","tags":["debug","plugins","security","basic"],"pid":10717,"message":"Trying to authenticate via state."}
{"type":"log","@timestamp":"2019-11-21T14:37:44Z","tags":["debug","plugins","security","basic"],"pid":10717,"message":"Request has been authenticated via state."}
{"type":"log","@timestamp":"2019-11-21T14:37:44Z","tags":["reporting","esqueue","queue-worker","debug"],"pid":10717,"message":"k38tldjb089pff63002r0feb - Job created in index .reporting-2019.11.17"}
{"type":"log","@timestamp":"2019-11-21T14:37:44Z","tags":["reporting","esqueue","queue-worker","debug"],"pid":10717,"message":"k38tldjb089pff63002r0feb - Job index refreshed .reporting-2019.11.17"}
{"type":"log","@timestamp":"2019-11-21T14:37:44Z","tags":["reporting","queue-job","info"],"pid":10717,"message":"Successfully queued job: k38tldjb089pff63002r0feb"}
{"type":"log","@timestamp":"2019-11-21T14:37:44Z","tags":["reporting","esqueue","queue-worker","debug"],"pid":10717,"message":"k38tfulm089pff63005pvc6w - 1 outstanding jobs returned"}
{"type":"log","@timestamp":"2019-11-21T14:37:45Z","tags":["reporting","esqueue","queue-worker","info"],"pid":10717,"message":"k38tfulm089pff63005pvc6w - Claimed job k38tldjb089pff63002r0feb"}
{"type":"log","@timestamp":"2019-11-21T14:37:45Z","tags":["reporting","esqueue","queue-worker","info"],"pid":10717,"message":"k38tfulm089pff63005pvc6w - Starting job"}
{"type":"log","@timestamp":"2019-11-21T14:37:45Z","tags":["reporting","browser-driver","debug"],"pid":10717,"message":"Creating browser driver factory"}
{"type":"log","@timestamp":"2019-11-21T14:37:45Z","tags":["reporting","browser-driver","debug"],"pid":10717,"message":"Browser driver factory created"}
{"type":"log","@timestamp":"2019-11-21T14:37:45Z","tags":["reporting","printable_pdf","execute","k38tldjb089pff63002r0feb","info"],"pid":10717,"message":"opening url http://kibana7.mxi.tdcfoo:1080/perf/s/tanium/app/canvas#/export/workpad/pdf/workpad-5dd0a737-84b8-4a08-a2bd-a8bbb7a47fb7/page/1?forceNow=2019-11-21T14%3A37%3A44.518Z"}
{"type":"log","@timestamp":"2019-11-21T14:37:45Z","tags":["reporting","printable_pdf","execute","k38tldjb089pff63002r0feb","debug"],"pid":10717,"message":"Using custom headers for http://kibana7.mxi.tdcfoo:1080/perf/s/tanium/app/canvas"}
{"type":"log","@timestamp":"2019-11-21T14:37:45Z","tags":["license","debug","xpack"],"pid":10717,"message":"Calling [data] Elasticsearch _xpack API. Polling frequency: 30001"}
{"type":"log","@timestamp":"2019-11-21T14:37:45Z","tags":["plugin","debug"],"pid":10717,"message":"Checking Elasticsearch version"}
{"type":"log","@timestamp":"2019-11-21T14:37:45Z","tags":["reporting","printable_pdf","execute","k38tldjb089pff63002r0feb","browser","debug"],"pid":10717,"message":"Failed to load resource: the server responded with a status of 400 (Bad Request)"}
{"type":"log","@timestamp":"2019-11-21T14:37:45Z","tags":["reporting","printable_pdf","execute","k38tldjb089pff63002r0feb","debug"],"pid":10717,"message":"waitForSelector .application"}

4

Thanks for the additional logs.

Nothing looks out of place, but I wish there was more detail around the "bad request" we're seeing. What happens if you navigate directly to http://kibana7.mxi.tdcfoo:1080/perf/s/tanium/app/canvas#/export/workpad/pdf/workpad-5dd0a737-84b8-4a08-a2bd-a8bbb7a47fb7/page/1?forceNow=2019-11-21T14%3A37%3A44.518Z in your browser?

5

Shows me the first page of the requested report in Workpad of Canvas

6

@stefws Thanks for testing.

What does your HAProxy setup look like? Is it doing anything with authentication, or manipulating the requests in any way?

Can you check the HAProxy logs and see what it's saying about that request? Is it possible that HAProxy is responding with the 400 instead of Kibana?

7

Well the HAproxy terminates the SSL and load balances over a pair of Nginx proxies used prior to xpacks included in the basic license to perform user authentication. Same setup are now used to proxy to various kibana instances, hence the use of server.basePath.

Not believing neither haproxy nor nginx to be involved in reporting as xpack.reporting.kibanaServer.* are pointing directly at the local kibana instance listening IP.

[root@kibana7 ~]# netstat -lntp | grep node
tcp 0 0 10.45.69.65:1080 0.0.0.0:* LISTEN 11510/node
[root@kibana7 ~]# ping kibana7.mxi.tdcfoo
PING kibana7.mxi.tdcfoo (10.45.69.65) 56(84) bytes of data.
64 bytes from kibana7.mxi.tdcfoo (10.45.69.65): icmp_seq=1 ttl=64 time=0.020 ms
64 bytes from kibana7.mxi.tdcfoo (10.45.69.65): icmp_seq=2 ttl=64 time=0.012 ms
^C

8

Latest error when attempting to generate a PDF:

16
Screenshot 2019-11-27 at 15.12.16.png1575×132 19.2 KB 

{"type":"error","@timestamp":"2019-11-27T13:53:07Z","tags":["reporting","printable_pdf","execute","k3hckhuf0jfh352e5dfhh12l","error"],"pid":718,"level":"error","error":{"message":"Request to [http://kibana7.mxi.tdcfoo:1080/perf5/login?next=%2Fperf5%2Fperf5%2Flogin%3Fnext%3D%252Fperf5%252Fperf5%252Flogin%253Fnext%253D%25252Fperf5%25252Fperf5%25252Flogin%25253Fnext%25253D%2525252Fperf5%2525252Fperf5%2525252Flogin%2525253Fnext%2525253D ... %2Fapp%2525252525252525252525252525252525252Fcanvas] failed! [net::ERR_TOO_MANY_REDIRECTS]","name":"Error","stack":"Error: Request to [http://kibana7.mxi.tdcfoo:1080/perf5/login?next=%2Fperf5%2Fperf5%2Flogin%3Fnext%3D%252Fperf5%252Fperf5%252Flogin%253Fnext%253D%25252Fperf5%25252Fperf5%25252Flogin%25253Fnext%25253D%2525252Fperf5%2525252Fperf5%2525252Flogin ... %2Fapp%2525252525252525252525252525252525252Fcanvas] failed! [net::ERR_TOO_MANY_REDIRECTS]\n    at MergeMapSubscriber.Rx.fromEvent.pipe.req [as project] (/usr/share/kibana/x-pack/legacy/plugins/reporting/server/browsers/chromium/driver_factory/index.js:159:32)\n    at MergeMapSubscriber._tryNext (/usr/share/kibana/node_modules/rxjs/internal/operators/mergeMap.js:65:27)\n    at MergeMapSubscriber._next (/usr/share/kibana/node_modules/rxjs/internal/operators/mergeMap.js:55:18)\n    at MergeMapSubscriber.Subscriber.next (/usr/share/kibana/node_modules/rxjs/internal/Subscriber.js:64:18)\n    at Page.handler (/usr/share/kibana/node_modules/rxjs/internal/observable/fromEvent.js:22:28)\n    at Page.emit (events.js:189:13)\n    at NetworkManager.Page.networkManager.on.event (/usr/share/kibana/node_modules/puppeteer-core/lib/Page.js:112:74)\n    at NetworkManager.emit (events.js:189:13)\n    at NetworkManager._onLoadingFailed (/usr/share/kibana/node_modules/puppeteer-core/lib/NetworkManager.js:315:10)\n    at CDPSession.emit (events.js:189:13)\n    at CDPSession._onMessage (/usr/share/kibana/node_modules/puppeteer-core/lib/Connection.js:200:12)\n    at Connection._onMessage (/usr/share/kibana/node_modules/puppeteer-core/lib/Connection.js:112:17)\n    at PipeTransport._dispatch (/usr/share/kibana/node_modules/puppeteer-core/lib/PipeTransport.js:61:22)\n    at Socket.PipeTransport._eventListeners.helper.addEventListener.buffer (/usr/share/kibana/node_modules/puppeteer-core/lib/PipeTransport.js:30:64)\n    at Socket.emit (events.js:189:13)\n    at addChunk (_stream_readable.js:284:12)"},"message":"Request to [http://kibana7.mxi.tdcfoo:1080/perf5/login?next=%2Fperf5%2Fperf5%2Flogin%3Fnext%3D%252Fperf5%252Fperf5%252Flogin%253Fnext%253D%25252Fperf5%25252Fperf5%25252Flogin%25253Fnext%25253D%2525252Fperf5%2525252Fperf5%2525252Flogin%2525253Fnext%2525253D%252525252Fperf5%252525252Fperf5%252525252Flogin%252525253Fnext%252525253D%25252525252Fperf5%25252525252Fperf5%25252525252Flogin%25252525253Fnext%25252525253D%2525252525252Fperf5%2525252525252Fperf5%2525252525252Flogin%2525252525253Fnext%2525252525253D%252525252525252Fperf5%252525252525252Fperf5%... 2Fapp%2525252525252525252525252525252525252Fcanvas] failed! [net::ERR_TOO_MANY_REDIRECTS]"}
{"type":"log","@timestamp":"2019-11-27T13:53:07Z","tags":["reporting","esqueue","queue-worker","error"],"pid":718,"message":"k3fxi1j200jyff6300c7c5o8 - Failure occurred on job k3hckhuf0jfh352e5dfhh12l: Error: Request to [http://kibana7.mxi.tdcfoo:1080/perf5/login?next=%2Fperf5%2Fperf5%2Flogin%3Fnext%3D%252Fperf5%252Fperf5%252Flogin%253Fnext%253D%25252Fperf5%25252Fperf5%25252Flogin%25253Fnext%25253D%2525252Fperf5%2525252Fperf5%2525252Flogin%2525253Fnext%2525253D%252525252Fperf5%252525252Fperf5%252525252Flogin%252525253Fnext%252525253D%25252525252Fperf5%25252525252Fperf5%25252525252Flogin%25252525253Fnext%25252525253D%2525252525252Fperf5%2525252525252Fperf5%2525252525252Flogin%2525252525253Fnext%2525252525253D%252525252525252Fperf5%252525252525252Fperf5%252525252525252Flogin%252525252525253Fnext%252525252525253D%25252525252525252Fperf5%25252525252525252Fperf5%25252525252525252Flogin%25252525252525253Fnext%25252525252525253D%2525252525252525252Fperf5%2525252525252525252Fperf5%2525252525252525252Flogin%2525252525252525253Fnext%2525252525252525253D%252525252525252525252Fperf5%252525252525252525252Fperf5%252525252...8)\n    at Page.handler (/usr/share/kibana/node_modules/rxjs/internal/observable/fromEvent.js:22:28)\n    at Page.emit (events.js:189:13)\n    at NetworkManager.Page.networkManager.on.event (/usr/share/kibana/node_modules/puppeteer-core/lib/Page.js:112:74)\n    at NetworkManager.emit (events.js:189:13)\n    at NetworkManager._onLoadingFailed (/usr/share/kibana/node_modules/puppeteer-core/lib/NetworkManager.js:315:10)\n    at CDPSession.emit (events.js:189:13)\n    at CDPSession._onMessage (/usr/share/kibana/node_modules/puppeteer-core/lib/Connection.js:200:12)\n    at Connection._onMessage (/usr/share/kibana/node_modules/puppeteer-core/lib/Connection.js:112:17)\n    at PipeTransport._dispatch (/usr/share/kibana/node_modules/puppeteer-core/lib/PipeTransport.js:61:22)\n    at Socket.PipeTransport._eventListeners.helper.addEventListener.buffer (/usr/share/kibana/node_modules/puppeteer-core/lib/PipeTransport.js:30:64)\n    at Socket.emit (events.js:189:13)\n    at addChunk (_stream_readable.js:284:12)"}
{"type":"log","@timestamp":"2019-11-27T13:53:07Z","tags":["reporting","esqueue","queue-worker","error"],"pid":718,"message":"A partial version of the entire error message was logged. The entire error message length is: 4077 characters."}
9

I succeed generating PDFs if configuring Kibana without HA+Nginx proxies, seems using server.basePath (removed by my proxy) causes an issue when pointing reporting directly to local kibana listening socket behind nginx proxies maybe because kibana referrals includes basePath :slight_smile:

10

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.