[SNMP4J] TcpTransportMapping.close(address) hanging in AIX
Brice Fines
bfines at sermepa.es
Mon Oct 19 19:23:08 CEST 2009
Hi Frank,
I downloaded the snapshot (19 October 2009).
Here are the logs (I sent a SNMP get, the application keep hanging if I
use TcpTransportMapping.close(address) ).
Hope it helps.
Regards
[10/19/09 19:07:52:610 CEST] 0000002b SystemOut O
org.snmp4j.security.USM <generateResponseMessage> RFC3414 §3.1.4.b
Outgoing message is not encrypted
[10/19/09 19:07:52:618 CEST] 0000002b SystemOut O
org.snmp4j.mp.MPv3$Cache <addEntry> Adding cache entry:
StateReference[msgID=1611175772,pduHandle=PduHandle[240916333],securityEngineID=,securityModel=org.snmp4j.security.USM at 3f2c3f
2c,securityName=urwxxxxxxx,securityLevel=1,contextEngineID=,contextName=]
[10/19/09 19:07:52:622 CEST] 0000002b SystemOut O
org.snmp4j.Snmp$PendingRequest <pduHandleAssigned> Running pending sync
request with handle PduHandle[240916333] and retry count left 0
[10/19/09 19:07:52:628 CEST] 0000002b SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Looking up connection for destination '10.2.2.91/161'
returned: null
[10/19/09 19:07:52:631 CEST] 0000002b SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> {}
[10/19/09 19:07:52:636 CEST] 0000002b SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Socket for address '10.2.2.91/161' is closed, opening it...
[10/19/09 19:07:52:642 CEST] 0000002b SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Trying to connect to 10.2.2.91/161
[10/19/09 19:07:52:645 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<processPending> Registering for connect:
SocketEntry[peerAddress=10.2.2.91/161,socket=Socket[unconnected],lastUse=Mon
Oct 19
19:07:52 CEST 2009]
[10/19/09 19:07:52:648 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key
is connectable
[10/19/09 19:07:52:649 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<connectChannel> Connected to 10.2.2.91/161
[10/19/09 19:07:52:651 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<connectChannel> Fire connected event for null
[10/19/09 19:07:52:655 CEST] 0000002f SystemOut O
org.snmp4j.transport.TcpTransportMapping <fireConnectionStateChanged>
Firing transport state event:
org.snmp4j.transport.TransportStateEvent[source=org.snmp4j.transport.DefaultTcpTransportMapping at 30903090,peerAddress=10.2.2.9
1/161,newState=1,cancelled=false,causingException=null]
[10/19/09 19:07:52:657 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<processPending> Registering for write:
SocketEntry[peerAddress=10.2.2.91/161,socket=Socket[addr=/10.2.2.91,port=161,localport=60154],lastUse=Mon
Oct 19 19:07:52
CEST 2009]
[10/19/09 19:07:52:658 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key
is writable
[10/19/09 19:07:52:662 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<writeMessage> Send message with length 61 to 10.2.2.91/161:
30:3b:02:01:03:30:11:02:04:60:08:97:5c:02:03:00:ff:ff:04:01:04:02:01:03:04:10:30:0e:04:00:02:01:00:02:01:00:04:00:04:00:04:00
:30:11:04:00:04:00:a0:0b:02:01:00:02:01:00:02:01:00:30:00
[10/19/09 19:07:52:664 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key
is readable
[10/19/09 19:07:52:665 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key
is reading
[10/19/09 19:07:52:668 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<readMessage> Reading header 6 bytes from 10.2.2.91/161
[10/19/09 19:07:52:671 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<readMessage> Message length is
org.snmp4j.transport.MessageLength[headerLength=2,payloadLength=106]
[10/19/09 19:07:52:675 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<dispatchMessage> Received message from 10.2.2.91/161 with length 108:
30:6a:02:01:03:30:12:02:04:60:08:97:5c:02:04:7f:ff:ff:ff:04:01:00:02:01:03:04:20:30:1e:04:0d:80:00:1f:88:80:e7:25:00:00:e1:03
:4a:4a:02:02:02:01:02:03:04:34:6d:04:00:04:00:04:00:30:2f:04:0d:80:00:1f:88:80:e7:25:00:00:e1:03:4a:4a:04:00:a8:1c:02:01:00:0
2:01:00:02:01:00:30:11:30:0f:06:0a:2b:06:01:06:03:0f:01:01:04:00:41:01:03
[10/19/09 19:07:52:703 CEST] 0000002f SystemOut O
org.snmp4j.mp.MPv3$HeaderData <decodeBER> SNMPv3 header decoded:
msgId=1611175772, msgMaxSize=2147483647, msgFlags=00, secModel=3
[10/19/09 19:07:52:707 CEST] 0000002f SystemOut O
org.snmp4j.security.USM <processIncomingMsg> Accepting zero length
security name
[10/19/09 19:07:52:721 CEST] 0000002f SystemOut O
org.snmp4j.mp.MPv3$Cache <popEntry> Removed cache entry:
StateReference[msgID=1611175772,pduHandle=PduHandle[240916333],securityEngineID=,securityModel=org.snmp4j.security.USM at 3f2c3f
2c,securityName=urwxxxxxxx,securityLevel=1,contextEngineID=,contextName=]
[10/19/09 19:07:52:722 CEST] 0000002f SystemOut O org.snmp4j.mp.MPv3
<prepareDataElements> RFC3412 §7.2.10 - Received PDU
(msgID=1611175772) is a response or an internal class message.
PduHandle.transactionID = 240916333
[10/19/09 19:07:52:726 CEST] 0000002f SystemOut O org.snmp4j.mp.MPv3
<prepareDataElements> MPv3 finished
[10/19/09 19:07:52:729 CEST] 0000002f SystemOut O
org.snmp4j.Snmp$ReportProcessor <processReport> Searching pending
request with handlePduHandle[240916333]
[10/19/09 19:07:52:730 CEST] 0000002f SystemOut O
org.snmp4j.Snmp$ReportProcessor <processReport> Send new request after
report.
[10/19/09 19:07:52:733 CEST] 0000002f 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:e7:25:00:00:e1:03:4a:4a
[10/19/09 19:07:52:737 CEST] 0000002f SystemOut O
org.snmp4j.security.USM <getUser>
getUser(engineID=80:00:1f:88:80:e7:25:00:00:e1:03:4a:4a,
securityName=urwxxxxxxx)
[10/19/09 19:07:53:992 CEST] 0000002f SystemOut O
org.snmp4j.security.AuthGeneric <passwordToKey> MD5First digest:
b4:f1:54:db:6f:3f:08:b8:1a:93:2a:f0:a3:aa:ae:e4
[10/19/09 19:07:53:995 CEST] 0000002f SystemOut O
org.snmp4j.security.AuthGeneric <passwordToKey> MD5localized key:
2d:40:ea:a9:a8:e7:0b:d4:c1:b0:15:7e:bd:3c:fc:7e
[10/19/09 19:07:54:023 CEST] 0000002f SystemOut O
org.snmp4j.security.UsmUserTable <addUser> Adding user urwxxxxxxx =
UsmUser[secName=urwxxxxxxx,authProtocol=1.3.6.1.6.3.10.1.1.2,authPassphrase=2d:40:ea:a9:a8:e7:0b:d4:c1:b0:15:7e:bd:3c:fc:7e,p
rivProtocol=null,privPassphrase=null,localizationEngineID=80:00:1f:88:80:e7:25:00:00:e1:03:4a:4a]
[10/19/09 19:07:54:025 CEST] 0000002f SystemOut O
org.snmp4j.security.USM <generateResponseMessage> RFC3414 §3.1.4.b
Outgoing message is not encrypted
[10/19/09 19:07:54:030 CEST] 0000002f SystemOut O
org.snmp4j.mp.MPv3$Cache <addEntry> Adding cache entry:
StateReference[msgID=1611175773,pduHandle=PduHandle[240916333],securityEngineID=80:00:1f:88:80:e7:25:00:00:e1:03:4a:4a,securi
tyModel=org.snmp4j.security.USM at 3f2c3f2c,securityName=urwxxxxxxx,securityLevel=2,contextEngineID=80:00:1f:88:80:e7:25:00:00:e
1:03:4a:4a,contextName=]
[10/19/09 19:07:54:032 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Looking up connection for destination '10.2.2.91/161'
returned:
SocketEntry[peerAddress=10.2.2.91/161,socket=Socket[addr=/10.2.2.91,port=161,localport=60154],lastUse=Mon
Oct 19 19:07:52
CEST 2009]
[10/19/09 19:07:54:035 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage>
{10.2.2.91/161=SocketEntry[peerAddress=10.2.2.91/161,socket=Socket[addr=/10.2.2.91,port=161,localport=60154],lastUse=Mon
Oct
19 19:07:52 CEST 2009]}
[10/19/09 19:07:54:037 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<processPending> Registering for write:
SocketEntry[peerAddress=10.2.2.91/161,socket=Socket[addr=/10.2.2.91,port=161,localport=60154],lastUse=Mon
Oct 19 19:07:52
CEST 2009]
[10/19/09 19:07:54:039 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key
is writable
[10/19/09 19:07:54:042 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<writeMessage> Send message with length 129 to 10.2.2.91/161:
30:7f:02:01:03:30:11:02:04:60:08:97:5d:02:03:00:ff:ff:04:01:05:02:01:03:04:33:30:31:04:0d:80:00:1f:88:80:e7:25:00:00:e1:03:4a
:4a:02:01:00:02:01:02:04:0a:75:72:77:53:65:72:6d:65:70:61:04:0c:a3:11:89:a0:1b:cd:47:ae:fe:77:92:27:04:00:30:32:04:0d:80:00:1
f:88:80:e7:25:00:00:e1:03:4a:4a:04:00:a0:1f:02:04:0e:5c:17:6d: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
[10/19/09 19:07:54:044 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key
is readable
[10/19/09 19:07:54:045 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key
is reading
[10/19/09 19:07:54:047 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<readMessage> Reading header 6 bytes from 10.2.2.91/161
[10/19/09 19:07:54:049 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<readMessage> Message length is
org.snmp4j.transport.MessageLength[headerLength=3,payloadLength=131]
[10/19/09 19:07:54:051 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<dispatchMessage> Received message from 10.2.2.91/161 with length 134:
30:81:83:02:01:03:30:12:02:04:60:08:97:5d:02:04:7f:ff:ff:ff:04:01:01:02:01:03:04:36:30:34:04:0d:80:00:1f:88:80:e7:25:00:00:e1
:03:4a:4a:02:02:02:01:02:03:04:34:6e:04:0a:75:72:77:53:65:72:6d:65:70:61:04:0c:da:43:76:50:fb:4c:b5:61:28:b6:e9:be:04:00:30:3
2:04:0d:80:00:1f:88:80:e7:25:00:00:e1:03:4a:4a:04:00:a8:1f:02:04:0e:5c:17:6d:02:01:00:02:01:00:30:11:30:0f:06:0a:2b:06:01:06:
03:0f:01:01:02:00:41:01:05
[10/19/09 19:07:54:053 CEST] 0000002f SystemOut O
org.snmp4j.mp.MPv3$HeaderData <decodeBER> SNMPv3 header decoded:
msgId=1611175773, msgMaxSize=2147483647, msgFlags=01, secModel=3
[10/19/09 19:07:54:056 CEST] 0000002f SystemOut O
org.snmp4j.security.USM <getUser>
getUser(engineID=80:00:1f:88:80:e7:25:00:00:e1:03:4a:4a,
securityName=urwxxxxxxx)
[10/19/09 19:07:54:059 CEST] 0000002f SystemOut O
org.snmp4j.security.UsmTimeTable <checkTime> CheckTime: time ok (non
authorative)
[10/19/09 19:07:54:062 CEST] 0000002f SystemOut O
org.snmp4j.mp.MPv3$Cache <popEntry> Removed cache entry:
StateReference[msgID=1611175773,pduHandle=PduHandle[240916333],securityEngineID=80:00:1f:88:80:e7:25:00:00:e1:03:4a:4a,securi
tyModel=org.snmp4j.security.USM at 3f2c3f2c,securityName=urwxxxxxxx,securityLevel=2,contextEngineID=80:00:1f:88:80:e7:25:00:00:e
1:03:4a:4a,contextName=]
[10/19/09 19:07:54:063 CEST] 0000002f SystemOut O org.snmp4j.mp.MPv3
<prepareDataElements> RFC3412 §7.2.10 - Received PDU
(msgID=1611175773) is a response or an internal class message.
PduHandle.transactionID = 240916333
[10/19/09 19:07:54:065 CEST] 0000002f SystemOut O org.snmp4j.mp.MPv3
<prepareDataElements> MPv3 finished
[10/19/09 19:07:54:067 CEST] 0000002f SystemOut O
org.snmp4j.Snmp$ReportProcessor <processReport> Searching pending
request with handlePduHandle[240916333]
[10/19/09 19:07:54:068 CEST] 0000002f SystemOut O
org.snmp4j.Snmp$ReportProcessor <processReport> Send new request after
report.
[10/19/09 19:07:54:071 CEST] 0000002f SystemOut O
org.snmp4j.security.USM <getUser>
getUser(engineID=80:00:1f:88:80:e7:25:00:00:e1:03:4a:4a,
securityName=urwxxxxxxx)
[10/19/09 19:07:54:073 CEST] 0000002f SystemOut O
org.snmp4j.security.USM <generateResponseMessage> RFC3414 §3.1.4.b
Outgoing message is not encrypted
[10/19/09 19:07:54:078 CEST] 0000002f SystemOut O
org.snmp4j.mp.MPv3$Cache <addEntry> Adding cache entry:
StateReference[msgID=1611175774,pduHandle=PduHandle[240916333],securityEngineID=80:00:1f:88:80:e7:25:00:00:e1:03:4a:4a,securi
tyModel=org.snmp4j.security.USM at 3f2c3f2c,securityName=urwxxxxxxx,securityLevel=2,contextEngineID=80:00:1f:88:80:e7:25:00:00:e
1:03:4a:4a,contextName=]
[10/19/09 19:07:54:080 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage> Looking up connection for destination '10.2.2.91/161'
returned:
SocketEntry[peerAddress=10.2.2.91/161,socket=Socket[addr=/10.2.2.91,port=161,localport=60154],lastUse=Mon
Oct 19 19:07:54
CEST 2009]
[10/19/09 19:07:54:082 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<sendMessage>
{10.2.2.91/161=SocketEntry[peerAddress=10.2.2.91/161,socket=Socket[addr=/10.2.2.91,port=161,localport=60154],lastUse=Mon
Oct
19 19:07:54 CEST 2009]}
[10/19/09 19:07:54:084 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<processPending> Registering for write:
SocketEntry[peerAddress=10.2.2.91/161,socket=Socket[addr=/10.2.2.91,port=161,localport=60154],lastUse=Mon
Oct 19 19:07:54
CEST 2009]
[10/19/09 19:07:54:085 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key
is writable
[10/19/09 19:07:54:089 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<writeMessage> Send message with length 133 to 10.2.2.91/161:
30:81:82:02:01:03:30:11:02:04:60:08:97:5e:02:03:00:ff:ff:04:01:05:02:01:03:04:36:30:34:04:0d:80:00:1f:88:80:e7:25:00:00:e1:03
:4a:4a:02:02:02:01:02:03:04:34:6e:04:0a:75:72:77:53:65:72:6d:65:70:61:04:0c:a8:ce:85:91:e5:92:e5:fc:f0:02:b6:74:04:00:30:32:0
4:0d:80:00:1f:88:80:e7:25:00:00:e1:03:4a:4a:04:00:a0:1f:02:04:0e:5c:17:6d: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
[10/19/09 19:07:54:114 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key
is readable
[10/19/09 19:07:54:115 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key
is reading
[10/19/09 19:07:54:116 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<readMessage> Reading header 6 bytes from 10.2.2.91/161
[10/19/09 19:07:54:118 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<readMessage> Message length is
org.snmp4j.transport.MessageLength[headerLength=3,payloadLength=148]
[10/19/09 19:07:54:121 CEST] 0000002f SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
<dispatchMessage> Received message from 10.2.2.91/161 with length 151:
30:81:94:02:01:03:30:12:02:04:60:08:97:5e:02:04:7f:ff:ff:ff:04:01:01:02:01:03:04:36:30:34:04:0d:80:00:1f:88:80:e7:25:00:00:e1
:03:4a:4a:02:02:02:01:02:03:04:34:6e:04:0a:75:72:77:53:65:72:6d:65:70:61:04:0c:98:98:a1:60:1e:c3:f4:a4:e8:98:96:bf:04:00:30:4
3:04:0d:80:00:1f:88:80:e7:25:00:00:e1:03:4a:4a:04:00:a2:30:02:04:0e:5c:17:6d: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:38:31:2d:38:38:38:38:2d:38:38:20:30:30:38:31
[10/19/09 19:07:54:122 CEST] 0000002f SystemOut O
org.snmp4j.mp.MPv3$HeaderData <decodeBER> SNMPv3 header decoded:
msgId=1611175774, msgMaxSize=2147483647, msgFlags=01, secModel=3
[10/19/09 19:07:54:125 CEST] 0000002f SystemOut O
org.snmp4j.security.USM <getUser>
getUser(engineID=80:00:1f:88:80:e7:25:00:00:e1:03:4a:4a,
securityName=urwxxxxxxx)
[10/19/09 19:07:54:127 CEST] 0000002f SystemOut O
org.snmp4j.security.UsmTimeTable <checkTime> CheckTime: time ok (non
authorative)
[10/19/09 19:07:54:130 CEST] 0000002f SystemOut O
org.snmp4j.mp.MPv3$Cache <popEntry> Removed cache entry:
StateReference[msgID=1611175774,pduHandle=PduHandle[240916333],securityEngineID=80:00:1f:88:80:e7:25:00:00:e1:03:4a:4a,securi
tyModel=org.snmp4j.security.USM at 3f2c3f2c,securityName=urwxxxxxxx,securityLevel=2,contextEngineID=80:00:1f:88:80:e7:25:00:00:e
1:03:4a:4a,contextName=]
[10/19/09 19:07:54:131 CEST] 0000002f SystemOut O org.snmp4j.mp.MPv3
<prepareDataElements> RFC3412 §7.2.10 - Received PDU
(msgID=1611175774) is a response or an internal class message.
PduHandle.transactionID = 240916333
[10/19/09 19:07:54:133 CEST] 0000002f SystemOut O org.snmp4j.mp.MPv3
<prepareDataElements> MPv3 finished
[10/19/09 19:07:54:134 CEST] 0000002f SystemOut O org.snmp4j.Snmp
<processPdu> Looking up pending request with handle
PduHandle[240916333]
[10/19/09 19:07:54:142 CEST] 0000002b SystemOut O org.snmp4j.Snmp
<send> Removed pending request with handle:
PduHandle[240916333]
[10/19/09 19:07:54:155 CEST] 0000002b SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping <close> Closing socket
for peer address 10.2.2.91/161
[10/19/09 19:08:52:654 CEST] 00000031 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run>
Scheduling 1463
[10/19/09 19:08:54:122 CEST] 00000031 SystemOut O
org.snmp4j.transport.DefaultTcpTransportMapping$SocketTimeout <run>
Socket has not been used for 60006 micro seconds, closing it
More information about the SNMP4J
mailing list