Pages: 1

#1 2015-03-16 14:41:29

ASiwon
Member
From: Poland
Registered: 2015-01-30
Posts: 82

Growing indentation of text in log files

Hello,

I found strange problem in log files which was created using TSQLLog class instances. The problem occurs only, when for called procedure an exception is raised. Here is small example:

20150316 14403761  +    TSQLRestServerDB(011F1E70).URI(POST root/BkWazeniaImport.Dodaj inlen=519)
20150316 14403761 call  	TSQLRestServerDB(011F1E70) BkWazeniaImport.Dodaj
20150316 14403761 call  	TServiceFactoryServer(0125D140) Adding BkWazeniaImport instance (id=10)
20150316 14403761  +    	TBkSerwisWazenieImport(01278CC0).Dodaj
20150316 14403761  +    		TSQLRestServerDB(011F1E70).URI(GET root inlen=522)
20150316 14403761 SQL   			TSQLDBOracleStatement(023FDE40) select WWI_ID as ID,WWI_ZDW_ID as WagaId,WWI_STANOWISKO as WagaStanowisko,WWI_GRANICA_OBC as WagonGranicaObciazenia,WWI_NR_WAGONU as WagonNumer,WWI_NR_WAGONU_BLAD as WagonNumerBlad,WWI_NR_WAGONU_FILTR as WagonNumerFiltr,WWI_NR_WAGONU_RODZ as WagonNumerRodzaj,WWI_WE_ID as WagonPobytId,WWI_TARA_Z_BEL as WagonTaraZBelki,WWI_WAGOWY as WagowyDane,WWI_WW_ID as WazenieBkId,WWI_CZAS_WAZENIA as WazenieCzas,WWI_WAZENIE_ID as WazenieIdZewnetrzne,WWI_TOWAR_NAZWA as WazenieLadunekNazwa,WWI_TOWAR_NUMER as WazenieLadunekNumer,WWI_MASA_BRUTTO as WazenieMasaBrutto,WWI_MASA_NETTO as WazenieMasaNetto,WWI_POSREDNIE as WazeniePosrednie,WWI_RODZAJ_WAZ as WazenieRodzaj,WWI_POTWIERDZ as WazenieRodzajPotwierdz,WWI_SKLAD as WazenieSklad,WWI_SKLAD_ID as WazenieSkladId,WWI_STATUS as WazenieStatus,WWI_TECHNOLOGICZNY as WazenieTechnologiczne from U_EKS.T_WAGONY_WAZENIA_IMPORTY where rownum<=1 and WWI_ZDW_ID=1 and WWI_STANOWISKO='HK1' and WWI_CZAS_WAZENIA='2015-01-02 06:55:14'
20150316 14403809 DB    			TSQLDBOracleStatement(023FDE40) 0 row(s) in 154.06ms
20150316 14403809 srvr  			TSQLRestServerDB(011F1E70)   GET root/ ORM-Get -> 200 with outlen=476 in 154191 us
20150316 14403809  -    		00.154.196
20150316 14403809 info  		Utworzono strukturę importu danych ważenia.
20150316 14403809  +    		TSQLRestServerDB(011F1E70).URI(POST root/BkWazenieImport inlen=607)
20150316 14403809 SQL   			TSQLDBOracleStatement(023FDE40) insert into U_EKS.T_WAGONY_WAZENIA_IMPORTY (WWI_ID,WWI_ZDW_ID,WWI_STANOWISKO,WWI_GRANICA_OBC,WWI_NR_WAGONU,WWI_NR_WAGONU_BLAD,WWI_NR_WAGONU_FILTR,WWI_NR_WAGONU_RODZ,WWI_WE_ID,WWI_TARA_Z_BEL,WWI_WAGOWY,WWI_WW_ID,WWI_CZAS_WAZENIA,WWI_WAZENIE_ID,WWI_TOWAR_NAZWA,WWI_TOWAR_NUMER,WWI_MASA_BRUTTO,WWI_MASA_NETTO,WWI_POSREDNIE,WWI_RODZAJ_WAZ,WWI_POTWIERDZ,WWI_SKLAD,WWI_SKLAD_ID,WWI_STATUS,WWI_TECHNOLOGICZNY) values (59721,1,'HK1',0,'82-51-5329990-4',1,'409992351528',0,0,0,'Renata Pach-Chalupka',0,'2015-01-02 06:55:14',313653,'KOKS STABIL','KOKS STABIL',55600,0,0,4,1,'680',34516,0,0)
20150316 14403809 EXC   			ESQLDBOracle {"Statement":{"SQL":"insert into U_EKS.T_WAGONY_WAZENIA_IMPORTY (WWI_ID,WWI_ZDW_ID,WWI_STANOWISKO,WWI_GRANICA_OBC,WWI_NR_WAGONU,WWI_NR_WAGONU_BLAD,WWI_NR_WAGONU_FILTR,WWI_NR_WAGONU_RODZ,WWI_WE_ID,WWI_TARA_Z_BEL,WWI_WAGOWY,WWI_WW_ID,WWI_CZAS_WAZENIA,WWI_WAZENIE_ID,WWI_TOWAR_NAZWA,WWI_TOWAR_NUMER,WWI_MASA_BRUTTO,WWI_MASA_NETTO,WWI_POSREDNIE,WWI_RODZAJ_WAZ,WWI_POTWIERDZ,WWI_SKLAD,WWI_SKLAD_ID,WWI_STATUS,WWI_TECHNOLOGICZNY) values (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)","SQLWithInlinedParams":"insert into U_EKS.T_WAGONY_WAZENIA_IMPORTY (WWI_ID,WWI_ZDW_ID,WWI_STANOWISKO,WWI_GRANICA_OBC,WWI_NR_WAGONU,WWI_NR_WAGONU_BLAD,WWI_NR_WAGONU_FILTR,WWI_NR_WAGONU_RODZ,WWI_WE_ID,WWI_TARA_Z_BEL,WWI_WAGOWY,WWI_WW_ID,WWI_CZAS_WAZENIA,WWI_WAZENIE_ID,WWI_TOWAR_NAZWA,WWI_TOWAR_NUMER,WWI_MASA_BRUTTO,WWI_MASA_NETTO,WWI_POSREDNIE,WWI_RODZAJ_WAZ,WWI_POTWIERDZ,WWI_SKLAD,WWI_SKLAD_ID,WWI_STATUS,WWI_TECHNOLOGICZNY) values (59721,1,'HK1',0,'82-51-5329990-4',1,'409992351528',0,0,0,'Renata Pach-Chalupka',0,'2015-01-02 06:55:14',313653,'KOKS STABIL','KOKS STABIL',55600,0,0,4,1,'680',34516,0,0)","CurrentRow":0,"TotalRowsRetrieved":0,"Connection":{"Connected":true,"ServerTimeStampAtConnection":"2015-03-16T14:39:49","TotalConnectionCount":1,"TransactionCount":0,"InTransaction":false,"RollbackOnDisconnect":true,"LastErrorMessage":"","LastErrorWasAboutConnection":false,"Properties":{"ClientVersion":"oci.dll rev. 11.2.0.1","EnvironmentInitializationMode":7,"InternalBufferSize":131072,"RowsPrefetchSize":131072,"BlobPrefetchSize":4096,"StatementCacheSize":30,"Engine":"Oracle","ServerName":"kolprem","DatabaseName":"","UserID":"system","DBMS":2,"DBMSEngineName":"Oracle","BatchSendingAbilities":13,"BatchMaxSentAtOnce":10000,"LoggedSQLMaxSize":0,"LogSQLStatementOnException":false,"ForcedSchemaName":"","UseCache":true,"RollbackOnDisconnect":true,"StoreVoidStringAsNull":false}}},"Message":"TSQLDBOracleStatement error: ORA-12899: wartość zbyt duża dla kolumny \"U_EKS\".\"T_WAGONY_WAZENIA_IMPORTY\".\"WWI_TOWAR_NUMER\" (obecna: 11, maksymalna: 6)"} at 00768834  stack trace API 005FFC02 5005FDB8 77B1B46B 77AD0133 00768834 0076CB8A 00753634 007513FA 00668A70 0066D57C 006A587C 0066463A 00664F70 006603D7 00679333 0246249A 024621B1 02462F05 00690AB7 00000001 00691A9D 006695FD 00669753 0066CC53 00668B8C 0066D57C 0072CD69 00722597 5016C3B9 50060BA6 
20150316 14403809 DB    			TSQLDBOracleStatement(023FDE40) 0 row(s) in 1.18ms
20150316 14403809 debug 			TSQLRestServerDB(011F1E70) {  "errorCode":400,  "errorText":"Bad Request"  }
20150316 14403809 srvr  			TSQLRestServerDB(011F1E70)   POST root/BkWazenieImport ORM-Write -> 400 with outlen=49 in 1261 us
20150316 14403809  -    		00.001.262
20150316 14403809 ERROR 		TSQLRestClientDB(023A4980) POST root/BkWazenieImport returned 400 Bad Request with message  {  "errorCode":400,  "errorText":"Bad Request"  } stack trace API 00601061 006647A9 00664F70 006603D7 00679333 0246249A 024621B1 02462F05 00690AB7 00000001 00691A9D 006695FD 00669753 0066CC53 00668B8C 0066D57C 0072CD69 00722597 5016C3B9 50060BA6 773E338A 77AF9F72 77AF9F45 
20150316 14403809 fail  		Podczas zapisu danych ważenia wystąpił błąd: 400: {  "errorCode":400,  "errorText":"Bad Request"  } stack trace API 00601129 002C292F 024624E8 024621B1 02462F05 00690AB7 00000001 00691A9D 006695FD 00669753 0066CC53 00668B8C 0066D57C 0072CD69 00722597 5016C3B9 50060BA6 773E338A 77AF9F72 77AF9F45 
20150316 14403809 EXC   		Exception ("Podczas zapisu danych ważenia wystąpił błąd: 400: {\r\n\"errorCode\":400,\r\n\"errorText\":\"Bad Request\"\r\n}") at 002C294E  stack trace 50060EFF 00724A5A 5005990B 0072CD69 00722597 00726AE8 5016C3B9 50060BA6 773E338A 77AF9F72 77AF9F45 
20150316 14403809 debug 		TSQLRestServerDB(011F1E70) {  "errorCode":500,  "error":  {"Exception":{"Exception":"Podczas zapisu danych ważenia wystąpił błąd: 400: {\r\n\"errorCode\":400,\r\n\"errorText\":\"Bad Request\"\r\n}")}  }
20150316 14403809 srvr  		TSQLRestServerDB(011F1E70)   POST root/BkWazeniaImport.Dodaj SOA-Interface -> 500 with outlen=180 in 156094 us
20150316 14403809  -    	00.156.048
20150316 14403910  +    	TSQLRestServerDB(011F1E70).URI(GET root/TimeStamp inlen=0)
20150316 14403910 call  		TSQLRestServerDB(011F1E70) TimeStamp
20150316 14403910 srvr  		TSQLRestServerDB(011F1E70)   GET root/TimeStamp SOA-Method -> 200 with outlen=12 in 30 us
20150316 14403910  -    	00.000.021
20150316 14403910  +    		TSQLRestServerDB(011F1E70).URI(GET root/Auth?UserName=User inlen=0)
20150316 14403910 call  			TSQLRestServerDB(011F1E70) Auth
20150316 14403910 debug 			TSQLRestServerDB(011F1E70) {  "errorCode":400,  "errorText":"Bad Request"  }
20150316 14403910 srvr  			TSQLRestServerDB(011F1E70)   GET root/Auth SOA-Method -> 400 with outlen=49 in 20 us
20150316 14403910  -    		00.000.018
20150316 14403910  +    	TSQLRestServerDB(011F1E70).URI(POST root/BkWazeniaImport._contract_ inlen=2)
20150316 14403910 call  		TSQLRestServerDB(011F1E70) BkWazeniaImport._contract_
20150316 14403910 srvr  		TSQLRestServerDB(011F1E70)   POST root/BkWazeniaImport._contract_ SOA-Interface -> 200 with outlen=31 in 15 us
20150316 14403910  -    	00.000.014
20150316 14403910  +    	TSQLRestServerDB(011F1E70).URI(GET root/BkWazenieZrodloDanych/1/ParametryWagi inlen=0)
20150316 14403910 SQL   		TSQLDBOracleStatement(023FDE40) select ZDW_PARAMETRY_WAGI from U_EKS.T_ZRODLA_DANYCH_WAZENIA where ZDW_ID=1
20150316 14403910 DB    		TSQLDBOracleStatement(023FDE40) 1 row(s) in 979us
20150316 14403910 srvr  		TSQLRestServerDB(011F1E70)   GET root/BkWazenieZrodloDanych ORM-Get -> 200 with outlen=104 in 1384 us
20150316 14403910  -    	00.001.385
20150316 14403915  +    	TSQLRestServerDB(011F1E70).URI(GET root/BkWazenieZrodloDanych/1/ParametryImportu inlen=0)
20150316 14403915 SQL   		TSQLDBOracleStatement(023FDE40) select ZDW_PARAMETRY_IMPORTU from U_EKS.T_ZRODLA_DANYCH_WAZENIA where ZDW_ID=1
20150316 14403915 DB    		TSQLDBOracleStatement(023FDE40) 1 row(s) in 936us
20150316 14403915 srvr  		TSQLRestServerDB(011F1E70)   GET root/BkWazenieZrodloDanych ORM-Get -> 200 with outlen=153 in 1350 us
20150316 14403915  -    	00.001.343
20150316 14403918  +    	TSQLRestServerDB(011F1E70).URI(GET root/BkWazenieZrodloDanych/1 inlen=0)
20150316 14403918 SQL   		TSQLDBOracleStatement(023FDE40) select ZDW_ID as ID,ZDW_AKTYWNY as Aktywne,ZDW_NAZWA as Nazwa,ZDW_PARAMETRY_DANE as ParametryDanych,ZDW_WGS_ID as SystemWagowy,ZDW_UBW_UBW_ID as WydzialId from U_EKS.T_ZRODLA_DANYCH_WAZENIA where ZDW_ID=1
20150316 14403918 DB    		TSQLDBOracleStatement(023FDE40) 1 row(s) in 949us
20150316 14403918 srvr  		TSQLRestServerDB(011F1E70)   GET root/BkWazenieZrodloDanych ORM-Get -> 200 with outlen=129 in 1018 us
20150316 14403918  -    	00.001.011
20150316 14403946  +    TSQLRestServerDB(011F1E70).URI(POST root/BkWazeniaImport.Dodaj inlen=519)

