NBU 7.6报错2074: Disk volume is down

vinciho

两个星期前安装的NBU 7.6.0.4，创建基于MSDP的Storage Unit，然后用来备份vsphere环境的VMs，走SAN方式，一切顺利。

昨天，突然所有备份都失败了，每个job报错：
NBU status=2074, EMM status=Disk volume is down

# ./nbdevquery -listdv -stype PureDisk -U
Disk Pool Name      : diskpool_01
Disk Type           : PureDisk
Disk Volume Name    : PureDiskVolume
Disk Media ID       : @aaaab
Total Capacity (GB) : 1843.51
Free Space (GB)     : 1059.01
Use%                : 42
Status              : DOWN
Flag                : ReadOnWrite
Flag                : AdminUp
Flag                : InternalDown
Num Read Mounts     : 0
Num Write Mounts    : 1
Cur Read Streams    : 0
Cur Write Streams   : 0
Num Repl Sources    : 0
Num Repl Targets    : 0


折腾2天了，看了日志许久，没搞定，请问大侠指点迷津！

vinciho

确认这个Storage Unit后台的分区是正常可用的，可以手动创建文件，没有问题。

liuxiaozhe

spad spoold的进程正常吗？把日志贴出来看看

vinciho

spad和spoold进程从Administration Console的Activity Monitor来看，运行都正常。

drwxr-xr-x. 2 root root 4096 Nov  5 09:23 bmrd
drwxr-xr-x. 2 root root 4096 Oct 20 13:58 bmrsetup
drwxr-xr-x. 2 root root 4096 Nov  5 00:00 nbars
drwxr-xr-x. 2 root root 4096 Nov  5 00:12 nbatd
drwxr-xr-x. 2 root root 4096 Nov  5 00:00 nbaudit
drwxr-xr-x. 2 root root 4096 Nov  5 00:00 nbdisco
drwxr-xr-x. 2 root root 4096 Nov  5 00:00 nbemm
drwxr-xr-x. 2 root root 4096 Nov  5 00:00 nbevtmgr
drwxr-xr-x. 2 root root 4096 Nov  5 09:23 nbftclnt
drwxr-xr-x. 2 root root 4096 Nov  3 14:29 nbftsrvr
drwxr-xr-x. 2 root root 4096 Nov  5 10:04 nbim
drwxr-xr-x. 2 root root 4096 Nov  5 00:00 nbjm
drwxr-xr-x. 2 root root 4096 Nov  5 09:23 nbkms
drwxr-xr-x. 2 root root 4096 Nov  5 00:00 nbpem
drwxr-xr-x. 2 root root 4096 Nov  5 00:00 nbrb
drwxr-xr-x. 2 root root 4096 Nov  5 00:00 nbrmms
drwxr-xr-x. 2 root root 4096 Nov  5 00:00 nbsl
drwxr-xr-x. 2 root root 4096 Nov  5 00:00 nbstserv
drwxr-xr-x. 2 root root 4096 Nov  5 00:00 nbsvcmon
drwxr-xr-x. 2 root root 4096 Nov  5 00:00 nbvault
drwxr-xr-x. 2 root root 4096 Oct 20 17:16 ncfnbrestore

需要看哪个deamon的日志呢？请告知，谢谢。

vinciho

