Logging

Serilog - Logging

For more details look at Serilog and the File sink

Logging levels

The MinimumLevel configures the logging levels for all inPoint.Core systems;

• Default are the inPoint.Core application logs
• Microsoft are the internal Microsoft ASP.NET logs
• System are the internal Microsoft .NET logs

Usually changing the Default level (application logging) should be enough.
Available logging levels:

Level	Usage
Verbose	Verbose is the noisiest level, rarely (if ever) enabled for a production app.
Debug	Debug is used for internal system events that are not necessarily observable from the outside, but useful when determining how something happened.
Information	Information events describe things happening in the system that correspond to its responsibilities and functions. Generally these are the observable actions the system can perform.
Warning	When service is degraded, endangered, or may be behaving outside of its expected parameters, Warning level events are used.
Error	When functionality is unavailable or expectations broken, an Error event is used.
Fatal	The most critical level, Fatal events demand immediate attention.

Setting the logging level

When you need to analyse an issue you should:

• raise the MinimulLevel/Default from Warning to Debug
• change the WriteTo/File/buffered to false in order to immediately save to the log file (otherwise it's buffered and you'll have to stop the Service to see the latest logs)

NOTE: do not forget to restore to their original values as these settings will negatively impact performance!

Log4net - Logging

log4net is a tool to help the programmer output log statements to a variety of output targets. It can be modified without restarting the application, the use of multiple loggers allows a much finer control than just an on and off switch.

App.Config/web.config

The configuration can be inside the default configuration file or more convenient in an external file.

For the external file, the section <appSettings> must contain the path to the real configuration.

log4net.Config

The full or relative path to the real configuration (keep in mind to encode it for XML)

Note
Use an absolute path, because the path is relative to the application base directory (AppDomain.CurrentDomain.BaseDirectory) and not relative to App.Config/web.config.

log4net.Config.Watch

If this flag is specified and set to true then the framework will watch the configuration file and will reload the config each time the file is modified.

log4net.Internal.Debug

If enabled, log4net will log its internal operation. Only useful if there is a problem with log4net itself!

Example

<?xml version="1.0" encoding="utf-8"?>
<configuration>
  <appSettings>
    <add key="log4net.Config" value="C:\Program Files (x86)\H&amp;S Heilig und Schubert Software AG\Pam.Storage\log4net.config"/>
    <add key="log4net.Config.Watch" value="True"/>
    <!-- <add key="log4net.Internal.Debug" value="true"/> -->
  </appSettings>
</configuration>

Config File

The config file contains two major parts:

• Appender: where the log is located, which format, filtering,....
• Logger: hierarchical structure of components which write logs, the level of logging and a list of appenders

Appender

An appender is the part which takes the log and writes/sends it to a specific target. They are configured with a name which is then used by the logger.

The most common type of appenders are listed here, for a full list go to the log4net homepage!

• OutputDebugStringAppender: writes to DebugOut (use DebugView or a similar tool to watch it; full documentation here)
• HsLog.HsRollingFileAppender (replaces the original RollingFileAppender): logs to a file an rotates based on file size
• ColoredConsoleAppender: write to the standard output and uses a colour filter (full documentation here)
• FileAppender: writes into a single log file (watch out for a full disk)
• SerilogAppender: forwards all logs to serilog.

Common Settings

name

The name of the logger.

type

The type of the logger (use the assembly-qualified name in case of a custom type or the predefined name from log4net).

Threshold

An optional setting so that only logs over this threshold are logged by this appender (the value can be any of the Levels as in the logger itself).

IMPORTANT! If a threshold is configured and you configure a more verbose log level remember to change the threshold as well (or remove it).

Layout

The format of the output, for more details see the log4net documentation or PatternLayout (see the Remarks section).
Default for File: %date{yyyy-MM-dd HH:mm:ss.fff} %-5level [%property{pid}/%thread] %c - %m%n
This example contains this parts:

• %date{...}: the date in a specific format
• %-5level: the Log-Level, left-align within five characters
• %property{pid}: the name of the process (will only work if HsLog.HsRollingFileAppender is used)
• %thread: Thread-Id (or the name of the thread for .NET workers)
• %c: Name of the logger (this is usually the name of the .NET class)
• %m: The message sent by the application
• %n: a line break at the end

Filter

Allows more complex filtering for an appender. The list of possible filter will be evaluated strict from top to bottom the first match will be used.

log4net.Filter.StringMatchFilter
Match the logged message (search for contained string or regular expression)

• acceptOnMatch: If true, the message will be logged if the filter matches.
• stringToMatch: A string to be searched with contains
• regexToMatch: A regular expression to be match (the whole message must match)

log4net.Filter.LevelRangeFilter
Match the log level (range)

• acceptOnMatch: If true, the message will be logged if the filter matches.
• levelMin: the minimum level to match
• levelMax: the maximum level to match

log4net.Filter.LevelMatchFilter\ Match the log level (exact)

• acceptOnMatch: If true, the message will be logged if the filter matches.
• levelToMatch: the log level to match

log4net.Filter.LoggerMatchFilter
Match the logger (hierarchical)

• acceptOnMatch: If true, the message will be logged if the filter matches.
• loggerToMatch: the logger and all children to match

log4net.Filter.DenyAllFilter
Denies the logger and matches all, usefull at the end of the list to deny all not matched messages.

Example:

1. Only Fatal Error, Error and Warnings will be logged.
2. If "DoNotLog" is contained in the message, the message is not logged.
3. If "DoLog" is contained in the message, the message is logged.
4. If any "number dot number" (e.g 12.45 or 1.2) combination is found the message is logged.
5. All other messages are discarded.

So bla DoNotLog, DoLog will be discarded. But Version 1.2.3 found will be logged.

    <appender name="HsRollingFileAppender" type="HsLog.HsRollingFileAppender, HsLog">

      <file value="C:\Temp\logs\log4Net.txt" />
      
      <maximumFileSize value="10MB" />
      <maxSizeRollBackups value="10" />

      <threshold value="WARN" />
      
      <filter type="log4net.Filter.StringMatchFilter">
        <stringToMatch value="DoNotLog" />
        <acceptOnMatch value="false" />
      </filter>
      
      <filter type="log4net.Filter.StringMatchFilter">
        <stringToMatch value="DoLog" />
        <acceptOnMatch value="true" />
      </filter>
      
      <filter type="log4net.Filter.StringMatchFilter">
        <regexToMatch value=".*[0-9]+\.[0-9]+.*" />
        <acceptOnMatch value="true" />
      </filter>
      
      <filter type="log4net.Filter.DenyAllFilter" />
      

      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date{yyyy-MM-dd HH:mm:ss.fff} %-5level %-8property{ProcessName} [%property{pid}/%thread] %c - %m%n" />
      </layout>
    </appender>

OutputDebugStringAppender

Writes to DebugOut (use DebugView, keep in mind that a normal user will only see his/her own process whereas an administrator can see the output of all processes.

Default Layout:
%-5p [%thread] %c - %m%n
The default layout is much simpler, the date is not needed, because DebugView will add it itself.

ColoredConsoleAppender

Write to the standard output and uses a colour filter A mapping will define which colour (foreground and background) will be used for which level.

Mapping

• Level: the log level for this mapping
• foreColor: the colour of the text (Values: Blue, Green, Red, White, Yellow, Purple, Cyan and can be combined with HighIntensity for brightness)
• backColor: the colour of the background (same colours as above)

Example

Example with all levels and lots of colours.

    <appender name="ColoredConsoleAppender" type="log4net.Appender.ColoredConsoleAppender">
      <mapping>
        <level value="FATAL" />
        <foreColor value="Red" />
        <backColor value="White" />
      </mapping>  
      <mapping>
        <level value="ERROR" />
        <foreColor value="Red, HighIntensity" />
      </mapping>
      <mapping>
        <level value="WARN" />
        <foreColor value="Yellow" />
      </mapping>
      <mapping>
        <level value="INFO" />
        <foreColor value="Cyan" />
      </mapping>      
      <mapping>
        <level value="DEBUG" />
        <foreColor value="Green" />
      </mapping> 
      </mapping>
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date{yyyy-MM-dd HH:mm:ss.fff} %-5level [%property{pid}/%thread] %c - %m%n" />
      </layout>
    </appender>

HsLog.HsRollingFileAppender

Similar to the original RollingFileAppender, but allows multiple processes to log into the same file. The write will always happen in the first file which avoids file locking errors during "log rotation" and works very well with the monitoring (tail) feature of Notepad++.

Note:
If any logger is active, the current log file cannot be deleted, but it is possible to clear the content. But not with "notepad.exe", because it tries to delete the file first and then re-create it.

file

the full path of the first file, environment variables are supported (e.g. ${temp}\Log.txt).

maximumFileSize

the maximum size of each file (GB,MB,KB are allowed units)

maxSizeRollBackups

Number of log files to keep

Example

In this example the class 'HsRollingFileAppender' is used. It will write files with 10MB and keep the last 10 of it. As a special threshold only warnings or more severe logs will be written.

<appender name="RollingFileAppender" type="HsLog.HsRollingFileAppender, HsLog">
  <file value="c:\temp\HybridStore.log" />
  <maximumFileSize value="10MB" />
  <maxSizeRollBackups value="10" />
  <layout type="log4net.Layout.PatternLayout">
    <conversionPattern value="%date{yyyy-MM-dd HH:mm:ss.fff} %-5level [%property{pid}/%thread] %c - %m%n" />
  </layout>
  <threshold value="WARN" />
</appender>

SerilogAppender

Forwards all logs to serilog so that all information is written to a single log file. Keep in mind what the log4net level and the serilog level both affect the logging result.

Example:

<appender name="SerilogAppender" type="inPoint.Core.Shared.SerilogAppender" />

Logger

The logger have a root entry for the default settings and then each additional logger can overwrite this in a hierarchy. The hierarchy is created using the name of the logger and instead of backslashes the nodes are separated by dots similar to types and namespaces in .NET (e.g. "inPoint.Fulltext.Searcher", has 3 levels and an additional root level, each level can override and add to the previous levels.)

On each level the log level and the list of appenders can be set.

name

The name of the logger

level

The log level

Values:

• OFF: logging switched off
• FATAL: a very severe error, that will presumably lead the application to abort
• ERROR: an error, but the application can continue running (the attempted operation was probably aborted)
• WARN: a potentially harmful situations, but the system can continue working
• INFO: detailed output
• DEBUG: very detailed output (will negatively impact performance)

additivity

If true the appender defined in the parent will be included.

Example:

The default is to log warnings, errors and fatal error to DebugOut (using OutputDebugStringAppender) and a log file (using RollingFileAppender).
The special logger of inPoint.Fulltext.Searcher will log all kind of messages (DEBUG) to the same appenders (because additivity="true").
All loggers starting with PSW would log to some different appender (because additivity="true"), but it's switched off.

This setting would help finding errors/glitches related to the fulltext search without overburdening the system with unnecessary logs.

<root>
  <level value="WARN" />
  <appender-ref ref="OutputDebugStringAppender" />
  <appender-ref ref="RollingFileAppender" />
</root>

<logger name="inPoint.Fulltext.Searcher" additivity="true">
  <level value="DEBUG" />
</logger>	

<logger name="PSW" additivity="false">
  <level value="OFF" />
  <appender-ref ref="PerformanceOutput" />
  <appender-ref ref="OutputDebugStringAppender" />
</logger>

Performance Logging - PamStopWatch

This is a group of special loggers using the same names as the other loggers, but using "PSW" as prefix. They will log the entry and exit of functions or special code blocks and report the number of milliseconds it took to execute it.

The log levels are redefined like this

• OFF: switched off (this is the default in all configuration files)
• DEBUG: display start and end of timed operation
• INFO: display end only

Turning on this logger can create a huge number of logs!

Example

2017-11-13 21:11:51.289 DEBUG [5380/22] PSW.Pam.DB.DBAccess.PamDBCommand - <start>                   	<id>0000150400000029</id>	<info>ExecuteReader            </info> <a>SQLSERVER</a> <a>pam.HS_FindExistingFiles</a></start>
...
2017-11-13 21:11:51.311 INFO  [5380/22] PSW.Pam.DB.DBAccess.PamDBCommand - <stop> <time>    22</time>	<id>0000150400000029</id>	<info>ExecuteReader            </info> <a>SQLSERVER</a> <a>pam.HS_FindExistingFiles</a></stop>

• The name of the logger is prefixed with PSW
• <time> The stop event contains the duration in milliseconds
• <id> a unique id which is the same for start end stop to find the corresponding message
• <info> the name of the function or code-block which was executed
• <a> multiple entries to add information to the message (in this example it's the database type and the executed statement)

Full Example

All errors are logged into a logfile (max 10 files, 10 MB each) and to DebugOut. HybridStore warnings and informational messages will also be logged. The performance log, which would log only to DebugOut is switched off.

To enable more detailed log, when reproducing a specific error. Set the level from 'root' and 'HybridStore' to DEBUG and remove the threshold in the file logger.

<?xml version="1.0" encoding="utf-8"?>
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
  </configSections>

  <log4net>
    
    <appender name="RollingFileAppender" type="HsLog.HsRollingFileAppender, HsLog">
      <file value="c:\temp\HybridStore.log" />
      <maximumFileSize value="10MB" />
      <maxSizeRollBackups value="10" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date{yyyy-MM-dd HH:mm:ss.fff} %-5level [%property{pid}/%thread] %c - %m%n" />
      </layout>
      <threshold value="WARN" />
    </appender>

    <appender name="PerformanceOutput" type="HsLog.HsRollingFileAppender, HsLog">
      <file value="c:\temp\HybridStore_Performance.log" />
      <maximumFileSize value="100MB" />
      <maxSizeRollBackups value="10" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date{yyyy-MM-dd HH:mm:ss.fff} %-5level [%property{pid}/%thread] %c - %m%n" />
      </layout>
    </appender>
    	
    <appender name="OutputDebugStringAppender" type="log4net.Appender.OutputDebugStringAppender">
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%-5p [%thread] %c - %m%n" />
      </layout>
    </appender>

    <root>
      <level value="ERROR" />
      <appender-ref ref="OutputDebugStringAppender" />
      <appender-ref ref="RollingFileAppender" />
    </root>

    <logger name="HybridStore" additivity="false">
      <level value="INFO" />
      <appender-ref ref="OutputDebugStringAppender" />
      <appender-ref ref="RollingFileAppender" />
    </logger>

    <!-- Logger for performance logging -->
    <!-- additivity="false => don't inherit appender from parent or root -->
    <logger name="PSW" additivity="false">

      <!--Possible values for 'value'
			  DEBUG   => display start and end of timed operation
			  INFO    => display end only
			  OFF     => don't log
		  -->
      <level value="OFF" />
      <!-- <appender-ref ref="PerformanceOutput"/> -->
      <appender-ref ref="OutputDebugStringAppender" />
    </logger>

  </log4net>

</configuration>