z.archive.ovsdb-dev@lists.opendaylight.org | Abrupt closing of socket connection between OVSDB client and server.

Home Messages Hashtags Subgroups

This group is locked. No changes can be made to the group while it is locked.

Date Date 1 - 3 of 3

Abrupt closing of socket connection between OVSDB client and server.

Anil Jangam <anilj.mailing@...>

Hi All,

I have a situation where (apparently) the ODL client is closing the socket connection with the remote ovsdb server. I am using a normal TCP socket API.

While client is waiting for a response after sending the "transact" request, an CancellationException is being received. I am attaching the two types of logs below.

Has anyone faced this problem before? What are the potential reasons for this? Any help in this regard will be highly useful.

Is there any missing socket level negotiation, which might be causing this problem? I am just thinking aloud.

Initialization logs:

=============

The ovsdb client initialization debug logs are here.

2018-05-14T18:02:02.886-0700 [debug] [io.netty.channel.MultithreadEventLoopGroup][debug:76] - -Dio.netty.eventLoopThreads: 16

2018-05-14T18:02:02.915-0700 [debug] [io.netty.util.internal.PlatformDependent][debug:71] - Platform: MacOS

2018-05-14T18:02:02.916-0700 [debug] [io.netty.util.internal.PlatformDependent0][debug:76] - -Dio.netty.noUnsafe: false

2018-05-14T18:02:02.917-0700 [debug] [io.netty.util.internal.PlatformDependent0][debug:76] - Java version: 8

2018-05-14T18:02:02.918-0700 [debug] [io.netty.util.internal.PlatformDependent0][debug:71] - sun.misc.Unsafe.theUnsafe: available

2018-05-14T18:02:02.919-0700 [debug] [io.netty.util.internal.PlatformDependent0][debug:71] - sun.misc.Unsafe.copyMemory: available

2018-05-14T18:02:02.919-0700 [debug] [io.netty.util.internal.PlatformDependent0][debug:71] - java.nio.Buffer.address: available

2018-05-14T18:02:02.920-0700 [debug] [io.netty.util.internal.PlatformDependent0][debug:71] - direct buffer constructor: available

2018-05-14T18:02:02.920-0700 [debug] [io.netty.util.internal.PlatformDependent0][debug:76] - java.nio.Bits.unaligned: available, true

2018-05-14T18:02:02.920-0700 [debug] [io.netty.util.internal.PlatformDependent0][debug:71] - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable prior to Java9

2018-05-14T18:02:02.920-0700 [debug] [io.netty.util.internal.PlatformDependent0][debug:76] - java.nio.DirectByteBuffer.<init>(long, int): available

2018-05-14T18:02:02.921-0700 [debug] [io.netty.util.internal.PlatformDependent][debug:76] - sun.misc.Unsafe: available

2018-05-14T18:02:02.921-0700 [debug] [io.netty.util.internal.PlatformDependent][debug:76] - -Dio.netty.tmpdir: /var/folders/r0/f7kkkm9526lgfz6jtgtphyww0000gn/T (java.io.tmpdir)

2018-05-14T18:02:02.921-0700 [debug] [io.netty.util.internal.PlatformDependent][debug:76] - -Dio.netty.bitMode: 64 (sun.arch.data.model)

2018-05-14T18:02:02.923-0700 [debug] [io.netty.util.internal.PlatformDependent][debug:76] - -Dio.netty.noPreferDirect: false

2018-05-14T18:02:02.923-0700 [debug] [io.netty.util.internal.PlatformDependent][debug:76] - -Dio.netty.maxDirectMemory: 3817865216 bytes

2018-05-14T18:02:02.923-0700 [debug] [io.netty.util.internal.PlatformDependent][debug:76] - -Dio.netty.uninitializedArrayAllocationThreshold: -1

2018-05-14T18:02:02.924-0700 [debug] [io.netty.util.internal.CleanerJava6][debug:71] - java.nio.ByteBuffer.cleaner(): available

2018-05-14T18:02:02.937-0700 [debug] [io.netty.channel.nio.NioEventLoop][debug:76] - -Dio.netty.noKeySetOptimization: false

2018-05-14T18:02:02.937-0700 [debug] [io.netty.channel.nio.NioEventLoop][debug:76] - -Dio.netty.selectorAutoRebuildThreshold: 512

2018-05-14T18:02:02.946-0700 [debug] [io.netty.util.internal.PlatformDependent][debug:71] - org.jctools-core.MpscChunkedArrayQueue: available

