query that canceled isnt logged

Mariel Cherkassky <[email protected]> Sun, 8 Dec 2019 15:08:27 +0200
Newsgroups gmane.comp.db.postgresql.performance
Message-ID <CA+t6e1nYocLRyELmm6VM81JjfwTz_QbkiSJgyUkyDHGd-DFt8A@mail.gmail.com>
--000000000000313f9c059930fae8
Content-Type: text/plain; charset="UTF-8"

Hey all,
I'm trying to analyze a weird situation that I have seen in my db.
Sometimes my app fails to start because of the following msg :
SQL State  : null
Error Code : 0
Message    : Cannot create PoolableConnectionFactory (ERROR: canceling
statement due to user request)

In the db at the same time I saw the same msg :
2019-12-08 00:04:56 IST DB 10035  ERROR:  canceling statement due to user
request
2019-12-08 00:04:56 IST DB 10035  STATEMENT:  select 1 as test

I thought that it might be related to the validation query that is set to 2
seconds (when I change the validation query from "select 1 as test" to
"select pg_sleep(10)" ) the same behavior was reproduced .

Therefore, my theory was that the validation query is taking more than 2
seconds.  I decided to log all the statements(log_statements=all) that are
running in order to see for how long the validation query is running in the
db (log_min_duration_statement wont be helpful here because the query is
canceled and I wont be able to see its duration..).

The weird thing is that I dont see before that error any log message that
indicate that the query was running. I hoped to see the following msg in
the db log :
2019-12-08 00:04:55 IST DB 2695  LOG:  *execute *<unnamed>: select 1 as test

but I dont see any execute msg of this query , I just see the ERROR msg :
  2019-12-08 00:04:56 IST DB 10035  ERROR:  canceling statement due to user
request
2019-12-08 00:04:56 IST DB 10035  STATEMENT:  select 1 as test

Any idea why I the query isnt logged but I still get the ERROR msg ?

--000000000000313f9c059930fae8
Content-Type: text/html; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

<div dir=3D"rtl"><div dir=3D"ltr">Hey all,</div><div dir=3D"ltr">I&#39;m tr=
ying to analyze a weird situation that I have seen in my db.</div><div dir=
=3D"ltr">Sometimes my app fails to start because of the following msg :=C2=
=A0</div><div dir=3D"ltr">SQL State =C2=A0: null<br>Error Code : 0<br>Messa=
ge =C2=A0 =C2=A0: Cannot create PoolableConnectionFactory (ERROR: canceling=
 statement due to user request)<br></div><div dir=3D"ltr"><br></div><div di=
r=3D"ltr">In the db at the same time I saw the same msg :=C2=A0</div><div d=
ir=3D"ltr">2019-12-08 00:04:56 IST DB 10035 =C2=A0ERROR: =C2=A0canceling st=
atement due to user request<br>2019-12-08 00:04:56 IST DB 10035 =C2=A0STATE=
MENT: =C2=A0select 1 as test<br></div><div dir=3D"ltr"><br></div><div dir=
=3D"ltr">I thought that it might be related to the validation query that is=
 set to 2 seconds (when I change the validation query from &quot;select 1 a=
s test&quot; to &quot;select pg_sleep(10)&quot; ) the same behavior was rep=
roduced .</div><div dir=3D"ltr"><br></div><div dir=3D"ltr"></div><div dir=
=3D"ltr">Therefore, my theory was that the validation query is taking more =
than 2 seconds.=C2=A0 I decided to log all the statements(log_statements=3D=
all) that are running in order to see for how long the validation query is =
running in the db (log_min_duration_statement wont be helpful=C2=A0here bec=
ause the query is canceled and I wont be able to see its duration..).

</div><div dir=3D"ltr"><br></div><div dir=3D"ltr">The weird=C2=A0thing is t=
hat I dont see before that error any log message that indicate that the que=
ry was running. I hoped to see the following msg in the db log :=C2=A0</div=
><div dir=3D"ltr">2019-12-08 00:04:55 IST DB 2695 =C2=A0LOG: =C2=A0<b>execu=
te </b>&lt;unnamed&gt;: select 1 as test<br></div><div dir=3D"ltr"><br></di=
v><div dir=3D"ltr">but I dont see any execute msg of this query , I just se=
e the ERROR msg :=C2=A0</div><div dir=3D"ltr">=C2=A0 2019-12-08 00:04:56 IS=
T DB 10035 =C2=A0ERROR: =C2=A0canceling statement due to user request<br>20=
19-12-08 00:04:56 IST DB 10035 =C2=A0STATEMENT: =C2=A0select 1 as test=C2=
=A0=C2=A0<br></div><div dir=3D"ltr"><br></div><div dir=3D"ltr">Any idea why=
 I the query isnt logged but I still get the ERROR msg ?=C2=A0</div></div>

--000000000000313f9c059930fae8--