Failure to remove a file using an outbound-gateway

Question

Im trying to use an sftp outbound gateway to delete a specific log file on a remote sftp.

<int-sftp:outbound-gateway id="removeSourceGateway"
                               session-factory="sftpCachingSessionFactory" 
                               reply-channel="outputChannel"
                               request-channel="afterSuccessBackupChannel"
                               requires-reply="false"
                               command="ls"
                               expression="'/export/logs/'"
                               remote-directory="${sftp.remote.dir}">
</int-sftp:outbound-gateway>

If I execute a LS or PUT command in the configuration above, then I get the expected content - see below for an example of the LS message. But whenever I try to run an RM command I get a rather cryptic error message.

GenericMessage [payload=[FileInfo [isDirectory=false, isLink=false, Size=2348, ModifiedTime=Wed Jun 17 15:21:13 CEST 2015, Filename=sdk.20150601003030.log, RemoteDirectory=/export/logs/, Permissions=-rw-rw-rw-]]

To add more mistery to this problem, whenever I connect to the SFTP using WinSCP and using the exact same account, I'll then be pefectly able to delete the remote file!

The error message:

2015-06-17 15:19:56 INFO  jsch:52 - SSH_MSG_NEWKEYS received
2015-06-17 15:19:56 INFO  stdout:71 - 2015-06-17 15:19:56 INFO  jsch:52 - SSH_MSG_SERVICE_REQUEST sent
2015-06-17 15:19:56 INFO  jsch:52 - SSH_MSG_SERVICE_REQUEST sent
2015-06-17 15:19:56 INFO  stdout:71 - 2015-06-17 15:19:56 INFO  jsch:52 - SSH_MSG_SERVICE_ACCEPT received
2015-06-17 15:19:56 INFO  jsch:52 - SSH_MSG_SERVICE_ACCEPT received
2015-06-17 15:19:56 INFO  stdout:71 - 2015-06-17 15:19:56 INFO  jsch:52 - Authentications that can continue: password
2015-06-17 15:19:56 INFO  jsch:52 - Authentications that can continue: password
2015-06-17 15:19:56 INFO  stdout:71 - 2015-06-17 15:19:56 INFO  jsch:52 - Next authentication method: password
2015-06-17 15:19:56 INFO  jsch:52 - Next authentication method: password
2015-06-17 15:19:56 INFO  stdout:71 - 2015-06-17 15:19:56 INFO  jsch:52 - Authentication succeeded (password).
2015-06-17 15:19:56 INFO  jsch:52 - Authentication succeeded (password).
2015-06-17 15:19:56 INFO  stdout:71 - 2015-06-17 15:19:56 DEBUG SimplePool:190 - Obtained new org.springframework.integration.sftp.session.SftpSession@3b63f280.
2015-06-17 15:19:56 DEBUG SimplePool:190 - Obtained new org.springframework.integration.sftp.session.SftpSession@3b63f280.
2015-06-17 15:19:56 INFO  stdout:71 - 2015-06-17 15:19:56 INFO  jsch:52 - Disconnecting from *.*.*.* port 22
2015-06-17 15:19:56 INFO  jsch:52 - Disconnecting from *.*.*.* port 22
2015-06-17 15:19:56 INFO  stdout:71 - 2015-06-17 15:19:56 DEBUG SimplePool:221 - Releasing org.springframework.integration.sftp.session.SftpSession@3b63f280 back to the pool
2015-06-17 15:19:56 DEBUG SimplePool:221 - Releasing org.springframework.integration.sftp.session.SftpSession@3b63f280 back to the pool
2015-06-17 15:19:57 INFO  stdout:71 - 2015-06-17 15:19:57 DEBUG DefaultListableBeanFactory:248 - Returning cached instance of singleton bean 'integrationEvaluationContext'
2015-06-17 15:19:57 DEBUG DefaultListableBeanFactory:248 - Returning cached instance of singleton bean 'integrationEvaluationContext'
2015-06-17 15:19:57 INFO  stdout:71 - 2015-06-17 15:19:57 DEBUG DirectChannel:277 - preSend on channel 'outputChannel', message: ErrorMessage [payload=org.springframework.integration.handler.advice.ExpressionEvaluatingRequestHandlerAdvice$MessageHandlingExpressionEvaluatingAdviceException: Handler Failed; nested exception is org.springframework.messaging.MessagingException: ; nested exception is org.springframework.messaging.MessagingException: Failed to execute on session; nested exception is org.springframework.core.NestedIOException: Failed to remove file: 4: Failure, headers={timestamp=1434547197002, id=18ca7961-f5f0-de0d-03f2-04909dbcdebc}]
2015-06-17 15:19:57 DEBUG DirectChannel:277 - preSend on channel 'outputChannel', message: ErrorMessage [payload=org.springframework.integration.handler.advice.ExpressionEvaluatingRequestHandlerAdvice$MessageHandlingExpressionEvaluatingAdviceException: Handler Failed; nested exception is org.springframework.messaging.MessagingException: ; nested exception is org.springframework.messaging.MessagingException: Failed to execute on session; nested exception is org.springframework.core.NestedIOException: Failed to remove file: 4: Failure, headers={timestamp=1434547197002, id=18ca7961-f5f0-de0d-03f2-04909dbcdebc}]
2015-06-17 15:19:57 INFO  stdout:71 - 2015-06-17 15:19:57 DEBUG CharacterStreamWritingMessageHandler:72 - org.springframework.integration.stream.CharacterStreamWritingMessageHandler#0 received message: ErrorMessage [payload=org.springframework.integration.handler.advice.ExpressionEvaluatingRequestHandlerAdvice$MessageHandlingExpressionEvaluatingAdviceException: Handler Failed; nested exception is org.springframework.messaging.MessagingException: ; nested exception is org.springframework.messaging.MessagingException: Failed to execute on session; nested exception is org.springframework.core.NestedIOException: Failed to remove file: 4: Failure, headers={timestamp=1434547197002, id=18ca7961-f5f0-de0d-03f2-04909dbcdebc}]
2015-06-17 15:19:57 DEBUG CharacterStreamWritingMessageHandler:72 - org.springframework.integration.stream.CharacterStreamWritingMessageHandler#0 received message: ErrorMessage [payload=org.springframework.integration.handler.advice.ExpressionEvaluatingRequestHandlerAdvice$MessageHandlingExpressionEvaluatingAdviceException: Handler Failed; nested exception is org.springframework.messaging.MessagingException: ; nested exception is org.springframework.messaging.MessagingException: Failed to execute on session; nested exception is org.springframework.core.NestedIOException: Failed to remove file: 4: Failure, headers={timestamp=1434547197002, id=18ca7961-f5f0-de0d-03f2-04909dbcdebc}]
2015-06-17 15:19:57 INFO  stdout:71 - org.springframework.integration.handler.advice.ExpressionEvaluatingRequestHandlerAdvice$MessageHandlingExpressionEvaluatingAdviceException: Handler Failed; nested exception is org.springframework.messaging.MessagingException: ; nested exception is org.springframework.messaging.MessagingException: Failed to execute on session; nested exception is org.springframework.core.NestedIOException: Failed to remove file: 4: Failure
2015-06-17 15:19:57 INFO  stdout:71 -   at org.springframework.integration.handler.advice.ExpressionEvaluatingRequestHandlerAdvice.evaluateFailureExpression(ExpressionEvaluatingRequestHandlerAdvice.java:185)
2015-06-17 15:19:57 INFO  stdout:71 -   at org.springframework.integration.handler.advice.ExpressionEvaluatingRequestHandlerAdvice.doInvoke(ExpressionEvaluatingRequestHandlerAdvice.java:143)
2015-06-17 15:19:57 INFO  stdout:71 -   at org.springframework.integration.handler.advice.AbstractRequestHandlerAdvice.invoke(AbstractRequestHandlerAdvice.java:69)
2015-06-17 15:19:57 INFO  stdout:71 -   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
2015-06-17 15:19:57 INFO  stdout:71 -   at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)
2015-06-17 15:19:57 INFO  stdout:71 -   at com.sun.proxy.$Proxy62.handleMessage(Unknown Source)

