search

aws / efs-utils

Utilities for Amazon Elastic File System (EFS)
MIT License
297 stars 190 forks source link

Mount hangs while trying to remove non-existent lock file #145

Closed Fydon closed 2 years ago

Fydon commented 2 years ago

I installed efs-utils using AWS Systems Manager. If I run sudo mount -t efs fs-X /mnt/efs/, where fs-X is replace with the real ID, it mounts successfully. If however I run sudo mount -t efs -o tls fs-X /mnt/efs/, it hangs. Therefore I changed the default logging level in /etc/amazon/efs/efs-utils.conf to debug and obtained the following:

2022-10-25 06:30:32 EDT - INFO - version=1.33.3 options={'rw': None, 'tls': None}
2022-10-25 06:30:32 EDT - DEBUG - Retrieve property region from instance metadata
2022-10-25 06:30:32 EDT - DEBUG - Skipping environment variable credential check because profile name was explicitly set.
2022-10-25 06:30:32 EDT - DEBUG - Looking for credentials via: env
2022-10-25 06:30:32 EDT - DEBUG - Looking for credentials via: assume-role
2022-10-25 06:30:32 EDT - DEBUG - Looking for credentials via: shared-credentials-file
2022-10-25 06:30:32 EDT - DEBUG - Looking for credentials via: config-file
2022-10-25 06:30:32 EDT - DEBUG - Looking for credentials via: ec2-credentials-file
2022-10-25 06:30:32 EDT - DEBUG - Looking for credentials via: boto-config
2022-10-25 06:30:32 EDT - DEBUG - Looking for credentials via: container-role
2022-10-25 06:30:32 EDT - DEBUG - Looking for credentials via: iam-role
2022-10-25 06:30:32 EDT - INFO - Starting new HTTP connection (1): 169.254.169.254
2022-10-25 06:30:32 EDT - DEBUG - "GET /latest/meta-data/iam/security-credentials/ HTTP/1.1" 200 28
2022-10-25 06:30:32 EDT - INFO - Starting new HTTP connection (1): 169.254.169.254
2022-10-25 06:30:32 EDT - DEBUG - "GET /latest/meta-data/iam/security-credentials/maintain-efs-with-ssh-access HTTP/1.1" 200 1438
2022-10-25 06:30:32 EDT - INFO - Found credentials from IAM Role: maintain-efs-with-ssh-access
2022-10-25 06:30:32 EDT - DEBUG - Loading JSON file: /usr/lib/python3/dist-packages/botocore/data/endpoints.json
2022-10-25 06:30:32 EDT - DEBUG - Loading JSON file: /usr/lib/python3/dist-packages/botocore/data/logs/2014-03-28/service-2.json
2022-10-25 06:30:32 EDT - DEBUG - Loading JSON file: /usr/lib/python3/dist-packages/botocore/data/_retry.json
2022-10-25 06:30:32 EDT - DEBUG - Registering retry handlers for service: logs
2022-10-25 06:30:32 EDT - DEBUG - Event creating-client-class.logs: calling handler <function add_generate_presigned_url at 0x7fd9f0327a60>
2022-10-25 06:30:32 EDT - DEBUG - The s3 config key is not a dictionary type, ignoring its value of: None
2022-10-25 06:30:32 EDT - DEBUG - Setting logs timeout as (60, 60)
2022-10-25 06:30:32 EDT - DEBUG - Pushing logs to log group named /aws/efs/utils in Cloudwatch.
2022-10-25 06:30:32 EDT - DEBUG - Retrieve property instanceId from instance metadata
2022-10-25 06:30:32 EDT - DEBUG - Instance metadata already retrieved in previous call, use the cached values.
2022-10-25 06:30:32 EDT - DEBUG - Making request for OperationModel(name=CreateLogGroup) (verify_ssl=True) with params: {'url': 'https://logs.us-east-1.amazonaws.com/', 'headers': {'Content-Type': 'application/x-amz-json-1.1', 'X-Amz-Target': 'Logs_20140328.CreateLogGroup', 'User-Agent': 'Botocore/1.4.70 Python/3.5.2 Linux/4.4.0-1128-aws'}, 'method': 'POST', 'body': b'{"logGroupName": "/aws/efs/utils"}', 'context': {'has_streaming_input': False, 'client_config': <botocore.config.Config object at 0x7fd9efd56828>, 'client_region': 'us-east-1'}, 'url_path': '/', 'query_string': ''}
2022-10-25 06:30:32 EDT - DEBUG - Event request-created.logs.CreateLogGroup: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7fd9efd567b8>>
2022-10-25 06:30:32 EDT - DEBUG - Calculating signature using v4 auth.
2022-10-25 06:30:32 EDT - DEBUG - CanonicalRequest:
POST
/

content-type:application/x-amz-json-1.1
host:logs.us-east-1.amazonaws.com
x-amz-date:20221025T103032Z
x-amz-security-token:X
x-amz-target:Logs_20140328.CreateLogGroup

content-type;host;x-amz-date;x-amz-security-token;x-amz-target
be3c05e99cdb18f3010d3847789c77e4c5e2143fceea23943b6c4907b1185089
2022-10-25 06:30:32 EDT - DEBUG - StringToSign:
AWS4-HMAC-SHA256
20221025T103032Z
20221025/us-east-1/logs/aws4_request
c9af5b3fcc7a2ab0dbd1554cfa5af81225e67ca644bf1359bc51a2e9e2719518
2022-10-25 06:30:32 EDT - DEBUG - Signature:
d7e54ae03643f6f31fbf8bd66dce66045eb0863e5e239e45a3ee4145c7160fcc
2022-10-25 06:30:32 EDT - DEBUG - Sending http request: <PreparedRequest [POST]>
2022-10-25 06:30:32 EDT - INFO - Starting new HTTPS connection (1): logs.us-east-1.amazonaws.com
2022-10-25 06:30:32 EDT - DEBUG - "POST / HTTP/1.1" 400 94
2022-10-25 06:30:32 EDT - DEBUG - Response headers: {'Content-Type': 'application/x-amz-json-1.1', 'x-amzn-RequestId': '6dde8310-adca-43b1-932b-d8e4c7537d36', 'Content-Length': '94', 'Date': 'Tue, 25 Oct 2022 10:30:31 GMT', 'Connection': 'close'}
2022-10-25 06:30:32 EDT - DEBUG - Response body:
b'{"__type":"ResourceAlreadyExistsException","message":"The specified log group already exists"}'
2022-10-25 06:30:32 EDT - DEBUG - Event needs-retry.logs.CreateLogGroup: calling handler <botocore.retryhandler.RetryHandler object at 0x7fd9efdc1ba8>
2022-10-25 06:30:32 EDT - DEBUG - No retry needed.
2022-10-25 06:30:32 EDT - DEBUG - Log group /aws/efs/utils already exist, {'ResponseMetadata': {'RetryAttempts': 0, 'HTTPStatusCode': 400, 'HTTPHeaders': {'Content-Type': 'application/x-amz-json-1.1', 'x-amzn-RequestId': '6dde8310-adca-43b1-932b-d8e4c7537d36', 'Content-Length': '94', 'Date': 'Tue, 25 Oct 2022 10:30:31 GMT', 'Connection': 'close'}, 'RequestId': '6dde8310-adca-43b1-932b-d8e4c7537d36'}, 'Error': {'Message': 'The specified log group already exists', 'Code': 'ResourceAlreadyExistsException'}}
2022-10-25 06:30:32 EDT - DEBUG - Making request for OperationModel(name=PutRetentionPolicy) (verify_ssl=True) with params: {'url': 'https://logs.us-east-1.amazonaws.com/', 'headers': {'Content-Type': 'application/x-amz-json-1.1', 'X-Amz-Target': 'Logs_20140328.PutRetentionPolicy', 'User-Agent': 'Botocore/1.4.70 Python/3.5.2 Linux/4.4.0-1128-aws'}, 'method': 'POST', 'body': b'{"logGroupName": "/aws/efs/utils", "retentionInDays": 14}', 'context': {'has_streaming_input': False, 'client_config': <botocore.config.Config object at 0x7fd9efd56828>, 'client_region': 'us-east-1'}, 'url_path': '/', 'query_string': ''}
2022-10-25 06:30:32 EDT - DEBUG - Event request-created.logs.PutRetentionPolicy: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7fd9efd567b8>>
2022-10-25 06:30:32 EDT - DEBUG - Calculating signature using v4 auth.
2022-10-25 06:30:32 EDT - DEBUG - CanonicalRequest:
POST
/

content-type:application/x-amz-json-1.1
host:logs.us-east-1.amazonaws.com
x-amz-date:20221025T103032Z
x-amz-security-token:X
x-amz-target:Logs_20140328.PutRetentionPolicy

