Tuesday, November 11, 2014

Importing SQLPS module results in Warnings

Update (June 2015): After originally posting this back in Nov, and debugging the issue earlier in the year I finally got around to recording my findings and updating this blog post. Hopefully this post also provides some insight into methods for Debugging PowerShell when faced with Provider issues.

I've been meaning to blog about this for a while now. If you do any work with PowerShell, SQL Server and Azure then chances are you have noticed that when you import the SQL module it reports the errors:

Errors as per below
WARNING: Could not obtain SQL Server Service information. An attempt to connect to WMI on
'Microsoft.WindowsAzure.Commands.SqlDatabase.Types.ps1xml' failed with the following error: The RPC server is
unavailable. (Exception from HRESULT: 0x800706BA)
WARNING: Could not obtain SQL Server Service information. An attempt to connect to WMI on
'Microsoft.WindowsAzure.Commands.SqlDatabase.Types.ps1xml' failed with the following error: The RPC server is
unavailable. (Exception from HRESULT: 0x800706BA)
...
WARNING: Could not obtain SQL Server Service information. An attempt to connect to WMI on
'Microsoft.WindowsAzure.Commands.SqlDatabase.dll' failed with the following error: The RPC server is unavailable.
(Exception from HRESULT: 0x800706BA)
WARNING: The names of some imported commands from the module 'sqlps' include unapproved verbs that might make them less
 discoverable. To find the commands with unapproved verbs, run the Import-Module command again with the Verbose
parameter. For a list of approved verbs, type Get-Verb.

The following Modules are affected by the issues described within this blog.

Module Version Notes
SQLPS 1.0 SQL 2014 release
SQLASCMDLETS 1.0 SQL 2014 release
Azure 0.8.8 Azure SDK June 2014 Release

Firstly a warning, do not modify any of the files mentioned in this blog as I will be exploring the code which runs when you import a module, but these are signed and any modifications may break the module functionality.

People generally notice this error when they run:

Import-Module SQLPS

What happens when you run this command is PowerShell loads up the Module Mainfest C:\Program Files (x86)\Microsoft SQL Server\120\Tools\PowerShell\Modules\SQLPS\SQLPS.PSD1


This references a number of other code bases.

Firstly a number of nested modules, most significantly both "Microsoft.SqlServer.Management.PSSnapins.dll" and "Microsoft.SqlServer.Management.PSProvider.dll" which load up the SQLPS provider and set the PSDrive path to the path of PS SQLSERVER:>

It also loads up the script file SqlPsPostScript.PS1 in the same path..... It is the code in this script where the warning is generated from (but this is not the cause).

This script has a step which is designed to import the SQLASCmdlets module and it is this step which is throwing the warnings. However, this isn't really to do with the loading of the SQL module but due to the Get-Module command which is executed.
#Load the SQLAS Module
$m = Get-Module -ListAvailable | where {$_.Name -eq "SQLASCmdlets"}
if($m -ne $null) { Import-Module $m -Global }

After a bit of troubleshooting I found that the problem even happens if you just run Get-Module -ListAvailable from within the SQLPS provider.



However if you run Get-Module -ListAvailable from another Provider (e.g. FileSystem) this does not return the error.



So the culprit is within the way the SQLPS Provider (via the PSDrive) implements standard cmdlets. You can see this even with Import-Module cmdlet when it specifically tries to work with the Azure module when the path is set to SQLSERVER:\.



Now typically this is where most would get stuck as the SqlPs and Azure modules are Binary Modules (aka it loads .dlls) so the general public cannot dig into the code.

However, here we can leverage PowerShell debugging to go deep into the code stack. So the actions that I took next were:

1) Use the -Debug switch parameter on the Import-Module
Import-Module -Name SqlPs -Debug

2) Use Trace-Command
Trace-Command -Expression {Import-Module SQLPS} -FilePath C:\ImportModuleTraceCommand.txt -Name * -Option All

Using the output captured by these commands we can actually trace the problem down further in the stack.

