Closed Bug 1304266 Opened 3 years ago Closed 3 years ago

libevent kqueue warning on macOS Sierra 10.2: kq_init: detected broken kqueue; not using.: Undefined error: 0

Categories

(Core :: IPC, defect)

Unspecified
macOS
defect
Not set

Tracking

()

VERIFIED FIXED
mozilla53
Tracking Status
firefox49 --- wontfix
firefox-esr45 --- fixed
firefox50 --- wontfix
firefox51 --- verified
firefox52 --- verified
firefox53 --- verified

People

(Reporter: cpeterson, Assigned: billm)

References

(Blocks 1 open bug)

Details

Attachments

(1 file)

On macOS 10.12, libevent issues this warning on stderr and refuses to use kqueue:

> [warn] kq_init: detected broken kqueue; not using.: Undefined error: 0

This is a libevent bug and has been fixed upstream:

https://github.com/libevent/libevent/issues/376

Here is the Chromium bug report:

https://crbug.com/626534
Hi guys,

I'm experiencing this issue when starting Firefox browser from Java application using Selenium Geckodriver on MacOS Sierra 10.12.

Except for the warning printed, Firefox is started with a delay of ~1 minute. I'm not sure, but I suppose that this is connected with the warning. Everything is all right if start Firefox manually or e.g. on Windows 10.

Could you please give me more details about the issue and if it can cause the delay in Firefox start? Also, are you planning to fix it?

Also I've tried to update libevent to the latest version but it didn't help.

My usecase details:

OS: macOS Sierra v10.12
Env: Geckodriver v0.11.1, Firefox 50.1

The log:

 ...
1482144253807	geckodriver	INFO	Listening on 127.0.0.1:16445
Dec 19, 2016 1:44:13 PM org.openqa.selenium.remote.ProtocolHandshake createSession
INFO: Attempting bi-dialect session, assuming Postel's Law holds true on the remote end
 2016-12-19 13:44:13,938 DEBUG org.apache.http.client.protocol.RequestAddCookies - CookieSpec selected: default
 2016-12-19 13:44:13,951 DEBUG org.apache.http.client.protocol.RequestAuthCache - Auth cache not set in the context
 2016-12-19 13:44:13,953 DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager - Connection request: [route: {}->http://localhost:16445][total kept alive: 0; route allocated: 0 of 2000; total allocated: 0 of 2000]
 2016-12-19 13:44:13,966 DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager - Connection leased: [id: 0][route: {}->http://localhost:16445][total kept alive: 0; route allocated: 1 of 2000; total allocated: 1 of 2000]
 2016-12-19 13:44:13,967 DEBUG org.apache.http.impl.execchain.MainClientExec - Opening connection {}->http://localhost:16445
 2016-12-19 13:44:13,969 DEBUG org.apache.http.impl.conn.DefaultHttpClientConnectionOperator - Connecting to localhost/127.0.0.1:16445
 2016-12-19 13:44:13,970 DEBUG org.apache.http.impl.conn.DefaultHttpClientConnectionOperator - Connection established 127.0.0.1:49352<->127.0.0.1:16445
 2016-12-19 13:44:13,970 DEBUG org.apache.http.impl.conn.DefaultManagedHttpClientConnection - http-outgoing-0: set socket timeout to 10800000
 2016-12-19 13:44:13,970 DEBUG org.apache.http.impl.execchain.MainClientExec - Executing request POST /session HTTP/1.1
 2016-12-19 13:44:13,970 DEBUG org.apache.http.impl.execchain.MainClientExec - Target auth state: UNCHALLENGED
 2016-12-19 13:44:13,971 DEBUG org.apache.http.impl.execchain.MainClientExec - Proxy auth state: UNCHALLENGED
 2016-12-19 13:44:13,974 DEBUG org.apache.http.headers - http-outgoing-0 >> POST /session HTTP/1.1
 2016-12-19 13:44:13,974 DEBUG org.apache.http.headers - http-outgoing-0 >> Content-Type: application/json; charset=utf-8
 2016-12-19 13:44:13,974 DEBUG org.apache.http.headers - http-outgoing-0 >> Content-Length: 435
 2016-12-19 13:44:13,974 DEBUG org.apache.http.headers - http-outgoing-0 >> Host: localhost:16445
 2016-12-19 13:44:13,974 DEBUG org.apache.http.headers - http-outgoing-0 >> Connection: Keep-Alive
 2016-12-19 13:44:13,974 DEBUG org.apache.http.headers - http-outgoing-0 >> User-Agent: Apache-HttpClient/4.5.2 (Java/1.8.0_91)
 2016-12-19 13:44:13,974 DEBUG org.apache.http.headers - http-outgoing-0 >> Accept-Encoding: gzip,deflate
 2016-12-19 13:44:13,975 DEBUG org.apache.http.wire - http-outgoing-0 >> "POST /session HTTP/1.1[\r][\n]"
 2016-12-19 13:44:13,975 DEBUG org.apache.http.wire - http-outgoing-0 >> "Content-Type: application/json; charset=utf-8[\r][\n]"
 2016-12-19 13:44:13,975 DEBUG org.apache.http.wire - http-outgoing-0 >> "Content-Length: 435[\r][\n]"
 2016-12-19 13:44:13,975 DEBUG org.apache.http.wire - http-outgoing-0 >> "Host: localhost:16445[\r][\n]"
 2016-12-19 13:44:13,975 DEBUG org.apache.http.wire - http-outgoing-0 >> "Connection: Keep-Alive[\r][\n]"
 2016-12-19 13:44:13,975 DEBUG org.apache.http.wire - http-outgoing-0 >> "User-Agent: Apache-HttpClient/4.5.2 (Java/1.8.0_91)[\r][\n]"
 2016-12-19 13:44:13,975 DEBUG org.apache.http.wire - http-outgoing-0 >> "Accept-Encoding: gzip,deflate[\r][\n]"
 2016-12-19 13:44:13,975 DEBUG org.apache.http.wire - http-outgoing-0 >> "[\r][\n]"
 2016-12-19 13:44:13,980 DEBUG org.apache.http.wire - http-outgoing-0 >> "{"capabilities": {"desiredCapabilities": {"marionette":true,"firefoxOptions":{"prefs":{},"args":[]},"browserName":"firefox","moz:firefoxOptions":{"prefs":{},"args":[]},"version":"","platform":"ANY"},"requiredCapabilities": {}},"desiredCapabilities": {"marionette":true,"firefoxOptions":{"prefs":{},"args":[]},"browserName":"firefox","moz:firefoxOptions":{"prefs":{},"args":[]},"version":"","platform":"ANY"},"requiredCapabilities": {}}"
1482144253986	mozprofile::profile	INFO	Using profile path /var/folders/zt/d2xz9hqx579_3jvthprp7kmm0000gs/T/rust_mozprofile.B5jDFHi6jZLE
1482144253988	geckodriver::marionette	INFO	Starting browser /Applications/Firefox.app/Contents/MacOS/firefox-bin
1482144253992	geckodriver::marionette	INFO	Connecting to Marionette on localhost:49353
[warn] kq_init: detected broken kqueue; not using.: Undefined error: 0
1482144255199	Marionette	INFO	Listening on port 49353
[warn] kq_init: detected broken kqueue; not using.: Undefined error: 0
 2016-12-19 13:45:29,679 DEBUG org.apache.http.wire - http-outgoing-0 << "HTTP/1.1 200 OK[\r][\n]"
 2016-12-19 13:45:29,679 DEBUG org.apache.http.wire - http-outgoing-0 << "Connection: close[\r][\n]"
 2016-12-19 13:45:29,679 DEBUG org.apache.http.wire - http-outgoing-0 << "Date: Mon, 19 Dec 2016 10:45:29 GMT[\r][\n]"
 2016-12-19 13:45:29,679 DEBUG org.apache.http.wire - http-outgoing-0 << "Content-Length: 534[\r][\n]"
 2016-12-19 13:45:29,679 DEBUG org.apache.http.wire - http-outgoing-0 << "Content-Type: application/json[\r][\n]"
 2016-12-19 13:45:29,679 DEBUG org.apache.http.wire - http-outgoing-0 << "[\r][\n]"
 2016-12-19 13:45:29,679 DEBUG org.apache.http.wire - http-outgoing-0 << "{"sessionId":"053c62a8-a29b-cf4a-b537-911f22e376d4","value":{"XULappId":"{ec8030f7-c20a-464f-9b0e-13a3a9e97384}","acceptSslCerts":false,"appBuildId":"20161208153507","browserName":"firefox","browserVersion":"50.1.0","command_id":1,"firefoxOptions":{"args":[],"prefs":{}},"marionette":true,"platform":"DARWIN","platformName":"darwin","platformVersion":"16.0.0","processId":5769,"proxy":{},"raisesAccessibilityExceptions":false,"rotatable":false,"specificationLevel":0,"takesElementScreenshot":true,"takesScreenshot":true,"version":""}}"
 2016-12-19 13:45:29,682 DEBUG org.apache.http.headers - http-outgoing-0 << HTTP/1.1 200 OK
 2016-12-19 13:45:29,682 DEBUG org.apache.http.headers - http-outgoing-0 << Connection: close
 2016-12-19 13:45:29,682 DEBUG org.apache.http.headers - http-outgoing-0 << Date: Mon, 19 Dec 2016 10:45:29 GMT
 2016-12-19 13:45:29,682 DEBUG org.apache.http.headers - http-outgoing-0 << Content-Length: 534
 2016-12-19 13:45:29,682 DEBUG org.apache.http.headers - http-outgoing-0 << Content-Type: application/json
 2016-12-19 13:45:29,689 DEBUG org.apache.http.impl.conn.DefaultManagedHttpClientConnection - http-outgoing-0: Close connection
 2016-12-19 13:45:29,691 DEBUG org.apache.http.impl.execchain.MainClientExec - Connection discarded
 2016-12-19 13:45:29,691 DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager - Connection released: [id: 0][route: {}->http://localhost:16445][total kept alive: 0; route allocated: 0 of 2000; total allocated: 0 of 2000]
Dec 19, 2016 1:45:29 PM org.openqa.selenium.remote.ProtocolHandshake createSession
INFO: Detected dialect: W3C
 2016-12-19 13:45:29,724 DEBUG org.apache.http.client.protocol.RequestAddCookies - CookieSpec selected: default
 2016-12-19 13:45:29,724 DEBUG org.apache.http.client.protocol.RequestAuthCache - Auth cache not set in the context
 2016-12-19 13:45:29,725 DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager - Connection request: [route: {}->http://localhost:16445][total kept alive: 0; route allocated: 0 of 2000; total allocated: 0 of 2000]
 2016-12-19 13:45:29,725 DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager - Connection leased: [id: 1][route: {}->http://localhost:16445][total kept alive: 0; route allocated: 1 of 2000; total allocated: 1 of 2000]
 2016-12-19 13:45:29,725 DEBUG org.apache.http.impl.execchain.MainClientExec - Opening connection {}->http://localhost:16445
 2016-12-19 13:45:29,726 DEBUG org.apache.http.impl.conn.DefaultHttpClientConnectionOperator - Connecting to localhost/127.0.0.1:16445
 2016-12-19 13:45:29,727 DEBUG org.apache.http.impl.conn.DefaultHttpClientConnectionOperator - Connection established 127.0.0.1:49377<->127.0.0.1:16445
 2016-12-19 13:45:29,727 DEBUG org.apache.http.impl.conn.DefaultManagedHttpClientConnection - http-outgoing-1: set socket timeout to 10800000
 2016-12-19 13:45:29,727 DEBUG org.apache.http.impl.execchain.MainClientExec - Executing request POST /session/053c62a8-a29b-cf4a-b537-911f22e376d4/url HTTP/1.1
 2016-12-19 13:45:29,727 DEBUG org.apache.http.impl.execchain.MainClientExec - Target auth state: UNCHALLENGED
 2016-12-19 13:45:29,727 DEBUG org.apache.http.impl.execchain.MainClientExec - Proxy auth state: UNCHALLENGED
 2016-12-19 13:45:29,728 DEBUG org.apache.http.headers - http-outgoing-1 >> POST /session/053c62a8-a29b-cf4a-b537-911f22e376d4/url HTTP/1.1
 2016-12-19 13:45:29,728 DEBUG org.apache.http.headers - http-outgoing-1 >> Content-Type: application/json; charset=utf-8
 2016-12-19 13:45:29,728 DEBUG org.apache.http.headers - http-outgoing-1 >> Content-Length: 27
 2016-12-19 13:45:29,728 DEBUG org.apache.http.headers - http-outgoing-1 >> Host: localhost:16445
 2016-12-19 13:45:29,728 DEBUG org.apache.http.headers - http-outgoing-1 >> Connection: Keep-Alive
 2016-12-19 13:45:29,728 DEBUG org.apache.http.headers - http-outgoing-1 >> User-Agent: Apache-HttpClient/4.5.2 (Java/1.8.0_91)
 2016-12-19 13:45:29,728 DEBUG org.apache.http.headers - http-outgoing-1 >> Accept-Encoding: gzip,deflate
 2016-12-19 13:45:29,728 DEBUG org.apache.http.wire - http-outgoing-1 >> "POST /session/053c62a8-a29b-cf4a-b537-911f22e376d4/url HTTP/1.1[\r][\n]"
 2016-12-19 13:45:29,728 DEBUG org.apache.http.wire - http-outgoing-1 >> "Content-Type: application/json; charset=utf-8[\r][\n]"
 2016-12-19 13:45:29,728 DEBUG org.apache.http.wire - http-outgoing-1 >> "Content-Length: 27[\r][\n]"
 2016-12-19 13:45:29,728 DEBUG org.apache.http.wire - http-outgoing-1 >> "Host: localhost:16445[\r][\n]"
 2016-12-19 13:45:29,728 DEBUG org.apache.http.wire - http-outgoing-1 >> "Connection: Keep-Alive[\r][\n]"
 2016-12-19 13:45:29,729 DEBUG org.apache.http.wire - http-outgoing-1 >> "User-Agent: Apache-HttpClient/4.5.2 (Java/1.8.0_91)[\r][\n]"
 2016-12-19 13:45:29,729 DEBUG org.apache.http.wire - http-outgoing-1 >> "Accept-Encoding: gzip,deflate[\r][\n]"
 2016-12-19 13:45:29,729 DEBUG org.apache.http.wire - http-outgoing-1 >> "[\r][\n]"
 2016-12-19 13:45:29,729 DEBUG org.apache.http.wire - http-outgoing-1 >> "{"url":"http://google.com"}"
 2016-12-19 13:45:31,534 DEBUG org.apache.http.wire - http-outgoing-1 << "HTTP/1.1 200 OK[\r][\n]"
 2016-12-19 13:45:31,534 DEBUG org.apache.http.wire - http-outgoing-1 << "Date: Mon, 19 Dec 2016 10:45:31 GMT[\r][\n]"
 2016-12-19 13:45:31,535 DEBUG org.apache.http.wire - http-outgoing-1 << "Content-Length: 2[\r][\n]"
 2016-12-19 13:45:31,535 DEBUG org.apache.http.wire - http-outgoing-1 << "Content-Type: application/json[\r][\n]"
 2016-12-19 13:45:31,535 DEBUG org.apache.http.wire - http-outgoing-1 << "Connection: close[\r][\n]"
 2016-12-19 13:45:31,535 DEBUG org.apache.http.wire - http-outgoing-1 << "[\r][\n]"
 2016-12-19 13:45:31,535 DEBUG org.apache.http.wire - http-outgoing-1 << "{}"
 2016-12-19 13:45:31,535 DEBUG org.apache.http.headers - http-outgoing-1 << HTTP/1.1 200 OK
 2016-12-19 13:45:31,535 DEBUG org.apache.http.headers - http-outgoing-1 << Date: Mon, 19 Dec 2016 10:45:31 GMT
 2016-12-19 13:45:31,535 DEBUG org.apache.http.headers - http-outgoing-1 << Content-Length: 2
 2016-12-19 13:45:31,535 DEBUG org.apache.http.headers - http-outgoing-1 << Content-Type: application/json
 2016-12-19 13:45:31,535 DEBUG org.apache.http.headers - http-outgoing-1 << Connection: close
 2016-12-19 13:45:31,536 DEBUG org.apache.http.impl.conn.DefaultManagedHttpClientConnection - http-outgoing-1: Close connection
 2016-12-19 13:45:31,536 DEBUG org.apache.http.impl.execchain.MainClientExec - Connection discarded
 2016-12-19 13:45:31,536 DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager - Connection released: [id: 1][route: {}->http://localhost:16445][total kept alive: 0; route allocated: 0 of 2000; total allocated: 0 of 2000]
...
Will libevent been updated in mozilla-central? Couldn't find a bug for this. Or can we apply this change downstream to fix this?
https://github.com/libevent/libevent/commit/df6f99e5b51a3c0786f54cb9822604ec63385400
(This change has fixed this warning for me)
Jim, who maintains ipc/chromium for macOS? Without this fix from upstream libevent, Firefox on macOS 10.12 falls back from the preferred kqueue API to a less efficient poll API. This may be a responsiveness regression on the most popular version of macOS.
Flags: needinfo?(jmathies)
Guys,

Meanwhile, could you please suggest a workaround for the case I've described (if possible)? 

Btw, I tried to install the latest libevent but it didn't help.

Thanks in advance!
(In reply to Chris Peterson (out until January 2) [:cpeterson] from comment #3)
> Jim, who maintains ipc/chromium for macOS? Without this fix from upstream
> libevent, Firefox on macOS 10.12 falls back from the preferred kqueue API to
> a less efficient poll API. This may be a responsiveness regression on the
> most popular version of macOS.

https://bugzilla.mozilla.org/page.cgi?id=triage_owners.html

Billm owns the older ipc chromium library. Bill, any other suggestions?

I have a couple people in platint that could take a look - spohl or dparks. We'll have to wait until the holiday break is over though.
Flags: needinfo?(jmathies) → needinfo?(wmccloskey)
Attached patch patchSplinter Review
I just copied the Chrome change at:
https://bugs.chromium.org/p/chromium/issues/detail?id=626534

I doubt this has much impact. We don't have many file descriptors, so poll() is probably fast enough.
Assignee: nobody → wmccloskey
Status: NEW → ASSIGNED
Flags: needinfo?(wmccloskey)
Attachment #8823451 - Flags: review?(dvander)
Attachment #8823451 - Flags: review?(dvander) → review+
Pushed by wmccloskey@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/5f820525e90d
Remove libevent workaround for MacOS 10.4 bug (r=dvander)
https://hg.mozilla.org/mozilla-central/rev/5f820525e90d
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla53
Is it something that we want to uplift? Thanks
Flags: needinfo?(wmccloskey)
Comment on attachment 8823451 [details] [diff] [review]
patch

[Approval Request Comment]
If this is not a sec:{high,crit} bug, please state case for ESR consideration: Scary message is printed to console when opening Firefox (see comment 0)
User impact if declined: Possible performance impact, likely to be small. Also, the message makes us look bad.
Fix Landed on Version: 53
Risk to taking this patch (and alternatives if risky): Very low risk (unless you're on MacOS 10.4, which I think we don't support).
String or UUID changes made by this patch: None

See https://wiki.mozilla.org/Release_Management/ESR_Landing_Process for more info.

Approval Request Comment
[Feature/Bug causing the regression]: New MacOS version
[User impact if declined]: See above
[Is this code covered by automated tests?]: No
[Has the fix been verified in Nightly?]: No
[Needs manual test from QE? If yes, steps to reproduce]: Run on MacOS 10.12, look for error message on startup.
[List of other uplifts needed for the feature/fix]: None
[Is the change risky?]: No.
[Why is the change risky/not risky?]: It removes some old compatibility code for MacOS 10.4 that doesn't work in 10.12.
[String changes made/needed]: None
Flags: needinfo?(wmccloskey)
Attachment #8823451 - Flags: approval-mozilla-esr45?
Attachment #8823451 - Flags: approval-mozilla-beta?
Attachment #8823451 - Flags: approval-mozilla-aurora?
Comment on attachment 8823451 [details] [diff] [review]
patch

avoid libevent error message due to no longer needed osx 10.4 compat code in aurora52
Attachment #8823451 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Comment on attachment 8823451 [details] [diff] [review]
patch

Avoid perf/error logging problem for new MacOS, OK to uplift to beta.
Attachment #8823451 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Flagging this for manual testing, instructions available in Comment 10.
Flags: qe-verify+
Comment on attachment 8823451 [details] [diff] [review]
patch

It seems like a good idea to take this in ESR45.7.
Attachment #8823451 - Flags: approval-mozilla-esr45? → approval-mozilla-esr45+
Hi Chris, could you please verify this issue is fixed as expected on a latest Beta/Aurora/Nightly builds? Thanks!
Flags: needinfo?(cpeterson)
Verified fixed in Nightly 53, Aurora 52, and Beta 51.
(In reply to Ritu Kothari (:ritu) from comment #16)
> Comment on attachment 8823451 [details] [diff] [review]
> patch
> 
> It seems like a good idea to take this in ESR45.7.

Just a polite request, again, to be cc'ed on bugs removing old OS X support: TenFourFox is built off ESR, and this bug would need to be reverted in it if it lands on 45. I can do that but I didn't even know about this until I was browsing changes in mozilla-beta.
You need to log in before you can comment on or make changes to this bug.