Notebook

Dockering¶

This notebook demonstrates how to set up a variety of MongoDB configurations using Linux containers and then experiment with failure modes.

Containers are like virtual machines within a virtual machine. Each MongoDB instance will run inside it's own container, isolated from other MongoDB instances and connected to them via a TCP/IP connection.

To make the setting up containerised MongoDB instances easier, we'll use an application called Docker, which is widely used for supporting virtualisation in cloud hosted systems.

In [ ]:

#Install the docker service - this will be preinstalled in final VM
!sudo apt-get install docker.io
#Install the python docker wrapper - this will be preinstalled in final VM
!pip3 install docker-py

We need to create some docker images - one to run the mongo database server, another (for sharded databases) to act as a configuration server.

In [ ]:

#We're going to use the recipe described by https://sebastianvoss.com/docker-mongodb-sharded-cluster.html
#You should only run this cell once - once you have run it, change the cell from a Code cell to a Raw NBConvert cell
docker_config_mongod='''FROM ubuntu:latest

# Add 10gen official apt source to the sources list
RUN apt-key adv --keyserver hkp://keyserver.ubuntu.com:80 --recv 7F0CEB10
RUN echo 'deb http://downloads-distro.mongodb.org/repo/ubuntu-upstart dist 10gen' | tee /etc/apt/sources.list.d/10gen.list

# Install MongoDB
RUN apt-get update
RUN apt-get install mongodb-10gen

# Create the MongoDB data directory
RUN mkdir -p /data/db

EXPOSE 27017
ENTRYPOINT ["usr/bin/mongod"]'''

docker_config_mongos='''FROM dev24/mongodb:latest

EXPOSE 27017
ENTRYPOINT ["usr/bin/mongos"]'''

!mkdir docker_mongodb_cluster

!mkdir docker_mongodb_cluster/mongod
with open('docker_mongodb_cluster/mongod/Dockerfile','w') as f:
    f.write(docker_config_mongod)
    
!mkdir docker_mongodb_cluster/mongos
with open('docker_mongodb_cluster/mongos/Dockerfile','w') as f:
    f.write(docker_config_mongos)

    
#Create the docker images
%cd docker_mongodb_cluster
!sudo docker.io build -t dev24/mongodb mongod
!sudo docker.io build -t dev24/mongos mongos
%cd /vagrant/notebooks

In [1]:

import docker

In [2]:

#Connect to docker
c = docker.Client(base_url='unix://var/run/docker.sock',
                  version='1.10',
                  timeout=10)

In [229]:

#We can run a mongo database server in a container using the following command:
#
##sudo docker run \
##  -P -name rs1_srv1 \
##  -d dev24/mongodb \
##  --replSet rs1 \
##  --noprealloc --smallfiles
#
#The -P flag is a docker flag, the rest are passed through the mongodb server)
#That is, the following command is run to start each mongo server using a configuration to keep it small for now...:
# usr/bin/mongod --replSet REPLICA_SET_NAME --noprealloc --smallfiles
#Add a -v flag to command to specify verbose stdio logging (increase the number of v's for more... eg -vv or -vvvv)

def createReplicaSetNode(c,stub,num=0):
    ''' Create and run a specified number of mongo database servers as a replica set '''
    name='{stub}_srv{num}'.format(stub=stub,num=num)
    command='--replSet {stub}  --noprealloc --smallfiles'.format(stub=stub)
    c.create_container('dev24/mongodb',name=name,command=command)
    c.start(name,publish_all_ports=True)
    return name

In [105]:

createReplicaSetNode(c,'test')

Out[105]:

'test_srv0'

In [106]:

#Some helper functions via https://github.com/docker/docker-py

#Equivalent of docker ps
def docker_ps(c):
    return c.containers(quiet=False, all=False, trunc=True, latest=False, since=None, before=None, limit=-1)

In [107]:

docker_ps(c)

Out[107]:

[{'Id': 'be65be35905b694f116a1e0f7e53a4f161a82d2c4ed08d8832b96dcb8c3fb628',
  'Ports': [{'PublicPort': 49206,
    'PrivatePort': 27017,
    'Type': 'tcp',
    'IP': '0.0.0.0'}],
  'Status': 'Up 8 seconds',
  'Image': 'dev24/mongodb:latest',
  'Command': 'usr/bin/mongod --replSet test --noprealloc --smallfiles',
  'Created': 1413577005,
  'Names': ['/test_srv0']}]

There are three main ways for addressing each of the containers and the mongo server running within them.

Firstly, we can call the container by name. Typically, in the naming scheme I'm going to use this will take the form rsN_srvMM, where rsN is the name of the replica set and srvMM the server within the set.

Secondly, we can look to a local port to connect to the mongo database server running within a particular container and then connect to that port number.

In [189]:

!docker.io ps | head -n 3

CONTAINER ID        IMAGE                  COMMAND                CREATED              STATUS              PORTS                      NAMES
01cf0f7845f4        dev24/mongodb:latest   usr/bin/mongod --rep   About a minute ago   Up About a minute   0.0.0.0:49215->27017/tcp   rs4_srv2            
8b436ad8d083        dev24/mongodb:latest   usr/bin/mongod --rep   About a minute ago   Up About a minute   0.0.0.0:49214->27017/tcp   rs4_srv1

In [109]:

#Find the local port bound for 27017/tcp for each server in the replica set
def get27017tcp_port(c,container):
    cConfig = c.inspect_container(container)
    return int(cConfig['NetworkSettings']['Ports']['27017/tcp'][0]['HostPort'])

def get27017tcp_ports(c,containers):
    ports={}
    for container in containers:
        ports[container]= get27017tcp_port(c,container)
    return ports

In [111]:

get27017tcp_ports(c,['test_srv0'])

Out[111]:

{'test_srv0': 49206}

Thirdly, we can connect to the default port 27017 on the IP address associated with the container:

In [15]:

def getContainIPaddress(c,container):
    cConfig = c.inspect_container(container)
    return cConfig['NetworkSettings']['IPAddress']

def getContainIPaddresses(c,containers):
    ipaddresses={}
    for container in containers:
        ipaddresses[container]= getContainIPaddress(c,container)
    return ipaddresses

In [112]:

getContainIPaddress(c,'test_srv0')

Out[112]:

'172.17.0.2'

In [92]:

