DX Unified Infrastructure Management

  • 1.  Port unregister from active probe alarm_enrichment

    Posted Jul 03, 2018 12:36 PM

    Hi

     

    I am experiencing restart of alarm_enrichment probe randomly for months.

    Sometime it trigger a "Port unregister from active probe alarm_enrichment" alarm message to nas.

    On 25 Jun there was a power cycle of the virtual machine and it seem no such alarm was receive from nas as of 4 Jun.

    Although in the logs there is still indication of restart of alarm_enrichment as of 1 Jun.

    Admin Console also only indicate restart of alarm_enrichment probe on 1 Jun.

    Nas probe did not indicate any restart in admin console

     

    I want to know what is causing a restart of alarm_enrichment below is a section of the log of ( alarm_enrichment, nas, controller ) at level 3

     

    OS / CPU and memory specifications of the Primary hub OS Windows Server 2008 R2 Enterprise 8 (4 processers ) with 10 GB RAM Memory ( VMware Virtual Machine )
    Version of UIM 8.50
    Version of nas probe version 8.42
    Version of hub and controller on the Primary hub where this nas probe is running Hub Version 7.80 , Controller 7.80

     

    I have log a case with CA but would want a some view and suggestion from the communities.

     

    Alarm enrichment log indicate stop at Jul 01 22:14:51:852
    Jul 01 22:14:41:893 [pool-1-thread-17, alarm_enrichment] CmdbMessageEnricher: processAlarm matched on field: prid
    Jul 01 22:14:41:893 [pool-1-thread-17, alarm_enrichment] AlarmEnrichmentService: Forwarding alarm to alarmEnricher 3
    Jul 01 22:14:41:893 [pool-1-thread-17, alarm_enrichment] AlarmEnrichmentService: Forwarding alarm to alarmEnricher 4
    Jul 01 22:14:41:893 [pool-1-thread-17, alarm_enrichment] AlarmRouter: 1 is posting message with subject 'alarm2'
    Jul 01 22:14:51:852 [main, alarm_enrichment] ****************[ Stopped ]****************
    Jul 01 22:14:51:852 [main, alarm_enrichment] Nas: Shutdown requested by 'run.exit'
    Jul 01 22:14:52:939 [main, alarm_enrichment] CmdbMessageEnricherError closing : 'os_enricher' problem: null
    Jul 01 22:14:52:940 [main, alarm_enrichment] CmdbMessageEnricherError closing : 'os_enricher' problem: null
    Jul 01 22:14:52:940 [main, alarm_enrichment] CmdbMessageEnricherError closing : 'os_enricher' problem: null
    Jul 01 22:14:52:952 [main, alarm_enrichment] Nas: Shutdown complete in 599ms
    ul 01 22:14:54:862 [main, alarm_enrichment] ****************[ Starting ]****************
    Jul 01 22:14:54:867 [main, alarm_enrichment] 8.42
    Jul 01 22:14:55:005 [main, alarm_enrichment] Nas: Starting: Alarm Enrichment Process
    Jul 01 22:14:55:073 [main, alarm_enrichment] CmdbJdbcDataSource: GenericCmdbJdbcDataSource intializing with config path enrichment-source/cmdbs/os_enricher
    Jul 01 22:14:55:075 [main, alarm_enrichment] CmdbJdbcDataSource: connecting to database
    Jul 01 22:14:56:010 [main, alarm_enrichment] AlarmEnrichmentService: reXXXtering Alarm Matchers
    Jul 01 22:14:56:014 [prepopulationTimer, alarm_enrichment] prepopulate cache start: os_enricher
    Jul 01 22:14:56:284 [main, alarm_enrichment] RoutingService: loading all alarm routing-rules
    Jul 01 22:14:56:284 [main, alarm_enrichment] RoutingService: no router-specific target set, setting router target to default hub: /XXXdom/***/***/spooler
    Jul 01 22:14:56:289 [main, alarm_enrichment] RoutingService: successfully loaded alarm router '1' (true - alarm2 -true)
    Jul 01 22:14:56:289 [main, alarm_enrichment] RoutingService: no router-specific target set, setting router target to default hub: /XXXdom/***/***/spooler
    Jul 01 22:14:56:291 [main, alarm_enrichment] RoutingService: successfully loaded alarm router '2' (true - alarm2 -true)
    Jul 01 22:14:56:335 [prepopulationTimer, alarm_enrichment] CmdbCacheEnrichmentSource: received 1555 object for prepopulation. Prepopulating Cache...
    Jul 01 22:14:56:350 [prepopulationTimer, alarm_enrichment] prepopulate cache end: os_enricher
    Jul 01 22:14:57:976 [main, alarm_enrichment] AlarmQueueReader: Connection to queue 'alarm' established.
    Jul 01 22:14:58:205 [attach_clientsession, alarm_enrichment] AlarmQueueReader: _numberBulkReads:readCount 1:1

     

    Nas log indicate called on Jul  1 22:14:51:350Jul  1 22:14:45:495 [12248] nas: dbBeginTransaction subscriber, OK - rc:0
    Jul  1 22:14:45:501 [12248] nas: dbCommitTransaction subscriber, OK - rc:0
    Jul  1 22:14:45:501 [12248] nas: pubCommitMonitor:  subscr_waiting:  'flushUncommitedAlarms'
    Jul  1 22:14:45:501 [12248] nas: pubCommitMonitor:  subscr_released: 'flushUncommitedAlarms'
    Jul  1 22:14:48:449 [2132] nas: nsLookup ip:100.***.100.57 => '100.***.100.57' in 4500ms
    Jul  1 22:14:48:455 [5196] nas: dbBeginTransaction dbsRun, OK - rc:0
    Jul  1 22:14:50:700 [2132] nas: nsLookup ip:***-XXXm => '***-XXXm' in 0ms
    Jul  1 22:14:50:708 [5196] nas: dbBeginTransaction dbsRun, OK - rc:0
    Jul  1 22:14:50:732 [5196] nas: dbCommitTransaction dbsRun, OK - rc:0
    Jul  1 22:14:50:732 [5196] nas: dbsRun committed 6 requests. 0 remaining in queue...
    Jul  1 22:14:50:969 [10212] nas: nimSockaddr2Ip - found ***
    Jul  1 22:14:50:980 [10212] nas: (cbRestart) from ***/50531
    Jul  1 22:14:50:980 [10212] nas: ----------------[ RESTART  ]----------------
    Jul  1 22:14:50:980 [10212] nas: NAS Services called using mode: 0
    Jul  1 22:14:50:980 [10212] nas: Waiting for Event-Processor to stop...
    Jul  1 22:14:50:985 [5916] nas: NiS bridge: NTS UPDATED: nimid='CR41610909-56389' rc: 0
    Jul  1 22:14:50:986 [5916] nas: NiS bridge: NA UPDATED: nimid='CR41610909-56389' rc: 0
    Jul  1 22:14:51:074 [11028] nas: dbBeginTransaction actLogRun, OK - rc:0
    Jul  1 22:14:51:097 [11028] nas: dbCommitTransaction actLogRun, OK - rc:0
    Jul  1 22:14:51:347 [10212] nas: pubCommitMonitor:  pub_released:    'pub'
    Jul  1 22:14:51:348 [8776] nas: Event-Processor terminated...
    Jul  1 22:14:51:350 [10212] nas: alarm_enrichment call to '_stop' successful
    Jul  1 22:14:51:350 [10212] nas: maint Maintenance Mode Terminated
    Jul  1 22:14:51:350 [10212] nas: Destroying Subscriber...
    Jul  1 22:14:51:376 [6596] nas: Event publisher terminated, 0 items in queue...
    Jul  1 22:14:51:389 [12436] nas: The AlarmStats monitor terminated...
    Jul  1 22:14:51:391 [5916] nas: NiS bridge terminated...
    Jul  1 22:14:51:398 [11028] nas: Activity-Logger terminated...
    Jul  1 22:14:51:398 [12136] nas: The SpoolerConnector terminated
    Jul  1 22:14:51:399 [0844] nas: Transaction-Logger terminated...
    Jul  1 22:14:51:502 [10212] nas: Subscriber destroyed...
    Jul  1 22:14:51:502 [10212] nas: Destroying Correlation engine...
    Jul  1 22:14:51:502 [12248] nas: Subscriber terminated...
    Jul  1 22:14:51:904 [12388] nas: The replExporter terminated...
    Jul  1 22:14:51:975 [12216] nas: The replication importer terminated...
    Jul  1 22:14:52:002 [12580] nas: Rule engine terminating, 0 scripts running...
    Jul  1 22:14:52:002 [12580] nas: Rule engine terminated...
    Jul  1 22:14:52:002 [4052] nas: Correlation engine terminated...
    Jul  1 22:14:52:432 [11256] nas: Auto-Operator scheduler terminated...
    Jul  1 22:14:52:433 [10212] nas: Correlation engine destroyed...
    Jul  1 22:14:52:433 [10212] nas: Destroying the NiS bridge...
    Jul  1 22:14:52:438 [10212] nas: NiS bridge destroyed...
    Jul  1 22:14:52:438 [10212] nas: QosBridge - waiting for thread to complete.
    Jul  1 22:14:52:438 [10212] nas: QosBridge - destroyed...
    Jul  1 22:14:52:438 [10212] nas: Destroying Activity-Logger...
    Jul  1 22:14:52:438 [10212] nas: Activity-Logger destroyed...
    Jul  1 22:14:52:438 [10212] nas: Destroying Transaction-Logger...
    Jul  1 22:14:52:438 [10212] nas: Transaction-Logger destroyed...
    Jul  1 22:14:52:438 [10212] nas: Destroying Replication engine...
    Jul  1 22:14:54:327 [0720] nas: Replication engine terminated...
    Jul  1 22:14:54:327 [10212] nas: Replication engine destroyed...
    Jul  1 22:14:54:327 [10212] nas: maint Maintenance Mode Destroyed
    Jul  1 22:14:54:327 [10212] nas: Destroying Event publisher...
    Jul  1 22:14:54:327 [10212] nas: Event publisher destroyed...
    Jul  1 22:14:54:327 [10212] nas: Destroying NameService...
    Jul  1 22:14:55:201 [2132] nas: nsLookup ip:100.***.100.56 => '100.***.100.56' in 4501ms
    Jul  1 22:14:55:201 [2132] nas: NameService housekeeping is done in 2674644ms, 1724 records processed.
    Jul  1 22:14:55:203 [5196] nas: dbBeginTransaction dbsRun, OK - rc:0
    Jul  1 22:14:55:210 [5196] nas: dbCommitTransaction dbsRun, OK - rc:0
    Jul  1 22:14:55:210 [5196] nas: dbsRun committed 1 requests. 0 remaining in queue...
    Jul  1 22:14:55:701 [2132] nas: NameService terminated...
    Jul  1 22:14:55:703 [10212] nas: NameService destroyed...
    Jul  1 22:14:55:703 [10212] nas: Destroying Database service...
    Jul  1 22:14:55:710 [5196] nas: Database service terminated...
    Jul  1 22:14:55:710 [10212] nas: Database service destroyed...
    Jul  1 22:14:55:715 [10212] nas: ------------[ RESTART COMPLETED ]-------------
    Jul  1 22:14:55:715 [10212] nas: NAS Services called using mode: 1
    Jul  1 22:14:55:715 [5840] nas: [0x01ABB960] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:55:717 [10212] nas: maint Maintenance Mode Initialized
    Jul  1 22:14:55:717 [11076] nas: [0x01ABBAA0] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:55:718 [11076] nas: Event publisher started...
    Jul  1 22:14:55:718 [5840] nas: Database service started...
    Jul  1 22:14:55:718 [11224] nas: The SpoolerConnector started
    Jul  1 22:14:55:718 [4416] nas: The AlarmStats monitor started...
    Jul  1 22:14:55:739 [11664] nas: maint:  Successful reXXXtration to: maintenance_mode
    Jul  1 22:14:55:739 [11664] nas: maint: MM State: UNHEALTHY Maintenance Mode Re-ReXXXtration **SUCCESS**
    Jul  1 22:14:55:933 [10212] nas: The QosBridge initializing
    Jul  1 22:14:55:934 [10212] nas: [0x18F203D0] Database provider is 'SQLITE3', database 'transactionlog.db'
    Jul  1 22:14:55:934 [12320] nas: The QosBridge started
    Jul  1 22:14:55:934 [12320] nas: QosBridge - terminated
    Jul  1 22:14:55:950 [10212] nas: [0x1AAC0E50] Database provider is 'SQLITE3', database 'transactionlog.db'
    Jul  1 22:14:55:951 [5160] nas: Activity-Logger started...
    Jul  1 22:14:55:958 [11384] nas: [0x1AAD62E0] Database provider is 'SQLITE3', database 'transactionlog.db'
    Jul  1 22:14:55:958 [10212] nas: corrInitialize: Last Alive Time: 1530454495
    Jul  1 22:14:55:958 [11384] nas: Transaction-Logger started...
    Jul  1 22:14:55:958 [11384] nas: Transaction-log database housekeeping scheduled to Mon Jul 02 00:30, 2018
    Jul  1 22:14:55:964 [10212] nas: [0x1A85A3F0] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:55:966 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Maintenance 25 -'
    Jul  1 22:14:55:966 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Maintenance 27 -'
    Jul  1 22:14:55:966 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Maintenance 29 -'
    Jul  1 22:14:55:966 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Maintenance 30 -'
    Jul  1 22:14:55:966 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Maintenance 31 -'
    Jul  1 22:14:55:966 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Automatic cleanup of low-severity messages (3 days)'
    Jul  1 22:14:55:966 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Stops Incoming ticket sound if not new alarm'
    Jul  1 22:14:55:966 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Ticket Generation - *** *** *** XXXing Do not remove'
    Jul  1 22:14:55:966 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Ticket Generation - ***'
    Jul  1 22:14:55:966 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Creation of incident tickets base on major, minor and critical alarm'
    Jul  1 22:14:55:966 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Temp SMS Action'
    Jul  1 22:14:55:967 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Maintenance1 - ***-X *.XX, *.XX2 & *.XX6 - *** 12 Dec 17 - XX'
    Jul  1 22:14:55:967 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Ticket Generation - ***'
    Jul  1 22:14:55:967 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Copy of Temp SMS Action SMS trigger base on correlated events'
    Jul  1 22:14:55:968 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Ticket Generation - ***'
    Jul  1 22:14:55:968 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Ticket Generation - ***'
    Jul  1 22:14:55:969 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Ticket Generation - ***'
    Jul  1 22:14:55:970 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Ticket Generation - ***'
    Jul  1 22:14:55:983 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Maintenance12 - Req by *** XX for ***5 *Memory* on 11 Oct 17 until further notice - XX'
    Jul  1 22:14:55:990 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Ticket Generation - ***'
    Jul  1 22:14:55:995 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Ticket Generation - ***'
    Jul  1 22:14:55:996 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Maintenance2 - XXXapp01 and 02 req *** *** 27 Jun 2018 - ***'
    Jul  1 22:14:55:997 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Ticket Generation - ***'
    Jul  1 22:14:55:999 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Maintenance13 - Req by *** 010718 2215hrs by ***'
    Jul  1 22:14:55:999 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Ticket Generation - - ***'
    Jul  1 22:14:55:999 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Ticket Generation - ***1 ***'
    Jul  1 22:14:55:999 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Ticket Generation - ***'
    Jul  1 22:14:55:999 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Close Invisbile other alarm older than 30 min between 9-10am, 12-1 pm'
    Jul  1 22:14:56:000 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Ticket Generation ***'
    Jul  1 22:14:56:000 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:EMAIL critical (repost)'
    Jul  1 22:14:56:003 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Ticket Generation - ***'
    Jul  1 22:14:56:006 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Maintenance20 - Req by *** for *** on 19 Oct 17 at 1346 hrs'
    Jul  1 22:14:56:007 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Maintenance19 - req *** by *** on 260517 at 1400hrs - ***'
    Jul  1 22:14:56:007 [5160] nas: Activity-log XXXistration used 6ms, status: OK
    Jul  1 22:14:56:007 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Maintenance22 - *** 100.***.100.*** req *** - 27 Feb 2018 - XX'
    Jul  1 22:14:56:008 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Maintenance18 - ***-a & b  Waiting for CR (***) - 12Jul2017-***'
    Jul  1 22:14:56:008 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Ticket Generation - ***'
    Jul  1 22:14:56:008 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Maintenance8 - ***-a - 13Jul2017 - *** ***- XX'
    Jul  1 22:14:56:008 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Maintenance7 - *** *** *** *** until )6 Dec 2017 9 pm'
    Jul  1 22:14:56:009 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Maintenance17 -XXXX,XXXX 26092017 *** XX'
    Jul  1 22:14:56:009 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Ticket Generation - XXXDB'
    Jul  1 22:14:56:009 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Maintenance 28 - *** 100.***.100.*** req *** 2:50pm 28 June 2018 -***'
    Jul  1 22:14:56:012 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Maintenance10 -***144,145, req *** - ***'
    Jul  1 22:14:56:012 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Upgrade1 - SNMP Agent not responding Upgrade from Warn to Yellow if count more than 7 - *** , for all projects 2909'
    Jul  1 22:14:56:012 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Close Clear alarm when it is not assigned'
    Jul  1 22:14:56:016 [10212] nas: Trigger state changed to TRUE , '__INTERNAL:Maintenance9 - ***1 per *** on 2 May 18 at 0953 am - ***'
    Jul  1 22:14:56:040 [10212] nas: corrInitialize: initialized state engine in 76 ms.
    Jul  1 22:14:56:040 [10212] nas: [0x1A85A760] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:040 [8972] nas: Correlation engine started...
    Jul  1 22:14:56:041 [3200] nas: Auto-Operator scheduler started...
    Jul  1 22:14:56:041 [6608] nas: Rule engine started...
    Jul  1 22:14:56:041 [6608] nas: [0x1AAD63D0] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:041 [3200] nas: Scheduler rescheduled profile:'***-XXXXX (warning every 28days)', next run Fri Jul 13 10:45, 2018
    Jul  1 22:14:56:043 [10212] nas: scanning dir.: replication
    Jul  1 22:14:56:043 [10212] nas: [0x1A85A620] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:043 [9688] nas: Replication engine started...
    Jul  1 22:14:56:043 [12880] nas: The replImporter started...
    Jul  1 22:14:56:044 [10328] nas: The replExporter started...
    Jul  1 22:14:56:044 [6608] nas: ExecEvent: OVERDUE rule='Close Clear alarm when it is not assigned', trigger='internal', nimid=ZO82521146-04327, age=6338s, ACTION:close
    Jul  1 22:14:56:044 [6608] nas: ExecEvent: Rule='Close Clear alarm when it is not assigned' on nimid='ZO82521146-04327' with ACTION:close, age:6338s, status:OK
    Jul  1 22:14:56:049 [5840] nas: dbBeginTransaction dbsRun, OK - rc:0
    Jul  1 22:14:56:054 [13288] nas: [0x0E2E5230] Database provider is 'SQLOLEDB', database 'NimsoftSLM'
    Jul  1 22:14:56:063 [10212] nas: nsInitialize used 19ms to initialize.
    Jul  1 22:14:56:063 [10212] nas: [0x1A85A620] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:064 [7644] nas: NameService started...
    Jul  1 22:14:56:064 [5320] nas: Subscriber started, subject:'alarm2'
    Jul  1 22:14:56:064 [13132] nas: [0x1AAF0530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:064 [13132] nas: Event-Processor started...
    Jul  1 22:14:56:064 [10212] nas: (get_info) - called from ***/58137
    Jul  1 22:14:56:064 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:076 [5840] nas: dbCommitTransaction dbsRun, OK - rc:0
    Jul  1 22:14:56:076 [5840] nas: dbsRun committed 2 requests. 0 remaining in queue...
    Jul  1 22:14:56:084 [10212] nas: (get_info) - called from ***/58136
    Jul  1 22:14:56:084 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:089 [13132] nas: _processEvents 3 of 1000 in 24 ms.
    Jul  1 22:14:56:089 [13132] nas: Event-Processor: published 3 messages in 24ms, 0 in queue.
    Jul  1 22:14:56:092 [10212] nas: (get_info) - called from ***/58135
    Jul  1 22:14:56:093 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:098 [10212] nas: (get_info) - called from ***/58130
    Jul  1 22:14:56:098 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:101 [10212] nas: (get_info) - called from ***/58128
    Jul  1 22:14:56:102 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:105 [10212] nas: (get_info) - called from ***/58125
    Jul  1 22:14:56:105 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:107 [5160] nas: dbBeginTransaction actLogRun, OK - rc:0
    Jul  1 22:14:56:108 [10212] nas: (get_info) - called from ***/58121
    Jul  1 22:14:56:108 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:111 [10212] nas: (get_info) - called from ***/58118
    Jul  1 22:14:56:111 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:114 [10212] nas: (get_info) - called from ***/58116
    Jul  1 22:14:56:114 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:118 [10212] nas: (get_info) - called from ***/50604
    Jul  1 22:14:56:118 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:125 [5160] nas: dbCommitTransaction actLogRun, OK - rc:0
    Jul  1 22:14:56:158 [11384] nas: dbBeginTransaction tlogRun, OK - rc:0
    Jul  1 22:14:56:169 [4416] nas: [0x01ACE130] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:176 [11384] nas: dbCommitTransaction tlogRun, OK - rc:0
    Jul  1 22:14:56:184 [13288] nas: [0x0E2E5800] Database provider is 'SQLOLEDB', database 'NimsoftSLM'
    Jul  1 22:14:56:211 [13288] nas: NiS bridge: current database provider is SQLSERVER - 6.1
    Jul  1 22:14:56:224 [13288] nas: NiS bridge: Discovery version: 6.210000
    Jul  1 22:14:56:225 [13288] nas: [0x0E2E57B0] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:247 [10212] nas: (get_info) - called from ***/58146
    Jul  1 22:14:56:247 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:251 [10212] nas: (get_info) - called from ***/58148
    Jul  1 22:14:56:251 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:753 [10212] nas: (get_info) - called from ***/58152
    Jul  1 22:14:56:753 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:757 [10212] nas: (get_info) - called from ***/58154
    Jul  1 22:14:56:757 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:760 [10212] nas: (get_info) - called from ***/58158
    Jul  1 22:14:56:760 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:764 [10212] nas: (get_info) - called from ***/58164
    Jul  1 22:14:56:764 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:767 [10212] nas: (get_info) - called from ***/58166
    Jul  1 22:14:56:767 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:771 [10212] nas: (get_info) - called from ***/58170
    Jul  1 22:14:56:771 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:774 [10212] nas: (get_info) - called from ***/58175
    Jul  1 22:14:56:774 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:777 [10212] nas: (get_info) - called from ***/58173
    Jul  1 22:14:56:777 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:781 [10212] nas: (get_info) - called from ***/58161
    Jul  1 22:14:56:781 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:843 [13288] nas: [0x0E2E57B0] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:871 [10212] nas: (get_info) - called from ***/58178
    Jul  1 22:14:56:871 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:875 [10212] nas: (get_info) - called from ***/58181
    Jul  1 22:14:56:875 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:884 [13288] nas: [0x0E2E57B0] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:56:975 [5320] nas: Successfully attached to HUB.
    Jul  1 22:14:57:136 [10212] nas: (get_info) - called from ***/50684
    Jul  1 22:14:57:136 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:57:344 [13288] nas: NiS bridge: synchronized alarms in 1120ms
    Jul  1 22:14:57:345 [13288] nas: [0x0E2E57B0] Database provider is 'SQLITE3', database 'transactionlog.db'
    Jul  1 22:14:57:963 [13288] nas: COM Error [0x80040e2f] IDispatch error #3119 - [Microsoft OLE DB Provider for SQL Server] Violation of UNIQUE KEY constraint 'UQ__NAS_TRAN__XXXXE'. Cannot insert duplicate key in object 'dbo.NAS_TRANSACTION_SUMMARY'. The duplicate key value is (ZO82521146-04327).
    Jul  1 22:14:57:963 [13288] nas: ndbTableInsert error: error, '[Microsoft OLE DB Provider for SQL Server] Violation of UNIQUE KEY constraint 'UQ__NAS_TRAN__XXXXE'. Cannot insert duplicate key in object 'dbo.NAS_TRANSACTION_SUMMARY'. The duplicate key value is (ZO82521146-04327).'
    Jul  1 22:14:57:966 [13288] nas: NiS bridge: synchronized alarm transactions in 622ms
    Jul  1 22:14:57:966 [13288] nas: NiS bridge started...
    Jul  1 22:14:57:968 [13288] nas: NiS bridge: NTS UPDATED CLOSE: nimid='ZO82521146-04327' rc: 0
    Jul  1 22:14:57:975 [5320] nas: Subscriber processed 1 msg.,0 updates the last 15s, 0.07 msg/s, queued:1
    Jul  1 22:14:57:987 [13288] nas: NiS bridge: NA UPDATED CLOSE: nimid='ZO82521146-04327' rc: 0
    Jul  1 22:14:58:147 [10212] nas: (get_info) - called from ***/50686
    Jul  1 22:14:58:147 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:14:58:317 [13288] nas: CreateDevCS map used 267ms
    Jul  1 22:14:58:324 [7644] nas: ptNetIpToHost - getaddrinfo failed for ***8
    Jul  1 22:14:58:324 [7644] nas: nsLookup ip:***8 => '***8' in 2250ms
    Jul  1 22:14:58:324 [7644] nas: nsLookup ip:*** => '***' in 0ms
    Jul  1 22:14:58:324 [7644] nas: nsLookup ip:100.***.100.8 => '***8-XXXm' in 0ms
    Jul  1 22:14:58:333 [5840] nas: dbBeginTransaction dbsRun, OK - rc:0
    Jul  1 22:14:58:352 [5840] nas: dbCommitTransaction dbsRun, OK - rc:0
    Jul  1 22:14:58:352 [5840] nas: dbsRun committed 3 requests. 0 remaining in queue...
    Jul  1 22:14:58:981 [5320] nas: dbBeginTransaction subscriber, OK - rc:0
    Jul  1 22:14:59:661 [10212] nas: (ao_status) from ***/50687
    Jul  1 22:14:59:983 [5320] nas: dbCommitTransaction subscriber, OK - rc:0
    Jul  1 22:14:59:983 [5320] nas: pubCommitMonitor:  subscr_waiting:  'flushUncommitedAlarms'
    Jul  1 22:14:59:983 [5320] nas: pubCommitMonitor:  subscr_released: 'flushUncommitedAlarms'
    Jul  1 22:15:02:363 [10212] nas: (get_info) - called from ***/58191
    Jul  1 22:15:02:363 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:02:369 [10212] nas: (get_info) - called from ***/58197
    Jul  1 22:15:02:369 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:02:373 [10212] nas: (get_info) - called from ***/58199
    Jul  1 22:15:02:373 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:02:378 [10212] nas: (get_info) - called from ***/58211
    Jul  1 22:15:02:378 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:02:381 [10212] nas: (get_info) - called from ***/58210
    Jul  1 22:15:02:381 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:02:385 [10212] nas: (get_info) - called from ***/58209
    Jul  1 22:15:02:385 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:02:388 [10212] nas: (get_info) - called from ***/58208
    Jul  1 22:15:02:388 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:02:391 [10212] nas: (get_info) - called from ***/58207
    Jul  1 22:15:02:391 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:02:395 [10212] nas: (get_info) - called from ***/58206
    Jul  1 22:15:02:395 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:02:398 [10212] nas: (get_info) - called from ***/58205
    Jul  1 22:15:02:398 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:02:401 [10212] nas: (get_info) - called from ***/58198
    Jul  1 22:15:02:401 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:02:825 [7644] nas: nsLookup ip:*** => '***' in 4501ms
    Jul  1 22:15:02:827 [5840] nas: dbBeginTransaction dbsRun, OK - rc:0
    Jul  1 22:15:02:832 [5840] nas: dbCommitTransaction dbsRun, OK - rc:0
    Jul  1 22:15:02:832 [5840] nas: dbsRun committed 1 requests. 0 remaining in queue...
    Jul  1 22:15:05:075 [7644] nas: ptNetIpToHost - getaddrinfo failed for ***9
    Jul  1 22:15:05:075 [7644] nas: nsLookup ip:***9 => '***9' in 2250ms
    Jul  1 22:15:05:079 [5840] nas: dbBeginTransaction dbsRun, OK - rc:0
    Jul  1 22:15:05:085 [5840] nas: dbCommitTransaction dbsRun, OK - rc:0
    Jul  1 22:15:05:085 [5840] nas: dbsRun committed 1 requests. 0 remaining in queue...
    Jul  1 22:15:07:983 [5320] nas: Subscriber processed 1 msg.,0 updates the last 10s, 0.10 msg/s, queued:1
    Jul  1 22:15:09:577 [7644] nas: nsLookup ip:100.***.100.12 => '100.***.100.12' in 4502ms
    Jul  1 22:15:09:581 [5840] nas: dbBeginTransaction dbsRun, OK - rc:0
    Jul  1 22:15:09:588 [5840] nas: dbCommitTransaction dbsRun, OK - rc:0
    Jul  1 22:15:09:588 [5840] nas: dbsRun committed 1 requests. 0 remaining in queue...
    Jul  1 22:15:10:049 [5320] nas: dbBeginTransaction subscriber, OK - rc:0
    Jul  1 22:15:10:142 [5320] nas: dbCommitTransaction subscriber, OK - rc:0
    Jul  1 22:15:10:142 [5320] nas: pubCommitMonitor:  subscr_waiting:  'flushUncommitedAlarms'
    Jul  1 22:15:10:142 [5320] nas: pubCommitMonitor:  subscr_released: 'flushUncommitedAlarms'
    Jul  1 22:15:11:128 [13132] nas: _processEvents 1 of 1000 in 25 ms.
    Jul  1 22:15:11:128 [13132] nas: Event-Processor: published 1 messages in 25ms, 0 in queue.
    Jul  1 22:15:11:206 [11384] nas: dbBeginTransaction tlogRun, OK - rc:0
    Jul  1 22:15:11:210 [4416] nas: [0x1A5D4AD0] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:11:242 [11384] nas: dbCommitTransaction tlogRun, OK - rc:0
    Jul  1 22:15:11:827 [7644] nas: ptNetIpToHost - getaddrinfo failed for ***7
    Jul  1 22:15:11:827 [7644] nas: nsLookup ip:***7 => '***7' in 2250ms
    Jul  1 22:15:11:827 [7644] nas: nsLookup ip:XXXha => 'XXXha' in 0ms
    Jul  1 22:15:11:835 [5840] nas: dbBeginTransaction dbsRun, OK - rc:0
    Jul  1 22:15:11:842 [5840] nas: dbCommitTransaction dbsRun, OK - rc:0
    Jul  1 22:15:11:842 [5840] nas: dbsRun committed 2 requests. 0 remaining in queue...
    Jul  1 22:15:22:124 [10212] nas: (get_info) - called from ***/51552
    Jul  1 22:15:22:124 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:22:983 [10212] nas: (ao_status) from ***/51555
    Jul  1 22:15:23:078 [7644] nas: ptNetIpToHost - getaddrinfo failed for ***8
    Jul  1 22:15:23:078 [7644] nas: nsLookup ip:***8 => '***8' in 2250ms
    Jul  1 22:15:23:087 [5840] nas: dbBeginTransaction dbsRun, OK - rc:0
    Jul  1 22:15:23:094 [5840] nas: dbCommitTransaction dbsRun, OK - rc:0
    Jul  1 22:15:23:094 [5840] nas: dbsRun committed 1 requests. 0 remaining in queue...
    Jul  1 22:15:26:149 [13132] nas: _processEvents 7 of 1000 in 6 ms.
    Jul  1 22:15:26:149 [13132] nas: Event-Processor: published 7 messages in 6ms, 0 in queue.
    Jul  1 22:15:26:153 [11384] nas: dbBeginTransaction tlogRun, OK - rc:0
    Jul  1 22:15:26:162 [4416] nas: [0x0CFD5D80] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:26:172 [11384] nas: dbCommitTransaction tlogRun, OK - rc:0
    Jul  1 22:15:26:419 [10212] nas: (get_info) - called from ***/58279
    Jul  1 22:15:26:419 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:26:424 [10212] nas: (get_info) - called from ***/58282
    Jul  1 22:15:26:424 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:26:429 [10212] nas: (get_info) - called from ***/58295
    Jul  1 22:15:26:429 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:26:435 [10212] nas: (get_info) - called from ***/58302
    Jul  1 22:15:26:435 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:26:440 [10212] nas: (get_info) - called from ***/58301
    Jul  1 22:15:26:440 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:26:444 [10212] nas: (get_info) - called from ***/58300
    Jul  1 22:15:26:444 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:26:449 [10212] nas: (get_info) - called from ***/58299
    Jul  1 22:15:26:449 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:26:454 [10212] nas: (get_info) - called from ***/58298
    Jul  1 22:15:26:454 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:26:459 [10212] nas: (get_info) - called from ***/58297
    Jul  1 22:15:26:459 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:26:462 [10212] nas: (get_info) - called from ***/58296
    Jul  1 22:15:26:462 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:26:465 [10212] nas: (get_info) - called from ***/58285
    Jul  1 22:15:26:465 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:26:608 [5320] nas: dbBeginTransaction subscriber, OK - rc:0
    Jul  1 22:15:27:027 [10212] nas: (get_info) - called from ***/58306
    Jul  1 22:15:27:028 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:27:031 [10212] nas: (get_info) - called from ***/58309
    Jul  1 22:15:27:031 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:27:035 [10212] nas: (get_info) - called from ***/58312
    Jul  1 22:15:27:035 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:27:038 [10212] nas: (get_info) - called from ***/58318
    Jul  1 22:15:27:038 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:27:042 [10212] nas: (get_info) - called from ***/58319
    Jul  1 22:15:27:042 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:27:045 [10212] nas: (get_info) - called from ***/58326
    Jul  1 22:15:27:045 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:27:048 [10212] nas: (get_info) - called from ***/58328
    Jul  1 22:15:27:048 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:27:052 [10212] nas: (get_info) - called from ***/58334
    Jul  1 22:15:27:052 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:27:055 [10212] nas: (get_info) - called from ***/58333
    Jul  1 22:15:27:055 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:27:058 [10212] nas: (get_info) - called from ***/58323
    Jul  1 22:15:27:058 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:27:062 [10212] nas: (get_info) - called from ***/58315
    Jul  1 22:15:27:062 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:27:580 [7644] nas: nsLookup ip:100.***.100.11 => '100.***.100.11' in 4502ms
    Jul  1 22:15:27:613 [5320] nas: dbCommitTransaction subscriber, OK - rc:0
    Jul  1 22:15:27:613 [5320] nas: pubCommitMonitor:  subscr_waiting:  'flushUncommitedAlarms'
    Jul  1 22:15:27:613 [5320] nas: pubCommitMonitor:  subscr_released: 'flushUncommitedAlarms'
    Jul  1 22:15:27:613 [5320] nas: Subscriber processed 6 msg.,4 updates the last 10s, 0.60 msg/s, queued:1
    Jul  1 22:15:27:622 [5840] nas: dbBeginTransaction dbsRun, OK - rc:0
    Jul  1 22:15:27:627 [5840] nas: dbCommitTransaction dbsRun, OK - rc:0
    Jul  1 22:15:27:627 [5840] nas: dbsRun committed 1 requests. 0 remaining in queue...
    Jul  1 22:15:29:841 [7644] nas: ptNetIpToHost - getaddrinfo failed for ***6
    Jul  1 22:15:29:841 [7644] nas: nsLookup ip:***6 => '***6' in 2261ms
    Jul  1 22:15:29:841 [7644] nas: nsLookup ip:100.***.100.22 => '***' in 0ms
    Jul  1 22:15:29:845 [5840] nas: dbBeginTransaction dbsRun, OK - rc:0
    Jul  1 22:15:29:852 [5840] nas: dbCommitTransaction dbsRun, OK - rc:0
    Jul  1 22:15:29:852 [5840] nas: dbsRun committed 2 requests. 0 remaining in queue...
    Jul  1 22:15:30:910 [10212] nas: nimSockaddr2Ip - found ***
    Jul  1 22:15:30:911 [10212] nas: (script_list) from ***/51904
    Jul  1 22:15:30:911 [10212] nas: scanning dir.: scripts
    Jul  1 22:15:30:911 [10212] nas: scanning dir.: scripts\examples
    Jul  1 22:15:30:911 [10212] nas: match file: copy of nsdconnector-process-alarm-on-arrival
    Jul  1 22:15:30:911 [10212] nas: match file: example-alarm-operations
    Jul  1 22:15:30:911 [10212] nas: match file: example-correlation
    Jul  1 22:15:30:911 [10212] nas: match file: example-database-operations
    Jul  1 22:15:30:911 [10212] nas: match file: example-file-operations
    Jul  1 22:15:30:911 [10212] nas: match file: example-get-probe-config
    Jul  1 22:15:30:911 [10212] nas: match file: example-html-email-alarms
    Jul  1 22:15:30:911 [10212] nas: match file: example-html-email-triggers
    Jul  1 22:15:30:911 [10212] nas: match file: example-nimbus-qos
    Jul  1 22:15:30:911 [10212] nas: match file: example-nimbus-request
    Jul  1 22:15:30:911 [10212] nas: match file: example-note-operations
    Jul  1 22:15:30:911 [10212] nas: match file: example-process-alarm-on-arrival
    Jul  1 22:15:30:911 [10212] nas: match file: example-string-operations
    Jul  1 22:15:30:911 [10212] nas: match file: example-time-functions
    Jul  1 22:15:30:911 [10212] nas: match file: example-using-variables
    Jul  1 22:15:30:911 [10212] nas: match file: example-xml-alarms
    Jul  1 22:15:30:911 [10212] nas: match file: nsdconnector-process-alarm-on-arrival
    Jul  1 22:15:30:911 [10212] nas: match file: resetalarmmessage
    Jul  1 22:15:30:911 [10212] nas: scanning dir.: scripts\library
    Jul  1 22:15:30:911 [10212] nas: match file: html-alarms-lib
    Jul  1 22:15:30:911 [10212] nas: match file: xml-alarms-lib
    Jul  1 22:15:31:958 [13132] nas: _processEvents 1 of 1000 in 808 ms.
    Jul  1 22:15:31:958 [13132] nas: Event-Processor: published 1 messages in 808ms, 1 in queue.
    Jul  1 22:15:32:003 [11384] nas: dbBeginTransaction tlogRun, OK - rc:0
    Jul  1 22:15:32:009 [11384] nas: dbCommitTransaction tlogRun, OK - rc:0
    Jul  1 22:15:32:094 [7644] nas: ptNetIpToHost - getaddrinfo failed for ***
    Jul  1 22:15:32:094 [7644] nas: nsLookup ip:*** => '***' in 2253ms
    Jul  1 22:15:32:094 [7644] nas: nsLookup ip:*** => '***' in 0ms
    Jul  1 22:15:32:094 [7644] nas: nsLookup ip:*** => '***' in 0ms
    Jul  1 22:15:32:094 [7644] nas: nsLookup ip:100.***.100.6 => '***6-XXXm' in 0ms
    Jul  1 22:15:32:103 [5840] nas: dbBeginTransaction dbsRun, OK - rc:0
    Jul  1 22:15:32:110 [5840] nas: dbCommitTransaction dbsRun, OK - rc:0
    Jul  1 22:15:32:110 [5840] nas: dbsRun committed 4 requests. 0 remaining in queue...
    Jul  1 22:15:32:554 [10212] nas: (get_info) - called from ***/58347
    Jul  1 22:15:32:554 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:32:562 [10212] nas: (get_info) - called from ***/58357
    Jul  1 22:15:32:562 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:32:566 [10212] nas: (get_info) - called from ***/58359
    Jul  1 22:15:32:566 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:32:569 [10212] nas: (get_info) - called from ***/58358
    Jul  1 22:15:32:569 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:32:574 [10212] nas: (get_info) - called from ***/58361
    Jul  1 22:15:32:574 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:32:589 [10212] nas: (get_info) - called from ***/58367
    Jul  1 22:15:32:589 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:32:592 [10212] nas: (get_info) - called from ***/58366
    Jul  1 22:15:32:592 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:32:596 [10212] nas: (get_info) - called from ***/58365
    Jul  1 22:15:32:596 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:32:599 [10212] nas: (get_info) - called from ***/58364
    Jul  1 22:15:32:599 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:32:603 [10212] nas: (get_info) - called from ***/58363
    Jul  1 22:15:32:603 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:32:606 [10212] nas: (get_info) - called from ***/58362
    Jul  1 22:15:32:606 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:34:503 [10212] nas: (get_info) - called from ***/58370
    Jul  1 22:15:34:503 [10212] nas: [0x1A85A530] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:36:595 [7644] nas: nsLookup ip:*** => '***' in 4501ms
    Jul  1 22:15:36:603 [5840] nas: dbBeginTransaction dbsRun, OK - rc:0
    Jul  1 22:15:36:608 [5840] nas: dbCommitTransaction dbsRun, OK - rc:0
    Jul  1 22:15:36:608 [5840] nas: dbsRun committed 1 requests. 0 remaining in queue...
    Jul  1 22:15:36:964 [13132] nas: _processEvents 1 of 1000 in 5 ms.
    Jul  1 22:15:36:964 [13132] nas: Event-Processor: published 1 messages in 5ms, 0 in queue.
    Jul  1 22:15:37:011 [4416] nas: [0x1BAE14D0] Database provider is 'SQLITE3', database 'database.db'
    Jul  1 22:15:37:015 [11384] nas: dbBeginTransaction tlogRun, OK - rc:0
    Jul  1 22:15:37:025 [11384] nas: dbCommitTransaction tlogRun, OK - rc:0
    Jul  1 22:15:37:196 [10212] nas: (ao_status) from ***/51948
    Jul  1 22:15:37:947 [5320] nas: Subscriber processed 1 msg.,1 updates the last 10s, 0.10 msg/s, queued:1
    Jul  1 22:15:38:845 [7644] nas: ptNetIpToHost - getaddrinfo failed for 92729086
    Jul  1 22:15:38:845 [7644] nas: nsLookup ip:92729086 => '92729086' in 2250ms
    Jul  1 22:15:38:851 [5840] nas: dbBeginTransaction dbsRun, OK - rc:0
    Jul  1 22:15:38:857 [5840] nas: dbCommitTransaction dbsRun, OK - rc:0
    Jul  1 22:15:38:857 [5840] nas: dbsRun committed 1 requests. 0 remaining in queue...
    Jul  1 22:15:40:536 [13288] nas: COM Error [0x80040e31] IDispatch error #3121 - [Microsoft OLE DB Provider for SQL Server] Query timeout expired
    Jul  1 22:15:40:536 [13288] nas: NiS-Bridge: Transaction-log XXXistration, failed to remove transaction entries older than 365 days.
    Jul  1 22:15:41:095 [7644] nas: ptNetIpToHost - getaddrinfo failed for ***7
    Jul  1 22:15:41:095 [7644] nas: nsLookup ip:***7 => '***7' in 2250ms
    Jul  1 22:15:41:095 [7644] nas: ptNetIpToHost - getaddrinfo failed for ***7.***.com
    Jul  1 22:15:41:095 [7644] nas: nsLookup ip:***7.***.com => '***7.***.com' in 0ms
    Jul  1 22:15:4*** [5840] nas: dbBeginTransaction dbsRun, OK - rc:0
    Jul  1 22:15:41:108 [5840] nas: dbCommitTransaction dbsRun, OK - rc:0
    Jul  1 22:15:41:108 [5840] nas: dbsRun committed 2 requests. 0 remaining in queue...

     

     

    Controller log indicate stopped on Jul  1 22:14:53:559
    Jul  1 22:14:52:994 [1408] Controller: (async)cb_hub_acallback done
    Jul  1 22:14:52:995 [1408] Controller: RREQUEST: _close <-***/50607  h=296 d=0
    Jul  1 22:14:53:559 [1408] Controller: Process stopped (probe=alarm_enrichment, pid=4100)
    Jul  1 22:14:53:573 [1408] Controller: probeGenerateMagicKey for alarm_enrichment
    Jul  1 22:14:53:573 [1408] Controller: probeFindCRCs for alarm_enrichment
    Jul  1 22:14:53:843 [1408] Controller: probeFindCRCs - 0
    Jul  1 22:14:53:843 [1408] Controller: probeGenerateMagicKey - LL0P0tM9FJtztfSmSrctGJvBeS9npPNUHUNlOKZpHU7UYiSOwCVgJvJm1KNUHmOq20dlM10GQ9a98LRJ8zTnUw==
    Jul  1 22:14:53:843 [1408] Controller: reserve_port (alarm_enrichment) starting at 48000
    Jul  1 22:14:53:843 [1408] Controller: sockGetFreePortStartingFrom: 48007: using fam=2 strict=0
    Jul  1 22:14:53:844 [1408] Controller: sockGetFreePortStartingFrom: 48022: using fam=2 strict=0
    Jul  1 22:14:53:845 [1408] Controller: reserve_port (alarm_enrichment) - assigned to 48023
    Jul  1 22:14:53:845 [1408] Controller: _ProcStart - Startup command for alarm_enrichment: ../../../../$NIM_JRE_HOME/bin/java.exe
    Jul  1 22:14:53:845 [1408] Controller: MyStringExpand (../../../../$NIM_JRE_HOME/bin/java.exe)...
    Jul  1 22:14:53:845 [1408] Controller: MyStringExpand - expanded to ../../../../jre/jre7/bin/java.exe
    Jul  1 22:14:53:845 [1408] Controller: MyStringExpand (-Xms2048m -Xmx3072m)...
    Jul  1 22:14:53:845 [1408] Controller: MyStringExpand (-Dfile.encoding=UTF-8 -jar ../lib/alarm_enrichment.jar)...
    Jul  1 22:14:53:845 [1408] Controller: _ProcStart - path = C:\Program Files (x86)\Nimsoft\probes\service\nas\alarm_enrichment\../../../../jre/jre7/bin/java.exe
    Jul  1 22:14:53:845 [1408] Controller: _ProcStart - command line = ../../../../jre/jre7/bin/java.exe -Xms2048m -Xmx3072m -Dfile.encoding=UTF-8 -jar ../lib/alarm_enrichment.jar
    Jul  1 22:14:53:848 [1408] Controller: Probe 'alarm_enrichment' started (pid=6344) (restart 1)



  • 2.  Re: Port unregister from active probe alarm_enrichment

    Posted Jul 04, 2018 03:50 AM

    Hi Guan Hua,

     

    The message you are getting 'port unregistered from active probe <probe name>' is sent from the controller when a probe send an unregistered process to the controller but continues to run.
    The unregister process is usually seen during a shut down or restart.
    It usually means the probe did not shut down as expected.
    If you check the probe and it is working. IE it is green with port and pid and activity in the probe log then this can be safely acknowledge.

     

    As we advised in the support case you raised with us, a possible solution could be the upgrade of the controller, hub and nas to the latest versions (controller and hub: 7.93 and nas: 9.0).

     

    I hope it's helpful.

     

    Thanks and regards.

     

    iulian ursu

    CA UIM Support



  • 3.  Re: Port unregister from active probe alarm_enrichment

    Posted Jul 05, 2018 01:04 AM

    Hi iulian,

     

    Sometime it generate alarm message to nas sometime it doesn't.

    When it generate an alarm meesage "Port unregister from active probe alarm_enrichment" , it creates a service desk ticket.

    Had saw the alarm received origin date difference to the time arrival time stamp to the nas vary from 3mins ~ more than one hour before nas alerting us occurrence.

     

    Regards

    Guan Hua



  • 4.  Re: Port unregister from active probe alarm_enrichment

    Posted Jul 05, 2018 04:31 AM

    Hi GuanHua

    Please update the controller, hub and nas as suggested and let us know if the issue reoccurs.

    Thanks and regards.

    iulian



  • 5.  Re: Port unregister from active probe alarm_enrichment

    Posted Jul 06, 2018 01:50 PM

    Hi iulian,

     

    It has stopped occurring since 25 Jun 2018 even without the upgrade of packages after a power cycle of the Virtual Machine.

    For the restart log on above entry without generating restart alarm message to nas was trigger when a change to the config file is apply to the nas.

    Have tried change to the config on multiple nas and it reflects a restart in the enrichment log in my environment.

     

    Regards

    Guan Hua