DEV Community: Ciro S. Costa

kubectl create pizza

Ciro S. Costa — Fri, 11 Dec 2020 16:04:47 +0000

Hey,

I recently created a series of articles and videos that goes through the
development of Kubernetes custom resources and controllers (see
gum.co/kubernetes-crds), but I missed that
nice catchy example that would showcase what custom resources are all about.

So, why not implement the ultimate missing feature that Kubernetes should have?

tl;dr: see https://github.com/cirocosta/pizza-controller

usage

First, create a secret with the credit card information (yeah, this is fine,
trust me) to be used during payment:

kind: Secret
apiVersion: v1
metadata:
  name: credit-card
stringData:
  number: 123343132314232
  expiration: 12/02
  securityCode: 123
  zip: m5d0l2

then, create a PizzaCustomer, the representation of you, the customer:

kind: PizzaCustomer
apiVersion: ops.tips/v1alpha1
metadata:
  name: you
spec:
  firstName: barack
  lastName: obama
  email: obama@gov.gov
  phone: "31241323"
  streetNumber: "20"
  streetName: King St
  city: Toronto
  state: "ON"
  zip: m5lz8j

With the PizzaCustomer object created, we can see what's the closest store available
for it:

$ kubectl get pizzacustomer

NAME              CLOSEST
you               store-123

Looking at the PizzaStore object, we can check out its menu:

$ kubectl get pizzastore store-123 -o yaml

kind: PizzaStore
metadata:
  name: store-123
spec:
  address: |
    51 Niagara St
    Toronto, ON M5V1C3
  id: "10391"
  phone: 416-364-3939
  products:
    - description: Unique Lymon (lemon-lime) flavor, clear, clean and crisp with no caffeine.
      id: 2LSPRITE
      name: Sprite
      size: 2 Litre

Knowing what's available to us, we can place the order:

kind: PizzaOrder
apiVersion: ops.tips/v1
metadata:
  name: ma-pizza
spec:
  yeahSurePlaceThisOrder: true  # otherwise, it'll just calculate the price
  storeRef: {name: store-123}
  customerRef: {name: you}
  payment:
    creditCardSecretRef: {name: cc}
  items:
    - ticker: 10SCREEN
      quantity: 1

To keep track of what's going on with your pizza, check out the order's status:

$ kubectl get pizzaorder ma-pizza

NAME    PRICE      ID                     CONDITION     AGE
order   9.030000   Wlz6HcE6BPlfQNlxDAXa   OrderPlaced   68m

and, there we go!

wait, but why?

no no, wait, why not?

see, with CI/CD being part of Kubernetes through projects like Argo and Tekton,
where you declare what your pipeline/workflow will be in terms of Kubernetes
resources, we're now able to get that nice pizza for the team after a
successfull release.

apiVersion: argoproj.io/v1alpha1
kind: Workflow
metadata:
  generateName: release-
spec:
  entrypoint: pi-tmpl
  templates:
  - name: main
    steps:
      - - name: unit-tests
          template: test
        - name: integration-tests
          template: test
          arguments:
            parameters:
              - name: type
                value: integration
      - - name: release
          template: release
      - - name: get-that-pizza
          template: order-pizza

  - name: order-pizza
    resource:
      action: create      
      manifest: |
        kind: PizzaOrder
        apiVersion: ops.tips/v1
        metadata:
          name: ma-pizza
        spec:
          yeahSurePlaceThisOrder: true
          storeRef: {name: store-123}
          customerRef: {name: you}
          payment:
            creditCardSecretRef: {name: cc}
          items:
            - ticker: 10SCREEN
              quantity: 2

i don't know about you, but that sounds quite right to me ¯\_(ツ)_/¯

installation

being a legit Kubernetes custom resource, you install it just like you would
install Tekton, kpack, or anything like that: you submit a manifest that
contains the CustomResourceDefinition objects to Kubernetes, a Deployment
that materializes the controller as a container in a pod, and then ... that's
it!

git clone https://github.com/cirocosta/pizza-controller
cd pizza-controller

kapp deploy -a pizza-controller -f ./config/release.yaml


# OR .. plain old kubectl
#
kubectl apply -f ./config/release.yaml

but, that's dumb

i disagree

I think it's a pretty cool example of the concepts behind extending
kubernetes via custom resources, and something that might bring you some
thoughts of ways in which you could bring the
declarative nature of Kubernetes objects plus the level-triggered approach to
controllers to bring to Kubernetes the ability to request external resources.

for instance, projects like crossplane give you pretty
much that, except that instead of ordering a pizza, you're ordering ... a
database (or things like that).

what's next?

are you really into ordering pizza using kubectl?

like, really? are you sure?

here's what's missing:

