We upgraded to version 5.7.4 and we noticed in the visualcron logs that the job that is not supposed to run if it is already running, is starting tasks at the same time.

5/19/2011 7:30:08 AM Info Task started: Copy_and_Delete_trn_Files (41363)
5/19/2011 7:30:08 AM Info Task started: Copy_and_Delete_trn_Files (41364)

Is this is a known issue? Any fixes planned for this?

Thanks!
DevonWay Operations

Hi devonway,

Does the task really runs twice or is the log writing a double (faulty) entry here?

Regards,
Erik

---

It does not seem like a double entry as the internal Task process id is different. My questions are:

* Is the Task only running twice or the whole Job? (do you have double lines for Job as well)? I mean, it could be some kind of condition or error flow.
* what kind of Trigger do you use?
* If file Trigger - have you set it to "Put Job in queue"?

---

Hi Erik,

The task is actually running since we get error notifications and see errors in the log as well:

5/19/2011 7:30:08 AM Info Task started: Copy_and_Delete_trn_Files (41363)
5/19/2011 7:30:08 AM Info Task started: Copy_and_Delete_trn_Files (41364)
5/19/2011 7:30:08 AM Err Exception in Task: The process cannot access the file 'test.zip' because it is being used by another process.
5/19/2011 7:30:08 AM Err Exception in Task: The process cannot access the file 'test.zip' because it is being used by another process.
5/19/2011 7:30:08 AM Err Exception in Task: No files copied
5/19/2011 7:30:08 AM Info Task completed: Copy_and_Delete_trn_Files (41364)

The 41364 task completes properly, but 41363 gives the above error. The job is copying files from one server to another.

Thanks,
DevonWay Operations

Hi Erik,

The job is also running:

Line 239: 5/19/2011 12:30:01 AM Info Job started: Prod_DBA_Maint_DB2_004A_Copy_15Min_trn_Bkup_To_DR2
Line 289: 5/19/2011 12:30:03 AM Info Job started: Prod_DBA_Maint_DB2_004A_Copy_15Min_trn_Bkup_To_DR2
Line 339: 5/19/2011 12:30:04 AM Info Job started: Prod_DBA_Maint_DB2_004A_Copy_15Min_trn_Bkup_To_DR2
Line 356: 5/19/2011 12:30:04 AM Info Job started: Prod_DBA_Maint_DB2_004A_Copy_15Min_trn_Bkup_To_DR2
Line 395: 5/19/2011 12:30:12 AM Info Job started: Prod_DBA_Maint_DB2_004A_Copy_15Min_trn_Bkup_To_DR2
Line 444: 5/19/2011 12:30:27 AM Info Job started: Prod_DBA_Maint_DB2_004A_Copy_15Min_trn_Bkup_To_DR2
Line 459: 5/19/2011 12:30:31 AM Info Job started:

On the main job settings tab, we have "Do no run job is it running", "Put job in queue", "Run tasks in order". The task has a condition but does not have Retry on Error. The condition also does not have retry in it.

We are using a File Arrive trigger.

1. have you set "Filename" only and "Wait until file has been released" in file trigger settings?

2. do you have a matching log for the two tasks and the Jobs? I mean, that we can see that the Jobs were run twice at 07:08. In the last job list there are some seconds between each Job and in your Tasks it is the same second.

---

Hi Henrik,

1] The trigger is using a file mask like "*.trn.zip", "Include subfolders", "Trigger when file has been released", "On error reconnect attempts 3" , "timeout of 2 hours".
File/folder watch type is "Created" only. Notify filters is "File Name" only.

2] Matching log:

5/19/2011 7:30:08 AM Info Job started: Prod_DBA_Maint_DB2_004A_Copy_15Min_trn_Bkup_To_DR2
5/19/2011 7:30:08 AM Info Job started: Prod_DBA_Maint_DB2_004A_Copy_15Min_trn_Bkup_To_DR2
5/19/2011 7:30:08 AM Info Job started: Prod_DBA_Maint_DB2_003C_FileArrive_Zip_Log_to_d_TempFilestoDR2
5/19/2011 7:30:08 AM Debug Running Condition Set: 'Check if any.zip files exist' for Job: Prod_DBA_Maint_DB2_004A_Copy_15Min_trn_Bkup_To_DR2
5/19/2011 7:30:08 AM Info Task: ***Job Notes*** (See SQL Tab) (inactive) was skipped because it was inactive.
5/19/2011 7:30:08 AM Debug Running Condition Set: 'Check if any.zip files exist' for Job: Prod_DBA_Maint_DB2_004A_Copy_15Min_trn_Bkup_To_DR2
5/19/2011 7:30:08 AM Debug File Condition (FileExist->MatchTrue) returned: Match
5/19/2011 7:30:08 AM Info Task started: Zip_File_In_Place_D_MSSQL (41360)
5/19/2011 7:30:08 AM Debug File Condition (FileExist->MatchTrue) returned: Match
5/19/2011 7:30:08 AM Info Job completed: Prod_DBA_Maint_DB2_004A_Copy_15Min_trn_Bkup_To_DR2
5/19/2011 7:30:08 AM Debug Condition Set (Job) returned: MatchAll-> ActionContinue
5/19/2011 7:30:08 AM Debug Condition Set (Job) returned: MatchAll-> ActionContinue
5/19/2011 7:30:08 AM Info Task: ***Job Notes*** (see SQL tab) (inactive) was skipped because it was inactive.
5/19/2011 7:30:08 AM Info Task: ***Job Notes*** (see SQL tab) (inactive) was skipped because it was inactive.
5/19/2011 7:30:08 AM Info Task started: Delete_Recycler_D_trn_Files inactive (41362)
5/19/2011 7:30:08 AM Info Task started: Delete_Recycler_D_trn_Files inactive (41362)
5/19/2011 7:30:08 AM Info Task started: Delete_Recycler_D_trn_Files inactive (41361)
5/19/2011 7:30:08 AM Info Impersonation result: True
5/19/2011 7:30:08 AM Info Impersonation result: True
5/19/2011 7:30:08 AM Info Task completed: Delete_Recycler_D_trn_Files inactive (41362)
5/19/2011 7:30:08 AM Info Task completed: Delete_Recycler_D_trn_Files inactive (41361)
5/19/2011 7:30:08 AM Debug Running Condition Set: 'Check if any *trn.zip files exist' for Task: Copy_and_Delete_trn_Files
5/19/2011 7:30:08 AM Debug Running Condition Set: 'Check if any *trn.zip files exist' for Task: Copy_and_Delete_trn_Files
5/19/2011 7:30:08 AM Debug File Condition (FileExist->MatchTrue) returned: Match
5/19/2011 7:30:08 AM Debug File Condition (FileExist->MatchTrue) returned: Match
5/19/2011 7:30:08 AM Debug Condition Set (Task) returned: MatchAll-> ActionContinue
5/19/2011 7:30:08 AM Debug Condition Set (Task) returned: MatchAll-> ActionContinue
5/19/2011 7:30:08 AM Info Task started: Copy_and_Delete_trn_Files (41363)
5/19/2011 7:30:08 AM Info Task started: Copy_and_Delete_trn_Files (41364)
5/19/2011 7:30:08 AM Info Task completed: Zip_File_In_Place_D_MSSQL (41360)
5/19/2011 7:30:08 AM Info Task started: Zip_n_Split_2GB_Chunks_to_D_TempFilestoDR2 (41365)
5/19/2011 7:30:08 AM Info Task completed: Zip_n_Split_2GB_Chunks_to_D_TempFilestoDR2 (41365)
5/19/2011 7:30:08 AM Info Job completed: Prod_DBA_Maint_DB2_003C_FileArrive_Zip_Log_to_d_TempFilestoDR2
5/19/2011 7:30:08 AM Err Exception in Task: The process cannot access the file 'D:\testfolder\test.trn.zip' because it is being used by another process.
5/19/2011 7:30:08 AM Err Exception in Task: The process cannot access the file 'D:\testfolder\test.trn.zip' because it is being used by another process.
5/19/2011 7:30:08 AM Err Exception in Task: No files copied
5/19/2011 7:30:08 AM Info Task completed: Copy_and_Delete_trn_Files (41364)
5/19/2011 7:30:09 AM Info Job started: Prod_DBA_Maint_DB2_003C_FileArrive_Zip_Log_to_d_TempFilestoDR2
5/19/2011 7:30:09 AM Info Task: ***Job Notes*** (See SQL Tab) (inactive) was skipped because it was inactive.
5/19/2011 7:30:09 AM Info Task started: Zip_File_In_Place_D_MSSQL (41366)
5/19/2011 7:30:09 AM Debug Running Email Notification: '**New**Email OpsAlert -- Log Backup FileCopy From DB2 to DR2'
5/19/2011 7:30:09 AM Debug Running Email Notification: 'DBAOnCall'
5/19/2011 7:30:09 AM Info Job completed: Prod_DBA_Maint_DB2_004A_Copy_15Min_trn_Bkup_To_DR2


In the above log, Prod_DBA_Maint_DB2_004A_Copy_15Min_trn_Bkup_To_DR2 is the name of the job that is causing problems and the tasks are:
1.***Job Notes*** (see SQL tab) (inactive)
2.Delete_Recycler_D_trn_Files inactive
3.Copy_and_Delete_trn_Files

1. can you reproduce this every time with this job?
2. what if you create a new (blank) job - same result?

---

1. This job executes about 12 times every hour. It fails 3 times a day and when it fails, it will send about 10 or so error notifications. Not reproducible in each run.

2. I will work on a setting up a blank job and get back with results.

Reproducible in the test job:

5/20/2011 1:00:41 PM Info Job started: Test_DBA_Maint_DB2_004B_Copy_15Min_trn_Bkup_To_DR2
5/20/2011 1:00:41 PM Info Task: ***Job Notes*** (see SQL tab) (inactive) was skipped because it was inactive.
5/20/2011 1:00:41 PM Info Task: Delete_Recycler_D_trn_Files inactive was skipped because it was inactive.
5/20/2011 1:00:41 PM Info Task started: Copy_and_Delete_trn_Files (5)
5/20/2011 1:00:41 PM Info Task completed: Copy_and_Delete_trn_Files (5)
5/20/2011 1:00:41 PM Err File was not found when checking for file release in Trigger. Already moved?
5/20/2011 1:00:41 PM Info Job started: Test_DBA_Maint_DB2_004B_Copy_15Min_trn_Bkup_To_DR2
5/20/2011 1:00:41 PM Info Task: ***Job Notes*** (see SQL tab) (inactive) was skipped because it was inactive.
5/20/2011 1:00:41 PM Info Task: Delete_Recycler_D_trn_Files inactive was skipped because it was inactive.
5/20/2011 1:00:41 PM Info Task started: Copy_and_Delete_trn_Files (6)
5/20/2011 1:00:41 PM Info Job completed: Test_DBA_Maint_DB2_004B_Copy_15Min_trn_Bkup_To_DR2
5/20/2011 1:00:42 PM Err Exception in Task: No files copied
5/20/2011 1:00:42 PM Info Task completed: Copy_and_Delete_trn_Files (6)
5/20/2011 1:00:42 PM Err File was not found when checking for file release in Trigger. Already moved?
5/20/2011 1:00:42 PM Debug Running Email Notification: 'Opsalert'
5/20/2011 1:00:42 PM Info Job completed: Test_DBA_Maint_DB2_004B_Copy_15Min_trn_Bkup_To_DR2
5/20/2011 1:00:42 PM Err File was not found when checking for file release in Trigger. Already moved?
5/20/2011 1:00:42 PM Info Job started: Test_DBA_Maint_DB2_004B_Copy_15Min_trn_Bkup_To_DR2
5/20/2011 1:00:42 PM Err Email verification error: Unable to send email. Enter the missing SMTP settings/values in the settings menu.
5/20/2011 1:00:42 PM Info Task: ***Job Notes*** (see SQL tab) (inactive) was skipped because it was inactive.
5/20/2011 1:00:42 PM Info Task: Delete_Recycler_D_trn_Files inactive was skipped because it was inactive.
5/20/2011 1:00:42 PM Info Task started: Copy_and_Delete_trn_Files (7)
5/20/2011 1:00:42 PM Err Exception in Task: No files copied
5/20/2011 1:00:42 PM Info Task completed: Copy_and_Delete_trn_Files (7)
5/20/2011 1:00:42 PM Err File was not found when checking for file release in Trigger. Already moved?
5/20/2011 1:00:42 PM Info Job started: Test_DBA_Maint_DB2_004B_Copy_15Min_trn_Bkup_To_DR2
5/20/2011 1:00:42 PM Info Task: ***Job Notes*** (see SQL tab) (inactive) was skipped because it was inactive.
5/20/2011 1:00:42 PM Info Task: Delete_Recycler_D_trn_Files inactive was skipped because it was inactive.
5/20/2011 1:00:43 PM Debug Running Email Notification: 'Opsalert'
5/20/2011 1:00:43 PM Info Task started: Copy_and_Delete_trn_Files (8)
5/20/2011 1:00:43 PM Err File was not found when checking for file release in Trigger. Already moved?
5/20/2011 1:00:43 PM Err Email verification error: Unable to send email. Enter the missing SMTP settings/values in the settings menu.
5/20/2011 1:00:43 PM Info Job completed: Test_DBA_Maint_DB2_004B_Copy_15Min_trn_Bkup_To_DR2
5/20/2011 1:00:43 PM Err Exception in Task: No files copied
5/20/2011 1:00:43 PM Info Task completed: Copy_and_Delete_trn_Files (8)
5/20/2011 1:00:43 PM Err File was not found when checking for file release in Trigger. Already moved?
5/20/2011 1:00:43 PM Info Job started: Test_DBA_Maint_DB2_004B_Copy_15Min_trn_Bkup_To_DR2
5/20/2011 1:00:43 PM Debug Running Email Notification: 'Opsalert'
5/20/2011 1:00:43 PM Info Task: ***Job Notes*** (see SQL tab) (inactive) was skipped because it was inactive.
5/20/2011 1:00:43 PM Err Email verification error: Unable to send email. Enter the missing SMTP settings/values in the settings menu.
5/20/2011 1:00:43 PM Info Job completed: Test_DBA_Maint_DB2_004B_Copy_15Min_trn_Bkup_To_DR2
5/20/2011 1:00:43 PM Info Task: Delete_Recycler_D_trn_Files inactive was skipped because it was inactive.
5/20/2011 1:00:43 PM Err File was not found when checking for file release in Trigger. Already moved?
5/20/2011 1:00:43 PM Err File was not found when checking for file release in Trigger. Already moved?
5/20/2011 1:00:43 PM Info Task started: Copy_and_Delete_trn_Files (9)
5/20/2011 1:00:43 PM Err Exception in Task: No files copied
5/20/2011 1:00:43 PM Info Task completed: Copy_and_Delete_trn_Files (9)
5/20/2011 1:00:44 PM Debug Running Email Notification: 'Opsalert'
5/20/2011 1:00:44 PM Err Email verification error: Unable to send email. Enter the missing SMTP settings/values in the settings menu.
5/20/2011 1:00:44 PM Info Job completed: Test_DBA_Maint_DB2_004B_Copy_15Min_trn_Bkup_To_DR2
5/20/2011 1:00:44 PM Info Job started: Test_DBA_Maint_DB2_004B_Copy_15Min_trn_Bkup_To_DR2
5/20/2011 1:00:44 PM Info Task: ***Job Notes*** (see SQL tab) (inactive) was skipped because it was inactive.
5/20/2011 1:00:44 PM Info Task: Delete_Recycler_D_trn_Files inactive was skipped because it was inactive.
5/20/2011 1:00:44 PM Info Task started: Copy_and_Delete_trn_Files (10)
5/20/2011 1:00:44 PM Err Exception in Task: No files copied
5/20/2011 1:00:44 PM Info Task completed: Copy_and_Delete_trn_Files (10)
5/20/2011 1:00:44 PM Debug Running Email Notification: 'Opsalert'
5/20/2011 1:00:44 PM Err Email verification error: Unable to send email. Enter the missing SMTP settings/values in the settings menu.
5/20/2011 1:00:44 PM Info Job completed: Test_DBA_Maint_DB2_004B_Copy_15Min_trn_Bkup_To_DR2
5/20/2011 1:00:45 PM Info Job started: Test_DBA_Maint_DB2_004B_Copy_15Min_trn_Bkup_To_DR2
5/20/2011 1:00:45 PM Info Task: ***Job Notes*** (see SQL tab) (inactive) was skipped because it was inactive.
5/20/2011 1:00:45 PM Info Task: Delete_Recycler_D_trn_Files inactive was skipped because it was inactive.
5/20/2011 1:00:45 PM Info Task started: Copy_and_Delete_trn_Files (11)
5/20/2011 1:00:45 PM Err Exception in Task: No files copied
5/20/2011 1:00:45 PM Info Task completed: Copy_and_Delete_trn_Files (11)
5/20/2011 1:00:45 PM Debug Running Email Notification: 'Opsalert'
5/20/2011 1:00:45 PM Err Email verification error: Unable to send email. Enter the missing SMTP settings/values in the settings menu.
5/20/2011 1:00:45 PM Info Job completed: Test_DBA_Maint_DB2_004B_Copy_15Min_trn_Bkup_To_DR2
5/20/2011 1:00:46 PM Info Job started: Test_DBA_Maint_DB2_004B_Copy_15Min_trn_Bkup_To_DR2
5/20/2011 1:00:46 PM Info Task: ***Job Notes*** (see SQL tab) (inactive) was skipped because it was inactive.
5/20/2011 1:00:46 PM Info Task: Delete_Recycler_D_trn_Files inactive was skipped because it was inactive.
5/20/2011 1:00:46 PM Info Task started: Copy_and_Delete_trn_Files (12)
5/20/2011 1:00:46 PM Err Exception in Task: No files copied
5/20/2011 1:00:46 PM Info Task completed: Copy_and_Delete_trn_Files (12)
5/20/2011 1:00:46 PM Debug Running Email Notification: 'Opsalert'
5/20/2011 1:00:46 PM Err Email verification error: Unable to send email. Enter the missing SMTP settings/values in the settings menu.
5/20/2011 1:00:46 PM Info Job completed: Test_DBA_Maint_DB2_004B_Copy_15Min_trn_Bkup_To_DR2
5/20/2011 1:00:47 PM Info Job started: Test_DBA_Maint_DB2_004B_Copy_15Min_trn_Bkup_To_DR2
5/20/2011 1:00:47 PM Info Task: ***Job Notes*** (see SQL tab) (inactive) was skipped because it was inactive.
5/20/2011 1:00:47 PM Info Task: Delete_Recycler_D_trn_Files inactive was skipped because it was inactive.
5/20/2011 1:00:47 PM Info Task started: Copy_and_Delete_trn_Files (13)
5/20/2011 1:00:47 PM Err Exception in Task: No files copied
5/20/2011 1:00:47 PM Info Task completed: Copy_and_Delete_trn_Files (13)
5/20/2011 1:00:47 PM Debug Running Email Notification: 'Opsalert'
5/20/2011 1:00:47 PM Err Email verification error: Unable to send email. Enter the missing SMTP settings/values in the settings menu.
5/20/2011 1:00:47 PM Info Job completed: Test_DBA_Maint_DB2_004B_Copy_15Min_trn_Bkup_To_DR2

