search

philippe44 / AirConnect

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

Too Many Missing Frames #516

Open chrispy212 opened 5 months ago

chrispy212 commented 5 months ago

I'm using AirConnect to connect Apple Music to a set of Google Chromecast speakers, grouped into one under the Google Home app. Airconnect runs in a docker environment on an ethernet-wired home server. Whilst it runs well, we hit into issues every 30-60 minutes. Occasionally this manifests as stutter, other times the audio completely drops, but still appears to be playing to the "AirPlay" target (the Chromecast group mentioned above) when checking my iPhone.

To resolve, I must pause the music, disconnect airplay, turn off wifi +- activate airplay mode, reactivate wifi, and reconnect to air connect.

Below is a log capturing the event. I do note the "too many frames" error and a negative 'gap' in the drain log

`[19:13:03.710] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:9237 R:9231] [19:13:03.715] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:0 gap:1902] [W:9241 R:9241] [R:12 S:0 F:0] [19:13:11.893] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:10261 R:10255] [19:13:11.908] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:0 gap:1884] [W:10265 R:10265] [R:21 S:0 F:0] [19:13:20.057] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:11285 R:11279] [19:13:20.066] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:0 gap:1899] [W:11289 R:11289] [R:21 S:0 F:0] [19:13:28.237] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:12309 R:12303] [19:13:28.239] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:0 gap:1898] [W:12313 R:12313] [R:21 S:0 F:0] [19:13:36.403] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:13333 R:13327] [19:13:36.413] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:0 gap:1896] [W:13337 R:13337] [R:21 S:0 F:0] [19:13:44.577] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:14357 R:14351] [19:13:44.591] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:0 gap:1885] [W:14361 R:14361] [R:33 S:0 F:0] [19:13:52.751] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:15381 R:15375] [19:13:52.752] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:0 gap:1906] [W:15385 R:15385] [R:33 S:0 F:0] [19:14:00.924] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:16405 R:16399] [19:14:00.926] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:0 gap:1904] [W:16409 R:16409] [R:33 S:0 F:0] [19:14:09.097] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:17429 R:17423] [19:14:09.099] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:0 gap:1903] [W:17433 R:17433] [R:33 S:0 F:0] [19:14:15.209] rtp_thread_func:714 [0x1539004e74c0]: Sending packets too slow -13 (skip: 1)[W:18190 R : 18191] [19:14:15.240] _buffer_get_frame:820 [0x1539004e74c0]: Sending packets too slow (skip: 0) [W:18201 R:18192] [19:14:17.270] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:18453 R:18447] [19:14:17.374] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:11 gap:1809] [W:18469 R:18458] [R:33 S:0 F:0] [19:14:22.170] rtp_thread_func:714 [0x1539004e74c0]: Sending packets too slow -5 (skip: 1)[W:19062 R : 19063] [19:14:22.200] _buffer_get_frame:820 [0x1539004e74c0]: Sending packets too slow (skip: 0) [W:19074 R:19064] [19:14:25.453] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:19477 R:19471] [19:14:25.552] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:10 gap:1814] [W:19493 R:19483] [R:33 S:0 F:0] [19:14:33.617] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:20501 R:20495] [19:14:33.711] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:10 gap:1830] [W:20517 R:20507] [R:33 S:0 F:0] [19:14:41.790] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:21525 R:21519] [19:14:41.884] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:3 gap:1830] [W:21534 R:21531] [R:33 S:0 F:0] [19:14:49.963] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:22549 R:22543] [19:14:50.080] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:7 gap:1805] [W:22562 R:22555] [R:33 S:0 F:0] [19:14:58.137] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:23573 R:23567] [19:14:58.236] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:10 gap:1823] [W:23589 R:23579] [R:33 S:0 F:0] [19:15:06.310] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:24597 R:24591] [19:15:06.409] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:10 gap:1826] [W:24613 R:24603] [R:33 S:0 F:0] [19:15:14.484] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:25621 R:25615] [19:15:14.588] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:10 gap:1818] [W:25637 R:25627] [R:33 S:0 F:0] [19:15:22.657] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:26645 R:26639] [19:15:22.750] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:6 gap:1828] [W:26657 R:26651] [R:33 S:0 F:0] [19:15:30.860] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:27669 R:27663] [19:15:30.927] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:10 gap:1826] [W:27685 R:27675] [R:33 S:0 F:0] [19:15:39.003] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:28693 R:28687] [19:15:39.106] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:10 gap:1821] [W:28709 R:28699] [R:33 S:0 F:0] [19:15:47.177] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:29717 R:29711] [19:15:47.283] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:10 gap:1816] [W:29733 R:29723] [R:33 S:0 F:0] [19:15:55.349] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:30741 R:30735] [19:15:55.443] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:10 gap:1831] [W:30757 R:30747] [R:33 S:0 F:0] [19:16:03.523] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:31765 R:31759] [19:16:03.616] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:6 gap:1830] [W:31777 R:31771] [R:33 S:0 F:0] [19:16:11.699] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:32789 R:32783] [19:16:11.809] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:10 gap:1812] [W:32805 R:32795] [R:33 S:0 F:0] [19:16:19.871] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:33813 R:33807] [19:16:19.969] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:10 gap:1825] [W:33829 R:33819] [R:33 S:0 F:0] [19:16:28.042] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:34837 R:34831] [19:16:28.139] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:10 gap:1829] [W:34853 R:34843] [R:33 S:0 F:0] [19:16:36.226] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:35861 R:35855] [19:16:36.316] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:10 gap:1824] [W:35877 R:35867] [R:33 S:0 F:0] [19:16:44.390] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:36885 R:36879] [19:16:44.510] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:10 gap:1804] [W:36901 R:36891] [R:33 S:0 F:0] [19:16:52.567] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:37909 R:37903] [19:16:52.670] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:10 gap:1816] [W:37925 R:37915] [R:33 S:0 F:0] [19:16:56.487] handle_rtsp:374 [0x15390c0b42c0]: received SET_PARAMETER [19:16:56.488] CastPlay:250 [0x4e52e8]: Immediate PLAY (id:1543) [19:16:56.488] handle_rtsp:559 [0x15390c0b42c0]: received metadata artist: Bon Jovi album: Slippery When Wet title: Livin' On a Prayer

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

[19:16:56.496] handle_rtsp:374 [0x15390c0b42c0]: received SET_PARAMETER [19:16:56.497] CastPlay:262 [0x4e52e8]: Queuing PLAY [19:16:56.497] handle_rtsp:559 [0x15390c0b42c0]: received metadata artist: Journey album: Escape (2022 Remaster) title: Don't Stop Believin' (2022 Remaster)

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

[19:16:56.503] handle_rtsp:374 [0x15390c0b42c0]: received SET_PARAMETER

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

[19:16:56.508] handle_rtsp:374 [0x15390c0b42c0]: received SET_PARAMETER [19:16:56.508] CastPlay:262 [0x4e52e8]: Queuing PLAY [19:16:56.509] handle_rtsp:559 [0x15390c0b42c0]: received metadata artist: Journey album: Escape (2022 Remaster) title: Don't Stop Believin' (2022 Remaster)

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

[19:16:56.516] handle_rtsp:374 [0x15390c0b42c0]: received SET_PARAMETER

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

[19:16:56.570] ProcessQueue:455 [0x4e52e8]: Processing PLAY (id:1544) [19:16:56.599] handle_rtsp:374 [0x15390c0b42c0]: received SET_PARAMETER [19:16:56.599] CastPlay:262 [0x4e52e8]: Queuing PLAY [19:16:56.599] handle_rtsp:559 [0x15390c0b42c0]: received metadata artist: Journey album: Escape (2022 Remaster) title: Don't Stop Believin' (2022 Remaster)

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

[19:16:56.663] handle_rtsp:374 [0x15390c0b42c0]: received SET_PARAMETER [19:16:56.663] CastPlay:262 [0x4e52e8]: Queuing PLAY [19:16:56.664] handle_rtsp:559 [0x15390c0b42c0]: received metadata artist: Journey album: Escape (2022 Remaster) title: Don't Stop Believin' (2022 Remaster)

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

[19:16:56.673] ProcessQueue:455 [0x4e52e8]: Processing PLAY (id:1545) [19:16:56.683] handle_rtsp:374 [0x15390c0b42c0]: received SET_PARAMETER [19:16:56.684] handle_rtsp:568 [0x15390c0b42c0]: received JPEG image of 84375 bytes [19:16:56.684] CastPlay:262 [0x4e52e8]: Queuing PLAY

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

[19:16:56.743] ProcessQueue:455 [0x4e52e8]: Processing PLAY (id:1546) [19:16:56.821] ProcessQueue:455 [0x4e52e8]: Processing PLAY (id:1547) [19:16:56.904] ProcessQueue:455 [0x4e52e8]: Processing PLAY (id:1548) [19:16:57.580] handle_rtsp:374 [0x15390c0b42c0]: received SET_PARAMETER [19:16:57.581] CastPlay:250 [0x4e52e8]: Immediate PLAY (id:1549) [19:16:57.581] handle_rtsp:559 [0x15390c0b42c0]: received metadata artist: Journey album: Escape (2022 Remaster) title: Don't Stop Believin' (2022 Remaster)

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

[19:16:57.589] handle_rtsp:374 [0x15390c0b42c0]: received SET_PARAMETER

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

[19:17:00.735] buffer_put_packet:518 [0x1539004e74c0]: fill [level:7] [W:38933 R:38927] [19:17:00.835] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:10 gap:1826] [W:38949 R:38939] [R:78 S:0 F:0] [19:17:16.980] buffer_put_packet:489 [0x1539004e74c0] too many missing frames 39624 (768) [19:17:16.995] _buffer_get_frame:888 [0x1539004e74c0]: drain [level:441 gap:-22507] [W:40404 R:39963] [R:6907 S:339 F:0] [19:17:21.804] handle_rtsp:374 [0x15390c0b42c0]: received SET_PARAMETER [19:17:21.805] CastPlay:250 [0x4e52e8]: Immediate PLAY (id:1572) [19:17:21.805] handle_rtsp:559 [0x15390c0b42c0]: received metadata artist: Journey album: Escape (2022 Remaster) title: Don't Stop Believin' (2022 Remaster)

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

[19:17:21.813] handle_rtsp:374 [0x15390c0b42c0]: received SET_PARAMETER

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

philippe44 commented 5 months ago

Its looks like a network issue, like suddenly your network is dropping off UDP frames (as used by AirPlay). I've seen that a few times with some complex architecture that include PLC plugs.