Nothing is more frustrating than a system being broken with no visibility into it, at the same time there is nothing more satisfying than catching problems with your vendors before they do. Being proactive, rather than reactive also buys a ton of grace from your users when you catch problems before they are reported and sometime having gone totally unnoticed.

This reminds me of a quote from the Futurama Godfellas episode where the Galaxy God Entity is talking to Bender and says “When you do things right, people won’t be sure you’ve done anything at all” and I couldn’t agree more. Proper logging and visibility will lead to exactly that!

Below we will look at how I have implemented it and the choices made along the way.

The Software Stack#

Grafana #

This is the user interface to query logs and metrics, creating rich dashboards and visualizations, and alerting when specific conditions are met.

Loki #

This is a platform specifically optimized for handling message streams. I prefer to instrument my applications using JSON messages that Grafana can then parse out with LogQL. Become familiar with writing log queries as that is how you will explore the data.

Log streams are grouped by labels. These labels have served me quite well for many years.

Application is the top level assembly or application that produced the log
Environment is the environment (e.g. dev, stage, production)
MachineName is the computer or server running the application

WARNING
Loki will group and store in like chunks (files) on the server using the stream labels. You want this to be as low cardinality as possible to avoid having too many individual files on the server.

You might be asking at this point, “How do I add additional information to my log messages”? This is where the Log Property Stack comes in. It is a way to enrich your logs with additional context without trying to jam it into the log message itself.

Log Property Stack#

Instead of adding all the details to the log message itself, you should utilize the property stack which will persist the property with every message nested within the scope that property was defined.

Here are some examples of what I use through my applications. These are staples that I include in everything and add more as needed to determine application state at major branching points.

InstanceId for long running process, defering to CorrelationId for nested units of work
CorrelationId for discrete units of work
RequestInfo object for web stuff like url, headers, query params, and other information to help trace requests.

Dependency Recommendations#

Serilog for dotnet applications
Serilog.Sinks.Debug for web applications when you are running locally
Serilog.Sinks.Console for console applications writing to stdout/stderr
Serilog.Sinks.Grafana.Loki for writing to a Loki server
SerilogTimings for timing operations, use this whenever my application leaves its domain of control (e.g. when making database query or web requests)
Custom stored procedures for SQL Server, see bonus content below

Prometheus #

Prometheus is a time series database and handles things that do not fit into structured logging such as performance counters. Like Loki, has its own query language called PromQL.

Performance counters#

CPU and Memory Utilization
Disk and Network Usage
IIS and SQL specific counters like request throughput

These counters can be gathered from the servers directly using a tool called windows_exporter that provides an HTTP endpoint that can be scraped by a Prometheus server.

WARNING
Please be mindful of your companies security practices as the out of the box the server is not secured. Configuration can be found here.

Logging Fundamentals#

Here be dragons…

Avoid logging PII — Logs are public and can leak information

Avoid excessive logging — Logging can be great at first to build confidence in a process. If you find yourself logging every little step, Debug or Verbose should be used

Avoid logging user correctable errors as Error. Debug or Warning may be a more appropriate place for these types of messages

Avoid punctuation when possible. Log messages are fragments, not sentences

Log Key Events#

Major branching points in your code
When errors or unexpected values are encountered
Any IO or resource intensive operations
Significant domain events
Request failures and retires
Beginning and end of time-consuming batch operations

Choose Appropriate Logging Level#

Be generous with your logging but strict with your logging levels. In almost all cases the level of your logs should be Debug
Use Information for log events that would be needed in production to determine the running state or correctness of your application
Use Warning or Error for unexpected events like exceptions
The Error level should be reserved for events that you intend to act on. User correctable errors should never be logged at this level

Bonus — Logging in SQL Server#

Configure#

This is called at the start of your SQL session that you want to log and should only be called once per session.

1
CREATE PROCEDURE [dbo].[ConfigureFor](
2
  @Application VARCHAR(200),
3
  @Environment VARCHAR(11)
4
)
5
AS
6
BEGIN
7
  BEGIN TRY
8
    -- normalize and validate environment value
9
    SELECT @Environment = CASE
10
      WHEN @Environment IN ('development', '0') THEN 'Development'
11
      WHEN @Environment IN ('stage', '2') THEN 'Stage'
12
      WHEN @Environment IN ('production', '1') THEN 'Production'
13
      ELSE NULL
14
    END
15

16
    IF @Environment IS NULL
17
    BEGIN
18
      RAISERROR('Invalid environment value. Should be one of [Development|Stage|Production]', 16, 1)
19
    END
20

21
    DECLARE @ReadOnly INT = 1
22
    EXECUTE sp_set_session_context 'Application', @Application, @ReadOnly
23
    EXECUTE sp_set_session_context 'MachineName', @@SERVERNAME, @ReadOnly
24
    EXECUTE sp_set_session_context 'Environment', @Environment, @ReadOnly
25

26
    EXECUTE sp_set_session_context '__index__', NULL
27
  END TRY
28
  BEGIN CATCH
29
    THROW
30
  END CATCH
31
END

Log Level Functions#

The meat and potatoes of the implementation. It will gather all of the log properties off the stack and do the submission to the Loki server. There are convenience functions for each log level.

Implementation#

IMPORTANT
This will need a way to make HTTP requests from SQL Server. This could be through OLEAutomation, a dotnet SQLCLR assembly or SQL Server Language Extensions.

NOTE
This is typically not called directly favoring the convenience functions.

1
CREATE PROCEDURE [dbo].[LogTo_Impl](
2
  @Message NVARCHAR(4000),
3
  @Level NVARCHAR(50)
4
)
5
AS
6
BEGIN
7
  BEGIN TRY
8
    --DECLARE @Message NVARCHAR(4000) = 'DONKEY!'
9
    -- cheap insurance to make sure that ConfigureFor has been called
10
    IF SESSION_CONTEXT(N'Application') IS NULL
11
    BEGIN
12
      RETURN
13
    END
14

15
    -- get log time as unix epoch in nanos
16
    DECLARE @Time BIGINT = DATEDIFF_BIG(NANOSECOND, '1970-01-01 00:00:00.0000000', SYSUTCDATETIME())
17

18
    -- add standard set of properties to be logged
19
    EXECUTE LogProperty_Add 'Message', @Message
20
    EXECUTE LogProperty_Add 'level', @Level
21

22
    -- send to loki
23
    -- json
24
    -- {
25
    --   "streams": [
26
    --   {
27
    --     "stream": {
28
    --       "label": "value"
29
    --     },
30
    --     "values": [
31
    --       [ "unix epoch in nanoseconds", "log line" ],
32
    --       [ "unix epoch in nanoseconds", "log line" ]
33
    --     ]
34
    --   }
35
    --   ]
36
    -- }
37
    --
38
    -- http://localhost:3100/loki/api/v1/push
39

40
    -- these are configured in the ConfigureFor stored procedure
41
    DECLARE @StreamLabels NVARCHAR(MAX) = (
42
      SELECT *
43
      FROM (
44
        SELECT *
45
        FROM(VALUES
46
          ('Application', SESSION_CONTEXT(N'Application')),
47
          ('MachineName', SESSION_CONTEXT(N'MachineName')),
48
          ('Environment', SESSION_CONTEXT(N'Environment'))
49
        ) stream_labels([key], [value])
50
      ) a
51
      PIVOT (
52
        MAX([value]) FOR [key] IN ([Application], [MachineName], [Environment])
53
      ) pvt
54
      FOR JSON AUTO, WITHOUT_ARRAY_WRAPPER/*, INCLUDE_NULL_VALUES*/
55
    )
56
    --SELECT @StreamLabels
57

58
    IF OBJECT_ID('tempdb..#TMP') IS NOT NULL
59
    BEGIN
60
      DROP TABLE #TMP
61
    END
62

63
    SELECT
64
      [key] = [value],
65
      [value] = SESSION_CONTEXT(CAST([value] AS NVARCHAR(100))),
66
      [is_json] = ISJSON(CAST(SESSION_CONTEXT(CAST([value] AS NVARCHAR(100))) AS NVARCHAR(MAX)))
67
    INTO #TMP
68
    FROM OPENJSON(CAST(SESSION_CONTEXT(N'__index__') AS NVARCHAR(MAX)))
69

70
    -- generate select list to account for json column data.
71
    -- we have to use JSON_QUERY on json data so that it is treated as a json fragment when the overall select is serialized
72
    DECLARE @SelectList NVARCHAR(MAX) = (SELECT STUFF((
73
    -- stuff select begin
74
    SELECT ',' + IIF([is_json] = 1, QUOTENAME([key]) + ' = JSON_QUERY(CAST(' + QUOTENAME([key]) + ' AS NVARCHAR(MAX)))', QUOTENAME([key]))
75
    FROM #TMP
76
    FOR XML PATH ('')
77
    -- stuff select end
78
    ), 1, 1, '')
79
    )
80
    --SELECT @SelectList
81

82
    -- generate pivot list
83
    DECLARE @PvtList NVARCHAR(MAX) = (SELECT STUFF((
84
    -- stuff select begin
85
    SELECT ',' + QUOTENAME([key]) FROM #TMP
86
    FOR XML PATH ('')
87
    -- stuff select end
88
    ), 1, 1, '')
89
    )
90
    --SELECT @PvtList
91

92
    -- generate message span
93
    DECLARE @Sql NVARCHAR(MAX) = ''
94
    SELECT @Sql = '
95
    DECLARE @Json NVARCHAR(MAX) = (
96
      SELECT {1}
97
      FROM (
98
        SELECT [key], [value]
99
        FROM #TMP
100
      ) a
101
      PIVOT (
102
        MAX([value]) FOR [key] IN ({0})
103
      ) pvt
104
      FOR JSON AUTO, WITHOUT_ARRAY_WRAPPER/*, INCLUDE_NULL_VALUES*/
105
    )
106
    SELECT @Json'
107
    SELECT @Sql = REPLACE(@Sql, '{0}', @PvtList)
108
    SELECT @Sql = REPLACE(@Sql, '{1}', @SelectList)
109

110
    DECLARE @Json TABLE ([Json] NVARCHAR(MAX))
111
    INSERT INTO @Json
112
    EXECUTE(@Sql)
113

114
    -- generate full loki request
115
    DECLARE @LokiRequest NVARCHAR(MAX) = (
116
      SELECT
117
        [stream] = JSON_QUERY(@StreamLabels),
118
        [values] = JSON_QUERY('[[' + QUOTENAME(CAST(@Time AS VARCHAR(20)), '"') + ',"' + STRING_ESCAPE([Json], 'json') + '"]]')
119
      FROM @Json
120
      FOR JSON AUTO, ROOT('streams')
121
    )
122
    --SELECT @LokiRequest
123
    --PRINT @LokiRequest
124

125
    -- reset exception
126
    EXECUTE LogProperty_Add 'Exception', NULL
127

128
    -- loose the request
129
    DECLARE @HeadersJson NVARCHAR(MAX) = (
130
      SELECT *
131
      FROM (
132
        SELECT
133
          [content-type] = 'application/json',
134
          [content-length] = CAST(LEN(@LokiRequest) AS VARCHAR(20))
135
      ) a
136
      FOR JSON AUTO
137
    )
138
    --SELECT @HeadersJson
139

140
    EXECUTE HttpPost 'http://localhost:3100/loki/api/v1/push', @LokiRequest, NULL, NULL, @HeadersJson
141
  END TRY
