netbackup client side deduplication backups fail with error 87

[NavGee]

client side deuplication backups fail with error 87, any ideas?

4/30/2014 17:26:34 - Info bpbrm (pid=31619) starting bpbkar on client
04/30/2014 17:26:34 - connecting
04/30/2014 17:26:34 - connected; connect time: 0:00:00
04/30/2014 17:26:36 - Info bpbkar (pid=9960) Backup started
04/30/2014 17:26:36 - Info bpbrm (pid=31619) bptm pid: 31630
04/30/2014 17:26:36 - Info bptm (pid=31630) start
04/30/2014 17:26:37 - Info bptm (pid=31630) using 262144 data buffer size
04/30/2014 17:26:37 - Info bptm (pid=31630) using 30 data buffers
04/30/2014 17:26:37 - Info basxtsprdbcka01 (pid=31630) Using OpenStorage client direct to backup from client basxpsprdfpsv01.be.xchanginghosting.com to basxtsprdbcka01
04/30/2014 17:26:39 - begin writing
04/30/2014 17:27:29 - Info bpbkar (pid=9960) change journal NOT enabled for <E:\>
04/30/2014 20:14:21 - Critical bptm (pid=31630) sts_close_handle failed: 2060022 software error
04/30/2014 20:14:21 - Critical bptm (pid=31630) cannot write image to disk, media close failed with status 2060022
04/30/2014 20:14:21 - Info basxtsprdbcka01 (pid=31630) StorageServer=PureDisk:basxtsprdbcka01; Report=PDDO Stats for (basxtsprdbcka01): scanned: 358440501 KB, CR sent: 132515037 KB, CR sent over FC: 0 KB, dedup: 63.0%, cache hits: 10793 (0.3%)
04/30/2014 20:14:21 - Critical bptm (pid=31630) sts_close_server failed: error 2060005 object is busy, cannot be closed
04/30/2014 20:14:24 - Info bptm (pid=31630) EXITING with status 87 <----------
04/30/2014 20:14:25 - Info bpbkar (pid=9960) done. status: 87: media close error
04/30/2014 20:14:25 - end writing; write time: 2:47:46
media close error  (87)
 

[Mark_Solutions]

Disk 16 - mmm - sure i saw something about disk 16 going down when you upgrade an appliance.... cant track it down right now..

[NavGee]

Hi Mark

Seem to bit and miss with client side deduplication and accelerator based backups for certain clients.  Appliance is not over loaded. Have reduced the fragment size to 5000 and introduced check points every 20mins will give it a go.

job log from last nights failure details are different from the previous failure.

1413546772, status = 2, info = system exception, ID 'IDL:omg.org/CORBA/COMM_FAILURE:1.0'.TAO exception, minor code = 14 (failed to recv request response; ENOTSUP), completed = MAYBE
05/06/2014 19:12:14 - Error bpbrm (pid=19157) libsts opensvh() 14/05/06 19:12:14: v11_open_server failed in plugin /usr/openv/lib/libstspinbostpxy.so err 2060057
05/06/2014 19:12:14 - Error bpbrm (pid=19157) sts_open_server failed: error 2060057
05/06/2014 19:12:14 - Info bpbkar (pid=2412) done. status: 87: media close error
05/06/2014 19:12:14 - end writing; write time: 1:11:26
media close error  (87)
 

[NavGee]

Hi Mark reduced storage unit value to 5000 and introduced checkpoint to every 20 mins. Will run another backup.

log from last night failure.

05/06/2014 18:56:39 - Critical bptm (pid=19166) sts_close_server failed: error 2060005 object is busy, cannot be closed
05/06/2014 18:56:41 - Info bptm (pid=19166) EXITING with status 87 <----------
05/06/2014 19:12:14 - Error bpbrm (pid=19157) [ERROR][proxy_open_server_v7]CORBA::SystemException is caught in proxy_open_server_v7, minor = 1413546772, status = 2, info = system exception, ID 'IDL:omg.org/CORBA/COMM_FAILURE:1.0'.TAO exception, minor code = 14 (failed to recv request response; ENOTSUP), completed = MAYBE
05/06/2014 19:12:14 - Error bpbrm (pid=19157) libsts opensvh() 14/05/06 19:12:14: v11_open_server failed in plugin /usr/openv/lib/libstspinbostpxy.so err 2060057
05/06/2014 19:12:14 - Error bpbrm (pid=19157) sts_open_server failed: error 2060057
05/06/2014 19:12:14 - Info bpbkar (pid=2412) done. status: 87: media close error
05/06/2014 19:12:14 - end writing; write time: 1:11:26
media close error  (87)
 

