Start a Conversation

Unsolved

This post is more than 5 years old

2643

December 11th, 2016 11:00

Recovery Point 5.0 for VMs splitter driver keeps reporting errors reading vvol datastores

This splitter vib is continuously contacting my vvOL datastore though this was not choosen to be part of datastores for replication on the splitter plugin in the Gui , however the hosts that were choosen has access to vvols . This is filling up my vmkernel logs and other logs masking my core issues and rolls up my logs faster .

Tried to kill the vib it hung up for quite some time and later completed later, little unusual though glad it didnt crash my hostd serivce .

Please help fix the issue ASAP .

VMware ESXi 6.0.0 build-3620759

VMware ESXi 6.0.0 Update 2

esxcli software vib list :

Name                           Version                                                  Vendor            Acceptance Level  Install Date

-----------------------------  ------------------------------------                               ----------------  ----------------  ------------

RP-Splitter                    RPESX-00.5.0.0.1.0.d.207.000          EMC_Recoverpoint  VMwareCertified   2016-12-11

[root@is-tse-d112:/var/log] /etc/init.d/rp@-splitterd stop

Sun Dec 11 19:10:07 UTC 2016: rp_splitterd: Stopping rp_splitter

Sun Dec 11 19:10:07 UTC 2016: rp_splitterd: killing kdriver

Sun Dec 11 19:10:07 UTC 2016) kill_kdriver: Requesting kdriver watchdog to stop loading the kdriver from next crash

Sun Dec 11 19:10:07 UTC 2016) kill_kdriver: run kill command. Please wait a few seconds for kdriver to be totally down.

Sun Dec 11 19:10:09 UTC 2016) kill_kdriver: tried to remove kdriver 1 times

kill: can't kill pid 475557: No such process

Sun Dec 11 19:10:09 UTC 2016) kill_kdriver: run kill command. Please wait a few seconds for kdriver to be totally down.

Sun Dec 11 19:10:11 UTC 2016) kill_kdriver: tried to remove kdriver 2 times

Sun Dec 11 19:10:11 UTC 2016) kill_kdriver: kdriver is down after 2 trials

Sun Dec 11 19:10:11 UTC 2016: rp_splitterd: Sleeping a lot

Sun Dec 11 19:10:21 UTC 2016: rp_splitterd: killing splitter

Module esx_splitter successfully unloaded

Sun Dec 11 19:11:54 UTC 2016: rp_splitterd: Sleeping

vmkernel logs after killing the process :

2016-12-11T19:11:10.691Z cpu7:486970)esx_splitter: KL_INFO:865: #2 - spl_destroy_rpvs_cluster_ids_timer: was called

2016-12-11T19:11:11.330Z cpu5:475505)esx_splitter: KL_INFO:865: #2 - spl_plt_print_memory_stats: HEAP SIZE = 174329056

2016-12-11T19:11:40.659Z cpu7:486970)esx_splitter: KL_INFO:865: #2 - spl_destroy_Rpas called

2016-12-11T19:11:41.333Z cpu6:475505)esx_splitter: KL_INFO:865: #2 - spl_plt_print_memory_stats: HEAP SIZE = 174329232

2016-12-11T19:11:41.333Z cpu7:486970)esx_splitter: KL_ERROR:940: #0 - SplList_destroy: Destroying non-empty list: list = (0x430fd46260e0), head = (0x430fd49a3cb0), tail = (0x430fd49a3d70), numObjects = (4096)

2016-12-11T19:11:41.333Z cpu7:486970)esx_splitter: KL_ERROR:940: #0 - SplList_destroy: Destroying non-empty list: list = (0x430fd4625d90), head = (0x430fd67ff890), tail = (0x430fd67ff9e8), numObjects = (4096)

2016-12-11T19:11:41.333Z cpu7:486970)esx_splitter: KL_INFO:865: #2 - spl_destroy called

2016-12-11T19:11:46.335Z cpu5:475505)esx_splitter: KL_INFO:865: #2 - spl_plt_print_memory_stats: HEAP SIZE = 176525984

2016-12-11T19:11:50.955Z cpu4:486970)esx_splitter: KL_INFO:865: #2 - ResponseQueue (DTOR) called for DataPath ResponseQueue.

2016-12-11T19:11:50.955Z cpu4:486970)esx_splitter: KL_INFO:865: #2 - ResponseQueue (DTOR) called for ControlPath ResponseQueue.

2016-12-11T19:11:50.955Z cpu4:486970)esx_splitter: KL_INFO:865: #2 - spl_timeouts_destroy called - destroying handle_timeouts timer

2016-12-11T19:11:51.335Z cpu4:486970)esx_splitter: KL_INFO:865: #2 - spl_keepalive_destroy called - destroying keepalive timer

2016-12-11T19:11:52.135Z cpu7:486970)esx_splitter: KL_INFO:865: #2 - spl_timeouts_destroy called - destroying try_handle_waiting_cmds timer

2016-12-11T19:11:53.911Z cpu5:486970)esx_splitter: KL_INFO:865: #2 - spl_destroy: Destroyed all timers

