Fix bug: "timeout_millis" option doesn't work as expected

[sakama]

This plugin has timeout_millis option but I noticed this option is not set to org.eclipse.jetty.client.HttpClient. So fixed it.

I tested with Elastic Cloud if this change works as expected.
As a result, many SocketTimeoutException happens when I set 100ms for timeout_millis.
No SocketTimeoutException happens when I set 10000ms for timeout_millis.

Stacktrace before fixed

java.util.concurrent.ExecutionException: java.net.SocketTimeoutException: Connect Timeout
	at org.eclipse.jetty.client.util.InputStreamResponseListener.get(InputStreamResponseListener.java:228) ~[na:na]
	at org.embulk.util.retryhelper.jetty92.StringJetty92ResponseEntityReader.getResponse(StringJetty92ResponseEntityReader.java:31) ~[na:na]
	at org.embulk.util.retryhelper.jetty92.Jetty92RetryHelper$1.call(Jetty92RetryHelper.java:107) ~[na:na]
	at org.embulk.spi.util.RetryExecutor.run(RetryExecutor.java:81) [embulk:0.9.7]
	at org.embulk.spi.util.RetryExecutor.runInterruptible(RetryExecutor.java:62) [embulk:0.9.7]
	at org.embulk.util.retryhelper.jetty92.Jetty92RetryHelper.requestWithRetry(Jetty92RetryHelper.java:95) [embulk-util-retryhelper-jetty92-0.5.3.jar:na]
	at org.embulk.output.elasticsearch.ElasticsearchHttpClient.sendRequest(ElasticsearchHttpClient.java:321) [embulk-output-elasticsearch-0.4.5.jar:na]
	at org.embulk.output.elasticsearch.ElasticsearchHttpClient.sendRequest(ElasticsearchHttpClient.java:312) [embulk-output-elasticsearch-0.4.5.jar:na]
	at org.embulk.output.elasticsearch.ElasticsearchHttpClient.getEsVersion(ElasticsearchHttpClient.java:165) [embulk-output-elasticsearch-0.4.5.jar:na]
	at org.embulk.output.elasticsearch.ElasticsearchOutputPluginDelegate.validateOutputTask(ElasticsearchOutputPluginDelegate.java:204) [embulk-output-elasticsearch-0.4.5.jar:na]
	at org.embulk.output.elasticsearch.ElasticsearchOutputPluginDelegate.validateOutputTask(ElasticsearchOutputPluginDelegate.java:28) [embulk-output-elasticsearch-0.4.5.jar:na]
	at org.embulk.base.restclient.RestClientOutputPluginBaseUnsafe.transaction(RestClientOutputPluginBaseUnsafe.java:42) [embulk-base-restclient-0.5.5.jar:na]
	at org.embulk.base.restclient.RestClientOutputPluginBase.transaction(RestClientOutputPluginBase.java:56) [embulk-base-restclient-0.5.5.jar:na]
	at org.embulk.exec.BulkLoader$4$1$1.transaction(BulkLoader.java:520) [embulk:0.9.7]
	at org.embulk.exec.LocalExecutorPlugin.transaction(LocalExecutorPlugin.java:49) [embulk:0.9.7]
	at org.embulk.exec.BulkLoader$4$1.run(BulkLoader.java:515) [embulk:0.9.7]
	at org.embulk.spi.util.Filters$RecursiveControl.transaction(Filters.java:84) [embulk:0.9.7]
	at org.embulk.spi.util.Filters.transaction(Filters.java:42) [embulk:0.9.7]
	at org.embulk.exec.BulkLoader$4.run(BulkLoader.java:510) [embulk:0.9.7]
	at org.embulk.spi.FileInputRunner$RunnerControl$1$1.run(FileInputRunner.java:112) [embulk:0.9.7]
	at org.embulk.standards.CsvParserPlugin.transaction(CsvParserPlugin.java:228) [embulk:0.9.7]
	at org.embulk.spi.FileInputRunner$RunnerControl$1.run(FileInputRunner.java:107) [embulk:0.9.7]
	at org.embulk.spi.util.Decoders$RecursiveControl.transaction(Decoders.java:68) [embulk:0.9.7]
	at org.embulk.spi.util.Decoders$RecursiveControl$1.run(Decoders.java:64) [embulk:0.9.7]
	at org.embulk.standards.GzipFileDecoderPlugin.transaction(GzipFileDecoderPlugin.java:25) [embulk:0.9.7]
	at org.embulk.spi.util.Decoders$RecursiveControl.transaction(Decoders.java:60) [embulk:0.9.7]
	at org.embulk.spi.util.Decoders.transaction(Decoders.java:29) [embulk:0.9.7]
	at org.embulk.spi.FileInputRunner$RunnerControl.run(FileInputRunner.java:105) [embulk:0.9.7]
	at org.embulk.input.gcs.GcsFileInputPlugin.resume(GcsFileInputPlugin.java:106) [embulk-input-gcs-0.2.8.jar:na]
	at org.embulk.input.gcs.GcsFileInputPlugin.transaction(GcsFileInputPlugin.java:80) [embulk-input-gcs-0.2.8.jar:na]
	at org.embulk.spi.FileInputRunner.transaction(FileInputRunner.java:62) [embulk:0.9.7]
	at org.embulk.exec.BulkLoader.doRun(BulkLoader.java:506) [embulk:0.9.7]
	at org.embulk.exec.BulkLoader.access$000(BulkLoader.java:34) [embulk:0.9.7]
	at org.embulk.exec.BulkLoader$1.run(BulkLoader.java:352) [embulk:0.9.7]
	at org.embulk.exec.BulkLoader$1.run(BulkLoader.java:349) [embulk:0.9.7]
	at org.embulk.spi.Exec.doWith(Exec.java:22) [embulk:0.9.7]
	at org.embulk.exec.BulkLoader.run(BulkLoader.java:349) [embulk:0.9.7]
	at org.embulk.EmbulkEmbed.run(EmbulkEmbed.java:161) [embulk:0.9.7]
	at org.embulk.EmbulkRunner.runInternal(EmbulkRunner.java:292) [embulk:0.9.7]
	at org.embulk.EmbulkRunner.run(EmbulkRunner.java:156) [embulk:0.9.7]
	at org.embulk.cli.EmbulkRun.runSubcommand(EmbulkRun.java:436) [embulk:0.9.7]
	at org.embulk.cli.EmbulkRun.run(EmbulkRun.java:91) [embulk:0.9.7]
	at org.embulk.cli.Main.main(Main.java:26) [embulk:0.9.7]
