[bitnami/rabbitmq] pods takes more time to deploy when used with AWS EFS as a storage class.

[sachgaik-xl]

Which chart:
The name (and version) of the affected chart
https://github.com/bitnami/charts/tree/master/bitnami/rabbitmq/
Version: 8.6.1

Describe the bug
RabbitMQ pod takes more than 20 mins to deploy when used with AWS EFS as a storage class. But it works fine when I use gp2 as a storage class.
Here is output of kubectl get pods

Here is the kubectl logs:

test-release-rabbitmq-0.log

To Reproduce
Steps to reproduce the behavior:
Install the Rabbitmq chart with AWS-EFS as a storage class and observe the output.

Expected behavior
Expected RabbitMQ pods to be in ready state withing few minuets(<2 min).

Version of Helm and Kubernetes:

• Output of helm version:

version.BuildInfo{Version:"v3.3.4", GitCommit:"a61ce5633af99708171414353ed49547cf05013d", GitTreeState:"clean", GoVersion:"go1.14.9"}

• Output of kubectl version:

Client Version: version.Info{Major:"1", Minor:"19", GitVersion:"v1.19.0", GitCommit:"e19964183377d0ec2052d1f1fa930c4d7575bd50", GitTreeState:"clean", BuildDate:"2020-08-26T14:30:33Z", GoVersion:"go1.15", Compiler:"gc", Platform:"linux/amd64"} Server Version: version.Info{Major:"1", Minor:"17+", GitVersion:"v1.17.12-eks-7684af", GitCommit:"7684af4ac41370dd109ac13817023cb8063e3d45", GitTreeState:"clean", BuildDate:"2020-10-20T22:57:40Z", GoVersion:"go1.13.15", Compiler:"gc", Platform:"linux/amd64"}

[carrodher]

Thanks for using the bitnami/rabbitmq Helm Chart. According to the container logs there is not any issue beyond of the time (from 08:35:35.95 to 08:49:59.102, 15 minutes is not normal). Regarding the storage class, the chart is not doing anything special depending on the provider, so it is like more an issue with the storage class provider than something that can be fixed with the chart itself.

We can maintain this issue open just in case more users are facing the same issue, but I can't see something fixable in the chart.

[chukka]

@carrodher We are facing the same issue #5183 with 7.x charts of bitnami with image tag - 3.8.9-debian-10-r58

Also , we tried with 6.25.2 chart of bitnami with image tag - 3.8.2-debian-9-r0, it starts as expected without any delay on nfs storage

Could you please check if there were any changes in

1. Docker images of bitnami (3.8.2-debian-9-r0 vs 3.8.9-debian-10-r58)
2. 6.x to 7.x chart

cc @rahulsadanandan

[carrodher]

Hi @chukka @rahulsadanandan, some questions in order to try to find where the issue can be located.

• Are you able to see the same issue by using the latest version (at this moment 8.7.4 with image 3.8.10-debian-10-r0)?
• When you say it worked in 6.X, are you referring to the past or in this very moment? I mean, what is your use case from the following scenarios?
  • Scenario 1: Installed 6.X in the past ✅ , installing 7.X now 🔴
  • Scenario 2: Installing 6.x now ✅, installing 7.x now 🔴
• Regarding the differences between versions, there is a "Notable changes" section in the README; both for the container and the chart, but in this section, only major changes are listed. In the same way, by default, those are the images bundled in each version: 6.25.2 contains 3.8.3-debian-10-r42 and the latest 7.7.1 contains 3.8.9-debian-10-r20
• What are the exact values you're using? Something else apart from persistence.storageClass="nfs", persistence.enabled=true, persistence.size=20Gi?
• Just to confirm, although it's taking more time than expected, in the end, everything is up and running, right? What is the step in the logs where it is stuck most of the time?

[carrodher]

BTW, I am closing #5183 in favor of this one, just to keep all the conversation in a single place

[peters95]

@carrodher You closed both tickets. Was this resolved?

[carrodher]

This issue is not closed, for me it is appearing as Open. I can't see any action where it was marked as closed or reopened.

[JfrogPrasanna]

Hi @chukka @rahulsadanandan, some questions in order to try to find where the issue can be located.

• Scenario 1: Installed 6.X in the past ✅ , installing 7.X now 🔴
• Scenario 2: Installing 6.x now ✅, installing 7.x now 🔴

@carrodher It is indeed Scenario 2. We tried 6.x now and it does work - but be aware that the version of rabbit is also older one.
We wanted to conclude that this is not an issue with EFS, as 6.x works.
Also concluded that it is not an issue with 3.8.9-debian-10-r20 as it works with NFS service when mounted into the container.

We have zeroed in on the chart, we will progress this further on Monday.

[carrodher]

Thanks! I hope to continue looking at this topic on Monday as well, an answer to the other questions would be very useful for us in order to debug the issue on our side.

[chukka]

@carrodher Appreciate the follow up on this. Replies inline :)

• Are you able to see the same issue by using the latest version (at this moment 8.7.4 with image 3.8.10-debian-10-r0)?
  @chukka - Yes , @sachgaik-xl tried on 8.6.x but it occurs on latest chart as well( we are still using 7.x charts implies apiVersion: 1 in our charts)
• When you say it worked in 6.X, are you referring to the past or in this very moment? I mean, what is your use case from the following scenarios?
• Scenario 1: Installed 6.X in the past ✅ , installing 7.X now 🔴
• Scenario 2: Installing 6.x now ✅, installing 7.x now 🔴
  @chukka - Yes - Scenario 2
• Regarding the differences between versions, there is a "Notable changes" section in the README; both for the container and the chart, but in this section, only major changes are listed. In the same way, by default, those are the images bundled in each version: 6.25.2 contains 3.8.3-debian-10-r42 and the latest 7.7.1 contains 3.8.9-debian-10-r20
  @chukka - we are using 6.25.2 chart with values overide of image tag to 3.8.2-debian-9-r0 and 7.7.1 chart with values overide of image tag to 3.8.9-debian-10-r58
• What are the exact values you're using? Something else apart from persistence.storageClass="nfs", persistence.enabled=true, persistence.size=20Gi?
  @chukka - we use below values

persistence:
  storageClass: "nfs"
  enabled: true
  size: 20Gi

• Just to confirm, although it's taking more time than expected, in the end, everything is up and running, right? What is the step in the logs where it is stuck most of the time?
  @chukka - Yes, it comes up after 15-30 mins - we enabled debug flag and here is the complete log - it waits at this step Waiting for applications 'rabbit_and_plugins'

kubectl logs -f rabbit-latest-rabbitmq-0
rabbitmq 13:47:48.12
rabbitmq 13:47:48.12 Welcome to the Bitnami rabbitmq container
rabbitmq 13:47:48.12 Subscribe to project updates by watching https://github.com/bitnami/bitnami-docker-rabbitmq
rabbitmq 13:47:48.13 Submit issues and feature requests at https://github.com/bitnami/bitnami-docker-rabbitmq/issues
rabbitmq 13:47:48.13
rabbitmq 13:47:48.13 INFO  ==> ** Starting RabbitMQ setup **
rabbitmq 13:47:48.15 INFO  ==> Validating settings in RABBITMQ_* env vars..
rabbitmq 13:47:48.17 INFO  ==> Initializing RabbitMQ...
rabbitmq 13:47:48.17 DEBUG ==> Creating environment file...
rabbitmq 13:47:48.18 DEBUG ==> Creating enabled_plugins file...
rabbitmq 13:47:48.18 DEBUG ==> Creating Erlang cookie...
rabbitmq 13:47:48.19 DEBUG ==> Ensuring expected directories/files exist...
rabbitmq 13:47:48.23 INFO  ==> Starting RabbitMQ in background...
Waiting for erlang distribution on node 'rabbit@rabbit-latest-rabbitmq-0.rabbit-latest-rabbitmq-headless.rabbitmqefs.svc.cluster.local' while OS process '44' is running
Configuring logger redirection
Waiting for applications 'rabbit_and_plugins' to start on node 'rabbit@rabbit-latest-rabbitmq-0.rabbit-latest-rabbitmq-headless.rabbitmqefs.svc.cluster.local'

@chukka  - waits for 15-30 mins here 

2021-01-22 13:55:37.032 [debug] <0.5095.0> Lager installed handler error_logger_lager_h into error_logger
2021-01-22 13:55:37.035 [debug] <0.5116.0> Lager installed handler lager_forwarder_backend into rabbit_log_ldap_lager_event
2021-01-22 13:55:37.035 [debug] <0.5107.0> Lager installed handler lager_forwarder_backend into rabbit_log_connection_lager_event
2021-01-22 13:55:37.035 [debug] <0.5119.0> Lager installed handler lager_forwarder_backend into rabbit_log_mirroring_lager_event
2021-01-22 13:55:37.035 [debug] <0.5122.0> Lager installed handler lager_forwarder_backend into rabbit_log_prelaunch_lager_event
2021-01-22 13:55:37.035 [debug] <0.5098.0> Lager installed handler lager_forwarder_backend into error_logger_lager_event
2021-01-22 13:55:37.035 [debug] <0.5104.0> Lager installed handler lager_forwarder_backend into rabbit_log_channel_lager_event
2021-01-22 13:55:37.035 [debug] <0.5101.0> Lager installed handler lager_forwarder_backend into rabbit_log_lager_event
2021-01-22 13:55:37.035 [debug] <0.5110.0> Lager installed handler lager_forwarder_backend into rabbit_log_feature_flags_lager_event
2021-01-22 13:55:37.035 [debug] <0.5113.0> Lager installed handler lager_forwarder_backend into rabbit_log_federation_lager_event
2021-01-22 13:55:37.035 [debug] <0.5125.0> Lager installed handler lager_forwarder_backend into rabbit_log_queue_lager_event
2021-01-22 13:55:37.035 [debug] <0.5128.0> Lager installed handler lager_forwarder_backend into rabbit_log_ra_lager_event
2021-01-22 13:55:37.035 [debug] <0.5131.0> Lager installed handler lager_forwarder_backend into rabbit_log_shovel_lager_event
2021-01-22 13:55:37.035 [debug] <0.5134.0> Lager installed handler lager_forwarder_backend into rabbit_log_upgrade_lager_event
2021-01-22 13:55:37.048 [info] <0.44.0> Application lager started on node 'rabbit@rabbit-latest-rabbitmq-0.rabbit-latest-rabbitmq-headless.rabbitmqefs.svc.cluster.local'
2021-01-22 13:55:37.273 [info] <0.44.0> Application mnesia started on node 'rabbit@rabbit-latest-rabbitmq-0.rabbit-latest-rabbitmq-headless.rabbitmqefs.svc.cluster.local'
2021-01-22 13:55:37.273 [info] <0.5074.0>
 Starting RabbitMQ 3.8.9 on Erlang 22.3
 Copyright (c) 2007-2020 VMware, Inc. or its affiliates.
 Licensed under the MPL 2.0. Website: https://rabbitmq.com
  ##  ##      RabbitMQ 3.8.9

