Re: FreeTDS Pylons Problem

Todd Hanson wrote:
> If simultaneous requests are
> made against the controller (i.e. request 1 is running and has not
> returned a result yet and a new request is made against the controller)
> Pylons blows out completely with a single line error pointing to FreeTDS
> as the culprit.  

The log indicates the error comes from re-using a closed connection. 
Here's a list of the db-lib calls.  (The dbopen() calls are not logged due
to an odd sequence in log initialization.  One day.):

dblib.c:325:db_env_chg(0xa06ea20, 1, master, master)
dblib.c:325:db_env_chg(0xa06ea20, 3, (0x1), cp850)
dblib.c:325:db_env_chg(0xa06ea20, 4, 4096, 512)
dblib.c:237:dblib_add_connection(0xb2049340, 0xa06ea20)

Unfortunately, this doesn't tell us the DBPROCESS pointer that was added. 
But we can infer later that TDSSOCKET* 0xa06ea20 is DBPROCESS* 0xa5a57f0. 

dblib.c:718:dbloginfree(0xa169be0)
dblib.c:1243:dbcmd(0xa5a57f0, SET ARITHABORT ON;SET
CONCAT_NULL_YIELDS_NULL ON;SET ANSI_NULLS ON;SET ANSI_NULL_DFLT_ON
ON;SET ANSI_PADDING ON;SET ANSI_WARNINGS ON;SET ANSI_NULL_DFLT_ON ON;SET
CURSOR_CLOSE_ON_COMMIT ON;SET QUOTED_IDENTIFIER ON)
dblib.c:1298:dbsqlexec(0xa5a57f0)
dblib.c:6722:dbsqlsend(0xa5a57f0)
dblib.c:4532:dbsqlok(0xa5a57f0)
dblib.c:3093:dbcancel(0xa5a57f0)
dblib.c:1243:dbcmd(0xa5a57f0, USE [QISmaster])
dblib.c:5727:dbfreebuf(0xa5a57f0)
dblib.c:1298:dbsqlexec(0xa5a57f0)
dblib.c:6722:dbsqlsend(0xa5a57f0)
dblib.c:4532:dbsqlok(0xa5a57f0)
dblib.c:325:db_env_chg(0xa06ea20, 1, master, QISmaster)

The dbcmd() call to use QISmaster for DBPROCESS*  0xa5a57f0 seems to have
resulted in a db_env_chg to QISmaster for TDSSOCKET* 0xa06ea20.  

dblib.c:3093:dbcancel(0xa5a57f0)
dblib.c:3093:dbcancel(0xa5a57f0)

Two calls, both unnecessary, to dbcancel().  

dblib.c:1243:dbcmd(0xa5a57f0, BEGIN TRAN)
dblib.c:5727:dbfreebuf(0xa5a57f0)
dblib.c:1298:dbsqlexec(0xa5a57f0)
dblib.c:6722:dbsqlsend(0xa5a57f0)
dblib.c:4532:dbsqlok(0xa5a57f0)
dblib.c:1599:dbresults(0xa5a57f0)
dblib.c:2678:dbcount(0xa5a57f0)
dblib.c:3093:dbcancel(0xa5a57f0)

Weird.  After results are retrieved, another dbcancel().  

dblib.c:1372:dbclose(0xa52f3b8)
dblib.c:256:dblib_del_connection(0xb2049340, 0xa361058)
dblib.c:5727:dbfreebuf(0xa52f3b8)

closed a different DBPROCESS*.  dbclose() calls dbfreebuf().  

We didn't see it opened; no login packet was ever sent.  It was never
used.  

dblib.c:3093:dbcancel(0xa5a57f0)

a second redundant cancellation....

dblib.c:1243:dbcmd(0xa5a57f0, exec qisxml_GetDailyCustodianStatus;)
dblib.c:5727:dbfreebuf(0xa5a57f0)
dblib.c:1298:dbsqlexec(0xa5a57f0)
dblib.c:6722:dbsqlsend(0xa5a57f0)
dblib.c:4532:dbsqlok(0xa5a57f0)

This sequence again sends the query to the server.  

dblib.c:7782:dbperror(0xa52f3b8, 20004, 9)
dblib.c:3093:dbcancel(0xa52f3b8)
dblib.c:1599:dbresults(0xa52f3b8)

The error arises from *something* trying to use the closed connection
0xa52f3b8, not the one on which a query was just sent, 0xa5a57f0.  

I don't think 0xa52f3b8 is a valid, open connection, based on the log.  I
suspect -- but haven't tried to reproduce the effect -- that dbclose() may
result in a read(2). 

In any case, you've pointed up an interesting "style" of error.  The
db-lib code checks doggedly for a NULL DBPROCESS* in every function.  It
doesn't check for a *valid* pointer.  It doesn't maintain a list of valid
pointers, although of course it could.  It does maintain a list of valid
sockets, but it doesn't check that either.  

There's no error message associated with using an invalid pointer, nor for
closing a DBPROCESS that's not open.  Maybe there should be....

HTH.  

--jkl