Uploaded image for project: 'Moodle'
  1. Moodle
  2. MDL-15030

Quiz time taken incorrect by huge margin - millions of days!

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Minor
    • Resolution: Duplicate
    • Affects Version/s: 1.8.2
    • Fix Version/s: None
    • Component/s: Quiz
    • Labels:
      None
    • Environment:
      Linux, Apache server
    • Database:
      MySQL
    • Affected Branches:
      MOODLE_18_STABLE

      Description

      Quiz displays millions of days for time taken in a quiz attempt. See attached screenshot.

        Gliffy Diagrams

        1. odd time screenshot.jpg
          273 kB
        2. screenshot-1.jpg
          208 kB
        3. time_taken.gif
          42 kB

          Issue Links

            Activity

            Hide
            timhunt Tim Hunt added a comment -

            I agree that is somewhat remarkable, but actually there is a logical explanation.

            That time interval is about 2^64 seconds.

            Now, in 64-bit two's compliment binary arithmetic, if you start with an a small negative number -x, and treat it as an unsigned int, you get 2^64-x.

            So what actually happened is that the start time for the attempt was after the stop time, which is, of course, impossible - and Moodle's format_time function must produce weird results like this when given a negative time.

            So, how did the start time before stop time situation arise?

            Do you, by any chance, use several load-balanced web servers? And if so, are their clocks properly synchronised?

            Show
            timhunt Tim Hunt added a comment - I agree that is somewhat remarkable, but actually there is a logical explanation. That time interval is about 2^64 seconds. Now, in 64-bit two's compliment binary arithmetic, if you start with an a small negative number -x, and treat it as an unsigned int, you get 2^64-x. So what actually happened is that the start time for the attempt was after the stop time, which is, of course, impossible - and Moodle's format_time function must produce weird results like this when given a negative time. So, how did the start time before stop time situation arise? Do you, by any chance, use several load-balanced web servers? And if so, are their clocks properly synchronised?
            Hide
            jhando Jason Hando added a comment -

            Hi Tim.... thanks for the explanation.

            not sure how it arose. It was a single anomaly inside a quiz attempted by several students. It only occurred, as you can see in the screenshot, for one attempt. Strange. It hasn't happened before, and may not happen again. Just thought it was worth reporting.

            The site in question does not use several load-balanced server... it is a school that has a single Moodle server running Linux, Apache, MySQL, PHP:

            Moodle 1.8.2 (2007021520)
            PHP Version 5.2.0
            MySQL 5.0.33

            Show
            jhando Jason Hando added a comment - Hi Tim.... thanks for the explanation. not sure how it arose. It was a single anomaly inside a quiz attempted by several students. It only occurred, as you can see in the screenshot, for one attempt. Strange. It hasn't happened before, and may not happen again. Just thought it was worth reporting. The site in question does not use several load-balanced server... it is a school that has a single Moodle server running Linux, Apache, MySQL, PHP: Moodle 1.8.2 (2007021520) PHP Version 5.2.0 MySQL 5.0.33
            Hide
            timhunt Tim Hunt added a comment -

            Well, it is certainly very weird. Since it is a single anomaly, and we don't know how it happened, I am going to resolve this bug as 'cannot reproduce' for now. However, if you (or anyone else) encounters this again, I'll reopen the bug and investigate further.

            Show
            timhunt Tim Hunt added a comment - Well, it is certainly very weird. Since it is a single anomaly, and we don't know how it happened, I am going to resolve this bug as 'cannot reproduce' for now. However, if you (or anyone else) encounters this again, I'll reopen the bug and investigate further.
            Hide
            jsilve1 Jeffrey Silverman added a comment -

            I have had a report of this same thing.

            Notes:

            1) Moodle Version 1.9.3+ ( $release = '1.9.3+ (Build: 20081216)'; // Human-friendly version name)

            2) The value in the Time Taken column is exactly the same as reported by op. Indication to me that this could be something along the lines of a divide by zero, or similar to getting dec 31, 1969 when timetamps are set to -1.

            3) We do use several webservers, load balanced. But I can confirm that they are very tightly time-synchronized, to the second.

            More details as I get 'em...

            Show
            jsilve1 Jeffrey Silverman added a comment - I have had a report of this same thing. Notes: 1) Moodle Version 1.9.3+ ( $release = '1.9.3+ (Build: 20081216)'; // Human-friendly version name) 2) The value in the Time Taken column is exactly the same as reported by op. Indication to me that this could be something along the lines of a divide by zero, or similar to getting dec 31, 1969 when timetamps are set to -1. 3) We do use several webservers, load balanced. But I can confirm that they are very tightly time-synchronized, to the second. More details as I get 'em...
            Hide
            timhunt Tim Hunt added a comment -

            The number of days is the number of days when you convert (2^32 - something small) seconds to days (or is it ^64?). That is why it is always the same, as long as something small is less than one day.

            If you look in the database, you will probably find that timefinish for this attempt is less than timestart.

            Anything you can do to work out how that happened would be greatly appreciated.

            I guess I could hack in some code to stop these funny times being displayed, but I would much rather leave the problem visible until we have tracked down the cause and fixed it.

            (If you want a quick fix, running

            UPDATE mdl_quiz_attempt SET timefinish = timestart + 1 WHERE timefinish < timestart;

            is probably safe, but backup first, and proceed very cautiously.)

            Show
            timhunt Tim Hunt added a comment - The number of days is the number of days when you convert (2^32 - something small) seconds to days (or is it ^64?). That is why it is always the same, as long as something small is less than one day. If you look in the database, you will probably find that timefinish for this attempt is less than timestart. Anything you can do to work out how that happened would be greatly appreciated. I guess I could hack in some code to stop these funny times being displayed, but I would much rather leave the problem visible until we have tracked down the cause and fixed it. (If you want a quick fix, running UPDATE mdl_quiz_attempt SET timefinish = timestart + 1 WHERE timefinish < timestart; is probably safe, but backup first, and proceed very cautiously.)
            Hide
            lholden Lori Davies added a comment -

            This issue has also been reported in v 1.9.7. I noticed that in both cases, the start and end time for the quiz was exactly the same at least down to the minute. Screenshot is attached.

            Show
            lholden Lori Davies added a comment - This issue has also been reported in v 1.9.7. I noticed that in both cases, the start and end time for the quiz was exactly the same at least down to the minute. Screenshot is attached.
            Hide
            drnyle Nyle Spoelstra added a comment -

            This is the "huge time taken" number. You see the start and stop times are almost the same. Also the time taken is the same (large) number in both cases.

            Show
            drnyle Nyle Spoelstra added a comment - This is the "huge time taken" number. You see the start and stop times are almost the same. Also the time taken is the same (large) number in both cases.
            Hide
            timhunt Tim Hunt added a comment -

            Ah, this is a duplicate of MDL-21111 which I fixed last week. (Well, chronologically speaking, MDL-21111 is a duplicate of this bug.

            So, update to 1.9.9+ or 1.9.10 when it is released.

            Show
            timhunt Tim Hunt added a comment - Ah, this is a duplicate of MDL-21111 which I fixed last week. (Well, chronologically speaking, MDL-21111 is a duplicate of this bug. So, update to 1.9.9+ or 1.9.10 when it is released.

              People

              • Votes:
                1 Vote for this issue
                Watchers:
                2 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: