cancel
Showing results for 
Search instead for 
Did you mean: 
cancel
1501
Views
3
Helpful
24
Replies
Highlighted
Beginner

Out of sequence response in .updateRoutes()

I use the All-in-one VM. On one machine (but not another) I am getting this exception message:

Error occurred in the operation. Failed to connect to the network element or the session is closed. Routing_L3UcastARTUpdateRoutesIDL failed: out of sequence response, Route REPLACE: interface GigabitEthernet0/2, destination 10.10.50.0/24"

This occurs at the .updateRoutes() call in the last line of this code:

      final NetworkPrefix networkPrefix = <<something sensible>>;

      final InetAddress nextHop =

        InetAddress.getByName(<<something sensible>>);

      final NetworkInterface networkInterface = <<something sensible>>;

      final Set<L3UnicastNextHop> hopSet =

        new HashSet<L3UnicastNextHop>();

      final L3UnicastNextHop hop =

        new L3UnicastNextHop(networkInterface, nextHop);

      hopSet.add(hop);

      final L3UnicastRoute route =

        new L3UnicastRoute(networkPrefix, hopSet);

      final RouteOperation routeOperation =

        new L3UnicastRouteOperation(

          operationType, route);

      final Scope scope =

          new L3UnicastScope();

      final Routing routing =

          Routing.getInstance(mConnection.getNetworkElement());

      final List<RouteOperation> opList =

          new ArrayList<RouteOperation>();

      opList.add(routeOperation);

      routing.getAppRouteTable().updateRoutes(scope, opList);

I'm not sure why this is - the session is definitely alive at time of call as shown on both router and using NetworkElement.isConnected().

The next call to this code generates an out-of-memory error. Am I getting the sequence of events wrong?

1 ACCEPTED SOLUTION

Accepted Solutions
Highlighted

Sorry I meant SSL (approx = TLS) not SSH. I have just replicated your exact command line and get the same anomalous observations.

Thanks so much for your help. Let's close this off on the assumption it's some as yet unidentified environmental condition unique to my Mac. I can work around it by using the JDK6 in the AiO VM. I have another machine here which I can try, too.

I'll carry on niggling away, and of course I'll let you know if I solve it!

View solution in original post

24 REPLIES 24
Highlighted
Hall of Fame Cisco Employee

This may be related to a known thread-safety issue.  Are you doing these updates synchronously or within a thread?

Highlighted

Yes, the different behaviour on different machines points to concurrency being the issue, too.

In my Java code, I manage one SessionHandle to each of several routers simultaneously. I certainly make simultaneous calls on different session handles.

I could make simultaneous calls on a particular session handle. For example I could try to read some property of a router while a call to say apply a new ip address is in progress; or perform two route add calls simultaneously.

Could you let me know what objects are thread unsafe? That is, should I serialize calls globally across all session handles (i.e. only 1 call is outstanding at any one time across the entire controller), or should I serialize per session handle?

Highlighted
Hall of Fame Cisco Employee

The RPC client is where the thread safety issue lies right now.  For the time being, serialize (or synchronize) all calls against a specific session handler.  Multiple sessions can be done in parallel as the app is communicating to a different device.

Highlighted

I've isolated this into a single-threaded test case, updated the All-in-one VM to latest and updated libraries on the client side to 1.1. This means using TLS, which slows things down an awful lot.

I now get (after a _long_ minute):

com.cisco.onep.core.exception.OnepConnectionException: Error occurred in the operation. Failed to connect to the network element or the session is closed. java.net.SocketTimeoutException: Read timed out.

The call seems never to return. The same behaviour occurs with the synchronous and asynchronous forms of the AppRouteTable.updateRoutes() method.

A previous call on the same connection to set an IP v4 address works just fine.


Any ideas?

Highlighted
Hall of Fame Cisco Employee

Can you post your test code in its entirety?  It will help with the troubleshooting to see what you see.  Also, how are you running the app, and how have you configured the device?

Highlighted

Thanks Joe. This Junit test has all my classes factored out so it's inline onePK stuff:

// Copyright (c) 2014 SPARKL Limited. All Rights Reserved.

package com.sparkl.onepk;

import java.net.InetAddress;

import java.util.ArrayList;

import java.util.HashSet;

import java.util.List;

import java.util.Set;

import junit.framework.Assert;

import org.junit.Test;

import com.cisco.onep.core.util.OnepConstants;

import com.cisco.onep.element.NetworkApplication;

import com.cisco.onep.element.NetworkElement;

import com.cisco.onep.element.SessionConfig;

import com.cisco.onep.element.SessionConfig.SessionTransportMode;

import com.cisco.onep.element.SessionHandle;

import com.cisco.onep.interfaces.InterfaceFilter;

import com.cisco.onep.interfaces.NetworkInterface;

import com.cisco.onep.interfaces.NetworkPrefix;

import com.cisco.onep.routing.AppRouteTable;

import com.cisco.onep.routing.L3UnicastNextHop;

import com.cisco.onep.routing.L3UnicastRoute;

import com.cisco.onep.routing.L3UnicastRouteOperation;

import com.cisco.onep.routing.L3UnicastScope;

import com.cisco.onep.routing.RouteOperation;

import com.cisco.onep.routing.Routing;

import com.cisco.onep.routing.Scope;

import com.sparkl.TestConstants;

public class OnePKRouteTest {

  @Test

  public void testOnePKRouteAdd() {

    try {

      final NetworkApplication app =

        NetworkApplication.getInstance();

      app.setName("ONEPK_ROUTE_TEST");

      final NetworkElement nde =

        app.getNetworkElement(

          InetAddress.getByName("10.10.10.2"));

      final SessionConfig sessionConfig =

          new SessionConfig(SessionTransportMode.TLS);

      sessionConfig.setPort(OnepConstants.ONEP_TLS_PORT);

      final SessionHandle sessionHandle =

        nde.connect(

          TestConstants.TEST_USER, TestConstants.TEST_PASS, sessionConfig);

      Assert.assertTrue("Should be connected", nde.isConnected());

      final InterfaceFilter allInterfaces = new InterfaceFilter();

      for (final NetworkInterface networkInterface :

        sessionHandle.getNetworkElement().getInterfaceList(allInterfaces)) {

          if (networkInterface.getName().equals("GigabitEthernet0/2")) {

            final NetworkPrefix networkPrefix =

              new NetworkPrefix(

                InetAddress.getByName("10.10.20.0"), 24);

            final InetAddress nextHop =

              InetAddress.getByName("10.11.0.6");

            final Set<L3UnicastNextHop> hopSet =

              new HashSet<L3UnicastNextHop>();

            final L3UnicastNextHop hop =

              new L3UnicastNextHop(networkInterface, nextHop);

            hopSet.add(hop);

            final L3UnicastRoute route =

                new L3UnicastRoute(networkPrefix, hopSet);

              final RouteOperation routeOperation =

                new L3UnicastRouteOperation(

                  RouteOperation.RouteOperationType.REPLACE, route);

            final Scope scope =

              new L3UnicastScope();

            final Routing routing =

              Routing.getInstance(nde);

            final List<RouteOperation> opList =

              new ArrayList<RouteOperation>();

            opList.add(routeOperation);

            final AppRouteTable appRouteTable =

              routing.getAppRouteTable();

            appRouteTable.updateRoutes( // EXCEPTION THROWN HERE.

              scope,

              opList);

          }

        }

      sessionHandle.getNetworkElement().disconnect();

    }

    catch (Exception e) {

      e.printStackTrace(); // STACK TRACE SHOWN BELOW.

      Assert.fail("Exception was thrown");

    }

  }

}

