ipdevpoll aborted due to plugin failure: tuple index out of range

[Alfred]

Hi
My configuration: Debian 6 amd64.
My installation: from sources.

The bug:
After, seed database step, i notice that i did not get any other host except the router i seed. From Network Explorer, i did not even get router interfaces. So i did not have for each router connected host.

From log, i have

$ tail -f /usr/local/nav/var/log/ipdevpoll.log
2012-09-24 16:56:06,132 [ERROR jobs.jobhandler] [logging 10.0.2.3] Plugin nav.ipdevpoll.plugins.arp.Arp(u'10.0.2.3') reported an unhandled failure
Traceback (most recent call last):
  File "/usr/lib/python2.6/dist-packages/twisted/internet/defer.py", line 1014, in unwindGenerator
    return _inlineCallbacks(None, f(*args, **kwargs), Deferred())
  File "/usr/lib/python2.6/dist-packages/twisted/internet/defer.py", line 893, in _inlineCallbacks
    result = g.send(result)
  File "/usr/local/nav/lib/python/nav/mibs/ip_mib.py", line 190, in get_ifindex_ip_mac_mappings
    mappings_new = yield self._get_ifindex_ip_mac_mappings()
  File "/usr/lib/python2.6/dist-packages/twisted/internet/defer.py", line 837, in unwindGenerator
    return _deferGenerator(f(*args, **kwargs), Deferred())
--- <exception caught here> ---
  File "/usr/lib/python2.6/dist-packages/twisted/internet/defer.py", line 739, in _deferGenerator
    result = g.next()
  File "/usr/local/nav/lib/python/nav/mibs/ip_mib.py", line 130, in _get_ifindex_ip_mac_mappings
    waiter = defer.waitForDeferred(self.retrieve_column(column))
  File "/usr/local/nav/lib/python/nav/mibs/mibretriever.py", line 372, in retrieve_column
    deferred = self.agent_proxy.getTable([ str(node.oid) ])
  File "/usr/local/nav/lib/python/nav/ipdevpoll/snmp/common.py", line 25, in _wrapper
    self, oids = args[0], args[2]
exceptions.IndexError: tuple index out of range

ERROR:nav.ipdevpoll.jobs.jobhandler:Job 'logging' for 10.0.2.3 aborted: ('Job aborted due to plugin failure', IndexError('tuple index out of range',))
2012-09-24 16:56:06,138 [ERROR jobs.jobhandler] [logging 10.0.2.3] Job 'logging' for 10.0.2.3 aborted: ('Job aborted due to plugin failure', IndexError('tuple index out of range',))
^C

If i add in file /usr/local/nav/etc/logging.conf

[levels]
nav.ipdevpoll = INFO
nav.ipdevpoll.jobs.jobhandler = DEBUG
nav.ipdevpoll.jobs.jobhandler.queue = INFO

I get this trace