well, any .. tests 🐴
order tracking (it's xml-based - SOAP stuff)
being more flexible with non-canadian folks (it's currently hardcoded for Canada, but could easily be changed)

at the moment I got my pizza .. development finished 😅 maybe you'll
carry it forward? head to https://github.com/cirocosta/pizza-controller

want to know more?

check out https://gum.co/kubernetes-crds

Article recommendation using Hugo

Ciro S. Costa — Sat, 06 Oct 2018 00:00:00 +0000

Hey,

This month I’ve been interested in increasing the overall time that a user spends navigating there in the blog (ops.tips).

Being article recommendation something that the blog was missing, I went for it.

Check out how you can do it for your static site too!

The idea

Given that my content usually is tagged, I thought that one easy way of adding article recommendation would be to simply take the union between the articles tagged with the same tag as the current one and then randomly list them.

For instance, consider the case of this article: A UDP server and client in Go.

Being the article tagged as Linux, Networking, and Go, we can infer that there are three pools of content that might be similar to what’s been there in this article (having some overlap between them).

Moving forward, we can think that once we addressed the possible articles to recommend, the next step is to give preference to some of them: rank higher those with more overlap in more categories.

Let’s implement that then.

Implementing a Recommended Articles list in Hugo

As a first step, we retrive all the pages that are not the currently page that we are seeing:

// Assign the current scope (the current page) to
// a variable named `$currentArticle` so that within
// other scopes we are able to still reference the 
// current page.
{{ $currentArticle := . }}

// From the list of all pages from the site, only keep
// those whose name is different from the name of the
// current article and whose kind is `page`.
//
// ps.: here we could check something else, like permalink
// or another unique identifier.
// 
// ps.: here you'd probably pick a specific section. To do
// so, perform another `where`.
{{ $articles := where 
        (where $.Site.Pages ".Kind" "eq" "page") 
        ".Title" "!=" $currentArticle.Title }}

note.: the where above must be inlined. Here I broke it in multiple lines just for achieving better readability.

Next, we now create two lists:

one that references all articles with at least two tags that are in the set of tags in the current article; and
a list that references all articles with a single tag in the set of tags of the current article.

We can call these two veryRelevantArticles and relevantArticles (accordingly):

// Instantiate each of them with an empty slice.
{{ $veryRelevantArticles := slice }}
{{ $relevantArticles := slice }}

With the variables set, we can now start iterating over our list of all article pages and checking how many intersections they have with the set of tags from our current page:

// Iterate over each of the articles from the list 
// of article pages
{{ range $idx, $article := $articles }}
        // Compute the number of tag intersactions.
        {{ $numberOfIntersections := len (
                intersect $article.Params.tags $currentArticle.Params.Tags
        ) }}

        // For those pages with a big number of 
        // intersections (>= 2), put in the first
        // slice.
        {{ if (ge $numberOfIntersections 2) }}
                {{ $veryRelevantArticles = 
                        $veryRelevantArticles | append $article }}
        // For the rest (single intersaction), put in the 
        // second slice.
        {{ else if (eq $numberOfIntersections 1) }}
                {{ $relevantArticles = 
                        $relevantArticles | append $article }}
        {{ end }}

        // note.: I'm ignoring those with 0 intersections.
{{ end }}

Once we’ve gotten all interesting articles, now we can create an ordered list starting from those with the biggest number of recommendations to those with the lowest, i.e., we can create a list that corresponds to the concatenation of the two variables we created above:

// Create an empty slice to hold the final list
{{ $recommendedArticles := slice }}

// For each very recommended article, append to the
// list.
{{ range $veryRelevantArticles }} 
        {{ $recommendedArticles = $recommendedArticles | append . }} 
{{ end }}

// For each recommended article, append to the
// list.
// 
// This will lead to something like 
// [very, very, rec, rec, rec....]
{{ range $relevantArticles }} 
        {{ $recommendedArticles = $recommendedArticles | append . }} 
{{ end }}

With the list created, now it’s time to show it.

Displaying the recommendation list

With a list containing those with the biggest number of intersections first and then the ones that have the less number of intersections, we can move forward with displaying that.

For this Blog, I took the approach of showing a shuffle of the very first five that are picked from such list.

<ul>

// For every article in the set of the first 5
// recommended articles shuffled, show their
// anchor.
{{ range (shuffle (first 5 $recommendedArticles)) }}
<li>
  <a href="{{ .Permalink }}">
    {{ .Title }}
  </a>
</li>
{{ end }}

</ul>

This guarantees that if I have some articles with big intersections with the content of the current article, they get displayed (even though unordered).

If you have a lot of content, and a lot of tags, you might want to create more categories (not only veryRelevant and relevant).

In such case, something more elaborate could be done.

Closing thoughts

It’s interesting to see how much we can accomplish without “an actual language”.

Although Hugo gives us some simple primitives, we can build upon that and achieve some pretty satisfactory results.

What about you? Have you ever achieved something similar doing something different? Please let me know!

Also, if you have any questions, feel free to drop me a message at @cirowrc on Twitter.

Have a good one!

A UDP server and client in Go

Ciro S. Costa — Sun, 30 Sep 2018 00:00:00 +0000

Hey,

While it’s prevalent to see implementations of TCP servers in Golang, it’s not very common to see the same when it comes to UDP.

Besides the many differences between UDP and TCP, using Go it feels like these are pretty much alike, except for little details that arise from each protocol specifics.

If you feel like some Golang UDP knowledge would be valuable, make sure you stick to the end.

As an extra, this article also covers the underlying differences between TCP and UDP when it comes to the syscalls that Golang uses under the hood, as well as some analysis of what the Kernel does when those syscalls get called.

Stay tuned!

Overview

As a goal for the blog post, the final implementation should look like an “echo channel”, where whatever a client writes to the server, the server echoes back.

        .---> HELLO!! -->-.
        |                 |
client -*                 *--> server --.
   ^                                    |
   |                                    |
   *---<----- HELLO!! ---------<--------*

Being UDP a protocol that doesn’t guarantee reliable delivery, it might be the case that the server receives the message, and it might be the case that the client receives the echo back from the server.

The flow might complete successfully (or not).

        .---> HELLO!! -->-.
        |                 |
client -*                 *--> server --.
                                        |
                                        |
            whoops, lost! -----<--------*

Not being connection-oriented, the client won’t really “establish a connection”, like in TCP; whenever a message arrives at the server, it won’t “write a response back to the connection”, it will only direct a message to the address that wrote to it.

With that in mind, the flow should look like this:

TIME    DESCRIPTION

t0      client and server exist

          client                         server
          10.0.0.1                       10.0.0.2


t1      client sends a message to the server

          client      ------------>      server
          10.0.0.1         msg           10.0.0.2
                       (from:10.0.0.1)
                       (to:  10.0.0.2)


t2      server receives the message, then it takes
        the address of the sender and then prepares
        another message with the same contents and
        then writes it back to the client

          client      <------------      server
          10.0.0.1         msg2          10.0.0.2
                       (from:10.0.0.1)
                       (to:  10.0.0.2)


t3      client receives the message

          client                         server
          10.0.0.1                       10.0.0.2

           thxx!! :D :D


ps.: ports omitted for brevity

That said, let’s see how that story rolls out in Go.

If you’d like a real deep dive, make sure you consider these books:

Computer Networking: A top-down approach

Unix Network Programming, Volume 1: The Sockets Networking API (3rd Edition)

The Linux Programming Interface

The first takes the approach of going from the very high level part of the networking stack (application layer), and then goes down to the very bottom, explaining the details of the protocols in there as it goes through them - if you need an excellent refresher on networking concepts without digging into the implementation details, check this one out!

The other two are more about Linux and Unix in general - very worthwhile if you’re more focused on the implementation.

Have a good reading!

Sending UDP packets using Go

Kicking off with the whole implementation at once (full of comments), we can start depicting it, understanding piece by piece, until the point that we can understand each and every interaction that happens behind the scenes.

// client wraps the whole functionality of a UDP client that sends
// a message and waits for a response coming back from the server
// that it initially targetted.
func client(ctx context.Context, address string, reader io.Reader) (err error) {
    // Resolve the UDP address so that we can make use of DialUDP
    // with an actual IP and port instead of a name (in case a
    // hostname is specified).
    raddr, err := net.ResolveUDPAddr("udp", address)
    if err != nil {
        return
    }

    // Although we're not in a connection-oriented transport,
    // the act of `dialing` is analogous to the act of performing
    // a `connect(2)` syscall for a socket of type SOCK_DGRAM:
    // - it forces the underlying socket to only read and write
    // to and from a specific remote address.
    conn, err := net.DialUDP("udp", nil, raddr)
    if err != nil {
        return
    }

    // Closes the underlying file descriptor associated with the,
    // socket so that it no longer refers to any file.
    defer conn.Close()

    doneChan := make(chan error, 1)

    go func() {
        // It is possible that this action blocks, although this
        // should only occur in very resource-intensive situations:
        // - when you've filled up the socket buffer and the OS
        // can't dequeue the queue fast enough.
        n, err := io.Copy(conn, reader)
        if err != nil {
            doneChan <- err
            return
        }

        fmt.Printf("packet-written: bytes=%d\n", n)

        buffer := make([]byte, maxBufferSize)

        // Set a deadline for the ReadOperation so that we don't
        // wait forever for a server that might not respond on
        // a resonable amount of time.
        deadline := time.Now().Add(*timeout)
        err = conn.SetReadDeadline(deadline)
        if err != nil {
            doneChan <- err
            return
        }

        nRead, addr, err := conn.ReadFrom(buffer)
        if err != nil {
            doneChan <- err
            return
        }

        fmt.Printf("packet-received: bytes=%d from=%s\n",
            nRead, addr.String())

        doneChan <- nil
    }()

    select {
    case <-ctx.Done():
        fmt.Println("cancelled")
        err = ctx.Err()
    case err = <-doneChan:
    }

    return
}

Having the client code, we can now depict it, exploring each of its nuances.

Address resolution

Before we even start creating a socket and carrying about sending the information to the server, the first thing that happens is a name resolution that translates a given name (like, google.com) into a set of IP addresses (like, 8.8.8.8).

The way we do that in our code is with the call to net.ResolveUDPAddr, which in a Unix environment, goes all the way down to performing the DNS resolution via the following stack:

(in a given goroutine ...)
    >> 0 0x00000000004e5dc5 in net.(*Resolver).goLookupIPCNAMEOrder
           at /usr/local/go/src/net/dnsclient_unix.go:553
    >> 1 0x00000000004fbe69 in net.(*Resolver).lookupIP
           at /usr/local/go/src/net/lookup_unix.go:101
        2 0x0000000000514948 in net.(*Resolver).lookupIP-fm
           at /usr/local/go/src/net/lookup.go:207
        3 0x000000000050faca in net.glob..func1
           at /usr/local/go/src/net/hook.go:19
    >> 4 0x000000000051156c in net.(*Resolver).LookupIPAddr.func1
           at /usr/local/go/src/net/lookup.go:221
        5 0x00000000004d4f7c in internal/singleflight.(*Group).doCall
           at /usr/local/go/src/internal/singleflight/singleflight.go:95
        6 0x000000000045d9c1 in runtime.goexit
           at /usr/local/go/src/runtime/asm_amd64.s:1333

(in another goroutine...)
0 0x0000000000431a74 in runtime.gopark
   at /usr/local/go/src/runtime/proc.go:303
1 0x00000000004416dd in runtime.selectgo
   at /usr/local/go/src/runtime/select.go:313
2 0x00000000004fa3f6 in net.(*Resolver).LookupIPAddr <<
   at /usr/local/go/src/net/lookup.go:227
3 0x00000000004f6ae9 in net.(*Resolver).internetAddrList <<
   at /usr/local/go/src/net/ipsock.go:279
4 0x000000000050807d in net.ResolveUDPAddr <<
   at /usr/local/go/src/net/udpsock.go:82
5 0x000000000051e63b in main.main
   at ./resolve.go:14
6 0x0000000000431695 in runtime.main
   at /usr/local/go/src/runtime/proc.go:201
7 0x000000000045d9c1 in runtime.goexit
   at /usr/local/go/src/runtime/asm_amd64.s:1333

If I’m not mistaken, the overall process looks like this:

it checks if we’re giving an already IP address or a hostname; if a hostname, then
looks up the host using the local resolver according to the lookup order specified by the system; then,
eventually performs an actual DNS request asking for records for such domain; then,
if all of that succeeds, a list of IP addresses is retrieved and then sorted out according to an RFC; which gives us the highest priority IP from the list.

Follow the stack trace above and you should be able to see by yourself the source code where the “magic” happens (it’s an interesting thing to do!).

With an IP address chosen, we can proceed.

note.: this process is not different for TCP.

The book Computer Networking: A top-down approach has a great section about DNS.

I’d really recommend you going through it to know more about.

I also wrote a blog post about writing something that is able to resolve A records from scratch using Go: Writing DNS messages from scratch using Go.

TCP Dialing vs UDP Dialing

Instead of using a regular Dial commonly used with TCP, for our UDP client, a different method was used: DialUDP.

The reason for that is that we can enforce the type of address passed, as well as receive a specialized connection: the “concrete type” UDPConn instead of the generic Conn interface.

Although both Dial and DialUDP might sound like the same (even when it comes to the syscalls used while talking to the kernel), they end up being pretty different concerning the network stack implementation.

For instance, we can check that both methods use connect(2) under the hood:

// TCP - performs an actual `connect` under the hood,
// trying to establish an actual connection with the
// other side.
net.Dial("tcp", "1.1.1.1:53")

// strace -f -e trace=network ./main
// [pid 4891] socket(
        AF_INET, 
 -----> SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 
        IPPROTO_IP) = 3
// [pid 4891] connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("1.1.1.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
...

// UDP - calls `connect` just like TCP, but given that
// the arguments are different (it's not SOCK_STREAM),
// the semantics differ - it constrains the socket 
// regarding to whom it might communicate with.
net.Dial("udp", "1.1.1.1:53")

// strace -f -e trace=network ./main
// [pid 5517] socket(
        AF_INET, 
 -----> SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 
        IPPROTO_IP) = 3
