Cards not displayed on wuffle pod restart until next background sync

[piyushk]

Describe the Bug

We restarted our wuffle pod and all cards on the frontend vanished. Store was restored from s3 within ~5 seconds. The cards appeared ~15 minutes later when the next background sync happened.

I removed some spurious log lines in the log below:

sed -i '/"name":"http"/d' log
sed -i '/"name":"wuffle:auth-flow"/d' log 
sed -i '/"name":"wuffle:user-/d' log 
sed -i '/"name":"github:user-/d' log

Log:

{"name":"wuffle:run","hostname":"wuffle-68d756bd5b-2mprw","pid":1,"level":30,"msg":"Attempting to run Wuffle v0.35.5 in /app/packages/app","time":"2021-03-08T21:06:29.278Z","v":0}
{"name":"wuffle:run","hostname":"wuffle-68d756bd5b-2mprw","pid":1,"level":30,"msg":"Validating configuration","time":"2021-03-08T21:06:29.280Z","v":0}
{"name":"wuffle:run","hostname":"wuffle-68d756bd5b-2mprw","pid":1,"level":30,"msg":"Starting Wuffle","time":"2021-03-08T21:06:29.282Z","v":0}
Warning: connect.session() MemoryStore is not
designed for a production environment, as it will leak
memory, and will not scale past a single process.
[@octokit/app] Deprecated. Use @octokit/app-auth instead. See https://github.com/octokit/app.js/#deprecated
{"name":"probot","hostname":"wuffle-68d756bd5b-2mprw","pid":1,"level":40,"msg":"Run `npm install --save-dev smee-client` to proxy webhooks to localhost.","time":"2021-03-08T21:06:29.404Z","v":0}
{"name":"probot","hostname":"wuffle-68d756bd5b-2mprw","pid":1,"level":30,"msg":"Listening on http://localhost:3000","time":"2021-03-08T21:06:29.404Z","v":0}
{"name":"wuffle:dump-store-s3","hostname":"wuffle-68d756bd5b-2mprw","pid":1,"level":30,"Bucket":"REDACTED","Key":"storedump.json","t":5244,"msg":"restored","time":"2021-03-08T21:06:34.644Z","v":0}
{"name":"wuffle","hostname":"wuffle-68d756bd5b-2mprw","pid":1,"level":30,"msg":"started","time":"2021-03-08T21:06:34.644Z","v":0}
{"name":"wuffle:dump-store-s3","hostname":"wuffle-68d756bd5b-2mprw","pid":1,"level":30,"Bucket":"REDACTED","Key":"storedump.json","t":783,"msg":"dumped","time":"2021-03-08T21:11:30.184Z","v":0}
{"name":"wuffle:dump-store-s3","hostname":"wuffle-68d756bd5b-2mprw","pid":1,"level":30,"Bucket":"REDACTED","Key":"storedump.json","t":680,"msg":"dumped","time":"2021-03-08T21:16:30.082Z","v":0}
{"name":"wuffle:background-sync","hostname":"wuffle-68d756bd5b-2mprw","pid":1,"level":30,"msg":"start","time":"2021-03-08T21:20:59.728Z","v":0}
...
...

Note that the background sync happened ~15 minutes after startup. After the background sync, cards appeared on the frontend as normal.

Steps to Reproduce

I'm not sure how reproducible this behavior is. We just restarted out wuffle pod. The repositories have a high number of issues.

Expected Behavior

I would expect that cards appear as soon as wuffle pod is restarted and the store has been restored.

Environment

• Host (Browser/Node version), if applicable: Node 10
• OS: It's running in an Amazon EKS environment, so it uses an Amazon Linux AMI
• Board version: v0.35.5. We do make some custom changes to automatic-dev-flow.js to better suit our needs

[nikku]

Thanks for opening this issue @piyushk.

What would be interesting is to get some more details on your utilization:

• How many issues do you have on the board?
• When did background sync start and when did it complete?
• When did store dump / restore start and when did it complete?
• Which environment do you run your board in (dev/prod)?

Note that the background sync happened ~15 minutes after startup. After the background sync, cards appeared on the frontend as normal.

The only explaination I can think of at the moment is that store restore did not kick in or did not restore anything. But looking at the logs restore completed in five seconds.

[nikku]

Do you by chance have a backup of your store dump? If so, it could be interesting to see what was inside / supposed to be restored.

[piyushk]

I'll try my best to provide details. We're running on this private repository, so I'll have to look through stuff before sharing it:

• The board had ~6000 issues before the restart. About ~5000 issues are in an archived column that most users keep collapsed -- we don't want to really show them on the board.
• Background sync started at 21:20:59 and finished at 21:21:10, so 11 seconds.

  {"name":"wuffle:background-sync","hostname":"wuffle-68d756bd5b-2mprw","pid":1,"level":30,"msg":"start","time":"2021-03-08T21:20:59.728Z","v":0}
  ...
  {"name":"wuffle:background-sync","hostname":"wuffle-68d756bd5b-2mprw","pid":1,"level":20,"issue":"REDACTED","msg":"skipping, as up-to-date","time":"2021-03-08T21:21:01.963Z","v":0}
  {"name":"wuffle:background-sync","hostname":"wuffle-68d756bd5b-2mprw","pid":1,"level":20,"issue":"REDACTED","msg":"skipping, as up-to-date","time":"2021-03-08T21:21:01.967Z","v":0}
  ...
  {"name":"wuffle:background-sync","hostname":"wuffle-68d756bd5b-2mprw","pid":1,"level":20,"msg":"cleanup start","time":"2021-03-08T21:21:10.932Z","v":0}
  1901 {"name":"wuffle:background-sync","hostname":"wuffle-68d756bd5b-2mprw","pid":1,"level":20,"t":4,"msg":"cleanup done","time":"2021-03-08T21:21:10.936Z","v":0}
  1902 {"name":"wuffle:background-sync","hostname":"wuffle-68d756bd5b-2mprw","pid":1,"level":30,"t":11125,"msg":"updated 1, removed 0 issues","time":"2021-03-08T21:21:10.936Z","v":0}
  1903 {"name":"wuffle:background-sync","hostname":"wuffle-68d756bd5b-2mprw","pid":1,"level":30,"msg":"done","time":"2021-03-08T21:21:10.936Z","v":0}

• After the background sync, I saw all ~6000 issues back on the board. I noted that the background sync generated about ~1500 lines in the log. Interestingly, the board only shows about ~1500 issues right now. Glancing at them, they seem to all be more recently touched issues. Since I assume that missing issues are archived issues, it's not a problem.
• I do not know when the store was dumped prior to pod restart. Unfortunately, we were not shipping logs from that pod. As the logs show, the store was restored within ~5 seconds. That's about as much as I know.
• We run in a prod environment.
• There were a whole bunch of skipping, as up-to-date messages in the log during the background sync, which seems to indicate that the store was restored at startup correctly.

We did save a copy of the storedump around restart. I'll see if I can share the store dump. I may not be able to, but I'll update within the week once I look through it.

[nikku]

Regarding background synchronization of issues: Old issues ("archived") are automatically cleaned up after some days (cf. CONFIG). So what you're seeing over there is expected behavior.

Looking at the logs I can verify what you pointed out regarding start, restore and background-sync:

• App started at 21:06:29

{"name":"wuffle:run","hostname":"wuffle-68d756bd5b-2mprw","pid":1,"level":30,"msg":"Starting Wuffle","time":"2021-03-08T21:06:29.282Z","v":0}

• As intended, restore happened as app starts 21:06:34

  {"name":"wuffle:dump-store-s3","hostname":"wuffle-68d756bd5b-2mprw","pid":1,"level":30,"Bucket":"REDACTED","Key":"storedump.json","t":5244,"msg":"restored","time":"2021-03-08T21:06:34.644Z","v":0}

• Background sync starts 15 minutes later, on 21:20:59

{"name":"wuffle:background-sync","hostname":"wuffle-68d756bd5b-2mprw","pid":1,"level":30,"msg":"start","time":"2021-03-08T21:20:59.728Z","v":0}

Background synchronization is done every hour and the timer is persisted across restarts.

:arrow_right: As we see the sync happen 15 minutes after start already, I conclude that restore worked and restored the last sync time.

I see no circumstance in which one bit of information is restored successfully and the other one (issues) is not. Are you sure you were properly logged-in into the board after restore? Sessions as well as a number of internal user-access caches do not persist.

[piyushk]

I can confirm that I was properly logged into the board after restore. I see session requests in the log. I also did a hard refresh on my browser. I also agree that the restore happened correctly.

I'll try and reproduce this bug at a time it will be less disruptive for users and try and debug it further. Since there isn't an obvious answer right now, please feel free to close the issue. I'll report back if I find something concrete.

[nikku]

Closing this issue as you suggested. Happy to re-open if you can reproduce what you're seeing.

[piyushk]

We recently bumped our pod again, and cards disappeared for 10 minutes. This time they appeared before the next background sync happened, so my original issue report was not correct.