# ./vxlogview -X "jobid=160" -d all
11/05/2015 13:42:51.662 [Diagnostic] NB 51216 nbpem 116 PID:48601 TID:140069293737728 File ID:116 [jobid=160 job_group_id=160 client=T_RHEL6.7_nbutest2_10.15.8.112 type=4 server= task=ID:0x7f643c005408 CTX:0x7f645c008b30 policy=policy_test] 1 V-116-215 [BaseJob::run] jobid=160 submitted to nbjm for processing
11/05/2015 13:42:51.797 [Debug] NB 51216 nbjm 117 PID:48570 TID:139882151728896 File ID:117 [jobid=160 parentid=160] 1 [JobInstance::state] (0x7f38c400dab0) state=0(JobInstance.cpp:346)
11/05/2015 13:42:51.801 [Diagnostic] NB 51216 nbjm 117 PID:48570 TID:139882151728896 File ID:117 [jobid=160 parentid=160] 4 V-117-56 [BackupJob::sendRequestToRB] requesting resources from RB for backup job (jobid=160)
11/05/2015 13:42:51.819 [Debug] NB 51216 nbpem 116 PID:48601 TID:140069300041472 File ID:116 [jobid=160 job_group_id=160 client=T_RHEL6.7_nbutest2_10.15.8.112 type=4 server= task=ID:0x7f643c005408 CTX:0x7f645c008b30 policy=policy_test] 1 [RecoverableJob::setPemJobState] (ID:0x7f643c005408 CTX:0x7f645c008b30) NOT changing job state from PJS_SUBMITTING (1) to PJS_SUBMITTED (3)(RecoverableJob.cpp:1497)
11/05/2015 13:42:51.830 [Diagnostic] NB 51216 nbrb 118 PID:48496 TID:140084796950272 File ID:118 [jobid=160] 4 V-118-227 [ResBroker_i::requestResources] received resource request ID {0DF6FE08-8380-11E5-869A-E7677C11C3E9}, priority 0, secondary priority 26,400, description THE_BACKUP_JOB-160-{0DF6FE08-8380-11E5-869A-E7677C11C3E9}
11/05/2015 13:42:51.843 [Debug] NB 51216 nbrb 118 PID:48496 TID:140084796950272 File ID:118 [jobid=160] 1 [ResBroker_i::requestResources] RequestSeq:
Request=0 provider=MPXProvider resourcename=MpxRequest-160 MPXGroupRequest maxmpx=1
    SubRequest=0 provider=DriveOperationProvider resourcename=storageunit_01 userSequence=0 RB::StorageUnitRequest { StorageUnitRequest { storageUnit=storageunit_01 mediaPool=NetBackup retentionLevel=1 mustUseLocalMediaServer=no failOnError=no mpxRequired=no mustBeNdmp=no getMaxFreeSpace=no minFreeSpaceKBytes=0 usageType=1 client=MEDIA_SERVER shareGroup=*ANY* isVMWare=true NDMPHostName= REQ_IS_VM_POLICY=true REQ_IS_FAST_BACKUP=true REQ_IS_ACCELERATOR_VMWARE=true } }
