Newbie's problems understanding how Cron works

[Fuddyduddy]

( => compare with your output)

Mine is more or less identical.

Here's cron.log

Code: Select all

crond: USER root pid 8167 Rsync script started at : 2014-09-09_12:00:02
crond: USER root pid 8167 USB share is available
crond: USER root pid 8167 rsync command:
umask 0 && /usr/sbin/rsync --stats --force --ignore-errors --modify-window=2 -tDvr --delete '/share/1000/My_Movies' '/share/1000/NAS_backup_1/Back-up My_Movies'> '/share/1000/cronjobs/My_Movies_2014-09-09_12-00-02.log' 2>&1
crond: USER root pid 8167 Rsync command returned some errors: see the log file (/share/1000/cronjobs/My_Movies_2014-09-09_12-00-02.log)!
12
crond: USER root pid 8167 Rsync script ended at : 2014-09-09_12:12:56
12
cron.log (END)


But I had no success with "Recorded_TV_xx-yy-zz_aa-bb-cc.log" (what was I meant to substitute for the 'xx...cc"?), nor with "My_Movies_2014-09-09_12-00-02.log" pointed-to in the output above:-

Code: Select all

login as: root
root@192.168.11.5's password:
root@fvdwsl-base:/ # cd /share/1000/cronjobs
root@fvdwsl-base:/share/1000/cronjobs # less Recorded_TV
_xx-yy-zz_aa-bb-cc.log
Recorded_TV_xx-yy-zz_aa-bb-cc.log: No such file or directory
root@fvdwsl-base:/share/1000/cronjobs # less /My_Movies_
2014-09-09_12-00-02.log
/My_Movies_2014-09-09_12-00-02.log: No such file or directory
root@fvdwsl-base:/share/1000/cronjobs #


But maybe I found an explanation. If your USB is a FAT32 or NTFS disk, then if there are some filename to backup with unauthorized characters (<>/?*:!"|) then the backup fails

I don't believe any of those unauthorised characters occur

[Jocko]

Be careful Fuddyduddy,

if you give less /My_Movies_2014-09-09_12-00-02.log then the shell will search the file from the partition root and not from the current folder.

so do

Code: Select all

less My_Movies_2014-09-09_12-00-02.log (if the current folder is /share/1000/cronjobs)
or
less /share/1000/cronjobs/My_Movies_2014-09-09_12-00-02.log

[Fuddyduddy]

Hi Jocko

Good news!

I've just done a check and found this entry in the Cron Log file

crond: USER root pid 1729 Rsync script started at : 2014-09-12_16:00:01
crond: USER root pid 1729 USB share is available
crond: USER root pid 1729 rsync command:
umask 0 && /usr/sbin/rsync --stats --force --ignore-errors --modify-window=2 -tDvr --delete-excluded --exclude-from='/share/1000/cronjobs/Recorded_TV_exclude.txt' '/share/1000/Recorded_TV/' '/share/1000/NAS_backup_1/Back-up Recorded_TV'> '/share/1000/cronjobs/Recorded_TV_2014-09-12_16-00-01.log' 2>&1
crond: USER root pid 1729 Rsync command successful
crond: USER root pid 1729 Rsync script ended at : 2014-09-12_16:00:03
0

Comparing the Source and Destination folders I find that they are indeed now synced exactly. It seems I (we?) were counting the days from the wrong base-line:- counting evidently starts from day 3 (not from day 1) and is every third day thereafter.

So that Cronjob is working to schedule :-D

Now to tackle the other one of the pair...

[Jocko]

:thumbup

You are right. Indeed */3 means 3,6,9,... :pound

[Fuddyduddy]

:thumbup

You are right. Indeed */3 means 3,6,9,... :pound

Hi Jocko

Yes, and that being the case and today being the 15th two backups ought to have been executed via the Cron scheduler - one at 1200 and one at 1600.

It's now 1615 and neither of them have been. The log contains no new entries since the one I previously quoted, which related to three days ago.

So already my previous euphoria has turned again into frustration and disappointment. I don't understand what's going wrong.

[Jocko]

Hi Fuddyduddy,

If this have run once, there is no reason that this doesn't continue :scratch

Please, could you post the screen capture of your setup menu (cron feature)

[Fuddyduddy]

Jocko

EDIT
Since I sent my previous post I've seen that one of the two backups has been logged. Why it ran later than scheduled I don't know, but anyway it has run. So, panic over so far as that one is concerned.

The other job (added since the 1600 one) should have run at 1200 but so far hasn't run at all.

[Jocko]

Thank Fuddyduddy,

Your cron settings are ok. :scratch

First we go to test cron feature.
Then add a job with this command

Code: Select all

date >> /share/1000/cronjobs/cron.log

In the five drop-down list select 'Every (*)' and for minute step, give a step 2.
Then you must get this cron job line

Code: Select all

*/2 * * * * date >> /share/1000/cronjobs/cron.log

If cron feature is ok you must see in cron log lines as

Code: Select all

Mon Sep 15 19:52:01 CEST 2014
Mon Sep 15 19:54:01 CEST 2014
Mon Sep 15 19:56:01 CEST 2014
Mon Sep 15 19:58:01 CEST 2014
...

(new line every 2minutes 0,2,...56,58)
If it is ok you can delete this job after.

[Fuddyduddy]

Hi Jocko

Yes, that's what I'm seeing.

However I'm also seeing something else, which is most peculiar. Although the time to which my computer is set is (right now) 14.31 (which is GMT +3 - because of Summertime - normally +2), the time at which a LOG file named cron.log and another named active_jobs.cron appear in Explorer is one hour later.

Secondly, and even weirder, when I open cron.log I see the series of entries every two minutes but timed for (roughly) two hours earlier
EDIT but it does have "UDT" after it, so I suppose it's not so weird after all.

[Jocko]

Hi Fuddyduddy,

Maybe an explanation about these time offsets.

With version 15.3, you need to select again your timezone (because it uses new ones). There is a warning in the setup help page

Important: After upgrading the firmware, the selected time zone is overwritten and by default the new selected time zone is UTC when you reboot the NAS. To restore the right time zone you need to select a new time zone

So I assume that you don't do yet and so PHP times, locale time and hardwaretime are not correctly set. To check that do in putty

Code: Select all

 date;hwclock; php -r 'echo date("r")."\n";'

(keep the single and double quotes). if it is ok, the output should be

Code: Select all

Wed Sep 17 13:59:14 CEST 2014
Wed Sep 17 11:59:13 2014  0.000000 seconds
Wed, 17 Sep 2014 13:59:14 +0200


the 2d time is in UTC so the two others must have an offset in accordance with your timezone (+2 in my case and +3 for you)

if not, select a new timezone (it should display UTC) in the setup menu.