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

Status: VERIFIED FIXED

(Core :: IPC, defect)

Description

[Chris Peterson [:cpeterson]]

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

Comment 1

[hanna]

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]
...

Comment 2

[Nomis101]

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)

Comment 3

[Chris Peterson [:cpeterson]]

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.

Comment 4

[hanna]

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!

Comment 5

[Jim Mathies [:jimm]]

(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.

Comment 6

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Attachment: patch

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.

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/5f820525e90d
Remove libevent workaround for MacOS 10.4 bug (r=dvander)

Comment 8

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/5f820525e90d

Comment 9

[Sylvestre Ledru [:Sylvestre]]

Is it something that we want to uplift? Thanks

Comment 10

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

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

Comment 11

[Julien Cristau [:jcristau]]

Comment on attachment 8823451 [details] [diff] [review]
patch

avoid libevent error message due to no longer needed osx 10.4 compat code in aurora52

Comment 12

[Liz Henry (:lizzard) (relman/hg->git project)]

Comment on attachment 8823451 [details] [diff] [review]
patch

Avoid perf/error logging problem for new MacOS, OK to uplift to beta.

Comment 13

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/releases/mozilla-aurora/rev/043b3b44cd5c

Comment 14

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/releases/mozilla-beta/rev/b74c313b7605

Comment 15

[Andrei Vaida [:avaida]]

Flagging this for manual testing, instructions available in Comment 10.

Comment 16

[Ritu Kothari (:ritu) (Inactive, please n-i to RyanVM, jcristau, or pascal)]

Comment on attachment 8823451 [details] [diff] [review]
patch

It seems like a good idea to take this in ESR45.7.

Comment 17

[Ritu Kothari (:ritu) (Inactive, please n-i to RyanVM, jcristau, or pascal)]

Hi Chris, could you please verify this issue is fixed as expected on a latest Beta/Aurora/Nightly builds? Thanks!

Comment 18

[Chris Peterson [:cpeterson]]

Verified fixed in Nightly 53, Aurora 52, and Beta 51.

Comment 19

[Cameron Kaiser [:spectre]]

(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.

Comment 20

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-esr45/rev/4d82e7314a72