Re: Ciscoworks User Tracking Switchport Report

jeffreydorn · ‎05-04-2010

I think I'm having an issue with the Swithport Report -> Reclaim Unused Up Report. I have roughly 150 switches and when I pull a report on all the switches the "Last Used" colum only shows 6 total dates. With over 2000 ports in this report, I have a hard time believing that there would only be 6 dates total for last seen. I upgraded RME at the beginning of the year and that deleted all my records, so I understand why the majority are Jan 1st dates, but the remaining dates seem to be random and don't follow a patten on why it would be working some days:

1/7 - Thurs

1/12 - Tues

1/13 - Wed

2/15 - Mon

2/25 - Thurs

3/18 - Thurs

I run a minor acquisition every 60 minutes, and a major is scheduled twice a day.

I know that the acquisition itself is working from pulling the "End Host" Report. This seems to be accurate and shows inactive ports every day.

Does anyone have an idea why this isn't showing up correctly in the Switchport Report?

Thanks

Joe Clarke · ‎05-05-2010

The reclaim reports will show all ports which had a user seen on those ports on a given date, but have since been free. For example, if UT acquires a user on a port 31 days ago, then today if you run a report for 30 days ago, you should see this port.

There's not much magic to how this report is generated. It's essentially direct SQL. Therefore, it would be useful to look at the data which is stored in the UT tables in the ANI database to see if there is a real problem. You could also change the number of days when running the report to something smaller (i.e. to line up with some inactive ports you see now), and see if the report shows correct results.

jeffreydorn · ‎05-10-2010

I changed the report to "Unused for 1 days". This gave me one more date in my list, 4/9/2010. Something is wrong, out of over 2500 down ports in this report, there are only 7 dates that show up for the "last used" column.

I'm not quite sure how to look at the data in the ANI database or what I should be looking for.

Joe Clarke · ‎05-10-2010

I rechecked the code, and the SQL to generate this report has changed in Campus 5.2. It no longer looks at UT data. It focuses on Data Collection information only. Every time Data Collection is run, the port admin and operation statuses are checked. If they are both up, then the port's last seen time is set to the current date and time. So if you are only seeing seven dates, then the ports must have been seen to have been up at other times. Alternatively, Data Collection may not be completing properly. Run a new Campus Data Collection, then post the ani.log.

jeffreydorn · ‎05-11-2010

OK, that makes sense. I've been focusing on User Tracking and that seems to be working properly.

