Closed Bug 1377004 Opened 4 years ago Closed 4 years ago

TCP FastOpen trying to narrow down a bug search 2

Categories

(Core :: Networking: HTTP, enhancement)

56 Branch
enhancement
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla56
Tracking Status
firefox56 --- fixed

People

(Reporter: dragana, Assigned: dragana)

References

Details

(Whiteboard: [necko-active])

Attachments

(3 files, 1 obsolete file)

This is the second test to try to narrow down search for a bug in TFO.

This test:
1) calls sendTo/connectEx/connectX kernal functions but it does not supply any data.
2) If a halfOpenSock has a backup transactions started at the time the primary transaction has been successfully connected, it abandons halfOpen (instead of returning halfOpenSock to the HalfOpen list)
I will run test from bug 1372897 again before I run this test.
Attached patch bug_test_tfo2.patch (obsolete) — Splinter Review
Assignee: nobody → dd.mozilla
Status: NEW → ASSIGNED
Attachment #8882067 - Flags: review?(mcmanus)
Whiteboard: [necko-active]
Attachment #8882068 - Flags: review?(mcmanus)
Comment on attachment 8882068 [details] [diff] [review]
bug_test_tfo2_revert.patch

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

rs
Attachment #8882068 - Flags: review?(mcmanus) → review+
Attachment #8882067 - Flags: review?(mcmanus) → review+
Pushed by dd.mozilla@gmail.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/8597b133717f
TCP FastOpen trying to narrow down a bug search 2. r=mcmanus
Keywords: leave-open
Backed out for crashing many tests with mozilla::net::nsHttpConnectionMgr::nsHalfOpenSocket::SetFastOpenConnected:

https://hg.mozilla.org/integration/mozilla-inbound/rev/e6e13ac24a64cf21ad795d03ae8c77af6a064a9d

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=8597b133717f94cdd88aa6aa04e32fb7a89288b8&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=retry&filter-resultStatus=usercancel&filter-resultStatus=runnable
Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=111458359&repo=mozilla-inbound

