aws / elastic-beanstalk-roadmap

AWS Elastic Beanstalk roadmap
https://aws.amazon.com/elasticbeanstalk/
Creative Commons Attribution Share Alike 4.0 International
283 stars 11 forks source link

PHP 8.2 and 8.3 worker instances hang on deployment #296

Open nickdnk opened 1 year ago

nickdnk commented 1 year ago

Hello

After upgrading our platform to PHP 8.2 (4.0.0), we consistently have issues with our worker environment updating only one instance and letting the other one hang indefinitely. The pipeline considers the deployment successful, but health shows this:

Screenshot 2023-08-08 at 14 34 44

Terminating the instance will launch a new one which works, which points to some kind of deployment command stalling. Rebooting the instance also works.

Relevant log from the hanging instance:

eb-engine.log


2023/08/08 12:25:50.536121 [INFO] Starting...
2023/08/08 12:25:50.536184 [INFO] Starting EBPlatform-PlatformEngine
2023/08/08 12:25:50.536205 [INFO] reading event message file
2023/08/08 12:25:50.536385 [INFO] Engine received EB command cfn-hup-exec

2023/08/08 12:25:50.593155 [INFO] Running command /bin/sh -c /opt/aws/bin/cfn-get-metadata -s arn:aws:cloudformation:eu-central-1:REDACTED:stack/awseb-e-REDACTED-stack/REDACTED -r AWSEBAutoScalingGroup --region eu-central-1
2023/08/08 12:25:50.940107 [INFO] Running command /bin/sh -c /opt/aws/bin/cfn-get-metadata -s arn:aws:cloudformation:eu-central-1:REDACTED:stack/awseb-e-REDACTED-stack/REDACTED -r AWSEBBeanstalkMetadata --region eu-central-1
2023/08/08 12:25:51.292428 [INFO] checking whether command app-deploy is applicable to this instance...
2023/08/08 12:25:51.292441 [INFO] this command is applicable to the instance, thus instance should execute command
2023/08/08 12:25:51.292444 [INFO] Engine command: (app-deploy)

2023/08/08 12:25:51.292448 [INFO] Downloading EB Application...
2023/08/08 12:25:51.292449 [INFO] Region: eu-central-1
2023/08/08 12:25:51.292451 [INFO] envID: e-REDACTED
2023/08/08 12:25:51.292453 [INFO] envBucket: elasticbeanstalk-eu-central-1-REDACTED
2023/08/08 12:25:51.292455 [INFO] Using manifest file name from command request
2023/08/08 12:25:51.292461 [INFO] Manifest name is : manifest_1691497528443
2023/08/08 12:25:51.292463 [INFO] Download app version manifest
2023/08/08 12:25:51.292642 [INFO] Downloading: bucket: elasticbeanstalk-eu-central-1-REDACTED, object: /resources/environments/e-REDACTED/_runtime/versions/manifest_1691497528443
2023/08/08 12:25:51.333365 [INFO] Download successful159bytes downloaded
2023/08/08 12:25:51.333518 [INFO] Trying to read and parse version manifest...
2023/08/08 12:25:51.335283 [INFO] Downloading: bucket: elasticbeanstalk-eu-central-1-REDACTED, object: /resources/environments/e-REDACTED/_runtime/_versions/REDACTED/code-pipeline-1691497520285-CompletedBuild-5f3065bd-2183-4592-a5ba-87bd50c7d3a4
2023/08/08 12:25:51.463792 [INFO] Download successful14790969bytes downloaded
2023/08/08 12:25:51.464030 [INFO] Executing instruction: ElectLeader
2023/08/08 12:25:51.464035 [INFO] Running leader election for instance i-062a6a8a40fc1bf41...
2023/08/08 12:25:51.464037 [INFO] Calling the cfn-elect-cmd-leader to elect the command leader.
2023/08/08 12:25:51.464048 [INFO] Running command /bin/sh -c /opt/aws/bin/cfn-elect-cmd-leader --stack arn:aws:cloudformation:eu-central-1:REDACTED:stack/awseb-e-REDACTED-stack/REDACTED --command-name ElasticBeanstalkCommand-AWSEBAutoScalingGroup --invocation-id 7a9eef3d-37b7-4880-b5f5-17cb59a28af6 --listener-id i-062a6a8a40fc1bf41 --region eu-central-1
2023/08/08 12:25:51.834020 [INFO] Instance is Leader.
2023/08/08 12:25:51.834050 [INFO] Executing instruction: stopSqsd
2023/08/08 12:25:51.834064 [INFO] Running command /bin/sh -c systemctl is-active sqsd.service
2023/08/08 12:25:51.844350 [INFO] Running command /bin/sh -c systemctl show -p PartOf sqsd.service
2023/08/08 12:25:51.855325 [INFO] Running command /bin/sh -c systemctl stop sqsd.service
2023/08/08 12:25:53.910866 [INFO] Executing instruction: PreBuildEbExtension
2023/08/08 12:25:53.910885 [INFO] Starting executing the config set Infra-EmbeddedPreBuild.
2023/08/08 12:25:53.910905 [INFO] Running command /bin/sh -c /opt/aws/bin/cfn-init -s arn:aws:cloudformation:eu-central-1:REDACTED:stack/awseb-e-REDACTED-stack/REDACTED -r AWSEBAutoScalingGroup --region eu-central-1 --configsets Infra-EmbeddedPreBuild
2023/08/08 12:25:54.294163 [INFO] Finished executing the config set Infra-EmbeddedPreBuild.

2023/08/08 12:25:54.294189 [INFO] Executing instruction: StageApplication
2023/08/08 12:25:54.346992 [INFO] extracting /opt/elasticbeanstalk/deployment/app_source_bundle to /var/app/staging/
2023/08/08 12:25:54.347042 [INFO] Running command /bin/sh -c /usr/bin/unzip -q -o /opt/elasticbeanstalk/deployment/app_source_bundle -d /var/app/staging/
2023/08/08 12:25:55.322226 [INFO] finished extracting /opt/elasticbeanstalk/deployment/app_source_bundle to /var/app/staging/ successfully
2023/08/08 12:25:55.418019 [INFO] Executing instruction: RunAppDeployPreBuildHooks
2023/08/08 12:25:55.418053 [INFO] Executing platform hooks in .platform/hooks/prebuild/
2023/08/08 12:25:55.418089 [INFO] Following scripts will be executed in order: [01_install_apcu.sh]
2023/08/08 12:25:55.418094 [INFO] Try add execution permission
2023/08/08 12:25:55.418108 [INFO] Running command /bin/sh -c file -b /var/app/staging/.platform/hooks/prebuild/01_install_apcu.sh
2023/08/08 12:25:55.422922 [INFO] Bourne-Again shell script, ASCII text executable

2023/08/08 12:25:55.422938 [INFO] Running script: .platform/hooks/prebuild/01_install_apcu.sh
2023/08/08 12:25:55.522035 [INFO] Finished running scripts in /var/app/staging/.platform/hooks/prebuild
2023/08/08 12:25:55.522047 [INFO] Executing instruction: Install composer dependencies
2023/08/08 12:25:55.522082 [INFO] vendor folder found, skip installing composer dependencies...
2023/08/08 12:25:55.522090 [INFO] Executing instruction: configure X-Ray
2023/08/08 12:25:55.522097 [INFO] X-Ray is not enabled.
2023/08/08 12:25:55.522099 [INFO] Executing instruction: configure proxy server
2023/08/08 12:25:55.558129 [INFO] Copying file /opt/elasticbeanstalk/config/private/nginx/php-fpm.conf to /var/proxy/staging/nginx/conf.d/php-fpm.conf
2023/08/08 12:25:55.559778 [WARN] skipping nginx folder under .ebextensions
2023/08/08 12:25:55.559816 [INFO] Running command /bin/sh -c cp -rp /var/app/staging/.platform/nginx/. /var/proxy/staging/nginx
2023/08/08 12:25:55.569866 [INFO] Executing instruction: configure healthd specific proxy conf
2023/08/08 12:25:55.571904 [INFO] Running command /bin/sh -c systemctl show -p PartOf healthd.service
2023/08/08 12:25:55.584328 [WARN] Warning: process healthd is already registered...
Deregistering the process ...
2023/08/08 12:25:55.584356 [INFO] Running command /bin/sh -c systemctl show -p PartOf healthd.service
2023/08/08 12:25:55.596041 [INFO] Running command /bin/sh -c systemctl is-active healthd.service
2023/08/08 12:25:55.605102 [INFO] Running command /bin/sh -c systemctl show -p PartOf healthd.service
2023/08/08 12:25:55.616338 [INFO] Running command /bin/sh -c systemctl stop healthd.service
2023/08/08 12:25:55.670474 [INFO] Running command /bin/sh -c systemctl disable healthd.service
2023/08/08 12:25:55.899376 [INFO] Removed "/etc/systemd/system/multi-user.target.wants/healthd.service".

2023/08/08 12:25:55.899550 [INFO] Running command /bin/sh -c systemctl daemon-reload
2023/08/08 12:25:56.149894 [INFO] Running command /bin/sh -c systemctl reset-failed
2023/08/08 12:25:56.161808 [INFO] Running command /bin/sh -c systemctl daemon-reload
2023/08/08 12:25:56.380418 [INFO] Running command /bin/sh -c systemctl reset-failed
2023/08/08 12:25:56.389424 [INFO] Running command /bin/sh -c systemctl is-enabled aws-eb.target
2023/08/08 12:25:56.399034 [INFO] Running command /bin/sh -c systemctl enable aws-eb.target
2023/08/08 12:25:56.632129 [INFO] Running command /bin/sh -c systemctl start aws-eb.target
2023/08/08 12:25:56.642200 [INFO] Running command /bin/sh -c systemctl enable healthd.service
2023/08/08 12:25:56.898455 [INFO] Created symlink /etc/systemd/system/multi-user.target.wants/healthd.service → /etc/systemd/system/healthd.service.

2023/08/08 12:25:56.898490 [INFO] Running command /bin/sh -c systemctl show -p PartOf healthd.service
2023/08/08 12:25:56.910197 [INFO] Running command /bin/sh -c systemctl is-active healthd.service
2023/08/08 12:25:56.919390 [INFO] Running command /bin/sh -c systemctl start healthd.service
2023/08/08 12:25:56.972704 [INFO] Copying file /opt/elasticbeanstalk/config/private/healthd/healthd_logformat.conf to /var/proxy/staging/nginx/conf.d/healthd_logformat.conf
2023/08/08 12:25:56.973760 [INFO] Copying file /opt/elasticbeanstalk/config/private/healthd/healthd_nginx.conf to /var/proxy/staging/nginx/conf.d/elasticbeanstalk/healthd.conf
2023/08/08 12:25:56.974881 [INFO] Executing instruction: configure php-fpm
2023/08/08 12:25:56.978954 [INFO] Executing instruction: configure log streaming
2023/08/08 12:25:56.978969 [INFO] start to get cloudwatch log client
2023/08/08 12:25:56.979063 [INFO] start to config log streaming
2023/08/08 12:25:56.979070 [INFO] start to configure log streaming config file
2023/08/08 12:25:56.979282 [INFO] start to create cloudwatch log stream
2023/08/08 12:25:56.979286 [INFO] start to create log streaming
2023/08/08 12:25:57.014082 [WARN] Log stream for log group /aws/elasticbeanstalk/REDACTED/var/log/eb-engine.log already exists. No need to create it.
2023/08/08 12:25:57.057467 [WARN] Log stream for log group /aws/elasticbeanstalk/REDACTED/var/log/eb-hooks.log already exists. No need to create it.
2023/08/08 12:25:57.087573 [WARN] Log stream for log group /aws/elasticbeanstalk/REDACTED/var/log/nginx/access.log already exists. No need to create it.
2023/08/08 12:25:57.114974 [WARN] Log stream for log group /aws/elasticbeanstalk/REDACTED/var/log/nginx/error.log already exists. No need to create it.
2023/08/08 12:25:57.143987 [WARN] Log stream for log group /aws/elasticbeanstalk/REDACTED/var/log/httpd/access_log already exists. No need to create it.
2023/08/08 12:25:57.170769 [WARN] Log stream for log group /aws/elasticbeanstalk/REDACTED/var/log/httpd/error_log already exists. No need to create it.
2023/08/08 12:25:57.170794 [INFO] start to fetch config
2023/08/08 12:25:57.170812 [INFO] Running command /bin/sh -c /opt/aws/amazon-cloudwatch-agent/bin/amazon-cloudwatch-agent-ctl -a fetch-config -c file:/opt/aws/amazon-cloudwatch-agent/etc/beanstalk.json -s
2023/08/08 12:25:58.000341 [INFO] ****** processing amazon-cloudwatch-agent ******
I! Trying to detect region from ec2 D! [EC2] Found active network interface Successfully fetched the config and saved in /opt/aws/amazon-cloudwatch-agent/etc/amazon-cloudwatch-agent.d/file_beanstalk.json.tmp
Start configuration validation...
I! Detecting run_as_user...
I! Trying to detect region from ec2
D! [EC2] Found active network interface
/opt/aws/amazon-cloudwatch-agent/bin/amazon-cloudwatch-agent -schematest -config /opt/aws/amazon-cloudwatch-agent/etc/amazon-cloudwatch-agent.toml
Configuration validation second phase succeeded
Configuration validation succeeded

2023/08/08 12:25:58.000363 [INFO] 2023/08/08 12:25:57 Reading json config file path: /opt/aws/amazon-cloudwatch-agent/etc/amazon-cloudwatch-agent.d/file_beanstalk.json.tmp ...
2023/08/08 12:25:57 I! Valid Json input schema.
2023/08/08 12:25:57 Configuration validation first phase succeeded

2023/08/08 12:25:58.000371 [INFO] Executing instruction: GetToggleForceRotate
2023/08/08 12:25:58.000373 [INFO] Checking if logs need forced rotation
2023/08/08 12:25:58.000391 [INFO] Running command /bin/sh -c /opt/aws/bin/cfn-get-metadata -s arn:aws:cloudformation:eu-central-1:REDACTED:stack/awseb-e-REDACTED-stack/REDACTED -r AWSEBAutoScalingGroup --region eu-central-1
2023/08/08 12:25:58.360974 [INFO] Running command /bin/sh -c /opt/aws/bin/cfn-get-metadata -s arn:aws:cloudformation:eu-central-1:REDACTED:stack/awseb-e-REDACTED-stack/REDACTED -r AWSEBBeanstalkMetadata --region eu-central-1
2023/08/08 12:25:58.709208 [INFO] Procfile not found. Generating default rsyslog config
2023/08/08 12:25:58.711226 [INFO] Running command /bin/sh -c systemctl restart rsyslog.service
2023/08/08 12:25:59.071688 [INFO] Executing instruction: PostBuildEbExtension
2023/08/08 12:25:59.071728 [INFO] Starting executing the config set Infra-EmbeddedPostBuild.
2023/08/08 12:25:59.071746 [INFO] Running command /bin/sh -c /opt/aws/bin/cfn-init -s arn:aws:cloudformation:eu-central-1:REDACTED:stack/awseb-e-REDACTED-stack/REDACTED -r AWSEBAutoScalingGroup --region eu-central-1 --configsets Infra-EmbeddedPostBuild
2023/08/08 12:25:59.762669 [INFO] Finished executing the config set Infra-EmbeddedPostBuild.

2023/08/08 12:25:59.762698 [INFO] Executing instruction: CleanEbExtensions
2023/08/08 12:25:59.762863 [INFO] Cleaned ebextensions subdirectories from app staging directory.
2023/08/08 12:25:59.762867 [INFO] Executing instruction: RunAppDeployPreDeployHooks
2023/08/08 12:25:59.762879 [INFO] Executing platform hooks in .platform/hooks/predeploy/
2023/08/08 12:25:59.762903 [INFO] The dir .platform/hooks/predeploy/ does not exist
2023/08/08 12:25:59.762905 [INFO] Finished running scripts in /var/app/staging/.platform/hooks/predeploy
2023/08/08 12:25:59.762910 [INFO] Executing instruction: stop X-Ray
2023/08/08 12:25:59.762912 [INFO] stop X-Ray ...
2023/08/08 12:25:59.762932 [INFO] Running command /bin/sh -c systemctl show -p PartOf xray.service
2023/08/08 12:25:59.776374 [WARN] stopProcess Warning: process xray is not registered 
2023/08/08 12:25:59.776405 [INFO] Running command /bin/sh -c systemctl stop xray.service
2023/08/08 12:25:59.790247 [INFO] Executing instruction: stop proxy
2023/08/08 12:25:59.790280 [INFO] Running command /bin/sh -c systemctl show -p PartOf httpd.service
2023/08/08 12:25:59.804969 [WARN] deregisterProcess Warning: process httpd is not registered, skipping...

2023/08/08 12:25:59.805004 [INFO] Running command /bin/sh -c systemctl show -p PartOf nginx.service
2023/08/08 12:25:59.818492 [INFO] Running command /bin/sh -c systemctl is-active nginx.service
2023/08/08 12:25:59.827624 [INFO] Running command /bin/sh -c systemctl show -p PartOf nginx.service
2023/08/08 12:25:59.838733 [INFO] Running command /bin/sh -c systemctl stop nginx.service
2023/08/08 12:25:59.967436 [INFO] Running command /bin/sh -c systemctl disable nginx.service
2023/08/08 12:26:00.304608 [INFO] Running command /bin/sh -c systemctl daemon-reload
2023/08/08 12:26:00.515728 [INFO] Running command /bin/sh -c systemctl reset-failed
2023/08/08 12:26:00.525325 [INFO] Executing instruction: stop php-fpm
2023/08/08 12:26:00.525358 [INFO] Running command /bin/sh -c systemctl show -p PartOf php-fpm.service
2023/08/08 12:26:00.538351 [INFO] Running command /bin/sh -c systemctl stop php-fpm.service
2023/08/08 12:26:00.606356 [INFO] Executing instruction: FlipApplication
2023/08/08 12:26:00.606380 [INFO] Removing /var/app/current/ if it exists
2023/08/08 12:26:00.932561 [INFO] Renaming /var/app/staging/ to /var/app/current/
2023/08/08 12:26:00.932813 [INFO] create soft link from /var/app/current/ to /var/www/html
2023/08/08 12:26:00.932858 [INFO] Executing instruction: start X-Ray
2023/08/08 12:26:00.932863 [INFO] X-Ray is not enabled.
2023/08/08 12:26:00.932866 [INFO] Executing instruction: start php-fpm
2023/08/08 12:26:00.933044 [INFO] Running command /bin/sh -c systemctl show -p PartOf php-fpm.service
2023/08/08 12:26:00.948074 [WARN] Warning: process php-fpm is already registered...
Deregistering the process ...
2023/08/08 12:26:00.948104 [INFO] Running command /bin/sh -c systemctl show -p PartOf php-fpm.service
2023/08/08 12:26:00.965390 [INFO] Running command /bin/sh -c systemctl is-active php-fpm.service
2023/08/08 12:26:00.978900 [INFO] Running command /bin/sh -c systemctl disable php-fpm.service
2023/08/08 12:26:01.234846 [INFO] Running command /bin/sh -c systemctl daemon-reload
2023/08/08 12:26:01.435158 [INFO] Running command /bin/sh -c systemctl reset-failed
2023/08/08 12:26:01.453938 [INFO] Running command /bin/sh -c systemctl daemon-reload
2023/08/08 12:26:01.700230 [INFO] Running command /bin/sh -c systemctl reset-failed
2023/08/08 12:26:01.710254 [INFO] Running command /bin/sh -c systemctl show -p PartOf php-fpm.service
2023/08/08 12:26:01.723553 [INFO] Running command /bin/sh -c systemctl is-active php-fpm.service
2023/08/08 12:26:01.733889 [INFO] Running command /bin/sh -c systemctl start php-fpm.service
2023/08/08 12:26:01.946173 [INFO] Executing instruction: start proxy with new configuration
2023/08/08 12:26:01.946215 [INFO] Running command /bin/sh -c /usr/sbin/nginx -t -c /var/proxy/staging/nginx/nginx.conf
2023/08/08 12:26:01.973046 [INFO] nginx: the configuration file /var/proxy/staging/nginx/nginx.conf syntax is ok
nginx: configuration file /var/proxy/staging/nginx/nginx.conf test is successful

