canonical / canonical/cloud-init

Cloud-init Hangs on System Time Change When Datasource is Unreachable

Open
#5,285 3 comments 0 reactions 0 assignees View on GitHub
ds: ec2 fixed in main
Dominant language
Python
Stars
3.8k
Forks
1.1k
Avg merge
2d 23h
Merged PRs (30d)
18

Description

# Bug report
Cloud-init hangs indefinitely during the initialization process when trying to access an unreachable datasource (like Ec2). This issue is observed when there is a significant system time change combined with a datasource that is configured with specific timeout and max_wait settings. The process attempts to connect multiple times due to the datasource being unreachable, eventually leading to a timeout error each time.

## Steps to reproduce the problem
1. Configure the datasource settings in cloud-init to have short timeout and max_wait values as follows:
datasource:
Ec2:
timeout: 5
max_wait: 10
CloudStack:
timeout: 5
max_wait: 10
ssh_pwauth: yes

2. Set up a virtual machine with cloud-init enabled and this configuration applied.
3. Simulate a datasource unavailability (e.g., by using firewall rules to block access to the EC2 metadata IP 169.254.169.254).
4. Trigger a cloud-init start with a significant system time change during the initial boot sequence.
5. bserve that cloud-init attempts to access the datasource and fails, repeating the connection attempts until the max_wait time is exhausted.

## Environment details
- Cloud-init version: v21.4
- Operating System Distribution: openEuler 22.03 LTS SP1 (RHEL)
- Cloud provider, platform or installer type: vmware

## cloud-init logs
2024-05-11 17:33:55,725 - dmi.py[DEBUG]: querying dmi data /sys/class/dmi/id/product_name
2024-05-11 17:33:55,726 - DataSourceEc2.py[DEBUG]: strict_mode: warn, cloud_name=no-ec2-metadata cloud_platform=ec2
2024-05-11 17:33:55,726 - __init__.py[DEBUG]: Datasource DataSourceAliYun not updated for events: boot-new-instance
2024-05-11 17:33:55,726 - handlers.py[DEBUG]: finish: init-network/search-AliYun: SUCCESS: no network data found from DataSourceAliYun
2024-05-11 17:33:55,726 - handlers.py[DEBUG]: start: init-network/search-Ec2: searching for network data from DataSourceEc2
2024-05-11 17:33:55,727 - __init__.py[DEBUG]: Seeing if we can get any data from
2024-05-11 17:33:55,727 - __init__.py[DEBUG]: Update datasource metadata and network config due to events: boot-new-instance
2024-05-11 17:33:55,727 - util.py[DEBUG]: Reading from /sys/hypervisor/uuid (quiet=False)
2024-05-11 17:33:55,727 - dmi.py[DEBUG]: querying dmi data /sys/class/dmi/id/product_uuid
2024-05-11 17:33:55,728 - dmi.py[DEBUG]: querying dmi data /sys/class/dmi/id/product_serial
2024-05-11 17:33:55,728 - dmi.py[DEBUG]: querying dmi data /sys/class/dmi/id/chassis_asset_tag
2024-05-11 17:33:55,728 - dmi.py[DEBUG]: querying dmi data /sys/class/dmi/id/sys_vendor
2024-05-11 17:33:55,728 - DataSourceEc2.py[DEBUG]: strict_mode: warn, cloud_name=unknown cloud_platform=ec2
2024-05-11 17:33:58,424 - util.py[DEBUG]: Resolving URL: http://169.254.169.254 took 2.696 seconds
2024-05-11 17:33:58,554 - util.py[DEBUG]: Resolving URL: http://instance-data.:8773 took 0.129 seconds
2024-05-11 17:33:58,555 - DataSourceEc2.py[DEBUG]: Removed the following from metadata urls: ['http://instance-data.:8773']
2024-05-11 17:33:58,555 - url_helper.py[DEBUG]: [0/1] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0} configuration
2024-05-11 09:59:42,533 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [-27256/10s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-data/instance-id (Caused by ConnectTimeoutError(, 'Connection to 169.254.169.254 timed out. (connect timeout=5.0)'))]
2024-05-11 09:59:42,533 - url_helper.py[DEBUG]: Please wait 1 seconds while we wait to try again
2024-05-11 09:59:43,536 - url_helper.py[DEBUG]: [0/1] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0} configuration
2024-05-11 09:59:48,547 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [-27250/10s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-data/instance-id (Caused by ConnectTimeoutError(, 'Connection to 169.254.169.254 timed out. (connect timeout=5.0)'))]
2024-05-11 09:59:48,548 - url_helper.py[DEBUG]: Please wait 1 seconds while we wait to try again
2024-05-11 09:59:49,550 - url_helper.py[DEBUG]: [0/1] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0} configuration
2024-05-11 09:59:54,562 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [-27243/10s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-data/instance-id (Caused by ConnectTimeoutError(, 'Connection to 169.254.169.254 timed out. (connect timeout=5.0)'))]
2024-05-11 09:59:54,562 - url_helper.py[DEBUG]: Please wait 1 seconds while we wait to try again
2024-05-11 09:59:55,564 - url_helper.py[DEBUG]: [0/1] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0} configuration
2024-05-11 10:00:00,574 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [-27237/10s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-data/instance-id (Caused by ConnectTimeoutError(, 'Connection to 169.254.169.254 timed out. (connect timeout=5.0)'))]
2024-05-11 10:00:00,575 - url_helper.py[DEBUG]: Please wait 1 seconds while we wait to try again
2024-05-11 10:00:01,577 - url_helper.py[DEBUG]: [0/1] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0} configuration
2024-05-11 10:00:06,587 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [-27231/10s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-data/instance-id (Caused by ConnectTimeoutError(, 'Connection to 169.254.169.254 timed out. (connect timeout=5.0)'))]
2024-05-11 10:00:06,588 - url_helper.py[DEBUG]: Please wait 1 seconds while we wait to try again
2024-05-11 10:00:07,589 - url_helper.py[DEBUG]: [0/1] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0} configuration
2024-05-11 10:00:12,601 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [-27225/10s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-data/instance-id (Caused by ConnectTimeoutError(, 'Connection to 169.254.169.254 timed out. (connect timeout=5.0)'))]
2024-05-11 10:00:12,601 - url_helper.py[DEBUG]: Please wait 2 seconds while we wait to try again
2024-05-11 10:00:14,605 - url_helper.py[DEBUG]: [0/1] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0} configuration
2024-05-11 10:00:19,623 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [-27218/10s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-data/instance-id (Caused by ConnectTimeoutError(, 'Connection to 169.254.169.254 timed out. (connect timeout=5.0)'))]
2024-05-11 10:00:19,624 - url_helper.py[DEBUG]: Please wait 2 seconds while we wait to try again
2024-05-11 10:00:21,627 - url_helper.py[DEBUG]: [0/1] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0} configuration
2024-05-11 10:00:26,639 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [-27211/10s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-data/instance-id (Caused by ConnectTimeoutError(, 'Connection to 169.254.169.254 timed out. (connect timeout=5.0)'))]
2024-05-11 10:00:26,640 - url_helper.py[DEBUG]: Please wait 2 seconds while we wait to try again
2024-05-11 10:00:28,643 - url_helper.py[DEBUG]: [0/1] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0} configuration
2024-05-11 10:00:33,657 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [-27204/10s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-data/instance-id (Caused by ConnectTimeoutError(, 'Connection to 169.254.169.254 timed out. (connect timeout=5.0)'))]
2024-05-11 10:00:33,658 - url_helper.py[DEBUG]: Please wait 2 seconds while we wait to try again
2024-05-11 10:00:35,661 - url_helper.py[DEBUG]: [0/1] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0} configuration
2024-05-11 10:00:40,674 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [-27197/10s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-data/instance-id (Caused by ConnectTimeoutError(, 'Connection to 169.254.169.254 timed out. (connect timeout=5.0)'))]
2024-05-11 10:00:40,675 - url_helper.py[DEBUG]: Please wait 2 seconds while we wait to try again
2024-05-11 10:00:42,678 - url_helper.py[DEBUG]: [0/1] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0} configuration
2024-05-11 10:00:47,691 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [-27190/10s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-data/instance-id (Caused by ConnectTimeoutError(, 'Connection to 169.254.169.254 timed out. (connect timeout=5.0)'))]
2024-05-11 10:00:47,691 - url_helper.py[DEBUG]: Please wait 3 seconds while we wait to try again
2024-05-11 10:00:50,695 - url_helper.py[DEBUG]: [0/1] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0} configuration
2024-05-11 10:00:55,709 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [-27182/10s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-data/instance-id (Caused by ConnectTimeoutError(, 'Connection to 169.254.169.254 timed out. (connect timeout=5.0)'))]
2024-05-11 10:00:55,710 - url_helper.py[DEBUG]: Please wait 3 seconds while we wait to try again
2024-05-11 10:00:58,713 - url_helper.py[DEBUG]: [0/1] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0} configuration
2024-05-11 10:01:03,725 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [-27174/10s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-data/instance-id (Caused by ConnectTimeoutError(, 'Connection to 169.254.169.254 timed out. (connect timeout=5.0)'))]
2024-05-11 10:01:03,726 - url_helper.py[DEBUG]: Please wait 3 seconds while we wait to try again
2024-05-11 10:01:06,730 - url_helper.py[DEBUG]: [0/1] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0} configuration
2024-05-11 10:01:11,743 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [-27166/10s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-data/instance-id (Caused by ConnectTimeoutError(, 'Connection to 169.254.169.254 timed out. (connect timeout=5.0)'))]
2024-05-11 10:01:11,743 - url_helper.py[DEBUG]: Please wait 3 seconds while we wait to try again

## Additional context:
The system's time change appears to interfere with cloud-init's ability to manage its internal timers and retries, leading to prolonged hang periods without successful completion of the initialization process. As you can see, the log entries end with "request error" containes negative wait time, so that it will retry until the wait time finally goes to 10s which mease it has to wait several hours.

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.