Question Re: How do I debug FORWARD TO creating a persistent idle connection? in Technology Q&A

How do I debug FORWARD TO creating a persistent idle connection?

Breck_Carter — Thu, 31 Oct 2019 10:58:29 GMT

(see also How do I stop sa_set_http_option 'SessionID' from causing second remote server connections?)

A SQL Anywhere procedure created in 2006, running in production since 2011 and last modified in 2013 has suddenly changed it's behavior on @@version 17.0.9.4882...

It creates a second persistent idle connection to a remote (proxy) SQL Anywhere server when three successive FORWARD TO statements are executed.

SELECT CURRENT TIMESTAMP, * FROM sa_conn_info() ORDER BY Number;

current timestamp,Number,Name,
   Userid,DBNumber,LastReqTime,ReqType,CommLink,NodeAddr,ClientPort,ServerPort,
   BlockedOn,LockRowID,LockIndexID,LockTable,UncommitOps,ParentConnection,LockObject,LockObjectType

2019-10-31 10:08:16.272,1,'Foxhound-Monitor-10160',     ***** the main Foxhound sampling connection on the target database
   'dba',0,'2019-10-31 10:08:16.272','PREFETCH','local','',59881,2638,
   0,0,,'',0,,'',''

2019-10-31 10:08:16.272,2,'ddd17-1',
   'dba',0,'2019-10-31 10:08:16.272','FETCH','local','',0,0,
   0,0,,'',0,,'',''

2019-10-31 10:08:16.272,3,'ddd17-2',
   'dba',0,'2019-10-31 10:07:22.210','PREFETCH','local','',0,0,
   0,0,,'',0,,'',''

2019-10-31 10:08:16.272,4,'Foxhound-Monitor-10160',     ***** the bogus idle connection
   'dba',0,'2019-10-31 10:07:42.573','COMMIT','local','',59883,2638,
   0,0,,'',0,,'',''

2019-10-31 10:08:16.272,1000000001,'INT: StmtPerfMngrConn',
   '',0,'','unknown (0)','NA','NA',0,0,
   0,0,,'',0,,'',''

Why is this bad? Because Foxhound thinks you have accidentally started two Monitor sessions on the same target...

Duplicate Foxhound sampling sessions. There is more than one Foxhound connection to this target database.

Note: The version 17.0.9.4882 has not changed recently.

When these FORWARD TO statements are executed, other code has already created a first persistent connection to the same remote SQL Anywhere server; I have always assumed that connection was used by the FORWARD TO statements, but I have no idea if short-lived connection were ever opened and closed.

However, if one or more connections were ever created by these FORWARD TO statements, they were never observed; i.e., they were not persistent.

...and, unexpected increases in connection numbers were ALSO never observed.

Here's the Last Plan Text on the idle connection...

( Plan 
  ( SingleRowGroupBy 
    ( NestedLoopsJoin
      ( IndexScan ( ISYSUSER su ) user_name )
      ( IndexOnlyScan ISYSOPTION ISYSOPTION )
    )
  )
)

Here's the calling code...

The "proxy owner" value is used for both a SQL Anywhere user id and an associated remote server name...

DECLARE @proxy_owner                                    VARCHAR ( 128 );
...
   SELECT ...
          rroad_sampling_options.proxy_owner
     INTO ...
          @proxy_owner
     FROM rroad_sampling_options
    WHERE rroad_sampling_options.sampling_id = @sampling_id;
...
   SET @RememberLastPlan      = TRIM ( LEFT ( COALESCE ( f_forward_string_function_call ( @proxy_owner, 'PROPERTY ( ''RememberLastPlan'' )' ),      '' ), 3 ) );
   SET @RememberLastStatement = TRIM ( LEFT ( COALESCE ( f_forward_string_function_call ( @proxy_owner, 'PROPERTY ( ''RememberLastStatement'' )' ), '' ), 3 ) );
   SET @RequestTiming         = TRIM ( LEFT ( COALESCE ( f_forward_string_function_call ( @proxy_owner, 'PROPERTY ( ''RequestTiming'' )' ),         '' ), 3 ) );

Here's where the FORWARD TO statements are...

CREATE FUNCTION f_forward_string_function_call (
   IN @p_remote_server_name   VARCHAR ( 128 ), 
   IN @p_string_function_call LONG VARCHAR )
   RETURNS LONG VARCHAR
   NOT DETERMINISTIC
BEGIN

-- © Copyright 2013 RisingRoad. All rights reserved. All unpublished rights reserved.
-- breck.carter@gmail.com
-- www.risingroad.com

DECLARE @remote_server_name       VARCHAR ( 128 );
DECLARE @sql                      LONG VARCHAR;
DECLARE @errormsg                 VARCHAR ( 32767 );
DECLARE @string_return_value      LONG VARCHAR;
DECLARE @string_return_value_pos  BIGINT;
DECLARE @semicolon_pos            BIGINT;

--------------------------------------------------------------------
SET @remote_server_name = TRIM ( COALESCE ( @p_remote_server_name, '' ) );

IF @remote_server_name = '' THEN
   RETURN '';
END IF;

--------------------------------------------------------------------
-- Get the string return value via FORWARD TO and RAISERROR.

BEGIN -- error handling block

   SET @sql = 'CAST ( ' + @p_string_function_call + ' AS VARCHAR )';

   SET @sql = 'RAISERROR 20000 ''Foxhound:'' + ' + @sql; -- use language-invariant eyecatcher 'Foxhound:'

   SET @sql = REPLACE ( @sql, '''', '''''' );

   SET @sql = 'FORWARD TO ' + @remote_server_name + ' ''' + @sql + '''';

   EXECUTE IMMEDIATE @sql;

   EXCEPTION

      WHEN OTHERS THEN

         SET @errormsg = ERRORMSG();

END; -- error handling block

-------------------------------------------------------------------
-- Extract the string value from the error message.

SET @string_return_value = ''; -- until successfully changed

IF @errormsg = 'Server '''': ???' THEN

ELSE

   SET @string_return_value_pos = LOCATE ( @errormsg, 'Foxhound:' );  

   IF @string_return_value_pos > 0 THEN

      -- +123456789
      -- Foxhound:xxx... 

      SET @string_return_value = TRIM ( SUBSTR ( @errormsg, @string_return_value_pos + 9 ) );

   END IF;

END IF;

RETURN @string_return_value;

END; -- f_forward_string_function_call

Re: How do I debug FORWARD TO creating a persistent idle connection?

VolkerBarth — Thu, 31 Oct 2019 13:26:24 GMT

Have you tried using Connect/Disconnect events on the target db to monitor new connections? (Probably yes, I assume)

Re: How do I debug FORWARD TO creating a persistent idle connection?

Breck_Carter — Thu, 31 Oct 2019 16:51:16 GMT

Yes, indeed... here are (some of) the connection properties captured by the Connection event;

The connection_authentication, LastStatement and LastPlanText are [cough] funky :)...

PropName                                 Value
...
AppInfo                                  IP=192.168.0.30;HOST=XPS;OSUSER=Breck;
   OS='Windows 10 Build 17134 ';EXE='C:\\Program Files\\SQL Anywhere 17\\Bin64\\dbsrv17.exe';
   PID=0x27b0;THREAD=0x283c;VERSION=17.0.9.4882;API=ODBC;TIMEZONEADJUSTMENT=-240
...
CommLink                                 local                
CommNetworkLink                          TCPIP                
CommProtocol                             CmdSeq               
,,,
ConnectedTime                            0                    
connection_authentication                Company=Sybase;
   Application=DBTools;
   Signature=000fa55157edb8e14d818eb4fe3db41447146f1571g
   2a1b5949cab32c7760419117ca3ce88770fecfd7
connection_type                          Standard             
...
LastPlanText                             ( Plan 
  ( SingleRowGroupBy 
    ( NestedLoopsJoin
      ( IndexScan ( ISYSUSER su ) user_name )
      ( IndexOnlyScan ISYSOPTION ISYSOPTION )
    )
  )
)
LastReqTime                              2019-10-31 10:07:42.558
LastStatement                              set temporary option "time_format" = 'hh:nn:ss';
  set temporary option "timestamp_format" = 'yyyy-mm-dd hh:nn:ss.ssssss';
  set temporary option "date_format" = 'yyyy-mm-dd';
  set temporary option "date_order" = 'ymd';
  set temporary option "isolation_level" = '0';
  set temporary option "timestamp_with_time_zone_format" = 'yyyy-mm-dd hh:nn:ss.ssssss +hh:nn';
  set temporary option "auto_commit" = 'ON'
