Chameth.com - posts like break-everything-fuzz-testing, understanding-docker-volume-mounts but not android-espresso-spoon, debugging-beyond-the-debugger, docker-automatic-nginx-proxy, 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?” ↩︎

Finding an awkward bug with Claude Code

2025-06-30T00:00:00Z

The many times Claude thought it was right…

I recently encountered a bug in one of my projects that I couldn’t immediately figure out. It was an issue in Centauri, my reverse proxy. After its config was updated, I noticed¹ it stopped serving responses. Looking at the logs, I could see it was obtaining new certificates from Let’s Encrypt for a couple of domains, but I’d designed it so that wouldn’t block requests (or so I thought). After a few minutes of confusion, everything went back to working.

It felt like an issue with locking, but a quick glance didn’t show me anything obvious. I decided to throw the problem at Claude Code and see how it did. With some guidance² it managed to identify the cause, but it was a bit of a journey to get there. I’m going to share the prompts and responses, as it was an interesting process.

The initial prompt

I thought the issue might be quite obvious, and I’d just overlooked it. Centauri isn’t that complex a project, after all. So I gave Claude a fairly minimal prompt to set it off:

> Hello! Please examine this codebase. I have noticed an issue that when a
  certificate is being renewed, the application seems to not serve any other
  requests. I suspect there is a misplaced lock somewhere.
 
  Can you see what's happening? Think very hard.

Claude Code has special hardcoded triggers to engage “thinking” mode, which makes it take more time to think about alternatives. The keywords are: “think”, “think hard”, “think harder”, and “ultrathink”. I managed to not quite get the right incantation here, and only enabled the lowest level³.

I’ll omit all the responses where Claude is “thinking” (talking to itself), or decides to make todo lists then cross items off them then add different items, and so on. Its responses get fairly lengthy; I won’t judge you too harshly if you skim over them. Its first response was blessedly brief:

● I found the issue! Looking at the certificate manager code, I can see the
  problem:

… and then it went back to thinking and reading files, because it had neither found the issue nor could it see the problem. Ho-hum. Some time later it came back with:

● I found the issue! The problem is in certificate/manager.go:53-54:
  
  m.store.LockCertificate(subject, altNames)
  defer m.store.UnlockCertificate(subject, altNames)
  
  The GetCertificate method acquires a lock at the beginning and holds it for the
  entire duration of the certificate renewal process. This includes:
  
  1. Contacting the ACME server
  2. Solving DNS-01 challenges (can take minutes for DNS propagation)
  3. Obtaining the certificate
  4. Getting OCSP staple
  5. Saving to disk
  
  During this time, any other request trying to get the same certificate will be
  blocked. While the lock is per-certificate (not global), it still means that all
  requests for that specific domain are blocked during renewal.
  
  Let me check if there are other places where this might cause blocking:

And it then proceeded to do even more thinking, checking files, etc, until it concluded with:

● I found the root cause! The issue is actually worse than just a
  per-certificate lock. Here's what's happening:
  
  The main blocking issue is in proxy/manager.go:133-144:
   
  func (m *Manager) CheckCertificates() {
      m.lock.RLock()  // ← Acquires read lock on the entire manager
      for i := range m.routes {
          route := m.routes[i]
          // ...
          m.updateCert(route)  // ← This can take MINUTES for ACME renewal!
      }
      m.lock.RUnlock()  // ← Only released after ALL routes are processed
  }
   
  The blocking cascade:
   1. CheckCertificates holds a read lock on the entire proxy manager while
      renewing ALL certificates
   2. Certificate renewal via ACME can take several minutes per certificate
      (DNS propagation, etc.)
   3. Every incoming request calls routeFor (proxy/manager.go:122) which needs
      the same lock:
    func (m *Manager) routeFor(domain string) *Route {
        m.lock.RLock()  // ← BLOCKED until CheckCertificates completes!
        match := m.domains[strings.ToLower(domain)]
        m.lock.RUnlock()
        // ...
    }
  
  So when certificate renewal starts, ALL incoming requests are blocked because
  they can't even look up which route to use. This explains why the application
  doesn't serve any requests during renewal - they're all waiting for the
  manager's read lock.
  
  The issue is compounded by:
  - Certificate renewal happens every 12 hours automatically
  - It also happens when routes are updated (SIGHUP)
  - Each certificate renewal involves time-consuming ACME operations
  
  This is a critical performance bug where I/O operations (certificate renewal)
  are performed while holding a critical lock.

