[pulseaudio-discuss] [PATCH] bluetooth: Don't abort on SBC decoding error

[James Bunton]

---
src/modules/bluetooth/module-bluez5-device.c | 12 +++++++-----
1 file changed, 7 insertions(+), 5 deletions(-)

diff --git a/src/modules/bluetooth/module-bluez5-device.c b/src/modules/bluetooth/module-bluez5-device.c
index 287e763..61723f8 100644
--- a/src/modules/bluetooth/module-bluez5-device.c
+++ b/src/modules/bluetooth/module-bluez5-device.c
@@ -458,7 +458,7 @@ static int a2dp_process_push(struct userdata *u) {
pa_log_error("SBC decoding error (%li)", (long) decoded);
pa_memblock_release(memchunk.memblock);
pa_memblock_unref(memchunk.memblock);
- return -1;
+ return 0;
}

/* Reset frame length, it can be changed due to bitpool change */
@@ -1095,10 +1095,12 @@ static void thread_func(void *userdata) {
if (n_read < 0)
goto io_fail;

- /* We just read something, so we are supposed to write something, too */
- pending_read_bytes += n_read;
- do_write += pending_read_bytes / u->write_block_size;
- pending_read_bytes = pending_read_bytes % u->write_block_size;
+ if (n_read > 0) {
+ /* We just read something, so we are supposed to write something, too */
+ pending_read_bytes += n_read;
+ do_write += pending_read_bytes / u->write_block_size;
+ pending_read_bytes = pending_read_bytes % u->write_block_size;
+ }
}
}

[Tanu Kaskinen]

Post by James Bunton
---
src/modules/bluetooth/module-bluez5-device.c | 12 +++++++-----
1 file changed, 7 insertions(+), 5 deletions(-)

Thanks for the patch! What's the background here? Are there products on
the market that send invalid SBC data?

It seems that we update timing stuff before the decoding is done, which
means that with your change the timing information behaves as if we
received valid data, but the audio stream from the source doesn't
actually progress. To fix this mismatch, I think you should move the
timing updates to happen after successful decoding, or alternatively we
should replace the invalid data with a matching amount of silence.
(Something to note about the timing code is that it's currently actually
very broken, because "u->read_index += (uint64_t) l" in
a2dp_process_push() treats l as if it referred to the length of the
decoded PCM data, while in reality it refers to length of the RTP header
+ SBC data.)

If this change is justified, the same change should be done in
module-bluez4-device.c too.

[James Bunton]

Hi Tanu,

Thanks for the quick review! :)

My mobile phone (Nokia E7 running Symbian Belle Refresh) is connecting
to pulseaudio/bluez running on my Arch Linux on my Raspberry Pi. Without
this patch every few minutes pulseaudio will disconnect the stream and
log "SBC decoding error (-3)". As you can imagine this is quite
annoying! :)

I see what you mean about the timing code being wrong. What does
pulseaudio use this for? Should I expect to hear some audio glitches
with the current incorrect code, or is it just for display in a GUI?

I've modified it to use the number of bytes that sbc_decode reports it
wrote to the output buffer. Both versions seem to work equally well for
me.

You can see them here:
Repo URL: http://delx.net.au/git/pulseaudio
Patch1:
http://delx.net.au/git/pulseaudio/commitdiff/f66bec680d5a78778ef44910807020724ba4ebae
Patch2:
http://delx.net.au/git/pulseaudio/commitdiff/ba134901487a30633beafe335a5670a6586a65d4

I can submit these as patch files with git-send-email if that's
preferable for review.

Thanks again :)

--

James

[Tanu Kaskinen]

Post by James Bunton
Hi Tanu,
Thanks for the quick review! :)
My mobile phone (Nokia E7 running Symbian Belle Refresh) is connecting
to pulseaudio/bluez running on my Arch Linux on my Raspberry Pi. Without
this patch every few minutes pulseaudio will disconnect the stream and
log "SBC decoding error (-3)". As you can imagine this is quite
annoying! :)

Yes, I can believe that :) Please add this information to the commit
message too. The commit message should always answer the question "why
is this needed". Here's some more wisdom about commit messages:
http://who-t.blogspot.de/2009/12/on-commit-messages.html

Post by James Bunton
I see what you mean about the timing code being wrong. What does
pulseaudio use this for? Should I expect to hear some audio glitches
with the current incorrect code, or is it just for display in a GUI?

It's used for latency reporting. I don't think the latency information
is used much when recording, it's more important for playback
(lip-sync), but of course we still should strive for correct values in
the latency reports. I don't expect that you would hear glitches even if
the latency information is wrong.

Post by James Bunton
I've modified it to use the number of bytes that sbc_decode reports it
wrote to the output buffer. Both versions seem to work equally well for
me.

