Closed Bug 854975 Opened 11 years ago Closed 11 years ago

Intermittent TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul,test_install_app.xul | install time is after install() call OR install time is before install success

Categories

(Core Graveyard :: DOM: Apps, defect)

Product:
Core Graveyard
Component:
DOM: Apps
Version:
22 Branch
Platform:
x86_64
Windows 8
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox24 fixed, firefox25 fixed, firefox26 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla26
Tracking Flags:
Tracking Status
firefox24 --- fixed
firefox25 --- fixed
firefox26 --- fixed

People

(Reporter: mbrubeck, Assigned: marco)

References

Details

(Keywords: intermittent-failure, Whiteboard: [apps-automation:P3])

Attachments

(2 files, 1 obsolete file)

print_installtimes_test
1.44 KB, patch
fabrice
: review+
marco
: checkin+
Details | Diff | Splinter Review
Patch
3.12 KB, patch
marco
: review+
Details | Diff | Splinter Review 
https://tbpl.mozilla.org/php/getParsedLog.php?id=21113131&tree=Firefox
WINNT 6.2 mozilla-central opt test mochitest-other on 2013-03-26 09:18:20 PDT for push 8d09f003e087

slave: t-w864-ix-026

09:24:47     INFO -  10182 INFO TEST-START | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul
09:24:47     INFO -  10183 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | getInstalled() returns nothing
09:24:48     INFO -  10184 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | origin
09:24:48     INFO -  10185 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | install origin
09:24:48     INFO -  10186 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | install time is after install() call
09:24:48     INFO -  10187 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | install time is before install success
09:24:48     INFO -  10188 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | manifest URL
09:24:48     INFO -  10189 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | manifest.name
09:24:48     INFO -  10190 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | manifest.installs_allowed_from
09:24:48     INFO -  10191 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | getInstalled() returns app identical to install()
09:24:48     INFO -  10192 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | getSelf() returns nothing (different origin)
09:24:48     INFO -  -- webapps.js uninstall http://test/chrome/dom/tests/mochitest/webapps/apps/launch_paths.webapp
09:24:48     INFO -  -- webapps.js uninstall http://test/chrome/dom/tests/mochitest/webapps/apps/launch_paths.webapp
09:24:48     INFO -  10193 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | getInstalled() returns nothing again after uninstall
09:24:48     INFO -  10194 INFO TEST-END | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | finished in 185ms
Probably has the same root cause as bug 856356.
See Also: → 856356
Whiteboard: [apps-automation]
Whiteboard: [apps-automation] → [apps-automation:P3]
Summary: Intermittent TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | install time is after install() call → Intermittent TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | install time is after install() call OR install time is before install success
This could help us understand what's going on.
Attachment #787062 - Flags: review?(fabrice)
Summary: Intermittent TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | install time is after install() call OR install time is before install success → Intermittent TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul,test_install_app.xul | install time is after install() call OR install time is before install success
The problem here could be that Date.now() is not precise enough, it's even not guaranteed to be monotonic. On my PC the difference between app.installTime and installSuccess is just 55 ms.
Comment on attachment 787062 [details] [diff] [review]
print_installtimes_test

Review of attachment 787062 [details] [diff] [review]:
-----------------------------------------------------------------

That will not fix this bug, so keep open after landing that.
Attachment #787062 - Flags: review?(fabrice) → review+
Keywords: checkin-needed
Whiteboard: [apps-automation:P3] → [apps-automation:P3][leave open]
I think fixing this bug is just impossible, because of Date.now().
Why is "test_install_app.xul" mentioned in the bug summary?  All sixteen of the failures logged above are in test_launch_paths.xul.  Can we improve the logging in test_launch_paths.xul to help figure out what is causing this?

