[SNMP4J] TcpTransportMapping.close(address) hanging in AIX
Frank Fock
fock at agentpp.com
Wed Oct 21 20:16:28 CEST 2009
Hi Brice,
Does it still hang? From the log everything
seems to be OK until the last log message.
Normally, another log message about the successful
closing of the socket should follow.
From the log I conclude, that this must be an
issue with the AIX JDK. There is no (potentially)
blocking operation after the last log message in
SNMP4J left. Thus, I think the hang is caused
by the AIX JDK.
See for example:
http://www-01.ibm.com/support/docview.wss?uid=swg1IZ22905
From what I read in the Internet, the problem with
Socket.close() does only occur with JDK 1.6, not with
JDK 1.5.
Regards,
Frank
Brice Fines wrote:
> Hi,
> (sorry I had no time to try it yesterday).
> I downloaded snapshot of 21 October 2009.
> Here are the logs.
> Regards.
>
> [10/21/09 19:00:33:097 CEST] 00000034 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/21/09 19:00:33:104 CEST] 00000034 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/21/09 19:00:33:109 CEST] 00000034 SystemOut O
> org.snmp4j.security.USM <generateResponseMessage> RFC3414 §3.1.4.b
> Outgoing message is not encrypted
> [10/21/09 19:00:33:117 CEST] 00000034 SystemOut O
> org.snmp4j.mp.MPv3$Cache <addEntry> Adding cache entry:
> StateReference[msgID=807915147,pduHandle=PduHandle[614437318],securityEngineID=80:00:1f:88:80:e7:25:00:00:e1:03:4a:4a,securityModel=org.snmp4j.security.USM at 79d279d2,securityName=urwxxxxxxx,securityLevel=2,contextEngineID=80:00:1f:88:80:e7:25:00:00:e1:03:4a:4a,contextName=]
> [10/21/09 19:00:33:128 CEST] 00000034 SystemOut O
> org.snmp4j.Snmp$PendingRequest <pduHandleAssigned> Running pending sync
> request with handle PduHandle[614437318] and retry count left 0
> [10/21/09 19:00:33:133 CEST] 00000034 SystemOut O
> org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
> Looking up connection for destination '10.2.2.91/161' returned: null
> [10/21/09 19:00:33:138 CEST] 00000034 SystemOut O
> org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
> {}
> [10/21/09 19:00:33:142 CEST] 00000034 SystemOut O
> org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
> Socket for address '10.2.2.91/161' is closed, opening it...
> [10/21/09 19:00:33:149 CEST] 00000034 SystemOut O
> org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <sendMessage>
> Trying to connect to 10.2.2.91/161
> [10/21/09 19:00:33:150 CEST] 00000038 SystemOut O
> org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
> <processPending> Registering for connect:
> SocketEntry[peerAddress=10.2.2.91/161,socket=Socket[unconnected],lastUse=Wed
> Oct 21 19:00:33 CEST 2009]
> [10/21/09 19:00:33:152 CEST] 00000038 SystemOut O
> org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key is
> connectable
> [10/21/09 19:00:33:153 CEST] 00000038 SystemOut O
> org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
> <connectChannel> Connected to 10.2.2.91/161
> [10/21/09 19:00:33:158 CEST] 0000003a SystemOut O
> org.snmp4j.transport.DefaultTcpTransportMapping <close> Socket to
> 10.2.2.66/161 closed
> [10/21/09 19:00:33:162 CEST] 00000038 SystemOut O
> org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread
> <connectChannel> Fire connected event for null
> [10/21/09 19:00:33:164 CEST] 00000038 SystemOut O
> org.snmp4j.transport.TcpTransportMapping <fireConnectionStateChanged>
> Firing transport state event:
> org.snmp4j.transport.TransportStateEvent[source=org.snmp4j.transport.DefaultTcpTransportMapping at 56225622,peerAddress=10.2.2.91/161,newState=1,cancelled=false,causingException=null]
> [10/21/09 19:00:33:165 CEST] 00000038 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=39578],lastUse=Wed
> Oct 21 19:00:33 CEST 2009]
> [10/21/09 19:00:33:167 CEST] 00000038 SystemOut O
> org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key is
> writable
> [10/21/09 19:00:33:169 CEST] 00000038 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:30:27:ce:8b: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:06:d5:b5:04:0a:75:72:77:53:65:72:6d:65:70:61:04:0c:f6:69:16:33:e5:03:08:a7:12:e6:2b:a6:04:00:30:32:04:0d:80:00:1f:88:80:e7:25:00:00:e1:03:4a:4a:04:00:a0:1f:02:04:24:9f:91:c6: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/21/09 19:00:33:182 CEST] 00000038 SystemOut O
> org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key is
> readable
> [10/21/09 19:00:33:183 CEST] 00000038 SystemOut O
> org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <run> Key is
> reading
> [10/21/09 19:00:33:185 CEST] 00000038 SystemOut O
> org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <readMessage>
> Reading header 6 bytes from 10.2.2.91/161
> [10/21/09 19:00:33:186 CEST] 00000038 SystemOut O
> org.snmp4j.transport.DefaultTcpTransportMapping$ServerThread <readMessage>
> Message length is
> org.snmp4j.transport.MessageLength[headerLength=3,payloadLength=148]
> [10/21/09 19:00:33:188 CEST] 00000038 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:30:27:ce:8b: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:06:d5:b5:04:0a:75:72:77:53:65:72:6d:65:70:61:04:0c:52:e9:5c:ef:e5:af:a8:73:e0:a0:e7:41:04:00:30:43:04:0d:80:00:1f:88:80:e7:25:00:00:e1:03:4a:4a:04:00:a2:30:02:04:24:9f:91:c6: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/21/09 19:00:33:190 CEST] 00000038 SystemOut O
> org.snmp4j.mp.MPv3$HeaderData <decodeBER> SNMPv3 header decoded:
> msgId=807915147, msgMaxSize=2147483647, msgFlags=01, secModel=3
> [10/21/09 19:00:33:195 CEST] 00000038 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/21/09 19:00:33:201 CEST] 00000038 SystemOut O
> org.snmp4j.security.UsmTimeTable <checkTime> CheckTime: time ok (non
> authorative)
> [10/21/09 19:00:33:213 CEST] 00000038 SystemOut O
> org.snmp4j.mp.MPv3$Cache <popEntry> Removed cache entry:
> StateReference[msgID=807915147,pduHandle=PduHandle[614437318],securityEngineID=80:00:1f:88:80:e7:25:00:00:e1:03:4a:4a,securityModel=org.snmp4j.security.USM at 79d279d2,securityName=urwxxxxxxx,securityLevel=2,contextEngineID=80:00:1f:88:80:e7:25:00:00:e1:03:4a:4a,contextName=]
> [10/21/09 19:00:33:214 CEST] 00000038 SystemOut O org.snmp4j.mp.MPv3
> <prepareDataElements> RFC3412 §7.2.10 - Received PDU (msgID=807915147) is
> a response or an internal class message. PduHandle.transactionID =
> 614437318
> [10/21/09 19:00:33:224 CEST] 00000038 SystemOut O org.snmp4j.mp.MPv3
> <prepareDataElements> MPv3 finished
> [10/21/09 19:00:33:225 CEST] 00000038 SystemOut O org.snmp4j.Snmp
> <processPdu> Looking up pending request with handle PduHandle[614437318]
> [10/21/09 19:00:33:243 CEST] 00000034 SystemOut O org.snmp4j.Snmp
> <send> Removed pending request with handle: PduHandle[614437318]
> [10/21/09 19:00:33:272 CEST] 00000034 SystemOut O
> org.snmp4j.transport.DefaultTcpTransportMapping <close> Closing socket for
> peer address 10.2.2.91/161
> _______________________________________________
> SNMP4J mailing list
> SNMP4J at agentpp.org
> http://lists.agentpp.org/mailman/listinfo/snmp4j
--
AGENT++
http://www.agentpp.com
http://www.snmp4j.com
http://www.mibexplorer.com
http://www.mibdesigner.com
More information about the SNMP4J
mailing list