Sending SIGINT to Syncplay connected to mpv rasies an exception

[daniel-123]

It's a low priority, but Syncplay should try to close itself cleanly upon receiving SIGINT. It's more likely to occur with --no-gui, but it's also possible to encounter it in GUI mode by for example using CTRL+C in the terminal it was ran from.

In this situation Syncplay also stays running for about minute until some timeout occurs.

Exception in thread Thread-2:
Traceback (most recent call last):
  File "/usr/lib/python3.8/threading.py", line 932, in _bootstrap_inner
    self.run()
  File "/usr/lib/syncplay/syncplay/players/python_mpv_jsonipc/python_mpv_jsonipc.py", line 163, in run
    current_data = self.socket.recv(1024)
ConnectionResetError: [Errno 104] Connection reset by peer

[FichteFoll]

Also happens for me when mpv or syncplay itself are closed normally.

[daniel-123]

Are you on current master branch?

[FichteFoll]

I was using 9484e10, let me quickly rebuild.

[FichteFoll]

Also reproducible on a1a5d7b (current master).

[daniel-123]

Since on my system it occurs only with SIGINT (with older pyside2 5.13 or 5.14), what you are getting might be something different still. Sadly this means it will likely require some more digging into actual cause.

[FichteFoll]

Including full traceback from #321:

~ ▶ syncplay
Attribute Qt::AA_EnableHighDpiScaling must be set before QCoreApplication is created.
Exception in thread Thread-2:
Traceback (most recent call last):
  File "/usr/lib/python3.8/threading.py", line 932, in _bootstrap_inner
    self.run()
  File "/usr/lib/syncplay/syncplay/players/python_mpv_jsonipc/python_mpv_jsonipc.py", line 163, in run
    current_data = self.socket.recv(1024)
ConnectionResetError: [Errno 104] Connection reset by peer
Unhandled Error
Traceback (most recent call last):
  File "/usr/lib/syncplay/syncplay/clientManager.py", line 16, in run
    syncplayClient.start(config['host'], config['port'])
  File "/usr/lib/syncplay/syncplay/client.py", line 841, in start
    reactor.run()
  File "/usr/lib/syncplay/syncplay/vendor/qt5reactor.py", line 303, in run
    self._blockApp.exec_()
  File "/usr/lib/syncplay/syncplay/vendor/qt5reactor.py", line 187, in write
    log.callWithLogger(w, _write)
--- <exception caught here> ---
  File "/usr/lib/python3.8/site-packages/twisted/python/log.py", line 103, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/usr/lib/python3.8/site-packages/twisted/python/log.py", line 86, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/usr/lib/python3.8/site-packages/twisted/python/context.py", line 122, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/usr/lib/python3.8/site-packages/twisted/python/context.py", line 85, in callWithContext
    return func(*args,**kw)
  File "/usr/lib/syncplay/syncplay/vendor/qt5reactor.py", line 182, in _write
    self.reactor._disconnectSelectable(w, why, False)
  File "/usr/lib/python3.8/site-packages/twisted/internet/posixbase.py", line 255, in _disconnectSelectable
    selectable.connectionLost(f)
  File "/usr/lib/python3.8/site-packages/twisted/internet/tcp.py", line 519, in connectionLost
    self._commonConnection.connectionLost(self, reason)
  File "/usr/lib/python3.8/site-packages/twisted/internet/tcp.py", line 327, in connectionLost
    protocol.connectionLost(reason)
  File "/usr/lib/python3.8/site-packages/twisted/protocols/tls.py", line 403, in connectionLost
    ProtocolWrapper.connectionLost(self, reason)
  File "/usr/lib/python3.8/site-packages/twisted/protocols/policies.py", line 125, in connectionLost
    self.wrappedProtocol.connectionLost(reason)
  File "/usr/lib/python3.8/site-packages/twisted/internet/endpoints.py", line 146, in connectionLost
    return self._wrappedProtocol.connectionLost(reason)
  File "/usr/lib/python3.8/site-packages/twisted/application/internet.py", line 438, in connectionLost
    self._lostNotification(reason)
  File "/usr/lib/python3.8/site-packages/twisted/application/internet.py", line 640, in <lambda>
    lambda _: self._clientDisconnected())
  File "/usr/lib/python3.8/site-packages/automat/_methodical.py", line 244, in _clientDisconnected
    value = output(oself, *a, **k)
  File "/usr/lib/python3.8/site-packages/automat/_methodical.py", line 283, in __call__
    return self.method(oself, *args, **kwargs)
  File "/usr/lib/python3.8/site-packages/twisted/application/internet.py", line 766, in _wait
    self._doWait()
  File "/usr/lib/python3.8/site-packages/twisted/application/internet.py", line 777, in _doWait
    delay = self._timeoutForAttempt(self._failedAttempts)
  File "/usr/lib/syncplay/syncplay/client.py", line 818, in retry
    self.ui.showMessage(getMessage("reconnection-attempt-notification"))
  File "/usr/lib/syncplay/syncplay/client.py", line 1581, in showMessage
    self.showOSDMessage(message, duration=constants.OSD_DURATION, OSDType=OSDType, mood=mood)
  File "/usr/lib/syncplay/syncplay/client.py", line 1611, in showOSDMessage
    self._client._player.displayMessage(message, int(duration * 1000), OSDType, mood)
  File "/usr/lib/syncplay/syncplay/players/mpv.py", line 132, in displayMessage
    self._listener.mpvpipe.show_text(messageString, duration, constants.MPLAYER_OSD_LEVEL)
  File "/usr/lib/syncplay/syncplay/players/python_mpv_jsonipc/python_mpv_jsonipc.py", line 584, in wrapper
    return self.command(name, *args)
  File "/usr/lib/syncplay/syncplay/players/python_mpv_jsonipc/python_mpv_jsonipc.py", line 617, in command
    return self.mpv_inter.command(command, *args)
  File "/usr/lib/syncplay/syncplay/players/python_mpv_jsonipc/python_mpv_jsonipc.py", line 316, in command
    self.socket.send({"command":command_list, "request_id": command_id})
  File "/usr/lib/syncplay/syncplay/players/python_mpv_jsonipc/python_mpv_jsonipc.py", line 156, in send
    raise BrokenPipeError("socket is closed")
builtins.BrokenPipeError: socket is closed

QFileSystemWatcher::removePaths: list is empty
QFileSystemWatcher::removePaths: list is empty

Arch Linux, qt 4.15.0, pyside built from git (44cb6278), syncplay from current master

[Et0h]

@iwalton3 Do you think the best way to resolve this would be to add an exception_callback or error_callback to python-mpv-jsonipc (similar to quit_callback) to allow those exceptions to be handled by Syncplay, or is there a better/simpler or alternative?

[iwalton3]

Right now quit_callback is supposed to be called when mpv dies for any reason. The ConnectionResetError might be due to mpv terminating uncleanly. I could just catch all exceptions and call quit_callback.

The BrokenPipeError is the current exception that I pass up for any MPV call where the connection stops existing.

[iwalton3]

This change should cover the issue: https://github.com/iwalton3/python-mpv-jsonipc/commit/40e34373480804c0600b515ade6842981892ed22

[albertosottile]

@Et0h Should we upgrade our vendor copy of python_mpv_jsonipc to include the fix linked here? At the moment, we are embedding 1.1.11.

[daniel-123]

I'm not sure at which point it has changed, but the problem doesn't occur anymore.

[FichteFoll]

I still experience the issue from OP with current master and Python 3.9. I don't seem to be able to reproduce the traceback I reported in this ticket earlier, however.

The most annoying part is that syncplay doesn't actually terminate afterwards, which then blocks my terminal until I suspend and/or kill syncplay.

[FichteFoll]

I don't seem to be able to reproduce the traceback I reported in this ticket earlier, however.

False alarm, I just forgot how to reproduce it. I still get the same traceback when I close the player (mpv).

[daniel-123]

@FichteFoll I'm not sure on what version you have tested, but using Python 3.9, mpv 0.32 and git HEAD of Syncplay on my own system I still cannot reproduce this issue. Neither by sending the signal to Syncplay nor to the connected player.

[FichteFoll]

~ ¬ mpv --version
mpv 0.33.0-dirty Copyright © 2000-2020 mpv/MPlayer/mplayer2 projects
 built on UNKNOWN
FFmpeg library versions:
   libavutil       56.51.100
   libavcodec      58.91.100
   libavformat     58.45.100
   libswscale      5.7.100
   libavfilter     7.85.100
   libswresample   3.7.100
FFmpeg version: n4.3.2

~ > python --version
Python 3.9.2

~ ∃ pacman -Ss syncplay
aur/syncplay 1.6.7-1
    synchronize watching movies on mplayer2, vlc, mpv, and mpc-hc on many computers
aur/syncplay-git 1.6.7.r24.g520569c-1 [installed]
    synchronize watching movies on mplayer2, vlc, mpv, and mpc-hc on many computers

~ ∇ syncplay
Attribute Qt::AA_EnableHighDpiScaling must be set before QCoreApplication is created.
^CException in thread Thread-2:
Traceback (most recent call last):
  File "/usr/lib/python3.9/threading.py", line 954, in _bootstrap_inner
    self.run()
  File "/usr/lib/syncplay/syncplay/vendor/python_mpv_jsonipc/python_mpv_jsonipc.py", line 163, in run
    current_data = self.socket.recv(1024)
ConnectionResetError: [Errno 104] Connection reset by peer

(that's a build from 520569c)

[daniel-123]

@FichteFoll could you try out whether PR #400 fixes the problem for you? I think that vendor change was what was supposed to fix the issue in first place.

[daniel-123]

@FichteFoll PR #400 has been fixed and merged into main branch. Could you test it now?

If it doesn't I'll might try to replicate the problem on Arch, but that would require me to set up a new VM so I'd prefer to avoid that :)

[FichteFoll]

400 doesn't seem to affect this issue at all. Closing mpv from a key binding or with ctrl-c from the terminal still results in the exception traces above.

[daniel-123]

@FichteFoll That seems really weird given that I don't see that issue with the same versions of Python/Syncplay.

Could you specify what distro you are using? Are you using pyside2/twisted from distro packages or from pip and in what versions?

[FichteFoll]

I use everything from the Arch repos, build syncplay (release or master) with aurutils and did a system update before all that. I also tested with --no-gui with the same results, so I think we can rule out pyside2. The installed twisted version is 20.3.0.

[FichteFoll]

I just recorded a video to show what I'm doing exactly, although it's really just ctrl-c for the terminal and q for mpv.

https://user-images.githubusercontent.com/931051/111871157-073e9980-8989-11eb-8ab1-51459ff16dbf.mp4

~ ▶ mpv --version
mpv 0.33.0-dirty Copyright © 2000-2020 mpv/MPlayer/mplayer2 projects
 built on UNKNOWN
FFmpeg library versions:
   libavutil       56.51.100
   libavcodec      58.91.100
   libavformat     58.45.100
   libswscale      5.7.100
   libavfilter     7.85.100
   libswresample   3.7.100
FFmpeg version: n4.3.2

~ ↻ pacman -Ss syncplay
aur/syncplay 1.6.7-1
    synchronize watching movies on mplayer2, vlc, mpv, and mpc-hc on many computers
aur/syncplay-git 1.6.7.r33.g77ce05d-1 [installed]
    synchronize watching movies on mplayer2, vlc, mpv, and mpc-hc on many computers

~ ¬ python --version
Python 3.9.2

[daniel-123]

I've whipped up an Arch container and installed the package from AUR - the problem actually appeared just like for you.

The thing is - it doesn't appear if I just run Syncplay directly from src folder of AUR repository or directly from our upstream repository. It also doesn't occur if I install Syncplay with make install.

This pretty conclusively narrows the problem down to the PKGBUILD and that puts it out of our hands since we aren't maintaining the AUR package. You can try asking the maintainer of that package to see what can be done to fix this. Or just use our AppImage/tarball.

Because of all the above I feel like this issue can be closed on our side. If you or somebody else manages to narrow it down to something within Syncplay itself feel free to reopen the issue.

[FichteFoll]

I can reproduce both problems from a cloned git repo with python syncplayClient.py --no-gui (and my system-wide syncplay removed to make sure there aren't any conflicts). I presume that's what you tried as well?

[daniel-123]

Yes, I've tried it on completely fresh Arch installation. Only difference was that I ran ./syncplayClient.py --no-gui rather than using python command. Which might have some effect on environment?

I also ran it with default Syncplay configuration save for host, room and player path.

[FichteFoll]

I also tried removing my mpv config to no avail. Where does syncplay store its configuration? The folder in ~/.config only has some of them, but renaming it didn't remove my nickname and room config, for example.

[daniel-123]

Standard config of syncplay is ~/.config/syncplay.ini, but it will also use any .syncplay in the folder tree where the video file is. Kinda like how .htaccess files work in Apache.

[FichteFoll]

I found my configuration file at ~/.syncplay. Renaming that and launching syncplay with command line overrides only, I managed to "fix" the long traceback from closing mpv but not from interrupting syncplay.

~/code/syncplay ж python syncplayClient.py -a syncplay.pl:8999 -n test -r nanatest --no-gui --player-path /usr/bin/mpv
[17:19:46] Attempting to connect to syncplay.pl:8999
[17:19:46] Attempting secure connection
[17:19:46] Successfully reached syncplay.pl (151.80.32.178)
[17:19:46] Secure connection established (TLSv1.3)

Hello test,

The Syncplay latest is available from http://syncplay.pl/

[17:19:46] Successfully connected to server
In room 'nanatest':
*<test>* is not playing a file
^CSocket connection died.
Traceback (most recent call last):
  File "/home/fichte/code/syncplay/syncplay/vendor/python_mpv_jsonipc/python_mpv_jsonipc.py", line 168, in run
    current_data = self.socket.recv(1024)
ConnectionResetError: [Errno 104] Connection reset by peer

The following config file should be able to reproduce the long traceback issue. I have never touched this file by hand before this (evident by me not knowing where it even was, heh) and only removed my media directories and trusted domains.

Details

``` [client_settings] name = FichteFoll room = nanatest playerpath = /usr/bin/mpv perplayerarguments = {'/usr/bin/mpv': ''} slowdownthreshold = 1.5 rewindthreshold = 4.0 fastforwardthreshold = 5.0 slowondesync = True rewindondesync = True fastforwardondesync = True dontslowdownwithme = False forceguiprompt = True filenameprivacymode = SendRaw filesizeprivacymode = SendRaw unpauseaction = IfOthersReady pauseonleave = False readyatstart = True autoplayminusers = -1.0 autoplayinitialstate = None mediasearchdirectories = [] sharedplaylistenabled = True loopatendofplaylist = False loopsinglefiles = False onlyswitchtotrusteddomains = True trusteddomains = [] publicservers = ['syncplay.pl:8995', 'syncplay.pl:8996', 'syncplay.pl:8997', 'syncplay.pl:8998', 'syncplay.pl:8999'] roomlist = [] autoplayrequiresamefilenames = True [gui] showosd = True showosdwarnings = False showslowdownosd = True showdifferentroomosd = False showsameroomosd = True shownoncontrollerosd = False showdurationnotification = True chatinputenabled = False chatinputfontunderline = False chatinputfontfamily = sans-serif chatinputrelativefontsize = 24.0 chatinputfontweight = 1.0 chatinputfontcolor = #FFFF00 chatinputposition = Top chatdirectinput = False chatoutputfontfamily = sans-serif chatoutputrelativefontsize = 24.0 chatoutputfontweight = 1.0 chatoutputfontunderline = False chatoutputmode = Chatroom chatmaxlines = 7.0 chattopmargin = 25.0 chatleftmargin = 20.0 chatbottommargin = 30.0 chatmoveosd = True chatosdmargin = 110.0 notificationtimeout = 3.0 alerttimeout = 5.0 chattimeout = 7.0 chatoutputenabled = False autosavejoinstolist = True [general] language = checkforupdatesautomatically = False lastcheckedforupdates = 2021-01-9 14:15:00.988 [server_data] host = syncplay.pl port = 8999 password = None ```

[daniel-123]

I did some more digging into this. After a fair bit of trying out various environments, settings and conditions I finally came to conclusion that this must be some sort of race condition. I haven't found any consistent way of triggering it, though it seems most common if I run Syncplay with no file specified and send SIGINT to it before loading any files.

My personal PC I'm testing this on is definitely on faster side (NVMe drive and overclocked Ryzen 5 CPU). All in all though, while I'm reopening the issue I think it might be somewhat hard to actually trace the reason for why this problem is occurring. And personally I see it as minor annoyance given that typical usage doesn't really involve SIGINT in first place. If somebody wants to dig into this I can offer some time with testing out the changes.