[Pgbouncer-general] pgbouncer got packet from server when not linked

[Filip Rembiałkowski]

Hi,

We got a series of warnings like the following. Nothing in the
postgresql log files.

This happened during a large peak of client connections to pgbouncer.

We observed the frontend application to stop responding at the same time.

I'll be thankful for any hint... Does it happen in normal situations?
What can be cause of this?



PgBouncer version 1.4.1, PostgreSQL version 9.0.4.



2012-03-03 22:33:54.028 13938 LOG Stats: 91 req/s, in 24711 b/s, out
279278 b/s,query 4235 us
2012-03-03 22:34:54.028 13938 LOG Stats: 99 req/s, in 34661 b/s, out
294598 b/s,query 4841 us
2012-03-03 22:35:02.401 13938 WARNING S-0x6e1480:
prod/postgres at 127.0.0.1:5432 got packet 'S' from server when not
linked
2012-03-03 22:35:02.401 13938 WARNING S-0x6e1480:
prod/postgres at 127.0.0.1:5432 got packet 'S' from server when not
linked
2012-03-03 22:35:02.401 13938 WARNING S-0x6e1480:
prod/postgres at 127.0.0.1:5432 got packet 'C' from server when not
linked
2012-03-03 22:35:02.401 13938 WARNING S-0x6e1480:
prod/postgres at 127.0.0.1:5432 got packet 'Z' from server when not
linked
2012-03-03 22:35:54.029 13938 LOG Stats: 104 req/s, in 28649 b/s, out
292938 b/s,query 4173 us
2012-03-03 22:36:54.029 13938 LOG Stats: 94 req/s, in 45789 b/s, out
297572 b/s,query 4123 us
2012-03-03 22:37:54.030 13938 LOG Stats: 97 req/s, in 26915 b/s, out
297181 b/s,query 4957 us
2012-03-03 22:38:54.030 13938 LOG Stats: 87 req/s, in 31265 b/s, out
254703 b/s,query 4026 us

2012-03-03 23:18:54.057 13938 LOG Stats: 99 req/s, in 70960 b/s, out
579232 b/s,query 5159 us
2012-03-03 23:19:54.058 13938 LOG Stats: 86 req/s, in 23166 b/s, out
329085 b/s,query 5130 us
2012-03-03 23:20:02.867 13938 WARNING S-0x6dcb80:
prod/postgres at 127.0.0.1:5432 got packet 'S' from server when not
linked
2012-03-03 23:20:02.867 13938 WARNING S-0x6dcb80:
prod/postgres at 127.0.0.1:5432 got packet 'S' from server when not
linked
2012-03-03 23:20:02.867 13938 WARNING S-0x6dcb80:
prod/postgres at 127.0.0.1:5432 got packet 'C' from server when not
linked
2012-03-03 23:20:02.867 13938 WARNING S-0x6dcb80:
prod/postgres at 127.0.0.1:5432 got packet 'Z' from server when not
linked
2012-03-03 23:20:02.881 13938 WARNING S-0x6dabe0:
prod/postgres at 127.0.0.1:5432 got packet 'S' from server when not
linked
2012-03-03 23:20:02.881 13938 WARNING S-0x6dabe0:
prod/postgres at 127.0.0.1:5432 got packet 'S' from server when not
linked
2012-03-03 23:20:02.881 13938 WARNING S-0x6dabe0:
prod/postgres at 127.0.0.1:5432 got packet 'C' from server when not
linked
2012-03-03 23:20:02.881 13938 WARNING S-0x6dabe0:
prod/postgres at 127.0.0.1:5432 got packet 'Z' from server when not
linked
2012-03-03 23:20:54.059 13938 LOG Stats: 87 req/s, in 50953 b/s, out
284675 b/s,query 11774 us
2012-03-03 23:21:54.060 13938 LOG Stats: 89 req/s, in 43242 b/s, out
277193 b/s,query 14027 us
2012-03-03 23:22:54.060 13938 LOG Stats: 78 req/s, in 22068 b/s, out
243555 b/s,query 8578 us


2012-03-03 23:57:54.081 13938 LOG Stats: 84 req/s, in 27134 b/s, out
183257 b/s,query 17874 us
2012-03-03 23:58:54.081 13938 LOG Stats: 69 req/s, in 20828 b/s, out
178645 b/s,query 15244 us
2012-03-03 23:59:54.081 13938 LOG Stats: 87 req/s, in 27448 b/s, out
179314 b/s,query 10716 us
2012-03-04 00:00:03.279 13938 WARNING S-0x6e1480:
prod/postgres at 127.0.0.1:5432 got packet 'T' from server when not
linked
2012-03-04 00:00:03.279 13938 WARNING S-0x6e1480:
prod/postgres at 127.0.0.1:5432 got packet 'D' from server when not
linked
2012-03-04 00:00:03.279 13938 WARNING S-0x6e1480:
prod/postgres at 127.0.0.1:5432 got packet 'C' from server when not
linked
2012-03-04 00:00:03.279 13938 WARNING S-0x6e1480:
prod/postgres at 127.0.0.1:5432 got packet 'Z' from server when not
linked
2012-03-04 00:00:03.279 13938 WARNING S-0x6e1480:
prod/postgres at 127.0.0.1:5432 got packet 'S' from server when not
linked
2012-03-04 00:00:03.279 13938 WARNING S-0x6e1480:
prod/postgres at 127.0.0.1:5432 got packet 'S' from server when not
linked
2012-03-04 00:00:03.279 13938 WARNING S-0x6e1480:
prod/postgres at 127.0.0.1:5432 got packet 'C' from server when not
linked
2012-03-04 00:00:03.279 13938 WARNING S-0x6e1480:
prod/postgres at 127.0.0.1:5432 got packet 'Z' from server when not
linked

[Marko Kreen]

Post by Filip Rembiałkowski
We got a series of warnings like the following. Nothing in the
postgresql log files.
This happened during a large peak of client connections to pgbouncer.
We observed the frontend application to stop responding at the same time.
I'll be thankful for any hint... Does it happen in normal situations?
What can be cause of this?

First time I've seen this. I looked at the code but cannot see
how it can happen.

Post by Filip Rembiałkowski
PgBouncer version 1.4.1, PostgreSQL version 9.0.4.
prod/postgres at 127.0.0.1:5432 got packet 'S' from server when not
linked
prod/postgres at 127.0.0.1:5432 got packet 'S' from server when not
linked
prod/postgres at 127.0.0.1:5432 got packet 'C' from server when not
linked
prod/postgres at 127.0.0.1:5432 got packet 'Z' from server when not
linked

This seems to be output from RESET ALL or DISCARD ALL statement.

It's probably from bouncer, not app, but I'm not sure why
appears unexpectedly.

Please send me your config, then I can think further.