invokeRemoteMethodBlocking overlapped calls mix id

[Marco Vimercati]

Hi,

I found a problem using the invokeRemoteMethodBlocking and TCP connections (QJsonRpcTcpServer and client).

It seems that when two calls overlap (coming from two distinct clients), the IDs of the response are mixed:

On the client I see:

Call1, socket1   (send id 10)    (a bit long call)

after some time....

Call2, socket2   (send id 11)     (very fast call)
Response2, socket2 (receive id11)
Response1, socket1 (receive id11)

The response to call1 takes the id of the second call.

In the servers the logs show a similar situation, but responses seems sent in a different order:

Call1, socket1   (receive id 10)    (a bit long call)

after some time....

Call2, socket2   (receive id 11)     (very fast call)
Response1, socket1 (send id11)
Response2, socket2 (send id11)

Here a real logs:
On the client:

sending( QJsonRpcSocket(0x5e4520) ):  "{"id":188,"jsonrpc":"2.0","method":"ICBox.startRequest","params":[1]}"
......
sending( QJsonRpcSocket(0x5f7158) ):  "{"id":192,"jsonrpc":"2.0","method":"ICBox.keepAliveRequest"}"
received( QJsonRpcSocket(0x5f7158) ):  "{"id":192,"jsonrpc":"2.0","result":1}"
received( QJsonRpcSocket(0x5e4520) ):  "{"id":192,"jsonrpc":"2.0","result":1}"

Note that two different sockets are used, due to qtcpsocket limitation in a multithread environment.

On the server:

received( QJsonRpcSocket(0x504fb0) ):  "{"id":188,"jsonrpc":"2.0","method":"ICBox.startRequest","params":[1]}"
received( QJsonRpcSocket(0x505030) ):  "{"id":192,"jsonrpc":"2.0","method":ICBox.keepAliveRequest"}"
sending( QJsonRpcSocket(0x504fb0) ):  "{"id":192,"jsonrpc":"2.0","result":1}"
sending( QJsonRpcSocket(0x505030) ):  "{"id":192,"jsonrpc":"2.0","result":1}"

Did you have any idea?

best regards
Marco

[Marco Vimercati]

I did futher investigations:
it seems that it's not just the id mixed up, but the whole response:

{"id":192,"jsonrpc":"2.0","result":1}"

because the first call result should be "result":3, not 1.

It seems the two responses are sent as soon the second call returns, regardless
the first call is still in execution:

Call1, socket1   (receive id 10)    (a long call)

after some time....

Call2, socket2   (receive id 11)     (very fast call)

send response2 id11 on socket 1
send response2 id11 on socket 2
after some time....
Call1 end execution, no response other following.

[Matt Broadstone]

Hey Marco,

qjsonrpc was developed against a version of the spec at the time that mandated that the id be a number type, however as you can see you can easily run into duplicates with such a scheme. The current jsonrpc 2.0 spec indicates the id should be "a String, Number, or NULL value if included". I think it would be a great idea to modify QJsonRpcMessage to make id a QJsonValue (encoding rules for it being any of the aforementioned value types), and to default to a scheme where uuids are used instead of an incremental integer counter.

I suspect that would solve your problem, unfortunately I have incredibly limited time to put towards the project at the moment. If you want to put together a PR for this I would be glad to review it and provide feedback. The tests are somewhat comprehensive, so you should get support from that side as well.

Matt

 

--
You received this message because you are subscribed to the Google Groups "qjsonrpc-development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to qjsonrpc-develop...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Marco Vimercati]

HI Matt,

I'm not sure to have understood your reply, or maybe I didn't explained well the problem.

In my opinion this is a bug: two clients are performing two different rpc on the same server.

The first one is taking more time to execute than the second one, but incredibly the response of the second one

is sent to the first client too (to a wrong socket!). (When second call execution terminates... first one is still processing).

Not only the id is wrong, also the return value is sent to the wrong client.

I'm going to look at the code in order to find a potential flaw, than I came back to you (or I'll do a patch/pr).

