New issue
Advanced search Search tips

Issue 836370 link

Starred by 2 users

Issue metadata

Status: Assigned
Owner:
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Linux , Windows , Chrome , Mac
Pri: 2
Type: Bug



Sign in to add a comment

lastError messages inconsistently logged for messaging APIs with native extension bindings

Reported by woxxom@gmail.com, Apr 24 2018

Issue description

Chrome 68
Windows 7

==========================

1. open chrome://extensions
2. enable developer mode
3. install the attached extension
4. click its "background page"
5. switch to console

Expected: 0 errors or exactly 2 errors
Observed: 1 error "Unchecked runtime.lastError: Could not establish connection. Receiving end does not exist."

==========================

Bisected the underlying CL using "--enable-features=NativeCrxBindings" command line
to b15f7f04de19b4e835f7be615a1d488876f8d086 = https://crrev.com/c/860755 by rdevlin.cronin@chromium.org
"[Extensions Bindings] Finish messaging-related implementations"
Landed in 66.0.3336.0 (disabled by default)

==========================

Notes:

* No errors were shown with the old JS bindings.
  Looks like a bug, and NativeCrxBindings fixed it.

* The error isn't shown when the callback is not specified with NativeCrxBindings:
  chrome.tabs.sendMessage(tab.id, 'foo');
  Looks like a bug.
 
test-ext.zip
557 bytes Download
bad.png
37.9 KB View Download
Cc: -rdevlin....@chromium.org
Owner: rdevlin....@chromium.org
Status: Assigned (was: Unconfirmed)
Cc: lazyboy@chromium.org jbroman@chromium.org
Labels: -Pri-3 OS-Chrome OS-Linux OS-Mac OS-Windows Pri-2
Summary: Extension Native Bindings: No runtime.lastErrors are logged without including a callback (was: Inconsistent error message when sending messages into pages that don't have a recipient)
I've investigated this.  The reason this happens is because we short-circuit if there's no callback, and don't actually deliver the error anywhere (this is most directly affected by [1]).  The side effect of this is that we also don't display the error message.  It seems like this is something we would ideally show, since we know the connection failed.  On the downside, it's not a terribly actionable error - there's no identifying information, and it happens asynchronously from the call site.  But we probably should still show something.

In looking into this, I realized that we have a similar problem for all API calls where the extension doesn't supply a callback function.  In none of them do we surface an error if the extension doesn't supply a callback.  We definitely should, for parity with JS bindings.

I'm going to broaden the scope of this bug, to include that as well.

Thanks for the report, woxxom@!

[1] https://chromium.googlesource.com/chromium/src/+/b9612d09b3d6879337d0795a8b82011d7cf4eee1/extensions/renderer/renderer_messaging_service.cc#200
Cc: rob@robwu.nl
For the specific case of messaging, this is also a little interesting.  One of the reasons we don't receive an error is because we immediately close the port if no response is expected.  We do this in both the old JS bindings [1] and the new native bindings [2].  Since the port is immediately disconnected, the browser never sends the disconnected message with the error about the receiving end.

There are some benefits to this: we can immediately remove the port entry from the map, and we don't have to bother sending a response to the opener.  The first is probably not a huge impact, and the second really only matters if the extension responds to the message *and* didn't have a callback - which I hope is pretty rare.

We could change this behavior to always expect a response, even for sendMessage calls that don't have a reply.  This allows us to throw proper errors in this case, as well as settling on one flow for the IPCs.  I'm not *too* concerned about the performance overhead this would incur (and as a future improvement, we could include a "can receive response" bit on the message - this would allow us to avoid any serialization in the browser or renderer, as well as log an error for extensions that try to respond when the initiator doesn't have a callback).  One other risk is that it might increase port leakage, but it shouldn't inherently do so.

Right now, I'm slightly leaning towards making the change to not disconnect the port immediately, and instead rely on the browser sending the disconnect signal.  But I'd like other opinions, and to know if anyone spots something I'm missing. :)

lazyboy@, jbroman@, woxxom@, any thoughts?  Also +Rob, since he's done quite a bit of work in the messaging code.

[1] https://chromium.googlesource.com/chromium/src/+/57e2ceecf8d901a03d123412762172e7991ddbf9/extensions/renderer/resources/messaging.js
[2] https://chromium.googlesource.com/chromium/src/+/aed202f9cec76ccbfcea6caa7c3ac6ee49ee8c79/extensions/renderer/one_time_message_handler.cc#205

Comment 4 by woxxom@gmail.com, Apr 25 2018

FWIW, for tabs.sendMessage Firefox shows the "Receiving end does not exist" error both when there's no callback or the callback didn't check runtime.lastError. The benefit of error reporting here is that it's possible to check for the lack of response explicitly instead of abusing the response parameter of the callback being "undefined". The downside is there can be [some? many?] Chrome extensions that will start spamming the console with errors once NativeCrxBindings is enabled by default.

Comment 5 by rob@robwu.nl, Apr 25 2018

In the messaging API, unchecked errors were never reported with JS bindings (but lastError is set).

I guess that if we start to report unchecked errors in messaging, that lots of log spam is going to be generated. So it's probably better to try and preserve the existing behavior.
Summary: lastError messages inconsistently logged for messaging APIs with native extension bindings (was: Extension Native Bindings: No runtime.lastErrors are logged without including a callback)
Hmm... given both woxxom@ and rob@ mentioned the concern for logspam, I'm retracting my opinion that we should just fix this as part of native bindings.  Instead, let's target native bindings have the same behavior, but I'll see if I can add some UMA for how often messages fail and last error is unchecked.  If it's reasonably low (e.g., < 1% of calls), I think it might be worth adding to help developers.

To that end, I'm going to separate this back out from the general "no errors logged when no callback provided" for native bindings bug, and file that one separately.

Sorry for the churn, folks, and thanks for the thoughtful responses!
Filed  issue 839528  for the generic bug.

Sign in to add a comment