Bad logs/bad processing with 7.2.034?

Bob Hansen · Post by **Bob Hansen** » Sat Apr 26, 2003 7:31 am

Using 7.2.034 with WIN98ME

Just finished running a nightly backup routine with horrible ressults in the log file. I don't know it the log is not recording properly or if the macro is processing out of sequence.

I am including some annoted excerpts from the log file:

4/26/2003 00:30:00:840 -
4/26/2003 00:30:00:840 - Label>Qbooks2003
4/26/2003 00:30:00:840 - //::QUICKBOOKS 2003 - keep last 7 days
The following lines should only run one time
4/26/2003 00:30:00:840 - Change Directory>Q:\Backups\Qbooks2003
4/26/2003 00:30:00:840 - Message>Copying QuickBooks 2003 file may take 1-2 minutes....please be patient..
4/26/2003 00:30:00:890 - Change Directory>Q:\Backups\Qbooks2003
4/26/2003 00:30:01:170 - DeleteFile>sensible_2003.007
4/26/2003 00:30:01:170 - Let>RP_WINDOWMODE=0
4/26/2003 00:30:01:220 - DeleteFile>sensible_2003.007
4/26/2003 00:30:01:220 - Let>RP_WINDOWMODE=0
4/26/2003 00:30:01:500 - Run Program>command.com /c rename sensible_2003.006 sensible_2003.007
4/26/2003 00:30:01:500 - Run Program>command.com /c rename sensible_2003.006 sensible_2003.007
4/26/2003 00:30:01:990 - Run Program>command.com /c rename sensible_2003.005 sensible_2003.006
4/26/2003 00:30:02:050 - Run Program>command.com /c rename sensible_2003.005 sensible_2003.006
4/26/2003 00:30:02:320 - Run Program>command.com /c rename sensible_2003.004 sensible_2003.005
4/26/2003 00:30:02:380 - Run Program>command.com /c rename sensible_2003.004 sensible_2003.005
.....
.....
.....
4/26/2003 00:30:18:740 - Change Directory>Q:\Backups\Outlook
4/26/2003 00:30:18:850 - DeleteFile>outlook.007
4/26/2003 00:30:18:910 - Let>RP_WINDOWMODE=0
4/26/2003 00:30:19:240 - Run Program>command.com /c rename Q:\Backups\Outlook\outlook.006 outlook.007
Following line belongs above with QuickBooks 2003 items.
4/26/2003 00:30:19:510 - CopyFile>C:\My Documents\Data\Qbooks\2003\sensible_2003.qbw,Q:\Backups\Qbooks2003\sensible_2003.qbw
4/26/2003 00:30:19:570 -
The following lines belong above with the Quicken99 files, not part of Outlook
4/26/2003 00:30:19:570 - Label>Quicken99
4/26/2003 00:30:19:570 - //::QUICKEN - keep last 7 days
4/26/2003 00:30:19:570 - Message>Copying Quicken 99 files may take 1-2 minutes....please be patient..
4/26/2003 00:30:19:680 - Change Directory>Q:\Backups\Quicken99
4/26/2003 00:30:19:950 - Run Program>command.com /c rename Q:\Backups\Outlook\outlook.005 outlook.006
The following line belongs above with the Quicken99 files, not part of Outlook
4/26/2003 00:30:20:280 - DeleteFile>home.007
4/26/2003 00:30:20:390 - Let>RP_WINDOWMODE=0
4/26/2003 00:30:20:880 - Run Program>command.com /c rename Q:\Backups\Outlook\outlook.004
.....
.....
.....

Thet section of the macro script follows here:

Label>Qbooks2003
//::QUICKBOOKS 2003 - keep last 7 days
Message>Copying QuickBooks 2003 file may take 1-2 minutes....please be patient..
Change Directory>Q:\Backups\Qbooks2003
DeleteFile>sensible_2003.007
Let>RP_WINDOWMODE=0
Run Program>command.com /c rename sensible_2003.006 sensible_2003.007
Run Program>command.com /c rename sensible_2003.005 sensible_2003.006
Run Program>command.com /c rename sensible_2003.004 sensible_2003.005
Run Program>command.com /c rename sensible_2003.003 sensible_2003.004
Run Program>command.com /c rename sensible_2003.002 sensible_2003.003
Run Program>command.com /c rename sensible_2003.001 sensible_2003.002
Run Program>command.com /c rename sensible_2003.qbw sensible_2003.001
Let>RP_WINDOWMODE=1
CopyFile>C:\My Documents\Data\Qbooks\2003\sensible_2003.qbw,Q:\Backups\Qbooks2003\sensible_2003.qbw