About this, I just find the time to make the flush patch modification but playing with sourcetree I already found the

patch applied. Did you patch yourself the code or did you get some PR from me? (I'm not very familiar with source tree :)).

bye, thank you

Marco

[Matt Broadstone]

On Wed, Oct 14, 2015 at 6:01 PM, Marco Vimercati <mvime...@gmail.com> wrote:

HI Matt,

I'm not sure to have understood your reply, or maybe I didn't explained well the problem.

In my opinion this is a bug: two clients are performing two different rpc on the same server.

The first one is taking more time to execute than the second one, but incredibly the response of the second one

is sent to the first client too (to a wrong socket!). (When second call execution terminates... first one is still processing).

Not only the id is wrong, also the return value is sent to the wrong client.

I'm going to look at the code in order to find a potential flaw, than I came back to you (or I'll do a patch/pr).

About this, I just find the time to make the flush patch modification but playing with sourcetree I already found the

patch applied. Did you patch yourself the code or did you get some PR from me? (I'm not very familiar with source tree :)).

Hey Marco,

Sorry I meant to send a response but I had some time over the weekend and took a look at the code, applying a patch for flushing in the process :)

I'd have to take a look at your sample code to have a better idea of what's going on, but that definitely sounds like a bug. Could you possibly provide a code sample?

As far as what I was talking about with the ids: currently QJsonRpc handles ids for you completely, starting from a static int of 0 everywhere you link the library to, and only treats ids as integers which as you can imagine will surely lead to collisions. I started down the path this weekend converting id to just a QJsonValue and the effort was non-trivial so I put it on the backburner for the moment, but this will have to be changed in the near future I imagine. I'll see if I can find some time this weekend to at least create a branch and start the ball rolling on that.

Cheers,

Matt

[Marco Vimercati]

Hi Matt,

thank you for the patch. I did not find an equivalent patch to be applied to the http server. Maybe it's not necessary.

I'm sending you a tcpserver and tcpclient test modified in order to reproduce the problem I described before.

Running these version you should see these output, that clearly shows the problem:

Server:

received( QJsonRpcSocket(0x638af0) ):  "{"id":1,"jsonrpc":"2.0","method":"agent.testLongMethodWithParamsAndReturnValue","params":["l
ong"]}"
class QString __thiscall TestService::testLongMethodWithParamsAndReturnValue(const class QString &) called

received( QJsonRpcSocket(0x63f088) ):  "{"id":2,"jsonrpc":"2.0","method":"agent.testFastMethodWithParamsAndReturnValue","params":["f
ast"]}"
class QString __thiscall TestService::testFastMethodWithParamsAndReturnValue(const class QString &) called - return now

sending( QJsonRpcSocket(0x638af0) ):  "{"id":2,"jsonrpc":"2.0","result":"Fast fast"}"
sending( QJsonRpcSocket(0x63f088) ):  "{"id":2,"jsonrpc":"2.0","result":"Fast fast"}"
class QString __thiscall TestService::testLongMethodWithParamsAndReturnValue(const class QString &) loop done - before exit

Client:

sending( QJsonRpcSocket(0x6995e0) ):  "{"id":1,"jsonrpc":"2.0","method":"agent.testLongMethodWithParamsAndReturnValue","params":["lo
ng"]}"
sending( QJsonRpcSocket(0x699520) ):  "{"id":2,"jsonrpc":"2.0","method":"agent.testFastMethodWithParamsAndReturnValue","params":["fa
st"]}"
received( QJsonRpcSocket(0x6995e0) ):  "{"id":2,"jsonrpc":"2.0","result":"Fast fast"}"
received( QJsonRpcSocket(0x699520) ):  "{"id":2,"jsonrpc":"2.0","result":"Fast fast"}"
QJsonRpcMessage(type=QJsonRpcMessage::Response, id=2, result=QJsonValue(string, "Fast fast") )
QJsonRpcMessage(type=QJsonRpcMessage::Error, id=1, code=-32100, message="request timed out", data=QJsonValue(null) )

Thanks for your attention,

Cheers
Marco