mORMot Open Source

Milos

Member

Registered: 2021-01-04

Posts: 36

A retry happens and I don't know why

Short version: it seems as if the client always retries the request if it times out, even though Client.RetryOnceOnTimeout is set to false.

Long version:

I made a simple interface service method, which just sleeps for N seconds, for testing:

procedure TBaseAccess.Delay(const Seconds: integer);
begin
  WriteLn ('Delay has been called');
  sleep (Seconds * 1000);
end;

I call it from the client

  FClient.Service<IBaseAccess>.Delay(Seconds);

Client.RetryOnceOnTimeout is set to false and the receive timeout is shorter (3 seconds) than the amount of time specified for the delay (30 seconds)

The Delay method gets called twice and I don't understand why or how to avoid that.

Server log:

20220517 15161109  -    00.194.606
20220517 15161731  +    funServerMain.TfunRestServer(032b3080).URI POST FUNDUS/BaseAccess.Delay?session_signature=33cd9752001b21f784cd2762 in=4 B
20220517 15161731 call          funServerMain.TfunRestServer(032b3080) IBaseAccess.Delay[30]
Delay has been called
20220517 15161827 srvr          funServerMain.TfunRestServer(032b3080) IIIb  POST FUNDUS/BaseAccess.Delay Interface=200 out=13 B in 30s
20220517 15161827 ret           funServerMain.TfunRestServer(032b3080) {"result":[]}
20220517 15161827  -    30.012.093
20220517 15162131  +    funServerMain.TfunRestServer(032b3080).URI POST FUNDUS/BaseAccess.Delay?session_signature=33cd9752001b21f784cd2762 in=4 B
20220517 15162131 call          funServerMain.TfunRestServer(032b3080) IBaseAccess.Delay[30]
Delay has been called
20220517 15162227 srvr          funServerMain.TfunRestServer(032b3080) IIIb  POST FUNDUS/BaseAccess.Delay Interface=200 out=13 B in 30s
20220517 15162227 ret           funServerMain.TfunRestServer(032b3080) {"result":[]}
20220517 15162227  -    30.012.076
20220517 15164731 srvr          funServerMain.TfunRestServer(032b3080) IIIb  POST FUNDUS/BaseAccess.Delay Interface=200 out=13 B in 30s
20220517 15164731 ret           funServerMain.TfunRestServer(032b3080) {"result":[]}
20220517 15164731  -    30.004.667

Help pls?

Milos

Member

Registered: 2021-01-04

Posts: 36

Re: A retry happens and I don't know why

after some digging the retry seems triggered from within THttpClientSocket.Request.

It sends the request, time passes, SockRecvLn comes back as empty string, it then calls DoRetry(STATUS_HTTPVERSIONNONSUPPORTED,Command)

Isn't this often unwanted, what if the call is making some changes like adding a record to the database? If for whatever reason server is slowed down it would add two records and the client program would not even know that a retry happened?

Last edited by Milos (2022-05-17 15:54:46)

ab

Administrator

From: France

Registered: 2010-06-21

Posts: 14,659

Website

Re: A retry happens and I don't know why

In fact, pending := SockReceivePending(Timeout) on line 1518 should trigger the timeout, not SockRecvLn.

Or are you using mORMOt 1?

Milos

Member

Registered: 2021-01-04

Posts: 36

Re: A retry happens and I don't know why

I am using version 1.18, sorry, I should have mentioned and the code in question is in
function THttpClientSocket.Request
line 5737 unit SynCrtSock

Last edited by Milos (2022-05-17 16:08:37)

ab

Administrator

From: France

Registered: 2010-06-21

Posts: 14,659

Website

Re: A retry happens and I don't know why

In mORMot 1, a fixed timeout of 1 second is used line 5973:
  if SockReceivePending(1000)=cspSocketError then
It should have been triggered in your case, not go any further. This is weird.

Anyway, you are right: there is an inconsistency with RetryOnceOnTimeout - or at least it is confusing.
The THttpClientSocket is making the retries, whereas it is also handled at higher level, in TSQLRestClientURI, where RetryOnceOnTimeout is defined.
It is because there are TWO timeouts.
The timeout we deal here is a timeout on the server side, e.g. triggered from TSQLRestServerURIContext.ExecuteCommand. Not a timeout on the client side.

I have rewritten the documentation to make it clear.
https://synopse.info/fossil/info/0f62f18f66

Anyway, for your anxiety about some database inconsistency due to communication errors, this is not to be resolved with low-level retries or such. This is unsolvable, for several reasons.
The regular (ans easy) way is to define and use a service on server side, which will make the data access atomic, e.g. within a transaction. The mORMOt native way is to use a REST Batch.
Never send partial updates from the client, hoping everything will go right. This is a wrong pattern. Send (or prepare) all atomic updates on the server side, to be executed at once.

Milos

Member

Registered: 2021-01-04

Posts: 36

Re: A retry happens and I don't know why

hmmm but even if it stopped at SockReceivePending it would still do a retry if I am not mistaken.

Thank you for the explanation on what is going on, but, what if we consider a scenario where client scans barcodes and adds products to the basket. In case of a timeout-induced retry, it would add two items to the basket instead of one. I suppose I could include some sort of non-repeatable client request ID so that the server knows that if an ID is repeated something has gone wrong, but then that would have to be part of every similar db-modifying operation if I'd want to be safe. Seems to me it would be easier for client side to handle occasional rare timeout errors (in the case above it would just mean "refresh the basket to see whats really in there before proceding") than to worry whether a successful request was actually executed twice.

ab

Administrator

From: France

Registered: 2010-06-21

Posts: 14,659

Website

Re: A retry happens and I don't know why

No, with proper design, the scanning would take place on the client side only, maintaining a list which will be sent to the server at once with all items, when the payment is fulfilled, and the items are actually to be deduced from the stock.

IMHO your use case of a Sleep() of several seconds is wrong.
The server side process should be as fast as possible. A few ms at most.
Otherwise the HTTP thread pool may be exhausted.
For long work, see the documentation about interface callbacks.

After years of using this code with thousands of clients, I never saw such a timeout, but with a really faulty connection, which would induce a lot of problems.
The purpose of this retry is to allow a re-connection, not more.

Milos

Member

Registered: 2021-01-04

Posts: 36

Re: A retry happens and I don't know why

No, no, I used sleep only to figure out whats going on - to simulate a timeout. I don't do it in real application. In practice I did not encounter timeouts except when debugging with delphi and pausing execution which does then cause confusion when a retry fires, that is how I first noticed it.

Last edited by Milos (2022-05-17 20:01:16)

ab

Administrator

From: France

Registered: 2010-06-21

Posts: 14,659

Website

Re: A retry happens and I don't know why

Yes, debugging is tricky with the retries, that's why I usually write separated regression tests for the business logic, with no client/server involved, or I use the logs.