#34 ct_cancel hangs
I have a problem with accessing a windows based sybase ASA 7.0 from python/freetds on linux.
The original post was on the python-sybase list, but I'm not sure whether the problem comes from the python module, and there is no activity on that list.
I don't know where the problem is, but the main issue is that cursor.close() hangs after a query folowed by several fetchone.
The problem seems to come from ** ct_cancel(CS_CANCEL_ALL) **
I'm using the latest freetds 0.65dev from 20070717
>>> db=Sybase.connect(...)
>>> c=db.cursor()
>>> c.execute('select * from rue')
>>> c.fetchone()
(...)
>>> c.close()
here it hangs, nothing happens, with 0% CPU.
It only exits if I stop the database server:
Exception Sybase.DatabaseError: <Sybase.DatabaseError instance at 0xb7cf47cc> in <bound method _FetchLazy.__del__ of <Sybase._FetchLazy instance at 0xb7cf4e4c>>
ignored
more info:
I'm using python 2.4.4 with sybase-python 0.38 compiled with -D HAVE_FREETDS -U
WANT_BULKCOPY, and freetds/libct4 0.64rc2.
(edit: 0.65dev now, same problem)
it also hangs if I call again c.execute(...) after c.fetchone()
The last thing found in the freetds logfile (debug level 99) is:
-------------------------------------------------------
(...)
token.c:1863:tds_get_data: column 8, type 47, varint size 1
token.c:1920:processing row. column size is 16
token.c:1863:tds_get_data: column 9, type 111, varint size 1
token.c:1920:processing row. column size is 8
token.c:1863:tds_get_data: column 10, type 39, varint size 1
token.c:1920:processing row. column size is 3
token.c:1863:tds_get_data: column 11, type 39, varint size 1
token.c:1920:processing row. column size is 1
token.c:1863:tds_get_data: column 12, type 111, varint size 1
net.c:446:Received header
0000 04 01 00 11 00 00 00 00- |........|
net.c:542:Received packet
0000 fd 30 00 02 00 d1 04 00-00 |.0...... .|
token.c:1920:processing row. column size is 253
-------------------------------------------------------
If I hit Ctrl-C on the python terminal, the freetds logfile tells:
net.c:336:socket read interrupted
(as many times I hit Ctrl-C)
-------------------------------------------------------------------------
I have some news:
In fact, the ct_cancel command hangs in _FetchLazy.__del__ of Sybase.py,
when I call cursor.close() after several fetchone()
But this is a random effect, sometimes it hangs, sometimes not.
It might look like a threading issue.
I don't know what the real problem is, but I've tried to replace CS_CANCEL_ALL
with CS_CANCEL_CURRENT or with CS_CANCEL_ATTN, and it doesn't hang anymore.
The difference between the different types of cancel is explained here:
http://manuals.sybase.com/onlinebooks/group-cnarc/cng1000e/prgguide/@Generic__BookTextView/5783;pt=6133
But I'm not sure what is the correct one in which circumstances.
Logged In: YES
user_id=84824
Originator: YES
James K. Lowden a écrit :
> > Post a TDSDUMP log of the activity here. That will allow us to isolate
> > the "hang" at the TDS level, and might provide enough information about
> > the API calling sequence to decide if Python is doing the right thing.
> >
> > I changed (i.e. fixed) cancel processing in the current snapshot some
> > months back, but ct-lib cancel processing isn't something I know much
> > about. We'll have to compare your log to the unit test (if extant) and
> > the docs to see what should be done.
> >
I really want to provide most information to investigate this, but I must be extremely careful because the database is full of personal medical informations, and I'm not authorized to disclose any of them, even accidentally, along with a logfile. Another thing is the full logfile size is 2,5Mb and I'm sure nobody
will appreciate to receive it :)
Actually the hang occurs for requests that should return large results. I'm doing just one cursor.fetchone(), then at the moment I run cursor.close() the logfile suddenly grows a lot (2,5MB) (it seems to contain the full result), then the close() operation never returns.
Here is the part of the logfile that contains the CANCEL_ALL operation.
If needed, please point me to the correct part of the logfile to provide so that the problem could be found.
(...)
ct.c:1858:_ct_get_client_type(type 39, user 1516, size 10)
cs.c:351:cs_convert()
ct.c:1971:_ct_get_server_type(0)
ct.c:1971:_ct_get_server_type(0)
cs.c:358:cs_convert() srctype = 47 (7) desttype = 47 (10)
cs.c:383:cs_convert() srctype = desttype
cs.c:419:cs_convert() desttype = character
ct.c:1677:_ct_bind_data(): column_type: 39 column_len: 1
ct.c:1971:_ct_get_server_type(0)
ct.c:1858:_ct_get_client_type(type 39, user 1515, size 2)
cs.c:351:cs_convert()
ct.c:1971:_ct_get_server_type(0)
ct.c:1971:_ct_get_server_type(0)
cs.c:358:cs_convert() srctype = 47 (1) desttype = 47 (2)
cs.c:383:cs_convert() srctype = desttype
cs.c:419:cs_convert() desttype = character
ct.c:2049:ct_cancel()
ct.c:2216:CS_CANCEL_ALL with connection
ct.c:2218:ct_cancel() cancelling a command for a connection
ct.c:2228:ct_cancel() command state SENT
ct.c:2229:ct_cancel() sending a cancel
net.c:673:Sending packet
0000 06 01 00 08 00 00 00 00- |........|
util.c:119:Changing query state from PENDING to READING
token.c:526:processing result tokens. marker is d1(ROW)
token.c:1863:tds_get_data: column 0, type 56, varint size 0
token.c:1920:processing row. column size is 4
token.c:1863:tds_get_data: column 1, type 47, varint size 1
token.c:1920:processing row. column size is 1
token.c:1863:tds_get_data: column 2, type 56, varint size 0
token.c:1920:processing row. column size is 4
token.c:1863:tds_get_data: column 3, type 47, varint size 1
token.c:1920:processing row. column size is 1
token.c:1863:tds_get_data: column 4, type 38, varint size 1
token.c:1920:processing row. column size is 4
token.c:1863:tds_get_data: column 5, type 39, varint size 1
token.c:1920:processing row. column size is 1
token.c:1863:tds_get_data: column 6, type 38, varint size 1
...
(about 45000 lines)
...
token.c:1863:tds_get_data: column 9, type 111, varint size 1
token.c:1920:processing row. column size is 8
token.c:1863:tds_get_data: column 10, type 39, varint size 1
token.c:1920:processing row. column size is 3
token.c:1863:tds_get_data: column 11, type 39, varint size 1
token.c:1920:processing row. column size is 1
token.c:1863:tds_get_data: column 12, type 111, varint size 1
token.c:1920:processing row. column size is -1
token.c:1863:tds_get_data: column 13, type 39, varint size 1
token.c:1920:processing row. column size is -1
token.c:1863:tds_get_data: column 14, type 39, varint size 1
token.c:1920:processing row. column size is -1
token.c:526:processing result tokens. marker is d1(ROW)
token.c:1863:tds_get_data: column 0, type 56, varint size 0
token.c:1920:processing row. column size is 4
token.c:1863:tds_get_data: column 1, type 47, varint size 1
token.c:1920:processing row. column size is 1
token.c:1863:tds_get_data: column 2, type 56, varint size 0
token.c:1920:processing row. column size is 4
token.c:1863:tds_get_data: column 3, type 47, varint size 1
token.c:1920:processing row. column size is 1
token.c:1863:tds_get_data: column 4, type 38, varint size 1
token.c:1920:processing row. column size is -1
token.c:1863:tds_get_data: column 5, type 39, varint size 1
token.c:1920:processing row. column size is -1
token.c:1863:tds_get_data: column 6, type 38, varint size 1
token.c:1920:processing row. column size is -1
token.c:1863:tds_get_data: column 7, type 39, varint size 1
token.c:1920:processing row. column size is -1
token.c:1863:tds_get_data: column 8, type 47, varint size 1
token.c:1920:processing row. column size is 16
token.c:1863:tds_get_data: column 9, type 111, varint size 1
token.c:1920:processing row. column size is 8
token.c:1863:tds_get_data: column 10, type 39, varint size 1
token.c:1920:processing row. column size is 3
token.c:1863:tds_get_data: column 11, type 39, varint size 1
token.c:1920:processing row. column size is 1
token.c:1863:tds_get_data: column 12, type 111, varint size 1
net.c:446:Received header
0000 04 01 00 11 00 00 00 00- |........|
net.c:542:Received packet
0000 fd 30 00 02 00 d1 04 00-00 |.0...... .|
token.c:1920:processing row. column size is 253
Logged In: YES
user_id=84824
Originator: YES
** A more complete tds logfile is available here : **
http://lists.ibiblio.org/pipermail/freetds/2007q3/022257.html
Logged In: YES
user_id=84824
Originator: YES
A full TDS logfile is available here:
http://ccomb.free.fr/freetds.log
I did not have a freeze for this log, but an error:
Exception Sybase.DatabaseError: <Sybase.DatabaseError instance at 0xb78fc4ac> in <bound method _FetchLazy.__del__ of <Sybase._FetchLazy instance at 0xb78fc28c>> ignored
Logged In: YES
user_id=1872449
Originator: NO
May be a bug, and ct_cancel should be called in a different thread.
Please try it again.