Change logging to use Serilog #666

rjmholt · 2018-05-20T16:51:49Z

After having a few problems with logging and thread safety, I've replaced our hand-rolled logger with Serilog, and in such a way that only one file depends on it. Note that we also have to copy the Serilog DLLs into the module.

There are probably a couple of rough edges that still need patching up here, so please give it a try. Especially on .NET Framework platforms.

TylerLeonhardt · 2018-05-20T17:15:11Z

Can you add the Serilog reference to the TPN?

https://github.com/PowerShell/PowerShellEditorServices/blob/master/Third%20Party%20Notices.txt

rjmholt · 2018-05-20T17:17:07Z

Looks like the logging tests are failing!

rjmholt · 2018-05-20T18:52:03Z

I should add a TPN for each of the Serilog bits I assume, since they are separate.

Also, is there a reason the Third Party Notice file has quotes in the name? It's named 'Third Party Notices.txt' and not, e.g., Third Party Notices.txt.

rkeithhill · 2018-05-21T01:18:48Z

PowerShellEditorServices.build.ps1

@@ -177,13 +177,13 @@ task TestServer -If { !$script:IsUnix } {
    exec { & $script:dotnetExe xunit -configuration $Configuration -framework net452 -verbose -nobuild }
 }

-task TestProtocol -If { !$script:IsUnix} {
+task TestProtocol -If { !$script:IsUnix } {


We should add the config line to trim trailing whitespace if/when we add a .editorconfig file. :-)

Agreed! I think the .editorconfig is a good idea.

Do you mean here I should remove the space I added before the brace?

Sorry, bad example. There were some trailing spaces after a chained exception filter that got removed. That's where the editorconfig file would have helped me where I use VS and it doesn't normally trim trailing whitespace.

rjmholt · 2018-05-21T01:21:46Z

So @rkeithhill made a good point about renaming ILogger. I just took it out on the basis that I'd renamed an interface that only had one implementation, but there are also good arguments for leaving it in and it would make the PR much smaller. Thoughts?

rkeithhill · 2018-05-21T01:27:14Z

Less code churn is usually better unless there's a good reason for it. :-)

rkeithhill · 2018-05-21T01:52:46Z

src/PowerShellEditorServices/Analysis/AnalysisService.cs

@@ -101,7 +101,7 @@ public string SettingsPath
        /// Creates an instance of the AnalysisService class.
        /// </summary>
        /// <param name="settingsPath">Path to a PSScriptAnalyzer settings file.</param>
-        /// <param name="logger">An ILogger implementation used for writing log messages.</param>
+        /// <param name="logger">A logger used for writing log messages.</param>


Might as well revert all these comment changes. That removes ~25 more files from the PR. :-)

rkeithhill · 2018-05-21T02:04:34Z

BTW what does the log file look like with this change?

rjmholt · 2018-05-21T02:18:20Z

Logging looks like this at the moment:

2018-05-20 19:15:35.609 [NORMAL] /home/rob/Documents/Dev/Microsoft/PowerShellEditorServices/src/PowerShellEditorServices.Host/EditorServicesHost.cs: In 'StartLogging', line 166:
    PowerShell Editor Services Host v1.7.0.0 starting (pid 20583)...
    
      Host application details:
    
        Name:      Visual Studio Code Host
        ProfileId: Microsoft.VSCode
        Version:   1.7.0
    
2018-05-20 19:15:35.627 [NORMAL] /home/rob/Documents/Dev/Microsoft/PowerShellEditorServices/src/PowerShellEditorServices.Host/EditorServicesHost.cs: In 'StartLanguageService', line 198:
    Language service started, type = Tcp, endpoint = 17901
2018-05-20 19:15:35.634 [NORMAL] /home/rob/Documents/Dev/Microsoft/PowerShellEditorServices/src/PowerShellEditorServices.Host/EditorServicesHost.cs: In 'StartDebugService', line 268:
    Debug service started, type = Tcp, endpoint = 20769
2018-05-20 19:15:36.472 [NORMAL] /home/rob/Documents/Dev/Microsoft/PowerShellEditorServices/src/PowerShellEditorServices/Session/PowerShellContext.cs: In 'Initialize', line 220:
    PowerShell runtime version: 6.1.0, edition: Core
2018-05-20 19:15:37.196 [NORMAL] /home/rob/Documents/Dev/Microsoft/PowerShellEditorServices/src/PowerShellEditorServices.VSCode/ComponentRegistration.cs: In 'Register', line 36:
    PowerShell Editor Services VS Code module loaded.
2018-05-20 19:15:37.278 [ERROR] /home/rob/Documents/Dev/Microsoft/PowerShellEditorServices/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageDispatcher.cs: In 'DispatchMessage', line 147:
    MessageDispatcher: No handler registered for Event type 'initialized'
2018-05-20 19:15:37.279 [ERROR] /home/rob/Documents/Dev/Microsoft/PowerShellEditorServices/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageDispatcher.cs: In 'DispatchMessage', line 147:
    MessageDispatcher: No handler registered for Event type '$/setTraceNotification'

rkeithhill · 2018-05-21T02:31:21Z

I wonder if we should consider adding a newline after the log messages (except for the first one above)? It might make visually scanning the log file a bit easier. Then again, it could be that I'm just used to the spacing on the existing log file. :-)

rjmholt · 2018-05-21T02:33:35Z

Actually I was thinking the same thing!

rkeithhill

Other than the extra newline to space out the individual log messages a bit, this PR LGTM!

TylerLeonhardt

Looks good - just a few questions before a approve.

TylerLeonhardt · 2018-05-21T17:51:44Z

src/PowerShellEditorServices/Utility/Logging.cs

+            /// <param name="logLevel">The minimum log level for this file</param>
+            /// <param name="useMultiprocess">Set whether the log file should be readable by other processes</param>
+            /// <returns>the ILogger builder for reuse.</returns>
+            public Builder AddLogFile(string filePath, LogLevel? logLevel = null, bool useMultiprocess = false)


useMultiprocess isn't used at all. Is this on purpose?

Also, what happens when the log level is null? What logs will we see?

TylerLeonhardt · 2018-05-21T17:53:32Z

src/PowerShellEditorServices/Utility/Logging.cs

+            }
+
+            /// <summary>
+            /// Take the log configuration use it to create An ILogger implementation.


nit: grammar? "Take the log configuration and use it..."?

TylerLeonhardt · 2018-05-21T18:05:09Z

src/PowerShellEditorServices/Utility/Logging.cs

+            /// </summary>
+            /// <param name="logLevel">The minimum log level for console logging.</param>
+            /// <returns>the ILogger builder for reuse.</returns>
+            public Builder AddConsoleLogging(LogLevel? logLevel = null)


Will this show up in the Integrated Terminal or in the VSCode logging view?

I'm not sure. Possibly the latter if VSCode redirects stdout to its logging view.

I put it in so you can start EditorServices by itself and see logs printed to the console you start it in. I haven't actually tested that that works though.

TylerLeonhardt

LGTM Yay async logging 🎉 🎉

SeeminglyScience

Really excited for this change, great work @rjmholt!

Just a couple very minor suggestions.

SeeminglyScience · 2018-05-23T12:59:04Z

src/PowerShellEditorServices.Protocol/Server/LanguageServer.cs

@@ -54,7 +54,7 @@ public IEditorOperations EditorOperations
        /// <param name="messageHandlers">An object that manages all of the message handlers</param>
        /// <param name="messageSender">The message sender</param>
        /// <param name="serverCompletedTask">A TaskCompletionSource<bool> that will be completed to stop the running process</param>
-        /// <param name="logger">The logger</param>
+        /// <param name="logger">the logger</param>


Any particular reason for changing the case here? Not a big deal, just curious if this was intentional.

Not intentional — the result of changing all the logging doc lines and back again.

SeeminglyScience · 2018-05-23T13:14:59Z

src/PowerShellEditorServices/Utility/Logging.cs

