search

philippe44 / AirConnect

Use AirPlay to stream to UPnP/Sonos & Chromecast devices
Other
3.58k stars 219 forks source link

html_parse problem with airupnp and aircast crashes the apps #39

Closed pbg4 closed 6 years ago

pbg4 commented 6 years ago

Hi Philippe, thanks a lot for this great project!!

one problem here:

I have compiled both aircast and airupnp from source on an ubuntu trusty x86_64 system, installed some init scripts and have both running as daemon processes, with an lms 7.9.1 server on the same system,..

everything works quite nicely, but from time to time there are problems like this when I stream remotely from an iTunes server on an mac to a sonos play5 with airupnp:

RTSP/1.0 200 OK Audio-Jack-Status: connected; type=analog CSeq: 7

[14:56:15.384438] http_parse:932 Request failed, bad header Error in `/usr/bin/airupnp': double free or corruption (fasttop): 0x00007f7448173290

and the daemon is dead and must get restartet,...

when I stream with aircast to a chromecast audio to the analog in of the sonos play5 its the same problem there:

[18:25:35.965617] handle_rtsp:341 [0x7fda600011f0]: received SET_PARAMETER

RTSP/1.0 200 OK Audio-Jack-Status: connected; type=analog CSeq: 52

[18:25:35.969446] http_parse:932 Request failed, bad header Error in `../bin/aircast-x86-64': double free or corruption (fasttop): 0x00007fda60001c00 than the daemons are dead and have to be restarted,..

this can be tracked down to the http_parse function in common/util.c when the http socket is analysed and a string compare for ":" ends unsuccessfull,.. mmh,

this also happens with the original precompiled binaries in your package, that is also why I have compiled both apps natively on my server, but this has not changed it..

please have a look into the problem, best wishes pbg4

philippe44 commented 6 years ago

You're brave :-) Maybe someting with the /configure of each library (flac) in x64 mode. Did you look at the libssl version issue? (does not start normally) ...best is that you compile with full symbols (no -s) in makefile and run gdb to see where it crashes, do not run it daemon mode of course

pbg4 commented 6 years ago

Hi, have to check with libFLAC, the flac version was the flac 1.3.2-1 ubuntu version with ogg disabled, because there were problems with missing symbols when linking airupnp and aircast with ogg enabled in libFLAC, ..

libssl is libssl1.0.0:amd64 1.0.1f-1ubuntu2.23,.. should be OK,

I had meanwhile already plastered http_parse with some printf("%s\n",line); and thus can log all calls to http_parse to the console, it runs than for quite a while, all the http_parse calls are logged correctly by the printf's,.. but finally freaks out when there is complete garbage in the http socket e.g. something like this:

??r??RS??T?3n???qo?|?G?\q??o٭_??r<G?x%

have to run it with gdb,.. weird

pbg4 commented 6 years ago

Hi, changed now the libFLAC-static.a from ubuntu package 1.3.2-1 to 1.3.2 from https://xiph.org/flac/ and compiled with Ogg enabled, aircast is now running for an hour or so together with the printf's still enabled in the console,.. test goes on,..

pbg4 commented 6 years ago

Hi Philippe,

with the aircast app running under gdb it took full 6 hours until finally the crash happened,..

the missing raise.c in the backtrace below belongs to /usr/src/eglibc-2.19/nptl/sysdeps/unix/sysv/linux/raise.c which is for embedded systems and not installed here on the x86_64 server system,..

here follows the backtrace, perhaps you can read something meaningful out of that Philippe:

[17:29:19.328574] handle_rtsp:341 [0x7fffec0011f0]: received SET_PARAMETER

RTSP/1.0 200 OK Audio-Jack-Status: connected; type=analog CSeq: 130

