With amanda-2.6.0, when I try to amrestore an archive from a tape which was created with 2.5.x or 2.6.0 version, I get this error message : gzip: stdin: not in gzip format Error writing fd 6: Broken pipe If I try to amrecover a file from a tape which was created with 2.5.x or 2.6.0 version, I get this error message : tar: This does not look like a tar archive tar: ./dir/file.ext: Not found in archive tar: Error exit delayed from previous errors Extractor child exited with status 2 It will never happen if I restore the same file or archive with amanda 2.5.x Reproducible: Always Steps to Reproduce: 1. install amanda 2.6.0_p2-r4 2. try to amrestore an archive or amrecover a file from a tape Expected Results: Restore correctly the file or archive Installed packages : app-arch/tar-1.20 app-arch/gzip-1.3.12-r1 porcinet ~ # emerge --info Portage 2.1.6.11 (default/linux/x86/2008.0, gcc-4.3.2, glibc-2.8_p20080602-r1, 2.6.28-gentoo-r5 i686) ================================================================= System uname: Linux-2.6.28-gentoo-r5-i686-Intel-R-_Pentium-R-_III_CPU_family_1133MHz-with-glibc2.0 Timestamp of tree: Thu, 07 May 2009 01:30:16 +0000 app-shells/bash: 3.2_p39 dev-lang/python: 2.5.4-r2 dev-python/pycrypto: 2.0.1-r6 sys-apps/baselayout: 1.12.11.1 sys-apps/sandbox: 1.6-r2 sys-devel/autoconf: 2.13, 2.63 sys-devel/automake: 1.4_p6, 1.5, 1.6.3, 1.7.9-r1, 1.8.5-r3, 1.9.6-r2, 1.10.2 sys-devel/binutils: 2.18-r3 sys-devel/gcc-config: 1.4.0-r4 sys-devel/libtool: 1.5.26 virtual/os-headers: 2.6.27-r2 ACCEPT_KEYWORDS="x86" CBUILD="i686-pc-linux-gnu" CFLAGS="-O2 -march=pentium3 -pipe -fomit-frame-pointer" CHOST="i686-pc-linux-gnu" CONFIG_PROTECT="/etc" CONFIG_PROTECT_MASK="/etc/ca-certificates.conf /etc/env.d /etc/gconf /etc/php/apache2-php4/ext-active/ /etc/php/apache2-php5/ext-active/ /etc/php/cgi-php4/ext-active/ /etc/php/cgi-php5/ext-active/ /etc/php/cli-php4/ext-active/ /etc/php/cli-php5/ext-active/ /etc/revdep-rebuild /etc/sandbox.d /etc/terminfo /etc/udev/rules.d" CXXFLAGS="-O2 -march=pentium3 -pipe -fomit-frame-pointer" DISTDIR="/usr/portage/distfiles" FEATURES="distlocks fixpackages parallel-fetch protect-owned sandbox sfperms strict unmerge-orphans userfetch" GENTOO_MIRRORS="ftp://mirror.ovh.net/gentoo-distfiles" LANG="en_US.UTF-8" LC_ALL="en_US.UTF-8" LDFLAGS="-Wl,-O1" PKGDIR="/usr/portage/packages" PORTAGE_CONFIGROOT="/" PORTAGE_RSYNC_OPTS="--recursive --links --safe-links --perms --times --compress --force --whole-file --delete --stats --timeout=180 --exclude=/distfiles --exclude=/local --exclude=/packages" PORTAGE_TMPDIR="/var/tmp" PORTDIR="/usr/portage" PORTDIR_OVERLAY="/usr/local/portage" SYNC="rsync://rsync.gentoo.org/gentoo-portage" USE="acl apache2 berkdb bzip2 cgi cli cracklib crypt dri fortran gd gdbm iconv isdnlog jpeg mbox midi mudflap mysql ncurses nls nptl nptlonly openmp pam pcre perl php png postgres pppd python readline reflection session spl ssl symlink sysfs tcpd unicode urandom usb x86 xinetd xml xorg zlib" ALSA_CARDS="ali5451 als4000 atiixp atiixp-modem bt87x ca0106 cmipci emu10k1 emu10k1x ens1370 ens1371 es1938 es1968 fm801 hda-intel intel8x0 intel8x0m maestro3 trident usb-audio via82xx via82xx-modem ymfpci" ALSA_PCM_PLUGINS="adpcm alaw asym copy dmix dshare dsnoop empty extplug file hooks iec958 ioplug ladspa lfloat linear meter mmap_emul mulaw multi null plug rate route share shm softvol" APACHE2_MODULES="actions alias auth_basic auth_digest authn_anon authn_dbd authn_dbm authn_default authn_file authz_dbm authz_default authz_groupfile authz_host authz_owner authz_user autoindex cache dav dav_fs dav_lock dbd deflate dir disk_cache env expires ext_filter file_cache filter headers ident imagemap include info log_config logio mem_cache mime mime_magic negotiation proxy proxy_ajp proxy_balancer proxy_connect proxy_http rewrite setenvif so speling status unique_id userdir usertrack vhost_alias" ELIBC="glibc" INPUT_DEVICES="keyboard mouse evdev" KERNEL="linux" LCD_DEVICES="bayrad cfontz cfontz633 glk hd44780 lb216 lcdm001 mtxorb ncurses text" USERLAND="GNU" VIDEO_CARDS="fbdev glint i810 intel mach64 mga neomagic nv r128 radeon savage sis tdfx trident vesa vga via vmware voodoo" Unset: CPPFLAGS, CTARGET, EMERGE_DEFAULT_OPTS, FFLAGS, INSTALL_MASK, LINGUAS, MAKEOPTS, PORTAGE_COMPRESS, PORTAGE_COMPRESS_FLAGS, PORTAGE_RSYNC_EXTRA_OPTS
What options are you passing to amrecover/amrestore? If you glance at the start of the restored file, maybe it still has the Amanda header on it because of options you gave? We're going to need your main amanda config and your dumptype definitions as well.
Created attachment 190904 [details] Main amanda config file
For amrestore, I type : amrestore /dev/nst0 hostname diskname For amrecover, I type : amrecover configname and then I type setdate and setdisk I attached my amanda.conf but what do you mean by dumptypes definitions ? Are you talking about my disklist file ? Thanks.
(In reply to comment #3) > I attached my amanda.conf but what do you mean by dumptypes definitions ? Are > you talking about my disklist file ? Yes, show at least the DLE (disklist entry) you try to restore. Did you change your config somehow when you upgraded to 2.6.0 (should be irrelevant anyway, restores should simply read what's on the tape, amrestore doesn't need much of the configs afaik) ? So you are able to amrestore exactly the *same* tape with 2.5.x which fails with amrestore from 2.6.x ?
Here is the disklist entry I try to restore (but all the disklist entries fail to restore anyway) : servername /data/users/autres tar-client-best I changed nothing in my amanda config when I updated to 2.6.0 (except the paths in the amanda related xinetd config file). And yes, I can succesfully amrestore (or amrecover) exactly the same files from exactly the same tape with 2.5.x version. I've just tried it again a few minutes ago. I don't know if that could help but I've tried to extract headers from the dumped disk entry with the command : amrestore -h /dev/nst0 hostname diskname I've tried this either with the 2.5.x and the 2.6.0 version. The output is exactly the same if I type : dd if=headersfile bs=32k count=1 : AMANDA: FILE 20090507231501 servername /data/users/autres lev 0 comp .gz program /bin/tar To restore, position tape at start of file and run: dd if=<tape> bs=32k skip=1 | /bin/gzip -dc | /bin/tar -f - ... 1+0 records in 1+0 records out 32768 bytes (33 kB) copied, 0.00282425 s, 11.6 MB/s
(In reply to comment #5) > And yes, I can succesfully amrestore (or amrecover) exactly the same files from > exactly the same tape with 2.5.x version. I've just tried it again a few > minutes ago. > > I don't know if that could help but I've tried to extract headers from the > dumped disk entry with the command : amrestore -h /dev/nst0 hostname diskname > I've tried this either with the 2.5.x and the 2.6.0 version. The output is > exactly the same if I type : dd if=headersfile bs=32k count=1 : So the tape seems to be OK ... I think we would have to look at the amanda-debugfiles and/or logfiles to see if anything fails there. Seems as if it uses the wrong commands to extract the data. You could also compare the output of "amadmin config version" to see if amanda uses the correct paths to tools like tar and gzip etc. (it needs them to access the data)
Here is the output of the "amadmin config version" command : build: VERSION="Amanda-2.5.1p3" BUILT_DATE="Mon May 11 10:26:48 CEST 2009" BUILT_MACH="Linux porcinet 2.6.28-gentoo-r5 #2 SMP Wed May 6 18:42:20 CEST 2009 i686 Intel(R) Pentium(R) III CPU family 1133MHz GenuineIntel GNU/Linux" CC="i686-pc-linux-gnu-gcc" CONFIGURE_COMMAND="'./configure' 'linux' 'gnu'" paths: bindir="/usr/bin" sbindir="/usr/sbin" libexecdir="/usr/libexec" mandir="/usr/share/man" AMANDA_TMPDIR="/var/spool/amanda/tmp" AMANDA_DBGDIR="/var/spool/amanda/tmp" CONFIG_DIR="/etc/amanda" DEV_PREFIX="/dev/" RDEV_PREFIX="/dev/" DUMP="/usr/sbin/dump" RESTORE="/usr/sbin/restore" VDUMP=UNDEF VRESTORE=UNDEF XFSDUMP=UNDEF XFSRESTORE=UNDEF VXDUMP=UNDEF VXRESTORE=UNDEF SAMBA_CLIENT="/usr/bin/smbclient" GNUTAR="/bin/tar" COMPRESS_PATH="/bin/gzip" UNCOMPRESS_PATH="/bin/gzip" LPRCMD=UNDEF MAILER="/bin/Mail" listed_incr_dir="/var/spool/amanda/tar-lists" defs: DEFAULT_SERVER="porcinet" DEFAULT_CONFIG="DailySet1" DEFAULT_TAPE_SERVER="porcinet" HAVE_MMAP HAVE_SYSVSHM LOCKING=POSIX_FCNTL SETPGRP_VOID DEBUG_CODE AMANDA_DEBUG_DAYS=4 BSD_SECURITY RSH_SECURITY USE_AMANDAHOSTS CLIENT_LOGIN="amanda" FORCE_USERID HAVE_GZIP COMPRESS_SUFFIX=".gz" COMPRESS_FAST_OPT="--fast" COMPRESS_BEST_OPT="--best" UNCOMPRESS_OPT="-dc" build: VERSION="Amanda-2.6.0p2" BUILT_DATE="Tue May 12 13:42:38 CEST 2009" BUILT_MACH="i686-pc-linux-gnu" BUILT_REV="1266" BUILT_BRANCH="amanda-260" CC="i686-pc-linux-gnu-gcc" paths: bindir="/usr/bin" sbindir="/usr/sbin" libexecdir="/usr/libexec" amlibexecdir="/usr/libexec/amanda" mandir="/usr/share/man" AMANDA_TMPDIR="/var/spool/amanda/tmp" AMANDA_DBGDIR="/var/spool/amanda/tmp" CONFIG_DIR="/etc/amanda" DEV_PREFIX="/dev/" RDEV_PREFIX="/dev/" DUMP="/usr/sbin/dump" RESTORE="/usr/sbin/restore" VDUMP=UNDEF VRESTORE=UNDEF XFSDUMP=UNDEF XFSRESTORE=UNDEF VXDUMP=UNDEF VXRESTORE=UNDEF SAMBA_CLIENT=UNDEF GNUTAR="/bin/tar" COMPRESS_PATH="/bin/gzip" UNCOMPRESS_PATH="/bin/gzip" LPRCMD=UNDEF MAILER="/bin/Mail" listed_incr_dir="/var/spool/amanda/tar-lists" defs: DEFAULT_SERVER="porcinet" DEFAULT_CONFIG="DailySet1" DEFAULT_TAPE_SERVER="porcinet" DEFAULT_TAPE_DEVICE="" HAVE_MMAP NEED_STRSTR HAVE_SYSVSHM LOCKING=**NONE** SETPGRP_VOID AMANDA_DEBUG_DAYS=4 BSD_SECURITY USE_AMANDAHOSTS CLIENT_LOGIN="amanda" CHECK_USERID HAVE_GZIP COMPRESS_SUFFIX=".gz" COMPRESS_FAST_OPT="--fast" COMPRESS_BEST_OPT="--best" UNCOMPRESS_OPT="-dc" I don't know if this is the file you want to see but here is the amrestore debug file (located in /var/spool/amanda/tmp/server/amrestore<timestamp>.debug) when I try to use it with 2.6.0 version : 1242130071.225033: amrestore: pid 8641 ruid 0 euid 0: start at Tue May 12 14:07:51 2009 1242130071.229688: amrestore: device_read_label; mode = 0 1242130071.250400: amrestore: device_start mode = 1 1242130079.900719: amrestore: device_start done; dev->access_mode = 1, result 1 1242130079.900841: amrestore: search_a_tape: no desired_tape 1242130079.900871: amrestore: current tapefile_idx = -1 The debug file from 2.5 version is not verbose at all. Interesting test : I restored the same file from the same tape with the amrestore -r (raw) option with both Amanda versions. Firstly, the file size is not the same. Secondly, I ran this command : "dd if=extractedfile.RAW bs=32k skip=1 | /bin/gzip -dc | /bin/tar t" with the file extracted with 2.5 version, it's ok, I see my backuped files but with 2.6 I got the infamous messages : gzip: stdin: not in gzip format and /bin/tar: This does not look like a tar archive Maybe Amanda produces spurious headers with 2.6 version ?
There are a few known bugs of which this could be a manifestation. Does this file span multiple volumes? If so, there was a bug in 2.6.0 which could sometimes add zeroes to the *end* of the first file on the second tape, causing tar to give errors like this. There was also a bug wherein the 'fsf' command to the tape skipped ahead one file too many, but to my knowledge this only affected Solaris. Is tape spanning enabled at all? Is this file split into multiple parts? Can you figure out where in the archive the error occurs? (as in: at the beginning, somewhere in the middle, or seems cut off at the end?) Finally, can you 'strace' the 2.6.0 amrestore run and perhaps snip out the repetitive stuff?
I have no file which span multiple tapes. Tape spanning isn't enable and no file is split. I always do full backups too. I'm not sure to understand what do you mean by "where in the archive the error occurs" but the error message appears immediatly after pressing the enter key. Here is the amrestore related stuff given by a strace : write(2, "amrestore: 1: restoring "..., 24amrestore: 1: restoring ) = 24 write(2, "FILE: date 20090505231501 host se"..., 88FILE: date 20090505231501 host servername disk /data/users/autres lev 0 comp .gz) = 88 write(2, " program /bin/tar"..., 17 program /bin/tar) = 17 write(2, "\n"..., 1 ) = 1 open("servername._data_users_autres.20090505231501.0.tmp", O_RDWR|O_CREAT|O_TRUNC|O_LARGEFILE, 0640) = 4 pipe([5, 6]) = 0 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7a27708) = 19974 close(5) = 0 close(4) = 0 mmap2(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7209000 mprotect(0xb7209000, 4096, PROT_NONE) = 0 clone(child_stack=0xb7a094b4, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xb7a09bd8, {entry_number:6, base_addr:0xb7a09b90, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}, child_tidptr=0xb7a09bd8) = 19975 futex(0xb7e63770, FUTEX_WAKE_PRIVATE, 1) = 1 mmap2(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6987000 mprotect(0xb6987000, 4096, PROT_NONE) = 0 clone(child_stack=0xb71874b4, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xb7187bd8, {entry_number:6, base_addr:0xb7187b90, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}, child_tidptr=0xb7187bd8) = 19976 futex(0xb7e63770, FUTEX_WAKE_PRIVATE, 1) = 1 futex(0xb7187bd8, FUTEX_WAIT, 19976, NULL gzip: stdin: not in gzip format Error writing fd 6: Broken pipe ) = 0 --- SIGCHLD (Child exited) @ 0 (0) --- Thanks for your help.
(In reply to comment #9) > I'm not sure to understand what do you mean by "where in the archive the error > occurs" but the error message appears immediatly after pressing the enter key. I'm trying to find out if the archive is missing data that should be there, has extra data added, or has had data changed without altering the length. In any case, I'd like to know if it's the first bytes, the last bytes, or (less likely since you're not spanning) somewhere in the middle. Can you compare the first, say, 1k of the results of a 2.5.x and 2.6.0 raw (-r) amrestore, perhaps with hexdump? > Here is the amrestore related stuff given by a strace : > > write(2, "amrestore: 1: restoring "..., 24amrestore: 1: restoring ) = 24 > write(2, "FILE: date 20090505231501 host se"..., 88FILE: date 20090505231501 > host servername disk /data/users/autres lev 0 comp .gz) = 88 > write(2, " program /bin/tar"..., 17 program /bin/tar) = 17 > write(2, "\n"..., 1 > ) = 1 Hmm, all of the information from above comes from the tape device, so you've omitted some earlier lines that involved opening fd 2, positioning it at the right file, and reading the header. Can you try again with a 'raw' restore, which should not fork like this?
Here is the ouput of the command "hexdump -n 1024 -c extractedfile-version2.5" : 0000000 A M A N D A : F I L E 2 0 0 0000010 9 0 5 1 1 2 3 1 5 0 2 s e r v 0000020 e u r 5 5 0 0 / d a t a / u t 0000030 i l i s a t e u r s / a u t r e 0000040 s l e v 0 c o m p . g 0000050 z p r o g r a m / b i n / t 0000060 a r \n T o r e s t o r e , p 0000070 o s i t i o n t a p e a t 0000080 s t a r t o f f i l e a n 0000090 d r u n : \n \t d d i f = < t 00000a0 a p e > b s = 3 2 k s k i p 00000b0 = 1 | / b i 00000c0 n / g z i p - d c | / 00000d0 b i n / t a r - f - . . . 00000e0 \n \f \n \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 00000f0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 * 0000400 And here is the ouput of the command "hexdump -n 1024 -c extractedfile-version2.6" : 0000000 A M A N D A : F I L E 2 0 0 0000010 9 0 5 1 1 2 3 1 5 0 2 s e r v 0000020 e u r 5 5 0 0 / d a t a / u t 0000030 i l i s a t e u r s / a u t r e 0000040 s l e v 0 c o m p . g 0000050 z p r o g r a m / b i n / t 0000060 a r \n T o r e s t o r e , p 0000070 o s i t i o n t a p e a t 0000080 s t a r t o f f i l e a n 0000090 d r u n : \n \t d d i f = < t 00000a0 a p e > b s = 3 2 k s k i p 00000b0 = 1 | / b i n 00000c0 / g z i p - d c | / b 00000d0 i n / t a r - f - . . . \n 00000e0 \f \n \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 00000f0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 * 0000400 And here is the ouput of "strace amrestore -r ..." (I hope I pasted the good informations this time) : open("/etc/amanda/amanda-client.conf", O_RDONLY|O_LARGEFILE) = 3 fstat64(3, {st_mode=S_IFREG|0644, st_size=109, ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7e32000 read(3, "conf \"daily\"\nindex_server \"porcin"..., 4096) = 109 read(3, ""..., 4096) = 0 close(3) = 0 munmap(0xb7e32000, 4096) = 0 stat64("/dev/nst0", {st_mode=S_IFCHR|0660, st_rdev=makedev(9, 128), ...}) = 0 futex(0xb7a4206c, FUTEX_WAKE_PRIVATE, 2147483647) = 0 open("/etc/ld.so.cache", O_RDONLY) = 3 fstat64(3, {st_mode=S_IFREG|0644, st_size=21406, ...}) = 0 mmap2(NULL, 21406, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb78ce000 close(3) = 0 open("/lib/libz.so", O_RDONLY) = 3 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\220\24\0\0004\0\0\0\340"..., 512) = 512 fstat64(3, {st_mode=S_IFREG|0755, st_size=70344, ...}) = 0 close(3) = 0 munmap(0xb78ce000, 21406) = 0 sched_getparam(21207, { 0 }) = 0 sched_getscheduler(21207) = 0 (SCHED_OTHER) clock_getres(CLOCK_MONOTONIC, {0, 1}) = 0 sched_get_priority_min(SCHED_OTHER) = 0 sched_get_priority_max(SCHED_OTHER) = 0 sched_get_priority_max(SCHED_OTHER) = 0 open("/usr/lib/charset.alias", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory) open("/usr/share/locale/locale.alias", O_RDONLY|O_LARGEFILE) = 3 fstat64(3, {st_mode=S_IFREG|0644, st_size=2570, ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7e32000 read(3, "# Locale name alias data base.\n# "..., 4096) = 2570 read(3, ""..., 4096) = 0 close(3) = 0 munmap(0xb7e32000, 4096) = 0 write(2, "\"/dev/nst0\" uses deprecated devic"..., 87"/dev/nst0" uses deprecated device naming convention; using "tape:/dev/nst0" instead. ) = 87 gettimeofday({1242140578, 531389}, NULL) = 0 write(10, "1242140578.531389: amrestore: dev"..., 58) = 58 open("/dev/nst0", O_RDWR|O_NONBLOCK|O_LARGEFILE) = 3 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0 fcntl64(3, F_GETFL) = 0x8802 (flags O_RDWR|O_NONBLOCK|O_LARGEFILE) fcntl64(3, F_SETFL, O_RDWR|O_LARGEFILE) = 0 ioctl(3, MGSL_IOCGPARAMS or MTIOCTOP or SNDCTL_MIDI_MPUMODE, 0xbfa165ac) = 0 ioctl(3, MGSL_IOCSTXIDLE or MTIOCGET or SNDCTL_MIDI_MPUCMD, 0xbfa1659c) = 0 time(NULL) = 1242140578 time(NULL) = 1242140578 ioctl(3, MGSL_IOCGPARAMS or MTIOCTOP or SNDCTL_MIDI_MPUMODE, 0xbfa165d4) = 0 mmap2(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7853000 read(3, "AMANDA: TAPESTART DATE 2009050523"..., 524288) = 32768 munmap(0xb7853000, 528384) = 0 gettimeofday({1242140599, 563409}, NULL) = 0 write(10, "1242140599.563409: amrestore: dev"..., 52) = 52 time(NULL) = 1242140599 time(NULL) = 1242140599 ioctl(3, MGSL_IOCGPARAMS or MTIOCTOP or SNDCTL_MIDI_MPUMODE, 0xbfa177d4) = 0 gettimeofday({1242140601, 513740}, NULL) = 0 write(10, "1242140601.513740: amrestore: dev"..., 80) = 80 gettimeofday({1242140601, 514031}, NULL) = 0 write(10, "1242140601.514031: amrestore: sea"..., 61) = 61 gettimeofday({1242140601, 514195}, NULL) = 0 write(10, "1242140601.514195: amrestore: cur"..., 56) = 56 write(2, "Restoring from tape Q-02 starting"..., 47Restoring from tape Q-02 starting with file 1. ) = 47 ioctl(3, MGSL_IOCGPARAMS or MTIOCTOP or SNDCTL_MIDI_MPUMODE, 0xbfa17730) = 0 mmap2(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7853000 read(3, "AMANDA: FILE 20090505231501 serve"..., 524288) = 524288 mmap2(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb77d2000 munmap(0xb77d2000, 528384) = 0 munmap(0xb7853000, 528384) = 0 write(2, "amrestore: 1: restoring "..., 24amrestore: 1: restoring ) = 24 write(2, "FILE: date 20090505231501 host se"..., 88FILE: date 20090505231501 host serveur5500 disk /data/utilisateurs/autres lev 0 comp .gz) = 88 write(2, " program /bin/tar"..., 17 program /bin/tar) = 17 write(2, "\n"..., 1 ) = 1 open("serveur5500._data_utilisateurs_autres.20090505231501.0.RAW.tmp", O_RDWR|O_CREAT|O_TRUNC|O_LARGEFILE, 0640) = 4 gettimeofday({1242140601, 601401}, NULL) = 0 write(10, "1242140601.601401: amrestore: Bui"..., 81) = 81 gettimeofday({1242140601, 601903}, NULL) = 0 write(10, "1242140601.601903: amrestore: Con"..., 68) = 68 gettimeofday({1242140601, 602274}, NULL) = 0 write(10, "1242140601.602274: amrestore: "..., 62) = 62 gettimeofday({1242140601, 602616}, NULL) = 0 write(10, "1242140601.602616: amrestore: "..., 70) = 70 gettimeofday({1242140601, 603079}, NULL) = 0 write(10, "1242140601.603079: amrestore: "..., 55) = 55 gettimeofday({1242140601, 603345}, NULL) = 0 write(10, "1242140601.603345: amrestore: "..., 57) = 57 gettimeofday({1242140601, 603561}, NULL) = 0 write(10, "1242140601.603561: amrestore: "..., 55) = 55 gettimeofday({1242140601, 603774}, NULL) = 0 write(10, "1242140601.603774: amrestore: "..., 59) = 59 gettimeofday({1242140601, 603987}, NULL) = 0 write(10, "1242140601.603987: amrestore: "..., 56) = 56 gettimeofday({1242140601, 604342}, NULL) = 0 write(10, "1242140601.604342: amrestore: "..., 67) = 67 gettimeofday({1242140601, 604608}, NULL) = 0 write(10, "1242140601.604608: amrestore: "..., 81) = 81 gettimeofday({1242140601, 604844}, NULL) = 0 write(10, "1242140601.604844: amrestore: "..., 64) = 64 gettimeofday({1242140601, 605056}, NULL) = 0 write(10, "1242140601.605056: amrestore: "..., 56) = 56 gettimeofday({1242140601, 605267}, NULL) = 0 write(10, "1242140601.605267: amrestore: "..., 56) = 56 gettimeofday({1242140601, 605478}, NULL) = 0 write(10, "1242140601.605478: amrestore: "..., 56) = 56 gettimeofday({1242140601, 605789}, NULL) = 0 write(10, "1242140601.605789: amrestore: "..., 56) = 56 gettimeofday({1242140601, 606001}, NULL) = 0 write(10, "1242140601.606001: amrestore: "..., 56) = 56 gettimeofday({1242140601, 606212}, NULL) = 0 write(10, "1242140601.606212: amrestore: "..., 75) = 75 gettimeofday({1242140601, 606423}, NULL) = 0 write(10, "1242140601.606423: amrestore: "..., 78) = 78 gettimeofday({1242140601, 606702}, NULL) = 0 write(10, "1242140601.606702: amrestore: "..., 56) = 56 gettimeofday({1242140601, 606913}, NULL) = 0 write(10, "1242140601.606913: amrestore: "..., 56) = 56 gettimeofday({1242140601, 607124}, NULL) = 0 write(10, "1242140601.607124: amrestore: "..., 56) = 56 gettimeofday({1242140601, 607335}, NULL) = 0 write(10, "1242140601.607335: amrestore: "..., 56) = 56 gettimeofday({1242140601, 607546}, NULL) = 0 write(10, "1242140601.607546: amrestore: "..., 56) = 56 gettimeofday({1242140601, 607758}, NULL) = 0 write(10, "1242140601.607758: amrestore: "..., 55) = 55 gettimeofday({1242140601, 608062}, NULL) = 0 write(10, "1242140601.608062: amrestore: "..., 55) = 55 gettimeofday({1242140601, 608273}, NULL) = 0 write(10, "1242140601.608273: amrestore: "..., 55) = 55 gettimeofday({1242140601, 608485}, NULL) = 0 write(10, "1242140601.608485: amrestore: "..., 59) = 59 brk(0x9452000) = 0x9452000 write(4, "AMANDA: FILE 20090505231501 serve"..., 32768) = 32768 brk(0x9442000) = 0x9442000 mmap2(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb70d3000 mprotect(0xb70d3000, 4096, PROT_NONE) = 0 clone(child_stack=0xb78d34b4, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xb78d3bd8, {entry_number:6, base_addr:0xb78d3b90, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}, child_tidptr=0xb78d3bd8) = 21220 futex(0xb7d2d770, FUTEX_WAKE_PRIVATE, 1) = 1 mmap2(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6851000 mprotect(0xb6851000, 4096, PROT_NONE) = 0 clone(child_stack=0xb70514b4, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xb7051bd8, {entry_number:6, base_addr:0xb7051b90, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}, child_tidptr=0xb7051bd8) = 21221 futex(0xb7d2d770, FUTEX_WAKE_PRIVATE, 1) = 1 futex(0xb7051bd8, FUTEX_WAIT, 21221, NULL) = 0 munmap(0xb674f000, 528384) = 0 munmap(0xb67d0000, 528384) = 0 stat64("serveur5500._data_utilisateurs_autres.20090505231501.0.RAW.tmp", {st_mode=S_IFREG|0640, st_size=38567936, ...}) = 0 rename("serveur5500._data_utilisateurs_autres.20090505231501.0.RAW.tmp", "serveur5500._data_utilisateurs_autres.20090505231501.0.RAW") = 0 mmap2(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7052000 read(3, "AMANDA: FILE 20090505231501 serve"..., 524288) = 524288 mmap2(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb67d0000 munmap(0xb67d0000, 528384) = 0 munmap(0xb7052000, 528384) = 0
Hmm, so the headers are identical (modulo whitespace, which isn't a problem). How about the file data itself? Which raw file is bigger? Can you see a string of zeroes in one file that doesn't exist in the other, or some data missing from one flie that's present in the other? Sorry, I'm still trying to get some useful indication of what is wrong here.
The file restored by 2.5 version is bigger. I tried to compare output from hexdump and I didn't see strings of zeros (but I can't seriously compare *all* lines). I noticed that even if the line numbers differ and that the beginning of both files differ too, the end of both files is identical. I really don't know what to try now...
(In reply to comment #13) > The file restored by 2.5 version is bigger. By how much? Just to check - your block size is 32k, right?
Here are the files size : 2.5 restored file : 39354368 2.6 restored file : 38862848 So if I checked right, it means a difference of 380k How can I check if the blocksize is 32k ?
Ah -- that's 480k, or 15 32-k blocks. In the second strace, I see Amanda reading 512k: read(3, "AMANDA: TAPESTART DATE 2009050523"..., 524288) = 32768 .. read(3, "AMANDA: FILE 20090505231501 serve"..., 524288) = 524288 In the first read, the on-tape file is only 32k, so Amanda gives the right size. In the second, for some reason the tape driver obliges Amanda by reading 512k, which is multiple blocks -- it's supposed to detect the on-tape block size and only return one block's worth of data. I expect what's happening is that Amanda is reading (with READ_BUFFER_SIZE - see http://wiki.zmanda.com/man/amanda-devices.7.html) 512k blocks, and as a consequence threw away the 480k in the first (header) block. This is behavior I haven't seen from the linux 'st' driver in the past, but it's worked around easiliy enough - pass the option -b32k to amrestore, and add device_property "READ_BUFFER_SIZE" "32k" to your amanda.conf.
Running amrecover with the -b32k option didn't change anything. I've put in amanda.conf the option you mentionned in your last comment but no success with amrecover neither.
Ugh! Can you attach an strace -f of an amrestore run *with* the -b32k option?
Created attachment 191167 [details] The output of strace used with amrestore Command launched : amrestore -b32k tape:/dev/nst0 servername diskname
Created attachment 191169 [details] The output of strace -f used with amrestore Details of command used : strace -f amrestore -b32k tape:/dev/nst0 servername diskname (sorry, I forgot the -f option in the precedent strace output)
(In reply to comment #20) > Created an attachment (id=191169) [edit] > The output of strace -f used with amrestore > > Details of command used : > strace -f amrestore -b32k tape:/dev/nst0 servername diskname Hmm, are you sure? 9192 execve("/usr/sbin/amrestore", ["amrestore", "tape:/dev/nst0", "serveur5500", "autres"], [/* 49 vars */]) = 0 Furthermore, I see a lot of: 9198 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 524288) = 512 in which Amanda is trying to read 512k from the tape and -- very oddly -- only getting 512 bytes (mostly zeroes!) back. Amanda's minimum block size has always been 32k, and to my knowledge no tapes or tape drivers go as low as 0.5k. Your kernel (in particular, the 'st' driver) is acting very strange here. Any idea why? One thing you can try is the following: mt -f /dev/nst0 rewind; mt -f /dev/nst0 fsf 1; dd if=/dev/nst0 of=tmp.32k bs=32k skip=1 mt -f /dev/nst0 rewind; mt -f /dev/nst0 fsf 1; dd if=/dev/nst0 of=tmp.512k bs=512k skip=1 mt -f /dev/nst0 rewind; mt -f /dev/nst0 fsf 1; dd if=/dev/nst0 of=tmp.512b bs=512 skip=1 and compare the resulting files. I expect that the first will succeed, the second will give the results you were seeing earlier from amrestore-2.6.0, and the third will fail entirely (with "Invalid argument"). If you strace the first, you will see it reading 32768 bytes at a time, and getting that many bytes back: read(fd, "...", 32768) = 32768 If you strace the second, I expect you will see one of these two (incorrect) behaviors from your kernel: read(fd, "...", 524288) = 524288 read(fd, "...", 524288) = 512 where the correct behavior is read(fd, "...", 524288) = 32768
Created attachment 191232 [details] Output of strace -f amrestore -b32k tape:/dev/nst0 servername diskname You're right ! I forgot the -b switch. Too bad. I'm sorry. Here is the right stuff.
I don't know why the kernel driver is acting strangely. The odd thing is that it perfectly works with amanda 2.5.x. Why so ? It uses the same kernel driver, right ? All set of commands you mentionned gave these messages (except the last command (the one with 512b) which didn't give me last line of the output pasted below) : dd: warning: working around lseek kernel bug for file (/dev/nst0) of mt_type=0x72 -- see <sys/mtio.h> for the list of types dd: warning: working around lseek kernel bug for file (/dev/nst0) of mt_type=0x72 -- see <sys/mtio.h> for the list of types dd: `/dev/nst0': cannot skip to specified offset Anyway, all the commands extracted data (no "Invalid argument" answer from the third command by the way) but I had no success trying to untar/gunzip the output files. strace from the first command gave me a lot of : read(0, "o\256\311\233\330\225\366 (t\17\314TC\6\207\36A\321\203\266\236\367\210`\205\0208\246\245\223\244\345"..., 32768) = 512 write(1, "o\256\311\233\330\225\366 (t\17\314TC\6\207\36A\321\203\266\236\367\210`\205\0208\246\245\223\244\345"..., 512) = 512 strace from the second command gave me a lot of : read(0, "\35~\251\23\25)\0336\372\242\376\234\n*\210j\10\245c\7\21\342BC\5a2\241\31}ykK"..., 524288) = 512 write(1, "\35~\251\23\25)\0336\372\242\376\234\n*\210j\10\245c\7\21\342BC\5a2\241\31}ykK"..., 512) = 512
(In reply to comment #23) > dd: warning: working around lseek kernel bug for file (/dev/nst0) > of mt_type=0x72 -- see <sys/mtio.h> for the list of types Strange, I saw this behavior a few days ago on a Suse 10.2 box, but with amanda 2.5.2p1 ... I also couldn't extract data there. The tapedrive there couldn't be positioned via "mt fsf" etc ... I don't know where this comes from, from the mt-code in the kernel or ... ?
My tape drive can be positionned via mt tool. But I don't think the problem comes from the mt code or kernel because if so, Amanda 2.5.x couldn't extract any data neither, right ?
(In reply to comment #25) > My tape drive can be positionned via mt tool. But I don't think the problem > comes from the mt code or kernel because if so, Amanda 2.5.x couldn't extract > any data neither, right ? Yes ... might be just a coincident that both servers hit that lseek-issue.
(In reply to comment #26) > Yes ... might be just a coincident that both servers hit that lseek-issue. I believe this issue is a problem with lseek not handing file positions >2GB. Amanda has a workaround in place for the same thing: 1431 /* Kernel workaround: If needed, poke the kernel so it doesn't fail. 1432 at the 2GB boundry. Parameters are G_GNUC_UNUSED in case NEED_RESETOFS 1433 is not defined. */ 1434 static void check_resetofs(TapeDevice * self G_GNUC_UNUSED, 1435 int count G_GNUC_UNUSED) { 1436 #ifdef NEED_RESETOFS 1437 Device * d_self; 1438 int result; 1439 1440 d_self = (Device*)self; 1441 1442 self->private->write_count += count; 1443 if (self->private->write_count < RESETOFS_THRESHOLD) { 1444 return; 1445 } 1446 1447 result = lseek(self->fd, 0, SEEK_SET); 1448 if (result < 0) { 1449 g_warning(_("lseek() failed during kernel 2GB workaround: %s"), 1450 strerror(errno)); 1451 } 1452 #endif 1453 } However, that's only invoked on writing, and furthermore your files are not even nearly 2G, so I'm fairly certain this is irrelevant. So we can verify that this problem afflicts 'dd' as well. I don't know why it wouldn't bother amanda-2.5.x, but that version of Amanda did make a habit of closing and re-opening the tape device repeatedly -- in other words, its handling of the tape device was less efficient than 2.6.0. So two more suggestions: - are there any kernel messages that might be relevant? - if you 'strace -f' the amanda-2.5.x amrestore in raw mode, what do the reads look like?
Well.. I downgraded Amanda to 2.5.x to try another strace and now, if I try to amrestore, the output is : short file header block : 512 bytes missing file header block error reading file header: Input/Output error A lot of this kind of nasty messages and Amanda never restored my files. I really think I'll give up and try another backup software. Or maybe the problem comes from my tape drive ? Do you think so ?
(In reply to comment #28) > Well.. I downgraded Amanda to 2.5.x to try another strace and now, if I try to > amrestore, the output is : > > short file header block : 512 bytes > missing file header block > error reading file header: Input/Output error > > A lot of this kind of nasty messages and Amanda never restored my files. So, to be clear, Amanda-2.5.x isn't working anymore, either? > I really think I'll give up and try another backup software. Or maybe the > problem comes from my tape drive ? Do you think so ? We now have the following results: Amanda-2.6.0 -- bogus short reads Amanda-2.5.x -- bogus short reads dd -- bogus short reads dd is not a part of Amanda, so I the problem is in the kernel, your tape drive, or maybe the tapes themselves.
Ok. I'll now try another software, another kernel, others tapes and if I can, another tapedrive. I mark this bug "CANTFIX". Thanks a lot for your help. Cheers.
(In reply to comment #30) > Ok. I'll now try another software, another kernel, others tapes and if I can, > another tapedrive. I mark this bug "CANTFIX". Update: I hit this behavior as well on a gentoo-box with amanda-2.6.0_p2-r4. I am currently rebuilding amanda-2.5.2p1 to try a restore :-(
sgw: any update?
(In reply to comment #32) > sgw: any update? Sorry, no, not yet. Currently using 2.5.2p1 there, I'd have to do a test setup to check that. Will try asap.
Did backups with 2.6.2p1. amrestore with 2.6.2p1: worked fine amrestore with 2.6.0p4: did NOT work I ended up with an empty file: amrestore: 2: restoring FILE: date 20091201145513 host backup.tld.com disk /mnt/data lev 1 comp .gz program /bin/tar gzip: stdin: not in gzip format Error writing fd 6: Broken pipe This as a short status-message ....