For completness here is what I am sending to my outbound-gateway:

2015-06-17 15:38:15 INFO  FtpSession:126 - File has been successfully transfered to: /Private/logs/2015-06/sdk.20150601003030.log
2015-06-17 15:38:15 INFO  stdout:71 - 2015-06-17 15:38:15 DEBUG SimplePool:221 - Releasing org.springframework.integration.ftp.session.FtpSession@2718fca1 back to the pool
2015-06-17 15:38:15 DEBUG SimplePool:221 - Releasing org.springframework.integration.ftp.session.FtpSession@2718fca1 back to the pool
2015-06-17 15:38:15 INFO  stdout:71 - 2015-06-17 15:38:15 DEBUG DefaultListableBeanFactory:248 - Returning cached instance of singleton bean 'integrationEvaluationContext'
2015-06-17 15:38:15 DEBUG DefaultListableBeanFactory:248 - Returning cached instance of singleton bean 'integrationEvaluationContext'
2015-06-17 15:38:15 INFO  stdout:71 - 2015-06-17 15:38:15 DEBUG DirectChannel:277 - preSend on channel 'afterSuccessBackupChannel', message: AdviceMessage [payload=/data/logs/live-test/sdk/sdk.20150601003030.log, headers={timestamp=1434548295753, id=17408be9-8acd-0325-b726-e87c81cafcc8}]
2015-06-17 15:38:15 DEBUG DirectChannel:277 - preSend on channel 'afterSuccessBackupChannel', message: AdviceMessage [payload=/data/logs/live-test/sdk/sdk.20150601003030.log, headers={timestamp=1434548295753, id=17408be9-8acd-0325-b726-e87c81cafcc8}]
2015-06-17 15:38:15 INFO  stdout:71 - 2015-06-17 15:38:15 DEBUG SftpOutboundGateway:72 - org.springframework.integration.sftp.gateway.SftpOutboundGateway#0 received message: AdviceMessage [payload=/data/logs/live-test/sdk/sdk.20150601003030.log, headers={timestamp=1434548295753, id=17408be9-8acd-0325-b726-e87c81cafcc8}]
2015-06-17 15:38:15 DEBUG SftpOutboundGateway:72 - org.springframework.integration.sftp.gateway.SftpOutboundGateway#0 received message: AdviceMessage [payload=/data/logs/live-test/sdk/sdk.20150601003030.log, headers={timestamp=1434548295753, id=17408be9-8acd-0325-b726-e87c81cafcc8}]
2015-06-17 15:38:15 INFO  stdout:71 - 2015-06-17 15:38:15 DEBUG DefaultListableBeanFactory:248 - Returning cached instance of singleton bean 'integrationEvaluationContext'
2015-06-17 15:38:15 DEBUG DefaultListableBeanFactory:248 - Returning cached instance of singleton bean 'integrationEvaluationContext'
2015-06-17 15:38:15 INFO  stdout:71 - 2015-06-17 15:38:15 INFO  jsch:52 - Connecting to *.*.*.* port 22

Cheers, Jes

Answer 1

Failed to remove file: 4: Failure

Unfortunately, the exceptions from the com.jcraft.jsch library (used for sftp) are a bit cryptic (4: Failure) in this case...

4 means:

SSH_FX_FAILURE
  is a generic catch-all error message; it should be returned if an
  error occurs for which there is no more specific error code
  defined.

...digging into the jsch code, it appears to me this status was returned by the server. Is there anything in the server logs?

If not, you might have to use wireshark or similar to figure out what the server doesn't like about the rm request.