2018-05-14T18:02:02.954-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@5fe2a63f

2018-05-14T18:02:02.955-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@15aa97a

2018-05-14T18:02:02.955-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@4bc33430

2018-05-14T18:02:02.955-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@5ee23db

2018-05-14T18:02:02.955-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@1850bb3b

2018-05-14T18:02:02.956-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@4c15c032

2018-05-14T18:02:02.956-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@1ea50f34

2018-05-14T18:02:02.956-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@6aa107c0

2018-05-14T18:02:02.956-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@7735f0cc

2018-05-14T18:02:02.956-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@1543aa48

2018-05-14T18:02:02.957-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@23a9cb7b

2018-05-14T18:02:02.957-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@41d447c9

2018-05-14T18:02:02.957-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@193f6caf

2018-05-14T18:02:02.957-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@11a6942a

2018-05-14T18:02:02.957-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@7cb96776

2018-05-14T18:02:02.957-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@1fb08d27

2018-05-14T18:02:02.958-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@2715907d

2018-05-14T18:02:02.958-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@4a479329

2018-05-14T18:02:02.959-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@27f8e0

2018-05-14T18:02:02.959-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@195b9769

2018-05-14T18:02:02.959-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@12466a47

2018-05-14T18:02:02.959-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@646e6dfd

2018-05-14T18:02:02.959-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@5bb16968

2018-05-14T18:02:02.959-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@1e144da8

2018-05-14T18:02:02.960-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@3f21187f

2018-05-14T18:02:02.960-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@28b78be3

2018-05-14T18:02:02.960-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@781d5db4

2018-05-14T18:02:02.960-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@44582612

2018-05-14T18:02:02.960-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@730d2c06

2018-05-14T18:02:02.960-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@67714917

2018-05-14T18:02:02.960-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@751348b0

2018-05-14T18:02:02.961-0700 [trace] [io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@70fe88b6

2018-05-14T18:02:02.995-0700 [debug] [io.netty.channel.DefaultChannelId][debug:76] - -Dio.netty.processId: 33206 (auto-detected)

2018-05-14T18:02:02.997-0700 [debug] [io.netty.util.NetUtil][debug:76] - -Djava.net.preferIPv4Stack: false

2018-05-14T18:02:02.997-0700 [debug] [io.netty.util.NetUtil][debug:76] - -Djava.net.preferIPv6Addresses: false

2018-05-14T18:02:02.998-0700 [debug] [io.netty.util.NetUtil][debug:86] - Loopback interface: lo0 (lo0, 0:0:0:0:0:0:0:1)

2018-05-14T18:02:02.999-0700 [debug] [io.netty.util.NetUtil][debug:81] - Failed to get SOMAXCONN from sysctl and file /proc/sys/net/core/somaxconn. Default: 128

2018-05-14T18:02:03.001-0700 [debug] [io.netty.channel.DefaultChannelId][debug:76] - -Dio.netty.machineId: a0:99:9b:ff:fe:14:8e:57 (auto-detected)

2018-05-14T18:02:03.006-0700 [debug] [io.netty.util.internal.InternalThreadLocalMap][debug:76] - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024

2018-05-14T18:02:03.006-0700 [debug] [io.netty.util.internal.InternalThreadLocalMap][debug:76] - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096

2018-05-14T18:02:03.014-0700 [debug] [io.netty.util.ResourceLeakDetector][debug:81] - -Dio.netty.leakDetection.level: simple

2018-05-14T18:02:03.014-0700 [debug] [io.netty.util.ResourceLeakDetector][debug:81] - -Dio.netty.leakDetection.maxRecords: 4

2018-05-14T18:02:03.014-0700 [debug] [io.netty.util.ResourceLeakDetector][debug:81] - -Dio.netty.leakDetection.maxSampledRecords: 40

2018-05-14T18:02:03.036-0700 [debug] [io.netty.buffer.PooledByteBufAllocator][debug:76] - -Dio.netty.allocator.numHeapArenas: 16

2018-05-14T18:02:03.036-0700 [debug] [io.netty.buffer.PooledByteBufAllocator][debug:76] - -Dio.netty.allocator.numDirectArenas: 16

2018-05-14T18:02:03.036-0700 [debug] [io.netty.buffer.PooledByteBufAllocator][debug:76] - -Dio.netty.allocator.pageSize: 8192

2018-05-14T18:02:03.036-0700 [debug] [io.netty.buffer.PooledByteBufAllocator][debug:76] - -Dio.netty.allocator.maxOrder: 11

2018-05-14T18:02:03.037-0700 [debug] [io.netty.buffer.PooledByteBufAllocator][debug:76] - -Dio.netty.allocator.chunkSize: 16777216

2018-05-14T18:02:03.037-0700 [debug] [io.netty.buffer.PooledByteBufAllocator][debug:76] - -Dio.netty.allocator.tinyCacheSize: 512

2018-05-14T18:02:03.037-0700 [debug] [io.netty.buffer.PooledByteBufAllocator][debug:76] - -Dio.netty.allocator.smallCacheSize: 256

2018-05-14T18:02:03.037-0700 [debug] [io.netty.buffer.PooledByteBufAllocator][debug:76] - -Dio.netty.allocator.normalCacheSize: 64

2018-05-14T18:02:03.037-0700 [debug] [io.netty.buffer.PooledByteBufAllocator][debug:76] - -Dio.netty.allocator.maxCachedBufferCapacity: 32768

2018-05-14T18:02:03.037-0700 [debug] [io.netty.buffer.PooledByteBufAllocator][debug:76] - -Dio.netty.allocator.cacheTrimInterval: 8192

2018-05-14T18:02:03.037-0700 [debug] [io.netty.buffer.PooledByteBufAllocator][debug:76] - -Dio.netty.allocator.useCacheForAllThreads: true

2018-05-14T18:02:03.045-0700 [debug] [io.netty.buffer.ByteBufUtil][debug:76] - -Dio.netty.allocator.type: pooled

2018-05-14T18:02:03.045-0700 [debug] [io.netty.buffer.ByteBufUtil][debug:76] - -Dio.netty.threadLocalDirectBufferSize: 65536

2018-05-14T18:02:03.045-0700 [debug] [io.netty.buffer.ByteBufUtil][debug:76] - -Dio.netty.maxThreadLocalCharBufferSize: 16384

2018-05-14T18:02:03.046-0700 [warn] [io.netty.bootstrap.ServerBootstrap][warn:146] - Unknown channel option 'TCP_NODELAY' for channel '[id: 0x305b2780]'

2018-05-14T18:02:03.072-0700 [info] [io.netty.handler.logging.LoggingHandler][info:101] - [id: 0x305b2780] REGISTERED

2018-05-14T18:02:03.073-0700 [info] [io.netty.handler.logging.LoggingHandler][info:101] - [id: 0x305b2780] BIND: 0.0.0.0/0.0.0.0:6640

2018-05-14T18:02:03.076-0700 [info] [io.netty.handler.logging.LoggingHandler][info:101] - [id: 0x305b2780, L:/0:0:0:0:0:0:0:0:6640] ACTIVE

Exception details:

=============

2018-05-14T18:12:21.312-0700 [debug] [com.tool.automation.mockcontroller.ovsdb.context.transaction.Transact][sendOvsdbRequest:221] - Sending Transaction request to the ovsdb server

2018-05-14T18:12:21.321-0700 [trace] [org.opendaylight.ovsdb.lib.jsonrpc.JsonRpcEndpoint][lambda$getClient$1:118] - getClient Request : {"id":"749e050e-bc3a-4d40-a95b-4d27a603c31f","method":"transact","params":["hardware_vtep",{"op":"insert","row":{"name":"logical_switch_10003","tunnel_key":10003},"table":"Logical_Switch"}]}

java.util.concurrent.CancellationException: Task was cancelled.

at com.google.common.util.concurrent.AbstractFuture.cancellationExceptionWithCause(AbstractFuture.java:1228)

at com.google.common.util.concurrent.AbstractFuture.getDoneValue(AbstractFuture.java:526)

at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:507)

at com.google.common.util.concurrent.AbstractFuture$TrustedFuture.get(AbstractFuture.java:85)

at com.tool.automation.mockcontroller.ovsdb.context.transaction.Transact.sendOvsdbRequest(Transact.java:223)

at com.tool.automation.mockcontroller.ovsdb.context.transaction.Transact.executeTransaction(Transact.java:95)

at com.tool.automation.mockcontroller.processor.OvsdbRunner.run(OvsdbRunner.java:66)

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

