[SOLVED] Possible bug in finalization of httpserver + logs enabled

macfly · 2020-12-17 13:57:26

Lazarus + FPC.
Cross compiled -> Win32 -> Win64.

If the logs are active, an exception occurs in fDBServers[0].Server.EndCurrentThread(Sender);

I believe this is due to fLog being seted from the first service added by TSQLHttpServer.Create, and then in Destroy he tries to use this that no longer exists.

constructor TSQLHttpServer.Create(...)..
 if high(aServers)<0 then
    fLog := TSQLLog else
    fLog := aServers[0].LogClass;

Workarround: Remove all registred services before server finalization:

  AHTTPServer.Shutdown();
  while AHTTPServer.DBServerCount > 0 do
    AHTTPServer.RemoveServer(AHTTPServer.DBServer[0]);   

FreeAndNil(AHTTPServer);

For definitive correction, should the HTTPServer Destructor perform this removal?
Or should the logs be initialized otherwise in Create?

Sample project to reprocuce:

https://pastebin.com/uZFyhHi8

Last edited by macfly (2020-12-21 13:37:26)

pvn0 · 2020-12-18 08:31:17

I was only able to reproduce with FPC. Better workaround is to declare your TSynLog.Family settings at the start of the program, or before the log is used, which is good practice.

macfly · 2020-12-18 12:48:41

Yes, it appears to be specific to the FPC.

Declaring before the same error occurs.

Declaring later avoids the error.

But in the documentation it does not mention a specific place to set the logs. Unless I haven't seen it.

In any case, I believe that removing the services in Destroy from TSQLHttpServer will not break the code and will solve the problem.

Edit: Declaring later also doesn't seem to solve it.

But I'm not sure where exactly you're referring to?

Last edited by macfly (2020-12-18 12:53:42)

pvn0 · 2020-12-18 13:15:32

sorry my bad, you're right, place of definition has no relevance, I just thought it did because it worked for me but the reason it worked is I changed options from httpApi to useHttpSocket so seems to be an issue with using http.sys.

macfly · 2020-12-19 01:34:46

I sent a pull request with the workarround to remove the DBServers on Destroy.

ab · 2020-12-19 09:19:34

Thanks for the P/R.
I will investigate further next week, when I will feel better.

macfly · 2020-12-19 13:17:14

Hi @ab,

I noticed your low frequency on the forum.
I hope you are well.

Take your time, the important thing is to take care of your health.

I wish you well.

macfly · 2020-12-19 19:31:59

Some findings:

- As pointed by pvn occurs with httpApi only.

- It is not directly related to the logs, any routine that adds a small delay to EndCurrentThread, such as a writeln will cause the error.

- Maybe it's a race condition problem.

It is difficult to debug. Because the debug itself can prevent the race condition from occurring.

pvn0 · 2020-12-20 09:30:30

@ab, hope you get to feel better soon!

mpv · 2020-12-20 16:32:20

This is a long-term problem. It not related to SynLog, but rather for HTTP.API clones termination. I tries to solve it many times w/o success.

Currently I use a modified SynCrtSock.pas where I adds a sleep(1000) in the THttpApiServer.DestroyMainThread above this line just before fClones(i).Free circle

This is not a solution but helps in most cases

P.S. wish a quick recovery for Arnauld

Last edited by mpv (2020-12-20 16:35:22)

pvn0 · 2020-12-20 16:37:52

I want to try and solve this but whenever I install fpc+laz stable (fpcupdeluxe) on windows 10 I get this mega delay while debugging with gdb (each line step is 1+ sec delay). I think I solved it once but my main dev is on Linux so I can't remember. Do you guys have this problem?

Edit : For anyone else interested, it got better by going 32bit fpc+laz instead of 64-bit, also gdb from mingw compiler chain seems to have made a bit of difference.

Last edited by pvn0 (2020-12-20 18:17:13)

pvn0 · 2020-12-20 18:10:25

Ok found the problem, @mpv you were right, the clones are destroyed without waiting for thread to terminate gracefully,

solution :

procedure THttpApiServer.DestroyMainThread; 
    ...
    for i := 0 to length(fClones)-1 do
    begin
      fClones[i].WaitFor; //<---
      fClones[i].Free;
    end;

Last edited by pvn0 (2020-12-20 18:24:02)

ab · 2020-12-21 10:55:24

It is weird because FPC TThread.Destroy calls TThread.SysDestroy which calls WaitFor.
Anyway, it won't hurt to call WaitFor.

Please check https://synopse.info/fossil/info/198cd28a4b

pvn0 · 2020-12-21 11:54:32

the commit is empty

ab · 2020-12-21 12:14:18

Sounds like if I am still a bit hill...

macfly · 2020-12-21 13:22:50

Thanks @pvn0, @mpv, @ab for the fix.

@ab GetDBServerCount Shouldn't be protected by a lock .. unlock?

function TSQLHttpServer.GetDBServerCount: integer;
begin
  result := length(fDBServers);
end;

ab · 2020-12-21 13:35:36

