@SeanGallardy-Microsoft I've just published whilst connected to the VPN - this time with the option to re-create all database objects and it is hanging whilst executing ALTER ASSEMBLY tSQLtCLR WITH PERMISSION_SET = EXTERNAL_ACCESS; the call stack for that is

ntdll.dll!NtAlpcSendWaitReceivePort()
rpcrt4.dll!LRPC_CCALL::SendReceive(struct _RPC_MESSAGE *)
rpcrt4.dll!NdrpClientCall3()
rpcrt4.dll!NdrClientCall3()
sechost.dll!LsaICLookupSids()
sechost.dll!LsaLookupTranslateSids()
sechost.dll!LookupAccountSidInternal()
sechost.dll!LookupAccountSidLocalW()
advapi32.dll!LookupAccountSidW()
sqllang.dll!LookupAccountSidInternal(unsigned short const * const,unsigned char *,unsigned short *,unsigned short *,char,enum _SID_NAME_USE *)
sqllang.dll!CWindowsSecurityPrimaryInfo::GetNtGroupsViaAuthZ(class IMemObj *)

So sqllang.dll!CStmtAlterAssembly::FChangePermissionSet is obviously correlated with the SQL and that ends up calling sqllang.dll!FVerifyAssemblyPermsForSids which eventually hangs for some reason. I'll try and repro the situation yesterday where calling CLR methods was hanging too

Hmmm - annoyingly I can't repro that now. It always gets stuck at ALTER ASSEMBLY tSQLtCLR WITH PERMISSION_SET = EXTERNAL_ACCESS; and then if I turn off the internet connection becomes unblocked and then the tsqlt tests succeed even when the internet is reconnected with the VPN running. I'm not sure how to get into the state I was in yesterday where the assembly was successfully installed with external access but calling CLR methods on it were blocked indefinitely.

@SolomonRutzky yep maybe something isn't quite configured correctly on the VPN - when not connected it doesn't bother trying but when connected it tries and for some reason fails.

@MartinSmith When you did this publish and selected to recreate everything, that includes the tSQLt objects as well, correct? And if so, when it hung on ALTER ASSEMBLY, that was when it was creating the tSQLt objects, and not yet running the tests, correct?

tSQLt installs the Assembly as SAFE and then calls EXEC tSQLt.EnableExternalAccess; which would explain why it got hung there and not where it did yesterday. But even if it did hang on a step past where it got hung yesterday, I think I know why, and why the tests worked while connected to the VPN after the initial run.

To have this documented: tSQLt starts here ( github.com/tSQLt-org/tSQLt/blob/master/Source/… ) which queries this TSQL TVF ( github.com/tSQLt-org/tSQLt/blob/master/Source/… ) which calls the UDT ( github.com/tSQLt-org/tSQLt/blob/master/tSQLtCLR/tSQLtCLR/… ). This is where it was hanging initially when this question was posted.

More recently, it got hung on changing the Permission_Set, which now that I look again, might only happen in tSQLt.EnableExternalAccess; which is called at the end of the Private_Init procedure (which is after the call to .Info()).

SO, given that once it installed it continued working, even with the VPN connected, I would say that it is due to caching. It could be that once it installed the Assembly was loaded in memory and didn't need to be checked again for your login; OR the credentials were cached by SQL Server; OR the execution plan was cached and did not recheck permissions.

If you can get to the state you were in yesterday with it working even when connected to the VPN, then unload the App Domain via ALTER DATABASE [your_db_name] SET TRUSTWORTHY OFF; and re-run the test. If it works, drop all the caching via DBCC FREESYSTEMCACHE('ALL'); and re-run.

Please note that if the Assembly is already set to EXTERNAL_ACCESS, then attempting to ALTER again to EXTERNAL_ACCESS will effectively be ignored, so I assume no OS permissions check on the SID. So if everything continues working, you can also ALTER ASSEMBLY tSQLtCLR WITH PERMISSION_SET = SAFE; and re-run the test to see if it gets hung on the ALTER to EXTERNAL_ACCESS.

@MartinSmith I don't necessarily think that the VPN is misconfigured. I think it sees a network route to the domain controller when the VPN is connected and so attempts to get current info, but when no route to the domain controller is there, it just uses the cached credentials.