Request=1 provider=NamedResourceProvider resourcename=R730-3.nbbyd.com.NBU_CLIENT.MAXJOBS.T_RHEL6.7_nbutest2_10.15.8.112 CountedResourceRequest { max=1 }
Request=2 provider=NamedResourceProvider resourcename=R730-3.nbbyd.com.NBU_POLICY.MAXJOBS.policy_test CountedResourceRequest { max=2147483647 }
11/05/2015 13:42:51.860 [Diagnostic] NB 51216 nbrb 118 PID:48496 TID:140084610574080 File ID:118 [jobid=160] 4 V-118-226 [ResBroker_i::evaluateOne] Evaluating request ID {0DF6FE08-8380-11E5-869A-E7677C11C3E9}
11/05/2015 13:42:51.868 [Debug] NB 51216 nbrb 118 PID:48496 TID:140084610574080 File ID:118 [jobid=160] 1 [FSMAccess::setFSM] using FSM Server R730-3.nbbyd.com
11/05/2015 13:42:51.891 [Diagnostic] NB 51216 nbrb 118 PID:48496 TID:140084610574080 File ID:118 [jobid=160] 2 V-118-146 [ProviderManager::allocate] NamedResourceProvider returned Allocation Granted for request ID {0DF6FE08-8380-11E5-869A-E7677C11C3E9}
11/05/2015 13:42:51.940 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 1 [allocateTwin] INITIATING:
11/05/2015 13:42:51.943 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [MdsGlobalCache::update_stale] clearing stale_host_config_key_map
11/05/2015 13:42:51.943 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [MdsGlobalCache::update_stale] clearing stale density_type_map
11/05/2015 13:42:51.943 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [MdsGlobalCache::update_stale] clearing stale dg_capacity_stat_map
11/05/2015 13:42:51.943 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [MdsGlobalCache::update_stale] clearing stale dg_dvlist_map
11/05/2015 13:42:51.943 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 1 [allocateTwin] masterServer = R730-3.nbbyd.com, client = MEDIA_SERVER, jobType = 1, capabilityFlags = 137363584, fatPipePreference = 0, statusOnly = 0, numberOfCopies = 1, kbytesNeeded = 0
11/05/2015 13:42:51.946 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 1 [allocateTwin] Twin_Record: STUIdentifier = storageunit_01, STUIdentifierType = 1, PoolName = NetBackup, MediaSharingGroup = *ANY*, RetentionLevel = 1, RequiredMediaServer = , PreferredMediaServer = , PreferredFilerForNDMPSnapDupe = , RequiredDiskVolumeMediaId = , RequiredStorageUnitName = , GetMaxFreeSpaceSTU = 0, CkptRestart = 0, CkptRestartSTUType = 0, CkptRestartSTUSubType = -1, CkptRestartSTUName = , CkptRestartMediaServer = , CkptRestartDiskGroupName = , CkptRestartDiskGroupServerType = , MpxEnabled = 0, MustUseLocalMediaServer = 0
11/05/2015 13:42:51.946 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] skip_stu_list is empty
11/05/2015 13:42:51.946 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] skip_med_list is empty
11/05/2015 13:42:51.946 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] skip_drv_list is empty
11/05/2015 13:42:51.946 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] skip_disk_volume_list is empty
11/05/2015 13:42:51.946 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] alloc_med_list is empty
11/05/2015 13:42:51.946 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] alloc_drv_list is empty
11/05/2015 13:42:51.946 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] reserved_med_list is empty
11/05/2015 13:42:51.946 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] umt_med_list is empty
11/05/2015 13:42:51.946 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] reserved_dv_list is empty
11/05/2015 13:42:51.946 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] disk_alloc_key_list is empty
11/05/2015 13:42:51.946 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] unload_requested_drive_cache is empty
11/05/2015 13:42:51.946 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [BEGIN_MDS_DB_TRANSACTION] attempting to get database connection
11/05/2015 13:42:51.946 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [BEGIN_MDS_DB_TRANSACTION] got database connection
11/05/2015 13:42:51.946 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [BEGIN_MDS_DB_TRANSACTION] attempting to start database transaction
11/05/2015 13:42:51.946 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [BEGIN_MDS_DB_TRANSACTION] started database transaction
11/05/2015 13:42:51.946 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocate_by_stu] master_server_name = R730-3.nbbyd.com, client_name = MEDIA_SERVER, job_type = 1, capability_flags = 137363584, num_copies = 1, kbytesNeeded = 0, fat_required = 0
11/05/2015 13:42:51.946 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocate_by_stu] twin_rec_env_t: stuid = storageunit_01, stuid_type = 1, orig_stuid = storageunit_01, orig_stuid_type = 1, pool_name = NetBackup, media_sharing_group = *ANY*, retlevel = 1, required_media_server = , preferred_media_server = , required_disk_volume_media_id = , max_free_space = 0, ckpt_restart = 0, ckpt_restart_env.stu_type = 0, ckpt_restart_env.stu_subtype = -1, ckpt_restart_env.stu_name = , ckpt_restart_env.media_server = , ckpt_restart_env.disk_group_name = , ckpt_restart_env.disk_group_server_type = , mpx_enabled = 0, must_use_local_for_this_job = 0, disk_spanning = 0
11/05/2015 13:42:51.955 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_host_info_by_name] host_name = R730-3.nbbyd.com, hc = 0
11/05/2015 13:42:51.956 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_host_info_by_name] raw_host_info - raw_host_info_t: key = 1000002, parent_key = 1000002, fqname = R730-3.nbbyd.com, state = 12, nbversion = 760400, nbtype = 3, cluster_key = 0, active_node_key = 0, flags = 119, rank = 3
11/05/2015 13:42:51.956 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_host_info_by_name] out - host_info_t: key = 1000002, parent_key = 1000002, fqname = R730-3.nbbyd.com, state = 12, nbversion = 760400, nbtype = 3, cluster_key = 0, cluster_fqname = , active_node_key = 0, flags = 119, raw_host_key = 1000002, raw_host_name = R730-3.nbbyd.com, rank = 3
11/05/2015 13:42:51.956 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_pool_info] pool_name = NetBackup
11/05/2015 13:42:51.958 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_pool_info] pool_num = 1, max_partially_full_media = 0, pool_name = NetBackup
11/05/2015 13:42:51.958 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_scratch_pool] scratch pool name = , scratch pool num = 0
11/05/2015 13:42:51.958 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_stu_props] stu_name = storageunit_01
11/05/2015 13:42:51.958 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_stu_props] master_serv - host_info_t: key = 1000002, parent_key = 1000002, fqname = R730-3.nbbyd.com, state = 12, nbversion = 760400, nbtype = 3, cluster_key = 0, cluster_fqname = , active_node_key = 0, flags = 119, raw_host_key = 1000002, raw_host_name = R730-3.nbbyd.com, rank = 3
11/05/2015 13:42:51.959 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_stu_props] out - stu_t: name = storageunit_01, media_server_key = 0, type = 0, density = 0, robot_num = -1, robot_type = 0, aj = 0, cj = 50, odo = 1, ndmp_host_key = 0, flags = 2, subtype = 6, key = 1, disk_flags = 1, media_server_name =
11/05/2015 13:42:51.959 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_host_info_by_name] host_name = MEDIA_SERVER, hc = 0
11/05/2015 13:42:51.960 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_is_client_media_server] host_name = MEDIA_SERVER
11/05/2015 13:42:51.962 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_host_config] host_info - host_info_t: key = 1000002, parent_key = 1000002, fqname = R730-3.nbbyd.com, state = 12, nbversion = 760400, nbtype = 3, cluster_key = 0, cluster_fqname = , active_node_key = 0, flags = 119, raw_host_key = 1000002, raw_host_name = R730-3.nbbyd.com, rank = 3
.......
11/05/2015 13:42:51.974 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [select_for_bkup] server_group - media_sharing_group_t: key = 0, state = 0, type = 0
11/05/2015 13:42:51.974 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [select_for_bkup] sgrp_whost_list is empty
11/05/2015 13:42:51.974 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [select_for_bkup] reserved_dv_list is empty
11/05/2015 13:42:51.974 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [select_for_bkup] disk_alloc_key_list is empty
11/05/2015 13:42:51.977 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [get_stu_list] stu_filter_type = STU_FILTER_BKUP_OPTIMAL, exclude_stu_type_mask = 0,mode = CONSIDER_DRIVE_MEDIA_AVAILABILITY
11/05/2015 13:42:51.977 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [get_stu_list] stu_type_mask = 5, match_host_name = MEDIA_SERVER, match_host_key = 0
11/05/2015 13:42:51.977 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [get_stu_list] client is not a media server, hence no local host to select
11/05/2015 13:42:51.977 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [select_from_stu_list] space_found = 0, local_drives = 1, cur_err = 2002011, can_retry = 0, best_fit = 1
11/05/2015 13:42:51.981 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [select_from_stu_list] Returning error = 2002011
11/05/2015 13:42:51.985 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [get_stu_list] stu_filter_type = STU_FILTER_BKUP_NON_OPTIMAL, exclude_stu_type_mask = 0,mode = CONSIDER_DRIVE_MEDIA_AVAILABILITY
11/05/2015 13:42:51.985 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [get_stu_list] stu_type_mask = 5, match_host_name = MEDIA_SERVER, match_host_key = 0
11/05/2015 13:42:51.985 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [set_allocation_info_in_stu_list] mode = CONSIDER_DRIVE_MEDIA_AVAILABILITY
11/05/2015 13:42:51.985 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [set_host_and_dg_info_in_stu_list] mode = CONSIDER_DRIVE_MEDIA_AVAILABILITY
11/05/2015 13:42:51.985 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [set_host_and_dg_info_in_stu_list] getting host info for storage unit, name = storageunit_01, media_server_key = 0
11/05/2015 13:42:51.985 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_disk_group_info_by_stu_key] stu_key = 1
11/05/2015 13:42:51.987 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_disk_group_info_by_stu_key] out - disk_group_t: key = 1, name = diskpool_01, id = diskpool_01, server_type = PureDisk, sts_state = 0, state = 2, type = 9, flags = 1137911, total_capacity = 1979453992960, used_space = 0, high_water_mark = 98, low_water_mark = 80, max_io_streams = -1
11/05/2015 13:42:51.987 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_disk_group_storage_servers] dg_key = 1
11/05/2015 13:42:51.987 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_disk_group_storage_servers] storage_server_list has 1 storage servers
11/05/2015 13:42:51.987 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [get_hostkey2info] key = 1000004
11/05/2015 13:42:51.987 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_hostkey2info] host_key = 1000004
11/05/2015 13:42:51.987 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_raw_host_info] host_key = 1000004
11/05/2015 13:42:51.988 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_raw_host_info] out - raw_host_info_t: key = 1000004, parent_key = 0, fqname = R730-3.nbbyd.com, state = 0, nbversion = 0, nbtype = 2, cluster_key = 0, active_node_key = 0, flags = 2, rank = 0
11/05/2015 13:42:51.988 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_hostkey2info] out - host_info_t: key = 1000004, parent_key = 0, fqname = R730-3.nbbyd.com, state = 0, nbversion = 0, nbtype = 2, cluster_key = 0, cluster_fqname = , active_node_key = 0, flags = 2, raw_host_key = 1000004, raw_host_name = R730-3.nbbyd.com, rank = 0
11/05/2015 13:42:51.988 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_ndmp_storage_server_media_servers] ss_key = 1000004
11/05/2015 13:42:51.989 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_ndmp_storage_server_media_servers] server_list has 1 servers
11/05/2015 13:42:51.989 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [get_hostkey2info] key = 1000002
11/05/2015 13:42:51.989 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_hostkey2info] host_key = 1000002
11/05/2015 13:42:51.989 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_raw_host_info] host_key = 1000002
11/05/2015 13:42:51.989 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_raw_host_info] out - raw_host_info_t: key = 1000002, parent_key = 1000002, fqname = R730-3.nbbyd.com, state = 12, nbversion = 760400, nbtype = 3, cluster_key = 0, active_node_key = 0, flags = 119, rank = 3
11/05/2015 13:42:51.989 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_hostkey2info] out - host_info_t: key = 1000002, parent_key = 1000002, fqname = R730-3.nbbyd.com, state = 12, nbversion = 760400, nbtype = 3, cluster_key = 0, cluster_fqname = , active_node_key = 0, flags = 119, raw_host_key = 1000002, raw_host_name = R730-3.nbbyd.com, rank = 3
11/05/2015 13:42:51.989 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_alloc_list_for_media_server] server_key = 1000002
11/05/2015 13:42:51.990 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_alloc_list_for_media_server] alloc_list has 0 allocations
11/05/2015 13:42:51.990 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [init_host_stats] host_stats_t: host_key = 1000002, nbversion = 760400, rank = 3, committed_space = 0, allocs = 0, disk_allocs = 0
11/05/2015 13:42:51.990 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [init_host_stats] fat_stats - fat_host_stats_t: pipe_allocs = 0, client_allocs = 0, client_pipes_available_cnt = 0, other_clients_cnt = 0, client_private_pipe_found = 0, client_below_optimal = 0
11/05/2015 13:42:51.990 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_disk_stats_by_dg_key] disk_group_key = 1
11/05/2015 13:42:51.990 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_disk_stats_by_dg_key] disk pool has 1 volumes
11/05/2015 13:42:51.990 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [set_host_stats_in_stu_list] Done with host stats computation
11/05/2015 13:42:51.991 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_disk_vol_list_for_dg_key_list] will add dg to vol_list cache, dg = 1
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_disk_vol_list_for_dg_key_list] adding vol key = 1 to vol cache
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_disk_vol_list_for_dg_key_list] disk_volume_list has 1 volumes
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [StuTraverser::display_traverser] disk_volume_t: key = 1, disk_group_key = 1, name = PureDiskVolume, id = PureDiskVolume, media_id = @aaaab, sts_state = 0, state = 2, flags = 6, fs_type = 0, curr_writers = 1, total_capacity = 1979453992960, free_space = 1137126473728, pot_free_space = 0, committed_space = 0, pre_committed_space = 0, num_active_read_streams = 0, num_active_write_streams = 0, rank = 1
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [StuTraverser::display_traverser] stu_t: name = storageunit_01, media_server_key = 0, type = 0, density = 0, robot_num = -1, robot_type = 0, aj = 0, cj = 50, odo = 1, ndmp_host_key = 0, flags = 2, subtype = 6, key = 1, disk_flags = 1, media_server_name =
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [StuTraverser::display_traverser]  host_key = 1000002, rank = 1
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [select_from_stu_list] space_found = 0, local_drives = 0, cur_err = 2002011, can_retry = 0, best_fit = 1
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [StuTraverser::next] Returning success stu_key = 1
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [StuTraverser::next] Returning success dv key = 1
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_host_config] host_info - host_info_t: key = 1000002, parent_key = 1000002, fqname = R730-3.nbbyd.com, state = 12, nbversion = 760400, nbtype = 3, cluster_key = 0, cluster_fqname = , active_node_key = 0, flags = 119, raw_host_key = 1000002, raw_host_name = R730-3.nbbyd.com, rank = 3
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [sql_get_host_config] out [cache] - host_config_t: allow_mul_retlevel = 0, disable_standalone_ext = 0, dont_eject_standalone = 0, dont_use_ndmp_for_non_ndmp_operation = 0, q_loc_drv_busy = 0, q_loc_drv_dn = 0, no_disk_stu_throttle = 0, media_request_delay = 0, err_hist_window = 12, media_err_threshold = 2, drive_err_threshold = 2, media_id_prefix = A, max_realloc_tries = 1000, scsi_protection = 1, sso_default_mount_point = /nbushareddisk, is_system_wide_sharing = 0, prefer_ndmp_for_restore = 1, max_initiator_ports = 2, max_clients_per_target_port = 2, wait_for_vtl_direct_path = 0, user_job_kbytes_estimate = 0, use_potential_freespace_for_allocation = 0
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [select_from_stu_list] ATTEMPTING TO ALLOCATE FROM STORAGE UNIT - stu_t: name = storageunit_01, media_server_key = 0, type = 0, density = 0, robot_num = -1, robot_type = 0, aj = 0, cj = 50, odo = 1, ndmp_host_key = 0, flags = 2, subtype = 6, key = 1, disk_flags = 1, media_server_name =
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [validate_stu] list_mode = CONSIDER_DRIVE_MEDIA_AVAILABILITY
11/05/2015 13:42:51.992 [Diagnostic] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 1 V-143-1545 [validate_disk_stu] Disk volume @aaaab is down or in unknown state
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 1 [validate_disk_stu] disk storage unit disk volumeis down, stu_name = storageunit_01, name = PureDiskVolume, state = 2
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [select_from_stu_list] allcation failed 0 0
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [StuTraverser::next] No stu/dv found
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [select_from_stu_list] Returning error = 2005074
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [END_MDS_DB_TRANSACTION] cur_err = 2005074, m_dbconn_stat = 0, m_dberr_stat = 0, m_closed_db_trx = 0
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [END_MDS_DB_TRANSACTION] rolled back database transaction
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 1 [allocateTwin] EXIT INFO:
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] skip_stu_list is empty
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] skip_med_list is empty
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] skip_drv_list is empty
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] skip_disk_volume_list is empty
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] alloc_med_list is empty
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] alloc_drv_list is empty
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] reserved_med_list is empty
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] umt_med_list is empty
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] reserved_dv_list is empty
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] disk_alloc_key_list is empty
11/05/2015 13:42:51.992 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 2 [allocateTwin] unload_requested_drive_cache is empty
11/05/2015 13:42:51.998 [Debug] NB 51216 mds 143 PID:48492 TID:140605719590656 File ID:111 [jobid=160] 1 [allocateTwin] EXIT STATUS = 2005074 (EMM_ERROR_MDS_DiskVolumeDown, Disk volume is down)

