Over at http://drupal.org/node/208687, Earl and myself diagnosed a rather nasty case that's been the source of much confusion and support noise.

The basic situation is that update(_status).module caches available update data that's usually valid for 24 hours. When a new core release goes out (especially with an SA), people download the new version, which updates their .info files (e.g. to version = 6.0-rc2). However, at this point, update_requirements() is utterly confused. It's still reusing the (now stale) available update data that thinks the latest core release is 6.0-rc1. Much badness ensues, since it doesn't recognize the current release, and it recommends people downgrade to 6.0-rc1.

The solution is rather simple (see attached patch). When we're generating our list of existing projects and inspecting the .info files, we also record the .info file's modification time. As we're processing our list to group modules into the projects they belong to, we always ensure we've got the mtime for the most recently modified .info file as the one we use overall for the project.

Then, all we have to do is in update_get_available(), the function that's used to figure out if we have cached data that we can reuse, or if we need to refresh, we need to compare the modification time on all the .info files we're using to make sure none of them have been modified more recently than the last time we checked for available updates.

This all works beautifully under my testing.

Of course, I'll admit that this only further increases the expense of update_requirements(), which is the source of concern over at http://drupal.org/node/200028. However, at this point, my first priority is correct behavior. We can consider if/how to optimize and attempt to cache things over at #200028, but I'd like to first ensure that update.module handles this case correctly.

p.s. Note: we only conditionally compute and stash the mtime for the info files, so that, for example, if cvs_deploy already filled in that value from hook_system_info_alter(), we don't clobber it. cvs_deploy will definitely want to do this, see http://drupal.org/node/158526 for more.

Support from Acquia helps fund testing for Drupal Acquia logo

Comments

dww’s picture

Some further comments:

A) To prevent this bug from hitting us during the RC2 to RC3 upgrade, perhaps we should add an update_update_6000() to clear the available update cache?

B) Furthermore, perhaps we should *always* invalidate the available update cache when update.php runs?

Notes on how to test this patch:
- add a drupal_set_message() right after the line that does this: $needs_refresh = TRUE;
- manually check for available updates
- touch modules/node/node.info (or whatever core .info files you want to test).
- visit admin/reports/status or admin/reports/available, but don't click "Check manually". you should see your drupal_set_message. actually, really, after you touch the file, you should see the message on any /admin/* page load, due to update_requirements() firing.

dww’s picture

(A) and (B) from #1 are both resolved cleanly by http://drupal.org/node/210141.

I'm really tempted to mark this critical. Whenever a new release comes out, update.module reports bogus things and it generates a lot of support noise. However, I'm trying to be a little disciplined about "critical", since it doesn't completely break everyone's sites, and it does resolve itself after 24 hours or if the user clicks "Check manually". That said, it's kind of discouraging that after days of soliciting reviews and tests in IRC and via other means, I'm the only one participating in this thread. :(

Dries’s picture

FYI, I've committed http://drupal.org/node/210141. As people have to run update.php after an upgrade, this should be a non-issue now?

dww’s picture

Sadly, no. Not every new release requires a schema change. update.php only flushes all caches if it completes actual work. And, even in the case where there is a schema change, the status report will warn them their site is missing a schema update *and* tell them weird bogus things like their (newly installed) version of core is insecure and they should downgrade. Given these mixed messages, I highly doubt that everyone will get this right and assume that running update.php as directed will clean up both problems.

Really, #210141 was icing on the cake and an extra precaution to ensure that even if somehow something weird went wrong with this mtime logic (e.g. when they untar the release, their filesystem sets the mtime on the .info files to the timestamps in the tarball, not the time the file was overwritten during the untar), that we'd still flush the cache on cases where they *do* manage to run update.php successfully. This patch is still very much necessary (and, I just checked, still applies cleanly).

Thanks,
-Derek

killes@www.drop.org’s picture

I am not sure I understand all this. But I have a bad feeling about relying on server time settings.

However, if I read the code correctly, we actually compare two timestams onthe same server so it should be ok.

dww’s picture

Status: Needs review » Needs work

@killes: Exactly. We're just making sure that the local server's idea of the mtime on each .info file is older than that same server's idea of the timestamp when we last checked for available updates. If we *also* checked the "datestamp" field in the .info files (added by the packaging script), we'd run into troubles of time skew and mismatch, which is why I think that just looking at the mtime is the safest approach.

As I mentioned above, the only possible case this wouldn't work perfectly is if some evil filesystem and/or tar implementation decided to set the mtime on untar'ed files to be timestamp of the file as recorded in the tarball itself, as opposed to the timestamp of when the file was untar'ed.

Since I had a bad feeling about this, I just tested it, and lo, tar is exactly as insane as I thought it might be. :( When you untar something, it goes out of its way to set the mtime back to the mtime of the file as recorded in the tarball. Ugh. Luckily, there's a trivial solution: instead of mtime and filemtime(), we need to use ctime and filectime():

http://us2.php.net/manual/en/function.filectime.php

When you untar an older tarball, the mtime is set to the timestamp in the tarball, but the ctime is correctly set to the time you actually did the untar operation. So, we're golden.

I'll reroll momentarily, stay tuned...

dww’s picture

Status: Needs work » Needs review
FileSize
4.21 KB

Like so. Tested carefully, this time with unpacking tarballs from d.o and making sure things all worked as expected. Even if I forced my test site into thinking it had checked for updates newer than the mtime of the files from the tarball, it still knew it had stale info when the ctimes were newer. Yay. I'm quite pleased with this patch now. I'd set it to RTBC myself, but I'll hold off and let other reviewers and testers have their say.

dww’s picture

FileSize
4.54 KB

A few of the code comments still referred to "modification time" which is misleading. This patch fixes that, and adds a note justifying the use of filectime() instead of filemtime() for this.

webchick’s picture

Priority: Normal » Critical

IMO this is critical. We'll see a lot of support requests about this otherwise, and a lot of ire from the community about false alarms and what-not. It's imperative that people can trust update.module, lest they get lax in following through on security announcements, thinking we're just crying wolf.

After many, many (many!) minutes of futzing around ;) I finally got update.module reading from http://localhost/release-history, following dww's very helpful documentation here: http://drupal.org/node/210984

Incidentally, the slightly obtuse "Unable to fetch any information about available new releases and updates." error that blocked me for 20 minutes or so was because I had copy/pasted the entirety of http://updates.drupal.org/release-history/devel/6.x to localhost, and it ended up with two XML headers. Since this should never happen "in the wild" I didn't file a bug about it, but just FYI while anyone else is testing this patch.

Anyway! Now on to testing it.

webchick’s picture

Hm, shoot. :( I am unable to reproduce the error dww's talking about without the patch. Please note that this should not be interpreted as "the error doesn't exist" but more "I am probably doing something stupid." :)

My release-history stuff is all setup... I changed my local devel-6.x.xml file to say that 6.1 was the latest release, I ran the update manually and it screamed at me about the security error, I manually updated the .info file to say 6.1, but the next time I reloaded ?q=admin, the message was gone. :( So I assume it's one variable somewhere I'm not changing.

dww, if you're around tomorrow on IRC at all, and are able to ping me and walk me through things, I can test this again. (or post back here)

dww’s picture

@webchick: To reproduce the error:

1. In devel-6.x.xml, put the following official releases:

6.x-1.1 (security update)
6.x-1.0

2. In your devel.info, say you're running 6.x-1.1

3. Check for available updates (everything should be cool).

4. tell devel-6.x.xml about 6.x-1.2 (regular release)

5. [introduce the error] edit your devel.info file to say you're running 6.x-1.2.

at this point, do *NOT* save your modules page, nor "Check manually".

Without the patch, it should tell you that devel is missing the 6.x-1.1 security update, and that 6.x-1.1 is recommended.

With the patch, it should refresh your available update data and tell you you're up to date.

Make sense?

-Derek

dww’s picture

To translate the above steps into what actually happens in the wild with core releases...

Here's what's currently in drupal-6.x.xml:

6.0-rc2 (security update)
6.0-rc1 (regular release)
...

Sites are running 6.0-rc2, have checked for updates, and everything is cool.

- 6.0-rc3 is released
- drupal-6.x.xml now says 6.0-rc3 is the latest release but update.module hasn't refreshed yet via cron
- announcement goes out to the front page (and/or, if it's a security release, via the security RSS/announcement list)
- people upgrade their site to the 6.0-rc3 tarball.

At this point, if this patch isn't committed, the status report will tell people that they're currently running 6.0-rc3, they're missing a security update, and they should downgrade to 6.0-rc2 immediately. This is because they'll have the cached copy of drupal-6.x.xml from the last time they checked, before 6.0-rc3 was in there. If we commit this patch, then at this point, update.module will realize the .info files are newer than the last time it checked for updates, will fetch the valid copy of drupal-6.x.xml that includes 6.0-rc3, and all will be happy.

webchick’s picture

Status: Needs review » Reviewed & tested by the community

Ok, I think I put this through the paces. After dww's helpful comment in #11, I fixed the problem I was having that prevented me from testing this. I confirmed that before the patch, I would receive an out of date error even after I had "updated" my release to the newest version. After the patch, it successfully informed update_status that I was ok.

I also tried throwing funky crap at it like suddenly upgrading my version 12 versions higher, or suddenly downgrading it two versions previous. In all cases, I was informed of the correct recommended release immediately (and the security release in devel 6.x-1.0).

Coupled with dww's extensive testing, I believe this is RTBC.

Gábor Hojtsy’s picture

Status: Reviewed & tested by the community » Fixed

Thanks, committed.

dww’s picture

Note: cvs_deploy users are safe if they update cvs_deploy to the latest in HEAD again. See http://drupal.org/node/211232.

Anonymous’s picture

Status: Fixed » Closed (fixed)

Automatically closed -- issue fixed for two weeks with no activity.