db_FLISTsend failed: invalid command usage (144)

[AdN]

Just upgraded to 6.0 MP7 on a Solaris 10 host and installed these packages according to the instruction in the release notes:

NB_60_7_M.solaris_308508.tar
NB_CLT_60_7_M_308528.tar
NB_DMP_60_7_M.solaris_308543.tar
NB_JAV_60_7_M_308546.tar

An NDMP backup of a small volume on our NetApp FAS 3020 filer succeeded. ONTAP release is 7.0.5P7. But when trying to back up another volume, then I get this error message in the log:

12/17/2008 11:15:42 - requesting resource adnnfs03-ndmp

12/17/2008 11:15:42 - requesting resource adnbackup.NBU_CLIENT.MAXJOBS.adnnfs03
12/17/2008 11:15:42 - requesting resource adnbackup.NBU_POLICY.MAXJOBS.Month-Netapp2
12/17/2008 11:15:43 - granted resource adnbackup.NBU_CLIENT.MAXJOBS.adnnfs03
12/17/2008 11:15:43 - granted resource adnbackup.NBU_POLICY.MAXJOBS.Month-Netapp2
12/17/2008 11:15:43 - granted resource LM2473
12/17/2008 11:15:43 - granted resource adnnfs03-LTO3-4
12/17/2008 11:15:43 - granted resource adnnfs03-ndmp
12/17/2008 11:15:44 - started process bpbrm (pid=5174)
12/17/2008 11:15:44 - connecting
12/17/2008 11:15:44 - connected; connect time: 0:00:00
12/17/2008 11:15:47 - mounting LM2473
12/17/2008 11:17:06 - mounted LM2473; mount time: 0:01:19
12/17/2008 11:17:12 - positioning LM2473 to file 1
12/17/2008 11:17:15 - positioned LM2473; position time: 0:00:03
12/17/2008 11:17:15 - begin writing
12/17/2008 11:41:27 - Error bpbrm (pid=5174) db_FLISTsend failed: invalid command usage (144)
12/17/2008 11:41:28 - Error ndmpagent (pid=5180) terminated by parent process
12/17/2008 11:41:28 - Error bptm (pid=5181) media manager terminated by parent process
12/17/2008 11:41:28 - Error ndmpagent (pid=5180) NDMP backup failed, path = /vol/home
12/17/2008 11:42:01 - end writing; write time: 0:24:46
invalid command usage (144)

The help at http://seer.entsupport.symantec.com/docs/301418.htm says, that one should make sure that all binaries have the same version. Command args are unfortunately limited to 80 characters:

 bpbrm -backup -S adnbackup -c adnnfs03 -ct 19 -ru root -cl Month-Netapp2 -sched

However, another volume in the same policy does backup fine.

[root@adnbackup /var/tmp]$ pkginfo |grep -i verit

application VRTSicsco                        VERITAS Infrastructure Core Services Common
application VRTSnbdmp                        VERITAS NetBackup for NDMP
application VRTSnetbp                        VERITAS NetBackup and Media Manager
system      VRTSpbx                          VERITAS Private Branch Exchange

As far as I know NDMP does not require to install a client on the NetApp.  NetApp backup log says:

