Debugging applications through logs

If you have test code and it is not sufficient then improve it immediately.

If you have monitoring and telemetry streams use those or improve them right now.

If you have a legacy application with nothing, but logs then welcome to the special HELL of attempting to debug an issue with only log messages.

In this case this is a legacy codebase application with complicated temporary transition states stored in temporary sql tables.  Yes this is bad and yes it could be better and a proper rewrite of the state transitions would be moved out of the database.  However this is the critical component of the legacy application and without tests this is the riskiest part of the application and primed for failure.

To have any chance of debugging the logs you will need to automate the integration/interaction tests.  In this case it is a web service so automate and set the

  • Clear all logs
  • Hopefully you have a multi target log system as in this case I have NLog.  If not you will need to watch the log file and automate a copy process say every minute to keep the logs concise and small.
  • Run automated test
  • Read logs for receiving system
  • Consolidate logs
  • Repeat and review

Attaching a NLog configuration that works

<?xml version="1.0" encoding="utf-8"?>

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
 xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">

 <!-- 
 See http://nlog-project.org/wiki/Configuration_file 
 for information on customizing logging rules and outputs.
 -->
 <targets>
 <!-- add your targets here -->
 <target xsi:type="File"
 name="fileLog"
 fileName="..\\Logs\\Manager.log"
 layout="${longdate} ${uppercase:${level}} ${message}"
			 archiveFileName="..\\Logs\\ManagerLogArchives\\Manager{#}.log"
			 archiveEvery="Hour"
			 archiveNumbering="Date"
			 archiveDateFormat="yyyyMMdd_hh.mm"
			 maxArchiveFiles="168"
			 keepFileOpen="false"
			/>
 <target xsi:type="File"
 name="triggersLog"
 fileName="..\\Logs\\Manager_Trigger.log"
 layout="${longdate} ${uppercase:${level}} ${message}"
			 archiveFileName="..\\Logs\\ManagerLogArchives\\Manager_Trigger.{#}.log"
			 archiveEvery="Hour"
			 archiveNumbering="Date"
			 archiveDateFormat="yyyyMMdd_hh.mm"
			 maxArchiveFiles="168"
			 keepFileOpen="false"
			/>
 <target xsi:type="File"
 name="usersLog"
 fileName="..\\Logs\\Manager_Users.log"
 layout="${longdate} ${uppercase:${level}} ${message}"
			 archiveFileName="..\\Logs\\ManagerLogArchives\\Manager_Users.{#}.log"
			 archiveEvery="Hour"
			 archiveNumbering="Date"
			 archiveDateFormat="yyyyMMdd_hh.mm"
			 maxArchiveFiles="168"
			 keepFileOpen="false"
			/>
 <target xsi:type="File"
 name="correlateLog"
 fileName="..\\Logs\\Manager_Correlation.log"
 layout="${longdate} ${uppercase:${level}} ${message}"
			 archiveFileName="..\\Logs\\ManagerLogArchives\\Manager_Correlation.{#}.log"
			 archiveEvery="Hour"
			 archiveNumbering="Date"
			 archiveDateFormat="yyyyMMdd_hh.mm"
			 maxArchiveFiles="168"
			 keepFileOpen="false"
			/>
 <target xsi:type="File"
 name="jobsLog"
 fileName="..\\Logs\\Manager_Job.log"
 layout="${longdate} ${uppercase:${level}} ${message}"
			 archiveFileName="..\\Logs\\ManagerLogArchives\\Manager_Job.{#}.log"
			 archiveEvery="Hour"
			 archiveNumbering="Date"
			 archiveDateFormat="yyyyMMdd_hh.mm"
			 maxArchiveFiles="168"
			 keepFileOpen="false"
			/>
 </targets>
 <rules>
 <logger name="*" minlevel="Trace" writeTo="fileLog" />
 <logger name="TheNamespace.Correlation.CorrelationSet" minlevel="Trace" writeTo="correlateLog" />
 <logger name="TheNamespace.Correlation.CgiValues" minlevel="Trace" writeTo="correlateLog" />
 <logger name="TheNamespace.Correlation.CorrelateAlgorithm" minlevel="Trace" writeTo="correlateLog" />
 <logger name="TheNamespace.Correlation.ReportDefinitions" minlevel="Trace" writeTo="correlateLog" />
 <logger name="TheNamespace.Correlation.AccuracyReportCalculator" minlevel="Trace" writeTo="correlateLog" />
 <logger name="TheNamespace.Correlation.ComplianceReportDataSet" minlevel="Trace" writeTo="correlateLog" />
 <logger name="TheNamespace.Correlation.ReportGenerator" minlevel="Trace" writeTo="correlateLog" />
 <logger name="TheNamespace.Correlation.SqlCorrelateAlgorithm" minlevel="Trace" writeTo="correlateLog" />
 <logger name="TheNamespace.Correlation.SqlProxy" minlevel="Trace" writeTo="correlateLog" />
 <logger name="TheNamespace.TriggersService" minlevel="Trace" writeTo="triggersLog" />
 <logger name="TheNamespace.TriggerEventService" minlevel="Trace" writeTo="triggersLog" />
 <logger name="TheNamespace.TriggerDetailContext" minlevel="Trace" writeTo="triggersLog" />
 <logger name="TheNamespace.TriggerDefinitionRepository" minlevel="Error" writeTo="triggersLog" />
 <logger name="TheNamespace.UserRepository" minlevel="Trace" writeTo="usersLog" />
 <logger name="TheNamespace.JobRepository" minlevel="Trace" writeTo="jobsLog" />
 </rules>
</nlog>

This type of debugging is tedious, difficult and error prone and is why structured logs, event streams, and reliable tests would be the preferred mechanism and why other organizations adopt and use them.