The read_index update is still not quite in the right place.
sbc_decode() is called in a loop, and if it fails at any iteration, then
read_index should not be updated. So, the update should happen after the
loop.

Post by James Bunton
Repo URL: http://delx.net.au/git/pulseaudio
http://delx.net.au/git/pulseaudio/commitdiff/f66bec680d5a78778ef44910807020724ba4ebae
http://delx.net.au/git/pulseaudio/commitdiff/ba134901487a30633beafe335a5670a6586a65d4
I can submit these as patch files with git-send-email if that's
preferable for review.

I prefer git send-email.

Post by James Bunton
Thanks again :)

Thanks for the patches!

[James Bunton]

The Nokia E7 running Symbian Belle Refresh seems to generate invalid SBC
packets every few minutes. This causes pulseaudio to disconnect the
stream and log "SBC decoding error (-3)".

If a single packet is bad, pulseaudio should keep playing the stream.
---
src/modules/bluetooth/module-bluez4-device.c | 12 +++++++-----
src/modules/bluetooth/module-bluez5-device.c | 12 +++++++-----
2 files changed, 14 insertions(+), 10 deletions(-)

diff --git a/src/modules/bluetooth/module-bluez4-device.c b/src/modules/bluetooth/module-bluez4-device.c
index 83e603f..90b1bcd 100644
--- a/src/modules/bluetooth/module-bluez4-device.c
+++ b/src/modules/bluetooth/module-bluez4-device.c
@@ -937,7 +937,7 @@ static int a2dp_process_push(struct userdata *u) {
pa_log_error("SBC decoding error (%li)", (long) decoded);
pa_memblock_release(memchunk.memblock);
pa_memblock_unref(memchunk.memblock);
- return -1;
+ return 0;
}

/* pa_log_debug("SBC: decoded: %lu; written: %lu", (unsigned long) decoded, (unsigned long) written); */
@@ -1039,10 +1039,12 @@ static void thread_func(void *userdata) {
if (n_read < 0)
goto io_fail;

- /* We just read something, so we are supposed to write something, too */
- pending_read_bytes += n_read;
- do_write += pending_read_bytes / u->write_block_size;
- pending_read_bytes = pending_read_bytes % u->write_block_size;
+ if (n_read > 0) {
+ /* We just read something, so we are supposed to write something, too */
+ pending_read_bytes += n_read;
+ do_write += pending_read_bytes / u->write_block_size;
+ pending_read_bytes = pending_read_bytes % u->write_block_size;
+ }
}
}

diff --git a/src/modules/bluetooth/module-bluez5-device.c b/src/modules/bluetooth/module-bluez5-device.c
index 287e763..61723f8 100644
--- a/src/modules/bluetooth/module-bluez5-device.c
+++ b/src/modules/bluetooth/module-bluez5-device.c
@@ -458,7 +458,7 @@ static int a2dp_process_push(struct userdata *u) {
pa_log_error("SBC decoding error (%li)", (long) decoded);
pa_memblock_release(memchunk.memblock);
pa_memblock_unref(memchunk.memblock);
- return -1;
+ return 0;
}

/* Reset frame length, it can be changed due to bitpool change */
@@ -1095,10 +1095,12 @@ static void thread_func(void *userdata) {
if (n_read < 0)
goto io_fail;

- /* We just read something, so we are supposed to write something, too */
- pending_read_bytes += n_read;
- do_write += pending_read_bytes / u->write_block_size;
- pending_read_bytes = pending_read_bytes % u->write_block_size;
+ if (n_read > 0) {
+ /* We just read something, so we are supposed to write something, too */
+ pending_read_bytes += n_read;
+ do_write += pending_read_bytes / u->write_block_size;
+ pending_read_bytes = pending_read_bytes % u->write_block_size;
+ }
}
}

[James Bunton]

Currently the latency information is being updated based on the encoded
SBC data instead of the decoded PCM data. Fixing this required moving
the timing update to be after the packet has been decoded.
---

Post by Tanu Kaskinen
The read_index update is still not quite in the right place.
sbc_decode() is called in a loop, and if it fails at any iteration,
then read_index should not be updated. So, the update should happen
after the loop.

I have updated the code to save the decoded byte count into a temporary
variable which is then used to update read_index.

Please let me know if anything else needs to be changed :)

Thanks!

src/modules/bluetooth/module-bluez4-device.c | 12 +++++++-----
src/modules/bluetooth/module-bluez5-device.c | 12 +++++++-----
2 files changed, 14 insertions(+), 10 deletions(-)

diff --git a/src/modules/bluetooth/module-bluez4-device.c b/src/modules/bluetooth/module-bluez4-device.c
index 90b1bcd..c70e4a6 100644
--- a/src/modules/bluetooth/module-bluez4-device.c
+++ b/src/modules/bluetooth/module-bluez4-device.c
@@ -881,6 +881,7 @@ static int a2dp_process_push(struct userdata *u) {
void *d;
ssize_t l;
size_t to_write, to_decode;
+ size_t total_written = 0;

a2dp_prepare_buffer(u);

@@ -907,17 +908,12 @@ static int a2dp_process_push(struct userdata *u) {

pa_assert((size_t) l <= a2dp->buffer_size);

- u->read_index += (uint64_t) l;
-
/* TODO: get timestamp from rtp */
if (!found_tstamp) {
/* pa_log_warn("Couldn't find SO_TIMESTAMP data in auxiliary recvmsg() data!"); */
tstamp = pa_rtclock_now();
}

- pa_smoother_put(u->read_smoother, tstamp, pa_bytes_to_usec(u->read_index, &u->sample_spec));
- pa_smoother_resume(u->read_smoother, tstamp, true);
-
p = (uint8_t*) a2dp->buffer + sizeof(*header) + sizeof(*payload);
to_decode = l - sizeof(*header) - sizeof(*payload);

@@ -943,6 +939,8 @@ static int a2dp_process_push(struct userdata *u) {
/* pa_log_debug("SBC: decoded: %lu; written: %lu", (unsigned long) decoded, (unsigned long) written); */
/* pa_log_debug("SBC: frame_length: %lu; codesize: %lu", (unsigned long) a2dp->frame_length, (unsigned long) a2dp->codesize); */

+ total_written += written;
+
/* Reset frame length, it can be changed due to bitpool change */
a2dp->frame_length = sbc_get_frame_length(&a2dp->sbc);

@@ -958,6 +956,10 @@ static int a2dp_process_push(struct userdata *u) {
to_write -= written;
}

+ u->read_index += (uint64_t) total_written;
+ pa_smoother_put(u->read_smoother, tstamp, pa_bytes_to_usec(u->read_index, &u->sample_spec));
+ pa_smoother_resume(u->read_smoother, tstamp, true);
+
memchunk.length -= to_write;

pa_memblock_release(memchunk.memblock);
diff --git a/src/modules/bluetooth/module-bluez5-device.c b/src/modules/bluetooth/module-bluez5-device.c
index 61723f8..857a972 100644
--- a/src/modules/bluetooth/module-bluez5-device.c
+++ b/src/modules/bluetooth/module-bluez5-device.c
@@ -402,6 +402,7 @@ static int a2dp_process_push(struct userdata *u) {
void *d;
ssize_t l;
size_t to_write, to_decode;
+ size_t total_written = 0;

a2dp_prepare_buffer(u);

@@ -428,17 +429,12 @@ static int a2dp_process_push(struct userdata *u) {

pa_assert((size_t) l <= sbc_info->buffer_size);

- u->read_index += (uint64_t) l;
-
/* TODO: get timestamp from rtp */
if (!found_tstamp) {
/* pa_log_warn("Couldn't find SO_TIMESTAMP data in auxiliary recvmsg() data!"); */
tstamp = pa_rtclock_now();
}

- pa_smoother_put(u->read_smoother, tstamp, pa_bytes_to_usec(u->read_index, &u->sample_spec));
- pa_smoother_resume(u->read_smoother, tstamp, true);
-
p = (uint8_t*) sbc_info->buffer + sizeof(*header) + sizeof(*payload);
to_decode = l - sizeof(*header) - sizeof(*payload);

@@ -461,6 +457,8 @@ static int a2dp_process_push(struct userdata *u) {
return 0;
}

+ total_written += written;
+
/* Reset frame length, it can be changed due to bitpool change */
sbc_info->frame_length = sbc_get_frame_length(&sbc_info->sbc);

@@ -476,6 +474,10 @@ static int a2dp_process_push(struct userdata *u) {
to_write -= written;
}

+ u->read_index += (uint64_t) total_written;
+ pa_smoother_put(u->read_smoother, tstamp, pa_bytes_to_usec(u->read_index, &u->sample_spec));
+ pa_smoother_resume(u->read_smoother, tstamp, true);
+
memchunk.length -= to_write;

pa_memblock_release(memchunk.memblock);

[Tanu Kaskinen]

Post by James Bunton
The Nokia E7 running Symbian Belle Refresh seems to generate invalid SBC
packets every few minutes. This causes pulseaudio to disconnect the
stream and log "SBC decoding error (-3)".
If a single packet is bad, pulseaudio should keep playing the stream.
---
src/modules/bluetooth/module-bluez4-device.c | 12 +++++++-----
src/modules/bluetooth/module-bluez5-device.c | 12 +++++++-----
2 files changed, 14 insertions(+), 10 deletions(-)

Thanks! Both patches have been applied to the "next" branch.