[Bug 53486] New: foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time
https://bugs.winehq.org/show_bug.cgi?id=53486 Bug ID: 53486 Summary: foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time Product: Wine Version: 7.5 Hardware: x86-64 OS: Linux Status: UNCONFIRMED Severity: normal Priority: P2 Component: ntdll Assignee: wine-bugs(a)winehq.org Reporter: pavlos.audiofreak(a)gmail.com Distribution: --- The problem occurs between versions wine-7.4 (good) and wine-7.5 (bad). All following releases are bad. I have checked both: the wine packages distributed by Arch Linux as well as compiled from the sources at https://source.winehq.org/git/wine.git. The "git bisect" process indicates the commit 74059d12b83e9f6d6fd64556ba11d7b5331d5d00 as the first bad commit. Environment: Stream sending computer: Arch Linux 5.18.15-arch1-1, wine (see above), foobar2000.exe v.1.6.11 with "UPnP Media Renderer Output" component "foo_out_upnp" version 1.3.2 Stream rendering computers: Windows 7 and Windows 10 (I have two renderers, one playing at a time), foobar2000.exe v.1.6.11 with "UPnP/DLNA Renderer, Server, Control Point" component "foo_upnp" version 0.99.4, configured only as "Media renderer", not "Media server". All computers are connected in LAN, no firewalls inside the home LAN. Symptoms: The audio stream starts properly, selected renderer properly plays the music on connected audio device. After a period of 10 to 60 seconds (randomly) the rendering computer stops receiving data and playing the music. I tried to revert the commit, but during the last 4 months the source file dlls/ntdll/unix/socket.c was heavily modified and git has refused to revert it. I am ready to help in testing patches. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 Pawel <pavlos.audiofreak(a)gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |jinoh.kang.kr(a)gmail.com, | |pavlos.audiofreak(a)gmail.com Distribution|--- |ArchLinux Regression SHA1| |74059d12b83e9f6d6fd64556ba1 | |1d7b5331d5d00 -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 Zeb Figura <z.figura12(a)gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Component|ntdll |winsock CC| |z.figura12(a)gmail.com -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 Zeb Figura <z.figura12(a)gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Keywords| |regression -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 --- Comment #1 from Jinoh Kang <jinoh.kang.kr(a)gmail.com> --- Created attachment 72857 --> https://bugs.winehq.org/attachment.cgi?id=72857 server: Always attempt synchronous I/O first -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 --- Comment #2 from Jinoh Kang <jinoh.kang.kr(a)gmail.com> --- Would you try running the app with the attached patch applied? Do you notice any message saying "forcing STATUS_ALERTED" in the output log? What is the errno? -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 --- Comment #3 from Pawel <pavlos.audiofreak(a)gmail.com> --- I have applied this patch to the "master" version 7.14. Shortly: it works. 20 minutes of continuous stream sending and playing audio on the renderer side. No breaks, hangups or hiccups. The "forcing STATUS_ALERTED" has appeared only once, briefly after the beginning of the first track. Never appeared again, even though I have cycled several times the playlist containing about 20 mins in 3 tracks. The log line says as follows: server/sock.c:3586:req_send_socket:forcing STATUS_ALERTED (errno=0) Please note, that errno will always be zero, because you assign it to zero just before the fprintf output statement. When I comment out the line 3575 "errno = 0;" of ./server/sock.c the log line says as follows: server/sock.c:3586:req_send_socket:forcing STATUS_ALERTED (errno=115) I have restarted the foobar for several times and the errno always returns 115. Next, after getting rid of the "once" variable and letting the fprintf statement to execute unconditionally, it usually (but no always) returns errno=115, what happens every 10 to 50 seconds. Other values are 22, 13 or 107. Full output log after playing the playlist of 3 tracks is in the attachment - please note beginnings of tracks, marked by me. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 --- Comment #4 from Pawel <pavlos.audiofreak(a)gmail.com> --- Created attachment 72859 --> https://bugs.winehq.org/attachment.cgi?id=72859 wine output log after the first patch and its modifications -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 --- Comment #5 from Jinoh Kang <jinoh.kang.kr(a)gmail.com> --- (In reply to Pawel from comment #3)
Please note, that errno will always be zero, because you assign it to zero just before the fprintf output statement.
Actually there is a "poll(2)" call in-between. My intention was to determine if the poll had failed.
When I comment out the line 3575 "errno = 0;" of ./server/sock.c the log line says as follows:
server/sock.c:3586:req_send_socket:forcing STATUS_ALERTED (errno=115)
I have restarted the foobar for several times and the errno always returns 115.
I guess it would have been leftover errno value from other system calls. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 Jinoh Kang <jinoh.kang.kr(a)gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #72857|0 |1 is obsolete| | --- Comment #6 from Jinoh Kang <jinoh.kang.kr(a)gmail.com> --- Created attachment 72865 --> https://bugs.winehq.org/attachment.cgi?id=72865 server: Always attempt synchronous I/O first [enhanced debug logging v2] Would you test this new patch which has more logging? This will help us devise a more performant and maintainable solution upstream. Thank you a lot for your cooperation! -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 Pawel <pavlos.audiofreak(a)gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #72859|0 |1 is obsolete| | -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 --- Comment #7 from Pawel <pavlos.audiofreak(a)gmail.com> --- Created attachment 72867 --> https://bugs.winehq.org/attachment.cgi?id=72867 wine output log after the second patch This is the output after reverting the first and applying the second patch. I have played two tracks, about 4 and 6 minutes long. Messages have been dropped out irregularly and have included all of them. As you see all messages are the same. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 --- Comment #8 from Pawel <pavlos.audiofreak(a)gmail.com> --- Please note that I have NOT refreshed my local wine-git repo since the day of the bug submission, so I don't have the latest development commits. If this is important - please let me know to update my local working copy before applying any of possible future patches. Thanks for your support! -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 --- Comment #9 from Jinoh Kang <jinoh.kang.kr(a)gmail.com> --- Created attachment 72886 --> https://bugs.winehq.org/attachment.cgi?id=72886 Set-up helper script for test virtual network topology Confirmed locally using a Linux virtual L2 network, with network namespace isolation and virtual Ethernet interfaces. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 --- Comment #10 from Jinoh Kang <jinoh.kang.kr(a)gmail.com> --- Created attachment 72887 --> https://bugs.winehq.org/attachment.cgi?id=72887 POLLOUT spurious falling edge test & epoll switch Diagnosis: foo_out_upnp.dll uses Windows Sockets in non-blocking mode for communicating with the UPnP media renderer. When requested to play an audio stream, the component enters an I/O loop that transmits the stream via a socket connected to the renderer. When sending a chunk of data, the component first performs a select() call with NULL readfds, non-NULL writefds and exceptfds, and NULL timeout (infinite). *Regardless* of the returned status of the select call(), the component then proceeds to perform a send() call. If send() fails with *any* error status (including WSAEWOULDBLOCK), the component throws a C++ exception. This exception is then caught by a catch(...) block outside the I/O loop that *silently* ignores the exception. It can be inferred from the algorithm above that, if a select() call completes successfully with a non-empty writefds set, the component expects that any immediately following send() call on a socket in the writefds set never fails with WSAEWOULDBLOCK. On Linux, Wine implements WSA select() via either epoll or poll (if epoll is not available) in Wineserver. When send() is called, Wineserver performs a poll() call to test whether the I/O request is immediately satiable before handing off the I/O to the client. It appears that the first epoll or poll yields (E)POLLOUT, but the second poll does not. Note that, before the regression, the client simply attempted the socket I/O first without asking the server if the I/O was indeed immediately satiable; the second poll either did not exist or was insignificant as far as the semantics of send() were concerned. Hypothesis 1: There exists a bug that causes Wine's epoll loop to signal a spurious (E)POLLOUT condition, which is not detected by a subsequent poll() call. To test hypothesis 1, would you test the attached patch *with* and *without* WINE_DISABLE_EPOLL=1 environment variable and post the output log here? -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 --- Comment #11 from Jinoh Kang <jinoh.kang.kr(a)gmail.com> --- (In reply to Jinoh Kang from comment #10)
Created attachment 72887 [details] POLLOUT spurious falling edge test & epoll switch
[...]
Hypothesis 1:
There exists a bug that causes Wine's epoll loop to signal a spurious (E)POLLOUT condition, which is not detected by a subsequent poll() call.
To test hypothesis 1, would you test the attached patch *with* and *without* WINE_DISABLE_EPOLL=1 environment variable and post the output log here?
Confirmed "decoding error" with WINE_DISABLE_EPOLL=1 when seeking forward or backward. Retracting hypothesis 1. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 --- Comment #12 from Pawel <pavlos.audiofreak(a)gmail.com> --- Hi Jinoh Kang, Thanks a lot for your efforts! Could you please clarify if and what I am expected to test? 1. Should I update my local working repo to the latest git version? 2. Should I keep or should I revert the second patch [enhanced debug logging v2]? 3. What should I do with the "setup.sh" set-up helper script for test virtual network topology? I think I should be executed as root (with sudo). 4. Should I patch and test the "Hypothesis 1"? You've just commented that the hypo has failed... -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 --- Comment #13 from Jinoh Kang <jinoh.kang.kr(a)gmail.com> --- (In reply to Pawel from comment #12)
Hi Jinoh Kang, Thanks a lot for your efforts!
Could you please clarify if and what I am expected to test?
1. Should I update my local working repo to the latest git version?
You could, if you're willing to test the fix I've submitted (see below).
2. Should I keep or should I revert the second patch [enhanced debug logging v2]?
No need to.
3. What should I do with the "setup.sh" set-up helper script for test virtual network topology? I think I should be executed as root (with sudo).
It's just there to help others reproduce the same bug in the future. You don't have to do anything about it, since you already have a working UPnP media client/server setup.
4. Should I patch and test the "Hypothesis 1"? You've just commented that the hypo has failed...
No need to either; it has been superseded by another explanation. You can still test https://gitlab.winehq.org/wine/wine/-/merge_requests/617 and see if it works if you want to. Assuming the Git origin remote points to https://gitlab.winehq.org/wine/wine.git, you can fetch the changes with: $ git fetch origin refs/merge-requests/617/head:fb2k-socket-fix -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 --- Comment #14 from Pawel <pavlos.audiofreak(a)gmail.com> --- I've made a fresh git clone from gitlab.* (instead of source.*) to a new directory. I've fetched the refs/merge-requests/617/head:fb2k-socket-fix, as advised. My build command is as follows: $ CC="ccache gcc -m32" ./configure --verbose --disable-tests && make I already thought that 'this is it', but after more than 3 minutes of continuous transmission the track stopped being played. Trying once more stopped already after 35 seconds. So, this fix doesn't work. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 --- Comment #15 from Pawel <pavlos.audiofreak(a)gmail.com> --- Created attachment 72906 --> https://bugs.winehq.org/attachment.cgi?id=72906 DRAFT: Always prefer synchronous I/O in nonblocking mode Wait! I have double-checked if there were any changes in server/sock.c file as described in https://gitlab.winehq.org/wine/wine/-/merge_requests/617. They were NOT applied. So I grabbed the diff code (attached) and applied it. And now - it works! -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 --- Comment #16 from Jinoh Kang <jinoh.kang.kr(a)gmail.com> --- (In reply to Pawel from comment #14)
I've made a fresh git clone from gitlab.* (instead of source.*) to a new directory. I've fetched the refs/merge-requests/617/head:fb2k-socket-fix, as advised. My build command is as follows:
$ CC="ccache gcc -m32" ./configure --verbose --disable-tests && make
I already thought that 'this is it', but after more than 3 minutes of continuous transmission the track stopped being played. Trying once more stopped already after 35 seconds.
So, this fix doesn't work.
You need to actually checkout the fb2k-socket-fix branch after you fetched it. Sorry for forgetting to mention that. (In reply to Pawel from comment #15)
Created attachment 72906 [details] DRAFT: Always prefer synchronous I/O in nonblocking mode
Wait! I have double-checked if there were any changes in server/sock.c file as described in https://gitlab.winehq.org/wine/wine/-/merge_requests/617. They were NOT applied. So I grabbed the diff code (attached) and applied it.
And now - it works!
That's a good news. Thanks for your work! -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 --- Comment #17 from Pawel <pavlos.audiofreak(a)gmail.com> --- So I did the forced git checkout -f fb2k-socket-fix. Had to force it because of applied previously patch. $./wine --version returns "wine-7.14-147-g52ffb007853" And foobar2000.exe performs as required, without problems. Should I test any variants of patches (I've noticed the discussion in gitlab) - I am ready to test it. And please let me know what are the final decisions for merging and releasing it into master. Thanks a lot for you support! -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 --- Comment #18 from Jinoh Kang <jinoh.kang.kr(a)gmail.com> --- Fixed in a115feab9ca8af9689a4ee13cd88ee6e93f902bd. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 --- Comment #19 from Pawel <pavlos.audiofreak(a)gmail.com> --- Hi Everyone, I have just performed standard update of packages from my distro, Arch has already consumed and published wine 7.16 in its 'multilib' repository. Apparently the commit resolving this bug has reached upstream, because fb2k plays the audio stream uninterruptedly, as in wine 7.4 - before the bug was introduced. cloning sources from https://source.winehq.org/git/wine.git and reviewing the sources of server/sock.c confirms the above empiric experience - the patch is in the official code of 7.16 release. THANK YOU ALL VERY MUCH !!! YOU ARE GREAT !!! Should I mark it as Resolved - please let me know. Or, please mark it as Resolved, otherwise. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 Zeb Figura <z.figura12(a)gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Resolution|--- |FIXED Fixed by SHA1| |a115feab9ca8af9689a4ee13cd8 | |8ee6e93f902bd Status|UNCONFIRMED |RESOLVED --- Comment #20 from Zeb Figura <z.figura12(a)gmail.com> --- Marking fixed. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=53486 Alexandre Julliard <julliard(a)winehq.org> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|RESOLVED |CLOSED --- Comment #21 from Alexandre Julliard <julliard(a)winehq.org> --- Closing bugs fixed in 7.17. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
participants (1)
-
WineHQ Bugzilla