Troubleshooting Guide : Why does SB2Bi SFTP Server Adapter reports "The message is not extractable" error when Extractability_Count=1

Body

       There are instances where 3rd party SFTP Client having issues while downloading file from SB2Bi SFTP Server due to server returning "Message not extractable" error. So I am putting together some information in this article that might help to troubleshoot this type of failure.

       I would like to start with sequence of key events happen on server end while client downloading a file from SFTP Server i.e., from underlying mailbox. I captured those events in flow-chart below. Solid arrows represent main flow. Dotted arrows show possible failure scenarios.

Successful Download

Here is how typical log looks like (sftpserver.log in DEBUG mode) for a file download. It may vary depending on product FixPack version you use. Let me try to map these logs with events from flow-chart.

#1 and #2 : Basic validation like file existence, user/permission check and extractability check

[2016-08-01 15:51:19.549] DEBUG MailboxSystemProvider.fileExists(S) entered with path[/KKCONS/test.txt], cleaned path to be[/KKCONS/test.txt].
[2016-08-01 15:51:19.555] DEBUG MailboxSystemProvider.fileExists(S) exited with [exists].
[2016-08-01 15:51:19.555] DEBUG MailboxSystemProvider.getFileAttributes(S) entered with path[/KKCONS/test.txt], cleaned path to be[/KKCONS/test.txt].
[2016-08-01 15:51:19.568] DEBUG MessageOperation.MessageOperation(S,UI32,S,S,E,b) - Entering with messagePath[/KKCONS/test.txt], userName[admin].
[2016-08-01 15:51:19.568] DEBUG MessageOperation.MessageOperation(S,UI32,S,S,E,b) - Exiting.
[2016-08-01 15:51:19.568] DEBUG MessageOperation.getSftpFileAttributes(b) Entered with restrictedView[true].
[2016-08-01 15:51:19.568] DEBUG MailboxSystemOperation.isListStagedDocuments() returning [false].

Found 2 messages by name text.txt under KKCONS directory but only one of them eligible for extraction
[2016-08-01 15:51:19.57] DEBUG MessageOperation.findMessage() got back 2 messages.
[2016-08-01 15:51:19.57] DEBUG MessageOperation.findMessage() filtered down to 1 messages.

Reads file attributes to confirm if file is eligible for download/read
[2016-08-01 15:51:19.57] DEBUG MessageOperation.getSftpFileAttributesFor(M) - Entering.
[2016-08-01 15:51:19.57] DEBUG MailboxSystemProvider.getFileAttributes(S) exited with [
Permissions: -rw-------
Size: 17271
GID: 100
UID: 200
AccessedTime: 1470080322
ModifiedTime: 1470080322
File] for [/KKCONS/test.txt].
[2016-08-01 15:51:19.572] DEBUG MailboxSystemProvider.fileExists(S) entered with path[/KKCONS/test.txt], cleaned path to be[/KKCONS/test.txt].
[2016-08-01 15:51:19.572] DEBUG MailboxSystemProvider.fileExists(S) cached value:true is used for /KKCONS/test.txt.
[2016-08-01 15:51:19.573] DEBUG MailboxSystemProvider.getFileAttributes(S) entered with path[/KKCONS/test.txt], cleaned path to be[/KKCONS/test.txt].
[2016-08-01 15:51:19.576] DEBUG MessageOperation.MessageOperation(S,UI32,S,S,E,b) - Entering with messagePath[/KKCONS/test.txt], userName[admin].
[2016-08-01 15:51:19.576] DEBUG MessageOperation.MessageOperation(S,UI32,S,S,E,b) - Exiting.
[2016-08-01 15:51:19.576] DEBUG MessageOperation.getSftpFileAttributes(b) Entered with restrictedView[true].
[2016-08-01 15:51:19.576] DEBUG MailboxSystemOperation.isListStagedDocuments() returning [false].
[2016-08-01 15:51:19.578] DEBUG MessageOperation.findMessage() got back 2 messages.
[2016-08-01 15:51:19.578] DEBUG MessageOperation.findMessage() filtered down to 1 messages.
[2016-08-01 15:51:19.578] DEBUG MessageOperation.getSftpFileAttributesFor(M) - Entering.
[2016-08-01 15:51:19.579] DEBUG MailboxSystemProvider.getFileAttributes(S) exited with [
Permissions: -rw-------
Size: 17271
GID: 100
UID: 200
AccessedTime: 1470080322
ModifiedTime: 1470080322
File] for [/KKCONS/test.txt].
[2016-08-01 15:51:19.58] DEBUG MailboxSystemProvider.fileExists(S) entered with path[/KKCONS/test.txt], cleaned path to be[/KKCONS/test.txt].
[2016-08-01 15:51:19.58] DEBUG MailboxSystemProvider.fileExists(S) cached value:true is used for /KKCONS/test.txt.
[2016-08-01 15:51:19.58] DEBUG MailboxSystemProvider.openFile(S,UI32,SFA) entered.
[2016-08-01 15:51:19.58] DEBUG MailboxSystemProvider.openFile(S,UI32,SFA) lastSlash:7
[2016-08-01 15:51:19.58] DEBUG MailboxSystemProvider.openFile(S,UI32,SFA) dirPath:/KKCONS
[2016-08-01 15:51:19.58] DEBUG NativeFilesystemProviderBase.checkCommandAllowed() There is no command limiting policy defined for this IP/user

