backend abm: Unlink of "/mnt/ssd1/arakoon/sas-back-abm/db/touch-20625" failed with ENOENT

[yongshengma]

Hello,

ovs-arakoon-sas-back-abm.service keeps on activating but it cannot start up. It has been like for a few weeks. Just wondering whats' going on:

-- Logs begin at Tue 2019-07-09 13:59:34 CST, end at Tue 2019-07-09 13:59:58 CST. --
Jul 09 13:59:39 node3 systemd[1]: ovs-arakoon-sas-back-abm.service holdoff time over, scheduling restart.
Jul 09 13:59:39 node3 systemd[1]: Starting Arakoon service for cluster sas-back-abm...
Jul 09 13:59:39 node3 systemd[1]: Started Arakoon service for cluster sas-back-abm.
Jul 09 13:59:46 node3 systemd[1]: ovs-arakoon-sas-back-abm.service: main process exited, code=exited, status=41/n/a
Jul 09 13:59:46 node3 systemd[1]: Unit ovs-arakoon-sas-back-abm.service entered failed state.
Jul 09 13:59:46 node3 systemd[1]: ovs-arakoon-sas-back-abm.service failed.
Jul 09 13:59:51 node3 systemd[1]: ovs-arakoon-sas-back-abm.service holdoff time over, scheduling restart.
Jul 09 13:59:51 node3 systemd[1]: Starting Arakoon service for cluster sas-back-abm...
Jul 09 13:59:52 node3 systemd[1]: Started Arakoon service for cluster sas-back-abm.
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 041391 +0800 - node3 - 20625/0000 - arakoon - 0 - info - --- NODE STARTED ---
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 042718 +0800 - node3 - 20625/0000 - arakoon - 1 - info - git_revision: tags/1.9.22-0-gd4f2572-dirty
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 042735 +0800 - node3 - 20625/0000 - arakoon - 2 - info - compile_time: 08/12/2017 01:32:14 UTC
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 042744 +0800 - node3 - 20625/0000 - arakoon - 3 - info - version: 1.9.22
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 042754 +0800 - node3 - 20625/0000 - arakoon - 4 - info - NOFILE: 8192
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 042843 +0800 - node3 - 20625/0000 - arakoon - 5 - info - cluster_cfg={ cfgs = [{ node_name = "XHGfO1fHVDeRKHxa"; ips = ["192.168.0.34"]; client_port = 26408; messaging_port = 26409; home = "/mnt/ssd1/arakoon/sas-back-abm/db"; tlog_dir = "/mnt/ssd1/arakoon/sas-back-abm/tlogs"; log_sinks = [Console]; crash_log_sinks = [File(console:)]; tlx_dir = "/mnt/ssd1/arakoon/sas-back-abm/tlogs"; head_dir = "/mnt/ssd1/arakoon/sas-back-abm/tlogs"; log_level = "info"; log_config = None; batched_transaction_config = None; lease_period = 10; master = "Elected"; is_laggy = false; is_learner = false; is_witness = false; targets = []; compressor = Snappy; fsync = true; is_test = false; reporting = 300; _fsync_tlog_dir = true; node_tls = None; collapse_slowdown = None; head_copy_throttling = 0.; optimize_db_slowdown = 0. }; { node_name = "3MHjJSpuV1GRFJPJ"; ips = ["192.168.0.33"]; client_port = 26408; messaging_port = 26409; home = "/mnt/ssd1/arakoon/sas-back-abm/db"; tlog_dir = "/mnt/ssd1/arakoon/sas-back-abm/tlogs"; log_sinks = [Console]; crash_log_sinks = [File(console:)]; tlx_dir = "/mnt/ssd1/arakoon/sas-back-abm/tlogs"; head_dir = "/mnt/ssd1/arakoon/sas-back-abm/tlogs"; log_level = "info"; log_config = None; batched_transaction_config = None; lease_period = 10; master = "Elected"; is_laggy = false; is_learner = false; is_witness = false; targets = []; compressor = Snappy; fsync = true; is_test = false; reporting = 300; _fsync_tlog_dir = true; node_tls = None; collapse_slowdown = None; head_copy_throttling = 0.; optimize_db_slowdown = 0. }; { node_name = "IqXn44EwnGDSnQrd"; ips = ["192.168.0.35"]; client_port = 26408; messaging_port = 26409; home = "/mnt/ssd1/arakoon/sas-back-abm/db"; tlog_dir = "/mnt/ssd1/arakoon/sas-back-abm/tlogs"; log_sinks = [Console]; crash_log_sinks = [File(console:)]; tlx_dir = "/mnt/ssd1/arakoon/sas-back-abm/tlogs"; head_dir = "/mnt/ssd1/arakoon/sas-back-abm/tlogs"; log_level = "info"; log_config = None; batched_transaction_config = None; lease_period = 10; master = "Elected"; is_laggy
Jul 09 13:59:52 node3 arakoon[20625]: = false; is_learner = false; is_witness = false; targets = []; compressor = Snappy; fsync = true; is_test = false; reporting = 300; _fsync_tlog_dir = true; node_tls = None; collapse_slowdown = None; head_copy_throttling = 0.; optimize_db_slowdown = 0. }]; log_cfgs = []; batched_transaction_cfgs = []; _master = Elected; _lease_period = 10; cluster_id = "sas-back-abm"; plugins = ["albamgr_plugin"]; nursery_cfg = None; tlog_max_entries = 5000; tlog_max_size = 33554432; max_value_size = 8388608; max_buffer_size = 33554432; client_buffer_capacity = 32; lcnum = 16384; ncnum = 8192; tls = None }
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 042859 +0800 - node3 - 20625/0000 - arakoon - 6 - info - Batched_store.max_entries = 100
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 042866 +0800 - node3 - 20625/0000 - arakoon - 7 - info - Batched_store.max_size = 100000
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 042877 +0800 - node3 - 20625/0000 - arakoon - 8 - info - autofix:true
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 042885 +0800 - node3 - 20625/0000 - arakoon - 9 - info - loading plugin albamgr_plugin
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 042893 +0800 - node3 - 20625/0000 - arakoon - 10 - info - qualified as: /mnt/ssd1/arakoon/sas-back-abm/db/albamgr_plugin.cmxs
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 058320 +0800 - node3 - 20625/0000 - arakoon - 11 - info - albamgr_plugin (1,3,25) git_revision:heads/master-0-ge43faca-dirty
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 058358 +0800 - node3 - 20625/0000 - arakoon - 12 - info - Cluster not part of nursery.
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 058408 +0800 - node3 - 20625/0000 - arakoon - 13 - info - cfg = { node_name = "IqXn44EwnGDSnQrd"; ips = ["192.168.0.35"]; client_port = 26408; messaging_port = 26409; home = "/mnt/ssd1/arakoon/sas-back-abm/db"; tlog_dir = "/mnt/ssd1/arakoon/sas-back-abm/tlogs"; log_sinks = [Console]; crash_log_sinks = [File(console:)]; tlx_dir = "/mnt/ssd1/arakoon/sas-back-abm/tlogs"; head_dir = "/mnt/ssd1/arakoon/sas-back-abm/tlogs"; log_level = "info"; log_config = None; batched_transaction_config = None; lease_period = 10; master = "Elected"; is_laggy = false; is_learner = false; is_witness = false; targets = []; compressor = Snappy; fsync = true; is_test = false; reporting = 300; _fsync_tlog_dir = true; node_tls = None; collapse_slowdown = None; head_copy_throttling = 0.; optimize_db_slowdown = 0. }
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 058486 +0800 - node3 - 20625/0000 - arakoon - 14 - info - other: XHGfO1fHVDeRKHxa
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 058505 +0800 - node3 - 20625/0000 - arakoon - 15 - info - other: 3MHjJSpuV1GRFJPJ
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 058517 +0800 - node3 - 20625/0000 - arakoon - 16 - info - quorum_function gives 2 for 3
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 058527 +0800 - node3 - 20625/0000 - arakoon - 17 - info - DAEMONIZATION=false
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 058543 +0800 - node3 - 20625/0000 - arakoon - 18 - info - open_tlog_collection_and_store ~autofix:true
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 058566 +0800 - node3 - 20625/0000 - arakoon - 19 - info - Unlinking "/mnt/ssd1/arakoon/sas-back-abm/db/touch-20625"
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 058620 +0800 - node3 - 20625/0000 - arakoon - 20 - info - Unlink of "/mnt/ssd1/arakoon/sas-back-abm/db/touch-20625" failed with ENOENT
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 059048 +0800 - node3 - 20625/0000 - arakoon - 21 - info - Unlinking "/mnt/ssd1/arakoon/sas-back-abm/db/touch-20625"
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 059132 +0800 - node3 - 20625/0000 - arakoon - 22 - info - Unlinking "/mnt/ssd1/arakoon/sas-back-abm/tlogs/touch-20625"
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 059171 +0800 - node3 - 20625/0000 - arakoon - 23 - info - Unlink of "/mnt/ssd1/arakoon/sas-back-abm/tlogs/touch-20625" failed with ENOENT
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 059915 +0800 - node3 - 20625/0000 - arakoon - 24 - info - Unlinking "/mnt/ssd1/arakoon/sas-back-abm/tlogs/touch-20625"
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 059983 +0800 - node3 - 20625/0000 - arakoon - 25 - info - Unlinking "/mnt/ssd1/arakoon/sas-back-abm/tlogs/touch-20625"
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 060023 +0800 - node3 - 20625/0000 - arakoon - 26 - info - Unlink of "/mnt/ssd1/arakoon/sas-back-abm/tlogs/touch-20625" failed with ENOENT
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 060686 +0800 - node3 - 20625/0000 - arakoon - 27 - info - Unlinking "/mnt/ssd1/arakoon/sas-back-abm/tlogs/touch-20625"
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 060748 +0800 - node3 - 20625/0000 - arakoon - 28 - info - Unlinking "/mnt/ssd1/arakoon/sas-back-abm/tlogs/touch-20625"
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 060772 +0800 - node3 - 20625/0000 - arakoon - 29 - info - Unlink of "/mnt/ssd1/arakoon/sas-back-abm/tlogs/touch-20625" failed with ENOENT
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 061426 +0800 - node3 - 20625/0000 - arakoon - 30 - info - Unlinking "/mnt/ssd1/arakoon/sas-back-abm/tlogs/touch-20625"
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 061525 +0800 - node3 - 20625/0000 - arakoon - 31 - info - copy_file /mnt/ssd1/arakoon/sas-back-abm/tlogs/head.db /mnt/ssd1/arakoon/sas-back-abm/db/IqXn44EwnGDSnQrd.db (overwrite=false,throttling=0.000000) buffer_size:1048576
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 061568 +0800 - node3 - 20625/0000 - arakoon - 32 - info - Not copying /mnt/ssd1/arakoon/sas-back-abm/tlogs/head.db to /mnt/ssd1/arakoon/sas-back-abm/db/IqXn44EwnGDSnQrd.db because target already exists
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 061594 +0800 - node3 - 20625/0000 - arakoon - 33 - info - _init ~check_marker:true ~check_sabotage:true
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 064886 +0800 - node3 - 20625/0000 - arakoon - 34 - info - tlog_number:37613
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 648783 +0800 - node3 - 20625/0000 - arakoon - 35 - warning - AUTOFIX: improperly closed tlog: Tlog_map.TLCNotProperlyClosed(_)
Jul 09 13:59:52 node3 arakoon[20625]: 2019-07-09 13:59:52 648828 +0800 - node3 - 20625/0000 - arakoon - 36 - info - Unlinking "/mnt/ssd1/arakoon/sas-back-abm/db/IqXn44EwnGDSnQrd.db"
Jul 09 13:59:52 node3 arakoon[20625]: 188047351:0
Jul 09 13:59:52 node3 arakoon[20625]: 188047352:146
Jul 09 13:59:52 node3 arakoon[20625]: 188047353:289
Jul 09 13:59:52 node3 arakoon[20625]: 188047354:338

Best regards, Yongsheng