Psycopg psycopg

Comments and changes to this ticket

• 

  Daniele Varrazzo September 18th, 2012 @ 12:14 PM

  Attached proposed patch to fix the issue

  • zope-pool.patch 748 Bytes
• 

  Federico Di Gregorio September 18th, 2012 @ 12:18 PM

  Zope has its own transaction management: like any sensible web framework the transaction is rolled back on errors, and commited just before sending the HTTP response. You don't want to ROLLBACK on a Zope connection. Peraphs we can have a specialized pool that doesn't ROLLBACK while keeping the fix for #62 in?

• 

  Daniele Varrazzo September 18th, 2012 @ 12:32 PM

  An optional solution would be to replace entirely PersistentConnectionPool.putconn and not invoke _putconn, but it leads to some code duplication.

  For me, any solution is fine, but because I just don't know how to test it, I'm happy to get the report "patch X is working" (for any X, this or any other one) and do with it.

• You flagged this item as spam.
  

  Wolfgang Eibner September 18th, 2012 @ 05:06 PM

  Hm, after some quick investigation I think the problem is located at another place. Your patched block gets never called cause get_transaction_status() returns 0 on every one of the Zope connections at putting them back into the pool.

  I get the following statement logs:

  2012-09-18 18:21:48 CEST 5619 1121366 LOG: Anweisung: SHOW default_transaction_isolation
  2012-09-18 18:21:48 CEST 5619 1121367 LOG: Anweisung: SET default_transaction_isolation TO 'repeatable read'
  2012-09-18 18:21:48 CEST 5619 1121368 LOG: Anweisung: SET client_encoding TO 'UTF8'

  2012-09-18 18:21:56 CEST 5619 1121369 LOG: Anweisung: SHOW default_transaction_isolation
  2012-09-18 18:21:56 CEST 5619 1121370 LOG: Anweisung: SET client_encoding TO 'UTF8'
  2012-09-18 18:21:56 CEST 5619 1121371 LOG: Anweisung: BEGIN
  2012-09-18 18:21:56 CEST 5619 1121371 LOG: Anweisung: update kontaktnummer set zopedate=now() where idkontakt = 12297;

  2012-09-18 18:22:00 CEST 5619 1121371 LOG: Anweisung: SHOW default_transaction_isolation
  2012-09-18 18:22:00 CEST 5619 1121371 LOG: Anweisung: ROLLBACK
  2012-09-18 18:22:00 CEST 5619 1121372 LOG: Anweisung: SET client_encoding TO 'UTF8'
  2012-09-18 18:22:00 CEST 5619 1121373 LOG: Anweisung: BEGIN
  2012-09-18 18:22:00 CEST 5619 1121373 LOG: Anweisung: select * from kontaktnummer where idkontakt = 12297;
  2012-09-18 18:22:04 CEST 5619 1121373 LOG: Anweisung: COMMIT

  BTW: Why is the default transaction isolation level repeatable read although serializable is checked in the ZPsycopgDA?

  After implementing some debug prints in the python code I found out, that the three lines
  2012-09-18 18:22:00 CEST 5619 1121371 LOG: Anweisung: SHOW default_transaction_isolation
  2012-09-18 18:22:00 CEST 5619 1121371 LOG: Anweisung: ROLLBACK
  2012-09-18 18:22:00 CEST 5619 1121372 LOG: Anweisung: SET client_encoding TO 'UTF8'
  occur when retrieving a connection from the pool with _getconn.

  As far as I can see (without further debugging) the rollback happens in connection_int.c at line 1155 (after / abort the current transaction, to set the encoding ouside of transactions /). So, while Zope retrieves the connection (which still has a transaction open) from the pool or before the next statement is executed (?), the encoding is set by psycopg. But this should be done outside transactions and so a rollback is issued.

  I simply tried a return 0; at the beginning of conn_set_client_encoding and with that modification everything looks fine:

  2012-09-18 19:00:11 CEST 5888 1121832 LOG: Anweisung: SHOW default_transaction_isolation
  2012-09-18 19:00:11 CEST 5888 1121833 LOG: Anweisung: SET default_transaction_isolation TO 'repeatable read'
  2012-09-18 19:00:11 CEST 5888 1121834 LOG: Anweisung: SHOW default_transaction_isolation
  2012-09-18 19:00:11 CEST 5888 1121835 LOG: Anweisung: BEGIN
  2012-09-18 19:00:11 CEST 5888 1121835 LOG: Anweisung: update kontaktnummer set zopedate=now() where idkontakt = 12297;
  2012-09-18 19:00:11 CEST 5888 1121835 LOG: Anweisung: SHOW default_transaction_isolation
  2012-09-18 19:00:11 CEST 5888 1121835 LOG: Anweisung: select * from kontaktnummer where idkontakt = 12297;
  2012-09-18 19:00:11 CEST 5888 1121835 LOG: Anweisung: COMMIT

  Of course this is no patch but maybe it helps you to fix the problem ;-)

• 

  Daniele Varrazzo September 18th, 2012 @ 05:25 PM

  Thank you for the analysis, Wolfgang.

  As you describe it, seems that most of the mess happens in ZPsycopgDA/db.py

  • inconsistent isolation level
  • resetting the client_encoding

  Looks like there is code dealing with not trying to re-init an already init'ed connection, maybe somehow it's not doing what it should. rolling back the connection before setting the client encoding is something has always happened.

  Can you take a look there?

  Thank you very much.

