Re: Not throwing NED exception to NSO Cli/GUI & no service rollback

previousqna · ‎05-09-2017

Hi Experts,

I have written one service in NSO which is using resource pool id allocator. When I committing the service, it is committed successfully but device does not accept the configuration change and raise the exception. This error is caught by NED and logged into NSO log file. And because service is using resource manager, this error is caught also by NSOUtil package (which is being used by ResourceManager package) while re-deploying the service but it simply logs the error in NSO log. You cannot see this error on NSO Cli/NSO GUI to notify the user about the exception and moreover service is also not rolled back.

Any idea to handle this kind of scenario.

<INFO> 20-Feb-2017::12:00:45.909 l2vpnp2pRFS Did-30-Worker-70: - ###Premodifications###

<INFO> 20-Feb-2017::12:08:11.582 l2vpnp2pRFS Did-30-Worker-70: - ###Premodifications###

<INFO> 20-Feb-2017::12:08:11.583 l2vpnp2pRFS Did-30-Worker-70: - User name :admin

<INFO> 20-Feb-2017::12:08:11.589 Utility Did-30-Worker-70: - inside check-sync

<INFO> 20-Feb-2017::12:08:11.589 Utility Did-30-Worker-70: - /ncs:devices/device{xrvr-1}/check-sync

<WARN> 20-Feb-2017::12:08:12.452 NavuContainer Did-30-Worker-70: - The node 'config' contains augumented children, i.e. nodes from other namespaces.

The child node 'cisco-ios-xr:interface' is for the moment unique,

but it is a strong recommendation to use the method container("cisco-ios-xr","interface")

to avoid future conflicts if new yang modules are augumented to the same node.

<INFO> 20-Feb-2017::12:08:12.455 Utility Did-30-Worker-70: - Loopback 0 ip configured on the device 1.1.1.1

<INFO> 20-Feb-2017::12:08:12.458 Utility Did-30-Worker-70: - *****************IN validatePopAndTranslateValues***************

<INFO> 20-Feb-2017::12:08:12.459 Utility Did-30-Worker-70: - vlan 2 check

<INFO> 20-Feb-2017::12:08:12.460 Utility Did-30-Worker-70: - POP value :Default

<INFO> 20-Feb-2017::12:08:12.461 Utility Did-30-Worker-70: - **************IN isServiceExists *********

<INFO> 20-Feb-2017::12:08:12.462 Utility Did-30-Worker-70: - Creating new transaction

<INFO> 20-Feb-2017::12:08:12.463 Utility Did-30-Worker-70: - checking service already exists : xpathQuery /services/l2vpn-p2p:l2vpn-p2p[service-name='test']

<INFO> 20-Feb-2017::12:08:12.464 l2vpnp2pRFS Did-30-Worker-70: - INSIDE ELSE

<INFO> 20-Feb-2017::12:08:12.464 Utility Did-30-Worker-70: - ***********IN checkPhysicalIntfStatus ***********

<INFO> 20-Feb-2017::12:08:12.465 Utility Did-30-Worker-70: - Creating new transaction

<INFO> 20-Feb-2017::12:08:12.466 Utility Did-30-Worker-70: - checking if ip address is configured on the physical interface /devices/device[name='xrvr-1']/config/cisco-ios-xr:interface/GigabitEthernet[id='0/0/0/1']/ipv4/address/ip

<INFO> 20-Feb-2017::12:08:12.467 Utility Did-30-Worker-70: - checking if l2transport is configured on the physical interface /devices/device[name='xrvr-1']/config/cisco-ios-xr:interface/GigabitEthernet[id='0/0/0/1']/l2transport

<INFO> 20-Feb-2017::12:08:12.470 Utility Did-30-Worker-70: - ***********IN checkNoSubIntfExistsUnderPhysicalIntf**********

<INFO> 20-Feb-2017::12:08:12.470 Utility Did-30-Worker-70: - Creating new transaction

<INFO> 20-Feb-2017::12:08:12.471 Utility Did-30-Worker-70: - checking subinterface under physical interface : xpathQuery device[name='xrvr-1']/config/interface/GigabitEthernet-subinterface/GigabitEthernet[contains(id,'0/0/0/1.')]/id

<INFO> 20-Feb-2017::12:08:12.476 Utility Did-30-Worker-70: - inside check-sync

<INFO> 20-Feb-2017::12:08:12.476 Utility Did-30-Worker-70: - /ncs:devices/device{xrvr-2}/check-sync

<WARN> 20-Feb-2017::12:08:13.956 NavuContainer Did-30-Worker-70: - The node 'config' contains augumented children, i.e. nodes from other namespaces.

The child node 'cisco-ios-xr:interface' is for the moment unique,

but it is a strong recommendation to use the method container("cisco-ios-xr","interface")

to avoid future conflicts if new yang modules are augumented to the same node.

<INFO> 20-Feb-2017::12:08:13.959 Utility Did-30-Worker-70: - Loopback 0 ip configured on the device 2.2.2.2

<INFO> 20-Feb-2017::12:08:13.961 Utility Did-30-Worker-70: - *****************IN validatePopAndTranslateValues***************

<INFO> 20-Feb-2017::12:08:13.962 Utility Did-30-Worker-70: - vlan 2 check

<INFO> 20-Feb-2017::12:08:13.963 Utility Did-30-Worker-70: - POP value :Default

<INFO> 20-Feb-2017::12:08:13.964 Utility Did-30-Worker-70: - **************IN isServiceExists *********

<INFO> 20-Feb-2017::12:08:13.965 Utility Did-30-Worker-70: - Creating new transaction

<INFO> 20-Feb-2017::12:08:13.966 Utility Did-30-Worker-70: - checking service already exists : xpathQuery /services/l2vpn-p2p:l2vpn-p2p[service-name='test']

<INFO> 20-Feb-2017::12:08:13.967 l2vpnp2pRFS Did-30-Worker-70: - INSIDE ELSE

<INFO> 20-Feb-2017::12:08:13.967 Utility Did-30-Worker-70: - ***********IN checkPhysicalIntfStatus ***********

<INFO> 20-Feb-2017::12:08:13.968 Utility Did-30-Worker-70: - Creating new transaction

<INFO> 20-Feb-2017::12:08:13.969 Utility Did-30-Worker-70: - checking if ip address is configured on the physical interface /devices/device[name='xrvr-2']/config/cisco-ios-xr:interface/GigabitEthernet[id='0/0/0/1']/ipv4/address/ip

<INFO> 20-Feb-2017::12:08:13.971 Utility Did-30-Worker-70: - checking if l2transport is configured on the physical interface /devices/device[name='xrvr-2']/config/cisco-ios-xr:interface/GigabitEthernet[id='0/0/0/1']/l2transport

<INFO> 20-Feb-2017::12:08:13.973 Utility Did-30-Worker-70: - ***********IN checkNoSubIntfExistsUnderPhysicalIntf**********

<INFO> 20-Feb-2017::12:08:13.973 Utility Did-30-Worker-70: - Creating new transaction

<INFO> 20-Feb-2017::12:08:13.974 Utility Did-30-Worker-70: - checking subinterface under physical interface : xpathQuery device[name='xrvr-2']/config/interface/GigabitEthernet-subinterface/GigabitEthernet[contains(id,'0/0/0/1.')]/id

<INFO> 20-Feb-2017::12:08:13.976 Utility Did-30-Worker-70: - ********* In checkDuplicates ********

<INFO> 20-Feb-2017::12:08:13.977 Utility Did-30-Worker-70: - key value pairs (xrvr-1GigabitEthernet0/0/0/1 ,*0*)

<INFO> 20-Feb-2017::12:08:13.978 Utility Did-30-Worker-70: - key value pairs (xrvr-2GigabitEthernet0/0/0/1 ,*0*)

<INFO> 20-Feb-2017::12:08:13.978 Utility Did-30-Worker-70: - ********* In checkServicePolicies ********

<INFO> 20-Feb-2017::12:08:13.982 l2vpnp2pRFS Did-30-Worker-70: - ###Create###

