Operating System: All
Platform: All

The error occurs after the VTN is deleted. When VTN is deleted, VTN Manager tries to delete all the installed flows.

Looks like an issue with OpenFlow Java and switch connections. Moving to OpenFlow Java.

Can you please acquire Wireshark capture (pcap files) of network communication ?

On the first look it looks like switch didn't send barrier reply in specified timeout.

It seems to me that openflowjava cannot handle concurrent barrier requests to the same switch.

openflowjava seems to put an ongoing barrier request into AbstractConnectionAdapter.responseCache.

openflow-protocol-impl/src/main/java/.../protocol/impl/core/connection/AbstractConnectionAdapter.java:

/** expiring cache for future rpcResponses */
protected Cache<RpcResponseKey, ResponseExpectedRpcListener<?>> responseCache;

Assuming that 2 threads in a controller issue barrier requests to the same switch at the same time, the first request will be put into responseCache. But the second request will remove the first request from responseCache because RpcResponseKey class doesn't see xid field (transaction ID) in equals(Object) and hashCode().

So the first request will be passed to REMOVAL_LISTENER immediately with RemovalCause.REPLACED, and it will result in timeout error.

protected static final RemovalListener<RpcResponseKey, ResponseExpectedRpcListener<?>> REMOVAL_LISTENER = new RemovalListener<RpcResponseKey, ResponseExpectedRpcListener<?>>() {
@Override
public void onRemoval(final RemovalNotification<RpcResponseKey, ResponseExpectedRpcListener<?>> notification) {
if (!notification.getCause().equals(RemovalCause.EXPLICIT))

}
};

openflow-protocol-impl/src/main/java/.../protocol/impl/core/connection/ResponseExpectedRpcListener.java:

public void discard() {
LOG.warn("Request for {} did not receive a response", key);
failedRpc(new TimeoutException("Request timed out"));
}

I think RpcResponseKey class should see xid field in equals(Object) and hashCode() so that openflowjava can handle concurrent requests to the same switch.

Openflowjava should handle concurrent messages correctly - they are enqueued in a LinkedBlockingQueue and from this point on, messages are handled only by netty thread. So the concurrency should be no issue here.

The XID is used - you can see it in AbstractConnectionAdapter#sendToSwitchExpectRpcResultFuture() ... where RpcResponseKey key = new RpcResponseKey(input.getXid(), responseClazz.getName());

• this key is used for lookup when a barrier reply comes back.

Could you provide wireshark pcap files and logs with openflowjava set to DEBUG ?

