bug: find cache: unexpected end of JSON input #920
Labels
No labels
FreeBSD
Kind/Breaking
Kind/Bug
Kind/Chore
Kind/DependencyUpdate
Kind/Documentation
Kind/Enhancement
Kind/Feature
Kind/Security
Kind/Testing
Priority
Critical
Priority
High
Priority
Low
Priority
Medium
Reviewed
Confirmed
Reviewed
Duplicate
Reviewed
Invalid
Reviewed
Won't Fix
Status
Abandoned
Status
Blocked
Status
Need More Info
Windows
linux-powerpc64le
linux-riscv64
linux-s390x
run-end-to-end-tests
run-forgejo-tests
run-multi-platform-tests
No milestone
No assignees
2 participants
Notifications
Due date
No due date set.
Dependencies
No dependencies set
Reference
forgejo/runner#920
Loading…
Reference in a new issue
No description provided.
Delete branch "%!s()"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
Workaround
Remove the cache and restart the runner.
Description
It started happening in the Forgejo runner, e.g. https://codeberg.org/forgejo/forgejo/actions/runs/99720#jobstep-1-3
Every attempt to retrieve a cache entry was met with this error.
Logs and data
Extract renovate logs with some context to get all the logged lines even if not renovate specific that happened at the same time. The focus is on finding cache related log lines (they have
module=artifactcache).The following shows details on the problem:
The error (
find cache: unexpected end of JSON input) happens here:if err := db.FindOne(cache,bolthold.Where("Repo").Eq(repo).Index("Repo").And("Key").Eq(prefix).And("Version").Eq(version).And("Complete").Eq(true).SortBy("CreatedAt").Reverse()); err == nil || !errors.Is(err, bolthold.ErrNotFound) {if err != nil {return nil, fmt.Errorf("find cache: %w", err)}return cache, nil}and is reported with details to the cache action but the cache action only logs
Cache service responded with 500without the details.Verified it works by manually triggering the renovate workflow
The error does not show on any other runners, all of which are running v9.1.1 which rules out a v9.1.1 specific regression.
I think it should be possible to repeat the error by spawning a new runner with the cache that was saved. I'm not able to find / separate an error other than "500" from the logs.
For comparison, the log of a successful cache retrieval looks like:
I thought it might be that a newer bolt version is not backward compatible but... that would impact the other runners as well so not that.
Updated the description with the proper way to extract the error (needs
-C 20to grep on renovate and then it is quite clear). It is definitely a bolt corruption from which it does not recover. It will keep trying to find entries and fail for the same reason, stuck.if err := db.FindOne(cache,bolthold.Where("Repo").Eq(repo).Index("Repo").And("Key").Eq(prefix).And("Version").Eq(version).And("Complete").Eq(true).SortBy("CreatedAt").Reverse()); err == nil || !errors.Is(err, bolthold.ErrNotFound) {if err != nil {return nil, fmt.Errorf("find cache: %w", err)}return cache, nil}I tried to reproduce the error with a new runner set to use the cache saved after the failure (
bolt.dbonly, not the 70GB of data as they are not involvedin the query). When it starts it shows something like:which is a good indication that it is happily using it. I then proceeded to run the cache example which succeeds.
No reproducer so far.
All entries are valid JSON.
bug: Failed to restore: getCacheEntry failed: Cache service responded with 500to bug: find cache: unexpected end of JSON inputI extracted as much information as I could from the saved data but it does not reproduce the error.
I had a thought: if finding an entry always fails in this way, then finding entries for garbage collection should also fail. But it did not. Garbage collection kept going on, happily.
Also, it cannot be because of handler that is somehow stale, the database is opened every time it is needed and closed upon completion.
One thing is wrong with that part of the code. An error in find should not be considered recoverable but fatal. It should either:
Displaying errors in the logs is good. But continuing to run when there is no hope for recovery is bad. I favor resetting the cache because it is a safe recovery mechanism in this case. The cache action will just have to re-populate everything.
I'd make a counter-argument... I'd say that if we had a known, specific error condition, with an understandable cause, then resetting the cache could be fine. In the absence of that specific knowledge, I'd favour making error handling in the cache as disruptive as possible so that it doesn't fail with unique and interesting conditions silently.
My concern is that I don't want a situation where a cache is relatively important -- preventing a large waste of energy, ensuring developers have fast iteration cycles -- to be quietly and repeatedly failing and clearing the cache. That's a situation that could go on indefinitely without anyone realizing the impact. I think it's better to raise the profile of such an error so that it can be diagnosed, understood, and error-specific handling installed.
You have me convinced, I'll work on a fix to exit the runner with a meaningful error message.
When that happens it will be noticed but it won't break anything: jobs will just pile up until it is restarted. Although it is disruptive, such a corruption has only occurred once in the past two years.
All past crashes were investigated and fixed, this is the first one that eludes forensic analysis (modulo a handful of crashes that were not noticed at all, it is not 100% 😁). The odds that such a hard fail creates a problem for admins are very low.
Make Handler mockable #934
#935 is in v11.0.0 released today. It does not solve that issue but it will make it more immediately visible and hopefully easier to debug.
Let's close this as there is very little chance it will happen again. And if it does, this issue does not really provide any usable insight: the data from the fail are sane and cannot be used to reproduce the problem.