For the line:
20150316 14403761  +    TSQLRestServerDB(011F1E70).URI(POST root/BkWazeniaImport.Dodaj inlen=519)

- (leave event) is never? or after long time called. In my test environment there is only one client which calls procedure sequentially. So before next call should be leave event logged. After some calls indentation of the log desciptions is growing and growing. At the end of my log file it looks like:

20150316 14511900  +    																							TSQLRestServerDB(011F1E70).URI(POST root/BkWazeniaImport.Dodaj inlen=490)
20150316 14511900 call  																								TSQLRestServerDB(011F1E70) BkWazeniaImport.Dodaj
20150316 14511900 call  																								TServiceFactoryServer(0125D140) Adding BkWazeniaImport instance (id=267)
20150316 14511900  +    																								TBkSerwisWazenieImport(04E91330).Dodaj
20150316 14511900  +    																									TSQLRestServerDB(011F1E70).URI(GET root inlen=522)
20150316 14511900 SQL   																										TSQLDBOracleStatement(023FDF60) select WWI_ID as ID,WWI_ZDW_ID as WagaId,WWI_STANOWISKO as WagaStanowisko,WWI_GRANICA_OBC as WagonGranicaObciazenia,WWI_NR_WAGONU as WagonNumer,WWI_NR_WAGONU_BLAD as WagonNumerBlad,WWI_NR_WAGONU_FILTR as WagonNumerFiltr,WWI_NR_WAGONU_RODZ as WagonNumerRodzaj,WWI_WE_ID as WagonPobytId,WWI_TARA_Z_BEL as WagonTaraZBelki,WWI_WAGOWY as WagowyDane,WWI_WW_ID as WazenieBkId,WWI_CZAS_WAZENIA as WazenieCzas,WWI_WAZENIE_ID as WazenieIdZewnetrzne,WWI_TOWAR_NAZWA as WazenieLadunekNazwa,WWI_TOWAR_NUMER as WazenieLadunekNumer,WWI_MASA_BRUTTO as WazenieMasaBrutto,WWI_MASA_NETTO as WazenieMasaNetto,WWI_POSREDNIE as WazeniePosrednie,WWI_RODZAJ_WAZ as WazenieRodzaj,WWI_POTWIERDZ as WazenieRodzajPotwierdz,WWI_SKLAD as WazenieSklad,WWI_SKLAD_ID as WazenieSkladId,WWI_STATUS as WazenieStatus,WWI_TECHNOLOGICZNY as WazenieTechnologiczne from U_EKS.T_WAGONY_WAZENIA_IMPORTY where rownum<=1 and WWI_ZDW_ID=1 and WWI_STANOWISKO='HK1' and WWI_CZAS_WAZENIA='2014-10-07 03:11:30'
20150316 14511904 DB    																										TSQLDBOracleStatement(023FDF60) 1 row(s) in 65.47ms
20150316 14511904 srvr  																										TSQLRestServerDB(011F1E70)   GET root/ ORM-Get -> 200 with outlen=631 in 65586 us
20150316 14511904  -    																									00.065.591
20150316 14511904 info  																									Utworzono strukturę importu danych ważenia.
20150316 14511904 debug 																									Znaleziono rekord z zapisem danych ważenia. Identyfikator: 60080
20150316 14511904 info  																									Znaleziono rekord z zapisem danych ważenia - ścieżka aktualizacji danych ważenia.
20150316 14511904  +    																									TSQLRestServerDB(011F1E70).URI(PUT root/BkWazenieImport/60080 inlen=578)
20150316 14512110 srvr  																										TSQLRestRoutingREST(024396A0) TimeOut {"TSQLRestRoutingREST(024396A0)":{}}.Execute(execORMWrite) after 2000 ms
20150316 14512110 debug 																										TSQLRestServerDB(011F1E70) {  "errorCode":408,  "errorText":"Request Timeout"  }
20150316 14512110 srvr  																										TSQLRestServerDB(011F1E70)   PUT root/BkWazenieImport ORM-Write -> 408 with outlen=53 in 2090599 us
20150316 14512110  -    																									02.090.603
20150316 14512110 ERROR 																									TSQLRestClientDB(023A4980) PUT root/BkWazenieImport/60080 returned 408 Request Timeout with message  {  "errorCode":408,  "errorText":"Request Timeout"  } stack trace API 00601061 006647A9 006653AF 0065FFD6 006795A7 024621A5 02462F05 00690AB7 00000001 00691A9D 006695FD 00669753 0066CC53 00668B8C 0066D57C 0072CD69 00722597 5016C3B9 50060BA6 773E338A 77AF9F72 77AF9F45 
20150316 14512110 info  																									Zmieniono import ważenia o identyfikatorze: 60080
20150316 14512110 info  																									Zakończono przetwarzanie danych ważenia.
20150316 14512110 srvr  																									TSQLRestServerDB(011F1E70)   POST root/BkWazeniaImport.Dodaj SOA-Interface -> 200 with outlen=27 in 2156412 us
20150316 14512110  -    																								02.156.368
20150316 14512230  +    																									TSQLRestServerDB(011F1E70).URI(LOCK root/BkWazenieZrodloDanych/1 inlen=0)
20150316 14512230 SQL   																										TSQLDBOracleStatement(023FDF60) select ZDW_ID as ID,ZDW_AKTYWNY as Aktywne,ZDW_NAZWA as Nazwa,ZDW_PARAMETRY_DANE as ParametryDanych,ZDW_WGS_ID as SystemWagowy,ZDW_UBW_UBW_ID as WydzialId from U_EKS.T_ZRODLA_DANYCH_WAZENIA where ZDW_ID=1
20150316 14512230 DB    																										TSQLDBOracleStatement(023FDF60) 1 row(s) in 514us
20150316 14512230 srvr  																										TSQLRestServerDB(011F1E70)   LOCK root/BkWazenieZrodloDanych ORM-Get -> 200 with outlen=129 in 584 us
20150316 14512230  -    																									00.000.576
20150316 14512357  +    																								TSQLRestServerDB(011F1E70).URI(PUT root/BkWazenieZrodloDanych/1 inlen=122)
20150316 14512618 srvr  																									TSQLRestRoutingREST(02439290) TimeOut {"TSQLRestRoutingREST(02439290)":{}}.Execute(execORMWrite) after 2000 ms
20150316 14512618 debug 																									TSQLRestServerDB(011F1E70) {  "errorCode":408,  "errorText":"Request Timeout"  }
20150316 14512618 srvr  																									TSQLRestServerDB(011F1E70)   PUT root/BkWazenieZrodloDanych ORM-Write -> 408 with outlen=53 in 2405761 us
20150316 14512618  -    																								02.405.756
20150316 14512737  +    																										TSQLRestServerDB(011F1E70).URI(UNLOCK root/BkWazenieZrodloDanych/1 inlen=0)
20150316 14512737 srvr  																											TSQLRestServerDB(011F1E70)   UNLOCK root/BkWazenieZrodloDanych ORM-Get -> 200 with outlen=0 in 21 us
20150316 14512737  -    																										00.000.016
20150316 14512857  +    																								TSQLRestServerDB(011F1E70).URI(POST root/BkWazeniaImport._free_/267 inlen=2)
20150316 14512857 call  																									TSQLRestServerDB(011F1E70) BkWazeniaImport._free_
20150316 14512857  -    																								00.000.018
20150316 14512857 srvr  																								TSQLRestServerDB(011F1E70)   POST root/BkWazeniaImport._free_ SOA-Interface -> 200 with outlen=0 in 38 us
20150316 14512857  -    																							99.802.458

