At one of my clients I was debugging an application which used the Microsoft Enterprise Library logging block and I added some code to log the service configuration on start up.

The odd thing was that when I turned on verbose logging I noticed the first couple of log entries were missing sometimes. After some mucking around I found that the log entries were only missing for a new deployment and everything was fine for a restart.

The missing log entries weren’t immediately obvious as I was testing an application which was clustered and there were multiple instances were logging information simultaneously.

public override bool OnStart()
{
Trace.Listeners.Add(new DiagnosticMonitorTraceListener());
Trace.AutoFlush = true;

CloudStorageAccount storageAccount = CloudStorageAccount.Parse(RoleEnvironment.GetConfigurationSettingValue("Microsoft.WindowsAzure.Plugins.Diagnostics.ConnectionString"));
RoleInstanceDiagnosticManager roleInstanceDiagnosticManager = storageAccount.CreateRoleInstanceDiagnosticManager(RoleEnvironment.DeploymentId, RoleEnvironment.CurrentRoleInstance.Role.Name, RoleEnvironment.CurrentRoleInstance.Id);

var configuration = roleInstanceDiagnosticManager.GetCurrentConfiguration();
if (configuration == null)
{
configuration = DiagnosticMonitor.GetDefaultInitialConfiguration();
}

configuration.Logs.BufferQuotaInMB = 4;
configuration.Logs.ScheduledTransferPeriod = TimeSpan.FromMinutes(1);
configuration.Logs.ScheduledTransferLogLevelFilter = LogLevel.Undefined;
roleInstanceDiagnosticManager.SetCurrentConfiguration(configuration);
EnterpriseLibraryContainer.Current = EnterpriseLibraryContainer.CreateDefaultContainer(new FileConfigurationSource("web.config", false));
Logger.Write("OnStart " + DateTime.UtcNow.ToLongTimeString());

return base.OnStart();
}

public override void Run()
{
int index = 0;

Logger.Write(“Run Start ” + DateTime.UtcNow.ToLongTimeString());

while (true)
{
Logger.Write(“Run Loop ” + index.ToString() + ” ” + DateTime.UtcNow.ToLongTimeString());
index++;
Thread.Sleep(10000);
}
}

The trace log for a new deployment looked like this (I have found it starts somewhere between loop 2 thru 6 )

Run Loop 6 8:04:09 AM
Run Loop 7 8:04:19 AM
Run Loop 8 8:04:29 AM
….

For a restart like this

OnStart 8:19:01 AM
Run Start 8:19:01 AM
Run Loop 0 8:19:01 AM
Run Loop 1 8:19:11 AM
Run Loop 2 8:19:21 AM

I’m assuming that it this is a result of the time it takes for DiagnosticsAgent.exe to spin up.

If I use the Windows Event log the results are similar but with duplicate entries every so often which is odd.