Working with forks and go sub modules

Just this week I needed to create a fork for an open source go package that uses go modules: https://github.com/alicebob/miniredis  

No problem I thought.  I created my fork and cloned my forked repo locally.    I created a directory in the source tree for my new submodule and then I initialized my new go module:

go mod init

My new go.mod for the submodule contained the following:

module github.com/Jim-Lambert-Bose/miniredis/sentinel

Well, that's not going to work now is it?  How will I merge things upstream to the parent repo when my PR includes a module with a FDQN that references my github account?

What to do next?  I have my fork and the parent repo... how do I get them to appear to be the same repo to the go module tooling?  Well, it's actually not that difficult.  I just need to clone the parent repo and add a new remote to this clone which points to my forked repo.

git clone git@github.com:alicebob/miniredis.git
cd miniredis
git remote add forked git@github.com:Jim-Lambert-Bose/miniredis
git branch -u forked/master

Now, I can just create a new branch for my changes and start making commits to my forked repo.

git branch -b amazing-pr-branch

# make some local edits/commits, then push to my forked repo
git push -u forked amazing-pr-branch

When I want to revert back to tracking the origin, because my PR has been merged (yes!), I can just enter:

git branch -u origin/master
git reset --hard origin/master

Using this process, I can easily fork and change any Go open source package.  Please feel free to comment below, if you find mistakes or issues.

Go - appending []byte as a variadic parameter  

In my last post, I demonstrated a type that implemented the io.Writer interface.  During the PR process for that code, one of my team members asked,  why did you use that odd syntax with append?

// newData is of type []byte

append(newData, []byte(",")...)

append() is a Go built in.  It's implemation is found here: builtins.go  There are lots of posts that talk about how append works, so I won't go into that here.  I just want to focus on answering the practical question my team member asked: why did I use that odd syntax with the "..."?

The simple answer is: that's the only way to append a slice of bytes to a slice of bytes.  Not really a helpful answer though, so here are some more details.   append() is a variadic func.  In our example, the first param is []byte.  It's a slice of "bytes".  That means that append() will only accept a byte as its second parameter.  Yep, a single byte, not a slice of bytes.  That's where the power of Go's variadic functions comes to play.  You can pass in an arbitrary number of single bytes as the second parameter to append().  Now we just need to convert []byte to multiple single bytes.  You do this by simply making []byte a variadic parameter by adding "..."

Add all of this together and you'll understand the answer and why this works:

b2 := append([]byte("hi mom"), []byte(" and dad")...)  

Here's some example code you can play with: https://play.golang.org/p/Ml5pRwryaQc

package main

import (
 "bytes"
 "strings"
 "fmt"
)


// I implemented an io.Write interface in our library and I got a question about why I used
// an odd syntax with append().  In our use case, we need to chop off the newline from
// the data param and add a comma during the Write()
//
// here's the method in question:
//  Write - simply append to the strings.Buffer but add a comma too
// func (b *LogBuffer) Write(data []byte) (n int, err error) {
// newData := bytes.TrimSuffix(data, []byte("\n"))
// return b.Buff.Write(append(newData, []byte(",")...))
// }
// taken from: https://github.com/Bose/go-gin-logrus/blob/7cf3281c11105460c98f821872b64aebc89e1b06/logBuffer.go#L17
//

