smbj icon indicating copy to clipboard operation
smbj copied to clipboard

[Question] DeadLetter, Signature

Open tomvtomv opened this issue 3 years ago • 4 comments
trafficstars

Hello, i'm facing a strange problem regarding signature handling, deleted session and future timeouts. I've allready been digging through the lib for quite a while and simply don't get the solution on how to handle this. Starting point of the journey is this:

2022-02-01 07:32:23.497 ERROR 1 --- [6000p081.sbk.de] c.h.s.c.PacketSignatory : Signatures for packet SMB2_CREATE with message id << 1588 >> do not match (received: [21, 28, 110, 77, -111, 89, -106, -55, -111, -100, 73, 110, 37, 60, 17, -58], calculated: [-12, -52, -61, -96, 55, 103, -65, 42, 109, -71, -107, -42, -69, 126, 86, 94])
2022-02-01 07:32:23.497 ERROR 1 --- [6000p081.sbk.de] c.h.s.c.PacketSignatory                  : Packet SMB2_CREATE with message id << 1588 >> has header: dialect=null, creditCharge=1, creditRequest=0, creditResponse=1, message=SMB2_CREATE, messageId=1588, asyncId=0, sessionId=1076360310983490645, treeId=1, status=0xc0000203, flags=9, nextCommandOffset=0
2022-02-01 07:32:23.497  WARN 1 --- [6000p081.sbk.de] p.SMB2SignatureVerificationPacketHandler : Invalid packet signature for packet SMB2_CREATE with message id << 1588 >>
2022-02-01 07:32:23.497  WARN 1 --- [6000p081.sbk.de] c.h.s.c.p.DeadLetterPacketHandler        : Packet << com.hierynomus.mssmb2.DeadLetterPacketData@5f5387fb >> ended up in dead letters

The statuscode indicates, that the session has been deleted serverside.

After checking the code, the handler chain in Connection-class contains SMB2SignatureVerificationPacketHandler, which has

if (signatory.verify(packetData, session.getSigningKey(packetData.getHeader(), false))) {
      logger.debug("Signature for packet {} verified.", packetData);
      next.handle(packetData);
      return;
} else {
      logger.warn("Invalid packet signature for packet {}", packetData);
      next.handle(new DeadLetterPacketData(packetData.getHeader()));
      return;
}

so finally i'm ending in the DeadLetterPacketHandler.

The real problem is, that this information is not catcheable. At the actial point of interaction with the lib, i'm just getting a Timeout when using the DiskShare Api:

com.hierynomus.smbj.common.SMBRuntimeException: com.hierynomus.protocol.transport.TransportException: java.util.concurrent.ExecutionException: com.hierynomus.smbj.common.SMBRuntimeException: java.util.concurrent.TimeoutException: Timeout expired

  at com.hierynomus.smbj.share.Share.receive(Share.java:390) ~[smbj-0.11.3.jar:?]
  at com.hierynomus.smbj.share.Share.receive(Share.java:372) ~[smbj-0.11.3.jar:?]
  at com.hierynomus.smbj.share.Share.sendReceive(Share.java:355) ~[smbj-0.11.3.jar:?]
  at com.hierynomus.smbj.share.Share.createFile(Share.java:156) ~[smbj-0.11.3.jar:?]
  at com.hierynomus.smbj.share.DiskShare.createFileAndResolve(DiskShare.java:75) ~[smbj-0.11.3.jar:?]
  at com.hierynomus.smbj.share.DiskShare.access$100(DiskShare.java:55) ~[smbj-0.11.3.jar:?]
  at com.hierynomus.smbj.share.DiskShare$2.apply(DiskShare.java:109) ~[smbj-0.11.3.jar:?]
  at com.hierynomus.smbj.share.DiskShare$2.apply(DiskShare.java:105) ~[smbj-0.11.3.jar:?]
  at com.hierynomus.smbj.paths.PathResolver$1.resolve(PathResolver.java:32) ~[smbj-0.11.3.jar:?]
  at com.hierynomus.smbj.paths.SymlinkPathResolver.resolve(SymlinkPathResolver.java:62) ~[smbj-0.11.3.jar:?]
  at com.hierynomus.smbj.share.DiskShare.resolveAndCreateFile(DiskShare.java:105) ~[smbj-0.11.3.jar:?]
  at com.hierynomus.smbj.share.DiskShare.open(DiskShare.java:65) ~[smbj-0.11.3.jar:?]
  at com.hierynomus.smbj.share.DiskShare.exists(DiskShare.java:214) ~[smbj-0.11.3.jar:?]
  at com.hierynomus.smbj.share.DiskShare.folderExists(DiskShare.java:210) ~[smbj-0.11.3.jar:?]

