From 70c72821c9373ceb6d17b4e524b2abf53f0d073d Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Sat, 14 Apr 2018 17:33:45 +0100 Subject: [PATCH 1/6] Add code to skip occasional outgoing and icoming timing and resnd packets to simulate a bad network. Quieten some debug messages. --- player.c | 10 +- rtp.c | 379 +++++++++++++++++++++++++++++-------------------------- 2 files changed, 205 insertions(+), 184 deletions(-) diff --git a/player.c b/player.c index 75d0fbfc..30633ffe 100644 --- a/player.c +++ b/player.c @@ -510,9 +510,9 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp // here, we should check for missing frames if (!conn->ab_buffering) { int j; - for (j = 1; j <= 7; j++) { + for (j = 1; j <= 8; j++) { // check j times, after a short period of has elapsed, assuming 352 frames per packet - int back_step = (((250 * 44100) / 352) / 1000) * (j); // approx 250, 500 and 750 ms + int back_step = (((250 * 44100) / 352) / 1000) * (j); // approx 250 ms intervals int k; for (k = -2; k <= 2; k++) { if (back_step < @@ -528,8 +528,8 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp if (config.disable_resend_requests == 0) { rtp_request_resend(next, 1, conn); // if (j>=3) - debug(1, "Resend request level #%d for packet %u in range %u to %u.", j, next, - conn->ab_read, conn->ab_write); + //debug(2, "Resend request level #%d for packet %u in range %u to %u.", j, next, + // conn->ab_read, conn->ab_write); conn->resend_requests++; } } @@ -1694,7 +1694,7 @@ static void *player_thread_func(void *arg) { // debug(3, "Play frame %d.", play_number); conn->play_number_after_flush++; if (inframe->timestamp == 0) { - debug(1, "Player has a supplied silent frame, (possibly frame %u).", + debug(2, "Player has supplied a silent frame, (possibly frame %u).", SUCCESSOR(conn->last_seqno_read)); conn->last_seqno_read = (SUCCESSOR(conn->last_seqno_read) & 0xffff); // manage the packet out of sequence minder diff --git a/rtp.c b/rtp.c index 9ef7be2c..6f098db1 100644 --- a/rtp.c +++ b/rtp.c @@ -147,7 +147,7 @@ void *rtp_audio_receiver(void *arg) { last_seqno = seqno; // reset warning... } } else { - debug(1, "Audio Receiver -- Retransmitted Audio Data Packet %u received.", seqno); + debug(2, "Audio Receiver -- Retransmitted Audio Data Packet %u received.", seqno); } uint32_t actual_timestamp = ntohl(*(uint32_t *)(pktp + 4)); @@ -372,7 +372,7 @@ void *rtp_control_receiver(void *arg) { pktp = packet + 4; plen -= 4; seq_t seqno = ntohs(*(uint16_t *)(pktp + 2)); - debug(1, "Control Receiver -- Retransmitted Audio Data Packet %u received.", seqno); + debug(2, "Control Receiver -- Retransmitted Audio Data Packet %u received.", seqno); uint32_t actual_timestamp = ntohl(*(uint32_t *)(pktp + 4)); int64_t timestamp = monotonic_timestamp(actual_timestamp, conn); @@ -391,7 +391,7 @@ void *rtp_control_receiver(void *arg) { debug(1, "Control Receiver -- Unknown RTP packet of type 0x%02X length %d, ignored.", packet[1], nread); } else { - debug(1, "Control Receiver -- dropping a packet to simulate a bad network."); + debug(2, "Control Receiver -- dropping a packet to simulate a bad network."); } } else { debug(1, "Control Receiver -- error receiving a packet."); @@ -457,11 +457,19 @@ void *rtp_timing_sender(void *arg) { if (conn->timing_sender_stop != 0) { break; } - if (sendto(conn->timing_socket, &req, sizeof(req), 0, - (struct sockaddr *)&conn->rtp_client_timing_socket, msgsize) == -1) { - char em[1024]; - strerror_r(errno, em, sizeof(em)); - debug(1, "Error %d using send-to to the timing socket: \"%s\".", errno, em); + + if ((config.diagnostic_drop_packet_fraction == 0.0) || + (drand48() > config.diagnostic_drop_packet_fraction)) { + + if (sendto(conn->timing_socket, &req, sizeof(req), 0, + (struct sockaddr *)&conn->rtp_client_timing_socket, msgsize) == -1) { + char em[1024]; + strerror_r(errno, em, sizeof(em)); + debug(1, "Error %d using send-to to the timing socket: \"%s\".", errno, em); + } + + } else { + debug(2, "Timing Sender Thread -- dropping outgoing packet to simulate bad network."); } request_number++; @@ -517,199 +525,207 @@ void *rtp_timing_receiver(void *arg) { break; } nread = recv(conn->timing_socket, packet, sizeof(packet), 0); - arrival_time = get_absolute_time_in_fp(); - // clock_gettime(CLOCK_MONOTONIC,&att); if (nread >= 0) { - // ssize_t plen = nread; - // debug(1,"Packet Received on Timing Port."); - if (packet[1] == 0xd3) { // timing reply - /* - char obf[4096]; - char *obfp = obf; - int obfc; - for (obfc=0;obfc config.diagnostic_drop_packet_fraction)) { - // arrival_time = ((uint64_t)att.tv_sec<<32)+((uint64_t)att.tv_nsec<<32)/1000000000; - // departure_time = ((uint64_t)dtt.tv_sec<<32)+((uint64_t)dtt.tv_nsec<<32)/1000000000; + arrival_time = get_absolute_time_in_fp(); + // clock_gettime(CLOCK_MONOTONIC,&att); - return_time = arrival_time - conn->departure_time; + // ssize_t plen = nread; + // debug(1,"Packet Received on Timing Port."); + if (packet[1] == 0xd3) { // timing reply + /* + char obf[4096]; + char *obfp = obf; + int obfc; + for (obfc=0;obfc> 32; + // arrival_time = ((uint64_t)att.tv_sec<<32)+((uint64_t)att.tv_nsec<<32)/1000000000; + // departure_time = ((uint64_t)dtt.tv_sec<<32)+((uint64_t)dtt.tv_nsec<<32)/1000000000; - if (rtus < 300000) { + return_time = arrival_time - conn->departure_time; - // debug(2,"Synchronisation ping return time is %f milliseconds.",(rtus*1.0)/1000); + uint64_t rtus = (return_time * 1000000) >> 32; - // distant_receive_time = - // ((uint64_t)ntohl(*((uint32_t*)&packet[16])))<<32+ntohl(*((uint32_t*)&packet[20])); + if (rtus < 300000) { - distant_receive_time = (uint64_t)nctohl(&packet[16]) << 32; - distant_receive_time += nctohl(&packet[20]); + // debug(2,"Synchronisation ping return time is %f milliseconds.",(rtus*1.0)/1000); - // distant_transmit_time = - // ((uint64_t)ntohl(*((uint32_t*)&packet[24])))<<32+ntohl(*((uint32_t*)&packet[28])); + // distant_receive_time = + // ((uint64_t)ntohl(*((uint32_t*)&packet[16])))<<32+ntohl(*((uint32_t*)&packet[20])); - distant_transmit_time = (uint64_t)nctohl(&packet[24]) << 32; - distant_transmit_time += nctohl(&packet[28]); + distant_receive_time = (uint64_t)nctohl(&packet[16]) << 32; + distant_receive_time += nctohl(&packet[20]); - // processing_time = distant_transmit_time - distant_receive_time; + // distant_transmit_time = + // ((uint64_t)ntohl(*((uint32_t*)&packet[24])))<<32+ntohl(*((uint32_t*)&packet[28])); - // debug(1,"Return trip time: %lluuS, remote processing time: - // %lluuS.",(return_time*1000000)>>32,(processing_time*1000000)>>32); + distant_transmit_time = (uint64_t)nctohl(&packet[24]) << 32; + distant_transmit_time += nctohl(&packet[28]); - uint64_t local_time_by_remote_clock = distant_transmit_time + return_time / 2; + // processing_time = distant_transmit_time - distant_receive_time; - unsigned int cc; - for (cc = time_ping_history - 1; cc > 0; cc--) { - conn->time_pings[cc] = conn->time_pings[cc - 1]; - conn->time_pings[cc].dispersion = - (conn->time_pings[cc].dispersion * 110) / - 100; // make the dispersions 'age' by this rational factor - } - // these are for diagnostics only -- not used - conn->time_pings[0].local_time = arrival_time; - conn->time_pings[0].remote_time = distant_transmit_time; + // debug(1,"Return trip time: %lluuS, remote processing time: + // %lluuS.",(return_time*1000000)>>32,(processing_time*1000000)>>32); - conn->time_pings[0].local_to_remote_difference = - local_time_by_remote_clock - arrival_time; - conn->time_pings[0].dispersion = return_time; - if (conn->time_ping_count < time_ping_history) - conn->time_ping_count++; + uint64_t local_time_by_remote_clock = distant_transmit_time + return_time / 2; - uint64_t local_time_chosen = arrival_time; - - // uint64_t remote_time_chosen = distant_transmit_time; - // now pick the timestamp with the lowest dispersion - uint64_t l2rtd = conn->time_pings[0].local_to_remote_difference; - uint64_t tld = conn->time_pings[0].dispersion; - // chosen = 0; - for (cc = 1; cc < conn->time_ping_count; cc++) - if (conn->time_pings[cc].dispersion < tld) { - l2rtd = conn->time_pings[cc].local_to_remote_difference; - // chosen = cc; - tld = conn->time_pings[cc].dispersion; - local_time_chosen = conn->time_pings[cc].local_time; - // remote_time_chosen = conn->time_pings[cc].remote_time; + unsigned int cc; + for (cc = time_ping_history - 1; cc > 0; cc--) { + conn->time_pings[cc] = conn->time_pings[cc - 1]; + conn->time_pings[cc].dispersion = + (conn->time_pings[cc].dispersion * 110) / + 100; // make the dispersions 'age' by this rational factor } - // int64_t ji; + // these are for diagnostics only -- not used + conn->time_pings[0].local_time = arrival_time; + conn->time_pings[0].remote_time = distant_transmit_time; - if (conn->time_ping_count > 1) { - if (l2rtd > conn->local_to_remote_time_difference) { - local_to_remote_time_jitters = - local_to_remote_time_jitters + l2rtd - conn->local_to_remote_time_difference; - // ji = l2rtd - conn->local_to_remote_time_difference; + conn->time_pings[0].local_to_remote_difference = + local_time_by_remote_clock - arrival_time; + conn->time_pings[0].dispersion = return_time; + if (conn->time_ping_count < time_ping_history) + conn->time_ping_count++; + + uint64_t local_time_chosen = arrival_time; + + // uint64_t remote_time_chosen = distant_transmit_time; + // now pick the timestamp with the lowest dispersion + uint64_t l2rtd = conn->time_pings[0].local_to_remote_difference; + uint64_t tld = conn->time_pings[0].dispersion; + // chosen = 0; + for (cc = 1; cc < conn->time_ping_count; cc++) + if (conn->time_pings[cc].dispersion < tld) { + l2rtd = conn->time_pings[cc].local_to_remote_difference; + // chosen = cc; + tld = conn->time_pings[cc].dispersion; + local_time_chosen = conn->time_pings[cc].local_time; + // remote_time_chosen = conn->time_pings[cc].remote_time; + } + // int64_t ji; + + if (conn->time_ping_count > 1) { + if (l2rtd > conn->local_to_remote_time_difference) { + local_to_remote_time_jitters = + local_to_remote_time_jitters + l2rtd - conn->local_to_remote_time_difference; + // ji = l2rtd - conn->local_to_remote_time_difference; + } else { + local_to_remote_time_jitters = + local_to_remote_time_jitters + conn->local_to_remote_time_difference - l2rtd; + // ji = -(conn->local_to_remote_time_difference - l2rtd); + } + local_to_remote_time_jitters_count += 1; + } + // uncomment below to print jitter between client's clock and oour clock + // int64_t rtus = (tld*1000000)>>32; ji = (ji*1000000)>>32; debug(1,"Choosing time + // difference + // with dispersion of %lld us with delta of %lld us",rtus,ji); + + conn->local_to_remote_time_difference = l2rtd; + if (first_local_to_remote_time_difference == 0) { + first_local_to_remote_time_difference = conn->local_to_remote_time_difference; + // first_local_to_remote_time_difference_time = get_absolute_time_in_fp(); + } + + // int64_t clock_drift; + // int64_t clock_drift_in_usec; + // double clock_drift_ppm = 0.0; + if (first_local_time == 0) { + first_local_time = local_time_chosen; + // first_remote_time = remote_time_chosen; + // clock_drift = 0; } else { - local_to_remote_time_jitters = - local_to_remote_time_jitters + conn->local_to_remote_time_difference - l2rtd; - // ji = -(conn->local_to_remote_time_difference - l2rtd); + // uint64_t local_time_change = local_time_chosen - first_local_time; + // uint64_t remote_time_change = remote_time_chosen - first_remote_time; + + /* + if (remote_time_change >= local_time_change) + clock_drift = remote_time_change - local_time_change; + else + clock_drift = -(local_time_change - remote_time_change); + */ + /* + if (clock_drift >= 0) + clock_drift_in_usec = (clock_drift * 1000000) >> 32; + else + clock_drift_in_usec = -(((-clock_drift) * 1000000) >> 32); + */ + + // clock_drift_ppm = (1.0 * clock_drift_in_usec) / (local_time_change >> 32); } - local_to_remote_time_jitters_count += 1; - } - // uncomment below to print jitter between client's clock and oour clock - // int64_t rtus = (tld*1000000)>>32; ji = (ji*1000000)>>32; debug(1,"Choosing time - // difference - // with dispersion of %lld us with delta of %lld us",rtus,ji); - conn->local_to_remote_time_difference = l2rtd; - if (first_local_to_remote_time_difference == 0) { - first_local_to_remote_time_difference = conn->local_to_remote_time_difference; - // first_local_to_remote_time_difference_time = get_absolute_time_in_fp(); - } + int64_t source_drift_usec; + if (conn->play_segment_reference_frame != 0) { + int64_t reference_timestamp; + uint64_t reference_timestamp_time, remote_reference_timestamp_time; + get_reference_timestamp_stuff(&reference_timestamp, &reference_timestamp_time, + &remote_reference_timestamp_time, conn); + uint64_t frame_difference = 0; + if (reference_timestamp >= conn->play_segment_reference_frame) + frame_difference = + (uint64_t)reference_timestamp - (uint64_t)conn->play_segment_reference_frame; + else // rollover + frame_difference = (uint64_t)reference_timestamp + 0x100000000 - + (uint64_t)conn->play_segment_reference_frame; + uint64_t frame_time_difference_calculated = + (((uint64_t)frame_difference << 32) / 44100); + uint64_t frame_time_difference_actual = + remote_reference_timestamp_time - + conn->play_segment_reference_frame_remote_time; // this is all done by reference + // to + // the + // sources' system clock + // debug(1,"%llu frames since play started, %llu usec calculated, %llu usec + // actual",frame_difference, (frame_time_difference_calculated*1000000)>>32, + // (frame_time_difference_actual*1000000)>>32); + if (frame_time_difference_calculated >= + frame_time_difference_actual) // i.e. if the time it should have taken to send the + // packets is greater than the actual time difference + // measured on the source clock + // then the source DAC's clock is running fast relative to the source system clock + source_drift_usec = frame_time_difference_calculated - frame_time_difference_actual; + else + // otherwise the source DAC's clock is running slow relative to the source system + // clock + source_drift_usec = + -(frame_time_difference_actual - frame_time_difference_calculated); + } else + source_drift_usec = 0; + source_drift_usec = (source_drift_usec * 1000000) >> 32; // turn it to microseconds - // int64_t clock_drift; - // int64_t clock_drift_in_usec; - // double clock_drift_ppm = 0.0; - if (first_local_time == 0) { - first_local_time = local_time_chosen; - // first_remote_time = remote_time_chosen; - // clock_drift = 0; + // long current_delay = 0; + // if (config.output->delay) { + // config.output->delay(¤t_delay); + //} + // Useful for troubleshooting: + // debug(1, "clock_drift_ppm %f\tchosen %5d\tsource_drift_usec + // %10.1lld\treturn_time_in_usec + // %10.1llu", + // clock_drift_ppm, + // chosen, + //(session_corrections*1000000)/44100, + // current_delay, + // source_drift_usec, + // buffer_occupancy, + //(return_time*1000000)>>32); } else { - // uint64_t local_time_change = local_time_chosen - first_local_time; - // uint64_t remote_time_change = remote_time_chosen - first_remote_time; - - /* - if (remote_time_change >= local_time_change) - clock_drift = remote_time_change - local_time_change; - else - clock_drift = -(local_time_change - remote_time_change); - */ - /* - if (clock_drift >= 0) - clock_drift_in_usec = (clock_drift * 1000000) >> 32; - else - clock_drift_in_usec = -(((-clock_drift) * 1000000) >> 32); - */ - - // clock_drift_ppm = (1.0 * clock_drift_in_usec) / (local_time_change >> 32); + debug(1, "Time ping turnaround time: %lld us -- it looks like a timing ping was lost.", + rtus); } - - int64_t source_drift_usec; - if (conn->play_segment_reference_frame != 0) { - int64_t reference_timestamp; - uint64_t reference_timestamp_time, remote_reference_timestamp_time; - get_reference_timestamp_stuff(&reference_timestamp, &reference_timestamp_time, - &remote_reference_timestamp_time, conn); - uint64_t frame_difference = 0; - if (reference_timestamp >= conn->play_segment_reference_frame) - frame_difference = - (uint64_t)reference_timestamp - (uint64_t)conn->play_segment_reference_frame; - else // rollover - frame_difference = (uint64_t)reference_timestamp + 0x100000000 - - (uint64_t)conn->play_segment_reference_frame; - uint64_t frame_time_difference_calculated = - (((uint64_t)frame_difference << 32) / 44100); - uint64_t frame_time_difference_actual = - remote_reference_timestamp_time - - conn->play_segment_reference_frame_remote_time; // this is all done by reference to - // the - // sources' system clock - // debug(1,"%llu frames since play started, %llu usec calculated, %llu usec - // actual",frame_difference, (frame_time_difference_calculated*1000000)>>32, - // (frame_time_difference_actual*1000000)>>32); - if (frame_time_difference_calculated >= - frame_time_difference_actual) // i.e. if the time it should have taken to send the - // packets is greater than the actual time difference - // measured on the source clock - // then the source DAC's clock is running fast relative to the source system clock - source_drift_usec = frame_time_difference_calculated - frame_time_difference_actual; - else - // otherwise the source DAC's clock is running slow relative to the source system - // clock - source_drift_usec = - -(frame_time_difference_actual - frame_time_difference_calculated); - } else - source_drift_usec = 0; - source_drift_usec = (source_drift_usec * 1000000) >> 32; // turn it to microseconds - - // long current_delay = 0; - // if (config.output->delay) { - // config.output->delay(¤t_delay); - //} - // Useful for troubleshooting: - // debug(1, "clock_drift_ppm %f\tchosen %5d\tsource_drift_usec - // %10.1lld\treturn_time_in_usec - // %10.1llu", - // clock_drift_ppm, - // chosen, - //(session_corrections*1000000)/44100, - // current_delay, - // source_drift_usec, - // buffer_occupancy, - //(return_time*1000000)>>32); } else { - debug(1, "Time ping turnaround time: %lld us -- it looks like a timing ping was lost.", - rtus); + debug(1, "Timing port -- Unknown RTP packet of type 0x%02X length %d.", packet[1], nread); } } else { - debug(1, "Timing port -- Unknown RTP packet of type 0x%02X length %d.", packet[1], nread); + debug(2, "Timing Receiver Thread -- dropping incoming packet to simulate a bad network."); } } else { debug(1, "Timing receiver -- error receiving a packet."); @@ -958,14 +974,19 @@ void rtp_request_resend(seq_t first, uint32_t count, rtsp_conn_info *conn) { if ((conn->rtp_time_of_last_resend_request_error_fp) || ((time_of_sending_fp - conn->rtp_time_of_last_resend_request_error_fp) > resend_error_backoff_time)) { - if (sendto(conn->audio_socket, req, sizeof(req), 0, - (struct sockaddr *)&conn->rtp_client_control_socket, msgsize) == -1) { - char em[1024]; - strerror_r(errno, em, sizeof(em)); - debug(1, "Error %d using send-to to an audio socket: \"%s\". ", errno, em); - conn->rtp_time_of_last_resend_request_error_fp = time_of_sending_fp; + if ((config.diagnostic_drop_packet_fraction == 0.0) || + (drand48() > config.diagnostic_drop_packet_fraction)) { + if (sendto(conn->audio_socket, req, sizeof(req), 0, + (struct sockaddr *)&conn->rtp_client_control_socket, msgsize) == -1) { + char em[1024]; + strerror_r(errno, em, sizeof(em)); + debug(1, "Error %d using send-to to an audio socket: \"%s\". ", errno, em); + conn->rtp_time_of_last_resend_request_error_fp = time_of_sending_fp; + } else { + conn->rtp_time_of_last_resend_request_error_fp = 0; + } } else { - conn->rtp_time_of_last_resend_request_error_fp = 0; + debug(2, "rtp_request_resend dropping outgoing packet to simulate a bad netowrk."); } } } else { From ed0ce06e822301f7892ff72c9ecca12e7f9468e5 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Mon, 16 Apr 2018 10:00:22 +0100 Subject: [PATCH 2/6] Fix a few tiny typos and rationalise some debug message levels. --- dacp.c | 2 +- mdns_avahi.c | 2 +- rtp.c | 4 ++-- 3 files changed, 4 insertions(+), 4 deletions(-) diff --git a/dacp.c b/dacp.c index 63001113..7b01a325 100644 --- a/dacp.c +++ b/dacp.c @@ -156,7 +156,7 @@ int dacp_send_command(const char *command, char **body, ssize_t *bodysize) { hints.ai_family = AF_UNSPEC; hints.ai_socktype = SOCK_STREAM; - // debug(1, "DHCP port string is \"%s:%s\".", server, portstring); + // debug(1, "DACP port string is \"%s:%s\".", server, portstring); int ires = getaddrinfo(server, portstring, &hints, &res); if (ires) { diff --git a/mdns_avahi.c b/mdns_avahi.c index f231eecd..6756c1ea 100644 --- a/mdns_avahi.c +++ b/mdns_avahi.c @@ -448,7 +448,7 @@ void avahi_dacp_dont_monitor(void *userdata) { free((char *)(dbs)); debug(3, "DACP monitor successfully stopped"); } else { - debug(1, "DHCP Monitor is not running."); + debug(1, "DACP Monitor is not running."); } } diff --git a/rtp.c b/rtp.c index 6f098db1..066b11f8 100644 --- a/rtp.c +++ b/rtp.c @@ -165,7 +165,7 @@ void *rtp_audio_receiver(void *arg) { (drand48() > config.diagnostic_drop_packet_fraction)) player_put_packet(seqno, actual_timestamp, timestamp, pktp, plen, conn); else - debug(3, "Dropping audio packet %u to simulate a bad connection.", seqno); + debug(2, "Dropping audio packet %u to simulate a bad connection.", seqno); continue; } if (type == 0x56 && seqno == 0) { @@ -986,7 +986,7 @@ void rtp_request_resend(seq_t first, uint32_t count, rtsp_conn_info *conn) { conn->rtp_time_of_last_resend_request_error_fp = 0; } } else { - debug(2, "rtp_request_resend dropping outgoing packet to simulate a bad netowrk."); + debug(2, "Dropping resend request packet to simulate a bad netowrk."); } } } else { From e002da60332b643332f1c256f40c000d9568a2fc Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Mon, 16 Apr 2018 10:05:02 +0100 Subject: [PATCH 3/6] Fix a tiny typo. --- rtp.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/rtp.c b/rtp.c index 066b11f8..aa3a7e0c 100644 --- a/rtp.c +++ b/rtp.c @@ -986,7 +986,7 @@ void rtp_request_resend(seq_t first, uint32_t count, rtsp_conn_info *conn) { conn->rtp_time_of_last_resend_request_error_fp = 0; } } else { - debug(2, "Dropping resend request packet to simulate a bad netowrk."); + debug(2, "Dropping resend request packet to simulate a bad network."); } } } else { From 75041c52cdbbbbf6398de09317e5c7a2f933323a Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Mon, 16 Apr 2018 19:19:32 +0100 Subject: [PATCH 4/6] quieten message when dacp scanner does down --- mdns.c | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/mdns.c b/mdns.c index 855f3c3e..e45dacc5 100644 --- a/mdns.c +++ b/mdns.c @@ -106,9 +106,7 @@ void mdns_unregister(void) { void *mdns_dacp_monitor(char *dacp_id) { void *reply = NULL; - if ((dacp_id==NULL) || (*dacp_id=='\0')) - debug(1, "A null or zero-length DACP-ID string was provided for monitoring -- nothing done."); - else { + if ((dacp_id!=NULL) && (*dacp_id!='\0')) { if ((config.mdns) && (config.mdns->mdns_dacp_monitor)) { reply = config.mdns->mdns_dacp_monitor(dacp_id); if (reply == NULL) { From cf6b98df5f2712fdea9754a8609d58770f154cfd Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Tue, 17 Apr 2018 16:01:28 +0100 Subject: [PATCH 5/6] Only drop metadata if the dacp server transitions fron available to unavailable rahter than if it's unavailable. Add a few sample dbus-send commands. --- documents/sample dbus commands | 5 +++ metadata_hub.c | 72 ++++++++++++++++++---------------- metadata_hub.h | 4 ++ 3 files changed, 48 insertions(+), 33 deletions(-) diff --git a/documents/sample dbus commands b/documents/sample dbus commands index a0306880..0a7c398d 100644 --- a/documents/sample dbus commands +++ b/documents/sample dbus commands @@ -15,4 +15,9 @@ dbus-send --print-reply --system --dest=org.gnome.ShairportSync /org/gnome/Shair # Include Elapsed Time in Log Entries dbus-send --print-reply --system --dest=org.gnome.ShairportSync /org/gnome/ShairportSync org.freedesktop.DBus.Properties.Set string:org.gnome.ShairportSync.Diagnostics string:ElapsedTime variant:boolean:true +# Play using regular Remote Control +dbus-send --system --print-reply --type=method_call --dest=org.gnome.ShairportSync '/org/gnome/ShairportSync' org.gnome.ShairportSync.RemoteControl.Play +#Remote Control commands include: Play, Pause, PlayPause, Resume, Stop, Next, Previous, VolumeUp, VolumeDown, ToggleMute, FastForward, Rewind, ShuffleSongs +# Set Volume using Advanced Remote Control +dbus-send --system --print-reply --type=method_call --dest=org.gnome.ShairportSync '/org/gnome/ShairportSync' org.gnome.ShairportSync.AdvancedRemoteControl.SetVolume int32:50 \ No newline at end of file diff --git a/metadata_hub.c b/metadata_hub.c index ff7eef46..4f3fc0f8 100644 --- a/metadata_hub.c +++ b/metadata_hub.c @@ -139,10 +139,18 @@ void run_metadata_watchers(void) { void metadata_hub_modify_epilog(int modified) { // always run this after changing an entry or a sequence of entries in the metadata_hub // debug(1, "unlocking metadata hub for writing"); + + // Here, we check to see if the dacp_server is transitioning between active and inactive + // If it's going off, we will release track metadata and image stuff + // If it's already off, we do nothing + // If it's transitioning to on, we will record it for use later. + int m = 0; - if (metadata_store.dacp_server_active == 0) { - // debug(1,"player_stop release track metadata and artwork"); - // + int tm = modified; + + if ((metadata_store.dacp_server_active == 0) && + (metadata_store.dacp_server_has_been_active != 0)) { + debug(1, "dacp_scanner going inactive -- release track metadata and artwork"); if (metadata_store.track_metadata) { m = 1; metadata_hub_release_track_metadata(metadata_store.track_metadata); @@ -154,10 +162,12 @@ void metadata_hub_modify_epilog(int modified) { } if (m) debug(2, "Release track metadata after dacp server goes inactive."); - modified += m; + tm += m; } + metadata_store.dacp_server_has_been_active = + metadata_store.dacp_server_active; // set the scanner_has_been_active now. pthread_rwlock_unlock(&metadata_hub_re_lock); - if (modified) { + if (tm) { run_metadata_watchers(); } } @@ -392,8 +402,7 @@ void metadata_hub_process_metadata(uint32_t type, uint32_t code, char *data, uin track_metadata->sort_name = strndup(data, length); debug(2, "MH Sort Name set to: \"%s\"", track_metadata->sort_name); } else { - debug(1, - "No track metadata memory allocated when sort name description received!"); + debug(1, "No track metadata memory allocated when sort name description received!"); } break; case 'assa': @@ -401,8 +410,7 @@ void metadata_hub_process_metadata(uint32_t type, uint32_t code, char *data, uin track_metadata->sort_artist = strndup(data, length); debug(2, "MH Sort Artist set to: \"%s\"", track_metadata->sort_artist); } else { - debug(1, - "No track metadata memory allocated when sort artist description received!"); + debug(1, "No track metadata memory allocated when sort artist description received!"); } break; case 'assu': @@ -410,8 +418,7 @@ void metadata_hub_process_metadata(uint32_t type, uint32_t code, char *data, uin track_metadata->sort_album = strndup(data, length); debug(2, "MH Sort Album set to: \"%s\"", track_metadata->sort_album); } else { - debug(1, - "No track metadata memory allocated when sort album description received!"); + debug(1, "No track metadata memory allocated when sort album description received!"); } break; case 'assc': @@ -419,32 +426,31 @@ void metadata_hub_process_metadata(uint32_t type, uint32_t code, char *data, uin track_metadata->sort_composer = strndup(data, length); debug(2, "MH Sort Composer set to: \"%s\"", track_metadata->sort_composer); } else { - debug(1, - "No track metadata memory allocated when sort composer description received!"); + debug(1, "No track metadata memory allocated when sort composer description received!"); } break; - default: - /* - { - char typestring[5]; - *(uint32_t *)typestring = htonl(type); - typestring[4] = 0; - char codestring[5]; - *(uint32_t *)codestring = htonl(code); - codestring[4] = 0; - char *payload; - if (length < 2048) - payload = strndup(data, length); - else - payload = NULL; - debug(1, "MH \"%s\" \"%s\" (%d bytes): \"%s\".", typestring, codestring, length, payload); - if (payload) - free(payload); - } - */ + default: + /* + { + char typestring[5]; + *(uint32_t *)typestring = htonl(type); + typestring[4] = 0; + char codestring[5]; + *(uint32_t *)codestring = htonl(code); + codestring[4] = 0; + char *payload; + if (length < 2048) + payload = strndup(data, length); + else + payload = NULL; + debug(1, "MH \"%s\" \"%s\" (%d bytes): \"%s\".", typestring, codestring, length, + payload); + if (payload) + free(payload); + } + */ break; - } } else if (type == 'ssnc') { switch (code) { diff --git a/metadata_hub.h b/metadata_hub.h index 29825555..8d003703 100644 --- a/metadata_hub.h +++ b/metadata_hub.h @@ -62,6 +62,10 @@ typedef struct metadata_bundle { int advanced_dacp_server_active; // true if there's a reachable DACP server with iTunes // capabilitiues // ; false otherwise + int dacp_server_has_been_active; // basically this is a delayed version of dacp_server_active, + // used detect transitions between server activity being on or off + // e.g. to reease metadata when a server goes inactive, but not if it's permanently + // inactive. enum play_status_type play_status; enum shuffle_status_type shuffle_status; enum repeat_status_type repeat_status; From ae94daf259d7d109ac19f6934b6fc7d90d3c3a76 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Tue, 17 Apr 2018 21:08:29 +0100 Subject: [PATCH 6/6] Add a little more detail to the resend requests --- player.c | 8 ++++---- rtp.c | 2 +- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/player.c b/player.c index 30633ffe..c333e318 100644 --- a/player.c +++ b/player.c @@ -528,8 +528,8 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp if (config.disable_resend_requests == 0) { rtp_request_resend(next, 1, conn); // if (j>=3) - //debug(2, "Resend request level #%d for packet %u in range %u to %u.", j, next, - // conn->ab_read, conn->ab_write); + debug(2, "Resend request level #%d for packet %u in range %u to %u.", j, next, + conn->ab_read, conn->ab_write); conn->resend_requests++; } } @@ -1694,8 +1694,8 @@ static void *player_thread_func(void *arg) { // debug(3, "Play frame %d.", play_number); conn->play_number_after_flush++; if (inframe->timestamp == 0) { - debug(2, "Player has supplied a silent frame, (possibly frame %u).", - SUCCESSOR(conn->last_seqno_read)); + debug(1, "Player has supplied a silent frame, (possibly frame %u) for play number %d.", + SUCCESSOR(conn->last_seqno_read),play_number); conn->last_seqno_read = (SUCCESSOR(conn->last_seqno_read) & 0xffff); // manage the packet out of sequence minder config.output->play(silence, conn->max_frames_per_packet * conn->output_sample_ratio); diff --git a/rtp.c b/rtp.c index aa3a7e0c..b0099910 100644 --- a/rtp.c +++ b/rtp.c @@ -953,7 +953,7 @@ void clear_reference_timestamp(rtsp_conn_info *conn) { void rtp_request_resend(seq_t first, uint32_t count, rtsp_conn_info *conn) { if (conn->rtp_running) { // if (!request_sent) { - debug(2, "requesting resend of %d packets starting at %u.", count, first); + // debug(2, "requesting resend of %d packets starting at %u.", count, first); // request_sent = 1; //}