73029 - new cache time problems, reload sometimes broken

Status: VERIFIED FIXED

(Core :: Networking: HTTP, defect)

Description

[NilsE]

System: RH 6.2
CVS pull build ID: 2001032211 (UTC)
Mozilla/5.0 (X11; U; Linux 2.2.18pre11-va1.8 i686; en-US; 0.8.1)

Description:

On revisiting the above URL, Mozilla doesn't update the frequently changing
page. <Reload> sometimes work, <shift>+<Reload> always works. (Therefore, this
is not a duplicate of bug 72983).

It could be a timing problem as the about:cache entry has wrong times:

           Key: http://www.heise.de/newsticker/
        Client: HTTP
     Data size: 138327 Bytes
   Fetch count: 11
  Last Fetched: Wed 21 Mar 2001 07:13:17 PM CET
 Last Modified: Thu 22 Mar 2001 06:40:38 PM CET
       Expires: Thu 22 Mar 2001 06:38:37 PM CET
  Stream based: TRUE

"Last fetched" is wrong, it was several times reloaded today. "Last modified" is
even two minutes in the future! The key entry of about:cache is:

key:           http://www.heise.de/newsticker/
request-time:  Thu 22 Mar 2001 06:38:37 PM CET
response-time: Thu 22 Mar 2001 06:38:37 PM CET
http-headers:

HTTP/1.1 200 OK
date: Thu, 22 Mar 2001 17:38:36 GMT
server: Apache/1.3.12 (Unix) mod_oas/4.64 mod_fastcgi/2.2.4 AuthMySQL/2.23
content-type: text/html

Why is "response time" != "Last fetched"?

Besides, I see lots of 

###!!! ASSERTION: bogus request time: 'now >= requestTime', file
nsHTTPChannel.cpp, line 978
###!!! Break: at file nsHTTPChannel.cpp, line 978

errors on the console.

Expected:
Page should be reloaded/refreshed on revisit as it expires immediately.

Observed: 
Page does not refresh on revisit, <shift>+<reload> is necessary.

Comment 1

[gordon]

reassigning to me.  Might be cache or http.

Comment 2

[Darin Fisher]

last fetched means last time fetched from the cache.
response time is the time that the response was received from the server.

Comment 3

[Daniel Bratell]

Confirming and changing platform to all. I see this on win32 also. My favorite
URL is the bonsai last checked in page:
http://bugzilla.mozilla.org/buglist.cgi?bug_status=UNCONFIRMED&bug_status=NEW&bug_status=ASSIGNED&bug_status=REOPENED&email1=&emailtype1=substring&emailassigned_to1=1&email2=&emailtype2=substring&emailreporter2=1&bugidtype=include&bug_id=&changedin=&votes=&chfieldfrom=&chfieldto=Now&chfieldvalue=&component=Networking%3A+Cache&short_desc=&short_desc_type=substring&long_desc=&long_desc_type=substring&bug_file_loc=&bug_file_loc_type=substring&status_whiteboard=&status_whiteboard_type=substring&keywords=&keywords_type=anywords&field0-0-0=noop&type0-0-0=noop&value0-0-0=&cmdtype=doit&newqueryname=&order=Reuse+same+sort+as+last+time

Comment 4

[Asko Tontti]

dogfood?

Comment 5

[:deanis74]

Big time!

Comment 6

[Darin Fisher]

-> myself

Comment 7

[Darin Fisher]

reporter: setting cache validation from "once-per-session" to "always" should
fix the problem... please verify.  thx!

Comment 8

[Darin Fisher]

*** Bug 73304 has been marked as a duplicate of this bug. ***

Comment 9

[Darin Fisher]

reporter: please delete your NewCache directory from your profile directory.

I suspect that the recent change to make the disk cache store using big endian
byte ordering resulted in some erroneous disk cache entries for you.

marking INVALID... please reopen if deleting the NewCache directory doesn't
fix the problem.

Comment 10

[NilsE]

Bug not yet reopened although problem partly persists. 

