TD-21288: TD6.2SP2.1 / Sybase Client 15.7 : Crash with logging

[FredRoge]

Hello,

When I add to sql.ini the section
[win32client.syb32]
log=C:\prov\sqsw1.log

TD crashes on SqlConnect (I even tried by just setting the 3 connexion variables SqlUser etc. and Call SqlConnect on SAM_AppStartup)

The log file is partially written and ends like this :
9/23/14 16:13:21 1> [get database parameter] param = 1004
9/23/14 16:13:21 1> [set database parameter] param = 5106 value = 0
9/23/14 16:13:21 1> [set database parameter] param = 3018 value = 1
9/23/14 16:13:21 1> [get database parameter] param = 5517
9/23/14 16:13:21 1> [ERROR] 196

It begins like that (OpenClient information)

9/23/14 16:13:21 0> SQLRouter LOG Utility - version 2.1.0
9/23/14 16:13:21 0> SQLRouter/Sybase - version 4.0.0
9/23/14 16:13:21 0> Sybase Client-Library/15.7/P-EBF22688 SP126/PC Intel/BU
9/23/14 16:13:21 0> ILD1570-041/OPT/Sun Apr 13 22:00:14 2014

[sybgtwy] contains only remotedbname keywords

Could you please check the reproduction of this problem ?

Kind regards,

Fred Rogé

[Jean-Marc Gemperle]

Hi

Do you imply to say that only enable router log is sufficient to crash the a simple SqlConnect()
in other words without the router log connection are fine.
If so I will enter an issue.

JM

[FredRoge]

Hello,

Yes, it is exactly that :
Setting the 3 Sql* variables then calling SqlConnect on SAM_AppStartup is all the stuff you need to try to reproduce the crash, as far as the [win32client.syb32] log key uncommented.

Comment it, then you can execute millions lines C/S applications !

Kind regards,

Fred Rogé

[Jean-Marc Gemperle]

Hi

Yes I could repro the issue see attached video
TD-21288
Simple SqlConnect() to SYBASE crashing when router log is enabled

As for setzerolengthstringstonull=1 this is I believe one of the most important setting (SQLSERVER/SYBASE) without it as you know STRING_Null in TD will be inserted as '' instead a NULL...so as long as we support router connectivity this setting be long lasting...that is for sure...

JM

[FredRoge]

Hello,

Thanks for your answers !

For setzerolengthstringstonull, SybRouter doesn't behave with Sybase as you describe (I know this behavior was discussed regarding other configuration), and keep being an high risk consideration for migration.

I will open a new thread to give detailed information on this most important feature - I fully agree with you !

Kind regards

Fred

[Jean-Marc Gemperle]

Hi

Really was not aware that on Sybase the behavior is different
Surely more people uses SQLSERVER and this is what I understand from this setting in the context of SQLSERVER

Salutation Compatriote? I assume since you are locate in Geneva where I'm born.

Cheers
JM

[FredRoge]

Hi,

Ideed, I am an expat' from France ; so many great travellers in our speciality !

As for Sybase, I reckon this difference might be unintentional, as the behaviour with Sybase changed between TD3.1 and TD6.x. ; and as it's the first time it is useful with Sybase, there are no real points of comparison.

I didn't use setzerolengthstringstonull with SqlServer for years, but I thought it was provided to do exactly what implies its name : to map '' (empty string) to NULL when writing in the DB through bind variables, so it makes sense.
And as at this time STRING_Null didn't exist, I can't say if the mapping is extended in some way to '' => STRING_Null => NULL... (would make sense).
By the way, the doc. says that STRING_Null should give NULL in any case with sqs, isn't it correct ?

NB : I posted the detailed Sybase issue separatly.

Cheers,

Fred

[Brian Howard]

Hi Fred & Jean,

In case it is relevant and/or helpful, I have been using TD6.2.1 with Sybase Client 15.7 and have the router log turned on and not having any issues. We pass some flags to the router log as follows.

[win32client.syb32]
log=d:\log\router.log /FD /Ld


C:\Users\bhoward>isql -v
Sybase CTISQL Utility/15.7/P/PC Intel/BUILD1570-011/OPT/Tue Aug 16 05:45:02 2011

Although I am using 15.7 Client our DB is 15.3
Select @@version
Adaptive Server Enterprise/15.0.3/EBF 18467 ESD#4 ONE-OFF/P/Sun_svr4/OS 5.8/ase1503/2768/64-bit/FBO/Thu Nov 18 20:03:17 2010

The following is excerpts from the generated log
10/23/14 09:00:42 0> SQLRouter LOG Utility - version 2.1.0
10/23/14 09:00:42 0> SQLRouter/Sybase - version 4.0.0
10/23/14 09:00:42 0> Sybase Client-Library/15.7/P/PC Intel/BUILD1570-011/OP
10/23/14 09:00:42 0> T/Tue Aug 16 05:39:10 2011
10/23/14 09:00:42 0> [show environ] SYBASE=C:\sybase
...
10/23/14 09:00:42 0> longbuffer=32650
10/23/14 09:00:42 0> locktimeout=0
10/23/14 09:00:42 0> sybautocommit=on
10/23/14 09:00:42 0> yieldonservercall=1
10/23/14 09:00:42 0> sybworkstationname=data-dkvwsbh01
10/23/14 09:00:42 0> sybapplicationname=@AppName
10/23/14 09:00:42 0> checkexists=off
10/23/14 09:00:42 0> fetchrow=20
10/23/14 09:00:42 0> sybmaxmessages=100
10/23/14 09:00:42 0> enablemultipleconnections=on
10/23/14 09:00:42 0> Each call to SqlConnect will create a new connection
10/23/14 09:00:42 0> closecursorateof=on
10/23/14 09:00:42 0> IF CCP IS OFF, Cursor will be closed at EOF
10/23/14 09:00:42 1> [connect] dbname = BRIAN username = UWAD237
10/23/14 09:00:42 1> SERVERMSG: 5704:10 Changed client character set settin
10/23/14 09:00:42 1> g to 'utf8'.
10/23/14 09:00:42 1> SERVERMSG: 5701:10 Changed database context to 'DV_UWA
10/23/14 09:00:42 1> 5'.
10/23/14 09:00:42 1> SERVERMSG: 5703:10 Changed language setting to 'us_eng
10/23/14 09:00:42 1> lish'.
10/23/14 09:00:42 1> TDS version - 7364
10/23/14 09:00:42 1> TDS packet size - 2048
10/23/14 09:00:42 1> DBMS version - Adaptive Server Enterprise/15.0.3/EBF 1
10/23/14 09:00:42 1> 8467 ESD#4 ONE-OFF/P/Sun_svr4/OS 5.8/ase1503/2768/64-b
10/23/14 09:00:42 1> it/FBO/Thu Nov 18 20:03:17 2010
...

king regards

Brian

[FredRoge]

Hello,

Thanks a lot for your very interesting feedback, Brian !

I just checked again with quite some hope, as our configurations are very close (TD6.2.1, ASE 15.0.3, OCS15.7) with some differences in build for Sybase client (1570-041 vs 1570-011 for you) and serveur (2707 vs 2768 for you).

Alas, it didn't changes anything.

I then try to set the same values than you in sql.ini sybrouter keywords, just in case => no more luck.

