Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Give up processing and throw ConfigException when "Auth fail" appears at the first time #33

Merged
merged 4 commits into from
Oct 5, 2018

Conversation

sakama
Copy link
Contributor

@sakama sakama commented Oct 4, 2018

Follow up for #29

I had improved retry logic while getting file list before #29
Plugin will throw ConfigException when "Auth fail" happens after several retries.
I thought this plugin was a bit unstable, so it's better to retry even if exception is "Auth fail".

However, I found that some external services detect such retry as a invalid access from bot.
They add our source IP to IP black list.

I think it's time to give up to retry "Auth fail" when it first appears.

Stacktrace

2018-09-09 04:29:52.995 +0000 [INFO] (0001:transaction): Connecting to sftp://sftp_user:***@sftp.example.com:22/
2018-09-09 04:29:52.997 +0000 [INFO] (0001:transaction): Getting to download file list
2018-09-09 04:29:53.064 +0000 [INFO] (0001:transaction): Connecting to sftp://sftp_user:***@sftp.example.com:22/
2018-09-09 04:29:53.130 +0000 [WARN] (0001:transaction): SFTP GET request failed. Retrying 1/5 after 0 seconds. Message: Could not connect to SFTP server at "sftp://sftp_user:***@sftp.example.com/".
2018-09-09 04:29:53.630 +0000 [INFO] (0001:transaction): Getting to download file list
2018-09-09 04:29:53.639 +0000 [INFO] (0001:transaction): Connecting to sftp://sftp_user:***@sftp.example.com:22/
2018-09-09 04:29:53.677 +0000 [WARN] (0001:transaction): SFTP GET request failed. Retrying 2/5 after 1 seconds. Message: Could not connect to SFTP server at "sftp://sftp_user:***@sftp.example.com/".
2018-09-09 04:29:54.678 +0000 [INFO] (0001:transaction): Getting to download file list
2018-09-09 04:29:54.687 +0000 [INFO] (0001:transaction): Connecting to sftp://sftp_user:***@sftp.example.com:22/
2018-09-09 04:29:54.972 +0000 [WARN] (0001:transaction): SFTP GET request failed. Retrying 3/5 after 2 seconds. Message: Could not connect to SFTP server at "sftp://sftp_user:***@sftp.example.com/".
org.apache.commons.vfs2.FileSystemException: Could not connect to SFTP server at "sftp://sftp_user:***@sftp.example.com/".
	at org.apache.commons.vfs2.provider.sftp.SftpFileProvider.doCreateFileSystem(SftpFileProvider.java:86) ~[na:na]
	at org.apache.commons.vfs2.provider.AbstractOriginatingFileProvider.getFileSystem(AbstractOriginatingFileProvider.java:92) ~[na:na]
	at org.apache.commons.vfs2.provider.AbstractOriginatingFileProvider.findFile(AbstractOriginatingFileProvider.java:71) ~[na:na]
	at org.apache.commons.vfs2.provider.AbstractOriginatingFileProvider.findFile(AbstractOriginatingFileProvider.java:55) ~[na:na]
	at org.apache.commons.vfs2.impl.DefaultFileSystemManager.resolveFile(DefaultFileSystemManager.java:711) ~[na:na]
	at org.apache.commons.vfs2.impl.DefaultFileSystemManager.resolveFile(DefaultFileSystemManager.java:648) ~[na:na]
	at org.embulk.input.sftp.SftpFileInput$1.call(SftpFileInput.java:217) ~[na:na]
	at org.embulk.input.sftp.SftpFileInput$1.call(SftpFileInput.java:205) ~[na:na]
	at org.embulk.spi.util.RetryExecutor.run(RetryExecutor.java:100) [embulk-core-0.8.36.jar:na]
	at org.embulk.spi.util.RetryExecutor.runInterruptible(RetryExecutor.java:77) [embulk-core-0.8.36.jar:na]
	at org.embulk.input.sftp.SftpFileInput.listFilesByPrefix(SftpFileInput.java:205) [embulk-input-sftp-0.2.11.jar:na]
	at org.embulk.input.sftp.SftpFileInputPlugin.transaction(SftpFileInputPlugin.java:23) [embulk-input-sftp-0.2.11.jar:na]
	at org.embulk.spi.FileInputRunner.transaction(FileInputRunner.java:67) [embulk-core-0.8.36.jar:na]
	at org.embulk.exec.BulkLoader.doRun(BulkLoader.java:544) [embulk-core-0.8.36.jar:na]
	at org.embulk.exec.BulkLoader.access$000(BulkLoader.java:35) [embulk-core-0.8.36.jar:na]
	at org.embulk.exec.BulkLoader$1.run(BulkLoader.java:391) [embulk-core-0.8.36.jar:na]
	at org.embulk.exec.BulkLoader$1.run(BulkLoader.java:387) [embulk-core-0.8.36.jar:na]
	at org.embulk.spi.Exec.doWith(Exec.java:25) [embulk-core-0.8.36.jar:na]
	at org.embulk.exec.BulkLoader.run(BulkLoader.java:387) [embulk-core-0.8.36.jar:na]
    ...