2018-05-14T18:12:22.327-0700 [error] [com.tool.automation.mockcontroller.ovsdb.context.transaction.Transact][sendOvsdbRequest:226] - Task was cancelled.

2018-0

/anil.

Vishal Thapar <vthapar@...>

#4724

Hi Anil,

Is this case of ODL connecting to switch? There are two main reasons
you can see this exception:

1. Connection to switch is lost -  Either switch disconnected or is unreachable.
2. Multiple connections from switch, making this a stale connection so
terminating it.

Can you check switch logs and see if there are any disconnects?

Regards,
Vishal.

Show quoted text

On Tue, May 15, 2018 at 8:12 AM, Anil Jangam <anilj.mailing@...> wrote:

Hi All,

I have a situation where (apparently) the ODL client is closing the socket
connection with the remote ovsdb server. I am using a normal TCP socket API.

While client is waiting for a response after sending the "transact" request,
an CancellationException is being received. I am attaching the two types of
logs below.

Has anyone faced this problem before? What are the potential reasons for
this? Any help in this regard will be highly useful.

Is there any missing socket level negotiation, which might be causing this
problem? I am just thinking aloud.


Initialization logs:
=============

The ovsdb client initialization debug logs are here.

2018-05-14T18:02:02.886-0700 [debug]
[io.netty.channel.MultithreadEventLoopGroup][debug:76] -
-Dio.netty.eventLoopThreads: 16
2018-05-14T18:02:02.915-0700 [debug]
[io.netty.util.internal.PlatformDependent][debug:71] - Platform: MacOS
2018-05-14T18:02:02.916-0700 [debug]
[io.netty.util.internal.PlatformDependent0][debug:76] - -Dio.netty.noUnsafe:
false
2018-05-14T18:02:02.917-0700 [debug]
[io.netty.util.internal.PlatformDependent0][debug:76] - Java version: 8
2018-05-14T18:02:02.918-0700 [debug]
[io.netty.util.internal.PlatformDependent0][debug:71] -
sun.misc.Unsafe.theUnsafe: available
2018-05-14T18:02:02.919-0700 [debug]
[io.netty.util.internal.PlatformDependent0][debug:71] -
sun.misc.Unsafe.copyMemory: available
2018-05-14T18:02:02.919-0700 [debug]
[io.netty.util.internal.PlatformDependent0][debug:71] -
java.nio.Buffer.address: available
2018-05-14T18:02:02.920-0700 [debug]
[io.netty.util.internal.PlatformDependent0][debug:71] - direct buffer
constructor: available
2018-05-14T18:02:02.920-0700 [debug]
[io.netty.util.internal.PlatformDependent0][debug:76] -
java.nio.Bits.unaligned: available, true
2018-05-14T18:02:02.920-0700 [debug]
[io.netty.util.internal.PlatformDependent0][debug:71] -
jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable prior
to Java9
2018-05-14T18:02:02.920-0700 [debug]
[io.netty.util.internal.PlatformDependent0][debug:76] -
java.nio.DirectByteBuffer.<init>(long, int): available
2018-05-14T18:02:02.921-0700 [debug]
[io.netty.util.internal.PlatformDependent][debug:76] - sun.misc.Unsafe:
available
2018-05-14T18:02:02.921-0700 [debug]
[io.netty.util.internal.PlatformDependent][debug:76] - -Dio.netty.tmpdir:
/var/folders/r0/f7kkkm9526lgfz6jtgtphyww0000gn/T (java.io.tmpdir)
2018-05-14T18:02:02.921-0700 [debug]
[io.netty.util.internal.PlatformDependent][debug:76] - -Dio.netty.bitMode:
64 (sun.arch.data.model)
2018-05-14T18:02:02.923-0700 [debug]
[io.netty.util.internal.PlatformDependent][debug:76] -
-Dio.netty.noPreferDirect: false
2018-05-14T18:02:02.923-0700 [debug]
[io.netty.util.internal.PlatformDependent][debug:76] -
-Dio.netty.maxDirectMemory: 3817865216 bytes
2018-05-14T18:02:02.923-0700 [debug]
[io.netty.util.internal.PlatformDependent][debug:76] -
-Dio.netty.uninitializedArrayAllocationThreshold: -1
2018-05-14T18:02:02.924-0700 [debug]
[io.netty.util.internal.CleanerJava6][debug:71] -
java.nio.ByteBuffer.cleaner(): available
2018-05-14T18:02:02.937-0700 [debug]
[io.netty.channel.nio.NioEventLoop][debug:76] -
-Dio.netty.noKeySetOptimization: false
2018-05-14T18:02:02.937-0700 [debug]
[io.netty.channel.nio.NioEventLoop][debug:76] -
-Dio.netty.selectorAutoRebuildThreshold: 512
2018-05-14T18:02:02.946-0700 [debug]
[io.netty.util.internal.PlatformDependent][debug:71] -
org.jctools-core.MpscChunkedArrayQueue: available
2018-05-14T18:02:02.954-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@5fe2a63f
2018-05-14T18:02:02.955-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@15aa97a
2018-05-14T18:02:02.955-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@4bc33430
2018-05-14T18:02:02.955-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@5ee23db
2018-05-14T18:02:02.955-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@1850bb3b
2018-05-14T18:02:02.956-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@4c15c032
2018-05-14T18:02:02.956-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@1ea50f34
2018-05-14T18:02:02.956-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@6aa107c0
2018-05-14T18:02:02.956-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@7735f0cc
2018-05-14T18:02:02.956-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@1543aa48
2018-05-14T18:02:02.957-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@23a9cb7b
2018-05-14T18:02:02.957-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@41d447c9
2018-05-14T18:02:02.957-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@193f6caf
2018-05-14T18:02:02.957-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@11a6942a
2018-05-14T18:02:02.957-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@7cb96776
2018-05-14T18:02:02.957-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@1fb08d27
2018-05-14T18:02:02.958-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@2715907d
2018-05-14T18:02:02.958-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@4a479329
2018-05-14T18:02:02.959-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@27f8e0
2018-05-14T18:02:02.959-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@195b9769
2018-05-14T18:02:02.959-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@12466a47
2018-05-14T18:02:02.959-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@646e6dfd
2018-05-14T18:02:02.959-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@5bb16968
2018-05-14T18:02:02.959-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@1e144da8
2018-05-14T18:02:02.960-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@3f21187f
2018-05-14T18:02:02.960-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@28b78be3
2018-05-14T18:02:02.960-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@781d5db4
2018-05-14T18:02:02.960-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@44582612
2018-05-14T18:02:02.960-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@730d2c06
2018-05-14T18:02:02.960-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@67714917
2018-05-14T18:02:02.960-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@751348b0
2018-05-14T18:02:02.961-0700 [trace]
[io.netty.channel.nio.NioEventLoop][trace:46] - instrumented a special
java.util.Set into: sun.nio.ch.KQueueSelectorImpl@70fe88b6
2018-05-14T18:02:02.995-0700 [debug]
[io.netty.channel.DefaultChannelId][debug:76] - -Dio.netty.processId: 33206
(auto-detected)
2018-05-14T18:02:02.997-0700 [debug] [io.netty.util.NetUtil][debug:76] -
-Djava.net.preferIPv4Stack: false
2018-05-14T18:02:02.997-0700 [debug] [io.netty.util.NetUtil][debug:76] -
-Djava.net.preferIPv6Addresses: false
2018-05-14T18:02:02.998-0700 [debug] [io.netty.util.NetUtil][debug:86] -
Loopback interface: lo0 (lo0, 0:0:0:0:0:0:0:1)
2018-05-14T18:02:02.999-0700 [debug] [io.netty.util.NetUtil][debug:81] -
Failed to get SOMAXCONN from sysctl and file /proc/sys/net/core/somaxconn.
Default: 128
2018-05-14T18:02:03.001-0700 [debug]
[io.netty.channel.DefaultChannelId][debug:76] - -Dio.netty.machineId:
a0:99:9b:ff:fe:14:8e:57 (auto-detected)
2018-05-14T18:02:03.006-0700 [debug]
[io.netty.util.internal.InternalThreadLocalMap][debug:76] -
-Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
2018-05-14T18:02:03.006-0700 [debug]
[io.netty.util.internal.InternalThreadLocalMap][debug:76] -
-Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
2018-05-14T18:02:03.014-0700 [debug]
[io.netty.util.ResourceLeakDetector][debug:81] -
-Dio.netty.leakDetection.level: simple
2018-05-14T18:02:03.014-0700 [debug]
[io.netty.util.ResourceLeakDetector][debug:81] -
-Dio.netty.leakDetection.maxRecords: 4
2018-05-14T18:02:03.014-0700 [debug]
[io.netty.util.ResourceLeakDetector][debug:81] -
-Dio.netty.leakDetection.maxSampledRecords: 40
2018-05-14T18:02:03.036-0700 [debug]
[io.netty.buffer.PooledByteBufAllocator][debug:76] -
-Dio.netty.allocator.numHeapArenas: 16
2018-05-14T18:02:03.036-0700 [debug]
[io.netty.buffer.PooledByteBufAllocator][debug:76] -
-Dio.netty.allocator.numDirectArenas: 16
2018-05-14T18:02:03.036-0700 [debug]
[io.netty.buffer.PooledByteBufAllocator][debug:76] -
-Dio.netty.allocator.pageSize: 8192
2018-05-14T18:02:03.036-0700 [debug]
[io.netty.buffer.PooledByteBufAllocator][debug:76] -
-Dio.netty.allocator.maxOrder: 11
2018-05-14T18:02:03.037-0700 [debug]
[io.netty.buffer.PooledByteBufAllocator][debug:76] -
-Dio.netty.allocator.chunkSize: 16777216
2018-05-14T18:02:03.037-0700 [debug]
[io.netty.buffer.PooledByteBufAllocator][debug:76] -
-Dio.netty.allocator.tinyCacheSize: 512
2018-05-14T18:02:03.037-0700 [debug]
[io.netty.buffer.PooledByteBufAllocator][debug:76] -
-Dio.netty.allocator.smallCacheSize: 256
2018-05-14T18:02:03.037-0700 [debug]
[io.netty.buffer.PooledByteBufAllocator][debug:76] -
-Dio.netty.allocator.normalCacheSize: 64
2018-05-14T18:02:03.037-0700 [debug]
[io.netty.buffer.PooledByteBufAllocator][debug:76] -
-Dio.netty.allocator.maxCachedBufferCapacity: 32768
2018-05-14T18:02:03.037-0700 [debug]
[io.netty.buffer.PooledByteBufAllocator][debug:76] -
-Dio.netty.allocator.cacheTrimInterval: 8192
2018-05-14T18:02:03.037-0700 [debug]
[io.netty.buffer.PooledByteBufAllocator][debug:76] -
-Dio.netty.allocator.useCacheForAllThreads: true
2018-05-14T18:02:03.045-0700 [debug] [io.netty.buffer.ByteBufUtil][debug:76]
- -Dio.netty.allocator.type: pooled
2018-05-14T18:02:03.045-0700 [debug] [io.netty.buffer.ByteBufUtil][debug:76]
- -Dio.netty.threadLocalDirectBufferSize: 65536
2018-05-14T18:02:03.045-0700 [debug] [io.netty.buffer.ByteBufUtil][debug:76]
- -Dio.netty.maxThreadLocalCharBufferSize: 16384
2018-05-14T18:02:03.046-0700 [warn]
[io.netty.bootstrap.ServerBootstrap][warn:146] - Unknown channel option
'TCP_NODELAY' for channel '[id: 0x305b2780]'
2018-05-14T18:02:03.072-0700 [info]
[io.netty.handler.logging.LoggingHandler][info:101] - [id: 0x305b2780]
REGISTERED
2018-05-14T18:02:03.073-0700 [info]
[io.netty.handler.logging.LoggingHandler][info:101] - [id: 0x305b2780] BIND:
0.0.0.0/0.0.0.0:6640
2018-05-14T18:02:03.076-0700 [info]
[io.netty.handler.logging.LoggingHandler][info:101] - [id: 0x305b2780,
L:/0:0:0:0:0:0:0:0:6640] ACTIVE



