FATAL ERROR occurred during execution of worker, queue no longer processed

question
1

I have been using Hangfire for about a month and have set it up both as an “always running” .Net app and now as a Windows service. Whatever way I use it, it will work for a few hours, then eventually I will receive exceptions and errors in the log, and jobs in the queue will no longer be processed.

I am using Windows Server 2008 R2 and SQL Server express. I am using Hangfire 1.3.3 and NLog.

The FATAL error messages say “see the exception for details”; however I see no exception in the log. My Nlog configuration is:

<!-- add your targets here -->

<target xsi:type="File" name="f" fileName="${basedir}/logs/${shortdate}.log"
        layout="${longdate} ${uppercase:${level}} ${message}" />

<logger name="*" minlevel="Trace" writeTo="f" />

This is a typical segment from the log:

2015-01-30 16:17:44.4394 DEBUG Removing outdated records from table ‘Set’…
2015-01-30 16:17:44.4394 DEBUG Removing outdated records from table ‘Hash’…
2015-01-30 17:12:16.8876 ERROR Error occurred during execution of ‘Recurring Job Scheduler’ component. Execution will be retried (attempt 1 of 10) in 00:00:01 seconds.
2015-01-30 17:12:36.7484 ERROR Error occurred during execution of ‘Worker #4’ component. Execution will be retried (attempt 1 of 10) in 00:00:00 seconds.
2015-01-30 17:12:36.9824 ERROR Error occurred during execution of ‘Worker #2’ component. Execution will be retried (attempt 1 of 10) in 00:00:01 seconds.
2015-01-30 17:12:36.9980 ERROR Error occurred during execution of ‘Worker #1’ component. Execution will be retried (attempt 1 of 10) in 00:00:00 seconds.
2015-01-30 17:12:37.5908 ERROR Error occurred during execution of ‘Worker #5’ component. Execution will be retried (attempt 1 of 10) in 00:00:01 seconds.
2015-01-30 17:12:37.7780 ERROR Error occurred during execution of ‘Worker #3’ component. Execution will be retried (attempt 1 of 10) in 00:00:01 seconds.
2015-01-30 17:12:41.5220 ERROR Error occurred during execution of ‘Server Heartbeat’ component. Execution will be retried (attempt 1 of 10) in 00:00:01 seconds.
2015-01-30 17:12:49.3532 ERROR Error occurred during execution of ‘Server Watchdog’ component. Execution will be retried (attempt 1 of 10) in 00:00:01 seconds.
2015-01-30 17:12:49.9304 ERROR Error occurred during execution of ‘Worker #3’ component. Execution will be retried (attempt 2 of 10) in 00:00:01 seconds.
2015-01-30 17:12:50.1332 ERROR Error occurred during execution of ‘Worker #5’ component. Execution will be retried (attempt 2 of 10) in 00:00:02 seconds.
2015-01-30 17:12:50.3360 ERROR Error occurred during execution of ‘Worker #2’ component. Execution will be retried (attempt 2 of 10) in 00:00:02 seconds.
2015-01-30 17:12:50.3360 ERROR Error occurred during execution of ‘Worker #1’ component. Execution will be retried (attempt 2 of 10) in 00:00:03 seconds.
2015-01-30 17:12:50.7104 ERROR Error occurred during execution of ‘Worker #4’ component. Execution will be retried (attempt 2 of 10) in 00:00:02 seconds.
2015-01-30 17:12:50.9132 ERROR Error occurred during execution of ‘Server Watchdog’ component. Execution will be retried (attempt 2 of 10) in 00:00:02 seconds.
2015-01-30 17:12:51.1628 ERROR Error occurred during execution of ‘Worker #3’ component. Execution will be retried (attempt 3 of 10) in 00:00:08 seconds.
2015-01-30 17:12:50.7104 ERROR Error occurred during execution of ‘Server Heartbeat’ component. Execution will be retried (attempt 2 of 10) in 00:00:04 seconds.
2015-01-30 17:12:52.3640 ERROR Error occurred during execution of ‘Worker #5’ component. Execution will be retried (attempt 3 of 10) in 00:00:05 seconds.
2015-01-30 17:12:52.5356 ERROR Error occurred during execution of ‘Worker #2’ component. Execution will be retried (attempt 3 of 10) in 00:00:07 seconds.
2015-01-30 17:12:52.7384 ERROR Error occurred during execution of ‘Worker #4’ component. Execution will be retried (attempt 3 of 10) in 00:00:05 seconds.
2015-01-30 17:12:52.9568 ERROR Error occurred during execution of ‘Schedule Poller’ component. Execution will be retried (attempt 1 of 10) in 00:00:01 seconds.
2015-01-30 17:12:53.1128 ERROR Error occurred during execution of ‘Server Watchdog’ component. Execution will be retried (attempt 3 of 10) in 00:00:04 seconds.
2015-01-30 17:12:53.5184 ERROR Error occurred during execution of ‘Worker #1’ component. Execution will be retried (attempt 3 of 10) in 00:00:04 seconds.
2015-01-30 17:12:54.1424 ERROR Error occurred during execution of ‘Schedule Poller’ component. Execution will be retried (attempt 2 of 10) in 00:00:02 seconds.
2015-01-30 17:12:55.5776 ERROR Error occurred during execution of ‘Server Heartbeat’ component. Execution will be retried (attempt 3 of 10) in 00:00:05 seconds.
2015-01-30 17:12:56.3576 ERROR Error occurred during execution of ‘Schedule Poller’ component. Execution will be retried (attempt 3 of 10) in 00:00:05 seconds.
2015-01-30 17:12:57.2000 ERROR Error occurred during execution of ‘Server Watchdog’ component. Execution will be retried (attempt 4 of 10) in 00:00:10 seconds.
2015-01-30 17:12:57.5744 ERROR Error occurred during execution of ‘Worker #5’ component. Execution will be retried (attempt 4 of 10) in 00:00:16 seconds.
2015-01-30 17:12:57.5744 ERROR Error occurred during execution of ‘Worker #1’ component. Execution will be retried (attempt 4 of 10) in 00:00:09 seconds.
2015-01-30 17:12:57.8084 ERROR Error occurred during execution of ‘Worker #4’ component. Execution will be retried (attempt 4 of 10) in 00:00:14 seconds.
2015-01-30 17:12:59.2124 ERROR Error occurred during execution of ‘Worker #3’ component. Execution will be retried (attempt 4 of 10) in 00:00:13 seconds.
2015-01-30 17:12:59.6180 ERROR Error occurred during execution of ‘Worker #2’ component. Execution will be retried (attempt 4 of 10) in 00:00:13 seconds.
2015-01-30 17:13:15.7952 ERROR Error occurred during execution of ‘Server Heartbeat’ component. Execution will be retried (attempt 4 of 10) in 00:00:14 seconds.
2015-01-30 17:13:15.7952 ERROR Error occurred during execution of ‘Worker #5’ component. Execution will be retried (attempt 5 of 10) in 00:00:21 seconds.
2015-01-30 17:13:16.1384 ERROR Error occurred during execution of ‘Worker #2’ component. Execution will be retried (attempt 5 of 10) in 00:00:17 seconds.
2015-01-30 17:13:16.1384 ERROR Error occurred during execution of ‘Worker #3’ component. Execution will be retried (attempt 5 of 10) in 00:00:25 seconds.
2015-01-30 17:13:16.1384 ERROR Error occurred during execution of ‘Worker #4’ component. Execution will be retried (attempt 5 of 10) in 00:00:18 seconds.
2015-01-30 17:13:16.3412 ERROR Error occurred during execution of ‘Server Watchdog’ component. Execution will be retried (attempt 5 of 10) in 00:00:22 seconds.
2015-01-30 17:13:16.5440 ERROR Error occurred during execution of ‘Worker #1’ component. Execution will be retried (attempt 5 of 10) in 00:00:18 seconds.
2015-01-30 17:13:16.9184 ERROR Error occurred during execution of ‘Schedule Poller’ component. Execution will be retried (attempt 4 of 10) in 00:00:10 seconds.
2015-01-30 17:13:27.0116 ERROR Error occurred during execution of ‘Schedule Poller’ component. Execution will be retried (attempt 5 of 10) in 00:00:24 seconds.
2015-01-30 17:13:30.1472 ERROR Error occurred during execution of ‘Server Heartbeat’ component. Execution will be retried (attempt 5 of 10) in 00:00:24 seconds.
2015-01-30 17:13:33.2828 ERROR Error occurred during execution of ‘Worker #2’ component. Execution will be retried (attempt 6 of 10) in 00:00:26 seconds.
2015-01-30 17:13:34.4684 ERROR Error occurred during execution of ‘Worker #4’ component. Execution will be retried (attempt 6 of 10) in 00:00:29 seconds.
2015-01-30 17:13:34.6712 ERROR Error occurred during execution of ‘Worker #1’ component. Execution will be retried (attempt 6 of 10) in 00:00:26 seconds.
2015-01-30 17:13:52.3928 ERROR Error occurred during execution of ‘Worker #5’ component. Execution will be retried (attempt 6 of 10) in 00:00:27 seconds.
2015-01-30 17:13:52.4084 ERROR Error occurred during execution of ‘Schedule Poller’ component. Execution will be retried (attempt 6 of 10) in 00:00:32 seconds.
2015-01-30 17:13:52.4084 ERROR Error occurred during execution of ‘Worker #3’ component. Execution will be retried (attempt 6 of 10) in 00:00:25 seconds.
2015-01-30 17:13:52.5800 ERROR Error occurred during execution of ‘Server Watchdog’ component. Execution will be retried (attempt 6 of 10) in 00:00:26 seconds.
2015-01-30 17:13:54.3116 ERROR Error occurred during execution of ‘Server Heartbeat’ component. Execution will be retried (attempt 6 of 10) in 00:00:34 seconds.
2015-01-30 17:13:59.4440 ERROR Error occurred during execution of ‘Worker #2’ component. Execution will be retried (attempt 7 of 10) in 00:00:39 seconds.
2015-01-30 17:14:00.8012 ERROR Error occurred during execution of ‘Worker #1’ component. Execution will be retried (attempt 7 of 10) in 00:00:42 seconds.
2015-01-30 17:14:03.7214 ERROR Error occurred during execution of ‘Worker #4’ component. Execution will be retried (attempt 7 of 10) in 00:00:37 seconds.
2015-01-30 17:14:17.6678 ERROR Error occurred during execution of ‘Worker #3’ component. Execution will be retried (attempt 7 of 10) in 00:00:42 seconds.
2015-01-30 17:14:18.8222 ERROR Error occurred during execution of ‘Server Watchdog’ component. Execution will be retried (attempt 7 of 10) in 00:00:37 seconds.
2015-01-30 17:14:19.4150 ERROR Error occurred during execution of ‘Worker #5’ component. Execution will be retried (attempt 7 of 10) in 00:00:44 seconds.
2015-01-30 17:14:24.4538 ERROR Error occurred during execution of ‘Schedule Poller’ component. Execution will be retried (attempt 7 of 10) in 00:00:36 seconds.
2015-01-30 17:14:28.3382 ERROR Error occurred during execution of ‘Server Heartbeat’ component. Execution will be retried (attempt 7 of 10) in 00:00:48 seconds.
2015-01-30 17:14:53.7038 ERROR Error occurred during execution of ‘Worker #2’ component. Execution will be retried (attempt 8 of 10) in 00:00:50 seconds.
2015-01-30 17:14:53.7038 ERROR Error occurred during execution of ‘Worker #1’ component. Execution will be retried (attempt 8 of 10) in 00:00:51 seconds.
2015-01-30 17:14:53.7038 ERROR Error occurred during execution of ‘Worker #4’ component. Execution will be retried (attempt 8 of 10) in 00:00:50 seconds.
2015-01-30 17:14:55.9970 ERROR Error occurred during execution of ‘Server Watchdog’ component. Execution will be retried (attempt 8 of 10) in 00:01:02 seconds.
2015-01-30 17:14:59.6942 ERROR Error occurred during execution of ‘Worker #3’ component. Execution will be retried (attempt 8 of 10) in 00:01:02 seconds.
2015-01-30 17:15:00.3182 ERROR Error occurred during execution of ‘Recurring Job Scheduler’ component. Execution will be retried (attempt 2 of 10) in 00:00:02 seconds.
2015-01-30 17:15:00.7082 ERROR Error occurred during execution of ‘Schedule Poller’ component. Execution will be retried (attempt 8 of 10) in 00:01:02 seconds.
2015-01-30 17:15:03.6098 ERROR Error occurred during execution of ‘Worker #5’ component. Execution will be retried (attempt 8 of 10) in 00:01:04 seconds.
2015-01-30 17:15:16.3706 ERROR Error occurred during execution of ‘Server Heartbeat’ component. Execution will be retried (attempt 8 of 10) in 00:00:52 seconds.
2015-01-30 17:15:43.7048 ERROR Error occurred during execution of ‘Worker #4’ component. Execution will be retried (attempt 9 of 10) in 00:01:04 seconds.
2015-01-30 17:15:43.7048 ERROR Error occurred during execution of ‘Worker #2’ component. Execution will be retried (attempt 9 of 10) in 00:01:06 seconds.
2015-01-30 17:15:44.8392 ERROR Error occurred during execution of ‘Worker #1’ component. Execution will be retried (attempt 9 of 10) in 00:01:12 seconds.
2015-01-30 17:16:36.4456 DEBUG Removing outdated records from table ‘Counter’…
2015-01-30 17:16:36.6484 DEBUG Removing outdated records from table ‘Job’…
2015-01-30 17:16:39.0920 DEBUG Removing outdated records from table ‘List’…
2015-01-30 17:16:39.1076 DEBUG Removing outdated records from table ‘Set’…
2015-01-30 17:16:39.1388 DEBUG Removing outdated records from table ‘Hash’…
2015-01-30 17:18:19.2612 ERROR Error occurred during execution of ‘Server Heartbeat’ component. Execution will be retried (attempt 1 of 10) in 00:00:01 seconds.
2015-01-30 17:18:20.6340 ERROR Error occurred during execution of ‘Server Heartbeat’ component. Execution will be retried (attempt 2 of 10) in 00:00:01 seconds.
2015-01-30 17:18:21.6948 ERROR Error occurred during execution of ‘Server Heartbeat’ component. Execution will be retried (attempt 3 of 10) in 00:00:08 seconds.
2015-01-30 17:18:34.9548 ERROR Error occurred during execution of ‘Schedule Poller’ component. Execution will be retried (attempt 1 of 10) in 00:00:00 seconds.
2015-01-30 17:18:36.0624 ERROR Error occurred during execution of ‘Recurring Job Scheduler’ component. Execution will be retried (attempt 1 of 10) in 00:00:00 seconds.
2015-01-30 17:18:38.6208 FATAL Fatal error occurred during execution of ‘Worker #4’ component. It will be stopped. See the exception for details.
2015-01-30 17:18:45.0012 ERROR Error occurred during execution of ‘Server Heartbeat’ component. Execution will be retried (attempt 4 of 10) in 00:00:15 seconds.
2015-01-30 17:18:45.1572 ERROR Error occurred during execution of ‘Schedule Poller’ component. Execution will be retried (attempt 2 of 10) in 00:00:01 seconds.
2015-01-30 17:18:46.1244 FATAL Fatal error occurred during execution of ‘Worker #1’ component. It will be stopped. See the exception for details.
2015-01-30 17:18:46.3896 ERROR Error occurred during execution of ‘Schedule Poller’ component. Execution will be retried (attempt 3 of 10) in 00:00:04 seconds.
2015-01-30 17:18:46.8108 ERROR Error occurred during execution of ‘Worker #3’ component. Execution will be retried (attempt 9 of 10) in 00:01:14 seconds.
2015-01-30 17:18:50.0088 FATAL Fatal error occurred during execution of ‘Worker #2’ component. It will be stopped. See the exception for details.
2015-01-30 17:18:50.6328 ERROR Error occurred during execution of ‘Schedule Poller’ component. Execution will be retried (attempt 4 of 10) in 00:00:12 seconds.
2015-01-30 17:19:03.6276 ERROR Error occurred during execution of ‘Worker #5’ component. Execution will be retried (attempt 9 of 10) in 00:01:09 seconds.
2015-01-30 17:19:15.9204 ERROR Error occurred during execution of ‘Server Heartbeat’ component. Execution will be retried (attempt 5 of 10) in 00:00:23 seconds.
2015-01-30 17:19:16.2636 ERROR Error occurred during execution of ‘Schedule Poller’ component. Execution will be retried (attempt 5 of 10) in 00:00:24 seconds.
2015-01-30 17:19:54.3744 ERROR Error occurred during execution of ‘Schedule Poller’ component. Execution will be retried (attempt 6 of 10) in 00:00:25 seconds.
2015-01-30 17:19:54.3744 ERROR Error occurred during execution of ‘Server Heartbeat’ component. Execution will be retried (attempt 6 of 10) in 00:00:35 seconds.
2015-01-30 17:20:00.5832 ERROR Error occurred during execution of ‘Recurring Job Scheduler’ component. Execution will be retried (attempt 2 of 10) in 00:00:03 seconds.
2015-01-30 17:20:00.9888 FATAL Fatal error occurred during execution of ‘Worker #3’ component. It will be stopped. See the exception for details.
2015-01-30 17:20:12.7044 FATAL Fatal error occurred during execution of ‘Worker #5’ component. It will be stopped. See the exception for details.
2015-01-30 17:20:19.5216 ERROR Error occurred during execution of ‘Schedule Poller’ component. Execution will be retried (attempt 7 of 10) in 00:00:41 seconds.
2015-01-30 17:20:29.4588 ERROR Error occurred during execution of ‘Server Heartbeat’ component. Execution will be retried (attempt 7 of 10) in 00:00:39 seconds.
2015-01-30 18:16:39.2602 DEBUG Removing outdated records from table ‘Counter’…
2015-01-30 18:16:39.2602 DEBUG Removing outdated records from table ‘Job’…
2015-01-30 18:16:39.2602 DEBUG Removing outdated records from table ‘List’…

Thanks for your help!

2

I am seeing a similar issue. Here is the stack trace.

    2015-02-04 08:22:01.6881;Fatal;Hangfire.Server.AutomaticRetryServerComponentWrapper;Fatal error occurred during execution of 'Recurring Job Scheduler' component. It will be stopped. See the exception for details.;"System.ArgumentNullException: String reference not set to an instance of a String.
Parameter name: s
   at System.Text.Encoding.GetBytes(String s)
   at ServiceStack.Redis.RedisClient.SetRangeInHash(String hashId, IEnumerable`1 keyValuePairs)
   at Hangfire.Server.RecurringJobScheduler.TryScheduleJob(IStorageConnection connection, String recurringJobId, Dictionary`2 recurringJob)
   at Hangfire.Server.RecurringJobScheduler.Execute(CancellationToken cancellationToken)
   at Hangfire.Server.AutomaticRetryServerComponentWrapper.ExecuteWithAutomaticRetry(CancellationToken cancellationToken)
   at Hangfire.Server.ServerSupervisor.ExecuteComponent()
   at Hangfire.Server.ServerSupervisor.RunComponent()"
3

Hi, that is very useful. Your exception very clearly shows where the error in the code is occurring.

Would you kindly tell me how you have configured your logging in order to see the exception detail? When I use Nlog and the “trace” level, I do not see these exceptions.

4

Here is our nlog.config
We have also found out that it is a problem with a job filter

<?xml version="1.0" encoding="utf-8"?>

<nlog autoReload="true" throwExceptions="false" internalLogFile="nlog.log" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
	<targets>
		<target name="Console"
		        xsi:type="ColoredConsole"
		        layout="${level} >> ${message}"
		        errorStream="false" />

		<target name="traceLogger"
		        type="file"
		        fileName="${basedir}/logs/traceLogger.log"
		        concurrentWrites="false"
		        keepFileOpen="false"
		        archiveFileName="${basedir}/logs/archives/traceLogger.{#}.log"
		        archiveEvery="Day"
		        archiveNumbering="Rolling"
		        maxArchiveFiles="1">
			<layout type="CsvLayout">
				<header type="CsvLayout">
					<delimiter>Semicolon</delimiter>
					<quoting>Auto</quoting>
					<column layout="Timestamp" />
				    <column layout="Logger" />
					<column layout="Level" />
					<column layout="Message" />
					<column layout="Stack" />
				</header>
				<delimiter>Semicolon</delimiter>
				<quoting>Auto</quoting>
				<column layout="${longdate:universalTime=true}" />
			    <column layout="${logger}" />
			    <column layout="${level}" />
				<column layout="${message}" />
				<column layout="${stacktrace}" />
			</layout>
		</target>

		<target name="serviceLogger"
		        type="file"
		        fileName="${basedir}/logs/serviceLogger.log"
		        concurrentWrites="false"
		        keepFileOpen="false"
		        archiveFileName="${basedir}/logs/archives/serviceLogger.{#}.log"
		        archiveEvery="Day"
		        archiveNumbering="Rolling"
		        maxArchiveFiles="7">
			<layout type="CsvLayout">
				<header type="CsvLayout">
					<delimiter>Semicolon</delimiter>
					<quoting>Auto</quoting>
					<column layout="Timestamp" />
					<column layout="Level" />
					<column layout="Message" />
					<!--<column layout="Stack" />-->
				</header>
				<delimiter>Semicolon</delimiter>
				<quoting>Auto</quoting>
				<column layout="${longdate:universalTime=true}" />
				<column layout="${level}" />
				<column layout="${message}" />
				<!--<column layout="${stacktrace}" />-->
			</layout>
		</target>

		<target
			name="exceptionLogger"
			type="file"
			fileName="${basedir}/logs/exceptionLogger.log"
			concurrentWrites="false"
			keepFileOpen="false"
			archiveFileName="${basedir}/logs/archives/exceptionLogger.{#}.log"
			archiveEvery="Day"
			archiveNumbering="Rolling"
			maxArchiveFiles="7">
			<layout type="CsvLayout">
				<header type="CsvLayout">
					<delimiter>Semicolon</delimiter>
					<quoting>Auto</quoting>
					<column layout="Timestamp" />
					<column layout="Level" />
					<column layout="Logger" />
					<column layout="Message" />
					<column layout="Exception" />
				</header>
				<delimiter>Semicolon</delimiter>
				<quoting>Auto</quoting>
				<column layout="${longdate:universalTime=true}" />
				<column layout="${level}" />
				<column layout="${logger}" />
				<column layout="${message}" />
				<column layout="${exception:format=tostring}" />
			</layout>
		</target>

	</targets>

	<rules>
		<!-- Note: There is a transformation for debug! -->

		<!-- everything in one log -->
		<!--<logger name="*" writeTo="traceLogger" minLevel="Trace" />-->

		<!-- exceptipons only -->
		<logger name="*" writeTo="exceptionLogger" minLevel="Error" />

		<!-- Analyzer service logs e.g. starting, shutting down, HangFire, etc -->
		<logger name="Hangfire.*" writeTo="serviceLogger" minLevel="Info" />

	</rules>
</nlog>