FDH2 / UxPlay

AirPlay Unix mirroring server
GNU General Public License v3.0
1.62k stars 82 forks source link

Audio error reverted in h265_new: works now(was: Audio stopped then restart / keep mute until manual reconnection when AirPlay Mirror in iOS 18? #344

Closed DYY-Studio closed 1 month ago

DYY-Studio commented 1 month ago

Device: iPad Pro 11-inch 2022 (iPad14,3) System: iPad OS 18.0 (22A3354) Environment: Windows 11 23H2 / MSYS2 MINGW64 Connection: 1Gbps Ethernet

Version: h265_new 0473ccd Options: -s 2688x1668 -nohold -h265 -fps 60

Also can be reproduced in H264 mode with options -s 1920x1080 -nohold -fps 60

When play video game, open the Album app to play a video or meet other audio content change, the mirror's audio may stop.

This is the debug logging when the audio shutted down

raop_rtp video: now = 1726723162.189435, ntp = 1726723162.224876, latency = -0.035440, ts = 60002.641370, 00 00 00 00  h265
raop_rtp audio: now = 1726723162.194751, ntp = 1726723162.280023, latency = -0.085271, rtp_time=1553823309 seqnum = 37803
raop_buffer_handle_resends first_seqnum=37804 last seqnum=37805
raop_rtp got resend request 37804 1
raop_buffer_handle_resends first_seqnum=37804 last seqnum=37805
raop_rtp got resend request 37804 1

raop_rtp type_c 0x56, packetlen = 20
raop_rtp resent audio packet: seqnum=37804
raop_buffer_handle_resends first_seqnum=37804 last seqnum=37805
raop_rtp got resend request 37804 1
raop_rtp video: now = 1726723162.206178, ntp = 1726723162.241549, latency = -0.035371, ts = 60002.658043, 00 00 00 00  h265

raop_rtp type_c 0x56, packetlen = 20
raop_rtp resent audio packet: seqnum=37804
raop_buffer_handle_resends first_seqnum=37804 last seqnum=37806
raop_rtp got resend request 37804 1

raop_rtp type_c 0x56, packetlen = 20
raop_rtp resent audio packet: seqnum=37804

raop_rtp type_c 0x56, packetlen = 20
raop_rtp resent audio packet: seqnum=37804
raop_rtp video: now = 1726723162.222555, ntp = 1726723162.258222, latency = -0.035667, ts = 60002.674716, 00 00 00 00  h265
raop_buffer_handle_resends first_seqnum=37804 last seqnum=37806
raop_rtp got resend request 37804 1
raop_rtp video: now = 1726723162.239228, ntp = 1726723162.274895, latency = -0.035667, ts = 60002.691389, 00 00 00 00  h265
raop_buffer_handle_resends first_seqnum=37804 last seqnum=37806
raop_rtp got resend request 37804 1

Then for seconds the logging changes to this

raop_rtp type_c 0x56, packetlen = 20
raop_rtp resent audio packet: seqnum=37804
raop_buffer_handle_resends first_seqnum=37804 last seqnum=38210
raop_rtp got resend request 37804 1

raop_rtp type_c 0x56, packetlen = 8
Received empty resent audio packet length 8, seqnum=0:
80 d6 00 01 93 ac 00 00

raop_buffer_handle_resends first_seqnum=37804 last seqnum=38210
raop_rtp got resend request 37804 1
raop_rtp video: now = 1726723167.809956, ntp = 1726723167.843733, latency = -0.033777, ts = 60008.260227, 00 00 00 00  h265

raop_rtp type_c 0x56, packetlen = 8
Received empty resent audio packet length 8, seqnum=0:
80 d6 00 01 93 ac 00 00

raop_buffer_handle_resends first_seqnum=37804 last seqnum=38210
raop_rtp got resend request 37804 1

raop_rtp type_c 0x56, packetlen = 8
Received empty resent audio packet length 8, seqnum=0:
80 d6 00 01 93 ac 00 00

raop_buffer_handle_resends first_seqnum=37804 last seqnum=38211
raop_rtp got resend request 37804 1

raop_rtp type_c 0x56, packetlen = 8
raop_rtp video: now = 1726723167.825252, ntp = 1726723167.860406, latency = -0.035154, ts = 60008.276900, 00 00 00 00  h265
Received empty resent audio packet length 8, seqnum=0:
80 d6 00 01 93 ac 00 00

raop_buffer_handle_resends first_seqnum=37804 last seqnum=38211
raop_rtp got resend request 37804 1

raop_rtp type_c 0x56, packetlen = 8
Received empty resent audio packet length 8, seqnum=0:
80 d6 00 01 93 ac 00 00

https://github.com/user-attachments/assets/77b673e5-df87-4292-8b5a-e9c790804767

This video shows one of the stable reproduction. And this time it keeps mute and shows the second logging for almost 2 minutes

fduncanh commented 1 month ago

@DYY-Studio Thanks for testing

Yes there seem to be some audio issues with h265 mode. This is still a WIP so it is very useful to get feedback!. I noticed that initially audio didnt play in h265, then started. Your debug shows audio resend requests.

The h265 support is very new, and so far main focus has been on getting h265 video working. The audio needs to be examined to find out what is happening. have you looked at it after "export GST_DEBUG=2 (or =4) ?

fduncanh commented 1 month ago

Also can be reproduced in H264 mode with options -s 1920x1080 -nohold -fps 60

@DYY-Studio Can you explain this some more?

Does this happen with the regular released (master branch,not h265_new branch) UxPlay? In that case something has broken in h265_new when running without -h265 option. (It should behave just like the current master branch UxPlay when the -h265 option is not used).

This should be easier to fix if it is a regression in non-h265 mode.

DYY-Studio commented 1 month ago

@fduncanh

The master branch seems also have the same problem. When I open an App Link! Like! LoveLive!, the sound stuck very little time and recover. But I take next action or restart the game, it becomes totally mute as h265_new.

But in this version I can't reproduce it with the game I use in h265_new?

Options: -s 1544x1080@60 -nohold -fps 60 -d

The debug logging is just like I mentioned in the former comment.

raop_rtp video: now = 1726757378.323576, ntp = 1726757378.362518, latency = -0.038941, ts = 80402.119338, 00 00 00 00
raop_rtp video: now = 1726757378.340948, ntp = 1726757378.379191, latency = -0.038243, ts = 80402.136011, 00 00 00 00
raop_buffer_handle_resends first_seqnum=58898 last seqnum=58907
raop_rtp got resend request 58898 9

raop_rtp type_c 0x56, packetlen = 20
raop_rtp resent audio packet: seqnum=58898

raop_rtp type_c 0x56, packetlen = 20
raop_rtp resent audio packet: seqnum=58899

raop_rtp type_c 0x56, packetlen = 20
raop_rtp resent audio packet: seqnum=58900

raop_rtp type_c 0x56, packetlen = 20
raop_rtp resent audio packet: seqnum=58901
raop_buffer_handle_resends first_seqnum=58898 last seqnum=58907
raop_rtp got resend request 58898 9

raop_rtp type_c 0x56, packetlen = 20
raop_rtp resent audio packet: seqnum=58902
raop_rtp video: now = 1726757378.357326, ntp = 1726757378.395864, latency = -0.038538, ts = 80402.152684, 00 00 00 00
raop_buffer_handle_resends first_seqnum=58898 last seqnum=58907
raop_rtp got resend request 58898 9

raop_rtp type_c 0x56, packetlen = 20
raop_rtp resent audio packet: seqnum=58903
raop_buffer_handle_resends first_seqnum=58898 last seqnum=58908
raop_rtp got resend request 58898 9

raop_rtp type_c 0x56, packetlen = 20
raop_rtp resent audio packet: seqnum=58904
raop_buffer_handle_resends first_seqnum=58898 last seqnum=58908
raop_rtp got resend request 58898 9

raop_rtp type_c 0x56, packetlen = 20
raop_rtp resent audio packet: seqnum=58905
raop_buffer_handle_resends first_seqnum=58898 last seqnum=58908
raop_rtp got resend request 58898 9
raop_rtp video: now = 1726757378.374487, ntp = 1726757378.412537, latency = -0.038050, ts = 80402.169357, 00 00 00 00

raop_rtp type_c 0x56, packetlen = 20
raop_rtp resent audio packet: seqnum=58906
raop_buffer_handle_resends first_seqnum=58898 last seqnum=58909
raop_rtp got resend request 58898 9

raop_rtp type_c 0x56, packetlen = 20
raop_rtp resent audio packet: seqnum=58898
raop_buffer_handle_resends first_seqnum=58898 last seqnum=58909
raop_rtp got resend request 58898 9

raop_rtp type_c 0x56, packetlen = 20
raop_rtp resent audio packet: seqnum=58899
raop_buffer_handle_resends first_seqnum=58898 last seqnum=58909
raop_rtp got resend request 58898 9
raop_rtp video: now = 1726757378.391262, ntp = 1726757378.429210, latency = -0.037948, ts = 80402.186031, 00 00 00 00

raop_rtp type_c 0x56, packetlen = 20
raop_rtp resent audio packet: seqnum=58900
raop_buffer_handle_resends first_seqnum=58898 last seqnum=58910
raop_rtp got resend request 58898 9

raop_rtp type_c 0x56, packetlen = 20
raop_rtp resent audio packet: seqnum=58901
raop_buffer_handle_resends first_seqnum=58898 last seqnum=58910
raop_rtp got resend request 58898 9

raop_rtp type_c 0x56, packetlen = 20
raop_rtp resent audio packet: seqnum=58902
raop_buffer_handle_resends first_seqnum=58898 last seqnum=58910
raop_rtp got resend request 58898 9

Back to normal

raop_rtp type_c 0x56, packetlen = 20
raop_rtp resent audio packet: seqnum=58906

raop_rtp type_c 0x54, packetlen = 20
raop_rtp sync: client ntp=80403.558608, ntp = 1726757379.801788, ntp_start_time 1726757365.859582
ts_client = 80403.558608 sync_rtp=1884782094
80 d4 00 04 70 57 7e 0e 83 ab b8 93 8f 00 f5 5d 70 57 86 ab

dataset 8 raop_rtp sync correction=26478, rtp_sync_offset = -59722258672328
raop_rtp video: now = 1726757380.975479, ntp = 1726757381.013551, latency = -0.038072, ts = 80404.770371, 00 00 00 00
raop_rtp audio: now = 1726757380.977969, ntp = 1726757381.010276, latency = -0.032307, rtp_time=1884835384 seqnum = 59148
raop_rtp audio: now = 1726757380.983506, ntp = 1726757381.021160, latency = -0.037654, rtp_time=1884835864 seqnum = 59149
raop_rtp audio: now = 1726757380.986582, ntp = 1726757381.032044, latency = -0.045462, rtp_time=1884836344 seqnum = 59150
raop_rtp video: now = 1726757380.990973, ntp = 1726757381.030224, latency = -0.039251, ts = 80404.787045, 00 00 00 00

GST Debugging seems normal…? (with environmental variable GST_DEBUG=4);

0:00:16.710016300 119400    226c9486400 WARN           audiobasesink gstaudiobasesink.c:1491:gst_audio_base_sink_skew_slaving:<autoaudiosink0-actual-sink-wasapi> correct clock skew -0:00:00.021122523 < -+0:00:00.020000000
0:00:16.779744700 119400    226c9486400 WARN           audiobasesink gstaudiobasesink.c:1491:gst_audio_base_sink_skew_slaving:<autoaudiosink0-actual-sink-wasapi> correct clock skew -0:00:00.023903216 < -+0:00:00.020000000
0:00:16.789800500 119400    226c9486400 WARN           audiobasesink gstaudiobasesink.c:1491:gst_audio_base_sink_skew_slaving:<autoaudiosink0-actual-sink-wasapi> correct clock skew -0:00:00.021029359 < -+0:00:00.020000000
0:00:16.849824400 119400    226c9486400 WARN           audiobasesink gstaudiobasesink.c:1491:gst_audio_base_sink_skew_slaving:<autoaudiosink0-actual-sink-wasapi> correct clock skew -0:00:00.021109469 < -+0:00:00.020000000
0:00:16.906591100 119400    226c9486400 WARN           audiobasesink gstaudiobasesink.c:1491:gst_audio_base_sink_skew_slaving:<autoaudiosink0-actual-sink-wasapi> correct clock skew -0:00:00.021005473 < -+0:00:00.020000000
0:00:17.003127400 119400    226c9486400 WARN           audiobasesink gstaudiobasesink.c:1491:gst_audio_base_sink_skew_slaving:<autoaudiosink0-actual-sink-wasapi> correct clock skew -0:00:00.020882146 < -+0:00:00.020000000
0:00:17.130555700 119400    226c9486400 WARN           audiobasesink gstaudiobasesink.c:1491:gst_audio_base_sink_skew_slaving:<autoaudiosink0-actual-sink-wasapi> correct clock skew -0:00:00.020257435 < -+0:00:00.020000000
0:00:17.343117700 119400    226c9486400 WARN           audiobasesink gstaudiobasesink.c:1491:gst_audio_base_sink_skew_slaving:<autoaudiosink0-actual-sink-wasapi> correct clock skew -0:00:00.020151715 < -+0:00:00.020000000
0:00:18.047288300 119400    226c9486400 WARN           audiobasesink gstaudiobasesink.c:1491:gst_audio_base_sink_skew_slaving:<autoaudiosink0-actual-sink-wasapi> correct clock skew -0:00:00.020168466 < -+0:00:00.020000000
0:00:27.158626400 119400    226c9486400 WARN           audioresample gstaudioresample.c:732:gst_audio_resample_check_discont:<audioresample0> encountered timestamp discontinuity of 36965 samples = 0:00:00.838208617
0:00:27.542654900 119400    226c9486400 WARN           audioresample gstaudioresample.c:732:gst_audio_resample_check_discont:<audioresample0> encountered timestamp discontinuity of 15359 samples = 0:00:00.348276644
0:00:27.947775300 119400    226c9486400 WARN           audioresample gstaudioresample.c:732:gst_audio_resample_check_discont:<audioresample0> encountered timestamp discontinuity of 1440 samples = 0:00:00.032653061
0:00:37.005552300 119400    226c9486400 WARN           audioresample gstaudioresample.c:732:gst_audio_resample_check_discont:<audioresample0> encountered timestamp discontinuity of 7201 samples = 0:00:00.163287982
DYY-Studio commented 1 month ago

I have also tested my iPhone SE 3rd (iPhone14,6) in iOS 16.3 with master branch, Wi-Fi connection. It's same as my iPad Pro. Slience.

Though my Wi-Fi environment is bad, I'm sure such long time mute can't be connection problem as the video is working…?

fduncanh commented 1 month ago

I have not yet tested iOS18/iPadOS 18 . Will need to see if anything new in iOS18 has broken anything.

But if you see an issue in iOS16.3 it's not that.

can you list what the test is, in the precise form

  1. do this
  2. do this
  3. do this ... (see the problem)

thanks

If you do NOT use the -s wxh@r option, (just use -s wxh) what happens?

In particular, on github master AND in h265_new , a change in the internal representation of the refresh rate 60hz specified as -s 1920x1080@60 was recently made (based on wireshark analysis of AppleTV gen 3) and might be incorrect,

EDITED:

Thanks!

fduncanh commented 1 month ago

https://github.com/FDH2/UxPlay/commits/88891c01270ab215450dc6ea0a868bb46abb5c66/

better: can you test master BEFORE the change in the refresh rate code was made

DYY-Studio commented 1 month ago

iPhone SE 3rd, iOS 16.3, UxPlay 1.69 (0a2dbaa)

Maybe Application specific problem? Successfully reproduced with COD MOBILE (CHINA), but unstable. Link! Like! LoveLive! (JAPAN) (Unity Engine) is the App that can most stably reproduce the problem.

options: -nohold / NONE

https://github.com/user-attachments/assets/82e4ba6f-abef-496e-9955-5d0a3be2206a

I took a video so you can easily know what I have done.

iPad Pro 11-inch 2022, iOS 18.0, UxPlay 1.69 (0a2dbaa)

options: NONE

As same as the iPhone SE, Link! Like! LoveLive! can stably reproduce the audio problem. Other applications seem do not have this problem? or just I haven't tried?

iPad Pro 11-inch 2022, iOS 18.0, h265_new (0473ccd)

Options: NONE

Different from 0a2dbaa, seems any App can easily reproduce the audio problem.

For IDOLY PRIDE, just like the video I post earliest. Just open an 3D LIVE, then exit.

Tested App: IDOLY PRIDE (JAPAN), Galaxy on Fire 2 HD

https://github.com/user-attachments/assets/1b516dc9-27d1-45cf-9b78-e6355f1904b4

iPhone SE 3rd, iOS 16.3, h265_new (0473ccd)

As same as iPad Pro. Just open an App, exit and reopen. Tested App: Galaxy on Fire 2 HD

fduncanh commented 1 month ago

@DYY-Studio We would like to investigate your issue.

Can you explain in detail where to get "Link! Like! LoveLive" game.

Is it in App Store ? Something on You Tube?

1 .how to access the game. (Is it online in a browser, something on YouTube, something that needs to be installed on an iPad/iPhone from the App Store, etc.)

  1. what to do to start the game and see the issue. thank you.

As same as the iPhone SE, Link! Like! LoveLive! can stably reproduce the audio problem. Other applications seem do not have this problem? or just I haven't tried?

fduncanh commented 1 month ago

OK have found galaxy on fire 2 HD in the Apple app store.. Its currently downloading.

Will it show all your issues, both in h264 on UxPlay-1.69 (master branch) and the experimental h265 version (h265_new branch, using 4K video with the -h265 option) ?

fduncanh commented 1 month ago

Link !Like! Love Live does not seem to be in the App Store (maybe only in Japan?) Its not available anywhere it seems.

fduncanh commented 1 month ago

FIXED!

An experimental change in the audio was accidentally commited.

One this was reverted, audio is working fine, just like in v1.69.

Will close this issue as fixed now.

PLEASE REPOST HERE IF YOU THINK IT IS STILL NOT FIXED!