mirrors/pipewire
1
0
Fork 0
mirror of https://gitlab.freedesktop.org/pipewire/pipewire.git synced 2025-12-17 08:56:49 -05:00
Code Issues Projects Releases Packages Wiki Activity Actions

bluez5: use log topics

Browse source 
Use log topics instead of prepending NAME: to log messages.
This commit is contained in:
Pauli Virtanen 2021-10-01 19:03:49 +03:00
parent 42d8b2b167
commit 58c7caf1bc
11 changed files with 387 additions and 345 deletions
Download patch file Download diff file Expand all files Collapse all files

68
spa/plugins/bluez5/a2dp-sink.c
View file

@ -55,7 +55,9 @@
#include "rtp.h" #include "rtp.h"
#include "a2dp-codecs.h" #include "a2dp-codecs.h"
struct codec; static struct spa_log_topic log_topic = SPA_LOG_TOPIC(0, "spa.bluez5.sink.a2dp");
#undef SPA_LOG_TOPIC_DEFAULT
#define SPA_LOG_TOPIC_DEFAULT &log_topic
struct props { struct props {
uint32_t min_latency; uint32_t min_latency;
@ -160,8 +162,6 @@ struct impl {
uint32_t fd_buffer_size; uint32_t fd_buffer_size;
}; };
#define NAME "a2dp-sink"
#define CHECK_PORT(this,d,p) ((d) == SPA_DIRECTION_INPUT && (p) == 0) #define CHECK_PORT(this,d,p) ((d) == SPA_DIRECTION_INPUT && (p) == 0)
static void reset_props(struct impl *this, struct props *props) static void reset_props(struct impl *this, struct props *props)
@ -331,7 +331,7 @@ static int impl_node_set_io(void *object, uint32_t id, void *data, size_t size)
following = is_following(this); following = is_following(this);
if (this->started && following != this->following) { if (this->started && following != this->following) {
spa_log_debug(this->log, NAME " %p: reassign follower %d->%d", this, this->following, following); spa_log_debug(this->log, "%p: reassign follower %d->%d", this, this->following, following);
this->following = following; this->following = following;
spa_loop_invoke(this->data_loop, do_reassign_follower, 0, NULL, 0, true, this); spa_loop_invoke(this->data_loop, do_reassign_follower, 0, NULL, 0, true, this);
} }
@ -438,10 +438,10 @@ static int get_transport_unused_size(struct impl *this)
int res, value; int res, value;
res = ioctl(this->flush_source.fd, TIOCOUTQ, &value); res = ioctl(this->flush_source.fd, TIOCOUTQ, &value);
if (res < 0) { if (res < 0) {
spa_log_error(this->log, NAME " %p: ioctl fail: %m", this); spa_log_error(this->log, "%p: ioctl fail: %m", this);
return -errno; return -errno;
} }
spa_log_trace(this->log, NAME " %p: fd unused buffer size:%d/%d", this, value, this->fd_buffer_size); spa_log_trace(this->log, "%p: fd unused buffer size:%d/%d", this, value, this->fd_buffer_size);
return value; return value;
} }
@ -454,17 +454,17 @@ static int send_buffer(struct impl *this)
this->codec->abr_process(this->codec_data, unsent); this->codec->abr_process(this->codec_data, unsent);
} }
spa_log_trace(this->log, NAME " %p: send %d %u %u %u %u", spa_log_trace(this->log, "%p: send %d %u %u %u %u",
this, this->frame_count, this->block_size, this->seqnum, this, this->frame_count, this->block_size, this->seqnum,
this->timestamp, this->buffer_used); this->timestamp, this->buffer_used);
written = send(this->flush_source.fd, this->buffer, written = send(this->flush_source.fd, this->buffer,
this->buffer_used, MSG_DONTWAIT | MSG_NOSIGNAL); this->buffer_used, MSG_DONTWAIT | MSG_NOSIGNAL);
spa_log_trace(this->log, NAME " %p: send %d", this, written); spa_log_trace(this->log, "%p: send %d", this, written);
if (written < 0) { if (written < 0) {
spa_log_debug(this->log, NAME " %p: %m", this); spa_log_debug(this->log, "%p: %m", this);
return -errno; return -errno;
} }
@ -484,7 +484,7 @@ static int encode_buffer(struct impl *this, const void *data, uint32_t size)
const void *from_data = data; const void *from_data = data;
int from_size = size; int from_size = size;
spa_log_trace(this->log, NAME " %p: encode %d used %d, %d %d %d", spa_log_trace(this->log, "%p: encode %d used %d, %d %d %d",
this, size, this->buffer_used, port->frame_size, this->block_size, this, size, this->buffer_used, port->frame_size, this->block_size,
this->frame_count); this->frame_count);
@ -517,7 +517,7 @@ static int encode_buffer(struct impl *this, const void *data, uint32_t size)
this->frame_count += processed / this->block_size; this->frame_count += processed / this->block_size;
this->buffer_used += out_encoded; this->buffer_used += out_encoded;
spa_log_trace(this->log, NAME " %p: processed %d %zd used %d", spa_log_trace(this->log, "%p: processed %d %zd used %d",
this, processed, out_encoded, this->buffer_used); this, processed, out_encoded, this->buffer_used);
if (this->tmp_buffer_used) { if (this->tmp_buffer_used) {
@ -529,7 +529,7 @@ static int encode_buffer(struct impl *this, const void *data, uint32_t size)
static int flush_buffer(struct impl *this) static int flush_buffer(struct impl *this)
{ {
spa_log_trace(this->log, NAME" %p: used:%d block_size:%d", this, spa_log_trace(this->log, "%p: used:%d block_size:%d", this,
this->buffer_used, this->block_size); this->buffer_used, this->block_size);
if (this->need_flush || want_flush(this)) if (this->need_flush || want_flush(this))
@ -603,7 +603,7 @@ again:
spa_list_remove(&b->link); spa_list_remove(&b->link);
SPA_FLAG_SET(b->flags, BUFFER_FLAG_OUT); SPA_FLAG_SET(b->flags, BUFFER_FLAG_OUT);
this->port.io->buffer_id = b->id; this->port.io->buffer_id = b->id;
spa_log_warn(this->log, NAME " %p: error %s, reuse buffer %u", spa_log_warn(this->log, "%p: error %s, reuse buffer %u",
this, spa_strerror(written), b->id); this, spa_strerror(written), b->id);
spa_node_call_reuse_buffer(&this->callbacks, 0, b->id); spa_node_call_reuse_buffer(&this->callbacks, 0, b->id);
port->ready_offset = 0; port->ready_offset = 0;
@ -618,7 +618,7 @@ again:
if (port->ready_offset >= d[0].chunk->size) { if (port->ready_offset >= d[0].chunk->size) {
spa_list_remove(&b->link); spa_list_remove(&b->link);
SPA_FLAG_SET(b->flags, BUFFER_FLAG_OUT); SPA_FLAG_SET(b->flags, BUFFER_FLAG_OUT);
spa_log_trace(this->log, NAME " %p: reuse buffer %u", this, b->id); spa_log_trace(this->log, "%p: reuse buffer %u", this, b->id);
this->port.io->buffer_id = b->id; this->port.io->buffer_id = b->id;
spa_node_call_reuse_buffer(&this->callbacks, 0, b->id); spa_node_call_reuse_buffer(&this->callbacks, 0, b->id);
@ -626,7 +626,7 @@ again:
} }
total_frames += n_frames; total_frames += n_frames;
spa_log_trace(this->log, NAME " %p: written %u frames", this, total_frames); spa_log_trace(this->log, "%p: written %u frames", this, total_frames);
} }
if (written > 0 && this->buffer_used == this->header_size) { if (written > 0 && this->buffer_used == this->header_size) {
@ -636,7 +636,7 @@ again:
written = flush_buffer(this); written = flush_buffer(this);
if (written == -EAGAIN) { if (written == -EAGAIN) {
spa_log_trace(this->log, NAME" %p: delay flush", this); spa_log_trace(this->log, "%p: delay flush", this);
if (now_time - this->last_error > SPA_NSEC_PER_SEC / 2) { if (now_time - this->last_error > SPA_NSEC_PER_SEC / 2) {
this->codec->reduce_bitpool(this->codec_data); this->codec->reduce_bitpool(this->codec_data);
this->last_error = now_time; this->last_error = now_time;
@ -645,7 +645,7 @@ again:
enable_flush(this, true); enable_flush(this, true);
} }
else if (written < 0) { else if (written < 0) {
spa_log_trace(this->log, NAME" %p: error flushing %s", this, spa_log_trace(this->log, "%p: error flushing %s", this,
spa_strerror(written)); spa_strerror(written));
reset_buffer(this); reset_buffer(this);
enable_flush(this, false); enable_flush(this, false);
@ -664,7 +664,7 @@ again:
} }
else { else {
/* Don't want to flush yet, or failed to write anything */ /* Don't want to flush yet, or failed to write anything */
spa_log_trace(this->log, NAME" %p: skip flush", this); spa_log_trace(this->log, "%p: skip flush", this);
enable_flush(this, false); enable_flush(this, false);
} }
return 0; return 0;
@ -674,10 +674,10 @@ static void a2dp_on_flush(struct spa_source *source)
{ {
struct impl *this = source->data; struct impl *this = source->data;
spa_log_trace(this->log, NAME" %p: flushing", this); spa_log_trace(this->log, "%p: flushing", this);
if (!SPA_FLAG_IS_SET(source->rmask, SPA_IO_OUT)) { if (!SPA_FLAG_IS_SET(source->rmask, SPA_IO_OUT)) {
spa_log_warn(this->log, NAME" %p: error %d", this, source->rmask); spa_log_warn(this->log, "%p: error %d", this, source->rmask);
if (this->flush_source.loop) if (this->flush_source.loop)
spa_loop_remove_source(this->data_loop, &this->flush_source); spa_loop_remove_source(this->data_loop, &this->flush_source);
return; return;
@ -703,7 +703,7 @@ static void a2dp_on_timeout(struct spa_source *source)
prev_time = this->current_time; prev_time = this->current_time;
now_time = this->current_time = this->next_time; now_time = this->current_time = this->next_time;
spa_log_debug(this->log, NAME" %p: timeout %"PRIu64" %"PRIu64"", this, spa_log_debug(this->log, "%p: timeout %"PRIu64" %"PRIu64"", this,
now_time, now_time - prev_time); now_time, now_time - prev_time);
if (SPA_LIKELY(this->position)) { if (SPA_LIKELY(this->position)) {
@ -734,7 +734,7 @@ static void a2dp_on_timeout(struct spa_source *source)
} }
spa_log_trace(this->log, NAME " %p: %d", this, io->status); spa_log_trace(this->log, "%p: %d", this, io->status);
io->status = SPA_STATUS_NEED_DATA; io->status = SPA_STATUS_NEED_DATA;
spa_node_call_ready(&this->callbacks, SPA_STATUS_NEED_DATA); spa_node_call_ready(&this->callbacks, SPA_STATUS_NEED_DATA);
@ -755,7 +755,7 @@ static int do_start(struct impl *this)
this->following = is_following(this); this->following = is_following(this);
spa_log_debug(this->log, NAME " %p: start following:%d", this, this->following); spa_log_debug(this->log, "%p: start following:%d", this, this->following);
if ((res = spa_bt_transport_acquire(this->transport, false)) < 0) if ((res = spa_bt_transport_acquire(this->transport, false)) < 0)
return res; return res;
@ -777,7 +777,7 @@ static int do_start(struct impl *this)
if (this->codec_data == NULL) if (this->codec_data == NULL)
return -EIO; return -EIO;
spa_log_info(this->log, NAME " %p: using A2DP codec %s, delay:%"PRIi64" ms", this, this->codec->description, spa_log_info(this->log, "%p: using A2DP codec %s, delay:%"PRIi64" ms", this, this->codec->description,
(int64_t)(spa_bt_transport_get_delay_nsec(this->transport) / SPA_NSEC_PER_MSEC)); (int64_t)(spa_bt_transport_get_delay_nsec(this->transport) / SPA_NSEC_PER_MSEC));
this->seqnum = 0; this->seqnum = 0;
@ -789,7 +789,7 @@ static int do_start(struct impl *this)
return -EIO; return -EIO;
} }
spa_log_debug(this->log, NAME " %p: block_size %d", this, spa_log_debug(this->log, "%p: block_size %d", this,
this->block_size); this->block_size);
val = this->codec->send_buf_size > 0 val = this->codec->send_buf_size > 0
@ -797,20 +797,20 @@ static int do_start(struct impl *this)
? this->codec->send_buf_size / 2 + this->codec->send_buf_size % 2 ? this->codec->send_buf_size / 2 + this->codec->send_buf_size % 2
: FILL_FRAMES * this->transport->write_mtu; : FILL_FRAMES * this->transport->write_mtu;
if (setsockopt(this->transport->fd, SOL_SOCKET, SO_SNDBUF, &val, sizeof(val)) < 0) if (setsockopt(this->transport->fd, SOL_SOCKET, SO_SNDBUF, &val, sizeof(val)) < 0)
spa_log_warn(this->log, NAME " %p: SO_SNDBUF %m", this); spa_log_warn(this->log, "%p: SO_SNDBUF %m", this);
len = sizeof(val); len = sizeof(val);
if (getsockopt(this->transport->fd, SOL_SOCKET, SO_SNDBUF, &val, &len) < 0) { if (getsockopt(this->transport->fd, SOL_SOCKET, SO_SNDBUF, &val, &len) < 0) {
spa_log_warn(this->log, NAME " %p: SO_SNDBUF %m", this); spa_log_warn(this->log, "%p: SO_SNDBUF %m", this);
} }
else { else {
spa_log_debug(this->log, NAME " %p: SO_SNDBUF: %d", this, val); spa_log_debug(this->log, "%p: SO_SNDBUF: %d", this, val);
} }
this->fd_buffer_size = val; this->fd_buffer_size = val;
val = FILL_FRAMES * this->transport->read_mtu; val = FILL_FRAMES * this->transport->read_mtu;
if (setsockopt(this->transport->fd, SOL_SOCKET, SO_RCVBUF, &val, sizeof(val)) < 0) if (setsockopt(this->transport->fd, SOL_SOCKET, SO_RCVBUF, &val, sizeof(val)) < 0)
spa_log_warn(this->log, NAME " %p: SO_RCVBUF %m", this); spa_log_warn(this->log, "%p: SO_RCVBUF %m", this);
val = 6; val = 6;
if (setsockopt(this->transport->fd, SOL_SOCKET, SO_PRIORITY, &val, sizeof(val)) < 0) if (setsockopt(this->transport->fd, SOL_SOCKET, SO_PRIORITY, &val, sizeof(val)) < 0)
@ -868,7 +868,7 @@ static int do_stop(struct impl *this)
if (!this->started) if (!this->started)
return 0; return 0;
spa_log_trace(this->log, NAME " %p: stop", this); spa_log_trace(this->log, "%p: stop", this);
spa_loop_invoke(this->data_loop, do_remove_source, 0, NULL, 0, true, this); spa_loop_invoke(this->data_loop, do_remove_source, 0, NULL, 0, true, this);
@ -1261,7 +1261,7 @@ impl_node_port_use_buffers(void *object,
b->h = spa_buffer_find_meta_data(buffers[i], SPA_META_Header, sizeof(*b->h)); b->h = spa_buffer_find_meta_data(buffers[i], SPA_META_Header, sizeof(*b->h));
if (buffers[i]->datas[0].data == NULL) { if (buffers[i]->datas[0].data == NULL) {
spa_log_error(this->log, NAME " %p: need mapped memory", this); spa_log_error(this->log, "%p: need mapped memory", this);
return -EINVAL; return -EINVAL;
} }
} }
@ -1316,12 +1316,12 @@ static int impl_node_process(void *object)
struct buffer *b = &port->buffers[io->buffer_id]; struct buffer *b = &port->buffers[io->buffer_id];
if (!SPA_FLAG_IS_SET(b->flags, BUFFER_FLAG_OUT)) { if (!SPA_FLAG_IS_SET(b->flags, BUFFER_FLAG_OUT)) {
spa_log_warn(this->log, NAME " %p: buffer %u in use", this, io->buffer_id); spa_log_warn(this->log, "%p: buffer %u in use", this, io->buffer_id);
io->status = -EINVAL; io->status = -EINVAL;
return -EINVAL; return -EINVAL;
} }
spa_log_trace(this->log, NAME " %p: queue buffer %u", this, io->buffer_id); spa_log_trace(this->log, "%p: queue buffer %u", this, io->buffer_id);
spa_list_append(&port->ready, &b->link); spa_list_append(&port->ready, &b->link);
SPA_FLAG_CLEAR(b->flags, BUFFER_FLAG_OUT); SPA_FLAG_CLEAR(b->flags, BUFFER_FLAG_OUT);
@ -1450,6 +1450,8 @@ impl_init(const struct spa_handle_factory *factory,
this->data_loop = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_DataLoop); this->data_loop = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_DataLoop);
this->data_system = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_DataSystem); this->data_system = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_DataSystem);
spa_log_topic_init(this->log, &log_topic);
if (this->data_loop == NULL) { if (this->data_loop == NULL) {
spa_log_error(this->log, "a data loop is needed"); spa_log_error(this->log, "a data loop is needed");
return -EINVAL; return -EINVAL;

36
spa/plugins/bluez5/a2dp-source.c
View file

@ -56,6 +56,10 @@
#include "rtp.h" #include "rtp.h"
#include "a2dp-codecs.h" #include "a2dp-codecs.h"
static struct spa_log_topic log_topic = SPA_LOG_TOPIC(0, "spa.bluez5.source.a2dp");
#undef SPA_LOG_TOPIC_DEFAULT
#define SPA_LOG_TOPIC_DEFAULT &log_topic
struct props { struct props {
uint32_t min_latency; uint32_t min_latency;
uint32_t max_latency; uint32_t max_latency;
@ -153,8 +157,6 @@ struct impl {
uint64_t duplex_timeout; uint64_t duplex_timeout;
}; };
#define NAME "a2dp-source"
#define CHECK_PORT(this,d,p) ((d) == SPA_DIRECTION_OUTPUT && (p) == 0) #define CHECK_PORT(this,d,p) ((d) == SPA_DIRECTION_OUTPUT && (p) == 0)
static const uint32_t default_min_latency = MIN_LATENCY; static const uint32_t default_min_latency = MIN_LATENCY;
@ -292,7 +294,7 @@ static int impl_node_set_io(void *object, uint32_t id, void *data, size_t size)
following = is_following(this); following = is_following(this);
if (this->started && following != this->following) { if (this->started && following != this->following) {
spa_log_debug(this->log, NAME" %p: reassign follower %d->%d", this, this->following, following); spa_log_debug(this->log, "%p: reassign follower %d->%d", this, this->following, following);
this->following = following; this->following = following;
spa_loop_invoke(this->data_loop, do_reassing_follower, 0, NULL, 0, true, this); spa_loop_invoke(this->data_loop, do_reassing_follower, 0, NULL, 0, true, this);
} }
@ -371,7 +373,7 @@ static void recycle_buffer(struct impl *this, struct port *port, uint32_t buffer
struct buffer *b = &port->buffers[buffer_id]; struct buffer *b = &port->buffers[buffer_id];
if (b->outstanding) { if (b->outstanding) {
spa_log_trace(this->log, NAME " %p: recycle buffer %u", this, buffer_id); spa_log_trace(this->log, "%p: recycle buffer %u", this, buffer_id);
spa_list_append(&port->free, &b->link); spa_list_append(&port->free, &b->link);
b->outstanding = false; b->outstanding = false;
} }
@ -517,7 +519,7 @@ static void a2dp_on_ready_read(struct spa_source *source)
return; return;
} }
if (this->skip_count > 0) { if (this->skip_count > 0) {
spa_log_info(this->log, NAME " %p: xrun, skipped %"PRIu64" usec", spa_log_info(this->log, "%p: xrun, skipped %"PRIu64" usec",
this, (uint64_t)(this->skip_count * SPA_USEC_PER_SEC / port->current_format.info.raw.rate)); this, (uint64_t)(this->skip_count * SPA_USEC_PER_SEC / port->current_format.info.raw.rate));
this->skip_count = 0; this->skip_count = 0;
} }
@ -542,7 +544,7 @@ static void a2dp_on_ready_read(struct spa_source *source)
/* copy data into buffer */ /* copy data into buffer */
avail = SPA_MIN(decoded, (int32_t)(datas[0].maxsize - port->ready_offset)); avail = SPA_MIN(decoded, (int32_t)(datas[0].maxsize - port->ready_offset));
if (avail < decoded) if (avail < decoded)
spa_log_warn(this->log, NAME ": buffer too small (%d > %d)", decoded, avail); spa_log_warn(this->log, "buffer too small (%d > %d)", decoded, avail);
memcpy ((uint8_t *)datas[0].data + port->ready_offset, read_decoded, avail); memcpy ((uint8_t *)datas[0].data + port->ready_offset, read_decoded, avail);
port->ready_offset += avail; port->ready_offset += avail;
this->sample_count += decoded / port->frame_size; this->sample_count += decoded / port->frame_size;
@ -635,7 +637,7 @@ static int transport_start(struct impl *this)
if (this->transport_acquired) if (this->transport_acquired)
return 0; return 0;
spa_log_debug(this->log, NAME" %p: transport %p acquire", this, spa_log_debug(this->log, "%p: transport %p acquire", this,
this->transport); this->transport);
if ((res = spa_bt_transport_acquire(this->transport, false)) < 0) if ((res = spa_bt_transport_acquire(this->transport, false)) < 0)
return res; return res;
@ -651,19 +653,19 @@ static int transport_start(struct impl *this)
if (this->codec_data == NULL) if (this->codec_data == NULL)
return -EIO; return -EIO;
spa_log_info(this->log, NAME " %p: using A2DP codec %s", this, this->codec->description); spa_log_info(this->log, "%p: using A2DP codec %s", this, this->codec->description);
val = fcntl(this->transport->fd, F_GETFL); val = fcntl(this->transport->fd, F_GETFL);
if (fcntl(this->transport->fd, F_SETFL, val | O_NONBLOCK) < 0) if (fcntl(this->transport->fd, F_SETFL, val | O_NONBLOCK) < 0)
spa_log_warn(this->log, NAME" %p: fcntl %u %m", this, val | O_NONBLOCK); spa_log_warn(this->log, "%p: fcntl %u %m", this, val | O_NONBLOCK);
val = FILL_FRAMES * this->transport->write_mtu; val = FILL_FRAMES * this->transport->write_mtu;
if (setsockopt(this->transport->fd, SOL_SOCKET, SO_SNDBUF, &val, sizeof(val)) < 0) if (setsockopt(this->transport->fd, SOL_SOCKET, SO_SNDBUF, &val, sizeof(val)) < 0)
spa_log_warn(this->log, NAME" %p: SO_SNDBUF %m", this); spa_log_warn(this->log, "%p: SO_SNDBUF %m", this);
val = FILL_FRAMES * this->transport->read_mtu; val = FILL_FRAMES * this->transport->read_mtu;
if (setsockopt(this->transport->fd, SOL_SOCKET, SO_RCVBUF, &val, sizeof(val)) < 0) if (setsockopt(this->transport->fd, SOL_SOCKET, SO_RCVBUF, &val, sizeof(val)) < 0)
spa_log_warn(this->log, NAME" %p: SO_RCVBUF %m", this); spa_log_warn(this->log, "%p: SO_RCVBUF %m", this);
val = 6; val = 6;
if (setsockopt(this->transport->fd, SOL_SOCKET, SO_PRIORITY, &val, sizeof(val)) < 0) if (setsockopt(this->transport->fd, SOL_SOCKET, SO_PRIORITY, &val, sizeof(val)) < 0)
@ -717,7 +719,7 @@ static int do_start(struct impl *this)
this->following = is_following(this); this->following = is_following(this);
spa_log_debug(this->log, NAME" %p: start state:%d following:%d", spa_log_debug(this->log, "%p: start state:%d following:%d",
this, this->transport->state, this->following); this, this->transport->state, this->following);
spa_return_val_if_fail(this->transport != NULL, -EIO); spa_return_val_if_fail(this->transport != NULL, -EIO);
@ -740,7 +742,7 @@ static int do_remove_source(struct spa_loop *loop,
{ {
struct impl *this = user_data; struct impl *this = user_data;
spa_log_debug(this->log, NAME" %p: remove source", this); spa_log_debug(this->log, "%p: remove source", this);
set_duplex_timeout(this, 0); set_duplex_timeout(this, 0);
@ -754,7 +756,7 @@ static int transport_stop(struct impl *this)
{ {
int res; int res;
spa_log_debug(this->log, NAME" %p: transport stop", this); spa_log_debug(this->log, "%p: transport stop", this);
spa_loop_invoke(this->data_loop, do_remove_source, 0, NULL, 0, true, this); spa_loop_invoke(this->data_loop, do_remove_source, 0, NULL, 0, true, this);
@ -779,7 +781,7 @@ static int do_stop(struct impl *this)
if (!this->started) if (!this->started)
return 0; return 0;
spa_log_debug(this->log, NAME" %p: stop", this); spa_log_debug(this->log, "%p: stop", this);
res = transport_stop(this); res = transport_stop(this);
@ -1174,7 +1176,7 @@ impl_node_port_use_buffers(void *object,
b->h = spa_buffer_find_meta_data(buffers[i], SPA_META_Header, sizeof(*b->h)); b->h = spa_buffer_find_meta_data(buffers[i], SPA_META_Header, sizeof(*b->h));
if (d[0].data == NULL) { if (d[0].data == NULL) {
spa_log_error(this->log, NAME " %p: need mapped memory", this); spa_log_error(this->log, "%p: need mapped memory", this);
return -EINVAL; return -EINVAL;
} }
spa_list_append(&port->free, &b->link); spa_list_append(&port->free, &b->link);
@ -1380,6 +1382,8 @@ impl_init(const struct spa_handle_factory *factory,
this->data_loop = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_DataLoop); this->data_loop = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_DataLoop);
this->data_system = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_DataSystem); this->data_system = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_DataSystem);
spa_log_topic_init(this->log, &log_topic);
if (this->data_loop == NULL) { if (this->data_loop == NULL) {
spa_log_error(this->log, "a data loop is needed"); spa_log_error(this->log, "a data loop is needed");
return -EINVAL; return -EINVAL;

150
spa/plugins/bluez5/backend-hsphfpd.c
View file

@ -39,7 +39,9 @@
#include "defs.h" #include "defs.h"
#define NAME "hsphfpd" static struct spa_log_topic log_topic = SPA_LOG_TOPIC(0, "spa.bluez5.hsphfpd");
#undef SPA_LOG_TOPIC_DEFAULT
#define SPA_LOG_TOPIC_DEFAULT &log_topic
struct impl { struct impl {
struct spa_bt_backend this; struct spa_bt_backend this;
@ -233,13 +235,13 @@ static int set_dbus_property(struct impl *backend,
m = NULL; m = NULL;
if (r == NULL) { if (r == NULL) {
spa_log_error(backend->log, NAME": Transport Set() failed for transport %s (%s)", path, err.message); spa_log_error(backend->log, "Transport Set() failed for transport %s (%s)", path, err.message);
dbus_error_free(&err); dbus_error_free(&err);
return -EIO; return -EIO;
} }
if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) { if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) {
spa_log_error(backend->log, NAME": Set() returned error: %s", dbus_message_get_error_name(r)); spa_log_error(backend->log, "Set() returned error: %s", dbus_message_get_error_name(r));
return -EIO; return -EIO;
} }
@ -257,7 +259,7 @@ static inline void set_rx_volume_gain_property(const struct spa_bt_transport *tr
if (set_dbus_property(backend, HSPHFPD_SERVICE, transport_data->transport_path, if (set_dbus_property(backend, HSPHFPD_SERVICE, transport_data->transport_path,
HSPHFPD_AUDIO_TRANSPORT_INTERFACE, "RxVolumeGain", HSPHFPD_AUDIO_TRANSPORT_INTERFACE, "RxVolumeGain",
DBUS_TYPE_UINT16, &gain)) DBUS_TYPE_UINT16, &gain))
spa_log_error(backend->log, NAME": Changing rx volume gain to %u for transport %s failed", spa_log_error(backend->log, "Changing rx volume gain to %u for transport %s failed",
(unsigned)gain, transport_data->transport_path); (unsigned)gain, transport_data->transport_path);
} }
@ -271,7 +273,7 @@ static inline void set_tx_volume_gain_property(const struct spa_bt_transport *tr
if (set_dbus_property(backend, HSPHFPD_SERVICE, transport_data->transport_path, if (set_dbus_property(backend, HSPHFPD_SERVICE, transport_data->transport_path,
HSPHFPD_AUDIO_TRANSPORT_INTERFACE, "TxVolumeGain", HSPHFPD_AUDIO_TRANSPORT_INTERFACE, "TxVolumeGain",
DBUS_TYPE_UINT16, &gain)) DBUS_TYPE_UINT16, &gain))
spa_log_error(backend->log, NAME": Changing tx volume gain to %u for transport %s failed", spa_log_error(backend->log, "Changing tx volume gain to %u for transport %s failed",
(unsigned)gain, transport_data->transport_path); (unsigned)gain, transport_data->transport_path);
} }
@ -299,19 +301,19 @@ static void parse_transport_properties_values(struct impl *backend,
dbus_message_iter_recurse(&element_i, &dict_i); dbus_message_iter_recurse(&element_i, &dict_i);
if (dbus_message_iter_get_arg_type(&dict_i) != DBUS_TYPE_STRING) { if (dbus_message_iter_get_arg_type(&dict_i) != DBUS_TYPE_STRING) {
spa_log_error(backend->log, NAME": Received invalid property for transport %s", transport_path); spa_log_error(backend->log, "Received invalid property for transport %s", transport_path);
return; return;
} }
dbus_message_iter_get_basic(&dict_i, &key); dbus_message_iter_get_basic(&dict_i, &key);
if (!dbus_message_iter_next(&dict_i)) { if (!dbus_message_iter_next(&dict_i)) {
spa_log_error(backend->log, NAME": Received invalid property for transport %s", transport_path); spa_log_error(backend->log, "Received invalid property for transport %s", transport_path);
return; return;
} }
if (dbus_message_iter_get_arg_type(&dict_i) != DBUS_TYPE_VARIANT) { if (dbus_message_iter_get_arg_type(&dict_i) != DBUS_TYPE_VARIANT) {
spa_log_error(backend->log, NAME": Received invalid property for transport %s", transport_path); spa_log_error(backend->log, "Received invalid property for transport %s", transport_path);
return; return;
} }
@ -334,7 +336,7 @@ static void parse_transport_properties_values(struct impl *backend,
volume_control = 0; volume_control = 0;
if (!volume_control) if (!volume_control)
spa_log_warn(backend->log, NAME": Transport %s received invalid '%s' property value '%s', ignoring", transport_path, key, value); spa_log_warn(backend->log, "Transport %s received invalid '%s' property value '%s', ignoring", transport_path, key, value);
else if (spa_streq(key, "RxVolumeControl")) else if (spa_streq(key, "RxVolumeControl"))
*rx_volume_control = volume_control; *rx_volume_control = volume_control;
else if (spa_streq(key, "TxVolumeControl")) else if (spa_streq(key, "TxVolumeControl"))
@ -384,20 +386,20 @@ static void hsphfpd_parse_transport_properties(struct impl *backend, struct spa_
&rx_volume_gain, &tx_volume_gain, &mtu); &rx_volume_gain, &tx_volume_gain, &mtu);
if (endpoint_path) if (endpoint_path)
spa_log_warn(backend->log, NAME": Transport %s received a duplicate '%s' property, ignoring", spa_log_warn(backend->log, "Transport %s received a duplicate '%s' property, ignoring",
transport_data->transport_path, "Endpoint"); transport_data->transport_path, "Endpoint");
if (air_codec) if (air_codec)
spa_log_warn(backend->log, NAME": Transport %s received a duplicate '%s' property, ignoring", spa_log_warn(backend->log, "Transport %s received a duplicate '%s' property, ignoring",
transport_data->transport_path, "AirCodec"); transport_data->transport_path, "AirCodec");
if (mtu) if (mtu)
spa_log_warn(backend->log, NAME": Transport %s received a duplicate '%s' property, ignoring", spa_log_warn(backend->log, "Transport %s received a duplicate '%s' property, ignoring",
transport_data->transport_path, "MTU"); transport_data->transport_path, "MTU");
if (rx_volume_control) { if (rx_volume_control) {
if (!!transport_data->rx_soft_volume != !!(rx_volume_control != HSPHFPD_VOLUME_CONTROL_REMOTE)) { if (!!transport_data->rx_soft_volume != !!(rx_volume_control != HSPHFPD_VOLUME_CONTROL_REMOTE)) {
spa_log_info(backend->log, NAME": Transport %s changed rx soft volume from %d to %d", spa_log_info(backend->log, "Transport %s changed rx soft volume from %d to %d",
transport_data->transport_path, transport_data->rx_soft_volume, transport_data->transport_path, transport_data->rx_soft_volume,
(rx_volume_control != HSPHFPD_VOLUME_CONTROL_REMOTE)); (rx_volume_control != HSPHFPD_VOLUME_CONTROL_REMOTE));
transport_data->rx_soft_volume = (rx_volume_control != HSPHFPD_VOLUME_CONTROL_REMOTE); transport_data->rx_soft_volume = (rx_volume_control != HSPHFPD_VOLUME_CONTROL_REMOTE);
@ -411,7 +413,7 @@ static void hsphfpd_parse_transport_properties(struct impl *backend, struct spa_
if (tx_volume_control) { if (tx_volume_control) {
if (!!transport_data->tx_soft_volume != !!(tx_volume_control != HSPHFPD_VOLUME_CONTROL_REMOTE)) { if (!!transport_data->tx_soft_volume != !!(tx_volume_control != HSPHFPD_VOLUME_CONTROL_REMOTE)) {
spa_log_info(backend->log, NAME": Transport %s changed tx soft volume from %d to %d", spa_log_info(backend->log, "Transport %s changed tx soft volume from %d to %d",
transport_data->transport_path, transport_data->rx_soft_volume, transport_data->transport_path, transport_data->rx_soft_volume,
(tx_volume_control != HSPHFPD_VOLUME_CONTROL_REMOTE)); (tx_volume_control != HSPHFPD_VOLUME_CONTROL_REMOTE));
transport_data->tx_soft_volume = (tx_volume_control != HSPHFPD_VOLUME_CONTROL_REMOTE); transport_data->tx_soft_volume = (tx_volume_control != HSPHFPD_VOLUME_CONTROL_REMOTE);
@ -425,7 +427,7 @@ static void hsphfpd_parse_transport_properties(struct impl *backend, struct spa_
if (rx_volume_gain != (uint16_t)-1) { if (rx_volume_gain != (uint16_t)-1) {
if (transport_data->rx_volume_gain != rx_volume_gain) { if (transport_data->rx_volume_gain != rx_volume_gain) {
spa_log_info(backend->log, NAME": Transport %s changed rx volume gain from %u to %u", spa_log_info(backend->log, "Transport %s changed rx volume gain from %u to %u",
transport_data->transport_path, (unsigned)transport_data->rx_volume_gain, (unsigned)rx_volume_gain); transport_data->transport_path, (unsigned)transport_data->rx_volume_gain, (unsigned)rx_volume_gain);
transport_data->rx_volume_gain = rx_volume_gain; transport_data->rx_volume_gain = rx_volume_gain;
rx_volume_gain_changed = true; rx_volume_gain_changed = true;
@ -434,7 +436,7 @@ static void hsphfpd_parse_transport_properties(struct impl *backend, struct spa_
if (tx_volume_gain != (uint16_t)-1) { if (tx_volume_gain != (uint16_t)-1) {
if (transport_data->tx_volume_gain != tx_volume_gain) { if (transport_data->tx_volume_gain != tx_volume_gain) {
spa_log_info(backend->log, NAME": Transport %s changed tx volume gain from %u to %u", spa_log_info(backend->log, "Transport %s changed tx volume gain from %u to %u",
transport_data->transport_path, (unsigned)transport_data->tx_volume_gain, (unsigned)tx_volume_gain); transport_data->transport_path, (unsigned)transport_data->tx_volume_gain, (unsigned)tx_volume_gain);
transport_data->tx_volume_gain = tx_volume_gain; transport_data->tx_volume_gain = tx_volume_gain;
tx_volume_gain_changed = true; tx_volume_gain_changed = true;
@ -448,8 +450,8 @@ static void hsphfpd_parse_transport_properties(struct impl *backend, struct spa_
if (tx_volume_gain_changed || tx_soft_volume_changed) if (tx_volume_gain_changed || tx_soft_volume_changed)
pa_hook_fire(pa_bluetooth_discovery_hook(transport_data->hsphfpd->discovery, PA_BLUETOOTH_HOOK_TRANSPORT_TX_VOLUME_GAIN_CHANGED), transport); pa_hook_fire(pa_bluetooth_discovery_hook(transport_data->hsphfpd->discovery, PA_BLUETOOTH_HOOK_TRANSPORT_TX_VOLUME_GAIN_CHANGED), transport);
#else #else
spa_log_debug(backend->log, NAME": RX volume gain changed: %d, soft volume changed: %d", rx_volume_gain_changed, rx_soft_volume_changed); spa_log_debug(backend->log, "RX volume gain changed: %d, soft volume changed: %d", rx_volume_gain_changed, rx_soft_volume_changed);
spa_log_debug(backend->log, NAME": TX volume gain changed: %d, soft volume changed: %d", tx_volume_gain_changed, tx_soft_volume_changed); spa_log_debug(backend->log, "TX volume gain changed: %d, soft volume changed: %d", tx_volume_gain_changed, tx_soft_volume_changed);
#endif #endif
if (rx_volume_control_changed) if (rx_volume_control_changed)
@ -592,12 +594,12 @@ static DBusHandlerResult hsphfpd_new_audio_connection(DBusConnection *conn, DBus
dbus_message_iter_next(&arg_i); dbus_message_iter_next(&arg_i);
dbus_message_iter_get_basic(&arg_i, &fd); dbus_message_iter_get_basic(&arg_i, &fd);
spa_log_debug(backend->log, NAME": NewConnection %s, fd %d", transport_path, fd); spa_log_debug(backend->log, "NewConnection %s, fd %d", transport_path, fd);
sender = dbus_message_get_sender(m); sender = dbus_message_get_sender(m);
if (!spa_streq(sender, backend->hsphfpd_service_id)) { if (!spa_streq(sender, backend->hsphfpd_service_id)) {
close(fd); close(fd);
spa_log_error(backend->log, NAME": Sender '%s' is not authorized", sender); spa_log_error(backend->log, "Sender '%s' is not authorized", sender);
r = dbus_message_new_error_printf(m, HSPHFPD_ERROR_REJECTED, "Sender '%s' is not authorized", sender); r = dbus_message_new_error_printf(m, HSPHFPD_ERROR_REJECTED, "Sender '%s' is not authorized", sender);
goto fail; goto fail;
} }
@ -620,28 +622,28 @@ static DBusHandlerResult hsphfpd_new_audio_connection(DBusConnection *conn, DBus
if (!endpoint_path) { if (!endpoint_path) {
close(fd); close(fd);
spa_log_error(backend->log, NAME": Endpoint property was not specified"); spa_log_error(backend->log, "Endpoint property was not specified");
r = dbus_message_new_error(m, HSPHFPD_ERROR_REJECTED, "Endpoint property was not specified"); r = dbus_message_new_error(m, HSPHFPD_ERROR_REJECTED, "Endpoint property was not specified");
goto fail; goto fail;
} }
if (!air_codec) { if (!air_codec) {
close(fd); close(fd);
spa_log_error(backend->log, NAME": AirCodec property was not specified"); spa_log_error(backend->log, "AirCodec property was not specified");
r = dbus_message_new_error(m, HSPHFPD_ERROR_REJECTED, "AirCodec property was not specified"); r = dbus_message_new_error(m, HSPHFPD_ERROR_REJECTED, "AirCodec property was not specified");
goto fail; goto fail;
} }
if (!rx_volume_control) { if (!rx_volume_control) {
close(fd); close(fd);
spa_log_error(backend->log, NAME": RxVolumeControl property was not specified"); spa_log_error(backend->log, "RxVolumeControl property was not specified");
r = dbus_message_new_error(m, HSPHFPD_ERROR_REJECTED, "RxVolumeControl property was not specified"); r = dbus_message_new_error(m, HSPHFPD_ERROR_REJECTED, "RxVolumeControl property was not specified");
goto fail; goto fail;
} }
if (!tx_volume_control) { if (!tx_volume_control) {
close(fd); close(fd);
spa_log_error(backend->log, NAME": TxVolumeControl property was not specified"); spa_log_error(backend->log, "TxVolumeControl property was not specified");
r = dbus_message_new_error(m, HSPHFPD_ERROR_REJECTED, "TxVolumeControl property was not specified"); r = dbus_message_new_error(m, HSPHFPD_ERROR_REJECTED, "TxVolumeControl property was not specified");
goto fail; goto fail;
} }
@ -649,7 +651,7 @@ static DBusHandlerResult hsphfpd_new_audio_connection(DBusConnection *conn, DBus
if (rx_volume_control != HSPHFPD_VOLUME_CONTROL_NONE) { if (rx_volume_control != HSPHFPD_VOLUME_CONTROL_NONE) {
if (rx_volume_gain == (uint16_t)-1) { if (rx_volume_gain == (uint16_t)-1) {
close(fd); close(fd);
spa_log_error(backend->log, NAME": RxVolumeGain property was not specified, but VolumeControl is not none"); spa_log_error(backend->log, "RxVolumeGain property was not specified, but VolumeControl is not none");
r = dbus_message_new_error(m, HSPHFPD_ERROR_REJECTED, "RxVolumeGain property was not specified, but VolumeControl is not none"); r = dbus_message_new_error(m, HSPHFPD_ERROR_REJECTED, "RxVolumeGain property was not specified, but VolumeControl is not none");
goto fail; goto fail;
} }
@ -660,7 +662,7 @@ static DBusHandlerResult hsphfpd_new_audio_connection(DBusConnection *conn, DBus
if (tx_volume_control != HSPHFPD_VOLUME_CONTROL_NONE) { if (tx_volume_control != HSPHFPD_VOLUME_CONTROL_NONE) {
if (tx_volume_gain == (uint16_t)-1) { if (tx_volume_gain == (uint16_t)-1) {
close(fd); close(fd);
spa_log_error(backend->log, NAME": TxVolumeGain property was not specified, but VolumeControl is not none"); spa_log_error(backend->log, "TxVolumeGain property was not specified, but VolumeControl is not none");
r = dbus_message_new_error(m, HSPHFPD_ERROR_REJECTED, "TxVolumeGain property was not specified, but VolumeControl is not none"); r = dbus_message_new_error(m, HSPHFPD_ERROR_REJECTED, "TxVolumeGain property was not specified, but VolumeControl is not none");
goto fail; goto fail;
} }
@ -670,7 +672,7 @@ static DBusHandlerResult hsphfpd_new_audio_connection(DBusConnection *conn, DBus
if (!mtu) { if (!mtu) {
close(fd); close(fd);
spa_log_error(backend->log, NAME": MTU property was not specified"); spa_log_error(backend->log, "MTU property was not specified");
r = dbus_message_new_error(m, HSPHFPD_ERROR_REJECTED, "MTU property was not specified"); r = dbus_message_new_error(m, HSPHFPD_ERROR_REJECTED, "MTU property was not specified");
goto fail; goto fail;
} }
@ -678,14 +680,14 @@ static DBusHandlerResult hsphfpd_new_audio_connection(DBusConnection *conn, DBus
endpoint = endpoint_find(backend, endpoint_path); endpoint = endpoint_find(backend, endpoint_path);
if (!endpoint) { if (!endpoint) {
close(fd); close(fd);
spa_log_error(backend->log, NAME": Endpoint %s does not exist", endpoint_path); spa_log_error(backend->log, "Endpoint %s does not exist", endpoint_path);
r = dbus_message_new_error_printf(m, HSPHFPD_ERROR_REJECTED, "Endpoint %s does not exist", endpoint_path); r = dbus_message_new_error_printf(m, HSPHFPD_ERROR_REJECTED, "Endpoint %s does not exist", endpoint_path);
goto fail; goto fail;
} }
if (!endpoint->valid) { if (!endpoint->valid) {
close(fd); close(fd);
spa_log_error(backend->log, NAME": Endpoint %s is not valid", endpoint_path); spa_log_error(backend->log, "Endpoint %s is not valid", endpoint_path);
r = dbus_message_new_error_printf(m, HSPHFPD_ERROR_REJECTED, "Endpoint %s is not valid", endpoint_path); r = dbus_message_new_error_printf(m, HSPHFPD_ERROR_REJECTED, "Endpoint %s is not valid", endpoint_path);
goto fail; goto fail;
} }
@ -693,17 +695,17 @@ static DBusHandlerResult hsphfpd_new_audio_connection(DBusConnection *conn, DBus
transport = spa_bt_transport_find(backend->monitor, endpoint_path); transport = spa_bt_transport_find(backend->monitor, endpoint_path);
if (!transport) { if (!transport) {
close(fd); close(fd);
spa_log_error(backend->log, NAME": Endpoint %s is not connected", endpoint_path); spa_log_error(backend->log, "Endpoint %s is not connected", endpoint_path);
r = dbus_message_new_error_printf(m, HSPHFPD_ERROR_REJECTED, "Endpoint %s is not connected", endpoint_path); r = dbus_message_new_error_printf(m, HSPHFPD_ERROR_REJECTED, "Endpoint %s is not connected", endpoint_path);
goto fail; goto fail;
} }
if (transport->codec != codec) if (transport->codec != codec)
spa_log_warn(backend->log, NAME": Expecting codec to be %d, got %d", transport->codec, codec); spa_log_warn(backend->log, "Expecting codec to be %d, got %d", transport->codec, codec);
if (transport->fd >= 0) { if (transport->fd >= 0) {
close(fd); close(fd);
spa_log_error(backend->log, NAME": Endpoint %s has already active transport", endpoint_path); spa_log_error(backend->log, "Endpoint %s has already active transport", endpoint_path);
r = dbus_message_new_error_printf(m, HSPHFPD_ERROR_REJECTED, "Endpoint %s has already active transport", endpoint_path); r = dbus_message_new_error_printf(m, HSPHFPD_ERROR_REJECTED, "Endpoint %s has already active transport", endpoint_path);
goto fail; goto fail;
} }
@ -753,7 +755,7 @@ static DBusHandlerResult audio_agent_endpoint_handler(DBusConnection *c, DBusMes
interface = dbus_message_get_interface(m); interface = dbus_message_get_interface(m);
member = dbus_message_get_member(m); member = dbus_message_get_member(m);
spa_log_debug(backend->log, NAME": dbus: path=%s, interface=%s, member=%s", path, interface, member); spa_log_debug(backend->log, "dbus: path=%s, interface=%s, member=%s", path, interface, member);
if (dbus_message_is_method_call(m, "org.freedesktop.DBus.Introspectable", "Introspect")) { if (dbus_message_is_method_call(m, "org.freedesktop.DBus.Introspectable", "Introspect")) {
const char *xml = AUDIO_AGENT_ENDPOINT_INTROSPECT_XML; const char *xml = AUDIO_AGENT_ENDPOINT_INTROSPECT_XML;
@ -818,7 +820,7 @@ static DBusHandlerResult application_object_manager_handler(DBusConnection *c, D
interface = dbus_message_get_interface(m); interface = dbus_message_get_interface(m);
member = dbus_message_get_member(m); member = dbus_message_get_member(m);
spa_log_debug(backend->log, NAME": dbus: path=%s, interface=%s, member=%s", path, interface, member); spa_log_debug(backend->log, "dbus: path=%s, interface=%s, member=%s", path, interface, member);
if (dbus_message_is_method_call(m, "org.freedesktop.DBus.Introspectable", "Introspect")) { if (dbus_message_is_method_call(m, "org.freedesktop.DBus.Introspectable", "Introspect")) {
const char *xml = APPLICATION_OBJECT_MANAGER_INTROSPECT_XML; const char *xml = APPLICATION_OBJECT_MANAGER_INTROSPECT_XML;
@ -869,18 +871,18 @@ static void hsphfpd_audio_acquire_reply(DBusPendingCall *pending, void *user_dat
return; return;
if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) { if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) {
spa_log_error(backend->log, NAME": RegisterApplication() failed: %s", spa_log_error(backend->log, "RegisterApplication() failed: %s",
dbus_message_get_error_name(r)); dbus_message_get_error_name(r));
goto finish; goto finish;
} }
if (!spa_streq(dbus_message_get_sender(r), backend->hsphfpd_service_id)) { if (!spa_streq(dbus_message_get_sender(r), backend->hsphfpd_service_id)) {
spa_log_error(backend->log, NAME": Reply for " HSPHFPD_ENDPOINT_INTERFACE ".ConnectAudio() from invalid sender"); spa_log_error(backend->log, "Reply for " HSPHFPD_ENDPOINT_INTERFACE ".ConnectAudio() from invalid sender");
goto finish; goto finish;
} }
if (!check_signature(r, "oso")) { if (!check_signature(r, "oso")) {
spa_log_error(backend->log, NAME": Invalid reply signature for " HSPHFPD_ENDPOINT_INTERFACE ".ConnectAudio()"); spa_log_error(backend->log, "Invalid reply signature for " HSPHFPD_ENDPOINT_INTERFACE ".ConnectAudio()");
goto finish; goto finish;
} }
@ -889,7 +891,7 @@ static void hsphfpd_audio_acquire_reply(DBusPendingCall *pending, void *user_dat
DBUS_TYPE_STRING, &service_id, DBUS_TYPE_STRING, &service_id,
DBUS_TYPE_OBJECT_PATH, &agent_path, DBUS_TYPE_OBJECT_PATH, &agent_path,
DBUS_TYPE_INVALID) == FALSE) { DBUS_TYPE_INVALID) == FALSE) {
spa_log_error(backend->log, NAME": Failed to parse " HSPHFPD_ENDPOINT_INTERFACE ".ConnectAudio() reply: %s", error.message); spa_log_error(backend->log, "Failed to parse " HSPHFPD_ENDPOINT_INTERFACE ".ConnectAudio() reply: %s", error.message);
goto finish; goto finish;
} }
@ -898,7 +900,7 @@ static void hsphfpd_audio_acquire_reply(DBusPendingCall *pending, void *user_dat
goto finish; goto finish;
} }
spa_log_debug(backend->log, NAME": hsphfpd audio acquired"); spa_log_debug(backend->log, "hsphfpd audio acquired");
finish: finish:
dbus_message_unref(r); dbus_message_unref(r);
@ -915,7 +917,7 @@ static int hsphfpd_audio_acquire(void *data, bool optional)
DBusPendingCall *call; DBusPendingCall *call;
DBusError err; DBusError err;
spa_log_debug(backend->log, NAME": transport %p: Acquire %s", spa_log_debug(backend->log, "transport %p: Acquire %s",
transport, transport->path); transport, transport->path);
if (backend->acquire_in_progress) if (backend->acquire_in_progress)
@ -956,7 +958,7 @@ static int hsphfpd_audio_release(void *data)
struct impl *backend = SPA_CONTAINER_OF(transport->backend, struct impl, this); struct impl *backend = SPA_CONTAINER_OF(transport->backend, struct impl, this);
struct hsphfpd_transport_data *transport_data = transport->user_data; struct hsphfpd_transport_data *transport_data = transport->user_data;
spa_log_debug(backend->log, NAME": transport %p: Release %s", spa_log_debug(backend->log, "transport %p: Release %s",
transport, transport->path); transport, transport->path);
if (transport->sco_io) { if (transport->sco_io) {
@ -1022,24 +1024,24 @@ static DBusHandlerResult hsphfpd_parse_endpoint_properties(struct impl *backend,
endpoint->local_address = strdup(value); endpoint->local_address = strdup(value);
else if (spa_streq(key, "Profile")) { else if (spa_streq(key, "Profile")) {
if (endpoint->profile) if (endpoint->profile)
spa_log_warn(backend->log, NAME": Endpoint %s received a duplicate '%s' property, ignoring", endpoint->path, key); spa_log_warn(backend->log, "Endpoint %s received a duplicate '%s' property, ignoring", endpoint->path, key);
else if (spa_streq(value, "headset")) else if (spa_streq(value, "headset"))
endpoint->profile = HSPHFPD_PROFILE_HEADSET; endpoint->profile = HSPHFPD_PROFILE_HEADSET;
else if (spa_streq(value, "handsfree")) else if (spa_streq(value, "handsfree"))
endpoint->profile = HSPHFPD_PROFILE_HANDSFREE; endpoint->profile = HSPHFPD_PROFILE_HANDSFREE;
else else
spa_log_warn(backend->log, NAME": Endpoint %s received invalid '%s' property value '%s', ignoring", endpoint->path, key, value); spa_log_warn(backend->log, "Endpoint %s received invalid '%s' property value '%s', ignoring", endpoint->path, key, value);
} else if (spa_streq(key, "Role")) { } else if (spa_streq(key, "Role")) {
if (endpoint->role) if (endpoint->role)
spa_log_warn(backend->log, NAME": Endpoint %s received a duplicate '%s' property, ignoring", endpoint->path, key); spa_log_warn(backend->log, "Endpoint %s received a duplicate '%s' property, ignoring", endpoint->path, key);
else if (spa_streq(value, "client")) else if (spa_streq(value, "client"))
endpoint->role = HSPHFPD_ROLE_CLIENT; endpoint->role = HSPHFPD_ROLE_CLIENT;
else if (spa_streq(value, "gateway")) else if (spa_streq(value, "gateway"))
endpoint->role = HSPHFPD_ROLE_GATEWAY; endpoint->role = HSPHFPD_ROLE_GATEWAY;
else else
spa_log_warn(backend->log, NAME": Endpoint %s received invalid '%s' property value '%s', ignoring", endpoint->path, key, value); spa_log_warn(backend->log, "Endpoint %s received invalid '%s' property value '%s', ignoring", endpoint->path, key, value);
} }
spa_log_trace(backend->log, NAME": %s: %s (%p)", key, value, endpoint); spa_log_trace(backend->log, " %s: %s (%p)", key, value, endpoint);
} }
break; break;
@ -1049,7 +1051,7 @@ static DBusHandlerResult hsphfpd_parse_endpoint_properties(struct impl *backend,
dbus_message_iter_get_basic(&value_i, &value); dbus_message_iter_get_basic(&value_i, &value);
if (spa_streq(key, "Connected")) if (spa_streq(key, "Connected"))
endpoint->connected = value; endpoint->connected = value;
spa_log_trace(backend->log, NAME": %s: %d", key, value); spa_log_trace(backend->log, " %s: %d", key, value);
} }
break; break;
@ -1081,13 +1083,13 @@ static DBusHandlerResult hsphfpd_parse_endpoint_properties(struct impl *backend,
endpoint->valid = true; endpoint->valid = true;
if (!endpoint->remote_address || !endpoint->local_address) { if (!endpoint->remote_address || !endpoint->local_address) {
spa_log_debug(backend->log, NAME": Missing addresses for %s", endpoint->path); spa_log_debug(backend->log, "Missing addresses for %s", endpoint->path);
return DBUS_HANDLER_RESULT_HANDLED; return DBUS_HANDLER_RESULT_HANDLED;
} }
d = spa_bt_device_find_by_address(backend->monitor, endpoint->remote_address, endpoint->local_address); d = spa_bt_device_find_by_address(backend->monitor, endpoint->remote_address, endpoint->local_address);
if (!d) { if (!d) {
spa_log_debug(backend->log, NAME": No device for %s", endpoint->path); spa_log_debug(backend->log, "No device for %s", endpoint->path);
return DBUS_HANDLER_RESULT_HANDLED; return DBUS_HANDLER_RESULT_HANDLED;
} }
@ -1097,9 +1099,9 @@ static DBusHandlerResult hsphfpd_parse_endpoint_properties(struct impl *backend,
if (!endpoint->connected || (backend->msbc_supported && (endpoint->air_codecs & HFP_AUDIO_CODEC_MSBC) && t->codec == HFP_AUDIO_CODEC_CVSD)) { if (!endpoint->connected || (backend->msbc_supported && (endpoint->air_codecs & HFP_AUDIO_CODEC_MSBC) && t->codec == HFP_AUDIO_CODEC_CVSD)) {
spa_bt_transport_free(t); spa_bt_transport_free(t);
spa_bt_device_check_profiles(d, false); spa_bt_device_check_profiles(d, false);
spa_log_debug(backend->log, NAME": Transport released for %s", endpoint->path); spa_log_debug(backend->log, "Transport released for %s", endpoint->path);
} else { } else {
spa_log_debug(backend->log, NAME": Transport already configured for %s", endpoint->path); spa_log_debug(backend->log, "Transport already configured for %s", endpoint->path);
return DBUS_HANDLER_RESULT_HANDLED; return DBUS_HANDLER_RESULT_HANDLED;
} }
} }
@ -1110,7 +1112,7 @@ static DBusHandlerResult hsphfpd_parse_endpoint_properties(struct impl *backend,
char *t_path = strdup(endpoint->path); char *t_path = strdup(endpoint->path);
t = spa_bt_transport_create(backend->monitor, t_path, sizeof(struct hsphfpd_transport_data)); t = spa_bt_transport_create(backend->monitor, t_path, sizeof(struct hsphfpd_transport_data));
if (t == NULL) { if (t == NULL) {
spa_log_warn(backend->log, NAME": can't create transport: %m"); spa_log_warn(backend->log, "can't create transport: %m");
free(t_path); free(t_path);
return DBUS_HANDLER_RESULT_NEED_MEMORY; return DBUS_HANDLER_RESULT_NEED_MEMORY;
} }
@ -1142,7 +1144,7 @@ static DBusHandlerResult hsphfpd_parse_endpoint_properties(struct impl *backend,
spa_bt_device_add_profile(d, t->profile); spa_bt_device_add_profile(d, t->profile);
spa_bt_device_connect_profile(t->device, t->profile); spa_bt_device_connect_profile(t->device, t->profile);
spa_log_debug(backend->log, NAME": Transport %s available for hsphfpd", endpoint->path); spa_log_debug(backend->log, "Transport %s available for hsphfpd", endpoint->path);
return DBUS_HANDLER_RESULT_HANDLED; return DBUS_HANDLER_RESULT_HANDLED;
} }
@ -1175,11 +1177,11 @@ static DBusHandlerResult hsphfpd_parse_interfaces(struct impl *backend, DBusMess
endpoint = calloc(1, sizeof(struct hsphfpd_endpoint)); endpoint = calloc(1, sizeof(struct hsphfpd_endpoint));
endpoint->path = strdup(path); endpoint->path = strdup(path);
spa_list_append(&backend->endpoint_list, &endpoint->link); spa_list_append(&backend->endpoint_list, &endpoint->link);
spa_log_debug(backend->log, NAME": Found endpoint %s", path); spa_log_debug(backend->log, "Found endpoint %s", path);
} }
hsphfpd_parse_endpoint_properties(backend, endpoint, &iface_i); hsphfpd_parse_endpoint_properties(backend, endpoint, &iface_i);
} else } else
spa_log_debug(backend->log, NAME": Unknown interface %s found, skipping", interface); spa_log_debug(backend->log, "Unknown interface %s found, skipping", interface);
dbus_message_iter_next(&element_i); dbus_message_iter_next(&element_i);
} }
@ -1198,18 +1200,18 @@ static void hsphfpd_get_endpoints_reply(DBusPendingCall *pending, void *user_dat
return; return;
if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) { if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) {
spa_log_error(backend->log, NAME": Failed to get a list of endpoints from hsphfpd: %s", spa_log_error(backend->log, "Failed to get a list of endpoints from hsphfpd: %s",
dbus_message_get_error_name(r)); dbus_message_get_error_name(r));
goto finish; goto finish;
} }
if (!spa_streq(dbus_message_get_sender(r), backend->hsphfpd_service_id)) { if (!spa_streq(dbus_message_get_sender(r), backend->hsphfpd_service_id)) {
spa_log_error(backend->log, NAME": Reply for GetManagedObjects() from invalid sender"); spa_log_error(backend->log, "Reply for GetManagedObjects() from invalid sender");
goto finish; goto finish;
} }
if (!dbus_message_iter_init(r, &i) || !check_signature(r, "a{oa{sa{sv}}}")) { if (!dbus_message_iter_init(r, &i) || !check_signature(r, "a{oa{sa{sv}}}")) {
spa_log_error(backend->log, NAME": Invalid arguments in GetManagedObjects() reply"); spa_log_error(backend->log, "Invalid arguments in GetManagedObjects() reply");
goto finish; goto finish;
} }
@ -1238,7 +1240,7 @@ static int backend_hsphfpd_register(void *data)
DBusError err; DBusError err;
int res; int res;
spa_log_debug(backend->log, NAME": Registering to hsphfpd"); spa_log_debug(backend->log, "Registering to hsphfpd");
m = dbus_message_new_method_call(HSPHFPD_SERVICE, "/", m = dbus_message_new_method_call(HSPHFPD_SERVICE, "/",
HSPHFPD_APPLICATION_MANAGER_INTERFACE, "RegisterApplication"); HSPHFPD_APPLICATION_MANAGER_INTERFACE, "RegisterApplication");
@ -1254,11 +1256,11 @@ static int backend_hsphfpd_register(void *data)
if (r == NULL) { if (r == NULL) {
if (dbus_error_has_name(&err, "org.freedesktop.DBus.Error.ServiceUnknown")) { if (dbus_error_has_name(&err, "org.freedesktop.DBus.Error.ServiceUnknown")) {
spa_log_info(backend->log, NAME": hsphfpd not available: %s", spa_log_info(backend->log, "hsphfpd not available: %s",
err.message); err.message);
res = -ENOTSUP; res = -ENOTSUP;
} else { } else {
spa_log_warn(backend->log, NAME": Registering application %s failed: %s (%s)", spa_log_warn(backend->log, "Registering application %s failed: %s (%s)",
path, err.message, err.name); path, err.message, err.name);
res = -EIO; res = -EIO;
} }
@ -1267,7 +1269,7 @@ static int backend_hsphfpd_register(void *data)
} }
if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) { if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) {
spa_log_error(backend->log, NAME": RegisterApplication() failed: %s", spa_log_error(backend->log, "RegisterApplication() failed: %s",
dbus_message_get_error_name(r)); dbus_message_get_error_name(r));
goto finish; goto finish;
} }
@ -1275,7 +1277,7 @@ static int backend_hsphfpd_register(void *data)
backend->hsphfpd_service_id = strdup(dbus_message_get_sender(r)); backend->hsphfpd_service_id = strdup(dbus_message_get_sender(r));
spa_log_debug(backend->log, NAME": Registered to hsphfpd"); spa_log_debug(backend->log, "Registered to hsphfpd");
m = dbus_message_new_method_call(HSPHFPD_SERVICE, "/", m = dbus_message_new_method_call(HSPHFPD_SERVICE, "/",
DBUS_INTERFACE_OBJECTMANAGER, "GetManagedObjects"); DBUS_INTERFACE_OBJECTMANAGER, "GetManagedObjects");
@ -1323,13 +1325,13 @@ static DBusHandlerResult hsphfpd_filter_cb(DBusConnection *bus, DBusMessage *m,
if (dbus_message_is_signal(m, DBUS_INTERFACE_OBJECTMANAGER, "InterfacesAdded")) { if (dbus_message_is_signal(m, DBUS_INTERFACE_OBJECTMANAGER, "InterfacesAdded")) {
DBusMessageIter arg_i; DBusMessageIter arg_i;
spa_log_warn(backend->log, NAME": sender: %s", dbus_message_get_sender(m)); spa_log_warn(backend->log, "sender: %s", dbus_message_get_sender(m));
if (!backend->endpoints_listed) if (!backend->endpoints_listed)
goto finish; goto finish;
if (!dbus_message_iter_init(m, &arg_i) || !check_signature(m, "oa{sa{sv}}")) { if (!dbus_message_iter_init(m, &arg_i) || !check_signature(m, "oa{sa{sv}}")) {
spa_log_error(backend->log, NAME": Invalid signature found in InterfacesAdded"); spa_log_error(backend->log, "Invalid signature found in InterfacesAdded");
goto finish; goto finish;
} }
@ -1342,7 +1344,7 @@ static DBusHandlerResult hsphfpd_filter_cb(DBusConnection *bus, DBusMessage *m,
goto finish; goto finish;
if (!dbus_message_iter_init(m, &arg_i) || !check_signature(m, "oas")) { if (!dbus_message_iter_init(m, &arg_i) || !check_signature(m, "oas")) {
spa_log_error(backend->log, NAME": Invalid signature found in InterfacesRemoved"); spa_log_error(backend->log, "Invalid signature found in InterfacesRemoved");
goto finish; goto finish;
} }
@ -1362,7 +1364,7 @@ static DBusHandlerResult hsphfpd_filter_cb(DBusConnection *bus, DBusMessage *m,
if (transport) if (transport)
spa_bt_transport_free(transport); spa_bt_transport_free(transport);
spa_log_debug(backend->log, NAME": Remove endpoint %s", path); spa_log_debug(backend->log, "Remove endpoint %s", path);
endpoint = endpoint_find(backend, path); endpoint = endpoint_find(backend, path);
if (endpoint) if (endpoint)
endpoint_free(endpoint); endpoint_free(endpoint);
@ -1379,7 +1381,7 @@ static DBusHandlerResult hsphfpd_filter_cb(DBusConnection *bus, DBusMessage *m,
goto finish; goto finish;
if (!dbus_message_iter_init(m, &arg_i) || !check_signature(m, "sa{sv}as")) { if (!dbus_message_iter_init(m, &arg_i) || !check_signature(m, "sa{sv}as")) {
spa_log_error(backend->log, NAME": Invalid signature found in PropertiesChanged"); spa_log_error(backend->log, "Invalid signature found in PropertiesChanged");
goto finish; goto finish;
} }
@ -1391,20 +1393,20 @@ static DBusHandlerResult hsphfpd_filter_cb(DBusConnection *bus, DBusMessage *m,
if (spa_streq(iface, HSPHFPD_ENDPOINT_INTERFACE)) { if (spa_streq(iface, HSPHFPD_ENDPOINT_INTERFACE)) {
struct hsphfpd_endpoint *endpoint = endpoint_find(backend, path); struct hsphfpd_endpoint *endpoint = endpoint_find(backend, path);
if (!endpoint) { if (!endpoint) {
spa_log_warn(backend->log, NAME": Properties changed on unknown endpoint %s", path); spa_log_warn(backend->log, "Properties changed on unknown endpoint %s", path);
goto finish; goto finish;
} }
spa_log_debug(backend->log, NAME": Properties changed on endpoint %s", path); spa_log_debug(backend->log, "Properties changed on endpoint %s", path);
hsphfpd_parse_endpoint_properties(backend, endpoint, &arg_i); hsphfpd_parse_endpoint_properties(backend, endpoint, &arg_i);
} else if (spa_streq(iface, HSPHFPD_AUDIO_TRANSPORT_INTERFACE)) { } else if (spa_streq(iface, HSPHFPD_AUDIO_TRANSPORT_INTERFACE)) {
struct spa_bt_transport *transport = spa_bt_transport_find_full(backend->monitor, struct spa_bt_transport *transport = spa_bt_transport_find_full(backend->monitor,
hsphfpd_cmp_transport_path, hsphfpd_cmp_transport_path,
(const void *)path); (const void *)path);
if (!transport) { if (!transport) {
spa_log_warn(backend->log, NAME": Properties changed on unknown transport %s", path); spa_log_warn(backend->log, "Properties changed on unknown transport %s", path);
goto finish; goto finish;
} }
spa_log_debug(backend->log, NAME": Properties changed on transport %s", path); spa_log_debug(backend->log, "Properties changed on transport %s", path);
hsphfpd_parse_transport_properties(backend, transport, &arg_i); hsphfpd_parse_transport_properties(backend, transport, &arg_i);
} }
} }
@ -1425,7 +1427,7 @@ static int add_filters(void *data)
dbus_error_init(&err); dbus_error_init(&err);
if (!dbus_connection_add_filter(backend->conn, hsphfpd_filter_cb, backend, NULL)) { if (!dbus_connection_add_filter(backend->conn, hsphfpd_filter_cb, backend, NULL)) {
spa_log_error(backend->log, NAME": failed to add filter function"); spa_log_error(backend->log, "failed to add filter function");
goto fail; goto fail;
} }
@ -1544,6 +1546,8 @@ struct spa_bt_backend *backend_hsphfpd_new(struct spa_bt_monitor *monitor,
else else
backend->msbc_supported = false; backend->msbc_supported = false;
spa_log_topic_init(backend->log, &log_topic);
spa_list_init(&backend->endpoint_list); spa_list_init(&backend->endpoint_list);
if (!dbus_connection_register_object_path(backend->conn, if (!dbus_connection_register_object_path(backend->conn,

186
spa/plugins/bluez5/backend-native.c
View file

@ -50,7 +50,9 @@
#include <libusb.h> #include <libusb.h>
#endif #endif
#define NAME "native" static struct spa_log_topic log_topic = SPA_LOG_TOPIC(0, "spa.bluez5.native");
#undef SPA_LOG_TOPIC_DEFAULT
#define SPA_LOG_TOPIC_DEFAULT &log_topic
#define PROP_KEY_HEADSET_ROLES "bluez5.headset-roles" #define PROP_KEY_HEADSET_ROLES "bluez5.headset-roles"
@ -264,7 +266,7 @@ static ssize_t rfcomm_send_cmd(const struct rfcomm *rfcomm, const char *format,
if (len > RFCOMM_MESSAGE_MAX_LENGTH) if (len > RFCOMM_MESSAGE_MAX_LENGTH)
return -E2BIG; return -E2BIG;
spa_log_debug(backend->log, NAME": RFCOMM >> %s", message); spa_log_debug(backend->log, "RFCOMM >> %s", message);
message[len] = '\n'; message[len] = '\n';
/* `message` is no longer null-terminated */ /* `message` is no longer null-terminated */
@ -274,7 +276,7 @@ static ssize_t rfcomm_send_cmd(const struct rfcomm *rfcomm, const char *format,
* be caught with the HANGUP and ERROR events handled above */ * be caught with the HANGUP and ERROR events handled above */
if (len < 0) { if (len < 0) {
len = -errno; len = -errno;
spa_log_error(backend->log, NAME": RFCOMM write error: %s", strerror(errno)); spa_log_error(backend->log, "RFCOMM write error: %s", strerror(errno));
} }
return len; return len;
@ -298,7 +300,7 @@ static ssize_t rfcomm_send_reply(const struct rfcomm *rfcomm, const char *format
if (len > RFCOMM_MESSAGE_MAX_LENGTH) if (len > RFCOMM_MESSAGE_MAX_LENGTH)
return -E2BIG; return -E2BIG;
spa_log_debug(backend->log, NAME": RFCOMM >> %s", &message[2]); spa_log_debug(backend->log, "RFCOMM >> %s", &message[2]);
message[0] = '\r'; message[0] = '\r';
message[1] = '\n'; message[1] = '\n';
@ -311,7 +313,7 @@ static ssize_t rfcomm_send_reply(const struct rfcomm *rfcomm, const char *format
* be caught with the HANGUP and ERROR events handled above */ * be caught with the HANGUP and ERROR events handled above */
if (len < 0) { if (len < 0) {
len = -errno; len = -errno;
spa_log_error(backend->log, NAME": RFCOMM write error: %s", strerror(errno)); spa_log_error(backend->log, "RFCOMM write error: %s", strerror(errno));
} }
return len; return len;
@ -335,7 +337,7 @@ static void rfcomm_emit_volume_changed(struct rfcomm *rfcomm, int id, int hw_vol
rfcomm->volumes[id].hw_volume = hw_volume; rfcomm->volumes[id].hw_volume = hw_volume;
} }
spa_log_debug(rfcomm->backend->log, NAME": volume changed %d", hw_volume); spa_log_debug(rfcomm->backend->log, "volume changed %d", hw_volume);
if (rfcomm->transport == NULL || !rfcomm->has_volume) if (rfcomm->transport == NULL || !rfcomm->has_volume)
return; return;
@ -366,7 +368,7 @@ static bool rfcomm_hsp_ag(struct spa_source *source, char* buf)
rfcomm_emit_volume_changed(rfcomm, SPA_BT_VOLUME_ID_TX, gain); rfcomm_emit_volume_changed(rfcomm, SPA_BT_VOLUME_ID_TX, gain);
rfcomm_send_reply(rfcomm, "OK"); rfcomm_send_reply(rfcomm, "OK");
} else { } else {
spa_log_debug(backend->log, NAME": RFCOMM receive unsupported VGS gain: %s", buf); spa_log_debug(backend->log, "RFCOMM receive unsupported VGS gain: %s", buf);
rfcomm_send_reply(rfcomm, "ERROR"); rfcomm_send_reply(rfcomm, "ERROR");
} }
} else if (sscanf(buf, "AT+VGM=%d", &gain) == 1) { } else if (sscanf(buf, "AT+VGM=%d", &gain) == 1) {
@ -376,7 +378,7 @@ static bool rfcomm_hsp_ag(struct spa_source *source, char* buf)
rfcomm_send_reply(rfcomm, "OK"); rfcomm_send_reply(rfcomm, "OK");
} else { } else {
rfcomm_send_reply(rfcomm, "ERROR"); rfcomm_send_reply(rfcomm, "ERROR");
spa_log_debug(backend->log, NAME": RFCOMM receive unsupported VGM gain: %s", buf); spa_log_debug(backend->log, "RFCOMM receive unsupported VGM gain: %s", buf);
} }
} else if (sscanf(buf, "AT+CKPD=%d", &dummy) == 1) { } else if (sscanf(buf, "AT+CKPD=%d", &dummy) == 1) {
rfcomm_send_reply(rfcomm, "OK"); rfcomm_send_reply(rfcomm, "OK");
@ -434,13 +436,13 @@ static bool rfcomm_hsp_hs(struct spa_source *source, char* buf)
if (gain <= SPA_BT_VOLUME_HS_MAX) { if (gain <= SPA_BT_VOLUME_HS_MAX) {
rfcomm_emit_volume_changed(rfcomm, SPA_BT_VOLUME_ID_RX, gain); rfcomm_emit_volume_changed(rfcomm, SPA_BT_VOLUME_ID_RX, gain);
} else { } else {
spa_log_debug(backend->log, NAME": RFCOMM receive unsupported VGS gain: %s", buf); spa_log_debug(backend->log, "RFCOMM receive unsupported VGS gain: %s", buf);
} }
} else if (sscanf(buf, "\r\n+VGM=%d\r\n", &gain) == 1) { } else if (sscanf(buf, "\r\n+VGM=%d\r\n", &gain) == 1) {
if (gain <= SPA_BT_VOLUME_HS_MAX) { if (gain <= SPA_BT_VOLUME_HS_MAX) {
rfcomm_emit_volume_changed(rfcomm, SPA_BT_VOLUME_ID_TX, gain); rfcomm_emit_volume_changed(rfcomm, SPA_BT_VOLUME_ID_TX, gain);
} else { } else {
spa_log_debug(backend->log, NAME": RFCOMM receive unsupported VGM gain: %s", buf); spa_log_debug(backend->log, "RFCOMM receive unsupported VGM gain: %s", buf);
} }
} if (strncmp(buf, "\r\nOK\r\n", 6) == 0) { } if (strncmp(buf, "\r\nOK\r\n", 6) == 0) {
if (rfcomm->hs_state == hsp_hs_init2) { if (rfcomm->hs_state == hsp_hs_init2) {
@ -540,7 +542,7 @@ done:
return ok; return ok;
fail: fail:
spa_log_info(backend->log, NAME": failed to acquire USB device info: %d (%s)", spa_log_info(backend->log, "failed to acquire USB device info: %d (%s)",
res, libusb_strerror(res)); res, libusb_strerror(res));
ok = false; ok = false;
goto done; goto done;
@ -569,7 +571,7 @@ static bool device_supports_required_mSBC_transport_modes(
} }
spa_log_info(backend->log, spa_log_info(backend->log,
NAME": bluez-monitor/hardware.conf: msbc:%d msbc-alt1:%d", (int)msbc_ok, (int)msbc_alt1_ok); "bluez-monitor/hardware.conf: msbc:%d msbc-alt1:%d", (int)msbc_ok, (int)msbc_alt1_ok);
if (!msbc_ok && !msbc_alt1_ok) if (!msbc_ok && !msbc_alt1_ok)
return false; return false;
@ -594,7 +596,7 @@ static bool device_supports_required_mSBC_transport_modes(
addr.sco_family = AF_BLUETOOTH; addr.sco_family = AF_BLUETOOTH;
bacpy(&addr.sco_bdaddr, &dst); bacpy(&addr.sco_bdaddr, &dst);
spa_log_debug(backend->log, NAME": connect to determine adapter msbc support..."); spa_log_debug(backend->log, "connect to determine adapter msbc support...");
/* Linux kernel code checks for features needed for BT_VOICE_TRANSPARENT /* Linux kernel code checks for features needed for BT_VOICE_TRANSPARENT
* among the first checks it does, and fails with EOPNOTSUPP if not * among the first checks it does, and fails with EOPNOTSUPP if not
@ -609,7 +611,7 @@ static bool device_supports_required_mSBC_transport_modes(
res = 0; res = 0;
close(sock); close(sock);
spa_log_debug(backend->log, NAME": determined adapter-msbc:%d res:%d", spa_log_debug(backend->log, "determined adapter-msbc:%d res:%d",
(res != EOPNOTSUPP), res); (res != EOPNOTSUPP), res);
if (res == EOPNOTSUPP) if (res == EOPNOTSUPP)
return false; return false;
@ -625,10 +627,10 @@ static bool device_supports_required_mSBC_transport_modes(
msbc_ok = false; msbc_ok = false;
} }
if (!msbc_ok) if (!msbc_ok)
spa_log_info(backend->log, NAME": bluetooth host adapter does not support USB ALT6"); spa_log_info(backend->log, "bluetooth host adapter does not support USB ALT6");
#else #else
spa_log_info(backend->log, spa_log_info(backend->log,
NAME": compiled without libusb; can't check if bluetooth adapter has USB ALT6"); "compiled without libusb; can't check if bluetooth adapter has USB ALT6");
msbc_ok = false; msbc_ok = false;
#endif #endif
} }
@ -675,7 +677,7 @@ static bool rfcomm_hfp_ag(struct spa_source *source, char* buf)
/* let's see if the headset supports codec negotiation */ /* let's see if the headset supports codec negotiation */
if ((features & (SPA_BT_HFP_HF_FEATURE_CODEC_NEGOTIATION)) != 0) { if ((features & (SPA_BT_HFP_HF_FEATURE_CODEC_NEGOTIATION)) != 0) {
spa_log_debug(backend->log, spa_log_debug(backend->log,
NAME": RFCOMM features = %i, codec negotiation supported by headset", "RFCOMM features = %i, codec negotiation supported by headset",
features); features);
/* Prepare reply: Audio Gateway (=computer) supports codec negotiation */ /* Prepare reply: Audio Gateway (=computer) supports codec negotiation */
rfcomm->codec_negotiation_supported = true; rfcomm->codec_negotiation_supported = true;
@ -683,7 +685,7 @@ static bool rfcomm_hfp_ag(struct spa_source *source, char* buf)
} else { } else {
/* Codec negotiation not supported */ /* Codec negotiation not supported */
spa_log_debug(backend->log, spa_log_debug(backend->log,
NAME": RFCOMM features = %i, codec negotiation NOT supported by headset", "RFCOMM features = %i, codec negotiation NOT supported by headset",
features); features);
rfcomm->codec_negotiation_supported = false; rfcomm->codec_negotiation_supported = false;
@ -711,10 +713,10 @@ static bool rfcomm_hfp_ag(struct spa_source *source, char* buf)
if (cntr > 0) { if (cntr > 0) {
int codec_id; int codec_id;
sscanf (token, "%u", &codec_id); sscanf (token, "%u", &codec_id);
spa_log_debug(backend->log, NAME": RFCOMM AT+BAC found codec %u", codec_id); spa_log_debug(backend->log, "RFCOMM AT+BAC found codec %u", codec_id);
if (codec_id == HFP_AUDIO_CODEC_MSBC) { if (codec_id == HFP_AUDIO_CODEC_MSBC) {
rfcomm->msbc_supported_by_hfp = true; rfcomm->msbc_supported_by_hfp = true;
spa_log_debug(backend->log, NAME": RFCOMM headset supports mSBC codec"); spa_log_debug(backend->log, "RFCOMM headset supports mSBC codec");
} }
} }
/* get next token */ /* get next token */
@ -735,14 +737,14 @@ static bool rfcomm_hfp_ag(struct spa_source *source, char* buf)
/* switch codec to mSBC by sending unsolicited +BCS message */ /* switch codec to mSBC by sending unsolicited +BCS message */
if (rfcomm->codec_negotiation_supported && rfcomm->msbc_supported_by_hfp) { if (rfcomm->codec_negotiation_supported && rfcomm->msbc_supported_by_hfp) {
spa_log_debug(backend->log, NAME": RFCOMM initial codec setup"); spa_log_debug(backend->log, "RFCOMM initial codec setup");
rfcomm->hfp_ag_initial_codec_setup = HFP_AG_INITIAL_CODEC_SETUP_SEND; rfcomm->hfp_ag_initial_codec_setup = HFP_AG_INITIAL_CODEC_SETUP_SEND;
rfcomm_send_reply(rfcomm, "+BCS: 2"); rfcomm_send_reply(rfcomm, "+BCS: 2");
codec_switch_start_timer(rfcomm, HFP_CODEC_SWITCH_INITIAL_TIMEOUT_MSEC); codec_switch_start_timer(rfcomm, HFP_CODEC_SWITCH_INITIAL_TIMEOUT_MSEC);
} else { } else {
rfcomm->transport = _transport_create(rfcomm); rfcomm->transport = _transport_create(rfcomm);
if (rfcomm->transport == NULL) { if (rfcomm->transport == NULL) {
spa_log_warn(backend->log, NAME": can't create transport: %m"); spa_log_warn(backend->log, "can't create transport: %m");
// TODO: We should manage the missing transport // TODO: We should manage the missing transport
} else { } else {
rfcomm->transport->codec = HFP_AUDIO_CODEC_CVSD; rfcomm->transport->codec = HFP_AUDIO_CODEC_CVSD;
@ -752,7 +754,7 @@ static bool rfcomm_hfp_ag(struct spa_source *source, char* buf)
} }
} else if (!rfcomm->slc_configured) { } else if (!rfcomm->slc_configured) {
spa_log_warn(backend->log, NAME": RFCOMM receive command before SLC completed: %s", buf); spa_log_warn(backend->log, "RFCOMM receive command before SLC completed: %s", buf);
rfcomm_send_reply(rfcomm, "ERROR"); rfcomm_send_reply(rfcomm, "ERROR");
return false; return false;
} else if (sscanf(buf, "AT+BCS=%u", &selected_codec) == 1) { } else if (sscanf(buf, "AT+BCS=%u", &selected_codec) == 1) {
@ -763,7 +765,7 @@ static bool rfcomm_hfp_ag(struct spa_source *source, char* buf)
codec_switch_stop_timer(rfcomm); codec_switch_stop_timer(rfcomm);
if (selected_codec != HFP_AUDIO_CODEC_CVSD && selected_codec != HFP_AUDIO_CODEC_MSBC) { if (selected_codec != HFP_AUDIO_CODEC_CVSD && selected_codec != HFP_AUDIO_CODEC_MSBC) {
spa_log_warn(backend->log, NAME": unsupported codec negotiation: %d", selected_codec); spa_log_warn(backend->log, "unsupported codec negotiation: %d", selected_codec);
rfcomm_send_reply(rfcomm, "ERROR"); rfcomm_send_reply(rfcomm, "ERROR");
if (was_switching_codec) if (was_switching_codec)
spa_bt_device_emit_codec_switched(rfcomm->device, -EIO); spa_bt_device_emit_codec_switched(rfcomm->device, -EIO);
@ -772,7 +774,7 @@ static bool rfcomm_hfp_ag(struct spa_source *source, char* buf)
rfcomm->codec = selected_codec; rfcomm->codec = selected_codec;
spa_log_debug(backend->log, NAME": RFCOMM selected_codec = %i", selected_codec); spa_log_debug(backend->log, "RFCOMM selected_codec = %i", selected_codec);
/* Recreate transport, since previous connection may now be invalid */ /* Recreate transport, since previous connection may now be invalid */
if (rfcomm->transport) if (rfcomm->transport)
@ -780,7 +782,7 @@ static bool rfcomm_hfp_ag(struct spa_source *source, char* buf)
rfcomm->transport = _transport_create(rfcomm); rfcomm->transport = _transport_create(rfcomm);
if (rfcomm->transport == NULL) { if (rfcomm->transport == NULL) {
spa_log_warn(backend->log, NAME": can't create transport: %m"); spa_log_warn(backend->log, "can't create transport: %m");
// TODO: We should manage the missing transport // TODO: We should manage the missing transport
rfcomm_send_reply(rfcomm, "ERROR"); rfcomm_send_reply(rfcomm, "ERROR");
if (was_switching_codec) if (was_switching_codec)
@ -800,7 +802,7 @@ static bool rfcomm_hfp_ag(struct spa_source *source, char* buf)
rfcomm_emit_volume_changed(rfcomm, SPA_BT_VOLUME_ID_RX, gain); rfcomm_emit_volume_changed(rfcomm, SPA_BT_VOLUME_ID_RX, gain);
rfcomm_send_reply(rfcomm, "OK"); rfcomm_send_reply(rfcomm, "OK");
} else { } else {
spa_log_debug(backend->log, NAME": RFCOMM receive unsupported VGM gain: %s", buf); spa_log_debug(backend->log, "RFCOMM receive unsupported VGM gain: %s", buf);
rfcomm_send_reply(rfcomm, "ERROR"); rfcomm_send_reply(rfcomm, "ERROR");
} }
} else if (sscanf(buf, "AT+VGS=%u", &gain) == 1) { } else if (sscanf(buf, "AT+VGS=%u", &gain) == 1) {
@ -808,7 +810,7 @@ static bool rfcomm_hfp_ag(struct spa_source *source, char* buf)
rfcomm_emit_volume_changed(rfcomm, SPA_BT_VOLUME_ID_TX, gain); rfcomm_emit_volume_changed(rfcomm, SPA_BT_VOLUME_ID_TX, gain);
rfcomm_send_reply(rfcomm, "OK"); rfcomm_send_reply(rfcomm, "OK");
} else { } else {
spa_log_debug(backend->log, NAME": RFCOMM receive unsupported VGS gain: %s", buf); spa_log_debug(backend->log, "RFCOMM receive unsupported VGS gain: %s", buf);
rfcomm_send_reply(rfcomm, "ERROR"); rfcomm_send_reply(rfcomm, "ERROR");
} }
} else if (spa_strstartswith(buf, "AT+BIND=?")) { } else if (spa_strstartswith(buf, "AT+BIND=?")) {
@ -825,16 +827,16 @@ static bool rfcomm_hfp_ag(struct spa_source *source, char* buf)
} else if (sscanf(buf, "AT+BIEV=%u,%u", &indicator, &indicator_value) == 2) { } else if (sscanf(buf, "AT+BIEV=%u,%u", &indicator, &indicator_value) == 2) {
if (indicator == SPA_BT_HFP_HF_INDICATOR_BATTERY_LEVEL) { if (indicator == SPA_BT_HFP_HF_INDICATOR_BATTERY_LEVEL) {
// Battery level is reported in range 0-100 // Battery level is reported in range 0-100
spa_log_debug(backend->log, NAME": battery level: %u%%", indicator_value); spa_log_debug(backend->log, "battery level: %u%%", indicator_value);
if (indicator_value <= 100) { if (indicator_value <= 100) {
// TODO: report without Battery Provider (using props) // TODO: report without Battery Provider (using props)
spa_bt_device_report_battery_level(rfcomm->device, indicator_value); spa_bt_device_report_battery_level(rfcomm->device, indicator_value);
} else { } else {
spa_log_warn(backend->log, NAME": battery HF indicator %u outside of range [0, 100]: %u", indicator, indicator_value); spa_log_warn(backend->log, "battery HF indicator %u outside of range [0, 100]: %u", indicator, indicator_value);
} }
} else { } else {
spa_log_warn(backend->log, NAME": unknown HF indicator: %u", indicator); spa_log_warn(backend->log, "unknown HF indicator: %u", indicator);
} }
} else if (sscanf(buf, "AT+XAPL=%04x-%04x-%04x,%u", &xapl_vendor, &xapl_product, &xapl_version, &xapl_features) == 4) { } else if (sscanf(buf, "AT+XAPL=%04x-%04x-%04x,%u", &xapl_vendor, &xapl_product, &xapl_version, &xapl_features) == 4) {
if (xapl_features & SPA_BT_HFP_HF_XAPL_FEATURE_BATTERY_REPORTING) { if (xapl_features & SPA_BT_HFP_HF_XAPL_FEATURE_BATTERY_REPORTING) {
@ -867,7 +869,7 @@ static bool rfcomm_hfp_ag(struct spa_source *source, char* buf)
if (k == SPA_BT_HFP_HF_IPHONEACCEV_KEY_BATTERY_LEVEL) { if (k == SPA_BT_HFP_HF_IPHONEACCEV_KEY_BATTERY_LEVEL) {
// Battery level is reported in range of 0-9, convert to 0-100% // Battery level is reported in range of 0-9, convert to 0-100%
uint8_t level = (SPA_CLAMP(v, 0, 9) + 1) * 10; uint8_t level = (SPA_CLAMP(v, 0, 9) + 1) * 10;
spa_log_debug(backend->log, NAME": battery level: %d%%", (int)level); spa_log_debug(backend->log, "battery level: %d%%", (int)level);
// TODO: report without Battery Provider (using props) // TODO: report without Battery Provider (using props)
spa_bt_device_report_battery_level(rfcomm->device, level); spa_bt_device_report_battery_level(rfcomm->device, level);
@ -910,9 +912,9 @@ static bool rfcomm_hfp_hf(struct spa_source *source, char* buf)
selected_codec = atoi(token); selected_codec = atoi(token);
if (selected_codec != HFP_AUDIO_CODEC_CVSD && selected_codec != HFP_AUDIO_CODEC_MSBC) { if (selected_codec != HFP_AUDIO_CODEC_CVSD && selected_codec != HFP_AUDIO_CODEC_MSBC) {
spa_log_warn(backend->log, NAME": unsupported codec negotiation: %d", selected_codec); spa_log_warn(backend->log, "unsupported codec negotiation: %d", selected_codec);
} else { } else {
spa_log_debug(backend->log, NAME": RFCOMM selected_codec = %i", selected_codec); spa_log_debug(backend->log, "RFCOMM selected_codec = %i", selected_codec);
/* send codec selection to AG */ /* send codec selection to AG */
rfcomm_send_cmd(rfcomm, "AT+BCS=%u", selected_codec); rfcomm_send_cmd(rfcomm, "AT+BCS=%u", selected_codec);
@ -925,7 +927,7 @@ static bool rfcomm_hfp_hf(struct spa_source *source, char* buf)
rfcomm->transport = _transport_create(rfcomm); rfcomm->transport = _transport_create(rfcomm);
if (rfcomm->transport == NULL) { if (rfcomm->transport == NULL) {
spa_log_warn(backend->log, NAME": can't create transport: %m"); spa_log_warn(backend->log, "can't create transport: %m");
// TODO: We should manage the missing transport // TODO: We should manage the missing transport
} else { } else {
rfcomm->transport->codec = selected_codec; rfcomm->transport->codec = selected_codec;
@ -944,7 +946,7 @@ static bool rfcomm_hfp_hf(struct spa_source *source, char* buf)
if (gain <= SPA_BT_VOLUME_HS_MAX) { if (gain <= SPA_BT_VOLUME_HS_MAX) {
rfcomm_emit_volume_changed(rfcomm, SPA_BT_VOLUME_ID_TX, gain); rfcomm_emit_volume_changed(rfcomm, SPA_BT_VOLUME_ID_TX, gain);
} else { } else {
spa_log_debug(backend->log, NAME": RFCOMM receive unsupported VGM gain: %s", token); spa_log_debug(backend->log, "RFCOMM receive unsupported VGM gain: %s", token);
} }
} else if (strncmp(token, "+VGS", 4) == 0) { } else if (strncmp(token, "+VGS", 4) == 0) {
/* get next token */ /* get next token */
@ -954,7 +956,7 @@ static bool rfcomm_hfp_hf(struct spa_source *source, char* buf)
if (gain <= SPA_BT_VOLUME_HS_MAX) { if (gain <= SPA_BT_VOLUME_HS_MAX) {
rfcomm_emit_volume_changed(rfcomm, SPA_BT_VOLUME_ID_RX, gain); rfcomm_emit_volume_changed(rfcomm, SPA_BT_VOLUME_ID_RX, gain);
} else { } else {
spa_log_debug(backend->log, NAME": RFCOMM receive unsupported VGS gain: %s", token); spa_log_debug(backend->log, "RFCOMM receive unsupported VGS gain: %s", token);
} }
} else if (strncmp(token, "OK", 5) == 0) { } else if (strncmp(token, "OK", 5) == 0) {
switch(rfcomm->hf_state) { switch(rfcomm->hf_state) {
@ -985,7 +987,7 @@ static bool rfcomm_hfp_hf(struct spa_source *source, char* buf)
if (!rfcomm->codec_negotiation_supported) { if (!rfcomm->codec_negotiation_supported) {
rfcomm->transport = _transport_create(rfcomm); rfcomm->transport = _transport_create(rfcomm);
if (rfcomm->transport == NULL) { if (rfcomm->transport == NULL) {
spa_log_warn(backend->log, NAME": can't create transport: %m"); spa_log_warn(backend->log, "can't create transport: %m");
// TODO: We should manage the missing transport // TODO: We should manage the missing transport
} else { } else {
rfcomm->transport->codec = HFP_AUDIO_CODEC_CVSD; rfcomm->transport->codec = HFP_AUDIO_CODEC_CVSD;
@ -1024,7 +1026,7 @@ static void rfcomm_event(struct spa_source *source)
struct impl *backend = rfcomm->backend; struct impl *backend = rfcomm->backend;
if (source->rmask & (SPA_IO_HUP | SPA_IO_ERR)) { if (source->rmask & (SPA_IO_HUP | SPA_IO_ERR)) {
spa_log_info(backend->log, NAME": lost RFCOMM connection."); spa_log_info(backend->log, "lost RFCOMM connection.");
rfcomm_free(rfcomm); rfcomm_free(rfcomm);
return; return;
} }
@ -1036,11 +1038,11 @@ static void rfcomm_event(struct spa_source *source)
len = read(source->fd, buf, 511); len = read(source->fd, buf, 511);
if (len < 0) { if (len < 0) {
spa_log_error(backend->log, NAME": RFCOMM read error: %s", strerror(errno)); spa_log_error(backend->log, "RFCOMM read error: %s", strerror(errno));
return; return;
} }
buf[len] = 0; buf[len] = 0;
spa_log_debug(backend->log, NAME": RFCOMM << %s", buf); spa_log_debug(backend->log, "RFCOMM << %s", buf);
#ifdef HAVE_BLUEZ_5_BACKEND_HSP_NATIVE #ifdef HAVE_BLUEZ_5_BACKEND_HSP_NATIVE
if (rfcomm->profile == SPA_BT_PROFILE_HSP_HS) if (rfcomm->profile == SPA_BT_PROFILE_HSP_HS)
@ -1056,7 +1058,7 @@ static void rfcomm_event(struct spa_source *source)
#endif #endif
if (!res) { if (!res) {
spa_log_debug(backend->log, NAME": RFCOMM receive unsupported command: %s", buf); spa_log_debug(backend->log, "RFCOMM receive unsupported command: %s", buf);
rfcomm_send_reply(rfcomm, "ERROR"); rfcomm_send_reply(rfcomm, "ERROR");
} }
} }
@ -1072,7 +1074,7 @@ static int sco_create_socket(struct impl *backend, struct spa_bt_adapter *adapte
sock = socket(PF_BLUETOOTH, SOCK_SEQPACKET, BTPROTO_SCO); sock = socket(PF_BLUETOOTH, SOCK_SEQPACKET, BTPROTO_SCO);
if (sock < 0) { if (sock < 0) {
spa_log_error(backend->log, NAME": socket(SEQPACKET, SCO) %s", strerror(errno)); spa_log_error(backend->log, "socket(SEQPACKET, SCO) %s", strerror(errno));
goto fail; goto fail;
} }
@ -1084,18 +1086,18 @@ static int sco_create_socket(struct impl *backend, struct spa_bt_adapter *adapte
bacpy(&addr.sco_bdaddr, &src); bacpy(&addr.sco_bdaddr, &src);
if (bind(sock, (struct sockaddr *) &addr, len) < 0) { if (bind(sock, (struct sockaddr *) &addr, len) < 0) {
spa_log_error(backend->log, NAME": bind(): %s", strerror(errno)); spa_log_error(backend->log, "bind(): %s", strerror(errno));
goto fail; goto fail;
} }
spa_log_debug(backend->log, NAME": msbc=%d", (int)msbc); spa_log_debug(backend->log, "msbc=%d", (int)msbc);
if (msbc) { if (msbc) {
/* set correct socket options for mSBC */ /* set correct socket options for mSBC */
struct bt_voice voice_config; struct bt_voice voice_config;
memset(&voice_config, 0, sizeof(voice_config)); memset(&voice_config, 0, sizeof(voice_config));
voice_config.setting = BT_VOICE_TRANSPARENT; voice_config.setting = BT_VOICE_TRANSPARENT;
if (setsockopt(sock, SOL_BLUETOOTH, BT_VOICE, &voice_config, sizeof(voice_config)) < 0) { if (setsockopt(sock, SOL_BLUETOOTH, BT_VOICE, &voice_config, sizeof(voice_config)) < 0) {
spa_log_error(backend->log, NAME": setsockopt(): %s", strerror(errno)); spa_log_error(backend->log, "setsockopt(): %s", strerror(errno));
goto fail; goto fail;
} }
} }
@ -1119,7 +1121,7 @@ static int sco_do_connect(struct spa_bt_transport *t)
bdaddr_t dst; bdaddr_t dst;
int retry = 2; int retry = 2;
spa_log_debug(backend->log, NAME": transport %p: enter sco_do_connect, codec=%u", spa_log_debug(backend->log, "transport %p: enter sco_do_connect, codec=%u",
t, t->codec); t, t->codec);
if (d->adapter == NULL) if (d->adapter == NULL)
@ -1137,15 +1139,15 @@ again:
addr.sco_family = AF_BLUETOOTH; addr.sco_family = AF_BLUETOOTH;
bacpy(&addr.sco_bdaddr, &dst); bacpy(&addr.sco_bdaddr, &dst);
spa_log_debug(backend->log, NAME": transport %p: doing connect", t); spa_log_debug(backend->log, "transport %p: doing connect", t);
err = connect(sock, (struct sockaddr *) &addr, len); err = connect(sock, (struct sockaddr *) &addr, len);
if (err < 0 && errno == ECONNABORTED && retry-- > 0) { if (err < 0 && errno == ECONNABORTED && retry-- > 0) {
spa_log_warn(backend->log, NAME": connect(): %s. Remaining retry:%d", spa_log_warn(backend->log, "connect(): %s. Remaining retry:%d",
strerror(errno), retry); strerror(errno), retry);
close(sock); close(sock);
goto again; goto again;
} else if (err < 0 && !(errno == EAGAIN || errno == EINPROGRESS)) { } else if (err < 0 && !(errno == EAGAIN || errno == EINPROGRESS)) {
spa_log_error(backend->log, NAME": connect(): %s", strerror(errno)); spa_log_error(backend->log, "connect(): %s", strerror(errno));
goto fail_close; goto fail_close;
} }
@ -1163,7 +1165,7 @@ static int sco_acquire_cb(void *data, bool optional)
int sock; int sock;
socklen_t len; socklen_t len;
spa_log_debug(backend->log, NAME": transport %p: enter sco_acquire_cb", t); spa_log_debug(backend->log, "transport %p: enter sco_acquire_cb", t);
if (optional || t->fd > 0) if (optional || t->fd > 0)
sock = t->fd; sock = t->fd;
@ -1186,14 +1188,14 @@ static int sco_acquire_cb(void *data, bool optional)
memset(&sco_opt, 0, len); memset(&sco_opt, 0, len);
if (getsockopt(sock, SOL_SCO, SCO_OPTIONS, &sco_opt, &len) < 0) if (getsockopt(sock, SOL_SCO, SCO_OPTIONS, &sco_opt, &len) < 0)
spa_log_warn(backend->log, NAME": getsockopt(SCO_OPTIONS) failed, loading defaults"); spa_log_warn(backend->log, "getsockopt(SCO_OPTIONS) failed, loading defaults");
else { else {
spa_log_debug(backend->log, NAME": autodetected mtu = %u", sco_opt.mtu); spa_log_debug(backend->log, "autodetected mtu = %u", sco_opt.mtu);
t->read_mtu = sco_opt.mtu; t->read_mtu = sco_opt.mtu;
t->write_mtu = sco_opt.mtu; t->write_mtu = sco_opt.mtu;
} }
} }
spa_log_debug(backend->log, NAME": transport %p: read_mtu=%u, write_mtu=%u", t, t->read_mtu, t->write_mtu); spa_log_debug(backend->log, "transport %p: read_mtu=%u, write_mtu=%u", t, t->read_mtu, t->write_mtu);
return 0; return 0;
@ -1206,7 +1208,7 @@ static int sco_release_cb(void *data)
struct spa_bt_transport *t = data; struct spa_bt_transport *t = data;
struct impl *backend = SPA_CONTAINER_OF(t->backend, struct impl, this); struct impl *backend = SPA_CONTAINER_OF(t->backend, struct impl, this);
spa_log_info(backend->log, NAME": Transport %s released", t->path); spa_log_info(backend->log, "Transport %s released", t->path);
if (t->sco_io) { if (t->sco_io) {
spa_bt_sco_io_destroy(t->sco_io); spa_bt_sco_io_destroy(t->sco_io);
@ -1229,7 +1231,7 @@ static void sco_event(struct spa_source *source)
struct impl *backend = SPA_CONTAINER_OF(t->backend, struct impl, this); struct impl *backend = SPA_CONTAINER_OF(t->backend, struct impl, this);
if (source->rmask & (SPA_IO_HUP | SPA_IO_ERR)) { if (source->rmask & (SPA_IO_HUP | SPA_IO_ERR)) {
spa_log_debug(backend->log, NAME": transport %p: error on SCO socket: %s", t, strerror(errno)); spa_log_debug(backend->log, "transport %p: error on SCO socket: %s", t, strerror(errno));
if (t->fd >= 0) { if (t->fd >= 0) {
if (source->loop) if (source->loop)
spa_loop_remove_source(source->loop, source); spa_loop_remove_source(source->loop, source);
@ -1253,18 +1255,18 @@ static void sco_listen_event(struct spa_source *source)
struct transport_data *td; struct transport_data *td;
if (source->rmask & (SPA_IO_HUP | SPA_IO_ERR)) { if (source->rmask & (SPA_IO_HUP | SPA_IO_ERR)) {
spa_log_error(backend->log, NAME": error listening SCO connection: %s", strerror(errno)); spa_log_error(backend->log, "error listening SCO connection: %s", strerror(errno));
goto fail; goto fail;
} }
memset(&addr, 0, sizeof(addr)); memset(&addr, 0, sizeof(addr));
optlen = sizeof(addr); optlen = sizeof(addr);
spa_log_debug(backend->log, NAME": doing accept"); spa_log_debug(backend->log, "doing accept");
sock = accept(source->fd, (struct sockaddr *) &addr, &optlen); sock = accept(source->fd, (struct sockaddr *) &addr, &optlen);
if (sock < 0) { if (sock < 0) {
if (errno != EAGAIN) if (errno != EAGAIN)
spa_log_error(backend->log, NAME": SCO accept(): %s", strerror(errno)); spa_log_error(backend->log, "SCO accept(): %s", strerror(errno));
goto fail; goto fail;
} }
@ -1274,7 +1276,7 @@ static void sco_listen_event(struct spa_source *source)
optlen = sizeof(addr); optlen = sizeof(addr);
if (getsockname(sock, (struct sockaddr *) &addr, &optlen) < 0) { if (getsockname(sock, (struct sockaddr *) &addr, &optlen) < 0) {
spa_log_error(backend->log, NAME": SCO getsockname(): %s", strerror(errno)); spa_log_error(backend->log, "SCO getsockname(): %s", strerror(errno));
goto fail; goto fail;
} }
@ -1289,7 +1291,7 @@ static void sco_listen_event(struct spa_source *source)
} }
} }
if (!t) { if (!t) {
spa_log_debug(backend->log, NAME": No transport for adapter %s and remote %s", spa_log_debug(backend->log, "No transport for adapter %s and remote %s",
local_address, remote_address); local_address, remote_address);
goto fail; goto fail;
} }
@ -1297,16 +1299,16 @@ static void sco_listen_event(struct spa_source *source)
/* The Synchronous Connection shall always be established by the AG, i.e. the remote profile /* The Synchronous Connection shall always be established by the AG, i.e. the remote profile
should be a HSP AG or HFP AG profile */ should be a HSP AG or HFP AG profile */
if ((t->profile & SPA_BT_PROFILE_HEADSET_AUDIO_GATEWAY) == 0) { if ((t->profile & SPA_BT_PROFILE_HEADSET_AUDIO_GATEWAY) == 0) {
spa_log_debug(backend->log, NAME": transport %p: Rejecting incoming audio connection to an AG profile", t); spa_log_debug(backend->log, "transport %p: Rejecting incoming audio connection to an AG profile", t);
goto fail; goto fail;
} }
if (t->fd >= 0) { if (t->fd >= 0) {
spa_log_debug(backend->log, NAME": transport %p: Rejecting, audio already connected", t); spa_log_debug(backend->log, "transport %p: Rejecting, audio already connected", t);
goto fail; goto fail;
} }
spa_log_debug(backend->log, NAME": transport %p: codec=%u", t, t->codec); spa_log_debug(backend->log, "transport %p: codec=%u", t, t->codec);
if (backend->defer_setup_enabled) { if (backend->defer_setup_enabled) {
/* In BT_DEFER_SETUP mode, when a connection is accepted, the listening socket is unblocked but /* In BT_DEFER_SETUP mode, when a connection is accepted, the listening socket is unblocked but
* the effective connection setup happens only on first receive, allowing to configure the * the effective connection setup happens only on first receive, allowing to configure the
@ -1319,14 +1321,14 @@ static void sco_listen_event(struct spa_source *source)
memset(&voice_config, 0, sizeof(voice_config)); memset(&voice_config, 0, sizeof(voice_config));
voice_config.setting = BT_VOICE_TRANSPARENT; voice_config.setting = BT_VOICE_TRANSPARENT;
if (setsockopt(sock, SOL_BLUETOOTH, BT_VOICE, &voice_config, sizeof(voice_config)) < 0) { if (setsockopt(sock, SOL_BLUETOOTH, BT_VOICE, &voice_config, sizeof(voice_config)) < 0) {
spa_log_error(backend->log, NAME": transport %p: setsockopt(): %s", t, strerror(errno)); spa_log_error(backend->log, "transport %p: setsockopt(): %s", t, strerror(errno));
goto fail; goto fail;
} }
} }
/* First read from the accepted socket is non-blocking and returns a zero length buffer. */ /* First read from the accepted socket is non-blocking and returns a zero length buffer. */
if (read(sock, &buff, 1) == -1) { if (read(sock, &buff, 1) == -1) {
spa_log_error(backend->log, NAME": transport %p: Couldn't authorize SCO connection: %s", t, strerror(errno)); spa_log_error(backend->log, "transport %p: Couldn't authorize SCO connection: %s", t, strerror(errno));
goto fail; goto fail;
} }
} }
@ -1341,7 +1343,7 @@ static void sco_listen_event(struct spa_source *source)
td->sco.rmask = 0; td->sco.rmask = 0;
spa_loop_add_source(backend->main_loop, &td->sco); spa_loop_add_source(backend->main_loop, &td->sco);
spa_log_debug(backend->log, NAME": transport %p: audio connected", t); spa_log_debug(backend->log, "transport %p: audio connected", t);
/* Report initial volume to remote */ /* Report initial volume to remote */
if (t->profile == SPA_BT_PROFILE_HSP_AG) { if (t->profile == SPA_BT_PROFILE_HSP_AG) {
@ -1373,7 +1375,7 @@ static int sco_listen(struct impl *backend)
sock = socket(PF_BLUETOOTH, SOCK_SEQPACKET | SOCK_NONBLOCK | SOCK_CLOEXEC, BTPROTO_SCO); sock = socket(PF_BLUETOOTH, SOCK_SEQPACKET | SOCK_NONBLOCK | SOCK_CLOEXEC, BTPROTO_SCO);
if (sock < 0) { if (sock < 0) {
spa_log_error(backend->log, NAME": socket(SEQPACKET, SCO) %m"); spa_log_error(backend->log, "socket(SEQPACKET, SCO) %m");
return -errno; return -errno;
} }
@ -1383,20 +1385,20 @@ static int sco_listen(struct impl *backend)
bacpy(&addr.sco_bdaddr, BDADDR_ANY); bacpy(&addr.sco_bdaddr, BDADDR_ANY);
if (bind(sock, (struct sockaddr *) &addr, sizeof(addr)) < 0) { if (bind(sock, (struct sockaddr *) &addr, sizeof(addr)) < 0) {
spa_log_error(backend->log, NAME": bind(): %m"); spa_log_error(backend->log, "bind(): %m");
goto fail_close; goto fail_close;
} }
if (setsockopt(sock, SOL_BLUETOOTH, BT_DEFER_SETUP, &defer, sizeof(defer)) < 0) { if (setsockopt(sock, SOL_BLUETOOTH, BT_DEFER_SETUP, &defer, sizeof(defer)) < 0) {
spa_log_warn(backend->log, NAME": Can't enable deferred setup: %s", strerror(errno)); spa_log_warn(backend->log, "Can't enable deferred setup: %s", strerror(errno));
backend->defer_setup_enabled = 0; backend->defer_setup_enabled = 0;
} else { } else {
backend->defer_setup_enabled = 1; backend->defer_setup_enabled = 1;
} }
spa_log_debug(backend->log, NAME": doing listen"); spa_log_debug(backend->log, "doing listen");
if (listen(sock, 1) < 0) { if (listen(sock, 1) < 0) {
spa_log_error(backend->log, NAME": listen(): %m"); spa_log_error(backend->log, "listen(): %m");
goto fail_close; goto fail_close;
} }
@ -1539,7 +1541,7 @@ static void codec_switch_timer_event(struct spa_source *source)
if (rfcomm->transport == NULL) { if (rfcomm->transport == NULL) {
rfcomm->transport = _transport_create(rfcomm); rfcomm->transport = _transport_create(rfcomm);
if (rfcomm->transport == NULL) { if (rfcomm->transport == NULL) {
spa_log_warn(backend->log, NAME": can't create transport: %m"); spa_log_warn(backend->log, "can't create transport: %m");
} else { } else {
rfcomm->transport->codec = HFP_AUDIO_CODEC_CVSD; rfcomm->transport->codec = HFP_AUDIO_CODEC_CVSD;
spa_bt_device_connect_profile(rfcomm->device, rfcomm->profile); spa_bt_device_connect_profile(rfcomm->device, rfcomm->profile);
@ -1640,7 +1642,7 @@ static DBusHandlerResult profile_new_connection(DBusConnection *conn, DBusMessag
int fd; int fd;
if (!dbus_message_has_signature(m, "oha{sv}")) { if (!dbus_message_has_signature(m, "oha{sv}")) {
spa_log_warn(backend->log, NAME": invalid NewConnection() signature"); spa_log_warn(backend->log, "invalid NewConnection() signature");
return DBUS_HANDLER_RESULT_NOT_YET_HANDLED; return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
} }
@ -1659,7 +1661,7 @@ static DBusHandlerResult profile_new_connection(DBusConnection *conn, DBusMessag
#endif #endif
if (profile == SPA_BT_PROFILE_NULL) { if (profile == SPA_BT_PROFILE_NULL) {
spa_log_warn(backend->log, NAME": invalid handler %s", handler); spa_log_warn(backend->log, "invalid handler %s", handler);
return DBUS_HANDLER_RESULT_NOT_YET_HANDLED; return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
} }
@ -1668,7 +1670,7 @@ static DBusHandlerResult profile_new_connection(DBusConnection *conn, DBusMessag
d = spa_bt_device_find(backend->monitor, path); d = spa_bt_device_find(backend->monitor, path);
if (d == NULL) { if (d == NULL) {
spa_log_warn(backend->log, NAME": unknown device for path %s", path); spa_log_warn(backend->log, "unknown device for path %s", path);
return DBUS_HANDLER_RESULT_NOT_YET_HANDLED; return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
} }
spa_bt_device_add_profile(d, profile); spa_bt_device_add_profile(d, profile);
@ -1676,7 +1678,7 @@ static DBusHandlerResult profile_new_connection(DBusConnection *conn, DBusMessag
dbus_message_iter_next(&it[0]); dbus_message_iter_next(&it[0]);
dbus_message_iter_get_basic(&it[0], &fd); dbus_message_iter_get_basic(&it[0], &fd);
spa_log_debug(backend->log, NAME": NewConnection path=%s, fd=%d, profile %s", path, fd, handler); spa_log_debug(backend->log, "NewConnection path=%s, fd=%d, profile %s", path, fd, handler);
rfcomm = calloc(1, sizeof(struct rfcomm)); rfcomm = calloc(1, sizeof(struct rfcomm));
if (rfcomm == NULL) if (rfcomm == NULL)
@ -1705,7 +1707,7 @@ static DBusHandlerResult profile_new_connection(DBusConnection *conn, DBusMessag
if (profile == SPA_BT_PROFILE_HSP_HS || profile == SPA_BT_PROFILE_HSP_AG) { if (profile == SPA_BT_PROFILE_HSP_HS || profile == SPA_BT_PROFILE_HSP_AG) {
t = _transport_create(rfcomm); t = _transport_create(rfcomm);
if (t == NULL) { if (t == NULL) {
spa_log_warn(backend->log, NAME": can't create transport: %m"); spa_log_warn(backend->log, "can't create transport: %m");
goto fail_need_memory; goto fail_need_memory;
} }
rfcomm->transport = t; rfcomm->transport = t;
@ -1717,7 +1719,7 @@ static DBusHandlerResult profile_new_connection(DBusConnection *conn, DBusMessag
spa_bt_device_connect_profile(t->device, profile); spa_bt_device_connect_profile(t->device, profile);
spa_log_debug(backend->log, NAME": Transport %s available for profile %s", t->path, handler); spa_log_debug(backend->log, "Transport %s available for profile %s", t->path, handler);
} else if (profile == SPA_BT_PROFILE_HFP_AG) { } else if (profile == SPA_BT_PROFILE_HFP_AG) {
/* Start SLC connection */ /* Start SLC connection */
unsigned int hf_features = SPA_BT_HFP_HF_FEATURE_NONE; unsigned int hf_features = SPA_BT_HFP_HF_FEATURE_NONE;
@ -1750,7 +1752,7 @@ static DBusHandlerResult profile_new_connection(DBusConnection *conn, DBusMessag
if (spa_bt_quirks_get_features(backend->quirks, d->adapter, d, &device_features) == 0) { if (spa_bt_quirks_get_features(backend->quirks, d->adapter, d, &device_features) == 0) {
rfcomm->broken_mic_hw_volume = !(device_features & SPA_BT_FEATURE_HW_VOLUME_MIC); rfcomm->broken_mic_hw_volume = !(device_features & SPA_BT_FEATURE_HW_VOLUME_MIC);
if (rfcomm->broken_mic_hw_volume) if (rfcomm->broken_mic_hw_volume)
spa_log_debug(backend->log, NAME": microphone HW volume disabled by quirk"); spa_log_debug(backend->log, "microphone HW volume disabled by quirk");
} }
} }
@ -1779,7 +1781,7 @@ static DBusHandlerResult profile_request_disconnection(DBusConnection *conn, DBu
struct rfcomm *rfcomm, *rfcomm_tmp; struct rfcomm *rfcomm, *rfcomm_tmp;
if (!dbus_message_has_signature(m, "o")) { if (!dbus_message_has_signature(m, "o")) {
spa_log_warn(backend->log, NAME": invalid RequestDisconnection() signature"); spa_log_warn(backend->log, "invalid RequestDisconnection() signature");
return DBUS_HANDLER_RESULT_NOT_YET_HANDLED; return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
} }
@ -1798,7 +1800,7 @@ static DBusHandlerResult profile_request_disconnection(DBusConnection *conn, DBu
#endif #endif
if (profile == SPA_BT_PROFILE_NULL) { if (profile == SPA_BT_PROFILE_NULL) {
spa_log_warn(backend->log, NAME": invalid handler %s", handler); spa_log_warn(backend->log, "invalid handler %s", handler);
return DBUS_HANDLER_RESULT_NOT_YET_HANDLED; return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
} }
@ -1807,7 +1809,7 @@ static DBusHandlerResult profile_request_disconnection(DBusConnection *conn, DBu
d = spa_bt_device_find(backend->monitor, path); d = spa_bt_device_find(backend->monitor, path);
if (d == NULL) { if (d == NULL) {
spa_log_warn(backend->log, NAME": unknown device for path %s", path); spa_log_warn(backend->log, "unknown device for path %s", path);
return DBUS_HANDLER_RESULT_NOT_YET_HANDLED; return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
} }
@ -1838,7 +1840,7 @@ static DBusHandlerResult profile_handler(DBusConnection *c, DBusMessage *m, void
interface = dbus_message_get_interface(m); interface = dbus_message_get_interface(m);
member = dbus_message_get_member(m); member = dbus_message_get_member(m);
spa_log_debug(backend->log, NAME": dbus: path=%s, interface=%s, member=%s", path, interface, member); spa_log_debug(backend->log, "dbus: path=%s, interface=%s, member=%s", path, interface, member);
if (dbus_message_is_method_call(m, "org.freedesktop.DBus.Introspectable", "Introspect")) { if (dbus_message_is_method_call(m, "org.freedesktop.DBus.Introspectable", "Introspect")) {
const char *xml = PROFILE_INTROSPECT_XML; const char *xml = PROFILE_INTROSPECT_XML;
@ -1875,15 +1877,15 @@ static void register_profile_reply(DBusPendingCall *pending, void *user_data)
return; return;
if (dbus_message_is_error(r, BLUEZ_ERROR_NOT_SUPPORTED)) { if (dbus_message_is_error(r, BLUEZ_ERROR_NOT_SUPPORTED)) {
spa_log_warn(backend->log, NAME": Register profile not supported"); spa_log_warn(backend->log, "Register profile not supported");
goto finish; goto finish;
} }
if (dbus_message_is_error(r, DBUS_ERROR_UNKNOWN_METHOD)) { if (dbus_message_is_error(r, DBUS_ERROR_UNKNOWN_METHOD)) {
spa_log_warn(backend->log, NAME": Error registering profile"); spa_log_warn(backend->log, "Error registering profile");
goto finish; goto finish;
} }
if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) { if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) {
spa_log_error(backend->log, NAME": RegisterProfile() failed: %s", spa_log_error(backend->log, "RegisterProfile() failed: %s",
dbus_message_get_error_name(r)); dbus_message_get_error_name(r));
goto finish; goto finish;
} }
@ -1905,7 +1907,7 @@ static int register_profile(struct impl *backend, const char *profile, const cha
if (!(backend->enabled_profiles & spa_bt_profile_from_uuid(uuid))) if (!(backend->enabled_profiles & spa_bt_profile_from_uuid(uuid)))
return -ECANCELED; return -ECANCELED;
spa_log_debug(backend->log, NAME": Registering Profile %s %s", profile, uuid); spa_log_debug(backend->log, "Registering Profile %s %s", profile, uuid);
m = dbus_message_new_method_call(BLUEZ_SERVICE, "/org/bluez", m = dbus_message_new_method_call(BLUEZ_SERVICE, "/org/bluez",
BLUEZ_PROFILE_MANAGER_INTERFACE, "RegisterProfile"); BLUEZ_PROFILE_MANAGER_INTERFACE, "RegisterProfile");
@ -2004,7 +2006,7 @@ static void unregister_profile(struct impl *backend, const char *profile)
DBusMessage *m, *r; DBusMessage *m, *r;
DBusError err; DBusError err;
spa_log_debug(backend->log, NAME": Unregistering Profile %s", profile); spa_log_debug(backend->log, "Unregistering Profile %s", profile);
m = dbus_message_new_method_call(BLUEZ_SERVICE, "/org/bluez", m = dbus_message_new_method_call(BLUEZ_SERVICE, "/org/bluez",
BLUEZ_PROFILE_MANAGER_INTERFACE, "UnregisterProfile"); BLUEZ_PROFILE_MANAGER_INTERFACE, "UnregisterProfile");
@ -2020,13 +2022,13 @@ static void unregister_profile(struct impl *backend, const char *profile)
m = NULL; m = NULL;
if (r == NULL) { if (r == NULL) {
spa_log_error(backend->log, NAME": Unregistering Profile %s failed", profile); spa_log_error(backend->log, "Unregistering Profile %s failed", profile);
dbus_error_free(&err); dbus_error_free(&err);
return; return;
} }
if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) { if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) {
spa_log_error(backend->log, NAME": UnregisterProfile() returned error: %s", dbus_message_get_error_name(r)); spa_log_error(backend->log, "UnregisterProfile() returned error: %s", dbus_message_get_error_name(r));
return; return;
} }
@ -2171,6 +2173,8 @@ struct spa_bt_backend *backend_native_new(struct spa_bt_monitor *monitor,
backend->conn = dbus_connection; backend->conn = dbus_connection;
backend->sco.fd = -1; backend->sco.fd = -1;
spa_log_topic_init(backend->log, &log_topic);
spa_list_init(&backend->rfcomm_list); spa_list_init(&backend->rfcomm_list);
if (parse_headset_roles(backend, info) < 0) if (parse_headset_roles(backend, info) < 0)

82
spa/plugins/bluez5/backend-ofono.c
View file

@ -42,7 +42,9 @@
#include "defs.h" #include "defs.h"
#define NAME "oFono" static struct spa_log_topic log_topic = SPA_LOG_TOPIC(0, "spa.bluez5.ofono");
#undef SPA_LOG_TOPIC_DEFAULT
#define SPA_LOG_TOPIC_DEFAULT &log_topic
struct impl { struct impl {
struct spa_bt_backend this; struct spa_bt_backend this;
@ -107,9 +109,9 @@ static void ofono_transport_get_mtu(struct impl *backend, struct spa_bt_transpor
memset(&sco_opt, 0, len); memset(&sco_opt, 0, len);
if (getsockopt(t->fd, SOL_SCO, SCO_OPTIONS, &sco_opt, &len) < 0) if (getsockopt(t->fd, SOL_SCO, SCO_OPTIONS, &sco_opt, &len) < 0)
spa_log_warn(backend->log, NAME": getsockopt(SCO_OPTIONS) failed, loading defaults"); spa_log_warn(backend->log, "getsockopt(SCO_OPTIONS) failed, loading defaults");
else { else {
spa_log_debug(backend->log, NAME" : autodetected mtu = %u", sco_opt.mtu); spa_log_debug(backend->log, "autodetected mtu = %u", sco_opt.mtu);
t->read_mtu = sco_opt.mtu; t->read_mtu = sco_opt.mtu;
t->write_mtu = sco_opt.mtu; t->write_mtu = sco_opt.mtu;
} }
@ -127,7 +129,7 @@ static struct spa_bt_transport *_transport_create(struct impl *backend,
t = spa_bt_transport_create(backend->monitor, t_path, sizeof(struct transport_data)); t = spa_bt_transport_create(backend->monitor, t_path, sizeof(struct transport_data));
if (t == NULL) { if (t == NULL) {
spa_log_warn(backend->log, NAME": can't create transport: %m"); spa_log_warn(backend->log, "can't create transport: %m");
free(t_path); free(t_path);
goto finish; goto finish;
} }
@ -164,14 +166,14 @@ static int _audio_acquire(struct impl *backend, const char *path, uint8_t *codec
m = NULL; m = NULL;
if (r == NULL) { if (r == NULL) {
spa_log_error(backend->log, NAME": Transport Acquire() failed for transport %s (%s)", spa_log_error(backend->log, "Transport Acquire() failed for transport %s (%s)",
path, err.message); path, err.message);
dbus_error_free(&err); dbus_error_free(&err);
return -EIO; return -EIO;
} }
if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) { if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) {
spa_log_error(backend->log, NAME": Acquire returned error: %s", dbus_message_get_error_name(r)); spa_log_error(backend->log, "Acquire returned error: %s", dbus_message_get_error_name(r));
ret = -EIO; ret = -EIO;
goto finish; goto finish;
} }
@ -180,7 +182,7 @@ static int _audio_acquire(struct impl *backend, const char *path, uint8_t *codec
DBUS_TYPE_UNIX_FD, &ret, DBUS_TYPE_UNIX_FD, &ret,
DBUS_TYPE_BYTE, codec, DBUS_TYPE_BYTE, codec,
DBUS_TYPE_INVALID)) { DBUS_TYPE_INVALID)) {
spa_log_error(backend->log, NAME": Failed to parse Acquire() reply: %s", err.message); spa_log_error(backend->log, "Failed to parse Acquire() reply: %s", err.message);
dbus_error_free(&err); dbus_error_free(&err);
ret = -EIO; ret = -EIO;
goto finish; goto finish;
@ -210,7 +212,7 @@ static int ofono_audio_acquire(void *data, bool optional)
if (transport->codec != codec) { if (transport->codec != codec) {
struct spa_bt_transport *t = NULL; struct spa_bt_transport *t = NULL;
spa_log_warn(backend->log, NAME": Acquired codec (%d) differs from transport one (%d)", spa_log_warn(backend->log, "Acquired codec (%d) differs from transport one (%d)",
codec, transport->codec); codec, transport->codec);
/* shutdown to make sure connection is dropped immediately */ /* shutdown to make sure connection is dropped immediately */
@ -229,7 +231,7 @@ static int ofono_audio_acquire(void *data, bool optional)
goto finish; goto finish;
} }
spa_log_debug(backend->log, NAME": transport %p: Acquire %s, fd %d codec %d", transport, spa_log_debug(backend->log, "transport %p: Acquire %s, fd %d codec %d", transport,
transport->path, transport->fd, transport->codec); transport->path, transport->fd, transport->codec);
ofono_transport_get_mtu(backend, transport); ofono_transport_get_mtu(backend, transport);
@ -244,7 +246,7 @@ static int ofono_audio_release(void *data)
struct spa_bt_transport *transport = data; struct spa_bt_transport *transport = data;
struct impl *backend = SPA_CONTAINER_OF(transport->backend, struct impl, this); struct impl *backend = SPA_CONTAINER_OF(transport->backend, struct impl, this);
spa_log_debug(backend->log, NAME": transport %p: Release %s", spa_log_debug(backend->log, "transport %p: Release %s",
transport, transport->path); transport, transport->path);
if (transport->sco_io) { if (transport->sco_io) {
@ -267,14 +269,14 @@ static DBusHandlerResult ofono_audio_card_removed(struct impl *backend, const ch
spa_assert(backend); spa_assert(backend);
spa_assert(path); spa_assert(path);
spa_log_debug(backend->log, NAME": card removed: %s", path); spa_log_debug(backend->log, "card removed: %s", path);
transport = spa_bt_transport_find(backend->monitor, path); transport = spa_bt_transport_find(backend->monitor, path);
if (transport != NULL) { if (transport != NULL) {
struct spa_bt_device *device = transport->device; struct spa_bt_device *device = transport->device;
spa_log_debug(backend->log, NAME" :transport %p: free %s", spa_log_debug(backend->log, "transport %p: free %s",
transport, transport->path); transport, transport->path);
spa_bt_transport_free(transport); spa_bt_transport_free(transport);
@ -304,7 +306,7 @@ static DBusHandlerResult ofono_audio_card_found(struct impl *backend, char *path
spa_assert(path); spa_assert(path);
spa_assert(props_i); spa_assert(props_i);
spa_log_debug(backend->log, NAME": new card: %s", path); spa_log_debug(backend->log, "new card: %s", path);
while (dbus_message_iter_get_arg_type(props_i) != DBUS_TYPE_INVALID) { while (dbus_message_iter_get_arg_type(props_i) != DBUS_TYPE_INVALID) {
DBusMessageIter i, value_i; DBusMessageIter i, value_i;
@ -318,7 +320,7 @@ static DBusHandlerResult ofono_audio_card_found(struct impl *backend, char *path
dbus_message_iter_recurse(&i, &value_i); dbus_message_iter_recurse(&i, &value_i);
if ((c = dbus_message_iter_get_arg_type(&value_i)) != DBUS_TYPE_STRING) { if ((c = dbus_message_iter_get_arg_type(&value_i)) != DBUS_TYPE_STRING) {
spa_log_error(backend->log, NAME": Invalid properties for %s: expected 's', received '%c'", path, c); spa_log_error(backend->log, "Invalid properties for %s: expected 's', received '%c'", path, c);
return DBUS_HANDLER_RESULT_NOT_YET_HANDLED; return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
} }
@ -333,7 +335,7 @@ static DBusHandlerResult ofono_audio_card_found(struct impl *backend, char *path
profile = SPA_BT_PROFILE_HFP_HF; profile = SPA_BT_PROFILE_HFP_HF;
} }
spa_log_debug(backend->log, NAME": %s: %s", key, value); spa_log_debug(backend->log, "%s: %s", key, value);
dbus_message_iter_next(props_i); dbus_message_iter_next(props_i);
} }
@ -348,7 +350,7 @@ static DBusHandlerResult ofono_audio_card_found(struct impl *backend, char *path
if (profile == SPA_BT_PROFILE_HFP_HF) { if (profile == SPA_BT_PROFILE_HFP_HF) {
int fd = _audio_acquire(backend, path, &codec); int fd = _audio_acquire(backend, path, &codec);
if (fd < 0) { if (fd < 0) {
spa_log_error(backend->log, NAME": Failed to retrieve codec for %s", path); spa_log_error(backend->log, "Failed to retrieve codec for %s", path);
return DBUS_HANDLER_RESULT_NOT_YET_HANDLED; return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
} }
/* shutdown to make sure connection is dropped immediately */ /* shutdown to make sure connection is dropped immediately */
@ -357,13 +359,13 @@ static DBusHandlerResult ofono_audio_card_found(struct impl *backend, char *path
} }
if (!remote_address || !local_address) { if (!remote_address || !local_address) {
spa_log_error(backend->log, NAME": Missing addresses for %s", path); spa_log_error(backend->log, "Missing addresses for %s", path);
return DBUS_HANDLER_RESULT_NOT_YET_HANDLED; return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
} }
d = spa_bt_device_find_by_address(backend->monitor, remote_address, local_address); d = spa_bt_device_find_by_address(backend->monitor, remote_address, local_address);
if (!d) { if (!d) {
spa_log_error(backend->log, NAME": Device doesn’t exist for %s", path); spa_log_error(backend->log, "Device doesn’t exist for %s", path);
return DBUS_HANDLER_RESULT_NOT_YET_HANDLED; return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
} }
spa_bt_device_add_profile(d, profile); spa_bt_device_add_profile(d, profile);
@ -372,7 +374,7 @@ static DBusHandlerResult ofono_audio_card_found(struct impl *backend, char *path
spa_bt_device_connect_profile(t->device, profile); spa_bt_device_connect_profile(t->device, profile);
spa_log_debug(backend->log, NAME": Transport %s available, codec %d", t->path, t->codec); spa_log_debug(backend->log, "Transport %s available, codec %d", t->path, t->codec);
return DBUS_HANDLER_RESULT_HANDLED; return DBUS_HANDLER_RESULT_HANDLED;
} }
@ -382,7 +384,7 @@ static DBusHandlerResult ofono_release(DBusConnection *conn, DBusMessage *m, voi
struct impl *backend = userdata; struct impl *backend = userdata;
DBusMessage *r; DBusMessage *r;
spa_log_warn(backend->log, NAME": release"); spa_log_warn(backend->log, "release");
r = dbus_message_new_error(m, OFONO_HF_AUDIO_AGENT_INTERFACE ".Error.NotImplemented", r = dbus_message_new_error(m, OFONO_HF_AUDIO_AGENT_INTERFACE ".Error.NotImplemented",
"Method not implemented"); "Method not implemented");
@ -401,7 +403,7 @@ static void sco_event(struct spa_source *source)
struct impl *backend = SPA_CONTAINER_OF(t->backend, struct impl, this); struct impl *backend = SPA_CONTAINER_OF(t->backend, struct impl, this);
if (source->rmask & (SPA_IO_HUP | SPA_IO_ERR)) { if (source->rmask & (SPA_IO_HUP | SPA_IO_ERR)) {
spa_log_debug(backend->log, NAME": transport %p: error on SCO socket: %s", t, strerror(errno)); spa_log_debug(backend->log, "transport %p: error on SCO socket: %s", t, strerror(errno));
if (t->fd >= 0) { if (t->fd >= 0) {
if (source->loop) if (source->loop)
spa_loop_remove_source(source->loop, source); spa_loop_remove_source(source->loop, source);
@ -467,7 +469,7 @@ static DBusHandlerResult ofono_new_audio_connection(DBusConnection *conn, DBusMe
err = enable_sco_socket(fd); err = enable_sco_socket(fd);
if (err) { if (err) {
spa_log_error(backend->log, NAME": transport %p: Couldn't authorize SCO connection: %s", t, strerror(err)); spa_log_error(backend->log, "transport %p: Couldn't authorize SCO connection: %s", t, strerror(err));
r = dbus_message_new_error(m, OFONO_ERROR_FAILED, "SCO authorization failed"); r = dbus_message_new_error(m, OFONO_ERROR_FAILED, "SCO authorization failed");
shutdown(fd, SHUT_RDWR); shutdown(fd, SHUT_RDWR);
close(fd); close(fd);
@ -477,7 +479,7 @@ static DBusHandlerResult ofono_new_audio_connection(DBusConnection *conn, DBusMe
t->fd = fd; t->fd = fd;
t->codec = codec; t->codec = codec;
spa_log_debug(backend->log, NAME": transport %p: NewConnection %s, fd %d codec %d", spa_log_debug(backend->log, "transport %p: NewConnection %s, fd %d codec %d",
t, t->path, t->fd, t->codec); t, t->path, t->fd, t->codec);
td = t->user_data; td = t->user_data;
@ -492,7 +494,7 @@ static DBusHandlerResult ofono_new_audio_connection(DBusConnection *conn, DBusMe
spa_bt_transport_set_state (t, SPA_BT_TRANSPORT_STATE_PENDING); spa_bt_transport_set_state (t, SPA_BT_TRANSPORT_STATE_PENDING);
} }
else if (fd) { else if (fd) {
spa_log_debug(backend->log, NAME": ignoring NewConnection"); spa_log_debug(backend->log, "ignoring NewConnection");
r = dbus_message_new_error(m, OFONO_ERROR_NOT_IMPLEMENTED, "Method not implemented"); r = dbus_message_new_error(m, OFONO_ERROR_NOT_IMPLEMENTED, "Method not implemented");
shutdown(fd, SHUT_RDWR); shutdown(fd, SHUT_RDWR);
close(fd); close(fd);
@ -521,7 +523,7 @@ static DBusHandlerResult ofono_handler(DBusConnection *c, DBusMessage *m, void *
interface = dbus_message_get_interface(m); interface = dbus_message_get_interface(m);
member = dbus_message_get_member(m); member = dbus_message_get_member(m);
spa_log_debug(backend->log, NAME": path=%s, interface=%s, member=%s", path, interface, member); spa_log_debug(backend->log, "path=%s, interface=%s, member=%s", path, interface, member);
if (dbus_message_is_method_call(m, "org.freedesktop.DBus.Introspectable", "Introspect")) { if (dbus_message_is_method_call(m, "org.freedesktop.DBus.Introspectable", "Introspect")) {
const char *xml = OFONO_INTROSPECT_XML; const char *xml = OFONO_INTROSPECT_XML;
@ -557,13 +559,13 @@ static void ofono_getcards_reply(DBusPendingCall *pending, void *user_data)
return; return;
if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) { if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) {
spa_log_error(backend->log, NAME": Failed to get a list of handsfree audio cards: %s", spa_log_error(backend->log, "Failed to get a list of handsfree audio cards: %s",
dbus_message_get_error_name(r)); dbus_message_get_error_name(r));
goto finish; goto finish;
} }
if (!dbus_message_iter_init(r, &i) || !spa_streq(dbus_message_get_signature(r), "a(oa{sv})")) { if (!dbus_message_iter_init(r, &i) || !spa_streq(dbus_message_get_signature(r), "a(oa{sv})")) {
spa_log_error(backend->log, NAME": Invalid arguments in GetCards() reply"); spa_log_error(backend->log, "Invalid arguments in GetCards() reply");
goto finish; goto finish;
} }
@ -599,7 +601,7 @@ static int backend_ofono_register(void *data)
DBusPendingCall *call; DBusPendingCall *call;
DBusError err; DBusError err;
spa_log_debug(backend->log, NAME": Registering"); spa_log_debug(backend->log, "Registering");
m = dbus_message_new_method_call(OFONO_SERVICE, "/", m = dbus_message_new_method_call(OFONO_SERVICE, "/",
OFONO_HF_AUDIO_MANAGER_INTERFACE, "Register"); OFONO_HF_AUDIO_MANAGER_INTERFACE, "Register");
@ -621,11 +623,11 @@ static int backend_ofono_register(void *data)
if (r == NULL) { if (r == NULL) {
if (dbus_error_has_name(&err, "org.freedesktop.DBus.Error.ServiceUnknown")) { if (dbus_error_has_name(&err, "org.freedesktop.DBus.Error.ServiceUnknown")) {
spa_log_info(backend->log, NAME": oFono not available: %s", spa_log_info(backend->log, "oFono not available: %s",
err.message); err.message);
res = -ENOTSUP; res = -ENOTSUP;
} else { } else {
spa_log_warn(backend->log, NAME": Registering Profile %s failed: %s (%s)", spa_log_warn(backend->log, "Registering Profile %s failed: %s (%s)",
path, err.message, err.name); path, err.message, err.name);
res = -EIO; res = -EIO;
} }
@ -634,29 +636,29 @@ static int backend_ofono_register(void *data)
} }
if (dbus_message_is_error(r, OFONO_ERROR_INVALID_ARGUMENTS)) { if (dbus_message_is_error(r, OFONO_ERROR_INVALID_ARGUMENTS)) {
spa_log_warn(backend->log, NAME": invalid arguments"); spa_log_warn(backend->log, "invalid arguments");
goto finish; goto finish;
} }
if (dbus_message_is_error(r, OFONO_ERROR_IN_USE)) { if (dbus_message_is_error(r, OFONO_ERROR_IN_USE)) {
spa_log_warn(backend->log, NAME": already in use"); spa_log_warn(backend->log, "already in use");
goto finish; goto finish;
} }
if (dbus_message_is_error(r, DBUS_ERROR_UNKNOWN_METHOD)) { if (dbus_message_is_error(r, DBUS_ERROR_UNKNOWN_METHOD)) {
spa_log_warn(backend->log, NAME": Error registering profile"); spa_log_warn(backend->log, "Error registering profile");
goto finish; goto finish;
} }
if (dbus_message_is_error(r, DBUS_ERROR_SERVICE_UNKNOWN)) { if (dbus_message_is_error(r, DBUS_ERROR_SERVICE_UNKNOWN)) {
spa_log_info(backend->log, NAME": oFono not available, disabling"); spa_log_info(backend->log, "oFono not available, disabling");
goto finish; goto finish;
} }
if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) { if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) {
spa_log_error(backend->log, NAME": Register() failed: %s", spa_log_error(backend->log, "Register() failed: %s",
dbus_message_get_error_name(r)); dbus_message_get_error_name(r));
goto finish; goto finish;
} }
dbus_message_unref(r); dbus_message_unref(r);
spa_log_debug(backend->log, NAME": registered"); spa_log_debug(backend->log, "registered");
m = dbus_message_new_method_call(OFONO_SERVICE, "/", m = dbus_message_new_method_call(OFONO_SERVICE, "/",
OFONO_HF_AUDIO_MANAGER_INTERFACE, "GetCards"); OFONO_HF_AUDIO_MANAGER_INTERFACE, "GetCards");
@ -686,7 +688,7 @@ static DBusHandlerResult ofono_filter_cb(DBusConnection *bus, DBusMessage *m, vo
DBusMessageIter arg_i, props_i; DBusMessageIter arg_i, props_i;
if (!dbus_message_iter_init(m, &arg_i) || !spa_streq(dbus_message_get_signature(m), "oa{sv}")) { if (!dbus_message_iter_init(m, &arg_i) || !spa_streq(dbus_message_get_signature(m), "oa{sv}")) {
spa_log_error(backend->log, NAME": Failed to parse org.ofono.HandsfreeAudioManager.CardAdded"); spa_log_error(backend->log, "Failed to parse org.ofono.HandsfreeAudioManager.CardAdded");
goto fail; goto fail;
} }
@ -702,7 +704,7 @@ static DBusHandlerResult ofono_filter_cb(DBusConnection *bus, DBusMessage *m, vo
const char *p; const char *p;
if (!dbus_message_get_args(m, &err, DBUS_TYPE_OBJECT_PATH, &p, DBUS_TYPE_INVALID)) { if (!dbus_message_get_args(m, &err, DBUS_TYPE_OBJECT_PATH, &p, DBUS_TYPE_INVALID)) {
spa_log_error(backend->log, NAME": Failed to parse org.ofono.HandsfreeAudioManager.CardRemoved: %s", err.message); spa_log_error(backend->log, "Failed to parse org.ofono.HandsfreeAudioManager.CardRemoved: %s", err.message);
goto fail; goto fail;
} }
@ -723,7 +725,7 @@ static int add_filters(struct impl *backend)
dbus_error_init(&err); dbus_error_init(&err);
if (!dbus_connection_add_filter(backend->conn, ofono_filter_cb, backend, NULL)) { if (!dbus_connection_add_filter(backend->conn, ofono_filter_cb, backend, NULL)) {
spa_log_error(backend->log, NAME": failed to add filter function"); spa_log_error(backend->log, "failed to add filter function");
goto fail; goto fail;
} }
@ -823,6 +825,8 @@ struct spa_bt_backend *backend_ofono_new(struct spa_bt_monitor *monitor,
else else
backend->msbc_supported = false; backend->msbc_supported = false;
spa_log_topic_init(backend->log, &log_topic);
if (!dbus_connection_register_object_path(backend->conn, if (!dbus_connection_register_object_path(backend->conn,
OFONO_AUDIO_CLIENT, OFONO_AUDIO_CLIENT,
&vtable_profile, backend)) { &vtable_profile, backend)) {

96
spa/plugins/bluez5/bluez5-dbus.c
View file

@ -53,7 +53,9 @@
#include "codec-loader.h" #include "codec-loader.h"
#include "defs.h" #include "defs.h"
#define NAME "bluez5-monitor" static struct spa_log_topic log_topic = SPA_LOG_TOPIC(0, "spa.bluez5");
#undef SPA_LOG_TOPIC_DEFAULT
#define SPA_LOG_TOPIC_DEFAULT &log_topic
enum backend_selection { enum backend_selection {
BACKEND_NONE = -2, BACKEND_NONE = -2,
@ -206,7 +208,7 @@ static void battery_remove(struct spa_bt_device *device) {
if (!device->adapter->has_battery_provider || !device->has_battery) if (!device->adapter->has_battery_provider || !device->has_battery)
return; return;
spa_log_debug(device->monitor->log, NAME": Removing virtual battery: %s", device->battery_path); spa_log_debug(device->monitor->log, "Removing virtual battery: %s", device->battery_path);
m = dbus_message_new_signal(PIPEWIRE_BATTERY_PROVIDER, m = dbus_message_new_signal(PIPEWIRE_BATTERY_PROVIDER,
DBUS_INTERFACE_OBJECT_MANAGER, DBUS_INTERFACE_OBJECT_MANAGER,
@ -224,7 +226,7 @@ static void battery_remove(struct spa_bt_device *device) {
dbus_message_iter_close_container(&i, &entry); dbus_message_iter_close_container(&i, &entry);
if (!dbus_connection_send(device->monitor->conn, m, NULL)) { if (!dbus_connection_send(device->monitor->conn, m, NULL)) {
spa_log_error(device->monitor->log, NAME": sending " DBUS_SIGNAL_INTERFACES_REMOVED " failed"); spa_log_error(device->monitor->log, "sending " DBUS_SIGNAL_INTERFACES_REMOVED " failed");
} }
dbus_message_unref(m); dbus_message_unref(m);
@ -265,7 +267,7 @@ static void battery_write_properties(DBusMessageIter *iter, struct spa_bt_device
// Send current percentage to BlueZ // Send current percentage to BlueZ
static void battery_update(struct spa_bt_device *device) static void battery_update(struct spa_bt_device *device)
{ {
spa_log_debug(device->monitor->log, NAME": updating battery: %s", device->battery_path); spa_log_debug(device->monitor->log, "updating battery: %s", device->battery_path);
DBusMessage *msg; DBusMessage *msg;
DBusMessageIter iter; DBusMessageIter iter;
@ -282,7 +284,7 @@ static void battery_update(struct spa_bt_device *device)
battery_write_properties(&iter, device); battery_write_properties(&iter, device);
if (!dbus_connection_send(device->monitor->conn, msg, NULL)) if (!dbus_connection_send(device->monitor->conn, msg, NULL))
spa_log_error(device->monitor->log, NAME": Error updating battery"); spa_log_error(device->monitor->log, "Error updating battery");
dbus_message_unref(msg); dbus_message_unref(msg);
} }
@ -310,13 +312,13 @@ static void battery_create(struct spa_bt_device *device) {
dbus_message_iter_close_container(&iter, &dict); dbus_message_iter_close_container(&iter, &dict);
if (!dbus_connection_send(device->monitor->conn, msg, NULL)) { if (!dbus_connection_send(device->monitor->conn, msg, NULL)) {
spa_log_error(device->monitor->log, NAME": Failed to create virtual battery for %s", device->address); spa_log_error(device->monitor->log, "Failed to create virtual battery for %s", device->address);
return; return;
} }
dbus_message_unref(msg); dbus_message_unref(msg);
spa_log_debug(device->monitor->log, NAME": Created virtual battery for %s", device->address); spa_log_debug(device->monitor->log, "Created virtual battery for %s", device->address);
device->has_battery = true; device->has_battery = true;
} }
@ -332,14 +334,14 @@ static void on_battery_provider_registered(DBusPendingCall *pending_call,
device->battery_pending_call = NULL; device->battery_pending_call = NULL;
if (dbus_message_get_type(reply) == DBUS_MESSAGE_TYPE_ERROR) { if (dbus_message_get_type(reply) == DBUS_MESSAGE_TYPE_ERROR) {
spa_log_error(device->monitor->log, NAME": Failed to register battery provider. Error: %s", dbus_message_get_error_name(reply)); spa_log_error(device->monitor->log, "Failed to register battery provider. Error: %s", dbus_message_get_error_name(reply));
spa_log_error(device->monitor->log, NAME": BlueZ Battery Provider is not available, won't retry to register it. Make sure you are running BlueZ 5.56+ with experimental features to use Battery Provider."); spa_log_error(device->monitor->log, "BlueZ Battery Provider is not available, won't retry to register it. Make sure you are running BlueZ 5.56+ with experimental features to use Battery Provider.");
device->adapter->battery_provider_unavailable = true; device->adapter->battery_provider_unavailable = true;
dbus_message_unref(reply); dbus_message_unref(reply);
return; return;
} }
spa_log_debug(device->monitor->log, NAME": Registered Battery Provider"); spa_log_debug(device->monitor->log, "Registered Battery Provider");
device->adapter->has_battery_provider = true; device->adapter->has_battery_provider = true;
@ -356,7 +358,7 @@ static void register_battery_provider(struct spa_bt_device *device)
DBusMessageIter message_iter; DBusMessageIter message_iter;
if (device->battery_pending_call) { if (device->battery_pending_call) {
spa_log_debug(device->monitor->log, NAME": Already registering battery provider"); spa_log_debug(device->monitor->log, "Already registering battery provider");
return; return;
} }
@ -366,7 +368,7 @@ static void register_battery_provider(struct spa_bt_device *device)
"RegisterBatteryProvider"); "RegisterBatteryProvider");
if (!method_call) { if (!method_call) {
spa_log_error(device->monitor->log, NAME": Failed to register battery provider"); spa_log_error(device->monitor->log, "Failed to register battery provider");
return; return;
} }
@ -378,14 +380,14 @@ static void register_battery_provider(struct spa_bt_device *device)
if (!dbus_connection_send_with_reply(device->monitor->conn, method_call, &device->battery_pending_call, if (!dbus_connection_send_with_reply(device->monitor->conn, method_call, &device->battery_pending_call,
DBUS_TIMEOUT_USE_DEFAULT)) { DBUS_TIMEOUT_USE_DEFAULT)) {
dbus_message_unref(method_call); dbus_message_unref(method_call);
spa_log_error(device->monitor->log, NAME": Failed to register battery provider"); spa_log_error(device->monitor->log, "Failed to register battery provider");
return; return;
} }
dbus_message_unref(method_call); dbus_message_unref(method_call);
if (!device->battery_pending_call) { if (!device->battery_pending_call) {
spa_log_error(device->monitor->log, NAME": Failed to register battery provider"); spa_log_error(device->monitor->log, "Failed to register battery provider");
return; return;
} }
@ -1251,7 +1253,7 @@ static void device_update_hw_volume_profiles(struct spa_bt_device *device)
if (!(bt_features & SPA_BT_FEATURE_HW_VOLUME)) if (!(bt_features & SPA_BT_FEATURE_HW_VOLUME))
device->hw_volume_profiles = 0; device->hw_volume_profiles = 0;
spa_log_debug(monitor->log, NAME ": hw-volume-profiles:%08x", (int)device->hw_volume_profiles); spa_log_debug(monitor->log, "hw-volume-profiles:%08x", (int)device->hw_volume_profiles);
} }
static int device_update_props(struct spa_bt_device *device, static int device_update_props(struct spa_bt_device *device,
@ -2138,7 +2140,7 @@ static int transport_set_property_volume(struct spa_bt_transport *transport, uin
dbus_message_unref(m); dbus_message_unref(m);
if (r == NULL) { if (r == NULL) {
spa_log_error(monitor->log, NAME": set volume %u failed for transport %s (%s)", spa_log_error(monitor->log, "set volume %u failed for transport %s (%s)",
value, transport->path, err.message); value, transport->path, err.message);
dbus_error_free(&err); dbus_error_free(&err);
return -EIO; return -EIO;
@ -2248,7 +2250,7 @@ static int transport_release(void *data)
DBusError err; DBusError err;
bool is_idle = (transport->state == SPA_BT_TRANSPORT_STATE_IDLE); bool is_idle = (transport->state == SPA_BT_TRANSPORT_STATE_IDLE);
spa_log_debug(monitor->log, NAME": transport %p: Release %s", spa_log_debug(monitor->log, "transport %p: Release %s",
transport, transport->path); transport, transport->path);
close(transport->fd); close(transport->fd);
@ -2356,25 +2358,25 @@ static bool a2dp_codec_switch_process_current(struct spa_bt_a2dp_codec_switch *s
codec = *sw->codec_iter; codec = *sw->codec_iter;
spa_log_debug(sw->device->monitor->log, NAME": a2dp codec switch %p: consider codec %s for remote endpoint %s", spa_log_debug(sw->device->monitor->log, "a2dp codec switch %p: consider codec %s for remote endpoint %s",
sw, (*sw->codec_iter)->name, *sw->path_iter); sw, (*sw->codec_iter)->name, *sw->path_iter);
ep = device_remote_endpoint_find(sw->device, *sw->path_iter); ep = device_remote_endpoint_find(sw->device, *sw->path_iter);
if (ep == NULL || ep->capabilities == NULL || ep->uuid == NULL) { if (ep == NULL || ep->capabilities == NULL || ep->uuid == NULL) {
spa_log_debug(sw->device->monitor->log, NAME": a2dp codec switch %p: endpoint %s not valid, try next", spa_log_debug(sw->device->monitor->log, "a2dp codec switch %p: endpoint %s not valid, try next",
sw, *sw->path_iter); sw, *sw->path_iter);
goto next; goto next;
} }
/* Setup and check compatible configuration */ /* Setup and check compatible configuration */
if (ep->codec != codec->codec_id) { if (ep->codec != codec->codec_id) {
spa_log_debug(sw->device->monitor->log, NAME": a2dp codec switch %p: different codec, try next", sw); spa_log_debug(sw->device->monitor->log, "a2dp codec switch %p: different codec, try next", sw);
goto next; goto next;
} }
if (!(sw->profile & spa_bt_profile_from_uuid(ep->uuid))) { if (!(sw->profile & spa_bt_profile_from_uuid(ep->uuid))) {
spa_log_debug(sw->device->monitor->log, NAME": a2dp codec switch %p: wrong uuid (%s) for profile, try next", spa_log_debug(sw->device->monitor->log, "a2dp codec switch %p: wrong uuid (%s) for profile, try next",
sw, ep->uuid); sw, ep->uuid);
goto next; goto next;
} }
@ -2384,13 +2386,13 @@ static bool a2dp_codec_switch_process_current(struct spa_bt_a2dp_codec_switch *s
} else if (sw->profile & SPA_BT_PROFILE_A2DP_SOURCE) { } else if (sw->profile & SPA_BT_PROFILE_A2DP_SOURCE) {
local_endpoint_base = A2DP_SINK_ENDPOINT; local_endpoint_base = A2DP_SINK_ENDPOINT;
} else { } else {
spa_log_debug(sw->device->monitor->log, NAME": a2dp codec switch %p: bad profile (%d), try next", spa_log_debug(sw->device->monitor->log, "a2dp codec switch %p: bad profile (%d), try next",
sw, sw->profile); sw, sw->profile);
goto next; goto next;
} }
if (a2dp_codec_to_endpoint(codec, local_endpoint_base, &local_endpoint) < 0) { if (a2dp_codec_to_endpoint(codec, local_endpoint_base, &local_endpoint) < 0) {
spa_log_debug(sw->device->monitor->log, NAME": a2dp codec switch %p: no endpoint for codec %s, try next", spa_log_debug(sw->device->monitor->log, "a2dp codec switch %p: no endpoint for codec %s, try next",
sw, codec->name); sw, codec->name);
goto next; goto next;
} }
@ -2399,24 +2401,24 @@ static bool a2dp_codec_switch_process_current(struct spa_bt_a2dp_codec_switch *s
&sw->device->monitor->default_audio_info, &sw->device->monitor->default_audio_info,
sw->device->settings, config); sw->device->settings, config);
if (res < 0) { if (res < 0) {
spa_log_debug(sw->device->monitor->log, NAME": a2dp codec switch %p: incompatible capabilities (%d), try next", spa_log_debug(sw->device->monitor->log, "a2dp codec switch %p: incompatible capabilities (%d), try next",
sw, res); sw, res);
goto next; goto next;
} }
config_size = res; config_size = res;
spa_log_debug(sw->device->monitor->log, NAME": a2dp codec switch %p: configuration %d", sw, config_size); spa_log_debug(sw->device->monitor->log, "a2dp codec switch %p: configuration %d", sw, config_size);
for (i = 0; i < config_size; i++) for (i = 0; i < config_size; i++)
spa_log_debug(sw->device->monitor->log, NAME": a2dp codec switch %p: %d: %02x", sw, i, config[i]); spa_log_debug(sw->device->monitor->log, "a2dp codec switch %p: %d: %02x", sw, i, config[i]);
/* org.bluez.MediaEndpoint1.SetConfiguration on remote endpoint */ /* org.bluez.MediaEndpoint1.SetConfiguration on remote endpoint */
m = dbus_message_new_method_call(BLUEZ_SERVICE, ep->path, BLUEZ_MEDIA_ENDPOINT_INTERFACE, "SetConfiguration"); m = dbus_message_new_method_call(BLUEZ_SERVICE, ep->path, BLUEZ_MEDIA_ENDPOINT_INTERFACE, "SetConfiguration");
if (m == NULL) { if (m == NULL) {
spa_log_debug(sw->device->monitor->log, NAME": a2dp codec switch %p: dbus allocation failure, try next", sw); spa_log_debug(sw->device->monitor->log, "a2dp codec switch %p: dbus allocation failure, try next", sw);
goto next; goto next;
} }
spa_log_info(sw->device->monitor->log, NAME": a2dp codec switch %p: trying codec %s for endpoint %s, local endpoint %s", spa_log_info(sw->device->monitor->log, "a2dp codec switch %p: trying codec %s for endpoint %s, local endpoint %s",
sw, codec->name, ep->path, local_endpoint); sw, codec->name, ep->path, local_endpoint);
dbus_message_iter_init_append(m, &iter); dbus_message_iter_init_append(m, &iter);
@ -2430,7 +2432,7 @@ static bool a2dp_codec_switch_process_current(struct spa_bt_a2dp_codec_switch *s
dbus_ret = dbus_connection_send_with_reply(sw->device->monitor->conn, m, &sw->pending, -1); dbus_ret = dbus_connection_send_with_reply(sw->device->monitor->conn, m, &sw->pending, -1);
if (!dbus_ret || sw->pending == NULL) { if (!dbus_ret || sw->pending == NULL) {
spa_log_error(sw->device->monitor->log, NAME": a2dp codec switch %p: dbus call failure, try next", sw); spa_log_error(sw->device->monitor->log, "a2dp codec switch %p: dbus call failure, try next", sw);
dbus_message_unref(m); dbus_message_unref(m);
goto next; goto next;
} }
@ -2439,7 +2441,7 @@ static bool a2dp_codec_switch_process_current(struct spa_bt_a2dp_codec_switch *s
dbus_message_unref(m); dbus_message_unref(m);
if (!dbus_ret) { if (!dbus_ret) {
spa_log_error(sw->device->monitor->log, NAME": a2dp codec switch %p: dbus set notify failure", sw); spa_log_error(sw->device->monitor->log, "a2dp codec switch %p: dbus set notify failure", sw);
goto next; goto next;
} }
@ -2469,7 +2471,7 @@ static void a2dp_codec_switch_process(struct spa_bt_a2dp_codec_switch *sw)
}; };
/* Didn't find any suitable endpoint. Report failure. */ /* Didn't find any suitable endpoint. Report failure. */
spa_log_info(sw->device->monitor->log, NAME": a2dp codec switch %p: failed to get an endpoint", sw); spa_log_info(sw->device->monitor->log, "a2dp codec switch %p: failed to get an endpoint", sw);
spa_bt_device_emit_codec_switched(sw->device, -ENODEV); spa_bt_device_emit_codec_switched(sw->device, -ENODEV);
spa_bt_device_check_profiles(sw->device, false); spa_bt_device_check_profiles(sw->device, false);
a2dp_codec_switch_free(sw); a2dp_codec_switch_free(sw);
@ -2494,7 +2496,7 @@ static void a2dp_codec_switch_reply(DBusPendingCall *pending, void *user_data)
struct spa_bt_a2dp_codec_switch *t; struct spa_bt_a2dp_codec_switch *t;
/* This codec switch has been canceled. Switch to the newest one. */ /* This codec switch has been canceled. Switch to the newest one. */
spa_log_debug(sw->device->monitor->log, NAME": a2dp codec switch %p: canceled, go to new switch", sw); spa_log_debug(sw->device->monitor->log, "a2dp codec switch %p: canceled, go to new switch", sw);
if (r != NULL) if (r != NULL)
dbus_message_unref(r); dbus_message_unref(r);
@ -2510,14 +2512,14 @@ static void a2dp_codec_switch_reply(DBusPendingCall *pending, void *user_data)
if (r == NULL) { if (r == NULL) {
spa_log_error(sw->device->monitor->log, spa_log_error(sw->device->monitor->log,
NAME": a2dp codec switch %p: empty reply from dbus, trying next", "a2dp codec switch %p: empty reply from dbus, trying next",
sw); sw);
goto next; goto next;
} }
if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) { if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) {
spa_log_debug(sw->device->monitor->log, spa_log_debug(sw->device->monitor->log,
NAME": a2dp codec switch %p: failed (%s), trying next", "a2dp codec switch %p: failed (%s), trying next",
sw, dbus_message_get_error_name(r)); sw, dbus_message_get_error_name(r));
dbus_message_unref(r); dbus_message_unref(r);
goto next; goto next;
@ -2526,7 +2528,7 @@ static void a2dp_codec_switch_reply(DBusPendingCall *pending, void *user_data)
dbus_message_unref(r); dbus_message_unref(r);
/* Success */ /* Success */
spa_log_info(sw->device->monitor->log, NAME": a2dp codec switch %p: success", sw); spa_log_info(sw->device->monitor->log, "a2dp codec switch %p: success", sw);
spa_bt_device_emit_codec_switched(sw->device, 0); spa_bt_device_emit_codec_switched(sw->device, 0);
spa_bt_device_check_profiles(sw->device, false); spa_bt_device_check_profiles(sw->device, false);
a2dp_codec_switch_free(sw); a2dp_codec_switch_free(sw);
@ -2659,7 +2661,7 @@ int spa_bt_device_ensure_a2dp_codec(struct spa_bt_device *device, const struct a
* request. * request.
*/ */
spa_log_debug(sw->device->monitor->log, spa_log_debug(sw->device->monitor->log,
NAME": a2dp codec switch: already in progress, canceling previous"); "a2dp codec switch: already in progress, canceling previous");
spa_list_prepend(&device->codec_switch_list, &sw->device_link); spa_list_prepend(&device->codec_switch_list, &sw->device_link);
} else { } else {
@ -3351,7 +3353,7 @@ static void reselect_backend(struct spa_bt_monitor *monitor)
struct spa_bt_backend *backend; struct spa_bt_backend *backend;
size_t i; size_t i;
spa_log_debug(monitor->log, NAME": re-selecting HFP/HSP backend"); spa_log_debug(monitor->log, "re-selecting HFP/HSP backend");
if (monitor->backend_selection == BACKEND_NONE) { if (monitor->backend_selection == BACKEND_NONE) {
spa_bt_backend_unregister_profiles(monitor->backend); spa_bt_backend_unregister_profiles(monitor->backend);
@ -3588,7 +3590,7 @@ static DBusHandlerResult filter_cb(DBusConnection *bus, DBusMessage *m, void *us
DBUS_TYPE_STRING, &old_owner, DBUS_TYPE_STRING, &old_owner,
DBUS_TYPE_STRING, &new_owner, DBUS_TYPE_STRING, &new_owner,
DBUS_TYPE_INVALID)) { DBUS_TYPE_INVALID)) {
spa_log_error(monitor->log, NAME": Failed to parse org.freedesktop.DBus.NameOwnerChanged: %s", err.message); spa_log_error(monitor->log, "Failed to parse org.freedesktop.DBus.NameOwnerChanged: %s", err.message);
goto fail; goto fail;
} }
@ -3644,7 +3646,7 @@ static DBusHandlerResult filter_cb(DBusConnection *bus, DBusMessage *m, void *us
goto finish; goto finish;
if (!dbus_message_iter_init(m, &it) || !spa_streq(dbus_message_get_signature(m), "oa{sa{sv}}")) { if (!dbus_message_iter_init(m, &it) || !spa_streq(dbus_message_get_signature(m), "oa{sa{sv}}")) {
spa_log_error(monitor->log, NAME": Invalid signature found in InterfacesAdded"); spa_log_error(monitor->log, "Invalid signature found in InterfacesAdded");
goto finish; goto finish;
} }
@ -3658,7 +3660,7 @@ static DBusHandlerResult filter_cb(DBusConnection *bus, DBusMessage *m, void *us
goto finish; goto finish;
if (!dbus_message_iter_init(m, &it) || !spa_streq(dbus_message_get_signature(m), "oas")) { if (!dbus_message_iter_init(m, &it) || !spa_streq(dbus_message_get_signature(m), "oas")) {
spa_log_error(monitor->log, NAME": Invalid signature found in InterfacesRemoved"); spa_log_error(monitor->log, "Invalid signature found in InterfacesRemoved");
goto finish; goto finish;
} }
@ -3974,7 +3976,7 @@ static int parse_codec_array(struct spa_bt_monitor *this, const struct spa_dict
spa_json_init(&it, str, strlen(str)); spa_json_init(&it, str, strlen(str));
if (spa_json_enter_array(&it, &it_array) <= 0) { if (spa_json_enter_array(&it, &it_array) <= 0) {
spa_log_error(this->log, NAME": property bluez5.codecs '%s' is not an array", str); spa_log_error(this->log, "property bluez5.codecs '%s' is not an array", str);
goto fallback; goto fallback;
} }
@ -3992,7 +3994,7 @@ static int parse_codec_array(struct spa_bt_monitor *this, const struct spa_dict
if (spa_dict_lookup_item(&this->enabled_codecs, codec->name) != NULL) if (spa_dict_lookup_item(&this->enabled_codecs, codec->name) != NULL)
continue; continue;
spa_log_debug(this->log, NAME": enabling codec %s", codec->name); spa_log_debug(this->log, "enabling codec %s", codec->name);
spa_assert(this->enabled_codecs.n_items < num_codecs); spa_assert(this->enabled_codecs.n_items < num_codecs);
@ -4009,14 +4011,14 @@ static int parse_codec_array(struct spa_bt_monitor *this, const struct spa_dict
for (i = 0; a2dp_codecs[i]; ++i) { for (i = 0; a2dp_codecs[i]; ++i) {
const struct a2dp_codec *codec = a2dp_codecs[i]; const struct a2dp_codec *codec = a2dp_codecs[i];
if (!is_a2dp_codec_enabled(this, codec)) if (!is_a2dp_codec_enabled(this, codec))
spa_log_debug(this->log, NAME": disabling codec %s", codec->name); spa_log_debug(this->log, "disabling codec %s", codec->name);
} }
return 0; return 0;
fallback: fallback:
for (i = 0; a2dp_codecs[i]; ++i) { for (i = 0; a2dp_codecs[i]; ++i) {
const struct a2dp_codec *codec = a2dp_codecs[i]; const struct a2dp_codec *codec = a2dp_codecs[i];
spa_log_debug(this->log, NAME": enabling codec %s", codec->name); spa_log_debug(this->log, "enabling codec %s", codec->name);
codecs[i].key = codec->name; codecs[i].key = codec->name;
codecs[i].value = "true"; codecs[i].value = "true";
} }
@ -4049,6 +4051,8 @@ impl_init(const struct spa_handle_factory *factory,
this->main_system = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_System); this->main_system = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_System);
this->plugin_loader = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_PluginLoader); this->plugin_loader = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_PluginLoader);
spa_log_topic_init(this->log, &log_topic);
if (this->dbus == NULL) { if (this->dbus == NULL) {
spa_log_error(this->log, "a dbus is needed"); spa_log_error(this->log, "a dbus is needed");
return -EINVAL; return -EINVAL;
@ -4066,14 +4070,14 @@ impl_init(const struct spa_handle_factory *factory,
this->a2dp_codecs = load_a2dp_codecs(this->plugin_loader, this->log); this->a2dp_codecs = load_a2dp_codecs(this->plugin_loader, this->log);
if (this->a2dp_codecs == NULL) { if (this->a2dp_codecs == NULL) {
spa_log_error(this->log, NAME ": failed to load required A2DP codec plugins"); spa_log_error(this->log, "failed to load required A2DP codec plugins");
res = -EIO; res = -EIO;
goto fail; goto fail;
} }
this->quirks = spa_bt_quirks_create(info, this->log); this->quirks = spa_bt_quirks_create(info, this->log);
if (this->quirks == NULL) { if (this->quirks == NULL) {
spa_log_error(this->log, NAME ": failed to parse quirk table"); spa_log_error(this->log, "failed to parse quirk table");
res = -EINVAL; res = -EINVAL;
goto fail; goto fail;
} }

34
spa/plugins/bluez5/bluez5-device.c
View file

@ -53,7 +53,9 @@
#include "defs.h" #include "defs.h"
#include "a2dp-codecs.h" #include "a2dp-codecs.h"
#define NAME "bluez5-device" static struct spa_log_topic log_topic = SPA_LOG_TOPIC(0, "spa.bluez5.device");
#undef SPA_LOG_TOPIC_DEFAULT
#define SPA_LOG_TOPIC_DEFAULT &log_topic
#define MAX_DEVICES 64 #define MAX_DEVICES 64
@ -579,7 +581,7 @@ static const struct spa_bt_transport_events dynamic_node_transport_events = {
static void emit_dynamic_node(struct dynamic_node *this, struct impl *impl, static void emit_dynamic_node(struct dynamic_node *this, struct impl *impl,
struct spa_bt_transport *t, uint32_t id, const char *factory_name, bool a2dp_duplex) struct spa_bt_transport *t, uint32_t id, const char *factory_name, bool a2dp_duplex)
{ {
spa_log_debug(impl->log, NAME": dynamic node, transport: %p->%p id: %08x->%08x", spa_log_debug(impl->log, "dynamic node, transport: %p->%p id: %08x->%08x",
this->transport, t, this->id, id); this->transport, t, this->id, id);
if (this->transport) { if (this->transport) {
@ -754,7 +756,7 @@ static bool validate_profile(struct impl *this, uint32_t profile,
static int set_profile(struct impl *this, uint32_t profile, enum spa_bluetooth_audio_codec codec) static int set_profile(struct impl *this, uint32_t profile, enum spa_bluetooth_audio_codec codec)
{ {
if (!validate_profile(this, profile, codec)) { if (!validate_profile(this, profile, codec)) {
spa_log_warn(this->log, NAME ": trying to set invalid profile %d, codec %d, %08x %08x", spa_log_warn(this->log, "trying to set invalid profile %d, codec %d, %08x %08x",
profile, codec, profile, codec,
this->bt_dev->profiles, this->bt_dev->connected_profiles); this->bt_dev->profiles, this->bt_dev->connected_profiles);
return -EINVAL; return -EINVAL;
@ -789,7 +791,7 @@ static int set_profile(struct impl *this, uint32_t profile, enum spa_bluetooth_a
ret = spa_bt_device_ensure_a2dp_codec(this->bt_dev, codecs); ret = spa_bt_device_ensure_a2dp_codec(this->bt_dev, codecs);
if (ret < 0) { if (ret < 0) {
if (ret != -ENOTSUP) if (ret != -ENOTSUP)
spa_log_error(this->log, NAME": failed to switch codec (%d), setting basic profile", ret); spa_log_error(this->log, "failed to switch codec (%d), setting basic profile", ret);
} else { } else {
return 0; return 0;
} }
@ -801,7 +803,7 @@ static int set_profile(struct impl *this, uint32_t profile, enum spa_bluetooth_a
ret = spa_bt_device_ensure_hfp_codec(this->bt_dev, get_hfp_codec(codec)); ret = spa_bt_device_ensure_hfp_codec(this->bt_dev, get_hfp_codec(codec));
if (ret < 0) { if (ret < 0) {
if (ret != -ENOTSUP) if (ret != -ENOTSUP)
spa_log_error(this->log, NAME": failed to switch codec (%d), setting basic profile", ret); spa_log_error(this->log, "failed to switch codec (%d), setting basic profile", ret);
} else { } else {
return 0; return 0;
} }
@ -826,13 +828,13 @@ static void codec_switched(void *userdata, int status)
{ {
struct impl *this = userdata; struct impl *this = userdata;
spa_log_debug(this->log, NAME": codec switched (status %d)", status); spa_log_debug(this->log, "codec switched (status %d)", status);
this->switching_codec = false; this->switching_codec = false;
if (status < 0) { if (status < 0) {
/* Failed to switch: return to a fallback profile */ /* Failed to switch: return to a fallback profile */
spa_log_error(this->log, NAME": failed to switch codec (%d), setting fallback profile", status); spa_log_error(this->log, "failed to switch codec (%d), setting fallback profile", status);
if (this->profile == DEVICE_PROFILE_A2DP && this->props.codec != 0) { if (this->profile == DEVICE_PROFILE_A2DP && this->props.codec != 0) {
this->props.codec = 0; this->props.codec = 0;
} else if (this->profile == DEVICE_PROFILE_HSP_HFP && this->props.codec != 0) { } else if (this->profile == DEVICE_PROFILE_HSP_HFP && this->props.codec != 0) {
@ -865,7 +867,7 @@ static void profiles_changed(void *userdata, uint32_t prev_profiles, uint32_t pr
connected_change = (this->bt_dev->connected_profiles ^ prev_connected_profiles); connected_change = (this->bt_dev->connected_profiles ^ prev_connected_profiles);
/* Profiles changed. We have to re-emit device information. */ /* Profiles changed. We have to re-emit device information. */
spa_log_info(this->log, NAME": profiles changed to %08x %08x (prev %08x %08x, change %08x)" spa_log_info(this->log, "profiles changed to %08x %08x (prev %08x %08x, change %08x)"
" switching_codec:%d", " switching_codec:%d",
this->bt_dev->profiles, this->bt_dev->connected_profiles, this->bt_dev->profiles, this->bt_dev->connected_profiles,
prev_profiles, prev_connected_profiles, connected_change, prev_profiles, prev_connected_profiles, connected_change,
@ -888,7 +890,7 @@ static void profiles_changed(void *userdata, uint32_t prev_profiles, uint32_t pr
case DEVICE_PROFILE_AG: case DEVICE_PROFILE_AG:
nodes_changed = (connected_change & (SPA_BT_PROFILE_HEADSET_AUDIO_GATEWAY | nodes_changed = (connected_change & (SPA_BT_PROFILE_HEADSET_AUDIO_GATEWAY |
SPA_BT_PROFILE_A2DP_SOURCE)); SPA_BT_PROFILE_A2DP_SOURCE));
spa_log_debug(this->log, NAME": profiles changed: AG nodes changed: %d", spa_log_debug(this->log, "profiles changed: AG nodes changed: %d",
nodes_changed); nodes_changed);
break; break;
case DEVICE_PROFILE_A2DP: case DEVICE_PROFILE_A2DP:
@ -896,14 +898,14 @@ static void profiles_changed(void *userdata, uint32_t prev_profiles, uint32_t pr
this->props.codec = 0; this->props.codec = 0;
nodes_changed = (connected_change & (SPA_BT_PROFILE_A2DP_SINK | nodes_changed = (connected_change & (SPA_BT_PROFILE_A2DP_SINK |
SPA_BT_PROFILE_A2DP_SOURCE)); SPA_BT_PROFILE_A2DP_SOURCE));
spa_log_debug(this->log, NAME": profiles changed: A2DP nodes changed: %d", spa_log_debug(this->log, "profiles changed: A2DP nodes changed: %d",
nodes_changed); nodes_changed);
break; break;
case DEVICE_PROFILE_HSP_HFP: case DEVICE_PROFILE_HSP_HFP:
if (spa_bt_device_supports_hfp_codec(this->bt_dev, get_hfp_codec(this->props.codec)) != 1) if (spa_bt_device_supports_hfp_codec(this->bt_dev, get_hfp_codec(this->props.codec)) != 1)
this->props.codec = 0; this->props.codec = 0;
nodes_changed = (connected_change & SPA_BT_PROFILE_HEADSET_HEAD_UNIT); nodes_changed = (connected_change & SPA_BT_PROFILE_HEADSET_HEAD_UNIT);
spa_log_debug(this->log, NAME": profiles changed: HSP/HFP nodes changed: %d", spa_log_debug(this->log, "profiles changed: HSP/HFP nodes changed: %d",
nodes_changed); nodes_changed);
break; break;
} }
@ -1074,7 +1076,7 @@ static bool set_initial_hsp_hfp_profile(struct impl *this)
DEVICE_PROFILE_AG : DEVICE_PROFILE_HSP_HFP; DEVICE_PROFILE_AG : DEVICE_PROFILE_HSP_HFP;
this->props.codec = get_hfp_codec_id(t->codec); this->props.codec = get_hfp_codec_id(t->codec);
spa_log_debug(this->log, NAME": initial profile HSP/HFP profile:%d codec:%d", spa_log_debug(this->log, "initial profile HSP/HFP profile:%d codec:%d",
this->profile, this->props.codec); this->profile, this->props.codec);
return true; return true;
} }
@ -1111,7 +1113,7 @@ static void set_initial_profile(struct impl *this)
this->profile = (i == SPA_BT_PROFILE_A2DP_SOURCE) ? this->profile = (i == SPA_BT_PROFILE_A2DP_SOURCE) ?
DEVICE_PROFILE_AG : DEVICE_PROFILE_A2DP; DEVICE_PROFILE_AG : DEVICE_PROFILE_A2DP;
this->props.codec = t->a2dp_codec->id; this->props.codec = t->a2dp_codec->id;
spa_log_debug(this->log, NAME": initial profile A2DP profile:%d codec:%d", spa_log_debug(this->log, "initial profile A2DP profile:%d codec:%d",
this->profile, this->props.codec); this->profile, this->props.codec);
return; return;
} }
@ -1120,7 +1122,7 @@ static void set_initial_profile(struct impl *this)
if (set_initial_hsp_hfp_profile(this)) if (set_initial_hsp_hfp_profile(this))
return; return;
spa_log_debug(this->log, NAME": initial profile off"); spa_log_debug(this->log, "initial profile off");
this->profile = DEVICE_PROFILE_OFF; this->profile = DEVICE_PROFILE_OFF;
this->props.codec = 0; this->props.codec = 0;
@ -1859,7 +1861,7 @@ static int impl_set_param(void *object,
if (profile == SPA_ID_INVALID) if (profile == SPA_ID_INVALID)
return -EINVAL; return -EINVAL;
spa_log_debug(this->log, NAME": setting profile %d codec:%d", profile, codec); spa_log_debug(this->log, "setting profile %d codec:%d", profile, codec);
return set_profile(this, profile, codec); return set_profile(this, profile, codec);
} }
case SPA_PARAM_Route: case SPA_PARAM_Route:
@ -2033,6 +2035,8 @@ impl_init(const struct spa_handle_factory *factory,
this->log = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_Log); this->log = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_Log);
_i18n = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_I18N); _i18n = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_I18N);
spa_log_topic_init(this->log, &log_topic);
if (info && (str = spa_dict_lookup(info, SPA_KEY_API_BLUEZ5_DEVICE))) if (info && (str = spa_dict_lookup(info, SPA_KEY_API_BLUEZ5_DEVICE)))
sscanf(str, "pointer:%p", &this->bt_dev); sscanf(str, "pointer:%p", &this->bt_dev);

22
spa/plugins/bluez5/codec-loader.c
View file

@ -26,8 +26,6 @@
#include <spa/utils/string.h> #include <spa/utils/string.h>
#define NAME "bluez5-a2dp-codecs"
#include "defs.h" #include "defs.h"
#include "codec-loader.h" #include "codec-loader.h"
@ -37,6 +35,10 @@
#define MAX_CODECS 0x3E #define MAX_CODECS 0x3E
#define MAX_HANDLES MAX_CODECS #define MAX_HANDLES MAX_CODECS
static struct spa_log_topic log_topic = SPA_LOG_TOPIC(0, "spa.bluez5.codecs");
#undef SPA_LOG_TOPIC_DEFAULT
#define SPA_LOG_TOPIC_DEFAULT &log_topic
struct impl { struct impl {
const struct a2dp_codec *codecs[MAX_CODECS + 1]; const struct a2dp_codec *codecs[MAX_CODECS + 1];
struct spa_handle *handles[MAX_HANDLES]; struct spa_handle *handles[MAX_HANDLES];
@ -94,14 +96,14 @@ static int load_a2dp_codecs_from(struct impl *impl, const char *factory_name, co
handle = spa_plugin_loader_load(impl->loader, factory_name, &info); handle = spa_plugin_loader_load(impl->loader, factory_name, &info);
if (handle == NULL) { if (handle == NULL) {
spa_log_info(impl->log, NAME ": Bluetooth codec plugin %s not available", factory_name); spa_log_info(impl->log, "Bluetooth codec plugin %s not available", factory_name);
return -ENOENT; return -ENOENT;
} }
spa_log_debug(impl->log, NAME ": loading codecs from %s", factory_name); spa_log_debug(impl->log, "loading codecs from %s", factory_name);
if ((res = spa_handle_get_interface(handle, SPA_TYPE_INTERFACE_Bluez5CodecA2DP, &iface)) < 0) { if ((res = spa_handle_get_interface(handle, SPA_TYPE_INTERFACE_Bluez5CodecA2DP, &iface)) < 0) {
spa_log_info(impl->log, NAME ": Bluetooth codec plugin %s has no codec interface", spa_log_info(impl->log, "Bluetooth codec plugin %s has no codec interface",
factory_name); factory_name);
goto fail; goto fail;
} }
@ -109,7 +111,7 @@ static int load_a2dp_codecs_from(struct impl *impl, const char *factory_name, co
bluez5_codec_a2dp = iface; bluez5_codec_a2dp = iface;
if (bluez5_codec_a2dp->iface.version != SPA_VERSION_BLUEZ5_CODEC_A2DP) { if (bluez5_codec_a2dp->iface.version != SPA_VERSION_BLUEZ5_CODEC_A2DP) {
spa_log_info(impl->log, NAME ": codec plugin %s has incompatible ABI version (%d != %d)", spa_log_info(impl->log, "codec plugin %s has incompatible ABI version (%d != %d)",
factory_name, bluez5_codec_a2dp->iface.version, SPA_VERSION_BLUEZ5_CODEC_A2DP); factory_name, bluez5_codec_a2dp->iface.version, SPA_VERSION_BLUEZ5_CODEC_A2DP);
res = -ENOENT; res = -ENOENT;
goto fail; goto fail;
@ -120,7 +122,7 @@ static int load_a2dp_codecs_from(struct impl *impl, const char *factory_name, co
size_t j; size_t j;
if (impl->n_codecs >= MAX_CODECS) { if (impl->n_codecs >= MAX_CODECS) {
spa_log_error(impl->log, NAME ": too many A2DP codecs"); spa_log_error(impl->log, "too many A2DP codecs");
break; break;
} }
@ -133,7 +135,7 @@ static int load_a2dp_codecs_from(struct impl *impl, const char *factory_name, co
goto next_codec; goto next_codec;
} }
spa_log_debug(impl->log, NAME ": loaded A2DP codec %s from %s", c->name, factory_name); spa_log_debug(impl->log, "loaded A2DP codec %s from %s", c->name, factory_name);
impl->codecs[impl->n_codecs++] = c; impl->codecs[impl->n_codecs++] = c;
++n_codecs; ++n_codecs;
@ -178,6 +180,8 @@ const struct a2dp_codec * const *load_a2dp_codecs(struct spa_plugin_loader *load
impl->loader = loader; impl->loader = loader;
impl->log = log; impl->log = log;
spa_log_topic_init(impl->log, &log_topic);
for (i = 0; i < SPA_N_ELEMENTS(plugins); ++i) for (i = 0; i < SPA_N_ELEMENTS(plugins); ++i)
load_a2dp_codecs_from(impl, plugins[i].factory, plugins[i].lib); load_a2dp_codecs_from(impl, plugins[i].factory, plugins[i].lib);
@ -187,7 +191,7 @@ const struct a2dp_codec * const *load_a2dp_codecs(struct spa_plugin_loader *load
has_sbc = true; has_sbc = true;
if (!has_sbc) { if (!has_sbc) {
spa_log_error(impl->log, NAME ": failed to load A2DP SBC codec from plugins"); spa_log_error(impl->log, "failed to load A2DP SBC codec from plugins");
free_a2dp_codecs(impl->codecs); free_a2dp_codecs(impl->codecs);
errno = ENOENT; errno = ENOENT;
return NULL; return NULL;

18
spa/plugins/bluez5/quirks.c
View file

@ -59,7 +59,9 @@
#include "a2dp-codecs.h" #include "a2dp-codecs.h"
#include "defs.h" #include "defs.h"
#define NAME "bluez5-quirks" static struct spa_log_topic log_topic = SPA_LOG_TOPIC(0, "spa.bluez5.quirks");
#undef SPA_LOG_TOPIC_DEFAULT
#define SPA_LOG_TOPIC_DEFAULT &log_topic
struct spa_bt_quirks { struct spa_bt_quirks {
struct spa_log *log; struct spa_log *log;
@ -204,7 +206,7 @@ static int load_conf(struct spa_bt_quirks *this, const char *path)
struct stat sbuf; struct stat sbuf;
int fd = -1; int fd = -1;
spa_log_debug(this->log, NAME ": loading %s", path); spa_log_debug(this->log, "loading %s", path);
if ((fd = open(path, O_CLOEXEC | O_RDONLY)) < 0) if ((fd = open(path, O_CLOEXEC | O_RDONLY)) < 0)
goto fail; goto fail;
@ -241,12 +243,14 @@ struct spa_bt_quirks *spa_bt_quirks_create(const struct spa_dict *info, struct s
this->log = log; this->log = log;
spa_log_topic_init(this->log, &log_topic);
this->force_sbc_xq = parse_force_flag(info, "bluez5.enable-sbc-xq"); this->force_sbc_xq = parse_force_flag(info, "bluez5.enable-sbc-xq");
this->force_msbc = parse_force_flag(info, "bluez5.enable-msbc"); this->force_msbc = parse_force_flag(info, "bluez5.enable-msbc");
this->force_hw_volume = parse_force_flag(info, "bluez5.enable-hw-volume"); this->force_hw_volume = parse_force_flag(info, "bluez5.enable-hw-volume");
if ((str = spa_dict_lookup(info, "bluez5.hardware-database")) != NULL) { if ((str = spa_dict_lookup(info, "bluez5.hardware-database")) != NULL) {
spa_log_debug(this->log, NAME ": loading session manager provided data"); spa_log_debug(this->log, "loading session manager provided data");
load_quirks(this, str, strlen(str)); load_quirks(this, str, strlen(str));
} else { } else {
char path[PATH_MAX]; char path[PATH_MAX];
@ -260,7 +264,7 @@ struct spa_bt_quirks *spa_bt_quirks_create(const struct spa_dict *info, struct s
} }
if (!(this->kernel_rules && this->adapter_rules && this->device_rules)) if (!(this->kernel_rules && this->adapter_rules && this->device_rules))
spa_log_warn(this->log, NAME ": failed to load bluez-hardware.conf"); spa_log_warn(this->log, "failed to load bluez-hardware.conf");
return this; return this;
} }
@ -316,7 +320,7 @@ int spa_bt_quirks_get_features(const struct spa_bt_quirks *this,
props = SPA_DICT_INIT(items, nitems); props = SPA_DICT_INIT(items, nitems);
log_props(this->log, &props); log_props(this->log, &props);
do_match(this->kernel_rules, &props, &no_features); do_match(this->kernel_rules, &props, &no_features);
spa_log_debug(this->log, NAME ": kernel quirks:%08x", no_features); spa_log_debug(this->log, "kernel quirks:%08x", no_features);
*features &= ~no_features; *features &= ~no_features;
} }
@ -341,7 +345,7 @@ int spa_bt_quirks_get_features(const struct spa_bt_quirks *this,
props = SPA_DICT_INIT(items, nitems); props = SPA_DICT_INIT(items, nitems);
log_props(this->log, &props); log_props(this->log, &props);
do_match(this->adapter_rules, &props, &no_features); do_match(this->adapter_rules, &props, &no_features);
spa_log_debug(this->log, NAME ": adapter quirks:%08x", no_features); spa_log_debug(this->log, "adapter quirks:%08x", no_features);
*features &= ~no_features; *features &= ~no_features;
} }
@ -368,7 +372,7 @@ int spa_bt_quirks_get_features(const struct spa_bt_quirks *this,
props = SPA_DICT_INIT(items, nitems); props = SPA_DICT_INIT(items, nitems);
log_props(this->log, &props); log_props(this->log, &props);
do_match(this->device_rules, &props, &no_features); do_match(this->device_rules, &props, &no_features);
spa_log_debug(this->log, NAME ": device quirks:%08x", no_features); spa_log_debug(this->log, "device quirks:%08x", no_features);
*features &= ~no_features; *features &= ~no_features;
} }

18
spa/plugins/bluez5/sco-sink.c
View file

@ -53,6 +53,10 @@
#include "defs.h" #include "defs.h"
static struct spa_log_topic log_topic = SPA_LOG_TOPIC(0, "spa.bluez5.sink.sco");
#undef SPA_LOG_TOPIC_DEFAULT
#define SPA_LOG_TOPIC_DEFAULT &log_topic
struct props { struct props {
uint32_t min_latency; uint32_t min_latency;
uint32_t max_latency; uint32_t max_latency;
@ -153,8 +157,6 @@ struct impl {
uint64_t total_samples; uint64_t total_samples;
}; };
#define NAME "sco-sink"
#define CHECK_PORT(this,d,p) ((d) == SPA_DIRECTION_INPUT && (p) == 0) #define CHECK_PORT(this,d,p) ((d) == SPA_DIRECTION_INPUT && (p) == 0)
static const uint32_t default_min_latency = MIN_LATENCY; static const uint32_t default_min_latency = MIN_LATENCY;
@ -313,7 +315,7 @@ static int impl_node_set_io(void *object, uint32_t id, void *data, size_t size)
following = is_following(this); following = is_following(this);
if (this->started && following != this->following) { if (this->started && following != this->following) {
spa_log_debug(this->log, NAME " %p: reassign follower %d->%d", this, this->following, following); spa_log_debug(this->log, "%p: reassign follower %d->%d", this, this->following, following);
this->following = following; this->following = following;
spa_loop_invoke(this->data_loop, do_reassign_follower, 0, NULL, 0, true, this); spa_loop_invoke(this->data_loop, do_reassign_follower, 0, NULL, 0, true, this);
} }
@ -567,7 +569,7 @@ static int do_start(struct impl *this)
this->following = is_following(this); this->following = is_following(this);
spa_log_debug(this->log, NAME " %p: start following:%d", this, this->following); spa_log_debug(this->log, "%p: start following:%d", this, this->following);
/* Do accept if Gateway; otherwise do connect for Head Unit */ /* Do accept if Gateway; otherwise do connect for Head Unit */
do_accept = this->transport->profile & SPA_BT_PROFILE_HEADSET_AUDIO_GATEWAY; do_accept = this->transport->profile & SPA_BT_PROFILE_HEADSET_AUDIO_GATEWAY;
@ -1071,7 +1073,7 @@ impl_node_port_use_buffers(void *object,
b->h = spa_buffer_find_meta_data(buffers[i], SPA_META_Header, sizeof(*b->h)); b->h = spa_buffer_find_meta_data(buffers[i], SPA_META_Header, sizeof(*b->h));
if (buffers[i]->datas[0].data == NULL) { if (buffers[i]->datas[0].data == NULL) {
spa_log_error(this->log, NAME " %p: need mapped memory", this); spa_log_error(this->log, "%p: need mapped memory", this);
return -EINVAL; return -EINVAL;
} }
} }
@ -1129,12 +1131,12 @@ static int impl_node_process(void *object)
struct buffer *b = &port->buffers[io->buffer_id]; struct buffer *b = &port->buffers[io->buffer_id];
if (!b->outstanding) { if (!b->outstanding) {
spa_log_warn(this->log, NAME " %p: buffer %u in use", this, io->buffer_id); spa_log_warn(this->log, "%p: buffer %u in use", this, io->buffer_id);
io->status = -EINVAL; io->status = -EINVAL;
return -EINVAL; return -EINVAL;
} }
spa_log_trace(this->log, NAME " %p: queue buffer %u", this, io->buffer_id); spa_log_trace(this->log, "%p: queue buffer %u", this, io->buffer_id);
spa_list_append(&port->ready, &b->link); spa_list_append(&port->ready, &b->link);
b->outstanding = false; b->outstanding = false;
@ -1247,6 +1249,8 @@ impl_init(const struct spa_handle_factory *factory,
this->data_loop = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_DataLoop); this->data_loop = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_DataLoop);
this->data_system = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_DataSystem); this->data_system = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_DataSystem);
spa_log_topic_init(this->log, &log_topic);
if (this->data_loop == NULL) { if (this->data_loop == NULL) {
spa_log_error(this->log, "a data loop is needed"); spa_log_error(this->log, "a data loop is needed");
return -EINVAL; return -EINVAL;

22
spa/plugins/bluez5/sco-source.c
View file

@ -54,6 +54,10 @@
#include "defs.h" #include "defs.h"
static struct spa_log_topic log_topic = SPA_LOG_TOPIC(0, "spa.bluez5.source.sco");
#undef SPA_LOG_TOPIC_DEFAULT
#define SPA_LOG_TOPIC_DEFAULT &log_topic
struct props { struct props {
uint32_t min_latency; uint32_t min_latency;
uint32_t max_latency; uint32_t max_latency;
@ -141,8 +145,6 @@ struct impl {
struct timespec now; struct timespec now;
}; };
#define NAME "sco-source"
#define CHECK_PORT(this,d,p) ((d) == SPA_DIRECTION_OUTPUT && (p) == 0) #define CHECK_PORT(this,d,p) ((d) == SPA_DIRECTION_OUTPUT && (p) == 0)
static const uint32_t default_min_latency = 128; static const uint32_t default_min_latency = 128;
@ -256,7 +258,7 @@ static int impl_node_set_io(void *object, uint32_t id, void *data, size_t size)
following = is_following(this); following = is_following(this);
if (this->started && following != this->following) { if (this->started && following != this->following) {
spa_log_debug(this->log, NAME" %p: reassign follower %d->%d", this, this->following, following); spa_log_debug(this->log, "%p: reassign follower %d->%d", this, this->following, following);
this->following = following; this->following = following;
} }
@ -329,7 +331,7 @@ static void recycle_buffer(struct impl *this, struct port *port, uint32_t buffer
struct buffer *b = &port->buffers[buffer_id]; struct buffer *b = &port->buffers[buffer_id];
if (b->outstanding) { if (b->outstanding) {
spa_log_trace(this->log, NAME " %p: recycle buffer %u", this, buffer_id); spa_log_trace(this->log, "%p: recycle buffer %u", this, buffer_id);
spa_list_append(&port->free, &b->link); spa_list_append(&port->free, &b->link);
b->outstanding = false; b->outstanding = false;
} }
@ -383,7 +385,7 @@ static void msbc_buffer_append_byte(struct impl *this, uint8_t byte)
} }
/* Helper function for debugging */ /* Helper function for debugging */
static SPA_UNUSED void hexdump_to_log(struct spa_log *log, uint8_t *data, size_t size) static SPA_UNUSED void hexdump_to_log(struct impl *this, uint8_t *data, size_t size)
{ {
char buf[2048]; char buf[2048];
size_t i, col = 0, pos = 0; size_t i, col = 0, pos = 0;
@ -397,7 +399,7 @@ static SPA_UNUSED void hexdump_to_log(struct spa_log *log, uint8_t *data, size_t
pos += res; pos += res;
col = (col + 1) % 16; col = (col + 1) % 16;
} }
spa_log_trace(log, "hexdump (%d bytes):%s", (int)size, buf); spa_log_trace(this->log, "hexdump (%d bytes):%s", (int)size, buf);
} }
/* helper function to detect if a packet consists only of zeros */ /* helper function to detect if a packet consists only of zeros */
@ -513,7 +515,7 @@ static int sco_source_cb(void *userdata, uint8_t *read_data, int size_read)
/* handle data read from socket */ /* handle data read from socket */
spa_log_trace(this->log, "read socket data %d", size_read); spa_log_trace(this->log, "read socket data %d", size_read);
#if 0 #if 0
hexdump_to_log(this->log, read_data, size_read); hexdump_to_log(this, read_data, size_read);
#endif #endif
if (this->transport->codec == HFP_AUDIO_CODEC_MSBC) { if (this->transport->codec == HFP_AUDIO_CODEC_MSBC) {
@ -611,7 +613,7 @@ static int do_start(struct impl *this)
this->following = is_following(this); this->following = is_following(this);
spa_log_debug(this->log, NAME" %p: start following:%d", spa_log_debug(this->log, "%p: start following:%d",
this, this->following); this, this->following);
/* Make sure the transport is valid */ /* Make sure the transport is valid */
@ -1077,7 +1079,7 @@ impl_node_port_use_buffers(void *object,
b->h = spa_buffer_find_meta_data(buffers[i], SPA_META_Header, sizeof(*b->h)); b->h = spa_buffer_find_meta_data(buffers[i], SPA_META_Header, sizeof(*b->h));
if (d[0].data == NULL) { if (d[0].data == NULL) {
spa_log_error(this->log, NAME " %p: need mapped memory", this); spa_log_error(this->log, "%p: need mapped memory", this);
return -EINVAL; return -EINVAL;
} }
spa_list_append(&port->free, &b->link); spa_list_append(&port->free, &b->link);
@ -1275,6 +1277,8 @@ impl_init(const struct spa_handle_factory *factory,
this->data_loop = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_DataLoop); this->data_loop = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_DataLoop);
this->data_system = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_DataSystem); this->data_system = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_DataSystem);
spa_log_topic_init(this->log, &log_topic);
if (this->data_loop == NULL) { if (this->data_loop == NULL) {
spa_log_error(this->log, "a data loop is needed"); spa_log_error(this->log, "a data loop is needed");
return -EINVAL; return -EINVAL;