Unexpected reindexing occurs when using uptime as the reindex method

Question

Unexpected reindexing occurs when using uptime as the reindex method

netniV opened this issue 2 years ago · 2 comments

Describe the bug

Under 1.2.23, if you run Spine v1.2.23 this appears to cause constant recaching events for various devices. For example, a Mikrotik running RouterOS will suddenly cause lots of reindexing if your method is set to uptime. The logs show a blank for one of the two uptime comparison values suggesting it doesn't know what it was, ergo it initiates a reindex.

Running an snmpget against the device shows that only the older uptime OID is supported:

netniv:/usr/share/cacti$ snmpget -v 1 -c <community> <IP> .1.3.6.1.6.3.10.2.1.3.0
Error in packet
Reason: (noSuchName) There is no such variable name in this MIB.
Failed object: SNMP-FRAMEWORK-MIB::snmpEngineTime.0

netniv:/usr/share/cacti$ snmpget -v 1 -c <community> <IP> .1.3.6.1.2.1.1.3.0
DISMAN-EVENT-MIB::sysUpTimeInstance = Timeticks: (703583600) 81 days, 10:23:56.00

Rolling Spine back to v1.2.20 (the previous version installed) stopped these messages from appearing. This may be a spine issue or a core issue so it's being logged here until it's known. If it becomes a spine-specific issue, this issue can be moved to that repository.

Sample logs

2022/11/22 21:50:36 - DSTRACE Field Name 'ifIPv6' found not suitable during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:50:36 - DSTRACE Field Name 'ifIP' found not suitable during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:50:36 - DSTRACE Field Name 'ifHwAddr' found not suitable. Non-unique and nonunique not specified during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:50:36 - DSTRACE Field Name 'ifHighSpeed' found not suitable during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:50:36 - DSTRACE Field Name 'ifSpeed' found not suitable during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:50:36 - DSTRACE Field Name 'ifType' found not suitable during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:50:36 - DSTRACE Field Name 'ifAlias' found not suitable during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:50:36 - DSTRACE Field Name 'ifName' found suitable during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:50:36 - DSTRACE Field Name 'ifDescr' found suitable during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:50:36 - DSTRACE Field Name 'ifAdminStatus' found not suitable during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:50:36 - DSTRACE Field Name 'ifOperStatus' found not suitable during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:50:36 - DSTRACE Field Name 'ifIndex' is an SNMP index and suitable Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:50:36 - DSTRACE Available Sort Fields for Re-Index for Device[55], DQ[SNMP - Interface Statistics] are [ifName:ifDescr:ifHwAddr:ifIndex]
2022/11/22 21:50:34 - DSTRACE Running Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:50:34 - PCOMMAND Device[55] NOTE: Recache Event Detected for Device
2022/11/22 21:50:01 - SPINE: Poller[Main Poller] PID[22127] PT[139995141547776] Device[55] HT[1] NOTICE: Spike Kill in Effect for '<IP>'
2022/11/22 21:50:01 - SPINE: Poller[Main Poller] PID[22127] PT[139995141547776] Device[55] HT[1] DQ[SNMP - Interface Statistics] RECACHE ASSERT FAILED: '701004300<'
2022/11/22 21:49:34 - DSTRACE Field Name 'ifIPv6' found not suitable during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:49:34 - DSTRACE Field Name 'ifIP' found not suitable during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:49:34 - DSTRACE Field Name 'ifHwAddr' found not suitable. Non-unique and nonunique not specified during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:49:34 - DSTRACE Field Name 'ifHighSpeed' found not suitable during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:49:34 - DSTRACE Field Name 'ifSpeed' found not suitable during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:49:34 - DSTRACE Field Name 'ifType' found not suitable during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:49:34 - DSTRACE Field Name 'ifAlias' found not suitable during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:49:34 - DSTRACE Field Name 'ifName' found suitable during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:49:34 - DSTRACE Field Name 'ifDescr' found suitable during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:49:34 - DSTRACE Field Name 'ifAdminStatus' found not suitable during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:49:34 - DSTRACE Field Name 'ifOperStatus' found not suitable during Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:49:34 - DSTRACE Field Name 'ifIndex' is an SNMP index and suitable Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:49:34 - DSTRACE Available Sort Fields for Re-Index for Device[55], DQ[SNMP - Interface Statistics] are [ifName:ifDescr:ifHwAddr:ifIndex]
2022/11/22 21:49:31 - DSTRACE Running Re-Index for Device[55], DQ[SNMP - Interface Statistics]
2022/11/22 21:49:31 - PCOMMAND Device[55] NOTE: Recache Event Detected for Device 
2022/11/22 21:49:01 - SPINE: Poller[Main Poller] PID[15212] PT[140069571065600] Device[55] HT[1] NOTICE: Spike Kill in Effect for '<IP>'
2022/11/22 21:49:01 - SPINE: Poller[Main Poller] PID[15212] PT[140069571065600] Device[55] HT[1] DQ[SNMP - Interface Statistics] RECACHE ASSERT FAILED: '700998400<'