2023/08/08 12:26:01.973280 [INFO] Running command /bin/sh -c cp -rp /var/proxy/staging/nginx/* /etc/nginx
2023/08/08 12:26:01.976651 [INFO] Running command /bin/sh -c systemctl show -p PartOf nginx.service
2023/08/08 12:26:01.992781 [INFO] Running command /bin/sh -c systemctl daemon-reload
2023/08/08 12:26:02.215573 [INFO] Running command /bin/sh -c systemctl reset-failed
2023/08/08 12:26:02.224586 [INFO] Running command /bin/sh -c systemctl show -p PartOf nginx.service
2023/08/08 12:26:02.238283 [INFO] Running command /bin/sh -c systemctl is-active nginx.service
2023/08/08 12:26:02.247827 [INFO] Running command /bin/sh -c systemctl start nginx.service
2023/08/08 12:26:02.365881 [INFO] Executing instruction: configureSqsd
2023/08/08 12:26:02.371354 [INFO] get sqsd conf from cfn metadata and write into sqsd conf file ...
2023/08/08 12:26:02.373322 [INFO] Executing instruction: startSqsd
2023/08/08 12:26:02.373345 [INFO] Running command /bin/sh -c systemctl show -p PartOf sqsd.service
2023/08/08 12:26:02.386322 [INFO] Running command /bin/sh -c systemctl is-active sqsd.service
2023/08/08 12:26:02.396337 [INFO] Running command /bin/sh -c systemctl start sqsd.service
2023/08/08 12:26:08.658185 [INFO] Executing instruction: Track pids in healthd
2023/08/08 12:26:08.658201 [INFO] This is an enhanced health env...
2023/08/08 12:26:08.658214 [INFO] Running command /bin/sh -c systemctl show -p ConsistsOf aws-eb.target | cut -d= -f2
2023/08/08 12:26:08.669888 [INFO] healthd.service php-fpm.service sqsd.service cfn-hup.service nginx.service amazon-cloudwatch-agent.service

2023/08/08 12:26:08.669924 [INFO] Running command /bin/sh -c systemctl show -p ConsistsOf eb-app.target | cut -d= -f2
2023/08/08 12:26:08.680663 [INFO] 

2023/08/08 12:26:08.680906 [INFO] Executing instruction: RunAppDeployPostDeployHooks
2023/08/08 12:26:08.680994 [INFO] Executing platform hooks in .platform/hooks/postdeploy/
2023/08/08 12:26:08.681021 [INFO] The dir .platform/hooks/postdeploy/ does not exist
2023/08/08 12:26:08.681023 [INFO] Finished running scripts in /var/app/current/.platform/hooks/postdeploy
2023/08/08 12:26:08.681028 [INFO] Executing cleanup logic
2023/08/08 12:26:08.681115 [INFO] CommandService Response: {"status":"SUCCESS","api_version":"1.0","results":[{"status":"SUCCESS","msg":"Engine execution has succeeded.","returncode":0,"events":[{"msg":"Instance deployment: You included a 'vendor' folder in your source bundle. The deployment ignored 'composer.json' and didn't install Composer dependencies.","timestamp":1691497555522,"severity":"INFO"},{"msg":"Instance deployment completed successfully.","timestamp":1691497568681,"severity":"INFO"}]}]}

2023/08/08 12:26:08.681273 [INFO] Platform Engine finished execution on command: app-deploy

2023/08/08 12:26:14.442461 [INFO] Starting...
2023/08/08 12:26:14.442514 [INFO] Starting EBPlatform-PlatformEngine
2023/08/08 12:26:14.442534 [INFO] reading event message file
2023/08/08 12:26:14.442715 [INFO] Engine received EB command cfn-hup-exec

2023/08/08 12:26:14.525323 [INFO] Running command /bin/sh -c /opt/aws/bin/cfn-get-metadata -s arn:aws:cloudformation:eu-central-1:REDACTED:stack/awseb-e-REDACTED-stack/REDACTED -r AWSEBAutoScalingGroup --region eu-central-1
2023/08/08 12:26:14.872124 [INFO] Running command /bin/sh -c /opt/aws/bin/cfn-get-metadata -s arn:aws:cloudformation:eu-central-1:REDACTED:stack/awseb-e-REDACTED-stack/REDACTED -r AWSEBBeanstalkMetadata --region eu-central-1
2023/08/08 12:26:15.230601 [INFO] checking whether command app-deploy is applicable to this instance...
2023/08/08 12:26:15.230615 [INFO] this command is not applicable to the instance, thus instance shouldn't execute command
2023/08/08 12:26:15.230618 [INFO] skip command app-deploy for this instance...
2023/08/08 12:26:15.230630 [ERROR] Ignoring not applicable command.
2023/08/08 12:26:15.230632 [INFO] Executing cleanup logic
2023/08/08 12:26:15.230727 [INFO] CommandService Response: {"status":"FAILURE","api_version":"1.0","results":[{"status":"FAILURE","msg":"Ignoring not applicable command.","returncode":0,"events":[]}]}

2023/08/08 12:26:15.231199 [INFO] Platform Engine finished execution on command: app-deploy

2023/08/08 12:30:41.265544 [INFO] Starting...
2023/08/08 12:30:41.265607 [INFO] Starting EBPlatform-PlatformEngine
2023/08/08 12:30:41.265632 [INFO] reading event message file
2023/08/08 12:30:41.265812 [INFO] Engine received EB command cfn-hup-exec

2023/08/08 12:30:41.356753 [INFO] Running command /bin/sh -c /opt/aws/bin/cfn-get-metadata -s arn:aws:cloudformation:eu-central-1:REDACTED:stack/awseb-e-REDACTED-stack/REDACTED -r AWSEBAutoScalingGroup --region eu-central-1
2023/08/08 12:30:41.730575 [INFO] Running command /bin/sh -c /opt/aws/bin/cfn-get-metadata -s arn:aws:cloudformation:eu-central-1:REDACTED:stack/awseb-e-REDACTED-stack/REDACTED -r AWSEBBeanstalkMetadata --region eu-central-1
2023/08/08 12:30:42.096753 [INFO] checking whether command bundle-log is applicable to this instance...
2023/08/08 12:30:42.096767 [INFO] this command is applicable to the instance, thus instance should execute command
2023/08/08 12:30:42.096776 [INFO] Engine command: (bundle-log)

2023/08/08 12:30:42.096822 [INFO] Executing instruction: GetBundleLogs
2023/08/08 12:30:42.096825 [INFO] Bundle Logs...
nickdnk commented 1 year ago

I'm getting a lot of this as well. Again only on the worker environment and always only one of the two.

Screenshot 2023-08-16 at 17 02 58

Last 100 of the problematic instance. There are no errors in any of the other log files I can find.

eb-engine.log

2023/08/16 14:57:51.260683 [INFO] Running command /bin/sh -c systemctl stop xray.service
2023/08/16 14:57:51.274434 [INFO] Executing instruction: stop proxy
2023/08/16 14:57:51.274482 [INFO] Running command /bin/sh -c systemctl show -p PartOf httpd.service
2023/08/16 14:57:51.287472 [WARN] deregisterProcess Warning: process httpd is not registered, skipping...

2023/08/16 14:57:51.287505 [INFO] Running command /bin/sh -c systemctl show -p PartOf nginx.service
2023/08/16 14:57:51.300385 [INFO] Running command /bin/sh -c systemctl is-active nginx.service
2023/08/16 14:57:51.309818 [INFO] Running command /bin/sh -c systemctl show -p PartOf nginx.service
2023/08/16 14:57:51.320137 [INFO] Running command /bin/sh -c systemctl stop nginx.service
2023/08/16 14:57:51.467114 [INFO] Running command /bin/sh -c systemctl disable nginx.service
2023/08/16 14:57:51.704484 [INFO] Running command /bin/sh -c systemctl daemon-reload
2023/08/16 14:57:51.944630 [INFO] Running command /bin/sh -c systemctl reset-failed
2023/08/16 14:57:51.953801 [INFO] Executing instruction: stop php-fpm
2023/08/16 14:57:51.953835 [INFO] Running command /bin/sh -c systemctl show -p PartOf php-fpm.service
2023/08/16 14:57:51.966522 [INFO] Running command /bin/sh -c systemctl stop php-fpm.service
2023/08/16 14:57:52.057020 [INFO] Executing instruction: FlipApplication
2023/08/16 14:57:52.057047 [INFO] Removing /var/app/current/ if it exists
2023/08/16 14:57:52.363265 [INFO] Renaming /var/app/staging/ to /var/app/current/
2023/08/16 14:57:52.363526 [INFO] create soft link from /var/app/current/ to /var/www/html
2023/08/16 14:57:52.363573 [INFO] Executing instruction: start X-Ray
2023/08/16 14:57:52.363579 [INFO] X-Ray is not enabled.
2023/08/16 14:57:52.363582 [INFO] Executing instruction: start php-fpm
2023/08/16 14:57:52.363779 [INFO] Running command /bin/sh -c systemctl show -p PartOf php-fpm.service
2023/08/16 14:57:52.379370 [WARN] Warning: process php-fpm is already registered...
Deregistering the process ...
2023/08/16 14:57:52.379402 [INFO] Running command /bin/sh -c systemctl show -p PartOf php-fpm.service
2023/08/16 14:57:52.393227 [INFO] Running command /bin/sh -c systemctl is-active php-fpm.service
2023/08/16 14:57:52.404069 [INFO] Running command /bin/sh -c systemctl disable php-fpm.service
2023/08/16 14:57:52.614543 [INFO] Running command /bin/sh -c systemctl daemon-reload
2023/08/16 14:57:52.837774 [INFO] Running command /bin/sh -c systemctl reset-failed
2023/08/16 14:57:52.849583 [INFO] Running command /bin/sh -c systemctl daemon-reload
2023/08/16 14:57:53.050823 [INFO] Running command /bin/sh -c systemctl reset-failed
2023/08/16 14:57:53.059984 [INFO] Running command /bin/sh -c systemctl show -p PartOf php-fpm.service
2023/08/16 14:57:53.074126 [INFO] Running command /bin/sh -c systemctl is-active php-fpm.service
2023/08/16 14:57:53.083895 [INFO] Running command /bin/sh -c systemctl start php-fpm.service
2023/08/16 14:57:53.267227 [INFO] Executing instruction: start proxy with new configuration
2023/08/16 14:57:53.267276 [INFO] Running command /bin/sh -c /usr/sbin/nginx -t -c /var/proxy/staging/nginx/nginx.conf
2023/08/16 14:57:53.291203 [INFO] nginx: the configuration file /var/proxy/staging/nginx/nginx.conf syntax is ok
nginx: configuration file /var/proxy/staging/nginx/nginx.conf test is successful

2023/08/16 14:57:53.291368 [INFO] Running command /bin/sh -c cp -rp /var/proxy/staging/nginx/* /etc/nginx
2023/08/16 14:57:53.294811 [INFO] Running command /bin/sh -c systemctl show -p PartOf nginx.service
2023/08/16 14:57:53.311070 [INFO] Running command /bin/sh -c systemctl daemon-reload
2023/08/16 14:57:53.489838 [INFO] Running command /bin/sh -c systemctl reset-failed
2023/08/16 14:57:53.499430 [INFO] Running command /bin/sh -c systemctl show -p PartOf nginx.service
2023/08/16 14:57:53.513675 [INFO] Running command /bin/sh -c systemctl is-active nginx.service
2023/08/16 14:57:53.523517 [INFO] Running command /bin/sh -c systemctl start nginx.service
2023/08/16 14:57:53.647258 [INFO] Executing instruction: configureSqsd
2023/08/16 14:57:53.650422 [INFO] get sqsd conf from cfn metadata and write into sqsd conf file ...
2023/08/16 14:57:53.651915 [INFO] Executing instruction: startSqsd
2023/08/16 14:57:53.651935 [INFO] Running command /bin/sh -c systemctl show -p PartOf sqsd.service
2023/08/16 14:57:53.663928 [INFO] Running command /bin/sh -c systemctl is-active sqsd.service
2023/08/16 14:57:53.672727 [INFO] Running command /bin/sh -c systemctl start sqsd.service
2023/08/16 14:57:59.859633 [INFO] Executing instruction: Track pids in healthd
2023/08/16 14:57:59.859649 [INFO] This is an enhanced health env...
2023/08/16 14:57:59.859661 [INFO] Running command /bin/sh -c systemctl show -p ConsistsOf aws-eb.target | cut -d= -f2
2023/08/16 14:57:59.870997 [INFO] nginx.service cfn-hup.service amazon-cloudwatch-agent.service php-fpm.service sqsd.service healthd.service

2023/08/16 14:57:59.871029 [INFO] Running command /bin/sh -c systemctl show -p ConsistsOf eb-app.target | cut -d= -f2
2023/08/16 14:57:59.881275 [INFO] 

2023/08/16 14:57:59.881499 [INFO] Executing instruction: RunAppDeployPostDeployHooks
2023/08/16 14:57:59.881585 [INFO] Executing platform hooks in .platform/hooks/postdeploy/
2023/08/16 14:57:59.881612 [INFO] The dir .platform/hooks/postdeploy/ does not exist
2023/08/16 14:57:59.881615 [INFO] Finished running scripts in /var/app/current/.platform/hooks/postdeploy
2023/08/16 14:57:59.881619 [INFO] Executing cleanup logic
2023/08/16 14:57:59.881705 [INFO] CommandService Response: {"status":"SUCCESS","api_version":"1.0","results":[{"status":"SUCCESS","msg":"Engine execution has succeeded.","returncode":0,"events":[{"msg":"Instance deployment: You included a 'vendor' folder in your source bundle. The deployment ignored 'composer.json' and didn't install Composer dependencies.","timestamp":1692197866757,"severity":"INFO"},{"msg":"Instance deployment completed successfully.","timestamp":1692197879881,"severity":"INFO"}]}]}

2023/08/16 14:57:59.881862 [INFO] Platform Engine finished execution on command: app-deploy

2023/08/16 14:58:05.105310 [INFO] Starting...
2023/08/16 14:58:05.105381 [INFO] Starting EBPlatform-PlatformEngine
2023/08/16 14:58:05.105401 [INFO] reading event message file
2023/08/16 14:58:05.105703 [INFO] Engine received EB command cfn-hup-exec

2023/08/16 14:58:05.174719 [INFO] Running command /bin/sh -c /opt/aws/bin/cfn-get-metadata -s arn:aws:cloudformation:eu-central-1:REDACTED:stack/awseb-e-REDACTED/REDACTED -r AWSEBAutoScalingGroup --region eu-central-1
2023/08/16 14:58:05.508542 [INFO] Running command /bin/sh -c /opt/aws/bin/cfn-get-metadata -s arn:aws:cloudformation:eu-central-1:REDACTED:stack/awseb-e-REDACTED/REDACTED -r AWSEBBeanstalkMetadata --region eu-central-1
2023/08/16 14:58:05.837325 [INFO] checking whether command app-deploy is applicable to this instance...
2023/08/16 14:58:05.837343 [INFO] this command is not applicable to the instance, thus instance shouldn't execute command
2023/08/16 14:58:05.837347 [INFO] skip command app-deploy for this instance...
2023/08/16 14:58:05.837367 [ERROR] Ignoring not applicable command.
2023/08/16 14:58:05.837370 [INFO] Executing cleanup logic
2023/08/16 14:58:05.837468 [INFO] CommandService Response: {"status":"FAILURE","api_version":"1.0","results":[{"status":"FAILURE","msg":"Ignoring not applicable command.","returncode":0,"events":[]}]}

2023/08/16 14:58:05.837673 [INFO] Platform Engine finished execution on command: app-deploy

2023/08/16 15:08:34.115957 [INFO] Starting...
2023/08/16 15:08:34.116018 [INFO] Starting EBPlatform-PlatformEngine
2023/08/16 15:08:34.116038 [INFO] reading event message file
2023/08/16 15:08:34.116228 [INFO] Engine received EB command cfn-hup-exec

2023/08/16 15:08:34.204704 [INFO] Running command /bin/sh -c /opt/aws/bin/cfn-get-metadata -s arn:aws:cloudformation:eu-central-1:REDACTED:stack/awseb-e-REDACTED/REDACTED -r AWSEBAutoScalingGroup --region eu-central-1
2023/08/16 15:08:34.543080 [INFO] Running command /bin/sh -c /opt/aws/bin/cfn-get-metadata -s arn:aws:cloudformation:eu-central-1:REDACTED:stack/awseb-e-REDACTED/REDACTED -r AWSEBBeanstalkMetadata --region eu-central-1
2023/08/16 15:08:34.889230 [INFO] checking whether command tail-log is applicable to this instance...
2023/08/16 15:08:34.889243 [INFO] this command is applicable to the instance, thus instance should execute command
2023/08/16 15:08:34.889246 [INFO] Engine command: (tail-log)

2023/08/16 15:08:34.889291 [INFO] Executing instruction: GetTailLogs
2023/08/16 15:08:34.889294 [INFO] Tail Logs...
2023/08/16 15:08:34.889836 [INFO] Running command /bin/sh -c tail -n 100 /var/log/eb-engine.log
RachelZhao commented 1 year ago

I am unable to repro the issue with the latest php8.2 platform, please use support plan to get support from the team.

nickdnk commented 1 year ago

I am unable to repro the issue with the latest php8.2 platform, please cut a ticket to EB with more information attached.

Do you work at AWS? It’s unclear from your profile. Where exactly do I submit this, and what more information do you need?

nickdnk commented 1 year ago

I am unable to repro the issue with the latest php8.2 platform, please use support plan to get support from the team.

I don't need paid support. I need you to fix what is clearly a bug in the deployment flow. This didn't happen on previous versions of EB.

I'm using a mix of spot and on-demand instances for the worker environment, so it may be related to that.

PeterCai7 commented 1 year ago

Sorry we took a look at your log but the information that could help us is still limited.

2023/08/08 12:26:15.230601 [INFO] checking whether command app-deploy is applicable to this instance...
2023/08/08 12:26:15.230615 [INFO] this command is not applicable to the instance, thus instance shouldn't execute command
2023/08/08 12:26:15.230618 [INFO] skip command app-deploy for this instance...
2023/08/08 12:26:15.230630 [ERROR] Ignoring not applicable command.

This log can only help us nail down to the fact that the command service is not sending the correct instance ID to platform engine. However, without further information, we cannot figure out what was wrong with the CFN exect command request.

We are more than happy to help but raising a support case through AWS cloud support is still the best way of moving forward. The cloud support will also investigate if there are something specific set up in your environments.

tehmaestro commented 1 year ago

I'm having the same issue, with PHP 8.0, so it seems there's a problem with the engine.

nickdnk commented 1 year ago

Sorry we took a look at your log but the information that could help us is still limited.

2023/08/08 12:26:15.230601 [INFO] checking whether command app-deploy is applicable to this instance...
2023/08/08 12:26:15.230615 [INFO] this command is not applicable to the instance, thus instance shouldn't execute command
2023/08/08 12:26:15.230618 [INFO] skip command app-deploy for this instance...
2023/08/08 12:26:15.230630 [ERROR] Ignoring not applicable command.

This log can only help us nail down to the fact that the command service is not sending the correct instance ID to platform engine. However, without further information, we cannot figure out what was wrong with the CFN exect command request.

We are more than happy to help but raising a support case through AWS cloud support is still the best way of moving forward. The cloud support will also investigate if there are something specific set up in your environments.

I don't have access to cloud support, so I cannot do that. What information do you need to help debug this?

I also have problems with our web environment consistently having "Degraded" health with no instances being in bad health and no problems whatsoever. This environment also includes spot instances, so it may be related to that. Have you tried including spot instances in attempt to recreate some of these problems? As you can see from @tehmaestro's response, it's not only affecting me, and as I said I changed nothing in our setup since it worked.

Screenshot 2023-09-11 at 16 14 55

Clicking "View causes" takes me to this:

Screenshot 2023-09-11 at 16 15 08

It seems to remain in this degraded health state either indefinitely or for several hours (not entirely sure). Edit: And just to be clear, I'm not doing anything crazy custom. Most things are simply set up using the EB console and it's mostly the default/suggested parameters. I have a few things set up with platform hooks (prebuild installs the APCu extension, but it only runs once per instance and simply skips the following deployments -- its log also has no errors) and nginx .conf files for virtual hosts, but these things have been the same for a long time and this health issue is new and started after 8.2 was released (that means version 4.x of EB). I also have ELB health checks enabled, but as evident from the reported health of the instances, this is working as expected. The fact that it's always only 1 of the workers and not both of them indicates that the problem is with the deployment logic and not with anything I'm doing.

Edit 2: Health is now back to normal for the web environment. I changed nothing and the health of all 3 instances has been OK the entire duration. That's 4 hours of degraded health for no obvious reason.

nickdnk commented 1 year ago

I updated EB to version 4.0.1, but it still hangs on deployment to our worker environment.

I've found out that maybe the health remaining degraded for the web environment is because of unbalanced AZ distribution due to spot instance availability, but this is not correctly displayed anywhere on the EB dashboard as far as I can tell. It's indicated in emails I receive from SNS, but as I mentioned clicking "View causes" on health does not help at all in figuring out the cause of "Degraded" health as all instances report as healthy. You may want to look into displaying this information somewhere.

nickdnk commented 10 months ago

EB 4.0.3 still causes 1 worker to hang on every deployment. It seems to always be the instance that has Lifecycle spot, which is configured in EB like this:

Instances min: 2 Instances max: 4 Fleet composition: Combine purchase options and instances Maximum spot price: Default On-demand base: 1 On-demand above base: 0% Capacity rebalancing: On

Maybe this can help reproduce the issue. Again, it only happens for workers, never the web server env.

I should also add that the update comes from Codepipeline. It is, however, the very last step of the pipeline and the pipeline itself reports the deployment as successful, even though EB remains in degraded health until I reboot the instance. Deploying again without rebooting the instance causes the same instance to report the "wrong version deployed" error.

morgano86 commented 9 months ago

I'm also running a worker on EB with 'Docker running on 64bit Amazon Linux 2/3.6.4',

The initial build goes fine, and all servers are up and running as expected. However, every time I push a new update if I have 4 active servers only 1 will succeed the other 3 get stuck in the "upgrading state". If I drop to two servers 1 will succeed 1 will fail. If I have 8 servers 1 will succeed and 7 will fail.

The servers are actually running and processing data but are as far as EB is aware stuck upgrading. After some time EB will rollback the update on the stuck servers so then the servers are out of sync. If I terminate each failed server before it rolls back it rebuilds with the new code every time - no issue. If I push an update all but one server will get stuck in the loop. It happens every time without fail. All my non-worker EB servers running the same configuration are ok, this only affects my worker.

The eb-engine.log on each failed server looks like this: 2023/12/07 12:55:15.703103 [INFO] checking whether command app-deploy is applicable to this instance... 2023/12/07 12:55:15.703122 [INFO] this command is not applicable to the instance, thus instance shouldn't execute command 2023/12/07 12:55:15.703125 [INFO] skip command app-deploy for this instance... 2023/12/07 12:55:15.703133 [ERROR] Ignoring not applicable command. 2023/12/07 12:55:15.703136 [INFO] Executing cleanup logic 2023/12/07 12:55:15.703186 [INFO] CommandService Response: {"status":"FAILURE","api_version":"1.0","results":[{"status":"FAILURE","msg":"Ignoring not applicable command.","returncode":0,"events":[]}]}

My instances are 'On-Demand' and not 'Spot'. My Docker containers are running PHP 8.2. My code is also being updated via CodePipeline.

nickdnk commented 7 months ago

~I think this problem may have been resolved with 4.0.5. I've just deployed and did not have any hanging worker instances. Up until now It's been consistently hanging on every deployment without exception since I created this issue.~

Never mind. It still doesn't work. Maybe a freak accident that it worked just before.

morgano86 commented 7 months ago

I'm on Platform Docker running on 64bit Amazon Linux 2/3.7.1 and the issue persists.

nickdnk commented 6 months ago

The issue persists on EB 4.1.0.

nickdnk commented 5 months ago

Still broken on 4.1.1.

nickdnk commented 2 months ago

The PHP 8.3 platform is still affected by this issue. I have to reboot the spot worker instance on every deployment.