Is it a problem in mORMot or I'm doing something wrong?

best regards
Adam Siwon

Offline

#2 2015-03-16 21:23:57

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

Re: Growing indentation of text in log files

Which version of the source code are you using?

Offline

#3 2015-03-18 12:24:11

ASiwon
Member
From: Poland
Registered: 2015-01-30
Posts: 82

Re: Growing indentation of text in log files

Hello,

I'm using version from date 16 march 2015 09:16:18, revision 1389 from github svn repository.

After long time log file looks like: 

20150317 11551003  +    		TSQLRestServerDB(011F1E70).URI(POST root/BkWazeniaImport._free_/10118 inlen=2)
20150317 11551003 call  			TSQLRestServerDB(011F1E70) BkWazeniaImport._free_
20150317 11551003  -    		00.000.017
20150317 11551003 srvr  		TSQLRestServerDB(011F1E70)   POST root/BkWazeniaImport._free_ SOA-Interface -> 200 with outlen=0 in 38 us
20150317 11551003  -    	72.108.686
20150317 11551145  +    																																												TSQLRestServerDB(011F1E70).URI(GET root/TimeStamp inlen=0)
20150317 11551145 call  																																													TSQLRestServerDB(011F1E70) TimeStamp
20150317 11551145 srvr  																																													TSQLRestServerDB(011F1E70)   GET root/TimeStamp SOA-Method -> 200 with outlen=12 in 28 us
20150317 11551145  -    																																												00.000.020
20150317 11552719  +    																																	TSQLRestServerDB(011F1E70).URI(GET root/Auth?UserName=User inlen=0)
20150317 11552719 call  																																		TSQLRestServerDB(011F1E70) Auth
20150317 11552719 debug 																																		TSQLRestServerDB(011F1E70) {  "errorCode":400,  "errorText":"Bad Request"  }
20150317 11552719 srvr  																																		TSQLRestServerDB(011F1E70)   GET root/Auth SOA-Method -> 400 with outlen=49 in 33 us
20150317 11552719  -    																																	00.000.024
20150317 11552944  +    		TSQLRestServerDB(011F1E70).URI(POST root/BkWazeniaImport._contract_ inlen=2)
20150317 11552944 call  			TSQLRestServerDB(011F1E70) BkWazeniaImport._contract_
20150317 11552944 srvr  			TSQLRestServerDB(011F1E70)   POST root/BkWazeniaImport._contract_ SOA-Interface -> 200 with outlen=31 in 28 us
20150317 11552944  -    		00.000.020
20150317 11553213  +    						TSQLRestServerDB(011F1E70).URI(GET root/BkWazenieZrodloDanych/1/ParametryWagi inlen=0)
20150317 11553213 SQL   							TSQLDBOracleStatement(023FDF60) select ZDW_PARAMETRY_WAGI from U_EKS.T_ZRODLA_DANYCH_WAZENIA where ZDW_ID=1
20150317 11553213 DB    							TSQLDBOracleStatement(023FDF60) 1 row(s) in 569us
20150317 11553213 srvr  							TSQLRestServerDB(011F1E70)   GET root/BkWazenieZrodloDanych ORM-Get -> 200 with outlen=104 in 977 us
20150317 11553213  -    						00.000.971
20150317 11553501  +    																																																							TSQLRestServerDB(011F1E70).URI(GET root/TimeStamp inlen=0)
20150317 11553501 call  																																																								TSQLRestServerDB(011F1E70) TimeStamp
20150317 11553501 srvr  																																																								TSQLRestServerDB(011F1E70)   GET root/TimeStamp SOA-Method -> 200 with outlen=12 in 29 us
20150317 11553501  -    																																																							00.000.021
20150317 11553642  +    																																																					TSQLRestServerDB(011F1E70).URI(GET root/Auth?UserName=User inlen=0)
20150317 11553642 call  																																																						TSQLRestServerDB(011F1E70) Auth
20150317 11553642 debug 																																																						TSQLRestServerDB(011F1E70) {  "errorCode":400,  "errorText":"Bad Request"  }
20150317 11553642 srvr  																																																						TSQLRestServerDB(011F1E70)   GET root/Auth SOA-Method -> 400 with outlen=49 in 33 us
20150317 11553642  -    																																																					00.000.024
20150317 11553740  +    																	TSQLRestServerDB(011F1E70).URI(POST root/BkWazeniaImport._contract_ inlen=2)
20150317 11553740 call  																		TSQLRestServerDB(011F1E70) BkWazeniaImport._contract_
20150317 11553740 srvr  																		TSQLRestServerDB(011F1E70)   POST root/BkWazeniaImport._contract_ SOA-Interface -> 200 with outlen=31 in 27 us
20150317 11553740  -    																	00.000.020
20150317 11553806  +    																																																																		TSQLRestServerDB(011F1E70).URI(GET root/BkWazenieZrodloDanych/1/ParametryWagi inlen=0)
20150317 11553806 SQL   																																																																			TSQLDBOracleStatement(023FDF60) select ZDW_PARAMETRY_WAGI from U_EKS.T_ZRODLA_DANYCH_WAZENIA where ZDW_ID=1
20150317 11553806 DB    																																																																			TSQLDBOracleStatement(023FDF60) 1 row(s) in 623us
20150317 11553806 srvr  																																																																			TSQLRestServerDB(011F1E70)   GET root/BkWazenieZrodloDanych ORM-Get -> 200 with outlen=104 in 1029 us

So some log informations have short indentation and some informations have long indentation.
But my mORMot service is connected to the Oracle database which is used also for writing by other apps. And I have many conflicts while updating data in the database which can happens also in production version. In this cases in log file request timeouts are reported. Maybe in this case freeing of the context takes much more time than usual. Please look in the above log example: for line 20150317 11551003  -        72.108.686 - logged time is long. Maybe this is very specific environment related problem. But in all cases REST service works correctly and still response for all requests.

best regards
Adam Siwon

Offline

#4 2015-03-18 13:32:03

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

Re: Growing indentation of text in log files

Try to enable the per-thread logging.

Your log is confusing the entries from several threads.

Offline

#5 2015-03-18 15:10:48

ASiwon
Member
From: Poland
Registered: 2015-01-30
Posts: 82

Re: Growing indentation of text in log files

I have changed parameter PerThreadLog to the ptOneFilePerThread value. Now log file looks correct (there is no strange indentation) but there is still only one log file. In the name of this file is added integer value (ThreadId?) Is it necessary to set TSynLog.Family options for particular threads? To setting Family options I'm using TSQLLog class not TSynLog class. Maybe here is a problem?

best regards
Adam Siwon

Offline

#6 2015-03-18 15:35:36

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

Re: Growing indentation of text in log files

For a REST server over HTTP, the classic setting is ptIdentifiedInOnFile.

By default, the REST server uses TSQLLog class for the logging settings.
You could also use TSQLRestServer.LogClass property.

Offline

#7 2015-03-18 20:01:56

ASiwon
Member
From: Poland
Registered: 2015-01-30
Posts: 82

Re: Growing indentation of text in log files

I have change setting to ptIdentifiedInOnFile. In the log file exist now an thread identifier in every line of the log file as expected. I will send you an information if I will find any unexpected results.

best regards
Adam Siwon

Offline

#8 2015-03-19 09:24:39

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

Re: Growing indentation of text in log files

The Log Viewer tool is able to browse the log file, and identify the threads.
You can mask threads and events, so that debugging is much easier on the server side.

Offline

Pages: 1

Board footer

Powered by FluxBB