Topic: DAR2 doesn't seem to do anything...?

[superwormy]

I have the DAR2 module installed and a backup set up, and when I tell it to do the backup it tells me:

Disk ARchive
SUCCESS    
Operation status report
Success

But it doesn't actually seem to do anything... I never get an e-mail (who is it sending this e-mail to?), and I don't see anything on my USB disk. I tried it with a local directory and it didn't do anything either. There are no logs in the /var/log/dar2 directory.

How can I tell what's going wrong?

[cactus]

How can I tell what's going wrong?

Check /var/log/messages

[superwormy]

/var/log/messages has lots of stuff in it, but when I run the DAR job *nothing* gets added to that log file.

Does anyone know the actual command that gets run, or is there a way to turn on debugging within SME server to see what's actually happening/being run?

[cactus]

/var/log/messages has lots of stuff in it, but when I run the DAR job *nothing* gets added to that log file.

Strange, in my setup it logs properly something like this:

Code: [Select]

May 16 10:08:03 homer e-smith-bg: Connecting to /media/usbdisk
May 16 10:08:04 homer e-smith-bg: Expanding /etc/dar2/Minimal2 template
May 16 10:08:07 homer e-smith-bg: Creating /media/usbdisk/homer.snetram.nl/Minimal2/db.zip
May 16 10:08:08 homer e-smith-bg: Expiring old backups
May 16 10:08:44 homer e-smith-bg: Executing pre-backup event
May 16 10:08:46 homer esmith::event[5185]: Processing event: pre-backup
May 16 10:08:46 homer esmith::event[5185]: Running event handler: /etc/e-smith/events/actions/generic_template_expand
May 16 10:08:47 homer esmith::event[5185]: expanding /etc/dar/DailyBackup.dcf
May 16 10:08:48 homer esmith::event[5185]: generic_template_expand=action|Event|pre-backup|Action|generic_template_expand|Start|12424613$
May 16 10:08:48 homer esmith::event[5185]: Running event handler: /etc/e-smith/events/pre-backup/S10mysql-delete-dumped-tables
May 16 10:08:48 homer esmith::event[5185]: S10mysql-delete-dumped-tables=action|Event|pre-backup|Action|S10mysql-delete-dumped-tables|St$
May 16 10:08:48 homer esmith::event[5185]: Running event handler: /etc/e-smith/events/pre-backup/S20mysql-dump-tables
May 16 10:08:52 homer esmith::event[5185]: S20mysql-dump-tables=action|Event|pre-backup|Action|S20mysql-dump-tables|Start|1242461328 882$
May 16 10:08:52 homer esmith::event[5185]: Running event handler: /etc/e-smith/events/pre-backup/S50rewind-tape
May 16 10:08:53 homer esmith::event[5185]: S50rewind-tape=action|Event|pre-backup|Action|S50rewind-tape|Start|1242461332 319815|End|1242$
May 16 10:08:53 homer e-smith-bg: Verbose logging is off
May 16 10:08:53 homer e-smith-bg: Performing Minimal2 backup
May 16 10:08:54 homer e-smith-bg: No terminal found for user interaction. All questions will be assumed a negative answer (less destructive choice), which most of the time will abort the program.

[...]