...
login_mode                               Standard             
login_procedure                          sp_login_environment 
LoginTime                                2019-10-31 10:07:42.561
...
Name                                     Foxhound-Monitor-10160
...
OSUser                                   Breck                
...
post_login_procedure                     dbo.sa_post_login_procedure
...
ReqType                                  EXEC                 
...
ServerPort                               2638                 
...
UserAppInfo                                                   
...
UserID                                   dba                  
...
webservice_namespace_host                                     
webservice_sessionid_name                SessionID            
(331 rows)

Re: How do I debug FORWARD TO creating a persistent idle connection?

Breck_Carter — Thu, 31 Oct 2019 17:13:49 GMT

Sadly, calling the very cool function sp_forward_to_remote_server() instead of jumping through EXECUTE IMMEDIATE hoops...

   SET @sql = STRING ( 
      'RAISERROR 20000 ''Foxhound:'' + CAST ( ', 
      @p_string_function_call,
      ' AS VARCHAR )' );
CALL dbo.sp_forward_to_remote_server ( @remote_server_name, @sql );
/*
   SET @sql = 'CAST ( ' + @p_string_function_call + ' AS VARCHAR )';
SET @sql = 'RAISERROR 20000 ''Foxhound:'' + ' + @sql; -- use language-invariant eyecatcher 'Foxhound:'
SET @sql = REPLACE ( @sql, '''', '''''' );
SET @sql = 'FORWARD TO ' + @remote_server_name + ' ''' + @sql + '''';
EXECUTE IMMEDIATE @sql;
*/

...doesn't help.

Re: How do I debug FORWARD TO creating a persistent idle connection?

Breck_Carter — Thu, 31 Oct 2019 17:25:49 GMT

Should I try request level logging?

That used to be fun and useful, before it got all f***ed up, er, obfuscated 🙂

Re: How do I debug FORWARD TO creating a persistent idle connection?

Breck_Carter — Thu, 31 Oct 2019 17:31:09 GMT

And then there's cis_option = 7.

I'll leave that for tomorrow, I've had enough fun for one day.

Re: How do I debug FORWARD TO creating a persistent idle connection?

Breck_Carter — Fri, 01 Nov 2019 05:04:25 GMT

Getting rid of the weird RAISERROR technique altogether, and using a DECLARE cursor instead, makes the code MUCH cleaner, and it works... but it STILL causes an unexpected idle second remote server connection to the target.

It's actually worse... the problem appears on an earlier call to this procedure, rather than waiting until a later call.

CREATE FUNCTION f_forward_string_function_call (
   IN @p_remote_server_name   VARCHAR ( 128 ), 
   IN @p_string_function_call LONG VARCHAR )
   RETURNS LONG VARCHAR
   NOT DETERMINISTIC
BEGIN
DECLARE @remote_server_name       VARCHAR ( 128 );
DECLARE @sql                      LONG VARCHAR;
DECLARE @string_return_value      LONG VARCHAR;
DECLARE c_fetch NO SCROLL CURSOR FOR CALL dbo.sp_forward_to_remote_server ( @remote_server_name, @sql );
SET @remote_server_name = TRIM ( COALESCE ( @p_remote_server_name, '' ) );
SET @sql = STRING ( 'SELECT CAST ( ', @p_string_function_call, ' AS VARCHAR )' );
OPEN c_fetch;
FETCH c_fetch INTO @string_return_value;
CLOSE c_fetch;
RETURN @string_return_value;
END;

Re: How do I debug FORWARD TO creating a persistent idle connection?

Breck_Carter — Fri, 01 Nov 2019 10:37:48 GMT

It's probably something in my code causing this change in behavior, not anything in V17.

Specifically, it is probably caused by something in a recent "patch" involving several new and changed procedures and other SQL objects, because the behavior appears immediately after that patch is applied. This is true even when SQL Anywhere 17 is not involved at all; the original V16 database is installed from the setup.exe, started with the V16 engine, and patched with the V16 engine.

...oh, well, I didn't have anything planned for the weekend 🙂

Re: How do I debug FORWARD TO creating a persistent idle connection?

Breck_Carter — Fri, 01 Nov 2019 10:39:52 GMT

...request level logging, cis_option = 7... and ODBC logging! whee!

Re: How do I debug FORWARD TO creating a persistent idle connection?

VolkerBarth — Fri, 01 Nov 2019 11:54:09 GMT

A wild guess: Is this related to the extern_login_credentials setting? (Don't know if I have spelled it correctly...)

Cf. that FAQ...

Re: How do I debug FORWARD TO creating a persistent idle connection?

Breck_Carter — Sat, 02 Nov 2019 06:53:02 GMT

oooh, oooh ...

...please let it be so! 🙂

Re: How do I debug FORWARD TO creating a persistent idle connection?

Breck_Carter — Sat, 02 Nov 2019 09:19:41 GMT

Alas... extern_login_credentials has been set to 'Login_user' for a long time...

-- 2013 03 01 BC 4221a: Added:   SET OPTION PUBLIC.extern_login_credentials      = 'Login_user';       -- remote connections will use the logged in user's extern login credentials

...assuming that is what it should be.

Karim's answer contains this statement which seems to be exactly wrong: "...then the extern_login_credentials option will be set to "Effective_user". The idea here is that if you have explicitly asked for legacy behavior when it comes to system stored procedures, then you probably want legacy behavior for remote connections as well."

I am under the impression that "legacy behavior" is "Login_user".

At this point I'm almost willing to try "Effective_user"... almost 🙂

Re: How do I debug FORWARD TO creating a persistent idle connection?

VolkerBarth — Sat, 02 Nov 2019 10:41:33 GMT

Yes, I just thought you might try the opposite option to see whether that makes a difference...

Re: How do I debug FORWARD TO creating a persistent idle connection?

Breck_Carter — Sun, 03 Nov 2019 08:16:05 GMT

Of course... I was just being lazy... sadly, Effective_user had the expected effect; i.e., it made the second connection appear right away instead of later 🙂

Anyway, it's gotten way more confusing; see How do I stop sa_set_http_option 'SessionID' from causing second remote server connections?

Re: How do I debug FORWARD TO creating a persistent idle connection?

VolkerBarth — Sun, 03 Nov 2019 11:22:18 GMT

Fwiw, are the remote calls done by the same logged in and the same effective user? SA17 has special values for these and more user names...

Re: How do I debug FORWARD TO creating a persistent idle connection?

Breck_Carter — Tue, 05 Nov 2019 08:14:21 GMT

O . . . M . . . G . . .

...you have just ruined my day 🙂

Once upon a time I said "I should really read the docs from cover to cover"... it's nice to have goals even if they're not achievable 🙂

Re: How do I debug FORWARD TO creating a persistent idle connection?

Breck_Carter — Tue, 05 Nov 2019 09:01:53 GMT

Login page, initial Display

2019-11-05 08:43:00.927 DIAG ***** 17 ***** SERVICE rroad_administrator_login()
2019-11-05 08:43:00.927 DIAG    CURRENT USER = "DBA_menu"
2019-11-05 08:43:00.943 DIAG  EXECUTING USER = "DBA"
2019-11-05 08:43:00.958 DIAG   INVOKING USER = "DBA_menu"
2019-11-05 08:43:00.958 DIAG    SESSION USER = "DBA_menu"
2019-11-05 08:43:00.974 DIAG PROCEDURE OWNER = "DBA"

Login page, after CALL sa_set_http_option ( 'SessionID' ...

2019-11-05 08:43:06.818 DIAG ***** 19 ***** SERVICE rroad_administrator_login()
2019-11-05 08:43:06.834 DIAG    CURRENT USER = "DBA_menu"
2019-11-05 08:43:06.834 DIAG  EXECUTING USER = "DBA"
2019-11-05 08:43:06.850 DIAG   INVOKING USER = "DBA_menu"
2019-11-05 08:43:06.850 DIAG    SESSION USER = "DBA_menu"
2019-11-05 08:43:06.850 DIAG PROCEDURE OWNER = "DBA"

Monitor Options page, after FORWARD TO (note same connection number 19)...

2019-11-05 08:44:24.808 DIAG ***** 19 ***** SERVICE rroad_monitor_options()
2019-11-05 08:44:24.808 DIAG    CURRENT USER = "DBA_monitor_options"
2019-11-05 08:44:24.824 DIAG  EXECUTING USER = "DBA"
2019-11-05 08:44:24.824 DIAG   INVOKING USER = "DBA_monitor_options"
2019-11-05 08:44:24.824 DIAG    SESSION USER = "DBA_monitor_options"
2019-11-05 08:44:24.824 DIAG PROCEDURE OWNER = "DBA"

Foxhound connection-level samples showing two Foxhound views of the same three connections to the target database, two real and one goofy:

Session Target       Conn # Conn Name              req_status  msec    What am I? 
------- ------------ ------ --------------------- ----------- -------- ----------
      7 ddd17             1 Foxhound-Monitor-8868 Executing   15366323    Real!   
      7 ddd17             2 Foxhound-Monitor-8868 Idle        15357421    Real!   
      7 ddd17             5 Foxhound-Monitor-8868 Idle              14    Goofy!  
      8 ddd17 string      1 Foxhound-Monitor-8868 Idle        15366369    Real!   
      8 ddd17 string      2 Foxhound-Monitor-8868 Executing   15367277    Real!   
      8 ddd17 string      5 Foxhound-Monitor-8868 Idle              14    Goofy!

Here's a description of the snapshot above...

There are two Foxhound sampling sessions (7 and 😎 connected to the same target database ddd17.db, one via DSN and the other via DSN-less connection string.

Each sampling session "sees" three connections on the target database: It's own real connection to the target database, the other session's real connection to the target database, and the goofy connection.

That means Foxhound is recording six sets of data; i.e., 3 connections times 2 sessions.

Note... The user ids DBA_menu and DBA_monitor_options are DBA-privilege user ids used ONLY for CREATE SERVICE AUTHORIZATION OFF USER clauses...

GRANT CONNECT TO DBA_menu IDENTIFIED BY "...";
GRANT DBA TO DBA_menu;
GRANT MEMBERSHIP IN GROUP DBA TO DBA_menu;
CREATE SERVICE rroad_administrator_login TYPE 'RAW' 
   AUTHORIZATION OFF USER DBA_menu
   AS CALL rroad_administrator_login();

Don't ask me "Why?", that AUTHORIZATION OFF USER clause setup was first used over 10 years ago and it has worked ever since 🙂

Re: How do I debug FORWARD TO creating a persistent idle connection?

Breck_Carter — Tue, 05 Nov 2019 09:07:56 GMT

PS the last CREATE EXTERNLOGIN statement was removed in 2008. All targets are SQL Anywhere.

Re: How do I debug FORWARD TO creating a persistent idle connection?

VolkerBarth — Tue, 05 Nov 2019 09:21:50 GMT

Hm, in my understanding the extern_login_credentials option set to its "pre-v16 default" "Login_user" does explain why a second connection is used (because the session user has changed - how do you do that for a running connection - via SETUSER?).

However, I would have thought the option set to "Effective_user" would mean that in both cases the executing user is "dba" and therefore only one remote connection is done...

Whcih basically means, I still have not fully understood the extern_login_credentials settings...

Re: How do I debug FORWARD TO creating a persistent idle connection?

Breck_Carter — Tue, 05 Nov 2019 10:57:06 GMT

> I still have not fully understood the extern_login_credentials settings

Indeed... it is worse for me, the more times I read the docs, the less I understand.

> via SETUSER?

No, I have never used SETUSER... ever 🙂

My current "wave a dead chicken" thought is to change the service definitions to AUTHORIZATION OFF USER DBA so that DBA is the only user id in use.

The Foxhound database almost entirely walled off from end users via client-server database connections... there is a read-only ADHOC reporting user id, and a new ADMIN user id that can only UPDATE a few columns in one single row of one single table... so all this talk of "session", "effective" and "login" is moot...

. . . DBA !