[17:29:19.329654] http_parse:907 http_parse, line http-socket content <--- error print from me ---> here content of line[256] empty [17:29:19.331785] http_parse:934 Request failed, bad header <--- here search for ":" in line =oe?ˈ?K4?9????i???f9{.??????&????I?tO??~p@'#om?I?? <-------- garbage print of line[256],.. V???F⎻????(⎽≠? ^??┬ْ?ˌɖ?\? ?␊???????????9??2?? 2????˗??7?7?│?┬┘␋?%????%⎺.?└?Ɨ??&PV[<???&ZC≥␊?⎻+??±?V@O├?£Џ?8⎼?E????????⎺Y??◆⎻??M?O?│ګM?8???????$?? ??????̘?/ Error in `/usr/src/AirConnect/bin/aircast-x86-64': double free or corruption (fasttop): 0x00007fffec008b30

Program received signal SIGABRT, Aborted. [Switching to Thread 0x7ffff4aa1700 (LWP 16829)] 0x00007ffff6ce0c37 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56 56 ../nptl/sysdeps/unix/sysv/linux/raise.c: Datei oder Verzeichnis nicht gefunden.

(gdb) backtrace

0 0x00007ffff6ce0c37 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56

1 0x00007ffff6ce4028 in __GI_abort () at abort.c:89

2 0x00007ffff6d1d2a4 in __libc_message (do_abort=do_abort@entry=1, fmt=fmt@entry=0x7ffff6e2f350 " Error in `%s': %s: 0x%s \n") at ../sysdeps/posix/libc_fatal.c:175

3 0x00007ffff6d2982e in malloc_printerr (ptr=, str=0x7ffff6e2f518 "double free or corruption (fasttop)", action=1) at malloc.c:4998

4 _int_free (av=, p=, have_lock=0) at malloc.c:3842

5 0x000000000040f4e3 in kd_free (kd=kd@entry=0x7ffff4aa0aa0) at ../common/util.c:1070

6 0x000000000040f891 in http_parse (sock=sock@entry=8,

method=method@entry=0x7ffff4aa0ea0 "\277\317~\372\343\345\375\237\276ɉ\305A\227\023+\362栓\231ɱ-R/\250\263\241I\274\021\337%\003e[\274\357\031A$\024Mɑv\317\001\244\035\216\246\272\300\266\036\370\342+\360ix|\270e\216e\350\351\177?\377|\336\017\367lx\222wnx\206o\230h\276z\325\034\363w\343%\207\035\"\371\033\376\345~", rkd=rkd@entry=0x7ffff4aa0aa0, 
body=body@entry=0x7ffff4aa08f8, len=len@entry=0x7ffff4aa08f4) at ../common/util.c:937

7 0x000000000040d536 in handle_rtsp (sock=8, ctx=0x7fffec0011f0) at ../common/raopcore.c:338

8 rtsp_thread (arg=0x7fffec0011f0) at ../common/raopcore.c:315

9 0x00007ffff7bc4184 in start_thread (arg=0x7ffff4aa1700) at pthread_create.c:312

10 0x00007ffff6da803d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

philippe44 commented 6 years ago

okay, I got it - it's really a problem with the HTTP header. Still, it's not handled properly (and I also found a bug with a HTTP deprecated technique named 'header folding'). So, long story short here is a link to try https://www.dropbox.com/s/v2ck9a2foe16a2o/airupnp-x86-64?dl=0. This is brand new version I'm working on with a lot of changes, so it might have other issues, at least this one should not happen (welcome to unvoluntary beta-tester)

pbg4 commented 6 years ago

Hi, got it, test is running here, will report back,..

after some more time of testing now with airupnp-x86-64 2.0 beta the old http_parse problem seems to have gone now, what I have seen sometime "remove unresponsive player" for sonos devices and another new http_parse:993 content length receive error 2447849, (see my email)

but: what now runs amazingly well is the older version airupnp-x86-64 1.6.1 recompiled with -fstack-protector-strong,...

philippe44 commented 6 years ago

good - I've now uploaded a version 0.2.0.0 which contains many other fixes... and probably new issues. The "unresponsive player" is when one device does not responf to UPnP search or has not signaled himself to 2 minutes. In your version, there was a few issues which could lead to that player not being added back upon discovery, but this should be fixed

pbg4 commented 6 years ago

Hi, fine,.. than the tests can continue,.. as all my sonos devices are in rooms in the house where there is also LAN connection possible for the testing phase now I have disabled sonosnet over wifi completely http://:1400/wifictrl?wifi=persist-off, so all sonos devices are cabled and in the same LAN subnet, which makes device detection more consistent,..

will report back later, thanks!

... things have improved a lot, though there are still some glitches, have send error logs per email,.. too long for the issue tracker here,..

philippe44 commented 6 years ago

Any update here? I like to close issues whenever I can :-)

pbg4 commented 6 years ago

Hi, the html_parse problem has definitely gone, so you can close this issue,..

what still remains is that airupnp 0.2.0.2 stops randomly while playing music, the airupnp service is dead after that and has to be restarted, log follows :

[10:52:36.946291] buffer_put_packet:447 [0x7fe07c001e80]: fill status [level:0] [W:15806 R:15806] [10:52:36.956648] buffer_get_frame:782 [0x7fe07c001e80]: drain status [level:1] [W:15808 R:15807] [R:0 S:0] [10:52:37.004912] UpdateThread:640 [0x697a40]: removing unresponsive player (Kitchen+)