142
  BEGIN CATCH
143
    -- swallow
144
  END CATCH
145
END

Fatal#

1
CREATE PROCEDURE [dbo].[LogTo_Fatal](
2
  @Message NVARCHAR(4000),
3
  @CallingProc SYSNAME = NULL
4
)
5
AS
6
BEGIN
7
  IF @CallingProc IS NOT NULL
8
  BEGIN
9
    EXECUTE LogProperty_AddSourceContext @CallingProc
10
  END
11

12
  -- extra error details
13
  IF ERROR_MESSAGE() IS NOT NULL
14
  BEGIN
15
    DECLARE @Exception NVARCHAR(4000)
16
    SELECT @Exception = (
17
      SELECT *
18
      FROM (
19
        SELECT
20
          [ErrorNumber] = ERROR_NUMBER(),
21
          [ErrorSeverity] = ERROR_SEVERITY(),
22
          [ErrorState] = ERROR_STATE(),
23
          [ErrorProcedure] = ERROR_PROCEDURE(),
24
          [ErrorLine] = ERROR_LINE(),
25
          [ErrorMessage] = ERROR_MESSAGE()
26
      ) exception
27
      FOR JSON AUTO, WITHOUT_ARRAY_WRAPPER
28
    )
29

30
    EXECUTE LogProperty_Add 'Exception', @Exception
31
  END
32

33
  EXECUTE LogTo_Impl @Message, 'critical'
34
END

Error#

1
CREATE PROCEDURE [dbo].[LogTo_Error](
2
  @Message NVARCHAR(4000),
3
  @CallingProc SYSNAME = NULL
4
)
5
AS
6
BEGIN
7
  IF @CallingProc IS NOT NULL
8
  BEGIN
9
    EXECUTE LogProperty_AddSourceContext @CallingProc
10
  END
11

12
  -- extra error details
13
  IF ERROR_MESSAGE() IS NOT NULL
14
  BEGIN
15
    DECLARE @Exception NVARCHAR(4000)
16
    SELECT @Exception = (
17
      SELECT *
18
      FROM (
19
        SELECT
20
          [ErrorNumber] = ERROR_NUMBER(),
21
          [ErrorSeverity] = ERROR_SEVERITY(),
22
          [ErrorState] = ERROR_STATE(),
23
          [ErrorProcedure] = ERROR_PROCEDURE(),
24
          [ErrorLine] = ERROR_LINE(),
25
          [ErrorMessage] = ERROR_MESSAGE()
26
      ) exception
27
      FOR JSON AUTO, WITHOUT_ARRAY_WRAPPER
28
    )
29

30
    EXECUTE LogProperty_Add 'Exception', @Exception
31
  END
32

33
  EXECUTE LogTo_Impl @Message, 'error'
34
END

Debug#

1
CREATE PROCEDURE [dbo].[LogTo_Debug](
2
  @Message NVARCHAR(4000),
3
  @CallingProc SYSNAME = NULL
4
)
5
AS
6
BEGIN
7
  IF @CallingProc IS NOT NULL
8
  BEGIN
9
    EXECUTE LogProperty_AddSourceContext @CallingProc
10
  END
11

12
  EXECUTE LogTo_Impl @Message, 'debug'
13
END

Warning#

1
CREATE PROCEDURE [dbo].[LogTo_Warning](
2
  @Message NVARCHAR(4000),
3
  @CallingProc SYSNAME = NULL
4
)
5
AS
6
BEGIN
7
  IF @CallingProc IS NOT NULL
8
  BEGIN
9
    EXECUTE LogProperty_AddSourceContext @CallingProc
10
  END
11

12
  EXECUTE LogTo_Impl @Message, 'warn'
13
END

Information#

1
CREATE PROCEDURE [dbo].[LogTo_Information](
2
  @Message NVARCHAR(4000),
3
  @CallingProc SYSNAME = NULL
4
)
5
AS
6
BEGIN
7
  IF @CallingProc IS NOT NULL
8
  BEGIN
9
    EXECUTE LogProperty_AddSourceContext @CallingProc
10
  END
11

12
  EXECUTE LogTo_Impl @Message, 'info'
13
END

Verbose#

1
CREATE PROCEDURE [dbo].[LogTo_Verbose](
2
  @Message NVARCHAR(4000),
3
  @CallingProc SYSNAME = NULL
4
)
5
AS
6
BEGIN
7
  IF @CallingProc IS NOT NULL
8
  BEGIN
9
    EXECUTE LogProperty_AddSourceContext @CallingProc
10
  END
11

12
  EXECUTE LogTo_Impl @Message, 'trace'
13
END

Log Property Stack#

This is how you add additional context to your logs with some convenience functions below. They are just key value pairs that will get added to the log stream and can be parsed out using the Loki logQL within Grafana.

Implementation#

1
ALTER PROCEDURE [dbo].[LogProperty_Add](
2
  @Name NVARCHAR(100),
3
  @Value NVARCHAR(4000)
4
)
5
AS
6
BEGIN
7
  BEGIN TRY
8
    --EXECUTE sp_set_session_context '__index__', '["ApplicationInstance", "CorrelationId"]'
9
    --DECLARE @Name VARCHAR(100) = 'InstanceId'
10

11
    -- you cannot query values from the SESSION_CONTEXT without explicitly knowing the key
12
    -- for this reason, we house a list of keys in a __index__ session value so we know what
13
    -- to pull when we generate the actual log
14
    -- add new key to property bag
15
    DECLARE @IndexKeys NVARCHAR(4000)
16
    SELECT @IndexKeys = '[' + ISNULL(STUFF(
17
-- stuff select begin
18
(SELECT ',"' + [Value] + '"'
19
FROM (
20
  SELECT [value]
21
  FROM OPENJSON(CAST(SESSION_CONTEXT(N'__index__') AS NVARCHAR(MAX)))
22
  UNION
23
  SELECT @Name
24
) a([value])
25
FOR XML PATH ('')),
26
-- stuff select end
27
    1, 1, ''), '') + ']'
28

29
    -- persist new property bag
30
    EXECUTE sp_set_session_context '__index__', @IndexKeys
31
    --SELECT SESSION_CONTEXT(N'__index__')
32

33
    -- persist log property
34
    EXECUTE sp_set_session_context @Name, @Value
35
  END TRY
36
  BEGIN CATCH
37
    -- swallow
38
  END CATCH
39
END

CorrelationId#

1
ALTER PROCEDURE [dbo].[LogProperty_CorrelationId](
2
  @Value NVARCHAR(4000)
3
)
4
AS
5
BEGIN
6
  EXECUTE LogProperty_Add 'CorrelationId', @Value
7
END

SourceContext#

1
ALTER PROCEDURE [dbo].[LogProperty_AddSourceContext](
2
  @Value NVARCHAR(4000)
3
)
4
AS
5
BEGIN
6
  EXECUTE LogProperty_Add 'SourceContext', @Value
7
END

InstanceId#

1
ALTER PROCEDURE [dbo].[LogProperty_InstanceId](
2
  @Value NVARCHAR(4000)
3
)
4
AS
5
BEGIN
6
  EXECUTE LogProperty_Add 'InstanceId', @Value
7
END

~ SK

The Software Stack#

Grafana#

Loki#

Log Property Stack#

Dependency Recommendations#

Prometheus#

Performance counters#

Logging Fundamentals#

Log Key Events#

Choose Appropriate Logging Level#

Bonus — Logging in SQL Server#

Configure#

Log Level Functions#

Implementation#

Fatal#

Error#

Debug#

Warning#

Information#

Verbose#

Log Property Stack#

Implementation#

CorrelationId#

SourceContext#

InstanceId#

Grafana #

Loki #

Prometheus #