// [pid 5517] connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("1.1.1.1")}, 16) = 0
...

While they’re pretty much the same, from the documentation we can see how they are semantically different depending on the way we configure the socket created via the socket(2) call that happens before connect(2):

If the socket sockfd is of type SOCK_DGRAM , then addr is the address to which datagrams are sent by default, and the only address from which datagrams are received.

If the socket is of type SOCK_STREAM or SOCK_SEQ‐PACKET, this call attempts to make a connection to the socket that is bound to the address specified by addr.

Should we be able to verify that with the TCP transport the Dial method would perform the act of really connecting to the other side? Sure!

./tools/funccount -p $(pidof main) 'tcp_*'
Tracing 316 functions for "tcp_*"... Hit Ctrl-C to end.
^C
FUNC COUNT
tcp_small_queue_check.isra.28 1
tcp_current_mss 1
tcp_schedule_loss_probe 1
tcp_mss_to_mtu 1
tcp_write_queue_purge 1
tcp_write_xmit 1
tcp_select_initial_window 1
tcp_fastopen_defer_connect 1
tcp_mtup_init 1
tcp_v4_connect 1
tcp_v4_init_sock 1
tcp_rearm_rto.part.61 1
tcp_close 1
tcp_connect 1
tcp_send_fin 1
tcp_rearm_rto 1
tcp_tso_segs 1
tcp_event_new_data_sent 1
tcp_check_oom 1
tcp_clear_retrans 1
tcp_init_xmit_timers 1
tcp_init_sock 1
tcp_initialize_rcv_mss 1
tcp_assign_congestion_control 1
tcp_sync_mss 1
tcp_init_tso_segs 1
tcp_stream_memory_free 1
tcp_setsockopt 1
tcp_chrono_stop 2
tcp_rbtree_insert 2
tcp_set_state 2
tcp_established_options 2
tcp_transmit_skb 2
tcp_v4_send_check 2
tcp_rate_skb_sent 2
tcp_options_write 2
tcp_poll 2
tcp_release_cb 4
tcp_v4_md5_lookup 4
tcp_md5_do_lookup 4

In the case of UDP though, in theory, it merely takes care of marking the socket for reads and writes to the specified address.

Going through the same process that we did for TCP (going further from looking at the syscall interface), we can trace the underlying kernel methods used by both DialUDP and Dial to see how they differ:

./tools/funccount -p $(pidof main) 'udp_*'
Tracing 57 functions for "udp_*"... Hit Ctrl-C to end.
^C
FUNC COUNT
udp_v4_rehash 1
udp_poll 1
udp_v4_get_port 1
udp_lib_close 1
udp_lib_lport_inuse 1
udp_init_sock 1
udp_lib_unhash 1
udp_lib_rehash 1
udp_lib_get_port 1
udp_destroy_sock 1

Much… Much less.

If we go even further, try to explore what happens at each of these calls, we can notice how connect(2) in the case of TCP ends up really transmitting data (to establish perform the handshake, for instance):

PID TID COMM FUNC
6747 6749 main tcp_transmit_skb
        tcp_transmit_skb+0x1
        tcp_v4_connect+0x3f5
        __inet_stream_connect+0x238
        inet_stream_connect+0x3b
        SYSC_connect+0x9e
        sys_connect+0xe
        do_syscall_64+0x73
        entry_SYSCALL_64_after_hwframe+0x3d

While in the case of UDP, nothing is transmitted, just some set up is performed:

PID TID COMM FUNC
6815 6817 main ip4_datagram_connect
        ip4_datagram_connect+0x1 [kernel]
        SYSC_connect+0x9e [kernel]
        sys_connect+0xe [kernel]
        do_syscall_64+0x73 [kernel]
        entry_SYSCALL_64_after_hwframe+0x3d [kernel]

If you’re not convinced yet that these two are really different (in the sense that the TCP one sends packets to establish the connection, while UDP doesn’t), we can set up some triggers in the network stack to tell us whenever packets flow:

# By creating a rule that will only match
# packets destined at `1.1.1.1` and that
# match a specific protocol, we're able
# to see what happens at the time that
# `connect(2)` happens with a given protocol
# or another.
iptables \
        --table filter \
        --insert OUTPUT \
        --jump LOG \
        --protocol udp \
        --destination 1.1.1.1 \
        --log-prefix="[UDP] "

iptables \
        --table filter \
        --insert OUTPUT \
        --jump LOG \
        --protocol tcp \
        --destination 1.1.1.1 \
        --log-prefix="[TCP] "

Now, run Dial against a TCP target and DialUDP target and compare the differences.

You should only see [TCP] logs:

[46260.105662] [TCP] IN= OUT=enp0s3 DST=1.1.1.1 SYN URGP=0
[46260.120454] [TCP] IN= OUT=enp0s3 DST=1.1.1.1 ACK URGP=0
[46260.120718] [TCP] IN= OUT=enp0s3 DST=1.1.1.1 ACK FIN URGP=0
[46260.150452] [TCP] IN= OUT=enp0s3 DST=1.1.1.1 ACK URGP=0

If you’re not familiar with the inner workings of dmesg, check out my other blog post - dmesg under the hood.

By the way, The Linux Programming Interface is a great book to know more about sockets and other related topics!

Writing to a UDP “connection”

With our UDP socket properly created and configured for a specific address, we’re now on time to go through the “write” path - when we actually take some data and write to the UDPConn object received from net.DialUDP.

A sample program that just sends a little bit of data to a given UDP server would be as follow:

// Perform the address resolution and also
// specialize the socket to only be able
// to read and write to and from such
// resolved address.
conn, err := net.Dial("udp", *addr)
if err != nil {
        panic(err)
}
defer conn.Close()

// Call the `Write()` method of the implementor
// of the `io.Writer` interface.
n, err = fmt.Fprintf(conn, "something")

Given that conn returned by Dial implements the io.Writer interface, we can make use of something like fmt.Fprintf (that takes an io.Writer as its first argument) as let it call Write() with the message we pass to it.

If interfaces and other Golang concepts are not clear for you yet, make sure you check Kernighan’s book: The Go Programming Language.

yeah, from the guy who wrote The C Programming Language with Dennis Ritchie.

Under the hood, UDPConn implements the Write() method from the io.Writer interface by being a composition of conn, a struct that implements the most basic methods regarding writing to and reading from a given file descriptor:

type conn struct {
    fd *netFD
}

// Write implements the Conn Write method.
func (c *conn) Write(b []byte) (int, error) {
    if !c.ok() {
        return 0, syscall.EINVAL
    }
    n, err := c.fd.Write(b)
    if err != nil {
        err = &OpError{Op: "write", Net: c.fd.net, Source: c.fd.laddr, Addr: c.fd.raddr, Err: err}
    }
    return n, err
}

// UDPConn is the implementation of the Conn 
// and PacketConn interfaces for UDP network 
// connections.
type UDPConn struct {
    conn
}

Now, knowing that in the end fmt.Fprintf(conn, "something") ends up in a write(2) to a file descriptor (the UDP socket), we can investigate even further and see how does the kernel path look for such write(2) call:

PID TID COMM FUNC
14502 14502 write.out ip_send_skb
        ip_send_skb+0x1 
        udp_sendmsg+0x3b5 
        inet_sendmsg+0x2e 
        sock_sendmsg+0x3e 
        sock_write_iter+0x8c 
        new_sync_write+0xe7 
        __vfs_write+0x29 
        vfs_write+0xb1 
        sys_write+0x55 
        do_syscall_64+0x73 
        entry_SYSCALL_64_after_hwframe+0x3d

At that point, the packet should be on its way to the other side of the communication channel.

Receiving from a UDP “connection” in a client

The act of receiving from UDPConn can be seen as pretty much the same as the “write path”, except that at this time, a buffer is supplied (so that it can get filled with the contents that arrive), and we don’t really know how long we have to wait for the content to arrive.

For instance, we could have the following code path for reading from a known address:

buf := make([]byte, *bufSize)
_, err = conn.Read(buf)

This would turn into a read(2) syscall under the hood, which would then go through vfs and turn into a read from a socket:

22313 22313 read __skb_recv_udp
        __skb_recv_udp+0x1 
        inet_recvmsg+0x51 
        sock_recvmsg+0x43 
        sock_read_iter+0x90 
        new_sync_read+0xe4 
        __vfs_read+0x29 
        vfs_read+0x8e 
        sys_read+0x55 
        do_syscall_64+0x73 
        entry_SYSCALL_64_after_hwframe+0x3d

Something important to remember is that when it comes to reading from the socket, that’s going to be a blocking operation.

Given that a message might never return from such socket, we can get stuck waiting forever.

To avoid such situation, we can set a reading deadline that would kill the whole thing in case we wait for too long:

buf := make([]byte, *bufSize)

// Sets the read deadline for now + 15seconds.
// If you plan to read from the same connection again,
// make sure you expand the deadline before reading
// it.
conn.SetReadDeadline(time.Now().Add(15 * time.Second))
_, err = conn.Read(buf)

Now, In case the other end takes too long to answer:

read udp 10.0.2.15:41745->1.1.1.1:53: i/o timeout

Receiving from a UDP “connection” in a server

While that’s great for the client (we know whom we’re reading from), it’s not for a server.

The reason why is that at the server side, we don’t know who we’re reading from (the address is unknown).

Differently from the case of a TCP server where we have accept(2) which returns to the server implementor the connection that the server can write to, in the case of UDP, there’s no such thing as a “connection to write to”. There’s only a “whom to write to”, that can be retrieved by inspecting the packet that arrived.

