Error deserializing JobKey when deleting trigger

[jsmorris]

I received the following error

ReadStartDocument can only be called when CurrentBsonType is Document, not when CurrentBsonType is Boolean.

at line 20 (var bsonType = bsonReader.CurrentBsonType;) in the JobKeySerializer class.

After debugging into the code, I cannot figure out how it gets past the if (bsonType == BsonType.Document) check.

The stack trace is

Quartz.Impl.MongoDB.dll!Quartz.Impl.MongoDB.JobKeySerializer.Deserialize(MongoDB.Bson.IO.BsonReader bsonReader = {MongoDB.Bson.IO.BsonBinaryReader}, System.Type nominalType = {Name = "JobKey" FullName = "Quartz.JobKey"}, System.Type actualType = {Name = "JobKey" FullName = "Quartz.JobKey"}, MongoDB.Bson.Serialization.IBsonSerializationOptions options = null) Line 14    C#
Quartz.Impl.MongoDB.dll!Quartz.Impl.MongoDB.JobKeySerializer.Deserialize(MongoDB.Bson.IO.BsonReader bsonReader = {MongoDB.Bson.IO.BsonBinaryReader}, System.Type nominalType = {Name = "JobKey" FullName = "Quartz.JobKey"}, MongoDB.Bson.Serialization.IBsonSerializationOptions options = null) Line 55 + 0x14 bytes  C#
[External Code]
Quartz.Impl.MongoDB.dll!Quartz.Impl.MongoDB.JobDetailImplSerializer.Deserialize(MongoDB.Bson.IO.BsonReader bsonReader = {MongoDB.Bson.IO.BsonBinaryReader}, System.Type nominalType = {Name = "IJobDetail" FullName = "Quartz.IJobDetail"}, System.Type actualType = {Name = "JobDetailImpl" FullName = "Quartz.Impl.JobDetailImpl"}, MongoDB.Bson.Serialization.IBsonSerializationOptions options = null) Line 26 + 0x3e bytes C#
[External Code]
Quartz.Impl.MongoDB.dll!Quartz.Impl.MongoDB.JobStore.RetrieveJob(Quartz.JobKey jobKey = {Quartz.JobKey}) Line 693 + 0x39 bytes  C#
Quartz.Impl.MongoDB.dll!Quartz.Impl.MongoDB.JobStore.RemoveTrigger(Quartz.TriggerKey key = {Quartz.TriggerKey}, bool removeOrphanedJob = true) Line 624 + 0x26 bytes    C#
Quartz.Impl.MongoDB.dll!Quartz.Impl.MongoDB.JobStore.RemoveTrigger(Quartz.TriggerKey triggerKey = {Quartz.TriggerKey}) Line 545 + 0xf bytes C#
Quartz.Impl.MongoDB.dll!Quartz.Impl.MongoDB.JobStore.TriggeredJobComplete(Quartz.Spi.IOperableTrigger trigger = {Quartz.Impl.Triggers.SimpleTriggerImpl}, Quartz.IJobDetail jobDetail = {Quartz.Impl.JobDetailImpl}, Quartz.SchedulerInstruction triggerInstCode = DeleteTrigger) Line 1663 + 0x2c bytes    C#
Quartz.dll!Quartz.Core.QuartzScheduler.NotifyJobStoreJobComplete(Quartz.Spi.IOperableTrigger trigger = {Quartz.Impl.Triggers.SimpleTriggerImpl}, Quartz.IJobDetail detail = {Quartz.Impl.JobDetailImpl}, Quartz.SchedulerInstruction instCode = DeleteTrigger) Line 1638    C#
Quartz.dll!Quartz.Core.JobRunShell.Run() Line 281 + 0x2c bytes  C#    
Quartz.dll!Quartz.Simpl.SimpleThreadPool.WorkerThread.Run() Line 475 + 0xc bytes    C#
[External Code] 

The JSON of the job it is deserializing is

{
    "Durable" : false,
    "Group" : "XMLSchedulingDataProcessorPlugin",
    "JobDataMap" : {
        "FILE_NAME" : "C:\\projects\\cost\\ccsd-trax.git\\Web\\quartz_jobs.xml",
        "FILE_SCAN_LISTENER_NAME" : "XMLSchedulingDataProcessorPlugin_xml",
        "LAST_MODIFIED_TIME" : ISODate("2013-06-04T20:26:37Z")
    },
    "Name" : "XMLSchedulingDataProcessorPlugin_xml_quartz_jobs_xml",
    "RequestRecovery" : false,
    "_assembly" : "Quartz, Version=2.1.2.400, Culture=neutral, PublicKeyToken=f6b8c98a402cc8a4",
    "_class" : "Quartz.Job.FileScanJob",
    "_id" : {
        "Name" : "XMLSchedulingDataProcessorPlugin_xml_quartz_jobs_xml",
        "Group" : "XMLSchedulingDataProcessorPlugin"
    },
    "_t" : "JobDetailImpl"
}

