Volume migration times out due to slow volume shutdown

[redlicha]

• source:

  2017-09-08 04:20:02 957916 -0400 - NY1SRV0008 - 5111/0x00007f79787f8700 - volumedriverfs/VFSLocalNode - 000000000420a9dc - info - transfer: Volume-d65df314-cebe-4d6b-97d4-fb6bae85e055: target_node data-ny1-02roLR7yTDk9hMdPGK
  2017-09-08 04:20:02 958025 -0400 - NY1SRV0008 - 5111/0x00007f79787f8700 - volumedriverfs/VFSLocalNode - 000000000420a9dd - info - destroy_: d65df314-cebe-4d6b-97d4-fb6bae85e055: trying to sync to the backend
  2017-09-08 04:20:02 961001 -0400 - NY1SRV0008 - 5111/0x00007f79787f8700 - volumedriverfs/DataStoreNG - 000000000420a9de - info - updateCurrentSCO_: created new write SCO 00_00000b7e_00 for Volume d65df314-cebe-4d6b-97d4-fb6bae85e055
  2017-09-08 04:20:02 961579 -0400 - NY1SRV0008 - 5111/0x00007f79787f8700 - volumedriverfs/CachedMetaDataStore - 000000000420a9e1 - info - cork: d65df314-cebe-4d6b-97d4-fb6bae85e055: corking f67d2fb9-986d-4476-a6e4-7779edefee08
  2017-09-08 04:20:03 984177 -0400 - NY1SRV0008 - 5111/0x00007f79787f8700 - volumedriverfs/VFSLocalNode - 000000000420aa07 - info - destroy_: d65df314-cebe-4d6b-97d4-fb6bae85e055: synced to the backend
  2017-09-08 04:20:03 984265 -0400 - NY1SRV0008 - 5111/0x00007f79787f8700 - volumedriverfs/VolManager - 000000000420aa08 - notice - Destroy Volume, VolumeId: d65df314-cebe-4d6b-97d4-fb6bae85e055, delete local data: DeleteLocalData::T, remove volume completely RemoveVolumeCompletely::F, delete namespace DeleteVolumeNamespace::F, force deletion ForceVolumeDeletion::F, START
  2017-09-08 04:20:03 984774 -0400 - NY1SRV0008 - 5111/0x00007f79787f8700 - volumedriverfs/Volume - 000000000420aa09 - info - destroy: d65df314-cebe-4d6b-97d4-fb6bae85e055: destroying volume: delete local data DeleteLocalData::T, remove volume completely RemoveVolumeCompletely::F, force_volume deletion ForceVolumeDeletion::F
  2017-09-08 04:20:03 984820 -0400 - NY1SRV0008 - 5111/0x00007f79787f8700 - volumedriverfs/FailOverCacheProxy - 000000000420aa0a - info - unregister_: Not deleting failover dir for d65df314-cebe-4d6b-97d4-fb6bae85e055
  2017-09-08 04:23:22 246209 -0400 - NY1SRV0008 - 5111/0x00007f79787f8700 - volumedriverfs/MDSMetaDataBackend - 000000000420acfd - info - ~MDSMetaDataBackend: d65df314-cebe-4d6b-97d4-fb6bae85e055: used clusters: 1602486
  2017-09-08 04:23:22 246312 -0400 - NY1SRV0008 - 5111/0x00007f79787f8700 - volumedriverfs/DataStoreNG - 000000000420acfe - info - destroy: d65df314-cebe-4d6b-97d4-fb6bae85e055: destroying DataStore, DeleteLocalData::T
  2017-09-08 04:23:22 246829 -0400 - NY1SRV0008 - 5111/0x00007f79787f8700 - volumedriverfs/SCOCacheMountPoint - 000000000420acff - info - removeNamespace: "/mnt/ssd2/data-ny1-02_write_sco_1": removing namespace d65df314-cebe-4d6b-97d4-fb6bae85e055 from mountpoint
  2017-09-08 04:23:22 247143 -0400 - NY1SRV0008 - 5111/0x00007f79787f8700 - volumedriverfs/SCOCacheMountPoint - 000000000420ad00 - info - removeNamespace: "/mnt/ssd3/data-ny1-02_write_sco_1": removing namespace d65df314-cebe-4d6b-97d4-fb6bae85e055 from mountpoint
  2017-09-08 04:23:22 247466 -0400 - NY1SRV0008 - 5111/0x00007f79787f8700 - volumedriverfs/Volume - 000000000420ad01 - info - destroy: d65df314-cebe-4d6b-97d4-fb6bae85e055: Unregistering volume from ClusterCache
  2017-09-08 04:23:22 247502 -0400 - NY1SRV0008 - 5111/0x00007f79787f8700 - volumedriverfs/VolManager - 000000000420ad02 - notice - Destroy Volume, VolumeId: d65df314-cebe-4d6b-97d4-fb6bae85e055, delete local data: DeleteLocalData::T, remove volume completely RemoveVolumeCompletely::F, delete namespace DeleteVolumeNamespace::F, force deletion ForceVolumeDeletion::F, FINISHED
  2017-09-08 04:23:22 247518 -0400 - NY1SRV0008 - 5111/0x00007f79787f8700 - volumedriverfs/Volume - 000000000420ad03 - info - ~Volume: d65df314-cebe-4d6b-97d4-fb6bae85e055: Destructor of 0x7f77869244a0
  2017-09-08 04:23:22 250181 -0400 - NY1SRV0008 - 5111/0x00007f79787f8700 - volumedriverfs/ObjectRegistry - 000000000420ad04 - info - migrate: 3b180e86-6a76-481b-95e0-93d139f87f06/data-ny1-02JmyoUr04PHfa41vA: trying to move d65df314-cebe-4d6b-97d4-fb6bae85e055 from data-ny1-02JmyoUr04PHfa41vA to data-ny1-02roLR7yTDk9hMdPGK
  2017-09-08 04:23:22 250219 -0400 - NY1SRV0008 - 5111/0x00007f79787f8700 - volumedriverfs/ObjectRegistry - 000000000420ad05 - info - prepare_migrate: 3b180e86-6a76-481b-95e0-93d139f87f06/data-ny1-02JmyoUr04PHfa41vA: trying to add migration of d65df314-cebe-4d6b-97d4-fb6bae85e055 from data-ny1-02JmyoUr04PHfa41vA to data-ny1-02roLR7yTDk9hMdPGK to sequence

• destination:

  017-09-08 04:20:06 106338 -0400 - NY1SRV0014 - 26773/0x00007f77ad7fa700 -
  volumedriverfs/VFSObjectRouter - 0000000000a1defc - info - migrate_: Trying to migrate d65df314-cebe-4d6b-97d4-fb6bae85e055 from data-ny1-02JmyoUr04PHfa41vA, only steal if offline OnlyStealFromOfflineNode::T
  2017-09-08 04:22:06 106484 -0400 - NY1SRV0014 - 26773/0x00007f77ad7fa700 - volumedriverfs/VFSRemoteNode - 0000000000a1e0fc - info - handle_: data-ny1-02JmyoUr04PHfa41vA: remote did not respond within 120000 milliseconds milliseconds - giving up
  2017-09-08 04:22:06 106869 -0400 - NY1SRV0014 - 26773/0x00007f77ad7fa700 - 
  volumedriverfs/XMLRPCTimingWrapper - 0000000000a1e0fd - error - execute: migrateVolume Caught fungi::IOException: request to remote node timed out
  2017-09-08 04:22:06 106969 -0400 - NY1SRV0014 - 26773/0x00007f77ad7fa700 -
  volumedriverfs/XMLRPCConnection - 0000000000a1e0fe - info - operator(): Closing socket 948

[redlicha]

related code: https://github.com/openvstorage/volumedriver/blob/6.17.1/src/volumedriver/Volume.cpp#L1697-L1717

[redlicha]

Possibly related: #350 , where big gaps in the timestamps during MDS slave catchup are observed?

[wimpers]

@jtorreke is this still an issue?