Hello,
On Wed, 2008-09-24 at 17:56 +0200, Kern Sibbald wrote:
> On Wednesday 24 September 2008 16:19:29 Ulrich Leodolter wrote:
> > Hello,
> >
> > ok, i've started bacula-fd in debug mode
> >
> > leodolter:~# nohup /opt/bacula/sbin/bacula-fd -f -d 200 -u root -g bacula \
> > -c /opt/bacula/etc/bacula-fd.conf >& /tmp/bacula-fd.log
> >
> > then i've started 2 consecutive incremental backups, and again looked at
> > /usr/bin/wget, (i can send u 350MB debug file if u like)
> >
> > leodolter:~# fgrep '/usr/bin/wget' /tmp/bacula-fd.log
> > leodolter-fd: htable.c:288-3680 Insert hp->next=0 hp->hash=0x59616a69
> > hp->key=/usr/bin/wget leodolter-fd: htable.c:294-3680 Leave insert
> > index=25223 num_items=50014 key=/usr/bin/wget leodolter-fd:
> > backup.c:1210-3680 No strip for /usr/bin/wget
> > leodolter-fd: accurate.c:182-3680 /usr/bin/wget st_mtime differs
> > leodolter-fd: backup.c:307-3680 FT_REG saving: /usr/bin/wget
> > leodolter-fd: backup.c:402-3680 bfiled: sending /usr/bin/wget to stored
> > leodolter-fd: backup.c:1210-3680 No strip for /usr/bin/wget
> > leodolter-fd: bfile.c:835-3680 open file /usr/bin/wget
> > leodolter-fd: htable.c:288-3681 Insert hp->next=0 hp->hash=0x59616a69
> > hp->key=/usr/bin/wget leodolter-fd: htable.c:294-3681 Leave insert
> > index=25223 num_items=50014 key=/usr/bin/wget leodolter-fd:
> > backup.c:1210-3681 No strip for /usr/bin/wget
> > leodolter-fd: accurate.c:182-3681 /usr/bin/wget st_mtime differs
> > leodolter-fd: backup.c:307-3681 FT_REG saving: /usr/bin/wget
> > leodolter-fd: backup.c:402-3681 bfiled: sending /usr/bin/wget to stored
> > leodolter-fd: backup.c:1210-3681 No strip for /usr/bin/wget
> > leodolter-fd: bfile.c:835-3681 open file /usr/bin/wget
> >
> > as u see , st_mtime is the reason.
> > but i am very sure that st_mtime did not change between incremental
> > backups! verified that st_time did not change using a simple perl script
> > called it before and after incremental jobs.
>
> When I look at the above, it looks perfectly normal to me. I see that
> st_mtime is different from the last backup, but that you are running two
> simultaneous jobs that seem to have the same FileSet, so they both want to
> save the same file. This is normal. If you want the second job to take into
> account what the first job backs up, you must ensure that it starts after the
> first job has finished.
>
I have started the second Job after the first finished, look at Start
and End time below, there are 2 minutes between. Look also at
the number of Files written, this looks very strange to me!
i am sure my system does not touch or modify more than 20000 files in 2
minutes. /usr/bin/wget i just an example.
again: when i look at the file names backed up, i looks like accurate
incremental backups are only compared against last full.
Build OS: i686-pc-linux-gnu redhat Enterprise release
JobId: 3680
Job: Backup-leodolter.2008-09-24_15.49.11
Backup Level: Incremental, since=2008-09-24 02:05:06
Client: "leodolter-fd" 2.5.3 (16Sep08)
i686-pc-linux-gnu,debian,lenny/sid
FileSet: "LinuxLocalPartitions" 2008-05-23 14:56:44
Pool: "DiskBackup" (From Job resource)
Catalog: "MyCatalog" (From Client resource)
Storage: "File" (From Job resource)
Scheduled time: 24-Sep-2008 15:48:58
Start time: 24-Sep-2008 15:49:03
End time: 24-Sep-2008 15:51:32
Elapsed time: 2 mins 29 secs
Priority: 10
FD Files Written: 22,297
SD Files Written: 22,297
FD Bytes Written: 249,462,630 (249.4 MB)
SD Bytes Written: 252,590,613 (252.5 MB)
Rate: 1674.2 KB/s
Software Compression: 63.2 %
VSS: no
Encryption: no
Accurate: yes
Volume name(s): Backup-0158
Volume Session Id: 178
Volume Session Time: 1221573719
Last Volume Bytes: 2,297,116,205 (2.297 GB)
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Backup OK
Build OS: i686-pc-linux-gnu redhat Enterprise release
JobId: 3681
Job: Backup-leodolter.2008-09-24_15.53.12
Backup Level: Incremental, since=2008-09-24 15:49:03
Client: "leodolter-fd" 2.5.3 (16Sep08)
i686-pc-linux-gnu,debian,lenny/sid
FileSet: "LinuxLocalPartitions" 2008-05-23 14:56:44
Pool: "DiskBackup" (From Job resource)
Catalog: "MyCatalog" (From Client resource)
Storage: "File" (From Job resource)
Scheduled time: 24-Sep-2008 15:53:32
Start time: 24-Sep-2008 15:53:43
End time: 24-Sep-2008 15:56:18
Elapsed time: 2 mins 35 secs
Priority: 10
FD Files Written: 22,299
SD Files Written: 22,299
FD Bytes Written: 249,462,803 (249.4 MB)
SD Bytes Written: 252,591,047 (252.5 MB)
Rate: 1609.4 KB/s
Software Compression: 63.2 %
VSS: no
Encryption: no
Accurate: yes
Volume name(s): Backup-0158
Volume Session Id: 179
Volume Session Time: 1221573719
Last Volume Bytes: 2,550,602,312 (2.550 GB)
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Backup OK
> If you really think that st_mtime has not changed since the last backup, then
> please find the backup record in the catalog associated with the previous
> backup job, and list it as well as the backup record from one of the two jobs
> above.
>
There a 2 minutes between End time of Job 3680
and Start time of Job 3681 (see above)
I don't think, i am sure st_time of /usr/bin/wget did not change.
I used system call lstat to read st_mtime before i started Job 3680
and after Job 3681 finished, it was exactly the same.
Bacula reports different st_mtime, but stores the same st_mtime.
Look at the sql query result, u can see that only the 11'th column st_atime
in LStat changed,
which is totally correct, but st_mtime and st_ctime are the same.
(hopefully your email reader does not break lines)
mysql> select File.JobId, File.FileId,
Filename.Name,Path.Path,File.LStat,File.MD5 from File
join Filename using (FilenameId)
join Path using (PathId) where File.JobId in (3680,3681) and Filename.Name =
'wget';
+-------+----------+------+-----------+------------------------------------------------------------+-----------------------------+
| JobId | FileId | Name | Path | LStat
| MD5 |
+-------+----------+------+-----------+------------------------------------------------------------+-----------------------------+
| 3680 | 79476174 | wget | /usr/bin/ | P4A HECd IHt B A A A 3PU BAA HI BI2kMY
BIxGDt BI11Hr A A E | FyVUN2j34bKjITbKF5khOovbiGs |
| 3681 | 79498472 | wget | /usr/bin/ | P4A HECd IHt B A A A 3PU BAA HI BI2kWI
BIxGDt BI11Hr A A E | FyVUN2j34bKjITbKF5khOovbiGs |
+-------+----------+------+-----------+------------------------------------------------------------+-----------------------------+
2 rows in set (0.22 sec)
> I may be missing something here, but this looks normal to me. I cannot rule
> out a bug with st_mtime with the new code, but I would like to see more
> information before asking Eric to look into it.
>
> Regards,
>
> Kern
>
Thanks
Ulrich
> >
> > so please tell me which st_mtime are compared?
> > (maybe there is a hash code bug in accurrate.c, just thinking
> > because i dont understand)
> >
> > [EMAIL PROTECTED]:~$ bin/ul_bacula_lstat.pl /usr/bin/wget
> > dev = 65024 P4A
> > ino = 1851549 HECd
> > mode = 33261 IHt
> > nlink = 1 B
> > uid = 0 A
> > gid = 0 A
> > rdev = 0 A
> > size = 226260 3PU
> > atime = 1222265400 BI2ko4
> > mtime = 1220829421 BIxGDt
> > ctime = 1222070763 BI11Hr
> > blksize = 4096 BAA
> > blocks = 456 HI
> > sha1 = FyVUN2j34bKjITbKF5khOovbiGs
> >
> >
> > mysql> select File.JobId, Filename.Name,Path.Path,File.LStat,File.MD5 from
> > File join Filename using (FilenameId)
> > join Path using (PathId) where File.JobId in
> > (3574,3605,3637,3669,3680,3681) and Filename.Name = 'wget';
> > +-------+------+-----------+-----------------------------------------------
> >-------------+-----------------------------+
> >
> > | JobId | Name | Path | LStat
> > | | MD5 |
> >
> > +-------+------+-----------+-----------------------------------------------
> >-------------+-----------------------------+
> >
> > | 3574 | wget | /usr/bin/ | P4A HEEh IHt B A A A 3PU BAA HI BIz28l BIaVNu
> > | BIfhPi A A E | 8dz2rHajxE25WMWnQ2U6DUja/MI | 3637 | wget | /usr/bin/ |
> > | P4A HECd IHt B A A A 3PU BAA HI BI2CXZ BIxGDt BI11Hr A A E |
> > | FyVUN2j34bKjITbKF5khOovbiGs | 3669 | wget | /usr/bin/ | P4A HECd IHt B A
> > | A A 3PU BAA HI BI2DL7 BIxGDt BI11Hr A A E | FyVUN2j34bKjITbKF5khOovbiGs |
> > | 3680 | wget | /usr/bin/ | P4A HECd IHt B A A A 3PU BAA HI BI2kMY BIxGDt
> > | BI11Hr A A E | FyVUN2j34bKjITbKF5khOovbiGs | 3681 | wget | /usr/bin/ |
> > | P4A HECd IHt B A A A 3PU BAA HI BI2kWI BIxGDt BI11Hr A A E |
> > | FyVUN2j34bKjITbKF5khOovbiGs |
> >
> > +-------+------+-----------+-----------------------------------------------
> >-------------+-----------------------------+
> >
> >
> > Please have a closer look at this
> > Ulrich
> >
> > On Wed, 2008-09-24 at 14:01 +0200, Eric Bollengier wrote:
> > > Hello,
> > >
> > > On Wednesday 24 September 2008 13:34:53 Kern Sibbald wrote:
> > > > Hello,
> > > >
> > > > On Wednesday 24 September 2008 11:52:41 Ulrich Leodolter wrote:
> > > > > Hi,
> > > > >
> > > > > I looks like Accurate Incremental backups work not like expected.
> > > > >
> > > > > I am using current bacula trunk, last update 2008-09-16.
> > > > > No config changes since last update.
> > > > >
> > > > > Below is a Job list where i tried to track down the problem.
> > > > > On Monday Sep 22 i did a system update (apt-get), so 20794 Files are
> > > > > ok for Job 3637. But i did not make major changes on Sep 23, so 21725
> > > > > Files for Job 3669 are not expected!
> > > > >
> > > > >
> > > > > JobId JobName Status Level Client Pool StartTime EndTime Duration
> > > > > Files Bytes 3574 Backup-leodolter OK F leodolter-fd DiskBackup
> > > > > 08-Sep-21 02:05 08-Sep-21 02:26 00:21:45 178,917 4.5 GB 3605
> > > > > Backup-leodolter OK I leodolter-fd DiskBackup 08-Sep-22 02:05
> > > > > 08-Sep-22 02:06 00:01:27 202 13.3 MB 3637 Backup-leodolter OK I
> > > > > leodolter-fd DiskBackup 08-Sep-23 02:05 08-Sep-23 02:07 00:02:34
> > > > > 20,794 187.6 MB 3669 Backup-leodolter OK I leodolter-fd DiskBackup
> > > > > 08-Sep-24 02:05 08-Sep-24 02:07 00:02:42 21,725 192.6 MB
> > > > >
> > > > >
> > > > > Now i looked at some special file /usr/bin/wget (see mysql select
> > > > > below) As far as i can see only st_atime (11'th field in LStat)
> > > > > changed from 23 Sep (JobId 3637) to 24 Sep (JobId 3669).
> > > > >
> > > > > Until now i thought st_atime is not used for Accurate backups.
> > > >
> > > > To the best of my knowledge, st_atime is not used by Bacula to make any
> > > > decision whether or not to backup the file. The tests are strictly
> > > > against st_mtime and st_ctime (depending on how you configure Bacula).
> > > >
> > > > It sounds to me like you have a problem of an anti-virus program that
> > > > is "touching" some files or some other change to your system happened.
> > > > Running verify InitCatalog, then later Catalog can verify this ...
> > > >
> > > > > For me i looks like Accurate Incremental backups are always made
> > > > > against last Full while ignoring previous Accurate Incremental jobs
> > > > > (maybe i am completely wrong)
> > > >
> > > > I haven't taken a careful look at all the details you presented above,
> > > > but Accurate works very much like existing backups -- that is it looks
> > > > at st_mtime and st_ctime (if I am not mistaken), and if the file needs
> > > > to be backed up for the "normal" backup reasons, it will be. What
> > > > Accurate does is in *addition* to the "normal" rules, it will check to
> > > > see if a file has been deleted or has been added with an old date, and
> > > > in those cases, it ensures that files that are deleted are so marked,
> > > > and any file that is missed by the normal backup will also be backed
> > > > up.
> > > >
> > > > I'll let Eric confirm this.
> > >
> > > I confirm :)
> > >
> > > Ulrich, you can try to run the the FD at debuglevel 200, and you will see
> > > why the file has been backuped.
> > >
> > > Bye
> > >
> > > > If it is not working like I described above, then please let me know
> > > > and we can look at it in more details.
> > > >
> > > > Best regards,
> > > >
> > > > Kern
> > > >
> > > > > mysql> select File.JobId, Filename.Name,Path.Path,File.LStat,File.MD5
> > > > > from File join Filename using (FilenameId)
> > > > > join Path using (PathId)
> > > > > where File.JobId in (3574,3605,3637,3669) and Filename.Name =
> > > > > 'wget';
> > > > >
> > > > > +-------+------+-----------+-----------------------------------------
> > > > >---- -- -------------+-----------------------------+
> > > > >
> > > > > | JobId | Name | Path | LStat
> > > > > |
> > > > > | | MD5 |
> > > > >
> > > > > +-------+------+-----------+-----------------------------------------
> > > > >---- -- -------------+-----------------------------+
> > > > >
> > > > > | 3574 | wget | /usr/bin/ | P4A HEEh IHt B A A A 3PU BAA HI BIz28l
> > > > > | BIaVNu BIfhPi A A E | 8dz2rHajxE25WMWnQ2U6DUja/MI | 3637 | wget |
> > > > > | /usr/bin/ | P4A HECd IHt B A A A 3PU BAA HI BI2CXZ BIxGDt BI11Hr A
> > > > > | A E
> > > > > |
> > > > > | FyVUN2j34bKjITbKF5khOovbiGs | 3669 | wget | /usr/bin/ | P4A HECd
> > > > > | IHt B A A A 3PU BAA HI BI2DL7 BIxGDt BI11Hr A A E |
> > > > > | FyVUN2j34bKjITbKF5khOovbiGs |
> > > > >
> > > > > +-------+------+-----------+-----------------------------------------
> > > > >---- -- -------------+-----------------------------+ 3 rows in set
> > > > > (0.00 sec)
> > > > >
> > > > >
> > > > > Please have a look at this
> > > > > Thanks
>
>
>
-------------------------------------------------------------------------
This SF.Net email is sponsored by the Moblin Your Move Developer's challenge
Build the coolest Linux based applications with Moblin SDK & win great prizes
Grand prize is a trip for two to an Open Source event anywhere in the world
http://moblin-contest.org/redirect.php?banner_id=100&url=/
_______________________________________________
Bacula-devel mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/bacula-devel