ALTER DATABASE [mydb] SET TRUSTWORTHY OFF; then running tSQLt.RunAll throws an error that is caught and then the tests succeed. The assembly is left in SAFE_ACCESS mode. So presumably I'm not actually using anything that needs this anyway.

I forgot to ask before: what version of tSQLt are you using?

Assuming you are still connected to the VPN, and with changing TRUSTWORTHY it unloaded the App Domain and presumably any cached plans using the Assembly, that points to the issue not having anything to do with cached object credentials or cached plans. Mainly due to the call to .Info() not getting hung. Maybe FREESYSTEMCACHE will show something..

Version is 1.0.5873.27393 - I've disconnected from the VPN and set trustworthy back on and EXTERNAL_ACCESS back - will try FREESYSTEMCACHE now

And tests work fine. So not sure how I got into the state that it hangs onSELECT @r = CASE WHEN I.Version = I.ClrVersion THEN 1 ELSE 0 END FROM tSQLt.Info() AS I;',N'@r BIT OUTPUT - I do sometimes also see the message from the error handler there

Cannot access CLR. Assembly might be in an invalid state. Try running EXEC tSQLt.EnableExternalAccess @enable = 0; or reinstalling tSQLt.

Next time that happens I'll see what the specific error was in case that gives any clues

Ah actually I can get that to happen by running SET TRUSTWORTHY OFF and then running the tests with the assembly already in place with EXTERNAL_ACCESS on, will try setting trustworthy back on...

Ah and that does it!

What is the "it" that it does? ;-)

Now I get hung on the (@r BIT OUTPUT)SELECT @r = CASE WHEN I.Version = I.ClrVersion THEN 1 ELSE 0 END FROM tSQLt.Info() AS I; call. I'll see what the call stack is

Can you check to see if the App Domain is loaded or not? SELECT * FROM sys.dm_clr_appdomains;

There is one app domain loaded for that database - but the database uses 2 CLR assemblies, should I expect to see two or one?

One App Domain

Try: SELECT * FROM sys.dm_clr_loaded_assemblies;

Both assemblies have the same owner, so both in the same App Domain

But one of them I don't think is being used at this point..it just has test SQLCLR objects..

the sys.dm_clr_loaded_assemblies returns no rows - probably no CLR method has been successfully called yet since I toggled the trustworthy setting

Right, and it can't load the Assembly since TRUSTWORTHY is OFF yet the Permission_Set = EXTERNAL_ACCESS, and I assume you never set up the Permissions Key in master..

So, with TRUSTWORTHY OFF in both cases: with PermissionSet = SAFE, it doesn't hang, but with PermissionSet = EXTERNAL_ACCESS it does. I would say the diff is that the first case the call to .Info() works as there is no reason it shouldn't, but the attempt to set it to EXTERNAL_ACCESS fails for the reason stated, yet that is merely a meta-data operation.

yep I'm pretty sure I never set up any permissions ley in master - just getting the stack...

BUT, in the second case, it hangs on the call to .Info() due to a) the Assembly was not loaded into memory, and b) loading it requires an actual permissions check. Once loaded, you can connect to the VPN since the Assembly is already loaded and no more external permissions check.

Yep makes sense - I see clr.dll!AssemblySpec::LoadDomainAssembly in the stack this time. Full stack incoming...

ntdll.dll!NtAlpcSendWaitReceivePort()
rpcrt4.dll!LRPC_CCALL::SendReceive(struct _RPC_MESSAGE *)
rpcrt4.dll!NdrpClientCall3()
rpcrt4.dll!NdrClientCall3()
sechost.dll!LsaICLookupSids()
sechost.dll!LsaLookupTranslateSids()
sechost.dll!LookupAccountSidInternal()
sechost.dll!LookupAccountSidLocalW()
advapi32.dll!LookupAccountSidW()
sqllang.dll!LookupAccountSidInternal(unsigned short const * const,unsigned char *,unsigned short *,unsigned short *,char,enum _SID_NAME_USE *)
sqllang.dll!CWindowsSecurityPrimaryInfo::GetNtGroupsViaAuthZ(class IMemObj *)