def showContainers(c):
    for xc in c.containers(quiet=False, all=False, trunc=True, latest=False, since=None,
             before=None, limit=-1):
        print(xc['Names'],xc['Status'])

In [204]:

showContainers(c)

In [26]:

#Helper routines for shutting down and removing containers
def tidyAwayContainer(c,container):
    container=container.strip('/')
    c.stop(container)
    c.remove_container(container)
    
def tidyAwayContainers(c,containers):
    for container in containers:
        tidyAwayContainer(c,container)

In [114]:

tidyAwayContainer(c,'test_srv0')

In a real replica set we want multiple servers running. Let's create a function to create several nodes in the same replica set.

In [117]:

#Let's create a function that will create several nodes
def createReplicaSetNodes(c,stub,numNodes):
    ''' Create and run a specified number of mongo database servers as a replica set '''
    names=[]
    for i in range(0,numNodes):
        name=createReplicaSetNode(c,stub,i)
        names.append(name)
    return names

We can initialise the replica set with a particular configuration defined using an object that has the following form:

rs_conf={"_id" : "rs1",
        "members" : [{"_id" : 1, "host" : "localhost:10001"},
                     {"_id" : 2, "host" : "localhost:10002"},
                     {"_id" : 3, "host" : "localhost:10003"} ]}}

In [115]:

def rs_config(c,rsid,num=3):
    ''' Create a replica set of nodes and then define a configuation file for that replica set '''
    createReplicaSetNodes(c,rsid,num)
    _rs_config={"_id" : rsid, 'members':[] }
    #This is scrappy - should really return something better from the creation
    for i in range(0,num):
        name='{stub}_srv{num}'.format(stub=rsid,num=i)
        #c.inspect_container(name)
        #get IP and port
        _rs_config['members'].append({"_id":i,"host":'{0}:{1}'.format(getContainIPaddress(c,name),27017)})
    return _rs_config

In [230]:

tidyAwayContainers(c,['rs4_srv0','rs4_srv1','rs4_srv2'])

In [235]:

rsc=rs_config(c,'rs4')
rsc

Out[235]:

{'_id': 'rs4',
 'members': [{'_id': 0, 'host': '172.17.0.2:27017'},
  {'_id': 1, 'host': '172.17.0.3:27017'},
  {'_id': 2, 'host': '172.17.0.4:27017'}]}

In [236]:

#Initialise the replica set
from pymongo import MongoClient

#We'll use the 0th server in the set as a the node
mc = MongoClient('localhost', get27017tcp_port(c,'rs4_srv0'))

In [237]:

#In the mongo console, we would typically use the command rs.config() to initial the replica set
#Here, we use the replSetInitiate admin command, applying it with the desired configuration
mc.admin.command( "replSetInitiate",rsc);

In [240]:

#We may need to wait a minute or two for the configuration to come up
#If you get an error message that suggests the configuration is up yet, wait a few seconds then rerun the cell
mc.admin.command('replSetGetStatus')

Out[240]:

{'set': 'rs4',
 'myState': 1,
 'members': [{'health': 1.0,
   'stateStr': 'PRIMARY',
   'optime': Timestamp(1413580563, 1),
   'self': True,
   'uptime': 57,
   '_id': 0,
   'optimeDate': datetime.datetime(2014, 10, 17, 21, 16, 3),
   'name': '172.17.0.2:27017',
   'state': 1},
  {'stateStr': 'SECONDARY',
   'pingMs': 0,
   '_id': 1,
   'health': 1.0,
   'name': '172.17.0.3:27017',
   'syncingTo': '172.17.0.2:27017',
   'uptime': 37,
   'optime': Timestamp(1413580563, 1),
   'lastHeartbeat': datetime.datetime(2014, 10, 17, 21, 16, 43),
   'optimeDate': datetime.datetime(2014, 10, 17, 21, 16, 3),
   'state': 2,
   'lastHeartbeatRecv': datetime.datetime(2014, 10, 17, 21, 16, 43)},
  {'stateStr': 'SECONDARY',
   'pingMs': 0,
   '_id': 2,
   'health': 1.0,
   'name': '172.17.0.4:27017',
   'syncingTo': '172.17.0.2:27017',
   'uptime': 37,
   'optime': Timestamp(1413580563, 1),
   'lastHeartbeat': datetime.datetime(2014, 10, 17, 21, 16, 43),
   'optimeDate': datetime.datetime(2014, 10, 17, 21, 16, 3),
   'state': 2,
   'lastHeartbeatRecv': datetime.datetime(2014, 10, 17, 21, 16, 43)}],
 'date': datetime.datetime(2014, 10, 17, 21, 16, 44),
 'ok': 1.0}

In [241]:

from pymongo import MongoReplicaSetClient

testclient= MongoReplicaSetClient('{0}:{1}'.format(getContainIPaddress(c,'rs4_srv0'),27017), replicaSet='rs4')
testdb=testclient.testdb
testcollection=testdb.testcollection

In [242]:

testcollection.insert({'name':'test1'})

Out[242]:

ObjectId('5441874630e3dd0a4a4ee018')

In [266]:

for x in range(0,10):
    testcollection.insert({'name':'test'+str(x)})

In [244]:

for ff in testcollection.find():
    print(ff)

{'_id': ObjectId('5441874630e3dd0a4a4ee018'), 'name': 'test1'}
{'_id': ObjectId('5441874830e3dd0a4a4ee019'), 'name': 'test0'}
{'_id': ObjectId('5441874830e3dd0a4a4ee01a'), 'name': 'test1'}
{'_id': ObjectId('5441874830e3dd0a4a4ee01b'), 'name': 'test2'}
{'_id': ObjectId('5441874830e3dd0a4a4ee01c'), 'name': 'test3'}
{'_id': ObjectId('5441874830e3dd0a4a4ee01d'), 'name': 'test4'}
{'_id': ObjectId('5441874830e3dd0a4a4ee01e'), 'name': 'test5'}
{'_id': ObjectId('5441874830e3dd0a4a4ee01f'), 'name': 'test6'}
{'_id': ObjectId('5441874830e3dd0a4a4ee020'), 'name': 'test7'}
{'_id': ObjectId('5441874830e3dd0a4a4ee021'), 'name': 'test8'}
{'_id': ObjectId('5441874830e3dd0a4a4ee022'), 'name': 'test9'}

We can model network failures by setting up firewall rules to block messages being passed between particular containers.

In [222]:

##https://github.com/dcm-oss/blockade/

#
#  Copyright (C) 2014 Dell, Inc.
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
#     http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.
#

import random
import string
import subprocess

import collections


#---errors.py
class BlockadeError(Exception):
    """Expected error within Blockade
    """


class BlockadeConfigError(BlockadeError):
    """Error in configuration
    """


class AlreadyInitializedError(BlockadeError):
    """Blockade already created in this context
    """


class NotInitializedError(BlockadeError):
    """Blockade not created in this context
    """


class InconsistentStateError(BlockadeError):
    """Blockade state is inconsistent (partially created or destroyed)
    """
    
#---



def parse_partition_index(blockade_id, chain):
    prefix = "%s-p" % (blockade_id,)
    if chain and chain.startswith(prefix):
        try:
            return int(chain[len(prefix):])
        except ValueError:
            pass
    raise ValueError("chain %s is not a blockade partition" % (chain,))


def partition_chain_name(blockade_id, partition_index):
    return "%s-p%s" % (blockade_id, partition_index)


def iptables_call_output(*args):
    cmd = ["iptables", "-n"] + list(args)
    try:
        output = subprocess.check_output(cmd)
        return output.decode().split("\n")
    except subprocess.CalledProcessError:
        raise BlockadeError("Problem calling '%s'" % " ".join(cmd))


def iptables_call(*args):
    cmd = ["iptables"] + list(args)
    try:
        subprocess.check_call(cmd)
    except subprocess.CalledProcessError:
        raise BlockadeError("Problem calling '%s'" % " ".join(cmd))


def iptables_get_chain_rules(chain):
    if not chain:
        raise ValueError("invalid chain")
    lines = iptables_call_output("-L", chain)
    if len(lines) < 2:
        raise BlockadeError("Can't understand iptables output: \n%s" %
                            "\n".join(lines))

    chain_line, header_line = lines[:2]
    if not (chain_line.startswith("Chain " + chain) and
            header_line.startswith("target")):
        raise BlockadeError("Can't understand iptables output: \n%s" %
                            "\n".join(lines))
    return lines[2:]


def iptables_get_source_chains(blockade_id):
    """Get a map of blockade chains IDs -> list of IPs targeted at them

    For figuring out which container is in which partition
    """
    result = {}
    if not blockade_id:
        raise ValueError("invalid blockade_id")
    lines = iptables_get_chain_rules("FORWARD")

    for line in lines:
        parts = line.split()
        if len(parts) < 4:
            continue
        try:
            partition_index = parse_partition_index(blockade_id, parts[0])
        except ValueError:
            continue  # not a rule targetting a blockade chain

        source = parts[3]
        if source:
            result[source] = partition_index
    return result


def iptables_delete_rules(chain, predicate):
    if not chain:
        raise ValueError("invalid chain")
    if not isinstance(predicate, collections.Callable):
        raise ValueError("invalid predicate")

    lines = iptables_get_chain_rules(chain)

    # TODO this is susceptible to check-then-act races.
    # better to ultimately switch to python-iptables if it becomes less buggy
    for index, line in reversed(list(enumerate(lines, 1))):
        line = line.strip()
        if line and predicate(line):
            iptables_call("-D", chain, str(index))


def iptables_delete_blockade_rules(blockade_id):
    def predicate(rule):
        target = rule.split()[0]
        try:
            parse_partition_index(blockade_id, target)
        except ValueError:
            return False
        return True
    iptables_delete_rules("FORWARD", predicate)


def iptables_delete_blockade_chains(blockade_id):
    if not blockade_id:
        raise ValueError("invalid blockade_id")

    lines = iptables_call_output("-L")
    for line in lines:
        parts = line.split()
        if len(parts) >= 2 and parts[0] == "Chain":
            chain = parts[1]
            try:
                parse_partition_index(blockade_id, chain)
            except ValueError:
                continue
            # if we are a valid blockade chain, flush and delete
            iptables_call("-F", chain)
            iptables_call("-X", chain)


def iptables_insert_rule(chain, src=None, dest=None, target=None):
    """Insert a new rule in the chain
    """
    if not chain:
        raise ValueError("Invalid chain")
    if not target:
        raise ValueError("Invalid target")
    if not (src or dest):
        raise ValueError("Need src, dest, or both")

    args = ["-I", chain]
    if src:
        args += ["-s", src]
    if dest:
        args += ["-d", dest]
    args += ["-j", target]
    iptables_call(*args)


def iptables_create_chain(chain):
    """Create a new chain
    """
    if not chain:
        raise ValueError("Invalid chain")
    iptables_call("-N", chain)


def clear_iptables(blockade_id):
    """Remove all iptables rules and chains related to this blockade
    """
    # first remove refererences to our custom chains
    iptables_delete_blockade_rules(blockade_id)

    # then remove the chains themselves
    iptables_delete_blockade_chains(blockade_id)


def partition_containers(blockade_id, partitions):
    if not partitions or len(partitions) == 1:
        return
    for index, partition in enumerate(partitions, 1):
        chain_name = partition_chain_name(blockade_id, index)

        # create chain for partition and block traffic TO any other partition
        iptables_create_chain(chain_name)
        for other in partitions:
            if partition is other:
                continue
            for container in other:
                if container.ip_address:
                    iptables_insert_rule(chain_name, dest=container.ip_address,
                                         target="DROP")

        # direct traffic FROM any container in the partition to the new chain
        for container in partition:
            iptables_insert_rule("FORWARD", src=container.ip_address,
                                 target=chain_name)

In [223]:

class netobj():
    def __init__(self, ip_address):
        self.ip_address = ip_address

We assign the IP addresses of the containers into different partitions.

In [267]:

#In this case, let's be cruel and put the primary in a partition on its own
partition_containers('test1w2s2', [ [netobj('172.17.0.2')],[netobj('172.17.0.3'),netobj('172.17.0.4')]])
#Wait a bit before generating the log...

In [249]:

#In an ssh shell, we can use the follow sort of command to look at a real time stream of stdio log messages from the container
#!docker.io logs --follow=true rs4_srv1
#testcollection.insert({'name':'test3'})
!docker.io logs rs4_srv0 > rs4_srv0_log.txt
!docker.io logs rs4_srv1 > rs4_srv1_log.txt
!docker.io logs rs4_srv2 > rs4_srv2_log.txt