The log output is

INFO 7 Quartz.Impl.StdSchedulerFactory - Using default implementation for object serializer
INFO 7 Quartz.Impl.StdSchedulerFactory - Using default implementation for ThreadExecutor
INFO 7 Quartz.Core.SchedulerSignalerImpl - Initialized Scheduler Signaller of type: Quartz.Core.SchedulerSignalerImpl
INFO 7 Quartz.Core.QuartzScheduler - Quartz Scheduler v.2.1.2.400 created.
INFO 7 Quartz.Plugin.Xml.XMLSchedulingDataProcessorPlugin - Registering Quartz Job Initialization Plug-in.
INFO 7 Quartz.Impl.MongoDB.JobStore - MongoDB JobStore initialized.
INFO 7 Quartz.Core.QuartzScheduler - Scheduler meta-data: Quartz Scheduler (v2.1.2.400) 'XmlConfiguredInstance' with instanceId 'NON_CLUSTERED'
  Scheduler class: 'Quartz.Core.QuartzScheduler' - running locally.
  NOT STARTED.
  Currently in standby mode.
  Number of jobs executed: 0
  Using thread pool 'Quartz.Simpl.SimpleThreadPool' - with 5 threads.
  Using job-store 'Quartz.Impl.MongoDB.JobStore' - which supports persistence. and is clustered.

