Pages: 1

#1 2014-01-20 09:13:32

DigDiver
Member
Registered: 2013-04-29
Posts: 137

BeginCurrentThread() twice and Unexpected EndCurrentThread()

I use http://synopse.info/fossil/info/9014c28bd5 version

In my application I have 4 TSQLRestServerDB and one HttpApi server


HttpServer  :=  TRootWebServer.Create(port, [WPlaceServer], '+', useHttpApi, 32, SSL);
...
 HttpServer.AddServer(FSettingsServer, nil, ssl);
 HttpServer.AddServer(FGroupServer, nil, ssl);
 HttpServer.AddServer(FBounceServer, nil, ssl);
 ...

During communication I often get an Exception:

 ECommunicationException ("BeginCurrentThread() twice") at 002E855E mORMot.TSQLRestServer.BeginCurrentThread (25553)

And when I destroy HttpServer I got ECommunicationException:

 Unexpected EndCurrentThread().

The version from 23.12.2013 does not have these problems

exception class   : ECommunicationException
exception message : Unexpected EndCurrentThread().

thread $17d8:
006e98e1 +1f1 EasyMail7Server.exe mORMot           25593 +25 TSQLRestServer.EndCurrentThread
007921e5 +03d EasyMail7Server.exe mORMotHttpServer   592  +3 TSQLHttpServer.HttpThreadTerminate
0078c384 +024 EasyMail7Server.exe SynCrtSock        2615  +2 TNotifiedThread.DoTerminate
005399d3 +083 EasyMail7Server.exe System.Classes   14576 +19 ThreadProc
0040b1b8 +028 EasyMail7Server.exe System           21627 +45 ThreadWrapper
004abe39 +00d EasyMail7Server.exe madExcept                  CallThreadProcSafe
004abe9e +032 EasyMail7Server.exe madExcept                  ThreadExceptFrame
7607495b +00c KERNEL32.DLL                                   BaseThreadInitThunk

main thread ($84c):
75948668 +000 KERNELBASE.dll                                    WaitForMultipleObjectsEx
757dadc4 +153 user32.dll                                        MsgWaitForMultipleObjectsEx
757dae24 +01a user32.dll                                        MsgWaitForMultipleObjects
0053a99f +06f EasyMail7Server.exe System.Classes     15342  +13 TThread.WaitFor
00539b81 +039 EasyMail7Server.exe System.Classes     14652   +6 TThread.Destroy
0078f37a +092 EasyMail7Server.exe SynCrtSock          4001  +10 THttpApiServer.Destroy
00409558 +008 EasyMail7Server.exe System             15046   +4 TObject.Free
00597646 +016 EasyMail7Server.exe System.Contnrs       340   +3 TObjectList.Notify
005222a4 +084 EasyMail7Server.exe System.Classes      4440  +17 TList.SetCount
00521d97 +007 EasyMail7Server.exe System.Classes      4173   +1 TList.Clear
00521d3f +00f EasyMail7Server.exe System.Classes      4157   +1 TList.Destroy
00409558 +008 EasyMail7Server.exe System             15046   +4 TObject.Free
00791d18 +02c EasyMail7Server.exe mORMotHttpServer     514   +1 TSQLHttpServer.Destroy
00409558 +008 EasyMail7Server.exe System             15046   +4 TObject.Free
00b4539e +0ce EasyMail7Server.exe DeliveryServer       580  +19 TEMServer.Destroy

sample code:


destructor TEMServer.Destroy;
var
 i : integer;
 List : TList;
begin
 List := ServerList.LockList;
 try
  for I := List.Count-1 downto 0 do
   TWPServer(List[i]).Free;
 finally
  List.Clear;
  ServerList.UnlockList;
  ServerList.Free;
 end;

 WPModel.Free;
 WPlaceServer.Free;

 HttpServer.Free;
 inherited;
end;

destructor TWPServer.Destroy;
var
 i     : integer;
 FList : TList;
