Oddball Error with Copy Files Task

[jimbarbour]

I've encountered what seems to be an oddball error with the Copy Files Task, an Add-In for SAS EG.

Before I go on, let me first say that the Copy Files Task is so freaking wonderful and I'm absolutely ecstatic to have it at my disposal.  But I have noticed one oddball quirk:

When I would run one particular project, the Copy Files Task would "stall" mid-way.  That is, the Copy Files Task would begin execution and then simply stop, without transferring files.  Sometimes.  Other times, it would run just fine.  In all my other projects, the Copy Files Task would run 100% of the time, with nary a glitch.  

Let me here include screen prints of my log files so as to better illustrate the behavior that I have observed.  The first screenshot is of a normal run, a run in which the Copy Files task executed flawlessly (as it so often does):

And all is right with the world.  But about half the time, I was getting this (NOT! normal):

Notice that the process "dies" right after "SAS log:"  

"What the heck?!?" I asked myself.  After digging through log files until my eyes glazed over thicker than a Krispy Kreme doughnut, I found this:

2015-11-22 07:01:42,236 [10] ERROR SAS.Tasks.CopyFiles.SasFileTransferTask [(null)] - Exception encountered!
System.ArgumentNullException: Value cannot be null.
Parameter name: text
   at SAS.EG.JobManagement.Job.AppendLog(String text)
   at SAS.EG.ProjectElements.CustomAddInLogAdapter.WriteText(String Text)
   at SAS.Tasks.CopyFiles.SasFileTransferTask.Run(ISASTaskTextWriter LogWriter)

Whereas in successful runs, I got this:

2015-11-21 07:01:49,260 [10] INFO  SAS.Tasks.CopyFiles.SasFileTransferTask [(null)] - Running Copy Files task: Copy KML

So, this is the problem description, and it's an intermittent problem, and that in only one out of many, many projects where the Copy Files runs flawlessly time after time.

I think I've identified the cause, and I've got an effective work-around, but I don't have a true solution.

I will list my work-around in a subsequent post, but I'm curious as to two things:

1.  Has anyone else encountered this error?

2.  Does anyone have a true solution?

Thank you, 

Jim

[jimbarbour · Accepted solution]

This is post #2 regarding an oddball error with the Copy Files Task:  Probable cause and workaround.

So, what I think is happening is an issue of timing.  This portion of the project looks like this:

Notice that after the "Write_KML" program, the project flow branches into two independent steps:  "Copy KML" and "Email1".   Email1 is a very short program that formats and sends a brief email message.  What I think is happening is when "Copy KML" executes, there's some "hand off" during different phases of the overall Copy Files process, and in that hand off, SAS EG allows Email1 to begin execution.  Something like that.  Whatever the exact specifics of what is happening Email1 completes before the Copy Files task fully completes and the execution of Email1 somehow overlays or nulls out something that the Copy Files task writes out, causing the following error:

2015-11-22 07:01:42,236 [10] ERROR SAS.Tasks.CopyFiles.SasFileTransferTask [(null)] - Exception encountered!
System.ArgumentNullException: Value cannot be null.
Parameter name: text
   at SAS.EG.JobManagement.Job.AppendLog(String text)
   at SAS.EG.ProjectElements.CustomAddInLogAdapter.WriteText(String Text)
   at SAS.Tasks.CopyFiles.SasFileTransferTask.Run(ISASTaskTextWriter LogWriter)

The work around is fairly simple:  Restrain program Email1 from running until the Copy Files task is fully complete.  This restraint is easily effected by changing the process flow such that Email1 follows "Copy KML" as shown below:

That's it; that's all there is to it.  Simply move the quick finishing step to to execute after the instance of the Copy Files task.  It's not a true fix, but it is an effective work around.

Now I can sleep at night again.  🙂  Sheesh, these oddball timing problems will drive you nuts, I tell you.

Hope that helps someone out there,

Jim

[ChrisHemedinger]

Hi Jim,

Well, it's a bug.  I'm not sure exactly what situation causes it, and maybe your workaround will provide a clue.

I assume you're using the 5.1 version of the task (file date 11/23/2013).  If we can determine the cause I might be able to fix it.

Chris

[jimbarbour]

Hi, Chris,

Bug, schmug, this is a fabulous piece of code.  There's some kind of subtle timing thing going on here, something that only a clairevoyant could have forseen.  

Yes, I have the 5.1 version of the copy files task.  I downloaded it from the SAS Dummy blog on 8/26/2015. 

You're welcome to my log files if you'd like to examine them (or if you have insomnia).  🙂

Jim

[ChrisHemedinger]

Jim,

Yes, it's a timing thing.  The Copy Files task is doing its work on its background thread and maybe has contention with the SAS job that's potentially running in parallel.  I suspect that if I looked at your logs, I would see multiple tasks starting up simultaneously on different processor threads.  So it's definitely a bug, but it sounds like we agree that it's not a high-priority item.  I'm sorry you had to spend so much time investigating.

If you're okay with the workaround (use the User Defined Link to control the sequence), then that might need to be good enough for now.  

I have heard of the problem from one other user -- similar situation and the same workaround.

Chris

[jimbarbour]

Chris,

No hurry.  The workaround takes care of business for now, and I don't forsee any situations that might require me to have a true solution.

I'm going to go ahead and mark my work around as the "solution" so as to resolve this thread.  If a fix comes out, perhaps a brief note to that effect on SAS Dummy would be in order.

Thanks,

Jim