[SNMP4J] Problems in DefaultTcpTransportMapping when receiving fragmented header

Tue Jan 26 13:29:19 CET 2016

Hi Frank,

The latest 2.4.2-SNAPSHOT is working great!

> You never stop learning ;-)

It's interesting to see that snmp4j enables other implementations not in the initial scope, like this NTCIP-PMPP.
We had an hard time to put it all together, using something new like snmp4j which we had no experience, but it's nice to see the fruits of hard work.

> When I wrote the initial version I could not image that the first 6 bytes of the TCP message could get fragmented (because the size of the message should have been determined in one go)!

Here you can find a sample log that illustrates the fragmented header scenario - using the test posted in one previous message and the latest snmp4j 2.4.2-SNAPSHOT.

2016-01-26 04:23:15,522-0700 [DEBUG|Snmp$PendingRequest] (Snmp.java:1720) Running pending sync request with handle PduHandle[917471882] and retry count left 2
2016-01-26 04:23:15,553-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:703) Looking up connection for destination '172.26.50.120/4001' returned: null
2016-01-26 04:23:15,569-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:705) {}
2016-01-26 04:23:15,569-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:715) Socket for address '172.26.50.120/4001' is closed, opening it...
2016-01-26 04:23:15,569-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:749) Trying to connect to 172.26.50.120/4001
2016-01-26 04:23:15,600-0700 [DEBUG|DefaultTcpTransportMapping$SocketEntry] (DefaultTcpTransportMapping.java:431) Adding operation 8 for: SocketEntry[peerAddress=172.26.50.120/4001,socket=Socket[unconnected],lastUse=Thu Jan 15 16:23:38 MST 1970,readBufferPosition=-1]
2016-01-26 04:23:15,615-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:831) Key is connectable
2016-01-26 04:23:15,615-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:912) Connected to 172.26.50.120/4001
2016-01-26 04:23:15,615-0700 [DEBUG|DefaultTcpTransportMapping$SocketEntry] (DefaultTcpTransportMapping.java:431) Adding operation 4 for: SocketEntry[peerAddress=172.26.50.120/4001,socket=Socket[addr=/172.26.50.120,port=4001,localport=10826],lastUse=Thu Jan 15 16:23:38 MST 1970,readBufferPosition=-1]
2016-01-26 04:23:15,615-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:926) Fire connected event for 172.26.50.120/4001
2016-01-26 04:23:15,615-0700 [DEBUG|TcpTransportMapping] (TcpTransportMapping.java:133) Firing transport state event: org.snmp4j.transport.TransportStateEvent[source=org.snmp4j.transport.DefaultTcpTransportMapping at 180b4f9,peerAddress=172.26.50.120/4001,newState=1,cancelled=false,causingException=null]
2016-01-26 04:23:15,615-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:820) Key is writable
2016-01-26 04:23:15,615-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:1170) Sent message with length 58 to 172.26.50.120/4001: 7e:05:13:c1:30:31:02:01:00:04:06:50:75:62:6c:69:63:a0:24:02:04:36:af:82:8a:02:01:00:02:01:00:30:16:30:14:06:10:2b:06:01:04:01:89:36:04:02:03:05:08:01:03:05:01:05:00:d7:b2:7e
2016-01-26 04:23:15,615-0700 [DEBUG|DefaultTcpTransportMapping$SocketEntry] (DefaultTcpTransportMapping.java:431) Adding operation 1 for: SocketEntry[peerAddress=172.26.50.120/4001,socket=Socket[addr=/172.26.50.120,port=4001,localport=10826],lastUse=Thu Jan 15 16:23:38 MST 1970,readBufferPosition=-1]
2016-01-26 04:23:15,615-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:820) Key is writable
2016-01-26 04:23:15,828-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:824) Key is readable
2016-01-26 04:23:15,828-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:836) Key is reading
2016-01-26 04:23:15,828-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:1034) Reading header 7 bytes from 172.26.50.120/4001
2016-01-26 04:23:15,828-0700 [DEBUG|DefaultTcpTransportMapping] (DefaultTcpTransportMapping.java:1221) Adding data java.nio.HeapByteBuffer[pos=7 lim=10 cap=65535] to read buffer null
2016-01-26 04:23:15,906-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:824) Key is readable
2016-01-26 04:23:15,906-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:836) Key is reading
2016-01-26 04:23:15,906-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:1001) Read 3 bytes from 172.26.50.120/4001
2016-01-26 04:23:15,906-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:1074) Message length is org.snmp4j.transport.MessageLength[headerLength=6,payloadLength=130]
2016-01-26 04:23:15,906-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:1095) Extending message buffer size according to message length to 136
2016-01-26 04:23:15,990-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:824) Key is readable
2016-01-26 04:23:15,990-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:836) Key is reading
2016-01-26 04:23:15,990-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:1001) Read 61 bytes from 172.26.50.120/4001
2016-01-26 04:23:15,990-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:1074) Message length is org.snmp4j.transport.MessageLength[headerLength=6,payloadLength=130]
2016-01-26 04:23:15,990-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:1117) Message completed with 136 bytes and 136 buffer limit
2016-01-26 04:23:15,990-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:1141) Received message from 172.26.50.120/4001 with length 136: 7e:05:13:c1:30:7f:02:01:00:04:06:50:75:62:6c:69:63:a2:72:02:04:36:af:82:8a:02:01:00:02:01:00:30:64:30:62:06:10:2b:06:01:04:01:89:36:04:02:03:05:08:01:03:05:01:04:4e:5b:66:39:5d:2f:5b:66:38:5d:2f:5b:66:31:30:5d:5b:6e:6c:5d:5b:66:31:5d:5b:6e:6c:5d:5b:66:34:5d:20:44:45:47:52:45:45:53:5b:6e:70:5d:54:48:41:4e:4b:53:20:46:4f:52:5b:6e:6c:5d:44:52:49:56:49:4e:47:5b:6e:6c:5d:4e:57:20:50:41:52:4b:57:41:59:fc:8b:7e
2016-01-26 04:23:15,990-0700 [DEBUG|Snmp] (Snmp.java:1193) Looking up pending request with handle PduHandle[917471882]
2016-01-26 04:23:15,990-0700 [DEBUG|Snmp] (Snmp.java:919) Removed pending request with handle: PduHandle[917471882]
2016-01-26 04:23:15,990-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:1200) Terminated worker task: org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
2016-01-26 04:23:15,990-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:1213) Interrupting worker task: org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
2016-01-26 04:23:15,990-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:901) Worker task finished: org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
2016-01-26 04:23:15,990-0700 [DEBUG|DefaultTcpTransportMapping$ServerThread] (DefaultTcpTransportMapping.java:1206) Joining worker task: org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
2016-01-26 04:23:15,990-0700 [DEBUG|DefaultTcpTransportMapping] (DefaultTcpTransportMapping.java:213) Socket to 172.26.50.120/4001 closed
2016-01-26 04:23:15,990-0700 [DEBUG|DefaultTcpTransportMapping] (DefaultTcpTransportMapping.java:218) Socket channel to 172.26.50.120/4001 closed

Best regards,
Bruno

Bruno Filipe Basílio
Departamento de Investigação, Desenvolvimento e Inovação

Tel: (+351) 214233436

http://www.brisainovacao.pt

--------------------------------------------------------------------------------

Declaração:
A informação contida nesta mensagem, e os ficheiros anexos, é privilegiada e confidencial, destinando-se exclusivamente ao(s) destinatário(s).Se não é o destinatário (ou o responsável pela sua entrega ao destinatário) e recebeu a mesma por engano, fica notificado que é estritamente proibido reproduzir, guardar ou distribuir toda ou qualquer parte desta mensagem e ficheiros anexos. Por favor reencaminhe a mensagem para o responsável pelo seu envio ou contacte-nos por telefone e elimine a mensagem e ficheiros anexos do seu computador, sem os reproduzir.

Disclaimer:
The information contained in this message, and any files attached, is privileged and confidential, and intended exclusively for the included addresses. If you are not the intended recipient (or the person responsible for delivering to the intended recipient) and received this message by mistake, be aware that copy, storage, distribution or any other use of all or part of this message and the files attached is strictly prohibited. Please notify the sender by reply e-mail or contact us by telephone and delete this message and the files attached, without retaining a copy.

--------------------------------------------------------------------------------