In [250]:

!tail -n 30 rs4_srv0_log.txt

Fri Oct 17 21:16:54.782 [FileAllocator] done allocating datafile /data/db/testdb.ns, size: 16MB,  took 0.029 secs
Fri Oct 17 21:16:54.801 [FileAllocator] allocating new datafile /data/db/testdb.0, filling with zeroes...
Fri Oct 17 21:16:54.836 [FileAllocator] done allocating datafile /data/db/testdb.0, size: 16MB,  took 0.034 secs
Fri Oct 17 21:16:54.837 [conn16] build index testdb.testcollection { _id: 1 }
Fri Oct 17 21:16:54.837 [conn16] build index done.  scanned 0 total records. 0 secs
Fri Oct 17 21:17:23.781 [conn17] end connection 172.17.0.3:44992 (8 connections now open)
Fri Oct 17 21:17:23.782 [initandlisten] connection accepted from 172.17.0.3:45399 #19 (9 connections now open)
Fri Oct 17 21:17:23.808 [conn18] end connection 172.17.0.4:56665 (8 connections now open)
Fri Oct 17 21:17:23.808 [initandlisten] connection accepted from 172.17.0.4:57073 #20 (9 connections now open)
Fri Oct 17 21:17:53.799 [conn19] end connection 172.17.0.3:45399 (8 connections now open)
Fri Oct 17 21:17:53.800 [initandlisten] connection accepted from 172.17.0.3:45802 #21 (9 connections now open)
Fri Oct 17 21:17:53.828 [conn20] end connection 172.17.0.4:57073 (8 connections now open)
Fri Oct 17 21:17:53.829 [initandlisten] connection accepted from 172.17.0.4:57476 #22 (9 connections now open)
Fri Oct 17 21:18:05.574 [rsHealthPoll] DBClientCursor::init call() failed
Fri Oct 17 21:18:05.574 [rsHealthPoll] DBClientCursor::init call() failed
Fri Oct 17 21:18:05.575 [rsHealthPoll] replSet info 172.17.0.3:27017 is down (or slow to respond): 
Fri Oct 17 21:18:05.575 [rsHealthPoll] replSet member 172.17.0.3:27017 is now in state DOWN
Fri Oct 17 21:18:05.575 [rsHealthPoll] replSet info 172.17.0.4:27017 is down (or slow to respond): 
Fri Oct 17 21:18:05.575 [rsHealthPoll] replSet member 172.17.0.4:27017 is now in state DOWN
Fri Oct 17 21:18:05.575 [rsMgr] can't see a majority of the set, relinquishing primary
Fri Oct 17 21:18:05.575 [rsMgr] replSet relinquishing primary state
Fri Oct 17 21:18:05.575 [rsMgr] replSet SECONDARY
Fri Oct 17 21:18:05.575 [rsMgr] replSet closing client sockets after relinquishing primary
Fri Oct 17 21:18:05.576 [conn15] end connection 172.17.0.4:56332 (8 connections now open)
Fri Oct 17 21:18:05.576 [conn13] end connection 172.17.0.4:56324 (7 connections now open)
Fri Oct 17 21:18:05.576 [conn12] end connection 172.17.0.3:44651 (6 connections now open)
Fri Oct 17 21:18:05.576 [conn1] end connection 172.17.42.1:55245 (5 connections now open)
Fri Oct 17 21:18:05.576 [conn16] end connection 172.17.42.1:56065 (4 connections now open)
Fri Oct 17 21:18:05.577 [conn14] end connection 172.17.0.3:44657 (3 connections now open)
Fri Oct 17 21:18:05.577 [conn2] end connection 172.17.42.1:55325 (2 connections now open)

In [251]:

!tail rs4_srv1_log.txt

Fri Oct 17 21:17:07.813 [conn8] end connection 172.17.0.4:60922 (3 connections now open)
Fri Oct 17 21:17:07.813 [initandlisten] connection accepted from 172.17.0.4:33102 #11 (5 connections now open)
Fri Oct 17 21:17:21.542 [conn9] end connection 172.17.0.2:54062 (3 connections now open)
Fri Oct 17 21:17:21.542 [initandlisten] connection accepted from 172.17.0.2:54471 #12 (5 connections now open)
Fri Oct 17 21:17:37.833 [conn11] end connection 172.17.0.4:33102 (3 connections now open)
Fri Oct 17 21:17:37.834 [initandlisten] connection accepted from 172.17.0.4:33504 #13 (5 connections now open)
Fri Oct 17 21:17:51.568 [conn12] end connection 172.17.0.2:54471 (3 connections now open)
Fri Oct 17 21:17:51.570 [initandlisten] connection accepted from 172.17.0.2:54876 #14 (4 connections now open)
Fri Oct 17 21:18:05.797 [rsHealthPoll] DBClientCursor::init call() failed
Fri Oct 17 21:18:05.798 [rsHealthPoll] replset info 172.17.0.2:27017 heartbeat failed, retrying

In [252]:

!tail rs4_srv2_log.txt

Fri Oct 17 21:17:05.532 [conn7] end connection 172.17.0.2:49448 (3 connections now open)
Fri Oct 17 21:17:05.533 [initandlisten] connection accepted from 172.17.0.2:49858 #10 (4 connections now open)
Fri Oct 17 21:17:07.771 [conn8] end connection 172.17.0.3:51615 (3 connections now open)
Fri Oct 17 21:17:07.772 [initandlisten] connection accepted from 172.17.0.3:52028 #11 (4 connections now open)
Fri Oct 17 21:17:35.551 [conn10] end connection 172.17.0.2:49858 (3 connections now open)
Fri Oct 17 21:17:35.551 [initandlisten] connection accepted from 172.17.0.2:50261 #12 (5 connections now open)
Fri Oct 17 21:17:37.789 [conn11] end connection 172.17.0.3:52028 (3 connections now open)
Fri Oct 17 21:17:37.790 [initandlisten] connection accepted from 172.17.0.3:52430 #13 (4 connections now open)
Fri Oct 17 21:18:05.829 [rsHealthPoll] DBClientCursor::init call() failed
Fri Oct 17 21:18:05.829 [rsHealthPoll] replset info 172.17.0.2:27017 heartbeat failed, retrying

In [265]:

#!sudo iptables -L
#Clear the network problems...
clear_iptables('test1w2s2')
#Wait a bit before generating the log...

In [254]:

#In an ssh shell, we can use the follow sort of command to look at a real time stream of stdio log messages from the container
#!docker.io logs --follow=true rs4_srv1
#testcollection.insert({'name':'test3'})
!docker.io logs rs4_srv0 > rs4_srv0_log.txt
!docker.io logs rs4_srv1 > rs4_srv1_log.txt
!docker.io logs rs4_srv2 > rs4_srv2_log.txt

In [256]:

!tail -n 30 rs4_srv0_log.txt

Fri Oct 17 21:18:05.577 [conn14] end connection 172.17.0.3:44657 (3 connections now open)
Fri Oct 17 21:18:05.577 [conn2] end connection 172.17.42.1:55325 (2 connections now open)
Fri Oct 17 21:18:13.580 [rsHealthPoll] replset info 172.17.0.3:27017 heartbeat failed, retrying
Fri Oct 17 21:18:13.581 [rsHealthPoll] replset info 172.17.0.4:27017 heartbeat failed, retrying
Fri Oct 17 21:18:17.579 [rsMgr] replSet can't see a majority, will not try to elect self
Fri Oct 17 21:18:22.307 [initandlisten] connection accepted from 172.17.42.1:57290 #23 (3 connections now open)
Fri Oct 17 21:18:25.579 [rsHealthPoll] replset info 172.17.0.3:27017 heartbeat failed, retrying
Fri Oct 17 21:18:25.579 [rsHealthPoll] replset info 172.17.0.4:27017 heartbeat failed, retrying
Fri Oct 17 21:18:37.581 [rsHealthPoll] replset info 172.17.0.3:27017 heartbeat failed, retrying
Fri Oct 17 21:18:37.581 [rsHealthPoll] replset info 172.17.0.4:27017 heartbeat failed, retrying
Fri Oct 17 21:18:49.584 [rsHealthPoll] replset info 172.17.0.3:27017 heartbeat failed, retrying
Fri Oct 17 21:18:49.584 [rsHealthPoll] replset info 172.17.0.4:27017 heartbeat failed, retrying
Fri Oct 17 21:19:01.585 [rsHealthPoll] replset info 172.17.0.3:27017 heartbeat failed, retrying
Fri Oct 17 21:19:01.590 [rsHealthPoll] couldn't connect to 172.17.0.4:27017: couldn't connect to server 172.17.0.4:27017
Fri Oct 17 21:19:07.592 [rsHealthPoll] couldn't connect to 172.17.0.4:27017: couldn't connect to server 172.17.0.4:27017
Fri Oct 17 21:19:08.834 [initandlisten] connection accepted from 172.17.0.4:58525 #24 (4 connections now open)
Fri Oct 17 21:19:09.802 [initandlisten] connection accepted from 172.17.0.3:46852 #25 (5 connections now open)
Fri Oct 17 21:19:10.592 [rsHealthPoll] replSet member 172.17.0.3:27017 is up
Fri Oct 17 21:19:10.592 [rsHealthPoll] replSet member 172.17.0.3:27017 is now in state SECONDARY
Fri Oct 17 21:19:10.592 [rsMgr] not electing self, 172.17.0.3:27017 would veto with '172.17.0.2:27017 is trying to elect itself but 172.17.0.4:27017 is already primary and more up-to-date'
Fri Oct 17 21:19:10.594 [rsHealthPoll] replSet member 172.17.0.4:27017 is up
Fri Oct 17 21:19:10.594 [rsHealthPoll] replSet member 172.17.0.4:27017 is now in state PRIMARY
Fri Oct 17 21:19:11.592 [rsBackgroundSync] replSet syncing to: 172.17.0.4:27017
Fri Oct 17 21:19:12.542 [rsSyncNotifier] replset setting oplog notifier to 172.17.0.4:27017
Fri Oct 17 21:19:12.546 [rsSyncNotifier] build index local.me { _id: 1 }
Fri Oct 17 21:19:12.548 [rsSyncNotifier] build index done.  scanned 0 total records. 0.001 secs
Fri Oct 17 21:19:24.850 [conn24] end connection 172.17.0.4:58525 (4 connections now open)
Fri Oct 17 21:19:24.850 [initandlisten] connection accepted from 172.17.0.4:58739 #26 (5 connections now open)
Fri Oct 17 21:19:25.812 [conn25] end connection 172.17.0.3:46852 (4 connections now open)
Fri Oct 17 21:19:25.814 [initandlisten] connection accepted from 172.17.0.3:47081 #27 (5 connections now open)

In [257]:

!tail rs4_srv1_log.txt

Fri Oct 17 21:18:50.800 [rsHealthPoll] replset info 172.17.0.2:27017 heartbeat failed, retrying
Fri Oct 17 21:19:02.801 [rsHealthPoll] replset info 172.17.0.2:27017 heartbeat failed, retrying
Fri Oct 17 21:19:07.897 [conn16] end connection 172.17.0.4:34328 (3 connections now open)
Fri Oct 17 21:19:07.898 [initandlisten] connection accepted from 172.17.0.4:34753 #17 (5 connections now open)
Fri Oct 17 21:19:09.803 [rsHealthPoll] replset info 172.17.0.2:27017 thinks that we are down
Fri Oct 17 21:19:09.803 [rsHealthPoll] replSet member 172.17.0.2:27017 is up
Fri Oct 17 21:19:09.804 [rsHealthPoll] replSet member 172.17.0.2:27017 is now in state SECONDARY
Fri Oct 17 21:19:10.590 [initandlisten] connection accepted from 172.17.0.2:55935 #18 (5 connections now open)
Fri Oct 17 21:19:24.600 [conn18] end connection 172.17.0.2:55935 (4 connections now open)
Fri Oct 17 21:19:24.600 [initandlisten] connection accepted from 172.17.0.2:56166 #19 (5 connections now open)

In [258]:

!tail rs4_srv2_log.txt

