diff --git a/.github/workflows/check_classic_mac_basic.yml b/.github/workflows/check_classic_mac_basic.yml index ae322e04..44f0def6 100644 --- a/.github/workflows/check_classic_mac_basic.yml +++ b/.github/workflows/check_classic_mac_basic.yml @@ -9,9 +9,7 @@ on: jobs: build: - - runs-on: macos-15 - + runs-on: macos-latest steps: - uses: actions/checkout@v6.0.2 - name: Install Dependencies diff --git a/.github/workflows/docker-on-push-tag-or-pr.yaml b/.github/workflows/docker-on-push-tag-or-pr.yaml index 9ebee0a2..11129949 100644 --- a/.github/workflows/docker-on-push-tag-or-pr.yaml +++ b/.github/workflows/docker-on-push-tag-or-pr.yaml @@ -59,7 +59,7 @@ jobs: fi - name: Login to Docker Registry - uses: docker/login-action@v3.7.0 + uses: docker/login-action@v4.0.0 with: registry: ${{ secrets.DOCKER_REGISTRY }} username: ${{ secrets.DOCKER_REGISTRY_USER }} @@ -67,13 +67,13 @@ jobs: if: needs.docker-vars.outputs.push_docker_image == 'true' - name: Set up QEMU - uses: docker/setup-qemu-action@v3.7.0 + uses: docker/setup-qemu-action@v4.0.0 - name: Set up Docker Buildx - uses: docker/setup-buildx-action@v3.12.0 + uses: docker/setup-buildx-action@v4.0.0 - name: Build and push ${{ matrix.name }} - uses: docker/build-push-action@v6.19.2 + uses: docker/build-push-action@v7.0.0 env: registry_and_name: ${{ secrets.DOCKER_REGISTRY }}/${{ secrets.DOCKER_IMAGE_NAME }} with: diff --git a/README.md b/README.md index 7aaeaea8..211ce56f 100644 --- a/README.md +++ b/README.md @@ -16,7 +16,7 @@ Shairport Sync does not support AirPlay video or photo streaming. * Next Steps and Advanced Topics are [here](ADVANCED%20TOPICS/README.md). * Runtime settings are documented [here](scripts/shairport-sync.conf). * Build configuration options are detailed in [CONFIGURATION FLAGS.md](CONFIGURATION%20FLAGS.md). -* The `man` page, detailing command line options, is [here](https://htmlpreview.github.io/?https://github.com/mikebrady/shairport-sync/blob/master/man/shairport-sync.html). +* The `man` page, detailing command line options, is [here](https://raw.githack.com/mikebrady/shairport-sync/master/man/shairport-sync.1.xml). * Some advanced topics and developed in [ADVANCED TOPICS](https://github.com/mikebrady/shairport-sync/tree/master/ADVANCED%20TOPICS). # Features diff --git a/ap2_buffered_audio_processor.c b/ap2_buffered_audio_processor.c index 38ddfd5d..30f3b00f 100644 --- a/ap2_buffered_audio_processor.c +++ b/ap2_buffered_audio_processor.c @@ -198,6 +198,8 @@ void *rtp_buffered_audio_processor(void *arg) { int packets_played_in_this_sequence = 0; int play_enabled = 0; + + int very_early_packets_signalled = 0; // double requested_lead_time = 0.0; // normal lead time minimum -- maybe it should be about 0.1 // wait until our timing information is valid @@ -332,7 +334,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) { @@ -368,7 +370,7 @@ void *rtp_buffered_audio_processor(void *arg) { } else { - debug(3, "immediate flush of block %u until block %u", seq_no, + debug(4, "immediate flush of block %u until block %u", seq_no, conn->ap2_immediate_flush_until_sequence_number); ap2_immediate_flush_requested = 1; new_audio_block_needed = 1; // @@ -421,10 +423,13 @@ void *rtp_buffered_audio_processor(void *arg) { debug(2, "immediate flush was %s.", ap2_immediate_flush_requested == 0 ? "off" : "on"); } 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, " + debug(4, + "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); @@ -441,27 +446,37 @@ void *rtp_buffered_audio_processor(void *arg) { // debug(1,"player buffer size and occupancy: %u and %u", player_buffer_size, // player_buffer_occupancy); - // If we are playing and there is room in the player buffer, go ahead and decode the block + // If we are playing and there is room in the player buffer, and the block it not too + // early, go ahead and decode the block // and send it to the player. Otherwise, keep the block and sleep for a while. - if ((play_enabled != 0) && - (((1.0 * player_buffer_occupancy * conn->frames_per_packet) / conn->input_rate) <= - config.audio_decoded_buffer_desired_length)) { - uint64_t buffer_should_be_time; - frame_to_local_time(timestamp, &buffer_should_be_time, conn); + // calculate if there is room in the decoded audio buffer... + int audio_decoded_buffer_below_desired_length = ((1.0 * player_buffer_occupancy * conn->frames_per_packet) / conn->input_rate) <= config.audio_decoded_buffer_desired_length; + uint64_t buffer_should_be_time; + + int have_valid_time = (frame_to_local_time(timestamp, &buffer_should_be_time, conn) == 0); + + // calculate the lead time to make sure it's not too early... + int64_t lead_time = buffer_should_be_time - get_absolute_time_in_ns(); + + if ((play_enabled != 0) && (have_valid_time != 0) && + (audio_decoded_buffer_below_desired_length != 0) && + (lead_time * 1E-9 < (config.audio_decoded_buffer_desired_length + 0.1))) { + + very_early_packets_signalled = 0; //reset very early packet warning signaller + // try to identify blocks that are timed to before the last buffer, and drop 'em int64_t time_from_last_buffer_time = buffer_should_be_time - previous_buffer_should_be_time; if ((packets_played_in_this_sequence == 0) || (time_from_last_buffer_time > 0)) { - int64_t lead_time = buffer_should_be_time - get_absolute_time_in_ns(); + payload_length = 0; if (ssrc_is_recognised(payload_ssrc) != 0) { // prepare_decoding_chain(conn, payload_ssrc); unsigned long long new_payload_length = 0; payload_pointer = m + leading_free_space_length; - if ((lead_time < (int64_t)30000000000L) && - (lead_time >= 0)) { // only decipher the packet if it's not too late or too early + if (lead_time >= 0) { // only decipher the packet if it's not too late int response = -1; // guess that there is a problem if (conn->session_key != NULL) { unsigned char nonce[12]; @@ -589,7 +604,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 @@ -620,6 +635,11 @@ void *rtp_buffered_audio_processor(void *arg) { } new_audio_block_needed = 1; // the block has been used up and is no longer current } else { + if ((have_valid_time != 0) && (very_early_packets_signalled == 0) && (lead_time * 1E-9 > (config.audio_decoded_buffer_desired_length + 0.2))) { + debug(1, "incoming frame suddenly (?) has a lead time of %f seconds, with a desired decoded buffer length of %f.", 1.0 * lead_time * 1E-9, config.audio_decoded_buffer_desired_length); + very_early_packets_signalled = 1; + } + usleep(20000); // wait for a while } } diff --git a/audio_alsa.c b/audio_alsa.c index 2fed54f0..b105457c 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -1668,7 +1668,7 @@ static int set_mute_state() { } close_mixer(); } - debug_mutex_unlock(&alsa_mixer_mutex, 3); // release the mutex + debug_mutex_unlock(&alsa_mixer_mutex, 4); // release the mutex pthread_cleanup_pop(0); // release the mutex pthread_setcancelstate(oldState, NULL); return response; @@ -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."); @@ -2163,7 +2163,7 @@ static int play(void *buf, int samples, __attribute__((unused)) int sample_type, } static void flush(void) { - pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 1); + pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 4); if (alsa_backend_state != abm_disconnected) { // must be playing or connected... // do nothing for a flush if config.keep_dac_busy is true if (config.keep_dac_busy == 0) { @@ -2172,7 +2172,7 @@ static void flush(void) { } else { debug(3, "alsa: flush() -- called on a disconnected alsa backend"); } - debug_mutex_unlock(&alsa_mutex, 3); + debug_mutex_unlock(&alsa_mutex, 4); pthread_cleanup_pop(0); // release the mutex } @@ -2194,7 +2194,7 @@ static void do_volume(double vol) { // caller is assumed to have the alsa_mutex int oldState; pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable set_volume = vol; - pthread_cleanup_debug_mutex_lock(&alsa_mixer_mutex, 1000, 1); + pthread_cleanup_debug_mutex_lock(&alsa_mixer_mutex, 1000, 4); if (volume_set_request && (open_mixer() == 0)) { if (has_softvol) { if (ctl && elem_id) { @@ -2224,7 +2224,7 @@ static void do_volume(double vol) { // caller is assumed to have the alsa_mutex volume_set_request = 0; // any external request that has been made is now satisfied close_mixer(); } - debug_mutex_unlock(&alsa_mixer_mutex, 3); + debug_mutex_unlock(&alsa_mixer_mutex, 4); pthread_cleanup_pop(0); // release the mutex pthread_setcancelstate(oldState, NULL); } @@ -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/bonjour_strings.c b/bonjour_strings.c index 81942fa6..19d63e98 100644 --- a/bonjour_strings.c +++ b/bonjour_strings.c @@ -79,7 +79,8 @@ void build_bonjour_strings(__attribute((unused)) rtsp_conn_info *conn) { txt_records[entry_number++] = "cn=0,1"; txt_records[entry_number++] = "da=true"; txt_records[entry_number++] = "et=0,1"; - + if (config.password != NULL) + txt_records[entry_number++] = "pw=true"; uint64_t features_hi = config.airplay_features; features_hi = (features_hi >> 32) & 0xffffffff; uint64_t features_lo = config.airplay_features; @@ -136,7 +137,7 @@ void build_bonjour_strings(__attribute((unused)) rtsp_conn_info *conn) { txt_records[entry_number++] = "cn=0,1"; txt_records[entry_number++] = "ch=2"; txt_records[entry_number++] = "txtvers=1"; - if (config.password == 0) + if (config.password == NULL) txt_records[entry_number++] = "pw=false"; else txt_records[entry_number++] = "pw=true"; diff --git a/configure.ac b/configure.ac index 7ca02886..f354846b 100644 --- a/configure.ac +++ b/configure.ac @@ -1,7 +1,7 @@ # Process this file with autoconf to produce a configure script. AC_PREREQ([2.50]) -AC_INIT([shairport-sync], [5.0.1], [4265913+mikebrady@users.noreply.github.com]) +AC_INIT([shairport-sync], [5.0.2], [4265913+mikebrady@users.noreply.github.com]) : ${CFLAGS="-O3"} : ${CXXFLAGS="-O3"} AM_INIT_AUTOMAKE([subdir-objects]) 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/mpris-service.c b/mpris-service.c index e903e661..b7877a98 100644 --- a/mpris-service.c +++ b/mpris-service.c @@ -167,7 +167,7 @@ void mpris_metadata_watcher(struct metadata_bundle *argc, __attribute__((unused) */ // Build the metadata array - debug(2, "Build metadata"); + debug(4, "Build metadata"); GVariantBuilder *dict_builder = g_variant_builder_new(G_VARIANT_TYPE("a{sv}")); // Add in the artwork URI if it exists. diff --git a/player.c b/player.c index 8f210a1c..e15de80e 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 @@ -1449,10 +1449,10 @@ uint32_t player_put_packet(uint32_t ssrc, seq_t seqno, uint32_t actual_timestamp // ignore a request to flush that has been made before the first packet... if (conn->packet_count == 0) { - debug_mutex_lock(&conn->flush_mutex, 1000, 1); + debug_mutex_lock(&conn->flush_mutex, 1000, 4); conn->flush_requested = 0; conn->flush_rtp_timestamp = 0; - debug_mutex_unlock(&conn->flush_mutex, 3); + debug_mutex_unlock(&conn->flush_mutex, 4); } pthread_cleanup_debug_mutex_lock(&conn->ab_mutex, 30000, 0); @@ -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(4, "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, " @@ -4538,9 +4539,9 @@ void *player_thread_func(void *arg) { inframe->timestamp, centered_sync_error_time * 1000, occ); unsigned int s; for (s = 0; s < conn->sync_samples_count; s++) { - debug(3, "sample: %u, value: %.3f ms", s, sync_samples[s] * 0.000001); + debug(4, "sample: %u, value: %.3f ms", s, sync_samples[s] * 0.000001); } - debug(3, "sync_history_length: %u, samples_count: %u, sample_index: %u", + debug(4, "sync_history_length: %u, samples_count: %u, sample_index: %u", sync_history_length, conn->sync_samples_count, last_sample_index); } sync_error_out_of_bounds = 0; @@ -4767,7 +4768,7 @@ void *player_thread_func(void *arg) { if (frames_to_skip > (unsigned int)play_samples) { debug(3, "skipping a packet of %u frames.", play_samples); debug_print_buffer( - 3, conn->outbuf, + 4, conn->outbuf, play_samples * CHANNELS_FROM_ENCODED_FORMAT(config.current_output_configuration) * sps_format_sample_size(FORMAT_FROM_ENCODED_FORMAT( @@ -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(4, "skipping the first %u frames in a packet of %u frames.", frames_to_skip, play_samples); - debug_print_buffer(3, conn->outbuf, offset - conn->outbuf); + + debug_print_buffer(4, 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/rtp.c b/rtp.c index d72568c2..79032ede 100644 --- a/rtp.c +++ b/rtp.c @@ -1520,7 +1520,7 @@ int frame_to_ptp_local_time(uint32_t timestamp, uint64_t *time, rtsp_conn_info * *time = ltime; result = 0; } else { - debug(2, "frame_to_ptp_local_time can't get anchor local time information"); + debug(4, "frame_to_ptp_local_time can't get anchor local time information"); } return result; } diff --git a/rtp.h b/rtp.h index fbbff766..de2f6d83 100644 --- a/rtp.h +++ b/rtp.h @@ -28,6 +28,7 @@ int local_time_to_frame(uint64_t time, uint32_t *frame, rtsp_conn_info *conn); int have_ptp_timing_information(rtsp_conn_info *conn); int get_ptp_anchor_local_time_info(rtsp_conn_info *conn, uint32_t *anchorRTP, uint64_t *anchorLocalTime); +void reset_ptp_anchor_info(rtsp_conn_info *conn); void *rtp_ap2_control_receiver(void *arg); void *rtp_realtime_audio_receiver(void *arg); void *rtp_ap2_timing_receiver(void *arg); diff --git a/rtsp.c b/rtsp.c index 52bda460..7da2ffaf 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; @@ -1134,7 +1134,7 @@ enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn, rtsp_mes reply = rtsp_read_request_response_error; // goto shutdown; } else { - debug(3, "buf is reallocated at 0x%" PRIxPTR ".", (uintptr_t)buf); + debug(4, "buf is reallocated at 0x%" PRIxPTR ".", (uintptr_t)buf); buflen = msg_size; } } @@ -1706,11 +1706,11 @@ void handle_flushbuffered(rtsp_conn_info *conn, rtsp_message *req, rtsp_message if (messagePlist != NULL) { plist_t item = plist_dict_get_item(messagePlist, "flushFromSeq"); if (item == NULL) { - debug(3, "Can't find a flushFromSeq"); + debug(4, "Can't find a flushFromSeq"); } 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"); @@ -1718,7 +1718,7 @@ void handle_flushbuffered(rtsp_conn_info *conn, rtsp_message *req, rtsp_message if (flushFromValid != 0) debug(1, "flushFromSeq without flushFromTS!"); else - debug(3, "Can't find a flushFromTS"); + debug(4, "Can't find a flushFromTS"); } else { plist_get_uint_val(item, &flushFromTS); if (flushFromValid == 0) @@ -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(4, "flushUntilSeq is %" PRId64 ".", flushUntilSeq & 0x7fffff); } item = plist_dict_get_item(messagePlist, "flushUntilTS"); @@ -1739,10 +1739,10 @@ void handle_flushbuffered(rtsp_conn_info *conn, rtsp_message *req, rtsp_message debug(1, "Can't find the flushUntilTS"); } else { plist_get_uint_val(item, &flushUntilTS); - debug(3, "flushUntilTS is %" PRId64 ".", flushUntilTS); + debug(4, "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 @@ -1782,7 +1782,7 @@ void handle_flushbuffered(rtsp_conn_info *conn, rtsp_message *req, rtsp_message } } - debug_mutex_unlock(&conn->flush_mutex, 3); + debug_mutex_unlock(&conn->flush_mutex, 4); plist_free(messagePlist); } @@ -1860,7 +1860,7 @@ void handle_setrateanchori(rtsp_conn_info *conn, rtsp_message *req, rtsp_message uint64_t rate; plist_get_uint_val(item, &rate); debug(3, "anchor rate 0x%016" PRIx64 ".", rate); - pthread_cleanup_debug_mutex_lock(&conn->flush_mutex, 1000, 1); + pthread_cleanup_debug_mutex_lock(&conn->flush_mutex, 1000, 4); conn->ap2_rate = rate; if ((rate & 1) != 0) { ptp_send_control_message_string( @@ -1874,6 +1874,7 @@ void handle_setrateanchori(rtsp_conn_info *conn, rtsp_message *req, rtsp_message #endif conn->ap2_play_enabled = 1; } else { + reset_ptp_anchor_info(conn); ptp_send_control_message_string("P"); // signify play is "P"ausing debug(2, "Connection %d: SETRATEANCHORI Pause playing.", conn->connection_number); conn->ap2_play_enabled = 0; @@ -2319,9 +2320,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,7 +2362,7 @@ 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); } } @@ -2403,7 +2404,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(3, "Connection %d:\n==\n%s\n==", conn->connection_number, printable_plist); free(printable_plist); } else { debug(1, "Can't print the plist!"); @@ -3857,13 +3858,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 +3888,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 +3925,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 +4223,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 +4256,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 +5019,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 +5064,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/shairport-sync-dbus-test-client.c b/shairport-sync-dbus-test-client.c index 3036bdee..b95f2a47 100644 --- a/shairport-sync-dbus-test-client.c +++ b/shairport-sync-dbus-test-client.c @@ -68,7 +68,7 @@ void on_properties_changed(__attribute__((unused)) GDBusProxy *proxy, GVariant * void notify_loudness_callback(ShairportSync *proxy, __attribute__((unused)) gpointer user_data) { // printf("\"notify_loudness_callback\" called with a gpointer of // %lx.\n",(int64_t)user_data); - gboolean ebl = shairport_sync_get_loudness(proxy); + gboolean ebl = shairport_sync_get_loudness_enabled(proxy); if (ebl == TRUE) printf("Client reports loudness is enabled.\n"); else 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) { diff --git a/utilities/debug.c b/utilities/debug.c index 0aa21689..ea3a9365 100644 --- a/utilities/debug.c +++ b/utilities/debug.c @@ -196,7 +196,7 @@ void _debug(const char *filename, const int linenumber, int level, const char *f return; int oldState; pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); - char b[1024]; + char b[1024 * 64]; b[0] = 0; pthread_mutex_lock(&debug_timing_lock); uint64_t time_now = debug_get_absolute_time_in_ns(); @@ -255,18 +255,18 @@ void _debug_print_buffer(const char *thefilename, const int linenumber, int leve char *obfp = obf; unsigned int obfc; for (obfc = 0; obfc < buf_len; obfc++) { - snprintf(obfp, 3, "%02X", buf[obfc]); + snprintf(obfp, 3, "%02X", (unsigned char)buf[obfc]); obfp += 2; if (obfc != buf_len - 1) { if (obfc % 32 == 31) { snprintf(obfp, 5, " || "); - obfp += 4; + obfp += strlen(" || "); } else if (obfc % 16 == 15) { snprintf(obfp, 4, " | "); - obfp += 3; + obfp += strlen(" | ");; } else if (obfc % 4 == 3) { snprintf(obfp, 2, " "); - obfp += 1; + obfp += strlen(" ");; } } };