Shairport-sync: Incomplete Cover art chunking over UDP

[OneBobone]

Mostly, but not always, I only get the first chunk and thereby incomplete images. I have tried with different packet sizes, but have not noticed any difference.
Also, I almost never get the “picture stream has ended code”: “ssncpcen”.

Any recommendations?

[mikebrady]

Thanks for the post. Can you get it to misbehave reliably?

[OneBobone]

Thank you for responding Mike.
I would say that it is quite “reliable”, unfortunately.
I can’t really see any effects of varying stuff, but I am running local-to-local communication and tried with pretty large packet sizes (>30000). I never have problems with the first packet.

[mikebrady]

Okay, I don't use this facility, so I have added a debug message when each chunk is transmitted and a delay of 100 milliseconds after each chunk. It's in a new branch called troubleshooting/multicast. Would you be kind enough to try it out please, and perhaps post some logs?

[OneBobone]

Thank you! Let me try that on Tuesday/Wednesday.

[OneBobone]

Noticed this issue when installing Cygwin according to your new write-up:
Problem 1/1
package openssl-devel-1.1.1b-1 requires libssl-devel, but none of the providers can be installed
Solution 1/1 (default)

• do not ask to install openssl-devel-1.1.1b-1

Postinstall script problems:
Package: _/libfontconfig-common
fontconfig_dtd.sh exit code 2

I did not have theses issues the last time I installed. Don't know if they matter?

[mikebrady]

Thanks. I'll check it out.

The "postinstall script problems" seem to be irrelevant.

[OneBobone]

Is this not the right syntax?
git clone https://github.com/mikebrady/shairport-sync.git@troubleshooting/multicast
(pls excuse, I have never installed a branch before)

[mikebrady]

What I would do is clone it in the normal way:

$ git clone https://github.com/mikebrady/shairport-sync.git

then cd into the new directory:

$ cd shairport-sync

and then:

$ git checkout troubleshooting/multicast

[OneBobone]

Instead of "development" or additionally?
I chose troubleshooting/multicast:

$ PKG_CONFIG_PATH=/usr/local/lib/pkgconfig ./configure --with-metadata --with-ao --with-ssl=openssl --with-avahi --with-dbus-interface --sysconfdir=/etc --with-cygwin-service
Then:

configure: WARNING: unrecognized options: --with-cygwin-service (disappears if I chose 'development')

......

checking encryption libraries chosen... checking for SSL... no
configure: error: Package requirements (libssl,libcrypto) were not met:

Package 'libssl', required by 'virtual:world', not found
Package 'libcrypto', required by 'virtual:world', not found

Consider adjusting the PKG_CONFIG_PATH environment variable if you
installed software in a non-standard prefix.

Alternatively, you may set the environment variables SSL_CFLAGS
and SSL_LIBS to avoid the need to call pkg-config.
See the pkg-config man page for more details.

"Make" fails.
I have tried to do a complete reinstall of Cygwin according to the instructions.

[mikebrady]

Yes, checkout troubleshooting/multicast Instead of development.

You should be following the steps in the development version of the CYGWIN guide.

[OneBobone]

Fair enough, but the CYGWIN guide for /multicast and development are identical?
Either way, the installation unfortunately fails.
What can I do?

[mikebrady]

Yes indeed. The multicast branch is a small variation of the development version.

[mikebrady]

Hmm. Just thinking of a checklist, can you say where the installation fails?

1. Is Bonjour Service working?
2. Is the CYGWIN D-Bus system service active?
3. Is the CYGWIN Avahi service active?
4. Did you get libconfig successfully installed?

Or, if you have an error message, perhaps you'd be kind enough to post it.

[OneBobone]

1-4: yes

I posted the error message above. Is there something else that I can provide?

[mikebrady]

Thanks. And did you do the Cygwin setup:

C:\Users\mike> Downloads\setup-x86_64.exe -P cygrunsrv,dbus,avahi,avahi-tools,gnome-keyring,libavahi-client-devel,^
libglib2.0-devel,openssl,pkg-config,autoconf,automake,clang,libdaemon-devel,popt-devel,^
make,libao-devel,openssl-devel,libtool,git,wget,flex,bison

beforehand?

[OneBobone]

Yes, all in one continuous string w/o the ^.
That produced the first posted error.

[mikebrady]

Okay. If you copy and paste that:

Downloads\setup-x86_64.exe -P cygrunsrv,dbus,avahi,avahi-tools,gnome-keyring,libavahi-client-devel,^
libglib2.0-devel,openssl,pkg-config,autoconf,automake,clang,libdaemon-devel,popt-devel,^
make,libao-devel,openssl-devel,libtool,git,wget,flex,bison

into a Windows Command Prompt, including the ^ symbols, it should accept the entry as one line.

That problem:

Problem 1/1
package openssl-devel-1.1.1b-1 requires libssl-devel, but none of the providers can be installed
Solution 1/1 (default)

do not ask to install openssl-devel-1.1.1b-1

seems to be a Cygwin bug -- I get it too. That may be causing the remaining problems you are experiencing, since it looks like it would not install libssl and libcrypto, as they are part of the openssl-devel package. I suggest you try it again like this on a Windows Command Prompt:

Downloads\setup-x86_64.exe -P openssl-devel

[OneBobone]

Downloads\setup-x86_64.exe -P openssl-devel produced the same error.
By downgrading the SSL libraries, I managed to get it to work. (Don't know which one is the culprit)

With the develop branch I got the same chunking error.
I did notice something new: coverart is saved in a cache folder that was not present before. There, the images are complete.
--> Is there some way of finding the GUID in the metadata stream or other?

Now I will install the other branch and collect logs.
BTW, ^ produces problems on Win7. Preferable if you could save one long string to copy.

[OneBobone]

shairport-sync.log

Not sure how you read the log (I can't see any error), but I fastforwarded around 10 Spotify songs (~ 20 images: 1 small "Spotify std playlist image" and then 1 larger track image.)
The last one appears almost complete on the receiving side.
Otherwise a good mix of "half" images and "90%-100%" images (hard to tell between 90-100%).

apr-04 00:33:23 Shairport-Sync Playing: 1978 Anne-Marie Perfect To Me
apr-04 00:33:17 Shairport-Sync Playing: 1976 The Vamps All Night
apr-04 00:33:12 Shairport-Sync Playing: 1840 Lukas Graham Off To See The World
apr-04 00:33:02 Shairport-Sync Playing: 1847 Zedd The Middle
apr-04 00:32:53 Shairport-Sync Playing: 1911 Basic Tape No Matter (Basic Tape vs. Frances)
apr-04 00:32:47 Shairport-Sync Playing: 2611 Ed Sheeran Castle on the Hill
apr-04 00:32:39 Shairport-Sync Playing: 1994 Shawn Mendes There's Nothing Holdin' Me Back
apr-04 00:32:27 Shairport-Sync Playing: 1904 Charlie Puth Marvin Gaye (feat. Meghan Trainor)
apr-04 00:32:19 Shairport-Sync Playing: 2202 JP Cooper September Song

No difference in results with package sizes bewteen 15000 and 65000

If I could receive the ssncpcen metadata code consistently, it would be helpful too...

[mikebrady]

Thanks. The log shows that every single chunk is being sent. For example, the very first one:

metadata_process: sending chunk 0 of 6.
Connection 1: RTSP Response:
  Type: "CSeq", content: "9"
  Type: "Server", content: "AirTunes/105.1"
Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
  Type: "RTP-Info", content: "rtptime=1170569481"
  Type: "Content-Length", content: "43"
  Type: "Content-Type", content: "text/parameters"
  Type: "CSeq", content: "10"
  Type: "DACP-ID", content: "703406F155B676BE"
  Type: "Active-Remote", content: "779568459"
  Type: "User-Agent", content: "AirPlay/373.9.1"
Connection 1: RTSP Response:
  Type: "CSeq", content: "10"
  Type: "Server", content: "AirTunes/105.1"
Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
  Type: "RTP-Info", content: "rtptime=1170569481"
  Type: "Content-Length", content: "189"
  Type: "Content-Type", content: "application/x-dmap-tagged"
  Type: "CSeq", content: "11"
  Type: "DACP-ID", content: "703406F155B676BE"
  Type: "Active-Remote", content: "779568459"
  Type: "User-Agent", content: "AirPlay/373.9.1"
Connection 1: RTSP Response:
  Type: "CSeq", content: "11"
  Type: "Server", content: "AirTunes/105.1"
metadata_process: sending chunk 1 of 6.
metadata_process: sending chunk 2 of 6.
metadata_process: sending chunk 3 of 6.
metadata_process: sending chunk 4 of 6.
Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
  Type: "RTP-Info", content: "rtptime=1170569481"
  Type: "Content-Length", content: "89346"
  Type: "Content-Type", content: "image/jpeg"
  Type: "CSeq", content: "12"
  Type: "DACP-ID", content: "703406F155B676BE"
  Type: "Active-Remote", content: "779568459"
  Type: "User-Agent", content: "AirPlay/373.9.1"
Connection 1: RTSP Response:
  Type: "CSeq", content: "12"
  Type: "Server", content: "AirTunes/105.1"
Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
  Type: "RTP-Info", content: "rtptime=1170586025"
  Type: "Content-Length", content: "43"
  Type: "Content-Type", content: "text/parameters"
  Type: "CSeq", content: "13"
  Type: "DACP-ID", content: "703406F155B676BE"
  Type: "Active-Remote", content: "779568459"
  Type: "User-Agent", content: "AirPlay/373.9.1"
Connection 1: RTSP Response:
  Type: "CSeq", content: "13"
  Type: "Server", content: "AirTunes/105.1"
Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
  Type: "RTP-Info", content: "rtptime=1170586025"
  Type: "Content-Length", content: "189"
  Type: "Content-Type", content: "application/x-dmap-tagged"
  Type: "CSeq", content: "14"
  Type: "DACP-ID", content: "703406F155B676BE"
  Type: "Active-Remote", content: "779568459"
  Type: "User-Agent", content: "AirPlay/373.9.1"
Connection 1: RTSP Response:
  Type: "CSeq", content: "14"
  Type: "Server", content: "AirTunes/105.1"
metadata_process: sending chunk 5 of 6.
MH Picture received, length 89346 bytes.

You can see all six chunks are sent (the index number is always 1 less than it should be in the log).

I've updated the branch to fix that cosmetic issue and add more diagnostic output. My guess is that UDP packets are being lost on your network -- remember UDP does not guarantee delivery.

The cached files are for the D-Bus interface and are not part of the metadata stream supplied by the source.

[OneBobone]

Ok, I can see. I will give it another try tonight. A few thoughts:

• no other udp packets are lost other than the last image chunk. Too much of a coincidence?
• where is the ssncpcen package? Is it being concatenated with the last chunk?
• the cached file could be of interest as a back-up solution...

[mikebrady]

The changes I made should show that the last chunk and the pcen item are being sent, but of course I'll keep looking for any issues. What is receiving the metadata?

[OneBobone]

A .Net standard udp receiver. SPS running both on same and another machine.
Will try later this evening.

[OneBobone]

shairport-sync.log
Can't see any errors.

Want to bring your attention to my log below.

> apr-05 10:49:31       ssncpcen    ssncpcen3291532220
> apr-05 10:49:30       ssncpcst    ssncpcst3291532220
> apr-05 10:49:30       Playing: 1671 Mike Perry Hands
> apr-05 10:49:20       ssncpcen    ssncpcen3291045756
> apr-05 10:49:19       ssncpcst    ssncpcst3291045756
> apr-05 10:49:19       ssncpcst    ssncpcst3291022172
> apr-05 10:49:18       Playing: 2454 The Script Superheroes
> apr-05 10:49:06       ssncpcen    ssncpcen3290416028
> apr-05 10:49:05       ssncpcst    ssncpcst3290416028
> apr-05 10:49:04       Playing: 1826 Ellie Goulding Close To Me (feat. Swae Lee)
> apr-05 10:48:55       ssncpcen    ssncpcen3289984828
> apr-05 10:48:55       ssncpcst    ssncpcst3289984828
> apr-05 10:48:55       ssncpcst    ssncpcst3289960540
> apr-05 10:48:54       Playing: 2070 Zedd Happy Now

Could it be that for unchunked (small) pictures, ssncpcen and sometimes ssncpcst goes missing? Typically for the Spotify playlist image.

[mikebrady]

Ha, thanks for that. I just pushed a slight update with a bit more error logging on sending the UDP packets -- it might be interesting, I just don't know.

I'll have a look at the issue you raise.

[mikebrady]

That looks like an old log? It doesn't seem to include any of the extra log information included in yesterday's update.

[OneBobone]

Will reinstall. (Sorry if I mixed up the logs, but they did not look so different to me either.
Could ssncpcen be received before the last chunk (chunking sub)?

[mikebrady]

Thanks.

Right off the top of my head, we know that UDP packets can be delivered out-of-order, so there is a way this could happen.

As far as Shairport Sync itself is concerned, one thread receives the metadata and hands it off, in the order of reception, to another single thread. That metadata processing thread processes everything in order, so I can't see where an out-of-order effect could take place within Shairport Sync. But once the UDP packets are emitted, anything could happen.

[OneBobone]

> apr-05 11:35:24       SPS ssncpcen2472336411
> apr-05 11:35:24       SPS ssncpcst2472336411
> apr-05 11:35:23       SPS ssncpcst2472295227
> apr-05 11:35:22       Nuvo Airplay    Playing: 1983 G.R.L. Ugly Heart
> apr-05 11:31:46       SPS ssncpcen2462694427
> apr-05 11:31:45       SPS ssncpcst2462694427
> apr-05 11:31:44       SPS ssncpcst2462650075
> apr-05 11:31:43       Nuvo Airplay    Playing: 2182 James Arthur Rewrite The Stars 
> apr-05 11:28:16       SPS ssncpcen2453488571
> apr-05 11:28:16       SPS ssncpcst2453488571
> apr-05 11:28:16       SPS ssncpcst2453466043
> apr-05 11:28:15       Nuvo Airplay    Playing: 2077 Jason Derulo Want to Want Me
> apr-05 11:27:41       SPS ssncpcst2451813403
> apr-05 11:27:41       Nuvo Airplay    Playing: 10720 1990 WALK THE MOON Shut Up and Dance
> apr-05 11:27:40       Nuvo Airplay    Paused: 10720 1990 WALK THE MOON Shut Up and Dance
> apr-05 11:27:40       SPS ssncpcen2451800893
> apr-05 11:27:40       SPS ssncpcst2451800893
> apr-05 11:27:39       Nuvo Airplay    Playing: 10710 1990 WALK THE MOON Shut Up and Dance
> apr-05 11:27:39       Nuvo Airplay    Paused: 10710 1990 WALK THE MOON Shut Up and Dance
> apr-05 11:27:39       Nuvo Airplay    Bob's iPad

shairport-sync.log

[OneBobone]

Dear Mike, I am not sure I want to take up your precious time on this.
The fact that the Cover art is cached is a good back-up, plus the incomplete chunking mostly but not only happens when you press "Next", i.e. could be some overload? The lack of ssncpcen for the spotify playlist image is however consistent.
If I may, getting dbus working would be very valuable.
:-)

[mikebrady]

Thanks. Apologies for the bug-laden previous update. I've fixed it.

The D-Bus situation is frustrating alright, but will take some time to resolve, as, AFAICT, it's either a CYGWIN or a D-Bus issue. I need to prepare a simple exemplar of the problem and ask the experts...

[OneBobone]

Pls Excuse, which bug did you fix so I can test?
It turns out that the lack of ssncpcenwas not causing my problems as I flush the array for each ssncpcstanyway

2 questions:

• The Linux Pipe becomes a windows link. Not sure how to get the metadata to a file? I tried replacing/adding to the pipe "metadata.txt"
• does the pipe and UPD output run in parallel or are they exclusive?

[mikebrady]

There were two bugs -- one was incorrectly reporting an error every time a piece of metadata was sent out on UDP. The second was mis-formatting the code attribute of a piece of metadata.

• The metadata pipe is, by default, at /tmp/shairport-sync-metadata. In Linux, you could direct it to a file like this:

$ cat /tmp/shairport-sync-metadata > file.txt

• If metadata is enabled, both the pipe and UDP are simultaneously available.

[OneBobone]

Thank you! I also had a few bugs/inefficiencies that were clouding my view of the events.
To summarize what we have learned:
1) Installing on Cygwin is currently not 100% straight forward as the current SSL versions are not mutually compatible. Not sure how/if to report this.
--> the solution is to select the next latest version of these
2) Reception of ssncpcen is not 100% consistent:

• it is often (always) lacking for small images that do not need chunking. Typically the Spotify playlist logo that is sent between songs.
• when the "system" is stressed, e.g. when forcing the next song with a "Next" command, the last ssncpcen can also be lacking. Unclear if the whole chunk is malformed/malreceived as well. Introducing a short wait period could be beneficial.
  3) Piping metadata to file ($ cat /tmp/shairport-sync-metadata > /tmp/file.txt) does not work so well on Cygwin:
• a file is created, but never filled

[mikebrady]

Yes, agreed. I think item 1 is a transient bug in Cygwin. Regarding item 2, it seems as if Shairport Sync is outputting the stuff to UDP but it is disappearing.
Item 3 is a bit surprising. Does it $ cat to the console? (That is, does: $ cat /tmp/shairport-sync-metadata work?)

[mikebrady]

Closing this interesting thread – I think we've moved on. Please feel free to open another issue if necessary.