So my question here is: Any hints what i'm missing or how to deal with this, despite just opening a new session on demand ? Is there a place for injecting a handler or something ?

Thank you in advance

tomvtomv avatar Feb 10 '22 13:02 tomvtomv

[AddOn] I have some additional logs, regarding the signature error:

2022-02-14 06:35:55.479 DEBUG 1 --- [criptionManager] c.h.s.s.Session                          : Returning cached Share DiskShare[\\XXX] for DDMPPL
2022-02-14 06:35:55.479 DEBUG 1 --- [criptionManager] c.h.s.c.Connection                       : Granted 1 (out of 58) credits to Signed(SMB2_CREATE with message id << 1527 >>)
2022-02-14 06:35:55.479 DEBUG 1 --- [criptionManager] c.h.s.t.t.d.DirectTcpTransport           : Writing packet Signed(SMB2_CREATE with message id << 1527 >>)
2022-02-14 06:35:55.480 DEBUG 1 --- [6000p081.sbk.de] c.h.s.t.t.d.DirectTcpPacketReader        : Received packet SMB2_CREATE with message id << 1527 >>
2022-02-14 06:35:55.480 ERROR 1 --- [6000p081.sbk.de] c.h.s.c.PacketSignatory                  : Signatures for packet SMB2_CREATE with message id << 1527 >> do not match (received: [69, 69, -91, 63, 42, -68, -109, 105, 117, -34, -66, -13, 93, 91, 74, 82], calculated: [-42, -79, 57, 13, 122, -8, 112, 23, -27, 95, -40, -49, -89, -1, -18, 107])
2022-02-14 06:35:55.480 ERROR 1 --- [6000p081.sbk.de] c.h.s.c.PacketSignatory                  : Packet SMB2_CREATE with message id << 1527 >> has header: dialect=null, creditCharge=1, creditRequest=0, creditResponse=1, message=SMB2_CREATE, messageId=1527, asyncId=0, sessionId=1076360310987361635, treeId=1, status=0xc0000203, flags=9, nextCommandOffset=0
2022-02-14 06:35:55.480  WARN 1 --- [6000p081.sbk.de] p.SMB2SignatureVerificationPacketHandler : Invalid packet signature for packet SMB2_CREATE with message id << 1527 >>
2022-02-14 06:35:55.480  WARN 1 --- [6000p081.sbk.de] c.h.s.c.p.DeadLetterPacketHandler        : Packet << com.hierynomus.mssmb2.DeadLetterPacketData@2287dbf5 >> ended up in dead letters
2022-02-14 06:36:00.645 DEBUG 1 --- [   scheduling-1] c.h.s.c.Connection                       : Granted 1 (out of 57) credits to Signed(SMB2_ECHO with message id << 1528 >>)
2022-02-14 06:36:00.645 DEBUG 1 --- [   scheduling-1] c.h.s.t.t.d.DirectTcpTransport           : Writing packet Signed(SMB2_ECHO with message id << 1528 >>)
2022-02-14 06:36:00.645 DEBUG 1 --- [   scheduling-1] d.s.w.c.f.s.SmbConnector                 : SessionId refreshed 1076360310987361635
2022-02-14 06:36:00.645 DEBUG 1 --- [6000p081.sbk.de] c.h.s.t.t.d.DirectTcpPacketReader        : Received packet SMB2_ECHO with message id << 1528 >>
2022-02-14 06:36:00.645 DEBUG 1 --- [6000p081.sbk.de] .h.s.c.p.SMB2CreditGrantingPacketHandler : Server granted us 1 credits for SMB2_ECHO with message id << 1528 >>, now available: 57 credits

Background info: I have a scheduled Job, which sends an Smb2Echo to the sever every 60 seconds, which actually should keep the session alive. Hence, i don't get, why the statuscode 0xc0000203 appears in the first place, since the echo-messages are returned correctly.

Btw, i'm using the latest version.

Still hoping for some advice.

tomvtomv avatar Feb 14 '22 06:02 tomvtomv

Which protocol version is negotiated?

hierynomus avatar Feb 14 '22 09:02 hierynomus

The latest one 3_1_1

tomvtomv avatar Feb 14 '22 12:02 tomvtomv

@tomvtomv Which version of SMBJ is running? Did you try the latest 0.11.5 already?

hierynomus avatar Mar 10 '22 08:03 hierynomus