A GUID might be prepended to the filename of the log file

Topics: Logging Application Block
Sep 22, 2010 at 2:59 AM

This is in response to this workitem.

todotnetfriend wrote:

"Hi,

Here is my problem definintion.  I am using Microsoft.Practices.EnterpriseLibrary.Logging.dll 4.1 version. It is found that 'A GUID might be prepended to the filename of the log file".'

I did some googling and came to know that this is known issue from the following link http://bloggingabout.net/blogs/erwyn/pages/rolling-file-trace-listener.aspx

So how to resolve this. Is there any cleaner approch that i can use.  Please do reply.

Thanks in advance."

Enterprise Library ships with the Distributor Service which addresses this scenario.  It involves using MSMQ trace listener in your application which will log to a msmq path.  The Distributor Service will then take care of picking up those messages from the queue and distribute it to the log destinations.  Click here for the link to the documentation on how to use it.

 

Sarah Urmeneta
Global Technology and Solutions
Avanade, Inc.
entlib.support@avanade.com
   

Sep 23, 2010 at 1:42 PM

Thanks for the quick response.

Sorry for initiating thread under wrong heading.

Coming back to the point,

well i dont have a seperate server for logging. The log files would be generated on a log folder which is actually deployed as a part of my application.

I have not gone through the details of "Distributor Service" so far but is it feasible to rollover my file after a certain limit as it is possible with RollingFlatFileListner configuration if i go with distributor service implementaton.

Apart from this ,one more concern is that the timestamp printed on log file is not in sequnetial order. Say for e.g.

9/17/2010 12:35:44.

9/17/2010 12:35:44

9/17/2010 12:34:14  ---? This should be greater than above.

So how this happens? Any clue.

Please reply.

Thanks you.

 

 

 

 

 

Sep 23, 2010 at 2:48 PM

The Distributor Service will still make use of RollingFlatFileListener if you have defined it so in your config.  For example, if your app contains a category named "FileLogs" under which it has a MSMQ trace listener which logs to the message queue where the Distributor Service is configured to use, then your distributor service's configuration must have a category named "FileLogs" as well which has a Rolling FlatFile Trace Listener.

On your second question,isn't it possible that the 12:34:14 is actually the first log it created? 

 

Sarah Urmeneta
Global Technology and Solutions
Avanade, Inc.
entlib.support@avanade.com
   

Sep 24, 2010 at 8:11 AM

Well i forgot to mention that the context of the whole discussion is with reference to web application to be deployed on IIS 6.0 / 7.0.

Please correct me if i am wrong, here is the summary of what i understand as a solution for my first problem definition:

I can use msmq trace listener (with the help of Distributor Service)  which will also allow me to use Rolling Flat File trace listner if configured in proper way.

This setting will help me not only to roll my log fine after certain limit but also prevent log file to be generated by guid name.

Again on my second question, if it is first log it created then it should be printed earlier in sequence. The concern is why in sequence it is printed later.

Thanks in advance.

 

Sep 24, 2010 at 8:37 AM

Your understanding is correct.

On the second item, are you sure it was created later or it just appears later in the sequence?  Isn't it possible that your windows explorer is just configured to show the files sorted by timestamp in descencing order?

 

Sarah Urmeneta
Global Technology and Solutions
Avanade, Inc.
entlib.support@avanade.com
   

Sep 24, 2010 at 1:17 PM

Well i don't know whether it created later or not. Basically these timestamps are enteries in log file and not the time

at which log file is created. So i have written log entries in code to be logged in log files. With each entry in log file i have attached a timestamp which is as per documentation

configured in web.config file. Now the problem is raised by the QA that why this entry of log file having timestamp smaller than the previous entry is displayed later in sequence.

Everywhere the timestamp sequence is correct in log file, So what is wrong here.

Hope this helps in understanding problem definition more clearly.

Thanks.

Sep 27, 2010 at 1:15 AM

I'm not sure what is happening there.  Are you using a flat file or a rolling flat file?  Is this intermittent or is it a consistent behavior?  If it's consistent, can you send me a small repro?

 

Sarah Urmeneta
Global Technology and Solutions
Avanade, Inc.
entlib.support@avanade.com
   

Sep 27, 2010 at 6:43 AM

This is not consistent behavior. So far it happens only once.

Yes i am using rolling flat file. Here are the details taken from the log file.

 

9/17/2010 12:35:29.828+0 GMT-INFO-Loader.ExecuteCallback()
9/17/2010 12:35:44.832+0 GMT-FATAL-SqlHelper.ExecuteReader(). Timeout expired.The timeout period elapsed prior to obtaining
a connection from the pool.[This is an exception].
9/17/2010 12:35:44.832+0 GMT-INFO-Loader.ExecuteCallback()
9/17/2010 12:35:44.833+0 GMT-INFO-Manager.Load() started.
9/17/2010 12:34:14.629+0 GMT-INFO-Manager.Load() loaded successfully.
9/17/2010 12:34:14.629+0 GMT-INFO-Loader.ExecuteCallback()
9/17/2010 12:34:14.630+0 GMT-INFO-Manager.Load()

