A very strange freeze - Mailing list psycopg

Hi there!

 

I've faced with a very strange problem on my Linux-server (Linux [hostname] 3.0.4-2-lxcna x86_64 GNU/Linux).

Some of queries freezes. Even so simple like "select * from reports".

 

At first I got the latest version of psycopg2 and build it in debug mode.

 

Here is a piese of an output:

 

[7321] psyco_connect: dsn = 'dbname=***** user=***** password=***** host=*****', async = 0
[7321] connection_setup: init connection object at 0xf53cd0, async 0, refcnt = 1
[7321] con_connect: connecting in SYNC mode
[7321] conn_connect: new postgresql connection at 0xf18300
[7321] conn_connect: server standard_conforming_strings parameter: off
[7321] conn_connect: server requires E'' quotes: YES
[7321] conn_connect: using protocol 3
[7321] conn_connect: client encoding: UTF8
[7321] clear_encoding_name: UTF8 -> UTF8
[7321] conn_connect: DateStyle ISO, MDY
[7321] connection_setup: good connection object at 0xf53cd0, refcnt = 1
[7321] psyco_conn_cursor: new cursor for connection at 0xf53cd0
[7321] psyco_conn_cursor:     parameters: name = (null)
[7321] cursor_setup: init cursor object at 0x7f58cd6d4338
[7321] cursor_setup: parameters: name = (null), conn = 0xf53cd0
[7321] cursor_setup: good cursor object at 0x7f58cd6d4338, refcnt = 1
[7321] psyco_conn_cursor: new cursor at 0x7f58cd6d4338: refcnt = 1
[7321] psyco_curs_execute: starting execution of new query
[7321] curs_execute: pg connection at 0xf18300 OK
[7321] pq_begin_locked: pgconn = 0xf18300, autocommit = 1, status = 1
[7321] pq_begin_locked: transaction in progress
[7321] pq_execute: executing SYNC query: pgconn = 0xf18300
[7321]     select * from reports

 

[freeze]

 

script is realy very simple:

 

import psycopg2
connection = psycopg2.connect(database="*****", host="*****", user="*****", password="******")
connection.autocommit = True
cursor = connection.cursor()
q = "select * from reports"
cursor.execute(q)
print cursor.fetchall()

 

After a few minutes of frustration I started TCP-dump and executed the script again. Then compared it with tcpdump output of my 32-bit Ubuntu desktop and something seemed to be strange.

 

Here is output from my hosting:

 

$ tcpdump -X -s0 -r bad_query

[greetings]

[auth]

08:45:40.342613 IP pg-server > frontend-server.49753: Flags [P.], seq 15:339, ack 94, win 5, length 324
        0x0000:  4500 016c 2bf2 0000 4006 fb7d b29a f69c  E..l+...@..}....
        0x0010:  b29a f64a 1538 c259 3635 50c9 c9ab 13ff  ...J.8.Y65P.....
        0x0020:  5018 0005 e1a3 0000 5200 0000 0800 0000  P.......R.......
        0x0030:  0053 0000 0016 6170 706c 6963 6174 696f  .S....applicatio
        0x0040:  6e5f 6e61 6d65 0000 5300 0000 1963 6c69  n_name..S....cli
        0x0050:  656e 745f 656e 636f 6469 6e67 0055 5446  ent_encoding.UTF
        0x0060:  3800 5300 0000 1744 6174 6553 7479 6c65  8.S....DateStyle
        0x0070:  0049 534f 2c20 4d44 5900 5300 0000 1969  .ISO,.MDY.S....i
        0x0080:  6e74 6567 6572 5f64 6174 6574 696d 6573  nteger_datetimes
        0x0090:  006f 6e00 5300 0000 1b49 6e74 6572 7661  .on.S....Interva
        0x00a0:  6c53 7479 6c65 0070 6f73 7467 7265 7300  lStyle.postgres.
        0x00b0:  5300 0000 1569 735f 7375 7065 7275 7365  S....is_superuse
        0x00c0:  7200 6f66 6600 5300 0000 1973 6572 7665  r.off.S....serve
        0x00d0:  725f 656e 636f 6469 6e67 0055 5446 3800  r_encoding.UTF8.
        0x00e0:  5300 0000 1973 6572 7665 725f 7665 7273  S....server_vers
        0x00f0:  696f 6e00 392e 302e 3400 5300 0000 2673  ion.9.0.4.S...&s
        0x0100:  6573 7369 6f6e 5f61 7574 686f 7269 7a61  ession_authoriza
        0x0110:  7469 6f6e 0062 7265 616b 7061 645f 7277  tion.breakpad_rw
        0x0120:  0053 0000 0024 7374 616e 6461 7264 5f63  .S...$standard_c
        0x0130:  6f6e 666f 726d 696e 675f 7374 7269 6e67  onforming_string
        0x0140:  7300 6f66 6600 5300 0000 1254 696d 655a  s.off.S....TimeZ
        0x0150:  6f6e 6500 572d 5355 004b 0000 000c 0000  one.W-SU.K......
        0x0160:  0c2d 4a8a aa52 5a00 0000 0549            .-J..RZ....I
