Closed Bug 517938 Opened 15 years ago Closed 14 years ago

mochitest-plain: intermittent "Test timed out" in security/ssl/mixedcontent tests (test_bug329869.html, test_bug383369.html, test_bug455367.html, test_bug472986.html)

Categories

(Core Graveyard :: Security: UI, defect)

Product:
Core Graveyard
Component:
Security: UI
Platform:
x86
Linux
Type:
defect
Priority:
Not set
Severity:
major

Tracking

(status1.9.2 .2-fixed, status1.9.1 .9-fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla1.9.3a1
Tracking Flags:
Tracking Status
status1.9.2 --- .2-fixed
status1.9.1 --- .9-fixed

People

(Reporter: sgautherie, Assigned: mayhemer)

References

(
URL
)

Details

(Keywords: intermittent-failure, Whiteboard: [test which aborts the suite] )

Attachments

(4 files, 3 obsolete files)

ssltunnel logging v1.1
9.64 KB, patch
Details | Diff | Splinter Review
Additional logging 1
2.97 KB, patch
Details | Diff | Splinter Review
Yet more logging
3.03 KB, patch
Details | Diff | Splinter Review
Fix v1.1 [Checkin comment 69] [1.9.2 comment 73] [1.9.1 comment 74]
8.68 KB, patch
ted
: review+
beltzner
: approval1.9.2.2+
beltzner
: approval1.9.1.9+
Details | Diff | Splinter Review 
{
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1253553992.1253556989.24061.gz
Linux mozilla-central test mochitests on 2009/09/21 10:26:32

86091 INFO Running /tests/security/ssl/mixedcontent/test_bug329869.html...
86092 ERROR TEST-UNEXPECTED-FAIL | /tests/security/ssl/mixedcontent/test_bug329869.html | Test timed out.
86094 INFO Running /tests/security/ssl/mixedcontent/test_bug383369.html...
86095 INFO Error: Unable to restore focus, expect failures and timeouts.
86096 ERROR TEST-UNEXPECTED-FAIL | /tests/security/ssl/mixedcontent/test_bug383369.html | Test timed out.
86098 INFO Running /tests/security/ssl/mixedcontent/test_bug455367.html...
86099 INFO Error: Unable to restore focus, expect failures and timeouts.
86100 ERROR TEST-UNEXPECTED-FAIL | /tests/security/ssl/mixedcontent/test_bug455367.html | Test timed out.
86102 INFO Running /tests/security/ssl/mixedcontent/test_bug472986.html...
86103 INFO Error: Unable to restore focus, expect failures and timeouts.
86104 ERROR TEST-UNEXPECTED-FAIL | /tests/security/ssl/mixedcontent/test_bug472986.html | Test timed out.
86105 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up.
86106 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 137 remaining tests.
}
Blocks: 438871
Whiteboard: [test which aborts the suite] [orange]
Assignee: nobody → kaie
Blocks: 452401
URL: http://mxr.mozilla.org/mozilla-centra...
Component: General → Security: UI
QA Contact: general → ui
This looks close to bug 508835 (fixed by bug 507370). Is it the first time this appeared?
Assignee: kaie → honzab.moz
(In reply to comment #1)
> Is it the first time this appeared?

First time I notice it at least, iirc. (But I can't be sure.)
Bug 522684 could potentially fix this.
Depends on: 522684
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256332883.1256334379.23037.gz
Linux mozilla-central test debug mochitests-5/5 on 2009/10/23 14:21:23
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256568709.1256570216.894.gz
Linux mozilla-central test mochitests-5/5 on 2009/10/26 07:51:49
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256568296.1256569910.29794.gz
Linux mozilla-central test debug mochitests-5/5 on 2009/10/26 07:44:56
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256769745.1256771579.24173.gz
Linux mozilla-central test debug mochitests-5/5 on 2009/10/28 15:42:25
This bug should be fixed on m-c by this check in:
http://hg.mozilla.org/mozilla-central/rev/293f92d1a482

If there is no report from now, let's close this.
Still happening, only on OSX this time:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257185653.1257187228.20126.gz
OS X 10.5.2 mozilla-central test mochitests-5/5 on 2009/11/02 10:14:13

(Linux unit tests are still running for that checkin)
Summary: mochitest-plain: intermittent "Test timed out" on test_bug329869.html (+ test_bug383369.html, test_bug455367.html and test_bug472986.html) → mochitest-plain: intermittent "Test timed out" in security/ssl/mixedcontent tests (test_bug329869.html, test_bug383369.html, test_bug455367.html, test_bug472986.html)
Still happening on Linux, it seems:

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257199619.1257201344.19732.gz
Linux mozilla-central test debug mochitests-5/5 on 2009/11/02 14:06:59
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257227272.1257228621.28309.gz
OS X 10.5.2 mozilla-central test mochitests-5/5 on 2009/11/02 21:47:52
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257381517.1257383407.7823.gz
Linux mozilla-central test mochitests-5/5 on 2009/11/04 16:38:37
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257598175.1257599733.18782.gz
Linux mozilla-central debug test mochitests-5/5 on 2009/11/07 04:49:35
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257703406.1257704871.32061.gz
Linux mozilla-central debug test mochitests-5/5 on 2009/11/08 10:03:26
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257944796.1257946814.12741.gz
Linux mozilla-central debug test mochitests-5/5 on 2009/11/11 05:06:36
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257971765.1257973641.2485.gz
Linux mozilla-central debug test mochitests-5/5 on 2009/11/11 12:36:05
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258024268.1258025924.2920.gz
Linux mozilla-central debug test mochitests-5/5 on 2009/11/12 03:11:08
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258313136.1258314514.15624.gz
Linux mozilla-central opt test mochitests-5/5 on 2009/11/15 11:25:36
s: moz2-linux-slave15
This still seems to be linux specific. I have CentOS 5 installation in VPC2007 only (no dedicated machine). I experience bug 521549 on it, so I have to wait to get it fixed or install a different distribution (where I am not sure I would be able to reproduce this bug).
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258466382.1258468209.30282.gz
Linux mozilla-central debug test mochitests-5/5 on 2009/11/17 05:59:42
s: moz2-linux-slave41
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258816586.1258818354.5550.gz
OS X 10.5.2 mozilla-central test mochitests-5/5 on 2009/11/21 07:16:26
s: moz2-darwin9-slave05
550 ERROR TEST-UNEXPECTED-FAIL | /tests/security/ssl/mixedcontent/test_bug383369.html | Test timed out.
buildbot.slave.commands.TimeoutError: command timed out: 1200 seconds without output, killing pid 381
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260402367.1260403955.20398.gz
Linux mozilla-central debug test mochitests-5/5 on 2009/12/09 15:46:07
s: moz2-linux-slave06
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260470704.1260472273.4332.gz
Linux mozilla-central debug test mochitests-5/5 on 2009/12/10 10:45:04
s: moz2-linux-slave08
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260613305.1260614736.23673.gz
Linux mozilla-central debug test mochitests-5/5 on 2009/12/12 02:21:45
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260661522.1260663772.25645.gz
Linux mozilla-central debug test mochitests-5/5 on 2009/12/12 15:45:22
s: moz2-linux-slave18
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260755728.1260757248.8086.gz
Linux mozilla-central debug test mochitests-5/5 on 2009/12/13 17:55:28
s: moz2-linux-slave10
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260830210.1260831817.6122.gz
Linux mozilla-central debug test mochitests-5/5 on 2009/12/14 14:36:50
s: moz2-linux-slave16
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1260988402.1260990571.23567.gz
Linux mozilla-central debug test mochitests-5/5 on 2009/12/16 10:33:22
s: moz2-linux-slave12
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1261411242.1261412781.11202.gz
OS X 10.5.2 mozilla-central test mochitests-5/5 on 2009/12/21 08:00:42
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1261506837.1261508623.28058.gz
OS X 10.5.2 mozilla-central test mochitests-5/5 on 2009/12/22 10:33:57
s: moz2-darwin9-slave05
589 ERROR TEST-UNEXPECTED-FAIL | /tests/security/ssl/mixedcontent/test_bug383369.html | Test timed out.
buildbot.slave.commands.TimeoutError: command timed out: 1200 seconds without output, killing pid 273
Going to land this and let's see.
Comment on attachment 419302 [details] [diff] [review]
ssltunnel logging v1 [Checking comment 46]

http://hg.mozilla.org/mozilla-central/rev/a707bf69e7a0
Attachment #419302 - Attachment description: ssltunnel logging v1 → ssltunnel logging v1 [Checking comment 46]
http://hg.mozilla.org/mozilla-central/rev/b7ee0f1acfef

%x -> %p, also to fix linux64 build errors.
Attachment #419302 - Attachment is obsolete: true
Attachment #419323 - Attachment description: v1.1 → ssltunnel logging v1.1
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1262493858.1262495404.9793.gz
Linux mozilla-central debug test mochitests-5/5 on 2010/01/02 20:44:18
s: moz2-linux-slave07
598 ERROR TEST-UNEXPECTED-FAIL | /tests/security/ssl/mixedcontent/test_bug329869.html | Test timed out.
602 ERROR TEST-UNEXPECTED-FAIL | /tests/security/ssl/mixedcontent/test_bug383369.html | Test timed out.
606 ERROR TEST-UNEXPECTED-FAIL | /tests/security/ssl/mixedcontent/test_bug455367.html | Test timed out.
610 ERROR TEST-UNEXPECTED-FAIL | /tests/security/ssl/mixedcontent/test_bug472986.html | Test timed out.
611 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up.
612 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 143 remaining tests.
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1262761275.1262763273.9553.gz
Linux mozilla-central debug test mochitests-5/5 on 2010/01/05 23:01:15
s: moz2-linux-slave07
Daniel, thanks for the log report!

It looks like ReadConnectRequest doesn't pass on data we get. The reason I can see is that the request (or the data we are processing in that function) is not tailed with \r\n\r\n at that moment. Going to investigate further.
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1263312572.1263314343.3984.gz
Linux mozilla-central debug test mochitests-5/5 on 2010/01/12 08:09:32  
s: moz2-linux-slave22
576 ERROR TEST-UNEXPECTED-FAIL | /tests/security/ssl/mixedcontent/test_bug329869.html | Test timed out.
580 ERROR TEST-UNEXPECTED-FAIL | /tests/security/ssl/mixedcontent/test_bug383369.html | Test timed out.
584 ERROR TEST-UNEXPECTED-FAIL | /tests/security/ssl/mixedcontent/test_bug455367.html | Test timed out.
588 ERROR TEST-UNEXPECTED-FAIL | /tests/security/ssl/mixedcontent/test_bug472986.html | Test timed out.
589 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up.
590 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 144 remaining tests.


This seems like what happens when the mochitest server crashes.

    
    

    
  
OS X 10.5.2 mozilla-central debug test mochitests-5/5 on 2010/01/18 02:55:12  

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1263812112.1263813748.16786.gz

    
    

    
  
(In reply to comment #54)
> OS X 10.5.2 mozilla-central debug test mochitests-5/5 on 2010/01/18 02:55:12  
> 
> http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1263812112.1263813748.16786.gz

I have figured out what happens here. From some reason ssltunnel sees the initial CONNECT request as malformed. I'll add more logging to see why.

I have a fix for the timeout: I am not telling the socket to write in case of CONNECT request parsing error, so the response to the client is never sent and communication stuck.  I'll add another patch as a fix for reference and land it after I figure out why the parsing fails.

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1263910526.1263912041.16718.gz
Linux mozilla-central debug test mochitests-5/5 on 2010/01/19 06:15:26

    
    

    
  

      
      
      
      

        Attached patch
          
          
        Fix v1 (obsolete)
        — 
          — Splinter Review
      

    


  
Standard strtok is not thread safe. When parsing and checking two or more requests in different threads, the internal strtok caret is common to all threads and interacts.

I will clean the added logging up in a different patch.

        Attachment #422425 -
        Flags: review?(ted.mielczarek)

    
  
Whiteboard: [test which aborts the suite] [orange] → [test which aborts the suite] [orange] [has patch] [needs review ted]

    
    

    
  

      
      
      
      

        Attached patch
          
          
        Fix v1.1 (obsolete)
        — 
          — Splinter Review
      

    


  
Sorry, wrong file, this one is correct.  The previous patch only included fix for a bad request parsing code.  This one also includes fix for the timeout itself, I was not setting WRITE flag on the socket in case of request parse failure and the error response was never sent back to the client.

        Attachment #422425 -
        Attachment is obsolete: true

        Attachment #422431 -
        Flags: review?(ted.mielczarek)

        Attachment #422425 -
        Flags: review?(ted.mielczarek)

    
    

    
  


  
This is the first time I have experienced that hg threw away my local changes! The previous patch didn't refresh but qpop and qpush has not been stopped by 'abort local changes found'.

This is the correct patch, double checked.

        Attachment #422431 -
        Attachment is obsolete: true

        Attachment #422434 -
        Flags: review?(ted.mielczarek)

        Attachment #422431 -
        Flags: review?(ted.mielczarek)

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1264136919.1264138698.6053.gz
Linux mozilla-central debug test mochitests-5/5 on 2010/01/21 21:08:39
s: moz2-linux-slave12

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1264182080.1264183547.19376.gz
OS X 10.5.2 mozilla-central debug test mochitests-5/5 on 2010/01/22 09:41:20
s: moz2-darwin9-slave18

    
    

    
  
Comment on attachment 422434 [details] [diff] [review]
Fix v1.1 [Checkin comment 69] [1.9.2 comment 73] [1.9.1 comment 74]

There's no easy to way to just link in nsCRT here, is there? That'd be a bit nicer than copy and pasting the code. But since this is just a test app, it's not the end of the world.

        Attachment #422434 -
        Flags: review?(ted.mielczarek) → review+

    
    

    
  
(In reply to comment #66)
> (From update of attachment 422434 [details] [diff] [review])
> There's no easy to way to just link in nsCRT here, is there? That'd be a bit
> nicer than copy and pasting the code. But since this is just a test app, it's
> not the end of the world.

I think it's not necessary to link against XPCOM due to a single function atm. I had some plans to move ssltunnel to be based on necko to a have a regular full proxy behavior and support for keep-alive connections. But it's sound of a future.

Thanks for the review.

    
    

    
  
Comment on attachment 422434 [details] [diff] [review]
Fix v1.1 [Checkin comment 69] [1.9.2 comment 73] [1.9.1 comment 74]

http://hg.mozilla.org/mozilla-central/rev/ccbc4b3e631e

        Attachment #422434 -
        Attachment description: Fix v1.1 → Fix v1.1 [Checkin comment 69]

    
  
Status: NEW → RESOLVED
Closed: 14 years ago
Resolution: --- → FIXED

    
  
Whiteboard: [test which aborts the suite] [orange] [has patch] [needs review ted] → [test which aborts the suite] [orange]
Target Milestone: --- → mozilla1.9.3a1

    
  
Blocks: 542207

    
    

    
  
Still affects 1.9.2.  Honza, would this bug's patch be appropriate for 1.9.2, and if so, could you request approval?

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.6/1264780161.1264783413.20486.gz
OS X 10.5.2 mozilla-1.9.2 opt test mochitests on 2010/01/29 07:49:21
s: moz2-darwin9-slave24
blocking1.9.2: --- → ?

    
    

    
  
Comment on attachment 422434 [details] [diff] [review]
Fix v1.1 [Checkin comment 69] [1.9.2 comment 73] [1.9.1 comment 74]

Agree.  Just a test change, this bug affects all branches since 1.9.0, seems necessary to land it there as well.

        Attachment #422434 -
        Flags: approval1.9.2.1?

        Attachment #422434 -
        Flags: approval1.9.1.8?

        Attachment #422434 -
        Flags: approval1.9.0.18?

        Attachment #422434 -
        Flags: approval1.9.1.9?

        Attachment #422434 -
        Flags: approval1.9.1.8?

        Attachment #422434 -
        Flags: approval1.9.0.19?

        Attachment #422434 -
        Flags: approval1.9.0.18?

    
    

    
  
Comment on attachment 422434 [details] [diff] [review]
Fix v1.1 [Checkin comment 69] [1.9.2 comment 73] [1.9.1 comment 74]

a=beltzner for a whole bunch of places.

        Attachment #422434 -
        Flags: approval1.9.2.2?

        Attachment #422434 -
        Flags: approval1.9.2.2+

        Attachment #422434 -
        Flags: approval1.9.1.9?

        Attachment #422434 -
        Flags: approval1.9.1.9+

        Attachment #422434 -
        Flags: approval1.9.0.19?

        Attachment #422434 -
        Flags: approval1.9.0.19+
blocking1.9.2: ? → ---

    
    

    
  
Comment on attachment 422434 [details] [diff] [review]
Fix v1.1 [Checkin comment 69] [1.9.2 comment 73] [1.9.1 comment 74]

http://hg.mozilla.org/releases/mozilla-1.9.2/rev/219830729ac4

        Attachment #422434 -
        Attachment description: Fix v1.1 [Checkin comment 69] → Fix v1.1 [Checkin comment 69] [1.9.2 comment 73]

    
  

          status1.9.2:
          --- → .2-fixed

    
    

    
  
Comment on attachment 422434 [details] [diff] [review]
Fix v1.1 [Checkin comment 69] [1.9.2 comment 73] [1.9.1 comment 74]

http://hg.mozilla.org/releases/mozilla-1.9.1/rev/dc14dbb34190

        Attachment #422434 -
        Attachment description: Fix v1.1 [Checkin comment 69] [1.9.2 comment 73] → Fix v1.1 [Checkin comment 69] [1.9.2 comment 73] [1.9.1 comment 74]

    
    

    
  
Comment on attachment 422434 [details] [diff] [review]
Fix v1.1 [Checkin comment 69] [1.9.2 comment 73] [1.9.1 comment 74]

This patch is not applicable to 1.9.0 branch.  There is much older version of ssltunnel that is not used.

        Attachment #422434 -
        Flags: approval1.9.0.19+

    
  

          status1.9.1:
          --- → .9-fixed

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  
Whiteboard: [test which aborts the suite] [orange] → [test which aborts the suite]
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: