From bd051e89a529ad95375220ad67c606b6e59e6451 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Fr=C3=A9d=C3=A9ric=20Danis?= Date: Tue, 8 Dec 2020 18:24:31 +0100 Subject: [PATCH] bluez5: improve debug --- spa/plugins/bluez5/backend-hsp-native.c | 70 +++++------ spa/plugins/bluez5/backend-hsphfpd.c | 148 ++++++++++++------------ 2 files changed, 111 insertions(+), 107 deletions(-) diff --git a/spa/plugins/bluez5/backend-hsp-native.c b/spa/plugins/bluez5/backend-hsp-native.c index 6e34ac701..316c2962c 100644 --- a/spa/plugins/bluez5/backend-hsp-native.c +++ b/spa/plugins/bluez5/backend-hsp-native.c @@ -38,6 +38,8 @@ #include "defs.h" +#define NAME "hsp-native" + struct spa_bt_backend { struct spa_bt_monitor *monitor; @@ -73,7 +75,7 @@ static void rfcomm_event(struct spa_source *source) struct spa_bt_backend *backend = t->backend; if (source->rmask & (SPA_IO_HUP | SPA_IO_ERR)) { - spa_log_info(backend->log, "lost RFCOMM connection."); + spa_log_info(backend->log, NAME": lost RFCOMM connection."); if (source->loop) spa_loop_remove_source(source->loop, source); goto fail; @@ -87,11 +89,11 @@ static void rfcomm_event(struct spa_source *source) len = read(source->fd, buf, 511); if (len < 0) { - spa_log_error(backend->log, "RFCOMM read error: %s", strerror(errno)); + spa_log_error(backend->log, NAME": RFCOMM read error: %s", strerror(errno)); goto fail; } buf[len] = 0; - spa_log_debug(backend->log, "RFCOMM << %s", buf); + spa_log_debug(backend->log, NAME": RFCOMM << %s", buf); /* There are only four HSP AT commands: * AT+VGS=value: value between 0 and 15, sent by the HS to AG to set the speaker gain. @@ -118,14 +120,14 @@ static void rfcomm_event(struct spa_source *source) } if (do_reply) { - spa_log_debug(backend->log, "RFCOMM >> OK"); + spa_log_debug(backend->log, NAME": RFCOMM >> OK"); len = write(source->fd, "\r\nOK\r\n", 6); /* we ignore any errors, it's not critical and real errors should * be caught with the HANGUP and ERROR events handled above */ if (len < 0) - spa_log_error(backend->log, "RFCOMM write error: %s", strerror(errno)); + spa_log_error(backend->log, NAME": RFCOMM write error: %s", strerror(errno)); } } return; @@ -146,11 +148,11 @@ static int sco_do_accept(struct spa_bt_transport *t) memset(&addr, 0, sizeof(addr)); optlen = sizeof(addr); - spa_log_debug(backend->log, "transport %p: doing accept", t); + spa_log_debug(backend->log, NAME": transport %p: doing accept", t); sock = accept(td->sco.fd, (struct sockaddr *) &addr, &optlen); if (sock < 0) { if (errno != EAGAIN) - spa_log_error(backend->log, "accept(): %s", strerror(errno)); + spa_log_error(backend->log, NAME": accept(): %s", strerror(errno)); goto fail; } return sock; @@ -184,7 +186,7 @@ static int sco_do_connect(struct spa_bt_transport *t) sock = socket(PF_BLUETOOTH, SOCK_SEQPACKET, BTPROTO_SCO); if (sock < 0) { - spa_log_error(backend->log, "socket(SEQPACKET, SCO) %s", strerror(errno)); + spa_log_error(backend->log, NAME": socket(SEQPACKET, SCO) %s", strerror(errno)); return -errno; } @@ -194,7 +196,7 @@ static int sco_do_connect(struct spa_bt_transport *t) bacpy(&addr.sco_bdaddr, &src); if (bind(sock, (struct sockaddr *) &addr, len) < 0) { - spa_log_error(backend->log, "bind(): %s", strerror(errno)); + spa_log_error(backend->log, NAME": bind(): %s", strerror(errno)); goto fail_close; } @@ -202,10 +204,10 @@ static int sco_do_connect(struct spa_bt_transport *t) addr.sco_family = AF_BLUETOOTH; bacpy(&addr.sco_bdaddr, &dst); - spa_log_debug(backend->log, "transport %p: doing connect", t); + spa_log_debug(backend->log, NAME": transport %p: doing connect", t); err = connect(sock, (struct sockaddr *) &addr, len); if (err < 0 && !(errno == EAGAIN || errno == EINPROGRESS)) { - spa_log_error(backend->log, "connect(): %s", strerror(errno)); + spa_log_error(backend->log, NAME": connect(): %s", strerror(errno)); goto fail_close; } @@ -241,9 +243,9 @@ static int sco_acquire_cb(void *data, bool optional) memset(&sco_opt, 0, len); if (getsockopt(sock, SOL_SCO, SCO_OPTIONS, &sco_opt, &len) < 0) - spa_log_warn(backend->log, "getsockopt(SCO_OPTIONS) failed, loading defaults"); + spa_log_warn(backend->log, NAME": getsockopt(SCO_OPTIONS) failed, loading defaults"); else { - spa_log_debug(backend->log, "autodetected mtu = %u", sco_opt.mtu); + spa_log_debug(backend->log, NAME": autodetected mtu = %u", sco_opt.mtu); t->read_mtu = sco_opt.mtu; t->write_mtu = sco_opt.mtu; } @@ -257,7 +259,7 @@ static int sco_release_cb(void *data) { struct spa_bt_transport *t = data; struct spa_bt_backend *backend = t->backend; - spa_log_info(backend->log, "Transport %s released", t->path); + spa_log_info(backend->log, NAME": Transport %s released", t->path); /* device will close the SCO socket for us */ return 0; } @@ -268,13 +270,13 @@ static void sco_event(struct spa_source *source) struct spa_bt_backend *backend = t->backend; if (source->rmask & (SPA_IO_HUP | SPA_IO_ERR)) { - spa_log_error(backend->log, "error listening SCO connection: %s", strerror(errno)); + spa_log_error(backend->log, NAME": error listening SCO connection: %s", strerror(errno)); goto fail; } #if 0 if (t->state != PA_BLUETOOTH_TRANSPORT_STATE_PLAYING) { - spa_log_info(monitor->log, "SCO incoming connection: changing state to PLAYING"); + spa_log_info(monitor->log, NAME": SCO incoming connection: changing state to PLAYING"); pa_bluetooth_transport_set_state (t, PA_BLUETOOTH_TRANSPORT_STATE_PLAYING); } #endif @@ -297,7 +299,7 @@ static int sco_listen(struct spa_bt_transport *t) sock = socket(PF_BLUETOOTH, SOCK_SEQPACKET | SOCK_NONBLOCK | SOCK_CLOEXEC, BTPROTO_SCO); if (sock < 0) { - spa_log_error(backend->log, "socket(SEQPACKET, SCO) %m"); + spa_log_error(backend->log, NAME": socket(SEQPACKET, SCO) %m"); return -errno; } @@ -313,13 +315,13 @@ static int sco_listen(struct spa_bt_transport *t) bacpy(&addr.sco_bdaddr, &src); if (bind(sock, (struct sockaddr *) &addr, sizeof(addr)) < 0) { - spa_log_error(backend->log, "bind(): %m"); + spa_log_error(backend->log, NAME": bind(): %m"); goto fail_close; } - spa_log_debug(backend->log, "transport %p: doing listen", t); + spa_log_debug(backend->log, NAME": transport %p: doing listen", t); if (listen(sock, 1) < 0) { - spa_log_error(backend->log, "listen(): %m"); + spa_log_error(backend->log, NAME": listen(): %m"); goto fail_close; } @@ -380,7 +382,7 @@ static DBusHandlerResult profile_new_connection(DBusConnection *conn, DBusMessag int fd; if (!dbus_message_has_signature(m, "oha{sv}")) { - spa_log_warn(backend->log, "invalid NewConnection() signature"); + spa_log_warn(backend->log, NAME": invalid NewConnection() signature"); return DBUS_HANDLER_RESULT_NOT_YET_HANDLED; } @@ -390,7 +392,7 @@ static DBusHandlerResult profile_new_connection(DBusConnection *conn, DBusMessag else if (strcmp(handler, PROFILE_HSP_HS) == 0) profile = SPA_BT_PROFILE_HSP_AG; else { - spa_log_warn(backend->log, "invalid handler %s", handler); + spa_log_warn(backend->log, NAME": invalid handler %s", handler); return DBUS_HANDLER_RESULT_NOT_YET_HANDLED; } @@ -399,21 +401,21 @@ static DBusHandlerResult profile_new_connection(DBusConnection *conn, DBusMessag d = spa_bt_device_find(backend->monitor, path); if (d == NULL) { - spa_log_warn(backend->log, "unknown device for path %s", path); + spa_log_warn(backend->log, NAME": unknown device for path %s", path); return DBUS_HANDLER_RESULT_NOT_YET_HANDLED; } dbus_message_iter_next(&it[0]); dbus_message_iter_get_basic(&it[0], &fd); - spa_log_debug(backend->log, "NewConnection path=%s, fd=%d, profile %s", path, fd, handler); + spa_log_debug(backend->log, NAME": NewConnection path=%s, fd=%d, profile %s", path, fd, handler); if ((pathfd = spa_aprintf("%s/fd%d", path, fd)) == NULL) return DBUS_HANDLER_RESULT_NEED_MEMORY; t = spa_bt_transport_create(backend->monitor, pathfd, sizeof(struct transport_data)); if (t == NULL) { - spa_log_warn(backend->log, "can't create transport: %m"); + spa_log_warn(backend->log, NAME": can't create transport: %m"); return DBUS_HANDLER_RESULT_NEED_MEMORY; } spa_bt_transport_set_implementation(t, &sco_transport_impl, t); @@ -435,7 +437,7 @@ static DBusHandlerResult profile_new_connection(DBusConnection *conn, DBusMessag sco_listen(t); - spa_log_debug(backend->log, "Transport %s available for profile %s", t->path, handler); + spa_log_debug(backend->log, NAME": Transport %s available for profile %s", t->path, handler); if ((r = dbus_message_new_method_return(m)) == NULL) return DBUS_HANDLER_RESULT_NEED_MEMORY; @@ -457,7 +459,7 @@ static DBusHandlerResult profile_request_disconnection(DBusConnection *conn, DBu DBusMessageIter it[5]; if (!dbus_message_has_signature(m, "o")) { - spa_log_warn(backend->log, "invalid RequestDisconnection() signature"); + spa_log_warn(backend->log, NAME": invalid RequestDisconnection() signature"); return DBUS_HANDLER_RESULT_NOT_YET_HANDLED; } @@ -467,7 +469,7 @@ static DBusHandlerResult profile_request_disconnection(DBusConnection *conn, DBu else if (strcmp(handler, PROFILE_HSP_HS) == 0) profile = SPA_BT_PROFILE_HSP_AG; else { - spa_log_warn(backend->log, "invalid handler %s", handler); + spa_log_warn(backend->log, NAME": invalid handler %s", handler); return DBUS_HANDLER_RESULT_NOT_YET_HANDLED; } @@ -476,7 +478,7 @@ static DBusHandlerResult profile_request_disconnection(DBusConnection *conn, DBu d = spa_bt_device_find(backend->monitor, path); if (d == NULL) { - spa_log_warn(backend->log, "unknown device for path %s", path); + spa_log_warn(backend->log, NAME": unknown device for path %s", path); return DBUS_HANDLER_RESULT_NOT_YET_HANDLED; } @@ -506,7 +508,7 @@ static DBusHandlerResult profile_handler(DBusConnection *c, DBusMessage *m, void interface = dbus_message_get_interface(m); member = dbus_message_get_member(m); - spa_log_debug(backend->log, "dbus: path=%s, interface=%s, member=%s", path, interface, member); + spa_log_debug(backend->log, NAME": dbus: path=%s, interface=%s, member=%s", path, interface, member); if (dbus_message_is_method_call(m, "org.freedesktop.DBus.Introspectable", "Introspect")) { const char *xml = PROFILE_INTROSPECT_XML; @@ -543,15 +545,15 @@ static void register_profile_reply(DBusPendingCall *pending, void *user_data) return; if (dbus_message_is_error(r, BLUEZ_ERROR_NOT_SUPPORTED)) { - spa_log_warn(backend->log, "Register profile not supported"); + spa_log_warn(backend->log, NAME": Register profile not supported"); goto finish; } if (dbus_message_is_error(r, DBUS_ERROR_UNKNOWN_METHOD)) { - spa_log_warn(backend->log, "Error registering profile"); + spa_log_warn(backend->log, NAME": Error registering profile"); goto finish; } if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) { - spa_log_error(backend->log, "RegisterProfile() failed: %s", + spa_log_error(backend->log, NAME": RegisterProfile() failed: %s", dbus_message_get_error_name(r)); goto finish; } @@ -573,7 +575,7 @@ static int register_profile(struct spa_bt_backend *backend, const char *profile, char *str; DBusPendingCall *call; - spa_log_debug(backend->log, "Registering Profile %s %s", profile, uuid); + spa_log_debug(backend->log, NAME": Registering Profile %s %s", profile, uuid); if (!dbus_connection_register_object_path(backend->conn, profile, diff --git a/spa/plugins/bluez5/backend-hsphfpd.c b/spa/plugins/bluez5/backend-hsphfpd.c index 7241c8483..bf1c11398 100644 --- a/spa/plugins/bluez5/backend-hsphfpd.c +++ b/spa/plugins/bluez5/backend-hsphfpd.c @@ -37,6 +37,8 @@ #include "defs.h" +#define NAME "hsphfpd" + struct spa_bt_backend { struct spa_bt_monitor *monitor; @@ -222,13 +224,13 @@ static int set_dbus_property(struct spa_bt_backend *backend, m = NULL; if (r == NULL) { - spa_log_error(backend->log, "Transport Set() failed for transport %s (%s)", path, err.message); + spa_log_error(backend->log, NAME": Transport Set() failed for transport %s (%s)", path, err.message); dbus_error_free(&err); return -EIO; } if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) { - spa_log_error(backend->log, "Set() returned error: %s", dbus_message_get_error_name(r)); + spa_log_error(backend->log, NAME": Set() returned error: %s", dbus_message_get_error_name(r)); return -EIO; } @@ -246,7 +248,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, HSPHFPD_AUDIO_TRANSPORT_INTERFACE, "RxVolumeGain", DBUS_TYPE_UINT16, &gain)) - spa_log_error(backend->log, "Changing rx volume gain to %u for transport %s failed", + spa_log_error(backend->log, NAME": Changing rx volume gain to %u for transport %s failed", (unsigned)gain, transport_data->transport_path); } @@ -260,7 +262,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, HSPHFPD_AUDIO_TRANSPORT_INTERFACE, "TxVolumeGain", DBUS_TYPE_UINT16, &gain)) - spa_log_error(backend->log, "Changing tx volume gain to %u for transport %s failed", + spa_log_error(backend->log, NAME": Changing tx volume gain to %u for transport %s failed", (unsigned)gain, transport_data->transport_path); } @@ -288,19 +290,19 @@ static void parse_transport_properties_values(struct spa_bt_backend *backend, dbus_message_iter_recurse(&element_i, &dict_i); if (dbus_message_iter_get_arg_type(&dict_i) != DBUS_TYPE_STRING) { - spa_log_error(backend->log, "Received invalid property for transport %s", transport_path); + spa_log_error(backend->log, NAME": Received invalid property for transport %s", transport_path); return; } dbus_message_iter_get_basic(&dict_i, &key); if (!dbus_message_iter_next(&dict_i)) { - spa_log_error(backend->log, "Received invalid property for transport %s", transport_path); + spa_log_error(backend->log, NAME": Received invalid property for transport %s", transport_path); return; } if (dbus_message_iter_get_arg_type(&dict_i) != DBUS_TYPE_VARIANT) { - spa_log_error(backend->log, "Received invalid property for transport %s", transport_path); + spa_log_error(backend->log, NAME": Received invalid property for transport %s", transport_path); return; } @@ -323,7 +325,7 @@ static void parse_transport_properties_values(struct spa_bt_backend *backend, volume_control = 0; if (!volume_control) - spa_log_warn(backend->log, "Transport %s received invalid '%s' property value '%s', ignoring", transport_path, key, value); + spa_log_warn(backend->log, NAME": Transport %s received invalid '%s' property value '%s', ignoring", transport_path, key, value); else if (strcmp(key, "RxVolumeControl") == 0) *rx_volume_control = volume_control; else if (strcmp(key, "TxVolumeControl") == 0) @@ -373,20 +375,20 @@ static void hsphfpd_parse_transport_properties(struct spa_bt_backend *backend, s &rx_volume_gain, &tx_volume_gain, &mtu); if (endpoint_path) - spa_log_warn(backend->log, "Transport %s received a duplicate '%s' property, ignoring", + spa_log_warn(backend->log, NAME": Transport %s received a duplicate '%s' property, ignoring", transport_data->transport_path, "Endpoint"); if (air_codec) - spa_log_warn(backend->log, "Transport %s received a duplicate '%s' property, ignoring", + spa_log_warn(backend->log, NAME": Transport %s received a duplicate '%s' property, ignoring", transport_data->transport_path, "AirCodec"); if (mtu) - spa_log_warn(backend->log, "Transport %s received a duplicate '%s' property, ignoring", + spa_log_warn(backend->log, NAME": Transport %s received a duplicate '%s' property, ignoring", transport_data->transport_path, "MTU"); if (rx_volume_control) { if (!!transport_data->rx_soft_volume != !!(rx_volume_control != HSPHFPD_VOLUME_CONTROL_REMOTE)) { - spa_log_info(backend->log, "Transport %s changed rx soft volume from %d to %d", + spa_log_info(backend->log, NAME": Transport %s changed rx soft volume from %d to %d", transport_data->transport_path, transport_data->rx_soft_volume, (rx_volume_control != HSPHFPD_VOLUME_CONTROL_REMOTE)); transport_data->rx_soft_volume = (rx_volume_control != HSPHFPD_VOLUME_CONTROL_REMOTE); @@ -400,7 +402,7 @@ static void hsphfpd_parse_transport_properties(struct spa_bt_backend *backend, s if (tx_volume_control) { if (!!transport_data->tx_soft_volume != !!(tx_volume_control != HSPHFPD_VOLUME_CONTROL_REMOTE)) { - spa_log_info(backend->log, "Transport %s changed tx soft volume from %d to %d", + spa_log_info(backend->log, NAME": Transport %s changed tx soft volume from %d to %d", transport_data->transport_path, transport_data->rx_soft_volume, (tx_volume_control != HSPHFPD_VOLUME_CONTROL_REMOTE)); transport_data->tx_soft_volume = (tx_volume_control != HSPHFPD_VOLUME_CONTROL_REMOTE); @@ -414,7 +416,7 @@ static void hsphfpd_parse_transport_properties(struct spa_bt_backend *backend, s if (rx_volume_gain != (uint16_t)-1) { if (transport_data->rx_volume_gain != rx_volume_gain) { - spa_log_info(backend->log, "Transport %s changed rx volume gain from %u to %u", + spa_log_info(backend->log, NAME": 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->rx_volume_gain = rx_volume_gain; rx_volume_gain_changed = true; @@ -423,7 +425,7 @@ static void hsphfpd_parse_transport_properties(struct spa_bt_backend *backend, s if (tx_volume_gain != (uint16_t)-1) { if (transport_data->tx_volume_gain != tx_volume_gain) { - spa_log_info(backend->log, "Transport %s changed tx volume gain from %u to %u", + spa_log_info(backend->log, NAME": 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->tx_volume_gain = tx_volume_gain; tx_volume_gain_changed = true; @@ -437,8 +439,8 @@ static void hsphfpd_parse_transport_properties(struct spa_bt_backend *backend, s 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); #else - 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, "TX volume gain changed: %d, soft volume changed: %d", tx_volume_gain_changed, tx_soft_volume_changed); + 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, NAME": TX volume gain changed: %d, soft volume changed: %d", tx_volume_gain_changed, tx_soft_volume_changed); #endif if (rx_volume_control_changed) @@ -581,12 +583,12 @@ static DBusHandlerResult hsphfpd_new_audio_connection(DBusConnection *conn, DBus dbus_message_iter_next(&arg_i); dbus_message_iter_get_basic(&arg_i, &fd); - spa_log_debug(backend->log, "NewConnection %s, fd %d", transport_path, fd); + spa_log_debug(backend->log, NAME": NewConnection %s, fd %d", transport_path, fd); sender = dbus_message_get_sender(m); if (strcmp(sender, backend->hsphfpd_service_id) != 0) { close(fd); - spa_log_error(backend->log, "Sender '%s' is not authorized", sender); + spa_log_error(backend->log, NAME": Sender '%s' is not authorized", sender); r = dbus_message_new_error_printf(m, HSPHFPD_ERROR_REJECTED, "Sender '%s' is not authorized", sender); goto fail; } @@ -609,28 +611,28 @@ static DBusHandlerResult hsphfpd_new_audio_connection(DBusConnection *conn, DBus if (!endpoint_path) { close(fd); - spa_log_error(backend->log, "Endpoint property was not specified"); + spa_log_error(backend->log, NAME": Endpoint property was not specified"); r = dbus_message_new_error(m, HSPHFPD_ERROR_REJECTED, "Endpoint property was not specified"); goto fail; } if (!air_codec) { close(fd); - spa_log_error(backend->log, "AirCodec property was not specified"); + spa_log_error(backend->log, NAME": AirCodec property was not specified"); r = dbus_message_new_error(m, HSPHFPD_ERROR_REJECTED, "AirCodec property was not specified"); goto fail; } if (!rx_volume_control) { close(fd); - spa_log_error(backend->log, "RxVolumeControl property was not specified"); + spa_log_error(backend->log, NAME": RxVolumeControl property was not specified"); r = dbus_message_new_error(m, HSPHFPD_ERROR_REJECTED, "RxVolumeControl property was not specified"); goto fail; } if (!tx_volume_control) { close(fd); - spa_log_error(backend->log, "TxVolumeControl property was not specified"); + spa_log_error(backend->log, NAME": TxVolumeControl property was not specified"); r = dbus_message_new_error(m, HSPHFPD_ERROR_REJECTED, "TxVolumeControl property was not specified"); goto fail; } @@ -638,7 +640,7 @@ static DBusHandlerResult hsphfpd_new_audio_connection(DBusConnection *conn, DBus if (rx_volume_control != HSPHFPD_VOLUME_CONTROL_NONE) { if (rx_volume_gain == (uint16_t)-1) { close(fd); - spa_log_error(backend->log, "RxVolumeGain property was not specified, but VolumeControl is not none"); + spa_log_error(backend->log, NAME": 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; } @@ -649,7 +651,7 @@ static DBusHandlerResult hsphfpd_new_audio_connection(DBusConnection *conn, DBus if (tx_volume_control != HSPHFPD_VOLUME_CONTROL_NONE) { if (tx_volume_gain == (uint16_t)-1) { close(fd); - spa_log_error(backend->log, "TxVolumeGain property was not specified, but VolumeControl is not none"); + spa_log_error(backend->log, NAME": 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; } @@ -659,7 +661,7 @@ static DBusHandlerResult hsphfpd_new_audio_connection(DBusConnection *conn, DBus if (!mtu) { close(fd); - spa_log_error(backend->log, "MTU property was not specified"); + spa_log_error(backend->log, NAME": MTU property was not specified"); r = dbus_message_new_error(m, HSPHFPD_ERROR_REJECTED, "MTU property was not specified"); goto fail; } @@ -667,14 +669,14 @@ static DBusHandlerResult hsphfpd_new_audio_connection(DBusConnection *conn, DBus endpoint = endpoint_find(backend, endpoint_path); if (!endpoint) { close(fd); - spa_log_error(backend->log, "Endpoint %s does not exist", endpoint_path); + spa_log_error(backend->log, NAME": 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; } if (!endpoint->valid) { close(fd); - spa_log_error(backend->log, "Endpoint %s is not valid", endpoint_path); + spa_log_error(backend->log, NAME": 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; } @@ -682,17 +684,17 @@ static DBusHandlerResult hsphfpd_new_audio_connection(DBusConnection *conn, DBus transport = spa_bt_transport_find(backend->monitor, endpoint_path); if (!transport) { close(fd); - spa_log_error(backend->log, "Endpoint %s is not connected", endpoint_path); + spa_log_error(backend->log, NAME": 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; } if (transport->codec != codec) - spa_log_warn(backend->log, "Expecting codec to be %d, got %d", transport->codec, codec); + spa_log_warn(backend->log, NAME": Expecting codec to be %d, got %d", transport->codec, codec); if (transport->fd >= 0) { close(fd); - spa_log_error(backend->log, "Endpoint %s has already active transport", endpoint_path); + spa_log_error(backend->log, NAME": 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; } @@ -757,7 +759,7 @@ static DBusHandlerResult audio_agent_endpoint_handler(DBusConnection *c, DBusMes interface = dbus_message_get_interface(m); member = dbus_message_get_member(m); - spa_log_debug(backend->log, "dbus: path=%s, interface=%s, member=%s", path, interface, member); + spa_log_debug(backend->log, NAME": dbus: path=%s, interface=%s, member=%s", path, interface, member); if (dbus_message_is_method_call(m, "org.freedesktop.DBus.Introspectable", "Introspect")) { const char *xml = AUDIO_AGENT_ENDPOINT_INTROSPECT_XML; @@ -822,7 +824,7 @@ static DBusHandlerResult application_object_manager_handler(DBusConnection *c, D interface = dbus_message_get_interface(m); member = dbus_message_get_member(m); - spa_log_debug(backend->log, "dbus: path=%s, interface=%s, member=%s", path, interface, member); + spa_log_debug(backend->log, NAME": dbus: path=%s, interface=%s, member=%s", path, interface, member); if (dbus_message_is_method_call(m, "org.freedesktop.DBus.Introspectable", "Introspect")) { const char *xml = APPLICATION_OBJECT_MANAGER_INTROSPECT_XML; @@ -873,18 +875,18 @@ static void hsphfpd_audio_acquire_reply(DBusPendingCall *pending, void *user_dat return; if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) { - spa_log_error(backend->log, "RegisterApplication() failed: %s", + spa_log_error(backend->log, NAME": RegisterApplication() failed: %s", dbus_message_get_error_name(r)); goto finish; } if (strcmp(dbus_message_get_sender(r), backend->hsphfpd_service_id) != 0) { - spa_log_error(backend->log, "Reply for " HSPHFPD_ENDPOINT_INTERFACE ".ConnectAudio() from invalid sender"); + spa_log_error(backend->log, NAME": Reply for " HSPHFPD_ENDPOINT_INTERFACE ".ConnectAudio() from invalid sender"); goto finish; } if (strcmp(dbus_message_get_signature(r), "oso") != 0) { - spa_log_error(backend->log, "Invalid reply signature for " HSPHFPD_ENDPOINT_INTERFACE ".ConnectAudio()"); + spa_log_error(backend->log, NAME": Invalid reply signature for " HSPHFPD_ENDPOINT_INTERFACE ".ConnectAudio()"); goto finish; } @@ -893,7 +895,7 @@ static void hsphfpd_audio_acquire_reply(DBusPendingCall *pending, void *user_dat DBUS_TYPE_STRING, &service_id, DBUS_TYPE_OBJECT_PATH, &agent_path, DBUS_TYPE_INVALID) == FALSE) { - spa_log_error(backend->log, "Failed to parse " HSPHFPD_ENDPOINT_INTERFACE ".ConnectAudio() reply: %s", error.message); + spa_log_error(backend->log, NAME": Failed to parse " HSPHFPD_ENDPOINT_INTERFACE ".ConnectAudio() reply: %s", error.message); goto finish; } @@ -902,7 +904,7 @@ static void hsphfpd_audio_acquire_reply(DBusPendingCall *pending, void *user_dat goto finish; } - spa_log_debug(backend->log, "hsphfpd audio acquired"); + spa_log_debug(backend->log, NAME": hsphfpd audio acquired"); finish: dbus_message_unref(r); @@ -958,11 +960,11 @@ static int hsphfpd_audio_release(void *data) struct hsphfpd_transport_data *transport_data = transport->user_data; if (transport->fd < 0) { - spa_log_info(backend->log, "transport %s already released", transport->path); + spa_log_info(backend->log, NAME": transport %s already released", transport->path); return 0; } - spa_log_debug(backend->log, "transport %p: Release %s", + spa_log_debug(backend->log, NAME": transport %p: Release %s", transport, transport->path); /* shutdown to make sure connection is dropped immediately */ @@ -1023,24 +1025,24 @@ static DBusHandlerResult hsphfpd_parse_endpoint_properties(struct spa_bt_backend endpoint->local_address = strdup(value); else if (strcmp(key, "Profile") == 0) { if (endpoint->profile) - spa_log_warn(backend->log, "Endpoint %s received a duplicate '%s' property, ignoring", endpoint->path, key); + spa_log_warn(backend->log, NAME": Endpoint %s received a duplicate '%s' property, ignoring", endpoint->path, key); else if (strcmp(value, "headset") == 0) endpoint->profile = HSPHFPD_PROFILE_HEADSET; else if (strcmp(value, "handsfree") == 0) endpoint->profile = HSPHFPD_PROFILE_HANDSFREE; else - spa_log_warn(backend->log, "Endpoint %s received invalid '%s' property value '%s', ignoring", endpoint->path, key, value); + spa_log_warn(backend->log, NAME": Endpoint %s received invalid '%s' property value '%s', ignoring", endpoint->path, key, value); } else if (strcmp(key, "Role") == 0) { if (endpoint->role) - spa_log_warn(backend->log, "Endpoint %s received a duplicate '%s' property, ignoring", endpoint->path, key); + spa_log_warn(backend->log, NAME": Endpoint %s received a duplicate '%s' property, ignoring", endpoint->path, key); else if (strcmp(value, "client") == 0) endpoint->role = HSPHFPD_ROLE_CLIENT; else if (strcmp(value, "gateway") == 0) endpoint->role = HSPHFPD_ROLE_GATEWAY; else - spa_log_warn(backend->log, "Endpoint %s received invalid '%s' property value '%s', ignoring", endpoint->path, key, value); + spa_log_warn(backend->log, NAME": Endpoint %s received invalid '%s' property value '%s', ignoring", endpoint->path, key, value); } - spa_log_trace(backend->log, " %s: %s (%p)", key, value, endpoint); + spa_log_trace(backend->log, NAME": %s: %s (%p)", key, value, endpoint); } break; @@ -1050,7 +1052,7 @@ static DBusHandlerResult hsphfpd_parse_endpoint_properties(struct spa_bt_backend dbus_message_iter_get_basic(&value_i, &value); if (strcmp(key, "Connected") == 0) endpoint->connected = value; - spa_log_trace(backend->log, " %s: %d", key, value); + spa_log_trace(backend->log, NAME": %s: %d", key, value); } break; @@ -1083,7 +1085,7 @@ static DBusHandlerResult hsphfpd_parse_endpoint_properties(struct spa_bt_backend d = spa_bt_device_find_by_address(backend->monitor, endpoint->remote_address, endpoint->local_address); if (!d) { - spa_log_debug(backend->log, "No device for %s", endpoint->path); + spa_log_debug(backend->log, NAME": No device for %s", endpoint->path); return DBUS_HANDLER_RESULT_HANDLED; } @@ -1093,9 +1095,9 @@ static DBusHandlerResult hsphfpd_parse_endpoint_properties(struct spa_bt_backend 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_device_check_profiles(d, false); - spa_log_debug(backend->log, "Transport released for %s", endpoint->path); + spa_log_debug(backend->log, NAME": Transport released for %s", endpoint->path); } else { - spa_log_debug(backend->log, "Transport already configured for %s", endpoint->path); + spa_log_debug(backend->log, NAME": Transport already configured for %s", endpoint->path); return DBUS_HANDLER_RESULT_HANDLED; } } @@ -1106,7 +1108,7 @@ static DBusHandlerResult hsphfpd_parse_endpoint_properties(struct spa_bt_backend char *t_path = strdup(endpoint->path); t = spa_bt_transport_create(backend->monitor, t_path, sizeof(struct hsphfpd_transport_data)); if (t == NULL) { - spa_log_warn(backend->log, "can't create transport: %m"); + spa_log_warn(backend->log, NAME": can't create transport: %m"); free(t_path); return DBUS_HANDLER_RESULT_NEED_MEMORY; } @@ -1134,7 +1136,7 @@ static DBusHandlerResult hsphfpd_parse_endpoint_properties(struct spa_bt_backend spa_bt_device_connect_profile(t->device, t->profile); - spa_log_debug(backend->log, "Transport %s available for hsphfpd", endpoint->path); + spa_log_debug(backend->log, NAME": Transport %s available for hsphfpd", endpoint->path); return DBUS_HANDLER_RESULT_HANDLED; } @@ -1167,11 +1169,11 @@ static DBusHandlerResult hsphfpd_parse_interfaces(struct spa_bt_backend *backend endpoint = calloc(1, sizeof(struct hsphfpd_endpoint)); endpoint->path = strdup(path); spa_list_append(&backend->endpoint_list, &endpoint->link); - spa_log_debug(backend->log, "Found endpoint %s", path); + spa_log_debug(backend->log, NAME": Found endpoint %s", path); } hsphfpd_parse_endpoint_properties(backend, endpoint, &iface_i); } else - spa_log_debug(backend->log, "Unknown interface %s found, skipping", interface); + spa_log_debug(backend->log, NAME": Unknown interface %s found, skipping", interface); dbus_message_iter_next(&element_i); } @@ -1190,18 +1192,18 @@ static void hsphfpd_get_endpoints_reply(DBusPendingCall *pending, void *user_dat return; if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) { - spa_log_error(backend->log, "Failed to get a list of endpoints from hsphfpd: %s", + spa_log_error(backend->log, NAME": Failed to get a list of endpoints from hsphfpd: %s", dbus_message_get_error_name(r)); goto finish; } if (strcmp(dbus_message_get_sender(r), backend->hsphfpd_service_id) != 0) { - spa_log_error(backend->log, "Reply for GetManagedObjects() from invalid sender"); + spa_log_error(backend->log, NAME": Reply for GetManagedObjects() from invalid sender"); goto finish; } if (!dbus_message_iter_init(r, &i) || strcmp(dbus_message_get_signature(r), "a{oa{sa{sv}}}") != 0) { - spa_log_error(backend->log, "Invalid arguments in GetManagedObjects() reply"); + spa_log_error(backend->log, NAME": Invalid arguments in GetManagedObjects() reply"); goto finish; } @@ -1233,14 +1235,14 @@ static void hsphfpd_register_application_reply(DBusPendingCall *pending, void *u return; if (dbus_message_get_type(r) == DBUS_MESSAGE_TYPE_ERROR) { - spa_log_error(backend->log, "RegisterApplication() failed: %s", + spa_log_error(backend->log, NAME": RegisterApplication() failed: %s", dbus_message_get_error_name(r)); goto finish; } backend->hsphfpd_service_id = strdup(dbus_message_get_sender(r)); - spa_log_debug(backend->log, "Registered to hsphfpd"); + spa_log_debug(backend->log, NAME": Registered to hsphfpd"); m = dbus_message_new_method_call(HSPHFPD_SERVICE, "/", DBUS_INTERFACE_OBJECTMANAGER, "GetManagedObjects"); @@ -1262,7 +1264,7 @@ static int hsphfpd_register_application(struct spa_bt_backend *backend) const char *path = APPLICATION_OBJECT_MANAGER_PATH; DBusPendingCall *call; - spa_log_debug(backend->log, "Registering to hsphfpd"); + spa_log_debug(backend->log, NAME": Registering to hsphfpd"); m = dbus_message_new_method_call(HSPHFPD_SERVICE, "/", HSPHFPD_APPLICATION_MANAGER_INTERFACE, "RegisterApplication"); @@ -1297,7 +1299,7 @@ static DBusHandlerResult hsphfpd_filter_cb(DBusConnection *bus, DBusMessage *m, DBUS_TYPE_STRING, &old_owner, DBUS_TYPE_STRING, &new_owner, DBUS_TYPE_INVALID)) { - spa_log_error(backend->log, "Failed to parse org.freedesktop.DBus.NameOwnerChanged: %s", err.message); + spa_log_error(backend->log, NAME": Failed to parse org.freedesktop.DBus.NameOwnerChanged: %s", err.message); goto finish; } @@ -1305,7 +1307,7 @@ static DBusHandlerResult hsphfpd_filter_cb(DBusConnection *bus, DBusMessage *m, if (old_owner && *old_owner) { struct hsphfpd_endpoint *endpoint; - spa_log_debug(backend->log, "hsphfpd disappeared"); + spa_log_debug(backend->log, NAME": hsphfpd disappeared"); if (backend->hsphfpd_service_id) { free(backend->hsphfpd_service_id); backend->hsphfpd_service_id = NULL; @@ -1316,24 +1318,24 @@ static DBusHandlerResult hsphfpd_filter_cb(DBusConnection *bus, DBusMessage *m, } if (new_owner && *new_owner) { - spa_log_debug(backend->log, "hsphfpd appeared"); + spa_log_debug(backend->log, NAME": hsphfpd appeared"); hsphfpd_register_application(backend); } } else { - spa_log_debug(backend->log, "Name owner changed %s", dbus_message_get_path(m)); + spa_log_debug(backend->log, NAME": Name owner changed %s", dbus_message_get_path(m)); } } } else if (backend->hsphfpd_service_id && strcmp(sender, backend->hsphfpd_service_id) == 0) { if (dbus_message_is_signal(m, DBUS_INTERFACE_OBJECTMANAGER, "InterfacesAdded")) { DBusMessageIter arg_i; - spa_log_warn(backend->log, "sender: %s", dbus_message_get_sender(m)); + spa_log_warn(backend->log, NAME": sender: %s", dbus_message_get_sender(m)); if (!backend->endpoints_listed) goto finish; if (!dbus_message_iter_init(m, &arg_i) || strcmp(dbus_message_get_signature(m), "oa{sa{sv}}") != 0) { - spa_log_error(backend->log, "Invalid signature found in InterfacesAdded"); + spa_log_error(backend->log, NAME": Invalid signature found in InterfacesAdded"); goto finish; } @@ -1346,7 +1348,7 @@ static DBusHandlerResult hsphfpd_filter_cb(DBusConnection *bus, DBusMessage *m, goto finish; if (!dbus_message_iter_init(m, &arg_i) || strcmp(dbus_message_get_signature(m), "oas") != 0) { - spa_log_error(backend->log, "Invalid signature found in InterfacesRemoved"); + spa_log_error(backend->log, NAME": Invalid signature found in InterfacesRemoved"); goto finish; } @@ -1366,7 +1368,7 @@ static DBusHandlerResult hsphfpd_filter_cb(DBusConnection *bus, DBusMessage *m, if (transport) spa_bt_transport_free(transport); - spa_log_debug(backend->log, "Remove endpoint %s", path); + spa_log_debug(backend->log, NAME": Remove endpoint %s", path); endpoint = endpoint_find(backend, path); if (endpoint) endpoint_free(endpoint); @@ -1383,7 +1385,7 @@ static DBusHandlerResult hsphfpd_filter_cb(DBusConnection *bus, DBusMessage *m, goto finish; if (!dbus_message_iter_init(m, &arg_i) || strcmp(dbus_message_get_signature(m), "sa{sv}as") != 0) { - spa_log_error(backend->log, "Invalid signature found in PropertiesChanged"); + spa_log_error(backend->log, NAME": Invalid signature found in PropertiesChanged"); goto finish; } @@ -1395,20 +1397,20 @@ static DBusHandlerResult hsphfpd_filter_cb(DBusConnection *bus, DBusMessage *m, if (strcmp(iface, HSPHFPD_ENDPOINT_INTERFACE) == 0) { struct hsphfpd_endpoint *endpoint = endpoint_find(backend, path); if (!endpoint) { - spa_log_warn(backend->log, "Properties changed on unknown endpoint %s", path); + spa_log_warn(backend->log, NAME": Properties changed on unknown endpoint %s", path); goto finish; } - spa_log_debug(backend->log, "Properties changed on endpoint %s", path); + spa_log_debug(backend->log, NAME": Properties changed on endpoint %s", path); hsphfpd_parse_endpoint_properties(backend, endpoint, &arg_i); } else if (strcmp(iface, HSPHFPD_AUDIO_TRANSPORT_INTERFACE) == 0) { struct spa_bt_transport *transport = spa_bt_transport_find_full(backend->monitor, hsphfpd_cmp_transport_path, (const void *)path); if (!transport) { - spa_log_warn(backend->log, "Properties changed on unknown transport %s", path); + spa_log_warn(backend->log, NAME": Properties changed on unknown transport %s", path); goto finish; } - spa_log_debug(backend->log, "Properties changed on transport %s", path); + spa_log_debug(backend->log, NAME": Properties changed on transport %s", path); hsphfpd_parse_transport_properties(backend, transport, &arg_i); } } @@ -1428,7 +1430,7 @@ void backend_hsphfpd_add_filters(struct spa_bt_backend *backend) dbus_error_init(&err); if (!dbus_connection_add_filter(backend->conn, hsphfpd_filter_cb, backend, NULL)) { - spa_log_error(backend->log, "failed to add filter function"); + spa_log_error(backend->log, NAME": failed to add filter function"); goto fail; }