1570977 - Very rare "broken pipe" error when running mda2 with cubeb sandboxing enabled on OSX

Status: RESOLVED FIXED

(Core :: Audio/Video: cubeb, defect, P2)

Description

[Paul Adenot (:padenot)]

This is an excerpt of the test running with RUST_LOG=audioipc=debug:

[task 2019-08-01T12:53:42.921Z] 12:53:42     INFO - GECKO(1726) | DEBUG 2019-08-01T12:53:42Z: audioipc_client::stream: ClientStream dropped...
[task 2019-08-01T12:53:42.921Z] 12:53:42     INFO - GECKO(1726) | DEBUG 2019-08-01T12:53:42Z: audioipc_server::server: Registering stream 0
[task 2019-08-01T12:53:42.921Z] 12:53:42     INFO - GECKO(1726) | DEBUG 2019-08-01T12:53:42Z: audioipc_client::stream: token = 0, handles = [PlatformHandle(20), PlatformHandle(30), PlatformHandle(42)]
[task 2019-08-01T12:53:42.922Z] 12:53:42     INFO - GECKO(1726) | DEBUG 2019-08-01T12:53:42Z: audioipc_server::server: Unexpected message Err(Custom { kind: BrokenPipe, error: StringError("broken pipe") }) during state callback
[task 2019-08-01T12:53:42.931Z] 12:53:42     INFO - GECKO(1726) | DEBUG 2019-08-01T12:53:42Z: audioipc_server::server: Unexpected message Err(Custom { kind: BrokenPipe, error: StringError("broken pipe") }) during data_callback
[task 2019-08-01T12:53:42.932Z] 12:53:42     INFO - GECKO(1726) | DEBUG 2019-08-01T12:53:42Z: audioipc_server::server: Unexpected message Err(Custom { kind: BrokenPipe, error: StringError("broken pipe") }) during state callback
[task 2019-08-01T12:53:43.122Z] 12:53:43     INFO - GECKO(1726) | DEBUG 2019-08-01T12:53:43Z: audioipc_client::stream: ClientStream dropped...

Comment 1

[Paul Adenot (:padenot)]

This seems to happen in the server when the client has closed its side, but I don't know why.

Comment 2

[Paul Adenot (:padenot)]

Recent example: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=269480429&repo=try&lineNumber=11037

I'm running with with RUST_LOG=audioipc=tracing to see what's up, hoping to get a repro before the cutoff of the log because of the size.

Comment 3

[Paul Adenot (:padenot)]

Attachment: filtered log at level "tracing" of failing mda1 test on OSX with remoting ON

This is the result when logging at trace level, and then parsing the result with

rg  "(TEST-UNEX|BrokenPipe|TEST-START|TEST-OK|TEST-SKIP)" live_backing.log

It looks like there is somewhat a correlation between those BrokenPipe errors and the test failing, but maybe it's a reverse correlation: when the test fails, there is a BrokenPipe. Also sometimes, there are lots of broken pipe errors, but no test failure (by the end).

Matthew, do you see the same on Windows? Do you know whether it's expected to have those BrokenPipe issues? From reading the code, this happens in the server when a call to the client errored out, probably because the client end of the channel has closed it .

Next, I'm going to try to understand what is causing the client to close its end.

Comment 4

[Paul Adenot (:padenot)]

Do you know whether it's expected to have those BrokenPipe issues?

I don't think it is, after reading more code. I'm trying to get backtraces near the close call in the client, but somehow the backtrace crate doesn't seem to work when in Gecko.

Comment 5

[Matthew Gregan [:kinetik]]

Different issue to what I'm debugging on Windows, unfortunately.

The server is expected to handle abrupt terminations from clients cleanly, since it's necessary to handle situations where the client crashes (for example). It's possible there are places the server doesn't handle this correctly, which we'll need to fix.

Comment 6

[Matthew Gregan [:kinetik]]

This is still showing up with the latest fixes. I'll see if I can track it down.

Comment 7

[Matthew Gregan [:kinetik]]

Fixed in IPC core rewrite landed via bug 1726275.