Problem with Zope 2.13.15, python 2.6.6 psycopg2-2.4.5, pg 9.0.3

Hi,

it is impossible to INSERT or UPDATE with ZSQL from external methods. The first
statement after a INSERT/UPDATE ends with an ROLLBACK.

Example:
2012-08-03 14:58:16.821 CEST [14542][501bca30.38ce][0] pre2(at)4com20110627_utf8
LOG: statement: BEGIN
2012-08-03 14:58:16.821 CEST [14542][501bca30.38ce][0]
pre2(at)4com20110627_utf8 LOG: duration: 0.021 ms
2012-08-03 14:58:16.821 CEST [14542][501bca30.38ce][0] pre2(at)4com20110627_utf8
LOG: statement: update ADRE set modified_at= '120803145816', modified_by_user=
'l.steinborn@', modified_by_meth= 'update_IndiAdre', mail1 =
'l(dot)steinborn(at)4c-ag(dot)de', /* Individuum.py (3) */ FirstName = 'Lutz', Last_entry
= '0001~000000000000' /* Serge.py (1) */ where login = '*******' AND password =
'******' AND Mail1 = 'l(dot)steinborn(at)4c-ag(dot)de'
2012-08-03 14:58:16.822 CEST [14542] [501bca30.38ce][0] pre2(at)4com20110627_utf8
LOG: duration: 0.273 ms
2012-08-03 14:58:16.823 CEST [14542][501bca30.38ce][0] pre2(at)4com20110627_utf8
LOG: statement: SHOW default_transaction_isolation
2012-08-03 14:58:16.823 CEST [14542] [501bca30.38ce][0] pre2(at)4com20110627_utf8
LOG: duration: 0.034 ms
2012-08-03 14:58:16.823 CEST [14542][501bca30.38ce][0] pre2(at)4com20110627_utf8
LOG: statement: ROLLBACK

Any idea whats going on?

--
Lutz

We had the exact same problem with psycopg2/zope2.10/pg9 but could not
find a satisfactory solution.

There are no problems with psycopg1 apart from it being old and
unsupported :)

Rich

Richard Harley
Technical Director
(0044) 01522 837264 | http://www.scholarpack.com

On 03/08/12 14:33, Lutz Steinborn wrote:
> Hi,
>
> it is impossible to INSERT or UPDATE with ZSQL from external methods. The first
> statement after a INSERT/UPDATE ends with an ROLLBACK.
>
> Example:
> 2012-08-03 14:58:16.821 CEST [14542][501bca30.38ce][0] pre2(at)4com20110627_utf8
> LOG: statement: BEGIN
> 2012-08-03 14:58:16.821 CEST [14542][501bca30.38ce][0]
> pre2(at)4com20110627_utf8 LOG: duration: 0.021 ms
> 2012-08-03 14:58:16.821 CEST [14542][501bca30.38ce][0] pre2(at)4com20110627_utf8
> LOG: statement: update ADRE set modified_at= '120803145816', modified_by_user=
> 'l.steinborn@', modified_by_meth= 'update_IndiAdre', mail1 =
> 'l(dot)steinborn(at)4c-ag(dot)de', /* Individuum.py (3) */ FirstName = 'Lutz', Last_entry
> = '0001~000000000000' /* Serge.py (1) */ where login = '*******' AND password =
> '******' AND Mail1 = 'l(dot)steinborn(at)4c-ag(dot)de'
> 2012-08-03 14:58:16.822 CEST [14542] [501bca30.38ce][0] pre2(at)4com20110627_utf8
> LOG: duration: 0.273 ms
> 2012-08-03 14:58:16.823 CEST [14542][501bca30.38ce][0] pre2(at)4com20110627_utf8
> LOG: statement: SHOW default_transaction_isolation
> 2012-08-03 14:58:16.823 CEST [14542] [501bca30.38ce][0] pre2(at)4com20110627_utf8
> LOG: duration: 0.034 ms
> 2012-08-03 14:58:16.823 CEST [14542][501bca30.38ce][0] pre2(at)4com20110627_utf8
> LOG: statement: ROLLBACK
>
> Any idea whats going on?
>
>

On Fri, Aug 3, 2012 at 2:42 PM, Richard Harley <richard(at)scholarpack(dot)com> wrote:
> We had the exact same problem with psycopg2/zope2.10/pg9 but could not find
> a satisfactory solution.
>
> There are no problems with psycopg1 apart from it being old and unsupported
> :)

Sorry, I missed these messages. The problem is probably in the pool
rolling back open transactions since psycopg 2.4.3.

I need some help with testing this issue: ok for you to test some
patch I will provide?

Thank you.

-- Daniele

On Tue, Sep 18, 2012 at 12:53 PM, Daniele Varrazzo
<daniele(dot)varrazzo(at)gmail(dot)com> wrote:
> On Fri, Aug 3, 2012 at 2:42 PM, Richard Harley <richard(at)scholarpack(dot)com> wrote:
>> We had the exact same problem with psycopg2/zope2.10/pg9 but could not find
>> a satisfactory solution.
>>
>> There are no problems with psycopg1 apart from it being old and unsupported
>> :)
>
> Sorry, I missed these messages. The problem is probably in the pool
> rolling back open transactions since psycopg 2.4.3.
>
> I need some help with testing this issue: ok for you to test some
> patch I will provide?

So, here it is. The patch attached assumes zope always uses
psycopg.pool.PersistentConnectionPool or its subclasses: is this the
case?

Can you please test:

1. what happens with regular pages that got broken as in the provided
case? Desired result is that everything works as expected.

2. what happens with pages making an error? Desired result is
eventually an error in the page but further pages generated correctly.

3. what happens if the database is restarted? Desired result is
eventually an error in the first page loaded but further pages
generated correctly (the pool should restore the connection).

Thank you very much.

-- Daniele

On Tue, Sep 18, 2012 at 1:08 PM, Daniele Varrazzo
<daniele(dot)varrazzo(at)gmail(dot)com> wrote:
> On Tue, Sep 18, 2012 at 12:53 PM, Daniele Varrazzo
> <daniele(dot)varrazzo(at)gmail(dot)com> wrote:
>> On Fri, Aug 3, 2012 at 2:42 PM, Richard Harley <richard(at)scholarpack(dot)com> wrote:
>>> We had the exact same problem with psycopg2/zope2.10/pg9 but could not find
>>> a satisfactory solution.
>>>
>>> There are no problems with psycopg1 apart from it being old and unsupported
>>> :)
>>
>> Sorry, I missed these messages. The problem is probably in the pool
>> rolling back open transactions since psycopg 2.4.3.
>>
>> I need some help with testing this issue: ok for you to test some
>> patch I will provide?
>
> So, here it is. The patch attached assumes zope always uses
> psycopg.pool.PersistentConnectionPool or its subclasses: is this the
> case?
>
> Can you please test:
>
> 1. what happens with regular pages that got broken as in the provided
> case? Desired result is that everything works as expected.
>
> 2. what happens with pages making an error? Desired result is
> eventually an error in the page but further pages generated correctly.
>
> 3. what happens if the database is restarted? Desired result is
> eventually an error in the first page loaded but further pages
> generated correctly (the pool should restore the connection).
>
> Thank you very much.

From analysis performed by Wolfgang Eibner in ticket #125, I suspect
something broke when ticket #73 was fixed and doesn't involve the pool
(although the pool rolling back the connection would still cause
problems).

If this is the case, the source of the problems is to be found in
ZPsycopgDA/db.py, in DB.getconn.

Any help to fix the issue would be appreciated.

-- Daniele

On 18/09/2012 20:13, Daniele Varrazzo wrote:
>> > 1. what happens with regular pages that got broken as in the provided
>> > case? Desired result is that everything works as expected.
>> >
>> > 2. what happens with pages making an error? Desired result is
>> > eventually an error in the page but further pages generated correctly.
>> >
>> > 3. what happens if the database is restarted? Desired result is
>> > eventually an error in the first page loaded but further pages
>> > generated correctly (the pool should restore the connection).
>> >
>> > Thank you very much.
> From analysis performed by Wolfgang Eibner in ticket #125, I suspect
> something broke when ticket #73 was fixed and doesn't involve the pool
> (although the pool rolling back the connection would still cause
> problems).
>
> If this is the case, the source of the problems is to be found in
> ZPsycopgDA/db.py, in DB.getconn.
>
> Any help to fix the issue would be appreciated.

I'll have a look at this. Just need to install Zope even if I sweared
I'd never do that again. ;)

federico

--
Federico Di Gregorio federico(dot)digregorio(at)dndg(dot)it
Studio Associato Di Nunzio e Di Gregorio http://dndg.it
I came like Water, and like Wind I go. -- Omar Khayam