Firstly by looking at the Debug output we can see the following function calls just before the WMI errors.

---------------------------------------------------------------------------
DEBUG: ItemExists: SQLSERVER:\Services\Microsoft.WindowsAzure.Commands.Websites.Types.ps1xml
DEBUG: ItemExists: SQLSERVER:\Sql\Microsoft.WindowsAzure.Commands.SqlDatabase.Types.ps1xml
WARNING: Could not obtain SQL Server Service information. An attempt to connect to WMI on 'Microsoft.WindowsAzure.Commands.S
qlDatabase.Types.ps1xml' failed with the following error: The RPC server is unavailable. (Exception from HRESULT: 0x800706BA
)
---------------------------------------------------------------------------

This tells us that the module loading is calling the ItemExists function to test a path for a file it is told to load (and we already know that the path is coming from the definition of the Azure module).

Next we can look at the Trace-Command data.

If you compare the logical code variations between the two extracts you can clearly see that the first resolves the path to the FILESYSTEM provider but the second resolves the path to the SQLSERVER provider. If we look even more closely we see a function call output by "Path is DRIVE-QUALIFIED" which returns true on the first and false on the second, and because it returns false on the second it then sets the SQLPROVIDER to go checking for the paths off the base drive which in this case is SQLSERVER:, and eventually fails with "ERROR: Item does not exist".


Successful loading of types file:

PathResolution Information: 0 :                                                     Resolving MSH path "C:\Program Files (x86)\Microsoft SDKs\Azure\PowerShell\ServiceManagement\Azure\.\Services\Microsoft.WindowsAzure.Commands.Websites.Types.ps1xml" to MSH path
...
PathResolution Information: 0 :                                                         Path is DRIVE-QUALIFIED
LocationGlobber Information: 0 :  WriteLine                                                           result = True
LocationGlobber Information: 0 :  WriteLine                                                           Drive Name: C
SessionState Information: 0 :  WriteLine                                                           Drive found in scope 1
LocationGlobber Information: 0 :  WriteLine                                                           path = Program Files (x86)\Microsoft SDKs\Azure\PowerShell\ServiceManagement\Azure\.\Services\Microsoft.WindowsAzure.Commands.Websites.Types.ps1xml
CmdletProviderClasses Information: 0 :  WriteLine                                                           result=Program Files (x86)\Microsoft SDKs\Azure\PowerShell\ServiceManagement\Azure\.\Services\Microsoft.WindowsAzure.Commands.Websites.Types.ps1xml
CmdletProviderClasses Information: 0 :  WriteLine                                                           result=C:\Program Files (x86)\Microsoft SDKs\Azure\PowerShell\ServiceManagement\Azure\.\Services\Microsoft.WindowsAzure.Commands.Websites.Types.ps1xml
SessionState Information: 0 :  WriteLine                                                           result = C:\Program Files (x86)\Microsoft SDKs\Azure\PowerShell\ServiceManagement\Azure\.\Services\Microsoft.WindowsAzure.Commands.Websites.Types.ps1xml
CmdletProviderClasses Information: 0 :  WriteLine                                                           basePath = C:\
...
PathResolution Information: 0 :                                                         DRIVE-RELATIVE path: Program Files (x86)\Microsoft SDKs\Azure\PowerShell\ServiceManagement\Azure\Services\Microsoft.WindowsAzure.Commands.Websites.Types.ps1xml
PathResolution Information: 0 :                                                         Drive: C
PathResolution Information: 0 :                                                         Provider: Microsoft.PowerShell.Core\FileSystem
...
PathResolution Information: 0 :                                                         RESOLVED PATH: C:\Program Files (x86)\Microsoft SDKs\Azure\PowerShell\ServiceManagement\Azure\Services\Microsoft.WindowsAzure.Commands.Websites.Types.ps1xml