dmp Wed Dec 17 11:50:47 CET /vol/home/(1) Phase_change (II)
dmp Wed Dec 17 11:51:08 CET /vol/home/(1) Phase_change (III)
dmp Wed Dec 17 11:59:31 CET /vol/home/(1) Tape_close (ndmp)
dmp Wed Dec 17 11:59:31 CET /vol/home/(1) Abort (200 MB)
dmp Wed Dec 17 12:00:27 CET /vol/home/(1) Start (Level 0, NDMP)
dmp Wed Dec 17 12:00:27 CET /vol/home/(1) Options (b=63, u)
dmp Wed Dec 17 12:00:27 CET /vol/home/(1) Snapshot (snapshot_for_backup.28795, Wed Dec 17 12:00:25 CET)
dmp Wed Dec 17 12:01:01 CET /vol/home/(1) Tape_open (ndmp)
dmp Wed Dec 17 12:01:01 CET /vol/home/(1) Phase_change (I)
dmp Wed Dec 17 12:18:14 CET /vol/home/(1) Phase_change (II)
dmp Wed Dec 17 12:18:36 CET /vol/home/(1) Phase_change (III)
dmp Wed Dec 17 12:28:08 CET /vol/home/(1) Tape_close (ndmp)
dmp Wed Dec 17 12:28:08 CET /vol/home/(1) Abort (200 MB)
dmp Wed Dec 17 12:28:58 CET /vol/home/(1) Start (Level 0, NDMP)
dmp Wed Dec 17 12:28:58 CET /vol/home/(1) Options (b=63, u)
dmp Wed Dec 17 12:28:58 CET /vol/home/(1) Snapshot (snapshot_for_backup.28798, Wed Dec 17 12:28:56 CET)
dmp Wed Dec 17 12:29:33 CET /vol/home/(1) Tape_open (ndmp)
dmp Wed Dec 17 12:29:33 CET /vol/home/(1) Phase_change (I)

Hm, what am I missing?

Thanks in advance,

Bernd

[AdN]

Forgot to mention: We upgraded from 6.0 to 6.0 MP7. Found the startup command of bpbrm in the /opt/openv/logs:

The backup of this NetApp volume succeeded:

bpbrm -backup -S adnbackup -c adnnfs03 -ct 19 -ru root -cl Month-Netapp2 -sched Full -bt 1229508943 -dt 0 -st 0 -b adnnfs03_1229508943 -mediasvr adnbackup -jobid 156466 -jobgrpid 156465 -masterversion 600000 -maxfrag 1048576 -reqid -1229506279 -mt 3 -to 0 -stunit adnnfs03-ndmp -cj 2 -rl 24 -rp 2147483647 -D 20 -rt 8 -rn 0 -pool Monatsbaender -use_ofb -use_otm -jm -secure 1 -kl 25 -rg root -fso -stream_count 2 -stream_number 1 -dmplevel 0

The NDMP backup of this NetApp volume failed w/opt/openv/netbackup/bin/ndmpagentith "Error bpbrm (pid=5174) db_FLISTsend failed: invalid command usage (144)".

bpbrm -backup -S adnbackup -c adnnfs03 -ct 19 -ru root -cl Month-Netapp2 -sched Full -bt 1229514311 -dt 0 -st 0 -b adnnfs03_1229514311 -mediasvr adnbackup -jobid 156472 -jobgrpid 156465 -masterversion 600000 -maxfrag 1048576 -reqid -1229506295 -mt 3 -to 0 -stunit adnnfs03-ndmp -cj 2 -rl 24 -rp 2147483647 -D 20 -rt 8 -rn 0 -pool Monatsbaender -use_ofb -use_otm -jm -secure 1 -kl 25 -rg root -fso -stream_count 2 -stream_number 2 -dmplevel 0

I don't see a difference in the command syntax. The binaries of bpbrm and ndmpagent have changed since the update. So it's unlikely that there is a version mismatch due to a forgotten package update.

cksum /opt/openv/netbackup/bin/bpbrm /net/adnnfs02/Volumes/Vol2/backup/hosts/adnbackup/opt/openv/netbackup/bin/bpbrm /opt/openv/netbackup/bin/ndmpagent /net/adnnfs02/Volumes/Vol2/backup/hosts/adnbackup/opt/openv/netbackup/bin/ndmpagent

894515789       530544  /opt/openv/netbackup/bin/bpbrm
104159472       507960  /net/adnnfs02/Volumes/Vol2/backup/hosts/adnbackup/opt/openv/netbackup/bin/bpbrm
1304096235      1564412 /opt/openv/netbackup/bin/ndmpagent
3097725886      1895788 /net/adnnfs02/Volumes/Vol2/backup/hosts/adnbackup/opt/openv/netbackup/bin/ndmpagent

[Andy_Welburn]

---

@AdN wrote:

However, another volume in the same policy does backup fine.

---

Have you tried creating another policy for this one volume just to see if there's some corruption in the original policy?

