log file has guids for filename

Topics: Logging Application Block
Jun 18, 2014 at 9:41 AM
Hello,

Please help me understand why I am getting fileguids as the log file names. Please let me know if more information is required.

Below is the application web config
  <configSections>
    <section name="loggingConfiguration" type="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.LoggingSettings, Microsoft.Practices.EnterpriseLibrary.Logging, Version=6.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35" requirePermission="true" />
    <section name="validation" type="Microsoft.Practices.EnterpriseLibrary.Validation.Configuration.ValidationSettings, Microsoft.Practices.EnterpriseLibrary.Validation, Version=6.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35" />
    <section name="dataConfiguration" type="Microsoft.Practices.EnterpriseLibrary.Data.Configuration.DatabaseSettings, Microsoft.Practices.EnterpriseLibrary.Data, Version=6.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35" />
  </configSections>
  <loggingConfiguration name="" tracingEnabled="true" defaultCategory="General">
    <listeners>
      <add name="Event Log Listener" type="Microsoft.Practices.EnterpriseLibrary.Logging.TraceListeners.FormattedEventLogTraceListener, Microsoft.Practices.EnterpriseLibrary.Logging, Version=6.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35"
        listenerDataType="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.FormattedEventLogTraceListenerData, Microsoft.Practices.EnterpriseLibrary.Logging, Version=6.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35"
        source="Enterprise Library Logging" formatter="Text Formatter"
        log="" machineName="." traceOutputOptions="None" />
      <add name="Rolling Flat File Trace Listener" type="Microsoft.Practices.EnterpriseLibrary.Logging.TraceListeners.RollingFlatFileTraceListener, Microsoft.Practices.EnterpriseLibrary.Logging, Version=6.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35"
        listenerDataType="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.RollingFlatFileTraceListenerData, Microsoft.Practices.EnterpriseLibrary.Logging, Version=6.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35"
        fileName="C:\Logfiles\AllicationLog.log" formatter="Text Formatter"
        rollInterval="Week" />
    </listeners>
    <formatters>
      <add type="Microsoft.Practices.EnterpriseLibrary.Logging.Formatters.TextFormatter, Microsoft.Practices.EnterpriseLibrary.Logging, Version=6.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35"
        template="Timestamp: {timestamp}{newline}&#xA;Message: {message}{newline}&#xA;Category: {category}{newline}&#xA;Priority: {priority}{newline}&#xA;EventId: {eventid}{newline}&#xA;Severity: {severity}{newline}&#xA;Title:{title}{newline}&#xA;Machine: {localMachine}{newline}&#xA;App Domain: {localAppDomain}{newline}&#xA;ProcessId: {localProcessId}{newline}&#xA;Process Name: {localProcessName}{newline}&#xA;Thread Name: {threadName}{newline}&#xA;Win32 ThreadId:{win32ThreadId}{newline}&#xA;Extended Properties: {dictionary({key} - {value}{newline})}"
        name="Text Formatter" />
    </formatters>
    <categorySources>
      <add switchValue="All" name="General">
        <listeners>
          <add name="Rolling Flat File Trace Listener" />
        </listeners>
      </add>
    </categorySources>
    <specialSources>
      <allEvents switchValue="All" name="All Events">
        <listeners>
          <add name="Rolling Flat File Trace Listener" />
        </listeners>
      </allEvents>
      <notProcessed switchValue="All" name="Unprocessed Category">
        <listeners>
          <add name="Rolling Flat File Trace Listener" />
        </listeners>
      </notProcessed>
      <errors switchValue="All" name="Logging Errors &amp; Warnings">
        <listeners>
          <add name="Rolling Flat File Trace Listener" />
        </listeners>
      </errors>
    </specialSources>
  </loggingConfiguration>
I instantiate the logger in the Application start of global.asax as below:
        IConfigurationSource configurationSource = ConfigurationSourceFactory.Create();
        LogWriterFactory logWriterFactory = new LogWriterFactory(configurationSource);
        Logger.SetLogWriter(logWriterFactory.Create(), false);
And logging is done as:
            Logger.Write(ex);
Jun 20, 2014 at 5:14 AM
The code and configuration looks OK. Are you using the same configuration file for multiple web sites or running the web site as a web garden? Files are locked so only one AppDomain can write to the same file.

~~
Randy Levy
entlib.support@live.com
Enterprise Library support engineer
Support How-to
Jun 20, 2014 at 12:59 PM
Edited Jun 20, 2014 at 1:44 PM
Hi Randy,

Thank you for your reponse. I am using 1 logging file per application. No other website/application is writing to the same log file. We are not using web gardens.

I should also add that I do not see the guid titled log files in any other environment other than production. And the only difference between the production environment and the test/dev environments is the user load accessing the application.