Could you please show us some more lines you get after the server infos (after the bold below), as it's with one of this [get database parameter] param = 5517 that the crash occurs :
(Rem : no more [ERROR] 196 after the crash today, I'll investigate that)

And do you have this ASSERTION FAILURE: file ..\..\sqlsyb32\c\SQSCPR.CPP too, I get it even with TD3.1 ?

Also, clearly the [get database parameter] param = 5517 was not here back in 3.1, I will investigate this further too, but Gupta's help would be nice as it seems to be a Gupta sqlrouter constant.

Crashed log excerpt in 6.2 :

10/23/14 14:19:26 1> [connect] dbname = SRVDEV1 username = fred
10/23/14 14:19:26 1> SERVERMSG: 5704:10 Changed client character set settin
10/23/14 14:19:26 1> g to 'utf8'.
10/23/14 14:19:26 1> SERVERMSG: 5701:10 Changed database context to 'dbsecl
10/23/14 14:19:26 1> i'.
10/23/14 14:19:26 1> SERVERMSG: 5703:10 Changed language setting to 'us_eng
10/23/14 14:19:26 1> lish'.
10/23/14 14:19:26 1> TDS version - 7364
10/23/14 14:19:26 1> TDS packet size - 2048
10/23/14 13:55:44 1> DBMS version - Adaptive Server Enterprise/15.0.3/EBF 1
10/23/14 13:55:44 1> 7769 ESD#4/P/Sun_svr4/OS 5.8/ase1503/2768/64-bit/FBO/T
10/23/14 13:55:44 1> hu Aug 26 15:08:16 2010
10/23/14 13:55:44 1> SERVERMSG: 5701:10 Changed database context to 'dbdev
10/23/14 13:55:44 1> 1'.
10/23/14 13:55:44 1> CLIENTMSG: 155:1 ct_results(): user api layer: externa
10/23/14 13:55:44 1> l error: This routine cannot be called when the comman
10/23/14 13:55:44 1> d structure is idle.
10/23/14 13:55:44 1> ASSERTION FAILURE: file ..\..\sqlsyb32\c\SQSCPR.CPP :
10/23/14 13:55:44 1> line 99
10/23/14 13:55:44 1> [get database parameter] param = 1004
10/23/14 13:55:44 1> [set database parameter] param = 5106 value = 0
10/23/14 13:55:44 1> [set database parameter] param = 3018 value = 1
10/23/14 13:55:44 1> [get database parameter] param = 5517

then nothing more... the process being dead


OK log excerpt in 3.1

10/23/14 13:00:05 1> DBMS version - Adaptive Server Enterprise/15.0.3/EBF 1
10/23/14 13:00:05 1> 7769 ESD#4/P/Sun_svr4/OS 5.8/ase1503/2768/64-bit/FBO/T
10/23/14 13:00:05 1> hu Aug 26 15:08:16 2010
10/23/14 13:00:05 1> SERVERMSG: 5701:10 Changed database context to 'dbdev
10/23/14 13:00:05 1> 1'.
10/23/14 13:00:05 1> CLIENTMSG: 155:1 ct_results(): user api layer: externa
10/23/14 13:00:05 1> l error: This routine cannot be called when the comman
10/23/14 13:00:05 1> d structure is idle.
10/23/14 13:00:05 1> ASSERTION FAILURE: file ..\..\sqlsyb32\c\SQSCPR.CPP :
10/23/14 13:00:05 1> line 99
10/23/14 13:00:05 1> [set database parameter] param = 5106 value = 0
10/23/14 13:00:05 1> [set database parameter] param = 3018 value = 1
10/23/14 13:00:05 1> [set database parameter] param = 3002 value = 120
10/23/14 13:00:05 1> [set database parameter] param = 3007 value = 0
10/23/14 13:00:05 1> [set database parameter] param = 3006 value = 1
10/23/14 13:00:05 1> [set database parameter] param = 5112 value = 10000
10/23/14 13:00:05 1> [set database parameter] param = 5224 value = 1
10/23/14 13:00:05 1> [set database parameter] param = 3003 value = 0
10/23/14 13:00:05 2> [connect] dbname = SRVDEV1 username = fred
10/23/14 13:00:05 2> [set database parameter] param = 5106 value = 0
10/23/14 13:00:05 2> [set database parameter] param = 3018 value = 1
10/23/14 13:00:05 2> [set database parameter] param = 3002 value = 120
10/23/14 13:00:05 2> [set database parameter] param = 3007 value = 0
10/23/14 13:00:05 2> [set database parameter] param = 3006 value = 1
10/23/14 13:00:05 2> [set database parameter] param = 5112 value = 10000
10/23/14 13:00:05 2> [set database parameter] param = 5224 value = 1
10/23/14 13:00:05 2> [set database parameter] param = 3003 value = 0

Kind regards,

Fred

[Brian Howard]

Hi Fred,

The following are the next lines in our router.log. i.e. after 5517 we get the ERROR 196 then everything else in sql we send down the line.

10/23/14 10:36:07 1> [get database parameter] param = 1004
10/23/14 10:36:07 1> [set database parameter] param = 5106 value = 0
10/23/14 10:36:07 1> [set database parameter] param = 3018 value = 1
10/23/14 10:36:07 1> [get database parameter] param = 5517
10/23/14 10:36:07 1> [ERROR] 196 Invalid GET parameter
10/23/14 10:36:07 1> [prepare proc] set arithabort arith_overflo
10/23/14 10:36:07 1> w on
10/23/14 10:36:07 1> [execute] set arithabort arith_overflow on
10/23/14 10:36:07 1> [prepare proc] set arithabort numeric_trunc
10/23/14 10:36:07 1> ation on
10/23/14 10:36:07 1> [execute] set arithabort numeric_truncation
10/23/14 10:36:07 1> on
10/23/14 10:36:07 1> [set database parameter] param = 5224 value = 1
10/23/14 10:36:07 1> [set database parameter] param = 3003 value = 1
10/23/14 10:36:07 2> [prepare proc] Exec PSP_GLO_LOGIN 'QUERY',

for the sake of being complete and in case it is useful, I have included below the rest of our [sybgtwy] other than remotedbname

longbuffer=32650
locktimeout=0
sybautocommit=on
yieldonservercall=1
sybworkstationname=data-dkvwsbh01
sybapplicationname=@AppName
checkexists=off
fetchrow=20
sybmaxmessages=100
enablemultipleconnections=on
closecursorateof=on
;sybtracefile=c:\sybase.log

cheers

[Brian Howard]

Apologies, I didn't answer all of your questions. here is some more router log

10/23/14 10:36:07 2> [connect] dbname = BRIAN username = TRUSTED
10/23/14 10:36:07 2> SERVERMSG: 5704:10 Changed client character set settin
10/23/14 10:36:07 2> g to 'utf8'.
10/23/14 10:36:07 2> SERVERMSG: 5701:10 Changed database context to 'master
10/23/14 10:36:07 2> '.
10/23/14 10:36:07 2> SERVERMSG: 5703:10 Changed language setting to 'us_eng
10/23/14 10:36:07 2> lish'.
10/23/14 10:36:07 2> TDS version - 7364
10/23/14 10:36:07 2> TDS packet size - 2048
10/23/14 10:36:07 2> DBMS version - Adaptive Server Enterprise/15.0.3/EBF 1
10/23/14 10:36:07 2> 8467 ESD#4 ONE-OFF/P/Sun_svr4/OS 5.8/ase1503/2768/64-b
10/23/14 10:36:07 2> it/FBO/Thu Nov 18 20:03:17 2010
10/23/14 10:36:07 2> SERVERMSG: 5701:10 Changed database context to 'DV_UWA
10/23/14 10:36:07 2> 3'.
10/23/14 10:36:07 2> CLIENTMSG: 155:1 ct_results(): user api layer: externa
10/23/14 10:36:07 2> l error: This routine cannot be called when the comman
10/23/14 10:36:07 2> d structure is idle.
10/23/14 10:36:07 2> ASSERTION FAILURE: file ..\..\sqlsyb32\c\SQSCPR.CPP :
10/23/14 10:36:07 2> line 99
10/23/14 10:36:07 2> [get database parameter] param = 1004

cheers

[FredRoge]

Hello,

Thanks a lot, Brian. It seems you are quite lucky, as I'd got the crash with different versions of Sybase Client, anyway, and JM can reproduce the issue.
We can see the only difference is you passing through this 196 error, which actually occurs.

Just one more thing, all my tries were under W7, so if ever you use a different version, please notify...

Now waiting for Gupta's investigations or patch...

Cheers,

Fred

[Brian Howard]

Hi,

FYI, Just found that on a windows 2112 r2 box we have the same crash.

cheers

[Brian Howard]

Hi Fred,

In case you are interested, we have found a work around for this. Grab a copy of sqlwntm.dll from an earlier version of TD. (The one I used had a version of 5.2.1 in the file properties i.e. not versioned such as the existing sqlwntm10.dll) then add this in with your other runtime files.

Good luck.

Brian