Page MenuHomePhabricator
Create Task
Maniphest T13152

Storage on `secure` was filled by binlogs from looping (?) rebuild-identities script
Closed, ResolvedPublic
Actions

Description

The /core/data volume on secure001 filled, which paused MySQL.

It was filled by an unusual number of binlogs. We have binlogs set to GC, but MySQL generated approximately 100GB of them in a day or so. The GC config seems correct, the fill rate was just unusually high.

I remedied the issue by:

  • Connecting to the replica on secure002.
  • Making sure replication was caught up (with SHOW SLAVE STATUS) and verifying that the current binlog on the replica was a recent binlog.
  • Removing most of the older binlogs with rm.
  • Restarting mysql with sudo service mysql restart.
  • (The replica was being a little slow to resume (via SHOW SLAVE STATUS) so I also did a STOP SLAVE; START SLAVE; on the replica.)

Using mysqlbinlog <log>, it looks like these logs are mostly updates from the rebuild-identities script. My guess is that it's running in a loop and that I have a bug in PhabricatorQueryIterator.

Revisions and Commits

rP Phabricator
D19479rP340150a60600 (stable) Fix loop in QueryIterator when row count is an exact multiple of page…
D19479rP13dd3014a758 Fix loop in QueryIterator when row count is an exact multiple of page size

Related Objects

Event Timeline

epriestley triaged this task as Normal priority.Jun 7 2018, 12:57 PM
epriestley created this task.
Herald added a subscriber: eadler. · View Herald TranscriptJun 7 2018, 12:57 PM
epriestley mentioned this in T13151: Plans: 2018 Week 23 - Week 30 Bonus Content.Jun 7 2018, 3:38 PM
epriestley added a comment.Jun 7 2018, 3:45 PM

My guess is that it's running in a loop and that I have a bug in PhabricatorQueryIterator.

I'm not immediately able to reproduce this on secure. I ran bin/repository rebuild-identities --all --trace and it finished in about a minute.

epriestley added a comment.Jun 7 2018, 3:52 PM

I did catch a rebuild-identities script eating 66% of CPU this morning, so I'm pretty sure there's a problem there somewhere, but it died at some point (likely when I restarted MySQL?) so there isn't much left in terms of forensic evidence.

epriestley added a comment.Jun 7 2018, 4:02 PM

A sub-issue here is that rebuild-identities (and, likewise, CommitMessageParserWorker) uses getAuthorName() from the CommitData.

This may not be the original string: in particular, it has been converted to utf8 and truncated to 255 characters.

For some data on secure, it is incomplete (probably because of different behavior in older versions of Phabricator), e.g. jack instead of jack <jack@jacksdomain.com>.

It may also be mangled somewhat by DiffusionCommitRef, which splits the author apart rather than preserving it completely faithfully.

Under the hood, DiffusionCommitRef is (possibly) transported in JSON which can not transport non-utf8 values. Fixing this is probably out of scope until wire encodings in T5955, though.

epriestley added a comment.Jun 7 2018, 4:06 PM

I'm going to try truncate + rebuild and see if this is a first-run issue, maybe?

epriestley added a comment.Jun 7 2018, 4:13 PM

That went through totally clean.

Upshot:

  • I'm reasonably suspicious (?) that PhabricatorQueryIterator is maybe (?) broken somehow and can get stuck in a loop (?).
  • I have absolutely no clue how to reproduce it.

@amckinley, any guesses what you might have done differently to get rebuild-identities into a stuck state? Can you try again and see if it sticks again?

I assume you didn't, like, run while true; do rebuild-identities; done, and ~/.bash_history isn't especially illuminating.

epriestley added a revision: D19479: Fix loop in QueryIterator when row count is an exact multiple of page size.Jun 7 2018, 7:14 PM
epriestley added a commit: rP13dd3014a758: Fix loop in QueryIterator when row count is an exact multiple of page size.Jun 7 2018, 8:17 PM
epriestley closed this task as Resolved.Jun 8 2018, 1:52 PM
epriestley claimed this task.
epriestley mentioned this in T12164: Put an indirection layer between author/committer strings and user accounts.

Pretty confident D19479 was the root cause here and we got unlucky (or lucky, to find the bug) by running with 37,000 commits exactly.

epriestley added a commit: rP340150a60600: (stable) Fix loop in QueryIterator when row count is an exact multiple of page….Jun 8 2018, 1:53 PM
epriestley mentioned this in D19484: Make re-running `rebuild-identities` a bit faster and add a little progress information.Jun 12 2018, 2:08 PM
epriestley mentioned this in rP1459fb303769: Make re-running `rebuild-identities` a bit faster and add a little progress….Jun 12 2018, 8:19 PM
epriestley mentioned this in rP38557b96c27e: (stable) Make re-running `rebuild-identities` a bit faster and add a little….
Phabricator · Built by Phacility