Re: tinytds based on freetds crashing

On Wed, 4 Apr 2012 13:00:05 +0200
Krzysztof Chodak <[email protected]> wrote:

> > Here it is: TDSDUMP log with a (ruby/tinytds/freetds) crash at the
> > end
> 
> list does not like zip attachments so file is placed here:
> https://docs.google.com/open?id=0B8Pbr6Jr1eaCZnFCUDk3LWxTYXVncFpCaUdfdjhIdw

(What message did you get posting a zip file?  It should be
permitted provided it's under 75 KB.)  

The TDSDUMP log clarifies several points.  

	FreeTDS 0.91
	TDS 7.1 
	Windows (log file is on C: drive)
	client charset is UTF-8 (unusual but OK)

The trouble starts when the server disconnects unexpectedly.  It ends
when unbounded recursion caused by the application's error handler
consumes the stack and crashes the process.  

Why the server disconnected isn't clear or even certain.  All that we
know is that the last write returned "Connection reset by peer", which
normally indicates the connection was closed by the remote.  

The last packet sent is on line 81590 of the log file

	SELECT TOP (1) [users].* FROM [users] 
	WHERE [users].[login] = N''bradoscb''

Immediately beneath the dumped packet we see

net.c:667:send(2) failed: 10054 
		(WSAECONNRESET: Connection reset by peer.) 

which tells us the library detected the OS error.  Then 

util.c:331:tdserror(03a04588, 03fe49b0, 20006, 10054)
dblib.c:7929:dbperror(03d32008, 20006, 10054)
dblib.c:7981:20006: "Write to the server failed"

per normal, then 

dblib.c:5780:dbgetuserdata(03d32008)
dblib.c:5780:dbgetuserdata(03d32008)
dblib.c:4880:dbdead(03d32008) [alive]

wrong.  A disconnected session is anything but alive. 

dblib.c:4639:dbsqlok(03d32008)
dblib.c:4669:dbsqlok() not done, calling tds_process_tokens()

db-lib still thinks the session is up ...

token.c:540:tds_process_tokens(03fe49b0, 00226220, 0022621c, 0x6914)
util.c:156:Changed query state from PENDING to READING
util.c:331:tdserror(03a04588, 03fe49b0, 20004, 10054)
dblib.c:7929:dbperror(03d32008, 20004, 10054)
dblib.c:7981:20004: "Read from the server failed"

but the read failed ... 

dblib.c:5780:dbgetuserdata(03d32008)
dblib.c:5780:dbgetuserdata(03d32008)
dblib.c:4880:dbdead(03d32008) [alive]
dblib.c:4639:dbsqlok(03d32008)
dblib.c:4669:dbsqlok() not done, calling tds_process_tokens()

and we enter an infinite loop.  

Analysis
---------

Windows returns a valid error code WSAECONNRESET.  This is reported to
the log in tds/net.c:tds_goodwrite() on line 667.  That logic closes
the socket and returns -1 to tds_write_packet().

How did we get there?  The log shows

dblib.c:6862:dbsqlsend(03d32008)
write.c:168:tds_put_string wrote 194 bytes

tds_put_string() calls 
tds_put_n() calls 
tds_write_packet

tds_write_packet() returrns TDS_FAIL to tds_put_n()

which discards the return code.  :-(

Propogating the error code is not the only way error information is
provided to db-lib from libtds.  tds_goodwrite()  also calls tdserror
(), which calls the client's error handler.  We see that in the log, too

util.c:331:tdserror(03a04588, 03fe49b0, 20006, 10054)
dblib.c:7929:dbperror(03d32008, 20006, 10054)
dblib.c:7981:20006: "Write to the server failed"

What we do *not* see in the log is the product of the next line in
tdserror()

  tdsdump_log(TDS_DBG_FUNC, 
	"tdserror: client library returned %s(%d)\n", retname(rc), rc);

The missing message in the log indicates the error handler is Charlie on
the MTA: it Never Returned.  

It would appear -- whether by design or not -- that the
client-installed error handler makes db-lib calls, in particular
dbsqlok().  Don't do that.  It engenders infinite recursion just
as evinced by the log:

dblib.c:4669:dbsqlok() not done, calling tds_process_tokens()
token.c:540:tds_process_tokens(03fe49b0, 00226220, 0022621c, 0x6914)
util.c:331:tdserror(03a04588, 03fe49b0, 20004, 10054)
dblib.c:7929:dbperror(03d32008, 20004, 10054)
dblib.c:7981:20004: "Read from the server failed"
# no tdserror message here 
# to indicate the handler's return code
...
dblib.c:4639:dbsqlok(03d32008) # from within handler
dblib.c:4669:dbsqlok() not done, calling tds_process_tokens()

(It looks like an infinite loop, but it's infinite recursion.
Computationally equivalent constructs, just one is more familar to C
programmers than the other.)  

Incidentally, this would also explain why dbdead() reports "[active]".
In tds_goodread(), the socket isn't closed until after tdserror()
returns.  Because the socket is still open within the recursion, all
calls to dbdead() continue to find the socket open and it reports
"active".  

Give your error handler a nickle and let it return.  Otherwise it will
eventually devour the stack along with your process.  

--jkl