Log4net visualiser

When we are implementing an EPiServer web site (or any other software solution) it is imperative to have good error handling. EPiServer uses log4net for its error handling so it is natural to use it as the logging framework for your application.
If your website is not behaving properly, you want to know about it and act accordingly. This is a good habit to have and it is a best practice in software development.

By default, EPiServer catches all unhandled exceptions in it's EPiServer.Global error handler, but in standard .NET applications, this will not happen and you will not be able to see your unhandled exceptions in your log file. That's where elmah kicks inn.

In this post we are going to look at how we can use log4net to track the exceptions you catch, elmah to track the exceptions you are not catching (and probably should) and and how we can aggregate and query this information in one central repository. This is done by appending exceptions caught by Elmah in our log4net repository and use log4net dashboard to analyse the errors.

We start by configuring the standard logging facility to write the errors in XML format. We have to edit [EPiServerLog|log4net].config and change the layout formatter. The file should look like this:

<?xml version="1.0" encoding="utf-8" ?>
<log4net>
  <appender name="RollingFile" type="log4net.Appender.RollingFileAppender">
    <file value="..\logs\mywebsite.xml" />
    <appendToFile value="true" />
    <maximumFileSize value="10MB" />
    <maxSizeRollBackups value="20" />

    <layout type="log4net.Layout.XmlLayout">
      <param name="Prefix" value="" />
    </layout>
  </appender>

  <root>
    <level value="ERROR" />
    <appender-ref ref="RollingFile" />
  </root>
</log4net>

We are instructing log4net to log the errors in XML format into files, rotating it every 10MB, up to 20 files.

We modify the pages that we want to log exceptions by getting an instance of the logger and writing the exception to it.
You declare a member in your class/page:
        private static readonly log4net.ILog Log = log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);

And use it when catching an exception:
            catch (SmtpException smtpException)
            {
                Log.Error(smtpException);
                (...)
            }

We are now going to plug Elmah in in order to track the exceptions that are not handled in our code (non EPiServer sites only).

First we modify our web.config to configure its settings:
    <configSections>
        <sectionGroup name="elmah">
            <section name="security" requirePermission="false" type="Elmah.SecuritySectionHandler, Elmah" />
            <section name="errorLog" requirePermission="false" type="Elmah.ErrorLogSectionHandler, Elmah" />
        </sectionGroup>
    </configSections>

    <elmah>
        <errorLog type="MyWebsite.Log4NetErrorLog, MyWebsite" logPath="c:\logs" />
        <security allowRemoteAccess="0"></security>
    </elmah>

    <modules>
            <add name="ErrorLog" type="Elmah.ErrorLogModule, Elmah"/>
            <add name="ErrorFilter" type="Elmah.ErrorFilterModule, Elmah"/>
    </modules>

And add a class to our project with the following code. This class extends Elmah's XmlFileErrorLog and overrides its logging behaviour. It will get the unhandled exception in your website and log it as a "Fatal" error in log4net, under the "Elmah" section.

using System;
using System.Collections;
using System.Collections.Generic;
using System.Linq;
using System.Web;
using Elmah;
using log4net;

namespace MyWebsite
{
    public class Log4NetErrorLog : XmlFileErrorLog
    {
        public Log4NetErrorLog(IDictionary config) : base(config)
        {
        }

        public Log4NetErrorLog(string logPath) : base(logPath)
        {
        }

        readonly ILog _log = LogManager.GetLogger("Elmah");
        public override string Log(Error error)
        {
            _log.Fatal("Exception logged through ELMAH: " + error.Message, error.Exception);
            return string.Empty;
        }
    }
}

The next step would be to install L4ndash. You can get it here: http://www.l4ndash.com/Download.aspx. The developer edition is free to use as long as you have only one instance per machine and access it via localhost.

Finally, we need to create a plugin that serves as a view over the l4ndash dashboard:

namespace EPiServer.Templates.Private
{
    using EPiServer.PlugIn;

    /// <summary>
    /// This plugin will display the errors in your error log
    /// </summary>
    [GuiPlugIn(DisplayName = "Error Report", Area = PlugInArea.AdminMenu, Url = "~/templates/private/errors.aspx")]
    public partial class Errors : System.Web.UI.Page
    {
    }
}