No, during processing, you should not add any server by definition, or only use this count value as informative.
If the user code is using it in a loop, it is really broken.

macfly · 2020-12-21 13:37:11

Ok. thanks for the info.

macfly · 2020-12-21 13:44:43

pvn0 wrote:

I want to try and solve this but whenever I install fpc+laz stable (fpcupdeluxe) on windows 10 I get this mega delay while debugging with gdb (each line step is 1+ sec delay). I think I solved it once but my main dev is on Linux so I can't remember. Do you guys have this problem?
Edit : For anyone else interested, it got better by going 32bit fpc+laz instead of 64-bit, also gdb from mingw compiler chain seems to have made a bit of difference.

Yes, I had this problem too.

Now I have the win32 version of Laz + FPC.

It gets better.
But sometimes it takes too long, seems that IDE freezes. But come back ...

ab · 2020-12-21 13:50:18

GDB + Windows is just a PITA.
Not very maintained and debugged.

I switched to Linux as my main system, using Lazarus in it, and cross-compiling to Windows.
Then Wine is not bad to run the console regression tests, or small VMs do the trick.
Lazarus debugging experience is much better on Linux, in which GDB is much more stable.
Note that the Delphi debugger experience is still better that GDB/Lazarus, even on Linux.

macfly · 2020-12-21 16:11:03

At the moment I still can't use Linux as the main OS.

With WLS2, this is on my list trying to install Ubuntu with GUI support as Windows Subsystem.

Edit:
After upgrading to WSL2, I was able to activate the graphical interface in Ubuntu, and installed FPC + Lazarus with fpcupdeluxe.

At least on my machine the performance was better than via VirtualBox.

For anyone interested:

https://docs.microsoft.com/en-us/window … tall-win10
https://dev.to/darksmile92/linux-on-win … a-rdp-522g

Last edited by macfly (2020-12-21 17:12:41)

mpv · 2020-12-21 18:44:50

Unfortunately I can't confirm HTTP.API server destruction is fixed. With latest fixes I still got

EXCOS EExternalException (c0000005) [] at   $0000000100030941  DOTERMINATE,  line 6687 of libs/Synopse/SynCrtSock.pas

So threads are destroyed before OnTerminate handlers are finished. May be this is problem in my code, but most likely @macfly just lucky with program he uses for tests. I return back a sleep(1000); hack in SyNode branch.

macfly · 2020-12-21 19:18:57

Unfortunately you are correct.

The fix worked with the test project I put in the first post (I checked again and it works).

But with the real application the same error occurs.

For now I will leave the workaround of removing the servers before finalizations of httserver.
So I don't have to modify the SynCrtSock.

 AHTTPServer.Shutdown();
  while AHTTPServer.DBServerCount > 0 do
    AHTTPServer.RemoveServer(AHTTPServer.DBServer[0]);

Last edited by macfly (2020-12-21 19:19:57)

macfly · 2020-12-21 19:43:18

Update again ...

The fix is working in my real application.

My confusion occurred because with the workarround to remove the servers I was destroying them before the httpserver.
And I forgot to change the order after applying the fix.

But destroying in the correct order, the fix resolved.

FreeAndNil(AHttpServer);
FreeAndNil(AService1);
FreeAndNil(AService2);
...

pvn0 · 2020-12-21 22:26:48

New fix :

destructor THttpApiServer.Destroy;
var endtix: Int64;
begin
  Terminate; // for Execute to be notified about end of process
  try
    if (fOwner=nil) and (Http.Module<>0) then // fOwner<>nil for cloned threads
         DestroyMainThread;    
    WaitFor;  // <----------------------- yes this guy over here
    ...
  finally
    inherited Destroy;
  end;
end;

When the HttApiServer is cloned, it inherits the onThreadTerminate event from its parent of which the origin is the TSQLHttpServer. (TSQLHttpServer.HttpThreadTerminate)
When the SQLHttpServer is shutdown, it fails to wait for the very first HttpApiServer instance to cleanup. As such there is a chance for the SQLHttpServer instance to be free'd before all the HttpApiServer instances.

Anyway I'm terrible at explaining but I hope that makes sense. It's a 1 line fix like before.

@macfly , @mpv please test it.

Last edited by pvn0 (2020-12-22 09:09:42)

macfly · 2020-12-22 00:50:37

pvn0 wrote:

Anyway I'm terrible at explaining but I hope that makes sense. It's a 1 line fix like before.

Perfectly understood.

The first fix had already worked for me, both in the test project, and in the real application.

This is also working, and it seems in fact the most logical place to put the waitfor.

I hope it also resolves for @mpv.

pvn0 · 2020-12-22 07:14:35

glad to hear that!
The problem with the first solution is that it doesn't fix the relationship between the SQLHttpServer instance and the very first instance spawn of HttpApiServer, this new fix solves that.

ab · 2020-12-22 08:20:19

@pnv0
What is weird is that THttpApiServer.Destroy calls TThread.Destroy which should indeed call WaitFor...
Also the loop waiting for fExecuting=false should do exactly the same: waiting for Execute to be actually finished.
Perhaps a weird behavior of FPC...

pvn0 · 2020-12-22 08:36:59

I agree, it also explains why Delphi has no problems.

ab · 2020-12-22 08:42:13

Anyway, I don't like to call WaitFor which waits forever.
So I changed the code to wait for a few seconds only.
Check https://synopse.info/fossil/info/2fd649e747

pvn0 · 2020-12-22 09:02:52

hmm, that's fine but I don't think it's a good idea. It's no different from using sleep then just trying to guess how much time to pass to make it safe, HttpApiServer has a hard dependency on SQLHttpServer so I do think the latter should wait for ever. Is there a guarantee that all the cleanup will be done in X seconds? I think it's better to resolve the hard dependency then.

Last edited by pvn0 (2020-12-22 09:06:26)

mpv · 2020-12-22 09:57:15

I verify a solution with WaitFor in THttpApiServer.Destroy as proposed by pvn0 (and remove all other hacks, including fClones[ i].WaitFor;) - it pass all my integration tests (~100 of HTTP server create / destroy circles).

I agree with @ab - having a timeout there is a good idea. Consider some thread is waiting for network response (forever) - in this case if we use WaitFor server never shouts down under Windows (under Linux if executed as a service OS(systemd) kills it by SIGKILL).
But 5 second is too small value - I propose to increase it to at last 30 second (for example systemd uses 90 second timeout before send SIGKILL to service what not stops).

For information - I found old thread about this problem - https://synopse.info/forum/viewtopic.php?id=3992 and even reverted MR https://github.com/synopse/mORMot/pull/42/files (waitFor in thread terminate caused a memory leak - as confirmed by Maciej Izak here https://bugs.freepascal.org/view.php?id=31987)

So my proposes are:
- Iincrease timeout to at last 30 sec
- remove fClones[ i].WaitFor (optional)
- add $ifdef FPC (seams delphi wait for thread terminate correctly)

pvn0 · 2020-12-22 10:13:40

mpv wrote:

Consider some thread is waiting for network response (forever) - in this case if we use WaitFor server never shouts down under Windows

But wouldn't you agree that's just bad practice then? Both win and linux allow you to set socket timeout.

Last edited by pvn0 (2020-12-22 11:44:38)

ab · 2020-12-22 10:27:38

Please check https://synopse.info/fossil/info/827f482d0c

mpv · 2020-12-22 11:49:42

pvn0 wrote:

mpv wrote:
Consider some thread is waiting for network response (forever) - in this case if we use WaitFor server never shouts down under Windows
But wouldn't you agree that's just bad implementation then? Both win and linux allow you to set socket timeout.

Socket is just an example. Another example - closing a database connection what have deadlock's. In real life too many types of blocking operations can be inside cleanup process - we cannot foresee everything.

Tested with https://synopse.info/fossil/info/827f482d0c commit - all my tests passed.

Now I can carefully confirm what problem is solved. Thanks to all participants!

Last edited by mpv (2020-12-22 11:50:32)

ab · 2020-12-22 11:52:33

Yes, thanks you all!

It is not the first time I have seen some minor differencies in behavior in TThread, in Delphi and FPC.
Nice seeing at least one problem seems solved!

mORMot Open Source

#1 2020-12-17 13:57:26

[SOLVED] Possible bug in finalization of httpserver + logs enabled

#2 2020-12-18 08:31:17

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#3 2020-12-18 12:48:41

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#4 2020-12-18 13:15:32

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#5 2020-12-19 01:34:46

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#6 2020-12-19 09:19:34

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#7 2020-12-19 13:17:14

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#8 2020-12-19 19:31:59

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#9 2020-12-20 09:30:30

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#10 2020-12-20 16:32:20

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#11 2020-12-20 16:37:52

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#12 2020-12-20 18:10:25

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#13 2020-12-21 10:55:24

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#14 2020-12-21 11:54:32

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#15 2020-12-21 12:14:18

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#16 2020-12-21 13:22:50

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#17 2020-12-21 13:35:36

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#18 2020-12-21 13:37:11

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#19 2020-12-21 13:44:43

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#20 2020-12-21 13:50:18

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#21 2020-12-21 16:11:03

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#22 2020-12-21 18:44:50

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#23 2020-12-21 19:18:57

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#24 2020-12-21 19:43:18

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#25 2020-12-21 22:26:48

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#26 2020-12-22 00:50:37

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#27 2020-12-22 07:14:35

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#28 2020-12-22 08:20:19

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#29 2020-12-22 08:36:59

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#30 2020-12-22 08:42:13

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#31 2020-12-22 09:02:52

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#32 2020-12-22 09:57:15

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#33 2020-12-22 10:13:40

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#34 2020-12-22 10:27:38

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#35 2020-12-22 11:49:42

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

#36 2020-12-22 11:52:33

Re: [SOLVED] Possible bug in finalization of httpserver + logs enabled

Board footer