Label>Quicken99
//::QUICKEN - keep last 7 days
Message>Copying Quicken 99 files may take 1-2 minutes....please be patient..
Change Directory>Q:\Backups\Quicken99
DeleteFile>home.007
Let>RP_WINDOWMODE=0
Run Program>command.com /c rename home.006 home.007
Run Program>command.com /c rename home.005 home.006
Run Program>command.com /c rename home.004 home.005
Run Program>command.com /c rename home.003 home.004
Run Program>command.com /c rename home.002 home.003
Run Program>command.com /c rename home.001 home.002
Run Program>command.com /c rename home.qdf home.001
Let>RP_WINDOWMODE=1
CopyFile>m:\Data\quicken99\home.*,Q:\Backups\Quicken99\
CopyFile>m:\Data\quicken99\q3.dir,Q:\Backups\Quicken99\

Label>Outlook
//::OUTLOOK - keep last 7 days
Message>Making 7 backups of Outlook file may take a few.minutes...please be patient..
//CopyFile took 18 minutes on 4/17/03
Change Directory>Q:\Backups\Outlook
DeleteFile>outlook.007
Let>RP_WINDOWMODE=0
Run Program>command.com /c rename Q:\Backups\Outlook\outlook.006 outlook.007
Run Program>command.com /c rename Q:\Backups\Outlook\outlook.005 outlook.006
Run Program>command.com /c rename Q:\Backups\Outlook\outlook.004 outlook.005
Run Program>command.com /c rename Q:\Backups\Outlook\outlook.003 outlook.004
Run Program>command.com /c rename Q:\Backups\Outlook\outlook.002 outlook.003
Run Program>command.com /c rename Q:\Backups\Outlook\outlook.001 outlook.002
Run Program>command.com /c rename Q:\Backups\Outlook\outlook.pst outlook.001
Let>RP_WINDOWMODE=1
Message>Copy of 7 backups of Outlook files is done.%CRLF%%CRLF%Will now start to make copy of latest Outlook file.%CRLF%%CRLF% This may take 18-25 minutes....please be patient..
//rem copies Outlook data in folders
CopyFile>m:\windows\Application Data\Microsoft\Outlook\outlook.pst,Q:\Backups\Outlook\outlook.pst
//rem copies Internet email data - need last 7 days
CopyFile>m:\windows\Application Data\Microsoft\Outlook\mailbox.pab,Q:\Backups\Outlook\mailbox.pab
//rem copies Outlook Folders - need last 7 days
CopyFile>m:\windows\Application Data\Microsoft\Outlook\Robert M Hansen.fav,Q:\Backups\Outlook\Robert M Hansen.fav
//rem copies Outlook Rules - need last 7 days
CopyFile>m:\windows\Application Data\Microsoft\Outlook\Robert M Hansen.rwz,Q:\Backups\Outlook\Robert M Hansen.rwz
Message>Copying Outlook files is done...Thanks for your patience..

What is happening here? The log file is about 350 lines doing backups for about 12 different applications. The sample above is typical of the log contents, lines being executed multiple times. Lines being executed in the wrong sequence..

If the log is incorrect, I can live with that for a while. But this needs immediate attention if the log is correcly recording the activities. I will try to do some testing on this on Saturday.

Bob Hansen · Post by **Bob Hansen** » Sun Apr 27, 2003 6:46 am

Using 7.2.034 with WIN98ME.

The backup routine tonght repeated the logging issue again. It can be seen as the first line for 4/27. An annotated excerpt showing the errors from the script log is shown here. It actually starts with the very first line of the log, before processing any lines of script:

4/26/2003 00:35:59:560 - Finished Macro : Minimal Backups
The next line should only be listed once
4/27/2003 00:30:00:840 - Started Macro : Minimal Backups
4/27/2003 00:30:00:840 - Started Macro : Minimal Backups
4/27/2003 00:30:00:840 - //Script file to copy minimal critical data files
4/27/2003 00:30:00:840 -
4/27/2003 00:30:00:840 - //Run Program>c:\batch\bakatnit.bat
4/27/2003 00:30:00:840 - //Goto>Test
4/27/2003 00:30:00:840 -
4/27/2003 00:30:00:840 - //::=====================================
4/27/2003 00:30:00:840 - //::NOTES
4/27/2003 00:30:00:840 - //Need to only copy IfFileChanged>
4/27/2003 00:30:00:840 - //Need MSIE bookmarks
4/27/2003 00:30:00:840 - //::Need AOL bookmarks, main.idx, addressbooks, favorite places, buddy lists
4/27/2003 00:30:00:840 - //Need pcAnyWhere profiles
The next section was already recorded above
4/27/2003 00:30:00:840 - //Script file to copy minimal critical data files
4/27/2003 00:30:00:840 -
4/27/2003 00:30:00:840 - //Run Program>c:\batch\bakatnit.bat
4/27/2003 00:30:00:840 - //Goto>Test
4/27/2003 00:30:00:840 -
4/27/2003 00:30:00:840 - //::=====================================
4/27/2003 00:30:00:840 - //::NOTES
4/27/2003 00:30:00:840 - //Need to only copy IfFileChanged>
4/27/2003 00:30:00:840 - //Need MSIE bookmarks
4/27/2003 00:30:00:840 - //::Need AOL bookmarks, main.idx, addressbooks, favorite places, buddy lists
4/27/2003 00:30:00:840 - //Need pcAnyWhere profiles
4/27/2003 00:30:00:890 - //Need Access General, Dietary, Movies, Network
4/27/2003 00:30:00:890 - //::Check results on FileCopy routines?
4/27/2003 00:30:00:890 - //::Use command.com /c ren vs. MoveFile>
4/27/2003 00:30:00:890 - //::======================================

That section of the backup script is shown here:

//Script file to copy minimal critical data files

//Run Program>c:\batch\bakatnit.bat
//Goto>Test

//::=====================================
//::NOTES
//Need to only copy IfFileChanged>
//Need MSIE bookmarks
//::Need AOL bookmarks, main.idx, addressbooks, favorite places, buddy lists
//Need pcAnyWhere profiles
//Need Access General, Dietary, Movies, Network
//::Check results on FileCopy routines?
//::Use command.com /c ren vs. MoveFile>
//::======================================

The sections from the previous night's backup did not repeat the same errors tonight; instead it was the section shown above that was repeated. Although this sample is only showing comments, there is something not working correctly here.

In looking closely at the log erors, it looks like log writing may be queued until the next time bucket and then written to the file. But the last line of the current queue is appended to the previous log file before writing the current queue. Did that make sense?

(Also new topic named "Log File Timing", which I was just reminded of).

support · Post by **support** » Sun Apr 27, 2003 9:32 am

Hi,

It looks like you may have two copies of the macro running at once.

Log file entries are only ever made once after each command has been processed.

I have been unable to replicate the issue, but have seen this behaviour occur before where someone had two instances running the same macro at the same time.

Is it possible you have two copies of Macro Scheduler running causing two copies of the scheduled macro to run simultaneously?

If not is there anything else we should do to attempt to replicate - is there a test script we can use without modification that you think will replicate the outcome?

Bob Hansen · Post by **Bob Hansen** » Sun Apr 27, 2003 4:03 pm

I have sent script and log. Just started with 034, Ok prior to this.

At the time of running, all other programs are off and this is the only active copy of Macro Scheduler, running in systray. It is automatically scheduled to run at 00:30 right now. Normally runs at 02:30, but running earlier now so I can observe it.

I will make additional efforts to duplicate it and observe other script logs.

Bob Hansen · Post by **Bob Hansen** » Tue Apr 29, 2003 2:43 pm

I am now unable to duplicate this problem again.

I took the offending script, commented all of the Copy/Rename/Move lines so no files would be modified. I scheduled the script to run every 15 minutes for about 10 hours, and the problem did not repeat.

Under its normal scheduled time for the past three nights, the full script, without being commented, has run with no logging errors.

Perhaps as you suggested there was a second copy of the same script running somehow, but I cannot determine that At this point, I will have to consider this issue unimportant unless it shows up again.

Thanks for your support.