Web-UI parallel backup tasks overwriting other task's log files (MacOS Mojave)

planned
web-ui

#1

Please describe what you are doing to trigger the bug:
I’m running a single scheduled job which has three parallel backups followed by a check and a prune. The resulting log files are emailed to me. (And let me say that I really appreciate both the parallel capability and the way it assembles the log files into the email:-). The platform is MacOS 10.14.5.

Please describe what you expect to happen (but doesn’t):
The email (and the log files left in the .duplicacy/log/ directory) contains the information logged from each of the individual tasks (each separate backup + check + prune).

Please describe what actually happens (the wrong behaviour):
I’ve seen two different behaviours (both wrong).
Usually we get just one log file from the backups (the log for the last of the backups in the Web-UI list, which is presumably the last one started). The report that’s emailed contains three copies of that one log, labelled as if they are from each of the three backup jobs.

But sometimes I get two log files from the backups. One is clean, and the other shows signs of having been written to from two separate tasks.
Here’s an example of the second mode of failure from the emailed report, showing just the first few lines from each backup job. Note in particular the first timestamped line of the first & third excerpts:

Back up /Users/brian@localhost to storage Duplicacy-2GB, status: Completed, log file: backup-20190516-085112.log
----------------------------------------------------------------------------------------------------------------
Running backup command from /Users/brian/.duplicacy-web/repositories/localhost/0 to back up /Users/brian
Options: [-log backup -storage Duplicacy-2GB -stats]
2019-2019-05-16 08:51:12.864 INFO REPOSITORY_SET Repository set to /Volumes2019-05-162019-05-16 08:51:12.865 INFO STORAGE_SET Storage set to /Volumes/Duplicacy-2GB/2019-05-16 08:51:39.620 INFO BACKUP_START Last backup at revision 49 found
2019-05-16 08:51:39.620 INFO BACKUP_INDEXING Indexing /Users/brian

[…]

Back up /Volumes/G-DriveMobile@localhost to storage Duplicacy-2GB, status: Completed, log file: backup-20190516-085113.log
--------------------------------------------------------------------------------------------------------------------------
Running backup command from /Users/brian/.duplicacy-web/repositories/localhost/1 to back up /Volumes/G-DriveMobile
Options: [-log backup -storage Duplicacy-2GB -stats]
2019-05-16 08:51:12.961 INFO REPOSITORY_SET Repository set to /Volumes/G-DriveMobile
2019-05-16 08:51:12.963 INFO STORAGE_SET Storage set to /Volumes/Duplicacy-2GB/duplicacy
2019-05-16 08:51:21.331 INFO BACKUP_START Last backup at revision 36 found
2019-05-16 08:51:21.331 INFO BACKUP_INDEXING Indexing /Volumes/G-DriveMobile

[…]

Back up /Volumes/LaCie-2T@localhost to storage Duplicacy-2GB, status: Completed, log file: backup-20190516-085112.log
---------------------------------------------------------------------------------------------------------------------
Running backup command from /Users/brian/.duplicacy-web/repositories/localhost/0 to back up /Users/brian
Options: [-log backup -storage Duplicacy-2GB -stats]
2019-2019-05-16 08:51:12.864 INFO REPOSITORY_SET Repository set to /Volumes2019-05-162019-05-16 08:51:12.865 INFO STORAGE_SET Storage set to /Volumes/Duplicacy-2GB/2019-05-16 08:51:39.620 INFO BACKUP_START Last backup at revision 49 found
2019-05-16 08:51:39.620 INFO BACKUP_INDEXING Indexing /Users/brian

Regards
Brian Marriott

[Edit]
I just thought look into the duplicacy_web.log file. A grep shows the cause of the problem:

brian@BrianMacBook-3 ~/.d/logs> grep "Created log" duplicacy_web.log                                                                                                                                                   
2019/05/16 08:51:12 Created log file /Users/brian/.duplicacy-web/logs/backup-20190516-085112.log
2019/05/16 08:51:12 Created log file /Users/brian/.duplicacy-web/logs/backup-20190516-085113.log
2019/05/16 08:51:12 Created log file /Users/brian/.duplicacy-web/logs/backup-20190516-085112.log
2019/05/16 08:59:10 Created log file /Users/brian/.duplicacy-web/logs/check-20190516-085910.log
2019/05/16 09:07:15 Created log file /Users/brian/.duplicacy-web/logs/prune-20190516-090715.log

It’s creating multiple log files with the same name.
Perhaps you could include milliseconds in the file name, or add a unique suffix?

Brian


#2

I’ll fix this bug in 1.0.1.