Fri Oct 17 21:19:08.835 [rsHealthPoll] replset info 172.17.0.2:27017 thinks that we are down
Fri Oct 17 21:19:08.835 [rsHealthPoll] replSet member 172.17.0.2:27017 is up
Fri Oct 17 21:19:08.836 [rsHealthPoll] replSet member 172.17.0.2:27017 is now in state SECONDARY
Fri Oct 17 21:19:10.593 [initandlisten] connection accepted from 172.17.0.2:51538 #18 (6 connections now open)
Fri Oct 17 21:19:11.592 [initandlisten] connection accepted from 172.17.0.2:51596 #19 (7 connections now open)
Fri Oct 17 21:19:12.543 [initandlisten] connection accepted from 172.17.0.2:51610 #20 (8 connections now open)
Fri Oct 17 21:19:12.594 [conn18] end connection 172.17.0.2:51538 (7 connections now open)
Fri Oct 17 21:19:12.595 [initandlisten] connection accepted from 172.17.0.2:51612 #21 (8 connections now open)
Fri Oct 17 21:19:13.554 [slaveTracking] build index local.slaves { _id: 1 }
Fri Oct 17 21:19:13.556 [slaveTracking] build index done.  scanned 0 total records. 0.002 secs

In [ ]:

#Create a new problem - this time we partition of a single secondary server
partition_containers('test1w2s2', [ [netobj('172.17.0.4')],[netobj('172.17.0.3'),netobj('172.17.0.2')]])
#Wait a bit before generating the log...

In [273]:

#In an ssh shell, we can use the follow sort of command to look at a real time stream of stdio log messages from the container
#!docker.io logs --follow=true rs4_srv1
#testcollection.insert({'name':'test3'})
!docker.io logs rs4_srv0 > rs4_srv0_log.txt
!docker.io logs rs4_srv1 > rs4_srv1_log.txt
!docker.io logs rs4_srv2 > rs4_srv2_log.txt

In [274]:

!tail -n 30 rs4_srv0_log.txt

Fri Oct 17 21:20:55.879 [initandlisten] connection accepted from 172.17.0.3:48294 #33 (6 connections now open)
Fri Oct 17 21:21:24.927 [conn32] end connection 172.17.0.4:59953 (4 connections now open)
Fri Oct 17 21:21:24.927 [initandlisten] connection accepted from 172.17.0.4:60360 #34 (6 connections now open)
Fri Oct 17 21:21:25.900 [conn33] end connection 172.17.0.3:48294 (4 connections now open)
Fri Oct 17 21:21:25.900 [initandlisten] connection accepted from 172.17.0.3:48702 #35 (6 connections now open)
Fri Oct 17 21:21:54.950 [conn34] end connection 172.17.0.4:60360 (4 connections now open)
Fri Oct 17 21:21:54.951 [initandlisten] connection accepted from 172.17.0.4:60777 #36 (5 connections now open)
Fri Oct 17 21:21:55.920 [initandlisten] connection accepted from 172.17.0.3:49119 #37 (6 connections now open)
Fri Oct 17 21:21:55.920 [conn35] end connection 172.17.0.3:48702 (5 connections now open)
Fri Oct 17 21:22:24.973 [conn36] end connection 172.17.0.4:60777 (4 connections now open)
Fri Oct 17 21:22:24.974 [initandlisten] connection accepted from 172.17.0.4:32959 #38 (5 connections now open)
Fri Oct 17 21:22:25.944 [conn37] end connection 172.17.0.3:49119 (4 connections now open)
Fri Oct 17 21:22:25.945 [initandlisten] connection accepted from 172.17.0.3:49533 #39 (6 connections now open)
Fri Oct 17 21:22:32.339 [rsSync] build index local.replset.minvalid { _id: 1 }
Fri Oct 17 21:22:32.342 [rsSync] build index done.  scanned 0 total records. 0 secs
Fri Oct 17 21:22:54.725 [rsHealthPoll] DBClientCursor::init call() failed
Fri Oct 17 21:22:54.725 [rsHealthPoll] replset info 172.17.0.4:27017 heartbeat failed, retrying
Fri Oct 17 21:22:54.754 [conn21] end connection 172.17.0.3:45802 (4 connections now open)
Fri Oct 17 21:22:55.726 [rsHealthPoll] replSet info 172.17.0.4:27017 is down (or slow to respond): 
Fri Oct 17 21:22:55.726 [rsHealthPoll] replSet member 172.17.0.4:27017 is now in state DOWN
Fri Oct 17 21:22:55.727 [rsMgr] replSet info electSelf 0
Fri Oct 17 21:22:55.964 [conn39] end connection 172.17.0.3:49533 (3 connections now open)
Fri Oct 17 21:22:55.964 [initandlisten] connection accepted from 172.17.0.3:49942 #40 (4 connections now open)
Fri Oct 17 21:23:03.728 [rsHealthPoll] replset info 172.17.0.4:27017 heartbeat failed, retrying
Fri Oct 17 21:23:12.373 [rsBackgroundSync] Socket recv() timeout  172.17.0.4:27017
Fri Oct 17 21:23:12.374 [rsBackgroundSync] SocketException: remote: 172.17.0.4:27017 error: 9001 socket exception [RECV_TIMEOUT] server [172.17.0.4:27017] 
Fri Oct 17 21:23:12.375 [rsBackgroundSync] replSet sync source problem: 10278 dbclient error communicating with server: 172.17.0.4:27017
Fri Oct 17 21:23:12.375 [rsMgr] replSet PRIMARY
Fri Oct 17 21:23:14.376 [initandlisten] connection accepted from 172.17.0.3:50202 #41 (5 connections now open)
Fri Oct 17 21:23:15.727 [rsHealthPoll] replset info 172.17.0.4:27017 heartbeat failed, retrying

In [276]:

!tail -n 20 rs4_srv1_log.txt