08:45:40.342761 IP frontend-server.49753 > pg-server.postgresql: Flags [P.], seq 94:105, ack 339, win 5, length 11
        0x0000:  4500 0033 1445 0000 4006 1464 b29a f64a  E..3.E..@..d...J
        0x0010:  b29a f69c c259 1538 c9ab 13ff 3635 520d  .....Y.8....65R.
        0x0020:  5018 0005 3649 0000 5100 0000 0a42 4547  P...6I..Q....BEG
        0x0030:  494e 00                                  IN.
08:45:40.343188 IP pg-server.postgresql > frontend-server.49753: Flags [P.], seq 339:356, ack 105, win 5, length 17
        0x0000:  4500 0039 2bf3 0000 4006 fcaf b29a f69c  E..9+...@.......
        0x0010:  b29a f64a 1538 c259 3635 520d c9ab 140a  ...J.8.Y65R.....
        0x0020:  5018 0005 efd8 0000 4300 0000 0a42 4547  P.......C....BEG
        0x0030:  494e 005a 0000 0005 54                   IN.Z....T
08:45:40.343241 IP frontend-server.49753 > pg-server.postgresql: Flags [P.], seq 105:132, ack 356, win 5, length 27
        0x0000:  4500 0043 1446 0000 4006 1453 b29a f64a  E..C.F..@..S...J
        0x0010:  b29a f69c c259 1538 c9ab 140a 3635 521e  .....Y.8....65R.
        0x0020:  5018 0005 0bc9 0000 5100 0000 1a73 656c  P.......Q....sel
        0x0030:  6563 7420 2a20 6672 6f6d 2072 6570 6f72  ect.*.from.repor
        0x0040:  7473 00                                  ts.
08:45:40.545206 IP frontend-server.49753 > pg-server.postgresql: Flags [P.], seq 105:132, ack 356, win 5, length 27
        0x0000:  4500 0043 1447 0000 4006 1452 b29a f64a  E..C.G..@..R...J
        0x0010:  b29a f69c c259 1538 c9ab 140a 3635 521e  .....Y.8....65R.
        0x0020:  5018 0005 0bc9 0000 5100 0000 1a73 656c  P.......Q....sel
        0x0030:  6563 7420 2a20 6672 6f6d 2072 6570 6f72  ect.*.from.repor
        0x0040:  7473 00                                  ts.
08:45:40.545563 IP pg-server.postgresql > frontend-server.49753: Flags [.], ack 132, win 5, options [nop,nop,sack 1 {105:132}], length 0
        0x0000:  4500 0034 2bf5 0000 4006 fcb2 b29a f69c  E..4+...@.......
        0x0010:  b29a f64a 1538 c259 3635 6d36 c9ab 1425  ...J.8.Y65m6...%
        0x0020:  8010 0005 1347 0000 0101 050a c9ab 140a  .....G..........
        0x0030:  c9ab 1425                                ...%
08:46:08.174098 IP frontend-server.49753 > pg-server.postgresql: Flags [F.], seq 132, ack 356, win 5, length 0
        0x0000:  4500 0028 1448 0000 4006 146c b29a f64a  E..(.H..@..l...J
        0x0010:  b29a f69c c259 1538 c9ab 1425 3635 521e  .....Y.8...%65R.
        0x0020:  5011 0005 5237 0000                      P...R7..
08:46:08.175583 IP pg-server.postgresql > frontend-server.49753: Flags [F.], seq 7292, ack 133, win 5, length 0
        0x0000:  4500 0028 2bfd 0000 4006 fcb6 b29a f69c  E..(+...@.......
        0x0010:  b29a f64a 1538 c259 3635 6d36 c9ab 1426  ...J.8.Y65m6...&
        0x0020:  5011 0005 04e3 0000                      P.......
08:46:08.175617 IP frontend-server.49753 > pg-server.postgresql: Flags [R], seq 3383432230, win 0, length 0
        0x0000:  4500 0028 1449 0000 4006 146b b29a f64a  E..(.I..@..k...J
        0x0010:  b29a f69c c259 1538 c9ab 1426 0000 0000  .....Y.8...&....
        0x0020:  5004 0000 a860 0000                      P....`..

 

Have a look at 08:45:40.343241

query select * from reports is sent twice!

(futhermore, output is the same for psql).

 

tcpdump on my 32-bit desktop Ubuntu contains only one query, that is followed by response from server.

 

So, connection freezes because of the server error. On postgresql-server in /var/log/postgres/error.log I found

> unexpected EOF on client connection

 

Do you have any idea about reasons and solutions?

Thanks!

 

--

Yours faithfully,

Konstantin Nikitin,

Software Engeneer