Exception details:
=============

2018-05-14T18:12:21.312-0700 [debug]
[com.tool.automation.mockcontroller.ovsdb.context.transaction.Transact][sendOvsdbRequest:221]
- Sending Transaction request to the ovsdb server
2018-05-14T18:12:21.321-0700 [trace]
[org.opendaylight.ovsdb.lib.jsonrpc.JsonRpcEndpoint][lambda$getClient$1:118]
- getClient Request :
{"id":"749e050e-bc3a-4d40-a95b-4d27a603c31f","method":"transact","params":["hardware_vtep",{"op":"insert","row":{"name":"logical_switch_10003","tunnel_key":10003},"table":"Logical_Switch"}]}
java.util.concurrent.CancellationException: Task was cancelled.
at
com.google.common.util.concurrent.AbstractFuture.cancellationExceptionWithCause(AbstractFuture.java:1228)
at
com.google.common.util.concurrent.AbstractFuture.getDoneValue(AbstractFuture.java:526)
at
com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:507)
at
com.google.common.util.concurrent.AbstractFuture$TrustedFuture.get(AbstractFuture.java:85)
at
com.tool.automation.mockcontroller.ovsdb.context.transaction.Transact.sendOvsdbRequest(Transact.java:223)
at
com.tool.automation.mockcontroller.ovsdb.context.transaction.Transact.executeTransaction(Transact.java:95)
at
com.tool.automation.mockcontroller.processor.OvsdbRunner.run(OvsdbRunner.java:66)
at java.lang.Thread.run(Thread.java:745)
2018-05-14T18:12:22.327-0700 [error]
[com.tool.automation.mockcontroller.ovsdb.context.transaction.Transact][sendOvsdbRequest:226]
- Task was cancelled.
2018-0

