View Issue Details

Related ChangesetsJump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0000639bareos-corestorage daemonpublic2016-04-05 23:492017-12-18 12:09
Reporterareplogle Assigned To 
PrioritylowSeverityminorReproducibilityalways
Status closedResolutionfixed 
PlatformLinuxOSUbuntuOS Version14.04
Product Version15.2.2 
Fixed in Version17.2.4 
Summary0000639: bareos unable to read AWS VTL iSCSI devices
DescriptionWhen using AWS Storage Gateway, trying to use bareos utilities to access the iSCSI devices exposed by Amazon's storage gateway results in failure on read attempts.


---<example>---
# mt -f /dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0-nst rewind
# btape -c /etc/bareos/bareos-sd.conf /dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0-nst
Tape block granularity is 1024 bytes.
btape: butil.c:274-0 Using device: "/dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0-nst" for writing.
btape: btape.c:487-0 open device "Drive-1" (/dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0-nst): OK
*test

=== Write, rewind, and re-read test ===

I'm going to write 10000 records and an EOF
then write 10000 records and an EOF, then rewind,
and re-read the data to verify that it is correct.

This is an *essential* feature ...

btape: btape.c:1172-0 Wrote 10000 blocks of 64412 bytes.
btape: btape.c:619-0 Wrote 1 EOF to "Drive-1" (/dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0-nst)
btape: btape.c:1188-0 Wrote 10000 blocks of 64412 bytes.
btape: btape.c:619-0 Wrote 1 EOF to "Drive-1" (/dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0-nst)
btape: btape.c:1230-0 Rewind OK.
05-Apr 17:39 btape JobId 0: Error: block.c:1003 Read error on fd=3 at file:blk 0:0 on device "Drive-1" (/dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0-nst). ERR=Input/output error.
btape: btape.c:1250-0 Read block 1 failed! ERR=Input/output error
--</example>--

Steps To ReproduceInstall bareos 15.2.2 on Ubuntu 14.04
Deploy AWS Gateway VM (There's a 60 day free trial if you need to reproduce) in your network.
Install lsscsi / open-iscsi packages
Set /etc/iscsi/iscsid.conf to automatic
Discover and register devices.
Run btape test.
Additional InformationUsing standard posix utilities like tar, I'm able to write and read from the AWS vtapes.
---<example>---
root@pbkupph01:~# mt -f /dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0-nst rewind
root@pbkupph01:~# tar cvf /dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0 .
./
./.aliasrc
./.viminfo
./.bashrc
./.ssh/
./.ssh/known_hosts
./.bconsole_history
./.bash_history
./.profile
root@pbkupph01:~# mt -f /dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0-nst rewind
root@pbkupph01:~# tar tvf /dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0
drwx------ root/root 0 2016-04-02 15:02 ./
-rw-r--r-- root/root 212 2016-04-02 15:02 ./.aliasrc
-rw------- root/root 14029 2016-04-02 15:02 ./.viminfo
-rw-r--r-- root/root 3216 2016-04-02 14:52 ./.bashrc
drwx------ root/root 0 2016-02-23 09:22 ./.ssh/
-rw-r--r-- root/root 444 2016-02-23 09:22 ./.ssh/known_hosts
-rw------- root/root 637 2016-04-02 14:50 ./.bconsole_history
-rw------- root/root 18424 2016-04-02 16:29 ./.bash_history
-rw-r--r-- root/root 140 2014-02-19 21:43 ./.profile
root@pbkupph01:~# mkdir tmp
root@pbkupph01:~# cd tmp
root@pbkupph01:~/tmp# mt -f /dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0-nst rewind
root@pbkupph01:~/tmp# tar xvf /dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0
./
./.aliasrc
./.viminfo
./.bashrc
./.ssh/
./.ssh/known_hosts
./.bconsole_history
./.bash_history
./.profile
root@pbkupph01:~/tmp# ls -la
total 64
drwx------ 3 root root 4096 Apr 2 15:02 .
drwx------ 4 root root 4096 Apr 5 17:43 ..
-rw-r--r-- 1 root root 212 Apr 2 15:02 .aliasrc
-rw------- 1 root root 18424 Apr 2 16:29 .bash_history
-rw-r--r-- 1 root root 3216 Apr 2 14:52 .bashrc
-rw------- 1 root root 637 Apr 2 14:50 .bconsole_history
-rw-r--r-- 1 root root 140 Feb 19 2014 .profile
drwx------ 2 root root 4096 Feb 23 09:22 .ssh
-rw------- 1 root root 14029 Apr 2 15:02 .viminfo
root@pbkupph01:~/tmp#
---</example>---
TagsNo tags attached.

Relationships

has duplicate 0000743 closed Bareos Amazon VTL block.c:1003 Read error on fd=6 at file:blk 0:0 on device "Drive_01" (/dev/st3). ERR=Input/output error. 
child of 0000861 closedjoergs Release bareos-17.2.4 

Activities

areplogle

areplogle

2016-04-06 00:47

reporter  

bareos-sysdig.txt (13,809 bytes)    
Write a block --
================
2401 18:33:55.169334866 0 btape (4795) < read res=3 data=wr. 
2402 18:33:55.169465021 0 btape (4795) > write fd=3(<f>/dev/nst9) size=64448 
2403 18:33:55.169484872 0 btape (4795) > switch next=4766 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
2424 18:33:55.169620989 0 btape (4795) > switch next=0 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
2427 18:33:55.171756791 0 btape (4795) < write res=64448 data=............BB02................................................................ 
2428 18:33:55.171772271 0 btape (4795) > write fd=1(<f>/dev/pts/0) size=22 
2429 18:33:55.171777930 0 btape (4795) > switch next=2086 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
2448 18:33:55.171811524 0 btape (4795) < write res=22 data=btape: btape.c:1930-0  
2449 18:33:55.171813787 0 btape (4795) > write fd=1(<f>/dev/pts/0) size=33 
2450 18:33:55.171816129 0 btape (4795) > switch next=2086 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
2469 18:33:55.171838447 0 btape (4795) > switch next=2086 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
2488 18:33:55.171850723 0 btape (4795) < write res=33 data=Wrote one record of 64412 bytes.. 
2489 18:33:55.171857267 0 btape (4795) > write fd=1(<f>/dev/pts/0) size=22 
2490 18:33:55.171859029 0 btape (4795) > switch next=2086 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
2509 18:33:55.171870807 0 btape (4795) < write res=22 data=btape: btape.c:1932-0  
2510 18:33:55.171872015 0 btape (4795) > write fd=1(<f>/dev/pts/0) size=23 
2511 18:33:55.171873474 0 btape (4795) > switch next=2086 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
2530 18:33:55.171885195 0 btape (4795) > switch next=2086 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
2549 18:33:55.171895233 0 btape (4795) < write res=23 data=Wrote block to device.. 
2550 18:33:55.171897644 0 btape (4795) > write fd=1(<f>/dev/pts/0) size=1 
2551 18:33:55.171899101 0 btape (4795) > switch next=2086 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
2570 18:33:55.171909903 0 btape (4795) < write res=1 data=* 
2571 18:33:55.171910581 0 btape (4795) > read fd=0(<f>/dev/pts/0) size=1024 
2572 18:33:55.171926293 0 btape (4795) > switch next=0 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 


Rewind --
==========
54956 18:34:56.318610898 0 btape (4795) < read res=7 data=rewind. 
54957 18:34:56.318621927 0 btape (4795) > ioctl fd=3(<f>/dev/nst9) request=40086D01 argument=7FFEE8583790 
54958 18:34:56.318639930 0 btape (4795) > switch next=4817 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
54960 18:34:56.318672265 0 btape (4795) > switch next=2519(sshd) pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
55162 18:34:56.330870618 0 btape (4795) > switch next=4817 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
55164 18:34:56.330891732 0 btape (4795) > switch next=0 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
55166 18:34:56.331187562 0 btape (4795) < ioctl res=0 
55167 18:34:56.331204872 0 btape (4795) > write fd=1(<f>/dev/pts/0) size=21 
55168 18:34:56.331209452 0 btape (4795) > switch next=2086 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
55170 18:34:56.331212555 0 btape (4795) < write res=21 data=btape: btape.c:589-0  
55171 18:34:56.331213783 0 btape (4795) > write fd=1(<f>/dev/pts/0) size=124 
55172 18:34:56.331215261 0 btape (4795) > switch next=2086 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
55174 18:34:56.331217659 0 btape (4795) > switch next=2086 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
55176 18:34:56.331218837 0 btape (4795) < write res=124 data=Rewound "Drive-1" (/dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com. 
55177 18:34:56.331221311 0 btape (4795) > write fd=1(<f>/dev/pts/0) size=1 
55178 18:34:56.331222581 0 btape (4795) > switch next=2086 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
55180 18:34:56.331223852 0 btape (4795) < write res=1 data=* 
55181 18:34:56.331224271 0 btape (4795) > read fd=0(<f>/dev/pts/0) size=1024 
55182 18:34:56.331225927 0 btape (4795) > switch next=2519(sshd) pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 



Read a block --
===============
87641 18:35:22.534428468 0 btape (4795) > open                                                                                                                                                                                                                                                                              [0/1862]
87642 18:35:22.534437371 0 btape (4795) > switch next=4817 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
87644 18:35:22.534453335 0 btape (4795) > switch next=0 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
87646 18:35:22.534548977 0 btape (4795) > switch next=4817 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
87648 18:35:22.534560249 0 btape (4795) > switch next=0 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
87650 18:35:22.534679721 0 btape (4795) > switch next=4817 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
87652 18:35:22.534692549 0 btape (4795) > switch next=0 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
87655 18:35:22.534822694 0 btape (4795) < open fd=3(<f>/dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0-nst) name=/dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0-nst flags=1(O_RDONLY) mode=0 
87656 18:35:22.534824683 0 btape (4795) > ioctl fd=3(<f>/dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0-nst) request=40086D01 argument=7FFEE85836F0 
87657 18:35:22.534825987 0 btape (4795) < ioctl res=0 
87658 18:35:22.534827124 0 btape (4795) > ioctl fd=3(<f>/dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0-nst) request=40086D01 argument=7FFEE85836E0 
87659 18:35:22.534832382 0 btape (4795) > switch next=4817 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
87661 18:35:22.534852633 0 btape (4795) > switch next=0 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
87663 18:35:22.535006893 0 btape (4795) < ioctl res=0 
87664 18:35:22.535007674 0 btape (4795) > getuid 
87665 18:35:22.535008300 0 btape (4795) < getuid uid=0(root) 
87666 18:35:22.535008848 0 btape (4795) > ioctl fd=3(<f>/dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0-nst) request=40086D01 argument=7FFEE85836E0 
87667 18:35:22.535010666 0 btape (4795) < ioctl res=0 
87668 18:35:22.535017340 0 btape (4795) > read fd=3(<f>/dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0-nst) size=64512 
87669 18:35:22.535027973 0 btape (4795) > switch next=4817 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
87671 18:35:22.535042398 0 btape (4795) > switch next=0 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
87673 18:35:22.536034848 0 btape (4795) < read res=-5(EIO) data= 
87674 18:35:22.536037308 0 btape (4795) > read fd=3(<f>/dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0-nst) size=64512 
87675 18:35:22.536045039 0 btape (4795) > switch next=4817 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
87677 18:35:22.536061879 0 btape (4795) > switch next=0 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
87679 18:35:22.536761234 0 btape (4795) < read res=-5(EIO) data= 
87680 18:35:22.536763437 0 btape (4795) > read fd=3(<f>/dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0-nst) size=64512 
87681 18:35:22.536770458 0 btape (4795) > switch next=4817 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
87683 18:35:22.536786866 0 btape (4795) > switch next=0 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
87685 18:35:22.537485610 0 btape (4795) < read res=-5(EIO) data= 
87686 18:35:22.537486802 0 btape (4795) > read fd=3(<f>/dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0-nst) size=64512 
87687 18:35:22.537492962 0 btape (4795) > switch next=4817 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
87689 18:35:22.537507295 0 btape (4795) > switch next=0 pgft_maj=0 pgft_min=400 vm_size=198584 vm_rss=5200 vm_swap=0 
87695 18:35:22.538213198 0 btape (4795) < read res=-5(EIO) data= 
87696 18:35:22.538216864 0 btape (4795) > ioctl fd=3(<f>/dev/tape/by-path/ip-172.22.2.250:3260-iscsi-iqn.1997-05.com.amazon:sgw-5d977234-tapedrive-01-lun-0-nst) request=80306D02 argument=7FFEE8583650 
87697 18:35:22.538218088 0 btape (4795) < ioctl res=0 
87698 18:35:22.538265071 0 btape (4795) > open 
87699 18:35:22.538269467 0 btape (4795) < open fd=-2(ENOENT) name=/usr/share/locale/en_US.UTF-8/LC_MESSAGES/libc.mo flags=1(O_RDONLY) mode=0 
87700 18:35:22.538270224 0 btape (4795) > open 
87701 18:35:22.538271398 0 btape (4795) < open fd=-2(ENOENT) name=/usr/share/locale/en_US.utf8/LC_MESSAGES/libc.mo flags=1(O_RDONLY) mode=0 
87702 18:35:22.538271930 0 btape (4795) > open 
87703 18:35:22.538273002 0 btape (4795) < open fd=-2(ENOENT) name=/usr/share/locale/en_US/LC_MESSAGES/libc.mo flags=1(O_RDONLY) mode=0 
87704 18:35:22.538273496 0 btape (4795) > open 
87705 18:35:22.538274940 0 btape (4795) < open fd=-2(ENOENT) name=/usr/share/locale/en.UTF-8/LC_MESSAGES/libc.mo flags=1(O_RDONLY) mode=0 
87706 18:35:22.538275448 0 btape (4795) > open 
87707 18:35:22.538276681 0 btape (4795) < open fd=-2(ENOENT) name=/usr/share/locale/en.utf8/LC_MESSAGES/libc.mo flags=1(O_RDONLY) mode=0 
87708 18:35:22.538277156 0 btape (4795) > open 
87709 18:35:22.538278754 0 btape (4795) < open fd=-2(ENOENT) name=/usr/share/locale/en/LC_MESSAGES/libc.mo flags=1(O_RDONLY) mode=0 
87710 18:35:22.538279240 0 btape (4795) > open 
87711 18:35:22.538280362 0 btape (4795) < open fd=-2(ENOENT) name=/usr/share/locale-langpack/en_US.UTF-8/LC_MESSAGES/libc.mo flags=1(O_RDONLY) mode=0 
87712 18:35:22.538280902 0 btape (4795) > open 
87713 18:35:22.538282066 0 btape (4795) < open fd=-2(ENOENT) name=/usr/share/locale-langpack/en_US.utf8/LC_MESSAGES/libc.mo flags=1(O_RDONLY) mode=0 
87714 18:35:22.538282710 0 btape (4795) > open 
87715 18:35:22.538283651 0 btape (4795) < open fd=-2(ENOENT) name=/usr/share/locale-langpack/en_US/LC_MESSAGES/libc.mo flags=1(O_RDONLY) mode=0 
87716 18:35:22.538284160 0 btape (4795) > open 
87717 18:35:22.538285020 0 btape (4795) < open fd=-2(ENOENT) name=/usr/share/locale-langpack/en.UTF-8/LC_MESSAGES/libc.mo flags=1(O_RDONLY) mode=0 
87718 18:35:22.538285528 0 btape (4795) > open 
87719 18:35:22.538286306 0 btape (4795) < open fd=-2(ENOENT) name=/usr/share/locale-langpack/en.utf8/LC_MESSAGES/libc.mo flags=1(O_RDONLY) mode=0 
87720 18:35:22.538286818 0 btape (4795) > open 
87721 18:35:22.538288205 0 btape (4795) < open fd=-2(ENOENT) name=/usr/share/locale-langpack/en/LC_MESSAGES/libc.mo flags=1(O_RDONLY) mode=0 
87722 18:35:22.538312526 0 btape (4795) > open 
87723 18:35:22.538315812 0 btape (4795) < open fd=4(<f>/etc/localtime) name=/etc/localtime flags=4097(O_RDONLY|O_CLOEXEC) mode=0 
87724 18:35:22.538316701 0 btape (4795) > fstat fd=4(<f>/etc/localtime) 
87725 18:35:22.538318400 0 btape (4795) < fstat res=0 
87726 18:35:22.538319545 0 btape (4795) > fstat fd=4(<f>/etc/localtime) 
87727 18:35:22.538319747 0 btape (4795) < fstat res=0 
87728 18:35:22.538320088 0 btape (4795) > mmap addr=0 length=4096 prot=3(PROT_READ|PROT_WRITE) flags=10(MAP_PRIVATE|MAP_ANONYMOUS) fd=4294967295 offset=0 
87729 18:35:22.538325410 0 btape (4795) < mmap res=7F8E7EF58000 vm_size=198588 vm_rss=5200 vm_swap=0 
87730 18:35:22.538326317 0 btape (4795) > read fd=4(<f>/etc/localtime) size=4096 
87731 18:35:22.538333122 0 btape (4795) < read res=3519 data=TZif2..........................................p...`...p...`.e.p.....j.p.5.`.S.. 
87732 18:35:22.538334776 0 btape (4795) > lseek fd=4(<f>/etc/localtime) offset=18446744073709549364 whence=1(SEEK_CUR) 
87733 18:35:22.538335796 0 btape (4795) < lseek res=1267 
87734 18:35:22.538336288 0 btape (4795) > read fd=4(<f>/etc/localtime) size=4096 
87735 18:35:22.538336876 0 btape (4795) < read res=2252 data=TZif2...........................................^..........p.......`.......p.... 
87736 18:35:22.538340208 0 btape (4795) > close fd=4(<f>/etc/localtime) 
87737 18:35:22.538340590 0 btape (4795) < close res=0 
87738 18:35:22.538342006 0 btape (4795) > munmap addr=7F8E7EF58000 length=4096 
87739 18:35:22.538348911 0 btape (4795) < munmap res=0 vm_size=198584 vm_rss=5272 vm_swap=0 
87740 18:35:22.538360036 0 btape (4795) > write fd=1(<f>/dev/pts/0) size=234 
87741 18:35:22.538365120 0 btape (4795) > switch next=2086 pgft_maj=0 pgft_min=404 vm_size=198584 vm_rss=5272 vm_swap=0 
87743 18:35:22.538370832 0 btape (4795) > switch next=2086 pgft_maj=0 pgft_min=404 vm_size=198584 vm_rss=5272 vm_swap=0 
87745 18:35:22.538372155 0 btape (4795) < write res=234 data=05-Apr 18:35 btape JobId 0: Error: block.c:1003 Read error on fd=3 at file:blk 0 
87746 18:35:22.538374705 0 btape (4795) > write fd=1(<f>/dev/pts/0) size=1 
87747 18:35:22.538376132 0 btape (4795) > switch next=2086 pgft_maj=0 pgft_min=404 vm_size=198584 vm_rss=5272 vm_swap=0 
87749 18:35:22.538377422 0 btape (4795) < write res=1 data=* 
87750 18:35:22.538377885 0 btape (4795) > read fd=0(<f>/dev/pts/0) size=1024 
87751 18:35:22.538379550 0 btape (4795) > switch next=2519(sshd) pgft_maj=0 pgft_min=404 vm_size=198584 vm_rss=5272 vm_swap=0
bareos-sysdig.txt (13,809 bytes)   
areplogle

areplogle

2016-04-06 00:53

reporter   ~0002228

I've run another test with sysdig in another window (e.g. - sysdig "proc.name=btape" ) executing a write block, rewind and read block.

It appears that its failing to find libc.mo, then trying to get /etc/localtime to determine my TZ (I think).

Is it possible that the write test is writing data thats outside of the codepage range for the read to handle?

Reference: bareos-sysdig.txt
areplogle

areplogle

2016-04-08 22:11

reporter   ~0002233

Just a quick update. Same exact issue on Centos 7.2.1511 (core)

# uname -a
Linux pbkupph01 3.10.0-327.13.1.el7.x86_64 0000001 SMP Thu Mar 31 16:04:38 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux
areplogle

areplogle

2016-04-24 18:43

reporter   ~0002246

For anyone else who's running into issue, for some reason Bacula 7.4 works fine. I've switched to that for now but am bummed since their plugin support isn't nearly as good or well documented.
areplogle

areplogle

2016-04-29 23:57

reporter   ~0002253

Had some time to circle back to this reviewing my steps. I realized that I was using the nst device which I thought was the cause of my issue (not being able to rewind), but even using the non-nst device I get the same issue.
areplogle

areplogle

2016-05-01 15:58

reporter   ~0002254

Since reproducing this would be a significant effort (have aws acct, deploy storage gateway to local vm env, setup new bareos install etc) I thought it might be easier if I provided the difference between the working block.c from bacula and comparison to the block.c from bareos.

Working:
https://github.com/prelegalwonder/bacula/blob/master/src/stored/block.c#L459

Input/Output Err:
https://github.com/bareos/bareos/blob/master/src/stored/block.c#L996

I have very little professional c development experience so forgive my ignorance if I'm just providing non-sense relations, but I also noticed that the bacula stored.h loads an additional vtape_dev.h/c and maybe there's some significant vtl support there thats allowing it to work in bacula?

Please let me know if there's anything I can do to assist.
sassyn

sassyn

2016-07-31 18:30

reporter   ~0002328

Hi,

Just had the same issue on ubuntu 14.04 with 15.2.2-37.1.

Did someone manage to solve this?

Is the upcoming 16.3.1 solve this?

Thank You
fbacchella

fbacchella

2016-09-07 19:23

reporter   ~0002349

Severity minor ? bareos is broken on AWS. I will need to switch to bacula because of this bug.
fbacchella

fbacchella

2016-09-07 19:24

reporter   ~0002350

I have the problem on RHEL 7.2 too.
maurizio.proietti

maurizio.proietti

2016-10-27 10:39

reporter   ~0002412

I have the problem on CentOS 7 too with tape library StorageTek L40.
With bacula 7.4 there is not this problem.
With all version of bareos btape fail.
I've tried with bareos 15 and 16 by yum and compiled by source code (from github).

this is the last messages from btape

btape: btape.c:1183-0 Wrote 10000 blocks of 64412 bytes.
btape (129): backends/generic_tape_device.c:368-0 === weof_dev="Drive-1" (/dev/nst0)
btape: btape.c:614-0 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape (950): record.c:353-0 Enter free_record.
btape (950): record.c:357-0 Data buf is freed.
btape (950): record.c:359-0 Leave free_record.
btape (400): backends/generic_tape_device.c:1115-0 rewind res=0 fd=3 "Drive-1" (/dev/nst0)
btape: btape.c:1225-0 Rewind OK.
btape (250): block.c:960-0 Full read in read_block_from_device() len=64512
btape (250): block.c:1000-0 Read device got: ERR=Errore di input/output
btape (250): sd_plugins.c:319-0 No bplugin_list: generate_plugin_event ignored.
btape (850): message.c:1557-0 Enter Jmsg type=4
btape (850): message.c:858-0 Enter dispatch_message type=4 msg=btape JobId 0: Error: block.c:1003 Read error on fd=3 at file:blk 0:0 on device "Drive-1" (/dev/nst0). ERR=Errore di input/output.
btape (850): message.c:1138-0 STDOUT for following msg: btape JobId 0: Error: block.c:1003 Read error on fd=3 at file:blk 0:0 on device "Drive-1" (/dev/nst0). ERR=Errore di input/output.
27-ott 10:36 btape JobId 0: Error: block.c:1003 Read error on fd=3 at file:blk 0:0 on device "Drive-1" (/dev/nst0). ERR=Errore di input/output.
btape: btape.c:1245-0 Read block 1 failed! ERR=Errore di input/output
btape (950): record.c:353-0 Enter free_record.
btape (950): record.c:357-0 Data buf is freed.
btape (950): record.c:359-0 Leave free_record.

I will need to switch to bacula because of this bug.
damiano.bortolato

damiano.bortolato

2017-04-18 11:17

reporter   ~0002628

Last edited: 2017-04-18 14:17

 Same problem on CentOS Linux release 7.3.1611 bareos 16.2.4, generic linux tools working on AWS Storage Gateway and bareos-fd don't.

Error given by bconsole:

Connecting to Storage daemon VTL at bcksrv1.utv.cps:9103 ...
Sending label command for Volume "UTV2A548F" Slot 1 ...
block.c:286 Volume data error at 0:0! Wanted ID: "BB02", got "". Buffer discarded.
block.c:630 Write error at 0:0 on device "amazon-vtl-td0" (/dev/nst7). ERR=Input/output error.
block.c:644 Write error on fd=4 at file:blk 0:0 on device "amazon-vtl-td0" (/dev/nst7). ERR=Input/output error.
Backspace record at EOT failed. ERR=Input/output error
3912 Failed to label Volume: ERR=generic_tape_device.c:726 ioctl MTBSR error on "amazon-vtl-td0" (/dev/nst7). ERR=Input/output error.

Label command failed for Volume UTV2A548F.


I noticed also the following messages on the syslog:

Apr 18 11:01:03 bcksrv1 kernel: connection18:0: detected conn error (1020)
Apr 18 11:01:03 bcksrv1 kernel: st 19:0:0:0: [st7] Error e0000 (driver bt 0x0, host bt 0xe).
Apr 18 11:01:03 bcksrv1 iscsid: Kernel reported iSCSI connection 18:0 error (1020 - ISCSI_ERR_TCP_CONN_CLOSE: TCP connection closed) state (3)
Apr 18 11:01:05 bcksrv1 kernel: st 19:0:0:0: [st7] Sense Key : Unit Attention [current]
Apr 18 11:01:05 bcksrv1 kernel: st 19:0:0:0: [st7] Add. Sense: Power on, reset, or bus device reset occurred
Apr 18 11:01:05 bcksrv1 kernel: connection18:0: detected conn error (1020)
Apr 18 11:01:05 bcksrv1 kernel: st 19:0:0:0: [st7] Error e0000 (driver bt 0x0, host bt 0xe).
Apr 18 11:01:05 bcksrv1 iscsid: connection18:0 is operational after recovery (1 attempts)
Apr 18 11:01:05 bcksrv1 iscsid: Kernel reported iSCSI connection 18:0 error (1020 - ISCSI_ERR_TCP_CONN_CLOSE: TCP connection closed) state (3)
Apr 18 11:01:07 bcksrv1 kernel: st 19:0:0:0: [st7] Sense Key : Unit Attention [current]
Apr 18 11:01:07 bcksrv1 kernel: st 19:0:0:0: [st7] Add. Sense: Power on, reset, or bus device reset occurred
Apr 18 11:01:07 bcksrv1 iscsid: connection18:0 is operational after recovery (1 attempts)

Apparently it is due to a communication error which causes an iSCSI disconnection. I would not consider this a MINOR bug, I was switching from Bacula after reading a tutorial give by Luis Alberto Giménez at Open Source Backup Conference in 2015 where he said that everything was working fine with amazon AWS, well now it isn't, so it is a feature that has been broken. I will ask him which bareos version he was running and on what OS...





Tried with

    Backward Space File = no
    Backward Space Record = no

on device config file. Nothing chages:

Connecting to Storage daemon VTL at bcksrv1.utv.cps:9103 ...
Sending label command for Volume "UTV2A548F" Slot 1 ...
block.c:286 Volume data error at 0:0! Wanted ID: "BB02", got "". Buffer discarded.
block.c:630 Write error at 0:0 on device "amazon-vtl-td0" (/dev/nst7). ERR=Input/output error.
block.c:644 Write error on fd=4 at file:blk 0:0 on device "amazon-vtl-td0" (/dev/nst7). ERR=Input/output error.
Backspace record at EOT failed. ERR=Input/output error
3912 Failed to label Volume: ERR=generic_tape_device.c:726 ioctl MTBSR error on "amazon-vtl-td0" (/dev/nst7). ERR=Input/output error.

Label command failed for Volume UTV2A548F.

It is still trying to perform an MTBSR ioctl() call, and there it fails.


After disabling MTBSR btape test gives:

Tape block granularity is 1024 bytes.
btape: butil.c:274-0 Using device: "amazon-vtl-td0" for writing.
btape: btape.c:482-0 open device "amazon-vtl-td0" (/dev/nst7): OK
*test

=== Write, rewind, and re-read test ===

I'm going to write 10000 records and an EOF
then write 10000 records and an EOF, then rewind,
and re-read the data to verify that it is correct.

This is an *essential* feature ...

btape: btape.c:1167-0 Wrote 10000 blocks of 64412 bytes.
btape: btape.c:614-0 Wrote 1 EOF to "amazon-vtl-td0" (/dev/nst7)
btape: btape.c:1183-0 Wrote 10000 blocks of 64412 bytes.
btape: btape.c:614-0 Wrote 1 EOF to "amazon-vtl-td0" (/dev/nst7)
btape: btape.c:1225-0 Rewind OK.
18-Apr 14:16 btape JobId 0: Error: block.c:1003 Read error on fd=3 at file:blk 0:0 on device "amazon-vtl-td0" (/dev/nst7). ERR=Input/output error.
btape: btape.c:1245-0 Read block 1 failed! ERR=Input/output error
guglez

guglez

2017-07-11 15:18

reporter   ~0002681

Was it fixed?
samashton

samashton

2017-07-20 03:20

reporter   ~0002688

Same problem on Redhat 7.3 (EC2 AMI), Bareos Version: 16.2.4 (01 July 2016)

Can use mt and tar as described but btape and bareos report ERR=Input/output error
btape result:

btape: btape.c:1167-0 Wrote 10000 blocks of 64412 bytes.
btape: btape.c:614-0 Wrote 1 EOF to "VTLDrive01" (/dev/tape/by-path/ip-172.31.0.30:3260-iscsi-iqn.1997-05.com.amazon:sgw-2d6f8044-tapedrive-01-lun-0-nst)
btape: btape.c:1183-0 Wrote 10000 blocks of 64412 bytes.
btape: btape.c:614-0 Wrote 1 EOF to "VTLDrive01" (/dev/tape/by-path/ip-172.31.0.30:3260-iscsi-iqn.1997-05.com.amazon:sgw-2d6f8044-tapedrive-01-lun-0-nst)
btape: btape.c:1225-0 Rewind OK.
19-Jul 21:05 btape JobId 0: Error: block.c:1003 Read error on fd=3 at file:blk 0:0 on device "VTLDrive01" (/dev/tape/by-path/ip-172.31.0.30:3260-iscsi-iqn.1997-05.com.amazon:sgw-2d6f8044-tapedrive-01-lun-0-nst). ERR=Input/output error.
btape: btape.c:1245-0 Read block 1 failed! ERR=Input/output error

And Bareos:

3307 Issuing autochanger "unload slot 9, drive 0" command.
3304 Issuing autochanger "load slot 10, drive 0" command.
3305 Autochanger "load slot 10, drive 0", status is OK.
block.c:630 Write error at 0:0 on device "VTLDrive01" (/dev/tape/by-path/ip-172.31.0.30:3260-iscsi-iqn.1997-05.com.amazon:sgw-2d6f8044-tapedrive-01-lun-0-nst). ERR=Input/output error.
block.c:644 Write error on fd=4 at file:blk 0:0 on device "VTLDrive01" (/dev/tape/by-path/ip-172.31.0.30:3260-iscsi-iqn.1997-05.com.amazon:sgw-2d6f8044-tapedrive-01-lun-0-nst). ERR=Input/output error.
Backspace record at EOT failed. ERR=Input/output error
3912 Failed to label Volume: ERR=generic_tape_device.c:726 ioctl MTBSR error on "VTLDrive01" (/dev/tape/by-path/ip-172.31.0.30:3260-iscsi-iqn.1997-05.com.amazon:sgw-2d6f8044-tapedrive-01-lun-0-nst). ERR=Input/output error.

Basicall I can not integrate Baroeos with Amazon VTL Service
damiano.bortolato

damiano.bortolato

2017-08-18 10:42

reporter   ~0002703

No fixes yet (as far as I know).
I'm wondering this is considered a "minor" bug.
kayak1

kayak1

2017-10-04 18:15

reporter   ~0002774

I also have this bug, as a long term user of bacula.org
I was attempting to move to bareos.

sudo -u bareos btape -v /dev/tape/by-path/ip-10.41.0.17:3260-iscsi-iqn.1997-05.com.amazon:sgw-4bc02522-tapedrive-01-lun-0-nst
[sudo] password for jkates:
Tape block granularity is 1024 bytes.
btape: butil.c:274-0 Using device: "/dev/tape/by-path/ip-10.41.0.17:3260-iscsi-iqn.1997-05.com.amazon:sgw-4bc02522-tapedrive-01-lun-0-nst" for writing.
btape: btape.c:482-0 open device "tapedrive-0" (/dev/tape/by-path/ip-10.41.0.17:3260-iscsi-iqn.1997-05.com.amazon:sgw-4bc02522-tapedrive-01-lun-0-nst): OK
*test

=== Write, rewind, and re-read test ===

I'm going to write 10000 records and an EOF
then write 10000 records and an EOF, then rewind,
and re-read the data to verify that it is correct.

This is an *essential* feature ...

btape: btape.c:1167-0 Wrote 10000 blocks of 64412 bytes.
btape: btape.c:614-0 Wrote 1 EOF to "tapedrive-0" (/dev/tape/by-path/ip-10.41.0.17:3260-iscsi-iqn.1997-05.com.amazon:sgw-4bc02522-tapedrive-01-lun-0-nst)
btape: btape.c:1183-0 Wrote 10000 blocks of 64412 bytes.
btape: btape.c:614-0 Wrote 1 EOF to "tapedrive-0" (/dev/tape/by-path/ip-10.41.0.17:3260-iscsi-iqn.1997-05.com.amazon:sgw-4bc02522-tapedrive-01-lun-0-nst)
btape: btape.c:1225-0 Rewind OK.
04-Oct 11:25 btape JobId 0: Error: block.c:1003 Read error on fd=3 at file:blk 0:0 on device "tapedrive-0" (/dev/tape/by-path/ip-10.41.0.17:3260-iscsi-iqn.1997-05.com.amazon:sgw-4bc02522-tapedrive-01-lun-0-nst). ERR=Input/output error.
btape: btape.c:1245-0 Read block 1 failed! ERR=Input/output error
joergs

joergs

2017-12-14 11:57

developer   ~0002838

Fix committed to bareos bareos-17.2 branch with changesetid 7367.

Related Changesets

bareos: bareos-17.2 0879e14d

2017-11-17 19:20

joergs

Ported: N/A

Details Diff		 tape: fix block size handling

Fixes a problem with devices that have the capability CAP_ADJWRITESIZE
(tape drive, ...). As this capability have be ignored, blocks have not
been padded to a minimum length.

Fixes 0000639: bareos unable to read AWS VTL iSCSI devices		 Affected Issues
0000639
mod - src/lib/bits.h Diff File
mod - src/stored/block.c Diff File
mod - src/stored/dev.c Diff File

Issue History

Date Modified Username Field Change
2016-04-05 23:49 areplogle New Issue
2016-04-06 00:47 areplogle File Added: bareos-sysdig.txt
2016-04-06 00:53 areplogle Note Added: 0002228
2016-04-08 22:11 areplogle Note Added: 0002233
2016-04-15 16:17 maik Status new => acknowledged
2016-04-15 16:20 maik Priority high => low
2016-04-15 16:20 maik Severity block => minor
2016-04-24 18:43 areplogle Note Added: 0002246
2016-04-29 23:57 areplogle Note Added: 0002253
2016-05-01 15:58 areplogle Note Added: 0002254
2016-07-31 18:30 sassyn Note Added: 0002328
2016-09-07 19:23 fbacchella Note Added: 0002349
2016-09-07 19:24 fbacchella Note Added: 0002350
2016-10-27 10:39 maurizio.proietti Note Added: 0002412
2016-12-22 12:48 joergs Relationship added has duplicate 0000743
2017-04-18 11:17 damiano.bortolato Note Added: 0002628
2017-04-18 11:50 damiano.bortolato Note Edited: 0002628
2017-04-18 14:17 damiano.bortolato Note Edited: 0002628
2017-07-11 15:18 guglez Note Added: 0002681
2017-07-20 03:20 samashton Note Added: 0002688
2017-08-18 10:42 damiano.bortolato Note Added: 0002703
2017-10-04 18:15 kayak1 Note Added: 0002774
2017-11-28 12:27 joergs Assigned To => joergs
2017-11-28 12:27 joergs Status acknowledged => assigned
2017-12-14 11:57 joergs Changeset attached => bareos bareos-17.2 0879e14d
2017-12-14 11:57 joergs Note Added: 0002838
2017-12-14 11:57 joergs Status assigned => resolved
2017-12-14 11:57 joergs Resolution open => fixed
2017-12-18 12:05 joergs Relationship added child of 0000861
2017-12-18 12:09 joergs Status resolved => closed
2017-12-18 12:09 joergs Assigned To joergs =>
2017-12-18 12:09 joergs Fixed in Version => 17.2.4