2016-12-11T19:11:53.911Z cpu5:486970)esx_splitter: KL_INFO:865: #2 - spl_thread_destroy_control_executer: CDELETE s_control_path_executer

2016-12-11T19:11:53.911Z cpu5:486970)esx_splitter: KL_INFO:865: #2 - CommandHandleWaitingCmds_create: CommandStopExecuter_ctor(0x430fd49c42d8, 0x430fd4623760)

2016-12-11T19:11:53.911Z cpu5:486970)esx_splitter: KL_INFO:865: #2 - CommandStopExecuter_create: CommandStopExecuter_s_control_path_executer, 0x430fd49c42d8, succeeded

2016-12-11T19:11:53.911Z cpu5:486970)esx_splitter: KL_INFO:865: #2 - CommandExecuterBase_v_stop_i: CommandStopExecuter_s_control_path_executer, started

2016-12-11T19:11:53.911Z cpu5:486970)esx_splitter: KL_INFO:865: #2 - CommandExecuterBase_v_stop_i: CommandStopExecuter_s_control_path_executer, CommandExecuterBase_enqueue(0x430fd4623760, 0x430fd49c42d8)

2016-12-11T19:11:53.911Z cpu5:486970)esx_splitter: KL_INFO:865: #2 - CommandExecuterBase_v_stop_i: CommandStopExecuter_s_control_path_executer, CommandStopExecuter_wait(0x430fd49c42d8)

2016-12-11T19:11:53.911Z cpu6:475504)esx_splitter: KL_INFO:865: #2 - static_CommandStopExecuter_execute: CommandStopExecuter_s_control_path_executer, 0x430fd49c42d8, started

2016-12-11T19:11:53.911Z cpu6:475504)esx_splitter: KL_INFO:865: #2 - static_CommandStopExecuter_execute: CommandStopExecuter_s_control_path_executer, 0x430fd49c42d8, succeeded

2016-12-11T19:11:53.912Z cpu5:486970)esx_splitter: KL_INFO:865: #2 - CommandExecuterBase_v_stop_i: CommandStopExecuter_s_control_path_executer, succeeded

2016-12-11T19:11:53.912Z cpu5:486970)esx_splitter: KL_INFO:865: #2 - spl_thread_destroy_data_executer: call to spl_plt_thread_destroy_executers

2016-12-11T19:11:53.912Z cpu5:486970)esx_splitter: KL_INFO:865: #2 - CommandHandleWaitingCmds_create: CommandStopExecuter_ctor(0x430fd49c42d8, 0x430fd4623a90)

2016-12-11T19:11:53.912Z cpu5:486970)esx_splitter: KL_INFO:865: #2 - CommandStopExecuter_create: CommandStopExecuter_s_data_path_executer, 0x430fd49c42d8, succeeded

2016-12-11T19:11:53.912Z cpu5:486970)esx_splitter: KL_INFO:865: #2 - CommandExecuterBase_v_stop_i: CommandStopExecuter_s_data_path_executer, started

2016-12-11T19:11:53.912Z cpu5:486970)esx_splitter: KL_INFO:865: #2 - CommandExecuterBase_v_stop_i: CommandStopExecuter_s_data_path_executer, CommandExecuterBase_enqueue(0x430fd4623a90, 0x430fd49c42d8)

2016-12-11T19:11:53.912Z cpu5:486970)esx_splitter: KL_INFO:865: #2 - CommandExecuterBase_v_stop_i: CommandStopExecuter_s_data_path_executer, CommandStopExecuter_wait(0x430fd49c42d8)

2016-12-11T19:11:53.912Z cpu4:475505)esx_splitter: KL_INFO:865: #2 - static_CommandStopExecuter_execute: CommandStopExecuter_s_data_path_executer, 0x430fd49c42d8, started

2016-12-11T19:11:53.912Z cpu4:475505)esx_splitter: KL_INFO:865: #2 - static_CommandStopExecuter_execute: CommandStopExecuter_s_data_path_executer, 0x430fd49c42d8, succeeded

2016-12-11T19:11:53.912Z cpu4:486970)esx_splitter: KL_INFO:865: #2 - CommandExecuterBase_v_stop_i: CommandStopExecuter_s_data_path_executer, succeeded

2016-12-11T19:11:53.912Z cpu4:486970)esx_splitter: KL_INFO:865: #2 - spl_destroy_all_volumes called

2016-12-11T19:11:53.912Z cpu4:486970)esx_splitter: KL_INFO:865: #2 - spl_clusters_destroy: started

2016-12-11T19:11:53.912Z cpu4:486970)esx_splitter: KL_INFO:865: #2 - spl_clusters_destroy: ended

2016-12-11T19:11:53.912Z cpu4:486970)esx_splitter: KL_INFO:865: #2 - IfSendIo_terminate: done

2016-12-11T19:11:53.912Z cpu4:486970)esx_splitter: KL_INFO:865: #2 - spl_sm_destory_state_machine: called

2016-12-11T19:11:53.913Z cpu4:486970)esx_splitter: KL_INFO:865: #2 - AllocatorSlab_terminate: called

2016-12-11T19:11:53.913Z cpu4:486970)esx_splitter: KL_INFO:865: #2 - spl_destroy done.

2016-12-11T19:11:53.913Z cpu4:486970)esx_splitter: KL_INFO:865: #2 - spl_esx_destroy_rpvs_sandiscovery called

2016-12-11T19:11:53.913Z cpu4:486970)esx_splitter: KL_INFO:865: #2 - spl_esx_destroy_rpa_sandiscovery called

2016-12-11T19:11:53.913Z cpu4:486970)esx_splitter: KL_INFO:865: #2 - EsxSplitterDriver DTOR

2016-12-11T19:11:53.913Z cpu4:486970)esx_splitter: KL_INFO:865: #2 - spl_destroy_rpvs_cluster_ids_db: was called

2016-12-11T19:11:53.913Z cpu4:486970)esx_splitter: KL_INFO:865: #2 - RPVS_ClusterLuns_DTOR: delete clusterLuns clusterID 5a67887a3b8dd623.

2016-12-11T19:11:53.913Z cpu4:486970)esx_splitter: KL_INFO:865: #2 - RPVS_ClusterLuns_DTOR: about to remove lun 1 in clusterID 5a67887a3b8dd623.

2016-12-11T19:11:53.915Z cpu4:486970)esx_splitter: cleanup_module:208: Splitter module saying goodbye!

2016-12-11T19:11:53.915Z cpu4:486970)WARNING: Heap: 2774: Non-empty heap (esx_splitter) being destroyed (avail is 4188912, should be 4202336).

2016-12-11T19:11:54.177Z cpu4:486970)Mod: 5201: Unload complete

========================================================================

Log snippet for vvol datastore query  spam :

2016-12-11T18:54:40.672Z cpu0:32791)esx_splitter: KL_WARNING:828: #1 - mode_sense_command_10_done: failed to send mode sense to naa.60012480000200006f8baced95f7ccf2. host Status = 0x1, device Status = 0x0, plugin Status = 0x0

2016-12-11T18:54:40.812Z cpu1:475504)esx_splitter: KL_ERROR:940: #0 - spl_esx_discover_RPvStorage_clusters_in_datastore: failed to read directory /vmfs/volumes/vvol:7940a91c53cf4dd5-a98d57cc7dbef9cc, returned with status Failure

2016-12-11T18:55:10.673Z cpu0:32791)esx_splitter: KL_WARNING:828: #1 - mode_sense_command_10_done: failed to send mode sense to naa.60012480000200006f8baced95f7ccf2. host Status = 0x1, device Status = 0x0, plugin Status = 0x0

2016-12-11T18:55:10.863Z cpu0:475504)esx_splitter: KL_ERROR:940: #0 - spl_esx_discover_RPvStorage_clusters_in_datastore: failed to read directory /vmfs/volumes/vvol:7940a91c53cf4dd5-a98d57cc7dbef9cc, returned with status Failure

2016-12-11T18:55:20.219Z cpu7:475624)esx_splitter: KL_INFO:865: #2 - spl_esx_ioctl_uspace_san_view: requested 0 devices. returning 0 devices

2016-12-11T18:55:40.674Z cpu3:32794)esx_splitter: KL_WARNING:828: #1 - mode_sense_command_10_done: failed to send mode sense to naa.60012480000200006f8baced95f7ccf2. host Status = 0x1, device Status = 0x0, plugin Status = 0x0

2016-12-11T18:55:40.868Z cpu1:475504)esx_splitter: KL_ERROR:940: #0 - spl_esx_discover_RPvStorage_clusters_in_datastore: failed to read directory /vmfs/volumes/vvol:7940a91c53cf4dd5-a98d57cc7dbef9cc, returned with status Failure

2016-12-11T18:56:05.592Z cpu4:475624)esx_splitter: KL_INFO:865: #2 - spl_esx_ioctl_uspace_san_view: requested 0 devices. returning 0 devices

2016-12-11T18:56:10.675Z cpu0:32791)esx_splitter: KL_WARNING:828: #1 - mode_sense_command_10_done: failed to send mode sense to naa.60012480000200006f8baced95f7ccf2. host Status = 0x1, device Status = 0x0, plugin Status = 0x0

2016-12-11T18:56:10.814Z cpu2:475504)esx_splitter: KL_ERROR:940: #0 - spl_esx_discover_RPvStorage_clusters_in_datastore: failed to read directory /vmfs/volumes/vvol:7940a91c53cf4dd5-a98d57cc7dbef9cc, returned with status Failure

Message was edited by: Hareesh K G

675 Posts

December 12th, 2016 00:00

Hi Hareesh,

The correct way to kill the kdriver and splitter would be to execute /kdriver/bin/kill_kdriver.sh.

Let's continue our offline discussion to further troubleshoot.

Regards,

Idan Kentor

RecoverPoint Corporate Systems Engineering

No Events found!

Top