BUG #8383: SQL statement error log misses query parameters

From: aschetinin(at)gmail(dot)com
To: pgsql-bugs(at)postgresql(dot)org
Subject: BUG #8383: SQL statement error log misses query parameters
Date: 2013-08-14 10:13:59
Message-ID: E1V9Y5X-0000Qp-B7@wrigleys.postgresql.org
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-bugs

The following bug has been logged on the website:

Bug reference: 8383
Logged by: Andrew Schetinin
Email address: aschetinin(at)gmail(dot)com
PostgreSQL version: 9.1.9
Operating system: Debian Linux (kernel 3.9.8-1)
Description:

Hi,

I was debugging some problematic SQL INSERT statement which complained about
one of the parameters. In order to try to understand what's wrong with the
parameter in question, I configured detailed SQL statement logs to be
printed by PostgreSQL.

This is the error message (with the SQL statement) I received:

2013-08-14 12:45:47 IDT ERROR: column "properties" is of type hstore but
expression is of type character varying at character 216
2013-08-14 12:45:47 IDT HINT: You will need to rewrite or cast the
expression.
2013-08-14 12:45:47 IDT STATEMENT: INSERT INTO pesticide_rule (id,
active_from, active_until, allowed, classifier, external_id, last_update,
priority, properties, first_id, pesticide_id, project_id, second_id) VALUES
($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13)
2013-08-14 12:45:47 IDT ERROR: current transaction is aborted, commands
ignored until end of transaction block

As you may see, there is no any clue on what the parameters are. So,
unfortunately, it did not help me at all in my troubleshooting.

Surprisingly, when I finally succeeded to guess and solve the problem with
the parameter, it started printing the parameters just fine:

2013-08-14 12:49:12 IDT LOG: execute <unnamed>: INSERT INTO pesticide_rule
(id, active_from, active_until, allowed, classifier, external_id,
last_update, priority, properties, first_id, pesticide_id, project_id,
second_id) VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13)
2013-08-14 12:49:12 IDT DETAIL: parameters: $1 = '72147802620887041', $2 =
NULL, $3 = NULL, $4 = 't', $5 = NULL, $6 = NULL, $7 = '2013-08-14
12:49:12.54895', $8 = '0', $9 = '', $10 = '200035', $11 = '320002', $12 =
'72142057617948673', $13 = '210009'
2013-08-14 12:49:12 IDT LOG: duration: 51.290 ms

My trouble with this story is that the troubleshooting of problematic SQL
queries is complicated by the fact that the parameters are not reported to
the log. Especially in cases when the error refers to some problem with the
parameters.

Regards,

Andrew Schetinin

Browse pgsql-bugs by date

  From Date Subject
Next Message Greg Stark 2013-08-14 10:44:40 Re: BUG #8382: Duplicate primary key
Previous Message ascot.moss@gmail.com 2013-08-14 09:26:14 Re: Recovery.conf PITR by recovery_target_time