INFO 7 Quartz.Impl.StdSchedulerFactory - Quartz scheduler 'XmlConfiguredInstance' initialized
INFO 7 Quartz.Impl.StdSchedulerFactory - Quartz scheduler version: 2.1.2.400
INFO 7 Quartz.Core.QuartzScheduler - JobFactory set to: Castle.Facilities.QuartzIntegration.WindsorJobFactory
INFO 7 Quartz.Core.QuartzScheduler - JobFactory set to: Castle.Facilities.QuartzIntegration.WindsorJobFactory
DEBUG 7 Quartz.Plugin.Xml.XMLSchedulingDataProcessorPlugin - Scheduled file scan job for data file: ~/quartz_jobs.xml, at interval: 00:00:10
INFO 7 Quartz.Xml.XMLSchedulingDataProcessor - Parsing XML file: C:\projects\cost\ccsd-trax.git\Web\quartz_jobs.xml with systemId: ~/quartz_jobs.xml
DEBUG 7 Quartz.Xml.XMLSchedulingDataProcessor - Found 0 delete job group commands.
DEBUG 7 Quartz.Xml.XMLSchedulingDataProcessor - Found 0 delete trigger group commands.
DEBUG 7 Quartz.Xml.XMLSchedulingDataProcessor - Found 0 delete job commands.
DEBUG 7 Quartz.Xml.XMLSchedulingDataProcessor - Found 0 delete trigger commands.
DEBUG 7 Quartz.Xml.XMLSchedulingDataProcessor - Directive 'overwrite-existing-data' specified as: True
DEBUG 7 Quartz.Xml.XMLSchedulingDataProcessor - Directive 'ignore-duplicates' specified as: False
DEBUG 7 Quartz.Xml.XMLSchedulingDataProcessor - Directive 'schedule-trigger-relative-to-replaced-trigger' specified as: False
DEBUG 7 Quartz.Xml.XMLSchedulingDataProcessor - Found 1 job definitions.
DEBUG 7 Quartz.Xml.XMLSchedulingDataProcessor - Parsed job definition: JobDetail 'DEFAULT.hello-world':  jobType: 'xxxxx.xxx.Jobs.SampleJob persistJobDataAfterExecution: False concurrentExectionDisallowed: False isDurable: True requestsRecovers: True
DEBUG 7 Quartz.Xml.XMLSchedulingDataProcessor - Found 1 trigger definitions.
DEBUG 7 Quartz.Xml.XMLSchedulingDataProcessor - Parsed trigger definition: Trigger 'DEFAULT.sample-trigger':  triggerClass: 'Quartz.Impl.Triggers.SimpleTriggerImpl calendar: '' misfireInstruction: 0 nextFireTime: 
INFO 7 Quartz.Xml.XMLSchedulingDataProcessor - Adding 1 jobs, 1 triggers.
INFO 7 Quartz.Xml.XMLSchedulingDataProcessor - Adding job: DEFAULT.hello-world
DEBUG 7 Quartz.Xml.XMLSchedulingDataProcessor - Scheduling job: DEFAULT.hello-world with trigger: DEFAULT.sample-trigger
INFO 7 Quartz.Core.QuartzScheduler - Scheduler XmlConfiguredInstance_$_NON_CLUSTERED started.
INFO XmlConfiguredInstance_QuartzSchedulerThread xxxxx.xxx.Jobs.GlobalTriggerListener - Global trigger listener.TriggerMisfired
INFO XmlConfiguredInstance_QuartzSchedulerThread xxxxx.xxx.Jobs.SampleTriggerListener - SampleTriggerListener.TriggerMisfired
DEBUG XmlConfiguredInstance_QuartzSchedulerThread Quartz.Core.QuartzSchedulerThread - Batch acquisition of 1 triggers
INFO XmlConfiguredInstance_QuartzSchedulerThread xxxxx.xxx.Jobs.GlobalTriggerListener - Global trigger listener.TriggerMisfired
INFO XmlConfiguredInstance_QuartzSchedulerThread xxxxx.xxx.Jobs.SampleTriggerListener - SampleTriggerListener.TriggerMisfired
INFO XmlConfiguredInstance_Worker-1 xxxxx.xxx.Jobs.GlobalTriggerListener - Global trigger listener.TriggerFired
INFO XmlConfiguredInstance_Worker-1 xxxxx.xxx.Jobs.GlobalTriggerListener - Global trigger listener.VetoJobExecution
INFO XmlConfiguredInstance_Worker-1 xxxxx.xxx.Jobs.SampleTriggerListener - SampleTriggerListener.TriggerFired
INFO XmlConfiguredInstance_Worker-1 xxxxx.xxx.Jobs.SampleTriggerListener - SampleTriggerListener.VetoJobExecution
INFO XmlConfiguredInstance_Worker-1 xxxxx.xxx.Jobs.GlobalJobListener - Global job listener.JobToBeExecuted
INFO XmlConfiguredInstance_Worker-1 xxxxx.xxx.Jobs.SampleJobListener - SampleJobListener.JobToBeExecuted
DEBUG XmlConfiguredInstance_Worker-1 Quartz.Core.JobRunShell - Calling Execute on job DEFAULT.hello-world
INFO XmlConfiguredInstance_Worker-1 xxxxx.xxx.Jobs.SampleJob - Hello world!
INFO XmlConfiguredInstance_Worker-1 xxxxx.xxx.Jobs.GlobalJobListener - Global job listener.JobWasExecuted
INFO XmlConfiguredInstance_Worker-1 xxxxx.xxx.Jobs.SampleJobListener - SampleJobListener.JobWasExecuted
DEBUG XmlConfiguredInstance_Worker-1 Quartz.Core.JobRunShell - Trigger instruction : DeleteTrigger
INFO XmlConfiguredInstance_Worker-1 xxxxx.xxx.Jobs.GlobalTriggerListener - Global trigger listener.TriggerComplete
INFO XmlConfiguredInstance_Worker-1 xxxxx.xxx.Jobs.SampleTriggerListener - SampleTriggerListener.TriggerComplete
DEBUG XmlConfiguredInstance_QuartzSchedulerThread Quartz.Core.QuartzSchedulerThread - Batch acquisition of 1 triggers
DEBUG XmlConfiguredInstance_Worker-1 Quartz.Impl.MongoDB.JobStore - Deleting trigger
INFO XmlConfiguredInstance_Worker-2 xxxxx.xxx.Jobs.GlobalTriggerListener - Global trigger listener.TriggerFired
INFO XmlConfiguredInstance_Worker-2 xxxxx.xxx.Jobs.GlobalTriggerListener - Global trigger listener.VetoJobExecution
INFO XmlConfiguredInstance_Worker-2 xxxxx.xxx.Jobs.SampleTriggerListener - SampleTriggerListener.TriggerFired
INFO XmlConfiguredInstance_Worker-2 xxxxx.xxx.Jobs.SampleTriggerListener - SampleTriggerListener.VetoJobExecution
INFO XmlConfiguredInstance_Worker-2 xxxxx.xxx.Jobs.GlobalJobListener - Global job listener.JobToBeExecuted
INFO XmlConfiguredInstance_Worker-2 xxxxx.xxx.Jobs.SampleJobListener - SampleJobListener.JobToBeExecuted
DEBUG XmlConfiguredInstance_Worker-2 Quartz.Core.JobRunShell - Calling Execute on job XMLSchedulingDataProcessorPlugin.XMLSchedulingDataProcessorPlugin_xml_quartz_jobs_xml
DEBUG XmlConfiguredInstance_QuartzSchedulerThread Quartz.Core.QuartzSchedulerThread - Batch acquisition of 0 triggers
DEBUG XmlConfiguredInstance_Worker-2 Quartz.Job.FileScanJob - File 'C:\projects\cost\ccsd-trax.git\Web\quartz_jobs.xml' unchanged.
INFO XmlConfiguredInstance_Worker-2 xxxxx.xxx.Jobs.GlobalJobListener - Global job listener.JobWasExecuted
INFO XmlConfiguredInstance_Worker-2 xxxxx.xxx.Jobs.SampleJobListener - SampleJobListener.JobWasExecuted
DEBUG XmlConfiguredInstance_Worker-2 Quartz.Core.JobRunShell - Trigger instruction : DeleteTrigger
INFO XmlConfiguredInstance_Worker-2 xxxxx.xxx.Jobs.GlobalTriggerListener - Global trigger listener.TriggerComplete
INFO XmlConfiguredInstance_Worker-2 xxxxx.xxx.Jobs.SampleTriggerListener - SampleTriggerListener.TriggerComplete
DEBUG XmlConfiguredInstance_Worker-2 Quartz.Impl.MongoDB.JobStore - Deleting trigger