Unsuccessful loading of types file:
PathResolution Information: 0 :                                                 Resolving MSH path ".\Sql\Microsoft.WindowsAzure.Commands.SqlDatabase.Types.ps1xml" to PROVIDER-INTERNAL path
...
PathResolution Information: 0 :                                                     Path is DRIVE-QUALIFIED
LocationGlobber Information: 0 :  WriteLine                                                       result = False
LocationGlobber Information: 0 :  WriteLine                                                       path = Sql\Microsoft.WindowsAzure.Commands.SqlDatabase.Types.ps1xml
CmdletProviderClasses Information: 0 :  WriteLine                                                       result=Sql\Microsoft.WindowsAzure.Commands.SqlDatabase.Types.ps1xml
CmdletProviderClasses Information: 0 :  WriteLine                                                       result=SQLSERVER:\Sql\Microsoft.WindowsAzure.Commands.SqlDatabase.Types.ps1xml
SessionState Information: 0 :  WriteLine                                                       result = SQLSERVER:\Sql\Microsoft.WindowsAzure.Commands.SqlDatabase.Types.ps1xml
CmdletProviderClasses Information: 0 :  WriteLine                                                       basePath = SQLSERVER:\
...
PathResolution Information: 0 :                                                     DRIVE-RELATIVE path: Sql\Microsoft.WindowsAzure.Commands.SqlDatabase.Types.ps1xml
PathResolution Information: 0 :                                                     Drive: SQLSERVER
PathResolution Information: 0 :                                                     Provider: Microsoft.SqlServer.Management.PSProvider\SqlServer
...
PathResolution Information: 0 :                                                     RESOLVED PATH: SQLSERVER:\Sql\Microsoft.WindowsAzure.Commands.SqlDatabase.Types.ps1xml
...
PathResolution Information: 0 :                                                             ERROR: Item does not exist: Sql\Microsoft.WindowsAzure.Commands.SqlDatabase.Types.ps1xml




At this point I new there was something different happening in the implementation of a PathResolution process.

Taking in everything I had investigated I could conclude that the SQLPROVIDER was implementing the ItemExist function differently to the FileSystem provider. In particular the SQLPROVIDER was checking the given file path and trying to match it to the SQLSERVER: drive, and in this case because the next part of the path starts with "\Sql\....." this would cause it to think it is trying to get the path of a SQL Server in which it would then attempt to connect to the name (in our case the file name) as a Server Name to retrieve the instance details...... hence the WMI errors.

To the best of my knowledge this issue has been around since an update to the Azure module in early 2014, as they change the folder structure they were using. At the time of writing this post, both initially and subsequent updates, the problem still exists.

If you want to help get this resolved please vote on the MS Connect item: https://connect.microsoft.com/SQLServer/feedback/details/1420992/import-module-sqlps-may-take-longer-to-load-but-always-returns-warnings-when-the-azure-powershell-module-is-also-installed#



 Legal Stuff: As always the contents of this blog is provided “as-is”. The information, opinions and views expressed are those of the author and do not necessarily state or reflect those of any other company with affiliation to the products discussed. This includes any URLs or Tools. The author does not accept any responsibility from the use of the information or tools mentioned within this blog, and recommends adequate evaluation against your own requirements to measure suitability.


Troubleshooting blocking locks in SQL Azure

I was faced with an interesting situation yesterday where a customer had created a blocking chain on their SQL Azure database. The scenario they described was:

A query took out and held a lock on object but the client connection closed and orphaned the session on the SQL Azure database. This resulted in other queries trying to access the object being blocked and timing out (even a SELECT *).

Given we do not have any graphical tools in SSMS to see current activity when you connect to a SQL Azure database, this offers a challenge for those that are use to going to Activity Monitor or the Reports to view this sort of information. Thankfully most of DMV's and DMF's have made their way into support on SQL Azure.

To troubleshoot the above scenario we then used the following queries to identify the culprit and eventually terminate it with the only option available.... KILL [spid]. To demonstrate this I have created the scenario on my Azure database through the use of PowerShell (but i am not sharing that as it is bad practice). The good news is that these queries will also work for your on-premise environments.

TSQL to identify the Blockers and Victims

