Agent failed while scanning the interfaces table: Unexpected error occurred processing ifTable/ifXTable

Description

Issues with node scanning Adtran TA-5000 chassis.

The Node with Id: 43; ForeignSource: Asset; ForeignId:1380906217714 has aborted for the following reason: Aborting node scan : Agent failed while scanning the interfaces table: Unexpected error occurred processing ifTable/ifXTable for /10.10.116.100: java.lang.NullPointerException

I've attached the output of a snmpwalk-debug.sh run (which errors out) plus a manual run of snmpbulkwalk against our Lab chassis. System report is to large to attach so here is a link to download it: https://dl.dropboxusercontent.com/u/40990204/opennms-system-report.txt.xz

Environment

Linux 3.5.0-23-generic (amd64)

Acceptance / Success Criteria

None

Attachments

2
  • 14 Jan 2014, 03:25 PM
  • 10 Jan 2014, 12:06 PM

Lucidchart Diagrams

Activity

Scott Cunningham August 18, 2014 at 12:55 PM

Updated to latest release and this device started scanning properly.

Scott Cunningham January 14, 2014 at 3:25 PM

provisiond.log debug for rescan of this node.

Scott Cunningham January 13, 2014 at 8:35 AM

Think this is what you need

2014-01-13 08:21:33,769 INFO [DefaultUDPTransportMapping_127.0.1.1/0] NodeScan$AgentScan$3: Processing ifTable row for ifIndex 4 on node 43/Asset/1380906217714
2014-01-13 08:21:33,769 WARN [DefaultUDPTransportMapping_127.0.1.1/0] PhysInterfaceTableTracker$PhysicalInterfaceRow: Cannot decode MAC address:
java.lang.IllegalArgumentException: Cannot decode MAC address:
at org.opennms.core.utils.InetAddressUtils.macAddressStringToBytes(InetAddressUtils.java:599)
at org.opennms.core.utils.InetAddressUtils.normalizeMacAddress(InetAddressUtils.java:628)
at org.opennms.netmgt.provision.service.PhysInterfaceTableTracker$PhysicalInterfaceRow.getPhysAddr(PhysInterfaceTableTracker.java:191)
at org.opennms.netmgt.provision.service.PhysInterfaceTableTracker$PhysicalInterfaceRow.createInterfaceFromRow(PhysInterfaceTableTracker.java:208)
at org.opennms.netmgt.provision.service.NodeScan$AgentScan$3.processPhysicalInterfaceRow(NodeScan.java:581)
at org.opennms.netmgt.provision.service.PhysInterfaceTableTracker.rowCompleted(PhysInterfaceTableTracker.java:239)
at org.opennms.netmgt.snmp.SnmpTableResult.handleCompleteRows(SnmpTableResult.java:103)
at org.opennms.netmgt.snmp.SnmpTableResult.storeResult(SnmpTableResult.java:79)
at org.opennms.netmgt.snmp.TableTracker.storeResult(TableTracker.java:103)
at org.opennms.netmgt.snmp.CollectionTracker.storeResult(CollectionTracker.java:77)
at org.opennms.netmgt.snmp.ColumnTracker$1.processResponse(ColumnTracker.java:95)
at org.opennms.netmgt.snmp.TableTracker$CombinedColumnResponseProcessor.processResponse(TableTracker.java:160)
at org.opennms.netmgt.snmp.AggregateTracker$ChildTrackerResponseProcessor.processResponse(AggregateTracker.java:161)
at org.opennms.netmgt.snmp.SnmpWalker.processResponse(SnmpWalker.java:197)
at org.opennms.netmgt.snmp.snmp4j.Snmp4JWalker.access$600(Snmp4JWalker.java:46)
at org.opennms.netmgt.snmp.snmp4j.Snmp4JWalker$Snmp4JResponseListener.processResponse(Snmp4JWalker.java:136)
at org.opennms.netmgt.snmp.snmp4j.Snmp4JWalker$Snmp4JResponseListener.onResponse(Snmp4JWalker.java:163)
at org.snmp4j.Snmp.processPdu(Snmp.java:1272)
at org.snmp4j.MessageDispatcherImpl.fireProcessPdu(MessageDispatcherImpl.java:616)
at org.snmp4j.MessageDispatcherImpl.dispatchMessage(MessageDispatcherImpl.java:287)
at org.snmp4j.MessageDispatcherImpl.processMessage(MessageDispatcherImpl.java:347)
at org.snmp4j.MessageDispatcherImpl.processMessage(MessageDispatcherImpl.java:309)
at org.snmp4j.transport.AbstractTransportMapping.fireProcessMessage(AbstractTransportMapping.java:83)
at org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread.run(DefaultUdpTransportMapping.java:365)
at java.lang.Thread.run(Thread.java:724)

Scott Cunningham January 10, 2014 at 1:42 PM

Here is the provisond.log (in debug) for the rescan I just ran.... I snipped a few thousand INFO lines. There was no java stack trace in this log. If there is somewhere else to look for the stack trace let me know.