[AdN]

It's in progress ... takes some hours because it's over 1 TB data. The weird is: It could already save some data: 152271 kB and 344000 files. Job terminated after 20 minutes. So it's unlikely a bad command syntax.

[AdN]

NDMP backup of the same volume using another policy results in the same error:

12/17/2008 14:11:42 - started process bpbrm (pid=17739)
12/17/2008 14:11:42 - connecting
12/17/2008 14:11:42 - connected; connect time: 0:00:00
12/17/2008 14:11:45 - mounting LM2728
12/17/2008 14:12:33 - mounted LM2728; mount time: 0:00:48
12/17/2008 14:12:38 - positioning LM2728 to file 103
12/17/2008 14:13:15 - positioned LM2728; position time: 0:00:37
12/17/2008 14:13:15 - begin writing
12/17/2008 16:38:01 - Error bpbrm (pid=17739) db_FLISTsend failed: invalid command usage (144)
12/17/2008 16:38:01 - Error ndmpagent (pid=17744) terminated by parent process
12/17/2008 16:38:01 - Error bptm (pid=17745) media manager terminated by parent process
12/17/2008 16:38:01 - Error ndmpagent (pid=17744) NDMP backup failed, path = /vol/home
12/17/2008 16:38:44 - end writing; write time: 2:25:29
invalid command usage (144)

[Omar_Villa]

try checking the logs with

vxlogview -p 51216 -o 134 -L -E -t 12:00:00

or

vxlogview -p 51216 -X "jobid=<jobid>"

will take a little while but you'll probably get more details about it.

regards

[Omar_Villa]

also for ndmp log

vxlogview -p 51216 -o 151 -L -E -t 12:00:00

[AdN]

Hi,

Here is some logging information. Could it be that there is a limitation of volume size? Are there known issues?

We recently increased the volume to 1.2 TB. Since then we have backup problems. With 6.0 the error message was "Cannot write TIR data to media, NDMP return code 20". Then I upgrade to 6.0 MP7 and now this. Backup server (master and media) runs on Solaris 10 3/05. NetApp filer is FAS 3020 7.0.5P7. Backup with NDMP to local attached Quantum PX506 LTO3 tape library. Before that the backup ran fine for years.

Sample job that produces errors:

Parent Job 156465

\_ Job 156466: /vol/pkg   (193 GB) -> State 0
\_ Job 156467: /vol/home (1017 GB) -> State 144
\_ Job 156472: /vol/home (1017 GB) -> State 144

 # vxlogview -p 51216 -o 151 -L -E -t 24:00:00
V-1-1-12 There are no records to be displayed.



