Background Worker Task problems under 3.1.0 rc3

[s3igell]

I'm having problems with the Background Worker Task, which does appear to startup/execute (per BYE and per TaskManager) but which doesn't succeed in placing the resulting files into the expected Folders.

 

For Imaging mode, the Preview Image that I took ended up in the proper destination Directory (User\My Pictures\BackyardEOS\2014-08-12\Pool Wall; I'm using Date#1 format and shooting test shots of my "Pool Wall").  However the resulting Images of a 4-shot Capture Plan ended up stuck in the BYE Temp Diretory (BackyardTEMP\Download).

 

For Planetary Mode, I shot a short 100-frame Movie and allowed it to complete the Background Worker Task (task popped-up a Security Warning upon start which I resolved by unchecking the "Always Ask for this Program" and Allowed it to proceed.  I then shot a longer 1000-frame Movie, followed 60-sec later by a short 100-frame Movie.  I noted that while each of the first two Planetary Capture Sequences were timed at 9.9FPS, once the Background Worker Task was active the 3rd Capture was timed at 7.9FPS (a rather substantial drop in FPS for a i5-2430M running at 2.4GHz with 8GB).  Neither of the latter two Captures triggered a Security Popup for the Background Worker Task, and I was able to confirm from TaskManager that the Task was present and working away.  The Camera Info Center Queue showed the 2 in-queue and then 1 and then none.  However, I ended up with no files in the expected destination directory, but rather there are a number of "task-#PID#-callback.dat" files in the BackyardTEMP\BackgroundWorker directory.

 

 

I scoured my HDD for any other locations where the missing files might be hidden, based upon Datestamp.  I found the v3.1.0 RC3 logfiles, as well as those for my "comparison test" startup of v3.0.3.  And, as a surprise, I found active log4net logfiles for both versions - even though neither instance has the Log4net Debug Advanced Setting checked.

 

Standard Logfiles attached:
 v310rc3 140812 Logs.zip     

BYE Log4net logfile attached:

7d30f4d5-8585-4cd4-b2be-5320aba9cb38BackyardEOS-log4net.txt 

BackgroundWorker "callback.dat" files:
DropBox Folder

[admin]

I'm having problems with the Background Worker Task, which does appear to startup/execute (per BYE and per TaskManager) but which doesn't succeed in placing the resulting files into the expected Folders.

 

For Imaging mode, the Preview Image that I took ended up in the proper destination Directory (User\My Pictures\BackyardEOS\2014-08-12\Pool Wall; I'm using Date#1 format and shooting test shots of my "Pool Wall").  However the resulting Images of a 4-shot Capture Plan ended up stuck in the BYE Temp Diretory (BackyardTEMP\Download).

 

For Planetary Mode, I shot a short 100-frame Movie and allowed it to complete the Background Worker Task (task popped-up a Security Warning upon start which I resolved by unchecking the "Always Ask for this Program" and Allowed it to proceed.  I then shot a longer 1000-frame Movie, followed 60-sec later by a short 100-frame Movie.  I noted that while each of the first two Planetary Capture Sequences were timed at 9.9FPS, once the Background Worker Task was active the 3rd Capture was timed at 7.9FPS (a rather substantial drop in FPS for a i5-2430M running at 2.4GHz with 8GB).  Neither of the latter two Captures triggered a Security Popup for the Background Worker Task, and I was able to confirm from TaskManager that the Task was present and working away.  The Camera Info Center Queue showed the 2 in-queue and then 1 and then none.  However, I ended up with no files in the expected destination directory, but rather there are a number of "task-#PID#-callback.dat" files in the BackyardTEMP\BackgroundWorker directory.

 

 

I scoured my HDD for any other locations where the missing files might be hidden, based upon Datestamp.  I found the v3.1.0 RC3 logfiles, as well as those for my "comparison test" startup of v3.0.3.  And, as a surprise, I found active log4net logfiles for both versions - even though neither instance has the Log4net Debug Advanced Setting checked.

 

Standard Logfiles attached:

 v310rc3 140812 Logs.zip     

 

BYE Log4net logfile attached:

 7d30f4d5-8585-4cd4-b2be-5320aba9cb38BackyardEOS-log4net.txt     

 

BackgroundWorker "callback.dat" files:

DropBox Folder

 

 

I do see an error trying to move the file to your final download folder.

 

I also noticed that you have a space in your file name "Pool  Wall"... I wonder if this is the actual bug preventing the move?  I'll run some tests with and without space and see what happens.

 

Thanks,

 

 

[admin]

Okay, so there are a few things here.

 

Thanks to your log files I was able to determine that a bug exists when using the SEQUENCE instead of the default TIMESTAMP in the file name configuration.  When SEQUENCE is chosen images never gets copied in the final download folder.  I'll fix that in RC04.

 

The log4net log file is irrelevant, you can disable it in Advance Setting.  This is used only when the log files are not created, it helps me find why they are not... but since the log files are created on your system you can disable it that in Advance Settings.

 

As for the planetary losing fps when recording a second session while the previous is encoding this is normal, unwanted but normal.  The background worker does run a lowest priority thread, but it may take -some- cycle from the main UI thread still <_>

 

As for the AVI not ending up in your download folder I do see an error in the log file indicating the file move has failed.  I'm not sure why at this time but I'm investigating... I'm almost tempted to have the AVI being creating directly in the user selected download folder instead of in the TEMP folder.  The only benefit in having it created in the TEMP folder is that I know it is a local folder and is always available.  The end user download folder on the other hand could very well be on a network folder / NAS / or USB drive... which may become unavailable and then all sort of side effect can occur <_ i on the fence. would rather find root cause and fix. continue looking for cause.>

 

Thank you for your time testing, I really appreciate it.

 

Regards,

[admin]

Okay, so I also found why the AVI was not copied.  The AVI was not there when the try move occurred.   This is probably a timer issue where VirtualDub (or Windows) may take a few milliseconds after the AVI encoding process is complete and the actual file showing up in the folder.

 

I will add a few seconds wait time between the AVI creating and the actual copy to take place.  This should resolve the issue.

 

Thanks for reporting it.

 

Regards,

[admin]

I believe most of these issues are now fixed in BETA 02e.

 

Thank you

[admin]

I believe most of these issues are now fixed in BETA 02e.

 

Thank you

[s3igell]

Tested in BYE v3.1.0rc4:

Space in Filename - OK

SEQUENCE in Filename - OK

Timing Delay in AVI Move - OK

 

BackgroundWorker Temp Files "task-PID#-callback.dat" remaining in BackyardTEMP\Camera1\BackgroundWorker - still occurring

 

Thanks

[admin]

Tested in BYE v3.1.0rc4:

Space in Filename - OK

SEQUENCE in Filename - OK

Timing Delay in AVI Move - OK

 

BackgroundWorker Temp Files "task-PID#-callback.dat" remaining in BackyardTEMP\Camera1\BackgroundWorker - still occurring

 

Thanks

 

The .dat staying behind is by design... and they will be cleaned up over time.

 

A .dat file is a completed tasks waiting by be pulled from the UI, typically a processed image the UI needs to display, including the histogram data, etc.  If BYE is closed while you still have tasks in the background worker, these tasks will complete and then sit as .dat files.  Since the UI is closed they are not picked up by the UI.  Eventually, when you restart BYE, they will be cleaned up.  The important thing is that even though the .dat was never pulled by the UI the actual image .cr2 was copied to your download folder because the tasks actually completed.  The .dat is a serialized copy of the completed task.

 

Hope this makes sense.

 

Regards,

[s3igell]

That does make sense, as a precaution in case the BackgroundWorker task is terminated prematurely when a user shuts down a Laptop immediately after taking the last Flat Exposure and shutting down BYE.

 

But, I'm not sure that your intended action jibes with the remaining files in my Directory - they are from the past 3 nights worth of Dark Site Imaging Sessions over the Labor Day Weekend (9/2-9/4) plus additional files from today's Test Sessions.  That covers several UI Restarts, without removing these Files.  AND, I almost NEVER terminate BYE immediately after an Exposure - my Laptop either sits Idle or continues to run other Apps while I start my Teardown or put away my Lightbox and apply my Scope Cover...

 

I remember you once describing the BackgroundWorker as persisting in the background idling for some number of minutes before self-terminating.  Could it be that these orphaned temp-PID#-callback.dat files are failing to be cleaned up for some reason related to the self-termination of a BackgroundWorker whilst BYE is still running in the foreground but simply Idle ??

 

I wouldn't be as concerned, if it were only a single file or two (even if they are the 17-20MB size of full CR2 Files).  BUT, from the above 4 Imaging Sessions, I'm already left with 500MB of orphaned Files.  (Eventually, that will confiscate sufficient HDD Space that should be available for a Productive Imaging Session...) 

[admin]

That does make sense, as a precaution in case the BackgroundWorker task is terminated prematurely when a user shuts down a Laptop immediately after taking the last Flat Exposure and shutting down BYE.

 

But, I'm not sure that your intended action jibes with the remaining files in my Directory - they are from the past 3 nights worth of Dark Site Imaging Sessions over the Labor Day Weekend (9/2-9/4) plus additional files from today's Test Sessions.  That covers several UI Restarts, without removing these Files.  AND, I almost NEVER terminate BYE immediately after an Exposure - my Laptop either sits Idle or continues to run other Apps while I start my Teardown or put away my Lightbox and apply my Scope Cover...

 

I remember you once describing the BackgroundWorker as persisting in the background idling for some number of minutes before self-terminating.  Could it be that these orphaned temp-PID#-callback.dat files are failing to be cleaned up for some reason related to the self-termination of a BackgroundWorker whilst BYE is still running in the foreground but simply Idle ??

 

I wouldn't be as concerned, if it were only a single file or two (even if they are the 17-20MB size of full CR2 Files).  BUT, from the above 4 Imaging Sessions, I'm already left with 500MB of orphaned Files.  (Eventually, that will confiscate sufficient HDD Space that should be available for a Productive Imaging Session...) 

 

Yes, the .dat is removed only once the UI pulls it in, otherwise it stays.  Pulling the .dat in the UI and removing it is the same task.

 

I will add logging to see if there is a bug that prevents the file from being deleted.

 

 

[s3igell]

The log4net log file is irrelevant, you can disable it in Advance Setting.  This is used only when the log files are not created, it helps me find why they are not... but since the log files are created on your system you can disable it that in Advance Settings.

 

While performing a File Comparison of the user.config files between RC04 and RC05, I noticed that there are actually TWO config entries which appear to affect LOG4NET usage:

 

  <add key="log4net.Internal.Debug" value="true" />

  <add key="System.Log4netDebug" value="False" />

Changing the Setting / Advanced / Experimental / log4net only affects the value of the latter config key entry.

 

Is it possible that these config keys have somehow been mis-associated within your code ??

 

I'd always wondered why I was seeing updated LOG4NET Debug Files when I'd checked per your instructions that the Experimental / log4net setting was OFF...