Parameter error in 7.1.2-stable

[fhaut]

on Delphi 2009 / Windows XP, PosgreSQL 9.2 (windows xp)

using the svn://svn.code.sf.net/p/zeoslib/code-0/tags/7.1.2-stable revision 2835

a issue occurs when use parameters with same name "select * from test where ( id = :X0 or :X0 is null)"

In version 7.0.6-stable that problem nor occurs

Sample:

Code: Select all

procedure TForm1.Button1Click(Sender: TObject);
var QAux : TZQuery;
begin
   QAux := TZQuery.Create(Self);
   try
      QAux.Connection := ZConnection1;

      QAux.SQL.Text := 'drop table if exists test;';
      QAux.ExecSQL;

      // Create table
      QAux.SQL.Text := 'create table test ( id int4, name varchar(50) );';
      QAux.ExecSQL;

      // Populate data
      QAux.SQL.Text := 'select * from test';
      QAux.Open;
      QAux.Append;
      QAux.FieldByName('id').asInteger := 1;
      QAux.FieldByName('name').asString := 'nam1';
      QAux.Post;
      QAux.Append;
      QAux.FieldByName('id').asInteger := 2;
      QAux.FieldByName('name').asString := 'nam2';
      QAux.Post;
      QAux.Append;
      QAux.FieldByName('id').asInteger := 3;
      QAux.FieldByName('name').asString := 'nam3';
      QAux.Post;
      QAux.Append;
      QAux.FieldByName('id').Clear;
      QAux.FieldByName('name').asString := 'namnul';
      QAux.Post;

      // Produce problem
      QAux.SQL.Text := 'select * from test where ( id = :P0 or :P0 is null) ';
      QAux.ParamByName('P0').asInteger := 2;
      QAux.Open;
      ShowMessage( IntToStr(QAux.RecordCount) );
      QAux.Close;

   finally
     QAux.Free;
   end;
end;

Log of postgres server

Code: Select all

