2 out of 3 bbs acting as master

[paolostivanin]

CF v 270
Diego v 1.23.1
IaaS: AWS
2 AZs

Tonight there was a failover of the rds db (5m) and after that the system was kinda down (no push, no delete, etc). While investigating, we found out that:

• bbs1 had "too many open files" error (but was still acting as master)
• bbs2 took over as master but didn't do anything
• bbs3 was idle

I guess something went wrong on the bbs side because I don't think it's normal to have 2 masters :)
What can I do to help you debug this issue?

[cf-gitbot]

We have created an issue in Pivotal Tracker to manage this:

https://www.pivotaltracker.com/story/show/150472188

The labels on this github issue will be updated when the story is started.

[emalm]

Thanks for letting us know about this issue, @paolostivanin. Would you be able to provide the stdout and stderr logs from all the BBS instances in this deployment, as well as the times when the RDS instance failed over or times when you noticed or resolved these degradations of service?

Some additional questions:

• Are the BBS instances configured to acquire their locks in Consul, Locket, or both?
• Could you clarify what you mean when you say that BBS Use a list of etcd endpoints rather than the single leader ip. #1 was still acting as master and that BBS No description or README for this repo  #2 took over as master but didn't do anything? Which instance or instances were handling API requests? Which instance or instances were performing convergence operations? If you happen to know it, which instances held the BBS lock during which periods of time?

Thanks,
Eric, CF Diego PM

[paolostivanin]

@emalm yes, I do have the stderr and stdout logs for the 2 bbs that were acting as master. Can I send them to you as they are of do I have to "clean" them before? AFAIK these logs shouldn't contain credentials, tokens, etc, right?

The following times are in UTC.

• 23.8. 01:33-01:34 - RDS used for CC DB did a fail over (took ~ 1min), this happened during the maintenance window specified for this RDS instance so it is a normal situation

• 23.8. 01:33-01:40 - CF API (/v2/info) was not available, RDS downtime triggered restart of cloud controller process (on api nodes), unclear why this took so long

• 23.8. 01:33-09:04 - Diego BBS (aka database) not available

  • 02:40 - Diego BBS came back automatically but with 2 masters which means it is still not working
  • 09:04 - manually repaired Diego BBS via bosh recreate, Diego BBS is available again (1 master, 2 slaves)

• BBS instances acquire their locks using consul (locket is still marked as experimental)

• I mean that prior to the outage only one BBS was reporting to grafana but after the outage 2 BBS were reporting at the same time. CF api and any lifecycle operation (including repair of crashed app instances) were not available. Prior to the outage, database_z1 83efe73d-0b03-47eb-a74e-52b2a2bc59df was the master. After the outage (and the manual repair) database_z2 865e9a1e-0dfe-44be-89e8-52c570d08823 became the master.

[emalm]

Thanks for the additional information, @paolostivanin, especially about the timing. I believe the BBS logs would be safe to send without any scrubbing to remove sensitive credentials or environmental details.

In the hopefully unlikely event that this issue occurs again before we identify the root cause and introduce any relevant fixes, could you also try killing the stuck BBS process with kill -QUIT $(pidof bbs), and then capture the goroutine dump that the process emits to the stderr log?

Thanks again,
Eric

[paolostivanin]

Hi,
please find attached the stderr and stdout logs for bbs_z1/0 and bbs_z2/0 and /1. In case you need them, I also have other jobs' logs.

bbs_all.tar.xz.zip

Maybe broken Consul could be a root cause for the 2 BBS masters? What do you think?

[crhino]

@paolostivanin What type of RDS database are you using, postgres or MySQL?

[paolostivanin]

postgres!

[crhino]

@paolostivanin In your timeline above, you have two events for the BBS. One at 02:40 where the BBS came back and two at 09:04 when you manually repaired the BBS via BOSH recreate. At what point did CF API operations start working?

[paolostivanin]

@crhino CF api and any lifecycle operations (including repair of crashed app instances) were not available for ~7.5h. API started working again ~9:04 UTC

[crhino]

@paolostivanin Is it possible for you to get the cell logs from that time period? That would help diagnose the downtime issue.

[paolostivanin]

Unfortunately no. We have a high load and hundred of cells, so we don't keep the logs too long.

[crhino]

We think we have figured out why the deployment wasn't working. Looking at the BBS logs for the node that did not shut down, you can see that there are still bbs.request.cells being logged starting soon after the BBS loses its lock. We believe this is the auctioneer attempting to fetch the CellReps from the BBS, as it retries every second (which the auctioneer is configured to do on failure), and started right as the new BBS took the lock and started to do convergence processes. Our theory is that the auctioneer had an idle TCP connection to the old BBS hanging around, and when it received work, reused that idle connection to the old BBS. That bypasses any DNS lookup, so it would not see a DNS change to the new BBS node.

The root cause of this is that the postgres driver does not provide any timeouts associated with a backing postgres database, causing the BBS to hang during shutdown. You can see here that others have experienced the problem of hanging database connections. We have written this story to implement postgres timeouts.

Hope that helps, we will close this issue since we have a story to track the work.