[10:52:37.025803] handle_rtsp:349 [0x7fe08c001c50]: received TEARDOWN Error in `/usr/bin/airupnp': double free or corruption (out): 0x00007fe07c0094a0 ^C root@nano4:/usr/src/AirConnect/airupnp# service airupnp status

codepeon commented 6 years ago

I had a similar issue. The easiest way of reproducing was to terminate the program while streaming. Try applying this patch and recompile and see if things start working better. https://github.com/codepeon/AirConnect/commit/9adeae232493fe8e9a50417b247ca6dd35349eae

philippe44 commented 6 years ago

try version 0.2.0.3 - it includes few fixes including the one by @codepeon

vladserkoff commented 6 years ago

Tried new version, for me there's no TEARDOWN error, but I still randomly (once in 30 minutes) get unresponsive player.

[13:13:24.931443] buffer_put_packet:447 [0x124d638]: fill status [level:0] [W:44743 R:44743]
[13:13:24.993116] buffer_get_frame:782 [0x124d638]: drain status [level:2] [W:44754 R:44752] [R:8 S:0]
[13:13:28.000175] UpdateThread:653 [0x87e44]: removing unresponsive player (Family Room+)
[13:13:28.008939] http_thread_func:943 [0x124d638]: terminating
[13:13:28.021877] rtp_thread_func:661 [0x124d638]: terminating
[13:14:08.301779] AddMRDevice:880 [0x87e44]: adding renderer (Family Room)
[13:14:08.309989] MasterHandler:588 [0x87e44]: subscribe success

I run AirConnect on raspberry pi 3 with suggested settings. The player is Sonos:1

pbg4 commented 6 years ago

Hi, just had some time to test v0.2.0.4 of airupnp, now in random intervals the http_parse problem is back again,..

`[13:46:23.648992] buffer_put_packet:447 [0x7fbb50001f20]: fill status [level:0] [W:64316 R:64316] [13:46:23.842959] buffer_get_frame:782 [0x7fbb50001f20]: drain status [level:1] [W:64341 R:64340] [R:0 S:0] [13:46:26.323523] handle_rtsp:353 [0x7fbb5400baf0]: received SET_PARAMETER

RTSP/1.0 200 OK Audio-Jack-Status: connected; type=analog CSeq: 46`

[13:46:26.325888] http_parse:1070 Request failed, bad header [13:46:26.326022] rtsp_thread:327 RTSP close 12 [13:46:27.736668] buffer_put_packet:447 [0x7fbb50001f20]: fill status [level:0] [W:64828 R:64828] [13:46:27.931027] buffer_get_frame:782 [0x7fbb50001f20]: drain status [level:1] [W:64853 R:64852] [R:0 S:0] [13:46:31.823511] buffer_put_packet:447 [0x7fbb50001f20]: fill status [level:0] [W:65340 R:65340]

rtsp packets are still send for a while until finally:

[13:46:44.084063] buffer_put_packet:447 [0x7fbb50001f20]: fill status [level:0] [W:1340 R:1340] [13:46:44.279044] buffer_get_frame:782 [0x7fbb50001f20]: drain status [level:1] [W:1365 R:1364] [R:0 S:0] [13:47:05.074899] http_thread_func:882 HTTP close 18 [13:47:05.113441] ActionHandler:464 [0x6995c8]: uPNP stopped ...,.. just another question,

the server on which airupnp is running as a process, is full with other processes which use upnp, ( an lsof -on|grep 1900 has more than 30 entries,... ) and on top than entries for airupnp and squeeze2upnp from the LMS plugin,

it seems to me as if new upnp announces when airupnp is started find their way very slowly to the receiving clients,.. for a while I had also globally installed a patched debian version of libupnp with the patches and config tweaks from squeeze2upnp, but was not shure if the other processes were really compatible with that, so I switched it back again,

if I compile airupnp as a static binary locally, should I use libupnp with patches from squeeze2upnp or without??, also the shared binary airupnp version of codepeon is not happy with the patched libupnp and segfaults,..

best wishes pbg4

philippe44 commented 6 years ago

you don't need a patched libupnp library for airupnp. I do not use shared libraries for any of these (squeeze2upnp/airupnp), anyway. Why are you referring to shared libs?

pbg4 commented 6 years ago

Hi, because for comparison I had also compiled the forked airupnp version of codepeon, there shared libs are used in the Makefile.x86-64 for the LDFLAGS with pkg-config,..

the logs above are from tests with the v0.2.0.4 static binaries from this repo of course,..

philippe44 commented 6 years ago

Can you set "util" log to sdebug ("-d util=sdebug") and log until the problem appears. I know log all the HTTP responses and should be able to see why this one causes a problem (lacking of a ":" in the HTTP header, even with line folding properly handled)

pbg4 commented 6 years ago

Hi, have it running now, with util=sdebug set in the xml config file, no problem until now, only some of these messages,...

[18:54:51.193374] XMLGetFirstDocumentItem:1332 Error finding CurrentTransportState in XML Node [18:54:52.433662] XMLGetFirstDocumentItem:1332 Error finding CurrentTransportState in XML Node [18:54:53.680621] XMLGetFirstDocumentItem:1332 Error finding CurrentTransportState in XML Node finally some problems:

`[19:23:48.273090] XMLGetFirstDocumentItem:1332 Error finding CurrentTransportState in XML Node [19:23:49.277417] XMLGetFirstDocumentItem:1332 Error finding CurrentTransportState in XML Node [19:23:49.629227] handle_rtsp:353 [0x7f4d8c00c990]: received SET_PARAMETER

RTSP/1.0 200 OK Audio-Jack-Status: connected; type=analog CSeq: 44 [19:23:49.635267] http_parse:1059 sock: 2668205904, received (null) [19:23:49.635374] http_parse:1072 Request failed, bad header [19:23:49.635652] rtsp_thread:327 RTSP close 16 [19:23:50.284109] XMLGetFirstDocumentItem:1332 Error finding CurrentTransportState in XML Node [19:23:51.282880] XMLGetFirstDocumentItem:1332 Error finding CurrentTransportState in XML Node ` snip

[19:24:09.677790] read_line:1131 disconnected on the other end 28 [19:24:09.678095] http_thread_func:885 HTTP close 28 [19:24:09.832757] XMLGetFirstDocumentItem:1332 Error finding CurrentTransportState in XML Node [19:24:09.861356] raop_notify:273 [0x7f4d8c00c990]: sending airplay remote GET /ctrl-int/1/stop HTTP/1.0 Active-Remote: 741607284 Connection: close <== received ==> HTTP/1.1 204 No Content Date: Sun, 18 Mar 2018 18:24:09 GMT DAAP-Server: iTunes/12.6.2.20 (OS X) Content-Type: application/x-dmap-tagged Content-Length: 0 [19:24:09.861483] ActionHandler:464 [0x697a40]: uPNP stopped

service airupnp is still running

`root@nano4:~# service airupnp status

philippe44 commented 6 years ago

These logs are not a problem - let's wait until we have the http_parse error

pbg4 commented 6 years ago

Hi, but these interuptions occur on a semiregular basis, every 10 -15 min,.. [21:47:47.256356] XMLGetFirstDocumentItem:1332 Error finding CurrentTransportState in XML Node [21:47:48.256391] XMLGetFirstDocumentItem:1332 Error finding CurrentTransportState in XML Node [21:47:49.152723] read_line:1131 disconnected on the other end 51 [21:47:49.153114] http_thread_func:885 HTTP close 51 [21:47:49.260578] XMLGetFirstDocumentItem:1332 Error finding CurrentTransportState in XML Node [21:47:49.724086] raop_notify:273 [0x7f4d8c00c990]: sending airplay remote GET /ctrl-int/1/stop HTTP/1.0 Active-Remote: 741607284 Connection: close

<== received ==> HTTP/1.1 204 No Content Date: Sun, 18 Mar 2018 20:47:49 GMT DAAP-Server: iTunes/12.6.2.20 (OS X) Content-Type: application/x-dmap-tagged Content-Length: 0

[21:47:49.724407] ActionHandler:464 [0x697a40]: uPNP stopped with the ios remote app I can play from the same iTunes/12.6.2.20 DAAP server to other instances in the net for hours without interuption, e.g to shairport-sync or an iphone in a sonos dock with AirFloat,..

once in a while also these issues occur, than with a http-parse error:

`[21:56:47.678724] XMLGetFirstDocumentItem:1332 Error finding CurrentTransportState in XML Node [21:56:48.443352] handle_rtsp:353 [0x7f4d8c00c990]: received SET_PARAMETER

RTSP/1.0 200 OK Audio-Jack-Status: connected; type=analog CSeq: 10`

