When indexing a VERY large text document (50 to 200MB) NEST throws WebException: The request was aborted: The request was canceled

Hello,

I have an ETL tool that transforms Office documents to text and indexes them into ElasticSearch. My documents sizes range very widely from a few kb to 500mb. When my document is very large, I get Web exceptions; typically when the size is > 50mb. ES itself is functioning and I can access it through Kibana but the document does not update.

My ES is running on a Windows Server 2012 R2, JVM HeapSize -Xms = -Xmx = 4gb, and m_lock_all is true. http.max_content_length = 500mb.

Please advise how I can debug what the issue is. Are there any windows level settings, or http settings or NEST Client settings I can adjust to ensure large documents get transferred. What should I look for in elastic search log files.

Thanks & Regards,
Raj

Can you share a trace?
Can you share elasticsearch logs?

Hello David,

Where should I look for the trace? Regarding elasticsearch\logs, these are the only entries I found since my ETL app started.
(Not sure if its relevant ; Though usually ES runs as a service, I am currently running it from command prompt to debug.)

FYI below - 'aura_es_cluster' is the name of my cluster and has just one node

I don't see any relevant info. Please let me know if I can do anything to increase logging.

Regards,
Raj

On Stdout :

[2017-09-24T21:44:04,471][INFO ][o.e.c.m.MetaDataMappingService] [ES_Node_ATP2ZU2APDWV006] [.kibana/ldHaAAF2Tf22hGM1dayEiw] create_mapping [index-pattern]
[2017-09-24T21:44:15,571][INFO ][o.e.c.m.MetaDataMappingService] [ES_Node_ATP2ZU2APDWV006] [.monitoring-kibana-2-2017.09.24/9iPos1fQQLOpu90FhsIBKg] update_mapping [kibana_stats]
[2017-09-25T00:00:12,721][INFO ][o.e.c.m.MetaDataCreateIndexService] [ES_Node_ATP2ZU2APDWV006] [.monitoring-kibana-2-2017.09.25] creating index, cause [auto(bulk api)], templates [.monitoring-kibana-2], shards [1]/[1], mappings [default, kibana_stats]
[2017-09-25T00:01:24,496][INFO ][o.e.c.m.MetaDataCreateIndexService] [ES_Node_ATP2ZU2APDWV006] [.monitoring-es-2-2017.09.25] creating index, cause [auto(bulk api)], templates [.monitoring-es-2], shards [1]/[1], mappings [shards, node, default, index_stats, index_recovery, cluster_state, cluster_stats, node_stats, indices_stats]
[2017-09-25T00:01:25,794][INFO ][o.e.c.m.MetaDataMappingService] [ES_Node_ATP2ZU2APDWV006] [.monitoring-es-2-2017.09.25/dIf5183pQkmLtdJTGc51sg] update_mapping [cluster_stats]
[2017-09-25T00:01:27,263][INFO ][o.e.c.m.MetaDataMappingService] [ES_Node_ATP2ZU2APDWV006] [.monitoring-es-2-2017.09.25/dIf5183pQkmLtdJTGc51sg] update_mapping [node_stats]
[2017-09-25T00:01:27,481][INFO ][o.e.c.m.MetaDataMappingService] [ES_Node_ATP2ZU2APDWV006] [.monitoring-es-2-2017.09.25/dIf5183pQkmLtdJTGc51sg] update_mapping [index_stats]
[2017-09-25T00:01:27,606][INFO ][o.e.c.m.MetaDataMappingService] [ES_Node_ATP2ZU2APDWV006] [.monitoring-es-2-2017.09.25/dIf5183pQkmLtdJTGc51sg] update_mapping [indices_stats]
[2017-09-25T00:46:01,553][INFO ][o.e.c.m.MetaDataMappingService] [ES_Node_ATP2ZU2APDWV006] [.monitoring-kibana-2-2017.09.25/SdSeepoLT4y8wpoYztA3Dw] update_mapping [kibana_stats]
[2017-09-25T01:23:06,310][INFO ][o.e.c.m.MetaDataMappingService] [ES_Node_ATP2ZU2APDWV006] [.monitoring-kibana-2-2017.09.25/SdSeepoLT4y8wpoYztA3Dw] update_mapping [kibana_stats]

aura_es_cluster-2017-09-24.log :

[2017-09-25T00:00:12,721][INFO ][o.e.c.m.MetaDataCreateIndexService] [ES_Node_ATP2ZU2APDWV006] [.monitoring-kibana-2-2017.09.25] creating index, cause [auto(bulk api)], templates [.monitoring-kibana-2], shards [1]/[1], mappings [default, kibana_stats]
[2017-09-25T00:01:24,496][INFO ][o.e.c.m.MetaDataCreateIndexService] [ES_Node_ATP2ZU2APDWV006] [.monitoring-es-2-2017.09.25] creating index, cause [auto(bulk api)], templates [.monitoring-es-2], shards [1]/[1], mappings [shards, node, default, index_stats, index_recovery, cluster_state, cluster_stats, node_stats, indices_stats]
[2017-09-25T00:01:25,794][INFO ][o.e.c.m.MetaDataMappingService] [ES_Node_ATP2ZU2APDWV006] [.monitoring-es-2-2017.09.25/dIf5183pQkmLtdJTGc51sg] update_mapping [cluster_stats]
[2017-09-25T00:01:27,263][INFO ][o.e.c.m.MetaDataMappingService] [ES_Node_ATP2ZU2APDWV006] [.monitoring-es-2-2017.09.25/dIf5183pQkmLtdJTGc51sg] update_mapping [node_stats]
[2017-09-25T00:01:27,481][INFO ][o.e.c.m.MetaDataMappingService] [ES_Node_ATP2ZU2APDWV006] [.monitoring-es-2-2017.09.25/dIf5183pQkmLtdJTGc51sg] update_mapping [index_stats]
[2017-09-25T00:01:27,606][INFO ][o.e.c.m.MetaDataMappingService] [ES_Node_ATP2ZU2APDWV006] [.monitoring-es-2-2017.09.25/dIf5183pQkmLtdJTGc51sg] update_mapping [indices_stats]
[2017-09-25T00:46:01,553][INFO ][o.e.c.m.MetaDataMappingService] [ES_Node_ATP2ZU2APDWV006] [.monitoring-kibana-2-2017.09.25/SdSeepoLT4y8wpoYztA3Dw] update_mapping [kibana_stats]
[2017-09-25T01:23:06,310][INFO ][o.e.c.m.MetaDataMappingService] [ES_Node_ATP2ZU2APDWV006] [.monitoring-kibana-2-2017.09.25/SdSeepoLT4y8wpoYztA3Dw] update_mapping [kibana_stats]

