search

philippe44 / LMS-ShairTunes2W

Airtunes with LMS (fork of https://github.com/disaster123/shairport2_plugin)
65 stars 3 forks source link

consistent socket failure on stream start #10

Closed simeonpilgrim closed 7 years ago

simeonpilgrim commented 7 years ago

When I start streaming I notice in the logs I always get the same error, which seems strange to me, looking at the code I cannot piece together what happening, but I have by SB3 on the other side of a powerline ethernet bridge, as wifi was inconsistent (yet apple tv is happy over both in same spot), and since going to the powerline bridge, the latency of seeing the SB3 as a airplay device takes 3-5 seconds and there is a latency of about that to start playing.. thus I started looking into the logs..

I could plug into ethernet next to server and see if I get there error's still (which might make them harmless)

[12:57:13.811] main:272 client: 192.168.178.20
[12:57:13.813] hairtunes_init:264 [02572240]: Using FLAC
[12:57:13.814] rtp_request_timing:635 [02572240]: timing request now:1345589781 (port: 56387)
[12:57:13.814] rtp_request_timing:635 [02572240]: timing request now:1345589781 (port: 56387)
[12:57:13.814] rtp_request_timing:635 [02572240]: timing request now:1345589781 (port: 56387)
[12:57:13.897] rtp_thread_func:616 [02572240]: Timing references local:1345589781, remote:83aa91c02ff74309 (delta:0, sum:0, adjust:0, gaps:0)
[12:57:13.897] rtp_thread_func:616 [02572240]: Timing references local:1345589781, remote:83aa91c0300f14db (delta:-1, sum:-1, adjust:0, gaps:0)
[12:57:13.898] rtp_thread_func:616 [02572240]: Timing references local:1345589781, remote:83aa91c0300fcc02 (delta:-1, sum:-2, adjust:0, gaps:0)
[12:57:13.991] http_thread_func:776 [02572240]: got HTTP connection 452
[12:57:13.993] handle_http:862 [02572240]: received GET
[12:57:13.993] handle_http:873 [02572240]: responding:
HTTP/1.0 200 OK

Server: HairTunes

Connection: close

Content-Type: audio/flac

[12:57:14.039] rtp_thread_func:542 [02572240]: 1st sync packet received
[12:57:14.039] rtp_thread_func:546 [02572240]: sync packet rtp_latency:1781734752 rtp:1781811927 remote ntp:83aa91c054824f74, local time 1345589923 (now:1345590000)
[12:57:14.039] rtp_request_timing:635 [02572240]: timing request now:1345590000 (port: 56387)
[12:57:14.042] rtp_thread_func:616 [02572240]: Timing references local:1345590000, remote:83aa91c05541bcf2 (delta:73, sum:71, adjust:0, gaps:1)
[12:57:14.110] rtp_thread_func:542 [02572240]: 1st sync packet received
[12:57:14.110] rtp_thread_func:546 [02572240]: sync packet rtp_latency:1781737873 rtp:1781815048 remote ntp:83aa91c066a05b64, local time 1345590067 (now:1345590078)
[12:57:14.116] hairtunes_flush:332 [02572240]: FLUSH ignored as seqno (53576) <= ab_read (0)
[12:57:14.121] read_line:975 fd: 452 read error: Error 0

[12:57:14.121] http_parse:897 cannot read method
[12:57:14.121] http_thread_func:793 HTTP close 452
[12:57:14.139] buffer_put_packet:415 [02572240]: buffer fill status [level:65535] [W:53575 R:53576]
[12:57:14.216] http_thread_func:776 [02572240]: got HTTP connection 456
[12:57:14.217] handle_http:862 [02572240]: received GET
[12:57:14.217] handle_http:873 [02572240]: responding:
HTTP/1.0 200 OK

Server: HairTunes

Connection: close

Content-Type: audio/flac

[12:57:15.110] buffer_get_frame:721 [02572240]: buffer drain status [level:121] [W:53697 R:53576]
[12:57:15.130] rtp_thread_func:546 [02572240]: sync packet rtp_latency:1781782826 rtp:1781860001 remote ntp:83aa91c16b93fb10, local time 1345591087 (now:1345591093)
[12:57:16.149] rtp_thread_func:546 [02572240]: sync packet rtp_latency:1781827812 rtp:1781904987 remote ntp:83aa91c270b8a520, local time 1345592107 (now:1345592109)

server log from same period:

[17-08-26 12:56:38.3986] main::init (388) Starting Logitech Media Server (v7.9.0, 1488878280, Wed Mar  8 14:37:44 CUT 2017) perl 5.014001 - MSWin32-x86-multi-thread
[17-08-26 12:56:43.6180] Plugins::ShairTunes2W::Plugin::publishPlayer (369) avahi-publish-player not in path
[17-08-26 12:56:43.6732] Plugins::ShairTunes2W::Plugin::publishPlayer (377) dns-sd not in path
[17-08-26 12:56:43.7274] Plugins::ShairTunes2W::Plugin::publishPlayer (385) mDNSPublish not in path
[17-08-26 12:56:43.7276] Plugins::ShairTunes2W::Plugin::publishPlayer (387) using built-in helper: C:\PROGRA~3\SQUEEZ~1\Cache\INSTAL~1\Plugins\SHAIRT~1\Bin\SHAIRP~1.EXE
[17-08-26 12:56:43.7321] Plugins::ShairTunes2W::Plugin::playerSubscriptionChange (280) create client Slim::Player::Squeezebox2=ARRAY(0xa8c01dc) with proc Proc::Background=HASH(0xaabca9c)
[17-08-26 12:57:12.5955] Plugins::ShairTunes2W::Plugin::handleSocketConnect (402) New connection from: 192.168.178.20
[17-08-26 12:57:12.5986] Plugins::ShairTunes2W::Plugin::conn_handle_request (752) DACP-ID: 9F7214CA84AFC648, Active Remote: 2772619289
[17-08-26 12:57:12.6707] Plugins::ShairTunes2W::Plugin::conn_handle_request (752) DACP-ID: 9F7214CA84AFC648, Active Remote: 2772619289
[17-08-26 12:57:13.7447] Plugins::ShairTunes2W::Plugin::conn_handle_request (752) DACP-ID: 9F7214CA84AFC648, Active Remote: 2772619289
[17-08-26 12:57:13.7876] Plugins::ShairTunes2W::Plugin::conn_handle_request (816) decode command: $VAR1 = 'host';
$VAR2 = '192.168.178.20';
$VAR3 = 'socket';
$VAR4 = '54396,54397,54398';
$VAR5 = 'iv';
$VAR6 = '833ce04f9521e57f2a28454ed36a3c41';
$VAR7 = 'key';
$VAR8 = '790761759d68b358897c009a060beb93';
$VAR9 = 'fmtp';
$VAR10 = '96 352 0 16 40 10 14 2 255 0 0 44100';
$VAR11 = 'cport';
$VAR12 = '65379';
$VAR13 = 'tport';
$VAR14 = '56387';
$VAR15 = 'latency';
$VAR16 = 1000;
$VAR17 = 'log';
$VAR18 = 'C:\\ProgramData\\Squeezebox\\Logs\\shairtunes2-00-04-20-12-38-24.log';
$VAR19 = 'dbg';
$VAR20 = 'debug';
$VAR21 = 'flac';
$VAR22 = 'sync';
[17-08-26 12:57:13.8146] Plugins::ShairTunes2W::Plugin::conn_handle_request (859) launched decoder: Proc::Background=HASH(0xaabcfbc) on ports: 57426/57427/57428/54402, http port: 54393
[17-08-26 12:57:13.9017] Plugins::ShairTunes2W::Plugin::conn_handle_request (879) Playing url: airplay://192.168.178.27:54402/508e68c1cab087d15fd2a41a3a7916e9_stream.flc
[17-08-26 12:57:14.0499] Plugins::ShairTunes2W::Plugin::conn_handle_request (944) sending-> vol: 69
[17-08-26 12:57:14.1170] Plugins::ShairTunes2W::Plugin::conn_handle_request (897) Flush up to 53576, 1781820559
[17-08-26 12:57:14.1195] Plugins::ShairTunes2W::Plugin::handleHelperOut (502) From helper: flushed 53576
[17-08-26 12:57:14.2090] Plugins::ShairTunes2W::Plugin::handleHelperOut (502) From helper: play
[17-08-26 12:57:16.1244] Plugins::ShairTunes2W::Plugin::conn_handle_request (744) Decoder error: shairport_helper: VERSION: 0.72.6
[17-08-26 12:57:16.1253] Plugins::ShairTunes2W::Plugin::conn_handle_request (752) DACP-ID: 9F7214CA84AFC648, Active Remote: 2772619289
[17-08-26 12:57:16.5145] Plugins::ShairTunes2W::Plugin::mDNSlistener (1057) Found remote: 9F7214CA84AFC648, 192.168.178.20:49872
simeonpilgrim commented 7 years ago

Ok, so moved the device next to server, and it behaved the same, then I change to not using flac and 500ms latency, instead of 1000ms and it definitly faster, but the error still happens...

[13:34:29.602] read_line:975 fd: 480 read error: Error 0

which is not really the fault of your windows port, as best I can tell.

philippe44 commented 7 years ago

It seems to me it's really the SB slamming the HTTP door at the helper. It's strange that moving away from flac helps. 500 ms instead of 1000 ms definitively causes the helper to "release" RTP (UDP) frames into HTTP(TCP) packets sooner, but you're on the edge here as there is less room for requesting RTP packets re-send when some are missed. Maybe the SB3 does not like my response to its 1st GET - I'll try with my SB3 as well, never used it before

[edit]: no, my SB3 does not close the socket to re-open it right after. Maybe you coudl try to Wireshark a bit what's happening

simeonpilgrim commented 7 years ago

ok, I can try that..

simeonpilgrim commented 7 years ago

both http sessions are identical from the transmitted data perspective.

except the first one fails before getting to equivalent of Packet 489 

GET /185784643567004b7880577bc486a659_stream.wav HTTP/1.0
Cache-Control: no-cache
Connection: close
Accept: */*
Host: 192.168.178.27:50010
User-Agent: iTunes/4.7.1 (Windows; N; Windows 10; 8664; EN; cp1252) SqueezeCenter, Squeezebox Server, Logitech Media Server/7.9.0/1488878280
Icy-Metadata: 1

HTTP/1.0 200 OK
Server: HairTunes
Connection: close
Content-Type: audio/L16;rate=44100;channels=2

..................................................................................................................................................................................................................................................................................................................  ... ... ... .....................................................................   ...
...
.

char peer0_0[] = { /* Packet 338 */
char peer1_0[] = { /* Packet 339 */
char peer0_1[] = { /* Packet 351 */
char peer0_2[] = { /* Packet 352 */
0x47, 0x45, 0x54, 0x20, 0x2f, 0x31, 0x38, 0x35, 
0x37, 0x38, 0x34, 0x36, 0x34, 0x33, 0x35, 0x36, 
0x37, 0x30, 0x30, 0x34, 0x62, 0x37, 0x38, 0x38, 
0x30, 0x35, 0x37, 0x37, 0x62, 0x63, 0x34, 0x38, 
0x36, 0x61, 0x36, 0x35, 0x39, 0x5f, 0x73, 0x74, 
0x72, 0x65, 0x61, 0x6d, 0x2e, 0x77, 0x61, 0x76, 
0x20, 0x48, 0x54, 0x54, 0x50, 0x2f, 0x31, 0x2e, 
0x30, 0x0d, 0x0a, 0x43, 0x61, 0x63, 0x68, 0x65, 
0x2d, 0x43, 0x6f, 0x6e, 0x74, 0x72, 0x6f, 0x6c, 
0x3a, 0x20, 0x6e, 0x6f, 0x2d, 0x63, 0x61, 0x63, 
0x68, 0x65, 0x0d, 0x0a, 0x43, 0x6f, 0x6e, 0x6e, 
0x65, 0x63, 0x74, 0x69, 0x6f, 0x6e, 0x3a, 0x20, 
0x63, 0x6c, 0x6f, 0x73, 0x65, 0x0d, 0x0a, 0x41, 
0x63, 0x63, 0x65, 0x70, 0x74, 0x3a, 0x20, 0x2a, 
0x2f, 0x2a, 0x0d, 0x0a, 0x48, 0x6f, 0x73, 0x74, 
0x3a, 0x20, 0x31, 0x39, 0x32, 0x2e, 0x31, 0x36, 
0x38, 0x2e, 0x31, 0x37, 0x38, 0x2e, 0x32, 0x37, 
0x3a, 0x35, 0x30, 0x30, 0x31, 0x30, 0x0d, 0x0a, 
0x55, 0x73, 0x65, 0x72, 0x2d, 0x41, 0x67, 0x65, 
0x6e, 0x74, 0x3a, 0x20, 0x69, 0x54, 0x75, 0x6e, 
0x65, 0x73, 0x2f, 0x34, 0x2e, 0x37, 0x2e, 0x31, 
0x20, 0x28, 0x57, 0x69, 0x6e, 0x64, 0x6f, 0x77, 
0x73, 0x3b, 0x20, 0x4e, 0x3b, 0x20, 0x57, 0x69, 
0x6e, 0x64, 0x6f, 0x77, 0x73, 0x20, 0x31, 0x30, 
0x3b, 0x20, 0x38, 0x36, 0x36, 0x34, 0x3b, 0x20, 
0x45, 0x4e, 0x3b, 0x20, 0x63, 0x70, 0x31, 0x32, 
0x35, 0x32, 0x29, 0x20, 0x53, 0x71, 0x75, 0x65, 
0x65, 0x7a, 0x65, 0x43, 0x65, 0x6e, 0x74, 0x65, 
0x72, 0x2c, 0x20, 0x53, 0x71, 0x75, 0x65, 0x65, 
0x7a, 0x65, 0x62, 0x6f, 0x78, 0x20, 0x53, 0x65, 
0x72, 0x76, 0x65, 0x72, 0x2c, 0x20, 0x4c, 0x6f, 
0x67, 0x69, 0x74, 0x65, 0x63, 0x68, 0x20, 0x4d, 
0x65, 0x64, 0x69, 0x61, 0x20, 0x53, 0x65, 0x72, 
0x76, 0x65, 0x72, 0x2f, 0x37, 0x2e, 0x39, 0x2e, 
0x30, 0x2f, 0x31, 0x34, 0x38, 0x38, 0x38, 0x37, 
0x38, 0x32, 0x38, 0x30, 0x0d, 0x0a, 0x49, 0x63, 
0x79, 0x2d, 0x4d, 0x65, 0x74, 0x61, 0x64, 0x61, 
0x74, 0x61, 0x3a, 0x20, 0x31, 0x0d, 0x0a, 0x0d, 
0x0a };
char peer1_1[] = { /* Packet 358 */
0x48, 0x54, 0x54, 0x50, 0x2f, 0x31, 0x2e, 0x30, 
0x20, 0x32, 0x30, 0x30, 0x20, 0x4f, 0x4b, 0x0d, 
0x0a, 0x53, 0x65, 0x72, 0x76, 0x65, 0x72, 0x3a, 
0x20, 0x48, 0x61, 0x69, 0x72, 0x54, 0x75, 0x6e, 
0x65, 0x73, 0x0d, 0x0a, 0x43, 0x6f, 0x6e, 0x6e, 
0x65, 0x63, 0x74, 0x69, 0x6f, 0x6e, 0x3a, 0x20, 
0x63, 0x6c, 0x6f, 0x73, 0x65, 0x0d, 0x0a, 0x43, 
0x6f, 0x6e, 0x74, 0x65, 0x6e, 0x74, 0x2d, 0x54, 
0x79, 0x70, 0x65, 0x3a, 0x20, 0x61, 0x75, 0x64, 
0x69, 0x6f, 0x2f, 0x4c, 0x31, 0x36, 0x3b, 0x72, 
0x61, 0x74, 0x65, 0x3d, 0x34, 0x34, 0x31, 0x30, 
0x30, 0x3b, 0x63, 0x68, 0x61, 0x6e, 0x6e, 0x65, 
0x6c, 0x73, 0x3d, 0x32, 0x0d, 0x0a, 0x0d, 0x0a };
char peer1_2[] = { /* Packet 489 */
0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 
0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 
0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00,
philippe44 commented 7 years ago

is this still happening with recent version? (0.80.1)

simeonpilgrim commented 7 years ago 
[13:25:08.003] main:250 client: 192.168.178.20, ipc port 49460
[13:25:08.004] rtp_request_timing:653 [024C2140]: timing request now:2040421812 (port: 60270)
[13:25:08.004] rtp_request_timing:653 [024C2140]: timing request now:2040421812 (port: 60270)
[13:25:08.004] rtp_request_timing:653 [024C2140]: timing request now:2040421812 (port: 60270)
[13:25:08.007] rtp_thread_func:634 [024C2140]: Timing references local:2040421812, remote:83b40b57f2967ec7 (delta:0, sum:0, adjust:0, gaps:0)
[13:25:08.008] rtp_thread_func:634 [024C2140]: Timing references local:2040421812, remote:83b40b57f298ea23 (delta:-1, sum:-1, adjust:0, gaps:0)
[13:25:08.008] rtp_thread_func:634 [024C2140]: Timing references local:2040421812, remote:83b40b57f2b0fcf8 (delta:-1, sum:-2, adjust:0, gaps:0)
[13:25:08.084] http_thread_func:804 [024C2140]: got HTTP connection 444 (silent frames 250)
[13:25:08.087] handle_http:916 [024C2140]: received GET
[13:25:08.087] handle_http:926 [024C2140]: responding:
HTTP/1.0 200 OK

Server: HairTunes

Connection: close

Content-Type: audio/wav

[13:25:08.092] rtp_thread_func:559 [024C2140]: 1st sync packet received
[13:25:08.092] rtp_thread_func:563 [024C2140]: sync packet rtp_latency:1051325780 rtp:1051402955 remote ntp:83b40b5808723dfc, local time 2040421896 (now:2040421906)
[13:25:08.092] rtp_request_timing:653 [024C2140]: timing request now:2040421906 (port: 60270)
[13:25:08.096] rtp_thread_func:634 [024C2140]: Timing references local:2040421906, remote:83b40b58094110fa (delta:5, sum:3, adjust:0, gaps:0)
[13:25:08.135] rtp_thread_func:559 [024C2140]: 1st sync packet received
[13:25:08.135] rtp_thread_func:563 [024C2140]: sync packet rtp_latency:1051327682 rtp:1051404857 remote ntp:83b40b58137cc2c4, local time 2040421945 (now:2040421953)
[13:25:08.223] buffer_put_packet:427 [024C2140]: buffer fill status [level:65535] [W:11423 R:11424]
[13:25:08.259] hairtunes_flush:342 [024C2140]: FLUSH ignored as seqno (11424) <= ab_read (11424)
[13:25:08.409] http_thread_func:854 [024C2140]: spent 312 ms in send!
[13:25:08.564] buffer_get_frame:748 [024C2140]: buffer drain status [level:51] [W:11475 R:11424]
[13:25:09.154] rtp_thread_func:563 [024C2140]: sync packet rtp_latency:1051372659 rtp:1051449834 remote ntp:83b40b5918940ce8, local time 2040422965 (now:2040422968)
[13:25:10.175] rtp_thread_func:563 [024C2140]: sync packet rtp_latency:1051417646 rtp:1051494821 remote ntp:83b40b5a1dba3368, local time 2040423985 (now:2040423984)
[13:25:11.195] rtp_thread_func:563 [024C2140]: sync packet rtp_latency:1051462627 rtp:1051539802 remote ntp:83b40b5b22d76f48, local time 2040425005 (now:2040425000)
[13:25:11.195] rtp_request_timing:653 [024C2140]: timing request now:2040425000 (port: 60270)
[13:25:11.199] rtp_thread_func:634 [024C2140]: Timing references local:2040425000, remote:83b40b5b23c85e3d (delta:-10, sum:-7, adjust:0, gaps:0)
[13:25:12.215] rtp_thread_func:563 [024C2140]: sync packet rtp_latency:1051507610 rtp:1051584785 remote ntp:83b40b5c27f7a40c, local time 2040426016 (now:2040426031)
[13:25:12.247] buffer_put_packet:427 [024C2140]: buffer fill status [level:3] [W:11935 R:11932]
[13:25:12.250] buffer_get_frame:748 [024C2140]: buffer drain status [level:1] [W:11937 R:11936]
[13:25:13.235] rtp_thread_func:563 [024C2140]: sync packet rtp_latency:1051552593 rtp:1051629768 remote ntp:83b40b5d2d17d8cc, local time 2040427036 (now:2040427046)
[13:25:14.254] rtp_thread_func:563 [024C2140]: sync packet rtp_latency:1051597566 rtp:1051674741 remote ntp:83b40b5e32293130, local time 2040428056 (now:2040428062)
[13:25:15.275] rtp_thread_func:563 [024C2140]: sync packet rtp_latency:1051642559 rtp:1051719734 remote ntp:83b40b5f37584250, local time 2040429076 (now:2040429078)
[13:25:15.275] rtp_request_timing:653 [024C2140]: timing request now:2040429078 (port: 60270)
[13:25:15.277] rtp_thread_func:634 [024C2140]: Timing references local:2040429078, remote:83b40b5f37ed6777 (delta:-1, sum:-8, adjust:0, gaps:0)
[13:25:16.295] rtp_thread_func:563 [024C2140]: sync packet rtp_latency:1051687535 rtp:1051764710 remote ntp:83b40b603c6e1004, local time 2040430095 (now:2040430109)
[13:25:16.358] buffer_put_packet:427 [024C2140]: buffer fill status [level:0] [W:12447 R:12447]
[13:25:16.361] buffer_get_frame:748 [024C2140]: buffer drain status [level:4] [W:12452 R:12448]
[13:25:17.315] rtp_thread_func:563 [024C2140]: sync packet rtp_latency:1051732520 rtp:1051809695 remote ntp:83b40b6141913da4, local time 2040431115 (now:2040431125)

Fixed..

philippe44 commented 7 years ago

Good