none
<Complaint> Add hard complaint

    Question

  • We instrumented the DiagnosticMonitor to use LogLevels as the "best practices document" recommends, but the level "information" is unusable due to all the noise created by the Azure Cache.

    Can someone explain what are these entries, how to tame the noise down other than changing the LogLevel (because the application also uses TraceInformation) and finally, are these traces an indicator about problems or faulty design?

    INFORMATION:   <Complaint> Add hard complaint :0 ; TraceSource 'WaIISHost.exe' event

    INFORMATION: <CASClient> Updated partition table to (0-121) generation: 634910124707726250:1000000000000000000000000 with transfer (0-121) generation: 634910124707726250:1000000000000000000000000; TraceSource 'WaIISHost.exe' event

    Friday, December 28, 2012 7:52 PM

Answers

  • Hi,

    Do you see the log in the "wad-custom-logs" blog container? If so it's server log, not client log. I just read the source code using Reflector where the caching logs stored in "wad-custom-logs" are configured (you can set a breakpoint in your code and check DiagnosticsConfigurationReader.DefaultInstance.CacheLogsConfiguration in the watch window of Visual Studio to get the value of cacheLogConfig. This object contains information you set in the config file, such as the value you configured in Microsoft.WindowsAzure.Plugins.Caching.DiagnosticLevel):

    private static void ConfigureCacheLogsCollection(DiagnosticMonitorConfiguration monitorConfiguration, CacheLogsConfigurationElement cacheLogConfig)
    {
        if ((cacheLogConfig == null) || (cacheLogConfig.LogLevel == TraceLevel.Off))
        {
            AzureStartupLogger.WriteLog("CacheDiagnostics", TraceEventType.Warning, "Traces are not enabled in configuration");
        }
        string logUploadDirectory = AzureUtility.GetLogUploadDirectory();
        DirectoryConfiguration item = new DirectoryConfiguration();
        item.set_Container("wad-custom-logs");
        item.set_DirectoryQuotaInMB(cacheLogConfig.LogStorageQuotaInMB);
        item.set_Path(logUploadDirectory);
        monitorConfiguration.get_Directories().get_DataSources().Add(item);
        monitorConfiguration.get_Directories().set_ScheduledTransferPeriod(TimeSpan.FromMinutes((double) cacheLogConfig.ScheduledTransferPeriodInMinutes));
    }

    As you can see the implementation is to use the monitorConfiguration object (per the MSDN document it should be the return value of DiagnosticMonitor.GetDefaultInitialConfiguration()) to handle diagnostic data. In addition, the Loglevel is not used at all except for checking whether trace is turned off. Because the implementation is tightly coupled with the DiagnosticMonitor I'm not sure there is a way to split the caching log in the wad-custom-logs container from other logs in your application. Probably you can write a small app to manually filter out these logs but it may not be the best approach. I would suggest you contact our product team to see how to handle this. Looks like a bug to me as the implementation is not align with the documentation but they may give you a confirmation.


    Allen Chen
    MSDN Community Support | Feedback to us
    Develop and promote your apps in Windows Store
    Please remember to mark the replies as answers if they help and unmark them if they provide no help.


    Thursday, January 10, 2013 6:49 AM
    Moderator