Caused by: java.net.SocketTimeoutException: Connect Timeout
	at org.eclipse.jetty.io.SelectorManager$ManagedSelector$ConnectTimeout.run(SelectorManager.java:965) ~[na:na]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_101]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_101]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[na:1.8.0_101]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[na:1.8.0_101]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_101]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_101]
	at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_101]
org.embulk.exec.PartialExecutionException: java.lang.RuntimeException: java.util.concurrent.TimeoutException
	at org.embulk.exec.BulkLoader$LoaderState.buildPartialExecuteException(BulkLoader.java:339)
	at org.embulk.exec.BulkLoader.doRun(BulkLoader.java:565)
	at org.embulk.exec.BulkLoader.access$000(BulkLoader.java:34)
	at org.embulk.exec.BulkLoader$1.run(BulkLoader.java:352)
	at org.embulk.exec.BulkLoader$1.run(BulkLoader.java:349)
	at org.embulk.spi.Exec.doWith(Exec.java:22)
	at org.embulk.exec.BulkLoader.run(BulkLoader.java:349)
	at org.embulk.EmbulkEmbed.run(EmbulkEmbed.java:161)
	at org.embulk.EmbulkRunner.runInternal(EmbulkRunner.java:292)
	at org.embulk.EmbulkRunner.run(EmbulkRunner.java:156)
	at org.embulk.cli.EmbulkRun.runSubcommand(EmbulkRun.java:436)
	at org.embulk.cli.EmbulkRun.run(EmbulkRun.java:91)
	at org.embulk.cli.Main.main(Main.java:26)
	Suppressed: java.lang.NullPointerException
		at org.embulk.exec.BulkLoader.doCleanup(BulkLoader.java:462)
		at org.embulk.exec.BulkLoader$3.run(BulkLoader.java:396)
		at org.embulk.exec.BulkLoader$3.run(BulkLoader.java:393)
		at org.embulk.spi.Exec.doWith(Exec.java:22)
		at org.embulk.exec.BulkLoader.cleanup(BulkLoader.java:393)
		at org.embulk.EmbulkEmbed.run(EmbulkEmbed.java:164)
		... 5 more
Caused by: java.lang.RuntimeException: java.util.concurrent.TimeoutException
	at com.google.common.base.Throwables.propagate(Throwables.java:160)
	at org.embulk.util.retryhelper.jetty92.Jetty92RetryHelper.requestWithRetry(Jetty92RetryHelper.java:164)
	at org.embulk.output.elasticsearch.ElasticsearchHttpClient.sendRequest(ElasticsearchHttpClient.java:321)
	at org.embulk.output.elasticsearch.ElasticsearchHttpClient.sendRequest(ElasticsearchHttpClient.java:312)
	at org.embulk.output.elasticsearch.ElasticsearchHttpClient.getEsVersion(ElasticsearchHttpClient.java:165)
	at org.embulk.output.elasticsearch.ElasticsearchOutputPluginDelegate.validateOutputTask(ElasticsearchOutputPluginDelegate.java:204)
	at org.embulk.output.elasticsearch.ElasticsearchOutputPluginDelegate.validateOutputTask(ElasticsearchOutputPluginDelegate.java:28)
	at org.embulk.base.restclient.RestClientOutputPluginBaseUnsafe.transaction(RestClientOutputPluginBaseUnsafe.java:42)
	at org.embulk.base.restclient.RestClientOutputPluginBase.transaction(RestClientOutputPluginBase.java:56)
	at org.embulk.exec.BulkLoader$4$1$1.transaction(BulkLoader.java:520)
	at org.embulk.exec.LocalExecutorPlugin.transaction(LocalExecutorPlugin.java:49)
	at org.embulk.exec.BulkLoader$4$1.run(BulkLoader.java:515)
	at org.embulk.spi.util.Filters$RecursiveControl.transaction(Filters.java:84)
	at org.embulk.spi.util.Filters.transaction(Filters.java:42)
	at org.embulk.exec.BulkLoader$4.run(BulkLoader.java:510)
	at org.embulk.spi.FileInputRunner$RunnerControl$1$1.run(FileInputRunner.java:112)
	at org.embulk.standards.CsvParserPlugin.transaction(CsvParserPlugin.java:228)
	at org.embulk.spi.FileInputRunner$RunnerControl$1.run(FileInputRunner.java:107)
	at org.embulk.spi.util.Decoders$RecursiveControl.transaction(Decoders.java:68)
	at org.embulk.spi.util.Decoders$RecursiveControl$1.run(Decoders.java:64)
	at org.embulk.standards.GzipFileDecoderPlugin.transaction(GzipFileDecoderPlugin.java:25)
	at org.embulk.spi.util.Decoders$RecursiveControl.transaction(Decoders.java:60)
	at org.embulk.spi.util.Decoders.transaction(Decoders.java:29)
	at org.embulk.spi.FileInputRunner$RunnerControl.run(FileInputRunner.java:105)
	at org.embulk.input.gcs.GcsFileInputPlugin.resume(GcsFileInputPlugin.java:106)
	at org.embulk.input.gcs.GcsFileInputPlugin.transaction(GcsFileInputPlugin.java:80)
	at org.embulk.spi.FileInputRunner.transaction(FileInputRunner.java:62)
	at org.embulk.exec.BulkLoader.doRun(BulkLoader.java:506)
	... 11 more
Caused by: java.util.concurrent.TimeoutException
	at org.eclipse.jetty.client.util.InputStreamResponseListener.get(InputStreamResponseListener.java:226)
	at org.embulk.util.retryhelper.jetty92.StringJetty92ResponseEntityReader.getResponse(StringJetty92ResponseEntityReader.java:31)
	at org.embulk.util.retryhelper.jetty92.Jetty92RetryHelper$1.call(Jetty92RetryHelper.java:107)
	at org.embulk.spi.util.RetryExecutor.run(RetryExecutor.java:81)
	at org.embulk.spi.util.RetryExecutor.runInterruptible(RetryExecutor.java:62)
	at org.embulk.util.retryhelper.jetty92.Jetty92RetryHelper.requestWithRetry(Jetty92RetryHelper.java:95)
	... 37 more

Error: java.lang.RuntimeException: java.util.concurrent.TimeoutException

[dmikurube]

Hmm, Jetty's HttpClient looks to have a variety of timeouts.

• http://www.eclipse.org/jetty/javadoc/9.2.22.v20170606/org/eclipse/jetty/client/HttpClient.html
  • setAddressResolutionTimeout
  • setConnectTimeout
  • setIdleTimeout
• http://www.eclipse.org/jetty/javadoc/9.2.22.v20170606/org/eclipse/jetty/client/api/Request.html
  • idleTimeout
  • timeout

For this general timeout_millis parameter, Request#timeout looked appropriate to me to specify. I'm not perfectly confident, though.

What do you think?

[sakama]

Hmm, Jetty's HttpClient looks to have a variety of timeouts.

I didn't notice that.

As you mentioned, timeout_millis should be used for Request#timeout.
I updated implementation and added another new option socket_timeout_millis instead. #53

[dmikurube]

Thanks for addressing this. lgtm!