My Data collection is not working properly, it shows last completion of 4/9/2010, the last date I have on the report. I tried to manually start a data collection, and it doesn't give me an error, but I don't think it runs. I do not see any jobs show up in the "recently completed jobs". Here is a sample of my ani.log (with IP's XXX out). I get a lot of "SNMP Exception on quering the interfaces on device XXX" messages. These are all old CatOS devices, so I understand why those aren't working properly. Looks like I'm also getting some Java errors.

Joe Clarke · ‎05-11-2010

There are no catatrophic errors here. Go to Campus Manager > Home, and click the Start Data Collection link. Run a new Data Collection for all devices. If this doesn't fix the problem, post the new ani.log.

jeffreydorn · ‎05-12-2010

I tried getting it to run, but nothing would happen. No error messages, just doesn't run. I rebooted the server and got it to run and it completed properly. But now it won't run again.

I have data collection to run every 4 hours, 7 days a week. The job doesn't seem to be working again. It did not run during it's scheduled time, and it did not run when I started it manually again. Again, no error messages nothing happens. Here is a a sample of the ani.log after I try to manually run it:

Validating License...

2010/05/12 12:16:06 NewMACPoller ani MESSAGE DBConnection: Created new Database connection [hashCode = 10752525]

Validating License...

2010/05/12 12:17:24 DBConnecton-Reaper ani MESSAGE DBConnection: Closed Database connection [hashCode = 10752525]

Validating License...

2010/05/12 12:26:27 RequestProcessor-9 ani WARNING AniLoadConfiguration: Discovery settings changed. Discovery restart requested.

2010/05/12 12:26:27 RequestProcessor-9 ani WARNING AniLoadConfiguration: rs.message-->

Validating License...

2010/05/12 12:28:18 RequestProcessor-9 ani WARNING AniLoadConfiguration: Discovery settings changed. Discovery restart requested.

2010/05/12 12:28:18 RequestProcessor-9 ani WARNING AniLoadConfiguration: rs.message-->

Validating License...

I'm not sure how to troubleshoot this.

Joe Clarke · ‎05-12-2010

It may take a reboot at this point to get a Data Collection to run until the point it fails. Try that. After the reboot, and after you run it, even if it reports it completed successfully, post the ani.log.

jeffreydorn · ‎05-13-2010

OK, I turned on all debugging and tried to manually run Data Collection. It looks like it is going to run, but nothing happens. I requested a manual scan at 10:23. Here is the output of the ani.log:

Validating License...

2010/05/13 10:38:10 DFMPoller ani AniTimeLine: normal wakeUp

2010/05/13 10:38:10 DFMPoller ani AniTimeLine: Setting timeline to running

2010/05/13 10:38:10 DFMPoller ani DFMPollerTimeBaseImpl: ...isEnabled property of DFMPoller is set as :off

2010/05/13 10:38:10 DFMPoller ani DFMPollerTimeBaseImpl: Clearing DFM information already Collected...as DFMPoller.enabled property is set to off

2010/05/13 10:38:10 DFMPoller ani DFMPollerTimeBaseImpl: ...isDataPresent:no

2010/05/13 10:38:10 DFMPoller ani DFMPollerTimeBaseImpl: DFM Data is not present

2010/05/13 10:38:10 DFMPoller ani DFMPollerTimeBaseImpl: DFM Data was already cleared...Did not clear in the current cycle

2010/05/13 10:38:10 DFMPoller ani DFMPollerTimeBaseImpl: ...Returning from perform schedule fn of DFM poller, as DFMPoller.enabled property is set to off

2010/05/13 10:38:10 DFMPoller ani AniTimeLine: Total memory: 86347776

2010/05/13 10:38:10 DFMPoller ani AniTimeLine: Free memory: 54191008

2010/05/13 10:38:10 DFMPoller ani AniTimeLine: starting sleep until: Thu May 13 10:44:10 CDT 2010 because: Periodic sleep

2010/05/13 10:38:10 DFMPoller ani AniTimeLine: Setting timeline to idle

Validating License...

2010/05/13 10:38:50 RequestProcessor-9 ani CoreServiceModule: This is a full data collection

2010/05/13 10:38:50 RequestProcessor-9 ani WARNING AniLoadConfiguration: Discovery settings changed. Discovery restart requested.

2010/05/13 10:38:50 RequestProcessor-9 ani WARNING AniLoadConfiguration: rs.message-->

Validating License...

2010/05/13 10:44:10 DFMPoller ani AniTimeLine: normal wakeUp

2010/05/13 10:44:10 DFMPoller ani AniTimeLine: Setting timeline to running

2010/05/13 10:44:10 DFMPoller ani DFMPollerTimeBaseImpl: ...isEnabled property of DFMPoller is set as :off

2010/05/13 10:44:10 DFMPoller ani DFMPollerTimeBaseImpl: Clearing DFM information already Collected...as DFMPoller.enabled property is set to off

2010/05/13 10:44:10 DFMPoller ani DFMPollerTimeBaseImpl: ...isDataPresent:no

2010/05/13 10:44:10 DFMPoller ani DFMPollerTimeBaseImpl: DFM Data is not present

2010/05/13 10:44:10 DFMPoller ani DFMPollerTimeBaseImpl: DFM Data was already cleared...Did not clear in the current cycle

2010/05/13 10:44:10 DFMPoller ani DFMPollerTimeBaseImpl: ...Returning from perform schedule fn of DFM poller, as DFMPoller.enabled property is set to off

2010/05/13 10:44:11 DFMPoller ani AniTimeLine: Total memory: 86347776

2010/05/13 10:44:11 DFMPoller ani AniTimeLine: Free memory: 54100304

2010/05/13 10:44:11 DFMPoller ani AniTimeLine: starting sleep until: Thu May 13 10:50:11 CDT 2010 because: Periodic sleep

2010/05/13 10:44:11 DFMPoller ani AniTimeLine: Setting timeline to idle

Validating License...

2010/05/13 10:46:32 NewMACPoller ani AniTimeLine: normal wakeUp

2010/05/13 10:46:32 NewMACPoller ani AniTimeLine: Setting timeline to running

2010/05/13 10:46:32 NewMACPoller ani Transaction: begin transaction

2010/05/13 10:46:32 NewMACPoller ani Transaction: Number of threads associated with this transaction com.cisco.nm.ani.server.framework.Transaction@14c583a = 1

2010/05/13 10:46:32 NewMACPoller ani AniTimeLineInfo: Recording times for NewMACPoller, start=Thu May 13 10:46:32 CDT 2010, end=Thu May 13 10:46:32 CDT 2010

2010/05/13 10:46:32 NewMACPoller ani AniTimeLineInfo: bind: _lastStart changed from 1273764691780 to 1273765592075

2010/05/13 10:46:32 NewMACPoller ani AniTimeLineInfo: bind: _lastEnd changed from 1273764691780 to 1273765592075

2010/05/13 10:46:32 NewMACPoller ani Transaction: commit transaction

2010/05/13 10:46:32 NewMACPoller ani Transaction: Fix for memory leak start...

2010/05/13 10:46:32 NewMACPoller ani Transaction: Number of elements in _ThreadObjectMap = 1

2010/05/13 10:46:32 NewMACPoller ani Transaction: Number of elements in _ThreadPOMap = 1

2010/05/13 10:46:32 NewMACPoller ani Transaction: Fix for memory leak End...

2010/05/13 10:46:32 NewMACPoller ani Transaction: Number of threads associated with this transaction com.cisco.nm.ani.server.framework.Transaction@14c583a = 1

2010/05/13 10:46:32 NewMACPoller ani Transaction: generated 1 protoEvents

2010/05/13 10:46:32 NewMACPoller ani Transaction: Committing 1 objects

2010/05/13 10:46:32 NewMACPoller ani MESSAGE DBConnection: Created new Database connection [hashCode = 2397714]

2010/05/13 10:46:32 NewMACPoller ani AniTimeLineInfo: modifying DB using: update WbuAniTimeLineInfo set lastEnd = '2010-05-13 10:46:32.075', timeBase = 'NewMACPoller', userName = NULL, lastStart = '2010-05-13 10:46:32.075' where dbId = 1

2010/05/13 10:46:32 NewMACPoller ani Transaction: Db Update done in 16 ms

2010/05/13 10:46:32 NewMACPoller ani Transaction: Sending event ID:PersistentData_Modify, Cat:EventCategory_PersistentData, ANI:ANIServer6.0-mnksrv152, SrcModule:ani.server.po, DestModule:, Host:, User:, Seq#: 0.0

DBTables: WbuAniTimeLineInfo DBIds: 1

2010/05/13 10:46:32 NewMACPoller ani Transaction: It took 0.0 seconds to send 0 alert events

2010/05/13 10:46:32 NewMACPoller ani Transaction: Sending event ID:PersistentData_EndOfSequence, Cat:EventCategory_PersistentData, ANI:ANIServer6.0-mnksrv152, SrcModule:ani.server.po, DestModule:, Host:, User:, Seq#: 0.0

DBTables: DBIds:

2010/05/13 10:46:32 NewMACPoller ani AniTimeLine: Total memory: 86347776

2010/05/13 10:46:32 NewMACPoller ani AniTimeLine: Free memory: 54064768

2010/05/13 10:46:32 NewMACPoller ani AniTimeLine: starting sleep until: Thu May 13 11:01:32 CDT 2010 because: Periodic sleep

2010/05/13 10:46:32 NewMACPoller ani AniTimeLine: Setting timeline to idle

Validating License...

2010/05/13 10:47:55 DBConnecton-Reaper ani MESSAGE DBConnection: Closed Database connection [hashCode = 2397714]

Validating License...

2010/05/13 10:50:11 DFMPoller ani AniTimeLine: normal wakeUp

2010/05/13 10:50:11 DFMPoller ani AniTimeLine: Setting timeline to running

2010/05/13 10:50:11 DFMPoller ani DFMPollerTimeBaseImpl: ...isEnabled property of DFMPoller is set as :off

2010/05/13 10:50:11 DFMPoller ani DFMPollerTimeBaseImpl: Clearing DFM information already Collected...as DFMPoller.enabled property is set to off

2010/05/13 10:50:11 DFMPoller ani DFMPollerTimeBaseImpl: ...isDataPresent:no

2010/05/13 10:50:11 DFMPoller ani DFMPollerTimeBaseImpl: DFM Data is not present

2010/05/13 10:50:11 DFMPoller ani DFMPollerTimeBaseImpl: DFM Data was already cleared...Did not clear in the current cycle

2010/05/13 10:50:11 DFMPoller ani DFMPollerTimeBaseImpl: ...Returning from perform schedule fn of DFM poller, as DFMPoller.enabled property is set to off

2010/05/13 10:50:11 DFMPoller ani AniTimeLine: Total memory: 86347776

2010/05/13 10:50:11 DFMPoller ani AniTimeLine: Free memory: 54045952

2010/05/13 10:50:11 DFMPoller ani AniTimeLine: starting sleep until: Thu May 13 10:56:11 CDT 2010 because: Periodic sleep

2010/05/13 10:50:11 DFMPoller ani AniTimeLine: Setting timeline to idle

Validating License...

I then rebooted the server and it ran fine again for one time, then it doesn't run again. Here is the end of the last collection that worked:

2010/05/13 12:04:23 Discovery ani CorexSMFGetDeviceDetails: 172.XXXXX9: Gi0/47 maps to physical port Gi0/47

2010/05/13 12:04:23 Discovery ani PortDetailsXml: PortStatusObj for port:C3550_12_1_11_EA1Port( Port(Gi0/48, 10148, 48, ethernetCsmacd, full-duplex, ok ) L2L3AdminMode - unknown L2L3OperMode - unknown ) is static

2010/05/13 12:04:23 Discovery ani PortDetailsXml: Checking UT allowed for Device: 172.21.90.69, port:Gi0/48

2010/05/13 12:04:23 Discovery ani PortDetailsXml: This is Trunk Port

2010/05/13 12:04:23 Discovery ani PortDetailsXml: DiscoveronTrunk: false

2010/05/13 12:04:23 Discovery ani CorexSMFGetDeviceDetails: 172.XXXXX9: Gi0/48 maps to physical port Gi0/48

2010/05/13 12:04:23 Discovery ani PortDetailsXml: TopoSMFGenerateCdpTopology.isLink(port): true

2010/05/13 12:04:23 Discovery ani PortDetailsXml: Port is trunking with AUxillary vlannull

2010/05/13 12:04:23 Discovery ani PortDetailsXml: Fetching the Discrepancies Count For Gi0/48

2010/05/13 12:04:23 Discovery ani PortDetailsXml: Done Discrepancies Count

2010/05/13 12:04:23 Discovery ani PortDetailsXml: Fetching the Best Practices Deviation Count For Gi0/48

2010/05/13 12:04:23 Discovery ani PortDetailsXml: Done Best Practices Deviation Count

2010/05/13 12:04:23 Discovery ani CorexSMFGetDeviceDetails: 172.XXXXXX9: Gi0/48 maps to physical port Gi0/48

2010/05/13 12:04:23 Discovery ani ERROR AniTimeLine: TimeBase Discovery caught exception: java.lang.NullPointerException

java.lang.NullPointerException

at com.objectspace.jgl.HashMap.put(HashMap.java)

at com.cisco.nm.ani.server.core.PortDetailsXml.populatePortData(PortDetailsXml.java:121)

at com.cisco.nm.ani.server.core.DiscoveryTimeBaseImpl.generatePortDetailsXml(DiscoveryTimeBaseImpl.java:132)

at com.cisco.nm.ani.server.core.DiscoveryTimeBaseImpl.postPerformScheduledFunction(DiscoveryTimeBaseImpl.java:93)

at com.cisco.nm.ani.server.frontend.AniTimeBaseImpl.execute(AniTimeBaseImpl.java:48)

at com.cisco.nm.ani.server.frontend.AniTimeLine.executeTimeBase(AniTimeLine.java:317)

at com.cisco.nm.ani.server.frontend.AniTimeLine.runSchedule(AniTimeLine.java:350)

at com.cisco.nm.ani.server.frontend.AniTimeLine.run(AniTimeLine.java:366)

at java.lang.Thread.run(Thread.java:595)

2010/05/13 12:04:23 Discovery ani AniTimeLine: Setting timeline to idle

Validating License...

2010/05/13 12:05:52 DBConnecton-Reaper ani MESSAGE DBConnection: Closed Database connection [hashCode = 14635167]

Validating License...

Joe Clarke · ‎05-13-2010

This is what I thought. You are seeing CSCtd49439. If you contact TAC, they can give you a patch to fix this.