May 16 14:31:20 homer e-smith-bg:
May 16 14:31:20 homer e-smith-bg:
May 16 14:31:20 homer e-smith-bg:  --------------------------------------------
May 16 14:31:20 homer e-smith-bg:  62836 inode(s) saved
May 16 14:31:20 homer e-smith-bg:  with 30 hard link(s) recorded
May 16 14:31:20 homer e-smith-bg:  0 inode(s) changed at the moment of the backup
May 16 14:31:20 homer e-smith-bg:  0 inode(s) not saved (no inode/file change)
May 16 14:31:20 homer e-smith-bg:  0 inode(s) failed to save (filesystem error)
May 16 14:31:20 homer e-smith-bg:  316 inode(s) ignored (excluded by filters)
May 16 14:31:20 homer e-smith-bg:  0 inode(s) recorded as deleted from reference backup
May 16 14:31:20 homer e-smith-bg:  --------------------------------------------
May 16 14:31:20 homer e-smith-bg:  Total number of inode considered: 63152
May 16 14:31:20 homer e-smith-bg:  --------------------------------------------
May 16 14:31:20 homer e-smith-bg:
May 16 14:31:20 homer e-smith-bg: Listing Minimal2 archives on target:
May 16 14:31:25 homer e-smith-bg: total 7125504
May 16 14:31:25 homer e-smith-bg: -rwxr-xr-x  1 root admin 1073741824 May 16 12:37 2009.05.16.1.dar
May 16 14:31:25 homer e-smith-bg: -rwxr-xr-x  1 root admin 1073741824 May 16 12:56 2009.05.16.2.dar
May 16 14:31:25 homer e-smith-bg: -rwxr-xr-x  1 root admin 1073741824 May 16 13:15 2009.05.16.3.dar
May 16 14:31:25 homer e-smith-bg: -rwxr-xr-x  1 root admin 1073741824 May 16 13:35 2009.05.16.4.dar
May 16 14:31:25 homer e-smith-bg: -rwxr-xr-x  1 root admin 1073741824 May 16 13:54 2009.05.16.5.dar
May 16 14:31:25 homer e-smith-bg: -rwxr-xr-x  1 root admin 1073741824 May 16 14:14 2009.05.16.6.dar
May 16 14:31:25 homer e-smith-bg: -rwxr-xr-x  1 root admin  853976036 May 16 14:31 2009.05.16.7.dar
May 16 14:31:25 homer e-smith-bg: -rwxr-xr-x  1 root admin      46344 May 16 12:13 db.zip
May 16 14:31:25 homer e-smith-bg:
May 16 14:31:25 homer e-smith-bg: Total target disk space usage:
May 16 14:31:25 homer e-smith-bg: Filesystem            Size  Used Avail Use% Mounted on
May 16 14:31:25 homer e-smith-bg: /dev/sda1             299G   79G  220G  27% /media/usbdisk
May 16 14:31:25 homer e-smith-bg:
May 16 14:31:25 homer e-smith-bg: Executing post-backup event
May 16 14:31:27 homer esmith::event[9521]: Processing event: post-backup
May 16 14:31:27 homer esmith::event[9521]: Running event handler: /etc/e-smith/events/post-backup/S10mysql-delete-dumped-tables
May 16 14:31:27 homer esmith::event[9521]: S10mysql-delete-dumped-tables=action|Event|post-backup|Action|S10mysql-delete-dumped-tables|S$
May 16 14:31:27 homer esmith::event[9521]: Running event handler: /etc/e-smith/events/post-backup/S50rewind-tape
May 16 14:31:29 homer esmith::event[9521]: S50rewind-tape=action|Event|post-backup|Action|S50rewind-tape|Start|1242477087 733282|End|1242477089 29421|Elapsed|1.296139
May 16 14:31:29 homer esmith::event[9521]: Running event handler: /etc/e-smith/events/post-backup/S90eject-tape
May 16 14:31:30 homer esmith::event[9521]: S90eject-tape=action|Event|post-backup|Action|S90eject-tape|Start|1242477089 32280|End|1242477090 143047|Elapsed|1.110767
May 16 14:31:30 homer e-smith-bg: Dismounting /media/usbdisk
May 16 14:31:30 homer e-smith-bg:
May 16 14:31:30 homer e-smith-bg: Sat May 16 12:13:03 CEST 2009 - backup started
May 16 14:31:30 homer e-smith-bg: Sat May 16 14:31:30 CEST 2009 - backup finished


[superwormy]

Is there any other way to debug this stuff...? No output is written to /var/log/messages, and it doesn't seem to ever do anything.

Where are the files for installed modules stored? Maybe I can find out what it's running and why it's not running it properly...?

[cactus]

Is there any other way to debug this stuff...? No output is written to /var/log/messages, and it doesn't seem to ever do anything.

