[SNMP4J] Problem with DefaultTCPTransportMapping
Brice Fines
bfines at sermepa.es
Fri Oct 9 13:25:44 CEST 2009
Hi again,
This is just to complete my previous answer.
To illustrate the following case with the snapshot version of SNMP4J with
detailed logs.
"For example, client A is listening for SNMP over TCP, client B is not
listening for SNMP over TCP.
Without closing manually TCP transport connection, we have (I will provide
logs for that case in a separate answer so you can check out it is
correct):
_send command to client A, result OK
_send command to client B, fail due to connection problem
_send command to client A, fail because TCP transport has not recovered
yet
_connection timeout occurs for failed client B TCP connection and close
gracefully
_send command to client A, result OK"
****************************************************************************************************************************
_send command to client A, result OK
****************************************************************************************************************************
[9/10/09 12:40:46:374 CEST] 00000035 SystemOut O org.snmp4j.mp.MPv3
<prepareOutgoingMessage> Context engine ID of scoped
PDU is empty! Setting it to authoritative engine ID:
80:00:1f:88:80:7d:10:00:00:29:15:78:4a
[9/10/09 12:40:46:374 CEST] 00000035 SystemOut O org.snmp4j.mp.MPv3
<prepareOutgoingMessage> Context engine ID of scoped
PDU is empty! Setting it to authoritative engine ID:
80:00:1f:88:80:7d:10:00:00:29:15:78:4a
[9/10/09 12:40:46:374 CEST] 00000035 SystemOut O
org.snmp4j.security.USM <getUser>
getUser(engineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,
securityName=urwxxxxxxx)
[9/10/09 12:40:46:374 CEST] 00000035 SystemOut O
org.snmp4j.security.USM <getUser>
getUser(engineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,
securityName=urwxxxxxxx)
[9/10/09 12:40:46:374 CEST] 00000035 SystemOut O
org.snmp4j.security.USM <generateResponseMessage> RFC3414 ?3.1.4.b
Outgoing message is not encrypted
[9/10/09 12:40:46:374 CEST] 00000035 SystemOut O
org.snmp4j.security.USM <generateResponseMessage> RFC3414 ?3.1.4.b
Outgoing message is not encrypted
[9/10/09 12:40:46:374 CEST] 00000035 SystemOut O
org.snmp4j.mp.MPv3$Cache <addEntry> Adding cache entry:
StateReference[msgID=2097228258,pduHandle=PduHandle[1902849333],securityEngineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,secur
ityModel=org.snmp4j.security.USM at b480b48,securityName=urwxxxxxxx,securityLevel=2,contextEngineID=80:00:1f:88:80:7d:10:00:00:2
9:15:78:4a,contextName=]
[9/10/09 12:40:46:374 CEST] 00000035 SystemOut O
org.snmp4j.mp.MPv3$Cache <addEntry> Adding cache entry:
StateReference[msgID=2097228258,pduHandle=PduHandle[1902849333],securityEngineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,secur
ityModel=org.snmp4j.security.USM at b480b48,securityName=urwxxxxxxx,securityLevel=2,contextEngineID=80:00:1f:88:80:7d:10:00:00:2
9:15:78:4a,contextName=]
[9/10/09 12:40:46:374 CEST] 00000035 SystemOut O
org.snmp4j.Snmp$PendingRequest <pduHandleAssigned> Running pending sync
request with handle PduHandle[1902849333] and retry count left 0
[9/10/09 12:40:46:374 CEST] 00000035 SystemOut O
org.snmp4j.Snmp$PendingRequest <pduHandleAssigned> Running pending sync
request with handle PduHandle[1902849333] and retry count left 0
[9/10/09 12:40:46:374 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Looking up connection for destination '10.2.2.127/161'
returned:
SocketEntry[peerAddress=10.2.2.127/161,socket=Socket[addr=/10.2.2.127,port=161,localport=3140],lastUse=Fri
Oct 09 12:40:32
CEST 2009]
[9/10/09 12:40:46:374 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Looking up connection for destination '10.2.2.127/161'
returned:
SocketEntry[peerAddress=10.2.2.127/161,socket=Socket[addr=/10.2.2.127,port=161,localport=3140],lastUse=Fri
Oct 09 12:40:32
CEST 2009]
[9/10/09 12:40:46:374 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage>
{10.2.2.127/161=SocketEntry[peerAddress=10.2.2.127/161,socket=Socket[addr=/10.2.2.127,port=161,localport=3140],lastUse=Fri
Oct 09 12:40:32 CEST 2009]}
[9/10/09 12:40:46:374 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage>
{10.2.2.127/161=SocketEntry[peerAddress=10.2.2.127/161,socket=Socket[addr=/10.2.2.127,port=161,localport=3140],lastUse=Fri
Oct 09 12:40:32 CEST 2009]}
[9/10/09 12:40:46:374 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<writeMessage> Send message with length 132 to 10.2.2.127/161:
30:81:81:02:01:03:30:11:02:04:7d:01:29:e2:02:03:00:ff:ff:04:01:05:02:01:03:04:35:30:33:04:0d:80:00:1f:88:80:7d:10:00:00:29:15
:78:4a:02:01:43:02:03:02:73:4f:04:0a:75:72:77:53:65:72:6d:65:70:61:04:0c:d5:25:ff:d7:a2:4a:75:9e:7d:e4:6b:d9:04:00:30:32:04:0
d:80:00:1f:88:80:7d:10:00:00:29:15:78:4a:04:00:a0:1f:02:04:71:6b:2d:35:02:01:00:02:01:00:30:11:30:0f:06:0b:2b:06:01:04:01:b6:
20:01:01:01:01:05:00
[9/10/09 12:40:46:374 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<writeMessage> Send message with length 132 to 10.2.2.127/161:
30:81:81:02:01:03:30:11:02:04:7d:01:29:e2:02:03:00:ff:ff:04:01:05:02:01:03:04:35:30:33:04:0d:80:00:1f:88:80:7d:10:00:00:29:15
:78:4a:02:01:43:02:03:02:73:4f:04:0a:75:72:77:53:65:72:6d:65:70:61:04:0c:d5:25:ff:d7:a2:4a:75:9e:7d:e4:6b:d9:04:00:30:32:04:0
d:80:00:1f:88:80:7d:10:00:00:29:15:78:4a:04:00:a0:1f:02:04:71:6b:2d:35:02:01:00:02:01:00:30:11:30:0f:06:0b:2b:06:01:04:01:b6:
20:01:01:01:01:05:00
[9/10/09 12:40:46:389 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<readMessage> Reading header 6 bytes from 10.2.2.127/161
[9/10/09 12:40:46:389 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<readMessage> Reading header 6 bytes from 10.2.2.127/161
[9/10/09 12:40:46:389 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<readMessage> Message length is
org.snmp4j.transport.MessageLength[headerLength=3,payloadLength=147]
[9/10/09 12:40:46:389 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<readMessage> Message length is
org.snmp4j.transport.MessageLength[headerLength=3,payloadLength=147]
[9/10/09 12:40:46:389 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<dispatchMessage> Received message from 10.2.2.127/161 with length 150:
30:81:93:02:01:03:30:12:02:04:7d:01:29:e2:02:04:7f:ff:ff:ff:04:01:01:02:01:03:04:35:30:33:04:0d:80:00:1f:88:80:7d:10:00:00:29
:15:78:4a:02:01:43:02:03:02:73:4f:04:0a:75:72:77:53:65:72:6d:65:70:61:04:0c:fd:9f:2a:80:31:3f:05:00:da:3d:a8:12:04:00:30:43:0
4:0d:80:00:1f:88:80:7d:10:00:00:29:15:78:4a:04:00:a2:30:02:04:71:6b:2d:35:02:01:00:02:01:00:30:22:30:20:06:0b:2b:06:01:04:01:
b6:20:01:01:01:01:04:11:30:30:36:35:2d:38:38:38:38:2d:38:38:20:30:30:36:35
[9/10/09 12:40:46:389 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<dispatchMessage> Received message from 10.2.2.127/161 with length 150:
30:81:93:02:01:03:30:12:02:04:7d:01:29:e2:02:04:7f:ff:ff:ff:04:01:01:02:01:03:04:35:30:33:04:0d:80:00:1f:88:80:7d:10:00:00:29
:15:78:4a:02:01:43:02:03:02:73:4f:04:0a:75:72:77:53:65:72:6d:65:70:61:04:0c:fd:9f:2a:80:31:3f:05:00:da:3d:a8:12:04:00:30:43:0
4:0d:80:00:1f:88:80:7d:10:00:00:29:15:78:4a:04:00:a2:30:02:04:71:6b:2d:35:02:01:00:02:01:00:30:22:30:20:06:0b:2b:06:01:04:01:
b6:20:01:01:01:01:04:11:30:30:36:35:2d:38:38:38:38:2d:38:38:20:30:30:36:35
[9/10/09 12:40:46:389 CEST] 0000003a SystemOut O
org.snmp4j.mp.MPv3$HeaderData <decodeBER> SNMPv3 header decoded:
msgId=2097228258, msgMaxSize=2147483647, msgFlags=01, secModel=3
[9/10/09 12:40:46:389 CEST] 0000003a SystemOut O
org.snmp4j.mp.MPv3$HeaderData <decodeBER> SNMPv3 header decoded:
msgId=2097228258, msgMaxSize=2147483647, msgFlags=01, secModel=3
[9/10/09 12:40:46:389 CEST] 0000003a SystemOut O
org.snmp4j.security.USM <getUser>
getUser(engineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,
securityName=urwxxxxxxx)
[9/10/09 12:40:46:389 CEST] 0000003a SystemOut O
org.snmp4j.security.USM <getUser>
getUser(engineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,
securityName=urwxxxxxxx)
[9/10/09 12:40:46:795 CEST] 0000003a SystemOut O
org.snmp4j.security.UsmTimeTable <checkTime> CheckTime: time ok (non
authorative)
[9/10/09 12:40:46:795 CEST] 0000003a SystemOut O
org.snmp4j.security.UsmTimeTable <checkTime> CheckTime: time ok (non
authorative)
[9/10/09 12:40:46:795 CEST] 0000003a SystemOut O
org.snmp4j.mp.MPv3$Cache <popEntry> Removed cache entry:
StateReference[msgID=2097228258,pduHandle=PduHandle[1902849333],securityEngineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,secur
ityModel=org.snmp4j.security.USM at b480b48,securityName=urwxxxxxxx,securityLevel=2,contextEngineID=80:00:1f:88:80:7d:10:00:00:2
9:15:78:4a,contextName=]
[9/10/09 12:40:46:795 CEST] 0000003a SystemOut O
org.snmp4j.mp.MPv3$Cache <popEntry> Removed cache entry:
StateReference[msgID=2097228258,pduHandle=PduHandle[1902849333],securityEngineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,secur
ityModel=org.snmp4j.security.USM at b480b48,securityName=urwxxxxxxx,securityLevel=2,contextEngineID=80:00:1f:88:80:7d:10:00:00:2
9:15:78:4a,contextName=]
[9/10/09 12:40:46:795 CEST] 0000003a SystemOut O org.snmp4j.mp.MPv3
<prepareDataElements> RFC3412 ?7.2.10 - Received PDU
(msgID=2097228258) is a response or an internal class message.
PduHandle.transactionID = 1902849333
[9/10/09 12:40:46:795 CEST] 0000003a SystemOut O org.snmp4j.mp.MPv3
<prepareDataElements> RFC3412 ?7.2.10 - Received PDU
(msgID=2097228258) is a response or an internal class message.
PduHandle.transactionID = 1902849333
[9/10/09 12:40:46:795 CEST] 0000003a SystemOut O org.snmp4j.mp.MPv3
<prepareDataElements> MPv3 finished
[9/10/09 12:40:46:795 CEST] 0000003a SystemOut O org.snmp4j.mp.MPv3
<prepareDataElements> MPv3 finished
[9/10/09 12:40:46:795 CEST] 0000003a SystemOut O org.snmp4j.Snmp
<processPdu> Looking up pending request with handle
PduHandle[1902849333]
[9/10/09 12:40:46:795 CEST] 0000003a SystemOut O org.snmp4j.Snmp
<processPdu> Looking up pending request with handle
PduHandle[1902849333]
[9/10/09 12:40:46:795 CEST] 00000035 SystemOut O org.snmp4j.Snmp
<send> Removed pending request with handle:
PduHandle[1902849333]
[9/10/09 12:40:46:795 CEST] 00000035 SystemOut O org.snmp4j.Snmp
<send> Removed pending request with handle:
PduHandle[1902849333]
****************************************************************************************************************************
_send command to client B, fail due to connection problem
****************************************************************************************************************************
[9/10/09 12:40:51:342 CEST] 00000035 SystemOut O
org.snmp4j.security.USM <generateResponseMessage> RFC3414 ?3.1.4.b
Outgoing message is not encrypted
[9/10/09 12:40:51:342 CEST] 00000035 SystemOut O
org.snmp4j.security.USM <generateResponseMessage> RFC3414 ?3.1.4.b
Outgoing message is not encrypted
[9/10/09 12:40:51:342 CEST] 00000035 SystemOut O
org.snmp4j.mp.MPv3$Cache <addEntry> Adding cache entry:
StateReference[msgID=2097228259,pduHandle=PduHandle[1902849335],securityEngineID=,securityModel=org.snmp4j.security.USM at b480b
48,securityName=urwxxxxxxx,securityLevel=1,contextEngineID=,contextName=]
[9/10/09 12:40:51:342 CEST] 00000035 SystemOut O
org.snmp4j.mp.MPv3$Cache <addEntry> Adding cache entry:
StateReference[msgID=2097228259,pduHandle=PduHandle[1902849335],securityEngineID=,securityModel=org.snmp4j.security.USM at b480b
48,securityName=urwxxxxxxx,securityLevel=1,contextEngineID=,contextName=]
[9/10/09 12:40:51:342 CEST] 00000035 SystemOut O
org.snmp4j.Snmp$PendingRequest <pduHandleAssigned> Running pending sync
request with handle PduHandle[1902849335] and retry count left 0
[9/10/09 12:40:51:358 CEST] 00000035 SystemOut O
org.snmp4j.Snmp$PendingRequest <pduHandleAssigned> Running pending sync
request with handle PduHandle[1902849335] and retry count left 0
[9/10/09 12:40:51:358 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Looking up connection for destination '10.2.2.90/161'
returned: null
[9/10/09 12:40:51:358 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Looking up connection for destination '10.2.2.90/161'
returned: null
[9/10/09 12:40:51:358 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage>
{10.2.2.127/161=SocketEntry[peerAddress=10.2.2.127/161,socket=Socket[addr=/10.2.2.127,port=161,localport=3140],lastUse=Fri
Oct 09 12:40:46 CEST 2009]}
[9/10/09 12:40:51:358 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage>
{10.2.2.127/161=SocketEntry[peerAddress=10.2.2.127/161,socket=Socket[addr=/10.2.2.127,port=161,localport=3140],lastUse=Fri
Oct 09 12:40:46 CEST 2009]}
[9/10/09 12:40:51:358 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Socket for address '10.2.2.90/161' is closed, opening it...
[9/10/09 12:40:51:358 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Socket for address '10.2.2.90/161' is closed, opening it...
[9/10/09 12:40:51:358 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Trying to connect to 10.2.2.90/161
[9/10/09 12:40:51:358 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Trying to connect to 10.2.2.90/161
[9/10/09 12:40:56:358 CEST] 00000035 SystemOut O org.snmp4j.Snmp
<send> Removed pending request with handle:
PduHandle[1902849335]
[9/10/09 12:40:56:358 CEST] 00000035 SystemOut O org.snmp4j.Snmp
<send> Removed pending request with handle:
PduHandle[1902849335]
****************************************************************************************************************************
_send command to client A, fail because TCP transport has not recovered
yet
****************************************************************************************************************************
[9/10/09 12:40:58:952 CEST] 00000035 SystemOut O org.snmp4j.mp.MPv3
<prepareOutgoingMessage> Context engine ID of scoped
PDU is empty! Setting it to authoritative engine ID:
80:00:1f:88:80:7d:10:00:00:29:15:78:4a
[9/10/09 12:40:58:952 CEST] 00000035 SystemOut O org.snmp4j.mp.MPv3
<prepareOutgoingMessage> Context engine ID of scoped
PDU is empty! Setting it to authoritative engine ID:
80:00:1f:88:80:7d:10:00:00:29:15:78:4a
[9/10/09 12:40:58:952 CEST] 00000035 SystemOut O
org.snmp4j.security.USM <getUser>
getUser(engineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,
securityName=urwxxxxxxx)
[9/10/09 12:40:58:952 CEST] 00000035 SystemOut O
org.snmp4j.security.USM <getUser>
getUser(engineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,
securityName=urwxxxxxxx)
[9/10/09 12:40:58:952 CEST] 00000035 SystemOut O
org.snmp4j.security.USM <generateResponseMessage> RFC3414 ?3.1.4.b
Outgoing message is not encrypted
[9/10/09 12:40:58:952 CEST] 00000035 SystemOut O
org.snmp4j.security.USM <generateResponseMessage> RFC3414 ?3.1.4.b
Outgoing message is not encrypted
[9/10/09 12:40:58:952 CEST] 00000035 SystemOut O
org.snmp4j.mp.MPv3$Cache <addEntry> Adding cache entry:
StateReference[msgID=2097228260,pduHandle=PduHandle[1902849336],securityEngineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,secur
ityModel=org.snmp4j.security.USM at b480b48,securityName=urwxxxxxxx,securityLevel=2,contextEngineID=80:00:1f:88:80:7d:10:00:00:2
9:15:78:4a,contextName=]
[9/10/09 12:40:58:952 CEST] 00000035 SystemOut O
org.snmp4j.mp.MPv3$Cache <addEntry> Adding cache entry:
StateReference[msgID=2097228260,pduHandle=PduHandle[1902849336],securityEngineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,secur
ityModel=org.snmp4j.security.USM at b480b48,securityName=urwxxxxxxx,securityLevel=2,contextEngineID=80:00:1f:88:80:7d:10:00:00:2
9:15:78:4a,contextName=]
[9/10/09 12:40:58:952 CEST] 00000035 SystemOut O
org.snmp4j.Snmp$PendingRequest <pduHandleAssigned> Running pending sync
request with handle PduHandle[1902849336] and retry count left 0
[9/10/09 12:40:58:952 CEST] 00000035 SystemOut O
org.snmp4j.Snmp$PendingRequest <pduHandleAssigned> Running pending sync
request with handle PduHandle[1902849336] and retry count left 0
[9/10/09 12:40:58:952 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Looking up connection for destination '10.2.2.127/161'
returned:
SocketEntry[peerAddress=10.2.2.127/161,socket=Socket[addr=/10.2.2.127,port=161,localport=3140],lastUse=Fri
Oct 09 12:40:46
CEST 2009]
[9/10/09 12:40:58:952 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Looking up connection for destination '10.2.2.127/161'
returned:
SocketEntry[peerAddress=10.2.2.127/161,socket=Socket[addr=/10.2.2.127,port=161,localport=3140],lastUse=Fri
Oct 09 12:40:46
CEST 2009]
[9/10/09 12:40:58:952 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage>
{10.2.2.127/161=SocketEntry[peerAddress=10.2.2.127/161,socket=Socket[addr=/10.2.2.127,port=161,localport=3140],lastUse=Fri
Oct 09 12:40:46 CEST 2009],
10.2.2.90/161=SocketEntry[peerAddress=10.2.2.90/161,socket=Socket[unconnected],lastUse=Fri
Oct 09
12:40:51 CEST 2009]}
[9/10/09 12:40:58:952 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage>
{10.2.2.127/161=SocketEntry[peerAddress=10.2.2.127/161,socket=Socket[addr=/10.2.2.127,port=161,localport=3140],lastUse=Fri
Oct 09 12:40:46 CEST 2009],
10.2.2.90/161=SocketEntry[peerAddress=10.2.2.90/161,socket=Socket[unconnected],lastUse=Fri
Oct 09
12:40:51 CEST 2009]}
[9/10/09 12:41:03:952 CEST] 00000035 SystemOut O org.snmp4j.Snmp
<send> Removed pending request with handle:
PduHandle[1902849336]
[9/10/09 12:41:03:952 CEST] 00000035 SystemOut O org.snmp4j.Snmp
<send> Removed pending request with handle:
PduHandle[1902849336]
[9/10/09 12:41:03:952 CEST] 0000003c SystemOut O
org.snmp4j.Snmp$PendingRequest <run> Request timed out: 1902849336
[9/10/09 12:41:03:952 CEST] 0000003c SystemOut O
org.snmp4j.Snmp$PendingRequest <run> Request timed out: 1902849336
[9/10/09 12:41:03:952 CEST] 0000003c SystemOut O
org.snmp4j.Snmp$PendingRequest <run> Failed to process pending request
PduHandle[1902849336] because null
java.lang.NullPointerException
at org.snmp4j.Snmp$PendingRequest.run(Snmp.java:1626)
at java.util.TimerThread.mainLoop(Timer.java:537)
at java.util.TimerThread.run(Timer.java:487)
[9/10/09 12:41:03:952 CEST] 0000003c SystemOut O
org.snmp4j.Snmp$PendingRequest <run> Failed to process pending request
PduHandle[1902849336] because null
java.lang.NullPointerException
at org.snmp4j.Snmp$PendingRequest.run(Snmp.java:1626)
at java.util.TimerThread.mainLoop(Timer.java:537)
at java.util.TimerThread.run(Timer.java:487)
[9/10/09 12:41:03:952 CEST] 0000003c SystemErr R Exception in thread
"Timer-9" java.lang.NullPointerException
[9/10/09 12:41:03:968 CEST] 0000003c SystemErr R at
org.snmp4j.Snmp$PendingRequest.run(Snmp.java:1626)
[9/10/09 12:41:03:968 CEST] 0000003c SystemErr R at
java.util.TimerThread.mainLoop(Timer.java:537)
[9/10/09 12:41:03:968 CEST] 0000003c SystemErr R at
java.util.TimerThread.run(Timer.java:487)
****************************************************************************************************************************
_connection timeout occurs for failed client B TCP connection and close
gracefully
****************************************************************************************************************************
[9/10/09 12:41:12:374 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<connectChannel> java.net.ConnectException: Connection timed out: no
further information
[9/10/09 12:41:12:374 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<connectChannel> java.net.ConnectException: Connection timed out: no
further information
[9/10/09 12:41:12:374 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<processPending> java.nio.channels.ClosedChannelException
[9/10/09 12:41:12:374 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<processPending> java.nio.channels.ClosedChannelException
[9/10/09 12:41:12:374 CEST] 0000003a SystemOut O
org.snmp4j.transport.TcpTransportMapping <fireConnectionStateChanged>
Firing transport state event:
org.snmp4j.transport.TransportStateEvent[source=org.snmp4j.transport.DefaultTcpTransportMapping at 7e607e6,peerAddress=10.2.2.90
/161,newState=4,cancelled=false,causingException=java.nio.channels.ClosedChannelException]
[9/10/09 12:41:12:374 CEST] 0000003a SystemOut O
org.snmp4j.transport.TcpTransportMapping <fireConnectionStateChanged>
Firing transport state event:
org.snmp4j.transport.TransportStateEvent[source=org.snmp4j.transport.DefaultTcpTransportMapping at 7e607e6,peerAddress=10.2.2.90
/161,newState=4,cancelled=false,causingException=java.nio.channels.ClosedChannelException]
****************************************************************************************************************************
_send command to client A, result OK
****************************************************************************************************************************
[9/10/09 12:41:18:796 CEST] 00000035 SystemOut O org.snmp4j.mp.MPv3
<prepareOutgoingMessage> Context engine ID of scoped
PDU is empty! Setting it to authoritative engine ID:
80:00:1f:88:80:7d:10:00:00:29:15:78:4a
[9/10/09 12:41:18:796 CEST] 00000035 SystemOut O org.snmp4j.mp.MPv3
<prepareOutgoingMessage> Context engine ID of scoped
PDU is empty! Setting it to authoritative engine ID:
80:00:1f:88:80:7d:10:00:00:29:15:78:4a
[9/10/09 12:41:18:796 CEST] 00000035 SystemOut O
org.snmp4j.security.USM <getUser>
getUser(engineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,
securityName=urwxxxxxxx)
[9/10/09 12:41:18:796 CEST] 00000035 SystemOut O
org.snmp4j.security.USM <getUser>
getUser(engineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,
securityName=urwxxxxxxx)
[9/10/09 12:41:18:796 CEST] 00000035 SystemOut O
org.snmp4j.security.USM <generateResponseMessage> RFC3414 ?3.1.4.b
Outgoing message is not encrypted
[9/10/09 12:41:18:796 CEST] 00000035 SystemOut O
org.snmp4j.security.USM <generateResponseMessage> RFC3414 ?3.1.4.b
Outgoing message is not encrypted
[9/10/09 12:41:18:796 CEST] 00000035 SystemOut O
org.snmp4j.mp.MPv3$Cache <addEntry> Adding cache entry:
StateReference[msgID=2097228261,pduHandle=PduHandle[1902849337],securityEngineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,secur
ityModel=org.snmp4j.security.USM at b480b48,securityName=urwxxxxxxx,securityLevel=2,contextEngineID=80:00:1f:88:80:7d:10:00:00:2
9:15:78:4a,contextName=]
[9/10/09 12:41:18:796 CEST] 00000035 SystemOut O
org.snmp4j.mp.MPv3$Cache <addEntry> Adding cache entry:
StateReference[msgID=2097228261,pduHandle=PduHandle[1902849337],securityEngineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,secur
ityModel=org.snmp4j.security.USM at b480b48,securityName=urwxxxxxxx,securityLevel=2,contextEngineID=80:00:1f:88:80:7d:10:00:00:2
9:15:78:4a,contextName=]
[9/10/09 12:41:18:796 CEST] 00000035 SystemOut O
org.snmp4j.Snmp$PendingRequest <pduHandleAssigned> Running pending sync
request with handle PduHandle[1902849337] and retry count left 0
[9/10/09 12:41:18:796 CEST] 00000035 SystemOut O
org.snmp4j.Snmp$PendingRequest <pduHandleAssigned> Running pending sync
request with handle PduHandle[1902849337] and retry count left 0
[9/10/09 12:41:18:796 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Looking up connection for destination '10.2.2.127/161'
returned:
SocketEntry[peerAddress=10.2.2.127/161,socket=Socket[addr=/10.2.2.127,port=161,localport=3140],lastUse=Fri
Oct 09 12:40:46
CEST 2009]
[9/10/09 12:41:18:796 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Looking up connection for destination '10.2.2.127/161'
returned:
SocketEntry[peerAddress=10.2.2.127/161,socket=Socket[addr=/10.2.2.127,port=161,localport=3140],lastUse=Fri
Oct 09 12:40:46
CEST 2009]
[9/10/09 12:41:18:796 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage>
{10.2.2.127/161=SocketEntry[peerAddress=10.2.2.127/161,socket=Socket[addr=/10.2.2.127,port=161,localport=3140],lastUse=Fri
Oct 09 12:40:46 CEST 2009],
10.2.2.90/161=SocketEntry[peerAddress=10.2.2.90/161,socket=Socket[unconnected],lastUse=Fri
Oct 09
12:40:51 CEST 2009]}
[9/10/09 12:41:18:796 CEST] 00000035 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage>
{10.2.2.127/161=SocketEntry[peerAddress=10.2.2.127/161,socket=Socket[addr=/10.2.2.127,port=161,localport=3140],lastUse=Fri
Oct 09 12:40:46 CEST 2009],
10.2.2.90/161=SocketEntry[peerAddress=10.2.2.90/161,socket=Socket[unconnected],lastUse=Fri
Oct 09
12:40:51 CEST 2009]}
[9/10/09 12:41:18:796 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<writeMessage> Send message with length 132 to 10.2.2.127/161:
30:81:81:02:01:03:30:11:02:04:7d:01:29:e4:02:03:00:ff:ff:04:01:05:02:01:03:04:35:30:33:04:0d:80:00:1f:88:80:7d:10:00:00:29:15
:78:4a:02:01:43:02:03:02:73:5b:04:0a:75:72:77:53:65:72:6d:65:70:61:04:0c:36:96:15:67:54:bf:c0:88:58:d1:63:45:04:00:30:32:04:0
d:80:00:1f:88:80:7d:10:00:00:29:15:78:4a:04:00:a0:1f:02:04:71:6b:2d:38:02:01:00:02:01:00:30:11:30:0f:06:0b:2b:06:01:04:01:b6:
20:01:01:01:01:05:00
[9/10/09 12:41:18:796 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<writeMessage> Send message with length 132 to 10.2.2.127/161:
30:81:81:02:01:03:30:11:02:04:7d:01:29:e4:02:03:00:ff:ff:04:01:05:02:01:03:04:35:30:33:04:0d:80:00:1f:88:80:7d:10:00:00:29:15
:78:4a:02:01:43:02:03:02:73:5b:04:0a:75:72:77:53:65:72:6d:65:70:61:04:0c:36:96:15:67:54:bf:c0:88:58:d1:63:45:04:00:30:32:04:0
d:80:00:1f:88:80:7d:10:00:00:29:15:78:4a:04:00:a0:1f:02:04:71:6b:2d:38:02:01:00:02:01:00:30:11:30:0f:06:0b:2b:06:01:04:01:b6:
20:01:01:01:01:05:00
[9/10/09 12:41:18:796 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<writeMessage> Send message with length 132 to 10.2.2.127/161:
30:81:81:02:01:03:30:11:02:04:7d:01:29:e5:02:03:00:ff:ff:04:01:05:02:01:03:04:35:30:33:04:0d:80:00:1f:88:80:7d:10:00:00:29:15
:78:4a:02:01:43:02:03:02:73:6f:04:0a:75:72:77:53:65:72:6d:65:70:61:04:0c:e0:90:c3:83:f7:50:52:b5:e0:cc:15:ab:04:00:30:32:04:0
d:80:00:1f:88:80:7d:10:00:00:29:15:78:4a:04:00:a0:1f:02:04:71:6b:2d:39:02:01:00:02:01:00:30:11:30:0f:06:0b:2b:06:01:04:01:b6:
20:01:01:01:01:05:00
[9/10/09 12:41:18:796 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<writeMessage> Send message with length 132 to 10.2.2.127/161:
30:81:81:02:01:03:30:11:02:04:7d:01:29:e5:02:03:00:ff:ff:04:01:05:02:01:03:04:35:30:33:04:0d:80:00:1f:88:80:7d:10:00:00:29:15
:78:4a:02:01:43:02:03:02:73:6f:04:0a:75:72:77:53:65:72:6d:65:70:61:04:0c:e0:90:c3:83:f7:50:52:b5:e0:cc:15:ab:04:00:30:32:04:0
d:80:00:1f:88:80:7d:10:00:00:29:15:78:4a:04:00:a0:1f:02:04:71:6b:2d:39:02:01:00:02:01:00:30:11:30:0f:06:0b:2b:06:01:04:01:b6:
20:01:01:01:01:05:00
[9/10/09 12:41:18:796 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<readMessage> Reading header 6 bytes from 10.2.2.127/161
[9/10/09 12:41:18:796 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<readMessage> Reading header 6 bytes from 10.2.2.127/161
[9/10/09 12:41:18:796 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<readMessage> Message length is
org.snmp4j.transport.MessageLength[headerLength=3,payloadLength=147]
[9/10/09 12:41:18:796 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<readMessage> Message length is
org.snmp4j.transport.MessageLength[headerLength=3,payloadLength=147]
[9/10/09 12:41:18:796 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<dispatchMessage> Received message from 10.2.2.127/161 with length 150:
30:81:93:02:01:03:30:12:02:04:7d:01:29:e4:02:04:7f:ff:ff:ff:04:01:01:02:01:03:04:35:30:33:04:0d:80:00:1f:88:80:7d:10:00:00:29
:15:78:4a:02:01:43:02:03:02:73:70:04:0a:75:72:77:53:65:72:6d:65:70:61:04:0c:34:f7:9a:d1:b5:e7:ca:96:cf:9f:d2:3d:04:00:30:43:0
4:0d:80:00:1f:88:80:7d:10:00:00:29:15:78:4a:04:00:a2:30:02:04:71:6b:2d:38:02:01:00:02:01:00:30:22:30:20:06:0b:2b:06:01:04:01:
b6:20:01:01:01:01:04:11:30:30:36:35:2d:38:38:38:38:2d:38:38:20:30:30:36:35
[9/10/09 12:41:18:796 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<dispatchMessage> Received message from 10.2.2.127/161 with length 150:
30:81:93:02:01:03:30:12:02:04:7d:01:29:e4:02:04:7f:ff:ff:ff:04:01:01:02:01:03:04:35:30:33:04:0d:80:00:1f:88:80:7d:10:00:00:29
:15:78:4a:02:01:43:02:03:02:73:70:04:0a:75:72:77:53:65:72:6d:65:70:61:04:0c:34:f7:9a:d1:b5:e7:ca:96:cf:9f:d2:3d:04:00:30:43:0
4:0d:80:00:1f:88:80:7d:10:00:00:29:15:78:4a:04:00:a2:30:02:04:71:6b:2d:38:02:01:00:02:01:00:30:22:30:20:06:0b:2b:06:01:04:01:
b6:20:01:01:01:01:04:11:30:30:36:35:2d:38:38:38:38:2d:38:38:20:30:30:36:35
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.mp.MPv3$HeaderData <decodeBER> SNMPv3 header decoded:
msgId=2097228260, msgMaxSize=2147483647, msgFlags=01, secModel=3
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.mp.MPv3$HeaderData <decodeBER> SNMPv3 header decoded:
msgId=2097228260, msgMaxSize=2147483647, msgFlags=01, secModel=3
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.security.USM <getUser>
getUser(engineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,
securityName=urwxxxxxxx)
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.security.USM <getUser>
getUser(engineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,
securityName=urwxxxxxxx)
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.security.UsmTimeTable <checkTime> CheckTime: time ok (non
authorative)
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.security.UsmTimeTable <checkTime> CheckTime: time ok (non
authorative)
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O org.snmp4j.mp.MPv3
<prepareDataElements> RFC3412 ?7.2.10 - Received PDU
(msgID=2097228260) is a response or internal class message, but cached
information for the msgID could not be found
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O org.snmp4j.mp.MPv3
<prepareDataElements> RFC3412 ?7.2.10 - Received PDU
(msgID=2097228260) is a response or internal class message, but cached
information for the msgID could not be found
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.MessageDispatcherImpl <dispatchMessage> noError
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.MessageDispatcherImpl <dispatchMessage> noError
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<readMessage> Reading header 6 bytes from 10.2.2.127/161
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<readMessage> Reading header 6 bytes from 10.2.2.127/161
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<readMessage> Message length is
org.snmp4j.transport.MessageLength[headerLength=3,payloadLength=147]
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<readMessage> Message length is
org.snmp4j.transport.MessageLength[headerLength=3,payloadLength=147]
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<dispatchMessage> Received message from 10.2.2.127/161 with length 150:
30:81:93:02:01:03:30:12:02:04:7d:01:29:e5:02:04:7f:ff:ff:ff:04:01:01:02:01:03:04:35:30:33:04:0d:80:00:1f:88:80:7d:10:00:00:29
:15:78:4a:02:01:43:02:03:02:73:70:04:0a:75:72:77:53:65:72:6d:65:70:61:04:0c:51:46:0d:fb:d3:d8:97:38:3c:2b:09:ef:04:00:30:43:0
4:0d:80:00:1f:88:80:7d:10:00:00:29:15:78:4a:04:00:a2:30:02:04:71:6b:2d:39:02:01:00:02:01:00:30:22:30:20:06:0b:2b:06:01:04:01:
b6:20:01:01:01:01:04:11:30:30:36:35:2d:38:38:38:38:2d:38:38:20:30:30:36:35
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<dispatchMessage> Received message from 10.2.2.127/161 with length 150:
30:81:93:02:01:03:30:12:02:04:7d:01:29:e5:02:04:7f:ff:ff:ff:04:01:01:02:01:03:04:35:30:33:04:0d:80:00:1f:88:80:7d:10:00:00:29
:15:78:4a:02:01:43:02:03:02:73:70:04:0a:75:72:77:53:65:72:6d:65:70:61:04:0c:51:46:0d:fb:d3:d8:97:38:3c:2b:09:ef:04:00:30:43:0
4:0d:80:00:1f:88:80:7d:10:00:00:29:15:78:4a:04:00:a2:30:02:04:71:6b:2d:39:02:01:00:02:01:00:30:22:30:20:06:0b:2b:06:01:04:01:
b6:20:01:01:01:01:04:11:30:30:36:35:2d:38:38:38:38:2d:38:38:20:30:30:36:35
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.mp.MPv3$HeaderData <decodeBER> SNMPv3 header decoded:
msgId=2097228261, msgMaxSize=2147483647, msgFlags=01, secModel=3
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.mp.MPv3$HeaderData <decodeBER> SNMPv3 header decoded:
msgId=2097228261, msgMaxSize=2147483647, msgFlags=01, secModel=3
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.security.USM <getUser>
getUser(engineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,
securityName=urwxxxxxxx)
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.security.USM <getUser>
getUser(engineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,
securityName=urwxxxxxxx)
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.security.UsmTimeTable <checkTime> CheckTime: time ok (non
authorative)
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.security.UsmTimeTable <checkTime> CheckTime: time ok (non
authorative)
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.mp.MPv3$Cache <popEntry> Removed cache entry:
StateReference[msgID=2097228261,pduHandle=PduHandle[1902849337],securityEngineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,secur
ityModel=org.snmp4j.security.USM at b480b48,securityName=urwxxxxxxx,securityLevel=2,contextEngineID=80:00:1f:88:80:7d:10:00:00:2
9:15:78:4a,contextName=]
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O
org.snmp4j.mp.MPv3$Cache <popEntry> Removed cache entry:
StateReference[msgID=2097228261,pduHandle=PduHandle[1902849337],securityEngineID=80:00:1f:88:80:7d:10:00:00:29:15:78:4a,secur
ityModel=org.snmp4j.security.USM at b480b48,securityName=urwxxxxxxx,securityLevel=2,contextEngineID=80:00:1f:88:80:7d:10:00:00:2
9:15:78:4a,contextName=]
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O org.snmp4j.mp.MPv3
<prepareDataElements> RFC3412 ?7.2.10 - Received PDU
(msgID=2097228261) is a response or an internal class message.
PduHandle.transactionID = 1902849337
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O org.snmp4j.mp.MPv3
<prepareDataElements> RFC3412 ?7.2.10 - Received PDU
(msgID=2097228261) is a response or an internal class message.
PduHandle.transactionID = 1902849337
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O org.snmp4j.mp.MPv3
<prepareDataElements> MPv3 finished
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O org.snmp4j.mp.MPv3
<prepareDataElements> MPv3 finished
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O org.snmp4j.Snmp
<processPdu> Looking up pending request with handle
PduHandle[1902849337]
[9/10/09 12:41:18:812 CEST] 0000003a SystemOut O org.snmp4j.Snmp
<processPdu> Looking up pending request with handle
PduHandle[1902849337]
[9/10/09 12:41:18:812 CEST] 00000035 SystemOut O org.snmp4j.Snmp
<send> Removed pending request with handle:
PduHandle[1902849337]
[9/10/09 12:41:18:812 CEST] 00000035 SystemOut O org.snmp4j.Snmp
<send> Removed pending request with handle:
PduHandle[1902849337]
Regards
More information about the SNMP4J
mailing list