search

eizedev / AirConnect-Synology

Updated AirConnect packages for Synology NAS and Synology Router
https://github.com/philippe44/AirConnect
MIT License
315 stars 14 forks source link

Sometimes stable, sometimes not #6

Closed vespino closed 3 years ago

vespino commented 3 years ago

I have been using this plugin for a week or so now and it does not always seem stable. Sometimes AirPlay plays for hours, sometimes it’s stops after an hour or 2 or less. I then have to restart the plugin and restart the audio.

AirPlay does seem to be stable when used from my iPhone and my Google speakers play the entire day when playing from the built in services like tune in, so I guess it’s not my wifi.

Any thoughts?

eizedev commented 3 years ago

Hi @vespino Could you please check the log files on your NAS when the problem reoccurs? There should be an error or at least a hint logged. Then you could upload the logfile here and I can have a look at it.

You can find more information about the logfiles in the readme: AirConnect-Synology Logfiles

vespino commented 3 years ago

@eizedev the file /var/log/packages/AirConnect.log is currently only showing stop/start logs for the crons I have set in place to restart the service every 24 hours, it doesn't show any other logs. I will look to the other log file (/var/log/airconnect.log) when the problem occurs.

eizedev commented 3 years ago

The log file /var/log/airconnect.log is written by the AirConnect synology package. All log entries of the AirConnect application (airupnp + aircast) are also written into this log file. The other log file is basically just the log file of the service managed by Synology. (i will update the readme to make it more clear)

vespino commented 3 years ago

Yesterday at around 6.35PM streaming stop and around that time I have found the following logs:

[18:32:21.133851] buffer_put_packet:620 [0x7f2558b8c560]: fill [level:2] [W:63396 R:63395] [18:32:21.676552] _buffer_get_frame:960 [0x7f2558b8c560]: drain [level:2 gap:987] [W:63464 R:63462] [R:0 S:0 F:0] [18:32:22.218740] CheckAndLock:259 device is NULL [18:32:22.233943] CheckAndLock:259 device is NULL [18:32:22.284344] CheckAndLock:259 device is NULL

[18:32:25.304080] buffer_put_packet:620 [0x7f2558b8c560]: fill [level:4] [W:63908 R:63905] [18:32:25.842246] _buffer_get_frame:960 [0x7f2558b8c560]: drain [level:0 gap:974] [W:63974 R:63974] [R:0 S:0 F:0] [18:32:26.639593] AddMRDevice:992 [0x7f5169b7e010]: adding renderer (TV Woonkamer) [18:32:26.639682] AddMRDevice:1013 [0x7f5169b7e010]: cannot get mac TV Woonkamer+, creating fake f1bed3f9 [18:32:26.651141] MasterHandler:656 [0x7f5169b7e010]: subscribe success [18:32:26.725412] ProcessEvent:451 [0x7f5169b7e010]: UPnP Volume local change 50:-1 (master) [18:32:29.059174] rtsp_thread:351 got RTSP connection 13 [18:32:29.059489] read_line:1174 disconnected on the other end 13 [18:32:29.059584] rtsp_thread:366 RTSP close 13 [18:32:29.060158] rtsp_thread:351 got RTSP connection 26 [18:32:29.060385] read_line:1174 disconnected on the other end 26 [18:32:29.060453] rtsp_thread:366 RTSP close 26 [18:32:29.061039] rtsp_thread:351 got RTSP connection 23 [18:32:29.061237] read_line:1174 disconnected on the other end 23 [18:32:29.061295] rtsp_thread:366 RTSP close 23 [18:32:29.312241] buffer_put_packet:620 [0x7f2558b8c560]: fill [level:5] [W:64420 R:64416] [18:32:29.896315] _buffer_get_frame:960 [0x7f2558b8c560]: drain [level:4 gap:951] [W:64490 R:64486] [R:0 S:0 F:0] [18:32:31.908761] ProcessEvent:451 [0x7f5169b7e010]: UPnP Volume local change 18:-1 (master) [18:32:32.582218] UpdateThread:737 [0x7f5169b7e010]: renderer bye-bye: TV Woonkamer+ [18:32:32.632867] CheckAndLock:259 device is NULL [18:32:32.683273] CheckAndLock:259 device is NULL [18:32:33.232823] CheckAndLock:259 device is NULL [18:32:33.232883] CheckAndLock:259 device is NULL [18:32:33.232989] CheckAndLock:259 device is NULL [18:32:33.522772] buffer_put_packet:620 [0x7f2558b8c560]: fill [level:2] [W:64932 R:64931] [18:32:34.061686] _buffer_get_frame:960 [0x7f2558b8c560]: drain [level:2 gap:979] [W:65000 R:64998] [R:0 S:0 F:0] [18:32:34.064425] rtsp_thread:351 got RTSP connection 20 [18:32:34.077071] read_line:1174 disconnected on the other end 20 [18:32:34.077169] rtsp_thread:366 RTSP close 20 [18:32:34.077807] rtsp_thread:351 got RTSP connection 15 [18:32:34.078722] rtsp_thread:351 got RTSP connection 12 [18:32:34.078780] read_line:1174 disconnected on the other end 15 [18:32:34.078871] rtsp_thread:366 RTSP close 15 [18:32:34.079005] read_line:1174 disconnected on the other end 12 [18:32:34.079072] rtsp_thread:366 RTSP close 12 [18:32:34.079860] rtsp_thread:351 got RTSP connection 9 [18:32:34.080078] read_line:1174 disconnected on the other end 9 [18:32:34.080143] rtsp_thread:366 RTSP close 9 [18:32:34.182784] read_line:1174 disconnected on the other end 19 [18:32:34.182910] rtsp_thread:366 RTSP close 19 [18:32:34.182937] rtsp_thread:351 got RTSP connection 19 [18:32:34.183056] read_line:1174 disconnected on the other end 19 [18:32:34.183080] rtsp_thread:366 RTSP close 19 [18:32:37.058402] rtsp_thread:351 got RTSP connection 26 [18:32:37.058639] read_line:1174 disconnected on the other end 26 [18:32:37.058713] rtsp_thread:366 RTSP close 26 [18:32:37.059299] rtsp_thread:351 got RTSP connection 23 [18:32:37.059491] read_line:1174 disconnected on the other end 23 [18:32:37.059567] rtsp_thread:366 RTSP close 23 [18:32:37.060136] rtsp_thread:351 got RTSP connection 19 [18:32:37.060351] read_line:1174 disconnected on the other end 19 [18:32:37.060414] rtsp_thread:366 RTSP close 19 [18:32:37.061048] rtsp_thread:351 got RTSP connection 20 [18:32:37.061295] read_line:1174 disconnected on the other end 20 [18:32:37.061372] rtsp_thread:366 RTSP close 20 [18:32:37.061993] rtsp_thread:351 got RTSP connection 15 [18:32:37.062219] read_line:1174 disconnected on the other end 15 [18:32:37.062289] rtsp_thread:366 RTSP close 15 [18:32:37.062919] rtsp_thread:351 got RTSP connection 12 [18:32:37.063169] read_line:1174 disconnected on the other end 12 [18:32:37.063246] rtsp_thread:366 RTSP close 12 [18:32:37.063810] rtsp_thread:351 got RTSP connection 9 [18:32:37.064017] read_line:1174 disconnected on the other end 9 [18:32:37.064079] rtsp_thread:366 RTSP close 9

