Threadsafe WebService log - will NLog do it?

[blondebier]

Hi Guys,

I have a vb.net WebService that has recently started getting very busy. This is good, but I now realise that the activity/error logging class that we have is not suitable as it is not thread safe.

This is an example extract from my Activity Log.

06/11/2007 14:38:55 LIVE: Start CheckAddress WebMethod ****************************************************************
06/11/2007 14:38:55 LIVE: XML Recieved to CheckAddress
06/11/2007 14:38:55 LIVE: <?xml version="1.0" encoding="utf-8"?><CheckAddress><ClientID>username</ClientID><ClientPWD>secret</ClientPWD><Address><HouseNumber>1</HouseNumber><Street>Toy Street</Street><District /><Town>Toy Town</Town><County>My County</County><Postcode>PC1 1CD</Postcode><AtAddressFrom>01/01/2003</AtAddressFrom><AtAddressTo>01/01/2006</AtAddressTo><AddressType>U</AddressType></Address></CheckAddress>
06/11/2007 14:38:56 LIVE: UserID: 1
06/11/2007 14:38:57 LIVE: Validating the address...
06/11/2007 14:38:57 LIVE: Validation complete. Final XML response...
06/11/2007 14:38:57 LIVE: <?xml version="1.0" encoding="UTF-8"?><Result>AddressOK</Result>
06/11/2007 14:38:57 LIVE: End CheckAddress WebMethod ****************************************************************

This is fine when requests come in one at a time, but if 2 or more requests are received by the web service at the same time or very close together, the Activity log entries get mixed up and I can't see what is going on.

I have a module in my project as follows:

Module _Module

    Public Sub dBug(ByVal Narrative As String)
        Dim log As New ErrorLog
        Dim debug As Boolean
        Dim environment As String = ""

        Try
            debug = CType(ConfigurationManager.AppSettings("Debug"), Boolean)
            environment = ConfigurationManager.AppSettings("Environment")

            ' Only write to the error log if debugging is enabled
            If debug Then
                If Narrative = "" Then
                    log.WriteError("X")
                Else
                    log.WriteError("Log " & Now & " " & environment & ": " & Narrative)
                End If
            End If

        Catch sii As System.IO.IOException
            Try
                log.WriteError("Log " & Now & " " & environment & ": " & Narrative)
            Catch ex As Exception
                ' Do Nothing
            End Try
        Catch ex As Exception
            ' Do Nothing
        End Try

    End Sub

End Module

I can then reference the dbug() function wherever I need to in my WebService for writing debug statements.

My ErrorLog class is as follows:

Public Class ErrorLog

    Public Sub WriteError(ByVal ErrorMessage As String, Optional ByVal FilePath As String = "C:\")
        Dim LogPath, environment As String

        LogPath = ConfigurationManager.AppSettings("DebugLogLocation")
        environment = ConfigurationManager.AppSettings("Environment")

        If LogPath = "" Then LogPath = FilePath

        LogPath = LogPath & environment & " Log - " & Format(Date.Today, "d MMM yyyy") & ".log"

        If File.Exists(LogPath) = True OrElse CheckFilePath(LogPath) Then
            Dim sr As StreamWriter = File.AppendText(LogPath)
            sr.WriteLine(ErrorMessage)
            sr.Close()
        End If
    End Sub

    Private Function CheckFilePath(ByVal FilePath As String) As Boolean
        Dim strChar As String
        Try
            If FilePath > "" Then
                strChar = ""
                If Not Directory.GetParent(FilePath).Exists Then
                    Do While Directory.GetParent(FilePath).Exists = False
                        strChar = Directory.GetParent(FilePath).ToString
                        Do While Not Directory.GetParent(strChar).Exists And strChar > ""
                            strChar = Directory.GetParent(strChar).ToString
                        Loop
                        Directory.CreateDirectory(strChar)
                    Loop
                End If
            End If
            CheckFilePath = True
        Catch Ex As Exception
            CheckFilePath = False
        End Try
    End Function

End Class

Will NLog work in a scenario like this?

I guess that instantiating a new instance of ErrorLog every time dBug is called is probably something that definitely needs to change...

Any pearls of wisdom or working examples would be most appreciated.

Cheers,

Francis

[Jaroslaw_Kowalski]

Yes. NLog is designed to be thread-safe and has been used in very big installations under heavy load. If you want your logging to be as quick as possible, you may want to use asynchronous logging, which will perform file writes in a separate thread:

<nlog>
   <targets async="true">
       ... put your targets here ...
   </targets>
</nlog>

[blondebier]

Thanks for the reply. That's great news!

I have created a simple WebService to test this that goes something like this:

Imports NLog
Imports System.Web.Services
Imports System.Web.Services.Protocols
Imports System.ComponentModel

<System.Web.Services.WebService(Namespace:="http://tempuri.org/")> _
<System.Web.Services.WebServiceBinding(ConformsTo:=WsiProfiles.BasicProfile1_1)> _
<ToolboxItem(False)> _
Public Class test
    Inherits System.Web.Services.WebService

    Private Shared logger As Logger = LogManager.GetCurrentClassLogger()

     <WebMethod()> _
    Public Function TestXML(ByVal request As String) As String
        Try
            logger.Debug("XML Received : " & request)
            Dim testMe As New XMLSchemaValidator
            logger.Debug("Testing XML 1.")
            Return testMe.ValidateXML(request)

        Catch ex As Exception
            logger.DebugException("Oh dear! ", ex)
        Finally
            logger.Debug("Testing XML 2")
        End Try
    End Function

End Class

What can I do so that I can reference the same instance of NLog in my other classes e.g. XMLSchemaValidator

Testing this as it is appears to just create one instance of logger and reuse it over and over again...

I think for this to work I would need it to create a new instance of "Logger" every time the WebMethod is called...?

[blondebier]

Still stumped.

I guess I could just declare an instance of the Logger at the top of my WebMethod and pass the instanciated variable byRef to all classes and methods as required and then destroy it at the end of my WebMethod...?

Seems a bit much like hard work though. Declaring it like a "Global Protected for this instance" type variable would be much easier.

Does that sound plausible ?

[Jaroslaw_Kowalski]

The preferred method of declaring loggers is "static" - single instance shared across all instances of a type.  NLog is internally thread-safe, so it's perfectly fine to share loggers.

In C# the recommended pattern is:

private static Logger logger = LogManager.GetCurrentClassLogger();

[blondebier]

Thanks for the reply.

Can you keep all the message entries in a particular instance of the logger and then write them to the target(e.g. file) in one hit? So that the entries do not get mixed up...

[Jaroslaw_Kowalski]

I recommend three approaches to this problem:

1. Include ${threadid} in the output file so that you can identify log entries coming from the same thread.

2. Use multiple logging files that don't clash (for example one per thread). All you have to do is:

<target type="File" fileName="path\top\logfile.${threadid}.log" />

Each thread will get its own log file.

3. There is also one more thing that you may want to try for WebServices - ASP.NET buffering wrapper, which will gather all logs during the execution of each web page and flush them in one shot. There's no guarantee of interlocking (that would kill the performance) so multiple requests can be interleaved, but at least they will kept closer together.

Use it like this:

<target name="wrappedFile" type="ASPNetBufferingWrapper">
     <target type="File" fileName="yourActualFile" />
</target>

<rules>
     <logger name="*" writeTo="wrappedFile" />
</rules>

See this page for more information:
http://www.nlog-project.org/target.ASPNetBufferingWrapper.html