begin
 SettingsModel.free;
 GroupsModel.Free;
 BouncedModel.Free;


 FSettingsServer.Free;
 FGroupServer.Free;
 FBounceServer.Free;


 FList := ConnectionList.LockList;
 try
  for i  := FList.Count-1 downto 0 do
   begin
    TSQLDBFireDACConnectionProperties(FList[i]).Free;
   end;
  finally
   ConnectionList.UnlockList;
  end;
  ConnectionList.Free;

  FList := OutboxServerList.LockList;
  try
   for i := FList.Count-1 downto 0 do
    TOutboxServer(FList[i]).free;
  finally
   OutboxServerList.UnlockList;
  end;

  OutboxServerList.Free;

  DeleteCriticalSection(ThCriticalSection);
  inherited;
end;
20140120 11525707  +    TRootWebServer(07D2FE48).003905C6 mORMotHttpServer.TSQLHttpServer.Create (420) 
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE65C0)) ThreadID=1972 ThreadCount=1
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE6640)) ThreadID=7152 ThreadCount=2
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE6740)) ThreadID=10280 ThreadCount=3
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE67C0)) ThreadID=10456 ThreadCount=4
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE6840)) ThreadID=4300 ThreadCount=5
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE66C0)) ThreadID=4496 ThreadCount=6
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE6940)) ThreadID=1936 ThreadCount=8
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE68C0)) ThreadID=11136 ThreadCount=7
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE69C0)) ThreadID=6872 ThreadCount=9
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE6A40)) ThreadID=5440 ThreadCount=10
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE6AC0)) ThreadID=11124 ThreadCount=11
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE6B40)) ThreadID=552 ThreadCount=12
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE6BC0)) ThreadID=10672 ThreadCount=13
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE6C40)) ThreadID=4612 ThreadCount=14
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE6CC0)) ThreadID=10484 ThreadCount=15
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE6D40)) ThreadID=3752 ThreadCount=16
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE6DC0)) ThreadID=11004 ThreadCount=17
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE6EC0)) ThreadID=10540 ThreadCount=18
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE6F40)) ThreadID=3336 ThreadCount=19
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE6E40)) ThreadID=4976 ThreadCount=20
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE6FC0)) ThreadID=9764 ThreadCount=21
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE7040)) ThreadID=9988 ThreadCount=22
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE70C0)) ThreadID=9188 ThreadCount=23
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE71C0)) ThreadID=10336 ThreadCount=28
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE7240)) ThreadID=9820 ThreadCount=25
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE72C0)) ThreadID=10788 ThreadCount=26
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE7340)) ThreadID=11044 ThreadCount=27
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE7140)) ThreadID=10104 ThreadCount=24
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE73C0)) ThreadID=3888 ThreadCount=29
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE7440)) ThreadID=9868 ThreadCount=30
20140120 11525707 info  	TRootWebServer(07D2FE48) THttpApiServer(06CE6540) initialized at http://localhost/wps:50888
20140120 11525707  -    00.013.357
20140120 11525707 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE74C0)) ThreadID=6104 ThreadCount=31

...

20140120 11525711  +    TRootWebServer(07D2FE48).003901E7 mORMotHttpServer.TSQLHttpServer.AddServer (350) 
20140120 11525711 debug 	result=true for Root=wp/1/settings
20140120 11525711  -    00.000.694
20140120 11525711  +    TRootWebServer(07D2FE48).003901E7 mORMotHttpServer.TSQLHttpServer.AddServer (350) 
20140120 11525711 debug 	result=true for Root=wp/1/group
20140120 11525711  -    00.000.669
20140120 11525711  +    TRootWebServer(07D2FE48).003901E7 mORMotHttpServer.TSQLHttpServer.AddServer (350) 
20140120 11525711 debug 	result=true for Root=wp/1/bounce
20140120 11525711  -    00.000.706

...

