Open Bug 1570977 Opened 2 years ago Updated 2 years ago

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

Categories

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

defect

Tracking

()

ASSIGNED

People

(Reporter: padenot, Assigned: kinetik)

References

(Blocks 1 open bug)

Details

Attachments

(1 file)

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...
Blocks: 1425788
Priority: -- → P2

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

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.

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.

Flags: needinfo?(kinetik)

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.

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.

Flags: needinfo?(kinetik)
Assignee: nobody → kinetik
Status: NEW → ASSIGNED

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

You need to log in before you can comment on or make changes to this bug.