+
+                return new PsesLogger(configuration.CreateLogger());
+            }
+


Style nitpick: Extra new line can be removed.

SeeminglyScience · 2018-05-23T13:15:56Z

src/PowerShellEditorServices/Utility/Logging.cs

+            {
+                return s_nullLogger ?? (s_nullLogger = CreateLogger().Build());
+            }
+        }


Style nitpick: Add new line to separate members NullLogger and s_nullLogger

SeeminglyScience · 2018-05-23T13:20:05Z

src/PowerShellEditorServices/Utility/PsesLogger.cs

+            [CallerLineNumber] int callerLineNumber = 0)
+        {
+            _logger.Error("[{Error:l}] {CallerSourceFile:l}: In method '{CallerName:l}', line {CallerLineNumber}:\n    {ErrorMessage:l}\n    {Exception:l}\n",
+                LogLevel.Error.ToString().ToUpper(), callerSourceFile, callerName, callerLineNumber, errorMessage, exception);


Should the result of LogLevel.Error.ToString().ToUpper() be a constant somewhere instead? I'm assuming that ToString().ToUpper() will be called on each invocation regardless of log level.

SeeminglyScience · 2018-05-23T13:32:39Z

src/PowerShellEditorServices/Utility/PsesLogger.cs

+                msgLines[i] = msgLines[i].Insert(0, "    ");
+            }
+
+            return String.Join("\n", msgLines)+"\n";


Is it feasible to use StringBuilder here to reduce some string allocations? Something like

var sb = new System.Text.StringBuilder(logMessage); return sb.Replace("\n", "\n ").ToString();

Edit: I should clarify that I'm referring to the method, not this line in particular

SeeminglyScience · 2018-05-23T13:34:42Z

src/PowerShellEditorServices/Utility/PsesLogger.cs

+        }
+
+        #region IDisposable Support
+        private bool disposedValue = false; // To detect redundant calls


Style nitpick: field name should be _disposedValue and comment should be above.

Agreed, although this is what the "dispose pattern" snippet expands to.

…ervices into logging-serilog

…, use cross-platform newlines

rjmholt · 2018-05-23T20:19:55Z

Ok, I think I've finally understood Serilog's template string stuff. Because we do some indirection, we basically don't end up using a lot of it and do our own string processing, which I don't think can really be helped.

I've changed the newlines to use Environment.NewLine, which is what I suspect Serilog's "{NewLine}" string template expands to.

Our current log files look something like this:

2018-05-23 13:11:37.201 [NORMAL] C:\Users\roholt\Documents\Dev\PowerShellEditorServices\src\PowerShellEditorServices.Host\EditorServicesHost.cs: In method 'StartLogging', line 166:
    PowerShell Editor Services Host v1.7.0.0 starting (pid 4324)...
    
      Host application details:
    
        Name:      Visual Studio Code Host
        ProfileId: Microsoft.VSCode
        Version:   1.7.0
        Arch:      64-bit
    
      Operating system details:
    
        Version: Microsoft Windows NT 10.0.16299.0
        Arch:    64-bit

2018-05-23 13:11:37.218 [NORMAL] C:\Users\roholt\Documents\Dev\PowerShellEditorServices\src\PowerShellEditorServices.Host\EditorServicesHost.cs: In method 'StartLanguageService', line 198:
    Language service started, type = Tcp, endpoint = 18125

2018-05-23 13:11:37.222 [NORMAL] C:\Users\roholt\Documents\Dev\PowerShellEditorServices\src\PowerShellEditorServices.Host\EditorServicesHost.cs: In method 'StartDebugService', line 268:
    Debug service started, type = Tcp, endpoint = 26849

2018-05-23 13:11:37.882 [NORMAL] C:\Users\roholt\Documents\Dev\PowerShellEditorServices\src\PowerShellEditorServices\Session\PowerShellContext.cs: In method 'Initialize', line 220:
    PowerShell runtime version: 5.1.16299.431, edition: Desktop

2018-05-23 13:11:38.081 [ERROR] C:\Users\roholt\Documents\Dev\PowerShellEditorServices\src\PowerShellEditorServices\Analysis\AnalysisService.cs: In method 'InvokePowerShell', line 445:
    The term 'Get-ScriptAnalyzerRule' is not recognized as the name of a cmdlet, function, script file, or operable program. Check the spelling of the name, or if a path was included, verify that the path is correct and try again.

2018-05-23 13:11:38.499 [NORMAL] C:\Users\roholt\Documents\Dev\PowerShellEditorServices\src\PowerShellEditorServices.VSCode\ComponentRegistration.cs: In method 'Register', line 36:
    PowerShell Editor Services VS Code module loaded.

2018-05-23 13:11:38.656 [ERROR] C:\Users\roholt\Documents\Dev\PowerShellEditorServices\src\PowerShellEditorServices.Protocol\MessageProtocol\MessageDispatcher.cs: In method 'DispatchMessage', line 152: Unhandled event
    System.Exception: VERY VERY BAD!!!
       at Microsoft.PowerShell.EditorServices.Protocol.MessageProtocol.MessageDispatcher.ThrowSomething()
       at Microsoft.PowerShell.EditorServices.Protocol.MessageProtocol.MessageDispatcher.<DispatchMessage>d__7.MoveNext()

2018-05-23 13:11:38.656 [ERROR] C:\Users\roholt\Documents\Dev\PowerShellEditorServices\src\PowerShellEditorServices.Protocol\MessageProtocol\MessageDispatcher.cs: In method 'DispatchMessage', line 152: Unhandled event
    System.Exception: VERY VERY BAD!!!
       at Microsoft.PowerShell.EditorServices.Protocol.MessageProtocol.MessageDispatcher.ThrowSomething()
       at Microsoft.PowerShell.EditorServices.Protocol.MessageProtocol.MessageDispatcher.<DispatchMessage>d__7.MoveNext()

2018-05-23 13:11:39.459 [ERROR] C:\Users\roholt\Documents\Dev\PowerShellEditorServices\src\PowerShellEditorServices\Analysis\AnalysisService.cs: In method 'InvokePowerShell', line 445:
    The term 'Invoke-ScriptAnalyzer' is not recognized as the name of a cmdlet, function, script file, or operable program. Check the spelling of the name, or if a path was included, verify that the path is correct and try again.

rjmholt · 2018-05-23T20:27:32Z

Just to document:

Serilog has two levels of string template: the output template and the actual event template.

The output template would be useful to us, since it has pre-defined settings for {NewLine}, (Log){Level}, {Timestamp} and {Exception}. But these don't work so well in our case, e.g.:

Our log levels are different from Serilogs, so we do so translation that Serilog can't understand.
For {Exception} to work, you need to log it without a template string, so we lose our log level and source metadata information.
{NewLine} only exists in the output template, not the log template...

So instead we call ToString() on a few things and do some string building with indents.

But it's still very worth using Serilog, since it handles all the sinks and the asynchronous stuff very nicely.

SeeminglyScience · 2018-05-24T11:42:02Z

@rjmholt

Because we do some indirection, we basically don't end up using a lot of it and do our own string processing

We might be able to do our own string processing and still let Serilog handle the when. You can pass it a custom Serilog.Formatting.ITextFormatter implementation to the sink when configuring it. There's also a way to customize the formatting of specific objects.

I wouldn't suggest holding up the PR for any of that though, this is already way better than what we currently have :)

rjmholt · 2018-05-24T15:42:33Z

Yeah, I actually implemented a custom format provider for our LogLevel enums at one stage because I didn't like calling logLevel.ToString().ToUpper().

It took a surprising amount of code and playing around with the $ and @ destructuring stuff I still couldn't get it to work. That was where I submitted the series of comments above about not being able to make Serilog work. I understand it a bit better now I think, so it would be easier now. But still a fair amount of complexity and probably a slowdown basically for some indenting.

rjmholt · 2018-05-24T15:43:21Z

