TIBCO Spotfire Automation Services jobs either get canceled with 'Canceled due to inactivity' status or stuck with the message "Job added to the queue and will be processed when the instance is free"

TIBCO Spotfire Automation Services jobs either get canceled with 'Canceled due to inactivity' status or stuck with the message "Job added to the queue and will be processed when the instance is free"

When multiple TIBCO Spotfire Automation Services jobs are triggered at the same time, some of them may get stuck in the queue with the message: "Job added to the queue and will be processed when the instance is free" but never complete. These jobs will eventually (after 2 or 3 days) have their status changed to "Canceled due to inactivity". It is highly possible that the same job that failed with that error message will be successfully executed on a subsequent attempt.

Here is one such example, where the logs show that when job "a67979fe-1e3f-4945-b5d6-c3d86182c622" is added there is 1 item, but that is not claimed by an Automation Services instance. Then when job "607c6421-bc8b-4b45-9b6b-07f36bf9e291" is added again the number of items is 1 and is not claimed. Then when the job "771c9a40-aa4d-41fb-aa30-588ec9e88a75" is added again the number of items is 1 which is not claimed but eventually gets claimed. After which the queue reported no items remaining in the queue. To summarize, the first two jobs disappeared from the queue and were never claimed.
 

DEBUG 2019-05-02T10:35:28,076-0400 [automation-services-job-a67979fe-1e3f-4945-b5d6-c3d86182c622] scheduler.service.AbstractQueueManager: After adding an item, the number of queued tasks are 1
DEBUG 2019-05-02T10:35:28,077-0400 [automation-services-job-a67979fe-1e3f-4945-b5d6-c3d86182c622] scheduler.service.AbstractQueueManager: A new job with id a67979fe-1e3f-4945-b5d6-c3d86182c622 and task id 3b9a597c-2e2a-4f6c-a0c7-9dc2504f6d26 for lib item 00000000-0000-0000-0000-000000000000 and destination https://nm.chapelhill.local:9501/1f9c0c65-781c-48a2-878f-36058e359687 added to the queue with key AUTOMATION_SERVICES 
INFO 2019-05-02T10:35:28,078-0400 [scheduled-jobs-queue-processor] scheduler.service.QueueProcessor: Processing the queued tasks with capability AUTOMATION_SERVICES for services [https://nm.chapelhill.local:9501/1f9c0c65-781c-48a2-878f-36058e359687] 
DEBUG 2019-05-02T10:35:28,079-0400 [scheduled-jobs-queue-processor] scheduler.service.AbstractQueueManager: Service 1f9c0c65-781c-48a2-878f-36058e359687 is busy, none of 1 items matching this destination were claimed
DEBUG 2019-05-02T10:35:28,083-0400 [automation-services-job-607c6421-bc8b-4b45-9b6b-07f36bf9e291] scheduler.service.AbstractQueueManager: After adding an item, the number of queued tasks are 1
DEBUG 2019-05-02T10:35:28,083-0400 [automation-services-job-607c6421-bc8b-4b45-9b6b-07f36bf9e291] scheduler.service.AbstractQueueManager: A new job with id 607c6421-bc8b-4b45-9b6b-07f36bf9e291 and task id 393eedd3-9a8e-4569-b1d6-45dea24d9102 for lib item 00000000-0000-0000-0000-000000000000 and destination https://nm.chapelhill.local:9501/1f9c0c65-781c-48a2-878f-36058e359687 added to the queue with key AUTOMATION_SERVICES 
INFO 2019-05-02T10:35:28,084-0400 [scheduled-jobs-queue-processor] scheduler.service.QueueProcessor: Processing the queued tasks with capability AUTOMATION_SERVICES for services [https://nm.chapelhill.local:9501/1f9c0c65-781c-48a2-878f-36058e359687] 
DEBUG 2019-05-02T10:35:28,095-0400 [automation-services-job-771c9a40-aa4d-41fb-aa30-588ec9e88a75] scheduler.service.AbstractQueueManager: After adding an item, the number of queued tasks are 1
DEBUG 2019-05-02T10:35:28,095-0400 [automation-services-job-771c9a40-aa4d-41fb-aa30-588ec9e88a75] scheduler.service.AbstractQueueManager: A new job with id 771c9a40-aa4d-41fb-aa30-588ec9e88a75 and task id e384b0c8-9ee4-40cc-b26c-1a61a2a23745 for lib item 00000000-0000-0000-0000-000000000000 and destination https://nm.chapelhill.local:9501/1f9c0c65-781c-48a2-878f-36058e359687 added to the queue with key AUTOMATION_SERVICES 
INFO 2019-05-02T10:35:28,095-0400 [scheduled-jobs-queue-processor] scheduler.service.QueueProcessor: Processing the queued tasks with capability AUTOMATION_SERVICES for services [https://nm.chapelhill.local:9501/1f9c0c65-781c-48a2-878f-36058e359687] 
DEBUG 2019-05-02T10:35:28,096-0400 [scheduled-jobs-queue-processor] scheduler.service.AbstractQueueManager: Service 1f9c0c65-781c-48a2-878f-36058e359687 is busy, none of 1 items matching this destination were claimed
DEBUG 2019-05-02T10:35:38,666-0400 [scheduled-jobs-queue-processor] scheduler.service.AbstractQueueManager: 1 item(s) of 1 are claimed for destination https://nm.chapelhill.local:9501/1f9c0c65-781c-48a2-878f-36058e359687 with available capacity 2 by the server 2f89063e-7c68-4683-a34e-c431c336c248
DEBUG 2019-05-02T10:35:38,666-0400 [scheduled-jobs-queue-processor] scheduler.service.AbstractQueueManager: No items remaining in the queue to be claimed with key AUTOMATION_SERVICES

  The cause of this issue is that some of the items in the schedule queue may disappear from the queue without ever being processed and these are the items that are canceled eventually within 2-3 days. 

This is a known defect which has been addressed in TIBCO Spotfire Server 10.3.2 and higher.