# vxlogview -p 51216 -o 134 -L -E -t 24:00:00
12/17/08 11:41:28.136 [Error] V-134-273 terminated by parent process
12/17/08 11:41:28.480 [Error] V-134-32 NDMP backup failed, path = /vol/home
12/17/08 12:10:05.084 [Error] V-134-273 terminated by parent process
12/17/08 12:10:05.280 [Error] V-134-32 NDMP backup failed, path = /vol/home
12/17/08 12:29:31.276 [Error] V-134-9 no -backup, -restore, or -copy parameter
12/17/08 12:30:04.230 [Error] V-134-9 no -backup, -restore, or -copy parameter
12/17/08 12:30:07.016 [Error] V-134-9 no -backup, -restore, or -copy parameter
12/17/08 12:30:10.121 [Error] V-134-9 no -backup, -restore, or -copy parameter
12/17/08 12:30:12.368 [Error] V-134-9 no -backup, -restore, or -copy parameter
12/17/08 12:38:27.126 [Error] V-134-273 terminated by parent process
12/17/08 12:38:27.314 [Error] V-134-32 NDMP backup failed, path = /vol/home
12/17/08 13:05:09.828 [Error] V-134-273 terminated by parent process
12/17/08 13:05:10.120 [Error] V-134-32 NDMP backup failed, path = /vol/home
12/17/08 16:38:01.346 [Error] V-134-273 terminated by parent process
12/17/08 16:38:01.710 [Error] V-134-32 NDMP backup failed, path = /vol/home
12/17/08 19:37:54.374 [Error] V-134-273 terminated by parent process
12/17/08 19:37:54.620 [Error] V-134-32 NDMP backup failed, path = /vol/home
12/17/08 21:31:18.315 [Error] V-134-273 terminated by parent process
12/17/08 21:31:18.528 [Error] V-134-112 FH send to BRM failed - Ddi - 0 0 0 0 7071228 0 0 12 13211001 weblogic.xml
12/17/08 21:31:18.850 [Error] V-134-32 NDMP backup failed, path = /vol/home
12/17/08 22:33:29.383 [Error] V-134-273 terminated by parent process
12/17/08 22:33:29.499 [Error] V-134-112 FH send to BRM failed - Ddi - 0 0 0 0 622147 0 0 36 1420688 130@390f9f933d4ef764d5ae4e490d628bf7
12/17/08 22:33:29.750 [Error] V-134-32 NDMP backup failed, path = /vol/home_hu
12/17/08 23:00:26.319 [Error] V-134-273 terminated by parent process
12/17/08 23:00:26.422 [Error] V-134-112 FH send to BRM failed - Ddi - 0 0 0 0 6401594 0 0 42 1420688 50@411737775ad287928ccc4e63e41a5696@shadow
12/17/08 23:00:26.610 [Error] V-134-32 NDMP backup failed, path = /vol/home_hu
12/17/08 23:31:49.711 [Error] V-134-273 terminated by parent process
12/17/08 23:31:49.824 [Error] V-134-112 FH send to BRM failed - Ddi - 0 0 0 0 12582620 0 0 35 1420688 50@d69f1c6c4f30a783a1418c76fa99b602
12/17/08 23:31:50.130 [Error] V-134-32 NDMP backup failed, path = /vol/home_hu
12/18/08 06:08:03.382 [Error] V-134-273 terminated by parent process
12/18/08 06:08:03.526 [Error] V-134-112 FH send to BRM failed - Ddi - 0 0 0 0 13235235 0 0 9 13235230 text-base
12/18/08 06:08:03.820 [Error] V-134-32 NDMP backup failed, path = /vol/home