In which case, you can probably turn TRUSTWORTHY back ON, connect to the VPN, and re-run the test. It should hang due to the app domain being unloaded by changing TRUSTWORTHY and so it needs the permissions check. Disconnect. Run again to see that it works. Connect to VPN. run again to see that it still works. While still connection to VPN, turn TRUSTWORTHY OFF and then back ON again to unload App Domain. re-run test. It should hang.

the test above was with trustworthy toggled back on and connected to the VPN - it did hang and the stack trace above was during that.

with the assembly installed and trustworthy off I just went straight to the error handler telling me that Cannot access CLR. Assembly might be in an invalid state. Try running EXEC tSQLt.EnableExternalAccess @enable = 0; or reinstalling tSQLt.

As soon as I disconnect from the VPN I got unblocked from the above hang and it continued running the tests

Right

So I'll try connecting back to the VPN now and running all tests again

So with trustworthy OFF and it going straight to that error, that is due to the Assembly being EXTERNAL_ACCESS and failing the FIsAssemblyAuthorized call since the Asymmetric Key isn't installed and Trustworthy is OFF...but that is in a TRY / CATCH so you get the tSQLt custom error, masking the SQL error that you saw when it tried to ALTER ASSEMBLY (i.e. not authorized for EXTERNAL_ACCESS) since that isn't in a TRY / CATCH

yep. I justy did your "Connect to VPN. run again to see that it still works." step and it does - trying the next thing...

The internal call to FIsAssemblyAuthorizedis just a meta-data check, as far as I can see and the evidence shows. But if you get passed that, then it checks OS permissions, but only when the Assembly is not marked as SAFE, which why when it was SAFE you only got the "not authorized for EXTERNAL_ACCESS" error since it was attempting to set to EXTERNAL_ACCESS as it always tries to do.

RE: "While still connection to VPN, turn TRUSTWORTHY OFF and then back ON again to unload App Domain. re-run test. It should hang." I tried that and it didn't hang but then added DBCC FREESYSTEMCACHE('ALL'); in and it did.

@SolomonRutzky yep makes sense!

@MartinSmith Hmm...That is odd. Do you mind getting back to this state where you were connected to the VPN, it didn't hang on testing, and then you reset trustworthy OFF and then back ON? Do the SELECT * FROM sys.dm_clr_appdomains; again, before running tSQLt again, to confirm that the App Domain is gone.

I have seen in the past where reseting TRUSTWORTHY doesn't unload the App Domain if the reset is done by issuing ALTER DATABASE ... OFF; ALTER ... ON; highlighted together and ran as a single submission..

Just done the following...

ALTER DATABASE MYDB SET TRUSTWORTHY OFF;
ALTER DATABASE MYDB SET TRUSTWORTHY ON;

SELECT * from sys.dm_clr_appdomains;
SELECT * FROM sys.dm_clr_loaded_assemblies;
EXEC tSQLt.RunAll

And the tests ran without issue though app domain had definitely gone - I guess it must cache permissions info?

Right, that is what I was wanting to narrow down and confirm..

the FREESYSTEMCACHE gets rid of everything.

So the permissions check is cached outside of the App Domain...

Yep I'll try running again with that called first just to be sure it is repeatable