If it turns out to a problem with the system clock being non-monotonic, we could see if releng can investigate and fix the cause of that.
(In reply to Matt Brubeck (:mbrubeck) from comment #24)
> Why is "test_install_app.xul" mentioned in the bug summary?  All sixteen of
> the failures logged above are in test_launch_paths.xul.  Can we improve the
> logging in test_launch_paths.xul to help figure out what is causing this?

The installTime test is exactly the same between test_launch_path.xul and test_install_app.xul, this is why I duped bug 879210 to this bug.

See bug 879210 comment 5 for a more meaningful error log.
(In reply to Marco Castelluccio [:marco] from comment #25)
> The installTime test is exactly the same between test_launch_path.xul and
> test_install_app.xul, this is why I duped bug 879210 to this bug.
> 
> See bug 879210 comment 5 for a more meaningful error log.

Ah, thanks! I missed that.

(In reply to TinderboxPushlog Robot from comment #5)
> 10456 ERROR TEST-UNEXPECTED-FAIL |
> chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/
> test_install_app.xul | install time (1376091000066) is before install
> success (1376091000058)

So, assuming the code is correct (I think it is), the clock on this slave went backwards by at least 8 ms, presumably from NTP or similar software adjusting for skew.  Maybe we should change the test to use fuzzy comparisons, e.g. "app.installTime <= installSuccess + 1000" assuming that the clock will not jump by more that that, or at least won't do it nearly as often.  Then we are still testing that installTime is basically correct, without exposing ourselve as much to the vagaries of Date.now().
(In reply to Matt Brubeck (:mbrubeck) from comment #27)
> So, assuming the code is correct (I think it is), the clock on this slave
> went backwards by at least 8 ms, presumably from NTP or similar software
> adjusting for skew.  Maybe we should change the test to use fuzzy
> comparisons, e.g. "app.installTime <= installSuccess + 1000" assuming that
> the clock will not jump by more that that, or at least won't do it nearly as
> often.  Then we are still testing that installTime is basically correct,
> without exposing ourselve as much to the vagaries of Date.now().

Marco, can you try this?
Flags: needinfo?(mcastelluccio)
Attached patch Patch (obsolete) — — Splinter Review 

        Attachment #795597 -
        Flags: review?(fabrice)
Flags: needinfo?(mcastelluccio)

    
  

        Attachment #787062 -
        Flags: checkin+

    
  
Whiteboard: [apps-automation:P3][leave open] → [apps-automation:P3]
Assignee: nobody → mcastelluccio

          status-firefox24:
          --- → affected

          status-firefox25:
          --- → affected

          status-firefox26:
          --- → affected

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
  
Comment on attachment 795597 [details] [diff] [review]
Patch

Review of attachment 795597 [details] [diff] [review]:
-----------------------------------------------------------------

In both files: make 1000 a constant and not a literal, and I think it's too much based on the logs we now get. I'd like to try with 250 instead.

r=me with this changes

        Attachment #795597 -
        Flags: review?(fabrice) → review+

    
    

    
  

      
      
      
      

        Attached patch
          
          
        Patch
        — 
          — Splinter Review
      

    


  
Carrying r+.

        Attachment #795597 -
        Attachment is obsolete: true

        Attachment #796204 -
        Flags: review+

    
  
Keywords: checkin-needed

    
    

    
  
A reminder - your commit messages should be describing what the patch is actually doing, not just restating the bug title.
https://hg.mozilla.org/integration/fx-team/rev/f975e58efdbc
Keywords: checkin-needed
Whiteboard: [apps-automation:P3] → [apps-automation:P3][fixed-in-fx-team]

    
    

    
  
https://hg.mozilla.org/mozilla-central/rev/f975e58efdbc
Status: NEW → RESOLVED
Closed: 11 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Whiteboard: [apps-automation:P3][fixed-in-fx-team] → [apps-automation:P3]
Target Milestone: --- → mozilla26

    
  
Product: Core → Core Graveyard

          You need to log in
          before you can comment on or make changes to this bug.
        






  

    
  







  

    

      
Attachment

      

      
      
      
      
    

    

      

        

          

            
General

            

              Creator: 



            

            
Created: 

            
Updated: 

            
Size: