diff --git a/ap2_buffered_audio_processor.c b/ap2_buffered_audio_processor.c index 38ddfd5d..75fa0c0b 100644 --- a/ap2_buffered_audio_processor.c +++ b/ap2_buffered_audio_processor.c @@ -332,7 +332,7 @@ void *rtp_buffered_audio_processor(void *arg) { if (finished == 0) { pthread_cleanup_debug_mutex_lock(&conn->flush_mutex, 25000, - 1); // 25 ms is a long time to wait! + 4); // 25 ms is a long time to wait! if (blocks_read != 0) { if (conn->ap2_immediate_flush_requested != 0) { if (ap2_immediate_flush_requested == 0) { @@ -422,9 +422,12 @@ void *rtp_buffered_audio_processor(void *arg) { } else if (conn->ap2_deferred_flush_requests[f].active != 0) { new_audio_block_needed = 1; debug(3, - "deferred flush of block: %u. flushFromTS: %12u, flushFromSeq: %12u, " + "deferred flush of block: %u, timestamp: %u, SSRC: \"%s\". flushFromTS: %12u, flushFromSeq: %12u, " "flushUntilTS: %12u, flushUntilSeq: %12u, timestamp: %12u.", - seq_no, conn->ap2_deferred_flush_requests[f].flushFromTS, + seq_no, + timestamp, + get_ssrc_name(payload_ssrc), + conn->ap2_deferred_flush_requests[f].flushFromTS, conn->ap2_deferred_flush_requests[f].flushFromSeq, conn->ap2_deferred_flush_requests[f].flushUntilTS, conn->ap2_deferred_flush_requests[f].flushUntilSeq, timestamp); @@ -589,7 +592,7 @@ void *rtp_buffered_audio_processor(void *arg) { uint32_t packet_size = player_put_packet( payload_ssrc, sequence_number_for_player, timestamp, payload_pointer, payload_length, mute, timestamp_difference, conn); - debug(3, "block %u, timestamp %u, length %u sent to the player.", seq_no, + debug(4, "block %u, timestamp %u, length %u sent to the player.", seq_no, timestamp, packet_size); sequence_number_for_player++; // simply increment expected_timestamp = timestamp + packet_size; // for the next time diff --git a/audio_alsa.c b/audio_alsa.c index 2fed54f0..3ce51b70 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -1987,7 +1987,7 @@ static int do_play(void *buf, int samples) { } snd_pcm_state_t prior_state = state; // keep this for afterwards.... - debug(3, "alsa: write %d frames.", samples); + debug(4, "alsa: write %d frames.", samples); ret = alsa_pcm_write(alsa_handle, buf, samples); if (ret == -EIO) { debug(1, "alsa: I/O Error."); @@ -2380,7 +2380,7 @@ static void *alsa_buffer_monitor_thread_code(__attribute__((unused)) void *arg) dither_random_number_store, current_encoded_output_format); ret = do_play(silence, frames_of_silence); - debug(3, "Played %u frames of silence on %u channels, equal to %zu bytes.", + debug(4, "Played %u frames of silence on %u channels, equal to %zu bytes.", frames_of_silence, CHANNELS_FROM_ENCODED_FORMAT(current_encoded_output_format), size_of_silence_buffer); frame_count++; diff --git a/dacp.c b/dacp.c index aeb3ca1f..aade558f 100644 --- a/dacp.c +++ b/dacp.c @@ -517,7 +517,7 @@ void *dacp_monitor_thread_code(__attribute__((unused)) void *na) { while (1) { int result = 0; int32_t the_volume; - pthread_cleanup_debug_mutex_lock(&dacp_server_information_lock, 500000, 2); + pthread_cleanup_debug_mutex_lock(&dacp_server_information_lock, 500000, 4); if (dacp_server.scan_enable == 0) { metadata_hub_modify_prolog(); int ch = (metadata_store.dacp_server_active != 0) || diff --git a/metadata_hub.c b/metadata_hub.c index f643d9c1..db3bac70 100644 --- a/metadata_hub.c +++ b/metadata_hub.c @@ -373,7 +373,7 @@ void metadata_hub_process_metadata(uint32_t type, uint32_t code, char *data, uin vl = vl << 32; // shift them into the correct location uint64_t ul = ntohl(*(uint32_t *)(data + sizeof(uint32_t))); // and the low order 32 bits vl = vl + ul; - debug(3, "MH Item ID seen: \"%" PRIx64 "\" of length %u.", vl, length); + debug(4, "MH Item ID seen: \"%" PRIx64 "\" of length %u.", vl, length); if ((vl != metadata_store.item_id) || (metadata_store.item_id_is_valid == 0)) { metadata_store.item_id = vl; metadata_store.item_id_changed = 1; @@ -528,14 +528,14 @@ void metadata_hub_process_metadata(uint32_t type, uint32_t code, char *data, uin case 'pcen': break; case 'mdst': - debug(3, "MH Metadata stream processing start."); + debug(4, "MH Metadata stream processing start."); metadata_packet_item_changed = 0; break; case 'mden': if (metadata_packet_item_changed != 0) debug(3, "MH Metadata stream processing end with changes."); else - debug(3, "MH Metadata stream processing end without changes."); + debug(4, "MH Metadata stream processing end without changes."); changed = metadata_packet_item_changed; break; case 'PICT': diff --git a/player.c b/player.c index 8f210a1c..c158b43c 100644 --- a/player.c +++ b/player.c @@ -402,7 +402,7 @@ static void swr_alloc_cleanup_handler(void *arg) { } static void av_packet_alloc_cleanup_handler(void *arg) { - debug(3, "av_packet_alloc_cleanup_handler"); + debug(4, "av_packet_alloc_cleanup_handler"); AVPacket **pkt = arg; av_packet_free(pkt); } @@ -1144,7 +1144,7 @@ int64_t avframe_to_audio(rtsp_conn_info *conn, AVFrame *decoded_frame, uint8_t * int number_of_output_samples_expected = swr_get_out_samples(conn->swr, decoded_frame->nb_samples); - debug(3, "A maximum of %d output samples expected for %d input samples.", + debug(4, "A maximum of %d output samples expected for %d input samples.", number_of_output_samples_expected, decoded_frame->nb_samples); // allocate enough space for the required number of output channels // and the number of samples decoded @@ -1155,10 +1155,10 @@ int64_t avframe_to_audio(rtsp_conn_info *conn, AVFrame *decoded_frame, uint8_t * int samples_generated = swr_convert(conn->swr, &pcm_audio, number_of_output_samples_expected, (const uint8_t **)decoded_frame->extended_data, decoded_frame->nb_samples); - debug(3, "conversion time for %u incoming samples: %.3f milliseconds.", decoded_frame->nb_samples, + debug(4, "conversion time for %u incoming samples: %.3f milliseconds.", decoded_frame->nb_samples, (get_absolute_time_in_ns() - conversion_start_time) * 0.000001); if (samples_generated > 0) { - debug(3, "swr generated %d frames of %" PRId64 " channels.", samples_generated, + debug(4, "swr generated %d frames of %" PRId64 " channels.", samples_generated, conn->resampler_output_channels); // samples_generated will be different from // the number of samples input if the output rate is different from the input @@ -2296,7 +2296,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn, int resync_requested) { uint64_t should_be_time; frame_to_local_time(curframe->timestamp, &should_be_time, conn); int64_t time_difference = should_be_time - get_absolute_time_in_ns(); - debug(3, "Check packet from buffer %u, timestamp %u, %f seconds ahead.", conn->ab_read, + debug(4, "Check packet from buffer %u, timestamp %u, %f seconds ahead.", conn->ab_read, curframe->timestamp, 0.000000001 * time_difference); } else { debug(3, "Check packet from buffer %u, empty.", conn->ab_read); @@ -3210,8 +3210,8 @@ int stuff_buffer_soxr_32(int32_t *inptr, int length, sps_format_t l_output_forma }; } - if (packets_processed % 1250 == 0) { - debug(3, + if ((packets_processed % 1250 == 0) && (stat_n > 0)) { + debug(4, "soxr_oneshot execution time in nanoseconds: mean, standard deviation and max " "for %" PRId32 " interpolations in the last " "1250 packets. %10.6f, %10.6f, %10.6f.", @@ -4269,7 +4269,7 @@ void *player_thread_func(void *arg) { output_buffer_delay_time = output_buffer_delay_time / RATE_FROM_ENCODED_FORMAT(config.current_output_configuration); - debug(3, + debug(4, "current_delay: %" PRId64 ", output_buffer_delay_time: %.3f, output rate: %u.", current_delay, output_buffer_delay_time * 0.000000001, RATE_FROM_ENCODED_FORMAT(config.current_output_configuration)); @@ -4352,8 +4352,9 @@ void *player_thread_func(void *arg) { gap_to_fix = -inframe->timestamp_gap; // this is frames at the input rate int64_t gap_to_fix_ns = (gap_to_fix * 1000000000) / conn->input_rate; gap_to_fix = (gap_to_fix_ns * - RATE_FROM_ENCODED_FORMAT(config.current_output_configuration)) / + RATE_FROM_ENCODED_FORMAT(config.current_output_configuration) + 1000000000/2) / 1000000000; // this is frames at the output rate + debug(3, "gap_to_fix: %u frames at input rate, %" PRId64 " frames at output rate.", -inframe->timestamp_gap, gap_to_fix); // debug(3, "due to timstamp gap of %d frames, skip %" PRId64 " output // frames.", inframe->timestamp_gap, gap_to_fix); } @@ -4471,16 +4472,16 @@ void *player_thread_func(void *arg) { amount_to_stuff = -1 * (inbuflength / 350); if (amount_to_stuff == 0) amount_to_stuff = -1; - debug(3, "drop a frame, inbuflength is %d, amount_to_stuff is %d.", + debug(4, "drop a frame, inbuflength is %d, amount_to_stuff is %d.", inbuflength, amount_to_stuff); } else if (centered_sync_error_ns < (-tolerance_ns)) { amount_to_stuff = +1 * (inbuflength / 350); if (amount_to_stuff == 0) amount_to_stuff = 1; - debug(3, "add a frame, inbuflength is %d, amount_to_stuff is %d.", + debug(4, "add a frame, inbuflength is %d, amount_to_stuff is %d.", inbuflength, amount_to_stuff); } else { - debug(3, + debug(4, "error is within tolerance: centered_sync_error_ns: %" PRId64 ", tolerance_ns: %" PRId64 " ns.", centered_sync_error_ns, tolerance_ns); @@ -4490,7 +4491,7 @@ void *player_thread_func(void *arg) { } if (amount_to_stuff) - debug(3, + debug(4, // "stuff: %+d, sync_error: %+5.3f milliseconds.", // amount_to_stuff, sync_error * 1000); "stuff: %+d, sync_errors actual: %+5.3f milliseconds, bufferlength: %d, " @@ -4775,19 +4776,23 @@ void *player_thread_func(void *arg) { frames_to_skip -= play_samples; } else { - char *offset = conn->outbuf; - offset += - frames_to_skip * + + + size_t bytes_to_skip = frames_to_skip * CHANNELS_FROM_ENCODED_FORMAT(config.current_output_configuration) * sps_format_sample_size( FORMAT_FROM_ENCODED_FORMAT(config.current_output_configuration)); - config.output->play(offset, play_samples - frames_to_skip, + + char *play_starting_point = conn->outbuf + bytes_to_skip; + + config.output->play(play_starting_point, play_samples - frames_to_skip, play_samples_are_timed, inframe->timestamp, should_be_time); - debug(3, "skipping the first %u frames in a packet of %u frames.", + debug(3, "skipping the first %u frames (listed below) in a packet of %u frames.", frames_to_skip, play_samples); - debug_print_buffer(3, conn->outbuf, offset - conn->outbuf); + + debug_print_buffer(3, conn->outbuf, bytes_to_skip); frames_played += play_samples - frames_to_skip; frames_to_skip = 0; @@ -4967,7 +4972,7 @@ static void player_send_volume_metadata(uint8_t vol_mode_both, double airplay_vo } void player_volume_without_notification(double airplay_volume, rtsp_conn_info *conn) { - debug_mutex_lock(&conn->volume_control_mutex, 5000, 1); + debug_mutex_lock(&conn->volume_control_mutex, 5000, 4); // first, see if we are hw only, sw only, both with hw attenuation on the top or both with sw // attenuation on top @@ -5149,7 +5154,7 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c double temp_fix_volume = 65536.0 * pow(10, software_attenuation / 2000); if (config.ignore_volume_control == 0) - debug(3, "Software attenuation set to %f, i.e %f out of 65,536, for airplay volume of %f", + debug(4, "Software attenuation set to %f, i.e %f out of 65,536, for airplay volume of %f", software_attenuation, temp_fix_volume, airplay_volume); else debug(3, "Software attenuation set to %f, i.e %f out of 65,536. Volume control is ignored.", @@ -5158,7 +5163,7 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c conn->fix_volume = temp_fix_volume; } if (conn != NULL) - debug(3, "Connection %d: AirPlay Volume set to %.3f, Output Level set to: %.2f dB.", + debug(4, "Connection %d: AirPlay Volume set to %.3f, Output Level set to: %.2f dB.", conn->connection_number, airplay_volume, scaled_attenuation / 100.0); else debug(3, "AirPlay Volume set to %.3f, Output Level set to: %.2f dB. NULL conn.", @@ -5176,7 +5181,7 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c config.output->mute(0); conn->software_mute_enabled = 0; - debug(3, + debug(4, "player_volume_without_notification: volume mode is %d, airplay volume is %.2f, " "software_attenuation dB: %.2f, hardware_attenuation dB: %.2f, muting " "is disabled.", @@ -5185,7 +5190,7 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c // here, store the volume for possible use in the future config.airplay_volume = airplay_volume; conn->own_airplay_volume = airplay_volume; - debug_mutex_unlock(&conn->volume_control_mutex, 3); + debug_mutex_unlock(&conn->volume_control_mutex, 4); } void player_volume(double airplay_volume, rtsp_conn_info *conn) { diff --git a/rtsp.c b/rtsp.c index 52bda460..3bc3420f 100644 --- a/rtsp.c +++ b/rtsp.c @@ -235,7 +235,7 @@ typedef struct { void pc_queue_init(pc_queue *the_queue, char *items, size_t item_size, uint32_t number_of_items, const char *name) { if (name) - debug(2, "Creating metadata queue \"%s\".", name); + debug(4, "Creating metadata queue \"%s\".", name); else debug(1, "Creating an unnamed metadata queue."); pthread_mutex_init(&the_queue->pc_queue_lock, NULL); @@ -290,11 +290,11 @@ int pc_queue_add_item(pc_queue *the_queue, const void *the_stuff, int block) { int rc; if (the_queue) { if (block == 0) { - rc = debug_mutex_lock(&the_queue->pc_queue_lock, 10000, 2); + rc = debug_mutex_lock(&the_queue->pc_queue_lock, 10000, 4); if (rc == EBUSY) return EBUSY; } else - rc = debug_mutex_lock(&the_queue->pc_queue_lock, 50000, 1); + rc = debug_mutex_lock(&the_queue->pc_queue_lock, 50000, 4); if (rc) debug(1, "Error %d (\"%s\") locking for pc_queue_add_item. Block is %d.", rc, strerror(rc), block); @@ -346,7 +346,7 @@ int pc_queue_add_item(pc_queue *the_queue, const void *the_stuff, int block) { int pc_queue_get_item(pc_queue *the_queue, void *the_stuff) { int rc; if (the_queue) { - rc = debug_mutex_lock(&the_queue->pc_queue_lock, 50000, 1); + rc = debug_mutex_lock(&the_queue->pc_queue_lock, 50000, 4); if (rc) debug(1, "metadata queue \"%s\": error locking for pc_queue_get_item", the_queue->name); pthread_cleanup_push(pc_queue_cleanup_handler, (void *)the_queue); @@ -367,7 +367,7 @@ int pc_queue_get_item(pc_queue *the_queue, void *the_stuff) { i = 0; the_queue->toq = i; the_queue->count--; - debug(3, "metadata queue- \"%s\" %d/%d.", the_queue->name, the_queue->count, + debug(4, "metadata queue- \"%s\" %d/%d.", the_queue->name, the_queue->count, the_queue->capacity); rc = pthread_cond_signal(&the_queue->pc_queue_item_removed_signal); if (rc) @@ -531,7 +531,7 @@ static void track_thread(rtsp_conn_info *conn) { die("could not reallocate memory for conns"); } } - debug_mutex_unlock(&conns_lock, 3); + debug_mutex_unlock(&conns_lock, 4); } // note: connection numbers start at 1, so an except_this_one value of zero means "all threads" @@ -575,34 +575,34 @@ void cleanup_threads(void) { int i; int connection_count = 0; // debug(2, "culling threads."); - debug_mutex_lock(&conns_lock, 1000000, 3); + debug_mutex_lock(&conns_lock, 1000000, 4); for (i = 0; i < nconns; i++) { if ((conns[i] != NULL) && (conns[i]->running == 0)) { - debug(3, "found RTSP connection thread %d in a non-running state.", + debug(4, "found RTSP connection thread %d in a non-running state.", conns[i]->connection_number); pthread_join(conns[i]->thread, &retval); - debug(3, "Connection %d: deleted in cleanup.", conns[i]->connection_number); + debug(4, "Connection %d: deleted in cleanup.", conns[i]->connection_number); free(conns[i]); conns[i] = NULL; } if (conns[i] != NULL) { - debug(3, "Airplay Volume for connection %d is %.6f.", conns[i]->connection_number, + debug(4, "Airplay Volume for connection %d is %.6f.", conns[i]->connection_number, suggested_volume(conns[i])); connection_count++; } } - debug_mutex_unlock(&conns_lock, 3); + debug_mutex_unlock(&conns_lock, 4); if (old_connection_count != connection_count) { if (connection_count == 0) { - debug(3, "No active connections."); + debug(4, "No active connections."); } else if (connection_count == 1) - debug(3, "One active connection."); + debug(4, "One active connection."); else - debug(3, "%d active connections.", connection_count); + debug(4, "%d active connections.", connection_count); old_connection_count = connection_count; } - debug(3, "Airplay Volume for new connections is %.6f.", suggested_volume(NULL)); + debug(4, "Airplay Volume for new connections is %.6f.", suggested_volume(NULL)); } // park a null at the line ending, and return the next line pointer @@ -630,12 +630,12 @@ static char *nextline(char *in, int inbuf) { } void msg_retain(rtsp_message *msg) { - int rc = debug_mutex_lock(&reference_counter_lock, 500000, 1); + int rc = debug_mutex_lock(&reference_counter_lock, 500000, 4); if (rc) debug(1, "Error %d locking reference counter lock", rc); if (msg > (rtsp_message *)0x00010000) { msg->referenceCount++; - debug(3, "msg_free increment reference counter message %d to %d.", msg->index_number, + debug(4, "msg_free increment reference counter message %d to %d.", msg->index_number, msg->referenceCount); // debug(1,"msg_retain -- item %d reference count %d.", msg->index_number, msg->referenceCount); rc = pthread_mutex_unlock(&reference_counter_lock); @@ -648,7 +648,7 @@ void msg_retain(rtsp_message *msg) { rtsp_message *msg_init(void) { // no thread cancellation points here - int rc = debug_mutex_lock(&reference_counter_lock, 500000, 1); + int rc = debug_mutex_lock(&reference_counter_lock, 500000, 4); if (rc) debug(1, "Error %d locking reference counter lock", rc); @@ -657,7 +657,7 @@ rtsp_message *msg_init(void) { memset(msg, 0, sizeof(rtsp_message)); msg->referenceCount = 1; // from now on, any access to this must be protected with the lock msg->index_number = msg_indexes++; - debug(3, "msg_init message %d", msg->index_number); + debug(4, "msg_init message %d", msg->index_number); } else { die("msg_init -- can not allocate memory for rtsp_message %d.", msg_indexes); } @@ -731,7 +731,7 @@ void msg_free(rtsp_message **msgh) { rtsp_message *msg = *msgh; msg->referenceCount--; if (msg->referenceCount) - debug(3, "msg_free decrement reference counter message %d to %d", msg->index_number, + debug(4, "msg_free decrement reference counter message %d to %d", msg->index_number, msg->referenceCount); if (msg->referenceCount == 0) { unsigned int i; @@ -747,7 +747,7 @@ void msg_free(rtsp_message **msgh) { index = 0x10000; // ensure it doesn't fold to zero. *msgh = (rtsp_message *)(index); // put a version of the index number of the freed message in here - debug(3, "msg_free freed message %d", msg->index_number); + debug(4, "msg_free freed message %d", msg->index_number); free(msg); } else { // debug(1,"msg_free item %d -- decrement reference to @@ -771,7 +771,7 @@ int msg_handle_line(rtsp_message **pmsg, char *line) { char *sp, *p; sp = NULL; // this is to quieten a compiler warning - debug(3, "RTSP/HTTP Message Received: \"%s\".", line); + debug(4, "RTSP/HTTP Message Received: \"%s\".", line); p = strtok_r(line, " ", &sp); if (!p) @@ -804,7 +804,7 @@ int msg_handle_line(rtsp_message **pmsg, char *line) { *p = 0; p += 2; msg_add_header(msg, line, p); - debug(3, " %s: %s.", line, p); + debug(4, " %s: %s.", line, p); return -1; } else { char *cl = msg_get_header(msg, "Content-Length"); @@ -1042,7 +1042,7 @@ enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn, rtsp_mes debug(1, "Connection %d: rtsp_read_request: can't get a buffer.", conn->connection_number); reply = rtsp_read_request_response_error; } else { - debug(3, "buf is allocated at 0x%" PRIxPTR ".", (uintptr_t)buf); + debug(4, "buf is allocated at 0x%" PRIxPTR ".", (uintptr_t)buf); pthread_cleanup_push(malloc_cleanup, &buf); ssize_t nread; ssize_t inbuf = 0; @@ -1710,7 +1710,7 @@ void handle_flushbuffered(rtsp_conn_info *conn, rtsp_message *req, rtsp_message } else { flushFromValid = 1; plist_get_uint_val(item, &flushFromSeq); - debug(3, "flushFromSeq is %" PRId64 ".", flushFromSeq); + debug(3, "flushFromSeq is %" PRId64 ".", flushFromSeq & 0x7fffff); } item = plist_dict_get_item(messagePlist, "flushFromTS"); @@ -1731,7 +1731,7 @@ void handle_flushbuffered(rtsp_conn_info *conn, rtsp_message *req, rtsp_message debug(1, "Can't find the flushUntilSeq"); } else { plist_get_uint_val(item, &flushUntilSeq); - debug(3, "flushUntilSeq is %" PRId64 ".", flushUntilSeq); + debug(3, "flushUntilSeq is %" PRId64 ".", flushUntilSeq & 0x7fffff); } item = plist_dict_get_item(messagePlist, "flushUntilTS"); @@ -1742,7 +1742,7 @@ void handle_flushbuffered(rtsp_conn_info *conn, rtsp_message *req, rtsp_message debug(3, "flushUntilTS is %" PRId64 ".", flushUntilTS); } - debug_mutex_lock(&conn->flush_mutex, 1000, 1); + debug_mutex_lock(&conn->flush_mutex, 1000, 4); if (flushFromValid == 0) { // an immediate flush is requested @@ -2319,9 +2319,9 @@ void handle_configure(rtsp_conn_info *conn __attribute__((unused)), void handle_feedback(rtsp_conn_info *conn, __attribute__((unused)) rtsp_message *req, __attribute__((unused)) rtsp_message *resp) { - debug(3, "Connection %d: POST %s Content-Length %d", conn->connection_number, req->path, + debug(4, "Connection %d: POST %s Content-Length %d", conn->connection_number, req->path, req->contentlength); - debug_log_rtsp_message(3, NULL, req); + debug_log_rtsp_message(4, NULL, req); int is_playing = 0; int type = 0; @@ -2361,15 +2361,15 @@ void handle_feedback(rtsp_conn_info *conn, __attribute__((unused)) rtsp_message // plist_free(payload_plist); msg_add_header(resp, "Content-Type", "application/x-apple-binary-plist"); - debug_log_rtsp_message(3, "FEEDBACK response:", resp); + debug_log_rtsp_message(4, "FEEDBACK response:", resp); } } void handle_command(rtsp_conn_info *conn, rtsp_message *req, __attribute__((unused)) rtsp_message *resp) { - debug(3, "Connection %d: POST %s Content-Length %d", conn->connection_number, req->path, + debug(4, "Connection %d: POST %s Content-Length %d", conn->connection_number, req->path, req->contentlength); - debug_log_rtsp_message(3, NULL, req); + debug_log_rtsp_message(4, NULL, req); if (rtsp_message_contains_plist(req)) { plist_t command_dict = NULL; plist_from_memory(req->content, req->contentlength, &command_dict); @@ -2403,7 +2403,7 @@ void handle_command(rtsp_conn_info *conn, rtsp_message *req, if (subsidiary_plist) { char *printable_plist = plist_as_xml_text(subsidiary_plist); if (printable_plist) { - debug(3, "\n%s", printable_plist); + debug(4, "Connection %d:\n==\n%s\n==", conn->connection_number, printable_plist); free(printable_plist); } else { debug(1, "Can't print the plist!"); @@ -3857,13 +3857,13 @@ void *metadata_thread_function(__attribute__((unused)) void *ignore) { pthread_cleanup_push(metadata_pack_cleanup_function, (void *)&pack); if (config.metadata_enabled) { if (pack.carrier) { - debug(3, " pipe: type %x, code %x, length %u, message %d.", pack.type, pack.code, + debug(4, " pipe: type %x, code %x, length %u, message %d.", pack.type, pack.code, pack.length, pack.carrier->index_number); } else { - debug(3, " pipe: type %x, code %x, length %u.", pack.type, pack.code, pack.length); + debug(4, " pipe: type %x, code %x, length %u.", pack.type, pack.code, pack.length); } metadata_process(pack.type, pack.code, pack.data, pack.length); - debug(3, " pipe: done."); + debug(4, " pipe: done."); } pthread_cleanup_pop(1); } @@ -3887,18 +3887,18 @@ void *metadata_multicast_thread_function(__attribute__((unused)) void *ignore) { pthread_cleanup_push(metadata_pack_cleanup_function, (void *)&pack); if (config.metadata_enabled) { if (pack.carrier) { - debug(3, + debug(4, " multicast: type " "%x, code %x, length %u, message %d.", pack.type, pack.code, pack.length, pack.carrier->index_number); } else { - debug(3, + debug(4, " multicast: type " "%x, code %x, length %u.", pack.type, pack.code, pack.length); } metadata_multicast_process(pack.type, pack.code, pack.data, pack.length); - debug(3, + debug(4, " multicast: done."); } pthread_cleanup_pop(1); @@ -3924,14 +3924,14 @@ void *metadata_hub_thread_function(__attribute__((unused)) void *ignore) { pc_queue_get_item(&metadata_hub_queue, &pack); pthread_cleanup_push(metadata_pack_cleanup_function, (void *)&pack); if (pack.carrier) { - debug(3, " hub: type %x, code %x, length %u, message %d.", pack.type, + debug(4, " hub: type %x, code %x, length %u, message %d.", pack.type, pack.code, pack.length, pack.carrier->index_number); } else { - debug(3, " hub: type %x, code %x, length %u.", pack.type, pack.code, + debug(4, " hub: type %x, code %x, length %u.", pack.type, pack.code, pack.length); } metadata_hub_process_metadata(pack.type, pack.code, pack.data, pack.length); - debug(3, " hub: done."); + debug(4, " hub: done."); pthread_cleanup_pop(1); } pthread_cleanup_pop(1); // will never happen @@ -4222,7 +4222,7 @@ static void handle_get_parameter(__attribute__((unused)) rtsp_conn_info *conn, r } static void handle_set_parameter(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { - debug(3, "Connection %d: SET_PARAMETER", conn->connection_number); + debug(4, "Connection %d: SET_PARAMETER", conn->connection_number); // if (!req->contentlength) // debug(1, "received empty SET_PARAMETER request."); @@ -4255,7 +4255,7 @@ static void handle_set_parameter(rtsp_conn_info *conn, rtsp_message *req, rtsp_m // not all items have RTP-time stuff in them, which is okay if (!strncmp(ct, "application/x-dmap-tagged", 25)) { - debug(3, "received metadata tags in SET_PARAMETER request."); + debug(4, "received metadata tags in SET_PARAMETER request."); if (p == NULL) debug(1, "Missing RTP-Time info for metadata"); if (p) @@ -5018,7 +5018,7 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { } void msg_cleanup_function(void *arg) { - debug(3, "msg_cleanup_function called 0x%" PRIxPTR ".", (uintptr_t)arg); + debug(4, "msg_cleanup_function called 0x%" PRIxPTR ".", (uintptr_t)arg); msg_free((rtsp_message **)arg); } @@ -5063,18 +5063,18 @@ static void *rtsp_conversation_thread_func(void *pconn) { while (conn->stop == 0) { pthread_testcancel(); - int debug_level = 2; // for printing the request and response + int debug_level = 4; // for printing the request and response // check to see if a conn has been zeroed - debug_mutex_lock(&conns_lock, 1000000, 3); + debug_mutex_lock(&conns_lock, 1000000, 4); int i; for (i = 0; i < nconns; i++) { if ((conns[i] != NULL) && (conns[i]->connection_number == 0)) { debug(1, "conns[%d] has a Connection Number of 0!", i); } } - debug_mutex_unlock(&conns_lock, 3); + debug_mutex_unlock(&conns_lock, 4); reply = rtsp_read_request(conn, &req); if (reply == rtsp_read_request_response_ok) { diff --git a/utilities/buffered_read.c b/utilities/buffered_read.c index 24f93cf7..8e195914 100644 --- a/utilities/buffered_read.c +++ b/utilities/buffered_read.c @@ -34,7 +34,7 @@ ssize_t buffered_read(buffered_tcp_desc *descriptor, void *buf, size_t count, size_t *bytes_remaining) { ssize_t response = -1; - if (debug_mutex_lock(&descriptor->mutex, 50000, 1) != 0) + if (debug_mutex_lock(&descriptor->mutex, 50000, 4) != 0) debug(1, "problem with mutex"); pthread_cleanup_push(mutex_unlock, (void *)&descriptor->mutex); // wipe the slate dlean before reading... @@ -115,7 +115,7 @@ void *buffered_tcp_reader(void *arg) { do { int have_time_to_sleep = 0; - if (debug_mutex_lock(&descriptor->mutex, 500000, 1) != 0) + if (debug_mutex_lock(&descriptor->mutex, 500000, 4) != 0) debug(1, "problem with mutex"); pthread_cleanup_push(mutex_unlock, (void *)&descriptor->mutex); while (descriptor->buffer_occupancy == descriptor->buffer_max_size) { @@ -148,7 +148,7 @@ void *buffered_tcp_reader(void *arg) { nread = recv(fd, descriptor->eoq, bytes_to_request, 0); // debug(1, "Received %d bytes for a buffer size of %d bytes.",nread, // descriptor->buffer_occupancy + nread); - if (debug_mutex_lock(&descriptor->mutex, 50000, 1) != 0) + if (debug_mutex_lock(&descriptor->mutex, 50000, 4) != 0) debug(1, "problem with not empty mutex"); pthread_cleanup_push(mutex_unlock, (void *)&descriptor->mutex); if (nread < 0) {