Operating System: Linux
Platform: PC

Hypothesis: Apparently, ODL was assuming that it can add request to waitingRequests upon sending Pcinitiate sooner than Pcrpt handling will look for it. As log evidences, this is not always so.

My idea on how the fix could look like:

https://git.opendaylight.org/gerrit/#/c/9160/

So the logs provided point actually to the fact that the request should have been on the queue: the listener writing the 'sent to socket' message is attached to the same future the listener which moves the message. The processing happens on the same thread, so the other listener should have been invoked, too.

https://git.opendaylight.org/gerrit/9162 adds trace messages to track lifecycle of the list, please retry with that.

> please retry with that

Basically the same. Excerpts:

2014-07-21 09:18:24.295 PDT [nettyThreadgroupModule$NioEventLoopGroupCloseable-7-7]
TRACE o.o.p.pcep.impl.PCEPSessionImpl - Message sent to socket: Pcinitiate ...

2014-07-21 09:18:24.296 PDT [nettyThreadgroupModule$NioEventLoopGroupCloseable-7-7] TRACE o.o.p.p.i.PCEPByteToMessageDecoder - Received to decode: ...

2014-07-21 09:18:24.300 PDT [nettyThreadgroupModule$NioEventLoopGroupCloseable-7-7] TRACE o.o.b.p.t.p.AbstractTopologySessionListener - Removed request SrpIdNumber [_value=3] object null

2014-07-21 09:18:24.300 PDT [nettyThreadgroupModule$NioEventLoopGroupCloseable-7-7] WARN o.o.b.p.t.p.Stateful07TopologySessionListener - Request ID SrpIdNumber [_value=3] not found in outstanding DB

2014-07-21 09:18:24.320 PDT [nettyThreadgroupModule$NioEventLoopGroupCloseable-7-7] TRACE o.o.b.p.t.p.AbstractTopologySessionListener - Request SrpIdNumber [_value=3] sent to peer (object org.opendaylight.bgpcep.pcep.topology.provider.PCEPRequest@20deec50)

> the logs provided point actually to the fact that the request should have been on the queue
> The processing happens on the same thread, so the other listener should have been invoked, too.

It was invoked, just 20 milliseconds too late.

My testing reached statistical significance for me to say: It is suspicious that I have never seen this bug when testing against single PCC (others present but do nothing, maybe apart keepalives).
But, logs do not show anything interesting regarding communication on other Pcep sessions (usually handled by different threads and with long enough time differences).

Training to get Change-Id right (and without syntax errors).
https://git.opendaylight.org/gerrit/#/c/9160/

So looking at the traces, it seems that netty does not deliver the notification of the request leaving the socket first, but rather continues to process the message from the router.

Your fixes are just papering over the problem, not fixing it, simply because membership on a particular list hold the logical state of the request.

In particular, even with your fix, if the PCC closes the connection after we have pushed it, but have not received the future notification, we will inform the client of an Unsent error, where in fact it is Noack.

So what we really need to do is get netty to order the events as they occur.

> So what we really need to do is get netty to order the events as they occur.

Agreed.

> In particular, even with your fix, if the PCC closes the connection after we have pushed it, but have not received the future notification, we will inform the client of an Unsent error, where in fact it is Noack.

I would have to think more about interaction between onSessionDown and !isSuccess.
For commit b2c0fb9b66d35776f0bf4e6cea614c7c1e419d35 line 216, are we sure PCC has definitely not received the message?

> Your fixes are just papering over the problem

So it is not worth to do a quick and dirty fix for "RPC hangs" bug if that would introduce "false unsent" bug?

This bug is verified to not appear in ODL based on this build: https://jenkins.opendaylight.org/integration/view/Integration%20jobs/job/integration-master-project-centralized-integration/1741