# Curator - DeleteSnapshots - Not fully functional **URL:** \ **Category:** Elasticsearch\ **Created:** [June 6, 2018, 12:43am UTC](https://discuss.elastic.co/t/curator-deletesnapshots-not-fully-functional/134710 "2018-06-06T00:43:17Z")\ **Posts on this page:** 14\ **Page:** 1
**Author:** ![Karthik\_Ramachandran](https://avatars.discourse-cdn.com/v4/letter/k/f19dbf/32.png) [@Karthik\_Ramachandran](https://discuss.elastic.co/u/Karthik_Ramachandran)\ **Post date:** [June 6, 2018, 12:43am UTC](https://discuss.elastic.co/t/curator-deletesnapshots-not-fully-functional/134710/1 "2018-06-06T00:43:17Z")
Environment: Curator 5.5.1, Elastic Search 6.2.1 Trying to use delete\_snapshots actions using curator, but it fails with below error always 2018-06-05 23:26:03,003 DEBUG curator.utils iterate\_filters:528 Post-instance: [list of snapshots.........] 2018-06-05 23:26:03,003 DEBUG curator.cli process\_action:99 Doing the action here. 2018-06-05 23:26:03,003 INFO curator.actions.delete\_snapshots do\_action:991 Deleting selected snapshots 2018-06-05 23:26:03,587 INFO curator.actions.delete\_snapshots do\_action:1000 Deleting snapshot \<\\> 2018-06-05 23:41:03,590 ERROR curator.cli run:184 Failed to complete action: delete\_snapshots. \: Exception encountered. Rerun with loglevel DEBUG and/or check Elasticsearch logs for more information. Exception: ConnectionTimeout caused by - ReadTimeoutError(HTTPSConnectionPool(host='-------', port=9200): Read timed out. (read timeout=900)) timeout\_override is 900 against the default 300. The action has couple of filters to filter snapshots based on regex and age. Looking at curator debug log, it finally lands up with the list of snapshots after applying filter. Then it loops thru' the list and issues delete snapshot for the first item. Post that it hangs and doesn't move forward with rest. Thought it is a timeout issue and increased to 900, but no result. Once the timeout overruns, it errors, but do see the first snapshot in the list is deleted successfully. When the curator was performing the action, monitored ES using \_tasks API. It did list the delete snapshot task for the first item, which was well done within ~5 mts (300 sec). The curator should have started with next, but it never did. The \_task API didn't list any delete snapshot action until the timer (900) overruns. Any thoughts/guidance is appreciated. Looked at curator code cli.py, but the log comes out from catch-all (logger.error). ---
**Author:** ![theuntergeek](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/theuntergeek/32/44961_2.png) [@theuntergeek](https://discuss.elastic.co/u/theuntergeek)\ **Post date:** [June 6, 2018, 1:29pm UTC](https://discuss.elastic.co/t/curator-deletesnapshots-not-fully-functional/134710/2 "2018-06-06T13:29:58Z")
> [@Karthik\_Ramachandran](#): > > Curator 5.5.1 Curator is at 5.5.4 now, and there have definitely been some improvements since then. As for what's going on in that wait period, more logging is necessary. Set `blacklist: []` in the client config under the `logging` section, and set `loglevel: debug`. The default hides the `elasticsearch` and `urllib3` responses, and those settings will unhide them, as well as add debug-level logging to what's happening inside Curator during that time period. ---
**Author:** ![Karthik\_Ramachandran](https://avatars.discourse-cdn.com/v4/letter/k/f19dbf/32.png) [@Karthik\_Ramachandran](https://discuss.elastic.co/u/Karthik_Ramachandran)\ **Post date:** [June 6, 2018, 8:13pm UTC](https://discuss.elastic.co/t/curator-deletesnapshots-not-fully-functional/134710/3 "2018-06-06T20:13:43Z")
Hi Aaron.. Thanks for the comment. Yup! I should have removed the entries from blacklist to get more info. Below is the log I see once apply empty blacklisting. 2018-06-06 18:32:39,854 INFO curator.actions.delete\_snapshots do\_action:1000 Deleting snapshot \<\>... 2018-06-06 18:32:39,854 DEBUG urllib3.util.retry from\_int:200 Converted retries value: False -\> Retry(total=False, connect=None, read=None, redirect=0, status=None) 2018-06-06 18:47:39,939 WARNING elasticsearch log\_request\_fail:97 DELETE https://-----:9200/\_snapshot/\<\>/\<\> [status:N/A request:900.085s] Traceback (most recent call last): File "/home/buh/.local/lib/python3.6/site-packages/urllib3/connectionpool.py", line 387, in \_make\_request File "", line 2, in raise\_from File "/home/buh/.local/lib/python3.6/site-packages/urllib3/connectionpool.py", line 383, in \_make\_request File "/usr/local/lib/python3.6/http/client.py", line 1331, in getresponse File "/usr/local/lib/python3.6/http/client.py", line 297, in begin File "/usr/local/lib/python3.6/http/client.py", line 258, in \_read\_status File "/usr/local/lib/python3.6/socket.py", line 586, in readinto File "/usr/local/lib/python3.6/ssl.py", line 1009, in recv\_into File "/usr/local/lib/python3.6/ssl.py", line 871, in read File "/usr/local/lib/python3.6/ssl.py", line 631, in read socket.timeout: The read operation timed out During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/home/buh/.local/lib/python3.6/site-packages/elasticsearch/connection/http\_urllib3.py", line 115, in perform\_request File "/home/buh/.local/lib/python3.6/site-packages/urllib3/connectionpool.py", line 639, in urlopen File "/home/buh/.local/lib/python3.6/site-packages/urllib3/util/retry.py", line 333, in increment File "/home/buh/.local/lib/python3.6/site-packages/urllib3/packages/six.py", line 686, in reraise File "/home/buh/.local/lib/python3.6/site-packages/urllib3/connectionpool.py", line 601, in urlopen File "/home/buh/.local/lib/python3.6/site-packages/urllib3/connectionpool.py", line 389, in \_make\_request File "/home/buh/.local/lib/python3.6/site-packages/urllib3/connectionpool.py", line 309, in \_raise\_timeout urllib3.exceptions.ReadTimeoutError: HTTPSConnectionPool(host='-------', port=9200): Read timed out. (read timeout=900) Observation 1. Delete on snapshot is issued, but the code call es api on the snapshot that is removed. This would not return any valid value. 2. Also looking at the log, the code calls \_task api even before executing delete snapshot. Not sure what the reason would be as the snapshot delete action would not be part of result (as observed in log). 3. Also observed ../snapshot/repo/\_all is called multiple times (atleast twice ) before filtering and after filtering. Not sure why. If we have lot of snapshots, it will end-up listing all Regardless the core issue could be on observation 1, as the loop sequence doesn't pick-up next snapshot. Any guidance would be helpful. ---
**Author:** ![theuntergeek](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/theuntergeek/32/44961_2.png) [@theuntergeek](https://discuss.elastic.co/u/theuntergeek)\ **Post date:** [June 6, 2018, 9:19pm UTC](https://discuss.elastic.co/t/curator-deletesnapshots-not-fully-functional/134710/4 "2018-06-06T21:19:29Z")
> [@Karthik\_Ramachandran](#): > > 1. Delete on snapshot is issued, but the code call es api on the snapshot that is removed. This would not return any valid value. Huh? The code in question is [here](https://github.com/elastic/curator/blob/v5.5.4/curator/actions.py#L1002-L1008): ```auto try: for s in self.snapshot_list.snapshots: self.loggit.info('Deleting snapshot {0}...'.format(s)) self.client.snapshot.delete( repository=self.repository, snapshot=s) except Exception as e: utils.report_failure(e) ``` Before it does this, it checks _once_ to see if it is [safe to delete a snapshot](https://github.com/elastic/curator/blob/v5.5.4/curator/utils.py#L1037-L1067). It does not check this for each snapshot. The flow is as follows, by the log lines (using the 5.5.1 tag, since that's what you're using, and your log lines reflect): ```auto 2018-06-05 23:26:03,003 INFO curator.actions.delete_snapshots do_action:991 Deleting selected snapshots ``` Line [991](https://github.com/elastic/curator/blob/v5.5.1/curator/actions.py#L991) is: ```auto self.loggit.info('Deleting selected snapshots') ``` The next step is [line 992](https://github.com/elastic/curator/blob/v5.5.1/curator/actions.py#L992) which checks to see if it is safe to take a snapshot (or in this case delete one) by verifying there are no snapshots currently in progress. This part [does check the \_tasks API](https://github.com/elastic/curator/blob/v5.5.1/curator/utils.py#L1037-L1067). Technically this is unnecessary, as the standard exception would result, but I test manually first so I can properly log it. That's all this step does. Having established that it is safe to delete a snapshot, Curator then [loops through each snapshot and deletes them one at a time.](https://github.com/elastic/curator/blob/v5.5.1/curator/actions.py#L998-L1004). This correlates with log line: ```auto 2018-06-05 23:26:03,587 INFO curator.actions.delete_snapshots do_action:1000 Deleting snapshot ``` > [@Karthik\_Ramachandran](#): > > 1. Also observed ../snapshot/repo/\_all is called multiple times (atleast twice ) before filtering and after filtering. Not sure why. If we have lot of snapshots, it will end-up listing all This redundancy will hopefully be addressed in a future release of Curator. It's mostly checking to see if something has changed from initial execution, i.e. new snapshots. > [@Karthik\_Ramachandran](#): > > Regardless the core issue could be on observation 1, as the loop sequence doesn't pick-up next snapshot. I respectfully disagree with that conclusion. The loop _will not_ pick up the next snapshot until ```auto self.client.snapshot.delete(repository=self.repository, snapshot=s) ``` ...has returned. The problem is that it is not returning, and I can't explain why. It's a very simple call, and it normally returns almost immediately. Curator has been around for many years, and is production tested by many users, beyond the CI testing that it goes through for each build iteration. As I have not seen the behavior you're describing reported by any other users, I cannot accept the idea that the code is the issue here. There is nothing that checks and waits for a snapshot to delete to finish _except_ for that call returning. As this works for everyone else, I have to suspect something in your environment isn't letting it complete. My first suspect is something repository related. What kind of repository are you using? Have you looked at the Elasticsearch logs to see what the interaction between Elasticsearch and the shared filesystem is? This is the next place I would look to troubleshoot. ---
**Author:** ![Karthik\_Ramachandran](https://avatars.discourse-cdn.com/v4/letter/k/f19dbf/32.png) [@Karthik\_Ramachandran](https://discuss.elastic.co/u/Karthik_Ramachandran)\ **Post date:** [June 6, 2018, 9:50pm UTC](https://discuss.elastic.co/t/curator-deletesnapshots-not-fully-functional/134710/5 "2018-06-06T21:50:39Z")
> [@theuntergeek](#): > > ing. As this works for everyone else, I have to suspect something in your environment isn't letting it complete. Hi Aaron, Thanks for response. We are using Azure storage for storing snapshots. I'm yet to look at ES logs as I see the snapshot process moving on successfully. Only the delete snapshot action fails. " It's a very simple call, and it normally returns almost immediately" -- Yes, but I'm concerned on what property or condition would impact this? Is there any chance that the snapshot metadata size returned by \_all on snapshot API impact this? If this is the case, the code did call the API twice and was successful. When I use elastic delete snapshot for a given (Single) snapshot using using "Dev Tool", it fails on timeout from UI perspective, but the DELETE runs in background and clean's up the snapshot in 5-6 minutes. I believe the case is same here. Should we use \_task API to monitor the snapshot delete task progress, and loop to next? Also, please refer to WARNING @ 2018-06-06 18:47:39,93 log\_request\_fail:97. The time is post 900sec timeout than the actual delete snapshot call @2018-06-06 18:32:39,854 for the same snapshot. The GET should be returning 404, snapshot not found, and logged as WARNING. But the trace comes immediately after that. ---
**Author:** ![theuntergeek](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/theuntergeek/32/44961_2.png) [@theuntergeek](https://discuss.elastic.co/u/theuntergeek)\ **Post date:** [June 6, 2018, 10:13pm UTC](https://discuss.elastic.co/t/curator-deletesnapshots-not-fully-functional/134710/6 "2018-06-06T22:13:36Z")
> [@Karthik\_Ramachandran](#): > > Yes, but I'm concerned on what property or condition would impact this? None. It's exclusively upstream in this case. I wish I had good news for you, but Azure has been a bit suspect with its behavior as a snapshot repository. Users have frequently had to employ the [`skip_repo_fs_check`](https://www.elastic.co/guide/en/elasticsearch/client/curator/5.5/option_skip_fsck.html) option as Azure fs often did not respond in a timely enough fashion for this check to work. > [@Karthik\_Ramachandran](#): > > Is there any chance that the snapshot metadata size returned by \_all on snapshot API impact this? No. No chance at all, because those calls are quite complete before a single delete is ever attempted. And they are not called again during the delete loop. > [@Karthik\_Ramachandran](#): > > When I use elastic delete snapshot for a given (Single) snapshot using using "Dev Tool", it fails on timeout from UI perspective, but the DELETE runs in background and clean's up the snapshot in 5-6 minutes. I believe the case is same here. I agree 100%. The huge problem for me is the _"it fails on timeout from UI perspective,"_ part. If it fails in Console, what makes you think it will be successful anywhere else? This is a huge red flag. This call should _never_ timeout in Console, or take longer than 30 seconds. In rare cases, I expect up to 3 minutes (the new `timeout_override` for `delete_snapshots` is 180 seconds, if I recall correctly). However, these are outliers. That your cluster + repo fs cannot delete a snapshot within 900 seconds is an indicator that there is a problem somewhere. > [@Karthik\_Ramachandran](#): > > Should we use \_task API to monitor the snapshot delete task progress, and loop to next? This solution would only address this use case, which is—as previously mentioned—exceptionally rare. You're the only user to ever report this behavior to me. I think the issue is between Elasticsearch and your Azure repository, rather than within Curator. The evidence supporting this conclusion is that that Console is timing out for you in exactly the same way. ---
**Author:** ![theuntergeek](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/theuntergeek/32/44961_2.png) [@theuntergeek](https://discuss.elastic.co/u/theuntergeek)\ **Post date:** [June 6, 2018, 10:46pm UTC](https://discuss.elastic.co/t/curator-deletesnapshots-not-fully-functional/134710/7 "2018-06-06T22:46:41Z")
Out of curiosity, what is your [`cloud.azure.storage.timeout`](https://www.elastic.co/guide/en/elasticsearch/plugins/6.2/repository-azure-usage.html) set to? ---
**Author:** ![Karthik\_Ramachandran](https://avatars.discourse-cdn.com/v4/letter/k/f19dbf/32.png) [@Karthik\_Ramachandran](https://discuss.elastic.co/u/Karthik_Ramachandran)\ **Post date:** [June 7, 2018, 6:50pm UTC](https://discuss.elastic.co/t/curator-deletesnapshots-not-fully-functional/134710/8 "2018-06-07T18:50:00Z")
> [@theuntergeek](#): > > Out of curiosity, what is your [`cloud.azure.storage.timeout`](https://www.elastic.co/guide/en/elasticsearch/plugins/6.2/repository-azure-usage.html) set to? Hi Aaron, We haven't set it explicitly, and left it to default. It should be 5 mts as read from documentation. Also, trying to understand the impact of skip\_repo\_fs\_check w.r.t delete\_snapshot action, but not able to find references in elastic api. Because the plugin doesn't provide a option for this. May be I'm missing. [API Documentation — Elasticsearch 8.0.0 documentation](http://elasticsearch-py.readthedocs.io/en/master/api.html#snapshot). Is it a check from curator? Please clarify ---
**Author:** ![theuntergeek](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/theuntergeek/32/44961_2.png) [@theuntergeek](https://discuss.elastic.co/u/theuntergeek)\ **Post date:** [June 7, 2018, 8:10pm UTC](https://discuss.elastic.co/t/curator-deletesnapshots-not-fully-functional/134710/9 "2018-06-07T20:10:01Z")
The name `skip_repo_fs_check` is what Curator uses for the [repository verification](https://www.elastic.co/guide/en/elasticsearch/reference/6.2/modules-snapshots.html#_repository_verification) API call to Elasticsearch. It is not used for snapshot deletions, but was mentioned because you're using Azure, and that has been known to be more slow to respond as a snapshot repository. Curator wants to ensure that all nodes are properly connected to the shared file system before performing actions (creating a snapshot, specifically), so that there are no unexpected surprises. It uses this API call to do so. Ordinarily, it takes a moment to test this, but on some network file shares—notably S3 and Azure—it can take just long enough that the verify call comes back with a negative result, even though it still works for snapshots. ---
**Author:** ![Karthik\_Ramachandran](https://avatars.discourse-cdn.com/v4/letter/k/f19dbf/32.png) [@Karthik\_Ramachandran](https://discuss.elastic.co/u/Karthik_Ramachandran)\ **Post date:** [June 7, 2018, 9:10pm UTC](https://discuss.elastic.co/t/curator-deletesnapshots-not-fully-functional/134710/10 "2018-06-07T21:10:34Z")
Got it. But, the issue here is on delete\_snapshots so we don't need to set it right? Please confirm. I don't see any issues with snapshot though. If we leave skip\_repo\_fs\_check aside for delete snapshot as it is not applicable, the only choice would be to refer to elastic logs! Any other things that I should be able to check. I monitored Azure Storage metrics and when the delete operation is performing, I do see the transactions. It should represent clean-up of files/file references. It co-relates to the delete action of first indice. Also, the task is living for the same duration as I see the metrics in Azure. If the dev tools is getting timeout error (below), the same is anticipated here. Agreed. Would it be due to any setting on the n/w. Probably at n/w routing level? Because ES runs behind and ensures that the snapshot is removed. { "statusCode": 504, "error": "Gateway Time-out", "message": "Client request timeout" } Is the timeout on ES-Curator/ES Dev Tool (or) Storage to ES. If it is the second case (Storage to ES), the deletion itself should fail. So I may need to check the routing between ES and its client. ---
**Author:** ![theuntergeek](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/theuntergeek/32/44961_2.png) [@theuntergeek](https://discuss.elastic.co/u/theuntergeek)\ **Post date:** [June 7, 2018, 9:25pm UTC](https://discuss.elastic.co/t/curator-deletesnapshots-not-fully-functional/134710/11 "2018-06-07T21:25:37Z")
> [@Karthik\_Ramachandran](#): > > But, the issue here is on delete\_snapshots so we don't need to set it right? That is correct. > [@Karthik\_Ramachandran](#): > > { > "statusCode": 504, > "error": "Gateway Time-out", > "message": "Client request timeout" > } Is that in Kibana? Or is that in the Elasticsearch logs? I recommend an appeal directly to the Elasticsearch logs. Kibana is a sort of proxy/backend, so I'm not sure how much to read into the 504 here. The direct feed from Elasticsearch will prove more helpful, I believe. The client-\>Elasticsearch is timing out because (and this is my belief) there is too much lag between Elasticsearch and Azure. ---
**Author:** ![Karthik\_Ramachandran](https://avatars.discourse-cdn.com/v4/letter/k/f19dbf/32.png) [@Karthik\_Ramachandran](https://discuss.elastic.co/u/Karthik_Ramachandran)\ **Post date:** [June 7, 2018, 9:32pm UTC](https://discuss.elastic.co/t/curator-deletesnapshots-not-fully-functional/134710/12 "2018-06-07T21:32:51Z")
> [@theuntergeek](#): > > Is that in Kibana? Or is that in the Elasticsearch logs? It is from Kibana--Dev Tools > [@theuntergeek](#): > > The client-\>Elasticsearch is timing out because (and this is my belief) there is too much lag between Elasticsearch and Azure. The timeout setting that is given (900 Sec) is for client to elastic is my understand. Moreover, ES was successfully deleting the snapshot after 5 minutes. It is well within the 900s timeout setting. Also, if I leave the timeout to default ES completes its task. Will look into ES logs. Hopefully I can monitor only the node represented by snapshot delete task. Have 30 nodes..so don't want to monitor logs on all nodes 🙂 ---
**Author:** ![theuntergeek](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/theuntergeek/32/44961_2.png) [@theuntergeek](https://discuss.elastic.co/u/theuntergeek)\ **Post date:** [June 7, 2018, 9:45pm UTC](https://discuss.elastic.co/t/curator-deletesnapshots-not-fully-functional/134710/13 "2018-06-07T21:45:32Z")
Your starting place should be the node that Curator and/or Kibana connect to. ---
**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\ **Post date:** [July 5, 2018, 9:45pm UTC](https://discuss.elastic.co/t/curator-deletesnapshots-not-fully-functional/134710/14 "2018-07-05T21:45:51Z")
This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.