Assuming you install landash as a virtual directory under your default web site:
<%@ Page Language="C#" AutoEventWireup="true" CodeBehind="Errors.aspx.cs" Inherits="EPiServer.Templates.Private.Errors" %>
<iframe src="http://localhost/landash/PageLoggerSummary/LoggerSummary.aspx" width="100%" height="100%"></iframe>

And you're good to go! The following is a sample screen shot from an EPiServer CMS6 + Composer 4 development box:
We can see the overview of all exceptions and drill down into specific errors to get more information.
We can also apply filters to get errors thrown by a specific method or to get the latest recorder errors.

Hopefully this will help you in diagnosing and debugging your EPiServer (and in general, web) applications.

LoaderExceptions when building in Release mode – sgen.exe

Recently we faced a problem where an application would build and run in debug mode but it would not do the same in release, throwing the following error at the end of a build.
sgen = http://msdn.microsoft.com/en-us/library/bk3w6240(v=VS.100).aspx
Knowing that sgen is responsible for generating the xml serialisation assembly for the application, the error was most likely related to an assembly that was injected during runtime into the AppDomain, in release mode. As sgen loads all the assemblies immediately, we see an error.
In debug mode the application appears to be running correctly but it would fail in release mode, when the assembly is loaded.

Now, the $1M question. Which assembly was causing this error?

The error message in VS output window was not very informative, so we set the build log to "diagnostic", rebuilt the application in release mode and watched the output window.

Target GenerateSerializationAssemblies:
  Building target "GenerateSerializationAssemblies" completely.
  Output file "obj\Release\ClientWebsite.XmlSerializers.dll" does not exist.
  Using "SGen" task from assembly "Microsoft.Build.Tasks.v3.5, Version=3.5.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a".
  Task "SGen"
    Command:
    C:\Program Files\Microsoft SDKs\Windows\v6.0A\bin\sgen.exe /assembly:D:\projects\repo\wwwroot\obj\Release\ClientWebsite.dll /proxytypes /reference:bin\(over 30 references)
    The "SGen" task is using "sgen.exe" from "C:\Program Files\Microsoft SDKs\Windows\v6.0A\bin\sgen.exe".
    Microsoft (R) Xml Serialization support utility
    [Microsoft (R) .NET Framework, Version 2.0.50727.3038]
    Copyright (C) Microsoft Corporation. All rights reserved.
    SGEN : error : Unable to load one or more of the requested types. Retrieve the LoaderExceptions property for more information.

    If you would like more help, please type "sgen /?".
    The command exited with code 1.
  Done executing task "SGen" -- FAILED.
Done building target "GenerateSerializationAssemblies" in project "Site.EPS.csproj" -- FAILED.

Retrieve the LoaderExceptions property for more information. Right.
So this error message was also not very informative, we had to dig a little bit deeper.
At this point we know that sgen cannot bind the assembly, so we are going to have a look at the binding logs via assembly binding log viewer aka fuslogvw.exe.
fuslogvw.exe = http://msdn.microsoft.com/en-us/library/e74a18c4%28v=VS.100%29.aspx

To enable fusion logging, the following DWORD registry key has to be set:
HKLM\Software\Microsoft\Fusion!EnableLog 1
Start fusion log viewer and configure it to log assembly binding failures to disk:

Now rebuild the application to log the errors and refresh the fusion log viewer window. You should see something similar to the following:

*** Assembly Binder Log Entry  (10/11/2010 @ 14:48:49) ***

The operation failed.
Bind result: hr = 0x80070002. The system cannot find the file specified.

Assembly manager loaded from:  C:\Windows\Microsoft.NET\Framework\v2.0.50727\mscorwks.dll
Running under executable  C:\Program Files\Microsoft SDKs\Windows\v6.0A\bin\sgen.exe
--- A detailed error log follows. 

=== Pre-bind state information ===
LOG: User = FCUK\Nimesh.Manmohanlal
LOG: DisplayName = EPiServer, Version=5.1.422.122, Culture=neutral, PublicKeyToken=8fe83dea738b45b7
 (Fully-specified)