func main() {
 // first some setup
 var b strings.Builder
 
 // the param to our func and it's a []byte (aka a slice)
 data := []byte("hi mom.\n") 
 
 // hack off the newline since newlines will cause problems in our use case
 newData := bytes.TrimSuffix(data, []byte("\n")) 
 
 
 // First, can't we just append the comma as a string?
 // nope, this causes an error: cannot use "," (type string) as type byte in append
 // yep, you can't append a string to []byte.  that makes sense.
 // b.Write(append(newData, ","))
 
 // Next, can't we just append the comma as []byte without any trailing ... ?
 // nope, this causes an error: cannot use ([]byte)(",") (type []byte) as type byte in append
 // What the heck?  What does this error mean?  Well, newData is a slice of bytes, so append insists
 // that you can only append a byte (or many individual bytes, since it's a variadic func) to it, 
 // not a slice of bytes (aka []byte)
 // b.Write(append(newData, []byte(",")))
 
 // Add the ... after the slice of bytes which tells Go to "unpack" the []bytes into individual bytes.
 // and append() takes a variadic as it's second parameter, so these "unpacked" individual bytes 
 // can now be appended to the first paramater []byte, which is a slice of bytes.  yes, it works!
 // Let's call this working version: V1
 b.Write(append(newData, []byte(",")...))
 fmt.Println(b.String())
 
 // BTW, we could just make two writes to the buffer.
 // this is V2 and it works too, but why is it worse than V2 for our use-case of
 // implementing the io.Writer?
 b.Reset()
 b.Write(newData)
 b.Write([]byte(","))
 fmt.Println(b.String())
 
}

Go - how to aggregate your logging with logrus and io.Writer

I'm always looking for better ways to observe microservices.  Recently I've been reading a lot of posts/blogs from Charity Majors (Charity Majors‏ @mipsytipsy).  Charity makes a compelling argument for producing structured data for every request that your services handle.  Currently, our microservices use Logrus for structured logging and, out of the box, Logrus writes to the log every time a log entry is created.   Basically, you call logrus.Info()and it writes structured data to the log, which is great... until your services start handling thousands of transactions per second (TPS) and they're writing 100s of times to the log per request.  At that point, your log infrastructure just starts falling over trying to ingest the thousands of TPS your services are sending it.  The solutions is obvious, you need to aggregate your logging in memory and only write one time to the log per request.

Luckily, the maintainers of Logrus provide a simple way to aggregate your logging.  The logrus.Logger exports Logger.Out io.Writer as an attribute.   That means we can do something like:

package main

import (
 "fmt"
 "string"

 "github.com/sirupsen/logrus"
)

func main() {
 var stringsBuilder strings.Builder
 log := &logrus.Logger{
  Out:       &stringsBuilder,
  Formatter: new(logrus.JSONFormatter),
  Hooks:     make(logrus.LevelHooks),
  Level:     logrus.DebugLevel,
 }
 logger := logrus.WithFields(logrus.Fields{
  "path":   "/test",
  "status": 200})
 logger.Logger = log3
 logger.Info("strings.Builder Info")
 logger.Debug("strings.Builder Debug")
 logger.Error("strings.Builder Error")
 fmt.Printf(stringsBuilder.String())
}

The code above will only make one write to the log, but that write will be an aggregate of all the structured data you've added to the logger.   Pretty slick and my hat's off to the Logrus maintainers for making it so easy.   There is one problem: the JSON would be outputted as a new object for each log entry.  That's easily fixed though with a new type that implements the io.Writer interface and encapsulates a strings.Builder:

import (
 "bytes"
 "strings"
)

// StringWriter - implement io.Writer inferface to append to a string
type logBuffer struct {
 Buff strings.Builder
}

// Write - simply append to the strings.Buffer but add a comma too
func (b *logBuffer) Write(data []byte) (n int, err error) {
 newData := bytes.TrimSuffix(data, []byte("\n"))
 return b.Buff.Write(append(newData, []byte(",")...))
}

// String - output the strings.Builder as one aggregated JSON object
func (b *logBuffer) String() string {
 return "{\"entries\":[" + strings.TrimSuffix(b.Buff.String(), ",") + "]}\n"
}



I've taken the above proof of concept for aggregating Logrus entries and written some Gin middleware that not only aggregates logging but also adds OpenTracing support:

https://github.com/Bose/go-gin-logrus

I hope others find this helpful and learned something about the io.Writer interface as well.

