Mojom Remote rejecting message despite valid parameters.

[Avynn Donaghe]

Does anyone know why a mojom client would reject messages if I have been able to verify that the parameters passed to the remote are all valid?

--- context ----

This issue is part of a chain of CLs that implement Speech Recognition for my teams goal. (PRD: go/schooltools)

The CL in question changes the architecture of the fake_speech_recognition_service test dependency such that it accepts multiple speechRecognition Clients (previously the FakeSpeechRecognizer only supported a single client, this was causing all sorts of issues downstream hence the current CL). These clients are then made self-owned receivers and a reference is passed back to the test class OnRecognizerBound and this reference is used to assert the correct behavior from the client.

The client itself is a FakeSpeechRecognizer which more or less tracks what methods have been called on it which we then use to assert correct behavior.

The interface is super simple, two methods: start and stop. However when the class under test calls start the message receiver associated with the AudioSourceFetcher rejects the message.

unfortunately the error message is super unhelpful:

```
2024-08-06T15:05:32.908519Z ERROR browser_tests[2839911:2839911]: [interface_endpoint_client.cc(723)] Message 0 rejected by interface media.mojom.AudioSourceFetcher
```

Class under test:
https://osscs.corp.google.com/chromium/chromium/src/+/main:chrome/browser/ash/accessibility/live_caption/system_live_caption_service.h;drc=6886e20294658465b0d2b0555f52cc2c069ec9f0;l=53

The client that is exposed to the class under test:
https://osscs.corp.google.com/chromium/chromium/src/+/main:chrome/browser/speech/speech_recognition_recognizer_client_impl.h;drc=fe132eeb21687c455d695d6af346f15454828d01;l=30

Note: the client class above uses a pattern where it passes a remote to itself to its client while binding its client remote, this pattern formalizes an asynchronous bi-di channel between the SpeechRecognizer and the client (in this case a FakeSpeechRecognizer posing as a AudioSourceFetcher). You can see where this happens in its implementation here:
https://osscs.corp.google.com/chromium/chromium/src/+/main:chrome/browser/speech/speech_recognition_recognizer_client_impl.cc;drc=d904acacb6cc997517e81e3421a31d453f3ef729;l=194

The interface in question is defined here: https://osscs.corp.google.com/chromium/chromium/src/+/main:media/mojo/mojom/speech_recognition_service.mojom;drc=810f5db25368d0c4ef7d35d21bb160dfeac4ec16;l=68

Essentially the call to start which is method 0 in this case tells the SpeechRecognizer to actually start the session, the recognizer can then use the remote it has for the client to emit transcription events.

I have verified that the parameters being passed to start are valid before they are passed, I'm not familiar enough with the nuances of Mojom to understand what other conditions cause the messageReceiver to reject my message.

here you can find the WIP CL in question: https://chromium-review.googlesource.com/c/chromium/src/+/5664296

[Ken Rockot]

On Tuesday, August 6, 2024 at 10:32:38 AM UTC-7 Avynn Donaghe wrote:

Does anyone know why a mojom client would reject messages if I have been able to verify that the parameters passed to the remote are all valid?

I really don't think there are any other reasons that could apply here.

First can you confirm from your debug logging that it's the sink_->Accept call which is failing in MessageDispatcher? I think this must be the case. And if you can repro locally, the generated code would be a good place to add logging. Specifically around the first case within AudioSourceFetcherStubDispatch::Accept.

However, I also see from the CL that both the factory remote and device ID are trivially valid. I'm much less certain about the AudioParameters. For those, since they're designated as  [Native] in mojom, validation is delegated to this code. I believe a rejection here would adequately explain the lack of more useful logging since this is a relatively rare edge case for validation. At least in a DCHECK-enabled build, most failures would log something more useful before the message you're seeing.

[Avynn Donaghe]

Hi Ken, chromium-mojo et. al. thanks for your quick reply!

The pointer to speech_recognition_service.mojom.cc and the params traits file is super helpful!  I wasn't sure where these generated files lived before but now knowing what to look for will really help in the future.

To answer your questions:
  1.) I would like to say that I can confirm that sink_->Accept is failing, however because of the oddness of what I've been experiencing I wouldn't rule it out that I'm chasing a red-herring here.  I have decorated MessageDispatcher::Accept with the following log:
```
bool MessageDispatcher::Accept(Message* message) {
  internal::MessageDispatchContext dispatch_context(message);
  DCHECK(sink_);
  if (validator_) {
    if (!validator_->Accept(message)) {
      LOG(WARNING) << "VALIDATOR REJECTS MESSAGE!";
      return false;
    }
  }

  if (!filter_) {
    const bool accepted = sink_->Accept(message);

    if (!accepted) {
      LOG(WARNING) << "Rejected by sink!";
    }

    return accepted;
  }
...
```
In logs I can see "Rejected by sink!" right before my test fails, so I think it's reasonable to think that sink_->Accept is failing here.

   2.) I added some logs to that params traits file, however they are never invoked (including a log to mark the start of the Read function you linked) So it seems like there's something I'm missing here...

So that being said I went ahead and started playing with some debug logs in the AudioSourceFetcherStubDispatch::Accept method and unfortunately I think that either I'm putting logs in the wrong file or whatever functions are pushed onto the stack between sink_->Accept in MessageDispatcher and AudioSourceFetcherStubDispatch::Accept are rejecting the request before it gets to the StubDispatch's Accept method.

I have been able to produce logs from AudioSourceFetcherProxy::Start, which I have determined executes correctly.  I suppose this isn't surprising because it seems like ::mojo::internal::SendMojoMessage looks like it probably preempts Accept on the message dispatcher side.

In the case that I may be putting my logs in the wrong file, could you confirm that I'm using the right generated files?
 - I'm building chromium in my out/Default directory with the shell-less flow.
 - (I don't think this is relevant but my args.gn for out/Default are:)

    -blink_symbol_level = 0

     dcheck_always_on = true
     target_os = "chromeos"
     use_clang_coverage = true
     is_component_build = true
     use_remoteexec = true
     ffmpeg_branding = "ChromeOS"
     is_debug = false
 - So given those pre-conditions I would expect to find the generated mojom file in: out/Default/gen/media/mojo/mojom/speech_recognition_service.mojom.cc

In the case that sink_->Accept calls something else before the StubDispatch's Accept method, is there any documentation on where that call goes? I'm guessing that sink_ IS the stub dispatcher but unfortunately with 60k overrides I don't actually know what tool I would use to verify that. Code Search refuses to run the full query on the overrides of sink_->Accept from what I've been able to tell.

If it might help, I'll add the context that I haven't made any changes to the params object, either how it is initialized or its structure as far as I can tell.  The actual changes in the CL change the FakeSpeechRecognitionService such that it is only responsible for binding self-owned receivers implemented by my new FakeSpeechRecognizer class and then passing references to the FakeSpeechRecognizer class back to the testing class.

I have uploaded a new patch to the CL that includes the Logs I've added to the param traits, because my out/* dir is gitignored I can't upload the logs in the generated file.

Thank you so much for helping, I'm sorry about the length of this message there's just a lot of context!

[Ken Rockot]

On Mon, Aug 12, 2024 at 9:35 AM Avynn Donaghe <av...@google.com> wrote:

Hi, just a gentle ping to see if there's any additional context I could provide!

Unfortunately, I'm completely blocked on this and I really cannot figure out what is going wrong here.

On Wed, Aug 7, 2024 at 8:25 AM Avynn Donaghe <av...@google.com> wrote:

Hi Ken, chromium-mojo et. al. thanks for your quick reply!

The pointer to speech_recognition_service.mojom.cc and the params traits file is super helpful!  I wasn't sure where these generated files lived before but now knowing what to look for will really help in the future.

To answer your questions:
  1.) I would like to say that I can confirm that sink_->Accept is failing, however because of the oddness of what I've been experiencing I wouldn't rule it out that I'm chasing a red-herring here.  I have decorated MessageDispatcher::Accept with the following log:
```
bool MessageDispatcher::Accept(Message* message) {
  internal::MessageDispatchContext dispatch_context(message);
  DCHECK(sink_);
  if (validator_) {
    if (!validator_->Accept(message)) {
      LOG(WARNING) << "VALIDATOR REJECTS MESSAGE!";
      return false;
    }
  }

  if (!filter_) {
    const bool accepted = sink_->Accept(message);

    if (!accepted) {
      LOG(WARNING) << "Rejected by sink!";
    }

    return accepted;
  }
...
```
In logs I can see "Rejected by sink!" right before my test fails, so I think it's reasonable to think that sink_->Accept is failing here.

Yes

 

   2.) I added some logs to that params traits file, however they are never invoked (including a log to mark the start of the Read function you linked) So it seems like there's something I'm missing here...

So that being said I went ahead and started playing with some debug logs in the AudioSourceFetcherStubDispatch::Accept method and unfortunately I think that either I'm putting logs in the wrong file or whatever functions are pushed onto the stack between sink_->Accept in MessageDispatcher and AudioSourceFetcherStubDispatch::Accept are rejecting the request before it gets to the StubDispatch's Accept method. 

I have been able to produce logs from AudioSourceFetcherProxy::Start, which I have determined executes correctly.  I suppose this isn't surprising because it seems like ::mojo::internal::SendMojoMessage looks like it probably preempts Accept on the message dispatcher side.

In the case that I may be putting my logs in the wrong file, could you confirm that I'm using the right generated files?
 - I'm building chromium in my out/Default directory with the shell-less flow.
 - (I don't think this is relevant but my args.gn for out/Default are:)

    -blink_symbol_level = 0

     dcheck_always_on = true
     target_os = "chromeos"
     use_clang_coverage = true
     is_component_build = true
     use_remoteexec = true
     ffmpeg_branding = "ChromeOS"
     is_debug = false
 - So given those pre-conditions I would expect to find the generated mojom file in: out/Default/gen/media/mojo/mojom/speech_recognition_service.mojom.cc

Seems right to me.

 

In the case that sink_->Accept calls something else before the StubDispatch's Accept method, is there any documentation on where that call goes? I'm guessing that sink_ IS the stub dispatcher but unfortunately with 60k overrides I don't actually know what tool I would use to verify that. Code Search refuses to run the full query on the overrides of sink_->Accept from what I've been able to tell.

So sink_->Accept effectively calls directly into InterfaceEndpointClient::HandleValidatedMessage (see dispatcher_ initialization and the definition of InterfaceEndpointClient::HandleIncomingMessageThunk for proof).

It would be worth logging failure branches in that method too. It's not immediately obvious to me how any but the last (returning the result of incoming_receiver_->Accept) could be failing here, but I think that must be the case if you don't see the stub being entered. Maybe something is triggering an error on the receiver such that encountered_error_ is true by the time the message arrives? This would be surprising though unless there is some bad (e.g. thread-unsafe) usage of the receiver.