msaccess odbc queries hang forever, server log: Binding on a statement, that has not been prepared

[m.ardito]

Hi,

I have two different (working) teiid installs:

- 8.2 on as 7.1.1

- 8.4 on eap 6.1 alpha (with the reasteasy patch)

I installed (deployed through the web console) on both same

- drivers,

- ds and

- vdbs

on both installs I enabled this flag in bin\standalone.conf.bat (see this thread, old)

set "JAVA_OPTS=%$JAVA_OPTS% -Dorg.teiid.backslashDefaultMatchEscape=true"

from squirrelSQL I can use mysql, mssql and mixed vdbs, on both teiid versions. great!

from msaccess, I can link tables using postgres odbc on both servers BUT:

opening tables or queries (even smaller ones) does not work: it hangs forever and the server console log shows immediately this kind of message

"WARN  [org.teiid.ODBC] (New I/O worker #2) null TEIID40077 Binding on a statement, that has not been prepared:_PLAN06D3AAC0"

but noyhing never happens... I have to terminate msaccess.

from msaccess, pass-through queries like seem to work, well, though

I could swear that in the past, on 8.2 on as 7.1.1 I was able to open msaccess linked tables and query them as regular queries (not pass-through) with no problem, but now it is not working... how to debug that?

Thanks,

Marco

[shawkins]

> but noyhing never happens... I have to terminate msaccess.

When that message is logged we are notifying the client that an error has occured.  But there may be something missing from the overall protocol as to why the client isn't resuming.  It seems odd though that it's happening in the first place.

What is the pg driver version?

[shawkins]

When using the pg jdbc and perl odbc clients and simulating the above error, I did not see hanging behavior - just a client exception.  However the perl client made me aware of https://issues.jboss.org/browse/TEIID-2604 which may be an issue for you here - I can test this specifically if you provide your pg driver version.  Why the statement is missing for the bind is another question though.  I'll keep looking.

Thanks,

Steve

[m.ardito]

thanks for you reply.

i never changed that odbc dsn, or pg drivers, since it was working (i just expected it would still work as before)

and, as said, passthrough queries seem to work perfectly.

but here are the details:

teiid server is on os win7x64, java 1.7.0_25,

vdb is:

<?xml version="1.0" encoding="UTF-8" standalone="yes"?>

<vdb name="Testmix" version="1">

    <description>Test Mix VDB</description>

    <property name="UseConnectorMetadata" value="true" />

     <model name="TestmixMS">

        <property name="importer.useFullSchemaName" value="true"/>

        <source name="sqlserver-connector" translator-name="sqlserver" connection-jndi-name="java:/magoDS"/>

    </model>

     <model name="TestmixMY">

        <property name="importer.useFullSchemaName" value="false"/>

        <source name="mysql5-connector" translator-name="mysql5" connection-jndi-name="java:/testmysql"/>

    </model>

</vdb>

tried

- sqirrelsql 3.4.0: works perfectly

- office 2010 on the same system, pg driver: 8.04.02.00 (unicode): opening tables hangs forever (it shows an empty table area, but without any grid and hourglass forever)

- office 97 on xp sp3, pg driver: 8.04.02.00 (ansi): opening tables hangs forever (it shows a somehow shaped table area, but without any grid, empty and hourglass forever)

- liberoffice base 4.0.2.2 (connects to teiid vdb, sees all tables, but opening one gives this error

[SQL State: 50000

Error code: 7

ERROR: TEIID31100 Parsing error: Encountered "SELECT * [*],[*] \"ctid\" FROM" at line 1, column 10.

Was expecting: <EOF> | "except" | "fetch" | "from" | "intersect" | "into" | "limit" | "offset" | "option" | "order" ...

org.teiid.jdbc.TeiidSQLException: TEIID31100 Parsing error: Encountered "SELECT * [*],[*] \"ctid\" FROM" at line 1, column 10.

Was expecting: <EOF> | "except" | "fetch" | "from" | "intersect" | "into" | "limit" | "offset" | "option" | "order" ...;

Error while executing the query

SELECT * FROM "Testmix"."TestmixMY"."conti_ripartizioni"

]

which maybe helps more than the msaccess endless hang... btw I just double clicked this table in the tree

odbc dsn (system) settings are identical on both clients :

I am not a Teiid/eap expert, so I don't know how to debug things at a deeper level, but I am willing to learn :-)

Marco

[shawkins]

Marco,

The parsing error is coming from a query that looks like "SELECT *,ctid FROM ...".  That is not valid generally or for Teiid.  The pg odbc client is expecting an updatable cursor and is altering the query to use the ctid implicit system column.  You should disable the updatable cursors and bytea as LO (not yet supported) settings and see if things work better.

Steve

[m.ardito]

Thanks, i disabled updatable cursors and bytea as LO and that helped with Lo 4.0.22 (win7x64) now I can open tables

But msoffice (both 97/XP and 2010/W7) still hanged with no trace of visible errors or logs... as before...

pg odbc driver has logging support,

* commlog (communications log)

* mylog (detailed debug output)

* msdtc log (msdtc debug output)

which may help in this case ?

Marco

[m.ardito]

tried enabling all of them: I am not reporting here those created by Liberoffice, since it works, but perhaps those of office 2010 will help?

1) while msaccess 2010 opening table (hanging, houglass) it creates 2 logs, and then theu keep the same rows, are no more updated, for hat I can see.

2) commlog:

[0.012]CONN ERROR: func=PGAPI_GetConnectOption, desc='', errnum=205, errmsg='Unknown connect option (Get)'

[0.014]            ------------------------------------------------------------

[0.015]            henv=0B522E08, conn=0B522E38, status=0, num_stmts=16

[0.016]            sock=0B5211F8, stmts=0B5212C0, lobj_type=-999

[0.017]            ---------------- Socket Info -------------------------------

[0.018]            socket=-1, reverse=0, errornumber=0, errormsg='(NULL)'