Expected behaviour

Since both should be known, the RECACHE ASSERT FAILED: '701004300<' log notice should show two uptime values (current vs previous).

Answer 1 · 2022-11-23T13:39:21.000Z

This is confirmed as a spine bug

Answer 2 · 2022-11-23T13:48:02.000Z

Running Spine v1.2.23 produces the following output:

2022/11/23 05:30:01 - SPINE: Poller[1] PID[24670] PT[140235009996544] Device[55] Updating Full System Information Table
2022/11/23 05:30:01 - SPINE: Poller[1] PID[24670] PT[140235009996544] ERROR: Failed to get oid '.1.3.6.1.6.3.10.2.1.3.0' for Device[55] with Response[2]
2022/11/23 05:30:01 - SPINE: Poller[1] PID[24670] PT[140235009996544] DEBUG: Device[55] HT[1] RECACHE: Processing 5 items in the auto reindex cache for '<IP>'
2022/11/23 05:30:01 - SPINE: Poller[1] PID[24670] PT[140235009996544] Device[55] HT[1] DQ[1] Legacy Uptime Result: 703767000, Is Numeric: 1
2022/11/23 05:30:01 - SPINE: Poller[1] PID[24670] PT[140235009996544] ERROR: Failed to get oid '.1.3.6.1.6.3.10.2.1.3.0' for Device[55] with Response[2]
2022/11/23 05:30:01 - SPINE: Poller[1] PID[24670] PT[140235009996544] Device[55] HT[1] DQ[1] Extended Uptime Result: , Is Numeric: 0
2022/11/23 05:30:01 - SPINE: Poller[1] PID[24670] PT[140235009996544] Device[55] HT[1] DQ[1] RECACHE OID: .1.3.6.1.2.1.1.3.0, (assert: 703761000 < output: )
2022/11/23 05:30:01 - SPINE: Poller[1] PID[24670] PT[140235009996544] Device[55] HT[1] DQ[1] RECACHE ASSERT FAILED: '703761000<'
2022/11/23 05:30:01 - SPINE: Poller[1] PID[24670] PT[140235009996544] Device[55] HT[1] NOTICE: Spike Kill in Effect for '<IP>'
2022/11/23 05:30:01 - SPINE: Poller[1] PID[24670] PT[140235009996544] Device[55] HT[1] DQ[10] RECACHE OID: .1.3.6.1.2.1.1.3.0, (assert: 703761000 < output: 703767000)
2022/11/23 05:30:01 - SPINE: Poller[1] PID[24670] PT[140235009996544] Device[55] HT[1] DQ[11] RECACHE OID: .1.3.6.1.2.1.1.3.0, (assert: 703761000 < output: 703767000)
2022/11/23 05:30:01 - SPINE: Poller[1] PID[24670] PT[140235009996544] Device[55] HT[1] DQ[12] RECACHE OID: .1.3.6.1.2.1.1.3.0, (assert: 703761000 < output: 703767000)
2022/11/23 05:30:01 - SPINE: Poller[1] PID[24670] PT[140235009996544] Device[55] HT[1] DQ[13] RECACHE OID: .1.3.6.1.2.1.1.3.0, (assert: 703761000 < output: 703767000)

Note the Extended Uptime Result is blank, and so is the final RECACHE OID result.