/anil.



_______________________________________________
ovsdb-dev mailing list
ovsdb-dev@...
https://lists.opendaylight.org/mailman/listinfo/ovsdb-dev

Anil Jangam <anilj.mailing@...>

#4730

Hi Vishal,

Thanks for your reply.

To isolate the problem, I wrote a separate client program. This client program is a minimal implementation of a OVSDB client, upon connecting with the server, receives the message from the server and responds with a standard template based response to Echo, Get_Schema, Monitor, and Transact methods.

When I test with this client, it is consistently failing with the same exception (CancellationException) at 4th message (Transact). I am attaching the sample code here: https://pastebin.com/HgykUG1a

On the client side, I receive these logs:

Received data from client: {"id":"3b0f520a-3a45-4750-9532-6a2ad66ec64f","method":"echo","params":[]}

Received data from client: {"id":"249e244e-5f77-4e07-af92-cf51d90aed18","method":"get_schema","params":["hardware_vtep"]}

Received data from client: {"id":"7e85aedc-6d3b-4a82-b9b6-2f8e8f35c957","method":"monitor","params":["hardware_vtep","jsonValue",{"Physical_Locator":{"columns":["encapsulation_type
","_uuid","dst_ip"],"select":{"initial":true,"insert":true,"delete":true,"modify":true}},"Physical_Locator_Set":{"columns":["locators","_uuid"],"select":{"initial":true,"insert":tr
ue,"delete":true,"modify":true}}}]}

Received data from client: {"id":"7e04c43d-42db-448b-a67b-05dbe0744e8a","method":"transact","params":["hardware_vtep",{"op":"insert","row":{"name":"logical_switch_10003","tunnel_ke
y":10003},"table":"Logical_Switch"}]}

On server side, I receive these logs:

2018-05-24T01:56:23.148-0700 [debug] [com.tool.automation.mockcontroller.ovsdb.context.transaction.Transact][sendOvsdbRequest:221] - Sending Transaction request to the ovsdb server
2018-05-24T01:56:23.156-0700 [trace] [org.opendaylight.ovsdb.lib.jsonrpc.JsonRpcEndpoint][lambda$getClient$1:118] - getClient Request : {"id":"7e04c43d-42db-448b-a67b-05dbe0744e8a","method":"transact","params":["hardware_vtep",{"op":"insert","row":{"name":"logical_switch_10003","tunnel_key":10003},"table":"Logical_Switch"}]}
java.util.concurrent.CancellationException: Task was cancelled.
at com.google.common.util.concurrent.AbstractFuture.cancellationExceptionWithCause(AbstractFuture.java:1228)
at com.google.common.util.concurrent.AbstractFuture.getDoneValue(AbstractFuture.java:526)
at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:507)
at com.google.common.util.concurrent.AbstractFuture$TrustedFuture.get(AbstractFuture.java:85)
at com.tool.automation.mockcontroller.ovsdb.context.transaction.Transact.sendOvsdbRequest(Transact.java:223)
at com.tool.automation.mockcontroller.ovsdb.context.transaction.Transact.executeTransaction(Transact.java:95)
at com.tool.automation.mockcontroller.processor.OvsdbRunner.run(OvsdbRunner.java:66)
at java.lang.Thread.run(Thread.java:745)
2018-05-24T01:56:24.162-0700 [error] [com.tool.automation.mockcontroller.ovsdb.context.transaction.Transact][sendOvsdbRequest:226] - Task was cancelled.

/anil.

1 - 3 of 3

Previous Topic Next Topic

Home Hashtags Subgroups Terms