2013-10-09 18:00:43 BRT LOG:  duração: 20.000 ms  comando: select setting from pg_settings where name = 'bytea_output'
2013-10-09 18:00:46 BRT LOG:  duração: 10.000 ms  comando: SELECT version()
2013-10-09 18:00:46 BRT LOG:  duração: 20.000 ms  comando: drop table if exists test;

	
2013-10-09 18:00:46 BRT LOG:  duração: 10.000 ms  comando: create table test ( id int4, name varchar(50) );

	
2013-10-09 18:00:46 BRT LOG:  duração: 0.000 ms  comando: select * from test

	
2013-10-09 18:00:46 BRT LOG:  duração: 30.000 ms  comando: SELECT n.nspname,c.relname,a.attname,a.atttypid,a.attnotnull,a.atttypmod,a.attlen,a.attnum,pg_get_expr(def.adbin, def.adrelid) as adsrc,dsc.description  FROM pg_catalog.pg_namespace n  JOIN pg_catalog.pg_class c ON (c.relnamespace = n.oid)  JOIN pg_catalog.pg_attribute a ON (a.attrelid=c.oid)  LEFT JOIN pg_catalog.pg_attrdef def ON (a.attrelid=def.adrelid AND a.attnum = def.adnum) LEFT JOIN pg_catalog.pg_description dsc ON (c.oid=dsc.objoid AND a.attnum = dsc.objsubid)  LEFT JOIN pg_catalog.pg_class dc ON (dc.oid=dsc.classoid AND dc.relname='pg_class') LEFT JOIN pg_catalog.pg_namespace dn ON (dc.relnamespace=dn.oid AND dn.nspname='pg_catalog')  WHERE a.attnum > 0 AND NOT a.attisdropped AND c.relname = E'test' ORDER BY nspname,relname,attnum
2013-10-09 18:00:46 BRT LOG:  duração: 0.000 ms  comando: SELECT oid, typname, typbasetype,typtype FROM pg_type WHERE (typtype = 'b' and oid < 10000) OR typtype = 'p' OR typtype = 'e' OR typbasetype<>0 ORDER BY oid
2013-10-09 18:00:46 BRT LOG:  duração: 0.000 ms  análise de 131811589: INSERT INTO public.test (id,"name") VALUES ($1,$2)
2013-10-09 18:00:46 BRT LOG:  duração: 0.000 ms  ligação 131811589: INSERT INTO public.test (id,"name") VALUES ($1,$2)
2013-10-09 18:00:46 BRT DETALHE:  parâmetros: $1 = '1', $2 = 'nam1'
2013-10-09 18:00:46 BRT LOG:  duração: 0.000 ms  executar 131811589: INSERT INTO public.test (id,"name") VALUES ($1,$2)
2013-10-09 18:00:46 BRT DETALHE:  parâmetros: $1 = '1', $2 = 'nam1'
2013-10-09 18:00:46 BRT LOG:  duração: 0.000 ms  ligação 131811589: INSERT INTO public.test (id,"name") VALUES ($1,$2)
2013-10-09 18:00:46 BRT DETALHE:  parâmetros: $1 = '2', $2 = 'nam2'
2013-10-09 18:00:46 BRT LOG:  duração: 0.000 ms  executar 131811589: INSERT INTO public.test (id,"name") VALUES ($1,$2)
2013-10-09 18:00:46 BRT DETALHE:  parâmetros: $1 = '2', $2 = 'nam2'
2013-10-09 18:00:46 BRT LOG:  duração: 0.000 ms  ligação 131811589: INSERT INTO public.test (id,"name") VALUES ($1,$2)
2013-10-09 18:00:46 BRT DETALHE:  parâmetros: $1 = '3', $2 = 'nam3'
2013-10-09 18:00:46 BRT LOG:  duração: 0.000 ms  executar 131811589: INSERT INTO public.test (id,"name") VALUES ($1,$2)
2013-10-09 18:00:46 BRT DETALHE:  parâmetros: $1 = '3', $2 = 'nam3'
2013-10-09 18:00:46 BRT LOG:  duração: 0.000 ms  ligação 131811589: INSERT INTO public.test (id,"name") VALUES ($1,$2)
2013-10-09 18:00:46 BRT DETALHE:  parâmetros: $1 = NULL, $2 = 'namnul'
2013-10-09 18:00:46 BRT LOG:  duração: 0.000 ms  executar 131811589: INSERT INTO public.test (id,"name") VALUES ($1,$2)
2013-10-09 18:00:46 BRT DETALHE:  parâmetros: $1 = NULL, $2 = 'namnul'
2013-10-09 18:00:46 BRT LOG:  duração: 0.000 ms  comando: DEALLOCATE "131811589";
2013-10-09 18:00:46 BRT ERRO:  não pôde determinar o tipo de dado do parâmetro $2
2013-10-09 18:00:46 BRT COMANDO:  select * from test where ( id = $1 or $2 is null)
2013-10-09 18:00:46 BRT LOG:  duração: 0.000 ms  comando: select * from test where ( id = 2 or 2 is null)

Log of ZSQLMonitor

Code: Select all

2013-10-09 17:53:10 cat: Execute, proto: postgresql-9, msg: select setting from pg_settings where name = 'bytea_output'
2013-10-09 17:53:12 cat: Execute, proto: postgresql-9, msg: SELECT version()
2013-10-09 17:53:12 cat: Execute, proto: postgresql-9, msg: drop table if exists test;

2013-10-09 17:53:12 cat: Execute prepared, proto: postgresql-9, msg: Statement 1
2013-10-09 17:53:12 cat: Execute, proto: postgresql-9, msg: create table test ( id int4, name varchar(50) );

2013-10-09 17:53:12 cat: Execute prepared, proto: postgresql-9, msg: Statement 2
2013-10-09 17:53:12 cat: Execute, proto: postgresql-9, msg: select * from test

2013-10-09 17:53:12 cat: Execute prepared, proto: postgresql-9, msg: Statement 3
2013-10-09 17:53:12 cat: Execute, proto: postgresql-9, msg: SELECT n.nspname,c.relname,a.attname,a.atttypid,a.attnotnull,a.atttypmod,a.attlen,a.attnum,pg_get_expr(def.adbin, def.adrelid) as adsrc,dsc.description  FROM pg_catalog.pg_namespace n  JOIN pg_catalog.pg_class c ON (c.relnamespace = n.oid)  JOIN pg_catalog.pg_attribute a ON (a.attrelid=c.oid)  LEFT JOIN pg_catalog.pg_attrdef def ON (a.attrelid=def.adrelid AND a.attnum = def.adnum) LEFT JOIN pg_catalog.pg_description dsc ON (c.oid=dsc.objoid AND a.attnum = dsc.objsubid)  LEFT JOIN pg_catalog.pg_class dc ON (dc.oid=dsc.classoid AND dc.relname='pg_class') LEFT JOIN pg_catalog.pg_namespace dn ON (dc.relnamespace=dn.oid AND dn.nspname='pg_catalog')  WHERE a.attnum > 0 AND NOT a.attisdropped AND c.relname = E'test' ORDER BY nspname,relname,attnum
2013-10-09 17:53:12 cat: Execute, proto: postgresql-9, msg: SELECT oid, typname, typbasetype,typtype FROM pg_type WHERE (typtype = 'b' and oid < 10000) OR typtype = 'p' OR typtype = 'e' OR typbasetype<>0 ORDER BY oid
2013-10-09 17:53:12 cat: Prepare, proto: postgresql-9, msg: PREPARE 'INSERT INTO public.test (id,"name") VALUES ($1,$2)'
2013-10-09 17:53:12 cat: Execute prepared, proto: postgresql-9, msg: INSERT INTO public.test (id,"name") VALUES (?,?)
2013-10-09 17:53:12 cat: Execute prepared, proto: postgresql-9, msg: Statement 4
2013-10-09 17:53:12 cat: Execute prepared, proto: postgresql-9, msg: INSERT INTO public.test (id,"name") VALUES (?,?)
2013-10-09 17:53:12 cat: Execute prepared, proto: postgresql-9, msg: Statement 4
2013-10-09 17:53:12 cat: Execute prepared, proto: postgresql-9, msg: INSERT INTO public.test (id,"name") VALUES (?,?)
2013-10-09 17:53:12 cat: Execute prepared, proto: postgresql-9, msg: Statement 4
2013-10-09 17:53:12 cat: Execute prepared, proto: postgresql-9, msg: INSERT INTO public.test (id,"name") VALUES (?,?)
2013-10-09 17:53:12 cat: Execute prepared, proto: postgresql-9, msg: Statement 4
2013-10-09 17:53:12 cat: Unprepare prepared, proto: postgresql-9, msg: DEALLOCATE "131811589";
2013-10-09 17:53:12 cat: Prepare, proto: postgresql-9, msg: PREPARE 'select * from test where ( id = $1 or $2 is null)', errcode: 0, error: ERRO:  não pôde determinar o tipo de dado do parâmetro $2
2013-10-09 17:53:12 cat: Prepare, proto: postgresql-9, msg: PREPARE 'select * from test where ( id = $1 or $2 is null)'
2013-10-09 17:53:12 cat: Execute, proto: postgresql-9, msg: select * from test where ( id = ? or ? is null)
2013-10-09 17:53:12 cat: Execute prepared, proto: postgresql-9, msg: Statement 5

[EgonHugeist]

fhaut,

I've noticed your report in the testers thread. Hmm or me it's not logical to use two params with same name. Now you wite this was/is supported in 7.0.6. Wondering about that.. However i'll add a testcase and check the issue.

[fhaut]

@EgonHugeist

I'm migrating my application from 7.0.6 to 7.1.2 and only this issue break the release.

Another example of log TZSQLMonitor in english

Code: Select all

2013-10-16 16:28:55 cat: Prepare, proto: postgresql-8, msg: PREPARE 'select * from table1 where codemp = $1 and codfil = $2 and numcha = $3 and codimp = $4 and codnat = $5 and numite = $6 and aliimp = $7 and (codcst = $8 or $9 is null)', errcode: 0, error: ERROR:  could not determine data type of parameter $9
2013-10-16 16:28:55 cat: Prepare, proto: postgresql-8, msg: PREPARE 'select * from table1 where codemp = $1 and codfil = $2 and numcha = $3 and codimp = $4 and codnat = $5 and numite = $6 and aliimp = $7 and (codcst = $8 or $9 is null)'
2013-10-16 16:28:55 cat: Execute, proto: postgresql-8, msg: select * from table1 where codemp = ? and codfil = ? and numcha = ? and codimp = ? and codnat = ? and numite = ? and aliimp = ? and (codcst = ? or ? is null), errcode: 0, error: ERROR:  current transaction is aborted, commands ignored until end of transaction block
2013-10-16 16:28:55 cat: Unprepare prepared, proto: postgresql-8, msg: DEALLOCATE "186393616";, errcode: 0, error: ERROR:  current transaction is aborted, commands ignored until end of transaction block
2013-10-16 16:28:55 cat: Execute, proto: postgresql-8, msg:  ROLLBACK

now a feature request, in the 7.1.2 version the parameter value are not visible, this make more dificult do debug de application, have a way to print it in the log ?

Code: Select all

QAux.SQL.Text := 'select * from test01 where id = :X1 or :X2';
QAux.ParamByName('X1').asInteger = 65;
QAux.ParamByName('X2').asInteger = 11;

LOG sample in 7.0.6:

Code: Select all

   select * from test01 where id = 65 or id = 11

LOG sample in 7.1.2

Code: Select all

   select * from test01 where id = ? or id = ?

where would like

Code: Select all

   select * from test01 where id = :X1 or id = :X2
      param X1, integer=>65
      param X2, integer=>11

where the sintax of printed data is
param = literal
X1 = name of parameter
, = separator
integer = type of data (string, tdatetime, boolean)
=> separator
65 = value(blob parameters are not displayed)

[mdaems]

Michael,

I think using the same parameter name twice is quite a normal thing to do. Maybe we forgot about that when the CAPI was implemented. But... a fix we really need.

Concerning the log : a record should w printed at execute time, containing all values that are bound. Have a look at the firebird implementation I wrote for that purpose.
(For speed we should consider how we can disable logging when no log listeners are listening)

Mark

[mdaems]

Update.

Adding a test for using a parameter twice doesn't give failures. That works as expected.

Looking deeper it seems like we have the (known) problem that the server can't decide on the datatype of a parameter because of the way it's used. Comparing a constant to null is possible, but it's impossible for the server to decide what datatype it should use when preparing the query. I think we implemented some trick to catch this error by marking the query as unpreparable and use the old behaviour in that case. But that doesn't seem to work here.

Mark

[mdaems]

The test case I prepared. Fails for postgres , but seems to work for FB, SQLite and mysql.

Code: Select all

{**
  Bugs report UseParamTwice.

  Queries using twice the same parameter should not fail
}
procedure ZTestCompCoreBugReport.TestUseUnpreparableParam;
var
  Query: TZQuery;
begin
  if SkipForReason(srClosedBug) then Exit;

  Query := CreateQuery;
  try
    Query.CachedUpdates := False;

    { Remove previously created record }
    Query.SQL.Text := 'DELETE FROM people WHERE p_id>=:id';
    Query.ParamByName('id').AsInteger := TEST_ROW_ID - 1;
    Query.ExecSQL;

    Query.SQL.Text := 'INSERT INTO people (p_id) VALUES (:id)';
    Query.ParamByName('id').AsInteger := TEST_ROW_ID - 1;
    Query.ExecSQL;
    Query.ParamByName('id').AsInteger := TEST_ROW_ID;
    Query.ExecSQL;

    { Opens a result set. }
    Query.SQL.Text := 'SELECT * FROM people WHERE p_id>=:id or :id IS NULL ORDER BY p_id';
    Query.ParamByName('id').AsInteger := TEST_ROW_ID - 1;
    Query.Open;
    CheckEquals(TEST_ROW_ID - 1, Query.FieldByName('p_id').AsInteger);
    Query.Next;
    CheckEquals(TEST_ROW_ID, Query.FieldByName('p_id').AsInteger);
    Query.Close;
    Query.ParamByName('id').Value := null;
    Query.Open;
    CheckEquals(TRUE, Query.RecordCount>2);
    { Remove newly created record }
    Query.SQL.Text := 'DELETE FROM people WHERE p_id>=:id';
    Query.ParamByName('id').AsInteger := TEST_ROW_ID - 1;
    Query.ExecSQL;
  finally
    Query.Free;
  end;
end;

Log for mysql with real preparation :

[ 5773] cat: Prepare, proto: mysql-5, msg: Statement 2174 : DELETE FROM people WHERE p_id>=?
[ 5774] cat: Bind prepared, proto: mysql-5, msg: Statement 2174 : 32766,
[ 5775] cat: Execute prepared, proto: mysql-5, msg: Statement 2174
[ 5776] cat: Prepare, proto: mysql-5, msg: Statement 2175 : INSERT INTO people (p_id) VALUES (?)
[ 5777] cat: Bind prepared, proto: mysql-5, msg: Statement 2175 : 32766,
[ 5778] cat: Execute prepared, proto: mysql-5, msg: Statement 2175
[ 5779] cat: Bind prepared, proto: mysql-5, msg: Statement 2175 : 32767,
[ 5780] cat: Execute prepared, proto: mysql-5, msg: Statement 2175
[ 5781] cat: Prepare, proto: mysql-5, msg: Statement 2176 : SELECT * FROM people WHERE p_id>=? or ? IS NULL ORDER BY p_id
[ 5782] cat: Bind prepared, proto: mysql-5, msg: Statement 2176 : 32766,32766,
[ 5783] cat: Execute, proto: mysql-5, msg: SHOW TABLES FROM zeostesting LIKE 'people'
[ 5784] cat: Execute, proto: mysql-5, msg: SHOW FULL COLUMNS FROM zeostesting.people LIKE '%'
[ 5785] cat: Execute prepared, proto: mysql-5, msg: Statement 2176
[ 5786] cat: Bind prepared, proto: mysql-5, msg: Statement 2176 : (NULL),(NULL),
[ 5787] cat: Execute prepared, proto: mysql-5, msg: Statement 2176
[ 5788] cat: Prepare, proto: mysql-5, msg: Statement 2177 : DELETE FROM people WHERE p_id>=?
[ 5789] cat: Bind prepared, proto: mysql-5, msg: Statement 2177 : 32766,
[ 5790] cat: Execute prepared, proto: mysql-5, msg: Statement 2177

[EgonHugeist]

@fhaut,

i will add a testcase to find the differences. Actually i cant say what's wrong. The value logging.. Yes you're right this is actually not supported for PostgresSQL+CAPIPrepared stmts. Didn't think about it as i wrote this type of statments.

@mdeams

i agree we should support the equal-Param-Names again. Actually there was NO testcase to see this behavior diff. So it was happen accidental.
The Value logging.... We will implement the generic way you did for FB on 7.1.

On 7.2:
Absolutly agree with a option to check if logging is usefull. One of the remaining speed killers is the logging. After switching everthing to raw-encoding for the ansi-based drivers the up-conversion of the values and the SQL-statemtent for the Unicode-IDE's is a real speed killer. IMHO the String(UnicodeString D2009up) of the logvalues is wrong since writing the logs happens always raw-encoded:

if not FileExists(FileName) then
Stream := TFileStream.Create(FileName, fmCreate)
else
Stream := TFileStream.Create(FileName, fmOpenWrite or fmShareDenyWrite);
try
for I := 0 to FTraceList.Count - 1 do
begin
Temp := AnsiString(TZLoggingEvent(FTraceList).AsString + LineEnding);
Buffer := PAnsiChar(Temp);
Stream.Write(Buffer^, {$IFDEF WITH_STRLEN_DEPRECATED}AnsiStrings.{$ENDIF}StrLen(Buffer) * sizeof(Ansichar));
end;

so switching the logs to raw would speed up the logging 'em selves. Making logging optional by checking for existing listeners like you propose would be THE speed burner.

And if i see this code... man there is loads of speed refactoring possible: StrLen of a localized string? LOL

However... step by step

[mdaems]

Yeah, just make fun of a stupid old COBOL and PL/SQLprogrammer with only self study pascal/dephi experience...

OK, for the logging I was thinking about sending string/object and function pointers (=constants that don't need runtime calculation!?) only to the DriverManager.LogMessage (or similar) function. That way this variant of the DriverManager.LogMessage function can just decide to do nothing when nobody's listening.
Does that make sense?

If it does... Wouldn't it be nice to have a Logcollect(Category: TZLoggingCategory) function on the most Abstract statement level that is responsible for creating a TZLoggingEvent of the statements current state for the asked LogiingCategory?
This would make it possible to:
- Create an Interface IZLoggingStatement having only one method LogCollect
- Make all Statements an implementor of this interface
- Create a DriverManager.LogMessage(Statement:IZLoggingStatement, Category: TZLoggingCategory) overload which checks for listeners before calling Staement.LogCollect(Category)
- Call DriverManager.LogMessage(Self,lcBindPrepStmt) whenever we want from the 'logging' Statement.

[EgonHugeist]

@fhaut,

got the value logging running. Patch done R2841 \testing-7.2 (SVN)

where would like

Code: Select all
select * from test01 where id = :X1 or id = :X2
param X1, integer=>65
param X2, integer=>11



where the sintax of printed data is
param = literal
X1 = name of parameter
, = separator
integer = type of data (string, tdatetime, boolean)
=> separator
65 = value(blob parameters are not displayed)

This is a open discussion. I'm not against that(if the logging changes). Help is welcome.
IMHO shouldn't we deal so much with the strings. Just to avoid performance issues(writing raw to streams or files but the String is a UnicodeString since D2009. So an additional conversion is required). You're talking about the component-layer. But the database-conectivity-layer (dbc) works mostly with using an index. The whole logging processing (actually) decreases a loads of performance.

Steps to be made: send the original paramnames to the stmts. Build up a TStringDynArray. This is currently not done. Than a upgrade for (where ever) needs to be done to make them persistant in the logging protocols...

Yeah, just make fun of a stupid old COBOL and PL/SQLprogrammer with only self study pascal/dephi experience...

Seems like my history too

OK, for the logging I was thinking about sending string/object and function pointers (=constants that don't need runtime calculation!?) only to the DriverManager.LogMessage (or similar) function. That way this variant of the DriverManager.LogMessage function can just decide to do nothing when nobody's listening.
Does that make sense?

Nope it doesn't. @7.2 i'm trying to avoid localizing the String where ever possible. It is faster is to work with mem-addresses and length settings instead. I added loads of code which does not work with string constants. The simply need to build up first to add them to the logs.

I'm talking about a step more: Do not log anything as long no listener persists. This includes messages, ErrorLogs, SQL-Stmt-strings, actions in any kind and finally Values.
I know this is a bit more. But we can start with your suggestion. Actually i'm thinking about a way to have the old behavior and/or all sub-options.

Your second idea makes sence for some of my options i'm thinking about.

Frst of all we should change the whole "String" to the !RawByteString! to avoid Up and Down conversions. There is only one plain which works with WideStrings allways: ADO. No idea about best practice here (ParamLogging misses too, btw).
Only if an Error is raised we should convert the strings. But the conversion stuff is my part anyway.

[mdaems]

Michael,

I probably expressed myself wrongly. The first proposal was just a starter idea for the second one. It was just the idea of sending one or more POINTERS to strings(or Z-equivalents)/objects/functions to the logmanager, so without doing string manipulations in the log calling method before the logmanager asks to do the log formatting. Without going to much in detail.
Second proposal just refined the idea.

I'm seriously thinking about making a separate 7.2-logging branch (including ONLY this logging features). If I create it, it should only follow 7.2-testing, and we only merge back the whole stuff after we both agree the solution works. We can do multiple iterations of this process to implement part by part. And only via 7.2-testing this work can get to trunk.
The advantage : when it turns out to be useless : we can just drop the whole stuff.

I think part of this process would be to unify the prepare/bind/execute processes as much as possible over the different drivers. I'm convinced most of this logic can be done on the abstract dbcstatement and/or dbcresultset level. Making the logging code more uniform too.

But let's do it all step by step.

Mark

[EgonHugeist]

Ok, Mark.
Well i think it wouldn't be usefull to kill all unnecessary conversion of the strings first? I was thinking about reforming all listeners and logs to the RawByteString first...

I've some more performance work to do on 7.2. So do it and than the refactoring happens afterwards.

[fhaut]

@fhaut,

got the value logging running. Patch done R2841 \testing-7.2 (SVN)

Works fine on 7.2

Thank you