Tridion Publisher Issue - Fails nightly

Question

Within our environment (doesn't occur in any lower environments) I am seeing the following error every night in the TcmPublisher.xml. I am thinking there is some batch process running every night either on TCM or DB causing some connection issues or maybe the pool connection times out after it keeps trying to connect to the firewall.?

When I look at the service on the server it says its running.. but the only way it can be fixed is to restart publisher..

6/24/2015 1:03:18 PM <10976> Stopping Deployment feedback handler thread.
6/24/2015 1:03:19 PM <10976> Deployment feedback handler thread stopped.
6/24/2015 1:03:19 PM <10976> Stopping worker threads for DeployQueue.
6/24/2015 1:03:19 PM <10976> Stopping Queue message handler for DeployQueue [0].
6/24/2015 1:03:19 PM <10976> Queue message handler for DeployQueue [0] stopped.
6/24/2015 1:03:20 PM <13052> Closing DeployQueue.
6/24/2015 1:03:20 PM <10976> All worker threads for DeployQueue stopped.
6/24/2015 1:03:20 PM <10976> Stopping worker threads for PublishQueue.
6/24/2015 1:03:20 PM <10976> Stopping Queue message handler for PublishQueue [0].
6/24/2015 1:03:20 PM <10976> Queue message handler for PublishQueue [0] stopped.
6/24/2015 1:03:20 PM <10592> Closing PublishQueue.
6/24/2015 1:03:20 PM <10976> All worker threads for PublishQueue stopped.
6/24/2015 1:03:20 PM <10976> Tridion Content Manager Publisher service stopped
6/24/2015 1:03:21 PM <4124> Starting 1 worker threads for PublishQueue.
6/24/2015 1:03:21 PM <4124> Starting 1 worker threads for DeployQueue.
6/24/2015 1:03:21 PM <4124> Starting Deployment feedback handler thread.
6/24/2015 1:03:21 PM <4124> Tridion Content Manager Publisher service started
6/24/2015 1:03:21 PM <12492> Deployment feedback handler thread started.
6/24/2015 1:03:22 PM <3436> Listening for messages on PublishQueue.
6/24/2015 1:03:22 PM <13088> Listening for messages on DeployQueue.
6/25/2015 4:33:30 AM <3436> Error occurred while retrieving message from PublishQueue:
6/25/2015 4:33:30 AM <3436> A database error occurred while executing Stored Procedure "TCM_QUEUE.MESSAGES_READ".
ORA-03113: end-of-file on communication channelProcess ID: 7876Session ID: 764 Serial number: 7939

6/25/2015 10:49:25 AM <15220> Stopping Deployment feedback handler thread.
6/25/2015 10:49:25 AM <15220> Deployment feedback handler thread stopped.
6/25/2015 10:49:25 AM <15220> Stopping worker threads for DeployQueue.
6/25/2015 10:49:25 AM <15220> Stopping Queue message handler for DeployQueue [0].
6/25/2015 10:49:26 AM <15220> Queue message handler for DeployQueue [0] stopped.
6/25/2015 10:49:26 AM <3436> Closing PublishQueue.
6/25/2015 10:49:27 AM <13088> Closing DeployQueue.
6/25/2015 10:49:27 AM <15220> All worker threads for DeployQueue stopped.
6/25/2015 10:49:27 AM <15220> Stopping worker threads for PublishQueue.
6/25/2015 10:49:27 AM <15220> Stopping Queue message handler for PublishQueue [0].
6/25/2015 10:49:27 AM <15220> Queue message handler for PublishQueue [0] stopped.
6/25/2015 10:49:27 AM <15220> All worker threads for PublishQueue stopped.
6/25/2015 10:49:27 AM <15220> Tridion Content Manager Publisher service stopped
6/25/2015 10:49:28 AM <13432> Starting 1 worker threads for PublishQueue.
6/25/2015 10:49:28 AM <13432> Starting 1 worker threads for DeployQueue.
6/25/2015 10:49:28 AM <13432> Starting Deployment feedback handler thread.
6/25/2015 10:49:28 AM <14364> Deployment feedback handler thread started.
6/25/2015 10:49:28 AM <13432> Tridion Content Manager Publisher service started
6/25/2015 10:49:30 AM <14700> Listening for messages on PublishQueue.
6/25/2015 10:49:30 AM <13816> Listening for messages on DeployQueue.

Has anyone more experienced in Tridion services seen any kind of activity like this in the past and possibly from a high level just understand exactly what could possibly be the causing this to stop?

Answer 1

This isn't about the publisher but about the database. Your log clearly shows the Oracle error.

ORA-03113: end-of-file on communication channelProcess

Whenever you see an ORA- error in your logs, you should Google it. In this case, it seems to be a catch-all error that could mean lots of things.

If it's occurring at a specific time, then perhaps there's a scheduled activity that affects the database. An incorrectly configured backup, perhaps. In any case, you can look in the ORACLE logs to see if there's any more information to be found that correlates with the timestamp in the log you already have.

Of course, the root cause might be something else such as a network problem, which then triggers the error condition in ORACLE, which in turn breaks your publisher.

In any case, you should report this to SDL customer support, because if restarting the publisher is enough to fix it, perhaps the exception handling can be improved so that the publisher itself can recover without a restart.

Answer 2

As you mentioned, looks like there is some kind of scheduled automated maintenance batch process is in place. Which stops the publishing process.

So I would suggest first check if there is any Scheduled Automated Script, and if it there how it's stopping/starting the services. Looks like, while stopping/re-starting the publishing process the script is not doing it in a proper way.

One such case I can guess of is a "Clean Up Script" of temporary items during publishing process:

As, we have a lots of intermediate files(stored in temp/Incoming folders) during publishing process and in some cases when anything goes wrong during the process the files remains there forever.

So to clean up those files by a automated script, the publishing process needs to be stopped first and a then re-start after clean up of files.