Unsolved
This post is more than 5 years old
7 Posts
0
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
Idan
675 Posts
0
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