(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

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


current timestamp,Number,Name,

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,

2019-10-31 10:08:16.272,2,'ddd17-1',
   'dba',0,'2019-10-31 10:08:16.272','FETCH','local','',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,

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,

2019-10-31 10:08:16.272,1000000001,'INT: StmtPerfMngrConn',
   '',0,'','unknown (0)','NA','NA',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 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 )

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 ...
     INTO ...
     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 )

-- © 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 '';

-- 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 + '''';




         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


   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;


RETURN @string_return_value;

END; -- f_forward_string_function_call

asked 31 Oct, 10:58

Breck%20Carter's gravatar image

Breck Carter
accept rate: 20%

edited 03 Nov, 08:13

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

(31 Oct, 13:26) Volker Barth
Replies hidden

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=;HOST=XPS;OSUSER=Breck;
   OS='Windows 10 Build 17134 ';EXE='C:\Program Files\SQL Anywhere 17\Bin64\dbsrv17.exe';
CommLink                                 local                
CommNetworkLink                          TCPIP                
CommProtocol                             CmdSeq               
ConnectedTime                            0                    
connection_authentication                Company=Sybase;
connection_type                          Standard             
LastPlanText                             ( Plan 
  ( SingleRowGroupBy 
    ( NestedLoopsJoin
      ( IndexScan ( ISYSUSER su ) user_name )
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                 
UserID                                   dba                  
webservice_sessionid_name                SessionID            
(331 rows)
(31 Oct, 16:51) Breck Carter

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 ( ', 
      ' 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 + '''';


...doesn't help.

(31 Oct, 17:13) Breck Carter

Should I try request level logging?

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

(31 Oct, 17:25) Breck Carter

And then there's cis_option = 7.

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

(31 Oct, 17:31) Breck Carter

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 )
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;
(01 Nov, 05:04) Breck Carter

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 :)

(01 Nov, 10:37) Breck Carter

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

(01 Nov, 10:39) Breck Carter

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

Cf. that FAQ...

(01 Nov, 11:54) Volker Barth

oooh, oooh ...

...please let it be so! :)

(02 Nov, 06:53) Breck Carter

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 :)

(02 Nov, 09:19) Breck Carter

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

(02 Nov, 10:41) Volker Barth

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?

(03 Nov, 08:16) Breck Carter

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...

(03 Nov, 11:22) Volker Barth

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 :)

(05 Nov, 08:14) Breck Carter
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 8) 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...

CREATE SERVICE rroad_administrator_login TYPE 'RAW' 
   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 :)

(05 Nov, 09:01) Breck Carter

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

(05 Nov, 09:07) Breck Carter

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...

(05 Nov, 09:21) Volker Barth

> 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 !

(05 Nov, 10:57) Breck Carter

No Dead Chicken Joy... I can get all the "XXX USER" thingies to be the same by using AUTHORIZATION OFF USER DBA, but the goofy connection still appears.

2019-11-05 11:11:04.515 DIAG ***** 22 ***** SERVICE rroad_administrator_login()
2019-11-05 11:11:04.516 DIAG    CURRENT USER = "DBA"
2019-11-05 11:11:04.516 DIAG  EXECUTING USER = "DBA"
2019-11-05 11:11:04.516 DIAG   INVOKING USER = "DBA"
2019-11-05 11:11:04.516 DIAG    SESSION USER = "DBA"
2019-11-05 11:11:04.516 DIAG PROCEDURE OWNER = "DBA"

2019-11-05 11:11:35.012 DIAG ***** 22 ***** SERVICE rroad_monitor_options()
2019-11-05 11:11:35.015 DIAG    CURRENT USER = "DBA"
2019-11-05 11:11:35.020 DIAG  EXECUTING USER = "DBA"
2019-11-05 11:11:35.024 DIAG   INVOKING USER = "DBA"
2019-11-05 11:11:35.028 DIAG    SESSION USER = "DBA"
2019-11-05 11:11:35.035 DIAG PROCEDURE OWNER = "DBA"

Session,Target,Conn #,Conn Name,current_req_status,msec between Login and LastReq,What am I?
7,'ddd17',1,'Foxhound-Monitor-20068','Idle',255514,'   Real!'
7,'ddd17',2,'Foxhound-Monitor-20068','Executing',255216,'   Real!'
7,'ddd17',3,'Foxhound-Monitor-20068','Idle',14,'   Goofy!'
8,'ddd17 string',1,'Foxhound-Monitor-20068','Executing',255482,'   Real!'
8,'ddd17 string',2,'Foxhound-Monitor-20068','Executing',255184,'   Real!'
8,'ddd17 string',3,'Foxhound-Monitor-20068','Idle',14,'   Goofy!'
(05 Nov, 11:14) Breck Carter

FYI the "Session" values 7, 8 are NOT SQL Anywhere HTTP sessions, they are Foxhound "sampling sessions".

There is only one HTTP session, started by rroad_administrator_login, and ALL the HTTP services after that are using the same connection number 22.

(05 Nov, 11:21) Breck Carter

And still "goofy" connections both with option "effective_user"?

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


(05 Nov, 11:32) Volker Barth

> And still "goofy" connections both with option "effective_user"?

SET OPTION PUBLIC.extern_login_credentials = 'Effective_user';

As reported earlier, it makes everything worse.

Now there are FOUR connections RIGHT AWAY, before sa_set_http_option 'SessionID' is even called.

As before, Foxhound has double-vision because it has two sample sessions for the same target; i.e., it sees the four connections twice:

Session,Target,sample_set_number,Conn #,Conn Name,current_req_status,msec between Login and LastReq,What am I?
7,'ddd17',62452,1,'Foxhound-Monitor-22764','Idle',169804,'   Real!'
7,'ddd17',62452,2,'Foxhound-Monitor-22764','Executing',169649,'   Real!'
7,'ddd17',62452,3,'Foxhound-Monitor-22764','Idle',158496,'   Real!'
7,'ddd17',62452,4,'Foxhound-Monitor-22764','Idle',158493,'   Real!'
8,'ddd17 string',62459,1,'Foxhound-Monitor-22764','Idle',169804,'   Real!'
8,'ddd17 string',62459,2,'Foxhound-Monitor-22764','Idle',169712,'   Real!'
8,'ddd17 string',62459,3,'Foxhound-Monitor-22764','Idle',168398,'   Real!'
8,'ddd17 string',62459,4,'Foxhound-Monitor-22764','Executing',168301,'   Real!'

Not only that, but the extra connection are REAL connections, doing REAL work... so they pass the "msec between Login and LastReq".

I believe these are the extra connections Karim talked about, and they are caused by other FORWARD TO operations (of which Foxhound has many).

I believe my goofy symptom is DIFFERENT, and has NOTHING to do with extern_login_credentials.

Now, let's see what happens when the Foxhound Login-then-Monitor-Options test is performed...

The owners are OK, just like before, all DBA...

2019-11-05 15:45:46.228 DIAG ***** 248 ***** SERVICE rroad_administrator_login()
2019-11-05 15:45:46.230 DIAG    CURRENT USER = "DBA"
2019-11-05 15:45:46.231 DIAG  EXECUTING USER = "DBA"
2019-11-05 15:45:46.232 DIAG   INVOKING USER = "DBA"
2019-11-05 15:45:46.233 DIAG    SESSION USER = "DBA"
2019-11-05 15:45:46.235 DIAG PROCEDURE OWNER = "DBA"
2019-11-05 15:45:52.290 DIAG ***** 253 ***** SERVICE rroad_administrator_login()
2019-11-05 15:45:52.292 DIAG    CURRENT USER = "DBA"
2019-11-05 15:45:52.294 DIAG  EXECUTING USER = "DBA"
2019-11-05 15:45:52.295 DIAG   INVOKING USER = "DBA"
2019-11-05 15:45:52.296 DIAG    SESSION USER = "DBA"
2019-11-05 15:45:52.298 DIAG PROCEDURE OWNER = "DBA"
2019-11-05 15:45:57.073 DIAG ***** 253 ***** SERVICE rroad_monitor_options()
2019-11-05 15:45:57.075 DIAG    CURRENT USER = "DBA"
2019-11-05 15:45:57.076 DIAG  EXECUTING USER = "DBA"
2019-11-05 15:45:57.077 DIAG   INVOKING USER = "DBA"
2019-11-05 15:45:57.078 DIAG    SESSION USER = "DBA"
2019-11-05 15:45:57.079 DIAG PROCEDURE OWNER = "DBA"

But now the goofy connection has appeared, for a total of FIVE connections (or 10, as seen by Foxhound):

Session,Target,sample_set_number,Conn #,Conn Name,current_req_status,msec between Login and LastReq,What am I?
7,'ddd17',62860,1,'Foxhound-Monitor-22764','Idle',674958,'   Real!'
7,'ddd17',62860,2,'Foxhound-Monitor-22764','Executing',674803,'   Real!'
7,'ddd17',62860,3,'Foxhound-Monitor-22764','Idle',663670,'   Real!'
7,'ddd17',62860,4,'Foxhound-Monitor-22764','Idle',663651,'   Real!'
7,'ddd17',62860,8,'Foxhound-Monitor-22764','Idle',21,'   Goofy!'
8,'ddd17 string',62866,1,'Foxhound-Monitor-22764','Idle',674958,'   Real!'
8,'ddd17 string',62866,2,'Foxhound-Monitor-22764','Idle',674849,'   Real!'
8,'ddd17 string',62866,3,'Foxhound-Monitor-22764','Idle',673554,'   Real!'
8,'ddd17 string',62866,4,'Foxhound-Monitor-22764','Executing',673473,'   Real!'
8,'ddd17 string',62866,8,'Foxhound-Monitor-22764','Idle',21,'   Goofy!'

So, no, 'Effective_user' is not what I want :)

(05 Nov, 15:55) Breck Carter

Of course, I don't want the goofy connection either, but I think I'm just gonna have to ignore it.

(05 Nov, 16:11) Breck Carter
More comments hidden
showing 5 of 24 show all flat view
Be the first one to answer this question!
toggle preview

Follow this question

By Email:

Once you sign in you will be able to subscribe for any updates here



Answers and Comments

Markdown Basics

  • *italic* or _italic_
  • **bold** or __bold__
  • link:[text](http://url.com/ "title")
  • image?![alt text](/path/img.jpg "title")
  • numbered list: 1. Foo 2. Bar
  • to add a line break simply add two spaces to where you would like the new line to be.
  • basic HTML tags are also supported

Question tags:


question asked: 31 Oct, 10:58

question was seen: 132 times

last updated: 05 Nov, 16:11