I should explain what the task "Copy_and_Delete_trn_Files" is doing. It is a 'Copy Files' task which copies each type of trn.zip file to a specific location.

Say we dropped the following files in D:\Testfolder at the same time:

a.trn.zip
b.trn.zip
c.trn.zip
d.trn.zip
e.trn.zip
f.trn.zip
g.trn.zip
h.trn.zip
i.trn.zip
j.trn.zip

Then, the first time that the job was triggered (for a.trn.zip), it would copy all of those files into another folder and delete the source files. The second time that the job is triggered (for b.trn.zip), it would not find any files to copy since they are already copied. For this reason, we have a condition on the task "If *trn.zip still exist" then continue.

Any fix planned for this yet?

Thanks,
DevonWay

Thanks for the report - but we need to reproduce this first. Is it possible that you could export the settings and send to support@visualcron.com?

---

By the way, you cannot use the *.etc for file name. You must be specific - otherwise you will run into problems. For folder, use:

{TRIGGER(Active,LastTrigger,File.Result.TriggerFolder)}

For file mask:

{TRIGGER(Active,LastTrigger,File.Result.Name)}


This is most likely causing the problem.

---

Henrik,

We are not using the trigger variable in the file mask used in the "Copy Files" task. We will test with this change and report back. Thanks for the info.

Thanks,
DevonWay