20140120 11525711  +    TRootWebServer(07D2FE48).003901E7 mORMotHttpServer.TSQLHttpServer.AddServer (350) 
20140120 11525711 debug 	result=true for Root=wp/1/settings
20140120 11525711  -    00.000.694
20140120 11525711  +    TRootWebServer(07D2FE48).003901E7 mORMotHttpServer.TSQLHttpServer.AddServer (350) 
20140120 11525711 debug 	result=true for Root=wp/1/group
20140120 11525711  -    00.000.669
20140120 11525711  +    TRootWebServer(07D2FE48).003901E7 mORMotHttpServer.TSQLHttpServer.AddServer (350) 
20140120 11525711 debug 	result=true for Root=wp/1/bounce
20140120 11525711  -    00.000.706
20140120 11525711 cache TSQLDatabase(07D3C010) not in cache
20140120 11525711 SQL   TSettingsServer(045C1090) SELECT ID,AccountType,AccountName,DisplayName,EmailAddress,ReplyEmail,ReturnEmail,Organization,DefaultSelect,Properties,AvailableSlots,MessagesPerHour,MessagesPerDay,SentInHour,StartDay,StartHour,SentInDay,HeaderFields FROM Account; is no prepared statement
20140120 11525711 res   TSQLDatabase(07D3C010) [{"ID":1,"AccountType":2,"AccountName":"G-Lock Software","DisplayName":"Julia from G-Lock Software","EmailAddress":"support@glocksoft.com","ReplyEmail":"support@glocksoft.com","ReturnEmail":"bounce@glocksoft.com","Organization":"","DefaultSelect":0,"Properties":"{\"USEPOPBefore\":false,\"POPServer\":\"\",\"POPPort\":110,\"PopLogin\":\"\",\"PopPassword\":\"\",\"SMTPServer\":\"mail.glocksoft.com\",\"SMTPPort\":25,\"USESMTPAuth\":true,\"SMTPLogin\":\"support@glocksoft.com\",\"SMTPPassword\":\"IBiUQI0a5zCE3fOq+
20140120 11525711 cache TSQLDatabase(07D3C010) not in cache
20140120 11525711 SQL   TSettingsServer(045C1090) SELECT ID,CharSet,Subject,MailTo,Attempt,Total,Processed,Sent,Excluded,Failed,Unsubscribed,Bounced,Complaint,Total_Opens,Unique_Opens,Total_Clicks,Unique_Clicks,Status,StatusMessage,CreateTime,StartTime,FinishTime,UseAnalytics,CID,CName,SendMode,TrackMethod,TrackName,Priority,ConfirmRead,AttachList,AccountList,GroupList,Deleted,Guid,MessageFormat,ResumeTime,User FROM Outbox WHERE Status=1; is no prepared statement
20140120 11525712 res   TSQLDatabase(07D3C010) {"fieldCount":38,"values":["ID","CharSet","Subject","MailTo","Attempt","Total","Processed","Sent","Excluded","Failed","Unsubscribed","Bounced","Complaint","Total_Opens","Unique_Opens","Total_Clicks","Unique_Clicks","Status","StatusMessage","CreateTime","StartTime","FinishTime","UseAnalytics","CID","CName","SendMode","TrackMethod","TrackName","Priority","ConfirmRead","AttachList","AccountList","GroupList","Deleted","Guid","MessageFormat","ResumeTime","User"],"rowCount":0} 
20140120 11525712 cache TSQLDatabase(0461AE00) not in cache
20140120 11525712 SQL   TWPManagerServer(045BD670) SELECT ID,Ident,SessionTimeout,AccessRights FROM AuthGroup WHERE Ident=:('Guest'):; prepared as SELECT ID,Ident,SessionTimeout,AccessRights FROM AuthGroup WHERE Ident=?; with 1 param
20140120 11525712 res   TSQLDatabase(0461AE00) [{"ID":4,"Ident":"Guest","SessionTimeout":60,"AccessRights":"0,1,4-256,0,0,0,0"}] 
20140120 11525712 cache TSQLDatabase(0461AE00) not in cache
20140120 11525712 SQL   TWPManagerServer(045BD670) SELECT ID,LogonName,DisplayName,PasswordHashHexa,GroupRights,Created,Email,FirstName,LastName,ValidTill,Guid FROM AuthUser; is no prepared statement
20140120 11525712 res   TSQLDatabase(0461AE00) [{"ID":1,"LogonName":"Admin","DisplayName":"Super Admin","PasswordHashHexa":"c2fc6c6adf8ba0f575a35f48df52c0968a3dcd3c577c2769dc2f1035943b975e","GroupRights":1,"Created":"2013-10-22T10:28:38","Email":"support@glocksoft.com","FirstName":"Super","LastName":"Admin","ValidTill":"2014-10-22T10:28:38","Guid":"{4791D897-6ADF-42E6-A335-4307866DDB1A}"},{"ID":3,"LogonName":"Julia","DisplayName":"Julia","PasswordHashHexa":"c2fc6c6adf8ba0f575a35f48df52c0968a3dcd3c577c2769dc2f1035943b975e","GroupRights":3,"Created":"2013
20140120 11530329 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE6540)) ThreadID=10412 ThreadCount=32
20140120 11530329 trace TSettingsServer(045C1090).BeginCurrentThread(THttpApiServer(06CE6540)) ThreadID=10412 ThreadCount=1
20140120 11530329 EXC   ECommunicationException ("BeginCurrentThread() twice") at 002E855E mORMot.TSQLRestServer.BeginCurrentThread (25553)  stack trace API 00292A18 SynCommons.SynRtlUnwind (35051) 00009790 System.@HandleOnException (18403) 
20140120 11530329  +    TWPManagerServer(045BD670).wps/TimeStamp

...

20140120 11530334  +    TSettingsServer(045C1090).wp/1/settings
20140120 11530334 auth  	TSQLRestRoutingREST(06CE75C0) Admin/TAuthSession(045937F0)
20140120 11530334 cache 	TSQLDatabase(07D3C010) not in cache
20140120 11530334 SQL   	TSettingsServer(045C1090) SELECT ID,GroupID,Name,Match,Criteria FROM Segment WHERE GroupID=:(19):; prepared as SELECT ID,GroupID,Name,Match,Criteria FROM Segment WHERE GroupID=?; with 1 param
20140120 11530334 res   	TSQLDatabase(07D3C010) {"fieldCount":5,"values":["ID","GroupID","Name","Match","Criteria"],"rowCount":0} 
20140120 11530334 srvr  	TSettingsServer(045C1090) GET  -> 200
20140120 11530334  -    00.002.085
20140120 11530334 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE6540)) ThreadID=10412 ThreadCount=33
20140120 11530334 EXC   ECommunicationException ("BeginCurrentThread() twice") at 002E855E mORMot.TSQLRestServer.BeginCurrentThread (25553)  stack trace API 00292A18 SynCommons.SynRtlUnwind (35051) 00009790 System.@HandleOnException (18403) 
20140120 11530335  +    TSettingsServer(045C1090).wp/1/settings