$ /usr/local/nav/bin/ipdevpolld -J inventory -n 10.0.2.3
/usr/local/nav/lib/python/nav/ipdevpoll/snmp/__init__.py:26: UserWarning: Using pure Python-based SNMP library, which will affect performance
  warnings.warn("Using pure Python-based SNMP library, which will affect "
INFO:nav.ipdevpoll:--- Starting ipdevpolld inventory ---
2012-09-24 16:56:56,204 [INFO nav.ipdevpoll] --- Starting ipdevpolld inventory ---
INFO:nav.ipdevpoll.plugins:Imported 20 plugin classes, 20 classes in plugin registry
2012-09-24 16:56:56,934 [INFO plugins] Imported 20 plugin classes, 20 classes in plugin registry
INFO:nav.ipdevpoll:Running single 'inventory' job for 10.0.2.3
2012-09-24 16:56:56,934 [INFO nav.ipdevpoll] Running single 'inventory' job for 10.0.2.3
DEBUG:nav.ipdevpoll.jobs.jobhandler:Job 'inventory' initialized with plugins: ['dnsname', 'typeoid', 'system', 'modules', 'ciscosup', 'bridge', 'interfaces', 'dot1q', 'ciscovlan', 'extremevlan', 'prefix', 'sensors', 'psu']
2012-09-24 16:56:56,935 [DEBUG jobs.jobhandler] [inventory 10.0.2.3] Job 'inventory' initialized with plugins: ['dnsname', 'typeoid', 'system', 'modules', 'ciscosup', 'bridge', 'interfaces', 'dot1q', 'ciscovlan', 'extremevlan', 'prefix', 'sensors', 'psu']
DEBUG:nav.ipdevpoll.jobs.jobhandler:AgentProxy created for 10.0.2.3: AgentProxy(10.0.2.3,161,public,v2c,<twistedsnmp.snmpprotocol.SNMPProtocol instance at 0x176c9e0>)
2012-09-24 16:56:56,935 [DEBUG jobs.jobhandler] [inventory 10.0.2.3] AgentProxy created for 10.0.2.3: AgentProxy(10.0.2.3,161,public,v2c,<twistedsnmp.snmpprotocol.SNMPProtocol instance at 0x176c9e0>)
DEBUG:nav.ipdevpoll.jobs.jobhandler:Plugins to call: DnsName,TypeOid,System,Modules,CiscoSup,Bridge,Interfaces,Dot1q,CiscoVlan,ExtremeVlan,Prefix,Sensors,PowerSupplyUnit
2012-09-24 16:56:56,937 [DEBUG jobs.jobhandler] [inventory 10.0.2.3] Plugins to call: DnsName,TypeOid,System,Modules,CiscoSup,Bridge,Interfaces,Dot1q,CiscoVlan,ExtremeVlan,Prefix,Sensors,PowerSupplyUnit
DEBUG:nav.ipdevpoll.jobs.jobhandler:Starting job 'inventory' for 10.0.2.3
2012-09-24 16:56:56,938 [DEBUG jobs.jobhandler] [inventory 10.0.2.3] Starting job 'inventory' for 10.0.2.3
DEBUG:nav.ipdevpoll.jobs.jobhandler:Now calling plugin: nav.ipdevpoll.plugins.dnsname.DnsName(u'10.0.2.3')
2012-09-24 16:56:56,938 [DEBUG jobs.jobhandler] [inventory 10.0.2.3] Now calling plugin: nav.ipdevpoll.plugins.dnsname.DnsName(u'10.0.2.3')
WARNING:nav.ipdevpoll.plugins.dnsname.dnsname:DNS lookup error for 10.0.2.3: DNSNameError
2012-09-24 16:56:58,571 [WARNING plugins.dnsname.dnsname] [inventory 10.0.2.3] DNS lookup error for 10.0.2.3: DNSNameError
WARNING:nav.ipdevpoll.plugins.dnsname.dnsname:Unable to find PTR record for 10.0.2.3 (3.2.0.10.in-addr.arpa.)
2012-09-24 16:56:58,572 [WARNING plugins.dnsname.dnsname] [inventory 10.0.2.3] Unable to find PTR record for 10.0.2.3 (3.2.0.10.in-addr.arpa.)
DEBUG:nav.ipdevpoll.jobs.jobhandler:Now calling plugin: nav.ipdevpoll.plugins.typeoid.TypeOid(u'10.0.2.3')
2012-09-24 16:56:58,572 [DEBUG jobs.jobhandler] [inventory 10.0.2.3] Now calling plugin: nav.ipdevpoll.plugins.typeoid.TypeOid(u'10.0.2.3')
WARNING:nav.ipdevpoll.plugins.typeoid.typeoid:Netbox has changed type from unknown to unknown (sysObjectID 1.3.6.1.4.1.8072.3.2.10)
2012-09-24 16:56:58,608 [WARNING plugins.typeoid.typeoid] [inventory 10.0.2.3] Netbox has changed type from unknown to unknown (sysObjectID 1.3.6.1.4.1.8072.3.2.10)
DEBUG:nav.ipdevpoll.jobs.jobhandler:Now calling plugin: nav.ipdevpoll.plugins.system.System(u'10.0.2.3')
2012-09-24 16:56:58,612 [DEBUG jobs.jobhandler] [inventory 10.0.2.3] Now calling plugin: nav.ipdevpoll.plugins.system.System(u'10.0.2.3')
DEBUG:nav.ipdevpoll.jobs.jobhandler:Now calling plugin: nav.ipdevpoll.plugins.modules.Modules(u'10.0.2.3')
2012-09-24 16:56:58,615 [DEBUG jobs.jobhandler] [inventory 10.0.2.3] Now calling plugin: nav.ipdevpoll.plugins.modules.Modules(u'10.0.2.3')
Traceback (most recent call last):
  File "/usr/local/nav/lib/python/nav/ipdevpoll/daemon.py", line 273, in start_ipdevpoll
    process.run()
  File "/usr/local/nav/lib/python/nav/ipdevpoll/daemon.py", line 65, in run
    reactor.run()
  File "/usr/lib/python2.6/dist-packages/twisted/internet/base.py", line 1165, in run
    self.mainLoop()
  File "/usr/lib/python2.6/dist-packages/twisted/internet/base.py", line 1174, in mainLoop
    self.runUntilCurrent()
--- <exception caught here> ---
  File "/usr/lib/python2.6/dist-packages/twisted/internet/base.py", line 796, in runUntilCurrent
    call.func(*call.args, **call.kw)
  File "/usr/local/nav/lib/python/nav/mibs/mibretriever.py", line 409, in schedule_next
    deferred = self.retrieve_column(column)
  File "/usr/local/nav/lib/python/nav/mibs/mibretriever.py", line 372, in retrieve_column
    deferred = self.agent_proxy.getTable([ str(node.oid) ])
  File "/usr/local/nav/lib/python/nav/ipdevpoll/snmp/common.py", line 25, in _wrapper
    self, oids = args[0], args[2]
exceptions.IndexError: tuple index out of range
^CWARNING:nav.ipdevpoll:SIGINT received: Shutting down
2012-09-24 17:39:57,642 [WARNING nav.ipdevpoll] SIGINT received: Shutting down
INFO:nav.ipdevpoll.jobs.jobhandler:Cancelling running job
2012-09-24 17:39:57,642 [INFO jobs.jobhandler] [inventory 10.0.2.3] Cancelling running job
WARNING:nav.ipdevpoll:Shutdown sequence completed in 0.01 seconds
2012-09-24 17:39:57,652 [WARNING nav.ipdevpoll] Shutdown sequence completed in 0.01 seconds

[Morten Brekkevold (mbrekkevold)]

For some reason, setting the log levels in logging.conf seems to have had no effect on your log output. Also, there is something wrong with the output, things seem to be logged twice, with two differing formats.

I do react to one thing, though:

> /usr/local/nav/lib/python/nav/ipdevpoll/snmp/__init__.py:26: UserWarning: Using pure Python-based SNMP library, which will affect performance

This means pynetsnmp is not installed on your system. Your error may stem from some incompatibility between TwistedSNMP and pynetsnmp, and I would highly recommend you to install the latter as a replacement for TwistedSNMP.

I just saw the same error on another installation, run as a side-project of a colleague of mine. He installed pynetsnmp as per my instructions, and it seems to have had an immediate effect after a restart of ipdevpoll.

[Morten Brekkevold (mbrekkevold)]

I can confirm this is a regression seen when using TwistedSNMP instead of pynetsnmp.

[Morten Brekkevold (mbrekkevold)]

Also, the logging problem appears to be related to TwistedSNMP, which does abominable things with the logging module once imported.

[Morten Brekkevold (mbrekkevold)]

fixed here: http://nav.uninett.no/hg/stable/rev/491773b4c391

[Alfred (hospicealfred)]

Le 25/09/2012 14:32, Morten Brekkevold a écrit :
> fixed here: http://nav.uninett.no/hg/stable/rev/491773b4c391
>
> ** Changed in: nav
> Status: Confirmed => Fix Committed
>
> ** Changed in: nav
> Milestone: None => 3.12.1
>
>
As you said, it was an incompatibility between TwistedSNMP and
pynetsnmp. After i install pynetsnmp, ipdevpoll start working correctly.
From log, everything seems ok. I can have trace of different plugin and
what they are doing.

Thanks!