Fri Oct 17 21:22:32.335 [rsSyncNotifier]   caught exception (socket exception [SEND_ERROR] for 172.17.0.2:27017) in destructor (~PiggyBackData)
Fri Oct 17 21:22:53.574 [conn14] end connection 172.17.0.2:54876 (5 connections now open)
Fri Oct 17 21:22:53.953 [rsHealthPoll] DBClientCursor::init call() failed
Fri Oct 17 21:22:53.954 [rsHealthPoll] replset info 172.17.0.4:27017 heartbeat failed, retrying
Fri Oct 17 21:22:54.731 [conn30] end connection 172.17.0.2:58618 (4 connections now open)
Fri Oct 17 21:22:54.731 [initandlisten] connection accepted from 172.17.0.2:59027 #32 (5 connections now open)
Fri Oct 17 21:22:54.954 [rsHealthPoll] replSet info 172.17.0.4:27017 is down (or slow to respond): 
Fri Oct 17 21:22:54.954 [rsHealthPoll] replSet member 172.17.0.4:27017 is now in state DOWN
Fri Oct 17 21:22:54.955 [rsMgr] not electing self, 172.17.0.2:27017 would veto with '172.17.0.3:27017 is trying to elect itself but 172.17.0.4:27017 is already primary and more up-to-date'
Fri Oct 17 21:22:55.727 [conn32] replSet info voting yea for 172.17.0.2:27017 (0)
Fri Oct 17 21:23:00.573 [rsMgr] replSet not trying to elect self as responded yea to someone else recently
Fri Oct 17 21:23:02.955 [rsHealthPoll] replset info 172.17.0.4:27017 heartbeat failed, retrying
Fri Oct 17 21:23:06.042 [rsMgr] replSet not trying to elect self as responded yea to someone else recently
Fri Oct 17 21:23:12.373 [rsBackgroundSync] Socket recv() timeout  172.17.0.4:27017
Fri Oct 17 21:23:12.374 [rsBackgroundSync] SocketException: remote: 172.17.0.4:27017 error: 9001 socket exception [RECV_TIMEOUT] server [172.17.0.4:27017] 
Fri Oct 17 21:23:12.374 [rsBackgroundSync] replSet sync source problem: 10278 dbclient error communicating with server: 172.17.0.4:27017
Fri Oct 17 21:23:12.612 [rsMgr] not electing self, 172.17.0.2:27017 would veto with 'I am already primary, 172.17.0.3:27017 can try again once I've stepped down'
Fri Oct 17 21:23:13.978 [rsHealthPoll] replSet member 172.17.0.2:27017 is now in state PRIMARY
Fri Oct 17 21:23:14.375 [rsBackgroundSync] replSet syncing to: 172.17.0.2:27017
Fri Oct 17 21:23:14.954 [rsHealthPoll] replset info 172.17.0.4:27017 heartbeat failed, retrying

In [277]:

!tail -n 20 rs4_srv2_log.txt

Fri Oct 17 21:22:54.987 [rsHealthPoll] replset info 172.17.0.2:27017 heartbeat failed, retrying
Fri Oct 17 21:22:55.026 [rsHealthPoll] replSet info 172.17.0.3:27017 is down (or slow to respond): 
Fri Oct 17 21:22:55.026 [rsHealthPoll] replSet member 172.17.0.3:27017 is now in state DOWN
Fri Oct 17 21:22:55.986 [rsHealthPoll] replSet info 172.17.0.2:27017 is down (or slow to respond): 
Fri Oct 17 21:22:55.986 [rsHealthPoll] replSet member 172.17.0.2:27017 is now in state DOWN
Fri Oct 17 21:22:55.986 [rsMgr] can't see a majority of the set, relinquishing primary
Fri Oct 17 21:22:55.986 [rsMgr] replSet relinquishing primary state
Fri Oct 17 21:22:55.986 [rsMgr] replSet SECONDARY
Fri Oct 17 21:22:55.986 [rsMgr] replSet closing client sockets after relinquishing primary
Fri Oct 17 21:22:55.986 [conn9] end connection 172.17.42.1:34964 (9 connections now open)
Fri Oct 17 21:22:55.987 [conn33] end connection 172.17.0.3:56297 (9 connections now open)
Fri Oct 17 21:22:55.987 [conn1] end connection 172.17.42.1:34221 (9 connections now open)
Fri Oct 17 21:22:55.987 [conn19] end connection 172.17.0.2:51596 (9 connections now open)
Fri Oct 17 21:22:55.987 [conn20] end connection 172.17.0.2:51610 (9 connections now open)
Fri Oct 17 21:22:55.987 [conn34] end connection 172.17.0.3:56464 (9 connections now open)
Fri Oct 17 21:23:03.027 [rsHealthPoll] replset info 172.17.0.3:27017 heartbeat failed, retrying
Fri Oct 17 21:23:03.988 [rsHealthPoll] replset info 172.17.0.2:27017 heartbeat failed, retrying
Fri Oct 17 21:23:07.026 [rsMgr] replSet can't see a majority, will not try to elect self
Fri Oct 17 21:23:15.030 [rsHealthPoll] replset info 172.17.0.3:27017 heartbeat failed, retrying
Fri Oct 17 21:23:15.990 [rsHealthPoll] replset info 172.17.0.2:27017 heartbeat failed, retrying

In [ ]:

#–--JUNK BELOW HERE

In [234]:

!sudo iptables -L

Chain INPUT (policy ACCEPT)
target     prot opt source               destination         

Chain FORWARD (policy ACCEPT)
target     prot opt source               destination         
ACCEPT     all  --  anywhere             anywhere             ctstate RELATED,ESTABLISHED
ACCEPT     all  --  anywhere             anywhere            
ACCEPT     all  --  anywhere             anywhere            

Chain OUTPUT (policy ACCEPT)
target     prot opt source               destination         

Chain test1-p1 (0 references)
target     prot opt source               destination         

Chain test1-pu76 (0 references)
target     prot opt source               destination         

Chain test12-p1 (0 references)
target     prot opt source               destination         

Chain test122-p1 (0 references)
target     prot opt source               destination

In [ ]:

In [103]:

# !netstat -lntu

Out[103]:

['local']

In [26]:

!more  /etc/default/docker.io

# Docker Upstart and SysVinit configuration file

# Customize location of Docker binary (especially for development testing).
#DOCKER="/usr/local/bin/docker"

# Use DOCKER_OPTS to modify the daemon startup options.
#DOCKER_OPTS="-dns 8.8.8.8 -dns 8.8.4.4"

# If you need Docker to use an HTTP proxy, it can also be specified here.
#export http_proxy="http://127.0.0.1:3128/"

# This is also a handy place to tweak where Docker's temporary files go.
#export TMPDIR="/mnt/bigdrive/docker-tmp"

In [32]:

!sudo docker.io run -P -name rs2_srv4  -d dev24/mongodb --replSet rs2 --noprealloc --smallfiles

Warning: '-name' is deprecated, it will be replaced by '--name' soon. See usage.
c3e21243cf1ed59236f2b5be5f3d287a62d8b77b8b03c3c25afac946e69eaf08

