[Reporting] Streaming CSV download appears to not be working

[tsullivan]

Kibana version: 7.15.1

Describe the bug:

Steps to reproduce:

1. Create a large set of data where CSV output size is around 100mb
2. Add a saved search panel to a dashboard and download the CSV
3. Note that the the download is stalled until the entire CSV content body is sent in the request.
4. The browser connection will time out if the download is stalled 2 minutes or so.

Expected behavior:
As CSV Export scrolls through the data, it should stream partial content through the request so the connection doesn't time out.

Any additional context:
From @lucabelluccini

I think the only way to make this work would be for the /api/reporting/v1/generate/immediate/csv_searchsource to return immediately an header as soon as the scroll starts with a chunked transfer encoding.
After that, we should stream the content periodically to the browser so it doesn't see the request as neverending (stalled).

[elasticmachine]

Pinging @elastic/kibana-app-services (Team:AppServicesUx)

[elasticmachine]

Pinging @elastic/kibana-reporting-services (Team:Reporting Services)

[TBragi]

Could this explain the issues experienced here https://discuss.elastic.co/t/csv-reporting-truncating-results-in-7-15-x/288142/4?

After upgrading Kibana + ElasticSearch to 7.15.2 a semi-large CSV report would halt the entire Kibana instance (worked prior version 7.15.X).

After scaling Kibana server vertically (more CPU and Memory resources) and increasing the following kibana.yml settings

xpack.task_manager.max_workers: 100
xpack.reporting.queue.timeout: 600000 #Was configured prior 7.15.X upgrade
xpack.reporting.csv.maxSizeBytes: 104857600 #Was configured prior 7.15.X upgrade
xpack.reporting.csv.scroll.size: 10000

the kibana instance is now mostly able to finish the CSV report (Kibana still becomes unresponsive/slow), but it returns a truncated report containing a fraction of the expected amount of rows, and the size of it is only ~ 13 MB while the maxSizeBytes is set to 100 MB.

This issue seems only to partly explain the kibana instance becoming unresponsive, but not the fact I get a truncated report?

[tsullivan]

@TBragi This issue is about downloading the CSV from an embedded saved search panel in the Dashboard app. If that is how you've been generating the CSV, does generating a CSV from the Discover app work?

I suspect what you are getting is a different issue. Do you see any errors in the Kibana server logs? Is Kibana crashing or restarting?

xpack.reporting.csv.scroll.size: 10000

I recommend leaving this at the default setting of 500. Lowering the setting means more queries to Elasticsearch to get all the data, but it also means Kibana works on smaller JSON bodies to parse the data into CSV.

[TBragi]

@tsullivan Thanks for the response,

CSV from an embedded saved search panel in the Dashboard app

This resulted in the following error message

The Kibana instance becomes slow (does not crash, just long response times). While trying to create the report I looked at the CPU usage, and a large spike can be seen, but it only tried once to create the report (not 3 times).

Looking at the Kibana logs it seems like it generates a part of the report (the low size, expected a factor 4 larger), but it fails to serve the file:

@timestamp	message	kibana.log.tags	http.response.body.bytes
2021-11-30 10:27:15.000	CSV may contain formulas whose values have been escaped	warning, plugins, reporting, csv_searchsource_immediate, csv_searchsource_immediate, execute-job	-
2021-11-30 10:27:15.000	Job output size: 10019365 bytes.	info, plugins, reporting, csv_searchsource_immediate	-
2021-11-30 10:27:15.000	ResponseError: search_phase_execution_exception: [search_context_missing_exception] Reason: No search context found for id [27926439]; [search_context_missing_exception] Reason: No search context found for id [27205553] at onBody (/usr/share/kibana/node_modules/@elastic/elasticsearch/lib/Transport.js:355:23) at IncomingMessage.onEnd (/usr/share/kibana/node_modules/@elastic/elasticsearch/lib/Transport.js:279:11) at IncomingMessage.emit (events.js:412:35) at endReadableNT (internal/streams/readable.js:1334:12) at processTicksAndRejections (internal/process/task_queues.js:82:21) { meta: { body: { error: [Object], status: 404 }, statusCode: 404, headers: { 'x-opaque-id': 'XXXXX', 'x-elastic-product': 'Elasticsearch', 'content-type': 'application/json; charset=UTF-8', 'content-length': '726' }, meta: { context: null, request: [Object], name: 'elasticsearch-js', connection: [Object], attempts: 0, aborted: false } } }	error, plugins, reporting, csv_searchsource_immediate, csv_searchsource_immediate, execute-job	-
2021-11-30 10:27:15.000	ResponseError: {"succeeded":true,"num_freed":0} at onBody (/usr/share/kibana/node_modules/@elastic/elasticsearch/lib/Transport.js:355:23) at IncomingMessage.onEnd (/usr/share/kibana/node_modules/@elastic/elasticsearch/lib/Transport.js:279:11) at IncomingMessage.emit (events.js:412:35) at endReadableNT (internal/streams/readable.js:1334:12) at processTicksAndRejections (internal/process/task_queues.js:82:21) { meta: { body: { succeeded: true, num_freed: 0 }, statusCode: 404, headers: { 'x-opaque-id': 'XXXXXXXX', 'x-elastic-product': 'Elasticsearch', 'content-type': 'application/json; charset=UTF-8', 'content-length': '32' }, meta: { context: null, request: [Object], name: 'elasticsearch-js', connection: [Object], attempts: 0, aborted: false } } }	error, plugins, reporting, csv_searchsource_immediate, csv_searchsource_immediate, execute-job	-
2021-11-30 10:24:17.000	POST /api/reporting/v1/generate/immediate/csv_searchsource 200 177634ms - 9.6MB	-	10.019.365

does generating a CSV from the Discover app work?

When I create a CSV report from the Discover App, the Kibana instance responds in the same way by slowing down and high cpu usage. The report is successfully generated, but it is truncated (it contains ~ 60.000 rows, but i expected ~300.000 rows)

The Kibana logs tells the same search_phase_execution_exception:

@timestamp	message	kibana.log.tags	http.response.body.bytes
2021-11-30 10:57:10.000	GET /api/reporting/jobs/download/kwlx9s1h000665941b9j1dzy 200 2274ms	security:canRedirect	0
2021-11-30 10:57:01.000	Saved csv_searchsource job /.reporting-2021-11-28/_doc/kwlx9s1h000665941b9j1dzy	info, plugins, reporting, runTask	-
this repeats 12 times	this repeats 12 times	this repeats 12 times	this repeats 12 times
2021-11-30 10:56:55.000	GET /api/reporting/jobs/list?page=0&ids=kwlx9s1h000665941b9j1dzy 200 6032ms - 1.3KB	-	1.361
2021-11-30 10:56:55.000	ResponseError: {"succeeded":true,"num_freed":0} at onBody (/usr/share/kibana/node_modules/@elastic/elasticsearch/lib/Transport.js:355:23) at IncomingMessage.onEnd (/usr/share/kibana/node_modules/@elastic/elasticsearch/lib/Transport.js:279:11) at IncomingMessage.emit (events.js:412:35) at endReadableNT (internal/streams/readable.js:1334:12) at processTicksAndRejections (internal/process/task_queues.js:82:21) { meta: { body: { succeeded: true, num_freed: 0 }, statusCode: 404, headers: { 'x-opaque-id': 'XXXXX', 'x-elastic-product': 'Elasticsearch', 'content-type': 'application/json; charset=UTF-8', 'content-length': '32' }, meta: { context: null, request: [Object], name: 'elasticsearch-js', connection: [Object], attempts: 0, aborted: false } } }	error, plugins, reporting, runTask, csv_searchsource, csv_searchsource, execute-job, kwlx9s1h000665941b9j1dzy	-
2021-11-30 10:56:55.000	GET /api/reporting/jobs/list?page=0&ids=kwlx9s1h000665941b9j1dzy 200 1277ms - 1.3KB	-	1.361
2021-11-30 10:56:55.000	GET /api/reporting/jobs/list?page=0&ids=kwlx9s1h000665941b9j1dzy 200 1283ms - 1.3KB	-	1.361
2021-11-30 10:56:55.000	ResponseError: search_phase_execution_exception: [search_context_missing_exception] Reason: No search context found for id [27239299]; [search_context_missing_exception] Reason: No search context found for id [27907640] at onBody (/usr/share/kibana/node_modules/@elastic/elasticsearch/lib/Transport.js:355:23) at IncomingMessage.onEnd (/usr/share/kibana/node_modules/@elastic/elasticsearch/lib/Transport.js:279:11) at IncomingMessage.emit (events.js:412:35) at endReadableNT (internal/streams/readable.js:1334:12) at processTicksAndRejections (internal/process/task_queues.js:82:21) { meta: { body: { error: [Object], status: 404 }, statusCode: 404, headers: { 'x-opaque-id': 'XXXXX', 'x-elastic-product': 'Elasticsearch', 'content-type': 'application/json; charset=UTF-8', 'content-length': '726' }, meta: { context: null, request: [Object], name: 'elasticsearch-js', connection: [Object], attempts: 0, aborted: false } } }	error, plugins, reporting, runTask, csv_searchsource, csv_searchsource, execute-job, kwlx9s1h000665941b9j1dzy	-
this repeats 30 times	this repeats 30 times	this repeats 30 times	this repeats 30 times
2021-11-30 10:53:13.000	GET /api/reporting/jobs/list?page=0&ids=kwlx9s1h000665941b9j1dzy 200 135ms - 1.3KB	-	1.361
2021-11-30 10:53:12.000	Generating request for space: this-is-my-space-id	info, plugins, reporting, runTask, csv_searchsource, csv_searchsource, execute-job, kwlx9s1h000665941b9j1dzy	-
2021-11-30 10:53:12.000	Request uses Space ID: this-is-my-space-id	info, plugins, reporting, runTask, csv_searchsource, csv_searchsource, execute-job, kwlx9s1h000665941b9j1dzy	-
2021-11-30 10:53:12.000	Creating UI Settings Client for space: this-is-my-space-id	info, plugins, reporting, runTask, csv_searchsource, csv_searchsource, execute-job, kwlx9s1h000665941b9j1dzy	-
2021-11-30 10:53:10.000	Scheduled csv_searchsource reporting task. Task ID: task:53573720-51c3-11ec-add2-abcfcd8ac870. Report ID: kwlx9s1h000665941b9j1dzy	info, plugins, reporting, createJob	-
2021-11-30 10:53:09.000	POST /api/reporting/generate/csv_searchsource 200 545ms - 1.2KB	-	1.254
2021-11-30 10:53:09.000	Request uses Space ID: this-is-my-space-id	info, plugins, reporting, createJob, csv_searchsource, csv_searchsource, create-job	-

[Evesy]

Potentially unrelated but we've also observed degradation in CSV reporting having jumpe form 6.8 to 7.15.1. A 400k row report that would previously complete successfully in a reasonable amount of time is now using an awful lot of CPU on the chosen Kibana instance to the point it becomes unresponsive for users and is eventually killed by our liveness probes

Interestingly I spotted the scroll settings that I haven't previously seen on 6.x and have just started tweaking them to see the impact on things. In this instance I've bumped it up to 10000, but I imagine the scroll window has expired here, as the finished report is only ~100k rows, when the original discover query is ~400k

{"ecs":{"version":"1.9.0"},"@timestamp":"2021-12-01T15:04:10.573+00:00","message":"Building 10000 CSV data rows...","log":{"level":"DEBUG","logger":"plugins.reporting.runTask.csv_searchsource.csv_searchsource.execute-job.kwnnonrl00v7180faa7846im"},"process":{"pid":1123}}
{"ecs":{"version":"1.9.0"},"@timestamp":"2021-12-01T15:04:10.849+00:00","message":"executing scroll request","log":{"level":"DEBUG","logger":"plugins.reporting.runTask.csv_searchsource.csv_searchsource.execute-job.kwnnonrl00v7180faa7846im"},"process":{"pid":1123}}
{"type":"log","@timestamp":"2021-12-01T15:05:23+00:00","tags":["error","plugins","taskManager"],"pid":1123,"message":"[Task Poller Monitor]: Observable Monitor: Hung Observable restarted after 33000ms of inactivity"}
{"ecs":{"version":"1.9.0"},"@timestamp":"2021-12-01T15:05:23.814+00:00","message":"[Task Poller Monitor]: Observable Monitor: Hung Observable restarted after 33000ms of inactivity","log":{"level":"ERROR","logger":"plugins.taskManager"},"process":{"pid":1123}}
{"ecs":{"version":"1.9.0"},"@timestamp":"2021-12-01T15:05:23.823+00:00","message":"search_phase_execution_exception: [search_context_missing_exception] Reason: No search context found for id [7633571]; [search_context_missing_exception] Reason: No search context found for id [6191081]; [search_context_missing_exception] Reason: No search context found for id [6183533]; [search_context_missing_exception] Reason: No search context found for id [6573527]; [search_context_missing_exception] Reason: No search context found for id [4759709]; [search_context_missing_exception] Reason: No search context found for id [6041275]; [search_context_missing_exception] Reason: No search context found for id [6709776]; [search_context_missing_exception] Reason: No search context found for id [6821453]; [search_context_missing_exception] Reason: No search context found for id [6788788]; [search_context_missing_exception] Reason: No search context found for id [6821454]; [search_context_missing_exception] Reason: No search context found for id [4759708]; [search_context_missing_exception] Reason: No search context found for id [6041276]; [search_context_missing_exception] Reason: No search context found for id [4853552]; [search_context_missing_exception] Reason: No search context found for id [6788786]; [search_context_missing_exception] Reason: No search context found for id [6623159]; [search_context_missing_exception] Reason: No search context found for id [6788787]; [search_context_missing_exception] Reason: No search context found for id [4853553]; [search_context_missing_exception] Reason: No search context found for id [4853554]","error":{"message":"search_phase_execution_exception: [search_context_missing_exception] Reason: No search context found for id [7633571]; [search_context_missing_exception] Reason: No search context found for id [6191081]; [search_context_missing_exception] Reason: No search context found for id [6183533]; [search_context_missing_exception] Reason: No search context found for id [6573527]; [search_context_missing_exception] Reason: No search context found for id [4759709]; [search_context_missing_exception] Reason: No search context found for id [6041275]; [search_context_missing_exception] Reason: No search context found for id [6709776]; [search_context_missing_exception] Reason: No search context found for id [6821453]; [search_context_missing_exception] Reason: No search context found for id [6788788]; [search_context_missing_exception] Reason: No search context found for id [6821454]; [search_context_missing_exception] Reason: No search context found for id [4759708]; [search_context_missing_exception] Reason: No search context found for id [6041276]; [search_context_missing_exception] Reason: No search context found for id [4853552]; [search_context_missing_exception] Reason: No search context found for id [6788786]; [search_context_missing_exception] Reason: No search context found for id [6623159]; [search_context_missing_exception] Reason: No search context found for id [6788787]; [search_context_missing_exception] Reason: No search context found for id [4853553]; [search_context_missing_exception] Reason: No search context found for id [4853554]","type":"ResponseError","stack_trace":"ResponseError: search_phase_execution_exception: [search_context_missing_exception] Reason: No search context found for id [7633571]; [search_context_missing_exception] Reason: No search context found for id [6191081]; [search_context_missing_exception] Reason: No search context found for id [6183533]; [search_context_missing_exception] Reason: No search context found for id [6573527]; [search_context_missing_exception] Reason: No search context found for id [4759709]; [search_context_missing_exception] Reason: No search context found for id [6041275]; [search_context_missing_exception] Reason: No search context found for id [6709776]; [search_context_missing_exception] Reason: No search context found for id [6821453]; [search_context_missing_exception] Reason: No search context found for id [6788788]; [search_context_missing_exception] Reason: No search context found for id [6821454]; [search_context_missing_exception] Reason: No search context found for id [4759708]; [search_context_missing_exception] Reason: No search context found for id [6041276]; [search_context_missing_exception] Reason: No search context found for id [4853552]; [search_context_missing_exception] Reason: No search context found for id [6788786]; [search_context_missing_exception] Reason: No search context found for id [6623159]; [search_context_missing_exception] Reason: No search context found for id [6788787]; [search_context_missing_exception] Reason: No search context found for id [4853553]; [search_context_missing_exception] Reason: No search context found for id [4853554]\n    at onBody (/usr/share/kibana/node_modules/@elastic/elasticsearch/lib/Transport.js:355:23)\n    at IncomingMessage.onEnd (/usr/share/kibana/node_modules/@elastic/elasticsearch/lib/Transport.js:279:11)\n    at IncomingMessage.emit (events.js:412:35)\n    at endReadableNT (internal/streams/readable.js:1317:12)\n    at processTicksAndRejections (internal/process/task_queues.js:82:21)"},"log":{"level":"ERROR","logger":"plugins.reporting.runTask.csv_searchsource.csv_searchsource.execute-job.kwnnonrl00v7180faa7846im"},"process":{"pid":1123}}
{"ecs":{"version":"1.9.0"},"@timestamp":"2021-12-01T15:05:23.827+00:00","message":"executing clearScroll request","log":{"level":"DEBUG","logger":"plugins.reporting.runTask.csv_searchsource.csv_searchsource.execute-job.kwnnonrl00v7180faa7846im"},"process":{"pid":1123}}
{"ecs":{"version":"1.9.0"},"@timestamp":"2021-12-01T15:05:23.977+00:00","message":"{\"succeeded\":true,\"num_freed\":0}","error":{"message":"{\"succeeded\":true,\"num_freed\":0}","type":"ResponseError","stack_trace":"ResponseError: {\"succeeded\":true,\"num_freed\":0}\n    at onBody (/usr/share/kibana/node_modules/@elastic/elasticsearch/lib/Transport.js:355:23)\n    at IncomingMessage.onEnd (/usr/share/kibana/node_modules/@elastic/elasticsearch/lib/Transport.js:279:11)\n    at IncomingMessage.emit (events.js:412:35)\n    at endReadableNT (internal/streams/readable.js:1317:12)\n    at processTicksAndRejections (internal/process/task_queues.js:82:21)"},"log":{"level":"ERROR","logger":"plugins.reporting.runTask.csv_searchsource.csv_searchsource.execute-job.kwnnonrl00v7180faa7846im"},"process":{"pid":1123}}
{"ecs":{"version":"1.9.0"},"@timestamp":"2021-12-01T15:05:23.977+00:00","message":"Finished generating. Row count: 110000.","log":{"level":"DEBUG","logger":"plugins.reporting.runTask.csv_searchsource.csv_searchsource.execute-job.kwnnonrl00v7180faa7846im"},"process":{"pid":1123}}

[tsullivan]

@TBragi @Evesy I filed this separate issue to drive the fix for the problems where CSV export causes Kibana to be unstable: #120275

The intention of this issue is to come up with a better implementation of the download CSV endpoint, so that it streams the data as it is formatted.