The timestamp 12.34.14 is logged after 12:35:44

So the problem here is of timestamp sequence order. Expected behaviour is to have lower timestamp logged to come above higher timestamp.

Please let me know for any other details.

Thanks

Sep 27, 2010 at 6:45 AM

Forgot to ask if this is an output of tracing or using calls to logWriter.Write.  Please confirm which of the two did you used so I could try if I could repro

 

Sarah Urmeneta
Global Technology and Solutions
Avanade, Inc.
entlib.support@avanade.com
   

Sep 27, 2010 at 6:58 AM

I have used Logger.Write.

Don't know in which scenario it can be re-produced. I have used 4.1 version.

 

 

Sep 27, 2010 at 7:26 AM
Edited Sep 27, 2010 at 7:52 AM

Unfortunately, I can't repro it as well.  The only thing I could think of is someone might've adjusted the time in your computer.  Was this likely to happen in your opinion?

 

Sarah Urmeneta
Global Technology and Solutions
Avanade, Inc.
entlib.support@avanade.com
   

Sep 27, 2010 at 7:49 AM

So what is the reason for this inconsistency in sequence order behavior. And what steps I should take to prevent it from happening again.

 

 

Sep 27, 2010 at 7:53 AM
Edited Sep 27, 2010 at 7:53 AM

Did this happen again occuring intermittently or it just happened once? 

 

Sarah Urmeneta
Global Technology and Solutions
Avanade, Inc.
entlib.support@avanade.com
   

Sep 27, 2010 at 11:18 AM

So far it just happened only once.

One more thing that i would like to clarify regarding my first problem:

Currently in web.config i have specified rollInterval="None" rollSizeKB="5120".

So if I change the rollInterval="Hour" rollSizeKB="5120". Would this prevent the filename to be generated by pre-fix as guid.

Thanks.

 

Sep 28, 2010 at 12:48 AM

What causes the creation of a file prefixed with guid is when 2 or more trace listeners are accessing the same file the same time.  That settings won't guarantee that it won't happen.  It would simply mean that a rollover would be performed every hour or when the file's size is already 5120KB.

On the problem regarding the timestamp, since I can't repro it, I'm afraid I can offer no other reason for that as of now other than someone might've changed the time settings on that machine.

Sarah Urmeneta
Global Technology and Solutions
Avanade, Inc.
entlib.support@avanade.com
   

Sep 29, 2010 at 8:09 AM

Thanks for the reply.

I have gone thru the article regarding "Distributor Service" and i have also implemented the same.

Messages are properly logging in outgoing entlib queue. But the problem is that i am not able to remove those message in file. I have configured

Rolling Flat File Listner in MsmqDistributor.exe.config file. It is creating Log folder but not creating log file in Log folder.

Some Key Points:

1. I am not using here Binary Formatter for Rolling Flat File Listner. I have configured it as formatter="Text Formatter". My assumption here is that it will read the message

from queue in binary format and my apply some build in logic to print it text format.

2. defaultCategory="Error". The same is specified in web.config file.

Please do let me know to make it work.

Here is my configuration setting forlMsmqDistributor.exe.config:

 

<loggingConfiguration name="Logging Application Block" tracingEnabled="true" defaultCategory="Error" logWarningsWhenNoCategoriesMatch="true">

	  <listeners>
	  <add name="Rolling Flat File Trace Listener" fileName="C:\App\Logs\MyApplication.log" formatter="Text Formatter" rollFileExistsBehavior="Increment" rollInterval="None" rollSizeKB="5120" timeStampPattern="yyyy-MM-dd"
		   listenerDataType="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.RollingFlatFileTraceListenerData, Microsoft.Practices.EnterpriseLibrary.Logging" traceOutputOptions="None" filter="All"
		   type="Microsoft.Practices.EnterpriseLibrary.Logging.TraceListeners.RollingFlatFileTraceListener, Microsoft.Practices.EnterpriseLibrary.Logging" />
      </listeners>
		<formatters>
			  <add name="Binary Formatter" type="Microsoft.Practices.EnterpriseLibrary.Logging.Formatters.BinaryLogFormatter, Microsoft.Practices.EnterpriseLibrary.Logging"/>
			  <add template="{timestamp(local:MM/dd/yyyy HH:mm:ss.fffz 'GMT')}-{message}" type="Microsoft.Practices.EnterpriseLibrary.Logging.Formatters.TextFormatter, Microsoft.Practices.EnterpriseLibrary.Logging" name="Text Formatter" />
		</formatters>
		<categorySources>
			<add switchValue="All" name="Error">
				<listeners>
                  <add name="Rolling Flat File Trace Listener" />
				</listeners>
			</add>
			<add switchValue="All" name="Information">
				<listeners>
        			<add name="Rolling Flat File Trace Listener" />
				</listeners>
			</add>
			<add switchValue="All" name="Debug">
				<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>

 

 

Sep 30, 2010 at 5:42 AM

Did you have the categories Error, Information and Debug in your application's configuration file?  If yes, are those categories using the MSMQ Trace listener?

Please also refer to this FAQ item for finding out why messages are sometimes not being logged.

Sarah Urmeneta
Global Technology and Solutions
Avanade, Inc.
entlib.support@avanade.com
   

Sep 30, 2010 at 8:30 AM

yes i have all these information in web.config file.

Here is my web.config settings:

	
<loggingConfiguration name="Logging Application Block" tracingEnabled="true" defaultCategory="Error" logWarningsWhenNoCategoriesMatch="true">
		<listeners>
			<!--RollingTraceListener Added-->
			<add name="Rolling Flat File Trace Listener" fileName="C:\App\Logs\MyApplication.log" formatter="Text Formatter" rollFileExistsBehavior="Increment" rollInterval="None" rollSizeKB="5120" timeStampPattern="yyyy-MM-dd"
			   listenerDataType="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.RollingFlatFileTraceListenerData, Microsoft.Practices.EnterpriseLibrary.Logging" traceOutputOptions="None" filter="All"
			   type="Microsoft.Practices.EnterpriseLibrary.Logging.TraceListeners.RollingFlatFileTraceListener, Microsoft.Practices.EnterpriseLibrary.Logging" />
			
			<!--MsmqTraceListener Added-->
			<add name="Msmq TraceListener" type="Microsoft.Practices.EnterpriseLibrary.Logging.TraceListeners.MsmqTraceListener, Microsoft.Practices.EnterpriseLibrary.Logging"
			      listenerDataType="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.MsmqTraceListenerData, Microsoft.Practices.EnterpriseLibrary.Logging" traceOutputOptions="None"
			      filter="All" queuePath="FormatName:DIRECT=OS:SDFG-ADB0F0DFFB\private$\entlib"
			      formatter="Binary Formatter" messagePriority="Normal" timeToReachQueue="49710.06:28:15"
			      timeToBeReceived="49710.06:28:15" recoverable="false" useAuthentication="false"
			      useDeadLetterQueue="false" useEncryption="false" transactionType="None" />
		</listeners>
		<formatters>
			      <add name="Binary Formatter" type="Microsoft.Practices.EnterpriseLibrary.Logging.Formatters.BinaryLogFormatter, Microsoft.Practices.EnterpriseLibrary.Logging"/>
			      <add template="{timestamp(local:MM/dd/yyyy HH:mm:ss.fffz 'GMT')}-{message}" type="Microsoft.Practices.EnterpriseLibrary.Logging.Formatters.TextFormatter, Microsoft.Practices.EnterpriseLibrary.Logging" name="Text Formatter" />
		</formatters>
		<logFilters>
			<add categoryFilterMode="DenyAllExceptAllowed" type="Microsoft.Practices.EnterpriseLibrary.Logging.Filters.CategoryFilter, Microsoft.Practices.EnterpriseLibrary.Logging" name="Category Filter">
				<categoryFilters>
					<add name="Error" />
					<add name="Information" />
					<add name="Debug" />
				</categoryFilters>
			</add>
		</logFilters>
		<categorySources>
			<add switchValue="All" name="Error">
				<listeners>
					<add name="Msmq TraceListener" />
         			</listeners>
			</add>
			<add switchValue="All" name="Information">
				<listeners>
					 <add name="Msmq TraceListener" />
				</listeners>
			</add>
			<add switchValue="All" name="Debug">
				<listeners>
					<add name="Msmq TraceListener" />
				</listeners>
			</add>
		</categorySources>
		<specialSources>
			<allEvents switchValue="All" name="All Events">
				<listeners>
					<add name="Msmq TraceListener" />
				</listeners>
			</allEvents>
			<notProcessed switchValue="All" name="Unprocessed Category">
				<listeners>
					<add name="Msmq TraceListener" />
				</listeners>
			</notProcessed>
			<errors switchValue="All" name="Logging Errors &amp; Warnings">
				<listeners>
				         <add name="Msmq TraceListener" />
				</listeners>
			</errors>
		</specialSources>
	</loggingConfiguration>


		
			<!--RollingTraceListener Added-->
			
			
			<!--MsmqTraceListener Added-->
			
		
		
			      
			      
		
		
			
				
					
					
					
				
			
		
		
			
				
					
         			
			
			
				
					 
				
			
			
				
					
				
			
		
		
			
				
					
				
			
			
				
					
				
			
			
				
				         
				
			
		
	

 

Sep 30, 2010 at 8:49 AM

Have you read through the link to the FAQ item?  Specifically, if none of the suggestion why logging doesn't works applies to your case, add an Event Log Trace Listener under the Logging Errors and Warnings section.  That configuration will cause logging failures to be logged to the Event Viewer.  Check it for logs indicating why logging failed.

Try also a different kind of trace listener under any one of the categories of your msmqdistributorservice.exe.config.

 

Sarah Urmeneta
Global Technology and Solutions
Avanade, Inc.
entlib.support@avanade.com
   

Oct 26, 2011 at 3:21 PM
Edited Oct 26, 2011 at 6:11 PM

Hi Guys,
Sorry for double posting. I actually posted this on a separate thread.

I am experiencing the same problem where in a GUID is prepended to the file name. and I would like to get some of your inputs about this. Can you please let me know how I can get around of this issue?

This is what my code looks like:

private void LogMessage()
{

 

     var configSource = SetConfigFile(logTypeCd);

            var logFactory = new LogWriterFactory(configSource);

            var logWriter = logFactory.CreateDefault();

            logWriter.Write(errorMessage);

            logWriter.Dispose();


}

        private static DictionaryConfigurationSource SetConfigFile(LogTypeCd logTypeCd)

        {

 

            var builder = new ConfigurationSourceBuilder();

 

            _sdateTimeStr = DateTime.Now.ToString("yyyyMMdd"); //Keep this

            _sErrLogFileNm = _sDateTimeStr + "LogFile.Txt”;

            builder.ConfigureLogging()

                .LogToCategoryNamed("CommonLogger")

                .SendTo.FlatFile("CommonLogListener")

                .FormatWith(new FormatterBuilder()

                                .TextFormatterNamed("Text Formatter")

                                .UsingTemplate(

                                    logTypeCd +

                                    "##{localProcessId}-{win32ThreadId}##{localMachine}##{localProcessName}##{timestamp}##{message}##"))

                .ToFile(_sErrLogFileNm);

 

            var configSource = new DictionaryConfigurationSource();

            builder.UpdateConfigurationWithReplace(configSource);

 

            return configSource;

 

        }

Oct 27, 2011 at 6:35 AM

Hyperthread,

The reason you are getting a GUID prepended to the filename is that the output file is locked when a write is attempted.  
Because the configuration information is created for each LogMessage it is possible to have 2 LogWriters attempting to write to the same file (each attempts to lock the file).

It looks like you are calling SetConfigFile for every LogMessage.  Is this done to create a rolling file type of behavior with the filename changing every day?  If so, I would
recommend looking at the RollingFlatFileTraceListener with a RollInterval of Midnight.  The only difference looks like you want the current file to have the date in the name and not
just files that have "rolled". 

If RollingFlatFileTraceListener doesn't suit you, you could modify the source to create your own trace listener that does exactly what you want.

It's difficult to tell exactly what your code is doing (since not all of the code is posted) but perhaps this could help you:

public static class MyLogger
{
    private static DateTime lastLogDate;
    private static LogWriter logWriter;

    private static object locker = new object();

    static MyLogger()
    {
        logWriter = SetConfigFile();
    }

    public static void LogMessage(string errorMessage)
    {
        lock (locker)
        {
            if (lastLogDate != DateTime.Now.Date)
            {
                logWriter.Dispose();
                logWriter = SetConfigFile();
            }
        }

        logWriter.Write(errorMessage, "CommonLogger");
    }

    private static LogWriter SetConfigFile()
    {
        lastLogDate = DateTime.Now.Date;
        string _sdateTimeStr = lastLogDate.ToString("yyyyMMdd"); //Keep this
        string _sErrLogFileNm = _sdateTimeStr + "LogFile.Txt";

        var builder = new ConfigurationSourceBuilder();

        builder.ConfigureLogging()
            .LogToCategoryNamed("CommonLogger")
            .SendTo.FlatFile("CommonLogListener")
            .FormatWith(new FormatterBuilder()
                            .TextFormatterNamed("Text Formatter")
                            .UsingTemplate(
                                "##{localProcessId}-{win32ThreadId}##{localMachine}##{localProcessName}##{timestamp}##{message}##"))
            .ToFile(_sErrLogFileNm);

        var configSource = new DictionaryConfigurationSource();
        builder.UpdateConfigurationWithReplace(configSource);

        var logFactory = new LogWriterFactory(configSource);
        return logFactory.CreateDefault();
    }
}

I wouldn't say it's the usual approach but fits with what you are already doing.

--
Randy Levy
Enterprise Library support engineer
entlib.support@live.com