[0.018]            buffer_in=189946264, buffer_out=189950368

[0.019]            buffer_filled_in=0, buffer_filled_out=0, buffer_read_in=0

[0.020]CONN ERROR: func=PGAPI_GetConnectOption, desc='fOption=30002', errnum=205, errmsg='Unknown connect option (Get)'

[0.021]            ------------------------------------------------------------

[0.021]            henv=0B522E08, conn=0B522E38, status=0, num_stmts=16

[0.022]            sock=0B5211F8, stmts=0B5212C0, lobj_type=-999

[0.023]            ---------------- Socket Info -------------------------------

[0.023]            socket=-1, reverse=0, errornumber=0, errormsg='(NULL)'

[0.023]            buffer_in=189946264, buffer_out=189950368

[0.024]            buffer_filled_in=0, buffer_filled_out=0, buffer_read_in=0

[0.025]CONN ERROR: func=PGAPI_SetConnectOption, desc='', errnum=205, errmsg='Unknown connect option (Set)'

[0.026]            ------------------------------------------------------------

[0.026]            henv=0B522E08, conn=0B522E38, status=0, num_stmts=16

[0.026]            sock=0B5211F8, stmts=0B5212C0, lobj_type=-999

[0.027]            ---------------- Socket Info -------------------------------

[0.027]            socket=-1, reverse=0, errornumber=0, errormsg='(NULL)'

[0.027]            buffer_in=189946264, buffer_out=189950368

[0.028]            buffer_filled_in=0, buffer_filled_out=0, buffer_read_in=0

[0.030]conn=0B522E38, PGAPI_DriverConnect( in)='DSN=PGT82testmix;UID=user;PWD=xxxx;DATABASE=Testmix;SERVER=localhost;PORT=35432;CA=d;A6=;A7=100;A8=4096;B0=255;B1=8190;BI=0;C2=dd_;CX=1b20510b9;A1=7.4-1;', fDriverCompletion=0

[0.050]DSN info: DSN='PGT82testmix',server='localhost',port='35432',dbase='Testmix',user='user',passwd='xxxxx'

[0.050]          onlyread='0',protocol='7.4',showoid='0',fakeoidindex='0',showsystable='0'

[0.051]          conn_settings='', conn_encoding='(null)'

[0.051]          translation_dll='',translation_option=''

3) mylog:

[2816-0.001]globals.extra_systable_prefixes = 'dd_;'

[2816-0.002]exe name=MSACCESS plaformId=2

[2816-0.002][[SQLAllocHandle]][2816-0.003]**** in PGAPI_AllocEnv **

[2816-0.004]** exit PGAPI_AllocEnv: phenv = 0B522E08 **

[2816-0.005][[SQLSetEnvAttr]] att=200,2

[2816-0.005][[SQLAllocHandle]][2816-0.005]PGAPI_AllocConnect: entering...

[2816-0.006]**** PGAPI_AllocConnect: henv = 0B522E08, conn = 0B522E38

[2816-0.007]EN_add_connection: self = 0B522E08, conn = 0B522E38

[2816-0.008]       added at 0, conn->henv = 0B522E08, conns[0]->henv = 0B522E08

[2816-0.009][SQLGetInfoW(30)][2816-0.009]PGAPI_GetInfo: entering...fInfoType=77

[2816-0.010]PGAPI_GetInfo: p='03.51', len=0, value=0, cbMax=12

[2816-0.010][SQLSetConnectAttrW][2816-0.010]PGAPI_SetConnectAttr for 0B522E38: 115 00000000

[2816-0.010]the application is unicode

[2816-0.010][SQLSetConnectAttrW][2816-0.011]PGAPI_SetConnectAttr for 0B522E38: 103 00000014

[2816-0.011]PGAPI_SetConnectOption: entering fOption = 103 vParam = 20

[2816-0.011][SQLGetConnectAttrW][2816-0.011]PGAPI_GetConnectAttr 30002

[2816-0.011]PGAPI_GetConnectOption: entering...

[2816-0.012]CC_error_statements: self=0B522E38

[2816-0.014]CONN ERROR: func=PGAPI_GetConnectOption, desc='', errnum=205, errmsg='Unknown connect option (Get)'

[2816-0.020]CONN ERROR: func=PGAPI_GetConnectOption, desc='fOption=30002', errnum=205, errmsg='Unknown connect option (Get)'

[2816-0.024][SQLSetConnectAttrW][2816-0.024]PGAPI_SetConnectAttr for 0B522E38: 30002 0AC75CF0

[2816-0.024]PGAPI_SetConnectOption: entering fOption = 30002 vParam = 180837616

[2816-0.025]CC_error_statements: self=0B522E38

[2816-0.025]CONN ERROR: func=PGAPI_SetConnectOption, desc='', errnum=205, errmsg='Unknown connect option (Set)'

[2816-0.028]Microsoft Jet !!!!

[2816-0.028][SQLDriverConnectW][2816-0.028]PGAPI_DriverConnect: entering...

[2816-0.029]**** PGAPI_DriverConnect: fDriverCompletion=0, connStrIn='DSN=PGT82testmix;UID=user;PWD=xxxx;DATABASE=Testmix;SERVER=localhost;PORT=35432;CA=d;A6=;A7=100;A8=4096;B0=255;B1=8190;BI=0;C2=dd_;CX=1b20510b9;A1=7.4-1;'

[2816-0.031]our_connect_string = 'DSN=PGT82testmix;UID=user;PWD=xxxx;DATABASE=Testmix;SERVER=localhost;PORT=35432;CA=d;A6=;A7=100;A8=4096;B0=255;B1=8190;BI=0;C2=dd_;CX=1b20510b9;A1=7.4-1;'

[2816-0.032]attribute = 'DSN', value = 'PGT82testmix'

[2816-0.032]copyAttributes: DSN='PGT82testmix',server='',dbase='',user='',passwd='xxxxx',port='',onlyread='',protocol='',conn_settings='',disallow_premature=-1)

[2816-0.033]attribute = 'UID', value = 'user'

[2816-0.033]copyAttributes: DSN='PGT82testmix',server='',dbase='',user='user',passwd='xxxxx',port='',onlyread='',protocol='',conn_settings='',disallow_premature=-1)

[2816-0.034]attribute = 'PWD', value = 'xxxxx'

[2816-0.034]copyAttributes: DSN='PGT82testmix',server='',dbase='',user='user',passwd='xxxxx',port='',onlyread='',protocol='',conn_settings='',disallow_premature=-1)

[2816-0.034]attribute = 'DATABASE', value = 'Testmix'

[2816-0.035]copyAttributes: DSN='PGT82testmix',server='',dbase='Testmix',user='user',passwd='xxxxx',port='',onlyread='',protocol='',conn_settings='',disallow_premature=-1)

[2816-0.036]attribute = 'SERVER', value = 'localhost'

[2816-0.036]copyAttributes: DSN='PGT82testmix',server='localhost',dbase='Testmix',user='user',passwd='xxxxx',port='',onlyread='',protocol='',conn_settings='',disallow_premature=-1)

[2816-0.037]attribute = 'PORT', value = '35432'

[2816-0.037]copyAttributes: DSN='PGT82testmix',server='localhost',dbase='Testmix',user='user',passwd='xxxxx',port='35432',onlyread='',protocol='',conn_settings='',disallow_premature=-1)

[2816-0.038]attribute = 'CA', value = 'd'

[2816-0.038]copyAttributes: DSN='PGT82testmix',server='localhost',dbase='Testmix',user='user',passwd='xxxxx',port='35432',onlyread='',protocol='',conn_settings='',disallow_premature=-1)

[2816-0.039]attribute = 'A6', value = ''

[2816-0.039]copyAttributes: DSN='PGT82testmix',server='localhost',dbase='Testmix',user='user',passwd='xxxxx',port='35432',onlyread='',protocol='',conn_settings='',disallow_premature=-1)

[2816-0.040]attribute = 'A7', value = '100'

[2816-0.040]copyAttributes: DSN='PGT82testmix',server='localhost',dbase='Testmix',user='user',passwd='xxxxx',port='35432',onlyread='',protocol='',conn_settings='',disallow_premature=-1)

[2816-0.041]attribute = 'A8', value = '4096'

[2816-0.041]copyAttributes: DSN='PGT82testmix',server='localhost',dbase='Testmix',user='user',passwd='xxxxx',port='35432',onlyread='',protocol='',conn_settings='',disallow_premature=-1)

[2816-0.042]attribute = 'B0', value = '255'

[2816-0.042]copyAttributes: DSN='PGT82testmix',server='localhost',dbase='Testmix',user='user',passwd='xxxxx',port='35432',onlyread='',protocol='',conn_settings='',disallow_premature=-1)

[2816-0.043]attribute = 'B1', value = '8190'

[2816-0.043]copyAttributes: DSN='PGT82testmix',server='localhost',dbase='Testmix',user='user',passwd='xxxxx',port='35432',onlyread='',protocol='',conn_settings='',disallow_premature=-1)

[2816-0.044]attribute = 'BI', value = '0'

[2816-0.044]copyAttributes: DSN='PGT82testmix',server='localhost',dbase='Testmix',user='user',passwd='xxxxx',port='35432',onlyread='',protocol='',conn_settings='',disallow_premature=-1)

[2816-0.045]attribute = 'C2', value = 'dd_'

[2816-0.045]copyAttributes: DSN='PGT82testmix',server='localhost',dbase='Testmix',user='user',passwd='xxxxx',port='35432',onlyread='',protocol='',conn_settings='',disallow_premature=-1)

[2816-0.046]attribute = 'CX', value = '1b20510b9'

[2816-0.046]copyAttributes: DSN='PGT82testmix',server='localhost',dbase='Testmix',user='user',passwd='xxxxx',port='35432',onlyread='0',protocol='7.4',conn_settings='',disallow_premature=0)

[2816-0.047]attribute = 'A1', value = '7.4-1'

[2816-0.047]rollback_on_error=1

[2816-0.047]copyAttributes: DSN='PGT82testmix',server='localhost',dbase='Testmix',user='user',passwd='xxxxx',port='35432',onlyread='0',protocol='7.4',conn_settings='',disallow_premature=0)

[2816-0.048]getDSNinfo: DSN=PGT82testmix overwrite=0

[2816-0.049]force_abbrev=0 bde=0 cvt_null_date=0

[2816-0.050]globals.extra_systable_prefixes = 'dd_;'

[2816-0.051]our_connect_string = 'DSN=PGT82testmix;UID=user;PWD=xxxx;DATABASE=Testmix;SERVER=localhost;PORT=35432;CA=d;A6=;A7=100;A8=4096;B0=255;B1=8190;BI=0;C2=dd_;CX=1b20510b9;A1=7.4-1;'

[2816-0.052]attribute = 'DSN', value = 'PGT82testmix'

[2816-0.052]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=0;B6=0;B7=1;B8=0;B9=1;C0=1;C1=0;C2=dd_;[2816-0.053]attribute = 'UID', value = 'user'

[2816-0.053]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=0;B6=0;B7=1;B8=0;B9=1;C0=1;C1=0;C2=dd_;[2816-0.053]attribute = 'PWD', value = 'xxxxx'

[2816-0.054]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=0;B6=0;B7=1;B8=0;B9=1;C0=1;C1=0;C2=dd_;[2816-0.054]attribute = 'DATABASE', value = 'Testmix'

[2816-0.055]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=0;B6=0;B7=1;B8=0;B9=1;C0=1;C1=0;C2=dd_;[2816-0.055]attribute = 'SERVER', value = 'localhost'