...

20140120 11531245 trace TWPManagerServer(045BD670).BeginCurrentThread(THttpApiServer(06CE6540)) ThreadID=10412 ThreadCount=34
20140120 11531245 EXC   ECommunicationException ("BeginCurrentThread() twice") at 002E855E mORMot.TSQLRestServer.BeginCurrentThread (25553)  stack trace API 00292A18 SynCommons.SynRtlUnwind (35051) 00009790 System.@HandleOnException (18403) 
20140120 11531247  +    TSettingsServer(045C1090).wp/1/settings/GetSentItems?MessageID=51&SQL=Select+count%28%2A%29+from+SentItems+Where+%28Status+%3D+1%29
20140120 11531247 auth  	TSQLRestRoutingREST(06CE78C0) Admin/TAuthSession(045937F0)
20140120 11531247 call  	TSettingsServer(045C1090) GetSentItems

and when destroy servers

20140120 11532529 info  TSettingsServer(045C1090) {   "ClientsCurrent": 1,   "ClientsMax": 1,   "Invalid": 2,   "Responses": 79,   "Modified": 0,   "IncomingBytes": 42566,   "OutcomingBytes": 228617,   "OutcomingFiles": 0,   "ServiceCalls": 53,   "CurrentThreadCount": 1,   "ProcessTime": "480.51ms"  }
20140120 11532529  +    00315166 SynSQLite3.TSQLDatabase.DBClose (3348) 
20140120 11532529  -    00.000.437
20140120 11532529 info  TGroupServer(0458C200) {   "ClientsCurrent": 1,   "ClientsMax": 1,   "Invalid": 1,   "Responses": 3,   "Modified": 0,   "IncomingBytes": 1640,   "OutcomingBytes": 437,   "OutcomingFiles": 0,   "ServiceCalls": 4,   "CurrentThreadCount": 0,   "ProcessTime": "5.07ms"  }
20140120 11532529  +    00315166 SynSQLite3.TSQLDatabase.DBClose (3348) 
20140120 11532529  -    00.000.112
20140120 11532529 info  TBounceServer(045A1570) {   "ClientsCurrent": 1,   "ClientsMax": 1,   "Invalid": 1,   "Responses": 3,   "Modified": 0,   "IncomingBytes": 1644,   "OutcomingBytes": 437,   "OutcomingFiles": 0,   "ServiceCalls": 4,   "CurrentThreadCount": 0,   "ProcessTime": "6.01ms"  }
20140120 11532529  +    00315166 SynSQLite3.TSQLDatabase.DBClose (3348) 
20140120 11532529  -    00.000.107
20140120 11532529 info  TWPManagerServer(045BD670) {   "ClientsCurrent": 1,   "ClientsMax": 1,   "Invalid": 0,   "Responses": 7,   "Modified": 0,   "IncomingBytes": 2943,   "OutcomingBytes": 1258,   "OutcomingFiles": 0,   "ServiceCalls": 6,   "CurrentThreadCount": 35,   "ProcessTime": "17.17ms"  }
20140120 11532529  +    00315166 SynSQLite3.TSQLDatabase.DBClose (3348) 
20140120 11532529  -    00.000.111
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE6940)) ThreadID=1936 ThreadCount=34
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE6E40)) ThreadID=4976 ThreadCount=27
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE6E40)) ThreadID=4976 ThreadCount=-1
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE6B40)) ThreadID=552 ThreadCount=31
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE6B40)) ThreadID=552 ThreadCount=-2
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE6D40)) ThreadID=3752 ThreadCount=29
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE6D40)) ThreadID=3752 ThreadCount=-3
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE6940)) ThreadID=1936 ThreadCount=0
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE68C0)) ThreadID=11136 ThreadCount=33
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE68C0)) ThreadID=11136 ThreadCount=-4
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE6F40)) ThreadID=3336 ThreadCount=25
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE6F40)) ThreadID=3336 ThreadCount=-5
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE7240)) ThreadID=9820 ThreadCount=23
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE7240)) ThreadID=9820 ThreadCount=-6
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE7340)) ThreadID=11044 ThreadCount=21
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE7340)) ThreadID=11044 ThreadCount=-7
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE6DC0)) ThreadID=11004 ThreadCount=19
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE6DC0)) ThreadID=11004 ThreadCount=-8
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE6A40)) ThreadID=5440 ThreadCount=32
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE6A40)) ThreadID=5440 ThreadCount=-9
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE6EC0)) ThreadID=10540 ThreadCount=16
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE6EC0)) ThreadID=10540 ThreadCount=-10
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE6AC0)) ThreadID=11124 ThreadCount=14
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE6AC0)) ThreadID=11124 ThreadCount=-11
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE65C0)) ThreadID=1972 ThreadCount=12
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE65C0)) ThreadID=1972 ThreadCount=-12
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE6740)) ThreadID=10280 ThreadCount=10
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE6740)) ThreadID=10280 ThreadCount=-13
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE6C40)) ThreadID=4612 ThreadCount=28
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE6C40)) ThreadID=4612 ThreadCount=-14
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE6FC0)) ThreadID=9764 ThreadCount=24
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE6FC0)) ThreadID=9764 ThreadCount=-15
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE7140)) ThreadID=10104 ThreadCount=20
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE7140)) ThreadID=10104 ThreadCount=-16
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE70C0)) ThreadID=9188 ThreadCount=17
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE70C0)) ThreadID=9188 ThreadCount=-17
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE74C0)) ThreadID=6104 ThreadCount=13
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE74C0)) ThreadID=6104 ThreadCount=-18
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE69C0)) ThreadID=6872 ThreadCount=30
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE69C0)) ThreadID=6872 ThreadCount=-19
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE72C0)) ThreadID=10788 ThreadCount=22
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE72C0)) ThreadID=10788 ThreadCount=-20
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE6640)) ThreadID=7152 ThreadCount=15
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE6640)) ThreadID=7152 ThreadCount=-21
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE6CC0)) ThreadID=10484 ThreadCount=26
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE6CC0)) ThreadID=10484 ThreadCount=-22
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE6840)) ThreadID=4300 ThreadCount=11
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE6840)) ThreadID=4300 ThreadCount=-23
20140120 11532529 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE66C0)) ThreadID=4496 ThreadCount=18
20140120 11532529 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE66C0)) ThreadID=4496 ThreadCount=-24
20140120 11532530 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE7440)) ThreadID=9868 ThreadCount=9
20140120 11532530 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE7440)) ThreadID=9868 ThreadCount=-25
20140120 11532530 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE71C0)) ThreadID=10336 ThreadCount=7
20140120 11532530 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE71C0)) ThreadID=10336 ThreadCount=-26
20140120 11532530 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE7040)) ThreadID=9988 ThreadCount=8
20140120 11532530 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE7040)) ThreadID=9988 ThreadCount=-27
20140120 11532530 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE67C0)) ThreadID=10456 ThreadCount=6
20140120 11532530 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE67C0)) ThreadID=10456 ThreadCount=-28
20140120 11532530 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE6BC0)) ThreadID=10672 ThreadCount=5
20140120 11532530 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE6BC0)) ThreadID=10672 ThreadCount=-29
20140120 11532530 trace TWPManagerServer(045BD670).EndCurrentThread(THttpApiServer(06CE73C0)) ThreadID=3888 ThreadCount=4
20140120 11532530 trace TSettingsServer(045C1090).EndCurrentThread(THttpApiServer(06CE73C0)) ThreadID=3888 ThreadCount=-30

Offline

#2 2014-01-20 13:41:48

ab
Administrator
From: France
Registered: 2010-06-21
Posts: 14,661
Website

Re: BeginCurrentThread() twice and Unexpected EndCurrentThread()

I've added some tests to validate HTTP/1.1 client-server with multiple TSQLRestServer instances..
And found just one issue in EndCurrentThread() method.

We were not able to reproduce the BeginCurrentThread() problem.

See http://synopse.info/fossil/info/93a6e4530b

Offline

#3 2014-01-20 13:53:44

DigDiver
Member
Registered: 2013-04-29
Posts: 137

Re: BeginCurrentThread() twice and Unexpected EndCurrentThread()

I will try to create a simple project to reproduce the BeginCurrentThread() problem.

P.S. if add before httpserver.free

 HttpServer.RemoveServer(FSettingsServer);
 HttpServer.RemoveServer(FGroupServer);
 HttpServer.RemoveServer(FBounceServer);

the EndCurrentThread executes without any issue.

Offline

#4 2014-01-20 16:23:35

ab
Administrator
From: France
Registered: 2010-06-21
Posts: 14,661
Website

Re: BeginCurrentThread() twice and Unexpected EndCurrentThread()

I've enhanced our regression tests, and was able to reproduce the BeginCurrentThread() problem.

Should be fixed by now.

See http://synopse.info/fossil/info/4e89caeaf5

Offline

#5 2014-01-21 06:13:46

DigDiver
Member
Registered: 2013-04-29
Posts: 137

Re: BeginCurrentThread() twice and Unexpected EndCurrentThread()

Thanks ab.

Now it works fine.

Offline

#6 2014-01-29 10:19:57

DigDiver
Member
Registered: 2013-04-29
Posts: 137

Re: BeginCurrentThread() twice and Unexpected EndCurrentThread()

When HttpServer is created it's cloned to the 32 threads to handle incoming connections.

Later I register 3 more TSQLRestServer instances to the HTTP server

HttpServer  :=  TRootWebServer.Create(port, [WPlaceServer], '+', useHttpApi, 32, SSL);
...
 HttpServer.AddServer(FSettingsServer, nil, ssl);
 HttpServer.AddServer(FGroupServer, nil, ssl);
 HttpServer.AddServer(FBounceServer, nil, ssl);
 ...

The problem is that all 32 threads process requests for one server WPlaceServer (TWPManagerServer in the log), and for processing requests for other TSQLRestServerDB instances only 1 thread is used, which is seen in the log.

20140131 12520142 info  TSettingsServer(04568000) {   "ClientsCurrent": 1,   "ClientsMax": 1,   "Invalid": 0,   "Responses": 23,   "Modified": 0,   "IncomingBytes": 12246,   "OutcomingBytes": 139805,   "OutcomingFiles": 0,   "ServiceCalls": 5,   "CurrentThreadCount": 1,   "ProcessTime": "44.68ms"  }
20140131 12520142  +    00315CBA SynSQLite3.TSQLDatabase.DBClose (3361) 
20140131 12520142  -    00.000.450
20140131 12520142 info  TGroupServer(0453F190) {   "ClientsCurrent": 1,   "ClientsMax": 1,   "Invalid": 0,   "Responses": 11,   "Modified": 0,   "IncomingBytes": 5204,   "OutcomingBytes": 9060,   "OutcomingFiles": 0,   "ServiceCalls": 3,   "CurrentThreadCount": 1,   "ProcessTime": "20.20ms"  }
20140131 12520142  +    00315CBA SynSQLite3.TSQLDatabase.DBClose (3361) 
20140131 12520142  -    00.000.208
20140131 12520142 info  TBounceServer(0452FFD0) {   "ClientsCurrent": 1,   "ClientsMax": 1,   "Invalid": 0,   "Responses": 11,   "Modified": 0,   "IncomingBytes": 5173,   "OutcomingBytes": 3417,   "OutcomingFiles": 0,   "ServiceCalls": 3,   "CurrentThreadCount": 1,   "ProcessTime": "10.70ms"  }
20140131 12520142  +    00315CBA SynSQLite3.TSQLDatabase.DBClose (3361) 
20140131 12520142  -    00.000.104
20140131 12520142 info  TWPManagerServer(045649A0) {   "ClientsCurrent": 1,   "ClientsMax": 1,   "Invalid": 0,   "Responses": 7,   "Modified": 0,   "IncomingBytes": 2943,   "OutcomingBytes": 1426,   "OutcomingFiles": 0,   "ServiceCalls": 6,   "CurrentThreadCount": 32,   "ProcessTime": "6.46ms"  }
20140131 12520142  +    00315CBA SynSQLite3.TSQLDatabase.DBClose (3361)

During an active work of the server, if the method execution takes a long time, clients get the 503 error - service unavailable.

It would be good if it was the possibility to set the number of threads to handle incoming connections when calling the HttpServer.AddServer method.

Offline

#7 2014-01-29 12:35:27

ab
Administrator
From: France
Registered: 2010-06-21
Posts: 14,661
Website

Re: BeginCurrentThread() twice and Unexpected EndCurrentThread()

Even if CurrentThreadCount is reported to equal 1, the incoming requests are processed by all threads of the thread pool.

The same THttpApiServer.fReqQueue handle is shared by all cloned threads of the HTTP server.

Offline

#8 2014-01-29 13:10:45

DigDiver
Member
Registered: 2013-04-29
Posts: 137

Re: BeginCurrentThread() twice and Unexpected EndCurrentThread()

Еhen what's the point in creating multiple threads, if all the TSQLRestServer share the same THttpApiServer.fReqQueue handler? I just thought that each server will have its own thread pool.
In my case four TSQLRestServer  servers handle different URIs:
http://host:port/wps/
http://host:port/wp/1/settings
http://host:port/wp/1/group
http://host:port/wp/1/onemore

Last edited by DigDiver (2014-01-29 13:12:09)

Offline

#9 2014-01-29 13:21:48

ab
Administrator
From: France
Registered: 2010-06-21
Posts: 14,661
Website

Re: BeginCurrentThread() twice and Unexpected EndCurrentThread()

fReqQueue is... the unique queue (!) which is unqueued by all threads of the thread pool.

Every and each URIs arr then added/registered to the queue.

IC262277.png

See http://msdn.microsoft.com/en-us/library … p/aa364667

Offline

#10 2014-01-29 13:40:40

DigDiver
Member
Registered: 2013-04-29
Posts: 137

Re: BeginCurrentThread() twice and Unexpected EndCurrentThread()

Sorry, I mean TSQLHttpServer.Request

Do I understand correctly that  mORMot works as a model 1?

http://i.imgur.com/UCj2ajd.png

Last edited by DigDiver (2014-01-29 13:43:04)

Offline

#11 2014-01-30 08:24:12

ab
Administrator
From: France
Registered: 2010-06-21
Posts: 14,661
Website

Re: BeginCurrentThread() twice and Unexpected EndCurrentThread()

DigDiver wrote:

Do I understand correctly that  mORMot works as a model 1?

Yes!

The thread pool is local to the HTTP server, not to the TSQLRestServer instances, which share the HTTP server threads.

In practice, a global thread pool does make sense.
For instance, the whole .Net framework uses an unique thread pool for its parallel library.

With mORMot, you can create another HTTP server instance, then have as many thread pool as needed.
But I do not think it is worth it.

Offline

#12 2014-01-30 10:01:05

DigDiver
Member
Registered: 2013-04-29
Posts: 137

Re: BeginCurrentThread() twice and Unexpected EndCurrentThread()

The problem is that if one TSQLRestServer (http://host:port/wp/1/settings/SomeMethod) executes the method long, other TSQLRestServer (http://host:port/wp/1/group/SomeMethod2)  can not handle at this point its methods and the client receives a 503 error

Offline

#13 2014-01-30 12:47:08

ab
Administrator
From: France
Registered: 2010-06-21
Posts: 14,661
Website

Re: BeginCurrentThread() twice and Unexpected EndCurrentThread()

DigDiver wrote:

The problem is that if one TSQLRestServer (http://host:port/wp/1/settings/SomeMethod) executes the method long, other TSQLRestServer (http://host:port/wp/1/group/SomeMethod2)  can not handle at this point its methods and the client receives a 503 error

AFAIK this is not true.

When one thread is processing http://host:port/wp/1/settings/SomeMethod
Another free thread of the thread pool will handle http://host:port/wp/1/group/SomeMethod2

Unless your method is blocked explicitly at the TSQLRestServer level.
But by default, all methods are re-entrant.
See "multi-threading" in the SAD 1.18 pdf.

Please enable per-thread logging in your applications, and check out how the requests are handled on server side.

Offline

Pages: 1

Board footer

Powered by FluxBB