Strange behaviour with prepared statements

WladiD · 2011-04-04 14:42:10

Hi Arnaud,

I think I found a bug, when prepared queries are used. Today I noticed some entries in my error log like this:

2011-04-04 15:24:45 TSQLRestServerDB.EngineExecuteAll Error: unrecognized token: ":"  UPDATE ItemFolderProperty SET ItemFolderID=0 WHERE ItemFolderID=:(8):;

This query was generated in following stack:

SQLite3.sqlite3_check(38752936,1)
SQLite3.TSQLRequest.Prepare(???,???)
SQLite3.TSQLRequest.ExecuteAll(???,???)
SQLite3.TSQLDatabase.ExecuteAll('UPDATE ItemFolderProperty SET ItemFolderID=0 WHERE ItemFolderID=:(8):; ')
SQLite3.TSQLRestServerDB.EngineExecuteAll('UPDATE ItemFolderProperty SET ItemFolderID=0 WHERE ItemFolderID=:(8):; ')
SQLite3Commons.TSQLRestServer.AfterDeleteForceCoherency(TSQLRecordItemFolder,8)
SQLite3Commons.TSQLRestServer.URI('root/ItemFolder/8','DELETE','','','',$892920)
SQLite3.TSQLRestClientDB.URI('root/ItemFolder/8','DELETE',???,???,$18FC98 {''})
SQLite3Commons.TSQLRestClientURI.Delete(TSQLRecordItemFolder,8)
LaugeIDB.TItemsDB.DeleteFolder($25CB670)

My DeleteFolder method is very simple and looks so:

procedure TItemsDB.DeleteFolder(Folder:TSQLRecordItemFolder);
begin
    GLF.LDB.RestClient.Delete(TSQLRecordItemFolder, Folder.ID);

    DoFolderDeleted(Folder);
end;

It seems, that the replace process of ':(' and '):' to '?' failed or the cache (your pool of prepared stmts) becomes invalid.

I try to localize the bug and write here some more detail.

I use your official 1.12 version.

The collaboration begins...

WladiD · 2011-04-04 15:48:08

Ok, here some odd things:

TSQLRestServerDB.EngineExecuteAll never calls TSQLRestServerDB.GetAndPrepareStatement
But TSQLRestServer.AfterDeleteForceCoherency can build a batch of prepared UPDATE queries and pass them to TSQLRestServerDB.EngineExecuteAll

I think that is it and hope you can fix it.

WladiD · 2011-04-05 07:46:54

I just pulled all files from trunk and saw, that you have already fixed this case in AfterDeleteCoherency.

It's time for 1.13

Last edited by WladiD (2011-04-05 08:00:20)

ab · 2011-04-05 18:13:20

Yes... 1.13 is coming... and has already fixed this issue.

I've just finished a new logging class, with optional full debugging information retrieval.
Objects, TList, and dynamic arrays can also be serialized as JSON in the log on request.
It could be also used to make customer-side performance profiling if needed.
See http://synopse.info/fossil/info/d65d009416

The only missing feature is remote sending of the log. But not difficult to add in the near future, if needed.

Here is some logging content sample:

D:\Dev\Lib\SQLite3\exe\TestSQL3.exe 0.0.0.0 (2011-04-05)
Host=HPENVY15 User=User CPU=8*9-6-7685 OS=6.1.7600 Wow64=1 Freq=1558710
TSQLLog 1.13 2011-04-05 23:12:00

0000000000000001 EXCOS EDivByZero (C0000094) at 004E09C2 SynSelfTests.TestsLog (811) stack trace 004E0CE2 SynSelfTests (850) 004039AF InitUnits 00403A17 @StartExe 00406543 SysInit.@InitExe 004E0FCC TestSQL3 (151) 75DD3677 771C9F02 771C9ED5 
00000000000005DC info  EDivByZero(020923C0) ^^^^^^^^ the first sample, divide by 0
0000000000000606 EXCOS EAccessViolation (C0000005) at 004E086E SynSelfTests.Proc1 (783) stack trace 004E0945 SynSelfTests.Proc2 (799) 004E08B5 SynSelfTests.Proc1 (788) 004E0945 SynSelfTests.Proc2 (799) 004E08B5 SynSelfTests.Proc1 (788) 004E0945 SynSelfTests.Proc2 (799) 004E08B5 SynSelfTests.Proc1 (788) 004E0945 SynSelfTests.Proc2 (799) 004E08B5 SynSelfTests.Proc1 (788) 004E0945 SynSelfTests.Proc2 (799) 004E08B5 SynSelfTests.Proc1 (788) 004E0A23 SynSelfTests.TestsLog (816) 004E0CE2 SynSelfTests (850) 004039AF InitUnits 00403A17 @StartExe 00406543 SysInit.@InitExe 004E0FCC TestSQL3 (151) 75DD3677 771C9F02 771C9ED5 
0000000000000648 info  EAccessViolation(02050100) ^^^^^^^^ recursion test Proc1
000000000000065C EXCOS EAccessViolation (C0000005) at 004E08FE SynSelfTests.Proc2 (794) stack trace 004E08B5 SynSelfTests.Proc1 (788) 004E0945 SynSelfTests.Proc2 (799) 004E08B5 SynSelfTests.Proc1 (788) 004E0945 SynSelfTests.Proc2 (799) 004E08B5 SynSelfTests.Proc1 (788) 004E0945 SynSelfTests.Proc2 (799) 004E08B5 SynSelfTests.Proc1 (788) 004E0945 SynSelfTests.Proc2 (799) 004E08B5 SynSelfTests.Proc1 (788) 004E0945 SynSelfTests.Proc2 (799) 004E0A34 SynSelfTests.TestsLog (817) 004E0CE2 SynSelfTests (850) 004039AF InitUnits 00403A17 @StartExe 00406543 SysInit.@InitExe 004E0FCC TestSQL3 (151) 75DD3677 771C9F02 771C9ED5 
000000000000069A info  EAccessViolation(020500E0) ^^^^^^^^ recursion test Proc2
00000000000006A7  +    TTestCompression(0208C1D0).004DD86D SynSelfTests.TTestCompression.TestLog (374) 
00000000000006A8 CUST1  004DD877 SynSelfTests.TTestCompression.TestLog (376) 
00000000000006A9 info   TestLevel=otULong
00000000000006AA info   set=(sftEnumerate,sftSet)
00000000000006AC debug  {"TSQLLog(0208A890)":{"GenericFamily":{"TSynLogFamily(0208A850)":{"Ident":0,"Level":["sllError","sllInfo","sllDebug","sllLastError","sllException","sllExceptionOS","sllEnter","sllLeave","sllMemory","sllCustom1","sllCustom2","sllCustom3","sllCustom4"],"DestinationPath":"D:\\Dev\\Lib\\SQLite3\\exe\\","BufferSize":4096,"PerThreadLog":true,"HighResolutionTimeStamp":true,"WithUnitName":false,"AutoFlushTimeOut":0,"StackTraceLevel":20}},"FileName":"D:\\Dev\\Lib\\SQLite3\\exe\\TestSQL3 Log 20110405 231200 3264.log"}}
00000000000006BF  +     TTestCompression(0208C1D0).004DD86D SynSelfTests.TTestCompression.TestLog (374) 
00000000000006BF CUST1   004DD877 SynSelfTests.TTestCompression.TestLog (376) 
00000000000006C0 info    TestLevel=otSLong
00000000000006C0 info    set=(sftEnumerate,sftFloat)
00000000000006C1 debug   {"TSQLLog(0208A890)":{"GenericFamily":{"TSynLogFamily(0208A850)":{"Ident":0,"Level":["sllError","sllInfo","sllDebug","sllLastError","sllException","sllExceptionOS","sllEnter","sllLeave","sllMemory","sllCustom1","sllCustom2","sllCustom3","sllCustom4"],"DestinationPath":"D:\\Dev\\Lib\\SQLite3\\exe\\","BufferSize":4096,"PerThreadLog":true,"HighResolutionTimeStamp":true,"WithUnitName":false,"AutoFlushTimeOut":0,"StackTraceLevel":20}},"FileName":"D:\\Dev\\Lib\\SQLite3\\exe\\TestSQL3 Log 20110405 231200 3264.log"}}
00000000000006C6  +      TTestCompression(0208C1D0).004DD86D SynSelfTests.TTestCompression.TestLog (374) 
00000000000006C7 CUST1    004DD877 SynSelfTests.TTestCompression.TestLog (376) 
00000000000006C7 info     TestLevel=otUWord
00000000000006C8 info     set=(sftEnumerate,sftFloat)
00000000000006C8 debug    {"TSQLLog(0208A890)":{"GenericFamily":{"TSynLogFamily(0208A850)":{"Ident":0,"Level":["sllError","sllInfo","sllDebug","sllLastError","sllException","sllExceptionOS","sllEnter","sllLeave","sllMemory","sllCustom1","sllCustom2","sllCustom3","sllCustom4"],"DestinationPath":"D:\\Dev\\Lib\\SQLite3\\exe\\","BufferSize":4096,"PerThreadLog":true,"HighResolutionTimeStamp":true,"WithUnitName":false,"AutoFlushTimeOut":0,"StackTraceLevel":20}},"FileName":"D:\\Dev\\Lib\\SQLite3\\exe\\TestSQL3 Log 20110405 231200 3264.log"}}
000000000000073F  +       TTestCompression(0208C1D0).004DD86D SynSelfTests.TTestCompression.TestLog (374) 
0000000000000740 CUST1     004DD877 SynSelfTests.TTestCompression.TestLog (376) 
0000000000000741 info      TestLevel=otSWord
0000000000000741 info      set=(sftEnumerate,sftFloat)
0000000000000742 debug     {"TSQLLog(0208A890)":{"GenericFamily":{"TSynLogFamily(0208A850)":{"Ident":0,"Level":["sllError","sllInfo","sllDebug","sllLastError","sllException","sllExceptionOS","sllEnter","sllLeave","sllMemory","sllCustom1","sllCustom2","sllCustom3","sllCustom4"],"DestinationPath":"D:\\Dev\\Lib\\SQLite3\\exe\\","BufferSize":4096,"PerThreadLog":true,"HighResolutionTimeStamp":true,"WithUnitName":false,"AutoFlushTimeOut":0,"StackTraceLevel":20}},"FileName":"D:\\Dev\\Lib\\SQLite3\\exe\\TestSQL3 Log 20110405 231200 3264.log"}}
0000000000000747  +        TTestCompression(0208C1D0).004DD86D SynSelfTests.TTestCompression.TestLog (374) 
0000000000000748 CUST1      004DD877 SynSelfTests.TTestCompression.TestLog (376) 
0000000000000748 info       TestLevel=otUByte
0000000000000748 info       set=(sftEnumerate,sftFloat)
0000000000000749 debug      {"TSQLLog(0208A890)":{"GenericFamily":{"TSynLogFamily(0208A850)":{"Ident":0,"Level":["sllError","sllInfo","sllDebug","sllLastError","sllException","sllExceptionOS","sllEnter","sllLeave","sllMemory","sllCustom1","sllCustom2","sllCustom3","sllCustom4"],"DestinationPath":"D:\\Dev\\Lib\\SQLite3\\exe\\","BufferSize":4096,"PerThreadLog":true,"HighResolutionTimeStamp":true,"WithUnitName":false,"AutoFlushTimeOut":0,"StackTraceLevel":20}},"FileName":"D:\\Dev\\Lib\\SQLite3\\exe\\TestSQL3 Log 20110405 231200 3264.log"}}
000000000000074E  +         TTestCompression(0208C1D0).004DD86D SynSelfTests.TTestCompression.TestLog (374) 
000000000000074E CUST1       004DD877 SynSelfTests.TTestCompression.TestLog (376) 
000000000000074F info        TestLevel=otSByte
000000000000074F info        set=(sftEnumerate,sftFloat)
000000000000074F debug       {"TSQLLog(0208A890)":{"GenericFamily":{"TSynLogFamily(0208A850)":{"Ident":0,"Level":["sllError","sllInfo","sllDebug","sllLastError","sllException","sllExceptionOS","sllEnter","sllLeave","sllMemory","sllCustom1","sllCustom2","sllCustom3","sllCustom4"],"DestinationPath":"D:\\Dev\\Lib\\SQLite3\\exe\\","BufferSize":4096,"PerThreadLog":true,"HighResolutionTimeStamp":true,"WithUnitName":false,"AutoFlushTimeOut":0,"StackTraceLevel":20}},"FileName":"D:\\Dev\\Lib\\SQLite3\\exe\\TestSQL3 Log 20110405 231200 3264.log"}}
000000000000077B EXCOS       EAccessViolation (C0000005) at 004DD8D4 SynSelfTests.TTestCompression.TestLog (381) stack trace 004E0CE2 SynSelfTests (850) 004039AF InitUnits 00403A17 @StartExe 00406543 SysInit.@InitExe 004E0FCC TestSQL3 (151) 75DD3677 771C9F02 771C9ED5 
00000000000007A1  -         TTestCompression(0208C1D0).004DD8FD SynSelfTests.TTestCompression.TestLog (383) 
00000000000007A3  -        TTestCompression(0208C1D0).004DD8FD SynSelfTests.TTestCompression.TestLog (383) 
00000000000007A4  -       TTestCompression(0208C1D0).004DD8FD SynSelfTests.TTestCompression.TestLog (383) 
00000000000007A5  -      TTestCompression(0208C1D0).004DD8FD SynSelfTests.TTestCompression.TestLog (383) 
00000000000007A6  -     TTestCompression(0208C1D0).004DD8FD SynSelfTests.TTestCompression.TestLog (383) 
00000000000007A7  -    TTestCompression(0208C1D0).004DD8FD SynSelfTests.TTestCompression.TestLog (383) 
00000000000007AA  +    004DD93D SynSelfTests.TestLogProc (389) 
00000000000007AB debug  TObjectList(02092280) GarbageCollector
00000000000007AB debug  {"TObjectList(02092280)":[{"TObjectList(02092340)":[{"TSynLogFamily(0208A850)":{"Ident":0,"Level":["sllError","sllInfo","sllDebug","sllLastError","sllException","sllExceptionOS","sllEnter","sllLeave","sllMemory","sllCustom1","sllCustom2","sllCustom3","sllCustom4"],"DestinationPath":"D:\\Dev\\Lib\\SQLite3\\exe\\","BufferSize":4096,"PerThreadLog":true,"HighResolutionTimeStamp":true,"WithUnitName":false,"AutoFlushTimeOut":0,"StackTraceLevel":20}}]},{"TObjectList(020923E0)":[{"TSQLLog(0208A890)":{"GenericFamily":{"TSynLogFamily(0208A850)":{"Ident":0,"Level":["sllError","sllInfo","sllDebug","sllLastError","sllException","sllExceptionOS","sllEnter","sllLeave","sllMemory","sllCustom1","sllCustom2","sllCustom3","sllCustom4"],"DestinationPath":"D:\\Dev\\Lib\\SQLite3\\exe\\","BufferSize":4096,"PerThreadLog":true,"HighResolutionTimeStamp":true,"WithUnitName":false,"AutoFlushTimeOut":0,"StackTraceLevel":20}},"FileName":"D:\\Dev\\Lib\\SQLite3\\exe\\TestSQL3 Log 20110405 231200 3264.log"}}]},{"TSynMapFile(0206CA60)":{}}]}
00000000000007EB  -    004DD980 SynSelfTests.TestLogProc (391) 
0000000000000E9B EXC   ECrtSocket ("Test exception 1024") at 004E0B06 SynSelfTests.TestsLog (832) stack trace 004E0CE2 SynSelfTests (850) 004039AF InitUnits 00403A17 @StartExe 00406543 SysInit.@InitExe 004E0FCC TestSQL3 (151) 75DD3677 771C9F02 771C9ED5 
0000000000000F03 info  ECrtSocket(02083520) ^^^^^^^^  custom exception type
0000000000000F21 info  ECrtSocket(02083520) ^^^^^^^^  nothing should be logged just above

Stay tuned!

WladiD · 2011-04-06 06:44:02

Wow, it sounds very interesting!

ab · 2011-04-06 13:43:52

For instance, the 910 KB TestSQL3.map file (created from a standard TestSQL3.dpr compilation) is compressed into a 69 KB TestSQL3.mab file, containing all the necessary symbols for enhanced logging information.

This TestSQL3.map file can be appended to the TestSQL3.exe, to send only one file to the customer, with no waste of space.

ab · 2011-12-12 19:07:50

About logging, see http://blog.synopse.info/?q=tsynlog

This will present the current state of TSynLog and all related features - including the log viewer.

mORMot Open Source

#1 2011-04-04 14:42:10

Strange behaviour with prepared statements

#2 2011-04-04 15:48:08

Re: Strange behaviour with prepared statements

#3 2011-04-05 07:46:54

Re: Strange behaviour with prepared statements

#4 2011-04-05 18:13:20

Re: Strange behaviour with prepared statements

#5 2011-04-06 06:44:02

Re: Strange behaviour with prepared statements

#6 2011-04-06 13:43:52

Re: Strange behaviour with prepared statements

#7 2011-12-12 19:07:50

Re: Strange behaviour with prepared statements

Board footer