Clean up code for the silent lead-in on a non-syncing back end e.g. a pipe. Clean up pipe creation and initial opening and associated error messages. Fix error with warning/die messages. Tidy up some debug messages.

This commit is contained in:
Mike Brady
2020-06-05 17:22:53 +01:00
parent a4d5927527
commit dfd90bac6b
7 changed files with 243 additions and 188 deletions
+14 -2
View File
@@ -51,8 +51,19 @@ static void start(__attribute__((unused)) int sample_rate,
// "ENXIO O_NONBLOCK | O_WRONLY is set, the named file is a FIFO, and no process has the FIFO
// open for reading."
fd = try_to_open_pipe_for_writing(pipename);
}
fd = try_to_open_pipe_for_writing(pipename);
// we check that it's not a "real" error. From the "man 2 open" page:
// "ENXIO O_NONBLOCK | O_WRONLY is set, the named file is a FIFO, and no process has the FIFO
// open for reading." Which is okay.
if ((fd == -1) && (errno != ENXIO)) {
char errorstring[1024];
strerror_r(errno, (char *)errorstring, sizeof(errorstring));
debug(1, "audio_pipe start -- error %d (\"%s\") opening pipe: \"%s\".", errno,
(char *)errorstring, pipename);
warn("can not open audio pipe -- error %d (\"%s\") opening pipe: \"%s\".", errno,
(char *)errorstring, pipename);
}
}
static int play(void *buf, int samples) {
// if the file is not open, try to open it.
@@ -74,6 +85,7 @@ static int play(void *buf, int samples) {
static void stop(void) {
// Don't close the pipe just because a play session has stopped.
}
static int init(int argc, char **argv) {
+9 -9
View File
@@ -283,10 +283,10 @@ char *generate_preliminary_string(char *buffer, size_t buffer_length, double tss
insertion_point = insertion_point + strlen(insertion_point);
space_remaining = space_remaining - strlen(insertion_point);
}
if (prefix) {
snprintf(insertion_point, space_remaining, "%s", prefix);
insertion_point = insertion_point + strlen(insertion_point);
space_remaining = space_remaining - strlen(insertion_point);
}
return insertion_point;
}
@@ -308,7 +308,8 @@ void _die(const char *filename, const int linenumber, const char *format, ...) {
1.0 * time_since_last_debug_message / 1000000000, filename,
linenumber, " *fatal error: ");
} else {
s = b;
strncpy(b, "fatal error: ", sizeof(b));
s = b+strlen(b);
}
va_list args;
va_start(args, format);
@@ -336,7 +337,8 @@ void _warn(const char *filename, const int linenumber, const char *format, ...)
1.0 * time_since_last_debug_message / 1000000000, filename,
linenumber, " *warning: ");
} else {
s = b;
strncpy(b, "warning: ", sizeof(b));
s = b+strlen(b);
}
va_list args;
va_start(args, format);
@@ -1135,27 +1137,25 @@ int try_to_open_pipe_for_writing(const char* pathname) {
// if it succeeds, it sets it to blocking.
// if not, it returns -1.
char errorstring[1024];
int fdis = open(pathname, O_WRONLY | O_NONBLOCK); // open it in non blocking mode first
// we check that it's not a "real" error. From the "man 2 open" page:
// "ENXIO O_NONBLOCK | O_WRONLY is set, the named file is a FIFO, and no process has the FIFO
// open for reading." Which is okay.
// This is checked by the caller.
if ((fdis == -1) && (errno != ENXIO)) {
strerror_r(errno, (char *)errorstring, sizeof(errorstring));
debug(1, "try_to_open_pipe -- error %d (\"%s\") opening pipe: \"%s\".", errno,
(char *)errorstring, pathname);
} else
if (fdis >= 0) {
// now we switch to blocking mode
int flags = fcntl(fdis, F_GETFL);
if ((flags == -1)) {
char errorstring[1024];
strerror_r(errno, (char *)errorstring, sizeof(errorstring));
debug(1, "try_to_open_pipe -- error %d (\"%s\") getting flags of pipe: \"%s\".", errno,
(char *)errorstring, pathname);
} else {
flags = fcntl(fdis, F_SETFL,flags & ~O_NONBLOCK);
if (flags == -1) {
char errorstring[1024];
strerror_r(errno, (char *)errorstring, sizeof(errorstring));
debug(1, "try_to_open_pipe -- error %d (\"%s\") unsetting NONBLOCK of pipe: \"%s\".", errno,
(char *)errorstring, pathname);
+2 -2
View File
@@ -1050,14 +1050,14 @@ static void on_dbus_name_acquired(GDBusConnection *connection, const gchar *name
static void on_dbus_name_lost_again(__attribute__((unused)) GDBusConnection *connection,
__attribute__((unused)) const gchar *name,
__attribute__((unused)) gpointer user_data) {
warn("Could not acquire a Shairport Sync native D-Bus interface \"%s\" on the %s bus.", name,
warn("could not acquire a Shairport Sync native D-Bus interface \"%s\" on the %s bus.", name,
(config.dbus_service_bus_type == DBT_session) ? "session" : "system");
}
static void on_dbus_name_lost(__attribute__((unused)) GDBusConnection *connection,
__attribute__((unused)) const gchar *name,
__attribute__((unused)) gpointer user_data) {
// debug(1, "Could not acquire a Shairport Sync native D-Bus interface \"%s\" on the %s bus --
// debug(1, "could not acquire a Shairport Sync native D-Bus interface \"%s\" on the %s bus --
// will try adding the process "
// "number to the end of it.",
// name, (config.dbus_service_bus_type == DBT_session) ? "session" : "system");
+1 -1
View File
@@ -345,7 +345,7 @@ static void on_mpris_name_acquired(GDBusConnection *connection, const gchar *nam
static void on_mpris_name_lost_again(__attribute__((unused)) GDBusConnection *connection,
const gchar *name,
__attribute__((unused)) gpointer user_data) {
warn("Could not acquire an MPRIS interface named \"%s\" on the %s bus.", name,
warn("could not acquire an MPRIS interface named \"%s\" on the %s bus.", name,
(config.mpris_service_bus_type == DBT_session) ? "session" : "system");
}
+5 -5
View File
@@ -50,7 +50,7 @@ void on_message(__attribute__((unused)) struct mosquitto *mosq,
memcpy(payload, msg->payload, msg->payloadlen);
payload[msg->payloadlen] = 0;
debug(1, "[MQTT]: received Message on topic %s: %s\n", msg->topic, payload);
debug(2, "[MQTT]: received Message on topic %s: %s\n", msg->topic, payload);
// All recognized commands
char *commands[] = {"command", "beginff", "beginrew", "mutetoggle", "nextitem",
@@ -63,7 +63,7 @@ void on_message(__attribute__((unused)) struct mosquitto *mosq,
while (commands[it] != NULL) {
if ((size_t)msg->payloadlen >= strlen(commands[it]) &&
strncmp(msg->payload, commands[it], strlen(commands[it])) == 0) {
debug(1, "[MQTT]: DACP Command: %s\n", commands[it]);
debug(2, "[MQTT]: DACP Command: %s\n", commands[it]);
send_simple_dacp_command(commands[it]);
break;
}
@@ -74,13 +74,13 @@ void on_message(__attribute__((unused)) struct mosquitto *mosq,
void on_disconnect(__attribute__((unused)) struct mosquitto *mosq,
__attribute__((unused)) void *userdata, __attribute__((unused)) int rc) {
connected = 0;
debug(1, "[MQTT]: disconnected");
debug(2, "[MQTT]: disconnected");
}
void on_connect(struct mosquitto *mosq, __attribute__((unused)) void *userdata,
__attribute__((unused)) int rc) {
connected = 1;
debug(1, "[MQTT]: connected");
debug(2, "[MQTT]: connected");
// subscribe if requested
if (config.mqtt_enable_remote) {
@@ -95,7 +95,7 @@ void mqtt_publish(char *topic, char *data, uint32_t length) {
char fulltopic[strlen(config.mqtt_topic) + strlen(topic) + 3];
snprintf(fulltopic, strlen(config.mqtt_topic) + strlen(topic) + 2, "%s/%s", config.mqtt_topic,
topic);
debug(1, "[MQTT]: publishing under %s", fulltopic);
debug(2, "[MQTT]: publishing under %s", fulltopic);
int rc;
if ((rc = mosquitto_publish(global_mosq, NULL, fulltopic, length, data, 0, 0)) !=
+185 -155
View File
@@ -1040,8 +1040,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) {
#endif
// Here, calculate when we should start playing. We need to know when to allow the
// packets to be sent to the player.
// We will send packets of silence from now until that time and then we will send the
// first packet, which will be followed by the subsequent packets.
// every second or so, we get a reference on when a particular packet should be
// played.
@@ -1087,175 +1086,170 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) {
}
}
if (conn->first_packet_time_to_play != 0) {
// recalculate conn->first_packet_time_to_play -- the latency might change
// Now that we know the timing of the first packet...
if (config.output->delay) {
// and that the output device is capable of synchronization...
uint64_t should_be_time;
uint32_t effective_latency = conn->latency;
// We may send packets of
// silence from now until the time the first audio packet should be sent
// and then we will send the first packet, which will be followed by
// the subsequent packets.
// here, we figure out whether and what silence to send.
switch (get_and_check_effective_latency(conn, &effective_latency,
config.audio_backend_latency_offset)) {
case -1:
if (conn->unachievable_audio_backend_latency_offset_notified == 0) {
warn("Negative latency! A latency of %d frames requested by the player, when "
"combined with an audio_backend_latency_offset of %f seconds, would make the "
"overall latency negative. The audio_backend_latency_offset setting is "
"ignored.",
conn->latency, config.audio_backend_latency_offset);
config.audio_backend_latency_offset = 0; // set it to zero
conn->unachievable_audio_backend_latency_offset_notified = 1;
};
break;
case 1:
if (conn->unachievable_audio_backend_latency_offset_notified == 0) {
warn("An audio_backend_latency_offset of %f seconds may exceed the frame buffering "
"capacity -- the setting is ignored.",
config.audio_backend_latency_offset);
config.audio_backend_latency_offset = 0; // set it to zero;
conn->unachievable_audio_backend_latency_offset_notified = 1;
};
break;
default:
break;
}
uint64_t should_be_time;
uint32_t effective_latency = conn->latency;
frame_to_local_time(conn->first_packet_timestamp +
effective_latency, // this will go modulo 2^32
&should_be_time, conn);
switch (get_and_check_effective_latency(conn, &effective_latency,
config.audio_backend_latency_offset)) {
case -1:
if (conn->unachievable_audio_backend_latency_offset_notified == 0) {
warn("Negative latency! A latency of %d frames requested by the player, when "
"combined with an audio_backend_latency_offset of %f seconds, would make the "
"overall latency negative. The audio_backend_latency_offset setting is "
"ignored.",
conn->latency, config.audio_backend_latency_offset);
config.audio_backend_latency_offset = 0; // set it to zero
conn->unachievable_audio_backend_latency_offset_notified = 1;
};
break;
case 1:
if (conn->unachievable_audio_backend_latency_offset_notified == 0) {
warn("An audio_backend_latency_offset of %f seconds may exceed the frame buffering "
"capacity -- the setting is ignored.",
config.audio_backend_latency_offset);
config.audio_backend_latency_offset = 0; // set it to zero;
conn->unachievable_audio_backend_latency_offset_notified = 1;
};
break;
default:
break;
}
conn->first_packet_time_to_play = should_be_time;
// readjust first packet time to play
frame_to_local_time(conn->first_packet_timestamp +
effective_latency, // this will go modulo 2^32
&should_be_time, conn);
if (local_time_now > conn->first_packet_time_to_play) {
uint64_t lateness = local_time_now - conn->first_packet_time_to_play;
debug(2, "Gone past starting time by %" PRIu64 " nanoseconds.", lateness);
// have_sent_prefiller_silence = 1;
conn->ab_buffering = 0;
} else {
// do some calculations
int64_t lead_time = conn->first_packet_time_to_play - local_time_now;
if ((config.audio_backend_silent_lead_in_time_auto == 1) ||
(lead_time <=
(int64_t)(config.audio_backend_silent_lead_in_time * (int64_t)1000000000))) {
debug(3, "Lead time: %" PRId64 ".", lead_time);
if (config.output->delay) { // if the output device has a delay function
debug(3, "Checking");
int resp = 0;
dac_delay = 0;
if (have_sent_prefiller_silence != 0)
resp = config.output->delay(&dac_delay);
if (resp == 0) {
int64_t gross_frame_gap =
((conn->first_packet_time_to_play - local_time_now) * config.output_rate) /
1000000000;
int64_t exact_frame_gap = gross_frame_gap - dac_delay;
int64_t frames_needed_to_maintain_desired_buffer =
(int64_t)(config.audio_backend_buffer_desired_length * config.output_rate) -
dac_delay;
// below, remember that exact_frame_gap and
// frames_needed_to_maintain_desired_buffer could both be negative
int64_t fs = frames_needed_to_maintain_desired_buffer;
conn->first_packet_time_to_play = should_be_time;
// if there isn't enough time to have the desired buffer size
if (exact_frame_gap <= frames_needed_to_maintain_desired_buffer) {
fs = conn->max_frames_per_packet * 2;
}
if (local_time_now > conn->first_packet_time_to_play) {
uint64_t lateness = local_time_now - conn->first_packet_time_to_play;
debug(2, "Gone past starting time by %" PRIu64 " nanoseconds.", lateness);
conn->ab_buffering = 0;
} else {
// do some calculations
int64_t lead_time = conn->first_packet_time_to_play - local_time_now;
if ((config.audio_backend_silent_lead_in_time_auto == 1) ||
(lead_time <=
(int64_t)(config.audio_backend_silent_lead_in_time * (int64_t)1000000000))) {
debug(1, "Lead time: %" PRId64 " nanoseconds.", lead_time);
int resp = 0;
dac_delay = 0;
if (have_sent_prefiller_silence != 0)
resp = config.output->delay(&dac_delay); // we know the output device must have a delay function
if (resp == 0) {
int64_t gross_frame_gap =
((conn->first_packet_time_to_play - local_time_now) * config.output_rate) /
1000000000;
int64_t exact_frame_gap = gross_frame_gap - dac_delay;
int64_t frames_needed_to_maintain_desired_buffer =
(int64_t)(config.audio_backend_buffer_desired_length * config.output_rate) -
dac_delay;
// below, remember that exact_frame_gap and
// frames_needed_to_maintain_desired_buffer could both be negative
int64_t fs = frames_needed_to_maintain_desired_buffer;
// if we are very close to the end of buffering, i.e. within to frame-lengths,
// add the remaining silence needed and end buffering
if (exact_frame_gap <= conn->max_frames_per_packet * 2) {
fs = exact_frame_gap;
if (fs > first_frame_early_bias)
fs = fs - first_frame_early_bias; // deliberately make the first packet a tiny bit early so that the player may compensate for it at the last minute
conn->ab_buffering = 0;
}
void *silence;
if (fs > 0) {
silence = malloc(conn->output_bytes_per_frame * fs);
if (silence == NULL)
debug(1, "Failed to allocate %d byte silence buffer.", fs);
else {
// generate frames of silence with dither if necessary
conn->previous_random_number =
generate_zero_frames(silence, fs, config.output_format,
conn->enable_dither, conn->previous_random_number);
config.output->play(silence, fs);
debug(3, "Sent %" PRId64 " frames of silence", fs);
free(silence);
have_sent_prefiller_silence = 1;
}
}
} else {
// if there isn't enough time to have the desired buffer size
if (exact_frame_gap <= frames_needed_to_maintain_desired_buffer) {
fs = conn->max_frames_per_packet * 2;
}
if (resp == sps_extra_code_output_stalled) {
if (conn->unfixable_error_reported == 0) {
conn->unfixable_error_reported = 1;
if (config.cmd_unfixable) {
command_execute(config.cmd_unfixable, "output_device_stalled", 1);
} else {
warn("an unrecoverable error, \"output_device_stalled\", has been "
"detected.",
conn->connection_number);
}
}
} else {
debug(2, "Unexpected response to getting dac delay: %d.", resp);
}
}
} else {
// no delay function on back end -- just send the prefiller silence
// debug(2,"Back end has no delay function.");
// send the appropriate prefiller here...
// if we are very close to the end of buffering, i.e. within two frame-lengths,
// add the remaining silence needed and end buffering
if (exact_frame_gap <= conn->max_frames_per_packet * 2) {
fs = exact_frame_gap;
if (fs > first_frame_early_bias)
fs = fs - first_frame_early_bias; // deliberately make the first packet a tiny bit early so that the player may compensate for it at the last minute
conn->ab_buffering = 0;
}
void *silence;
if (fs > 0) {
silence = malloc(conn->output_bytes_per_frame * fs);
if (silence == NULL)
debug(1, "Failed to allocate %d byte silence buffer.", fs);
else {
// generate frames of silence with dither if necessary
conn->previous_random_number =
generate_zero_frames(silence, fs, config.output_format,
conn->enable_dither, conn->previous_random_number);
config.output->play(silence, fs);
debug(1, "Sent %" PRId64 " frames of silence", fs);
free(silence);
have_sent_prefiller_silence = 1;
}
}
} else {
void *silence;
if (lead_time != 0) {
int64_t frame_gap = (lead_time * config.output_rate) / 1000000000;
// debug(1,"%d frames needed.",frame_gap);
while (frame_gap > 0) {
ssize_t fs = config.output_rate / 10;
if (fs > frame_gap)
fs = frame_gap;
if (resp == sps_extra_code_output_stalled) {
if (conn->unfixable_error_reported == 0) {
conn->unfixable_error_reported = 1;
if (config.cmd_unfixable) {
command_execute(config.cmd_unfixable, "output_device_stalled", 1);
} else {
warn("an unrecoverable error, \"output_device_stalled\", has been "
"detected.",
conn->connection_number);
}
}
} else {
debug(2, "Unexpected response to getting dac delay: %d.", resp);
}
}
}
}
} else {
// if the output device doesn't have a delay, we simply send the lead-in
int64_t lead_time = conn->first_packet_time_to_play - local_time_now; // negative if we are late
void *silence;
int64_t frame_gap = (lead_time * config.output_rate) / 1000000000;
// debug(1,"%d frames needed.",frame_gap);
while (frame_gap > 0) {
ssize_t fs = config.output_rate / 10;
if (fs > frame_gap)
fs = frame_gap;
silence = malloc(conn->output_bytes_per_frame * fs);
if (silence == NULL)
debug(1, "Failed to allocate %d frame silence buffer.", fs);
else {
// debug(1, "No delay function -- outputting %d frames of silence.", fs);
conn->previous_random_number =
generate_zero_frames(silence, fs, config.output_format,
conn->enable_dither, conn->previous_random_number);
config.output->play(silence, fs);
free(silence);
}
frame_gap -= fs;
}
}
have_sent_prefiller_silence = 1;
conn->ab_buffering = 0;
}
}
}
}
if (conn->ab_buffering == 0) {
/*
// note the time of the playing of the first frame
uint64_t reference_timestamp_time; // don't need this...
get_reference_timestamp_stuff(&conn->play_segment_reference_frame,
&reference_timestamp_time,
&conn->play_segment_reference_frame_remote_time, conn);
conn->play_segment_reference_frame *= conn->output_sample_ratio;
*/
silence = malloc(conn->output_bytes_per_frame * fs);
if (silence == NULL)
debug(1, "Failed to allocate %d frame silence buffer.", fs);
else {
// debug(1, "No delay function -- outputting %d frames of silence.", fs);
conn->previous_random_number =
generate_zero_frames(silence, fs, config.output_format,
conn->enable_dither, conn->previous_random_number);
config.output->play(silence, fs);
free(silence);
}
frame_gap -= fs;
}
conn->ab_buffering = 0;
}
}
#ifdef CONFIG_METADATA
debug(2, "prsm");
send_ssnc_metadata('prsm', NULL, 0,
0); // "resume", but don't wait if the queue is locked
if (conn->ab_buffering == 0) {
debug(2, "prsm");
send_ssnc_metadata('prsm', NULL, 0,
0); // "resume", but don't wait if the queue is locked
}
#endif
}
}
}
}
// Here, we work out whether to release a packet or wait
// We release a buffer when the time is right.
// We release a packet when the time is right.
// To work out when the time is right, we need to take account of (1) the actual time the packet
// should be released,
@@ -2107,10 +2101,18 @@ void *player_thread_func(void *arg) {
// frames from then onwards
inbuflength *= conn->output_sample_ratio;
/*
uint32_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); // types okay
*/
// nt is the rtp timestamp of the first frame of the current packet of
// frames from the source.
// multiply it by the output frame ratio to get, effectively, the rtp timestamp
// of the first frame of the corresponding packet of output frames.
uint64_t nt;
nt = inframe->given_timestamp; // uint32_t to int64_t
nt = nt * conn->output_sample_ratio;
@@ -2529,8 +2531,36 @@ void *player_thread_func(void *arg) {
*/
}
} else {
// if there is no delay procedure, or it's not working or not allowed, there can be no
// synchronising
// if there is no delay procedure, then we should be sending the packet
// to the output at the time determined by
// the packet's time to play + requested latency + requested offset.
/*
// This is just for checking during development
uint32_t should_be_frame_32;
local_time_to_frame(local_time_now, &should_be_frame_32, conn);
// int64_t should_be_frame = ((int64_t)should_be_frame_32) * conn->output_sample_ratio;
int32_t ilatency = (int32_t)((config.audio_backend_latency_offset - config.audio_backend_buffer_desired_length) * conn->input_rate) + conn->latency;
if (ilatency < 0)
debug(1,"incorrect latency %d.", ilatency);
int32_t idelay = (int32_t)(should_be_frame_32 - inframe->given_timestamp);
idelay = idelay - ilatency;
debug(2,"delay is %d input frames.", idelay);
*/
// if this is the first frame, see if it's close to when it's supposed to be
// release, which will be its time plus latency and any offset_time
if (at_least_one_frame_seen_this_session == 0) {
at_least_one_frame_seen_this_session = 1;
}
play_samples =
stuff_buffer_basic_32((int32_t *)conn->tbuf, inbuflength, config.output_format,
conn->outbuf, 0, conn->enable_dither, conn);
+27 -14
View File
@@ -1306,19 +1306,6 @@ void metadata_create_multicast_socket(void) {
}
}
}
size_t pl = strlen(config.metadata_pipename) + 1;
char *path = malloc(pl + 1);
snprintf(path, pl + 1, "%s", config.metadata_pipename);
mode_t oldumask = umask(000);
if (mkfifo(path, 0666) && errno != EEXIST)
die("Could not create metadata FIFO %s", path);
free(path);
umask(oldumask);
}
void metadata_delete_multicast_socket(void) {
@@ -1331,7 +1318,6 @@ void metadata_delete_multicast_socket(void) {
}
void metadata_open(void) {
if (config.metadata_enabled == 0)
return;
@@ -1563,6 +1549,33 @@ void metadata_hub_thread_cleanup_function(__attribute__((unused)) void *arg) {
}
void *metadata_hub_thread_function(__attribute__((unused)) void *ignore) {
// create the fifo, if necessary
size_t pl = strlen(config.metadata_pipename) + 1;
char *path = malloc(pl + 1);
snprintf(path, pl + 1, "%s", config.metadata_pipename);
mode_t oldumask = umask(000);
if (mkfifo(path, 0644) && errno != EEXIST)
die("Could not create metadata pipe \"%s\".", path);
umask(oldumask);
debug(1, "metadata pipe name is \"%s\".", path);
// try to open it
fd = try_to_open_pipe_for_writing(path);
// we check that it's not a "real" error. From the "man 2 open" page:
// "ENXIO O_NONBLOCK | O_WRONLY is set, the named file is a FIFO, and no process has the FIFO
// open for reading." Which is okay.
if ((fd == -1) && (errno != ENXIO)) {
char errorstring[1024];
strerror_r(errno, (char *)errorstring, sizeof(errorstring));
debug(1, "metadata_hub_thread_function -- error %d (\"%s\") opening pipe: \"%s\".", errno,
(char *)errorstring, path);
warn("can not open metadata pipe -- error %d (\"%s\") opening pipe: \"%s\".", errno,
(char *)errorstring, path);
}
free(path);
// create a pc_queue for passing information to a threaded metadata handler
pc_queue_init(&metadata_hub_queue, (char *)&metadata_hub_queue_items, sizeof(metadata_package),
metadata_hub_queue_size, "hub");