LOG: Appbase = file:///C:/Program Files/Microsoft SDKs/Windows/v6.0A/bin/
LOG: Initial PrivatePath = NULL
LOG: Dynamic Base = NULL
LOG: Cache Base = NULL
LOG: AppName = NULL
Calling assembly : EPiCode.Caching, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null.
===
LOG: This bind starts in LoadFrom load context.
WRN: Native image will not be probed in LoadFrom context. Native image will only be probed in default load context, like with Assembly.Load().
LOG: No application configuration file found.
LOG: Using machine configuration file from C:\Windows\Microsoft.NET\Framework\v2.0.50727\config\machine.config.
LOG: Post-policy reference: EPiServer, Version=5.1.422.122, Culture=neutral, PublicKeyToken=8fe83dea738b45b7
LOG: GAC Lookup was unsuccessful.
LOG: Attempting download of new URL file:///C:/Program Files/Microsoft SDKs/Windows/v6.0A/bin/EPiServer.DLL.
LOG: Attempting download of new URL file:///C:/Program Files/Microsoft SDKs/Windows/v6.0A/bin/EPiServer/EPiServer.DLL.
LOG: Attempting download of new URL file:///C:/Program Files/Microsoft SDKs/Windows/v6.0A/bin/EPiServer.EXE.
LOG: Attempting download of new URL file:///C:/Program Files/Microsoft SDKs/Windows/v6.0A/bin/EPiServer/EPiServer.EXE.
LOG: Attempting download of new URL file:///C:/projects/MyWebsite/References/EPiServer.DLL.
LOG: Attempting download of new URL file:///C:/projects/MyWebsite/References/EPiServer/EPiServer.DLL.
LOG: Attempting download of new URL file:///C:/projects/MyWebsite/References/EPiServer.EXE.
LOG: Attempting download of new URL file:///C:/projects/MyWebsite/References/EPiServer/EPiServer.EXE.
LOG: All probing URLs attempted and failed.
Finally we found the cause of our problem. We had a third party assembly that was built using a different version of EPiServer (5.1.422.122), so when sgen.exe tried to load the project assemblies and all of the dependencies it failed.
The fix was to rebuild the third party assembly using the correct version of EPiServer (5.2.375.236).

This happened because we upgraded an EPiServer web application project from CMS5 to CMS5 R2. The application was migrated succesfully but the third party assemblies were not taken in consideration and the error only manifested itself further down the line.

The morale of the story is, if you perform an application upgrade, make sure you also upgrade all your third party libraries that have dependencies on your product.

EPiServer DataFactory deadlock exception

Recently we faced a problem in one of our websites where some pages would randomly fail to load and a deadlock exception would be thrown from EPiServer.DataAccess.DatabaseFactory: "Failing because of deadlock."

At this point we suspected that some other process might be locking some rows out thus causing the loading of our page to fail.
Drilling down the logs, we found out a bit more of what was causing the pages to fail:

<event logger="EPiServer.DataAccess.DatabaseFactory" timestamp="2010-09-23T14:08:29.359375+01:00" level="ERROR" thread="13" domain="/LM/W3SVC/1" username="NT AUTHORITY\NETWORK SERVICE">
  <message>Failing because of deadlock.</message>
  <properties>
    <data name="log4net:HostName" value="web1" />
  </properties>
  <exception>
    <![CDATA[System.Data.SqlClient.SqlException: Transaction (Process ID 137) was deadlocked on lock | communication buffer resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
  </exception>
</event>    

Our initial suspicions were correct, we were facing an issue were another process was locking the rows that we needed in order to load the page.

Continuing our investigation, we turned on SQL lock tracing and watched the error logs while we refreshed the page.

DBCC TRACEON (1222, -1)

09/23/2010 09:08:00,spid14s,Unknown,deadlock-list
09/23/2010 09:08:00,spid14s,Unknown,deadlock victim=process3812c208																																																																																																																																		

09/23/2010 09:08:00,spid14s,Unknown,process-list																																																																																																																																		

09/23/2010 09:08:00,spid14s,Unknown,process id=processc6ab68 taskpriority=0 logused=20000 waittime=187 schedulerid=5 kpid=11600 status=suspended spid=98 sbid=0 ecid=0 priority=0 transcount=0 lastbatchstarted=2010-09-23T09:08:00.123 lastbatchcompleted=2010-09-23T09:08:00.123 clientapp=.Net SqlClient Data Provider hostname=WEB2 hostpid=4548 loginname=sa isolationlevel=read committed (2) xactid=72110112461 currentdb=17 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
09/23/2010 09:08:00,spid14s,Unknown,executionStack
09/23/2010 09:08:00,spid14s,Unknown,frame procname=dbEPiServer.dbo.netPropertySearchString line=21 stmtstart=1064 stmtend=3640 sqlhandle=0x030011009d4ce3523d5771005d9d00000100000000000000
09/23/2010 09:08:00,spid14s,Unknown,SELECT DISTINCT(tblProperty.fkPageID)<nl/>	FROM       tblProperty<nl/>	INNER JOIN tblPageDefinition ON tblPageDefinition.pkID=tblProperty.fkPageDefinitionID<nl/>	INNER JOIN tblTree ON tblTree.fkChildID=tblProperty.fkPageID<nl/>	INNER JOIN tblPageLanguage ON tblPageLanguage.fkPageID=tblProperty.fkPageID<nl/>	WHERE <nl/>	         tblTree.fkParentID=@PageID <nl/>	AND tblPageDefinition.Name=@PropertyName<nl/>	AND (@LangBranchID=-1 OR tblProperty.fkLanguageBranchID=@LangBranchID OR tblPageDefinition.LanguageSpecific=0)<nl/>	AND<nl/>	(<nl/>		(	/*STRING*/<nl/>
09/23/2010 09:08:00,spid14s,Unknown,inputbuf
09/23/2010 09:08:00,spid14s,Unknown,Proc [Database Id = 17 Object Id = 1390627997]																																																																																																																																		

09/23/2010 09:08:00,spid14s,Unknown,process id=processdac5c8 taskpriority=0 logused=4560 waitresource=OBJECT: 17:1349579846:0  waittime=1906 ownerId=72110076172 transactionname=user_transaction lasttranstarted=2010-09-23T09:07:58.390 XDES=0x302d0250 lockMode=IX schedulerid=8 kpid=8432 status=suspended spid=51 sbid=0 ecid=0 priority=0 transcount=3 lastbatchstarted=2010-09-23T09:07:58.390 lastbatchcompleted=2010-09-23T09:07:58.390 clientapp=.Net SqlClient Data Provider hostname=WEB1 hostpid=3780 loginname=sa isolationlevel=read committed (2) xactid=72110076172 currentdb=17 lockTimeout=4294967295 clientoption1=673316896 clientoption2=128056
09/23/2010 09:08:00,spid14s,Unknown,executionStack
09/23/2010 09:08:00,spid14s,Unknown,frame procname=dbEPiServer.dbo.editPublishPageVersion line=97 stmtstart=6296 stmtend=6818 sqlhandle=0x03001100cb6e6d758593cc004b9b00000100000000000000
09/23/2010 09:08:00,spid14s,Unknown,DELETE FROM <nl/>		tblProperty<nl/>	FROM <nl/>		tblProperty<nl/>	INNER JOIN<nl/>		tblPageDefinition ON fkPageDefinitionID=pkID<nl/>	WHERE <nl/>		fkPageID=@PageID AND<nl/>		fkPageTypeID IS NOT NULL AND<nl/>
09/23/2010 09:08:00,spid14s,Unknown,inputbuf
09/23/2010 09:08:00,spid14s,Unknown,Proc [Database Id = 17 Object Id = 1970106059]																																																																																																																																		

09/23/2010 09:08:00,spid14s,Unknown,process id=process9068e38 taskpriority=0 logused=20026 waittime=93 schedulerid=1 kpid=8036 status=suspended spid=98 sbid=0 ecid=2 priority=0 transcount=0 lastbatchstarted=2010-09-23T09:08:00.123 lastbatchcompleted=2010-09-23T09:08:00.123 clientapp=.Net SqlClient Data Provider hostname=WEB2 hostpid=4548 isolationlevel=read committed (2) xactid=72110112461 currentdb=17 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
09/23/2010 09:08:00,spid14s,Unknown,executionStack
09/23/2010 09:08:00,spid14s,Unknown,frame procname=dbEPiServer.dbo.netPropertySearchString line=21 stmtstart=1064 stmtend=3640 sqlhandle=0x030011009d4ce3523d5771005d9d00000100000000000000
09/23/2010 09:08:00,spid14s,Unknown,SELECT DISTINCT(tblProperty.fkPageID)<nl/>	FROM       tblProperty<nl/>	INNER JOIN tblPageDefinition ON tblPageDefinition.pkID=tblProperty.fkPageDefinitionID<nl/>	INNER JOIN tblTree ON tblTree.fkChildID=tblProperty.fkPageID<nl/>	INNER JOIN tblPageLanguage ON tblPageLanguage.fkPageID=tblProperty.fkPageID<nl/>	WHERE <nl/>	         tblTree.fkParentID=@PageID <nl/>	AND tblPageDefinition.Name=@PropertyName<nl/>	AND (@LangBranchID=-1 OR tblProperty.fkLanguageBranchID=@LangBranchID OR tblPageDefinition.LanguageSpecific=0)<nl/>	AND<nl/>	(<nl/>		(	/*STRING*/<nl/>
09/23/2010 09:08:00,spid14s,Unknown,inputbuf																																																																																																																																		

09/23/2010 09:08:00,spid14s,Unknown,process id=process3812c208 taskpriority=0 logused=0 waitresource=PAGE: 17:1:726012 waittime=78 ownerId=72110112461 transactionname=SELECT lasttranstarted=2010-09-23T09:08:00.123 XDES=0x584e1990 lockMode=S schedulerid=7 kpid=10212 status=suspended spid=98 sbid=0 ecid=9 priority=0 transcount=0 lastbatchstarted=2010-09-23T09:08:00.123 lastbatchcompleted=2010-09-23T09:08:00.123 clientapp=.Net SqlClient Data Provider hostname=WEB2 hostpid=4548 isolationlevel=read committed (2) xactid=72110112461 currentdb=17 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
09/23/2010 09:08:00,spid14s,Unknown,executionStack
09/23/2010 09:08:00,spid14s,Unknown,frame procname=dbEPiServer.dbo.netPropertySearchString line=21 stmtstart=1064 stmtend=3640 sqlhandle=0x030011009d4ce3523d5771005d9d00000100000000000000
09/23/2010 09:08:00,spid14s,Unknown,SELECT DISTINCT(tblProperty.fkPageID)<nl/>	FROM       tblProperty<nl/>	INNER JOIN tblPageDefinition ON tblPageDefinition.pkID=tblProperty.fkPageDefinitionID<nl/>	INNER JOIN tblTree ON tblTree.fkChildID=tblProperty.fkPageID<nl/>	INNER JOIN tblPageLanguage ON tblPageLanguage.fkPageID=tblProperty.fkPageID<nl/>	WHERE <nl/>	         tblTree.fkParentID=@PageID <nl/>	AND tblPageDefinition.Name=@PropertyName<nl/>	AND (@LangBranchID=-1 OR tblProperty.fkLanguageBranchID=@LangBranchID OR tblPageDefinition.LanguageSpecific=0)<nl/>	AND<nl/>	(<nl/>		(	/*STRING*/<nl/>			Property = 6<nl/>			AND<nl/>			(<nl/>				(@String IS NULL AND String IS NULL)<nl/>				OR<nl/>				String LIKE <nl/>					CASE    WHEN @UseWildCardsBefore=0 AND @UseWildCardsAfter=0 THEN @String<nl/>						WHEN @UseWildCardsBefore=1 AND @UseWildCardsAfter=0 THEN '%' + @String<nl/>						WHEN @UseWildCardsBefore=0 AND @UseWildCardsAfter=1 THEN @String + '%'<nl/>						ELSE '%' + @String + '%'<nl/>					END<nl/>			)<nl/>		)<nl/>	OR 	(	/*LONGSTRING*/<nl/>			Property = 7<nl/>			AND<nl/>			(<nl/>				(@String IS NULL AND @String IS NULL)<nl/>				OR<nl/>				LongString LIKE <nl/>					CASE    WHEN @
09/23/2010 09:08:00,spid14s,Unknown,inputbuf																																																																																																																																		

09/23/2010 09:08:00,spid14s,Unknown,resource-list																																																																																																																																		

09/23/2010 09:08:00,spid14s,Unknown,objectlock lockPartition=0 objid=1349579846 subresource=FULL dbid=17 objectname=dbEPiServer.dbo.tblProperty id=lock1aec93c0 mode=S associatedObjectId=1349579846
09/23/2010 09:08:00,spid14s,Unknown,owner-list
09/23/2010 09:08:00,spid14s,Unknown,owner id=processc6ab68 mode=S																Property = 6<nl/>			AND<nl/>			(<nl/>				(@String IS NULL AND String IS NULL)<nl/>				OR<nl/>				String LIKE <nl/>					CASE    WHEN @UseWildCardsBefore=0 AND @UseWildCardsAfter=0 THEN @String<nl/>						WHEN @UseWildCardsBefore=1 AND @UseWildCardsAfter=0 THEN '%' + @String<nl/>						WHEN @UseWildCardsBefore=0 AND @UseWildCardsAfter=1 THEN @String + '%'<nl/>						ELSE '%' + @String + '%'<nl/>					END<nl/>			)<nl/>		)<nl/>	OR 	(	/*LONGSTRING*/<nl/>			Property = 7<nl/>			AND<nl/>			(<nl/>				(@String IS NULL AND @String IS NULL)<nl/>				OR<nl/>				LongString LIKE <nl/>					CASE    WHEN @
09/23/2010 09:08:00,spid14s,Unknown,owner id=processc6ab68 mode=IS
09/23/2010 09:08:00,spid14s,Unknown,waiter-list
09/23/2010 09:08:00,spid14s,Unknown,waiter id=processdac5c8 mode=IX requestType=wait																																																																																																																																		

09/23/2010 09:08:00,spid14s,Unknown,pagelock fileid=1 pageid=726012 dbid=17 objectname=dbEPiServer.dbo.tblPageLanguage id=lock5f275300 mode=IX associatedObjectId=72057594051428352
09/23/2010 09:08:00,spid14s,Unknown,owner-list
09/23/2010 09:08:00,spid14s,Unknown,owner id=processdac5c8 mode=IX															fkLanguageBranchID=@LangBranchID<nl/>	/* Move properties from worktable to published table */
09/23/2010 09:08:00,spid14s,Unknown,waiter-list
09/23/2010 09:08:00,spid14s,Unknown,waiter id=process3812c208 mode=S requestType=wait																																																																																																																																		

09/23/2010 09:08:00,spid14s,Unknown,exchangeEvent id=port42c8680 nodeId=26
09/23/2010 09:08:00,spid14s,Unknown,owner-list
09/23/2010 09:08:00,spid14s,Unknown,owner event=e_waitNone type=producer id=process3812c208
09/23/2010 09:08:00,spid14s,Unknown,waiter-list																Property = 6<nl/>			AND<nl/>			(<nl/>				(@String IS NULL AND String IS NULL)<nl/>				OR<nl/>				String LIKE <nl/>					CASE    WHEN @UseWildCardsBefore=0 AND @UseWildCardsAfter=0 THEN @String<nl/>						WHEN @UseWildCardsBefore=1 AND @UseWildCardsAfter=0 THEN '%' + @String<nl/>						WHEN @UseWildCardsBefore=0 AND @UseWildCardsAfter=1 THEN @String + '%'<nl/>						ELSE '%' + @String + '%'<nl/>					END<nl/>			)<nl/>		)<nl/>	OR 	(	/*LONGSTRING*/<nl/>			Property = 7<nl/>			AND<nl/>			(<nl/>				(@String IS NULL AND @String IS NULL)<nl/>				OR<nl/>				LongString LIKE <nl/>					CASE    WHEN @
09/23/2010 09:08:00,spid14s,Unknown,waiter event=e_waitPortClose type=consumer id=process9068e38																																																																																																																																		

09/23/2010 09:08:00,spid14s,Unknown,exchangeEvent id=port42c9f80 nodeId=0
09/23/2010 09:08:00,spid14s,Unknown,owner-list
09/23/2010 09:08:00,spid14s,Unknown,owner event=e_waitNone type=producer id=process9068e38
09/23/2010 09:08:00,spid14s,Unknown,waiter-list
09/23/2010 09:08:00,spid14s,Unknown,waiter event=e_waitPortOpen type=consumer id=processc6ab68																																																																																																																																		

So looking at the errors, we are doing a number of property searches (FindPagesWithCriteria), that acquire a shared lock on the rows, as well as a page publish, that tries to acquire an exclusive lock.
Having A = processc6ab68, B = process9068e38, C = process3812c208, D = processdac5c8, where D is the page publish and A, B and C are FindPagesWithCriteria running in parallel.
we can see that A is waiting for B which in turn is waiting for C which is waiting for D which is waiting for A... and the deadlock resolution victim was C, causing our page load failure.

The culprit of this situation was a long running job that was reading pages and publishing them in new language branches on a (high traffic) web site that has a large number of property searches.

A number of things can be done to resolve or at least mitigate this problem such as refactor the property searches to run under a specific language branch, run the job at a period of low traffic or even run the job with the web site in "maintenance" mode.