Re: Unexpected "canceling statement due to user request" error

On Sun 2019-09-01 19:46:19 -0400, Tom Lane wrote:
> I poked at this for awhile and concluded that what you must be seeing is
> that the statement timeout interrupt triggers, but no CHECK_FOR_INTERRUPTS
> call happens thereafter, until we get to the disable_statement_timeout()
> call in finish_xact_command(). That throws away the timeout-happened
> indicator, but it does nothing to reset InterruptPending or
> QueryCancelPending. Those flags will also be thrown away eventually,
> after we've read a new client command:
>
> /*
> * (4) disable async signal conditions again.
> *
> * Query cancel is supposed to be a no-op when there is no query in
> * progress, so if a query cancel arrived while we were idle, just
> * reset QueryCancelPending. ProcessInterrupts() has that effect when
> * it's called when DoingCommandRead is set, so check for interrupts
> * before resetting DoingCommandRead.
> */
> CHECK_FOR_INTERRUPTS();
> DoingCommandRead = false;
>
> Ignoring the timeout if it happened too late is what we're supposed
> to be doing, so that's fine so far.
>
> But: what happens if some other CHECK_FOR_INTERRUPTS occurs before we
> reach the main input loop? Of course, exactly the symptom you saw:
> a bogus "canceling statement due to user request" error report.
> What's worse, that happens after we've completed the transaction, leaving
> the client with a very misleading idea of whether the command committed
> or not.
>
> So how could that happen? After experimenting, I found a pretty
> obvious candidate: statement duration logging happens after we
> do finish_xact_command, and there's a CHECK_FOR_INTERRUPTS in
> errfinish(). So I hypothesize that you have log_duration or
> log_min_duration_statement enabled.

Yes, I have log_min_duration_statement set to 0! (log_duration is off)

> I was able to replicate the problem by lobotomizing a couple of
> CHECK_FOR_INTERRUPTS that would normally happen in a simple
> "select pg_sleep()" query (see attached for-demonstration-
> purposes-only patch). Then I get
>
> regression=# set statement_timeout TO '1s';
> SET
> regression=# select pg_sleep(2.0); -- completes normally after 2 sec
> pg_sleep
> ----------
>
> (1 row)
>
> regression=# set log_min_duration_statement TO '100ms';
> SET
> regression=# select pg_sleep(2.0); -- sits for 2 sec, then:
> ERROR: canceling statement due to user request
>
> So that's not very good and we ought to do something about it.
> We can't have disable_statement_timeout() clear QueryCancelPending,
> because that might lose state about some other cause for query
> cancel. I'm inclined to think that we need to split QueryCancelPending
> into more than one flag.
>
> A separate question is how come the particular query you're complaining
> about has (seemingly) a fairly wide window where it never does any
> CHECK_FOR_INTERRUPTS call before terminating. Perhaps there's someplace
> we need to sprinkle a few more of those.

Yeah, it is strange. There are many queries in this system with statement
timeouts and this is the only one where I see this and it happens several
times a day.

Thank you so much for looking into this. An impressive analysis!