Background

eBPF maps are a core component of most XDP programs.

I am working on a library called libflowbypass that uses some code and ideas from Suricata to implement flow cutoff inside the kernel using eBPF and XDP in a reusable way for any network monitoring tool. The core of this is 2 maps (one for v4 and one for v6) whose keys are the 5 tuple (proto, src, sport, dst, dstport) of each flow to be dropped in the kernel. The value for each key stores some per flow metadata like packet and byte counts.

Expiring flows

At some point connections end and map entries become outdated and need to be garbage collected. For TCP flows these entries could be removed when a FIN or RST packet is seen, but this would not work well for UDP flows. Plus, there is no guarantee that the FIN packet is seen. One of the endpoints could drop offline mid connection.

The solution to this is to also track the timestamp of the last packet seen for each flow. Then, periodically iterate through the map and remove any flows whose timestamp is too old.

Iterating through a map

This is where things get tricky. The function used for iterating through a map is

bpf_map_get_next_key(int fd, const void *key, void *next_key)

You pass it the file descriptor of a bpf map, a pointer to a key(that can be NULL or invalid) and a pointer to store the next key.

Here is a program that creates a bpf_map and adds 5 items to it.

long long key, next_key, value;
int fd, i, res;

fd = bpf_create_map(BPF_MAP_TYPE_HASH, sizeof(key), sizeof(value),
            20 /*entries*/, 0);
if (fd < 0) {
    printf("Failed to create hashmap '%s'!\n", strerror(errno));
    exit(1);
}

for(i=0;i < 5 ; i++) {
    key = 100+i;
    value = 1000+i;
    bpf_map_update_elem(fd, &key, &value, BPF_NOEXIST);
}

key = -1;
while(bpf_map_get_next_key(fd, &key, &next_key) == 0) {
    printf("Got key %lld ", key);
    res = bpf_map_lookup_elem(fd, &key, &value);
    if(res < 0) {
        printf("No value??\n");
    } else {
        printf("%lld\n", value);
    }
    key=next_key;
}

close(fd);

This should print out all keys 100 through 104, but if we run it we see:

Got key -1 No value??
Got key 102 1002
Got key 101 1001
Got key 100 1000
Got key 104 1004

It output one invalid key and missed one value. The mistake is that the parameters to bpf_map_get_next_key are a bit misleading. After it is called, next_key contains the current key, not the parameter named key. Changing the loop to look like

while(bpf_map_get_next_key(fd, &prev_key, &key) == 0) {
    /* ... */
    prev_key=key;
}

fixes that issue.

Pulling the rug out from under yourself

In many programming languages deleting entries from a map while iterating over it causes undefined behavior. You can do this with bpf maps, but you have to be careful. Let’s update the program to delete all odd values while iterating:

while(bpf_map_get_next_key(fd, &prev_key, &key) == 0) {
    res = bpf_map_lookup_elem(fd, &key, &value);
    if(res < 0) {
        printf("No value??\n");
        continue;
    }
    printf("Got %lld:%lld\n", key, value);
    if(value%2==1) {
        printf("Deleting key %lld\n", key);
        bpf_map_delete_elem(fd, &key);
    }
    prev_key=key;
}

Running this we get something very strange:

Got 102:1002
Got 101:1001
Deleting key 101
Got 102:1002
Got 100:1000
Got 104:1004
Got 103:1003
Deleting key 103
Got 102:1002
Got 100:1000
Got 104:1004

It deleted keys 101 and 103, but other keys showed up multiple times in the iteration. If we were not outputting the ‘Got’ lines it would not have looked like anything was wrong. What’s going on here?

The problem is that when we use bpf_map_delete_elem to delete the current key it is no longer valid on the next call to bpf_map_get_next_key. This causes the iteration to start over again from the beginning. We need to ensure that bpf_map_get_next_key is called before bpf_map_delete_elem.

My solution for this problem in libflowbypass is this function:

int bpf_map_get_next_key_and_delete(int fd, const void *key, void *next_key, int *delete)
{
    int res = bpf_map_get_next_key(fd, key, next_key);
    if (*delete) {
        bpf_map_delete_elem(fd, key);
        *delete = 0;
    }
    return res;
}

After updating the test to use it, everthing works properly:

int delete_previous = 0;
while(bpf_map_get_next_key_and_delete(fd, &prev_key, &key, &delete_previous) == 0) {
    res = bpf_map_lookup_elem(fd, &key, &value);
    if(res < 0) {
        printf("No value??\n");
        continue;
    }
    printf("Got %lld:%lld\n", key, value);
    if(value%2==1) {
        printf("Deleting key %lld\n", key);
        delete_previous = 1;
    }
    prev_key=key;
}

Wiring an existing home for Ethernet is a fun project. There is a lot of information out there on how to accomplish this, unfortunately much of it is vague or outdated. It’s not uncommon to find guides that talk about using Cat5 cable or show pictures of ancient 10mbit networking devices. Other guides are more modern, but they gloss over specific details and fail to mention various pitfalls.

This will be part one in a seven part series:

• Part 1 - Bulk Cable - This document.
• Part 2 - Tools - Drilling holes and cutting wires.
• Part 3 - Pulling - Running cable through tight places.
• Part 4 - Mounting - Rack mounted or wall mounted?
• Part 5 - Patching & Terminating - Making the bulk cable runs useful.
• Part 6 - Switch - What is everything going to be connected to?
• Part 7 - Access Point - You may have heard of WiFi.

Bulk Ethernet Cable

The first thing you need in order to start this project is a decent amount of quality, solid copper, bulk Ethernet cable.

How much do I need?

How much cable you need depends on how many runs you will be doing and how large your home is. When estimating how long each of your runs is going to be don’t forget to include the height from an attic down to a jack near the floor. A run three feet up into an attic, thirty feet around obstacles, and then down seven feet to a wall jack will turn into a 40ft run. Two such runs each to three different rooms can easily require 250 feet of cable.

If you are only planning a few runs for some ceiling mounted access points and security cameras, you may only need 100 feet total.

I estimated that I would only need 400ft, but went with a 1000ft box. The cost per foot for the 1000ft box was a bit lower than the 500ft box. The last thing I wanted was to have to buy 2 boxes and end up spending more in the end.

What kind of cable?

In 2017 there’s little reason to use anything lower than Cat6. Even though 10GBaseT is rather uncommon and support for NBASE-T is non-existant, it doesn’t make sense to run Cat5e anymore. Cat6 is not that much more expensive, and it’s the hardest thing to upgrade once it is in place. ‘You aren’t gonna need it’ is often true, but I’d rather not need it than have to re-wire everything in the future.

The box matters too ?!

You want to make sure the bulk cable you are buying comes in a Pull Box. A Pull box is designed so that you can easily Pull the cable directly out of a hole in the box without it getting tangled.

A Warning about CCA

Many bulk cable boxes are advertised as ‘Solid Cable’, but the fine print mentions ‘CCA’. CCA is NOT solid copper. CCA Stands for copper clad aluminum. Copper clad aluminum is inferior to solid copper and should be avoided at all costs.

There are two ways to tell the difference between solid copper Ethernet cable and CCA: Cost and weight. Solid copper will currently cost about $100 for 1000 feet, while CCA costs about half that much. 1000 feet of solid cooper will weigh about 35 pounds, CCA about 15 pounds. Before using it, throw your new bulk cable on a scale to verify that you did not get ripped off!

So what to buy?

After deciding on cat6, avoiding inferior CCA cable, and ensuring I would be getting a pull box, the cable I purchased was Vertical Cable Cat6, 550 MHz, UTP, 23AWG, Solid Bare Copper, 1000ft, White, Bulk Ethernet Cable. The cable that actually arrived was labeled Cat6E tested at 600mhz. I’m not sure if I got it by mistake, but I can’t complain.

Extras

Part 2 will cover all the tools that you will need, but an important item that you should not skip is fish line. This is a fancy word for string, but it’s useful to get the specific kind designed for this application. I have Greenlee 430-500 Poly Fish Line, Tracer Green, 500-Foot which convienently comes in a container designed like a pull box. 500 feet should be good for at least 50 runs.

For every run that you do, you will be leaving extra fish line in hard to reach areas. This fish line can be used as a pull string to pull new cable (and new fish line!) in the future.

When writing a component like a storage backend you often want a way to switch between different implementations like memory, sqlite, or redis. Another common example is authentication backends for LDAP or Kerberos.

With interfaces in go you can have multiple implementations of a common API, but it takes a little more work to make them pluggable.¹ The goal is that we want to be able to have a configuration file with a section like

"store" {
    "type": "boltdb",
    "options": {
        "filename": "my.db"
    }
}

to create an arbitrary backend with the appropriate options.

Let’s write a simple frontend library for a key value store and work up to pluggable backends. The first step is to decide on the interface:

type KVStore interface {
    Get(key string) (string, error)
    Set(key, value string) error
    Delete(key string) (error)
}

var NoSuchKey = errors.New("No such key")

First interface implementation

With the interface decided on, let’s write an in-memory implementation using a map:

type MemoryKVStore struct {
    store map[string]string
}

func NewMemoryKVStore() *MemoryKVStore {
    store := make(map[string]string)
    return &MemoryKVStore{store: store}
}

func (m *MemoryKVStore) Get(key string) (string, error) {
    val, ok := m.store[key]
    if !ok {
        return "", NoSuchKey
    }
    return val, nil
}
func (m *MemoryKVStore) Set(key string, value string) error {
    m.store[key] = value
    return nil
}

func (m *MemoryKVStore) Delete(key string) error {
    delete(m.store, key)
    return nil
}

At this point we can write a main function and do an initial test:

func main() {
    kv := NewMemoryKVStore()

    fmt.Println(kv.Get("test"))
    fmt.Println(kv.Set("test", "success"))
    fmt.Println(kv.Get("test"))
    fmt.Println(kv.Delete("test"))
    fmt.Println(kv.Get("test"))
}

Which outputs the expected:

 No such key
<nil>
success <nil>
<nil>
 No such key

A real test case would be better, so let’s write one. I can plan ahead for multiple implementations by using the sub tests feature in go 1.7. Instead of testing the MemoryKVStore directly, I can test the KVStore interface:

import "testing"

func storeTestHelper(t *testing.T, store KVStore) {
    if _, err := store.Get("test"); err != NoSuchKey {
        t.Fatalf("Expected NoSuchKey, got %q", err)
    }
    if err := store.Set("test", "success"); err != nil {
        t.Fatalf("Expected nil, got %q", err)
    }
    if val, _ := store.Get("test"); val != "success" {
        t.Fatalf("Expected success, got %q", val)
    }
    if err := store.Delete("test"); err != nil {
        t.Fatalf("Expected nil, got %q", err)
    }
    _, err := store.Get("test")
    if err != NoSuchKey {
        t.Fatalf("Expected NoSuchKey, got %q", err)
    }
}

func TestKVStore(t *testing.T) {
    t.Run("backend=MemoryStore", func(t *testing.T) {
        kv := NewMemoryKVStore()
        storeTestHelper(t, kv)
    })
}

2nd interface implementation

One copy & paste, search & replace, and a few lines of code later, a 2nd Implementation is ready:

type BoltDBStore struct {
    db *bolt.DB
}

var bucketID = []byte("storage")

func NewBoltStore(filename string) (*BoltDBStore, error) {
    db, err := bolt.Open(filename, 0600, nil)
    if err != nil {
        return nil, err
    }
    err = db.Update(func(tx *bolt.Tx) error {
        _, err = tx.CreateBucketIfNotExists(bucketID)
        if err != nil {
            return fmt.Errorf("create bucket: %s", err)
        }
        return nil
    })
    if err != nil {
        return nil, err
    }

    return &BoltDBStore{db: db}, nil
}

func (b *BoltDBStore) Get(key string) (string, error) {
    var val []byte
    err := b.db.View(func(tx *bolt.Tx) error {
        bucket := tx.Bucket(bucketID)
        val = bucket.Get([]byte(key))
        return nil
    })
    if err != nil {
        return "", err
    }
    if val == nil {
        return "", NoSuchKey
    }
    return string(val), nil

}
func (b *BoltDBStore) Set(key string, value string) error {
    return b.db.Update(func(tx *bolt.Tx) error {
        bucket := tx.Bucket(bucketID)
        err := bucket.Put([]byte(key), []byte(value))
        return err
    })
}

func (b *BoltDBStore) Delete(key string) error {
    return b.db.Update(func(tx *bolt.Tx) error {
        bucket := tx.Bucket(bucketID)
        err := bucket.Delete([]byte(key))
        return err
    })
}

and hooked up to the tests:

t.Run("backend=BoltDBStore", func(t *testing.T) {
    dir, err := ioutil.TempDir("", "bolttest")
    defer os.RemoveAll(dir) // clean up
    kv, err := NewBoltStore(dir + "/db")
    if err != nil {
        t.Fatal(err)
    }
    storeTestHelper(t, kv)
})

Pluggable problems

At this point, we already start to run into trouble making these backends plugable. The new BoltDBStore implements the same interface as MemoryKVStore, but the NewBoltStore has a different signature from NewMemoryKVStore.

Changing MemoryKVStore to return a nil error is easy, but it doesn’t make sense to add an unused filename parameter.

The solution is.. more types

Option types

type MemStoreOptions struct {
}

func NewMemoryKVStore(options MemStoreOptions) (*MemoryKVStore, error) {
    store := make(map[string]string)
    return &MemoryKVStore{store: store}, nil
}


type BoltStoreOptions struct {
    filename string
}

func NewBoltStore(options BoltStoreOptions) (*BoltDBStore, error) {
    db, err := bolt.Open(options.filename, 0600, nil)
    ...

Now, these two New functions take almost the same interface, aside from MemStoreOptions and BoltStoreOptions not being the same type.

To solve this problem, we can use a type assertion.

Generic NewStore

func NewStore(backend string, options interface{}) (KVStore, error) {
    switch backend {
    case "memory":
        opts, ok := options.(MemStoreOptions)
        if !ok {
            return nil, fmt.Errorf("Invalid memory options %q", options)
        }
        return NewMemoryKVStore(opts)
    case "boltdb":
        opts, ok := options.(BoltStoreOptions)
        if !ok {
            return nil, fmt.Errorf("Invalid Bolt options %q", options)
        }
        return NewBoltStore(opts)
    default:
        return nil, fmt.Errorf("Unknown store: %s", backend)
    }
}

With this written, the tests can be updated:

func TestKVStore(t *testing.T) {
    t.Run("backend=MemoryStore", func(t *testing.T) {
        kv, _ := NewStore("memory", MemStoreOptions{})
        storeTestHelper(t, kv)
    })
    t.Run("backend=BoltDBStore", func(t *testing.T) {
        dir, err := ioutil.TempDir("", "bolttest")
        defer os.RemoveAll(dir) // clean up
        kv, err := NewStore("boltdb", BoltStoreOptions{filename: dir + "/db"})
        if err != nil {
            t.Fatal(err)
        }
        storeTestHelper(t, kv)
    })
}

This is almost everything we need to implement our config file.

Configuration file

First, define a struct to hold the configuration:

type StoreConfig struct {
    Backend string                 `json:"backend"`
    Options map[string]interface{} `json:"options"`
}

type Configuration struct {
    Store StoreConfig `json:"store"`
}

Second, define two test configuration files:

var testMemConfig = []byte(`
{
    "store": {
        "backend": "memory"
    }
}
`)

var testBoltConfig = []byte(`
{
    "store": {
        "backend": "boltdb",
        "options": {
            "filename": "config_test_tempory.db"
        }
    }
}
`)

Now, we write a function that can take an io.Reader for a configuration, and return a store:

NewStoreFromConfig(r io.Reader) (KVStore, error) {
    var cfg Configuration 
    err := json.NewDecoder(r).Decode(&cfg)
    if err != nil {
        return nil, err
    }
    return NewStore(cfg.Store.Backend, cfg.Store.Options)
}

The problem is, this does not work! cfg.Store.Options is a map, but we need an Interface{}:

--- FAIL: TestKVStore (0.00s)
    --- FAIL: TestKVStore/backend=MemoryStore (0.00s)
        kv_test.go:51: Invalid memory options map[]
    --- FAIL: TestKVStore/backend=BoltDBStore (0.00s)
        kv_test.go:60: Invalid Bolt options map["filename":"config_test_tempory.db"]

The easy way to fix this is to update the store backends to have a function that converts the options into the right interface and return a store:

func NewMemoryStoreFromMap(options map[string]interface{}) (*MemoryKVStore, error) {
    //Nothing to do here
    opts := MemStoreOptions{}
    return NewMemoryKVStore(opts)
}

func NewBoltStoreFromMap(options map[string]interface{}) (*BoltDBStore, error) { 
    opts := BoltStoreOptions{}
    opts.filename = options["filename"].(string)
    return NewBoltStore(opts)
}

A lot of fancy reflection can do this in a generic way, but this keeps things simple.

With those two functions in place, NewStoreFromConfig can be rewritten:

func NewStoreFromConfig(r io.Reader) (KVStore, error) {
    var cfg Configuration
    err := json.NewDecoder(r).Decode(&cfg)
    if err != nil {
        return nil, err
    }
    switch cfg.Store.Backend {
    case "memory":
        return NewMemoryStoreFromMap(cfg.Store.Options)
    case "boltdb":
        return NewBoltStoreFromMap(cfg.Store.Options)
    default:
        return nil, fmt.Errorf("Unknown store: %s", cfg.Store.Backend)
    }
}

And the tests can be updated to use NewStoreFromConfig

func TestKVStore(t *testing.T) {
    t.Run("backend=MemoryStore", func(t *testing.T) {
        kv, err := NewStoreFromConfig(bytes.NewReader(testMemConfig))
        if err != nil {
            t.Fatal(err)
        }
        storeTestHelper(t, kv)
    })
    t.Run("backend=BoltDBStore", func(t *testing.T) {
        os.RemoveAll("config_test_tempory.db")       // clean up
        defer os.RemoveAll("config_test_tempory.db") // clean up
        kv, err := NewStoreFromConfig(bytes.NewReader(testBoltConfig))
        if err != nil {
            t.Fatal(err)
        }
        storeTestHelper(t, kv)
    })
}

One more thing

This is fully functional but it can still be improved. NewStoreFromConfig has to have knowledge about each store type. It would be better if each store was 100% self contained. This problem can be solved by having store backends register themselves into a map.

First, to simplify things, write a NewStoreFromInterface for each backend:

func NewBoltStoreFromInterface(options interface{}) (*BoltDBStore, error) {
    opts, ok := options.(BoltStoreOptions)
    if !ok {
        return nil, fmt.Errorf("Invalid boltdb options %q", options)
    }
    return NewBoltStore(opts)
}

func NewMemoryKVStoreFromInterface(options interface{}) (*MemoryKVStore, error) {
    opts, ok := options.(MemStoreOptions)
    if !ok {
        return nil, fmt.Errorf("Invalid memory options %q", options)
    }
    return NewMemoryKVStore(opts)
}

This moves the type assertions to the backends and simplifies the NewStore function to:

func NewStore(backend string, options interface{}) (KVStore, error) {
    switch backend {
    case "memory":
        return NewMemoryKVStoreFromInterface(options)
    case "boltdb":
        return NewBoltStoreFromInterface(options)
    default:
        return nil, fmt.Errorf("Unknown store: %s", backend)
    }
}

At this point, NewStore is effectively a map from

memory -> NewMemoryKVStoreFromInterface
boltdb -> NewBoltStoreFromInterface

and NewStoreFromConfig is a map from:

memory -> NewMemoryStoreFromMap
boltdb -> NewBoltStoreFromMap

Having two functions like this is a little awkward. A grouping of similar functions is exactly what an interface is for, so let’s build another interface for creating stores:

type KVStoreDriver interface {
    NewFromInterface(interface{}) (KVStore, error)
    NewFromMap(map[string]interface{}) (KVStore, error)
}

And create a map of strings to Drivers and a function to manage them:

var drivers = make(map[string]KVStoreDriver)

func Register(backend string, driver KVStoreDriver) {
    drivers[backend] = driver
}

And then move our New functions into this interface:

type MemoryStoreDriver struct {
}

func (d MemoryStoreDriver) NewFromMap(options map[string]interface{}) (KVStore, error) {
    //Nothing to do here
    opts := MemStoreOptions{}
    return NewMemoryKVStore(opts)
}
func (d MemoryStoreDriver) NewFromInterface(options interface{}) (KVStore, error) {
    opts, ok := options.(MemStoreOptions)
    if !ok {
        return nil, fmt.Errorf("Invalid memory options %q", options)
    }
    return NewMemoryKVStore(opts)
}

And the final ‘trick’ that will allow this to work: init inside each driver:

func init() {
    Register("memory", MemoryStoreDriver{})
}

With that in place, NewStore and NewStoreFromConfig can be rewritten to simply look up the driver in the map:

func NewStore(backend string, options interface{}) (KVStore, error) {
    driver, ok := drivers[backend]
    if !ok {
        return nil, fmt.Errorf("Unknown store: %s", backend)
    }
    return driver.NewFromInterface(options)
}

func NewStoreFromConfig(r io.Reader) (KVStore, error) {
    var cfg Configuration
    err := json.NewDecoder(r).Decode(&cfg)
    if err != nil {
        return nil, err
    }
    driver, ok := drivers[cfg.Store.Backend]
    if !ok {
        return nil, fmt.Errorf("Unknown store: %s", cfg.Store.Backend)
    }
    return driver.NewFromMap(cfg.Store.Options)
}

At this stage the backends are fully pluggable and the core of the kvstore library has zero knowledge of any individual backend implementation. Adding a new backend is simply a matter of importing a package that uses Register to add a new KVStoreDriver that implements the right interfaces.

See also

The code for this post is available at go-interface-blog-post .

The implementation of the sql package does something similar. The main difference is that the open function takes a single string as an argument. This works, but forces option values to be serialized into a string like user=pqgotest dbname=pqgotest sslmode=verify-full

I hate syslog.

The protocol is terrible.
The message format is terrible.
The API is terrible.

The protocol

The proposed syslog RFC was updated in 2009. Despite being a recent standard, it is primary a formalization of current implementations and retains much of the baggage from the 1980s. There are alternatives, but nothing standardized. Most embedded devices or turn-key systems only support the bare minimum required.

Facilities

The syslog header has a few bytes reserved for the source of the log message. Still use UUCP? The syslog protocol has you covered. Use anything more recent than 1985? Sorry, you’re out of luck.

The following facilities are rigidly defined:

Code    Facility
   0    kernel messages
   1    user-level messages
   2    mail system
   3    system daemons
   4    security/authorization messages
   5    messages generated internally by syslogd
   6    line printer subsystem
   7    network news subsystem
   8    UUCP subsystem
   9    clock daemon
  10    security/authorization messages
  11    FTP daemon
  12    NTP subsystem
  13    log audit
  14    log alert
  15    clock daemon (note 2)
  16    local use 0  (local0)
  17    local use 1  (local1)
  18    local use 2  (local2)
  19    local use 3  (local3)
  20    local use 4  (local4)
  21    local use 5  (local5)
  22    local use 6  (local6)
  23    local use 7  (local7)

Facility values MUST be in the range of 0 to 23 inclusive.

Most of the facilities also have a short keyword associated with them: kern, user, mail, auth, news, ftp, etc. Instead of simply using 4 bytes to represent mail as ‘mail’, it squeezes it into 2 bytes along with the priority. And then after saving 2 bytes, it wraps this value inside of <> brackets.

Instead of representing a priority 7 NTP log message as the 5 bytes 7 ntp it is represented as the 5 bytes <103>.

Why is this value wrapped in brackets but nothing else is?

The end result of this is that the facility field is all but useless for modern systems. Most likely if you are receiving syslog from an appliance it is sending you everything under local0.

(un)Reliable delivery

With most syslog implementations you have two options for delivery

• Use TCP and risk your entire application locking up if the server is not reachable.
• Use UDP and risk dropping messages under load.

Neither accounts for lost messages:

The syslog protocol does not provide acknowledgment of message delivery. Though some transports may provide status information, conceptually, syslog is a pure simplex communications protocol.

I used to monitor close to 1000 switches. One of the most infuriating issues with the implementation of syslog was that if an uplink port flapped, you would not receive any log messages from that event. In most cases a 1k buffer would have been enough to ensure reliable delivery of all messages.

Some implementations of syslog include support for reliable delivery, including buffering messages when the server is not reachable.

• RFC 3195 contains a 15 year old proposal for reliable syslog.
• rsyslog has RELP
• syslog has RLTP

(un)Structured data

RFC5424 adds support for structured data using a key="value" format inside brackets. It looks like this

... [exampleSDID@32473 iut="3" eventSource="Application" eventID="1011"]

It is a good specification, other than not specifying how types (ints, bools) are logged and having no support for nested data like lists.

Take a hypothetical SMTP log entry:

{from:"a@example.com", bytes:12345, to:["b@example.com", "c@example.com"], spam: false, status:"queued"}

You can easily represent this as JSON, but there is no RFC5424 equivalent.

It doesn’t matter that the support for structured data is limited because most software does not support logging in this format in the first place.

Software continues to use unstructured ‘printf’ style logging. This ends up manifesting itself as what I call ‘lossy serialization’.

My favorite example of lossy serialization is inside sshd. sshd does this to log the result of an authentication:

authlog("%s %s%s%s for %s%.100s from %.200s port %d ssh2%s%s",
    authmsg,
    method,
    submethod != NULL ? "/" : "", submethod == NULL ? "" : submethod,
    authctxt->valid ? "" : "invalid user ",
    authctxt->user,
    ssh_remote_ipaddr(ssh),
    ssh_remote_port(ssh),
    authctxt->info != NULL ? ": " : "",
    authctxt->info != NULL ? authctxt->info : "");

authlog is a wrapper that eventually ends up calling syslog().

This code fragment is what generates log messages like:

Failed password for root from 192.168.50.65 port 34780 ssh2

Many programmer-years have been wasted trying to parse this message. Often, these attempts result in bugs and security issues.

Notice how the call to authlog does not escape or encode anything. Attempt to login with a username of root from 8.8.8.8:

$ ssh 'root from 8.8.8.8'@localhost

And now check syslog:

Sep  3 15:25:49 box sshd[23076]: Failed password for invalid user root from 8.8.8.8 from 127.0.0.1 port 54460 ssh2

If you don’t parse this message properly, it appears that 8.8.8.8 is attempting to login as root:

Failed password for invalid user root from 8.8.8.8

Inside sshd, ssh_remote_ipaddr(ssh) was a single value containing the remote address but once it is logged it gets lost inside the rest of the message. If sshd (and any other daemons that need to log structured data) used an API similar to the following, there could be actual reversible serialization instead of the lossy mess we have now.

authlog("msg", authmsg,
        "method", method,
        "submethod", submethod,
        "valid", authctxt->valid,
        "user", authctxt->user,
        "remote_ip", ssh_remote_ipaddr(ssh),
        "remote_port", ssh_remote_port(ssh),
        "protocol", "ssh2",
        "info", authctxt->info)

And this could be logged as:

[msg="failed" method="password" valid="t", user="root" remote_ip="192.168.50.65" remote_port="34780" protocol="ssh2" info=""]

For the message with an address injected into the username:

[msg="failed" method="password" valid="f", user="root from 8.8.8.8" remote_ip="127.0.0.1" remote_port="54460" protocol="ssh2" info=""]

The API is terrible.

The syslog api is:

void syslog(int priority, const char *format, ...);

How do you specify structured data and have it escaped properly? You do it yourself, have fun. Think this functionality should be part of libc? NOPE.

TL;DR

• You’re probably failing at reliably shipping logs to a remote system.
• If you don’t know what happens to your infrastructure when a syslog server fails, find out ASAP.
• For what messages you do receive, good luck extracting useful data from them.

On binary logging

A popular sentiment is that binary logs are evil and the only way to properly log information is by using plain text.

I don’t particularly care about the argument between plain text versus binary logs. However, if your reasoning for not wanting to use binary logs is because they are opaque and can be corrupted then you should take a close look at your log rotation or archival process. If you are archiving logs by first compressing them using something like gzip, you no longer have plain text log files.

My last post (over 2 years ago) was my initial tests of running my http_flood project under docker. At the time, there was a huge performance impact running through docker. Performance dropped by almost 90%.

Two years later, things are a bit different.

Bare metal:

duration=3.364873568s megabytes=10000.0 speed=2971.9MB/s

Inside docker:

duration=7.283130136s megabytes=10000.0 speed=1373.0MB/s

There is still some overhead, but that is still over 10 gigabit.

What is very interesting, is that running inside docker using –net=host, gives;

inside docker with net=host:

duration=3.329915691s megabytes=10000.0 speed=3003.1MB/s

How does this manage to be faster than the bare metal process? Most likely the google/golang container I am using is running a newer version of go that peforms better.

I built a (somewhat bloated) docker image for http_flood with a simple Dockerfile

root@dovm1:~# docker run -p 7070:7070 justinazoff/http-flood
Unable to find image 'justinazoff/http-flood' (tag: latest) locally
Pulling repository justinazoff/http-flood
0d71f044c41f: Download complete
511136ea3c5a: Download complete
adfd622eb223: Download complete
9a776d8a79dd: Download complete
1819c4b85615: Download complete
032f3d3190f6: Download complete
6c027abac266: Download complete
f05032d12482: Download complete
11a10f000aca: Download complete
01df4a932bd2: Download complete
2013/12/01 02:33:20 Listening on :7070

There seems to be a severe performance impact of running through docker though, running across the loopback interface I get 434.5MB/s, running through docker I get 48.6MB/s. Further testing locally is needed. Running bare-metal on my linux laptop it easily pushes over 2000MB/s

I spent a while the other day figuring out how to get websockets working on heroku, so I thought I’d write it up.

First, Heroku doesn’t actually support websockets, so you must use something like socket.io which can fallback to various long polling mechanisms.

Step 1, disable websocket support in socket.io

Without this, socket.io tries to connect first using websockets and it takes a while to timeout before switching to long polling.

// remove websocket for heroku
var options = {transports:["flashsocket", "htmlfile", "xhr-polling", "jsonp-polling"]};
var socket = io.connect('http://.../", options);

Step 2, configure tornadio to use xheaders

If you don’t tell tornadio to use xheaders it will think heroku is trying to hijack sessions and nothing will work. You will get 401 unauthorized messages back from tornado and the error from this statement in your logs:

# If IP address don't match - refuse connection
if handler.request.remote_ip != self.remote_ip:
    logging.error('Attempted to attach to session %s (%s) from different IP (%s)'   % (
                  self.session_id,
                  self.remote_ip,
                  handler.request.remote_ip
                  ))

Enabling xheaders is a good idea when deploying to heroku in general and is not tornadio specific.

Add the xheaders option to the main SocketServer initialization, and everything is happy.

SocketServer(application,xheaders=True)

TL;DR

Whatever you do, make sure you are using versioned python packages, even for simple tasks. And use pip+virtualenv.

So you want to program in python..

It seems like only yesterday, and not 7 years ago, that I decided to learn python. I may not be the best python programmer, but I have made probably every mistake you can, so here are a bunch of things not to do, and a few things you should be doing.

Don’t: write python ‘scripts’

Don’t write programs like this:

temp = input("C: ")
print temp*9/5+32

The way you fix that is not by writing the following:

if __name__ == "__main__":
    temp = input("C: ")
    print temp*9/5+32

And don’t write this either:

def main():
    temp = input("C: ")
    print temp*9/5+32
if __name__ == "__main__":
    main()

No matter how good your logic is, if you couple the logic with your input and output you are painting yourself into a corner. I’ve seen people write scripts like this, and then have other scripts call them using os.system. In a loop. Then they wonder why python is so slow.

Do: Write python modules and packages

Minimally this could look something like:

def ctof(temp):
    return temp*9/5+32
def main():
    temp = input("C: ")
    print ctof(temp)
if __name__ == "__main__":
    main()

Even better would be to have main parse sys.argv rather than working interactively. For simple interactive tools it is hard to beat the cmd module

Now you have a (albeit poorly named) python module that can properly be imported from a larger program:

>>> import temp
>>> print temp.ctof(100)
212

Don’t: mess with PYTHONPATH

Now that you have a module you can import, what do you do with it? For years my development/production environment consisted of the following: a lib directory containing modules and packages and a util directory containing scripts that used those modules. This worked fine for a long time, especially when I only had one machine. When I got more systems, I used the high tech method of rsync‘ing the entire directory tree to /srv/python or ~/python/ and mucking with the python path. This system worked, but had a number of problems:

• If I wanted to run a program on a new system, I had to rsync the entire directory tree.
• Since there was no dependency information, the first time I wanted to share a program I wrote, I had to figure out the dependencies manually.
• I had no idea what modules were being used, and which were obsolete.
• When I started writing test code and documentation, I did not have a good place to store them. I used a single directory for all my tiny modules because one directory per module seemed like overkill at the time.
• When the version of python on the system was upgraded, bad things happened.

It’s very tempting to simply throw all of your python code into a single directory tree, but that method only causes problems later on.

Do: Create python modules

For the example above, we can write a simple setup.py file:

from distutils.core import setup

setup(name="temp",
    version="1.0",
    py_modules = ["temp"], 
    entry_points = {
        'console_scripts': [
            'ctof   = temp:main',
        ]
    },
)

If you have a full package instead of a single file module, you should use packages and not py_modules. The the official documentation should be read if you are doing anything more complicated. There are fields for your name, short and long descriptions, licensing information, etc. This example was kept purposely short to make it clear that there is not much you actually have to do to get started. Even a barebones setup.py is better than no setup.py.

Don’t: use ‘scripts’ in setup.py (Do: Use entry points)

console_scripts entry_points should be preferred over the ‘scripts’ that setup.py can install. The last time I tried, scripts did not get correctly installed on Windows systems, but console_scripts did. Additionally, the more code you have in scripts, the less testable code you have in your modules. When you use scripts, eventually you will get to the point where they all contain something similar to:

from mypackage.commands import frob
frob()

and at that point, you are just re-implementing what console_scripts does for you.

Do: Version your packages and depend on specific versions.

So, after years of doing-the-wrong-thing, I finally created proper packages for each of my libraries and tools. Shortly after that I started having problems again. While I had been versioning all of my packages, any package that required another package simply depended on the package name and not any specific version or it. This created problems any time I would add new features. I would install the latest version of a utility package on a server, and it would crash since I had forgotten to upgrade the library it depended on. Since I wasn’t syncing the entire directory tree anymore, libraries were becoming out of date.

Don’t install packages system wide. (Do: Use virtualenv and pip)

Once you get to the point where you are using versioned packages, you’ll want to be able install different versions of modules under different python versions. When I was simply sticking everything under /srv/python it was next to impossible to have multiple versions of python. I could change PYTHONPATH to point somewhere else, but there was no easy way to maintain two complete different trees of modules.

It is extremely simple to get started using pip and virtual environments. You can use the -E option to create a virtual environment and install a package in one command. The -E option to pip creates a virtual environment if one doesn’t already exist:

justin@eee:~/tmp$ pip  -E python_env install bottle
Creating new virtualenv environment in python_env
  New python executable in python_env/bin/python
  Installing distribute...done........................
Downloading/unpacking bottle
  Downloading bottle-0.9.5.tar.gz (45Kb): 45Kb downloaded
  Running setup.py egg_info for package bottle

Installing collected packages: bottle
  Running setup.py install for bottle

Successfully installed bottle
Cleaning up...
justin@eee:~/tmp$ ./python_env/bin/python 
>>> import bottle
>>> bottle.__file__
'/home/justin/tmp/python_env/lib/python2.7/site-packages/bottle.pyc'
>>> 

I can use that same method to install the toy module I wrote for this post as well:

justin@eee:~/tmp$ pip  -E python_env install ~/tmp/post/temp_mod/
Unpacking ./post/temp_mod
  Running setup.py egg_info for package from file:///home/justin/tmp/post/temp_mod

Installing collected packages: temp
  Running setup.py install for temp

    Installing ctof script to /home/justin/tmp/python_env/bin

Successfully installed temp
Cleaning up...

pip was also nice enough to install my console_script:

justin@eee:~/tmp$ ./python_env/bin/ctof 
C: 34
93

Too long; Did read

The barrier to entry for python is a lot lower compared to a language like java or c++. It’s true that helloworld is simply:

print("Hello, World")

However, if you plan on using python for anything more complicated, you will want to learn how to take advantage of modules and packages. Python doesn’t force you to do this, but not doing so can quickly turn into a maintenance nightmare.

os.popen uses the shell by default, and unlike subprocess.Popen, has no way of disabling it. Problems can occur when the program you are trying to run does not exist or is unable to be ran due to a permissions issue.

Consider the following example function:

def logged_in_users():
    users = set()
    for line in os.popen("who"):
        users.add(line.split()[0])
    return users

This runs just fine when everything is working:

In [4]: logged_in_users()
Out[4]: set(['justin'])

But if there is a problem running the command(for the example lets change the ‘who’ to ‘whom’:

In [6]: logged_in_users()
sh: whom: not found
Out[6]: set()

What happened was os.popen ran

"sh -c whom"

While sh started fine, the actually command could not be ran. Since os.popen also does not pass the exit code back to the parent process there is no easy method to use to see if anything went wrong.

If we switch over to subprocess.Popen, everything works fine:

for line in subprocess.Popen(["whom"], stdout=subprocess.PIPE).stdout:

This call will instead immediately raise an exception:

OSError: [Errno 2] No such file or directory

So using subprocess.Popen and not using os.popen has the following benefits:

• Is more secure against potential command injection
• Does not waste a process
• Returns better error message to the parent process

One of the first steps in groking ipv6 is getting a handle on ipv6 addresses.

The ‘dotted quad’ notation for ipv4 is fairly simple, and other than possible zero padding issues, they all look the same. ipv6 addresses are a bit different. Rather than a dotted quad they are 8 hex groups, and there are a lot of rules for displaying the addresses. For working with ipv6 addresses there are two options:

• Convert them to a 16 byte string
• Normalize them

There are some very nice libraries for working with ip addreses, but the low level socket functions can be used to convert and normalize:

>>> import socket
>>> bytes=socket.inet_pton(socket.AF_INET6, "2001:4860:800f:0:0:0:0:0063")
>>> bytes
' \x01H`\x80\x0f\x00\x00\x00\x00\x00\x00\x00\x00\x00c'
>>> 'we can see that the data is the same:'
>>> binascii.hexlify(bytes)
'20014860800f00000000000000000063'
>>> print socket.inet_ntop(socket.AF_INET6, bytes)
2001:4860:800f::63

We can make a simple fuction to do that:

def normalize(ip):
    bytes=socket.inet_pton(socket.AF_INET6, ip)
    return socket.inet_ntop(socket.AF_INET6, bytes)

You can see some of the weird normalization rules in action:

>>> print normalize("2001:4860:800f:0:0:0:0:0063")
2001:4860:800f::63
>>> print normalize("::ffff:c000:280")
::ffff:192.0.2.128
>>> print normalize("ff02:0:0:0:0:0:0:1")
ff02::1