#3 File is being opened
[2016-08-01 15:51:19.58] ALL AUDIT: User [admin] is opening file [/KKCONS/test.txt] for transfer.
[2016-08-01 15:51:19.58] DEBUG MessageProvider.open(S,UI32,SFA,S,C,S) - Entering with path[/KKCONS/test.txt].
[2016-08-01 15:51:19.58] DEBUG ProviderBase.userHasRightsAlongPath(S,S,S) called with path [/KKCONS/], user [admin], relRight 1
[2016-08-01 15:51:19.581] DEBUG ProviderBase.userHasRightsAlongPath(S,S,S) doesNotNeedVRPermsToLogin=true
[2016-08-01 15:51:19.581] DEBUG ProviderBase.userHasRightsAlongPath(S,S,S) middlePath=/KKCONS.
[2016-08-01 15:51:19.582] DEBUG ProviderBase.userHasRightsAlongPath(S,S,S) returning true
[2016-08-01 15:51:19.582] DEBUG MessageOperation.MessageOperation(S,UI32,S,S,E,b) - Entering with messagePath[/KKCONS/test.txt], userName[admin].
[2016-08-01 15:51:19.582] DEBUG MessageOperation.MessageOperation(S,UI32,S,S,E,b) - Exiting.
[2016-08-01 15:51:19.583] DEBUG ProviderBase.hasRights(S,S,S) called with path [/KKCONS], user [admin], relRight 4, with fullpath=[/KKCONS] returning true
[2016-08-01 15:51:19.585] DEBUG ProviderBase.hasRights(S,S,S) called with path [/KKCONS], user [admin], relRight 2, with fullpath=[/KKCONS] returning true
[2016-08-01 15:51:19.585] DEBUG MessageOperation.open(NT,i) opening with absPath=[/KKCONS], name=[test.txt], readOnly=[true]
[2016-08-01 15:51:19.587] DEBUG MessageOperation.findMessage() got back 2 messages.
[2016-08-01 15:51:19.587] DEBUG MessageOperation.findMessage() filtered down to 1 messages.
[2016-08-01 15:51:19.587] DEBUG MessageReaderWriterFactory.getMessageReaderWriter(UI32,S,S,S,E,l,M,S,NT,i) entered with mbx[/KKCONS] and msgName[test.txt], flags[FLAGS(Append=[false],Create=[false],Exclusive=[false],Read=[true],Truncate=[false],Write=[false])], msg=[Message: messageId: 1343 mailboxPath: /KKCONS messageName: test.txt documentId: 416194156479680d2node1 extractability: ExtractableCount: count: 1 isRoutingEligible: true].
[2016-08-01 15:51:19.587] DEBUG MessageReader.MessageReader(9) - entered
[2016-08-01 15:51:19.617] DEBUG DocumentOutputStreamWrapper.constructBackingStream(b) exiting with cursor=0

Confirming extractability_count
[2016-08-01 15:51:19.618] DEBUG Utils.extractMessage() - Beginning extraction of Msg Message name [test.txt], Mailbox path [/KKCONS], Extractable count [1].
[2016-08-01 15:51:19.633] DEBUG Utils.extractMessage() - After extractBegin, Extractable count [1].
[2016-08-01 15:51:19.633] DEBUG MessageReaderWriterFactory.getMessageReaderWriter(UI32,S,S,S,E,l,M,S,NT,i) exited.
[2016-08-01 15:51:19.633] DEBUG MessageOperation.open(NT,i) - Exiting.
[2016-08-01 15:51:19.633] DEBUG MessageProvider.open(S,UI32,SFA,S,C,S) checked fullpath=[/KKCONS], mo.cr=true, mo.cw=true
[2016-08-01 15:51:19.633] DEBUG MessageProvider.open(S,UI32,SFA,S,C,S) - Exiting.
[2016-08-01 15:51:19.636] COMMTRACE user=[admin], sessionId=[KK.SFTP.Server_14700802966281003:9988], ip=[host.xyz.com], event=[Opened message /KKCONS/test.txt with flags 1]

#4 File was opened. At this point of time, file's extractability_count is logically reduced by 1. (i.e., 1 became 0)
[2016-08-01 15:51:19.636] DEBUG MailboxSystemProvider.openFile(S,UI32,SFA) exited returning key[[B@955066e4].

#5 Client reading file in chunks through MailboxSystemProvider.readFile API
[2016-08-01 15:51:19.639] DEBUG NativeFilesystemProviderBase.checkCommandAllowed() There is no command limiting policy defined for this IP/user
[2016-08-01 15:51:19.639] DEBUG MailboxSystemProvider.readFile(b[],UI64,b[],i,i) entered.
[2016-08-01 15:51:19.639] DEBUG MessageProvider.read(MH,UI64,b[],i,i) - Entering.
[2016-08-01 15:51:19.639] DEBUG Utils.readBinary(UI64,b[],i,i) - entered
[2016-08-01 15:51:19.639] DEBUG DocumentOutputStreamWrapper.seek(l) pos=0, cursor=0
[2016-08-01 15:51:19.644] DEBUG DocumentOutputStreamWrapper.read(b[],i,i) read 17271
[2016-08-01 15:51:19.644] DEBUG Utils.readBinary(UI64,b[],i,i) - exited
[2016-08-01 15:51:19.644] DEBUG MessageProvider.read(MH,UI64,b[],i,i) - Exiting.
[2016-08-01 15:51:19.645] DEBUG MailboxSystemProvider.readFile(b[],UI64,b[],i,i) exited returning [17271].
[2016-08-01 15:51:19.67] DEBUG NativeFilesystemProviderBase.checkCommandAllowed() There is no command limiting policy defined for this IP/user
[2016-08-01 15:51:19.67] DEBUG MailboxSystemProvider.readFile(b[],UI64,b[],i,i) entered.
[2016-08-01 15:51:19.67] DEBUG MessageProvider.read(MH,UI64,b[],i,i) - Entering.
[2016-08-01 15:51:19.67] DEBUG Utils.readBinary(UI64,b[],i,i) - entered
[2016-08-01 15:51:19.67] DEBUG DocumentOutputStreamWrapper.seek(l) pos=17271, cursor=17271

#6 EOF sent to client
[2016-08-01 15:51:19.67] DEBUG DocumentOutputStreamWrapper.read(b[],i,i) read -1
[2016-08-01 15:51:19.67] DEBUG Utils.readBinary(UI64,b[],i,i) - exited

#7 Server received SSH_FXP_CLOSE from client as response to server's EOF.
[2016-08-01 15:51:19.672] DEBUG NativeFilesystemProviderBase.endSession() called with sessionId=8
[2016-08-01 15:51:19.672] DEBUG MailboxSystemProvider.closeFile(b[]) entered, closing[/KKCONS,/KKCONS/test.txt]. Removed cache for /KKCONS/test.txt
[2016-08-01 15:51:19.672] DEBUG MessageProvider.close(MH,b) - Entered.
[2016-08-01 15:51:19.672] DEBUG MessageOperation.close() - closing.
[2016-08-01 15:51:19.673] DEBUG Utils.closeConnection() - entered
[2016-08-01 15:51:19.673] DEBUG DocumentOutputStreamWrapper.close() with cursor=17271
[2016-08-01 15:51:19.673] DEBUG Utils.closeConnection() - exited

File download was successful. Server decrements message's extractability_count by 1. That means, updated count would be persisted into Database.
[2016-08-01 15:51:19.761] DEBUG MessageReader.closeSucceeded() - committing the extract.
[2016-08-01 15:51:19.761] ALL AUDIT: User [admin] finished reading file [test.txt] for transfer.
[2016-08-01 15:51:19.761] DEBUG MessageProvider.close(MH,b) - Exiting.
[2016-08-01 15:51:19.762] COMMTRACE user=[admin], sessionId=[KK.SFTP.Server_14700802966281003:9988], ip=[host.xyz.com], event=[Closed message /KKCONS/test.txt after reading 17271 and writing 0]
[2016-08-01 15:51:19.762] DEBUG MailboxSystemProvider.closeFile(b[]) remove the handle 8 handlesToOps={}

Failure Scenarios

          Now I will discuss what the log would look like, for failure scenarios, when the SFTP client issues additional commands that the SB2Bi SFTP server doesn't expect, between SSH_FXP_OPEN and SSH_FXP_CLOSE. That may work well when message's extractability_count>1 but doesn't work well when it is just 1. Reason being after file is opened (i.e., post SSH_FXP_OPEN) for download, SB2Bi SFTP Server does consider extractability_count was already (logically) reduced by 1.

         Following are 2 different instances where SB2Bi SFTP Server threw "not extractable" error due to respective clients trying to obtain message attributes after either file was opened or file was downloaded. But since server does extractability check to honor client's getAttributes request and count was already 0, so server fails download with "The message ... not extractable" error.

         I have captured only some key log segments here below.

Failure Scenario#1

#3 and #4 Server received SSH_FXP_OPEN. File is opened for download. logically file's extractability_count=0

[2016-07-01 07:49:39.599] ALL AUDIT: User [user100] is opening file [/Outbox/File2.txt] for transfer.
[2016-07-01 07:49:39.66] DEBUG Utils.extractMessage() - Beginning extraction of Msg Message name [File2.txt], Mailbox path [/user100/Outbox], Extractable count [1].
[2016-07-01 07:49:39.696] DEBUG Utils.extractMessage() - After extractBegin, Extractable count [1].
[2016-07-01 07:49:39.696] DEBUG MessageReaderWriterFactory.getMessageReaderWriter(UI32,S,S,S,E,l,M,S,NT,i) exited.
[2016-07-01 07:49:39.696] DEBUG MessageOperation.open(NT,i) - Exiting.
[2016-07-01 07:49:39.696] DEBUG MessageProvider.open(S,UI32,SFA,S,C,S) checked fullpath=[/user100/Outbox], mo.cr=true, mo.cw=true
[2016-07-01 07:49:39.696] DEBUG MessageProvider.open(S,UI32,SFA,S,C,S) - Exiting.
[2016-07-01 07:49:39.696] COMMTRACE user=[user100], sessionId=[SFTP_Server_Adapter_Node2_146737377675076697:31766264], ip=[myipaddress], event=[Opened message /Outbox/File2.txt with flags 1]
[2016-07-01 07:49:39.696] DEBUG MailboxSystemProvider.openFile(S,UI32,SFA) exited returning key[[B@759c4fae].

#A After file was opened, Client issued command to read attributes
[2016-07-01 07:49:39.732] DEBUG MailboxSystemProvider.fileExists(S) entered with path[/Outbox/File2.txt], cleaned path to be[/Outbox/File2.txt].
[2016-07-01 07:49:39.732] DEBUG MailboxSystemProvider.fileExists(S) cached value:true is used for /Outbox/File2.txt.
[2016-07-01 07:49:39.732] DEBUG MailboxSystemProvider.getFileAttributes(S) entered with path[/Outbox/File2.txt], cleaned path to be[/Outbox/File2.txt].
[2016-07-01 07:49:39.753] DEBUG MessageOperation.MessageOperation(S,UI32,S,S,E,b) - Entering with messagePath[/Outbox/File2.txt], userName[user100].
[2016-07-01 07:49:39.753] DEBUG MessageOperation.MessageOperation(S,UI32,S,S,E,b) - Exiting.
[2016-07-01 07:49:39.753] DEBUG MessageOperation.getSftpFileAttributes(b) Entered with restrictedView[true].
[2016-07-01 07:49:39.753] DEBUG MailboxSystemOperation.isListStagedDocuments() returning [false].

Although there is one file regardless of extractability_count, but message existence (based on extractability_count) got filtered down to 0.
[2016-07-01 07:49:39.765] DEBUG MessageOperation.findMessage() got back 1 messages.
[2016-07-01 07:49:39.765] DEBUG MessageOperation.findMessage() filtered down to 0 messages.
[2016-07-01 07:49:39.765] WARN MessageOperation.findMessage() - The message [/Outbox/File2.txt] is not extractable!.
[2016-07-01 07:49:39.832] DEBUG MailboxSystemProvider.Listener.onChannelClose()
[2016-07-01 07:49:39.832] DEBUG MailboxSystemProvider.closeFilesystem() entered.
[2016-07-01 07:49:39.832] DEBUG MailboxSystemProvider.closeFailedAllOpen() entered.
[2016-07-01 07:49:39.832] DEBUG MessageProvider.closeConnectionLost(MH) - Entered.
[2016-07-01 07:49:39.832] DEBUG MessageOperation.closeConnectionLost() - closing.
[2016-07-01 07:49:39.832] DEBUG MessageReader.closeConnectionLost() - entered
[2016-07-01 07:49:39.832] DEBUG Utils.closeConnection() - entered
[2016-07-01 07:49:39.832] DEBUG DocumentOutputStreamWrapper.close() with cursor=0
[2016-07-01 07:49:39.832] DEBUG Utils.closeConnection() - exited

#B Since download failed, count would be set back to 1.
[2016-07-01 07:49:39.857] DEBUG MessageReader.closeFailed() - aborting the extract.
[2016-07-01 07:49:39.857] ALL AUDIT: User [user100] finished reading file [File2.txt] for transfer.
[2016-07-01 07:49:39.972] DEBUG MessageProvider.closeConnectionLost(MH) - Exiting.
 

Failure Scenario#2

#3 and #4 File is opened after SSH_FXP_OPEN. extractability_count had been reduced to 0.

[2016-06-27 11:07:05.096] DEBUG Utils.extractMessage() - Beginning extraction of Msg Message name [Test.zip], Mailbox path [/sftp_user/Inbox], Extractable count [1].
[2016-06-27 11:07:05.112] DEBUG Utils.extractMessage() - After extractBegin, Extractable count [1].
[2016-06-27 11:07:05.112] DEBUG MessageReaderWriterFactory.getMessageReaderWriter(UI32,S,S,S,E,l,M,S,NT,i) exited.
[2016-06-27 11:07:05.112] DEBUG MessageOperation.open(NT,i) - Exiting.
[2016-06-27 11:07:05.112] DEBUG MessageProvider.open(S,UI32,SFA,S,C,S) checked fullpath=[/sftp_user/Inbox], mo.cr=true, mo.cw=true
[2016-06-27 11:07:05.112] DEBUG MessageProvider.open(S,UI32,SFA,S,C,S) - Exiting.
[2016-06-27 11:07:05.128] COMMTRACE user=[sftp_user], sessionId=[MY_SFTP_1_14670400249727723:157217062], ip=[1.1.1.1], event=[Opened message /Inbox/Test.zip with flags 1]
[2016-06-27 11:07:05.128] DEBUG MailboxSystemProvider.openFile(S,UI32,SFA) exited returning key[[B@29476818].

#5 File is being read in chunks
[2016-06-27 11:07:05.128] DEBUG NativeFilesystemProviderBase.checkCommandAllowed() There is no command limiting policy defined for this IP/user
[2016-06-27 11:07:05.128] DEBUG MailboxSystemProvider.readFile(b[],UI64,b[],i,i) entered.
[2016-06-27 11:07:05.128] DEBUG MessageProvider.read(MH,UI64,b[],i,i) - Entering.
[2016-06-27 11:07:05.128] DEBUG Utils.readBinary(UI64,b[],i,i) - entered
[2016-06-27 11:07:05.128] DEBUG DocumentOutputStreamWrapper.seek(l) pos=0, cursor=0
[2016-06-27 11:07:05.143] DEBUG DocumentOutputStreamWrapper.read(b[],i,i) read 134
[2016-06-27 11:07:05.143] DEBUG Utils.readBinary(UI64,b[],i,i) - exited
[2016-06-27 11:07:05.143] DEBUG MessageProvider.read(MH,UI64,b[],i,i) - Exiting.
[2016-06-27 11:07:05.143] DEBUG MailboxSystemProvider.readFile(b[],UI64,b[],i,i) exited returning [134].
[2016-06-27 11:07:05.143] DEBUG NativeFilesystemProviderBase.checkCommandAllowed() There is no command limiting policy defined for this IP/user
[2016-06-27 11:07:05.143] DEBUG MailboxSystemProvider.readFile(b[],UI64,b[],i,i) entered.
[2016-06-27 11:07:05.143] DEBUG MessageProvider.read(MH,UI64,b[],i,i) - Entering.
[2016-06-27 11:07:05.143] DEBUG Utils.readBinary(UI64,b[],i,i) - entered
[2016-06-27 11:07:05.143] DEBUG DocumentOutputStreamWrapper.seek(l) pos=134, cursor=134
[2016-06-27 11:07:05.143] DEBUG DocumentOutputStreamWrapper.read(b[],i,i) read -1
[2016-06-27 11:07:05.143] DEBUG Utils.readBinary(UI64,b[],i,i) - exited
[2016-06-27 11:07:05.143] DEBUG NativeFilesystemProviderBase.checkCommandAllowed() There is no command limiting policy defined for this IP/user
[2016-06-27 11:07:05.143] DEBUG MailboxSystemProvider.readFile(b[],UI64,b[],i,i) entered.
[2016-06-27 11:07:05.143] DEBUG MessageProvider.read(MH,UI64,b[],i,i) - Entering.
[2016-06-27 11:07:05.143] DEBUG Utils.readBinary(UI64,b[],i,i) - entered
[2016-06-27 11:07:05.143] DEBUG DocumentOutputStreamWrapper.seek(l) pos=32755, cursor=134
[2016-06-27 11:07:05.143] DEBUG DocumentOutputStreamWrapper.seek(l) skipped 0

#6 SFTP Server sent EOF
[2016-06-27 11:07:05.143] DEBUG DocumentOutputStreamWrapper.read(b[],i,i) read -1
[2016-06-27 11:07:05.143] DEBUG Utils.readBinary(UI64,b[],i,i) - exited
[2016-06-27 11:07:05.143] DEBUG NativeFilesystemProviderBase.endSession() called with sessionId=0

#7 Server received SSH_FXP_CLOSE from Client.
[2016-06-27 11:07:05.143] DEBUG MailboxSystemProvider.closeFile(b[]) entered, closing[/Inbox,/Inbox/Test.zip]. Removed cache for /Inbox/Test.zip
[2016-06-27 11:07:05.143] DEBUG MessageProvider.close(MH,b) - Entered.
[2016-06-27 11:07:05.143] DEBUG MessageOperation.close() - closing.
[2016-06-27 11:07:05.143] DEBUG Utils.closeConnection() - entered
[2016-06-27 11:07:05.143] DEBUG DocumentOutputStreamWrapper.close() with cursor=134
[2016-06-27 11:07:05.143] DEBUG Utils.closeConnection() - exited

Extractability count is being persisted into DB. i.e., 0
[2016-06-27 11:07:05.159] DEBUG MessageReader.closeSucceeded() - committing the extract.
[2016-06-27 11:07:05.159] ALL AUDIT: User [sftp_user] finished reading file [Test.zip] for transfer.
[2016-06-27 11:07:05.159] DEBUG MessageProvider.close(MH,b) - Exiting.
[2016-06-27 11:07:05.159] COMMTRACE user=[sftp_user], sessionId=[MY_SFTP_1_14670400249727723:157217062], ip=[1.1.1.1], event=[Closed message /Inbox/Test.zip after reading 134 and writing 0]
[2016-06-27 11:07:05.159] DEBUG MailboxSystemProvider.closeFile(b[]) remove the handle 0 handlesToOps={}

Client is reading file attributes on file that is no longer eligible for extraction. In this case, file was already downloaded by client but subsequent command (getAttributes) was what failed.

[2016-06-27 11:07:05.174] DEBUG MailboxSystemProvider.fileExists(S) entered with path[/Inbox/Test.zip], cleaned path to be[/Inbox/Test.zip].
[2016-06-27 11:07:05.174] DEBUG MailboxSystemProvider.fileExists(S) exited with [exists].
[2016-06-27 11:07:05.174] DEBUG MailboxSystemProvider.getFileAttributes(S) entered with path[/Inbox/Test.zip], cleaned path to be[/Inbox/Test.zip].
[2016-06-27 11:07:05.19] DEBUG MessageOperation.MessageOperation(S,UI32,S,S,E,b) - Entering with messagePath[/Inbox/Test.zip], userName[sftp_user].
[2016-06-27 11:07:05.19] DEBUG MessageOperation.MessageOperation(S,UI32,S,S,E,b) - Exiting.
[2016-06-27 11:07:05.19] DEBUG MessageOperation.getSftpFileAttributes(b) Entered with restrictedView[true].
[2016-06-27 11:07:05.19] DEBUG MailboxSystemOperation.isListStagedDocuments() returning [false].
[2016-06-27 11:07:05.19] DEBUG MessageOperation.findMessage() got back 1 messages.
[2016-06-27 11:07:05.19] DEBUG MessageOperation.findMessage() filtered down to 0 messages.
[2016-06-27 11:07:05.19] WARN MessageOperation.findMessage() - The message [/Inbox/Test.zip] is not extractable!.
[2016-06-27 11:07:05.221] DEBUG MailboxSystemProvider.Listener.onChannelClose()
[2016-06-27 11:07:05.221] DEBUG MailboxSystemProvider.closeFilesystem() entered.
[2016-06-27 11:07:05.221] DEBUG MailboxSystemProvider.closeFailedAllOpen() entered.
[2016-06-27 11:07:05.221] COMMTRACE user=[sftp_user], sessionId=[MY_SFTP_1_14670400249727723:157217062], ip=[1.1.1.1], event=[Disconnected]
[2016-06-27 11:07:05.221] DEBUG MailboxSystemProvider.closeFilesystem() entered.
[2016-06-27 11:07:05.237] DEBUG SSHSCIAuthenticationProvider.logoffUser(b[],S,SA) entered with user[sftp_user].
[2016-06-27 11:07:05.237] ALL AUDIT: User [sftp_user] logged off.

Both these failure scenarios indicate there is no faulty behavior with SB2Bi SFTP Server Adapter. If clients act like ones caused these failures, SFTP Server can get around only by increasing extractability_count for those messages from 1 to 2. Permanent fix might be required to SFTP Client in use.

Thanks for reading through this article.
If you have any questions/comments, please feel free to post them in comments section below.