Caused by: org.apache.commons.vfs2.FileSystemException: Could not connect to SFTP server at "sftp.example.com".
	at org.apache.commons.vfs2.provider.sftp.SftpClientFactory.createConnection(SftpClientFactory.java:147) ~[na:na]
	at org.apache.commons.vfs2.provider.sftp.SftpFileProvider.doCreateFileSystem(SftpFileProvider.java:79) ~[na:na]
	... 28 common frames omitted
Caused by: com.jcraft.jsch.JSchException: Auth fail
	at com.jcraft.jsch.Session.connect(Session.java:519) ~[jsch-0.1.42.jar:na]
	at com.jcraft.jsch.Session.connect(Session.java:183) ~[jsch-0.1.42.jar:na]
	at org.apache.commons.vfs2.provider.sftp.SftpClientFactory.createConnection(SftpClientFactory.java:145) ~[na:na]
	... 29 common frames omitted
2018-09-09 04:29:56.973 +0000 [INFO] (0001:transaction): Getting to download file list
2018-09-09 04:29:56.981 +0000 [INFO] (0001:transaction): Connecting to sftp://sftp_user:***@sftp.example.com:22/
2018-09-09 04:29:57.016 +0000 [WARN] (0001:transaction): SFTP GET request failed. Retrying 4/5 after 4 seconds. Message: Could not connect to SFTP server at "sftp://sftp_user:***@sftp.example.com/".
2018-09-09 04:30:01.016 +0000 [INFO] (0001:transaction): Getting to download file list
2018-09-09 04:30:01.023 +0000 [INFO] (0001:transaction): Connecting to sftp://sftp_user:***@sftp.example.com:22/
2018-09-09 04:30:01.058 +0000 [WARN] (0001:transaction): SFTP GET request failed. Retrying 5/5 after 8 seconds. Message: Could not connect to SFTP server at "sftp://sftp_user:***@sftp.example.com/".
2018-09-09 04:30:09.059 +0000 [INFO] (0001:transaction): Getting to download file list
2018-09-09 04:30:09.070 +0000 [INFO] (0001:transaction): Connecting to sftp://sftp_user:***@sftp.example.com:22/
2018-09-09 04:30:09.326 +0000 [WARN] (main): org.apache.commons.vfs2.FileSystemException: Could not connect to SFTP server at "sftp://sftp_user:***@sftp.example.com/".
org.embulk.exec.PartialExecutionException: org.embulk.config.ConfigException: org.apache.commons.vfs2.FileSystemException: Could not connect to SFTP server at "sftp://sftp_user:***@sftp.example.com/".
	at org.embulk.exec.BulkLoader$LoaderState.buildPartialExecuteException(BulkLoader.java:375) ~[embulk-core-0.8.36.jar:na]
	at org.embulk.exec.BulkLoader.doRun(BulkLoader.java:607) ~[embulk-core-0.8.36.jar:na]
	at org.embulk.exec.BulkLoader.access$000(BulkLoader.java:35) ~[embulk-core-0.8.36.jar:na]
	at org.embulk.exec.BulkLoader$1.run(BulkLoader.java:391) ~[embulk-core-0.8.36.jar:na]
	at org.embulk.exec.BulkLoader$1.run(BulkLoader.java:387) ~[embulk-core-0.8.36.jar:na]
	at org.embulk.spi.Exec.doWith(Exec.java:25) ~[embulk-core-0.8.36.jar:na]
	at org.embulk.exec.BulkLoader.run(BulkLoader.java:387) ~[embulk-core-0.8.36.jar:na]
    ...
Caused by: org.embulk.config.ConfigException: org.apache.commons.vfs2.FileSystemException: Could not connect to SFTP server at "sftp://sftp_user:***@sftp.example.com/".
	at org.embulk.input.sftp.SftpFileInput$1.onGiveup(SftpFileInput.java:296) ~[na:na]
	at org.embulk.spi.util.RetryExecutor.run(RetryExecutor.java:106) ~[embulk-core-0.8.36.jar:na]
	at org.embulk.spi.util.RetryExecutor.runInterruptible(RetryExecutor.java:77) ~[embulk-core-0.8.36.jar:na]
	at org.embulk.input.sftp.SftpFileInput.listFilesByPrefix(SftpFileInput.java:205) ~[na:na]
	at org.embulk.input.sftp.SftpFileInputPlugin.transaction(SftpFileInputPlugin.java:23) ~[na:na]
	at org.embulk.spi.FileInputRunner.transaction(FileInputRunner.java:67) ~[embulk-core-0.8.36.jar:na]
	at org.embulk.exec.BulkLoader.doRun(BulkLoader.java:544) ~[embulk-core-0.8.36.jar:na]
	... 15 common frames omitted
