Corrupted metadata JSON files caused by bug #297

[lqs]

The bug #297 frequently leads to corrupted JSON files when multiple instances mount a shared NFS directory as storage. We’ve encountered numerous cases in production where this causes certificate failures with the error message decoding certificate metadata: invalid character '}' after top-level value, rendering the affected sites completely unusable.

The number of corrupted files is increasing, and I can’t restart the service.

I see the bug fix is in the master branch. Please release a new version that includes this fix. Additionally, how can I identify and repair the already corrupted files among thousands without deleting all files? Alternatively, is there a way to ignore corrupted files during loading?

[francislavoie]

If you're in a hurry, you can make a build yourself with this:

xcaddy build --with github.com/caddyserver/certmagic@16e2e0b

[mholt]

Curious what evidence you have that this and #297 are related -- how do you know that superfluous ARI requests is corrupting files?

[lqs]

I’m using certmagic as a library for a web server that serves front-end files and supports custom domains. When the error occurred, I checked the logs and file modification times and found that an extra ‘}’ appeared after multiple ARI updates. After reviewing the source code, I suspect this issue is due to concurrent writes to NFS.

Prior to the error, I was already preparing to migrate from NFS to S3 and implemented a custom storage to access S3. After the error, I expedited the migration process. Since S3 writes are atomic, it prevented the issue, even though redundant ARI requests still remain.

[mholt]

NFS has known bugs related to synchronization, that might be the actual problem.

S3 does not provide atomic operations for us to be able to safely offer synchronization, even if writes are synced. I recommend using a database like MySQL/Postgres/Redis for high concurrency distributed storage.

[mholt]

Moving another discussion with @Zenexer into here:

As far as I can tell, this isn't fixed by 16e2e0b. I'm able to repro the extra } error reliably--multiple times per hour--regardless of the lengths of the original and new files, so it's not just a simple truncation issue. It's always one extra }, even though file sizes often differ by more than one character.

Removing the extraneous closing braces restores sanity, but only briefly. They keep reappearing in new files.

Originally posted by @Zenexer in #297

---

Anyway, @lqs, from what you're saying:

• Using NFS, files have extra }
• Using S3, files don't have extra } but still redundant ARI requests still happen

This actually checks out with known issues with both of those storage backends (as noted just above). NFS has sync/flush issues when it comes to concurrent users over a network; and S3 doesn't provide atomic operations, so proper locking/syncing of an operation like an ARI request is impossible.

@Zenexer, are you also using NFS perchance?

[Zenexer]

I spent about a dozen hours debugging this yesterday, and I believe my initial comment was incorrect: rather than the bug persisting, I believe I just hadn't sufficiently cleaned all of the existing corrupt files. There were situations in which there were two trailing bytes at the end of a file (\n}), and my cleanup script didn't account for that.

I am using NFS, but it does appear to support locking correctly with my current mount options--or, at least, in a way that is compatible with this patch. I'm not a huge fan of NFS and generally don't trust it, but it should work with this lock/write pattern. I doubt it would ever make sense to officially support NFS given how fickle it is, but the locking code in certmagic is straightforward enough that I should be able to debug and patch it if there are further issues.

The one thing that still has me a little worried is a disconcerting number of requests to the on-demand ask endpoint. The docs make it sound as though that's to be expected, but it's accompanied by a large number of log entries related to ARI. I don't think it's a bug--it's probably just a coincidence--but I happened to notice it while troubleshooting.

[francislavoie]

That's good to hear! Yours was the only feedback so far that it didn't fix the issue, so it's reassuring that it was an oversight.

[mholt]

That's a relief, thanks for the follow-up.

The one thing that still has me a little worried is a disconcerting number of requests to the on-demand ask endpoint. The docs make it sound as though that's to be expected, but it's accompanied by a large number of log entries related to ARI. I don't think it's a bug--it's probably just a coincidence--but I happened to notice it while troubleshooting.

The ask endpoint can be busy... we could potentially ease this with a bloom filter or something, that we just reset every 5 or 10 minutes (or something like that). But ideally I'd rather the ask endpoint itself do the caching since it knows better logic than we can guess.

I'd be curious if the ARI log entries are redundant (same hostname) or not. I really want that to be fixed (AFAIK it should be already).

