OpenStack Operations Guide (2014)

Appendix B. Tales From the Cryp^H^H^H^H Cloud

Herein lies a selection of tales from OpenStack cloud operators. Read and learn from their wisdom.

Double VLAN

I was on-site in Kelowna, British Columbia, Canada, setting up a new OpenStack cloud. The deployment was fully automated: Cobbler deployed the OS on the bare metal, bootstrapped it, and Puppet took over from there. I had run the deployment scenario so many times in practice and took for granted that everything was working.

On my last day in Kelowna, I was in a conference call from my hotel. In the background, I was fooling around on the new cloud. I launched an instance and logged in. Everything looked fine. Out of boredom, I ran ps aux, and all of the sudden the instance locked up.

Thinking it was just a one-off issue, I terminated the instance and launched a new one. By then, the conference call ended, and I was off to the data center.

At the data center, I was finishing up some tasks and remembered the lockup. I logged in to the new instance and ran ps aux again. It worked. Phew. I decided to run it one more time. It locked up. WTF.

After reproducing the problem several times, I came to the unfortunate conclusion that this cloud did indeed have a problem. Even worse, my time was up in Kelowna, and I had to return to Calgary.

Where do you even begin troubleshooting something like this? An instance just randomly locks when a command is issued. Is it the image? Nope—it happens on all images. Is it the compute node? Nope—all nodes. Is the instance locked up? No! New SSH connections work just fine!

We reached out for help. A networking engineer suggested it was an MTU issue. Great! MTU! Something to go on! What’s MTU, and why would it cause a problem?

MTU is maximum transmission unit. It specifies the maximum number of bytes that the interface accepts for each packet. If two interfaces have two different MTUs, bytes might get chopped off and weird things happen—such as random session lockups.

NOTE

Not all packets have a size of 1,500. Running the ls command over SSH might create only a single packet, less than 1,500 bytes. However, running a command with heavy output, such as ps aux, requires several packets of 1,500 bytes.

OK, so where is the MTU issue coming from? Why haven’t we seen this in any other deployment? What’s new in this situation? Well, new data center, new uplink, new switches, new model of switches, new servers, first time using this model of servers…so, basically, everything was new. Wonderful. We toyed around with raising the MTU at various areas: the switches, the NICs on the compute nodes, the virtual NICs in the instances; we even had the data center raise the MTU for our uplink interface. Some changes worked; some didn’t. This line of troubleshooting didn’t feel right, though. We shouldn’t have to be changing the MTU in these areas.

As a last resort, our network admin (Alvaro) and I sat down with four terminal windows, a pencil, and a piece of paper. In one window, we ran ping. In the second window, we ran tcpdump on the cloud controller. In the third, tcpdump on the compute node. And the fourth had tcpdump on the instance. For background, this cloud was a multinode, non-multi-host setup.

One cloud controller acted as a gateway to all compute nodes. VlanManager was used for the network config. This means that the cloud controller and all compute nodes had a different VLAN for each OpenStack project. We used the -s option of ping to change the packet size. We watched as sometimes packets would fully return, sometimes only make it out and never back in, and sometimes stop at a random point. We changed tcpdump to start displaying the hex dump of the packet. We pinged between every combination of outside, controller, compute, and instance.

Finally, Alvaro noticed something. When a packet from the outside hits the cloud controller, it should not be configured with a VLAN. We verified this as true. When the packet went from the cloud controller to the compute node, it should have a VLAN only if it was destined for an instance. This was still true. When the ping reply was sent from the instance, it should be in a VLAN. True. When it came back to the cloud controller and on its way out to the public Internet, it should no longer have a VLAN. False. Uh oh. It looked as though the VLAN part of the packet was not being removed.

That made no sense.

While bouncing this idea around in our heads, I was randomly typing commands on the compute node:

$ ip a

...

10: vlan100@vlan20: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue

master br100 state UP

...

“Hey Alvaro, can you run a VLAN on top of a VLAN?”

“If you did, you’d add an extra four bytes to the packet.”

