BUG (or new feature) on SOA Calls

itSDS · 2024-02-27 13:51:45

Hi Arnaud, today i get an error calling a simple SOA function:

here a part of the log:

27.02.2024 14:36:12.224	Enter	1	 mormot.soa.client.TServiceFactoryClient(18f37450).InternalInvoke IDomBelegverwaltung.GetAlleAuftraege("",1) 1
27.02.2024 14:36:12.224	Enter	1	    mormot.rest.http.client.TRestHttpClientWinHttp(18f738a0).InternalUri POST
27.02.2024 14:36:12.256	Client	1	       mormot.rest.http.client.TRestHttpClientWinHttp(18f738a0) POST LSYS/DomBelegverwaltung.GetAlleAuftraege/1?session_signature=000d4a4f0018aa4462b2baf2 status=200 len=692979 state=5
27.02.2024 14:36:12.256	Leave	1	    00.039.894
27.02.2024 14:36:12.256	Service return	1	    mormot.soa.client.TServiceFactoryClient(18f37450) {"result":[[{State:2,Anlagedatum:"2023-09-20T10:53:14",LetzteAenderung:"2023-12-14T15:08:53",....
27.02.2024 14:36:12.256	Leave	1	 00.046.140
27.02.2024 14:37:45.976	Exception	1	 EInterfaceFactory {Message:"TInterfacedObjectFakeClient.FakeCall(IDomBelegverwaltung.GetAlleAuftraege) failed: 'Invalid returned JSON content: expects {result:...}, got {\"result~:[[{State:2,Anlagedatum:\"2023-09-20T10:53:14\",LetzteAenderung:\"2023-12-14T15:08:53

As you can see the server sends everything ok, but in last line instead of result: there is \"result~: and other Strings are also escaped.

Not every SOA Call has this behavior, may be it depends on the amount of Data received.

Last edited by itSDS (2024-02-27 14:03:50)

igors233 · 2024-02-27 15:45:45

This seems like server/client mistakes json as text and so escapes " with \.
Try to use RawJSON for your interface function result.

ab · 2024-02-27 16:36:28

Sounds like if the JSON is parsed twice on the client side, so the "result": field is already parsed as '"result'#0 in the JSON buffer.

Can you check with the debugger what happens on the client side?

itSDS · 2024-02-27 19:15:27

Hi Arnaud, i debugged the code and compared V 2.2.6792 with 2.2.7166

with 7166 the parser said - Error in File, so i compared the Log Outputs from 6792 and 7166 both Server Side and Client Side.
6792 works as expected. But in 7166 Client Log the JSON Buffer was corrupted after Byte 524288, is there a Buffer to small ? My Data has in all cases 692979 Byte !

The Client got 692979 Byte but after Byte 524288 was a copy starting at byte 262144
There Seems to be a buffer Problem in the 7166 client

ab · 2024-02-27 19:17:56

Don't look at the log, write the full body with FileFromString() as a local file and inspect it, just when it is received on the client side.

Which HTTP server class do you use?
It may be a server side output buffer problem.

itSDS · 2024-02-27 19:23:04

i use WEBSOCKETS_DEFAULT_MODE

itSDS · 2024-02-27 19:31:00

i wrote resp in File (Line 724 mormot.soa.client) and the same value as in log i described further, Log is correct.

    begin
      FileFromString(resp, 't:\resp.txt', true);
      if (JsonDecode(pointer(resp), ['result', // 0
                                     'id'      // 1

itSDS · 2024-02-27 20:03:21

I think the Problem is on the Server Side,

i digged a little Deeper
i swiched client to Socket Client and put FileFromString in mormot.net.http GetBody line 4266:

  if Http.CompressContentEncoding >= 0 then
    Http.UncompressData;
  if Assigned(OnLog) then
    OnLog(sllTrace, 'GetBody len=%', [Http.ContentLength], self);

  FileFromString(http.Content, 't:\sockresp.txt');

  if SockIn <> nil then

the received data is corrupted. In Former test i used WinHttp Client.

itSDS · 2024-02-27 20:08:24

I switched Server to useHttpApiRegisteringURI and the Request works as before. So definitelly a server problem with WEBSOCKETS_DEFAULT_MODE

itSDS · 2024-02-28 07:36:34

Question, i saw lot of DoLOG lines in the Socket Code, how can i activate it ? May be i can find the Error on the server

Last edited by itSDS (2024-02-28 07:36:44)

ab · 2024-02-28 14:25:04

I will detail here the investigation steps, which is always useful.

If we add [rsoLogVerbose] to HTTPSERVER_DEFAULT_OPTIONS then we find some additional information in the logs.
For instance, with the SOA regression tests and forcing return size of a body of 600,000 bytes with the WEBSOCKETS_DEFAULT_MODE on Windows, I was able to reproduce the problem.
The logs are the following:
https://gist.github.com/synopse/c1b5ad2 … 4b312bc548

After analysis, the new IOCP engine seems to work well when the socket output buffer is full.
It writes 256KB then subscribe for the next write/send.
But the ProcessWrite() method seems confused about the sent length... there should be a succession of GetNext(W) ProcessWrite AfterWrite PrepareNext(W) calls but here the lengths are still 262144...

There was indeed a problem when calculating the next packet to be sent.
Fixed by https://github.com/synopse/mORMot2/commit/4dcad39f

Now we can see the proper process in the logs:
https://gist.github.com/synopse/33b30e6 … f5438694a0

I have added the corresponding regression tests:
https://github.com/synopse/mORMot2/commit/0f63c680

itSDS · 2024-02-28 18:09:59

Hi Arnaud i can confirm that it works now as expected. Thank you !

itSDS · 2024-02-28 18:15:39

But one question, i set HTTPSERVER_DEBUG_OPTIONS in TRestHttpServer.Create(...
But fDebugLog in mormot.net.async - procedure TPollAsyncSockets.ProcessWrite( const notif: TPollSocketResult; sent: integer); is nil an no Debug written,
where should i set rsoLogVerbose ?

itSDS · 2024-03-01 08:53:45

Just for your information, yesterday i got corrupted packets at size 1.6MB with 7177
i checked it with latest version 7184 and it worked !

Last edited by itSDS (2024-03-01 08:54:18)

ab · 2024-03-01 13:43:26

Yes, but I have fixed this morning one last bug with IOCP - as 7185
https://github.com/synopse/mORMot2/comm … 66192791e2 - with some details in the commit description.

Seems very stable now. The LUTI integration tests are green on all systems.

I have run a 600KB response millions of times for more than 20 minutes, with no problem.

Time elapsed for all tests: 22m33
Performed 2024-03-01 11:12:41 by user1 on WIN7DEV

Total assertions failed for all test suits:  0 / 605,904,448
! All tests passed successfully.

mORMot Open Source

#1 2024-02-27 13:51:45

BUG (or new feature) on SOA Calls

#2 2024-02-27 15:45:45

Re: BUG (or new feature) on SOA Calls

#3 2024-02-27 16:36:28

Re: BUG (or new feature) on SOA Calls

#4 2024-02-27 19:15:27

Re: BUG (or new feature) on SOA Calls

#5 2024-02-27 19:17:56

Re: BUG (or new feature) on SOA Calls

#6 2024-02-27 19:23:04

Re: BUG (or new feature) on SOA Calls

#7 2024-02-27 19:31:00

Re: BUG (or new feature) on SOA Calls

#8 2024-02-27 20:03:21

Re: BUG (or new feature) on SOA Calls

#9 2024-02-27 20:08:24

Re: BUG (or new feature) on SOA Calls

#10 2024-02-28 07:36:34

Re: BUG (or new feature) on SOA Calls

#11 2024-02-28 14:25:04

Re: BUG (or new feature) on SOA Calls

#12 2024-02-28 18:09:59

Re: BUG (or new feature) on SOA Calls

#13 2024-02-28 18:15:39

Re: BUG (or new feature) on SOA Calls

#14 2024-03-01 08:53:45

Re: BUG (or new feature) on SOA Calls

#15 2024-03-01 13:43:26

Re: BUG (or new feature) on SOA Calls

Board footer