I found a strange problem. I am running ODBTP service on Win 2008 Server 64bit and ODBTP client on OpenBSD 4.6 amd64. The database is MSSQL 2008 (ver. 10.0.2531.0).
Whenever a query, longer than 256 characters is sent to the server, there is no reply from the service (the server reports timeout and the client reports "unable to read from server").
I can reproduce this with odbtpcli. It happens even when I send a long comment or an invalid query (no syntax error is reported). A long wait is followed by a disconnect and that is all. Queries <256 characters work fine.
In the ODBTP client, it looks like odbSockReadData times out waiting for odbSockRead (I guess no reply from service). I can't debug the service as it is running on my client's production server (and my Windows/ODBC knowledge is limited).
The problem may be due to upgrade to Win 2008 last week, but I can't be sure. The connection worked fine since 2006 but circumstances show that it is entirely possible that no query of such length was encountered during this period.
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Yes, but It looks like these queries never reach the SQL server (if I run the last one with one "x" less, it works fine and the SQL server reports syntax error).
The errors in ODBTP service log file look like this:
OPEN 192.168.2.2 4967
ERROR 192.168.2.2 4967
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
When I execute the 'invalid query via odbtpcli.exe, I get the expected syntax error, even after adding more x's. Can you test this query on the Windows production box using odbtpcli.exe? Also, set LogReadAndSent=1 in odbtpsrv.ini, and then again post the log.
bob
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Here is the log again, with LogReadAndSent set to 1:
OPEN 192.168.2.2 1
SENT 192.168.2.2 1
READ 192.168.2.2 1
SENT 192.168.2.2 1
READ 192.168.2.2 1
SENT 192.168.2.2 1
ERROR 192.168.2.2 1
CLOSE 192.168.2.2 1
The query was 255 'x' characters (I found out 255 characters is actually the limit: 254 works, 255 doesn't).
I can't try odbtpcli on the windows box right now. I'll set up a test box, try to reproduce the error and report back later today.
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
I can not reproduce the error on my test server (the test server runs MS-SQL version 10.50.1600.1 while the production server has 10.0.2531.0; both run Win 2008 Server R2). Everything works OK even when I connect with the same ODBTP client from the same OpenBSD box.
I also tested on the production box with the windows odbtpcli.exe, as you suggested. Again, everything works fine.
I suspected the windows ODBC driver and tried a few long queries with another odbc client (www.firstsql.com/iodbc) but I could not reproduce the problem.
This looks like a weird error that only occurs in my specific case. I'll try to debug some more, but need to set-up development environment first.
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Successfully running odbtpcli.exee on your production server indicates there is nothing wrong with the ODBC driver on that server.
According to the log, the last successfully read command was ODBTP_SETATTR (Code = 06). At that point the ODBTP service times out because it did not receive another command before the ReadTimeout value set in odbtpserv.ini. Something is peculiar with the connection between your UNIX client and the production server. Can you run the test as follows:
From UNIX client, connect to ODBTP service running on development Win server. Configure the ODBC driver connect string to connect to the production server. Run the query. Since the SQL statement was never received, the problem does not appear to pertain to ODBC nor SQL Server. You should compare the posted log with that of a successfully test.
This test connects the UNIX client to the production SQL server via the development server's ODBTP service:
UNIX ODBTP client -> Dev ODBTP service -> Production SQL Server
bob
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
I did the test (ODBTP client <-> test server ODBTP service <-> production server MS-SQL). It works fine. Here is the log:
OPEN 192.168.55.26 1
SENT 192.168.55.26 1
READ 192.168.55.26 1
SENT 192.168.55.26 1
READ 192.168.55.26 1
SENT 192.168.55.26 1
READ 192.168.55.26 1
SENT 192.168.55.26 1
READ 192.168.55.26 1
SENT 192.168.55.26 1
CLOSE 192.168.55.26 1
This is strange. I have the very same ODBTP service (as downloaded and reinstalled yesterday) on both the test server and the produtcion server and I use the very same ODBTP client. The only difference is that the test was performed via a number of SSH tunnels while the regular connection is plain TCP.
Also, I did some debugging of the client. Even when this bug occurs, the client sends the entire message to the socket (the write(2) call in sock_send() returns query-length + 5 bytes). I guess the problem must be in the windows ODBTP service.
What is the easiest way for me to debug/recompile the service. I installed Visual C++ 2010 Express but it can't open the dsw/dsp files (it tries to "upgrade the project" but fails).
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
The problem is not likely in the ODBTP service. There is something inherent in the connection between the UNIX box and the production server. The ODBTP_EXECUTE request (Code = 20) is not being received by the ODBTP service within 3 minutes. As a test, it would be interesting to see if this does not pertain to the ODBTP_EXECUTE request.
Make the follwoing change to odbtpcli.c on the UNIX box:
change
odbCHAR szDbConnect;
to
odbCHAR szDbConnect;
Run make to recomplie odbtpcli. On the 2nd line of the odbtpcli.con file, which specifies the ODBC connect string, put a string of characters that exceeds 255. Run odbtpcli with this file. I will not be surprised if the timeout error occurs while the ODBTP service is waiting for the ODBTP_LOGIN request (Code = 01).
bob
bob
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
OPEN 192.168.2.2 1
SENT 192.168.2.2 1
ERROR 192.168.2.2 1
CLOSE 192.168.2.2 1
I think you are right about this problem being due to connection. There is a firewall between both machines which may be the cause (I disabled all the packet shaping stuff though, but the problem persists). I'll probably just give up on this and tunnel the connection through SSH, which - as I just found out - works fine.
Thank you for your help!
Tin
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Hmm, just in case there is something magical about 255, change the statement on line 4252 of odbtp.c from
Sock->ulTransBufSize = 4096;
to
Sock->ulTransBufSize = 256;
Run make, and the again try odbtpcli.
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
OPEN 192.168.2.2 1
SENT 192.168.2.2 1
READ 192.168.2.2 1
SENT 192.168.2.2 1
READ 192.168.2.2 1
SENT 192.168.2.2 1
READ 192.168.2.2 1
SENT 192.168.2.2 1
READ 192.168.2.2 1
SENT 192.168.2.2 1
CLOSE 192.168.2.2 1
I still suspect the ODBTP service though. I just checked the logs: long queries were executed regulary on the old Win2003 box, and without any problems.
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
If it is working when you reduce the max transfer size from 4096 to 256, then problem is occuring in the TCP layer, and not in the ODBTP layer. The reson why I don't think it's the ODBTPservice is because it occurs at a point when the service is just waiting for bytes to arrive on the socket. The timeout occurs in the CODBTPThread::Run() method defined in winservice\build\odbtpsrv\ODBTPThread.cpp. Below is the code segment to analyze:
The socket is polled for ANY data until the elapsed time reaches the read timeout value. For some reason, NO data comes accross the socket when the client tries to transfer more than 256 bytes of data with one write() call.
bob
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
I found a strange problem. I am running ODBTP service on Win 2008 Server 64bit and ODBTP client on OpenBSD 4.6 amd64. The database is MSSQL 2008 (ver. 10.0.2531.0).
Whenever a query, longer than 256 characters is sent to the server, there is no reply from the service (the server reports timeout and the client reports "unable to read from server").
I can reproduce this with odbtpcli. It happens even when I send a long comment or an invalid query (no syntax error is reported). A long wait is followed by a disconnect and that is all. Queries <256 characters work fine.
In the ODBTP client, it looks like odbSockReadData times out waiting for odbSockRead (I guess no reply from service). I can't debug the service as it is running on my client's production server (and my Windows/ODBC knowledge is limited).
The problem may be due to upgrade to Win 2008 last week, but I can't be sure. The connection worked fine since 2006 but circumstances show that it is entirely possible that no query of such length was encountered during this period.
Questions:
Can you post the exact error message that occurs when you process the query with odbtpcli?
Can you post a query that causes the error?
Have you tested the query with Query Analizer?
Bob:
> Can you post the exact error message that occurs when you process the query with odbtpcli?
Execute Failed: Unable to read from server
> Can you post a query that causes the error?
Any query longer than 256 bytes. Examples follow:
The actual query that I found it with:
INSERT INTO prodaja(id_rcl, trgovec, stn_trg, datn_trg, dog_stat, datum_predaje_trgovcu, opis_poskodbe_3, pogodba, datum_pogodbe, racun) VALUES('035041', '0003700', 'N100111', '2010-04-21', '1', '2010-04-26', 'V vozilu manjka obvezna oprema (trikotnik, zarnice, prva pomoc) ter knjizice (servisna, prirocnik vozila, prirocnik radia).', '', NULL, '0');
This one is very simple, but fails (unless I remove one "id_rcl"):
SELECT TOP 1 id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl FROM prodaja;
This one is commented out, but still fails:
-SELECT TOP 1 id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl, id_rcl FROM prodaja;
This is not even a query, but it triggers the error just the same:
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx xxxxxxxxxxxxxxxxxxxxxxxxxxx
> Have you tested the query with Query Analizer?
Yes, but It looks like these queries never reach the SQL server (if I run the last one with one "x" less, it works fine and the SQL server reports syntax error).
The errors in ODBTP service log file look like this:
OPEN 192.168.2.2 4967
ERROR 192.168.2.2 4967
When I execute the 'invalid query via odbtpcli.exe, I get the expected syntax error, even after adding more x's. Can you test this query on the Windows production box using odbtpcli.exe? Also, set LogReadAndSent=1 in odbtpsrv.ini, and then again post the log.
Here is the log again, with LogReadAndSent set to 1:
OPEN 192.168.2.2 1
SENT 192.168.2.2 1
READ 192.168.2.2 1
SENT 192.168.2.2 1
READ 192.168.2.2 1
SENT 192.168.2.2 1
ERROR 192.168.2.2 1
CLOSE 192.168.2.2 1
The query was 255 'x' characters (I found out 255 characters is actually the limit: 254 works, 255 doesn't).
I can't try odbtpcli on the windows box right now. I'll set up a test box, try to reproduce the error and report back later today.
I made some more tests.
I can not reproduce the error on my test server (the test server runs MS-SQL version 10.50.1600.1 while the production server has 10.0.2531.0; both run Win 2008 Server R2). Everything works OK even when I connect with the same ODBTP client from the same OpenBSD box.
I also tested on the production box with the windows odbtpcli.exe, as you suggested. Again, everything works fine.
I suspected the windows ODBC driver and tried a few long queries with another odbc client (www.firstsql.com/iodbc) but I could not reproduce the problem.
This looks like a weird error that only occurs in my specific case. I'll try to debug some more, but need to set-up development environment first.
Successfully running odbtpcli.exee on your production server indicates there is nothing wrong with the ODBC driver on that server.
According to the log, the last successfully read command was ODBTP_SETATTR (Code = 06). At that point the ODBTP service times out because it did not receive another command before the ReadTimeout value set in odbtpserv.ini. Something is peculiar with the connection between your UNIX client and the production server. Can you run the test as follows:
From UNIX client, connect to ODBTP service running on development Win server. Configure the ODBC driver connect string to connect to the production server. Run the query. Since the SQL statement was never received, the problem does not appear to pertain to ODBC nor SQL Server. You should compare the posted log with that of a successfully test.
This test connects the UNIX client to the production SQL server via the development server's ODBTP service:
UNIX ODBTP client -> Dev ODBTP service -> Production SQL Server
I did the test (ODBTP client <-> test server ODBTP service <-> production server MS-SQL). It works fine. Here is the log:
OPEN 192.168.55.26 1
SENT 192.168.55.26 1
READ 192.168.55.26 1
SENT 192.168.55.26 1
READ 192.168.55.26 1
SENT 192.168.55.26 1
READ 192.168.55.26 1
SENT 192.168.55.26 1
READ 192.168.55.26 1
SENT 192.168.55.26 1
CLOSE 192.168.55.26 1
This is strange. I have the very same ODBTP service (as downloaded and reinstalled yesterday) on both the test server and the produtcion server and I use the very same ODBTP client. The only difference is that the test was performed via a number of SSH tunnels while the regular connection is plain TCP.
Also, I did some debugging of the client. Even when this bug occurs, the client sends the entire message to the socket (the write(2) call in sock_send() returns query-length + 5 bytes). I guess the problem must be in the windows ODBTP service.
What is the easiest way for me to debug/recompile the service. I installed Visual C++ 2010 Express but it can't open the dsw/dsp files (it tries to "upgrade the project" but fails).
The problem is not likely in the ODBTP service. There is something inherent in the connection between the UNIX box and the production server. The ODBTP_EXECUTE request (Code = 20) is not being received by the ODBTP service within 3 minutes. As a test, it would be interesting to see if this does not pertain to the ODBTP_EXECUTE request.
Make the follwoing change to odbtpcli.c on the UNIX box:
change
odbCHAR szDbConnect;
to
odbCHAR szDbConnect;
Run make to recomplie odbtpcli. On the 2nd line of the odbtpcli.con file, which specifies the ODBC connect string, put a string of characters that exceeds 255. Run odbtpcli with this file. I will not be surprised if the timeout error occurs while the ODBTP service is waiting for the ODBTP_LOGIN request (Code = 01).
bob
bob
Yes, it now fails when connecting:
OPEN 192.168.2.2 1
SENT 192.168.2.2 1
ERROR 192.168.2.2 1
CLOSE 192.168.2.2 1
I think you are right about this problem being due to connection. There is a firewall between both machines which may be the cause (I disabled all the packet shaping stuff though, but the problem persists). I'll probably just give up on this and tunnel the connection through SSH, which - as I just found out - works fine.
Thank you for your help!
Tin
Hmm, just in case there is something magical about 255, change the statement on line 4252 of odbtp.c from
Sock->ulTransBufSize = 4096;
to
Sock->ulTransBufSize = 256;
Run make, and the again try odbtpcli.
Yes, it works now:
OPEN 192.168.2.2 1
SENT 192.168.2.2 1
READ 192.168.2.2 1
SENT 192.168.2.2 1
READ 192.168.2.2 1
SENT 192.168.2.2 1
READ 192.168.2.2 1
SENT 192.168.2.2 1
READ 192.168.2.2 1
SENT 192.168.2.2 1
CLOSE 192.168.2.2 1
I still suspect the ODBTP service though. I just checked the logs: long queries were executed regulary on the old Win2003 box, and without any problems.
If it is working when you reduce the max transfer size from 4096 to 256, then problem is occuring in the TCP layer, and not in the ODBTP layer. The reson why I don't think it's the ODBTPservice is because it occurs at a point when the service is just waiting for bytes to arrive on the socket. The timeout occurs in the CODBTPThread::Run() method defined in winservice\build\odbtpsrv\ODBTPThread.cpp. Below is the code segment to analyze:
while( bOK )
{
if( m_pService->m_dwReadTimeout )
{
if( !m_pSock->Wait(3) )
{
if( m_pService->IsStopping() )
{
bOK = FALSE;
}
else if( ulRemainingReadTime <= 3 )
{
if( m_pSock->GetError() == TCPERR_NONE )
m_pSock->SetError( TCPERR_TIMEOUT );
break;
}
else
{
ulRemainingReadTime -= 3;
}
continue;
}
ulRemainingReadTime = m_pService->m_dwReadTimeout;
}
if( !m_pSock->ReadRequest() ) break;
if( bLogReadAndSent ) LogRequest();
The socket is polled for ANY data until the elapsed time reaches the read timeout value. For some reason, NO data comes accross the socket when the client tries to transfer more than 256 bytes of data with one write() call.