Then it all made sense:

$ grep vlan_interface /etc/nova/nova.conf

vlan_interface=vlan20

In nova.conf, vlan_interface specifies what interface OpenStack should attach all VLANs to. The correct setting should have been: vlan_interface=bond0.

This would be the server’s bonded NIC.

The vlan20 setting is the VLAN that the data center gave us for outgoing public Internet access. It’s a correct VLAN and is also attached to bond0.

By mistake, I configured OpenStack to attach all tenant VLANs to vlan20 instead of bond0, thereby stacking one VLAN on top of another. This then added an extra four bytes to each packet, which caused a packet of 1,504 bytes to be sent out, which would cause problems when it arrived at an interface that accepted 1,500!

As soon as this setting was fixed, everything worked.

The Issue

At the end of August 2012, a post-secondary school in Alberta, Canada, migrated its infrastructure to an OpenStack cloud. As luck would have it, within the first day or two of it running, one of its servers just disappeared from the network. Blip. Gone.

After restarting the instance, everything was back up and running. We reviewed the logs and saw that at some point, network communication stopped and then everything went idle. We chalked this up to a random occurrence.

A few nights later, it happened again.

We reviewed both sets of logs. The one thing that stood out the most was DHCP. At the time, OpenStack, by default, set DHCP leases for one minute (it’s now two minutes). This means that every instance contacts the cloud controller (DHCP server) to renew its fixed IP. For some reason, this instance could not renew its IP. We correlated the instance’s logs with the logs on the cloud controller and put together a conversation:

1. Instance tries to renew IP.

2. Cloud controller receives the renewal request and sends a response.

3. Instance “ignores” the response and resends the renewal request.

4. Cloud controller receives the second request and sends a new response.

5. Instance begins sending a renewal request to 255.255.255.255, since it hasn’t heard back from the cloud controller.

6. The cloud controller receives the 255.255.255.255 request and sends a third response.

7. The instance finally gives up.

With this information in hand, we were sure that the problem had to do with DHCP. We thought that, for some reason, the instance wasn’t getting a new IP address, and with no IP, it shut itself off from the network.

A quick Google search turned up this: DHCP lease errors in VLAN mode, which further supported our DHCP theory.

An initial idea was to just increase the lease time. If the instance renewed only once every week, the chances of this problem happening would be tremendously smaller than every minute. This didn’t solve the problem, though. It was just covering the problem up.

We decided to have tcpdump run on this instance and see whether we could catch it in action again. Sure enough, we did.

The tcpdump looked very, very weird. In short, it looked as though network communication stopped before the instance tried to renew its IP. Since there is so much DHCP chatter from a one-minute lease, it’s very hard to confirm it, but even with only milliseconds difference between packets, if one packet arrives first, it arrives first, and if that packet reported network issues, then it had to have happened before DHCP.

Additionally, the instance in question was responsible for a very, very large backup job each night. While “the Issue” (as we were now calling it) didn’t happen exactly when the backup happened, it was close enough (a few hours) that we couldn’t ignore it.

More days go by and we catch the Issue in action more and more. We find that dhclient is not running after the Issue happens. Now we’re back to thinking it’s a DHCP problem. Running /etc/init.d/networking restart brings everything back up and running.

Ever have one of those days where all of the sudden you get the Google results you were looking for? Well, that’s what happened here. I was looking for information on dhclient and why it dies when it can’t renew its lease, and all of the sudden I found a bunch of OpenStack and dnsmasq discussions that were identical to the problem we were seeing:

§ “Problem with Heavy Network IO and Dnsmasq”

§ “Instances losing IP address while running, due to No DHCPOFFER”

Seriously, Google.

This bug report was the key to everything: “KVM images lose connectivity with bridged network”.

It was funny to read the report. It was full of people who had some strange network problem but didn’t quite explain it in the same way.

So it was a QEMU/KVM bug.

At the same time I found the bug report, a coworker was able to successfully reproduce the Issue! How? He used iperf to spew a ton of bandwidth at an instance. Within 30 minutes, the instance just disappeared from the network.