[rahulsadanandan]

@carrodher some additional information
we also tested this with an ec2 instance (with an EFS file system mount).
Reproducible steps

1. Create an efs file system
2. Create an ec2 instance mounting the efs file system to a path (/mnt/efs/fs1)
3. Run newer bitnami rabbitmq image - docker run -v /mnt/efs/fs1:/bitnami bitnami/rabbitmq:3.8.10-debian-10-r1 or latest (more than 10 minutes to start)
4. Run older image -> docker run -v /mnt/efs/fs1:/bitnami bitnami/rabbitmq:3.8.2-debian-9-r0 (starts normally )

seems like this is an issue with the image and efs filesystem.

[carrodher]

I was trying to figure out the relation between the files system used as a volume and the Bitnami RabbitMQ container image.

The ENTRYPOINT directive in the Dockerfile, execute the entrypoint.sh script.

This script, basically, prints the welcome message

rabbitmq 13:47:48.12 Welcome to the Bitnami rabbitmq container
rabbitmq 13:47:48.12 Subscribe to project updates by watching https://github.com/bitnami/bitnami-docker-rabbitmq
rabbitmq 13:47:48.13 Submit issues and feature requests at https://github.com/bitnami/bitnami-docker-rabbitmq/issues

followed by

rabbitmq 13:47:48.13 INFO  ==> ** Starting RabbitMQ setup **

and executes the setup.sh script.

setup.sh run some validations related to the env. variables used by the container, and then execute the rabbitmq validation using the rabbitmq_initialize function.

This function starts logging some info in the log:

rabbitmq 13:47:48.17 INFO  ==> Initializing RabbitMQ...

apart from that, other actions are performed, those actions are logged when debug is enabled:

rabbitmq 13:47:48.17 DEBUG ==> Creating environment file...
rabbitmq 13:47:48.18 DEBUG ==> Creating enabled_plugins file...
rabbitmq 13:47:48.18 DEBUG ==> Creating Erlang cookie...
rabbitmq 13:47:48.19 DEBUG ==> Ensuring expected directories/files exist...

according to the timestamps, those actions are executed without any issues.

Then, still inside the rabbitmq_initialize function, the following line is executed:

! is_rabbitmq_running && rabbitmq_start_bg

At that point, we're calling the rabbitmq_start_bg function. This function add the following entry to the logs

rabbitmq 13:47:48.23 INFO  ==> Starting RabbitMQ in background...

according to the information provided, it seems at this point is where the container is stuck for more time than expected when using EFS.

Basically, this function is executing /opt/bitnami/rabbitmq/sbin/rabbitmq-server in the background and waiting until the process finishes. Once finished, other actions are executed inside the rabbitmq_initialize function before return the execution to the setup.sh and entrypoint.sh scripts.

According to the logs, the container is stuck running /opt/bitnami/rabbitmq/sbin/rabbitmq-server that, at the end, is running the rabbitmq executable, there is not any Bitnami action performed at this point.

Why may there be differences between
a) Using or not EFS: Depending on the usage of the volume by the application the performance can be affected. If there is an exhaustive usage it is going to depend on the configuration/resources or directly the nature of the file system itself. In this case, maybe some settings can be adjusted such as throughput mode, burst credits, etc
b) Using old versions of the image: If using an old version and the same EFS the issue is not reproducible can be related to new operations performed by the sbin/rabbitmq-server executable. If in an old version this executable executes a smaller amount of actions, the EFS performance cannot be affected, but in recent versions, more actions (or more intensive) are executed, the EFS performance can be affected.

After this investigation, I am not sure how from Bitnami we can improve this time, since the command where it gets trapped is not related to bitnami but the application binary.

[michaelklishin]

RabbitMQ logs a lot of its boot time activity at debug level. Combined with strace it can tell you a lot about what the node is doing.

[rahulsadanandan]

Seems this is not a chart issue, as this is also reproducible in the official docker hub image, I have raised an issue there with the debug logs.