[Bug 53486] New: foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

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: [e-mail]
          Reporter: [e-mail]
      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.

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

Pawel  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |[e-mail],
                   |                            |[e-mail]
       Distribution|---                         |ArchLinux
    Regression SHA1|                            |74059d12b83e9f6d6fd64556ba1
                   |                            |1d7b5331d5d00

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

Zeb Figura  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
          Component|ntdll                       |winsock
                 CC|                            |[e-mail]

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

Zeb Figura  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
           Keywords|                            |regression

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

--- Comment #1 from Jinoh Kang  ---
Created attachment 72857
  --> https://bugs.winehq.org/attachment.cgi?id=72857
server: Always attempt synchronous I/O first

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

--- Comment #2 from Jinoh Kang  ---
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?

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

--- Comment #3 from Pawel  ---
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.

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

--- Comment #4 from Pawel  ---
Created attachment 72859
  --> https://bugs.winehq.org/attachment.cgi?id=72859
wine output log after the first patch and its modifications

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

--- Comment #5 from Jinoh Kang  ---
(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.

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

Jinoh Kang  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
  Attachment #72857|0                           |1
        is obsolete|                            |

--- Comment #6 from Jinoh Kang  ---
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!

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

Pawel  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
  Attachment #72859|0                           |1
        is obsolete|                            |

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

--- Comment #7 from Pawel  ---
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.

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

--- Comment #8 from Pawel  ---
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!

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

--- Comment #9 from Jinoh Kang  ---
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.

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

--- Comment #10 from Jinoh Kang  ---
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?

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

--- Comment #11 from Jinoh Kang  ---
(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.

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

--- Comment #12 from Pawel  ---
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...

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

--- Comment #13 from Jinoh Kang  ---
(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?
> - 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).
> - Should I keep or should I revert the second patch [enhanced debug logging
>
> v2]?

No need to.
> - 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.
> - 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

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

--- Comment #14 from Pawel  ---
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.

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

--- Comment #15 from Pawel  ---
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!

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

--- Comment #16 from Jinoh Kang  ---
(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!

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

--- Comment #17 from Pawel  ---
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!

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

--- Comment #18 from Jinoh Kang  ---
Fixed in a115feab9ca8af9689a4ee13cd88ee6e93f902bd.

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

--- Comment #19 from Pawel  ---
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.

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

Zeb Figura  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
         Resolution|---                         |FIXED
      Fixed by SHA1|                            |a115feab9ca8af9689a4ee13cd8
                   |                            |8ee6e93f902bd
             Status|UNCONFIRMED                 |RESOLVED

--- Comment #20 from Zeb Figura  ---
Marking fixed.

[Bug 53486] foobar2000.exe with foo_out_upnp breaks sending audio stream to another upnp renderer after a short period of time

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=53486

Alexandre Julliard  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|RESOLVED                    |CLOSED

--- Comment #21 from Alexandre Julliard  ---
Closing bugs fixed in 7.17.