Then you (or the cronjob) did not start your backup job as at least it should try and start the pre-backup event, what is the output of

Code: [Select]

db dar2 showand the output of

Code: [Select]

grep 'pre-backup' /var/log/messages*

[superwormy]

[root@ldap-academickeys ~]# db dar2 show
Main Backup=dar2
    Backup=etc/e-smith/templates-custom,etc/e-smith/templates-user-custom,etc/group,etc/gshadow,etc/passwd,etc/samba/secrets.tdb,etc/samba/smbpasswd,etc/shadow,etc/smbpasswd,etc/ssh,etc/sudoers,home/e-smith,root
    Compression=4
    Description=Main Backup
    Exclude=
    Expiry=7
    Mount=/backup
    Password=
    Prune=
    Slice=650
    Target=/backup
    Username=
    VFSType=ext3
    Verbose=on
    backupDay=manual
    backupTime=23:30
    status=enabled
test backup=dar2
    Backup=etc/e-smith/templates-custom,etc/e-smith/templates-user-custom,etc/group,etc/gshadow,etc/passwd,etc/samba/secrets.tdb,etc/samba/smbpasswd,etc/shadow,etc/smbpasswd,etc/ssh,etc/sudoers,home/e-smith,root
    Compression=0
    Description=test backup 1
    Exclude=
    Expiry=0
    Mount=/backup
    Password=
    Prune=
    Slice=650
    Target=/backup
    Username=
    VFSType=ext3
    Verbose=on
    backupDay=manual
    backupTime=23:30
    status=enabled


[root@ldap-academickeys ~]# grep 'pre-backup' /var/log/messages*
/var/log/messages.20090515011203:May 19 09:55:40 ldap-academickeys esmith::event[28085]: Processing event: pre-backup desktop
/var/log/messages.20090515011203:May 19 09:55:40 ldap-academickeys esmith::event[28085]: generic_template_expand=action|Event|pre-backup|Action|generic_template_expand|Start|1242741340 656319|End|1242741340 987865|Elapsed|0.331546
/var/log/messages.20090515011203:May 19 09:55:40 ldap-academickeys esmith::event[28085]: Running event handler: /etc/e-smith/events/pre-backup/S10mysql-delete-dumped-tables
/var/log/messages.20090515011203:May 19 09:55:41 ldap-academickeys esmith::event[28085]: S10mysql-delete-dumped-tables=action|Event|pre-backup|Action|S10mysql-delete-dumped-tables|Start|1242741340 988212|End|1242741341 38123|Elapsed|0.049911
/var/log/messages.20090515011203:May 19 09:55:41 ldap-academickeys esmith::event[28085]: Running event handler: /etc/e-smith/events/pre-backup/S20mysql-dump-tables
/var/log/messages.20090515011203:May 19 09:55:42 ldap-academickeys esmith::event[28085]: S20mysql-dump-tables=action|Event|pre-backup|Action|S20mysql-dump-tables|Start|1242741341 38576|End|1242741342 25689|Elapsed|0.987113
/var/log/messages.20090515011203:May 19 09:55:42 ldap-academickeys esmith::event[28085]: Running event handler: /etc/e-smith/events/pre-backup/S50rewind-tape
/var/log/messages.20090515011203:May 19 09:55:42 ldap-academickeys esmith::event[28085]: S50rewind-tape=action|Event|pre-backup|Action|S50rewind-tape|Start|1242741342 26066|End|1242741342 142261|Elapsed|0.116195
[root@ldap-academickeys ~]#

[cactus]

