René's URL Explorer Experiment

{"@context":"https://schema.org","@type":"DiscussionForumPosting","headline":"`awslambdaric` prevents graceful lambda shutdown","articleBody":"# Overview\r\n\r\nI've followed the guide described in [graceful-shutdown-with-aws-lambda](https://github.com/aws-samples/graceful-shutdown-with-aws-lambda). Unfortunately, my signal handler is never invoked.\r\n\r\nI spent time investigating and it looks like the native code in `awslambdaric` is not bubbling up the signal preventing the signal handler registered from ever running. I don't have experience with writing native code python extensions, so I don't know what needs to change in `runtime_client.cpp` so that this works.\r\n\r\nThe graceful shutdown guide actually has a note at the end of the readme which says:\r\n\r\n    Please be aware that this feature does not work on Python 3.8 and 3.9 runtimes.\r\n\r\nI think this is exactly because of the issue I am describing here (and mentioned here https://github.com/aws-samples/graceful-shutdown-with-aws-lambda/issues/2).\r\n\r\n# Steps to reproduce.\r\n\r\nI took a simple lambda function `handler.py`:\r\n\r\n```py\r\nimport signal\r\nfrom types import FrameType\r\n\r\ndef shutdown(_signum: int, _frame: FrameType | None) -\u003e None:\r\n    print(\"Shutdown hook invoked\")\r\n\r\n\r\nsignal.signal(signal.SIGTERM, shutdown)\r\n\r\n\r\ndef lambda_handler(event, context):\r\n    print(f\"Handled event {event}\")\r\n\r\n    return \"SUCCESS\"\r\n```\r\n\r\nand created a lambda in `eu-central-1` with this as a zip, adding the layer `arn:aws:lambda:eu-central-1:580247275435:layer:LambdaInsightsExtension:38` and invoked it once. I waited until the instance was spun down (10-15 minutes), but there was no log from the shutdown hook.\r\n\r\nI also deployed it as a docker image with this Dockerfile:\r\n\r\n```Dockerfile\r\nFROM public.ecr.aws/lambda/python:3.10.2023.07.13.16\r\n\r\n# download manually before building the image:\r\n# curl -f -s -o lambda-insights-amd64-38.zip \"$(aws lambda get-layer-version-by-arn --arn \"arn:aws:lambda:eu-central-1:580247275435:layer:LambdaInsightsExtension:38\" --query 'Content.Location' --output text)\"\r\n\r\nCOPY lambda-insights-amd64-38.zip /tmp\r\n# hadolint ignore=DL3033\r\nRUN yum install -y unzip \u0026\u0026 unzip -q -d /opt /tmp/lambda-insights-amd64-38.zip \u0026\u0026 rm /tmp/*.zip \u0026\u0026 \\\r\n    yum history undo -y last \u0026\u0026 yum clean all \u0026\u0026 rm -rf /var/cache/yum\r\n\r\nCOPY handler.py \"$LAMBDA_TASK_ROOT/handler.py\"\r\n\r\nCMD [\"handler.lambda_handler\"]\r\n```\r\n\r\nI pushed this into ECR and then created a container-based lambda with this image again in `eu-central-1` and invoked it once. Again, I waited until the instance was spun down (10-15 minutes), but there was no log from the shutdown hook.\r\n\r\nTo prove that SIGTERM was being sent to the runtime, I altered the previous image to just be a simple shell script and updated the container-based lambda from the previous step:\r\n\r\n`startup.sh`\r\n\r\n```sh\r\n#!/usr/bin/env bash\r\n\r\nset -e\r\nset -o pipefail\r\n\r\nprintf 'Starting lambda handler. Running as pid %s\\n' \"$BASHPID\"\r\n\r\nshutdown() {\r\n  printf 'Shutting down gracefully\\n'\r\n  exit\r\n}\r\ntrap 'shutdown' SIGTERM\r\n\r\nwhile true ; do\r\n  HEADERS=\"$(mktemp)\"\r\n  BODY=\"$(mktemp)\"\r\n  curl -f -sS -LD \"$HEADERS\" -X GET \"http://$AWS_LAMBDA_RUNTIME_API/2018-06-01/runtime/invocation/next\" -o \"$BODY\"\r\n  REQUEST_ID=\"$(grep -Fi Lambda-Runtime-Aws-Request-Id \"$HEADERS\" | tr -d '[:space:]' | cut -d: -f2)\"\r\n  rm -rf \"$HEADERS\"\r\n\r\n  printf 'Processing request %s\\n' \"$REQUEST_ID\"\r\n\r\n  curl -f -sS -X POST \"http://$AWS_LAMBDA_RUNTIME_API/2018-06-01/runtime/invocation/$REQUEST_ID/response\" -d '\"SUCCESS\"'\r\n  rm -rf \"$BODY\"\r\ndone\r\n```\r\n\r\nwith this `Dockerfile`:\r\n\r\n```Dockerfile\r\nFROM public.ecr.aws/lambda/python:3.10.2023.07.13.16\r\n\r\n# download manually before building the image:\r\n# curl -f -s -o lambda-insights-amd64-38.zip \"$(aws lambda get-layer-version-by-arn --arn \"arn:aws:lambda:eu-central-1:580247275435:layer:LambdaInsightsExtension:38\" --query 'Content.Location' --output text)\"\r\n\r\nCOPY lambda-insights-amd64-38.zip /tmp\r\n# hadolint ignore=DL3033\r\nRUN yum install -y unzip \u0026\u0026 unzip -q -d /opt /tmp/lambda-insights-amd64-38.zip \u0026\u0026 rm /tmp/*.zip \u0026\u0026 \\\r\n    yum history undo -y last \u0026\u0026 yum clean all \u0026\u0026 rm -rf /var/cache/yum\r\n\r\nCOPY startup.sh \"$LAMBDA_TASK_ROOT/startup.sh\"\r\n\r\nENTRYPOINT [\"/var/runtime/startup.sh\"]\r\n```\r\n\r\nI invoked the lambda and got the `\"SUCCESS\"` response. I waited for it to spin down and checked the cloudwatch logs again:\r\n\r\n```\r\nLOGS\tName: cloudwatch_lambda_agent\tState: Subscribed\tTypes: [Platform]\r\nStarting lambda handler. Running as pid 12\r\nName: cloudwatch_lambda_agent\tState: Ready\tEvents: [INVOKE, SHUTDOWN]\r\nSTART RequestId: 1127e4c8-97e8-4ef9-9c52-e24673eb40a7 Version: $LATEST\r\nProcessing request 1127e4c8-97e8-4ef9-9c52-e24673eb40a7\r\n{\"\"status\"\":\"\"OK\"\"}\r\nEND RequestId: 1127e4c8-97e8-4ef9-9c52-e24673eb40a7\r\nREPORT RequestId: 1127e4c8-97e8-4ef9-9c52-e24673eb40a7\tDuration: 304.42 ms\tBilled Duration: 590 ms\tMemory Size: 128 MB\tMax Memory Used: 35 MB\tInit Duration: 285.31 ms\t\r\nTerminated\r\nShutting down gracefully\r\n```\r\n\r\nSuccess, so I knew that SIGTERM was being sent. After this, I suspected that it had to be somewhere in the runtime handling for python. While reading the source code for `awslambdaric` I realised part of it was written in cpp and I wondered if this might be the issue.\r\n\r\nTo test whether this was the problem, I replaced the `runtime_client` written in cpp, with one written in python.\r\n\r\n`runtime_client_py.py`\r\n\r\n```py\r\n# Reimplementation of runtime_client.cpp in python\r\n\r\nimport http\r\nimport http.client\r\nimport os\r\n\r\nlambda_runtime_address = os.environ[\"AWS_LAMBDA_RUNTIME_API\"]\r\nuser_agent = \"awslambdaric\"\r\n\r\n\r\nclass RuntimeClient:\r\n    @staticmethod\r\n    def initialize_client(user_agent: str) -\u003e None:\r\n        user_agent = user_agent\r\n\r\n    @staticmethod\r\n    def next() -\u003e tuple[bytes, dict]:\r\n        endpoint = \"/2018-06-01/runtime/invocation/next\"\r\n        runtime_connection = http.client.HTTPConnection(lambda_runtime_address)\r\n        runtime_connection.connect()\r\n\r\n        runtime_connection.request(\"GET\", endpoint, headers={\"User-Agent\": user_agent})\r\n        response = runtime_connection.getresponse()\r\n        response_body = response.read()\r\n        raw_headers = response.headers\r\n\r\n        headers = {\r\n            \"Lambda-Runtime-Aws-Request-Id\": raw_headers.get(\r\n                \"Lambda-Runtime-Aws-Request-Id\"\r\n            ),\r\n            \"Lambda-Runtime-Trace-Id\": raw_headers.get(\"Lambda-Runtime-Trace-Id\")\r\n            or None,\r\n            \"Lambda-Runtime-Invoked-Function-Arn\": raw_headers.get(\r\n                \"Lambda-Runtime-Invoked-Function-Arn\"\r\n            ),\r\n            \"Lambda-Runtime-Deadline-Ms\": int(\r\n                raw_headers.get(\"Lambda-Runtime-Deadline-Ms\") or \"0\"\r\n            ),\r\n            \"Lambda-Runtime-Client-Context\": raw_headers.get(\r\n                \"Lambda-Runtime-Client-Context\"\r\n            )\r\n            or None,\r\n            \"Lambda-Runtime-Cognito-Identity\": raw_headers.get(\r\n                \"Lambda-Runtime-Cognito-Identity\"\r\n            )\r\n            or None,\r\n            \"Content-Type\": raw_headers.get(\"Content-Type\") or None,\r\n        }\r\n\r\n        return response_body, headers\r\n\r\n    @staticmethod\r\n    def post_invocation_result(\r\n        invoke_id: str, result_data: bytes, content_type: str\r\n    ) -\u003e None:\r\n        from awslambdaric.lambda_runtime_client import LambdaRuntimeClientError\r\n\r\n        endpoint = f\"/2018-06-01/runtime/invocation/{invoke_id}/response\"\r\n        runtime_connection = http.client.HTTPConnection(lambda_runtime_address)\r\n        runtime_connection.connect()\r\n\r\n        runtime_connection.request(\r\n            \"POST\",\r\n            endpoint,\r\n            body=result_data,\r\n            headers={\"User-Agent\": user_agent, \"Content-Type\": content_type},\r\n        )\r\n\r\n        response = runtime_connection.getresponse()\r\n\r\n        if response.status != http.HTTPStatus.ACCEPTED:\r\n            raise LambdaRuntimeClientError(endpoint, response.status, None)\r\n\r\n    @staticmethod\r\n    def post_error(invoke_id: str, error_response_data: bytes, xray_fault: str) -\u003e None:\r\n        endpoint = f\"/2018-06-01/runtime/invocation/{invoke_id}/error\"\r\n        runtime_connection = http.client.HTTPConnection(lambda_runtime_address)\r\n        runtime_connection.connect()\r\n\r\n        runtime_connection.request(\r\n            \"POST\",\r\n            endpoint,\r\n            body=error_response_data,\r\n            headers={\r\n                \"User-Agent\": user_agent,\r\n                \"Content-Type\": \"application/json\",\r\n                \"Lambda-Runtime-Function-Error-Type\": \"UnhandledContent\",\r\n                \"Lambda-Runtime-Function-xray-error-cause\": xray_fault,\r\n            },\r\n        )\r\n\r\n\r\nruntime_client = RuntimeClient()\r\n```\r\n\r\nand I put this in an image with this `Dockerfile`:\r\n\r\n```Dockerfile\r\nFROM public.ecr.aws/lambda/python:3.10.2023.07.13.16\r\n\r\n# download manually before building the image:\r\n# curl -f -s -o lambda-insights-amd64-38.zip \"$(aws lambda get-layer-version-by-arn --arn \"arn:aws:lambda:eu-central-1:580247275435:layer:LambdaInsightsExtension:38\" --query 'Content.Location' --output text)\"\r\n\r\nCOPY lambda-insights-amd64-38.zip /tmp\r\n# hadolint ignore=DL3033\r\nRUN yum install -y unzip \u0026\u0026 unzip -q -d /opt /tmp/lambda-insights-amd64-38.zip \u0026\u0026 rm /tmp/*.zip \u0026\u0026 \\\r\n    yum history undo -y last \u0026\u0026 yum clean all \u0026\u0026 rm -rf /var/cache/yum\r\n\r\nRUN rm \"$LAMBDA_RUNTIME_DIR/runtime_client.cpython\"*.so \u0026\u0026 sed -i 's/import runtime_client/from awslambdaric.runtime_client import runtime_client/' \"$LAMBDA_RUNTIME_DIR/awslambdaric/lambda_runtime_client.py\"\r\nCOPY runtime_client_py.py \"$LAMBDA_RUNTIME_DIR/awslambdaric/runtime_client.py\"\r\nCOPY handler.py \"$LAMBDA_TASK_ROOT/handler.py\"\r\n\r\nCMD [\"handler.lambda_handler\"]\r\n```\r\n\r\nI updated the image used by the lambda again and invoked it and waited for it to spin back down. I checked the cloudwatch logs again:\r\n\r\n```\r\nLOGS\tName: cloudwatch_lambda_agent\tState: Subscribed\tTypes: [Platform]\r\nEXTENSION\tName: cloudwatch_lambda_agent\tState: Ready\tEvents: [INVOKE, SHUTDOWN]\r\nSTART RequestId: faab07eb-60f6-47c6-b5ba-0dced4097ec9 Version: $LATEST\r\nHandled event {'test': 'value'}\r\nEND RequestId: faab07eb-60f6-47c6-b5ba-0dced4097ec9\r\nREPORT RequestId: faab07eb-60f6-47c6-b5ba-0dced4097ec9\tDuration: 48.67 ms\tBilled Duration: 383 ms\tMemory Size: 128 MB\tMax Memory Used: 45 MB\tInit Duration: 333.96 ms\t\r\nShutdown hook invoked\r\n```\r\n\r\nSuccess! So indeed it looks like the native code needs some adjustment to handle the signal.\r\n\r\nUnfortunately, I can't offer a pull request to fix this since I don't know enough about how this works. Some searching points out that perhaps the code needs to be using [`PyErr_CheckSignals`](https://docs.python.org/3/c-api/exceptions.html#c.PyErr_CheckSignals). `awslambdaric` is also using `aws-lambda-runtime` internally, so there might be some interaction there too that needs even more handling.\r\n\r\nAnyway, I hope these reproduction steps can help someone with the skills find the correct solution.\r\n\r\nThanks.","author":{"url":"https://github.com/aclemons","@type":"Person","name":"aclemons"},"datePublished":"2023-07-18T04:46:10.000Z","interactionStatistic":{"@type":"InteractionCounter","interactionType":"https://schema.org/CommentAction","userInteractionCount":5},"url":"https://github.com/105/aws-lambda-python-runtime-interface-client/issues/105"}