The timeout occurs on the call to updateRoutes() at line 87. The stacktrace at line 95 is shown below:

com.cisco.onep.core.exception.OnepConnectionException: Error occurred in the operation. Failed to connect to the network element or the session is closed. java.net.SocketTimeoutException: Read timed out

  at com.cisco.onep.routing.AppRouteTable.updateRoutes(AppRouteTable.java:210)

  at com.sparkl.onepk.OnePKRouteTest.testOnePKRouteAdd(OnePKRouteTest.java:84)

  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

  at java.lang.reflect.Method.invoke(Method.java:597)

  at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45)

  at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)

  at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)

  at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)

  at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:263)

  at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:68)

  at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:47)

  at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)

  at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)

  at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)

  at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)

  at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)

  at org.junit.runners.ParentRunner.run(ParentRunner.java:300)

  at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:50)

  at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)

  at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:467)

  at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:683)

  at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:390)

  at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:197)

Caused by: org.apache.thrift.transport.TTransportException: java.net.SocketTimeoutException: Read timed out

  at org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:129)

  at org.apache.thrift.transport.TTransport.readAll(TTransport.java:84)

  at org.apache.thrift.protocol.TBinaryProtocol.readAll(TBinaryProtocol.java:378)

  at org.apache.thrift.protocol.TBinaryProtocol.readI32(TBinaryProtocol.java:297)

  at org.apache.thrift.protocol.TBinaryProtocol.readMessageBegin(TBinaryProtocol.java:204)

  at com.cisco.onep.idl.RoutingIDL$Client.recv_Routing_L3UcastARTUpdateRoutesIDL(RoutingIDL.java:342)

  at com.cisco.onep.idl.RoutingIDL$Client.Routing_L3UcastARTUpdateRoutesIDL(RoutingIDL.java:321)

  at com.cisco.onep.routing.AppRouteTable.updateRoutes(AppRouteTable.java:188)

  ... 24 more

Caused by: java.net.SocketTimeoutException: Read timed out

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

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

  at com.sun.net.ssl.internal.ssl.InputRecord.readFully(InputRecord.java:422)

  at com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:460)

  at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:863)

  at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:820)

  at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75)

  at org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:127)

  ... 31 more

I'm running this test from within Eclipse using the JUnit runner.

The device runs in the All-in-one VM. The startup config of the device is shown below:

version 15.3

service timestamps debug datetime msec

service timestamps log datetime msec

no service password-encryption

!

hostname NDE_CORE

!

boot-start-marker

boot-end-marker

!

!

!

no aaa new-model

mmi polling-interval 60

no mmi auto-configure

no mmi pvc

mmi snmp-timeout 180

!

!

!

!

!

!

ip cef

no ipv6 cef

ipv6 multicast rpf use-bgp

!

multilink bundle-name authenticated

!

username CISCO privilege 15 password 0 cisco123

!

redundancy

!

!

!

!

!

!

!

!

!

!

!

!

!

!

interface GigabitEthernet0/0

mac-address 1001.0000.0000

ip address 10.10.10.2 255.255.255.0

no shutdown

duplex auto

speed auto

media-type rj45

!

interface GigabitEthernet0/1

mac-address 1001.0000.0001

no ip address

duplex auto

speed auto

media-type rj45

!

interface GigabitEthernet0/2

mac-address 1001.0000.0002

ip address 1.0.0.1 255.255.255.252

no shutdown

duplex auto

speed auto

media-type rj45

!

interface GigabitEthernet0/3

mac-address 1001.0000.0003

ip address 10.10.50.1 255.255.255.0

no shutdown

duplex auto

speed auto

media-type rj45

!

interface GigabitEthernet0/4

mac-address 1001.0000.0004

ip address 1.0.0.5 255.255.255.252

no shutdown

duplex auto

speed auto

media-type rj45

!

interface GigabitEthernet0/5

no ip address

shutdown

duplex auto

speed auto

media-type rj45

!

interface GigabitEthernet0/6

no ip address

shutdown

duplex auto

speed auto

media-type rj45

!

interface GigabitEthernet0/7

no ip address

shutdown

duplex auto

speed auto

media-type rj45

!

interface GigabitEthernet0/8

no ip address

shutdown

duplex auto

speed auto

media-type rj45

!

interface GigabitEthernet0/9

no ip address

shutdown

duplex auto

speed auto

media-type rj45

!

ip forward-protocol nd

!

!

ip http server

no ip http secure-server

ip route 192.168.56.0 255.255.255.0 10.10.10.100

!

!

!

!

control-plane

!

banner exec ^CC

**************************************************************************

* vIOS - Cisco Systems Confidential                                      *

*                                                                        *

* SPARKL config from ledgers_NDE_CORE.con                                *

* Note the ip route line which sets the static route to the vboxnet LAN  *

**************************************************************************^C

banner incoming ^CC

**************************************************************************

* vIOS - Cisco Systems Confidential                                      *

*                                                                        *

* SPARKL config from ledgers_NDE_CORE.con                                *

* Note the ip route line which sets the static route to the vboxnet LAN  *

**************************************************************************^C

banner login ^CC

**************************************************************************

* vIOS - Cisco Systems Confidential                                      *

*                                                                        *

* SPARKL config from ledgers_NDE_CORE.con                                *

* Note the ip route line which sets the static route to the vboxnet LAN  *

**************************************************************************^C

!

line con 0

line aux 0

line 578 580

login local

exec-character-bits 8

length 0

width 0

no history

international

transport input all

speed 9600

line vty 3 4

!

no scheduler allocate

onep

transport type tls disable-remotecert-validation

!

end

Highlighted

In this case, I am not sure, but you don't use certificates in TLS connection. Yours SessionConfig has not path to certification file.

And on device you don't have set certificates.

Try All-in-one 1.1.0-99 VM from developer.cisco.com

And and read some guide

How it works in all-ine-one 1.1.0-99:

When you click start3node -> symlink to python tiny application (/home/cisco/.3node/3node.py)

This application calls other scripts(/home/cisco/.3node/{3node_certify.sh, 3node_create.sh}). 3node_certify.sh calling  script (./simpleCA/createNEp12.sh), which generates 3 new certifications and rewrite ~/vmcloud-example-networks/3node/routerX.p12 (where X is integer)

These certifications are signed by CERTIFICATION AUTHORITY (~/ca.pem (~/.simpleCA/createCA.sh)(PYTHON and C API!!!!!)) 

After these process, devices booting(3node_create.sh). After booting, devices download certificates via TFTP.

in my case:

show run

(...

onep

transport type tls disable-remotecert-validation

service set vty

event manager applet load_identity

event timer countdown name Delay time 20

action 0.0 cli command "enable"

action 1.0 cli command "config terminal"

action 2.0 cli command "file prompt quiet"

action 3.0 cli command "crypto pki import demoTP pkcs12 flash2://router1.p12 password cisco1"

action 4.0 syslog msg "Loaded bootstrap identity certificate"

!

end

)

Highlighted

The TLS config is set up correctly and works fine (see the assertion at line 52). I use JVM flags to identify the keystore, that's all.

Highlighted

Ok, sorry I didn't see.

Highlighted
Hall of Fame Cisco Employee

Thanks for the code.  I took this, removed the JUnit stuff, added a main method, compiled it, and it worked (well, I changed a few IP addresses, too).  I ran it a number of times, and I was unable to reproduce the timeout you show.

If you are running this through JUnit, could threading still be an issue?  If you run this as a standalone piece of code, does it work?  What other routes are in your routing table?

Highlighted

This is the trace from the router when running the JUnit test code above (note that I changed the app name to ONEPK_VANILLA_ROUTE_TEST).

I'm not sure how to interpret this, but there's some stuff about re-connecting and unique application name at the bottom which looks odd. I've noticed that the application name in successive tests needs to be different unless you leave a few seconds between them, but this trace relates to a single run of the test.

[02/07/14 16:49:14.754 4F80] [348] [ONEP][Session]: ONEP TLS done accept_fd: 2, pid: 348, context: 11CAF348 [onep_al_tls_accept:239]

[02/07/14 16:49:14.854 4F81] [348] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk: Connecting attempt: timeout[0] shandle[0] fd[2] addr[192.168.56.1] port[53978] transport[onep tls server] [NetworkElement_connectIDL:455]

[02/07/14 16:49:14.856 4F82] [348] [ONEP][AAA]: Authenticating ONEP Session for appname ONEPK_VANILLA_ROUTE_TEST [onep_al_aaa_session_authenticate:1472]

[02/07/14 16:49:14.856 4F83] [348] [ONEP][AAA]: AAA is not configured, using local database [onep_al_aaa_session_authenticate:1476]

[02/07/14 16:49:14.856 4F84] [348] [ONEP][AAA]: Authentication using local database: SUCCESS [onep_al_aaa_session_authenticate:1480]

[02/07/14 16:49:14.856 4F85] [348] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk: Authentication succeeded for user cisco [NetworkElement_connectIDL:473]

[02/07/14 16:49:14.856 4F86] [348] [ONEP][Server]: auth success. ratep: 0x0 [onep_rate_limit_update:982]

[02/07/14 16:49:14.856 4F87] [348] [ONEP][Session]: Searching for application with AID ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk resulted in No App Found [NetworkElement_connectIDL:531]

[02/07/14 16:49:14.856 4F88] [348] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk: FSM: [Disconnected] ==> [Connecting] remote_addr[] port[0] [network_app_fsm_connecting:2828]

[02/07/14 16:49:14.856 4F89] [348] [ONEP][Session]: Fail to find handle [4809] [network_element_find_app_by_handle:562]

[02/07/14 16:49:14.856 4F8A] [348] [ONEP][Session]: Fail to find handle [4809] [network_element_find_app_by_handle:562]

[02/07/14 16:49:14.856 4F8B] [348] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809: [0x1335C878][12C9] added [network_element_add_app_internal:396]

[02/07/14 16:49:14.856 4F8C] [348] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809: Connecting with handle [0x12C9] at Fri Feb 07 16:49:14.855 [network_app_fsm_connecting:2856]

[02/07/14 16:49:14.856 4F8D] [348] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809: FSM: [Connecting] ==> [Authenticated] remote_addr[] port[0] [network_app_fsm_authenticated:2985]

[02/07/14 16:49:14.856 4F8E] [348] [ONEP][Session]: entering ... [create_application_process:1966]

[02/07/14 16:49:14.856 4F8F] [348] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809: stack size changed from =12000 bytes, to =200% of normal [create_application_process:2024]

[02/07/14 16:49:14.858 4F90] [241] [ONEP][Server]: app name ONEPK_VANILLA_ROUTE_TEST session handle 0x12C9 [network_application_xdm_init:2292]

[02/07/14 16:49:14.858 4F91] [241] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST: attach async stats return retval 0 Unknown error 0 [network_application_xdm_init:2356]

[02/07/14 16:49:14.858 4F92] [241] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST: attach timer return retval 0 Unknown error 0 [network_application_xdm_init:2362]

[02/07/14 16:49:14.858 4F93] [348] [ONEP][Session]: TLS dup old <2, 348>, new<0, 241> [onep_al_tls_dup:285]

[02/07/14 16:49:14.858 4F94] [348] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809: Cloned fd 2 -> 0 [ne_to_app_fd_clone:2087]

[02/07/14 16:49:14.858 4F95] [348] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809: cthrift_rb @0xFE417D8 status = 0x8 [NetworkElement_connectIDL:780]

[02/07/14 16:49:14.858 4F96] [348] [ONEP][Message]: Write cthrift buffer to socket 2: bytes 425 [cthrift_write_entire_buffer__:318]

[02/07/14 16:49:14.860 4F97] [348] [ONEP][Session]: ONEP TLS close fd: 2, pid: 348 [onep_al_tls_close:227]

[02/07/14 16:49:16.372 4F98] [348] [ONEP][Session]: ONEP TLS done accept_fd: 2, pid: 348, context: 10186D00 [onep_al_tls_accept:239]

[02/07/14 16:49:16.474 4F99] [348] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809: Event channel fd[2] [NetworkElement_evtChannelIDL:886]

[02/07/14 16:49:16.474 4F9A] [348] [ONEP][Session]: TLS dup old <2, 348>, new<1, 241> [onep_al_tls_dup:285]

[02/07/14 16:49:16.474 4F9B] [348] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809: Cloned fd 2 -> 1 [ne_to_app_fd_clone:2087]

[02/07/14 16:49:16.474 4F9C] [348] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809: FSM: [Authenticated] ==> [Connected] remote_addr[192.168.56.1] port[53979] [network_app_fsm_connected:3074]

[02/07/14 16:49:16.474 4F9D] [348] [ONEP][Server]: entering ... [onep_ha_ctx_store:241]

[02/07/14 16:49:16.474 4F9E] [348] [ONEP][Server]: service=0, table=0, session handle (key)=0x12C9 cidl_onep_ha_netapp_ctx_size_hint: 2178 [onep_ha_ctx_store:244]

[02/07/14 16:49:16.474 4F9F] [348] [ONEP][Server]: stored app name ONEPK_VANILLA_ROUTE_TEST session handle 0x12C9 [onep_ha_ctx_store:258]

[02/07/14 16:49:16.474 4FA0] [348] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809: Connected with handle [12C9] at Fri Feb 07 16:49:16.473 [network_app_fsm_connected:3115]

[02/07/14 16:49:16.474 4FA1] [348] [ONEP][Message]: Write cthrift buffer to socket 2: bytes 48 [cthrift_write_entire_buffer__:318]

[02/07/14 16:49:16.474 4FA2] [348] [ONEP][Session]: ONEP TLS close fd: 2, pid: 348 [onep_al_tls_close:227]

[02/07/14 16:49:16.474 4FA3] [241] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809: Starting keepalive timer for 60 secs [network_application_process:1720]

[02/07/14 16:49:16.474 4FA4] [241] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809: session_init [onep_session_manager_session_init:326]

[02/07/14 16:49:16.474 4FA5] [241] [ONEP][Event]: Session init for handle 4809 [onep_async_session_init:949]

[02/07/14 16:49:16.474 4FA6] [241] [ONEP][Event]: store async session handle=4809 successfully [onep_event_async_session_store:1434]

[02/07/14 16:49:16.474 4FA7] [241] [ONEP][Event]: SESSION_INIT: session handle 4809 [onep_event_session_init:1024]

[02/07/14 16:49:16.474 4FA8] [241] [ONEP][Event]: init new context pid 241 handle: 4809 [fh_first_time_init:626]

[02/07/14 16:49:16.474 4FA9] [241] [ONEP][Policy]: Async thread already created [create_async_policy_thread:735]

[02/07/14 16:49:16.474 4FAA] [241] [ONEP][Policy]: Binding to XOS for client 4809 [policy_bulk_session_init:379]

[02/07/14 16:49:16.474 4FAB] [241] [ONEP][Policy]: Binding to XOS - xos_async_wait retured successfully [policy_bulk_session_init:394]

[02/07/14 16:49:16.474 4FAC] [241] [ONEP][Policy]: Unknown error 0 in bind_result.status [policy_bulk_session_init:406]

[02/07/14 16:49:16.474 4FAD] [241] [ONEP][Policy]: Session init 4809 [onep_policy_session_init:549]

[02/07/14 16:49:16.474 4FAE] [241] [ONEP][VTY]: onep_vty_session_init: Session init 4809l [onep_vty_session_init:2206]

[02/07/14 16:49:16.474 4FAF] [241] [ONEP][MEDIATRACE]: ONEP Mediatrace: Ignoring session init

[onep_pathtrace_event_session_init:795]

[02/07/14 16:49:16.474 4FB0] [241] [ONEP][ROUTING]: ONEP Routing: Session init sh: 4809 [onep_rtg_svc_session_init:140]

[02/07/14 16:49:16.474 4FB1] [241] [ONEP][ROUTING]: session_init, rtg_client_handle 0 [onep_rtg_svc_session_init:146]

[02/07/14 16:49:16.474 4FB2] [241] [ONEP][ROUTING]: ONEP Routing: Session init sh: 4809, app: 0x1335C878 [onep_rtg_svc_session_init:163]

[02/07/14 16:49:17.136 4FB3] [114] [ONEP][Topology]: topo_cdp_packet_received(GigabitEthernet0/0): pak 0x104C0A28 tlv_len 322 mac 0x1020000 [topo_cdp_packet_received:44]

[02/07/14 16:49:17.136 4FB4] [114] [ONEP][Topology]:

Event type 0: ifname GigabitEthernet0/0 ifindex 2 [topo_cdp_event_common:512]

[02/07/14 16:49:19.742 4FB5] [241] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809: Session event [0x1] occured [network_app_session_handler:1432]

[02/07/14 16:49:19.742 4FB6] [241] [ONEP][Session]: TLS reset ioref fd: 0 [onep_tls_reset_ioref:210]

[02/07/14 16:49:19.742 4FB7] [241] [ONEP][Session]: TLS reset ioref fd: 1 [onep_tls_reset_ioref:210]

[02/07/14 16:49:19.750 4FB8] [241] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809: Session event [0x1] occured [network_app_session_handler:1432]

[02/07/14 16:49:19.752 4FB9] [241] [ONEP][Interface]: Interface List request: xosHandle: -1 ifType: 1 slot:0 [NetworkElement_getInterfaceListIDL:1575]

[02/07/14 16:49:19.758 4FBA] [241] [ONEP][Message]: Write cthrift buffer to socket 0: bytes 495 [cthrift_write_entire_buffer__:318]

[02/07/14 16:49:19.790 4FBB] [241] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809: Session event [0x1] occured [network_app_session_handler:1432]

[02/07/14 16:49:19.798 4FBC] [241] [ONEP][Interface]: NetworkInterface_setAddressIDL xosHdl[4] oper[1] scope[1] [NetworkInterface_setAddressIDL:2075]

[02/07/14 16:49:19.800 4FBD] [241] [ONEP][Interface]:

SET ADDRESS SHIM START: ifhdl[4], family[1], oper[1] scope[1] [onep_al_interface_set_address:945]

[02/07/14 16:49:19.800 4FBE] [241] [ONEP][Interface]:

Address set/unset succeded [onep_al_interface_set_address:1297]

[02/07/14 16:49:19.800 4FBF] [241] [ONEP][Interface]: Sync was successful [NetworkInterface_setAddressIDL:2164]

[02/07/14 16:49:19.800 4FC0] [241] [ONEP][Interface]: Set/unset of IP address success [NetworkInterface_setAddressIDL:2169]

[02/07/14 16:49:19.800 4FC1] [241] [ONEP][Message]: Write cthrift buffer to socket 0: bytes 50 [cthrift_write_entire_buffer__:318]

[02/07/14 16:49:19.848 4FC2] [241] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809: Session event [0x1] occured [network_app_session_handler:1432]

[02/07/14 16:49:19.850 4FC3] [241] [ONEP][Interface]: Interface List request: xosHandle: -1 ifType: 1 slot:0 [NetworkElement_getInterfaceListIDL:1575]

[02/07/14 16:49:19.856 4FC4] [241] [ONEP][Message]: Write cthrift buffer to socket 0: bytes 495 [cthrift_write_entire_buffer__:318]

[02/07/14 16:49:19.892 4FC5] [241] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809: Session event [0x1] occured [network_app_session_handler:1432]

[02/07/14 16:49:19.914 4FC6] [241] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809: Session event [0x1] occured [network_app_session_handler:1432]

[02/07/14 16:49:31.564 4FC7] [114] [ONEP][Topology]: topo_cdp_packet_received(GigabitEthernet0/4): pak 0x1043FC08 tlv_len 322 mac 0x1020002 [topo_cdp_packet_received:44]

[02/07/14 16:49:31.564 4FC8] [114] [ONEP][Topology]:

Event type 0: ifname GigabitEthernet0/4 ifindex 6 [topo_cdp_event_common:512]

[02/07/14 16:49:32.650 4FC9] [114] [ONEP][Topology]: topo_cdp_packet_received(GigabitEthernet0/2): pak 0x10457848 tlv_len 331 mac 0x1030002 [topo_cdp_packet_received:44]

[02/07/14 16:49:32.650 4FCA] [114] [ONEP][Topology]:

Event type 0: ifname GigabitEthernet0/2 ifindex 4 [topo_cdp_event_common:512]

[02/07/14 16:49:33.582 4FCB] [114] [ONEP][Topology]: topo_cdp_packet_received(GigabitEthernet0/0): pak 0x104600C8 tlv_len 327 mac 0x1030000 [topo_cdp_packet_received:44]

[02/07/14 16:49:33.582 4FCC] [114] [ONEP][Topology]:

Event type 0: ifname GigabitEthernet0/0 ifindex 2 [topo_cdp_event_common:512]

[02/07/14 16:49:42.960 4FCD] [114] [ONEP][Topology]: topo_cdp_packet_received(GigabitEthernet0/0): pak 0x1042CDC8 tlv_len 322 mac 0x1020000 [topo_cdp_packet_received:44]

[02/07/14 16:49:42.960 4FCE] [114] [ONEP][Topology]:

Event type 0: ifname GigabitEthernet0/0 ifindex 2 [topo_cdp_event_common:512]

[02/07/14 16:49:46.474 4FCF] [241] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809: Keepalive idle timer elapsed, sending keepalive message to app [network_app_timer_handler:1476]

[02/07/14 16:49:46.474 4FD0] [241] [ONEP][Message]: Write cthrift buffer to socket 1: bytes 51 [cthrift_write_entire_buffer__:318]

[02/07/14 16:49:46.474 4FD1] [241] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809: Restarting keepalive timer for 60 secs [network_app_timer_handler:1498]

[02/07/14 16:49:46.798 4FD2] [348] [ONEP][Session]: ONEP TLS done accept_fd: 2, pid: 348, context: 101871A0 [onep_al_tls_accept:239]

[02/07/14 16:49:46.898 4FD3] [348] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk: Connecting attempt: timeout[0] shandle[0] fd[2] addr[192.168.56.1] port[53988] transport[onep tls server] [NetworkElement_connectIDL:455]

[02/07/14 16:49:46.898 4FD4] [348] [ONEP][AAA]: Authenticating ONEP Session for appname ONEPK_VANILLA_ROUTE_TEST [onep_al_aaa_session_authenticate:1472]

[02/07/14 16:49:46.898 4FD5] [348] [ONEP][AAA]: AAA is not configured, using local database [onep_al_aaa_session_authenticate:1476]

[02/07/14 16:49:46.898 4FD6] [348] [ONEP][AAA]: Authentication using local database: SUCCESS [onep_al_aaa_session_authenticate:1480]

[02/07/14 16:49:46.898 4FD7] [348] [ONEP][Session]: ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk: Authentication succeeded for user cisco [NetworkElement_connectIDL:473]

[02/07/14 16:49:46.898 4FD8] [348] [ONEP][Server]: auth success. ratep: 0x0 [onep_rate_limit_update:982]

[02/07/14 16:49:46.898 4FD9] [348] [ONEP][Session]: Searching for application with AID ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk resulted in ONEPK_VANILLA_ROUTE_TEST-uca-2.uca.ucl.ac.uk-4809 [NetworkElement_connectIDL:531]

[02/07/14 16:49:46.898 4FDA] [348] [ONEP][Session]: Connect: provide unique application name [NetworkElement_connectIDL:643]

[02/07/14 16:49:46.898 4FDB] [348] [ONEP][Session]: Exception Raised: Connect: provide unique application name [onep_new_exception:46]

[02/07/14 16:49:46.898 4FDC] [348] [ONEP][Message]: Write cthrift buffer to socket 2: bytes 103 [cthrift_write_entire_buffer__:318]

[02/07/14 16:49:46.898 4FDD] [348] [ONEP][Session]: ONEP TLS close fd: 2, pid: 348 [onep_al_tls_close:227]

[02/07/14 16:49:46.898 4FDE] [348] [ONEP][Session]: IOS: close_ctxt_fd [close_ctxt_fd:62]

Highlighted
Hall of Fame Cisco Employee

I just noticed something.  You're show run has version at 15.3, but you said you updated to the latest AiO VM, which should give you API version 1.1.0 and IOSv version 15.4.  Can you confirm you are in fact testing API version 1.1.0 against an IOSv instance running 15.4?  The "show ver" should be:

Cisco IOS Software, vios Software (vios-ADVENTERPRISEK9-M), Experimental Version 15.4(20131213:232637) [lucylee-ca_pi23 137]

For reference, here is a healthy trace of your code:

*Feb  6 07:20:59.703: [336] [ONEP][Session]: ONEP TLS done accept_fd: 2, pid: 336, context: 12DA77E0 [onep_al_tls_accept:239]

*Feb  6 07:20:59.807: [336] [ONEP][Message]: Server Done tos 1 [cthrift_recv_main__:2644]

*Feb  6 07:20:59.807: [336] [ONEP][Message]: Received 140(bytes) equal to or grater than parsed 140(bytes) [cthrift_recv_main__:2654]

*Feb  6 07:20:59.807: [336] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk: Connecting attempt: timeout[0] shandle[0] fd[2] addr[10.20.10.1] port[55500] transport[onep tls server] [NetworkElement_connectIDL:455]

*Feb  6 07:20:59.807: [336] [ONEP][AAA]: Authenticating ONEP Session for appname ONEPK_ROUTE_TEST [onep_al_aaa_session_authenticate:1472]

*Feb  6 07:20:59.807: [336] [ONEP][AAA]: AAA is not configured, using local database [onep_al_aaa_session_authenticate:1476]

*Feb  6 07:20:59.807: [336] [ONEP][AAA]: Authentication using local database: SUCCESS [onep_al_aaa_session_authenticate:1480]

*Feb  6 07:20:59.807: [336] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk: Authentication succeeded for user CISCO [NetworkElement_connectIDL:473]

*Feb  6 07:20:59.807: [336] [ONEP][Server]: auth success. ratep: 0x0 [onep_rate_limit_update:982]

*Feb  6 07:20:59.807: [336] [ONEP][Session]: Searching for application with AID ONEPK_ROUTE_TEST-onepk resulted in No App Found [NetworkElement_connectIDL:531]

*Feb  6 07:20:59.807: [336] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk: FSM: [Disconnected] ==> [Connecting] remote_addr[] port[0] [network_app_fsm_connecting:2828]

*Feb  6 07:20:59.807: [336] [ONEP][Session]: Fail to find handle [9226] [network_element_find_app_by_handle:562]

*Feb  6 07:20:59.807: [336] [ONEP][Session]: Fail to find handle [9226] [network_element_find_app_by_handle:562]

*Feb  6 07:20:59.807: [336] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: [0x1325C3A0][240A] added [network_element_add_app_internal:396]

*Feb  6 07:20:59.807: [336] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Connecting with handle [0x240A] at Thu Feb 06 07:20:59.807 [network_app_fsm_connecting:2856]

*Feb  6 07:20:59.807: [336] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: FSM: [Connecting] ==> [Authenticated] remote_addr[] port[0] [network_app_fsm_authenticated:2985]

*Feb  6 07:20:59.807: [336] [ONEP][Session]: entering ... [create_application_process:1966]

*Feb  6 07:20:59.807: [336] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: stack size changed from =12000 bytes, to =200% of normal [create_application_process:2024]

*Feb  6 07:20:59.809: [3] [ONEP][Server]: app name ONEPK_ROUTE_TEST session handle 0x240A [network_application_xdm_init:2292]

*Feb  6 07:20:59.809: [3] [ONEP][Session]: ONEPK_ROUTE_TEST: attach async stats return retval 0 Unknown error 0 [network_application_xdm_init:2356]

*Feb  6 07:20:59.809: [3] [ONEP][Session]: ONEPK_ROUTE_TEST: attach timer return retval 0 Unknown error 0 [network_application_xdm_init:2362]

*Feb  6 07:20:59.809: [336] [ONEP][Session]: TLS dup old <2, 336>, new<0, 3> [onep_al_tls_dup:285]

*Feb  6 07:20:59.809: [336] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Cloned fd 2 -> 0 [ne_to_app_fd_clone:2087]

*Feb  6 07:20:59.809: [336] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: cthrift_rb @0x13704B20 status = 0x8 [NetworkElement_connectIDL:780]

*Feb  6 07:20:59.809: [336] [ONEP][Message]: Write cthrift buffer to socket 2: bytes 425 [cthrift_write_entire_buffer__:318]

*Feb  6 07:20:59.809: [336] [ONEP][Message]: cthrift wrote 425 bytes, 0 remaining to send, took 0 usec [cthrift_write_entire_buffer__:386]

*Feb  6 07:20:59.809: [336] [ONEP][Session]: ONEP TLS close fd: 2, pid: 336 [onep_al_tls_close:227]

*Feb  6 07:21:00.053: [336] [ONEP][Session]: ONEP TLS done accept_fd: 2, pid: 336, context: 11277960 [onep_al_tls_accept:239]

*Feb  6 07:21:00.155: [336] [ONEP][Message]: Server Done tos 1 [cthrift_recv_main__:2644]

*Feb  6 07:21:00.155: [336] [ONEP][Message]: Received 48(bytes) equal to or grater than parsed 48(bytes) [cthrift_recv_main__:2654]

*Feb  6 07:21:00.155: [336] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: [0x1325C3A0][240A] found [network_element_find_app_by_handle:555]

*Feb  6 07:21:00.155: [336] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Event channel fd[2] [NetworkElement_evtChannelIDL:886]

*Feb  6 07:21:00.157: [336] [ONEP][Session]: TLS dup old <2, 336>, new<1, 3> [onep_al_tls_dup:285]

*Feb  6 07:21:00.157: [336] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Cloned fd 2 -> 1 [ne_to_app_fd_clone:2087]

*Feb  6 07:21:00.157: [336] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: FSM: [Authenticated] ==> [Connected] remote_addr[10.20.10.1] port[55501] [network_app_fsm_connected:3074]

*Feb  6 07:21:00.157: [336] [ONEP][Server]: entering ... [onep_ha_ctx_store:241]

*Feb  6 07:21:00.157: [336] [ONEP][Server]: service=0, table=0, session handle (key)=0x240A cidl_onep_ha_netapp_ctx_size_hint: 2178 [onep_ha_ctx_store:244]

*Feb  6 07:21:00.157: [336] [ONEP][Server]: stored app name ONEPK_ROUTE_TEST session handle 0x240A [onep_ha_ctx_store:258]

*Feb  6 07:21:00.157: [336] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Connected with handle [240A] at Thu Feb 06 07:21:00.157 [network_app_fsm_connected:3115]

*Feb  6 07:21:00.157: [336] [ONEP][Message]: Write cthrift buffer to socket 2: bytes 48 [cthrift_write_entire_buffer__:318]

*Feb  6 07:21:00.159: [336] [ONEP][Message]: cthrift wrote 48 bytes, 0 remaining to send, took 0 usec [cthrift_write_entire_buffer__:386]

*Feb  6 07:21:00.159: [336] [ONEP][Session]: ONEP TLS close fd: 2, pid: 336 [onep_al_tls_close:227]

*Feb  6 07:21:00.159: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Starting keepalive timer for 60 secs [network_application_process:1720]

*Feb  6 07:21:00.159: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: session_init [onep_session_manager_session_init:326]

*Feb  6 07:21:00.159: [3] [ONEP][Event]: Session init for handle 9226 [onep_async_session_init:949]

*Feb  6 07:21:00.159: [3] [ONEP][Event]: store async session handle=9226 successfully [onep_event_async_session_store:1434]

*Feb  6 07:21:00.159: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Async session_init done [onep_session_manager_session_init:336]

*Feb  6 07:21:00.159: [3] [ONEP][Event]: SESSION_INIT: session handle 9226 [onep_event_session_init:1024]

*Feb  6 07:21:00.159: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: [0x1325C3A0][240A] found [network_element_find_app_by_handle:555]

*Feb  6 07:21:00.159: [3] [ONEP][Event]: init new context pid 3 handle: 9226 [fh_first_time_init:626]

*Feb  6 07:21:00.159: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Event session_init done [onep_session_manager_session_init:336]

*Feb  6 07:21:00.159: [3] [ONEP][Policy]: Async thread already created [create_async_policy_thread:735]

*Feb  6 07:21:00.159: [3] [ONEP][Policy]: Binding to XOS for client 9226 [policy_bulk_session_init:379]

*Feb  6 07:21:00.161: [3] [ONEP][Policy]: Binding to XOS - xos_async_wait retured successfully [policy_bulk_session_init:394]

*Feb  6 07:21:00.161: [3] [ONEP][Policy]: Unknown error 0 in bind_result.status [policy_bulk_session_init:406]

*Feb  6 07:21:00.161: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: [0x1325C3A0][240A] found [network_element_find_app_by_handle:555]

*Feb  6 07:21:00.161: [3] [ONEP][Policy]: Session init 9226 [onep_policy_session_init:549]

*Feb  6 07:21:00.161: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Policy session_init done [onep_session_manager_session_init:336]

*Feb  6 07:21:00.161: [3] [ONEP][VTY]: onep_vty_session_init: Session init 9226l [onep_vty_session_init:2206]

*Feb  6 07:21:00.161: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: VTY session_init done [onep_session_manager_session_init:336]

*Feb  6 07:21:00.161: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Topology session_init done [onep_session_manager_session_init:336]

*Feb  6 07:21:00.161: [3] [ONEP][MEDIATRACE]: ONEP Mediatrace: Ignoring session init

[onep_pathtrace_event_session_init:795]

*Feb  6 07:21:00.161: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Mediatrace session_init done [onep_session_manager_session_init:336]

*Feb  6 07:21:00.161: [3] [ONEP][ROUTING]: ONEP Routing: Session init sh: 9226 [onep_rtg_svc_session_init:140]

*Feb  6 07:21:00.161: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: [0x1325C3A0][240A] found [network_element_find_app_by_handle:555]

*Feb  6 07:21:00.161: [3] [ONEP][ROUTING]: session_init, rtg_client_handle 0 [onep_rtg_svc_session_init:146]

*Feb  6 07:21:00.161: [3] [ONEP][ROUTING]: ONEP Routing: Session init sh: 9226, app: 0x1325C3A0 [onep_rtg_svc_session_init:163]

*Feb  6 07:21:00.161: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Routing session_init done [onep_session_manager_session_init:336]

*Feb  6 07:21:00.193: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Session event [0x1] occured [network_app_session_handler:1432]

*Feb  6 07:21:00.193: [3] [ONEP][Session]: TLS reset ioref fd: 0 [onep_tls_reset_ioref:210]

*Feb  6 07:21:00.193: [3] [ONEP][Session]: TLS reset ioref fd: 1 [onep_tls_reset_ioref:210]

*Feb  6 07:21:00.195: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Session event [0x1] occured [network_app_session_handler:1432]

*Feb  6 07:21:00.195: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Session event [0x1] occured [network_app_session_handler:1432]

*Feb  6 07:21:00.195: [3] [ONEP][Message]: Server Done tos 1 [cthrift_recv_main__:2644]

*Feb  6 07:21:00.195: [3] [ONEP][Message]: Received 86(bytes) equal to or grater than parsed 86(bytes) [cthrift_recv_main__:2654]

*Feb  6 07:21:00.197: [3] [ONEP][Interface]: Interface List request: xosHandle: -1 ifType: 1 slot:0 [NetworkElement_getInterfaceListIDL:1575]

*Feb  6 07:21:00.199: [3] [ONEP][Message]: Write cthrift buffer to socket 0: bytes 495 [cthrift_write_entire_buffer__:318]

*Feb  6 07:21:00.201: [3] [ONEP][Message]: cthrift wrote 495 bytes, 0 remaining to send, took 0 usec [cthrift_write_entire_buffer__:386]

*Feb  6 07:21:00.201: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: API served - done [network_app_process_cthrift_msg:1368]

*Feb  6 07:21:00.209: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Session event [0x1] occured [network_app_session_handler:1432]

*Feb  6 07:21:00.211: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Session event [0x1] occured [network_app_session_handler:1432]

*Feb  6 07:21:00.213: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Session event [0x1] occured [network_app_session_handler:1432]

*Feb  6 07:21:00.219: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Session event [0x1] occured [network_app_session_handler:1432]

*Feb  6 07:21:00.225: [3] [ONEP][Message]: Server Done tos 1 [cthrift_recv_main__:2644]

*Feb  6 07:21:00.225: [3] [ONEP][Message]: Received 329(bytes) equal to or grater than parsed 329(bytes) [cthrift_recv_main__:2654]

*Feb  6 07:21:00.225: [3] [ONEP][ROUTING]: Routing L3 UCast Update Route [Routing_L3UcastARTUpdateRoutesIDL:717]

*Feb  6 07:21:00.225: [145] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: [0x1325C3A0][240A] found [network_element_find_app_by_handle:555]

*Feb  6 07:21:00.225: [145] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: [0x1325C3A0][240A] found [network_element_find_app_by_handle:555]

*Feb  6 07:21:00.225: [145] [ONEP][ROUTING]: UpdateRoute: Registering ONEPK_ROUTE_TEST:9226 with art [onep_al_l3_ucast_update_app_route:2325]

*Feb  6 07:21:00.225: [145] [ONEP][ROUTING]: App route table init, app name ONEPK_ROUTE_TEST:9226 [onep_al_app_route_table_init:1472]

*Feb  6 07:21:00.225: [145] [ONEP][ROUTING]: APP register with ART: app_handle 1 [onep_al_app_route_table_init:1480]

*Feb  6 07:21:00.225: [145] [ONEP][ROUTING]: Update routed: Received list of size 1 [onep_al_l3_ucast_update_app_route:2341]

*Feb  6 07:21:00.227: [145] [ONEP][ROUTING]: Update route; process list item 0  [onep_al_l3_ucast_update_app_route:2343]

*Feb  6 07:21:00.227: [145] [ONEP][ROUTING]: Replace route Api for app 1 [onep_al_l3_ucast_art_replace_route:2205]

*Feb  6 07:21:00.227: [145] [ONEP][ROUTING]: art rep route: route with hop list size 1 [onep_al_l3_ucast_art_replace_route:2208]

*Feb  6 07:21:00.227: [145] [ONEP][ROUTING]: App route admin distance: 4 [routing_create_app_route_info:1543]

*Feb  6 07:21:00.227: [145] [ONEP][ROUTING]: Scope2topoid: setting vrf id to default [onep_al_l3_ucast_scope2topoid:923]

*Feb  6 07:21:00.227: [145] [ONEP][ROUTING]: route topoid is 0 [routing_create_app_route_info:1551]

*Feb  6 07:21:00.227: [145] [ONEP][ROUTING]: Scope2topoid: setting vrf id to default [onep_al_l3_ucast_scope2topoid:923]

*Feb  6 07:21:00.227: [145] [ONEP][ROUTING]: nh topoid is 0 [routing_create_app_route_info:1615]

*Feb  6 07:21:00.227: [145] [ONEP][ROUTING]: art replace route: Succeed to replace route for hop number 0 [onep_al_l3_ucast_art_replace_route:2235]

*Feb  6 07:21:00.227: [145] [ONEP][ROUTING]: art replace route: Replace route success for all hops [onep_al_l3_ucast_art_replace_route:2270]

*Feb  6 07:21:00.227: [145] [ONEP][ROUTING]: Route replace status 0 [onep_al_l3_ucast_update_app_route:2390]

*Feb  6 07:21:00.227: [145] [ONEP][ROUTING]: Update status for list item 0 is 0 [onep_al_l3_ucast_update_app_route:2411]

*Feb  6 07:21:00.227: [145] [ONEP][ROUTING]: UpdateRoute: all route operations success [onep_al_l3_ucast_update_app_route:2416]

*Feb  6 07:21:00.227: [145] [ONEP][ROUTING]: Number of routes updated: 1 [update_routes_deferred_cb:104]

*Feb  6 07:21:00.227: [145] [ONEP][ROUTING]: UpdateRoute:route list size 1 [update_routes_deferred_cb:107]

*Feb  6 07:21:00.227: [145] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: [0x1325C3A0][240A] found [network_element_find_app_by_handle:555]

*Feb  6 07:21:00.229: [3] [ONEP][Message]: Write cthrift buffer to socket 0: bytes 294 [cthrift_write_entire_buffer__:318]

*Feb  6 07:21:00.229: [3] [ONEP][Message]: cthrift wrote 294 bytes, 0 remaining to send, took 0 usec [cthrift_write_entire_buffer__:386]

*Feb  6 07:21:00.229: [3] [ONEP][ROUTING]: Cleanup update route list

[Routing_L3UcastARTUpdateRoutesIDL_cleanup:771]

*Feb  6 07:21:00.229: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: API served - done [network_app_process_cthrift_msg:1368]

*Feb  6 07:21:00.231: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Session event [0x1] occured [network_app_session_handler:1432]

*Feb  6 07:21:00.231: [3] [ONEP][Session]: ONEP TLS recv error <-2001> for fd: 0, pid: 3 [onep_al_tls_recv:115]

*Feb  6 07:21:00.231: [3] [ONEP][Session]: ONEP TLS close fd: 0, pid: 3 [onep_al_tls_close:227]

*Feb  6 07:21:00.231: [3] [ONEP][Session]: IOS: close_ctxt_fd [close_ctxt_fd:62]

*Feb  6 07:21:00.233: [3] [ONEP][Message]: cthrift read returning due to error. errno = 0 [cthrift_recv_check_rb__:510]

*Feb  6 07:21:00.233: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: cthrift error: -65539 'system error' [na_rx_fsm_do_cthrift_read:1148]

*Feb  6 07:21:00.233: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: NA_RX_FSM_STATE_READ error (1) - generating NA_RX_FSM_STATE_CLEANUP [network_app_process_cthrift_msg:1323]

*Feb  6 07:21:00.233: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: NA_RX_FSM_STATE_CLEANUP - generating NETWORK_APP_STATE_DISCONNECTED [network_app_process_cthrift_msg:1371]

*Feb  6 07:21:00.233: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: FSM: [Connected] ==> [Disconnected] remote_addr[10.20.10.1] port[55500] [network_app_fsm_disconnected:3220]

*Feb  6 07:21:00.233: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Disconnected with handle [240A] at Thu Feb 06 07:21:00.233 [network_app_fsm_disconnected:3334]

*Feb  6 07:21:00.233: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: [0x1325C3A0][240A] found [network_element_find_app_by_handle:555]

*Feb  6 07:21:00.235: [3] [ONEP][Session]: caller pc 0x0x24D2B3A [network_application_final_cleanup:2511]

*Feb  6 07:21:00.235: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: session_exit [onep_session_manager_session_exit:400]

*Feb  6 07:21:00.235: [3] [ONEP][Event]: Session exit for handle 9226 [onep_async_session_exit:984]

*Feb  6 07:21:00.235: [3] [ONEP][Event]: delete async tbl elem session handle= 9226 successfully [onep_event_async_session_remove:1455]

*Feb  6 07:21:00.235: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Async session_exit done [onep_session_manager_session_exit:416]

*Feb  6 07:21:00.235: [3] [ONEP][Event]: SESSION_EXIT: session handle 9226 [onep_event_session_exit:1046]

*Feb  6 07:21:00.235: [3] [ONEP][Event]: get by session_handle looking for: 9226 [fh_get_ctx_block_by_session_handle:275]

