Re: [sqlalchemy] Bug in BufferedColumnResultProxy class?

2016-04-28 Thread Piotr Dobrogost 
On Wednesday, April 27, 2016 at 6:41:24 PM UTC+2, Mike Bayer wrote:
>
>
>
> On 04/27/2016 11:11 AM, Mike Bayer wrote: 
> > 
> > I'm improving our test suite by ensuring that result processors are 
> > fired off for all result proxy subtypes when caching is used as well and 
> > I will ensure the line of code you mention is exercised.  If I can 
> > reproduce your described issue at that level, then the bug will be 
> > located and fixed.   I'll keep you posted. 
> > 
>
> with query caching enabled the issue is reproduced with new test cases, 
> a fix for the issue is in review via the link at 
>
> https://bitbucket.org/zzzeek/sqlalchemy/issues/3699/buffferedcolumnresultproxy-with.
>  
>
>

I would like to thank you Mike very much for your assistance, perseverance, 
invaluable help and the fix.
Your support is exemplar.

Best regards from users of your excellent SQLAlchemy,
Marcin Raczyński i Piotr Dobrogost from Poland

ps.
The original investigation of the issue and suggested fix was done by 
Marcin Raczyński.

-- 
You received this message because you are subscribed to the Google Groups 
"sqlalchemy" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to sqlalchemy+unsubscr...@googlegroups.com.
To post to this group, send email to sqlalchemy@googlegroups.com.
Visit this group at https://groups.google.com/group/sqlalchemy.
For more options, visit https://groups.google.com/d/optout.

Re: [sqlalchemy] Bug in BufferedColumnResultProxy class?

2016-04-27 Thread Mike Bayer 



On 04/27/2016 11:11 AM, Mike Bayer wrote:


I'm improving our test suite by ensuring that result processors are
fired off for all result proxy subtypes when caching is used as well and
I will ensure the line of code you mention is exercised.  If I can
reproduce your described issue at that level, then the bug will be
located and fixed.   I'll keep you posted.



with query caching enabled the issue is reproduced with new test cases, 
a fix for the issue is in review via the link at 
https://bitbucket.org/zzzeek/sqlalchemy/issues/3699/buffferedcolumnresultproxy-with.



--
You received this message because you are subscribed to the Google Groups 
"sqlalchemy" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to sqlalchemy+unsubscr...@googlegroups.com.
To post to this group, send email to sqlalchemy@googlegroups.com.
Visit this group at https://groups.google.com/group/sqlalchemy.
For more options, visit https://groups.google.com/d/optout.

Re: [sqlalchemy] Bug in BufferedColumnResultProxy class?

2016-04-27 Thread Mike Bayer 



On 04/26/2016 12:11 PM, Piotr Dobrogost wrote:

On Tue, Apr 26, 2016 at 12:18 AM, Mike Bayer  wrote:


On 04/25/2016 11:04 AM, Piotr Dobrogost wrote:


Is caching using dogpile what you call "Query cache extension"? If so
we don't use it.


this extension:
http://docs.sqlalchemy.org/en/rel_1_0/orm/extensions/baked.html?highlight=baked#module-sqlalchemy.ext.baked


Ok. I see this being used in Kotti (the framework I use). For example
here 
https://github.com/Kotti/Kotti/blob/0d162332e369dedb1b4936935e43de89e9665f8e/kotti/resources.py#L812


the stack trace shown here illustrates an INSERT statement in the context of
an ORM flush, which does use the compiled_cache feature; so to that degree,
this part of the puzzle makes sense.


I'm curious what in the log shows that we deal with "INSERT statement
in the context of an ORM flush"?


However, in cx_oracle, an INSERT statement does not return rows there's no
data to be returned; cursor.description should be None and the
BufferredColumnResultProxy will not be used.An INSERT statement in
Oracle that uses "RETURNING", as is usually the case for the ORM INSERT
statement, uses OUT parameters to achieve this and will make use of the
ReturningResultProxy to work around what's needed here.


Ok.


Since we're working without a test case of any kind, are you sure that the
result proxy indicating the problem is not a ReturningResultProxy ?   Are we
dealing with a column that has a server-generated default value that is of
type BLOB, CLOB, or similar ?


There is ReturningResultProxy in the call stack for example here
https://gist.github.com/piotr-dobrogost/6d57cacb9e77f59748353b2b6c1334d7#file-call-stack-while-executing-line-519-of-result-py-run-for-the-first-time-ever-during-app-startup-L58

and it's the type of "self" which I showed here

https://gist.github.com/piotr-dobrogost/6d57cacb9e77f59748353b2b6c1334d7#file-call-stack-while-executing-line-519-of-result-py-run-for-the-first-time-ever-during-app-startup-L74

It occurred to me that one can reproduce this rather easily installing
Kotti framework alone (or rather slightly modified version adjusted to
work with Oracle which you can find at
https://github.com/piotr-dobrogost/Kotti/tree/sfx).Kotti has
requirements.txt file where you can replace Kotti==1.3.0-alpha.4 with
git+https://github.com/piotr-dobrogost/Kotti.git@sfx and install
everything with `pip install --no-deps -r requirements.txt`. Running
is simple with `pserve development.ini` command (as Kotti is based on
Pyramid). Before running you have to edit development.ini and change
sqlalchemy.url to point to your Oracle db. When run Kotti creates and
populates db and when you try to access app at http://localhost:5000/
the error happens.


Unfortunately I can't accept bug reports of this form.   At the level 
of, "I can't reproduce it unless I run Kotti", by that logic it is just 
as easily a bug in Kotti itself and I don't have the resources to debug 
issues in other projects.   Kotti developers should be pitching in here 
to do the work of extracting the code paths that Kotti is exercising 
that produces this otherwise not-yet-reproducible behavior into a 
demonstration of unexpected behavior directly against SQLAlchemy.


I'm improving our test suite by ensuring that result processors are 
fired off for all result proxy subtypes when caching is used as well and 
I will ensure the line of code you mention is exercised.  If I can 
reproduce your described issue at that level, then the bug will be 
located and fixed.   I'll keep you posted.





Regards,
Piotr Dobrogost



--
You received this message because you are subscribed to the Google Groups 
"sqlalchemy" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to sqlalchemy+unsubscr...@googlegroups.com.
To post to this group, send email to sqlalchemy@googlegroups.com.
Visit this group at https://groups.google.com/group/sqlalchemy.
For more options, visit https://groups.google.com/d/optout.

Re: [sqlalchemy] Bug in BufferedColumnResultProxy class?

2016-04-26 Thread Piotr Dobrogost 
On Tue, Apr 26, 2016 at 12:18 AM, Mike Bayer  wrote:
>
> On 04/25/2016 11:04 AM, Piotr Dobrogost wrote:
>>
>> Is caching using dogpile what you call "Query cache extension"? If so
>> we don't use it.
>
> this extension:
> http://docs.sqlalchemy.org/en/rel_1_0/orm/extensions/baked.html?highlight=baked#module-sqlalchemy.ext.baked

Ok. I see this being used in Kotti (the framework I use). For example
here 
https://github.com/Kotti/Kotti/blob/0d162332e369dedb1b4936935e43de89e9665f8e/kotti/resources.py#L812

> the stack trace shown here illustrates an INSERT statement in the context of
> an ORM flush, which does use the compiled_cache feature; so to that degree,
> this part of the puzzle makes sense.

I'm curious what in the log shows that we deal with "INSERT statement
in the context of an ORM flush"?

> However, in cx_oracle, an INSERT statement does not return rows there's no
> data to be returned; cursor.description should be None and the
> BufferredColumnResultProxy will not be used.An INSERT statement in
> Oracle that uses "RETURNING", as is usually the case for the ORM INSERT
> statement, uses OUT parameters to achieve this and will make use of the
> ReturningResultProxy to work around what's needed here.

Ok.

> Since we're working without a test case of any kind, are you sure that the
> result proxy indicating the problem is not a ReturningResultProxy ?   Are we
> dealing with a column that has a server-generated default value that is of
> type BLOB, CLOB, or similar ?

There is ReturningResultProxy in the call stack for example here
https://gist.github.com/piotr-dobrogost/6d57cacb9e77f59748353b2b6c1334d7#file-call-stack-while-executing-line-519-of-result-py-run-for-the-first-time-ever-during-app-startup-L58

and it's the type of "self" which I showed here

https://gist.github.com/piotr-dobrogost/6d57cacb9e77f59748353b2b6c1334d7#file-call-stack-while-executing-line-519-of-result-py-run-for-the-first-time-ever-during-app-startup-L74

It occurred to me that one can reproduce this rather easily installing
Kotti framework alone (or rather slightly modified version adjusted to
work with Oracle which you can find at
https://github.com/piotr-dobrogost/Kotti/tree/sfx). Kotti has
requirements.txt file where you can replace Kotti==1.3.0-alpha.4 with
git+https://github.com/piotr-dobrogost/Kotti.git@sfx and install
everything with `pip install --no-deps -r requirements.txt`. Running
is simple with `pserve development.ini` command (as Kotti is based on
Pyramid). Before running you have to edit development.ini and change
sqlalchemy.url to point to your Oracle db. When run Kotti creates and
populates db and when you try to access app at http://localhost:5000/
the error happens.


Regards,
Piotr Dobrogost

-- 
You received this message because you are subscribed to the Google Groups 
"sqlalchemy" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to sqlalchemy+unsubscr...@googlegroups.com.
To post to this group, send email to sqlalchemy@googlegroups.com.
Visit this group at https://groups.google.com/group/sqlalchemy.
For more options, visit https://groups.google.com/d/optout.

Re: [sqlalchemy] Bug in BufferedColumnResultProxy class?

2016-04-25 Thread Mike Bayer 



On 04/25/2016 11:04 AM, Piotr Dobrogost wrote:

On Mon, Apr 25, 2016 at 3:23 PM, Mike Bayer  wrote:


OK I can try to work with that but that's a very specific feature, you'd
need to be using the Query cache extension,


I have problem finding information on "Query cache extension".
Googling for  I get
http://docs.sqlalchemy.org/en/latest/orm/examples.html#module-examples.dogpile_caching
as the first result from SA's docs and
http://stackoverflow.com/questions/204918/does-sqlalchemy-support-caching
as the first result from Stackoverflow.

Is caching using dogpile what you call "Query cache extension"? If so
we don't use it.


this extension: 
http://docs.sqlalchemy.org/en/rel_1_0/orm/extensions/baked.html?highlight=baked#module-sqlalchemy.ext.baked








  or using the "compiled_cache"
option,


There's no "compiled_cache" string in Kotti framework so I guess we
don't use it.


option, *or* the error is being generated within the context of a Session
being flushed within an INSERT or UPDATE RETURNING statement, which itself I
don't think uses the traditional result set model in Oracle anyway.


It's hard to say. Right before printing call stack from line 519 of
result.py there's SELECT logged:


the stack trace shown here illustrates an INSERT statement in the 
context of an ORM flush, which does use the compiled_cache feature; so 
to that degree, this part of the puzzle makes sense.


However, in cx_oracle, an INSERT statement does not return rows there's 
no data to be returned; cursor.description should be None and the 
BufferredColumnResultProxy will not be used.An INSERT statement in 
Oracle that uses "RETURNING", as is usually the case for the ORM INSERT 
statement, uses OUT parameters to achieve this and will make use of the 
ReturningResultProxy to work around what's needed here.


Since we're working without a test case of any kind, are you sure that 
the result proxy indicating the problem is not a ReturningResultProxy ? 
  Are we dealing with a column that has a server-generated default 
value that is of type BLOB, CLOB, or similar ?








2016-04-25 16:36:02,954 INFO
[sqlalchemy.engine.base.Engine][waitress] SELECT nodes.id AS nodes_id,
nodes.type AS nodes_type, nodes.parent_id AS nodes_parent_id,
nodes.position AS nodes_position, nodes."_acl" AS nodes__acl,
nodes.name AS nodes_name, nodes.title AS nodes_title,
nodes.annotations AS nodes_annotations, nodes.path AS nodes_path
FROM nodes LEFT OUTER JOIN contents ON nodes.id = contents.id LEFT
OUTER JOIN documents ON contents.id = documents.id LEFT OUTER JOIN
files ON contents.id = files.id LEFT OUTER JOIN images ON contents.id
= images.id
WHERE nodes.parent_id IS NULL

and right before the traceback is printed there's rollback being logged:
2016-04-25 16:36:02,975 INFO  [sqlalchemy.engine.base.Engine][waitress] ROLLBACK

however I don't know if it answers your last question.


any of these true for your case ?  Looks like you haven't provided a stack
trace for your issue, I'm sure you have that, so send that along.


Please find all information at
https://gist.github.com/piotr-dobrogost/6d57cacb9e77f59748353b2b6c1334d7
Probably you are most interested in the raw log (file named "Full log
from the start of the application (with empty db)"). Please note that
I modified line 519 in result.py by inserting the following code:
import traceback; traceback.print_stack();
to get call stack at this moment of execution.
Also the nature of the bug is such that there's no information in the
log about original problem (not executing some processors which were
registered and executed earlier). I'm guessing there are scopes during
which one should not modify the list of registered processors. If it
happens that this list (as a consequence of this bug) is being cleared
while one of such scopes that it would be awesome if SA could somehow
notice that the list of processors was changed in some scope where it
should be left intact and log warning or raise hard error. This way
the reason for error would be much easier to find in this case and
probably also in future.


Regards,
Piotr Dobrogost



--
You received this message because you are subscribed to the Google Groups 
"sqlalchemy" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to sqlalchemy+unsubscr...@googlegroups.com.
To post to this group, send email to sqlalchemy@googlegroups.com.
Visit this group at https://groups.google.com/group/sqlalchemy.
For more options, visit https://groups.google.com/d/optout.

Re: [sqlalchemy] Bug in BufferedColumnResultProxy class?

2016-04-25 Thread Piotr Dobrogost 
On Mon, Apr 25, 2016 at 3:23 PM, Mike Bayer  wrote:
>
> OK I can try to work with that but that's a very specific feature, you'd
> need to be using the Query cache extension,

I have problem finding information on "Query cache extension".
Googling for  I get
http://docs.sqlalchemy.org/en/latest/orm/examples.html#module-examples.dogpile_caching
as the first result from SA's docs and
http://stackoverflow.com/questions/204918/does-sqlalchemy-support-caching
as the first result from Stackoverflow.

Is caching using dogpile what you call "Query cache extension"? If so
we don't use it.

>  or using the "compiled_cache"
> option,

There's no "compiled_cache" string in Kotti framework so I guess we
don't use it.

> option, *or* the error is being generated within the context of a Session
> being flushed within an INSERT or UPDATE RETURNING statement, which itself I
> don't think uses the traditional result set model in Oracle anyway.

It's hard to say. Right before printing call stack from line 519 of
result.py there's SELECT logged:
2016-04-25 16:36:02,954 INFO
[sqlalchemy.engine.base.Engine][waitress] SELECT nodes.id AS nodes_id,
nodes.type AS nodes_type, nodes.parent_id AS nodes_parent_id,
nodes.position AS nodes_position, nodes."_acl" AS nodes__acl,
nodes.name AS nodes_name, nodes.title AS nodes_title,
nodes.annotations AS nodes_annotations, nodes.path AS nodes_path
FROM nodes LEFT OUTER JOIN contents ON nodes.id = contents.id LEFT
OUTER JOIN documents ON contents.id = documents.id LEFT OUTER JOIN
files ON contents.id = files.id LEFT OUTER JOIN images ON contents.id
= images.id
WHERE nodes.parent_id IS NULL

and right before the traceback is printed there's rollback being logged:
2016-04-25 16:36:02,975 INFO  [sqlalchemy.engine.base.Engine][waitress] ROLLBACK

however I don't know if it answers your last question.

> any of these true for your case ?  Looks like you haven't provided a stack
> trace for your issue, I'm sure you have that, so send that along.

Please find all information at
https://gist.github.com/piotr-dobrogost/6d57cacb9e77f59748353b2b6c1334d7
Probably you are most interested in the raw log (file named "Full log
from the start of the application (with empty db)"). Please note that
I modified line 519 in result.py by inserting the following code:
import traceback; traceback.print_stack();
to get call stack at this moment of execution.
Also the nature of the bug is such that there's no information in the
log about original problem (not executing some processors which were
registered and executed earlier). I'm guessing there are scopes during
which one should not modify the list of registered processors. If it
happens that this list (as a consequence of this bug) is being cleared
while one of such scopes that it would be awesome if SA could somehow
notice that the list of processors was changed in some scope where it
should be left intact and log warning or raise hard error. This way
the reason for error would be much easier to find in this case and
probably also in future.


Regards,
Piotr Dobrogost

-- 
You received this message because you are subscribed to the Google Groups 
"sqlalchemy" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to sqlalchemy+unsubscr...@googlegroups.com.
To post to this group, send email to sqlalchemy@googlegroups.com.
Visit this group at https://groups.google.com/group/sqlalchemy.
For more options, visit https://groups.google.com/d/optout.

Re: [sqlalchemy] Bug in BufferedColumnResultProxy class?

2016-04-25 Thread Mike Bayer 



On 04/25/2016 05:49 AM, Piotr Dobrogost wrote:

On Friday, April 22, 2016 at 5:22:38 PM UTC+2, Mike Bayer wrote:


On 04/22/2016 10:40 AM, Piotr Dobrogost wrote:
 > It seems BufferedColumnResultProxy class (used only in Oracle
dialect)
 > has a bug.

I cannot confirm it, would need a test case.  Here's one that is
extremely simple but exercises the features you describe.   I have no
doubt that what you're seeing is a bug however so I'd need to know what
to add to this test to illustrate the issue:


Thanks for quick response and creation of sample code. We have trouble
adding something that would trigger bug as we don't fully understand
source code of SA and in addition we use other framework (Kotti) which
adds its layer of complexity. Having said that we think that what's
needed to reproduce bug is to modify your test case so that line 519 in
result.py would get hit
(https://github.com/zzzeek/sqlalchemy/blob/rel_1_0_12/lib/sqlalchemy/engine/result.py#L519).


OK I can try to work with that but that's a very specific feature, you'd 
need to be using the Query cache extension, or using the 
"compiled_cache" option, *or* the error is being generated within the 
context of a Session being flushed within an INSERT or UPDATE RETURNING 
statement, which itself I don't think uses the traditional result set 
model in Oracle anyway.   Are any of these true for your case ?  Looks 
like you haven't provided a stack trace for your issue, I'm sure you 
have that, so send that along.







There is no need for you or your developers to attempt to debug deep
issues like these; I can identify them within minutes given a
demonstration of the behavior and I am glad to do this work once an
incorrect behavior is demonstrated.


Thank you very much for offering your help.

The work that you need to do when you encounter stack traces like this
is to isolate the behavior into a simple test case, such as the one I
have above.Using the "divide and conquer" approach, where you begin
with your whole application, then slowly remove pieces of it that
continue to exhibit the bad behavior until you have something entirely
minimal.  The guidelines that I often refer to at
http://stackoverflow.com/help/mcve
 have an excellent description
of this.


Sure thing. The problem in practice is that in order to create "simple
test case" it's often needed to get good understanding of used libraries
at the source code level. The good example is your sample test case
which we don't know how to modify in spite of the fact that we suspect
which specific line needs to be hit.


Regards,
Piotr Dobrogost

--
You received this message because you are subscribed to the Google
Groups "sqlalchemy" group.
To unsubscribe from this group and stop receiving emails from it, send
an email to sqlalchemy+unsubscr...@googlegroups.com
.
To post to this group, send email to sqlalchemy@googlegroups.com
.
Visit this group at https://groups.google.com/group/sqlalchemy.
For more options, visit https://groups.google.com/d/optout.


--
You received this message because you are subscribed to the Google Groups 
"sqlalchemy" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to sqlalchemy+unsubscr...@googlegroups.com.
To post to this group, send email to sqlalchemy@googlegroups.com.
Visit this group at https://groups.google.com/group/sqlalchemy.
For more options, visit https://groups.google.com/d/optout.

Re: [sqlalchemy] Bug in BufferedColumnResultProxy class?

2016-04-25 Thread Piotr Dobrogost 
On Friday, April 22, 2016 at 5:22:38 PM UTC+2, Mike Bayer wrote:
>
>
> On 04/22/2016 10:40 AM, Piotr Dobrogost wrote: 
> > It seems BufferedColumnResultProxy class (used only in Oracle dialect) 
> > has a bug. 
>
 

> I cannot confirm it, would need a test case.  Here's one that is 
> extremely simple but exercises the features you describe.   I have no 
> doubt that what you're seeing is a bug however so I'd need to know what 
> to add to this test to illustrate the issue: 
>

Thanks for quick response and creation of sample code. We have trouble 
adding something that would trigger bug as we don't fully understand source 
code of SA and in addition we use other framework (Kotti) which adds its 
layer of complexity. Having said that we think that what's needed to 
reproduce bug is to modify your test case so that line 519 in result.py 
would get hit 
(https://github.com/zzzeek/sqlalchemy/blob/rel_1_0_12/lib/sqlalchemy/engine/result.py#L519).

There is no need for you or your developers to attempt to debug deep 
> issues like these; I can identify them within minutes given a 
> demonstration of the behavior and I am glad to do this work once an 
> incorrect behavior is demonstrated. 
>

Thank you very much for offering your help. 

The work that you need to do when you encounter stack traces like this 
> is to isolate the behavior into a simple test case, such as the one I 
> have above.Using the "divide and conquer" approach, where you begin 
> with your whole application, then slowly remove pieces of it that 
> continue to exhibit the bad behavior until you have something entirely 
> minimal.  The guidelines that I often refer to at 
> http://stackoverflow.com/help/mcve have an excellent description of this. 
>

Sure thing. The problem in practice is that in order to create "simple test 
case" it's often needed to get good understanding of used libraries at the 
source code level. The good example is your sample test case which we don't 
know how to modify in spite of the fact that we suspect which specific line 
needs to be hit.


Regards,
Piotr Dobrogost

-- 
You received this message because you are subscribed to the Google Groups 
"sqlalchemy" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to sqlalchemy+unsubscr...@googlegroups.com.
To post to this group, send email to sqlalchemy@googlegroups.com.
Visit this group at https://groups.google.com/group/sqlalchemy.
For more options, visit https://groups.google.com/d/optout.

[sqlalchemy] Bug in BufferedColumnResultProxy class?

2016-04-22 Thread Piotr Dobrogost 
It seems BufferedColumnResultProxy class (used only in Oracle dialect) has 
a bug.

_init_metadata() method defined at 
https://github.com/zzzeek/sqlalchemy/blob/rel_1_0_12/lib/sqlalchemy/engine/result.py#L1238
is being called even for already cached data (that's probably bug) and 
because this method clears a list of processors (metadata._processors = 
[None for _ in range(len(metadata.keys))]) the list of original processors 
(metadata._orig_processors) gets cleared the second time _init_metadata() 
method is called. The end result is that column's value is not being 
processed to proper Python type from the db original type and one gets 
errors like:

File 
"/home/piotr/.virtualenvs/kotti/lib/python2.7/site-packages/sqlalchemy/ext/mutable.py",
 
line 403, in coerce
raise ValueError(msg % (key, type(value)))
ValueError: Attribute '_acl' does not accept objects of type 

Whole traceback is available at http://pastebin.com/Ssui33XC

Guarding method's body after line L1240 with "if not hasattr(metadata, 
'_orig_processors'):" solves the problem but it's neither pretty nor it's 
the right solution. The right solution is probably to not call 
_init_metadata() method on cached data at all.

I'd appreciate if someone with good understanding of SA internals could 
take a look and confirm (better yet fix) this bug. I have to admit it took 
a top notch developer a couple of hours of debugging to go through much of 
SA code and establish the root cause of this problem.

I'm going to raise issue on tracker as soon as someone confirms this bug.

Best regards,
Piotr Dobrogost

-- 
You received this message because you are subscribed to the Google Groups 
"sqlalchemy" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to sqlalchemy+unsubscr...@googlegroups.com.
To post to this group, send email to sqlalchemy@googlegroups.com.
Visit this group at https://groups.google.com/group/sqlalchemy.
For more options, visit https://groups.google.com/d/optout.