Log snipplet (I don't want to copy+paste the thousands lines here):

# vxlogview -p 51216 -X "jobid=156465"

[...]

12/17/08 12:45:21.162 [setAvailable] EXIT STATUS = 0 (EMM_ERROR_Success, Success)

12/17/08 12:45:21.228 [ResBroker_i::releaseOne] releasing allocation id={A8FCF388-1DD1-11B2-8C93-00E000C5640F}
12/17/08 12:45:21.329 [ResBroker_i::releaseOne] releasing allocation id={A8FCED0C-1DD1-11B2-B530-00E000C5640F}12/17/08 12:45:21.162 [setAvailable] EXIT STATUS = 0 (EMM_ERROR_Success, Success)

12/17/08 12:45:21.228 [ResBroker_i::releaseOne] releasing allocation id={A8FCF388-1DD1-11B2-8C93-00E000C5640F}
12/17/08 12:45:21.329 [ResBroker_i::releaseOne] releasing allocation id={A8FCED0C-1DD1-11B2-B530-00E000C5640F}
12/17/08 12:45:21.893 [BackupJob::stateTransition] old state = 4 new state = 10(BackupJob.cpp:2126)
12/17/08 12:45:21.893 [BackupJob::terminateThisJob] terminated job (jobid=156465), status=144(BackupJob.cpp:1148)
12/17/08 12:45:21.921 [Info] V-116-14 CLIENT adnnfs03  POLICY Month-Netapp2  SCHED Full  EXIT STATUS 144 (invalid command usage)
12/17/08 12:45:21.923 [Error] V-116-85 backup of client adnnfs03 exited with status 144 (invalid command usage)
12/17/08 12:45:21.964 [?]  << <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
12/17/08 12:45:21.964 [?]  << End JOBID jobid=156465  policy=Month-Netapp2  client=adnnfs03 schedule=Full bt=1229508942
12/17/08 12:45:21.964 [?]  << stream # = -1 runonce = 1 time = Wed Dec 17 12:45:21 2008
12/17/08 12:45:21.964 [?]  << status 144 (invalid command usage)
12/17/08 12:45:21.964 [?]  << <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
12/17/08 12:45:21.893 [BackupJob::stateTransition] old state = 4 new state = 10(BackupJob.cpp:2126)
12/17/08 12:45:21.893 [BackupJob::terminateThisJob] terminated job (jobid=156465), status=144(BackupJob.cpp:1148)
12/17/08 12:45:21.921 [Info] V-116-14 CLIENT adnnfs03  POLICY Month-Netapp2  SCHED Full  EXIT STATUS 144 (invalid command usage)
12/17/08 12:45:21.923 [Error] V-116-85 backup of client adnnfs03 exited with status 144 (invalid command usage)
12/17/08 12:45:21.964 [?]  << <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
12/17/08 12:45:21.964 [?]  << End JOBID jobid=156465  policy=Month-Netapp2  client=adnnfs03 schedule=Full bt=1229508942
12/17/08 12:45:21.964 [?]  << stream # = -1 runonce = 1 time = Wed Dec 17 12:45:21 2008
12/17/08 12:45:21.964 [?]  << status 144 (invalid command usage)
12/17/08 12:45:21.964 [?]  << <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<

# vxlogview -p 51216 -X "jobid=156467"

[...]

12/17/08 11:15:44.437 [Info] V-117-122 started backup job for client adnnfs03, policy Month-Netapp2, schedule Full on storage unit adnnfs03-ndmp
12/17/08 11:15:44.574 [BackupJob::getFirstCopyJobid] first copy jobid=156467(BackupJob.cpp:2993)
12/17/08 11:15:45.727 [JobInstance::ping] Ping for jobid=156467 next interval is -1(JobInstance.cpp:608)
12/17/08 11:15:47.730 [JobInstance::ping] Ping for jobid=156467 next interval is 0(JobInstance.cpp:608)
12/17/08 11:42:01.502 [BackupJob::stateTransition] old state = 4 new state = 10(BackupJob.cpp:2126)
12/17/08 11:42:01.504 [BackupJob::terminateThisJob] terminated job (jobid=156467), status=144(BackupJob.cpp:1148)
12/17/08 11:42:01.880 [Info] V-116-14 CLIENT adnnfs03  POLICY Month-Netapp2  SCHED Full  EXIT STATUS 144 (invalid command usage)
12/17/08 11:42:02.042 [?] <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
12/17/08 11:42:02.043 [?] << End Job JOBID = 156467 status 144 (invalid command usage)
12/17/08 11:42:02.043 [JobListener_i::updateJobStatus_u] << resubmitting retryable immediate backup
12/17/08 11:42:02.043 [?] <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
12/17/08 11:42:02.043 [?]  >>>>>>>>>>>RESTART>>>>>>>>>>>>>>>>>
12/17/08 11:42:02.043 [?]  >> Restart JOBID jobid=156467 policy=Month-Netapp2 client=adnnfs03 schedule =Full last sched used =
12/17/08 11:42:02.043 [?]  >> stream # = 2 runonce = 1 try = 2 disk full=0 (IB) time = Wed Dec 17 11:42:02 2008
12/17/08 11:42:02.043 [?]  >> window close time = Thu Jan  1 00:59:59 1970
12/17/08 11:42:02.043 [?]  >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
[...]

The rest of the logs don't look very useful for me - but I'm not an expert. I'll try to enable NDMP debugging on the NetApp filer.

Best regards,

Bernd

[AdN]

This is the only error I see when setting ndmpd debug level to 70 on the NetApp filer:

Dec 18 10:23:19 CET [ndmpd:2]: Created an NDMP server connection
Dec 18 10:23:19 CET [ndmpd:2]: Message NDMP_NOTIFY_CONNECTION_STATUS sent
Dec 18 10:23:19 CET [ndmpd:2]: NDMP message type: NDMP_CONNECT_OPEN
Dec 18 10:23:19 CET [ndmpd:2]: NDMP message replysequence: 1
Dec 18 10:23:19 CET [ndmpd:2]: NDMP message type: NDMP_CONFIG_GET_SERVER_INFO
Dec 18 10:23:19 CET [ndmpd:2]: NDMP message replysequence: 2
Dec 18 10:23:19 CET [ndmpd:2]: NDMP message type: NDMP_CONFIG_GET_AUTH_TYPE_ATTR
Dec 18 10:23:19 CET [ndmpd:2]: NDMP message replysequence: 3
Dec 18 10:23:19 CET [ndmpd:2]: NDMP message type: NDMP_CONNECT_CLIENT_AUTH
Dec 18 10:23:19 CET [ndmpd:2]: NDMP message replysequence: 4
Dec 18 10:23:19 CET [ndmpd:2]: NDMP message type: NDMP_CONFIG_GET_HOST_INFO_V3
Dec 18 10:23:19 CET [ndmpd:2]: NDMP message replysequence: 5
Dec 18 10:23:20 CET [ndmpd:2]: NDMP message type: NDMP_TAPE_OPEN
Dec 18 10:23:20 CET [ndmpd:2]: NDMP message replysequence: 6
Dec 18 10:23:20 CET [ndmpd:2]: NDMP message type: NDMP_CONNECT_CLOSE
Dec 18 10:23:20 CET [ndmpd:2]: NDMP message replysequence: 7
Dec 18 10:23:20 CET [ndmpd:2]: Error sending notify shutdown message
Dec 18 10:23:20 CET [ndmpd:2]: Ndmpd session closed successfully

[CRZ]

---

@AdN wrote:

ONTAP release is 7.0.5P7

---

You're probably going to get mad at me for suggesting ANOTHER upgrade, but would you consider applying the latest ONTAP version to your filer?  (I think they're up to 7.3?)

I think you may be getting thrown by some filenames with "weird" characters in them (non-ASCII, UTF-8).

One way to work around is to prepend "set HIST=n" to your policy list.  The upside is the backup should complete.  The DOWNside is you lose the ability to select single files should you want that granularity in any restore attempts - and if it's a 1.2T volume, you surely do.

We have an older TechNote on this:

When attempting an NDMP backup of files or data paths that contain non-ASCII UTF-8 characters with NetBackup 5.0, 5.1, or 6.0 GA, 6.0 MP1 or 6.0 MP2, the backup could incorrectly exit with a NetBackup Status Code 0; however, the files/directories which contain the non-ASCII UTF-8 characters are not available for restore.

 http://support.veritas.com/docs/285798

In a nutshell, in 6.0, we USED to not have these errors and the backups would appear to succeed...except you'd never be able to restore the files with the weird characters in them.  (For all we know, this may have actually been happening to you for years!)

At 6.0 MP4, we throw a Status Code 144...and it looks like that's what you're getting.  Since your NetBackup is up to date, the next suspect is ONTAP.  I have a feeling if you get 7.1 or above on there, this problem may go away.

(I'm sorry I didn't find this TechNote in your last thread!  Your logs definitely helped me find it this time, though.)

[AdN]

Hi Chris,

Thanks for your hint. Wen setting up the NetApp I configured UTF-8 character set for the volumes.

We're already planning an upgrade to ONTAP 7.2.5.1 (7.3 is only a general available release) and a filer replacement from FAS 3020 to 3140. An upgrade to Netbackup 6.5 is also planned because we need to be able to backup Solaris ZFS filesystem.

But we would like to have a current tape backup before the migration. ;)

So the workaround would be for me to write a script that searches for files with non-ascii filenames and replace them. At least 90% of our NDMP backup runs through. It's only the user homes.

Bye

Bernd

[AdN · Accepted solution]

Upgrading NetApp Data ONTAP 7.0.5P7 to 7.2.6.1 and Netbackup 6.0 to Netbackup MP7 solved that issue. All tape backups now run fine.

Thanks a lot for your help!

Best regards

Bernd