[21:56:48.449397] http_parse:1059 sock: 2668205904, received (null) [21:56:48.452139] http_parse:1059 sock: 2668205904, received (null) [21:56:48.452213] http_parse:1072 Request failed, bad header [21:56:48.452353] rtsp_thread:327 RTSP close 16 [21:56:48.932329] XMLGetFirstDocumentItem:1332 Error finding CurrentTransportState in XML Node [21:56:49.936738] XMLGetFirstDocumentItem:1332 Error finding CurrentTransportState in XML Node [2

snip

[21:57:07.478764] XMLGetFirstDocumentItem:1332 Error finding CurrentTransportState in XML Node [21:57:08.482455] XMLGetFirstDocumentItem:1332 Error finding CurrentTransportState in XML Node [21:57:08.519478] read_line:1131 disconnected on the other end 57 [21:57:08.519857] http_thread_func:885 HTTP close 57 [21:57:09.012178] raop_notify:273 [0x7f4d8c00c990]: sending airplay remote GET /ctrl-int/1/stop HTTP/1.0 Active-Remote: 741607284 Connection: close

<== received ==> HTTP/1.1 204 No Content Date: Sun, 18 Mar 2018 20:57:08 GMT DAAP-Server: iTunes/12.6.2.20 (OS X) Content-Type: application/x-dmap-tagged Content-Length: 0

[21:57:09.012305] ActionHandler:464 [0x697a40]: uPNP stopped next tests will be with forked-daapd as DAAP server and airupnp,..

philippe44 commented 6 years ago

Just to be sure I got that right, every 10-15 minutes, the playback stops fully or there is a silence and then it restarts automatically?

[edit]: BTW, I'm using it daily to play for hours on my Sonos and does not have dropouts. It runs on an odroid C2, which is a sort of clone of a Pi3, connected through ethernet - I really recommend not using WiFi for the computer that runs the AirConnect instance. I'm not saying there is no issues, just that some configurations might exacerbate bugs in my app

pbg4 commented 6 years ago

Hi, when playing content from iTunes/12.6.2.20 DAAP server the playback sometimes stops fully, sometimes every 10- 15 minutes, but it can be restarted with the ios remote app,..

tests yesterday evening when playing content from forked-daapd (0.52) with airupnp to the play5 were without a problem,..

Test configuration:

when I powered the play5 and a squeezeboxradio down late yesterday there were some oddities also,

[23:00:21.864037] read_line:1131 disconnected on the other end 16 [23:00:21.864291] rtsp_thread:327 RTSP close 16 [23:02:08.485898] UpdateThread:667 [0x6995c8]: renderer bye-bye: Squeezebox Radio+ [23:02:08.780052] CheckAndLock:217 device is NULL but than:

[23:02:09.352289] CheckAndLock:217 device is NULL [23:02:09.451934] CheckAndLock:217 device is NULL [23:02:27.014227] MasterHandler:564 [0x697a40]: Auto-renewal failed, re-subscribing [23:02:32.017699] MasterHandler:589 [0x697a40]: subscribe fail, re-trying 1 [23:02:37.020040] MasterHandler:589 [0x697a40]: subscribe fail, re-trying 2 [23:02:42.025624] MasterHandler:589 [0x697a40]: subscribe fail, re-trying 3 [23:02:43.125924] MasterHandler:593 [0x697a40]: subscribe fail, volume feedback will not work [23:04:23.005311] UpdateThread:652 [0x697a40]: removing unresponsive player (Kitchen+) *** stack smashing detected ***: /usr/bin/airupnp terminated

pbg4 commented 6 years ago

Hi, later today I changed the test configuration with playing content only from forked-daapd server now with wired ethernet connection to the central switch,..

airupnp v0.2.0.5 x86-64 binary than ran over several hours successfully without a hitch,..

conclusion for me now is that problems occur more frequently/ most often only when content is played with iTunes 12.6.2.20 as daap server via WLAN ,..

philippe44 commented 6 years ago

It's probably WLAN-related then. In my tests, I use iTunes 12.6 as well

pbg4 commented 6 years ago

Hi, for the last ten days I had airupnp v0.2.0.5 x86-64 now running as a service, no problems anymore, after the first tests of airupnp v0.2.0.5 I had changed my setup here, m4a files are served now with forked-daapd (latest git), and iTunes and XLD are now used only for metadata editing/creation for m4a and flac files, especially iTunes 12.6.2.20 under MacOS 10.9.5 is sometimes laggy, which together with the WLAN connection was most probably the real source of errors, thanks again philippe !!

philippe44 commented 6 years ago

Glad you had it working - the other benefice to have it as a service is that if it ever crashes, it will be restarted automatically. Would mind closing this issue then?

pbg4 commented 6 years ago

Hi, shure, you can close it!

philippe44 commented 6 years ago

thanks