random </item> in metadata pipe

roblan commented 8 years ago

It looks like there is some error in metadata pipe and it inserts when it shouldn't. It happens only (I think) when artwork in metadata is enabled. It may have something to do with artwork send error. Oh, and shairport-sync version is most recent development.

Example pipe output

<item>
    <type>73736e63</type>
    <code>50494354</code>
    <length>92821</length>
    <data encoding="base64">[...]</data>
</item>
<item>
    <type>73736e63</type>
    <code>7063656e</code>
    <length>10</length>
    <data encoding="base64">MjM5NDM0MTU3MQ==</data>
</item>
<item>
    <type>73736e63</type>
    <code>70726772</code>
    <length>32</length>
    <data encoding="base64">MjM5NDMyNjIxMS8yMzk0MzQxNTcxLzI0MDQ5NjEzNjc=</data>
</item>
</item>
</item>

<item>
    <type>636f7265</type>
    <code>61737273</code>
        <length>1</length>
    <data encoding="base64">AA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736c72</code>
    <length>1</length>
    <data encoding="base64">KA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736173</code>
    <length>1</length>
    <data encoding="base64">AQ==</data>
</item>
<item>
    <type>636f7265</type>
    <code>6165434b</code>
    <length>1</length>
    <data encoding="base64">AQ==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61654773</code>
    <length>1</length>
    <data encoding="base64">AQ==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61656c73</code>
    <length>1</length>
    <data encoding="base64">AA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>616a616c</code>
    <length>1</length>
    <data encoding="base64">AA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>616a6361</code>
    <length>1</length>
    <data encoding="base64">AA==</data>
</item>
<item>
    <type>73736e63</type>
    <code>6d64656e</code>
    <length>10</length>
    <data encoding="base64">MTc5Nzg4NDk5NQ==</data>
</item>
</item>
</item>
</item>

roblan commented 8 years ago

And sometimes (not surprisingly ;) ) they are missing (also data closing is missing in first item)

<item>
    <type>73736e63</type>
    <code>7063656e</code>
    <length>10</length>
    <data encoding="base64">MjM5NzkyODA5OQ==
<item>
    <type>73736e63</type>
    <code>7072736d</code>
    <length>0</length>
<item>
    <type>73736e63</type>
    <code>70666c73</code>
    <length>0</length>
<item>
    <type>73736e63</type>
    <code>6d647374</code>
    <length>10</length>
    <data encoding="base64">MjM5ODMwODI1OQ==</data>
</item>
<item>
    <type>636f7265</type>
    <code>6d696b64</code>
    <length>1</length>
    <data encoding="base64">Ag==</data>
</item>

JSON could be easier ;) maybe add it as an option?

mikebrady commented 8 years ago

Thanks for the report. I'll see if I can replicate it...

roblan commented 8 years ago

I think that large artwork in file could be helpful (like over 1000x1000 px). And presumably Wi-Fi connection.

mikebrady commented 8 years ago

Thanks.

mikebrady commented 8 years ago

I had a thought about this – the sending thread in Shairport Sync will time out – that is, it will give up – if it has to wait more than 5 seconds to write to the pipe – it should log something if verbosity is set to 1 or more. Could that be happening?

roblan commented 8 years ago

Could be. My bet is on timeout during artwork sending (something goes wrong and it's left hanging).

mikebrady commented 8 years ago

Yeah, it's not so much the sending as the receiving: if the stuff isn't taken out of the pipe quickly enough, the pipe will block and then, if there's no movement after five seconds, it'll give up. I could try making the timeout longer, or make it a settable option. (?)

mikebrady commented 8 years ago

Hi there. Is this still a problem? Should I make the blocking timeout a setting you can alter?

roblan commented 8 years ago

I'll try to check it later today

roblan commented 8 years ago

It took me a while ;)

Yes, the issue is still present. Lets try with the timeout setting then :)

mikebrady commented 8 years ago

No worries – I'll set about that in the next few days.

mikebrady commented 8 years ago

Hmm, there's definitely something odd about the code responsible for writing to the pipe.

mikebrady commented 8 years ago

I pushed an update just now that reimplements the code for writing to the pipe. It doesn't allow you to change the timeout setting, but I think it should work better – I can't follow the logic of the code I wrote previously :(.

I'll add in the code to change the timeout later, but if you got a chance to test the latest push, I'd be obliged.

mikebrady commented 8 years ago

Actually I've now put in the code to allow you to change the time-out time and pushed it out as 2.8.3.11. Feedback appreciated.

roblan commented 8 years ago

There are still thing like missing

<item>
    <type>73736e63</type>
    <code>70666c73</code>
    <length>0</length>
<item>
    <type>73736e63</type>
    <code>6d647374</code>
    <length>9</length>
    <data encoding="base64">MTc1NDA3NjIw</data>
</item>

or missing (when data is 'cut' during) and additional

<item>
    <type>73736e63</type>
    <code>50494354</code>
    <length>13119</length>
    <data encoding="base64">[...]</item>
</item>
<item>
    <type>73736e63</type>
    <code>70656e64</code>
    <length>0</length>
</item>

second closing for appeared after a while. Sometimes it appears when I push pause in iTunes.

I've set pipe_timeout = 15000

mikebrady commented 8 years ago

Thanks. Are you using a program to pretty-print the output?

roblan commented 8 years ago

Nope. cat /tmp/shairport-sync and check interesting places "by hand"

mikebrady commented 8 years ago

Thanks again. I've just pushed yet another mod, and if it fixes the problem, it proves I'm an idiot. Would you mind trying it out please?

roblan commented 8 years ago

It seems to be a lot more responsive, but it has some issues unfortunately

Full log (from start to stop - last two showed after pause and disconnect I think) from 1 song I've addded [MISSING x]

<item>
    <type>73736e63</type>
    <code>736e7561</code>
    <length>37</length>
    <data encoding="base64">aVR1bmVzLzEyLjQgKE1hY2ludG9zaDsgT1MgWCAxMC4xMS41KQ==</data>
</item>
<item>
    <type>73736e63</type>
    <code>61637265</code>
    <length>10</length>
</item>
<item>
    <type>73736e63</type>
    <code>64616964</code>
    <length>16</length>
    <data encoding="base64">MDJGMUNDM0Q0N0FCRjA2Qg==</data>
</item>
<item>
    <type>73736e63</type>
    <code>70626567</code>
    <length>0</length>
</item>
<item>
    <type>73736e63</type>
    <code>70666c73</code>
    <length>0</length>
</item>
<item>
    <type>73736e63</type>
    <code>70766f6c</code>
    <length>26</length>
    <data encoding="base64">LTEwLjMwLC0xNy42OSwtMTAzLjAwLDAuMDA=</data>
</item>
<item>
    <type>73736e63</type>
    <code>70766f6c</code>
    <length>26</length>
    <data encoding="base64">LTEwLjMwLC0xNy42OSwtMTAzLjAwLDAuMDA=</data>
</item>
[MISSING item, code, length]
    <data encoding="base64">MTU2NDE5OTY2MQ==</data>
</item>
<item>
    <type>636f7265</type>
    <code>6d696b64</code>
    <length>1</length>
    <data encoding="base64">Ag==</data>
</item>
<item>
    <type>636f7265</type>
    <code>6173616c</code>
    <length>14</length>
    <data encoding="base64">QmVhdXRpZnVsIExpZXM=</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736172</code>
    <length>5</length>
    <data encoding="base64">QmlyZHk=</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736272</code>
    <length>2</length>
    <data encoding="base64">AQA=</data>
</item>
<item>
    <type>636f7265</type>
    <code>6173636d</code>
    <length>0</length>
</item>
<item>
    <type>636f7265</type>
    <code>6173636f</code>
    <length>1</length>
    <data encoding="base64">AA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736370</code>
    <length>0</length>
</item>
<item>
    <type>636f7265</type>
    <code>6d656961</code>
    <length>4</length>
    <data encoding="base64">VxPo1g==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736461</code>
    <length>4</length>
    <data encoding="base64">VxPo1g==</data>
</item>
<item>
    <type>636f7265</type>
    <code>6d656970</code>
    <length>4</length>
    <data encoding="base64">V0Gtuw==</data>
</item>
<item>
    <type>636f7265</type>
    <code>6173706c</code>
    <length>4</length>
    <data encoding="base64">V0Gtuw==</data>
</item>
<item>
    <type>636f7265</type>
    <code>6173646d</code>
    <length>4</length>
    <data encoding="base64">Vxe2+w==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736463</code>
    <length>2</length>
    <data encoding="base64">AAE=</data>
</item>
<item>
    <type>636f7265</type>
    <code>6173646e</code>
    <length>2</length>
    <data encoding="base64">AAE=</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736571</code>
    <length>0</length>
</item>
<item>
    <type>636f7265</type>
    <code>6173676e</code>
    <length>10</length>
    <data encoding="base64">SW5kaWUgUm9jaw==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736474</code>
    <length>14</length>
    <data encoding="base64"/>
</item>
<item>
    <type>636f7265</type>
    <code>61737276</code>
    <length>1</length>
    <data encoding="base64">AA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61737372</code>
    <length>4</length>
    <data encoding="base64">AACsRA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>6173737a</code>
    <length>4</length>
    <data encoding="base64">AH9DEg==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61737374</code>
    <length>4</length>
    <data encoding="base64">AAAAAA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61737370</code>
    <length>4</length>
    <data encoding="base64">AAAAAA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>6173746d</code>
    <length>4</length>
    <data encoding="base64">AAOwlQ==
    [MISSING /data]
</item>
<item>
    <type>636f7265</type>
    <code>61737463</code>
    <length>2</length>
    <data encoding="base64">ABI=</data>
</item>
<item>
    <type>636f7265</type>
    <code>6173746e</code>
    <length>2</length>
    <data encoding="base64">AAI=</data>
</item>
<item>
    <type>636f7265</type>
    <code>61737572</code>
    <length>1</length>
    <data encoding="base64">AA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61737972</code>
    <length>2</length>
    <data encoding="base64">B+A=</data>
</item>
<item>
    <type>636f7265</type>
    <code>6173666d</code>
    <length>3</length>
    <data encoding="base64">bTRh</data>
</item>
<item>
    <type>636f7265</type>
    <code>6d696964</code>
    <length>4</length>
    <data encoding="base64">AAAi5g==</data>
</item>
<item>
    <type>636f7265</type>
    <code>6d696e6d</code>
    <length>6</length>
    <data encoding="base64">U2hhZG93</data>
</item>
<item>
    <type>636f7265</type>
    <code>6d706572</code>
    <length>8</length>
    <data encoding="base64">WBpsnFGTgRk=</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736462</code>
    <length>1</length>
    <data encoding="base64"/>
</item>
<item>
    <type>636f7265</type>
    <code>61654e56</code>
    <length>4</length>
    <data encoding="base64">AAANMA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>6173646b</code>
    <length>1</length>
    <data encoding="base64">AA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736274</code>
    <length>2</length>
    <data encoding="base64">AAA=</data>
[MISSING /item]
<item>
    <type>636f7265</type>
    <code>61677270</code>
    <length>0</length>
</item>
<item>
    <type>636f7265</type>
    <code>61736364</code>
    <length>4</length>
    <data encoding="base64">bXA0YQ==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736373</code>
    <length>4</length>
    <data encoding="base64">AAAAAg==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61655043</code>
    <length>1</length>
    <data encoding="base64">AA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736374</code>
    <length>0</length>
</item>
<item>
    <type>636f7265</type>
    <code>6173636e</code>
    <length>0</length>
</item>
<item>
    <type>636f7265</type>
    <code>61736372</code>
    <length>1</length>
    <data encoding="base64">AA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61654856</code>
    <length>1</length>
    <data encoding="base64">AA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61654d4b</code>
    <length>1</length>
    <data encoding="base64">AQ==</data>
</item>
<item>
    <type>636f7265</type>
    <code>6165534e</code>
    <length>0</length>
</item>
<item>
    <type>636f7265</type>
    <code>6165454e</code>
    <length>0</length>
</item>
<item>
    <type>636f7265</type>
    <code>61654553</code>
    <length>4</length>
    <data encoding="base64">AAAAAA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61655355</code>
    <length>4</length>
    <data encoding="base64">AAAAAA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61654748</code>
    <length>4</length>
    <data encoding="base64">AAAAAQ==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61654744</code>
    <length>4</length>
    <data encoding="base64">AAADoA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61654755</code>
    <length>8</length>
    <data encoding="base64">AAAAAACiuCA=</data>
</item>
<item>
    <type>636f7265</type>
    <code>61654752</code>
    <length>8</length>
    <data encoding="base64">AAAAAAAAAAA=</data>
</item>
<item>
    <type>636f7265</type>
    <code>61654745</code>
    <length>4</length>
    <data encoding="base64">AAAIQA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736161</code>
    <length>0</length>
</item>
<item>
    <type>636f7265</type>
    <code>61736770</code>
    <length>1</length>
    <data encoding="base64">AA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>6d657874</code>
    <length>2</length>
    <data encoding="base64">AAE=</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736564</code>
    <length>2</length>
    <data encoding="base64">AAE=</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736870</code>
    <length>1</length>
    <data encoding="base64">AQ==</data>
</item>
<item>
    <type>636f7265</type>
    <code>6173736e</code>
    <length>0</length>
</item>
<item>
    <type>636f7265</type>
    <code>61737361</code>
    <length>0</length>
</item>
<item>
    <type>636f7265</type>
    <code>6173736c</code>
    <length>0</length>
</item>
<item>
    <type>636f7265</type>
    <code>61737375</code>
    <length>14</length>
    <data encoding="base64">QmVhdXRpZnVsIExpZXM=</data>
</item>
<item>
    <type>636f7265</type>
    <code>61737363</code>
    <length>0</length>
</item>
<item>
    <type>636f7265</type>
    <code>61737373</code>
    <length>0</length>
</item>
<item>
    <type>636f7265</type>
    <code>6173626b</code>
    <length>1</length>
    <data encoding="base64">AA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61737075</code>
    <length>0</length>
</item>
<item>
    <type>636f7265</type>
    <code>61654352</code>
    <length>0</length>
</item>
<item>
    <type>636f7265</type>
    <code>61736169</code>
    <length>8</length>
    <data encoding="base64"/>
</item>
<item>
    <type>636f7265</type>
    <code>61736c73</code>
    <length>8</length>
    <data encoding="base64">AAAAAAB/QxI=</data>
</item>
<item>
    <type>636f7265</type>
    <code>61655345</code>
    <length>8</length>
    <data encoding="base64">AAAAAD/yJPs=</data>
</item>
<item>
    <type>636f7265</type>
    <code>61654456</code>
    <length>4</length>
    <data encoding="base64">AAAAAA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61654450</code>
    <length>4</length>
    <data encoding="base64">AAAAAA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61654452</code>
    <length>8</length>
    <data encoding="base64">AAAAAAAAAAA=</data>
</item>
<item>
    <type>636f7265</type>
    <code>61654e44</code>
    <length>8</length>
    <data encoding="base64">AAAAAAAAAAA=</data>
</item>
<item>
    <type>636f7265</type>
    <code>61654b31</code>
    <length>8</length>
    <data encoding="base64">AAAAAAAAAAA=</data>
</item>
<item>
    <type>636f7265</type>
    <code>61654b32</code>
    <length>8</length>
    <data encoding="base64">AAAAAAAAAAA=</data>
</item>
<item>
    <type>636f7265</type>
    <code>6165444c</code>
    <length>8</length>
    <data encoding="base64">AAAAAAAAAAA=</data>
</item>
<item>
    <type>636f7265</type>
    <code>61654641</code>
    <length>8</length>
    <data encoding="base64">AAAAAAAAAAA=</data>
</item>
<item>
    <type>636f7265</type>
    <code>61655844</code>
    <length>0</length>
</item>
<item>
    <type>636f7265</type>
    <code>61654d6b</code>
    <length>4</length>
    <data encoding="base64">AAAAAQ==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61654d58</code>
    <length>0</length>
</item>
<item>
    <type>636f7265</type>
    <code>61737063</code>
    <length>4</length>
    <data encoding="base64">AAAAEg==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61737269</code>
    <length>8</length>
    <data encoding="base64">W5TJsSOxcuA=</data>
</item>
<item>
    <type>636f7265</type>
    <code>61654353</code>
    <length>4</length>
    <data encoding="base64">aEm4Tg==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736b70</code>
    <length>4</length>
    <data encoding="base64">AAAAAA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736163</code>
    <length>2</length>
    <data encoding="base64">AAE=</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736b64</code>
    <length>4</length>
    <data encoding="base64">g9ozYA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>6d647374</code>
    <length>1</length>
    <data encoding="base64">AQ==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736573</code>
    <length>1</length>
    <data encoding="base64">AA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61737273</code>
    <length>1</length>
    <data encoding="base64">AA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736c72</code>
    <length>1</length>
    <data encoding="base64">UA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61736173</code>
    <length>1</length>
    <data encoding="base64">IA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61654773</code>
    <length>1</length>
    <data encoding="base64">AA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>61656c73</code>
    <length>1</length>
    <data encoding="base64">AA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>616a616c</code>
    <length>1</length>
    <data encoding="base64">AA==</data>
</item>
<item>
    <type>636f7265</type>
    <code>616a6341</code>
    <length>1</length>
    <data encoding="base64">AA==</data>
</item>
<item>
    <type>73736e63</type>
    <code>6d64656e</code>
    <length>10</length>
    <data encoding="base64">MTU2NDE5OTY2MQ==</data>
</item>
<item>
    <type>73736e63</type>
    <code>70637374</code>
    <length>10</length>
    <data encoding="base64">MTU2NDE5OTY2MQ==</data>
</item>
<item>
    <type>73736e63</type>
    <code>50494354</code>
    <length>48899</length>
    <data encoding="base64">[...]
[MISSING /data]
</item>
</item>
</item>

last item is artwork.

mikebrady commented 8 years ago

Thanks. Was anything strange written to the log, by any chance?

mikebrady commented 8 years ago

Also, could you say what are you running Shairport Sync on, please?

mikebrady commented 8 years ago

The thing is, I'd like to try to replicate the problem on one of my own machines.

roblan commented 8 years ago

Nothing strange I think. But I haven set logging level.

I'm running it on raspberry Pi 2 B with official wifi dongle. It only happens when artworks in metadata are enabled I think.

roblan commented 8 years ago

I'll check if it also happens on wired connection and on CHIP.

mikebrady commented 8 years ago

Thanks for that. I'll try to set up that scenario.

mikebrady commented 8 years ago

No luck using a Pi 3 with built-in WiFi, which I guess i not too far off a Pi 2 with official WiFi. I'm going to have to try a more in-depth approach to this – I'll try to write a streaming XML grammar checker. It might take some time.™

roblan commented 8 years ago

After comparing the otuput from CHIP and RasPi it looks like there is something odd only on my Pi. XML on CHIP looks 100% correct.

It looks like my node.js metadata stream reader breaks something, because when it's not started xml seems to be fine. So it looks like there is something wrong in my code.

After some experimenting it looks like just doing

require('fs').createReadStream('/tmp/shairport-sync-metadata')

is messing with metadata stream...

mikebrady commented 8 years ago

Thanks for the update. I'll keep looking at this end too, as your reports made me look a lot closer at the code and I did find issues with it. I haven't been able to detect errors in the output in the last few days though, using xmllint and the like.

roblan commented 8 years ago

I've a few questions :) Is reading metadata-pipe using cat is ok? Should it be possible to read it "multiple" times (eq. using cat multiple times)? Because as I've found out that this is what causes my problem (there was my meta reader in the background, when I was using cat). It's also visible when I run shairport-sync-metadata-reader multiple times - each reader gets only part of the stream. Should it work that way? If only one process can read pipe then I've been debugging it all wrong and it's possible that there's nothing wrong and issue can be closed.

mikebrady commented 8 years ago

It's perfectly valid to use cat alright, or you can use the metadata pipe feed as stdin to programs. It's not okay to have multiple readers though – each byte in the pipe can only be read once; see, for example, http://stackoverflow.com/questions/20597149/multiple-read-processes-of-the-same-pipe-can-all-read-the-same-message. You might be able to use the UNIX tee utility to make copies of the pipe's output.

By the way, I've improved the error checking on shairport-sync-metadata-reader and I believe it will pick up malformed data coming from Shairport Sync. So far, not a peep. So maybe we can close this issue?

roblan commented 8 years ago

As it turns out that my debugging method was clearly wrong :)

mikebrady commented 8 years ago

Thanks. It was a useful exercise at this end.

mikebrady / shairport-sync

random </item> in metadata pipe #239