[2816-0.055]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=0;B6=0;B7=1;B8=0;B9=1;C0=1;C1=0;C2=dd_;[2816-0.056]attribute = 'PORT', value = '35432'

[2816-0.056]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=0;B6=0;B7=1;B8=0;B9=1;C0=1;C1=0;C2=dd_;[2816-0.057]attribute = 'CA', value = 'd'

[2816-0.057]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=0;B6=0;B7=1;B8=0;B9=1;C0=1;C1=0;C2=dd_;[2816-0.057]attribute = 'A6', value = ''

[2816-0.057]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=0;B6=0;B7=1;B8=0;B9=1;C0=1;C1=0;C2=dd_;[2816-0.058]attribute = 'A7', value = '100'

[2816-0.058]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=0;B6=0;B7=1;B8=0;B9=1;C0=1;C1=0;C2=dd_;[2816-0.059]attribute = 'A8', value = '4096'

[2816-0.059]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=0;B6=0;B7=1;B8=0;B9=1;C0=1;C1=0;C2=dd_;[2816-0.059]attribute = 'B0', value = '255'

[2816-0.062]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=0;B6=0;B7=1;B8=0;B9=1;C0=1;C1=0;C2=dd_;[2816-0.062]attribute = 'B1', value = '8190'

[2816-0.063]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=0;B6=0;B7=1;B8=0;B9=1;C0=1;C1=0;C2=dd_;[2816-0.063]attribute = 'BI', value = '0'

[2816-0.063]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=0;B6=0;B7=1;B8=0;B9=1;C0=1;C1=0;C2=dd_;[2816-0.064]attribute = 'C2', value = 'dd_'

[2816-0.064]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=0;B6=0;B7=1;B8=0;B9=1;C0=1;C1=0;C2=dd_[2816-0.064]attribute = 'CX', value = '1b20510b9'

[2816-0.065]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=0;B6=0;B7=1;B8=0;B9=1;C0=1;C1=0;C2=dd_[2816-0.065]attribute = 'A1', value = '7.4-1'

[2816-0.065]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=0;B6=0;B7=1;B8=0;B9=1;C0=1;C1=0;C2=dd_

hth

Marco

[shawkins]

> But msoffice (both 97/XP and 2010/W7) still hanged with no trace of visible errors or logs... as before...

Well that is at least some progress.  Yes I don't see anything too meaningful in the above either.  And you don't see any errors/warnings in the teiid logs correct?  If you set the logging level much higher such as debug (with at least the org.teiid.ODBC level on trace) or trace - it should give a better picture of what is happening from our side.

Also https://issues.jboss.org/browse/TEIID-2604 has been addressed for 8.5 Beta1 which should hopefully prevent the hanging behavior if it was due to the error response message.

Steve

[m.ardito]

here is what I get (restarted the server and clients from scratch)

liberoffice opening table conti_ripartizioni (ok)

16:58:15,998 INFO  [org.teiid.PROCESSOR.MATVIEWS] (Worker0_QueryProcessorQueue0) SkDfGgVha+Uy TEIID30013 Loading materialized view table #MAT_PG_CATALOG.PG_TYPE

16:58:16,377 INFO  [org.teiid.PROCESSOR.MATVIEWS] (Worker0_QueryProcessorQueue0) SkDfGgVha+Uy TEIID30014 Loaded materialized view table #MAT_PG_CATALOG.PG_TYPE with row count 37.

16:58:16,394 INFO  [org.teiid.PROCESSOR.MATVIEWS] (Worker0_QueryProcessorQueue0) SkDfGgVha+Uy TEIID30013 Loading materialized view table #MAT_PG_CATALOG.MATPG_RELATT

16:58:16,432 INFO  [org.teiid.PROCESSOR.MATVIEWS] (Worker0_QueryProcessorQueue0) SkDfGgVha+Uy TEIID30013 Loading materialized view table #MAT_PG_CATALOG.PG_ATTRIBUTE

16:58:16,453 INFO  [org.teiid.PROCESSOR.MATVIEWS] (Worker0_QueryProcessorQueue0) SkDfGgVha+Uy TEIID30013 Loading materialized view table #MAT_PG_CATALOG.MATPG_DATATYPE

16:58:16,471 INFO  [org.teiid.PROCESSOR.MATVIEWS] (Worker0_QueryProcessorQueue0) SkDfGgVha+Uy TEIID30014 Loaded materialized view table #MAT_PG_CATALOG.MATPG_DATATYPE with row count 18.

16:58:17,195 INFO  [org.teiid.PROCESSOR.MATVIEWS] (Worker0_QueryProcessorQueue0) SkDfGgVha+Uy TEIID30014 Loaded materialized view table #MAT_PG_CATALOG.PG_ATTRIBUTE with row count 17.771.

16:58:17,234 INFO  [org.teiid.PROCESSOR.MATVIEWS] (Worker0_QueryProcessorQueue0) SkDfGgVha+Uy TEIID30013 Loading materialized view table #MAT_PG_CATALOG.PG_CLASS

16:58:17,274 INFO  [org.teiid.PROCESSOR.MATVIEWS] (Worker0_QueryProcessorQueue0) SkDfGgVha+Uy TEIID30014 Loaded materialized view table #MAT_PG_CATALOG.PG_CLASS with row count 1.038.

16:58:18,956 INFO  [org.teiid.PROCESSOR.MATVIEWS] (Worker0_QueryProcessorQueue0) SkDfGgVha+Uy TEIID30014 Loaded materialized view table #MAT_PG_CATALOG.MATPG_RELATT with row count 17.717.

16:58:26,667 INFO  [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue14) SkDfGgVha+Uy MySQL5ExecutionFactory Commit=true;DatabaseProductName=MySQL;DatabaseProductVersion=5.1.63-0ubuntu0.10.04.1;DriverMajorVersion=5;DriverMajorVersion=1;DriverName=MySQL-AB JDBC Driver;DriverVersion=mysql-connector-java-5.1.22 ( Revision: ${bzr.revision-id} );IsolationLevel=2

msaccess2010 trying to open table conti_ripartizioni

17:00:39,772 WARN  [org.teiid.PROCESSOR] (Worker2_QueryProcessorQueue23) Q2TUyYbzHOo3 TEIID30020 Processing exception for request Q2TUyYbzHOo3.3 'Group does not exist: MSysConf'. Originally QueryResolverException ResolverUtil.java:814. Enable more detailed logging to see the entire stacktrace.

17:00:40,045 WARN  [org.teiid.ODBC] (New I/O worker #3) null TEIID40077 Binding on a statement, that has not been prepared:_PLAN0B817BB0

and only if I terminate msaccess:

17:01:23,956 ERROR [org.teiid.ODBC] (New I/O worker #3) null Unhandled exception, closing client instance: java.io.IOException: Connessione in corso interrotta forzatamente dall'host remoto

    at sun.nio.ch.SocketDispatcher.read0(Native Method) [rt.jar:1.7.0_25]

    at sun.nio.ch.SocketDispatcher.read(Unknown Source) [rt.jar:1.7.0_25]

    at sun.nio.ch.IOUtil.readIntoNativeBuffer(Unknown Source) [rt.jar:1.7.0_25]

    at sun.nio.ch.IOUtil.read(Unknown Source) [rt.jar:1.7.0_25]

    at sun.nio.ch.SocketChannelImpl.read(Unknown Source) [rt.jar:1.7.0_25]

    at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:64) [netty-3.6.2.Final.jar:]

    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:107) [netty-3.6.2.Final.jar:]

    at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:312) [netty-3.6.2.Final.jar:]

    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:88) [netty-3.6.2.Final.jar:]

    at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178) [netty-3.6.2.Final.jar:]

    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [rt.jar:1.7.0_25]

    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [rt.jar:1.7.0_25]

    at java.lang.Thread.run(Unknown Source) [rt.jar:1.7.0_25]

I'll try increasing loggin level tomorrow, hopefully.

Thx, and congratulations! You're about to reach 1k posts! :-D

Marco

[shawkins]

I did confirm that TEIID-2604 will address the hanging, but with just libreoffice was not able to reproduce "'Group does not exist: MSysConf'" nor "TEIID40077 Binding on a statement, that has not been prepared:_PLAN0B817BB0".  Having an odbc trace log will allow us to see the exact sequence of client/server messages that is causing the latter issue.

> and only if I terminate msaccess:

That is happening because the client is terminating unexpectedly, but it's being logged at too high a level.

> Thx, and congratulations! You're about to reach 1k posts! :-D

Thanks, hopefully we'll get this stuff resolved before 2k

[m.ardito]

Great!, Well, about TEIID-2604 I'm happy. I see on that issue Fix Version/s: 8.4.1, 8.5. There will be a 8.4.1 before?

For Liberoffice, remember that when i disabled updatable cursors and bytea as LO, that helped with Lo 4.0.22 (win7x64): now works perfectly.

Instead, "'Group does not exist: MSysConf'" and "TEIID40077" were in the msaccess 2010 error log!

I'll try to have more traces today, by odbc and eap/teiis, too.

Marco

[m.ardito]

I logged the windows ODBC trace for two situations:

1) liberoffice opening "teiidtest.odb" (database created from odbc postgres dsn -> teiid, vdb model as previously posted), and then opening and cloing a table "conti_contratti". Pinfully slow due to the logging, but everything works.

this produced a huge 100k+ lines trace log, which I attach here as file "SQL_LO_open_table_conti_contratti_open-close.LOG"

until line 92136:

Desktop"	1348-11a8	EXIT  SQLFreeHandle  with return code 0 (SQL_SUCCESS)
		SQLSMALLINT	3 <SQL_HANDLE_STMT>
		SQLHANDLE	0x00FFE9A8

It is barely opening the database itself (the vdb joins a small mysql db and a huge sqlserver with more than 450 tables)

From that line on, it is opening the table and then closing it.

2) msaccess 2010 "teiidtest.accdb", with only two linked tables  from the same DSN, logs only whan trying (but hanging) to open the same table "conti_contratti"

this produced a much smaller "SQL_MSA2010_open_table_conti_contratti.LOG" of 3232 lines only. I can see seom problems here, hope helps you to understand.

3) I'm adding, for comparison, a new windows odbc trace, "SQL_MSA2010_open_table_conti_contratti_mysql_odbc.LOG"

got from the same msaccess 2010 database "teiidtest.accdb", opening the same table "conti_contratti" linked through mysql odbc driver, not teiid.

Slightly bigger than case 2) but this works.

Marco

[m.ardito]

other hints, I hope:

in msaccess 2010, same .accdb.

when i link the table from odbc dsn, msaccess saves it as "TestmixMY_conti_ripartizioni"

1) i cannot open it directly, since it hangs

2) if i try a pass-through (same dsn) like SELECT * FROM TestmixMY_conti_ripartizioni;

i get this error: "ERROR: Group does not exist: TestmixMY_conti_ripartizioni org.teiid.jdbc.TeiidSQLException: Group does not exist: TestmixMY_conti_ripartizioni; Error while executing the query (#7) "

3) if i try a pass-through (same dsn) like SELECT * FROM "TestmixMY"."conti_ripartizioni"

it works, no error (same as in squirrelsql)

4) if i try a pass-through (same dsn) like SELECT * FROM conti_ripartizioni

it works, no error (same as in squirrelsql)

Marco

[shawkins]

> I see on that issue Fix Version/s: 8.4.1, 8.5. There will be a 8.4.1 before?

There will not be a community release based upon 8.4.1.  8.5 beta1 should be available later today though with the final release in September.

> For Liberoffice, remember that when i disabled updatable cursors and bytea as LO, that helped with Lo 4.0.22 (win7x64): now works perfectly.

Yes, but I'm on a linux system so I'm just trying that are easy to replicate locally - different DSN settings and differernt driver versions, etc.

> this produced a much smaller "SQL_MSA2010_open_table_conti_contratti.LOG" of 3232 lines only. I can see seom problems here, hope helps you to understand.

The MSysConf error is appearently expected and looks to be properly ignored by the log - http://knowledgebase.progress.com/articles/Article/9986

Did you see something else that was amiss?

Ideally if you can change the Teiid server logging level to trace for org.teiid.ODBC that would give us a clear picture of the messge flow leading up to the error response that is causing the now fixed hang.

Thanks for digging into this,

Steve

[m.ardito]

Great about 8.5 beta, I'll try asap.

about the trace log, i added

<logger category="org.teiid.ODBC">

    <level name="TRACE"/>

</logger>

near similar sections...

then with msaccess 2010 .accdb, opening (hanging) table, got (from log\server.log file, on the console many rowws are missing... ?):

13:45:34,651 TRACE [org.teiid.ODBC] (New I/O worker #2)  StartupMessage version 196608 ( 3 . 0 )

13:45:34,662 TRACE [org.teiid.ODBC] (New I/O worker #2)  invoking server method: initialize [{client_encoding=UTF8, extra_float_digits=2, user=user, default_transaction_isolation=read committed, version=196608, TimeZone=Ora dell'Europa centrale, DateStyle=ISO, database=Testmix, geqo=on}]

13:45:34,663 TRACE [org.teiid.ODBC] (New I/O worker #2)  invoking client method: initialized [{client_encoding=UTF8, extra_float_digits=2, user=user, default_transaction_isolation=read committed, version=196608, TimeZone=Ora dell'Europa centrale, DateStyle=ISO, database=Testmix, geqo=on}]

13:45:34,664 TRACE [org.teiid.ODBC] (New I/O worker #2)  invoking client method: useClearTextAuthentication null

13:45:34,667 TRACE [org.teiid.ODBC] (New I/O worker #2)  invoking server method: logon [Testmix, user, org.teiid.transport.PgFrontendProtocol$NullTerminatedStringDataInputStream@1b17655]

13:45:34,784 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking client method: authenticationSucess [-1033520105, -1033520105]

13:45:34,785 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking client method: ready [false, false]

13:45:34,785 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking server method: executeQuery [select oid, typbasetype from pg_type where typname = 'lo']

13:45:35,106 INFO  [org.teiid.PROCESSOR.MATVIEWS] (Worker0_QueryProcessorQueue0) nFw//lTEyO/r TEIID30013 Loading materialized view table #MAT_PG_CATALOG.PG_TYPE

13:45:35,210 INFO  [org.teiid.PROCESSOR.MATVIEWS] (Worker0_QueryProcessorQueue0) nFw//lTEyO/r TEIID30014 Loaded materialized view table #MAT_PG_CATALOG.PG_TYPE with row count 37.

13:45:35,231 INFO  [org.teiid.PROCESSOR.MATVIEWS] (Worker0_QueryProcessorQueue0) nFw//lTEyO/r TEIID30013 Loading materialized view table #MAT_PG_CATALOG.MATPG_RELATT

13:45:35,278 INFO  [org.teiid.PROCESSOR.MATVIEWS] (Worker0_QueryProcessorQueue0) nFw//lTEyO/r TEIID30013 Loading materialized view table #MAT_PG_CATALOG.PG_ATTRIBUTE

13:45:35,299 INFO  [org.teiid.PROCESSOR.MATVIEWS] (Worker0_QueryProcessorQueue0) nFw//lTEyO/r TEIID30013 Loading materialized view table #MAT_PG_CATALOG.MATPG_DATATYPE

13:45:35,322 INFO  [org.teiid.PROCESSOR.MATVIEWS] (Worker0_QueryProcessorQueue0) nFw//lTEyO/r TEIID30014 Loaded materialized view table #MAT_PG_CATALOG.MATPG_DATATYPE with row count 18.

13:45:36,018 INFO  [org.teiid.PROCESSOR.MATVIEWS] (Worker0_QueryProcessorQueue0) nFw//lTEyO/r TEIID30014 Loaded materialized view table #MAT_PG_CATALOG.PG_ATTRIBUTE with row count 17.771.

13:45:36,070 INFO  [org.teiid.PROCESSOR.MATVIEWS] (Worker0_QueryProcessorQueue0) nFw//lTEyO/r TEIID30013 Loading materialized view table #MAT_PG_CATALOG.PG_CLASS

13:45:36,108 INFO  [org.teiid.PROCESSOR.MATVIEWS] (Worker0_QueryProcessorQueue0) nFw//lTEyO/r TEIID30014 Loaded materialized view table #MAT_PG_CATALOG.PG_CLASS with row count 1.038.

13:45:37,732 INFO  [org.teiid.PROCESSOR.MATVIEWS] (Worker0_QueryProcessorQueue0) nFw//lTEyO/r TEIID30014 Loaded materialized view table #MAT_PG_CATALOG.MATPG_RELATT with row count 17.717.

13:45:37,738 TRACE [org.teiid.ODBC] (Worker0_QueryProcessorQueue0) nFw//lTEyO/r invoking client method: sendResults [select oid, typbasetype from pg_type where typname = 'lo', org.teiid.jdbc.ResultSetImpl@1abf749, [org.teiid.odbc.PGUtil$PgColInfo@f810d8, org.teiid.odbc.PGUtil$PgColInfo@1a09b8], org.teiid.client.util.ResultsFuture@1742399, true]

13:45:37,744 TRACE [org.teiid.ODBC] (Worker0_QueryProcessorQueue0) nFw//lTEyO/r invoking client method: ready [false, false]

13:45:37,745 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking server method: executeQuery [SELECT Config, nValue FROM MSysConf]

13:45:37,758 WARN  [org.teiid.PROCESSOR] (Worker1_QueryProcessorQueue1) nFw//lTEyO/r TEIID30020 Processing exception for request nFw//lTEyO/r.3 'Group does not exist: MSysConf'. Originally QueryResolverException ResolverUtil.java:814. Enable more detailed logging to see the entire stacktrace.

13:45:37,760 TRACE [org.teiid.ODBC] (Worker1_QueryProcessorQueue1) nFw//lTEyO/r invoking client method: errorOccurred [org.teiid.jdbc.TeiidSQLException: Group does not exist: MSysConf]

13:45:37,760 WARN  [org.teiid.ODBC] (Worker1_QueryProcessorQueue1) nFw//lTEyO/r TEIID40020 Error occurred: org.teiid.jdbc.TeiidSQLException: Group does not exist: MSysConf

    at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:135) [teiid-client-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:71) [teiid-client-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.jdbc.StatementImpl.postReceiveResults(StatementImpl.java:667) [teiid-client-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.jdbc.StatementImpl.access$100(StatementImpl.java:63) [teiid-client-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.jdbc.StatementImpl$2.onCompletion(StatementImpl.java:516) [teiid-client-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.client.util.ResultsFuture.done(ResultsFuture.java:130) [teiid-client-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.client.util.ResultsFuture.access$200(ResultsFuture.java:37) [teiid-client-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.client.util.ResultsFuture$1.receiveResults(ResultsFuture.java:75) [teiid-client-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.dqp.internal.process.RequestWorkItem.sendError(RequestWorkItem.java:957) [teiid-engine-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.dqp.internal.process.RequestWorkItem.close(RequestWorkItem.java:543) [teiid-engine-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.dqp.internal.process.RequestWorkItem.process(RequestWorkItem.java:346) [teiid-engine-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.dqp.internal.process.AbstractWorkItem.run(AbstractWorkItem.java:51) [teiid-engine-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.dqp.internal.process.RequestWorkItem.run(RequestWorkItem.java:248) [teiid-engine-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:269) [teiid-engine-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:119) [teiid-engine-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:214) [teiid-engine-8.4.0.Final.jar:8.4.0.Final]

    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [rt.jar:1.7.0_25]

    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [rt.jar:1.7.0_25]

    at java.lang.Thread.run(Unknown Source) [rt.jar:1.7.0_25]

Caused by: org.teiid.api.exception.query.QueryResolverException: Group does not exist: MSysConf

    at org.teiid.query.resolver.util.ResolverUtil.handleUnresolvedGroup(ResolverUtil.java:814) [teiid-engine-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.query.resolver.util.ResolverUtil.resolveGroup(ResolverUtil.java:893) [teiid-engine-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.query.resolver.QueryResolver.isXMLQuery(QueryResolver.java:348) [teiid-engine-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.query.resolver.QueryResolver.chooseResolver(QueryResolver.java:293) [teiid-engine-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.query.resolver.QueryResolver.resolveCommand(QueryResolver.java:267) [teiid-engine-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.query.resolver.QueryResolver.resolveCommand(QueryResolver.java:124) [teiid-engine-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.dqp.internal.process.Request.resolveCommand(Request.java:260) [teiid-engine-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.dqp.internal.process.Request.generatePlan(Request.java:370) [teiid-engine-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.dqp.internal.process.Request.processRequest(Request.java:436) [teiid-engine-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.dqp.internal.process.RequestWorkItem.processNew(RequestWorkItem.java:600) [teiid-engine-8.4.0.Final.jar:8.4.0.Final]

    at org.teiid.dqp.internal.process.RequestWorkItem.process(RequestWorkItem.java:309) [teiid-engine-8.4.0.Final.jar:8.4.0.Final]

    ... 8 more

13:45:37,770 TRACE [org.teiid.ODBC] (Worker1_QueryProcessorQueue1) nFw//lTEyO/r invoking client method: ready [false, false]

13:45:37,773 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking server method: executeQuery [SELECT "TestmixMY"."conti_ripartizioni"."conto" FROM "TestmixMY"."conti_ripartizioni" ]

13:45:37,794 INFO  [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue3) nFw//lTEyO/r MySQL5ExecutionFactory Commit=true;DatabaseProductName=MySQL;DatabaseProductVersion=5.1.63-0ubuntu0.10.04.1;DriverMajorVersion=5;DriverMajorVersion=1;DriverName=MySQL-AB JDBC Driver;DriverVersion=mysql-connector-java-5.1.22 ( Revision: ${bzr.revision-id} );IsolationLevel=2

13:45:37,830 TRACE [org.teiid.ODBC] (Worker1_QueryProcessorQueue4) nFw//lTEyO/r invoking client method: sendResults [SELECT "TestmixMY"."conti_ripartizioni"."conto" FROM "TestmixMY"."conti_ripartizioni", org.teiid.jdbc.ResultSetImpl@11d077c, [org.teiid.odbc.PGUtil$PgColInfo@d67d3c], org.teiid.client.util.ResultsFuture@1b80d58, true]

13:45:37,832 TRACE [org.teiid.ODBC] (Worker1_QueryProcessorQueue4) nFw//lTEyO/r invoking client method: ready [false, false]

13:45:37,834 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking server method: prepare [_PLAN0AE60FD8, SELECT "conto","descrizione","split_fornitori","ivaind","attivo"  FROM "TestmixMY"."conti_ripartizioni"  WHERE "conto" = $1, [0]]

13:45:37,835 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking client method: prepareCompleted [_PLAN0AE60FD8]

13:45:37,835 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking server method: getParameterDescription [_PLAN0AE60FD8]

13:45:37,836 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking client method: sendParameterDescription [org.teiid.jdbc.ParameterMetaDataImpl@186905e, [0]]

13:45:37,839 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking client method: sendResultSetDescription [[org.teiid.odbc.PGUtil$PgColInfo@13c661c, org.teiid.odbc.PGUtil$PgColInfo@53e816, org.teiid.odbc.PGUtil$PgColInfo@aa1109, org.teiid.odbc.PGUtil$PgColInfo@1447492, org.teiid.odbc.PGUtil$PgColInfo@1414f21]]

13:45:37,840 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking server method: bindParameters [_PLAN0AE60FD8, _PLAN0AE60FD8, 1, [06000013], 0, []]

13:45:37,840 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking client method: bindComplete null

13:45:37,840 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking server method: execute [_PLAN0AE60FD8, 0]

13:45:37,842 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking server method: closeBoundStatement [_PLAN0AE60FD8]

13:45:37,842 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking server method: sync null

13:45:37,849 TRACE [org.teiid.ODBC] (Worker1_QueryProcessorQueue8) nFw//lTEyO/r invoking client method: sendResults [SELECT "conto","descrizione","split_fornitori","ivaind","attivo"  FROM "TestmixMY"."conti_ripartizioni"  WHERE "conto" = $1, org.teiid.jdbc.ResultSetImpl@91f8, [org.teiid.odbc.PGUtil$PgColInfo@16f454c, org.teiid.odbc.PGUtil$PgColInfo@2ea016, org.teiid.odbc.PGUtil$PgColInfo@1102f87, org.teiid.odbc.PGUtil$PgColInfo@1a06970, org.teiid.odbc.PGUtil$PgColInfo@6a3f0d], org.teiid.client.util.ResultsFuture@1517e14, false]

13:45:37,851 TRACE [org.teiid.ODBC] (Worker1_QueryProcessorQueue8) nFw//lTEyO/r invoking client method: statementClosed null

13:45:37,851 TRACE [org.teiid.ODBC] (Worker1_QueryProcessorQueue8) nFw//lTEyO/r invoking client method: ready [false, false]

13:45:37,870 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking server method: prepare [_PLAN0B8D78F8, SELECT "conto","descrizione","split_fornitori","ivaind","attivo"  FROM "TestmixMY"."conti_ripartizioni"  WHERE "conto" = $1 OR "conto" = $2 OR "conto" = $3 OR "conto" = $4 OR "conto" = $5 OR "conto" = $6 OR "conto" = $7 OR "conto" = $8 OR "conto" = $9 OR "conto" = $10, [0, 0, 0, 0, 0, 0, 0, 0, 0, 0]]

13:45:37,870 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking client method: prepareCompleted [_PLAN0B8D78F8]

13:45:37,870 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking server method: getParameterDescription [_PLAN0B8D78F8]

13:45:37,871 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking client method: sendParameterDescription [org.teiid.jdbc.ParameterMetaDataImpl@c1e0c, [0, 0, 0, 0, 0, 0, 0, 0, 0, 0]]

13:45:37,873 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking client method: sendResultSetDescription [[org.teiid.odbc.PGUtil$PgColInfo@150c086, org.teiid.odbc.PGUtil$PgColInfo@8f9e16, org.teiid.odbc.PGUtil$PgColInfo@d3e5d3, org.teiid.odbc.PGUtil$PgColInfo@195ad34, org.teiid.odbc.PGUtil$PgColInfo@19e5188]]

13:45:37,874 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking server method: bindParameters [_PLAN0B8D78F8, _PLAN0B8D78F8, 10, [06000013, 06000027, 06000030, 06011002, 06011004, 06011010, 06011020, 06012000, 06020016, 06020017], 0, []]

13:45:37,874 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking client method: bindComplete null

13:45:37,874 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking server method: execute [_PLAN0B8D78F8, 0]

13:45:37,874 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking server method: closeBoundStatement [_PLAN0B8D78F8]

13:45:37,874 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking server method: sync null

13:45:37,885 TRACE [org.teiid.ODBC] (Worker1_QueryProcessorQueue12) nFw//lTEyO/r invoking client method: sendResults [SELECT "conto","descrizione","split_fornitori","ivaind","attivo"  FROM "TestmixMY"."conti_ripartizioni"  WHERE "conto" = $1 OR "conto" = $2 OR "conto" = $3 OR "conto" = $4 OR "conto" = $5 OR "conto" = $6 OR "conto" = $7 OR "conto" = $8 OR "conto" = $9 OR "conto" = $10, org.teiid.jdbc.ResultSetImpl@1de4713, [org.teiid.odbc.PGUtil$PgColInfo@c42ca, org.teiid.odbc.PGUtil$PgColInfo@f507e8, org.teiid.odbc.PGUtil$PgColInfo@da30a2, org.teiid.odbc.PGUtil$PgColInfo@af010b, org.teiid.odbc.PGUtil$PgColInfo@16db0eb], org.teiid.client.util.ResultsFuture@7a401e, false]

13:45:37,886 TRACE [org.teiid.ODBC] (Worker1_QueryProcessorQueue12) nFw//lTEyO/r invoking client method: statementClosed null

13:45:37,886 TRACE [org.teiid.ODBC] (Worker1_QueryProcessorQueue12) nFw//lTEyO/r invoking client method: ready [false, false]

13:45:37,887 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking server method: bindParameters [_PLAN0B8D78F8, _PLAN0B8D78F8, 10, [06020020, 06020021, 06020022, 06020023, 06020024, 06020026, 06020029, 06020035, 06020036, 06020038], 0, []]

13:45:37,887 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking client method: errorOccurred [TEIID40077 Binding on a statement, that has not been prepared:_PLAN0B8D78F8]

13:45:37,887 WARN  [org.teiid.ODBC] (New I/O worker #2) null TEIID40077 Binding on a statement, that has not been prepared:_PLAN0B8D78F8

13:45:37,887 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking server method: execute [_PLAN0B8D78F8, 0]

13:45:37,888 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking server method: closeBoundStatement [_PLAN0B8D78F8]

13:45:37,888 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking server method: sync null

13:45:37,888 TRACE [org.teiid.ODBC] (New I/O worker #2) null invoking client method: ready [false, false]

any other useful log to trace ?

Marco