Tracing for UWP-Apps

There are several tools available for tracing in UWP Apps:

I wanted to use ETW via Diagnostics.FileLoggingSession but it proved to be unstable and there was no way to convert the etl files to human readable form to allow app users to examine the content before sending them as email attachments.

My main requirements for tracing tools are:

  • Tool errors must never crash the app.
  • Minimal impact on app performance.
  • Ability to specify maximum file storage usage.
  • Inject trace location (method name, line number).
  • Unobtrusive trace calls that do not obscure the app code.

I make a distinction between tracing the program flow and variable values for developer usage and logging unexpected exceptions and important status messages for system management.

None of the tools available fulfilled all these requirement to my liking. Thus I wrote a little class Trace with the following features:

  • Stores traces in alternating text files in ApplicationData.
  • Short static trace methods.
  • Trace levels Verbose, Debug, Info, Time, Status, Warning, Error, Fatal, Off
    The level “Status” is intended to filter messages for logging errors and important status messages like started and stopped. This level is missing in many tracing frameworks and leads to either flooding logs intended for system management with info messages or not logging important status messages.
  • Inject trace location via compiler generated parameter values like CallerMemberName and CallerLineNumber. These point to the correct source code location even in release. mode (when the app was compiled with the .NET Native toolchain.
  • Buffer traces in a TPL BatchBlock to improve performance when writing to storage.
  • CyclicBuffer to allow to trace the last n messages on error.
    Experimental feature only. Have not used it in production yet. Don’t know if it still works.

Download complete code.

Sample Trace Output

160628 18:57:47.837 Trace.Init@75|========== Travel Currencies V1.1.42.0
160628 18:57:47.837 Trace.Init@76|traceOutputLevel=Debug: traceTragets=Debug, BufferedFile traceSource=BackgroundTask
160628 18:57:47.837 Trace.Init@77|==========
160628 18:57:47.837 RefreshRatesTask.Run@24|->
160628 18:57:48.484 RefreshRatesTask.Run@39|Refreshing rates. RatesSource=Web
160628 18:57:48.488 License.GetLicenseInfo@37|
160628 18:57:48.495 License.GetLicenseInfo@42|LicenseInformation: isTrial=True TrialExpiration=12/31/9999 1:00:00 AM +01:00 isActive=True 
160628 18:57:48.498 Globals.CheckLicensingInformUser@35|
160628 18:57:48.503 PublisherCacheFile..ctor@13| folder.Path=C:\Users\pit\AppData\Local\Publishers\bmpfaqh7gxjd4\Currencies
160628 18:57:48.503 CurrentRatesSource.GetRatesFromFileAsync@40|
160628 18:57:48.511 PublisherCacheFile.ReadObjectAsync@38|->
160628 18:57:48.682 PublisherCacheFile.ReadObjectAsync@52|<- 160628 18:57:48.687 _RatesSourceBase.LoadRatesFromFileAsync@34|Found cached rates. RatesAsOfDate=6/28/2016 4:00:21 PM +00:00 160628 18:57:48.688 CurrentRatesSource.GetRatesFromWebAsync@51| 160628 18:57:48.688 PublisherCacheFile..ctor@13| folder.Path=C:\Users\pit\AppData\Local\Publishers\bmpfaqh7gxjd4\Currencies 160628 18:57:48.691 WebRatesSource.RefreshRatesFromWebAsync@10|->
160628 18:57:49.396 WebRatesSource.RefreshRatesFromWebAsync@27|RatesAsOfDate Utc=6/28/2016 4:00:21 PM +00:00 RatesAsOfDate Local=6/28/2016 6:00:21 PM +02:00
160628 18:57:49.396 WebRatesSource.RefreshRatesFromWebAsync@33|<-
160628 18:57:49.396 RatesRefresher.RefreshRatesToFile@64|Got new rates as of UTC 6/28/2016 4:00:21 PM +00:00

...

Usage

Trace.Init(TraceTarget.Debug Or TraceTarget.BufferedFile, TraceLevel.Debug)

Sub Test
    Trace("")
  '... 
    Trace.Debug($"Recovered from exception: {unhandledEx.Message}")
  '...
    Trace.Time(NameOf(ratesRefreshAndSaveStopwach), ratesRefreshAndSaveStopwach)
End Sub

Implementation

Private Shared Sub InitDataFlowBlocks()
    _batchMessagesBlock = New BatchBlock(Of String)(_batchSize,
        New GroupingDataflowBlockOptions With {.BoundedCapacity = _boundedCapacity,
        .CancellationToken = _ct})
      
    _fileWriterActionBlock = New ActionBlock(Of String())(
        Async Function(messages) As Task
            Await WriteToFile(messages)
        End Function, New ExecutionDataflowBlockOptions With {.CancellationToken = _ct})
        
    _batchMessagesBlock.LinkTo(_fileWriterActionBlock,
        New DataflowLinkOptions With {.PropagateCompletion = True})
End Sub

Public Shared Sub Debug(message As String,
                        <CallerMemberName> Optional CallerMemberName As String = "",
                        <CallerFilePath> Optional CallerFilePath As String = "",
                        <CallerLineNumber> Optional CallerLineNumber As Integer = 0)
    Buffer(TraceLevel.Debug, CallerMemberName, CallerFilePath, CallerLineNumber, message)
End Sub

Private Shared Sub Buffer(traceLevel As TraceLevel, CallerMemberName As String, CallerFilePath As String, CallerLineNumber As Integer,
                        format As String, ParamArray args() As Object)
  ...
    _batchMessagesBlock.SendAsync($"{GetTraceTimeStamp()} {msg}").Wait()
  ...
End Sub

Private Shared Async Function WriteToFile(messages() As String) As Task
  ...
    Await FileIO.AppendLinesAsync(_traceFile, messages, Streams.UnicodeEncoding.Utf8)
  ...
End Function    

Since Windows 10 Anniversary Update one can view files like trace files in the users \AppData via the App File Explorer of the Device Portal:

UWPErrors Abb6 App File Explorer

View trace files on device using Device Portal

About Peter Meinl

IT Consultant
This entry was posted in Computers and Internet and tagged , , . Bookmark the permalink.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s