View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0000796bareos-coredirectorpublic2017-03-10 09:442023-04-14 11:49
Reporterisi Assigned Tobruno-at-bareos  
PrioritynormalSeverityminorReproducibilityalways
Status closedResolutionunable to reproduce 
PlatformLinuxOSDebianOS Version8
Product Version16.2.4 
Summary0000796: NDMP Restore Error Messages
DescriptionNDMP 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 ReproduceRestore NDMP Backup of OmniOS r151020 Volume
TagsNo tags attached.

Activities

isi

isi

2017-03-10 09:52

reporter   ~0002604

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.'
bruno-at-bareos

bruno-at-bareos

2023-03-23 16:18

manager   ~0004934

Is this still reproducible with current code (Bareos >21) ?
bruno-at-bareos

bruno-at-bareos

2023-04-14 11:49

manager   ~0004971

No feedback, works as expected in >=22

Issue History

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