From: Mike Brady Date: Thu, 10 Jan 2019 16:10:53 +0000 (+0000) Subject: Add some diagnostics, shorten timeouts and set so_linger of zero whenever a write... X-Git-Tag: 3.3RC0~66^2~70 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=8e72574a579322d976e77c17f73d06864e6bdf1d;p=thirdparty%2Fshairport-sync.git Add some diagnostics, shorten timeouts and set so_linger of zero whenever a write or read error occurs. --- diff --git a/dacp.c b/dacp.c index 04821650..f1c91e48 100644 --- a/dacp.c +++ b/dacp.c @@ -127,9 +127,9 @@ void addrinfo_cleanup(void *arg) { } void mutex_lock_cleanup(void *arg) { - // debug(1, "mutex lock cleanup called."); pthread_mutex_t *m = (pthread_mutex_t *)arg; - pthread_mutex_unlock(m); + if (pthread_mutex_unlock(m)) + debug(1,"Error releasing mutex."); } void connect_cleanup(void *arg) { @@ -193,6 +193,7 @@ int dacp_send_command(const char *command, char **body, ssize_t *bodysize) { // debug(1,"Error %d \"%s\" at getaddrinfo.",ires,gai_strerror(ires)); response.code = 498; // Bad Address information for the DACP server } else { + uint64_t start_time = get_absolute_time_in_fp(); pthread_cleanup_push(addrinfo_cleanup, (void *)&res); // only do this one at a time -- not sure it is necessary, but better safe than sorry @@ -200,7 +201,6 @@ int dacp_send_command(const char *command, char **body, ssize_t *bodysize) { // int mutex_reply = pthread_mutex_lock(&dacp_conversation_lock); if (mutex_reply == 0) { pthread_cleanup_push(mutex_lock_cleanup, (void *)&dacp_conversation_lock); - // debug(1,"dacp_conversation_lock acquired for command \"%s\".",command); // make a socket: sockfd = socket(res->ai_family, res->ai_socktype, res->ai_protocol); @@ -213,8 +213,8 @@ int dacp_send_command(const char *command, char **body, ssize_t *bodysize) { // debug(2, "dacp_send_command: open socket %d.",sockfd); struct timeval tv; - tv.tv_sec = 2; - tv.tv_usec = 0; + tv.tv_sec = 0; + tv.tv_usec = 80000; if (setsockopt(sockfd, SOL_SOCKET, SO_RCVTIMEO, (const char *)&tv, sizeof tv) == -1) debug(1, "dacp_send_command: error %d setting receive timeout.", errno); if (setsockopt(sockfd, SOL_SOCKET, SO_SNDTIMEO, (const char *)&tv, sizeof tv) == -1) @@ -223,7 +223,7 @@ int dacp_send_command(const char *command, char **body, ssize_t *bodysize) { // connect! // debug(1, "DACP socket created."); if (connect(sockfd, res->ai_addr, res->ai_addrlen) < 0) { - // debug(2, "dacp_send_command: connect failed with errno %d.", errno); + debug(3, "dacp_send_command: connect failed with errno %d.", errno); response.code = 496; // Can't connect to the DACP server } else { // debug(1,"DACP connect succeeded."); @@ -233,13 +233,26 @@ int dacp_send_command(const char *command, char **body, ssize_t *bodysize) { command, dacp_server.ip_string, dacp_server.port, dacp_server.active_remote_id); // Send command - // debug(3,"dacp_send_command: connect message: \"%s\".",message); - if (send(sockfd, message, strlen(message), 0) != (ssize_t)strlen(message)) { - debug(1, "dacp_send_command: send failed."); + debug(3,"dacp_send_command: \"%s\".",command); + ssize_t wresp = send(sockfd, message, strlen(message), 0); + if (wresp == -1) { + char errorstring[1024]; + strerror_r(errno, (char *)errorstring, sizeof(errorstring)); + debug(2, "dacp_send_command: write error %d: \"%s\".", errno, (char *)errorstring); + struct linger so_linger; + so_linger.l_onoff = 1; // "true" + so_linger.l_linger = 0; + int err = setsockopt(sockfd, SOL_SOCKET, SO_LINGER, &so_linger, sizeof so_linger); + if (err) + debug(1, "Could not set the dacp socket to abort due to a write error on closing."); + } + if (wresp != (ssize_t)strlen(message)) { + // debug(1, "dacp_send_command: send failed."); response.code = 493; // Client failed to send a message } else { + response.body = malloc(2048); // it can resize this if necessary response.malloced_size = 2048; pthread_cleanup_push(malloc_cleanup, response.body); @@ -256,11 +269,21 @@ int dacp_send_command(const char *command, char **body, ssize_t *bodysize) { const char *data = buffer; if (setsockopt(sockfd, SOL_SOCKET, SO_RCVTIMEO, (const char *)&tv, sizeof tv) == -1) debug(1, "dacp_send_command: error %d setting receive timeout.", errno); - int ndata = recv(sockfd, buffer, sizeof(buffer), 0); + ssize_t ndata = recv(sockfd, buffer, sizeof(buffer), 0); // debug(3, "Received %d bytes: \"%s\".", ndata, buffer); if (ndata <= 0) { - // debug(1, "dacp_send_command -- error receiving response for command \"%s\".", - // command); + if (ndata == -1) { + char errorstring[1024]; + strerror_r(errno, (char *)errorstring, sizeof(errorstring)); + debug(2, "dacp_send_command: receiving error %d: \"%s\".", errno,(char *)errorstring); + struct linger so_linger; + so_linger.l_onoff = 1; // "true" + so_linger.l_linger = 0; + int err = setsockopt(sockfd, SOL_SOCKET, SO_LINGER, &so_linger, sizeof so_linger); + if (err) + debug(1, "Could not set the dacp socket to abort due to a read error on closing."); + } + free(response.body); response.body = NULL; response.malloced_size = 0; @@ -308,6 +331,9 @@ int dacp_send_command(const char *command, char **body, ssize_t *bodysize) { } pthread_cleanup_pop(1); // this should free the addrinfo // freeaddrinfo(res); + uint64_t et = get_absolute_time_in_fp() - start_time; + et = (et * 1000000) >> 32; // microseconds + debug(2,"dacp_send_command: %f seconds, response code %d, command \"%s\".",(1.0 * et) / 1000000, response.code, command); } *body = response.body; *bodysize = response.size; @@ -829,6 +855,8 @@ void dacp_monitor_start() { rc = pthread_mutex_init(&dacp_conversation_lock, &mta); if (rc) debug(1, "Error creating the DACP Conversation Lock Mutex Init"); + else + debug(1, "DACP Conversation Lock Mutex Init"); rc = pthread_mutexattr_destroy(&mta); if (rc) @@ -864,6 +892,7 @@ void dacp_monitor_stop() { pthread_cancel(dacp_monitor_thread); pthread_join(dacp_monitor_thread, NULL); pthread_mutex_destroy(&dacp_server_information_lock); + debug(1, "DACP Conversation Lock Mutex Destroyed"); pthread_mutex_destroy(&dacp_conversation_lock); }