[18:32:37.064017] read_line:1174 disconnected on the other end 9 [18:32:37.064079] rtsp_thread:366 RTSP close 9 [18:32:42.518132] AddCastDevice:653 [0x15ce990]: adding renderer (TV Woonkamer) [18:32:42.518215] AddCastDevice:659 [0x15ce990]: creating MAC 15ce99a [18:32:45.036678] rtsp_thread:351 got RTSP connection 76 [18:32:45.036934] read_line:1174 disconnected on the other end 76 [18:32:45.037000] rtsp_thread:366 RTSP close 76 [18:32:45.037585] rtsp_thread:351 got RTSP connection 26 [18:32:45.038436] rtsp_thread:351 got RTSP connection 23 [18:32:45.038521] read_line:1174 disconnected on the other end 26 [18:32:45.038586] rtsp_thread:366 RTSP close 26 [18:32:45.038679] read_line:1174 disconnected on the other end 23 [18:32:45.038737] rtsp_thread:366 RTSP close 23 [18:32:45.039315] rtsp_thread:351 got RTSP connection 19 [18:32:45.039510] read_line:1174 disconnected on the other end 19 [18:32:45.039573] rtsp_thread:366 RTSP close 19 [18:32:45.040135] rtsp_thread:351 got RTSP connection 20 [18:32:45.040354] read_line:1174 disconnected on the other end 20 [18:32:45.040418] rtsp_thread:366 RTSP close 20 [18:32:45.040986] rtsp_thread:351 got RTSP connection 15 [18:32:45.041192] read_line:1174 disconnected on the other end 15 [18:32:45.041254] rtsp_thread:366 RTSP close 15 [18:32:45.041829] rtsp_thread:351 got RTSP connection 12 [18:32:45.042040] read_line:1174 disconnected on the other end 12 [18:32:45.042106] rtsp_thread:366 RTSP close 12 [18:32:45.042674] rtsp_thread:351 got RTSP connection 9 [18:32:45.042880] read_line:1174 disconnected on the other end 9 [18:32:45.042944] rtsp_thread:366 RTSP close 9 [18:41:30.679955] CheckAndLock:259 device is NULL [18:41:30.731524] CheckAndLock:259 device is NULL [18:41:30.787121] CheckAndLock:259 device is NULL [18:41:30.840242] CheckAndLock:259 device is NULL

Are these of any help?

vespino commented 3 years ago

I think I found a relationship with my TV. It seems that when I start casting to my TV my speakers stop. Don’t know if this is even possible or purely coincidental, but it has happened a couple of times now, while having played without errors the entire day.

eizedev commented 3 years ago

hmm... 

[18:32:31.908761] ProcessEvent:451 [0x7f5169b7e010]: UPnP Volume local change 18:-1 (master)
[18:32:32.582218] UpdateThread:737 [0x7f5169b7e010]: renderer bye-bye: TV Woonkamer+
[18:32:32.632867] CheckAndLock:259 device is NULL
[18:32:32.683273] CheckAndLock:259 device is NULL

i don't know why but after you powered off your TV the "device is NULL" messages are being logged. This is not directly a problem with the AirConnect package for synology devices. I think you should open another issue on the official AirConnect repository and reference this issue here (So the issue get tracked at the right place). AirConnect Issue Page

Thanks

vespino commented 3 years ago

Thanks, I will do that.