All replies

  • Hi,

    It seems happening when upgrading the caching. Try to remove <tracing sinkType="DiagnosticSink" traceLevel="Error" /> in the config file to see if it works:

    http://social.msdn.microsoft.com/Forums/en-US/windowsazuredata/thread/c878ec14-771d-4bdc-9bfd-4d4e5e025029

    Thanks,


    QinDian Tang
    MSDN Community Support | Feedback to us
    Develop and promote your apps in Windows Store
    Please remember to mark the replies as answers if they help and unmark them if they provide no help.

    Monday, December 31, 2012 7:23 AM
    Moderator
  • Hi Qin Dian Tang,

    removing DiagnosticSink does nothing to the noise. In fact I removed the entry since the 1.8 upgrade and the link you sent me also states that it has no effect.

    If the log messages are a result of poor caching design in my application, then it is important to understand what is the cause and how to fix it. Could you send me some pointers about the hard complaint trace?

    If these messages are only to debug the cache client, I have not use for them and would like to remove them from my traces, but I can't find a way to do so.

    The Diagnostic for Cache 1.8 seams to be broken:

    1. Removing the entry DiagnosticSink does nothing.
    2. The entry "Microsoft.WindowsAzure.Plugins.Caching.ClientDiagnosticLevel" value="1" does nothing... I tried from zero to 5
    3. Finally "Microsoft.WindowsAzure.Plugins.Caching.DiagnosticLevel" value="1" also is useless.

    Any ideas?

    Regards,

    Uri

    Wednesday, January 02, 2013 1:33 AM
  • Hi,

    You may have a look at custom diagnostics by the creation of a custom file-based data buffer configured:

    http://convective.wordpress.com/2009/12/08/custom-diagnostics-in-windows-azure/

    Or use custom Azure Nlog:

    http://blog.elastacloud.com/2011/02/18/custom-azure-nlog-integration-with-azure-diagnostics-sdk-1-3-using-nuget/

    Thanks,


    QinDian Tang
    MSDN Community Support | Feedback to us
    Develop and promote your apps in Windows Store
    Please remember to mark the replies as answers if they help and unmark them if they provide no help.

    Wednesday, January 02, 2013 3:36 AM
    Moderator
  • Hi QinDian Tang,

    I have 2 questions in my post:

    WHY and HOW to stop generation of noise.

    I am using cache to avoid reading from the database, but instead I am getting "Writes" to Table Storage. That can’t scale (diagnostics).

    Q1) I need to understand if cache requires more IO resources than SQL query.

    Therefore I am asking what the meaning for the traces is. If the design has a flaw and the traces are pointing to the problem, then it is useful information, but I don't understand what the traces are telling me about "Hard Complaint" or "Updated partition"

    The other problem is how to stop the noise

    Q2) There are different ways as you point out to filter the noise, but please explain how to use the property (note all levels produce the same results): Microsoft.WindowsAzure.Plugins.Caching. ClientDiagnosticLevel

    Thursday, January 03, 2013 5:01 PM
  • Hi,

    These two traces are raised by internal class ServiceResolverBase, which can be ignored normally. I think they are for our dev team to troubleshoot as there is no public documents for it. It's tightly bound to intermal implementation so I don't think it's very accountable and useful for you to do anything based on the information you get from these trace logs.

    If you have interest, INFORMATION:   <Complaint> Add hard complaint :0 ; TraceSource 'WaIISHost.exe' event
     is logged in this method:

    public IAsyncResult BeginRefresh(string serviceNamespace, int key, ServiceReplicaSet replicaSet, TimeSpan timeout, AsyncCallback callback, object state)

    and INFORMATION: <CASClient> Updated partition table to (0-121) generation:  is logged in below method:

    internal void UpdateLookupTable(LookupTableTransfer transfer)

    >I need to understand if cache requires more IO resources than SQL query.

    If you want to test performance agains Cache vs. SQL query, why not test the execution time with a simple test app? It would be easier and more reliable than using trace.

    >Finally "Microsoft.WindowsAzure.Plugins.Caching.DiagnosticLevel" value="1" also is useless.

    From this document http://msdn.microsoft.com/en-us/library/windowsazure/hh914135.aspx

    it should work to filter out information level cache server traces. What happens if you use '0'? Did you add/change this setting after deployment? If so try to set it before the deployment to see whether it works.


    Allen Chen
    MSDN Community Support | Feedback to us
    Develop and promote your apps in Windows Store
    Please remember to mark the replies as answers if they help and unmark them if they provide no help.





    Friday, January 04, 2013 6:27 AM
    Moderator
  • Thanks for your answers, for completion here are my observations:

    Microsoft.WindowsAzure.Plugins.Caching.DiagnosticLevel  value="1" should only be logging errors (not information), but changing it to "0" doesn't stop the noise.

    I suspect the problem is with the diagnostics methods and lack of consistency... there are 3 ways to do the same, but the LogLevel filters works different.

    1. Trace.WriteLine(string message) In this case the LogLevel is ignored
    2. Trace.WriteLine (string message, string category); For example enter INFORMATION in the category. But the LogLevel is Ignored
    3. Trace.TraceInformation (string message) ONLY in this case the LogLevel works.

    If you look at the message we are getting from the cache client:

    INFORMATION:   <Complaint> Add hard complaint :0 ; TraceSource 'WaIISHost.exe' event

    It is clear that Cache Client is using the Trace.WriteLine(string message, string category) and I have done enough experiments to ensure that the LogLevel doesn't filter.

    The solution is for your team: Either to implement LogLevel filtering to Trace.WriteLine, or to replace by the Trace.TraceInformation method in all the cache client methods.

    Friday, January 04, 2013 3:09 PM
  • Hi,

    The diagnostic code does use Trace.TraceInformation. For instance, if you look into UpdateLookupTable method of ServiceResolverBase using tools like reflector, where the information log you want to filter out:

    internal void UpdateLookupTable(LookupTableTransfer transfer)
    {
      ..   

    EventLogWriter.WriteInfo("CASClient", "Updated partition table to {0} with transfer {1}", new object[] { this.m_partitionTable.ToShortString(), transfer.ToShortString() });
    }

    public static void WriteInfo(string src, string format, params object[] args)
    {
        foreach (SinkWrapper wrapper in s_sinks)
        {
            wrapper.WriteEntry(2, src, TraceEventType.Information, format, args);
        }
    }

    public void WriteEntry(int msgLevel, string src, TraceEventType msgType, string msgText, params object[] args)
    {
       ..       

    this.m_sink.WriteEntry(src, msgType, str2);
       ..
    }

     DiagnosticsTraceSink class:

    public void WriteEntry(string src, TraceEventType msgType, string msgText)
    {
       ..            this._traceProvider.WriteEntry(src, msgType, msgText);
      ..            DiagnosticsTraceUtility.WriteEntry(src, msgType, msgText);
         ..
        }
    }

    internal static void WriteEntry(string src, TraceEventType msgType, string msgText)
    {
      ..

            switch (type)
            {
                     case TraceEventType.Information:
                    goto Label_008D;

            ..

    Label_008D:
        Trace.TraceInformation(GetMessageString(TraceEventType.Information, src, msgText));
    }

    So if everything is configured well but Microsoft.WindowsAzure.Plugins.Caching.DiagnosticLevel does not help to filter out the trace logs it sounds like a bug (My wild guess is something stops the this configuration from being applied). You can report it to our product team via this link:

    https://github.com/WindowsAzure/azure-sdk-for-net/issues

    to get a confirmation.


    Allen Chen
    MSDN Community Support | Feedback to us
    Develop and promote your apps in Windows Store
    Please remember to mark the replies as answers if they help and unmark them if they provide no help.



    Monday, January 07, 2013 1:58 AM
    Moderator
  • Hey Allen Chen,

    I posted the bug as you suggested. but here is another tought:

    Could it be that the diagnostics settings I am ussing for my application traces override the cache client log level?

    In other words: is it possible for me to pay more attention to my instrumentation and less to the framework?

    Here is the code I use to enable diagnostics:

            private static void EnableDiagnostics(int transferTime)
            {
    
                // For information on handling configuration changes
                // see the MSDN topic at http://go.microsoft.com/fwlink/?LinkId=166357.
                //http://www.microsoftpdc.com/2009/SVC15
    
                var diag = DiagnosticMonitor.GetDefaultInitialConfiguration();
    
                diag.Logs.ScheduledTransferLogLevelFilter = LogLevel.Information;
                diag.Logs.ScheduledTransferPeriod = TimeSpan.FromMinutes(transferTime);
    
                DiagnosticMonitor.Start("Microsoft.WindowsAzure.Plugins.Diagnostics.ConnectionString", diag);
    
            }

    Wednesday, January 09, 2013 4:02 PM
  • Hi,

    Do you see the log in the "wad-custom-logs" blog container? If so it's server log, not client log. I just read the source code using Reflector where the caching logs stored in "wad-custom-logs" are configured (you can set a breakpoint in your code and check DiagnosticsConfigurationReader.DefaultInstance.CacheLogsConfiguration in the watch window of Visual Studio to get the value of cacheLogConfig. This object contains information you set in the config file, such as the value you configured in Microsoft.WindowsAzure.Plugins.Caching.DiagnosticLevel):

    private static void ConfigureCacheLogsCollection(DiagnosticMonitorConfiguration monitorConfiguration, CacheLogsConfigurationElement cacheLogConfig)
    {
        if ((cacheLogConfig == null) || (cacheLogConfig.LogLevel == TraceLevel.Off))
        {
            AzureStartupLogger.WriteLog("CacheDiagnostics", TraceEventType.Warning, "Traces are not enabled in configuration");
        }
        string logUploadDirectory = AzureUtility.GetLogUploadDirectory();
        DirectoryConfiguration item = new DirectoryConfiguration();
        item.set_Container("wad-custom-logs");
        item.set_DirectoryQuotaInMB(cacheLogConfig.LogStorageQuotaInMB);
        item.set_Path(logUploadDirectory);
        monitorConfiguration.get_Directories().get_DataSources().Add(item);
        monitorConfiguration.get_Directories().set_ScheduledTransferPeriod(TimeSpan.FromMinutes((double) cacheLogConfig.ScheduledTransferPeriodInMinutes));
    }

    As you can see the implementation is to use the monitorConfiguration object (per the MSDN document it should be the return value of DiagnosticMonitor.GetDefaultInitialConfiguration()) to handle diagnostic data. In addition, the Loglevel is not used at all except for checking whether trace is turned off. Because the implementation is tightly coupled with the DiagnosticMonitor I'm not sure there is a way to split the caching log in the wad-custom-logs container from other logs in your application. Probably you can write a small app to manually filter out these logs but it may not be the best approach. I would suggest you contact our product team to see how to handle this. Looks like a bug to me as the implementation is not align with the documentation but they may give you a confirmation.


    Allen Chen
    MSDN Community Support | Feedback to us
    Develop and promote your apps in Windows Store
    Please remember to mark the replies as answers if they help and unmark them if they provide no help.


    Thursday, January 10, 2013 6:49 AM
    Moderator
  • Hi

    I also get this Information tracing from the Cache Cluster on vlient side. Is their a way to switch this off?

    I still want to trace my application Information logs.

    Thanks,

    Andreas

    Sunday, March 17, 2013 11:26 AM
  • Could you please post here the link to the bug report? I would like to upvote for it as I have the same problem.. Thanks!

    eXavier

    Friday, May 10, 2013 9:00 AM
  • It's issue #156 in the azure-sdk-for-net repository. Unfortunately Technet isn't letting me post a link so you'll have to try to search for the issue with this information.

    It seems like they won't fix it unless others state that the issue affects them, so I have attempted to do so by commenting on the issue and suggest that others do the same!

    Friday, May 31, 2013 4:23 AM
  • Just to add, this hasn't been fixed with SDK 2.0.  This is really infuriating.  My application diagnostic logging is rendered useless because of all this.  I literally get hundreds of these useless messages in the WADLogsTable every minute.  This needs to be made high priority...
    Wednesday, July 10, 2013 1:15 PM
  • Happens also on 2.1.

    did someone managed to fix it?

    Saturday, September 28, 2013 8:54 AM
  • I confirm that it's still impossible to control the level of logging with v2.1 of the library.

    How come can such a bug not being treated in high priority?

    Monday, October 28, 2013 3:06 AM
  • Yes our logs are completely out of control too. We have had over 100,000 entries of noise in the last hour alone.

    It has rendered our logging completely useless, not to mention the cost & performance impact of logging this much data.

    Microsoft please do something about this.

    Anthony.

    Wednesday, November 13, 2013 9:07 AM
  • The solution I found so far is to 1) make my log level >= "Warning" and 2) only write logs >= "warning".
    Sunday, January 19, 2014 6:19 AM