(In reply to Michal Polkorab from comment #5)
> The XID is used - you can see it in
> AbstractConnectionAdapter#sendToSwitchExpectRpcResultFuture() ... where
> RpcResponseKey key = new RpcResponseKey(input.getXid(),
> responseClazz.getName());
> - this key is used for lookup when a barrier reply comes back.

No. RpcResponseKey sees only outputClazz in hashCode()/equals(Object) and never sees xid. So xid is never used for lookup.

RpcResponseKey.java:

@Override
public int hashCode()

@Override
public boolean equals(Object obj) {
if (this == obj)

if (obj == null)

RpcResponseKey other = (RpcResponseKey) obj;
if (outputClazz == null) {
if (other.outputClazz != null)

} else if (!outputClazz.equals(other.outputClazz))

return true;
}

For example, the below equals() returns true because RpcResponseKey.equals(Object) always ignores xid.

RpcResponseKey r1 = new RpcResponseKey(1L, "output-class");
RpcResponseKey r2 = new RpcResponseKey(2L, "output-class");
r1.equals(r2);

I could reproduce this issue with applying the following patch to openflowjava.

diff --git a/openflow-protocol-impl/src/main/java/org/opendaylight/openflowjava/protocol/impl/core/connection/AbstractConnectionAdapter.java b/openflow-protocol-impl/src/main/java/org/opendaylight/openflowjava/protocol/impl/core/connection/AbstractConnectionAdapter.java
index 57f1498..0e666c7 100644
— a/openflow-protocol-impl/src/main/java/org/opendaylight/openflowjava/protocol/impl/core/connection/AbstractConnectionAdapter.java
+++ b/openflow-protocol-impl/src/main/java/org/opendaylight/openflowjava/protocol/impl/core/connection/AbstractConnectionAdapter.java
@@ -83,6 +83,10 @@ abstract class AbstractConnectionAdapter implements ConnectionAdapter {
@Override
public void onRemoval(final RemovalNotification<RpcResponseKey, ResponseExpectedRpcListener<?>> notification) {
if (!notification.getCause().equals(RemovalCause.EXPLICIT)) {
+ if (RemovalCause.REPLACED.equals(notification.getCause())) {
+ LOG.warn("Request was replaced: key={}",
+ notification.getKey());
+ }
notification.getValue().discard();
}
}

2016-02-02 20:46:04,202 | WARN | entLoopGroup-9-3 | AbstractConnectionAdapter | 162 - org.opendaylight.openflowjava.openflow-protocol-impl - 0.7.0.SNAPSHOT | Request was replaced: key=RpcResultKey [xid=139, outputClazz=org.opendaylight.yang.gen.v1.urn.opendaylight.openflow.protocol.rev130731.BarrierOutput]
2016-02-02 20:46:04,202 | WARN | entLoopGroup-9-3 | ResponseExpectedRpcListener | 162 - org.opendaylight.openflowjava.openflow-protocol-impl - 0.7.0.SNAPSHOT | Request for RpcResultKey [xid=138, outputClazz=org.opendaylight.yang.gen.v1.urn.opendaylight.openflow.protocol.rev130731.BarrierOutput] did not receive a response
2016-02-02 20:46:04,204 | ERROR | TN Flow Thread-0 | FlowRemoveContext | 178 - org.opendaylight.vtn.manager.implementation - 0.4.0.SNAPSHOT | remove-flow: RPC returned error: errors=[RpcError [message=barrier sending failed, severity=WARNING, errorType=RPC, tag=TIMOUT, applicationTag=OPENFLOW_PLUGIN, info=switch failed to respond on barrier request, barrier.xid = 138, cause=null], RpcError [message=check switch connection, severity=ERROR, errorType=RPC, tag=OPENFLOW, applicationTag=OPENFLOW_LIBRARY, info=barrier-input sending failed, cause=java.util.concurrent.TimeoutException: Request timed out]]
java.util.concurrent.TimeoutException: Request timed out
at org.opendaylight.openflowjava.protocol.impl.core.connection.ResponseExpectedRpcListener.discard(ResponseExpectedRpcListener.java:33)[162:org.opendaylight.openflowjava.openflow-protocol-impl:0.7.0.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.core.connection.AbstractConnectionAdapter$1.onRemoval(AbstractConnectionAdapter.java:90)[162:org.opendaylight.openflowjava.openflow-protocol-impl:0.7.0.SNAPSHOT]
at com.google.common.cache.LocalCache.processPendingNotifications(LocalCache.java:1956)[54:com.google.guava:18.0.0]
at com.google.common.cache.LocalCache$Segment.runUnlockedCleanup(LocalCache.java:3460)[54:com.google.guava:18.0.0]
at com.google.common.cache.LocalCache$Segment.postWriteCleanup(LocalCache.java:3436)[54:com.google.guava:18.0.0]
at com.google.common.cache.LocalCache$Segment.put(LocalCache.java:2891)[54:com.google.guava:18.0.0]
at com.google.common.cache.LocalCache.put(LocalCache.java:4149)[54:com.google.guava:18.0.0]
at com.google.common.cache.LocalCache$LocalManualCache.put(LocalCache.java:4754)[54:com.google.guava:18.0.0]
at org.opendaylight.openflowjava.protocol.impl.core.connection.ResponseExpectedRpcListener.operationSuccessful(ResponseExpectedRpcListener.java:44)[162:org.opendaylight.openflowjava.openflow-protocol-impl:0.7.0.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.core.connection.AbstractRpcListener.operationComplete(AbstractRpcListener.java:63)[162:org.opendaylight.openflowjava.openflow-protocol-impl:0.7.0.SNAPSHOT]
at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:680)[113:io.netty.common:4.0.33.Final]
at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:567)[113:io.netty.common:4.0.33.Final]
at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:406)[113:io.netty.common:4.0.33.Final]
at io.netty.channel.DefaultChannelPromise.trySuccess(DefaultChannelPromise.java:82)[114:io.netty.transport:4.0.33.Final]
at io.netty.channel.ChannelOutboundBuffer.safeSuccess(ChannelOutboundBuffer.java:672)[114:io.netty.transport:4.0.33.Final]
at io.netty.channel.ChannelOutboundBuffer.remove(ChannelOutboundBuffer.java:262)[114:io.netty.transport:4.0.33.Final]
at io.netty.channel.ChannelOutboundBuffer.removeBytes(ChannelOutboundBuffer.java:342)[114:io.netty.transport:4.0.33.Final]
at io.netty.channel.socket.nio.NioSocketChannel.doWrite(NioSocketChannel.java:318)[114:io.netty.transport:4.0.33.Final]
at io.netty.channel.AbstractChannel$AbstractUnsafe.flush0(AbstractChannel.java:765)[114:io.netty.transport:4.0.33.Final]
at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0(AbstractNioChannel.java:311)[114:io.netty.transport:4.0.33.Final]
at io.netty.channel.AbstractChannel$AbstractUnsafe.flush(AbstractChannel.java:733)[114:io.netty.transport:4.0.33.Final]
at io.netty.channel.DefaultChannelPipeline$HeadContext.flush(DefaultChannelPipeline.java:1127)[114:io.netty.transport:4.0.33.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:673)[114:io.netty.transport:4.0.33.Final]
at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:654)[114:io.netty.transport:4.0.33.Final]
at io.netty.channel.ChannelOutboundHandlerAdapter.flush(ChannelOutboundHandlerAdapter.java:115)[114:io.netty.transport:4.0.33.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:673)[114:io.netty.transport:4.0.33.Final]
at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:654)[114:io.netty.transport:4.0.33.Final]
at io.netty.channel.DefaultChannelPipeline.flush(DefaultChannelPipeline.java:897)[114:io.netty.transport:4.0.33.Final]
at io.netty.channel.AbstractChannel.flush(AbstractChannel.java:192)[114:io.netty.transport:4.0.33.Final]
at org.opendaylight.openflowjava.protocol.impl.core.connection.ChannelOutboundQueue.flush(ChannelOutboundQueue.java:212)[162:org.opendaylight.openflowjava.openflow-protocol-impl:0.7.0.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.core.connection.ChannelOutboundQueue.access$000(ChannelOutboundQueue.java:37)[162:org.opendaylight.openflowjava.openflow-protocol-impl:0.7.0.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.core.connection.ChannelOutboundQueue$1.run(ChannelOutboundQueue.java:81)[162:org.opendaylight.openflowjava.openflow-protocol-impl:0.7.0.SNAPSHOT]
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:329)[113:io.netty.common:4.0.33.Final]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:350)[114:io.netty.transport:4.0.33.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)[113:io.netty.common:4.0.33.Final]
at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)[113:io.netty.common:4.0.33.Final]
at java.lang.Thread.run(Thread.java:745)[:1.7.0_80]
2016-02-02 20:46:04,210 | WARN | entLoopGroup-9-3 | ConnectionAdapterImpl | 162 - org.opendaylight.openflowjava.openflow-protocol-impl - 0.7.0.SNAPSHOT | received unexpected rpc response: RpcResultKey [xid=139, outputClazz=org.opendaylight.yang.gen.v1.urn.opendaylight.openflow.protocol.rev130731.BarrierOutput]
2016-02-02 20:46:04,210 | WARN | TN Flow Thread-0 | TxSyncFuture | 178 - org.opendaylight.vtn.manager.implementation - 0.4.0.SNAPSHOT | Background task for MD-SAL transaction has failed: target=org.opendaylight.vtn.manager.internal.vnode.RemoveVlanMapTask@5690af87
org.opendaylight.vtn.manager.VTNException: RPC returned error
at org.opendaylight.vtn.manager.internal.util.rpc.RpcUtils.checkResult(RpcUtils.java:189)[178:org.opendaylight.vtn.manager.implementation:0.4.0.SNAPSHOT]
at org.opendaylight.vtn.manager.internal.util.rpc.RpcInvocation.getResult(RpcInvocation.java:92)[178:org.opendaylight.vtn.manager.implementation:0.4.0.SNAPSHOT]
at org.opendaylight.vtn.manager.internal.flow.remove.FlowRemoveTask.checkResults(FlowRemoveTask.java:78)[178:org.opendaylight.vtn.manager.implementation:0.4.0.SNAPSHOT]
at org.opendaylight.vtn.manager.internal.flow.remove.FlowRemoveTask.run(FlowRemoveTask.java:114)[178:org.opendaylight.vtn.manager.implementation:0.4.0.SNAPSHOT]
at org.opendaylight.vtn.manager.internal.util.concurrent.VTNThreadPool$WorkerThread.run(VTNThreadPool.java:400)[178:org.opendaylight.vtn.manager.implementation:0.4.0.SNAPSHOT]

Attachment mininet.pcap has been added with description: Packets between connection and mininet.

I agree with your remarks now. The reason why the xid is not used is due to communication with virtual switches (OVS or Cpqd - probably Cpqd) - as the switches replied to requests with different xid-s. I thought we have already fixed this behavior - but unfortunately not. Thanks for reporting the bug.

Fix is pushed here:
https://git.opendaylight.org/gerrit/#/c/33906

Hopefully noone uses old switches today - otherwise this might cause problems in communication.

(In reply to Michal Polkorab from comment #8)
> Fix is pushed here:
> https://git.opendaylight.org/gerrit/#/c/33906

I verified the patch fixed this issue. Thanks.
Could you cherry-pick the patch to master?

Definitely, I will just wait for any failure reports. If there are none, I will also cherry-pick the change to master.

Fix for Boron: https://git.opendaylight.org/gerrit/#/c/35353/