Aagh - And this time the tests run :-(

? trustworthy is ON, permission_Set = EXTERNAL_ACCESS, and you did the DBCCFREESYSTEMCACHE('ALL') before anything else?

oh, and VPN is connected?

yes to all of those

running

DBCC FREESYSTEMCACHE('ALL');
ALTER DATABASE MyDB SET TRUSTWORTHY OFF;
ALTER DATABASE MyDB SET TRUSTWORTHY ON;
select * from sys.assemblies
SELECT * from sys.dm_clr_appdomains;
SELECT * FROM sys.dm_clr_loaded_assemblies;
EXEC tSQLt.RunAll

But TBH I'm quite happy to leave this as a mystery, the stack above shows that loading the assembly can certainly cause me to get hung up waiting for permissions so that's good enough to explain the original hang (if not why I don't always get it)

hmm...but I also feel that we are soooo close to this...must be something rather small at this point..

with the DBCC call in there you can remove the ALTER DATABASE..

both ALTER DATABASE lines, actually, can be removed...the FREESYSTEMCACHE('ALL') unloads all App domains in the Instance..

One thing to consider:

Hah - I've just removed both ALTER DATABASE calls and now it is hanging again. Maybe it is cached somewhere untouched by anything we are doing and expires after a certain time?

Is it possible that the ALTER TRUSTWORTHY ON needed a permissions check of its own, which got cached?

try again with just the DBCC and no ALTER DB to see if repeatable..

App Domains can get get unloaded after time due to memory pressure...you would see that in the error_log..

Hm...I think I just remembered something..

about DBCC FREESYSTEMCACHE..

I think it just marks stuff to be released, but doesn't guarantee immediate release of all cached info..

Yeah, MSDN says "Releases all unused cache entries from all caches." (emphasis added)..

better to use: DBCC FREESYSTEMCACHE('ALL') WITH MARK_IN_USE_FOR_REMOVAL;

I see AppDomain 37 (MyDB.dbo[runtime].36) is marked for unload due to common language runtime (CLR) or security data definition language (DDL) operations. and both the DMVs (sys.dm_clr_appdomains, sys.dm_clr_loaded_assemblies) return nothing for that DB - but the test still succeeds. Will try that one.

and maybe give it 30 seconds or so after running DBCC before testing again...not sure what the requirement is for being considered no longer "in use"..

I tried the following and the tests run without issue

DBCC FREESYSTEMCACHE('ALL') WITH MARK_IN_USE_FOR_REMOVAL;
WAITFOR DELAY '00:00:30'
ALTER DATABASE MyDB SET TRUSTWORTHY OFF;
ALTER DATABASE MyDB SET TRUSTWORTHY ON;
SELECT * from sys.dm_clr_appdomains;
SELECT * FROM sys.dm_clr_loaded_assemblies;
EXEC tSQLt.RunAll

then I tried this and they failed

DBCC FREESYSTEMCACHE('ALL') WITH MARK_IN_USE_FOR_REMOVAL;
WAITFOR DELAY '00:00:30'
SELECT * from sys.dm_clr_appdomains;
SELECT * FROM sys.dm_clr_loaded_assemblies;
EXEC tSQLt.RunAll

is the latter test repeatable?

But I suspect that if I retry the second one after reconnecting to the VPN they will succeed -does seem like there is a time based thing. Will just try.

is possible that 30 seconds isn't enough time. Or that a second call to DBCC after the WAITFOR DELAY would clear things out better..

yep that wasn't repeatable

Second DBCC doesn't cause the hang - pretty sure if I just wait x amount of time and retry it will do a permissions check and hang.

I wonder if there is caching at the OS level...

Let's say you wait 5 minutes and it hangs. Did you also test running these successfully 7 hours ago for a period longer than you are testing now?

Meaning, once you saw this working over the VPN, did you continue running the tests for a longer period of time than we are waiting for now for the "timeout"?

Would make sense if there was caching at the OS level rather than having to hit the DC every time. I'm not sure TBH for the second question as once I realised the VPN was causing my woes I probably just disconnected

Right, so possibly DBCC isn't doing anything..

outside of the unloading of the app domain

if this is working over the VPN, I wonder if waiting 5 minutes or so, but staying connected, and then trying again would cause it to hang again..

yep - I just got another hang and disconnected from the VPN and ran all tests successfully at 19:42:30 - will try running the tests first at 19:47:30 then the DBCC - but the stack trace above shows that loading the assembly can definitely cause my issue and the DBCC will ensure that happens.

Right, but just to be clear, at this point we can only be sure that the DBCC ensures that it happens due to it causing an instance-wide unloading of App Domains.

which, of course, is necessary to reproduce this since it is the loading of the Assembly that causes the SID lookup.

I wonder if there is anything else we can do in SQL Server, not related to SQLCLR, that would require the same SID permissions check...

Basically, I am wondering why this is getting hung in the first place. If this gets hung, then would other operations needing the same permissions verification, also hang? Even outside of SQL Server? OR, is it possible that this is a bug within SQL Server related to how SQLCLR is performing the permissions verification?

Ran the same thing repeatedly with no hang until 19:51:54 - so if it is time based it is around 9 minutes - unfortunately must go now though, thanks for your help!

Np...should I start typing up an answer?

I think it is clear enough now as to where the issue mostly is...just haven't nailed down that caching..

yet

;-).

I guess I can submit what we have so far and update it if/when we have more info..

Yes please. I think the case is basically cracked even if there’s a few looose ends!