 |
Try adding the following to your bareos-dir.conf and bareos-sd.conf both in the server section NDMP Snooping = yes NDMP Loglevel = 7 e.g. for SD that is in the Storage section of the conf and for the DIR its the Director section. Smells a bit like the SD doesn't know how to connect to the NDMP data agent on the NetAPP box. |
|
|
ndmp-snooping-output-201412161549.txt (20,917 bytes) |
|
|
I've attached a text file with the messages output of another restore attempt with NDMP Snooping = yes and NDMP Loglevel = 7 as requested. In case it helps, the name of my Bareos server is "sneakernet" and it's IP address is 192.168.3.157 (c0a8039d in hex). The IP address of the DSTNETAPP system is 192.168.3.216, and SRCNETAPP is the NetApp from which I backed up the volume (/vol/vol1 on SRCNETAPP, and /vol/SRCNETAPP_vol1 on DSTNETAPP). Note that I have the same problem when I try to restore to the same volume name (i.e. /vol/vol1) on DSTNETAPP, so it doesn't appear to be related to redirecting the restore to a different volume name. |
|
|
The NDMP trace shows indeed that the full handshake succeeds and it starts a restore session it only seems it doesn't read a block which must be because the restore selected no media to read. Next option would be to run the SD in debug mode starting with a level 100 or maybe even 200 but this gives really a lot of output. How does your restore session look like in bconsole ? It would also be interesting to see the BSR that gets created as that describes what the SD is going to read. |
|
|
Yes, that's what I thought I was seeing in the NDMP trace, too, which is weird. Like I said, I know the data is intact in the FileStorage pool volumes, because I extracted it using bextract, and in fact, I used a BSR generated by a restore job attempt to do it. Note that when I did the extract, it put the extracted files relative to a top-level directory named "@NDMP", so when I extracted an SMTAPE backup of /vol/vol1 to /home/tmp, it actually put the file in /home/tmp/@NDMP/vol/vol1. I also manually copied that extracted "vol1" file to DSTNETAPP and successfully used it to restore a volume using the "smtape restore" command right on the NetApp CLI, so it's definitely not munged. Anyway, here's what the restore job looks like in bconsole right before I run it: Run Restore job JobName: Restore SRCNETAPP:vol1 smtape to DSTNETAPP:SRCNETAPP_vol1 Bootstrap: /var/lib/bareos/sneakernet-dir.restore.3.bsr Where: /vol/SRCNETAPP_vol1 Replace: Always FileSet: SRCNETAPP_vol1-fileset Backup Client: SRCNETAPP Restore Client: DSTNETAPP Format: smtape Storage: File When: 2014-12-16 14:13:16 Catalog: MyCatalog Priority: 10 Plugin Options: *None* I also attached the BSR referenced above to this bug. Any idea why bextract is reading the FileStorage volumes properly, but SD seems to be choking on them and returning EOF right on the first read? |
|
|
As the same code is used there must be something that it doesn't like. Which can be also still on the NDMP level. Only a debug run of the SD will show what is going on. So run bareos-sd -f -d 200 > logfile and make sure you only have the NDMP restore as this will give quite some debug output and gets fully unreadable when more then one job is running. Keep in mind that the SD probably runs as user bareos so you need to run the debug also under that user (as the user has not login shell you need su - bareos -s /bin/bash or so) |
|
|
I've uploaded the bareos-sd log output (at debug level 200) for an attempt to restore vol2. I had to split it into two parts in order to upload it to this bug, but it's all from one run. |
|
|
Ok log looks normal and the SD processes everything only the NDMP tape never opens. The SD get a cancel: sneakernet-sd: dir_cmd.c:262-0 <dird: cancel Job=Restore_SRCNETAPP:vol2_smtape_to_DSTNETAPP:vol2.2014-12-17_11.16.47_10 So the dir is canceling the restore for whatever reason. So think we can remove the SD from the problem. |
|
|
Need a debug log from the director which is more or less the same cmdline. |
|
|
Director debug log (level 200) for another restore job with the same parameters as for the bareos-sd debug is attached. |
|
|
Just want to throw this out there: I seem to remember something about SMTAPE on the NetApp using a 240KB tape block size, but in the debug logs I just uploaded, I see a lot of references to a max block size of 64KB. Any relevance? |
|
|
The logs at least confirm that everything is setup right and tape is opened by the NDMP DMA and the moment the data mover gets active the NetAPP seems to abort the restore. About the tape block size as NDMP is so device specific you could be right. The blocksize you see is the default blocksize but its configurable using the NdmpBlockSize parameter in the client definition it defaults to 64512. |
|
|
Does the Director communicate the blocksize to the NetApp prior to the abort? With the FileStorage volume type, does the block size on the restore have to match the block size on the backup? I'd like to try to change the NdmpBlockSize parameter to 245760 bytes, but I want to make sure this won't cause any major problems on the NetApp. |
|
|
The NDMP blocksize is only used as send size over the NDMP protocol as we don't support direct writing to NDMP Tape agents e.g. we emulate the Tape Agent in the bareos SD the actual data is written in the blocksize of the lower level device anyway. So I think you can just change the blocksize but what impact that has on the NetAPP I have no idea then again its not an enormous blocksize. |
|
|
I changed the NdmpBlockSize on the Client entry for DSTNETAPP to 24576 (240KB), and now it no longer fails immediately! However, the NDMP Mover function of the SD doesn't actually move any data. The TCP connection established from the NetApp to the SD stays connected now, but they just keep exchanging 0 byte payload packets, and the restore job just keeps logging "DATA: bytes 0KB MOVER: read 0KB record 0" every 30 seconds until I cancel the job. |
|
|
Uploaded new debug logs for DIR and SD on new restore attempt described in my last note. |
|
|
Ok removed the debugging output from the report as it only shows obvious things. Looked at the whole blocksize thing with SMTAPE and it seems its hardcoded to use a blocksizes from 4 to 256 Kb in multiples of 4 Kb. Don't seem to remember that was like that before. But that does show a problem with the default blocksize we use which is 15.75 x 4 Kb so that is probably why its not happy. The problem with replying at night is that you sometimes don't see the whole picture. But the current code will always return the saved data in the same chunk size as the data was saved in so changing it to 240 Kb will still return only chunks of the original size. So I think your only option is to: - Change the NDMP blocksize to something that can be divided by 4 Kb - Create a Pool with a blocksize that matches the NDMP blocksize - Create a new backup with these new settings. |
|
|
I'm still unclear as to what's happening here. Can the SD not read the backed-up data in the File-type Volumes that hold the backups for some reason? Is it trying to use the newly-set 240KB NdmpBlockSize to read them and failing to do so because it doesn't match the blocksize used to back up the data? I'm still confused as to how the source Netapp was able to stream the SMTAPE back to the SD in the first place if the size of the 240KB blocks the Netapp was sending exceeded Bareos' default block size for File-type Volumes (is this 63KB)? Did the SD just ignore the blocking and take the data as a stream of bytes, reblocking it to whatever block size it uses for the File-type Volumes (is this also 63KB)? Is the block size of the File-type Volumes configurable, or is it the same for all such File-type Volumes? If it is configurable/variable, is there any way to tell what the block size of an existing File-type Volume is? No matter what I set the "Maximum Block Size" and "Minimum Block Size" for the "File" Device in bareos-sd.conf, bls seems to be able to read the existing Volumes without issue, so I suspect this parameter is fixed and ignore for this Volume/Device type, but that's just a guess, I'm sure you know for sure. |
|
|
Those are a lot of questions and they mostly make little sense. One things is for sure the NetAPP is indeed buggy as it allows you to use a blocksize that it doesn't support for backup but on restore it fails to restore such a blocksize. The 240 Kb blocksize is the default but is in no way a must see my previous note on how it really works. Could be it are two different levels of the NetAPP OS. When you search for blocksize and NetAPP it looks as if 8.2 is somewhat prominently mentioned. As to why 240 Kb reading doesn't work is because the SD reads the old NDMP blocks (which are completely different then what Bareos calls a block) back in their own size. The NDMP blocks are encoded as normal so called DATA streams (each piece of backup data has it own streamtype e.g. data, metadata, compressed data etc.) The current code doesn't try to assemble parts or multipe parts of data into one bigger block. That is also fine as its a known limitation that you should use the same NDMP blocksize for backup and restore. As to why it works with bextract is fairly simple, that just concatenates all data blocks into one long data stream. That is something you can of course read in any blocksize you want until it fully processed. Any setting of the minimum and maximum block size on the bareos tape/file device have zero impact on the whole thing as the NDMP blocksize is a separate configuration setting and the code will chunk things in the right way as it operates on NDMP data streams which are for the SD an opaque data stream. The SD just returns the exact same data as the bextract only in 63 Kb e.g. the POSIX default blocksize. The NetAPP for whatever reason (probably because its not a 4 Kb chunked piece of data) doesn't like the data coming in over the NDMP protocol. I would be possible to write re-assembly code that maps from one NDMP blocksize to an other on restore but that is not something that is really high on my priority list, also given that NDMP blocksize is a known fixed thing for NDMP so it only possible because we emulate the NDMP Tape Agent to do such translation. So I guess your only option is to perform the actions I mentioned in the note above. The blocksize on the disk pool is not strictly needed but for performance reasons it probably makes sense to have a blocksize that is a bit bigger even then NDMP blocksize so a single chunk of backup data fits and doesn't need to be cut into multiple pieces when saving it. |
|
|
"One things is for sure the NetAPP is indeed buggy as it allows you to use a blocksize that it doesn't support for backup but on restore it fails to restore such a blocksize. The 240 Kb blocksize is the default but is in no way a must see my previous note on how it really works. Could be it are two different levels of the NetAPP OS. When you search for blocksize and NetApp it looks as if 8.2 is somewhat prominently mentioned." I think SMTAPE is somewhat different than a non-SMTAPE NDMP backup. The NetApp generates a single SMTAPE file for the volume you're backing up and transfers it via NDMP to the Tape Agent as it's being generated. The SMTAPE volume backup file seems to be somewhat like a tarfile, and it is generated with a 240KB internal data block size by default. When an SMTAPE backup is conducted via NDMP, the NetApp doesn't seem to care if the NDMP Tape Agent session's block size is different than the SMTAPE block size. With an NdmpBlockSize of 63KB configured on a session, the NDMP service on the NetApp just breaks the stream of bytes from its SMTAPE generation process into 63KB blocks and transfers them to the Tape Agent. It's on the NDMP SMTAPE restore sessions that the NetApp seems to require an exactly 240KB NDMP block size, or else it fails immediately, with the error I originally reported, regardless of the DATA_BLOCK_SIZE meta option configured on the restore fileset in bareos-dir.conf (I tried setting that to 63KB at one point, too). This seems to me to be an arbitrary and harmful limitation of the NetApp, so I agree with your "buggy" assessment in this case. "The SD just returns the exact same data as the bextract only in 63 Kb e.g. the POSIX default blocksize. The NetAPP for whatever reason (probably because its not a 4 Kb chunked piece of data) doesn't like the data coming in over the NDMP protocol." I don't think that's what we're seeing here. I've run tcpdump during the restore attempts, and as far as I can tell, the SD isn't sending anything to the NetApp at all. The SD and the NetApp just exchange TCP packets with zero-byte payloads back and forth over the NDMP Tape Agent connection forever until I abort the job by stopping the Director. Is the SD not sending anything because the size of the blocks that it's reading from the backup Volumes is different from the NdmpBlockSize? Is there any indication of this in the SD debug logs? I can live with making another NDMP SMTAPE backup of the source volume using a 240KB NdmpBlockSize if I have to, I just want to make sure we understand why the SD isn't reading and sending blocks of data to the NetApp with the current configuration before I do so, because it's a big volume, and it will probably take a full 24 hours for me to back it up again. |
|
|
I have no idea but I would say create a small test set. As NDMP is such a weird protocol it seems everyone does it own way of implementing things. I think its a protocol violation if the NetAPP doesn't adhere to the correct blocksize given on restore then again NetAPP is one of the inventors of NDMP. But we have seen more strangeness from NetAPP, but unless I get some money to spend on it this is how far I can debug it remotely. After all this is open source you could try adding some more debugging to the NDMP tape callbacks in the SD to get a better idea what its doing. We based this on top of a reference implementation of NDMP which is also used by other open source vendors. |
|
|
b.t.w. as we are entering the holiday season I won't be doing much this year. |
|
|
Ok, thanks for your help, I appreciate it. You've pointed me in the right direction, and I'll post back to this bug after I've got it figured out. Cheers! |
|
|
Just a quick update. I tried setting the NdmpBlockSize on the source NetApp's Client definition and the Max Block Size on a new Pool and Storage Device all to 245760 bytes (240KB) , but tripped over an issue with setting the NdmpBlockSize greater than 102400 bytes (100KB). I think this is because the NDMP Channel Image Stream Buffer Size is currently set to 100KB in src/ndmp/ndmagents.h, here: #ifndef NDM_N_IMAGE_STREAM_BUF #define NDM_N_IMAGE_STREAM_BUF (100*1024) #endif As a result, when you specify the NdmpBlockSize bigger than NDM_N_IMAGE_STREAM_BUF on a backup, the image stream buffer fills up waiting for the Bareos SD to start pulling it out of the buffer and writing it to disk, but the SD is waiting for a full NDMP block to be received, which will never happen, because the NDMP channel is out of buffer space to store more data, so the SD starts advertising a zero-byte TCP window to the client (the NetApp, in this case). I'm going to increase the stream buffer size in the header file to 256KB and recompile to see if that allows me to take a backup with 240KB NDMP, tape, and SMTAPE image block sizes. |
|
|
Increasing that NDM_M_IMAGE_STREAM_BUF value to 256KB did indeed allow a backup to proceed with NdmpBlockSize and the volume max block size set to 245760 bytes (note that I left the volume label block size at the new default value of 63KB), but restores are still failing almost immediately with the same EOF error I originally reported. However, I am now almost certain that this error is being generated by the Bareos SD. Here's the relevant debug output from the bareos-sd process (run at debug level 999) during a restore attempt: *** sneakernet-sd: ndmp_tape.c:245-0 NDMP: [#C] [5] >C NDMP4_MOVER_READ 11 *** sneakernet-sd: ndmp_tape.c:245-0 NDMP: [#C] [6] offset=0 length=-1 *** sneakernet-sd: ndmp_tape.c:245-0 NDMP: [#C] [5] R> NDMP4_MOVER_READ 11 (13) *** sneakernet-sd: ndmp_tape.c:245-0 NDMP: [#C] [6] error=NDMP4_NO_ERR *** sneakernet-sd: ndmp_tape.c:245-0 NDMP: [#C] [9] writing 32 ... *** sneakernet-sd: ndmp_tape.c:245-0 NDMP: [#C] [9] 80 00 00 1c 00 00 00 0d 54 af 66 78 00 00 00 01 *** sneakernet-sd: ndmp_tape.c:245-0 NDMP: [#C] [9] 00 00 0a 06 00 00 00 0b 00 00 00 00 00 00 00 00 *** sneakernet-sd: ndmp_tape.c:245-0 NDMP: [#C] [8] write=32 len=32 In the snippet above, the NetApp appears to tell the MOVER state machine within Bareos SD's NDMP TAPE service to start reading the backup from the file volume. *** sneakernet-sd: record.c:669-0 Block=0 Ver=2 size=245760 *** sneakernet-sd: record.c:677-0 Enter read_record_block: remlen=245736 data_len=0 rem=0 blkver=2 *** sneakernet-sd: record.c:741-0 rd_rec_blk() got FI=SOS_LABEL SessId=1 Strm=128 len=223 remlen=245724 data_len=0 *** sneakernet-sd: record.c:805-0 Rtn full rd_rec_blk FI=SOS_LABEL SessId=1 Strm=128 len=223 *** sneakernet-sd: read_record.c:285-0 read-OK. state_bits= blk=0 rem=0 file:block=0:245973 *** sneakernet-sd: read_record.c:296-0 recno=1 state_bits= blk=0 SI=1 ST=1420780864 FI=-4 *** sneakernet-sd: read_record.c:74-0 Begin Session Record: VolSessionId=1 VolSessionTime=1420780864 JobId=128 DataLen=223 Then, the debug shows that the SD successfully read the SOS (Start of Session) record from the volume, and it correctly identifies the backup as JobId 128. *** sneakernet-sd: ndmp_tape.c:245-0 NDMP: [#C] [5] C> NDMP4_NOTIFY_MOVER_PAUSED 14 *** sneakernet-sd: ndmp_tape.c:245-0 NDMP: [#C] [6] reason=NDMP4_MOVER_PAUSE_EOF seek_position=0 *** sneakernet-sd: ndmp_tape.c:245-0 NDMP: [#C] [9] writing 40 ... *** sneakernet-sd: ndmp_tape.c:245-0 NDMP: [#C] [9] 80 00 00 24 00 00 00 0e 54 af 66 78 00 00 00 00 *** sneakernet-sd: ndmp_tape.c:245-0 NDMP: [#C] [9] 00 00 05 04 00 00 00 00 00 00 00 00 00 00 00 02 *** sneakernet-sd: ndmp_tape.c:245-0 NDMP: [#C] [9] 00 00 00 00 00 00 00 00 *** sneakernet-sd: ndmp_tape.c:245-0 NDMP: [#C] [8] write=40 len=40 Right here is the problem: immediately after the SD successfully reads the SOS record, the SD notifies the NDMP client (the NetApp) that it has paused its MOVER because it reached an unexpected EOF reading from the volume, which is incorrect. As soon as the NetApp sees this EOF notification, it tells the Director to cancel the restore job. So, any idea why the SD is pausing the MOVER and blaming it on a non-existent EOF read? |
|
|
I guess you only find out if you put thing under a debugger the interesting entry points are bndmp_read_data_from_block() and bndmp_tape_read(). bndmp_tape_read() is the callback called by the NDMP code for reading tape data. I also added two patches that change the checking of the SMTAPE blocksize to be in the range defined by NetAPP and one other patch allocating the image stream buffer dynamically according to the used NDMP Job. We spend quite some time on modernizing this reference implementation of the NDMP protocol but its from 2001 and that shows in some cases. Although this has my personal interest there are currently a lot of things preempting any time I can spend on it other then replying and giving some hints. |
|
|
I think I got it figured out Friday night. In the main loop of bndmp_read_data_from_block(), when read_next_record_from_block() succeeds, the maskedStream field (an int32_t) of the read record is checked and matched against three possible values (defined in streams.h): * STREAM_UNIX_ATTRIBUTES [1] * STREAM_FILE_DATA [2] * STREAM_NDMP_SEPERATOR [999] STREAM_UNIX_ATTRIBUTES records are silently discarded (i.e. the read loop just continues) and STREAM_FILE_DATA records are passed to the DATA agent. STREAM_NDMP_SEPERATOR and all other record types (including SOS_LABEL records) are also discarded, but not silently. Rather, the data_length variable is set to zero, and the function returns true back to bndmp_tape_read() from which it was called. The data_length value in bndmp_read_data_from_block() is passed back to the done_count variable in bndmp_tape_read(), and if done_count equals zero (which it does, in this case), then bndmp_tape_read() returns an NDMP9_EOF_ERR to its caller, which kills the restore job as soon as it begins. To fix this behavior, I modified bndmp_read_data_from_block() to silently discard the SOS_LABEL record (with maskedStream of 128) in the same manner as it does STREAM_UNIX_ATTRIBUTES records. An EOF is still generated when the STREAM_NDMP_SEPERATOR record that appears after the SMTAPE file data stream is fully read, which causes Bareos to report that the restore failed, but it actually succeeds on the NetApp (i.e. the restore target volume is fully restored from the SMTAPE backup). So, some further modification is necessary to get Bareos to close out the restore job properly, but it appears to do what I need it to do now. |
|
|
Thanks for the analyses it seems this is a side effect of some things changing over time in the upper levels which means that the reader now needs to handle those label records itself (e.g. ignore them.) Although your workaround probably works I think the fix is a bit more subtle e.g. we need to skip any label record e.g. check if FileIndex is negative and skip those. I added a patch that does that and also prints an error now when it gets a datastream that it doesn't like which means we sooner see these kind of problems in the debugging output may it ever occur again. I added that patch maybe you can test with these 3 patches and we can take it from there. Regarding the STREAM_NDMP_SEPERATOR that is a valid EOF marker so I would be interested as to why the restore Job is actually getting a failed state. As each NDMP implementation is different this could be some strange side effect. I do remeber that when writing the code I also got some strange error on the Oracle NDMP implementation when it asked for a certain return status after the restore but when looking better at the NDMP rfc it was obvious that was a false implementation in the NDMP server software. |
|
|
Could you elaborate a bit more on what error you see when restoring after the fixes you made ? Then I can either close this report or look what needs to be fixed. |
- Anonymous
