Timeout at discovery

[kconnellTMU]

I understand there is no official support, is there an email list or community to post on ?
Been using Devmon 0.3.1-beta1 for years, installing v0.23.09, hit a speed bump.

[bonomani]

yes this is the place !

[kconnellTMU]

OK, awesome.

Building a new Xymon server on RHEL9 and Devmon 0.23.09.
( Current server is Xymon 4.3.28 with devmon 0.3.1-beta1 - have used Xymon/Devmon for over a decade).

New Server situation:
Xymon 4.3.30 on RHEL9.5 (Plow) & Devmon 0.23.09

Host has just one Devmon/SNMP Test defined:
Hosts.cfg file - Forced template (my "devmon tag" is snmp):
10.241.12.69 jr5520.ns # snmp:model(uptime;uptime)

Devmon restart/read:
|DEBUG|templates|32684| 235|Test 'uptime:uptime:uptime' loaded
|INFO |config |32684|2103|Discovered jr5520.ns as a uptime uptime

Devmon Log:
2024-12-14T15:14:04.435-0500|WARN |snmp |31205| 375|Fork:3 Device:jr5520.ns Try:1 Msg:Timeout at discovery stage:2. will retry until success
2024-12-14T15:14:09.482-0500|WARN |snmp |31205| 375|Fork:3 Device:jr5520.ns Try:2 Msg:Timeout at discovery stage:2. will retry until success
2024-12-14T15:14:14.527-0500|WARN |snmp |31205| 375|Fork:3 Device:jr5520.ns Try:3 Msg:Timeout at discovery stage:2. will retry until success
2024-12-14T15:14:19.576-0500|WARN |snmp |31205| 375|Fork:3 Device:jr5520.ns Try:4 Msg:Timeout at discovery stage:2. will retry until success
2024-12-14T15:14:24.611-0500|WARN |snmp |31205| 375|Fork:3 Device:jr5520.ns Try:5 Msg:Timeout at discovery stage:2. will retry until success
2024-12-14T15:14:29.639-0500|WARN |snmp |31205| 375|Fork:3 Device:jr5520.ns Try:6 Msg:Timeout at discovery stage:2. will retry until success
2024-12-14T15:14:29.639-0500|WARN |snmp |31205| 446|Device: jr5520.ns Try:6 Msg:snmp_try_maxcnt reached, snmp polling stops
2024-12-14T15:14:29.702-0500|WARN |snmp |31205| 216|No answer for oid:1.3.6.1.2.1.1.1.0 on device:jr5520.ns
2024-12-14T15:14:29.702-0500|WARN |snmp |31205| 216|No answer for oid:1.3.6.1.2.1.1.3.0 on device:jr5520.ns
2024-12-14T15:14:29.702-0500|WARN |snmp |31205| 245|Received 0/2 oid for device jr5520.ns

I also did a devmon host specific test (./devmon -p jr5720.ns=uptime -d):
|DEBUG|tests |44681| 590|Math transform on jr5520.ns/sysUpTimeSecs do not have valid dependencies: skipping
Is this because there was no answer for the SNMP poll ? (see below line)
|WARN |snmp |44809| 245|Received 0/2 oid for device jr5520.ns

|INFO |msg |44809| 48|Sending 1 messages to 'xymon://stdout' (msg is for status clear)

$ cat specs
vendor : uptime
model : uptime
snmpver : 2
sysdesc : uptimeonly

$ cat oids
sysUpTime : .1.3.6.1.2.1.1.3.0 : leaf
sysDescr : .1.3.6.1.2.1.1.1.0 : leaf

$ cat transforms
sysUpTimeSecs : MATH : {sysUpTime} / 100
UpTimeTxt : ELAPSED : {sysUpTimeSecs}

$ cat thresholds
sysUpTimeSecs : red : <900 : Device rebooted recently. System uptime: {UpTimeTxt}
sysUpTimeSecs : yellow : <1800 : Device rebooted recently. System uptime: {UpTimeTxt}
sysUpTimeSecs : green : : System uptime: {UpTimeTxt}

$ cat message
{sysUpTimeSecs.color}: Up for {UpTimeTxt}
{sysDescr}

Device answers fine (and always) from Xymon-server ("walk" is just a shortcut for 'snmpwalk -v2c -c '):
$ walk jr5520.ns 1.3.6.1.2.1.1.3.0
DISMAN-EVENT-MIB::sysUpTimeInstance = Timeticks: (1012779100) 117 days, 5:16:31.

$ walk jr5520.ns 1.3.6.1.2.1.1.1.0
SNMPv2-MIB::sysDescr.0 = STRING: 5520-12MW-36W-FabricEngine (8.10.5.0)

[bonomani]

Thank you for the excellent report.
The error at stage 2 (discovering the number of OIDs that can be requested with max repetition = 1 and a list of previously requested OIDs) seems to indicate that we are reaching the 5-second timeout (the request can be quite huge at the discovery phase...so probably I have to change this)
Could you try increasing the timeout?
Change line 990:
$host = "$snmp_cid\@$hostip:$snmp_port:5:1:$backoff:$snmp_ver";
to:
$host = "$snmp_cid\@$hostip:$snmp_port:15:1:$backoff:$snmp_ver";
Let me know the result!

[kconnellTMU]

dm_snmp.pm, I see this @ line 990 (so maybe just a typo for line # 900 that you mention)

Change made, devmon restarted, single host test forced:

Seeing same entries in the log, host was updated with status clear:

2024-12-15T02:15:58.329-0500|WARN |snmp |47957| 232|No answer for oid:1.3.6.1.4.1.2272.1.4.10.1.1.11 on device:jr5720.ns
2024-12-15T02:15:58.329-0500|WARN |snmp |47957| 232|No answer for oid:1.3.6.1.2.1.2.2.1.2 on device:jr5720.ns
2024-12-15T02:15:58.329-0500|WARN |snmp |47957| 245|Received 0/79 oid for device jr5720.ns
2024-12-15T02:15:58.358-0500|WARN |config |47957| 933|Exceeded cycle time (90.3789079189301 seconds).
2024-12-15T02:16:13.541-0500|WARN |snmp |47957| 375|Fork:3 Device:jr5720.ns Try:1 Msg:Timeout at discovery stage:2. will retry until success
2024-12-15T02:16:13.542-0500|WARN |snmp |47957| 375|Fork:2 Device:jr5520.ns Try:1 Msg:Timeout at discovery stage:2. will retry until success

Something to note/ask:
WIth TCP dump, a manual poll, I see it notes snmp, but the devmon polls are 1 snmp, then just udp ?
( I haven't yet done a full trace).

Manual SNMP poll:
02:26:46.723374 IP xymon.ns.57168 > jr5520.ns.snmp: C="snmp-string" GetNextRequest(27) system.sysUpTime
02:26:46.724050 IP jr5520.ns.snmp > xymon.ns.57168: C="snmp-string" GetResponse(32) system.sysUpTime.0=1016676300
02:26:46.724114 IP xymon.ns.57168 > jr5520.ns.snmp: C="snmp-string" GetNextRequest(28) system.sysUpTime.0
02:26:46.725066 IP jr5520.ns.snmp > xymon.ns.57168: C="snmp-string" GetResponse(42) system.sysContact.0="noc@ns"

Devmon:
02:32:36.292721 IP jr5520.ns.snmp > xymon.ns.36717: [len1468<asnlen8171]
02:32:36.293038 IP jr5520.ns > xymon.ns: udp
02:32:36.293260 IP jr5520.ns > xymon.ns: udp
02:32:36.293528 IP jr5520.ns > xymon.ns: udp
02:32:36.293775 IP jr5520.ns > xymon.ns: udp
02:32:36.294030 IP jr5520.ns > xymon.ns: udp
02:32:36.301901 IP xymon.ns.36717 > jr5520.ns.snmp: [len1468<asnlen4108]
02:32:36.301911 IP xymon.ns > jr5520.ns: udp
02:32:36.301912 IP xymon.ns > jr5520.ns: udp
02:32:51.309885 IP xymon.ns.36717 > jr5520.ns.snmp: C="snmp-string" GetBulk(24) N=0 M=1000 .iso.org.dod.snmp-string
02:32:51.330342 IP jr5520.ns.snmp > xymon.ns.36717: [len1468<asnlen8171]
02:32:51.330612 IP jr5520.ns > xymon.ns: udp
02:32:51.330913 IP jr5520.ns > xymon.ns: udp
02:32:51.331134 IP jr5520.ns > xymon.ns: udp
02:32:51.331348 IP jr5520.ns > xymon.ns: udp
02:32:51.331551 IP jr5520.ns > xymon.ns: udp

[bonomani]

1. Yes, line 990 is the correct line. Apologies for the confusion.

2. It seems you have multiple devices. It would be better to diagnose with only one device, such as jr5720.ns or jr5520.ns.

3. The timeout of 90.3789079189301 seconds indicates that the 15-second timeout appears to have been applied. However, there is still no response. This does not seem to be a timeout issue.

4. With TCP dump, during a manual SNMP poll, I observe the traffic clearly labeled as SNMP. However, for Devmon polls, I notice one SNMP request, followed by multiple UDP packets.

   • This behavior appears normal, as SNMP uses UDP. UDP is the protocol, and the port (though not explicitly shown) is likely the standard SNMP port (161).
   • The responses are spread across multiple packets because the discovery process involves a large request. This explains why multiple lines appear in the dump.

   N=0 M=1000 indicates discovery stage 1:

   • At this stage, the goal is to determine the SNMP agent's maximum response capacity by requesting up to 1000 SNMP entries starting from the initial OID 1.3.6.1 (the first entry in the SNMP tree).
   • Discovery stage 1 completes successfully, returning a maximum of 1000 OIDs as expected.

   At stage 2, I take the results from stage 1 and use the number of returned OIDs to craft a request that asks for 1 entry (M=1) for each of these (max 1000) OIDs.

The discovery stages are designed to determine the capability of the SNMP agent (i.e., the maximum number of responses per request).

---

Suggestions:

It would be helpful to log the value of Max Repetition discovered at stage 1 for debugging purposes. This can be implemented with the following code:

1016 $max_getbulk_responses = scalar @ret1;  # max_getbulk_responses is defined!
$data_out{snmp_msg}{ ++$snmp_msg_count } = "stage:1 Max Repetition Discovered: $max_getbulk_responses";

Since the agent seems unable to respond with this value, try reducing the number of OIDs requested. Test with progressively smaller subsets of OIDs (less than the Max Repetition Discovered), such as:
200, 100, 50, ...

For example:

1029 my @ret2 = snmpgetbulk( $host, 0, 1, @oids );         # Original request
     my @ret2 = snmpgetbulk( $host, 0, 1, @oids[0..49] );  # Request with a smaller subset

Have a look also at your device log...

[kconnellTMU]

Current I have it at : @Oids[1..100] (have tried 15, 25, 50, 250) just seems to flip-flop from good to bad (clear-to-green-then-back-to-green)

Started with just uptime, seemed stable, so started adding in some other tests (not at the same time, would wait to see if response was ok, then add another test).

Was good for hours with tests: cpu, fans, & uptime.
added ports - was ok
added poe - was ok
added temp - was ok, left it to bake, but it started flip-flopping a hour or so later.

Some log snips:
15:30 @Oids[1..25]
|Received 0/21 oid for device jr5720.ns

@Oids[1..100]
2024-12-16T15:16:05.924-0500|WARN |snmp | 2857| 232|No answer for oid:1.3.6.1.4.1.2272.1.4.10.1.1.13 on device:jr5720.ns
2024-12-16T15:16:05.924-0500|WARN |snmp | 2857| 245|Received 0/21 oid for device jr5720.ns

@Oids[1..250]
went green, then went clear:
Received 0/21 oid for device jr5720.ns

Seeing on devmon startup:
|Fork:1 Device:jr5720.ns Try:1 Msg:stage:1 Max Repetition Discovered: 257

[bonomani]

First, let me explain what Devmon does:
At discovery stage 1, we make a large SNMP request. Specifically, we query the top OID and request the next 1000 OIDs (1 OID and 1000 subsequent answers) with M=1000.

• In this case, you receive 257 single OIDs, which means we should never request more than that.

At discovery stage 2, Devmon normally tries to request the 257 OIDs received in stage 1, one at a time (257 OIDs, 1 answer each).

• Ideally, we should receive exactly the same results as in stage 1.

---

Your Case

However, in your case, we encounter a timeout message with either 5 seconds or 15 seconds.

• For example, @OIDs[1..250] (use @Oids[0..249] to test 250 oids) seems to work consistently, as it is close to 257. This behavior seems strange to me.
  -> So, the question is: Are we sure it never works for 257 and always works for 250?
  -> If yes, can you also test with 256?

My current understanding:

• Never work for 257 (with timer 5 or 15sec)
• Always work for 250 (with timer 15sec)

With this information, I can design a fallback mechanism to address the issue. Fixing this point is the first priority.

---

Remarks

In SNMP, a device can time out for several reasons:

1. Request Timer Too Low: This doesn’t seem to be the issue in your case.
2. Request Load Too Heavy:
   • The device may fail to respond (hang).
   • The device may respond very slowly, leading to a timeout.
3. SNMP Throttling:
   • The device may throttle SNMP requests to avoid excessive load by intentionally delaying or dropping responses for a few seconds.

Cases 2 and 3 can lead to inconsistent behavior, which need to be addressed in one way or another.

---

Action Plan

1. Find the Maximum Stable Response Size (if any):

   • Test the device’s response with different OID batch sizes (257, 256, 250).

   • Use the following command in verbose mode (trace) to capture the relevant information during discovery stage 2:

     ./bin/devmon -t -p myrouter=cpu -log_m="|snmp"

   • This command runs one cycle, which is sufficient for testing the discovery stage.

   • Procedure:

     • Run the command multiple times in quick succession to stress the device.
     • Observe if the device consistently responds with the expected batch size.

2. Determine the Minimal Timeout:

   • Once the largest stable batch size is identified, test various timeout durations.
   • Gradually decrease the timeout until the device stops responding consistently.
     • Stop reducing the timeout if you reach 5 seconds.
   • The goal is to find the lowest timeout that maintains consistent responses while avoiding unnecessary delays.

---

Priority

Our immediate focus is achieving a stable discovery stage 2 process with:

1. The largest batch size possible.
2. The lowest timeout possible.

Once stage 2 is stabilized, we can move on to debug other areas.

---

Let me know the results of your tests! So I can make a patch already for this point.

[bonomani]

Let me know if the new version resolves your issues!

[bonomani]

"The previous 'Discovery at stage 2' error no longer occurs as the code has been updated to prevent this issue."