2014-01-10 13:05:21,513 INFO [Provisiond:EventListener-Thread] EventIpcManagerDefaultImpl: run: calling onEvent on Provisiond:EventListener for event uei.opennms.org/internal/capsd/forceRescan dbid 59588 with time Friday, January 10, 2014 6:05:21 GMT PM
2014-01-10 13:05:21,537 INFO [Provisiond:EventListener-Thread] Provisioner: createNodeScan called
2014-01-10 13:05:21,537 WARN [Provisiond:EventListener-Thread] Provisioner: nodeScan = org.opennms.netmgt.provision.service.NodeScan@16d4fe70[foreign source=Asset,foreign id=1380906217714,node id=43,aborted=false,provision service=org.opennms.netmgt.provision.service.DefaultProvisionService@76ce7b9c]
2014-01-10 13:05:21,540 INFO [scanExecutor-5] NodeScan: Scanning node 43/Asset/1380906217714
2014-01-10 13:05:21,546 WARN [Provisiond:EventListener-Thread] Provisioner: addToScheduleQueue future = java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@1cf3ebc5
2014-01-10 13:05:21,606 INFO [scanExecutor-10] IpInterfaceScan: Detecting services for node 43/Asset on address 10.10.116.100: found 3 detectors
2014-01-10 13:05:21,606 INFO [scanExecutor-1] IpInterfaceScan$2: Attemping to detect service ICMP on address 10.10.116.100
2014-01-10 13:05:21,607 INFO [scanExecutor-1] SinglePingResponseCallback: waiting for ping to /10.10.116.100 to finish
2014-01-10 13:05:21,607 INFO [scanExecutor-6] IpInterfaceScan$2: Attemping to detect service SNMP on address 10.10.116.100
2014-01-10 13:05:21,607 WARN [scanExecutor-6] SnmpPeerFactory: Range[begin=10.10.116.254, end=10.10.116.6] has an 'end' that is earlier than its 'beginning'!
2014-01-10 13:05:21,608 INFO [scanExecutor-4] IpInterfaceScan$2: Attemping to detect service SSH on address 10.10.116.100
2014-01-10 13:05:21,609 INFO [scanExecutor-4] SshDetector: isServiceDetected: Checking address: 10.10.116.100 for SSH capability on port 22
2014-01-10 13:05:21,613 INFO [JNI-ICMP-4173-Reply-Processor] SinglePingResponseCallback: got response for address /10.10.116.100, thread 4173, seq 1 with a responseTime 6.466ms
2014-01-10 13:05:21,613 INFO [scanExecutor-1] SinglePingResponseCallback: finished waiting for ping to /10.10.116.100 to finish
2014-01-10 13:05:21,613 INFO [scanExecutor-1] IcmpDetector: isServiceDetected: ICMP based service for address: /10.10.116.100 is detected: true.
2014-01-10 13:05:21,613 INFO [scanExecutor-1] IpInterfaceScan$1: Attempted to detect service ICMP on address 10.10.116.100: true
2014-01-10 13:05:21,621 INFO [scanExecutor-6] IpInterfaceScan$1: Attempted to detect service SNMP on address 10.10.116.100: true
2014-01-10 13:05:21,822 INFO [scanExecutor-4] SshDetector: isServiceDetected: Attempting to connect to address: 10.10.116.100, port: 22, attempt: #0
2014-01-10 13:05:21,823 INFO [scanExecutor-4] IpInterfaceScan$1: Attempted to detect service SSH on address 10.10.116.100: true
2014-01-10 13:05:21,847 WARN [scanExecutor-7] SnmpPeerFactory: Range[begin=10.10.116.254, end=10.10.116.6] has an 'end' that is earlier than its 'beginning'!
2014-01-10 13:05:21,960 WARN [scanExecutor-8] SnmpPeerFactory: Range[begin=10.10.116.254, end=10.10.116.6] has an 'end' that is earlier than its 'beginning'!
2014-01-10 13:05:21,998 INFO [DefaultUDPTransportMapping_127.0.1.1/0] NodeScan$AgentScan$3: Processing ifTable row for ifIndex 1 on node 43/Asset/1380906217714
2014-01-10 13:05:22,004 INFO [writeExecutor-3] DefaultProvisionService$2: Updating SnmpInterface [OnmsSnmpInterface@3482b635 snmpipadentnetmask = [null], snmpphysaddr = '00a0c8a8f1f2', snmpifindex = 1, snmpifdescr = 'eth0', snmpiftype = 6, snmpifname = 'eth0', snmpifspeed = 10000000, snmpifadminstatus = 1, snmpifoperstatus = 2, snmpifalias = 'none', snmpCollect = 'N', snmpPoll = 'N', lastCapsdPoll = Fri Jan 10 13:05:21 EST 2014, lastSnmpPoll = [null]]
2014-01-10 13:05:22,008 INFO [DefaultUDPTransportMapping_127.0.1.1/0] NodeScan$AgentScan$3: Processing ifTable row for ifIndex 2 on node 43/Asset/1380906217714
2014-01-10 13:05:22,020 INFO [writeExecutor-2] DefaultProvisionService$2: Updating SnmpInterface [OnmsSnmpInterface@5f4a3069 snmpipadentnetmask = /255.255.254.0, snmpphysaddr = '00a0c8a8f1f3', snmpifindex = 2, snmpifdescr = 'eth1', snmpiftype = 6, snmpifname = 'eth1', snmpifspeed = 1000000, snmpifadminstatus = 1, snmpifoperstatus = 1, snmpifalias = 'none', snmpCollect = 'UC', snmpPoll = 'N', lastCapsdPoll = Fri Jan 10 13:05:21 EST 2014, lastSnmpPoll = [null]]
2014-01-10 13:05:22,309 INFO [DefaultUDPTransportMapping_127.0.1.1/0] NodeScan$AgentScan$3: Processing ifTable row for ifIndex 3 on node 43/Asset/1380906217714
2014-01-10 13:05:22,325 INFO [writeExecutor-8] DefaultProvisionService$2: Updating SnmpInterface [OnmsSnmpInterface@79df41c1 snmpipadentnetmask = [null], snmpphysaddr = '00a0c8a8f1f4', snmpifindex = 3, snmpifdescr = 'eth5', snmpiftype = 6, snmpifname = 'eth5', snmpifspeed = 10000000, snmpifadminstatus = 1, snmpifoperstatus = 2, snmpifalias = 'none', snmpCollect = 'N', snmpPoll = 'N', lastCapsdPoll = Fri Jan 10 13:05:21 EST 2014, lastSnmpPoll = [null]]
2014-01-10 13:05:22,327 INFO [DefaultUDPTransportMapping_127.0.1.1/0] NodeScan$AgentScan$3: Processing ifTable row for ifIndex 4 on node 43/Asset/1380906217714
2014-01-10 13:05:22,327 WARN [DefaultUDPTransportMapping_127.0.1.1/0] PhysInterfaceTableTracker$PhysicalInterfaceRow: Cannot decode MAC address:
2014-01-10 13:05:22,333 INFO [writeExecutor-1] DefaultProvisionService$2: Updating SnmpInterface [OnmsSnmpInterface@3442373f snmpipadentnetmask = [null], snmpphysaddr = '', snmpifindex = 4, snmpifdescr = 'lpbk', snmpiftype = 24, snmpifname = 'lpbk', snmpifspeed = 0, snmpifadminstatus = 1, snmpifoperstatus = 1, snmpifalias = 'none', snmpCollect = 'N', snmpPoll = 'N', lastCapsdPoll = Fri Jan 10 13:05:21 EST 2014, lastSnmpPoll = [null]]
2014-01-10 13:05:59,633 INFO [DefaultUDPTransportMapping_127.0.1.1/0] NodeScan$AgentScan$3: Processing ifTable row for ifIndex 100001 on node 43/Asset/1380906217714
2014-01-10 13:05:59,633 INFO [DefaultUDPTransportMapping_127.0.1.1/0] NodeScan$AgentScan$3: Processing ifTable row for ifIndex 100001 on node 43/Asset/1380906217714

{snip}

2014-01-10 13:06:49,509 INFO [DefaultUDPTransportMapping_127.0.1.1/0] NodeScan$AgentScan$3: Processing ifTable row for ifIndex 100001 on node 43/Asset/1380906217714
2014-01-10 13:06:49,511 INFO [DefaultUDPTransportMapping_127.0.1.1/0] NodeScan$AgentScan$3: Processing ifTable row for ifIndex 100001 on node 43/Asset/1380906217714
2014-01-10 13:06:49,511 INFO [scanExecutor-8] NodeScan: Aborting Scan of node 43 for the following reason: Aborting node scan : Agent failed while scanning the interfaces table: Unexpected error occurred processing ifTable/ifXTable for /10.10.116.100: java.lang.NullPointerException
2014-01-10 13:06:49,514 INFO [scanExecutor-6] NodeScan$AgentScan: detecting IP interfaces for node null/Asset/1380906217714 using table tracker org.opennms.netmgt.provision.service.NodeScan$AgentScan$1@22fd9da
2014-01-10 13:06:49,515 INFO [scanExecutor-5] NodeScan$AgentScan: detecting IP interfaces for node null/Asset/1380906217714 using table tracker org.opennms.netmgt.provision.service.NodeScan$AgentScan$2@13877855
2014-01-10 13:06:49,521 INFO [nodeScanExecutor-5] NodeScan: Finished scanning node 43/Asset/1380906217714

Benjamin Reed January 10, 2014 at 12:50 PM

Do you have the rest of the stack trace? The bit after the NullPointerException is the part we need to find the place in the code to check.

Fixed

Details

Assignee

Reporter

Labels

Fix versions

Affects versions

Priority

PagerDuty

Created January 10, 2014 at 12:06 PM
Updated August 18, 2014 at 12:55 PM
Resolved August 18, 2014 at 12:55 PM

Flag notifications