WITH READ

  "Hmmm, let me write something to
   my buddy at 1.1.1.1:53"

   client --.
            |
            | client: n, err := udpConn.Write(buf)
            | server: n, err := udpConn.Read(buf)
            |
            *---> server
                  "Oh, somebody wrote me something!
                   I'd like to write back to him/her,
                   but, what's his/her address?

                   I don't have a connection... I need
                   an address to write to! I can't to
                   a thing now!"



WITH READFROM

   client --.
            |
            | client: n, err := udpConn.Write(buf)
            | server: n, address, err := udpConn.Read(buf)
            |
            *---> server
                  "Oh, looking at the packet, I can
                   see that my friend Jane wrote to me,
                   I can see that from `address`!

                   Let me answer her back!"

For that reason, on the server, we need the specialized connection: UDPConn.

Such specialized connection is able of giving us ReadFrom, a method that instead of just reading from a file descriptor and adding the contents to a buffer, it also inspects the headers of the packet and gives us information about who sent the package.

Its usage looks like this:

buffer := make([]byte, 1024)

// Given a buffer that is meant to hold the
// contents from the messages arriving at the
// socket that `udpConn` wraps, it blocks until
// messages arrive. 
//
// For each message arriving, `ReadFrom` unwraps
// the message, getting information about the
// sender from the protocol headers and then
// fills the buffer with the data.
n, addr, err := udpConn.ReadFrom(buffer)
if err != nil {
        panic(err)
}

An interesting way of trying to understand how things work under the hood is looking at the plan9 implementation (net/udpsock_plan9.go).

Here’s how it looks (with comments of my own):

func (c *UDPConn) readFrom(b []byte) (n int, addr *UDPAddr, err error) {
        // creates a buffer a little bit bigger than
        // the one we provided (to account for the header of
        // the UDP headers)
    buf := make([]byte, udpHeaderSize+len(b))

        // reads from the underlying file descriptor (this might
        // block).
    m, err := c.fd.Read(buf)
    if err != nil {
        return 0, nil, err
    }
    if m < udpHeaderSize {
        return 0, nil, errors.New("short read reading UDP header")
    }

        // strips out the parts that were not readen
    buf = buf[:m]

        // interprets the UDP header
    h, buf := unmarshalUDPHeader(buf)

        // copies the data back to our supplied buffer
        // so that we only receive the data, not the header.
    n = copy(b, buf)
    return n, &UDPAddr{IP: h.raddr, Port: int(h.rport)}, nil
}

Naturally, under Linux, that’s not the path that readFrom takes. It uses recvfrom which does the whole “UDP header interpretation” under the hood, but the idea is the same (except that with plan9 it’s all done in userspace).

To verify the fact that under Linux we’re using recvfrom, we trace UDPConn.ReadFrom down (you can use delve for that):

0 0x00000000004805b8 in syscall.recvfrom
   at /usr/local/go/src/syscall/zsyscall_linux_amd64.go:1641
1 0x000000000047e84f in syscall.Recvfrom
   at /usr/local/go/src/syscall/syscall_unix.go:262
2 0x0000000000494281 in internal/poll.(*FD).ReadFrom
   at /usr/local/go/src/internal/poll/fd_unix.go:215
3 0x00000000004f5f4e in net.(*netFD).readFrom
   at /usr/local/go/src/net/fd_unix.go:208
4 0x0000000000516ab1 in net.(*UDPConn).readFrom
   at /usr/local/go/src/net/udpsock_posix.go:47
5 0x00000000005150a4 in net.(*UDPConn).ReadFrom
   at /usr/local/go/src/net/udpsock.go:121
6 0x0000000000526bbf in main.server.func1
   at ./main.go:65
7 0x000000000045e1d1 in runtime.goexit
   at /usr/local/go/src/runtime/asm_amd64.s:1333

At the kernel level, we can also check what are the methods involved:

24167 24167 go-sample-udp __skb_recv_udp
        __skb_recv_udp+0x1 
        inet_recvmsg+0x51 
        sock_recvmsg+0x43 
        SYSC_recvfrom+0xe4 
        sys_recvfrom+0xe 
        do_syscall_64+0x73 
        entry_SYSCALL_64_after_hwframe+0x3d

A UDP Server in Go

Now, going to the server-side implementation, here’s how the code would look like (heavily commented):

// maxBufferSize specifies the size of the buffers that
// are used to temporarily hold data from the UDP packets
// that we receive.
const maxBufferSize = 1024

// server wraps all the UDP echo server functionality.
// ps.: the server is capable of answering to a single
// client at a time.
func server(ctx context.Context, address string) (err error) {
    // ListenPacket provides us a wrapper around ListenUDP so that
    // we don't need to call `net.ResolveUDPAddr` and then subsequentially
    // perform a `ListenUDP` with the UDP address.
    //
    // The returned value (PacketConn) is pretty much the same as the one
    // from ListenUDP (UDPConn) - the only difference is that `Packet*`
    // methods and interfaces are more broad, also covering `ip`.
    pc, err := net.ListenPacket("udp", address)
    if err != nil {
        return
    }

    // `Close`ing the packet "connection" means cleaning the data structures
    // allocated for holding information about the listening socket.
    defer pc.Close()

    doneChan := make(chan error, 1)
    buffer := make([]byte, maxBufferSize)

    // Given that waiting for packets to arrive is blocking by nature and we want
    // to be able of canceling such action if desired, we do that in a separate
    // go routine.
    go func() {
        for {
            // By reading from the connection into the buffer, we block until there's
            // new content in the socket that we're listening for new packets.
            //
            // Whenever new packets arrive, `buffer` gets filled and we can continue
            // the execution.
            //
            // note.: `buffer` is not being reset between runs.
            // It's expected that only `n` reads are read from it whenever
            // inspecting its contents.
            n, addr, err := pc.ReadFrom(buffer)
            if err != nil {
                doneChan <- err
                return
            }

            fmt.Printf("packet-received: bytes=%d from=%s\n",
                n, addr.String())

            // Setting a deadline for the `write` operation allows us to not block
            // for longer than a specific timeout.
            //
            // In the case of a write operation, that'd mean waiting for the send
            // queue to be freed enough so that we are able to proceed.
            deadline := time.Now().Add(*timeout)
            err = pc.SetWriteDeadline(deadline)
            if err != nil {
                doneChan <- err
                return
            }

            // Write the packet's contents back to the client.
            n, err = pc.WriteTo(buffer[:n], addr)
            if err != nil {
                doneChan <- err
                return
            }

            fmt.Printf("packet-written: bytes=%d to=%s\n", n, addr.String())
        }
    }()

    select {
    case <-ctx.Done():
        fmt.Println("cancelled")
        err = ctx.Err()
    case err = <-doneChan:
    }

    return
}

As you might have noticed, it’s not all that different from the client! The reason why is that not having an actual connection involved (like in TCP), both client and servers end up going through the same path: preparing a socket to read and write from and to, then checking the content from the packets and doing the same thing over and over again.

Closing thoughts

It was great to go through this exploration, checking what’s going on behind the scenes in the Go source code (very well written, by the way), as well as in the Kernel.

I think I finally got a great workflow when it comes to debugging with Delve and verifying the Kernel functions with bcc, maybe I’ll write about that soon - let me know if that’d be interesting!

If you have any questions, please let me know! I’m @cirowrc on Twitter, and I’d love to receive your feedback.

Have a good one!

Retrieving the full path of a process on MacOS (and exploring procfs)

Ciro S. Costa — Tue, 25 Sep 2018 00:00:00 +0000

Hey,

Another day I was trying to make sure that a given process that I was running was using a specific binary that I had built, but I couldn’t figure out: ps would only show me the non-absolute path.

# How could I know what is the absolute path of the
# `hugo` binary, assuming that I could have multiple
# `hugo` binaries in `$PATH`?
ps
  PID TTY TIME CMD
 4153 ttys000 5:14.98 hugo serve <<<
 9035 ttys001 0:00.04 /Applications/iTerm.app/Content...
 9037 ttys001 0:00.10 -bash
 9086 ttys001 0:02.27 /usr/local/Cellar/macvim/8.1-15...
 9236 ttys002 0:00.04 /Applications/iTerm.app/Content...
 9238 ttys002 0:00.10 -bash

If I were using Linux though, I thought, that’d be easy: head to /proc, search for the pid of the process and then check what exe links to; done.

# (on a Linux machine ...)
#
# See `hugo` will still not show up with the absolute path
# like on MacOS.
ps aux | grep hugo
ubuntu 2275 0.0 0.0 101852 748 pts/0 Sl+ 00:26 0:00 hugo serve

# Given that the proc filesystem can provide us with some
# more information about the process, check out the `exe`
# link (which should provide a link to the actual executable).
stat /proc/2275/exe
  File: /proc/2275/exe -> /usr/local/bin/hugo
  Size: 0 Blocks: 0 IO Block: 1024 symbolic link
Device: 4h/4d   Inode: 140106 Links: 1
Access: (0777/lrwxrwxrwx) Uid: ( 1001/ ubuntu) Gid: ( 1001/ ubuntu)
Access: 2018-09-24 00:26:37.167004005 +0000
Modify: 2018-09-24 00:26:27.391004005 +0000
Change: 2018-09-24 00:26:27.391004005 +0000
 Birth: -

In this post, I go through how we can gather such information on a MacOS, and what the procfs in Linux is all about.

tl;dr: /proc on Linux is dope; on MacoS: compile a little code that uses proc_pidpath from libproc, or install pidpath.

The /proc filesystem in Linux

In “Linux land”, there’s this thing called “procfs”.

It’s a virtual filesystem - in the sense that there are no real regular files in your disk that map to the filesystem representation - that allows a user (in userspace) to perform some introspection about its current running process and others as well.

From the kernel docs:

The proc file system acts as an interface to internal data structures in the kernel.

It can be used to obtain information about the system and to change certain kernel parameters at runtime (sysctl).

The way the interaction with it is set up is pretty nifty:

each process receives a given path under /proc (like, /proc/<pid>), and then
as subdirectories of this path, various other files and subdirectories are present to allow deeper introspection about the specific pid.

# Display the files and directories present at the
# very root of `/proc`.
#
# Here we can find the list of PIDs that we can access,
# as well as some more system-wide information and 
# settings that we can tweak.
ls -lah /proc
total 4.0K
dr-xr-xr-x 124 root root 0 Sep 24 23:56 .
drwxr-xr-x 24 root root 4.0K Sep 24 23:57 ..
dr-xr-xr-x 9 root root 0 Sep 24 23:56 1
dr-xr-xr-x 9 root root 0 Sep 25 00:54 2016
dr-xr-xr-x 9 root root 0 Sep 24 23:57 417
...
-r--r--r-- 1 root root 0 Sep 25 01:25 sched_debug
-r--r--r-- 1 root root 0 Sep 25 01:25 schedstat
dr-xr-xr-x 4 root root 0 Sep 25 01:25 scsi
lrwxrwxrwx 1 root root 0 Sep 24 23:56 self -> 2574
...

# Getting into a specific pid path, we're able to
# gather more information about the specifics of
# a given process.
ls -lah /proc/472
total 0
dr-xr-xr-x 9 root root 0 Sep 24 23:57 .
dr-xr-xr-x 123 root root 0 Sep 24 23:56 ..
...
lrwxrwxrwx 1 root root 0 Sep 25 01:30 cwd -> /
-r-------- 1 root root 0 Sep 25 01:30 environ
lrwxrwxrwx 1 root root 0 Sep 24 23:57 exe -> /lib/systemd/systemd-udevd
dr-x------ 2 root root 0 Sep 24 23:57 fd
lrwxrwxrwx 1 root root 0 Sep 25 01:30 root -> /
-rw-r--r-- 1 root root 0 Sep 25 01:30 sched
...

Not only that, procfs is very helpful when you’re not sure if a process is blocked on something you didn’t expect (like a write(2) to an nfs mount point that is malformed due to a bad set of servers not responding), or something simple as your process sleeping when you didn’t want to:

# Sleep for 33 days on the background
sleep 33d &
[1] 2786

# Check what's the state of the process
cat /proc/2786/stat
2786 (sleep) S ...
 | | |
 | | `-> state (interruptible sleep)
 | `-> command being run (sleep command)
 `-> process id (the pid we used before)

# Check what's the stack trace (from the kernel
# perspective) that led the process to this 
# sleep state
cat /proc/2786/stack
[<0>] hrtimer_nanosleep+0xd8/0x1d0
[<0>] SyS_nanosleep+0x72/0xa0
[<0>] do_syscall_64+0x73/0x130
[<0>] entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[<0>] 0xffffffffffffffff

procfs under the hood

What’s interesting about being virtual is that the implementation of procfs is able to generate the representation of the filesystem on the fly - whenever you issue an I/O call like read(2), Linux answers back with what you asked for, be it the list of file descriptors opened by a given process, or the list of environment variables that were set at process startup time.

For instance, if tracing the execution of cat /proc/<pid>/meminfo down, we can find the path that the read(2) syscall takes:

# stack trace of `cat /proc/<pid>/meminfo`
        meminfo_proc_show
        proc_reg_read
        __vfs_read
        vfs_read
        sys_read
        do_syscall_64
        entry_SYSCALL_64_after_hwframe

# stack trace of `cat /file.txt` 
# on an ext4 mount point
        ext4_file_read_iter
        __vfs_read
        vfs_read
        sys_read
        do_syscall_64
        entry_SYSCALL_64_after_hwframe

Very different from a regular read (as shown in the second stack trace), there’s no real file on disk being accessed - just meminfo_proc_show returning the contents related to what the user asked for: virtual memory stuff.

By the way, if you’re interested in knowing more about related subjects, a great reference for this type of knowledge is The Linux Programming Interface: A Linux and UNIX System Programming Handbook.

Now to MacOS.

The libproc library in MacOS

Differently from Linux, it feels like we can’t know all that much about how things work on MacOS.

After searching a bit on how to accomplish how to gather information about a process, libproc showed up.

As mentioned in libproc.h:

/*
 * This header file contains private interfaces 
 * to obtain process information.
 *
 * These interfaces are subject to change in future releases.
 */

One thing to note:

the interfaces are private - no guaranteed compatibility with future releases.

This has been elucidated by an Apple staff member on post at the Apple’s developer forum regarding gathering process information:

[…] Apple has not put a lot of effort into providing APIs for getting this sort of information.

What APIs that do exist were either inherited from OS X’s predecessor OSs or were added primarily to meet our internal requirements rather than the needs for third-party developers.

Thus, you will find a lot of places where these APIs are: incomplete; incorrect; poorly documented and aren’t as binary compatible as they should be.

Anyway, we can still make use of it - more specifically, we can make use of proc_pidpath, a method that takes a pid (the pid of the process that we want to know more about), a buffer where the path should be written to, and the buffer size.

int proc_pidpath(
  int pid, // pid of the process to know more about
  void * buffer, // buffer to fill with the abs path
  uint32_t buffersize // size of the buffer
);

That said, we can go ahead and create our Go binary that can handle both Linux and MacOS by specifying two different compilation targets.

A Golang binary that suits Linux and MacOS

Given that libproc will not be a thing under Linux, we can start by creating a pidpath_linux.go file that is meant to be compiled only on Linux, and another file, pidpath_darwin.go, aimed at MacOS machines.

The Linux one is rather simple: it follows the /proc/<pid>/exe symlink, and that’s it:

// +build linux
package main

import (
    "os"
    "strconv"
)

func GetExePathFromPid(pid int) (path string, err error) {
    path, err = os.Readlink("/proc/" + strconv.Itoa(pid) + "/exe")
    return
}

The MacOS version though, needs a little bit more.

Given that we’d access libproc via C, we can leverage CGO.

// +build darwin
package main

// #include <libproc.h>
// #include <stdlib.h>
// #include <errno.h>
import "C"

import (
    "fmt"
    "unsafe"
)

// bufSize references the constant that the implementation
// of proc_pidpath uses under the hood to make sure that
// no overflows happen.
//
// See https://opensource.apple.com/source/xnu/xnu-2782.40.9/libsyscall/wrappers/libproc/libproc.c
const bufSize = C.PROC_PIDPATHINFO_MAXSIZE

func GetExePathFromPid(pid int) (path string, err error) {
        // Allocate in the C heap a string (char* terminated
        // with `/0`) of size `bufSize` and then make sure
        // that we free that memory that gets allocated
        // in C (see the `defer` below).
    buf := C.CString(string(make([]byte, bufSize)))
    defer C.free(unsafe.Pointer(buf))

        // Call the C function `proc_pidpath` from the included
        // header file (libproc.h).
    ret, err := C.proc_pidpath(C.int(pid), unsafe.Pointer(buf), bufSize)
    if ret <= 0 {
        err = fmt.Errorf("failed to retrieve pid path: %v", err)
        return
    }

        // Convert the C string back to a Go string.
    path = C.GoString(buf)
    return
}

That done, we can now consume GetExePathFromPid in our application.

To see that in place, check out cirocosta/pidpath.

Closing thoughts

It was interesting to me to check out how different things are in MacOS land.

Although I use a Macbook Pro as a personal computer (and a Mac at work), I’ve not really paid attention to these little details.

Also, /proc is just so valuable! Definitely worth knowing more about other functionality over there. Make sure you check out The Linux Programming Interface: A Linux and UNIX System Programming Handbook.

If you have any questions, or suggestions to improve this blog post, please let me know! I’m cirowrc, and I’d love to chat.

Have a good one!

Dmesg under the hood

Ciro S. Costa — Sat, 22 Sep 2018 00:00:00 +0000

Hey,

This week I wanted to discover a bit more about how dmesg works under the hood. In the past, I wanted to have alerting based on error messages popping at dmesg, so, maybe by trying to create something that uses the same thing that dmesg uses under the hood, I could better understand it.

Also, I knew that in some systems, it was possible to gather the same information from kern.log and that dmesg was all about reading “the kernel ring buffer”, but, what did that mean?

More specifically, where was dmesg reading from?

In this blog post, I go through some exploration to better understand the whole picture:

Producing logs from kernel space
Producing logs from iptables
Producing logs from a Linux loadable kernel module
Producing logs from kmsg
Seeing kernel logs from user space
Interpreting the kmsg messages

If you have any questions, drop me a message @cirowrc on Twitter!

Producing logs from kernel space

Whenever something in the Linux kernel (which could be a module) wants to do the equivalent of a printf, a similar utility (printk) can be used.

That allows the program to give information back to the developer (or any other user) in userspace to know more about what’s going on with the module - be a warning message, stack traces or some pure debugging information.

To test out producing logs from the Kernel, I came up with some ideas:

iptables has a LOG target that essentially produces some logs from iptables itself whenever the target is, well, targetted. Being iptables something that runs in kernel space (not the cli, I mean - the actual thing), we could see logs coming out of the kernel;
writing a minimal kernel module should not be something very hard - many people did that before. I could write a printk("hello-world") and that’s it!
check if there’s something simpler that we could use to produce the logs (maybe the Kernel exposes a standard interface for doing that?)

Being this an exploration, why not try all of them?

Producing logs from iptables

Although this blog post is not particularly about iptables, we can use it as an example where interacting with something that is going on under the hood deep in the kernel is interesting for a user that sits on userspace.

From iptables man page:

Iptables is used to set up, maintain, and inspect the tables of IP packet filter rules in the Linux kernel. Several different tables may be defined.

These mentioned rules can be either very simple things (drop a packet if it comes from a given source), or some very complicated chain of rules that depend on a bunch of conditionals.

Acknowledging that it’s very useful to be able to visualize the packets that are hitting a specific chain of rules, the LOG target came to existence.

LOG: Turn on kernel logging of matching packets.

When this option is set for a rule, the Linux kernel will print some information on all matching packets (like most IP/IPv6 header fields) via the kernel log.

Here’s an example set up that allows us to see that working:

# List the current state of the `filter` table.
# As we can see below, nothing is set up:
# - any packet arriving w/ our machine as the
# destination is accepted;
# - any packet arriving that should be forwarded
# is dropped;
# - any packet that is sent from our machine is
# accepted (can go through).
iptables --table filter --list
Chain INPUT (policy ACCEPT)
target prot opt source destination

Chain FORWARD (policy DROP)
target prot opt source destination

Chain OUTPUT (policy ACCEPT)
target prot opt source destination

# Add a rule to the OUTPUT chain to log every packet
# that is destined towards 8.8.8.8 (google's public
# dns) 
iptables \
        --table filter \
        --insert OUTPUT \
        --jump LOG \
        --destination 8.8.8.8 \
        --log-prefix="[google-dns-out]"

# Check that the rule has been placed in the OUTPUT 
# chain of the `filter` table
iptables --table filter --list OUTPUT --numeric
Chain OUTPUT (policy ACCEPT)
target prot opt source destination
LOG all -- 0.0.0.0/0 8.8.8.8 LOG flags 0 level 4 prefix "[google-dns-out]"

# Perform a DNS query targetting 8.8.8.8
dig example.com @8.8.8.8
... example.com. 18272  IN  A   93.184.216.34

# Verify the request packet in our logs (dmesg)
dmesg | grep google-dns-out
[66458.608136] [google-dns-out]IN= OUT=enp0s3 SRC=10.0.2.15 DST=8.8.8.8 LEN=80 TOS=0x00 PREC=0x00 TTL=64 ID=30602 PROTO=UDP SPT=39573 DPT=53 LEN=60

Producing logs from a Linux loadable kernel module

Not being a driver developer myself (honestly, having never written a kernel module before), it was interesting to look for resources that would teach me how to accomplish this task.

Based on a guide from The Linux Kernel Labs, I came up with the following code for a very simple kernel module:

/**
 * `module.h` contains the most basic functionality needed for
 * us to create a loadable kernel module, including the `MODULE_*`
 * macros, `module_*` functions and including a bunch of other
 * relevant headers that provide useful functionality for us
 * (for instance, `printk`, which comes from `linux/printk.h`,
 * a header included by `linux/module.h`).
 */

#include <linux/module.h>

/**
 * Following, we make use of several macros to properly provide
 * information about the kernel module that we're creating.
 *
 * The information supplied here are visible through tools like
 * `modinfo`.
 *
 * Note.: the license you choose here **DOES AFFECT** other things -
 * by using a proprietary license your kernel will be "tainted".
 */
MODULE_LICENSE("GPL");
MODULE_AUTHOR("Ciro S. Costa");
MODULE_DESCRIPTION("A hello-world printer");
MODULE_VERSION("0.1");

/** hello_init - initializes the module
 *
 * The `hello_init` method defines the procedures that performs the set up
 * of our module.
 */
static int
hello_init(void)
{
         // By making use of `printk` here (in the initialization),
         // we can look at `dmesg` and verify that what we log here
         // appears there at the moment that we load the module with
         // `insmod`.
    printk(KERN_INFO "HELLO-WORLD: Hello world!\n");
    return 0;
}

static void
hello_exit(void)
{
        // similar to `init`, but for the removal time.
    printk(KERN_INFO "HELLO-WORLD: Bye bye world!\n");
}

// registers the `hello_init` method as the method to run at module
// insertion time.
module_init(hello_init);

// similar, but for `removal`
module_exit(hello_exit);

ps.: the source code is available at github.com/cirocosta/hello-world-lkm

Load the module, and there you go:

dmesg | grep HELLO-WORLD
[62076.224353] HELLO-WORLD: Hello world!

Producing logs from kmsg

A standard interface that we can use to insert messages into the printk buffer is exactly the same that we can use to read the messages from it: /dev/kmsg.

From the kernel documentation:

Injecting messages: Every write() to the opened device node places a log entry in the kernel’s printk buffer.

That is, whatever we echo "haha" as a single write to /dev/kmsg goes into the buffer.

Let’s try it then:

# Generate the message from my current unprivileged
# user and then pipe to the privileged `tee` which is
# able to write into `/dev/kmsg` (yep, /dev/kmsg can be
# see and read, but to write you need more privileges)
echo "haha" | sudo tee "/dev/kmsg"

# Check that we can see our message is indeed there:
dmesg | grep haha
[67030.010334] haha

Seeing kernel logs from user space

Having already spoiled the blog post by mentioning kmsg in the section before, there’s not a bunch to talk now.

The kernel provides to us /dev/kmsg in userspace, a special device that allows us to read from the ring buffer (with multitenancy in mind), and that’s what dmesg uses.

# Trace the syscalls `openat` and `read` to verify
# that it reads from `/dev/kmsg`
strace -e openat,read -f dmesg > /dev/null
openat(AT_FDCWD, "/dev/kmsg", O_RDONLY|O_NONBLOCK) = 3
read(3, "5,0,0,-;Linux version 4.15.0-34-"..., 8191) = 192
read(3, "6,1,0,-;Command line: BOOT_IMAGE"..., 8191) = 142
read(3, "6,2,0,-;KERNEL supported cpus:\n", 8191) = 31
read(3, "6,3,0,-; Intel GenuineIntel\n", 8191) = 29

Going even deeper, whenever a read(2) syscall is emitted targetting such file, the kernel triggers kernel/printk/devkmsg_read internally, taking a message from the circular queue, formatting it and then sending back to the user.

# We can use `iovisor/bcc#examples/trace/stacknoop.py` to
# gather the stack trace from the execution of `devkmsg_read`
# to verify that the `read` gets right there when `vfs_read`
# is called.
./stacksnoop.py -v devkmsg_read
TIME(s) COMM PID CPU FUNCTION
1.875072956 tail 1565 0 devkmsg_read
    devkmsg_read
    vfs_read
    sys_read
    do_syscall_64
    entry_SYSCALL_64_after_hwframe

A similar path is followed when writing to the circular queue as well: whenever a write(2) is issued, at some point devkmsg_write is called.

devkmsg translates such call to the equivalent of a printk, which then takes the path of reaching log_store, the method that ends up finally taking a free space from the queue and adding the log message:

# In one terminal
echo "haha" > /dev/kmsg

# In another terminal
./stacksnoop.py -v log_store
TIME(s) COMM PID CPU FUNCTION
1.786375046 bash 1450 2 log_store
    log_store
    printk_emit
    devkmsg_write
    new_sync_write
    __vfs_write
    vfs_write
    sys_write
    do_syscall_64
    entry_SYSCALL_64_after_hwframe

By knowing that the kernel provides this interface, we can implement a simple program that constantly performs read(2)s against such device and then parses the contents (messages) that arrive.

Interpreting the kmsg messages

Knowing that every read(2) syscall performed against /dev/kmsg returns us a single message, we’re left to: - implementing a reader that continuously looks at /dev/kmsg and then extracts the raw messages from there; as well as - implementing the parsing of those messages.

The later is the most interesting, imo.

Each message comes packed in the following format: a list of comma-separated info fields and a message (these, separated by a semicolon).

//
//                  INFO                      MSG
//     .------------------------------------------. .------.
//    |                                            |        |
//    | int int      int      char, <ignore>   | string |
//    prefix,   seq, timestamp_us,flag[,..........];<message>
//

There are four standard fields in the info section, leaving room for other fields in the future.

From the priority field, we can extract two pieces of information: priority and facility.

// DecodePrefix extracts both priority and facility from a given
// syslog(2) encoded prefix.
//
//     facility    priority
//      .-----------.  .-----.
//      |           |  |     |
//  7  6  5  4  3  2  1  0    bits

With the rest of the fields, we’re able to know when the message was produced and what ID does such message carry in the sequence of messages that have been put in the buffer.

If you’re interested in seeing this parsing in the form of actual code, I wrote a Golang implementation that you can check here: github.com/cirocosta/dmesg_exporter/kmsg/kmsg.go.

Closing thoughts

It was great to have the opportunity of going deep into the stack and verifying how components from the kernel can communicate with userspace applications.

That led me to create dmesg_exporter, a tool for exporting “dmesg” logs metrics so that people can eventually alert messages marked as “critical” arriving from a specific facility.

During the writing of this blog post, I made use of the following book: The Linux Programming Interface. Please make sure you check it out! It’s definitely one of the best books on Linux out there.

If you’ve had any questions, or have ideas for improvements, please let me know! I’m cirowrc on Twitter, and I’d love to hear from you!

Have a good one!