Logging impact with Policy Injection issue

Topics: Logging Application Block, Policy Injection Application Block
Mar 12, 2009 at 9:55 AM
Edited Mar 12, 2009 at 1:59 PM

Hi,

We have used the remoting as the distributed mechanism.

Web Server(1 Server, IIS 6, Windows 2003)  --> Windows Network Load Balance --> Application Server(2 Servers,IIS 6.0, Windows 2003, IIS host, Use remoting between the web server and application server)

In our application server,

We have some function using the Logging and Policy Injection.

In Logging config:

<?xml version="1.0" encoding="utf-8" ?>
<!-- Logging configurations -->
<loggingConfiguration name="Logging Application Block" tracingEnabled="true"
  defaultCategory="General" logWarningsWhenNoCategoriesMatch="true">
 <listeners>
    <add fileName="bin/Logs/audit.log"
         rollSizeKB="0"
         timeStampPattern="yyyy-MM-dd"
         rollFileExistsBehavior="Increment"
         rollInterval="Week"
         formatter="Audit Text Formatter"
         header="----------------------------------------"
         footer="----------------------------------------"
         listenerDataType="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.RollingFlatFileTraceListenerData, Microsoft.Practices.EnterpriseLibrary.Logging"
         traceOutputOptions="None"
         type="Microsoft.Practices.EnterpriseLibrary.Logging.TraceListeners.RollingFlatFileTraceListener, Microsoft.Practices.EnterpriseLibrary.Logging"
         name="Rolling Flat File Audit Trace Listener" />
 </listeners>
 <formatters>
    <add template="Timestamp: {timestamp(local:)}
Type:     {property(TypeName)}
Method:   {property(MethodName)}
Parameters: {dictionary({key} : {value}; )}
Return Value: {property(ReturnValue)}
Exception: {property(Exception)}
Call Time: {property(CallTime)}
Machine:  {machine}"
      type="Microsoft.Practices.EnterpriseLibrary.Logging.Formatters.TextFormatter, Microsoft.Practices.EnterpriseLibrary.Logging"
      name="Audit Text Formatter" />
    <add switchValue="All" name="Audit">
      <listeners>
        <add name="Rolling Flat File Audit Trace Listener" />
      </listeners>
    </add>
 </categorySources>
 <specialSources>
  <allEvents switchValue="All" name="All Events" />
  <notProcessed switchValue="All" name="Unprocessed Category" />
  <errors switchValue="All" name="Logging Errors &amp; Warnings" />
 </specialSources>
</loggingConfiguration>


In our policy Injection config like this:

<?xml version="1.0" encoding="utf-8" ?>
<!--policyInjection configurations-->
<policyInjection>
  <policies>
    <add name="Class Level Policy">
      <matchingRules>
        <add type="Microsoft.Practices.EnterpriseLibrary.PolicyInjection.MatchingRules.NamespaceMatchingRule, Microsoft.Practices.EnterpriseLibrary.PolicyInjection"
          name="Namespace Matching Rule">
          <matches>
            <add match="XXXX.YYYY.LIS.BusinessFacade" ignoreCase="false" />
         </matches>
        </add>
      </matchingRules>
      <handlers>
        <add logBehavior="After" beforeMessage="Before" afterMessage="After"
            eventId="0" includeParameterValues="true" includeCallStack="false"
            includeCallTime="true" priority="-1" severity="Information"
            type="Microsoft.Practices.EnterpriseLibrary.PolicyInjection.CallHandlers.LogCallHandler, Microsoft.Practices.EnterpriseLibrary.PolicyInjection.CallHandlers"
            name="Logging Handler" >
          <categories>
            <add name="Audit" />         
          </categories>
        </add> 
        </handlers>
    </add>
      </policies>
</policyInjection>

In our web server, always contains the exception like this:

----------------------------------------
Timestamp: 01/03/2009 06:32 PM
Message:  System.Runtime.Serialization.SerializationException: The input stream is not a valid binary format. The starting contents (in bytes) are: 3C-3F-78-6D-6C-20-76-65-72-73-69-6F-6E-3D-22-31-2E ...

