Tridion publishing in debug mode

Publishing is the most critical process for Tridion users and when publishing fails (or takes too long) they become unhappy and the sysadmin has to explain why and fix it asap. Here is my Tridion tip for today: how to debug the publishing process.

Pre-requisites:

  • Admin access to machine where Publisher service runs
  • Nobody is publishing from that CMS

Steps for setting up the publisher in DEBUG mode:

  • Stop the Publisher windows service
  • Open command prompt (or Powershell)
  • Navigate to <TRIDION_HOME>\bin\ folder
  • Run 'TcmPublisher.exe -debug'

Now the publisher service is listening in DEBUG mode to the publish queue. Now you can publish the page that is causing issues and see what the publisher is doing under the hood and what is going wrong. 

Example response of publishing page

Below is an example result (modified a bit for readability):

10:33:29.5042 <12152> Retrieved queue message 73 from PublishQueue
10:33:29.5042 <12680> Working on queue message 73
10:33:29.7073 <12680> Extension initialized: CME System Privileges Extensions (Tridion.Web.UI.CME.TcmExtensions.SystemPr
ivileges)
10:33:29.7230 <12680> Extension initialized: CME Event System Extensions (Tridion.Web.UI.CME.TcmExtensions.EventHandlers
)
10:33:29.7542 <12680> Extension initialized: XPM - TCM Extensions (Tridion.SiteEdit.TcmExtensions.EventHandlers)
10:33:30.4376 <12680> Handling Publish Transaction [tcm:0-2-66560]
10:33:31.6916 <12680> Publishing item [tcm:1-41-64] from publication [tcm:0-1-1] to target [tcm:0-1-65537]
10:33:31.8836 <12680> Storage location: c:\Temp\tcm_0-2-66560.Content\
10:33:32.0197 <12680> Using resolver [Tridion.ContentManager.Publishing.Resolving.PageResolver]
10:33:32.1291 <12680> Resolving the pages [tcm:1-41-64] took 00:00:00.1135300
10:33:32.1447 <12680> Page tcm:1-41-64 resolved to 1 items. Resolving took: 00:00:00.1412808
10:33:32.1760 <12680> Rendering item [tcm:1-41-64] 'Test Page' with template [tcm:1-34-128] 'Default Page Template' in p
ublication target [tcm:0-1-65537] 'Staging'
10:33:32.9103 <12680> Referenced assemblies from the GAC:

10:33:32.9103 <12680> Referenced assemblies from the custom path:

10:33:32.9103 <12680> Source code: /* C# sourcecode removed for readability */
            
10:33:34.3745 <12680> Rendering of item [tcm:1-41-64] 'Test Page' with template [tcm:1-34-128] 'Default Page Template' i
n publication target [tcm:0-1-65537] 'Staging' took: 00:00:02.1851037
10:33:34.3865 <12680> Adding rendered item to the transport package: item [tcm:1-41-64] 'Test Page' with template [tcm:1
-34-128] 'Default Page Template' in publication target [tcm:0-1-65537] 'Staging'
10:33:34.3905 <12680> Using transport package handler: Tridion.ContentManager.Publishing.Transporting.DefaultPageHandler

10:33:34.3945 <12680> Adding [Page tcm:1-41-64] to the transport package.
10:33:34.3995 <12680> Writing file: c:\Temp\tcm_0-2-66560.Content\Pages\test.html
10:33:34.5353 <12680> Updating the publish transaction with the list of processed items
10:33:34.5509 <12680> Saving the transport package.
10:33:34.5978 <12680> Sending tranport package for transaction [tcm:0-2-66560] with deploy control [Commit] to transport
 service.
10:33:34.8514 <12680> Sending information to transport service took: 00:00:00.2454763.
10:33:34.8544 <12680> Transport service reported state [ReadyForTransport] for Publish Transaction [tcm:0-2-66560] with
response: <TransportSummary referenceId="tcm:0-2-66560" state="Ready for transport"><Processing><Context topic="Content
Delivery"><IsRollbackOnFailure>false</IsRollbackOnFailure></Context><Step href="simple" type="Prepare transport" state="
Ready for transport"><RemoteEndpoint connector="DiscoveryService" id="DgHAheAA2zLe19e5+Pe/tQ==" name="Discovery Service
Upload" state="Ready for transport" windowSize="0" /></Step><Step href="simple" type="Transporting" state="None"><Remote
Endpoint connector="DiscoveryService" id="DgHAheAA2zLe19e5+Pe/tQ==" name="Discovery Service Upload" state="None" windowS
ize="0" /></Step><Step href="simple" type="Deployment preparation" state="None"><RemoteEndpoint connector="DiscoveryServ
ice" id="DgHAheAA2zLe19e5+Pe/tQ==" name="Discovery Service Upload" state="None" windowSize="0" /></Step><Step href="simp
le" type="Deploying" state="None"><RemoteEndpoint connector="DiscoveryService" id="DgHAheAA2zLe19e5+Pe/tQ==" name="Disco
very Service Upload" state="None" windowSize="0" /></Step><Step href="simple" type="Deployment committing" state="None">
<RemoteEndpoint connector="DiscoveryService" id="DgHAheAA2zLe19e5+Pe/tQ==" name="Discovery Service Upload" state="None"
windowSize="0" /></Step></Processing></TransportSummary>
10:33:34.9102 <12680> Handling Publish Transaction [tcm:0-2-66560] took: 00:00:04.4792882
10:33:34.9102 <12680> Cache statistics: SimpleCache: 5 Regions, 5 Objects, 11 Hits, 2 Misses
10:33:34.9102 <12680>   Region 'Component': 0 Objects, 0 Hits, 0 Misses.
10:33:34.9102 <12680>   Region 'PublishTransaction': 3 Objects, 6 Hits, 1 Misses.
10:33:34.9102 <12680>   Region 'TargetType': 1 Objects, 4 Hits, 0 Misses.
10:33:34.9102 <12680>   Region 'PublicationTarget': 1 Objects, 1 Hits, 0 Misses.
10:33:34.9258 <12680>   Region 'Tdse': 0 Objects, 0 Hits, 1 Misses.
10:33:35.0352 <12152> Deleting queue message: 73 from PublishQueue.
10:33:35.4883 <6132> Transport service response: <?xml version="1.0" encoding="UTF-8" standalone="yes"?>
/* XML response is removed for readability */
10:33:35.5234 <6132> Receiving deployment feedback for publish transaction [tcm:0-2-66560] with status: WaitingForDeploy
ment
10:33:39.7672 <6132> Transport service response: <?xml version="1.0" encoding="UTF-8" standalone="yes"?>
/* XML response is removed for readability */

10:33:39.7922 <6132> Receiving deployment feedback for publish transaction [tcm:0-2-66560] with status: Success

What good to know is that this also works for other TCM services as well. After you finished your investigation, don't forget to start the service again.