Chameth.com - posts like break-everything-fuzz-testing, debugging-beyond-the-debugger, why-you-should-be-using-https but not building-a-new-computer, g15-ram-upgrade, migrating-from-github-to-forgejo

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 ↩︎

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).

Why you should be using HTTPS

2016-06-17T00:00:00Z

The EFF’s HTTPS Everywhere logo

One of my favourite hobbyhorses recently has been the use of HTTPS, or lack thereof. HTTPS is the thing that makes the little padlock appear in your browser, and has existed for over 20 years. In the past, that little padlock was the exclusive preserve of banks and other ‘high security’ establishments; over time its use has gradually expanded to most (but not all) websites that handle user information, and the time is now right for it to become ubiquitous.

Why use HTTPS?

There are numerous advantages to using HTTPS, both for the users of a website and for the operator:

Privacy

The most obvious advantage is that HTTPS gives your users additional privacy. An insecure (HTTP) request can potentially be read by anyone on the same network, or the network operators, or anyone who happens to operate a network along the path between the user and the server.

Users on shared WiFi networks (such as those in coffee shops, hotels, or offices) are particularly vulnerable to passive sniffing by anyone else on that network. If the network is open (as is frequently the case) then anyone in radio range can see exactly what the user is up to.

Integrity

HTTPS also helps to maintain the integrity of your site. With a plain HTTP request, there’s nothing to stop anyone in between the server and the user from modifying the content of the request or the response. This is a frequent tactic used by annoying WiFi gateways (such as the ones you’d find in a hotel), dubious ISPs who want to serve you extra adverts, or just plain old nefarious attackers.

If you’re trying to convey some kind of information to users (and if you aren’t, why exactly are you running a website again?) it seems beneficial to both you and them if the information arrives as you intended, rather than in a modified form due to someone or something tampering with it.

Security

If your website has any kind of authentication, or session identifiers, it becomes extremely vulnerable to an attacker monitoring the traffic and stealing the credentials. This was starkly demonstrated in 2010 when Firesheep was released. This tool allowed anyone to quickly and automatically hijack social media accounts of anyone on the same network who was using HTTP to access them.

Even if your login pages are served over HTTPS, if you send a single session ID cookie over HTTP (such as a page you decided wasn’t particularly ‘important’) then an attacker can probably spoof the user’s session and gain full access to their account. Again, in the case of open WiFi networks that could be anyone in radio range.

Search engine rankings

Some search engines use HTTPS as a signal in their ranking algorithms. Google announced in 2004 that it was using the presence of HTTPS as a small positive signal, but that it may strengthen that signal over time as more and more websites switch to using a secure transport. It’s not unthinkable that at some point in the future there will be HTTPS-only search engines.

But… But… But…

There are lots of excuses for not implementing HTTPS. Most of them are either misguided or outdated.

It’s too expensive and/or complicated

In the past, getting HTTPS certificates was a pain. A number of free suppliers have existed for a while but the process for getting their certificates wasn’t particularly straight forward, and many imposed arbitrary restrictions on the certificate parameters. Even once you had the certificate, you had to fiddle about with your HTTP server configuration to make it work, remember to manually get a new certificate when the old one expired, and lots of other annoying busywork.

With the arrival of Let’s Encrypt, all that changed. You can retrieve and deploy a free HTTPS certificate with two or three commands. Renewal can be handled completely automatically with a single command executed by cron.

There’s no point; nothing on my site is sensitive

You might not think your content warrants privacy, but can you speak for everyone who accesses it? Even content that seems mundane to you — such as travel advice, or technical writing — could be used to build up a profile of a user. If an attacker is monitoring traffic in a coffee shop and sees a user looking at travel advice and weather forecasts for a foreign country, he could use that information to plan a burglary knowing that the user will be away. Similarly, some content which is perfectly mundane to you may actually be very sensitive in other countries with repressive governments. HTTPS makes it much harder for these people to snoop on traffic.

From another angle, if you’re offering any kind of information, instructions, or especially file downloads, there’s a severe risk to users if the content is modified on its way to them. An evil sysadmin could rewrite your travel advice to suggest visiting the local drug dealer’s hangout, or replace your download with a malware-infested version.

HTTPS is slower, uses more resources, etc

Back in 1995 this might have been a valid argument. Enabling HTTPS on a modern server will make an almost negligible difference to performance. If you also enable HTTP/2 (which most implementations only support over HTTPS), it’s likely to actually use fewer resources, and result in a faster, smoother experience for your users. HTTP/2 was designed to work with HTTPS, and designed with modern requirements and networking techniques in mind.

CloudFlare have an excellent demonstration of the benefits of HTTP/2, and it can show speed improvements of 2-3x in a typical environment. On top of being faster, HTTP/2 uses fewer connections which results in less resource overhead on both the server and the client.

So what are you waiting for?

If you run a website and aren’t using HTTPS, give it a try.