(last updated: 2019-06-20 @ 20:05 EST / 2019-06-21 @ 00:05 UTC )
The other day I was testing some security-related behavior of SQL Server Agent and stumbled upon something that is odd, and as far as I can tell, undocumented: a very specific string pattern is entirely removed from any output: either output file or job step history. I wasn’t able to find this behavior documented anywhere, so now it is ??.
How It All Started
For testing / debugging, I was printing certain environmental values, such as Database name, Login name, and User name. I happened to be using QUOTENAME(ORIGINAL_DB_NAME()) at the beginning of the line as follows:
PRINT CONCAT(QUOTENAME(ORIGINAL_DB_NAME()),
N' ~ ',
QUOTENAME(DB_NAME()),
N' :: ',
ORIGINAL_LOGIN(),
N' ~ ',
SUSER_NAME(),
N' :: ',
USER_NAME());
and nothing would ever come back for QUOTENAME(ORIGINAL_DB_NAME()). The first thing on the line would always be that first “~”. For the most part I had figured that this was merely the condition where ORIGINAL_DB_NAME() didn’t return anything anyway, similar to:
SELECT CONCAT('hello', QUOTENAME(NULL), 'goodbye');
-- hellogoodbye
Though, it did strike me as odd that the square brackets didn’t show up because they do when I run the following in SSMS:
SELECT CONCAT('hello', QUOTENAME(ORIGINAL_DB_NAME()), 'goodbye');
-- hello[]goodbye
Oh well. Whatever. That slightly odd behavior didn’t seem to be getting in the way of anything.
But Then…
Things done got weird, yo! Viewing the step output in “Log File Viewer” isn’t super easy given that it:
- converts Carriage Returns (i.e.
r/CHAR(13)/ “CR” ) and Line Feeds (i.e.n/CHAR(10)/ “LF” ) into spaces. - appends “
[SQLSTATE 01000] (Message 0)” to the end of each printed line
so, I decided to add a little bit of formatting to make it easier / quicker to read. I added a few characters at the beginning and ending of the concatenated value:
PRINT CONCAT(N'<< ',
QUOTENAME(ORIGINAL_DB_NAME()),
N' ~ ',
QUOTENAME(DB_NAME()),
N' :: ',
ORIGINAL_LOGIN(),
N' ~ ',
SUSER_NAME(),
N' :: ',
USER_NAME(),
N' >>');
And that’s when it happened: I started getting a value back from QUOTENAME(ORIGINAL_DB_NAME()), and not just the square brackets with nothing between them. The name of a database was now between the square brackets. Why wasn’t that showing up before?
For another test, I printed just a few characters in square brackets, as static text (i.e. no function call):
PRINT '[hidden]';
But that did not show up in the step output. At all! There wasn’t even the usual “[SQLSTATE 01000] (Message 0)” at the end of the line. There was absolutely no indication that a PRINT statement had been executed.
Then I tried adding characters after that, just like my original PRINT statement:
PRINT '[hidden]after';
This time something did show up in the output, but it was just the word “after”, and not even any spaces to the left of it.
Figuring that the only difference between what did and did not show a value was the “<<" that I had added to the start of the line, I added a simple "Z" to the beginning of the line with the static value in square brackets:
PRINT 'Z[hidden]after';
And, as you might have guess, the full line — "Z[hidden]after" — showed up in the output. W.T.(F|H).?
Pattern of Mystery
In Words…
After quite a bit more testing, I found that the "magic" string pattern is:
- Strings contained within square brackets at the very beginning of the line (not preceded by anything) are completely removed from output.
PRINT '[hidden]'; -- NO output PRINT '[hidden]A'; -- output starts with "A"
- The string contained within square brackets can contain any character except a right-square bracket (i.e. "
]"). There does not seem to be a way to escape these, and I tried the following potential escape characters:],,%.PRINT '[hidden with some newlines]'; -- NO output
- Any number of square-bracketed strings will be hidden as long as there is nothing between an ending right square-bracket — "
]" — and the next starting left square-bracket — "[".PRINT '[hidden1][hidden2][hidden3][hiddenN]'; -- NO output PRINT '[hidden1][hidden2][hidden3][hiddenN]A'; -- output starts with "A"
- All spaces, Carriage Returns, and Newlines / Line Feeds prior to the first non-space, non-CR, non-LF character are completely removed from output.
PRINT ' A...'; -- output starts with "A" PRINT '[hidden] A...'; -- output starts with "A" PRINT '[hidden] '; -- NO output
- Only a single square-bracketed string will be hidden if preceded with any number of spaces, Carriage Returns, and Newlines / Line Feeds.
PRINT ' [hidden][NOT hidden]'; -- output starts with "[NOT" PRINT '[hidden1] [hidden2][NOT hidden]'; -- output starts with "[NOT"
In RegEx…
Expressed as a Regular Expression, the pattern is:
^([[^]]*])*[ rn]*([[^]]*])?
Written out, that pattern means:
- Starting at the beginning of the line, there can be 0 or more sets of:
[+ 0 or more of any character except "]" +] - followed by 0 or more spaces and/or CRLFs (and maybe also just LF / Newline; no, tabs do not work here)
- followed by 0 or 1 set(s) of:
[+ 0 or more of any character except "]" +]
This pattern can be tested rather easily by using a SQLCLR RegEx function. The following examples make use of the Free version of SQL#:
DECLARE @Pattern NVARCHAR(500) = N'^([[^]]*])*[ rn]*([[^]]*])?',
@Bar NVARCHAR(10) = NCHAR(0x2307); -- "Wavy Line"
SELECT @Bar + SQL#.RegEx_MatchSimple4k(N'[hidden]', @Pattern, 1, NULL) + @Bar;
-- ?[hidden]?
SELECT @Bar + SQL#.RegEx_MatchSimple4k(N'[hidden]A', @Pattern, 1, NULL) + @Bar;
-- ?[hidden]?
SELECT @Bar + SQL#.RegEx_MatchSimple4k(N'[hidden
with some
newlines]', @Pattern, 1, NULL) + @Bar;
/*
?[hidden
with some
newlines]?
*/SELECT @Bar + SQL#.RegEx_MatchSimple4k(N'[hidden1][hidden2][hidden3][hiddenN]',
@Pattern, 1, NULL) + @Bar;
-- ?[hidden1][hidden2][hidden3][hiddenN]?
SELECT @Bar + SQL#.RegEx_MatchSimple4k(N'[hidden1][hidden2][hidden3][hiddenN]A',
@Pattern, 1, NULL) + @Bar;
-- ?[hidden1][hidden2][hidden3][hiddenN]?
SELECT @Bar + SQL#.RegEx_MatchSimple4k(N' A...', @Pattern, 1, NULL) + @Bar;
-- ? ?
SELECT @Bar + SQL#.RegEx_MatchSimple4k(N'[hidden] A...',
@Pattern, 1, NULL) + @Bar;
-- ?[hidden] ?
SELECT @Bar + SQL#.RegEx_MatchSimple4k(N'[hidden] ', @Pattern, 1, NULL) + @Bar;
-- ?[hidden] ?
SELECT @Bar + SQL#.RegEx_MatchSimple4k(N' [hidden][NOT hidden]',
@Pattern, 1, NULL) + @Bar;
-- ? [hidden]?
SELECT @Bar + SQL#.RegEx_MatchSimple4k(N'[hidden1] [hidden2][NOT hidden]',
@Pattern, 1, NULL) + @Bar;
-- ?[hidden1] [hidden2]?
Test
I created a SQL Agent Job with a T-SQL Job Step, using the following T-SQL:
PRINT '~[a][??][d][A][??][D][1]';
— 2) No spaces / returns:
PRINT '[a][??][d][A][??][D][2]';
— 3) Spaces / returns inside :
PRINT '[a][ b ][??][d][A][??][D][3]';
— 4) Spaces / returns before [a]:
PRINT ' [a][??][d][A][??][D][4]';
— 5) Spaces / returns after :
PRINT '[a] [??][d][A][??][D][5]';
— 6) Spaces / returns plus non-space/non-return after :
PRINT '[a] * [??][d][A][??][6]';
— 7) Only spaces preceding first non-space character:
PRINT ' * [??][d][A][??][7]';
Under the “Advanced” options, I specified an “Output file” — C:TempOutputHistoryTest.txt — and enabled “Include step output in history”.
To run the job, just right-click on the job in Object Explorer and select “Start Job at Step…”.
Test Results
I tested on SQL Server versions 2005, 2017, and 2019. You can use the following query to see the job step output that is shown in the “Log File Viewer”:
SELECT hist.[message] FROM [msdb].[dbo].[sysjobhistory] hist WHERE hist.[step_name] = N'OUTPUT HISTORY TEST' ORDER BY hist.[instance_id] DESC; -- newest first
SQL Server 2005 SP4 and 2017 CU15:
Using the “Log File Viewer” in SSMS 18.0 RTM, I see:
Notice how the two emoji characters have been converted into “??”. The message column of [msdb].[dbo].[sysjobhistory] is NVARCHAR(MAX), and the characters are stored correctly in the command column of [msdb].[dbo].[sysjobsteps], so somewhere in the processing of the job there is (or was) a string handling bug that affects at least supplementary characters if not all non-BMP Unicode characters.
And the output file contents are:
~[a][??][d][A][??][D][1] [SQLSTATE 01000]
[??][d][A][??][D][4] [SQLSTATE 01000]
[d][A][??][D][5] [SQLSTATE 01000]
* [??][d][A][??][6] [SQLSTATE 01000]
* [??][d][A][??][7] [SQLSTATE 01000]
Same supplementary character handling problem as we saw in the job history.
SQL Server 2019 CTP 3.0
Using the “Log File Viewer” in SSMS 18.0 RTM, I see:
The same string pattern is hidden, but at least the character encoding bug has been fixed.
And the output file contents are:
~[a][??][d][A][??][D][1] [SQLSTATE 01000]
[??][d][A][??][D][4] [SQLSTATE 01000]
[d][A][??][D][5] [SQLSTATE 01000]
* [??][d][A][??][6] [SQLSTATE 01000]
* [??][d][A][??][7] [SQLSTATE 01000]
Please note: the emoji characters do not display correctly when viewing in a Command Prompt / DOS window. However, if you copy and paste that output into a Unicode-capable editor, they should display correctly (at least it worked for me when pasting into both SSMS and Notepad++).
Conclusion
I have no idea why this behavior exists. Is it to prevent “sensitive” data (passwords, etc) from showing up in the history table? Who knows.
A T-SQL script to create the SQL Agent job mentioned above can be found on PasteBin.com.