One DBA's Ongoing Search for Clarity in the Middle of Nowhere


*or*

Yet Another Andy Writing About SQL Server

Wednesday, October 17, 2018

Invalid value given for parameter PASSWORD. Specify a valid parameter value.

I still use sp_help_revlogin to transfer logins between servers.  I know there are other options, including a set of Powershell commands contained in dbatools (#YouCanDoAnythingWithPowershell) but this is a case where the old method works so I don't mess with it.

http://wanna-joke.com/wp-content/uploads/2013/08/funny-pictures-too-olf-for-internet.jpg

Having said that, I know a lot of people still use sp_help_revlogin, so I wanted to document something I tripped over.

--

This morning trying to use a saved script to transfer a login to a new server, I ran into this:
Msg 15021, Level 16, State 2, Line 1 
Invalid value given for parameter PASSWORD. Specify a valid parameter value.
https://pics.me.me/um-ok-memecrunch-com-19987825.png

This was a new one on me, but a little Google led me to the problem, and it was described in the notes for the sp_help_revlogin procedure itself at https://support.microsoft.com/en-us/help/918992/how-to-transfer-logins-and-passwords-between-instances-of-sql-server:

--
A password can be hashed in the following ways:
  • VERSION_SHA1: This hash is generated by using the SHA1 algorithm and is used in SQL Server 2000 through SQL Server 2008 R2.
  • VERSION_SHA2: This hash is generated by using the SHA2 512 algorithm and is used in SQL Server 2012 and later versions.
--

Sure enough I checked and the server I was trying to deploy onto was a SQL 2008R2 server (yes our clients still have lots of 2005/2008/2008R2).

The script I had saved looked like this:
CREATE LOGIN [MyLogin] 
WITH PASSWORD = 0x0200A52324E0FFEBABFAD9327A62EECD2A5D648FF3B98D97C5D020FC16552BA728464BAAC04C8EFDE3BB0235A1F3648E419B038C04C8EFDE3BB0235A1F3648E419B0385A5933 HASHED
/* Hash slightly character masked :) */

, SID = 0x7FCDC703D88B5C48A47D7D13699658E2

, DEFAULT_DATABASE = [master]

, CHECK_POLICY = OFF

, CHECK_EXPIRATION = OFF
As a test, I ran an sp_help_revlogin for the same login (same password) on SQL 2008 server:
CREATE LOGIN [MyLogin] 
WITH PASSWORD = 0x0100E02F8267F60
81A5AB316F8A6891C81A5AB316F8A6891CCC HASHED
/* Hash slightly character masked :) */

, SID = 0x14B5D0191E908D499C83C1695F13F7F3

, DEFAULT_DATABASE = [master]

, CHECK_POLICY = OFF

, CHECK_EXPIRATION = OFF
Note that the second password hash is significantly shorter (which makes perfect sense since SHA1 is a shorter hash than SHA2, as described here.)  This is one of the key reasons SHA1 has fallen out of favor - there have been known issues with SHA1 for years.

(Another reason to get off SQL 2005/2008/2008R2...as if you should need another reason in the year 2018!)

http://img.izismile.com/img/img6/20130327/original640/old_technology_640_01.jpg

The bottom line is that to have login scripts like this, you need two versions, a SQL2005-2008R2 SHA1 version, and a SQL 2012+ SHA2 version.

*OR*

If you truly only want one copy of your script, it needs to be a SHA1 (short hash) version.  SQL 2005/2008/2008 R2 don't understand the 2012+ SHA2 long hash, but SQL 2012+ is backward-compatible to the SHA1 short hash.

Having said that, I would still use the SHA2 hash script whenever possible.

--

Hope this helps!


Wednesday, September 26, 2018

Coming Soon to Minnesota...Lincoln...and Seattle!!!

It's that time of year when SQLSaturdays start to slow down (in the U.S. anyway) as we march towards Summit and the holiday season.

Having said that, I have three speaking engagements in the near future - two SQLSaturdays and...SUMMIT!!!

https://pbs.twimg.com/profile_images/1037416795282403329/vrSIsVTR_400x400.jpg

I will be giving slight variations on the same talk at all three events as I tweak possible changes for my Summit talk.

--

SQLSaturday #796 - Minnesota - St Paul, MN - October 6th

SQLSaturday #767 - Lincoln - Lincoln, NE - October 27th

PASS Summit v.20 - Seattle, WA - November 5th-9th

--

Minnesota and Lincoln are always amazing events, and this is only my second time speaking at Summit.  I have spoken at more than a dozen SQLSaturdays and yet I get edgy thinking about being on stage at Summit (it's just a really big SQLSaturday, right?  ...right?)

http://he.memegenerator.net/instance/59791161/mr-bean-you-just-keep-telling-yourself-that
--

The talk I am giving is my Extended Events talk:

--
Getting Started with Extended Events 
Few subjects in Microsoft SQL Server inspire the same amount of Fear, Uncertainty, and Doubt (FUD) as Extended Events. Many DBAs continue to use Profiler and SQL Trace even though they have been deprecated for years. Why is this? 
Extended Events started out in SQL Server 2008 with no user interface and only a few voices in the community documenting the features as they found them. Since then, it has blossomed into a full feature of SQL Server and an amazingly low-impact replacement for Profiler and Trace.
Come learn how to get started - the basics of sessions, events, actions, targets, packages, and more. We will look at some base scenarios where Extended Events can be very useful as well as considering a few gotchas along the way. You may never go back to Profiler again!
--

I have been tweaking it to add more demos and extend the length (Summit sessions are 75 minutes and most SQLSaturday sessions are 60-70 minutes.)  Even if you have seen me present this session before I hope you will get something out of it.

--

Another important part of SQLSaturdays and Summit to me are the pre-conference sessions/workshops.  They do cost an extra fee but it is worth it for a full day of in-depth training on a topic by a dedicated speaker (events like this don't give preconference slots to just anybody).

All three of these events have preconference sessions, and to me as primarily a systems DBA I recommend the following:

--

SQLSaturday Minnesota (Full List at https://www.eventbrite.com/e/sqlsaturday-796-minnesota-pre-cons-tickets-49272636783?aff=SQLSaturday)

Data Security for the Cloud by Ed Leighton-Dick from Kingfisher Technologies - I have known Ed for some time and he has put a lot of time into becoming a rising star in the security area.

--

SQLSaturday Lincoln (Full List at https://www.sqlsaturday.com/767/eventhome.aspx)

Level UP! Your Cloud Infrastructure Skills by David Klee of Heraflux - David is one of the top (if not the top) speaker on SQL Server on VMs and the cloud.

Data Security for the Cloud by Ed (see above) - if you don't see Ed in Minnesota you have another chance in Lincoln!

--

Summit (Full List at https://www.pass.org/summit/2018/Learn/Pre-ConferenceSessions.aspx

SQL Server Security by Denny Cherry of Denny Cherry & Associates Consulting (DCAC) - Denny is a security (and all-around) SQL Server expert who always gives a great talk.

Modernize your SQL Server with Bob Ward, the Tiger Team, and CSS Escalation Engineers by Bob Ward and the SQL Tiger Team from Microsoft - nobody can melt your brain like Bob Ward.  Any time you can see Bob speak, you should...period.

Fixing Query Performance Problems from Estimates, Statistics, Heuristics, and Cardinality by Kimberly L. Tripp of SQLskills.com - Kimberly knows more about statistics and the related topics than anyone I know, and she shares it so well. 

Kimberly and Bob are in the same time slot (all-day Tuesday) and in this case I am going to see Bob but I have already had weeks of training from Kimberly and if her topic sounds more interesting to you it will be worth it!

--

Hope to see you at these events and in the preconference sessions!

https://memegenerator.net/img/instances/68890668/see-you-soon.jpg


Tuesday, September 4, 2018

Did Not Know That - Redirecting CMD to the Clipboard

One of the items I frequently deal with as a Production DBA is drive alarms.  I have written previously about looking for space inside database files, but what if your problem is non-database files?

The goto tool in Windows for me has always been du (Disk Usage) created by Mark Russinovich (blog/@markrussinovich) as part of his Sysinternals project.

du is a very straightforward command tool the traverses the directory structure below the current path and returns the folder sizes of the given folders.  For example, the output for C:\Windows on a given server looks like this:


Fine to look at, but a bit onerous to manipulate - after all this is just a screenshot.

The first way I knew to deal with this was via the >> redirect:
du -l 1 >> Output4.txt
This would create a text file at the path being searched containing the output from the command, which can then be copy-pasted out to another site:



To clean it up for manipulation (in Excel for example), you can add a parameter to du to turn the output to comma- or tab-delimited format (either -c or -ct):
du -ct -l 1 >> output5.txt

--

The new trick I learned is that you can use a pipe - similar to Powershell - to redirect the output of the du command to another command, and that there is a command to send the output of a command directly to the clipboard (unbelievably enough, called "clip"):
du -ct -l 1 | clip
http://ru.memegenerator.net/instance/57285847/mind-blown-cat-mind-blown
I found this trick in a helpful blog post here.

Once it's in the clipboard, it can be pasted straight into Excel where it can be easily sorted, for example to find the largest directories:


Pretty cool, huh?

This same process of piping into clip works with a wide variety of command line commands, but this is the one for which I see the most immediate value.

--

Hope this helps!


Thursday, August 2, 2018

The Mystery of the Exploding T-Log

There were a stack of errors overnight in the DB123 database on SQL01, including one horror show error:

--

Log Name:      Application
Source:        MSSQLSERVER
Date:          5/24/2018 12:49:39 AM
Event ID:      3314
Task Category: Server
Level:         Error
Keywords:      Classic
User:          N/A
Computer:      SQL01.client99.com
Description:
During undoing of a logged operation in database 'DB123', an error occurred at log record ID (195237:96178:4). Typically, the specific failure is logged previously as an error in the Windows Event Log service. Restore the database or file from a backup, or repair the database.

--

https://i.imgflip.com/rlu4s.jpg?a424656
The catch is that when I checked the server, the database was online.

Say what?

--

It started with the LOG drive filling generating a long string of 9002’s:

--

Log Name:      Application
Source:        MSSQLSERVER
Date:          5/24/2018 12:49:39 AM
Event ID:      9002
Task Category: Server
Level:         Error
Keywords:      Classic
User:          N/A
Computer:      SQL01.client99.com
Description:
The transaction log for database 'DB123' is full due to 'ACTIVE_TRANSACTION'.

--

Followed by a “crash” including the horror show error:

--

Log Name:      Application
Source:        MSSQLSERVER
Date:          5/24/2018 12:49:39 AM
Event ID:      9001
Task Category: Server
Level:         Error
Keywords:      Classic
User:          N/A
Computer:      SQL01.client99.com
Description:
The log for database 'DB123' is not available. Check the event log for related error messages. Resolve any errors and restart the database.

--

Log Name:      Application
Source:        MSSQLSERVER
Date:          5/24/2018 12:49:39 AM
Event ID:      3314
Task Category: Server
Level:         Error
Keywords:      Classic
User:          N/A
Computer:      SQL01.client99.com
Description:
During undoing of a logged operation in database 'DB123', an error occurred at log record ID (195237:96178:4). Typically, the specific failure is logged previously as an error in the Windows Event Log service. Restore the database or file from a backup, or repair the database.

--

…which seems scary, but then the database seemed to magically recover on its own:

--

Log Name:      Application
Source:        MSSQLSERVER
Date:          5/24/2018 12:49:41 AM
Event ID:      17137
Task Category: Server
Level:         Information
Keywords:      Classic
User:          N/A
Computer:      SQL01.client99.com
Description:
Starting up database 'DB123'.

--

Log Name:      Application
Source:        MSSQLSERVER
Date:          5/24/2018 12:49:45 AM
Event ID:      3450
Task Category: Server
Level:         Information
Keywords:      Classic
User:          N/A
Computer:      SQL01.client99.com
Description:
Recovery of database 'DB123' (5) is 0%% complete (approximately 4502 seconds remain). Phase 1 of 3. This is an informational message only. No user action is required.

--

There was a huge string of Error 18456 (login failures) since DB123 was unavailable during regular recovery, followed eventually by:

--

Log Name:      Application
Source:        MSSQLSERVER
Date:          5/24/2018 1:08:12 AM
Event ID:      3421
Task Category: Server
Level:         Information
Keywords:      Classic
User:          N/A
Computer:      SQL01.client99.com
Description:
Recovery completed for database DB123 (database ID 5) in 1107 second(s) (analysis 52027 ms, redo 238039 ms, undo 700990 ms.) This is an informational message only. No user action is required.

--

…and all was well.

http://www.thingsmadefromletters.com/wp-content/uploads/2013/10/whut-i-dont-understand-this.jpg

I went looking for similar situations and found this:


In this situation the drive filled and the database crashed, going through recovery once there was additional free space on the drive, which sounded exactly like the situation here.

In short, there was no actual corruption crash, just insufficient disk space.

--

Using the default trace query described here, I checked for autogrowths, and here was what they looked like:

EventName
DatabaseName
FileName
ApplicationName
HostName
LoginName
Duration
TextData
Log File Auto Grow
DB123
DB123_log
.Net SqlClient Data Provider
WEB05
WebLogin01
1013000
NULL
Log File Auto Grow
DB123
DB123_log
.Net SqlClient Data Provider
WEB05
WebLogin01
920000
NULL
Log File Auto Grow
DB123
DB123_log
.Net SqlClient Data Provider
WEB05
WebLogin01
873000
NULL
Log File Auto Grow
DB123
DB123_log
.Net SqlClient Data Provider
WEB05
WebLogin01
1083000
NULL
Log File Auto Grow
DB123
DB123_log
.Net SqlClient Data Provider
WEB05
WebLogin01
646000
NULL
Log File Auto Grow
DB123
DB123_log
Ivanti
WEB05
WebLogin01
903000
NULL
Log File Auto Grow
DB123
DB123_log
.Net SqlClient Data Provider
WEB05
WebLogin01
880000
NULL
Log File Auto Grow
DB123
DB123_log
.Net SqlClient Data Provider
WEB05
WebLogin01
846000
NULL
Log File Auto Grow
DB123
DB123_log
.Net SqlClient Data Provider
WEB05
WebLogin01
1176000
NULL
Log File Auto Grow
DB123
DB123_log
.Net SqlClient Data Provider
WEB05
WebLogin01
846000
NULL
Log File Auto Grow
DB123
DB123_log
.Net SqlClient Data Provider
WEB05
WebLogin01
1416000
NULL

Since the TEXTDATA is NULL I can’t say what process caused the growths for sure, but they started at 12:22am local server time. 

I could tell the client that since they came from the .NET provider they aren’t caused by Index/Statistics maintenance or anything else internal.

--

To try to run down what might be causing the autogrowths I set up an Extended Events session to capture statement completion events (rpc_completed, sp_statement_completed, and sql_batchcompleted) to see what was actually running during the time slice.  Sure enough there was a smoking gun:



Check out the row near the middle with a very large duration, logical_reads count, *and* writes count.

https://steemitimages.com/DQmarWgB1ztrx628DTGpkteJeKiU3waad9YRtm5jVedJxws/problem.jpg
Durations in SQL 2012 Extended Events are in microseconds – a very small unit.

The catch is the duration for this statement is 6,349,645,772 (6 billion) microseconds…105.83 minutes!

--

The DB123 database is in SIMPLE recovery (note - when I find this I question it – isn’t point-in-time recovery important? – but that is another discussion).  The relevance here is that in SIMPLE recovery, LOG backups are irrelevant (and actually *can’t* be run) – once a transaction or batch completes the LDF/LOG file space is marked available for re-use, meaning that *usually* the LDF file doesn’t grow very large. (usually!)

A database in SIMPLE recovery growing large LDF/LOG files almost always mean a long-running unit of work or accidentally open transactions (a BEGIN TRAN with no subsequent CLOSE TRAN) – looking at the errors in the SQL Error Log last night, the 9002 log file full errors stopped at 1:45:51am server time, which means the offending unit of work ended then one way or another (crash or success).

Sure enough when I filtered the XEvents event file to things with a duration > 100 microseconds and then scanned down to 1:45:00 I quickly saw the row shown above.   Note this doesn’t mean the unit of work was excessively large in CPU/RAM/IO/etc. (and in fact the query errored out due to lack of LOG space) but the excessive duration made all of the tiny units of work over the previous 105 minutes have to persist in the transaction LDF/LOG file until this unit of work completed, preventing all of the LOG from that time to be marked for re-use until this statement ended.

--

The query in question is this:

--

exec sp_executesql N'DELETE from SecurityAction 
WHERE ActionDate < @1 AND 
(ActionCode != 102 AND ActionCode != 103 AND ActionCode != 129 
AND ActionCode != 130)',N'@1 datetime',@1='2017-09-14 00:00:00'

--

Stripping off the sp_executesql wrapper and the parameter replacement turns it into this:

--

DELETE from SecurityAction
WHERE ActionDate < '2017-09-14 00:00:00'
AND
(
ActionCode != 102
AND ActionCode != 103
AND ActionCode != 129
AND ActionCode != 130
)

--

Checking out DB123.dbo.SecurityAction, the table is 13GB with 14 million rows.  Looking at a random TOP 1000 rows I see rows that would satisfy this query that are at least 7 months old (from February 2017) and there may be even older rows – I didn’t want to spend the resources to run an ORDER BY query to find the absolute oldest.  I don’t know if this means this individual statement has been failing for a long time or maybe this DELETE statement is a recent addition to the overnight processes and has been failing since then.

The DELETE looks like it must be a scheduled/regular operation from a .NET application running on WEB05 since we are seeing it each night in a similar time window.

The immediate term action they chose was to run a batched DELETE to purge this table down – once it has been purged down maybe the nightly operation will run with a short enough duration to not break the universe.

I told them it should be able to be handled with a TOP DELETE something like this:

--

WHILE 1=1
BEGIN
       DELETE TOP (10000) from SecurityAction
       WHERE ActionDate < '2017-09-14 00:00:00'
       AND
       (
       ActionCode != 102
       AND ActionCode != 103
       AND ActionCode != 129
       AND ActionCode != 130
       )
END
      
--

This would DELETE rows in 10,000 row batches; wrapping it in the WHILE 1=1 allows the batch to run over and over without ending.  Once there are no more rows to satisfy the criteria the query *WILL CONTINUE TO RUN* but will simply delete -0- rows each time, and then when the user is ready to stop the batch they simply cancel it.

You could write a WHILE clause that actually checks for the existence of rows that meet the criteria, but in this case there were so many rows that meet the criteria that running the check itself is more intensive than simply allowing the DELETE to run over and over.

It took several hours of running the "batched" loop, but eventually the table got down from 14 million rows to 900,000 rows without growing the LDF file past 2GB!


https://memegenerator.net/img/instances/80336841/booyah.jpg
--

Lesson #1 - don't run giant deletes without considering the impact.

Lesson #2 (and maybe the more important) - "horror show" errors aren't always a horror show - always investigate fully!

--

Hope this helps!