Does Nest provide more details than WebException? It's too vague to me.

May be Nest experts can help here... @Martijn_Laarman ?

Can you share the .NET exception stacktrace or the complete response.DebugInformation? Are you running .NET core ?

Hello Martijn,

Please find the 'response' object below. Should I configure HttpConnection.RequestTimeout to some big number? If so, how can I compute what the value should be? Will that work? Are there any other connection settings (keepalive?) I should look into when transferring very large files?

FYI, At this stage, I am constrained to a small server shared with other app services. Its running at 96% capacity but is fairly responsive. Will this have an impact? Are there any ES levers I can pull?

Regards,
Raj

response.lApiCall

{
"Success": false,
"HttpMethod": 1,
"Uri": "http://<my_es_endpoint>:9200/eng-b9ee2d2a-0dce-461e-ac4b-2acb0c120075/esevidencetype/6ab07910-f081-e711-8140-000d3a13f5d3/_update",
"RequestBodyInBytes": null,
"ResponseBodyInBytes": null,
"Body": null,
"HttpStatusCode": null,
"AuditTrail": [
{
"Event": 9,
"Started": "2017-09-25T16:24:25.9540064Z",
"Ended": "2017-09-25T16:25:26.1192555Z",
"Node": {
"Uri": "http://<my_es_endpoint>:9200/",
"IsResurrected": false,
"HttpEnabled": true,
"HoldsData": true,
"MasterEligible": true,
"Id": null,
"Name": null,
"FailedAttempts": 1,
"DeadUntil": "2017-09-25T16:26:26.123257Z",
"IsAlive": false
},
"Path": "eng-b9ee2d2a-0dce-461e-ac4b-2acb0c120075/esevidencetype/6ab07910-f081-e711-8140-000d3a13f5d3/_update",
"Exception": null
},
{
"Event": 11,
"Started": "2017-09-25T16:25:26.1372479Z",
"Ended": "0001-01-01T00:00:00",
"Node": null,
"Path": null,
"Exception": null
}
],
"SuccessOrKnownError": false,
"OriginalException": {
"ClassName": "System.Net.WebException",
"Message": "The operation has timed out",
"Data": {},
"InnerException": null,
"HelpURL": null,
"StackTraceString": " at System.Net.HttpWebRequest.GetResponse()\r\n at Elasticsearch.Net.HttpConnection.Request[TReturn](RequestData requestData) in C:\Users\russ\source\elasticsearch-net-5.x\src\Elasticsearch.Net\Connection\HttpConnection.cs:line 143",
"RemoteStackTraceString": null,
"RemoteStackIndex": 0,
"ExceptionMethod": "8\nGetResponse\nSystem, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089\nSystem.Net.HttpWebRequest\nSystem.Net.WebResponse GetResponse()",
"HResult": -2146233079,
"Source": "System",
"WatsonBuckets": null
},
"ServerError": null,
}

DebugInformation:

Invalid NEST response built from a unsuccessful low level call on POST: /eng-b9ee2d2a-0dce-461e-ac4b-2acb0c120075/esevidencetype/6ab07910-f081-e711-8140-000d3a13f5d3/_update

Audit trail of this API call:

  • [1] BadResponse: Node: http://<my_es_endpoint>:9200/ Took: 00:01:00.1652491
  • [2] MaxTimeoutReached: Took: -736596.16:25:26.1372479
    OriginalException: System.Net.WebException: The operation has timed out
    at System.Net.HttpWebRequest.GetResponse()
    at Elasticsearch.Net.HttpConnection.Request[TReturn](RequestData requestData) in C:\Users\russ\source\elasticsearch-net-5.x\src\Elasticsearch.Net\Connection\HttpConnection.cs:line 143

Request:
<Request stream not captured or already read to completion by serializer. Set DisableDirectStreaming() on ConnectionSettings to force it to be set on the response.>

Response:
<Response stream not captured or already read to completion by serializer. Set DisableDirectStreaming() on ConnectionSettings to force it to be set on the response.>

Hi David & Martijn,

 Thank you for your pointers.  Setting the xxxRequest.Timeout to 20 mins fixed my issue.  But there doesn't seem to be a NEST exposed property to to set the timeout once for all the calls, something like in ConnectionSettings.  Please advise if its possible.  I am using 5.2.2 but will upgrade to 5.6.

Regards,
Raj

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