I've frequently erased cache dirs because of switching between new and old
cache. Switching cache policy to "always" doesn't remove the problem. Today's
builds (both, my CVS depend build and nightly build 2001032621) don't refresh
the expired page on revisit, but now do so on simple <reload>. Insofar, the
situation today is better and is now equal to NS 4.76.

Here's an about:cache entry (taken at 01:14 pm CEST) from the above nightly
build, showing and outdated page:

           Key: http://www.heise.de/newsticker/
        Client: HTTP
     Data size: 58704 Bytes
   Fetch count: 7
  Last Fetched: Tue 27 Mar 2001 12:43:42 PM CEST
 Last Modified: Tue 27 Mar 2001 01:14:03 PM CEST
       Expires: Tue 27 Mar 2001 12:43:42 PM CEST
  Stream based: TRUE


After each revisit, the "Last Modified" becomes the current time. Now I do a
simple <reload>, the page gets updated correctly, the new entry looks like this:

           Key: http://www.heise.de/newsticker/
        Client: HTTP
     Data size: 118472 Bytes
   Fetch count: 11
  Last Fetched: Tue 27 Mar 2001 12:43:42 PM CEST
 Last Modified: Tue 27 Mar 2001 01:17:46 PM CEST
       Expires: Tue 27 Mar 2001 01:17:45 PM CEST
  Stream based: TRUE

Why didn't "Last Fetched" change? The page itself did change. Am I right in
expecting that a simple revisit should have updated the page? 

BTW, the assertions are still flooding my console. This hasn't changed.

Comment 11

[Ferdinand]

Marking 73304 a dup of this bug and then marking this bug invalid is wrong...
the problem described in 73304 (and mentioned aside here) persists (win32 debug
cvs20010325) and is very annoying since i get a popup at every assertion. The
assertion seems to happen for every POST or GET request, so i usually see
several per page.

Comment 12

[Darin Fisher]

i'm not able to reproduce this on linux... wonder if it windows only?!?  hmm...
REOPENING to investigate.

Comment 13

[NilsE]

Attachment: stack trace from (now >= requestTime) assertion in RedHat 6.2

Comment 14

[NilsE]

darin: no, I observe the assertion in RedHat 6.2. Stack trace included above. I
physically erased the cache and mozilla (CVS pull from 03/27, using 
--enable-crash-on-assert) crashed on loading the startup page. So with an empty
cache, the problem might not be connected to the new cache, but rather http.
[But this bug is shifting its focus away from the original cache topic anyway].

Any chance of an answer to the questions in my comment from 03/27 ? 'Cause if
I'm wrong there, the cache topic bug can be closed and only this assertion thing
remains.

Comment 15

[Darin Fisher]

nils: gordon has a bug tracking the "exuberant touching" of lastModified.  I'm
not convinced that that would explain the assertion.  BTW: thanks for the stack
trace!

Comment 16

[NilsE]

It does not. Gordon checked in the fixes for bug 73099, but the assertion
remains. What else can I do to provide more info?

Comment 17

[Darin Fisher]

reporter: one thing you could do is check about:cache to see what it says
about the corresponding cache entry... perhaps there is no cache entry, or
perhaps the request-time is simply not set.  i'm having a difficult time
reproducing this problem... makes it hard to know/guess what could be wrong.

Comment 18

[Ferdinand]

For me this assertion happens with uncached files.

Comment 19

[NilsE]

I think I found the assertion-bug (temporary patch will be attached).

Problem source:

The cache needs to store several "time stamps" for each entry,
e.g. request time, expiration time. On Unix, time is internally
represented as an integer. Mozilla converts it to a time string such as
"Mon 02 Apr 2001 09:15:55 PM CEST". To calculate differences between
times, the time string is parsed and converted back to int. The parser
is located at
http://lxr.mozilla.org/seamonkey/source/nsprpub/pr/src/misc/prtime.c#939

and fails to recognize some timezones. In such a case, the returned int
is bogus and calculations using it may well trigger our assertion.

Problem description:

In my case, CEST (central european summer time) was missing. The only
timezones currently supported are:

PST, PDT, MST, MDT, CST, CDT, EST, EDT, AST, NST, GMT, BST, MET, EET,
JST

Unfortunatly, the world is bigger than this.


Quick fix:

I will attach a patch that adds support for CET, CEST and MEST. People
in timezones not covered will still experience the assertion and a
by-and-large unusable cache.

Possible general fix:

- Use some external library to parse time strings (such as the one used
in Linux' date(1) utility) to avoid missing timezones and reinventing
the wheel.

OR

- Use the integer to store the time. For printing (such as in about:cache),
the conversion to string exists and seems to work. This way you don't
need string-to-int conversion and avoid the error-prone parser. But I
don't know how this translates to non-Unix OSes.

Botton line:

Fixing this assertion seems to make the new cache at least partially
usable again [the "WARNING: CheckCache failed... what should I do?, file
nsHTTPChannel.cpp, line 2089" is still there ...]. For Mozilla's
international "audience" a general fix seems (at least to me) *very*
necessary.

[Sorry for the length, but I wanted to make sure that I am understood.]

Comment 20

[NilsE]

Attachment: Patch for CEST-support in mozilla/nsprpub/pr/src/misc/prtime.c

Comment 21

[Darin Fisher]

excellent find!

BTW: without a good string->int parser, we'll never be able to correctly impl
the HTTP protocol, which uses strings for dates.  so, i think that fixing
NSPR/using-a-different-date-parser is *absolutely* essential.

Comment 22

[Darin Fisher]

we need to get some NSPR folks involved with this... i wonder if more recent
versions of NSPR support string->int conversion better?

Comment 23

[Darin Fisher]

i stand corrected... HTTP servers send GMT (or otherwise standardized) date
stamps, so we definitely can implement HTTP without a working generic
catch-all-timezones date_string -> integer_seconds parser.

the easiest fix for this problem is to fix HTTP to not use localized times.

Comment 24

[NilsE]

As for the status of this bug report: I'm not sure if the original <reload>
problem is still there/would be fixed by the timezone thing (my CVS pulls are
quite shaky recently, lots of warnings and crashes, can't really test "normal"
cache behaviour - I'll wait a few more days).

darin: I understand that getting all timezones covered by the parser is a
non-trivial patch that may take some time. May I suggest that for the meantime
my patch be included as this would at least be a relief for european Mozilla
users (which seem to be quite a few)?

Comment 25

[Daniel Bratell]

I agree completely with Nils. It's no fun clicking away hundreds of assertion
dialogs during a session just because I live in a non american timezone. As soon
as we can get the temporary european fix in, the better. 

Upped severity. Maybe it should be even higher.

Comment 26

[Darin Fisher]

i understand your concern about getting this fixed ASAP, but getting approval
to change/fix NSPR is probably more time consuming than making the correct
fix to the problem in HTTP.  i'll attach a real fix soon.

Comment 27

[Darin Fisher]

Attachment: fixes the problem in http

Comment 28

[Darin Fisher]

my patch removes "request-time" and "response-time" from the cache meta data.
they didn't need to be there!

Comment 29

[NilsE]

Thanks for the patch, Darin. I've applied it and it works. Great! Get it in :-)

As for PR_ParseTimeString - could you still tell the NSPR people that it's
broken? LXR tells me it's being referenced in 19 files, of which
nsHTTPChannel.cpp is/was only one. Sooner or later the problem is gonna hurt
someone else. Or should I simply file a new bug about it? ;-)

Comment 30

[Darin Fisher]

Nils: please file a new bug on NSPR.. thx!

Comment 31

[Peter "jag" Annema]

Nice clean-up! r=jag

Comment 32

[Gagan]

r=gagan

Comment 33

[Scott MacGregor]

sr=mscott

Comment 34

[Darin Fisher]

fix checked in.

Comment 35

[benc]

+verifyme - not sure how this is supposed to look now.

Comment 36

[Tom Everingham]

verified 7/10 builds all platforms