View Issue Details
ID | Project | Category | View Status | Date Submitted | Last Update |
---|---|---|---|---|---|
0000796 | bareos-core | director | public | 2017-03-10 09:44 | 2023-04-14 11:49 |
Reporter | isi | Assigned To | bruno-at-bareos | ||
Priority | normal | Severity | minor | Reproducibility | always |
Status | closed | Resolution | unable to reproduce | ||
Platform | Linux | OS | Debian | OS Version | 8 |
Product Version | 16.2.4 | ||||
Summary | 0000796: NDMP Restore Error Messages | ||||
Description | NDMP Backup of OmniOS r151020 works with no errors. Restore first checks looks ok, all files are there even the not found ones in the logs. It throws following error Messages and Job State is Failure: 2017-03-10 08:10:53 bareos-dir JobId 26: Commanding tape drive to rewind 2017-03-10 08:10:53 bareos-dir JobId 26: Closing tape drive EBNK-FNHP-KGOJ-CFAD-HJLP-NJPE-KJAH-PNGA@/vol1/admin 2017-03-10 08:10:53 bareos-dir JobId 26: Operation did not halt, something wrong 2017-03-10 08:10:53 bareos-dir JobId 26: Operation halted, stopping 2017-03-10 08:10:53 bareos-dir JobId 26: Operation ended in failure 2017-03-10 08:10:53 bareos-dir JobId 26: ERR NDMP4_DATA_STOP NDMP4_ILLEGAL_STATE_ERR 2017-03-10 08:10:53 bareos-dir JobId 26: Operation did not stop, something wrong 2017-03-10 08:10:53 bareos-dir JobId 26: Error: ERROR in ndmca_control_agent 2017-03-10 08:10:53 bareos-dir JobId 26: Error: Bareos bareos-dir 16.2.4 (01Jul16): Build OS: x86_64-pc-linux-gnu debian Debian GNU/Linux 8.0 (jessie) JobId: 26 Job: tknas_restore-job.2017-03-10_08.09.02_23 Restore Client: tknas-ndmp Start time: 10-Mär-2017 08:09:04 End time: 10-Mär-2017 08:10:53 Elapsed time: 1 min 49 secs Files Expected: 1 Files Restored: 0 Bytes Restored: 0 Rate: 0.0 KB/s SD termination status: Running Termination: *** Restore Error *** 2017-03-10 08:10:33 bareos-dir JobId 26: DATA: bytes 13418KB MOVER: read 14616KB record 231 2017-03-10 08:10:33 bareos-dir JobId 26: Operation monitoring mishandled, cancelling 2017-03-10 08:10:33 bareos-dir JobId 26: Waiting for operation to halt 2017-03-10 08:10:23 bareos-dir JobId 26: DATA: bytes 13418KB MOVER: read 14616KB record 231 2017-03-10 08:10:13 bareos-dir JobId 26: DATA: bytes 13418KB MOVER: read 14616KB record 231 2017-03-10 08:10:03 bareos-dir JobId 26: DATA: bytes 13418KB MOVER: read 14616KB record 231 2017-03-10 08:09:53 bareos-dir JobId 26: DATA: bytes 13418KB MOVER: read 14616KB record 231 2017-03-10 08:09:43 bareos-dir JobId 26: DATA: bytes 13418KB MOVER: read 14616KB record 231 2017-03-10 08:09:33 bareos-dir JobId 26: DATA: bytes 13418KB MOVER: read 14616KB record 231 2017-03-10 08:09:25 bareos-dir JobId 26: OK: /vol1/admin/tknas-old 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/config-db 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/config-db/tknas_20131208.db 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/check_space.py 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/pymail.py 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/sysctl.txt 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/nas0-liesmich.txt 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/tknas-liesmich.txt 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/upgrade.bat 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/info.sh 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/config-db/tknas_20131205.db 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/versions.txt 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/bkpconfig.sh 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/prom0011.img 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/flash.exe 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/automatic_redirect_10.2.2.1_release_notes.html 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/10.2.2.1-9750-firmware.zip 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/config-db/tknas_20131207.db 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/config-db/tknas_20131206.db 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/config-db/tknas_20131204.db 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/config-db/tknas_20131203.db 2017-03-10 08:09:25 bareos-dir JobId 26: Not found: /vol1/admin/tknas-old/config-db/tknas_20131209.db 2017-03-10 08:09:23 bareos-dir JobId 26: OK: /vol1/admin/sas2ircu 2017-03-10 08:09:23 bareos-dir JobId 26: OK: /vol1/admin/prepare_tsm_ndmp.sh 2017-03-10 08:09:23 bareos-dir JobId 26: DATA: bytes 10628KB MOVER: read 14616KB record 231 2017-03-10 08:09:23 bareos-dir JobId 26: Mover paused, reason=NDMP9_MOVER_PAUSE_EOF 2017-03-10 08:09:23 bareos-dir JobId 26: End of tapes 2017-03-10 08:09:23 bareos-dir JobId 26: DATA: bytes 10628KB MOVER: read 14616KB record 231 2017-03-10 08:09:22 bareos-dir JobId 26: OK: /vol1/admin/nfssvrtop.sh 2017-03-10 08:09:22 bareos-dir JobId 26: OK: /vol1/admin/smart-log.old 2017-03-10 08:09:21 bareos-dir JobId 26: OK: /vol1/admin/disk-errors.old 2017-03-10 08:09:21 bareos-dir JobId 26: OK: /vol1/admin/smart-log.txt 2017-03-10 08:09:20 bareos-dir JobId 26: OK: /vol1/admin/checksmart.sh 2017-03-10 08:09:19 bareos-dir JobId 26: OK: /vol1/admin/zrep-161 2017-03-10 08:09:18 bareos-dir JobId 26: OK: /vol1/admin/bbcp 2017-03-10 08:09:17 bareos-dir JobId 26: OK: /vol1/admin/zrep 2017-03-10 08:09:16 bareos-dir JobId 26: OK: /vol1/admin/admin_solaris_ZFS.pdf 2017-03-10 08:09:15 bareos-dir JobId 26: OK: /vol1/admin/liesmich-system.txt 2017-03-10 08:09:14 bareos-dir JobId 26: OK: /vol1/admin/disks.new 2017-03-10 08:09:13 bareos-dir JobId 26: OK: /vol1/admin/maillogs.sh 2017-03-10 08:09:12 bareos-dir JobId 26: OK: /vol1/admin/disk-errors.log 2017-03-10 08:09:11 bareos-dir JobId 26: OK: /vol1/admin/cifssvrtop.sh 2017-03-10 08:09:10 bareos-dir JobId 26: OK: /vol1/admin/hdd-health-status.sh 2017-03-10 08:09:09 bareos-dir JobId 26: OK: /vol1/admin/disks.txt 2017-03-10 08:09:08 bareos-dir JobId 26: OK: /vol1/admin/zilstat.sh 2017-03-10 08:09:07 bareos-dir JobId 26: OK: /vol1/admin/liesmich-zfs.txt 2017-03-10 08:09:06 bareos-dir JobId 26: OK: /vol1/admin/admin_solaris_ZFS.pdf.ndmptest 2017-03-10 08:09:05 bareos-dir JobId 26: OK: /vol1/admin/zrep-131 2017-03-10 08:09:04 bareos-dir JobId 26: Start Restore Job tknas_restore-job.2017-03-10_08.09.02_23 2017-03-10 08:09:04 bareos-dir JobId 26: Using Device "FileStorage" to read. 2017-03-10 08:09:04 bareos-dir JobId 26: Opening tape drive EBNK-FNHP-KGOJ-CFAD-HJLP-NJPE-KJAH-PNGA@/vol1/admin read-only 2017-03-10 08:09:04 bareos-dir JobId 26: Commanding tape drive to rewind 2017-03-10 08:09:04 bareos-sd JobId 26: Ready to read from volume "ndmp001" on device "FileStorage" (/var/lib/bareos/storage). 2017-03-10 08:09:04 bareos-sd JobId 26: Forward spacing Volume "ndmp001" to file:block 0:48551436. 2017-03-10 08:09:04 bareos-dir JobId 26: Async request NDMP4_LOG_MESSAGE 2017-03-10 08:09:04 bareos-dir JobId 26: LOG_MESSAGE: 'DAR is disabled. Running Restore without DAR' 2017-03-10 08:09:04 bareos-dir JobId 26: Async request NDMP4_LOG_MESSAGE 2017-03-10 08:09:04 bareos-dir JobId 26: LOG_MESSAGE: 'Restoring to "/vol1/admin/vol1/restore/tknas-old, /vol1/admin/vol1/restore/tknas-old/config-db, /vol1/admin/vol1/restore/bbcp, /vol1/admin/vol1/restore/zrep-161, /vol1/admin/vol1/restore/hdd-health-status.sh, /vol1/admin/vol1/restore/tknas-old/config-db/tknas_20131208.".' 2017-03-10 08:09:04 bareos-dir JobId 26: Async request NDMP4_LOG_MESSAGE 2017-03-10 08:09:04 bareos-dir JobId 26: LOG_MESSAGE: 'Tape server: remote at 10.210.0.47:47935.' 2017-03-10 08:09:04 bareos-dir JobId 26: Waiting for operation to start 2017-03-10 08:09:04 bareos-dir JobId 26: Async request NDMP4_NOTIFY_DATA_READ 2017-03-10 08:09:04 bareos-dir JobId 26: Async request NDMP4_LOG_MESSAGE 2017-03-10 08:09:04 bareos-dir JobId 26: Operation started 2017-03-10 08:09:04 bareos-dir JobId 26: Monitoring recover | ||||
Steps To Reproduce | Restore NDMP Backup of OmniOS r151020 Volume | ||||
Tags | No tags attached. | ||||
Here is the corresponding Backup LOG: 2017-03-10 08:06:40 bareos-dir JobId 25: Commanding tape drive to NDMP9_MTIO_EOF 2 times 2017-03-10 08:06:40 bareos-dir JobId 25: Commanding tape drive to rewind 2017-03-10 08:06:40 bareos-dir JobId 25: Closing tape drive BMNF-BGMC-ALEA-FOGK-PBAO-KKBJ-HECM-IFIP@/vol1/admin 2017-03-10 08:06:40 bareos-dir JobId 25: Operation halted, stopping 2017-03-10 08:06:40 bareos-dir JobId 25: Operation ended OKAY 2017-03-10 08:06:40 bareos-dir JobId 25: ndmp_fhdb_lmdb.c:724 Now processing lmdb database 2017-03-10 08:06:40 bareos-dir JobId 25: ndmp_fhdb_lmdb.c:728 Processing lmdb database done 2017-03-10 08:06:40 bareos-sd JobId 25: Elapsed time=00:00:04, Transfer rate=3.741 M Bytes/second 2017-03-10 08:06:40 bareos-dir JobId 25: Bareos bareos-dir 16.2.4 (01Jul16): Build OS: x86_64-pc-linux-gnu debian Debian GNU/Linux 8.0 (jessie) JobId: 25 Job: tknas-ndmp-job.2017-03-10_08.06.34_21 Backup Level: Full Client: "tknas-ndmp" FileSet: "tknas-fs" 2017-03-09 07:33:48 Pool: "NDMPFile" (From Job resource) Catalog: "MyCatalog" (From Client resource) Storage: "NDMPFile" (From Pool resource) Scheduled time: 10-Mär-2017 08:06:29 Start time: 10-Mär-2017 08:06:36 End time: 10-Mär-2017 08:06:40 Elapsed time: 4 secs Priority: 10 NDMP Files Written: 45 SD Files Written: 1 NDMP Bytes Written: 14,966,784 (14.96 MB) SD Bytes Written: 14,966,875 (14.96 MB) Rate: 3741.7 KB/s Volume name(s): ndmp001 Volume Session Id: 15 Volume Session Time: 1489039946 Last Volume Bytes: 63,529,885 (63.52 MB) Termination: Backup OK 2017-03-10 08:06:38 bareos-dir JobId 25: DATA: bytes 14616KB MOVER: written 14616KB record 232 2017-03-10 08:06:38 bareos-dir JobId 25: Operation done, cleaning up 2017-03-10 08:06:38 bareos-dir JobId 25: Waiting for operation to halt 2017-03-10 08:06:37 bareos-dir JobId 25: LOG_MESSAGE: 'Runtime [/vol1/admin] 14966784 bytes (14966784): 0 seconds' 2017-03-10 08:06:36 bareos-dir JobId 25: Start NDMP Backup JobId 25, Job=tknas-ndmp-job.2017-03-10_08.06.34_21 2017-03-10 08:06:36 bareos-dir JobId 25: Using Device "FileStorage" to write. 2017-03-10 08:06:36 bareos-dir JobId 25: Opening tape drive BMNF-BGMC-ALEA-FOGK-PBAO-KKBJ-HECM-IFIP@/vol1/admin read/write 2017-03-10 08:06:36 bareos-sd JobId 25: Volume "ndmp001" previously written, moving to end of data. 2017-03-10 08:06:36 bareos-sd JobId 25: Ready to append to end of Volume "ndmp001" size=48551436 2017-03-10 08:06:36 bareos-dir JobId 25: Commanding tape drive to rewind 2017-03-10 08:06:36 bareos-dir JobId 25: Async request NDMP4_LOG_MESSAGE 2017-03-10 08:06:36 bareos-dir JobId 25: LOG_MESSAGE: 'Direct Access Restore information is supported' 2017-03-10 08:06:36 bareos-dir JobId 25: Waiting for operation to start 2017-03-10 08:06:36 bareos-dir JobId 25: Async request NDMP4_LOG_MESSAGE 2017-03-10 08:06:36 bareos-dir JobId 25: Operation started 2017-03-10 08:06:36 bareos-dir JobId 25: Monitoring backup 2017-03-10 08:06:36 bareos-dir JobId 25: LOG_MESSAGE: 'Backing up "/vol1/admin".' 2017-03-10 08:06:36 bareos-dir JobId 25: LOG_MESSAGE: 'Tape record size: 64512.' 2017-03-10 08:06:36 bareos-dir JobId 25: LOG_MESSAGE: 'File history: Y.' 2017-03-10 08:06:36 bareos-dir JobId 25: LOG_MESSAGE: 'Date of the last level '0': the epoch.' 2017-03-10 08:06:36 bareos-dir JobId 25: LOG_MESSAGE: 'Date of this level '0': Fri Mar 10 08:06:36 2017.' 2017-03-10 08:06:36 bareos-dir JobId 25: LOG_MESSAGE: 'Update: FALSE.' |
|
Is this still reproducible with current code (Bareos >21) ? | |
No feedback, works as expected in >=22 | |
Date Modified | Username | Field | Change |
---|---|---|---|
2017-03-10 09:44 | isi | New Issue | |
2017-03-10 09:52 | isi | Note Added: 0002604 | |
2023-03-23 16:18 | bruno-at-bareos | Assigned To | => bruno-at-bareos |
2023-03-23 16:18 | bruno-at-bareos | Status | new => feedback |
2023-03-23 16:18 | bruno-at-bareos | Note Added: 0004934 | |
2023-04-14 11:49 | bruno-at-bareos | Status | feedback => closed |
2023-04-14 11:49 | bruno-at-bareos | Resolution | open => unable to reproduce |
2023-04-14 11:49 | bruno-at-bareos | Note Added: 0004971 |