[task 2017-07-03T09:24:59.748844Z] 09:24:59     INFO - Application command: /home/worker/workspace/build/application/firefox/firefox -marionette -foreground -profile /tmp/tmpYnCtKU.mozrunner
[task 2017-07-03T09:24:59.765194Z] 09:24:59     INFO - runtests.py | Application pid: 1251
[task 2017-07-03T09:24:59.766089Z] 09:24:59     INFO - TEST-INFO | started process GECKO(1251)
[task 2017-07-03T09:25:03.670365Z] 09:25:03     INFO - GECKO(1251) | 1499073903663	Marionette	INFO	Listening on port 2828
[task 2017-07-03T09:25:03.795754Z] 09:25:03     INFO - GECKO(1251) | 1499073903790	Marionette	DEBUG	Register listener.js for window 2147483649
[task 2017-07-03T09:25:03.803693Z] 09:25:03     INFO - GECKO(1251) | JavaScript error: chrome://marionette/content/server.js, line 350: NS_ERROR_SOCKET_ADDRESS_IN_USE: Component returned failure code: 0x804b0036 (NS_ERROR_SOCKET_ADDRESS_IN_USE) [nsIServerSocket.initSpecialConnection]
[task 2017-07-03T09:25:04.268235Z] 09:25:04     INFO - GECKO(1251) | ExceptionHandler::GenerateDump cloned child ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[task 2017-07-03T09:25:04.270106Z] 09:25:04     INFO - GECKO(1251) | 1370
[task 2017-07-03T09:25:04.270542Z] 09:25:04     INFO - GECKO(1251) | ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2017-07-03T09:25:04.392823Z] 09:25:04     INFO - GECKO(1251) | [GFX1-]: Receive IPC close with reason=AbnormalShutdown
[task 2017-07-03T09:25:04.399844Z] 09:25:04     INFO - GECKO(1251) | [Child 1336] WARNING: pipe error (3): Connection reset by peer: file /home/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 353
[task 2017-07-03T09:25:04.402712Z] 09:25:04     INFO - GECKO(1251) | [GFX1-]: Receive IPC close with reason=AbnormalShutdown
[task 2017-07-03T09:25:04.404963Z] 09:25:04     INFO - GECKO(1251) | [Child 1302] WARNING: pipe error (3): Connection reset by peer: file /home/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 353
[task 2017-07-03T09:25:04.645840Z] 09:25:04     INFO - TEST-INFO | Main app process: exit 11
[task 2017-07-03T09:25:04.646690Z] 09:25:04     INFO - Buffered messages finished
[task 2017-07-03T09:25:04.647547Z] 09:25:04    ERROR - TEST-UNEXPECTED-FAIL | automation.py | application terminated with exit code 11
[task 2017-07-03T09:25:04.648252Z] 09:25:04     INFO - runtests.py | Application ran for: 0:00:04.898643
[task 2017-07-03T09:25:04.648936Z] 09:25:04     INFO - zombiecheck | Reading PID log: /tmp/tmp226f3Cpidlog
[task 2017-07-03T09:25:04.649675Z] 09:25:04     INFO - ==> process 1251 launched child process 1274
[task 2017-07-03T09:25:04.649737Z] 09:25:04     INFO - ==> process 1251 launched child process 1302
[task 2017-07-03T09:25:04.650361Z] 09:25:04     INFO - ==> process 1251 launched child process 1336
[task 2017-07-03T09:25:04.651089Z] 09:25:04     INFO - zombiecheck | Checking for orphan process with PID: 1274
[task 2017-07-03T09:25:04.651157Z] 09:25:04     INFO - zombiecheck | Checking for orphan process with PID: 1302
[task 2017-07-03T09:25:04.651770Z] 09:25:04     INFO - zombiecheck | Checking for orphan process with PID: 1336
[task 2017-07-03T09:25:04.652455Z] 09:25:04     INFO - mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/dE18K_CWQtq0JnSJBK6n3A/artifacts/public/build/target.crashreporter-symbols.zip
[task 2017-07-03T09:25:11.185074Z] 09:25:11     INFO - mozcrash Copy/paste: /usr/local/bin/linux64-minidump_stackwalk /tmp/tmpYnCtKU.mozrunner/minidumps/249b9640-1693-22e6-33db-6c04fced363e.dmp /tmp/tmpu3Sm5t
[task 2017-07-03T09:25:19.293458Z] 09:25:19     INFO - mozcrash Saved minidump as /home/worker/workspace/build/blobber_upload_dir/249b9640-1693-22e6-33db-6c04fced363e.dmp
[task 2017-07-03T09:25:19.295963Z] 09:25:19     INFO - mozcrash Saved app info as /home/worker/workspace/build/blobber_upload_dir/249b9640-1693-22e6-33db-6c04fced363e.extra
[task 2017-07-03T09:25:19.349032Z] 09:25:19     INFO - PROCESS-CRASH | automation.py | application crashed [@ mozilla::net::nsHttpConnectionMgr::nsHalfOpenSocket::SetFastOpenConnected]
[task 2017-07-03T09:25:19.350630Z] 09:25:19     INFO - Crash dump filename: /tmp/tmpYnCtKU.mozrunner/minidumps/249b9640-1693-22e6-33db-6c04fced363e.dmp
[task 2017-07-03T09:25:19.351327Z] 09:25:19     INFO - Operating system: Linux
[task 2017-07-03T09:25:19.351890Z] 09:25:19     INFO -                   0.0.0 Linux 3.13.0-112-generic #159-Ubuntu SMP Fri Mar 3 15:26:07 UTC 2017 x86_64
[task 2017-07-03T09:25:19.352813Z] 09:25:19     INFO - CPU: amd64
[task 2017-07-03T09:25:19.353310Z] 09:25:19     INFO -      family 6 model 62 stepping 4
[task 2017-07-03T09:25:19.353936Z] 09:25:19     INFO -      2 CPUs
[task 2017-07-03T09:25:19.354790Z] 09:25:19     INFO - 
[task 2017-07-03T09:25:19.355474Z] 09:25:19     INFO - GPU: UNKNOWN
[task 2017-07-03T09:25:19.355885Z] 09:25:19     INFO - 
[task 2017-07-03T09:25:19.356799Z] 09:25:19     INFO - Crash reason:  SIGSEGV
[task 2017-07-03T09:25:19.357185Z] 09:25:19     INFO - Crash address: 0x60
[task 2017-07-03T09:25:19.361616Z] 09:25:19     INFO - Process uptime: not available
[task 2017-07-03T09:25:19.362644Z] 09:25:19     INFO - 
[task 2017-07-03T09:25:19.363268Z] 09:25:19     INFO - Thread 3 (crashed)
[task 2017-07-03T09:25:19.363961Z] 09:25:19     INFO -  0  libxul.so!mozilla::net::nsHttpConnectionMgr::nsHalfOpenSocket::SetFastOpenConnected [nsHttpConnectionMgr.cpp:8597b133717f : 4264 + 0x0]
[task 2017-07-03T09:25:19.364699Z] 09:25:19     INFO -     rax = 0x0000000000000000   rdx = 0x00007f03fd734db0
[task 2017-07-03T09:25:19.365388Z] 09:25:19     INFO -     rcx = 0x0000000000000000   rbx = 0x0000000000000000
[task 2017-07-03T09:25:19.366074Z] 09:25:19     INFO -     rsi = 0x0000000000000001   rdi = 0x00007f03f3c54100
[task 2017-07-03T09:25:19.366780Z] 09:25:19     INFO -     rbp = 0x00007f04187fdac0   rsp = 0x00007f04187fda20
[task 2017-07-03T09:25:19.367446Z] 09:25:19     INFO -      r8 = 0x00007f0412995568    r9 = 0x00007f042f8005c8
[task 2017-07-03T09:25:19.368123Z] 09:25:19     INFO -     r10 = 0x0000000000000001   r11 = 0x0000000000000283
[task 2017-07-03T09:25:19.368773Z] 09:25:19     INFO -     r12 = 0x0000000000000000   r13 = 0x00007f03f3c54100
[task 2017-07-03T09:25:19.369437Z] 09:25:19     INFO -     r14 = 0x00000000002334cd   r15 = 0x0000000000000001
[task 2017-07-03T09:25:19.370115Z] 09:25:19     INFO -     rip = 0x00007f041fb12fdd
[task 2017-07-03T09:25:19.370924Z] 09:25:19     INFO -     Found by: given as instruction pointer in context
[task 2017-07-03T09:25:19.371849Z] 09:25:19     INFO -  1  libxul.so!mozilla::net::nsSocketTransport::OnSocketConnected [nsSocketTransport2.cpp:8597b133717f : 1891 + 0xa]
[task 2017-07-03T09:25:19.372586Z] 09:25:19     INFO -     rbx = 0x00007f03f27ca000   rbp = 0x00007f04187fdae0
[task 2017-07-03T09:25:19.373264Z] 09:25:19     INFO -     rsp = 0x00007f04187fdad0   r12 = 0x0000000000000002
[task 2017-07-03T09:25:19.373982Z] 09:25:19     INFO -     r13 = 0x00007f03f3cef2b0   r14 = 0x00000000002334cd
[task 2017-07-03T09:25:19.374636Z] 09:25:19     INFO -     r15 = 0x0000000000000001   rip = 0x00007f041f8674ec
[task 2017-07-03T09:25:19.375321Z] 09:25:19     INFO -     Found by: call frame info
[task 2017-07-03T09:25:19.376017Z] 09:25:19     INFO -  2  libxul.so!mozilla::net::nsSocketTransport::OnSocketReady [nsSocketTransport2.cpp:8597b133717f : 2222 + 0x8]
[task 2017-07-03T09:25:19.376646Z] 09:25:19     INFO -     rbx = 0x00007f03f27ca000   rbp = 0x00007f04187fdb20
[task 2017-07-03T09:25:19.377306Z] 09:25:19     INFO -     rsp = 0x00007f04187fdaf0   r12 = 0x0000000000000002
[task 2017-07-03T09:25:19.377982Z] 09:25:19     INFO -     r13 = 0x00007f03f3cef2b0   r14 = 0x00000000002334cd
[task 2017-07-03T09:25:19.378634Z] 09:25:19     INFO -     r15 = 0x0000000000000001   rip = 0x00007f041f867884
[task 2017-07-03T09:25:19.379017Z] 09:25:19     INFO -     Found by: call frame info
[task 2017-07-03T09:25:19.379462Z] 09:25:19     INFO -  3  libxul.so!mozilla::net::nsSocketTransportService::DoPollIteration [nsSocketTransportService2.cpp:8597b133717f : 1166 + 0xd]
[task 2017-07-03T09:25:19.379866Z] 09:25:19     INFO -     rbx = 0x00007f042f753bf0   rbp = 0x00007f04187fdb90
[task 2017-07-03T09:25:19.380536Z] 09:25:19     INFO -     rsp = 0x00007f04187fdb30   r12 = 0x0000000000000018
[task 2017-07-03T09:25:19.381208Z] 09:25:19     INFO -     r13 = 0x0000000000000020   r14 = 0x0000000000000001
[task 2017-07-03T09:25:19.381893Z] 09:25:19     INFO -     r15 = 0x0000000000000001   rip = 0x00007f041f86a9d6
[task 2017-07-03T09:25:19.382552Z] 09:25:19     INFO -     Found by: call frame info
[task 2017-07-03T09:25:19.383248Z] 09:25:19     INFO -  4  libxul.so!mozilla::net::nsSocketTransportService::Run [nsSocketTransportService2.cpp:8597b133717f : 936 + 0xf]
[task 2017-07-03T09:25:19.383917Z] 09:25:19     INFO -     rbx = 0x0000000000000000   rbp = 0x00007f04187fdc70
[task 2017-07-03T09:25:19.384565Z] 09:25:19     INFO -     rsp = 0x00007f04187fdba0   r12 = 0x00007f042f753cd4
[task 2017-07-03T09:25:19.385234Z] 09:25:19     INFO -     r13 = 0x00007f04187fdbff   r14 = 0x00007f042f753cdc
[task 2017-07-03T09:25:19.385860Z] 09:25:19     INFO -     r15 = 0x00007f042f753bf0   rip = 0x00007f041f87446f
[task 2017-07-03T09:25:19.386515Z] 09:25:19     INFO -     Found by: call frame info
[task 2017-07-03T09:25:19.387185Z] 09:25:19     INFO -  5  libxul.so!nsThread::ProcessNextEvent [nsThread.cpp:8597b133717f : 1422 + 0x6]
[task 2017-07-03T09:25:19.387857Z] 09:25:19     INFO -     rbx = 0x00007f042f75e200   rbp = 0x00007f04187fdd80
[task 2017-07-03T09:25:19.388508Z] 09:25:19     INFO -     rsp = 0x00007f04187fdc80   r12 = 0x0000000000000001
[task 2017-07-03T09:25:19.389192Z] 09:25:19     INFO -     r13 = 0x0000000000000000   r14 = 0x0000000000000000
[task 2017-07-03T09:25:19.389884Z] 09:25:19     INFO -     r15 = 0x00007f04187fdd9f   rip = 0x00007f041f7c3f61
[task 2017-07-03T09:25:19.390504Z] 09:25:19     INFO -     Found by: call frame info
[task 2017-07-03T09:25:19.391147Z] 09:25:19     INFO -  6  libxul.so!NS_ProcessNextEvent [nsThreadUtils.cpp:8597b133717f : 489 + 0xd]
[task 2017-07-03T09:25:19.391818Z] 09:25:19     INFO -     rbx = 0x0000000000000000   rbp = 0x00007f04187fddb0
[task 2017-07-03T09:25:19.392503Z] 09:25:19     INFO -     rsp = 0x00007f04187fdd90   r12 = 0x00007f0419049a40
[task 2017-07-03T09:25:19.394177Z] 09:25:19     INFO -     r13 = 0x00007f042f75e220   r14 = 0x00007f042f75e200
[task 2017-07-03T09:25:19.394854Z] 09:25:19     INFO -     r15 = 0x00007f0419049a60   rip = 0x00007f041f7c1b3d
[task 2017-07-03T09:25:19.395510Z] 09:25:19     INFO -     Found by: call frame info
[task 2017-07-03T09:25:19.396219Z] 09:25:19     INFO -  7  libxul.so!mozilla::ipc::MessagePumpForNonMainThreads::Run [MessagePump.cpp:8597b133717f : 339 + 0xa]
[task 2017-07-03T09:25:19.396862Z] 09:25:19     INFO -     rbx = 0x00007f042f75e3a0   rbp = 0x00007f04187fde10
[task 2017-07-03T09:25:19.397524Z] 09:25:19     INFO -     rsp = 0x00007f04187fddc0   r12 = 0x00007f0419049a40
[task 2017-07-03T09:25:19.397986Z] 09:25:19     INFO -     r13 = 0x00007f042f75e220   r14 = 0x00007f042f75e200
[task 2017-07-03T09:25:19.398378Z] 09:25:19     INFO -     r15 = 0x00007f0419049a60   rip = 0x00007f041fbf1c6a
[task 2017-07-03T09:25:19.398798Z] 09:25:19     INFO -     Found by: call frame info
[task 2017-07-03T09:25:19.399210Z] 09:25:19     INFO -  8  libxul.so!MessageLoop::Run [message_loop.cc:8597b133717f : 320 + 0x5]
[task 2017-07-03T09:25:19.399645Z] 09:25:19     INFO -     rbx = 0x00007f042f75e200   rbp = 0x00007f04187fde40
[task 2017-07-03T09:25:19.403621Z] 09:25:19     INFO -     rsp = 0x00007f04187fde20   r12 = 0x00007f04187fde80
[task 2017-07-03T09:25:19.404087Z] 09:25:19     INFO -     r13 = 0x00007f042f75e220   r14 = 0x00007f042f75e3a0
[task 2017-07-03T09:25:19.404750Z] 09:25:19     INFO -     r15 = 0x00007f04187fe670   rip = 0x00007f041fbc4302
[task 2017-07-03T09:25:19.405417Z] 09:25:19     INFO -     Found by: call frame info
[task 2017-07-03T09:25:19.406097Z] 09:25:19     INFO -  9  libxul.so!nsThread::ThreadFunc [nsThread.cpp:8597b133717f : 504 + 0x8]
[task 2017-07-03T09:25:19.406770Z] 09:25:19     INFO -     rbx = 0x00007f042f75e200   rbp = 0x00007f04187fdec0
[task 2017-07-03T09:25:19.407435Z] 09:25:19     INFO -     rsp = 0x00007f04187fde50   r12 = 0x00007f04187fde80
[task 2017-07-03T09:25:19.408087Z] 09:25:19     INFO -     r13 = 0x00007f042f75e220   r14 = 0x00007f042f75e3a0
[task 2017-07-03T09:25:19.408735Z] 09:25:19     INFO -     r15 = 0x00007f04187fe670   rip = 0x00007f041f7c2470
[task 2017-07-03T09:25:19.409398Z] 09:25:19     INFO -     Found by: call frame info
[task 2017-07-03T09:25:19.410070Z] 09:25:19     INFO - 10  libnspr4.so!_pt_root [ptthread.c:8597b133717f : 216 + 0x7]
[task 2017-07-03T09:25:19.410728Z] 09:25:19     INFO -     rbx = 0x00007f042f74bc80   rbp = 0x00007f04187fdf10
[task 2017-07-03T09:25:19.411402Z] 09:25:19     INFO -     rsp = 0x00007f04187fded0   r12 = 0x0000000000000000
[task 2017-07-03T09:25:19.412088Z] 09:25:19     INFO -     r13 = 0x00000000000004eb   r14 = 0x00007f04187fe700
[task 2017-07-03T09:25:19.412755Z] 09:25:19     INFO -     r15 = 0x00007f04187fe670   rip = 0x00007f042f2cda21
[task 2017-07-03T09:25:19.413399Z] 09:25:19     INFO -     Found by: call frame info
[task 2017-07-03T09:25:19.414057Z] 09:25:19     INFO - 11  libpthread-2.23.so + 0x76ba
[task 2017-07-03T09:25:19.414725Z] 09:25:19     INFO -     rbx = 0x0000000000000000   rbp = 0x0000000000000000
[task 2017-07-03T09:25:19.415379Z] 09:25:19     INFO -     rsp = 0x00007f04187fdf20   r12 = 0x0000000000000000
[task 2017-07-03T09:25:19.416003Z] 09:25:19     INFO -     r13 = 0x00007fff1cbe0e5f   r14 = 0x00007f04187fe9c0
[task 2017-07-03T09:25:19.416634Z] 09:25:19     INFO -     r15 = 0x00007f042f74bc80   rip = 0x00007f04309956ba
[task 2017-07-03T09:25:19.417304Z] 09:25:19     INFO -     Found by: call frame info
[task 2017-07-03T09:25:19.417968Z] 09:25:19     INFO - 12  libc-2.23.so + 0x10682d
[task 2017-07-03T09:25:19.418597Z] 09:25:19     INFO -     rsp = 0x00007f04187fdfc0   rip = 0x00007f042fa1e82d
[task 2017-07-03T09:25:19.419262Z] 09:25:19     INFO -     Found by: stack scanning
Flags: needinfo?(dd.mozilla)
Pushed by dd.mozilla@gmail.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/25b411a687da
TCP FastOpen trying to narrow down a bug search 2. r=mcmanus
Flags: needinfo?(dd.mozilla)
Backout by kwierso@gmail.com:
https://hg.mozilla.org/mozilla-central/rev/e6a7a778ba13
Backed out changeset 25b411a687da for quantum_pageload_google failures on win10 a=backout
Flags: needinfo?(dd.mozilla)
crash dump cannot be opened. I do not know what is happening. This is a side effect of the test code that will never be actually deployed, I added it just to narrow down a bug search. Cause of the crash is step 1) in description ("calls sendTo/connectEx/connectX kernal functions but it does not supply any data.")

I will run tests without that part.
Attachment #8882067 - Attachment is obsolete: true
Attachment #8885645 - Flags: review+
Pushed by dd.mozilla@gmail.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/211800000a63
TCP FastOpen trying to narrow down a bug search 2. r=mcmanus
For the record, this temporary change brought an improvement:

== Change summary for alert #7887 (as of July 12 2017 10:12 UTC) ==

Improvements:

 24%  sessionrestore_many_windows windows10-64 opt e10s     4,332.92 -> 3,278.67

For up to date results, see: https://treeherder.mozilla.org/perf.html#/alerts?id=7887
Depends on: 1381256
Pushed by dd.mozilla@gmail.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/be492541cb16
REVERT - TCP FastOpen trying to narrow down a bug search 2. r=mcmanus
Keywords: leave-open
https://hg.mozilla.org/mozilla-central/rev/be492541cb16
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla56
Depends on: 1385116
You need to log in before you can comment on or make changes to this bug.