Logging

From Sense/Net Wiki
Jump to: navigation, search
  •  
  •  
  •  
  •  
  • 100%
  • 6.0
  • Enterprise
  • Community
  • Planned

Overview

Logging
Sense/Net uses the Microsoft Enterprise Library logging features to format and log information in response to portal or application events. Events can be logged to different locations - primarily into file system and database tables as well - simply by configuring logging properties in the application configuration file. Every log entry is marked with categories to allow easy filtering of logs. Developers are provided with a handy application interface enabling easy access of logging features.

In cases when the default logging infrastructure is not enough, you may use the Detailed logger feature to keep track of what is happening in the system.

Details

Severity levels

Portal events are categorized according to the following outline of available log severity levels:

  • Critical: indicates high severity critical errors
  • Error: indicates errors that mark abnormal function execution
  • Warning: shows warning messages that do not affect general flow of execution but might lead to errors
  • Information: marks general information messages
  • Verbose: low severity general messages following execution of functions

Default settings

The default settings of the logging system are based on the following rules:

  • Audit log is logged into database
  • AdSync is logged into file
  • Critical, Error, Warning and Information events are logged into event log
  • Verbose and categories above are logged onto debug trace

Categories

Log messages are categorized not only by their severity levels but also by the source of events. Different subsystems use different categories to make filtering of logs easier and to allow the logging system to be configured to log events of different subsystems to different target locations. The AD sync tools for example use the category AdSync - AD events are logged to a separate target location as the rest of system events since the source of events are distinguished by their categories. Developers may include custom categories when logging events.

Event identifiers

Sense/Net logging framework lets you tag logged messages (errors, warnings, etc.) with specific event ids. Administrators may use those ids to filter the log flow (e.g. in the Event Viewer). We have a list of all built-in Event identifiers where you can look for the ids of messages sent by the core system. 3rd party developers can define custom event ids (as these are simple numbers) to create customized event log messages.

Configuration

The configuration for log can be found in the application configuration files (the Web.config for the portal). The files contain a section called loggingConfiguration that contains all the settings. Below is an excerpt of the configuration:

  <loggingConfiguration name="Logging Application Block" tracingEnabled="false"
    defaultCategory="General" logWarningsWhenNoCategoriesMatch="true">
    <listeners>
      <add fileName="adsync.log" footer="" formatter="AdSync Text Formatter"
        header="" rollFileExistsBehavior="Increment" rollInterval="None"
        rollSizeKB="200" timeStampPattern="yyyy-MM-dd" listenerDataType="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.RollingFlatFileTraceListenerData, Microsoft.Practices.EnterpriseLibrary.Logging, Version=4.1.0.0, Culture=neutral, PublicKeyToken=null"
        traceOutputOptions="None" filter="All" type="Microsoft.Practices.EnterpriseLibrary.Logging.TraceListeners.RollingFlatFileTraceListener, Microsoft.Practices.EnterpriseLibrary.Logging, Version=4.1.0.0, Culture=neutral, PublicKeyToken=null"
        name="AdSync Flat File Trace Listener" />
      <add source="Enterprise Library Logging" formatter="" log="Application"
        machineName="" listenerDataType="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.FormattedEventLogTraceListenerData, Microsoft.Practices.EnterpriseLibrary.Logging, Version=4.1.0.0, Culture=neutral, PublicKeyToken=null"
        traceOutputOptions="None" filter="All" type="Microsoft.Practices.EnterpriseLibrary.Logging.TraceListeners.FormattedEventLogTraceListener, Microsoft.Practices.EnterpriseLibrary.Logging, Version=4.1.0.0, Culture=neutral, PublicKeyToken=null"
        name="Application EventLog TraceListener" />
      <add databaseInstanceName="SnCrMsSql" writeLogStoredProcName="proc_LogWrite"
        addCategoryStoredProcName="proc_LogAddCategory" formatter="XmlFormatter"
        listenerDataType="Microsoft.Practices.EnterpriseLibrary.Logging.Database.Configuration.FormattedDatabaseTraceListenerData, Microsoft.Practices.EnterpriseLibrary.Logging.Database, Version=4.1.0.0, Culture=neutral, PublicKeyToken=null"
        traceOutputOptions="None" filter="All" type="Microsoft.Practices.EnterpriseLibrary.Logging.Database.FormattedDatabaseTraceListener, Microsoft.Practices.EnterpriseLibrary.Logging.Database, Version=4.1.0.0, Culture=neutral, PublicKeyToken=null"
        name="Database Trace Listener" />
      <add listenerDataType="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.CustomTraceListenerData, Microsoft.Practices.EnterpriseLibrary.Logging, Version=4.1.0.0, Culture=neutral, PublicKeyToken=null"
        traceOutputOptions="None" filter="All" type="SenseNet.Diagnostics.OneLineTraceListener, SenseNet.Storage, Version=5.9.1.2, Culture=neutral, PublicKeyToken=null"
        name="Debug Trace Listener" initializeData="" formatter="OneLineFormatter" />
      <add source="SenseNetInstrumentation" formatter="Text Formatter"
        log="SenseNet" machineName="" listenerDataType="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.FormattedEventLogTraceListenerData, Microsoft.Practices.EnterpriseLibrary.Logging, Version=4.1.0.0, Culture=neutral, PublicKeyToken=null"
        traceOutputOptions="None" filter="Information" type="Microsoft.Practices.EnterpriseLibrary.Logging.TraceListeners.FormattedEventLogTraceListener, Microsoft.Practices.EnterpriseLibrary.Logging, Version=4.1.0.0, Culture=neutral, PublicKeyToken=null"
        name="SenseNet EventLog TraceListener" />
    </listeners>
    <formatters>
      <add template="{timestamp} {severity} {message} {keyvalue(Messages)}"
        type="Microsoft.Practices.EnterpriseLibrary.Logging.Formatters.TextFormatter, Microsoft.Practices.EnterpriseLibrary.Logging, Version=4.1.0.0, Culture=neutral, PublicKeyToken=null"
        name="AdSync Text Formatter" />
      <add template="{severity} {category} {message}: Properties: {dictionary({key}={value};)}; Timestamp: {timestamp}; Machine: {machine}; AppDomain: {appDomain}; ProcessId: {processId}; Process: {processName}; Win32ThreadId: {win32ThreadId}; ThreadName: {threadName}"
        type="Microsoft.Practices.EnterpriseLibrary.Logging.Formatters.TextFormatter, Microsoft.Practices.EnterpriseLibrary.Logging, Version=4.1.0.0, Culture=neutral, PublicKeyToken=null"
        name="OneLineFormatter" />
      <add template="Timestamp: {timestamp}&#xD;&#xA;Message: {message}&#xD;&#xA;Category: {category}&#xD;&#xA;Priority: {priority}&#xD;&#xA;EventId: {eventid}&#xD;&#xA;Severity: {severity}&#xD;&#xA;Title:{title}&#xD;&#xA;Machine: {machine}&#xD;&#xA;Application Domain: {appDomain}&#xD;&#xA;Process Id: {processId}&#xD;&#xA;Process Name: {processName}&#xD;&#xA;Win32 Thread Id: {win32ThreadId}&#xD;&#xA;Thread Name: {threadName}&#xD;&#xA;Extended Properties: {dictionary({key} - {value}&#xD;&#xA;)}"
        type="Microsoft.Practices.EnterpriseLibrary.Logging.Formatters.TextFormatter, Microsoft.Practices.EnterpriseLibrary.Logging, Version=4.1.0.0, Culture=neutral, PublicKeyToken=null"
        name="Text Formatter" />
      <add template="&lt;LogEntry&gt;&#xD;&#xA;  &lt;Timestamp&gt;{timestamp}&lt;/Timestamp&gt;&#xD;&#xA;  &lt;Message&gt;{message}&lt;/Message&gt;&#xD;&#xA;  &lt;Category&gt;{category}&lt;/Category&gt;&#xD;&#xA;  &lt;Priority&gt;{priority}&lt;/Priority&gt;&#xD;&#xA;  &lt;EventId&gt;{eventid}&lt;/EventId&gt;&#xD;&#xA;  &lt;Severity&gt;{severity}&lt;/Severity&gt;&#xD;&#xA;  &lt;Title&gt;{title}&lt;/Title&gt;&#xD;&#xA;  &lt;Machine&gt;{machine}&lt;/Machine&gt;&#xD;&#xA;  &lt;ApplicationDomain&gt;{appDomain}&lt;/ApplicationDomain&gt;&#xD;&#xA;  &lt;ProcessId&gt;{processId}&lt;/ProcessId&gt;&#xD;&#xA;  &lt;ProcessName&gt;{processName}&lt;/ProcessName&gt;&#xD;&#xA;  &lt;Win32ThreadId&gt;{win32ThreadId}&lt;/Win32ThreadId&gt;&#xD;&#xA;  &lt;ThreadName&gt;{threadName}&lt;/ThreadName&gt;&#xD;&#xA;  &lt;ExtendedProperties&gt;{dictionary(&lt;{key}&gt;{value}&lt;/{key}&gt;&#xD;&#xA;)}&lt;/ExtendedProperties&gt;&#xD;&#xA;&lt;/LogEntry&gt;"
        type="Microsoft.Practices.EnterpriseLibrary.Logging.Formatters.TextFormatter, Microsoft.Practices.EnterpriseLibrary.Logging, Version=4.1.0.0, Culture=neutral, PublicKeyToken=null"
        name="XmlFormatter" />
    </formatters>
    <categorySources>
      <add switchValue="All" name="AdSync">
        <listeners>
          <add name="AdSync Flat File Trace Listener" />
        </listeners>
      </add>
      <add switchValue="All" name="Audit">
        <listeners>
          <add name="Database Trace Listener" />
          <add name="Debug Trace Listener" />
        </listeners>
      </add>
      <add switchValue="All" name="General">
        <listeners>
          <add name="Debug Trace Listener" />
        </listeners>
      </add>
    </categorySources>
    <specialSources>
      <allEvents switchValue="All" name="All Events">
        <listeners>
          <add name="SenseNet EventLog TraceListener" />
        </listeners>
      </allEvents>
      <notProcessed switchValue="All" name="Unprocessed Category" />
      <errors switchValue="All" name="Logging Errors &amp; Warnings">
        <listeners>
          <add name="SenseNet EventLog TraceListener" />
        </listeners>
      </errors>
    </specialSources>
  </loggingConfiguration>

As you can see in the above outline a whole line of log config entries has to be defined in order to log a type of event information:

  • event sources are defined in Special Sorces or Category Sources
  • sources are handled by Trace Listeners that mark the target location of logs
  • Trace Listeners are provided with Formatters that format the output of logged event information

The default log settings of the portal is built up according to the following:

  • AdSync category is logged using AdSync Flat File Trace Listener (with AdSync Text Formatter) to log events associated with Active Directory synchronization
  • Audit category is logged using Debug Trace Listener (with OneLineFormatter) and Database Trace Listener (with XmlFormatter) to log audit events
  • General category is logged using Custom Trace Listener (with OneLineFormatter)
  • All Events and Logging Errors & Warnings category is logged using SenseNet EventLog TraceListener (with Text Formatter)

The trace listeners are configured according to the following:

  • AdSync Flat File Trace Listener logs into a rolling file adync.log
    • the rolling file is configured to log in 200kB files and then rolls over to another logfile.
    • it can also be configured to roll after a given interval by setting the RollInterval to Day and RollSizeKB to 0.

Set RollInterval to Midnight to log into different files every day.

  • Database Trace Listener logs into database using default connection settings (MySenseNetContentRepositoryDatasource) and proc_LogAddCategory, proc_LogWrite stored procedures
  • Debug Trace Listener logs onto debug trace
  • SenseNet EventLog TraceListener logs into eventlog, log's name is SenseNet

Configuration using EntLibConfig.exe

The easiest way to configure logging is to use the EntLibConfig.exe tool that comes with Microsoft Enterprise Library. After executing the program a configuration file has to be opened for editing. Below you can see the Web.config opened in EntLibConfig.exe:

Web.config edited with EntLibConfig.exe

This is a handy tool to define custom event sources, create custom trace listeners and custom formatters to leverage more detailed logs. See examples below for detailed information on using EntLibConfig.exe.

EventLog

Before events can be logged into the event log, a log has to be created in the event log. This can be done using the EventLogCreator.exe that comes with the SenseNet package. Type '-h' or '-help' to see usage:

Sense/Net Content Repository Tools - EventLog creator
This tool creates a log and attached sources in the eventlog.
-------------------------------------------------------------
 
use: EventLogCreator [-machine MachineName] [-logname LogName] [-sources CommaSeparatedSources] [-delete]
 
-machine : On which machine you want to create the log. Default: "."
-logname : The name of the log (eg. Application, Security...). Default: "SenseNet"
-sources : The name of the sources will be registered for the log. Default: "Common,SenseNet.ContentRepository,SenseNet.Storage,SenseNet.Portal,SenseNet.CorePortlets,SenseNet.Services,SenseNet.ContentExplorer"
-delete  : Deletes the log and the registrated sources rather than create it.

The most important parameter here is logname. By default this is SenseNet, which means that simply running EventLogCreator.exe without parameters will create a log on the current machine with the name SenseNet that will appear under Applications and Services logs.

Note, that although the name can be more than 8 characters long, only the first 8 characters are taken into account, so if SenseNet log is already created, you will not be able to create SenseNet2, as their first 8 characters coincide, and an error messege will be shown when creating the log.

The user running the EventLogCreator.exe must have sufficient privileges to create a log in the event log.

The newly created log will not appear immediately in the Event Viewer (eventvwr), the program has to be closed and opened again to see the new log!

The portal itself can also create the log when started, but the user running the application pool usually does not have the sufficient privileges for it. It is highly recommended though that the configured log is created with the EventLogCreator.exe

After created, logging needs to be configured so that events are logged to the appropriate event log. By default the system is configured to use the SenseNet log, but this can be set to any name of your choice with the Log property of the SenseNet EventLog TraceListener. Also, change the value of the Source property accordingly. For example if the name of the created log is MyLog, the following settings will be appropriate:

  • Log: MyLog
  • Source: MyLogInstrumentation

You can use the -delete parameter to delete a log from the event log. If you don't provide any further parameters, SenseNet will be deleted, with all log entries - use it with -logname parameter to delete a custom log.

Audit log

The logging system includes an audit log (Audit category) with the following predefined event types:

  • LoginTry
  • LoginSuccessful
  • LoginUnsuccessful
  • Logout
  • ContentCreated
  • ContentUpdated
  • ContentDeleted
  • VersionChanged
  • PermissionChanged
  • LockTakenOver

The above events generate lines in the database (LogEntries table) - one line per event - including extended property info in an xml blob. This blob for content updates not only contains the modified fields of content, but the previous state and the new state is also included, see the excerpt below:

<LogEntry>
  <Timestamp>2010.11.10. 8:32:46</Timestamp>
  <Message>ContentUpdated</Message>
  <Category>Audit</Category>
  ...
  <ExtendedProperties>
    <Id>3</Id>
    <Path>/Root/IMS</Path>
    <ChangedData>
      <NodeModificationDate>
        <OldValue>2010-11-10 09:31:30.0530</OldValue>
        <NewValue>2010-11-10 09:32:46.4149+01:00</NewValue>
      </NodeModificationDate>
      <ModificationDate>
        <OldValue>2007-07-08 00:00:00.0000</OldValue>
        <NewValue>2010-11-10 09:32:46.4149+01:00</NewValue>
      </ModificationDate>
      <Title>
        <OldValue></OldValue>
        <NewValue>Users and Groups</NewValue>
      </Title>
      <Hidden>
        <OldValue></OldValue>
        <NewValue></NewValue>
      </Hidden>
    </ChangedData>
    <UserName>BuiltIn\Administrator</UserName>
  </ExtendedProperties>
</LogEntry>

User name in auditing authentication

Authentication related events are: LoginSuccessful, LoginUnsuccessful and Logout. Be careful when checking the username related to the LoginSuccessful and LoginUnsuccessful events: when this events are fired, the current user is always the Visitor but the relevant information is which user is logging in and which user is trying to login. In these cases the UserName of the event will be the related user's name and the name of the actually logged in user will be written into the LoggedUserName property of the extended properties section.

Note that the UserName property is written to an individual column of the LogEntries datatable and extended properties are written into a blob so it is easy to write an SQL query that uses a filter for the UserName.

Journal and Audit log

Sense/Net includes journal functionality to log event types that are also logged with audit log. Journal is a built-in module that logs content-operation-specific events into a non-configurable database table (JournalItems). The main difference between the two techniques (journal and audit log) is that the journal cannot be switched off, whereas you are able to configure logging to disable the logging of audit events.

for Developers

Developers can use static functions of SenseNet.Diagnostics.Logger class to log events of different severity levels such as:

   Logger.WriteCritical(int eventId, object message);
   Logger.WriteError(int eventId, object message);
   Logger.WriteWarning(int eventId, object message);
   Logger.WriteInformation(int eventId, object message);
   Logger.WriteVerbose(object message);

Categories can be defined using overloads of the above functions, for example:

   Logger.WriteCritical(int eventId, object message, IEnumerable<string> categories);

Exceptions can be logged using the following:

   Logger.WriteException(Exception ex);
   Logger.WriteException(Exception ex, IEnumerable<string> categories);

For audit log the following functions are available:

   Logger.WriteAudit(AuditEvent auditEvent, IDictionary<string, object> properties);

Example/Tutorials

Changing target location of logging

This example shows you how to change the target location of a source - Audit - from database to filesystem file. Open the Web.config with the EntLibConfig.exe and follow these steps:

  • First lets create a new formatter to our new log file. Add a Text Formatter to the Formatters section:
Adding new formatter

Rename the newly created formatter to MyFormatter and edit the template to only show some basic event information:

Customizong formatter

Now any trace listener that uses MyFormatter will log incoming events with the text template you have specified: Timestamp in first row, Message in second, etc.

  • Create a new trace listener that logs events into a file using our formatter. Add a Flat File Trace Listener to the Trace Listeners section:
Adding new trace listener

Rename it to My FlatFile TraceListener, set the Formatter to MyFormatter and rename the Filename from the default trace.log to mylog.log. Leave the Filter property set to All so we capture events of all severity levels.

Customizing trace listener
  • Set our new trace listener to log Audit events. Add a new Trace Listener Reference to the Audit category:
Adding new reference to trace listener

Select My FlatFile TraceListener in the ReferencedTraceListener field:

Setting trace listener reference
  • Remove old Database Trace Listener reference from the Audit category
Setting trace listener reference

We are done. Let's save the configuration and test the new settings! Log in to the portal and create a new folder under the Default site. After saving mylog.log should appear in the web folder with the following content (this is an excerpt only):

----------------------------------------
Timestamp: 11/12/2010 10:08:30 AM
Message: ContentCreated
Category: Audit
Priority: -1
Severity: Information
Title:ContentCreated
Extended Properties: Id - 4292
NodeTypeId - 1
NodeType - Folder
ContentListId - 0
ContentListTypeId - 0
ParentId - 2974
Name - newfolder
...
----------------------------------------

The event has been logged using our new Flat file listener and custom Text formatter as configured.

Creating and using custom log category and location

The following example shows you how to add a log location for a custom event category and how to write an application that logs its events using the custom category.

  • First, open the Web.config in EntLibConfig.exe and create a new category called MyCategory
Creating a new event category

Rename the newly created category and leave SourceLevels property set to All, as we are going to listen to all types of events.

Category properties
  • Add a Trace Listener Reference to our category to define a target location for logging. We will use the trace listener created in the previous example, but you can easily create your own by following the steps of the previous example.
Category properties

We are finished with the configuration, now let's see how our custom application can use this new category!

  • In your application source code create a static member to hold category information:
   public static readonly string[] MyLogCategory = new[] {"MyCategory"};
  • Use the SenseNet.Diganostics.Logger class to log events and provide the category information when logging:
   Logger.WriteInformation("process has started...", MyLogCategory);
   try
   {
      // do something...
   } 
   catch (Exception ex) 
   {
      Logger.WriteException(ex, MyLogCategory);
   }

Now mylog.log defined in My FlatFile TraceListener will include event messages from your application.

Related links

References