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