Caused by: org.apache.commons.vfs2.FileSystemException: Could not connect to SFTP server at "sftp://sftp_user:***@sftp.example.com/".
	at org.apache.commons.vfs2.provider.sftp.SftpFileProvider.doCreateFileSystem(SftpFileProvider.java:86) ~[na:na]
	at org.apache.commons.vfs2.provider.AbstractOriginatingFileProvider.getFileSystem(AbstractOriginatingFileProvider.java:92) ~[na:na]
	at org.apache.commons.vfs2.provider.AbstractOriginatingFileProvider.findFile(AbstractOriginatingFileProvider.java:71) ~[na:na]
	at org.apache.commons.vfs2.provider.AbstractOriginatingFileProvider.findFile(AbstractOriginatingFileProvider.java:55) ~[na:na]
	at org.apache.commons.vfs2.impl.DefaultFileSystemManager.resolveFile(DefaultFileSystemManager.java:711) ~[na:na]
	at org.apache.commons.vfs2.impl.DefaultFileSystemManager.resolveFile(DefaultFileSystemManager.java:648) ~[na:na]
	at org.embulk.input.sftp.SftpFileInput$1.call(SftpFileInput.java:217) ~[na:na]
	at org.embulk.input.sftp.SftpFileInput$1.call(SftpFileInput.java:205) ~[na:na]
	at org.embulk.spi.util.RetryExecutor.run(RetryExecutor.java:100) ~[embulk-core-0.8.36.jar:na]
	... 20 common frames omitted
Caused by: org.apache.commons.vfs2.FileSystemException: Could not connect to SFTP server at "sftp.example.com".
	at org.apache.commons.vfs2.provider.sftp.SftpClientFactory.createConnection(SftpClientFactory.java:147) ~[na:na]
	at org.apache.commons.vfs2.provider.sftp.SftpFileProvider.doCreateFileSystem(SftpFileProvider.java:79) ~[na:na]
	... 28 common frames omitted
Caused by: com.jcraft.jsch.JSchException: Auth fail
	at com.jcraft.jsch.Session.connect(Session.java:519) ~[jsch-0.1.42.jar:na]
	at com.jcraft.jsch.Session.connect(Session.java:183) ~[jsch-0.1.42.jar:na]
	at org.apache.commons.vfs2.provider.sftp.SftpClientFactory.createConnection(SftpClientFactory.java:145) ~[na:na]
	... 29 common frames omitted
2018-09-09 04:30:09.369 +0000 [INFO] (pool-3-thread-1): Saving all buffers
2018-09-09 04:30:09.369 +0000 [INFO] (pool-3-thread-1): Closing buffers

@sakama sakama requested a review from tvhung83 October 4, 2018 06:08
@@ -264,6 +264,12 @@ else if (files.isFile()) {
@Override
public boolean isRetryableException(Exception exception)
{
if (exception.getCause() != null && exception.getCause().getCause() != null) {
Throwable cause = exception.getCause().getCause();
if (cause.getMessage().contains("Auth fail")) {
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

minor: this could have NPE.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It'd be nice to have a small test to make sure no retry for 'Auth fail' :)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Added a test to make sure ConfigException is thrown.
To check no retry might be a bit difficult.

@@ -266,7 +266,7 @@ public boolean isRetryableException(Exception exception)
{
if (exception.getCause() != null && exception.getCause().getCause() != null) {
Throwable cause = exception.getCause().getCause();
if (cause.getMessage().contains("Auth fail")) {
if (!cause.getMessage().isEmpty() && cause.getMessage().contains("Auth fail")) {
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sorry for confusion 🙇
What I mean is some exceptions won't have message, for example: java.util.concurrent.TimeoutException. So this line still could raise NPE.

Copy link

@tvhung83 tvhung83 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM 👍 (sorry for the back and forth)

@sakama sakama merged commit c3ed1c2 into master Oct 5, 2018
@sakama sakama deleted the dont-retry-auth-fail branch October 5, 2018 05:04
@sakama
Copy link
Contributor Author

sakama commented Oct 5, 2018

Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

Successfully merging this pull request may close these issues.

2 participants