Server stack trace:
   at System.Runtime.Serialization.Formatters.Binary.SerializationHeaderRecord.Read(__BinaryParser input)
   at System.Runtime.Serialization.Formatters.Binary.__BinaryParser.ReadSerializationHeaderRecord()
   at System.Runtime.Serialization.Formatters.Binary.__BinaryParser.Run()
   at System.Runtime.Serialization.Formatters.Binary.ObjectReader.Deserialize(HeaderHandler handler, __BinaryParser serParser, Boolean fCheck, Boolean isCrossAppDomain, IMethodCallMessage methodCallMessage)
   at System.Runtime.Serialization.Formatters.Binary.BinaryFormatter.Deserialize(Stream serializationStream, HeaderHandler handler, Boolean fCheck, Boolean isCrossAppDomain, IMethodCallMessage methodCallMessage)
   at System.Runtime.Remoting.Channels.CoreChannel.DeserializeBinaryResponseMessage(Stream inputStream, IMethodCallMessage reqMsg, Boolean bStrictBinding)
   at System.Runtime.Remoting.Channels.BinaryClientFormatterSink.SyncProcessMessage(IMessage msg)

Exception rethrown at [0]:
   at System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg)
   at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type)
   at NCS.Customs.LIS.ServiceContract.ILiquorQuota.SearchPassengers(String passengerName, Nullable`1 passengerDob, String passportNo, Int32 startRowIndex, Int32 maximumRows, Int32& totalCount, String sortExpression)
   at NCS.Customs.WebUI.LIS.LiquorPassengerSearch.SearchPassengers(String passengerName, Nullable`1 passengerDob, String passportNo, Int32 startRowIndex, Int32 maximumRows, Int32& totalCount, String sortExpression) in E:\eCustoms\Migration\MigrationBaseVersion_7687\WebUI\LIS\LiquorPassengerSearch.aspx.cs:line 141
Extended Properties: AuthenticationType - Forms IdentityName - 00284183 IsAuthenticated - True
Machine:  ECPDCWEB01
----------------------------------------

1) The code is very simple
2) if I cache something into web server and won't communicate with remoting server, the exception of serialization will be reduced more.

The general explaination about this exception is:

Due to our application server is based on IIS host and communicate with Http protocol.

So When server occur an unknown exception and response to web server, web server

will throw the exception of serialization when can't serialized them as the normal response.

My question is:

When system invoke the method which exists in the BusinessFacade class, the audit log file will be created.

So If the online user is < 50, does it(log the info into audit.log in the application server) cause the performance issue, such as time out issue or unknown exception?

Thanks
Hong Hai

Mar 12, 2009 at 10:32 AM
Some clarifications, where is the BusinessFacade class defined?  And why would the audit log file will be created once a method in that class is invoked?  


Sarah Urmeneta
Global Technology & Solutions
Avanade, Inc.
entlib.support@avanade.com
Mar 12, 2009 at 2:03 PM
The class of Business Facade like this:
Class BF.XX
{
        [TransactionScopeCallHandler("ARS Agent","Update Agent")]
        public void UpdateAgentLicense(ARSAgentLicenseUpdateDataSet ds,bool flag)
        {
            this.bc.UpdateAgentLicense(ds,flag);
        }

}

The PIAB will inject this method due to the PolicyInjection.config.

So in the config file, has this:

    <handlers>
        <add logBehavior="After" beforeMessage="Before" afterMessage="After"
            eventId="0" includeParameterValues="true" includeCallStack="false"
            includeCallTime="true" priority="-1" severity="Information"
            type="Microsoft.Practices.EnterpriseLibrary.PolicyInjection.CallHandlers.LogCallHandler, Microsoft.Practices.EnterpriseLibrary.PolicyInjection.CallHandlers"
            name="Logging Handler" >
          <categories>
            <add name="Audit" />         
          </categories>
        </add> 
        </handlers>

So the audit.log will be created.


Mar 13, 2009 at 3:25 AM
There's always an overhead when performing logging, but it can be negligible depending on the amount of info you're logging.  If those serialization exception occurs frequently, it may cause performance issue.  I can't say for sure, but the best way is to use performance counters.  Or if you just want to ignore those serializationexception, you may create an exception policy with the PostHandlingAction set to None.


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