[Zenexer]

The ask endpoint can be busy... we could potentially ease this with a bloom filter or something, that we just reset every 5 or 10 minutes (or something like that). But ideally I'd rather the ask endpoint itself do the caching since it knows better logic than we can guess.

I would assume that any Caddy user with that sort of traffic probably has caching on their ask endpoint anyway and can keep it fast. From my perspective, though, I'd like to be able to log exactly when I've told Caddy it was authorized to go out and request a certificate: having that logging on my application helps me with troubleshooting, since I can use that to determine where in the stack a problem is arising that might be leading to excessive certificate requests. As it currently stands, I don't know whether an ask is for a certificate request/renewal, an ARI request, or some other maintenance task being performed by Caddy--it's a black box.

I'd be curious if the ARI log entries are redundant (same hostname) or not. I really want that to be fixed (AFAIK it should be already).

I'll try to figure that out, but Caddy is spitting out gigabytes of log data with on-demand TLS enabled, so I'm still trying to sort out what's important and what's not.

[Zenexer]

I think most of the log entries are the result of various hosting providers and registrars trying to request or renew certificates for domains that no longer point to them, with no checking on their end prior to starting the ACME challenge process. That makes it really difficult to tell the difference between legitimate ACME-related error messages and errors that I can safely ignore. (Ugh, I really wish CAs wouldn't waive rate limiting on challenge failures for large integrators--it hurts everyone.) I don't think that should affect ARI log messages, so I'll let docker compose logs -fn0 | grep -F '"updated ACME renewal information"' and see what turns up.

[Zenexer]

I'm not seeing any overlap between ARI requests so far. Each one is unique.

[mholt]

I'd like to be able to log exactly when I've told Caddy it was authorized to go out and request a certificate; having that logging on my application helps me with troubleshooting, since I can use that to determine where in the stack a problem is arising that might be leading to excessive certificate requests. As it currently stands, I don't know whether an ask is for a certificate request/renewal, an ARI request, or some other maintenance task being performed by Caddy--it's a black box.

To make sure I understand, you want a way for the 'ask' request to distinguish whether a certificate is being obtained or something else?

The only times the 'ask' endpoint is invoked are currently when a certificate needs to be obtained or renewed. It does not guard ARI requests or other maintenance, per-se, though in theory it should be guarding them implicitly, because if you cannot obtain or renew a cert, you cannot maintain it either.

Technically, 'ask' is invoked before even trying to load a certificate from storage (as that can be expensive depending on the storage backend).

So I guess, to your request, I would say that it shouldn't matter, but I'm open to discussing this further if desired.

I think most of the log entries are the result of various hosting providers and registrars trying to request or renew certificates for domains that no longer point to them, with no checking on their end prior to starting the ACME challenge process. That makes it really difficult to tell the difference between legitimate ACME-related error messages and errors that I can safely ignore. (Ugh, I really wish CAs wouldn't waive rate limiting on challenge failures for large integrators--it hurts everyone.) I don't think that should affect ARI log messages, so I'll let docker compose logs -fn0 | grep -F '"updated ACME renewal information"' and see what turns up.

I was one who advocated for exemptions to the rate limits when conforming to ARI, out of concerns that certificate renewals would be rejected -- sometimes past their expiration -- on account of rate limits, even though it was the CA who specified the renewal window. So to ensure certificates can be renewed even if they have to be squished into a narrow window, Let's Encrypt (rightly) exempts clients from rate limits in that situation. Why do you think it hurts everyone?

Is Caddy attempting to renew lots of certificates for you and failing?

I'm not seeing any overlap between ARI requests so far. Each one is unique.

That's good, so it sounds like the synchronization is working. 👍 Thanks for checking on that.

[Zenexer]

To make sure I understand, you want a way for the 'ask' request to distinguish whether a certificate is being obtained or something else?

Yes, mostly for debugging purposes. If I see that multiple Caddy instances are all trying to get certs at the same time, that's a sign something is amiss. It would likely help when troubleshooting future concurrency issues, but a lightweight plugin could probably serve the same purpose.

I'm still not 100% confident the remaining errors I'm seeing are benign, but I'll have more data over the next few days.