11/05/2015 13:42:51.999 [Diagnostic] NB 51216 nbrb 118 PID:48496 TID:140084610574080 File ID:118 [jobid=160] 4 V-118-201 [EMMAccess::allocateTwin] request to allocate STU (Master Server R730-3.nbbyd.com, Client MEDIA_SERVER, Job Type 1, STU storageunit_01, STU Type 1, Media Pool NetBackup, Retention Level 1, Capabilities 137,363,584, Fibre Transport Preference 0) returned 2005074
11/05/2015 13:42:52.006 [Diagnostic] NB 51216 nbrb 118 PID:48496 TID:140084610574080 File ID:118 [jobid=160] 2 V-118-146 [ProviderManager::allocate] MPXProvider returned Not Enough Valid Resources for request ID {0DF6FE08-8380-11E5-869A-E7677C11C3E9}
11/05/2015 13:42:52.006 [Application] NB 51216 nbrb 118 PID:48496 TID:140084610574080 File ID:118 [jobid=160] [Error] V-118-171 request ID {0DF6FE08-8380-11E5-869A-E7677C11C3E9} failed with status 0 (Not Enough Valid Resources); releasing 2 allocated resources
11/05/2015 13:42:52.006 [Debug] NB 51216 nbrb 118 PID:48496 TID:140084610574080 File ID:118 [jobid=160] 1 [ResBroker_i::evaluateOne] resource request fails, requestId={0DF6FE08-8380-11E5-869A-E7677C11C3E9}, userId=jobid=160, status=2005074, birthTime=1446702171, timeToFirstEval=0 sec, timeToSuccessOrFailure=1 sec, numberOfTimesEvaluated=1
11/05/2015 13:42:52.006 [Diagnostic] NB 51216 nbrb 118 PID:48496 TID:140084610574080 File ID:118 [jobid=160] 1 V-118-108 [ResBroker_i::failOne] failing resource request ID {0DF6FE08-8380-11E5-869A-E7677C11C3E9}, status 2005074
11/05/2015 13:42:52.006 [Diagnostic] NB 51216 nbrb 118 PID:48496 TID:140084610574080 File ID:118 [jobid=160] 2 V-118-137 [EMMProvider::getDriveForWaitingRequest] allocation information for request ID {0DF6FE08-8380-11E5-869A-E7677C11C3E9} is not found
11/05/2015 13:42:52.007 [Diagnostic] NB 51216 nbrb 118 PID:48496 TID:140084608472832 File ID:118 [jobid=160] 1 V-118-255 [CorbaCall_requestFailed::execute] sending failure of request to nbjm for request ID {0DF6FE08-8380-11E5-869A-E7677C11C3E9}, error code 2,005,074, reason not enough valid resources
11/05/2015 13:42:52.018 [Debug] NB 51216 nbjm 117 PID:48570 TID:139882346039072 File ID:117 [jobid=160 parentid=160] 1 [BackupJob::ERMEvent] (0x7f38c400dab0) initial resource request failed, copy#=-1, EMM status=Disk volume is down, NBU status=2074(BackupJob.cpp:426)
11/05/2015 13:42:52.018 [Application] NB 51216 nbjm 117 PID:48570 TID:139882346039072 File ID:117 [jobid=160 parentid=160] [Error] V-117-131  NBU status: 2074, EMM status: Disk volume is down

11/05/2015 13:42:52.018 [Debug] NB 51216 nbjm 117 PID:48570 TID:139882151728896 File ID:117 [jobid=160 parentid=160] 1 [JobInstance::state] (0x7f38c400dab0) state=1(JobInstance.cpp:346)
11/05/2015 13:42:52.018 [Debug] NB 51216 nbjm 117 PID:48570 TID:139882151728896 File ID:117 [jobid=160 parentid=160] 1 [JobInstance::state] (0x7f38c400dab0) state=1(JobInstance.cpp:346)
11/05/2015 13:42:52.018 [Debug] NB 51216 nbjm 117 PID:48570 TID:139882151728896 File ID:117 [jobid=160 parentid=160] 1 [BackupJob::sendNotifications] (0x7f38c400dab0) disable resume=false, brm started=false(BackupJob.cpp:2415)
11/05/2015 13:42:52.018 [Diagnostic] NB 51216 nbjm 117 PID:48570 TID:139882151728896 File ID:117 [jobid=160 parentid=160] 1 V-117-239 [BackupJob::terminateThisJob] terminated job, jobid=160, status=2,074
11/05/2015 13:42:52.018 [Debug] NB 51216 nbjm 117 PID:48570 TID:139882151728896 File ID:117 [jobid=160 parentid=160] 1 [BackupJob::~BackupJob] (dump Backup Job):
**************************
*BackupJob               *
(jobid=160 jobtype=0)
**************************
isStdBackup       = false
backupType        = 0
subtype           = 40
mpxid             = {00000000-0000-0000-0000-000000000000}
maxmpx            = 1
Birthtime         = 0
backupid          =
Active pid        = 0
Job Count         = 1
IPaddr            =
currentThrottle   = -1
estimatedSize     = 0
estimatedFileCount= 80200
suspendable       = 0
progressLogTimerID= -1
localBackup       = 0
policy            = policy_test
Num copies        = 1
Include_file#     = 2
resourceCount     = 1
Stu               = storageunit_01
Pool              = NetBackup
Retention         = 1
UseLocal          = false
(BackupJob.cpp:379)
11/05/2015 13:42:52.019 [Diagnostic] NB 51216 nbpem 116 PID:48601 TID:140069300041472 File ID:116 [jobid=160 job_group_id=160 client=T_RHEL6.7_nbutest2_10.15.8.112 type=4 server= task=ID:0x7f643c005408 CTX:0x7f645c008b30 policy=policy_test] 1 V-116-216 [RecoverableJob::doJobCompletion] jobid=160 completed with status 2,074
11/05/2015 13:42:52.031 [Diagnostic] NB 51216 nbpem 116 PID:48601 TID:140068939343616 File ID:116 [jobid=160 job_group_id=160 client=T_RHEL6.7_nbutest2_10.15.8.112 type=4 server= task=ID:0x7f643c005408 CTX:0x7f645c008b30 policy=policy_test] 1 V-116-222 [RecoverableJob::registerForRetryTime] retry of jobid=160 schedule for 2015-11-05 13:52
11/05/2015 13:42:52.038 [Application] NB 51216 nbpem 116 PID:48601 TID:140068939343616 File ID:116 [jobid=160 job_group_id=160 client=T_RHEL6.7_nbutest2_10.15.8.112 type=4 server= task=ID:0x7f643c005408 CTX:0x7f645c008b30 policy=policy_test] [Info] V-116-14 CLIENT T_RHEL6.7_nbutest2_10.15.8.112  POLICY policy_test  SCHED VMs_Backup  EXIT STATUS 2074 (Disk volume is down)
11/05/2015 13:42:52.038 [Application] NB 51216 nbpem 116 PID:48601 TID:140068939343616 File ID:116 [jobid=160 job_group_id=160 client=T_RHEL6.7_nbutest2_10.15.8.112 type=4 server= task=ID:0x7f643c005408 CTX:0x7f645c008b30 policy=policy_test] [Error] V-116-85 backup of client T_RHEL6.7_nbutest2_10.15.8.112 exited with status 2074 (Disk volume is down)

vinciho

以上是出2074错误的job 160的详细日志输出，因为太长，中间截掉了一小部分，重点出错在后面，请大侠帮忙分析分析。

xuman6601651

你把NBU服务全部重启下

vinciho

重启无数次了，包括OS。

hank1980

这个问题我前段时间也遇到了，也不知道怎么解决，后来干脆恢复了系统到出厂状态（原本也没备份什么数据），现在正常。我的是NB5230，出问题前记得是手动启用了机子自带的策略“SYMC_NBA_Dedupe_Catalog_nbu”，不知道是不是跟这个有关。