• You flagged this item as spam.
  

  Wolfgang Eibner September 19th, 2012 @ 12:45 PM

  Regarding the isolation level:

  In ZPsycopgDA/dtml/edit.dtml serializable is referenced as value 2 (but it has 4):
  <option value="2"

              <dtml-if expr="tilevel==2">selected="YES"</dtml-if>>
      Serializable</option>
  

  Like mentioned here (of course autocommit is no isolation level):
  http://technobabble.afccommercial.co.uk/technobabble/zpsycopgda-and...

  BUT:
  At my postgresql database (version 8.2) the mapping is as following:
  1 results in "SET default_transaction_isolation TO DEFAULT" (read committed?) 2 results in no log statement (isolation level not set or equal to default?) 3 results in "SET default_transaction_isolation TO 'repeatable read'" 4 results in "SET default_transaction_isolation TO 'serializable'" 5 results in "SET default_transaction_isolation TO 'read uncommitted'"

  for my case I need serializable and so I've to change the value to 4. But I don't know which would be the right value for read committed (1 or 2?) cause I don't know the postgres api.

  Regarding the client_encoding: I'll debug that later.

• You flagged this item as spam.
  

  Wolfgang Eibner September 19th, 2012 @ 12:48 PM

  Sorry for the bad formatting and there was also an error:

  At my postgresql database (version 8.2) the mapping is as following:

  • 0 results in "SET default_transaction_isolation TO DEFAULT" (read committed?)
  • 1 results in no log statement (isolation level not set or equal to default?)
  • 2 results in "SET default_transaction_isolation TO 'repeatable read'"
  • 3 results in "SET default_transaction_isolation TO 'serializable'"
  • 4 results in "SET default_transaction_isolation TO 'read uncommitted'"

  for my case I need serializable and so I've to change the value to 3. But I don't know which would be the right value for read committed (1 or 2?) cause I don't know the postgres api.

• 

  Daniele Varrazzo September 19th, 2012 @ 02:01 PM

  Oh, I see. In PG the serializable and repeatable read used to be the same, since 9.0 iirc serializable became stronger and the previous semantics is available as repeatable read. So in PG serializable now requires value 3. Actually the story is slightly different resulting in some rants, a few buggy versions and probably some grief at Skype... let's say that now it's this way :)

  So, these options in add.dtml are out of date respect to the ISOLATION_LEVEL_* constants available in extensions.py.

  Psycopg is also changed in another way since ZPsycopgDA was implemented: it used to query the server for the the default level and re-issue it at every begin, resulting in a query mostly useless at connection time. The best thing would be to add another option to that menu: "default", which is whatever the server defines, and which results in no query performed neither to know the default nor to set the isolevel. This is usually "read committed" but can be set in the server config file.

  The article you have linked is right. Too bad the author is a total moron has never contacted us to report the bug. What a shit attitude! Also, comments on his site are broken and there's no email link nor even a name to contact him... Who the hell is he?

  To that list I'd add a "default" value, for instance an empty string or -1, whatever, meaning "just don't set the isolation level and let the server deal with it".

  Also, db.py should be implemented using set_session instead of set_isolation_level, so that no "SHOW default_transaction_isolation" is performed.

  So, the bugs here are:
  - add.dtml should be consistent with the constants in extensions.py - db.py should use set_session(isolation_level=...) instead of set_isolation_level. set_session should not be invoked if the level chosen is "default". - note that using set_session you could also add "readonly" to the connection configuration - client_encoding should be set only once (likely bug in db.py) - and then maybe we can arrive to the bug in the pool.

  In the resulting communication sequence, there should be no "SHOW default_transaction_isolation", only one "SET default_transaction_isolation to LEVEL" (unless the level chosen is DEFAULT), only one SET client_encoding TO 'UTF8', no spurious rollback.

  Can you help fixing this mess? Thank you.

• 

  Daniele Varrazzo September 20th, 2012 @ 02:43 PM

  I've fixed the menu for add/edit pages showing all the available isolation level. Note that the default is "repeatable read" because in postgres 9.1 serializable has changed becoming something stricter than before. In previous pg version "repeatable read" and "serializable" are aliases.

  I've also fixed db.py so that "SHOW default_transaction_isolation" is not queried anymore; anyway that's not what is causing your problem.

  These corrections are available in my "zope-pool" branch https://github.com/dvarrazzo/psycopg/tree/zope-pool

  As I see it, just looking at the code statically, the problem is caused by DB.getcursor() being called twice, once before your "insert" the other before your "select". This in turn causes getconn with init=True twice, which calls the set_client_encoding() which issues a rollback. It should be easy to verify it with a couple of prints, but I don't know how to setup such a zope page.

• You flagged this item as spam.
  

  Wolfgang Eibner September 22nd, 2012 @ 08:32 PM

  Hi,

  it will take me some time to test/fix this because I'll be not at the office till Thursday and I'm very busy at the moment.

  Best regards,
  Wolfgang

• 

  Daniele Varrazzo December 3rd, 2012 @ 12:26 AM

  • State changed from “new” to “resolved”

  I've fixed the pool by adding a zope-specific implementation of the base pool copied from Psycopg 2.4.

  the reset upon set_client_encoding is still there, but it has always been. If it is an issue you will have to provide a solution yourself, as I'm not able to set up a test page to reproduce it.