WITH Blockers AS
    (select DISTINCT blocking_session_id as session_id
 from sys.dm_exec_requests
 where blocking_session_id > 0
)
SELECT 'Blocker' as type_desc
 , sys.dm_exec_sessions.session_id
 , sys.dm_exec_requests.start_time
 , sys.dm_exec_requests.status
 , sys.dm_exec_requests.command
 , sys.dm_exec_requests.wait_type
 , sys.dm_exec_requests.wait_time
 , sys.dm_exec_requests.blocking_session_id
 , '' AS stmt_text
FROM sys.dm_exec_sessions
LEFT JOIN sys.dm_exec_requests ON sys.dm_exec_requests.session_id = sys.dm_exec_sessions.session_id
INNER JOIN Blockers ON Blockers.session_id = sys.dm_exec_sessions.session_id
UNION
SELECT 'Victim' as type_desc
 , sys.dm_exec_sessions.session_id
 , sys.dm_exec_requests.start_time
 , sys.dm_exec_requests.status
 , sys.dm_exec_requests.command
 , sys.dm_exec_requests.wait_type
 , sys.dm_exec_requests.wait_time
 , sys.dm_exec_requests.blocking_session_id
 , ST.text AS stmt_text
FROM sys.dm_exec_sessions
INNER JOIN sys.dm_exec_requests ON sys.dm_exec_requests.session_id = sys.dm_exec_sessions.session_id
CROSS APPLY SYS.DM_EXEC_SQL_TEXT(sys.dm_exec_requests.sql_handle) AS ST
WHERE blocking_session_id > 0

The output of this query looks then like the following where you can clearly see the blocker and it's victims (in fact this example then has a 2nd layer of blocking).





TSQL to view the established locks within the current database

SELECT
 (CASE sys.dm_tran_locks.request_session_id
  WHEN -2 THEN 'ORPHANED DISTRIBUTED TRANSACTION'
  WHEN -3 THEN 'DEFERRED RECOVERY TRANSACTION'
  ELSE sys.dm_tran_locks.request_session_id
 END) AS session_id
 , DB_NAME(sys.dm_tran_locks.resource_database_id) AS database_name
 , sys.objects.name AS locked_obj_name
 , sys.dm_tran_locks.resource_type AS locked_resource
 , sys.dm_tran_locks.request_mode AS lock_type
 , ST.text AS stmt_text
 , sys.dm_exec_sessions.login_name AS login_name
 , sys.dm_exec_sessions.host_name AS host_name
 , sys.dm_tran_locks.request_status as request_status
FROM sys.dm_tran_locks
JOIN sys.objects ON sys.objects.object_id = sys.dm_tran_locks.resource_associated_entity_id
JOIN sys.dm_exec_sessions ON sys.dm_exec_sessions.session_id = sys.dm_tran_locks.request_session_id
JOIN sys.dm_exec_connections ON sys.dm_exec_connections.session_id = sys.dm_exec_sessions.session_id
CROSS APPLY SYS.DM_EXEC_SQL_TEXT(sys.dm_exec_connections.most_recent_sql_handle) AS st
WHERE sys.dm_tran_locks.resource_database_id = DB_ID()
ORDER BY sys.dm_tran_locks.request_session_id

The output of this query shows the various locks which have been established by each session (one-to-many in sessions-to-locks). From here we can see which locks will have taken priority and potentially blocking more queries in the future.



So while you may not have a graphical view of this information we can definitely use our trusted DMV's and DMF's to gain access to the relevant data. Who knows with the rate of change it can surely only be a matter of time until Activity Monitor and the standard reports are available to us in SSMS for SQL Azure.

Legal Stuff: As always the contents of this blog is provided “as-is”. The information, opinions and views expressed are those of the author and do not necessarily state or reflect those of any other company with affiliation to the products discussed. This includes any URLs or Tools. The author does not accept any responsibility from the use of the information or tools mentioned within this blog, and recommends adequate evaluation against your own requirements to measure suitability.