content-type;host;x-amz-date;x-amz-security-token;x-amz-target
cd529d83de6de761755a300fc1563774d2211f115a1120dc3950c41f93ee9d91
2022-10-25 06:30:32 EDT - DEBUG - StringToSign:
AWS4-HMAC-SHA256
20221025T103032Z
20221025/us-east-1/logs/aws4_request
b76bff9525d94516f0e2b0802f69bec465a7d8fe8b19306f9f76a632d2193ee5
2022-10-25 06:30:32 EDT - DEBUG - Signature:
8c2bae4b5d0cca8308a5a86dd49cb6c6dee002d569dcf7e21a14884219d17bd2
2022-10-25 06:30:32 EDT - DEBUG - Sending http request: <PreparedRequest [POST]>
2022-10-25 06:30:32 EDT - INFO - Resetting dropped connection: logs.us-east-1.amazonaws.com
2022-10-25 06:30:32 EDT - DEBUG - "POST / HTTP/1.1" 200 0
2022-10-25 06:30:32 EDT - DEBUG - Response headers: {'Content-Type': 'application/x-amz-json-1.1', 'x-amzn-RequestId': 'a62885b7-c48a-4f33-a8ef-7f71632ad34e', 'Content-Length': '0', 'Date': 'Tue, 25 Oct 2022 10:30:32 GMT'}
2022-10-25 06:30:32 EDT - DEBUG - Response body:
b''
2022-10-25 06:30:32 EDT - DEBUG - Event needs-retry.logs.PutRetentionPolicy: calling handler <botocore.retryhandler.RetryHandler object at 0x7fd9efdc1ba8>
2022-10-25 06:30:32 EDT - DEBUG - No retry needed.
2022-10-25 06:30:32 EDT - DEBUG - Set cloudwatch log group retention days to 14
2022-10-25 06:30:32 EDT - DEBUG - Making request for OperationModel(name=CreateLogStream) (verify_ssl=True) with params: {'url': 'https://logs.us-east-1.amazonaws.com/', 'headers': {'Content-Type': 'application/x-amz-json-1.1', 'X-Amz-Target': 'Logs_20140328.CreateLogStream', 'User-Agent': 'Botocore/1.4.70 Python/3.5.2 Linux/4.4.0-1128-aws'}, 'method': 'POST', 'body': b'{"logGroupName": "/aws/efs/utils", "logStreamName": "fs-0590832ac4242266b - i-0f4d8b6c99009c387 - mount.log"}', 'context': {'has_streaming_input': False, 'client_config': <botocore.config.Config object at 0x7fd9efd56828>, 'client_region': 'us-east-1'}, 'url_path': '/', 'query_string': ''}
2022-10-25 06:30:32 EDT - DEBUG - Event request-created.logs.CreateLogStream: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7fd9efd567b8>>
2022-10-25 06:30:32 EDT - DEBUG - Calculating signature using v4 auth.
2022-10-25 06:30:32 EDT - DEBUG - CanonicalRequest:
POST
/

content-type:application/x-amz-json-1.1
host:logs.us-east-1.amazonaws.com
x-amz-date:20221025T103032Z
x-amz-security-token:X
x-amz-target:Logs_20140328.CreateLogStream

content-type;host;x-amz-date;x-amz-security-token;x-amz-target
da2b9c66d99ef51c6abdf37f9bc3268aa193c0418108faffdd99e8e90e5f0a27
2022-10-25 06:30:32 EDT - DEBUG - StringToSign:
AWS4-HMAC-SHA256
20221025T103032Z
20221025/us-east-1/logs/aws4_request
ecf5413fc8c32b3af48231641b9b87136eedcd9e1b6a91520eed1130b32cfbdf
2022-10-25 06:30:32 EDT - DEBUG - Signature:
1345104b690147ff467301ea5fb831988c13b72033a9b06eb9349958edf4ce3e
2022-10-25 06:30:32 EDT - DEBUG - Sending http request: <PreparedRequest [POST]>
2022-10-25 06:30:32 EDT - DEBUG - "POST / HTTP/1.1" 400 95
2022-10-25 06:30:32 EDT - DEBUG - Response headers: {'Content-Type': 'application/x-amz-json-1.1', 'x-amzn-RequestId': 'f0f3de5a-3d1a-4d26-8bfe-54a0366cc948', 'Content-Length': '95', 'Date': 'Tue, 25 Oct 2022 10:30:32 GMT', 'Connection': 'close'}
2022-10-25 06:30:32 EDT - DEBUG - Response body:
b'{"__type":"ResourceAlreadyExistsException","message":"The specified log stream already exists"}'
2022-10-25 06:30:32 EDT - DEBUG - Event needs-retry.logs.CreateLogStream: calling handler <botocore.retryhandler.RetryHandler object at 0x7fd9efdc1ba8>
2022-10-25 06:30:32 EDT - DEBUG - No retry needed.
2022-10-25 06:30:32 EDT - DEBUG - Log stream fs-0590832ac4242266b - i-0f4d8b6c99009c387 - mount.log already exist in log group /aws/efs/utils, {'ResponseMetadata': {'RetryAttempts': 0, 'HTTPStatusCode': 400, 'HTTPHeaders': {'Content-Type': 'application/x-amz-json-1.1', 'x-amzn-RequestId': 'f0f3de5a-3d1a-4d26-8bfe-54a0366cc948', 'Content-Length': '95', 'Date': 'Tue, 25 Oct 2022 10:30:32 GMT', 'Connection': 'close'}, 'RequestId': 'f0f3de5a-3d1a-4d26-8bfe-54a0366cc948'}, 'Error': {'Message': 'The specified log stream already exists', 'Code': 'ResourceAlreadyExistsException'}}
2022-10-25 06:30:32 EDT - DEBUG - Identified init system: systemd
2022-10-25 06:30:32 EDT - DEBUG - Retrieve property region from instance metadata
2022-10-25 06:30:32 EDT - DEBUG - Instance metadata already retrieved in previous call, use the cached values.
2022-10-25 06:30:32 EDT - DEBUG - Using dns_name_suffix amazonaws.com in config section [mount]
2022-10-25 06:30:32 EDT - INFO - binding 20604
2022-10-25 06:30:32 EDT - DEBUG - Retrieve property region from instance metadata
2022-10-25 06:30:32 EDT - DEBUG - Instance metadata already retrieved in previous call, use the cached values.
2022-10-25 06:30:32 EDT - DEBUG - Retrieve property region from instance metadata
2022-10-25 06:30:32 EDT - DEBUG - Instance metadata already retrieved in previous call, use the cached values.
2022-10-25 06:30:32 EDT - DEBUG - Removed /var/run/efs/efs-utils-lock successfully
2022-10-25 06:30:32 EDT - DEBUG - lock file does not exist or Bad file descriptor, The file is already removed nothing to do.
2022-10-25 06:30:32 EDT - DEBUG - Removed /var/run/efs/efs-utils-lock successfully
2022-10-25 06:30:32 EDT - DEBUG - lock file does not exist or Bad file descriptor, The file is already removed nothing to do.
2022-10-25 06:30:32 EDT - DEBUG - Removed /var/run/efs/efs-utils-lock successfully
2022-10-25 06:30:32 EDT - DEBUG - lock file does not exist or Bad file descriptor, The file is already removed nothing to do.

I've only copied 3 sets of the lines Removed /var/run/efs/efs-utils-lock successfully and lock file does not exist or Bad file descriptor, The file is already removed nothing to do. but these are actually printed in the log file many times per second over and over again for as long as I let the process run. It does not get any further. /var/run/efs/efs-utils-lock does not exist.

The stack trace that was printed out when I stopped the process was as follows:

Traceback (most recent call last):
  File "/sbin/mount.efs", line 3676, in <module>

    main()
  File "/sbin/mount.efs", line 3662, in main
    fallback_ip_address=fallback_ip_address,
  File "/sbin/mount.efs", line 2814, in mount_tls
    fallback_ip_address=fallback_ip_address,
  File "/usr/lib/python3.5/contextlib.py", line 59, in __enter__
    return next(self.gen)
  File "/sbin/mount.efs", line 1515, in bootstrap_tls
    base_path=state_file_dir,
  File "/sbin/mount.efs", line 1954, in create_certificate
    private_key = check_and_create_private_key(base_path)
  File "/sbin/mount.efs", line 2046, in check_and_create_private_key
    do_with_lock(generate_key)
  File "/sbin/mount.efs", line 2016, in do_with_lock
    return function()
  File "/sbin/mount.efs", line 2042, in generate_key
    subprocess_call(cmd, "Failed to create private key")
  File "/sbin/mount.efs", line 2165, in subprocess_call
    cmd.split(), stdout=subprocess.PIPE, stderr=subprocess.PIPE, close_fds=True
  File "/usr/lib/python3.5/subprocess.py", line 947, in __init__
    restore_signals, start_new_session)
  File "/usr/lib/python3.5/subprocess.py", line 1513, in _execute_child
    part = os.read(errpipe_read, 50000)
KeyboardInterrupt

What can I try to get EFS to mount with TLS?

Fydon commented 2 years ago

The problem was that sudo couldn't find openssl, even though root could. Fixing that solved the problem.