[NavGee]

Mark reduced the fragment size for the SU introduced checkpoint. Currently running another backup.

However the job log from lastnights backup was different

05/06/2014 18:56:39 - Critical bptm (pid=19166) sts_close_server failed: error 2060005 object is busy, cannot be closed
05/06/2014 18:56:41 - Info bptm (pid=19166) EXITING with status 87 <----------
05/06/2014 19:12:14 - Error bpbrm (pid=19157) [ERROR][proxy_open_server_v7]CORBA::SystemException is caught in proxy_open_server_v7, minor = 1413546772, status = 2, info = system exception, ID 'IDL:omg.org/CORBA/COMM_FAILURE:1.0'.TAO exception, minor code = 14 (failed to recv request response; ENOTSUP), completed = MAYBE
05/06/2014 19:12:14 - Error bpbrm (pid=19157) libsts opensvh() 14/05/06 19:12:14: v11_open_server failed in plugin /usr/openv/lib/libstspinbostpxy.so err 2060057
05/06/2014 19:12:14 - Error bpbrm (pid=19157) sts_open_server failed: error 2060057
05/06/2014 19:12:14 - Info bpbkar (pid=2412) done. status: 87: media close error
05/06/2014 19:12:14 - end writing; write time: 1:11:26
media close error  (87)
 

[NavGee]

Hi Mark made your recommended changes rerunning backup currently.

Details from last night failure with accelerator

 Report=PDDO Stats for (basxtsprdbcka01): scanned: 13617395 KB, CR sent: 0 KB, CR sent over FC: 0 KB, dedup: 100.0%
05/06/2014 18:40:26 - Critical bptm (pid=19164) sts_close_server failed: error 2060005 object is busy, cannot be closed
05/06/2014 18:40:28 - Info bptm (pid=19164) EXITING with status 87 <----------
05/06/2014 18:56:00 - Error bpbrm (pid=19146) [ERROR][proxy_open_server_v7]CORBA::SystemException is caught in proxy_open_server_v7, minor = 1413546772, status = 2, info = system exception, ID 'IDL:omg.org/CORBA/COMM_FAILURE:1.0'.TAO exception, minor code = 14 (failed to recv request response; ENOTSUP), completed = MAYBE
05/06/2014 18:56:00 - Error bpbrm (pid=19146) libsts opensvh() 14/05/06 18:56:00: v11_open_server failed in plugin /usr/openv/lib/libstspinbostpxy.so err 2060057
05/06/2014 18:56:00 - Error bpbrm (pid=19146) sts_open_server failed: error 2060057
05/06/2014 18:56:00 - Error bpbrm (pid=19146) could not send server status message
05/06/2014 18:56:01 - Info bpbkar (pid=10396) done. status: 87: media close error
05/06/2014 18:56:01 - end writing; write time: 0:55:15
media close error  (87)
 

[NavGee · Accepted solution]

Details from last night failure with accelerator enabled as well as clientside deduplication.

05/06/2014 18:40:26 - Critical bptm (pid=19164) sts_close_server failed: error 2060005 object is busy, cannot be closed
05/06/2014 18:40:28 - Info bptm (pid=19164) EXITING with status 87 <----------
05/06/2014 18:56:00 - Error bpbrm (pid=19146) [ERROR][proxy_open_server_v7]CORBA::SystemException is caught in proxy_open_server_v7, minor = 1413546772, status = 2, info = system exception, ID 'IDL:omg.org/CORBA/COMM_FAILURE:1.0'.TAO exception, minor code = 14 (failed to recv request response; ENOTSUP), completed = MAYBE
05/06/2014 18:56:00 - Error bpbrm (pid=19146) libsts opensvh() 14/05/06 18:56:00: v11_open_server failed in plugin /usr/openv/lib/libstspinbostpxy.so err 2060057
05/06/2014 18:56:00 - Error bpbrm (pid=19146) sts_open_server failed: error 2060057
05/06/2014 18:56:00 - Error bpbrm (pid=19146) could not send server status message
05/06/2014 18:56:01 - Info bpbkar (pid=10396) done. status: 87: media close error
05/06/2014 18:56:01 - end writing; write time: 0:55:15
media close error (87)

will update worker thread next to 128