[Problem]: Log statement data type warnings, dev branch

[ejurgensen]

What happened?

See warnings below

Relevant log output

In file included from rtsp.c:72:
rtsp.c: In function ‘read_from_rtsp_connection’:
rtsp.c:1011:16: warning: format ‘%lu’ expects argument of type ‘long unsigned int’, but argument 7 has type ‘size_t’ {aka ‘unsigned int’} [-Wformat=]
 1011 |       debug(3, "read_from_rtsp_connection error %d \"%s\" attempting to read up to %lu bytes.",
      |                ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
 1012 |             errno, errorstring, count);
      |                                 ~~~~~
      |                                 |
      |                                 size_t {aka unsigned int}
common.h:488:47: note: in definition of macro ‘debug’
  488 | #define debug(...) _debug(__FILE__, __LINE__, __VA_ARGS__)
      |                                               ^~~~~~~~~~~
rtsp.c:1011:86: note: format string is defined here
 1011 |       debug(3, "read_from_rtsp_connection error %d \"%s\" attempting to read up to %lu bytes.",
      |                                                                                    ~~^
      |                                                                                      |
      |                                                                                      long unsigned int
      |                                                                                    %u
rtsp.c: In function ‘msg_write_response’:
rtsp.c:1336:14: warning: format ‘%ld’ expects argument of type ‘long int’, but argument 5 has type ‘int’ [-Wformat=]
 1336 |     debug(1, "msg_write_response error -- requested bytes: %ld not fully written: %ld.", p - pkt,
      |              ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~  ~~~~~~~
      |                                                                                            |
      |                                                                                            int
common.h:488:47: note: in definition of macro ‘debug’
  488 | #define debug(...) _debug(__FILE__, __LINE__, __VA_ARGS__)
      |                                               ^~~~~~~~~~~
rtsp.c:1336:62: note: format string is defined here
 1336 |     debug(1, "msg_write_response error -- requested bytes: %ld not fully written: %ld.", p - pkt,
      |                                                            ~~^
      |                                                              |
      |                                                              long int
      |                                                            %d
rtsp.c:1336:14: warning: format ‘%ld’ expects argument of type ‘long int’, but argument 6 has type ‘ssize_t’ {aka ‘int’} [-Wformat=]
 1336 |     debug(1, "msg_write_response error -- requested bytes: %ld not fully written: %ld.", p - pkt,
      |              ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
 1337 |           reply);
      |           ~~~~~
      |           |
      |           ssize_t {aka int}
common.h:488:47: note: in definition of macro ‘debug’
  488 | #define debug(...) _debug(__FILE__, __LINE__, __VA_ARGS__)
      |                                               ^~~~~~~~~~~
rtsp.c:1336:85: note: format string is defined here
 1336 |     debug(1, "msg_write_response error -- requested bytes: %ld not fully written: %ld.", p - pkt,
      |                                                                                   ~~^
      |                                                                                     |
      |                                                                                     long int
      |                                                                                   %d
rtsp.c: In function ‘rtsp_conversation_thread_func’:
rtsp.c:5197:20: warning: format ‘%ld’ expects argument of type ‘long int’, but argument 5 has type ‘size_t’ {aka ‘unsigned int’} [-Wformat=]
 5197 |           debug(1, "rtsp_read_request_response_bad_packet write %ld bytes requested but %d written.",
      |                    ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
 5198 |                 strlen(response_text), reply);
      |                 ~~~~~~~~~~~~~~~~~~~~~
      |                 |
      |                 size_t {aka unsigned int}
common.h:488:47: note: in definition of macro ‘debug’
  488 | #define debug(...) _debug(__FILE__, __LINE__, __VA_ARGS__)
      |                                               ^~~~~~~~~~~
rtsp.c:5197:67: note: format string is defined here
 5197 |           debug(1, "rtsp_read_request_response_bad_packet write %ld bytes requested but %d written.",
      |                                                                 ~~^
      |                                                                   |
      |                                                                   long int
      |                                                                 %d
In file included from common.c:29:
common.c: In function ‘rsa_apply’:
common.c:849:26: warning: format ‘%lu’ expects argument of type ‘long unsigned int’, but argument 5 has type ‘size_t’ {aka ‘unsigned int’} [-Wformat=]
  849 |                 debug(3, "success with output length of %lu.", ol);
      |                          ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~  ~~
      |                                                                |
      |                                                                size_t {aka unsigned int}
common.h:488:47: note: in definition of macro ‘debug’
  488 | #define debug(...) _debug(__FILE__, __LINE__, __VA_ARGS__)
      |                                               ^~~~~~~~~~~
common.c:849:59: note: format string is defined here
  849 |                 debug(3, "success with output length of %lu.", ol);
      |                                                         ~~^
      |                                                           |
      |                                                           long unsigned int
      |                                                         %u
In file included from rtp.c:29:
rtp.c: In function ‘rtp_audio_receiver’:
rtp.c:303:18: warning: format ‘%ld’ expects argument of type ‘long int’, but argument 6 has type ‘ssize_t’ {aka ‘int’} [-Wformat=]
  303 |         debug(1, "Audio receiver -- Unknown RTP packet of type 0x%02X length %ld seqno %d", type,
      |                  ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  304 |               nread, seqno);
      |               ~~~~~
      |               |
      |               ssize_t {aka int}
common.h:488:47: note: in definition of macro ‘debug’
  488 | #define debug(...) _debug(__FILE__, __LINE__, __VA_ARGS__)
      |                                               ^~~~~~~~~~~
rtp.c:303:80: note: format string is defined here
  303 |         debug(1, "Audio receiver -- Unknown RTP packet of type 0x%02X length %ld seqno %d", type,
      |                                                                              ~~^
      |                                                                                |
      |                                                                                long int
      |                                                                              %d
rtp.c:306:12: warning: format ‘%ld’ expects argument of type ‘long int’, but argument 5 has type ‘ssize_t’ {aka ‘int’} [-Wformat=]
  306 |       warn("Audio receiver -- Unknown RTP packet of type 0x%02X length %ld.", type, nread);
      |            ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~        ~~~~~
      |                                                                                     |
      |                                                                                     ssize_t {aka int}
common.h:489:45: note: in definition of macro ‘warn’
  489 | #define warn(...) _warn(__FILE__, __LINE__, __VA_ARGS__)
      |                                             ^~~~~~~~~~~
rtp.c:306:74: note: format string is defined here
  306 |       warn("Audio receiver -- Unknown RTP packet of type 0x%02X length %ld.", type, nread);
      |                                                                        ~~^
      |                                                                          |
      |                                                                          long int
      |                                                                        %d
rtp.c: In function ‘rtp_control_receiver’:
rtp.c:576:20: warning: format ‘%ld’ expects argument of type ‘long int’, but argument 6 has type ‘ssize_t’ {aka ‘int’} [-Wformat=]
  576 |           debug(1, "Control Receiver -- Unknown RTP packet of type 0x%02X length %ld, ignored.",
      |                    ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  577 |                 packet[1], nread);
      |                            ~~~~~
      |                            |
      |                            ssize_t {aka int}
common.h:488:47: note: in definition of macro ‘debug’
  488 | #define debug(...) _debug(__FILE__, __LINE__, __VA_ARGS__)
      |                                               ^~~~~~~~~~~
rtp.c:576:84: note: format string is defined here
  576 |           debug(1, "Control Receiver -- Unknown RTP packet of type 0x%02X length %ld, ignored.",
      |                                                                                  ~~^
      |                                                                                    |
      |                                                                                    long int
      |                                                                                  %d
rtp.c: In function ‘rtp_timing_receiver’:
rtp.c:984:20: warning: format ‘%ld’ expects argument of type ‘long int’, but argument 6 has type ‘ssize_t’ {aka ‘int’} [-Wformat=]
  984 |           debug(1, "Timing port -- Unknown RTP packet of type 0x%02X length %ld.", packet[1], nread);
      |                    ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~             ~~~~~
      |                                                                                               |
      |                                                                                               ssize_t {aka int}
common.h:488:47: note: in definition of macro ‘debug’
  488 | #define debug(...) _debug(__FILE__, __LINE__, __VA_ARGS__)
      |                                               ^~~~~~~~~~~
rtp.c:984:79: note: format string is defined here
  984 |           debug(1, "Timing port -- Unknown RTP packet of type 0x%02X length %ld.", packet[1], nread);
      |                                                                             ~~^
      |                                                                               |
      |                                                                               long int
      |                                                                             %d
In file included from player.c:83:
player.c: In function ‘buffer_get_frame’:
player.c:2128:33: warning: format ‘%lu’ expects argument of type ‘long unsigned int’, but argument 8 has type ‘uint32_t’ {aka ‘unsigned int’} [-Wformat=]
 2128 |                                 "flush to %u request: flush buffer %u, from "
      |                                 ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
......
 2131 |                                 current_packet->timestamp + current_packet->length - 1,
      |                                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
      |                                                                                    |
      |                                                                                    uint32_t {aka unsigned int}
common.h:488:47: note: in definition of macro ‘debug’
  488 | #define debug(...) _debug(__FILE__, __LINE__, __VA_ARGS__)
      |                                               ^~~~~~~~~~~
player.c: In function ‘stuff_buffer_soxr_32’:
player.c:3146:13: warning: format ‘%lu’ expects argument of type ‘long unsigned int’, but argument 4 has type ‘size_t’ {aka ‘unsigned int’} [-Wformat=]
 3146 |         die("odone = %lu!\n", odone);
      |             ^~~~~~~~~~~~~~~~  ~~~~~
      |                               |
      |                               size_t {aka unsigned int}
common.h:487:43: note: in definition of macro ‘die’
  487 | #define die(...) _die(__FILE__, __LINE__, __VA_ARGS__)
      |                                           ^~~~~~~~~~~
player.c:3146:24: note: format string is defined here
 3146 |         die("odone = %lu!\n", odone);
      |                      ~~^
      |                        |
      |                        long unsigned int
      |                      %u
player.c: In function ‘player_thread_func’:
player.c:4040:28: warning: format ‘%lu’ expects argument of type ‘long unsigned int’, but argument 5 has type ‘size_t’ {aka ‘unsigned int’} [-Wformat=]
 4040 |                   debug(3, "tsum_of_frames: %lu.", tsum_of_frames);
      |                            ^~~~~~~~~~~~~~~~~~~~~~  ~~~~~~~~~~~~~~
      |                                                    |
      |                                                    size_t {aka unsigned int}
common.h:488:47: note: in definition of macro ‘debug’
  488 | #define debug(...) _debug(__FILE__, __LINE__, __VA_ARGS__)
      |                                               ^~~~~~~~~~~
player.c:4040:47: note: format string is defined here
 4040 |                   debug(3, "tsum_of_frames: %lu.", tsum_of_frames);
      |                                             ~~^
      |                                               |
      |                                               long unsigned int
      |                                             %u
In file included from audio_alsa.c:42:
audio_alsa.c: In function ‘alsa_buffer_monitor_thread_code’:
audio_alsa.c:2383:20: warning: format ‘%lu’ expects argument of type ‘long unsigned int’, but argument 7 has type ‘size_t’ {aka ‘unsigned int’} [-Wformat=]
 2383 |           debug(3, "Played %u frames of silence on %u channels, equal to %lu bytes.",
      |                    ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
 2384 |                 frames_of_silence, CHANNELS_FROM_ENCODED_FORMAT(current_encoded_output_format),
 2385 |                 size_of_silence_buffer);
      |                 ~~~~~~~~~~~~~~~~~~~~~~
      |                 |
      |                 size_t {aka unsigned int}
common.h:488:47: note: in definition of macro ‘debug’
  488 | #define debug(...) _debug(__FILE__, __LINE__, __VA_ARGS__)
      |                                               ^~~~~~~~~~~
audio_alsa.c:2383:76: note: format string is defined here
 2383 |           debug(3, "Played %u frames of silence on %u channels, equal to %lu bytes.",
      |                                                                          ~~^
      |                                                                            |
      |                                                                            long unsigned int
      |                                                                          %u

System Information.

pi@bookworm:~/build/github/shairport-sync $ ./shairport-sync --displayConfig
         0.000834064 "shairport.c:2484" >> Display Config Start.
         0.006180158 "shairport.c:2484"
         0.000171994 "shairport.c:2484" From "uname -a":
         0.000070850 "shairport.c:2484"  Linux bookworm 6.12.47+rpt-rpi-v8 #1 SMP PREEMPT Debian 1:6.12.47-1+rpt1~bookworm (2025-09-16) aarch64 GNU/Linux
         0.011756837 "shairport.c:2484"
         0.000197345 "shairport.c:2484" From /etc/os-release:
         0.000071942 "shairport.c:2484"  Raspbian GNU/Linux 12 (bookworm)
         0.008229773 "shairport.c:2484"
         0.000540223 "shairport.c:2484" From /sys/firmware/devicetree/base/model:
         0.000091737 "shairport.c:2484"  Raspberry Pi 4 Model B Rev 1.4
         0.000152680 "shairport.c:2484"
         0.000070850 "shairport.c:2484" Shairport Sync Version String:
         0.000061572 "shairport.c:2484"  5.0-dev-150-gd7f88166-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/usr/local/etc
         0.000067886 "shairport.c:2484"
         0.000058183 "shairport.c:2484" Command Line:
         0.000379302 "shairport.c:2484"  ./shairport-sync --displayConfig
         0.000075609 "shairport.c:2484" No configuration file.
         0.000062664 "shairport.c:2484"
         0.000057683 "shairport.c:2484" >> Display Config End.
         0.000058980 "shairport.c:2486" >> Goodbye!
         0.000082238 "shairport.c:1996" normal exit

Configuration Information.

See system info

PulseAudio or PipeWire installed?

• Check if your system uses a Sound Server.

How did you install Shairport Sync?

Built from source

Check previous issues

• Confirm

[mikebrady]

Thanks. Working on this.

[mikebrady]

I think we have fixed most of these.

[ejurgensen]

Yes, it builds without warnings now 👍

Unfortunately, I think there might be another problem in the dev branch. I notice that sometimes after just having started SPS, when I try to start playback, there is no response to the OPTIONS request. SPS logs nothing. Then, if I just leave it running for a few minutes, it seems to work.

I haven't seen this issue with the master branch, despite restarting SPS many times.

A wild guess at what could be happening: When OwnTone sees a new device from mdns, it will make a connection to it and then close it (without sending a request). Maybe the dev branch SPS doesn't detect that the connection is closed and keeps listening?

One more thing from the dev branch. SPS logs the below, which seem to be about dropped packages, because they are late by 50-60 ms. I don't quite understand why they would be dropped when the delay is so relatively short compared to the 99250 frame buffer time? This test is still with OwnTone and SPS on the same device, btw.

         1.259365524 "player.c:4535" drop late packet, timestamp: 1309160353,  late by: 50.018 ms, packets remaining in the buffer: 262.
         0.000484215 "player.c:4535" drop late packet, timestamp: 1309160705,  late by: 50.016 ms, packets remaining in the buffer: 261.
         1.811842253 "player.c:4535" drop late packet, timestamp: 1309239905,  late by: 54.960 ms, packets remaining in the buffer: 263.
         0.000175627 "player.c:4535" drop late packet, timestamp: 1309240257,  late by: 54.975 ms, packets remaining in the buffer: 262.
         0.000111572 "player.c:4535" drop late packet, timestamp: 1309240609,  late by: 54.975 ms, packets remaining in the buffer: 261.
         0.000106628 "player.c:4535" drop late packet, timestamp: 1309240961,  late by: 54.069 ms, packets remaining in the buffer: 260.
         0.000109814 "player.c:4535" drop late packet, timestamp: 1309241313,  late by: 50.074 ms, packets remaining in the buffer: 259.
         1.799711105 "player.c:4535" drop late packet, timestamp: 1309319809,  late by: 52.115 ms, packets remaining in the buffer: 261.
         0.000170201 "player.c:4535" drop late packet, timestamp: 1309320161,  late by: 52.115 ms, packets remaining in the buffer: 260.
         1.227312892 "player.c:4535" drop late packet, timestamp: 1309372257,  late by: 67.062 ms, packets remaining in the buffer: 266.
         0.000234793 "player.c:4535" drop late packet, timestamp: 1309372609,  late by: 67.112 ms, packets remaining in the buffer: 265

Sorry for cluttering the issue with these other things!

[mikebrady]

Thanks for these observations!

It would be very useful to have the configuration information for these, ($ shairport-sync --displayConfig) but let me make a few guesses and hope I'm right.

Unfortunately, I think there might be another problem in the dev branch. I notice that sometimes after just having started SPS, when I try to start playback, there is no response to the OPTIONS request. SPS logs nothing. Then, if I just leave it running for a few minutes, it seems to work.
I haven't seen this issue with the master branch, despite restarting SPS many times.
A wild guess at what could be happening: When OwnTone sees a new device from mdns, it will make a connection to it and then close it (without sending a request). Maybe the dev branch SPS doesn't detect that the connection is closed and keeps listening?

There are changes between the master and development branch that might account for this: when a connection is made, it is now assumed (incorrectly in the case of OwnTone) that a play session is about to begin. Since a play session in AirPlay 1 can not be interrupted by default, a subsequent attempt to start a new session is ignored until the first "session" ends. If I'm right, you can stop this misbehaviour by allowing session interruption with the allow_session_interruption flag in the configuration file. We will try to change SPS's behaviour back to the old way.

One more thing from the dev branch. SPS logs the below, which seem to be about dropped packages, because they are late by 50-60 ms. I don't quite understand why they would be dropped when the delay is so relatively short compared to the 99250 frame buffer time? This test is still with OwnTone and SPS on the same device, btw.

To explain -- there are three situations where synchronisation activity occurs in SPS:

1. When a play session is about to begin, SPS tries to start it at exactly the right instant by priming the output DAC with just the right number of silent frames.
2. While a play session is in progress, SPS monitors synchronisation and interpolates-- adding or removing frames -- to maintain sync.
3. However, in that situation, if a very large synchronisation error (50 milliseconds by default) is seen while this monitoring is being done, then SPS will drop frames or possibly do an entire resynchronisation. That's what you are seeing there.

In reality, it's unlikely that one packet of frames could be so far off while the previous ones are okay, to this could be a timing measurement error. Is it possible that the computer is very busy on some occasions? Anyway, if I'm right, you can change the 50 mS threshold or turn that behaviour off using the resync_threshold_in_seconds setting in the configuration file. A value of 0.0 turns it off.
Another thing here is that when SPS is installed as a system service, some of its threads run at a slightly elevated level of priority, which tends to make it less prone to scheduling difficulties. But if it is run from a standard user's command line, it doesn't have the privileges necessary to change its priority.

So, thanks again for these observations. If you could let us have the --displayConfig logs whenever convenient, I could get to work.

[ejurgensen]

Sorry, should have mentioned, but I'm still testing on the RPi4, so the --displayConfig is the same as above. I'm running SPS as a user service, but the RPi isn't doing anything that would make it busy, so I think it is unlikely that there is an actual bottleneck.

I will try with resync_threshold_in_seconds. I guess I still don't understand the wording of the log message. It seems to indicate that SPS is receiving packages late, but it's hard to understand how 50 ms would be late with a 2 sec buffer. I understand SPS might discard packages to keep playback sync, but then shouldn't the logging say that instead?

Btw, as the log shows, 11 packets where discarded during 5 secs. It would be after playback started. That's a lot of correction for a short interval - doesn't that seem wrong?

[ejurgensen]

by allowing session interruption with the allow_session_interruption flag in the configuration file

I tried this now, and can confirm that fixed the issue 👍

[mikebrady]

Thanks for the update.

Sorry, should have mentioned, but I'm still testing on the RPi4, so the --displayConfig is the same as above. I'm running SPS as a user service, but the RPi isn't doing anything that would make it busy, so I think it is unlikely that there is an actual bottleneck.

Btw, as the log shows, 11 packets where discarded during 5 secs. It would be after playback started. That's a lot of correction for a short interval - doesn't that seem wrong?

Yes, that does indeed seem wrong.

As I understand it, you are running OwnTone out of the same device, no? It just may be that it's causing more scheduling activity than normal. If you ran SPS in supervisor mode from the command line, it could use those higher thread priorities and that might obviate the problem. (BTW, this problem is now really quite a rarity, even on an original Raspberry Pi B.)

I will try with resync_threshold_in_seconds. I guess I still don't understand the wording of the log message. It seems to indicate that SPS is receiving packages late, but it's hard to understand how 50 ms would be late with a 2 sec buffer. I understand SPS might discard packages to keep playback sync, but then shouldn't the logging say that instead?

There are two kinds of "lateness" here. One is not being sent to SPS in time. As you point out, this is unlikely when audio is usually sent and normally received two or more seconds ahead of time. However, the second kind of lateness is when a packet of audio, in the queue of packets to be sent to the output device, will be very late arriving at the output device according to its own timestamp. This can happen for a number of reasons, for example, the packet is faulty (rare); the packet is left over from a previous session and should have been flushed; or there is a real discontinuity in the timing of the packets arriving. All of these phenomena have been observed over time.
What happens is that, when a packet of audio has been dequeued and is being processed for adding to the output device's buffer, the timing of that buffer is checked according to its timestamp and the current clock. If it is way too late, it will be dropped, i.e. discarded. That is what the message signifies.