# grep 'pre-backup' /var/log/messages*
/var/log/messages.20090515011203:May 19 09:55:40 ldap-academickeys esmith::event[28085]: Processing event: pre-backup desktop
/var/log/messages.20090515011203:May 19 09:55:40 ldap-academickeys esmith::event[28085]: generic_template_expand=action|Event|pre-backup|Action|generic_template_expand|Start|1242741340 656319|End|1242741340 987865|Elapsed|0.331546
/var/log/messages.20090515011203:May 19 09:55:40 ldap-academickeys esmith::event[28085]: Running event handler: /etc/e-smith/events/pre-backup/S10mysql-delete-dumped-tables
/var/log/messages.20090515011203:May 19 09:55:41 ldap-academickeys esmith::event[28085]: S10mysql-delete-dumped-tables=action|Event|pre-backup|Action|S10mysql-delete-dumped-tables|Start|1242741340 988212|End|1242741341 38123|Elapsed|0.049911
/var/log/messages.20090515011203:May 19 09:55:41 ldap-academickeys esmith::event[28085]: Running event handler: /etc/e-smith/events/pre-backup/S20mysql-dump-tables
/var/log/messages.20090515011203:May 19 09:55:42 ldap-academickeys esmith::event[28085]: S20mysql-dump-tables=action|Event|pre-backup|Action|S20mysql-dump-tables|Start|1242741341 38576|End|1242741342 25689|Elapsed|0.987113
/var/log/messages.20090515011203:May 19 09:55:42 ldap-academickeys esmith::event[28085]: Running event handler: /etc/e-smith/events/pre-backup/S50rewind-tape
/var/log/messages.20090515011203:May 19 09:55:42 ldap-academickeys esmith::event[28085]: S50rewind-tape=action|Event|pre-backup|Action|S50rewind-tape|Start|1242741342 26066|End|1242741342 142261|Elapsed|0.116195
[root@ldap-academickeys ~]#

So it did start... now go and have a scroll through that file and see if it explains you why it stopped.

[superwormy]

Those messages are all from the 'Backup or Restore' tab of SME server, not from the 'Disk ARchive' module of SME server.

Again, is there a way to see the actual commands SME server is trying to run? Where is the code that actually invokes the command line DAR application?

[janet]

superwormy

Again, is there a way to see the actual commands SME server is trying to run? Where is the code that actually invokes the command line DAR application?

Have you done an "advanced" search on these forums ie on dar2, going back a year or two as well.

Darrell May has posted extensive command line troubleshooting info about dar2

[superwormy]

*groan* 

The DAR2 module doesn't support spaces in the 'Job Name'.

It says this in a note, but there is no validation and I didn't read the note. DAR2 backups with spaces in the file name will silently fail, and not write any log messages anywhere, but still tell you it succeeded in the web panel: "Operation status report   Success"

For anyone else who reads this or needs help with DAR2, the best way to check for errors is to run it from the command line:

/etc/e-smith/events/actions/dar2-backup your-job-name-here

[Stefano]

*groan* 

The DAR2 module doesn't support spaces in the 'Job Name'.

It says this in a note, but there is no validation and I didn't read the note. DAR2 backups with spaces in the file name will silently fail, and not write any log messages anywhere, but still tell you it succeeded in the web panel: "Operation status report   Success"

For anyone else who reads this or needs help with DAR2, the best way to check for errors is to run it from the command line:

/etc/e-smith/events/actions/dar2-backup your-job-name-here

sounds like a bug for me, even if it is said in a note..

please open a bug or, better, a NFR  for validation

Ciao
Stefano

[superwormy]

Hah, I can't. The bug tracker is broken.

I'm trying to create a new account here:
http://bugs.contribs.org/createaccount.cgi

And after I click the submit button:

Forbidden
You don't have permission to access /createaccount.cgi on this server.
Apache/2.2.3 (CentOS) Server at bugs.contribs.org Port 80

[superwormy]

Here's another item to add to the bug report:

You can back up to vfat FAT32 disks by choosing the 'ext3' option. However, it's sort of misleading to have to choose 'ext3' when it's really 'vfat'.

Seems to work just fine though.

[cactus]

Hah, I can't. The bug tracker is broken.

I'm trying to create a new account here:
http://bugs.contribs.org/createaccount.cgi

And after I click the submit button:

Forbidden
You don't have permission to access /createaccount.cgi on this server.
Apache/2.2.3 (CentOS) Server at bugs.contribs.org Port 80

It seems to work now. Just tested it.