*Feb  6 07:21:00.235: [3] [ONEP][Event]: get by session_handle found: 9226 [fh_get_ctx_block_by_session_handle:278]

*Feb  6 07:21:00.235: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Event session_exit done [onep_session_manager_session_exit:416]

*Feb  6 07:21:00.235: [3] [ONEP][Policy]: Session exit 9226 [onep_policy_session_exit:570]

*Feb  6 07:21:00.235: [3] [ONEP][Policy]: Deleting Classes [onep_al_policy_delete_all_classes:490]

*Feb  6 07:21:00.235: [3] [ONEP][Policy]: No policy created [onep_al_policy_delete_all_policies:165]

*Feb  6 07:21:00.235: [3] [ONEP][Policy]: Deleting ACLs [onep_al_acl_delete_all_acls:275]

*Feb  6 07:21:00.235: [3] [ONEP][Policy]: Deleting ACEs [onep_al_acl_delete_all_acls:370]

*Feb  6 07:21:00.235: [3] [ONEP][Policy]: @@@calling xos_plc_unbind id : 10 [policy_bulk_session_cleanup:456]

*Feb  6 07:21:00.235: [3] [ONEP][Policy]: @@@policy_bulk_get_client_handle: 10 [policy_bulk_get_client_handle:139]

*Feb  6 07:21:00.235: [3] [ONEP][Policy]: @@@unbind is successful [policy_bulk_session_cleanup:463]

*Feb  6 07:21:00.235: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Policy session_exit done [onep_session_manager_session_exit:416]

*Feb  6 07:21:00.235: [3] [ONEP][VTY]: Session exit 9226l [onep_vty_session_exit:2222]

*Feb  6 07:21:00.237: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: [0x1325C3A0][240A] found [network_element_find_app_by_handle:555]

*Feb  6 07:21:00.237: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: VTY session_exit done [onep_session_manager_session_exit:416]

*Feb  6 07:21:00.237: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Topology session_exit done [onep_session_manager_session_exit:416]

*Feb  6 07:21:00.237: [3] [ONEP][MEDIATRACE]: ONEP Mediatrace: session exit

[onep_pathtrace_event_session_exit:809]

*Feb  6 07:21:00.237: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Mediatrace session_exit done [onep_session_manager_session_exit:416]

*Feb  6 07:21:00.237: [3] [ONEP][ROUTING]: ONEP Routing: session exit sh: 9226 [onep_rtg_svc_session_exit:178]

*Feb  6 07:21:00.237: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: [0x1325C3A0][240A] found [network_element_find_app_by_handle:555]

*Feb  6 07:21:00.237: [3] [ONEP][ROUTING]: session exit: app handle 1, rtg_session_id 9226, session_handle 9226 [onep_rtg_svc_session_exit:187]

*Feb  6 07:21:00.237: [3] [ONEP][ROUTING]: calling onep_al_app_route_table_deinit 1 [onep_rtg_svc_session_exit:201]

*Feb  6 07:21:00.237: [3] [ONEP][ROUTING]: App route table deinit [onep_al_app_route_table_deinit:119]

*Feb  6 07:21:00.237: [3] [ONEP][ROUTING]: ONEP Routing: session exit sh: 9226 app: 0x1325C3A0 [onep_rtg_svc_session_exit:208]

*Feb  6 07:21:00.237: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Routing session_exit done [onep_session_manager_session_exit:416]

*Feb  6 07:21:00.237: [3] [ONEP][DATAPATH]: Subblock is NULL for session - 9226 [onep_datapath_session_exit:64]

*Feb  6 07:21:00.237: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Datapath session_exit done [onep_session_manager_session_exit:416]

*Feb  6 07:21:00.237: [336] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: [0x1325C3A0][240A] removed [network_element_remove_app_cb:239]

*Feb  6 07:21:00.237: [336] [ONEP][Server]: service=0, table=0, session handle (key)=0x240A [onep_ha_ctx_remove:270]

*Feb  6 07:21:00.237: [336] [ONEP][Server]: removed app name ONEPK_ROUTE_TEST session handle 0x240A [onep_ha_ctx_remove:281]

*Feb  6 07:21:00.237: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: Session history archived, Count = 10 [onep_app_history_archive:281]

*Feb  6 07:21:00.237: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: session_update thread [-1] [onep_session_manager_session_update:360]

*Feb  6 07:21:00.237: [3] [ONEP][Session]: Fail to find handle [9226] [network_element_find_app_by_handle:562]

*Feb  6 07:21:00.237: [3] [ONEP][Session]: ONEPK_ROUTE_TEST-onepk-9226: session_update fail [9226] [onep_session_manager_session_update:368]

*Feb  6 07:21:00.237: [3] [ONEP][Session]: ONEP TLS close fd: 1, pid: 3 [onep_al_tls_close:227]

*Feb  6 07:21:00.237: [3] [ONEP][Session]: IOS: close_ctxt_fd [close_ctxt_fd:62]

Highlighted

Thanks very much Joe. I checked the versions, they're correct. I also checked the behaviour is the same whether running JUnit tests or static main() method to do the same things.

I use Eclipse under Mac OS X for development, and fire up the All-in-one VM using Oracle VirtualBox. Thus I run all my tests from Mac OS X. The tests all use onePK to the same router(s) - but only that particular test fails.

Here's the thing that proves it's somehow environmental though. When I run that particular test from Eclipse under Ubuntu inside the All-in-one VM, it does indeed work (along with all the others which work from Mac OS X anyway). Not only that, but the tests all complete much quicker (from about 8 seconds per simple test to about 2).

So there's something about the routing environment between Mac OS X and the VirtualBox which is introducing the observed behaviour and somehow breaks just that one test.

I've turned on packet forwarding in both the All-in-one VM (sysctl -w net.ipv4.ip_forward=1) and in Mac OS X (sysctl -w net.inet.ip.forwarding=1). You'll notice the router conf file #126 has a static route:

  ip route 192.168.56.0 255.255.255.0 10.10.10.100

where 192.168.56.0 is the net shared with the Mac OS and 10.10.10.100 is the adapter address of the All-in-one VM on a vmcloud routable LAN.

The Mac has a static route set up as follows:

  route add -net 10.10.10.0 192.168.56.101 255.255.255.0

where 192.168.56.101 is the host address of the All-in-one VM on that same net and 10.10.10.0 is the vmcloud routable LAN.

Is there anything obvious I should look for, if (for example) some packets are getting lost en route and others are getting through?

Highlighted
Hall of Fame Cisco Employee

While I have used the static routes approach in the past (and I don't recall seeing any weirdness, but I use VMware Fusion), you shouldn't need to do that these days assuming you use the default 3node topology, or you create a topology that shares a NIC with the Linux VM.  In the 3node topology, each one of the IOSv instances has an interface connected to a VM shared with Linux and with the host (your Mac).  On my Mac, this subnet is 172.16.129.0/24.  If I use these addresses for connecting to my IOSv instances, I don't have to worry with any routing.  Everything is bridged.

While it would be weird to see some packets dropped, you might want to check to see if you have your firewall enabled on either the Mac or Linux side.  On the Mac, check "sudo ipfw show".  On Linux, check "sudo iptables --list".  There may be some oddities in vBox, too, but I've never used it, so I'm not sure where to begin there except maybe Google for similar-sounding cases.