Armed with a patched QEMU and a way to reproduce, we set out to see if we had finally solved the Issue. After 48 straight hours of hammering the instance with bandwidth, we were confident. The rest is history. You can search the bug report for “joe” to find my comments and actual tests.

Disappearing Images

At the end of 2012, Cybera (a nonprofit with a mandate to oversee the development of cyberinfrastructure in Alberta, Canada) deployed an updated OpenStack cloud for its DAIR project. A few days into production, a compute node locked up. Upon rebooting the node, I checked to see what instances were hosted on that node so I could boot them on behalf of the customer. Luckily, only one instance.

The nova reboot command wasn’t working, so I used virsh, but it immediately came back with an error saying it was unable to find the backing disk. In this case, the backing disk is the glance image that is copied to /var/lib/nova/instances/_base when the image is used for the first time. Why couldn’t it find it? I checked the directory, and sure enough, it was gone.

I reviewed the nova database and saw the instance’s entry in the nova.instances table. The image that the instance was using matched what virsh was reporting, so no inconsistency there.

I checked glance and noticed that this image was a snapshot that the user created. At least that was good news—this user would have been the only user affected.

Finally, I checked StackTach and reviewed the user’s events. He had created and deleted several snapshots—most likely experimenting. Although the timestamps didn’t match up, my conclusion was that he launched his instance and then deleted the snapshot and it was somehow removed from /var/lib/nova/instances/_base. None of that made sense, but it was the best I could come up with.

It turns out the reason that this compute node locked up was a hardware issue. We removed it from the DAIR cloud and called Dell to have it serviced. Dell arrived and began working. Somehow or another (or a fat finger), a different compute node was bumped and rebooted. Great.

When this node fully booted, I ran through the same scenario of seeing what instances were running so that I could turn them back on. There were a total of four. Three booted and one gave an error. It was the same error as before: unable to find the backing disk. Seriously, what?

Again, it turns out that the image was a snapshot. The three other instances that successfully started were standard cloud images. Was it a problem with snapshots? That didn’t make sense.

A note about DAIR’s architecture: /var/lib/nova/instances is a shared NFS mount. This means that all compute nodes have access to it, which includes the _base directory. Another centralized area is /var/log/rsyslog on the cloud controller. This directory collects all OpenStack logs from all compute nodes. I wondered if there were any entries for the file that virsh is reporting:

dair-ua-c03/nova.log:Dec 19 12:10:59 dair-ua-c03

2012-12-19 12:10:59 INFO nova.virt.libvirt.imagecache

[-] Removing base file:

/var/lib/nova/instances/_base/7b4783508212f5d242cbf9ff56fb8d33b4ce6166_10

Aha! So OpenStack was deleting it. But why?

A feature was introduced in Essex to periodically check and see whether there were any _base files not in use. If there were, nova would delete them. This idea sounds innocent enough and has some good qualities to it. But how did this feature end up turned on? It was disabled by default in Essex, as it should be, but it was decided to enable it in Folsom. I cannot emphasize enough that:

Actions that delete things should not be enabled by default.

Disk space is cheap these days. Data recovery is not.

Secondly, DAIR’s shared /var/lib/nova/instances directory contributed to the problem. Since all compute nodes have access to this directory, all compute nodes periodically review the _base directory. If there is only one instance using an image, and the node that the instance is on is down for a few minutes, it won’t be able to mark the image as still in use. Therefore, the image seems like it’s not in use and is deleted. When the compute node comes back online, the instance hosted on that node is unable to start.

The Valentine’s Day Compute Node Massacre

Although the title of this story is much more dramatic than the actual event, I don’t think, or hope, that I’ll have the opportunity to use “Valentine’s Day Massacre” again in a title.

This past Valentine’s Day, I received an alert that a compute node was no longer available in the cloud—meaning:

$nova-manage service list

showed this particular node with a status of XXX.

I logged in to the cloud controller and was able to both ping and SSH into the problematic compute node, which seemed very odd. Usually when I receive this type of alert, the compute node has totally locked up and would be inaccessible.

After a few minutes of troubleshooting, I saw the following details:

§ A user recently tried launching a CentOS instance on that node.

§ This user was the only user on the node (new node).

§ The load shot up to 8 right before I received the alert.

§ The bonded 10gb network device (bond0) was in a DOWN state.

§ The 1gb NIC was still alive and active.

I looked at the status of both NICs in the bonded pair and saw that neither was able to communicate with the switch port. Seeing as how each NIC in the bond is connected to a separate switch, I thought that the chance of a switch port dying on each switch at the same time was quite improbable. I concluded that the 10gb dual port NIC had died and needed to be replaced. I created a ticket for the hardware support department at the data center where the node was hosted. I felt lucky that this was a new node and no one else was hosted on it yet.

An hour later I received the same alert, but for another compute node. Crap. OK, now there’s definitely a problem going on. Just as with the original node, I was able to log in by SSH. The bond0 NIC was DOWN, but the 1gb NIC was active.

And the best part: the same user had just tried creating a CentOS instance. What?

I was totally confused at this point, so I texted our network admin to see if he was available to help. He logged in to both switches and immediately saw the problem: the switches detected spanning tree packets coming from the two compute nodes and immediately shut the ports down to prevent spanning tree loops:

Feb 15 01:40:18 SW-1 Stp: %SPANTREE-4-BLOCK_BPDUGUARD: Received BPDU packet on

Port-Channel35 with BPDU guard enabled. Disabling interface.

(source mac fa:16:3e:24:e7:22)

Feb 15 01:40:18 SW-1 Ebra: %ETH-4-ERRDISABLE: bpduguard error detected

on Port-Channel35.

Feb 15 01:40:18 SW-1 Mlag: %MLAG-4-INTF_INACTIVE_LOCAL: Local interface

Port-Channel35 is link down. MLAG 35 is inactive.

Feb 15 01:40:18 SW-1 Ebra: %LINEPROTO-5-UPDOWN: Line protocol on Interface

Port-Channel35 (Server35), changed state to down

Feb 15 01:40:19 SW-1 Stp: %SPANTREE-6-INTERFACE_DEL: Interface Port-Channel35

has been removed from instance MST0

Feb 15 01:40:19 SW-1 Ebra: %LINEPROTO-5-UPDOWN: Line protocol on Interface

Ethernet35 (Server35), changed state to down

He reenabled the switch ports, and the two compute nodes immediately came back to life.

Unfortunately, this story has an open ending—we’re still looking into why the CentOS image was sending out spanning tree packets. Further, we’re researching a proper way to mitigate how often this happens. It’s a bigger issue than one might think. While it’s extremely important for switches to prevent spanning tree loops, it’s very problematic to have an entire compute node be cut from the network when this occurs. If a compute node is hosting 100 instances and one of them sends a spanning tree packet, that instance has effectively DDOS’d the other 99 instances.

This is an ongoing and hot topic in networking circles—especially with the rise of virtualization and virtual switches.

Down the Rabbit Hole

Users being able to retrieve console logs from running instances is a boon for support—many times they can figure out what’s going on inside their instance and fix what’s going on without bothering you. Unfortunately, sometimes overzealous logging of failures can cause problems of its own.

A report came in: VMs were launching slowly, or not at all. Cue the standard checks—nothing on the Nagios, but there was a spike in network toward the current master of our RabbitMQ cluster. Investigation started, but soon the other parts of the queue cluster were leaking memory like a sieve. Then the alert came in: the master rabbit server went down. Connections failed over to the slave.

At that time, our control services were hosted by another team. We didn’t have much debugging information to determine what was going on with the master, and couldn’t reboot it. That team noted that the master failed without alert, but they managed to reboot it. After an hour, the cluster had returned to its normal state, and we went home for the day.

Continuing the diagnosis the next morning was kick-started by another identical failure. We quickly got the message queue running again and tried to work out why Rabbit was suffering from so much network traffic. Enabling debug logging on nova-api quickly brought understanding. Atail -f /var/log/nova/nova-api.log was scrolling by faster than we’d ever seen before. CTRL+C on that, and we could plainly see the contents of a system log spewing failures over and over again—a system log from one of our users’ instances.

After finding the instance ID, we headed over to /var/lib/nova/instances to find the console.log:

adm@cc12:/var/lib/nova/instances/instance-00000e05# wc -l console.log

92890453 console.log

adm@cc12:/var/lib/nova/instances/instance-00000e05# ls -sh console.log

5.5G console.log

Sure enough, the user had been periodically refreshing the console log page on the dashboard, and the 5 GB file was traversing the rabbit cluster to get to the dashboard.

We called the user and asked her to stop for a while, and she was happy to abandon the horribly broken VM. After that, we started monitoring the size of console logs.

To this day, the issue doesn’t have a permanent resolution, but we look forward to the discussion at the next summit.

Havana Haunted by the Dead

Felix Lee of Academia Sinica Grid Computing Centre in Taiwan contributed this story.

I just upgraded OpenStack from Grizzly to Havana 2013.2-2 using the RDO repository and everything was running pretty well—except the EC2 API.

I noticed that the API would suffer from a heavy load and respond slowly to particular EC2 requests, such as RunInstances.

Output from /var/log/nova/nova-api.log on Havana:

2014-01-10 09:11:45.072 129745 INFO nova.ec2.wsgi.server

[req-84d16d16-3808-426b-b7af-3b90a11b83b0

0c6e7dba03c24c6a9bce299747499e8a 7052bd6714e7460caeb16242e68124f9]

117.103.103.29 "GET

/services/Cloud?AWSAccessKeyId= \

[something]&Action=RunInstances&ClientToken= \

[something]&ImageId=ami-00000001&InstanceInitiatedShutdownBehavior=terminate...

HTTP/1.1" status: 200 len: 1109 time: 138.5970151

This request took more than two minutes to process, but it executed quickly on another coexisting Grizzly deployment using the same hardware and system configuration.

Output from /var/log/nova/nova-api.log on Grizzly:

2014-01-08 11:15:15.704 INFO nova.ec2.wsgi.server

[req-ccac9790-3357-4aa8-84bd-cdaab1aa394e

ebbd729575cb404081a45c9ada0849b7 8175953c209044358ab5e0ec19d52c37]

117.103.103.29 "GET

/services/Cloud?AWSAccessKeyId= \

[something]&Action=RunInstances&ClientToken= \

[something]&ImageId=ami-00000007&InstanceInitiatedShutdownBehavior=terminate...

HTTP/1.1" status: 200 len: 931 time: 3.9426181

While monitoring system resources, I noticed a significant increase in memory consumption while the EC2 API processed this request. I thought it wasn’t handling memory properly—possibly not releasing memory. If the API received several of these requests, memory consumption quickly grew until the system ran out of RAM and began using swap. Each node has 48 GB of RAM, and the nova-api process would consume all of it within minutes. Once this happened, the entire system would become unusably slow until I restarted the nova-api service.

So, I found myself wondering what changed in the EC2 API on Havana that might cause this to happen. Was it a bug or normal behavior that I now need to work around?

After digging into the nova code, I noticed two areas in api/ec2/cloud.py potentially impacting my system:

instances = self.compute_api.get_all(context,

search_opts=search_opts,

sort_dir='asc')

sys_metas = self.compute_api.get_all_system_metadata(

context, search_filts=[{'key': ['EC2_client_token']},

{'value': [client_token]}])

Since my database contained many records—over 1 million metadata records and over 300,000 instance records in “deleted” or “errored” states—each search took ages. I decided to clean up the database by first archiving a copy for backup and then performing some deletions using the MySQL client. For example, I ran the following SQL command to remove rows of instances deleted for more than a year:

mysql> delete from nova.instances where deleted=1 and terminated_at < (NOW() - INTERVAL 1 YEAR);

Performance increased greatly after deleting the old records, and my new deployment continues to behave well.