Anyway, unless there are any objections, I'll merge this at the end of the day (in about 8 hours).

Robert Holt and others added 13 commits May 17, 2018 20:18

Introduce serilog as logger backend

6f64497

Put netstandard first in csproj files

3781012

Add serilog logic, begin internal builder for logger

535d6c1

Add log builder, switch log use, add comments

4f35fef

Add Serilog DLL to module output

9c6dc76

Add .NET Framework Serilog references

cf5086d

Add required XML comments

ab9f87f

Partial revert line endings change

79d7c6b

Revert line ending changes

c0214df

Revert line ending changes

40c183c

Revert line ending changes

be2f224

Revert line ending changes

2f3b057

Update comments to remove ILogger references

c73fd2b

rjmholt added 8 commits May 20, 2018 10:22

Update Third Party Notices

a1e830d

Make log files readable by other processes

164b4d3

Add XML comment for multiprocess option

54f169d

Make file logging asynchronous

1997fba

Make logger disposable for testing

6dd1c37

Add XML comment for dispose pattern

acd74f3

Fix csproj

3c1c51a

Make log level in messages uppercase

3f316ca

rjmholt added 6 commits May 20, 2018 11:57

Fix log output template

a83e31c

Make log levels log properly

d7bacd9

Destructure log level enums

d8e03c4

Use uppercase template modifier

bd6cc79

Try uppercase without destructuring

ec3d2a9

Remove overengineered stuff, use unquoted strings in messages

fda57ef

rjmholt added 2 commits May 20, 2018 18:02

Remove logger interface, remove log file sharing

e27caff

Add static null logger

23cd8ec

rkeithhill reviewed May 21, 2018

View reviewed changes

Revert to ILogger usage

d03ee64

rkeithhill reviewed May 21, 2018

View reviewed changes

Revert logger comments

9dcaef4

Revert remaining comment changes

64dd41d

rkeithhill approved these changes May 21, 2018

View reviewed changes

Add newlines to log lines

9ecf846

TylerLeonhardt reviewed May 21, 2018

View reviewed changes

Remove extraneous multiprocess option, improve comments

fb7fc0f

TylerLeonhardt approved these changes May 21, 2018

View reviewed changes

TylerLeonhardt requested a review from SeeminglyScience May 22, 2018 17:09

SeeminglyScience approved these changes May 23, 2018

View reviewed changes

Robert Holt added 2 commits May 23, 2018 10:03

Merge branch 'master' of https://github.com/rjmholt/PowerShellEditorS…

54a53bb

…ervices into logging-serilog

Address @SeeminglyScience feedback, correct log strings and templates…

e9becd1

…, use cross-platform newlines

rjmholt merged commit 8a1e9bd into PowerShell:master May 25, 2018

rjmholt mentioned this pull request Jun 26, 2018

Frequent powershell crashes PowerShell/vscode-powershell#1346

Closed

rjmholt deleted the logging-serilog branch December 12, 2018 06:00

Change logging to use Serilog #666

Change logging to use Serilog #666

Conversation

rjmholt commented May 20, 2018

TylerLeonhardt commented May 20, 2018

rjmholt commented May 20, 2018

rjmholt commented May 20, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rjmholt commented May 21, 2018 • edited Loading

rkeithhill commented May 21, 2018

Choose a reason for hiding this comment

rkeithhill commented May 21, 2018

rjmholt commented May 21, 2018

rkeithhill commented May 21, 2018

rjmholt commented May 21, 2018

rkeithhill left a comment

Choose a reason for hiding this comment

TylerLeonhardt left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

TylerLeonhardt left a comment

Choose a reason for hiding this comment

SeeminglyScience left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

SeeminglyScience May 23, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rjmholt commented May 23, 2018

rjmholt commented May 23, 2018

SeeminglyScience commented May 24, 2018

rjmholt commented May 24, 2018

rjmholt commented May 24, 2018

rjmholt commented May 21, 2018 •

edited

Loading

SeeminglyScience May 23, 2018 •

edited

Loading