New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add structured logging (json) to whole server code base: file/error/console logs and stats (except ClientAPI) #1678

Merged
merged 3 commits into from Dec 31, 2018

Conversation

7 participants
@shaan1337
Copy link
Member

shaan1337 commented Jul 20, 2018

  • This PR adds structured logging to the whole server code base: file/error/console logs and stats (no support for ClientAPI yet) preserving backward compatibility
  • Add option --structured-log/StructuredLog to enable structured logging on startup
  • Upgrade NLog to version 4.5.6
  • Improve logging performance by adding keepFileOpen="true"

Co-authored-by: Avish Cheetaram avishcheetaram.ai@gmail.com
Co-authored-by: Lougarou yogisawesome@gmail.com
Co-authored-by: Shaan Nobee sniper111@gmail.com

<layout xsi:type="JsonLayout">
<attribute name="PID" layout="${processid}" />
<attribute name="ThreadID" layout="${threadid}" />
<attribute name="Date" layout="${date:universalTime=true:format=yyyy\.MM\.dd HH\:mm\:ss\.fff}" />

This comment has been minimized.

@shaan1337

shaan1337 Jul 21, 2018

Member

format needs to be fixed to yyyy\-MM\-ddTHH\:mm\:ss\.ffffffZ

@avish0694 avish0694 assigned avish0694 and unassigned avish0694 Jul 23, 2018

@avish0694 avish0694 requested review from avish0694 and removed request for avish0694 Jul 23, 2018

@shaan1337 shaan1337 referenced this pull request Jul 23, 2018

Closed

Replaced NLog with Serilog #1651

3 of 3 tasks complete
@snakefoot

This comment has been minimized.

Copy link

snakefoot commented Jul 23, 2018

@shaan1337 Any reason why you are not referencing the NLog-nuget-package in EventStore.Core.Tests.csproj:

<Reference Include="NLog">
<HintPath>..\libs\NLog.dll</HintPath>
</Reference>

Along with removing this file from the repository:

src/libs/NLog.dll

You can also optimize the log.config by adding timeToSleepBetweenBatches="0" to the default-wrapper (Supported by NLog ver. 4.3.11 or later):

<default-wrapper xsi:type="AsyncWrapper" overflowAction="Grow" timeToSleepBetweenBatches="0" />

It will optimize the performance of the AsyncWrapper, and also make the system more "silent" when idle (reducing the number of timer events)

<variable name="VerboseLayout" value="[PID:${processid:padCharacter=0:padding=5}:${threadid:padCharacter=0:padding=3} ${date:universalTime=true:format=yyyy\.MM\.dd HH\:mm\:ss\.fff} ${level:padding=-5:uppercase=true} ${logger:padding=-20:fixedLength=true}] ${message}${onexception:${newline}EXCEPTION OCCURRED:${newline}${exception:format=tostring:innerFormat=tostring:maxInnerExceptionLevel=20}}"/>
<variable name="ConsoleLayout" value="[${processid:padCharacter=0:padding=5},${threadid:padCharacter=0:padding=2},${date:universalTime=true:format=HH\:mm\:ss\.fff}] ${message}${onexception:${newline}EXCEPTION OCCURRED:${newline}${exception:format=message}}"/>
<variable name="VerboseLayout" value="[PID:${processid:padCharacter=0:padding=5}:${threadid:padCharacter=0:padding=3} ${date:universalTime=true:format=yyyy\.MM\.dd HH\:mm\:ss\.fff} ${level:padding=-5:uppercase=true} ${logger:padding=-20:fixedLength=true}] ${message}${onexception:${newline}${literal:text=EXCEPTION OCCURRED}${newline}${exception:format=tostring:innerFormat=tostring:maxInnerExceptionLevel=20}}"/>
<variable name="ConsoleLayout" value="[${processid:padCharacter=0:padding=5},${threadid:padCharacter=0:padding=2},${date:universalTime=true:format=HH\:mm\:ss\.fff}] ${message}${onexception:${newline}${literal:text=EXCEPTION OCCURRED}${newline}${exception:format=message}}"/>
<variable name="LogFileNameBase" value="${logsdir}/${shortdate:universalTime=true}/${environment:variable=EVENTSTORE_INT-COMPONENT-NAME}"/>

<targets>
<default-wrapper xsi:type="AsyncWrapper" overflowAction="Grow" />

This comment has been minimized.

@shaan1337

shaan1337 Jul 25, 2018

Member

Add timeToSleepBetweenBatches="0" as per recommendations of @snakefoot

@shaan1337

This comment has been minimized.

Copy link
Member

shaan1337 commented Jul 25, 2018

thanks for the tip @snakefoot, we'll add this. we have only a few external dependencies, so just including the DLLs simplifies the build/release process

@gregoryyoung

This comment has been minimized.

Copy link
Member

gregoryyoung commented Jul 25, 2018

My guess is that this is historical.

@@ -183,11 +184,11 @@ public void Handle(GossipMessage.GossipSendFailed message)

if (CurrentMaster != null && node.InstanceId == CurrentMaster.InstanceId)
{
Log.Trace("Looks like master [{0}, {1:B}] is DEAD (Gossip send failed), though we wait for TCP to decide.",
Log.Trace("Looks like master [{recipient}, {instanceId:B}] is DEAD (Gossip send failed), though we wait for TCP to decide.",

This comment has been minimized.

@shaan1337

shaan1337 Jul 25, 2018

Member

rename recipient

@@ -76,6 +76,7 @@ internal class TcpPackageConnection
log.Debug("TcpPackageConnection: connection to [{0}, L{1}, {2:B}] failed. Error: {3}.", conn.RemoteEndPoint, conn.LocalEndPoint, connectionId, error);
if (connectionClosed != null)
connectionClosed(this, error);
log.Debug("TcpPackageConnection: connection to [{0}, L{localEndPoint}, {connectionId:B}] failed. Error: {e}.", conn.RemoteEndPoint, conn.LocalEndPoint, connectionId, error);

This comment has been minimized.

@shaan1337

shaan1337 Jul 25, 2018

Member

remove this line, seems like a wrong merge

@@ -64,31 +70,32 @@ public void Warn(string format, params object[] args)
public void Trace(string format, params object[] args)
{
_logger.Trace(format, args);

This comment has been minimized.

@shaan1337

shaan1337 Jul 25, 2018

Member

remove extra line

<attribute name="Message" layout="${message:raw=true}" />
<attribute name="Exception" layout="${exception:format=@}" encode="false"/>
<attribute name="EventProperties" encode="false" >
<layout type='JsonLayout' includeAllProperties="true"/>

This comment has been minimized.

@shaan1337

shaan1337 Jul 25, 2018

Member

verify this line

This comment has been minimized.

@shaan1337

@shaan1337 shaan1337 requested a review from riccardone Jul 25, 2018

@riccardone
Copy link
Member

riccardone left a comment

in log.config I suggest to add the following target ColoredConsole instead of the Console

<target name="plainConsoleLog" xsi:type="ColoredConsole" layout="${ConsoleLayout}" useDefaultRowHighlightingRules="true">
      <highlight-row condition="level == LogLevel.Info" foregroundColor="Green" />
    </target>```
@shaan1337

This comment has been minimized.

Copy link
Member

shaan1337 commented Jul 26, 2018

Manual review completed - several commits pushed.

@snakefoot

This comment has been minimized.

Copy link

snakefoot commented Jul 26, 2018

It is nice of you to copy the source code of NLog and taking it to your bosom, but if you only need to remove quotes around strings, then you can also do this:

        class OverrideValueFormatter : IValueFormatter
        {
            private IValueFormatter _originalFormatter;

            public bool IsStructured { get; set; }

            public OverrideValueFormatter(IValueFormatter originalFormatter)
            {
                _originalFormatter = originalFormatter;
            }

            public bool FormatValue(object value, string format, NLog.MessageTemplates.CaptureType captureType, IFormatProvider formatProvider, System.Text.StringBuilder builder)
            {
                if (!IsStructured && captureType == NLog.MessageTemplates.CaptureType.Normal)
                {
                    switch (Convert.GetTypeCode(value))
                    {
                        case TypeCode.String:
                            {
                                builder.Append((string)value);
                                return true;
                            }
                        case TypeCode.Char:
                            {
                                builder.Append((char)value);
                                return true;
                            }
                        case TypeCode.Empty:
                            return true;  // null becomes empty string
                    }
                }

                return _originalFormatter.FormatValue(value, format, captureType, formatProvider, builder);
            }
        }

And then use it like this:

            var oldFormatter = NLog.Config.ConfigurationItemFactory.Default.ValueFormatter;
            var newFormatter = new OverrideValueFormatter(oldFormatter);
            newFormatter.IsStructured = false;
            NLog.Config.ConfigurationItemFactory.Default.ValueFormatter = newFormatter;

Then you can remove these files:

+    <Compile Include="Log\ESValueFormatter.cs" />
+    <Compile Include="Log\MruCache.cs" />
+    <Compile Include="Log\SingleItemOptimizedHashSet.cs" />
@shaan1337

This comment has been minimized.

Copy link
Member

shaan1337 commented Jul 27, 2018

hey @snakefoot thanks that's perfect, we didn't find an easier way earlier

@Lougarou
Copy link
Contributor

Lougarou left a comment

Code Review looks good.
Optional changes:

  1. replace string.joins to lists so that value is still json in the structured log
  2. fix padding in some places(if required)
@@ -3,6 +3,7 @@
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
throwExceptions="false"
throwConfigExceptions="true"

This comment has been minimized.

@shaan1337

@shaan1337 shaan1337 force-pushed the nlog-structured-log-rebased branch from e328ba2 to 7ede396 Nov 13, 2018

@shaan1337 shaan1337 force-pushed the nlog-structured-log-rebased branch from 7ede396 to 910f127 Dec 31, 2018

@shaan1337 shaan1337 force-pushed the nlog-structured-log-rebased branch from f8539ad to e4846bb Dec 31, 2018

@shaan1337

This comment has been minimized.

Copy link
Member

shaan1337 commented Dec 31, 2018

Additional logging changes made after rebase to master

avish0694 and others added some commits Jun 27, 2018

Add structured logging (json) to whole server code base: file/error/c…
…onsole logs and stats (except ClientAPI)

Add option --structured-log/StructuredLog to enable structured logging on startup

Co-authored-by: Lougarou <yogisawesome@gmail.com>
Co-authored-by: Shaan Nobee <sniper111@gmail.com>

@shaan1337 shaan1337 force-pushed the nlog-structured-log-rebased branch from e4846bb to c290c2a Dec 31, 2018

@shaan1337 shaan1337 merged commit 0693293 into master Dec 31, 2018

@shaan1337 shaan1337 deleted the nlog-structured-log-rebased branch Dec 31, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment