WIKI EDITS ARE BROKEN!! Users being shown & editing OUTDATED cached versions of documents

[seabelis]

Description

All changes: edits to editions or works, list creation, cover changes...are lost on save.

Relevant url?

all

Expectation

Changes should be saved.

Details
No error message, and all functionality seems to work at the time, but changes are lost on refresh.

Logged In
Crome Version 73.0.3683.86 (Official Build) (64-bit)
Win 7 Pro

[seabelis]

For some reason I have been able to make changes to this record alone. https://openlibrary.org/books/OL4723885M/Bunnicula

[tfmorris]

I had a quick look at this and for the author page that I edited, the edits were saved, but not rendered in the HTML, even after a hard refresh, so it seems likely that this is some kind of caching issue.

[tfmorris]

For the record that @seabelis edited (https://openlibrary.org/books/OL4723885M/Bunnicula) the new cover, subtitle, etc are rendered correctly, but none of the edits are listed in the edit history at the bottom of the page, although they are listed when you click through to the detailed history.

For the record I edited (https://openlibrary.org/books/OL4723885M/Bunnicula), the bad AKA remains and the edit also is not listed in the summary edit history, but, again, is shown on the detailed edit history page.

[seabelis]

And I was not able to add to a list, but was able to add to my reading log.

[mekarpeles]

I'm unable to reproduce -- I just edited https://openlibrary.org/books/OL4723885M/Bunnicula/edit and added an illustrator Alan Daniel and it shows up correctly on the html and in the history.

Is this still an issue?

[seabelis]

Yes, still an issue. That example was the one record I have been able to edit. All others I've tried, for this and other works, are still uneditable.

[stefanauss]

I'm also experiencing this. One example of a record i've been unable to save edit to is https://openlibrary.org/books/OL12320650M/LAN_Switching_and_Wireless_CCNA_Exploration_Companion_Guide_(2nd_Edition)_(Companion_Guide). This is also the case for the work it is linked to.

The thing is the edits do appear in the history but not rendered at all. Also when showing history, the radio button to select what to compare with the diff tool exclude the unrendered edit: the last and second to last rendered edits are pre-selected.

[seabelis]

Adding new editions is possible. Data added to the edit form beyond what is collected on the "Add new" form is saved and displayed as usual. Subsequent edits after that initial save are lost but shown in the detailed edit log.

[seabelis]

But I see edition count for the work is not updated nor is the new edition displayed on the edition list. This is the edition I added. https://openlibrary.org/books/OL26846444M/Educated

[mekarpeles]

I'm wondering if this is database or solr updater related

[seabelis]

I take it back. The subsequent edits to show and the edition now shows on the list of editions. Edition count is still incorrect.

[tfmorris]

It looks to me like it's rendering old versions. When I look at @stefanauss' example, after editing it, it's unchanged, but if I click on my edit in the history and view https://openlibrary.org/books/OL12320650M/LAN_Switching_and_Wireless_CCNA_Exploration_Companion_Guide_(2nd_Edition)_(Companion_Guide)?v=11 it includes my edits.

A perhaps related weirdness is when I click through to the detailed version history, it comes up with version 5 & 6 selected for the compare, indicating that for some reason it thinks that version 6 is the latest version.

[cdrini]

Since this is a break of previous functionality, let's see what changed recently.

• We had a deploy on April 9th (2 days before this issue): https://github.com/internetarchive/openlibrary/releases/tag/deploy-2019-04-09
  But judging by the diff, that seems unlikely to have caused this issue.

• we also had progress on Upgrade All Trusty Nodes to Ubuntu Latest #2036 (1 day before issue opened):

Prove provisioning a generic minimal xenail VM (e.g. of the ol-mem flavor) and add it to the ol cluster (e.g. as ol-mem4)

Could this be related, @mek ? Maybe ol-mem is misbehaving and serving outdated copies of the site? What changed exactly?

[tfmorris]

That's an interesting hypothesis. It also makes me wonder if the new ol-mem pool member could be related to the recent bursts of 5xx errors.

[mekarpeles]

@tfmorris that I don't feel super confident about as it feels like the problem as occurring before introducing ol-mem4

[cdrini]

Ok, we were discussing on slack, and @mekarpeles just closed the memcache in question. We want to bring it back in ~10min (because it slows the site); is anyone available now to confirm if it worked? https://openlibrary.org/books/OL12320650M/LAN_Switching_and_Wireless_CCNA_Exploration_Companion_Guide_(2nd_Edition)_(Companion_Guide) seems to be displaying correctly, but I forgot to check how it looked just before we took down the memcache 😭

[stefanauss]

Hi, I just checked. The title seems to reflect the last edit I did on this edition, so It seems to be actually working. Unfortunately I'm AFK and cannot check further.

[cdrini]

Thanks @stefanauss ! Ok, we need some harder proof that this is the true culprit, because this would be quite an annoying bug to fix. We're reinstating the memcache now. Please post links to any works/editions you see not updating properly! We'll do another takedown test later and use those to determine if that's what's causing the problem (assuming I actually remember to check them this time 😛).

[seabelis]

It looks like the edits I made earlier have caught up, but new edits are lost on this edition. https://openlibrary.org/books/OL26336755M/Bunnicula
The only one I've tried so far.

[seabelis]

Lost on this also. https://openlibrary.org/books/OL7729374M/Bunnicula

[cdrini]

More examples now that all my previous ones have been exhausted:

Link	Status
https://openlibrary.org/works/OL5960676W/Ethics_(and_other_liabilities)?m=history	wrong revision
https://openlibrary.org/books/OL3489849M/Little_sister?m=history	wrong revision
https://openlibrary.org/books/OL3026549M/Giacometti_a_biography?m=history	wrong revision

[cdrini]

Ahhh, thank you @stefanauss ! (Sorry for the lag; GitHub didn't show me your comment :P) That helps a ton; we can search a bit further back for what might have caused this issue.

[seabelis]

That's funny. I updated the title of https://openlibrary.org/works/OL15102237W/Bon%C3%ADcula and it is not reflected on the work record itself but the new title is shown on the list view:

[cdrini]

Status update:

• This issue is reproducible on our local dev environment; this should make finding the commit that caused it easier
• It's unrelated to the xenial changes
• This file describes how memcache invalidates/updates when an infobase edit occurs: openlibrary/olbase/events.py
  • On prod, we saw the "setting up infobase events for Open Library" log but neither the "Edited by" or "invalidating" logs
  • locally, all logs appeared at the right moment: local web log after editing an edition.txt. Note the log does display a save_many log which appears to be saving the wrong version (ctrl-f for revision" in the log file posted above).

Possible next steps:

• Try going back in git's history to determine the offending commit. See git bisect; we probably won't be able to fully automate the process, but it will help (maybe copying some CURL commands from the browser (with editing cookies) might let use fully automatically bisect this?)

[cdrini]

@seabelis You edit pretty regularly; what was the earliest date you noticed this issue?

[cdrini]

Alright, I've been testing backwards trying to find a commit where the error doesn't occur (so I could do a git bisect), and I've been able to find it all the way back to Dec 3, 2018 before stopping :/ I think that's too far back, so that makes me think my method is wrong. Here's my detailed methodology: https://gist.github.com/cdrini/9ee2c78da213b38262b02bbd9e35b1b4 ; @hornc does that look correct? Am I making any silly docker mistakes? @seabelis is it possible this issue could have been existing since then (or possibly even before then)?

[seabelis]

@cdrini I reported it immediately. Prior to that edits were generally working as expected. The only thing I did notice, and maybe this is unrelated, is that for about the two days prior the system was taking a bit longer to process changes at the work level. I don't mean that the edits were not immediately seen on the records themselves, but that the tags took a long time to (???: I have no word for this: when you add a tag, normally it takes about +/- 15 min. to be reflected on the tag's view or if the work's cover is updated, for that to be seen on the list view). Instead of 15 minutes this process was taking a day or more.

If this existed prior to a few days ago, it was infrequent and either got by me were passed off as my own mistakes. If it had been frequent, I'm confident I'd have noticed.

[LeadSongDog]

Further example, edit on an author page today:
https://openlibrary.org/authors/OL5867300A/Thom_McGuire?b=2&a=1&_compare=Compare&m=diff
is not reflected:

A similar edit on 10 April had no such problem:
https://openlibrary.org/authors/OL439448A?m=diff&b=2
and is properly shown at:
https://openlibrary.org/authors/OL439448A/Chuck_Murphy

[seabelis]

@cdrini Most editions I've made significant changes to are on this list. It seems like edits through the 10 April were fine. https://openlibrary.org/people/seabelis/lists/OL125878L/verified I'd estimate the slow-down of work tags/subjects populating that I mentioned above started approximately 5-8 April.

[LeadSongDog]

Hmm, https://openlibrary.org/authors/OL5867300A.json?v=2 shows the edits, but https://openlibrary.org/authors/OL5867300A.json does not. What's going wrong here?

[cdrini]

The (temp) fix is on dev, if folks want to help with testing! ( https://dev.openlibrary.org/ )

[seabelis]

@cdrini Covers still seem to be an issue.

[seabelis]

Edits to edition data is working normally. Cannot add to lists.

[seabelis]

Edition edits appear in the work edits log. This was not the case before.

[mekarpeles]

@hornc believes this issue has been resolved by reverting openlibrary.yml and infobase.yml on production to a state before ol-mem4 was added.

It's hypothesized perhaps infobase needed to be restarted on ol-home via supervisorctl after deploy (prior to restarting ol-web3 and ol-web4) in addition to restarting ol-mem*.

I'm very tentatively marking this as resolved and hoping doing so will cause others who are still noticing a problem to speak up here.

I'm opening a new issue for us to evaluate how many records / edits were affected during this time period (and what strategy we should take, e.g. potentially reverting edits during this time?

[tfmorris]

@hornc believes this issue has been resolved by reverting openlibrary.yml and infobase.yml on production to a state before ol-mem4 was added.

Is there more information on what the problematic change was so that we can avoid it in the future?

It's hypothesized perhaps infobase needed to be restarted on ol-home via supervisorctl after deploy (prior to restarting ol-web3 and ol-web4) in addition to restarting ol-mem*.

Can you (or @hornc) expand on this? Is the theory that different clients were operating with different memcached server lists, giving them inconsistent world views or something else?

I can definitely see a scenario where 2 cache servers with 50% of the cached entries each could continue to serve stale data to clients who thought that there were only two 2 servers if a new client started invalidating and updating 1/3 of its entries on a new third cache server (leaving the stale entries on the old server), but I'd like to confirm that that's what actually happened.