This is the error reported by ipdevpolld when I execute it in a netbox:
root@nav:/etc/nav# ipdevpolld -J topo -n 192.168.250.252 2014-07-03 14:39:07,331 [INFO nav.ipdevpoll] --- Starting ipdevpolld topo --- 2014-07-03 14:39:07,332 [DEBUG plugins] Importing plugin system= 2014-07-03 14:39:07,337 [DEBUG plugins] found plugin class System in <module 'nav.ipdevpoll.plugins.system' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/system.pyc'> 2014-07-03 14:39:07,337 [DEBUG plugins] Importing plugin uptime= 2014-07-03 14:39:07,337 [DEBUG plugins] found plugin class Uptime in <module 'nav.ipdevpoll.plugins.uptime' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/uptime.pyc'> 2014-07-03 14:39:07,337 [DEBUG plugins] Importing plugin interfaces= 2014-07-03 14:39:07,343 [DEBUG plugins] found plugin class Interfaces in <module 'nav.ipdevpoll.plugins.interfaces' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/interfaces.pyc'> 2014-07-03 14:39:07,343 [DEBUG plugins] Importing plugin bridge= 2014-07-03 14:39:07,343 [DEBUG plugins] found plugin class Bridge in <module 'nav.ipdevpoll.plugins.bridge' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/bridge.pyc'> 2014-07-03 14:39:07,343 [DEBUG plugins] Importing plugin typeoid= 2014-07-03 14:39:07,344 [DEBUG plugins] found plugin class TypeOid in <module 'nav.ipdevpoll.plugins.typeoid' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/typeoid.pyc'> 2014-07-03 14:39:07,344 [DEBUG plugins] Importing plugin dot1q= 2014-07-03 14:39:07,350 [DEBUG plugins] found plugin class Dot1q in <module 'nav.ipdevpoll.plugins.dot1q' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/dot1q.pyc'> 2014-07-03 14:39:07,351 [DEBUG plugins] Importing plugin ciscovlan= 2014-07-03 14:39:07,359 [DEBUG plugins] found plugin class CiscoVlan in <module 'nav.ipdevpoll.plugins.ciscovlan' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/ciscovlan.pyc'> 2014-07-03 14:39:07,359 [DEBUG plugins] Importing plugin prefix= 2014-07-03 14:39:07,396 [DEBUG plugins] found plugin class Prefix in <module 'nav.ipdevpoll.plugins.prefix' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/prefix.pyc'> 2014-07-03 14:39:07,396 [DEBUG plugins] Importing plugin virtualrouter= 2014-07-03 14:39:07,398 [DEBUG plugins] found plugin class VirtualRouter in <module 'nav.ipdevpoll.plugins.virtualrouter' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/virtualrouter.pyc'> 2014-07-03 14:39:07,398 [DEBUG plugins] Importing plugin arp= 2014-07-03 14:39:07,399 [DEBUG plugins] found plugin class Arp in <module 'nav.ipdevpoll.plugins.arp' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/arp.pyc'> 2014-07-03 14:39:07,399 [DEBUG plugins] Importing plugin cam= 2014-07-03 14:39:07,404 [DEBUG plugins] found plugin class Cam in <module 'nav.ipdevpoll.plugins.cam' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/cam.pyc'> 2014-07-03 14:39:07,404 [DEBUG plugins] Importing plugin lldp= 2014-07-03 14:39:07,404 [DEBUG plugins] found plugin class LLDP in <module 'nav.ipdevpoll.plugins.lldp' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/lldp.pyc'> 2014-07-03 14:39:07,405 [DEBUG plugins] Importing plugin cdp= 2014-07-03 14:39:07,407 [DEBUG plugins] found plugin class CDP in <module 'nav.ipdevpoll.plugins.cdp' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/cdp.pyc'> 2014-07-03 14:39:07,407 [DEBUG plugins] Importing plugin modules= 2014-07-03 14:39:07,407 [DEBUG plugins] found plugin class Modules in <module 'nav.ipdevpoll.plugins.modules' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/modules.pyc'> 2014-07-03 14:39:07,407 [DEBUG plugins] Importing plugin ciscosup= 2014-07-03 14:39:07,408 [DEBUG plugins] found plugin class CiscoSup in <module 'nav.ipdevpoll.plugins.ciscosup' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/ciscosup.pyc'> 2014-07-03 14:39:07,408 [DEBUG plugins] Importing plugin extremevlan= 2014-07-03 14:39:07,412 [DEBUG plugins] found plugin class ExtremeVlan in <module 'nav.ipdevpoll.plugins.extremevlan' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/extremevlan.pyc'> 2014-07-03 14:39:07,413 [DEBUG plugins] Importing plugin linkstate= 2014-07-03 14:39:07,413 [DEBUG plugins] found plugin class LinkState in <module 'nav.ipdevpoll.plugins.linkstate' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/linkstate.pyc'> 2014-07-03 14:39:07,413 [DEBUG plugins] Importing plugin sensors= 2014-07-03 14:39:09,685 [DEBUG plugins] found plugin class Sensors in <module 'nav.ipdevpoll.plugins.sensors' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/sensors.pyc'> 2014-07-03 14:39:09,685 [DEBUG plugins] Importing plugin psu= 2014-07-03 14:39:09,691 [DEBUG plugins] found plugin class PowerSupplyUnit in <module 'nav.ipdevpoll.plugins.psu' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/psu.pyc'> 2014-07-03 14:39:09,691 [DEBUG plugins] Importing plugin snmpcheck= 2014-07-03 14:39:09,692 [DEBUG plugins] found plugin class SnmpCheck in <module 'nav.ipdevpoll.plugins.snmpcheck' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/snmpcheck.pyc'> 2014-07-03 14:39:09,692 [DEBUG plugins] Importing plugin propserial= 2014-07-03 14:39:09,696 [DEBUG plugins] found plugin class ProprietarySerial in <module 'nav.ipdevpoll.plugins.propserial' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/propserial.pyc'> 2014-07-03 14:39:09,696 [DEBUG plugins] Importing plugin statports= 2014-07-03 14:39:09,696 [DEBUG plugins] found plugin class StatPorts in <module 'nav.ipdevpoll.plugins.statports' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/statports.pyc'> 2014-07-03 14:39:09,696 [DEBUG plugins] Importing plugin statsystem= 2014-07-03 14:39:09,824 [DEBUG plugins] found plugin class StatSystem in <module 'nav.ipdevpoll.plugins.statsystem' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/statsystem.pyc'> 2014-07-03 14:39:09,824 [DEBUG plugins] Importing plugin statsensors= 2014-07-03 14:39:09,825 [DEBUG plugins] found plugin class StatSensors in <module 'nav.ipdevpoll.plugins.statsensors' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/statsensors.pyc'> 2014-07-03 14:39:09,825 [INFO plugins] Imported 24 plugin classes, 24 classes in plugin registry 2014-07-03 14:39:09,825 [INFO nav.ipdevpoll] Running single 'topo' job for 192.168.250.252 2014-07-03 14:39:09,825 [DEBUG config] parsed jobs from config file: ['inventory', 'dns', 'ip2mac', 'topo', 'linkcheck', 'snmpcheck', '5minstats', '1minstats'] 2014-07-03 14:39:09,826 [DEBUG jobs.jobhandler] [topo 192.168.250.252] Job 'topo' initialized with plugins: ['cam', 'lldp', 'cdp'] 2014-07-03 14:39:09,827 [DEBUG jobs.jobhandler] [topo 192.168.250.252] AgentProxy created for 192.168.250.252: <nav.ipdevpoll.snmp.pynetsnmp.AgentProxy object at 0x5562bd0> 2014-07-03 14:39:09,846 [DEBUG jobs.jobhandler] [topo 192.168.250.252] no unwilling plugins 2014-07-03 14:39:09,846 [DEBUG jobs.jobhandler] [topo 192.168.250.252] willing plugins: ['Cam', 'LLDP', 'CDP'] 2014-07-03 14:39:09,846 [DEBUG jobs.jobhandler] [topo 192.168.250.252] Starting job 'topo' for 192.168.250.252 2014-07-03 14:39:09,846 [DEBUG jobs.jobhandler] [topo 192.168.250.252] Now calling plugin: nav.ipdevpoll.plugins.cam.Cam(u'192.168.250.252') 2014-07-03 14:39:38,419 [DEBUG plugins.cam.cam] [topo 192.168.250.252] Q-BRIDGE-MIB: 0 MAC addresses found on 0 ports 2014-07-03 14:44:48,865 [DEBUG plugins.cam.cam] [topo 192.168.250.252] BRIDGE-MIB: 4223 MAC addresses found on 2 ports 2014-07-03 14:44:48,895 [DEBUG plugins.cam.cam] [topo 192.168.250.252] up/downlinks: [4] 2014-07-03 14:44:48,895 [DEBUG plugins.cam.cam] [topo 192.168.250.252] access ports: [539] 2014-07-03 14:44:48,895 [DEBUG plugins.cam.cam] [topo 192.168.250.252] 4 sees the following monitored mac addresses: set(['00:16:e0:ee:58:01', '00:16:e0:ee:55:81', '00:18:74:2e:f4:80']) 2014-07-03 14:47:39,441 [DEBUG plugins.cam.cam] [topo 192.168.250.252] found 4 STP blocking ports on 114 vlans: [(1, 'vlan1505'), (2, 'vlan1505'), (543, 'vlan1137'), (1, 'vlan1006'), (1, 'vlan1200'), (543, 'vlan1200'), (544, 'vlan1200'), (1, 'vlan1123'), (543, 'vlan253'), (544, 'vlan253'), (1, 'vlan1054'), (1, 'vlan1545'), (1, 'vlan254'), (543, 'vlan254'), (544, 'vlan254'), (543, 'vlan1223'), (544, 'vlan1223'), (544, 'vlan1115'), (1, 'vlan1045'), (544, 'vlan1045'), (543, 'vlan1619'), (1, 'vlan1511'), (1, 'vlan1138'), (543, 'vlan1138'), (543, 'vlan108'), (1, 'vlan1162'), (543, 'vlan1162'), (544, 'vlan1162'), (543, 'vlan1037'), (1, 'vlan1009'), (543, 'vlan1129'), (1, 'vlan1191'), (543, 'vlan1191'), (1, 'vlan1093'), (543, 'vlan1093'), (543, 'vlan1811'), (544, 'vlan1811'), (1, 'vlan1055'), (1, 'vlan1636'), (543, 'vlan255'), (1, 'vlan1224'), (543, 'vlan1224'), (544, 'vlan1224'), (544, 'vlan1116'), (1, 'vlan1176'), (544, 'vlan1084'), (543, 'vlan1139'), (1, 'vlan1204'), (543, 'vlan1204'), (544, 'vlan1204'), (1, 'vlan1106'), (2, 'vlan1106'), (543, 'vlan1038'), (543, 'vlan1130'), (543, 'vlan1192'), (543, 'vlan1030'), (1, 'vlan301'), (1, 'vlan1225'), (543, 'vlan1225'), (544, 'vlan1225'), (544, 'vlan1085'), (1, 'vlan1700'), (1, 'vlan1140'), (543, 'vlan1140'), (1, 'vlan1107'), (543, 'vlan1805'), (544, 'vlan1630'), (1, 'vlan1039'), (544, 'vlan1039'), (544, 'vlan1605'), (1, 'vlan1012'), (1, 'vlan1242'), (2, 'vlan1242'), (543, 'vlan1131'), (544, 'vlan1131'), (1, 'vlan2'), (2, 'vlan2'), (1, 'vlan1095'), (543, 'vlan1031'), (1, 'vlan1585'), (1, 'vlan302'), (1, 'vlan1226'), (543, 'vlan1226'), (544, 'vlan1226'), (1, 'vlan1118'), (543, 'vlan1118'), (544, 'vlan1118'), (1, 'vlan1701'), (1, 'vlan1524'), (544, 'vlan1806'), (1, 'vlan1075'), (1, 'vlan1040'), (1, 'vlan1243'), (2, 'vlan1243'), (1, 'vlan3'), (2, 'vlan3'), (543, 'vlan1194'), (544, 'vlan1098'), (543, 'vlan1032'), (544, 'vlan1032'), (1, 'vlan1248'), (543, 'vlan1134'), (1, 'vlan1227'), (544, 'vlan1227'), (1, 'vlan1100'), (544, 'vlan1180'), (543, 'vlan1087'), (544, 'vlan1087'), (544, 'vlan1049'), (1, 'vlan1591'), (543, 'vlan1228'), (1, 'vlan1120'), (543, 'vlan1120'), (1, 'vlan250'), (543, 'vlan250'), (544, 'vlan250'), (1, 'vlan1211'), (1, 'vlan1088'), (544, 'vlan1088'), (1, 'vlan1170'), (543, 'vlan1170'), (1, 'vlan1076'), (1, 'vlan1041'), (544, 'vlan1041'), (1, 'vlan1110'), (544, 'vlan1110'), (1, 'vlan4'), (2, 'vlan4'), (544, 'vlan1195'), (1, 'vlan1077'), (1, 'vlan1155'), (1, 'vlan1033'), (544, 'vlan1033'), (1, 'vlan1340'), (1, 'vlan1135'), (543, 'vlan1135'), (543, 'vlan1197'), (544, 'vlan1050'), (1, 'vlan1025'), (1, 'vlan251'), (543, 'vlan251'), (544, 'vlan251'), (544, 'vlan1188'), (544, 'vlan1089'), (1, 'vlan1052'), (1, 'vlan4008'), (1, 'vlan1042'), (544, 'vlan1042'), (544, 'vlan1111'), (544, 'vlan1043'), (543, 'vlan1034'), (543, 'vlan1136'), (1, 'vlan1001'), (2, 'vlan1001'), (1, 'vlan1070'), (1, 'vlan252'), (2, 'vlan252'), (543, 'vlan252'), (544, 'vlan252'), (1, 'vlan1189'), (543, 'vlan1189'), (1, 'vlan1090'), (1, 'vlan1053'), (543, 'vlan1533'), (544, 'vlan1222'), (1, 'vlan1113'), (543, 'vlan1113'), (544, 'vlan1113'), (1, 'vlan1044'), (2, 'vlan1044')] 2014-07-03 14:47:39,447 [DEBUG jobs.jobhandler] [topo 192.168.250.252] Now calling plugin: nav.ipdevpoll.plugins.lldp.LLDP(u'192.168.250.252') 2014-07-03 14:47:39,883 [DEBUG timestamps.timestampchecker] [topo 192.168.250.252] 'lldp': None in timestamp list: (None,) 2014-07-03 14:47:39,883 [WARNING timestamps.timestampchecker] [topo 192.168.250.252] 'lldp': retrieved empty timestamp 2014-07-03 14:49:59,504 [DEBUG plugins.lldp.lldp] [topo 192.168.250.252] LLDP neighbors: [LLDPNeighbor(ifindex=1, chassis_id=macAddress('00:22:57:74:1f:00'), port_id=interfaceName('TenGigabitEthernet1/1/2'), port_desc='TenGigabitEthernet1/1/2', sysname='SeTIC-251.247'), LLDPNeighbor(ifindex=539, chassis_id=macAddress('00:22:b0:bc:35:f8'), port_id=interfaceName('1:23'), port_desc='Ethernet Interface', sysname='ENS-Nova[86-4]'), LLDPNeighbor(ifindex=544, chassis_id=macAddress('b0:fa:eb:62:c2:80'), port_id=interfaceName('Te1/31'), port_desc='TenGigabitEthernet1/31', sysname='CFH-243.ufsc.br'), LLDPNeighbor(ifindex=543, chassis_id=macAddress('44:03:a7:e9:17:c0'), port_id=interfaceName('Te1/31'), port_desc='TenGigabitEthernet1/31', sysname='CSE-246.ufsc.br'), LLDPNeighbor(ifindex=2, chassis_id=macAddress('00:16:e0:ee:55:80'), port_id=interfaceName('TenGigabitEthernet1/1/2'), port_desc='TenGigabitEthernet1/1/2', sysname='SeTIC-252.247')] 2014-07-03 14:49:59,543 [DEBUG jobs.jobhandler] [topo 192.168.250.252] Now calling plugin: nav.ipdevpoll.plugins.cdp.CDP(u'192.168.250.252') 2014-07-03 14:49:59,553 [DEBUG timestamps.timestampchecker] [topo 192.168.250.252] 'cdp': timestamps have changed: (12700620L,) / (12703533L,) 2014-07-03 14:49:59,573 [DEBUG plugins.cdp.cdp] [topo 192.168.250.252] found CDP cache data: [CDPNeighbor(ifindex=4, ip=IP('150.162.103.251'), deviceid='SeTIC-251.ufsc.br', deviceport='TenGigabitEthernet1/1'), CDPNeighbor(ifindex=562, ip=IP('150.162.251.240'), deviceid='UFSC-QinQ[200.17].ufsc.br', deviceport='GigabitEthernet0/27'), CDPNeighbor(ifindex=543, ip=IP('150.162.250.246'), deviceid='CSE-246.ufsc.br', deviceport='TenGigabitEthernet1/31'), CDPNeighbor(ifindex=544, ip=IP('150.162.250.243'), deviceid='CFH-243.ufsc.br', deviceport='TenGigabitEthernet1/31'), CDPNeighbor(ifindex=1, ip=IP('150.162.0.82'), deviceid='VPN', deviceport='FastEthernet0/0')] 2014-07-03 14:49:59,634 [DEBUG shadows.interface.interfacemanager] [topo 192.168.250.252] resolving link state alerts for these ifcs: [] 2014-07-03 14:49:59,643 [DEBUG shadows.adjacency.adjacencymanager] [topo 192.168.250.252] existing: {(1164, 1, u'cam'): <AdjacencyCandidate: 192.168.250.252:Te1/4 at 192.168.250.252 cam candidate 150.162.251.245:None>, (1164, 12, u'cam'): <AdjacencyCandidate: 192.168.250.252:Te1/4 at 192.168.250.252 cam candidate 150.162.250.253:None>, (1164, 11, u'cam'): <AdjacencyCandidate: 192.168.250.252:Te1/4 at 192.168.250.252 cam candidate 150.162.252.247:None>, (1164, 8, u'cam'): <AdjacencyCandidate: 192.168.250.252:Te1/4 at 192.168.250.252 cam candidate 150.162.251.247:None>, (1164, 2, u'cam'): <AdjacencyCandidate: 192.168.250.252:Te1/4 at 192.168.250.252 cam candidate 150.162.252.245:None>} 2014-07-03 14:49:59,673 [DEBUG shadows.adjacency.adjacencymanager] [topo 192.168.250.252] missing: [<AdjacencyCandidate: 192.168.250.252:Te1/4 at 192.168.250.252 cam candidate 150.162.251.245:None>, <AdjacencyCandidate: 192.168.250.252:Te1/4 at 192.168.250.252 cam candidate 150.162.251.247: None>] 2014-07-03 14:49:59,673 [DEBUG shadows.adjacency.adjacencymanager] [topo 192.168.250.252] sources: set(['lldp', 'cdp', 'cam']) 2014-07-03 14:49:59,682 [DEBUG shadows.cam.cammanager] [topo 192.168.250.252] existing=134 (reclaimable=28) / found=131 (known=107 new=24 missing=27) 2014-07-03 14:49:59,687 [ERROR jobs.jobhandler] [topo 192.168.250.252] Caught exception during save. Last manager = None. Last model = None Traceback (most recent call last): File "/usr/lib/python2.7/dist-packages/nav/ipdevpoll/jobs.py", line 409, in perform_save self._log_containers("containers before save") File "/usr/lib/python2.7/dist-packages/nav/ipdevpoll/jobs.py", line 439, in _log_containers pprint.pformat(dict(self.containers))) File "/usr/lib/python2.7/pprint.py", line 60, in pformat return PrettyPrinter(indent=indent, width=width, depth=depth).pformat(object) File "/usr/lib/python2.7/pprint.py", line 119, in pformat self._format(object, sio, 0, 0, {}, 0) File "/usr/lib/python2.7/pprint.py", line 137, in _format rep = self._repr(object, context, level - 1) File "/usr/lib/python2.7/pprint.py", line 230, in _repr self._depth, level) File "/usr/lib/python2.7/pprint.py", line 242, in format return _safe_repr(object, context, maxlevels, level) File "/usr/lib/python2.7/pprint.py", line 286, in _safe_repr vrepr, vreadable, vrecur = saferepr(v, context, maxlevels, level) File "/usr/lib/python2.7/pprint.py", line 284, in _safe_repr for k, v in _sorted(object.items()): File "/usr/lib/python2.7/pprint.py", line 79, in _sorted return sorted(iterable) File "/usr/lib/python2.7/dist-packages/IPy.py", line 745, in __eq__ return self.__cmp__(other) == 0 File "/usr/lib/python2.7/dist-packages/IPy.py", line 708, in __cmp__ if self._prefixlen < other.prefixlen(): AttributeError: 'macAddress' object has no attribute 'prefixlen' 2014-07-03 14:49:59,689 [ERROR jobs.jobhandler] [topo 192.168.250.252] Save stage failed with unhandled error *--- Failure #6 --- /usr/lib/python2.7/threading.py:525: __bootstrap(...) /usr/lib/python2.7/threading.py:552: __bootstrap_inner(...) /usr/lib/python2.7/threading.py:505: run(...) [Capture of Locals and Globals disabled (use captureVars=True)] --- <exception caught here> --- /usr/lib/python2.7/dist-packages/twisted/python/threadpool.py:207: _worker(...) /usr/lib/python2.7/dist-packages/twisted/python/context.py:118: callWithContext(...) /usr/lib/python2.7/dist-packages/twisted/python/context.py:81: callWithContext(...) /usr/lib/python2.7/dist-packages/nav/ipdevpoll/db.py:152: _reset(...) /usr/lib/python2.7/dist-packages/nav/ipdevpoll/db.py:111: _autocommit(...) /usr/lib/python2.7/dist-packages/nav/ipdevpoll/db.py:130: _cleanup(...) /usr/lib/python2.7/dist-packages/nav/ipdevpoll/jobs.py:368: complete_save_cycle(...) /usr/lib/python2.7/dist-packages/nav/ipdevpoll/jobs.py:409: perform_save(...) /usr/lib/python2.7/dist-packages/nav/ipdevpoll/jobs.py:439: _log_containers(...) /usr/lib/python2.7/pprint.py:60: pformat(...) /usr/lib/python2.7/pprint.py:119: pformat(...) /usr/lib/python2.7/pprint.py:137: _format(...) /usr/lib/python2.7/pprint.py:230: _repr(...) /usr/lib/python2.7/pprint.py:242: format(...) /usr/lib/python2.7/pprint.py:286: _safe_repr(...) /usr/lib/python2.7/pprint.py:284: _safe_repr(...) /usr/lib/python2.7/pprint.py:79: _sorted(...) /usr/lib/python2.7/dist-packages/IPy.py:745: __eq__(...) /usr/lib/python2.7/dist-packages/IPy.py:708: __cmp__(...) [Capture of Locals and Globals disabled (use captureVars=True)] exceptions.AttributeError: 'macAddress' object has no attribute 'prefixlen' *--- End of Failure #6 ---
2014-07-03 14:49:59,689 [DEBUG jobs.jobhandler-timings] [topo 192.168.250.252] Job 'topo' timings for 192.168.250.252: Cam : 0:08:29.600778 LLDP : 0:02:20.095687 CDP : 0:00:00.054041 ---------------------------- Plugin total: 0:10:49.750506 ---------------------------- Job total : 0:10:49.842300 Job overhead: 0:00:00.091794 2014-07-03 14:49:59,689 [ERROR jobs.jobhandler] [topo 192.168.250.252] Job 'topo' for 192.168.250.252 aborted: Job aborted due to save failure (cause=AttributeError("'macAddress' object has no attribute 'prefixlen'",))
root@nav:/etc/nav# nav version NAV 4.1.0
root@nav:/etc/nav# lsb_release -a No LSB modules are available. Distributor ID: Debian Description: Debian GNU/Linux 7.5 (wheezy) Release: 7.5 Codename: wheezy
root@nav:/etc/nav# python --version Python 2.7.3
On Thu, 3 Jul 2014 15:03:10 -0300 Bruno Galindro da Costa bruno.galindro@gmail.com wrote:
This is the error reported by ipdevpolld when I execute it in a netbox:
[snip]
Caught exception during save. Last manager = None. Last model = None Traceback (most recent call last): File "/usr/lib/python2.7/dist-packages/nav/ipdevpoll/jobs.py", line 409, in perform_save self._log_containers("containers before save") File "/usr/lib/python2.7/dist-packages/nav/ipdevpoll/jobs.py", line 439, in _log_containers pprint.pformat(dict(self.containers))) File "/usr/lib/python2.7/pprint.py", line 60, in pformat return PrettyPrinter(indent=indent, width=width, depth=depth).pformat(object) File "/usr/lib/python2.7/pprint.py", line 119, in pformat self._format(object, sio, 0, 0, {}, 0) File "/usr/lib/python2.7/pprint.py", line 137, in _format rep = self._repr(object, context, level - 1) File "/usr/lib/python2.7/pprint.py", line 230, in _repr self._depth, level) File "/usr/lib/python2.7/pprint.py", line 242, in format return _safe_repr(object, context, maxlevels, level) File "/usr/lib/python2.7/pprint.py", line 286, in _safe_repr vrepr, vreadable, vrecur = saferepr(v, context, maxlevels, level) File "/usr/lib/python2.7/pprint.py", line 284, in _safe_repr for k, v in _sorted(object.items()): File "/usr/lib/python2.7/pprint.py", line 79, in _sorted return sorted(iterable) File "/usr/lib/python2.7/dist-packages/IPy.py", line 745, in __eq__ return self.__cmp__(other) == 0 File "/usr/lib/python2.7/dist-packages/IPy.py", line 708, in __cmp__ if self._prefixlen < other.prefixlen(): AttributeError: 'macAddress' object has no attribute 'prefixlen'
This seems to be a rather embarrassing bug in IPy.
(Tech description: The IP class implementation naively assumes IP objects will only ever be compared with other IP objects, which in practice is not true. Witness it here being compared to macAddress objects during pretty-print formatting in Python's pprint module).
This pretty-printing only occurs in ipdevpoll when you have enabled DEBUG-level logging for the "nav.ipdevpoll.jobs.jobhandler-queue" logger. Unless you have a specific reason for running with DEBUG level logging on all parts of NAV, reconfiguring your logging levels would mitigate this.
Debian Wheezy appears to ship with IPy 0.75, whereas the bug seems to have been fixed in the 0.80 release. Version 0.81 is available in Debian testing (Jessie), so you could also fix the bug by installing the python-ipy package from there.
Morten,
I've upgraded the package and now the problem is other. Another thing is that the previous error was ocurring even running NAV without DEBUG setting in nav.ipdevpoll.jobs.jobhandler at /etc/nav/logging.conf. I've put it in DEBUG to provide more information about this error before starting this tread.
This new problem seems to ocurring only with DEBUG setting... but I don't know if this is true or false. Can you confirm it for me please?
root@nav:~# dpkg --list python-ipy Desired=Unknown/Install/Remove/Purge/Hold | Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend |/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad) ||/ Name Version Architecture Description +++-======================================-========================-========================-================================================================================= ii python-ipy *1:0.81-1* all Python module for handling IPv4 and IPv6 addresses and networks
WITHOUT DEBUG (Only a WARNING is displayed):
root@nav:~# ipdevpolld -J topo -n 150.162.250.252 2014-07-07 08:12:58,333 [INFO nav.ipdevpoll] --- Starting ipdevpolld topo --- 2014-07-07 08:13:00,732 [INFO plugins] Imported 24 plugin classes, 24 classes in plugin registry 2014-07-07 08:13:00,732 [INFO nav.ipdevpoll] Running single 'topo' job for 150.162.250.252 *2014-07-07 08:18:03,540 [WARNING timestamps.timestampchecker] [topo 150.162.250.252] 'lldp': retrieved empty timestamp*
WITH DEBUG:
2014-07-07 07:29:55,348 [INFO nav.ipdevpoll] --- Starting ipdevpolld topo --- 2014-07-07 07:29:55,348 [DEBUG plugins] Importing plugin system= 2014-07-07 07:29:55,354 [DEBUG plugins] found plugin class System in <module 'nav.ipdevpoll.plugins.system' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/system.pyc'> 2014-07-07 07:29:55,354 [DEBUG plugins] Importing plugin uptime= 2014-07-07 07:29:55,354 [DEBUG plugins] found plugin class Uptime in <module 'nav.ipdevpoll.plugins.uptime' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/uptime.pyc'> 2014-07-07 07:29:55,354 [DEBUG plugins] Importing plugin interfaces= 2014-07-07 07:29:55,361 [DEBUG plugins] found plugin class Interfaces in <module 'nav.ipdevpoll.plugins.interfaces' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/interfaces.pyc'> 2014-07-07 07:29:55,361 [DEBUG plugins] Importing plugin bridge= 2014-07-07 07:29:55,362 [DEBUG plugins] found plugin class Bridge in <module 'nav.ipdevpoll.plugins.bridge' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/bridge.pyc'> 2014-07-07 07:29:55,362 [DEBUG plugins] Importing plugin typeoid= 2014-07-07 07:29:55,362 [DEBUG plugins] found plugin class TypeOid in <module 'nav.ipdevpoll.plugins.typeoid' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/typeoid.pyc'> 2014-07-07 07:29:55,362 [DEBUG plugins] Importing plugin dot1q= 2014-07-07 07:29:55,370 [DEBUG plugins] found plugin class Dot1q in <module 'nav.ipdevpoll.plugins.dot1q' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/dot1q.pyc'> 2014-07-07 07:29:55,370 [DEBUG plugins] Importing plugin ciscovlan= 2014-07-07 07:29:55,382 [DEBUG plugins] found plugin class CiscoVlan in <module 'nav.ipdevpoll.plugins.ciscovlan' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/ciscovlan.pyc'> 2014-07-07 07:29:55,382 [DEBUG plugins] Importing plugin prefix= 2014-07-07 07:29:55,417 [DEBUG plugins] found plugin class Prefix in <module 'nav.ipdevpoll.plugins.prefix' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/prefix.pyc'> 2014-07-07 07:29:55,417 [DEBUG plugins] Importing plugin virtualrouter= 2014-07-07 07:29:55,420 [DEBUG plugins] found plugin class VirtualRouter in <module 'nav.ipdevpoll.plugins.virtualrouter' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/virtualrouter.pyc'> 2014-07-07 07:29:55,420 [DEBUG plugins] Importing plugin arp= 2014-07-07 07:29:55,420 [DEBUG plugins] found plugin class Arp in <module 'nav.ipdevpoll.plugins.arp' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/arp.pyc'> 2014-07-07 07:29:55,420 [DEBUG plugins] Importing plugin cam= 2014-07-07 07:29:55,426 [DEBUG plugins] found plugin class Cam in <module 'nav.ipdevpoll.plugins.cam' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/cam.pyc'> 2014-07-07 07:29:55,427 [DEBUG plugins] Importing plugin lldp= 2014-07-07 07:29:55,427 [DEBUG plugins] found plugin class LLDP in <module 'nav.ipdevpoll.plugins.lldp' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/lldp.pyc'> 2014-07-07 07:29:55,427 [DEBUG plugins] Importing plugin cdp= 2014-07-07 07:29:55,430 [DEBUG plugins] found plugin class CDP in <module 'nav.ipdevpoll.plugins.cdp' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/cdp.pyc'> 2014-07-07 07:29:55,430 [DEBUG plugins] Importing plugin modules= 2014-07-07 07:29:55,430 [DEBUG plugins] found plugin class Modules in <module 'nav.ipdevpoll.plugins.modules' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/modules.pyc'> 2014-07-07 07:29:55,430 [DEBUG plugins] Importing plugin ciscosup= 2014-07-07 07:29:55,430 [DEBUG plugins] found plugin class CiscoSup in <module 'nav.ipdevpoll.plugins.ciscosup' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/ciscosup.pyc'> 2014-07-07 07:29:55,431 [DEBUG plugins] Importing plugin extremevlan= 2014-07-07 07:29:55,436 [DEBUG plugins] found plugin class ExtremeVlan in <module 'nav.ipdevpoll.plugins.extremevlan' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/extremevlan.pyc'> 2014-07-07 07:29:55,436 [DEBUG plugins] Importing plugin linkstate= 2014-07-07 07:29:55,436 [DEBUG plugins] found plugin class LinkState in <module 'nav.ipdevpoll.plugins.linkstate' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/linkstate.pyc'> 2014-07-07 07:29:55,437 [DEBUG plugins] Importing plugin sensors= 2014-07-07 07:29:57,757 [DEBUG plugins] found plugin class Sensors in <module 'nav.ipdevpoll.plugins.sensors' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/sensors.pyc'> 2014-07-07 07:29:57,757 [DEBUG plugins] Importing plugin psu= 2014-07-07 07:29:57,764 [DEBUG plugins] found plugin class PowerSupplyUnit in <module 'nav.ipdevpoll.plugins.psu' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/psu.pyc'> 2014-07-07 07:29:57,765 [DEBUG plugins] Importing plugin snmpcheck= 2014-07-07 07:29:57,765 [DEBUG plugins] found plugin class SnmpCheck in <module 'nav.ipdevpoll.plugins.snmpcheck' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/snmpcheck.pyc'> 2014-07-07 07:29:57,765 [DEBUG plugins] Importing plugin propserial= 2014-07-07 07:29:57,771 [DEBUG plugins] found plugin class ProprietarySerial in <module 'nav.ipdevpoll.plugins.propserial' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/propserial.pyc'> 2014-07-07 07:29:57,771 [DEBUG plugins] Importing plugin statports= 2014-07-07 07:29:57,771 [DEBUG plugins] found plugin class StatPorts in <module 'nav.ipdevpoll.plugins.statports' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/statports.pyc'> 2014-07-07 07:29:57,771 [DEBUG plugins] Importing plugin statsystem= 2014-07-07 07:29:57,906 [DEBUG plugins] found plugin class StatSystem in <module 'nav.ipdevpoll.plugins.statsystem' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/statsystem.pyc'> 2014-07-07 07:29:57,907 [DEBUG plugins] Importing plugin statsensors= 2014-07-07 07:29:57,907 [DEBUG plugins] found plugin class StatSensors in <module 'nav.ipdevpoll.plugins.statsensors' from '/usr/lib/python2.7/dist-packages/nav/ipdevpoll/plugins/statsensors.pyc'> 2014-07-07 07:29:57,907 [INFO plugins] Imported 24 plugin classes, 24 classes in plugin registry 2014-07-07 07:29:57,907 [INFO nav.ipdevpoll] Running single 'topo' job for 192.168.250.252 2014-07-07 07:29:57,907 [DEBUG config] parsed jobs from config file: ['inventory', 'dns', 'ip2mac', 'topo', 'linkcheck', 'snmpcheck', '5minstats', '1minstats'] 2014-07-07 07:29:57,908 [DEBUG jobs.jobhandler] [topo 192.168.250.252] Job 'topo' initialized with plugins: ['cam', 'lldp', 'cdp'] 2014-07-07 07:29:57,909 [DEBUG jobs.jobhandler] [topo 192.168.250.252] AgentProxy created for 192.168.250.252: <nav.ipdevpoll.snmp.pynetsnmp.AgentProxy object at 0x6f052d0> 2014-07-07 07:29:57,932 [DEBUG jobs.jobhandler] [topo 192.168.250.252] no unwilling plugins 2014-07-07 07:29:57,932 [DEBUG jobs.jobhandler] [topo 192.168.250.252] willing plugins: ['Cam', 'LLDP', 'CDP'] 2014-07-07 07:29:57,932 [DEBUG jobs.jobhandler] [topo 192.168.250.252] Starting job 'topo' for 192.168.250.252 2014-07-07 07:29:57,932 [DEBUG jobs.jobhandler] [topo 192.168.250.252] Now calling plugin: nav.ipdevpoll.plugins.cam.Cam(u'192.168.250.252') 2014-07-07 07:30:23,103 [DEBUG plugins.cam.cam] [topo 192.168.250.252] Q-BRIDGE-MIB: 0 MAC addresses found on 0 ports 2014-07-07 07:32:16,779 [DEBUG plugins.cam.cam] [topo 192.168.250.252] BRIDGE-MIB: 1897 MAC addresses found on 2 ports 2014-07-07 07:32:16,794 [DEBUG plugins.cam.cam] [topo 192.168.250.252] up/downlinks: [4] 2014-07-07 07:32:16,794 [DEBUG plugins.cam.cam] [topo 192.168.250.252] access ports: [539] 2014-07-07 07:32:16,795 [DEBUG plugins.cam.cam] [topo 192.168.250.252] 4 sees the following monitored mac addresses: set(['00:16:e0:ee:58:01', '00:16:e0:ee:55:81', '00:1e:c1:ed:78:81', '00:18:74:2e:f4:80', '00:22:57:74:1f:01']) 2014-07-07 07:33:12,379 [DEBUG plugins.cam.cam] [topo 192.168.250.252] found 4 STP blocking ports on 114 vlans: [(1, 'vlan1505'), (2, 'vlan1505'), (543, 'vlan1137'), (1, 'vlan1006'), (1, 'vlan1200'), (543, 'vlan1200'), (544, 'vlan1200'), (1, 'vlan1123'), (543, 'vlan253'), (544, 'vlan253'), (1, 'vlan1054'), (1, 'vlan1545'), (1, 'vlan254'), (543, 'vlan254'), (544, 'vlan254'), (543, 'vlan1223'), (544, 'vlan1223'), (544, 'vlan1115'), (1, 'vlan1045'), (544, 'vlan1045'), (543, 'vlan1619'), (1, 'vlan1511'), (1, 'vlan1138'), (543, 'vlan1138'), (543, 'vlan108'), (1, 'vlan1162'), (543, 'vlan1162'), (544, 'vlan1162'), (543, 'vlan1037'), (1, 'vlan1009'), (543, 'vlan1129'), (1, 'vlan1191'), (543, 'vlan1191'), (1, 'vlan1093'), (543, 'vlan1093'), (543, 'vlan1811'), (544, 'vlan1811'), (1, 'vlan1055'), (1, 'vlan1636'), (543, 'vlan255'), (1, 'vlan1224'), (543, 'vlan1224'), (544, 'vlan1224'), (544, 'vlan1116'), (1, 'vlan1176'), (544, 'vlan1084'), (543, 'vlan1139'), (1, 'vlan1204'), (543, 'vlan1204'), (544, 'vlan1204'), (1, 'vlan1106'), (2, 'vlan1106'), (543, 'vlan1038'), (543, 'vlan1130'), (543, 'vlan1192'), (543, 'vlan1030'), (1, 'vlan301'), (1, 'vlan1225'), (543, 'vlan1225'), (544, 'vlan1225'), (544, 'vlan1085'), (1, 'vlan1700'), (1, 'vlan1140'), (543, 'vlan1140'), (1, 'vlan1107'), (543, 'vlan1805'), (544, 'vlan1630'), (1, 'vlan1039'), (544, 'vlan1039'), (544, 'vlan1605'), (1, 'vlan1012'), (1, 'vlan1242'), (2, 'vlan1242'), (543, 'vlan1131'), (544, 'vlan1131'), (1, 'vlan2'), (2, 'vlan2'), (1, 'vlan1095'), (543, 'vlan1031'), (1, 'vlan1585'), (1, 'vlan302'), (1, 'vlan1226'), (543, 'vlan1226'), (544, 'vlan1226'), (1, 'vlan1118'), (543, 'vlan1118'), (544, 'vlan1118'), (1, 'vlan1701'), (1, 'vlan1524'), (544, 'vlan1806'), (1, 'vlan1075'), (1, 'vlan1040'), (1, 'vlan1243'), (2, 'vlan1243'), (1, 'vlan3'), (2, 'vlan3'), (543, 'vlan1194'), (544, 'vlan1098'), (543, 'vlan1032'), (544, 'vlan1032'), (1, 'vlan1248'), (543, 'vlan1134'), (1, 'vlan1227'), (544, 'vlan1227'), (1, 'vlan1100'), (544, 'vlan1180'), (543, 'vlan1087'), (544, 'vlan1087'), (544, 'vlan1049'), (1, 'vlan1591'), (543, 'vlan1228'), (1, 'vlan1120'), (543, 'vlan1120'), (1, 'vlan250'), (543, 'vlan250'), (544, 'vlan250'), (1, 'vlan1211'), (1, 'vlan1088'), (544, 'vlan1088'), (1, 'vlan1170'), (543, 'vlan1170'), (1, 'vlan1076'), (1, 'vlan1041'), (544, 'vlan1041'), (1, 'vlan1110'), (544, 'vlan1110'), (1, 'vlan4'), (2, 'vlan4'), (544, 'vlan1195'), (1, 'vlan1077'), (1, 'vlan1155'), (1, 'vlan1033'), (544, 'vlan1033'), (1, 'vlan1340'), (1, 'vlan1135'), (543, 'vlan1135'), (543, 'vlan1197'), (544, 'vlan1050'), (1, 'vlan1025'), (1, 'vlan251'), (543, 'vlan251'), (544, 'vlan251'), (544, 'vlan1188'), (544, 'vlan1089'), (1, 'vlan1052'), (1, 'vlan4008'), (1, 'vlan1042'), (544, 'vlan1042'), (544, 'vlan1111'), (544, 'vlan1043'), (543, 'vlan1034'), (543, 'vlan1136'), (1, 'vlan1001'), (2, 'vlan1001'), (1, 'vlan1070'), (1, 'vlan252'), (2, 'vlan252'), (543, 'vlan252'), (544, 'vlan252'), (1, 'vlan1189'), (543, 'vlan1189'), (1, 'vlan1090'), (1, 'vlan1053'), (543, 'vlan1533'), (544, 'vlan1222'), (1, 'vlan1113'), (543, 'vlan1113'), (544, 'vlan1113'), (1, 'vlan1044'), (2, 'vlan1044')] 2014-07-07 07:33:12,382 [DEBUG jobs.jobhandler] [topo 192.168.250.252] Now calling plugin: nav.ipdevpoll.plugins.lldp.LLDP(u'192.168.250.252') 2014-07-07 07:33:12,390 [DEBUG timestamps.timestampchecker] [topo 192.168.250.252] 'lldp': None in timestamp list: (None,) 2014-07-07 07:33:12,390 [WARNING timestamps.timestampchecker] [topo 192.168.250.252] 'lldp': retrieved empty timestamp 2014-07-07 07:33:35,045 [DEBUG plugins.lldp.lldp] [topo 192.168.250.252] LLDP neighbors: [LLDPNeighbor(ifindex=1, chassis_id=macAddress('00:22:57:74:1f:00'), port_id=interfaceName('TenGigabitEthernet1/1/2'), port_desc='TenGigabitEthernet1/1/2', sysname='SeTIC-251.247'), LLDPNeighbor(ifindex=539, chassis_id=macAddress('00:22:b0:bc:35:f8'), port_id=interfaceName('1:23'), port_desc='Ethernet Interface', sysname='ENS-Nova[86-4]'), LLDPNeighbor(ifindex=544, chassis_id=macAddress('b0:fa:eb:62:c2:80'), port_id=interfaceName('Te1/31'), port_desc='TenGigabitEthernet1/31', sysname='CFH-243.ufsc.br'), LLDPNeighbor(ifindex=543, chassis_id=macAddress('44:03:a7:e9:17:c0'), port_id=interfaceName('Te1/31'), port_desc='TenGigabitEthernet1/31', sysname='CSE-246.ufsc.br'), LLDPNeighbor(ifindex=2, chassis_id=macAddress('00:16:e0:ee:55:80'), port_id=interfaceName('TenGigabitEthernet1/1/2'), port_desc='TenGigabitEthernet1/1/2', sysname='SeTIC-252.247')] 2014-07-07 07:33:35,052 [DEBUG jobs.jobhandler] [topo 192.168.250.252] Now calling plugin: nav.ipdevpoll.plugins.cdp.CDP(u'192.168.250.252') 2014-07-07 07:33:35,056 [DEBUG timestamps.timestampchecker] [topo 192.168.250.252] 'cdp': timestamps have changed: (12700620L,) / (13022957L,) 2014-07-07 07:33:35,067 [DEBUG plugins.cdp.cdp] [topo 192.168.250.252] found CDP cache data: [CDPNeighbor(ifindex=4, ip=IP('150.162.103.251'), deviceid='SeTIC-251.ufsc.br', deviceport='TenGigabitEthernet1/1'), CDPNeighbor(ifindex=562, ip=IP('150.162.251.240'), deviceid='UFSC-QinQ[200.17].ufsc.br', deviceport='GigabitEthernet0/27'), CDPNeighbor(ifindex=543, ip=IP('150.162.250.246'), deviceid='CSE-246.ufsc.br', deviceport='TenGigabitEthernet1/31'), CDPNeighbor(ifindex=544, ip=IP('150.162.250.243'), deviceid='CFH-243.ufsc.br', deviceport='TenGigabitEthernet1/31'), CDPNeighbor(ifindex=1, ip=IP('150.162.0.82'), deviceid='VPN', deviceport='FastEthernet0/0')] 2014-07-07 07:33:35,117 [DEBUG shadows.interface.interfacemanager] [topo 192.168.250.252] resolving link state alerts for these ifcs: [] 2014-07-07 07:33:35,126 [DEBUG shadows.adjacency.adjacencymanager] [topo 192.168.250.252] existing: {(1164, 1, u'cam'): <AdjacencyCandidate: 192.168.250.252:Te1/4 at 192.168.250.252 cam candidate 150.162.251.245:None>, (1164, 12, u'cam'): <AdjacencyCandidate: 192.168.250.252:Te1/4 at 192.168.250.252 cam candidate 150.162.250.253:None>, (1164, 11, u'cam'): <AdjacencyCandidate: 192.168.250.252:Te1/4 at 192.168.250.252 cam candidate 150.162.252.247:None>, (1164, 8, u'cam'): <AdjacencyCandidate: 192.168.250.252:Te1/4 at 192.168.250.252 cam candidate 150.162.251.247:None>, (1164, 2, u'cam'): <AdjacencyCandidate: 192.168.250.252:Te1/4 at 192.168.250.252 cam candidate 150.162.252.245:None>} 2014-07-07 07:33:35,143 [DEBUG shadows.adjacency.adjacencymanager] [topo 192.168.250.252] missing: [] 2014-07-07 07:33:35,143 [DEBUG shadows.adjacency.adjacencymanager] [topo 192.168.250.252] sources: set(['lldp', 'cdp', 'cam']) 2014-07-07 07:33:35,150 [DEBUG shadows.cam.cammanager] [topo 192.168.250.252] existing=134 (reclaimable=28) / found=35 (known=31 new=4 missing=103) 2014-07-07 07:33:35,155 [ERROR jobs.jobhandler] [topo 192.168.250.252] Caught exception during save. Last manager = None. Last model = None Traceback (most recent call last): File "/usr/lib/python2.7/dist-packages/nav/ipdevpoll/jobs.py", line 409, in perform_save self._log_containers("containers before save") File "/usr/lib/python2.7/dist-packages/nav/ipdevpoll/jobs.py", line 439, in _log_containers pprint.pformat(dict(self.containers))) File "/usr/lib/python2.7/pprint.py", line 60, in pformat return PrettyPrinter(indent=indent, width=width, depth=depth).pformat(object) File "/usr/lib/python2.7/pprint.py", line 119, in pformat self._format(object, sio, 0, 0, {}, 0) File "/usr/lib/python2.7/pprint.py", line 137, in _format rep = self._repr(object, context, level - 1) File "/usr/lib/python2.7/pprint.py", line 230, in _repr self._depth, level) File "/usr/lib/python2.7/pprint.py", line 242, in format return _safe_repr(object, context, maxlevels, level) File "/usr/lib/python2.7/pprint.py", line 286, in _safe_repr vrepr, vreadable, vrecur = saferepr(v, context, maxlevels, level) File "/usr/lib/python2.7/pprint.py", line 284, in _safe_repr for k, v in _sorted(object.items()): File "/usr/lib/python2.7/pprint.py", line 79, in _sorted return sorted(iterable) File "/usr/lib/python2.7/dist-packages/IPy.py", line 741, in __cmp__ raise TypeError TypeError 2014-07-07 07:33:35,157 [ERROR jobs.jobhandler] [topo 192.168.250.252] Save stage failed with unhandled error *--- Failure #6 --- /usr/lib/python2.7/threading.py:525: __bootstrap(...) /usr/lib/python2.7/threading.py:552: __bootstrap_inner(...) /usr/lib/python2.7/threading.py:505: run(...) [Capture of Locals and Globals disabled (use captureVars=True)] --- <exception caught here> --- /usr/lib/python2.7/dist-packages/twisted/python/threadpool.py:207: _worker(...) /usr/lib/python2.7/dist-packages/twisted/python/context.py:118: callWithContext(...) /usr/lib/python2.7/dist-packages/twisted/python/context.py:81: callWithContext(...) /usr/lib/python2.7/dist-packages/nav/ipdevpoll/db.py:152: _reset(...) /usr/lib/python2.7/dist-packages/nav/ipdevpoll/db.py:111: _autocommit(...) /usr/lib/python2.7/dist-packages/nav/ipdevpoll/db.py:130: _cleanup(...) /usr/lib/python2.7/dist-packages/nav/ipdevpoll/jobs.py:368: complete_save_cycle(...) /usr/lib/python2.7/dist-packages/nav/ipdevpoll/jobs.py:409: perform_save(...) /usr/lib/python2.7/dist-packages/nav/ipdevpoll/jobs.py:439: _log_containers(...) /usr/lib/python2.7/pprint.py:60: pformat(...) /usr/lib/python2.7/pprint.py:119: pformat(...) /usr/lib/python2.7/pprint.py:137: _format(...) /usr/lib/python2.7/pprint.py:230: _repr(...) /usr/lib/python2.7/pprint.py:242: format(...) /usr/lib/python2.7/pprint.py:286: _safe_repr(...) /usr/lib/python2.7/pprint.py:284: _safe_repr(...) /usr/lib/python2.7/pprint.py:79: _sorted(...) /usr/lib/python2.7/dist-packages/IPy.py:741: __cmp__(...) [Capture of Locals and Globals disabled (use captureVars=True)] exceptions.TypeError: *--- End of Failure #6 ---
2014-07-07 07:33:35,157 [DEBUG jobs.jobhandler-timings] [topo 192.168.250.252] Job 'topo' timings for 192.168.250.252: Cam : 0:03:14.449810 LLDP : 0:00:22.670179 CDP : 0:00:00.032089 ---------------------------- Plugin total: 0:03:37.152078 ---------------------------- Job total : 0:03:37.224704 Job overhead: 0:00:00.072626 *2014-07-07 07:33:35,157 [ERROR jobs.jobhandler] [topo 192.168.250.252] Job 'topo' for 192.168.250.252 aborted: Job aborted due to save failure (cause=TypeError())*
2014-07-07 7:08 GMT-03:00 Morten Brekkevold morten.brekkevold@uninett.no:
On Thu, 3 Jul 2014 15:03:10 -0300 Bruno Galindro da Costa < bruno.galindro@gmail.com> wrote:
This is the error reported by ipdevpolld when I execute it in a netbox:
[snip]
Caught exception during save. Last manager = None. Last model = None Traceback (most recent call last): File "/usr/lib/python2.7/dist-packages/nav/ipdevpoll/jobs.py", line
409,
in perform_save self._log_containers("containers before save") File "/usr/lib/python2.7/dist-packages/nav/ipdevpoll/jobs.py", line
439,
in _log_containers pprint.pformat(dict(self.containers))) File "/usr/lib/python2.7/pprint.py", line 60, in pformat return PrettyPrinter(indent=indent, width=width, depth=depth).pformat(object) File "/usr/lib/python2.7/pprint.py", line 119, in pformat self._format(object, sio, 0, 0, {}, 0) File "/usr/lib/python2.7/pprint.py", line 137, in _format rep = self._repr(object, context, level - 1) File "/usr/lib/python2.7/pprint.py", line 230, in _repr self._depth, level) File "/usr/lib/python2.7/pprint.py", line 242, in format return _safe_repr(object, context, maxlevels, level) File "/usr/lib/python2.7/pprint.py", line 286, in _safe_repr vrepr, vreadable, vrecur = saferepr(v, context, maxlevels, level) File "/usr/lib/python2.7/pprint.py", line 284, in _safe_repr for k, v in _sorted(object.items()): File "/usr/lib/python2.7/pprint.py", line 79, in _sorted return sorted(iterable) File "/usr/lib/python2.7/dist-packages/IPy.py", line 745, in __eq__ return self.__cmp__(other) == 0 File "/usr/lib/python2.7/dist-packages/IPy.py", line 708, in __cmp__ if self._prefixlen < other.prefixlen(): AttributeError: 'macAddress' object has no attribute 'prefixlen'
This seems to be a rather embarrassing bug in IPy.
(Tech description: The IP class implementation naively assumes IP objects will only ever be compared with other IP objects, which in practice is not true. Witness it here being compared to macAddress objects during pretty-print formatting in Python's pprint module).
This pretty-printing only occurs in ipdevpoll when you have enabled DEBUG-level logging for the "nav.ipdevpoll.jobs.jobhandler-queue" logger. Unless you have a specific reason for running with DEBUG level logging on all parts of NAV, reconfiguring your logging levels would mitigate this.
Debian Wheezy appears to ship with IPy 0.75, whereas the bug seems to have been fixed in the 0.80 release. Version 0.81 is available in Debian testing (Jessie), so you could also fix the bug by installing the python-ipy package from there.
-- Morten Brekkevold UNINETT
On Mon, 7 Jul 2014 08:27:08 -0300 Bruno Galindro da Costa bruno.galindro@gmail.com wrote:
Morten,
I've upgraded the package and now the problem is other. Another thing is that the previous error was ocurring even running NAV without DEBUG setting in nav.ipdevpoll.jobs.jobhandler at /etc/nav/logging.conf. I've put it in DEBUG to provide more information about this error before starting this tread.
If there was a problem before you set the DEBUG level, then it must have been a different problem than the one you sent a traceback for. The specific traceback you sent showed the error to occur when attempting to debug-log the data structures that were being saved to the database.
This new problem seems to ocurring only with DEBUG setting... but Idon't know if this is true or false. Can you confirm it for me please?
Ah, yes. *headslap*. I was too quick when saying the bug was fixed in a newer IPy. They changed the code, but the comparison problem isn't really fixed. You still cannot compare IP objects to arbitrary other objects; the only difference is the type of exception raised when you attempt to. This isn't really good behavior for a Python object.
Even so, the only reason IP objects are being compared to non-IP objects is because Python's pprint insists on sorting dictionary keys for pretty-printing.
As long as the problem exists in IPy, all we can do is think of some workaround in NAV, at best. Maybe report a bug to the IPy guys. My mitigation tip is still valid though - you will likely never need to have debug level set for "nav.ipdevpoll.jobs.jobhandler-queue", unless a developer asks for it specifically :)
If there was a problem before you set the DEBUG level, then it must have been a different problem than the one you sent a traceback for. The specific traceback you sent showed the error to occur when attempting to debug-log the data structures that were being saved to the database.
Yes, you are right. This is the message that apeared in logs and I was thinked that is was an error... my mistake sorry... What this message means?
2014-07-03 10:26:32,806 [WARNING timestamps.timestampchecker] [topo 150.162.250.252] 'lldp': retrieved empty timestamp
As long as the problem exists in IPy, all we can do is think of some
workaround in NAV, at best. Maybe report a bug to the IPy guys. My mitigation tip is still valid though - you will likely never need to have debug level set for "nav.ipdevpoll.jobs.jobhandler-queue", unless a developer asks for it specifically :)
Ok!
2014-07-08 4:51 GMT-03:00 Morten Brekkevold morten.brekkevold@uninett.no:
On Mon, 7 Jul 2014 08:27:08 -0300 Bruno Galindro da Costa < bruno.galindro@gmail.com> wrote:
Morten,
I've upgraded the package and now the problem is other. Another thing
is
that the previous error was ocurring even running NAV without DEBUG
setting
in nav.ipdevpoll.jobs.jobhandler at /etc/nav/logging.conf. I've put it in DEBUG to provide more information about this error before starting this tread.
If there was a problem before you set the DEBUG level, then it must have been a different problem than the one you sent a traceback for. The specific traceback you sent showed the error to occur when attempting to debug-log the data structures that were being saved to the database.
This new problem seems to ocurring only with DEBUG setting... but Idon't know if this is true or false. Can you confirm it for me please?
Ah, yes. *headslap*. I was too quick when saying the bug was fixed in a newer IPy. They changed the code, but the comparison problem isn't really fixed. You still cannot compare IP objects to arbitrary other objects; the only difference is the type of exception raised when you attempt to. This isn't really good behavior for a Python object.
Even so, the only reason IP objects are being compared to non-IP objects is because Python's pprint insists on sorting dictionary keys for pretty-printing.
As long as the problem exists in IPy, all we can do is think of some workaround in NAV, at best. Maybe report a bug to the IPy guys. My mitigation tip is still valid though - you will likely never need to have debug level set for "nav.ipdevpoll.jobs.jobhandler-queue", unless a developer asks for it specifically :)
-- Morten Brekkevold UNINETT
On Wed, 9 Jul 2014 08:31:23 -0300 Bruno Galindro da Costa bruno.galindro@gmail.com wrote:
Yes, you are right. This is the message that apeared in logs and I was thinked that is was an error... my mistake sorry... What this message means?
2014-07-03 10:26:32,806 [WARNING timestamps.timestampchecker] [topo 150.162.250.252] 'lldp': retrieved empty timestamp
Normally, when the LLDP-MIB is properly implemented, one should be able to retrieve a timestamp (lldpStatsRemTablesLastChangeTime) that represents the sysUpTime of the system when the lldpRemTable was last updated.
NAV retrieves this timestamp before polling the lldpRemTable, so it can detect whether there have been any changes that warrant a new poll. If things are pretty static, this means NAV can avoid spending time on polling the device for the full lldpRemTable unnecessarily.
This warning message is NAV telling you that it couldn't retrieve a timestamp from this device, so it will poll the full lldpRemTable every time it checks for updates.
Thanks for explanation.
Is there any chance to put this kind of information in nav docs? Two interesting things were explained in this thread.
I'm here to help with this if you want... I'm work in a University in Brazil -> UFSC http://ufsc.br/ and I can help the project feeding the knowledge base whenever possible.
2014-07-11 10:46 GMT-03:00 Morten Brekkevold morten.brekkevold@uninett.no:
On Wed, 9 Jul 2014 08:31:23 -0300 Bruno Galindro da Costa < bruno.galindro@gmail.com> wrote:
Yes, you are right. This is the message that apeared in logs and I was thinked that is was an error... my mistake sorry... What this message
means?
2014-07-03 10:26:32,806 [WARNING timestamps.timestampchecker] [topo 150.162.250.252] 'lldp': retrieved empty timestamp
Normally, when the LLDP-MIB is properly implemented, one should be able to retrieve a timestamp (lldpStatsRemTablesLastChangeTime) that represents the sysUpTime of the system when the lldpRemTable was last updated.
NAV retrieves this timestamp before polling the lldpRemTable, so it can detect whether there have been any changes that warrant a new poll. If things are pretty static, this means NAV can avoid spending time on polling the device for the full lldpRemTable unnecessarily.
This warning message is NAV telling you that it couldn't retrieve a timestamp from this device, so it will poll the full lldpRemTable every time it checks for updates.
-- Morten Brekkevold UNINETT
-- Att. Bruno Galindro da Costa
On Fri, 11 Jul 2014 13:15:50 -0300 Bruno Galindro da Costa bruno.galindro@gmail.com wrote:
Thanks for explanation.
Is there any chance to put this kind of information in nav docs? Two interesting things were explained in this thread.
Sure, if you have suggestions on where it would fit in the existing docs. Our documentation practices could be a lot better.
I'm here to help with this if you want... I'm work in a University in Brazil -> UFSC http://ufsc.br/ and I can help the project feeding the knowledge base whenever possible.
We would love help with our docs, if you have something to contribute :-) It helps to know a bit about Sphinx [1], which we use as our documentation system, and a bit about Mercurial for version control.
Though our official code repository is hosted at nav.uninett.no, we use Bitbucket extensively when working. Our official repository is mirrored at [2], so the most seamless way to contribute is to fork that repo and send pull requests through Bitbucket.
[1] http://sphinx-doc.org/ [2] https://bitbucket.org/mbrekkevold/nav-mirror
-
Bruno Galindro da Costa -
Morten Brekkevold