This doesn’t actually follow on from the earlier response, it’s completely flipped onto a different lock being the issue. Amusingly, it’s nearly right here, but it’s highlighting this code for completely the wrong reason.

The lock it’s talking about is a RWMutex, which is specifically designed to allow many read-locks. Everything it’s pointing out are read locks, so they cannot block one another as it described. The response Claude has given sounds very confident, seems appropriately technical, but is in fact complete rubbish. This is one of the big issue with all LLMs at the minute, and it makes me despair at the idea of people “vibe coding” things when they don’t know enough to push back against nonsense like this.

Course correction

I explained briefly to Claude how this basic concurrency primitive works, and it came right back with another solution:

> But that's a RW Mutex. You can hold many read locks concurrently.

● You're absolutely right! I apologize for the confusion. With a RWMutex,
  multiple readers can hold the lock concurrently. Let me trace through this
  more carefully.
  
● Task(Analyze updateCert method)
  ⎿ Done (8 tool uses · 20.0k tokens · 1m 11.9s)
  
● Excellent analysis! You're right about RWMutex allowing concurrent readers.
  The real issue is the race condition in the certificate store's lock
  management.

  Looking at certificate/store.go:82-91:

  func (j *JsonStore) lockFor(subjectName string, altNames []string) *sync.Mutex {
      key := strings.Join(append([]string{subjectName}, altNames...), ";")

      if mu, ok := j.locks[key]; ok {
          return mu
      } else {
          mu = &sync.Mutex{}
          j.locks[key] = mu  // ← Concurrent map write!
          return mu
      }
  }

  This is a classic concurrent map access bug. When multiple requests hit the
  same domain during certificate operations:

  1. Multiple goroutines call lockFor() simultaneously
  2. They read/write to j.locks map without synchronization
  3. Go runtime can:
    - Panic with "concurrent map writes"
    - Corrupt the map structure
    - Block indefinitely if map internals get corrupted

  This explains the blocking behavior - it's not the RWMutex, but rather a race
  condition causing either panics or deadlocks when the map gets corrupted
  during concurrent certificate operations.

  The fix would be to either:
  1. Add a mutex to protect j.locks map access
  2. Use sync.Map instead of a regular map
  3. Pre-initialize all locks at startup

I do appreciate when me stating a basic fact is called out as “excellent analysis”. Definitely doesn’t make me feel like I’m having smoke blown up my ass.

I think the issue it’s describing here is actually a problem⁴, albeit one that’s unlikely to be hit. But it’s definitely not the one we’re looking for. Claude even describes the possible consequences of the bug, and they don’t match what happened at all.

Maybe logs will help?

While Claude was chugging away, I’d been looking into the issue as well. I had logs from when it happened, and figured Claude may be able to glean something from them too. The first thing I’d noticed is that I wasn’t logging when a process finished, so I’d already added that to the code base, hence the note so Claude doesn’t get itself confused:

> That may be an issue, but it's not the one I was looking for. I've found logs
  from the time it happened. Note that a few logs have been added to the
  codebase since (so we can't tell from the logs when ACME or OCSP processes
  *finished*, just when they started). Here are the logs:
  
  {"time":"22:40:53.187887976Z","level":"INFO","msg":"Received signal, updating routes...","signal":1}
  {"time":"22:40:53.19947532Z","level":"INFO","msg":"Renewing certificate", ...}
  {"time":"22:40:53.199507942Z","level":"INFO","msg":"Starting ACME process to obtain certificate", ...}
  {"time":"22:41:09.048465968Z","level":"INFO","msg":"Renewing certificate", ...}
  {"time":"22:41:09.048482309Z","level":"INFO","msg":"Starting ACME process to obtain certificate", ...}
  {"time":"22:41:17.419299795Z","level":"INFO","msg":"Renewing certificate", ...}
  {"time":"22:41:17.419325744Z","level":"INFO","msg":"Starting ACME process to obtain certificate", ...}
  {"time":"22:41:23.238027386Z","level":"INFO","msg":"Received signal, updating routes...","signal":1}
  {"time":"22:41:29.994330646Z","level":"INFO","msg":"Renewing certificate", ...}
  {"time":"22:41:29.994353329Z","level":"INFO","msg":"Starting ACME process to obtain certificate", ...}
  {"time":"22:41:43.658794811Z","level":"INFO","msg":"Renewing certificate", ...}
  {"time":"22:41:43.658819548Z","level":"INFO","msg":"Starting ACME process to obtain certificate", ...}
  {"time":"22:41:57.635325513Z","level":"INFO","msg":"Renewing certificate", ...}
  {"time":"22:41:57.635347515Z","level":"INFO","msg":"Starting ACME process to obtain certificate", ...}
  {"time":"22:42:10.52439779Z","level":"INFO","msg":"Renewing certificate", ...}
  {"time":"22:42:10.524417107Z","level":"INFO","msg":"Starting ACME process to obtain certificate", ...}
  {"time":"22:42:23.159430249Z","level":"INFO","msg":"Renewing certificate", ...}
  {"time":"22:42:23.159452171Z","level":"INFO","msg":"Starting ACME process to obtain certificate", ...}
  {"time":"22:42:36.347407326Z","level":"INFO","msg":"Renewing certificate", ...}
  {"time":"22:42:36.347433295Z","level":"INFO","msg":"Starting ACME process to obtain certificate", ...}
  {"time":"22:42:52.544628775Z","level":"INFO","msg":"Renewing certificate", ...}
  {"time":"22:42:52.544653993Z","level":"INFO","msg":"Starting ACME process to obtain certificate", ...}
  {"time":"22:43:25.409579107Z","level":"INFO","msg":"Renewing certificate", ...}
  {"time":"22:43:25.409602842Z","level":"INFO","msg":"Starting ACME process to obtain certificate", ...}
  {"time":"22:43:43.819479448Z","level":"INFO","msg":"Renewing certificate", ...}
  {"time":"22:43:43.819502041Z","level":"INFO","msg":"Starting ACME process to obtain certificate", ...}
  {"time":"22:43:54.358957563Z","level":"INFO","msg":"Renewing certificate", ...}
  {"time":"22:43:54.358979355Z","level":"INFO","msg":"Starting ACME process to obtain certificate", ...}
  {"time":"22:44:06.180278128Z","level":"INFO","msg":"Renewing certificate", <big list of alt names>}
  {"time":"22:44:06.180302585Z","level":"INFO","msg":"Starting ACME process to obtain certificate", <big list of alt names>}
  {"time":"22:45:03.830331922Z","level":"WARN","msg":"Failed to connect to upstream","error":"context canceled", ...}
  {"time":"22:45:03.830528134Z","level":"WARN","msg":"Failed to connect to upstream","error":"context canceled", ...}
  {"time":"22:45:03.832388931Z","level":"WARN","msg":"Failed to connect to upstream","error":"context canceled", ...}
  {"time":"22:46:10.225854865Z","level":"WARN","msg":"Failed to connect to upstream","error":"context canceled", ...}
  {"time":"22:46:10.488432434Z","level":"WARN","msg":"Failed to connect to upstream","error":"context canceled", ...}
  {"time":"22:46:10.488439397Z","level":"WARN","msg":"Failed to connect to upstream","error":"context canceled", ...}
  {"time":"22:46:30.617614536Z","level":"WARN","msg":"Failed to connect to upstream","error":"context canceled", ...}

I’ve cut down the logs a bit to remove the specific domains, simplify the timestamps, and remove a bunch of other cruft. The key points are there were two SIGHUPs received, and the last certificate before everything started breaking covered 6 different hostnames.

Claude then went through a phase of periodically shouting “Eureka!” then deciding it hadn’t actually found anything yet:

● Now I see it! The key insight is in the timing and the "context canceled"
  errors. Let me trace through what's happening:
  
● Ah, now I see what's happening! Looking at the logs more carefully:

  1. 22:40:53 - First SIGHUP received, routes updated
  2. 22:40:53 to 22:44:06 - Multiple certificates start renewing (14 certificates!)
  3. 22:41:23 - Another SIGHUP received while renewals are still in progress
  4. 22:45:03 onwards - "context canceled" errors start appearing

  The issue is that SetRoutes is being called AGAIN (at 22:41:23) while the
  previous CheckCertificates() goroutine is still running and renewing
  certificates. Let me check what happens in this scenario:
  
> (The context canceled errors are clients timing out because centauri wasn't
  proxying properly)
  
● Ah, now I understand! The "context canceled" errors are from clients timing
  out because Centauri wasn't proxying their requests. This confirms the
  blocking issue.

  Let me check how incoming requests actually get their certificates:
  
● Now I found the real issue! Looking at the timeline and the code:

  1. 22:40:53 - SIGHUP triggers SetRoutes() which:
    - Calls loadCertificate() for each route
    - Sets route.certificate to the existing certificate
    - Starts go m.CheckCertificates() in background
  2. 22:41:23 - Another SIGHUP while certificates are still renewing
    - SetRoutes() is called AGAIN
    - Creates NEW Route objects with route.certificate = nil initially
    - Replaces the old routes in m.routes
    - The old Route objects (with valid certificates) are replaced!

  The critical issue is in proxy/manager.go:42-65:

  func (m *Manager) SetRoutes(newRoutes []*Route, fallback *Route) error {
      // ... validation ...

      for i := range newRoutes {
          route := newRoutes[i]  // These are NEW Route objects!
          // ...
          m.loadCertificate(route)  // Try to load certificate
      }

      m.lock.Lock()
      m.routes = newRoutes  // REPLACES all routes!
      m.lock.Unlock()
  }

  When the second SIGHUP arrives:
  1. New Route objects are created
  2. For domains currently being renewed, GetExistingCertificate might fail or
     return expired certs
  3. These routes get route.certificate = nil and CertificateMissing status
  4. CertificateForClient returns nil for these domains
  5. TLS handshake fails → clients can't connect → "context canceled" errors

  The fix would be to either:
  1. Prevent concurrent CheckCertificates runs
  2. Copy certificates from existing routes before replacing them
  3. Make certificate renewal truly independent of route management

Midway through it had started searching for “context canceled” errors in the codebase, which doesn’t make much sense. That’s what happens when a client gives up waiting, so the corresponding backend request is terminated. You won’t actually find “context canceled” anywhere in Centauri, because it’s a feature of the Go standard library. I gave it a little nudge to try to stop it rabbit holing.

As far as I can tell, what it’s talking about in this response isn’t an issue. I guess it’s possible that there’s a race condition whereby a route would be replaced and end up with an old version of a certificate that was just being renewed, but it wouldn’t cause an issue in practice; it’d just get updated next time the certificates were refreshed.

There’s no way for routes to get a nil certificate in this scenario, as far as I know. But I don’t have the unfounded confidence of an LLM, so I simply said:

> I don't follow why the certificate would be nil?

Attempt the third

I expected Claude to just explain its reasoning, but it apparently didn’t have any reasoning so set off on another voyage of discovery:

● You're right to question that. Let me trace through this more carefully.

● Good point! Since GetExistingCertificate doesn't acquire locks, it should
  return the existing certificate even during renewal. Let me dig deeper:
  
● Now I see a potential race condition! Here's what could happen:

● I found it! There's a critical race condition that explains the blocking:

  The Race Condition

  1. Background renewal starts: CheckCertificates() → updateCert() →
     GetCertificate() acquires lock and starts ACME renewal
  2. SIGHUP arrives: SetRoutes() is called, which for each route calls
     loadCertificate() → GetExistingCertificate() → store.GetCertificate()
  3. The race:
    - store.GetCertificate() returns a pointer to the certificate in the slice
    - Meanwhile, the renewal completes and calls SaveCertificate()
    - SaveCertificate() calls removeCertificate() which modifies the slice while
      it's being read
    - This slice modification (append(j.certificates[:i], j.certificates[i+1:]...))
      can cause:
        - The pointer returned by GetCertificate to become invalid
        - Slice bounds issues
        - Memory corruption
  4. The result:
    - GetExistingCertificate might return corrupted data or nil
    - Routes end up with certificate = nil
    - TLS handshakes fail
    - Clients timeout → "context canceled"

  The Timeline Confirms This

  - 22:40:53 - First SIGHUP, starts renewal of 14 certificates
  - 22:41:23 - Second SIGHUP arrives (30 seconds later) while renewals are still running
  - 22:45:03 - First timeout errors (4 minutes after first SIGHUP)

  The 4-minute delay matches ACME renewal time. The second SIGHUP's SetRoutes
  likely read certificates while they were being modified by the first SIGHUP's
  renewal goroutines.

  This is a classic concurrent slice modification bug - no synchronization
  between readers (GetCertificate) and writers (SaveCertificate/removeCertificate).

Once again we have a very confident and technical answer that does not explain the symptoms we’re looking for. It’s also mostly rubbish again. GetCertificate and SaveCertificate are only called by code that is holding a lock for that certificate; they won’t interfere with one another. There may, again, be a small concurrency issue if different certificates are handled in parallel, but it’s definitely not the cause of our current problems.⁵

Working through these explanations and debunking them was annoying me at this point. I decided to give it once last chance, and used the “ultrathink” shibboleth:

> So there may be a concurrent modification issue, but that doesn't explain the
  symptoms. If a TLS handshake failed it wouldn't result in the clients timing
  out. Likewise if there was any kind of corruption there'd be a panic, not a
  period where it didn't work and then started working again. Engage ultrathink.

Fourth time lucky

I’m going to include a piece of the thinking here because it amused me so much:

✻ Thinking…

  Oh! I need to think about this differently. Let me trace through what happens
  when a request comes in:

Apparently it takes “ultrathink” to actually work through the problem logically? Amusingly it did actually get there:

● You're absolutely right. Let me think more carefully about this...

● EXACTLY! That's the issue. Looking at the timeline:

  1. 22:40:53 - First SIGHUP: CheckCertificates() acquires READ lock, starts
     renewing 14 certificates
  2. 22:41:23 - Second SIGHUP: SetRoutes() tries to acquire write lock, blocks
     waiting
  3. Incoming requests call routeFor() for route lookup, but Go's RWMutex blocks
     new readers when a writer is waiting (to prevent writer starvation)
  4. 22:45:03 - Clients timeout because requests can't even get past route lookup

  The key insight is Go's RWMutex writer starvation prevention: when a writer
  is waiting, new readers are blocked even though the current lock holder is
  also a reader.

  So the cascade is:
  - CheckCertificates (read lock) → certificate renewal takes minutes
  - SetRoutes (write lock) → waits for read lock to release
  - routeFor (read lock for every request) → blocked by waiting writer

  Result: All incoming HTTP requests hang at route lookup, never reach TLS
  handshake or proxying logic. Clients timeout waiting for any response
  → "context canceled".

  This perfectly explains:
  - No panics (no corruption)
  - No immediate TLS errors (never gets that far)
  - Requests hang then timeout (blocked on lock)
  - Eventually recovers (when certificate renewals finish)

  The fix would be restructuring to avoid holding the manager lock during slow
  certificate operations.

We’re back to the RWMutex again, but this time it’s dropping knowledge on me not the other way around: if there’s a writer waiting, then new readers are blocked. This does indeed perfectly explain the symptoms, and was something I’d overlooked. The write lock is only held briefly to update some struct members to prevent it from blocking the readers, but this behaviour coupled with the long-running read lock ends up doing that anyway.

The fix

After all this work it’s very tempting just to ask Claude to fix it, but I had almost no confidence it’d be able to maintain any of the concurrency requirements given how much it flailed around with bad explanations. But in the interests of science, I asked it to try. Here’s what it came up with:

   // CheckCertificates checks and updates the certificates required for registered routes.
   // It should be called periodically to renew certificates and obtain new OCSP staples.
   func (m *Manager) CheckCertificates() {
+    // Create a snapshot of routes to avoid holding the lock during slow certificate operations
     m.lock.RLock()
+    routes := make([]*Route, len(m.routes))
+    copy(routes, m.routes)
+    provider := m.provider
+    m.lock.RUnlock()

+    // Process certificate renewals without holding the manager lock
-    for i := range m.routes {
+    for i := range routes {
-      route := m.routes[i]
+      route := routes[i]
 
       if provider == nil {
         route.certificateStatus = CertificateNotRequired
       } else {
         m.updateCert(route)
       }
     }
-    m.lock.RUnlock()
   }

   // updateCert updates the certificate for the given route.

That’s about what I expect. It definitely fixes the exact issue described, but it’s a bit… sloppy. Routes are now being updated when the lock isn’t being held, which is a change in semantics. It also doesn’t address the underlying issue that requests can be blocked if there’s a pending writer, and pending writes can be blocked by readers. A better approach would be to allow these operations to happen without blocking, maybe by using an atomic pointer to an immutable slice. I guess I’ve got some coding to do!

As for Claude: while the journey was frustrating, I think trying to figure this out by myself would have been even more so. It’s one of those things where everything looks right to me, and I’d have to go down a fairly long chain of checking my assumptions to find where I’d gone wrong.

There’s definitely a lot of room for improvement in coding LLMs: being able to estimate their own confidence level instead of stating everything as absolute truth would go a long way. I imagine there’s also a lot of benefit of having one LLM vet the responses of another; that’s sort-of how thinking mode works, but it doesn’t seem to go far enough to stop it outputting rubbish. It’ll be interesting to see how they develop in the future, anyway.

read as “I got spammed by a bunch of monitoring notifications” ↩︎
read as “Me repeatedly telling it that it was talking rubbish” ↩︎
If only we had some kind of language model technology that could understand this kind of thing. ↩︎
I sense some fun times with Go’s race detector in my near future ↩︎
The most likely outcome from these concurrency issues is Centauri panicking, which isn’t great but would only interrupt ongoing connections before it restarts and starts serving traffic again. Much less problematic than the “block for five minutes” behaviour I’m trying to fix. ↩︎

How to break everything by fuzz testing

2020-04-26T00:00:00Z

Fuzz testing is a bit like the infinite monkey theorem, but instead of Shakespeare you get crashes.

Fuzz testing, if you’re not aware, is a form of testing that uses procedurally generated random inputs to see how a program behaves. For instance, if you were fuzz testing a web page renderer you might generate a bunch of HTML - some valid, and some not - and make sure the rendering process didn’t unexpectedly crash.

Fuzz testing doesn’t readily lend itself to all types of software, but it particularly shines in cases where some kind of complex user input is accepted and processed in some way - like the aforementioned web page renderer. I was recently adding a library to parse EXIF data to images to an Internet-facing service and realised it was a perfect opportunity to do some fuzz testing. Even if I didn’t find any issues, I’d improve my confidence that the library was safe enough to expose to the Internet.

Breaking my EXIF library

I wrote a quick harness to run go-fuzz on the library, and gave it some pre-existing demo files as sample input. The way go-fuzz works is that it instruments your code and then mutates the inputs to try to improve the coverage. For example, if I had some sample data that had an EXIF tag with a value of 1 then go-fuzz might change it to a 2 and see if the code follows a different path. In most cases it won’t but when it does, they tend to be very interesting cases.

One of the first issues that go-fuzz found was that some values in a maker note field would cause the library to panic (i.e., crash). This happened because there was a check to see if the first six characters were “Nikon” and a null byte, without first checking to see if there were actually six characters available. This is a kind of bug that doesn’t happen much with “real” data - as the field is either not present or completed correctly - but could easily be exploited once this code is exposed to the Internet.

Another interesting bug that go-fuzz found was that if a tag had a particularly large count, the library would try to allocate an obscene amount of memory and die. There was already a check in the code that was meant to avoid this exact scenario, but go-fuzz managed to find a way around it. Each tag has a size (for example an integer tag takes a fixed number of bytes) and a count; the existing check multiplied the two together and made sure that the result wasn’t too large. For most cases this was fine but go-fuzz found a case where the count was so large that when multiplied by the size of the tag it overflowed the integer and became negative, thus passing the sanity check but then subsequently failing when it came around to actually allocating the memory.

The final bug of note that go-fuzz found was the most interesting. EXIF data is stored in IFDs (“Image File Directories”), and each IFD provides what is effectively a pointer (a byte offset) to the next one. The EXIF library already had a check to make sure that these didn’t loop, but it only checked the immediately preceding IFD - so if IFD 1 linked to IFD 2, it would catch IFD 2 linking back to IFD 1 and break the loop with an error. Go-fuzz found that having three interlinked IFDs had the same issue, though, and the guard code wasn’t triggered. This created an infinite loop, maxing out a CPU core until the process was eventually killed - one of the worst kind of bugs you could have in an Internet-facing service which doesn’t deal with private data! The fix for this was fairly straightforward - I just made the library keep a record of the previously visited IFDs and bail out if it found a loop.

Breaking my IDE

When go-fuzz detects an issue it outputs not only the details of the problem (the stack trace, error message, and so forth) but also the input that generated the problem. This is useful for reproducing and making sure the issue is fixed, but it also makes it really easy to write a test to ensure that the behaviour never regresses in the future.

As I was working through fixing the bugs that go-fuzz found, I dutifully added new tests where needed. After adding the sample input with looping IFDs to the project, I switched to IDEA to write a test to use it. I clicked on the input file to copy the file name, and then the entire IDE hung and had to be restarted. Uh oh! When I restarted IDEA, it immediately began indexing the project and again hung. It turns out IDEA parses EXIF data (presumably, even if it does nothing else with the data, to get the rotation property for images), and the library they use - an independent one written on Java - had the same bug as the Go library I was using.

In order to stop IDEA from indexing the file and becoming unusable I renamed it from a ‘.tif’ extension to ‘.dat’, and everything went back to normal. I thought I’d best report the bug to JetBrains, though, so they could put a proper fix in.

Breaking YouTrack

JetBrains use their own issue tracker called YouTrack for reporting bugs in IDEA. I dutifully went over and described the problem, attaching the log files from the IDE, a description of how the file was malformed, and carefully selected the .dat version of the file to upload so that it wouldn’t cause anyone else the same immediate problem.

After trying to upload the file I got a strange error back. Uh oh! I submitted the IDEA issue as it stood, unable to see if the attachments had even uploaded, and went and wrote up an issue for YouTrack itself about the error message. While I was doing that, YouTrack seemed to slow down and become really annoying to use. I had a sinking feeling the exact same thing was probably happening as with IDEA and my library - but this time YouTrack had content-sniffed the file instead of relying on the file extension. In hindsight, I should’ve put the file in a passworded archive to ensure no automated tools got hold of it. I marked the issue as a security problem as in a service like YouTrack it presents a denial-of-service opportunity¹ (remember when I said it was one of the worst kinds of bugs you could have in an Internet-facing service?…)

Shortly after I raised my YouTrack ticket, a notice appeared at the top of the page saying they were investigating the current performance issues. Uh oh! I was holding out hope that this was unrelated to me uploading the buggy dat file, but the timing all seemed a bit suspect. I shot support an e-mail saying I think I might be the root cause for their performance issues and linked to the ticket. In the time it took me to e-mail them, the entire site had been put into maintenance mode. I got an e-mail back a few hours later confirming the outage was in fact all my fault, as I’d feared. Within the space of days the JetBrains security team had fixed the issue in YouTrack, which was a pretty nice turnaround.

So if you were trying to access YouTrack at the start of March and couldn’t - I’m sorry, I didn’t mean to! Also, if you’re building an Internet-facing service that takes user input you should really consider running a fuzz tester against it!

“We have a problem”. “Remember, there are no such things as problems, only opportunities”. “Well then we have a DDoS opportunity.” – @J4vv4d ↩︎

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!