The quartz_jobs.xml file

<?xml version="1.0" encoding="utf-8" ?>
<job-scheduling-data xmlns="http://quartznet.sourceforge.net/JobSchedulingData" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" version="2.0">

  <processing-directives>
    <overwrite-existing-data>true</overwrite-existing-data>
  </processing-directives>

  <schedule>
    <job>
      <name>hello-world</name>
      <job-type>xxxxx.xxx.Jobs.SampleJob, xxxxx.xxx.Jobs</job-type>
      <durable>true</durable>
      <recover>true</recover>
    </job>
    <trigger>
      <simple>
        <name>sample-trigger</name>
        <job-name>hello-world</job-name>
        <start-time>1982-06-28T12:24:00.0Z</start-time>
        <repeat-count>-1</repeat-count>
        <repeat-interval>2000</repeat-interval> <!-- 2 seconds -->
      </simple>
    </trigger>
  </schedule>
</job-scheduling-data>

[jsmorris]

After more debugging, I think the problem is in the JobDetailImplSerializer.Deserialize(...) method.

My two jobs in the Jobs collection look like this

/* 0 */
{
    "_id" : {
        "Name" : "hello-world",
        "Group" : "DEFAULT"
    },
    "_t" : "JobDetailImpl",
    "_assembly" : "Intel.TraX.Jobs, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null",
    "_class" : "xxxxx.xxxx.Jobs.SampleJob",
    "Name" : "hello-world",
    "Group" : "DEFAULT",
    "RequestRecovery" : true,
    "Durable" : true,
    "JobDataMap" : {}
}

/* 1 */
{
    "Durable" : false,
    "Group" : "XMLSchedulingDataProcessorPlugin",
    "JobDataMap" : {
        "FILE_NAME" : "C:\\projects\\cost\\ccsd-trax.git\\Web\\quartz_jobs.xml",
        "FILE_SCAN_LISTENER_NAME" : "XMLSchedulingDataProcessorPlugin_xml",
        "LAST_MODIFIED_TIME" : ISODate("2013-06-04T20:26:37Z")
    },
    "Name" : "XMLSchedulingDataProcessorPlugin_xml_quartz_jobs_xml",
    "RequestRecovery" : false,
    "_assembly" : "Quartz, Version=2.1.2.400, Culture=neutral, PublicKeyToken=f6b8c98a402cc8a4",
    "_class" : "Quartz.Job.FileScanJob",
    "_id" : {
        "Name" : "XMLSchedulingDataProcessorPlugin_xml_quartz_jobs_xml",
        "Group" : "XMLSchedulingDataProcessorPlugin"
    },
    "_t" : "JobDetailImpl"
}

I get the error, when the /* 1 */ job is deserialized. I think the deserialization is order dependent and having Durable field first, causes the error.

[cppmyjob]

Hi
Regarding the next links http://stackoverflow.com/questions/5046835/mongodb-field-order-and-document-position-change-after-update and https://jira.mongodb.org/browse/SERVER-2592, updating of a job may lead to reordering fields in mongo document and it leads to the problem.

I fixed it for my case (i used [PersistJobDataAfterExecution] attribute) via updating whole document

                if (jobDetail.PersistJobDataAfterExecution)
                {
                    this.Jobs.Update(
                        Query.EQ("_id", jobDetail.Key.ToBsonDocument()), Update.Replace(jobDetail.ToBsonDocument()));
                }

instead of

                if (jobDetail.PersistJobDataAfterExecution)
                {
                    this.Jobs.Update(
                        Query.EQ("_id", jobDetail.Key.ToBsonDocument()),
                        Update.Set("JobDataMap", jobDetail.JobDataMap.ToBsonDocument()));
                }

in JobStore Class

I am afraid for there is another place with the same behavior..... :(

Thank you
Pavel