<INFO> 20-Feb-2017::12:08:13.987 l2vpnp2pRFS Did-30-Worker-70: - !!!!!!!!!!!!!! Normal service creation !!!!!!!!!!!!!

<INFO> 20-Feb-2017::12:08:13.987 l2vpnp2pRFS Did-30-Worker-70: - Remote connect

<INFO> 20-Feb-2017::12:08:13.987 Utility Did-30-Worker-70: - ************* In isResourcePoolExists ************

<INFO> 20-Feb-2017::12:08:13.988 Utility Did-30-Worker-70: - Creating new transaction

<INFO> 20-Feb-2017::12:08:13.988 Utility Did-30-Worker-70: - poolxpath/resource-pools/id-pool[name='pw-id']

<INFO> 20-Feb-2017::12:08:13.990 Utility Did-30-Worker-70: - poolCheck14

<INFO> 20-Feb-2017::12:08:13.990 l2vpnp2pRFS Did-30-Worker-70: - Before invoking.

<INFO> 20-Feb-2017::12:08:13.994 l2vpnp2pRFS Did-30-Worker-70: - After invoking.

<INFO> 20-Feb-2017::12:08:13.994 l2vpnp2pRFS Did-30-Worker-70: - Before read from pool.

<ERROR> 20-Feb-2017::12:08:13.995 l2vpnp2pRFS Did-30-Worker-70: - Trying to allocate from pool: 'pw-id : com.tailf.pkg.resourcemanager.ResourceErrorException: No such allocation: test

<ERROR> 20-Feb-2017::12:08:13.996 l2vpnp2pRFS Did-30-Worker-70: - pw-id is null

<INFO> 20-Feb-2017::12:09:29.046 l2vpnp2pRFS Did-30-Worker-70: - ###Premodifications###

<INFO> 20-Feb-2017::12:09:29.047 l2vpnp2pRFS Did-30-Worker-70: - User name :admin

<INFO> 20-Feb-2017::12:09:29.054 Utility Did-30-Worker-70: - inside check-sync

<INFO> 20-Feb-2017::12:09:29.054 Utility Did-30-Worker-70: - /ncs:devices/device{xrvr-1}/check-sync

<WARN> 20-Feb-2017::12:09:29.998 NavuContainer Did-30-Worker-70: - The node 'config' contains augumented children, i.e. nodes from other namespaces.

The child node 'cisco-ios-xr:interface' is for the moment unique,

but it is a strong recommendation to use the method container("cisco-ios-xr","interface")

to avoid future conflicts if new yang modules are augumented to the same node.

<INFO> 20-Feb-2017::12:09:30.001 Utility Did-30-Worker-70: - Loopback 0 ip configured on the device 1.1.1.1

<INFO> 20-Feb-2017::12:09:30.004 Utility Did-30-Worker-70: - *****************IN validatePopAndTranslateValues***************

<INFO> 20-Feb-2017::12:09:30.004 Utility Did-30-Worker-70: - vlan 2 check

<INFO> 20-Feb-2017::12:09:30.005 Utility Did-30-Worker-70: - POP value :Default

<INFO> 20-Feb-2017::12:09:30.007 Utility Did-30-Worker-70: - **************IN isServiceExists *********

<INFO> 20-Feb-2017::12:09:30.008 Utility Did-30-Worker-70: - Creating new transaction

<INFO> 20-Feb-2017::12:09:30.009 Utility Did-30-Worker-70: - checking service already exists : xpathQuery /services/l2vpn-p2p:l2vpn-p2p[service-name='test']

<ERROR> 20-Feb-2017::12:09:30.011 Utility Did-30-Worker-70: - service already exists test

<INFO> 20-Feb-2017::12:09:30.011 l2vpnp2pRFS Did-30-Worker-70: - INSIDE IF

<INFO> 20-Feb-2017::12:09:30.011 Utility Did-30-Worker-70: - *************IN checkNoSubIntfExistsUnderPhysicalIntf2 *************

<INFO> 20-Feb-2017::12:09:30.011 Utility Did-30-Worker-70: - Creating new transaction

<INFO> 20-Feb-2017::12:09:30.012 Utility Did-30-Worker-70: - checking if record exists with same sid : xpathQuery /services/l2vpn-p2p:l2vpn-p2p[service-name='test']/attachment-circuits[sid='111111']/*

<INFO> 20-Feb-2017::12:09:30.039 Utility Did-30-Worker-70: - record already exists for provided device and interface xrvr-1:gigabit-interface-number-0/0/0/1

<INFO> 20-Feb-2017::12:09:30.043 Utility Did-30-Worker-70: - interface type gigabit-interface-number interfsce number 0/0/0/1

<INFO> 20-Feb-2017::12:09:30.043 Utility Did-30-Worker-70: - INterface type and number match

<INFO> 20-Feb-2017::12:09:30.053 Utility Did-30-Worker-70: - checking subinterface under physical interface : xpathQuery device[name='xrvr-1']/config/interface/GigabitEthernet-subinterface/GigabitEthernet[contains(id,'0/0/0/1.') and not(id='0/0/0/1.')]/id

<INFO> 20-Feb-2017::12:09:30.055 Utility Did-30-Worker-70: - ********* In checkPhysicalIntfPresence ********

<INFO> 20-Feb-2017::12:09:30.056 Utility Did-30-Worker-70: - Creating new transaction

<INFO> 20-Feb-2017::12:09:30.057 Utility Did-30-Worker-70: - checking if the existing service is configured on the physical interface /services/l2vpn-p2p:l2vpn-p2p[service-name='test']/attachment-circuits[sid='111111']/*

<INFO> 20-Feb-2017::12:09:30.073 Utility Did-30-Worker-70: - record already exists for provided SID 111111

<INFO> 20-Feb-2017::12:09:30.077 Utility Did-30-Worker-70: - inside check-sync

<INFO> 20-Feb-2017::12:09:30.077 Utility Did-30-Worker-70: - /ncs:devices/device{xrvr-2}/check-sync

<WARN> 20-Feb-2017::12:09:31.429 NavuContainer Did-30-Worker-70: - The node 'config' contains augumented children, i.e. nodes from other namespaces.

The child node 'cisco-ios-xr:interface' is for the moment unique,

but it is a strong recommendation to use the method container("cisco-ios-xr","interface")

to avoid future conflicts if new yang modules are augumented to the same node.

<INFO> 20-Feb-2017::12:09:31.432 Utility Did-30-Worker-70: - Loopback 0 ip configured on the device 2.2.2.2

<INFO> 20-Feb-2017::12:09:31.435 Utility Did-30-Worker-70: - *****************IN validatePopAndTranslateValues***************

<INFO> 20-Feb-2017::12:09:31.435 Utility Did-30-Worker-70: - vlan 2 check

<INFO> 20-Feb-2017::12:09:31.436 Utility Did-30-Worker-70: - POP value :Default

<INFO> 20-Feb-2017::12:09:31.438 Utility Did-30-Worker-70: - **************IN isServiceExists *********

<INFO> 20-Feb-2017::12:09:31.438 Utility Did-30-Worker-70: - Creating new transaction

<INFO> 20-Feb-2017::12:09:31.439 Utility Did-30-Worker-70: - checking service already exists : xpathQuery /services/l2vpn-p2p:l2vpn-p2p[service-name='test']

<ERROR> 20-Feb-2017::12:09:31.442 Utility Did-30-Worker-70: - service already exists test

<INFO> 20-Feb-2017::12:09:31.442 l2vpnp2pRFS Did-30-Worker-70: - INSIDE IF

<INFO> 20-Feb-2017::12:09:31.442 Utility Did-30-Worker-70: - *************IN checkNoSubIntfExistsUnderPhysicalIntf2 *************

<INFO> 20-Feb-2017::12:09:31.442 Utility Did-30-Worker-70: - Creating new transaction

<INFO> 20-Feb-2017::12:09:31.443 Utility Did-30-Worker-70: - checking if record exists with same sid : xpathQuery /services/l2vpn-p2p:l2vpn-p2p[service-name='test']/attachment-circuits[sid='111222']/*

<INFO> 20-Feb-2017::12:09:31.463 Utility Did-30-Worker-70: - record already exists for provided device and interface xrvr-2:gigabit-interface-number-0/0/0/1

<INFO> 20-Feb-2017::12:09:31.466 Utility Did-30-Worker-70: - interface type gigabit-interface-number interfsce number 0/0/0/1

<INFO> 20-Feb-2017::12:09:31.467 Utility Did-30-Worker-70: - INterface type and number match

<INFO> 20-Feb-2017::12:09:31.474 Utility Did-30-Worker-70: - checking subinterface under physical interface : xpathQuery device[name='xrvr-2']/config/interface/GigabitEthernet-subinterface/GigabitEthernet[contains(id,'0/0/0/1.') and not(id='0/0/0/1.')]/id

<INFO> 20-Feb-2017::12:09:31.476 Utility Did-30-Worker-70: - ********* In checkPhysicalIntfPresence ********

<INFO> 20-Feb-2017::12:09:31.477 Utility Did-30-Worker-70: - Creating new transaction

<INFO> 20-Feb-2017::12:09:31.478 Utility Did-30-Worker-70: - checking if the existing service is configured on the physical interface /services/l2vpn-p2p:l2vpn-p2p[service-name='test']/attachment-circuits[sid='111222']/*

<INFO> 20-Feb-2017::12:09:31.494 Utility Did-30-Worker-70: - record already exists for provided SID 111222

<INFO> 20-Feb-2017::12:09:31.495 Utility Did-30-Worker-70: - ********* In checkDuplicates ********

<INFO> 20-Feb-2017::12:09:31.496 Utility Did-30-Worker-70: - key value pairs (xrvr-1GigabitEthernet0/0/0/1 ,*0*)

<INFO> 20-Feb-2017::12:09:31.497 Utility Did-30-Worker-70: - key value pairs (xrvr-2GigabitEthernet0/0/0/1 ,*0*)

<INFO> 20-Feb-2017::12:09:31.497 Utility Did-30-Worker-70: - ********* In checkServicePolicies ********

<INFO> 20-Feb-2017::12:09:31.502 l2vpnp2pRFS Did-30-Worker-70: - ###Create###

<INFO> 20-Feb-2017::12:09:31.507 l2vpnp2pRFS Did-30-Worker-70: - !!!!!!!!!!!!!! Normal service creation !!!!!!!!!!!!!

<INFO> 20-Feb-2017::12:09:31.507 l2vpnp2pRFS Did-30-Worker-70: - Remote connect

<INFO> 20-Feb-2017::12:09:31.507 Utility Did-30-Worker-70: - ************* In isResourcePoolExists ************

<INFO> 20-Feb-2017::12:09:31.508 Utility Did-30-Worker-70: - Creating new transaction

<INFO> 20-Feb-2017::12:09:31.508 Utility Did-30-Worker-70: - poolxpath/resource-pools/id-pool[name='pw-id']

<INFO> 20-Feb-2017::12:09:31.511 Utility Did-30-Worker-70: - poolCheck98

<INFO> 20-Feb-2017::12:09:31.511 l2vpnp2pRFS Did-30-Worker-70: - Before invoking.

<INFO> 20-Feb-2017::12:09:31.515 l2vpnp2pRFS Did-30-Worker-70: - After invoking.

<INFO> 20-Feb-2017::12:09:31.515 l2vpnp2pRFS Did-30-Worker-70: - Before read from pool.

<INFO> 20-Feb-2017::12:09:31.518 l2vpnp2pRFS Did-30-Worker-70: - pwid allocated from pool :2000

<INFO> 20-Feb-2017::12:09:31.529 l2vpnp2pRFS Did-30-Worker-70: - Neighbor ip : 2.2.2.2

<INFO> 20-Feb-2017::12:09:31.544 l2vpnp2pRFS Did-30-Worker-70: - Neighbor ip : 1.1.1.1

<ERROR> 20-Feb-2017::12:09:47.988 NedWorker Ned-Worker-Thread-0: - NedWorker error for ned_prepare_cli

com.tailf.packages.ned.iosxr.IosxrNedCli$ExtendedApplyException: command: commit confirmed:

Mon Feb 20 06:36:29.682 UTC !! SEMANTIC ERRORS: This configuration was rejected by !! the system due to semantic errors. The individual !! errors with each failed configuration command can be !! found below. interface GigabitEthernet0/0/0/1 l2transport service-policy input 95M !!% 'NetIO' detected the 'warning' condition 'Netio or a feature DLL returned:': Invalid argument ! ! end at com.tailf.packages.ned.iosxr.IosxrNedCli.print_line_wait_oper(IosxrNedCli.java:983) at com.tailf.packages.ned.iosxr.IosxrNedCli.applyConfig2(IosxrNedCli.java:1557) at com.tailf.packages.ned.iosxr.IosxrNedCli.applyConfig(IosxrNedCli.java:1604) at com.tailf.ned.NedCliBaseTemplate.prepare(NedCliBaseTemplate.java:478) at com.tailf.ned.NedWorker.dorun(NedWorker.java:1416) at com.tailf.ned.NedWorker.run(NedWorker.java:293) <ERROR> 20-Feb-2017::12:09:53.279 NedWorker Ned-Worker-Thread-1: - NedWorker error for ned_prepare_cli

java.net.SocketTimeoutException: Read timed out

at java.net.SocketInputStream.socketRead0(Native Method)

at java.net.SocketInputStream.read(SocketInputStream.java:152)

at java.net.SocketInputStream.read(SocketInputStream.java:122)

at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)

at java.io.BufferedInputStream.read1(BufferedInputStream.java:275)

at java.io.BufferedInputStream.read(BufferedInputStream.java:334)

at com.tailf.ned.TelnetSession.get_char(TelnetSession.java:801)

at com.tailf.ned.TelnetSession.expect(TelnetSession.java:558)

at com.tailf.ned.TelnetSession.expect(TelnetSession.java:482)

at com.tailf.ned.TelnetSession.expect(TelnetSession.java:465)

at com.tailf.packages.ned.iosxr.IosxrNedCli.print_line_wait_oper(IosxrNedCli.java:956)

at com.tailf.packages.ned.iosxr.IosxrNedCli.applyConfig2(IosxrNedCli.java:1557)

at com.tailf.packages.ned.iosxr.IosxrNedCli.applyConfig(IosxrNedCli.java:1604)

at com.tailf.ned.NedCliBaseTemplate.prepare(NedCliBaseTemplate.java:478)

at com.tailf.ned.NedWorker.dorun(NedWorker.java:1416)

at com.tailf.ned.NedWorker.run(NedWorker.java:293)

<ERROR> 20-Feb-2017::12:10:10.235 NSOUtil$Redeployer Thread-91: - error in re-deploy: com.tailf.maapi.MaapiException: External error in the NED implementation for device xrvr-1: command: commit confirmed:

Mon Feb 20 06:36:29.682 UTC

!! SEMANTIC ERRORS: This configuration was rejected by

!! the system due to semantic errors. The individual

!! errors with each failed configuration command can be

!! found below.

interface GigabitEthernet0/0/0/1

l2transport

service-policy input 95M

!!% 'NetIO' detected the 'warning' condition 'Netio or a feature DLL returned:': Invalid argument

!

end

previousqna · ‎05-09-2017

To handle this we added an alarm consumer into our service to capture the alarms and then they will display into the GUI etc.

Ping me and I can show you the associated Java code etc.

previousqna · ‎05-09-2017

This is by design. When the initial request comes in, NSO accepts the requests but it cannot fulfil it as asynchronous allocations need to be made (from resource manager in this case) before service creation logic can proceed. So the service-logic just returns OK indicating that the request was accepted. That is how reactive-fastmap pattern works.

At a later time when the allocations complete, the service-creation logic is re-run at a later time (in another thread) and the error is encountered. It is not possible to feed back an error message towards the NB system (CLI/GUI/API) as the original caller may not around anymore. How this should be handled depends on the service-designer, if they want to raise alarm towards the north, backtrack the service on its Plan’s stage causing rollback, send a message towards a NB open web-socket etc. Thus due to the characteristics of asynchronous communication.

previousqna · ‎05-09-2017

Thank you, I will plan to write some alarm consumer to intimate NB.