[SNMP4J] help - possible thread-unsafe code in snmp4j
Ali, Syed F
Syed.Ali02 at ca.com
Mon Feb 4 16:57:25 CET 2013
Hi Frank, thanks for the quick reply.
So if the agent sends back 3 identical REPORTs for example at the same time. Assume Snmp class is processing them concurrently by using a MultithreadMessageDispatcher, then the following could happen:
Suppose the following threads reach line 1314 at the same time:
Thread 1 reaches line 1314 if (request.requestStatus < request.maxRequestStatus)
Thread 2 reaches line 1314 and also checks request.requestStatus < 2
Thread 3 reaches line 1314 and also checks request.requestStatus < 2
Thread 1: Since Request.requestStatus < 2 => thread 1 goes through and sets resend=true, then goes through until line 1340 and and sends out the message.
Thread 2: Checks Request.requestStatus < 2 => since the value of requestStatus was not incremented atomically, thread 2 will see the value as 0, and set resend = true. Then when it reaches line 1340, it will resend the GET request.
Thread 3: Checks Request.requestStatus < 2 => since the value of requestStatus was not incremented atomically, thread 2 will see the value as 0, and set resend = true. Then when it reaches line 1340, it will resend the GET request.
By the logic above, if an agent is buggy or sends N REPORTs with the same handle, then this code might be susceptible to sending / retrying back N number of requests where N is > request.maxRequestStatus.
This may be a theoretical case, but I only theorized this because we saw a wireshark trace where 60 identical GETs were issued in 20 milliseconds.
Here is a snippet of the wireshark trace:
No. Time Source Destination Protocol Length Info
3605 25.115655 10.194.33.80 10.194.30.193 SNMP 173 get-request SNMPv2-SMI::enterprises.9.9.305.1.1.2.0
Frame 3605: 173 bytes on wire (1384 bits), 173 bytes captured (1384 bits)
WTAP_ENCAP: 1
Arrival Time: Jan 16, 2013 12:23:29.392196000 Eastern Standard Time
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1358357009.392196000 seconds
[Time delta from previous captured frame: 0.000010000 seconds]
[Time delta from previous displayed frame: 0.000010000 seconds]
[Time since reference or first frame: 25.115655000 seconds]
Frame Number: 3605
Frame Length: 173 bytes (1384 bits)
Capture Length: 173 bytes (1384 bits)
[Frame is marked: True]
[Frame is ignored: False]
[Protocols in frame: eth:ip:udp:snmp]
[Coloring Rule Name: UDP]
[Coloring Rule String: udp]
Ethernet II, Src: Cisco_1e:6c:40 (00:19:a9:1e:6c:40), Dst: Cisco_79:df:41 (00:22:55:79:df:41)
Destination: Cisco_79:df:41 (00:22:55:79:df:41)
Address: Cisco_79:df:41 (00:22:55:79:df:41)
.... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
.... ...0 .... .... .... .... = IG bit: Individual address (unicast)
Source: Cisco_1e:6c:40 (00:19:a9:1e:6c:40)
Address: Cisco_1e:6c:40 (00:19:a9:1e:6c:40)
.... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
.... ...0 .... .... .... .... = IG bit: Individual address (unicast)
Type: IP (0x0800)
Internet Protocol Version 4, Src: 10.194.33.80 (10.194.33.80), Dst: 10.194.30.193 (10.194.30.193)
User Datagram Protocol, Src Port: 39417 (39417), Dst Port: snmp (161)
Source port: 39417 (39417)
Destination port: snmp (161)
Length: 139
Checksum: 0xd96c [validation disabled]
[Good Checksum: False]
[Bad Checksum: False]
Simple Network Management Protocol
msgVersion: snmpv3 (3)
msgGlobalData
msgID: 745338668
msgMaxSize: 65535
msgFlags: 05
.... .1.. = Reportable: Set
.... ..0. = Encrypted: Not set
.... ...1 = Authenticated: Set
msgSecurityModel: USM (3)
msgAuthoritativeEngineID: 8000000903c0626bae0880
1... .... = Engine ID Conformance: RFC3411 (SNMPv3)
Engine Enterprise ID: ciscoSystems (9)
Engine ID Format: MAC address (3)
Engine ID Data: MAC address: Cisco_ae:08:80 (c0:62:6b:ae:08:80)
msgAuthoritativeEngineBoots: 14
msgAuthoritativeEngineTime: 5971516
msgUserName: blah
msgAuthenticationParameters: 5913acc5dc2c77534ec09eb8
msgPrivacyParameters: <MISSING>
msgData: plaintext (0)
plaintext
contextEngineID: 8000000903c0626bae0880
1... .... = Engine ID Conformance: RFC3411 (SNMPv3)
Engine Enterprise ID: ciscoSystems (9)
Engine ID Format: MAC address (3)
Engine ID Data: MAC address: Cisco_ae:08:80 (c0:62:6b:ae:08:80)
contextName:
data: get-request (0)
get-request
request-id: 87745250
error-status: noError (0)
error-index: 50
variable-bindings: 1 item
SNMPv2-SMI::enterprises.9.9.305.1.1.2.0 (1.3.6.1.4.1.9.9.305.1.1.2.0): Value (Null)
Object Name: 1.3.6.1.4.1.9.9.305.1.1.2.0 (SNMPv2-SMI::enterprises.9.9.305.1.1.2.0)
Value (Null)
No. Time Source Destination Protocol Length Info
3606 25.115950 10.194.33.80 10.194.30.193 SNMP 173 get-request SNMPv2-SMI::enterprises.9.9.305.1.1.2.0
Frame 3606: 173 bytes on wire (1384 bits), 173 bytes captured (1384 bits)
WTAP_ENCAP: 1
Arrival Time: Jan 16, 2013 12:23:29.392491000 Eastern Standard Time
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1358357009.392491000 seconds
[Time delta from previous captured frame: 0.000295000 seconds]
[Time delta from previous displayed frame: 0.000295000 seconds]
[Time since reference or first frame: 25.115950000 seconds]
Frame Number: 3606
Frame Length: 173 bytes (1384 bits)
Capture Length: 173 bytes (1384 bits)
[Frame is marked: True]
[Frame is ignored: False]
[Protocols in frame: eth:ip:udp:snmp]
[Coloring Rule Name: UDP]
[Coloring Rule String: udp]
Ethernet II, Src: Cisco_79:df:41 (00:22:55:79:df:41), Dst: Cisco_1e:6c:40 (00:19:a9:1e:6c:40)
Destination: Cisco_1e:6c:40 (00:19:a9:1e:6c:40)
Address: Cisco_1e:6c:40 (00:19:a9:1e:6c:40)
.... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
.... ...0 .... .... .... .... = IG bit: Individual address (unicast)
Source: Cisco_79:df:41 (00:22:55:79:df:41)
Address: Cisco_79:df:41 (00:22:55:79:df:41)
.... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
.... ...0 .... .... .... .... = IG bit: Individual address (unicast)
Type: IP (0x0800)
Internet Protocol Version 4, Src: 10.194.33.80 (10.194.33.80), Dst: 10.194.30.193 (10.194.30.193)
User Datagram Protocol, Src Port: 39417 (39417), Dst Port: snmp (161)
Source port: 39417 (39417)
Destination port: snmp (161)
Length: 139
Checksum: 0xd96c [validation disabled]
[Good Checksum: False]
[Bad Checksum: False]
Simple Network Management Protocol
msgVersion: snmpv3 (3)
msgGlobalData
msgID: 745338668
msgMaxSize: 65535
msgFlags: 05
.... .1.. = Reportable: Set
.... ..0. = Encrypted: Not set
.... ...1 = Authenticated: Set
msgSecurityModel: USM (3)
msgAuthoritativeEngineID: 8000000903c0626bae0880
1... .... = Engine ID Conformance: RFC3411 (SNMPv3)
Engine Enterprise ID: ciscoSystems (9)
Engine ID Format: MAC address (3)
Engine ID Data: MAC address: Cisco_ae:08:80 (c0:62:6b:ae:08:80)
msgAuthoritativeEngineBoots: 14
msgAuthoritativeEngineTime: 5971516
msgUserName: blah
msgAuthenticationParameters: 5913acc5dc2c77534ec09eb8
msgPrivacyParameters: <MISSING>
msgData: plaintext (0)
plaintext
contextEngineID: 8000000903c0626bae0880
1... .... = Engine ID Conformance: RFC3411 (SNMPv3)
Engine Enterprise ID: ciscoSystems (9)
Engine ID Format: MAC address (3)
Engine ID Data: MAC address: Cisco_ae:08:80 (c0:62:6b:ae:08:80)
contextName:
data: get-request (0)
get-request
request-id: 87745250
error-status: noError (0)
error-index: 50
variable-bindings: 1 item
SNMPv2-SMI::enterprises.9.9.305.1.1.2.0 (1.3.6.1.4.1.9.9.305.1.1.2.0): Value (Null)
Object Name: 1.3.6.1.4.1.9.9.305.1.1.2.0 (SNMPv2-SMI::enterprises.9.9.305.1.1.2.0)
Value (Null)
No. Time Source Destination Protocol Length Info
3607 25.115960 10.194.33.80 10.194.30.193 SNMP 173 get-request SNMPv2-SMI::enterprises.9.9.305.1.1.2.0
Frame 3607: 173 bytes on wire (1384 bits), 173 bytes captured (1384 bits)
WTAP_ENCAP: 1
Arrival Time: Jan 16, 2013 12:23:29.392501000 Eastern Standard Time
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1358357009.392501000 seconds
[Time delta from previous captured frame: 0.000010000 seconds]
[Time delta from previous displayed frame: 0.000010000 seconds]
[Time since reference or first frame: 25.115960000 seconds]
Frame Number: 3607
Frame Length: 173 bytes (1384 bits)
Capture Length: 173 bytes (1384 bits)
[Frame is marked: True]
[Frame is ignored: False]
[Protocols in frame: eth:ip:udp:snmp]
[Coloring Rule Name: UDP]
[Coloring Rule String: udp]
Ethernet II, Src: Cisco_1e:6c:40 (00:19:a9:1e:6c:40), Dst: Cisco_79:df:41 (00:22:55:79:df:41)
Destination: Cisco_79:df:41 (00:22:55:79:df:41)
Address: Cisco_79:df:41 (00:22:55:79:df:41)
.... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
.... ...0 .... .... .... .... = IG bit: Individual address (unicast)
Source: Cisco_1e:6c:40 (00:19:a9:1e:6c:40)
Address: Cisco_1e:6c:40 (00:19:a9:1e:6c:40)
.... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
.... ...0 .... .... .... .... = IG bit: Individual address (unicast)
Type: IP (0x0800)
Internet Protocol Version 4, Src: 10.194.33.80 (10.194.33.80), Dst: 10.194.30.193 (10.194.30.193)
User Datagram Protocol, Src Port: 39417 (39417), Dst Port: snmp (161)
Source port: 39417 (39417)
Destination port: snmp (161)
Length: 139
Checksum: 0xd96c [validation disabled]
[Good Checksum: False]
[Bad Checksum: False]
Simple Network Management Protocol
msgVersion: snmpv3 (3)
msgGlobalData
msgID: 745338668
msgMaxSize: 65535
msgFlags: 05
.... .1.. = Reportable: Set
.... ..0. = Encrypted: Not set
.... ...1 = Authenticated: Set
msgSecurityModel: USM (3)
msgAuthoritativeEngineID: 8000000903c0626bae0880
1... .... = Engine ID Conformance: RFC3411 (SNMPv3)
Engine Enterprise ID: ciscoSystems (9)
Engine ID Format: MAC address (3)
Engine ID Data: MAC address: Cisco_ae:08:80 (c0:62:6b:ae:08:80)
msgAuthoritativeEngineBoots: 14
msgAuthoritativeEngineTime: 5971516
msgUserName: blah
msgAuthenticationParameters: 5913acc5dc2c77534ec09eb8
msgPrivacyParameters: <MISSING>
msgData: plaintext (0)
plaintext
contextEngineID: 8000000903c0626bae0880
1... .... = Engine ID Conformance: RFC3411 (SNMPv3)
Engine Enterprise ID: ciscoSystems (9)
Engine ID Format: MAC address (3)
Engine ID Data: MAC address: Cisco_ae:08:80 (c0:62:6b:ae:08:80)
contextName:
data: get-request (0)
get-request
request-id: 87745250
error-status: noError (0)
error-index: 50
variable-bindings: 1 item
SNMPv2-SMI::enterprises.9.9.305.1.1.2.0 (1.3.6.1.4.1.9.9.305.1.1.2.0): Value (Null)
Object Name: 1.3.6.1.4.1.9.9.305.1.1.2.0 (SNMPv2-SMI::enterprises.9.9.305.1.1.2.0)
Value (Null)
No. Time Source Destination Protocol Length Info
3608 25.116117 10.194.33.80 10.194.30.193 SNMP 173 get-request SNMPv2-SMI::enterprises.9.9.305.1.1.2.0
Frame 3608: 173 bytes on wire (1384 bits), 173 bytes captured (1384 bits)
WTAP_ENCAP: 1
Arrival Time: Jan 16, 2013 12:23:29.392658000 Eastern Standard Time
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1358357009.392658000 seconds
[Time delta from previous captured frame: 0.000157000 seconds]
[Time delta from previous displayed frame: 0.000157000 seconds]
[Time since reference or first frame: 25.116117000 seconds]
Frame Number: 3608
Frame Length: 173 bytes (1384 bits)
Capture Length: 173 bytes (1384 bits)
[Frame is marked: True]
[Frame is ignored: False]
[Protocols in frame: eth:ip:udp:snmp]
[Coloring Rule Name: UDP]
[Coloring Rule String: udp]
Ethernet II, Src: Cisco_79:df:41 (00:22:55:79:df:41), Dst: Cisco_1e:6c:40 (00:19:a9:1e:6c:40)
Destination: Cisco_1e:6c:40 (00:19:a9:1e:6c:40)
Address: Cisco_1e:6c:40 (00:19:a9:1e:6c:40)
.... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
.... ...0 .... .... .... .... = IG bit: Individual address (unicast)
Source: Cisco_79:df:41 (00:22:55:79:df:41)
Address: Cisco_79:df:41 (00:22:55:79:df:41)
.... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
.... ...0 .... .... .... .... = IG bit: Individual address (unicast)
Type: IP (0x0800)
Internet Protocol Version 4, Src: 10.194.33.80 (10.194.33.80), Dst: 10.194.30.193 (10.194.30.193)
User Datagram Protocol, Src Port: 39417 (39417), Dst Port: snmp (161)
Source port: 39417 (39417)
Destination port: snmp (161)
Length: 139
Checksum: 0xd96c [validation disabled]
[Good Checksum: False]
[Bad Checksum: False]
Simple Network Management Protocol
msgVersion: snmpv3 (3)
msgGlobalData
msgID: 745338668
msgMaxSize: 65535
msgFlags: 05
.... .1.. = Reportable: Set
.... ..0. = Encrypted: Not set
.... ...1 = Authenticated: Set
msgSecurityModel: USM (3)
msgAuthoritativeEngineID: 8000000903c0626bae0880
1... .... = Engine ID Conformance: RFC3411 (SNMPv3)
Engine Enterprise ID: ciscoSystems (9)
Engine ID Format: MAC address (3)
Engine ID Data: MAC address: Cisco_ae:08:80 (c0:62:6b:ae:08:80)
msgAuthoritativeEngineBoots: 14
msgAuthoritativeEngineTime: 5971516
msgUserName: blah
msgAuthenticationParameters: 5913acc5dc2c77534ec09eb8
msgPrivacyParameters: <MISSING>
msgData: plaintext (0)
plaintext
contextEngineID: 8000000903c0626bae0880
1... .... = Engine ID Conformance: RFC3411 (SNMPv3)
Engine Enterprise ID: ciscoSystems (9)
Engine ID Format: MAC address (3)
Engine ID Data: MAC address: Cisco_ae:08:80 (c0:62:6b:ae:08:80)
contextName:
data: get-request (0)
get-request
request-id: 87745250
error-status: noError (0)
error-index: 50
variable-bindings: 1 item
SNMPv2-SMI::enterprises.9.9.305.1.1.2.0 (1.3.6.1.4.1.9.9.305.1.1.2.0): Value (Null)
Object Name: 1.3.6.1.4.1.9.9.305.1.1.2.0 (SNMPv2-SMI::enterprises.9.9.305.1.1.2.0)
Value (Null)
No. Time Source Destination Protocol Length Info
3609 25.116126 10.194.33.80 10.194.30.193 SNMP 173 get-request SNMPv2-SMI::enterprises.9.9.305.1.1.2.0
Frame 3609: 173 bytes on wire (1384 bits), 173 bytes captured (1384 bits)
WTAP_ENCAP: 1
Arrival Time: Jan 16, 2013 12:23:29.392667000 Eastern Standard Time
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1358357009.392667000 seconds
[Time delta from previous captured frame: 0.000009000 seconds]
[Time delta from previous displayed frame: 0.000009000 seconds]
[Time since reference or first frame: 25.116126000 seconds]
Frame Number: 3609
Frame Length: 173 bytes (1384 bits)
Capture Length: 173 bytes (1384 bits)
[Frame is marked: True]
[Frame is ignored: False]
[Protocols in frame: eth:ip:udp:snmp]
[Coloring Rule Name: UDP]
[Coloring Rule String: udp]
Ethernet II, Src: Cisco_1e:6c:40 (00:19:a9:1e:6c:40), Dst: Cisco_79:df:41 (00:22:55:79:df:41)
Destination: Cisco_79:df:41 (00:22:55:79:df:41)
Address: Cisco_79:df:41 (00:22:55:79:df:41)
.... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
.... ...0 .... .... .... .... = IG bit: Individual address (unicast)
Source: Cisco_1e:6c:40 (00:19:a9:1e:6c:40)
Address: Cisco_1e:6c:40 (00:19:a9:1e:6c:40)
.... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
.... ...0 .... .... .... .... = IG bit: Individual address (unicast)
Type: IP (0x0800)
Internet Protocol Version 4, Src: 10.194.33.80 (10.194.33.80), Dst: 10.194.30.193 (10.194.30.193)
User Datagram Protocol, Src Port: 39417 (39417), Dst Port: snmp (161)
Source port: 39417 (39417)
Destination port: snmp (161)
Length: 139
Checksum: 0xd96c [validation disabled]
[Good Checksum: False]
[Bad Checksum: False]
Simple Network Management Protocol
msgVersion: snmpv3 (3)
msgGlobalData
msgID: 745338668
msgMaxSize: 65535
msgFlags: 05
.... .1.. = Reportable: Set
.... ..0. = Encrypted: Not set
.... ...1 = Authenticated: Set
msgSecurityModel: USM (3)
msgAuthoritativeEngineID: 8000000903c0626bae0880
1... .... = Engine ID Conformance: RFC3411 (SNMPv3)
Engine Enterprise ID: ciscoSystems (9)
Engine ID Format: MAC address (3)
Engine ID Data: MAC address: Cisco_ae:08:80 (c0:62:6b:ae:08:80)
msgAuthoritativeEngineBoots: 14
msgAuthoritativeEngineTime: 5971516
msgUserName: blah
msgAuthenticationParameters: 5913acc5dc2c77534ec09eb8
msgPrivacyParameters: <MISSING>
msgData: plaintext (0)
plaintext
contextEngineID: 8000000903c0626bae0880
1... .... = Engine ID Conformance: RFC3411 (SNMPv3)
Engine Enterprise ID: ciscoSystems (9)
Engine ID Format: MAC address (3)
Engine ID Data: MAC address: Cisco_ae:08:80 (c0:62:6b:ae:08:80)
contextName:
data: get-request (0)
get-request
request-id: 87745250
error-status: noError (0)
error-index: 50
variable-bindings: 1 item
SNMPv2-SMI::enterprises.9.9.305.1.1.2.0 (1.3.6.1.4.1.9.9.305.1.1.2.0): Value (Null)
Object Name: 1.3.6.1.4.1.9.9.305.1.1.2.0 (SNMPv2-SMI::enterprises.9.9.305.1.1.2.0)
Value (Null)
Syed F. Ali
CA Technologies
Sr Software Engineer
Tel: +1 603 334 2111
Syed.Ali02 at ca.com
-----Original Message-----
From: Ali, Syed F
Sent: Friday, February 01, 2013 7:04 PM
To: snmp4j at agentpp.org
Subject: help - possible thread-unsafe code in snmp4j
Hi,
We use snmp4j in one of our applications and while tracking down an issue reported by our customer, I came across some code in snmp4j that I believe may be thread-unsafe and that MIGHT occasionally be causing a device to be flooded with too many GET requests.
Code snippet as follows
In org.snmp4j.Snmp.java, org.snmp4j.Snmp.ReportProcessor class
1294 public void processReport(PduHandle handle, CommandResponderEvent e) {
1295 PDU pdu = e.getPDU();
1296 logger.debug("Searching pending request with handle" + handle); ..
..
...
...
...
..
1313 boolean resend = false;
1314 if (request.requestStatus < request.maxRequestStatus) {
1315 switch (request.requestStatus) {
1316 case 0:
1317 if (SnmpConstants.usmStatsUnknownEngineIDs.equals(firstOID)) {
1318 resend = true;
1319 }
1320 else if (SnmpConstants.usmStatsNotInTimeWindows.equals(firstOID)) {
1321 request.requestStatus++;
1322 resend = true;
1323 }
1324 break;
1325 case 1:
1326 if (SnmpConstants.usmStatsNotInTimeWindows.equals(firstOID)) {
1327 resend = true;
1328 }
1329 break;
1330 }
1331 }
1332 // if legal report PDU received, then resend request
1333 if (resend) {
1334 logger.debug("Send new request after report.");
1335 request.requestStatus++;
1336 try {
1337 // We need no callback here because we already have an equivalent
1338 // handle registered.
1339 PduHandle resentHandle =
1340 sendMessage(request.pdu, request.target, e.getTransportMapping(),
1341 null);
1342 // make sure reference to handle is hold until request is finished,
1343 // because otherwise cache information may get lost (WeakHashMap)
1344 request.key = resentHandle;
1345 }
1346 catch (IOException iox) {
1347 logger.error("Failed to send message to " + request.target + ": " +
1348 iox.getMessage());
1349 return;
1350 }
1351 }
1352 else {
..
....
The value of the resend boolean is based on the value of requestStatus. But the use of request.requestStatus++ is not threadsafe in this method above - because
a) the ++ operation is not atomic on a primitive integer and
b) the value is read on one line and modified on another.
If multiple threads enter the processReport() method in order to process a report for the same request object, they may end up seeing the cached value of 0 over and over again and resending the request several times until the request.requestStatus object value finally hits a memory barrier and the real value is flushed.
Also, since the value of requestStatus is read first on line 1314, and then incremented either on line 1335, line 1321, if multiple threads got in here for the same request object, you wouldn't get atomic behavior.
The customer reported a scenario (and provided a wireshark capture to prove it) that showed the exact same SNMP GET request (with the same requestID) going out to a particular snmp device approximately 180 times in ~9 seconds. We are using timeout=3000 and retries = 2 - so we expect to see 3 requests in 9 seconds with the same request ID. So in the span of approximately 20 milliseconds, we see about 60 identical GET requests are being issued with the same requestID. I can provide the pcap file showing this behavior if necessary. Also, these GETs are interspersed with many REPORTs coming in from the device so this situation may have been induced by a bug on the agent - however I'm writing to check whether the code should protect itself from such agent bugs. Perhaps I am wrong and this code is synchronized somewhere at a higher layer so that a REPORT for a request with a particular handle can only be processed on a single thread at a time.
Thanks for any assistance / clarification in advance!
Syed F. Ali
More information about the SNMP4J
mailing list