# example aggregated log entry for a request with UseBanner == true
{
  "new-header-index-name": "this is how you set new header level data",
  "request-summary-info": {
    "comment": "",
    "ip": "::1",
    "latency": "     98.217µs",
    "method": "GET",
    "path": "/",
    "requestID": "4b4fb22ef51cc540:4b4fb22ef51cc540:0:1",
    "status": 200,
    "time": "2019-02-06T13:24:06Z",
    "user-agent": "curl/7.54.0"
  },
  "entries": [
    {
      "level": "info",
      "msg": "this will be aggregated into one write with the access log and will show up when the request is completed",
      "time": "2019-02-06T08:24:06-05:00"
    },
    {
      "comment": "this is an aggregated log entry with initial comment field",
      "level": "debug",
      "msg": "aggregated entry with new comment field",
      "time": "2019-02-06T08:24:06-05:00"
    },
    {
      "level": "error",
      "msg": "aggregated error entry with new-comment field",
      "new-comment": "this is an aggregated log entry with reset comment field",
      "time": "2019-02-06T08:24:06-05:00"
    }
  ],
  "banner": "[GIN] ----------- GinLogrusWithTracing -----------"
}

Go interfaces and nil

This little subtlety in Go caught me today.  I was trying determine if what an interface referenced was nil and I wrote a bit of code like this (this is not the actual code I wrote, just a simple version to demonstrate the issue):

type I interface {

}

func main() {

var p *int

var i I

i = p

if i != nil {

fmt.Println("p + 1 ==", *i.(*int) + 1)

}

}

Sadly, it did not have the intended outcome and the program panicked:

panic: runtime error: invalid memory address or nil pointer dereference

What happened?  I tested to see if the interface was nil but the program still panicked over a nil pointer?  That can't be right.  So I wrote a small test program and realized something pretty simple.  You need to test both that the interface isn't nil and also check to make sure that what it references isn't nil:

type I interface {
}

func main() {
var p *int
var i I
i = p
if i != nil && i.(*int) != nil {
fmt.Println("p + 1 ==", *i.(*int) + 1)
}
}


I've been writing Go for over a year and I'd never really thought about this before.. or been caught by a defect because of it.

Writing unit tests when the func calls panic()

It's a new year and you've decide to step up your unit testing game.   Life is good as a Go programer, since Go comes with an awesome test package in the standard library - https://golang.org/pkg/testing

This is great.  There's no reason to re-invent the wheel. No really, please don't write yet another test package.  You're not that special and your software isn't super special as well.  Please, I'm begging you to use the standard lib solution. DevOps and every other person that maintains your software in the future will curse your name forever if you decide to roll your own.

So that's settled, you're writing some unit tests using the Go testing package, and you stubble into this function:

func mustExist(varValue string, varName string) {
    if len(varValue) == 0 {
        panic(varName + " not set")
    }
}

You have so many questions at this point.  First, why would someone write this func?  What were they thinking?  Don't they know you should never panic?   Haven't they seen Mat Ryer's presentation: Things in Go I never use   Even though you have all these questions, you realize that you probably should refactor this thing, since it's used a LOT in this thing you're writing unit tests for.

So, how are you going write unit tests for this thing?  The first time you send it bad data, it's going to panic and your tests are going to come to a screeching halt.

func TestPanic(t *testing.T) {
mustExist("", "what the heck")
}

--- FAIL: TestPanic (0.00s)

panic: what the heck not set [recovered]

panic: what the heck not set

Yep, just as we feared.  But don't fret, there's a simple solution to this problem: defer and recover. This is straight from the go wiki:  panic  causes the program stack to begin unwinding and  recover  can stop it.

Now we can stop panicking and just write the unit test:

func Test_mustExist(t * testing.T) {
    tests: = [] struct {
        name string
        varValue string
        varName string
        wantPanic bool
    } {
        {
            name: "mom",
            varValue: "hi",
            varName: "mom",
            wantPanic: false
        }, {
            name: "panic",
            varValue: "",
            varName: "panic",
            wantPanic: true
        },
    }
    for _,
    tt: = range tests {
        t.Run(tt.name, func(t * testing.T) {
            func() {
                defer func() {
                    if err: = recover();
                    err != nil {
                        if !tt.wantPanic {
                            t.Errorf("Unexpected panic")
                        }
                    }
                }()
                mustExist(tt.varValue, tt.varName)
            }()
        })
    }
}

Yep, go is pretty sweet.  Even when you're completely panicked, it provides an elegant clear solution.

Happy New Year.

Using stern to view logs on Kubernetes 

Stern is a kubernetes tool that allows you to tail logs from multiple PODs at one time. I find stern to be an invaluable tool everyday and it's simple to install and use.  It makes tailing logs from multiple Pods of a deployment trivial and no more difficult than tailing files on your local system.

Installation:

• Binary releases: https://github.com/wercker/stern/releases
• Mac: brew install stern
• Of course you can build it from source as well.

The problem stern solves

Before stern, it was a multi-step process to view the logs of my application's pods.  First, I'd fire up kubeclt and get all the pod names:

$ kubectl get pods

NAME                                            READY     STATUS    RESTARTS   AGE

helloworld-7cc4755575-7kbdd       2/2       Running   0          15h

helloworld-7cc4755575-7t2pf       2/2       Running   0          15h

helloworld-7cc4755575-gpdtm       2/2       Running   0          15h

Then I'd use kubeclt again to tail each individual pods logs, and I'd have to match the pod name and container name precisely, or the command would fail:

$ kubectl logs  helloworld-7cc4755575-7kbdd app --since 2m

[GIN] 2018/07/20 - 11:09:51 | 200 |     1.08808ms | GET      /planet/1a0ffebfcbea

[GIN] 2018/07/20 - 11:10:03 | 201 |   11.273898ms | POST     /planet

[GIN] 2018/07/20 - 11:11:27 | 200 |    7.740818ms | GET      /planet/9e7e61e8615e

Okay... that's the logs for one container in one pod, now I just need to repeat the process for every container in the pod and then multiple that by the number of pods in the deployment.  And there's no way for me to stream all of them together easily.

It's easy to see that this is a far from ideal expedient process and there's got to be a better way to do this.

Using stern

Thankfully, stern eliminates all the tedium associated with tailing pod logs in Kubernetes and provides a simple easy to use interface.   Let's go back to our example above: I need to view the logs of my applications logs.  With stern, I can accomplish that task with one command:

$ stern helloworld -s 20s 

helloworld-gd2g9 app [GIN] 2018/07/20 - 11:50:45 | 200 |   22.813937ms | PUT   /planet/b8ae-0d1c6f1a83e7

helloworld-gd2g9 app [GIN] 2018/07/20 - 11:50:45 | 200 |   15.813246ms | DELETE /planet/0d1c6f1a83e7

helloworld-gd2g9 app [GIN] 2018/07/20 - 11:50:46 | 200 |     6.73568ms | GET /planet/0d1c6f1a83e7

helloworld-gd2g9 app [GIN] 2018/07/20 - 11:50:49 | 201 |   21.484858ms | POST /planet

helloworld-lnkfw app [GIN] 2018/07/20 - 11:50:50 | 200 |     729.593µs | GET /planet/0d1c6f1a83e7

helloworld-lnkfw sidecar [GIN] 2018-07-20T11:50:50Z | 200 |  1.361762ms | GET /planet/0d1c6f1a83e7 

As you can see, stern tailed all the pods and all the containers in one stream.  This is incredibly powerful and useful.

Of course, stern allows you to filter your results by:

• regex's that match pods
• which containers (--container -c)
• how far back in time to get logs (--since -s),
• the type of output (--output -o).  Since we do structure JSON logs

I use -o=raw all the time to get raw logs and then filter them via https://stedolan.github.io/jq/