Problem with error handling

I'm getting a "SystemError: null argument to internal routine" problem
that is gobbling up the actual error. I turned on debugging and see
that the problem is that my connection is closed (and I have to connect
a second time to get it to work). However, the SystemError hid this
until I turned on debugging.

In trying to find why the SystemError is happening, I found that at the
point pq_raise is called, no exception has been set. The conn and pgres
objects are fine and the cursor is NULL. The following call is NULL:

code = PQresultErrorField(pgres, PG_DIAG_SQLSTATE);

This results in "exc" staying null. Thus, when psyco_set_error is
called, only msg and pgerror are not NULL. Since the cursor is NULL,
the connection object is not pulled, and the following line is valid:

pymsg = conn_text_from_chars(conn, msg)

Subsequently, the following is called with "exc" set to NULL:

err = PyObject_CallFunctionObjArgs(exc, pymsg, NULL);

Thus err is NULL and the if statement is not called. Because it is not
called, PyErr_SetObject is never called. All of this started with a
call to cursor.execute in Python. That dropped down into the C module's
psyco_curs_execute. That returns NULL without the PyErr object set,
which results in the SystemError.

I am guessing that the solution is one of the following:

* PQresultErrorField should not have returned NULL
* "exc" should have been calculated another way (like an else after the
"if (code != NULL)")

Regardless of the solution, thanks for your time.

-eric

This email message is intended for the use of the person to whom it has been sent, and may contain information that is confidential or legally protected. If you are not the intended recipient or have received this message in error, you are not authorized to copy, distribute, or otherwise use this message or its attachments. Please notify the sender immediately by return e-mail and permanently delete this message and any attachments. Verio, Inc. makes no warranty that this email is error or virus free. Thank you.

On Sat, Apr 23, 2011 at 2:56 AM, Eric Snow <esnow(at)verio(dot)net> wrote:

> I am guessing that the solution is one of the following:
>
> * PQresultErrorField should not have returned NULL

This is from the libpq, I guess we can do little about it, if not
keeping it in consideration.

> * "exc" should have been calculated another way (like an else after the
> "if (code != NULL)")

Definitely there should have been an else here: We check for the state
not null but then don't do anything as an alternative. I don't think
passing a NULL to psyco_set_error was ever intentional. Fixing in my
repos.

> Regardless of the solution, thanks for your time.

Thank you for yours!

-- Daniele

On Sun, Apr 24, 2011 at 2:47 AM, Daniele Varrazzo
<daniele(dot)varrazzo(at)gmail(dot)com> wrote:
> On Sat, Apr 23, 2011 at 2:56 AM, Eric Snow <esnow(at)verio(dot)net> wrote:

>> * "exc" should have been calculated another way (like an else after the
>> "if (code != NULL)")
>
> Definitely there should have been an else here: We check for the state
> not null but then don't do anything as an alternative. I don't think
> passing a NULL to psyco_set_error was ever intentional. Fixing in my
> repos.

I have fixed the issue
<https://github.com/dvarrazzo/psycopg/commit/c08799b0>, but the error
may be unhelpful if the libpq didn't provide a message either.

Do you have a way to reproduce the bug so we can see if there is any
other hint we can provide as exception message? If not, would you mind
testing the patch and see if you get a reasonable error?

Thanks,

-- Daniele

Daniele,

Thanks for jumping on this. Interestingly, you did exactly the same
thing that I did in the else (set DatabaseError). And yes, it did fix
my problem, so you are spot on.

As to the error, here is the relevant piece of our code:

cur = self.conn.cursor(wrapped=0)
logger.debug(cur.mogrify(sql, values))
logger.debug("before: %s" % cur)
cur.execute(sql, values)
logger.debug("after: %s" % cur)
return cur

The call to cur.execute was raising an exception because the connection
had closed. It was still open during the logger entry for "before". It
closed sometime during the execute call. It made it to the call to "
_psyco_curs_execute ", so none of the other failure conditions prior to
that in "psyco_curs_execute" were triggered. Maybe they should have
been or maybe not. Maybe they caused the connection to close or maybe
not. Probably not. Regardless, it runs into trouble when it gets to
the locking portion of the query execution.

Here's the relevant output from the debugging log:

[20299] curs_execute: pg connection at 0x859a000 OK
[20299] pq_begin_locked: pgconn = 0x859a000, isolevel = 1, status = 1
[20299] pq_execute_command_locked: pgconn = 0x859a000, query = BEGIN;
SET TRANSACTION ISOLATION LEVEL READ COMMITTED
[20299] pq_execute_command_locked: result was not COMMAND_OK (7)
[20299] pq_complete_error: pgconn = 0x859a000, pgres = 0x8125a80, error
= (null)
[20299] pq_raise: PQerrorMessage: err=server closed the connection
unexpectedly
This probably means the server terminated abnormally
before or while processing the request.

[20299] pq_raise: err2=server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.

[20299] psyco_curs_execute: res = -1, pgres = 0x0

I am guessing that this is an issue with our database more than with
psycopg. It works if we catch the exception and re-connect. We are
using postgresql 8.1 on FreeBSD 4.8 (without pthreads). The postgres
connection is made over stunnel. Keep in mind that we are currently in
the process of moving to postgres 9 and RHEL 5 in the coming weeks.
Regardless, thanks for your timely attention on this matter.

-eric

-----Original Message-----
From: Daniele Varrazzo [mailto:daniele(dot)varrazzo(at)gmail(dot)com]
Sent: Saturday, April 23, 2011 8:07 PM
To: Eric Snow
Cc: psycopg(at)postgresql(dot)org
Subject: Re: [psycopg] Problem with error handling

On Sun, Apr 24, 2011 at 2:47 AM, Daniele Varrazzo
<daniele(dot)varrazzo(at)gmail(dot)com> wrote:
> On Sat, Apr 23, 2011 at 2:56 AM, Eric Snow <esnow(at)verio(dot)net> wrote:

>> * "exc" should have been calculated another way (like an else after
>> the "if (code != NULL)")
>
> Definitely there should have been an else here: We check for the state

> not null but then don't do anything as an alternative. I don't think
> passing a NULL to psyco_set_error was ever intentional. Fixing in my
> repos.

I have fixed the issue
<https://github.com/dvarrazzo/psycopg/commit/c08799b0>, but the error
may be unhelpful if the libpq didn't provide a message either.

Do you have a way to reproduce the bug so we can see if there is any
other hint we can provide as exception message? If not, would you mind
testing the patch and see if you get a reasonable error?

Thanks,

-- Daniele

This email message is intended for the use of the person to whom it has been sent, and may contain information that is confidential or legally protected. If you are not the intended recipient or have received this message in error, you are not authorized to copy, distribute, or otherwise use this message or its attachments. Please notify the sender immediately by return e-mail and permanently delete this message and any attachments. Verio, Inc. makes no warranty that this email is error or virus free. Thank you.

On Mon, Apr 25, 2011 at 6:20 PM, Eric Snow <esnow(at)verio(dot)net> wrote:

> [...]
> [20299] pq_raise: PQerrorMessage: err=server closed the connection
> unexpectedly
>        This probably means the server terminated abnormally
>        before or while processing the request.
[...]

> I am guessing that this is an issue with our database more than with
> psycopg.

I think so: this seems a "regular" backend crash (I've seen it way too
often developing a C extension). Just asking in case the condition was
reproducible in the unit test, but I don't think it is (unless I write
a C extension to purposely segfault the session, which wouldn't be
that hard...)

Cheers,

-- Daniele