iinvalid string enlargement PG 7.4.5

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hi all,
this morning I perform an upgrade 7.4.2 -> 7.4.5 and
after 6 months without errors this night a backend
crashed:

ERROR: invalid string enlargement request size 1476395004
DEBUG: AbortCurrentTransaction
WARNING: AbortTransaction and not in in-progress state
ERROR: could not send data to client: Broken pipe
PANIC: error during error recovery, giving up
DEBUG: child process (PID 32247) was terminated by signal 6
LOG: server process (PID 32247) was terminated by signal 6
LOG: terminating any other active server processes

do you have any idea on what could be the reason ?

Regards
Gaetano Mendola

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.2.4 (MingW32)
Comment: Using GnuPG with Thunderbird - http://enigmail.mozdev.org

iD8DBQFBNlh77UpzwH2SGd4RAqfoAJ4zEPgG/0Yr8YTKN+PpbYQvbU7TigCggQ+3
ie8oxH9jFgFDDMlZfNnKj4w=
=5epB
-----END PGP SIGNATURE-----

Gaetano Mendola <mendola(at)bigfoot(dot)com> writes:
> ERROR: invalid string enlargement request size 1476395004
> DEBUG: AbortCurrentTransaction
> WARNING: AbortTransaction and not in in-progress state
> ERROR: could not send data to client: Broken pipe
> PANIC: error during error recovery, giving up

> do you have any idea on what could be the reason ?

I'm betting on a communications failure. What I see there is a few
bytes of corrupted data received from the client (ie, a ridiculous
message-length word) followed by abrupt disconnect *by the client*.

You have any logs indicating what might have happened at the client
end?

regards, tom lane

Tom Lane wrote:

> Gaetano Mendola <mendola(at)bigfoot(dot)com> writes:
>
>>ERROR: invalid string enlargement request size 1476395004
>>DEBUG: AbortCurrentTransaction
>>WARNING: AbortTransaction and not in in-progress state
>>ERROR: could not send data to client: Broken pipe
>>PANIC: error during error recovery, giving up
>
>
>>do you have any idea on what could be the reason ?
>
>
> I'm betting on a communications failure. What I see there is a few
> bytes of corrupted data received from the client (ie, a ridiculous
> message-length word) followed by abrupt disconnect *by the client*.
>
> You have any logs indicating what might have happened at the client
> end?

I had this failure several time:

Sep 1 20:49:51 dbsdr1 postgres[23173]: [124865-1] LOG: statement: SELECT sp_foo (
Sep 1 20:49:51 dbsdr1 postgres[23173]: [124865-2] 'EmailAlert','xxxxxxx','waelkhemiri00d0d7031e93','application/x-www-form-urlencoded','date=Wed+Sep+01+08%3A06%3A16+CEST+2004&su
Sep 1 20:49:51 dbsdr1 postgres[23173]: [124865-3] bject=HBM+Pics+for+September+1%2C+2004&from=hardcorebm%40hardcorebymail.com&to=khemiriwael%40webmails.com' )
Sep 1 20:49:51 dbsdr1 postgres[23173]: [124881-1] ERROR: invalid string enlargement request size 1476395004
Sep 1 20:49:51 dbsdr1 postgres[23173]: [124882-1] DEBUG: AbortCurrentTransaction
Sep 1 20:49:51 dbsdr1 postgres[23173]: [124883-1] WARNING: AbortTransaction and not in in-progress state
Sep 1 20:49:51 dbsdr1 postgres[23173]: [124884-1] LOG: could not send data to client: Broken pipe
Sep 1 20:49:51 dbsdr1 postgres[23173]: [124885-1] FATAL: invalid frontend message type 4
[...]
Sep 1 23:45:58 dbsdr1 postgres[24080]: [152267-1] LOG: statement: SELECT sp_foo (
Sep 1 23:45:58 dbsdr1 postgres[24080]: [152267-2] 'EmailAlert','xxxxxxx','bridge500306a80229c','application/x-www-form-urlencoded','date=Wed+Dec+17+21%3A43%3A10+CET+2003&subject
Sep 1 23:45:58 dbsdr1 postgres[24080]: [152267-3] =XPiedziivojumi+-+jauns+zhurnaals%21&from=promotions%40inbox.lv&to=ahsan%40inbox.lv' )
Sep 1 23:45:58 dbsdr1 postgres[24080]: [152283-1] ERROR: invalid string enlargement request size 1476395004
Sep 1 23:45:58 dbsdr1 postgres[24080]: [152284-1] DEBUG: AbortCurrentTransaction
Sep 1 23:45:58 dbsdr1 postgres[24080]: [152285-1] WARNING: AbortTransaction and not in in-progress state
Sep 1 23:45:58 dbsdr1 postgres[24080]: [152286-1] LOG: could not send data to client: Broken pipe
Sep 1 23:45:58 dbsdr1 postgres[24080]: [152287-1] FATAL: invalid frontend message type 4
[...]
Sep 1 23:52:24 dbsdr1 postgres[32247]: [153117-1] LOG: statement: SELECT sp_foo (
Sep 1 23:52:24 dbsdr1 postgres[32247]: [153117-2] 'EmailAlert','xxxxxxx','waelkhemiri00d0d7031e93','application/x-www-form-urlencoded','date=Wed+Sep+01+08%3A06%3A16+CEST+2004&su
Sep 1 23:52:24 dbsdr1 postgres[32247]: [153117-3] bject=HBM+Pics+for+September+1%2C+2004&from=hardcorebm%40hardcorebymail.com&to=khemiriwael%40webmails.com' )
Sep 1 23:52:24 dbsdr1 postgres[32247]: [153133-1] ERROR: invalid string enlargement request size 1476395004
Sep 1 23:52:24 dbsdr1 postgres[32247]: [153134-1] DEBUG: AbortCurrentTransaction
Sep 1 23:52:24 dbsdr1 postgres[32247]: [153135-1] WARNING: AbortTransaction and not in in-progress state
Sep 1 23:52:24 dbsdr1 postgres[32247]: [153136-1] ERROR: could not send data to client: Broken pipe
Sep 1 23:52:24 dbsdr1 postgres[32247]: [153137-1] PANIC: error during error recovery, giving up
[...]
Sep 2 00:00:58 dbsdr1 postgres[11857]: [156602-1] LOG: duration: 209.141 ms
Sep 2 00:00:58 dbsdr1 postgres[11857]: [156603-1] LOG: duration: 209.141 ms statement: SELECT sp_foo (
Sep 2 00:00:58 dbsdr1 postgres[11857]: [156603-2] 'EmailAlert','xxxxxxx','bridge500306a80229c','application/x-www-form-urlencoded','date=Thu+Jan+29+18%3A54%3A03+CET+2004&subject
Sep 2 00:00:58 dbsdr1 postgres[11857]: [156603-3] =Laimee+celojumu+uz+Egipti%21&from=promotions%40inbox.lv&to=ahsan%40inbox.lv' )
Sep 2 00:00:58 dbsdr1 postgres[11857]: [156604-1] ERROR: invalid string enlargement request size 1476395004
Sep 2 00:00:58 dbsdr1 postgres[11857]: [156605-1] DEBUG: AbortCurrentTransaction
Sep 2 00:00:58 dbsdr1 postgres[11857]: [156606-1] WARNING: AbortTransaction and not in in-progress state
Sep 2 00:00:58 dbsdr1 postgres[11857]: [156607-1] LOG: could not send data to client: Broken pipe
Sep 2 00:00:58 dbsdr1 postgres[11857]: [156608-1] FATAL: invalid frontend message type 4
[...]

basically is a store procedure call that genereate that error, only once there was that PANIC

On the client side I have always:

Internal Server Error: org.postgresql.util.PSQLException: An I/O error has occured while flushing the output - Exception: java.net.SocketException: Socket closed
Stack Trace:

java.net.SocketException: Socket closed
at java.net.SocketOutputStream.socketWrite(Native Method)
at java.net.SocketOutputStream.write(SocketOutputStream.java:83)
at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:72)
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:130)
at org.postgresql.core.PGStream.flush(PGStream.java:412)
at org.postgresql.core.QueryExecutor.sendQueryV3(QueryExecutor.java:339)
at org.postgresql.core.QueryExecutor.executeV3(QueryExecutor.java:122)
at org.postgresql.core.QueryExecutor.execute(QueryExecutor.java:101)
at org.postgresql.core.QueryExecutor.execute(QueryExecutor.java:43)
at org.postgresql.jdbc1.AbstractJdbc1Statement.execute(AbstractJdbc1Statement.java:515)
at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:50)
at org.postgresql.jdbc1.AbstractJdbc1Statement.executeQuery(AbstractJdbc1Statement.java:231)

I searched the error "invalid string enlargment request" in the logs of last week and I never encountered it.
Only since today after the 7.4.5 installation. Note that the request size is always the same!

Regards
Gaetano Mendola