Hello Arno,

If this is happening on 1.37.38, then it certainly merits a bug report. A bug 
report is the only way I can properly deal with a complicated problem.  
Please don't worry about lengthy reports -- that is not a problem. What is 
important is that I can either "see" the problem or reproduce it.  

Having an exact copy of the error message is important -- see below:

On Wednesday 14 September 2005 15:53, Arno Lehmann wrote:
> Hi,
>
> I've just experienced something similar, and, because I use version
> 1.37.38 I copy the devel list.
>
> The error:
> "Number of files mismatch!"

I assume you are summarizing here since I don't think that is the exact 
message that Bacula prints.

>
> In this case, the catalog has 2, the volme 2 files.

Huh.  Why would it complain if both have the same number of files?

>
> Interestingly, this tape from a pool where this morning a job from one
> client should go, but the job had an error:
>
> 14-Sep 09:42 goblin-sd: BeowulfStd.2005-09-14_08.20.01 Fatal error:
> acquire.c:359 Wanted Volume "DAT-120-0043", but device "HP DAT 0"
> (/dev/nst1) is busy writing on "DAT-120-0022" .
> 14-Sep 09:42 beowulf-fd: BeowulfStd.2005-09-14_08.20.01 Fatal error:
> c:\cygwin\home\kern\bacula\k\src\win32\filed\../../filed/job.c:1597 Bad
> response to Append Data command. Wanted 3000 OK data
> , got 3903 Error append data
>
> The tape in question is:
> > Choose a query (1-19): Unexpected question has been received.
> > 15
> > Enter Volume name: Unexpected question has been received.
> > DAT-120-0042
> > +-------+------------+---------------------+------+-------+-------+------
> >---------+--------+
> >
> > | JobId | Name       | StartTime           | Type | Level | Files | Bytes
> > |         | Status |
> >
> > +-------+------------+---------------------+------+-------+-------+------
> >---------+--------+
> >
> > | 3,057 | DracheStd  | 2005-08-31 08:20:01 | B    | D     | 2,525 |  
> > | 986,900,617 | T      | 3,058 | BeowulfStd | 2005-08-31 08:20:05 | B   
> > | | D     | 1,685 |   930,059,897 | T      | 3,227 | BeowulfStd |
> > | 2005-09-14 09:48:21 | B    | D     | 3,394 | 1,929,569,994 | T      |
> >
> > +-------+------------+---------------------+------+-------+-------+------
> >---------+--------+
>
> The job report for the manually started job from Beowulf looks like this:
> > 14-Sep 09:48 goblin-dir: Prior failed job found. Upgrading to
> > Differential. 14-Sep 09:48 goblin-dir: RunBefore: Host beowulf is up.
> > 14-Sep 09:48 goblin-dir: Start Backup JobId 3227,
> > Job=BeowulfStd.2005-09-14_09.48.21 14-Sep 09:48 goblin-sd: Job
> > BeowulfStd.2005-09-14_09.48.21 waiting to reserve a device. 14-Sep 10:01
> > beowulf-fd: DIR and FD clocks differ by 1 seconds, FD automatically
> > adjusting. 14-Sep 10:01 beowulf-fd: ClientRunBeforeJob: Saving
> > registry...
> > 14-Sep 10:02 beowulf-fd: ClientRunBeforeJob: Registry done. Now saving
> > systemstate according to ntbackup 14-Sep 10:06 beowulf-fd:
> > ClientRunBeforeJob: Pre-Backup work done. 14-Sep 10:07 goblin-sd: Please
> > mount Volume "DAT-120-0043" on Storage Device "HP DAT 0" (/dev/nst1) for
> > Job BeowulfStd.2005-09-14_09.48.21 14-Sep 10:53 goblin-sd:
> > BeowulfStd.2005-09-14_09.48.21 Warning: Director wanted Volume
> > "DAT-120-0043". Current Volume "DAT-120-0041" not acceptable because:
> >     1998 Volume "DAT-120-0041" status is Full, but should be Append,
> > Purged or Recycle. 14-Sep 10:53 goblin-sd: 3301 Issuing autochanger
> > "loaded drive 0" command. 14-Sep 10:53 goblin-sd: 3302 Autochanger
> > "loaded drive 0", result is Slot 5. 14-Sep 10:53 goblin-sd: 3307 Issuing
> > autochanger "unload slot 5, drive 0" command. 14-Sep 10:53 goblin-sd:
> > 3304 Issuing autochanger "load slot 4, drive 0" command. 14-Sep 10:54
> > goblin-sd: 3305 Autochanger "load slot 4, drive 0", status is OK. 14-Sep
> > 10:54 goblin-sd: 3301 Issuing autochanger "loaded drive 0" command.
> > 14-Sep 10:54 goblin-sd: 3302 Autochanger "loaded drive 0", result is Slot
> > 4. 14-Sep 10:54 goblin-sd: Volume "DAT-120-0043" previously written,
> > moving to end of data. 14-Sep 10:55 goblin-sd: Ready to append to end of
> > Volume "DAT-120-0043" at file=7. 14-Sep 10:55 goblin-sd: Spooling data
> > ...
> > 14-Sep 10:55 beowulf-fd: Generate VSS snapshots. Driver="VSS WinXP",
> > Drive(s)="C" 14-Sep 10:55 beowulf-fd: VSS Writer: "MSDEWriter", State: 1
> > (VSS_WS_STABLE) 14-Sep 10:55 beowulf-fd: VSS Writer: "WMI Writer", State:
> > 5 (VSS_WS_WAITING_FOR_BACKUP_COMPLETE) 14-Sep 10:55 beowulf-fd: VSS
> > Writer: "Microsoft Writer (Service State)", State: 1 (VSS_WS_STABLE)
> > 14-Sep 10:55 beowulf-fd: VSS Writer: "Microsoft Writer (Bootable State)",
> > State: 1 (VSS_WS_STABLE) 14-Sep 11:08 goblin-sd: Committing spooled data
> > to Volume. Despooling 1,932,554,590 bytes ... 14-Sep 11:44 goblin-sd: End
> > of Volume "DAT-120-0043" at 8:14178 on device "HP DAT 0" (/dev/nst1).
> > Write of 64512 bytes got -1. 14-Sep 11:44 goblin-sd: Re-read of last
> > block succeeded.
> > 14-Sep 11:44 goblin-sd: End of medium on Volume "DAT-120-0043"
> > Bytes=7,584,615,071 Blocks=117,572 at 14-Sep-2005 11:44. 14-Sep 11:46
> > goblin-sd: 3301 Issuing autochanger "loaded drive 0" command. 14-Sep
> > 11:46 goblin-sd: 3302 Autochanger "loaded drive 0", result is Slot 4.
> > 14-Sep 11:46 goblin-sd: 3307 Issuing autochanger "unload slot 4, drive 0"
> > command. 14-Sep 11:46 goblin-sd: 3304 Issuing autochanger "load slot 3,
> > drive 0" command. 14-Sep 11:47 goblin-sd: 3305 Autochanger "load slot 3,
> > drive 0", status is OK. 14-Sep 11:47 goblin-sd: 3301 Issuing autochanger
> > "loaded drive 0" command. 14-Sep 11:47 goblin-sd: 3302 Autochanger
> > "loaded drive 0", result is Slot 3. 14-Sep 11:47 goblin-sd: Volume
> > "DAT-120-0042" previously written, moving to end of data. 14-Sep 11:47
> > goblin-sd: Ready to append to end of Volume "DAT-120-0042" at file=2.
> > 14-Sep 11:47 goblin-sd: New volume "DAT-120-0042" mounted on device "HP
> > DAT 0" (/dev/nst1) at 14-Sep-2005 11:47. 14-Sep 11:48 goblin-sd: Sending
> > spooled attrs to the Director. Despooling 1,278,547 bytes ... 14-Sep
> > 11:49 beowulf-fd: ClientRunAfterJob: Deleting temporary files 14-Sep
> > 11:49 goblin-dir: Bacula 1.37.38 (04Sep05): 14-Sep-2005 11:49:11 JobId:  
> >                3227
> >   Job:                    BeowulfStd.2005-09-14_09.48.21
> >   Backup Level:           Differential (upgraded from Differential)
> >   Client:                 "beowulf-fd" Windows XP,MVS,NT 5.1.2600
> >   FileSet:                "WindowsXP-C" 2005-01-12 10:49:17
> >   Pool:                   "Diff"
> >   Storage:                "HPDAT"
> >   Scheduled time:         14-Sep-2005 09:48:18
> >   Start time:             14-Sep-2005 09:48:21
> >   End time:               14-Sep-2005 11:49:11
> >   Priority:               10
> >   FD Files Written:       3,394
> >   SD Files Written:       3,394
> >   FD Bytes Written:       1,929,569,994
> >   SD Bytes Written:       1,930,300,576
> >   Rate:                   266.1 KB/s
> >   Software Compression:   None
> >   Volume name(s):         DAT-120-0043|DAT-120-0042
> >   Volume Session Id:      8
> >   Volume Session Time:    1126675939
> >   Last Volume Bytes:      1,926,310,601
> >   Non-fatal FD errors:    0
> >   SD Errors:              0
> >   FD termination status:  OK
> >   SD termination status:  OK
> >   Termination:            Backup OK
>
> So, bacula knows that this job went to this volume but didn't correctly
> update it's catalog!?

It seems that something must be going wrong when switching pools.
Sometimes an "llist volume=xxx" before and after the job can help ...

>
> My problem troubleshooting all this is that I only see these problems
> when running multiple jobs in parallel, and using different pools where
> jobs have to wait for one another... the resulting debug output and
> console log is accordingly a little long :-)
>
> Arno
>
> On 14.09.2005 15:13, Alan Brown wrote:
> > On Tue, 13 Sep 2005, Arunav Mandal wrote:
> >>> I understand this is a known bug, fixed in CVS.
> >>
> >> What happens when I change the error to Append manually will the tape
> >> be used again?
> >
> > I've tried this, it errors again. Switch the tape to used and let it
> > expire, or purge it if the incomplete backup is the only thing on the
> > tape.
> >
> >
> >
> >
> > -------------------------------------------------------
> > SF.Net email is sponsored by:
> > Tame your development challenges with Apache's Geronimo App Server.
> > Download it for free - -and be entered to win a 42" plasma tv or your
> > very own Sony(tm)PSP.  Click here to play:
> > http://sourceforge.net/geronimo.php
> > _______________________________________________
> > Bacula-users mailing list
> > Bacula-users@lists.sourceforge.net
> > https://lists.sourceforge.net/lists/listinfo/bacula-users

-- 
Best regards,

Kern

  (">
  /\
  V_V


-------------------------------------------------------
SF.Net email is sponsored by:
Tame your development challenges with Apache's Geronimo App Server. 
Download it for free - -and be entered to win a 42" plasma tv or your very
own Sony(tm)PSP.  Click here to play: http://sourceforge.net/geronimo.php
_______________________________________________
Bacula-users mailing list
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users

Reply via email to