class NetworkState(object): NORMAL = "NORMAL" SLOW = "SLOW" FLAKY = "FLAKY" UNKNOWN = "UNKNOWN" class BlockadeNetwork(object): def __init__(self, config): self.config = config def new_veth_device_name(self): chars = string.ascii_letters + string.digits return "veth" + "".join(random.choice(chars) for _ in range(8)) def network_state(self, device): return network_state(device) def flaky(self, device): flaky_config = self.config.network['flaky'].split() traffic_control_netem(device, ["loss"] + flaky_config) def slow(self, device): slow_config = self.config.network['slow'].split() traffic_control_netem(device, ["delay"] + slow_config) def fast(self, device): traffic_control_restore(device) def restore(self, blockade_id): clear_iptables(blockade_id) def partition_containers(self, blockade_id, partitions): clear_iptables(blockade_id) partition_containers(blockade_id, partitions) def get_ip_partitions(self, blockade_id): return iptables_get_source_chains(blockade_id) def traffic_control_restore(device): cmd = ["tc", "qdisc", "del", "dev", device, "root"] p = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) _, stderr = p.communicate() stderr = stderr.decode() if p.returncode != 0: if p.returncode == 2 and stderr: if "No such file or directory" in stderr: return # TODO log error somewhere? raise BlockadeError("Problem calling traffic control: " + " ".join(cmd)) def traffic_control_netem(device, params): try: cmd = ["tc", "qdisc", "replace", "dev", device, "root", "netem"] + params subprocess.check_call(cmd) except subprocess.CalledProcessError: # TODO log error somewhere? raise BlockadeError("Problem calling traffic control: " + " ".join(cmd)) def network_state(device): try: output = subprocess.check_output( ["tc", "qdisc", "show", "dev", device]).decode() # sloppy but good enough for now if " delay " in output: return NetworkState.SLOW if " loss " in output: return NetworkState.FLAKY return NetworkState.NORMAL except subprocess.CalledProcessError: # TODO log error somewhere? return NetworkState.UNKNOWN

In [ ]:

#!netstat -lntu

In [187]:

!sudo docker.io ps --all #--no-trunc

CONTAINER ID        IMAGE                  COMMAND                CREATED             STATUS              PORTS                      NAMES
19daf983bcb5        dev24/mongodb:latest   usr/bin/mongod --rep   19 hours ago        Up 19 hours         27017/tcp                  rs3_srv2            
c3e21243cf1e        dev24/mongodb:latest   usr/bin/mongod --rep   20 hours ago        Up 20 hours         0.0.0.0:49169->27017/tcp   rs2_srv4            
03d0dee48b5a        dev24/mongos:latest    usr/bin/mongos --por   43 hours ago        Up 43 hours         0.0.0.0:49168->27017/tcp   mongos1             
e63e5ad534f3        dev24/mongodb:latest   usr/bin/mongod --nop   45 hours ago        Up 45 hours         0.0.0.0:49161->27017/tcp   cfg3                
ac61bd95aa07        dev24/mongodb:latest   usr/bin/mongod --nop   45 hours ago        Up 45 hours         0.0.0.0:49160->27017/tcp   cfg2                
25f80dc762fa        dev24/mongodb:latest   usr/bin/mongod --nop   45 hours ago        Up 45 hours         0.0.0.0:49159->27017/tcp   cfg1                
81385e4ce354        dev24/mongodb:latest   usr/bin/mongod --rep   45 hours ago        Up 45 hours         0.0.0.0:49158->27017/tcp   rs2_srv3            
f21255ed5479        dev24/mongodb:latest   usr/bin/mongod --rep   45 hours ago        Up 45 hours         0.0.0.0:49157->27017/tcp   rs2_srv2            
2ffb31f70bab        dev24/mongodb:latest   usr/bin/mongod --rep   45 hours ago        Up 45 hours         0.0.0.0:49156->27017/tcp   rs2_srv1            
a80c69e9e434        dev24/mongodb:latest   usr/bin/mongod --rep   45 hours ago        Up 45 hours         0.0.0.0:49155->27017/tcp   rs1_srv3            
1edfb75fa453        dev24/mongodb:latest   usr/bin/mongod --rep   45 hours ago        Up 45 hours         0.0.0.0:49154->27017/tcp   rs1_srv2            
84fa8b8bfc0c        dev24/mongodb:latest   usr/bin/mongod --rep   45 hours ago        Up 45 hours         0.0.0.0:49153->27017/tcp   rs1_srv1

In [204]:

traffic_control_netem('vethb03e', ["loss", '40%'])

In [218]:

device='vethb03e'
traffic_control_netem(device, ["loss", '40%'])
traffic_control_netem(device, ["delay","75ms","100ms","distribution","normal"])

In [228]:

traffic_control_restore('vethafb1')

In [201]:

#We can see the different veth names from netstat
!netstat -i
#but this doesn't give a way of associating them with a container (sudo docker.io ps)

Kernel Interface table
Iface   MTU Met   RX-OK RX-ERR RX-DRP RX-OVR    TX-OK TX-ERR TX-DRP TX-OVR Flg
docker0    1500 0     36256      0      0 0         65281      0      0      0 BMRU
eth0       1500 0    211877      0      0 0        127081      0      0      0 BMRU
lo        65536 0     16401      0      0 0         16401      0      0      0 LRU
veth6782   1500 0    300349      0      0 0        305285      0      0      0 BRU
veth9541   1500 0    235540      0      0 0        258248      0      0      0 BRU
veth0cc7   1500 0         9      0      0 0            64      0      0      0 BRU
veth4c89   1500 0         9      0      0 0            91      0      0      0 BRU
veth5b89   1500 0    234335      0      0 0        256913      0      0      0 BRU
veth6bd2   1500 0    233697      0      0 0        255926      0      0      0 BRU
veth86dc   1500 0    149942      0      0 0        172384      0      0      0 BRU
vetha087   1500 0    199264      0      0 0        275534      0      0      0 BRU
vethafb1   1500 0    845641      0      0 0        605569      0      0      0 BRU
vethb03e   1500 0    301702      0      0 0        306421      0      0      0 BRU
vethe5d1   1500 0    132717      0      0 0        175587      0      0      0 BRU
vethf7c0   1500 0    235662      0      0 0        258371      0      0      0 BRU

In [ ]: