Chameth.com - posts like android-espresso-spoon, debugging-beyond-the-debugger, shoring-up-sshd, understanding-docker-volume-mounts, why-you-should-be-using-https

The Case of the Unchanging Config

2026-04-09T00:00:00Z

Last week I was attempting to make it so I could share pictures on IRC directly from my client. This sounds simple, but it involves a bouncer¹ that proxies the request to a standalone image hosting service that I had to modify to be compatible. At one point my testing loop was:

Make a change to the hosting service
Commit it
Tag a new release
Wait for it to build
Update the version I’m running on my server
Reconfigure the bouncer to pass the new parameter or change the URL or whatever
Try uploading a photo from my phone
Realise I’ve overlooked something and go back to step one

I could have set up a local copy of everything and tested it sensibly. I should have set up a local copy of everything and tested it sensibly. But it seemed like such a trivial change, and setting up the whole environment seemed like such a pain. After the third or so iteration of failure I was pretty annoyed with myself, computers, and basically everything.

My biggest annoyance was that my bouncer would not pick up the new URL from the config when I changed it. It’s meant to reload the config when it receives a SIGHUP, and it claimed to in the logs, but I could clearly see it was still hitting the old URL. Restarting the bouncer to update the config is a pain, as it disconnects me from all the IRC networks, and has to reconnect to them all, reauthenticate, etc. It also mildly spams everyone who shares a channel with me².

When I finally got everything working I had a look at the bouncer source, and thought I’d spotted the issue. I raised a bug report, ending in this remark:

It looks like the config is reloaded properly, but the handler for uploads is created once at startup and has its own copy of the uploader, so effectively snapshots the config to whatever it is at startup:

fileUploadHandler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
    cfg := srv.Config()
    h := fileupload.Handler{
        Uploader:    cfg.FileUploader,
        DB:          db,
        Auth:        cfg.Auth,
        HTTPOrigins: cfg.HTTPOrigins,
    }
    h.ServeHTTP(w, r)
})

I’m not quite sure what I thought I saw there, but that’s not right. I want to call it a hallucination, but that feels like a very overloaded word these days. I guess I was just seeing what I wanted to see, and that was a good excuse to stop investigating. Still, even if I misidentified the cause, the bug was still present, right? … Right?

The Science of Deduction

When the developer got back and said he couldn’t reproduce my issue, I went back to my install and immediately reproduced it. With a calmer head, I figured it was probably something with my particular set up. First thing to check: am I actually running the version I think I am?

Unfortunately the bouncer doesn’t actually seem to expose the version anywhere that I can see. It’s not in the logs, it doesn’t have a -version flag, and none of the IRC-based status commands seem to include it. But I know it’s a Go app, and I know Go embeds the version information. go version -m <binary> will dump it all out, but the binary is inside a Docker image, and the Docker image is one of my nice, minimal, artisanal ones so doesn’t ship a go binary. No problem, docker compose cp bouncer:/bnc ./bnc yoinks the binary out of the container, and then dumping the version shows that, yes, I am running the version I thought I was. Hmm.

The next tool I reached for in my toolbox was strace. Maybe it’s not actually reading the file for some reason? I immediately executed strace -p <pid> -e trace=openat,open,read,pread64 -f without having to look any part of that up. Yep. Definitely. Then I edited the config, HUP’d the bouncer, and saw that it was… reading the config file. As it’s meant to. By default strace truncates strings to 32 bytes, so I couldn’t actually see the line I’d changed. Some more definitely-not-RTFMing later, and rerunning it with an extra -s 65536 let me see the full config. Surprise! The config hadn’t changed!

To confirm my findings, I used docker compose cp again, this time yoinking the config file from inside the container. The inside config file was definitely different to the outside config file. What? My hypothesis at this point was “something something Docker nonsense”. I mount the config as read-only, and was wondering if that meant that Docker was doing something weird instead of just bind mounting it. A quick trip to /proc/<pid>/mounts showed that it was, in fact, not doing anything weird, and was just bind mounting it.

If the file is bind mounted, then surely it’s the same file? I ran stat on the file on the host, noted the inode number, then pondered how to actually run stat on the file inside the container, given the aforementioned awkwardly minimal image. The solution was easy: access it via /proc/<pid>/root/. I could’ve saved myself a bunch of docker compose cp if I’d thought about that earlier. Oh well. The inode of that file was different. What?

The answer was DNS. It’s always DNS. Oh, sorry, force of habit. I meant the answer was vim. I was editing the config in vim, and when it saves files, by default, it writes the new content to a temporary file and does an atomic rename. That’s normally a good thing: it prevents corruption if the write fails midway through³. In this case, though, that means the new file has a new inode. Bind mounting a file binds to the inode, so the container just keeps clutching onto the original config from when it was started, blissfully unaware that the party has relocated down the street.

This problem is likely to happen whenever you bind mount a file into a container. When I mentioned this to a friend, he immediately responded “oh yeah, never do that”, and went on to describe the horrible hacks he’s had to add to Ansible to sidestep the issue. The nicer solution is to just bind mount an entire directory if you can, as then it doesn’t matter what happens to the files within it. I really like having the config files sat alongside the Docker compose files, though; having to create a directory just to work around some bind mount weirdness upsets me.

Now I knew what the problem was, I found there was an issue raised against Docker twelve years ago⁴. The first response was “that’s expected”, and I fully agree with the author: “respectfully, that might be expected by you, but it was not expected by me”!⁵ As a result of the issue they added a nice note to the docs:

Note: Many tools used to edit files including vi and sed --in-place may result in an inode change. Since Docker v1.1.0, this will produce an error such as “sed: cannot rename ./sedKdJ9Dy: Device or resource busy”. In the case where you want to edit the mounted file, it is often easiest to instead mount the parent directory.

But in the intervening twelve years, both the note and the functionality described have gone missing. Ho-hum.

I found it interesting how I’ve only just hit this problem, given how long I’ve used Docker. But I realised that almost everything I run I’m happy to just restart. Cattle, not pets, and so on. My IRC bouncer is one of the few exceptions to that. The only other thing I regularly hot reloaded was Centauri, my reverse proxy, but that had a whole config directory mounted because it was shared between containers, so nicely sidestepped the foot-gun.

So lesson learnt: check for weird bind mount issues before raising issues about config hot reloading. It’ll join the esteemed company of “maybe the drive is full and causing completely unrelated problems?”, “perhaps everything is dog slow because the kernel ran out of entropy?”, and “did systemd sneakily take over that functionality while you weren’t looking?” in the troubleshooting checklist.

An IRC bouncer is basically an always-on proxy. It connects to the IRC networks for you, then your clients connect to your bouncer. The bouncer can then send incoming messages to all your different clients, cache them when you’re offline and replay them later, and lots of other nice things people take for granted in their chat apps these days. ↩︎
Join/part/quit spam is part of IRC, and clients have ways of handling it, but I still feel bad about doing it excessively. ↩︎
You can disable this in vim by setting backupcopy=yes. Good luck redoing all the debugging if you ever accidentally remove that from your vimrc, though! ↩︎
Which is weird, because Docker can’t possibly be that old. That would make me much older than I’m prepared to accept. ↩︎
If you read the thread they didn’t actually mean to sound so dismissive, but it’s still pretty funny. “Yes, it’s expected that the foot-gun causes your foot to hurt. Duh. What did you expect?” ↩︎

Debugging beyond the debugger

2019-05-08T00:00:00Z

Real-life debugging tools

Most programming — and sysadmin — problems can be debugged in a fairly straight forward manner using logs, print statements, educated guesses, or an actual debugger. Sometimes, though, the problem is more elusive. There’s a wider box of tricks that can be employed in these cases but I’ve not managed to find a nice overview of them, so here’s mine. I’m mainly focusing on Linux and similar systems, but there tend to be alternatives available for other Operating Systems or VMs if you seek them out.

Networking

tcpdump

tcpdump prints out descriptions of packets on a network interface. You can apply filters to limit which packets are displayed, chose to dump the entire content of the packet, and so forth.

Typical usage might look something like:

# tcpdump -nSi eth0 port 80
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 262144 bytes
16:03:35.577781 IP6 2001:db8::1.54742 > 2001:db8::2.80: Flags [S], seq 2815779044, win 64800, options [mss 1440,sackOK,TS val 2378811665 ecr 0,nop,wscale 7], length 0
16:03:35.586853 IP6 2001:db8::2.80 > 2001:db8::1.54742: Flags [S.], seq 1522609102, ack 2815779045, win 28560, options [mss 1440,sackOK,TS val 3063610173 ecr 2378811665,nop,wscale 7], length 0
16:03:35.586877 IP6 2001:db8::1.54742 > 2001:db8::2.80: Flags [.], ack 1522609103, win 507, options [nop,nop,TS val 2378811674 ecr 3063610173], length 0
16:03:35.620678 IP6 2001:db8::1.54742 > 2001:db8::2.80: Flags [P.], seq 2815779045:2815779399, ack 1522609103, win 507, options [nop,nop,TS val 2378811708 ecr 3063610173], length 354: HTTP: GET / HTTP/1.1

Here you can see the start of a plaintext HTTP request: the three-way handshake as the TCP connection is established followed by a GET request. Even if the data is encrypted as it will be in most cases, it’s often useful to see the “shape” of the transmissions: did the client start sending data when it connected, did the server ever respond, etc.

Daniel Miessler has a good tutorial on tcpdump if you’re not familiar with it and don’t want to jump straight into the man page.

… with Docker

Docker sets up separate network namespaces for each container. To see the traffic across the interfaces of a single container you can nsenter the container’s network namespace:

# nsenter -t $(docker inspect --format '{{.State.Pid}}' my_container) -n tcpdump -nS port 80

This retrieves the PID for the container, and tells nsenter to enter the network (-n) namespace from the given target (-t) PID, and then run the given command (in this case tcpdump ...).

openssl s_client / s_server

When a connection is using TLS it’s often useful to try connecting to the server and see what certificate it presents, algorithms it negotiates, and so forth. OpenSSL offers two useful subcommands which can help with this: s_client for connecting as a client, and s_server for listening to connections.

For example, using s_client to connect to google.com on the standard HTTPS port shows us details about the server cert and its verification status:

$ openssl s_client -connect google.com:443
CONNECTED(00000003)
depth=2 OU = GlobalSign Root CA - R2, O = GlobalSign, CN = GlobalSign
verify return:1
depth=1 C = US, O = Google Trust Services, CN = Google Internet Authority G3
verify return:1
depth=0 C = US, ST = California, L = Mountain View, O = Google LLC, CN = *.google.com
verify return:1
---
Certificate chain
 0 s:C = US, ST = California, L = Mountain View, O = Google LLC, CN = *.google.com
   i:C = US, O = Google Trust Services, CN = Google Internet Authority G3
 1 s:C = US, O = Google Trust Services, CN = Google Internet Authority G3
   i:OU = GlobalSign Root CA - R2, O = GlobalSign, CN = GlobalSign
---
# ...

Whereas connecting to my webserver and providing an unknown host in the SNI field results in an SSL alert 112 (“The server name sent was not recognized”) and no server certificate is sent:

$ openssl s_client -connect chameth.com:443 -servername example.com
CONNECTED(00000003)
140384831313024:error:14094458:SSL routines:ssl3_read_bytes:tlsv1 unrecognized name:../ssl/record/rec_layer_s3.c:1536:SSL alert number 112
---
no peer certificate available
---
# ...

Often if you hit this kind of alert in an application the exact error will be lost somewhere in the many layers between the SSL library and the logs, so being able to directly connect and test can help diagnose a lot of issues.

Once a connection is established you can read and write plain text and it will be encrypted and decrypted automatically.

Java apps

If a Java app is involved in the connection, you can enable a lot of built-in debugging with a simple JVM property: javax.net.debug. You can tweak what exactly gets logged, but the easiest thing to do is just set the property to all and you’ll see information about certificate chains, verification, and packet dumps:

$ java -Djavax.net.debug=all -jar ....
# ...
found key for : duke
chain [0] = [
[
  Version: V1
  Subject: CN=Duke, OU=Java Software, O="Sun Microsystems, Inc.",
  L=Cupertino, ST=CA, C=US
# ...

More information about Java’s debugging options is available on docs.oracle.com.

Thread and core dumps

Higher-level languages frequently provide an interactive way to dump the current execution state of all of their threads (a “thread dump”). This is useful to spot deadlocks, some types of race conditions, and as a quick and dirty method of investigating hangs or excessive CPU usage.

With both Java and Go applications you can send a QUIT signal to have a thread dump printed out; Go applications will quit after doing so, Java ones will carry on running. At most terminals you can hit Ctrl and \ to send a QUIT signal.

For Java you can also use the jstack tool from the JDK to dump threads by PID; this can be useful if the application is running in the background or has redirected sysout:

$ jstack 8321
Attaching to process ID 8321, please wait...
Debugger attached successfully.
Client compiler detected.

Thread t@5: (state = BLOCKED)
 - java.lang.Object.wait(long) @bci=-1107318896 (Interpreted frame)
 - java.lang.Object.wait(long) @bci=0 (Interpreted frame)
 - java.lang.ref.ReferenceQueue.remove(long) @bci=44, line=116 (Interpreted frame)
 - java.lang.ref.ReferenceQueue.remove() @bci=2, line=132 (Interpreted frame)
 - java.lang.ref.Finalizer$FinalizerThread.run() @bci=3, line=159 (Interpreted frame)

# ...

A core dump provides more complete information about the state of a process, but is often more complex to interpret. The gcore utility from GDB will create a core dump of a process with a given PID. You can then generally load the core file using your normal debugger, depending on the language in question.

System calls

strace is the swiss army knife for seeing what a process is doing. It details each system call made by a program (you can filter them down, of course). For example:

$ strace -e read curl https://google.com/
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 \236\0\0\0\0\0\0"..., 832) = 832
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P!\0\0\0\0\0\0"..., 832) = 832
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\200l\2\0\0\0\0\0"..., 832) = 832
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\20Q\0\0\0\0\0\0"..., 832) = 832
# ...
read(3, "\0\0\0\0\0\0\0\4\25\345\366\302\273sE6\365wI\225\321|\3435Z\362\216\372\215\251aO"..., 253) = 253
<HTML><HEAD><meta http-equiv="content-type" content="text/html;charset=utf-8">
<TITLE>301 Moved</TITLE></HEAD><BODY>
<H1>301 Moved</H1>
The document has moved
<A HREF="https://www.google.com/">here</A>.
</BODY></HTML>
read(3, "\27\3\3\0!", 5)                = 5
# ...

Brendan Gregg has a nice guide on strace and alternatives.

… with docker

When the application is running in docker you can usually just strace it from the host with the correct PID (from e.g. docker inspect --format '{{.State.Pid}}' my_container). Sometimes you may need to trace the startup of an application though, which is a bit trickier. Instead you can run a new container using the same PID namespace as your target, and the permissions needed to strace:

$ docker run --rm -it --pid=container:my_container \
  --net=container:my_container \
  --cap-add sys_admin \
  --cap-add sys_ptrace \
  alpine

From within the new container you can install strace, and trace any running program within the target container using strace -p as normal. To start a new program you need access to the target container’s filesystem, which you can get to via /proc/1/root (PID 1 being the main process that docker started in the target container).

Files

Sometimes the problem might relate to file access. There are a couple of straight forward — but nonetheless useful — tools which might help here. inotifywait uses the Linux inotify subsystem to watch files or directories for operations. For example:

$ inotifywait -mr site/content
Setting up watches.  Beware: since -r was given, this may take a while!
Watches established.
site/content/post/ MODIFY 2019-05-08-debugging-beyond-the-debugger.md
site/content/post/ OPEN 2019-05-08-debugging-beyond-the-debugger.md
site/content/post/ MODIFY 2019-05-08-debugging-beyond-the-debugger.md
site/content/post/ MODIFY 2019-05-08-debugging-beyond-the-debugger.md
site/content/post/ CLOSE_WRITE,CLOSE 2019-05-08-debugging-beyond-the-debugger.md
# ...

Here the -m switch makes inotifywait monitor the files forever (instead of exiting on the first modification, which is the normal behaviour) and r makes it recurse into the directory and monitor each file and subdirectory in there.

If you want to see what processes currently have a file open, fuser is the go-to tool. For example:

$ fuser -v /
                     USER PID ACCESS COMMAND
/:                   root     kernel mount /
                     chris      2961 .rc.. systemd
                     chris      2986 .r... gdm-x-session
                     chris      2994 .r... dbus-daemon
                     chris      3001 .r... gnome-session-b
# ...

Honourable mentions

These aren’t really debugging tools, but I feel it’s worth mentioning as they often feature somewhere along the debugging-of-weird-problems journey.

I’ve seen some weird and wonderful problems happen because a disk is full, so a quick df early on in the debugging process never hurts. Some apps may hang, some may corrupt their config, some may fall over and die; sometimes the manner in which they fail doesn’t obviously point to a disk space issue.

Another issue that comes up now and then — especially inside VMs or other environment that don’t have a decent amount of “noise” happening — is entropy exhaustion. A quick look at /proc/sys/kernel/random/entropy_avail should be enough to confirm that everything is ticking along nicely. If it’s exceedingly low then you may find that anything involving random number generation stalls (TLS connections for example).

Understanding Docker volume mounts

2019-04-01T00:00:00Z

The Docker project logo

One thing that always confuses me with Docker is how exactly mounting volumes behaves. At a basic level it’s fairly straight forward: you declare a volume in a Dockerfile, and then either explicitly mount something there or docker automatically creates an anonymous volume for you. Done. But it turns out there’s quite a few edge cases…

Changing ownership of the folder

Perhaps the most common operation done on a Docker volume other than simply mounting it is trying to change the ownership of the directory. If your Docker process runs as a certain user you probably want the directory to be writable by that user.

At first we might try something like:

FROM alpine
RUN adduser -D -u 1113 test123
USER test123
VOLUME /testing

But changing the user doesn’t seem to have any effect on the volume. Why? Checking the docs for the USER instruction shows that only affects certain future operations — namely RUN, CMD, and ENTRYPOINT. It doesn’t affect the VOLUME instruction; if it did, you’d probably just get a permission denied error unless the user you switch to had privileges to create mount points.

OK, so instead we might try using the good old chown command:

FROM alpine
RUN adduser -D -u 1113 test123
VOLUME /testing
RUN chown test123 /testing

But again, the directory is just owned by root at runtime. Back to the docs, this time for the VOLUME instruction and towards the bottom is this little tidbit:

Changing the volume from within the Dockerfile: If any build steps change the data within the volume after it has been declared, those changes will be discarded.

As soon as Docker hits the VOLUME instruction the directory becomes a mount point, and anything we do to the temporary volume mounted there is discarded during the build process. So we have to change the ownership before the instruction, which may seem a little counter-intuitive:

FROM alpine
RUN adduser -D -u 1113 test123
RUN mkdir /testing && chown test123 /testing
VOLUME /testing

Now when the container runs, the /testing directory is owned by the test123 user. It’s not quite over, yet, though. This works if we let Docker create a volume automatically for us, or if we create a named volume and mount that; if we try and mount a host directory, though, it falls flat:

$ docker run --rm -it -v "$PWD/testing:/testing" testing ls -al /testing
total 8
drwxr-xr-x    2 1000     1000          4096 Apr  1 19:39 .
drwxr-xr-x    1 root     root          4096 Apr  1 20:44 ..

Docker handles mounting host directories differently to mounting volumes, even though the syntax is basically the same. Host directories are bind mounted directly into the container, so the permissions and ownership are the same as the directory on your host. The only way to fix them are to either change the permissions on the host, or have the container change them at runtime (assuming it has sufficient privileges).

One final wrinkle in all this happens when you use the same volume in multiple containers. Here we have two images built from the Dockerfile above, one with userid 1113 and one with userid 1114:

$ docker volume create testing
testing

$ docker run --rm -it -v testing:/testing testing1113 ls -nal /testing
total 8
drwxr-xr-x    2 1113     0             4096 Apr  1 19:49 .
drwxr-xr-x    1 0        0             4096 Apr  1 20:51 ..

$ docker run --rm -it -v testing:/testing testing1114 ls -nal /testing
total 8
drwxr-xr-x    2 1114     0             4096 Apr  1 20:47 .
drwxr-xr-x    1 0        0             4096 Apr  1 20:52 ..

$ docker run --rm -it -v testing:/testing testing1114 touch /testing/Hello

$ docker run --rm -it -v testing:/testing testing1113 ls -nal /testing
total 8
drwxr-xr-x    2 1114     0             4096 Apr  1 20:52 .
drwxr-xr-x    1 0        0             4096 Apr  1 20:53 ..
-rw-r--r--    1 0        0                0 Apr  1 20:52 Hello

$ docker run --rm -it -v testing:/testing testing1114 ls -nal /testing
total 8
drwxr-xr-x    2 1114     0             4096 Apr  1 20:52 .
drwxr-xr-x    1 0        0             4096 Apr  1 20:52 ..
-rw-r--r--    1 0        0                0 Apr  1 20:52 Hello

Can you see what’s going on? When the volume is empty, the ownership changes based on the mount point in the container. Once it has something in it, the ownership is fixed.

So Docker behaves differently with regard to permissions:

when the folder is mounted from the host vs a volume
when the volume is empty vs having content

Pre-populating mounts with files from the image

One of the more esoteric features of the way Docker handles volume mounts is that in some cases files from the image are copied over into the container. For example:

$ docker volume create testing
testing

$ docker run --rm -it -v testing:/etc testing sleep 1

$ docker run --rm -it -v testing:/tmp testing ls -al /tmp
total 184
drwxr-xr-x   15 root     root          4096 Apr  1 20:58 .
drwxr-xr-x    1 root     root          4096 Apr  1 20:59 ..
-rw-r--r--    1 root     root             4 Jun  7  2018 TZ
-rw-r--r--    1 root     root             6 Dec 20 21:31 alpine-release
...

The first container we run mounts the newly created testing volume at /etc. Docker copies all the existing files and folders into the volume; when we then run the second container with the volume mounted at /tmp, we can see all the files that were in the first container’s /etc.

As with permissions, this behaviour is anything but consistent. Say we switch from a volume to a host directory:

$ mkdir testing
$ docker run --rm -it -v "$PWD/testing:/usr/bin" testing sleep 1
$ ls -al testing
total 8
drwxr-xr-x 2 root  root  4096 Apr  1 22:05 .
drwxr-xr-x 3 chris chris 4096 Apr  1 22:05 ..

Nothing is copied in, and inside the container the folder will be empty. Based on our discoveries with permissions, it’s reasonable to assume the same will happen with a non-empty volume too:

$ docker volume create testing
testing

$ docker run --rm -it -v testing:/testing testing touch /testing/Hello

$ docker run --rm -it -v testing:/usr/bin testing sleep 1

$ docker run --rm -it -v testing:/tmp testing ls -al /tmp
total 8
drwxr-xr-x    2 root     root          4096 Apr  1 21:09 .
drwxr-xr-x    1 root     root          4096 Apr  1 21:09 ..
-rw-r--r--    1 root     root             0 Apr  1 21:08 Hello

So at least that’s consistent. If you’re very observant, though, you might notice I switched from /etc/ to /usr/bin in the examples. That’s because within the container /etc/ has some files bind-mounted into it, such as /etc/resolv.conf, and these do always result in files being created in the mounted volumes or folders:

$ mkdir testing
$ docker run --rm -it -v "$PWD/testing:/etc" testing sleep 1
$ ls -al testing
total 8
drwxr-xr-x 2 chris chris 4096 Apr  1 22:12 .
drwxr-xr-x 3 chris chris 4096 Apr  1 22:12 ..
-rwxr-xr-x 1 root  root     0 Apr  1 22:12 hostname
-rwxr-xr-x 1 root  root     0 Apr  1 22:12 hosts
-rwxr-xr-x 1 root  root     0 Apr  1 22:12 resolv.conf

Summary

Docker treats mounting host folders and mounting volumes differently. Don’t just assume that you can swap one for another and get the exact same behaviour.
Empty volumes will inherit permissions and files from the image they are mounted in; non-empty volumes and host folders will not.
Relying on Docker copying files into volumes is a very bad idea, as if you change those files in a future version of your image they will not be copied unless the volume is deleted and recreated.

I can’t find anywhere that these points are documented properly; if you know of anywhere, please drop me a message!

Android testing with Espresso and Spoon

2017-05-16T00:00:00Z

I’ve been spending some time recently setting up automated testing for our collection of Android apps and libraries at work. We have a mixture of unit tests, integration tests, and UI tests for most projects, and getting them all to run reliably and automatically has posed some interesting challenges.

Running tests on multiple devices using Spoon

Spoon is a tool developed by Square that handles distributing instrumentation tests to multiple connected devices, aggregating the results, and making reports.

As part of our continuous integration we build both application and test APKs, and these are pushed to the build server as build artefacts. A separate build job then pulls these artefacts down to a Mac Mini we have in the office, and executes Spoon with a few arguments:

java -jar spoon-runner.jar \
    --apk application.apk \
    --test-apk applicationTests.apk \
    --fail-on-failure \
    --fail-if-no-device-connected

Spoon finds all devices, deploys both APKs on them, and then begins the instrumentation tests. We use two physical devices and an emulator to cover the form factors and API versions that are important to us; if any test fails on any of those devices, Spoon will return an error code and the build will fail.

For library projects, you only have a single APK containing both the tests and the library itself. The current version of Spoon requires both --apk and --test-apk to be specified, so we simply pass in the same APK to both. It looks like future versions of Spoon will be more flexible in this regard.

Spoon produces HTML reports, showing the status of each test run on each device. We have the report output folder collected as a build artefact, so the reports can be seen right from the build server:

Spoon output summary, showing results of 171 tests run on 3 devices

Flake-free UI testing with Espresso

Espresso is an Android library that provides an API for interacting with and making assertions about the UI of Android applications. Espresso has a very simple interface, and does lots of clever things under the hood to ensure that your tests only execute code when the UI is idle (and hence stable). You shouldn’t ever need to make your code sleep or wait.

In order for Espresso’s magic to work, it needs to know whenever some background activity is going on that it needs to wait for. By default, it hooks in to Android’s AsyncTask executor so it can wait for those to finish. In our apps, there were a few cases where we used an explicit Thread to do some background work, which caused tests to fail intermittently (depending on whether the thread performed its UI update before or after Espresso executed the test code). Rewriting these cases to use an AsyncTask enabled Espresso to figure out what was happening and the tests started passing reliably.

Another, similar, problem occurred where we were using RxJava to load some data. There are two possible ways to deal with this… Espresso has a concept of an idling resource, which provides a way of telling Espresso when a resource is busy so it can belay interacting with or testing the UI until the resource is finished. In our case, the code in question was going to be rewritten soon, so we went for a quicker and dirtier option: force RxJava to use the same executor as AsyncTask.

To do this, we added a simple test utility class that registers an RxJavaPlugin that overrides the Schedulers used by Rx:

/**
 * Hooks in to the RxJava plugins API to force Rx work to be scheduled on the
 * AsyncTask's thread pool executor. This is a quick and dirty hack to make
 * Espresso aware of when Rx is doing work (and wait for it).
 */
public final class RxSchedulerHook {

    private static final RxJavaSchedulersHook javaHook =
            new RxJavaTestSchedulerHook();

    private RxSchedulerHook() {
        // Should not be insantiated
    }

    public static void registerHooksForTesting() {
        if (RxJavaPlugins.getInstance().getSchedulersHook() != javaHook) {
            RxJavaPlugins.getInstance().reset();
            RxJavaPlugins.getInstance().registerSchedulersHook(javaHook);
        }
    }

    private static class RxJavaTestSchedulerHook extends RxJavaSchedulersHook {
        @Override
        public Scheduler getComputationScheduler() {
            return Schedulers.from(AsyncTask.THREAD_POOL_EXECUTOR);
        }

        @Override
        public Scheduler getIOScheduler() {
            return Schedulers.from(AsyncTask.THREAD_POOL_EXECUTOR);
        }

        @Override
        public Scheduler getNewThreadScheduler() {
            return Schedulers.from(AsyncTask.THREAD_POOL_EXECUTOR);
        }
    }
}

With the hook registered Rx does all of its work on the same thread pool as AsyncTask, which Espresso already knows about. It’s not the best long-term solution, but it means we don’t have to spend time integrating IdlingResource for code that doesn’t have long to live. With the hook in place, the tests that were flaking because of Rx started passing reliably as well.

Getting automatic screenshots of failures

Spoon provides a client library to, among other things, take a screenshot of the device. Espresso provides a hook that can be used to change how errors are handled. Putting the two together is very simple:

final FailureHandler defaultHandler =
        new DefaultFailureHandler(
                InstrumentationRegistry.getTargetContext());

Espresso.setFailureHandler(new FailureHandler() {
    @Override
    public void handle(Throwable throwable, Matcher<View> matcher) {
        try {
            Spoon.screenshot(
                    getActivity(),
                    "espresso-failure",
                    description.getClassName(),
                    description.getMethodName());
        } catch (Exception ex) {
            Log.e(TAG, "Error capturing screenshot", ex);
        }
        defaultHandler.handle(throwable, matcher);
    }
});

In our new error handler we simply ask Spoon to take a screenshot, then call Espresso’s original handler so that it can output its debugging information and fail the test. The Spoon runner automatically picks up the screenshot and adds it to the report:

Spoon output details, showing a screenshot captured of the failure

Having the screenshot, error message and logs all presented in a clean UI makes debugging failures much, much easier than searching through a huge build log to try and find the exception.

Filtering tests based on device capabilities

Some tests won’t work on every device you throw at them. We had two problems: some tests require a higher API version than some of our devices, and some of the UIs under test were designed to run only on certain resolutions.

The main cause for our dependence on newer API versions was the use of WireMock, a brilliant library for stubbing out web services. WireMock requires API 19, while our physical devices tend to run versions older than that. Stopping these tests running is simply a case of applying an annotation to the class:

@SdkSuppress(minSdkVersion=19)

Screen resolution is a bit more complicated. One of our apps is designed for a specific tablet device (and will never be used on anything else), and trying to render the UI on smaller screens results in items overlapping, important parts ending up below the fold, and other problems.

We’d still like all the other tests for that app to run on all of the devices, though, so we can test them on a variety of API versions and in other conditions. We just need to suppress the UI tests. To do this, we subclassed the Android ActivityTestRule and overrode the apply method:

@Override
public Statement apply(Statement base, final Description description) {
    if (!canRunUiTests(InstrumentationRegistry.getContext())) {
        // If we can't run UI tests, then return a statement that does nothing
        // at all.  With normal JUnit tests we'd just throw an assumption
        // failure and the test would be ignored, but that makes the Android
        // runner angry.
        return new Statement() {
            @Override
            public void evaluate() throws Throwable {
                // Do nothing
            }
        };
    }

    return super.apply(base, description);
}

/**
 * Checks that the screen size is close enough to that of our tablet device.
 */
@TargetApi(Build.VERSION_CODES.HONEYCOMB_MR2)
private boolean canRunUiTests(Context context) {
    if (Build.VERSION.SDK_INT < Build.VERSION_CODES.HONEYCOMB_MR2) {
        return false;
    }
    int screenWidth = dpToPx(context,
            context.getResources().getConfiguration().screenWidthDp);
    return screenWidth >= 600;
}

private int dpToPx(Context context, int dp) {
    DisplayMetrics displayMetrics = context.getResources().getDisplayMetrics();
    return Math.round(dp * displayMetrics.density);
}

When the rule is run, we check if the screen width meets a minimum number of pixels. If it doesn’t, an empty Statement is returned that turns the test into a no-op. These show up as passed rather than skipped in the output, but there doesn’t seem to be a nice way to signal to the Android JUnit runner that the test is being ignored programatically.

Shoring up SSHd configuration

2016-10-18T00:00:00Z

I recently came across a useful tool on GitHub called ssh-audit. It’s a small Python script that connects to an SSH server, gathers a bunch of information, and then highlights any problems it has detected. The problems it reports range from potentially weak algorithms right up to know remote code execution vulnerabilities.

This is the kind of output you get when running ssh-audit. In this particular example, I’m looking at GitHub’s SSH server and have filtered the output to just warnings and failures:

Output of ssh-audit pointing at GitHub’s SSH servers

GitHub’s a bit of a special case, as they’re trying to cope with scores of developers pushing code: they can’t disable weaker algorithms without also stopping lots of people being able to use their service. Still, from the output you can see that ssh-audit has spotted a known vulnerability (CVE-2016-076) and has a lot to say about the various types of supported algorithms.

Background: crypto algorithms used by SSH

Establishing an SSH connection is a moderately complex endeavour, and various parts involve the use of a number of different cryptographic algorithms:

The first such algorithm is the key exchange algorithm. This is the process by which the client and the server agree on a shared key that will be used later. Next comes the host-key algorithm; this is how the server proves its identity to the client. Most SSH users will be familiar with warnings like the following:

$ ssh server.example.com
The authenticity of host 'server.example.com (11.22.33.444)' can't be established.
ED25519 key fingerprint is SHA256:rPVMho1fhEkJqvgce/8iAl353dX5QkGT9F3uCFndsa.
Are you sure you want to continue connecting (yes/no)?

The warning means that the SSH client doesn’t recognise the server’s key, and is asking the user to confirm it. If the key changes later, the SSH client will refuse to connect. In the warning above you can see the algorithm used by the server was ED25519.

Next up is the encryption algorithm, which handles actually encrypting the data sent over the connection. Finally comes the message authentication code algorithm, commonly referred to as ‘mac’. The mac algorithm is effectively responsible for signing each message as a proof that it came from the other party.

Following the recommendations

ssh-audit’s recommendations are pretty easy to follow. It points and shouts at a particular algorithm, and you configure SSHd to not allow it. This is a snippet from my new SSHd config, which gets no complaints from ssh-audit:

HostKey /etc/ssh/ssh_host_rsa_key
HostKey /etc/ssh/ssh_host_ed25519_key

KexAlgorithms curve25519-sha256@libssh.org
Ciphers chacha20-poly1305@openssh.com,aes256-gcm@openssh.com,aes128-gcm@openssh.com,aes256-ctr,aes192-ctr,aes128-ctr
MACs hmac-sha2-512-etm@openssh.com,hmac-sha2-256-etm@openssh.com,umac-128-etm@openssh.com

What’s more interesting is the reasoning behind some of the algorithms removed. The ecdh-sha2-nistp series of key exchange algorithms are subject to a sidechannel attack described in a paper in 2014. Some people are also concerned about the involvement of NIST, and the potential for backdoors. Various other key exchange algorithms use too small a number of bits in the key exchange (e.g. diffie-hellman-group1-sha1, which uses 1024). Others still use known-bad hash algorithms (e.g. diffie-hellman-group14-sha1, which uses an acceptable 2048 bit modulus, but relies on SHA1 hashes). ssh-audit only treats the use of SHA1 as a warning, but there’s no compelling reason to keep it around if you’re using remotely modern clients to connect. Similarly the host-key DSA algorithm uses a 1024 bit key, so should be disabled.

Many of the rejected encryption algorithms use basically-broken algorithms (3des-cbc and arcfour for example). Some of the remaining are block ciphers with small block sizes, which makes them weak (e.g. blockfish-cbc uses a block size of 64 bits).

Many of these concerns also apply to mac algorithms (e.g. eliminating hmac-md5, hmac-sha1-etm@openssh.com, etc, as they use weak hash algos). Of particular note, OpenSSH supports the hmac-ripemd160 and hmac-ripemd160-etm@openssh.com algorithms. RIPEMD160 isn’t that common but, like SHA1, is considered to be weak. One other concern with mac algorithms is the order in which the encryption and mac attachment are performed. Encrypt-then-mac is the preferred way of doing it (i.e., the message is encrypted, then a MAC of the ciphertext is attached). The default used in SSH is encrypt-and-mac, where the mac of the plaintext is attached after encryption. Attaching the plaintext mac potentially leaks information (a mac is designed to provide integrity, not confidentiality, after all). The encrypt-then-mac algorithms are indicated by the -etm suffix.

Other changes

In addition to the ssh-audit inspired changes, I took the time to review the rest of my standard SSH configuration. The config touches on a few areas; I’m only going to highlight a couple of them:

  PubkeyAuthentication yes
  RhostsRSAAuthentication no
  HostbasedAuthentication no
  ChallengeResponseAuthentication no
  PasswordAuthentication no

Here all authentication methods other than public key are disabled. A decent key (used in combination with good crypto algorithms!) is drastically harder to brute force than a very good password. It’s also less prone to accidentally being copied into the wrong place, provided to the wrong server, etc.

- UsePrivilegeSeparation yes
+ UsePrivilegeSeparation sandbox

Switching UsePrivilegeSeparation from ‘yes’ to ‘sandbox’ tells OpenSSH to employ kernel sandbox mechanisms on the unprivileged process. This adds another layer of defence in case there’s a severe exploit in OpenSSH itself.

An unexpected side effect

After reconfiguring OpenSSH, all of my servers stopped reporting SSH brute force attempts. Every day prior to the change saw hundreds of connections and, after rate limiting and automatic banning blocked a fair chunk, about two dozen unsuccessful login attempts. With the new algorithm selections in place, there were still hundreds of connections, but no failed login attempts at all. A closer look at the logs showed this:

fatal: Unable to negotiate with 1.2.3.4 port 55025:
  no matching key exchange method found. Their offer:
    diffie-hellman-group14-sha1,
    diffie-hellman-group-exchange-sha1,
    diffie-hellman-group1-sha1

Apparently not a single one of the clients trying to bruteforce their way in supported the one key exchange algorithm I now allow. I guess at some point they’ll be updated with a modern crypto stack, but until then it’s going to be oddly peaceful…