Thanks,
Rochelle
Jun 22, 2014 at 6:15 AM
Does this happen in production all the time or just sometimes?

I would suspect a mis-configuration in production (unless there is something else going on that wasn't posted like reconfiguration or disposing the logger at some point) but it's not entirely clear what is happening. If possible you might try monitoring the file (e.g. Process Monitor to see what accesses are occurring.

Load shouldn't matter because a trace listener will lock the lock file. The GUID behavior will only happen when another trace listener tries to open the locked file (and fails). The only time I would suspect that load is an issue is if there is some programmatic reconfiguration or creation of the logging block/trace listeners.

~~
Randy Levy
entlib.support@live.com
Enterprise Library support engineer
Support How-to
Jun 26, 2014 at 10:40 AM
Hi Randy,

Thank you for your response and apologies for the delay in response from my end.

The config and code is exactly as posted above and no reconfiguration or disposing is done in the code. Which is why it is quite puzzling to figure out the reason for the guids.

However I shall try the process monitor you suggested and revert with the findings.

Thanks,
Rochelle
Jun 26, 2014 at 1:29 PM
Hi Randy,

I see this issue occurring all the time in production ever since I upgraded to Enterprise Lib 6.

I ran the process monitor tool and below are my observations.
  1. The operation "CreateFile" runs at different time on the log file which results in "SHARING VIOLATION". This causes the guid titled logs to be created. The detail I see on the tool is "Desired Access: Generic Write, Read Attributes, Disposition: OpenIf, Options: Sequential Access, Synchronous IO Non-Alert, Non-Directory File, Open No Recall, Attributes: n/a, ShareMode: Read, AllocationSize: 0"
  2. The operations "WriteFile", "CloseFile" runs only for the guid titled files
  3. The same w3wp process is accessing the log path
Does this info help you in anyway? If you need the csv extract of the processes from the Process Monitor, please let me know how do I send it across.

Thanks,
Rochelle
Jun 30, 2014 at 2:02 PM
It would be helpful to know what process is locking the file first and what process is attempting to acquire a lock after the file is locked. Also, do you see a sharing violation on every request or at some other interval?

Usually, a self contained sample can help but if the issue only occurs in production then what is the difference between the development server and production server (mainly in terms of software and configuration)?

~~
Randy Levy
entlib.support@live.com
Enterprise Library support engineer
Support How-to
Jul 2, 2014 at 9:24 AM
Hi Randy,

Using the tool you recommended, Only a w3wp process was accessing the log file. Any suggestion on how can I find out more details on the process?

The sharing violation happens randomly. The time interval varies between 1 - 6 minutes. And there is no trend that I could see.

I can confirm that the software is the same between development and production. I spoke to our network resources and they confirmed that other software like operating system, IIS is the same too. There is just one difference and that is external users access the application via Big IP in production. But that is not the case in the development environment.

I tried googling to see if there were any Enterprise logging issues due to Big IP. But I did not find anything.

Do you have any more suggestions?

Thanks and Regards,
Rochelle
Jul 15, 2014 at 7:18 AM
I am getting same issue with 6.0; The way to reproduce is , go to IISManager->app pool -> Recycle; You will get file with guid pre-pended


--Sanjay
Jul 15, 2014 at 10:32 PM
@sanjay10, thanks for providing steps to reproduce. It sounds like you are running IIS using Overlapped Recycling (this is the default) and are experiencing multi-instancing causing file locking issues.

You have a few options that I can think of:

Use the DisallowOverlappingRotation property to disable overlapped recycling. There are

Alternatively you could go with a programmatic approach for naming log files accounting for multi-instancing and/or log file locking. e.g. if at application bootstrapping the anticipated log file is locked then fall back to a better named log file. If you are using rolling Flat File you could align with the incrementing sequence number.

There's some other hoops you could jump through but the first two options seem like the first to look at.

~~
Randy Levy
entlib.support@live.com
Enterprise Library support engineer
Support How-to
Jan 20, 2015 at 8:49 PM
Hi,

I have a web site that processes incoming XML messages (hundreds/second). It records about 8 log messages for each message received. I needed to use the rolling flat file listener because of the high volume of tracing (we always get disputes about the quality of the XML messages from those from whom we receive them and need some short-term record of what we received). The rolling flat file mechanism would be perfect, except for all the files with GUIDs in their names. They would be generated so quickly, there would be so many of them, and they would not be involved in any "rolling file rotation", they would fill up the hard drive in no time.

As I looked harder at the log messages that made it into the "TraceFile.LOG" series and those that didn't, I noticed that what started the unwanted behavior was a trace that hadn't been categorized. So, I went back and gave every trace message a category and - no more file names with GUIDs in them!

May sound strange, but try giving every message a category - don't assume a default.

Thanks,
Rob