OS X: syncplay does not run on macOS Sierra 10.12

[albertosottile]

Syncplay (1.3 and 1.4) does not run on macOS Sierra 10.12 . After pressing the button "store configuration and run Syncplay", the console gives this error:

ValueError: time data '@Variant(' does not match format '%Y-%m-%d %H:%M:%S.%f'

The first window does not close and the syncplay media windows nor VLC do not start at all. If the button is then pushed again, the same error keeps showing up.

Tracing back the error, it points to the comparison in syncplay/resources/ui/GuiConfiguration.py line 281 if self.lastCheckedForUpdates > datetime.strptime(self.config["lastCheckedForUpdates"], "%Y-%m-%d %H:%M:%S.%f"):

If printed, both the variables self.config["lastCheckedForUpdates"] and self.lastCheckedForUpdates contain @Variant( . I have no idea why, but it seems that macOS 10.12 changed how these settings are stored/read from config files and/or the UI. I tried to correct this bug by myself but I am not a python developer, I did not find a way to alter or restore these values.

I "patched" the bug by disabling entirely this update check, by commenting lines from 279 to 284 in GuiConfiguration.py. With this edit, Syncplay and VLC start correctly, but then crash with a similar error, this time in gui.py, line 1326. This can be "solved" by disabling update check from the UI or commenting lines between 1325 and 1334. This way syncplay runs on macOS 10.12.

I understand that you do not have a macOS test system, so please let me know if I can assist you in fixing this bug for real.

Thanks for all your work, syncplay is amazing!

[Et0h]

Cheers, I'll look into whether the code can simply be disabled for OSX users without causing other problems.

[albertosottile]

Nevermind, Syncplay is actually unusable with macOS 10.12 Sierra. I guess lot of stuff were stored in these way, not only lastCheckedForUpdates , and apparently they are all broken. The program "seems" to run, but gives a lot of errors and constantly goes out of sync. Here there is a log from a session that I attempted to run today

18:47:25] unpaused [18:48:35] Warning: The media player took 9 seconds to respond. If you experience syncing issues then close applications to free up system resources, and if that doesn't work then try a different media player. [18:48:46] Rewinded due to time difference with [18:48:46] Slowing down due to time difference with [18:48:56] Rewinded due to time difference with [18:48:56] Rewinded due to time difference with [18:48:56] Rewinded due to time difference with [18:48:56] Rewinded due to time difference with [18:48:56] Rewinded due to time difference with [18:49:06] Connection with server lost, attempting to reconnect [18:49:10] Attempting to connect to syncplay.pl:8995 [18:49:20] Connection with server timed out [18:49:20] Connection with server lost, attempting to reconnect [18:49:32] Attempting to connect to syncplay.pl:8995 [18:49:34] has joined the room: 'room'

Hello Alby,

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

[18:49:34] Successfully connected to server [18:49:34] is playing 'filename.mkv' (20:32) in room: 'room'`

It does this every 2 or 3 minutes. I am going to try if syncplay portable can run in a Wine bottle and if not, I am going to downgrade back to 10.11 or give up and abandon Syncplay entirely. Please, at least state clear on the website and on Github that syncplay is NOT compatible with macOS 10.12 Sierra at all, so that no one else will have to go through this.

Thanks

[Et0h]

Thanks for your work on this - the website has now been updated. If you can get it to work with Wine please write some instructions to go on the website.

[albertosottile]

I tried with Crossover 15.3 (basically Wine), but the bottle crashed after pushing "Store configuration and run Syncplay". I already downgraded to macOS 10.11.6 where everything is fine. I think part of the problem (if not all of it) is due to the pyside and qt4 support on 10.12. Maybe in the future there will be updates fro these packages and syncplay will then work seamlessly. I think I will give it another try on 10.12 in the next few months.

[Hamuko]

I think part of the problem (if not all of it) is due to the pyside and qt4 support on 10.12. Maybe in the future there will be updates fro these packages and syncplay will then work seamlessly.

Homebrew devs currently consider Qt4 a deprecated product, as it's currently dead on upstream and has been broken on OS X for a couple of major versions as of now. For Qt4 to work on OS X 10.11, the formula had to be patched before building and for 10.12, there's even more patches to be applied. The devs do not consider cutting features one at a time from Qt4 as a viable strategy, so it will probably not be supported past 10.11.

You can find more information as well as the fix to install Qt4 on 10.12 via Homebrew at Homebrew/homebrew-core#5216. It does definitely work to get Qt4 and PySide working on 10.12, as I tried it out yesterday. However, the Syncplay core worked as well for me with mpv as it did on 10.9, that is to say not at all. But I guess if you formerly had Syncplay working on OS X, you could fix the client this way.

The long-term solution would be to switch to Qt5, but as far as I know, PySide does not work with Qt5 and PySide2 is far from production ready. PyQt would work with Qt5, but that requires the entire project to be converted to GPL. So as far as I see it, there just isn't a good strategy to get the Qt GUI working on current and future versions of OS X.

[albertosottile]

I am aware of this, I used the tap from @cartr to install qt4 and pyside on 10.12, without that it would have been impossible to even run Syncplay with a GUI on 10.12. We could try to file an issue on his tap ( https://github.com/cartr/homebrew-qt4 ) but we need a test system with 10.12 and currently I downgraded to 10.11 to be able to use Syncplay again. Also, i think that we need a POC code that just uses ConfigDialog and reproduces the issue, to help the developer to fix the bug.

Moreover, this effort will only fix the UI bugs that I addressed by commenting the code, but not the loss of sync that I experienced later. To be honest, I have no idea of why that happened, and we cannot have any input from Syncplay's developers because they do not have a Mac. So I don't see an easy way to solve these problems. Speaking of that, if any of you has any idea of what (qt related or not) could have caused the problems described in the third comment, please share.

[Hamuko]

From what I could tell from testing Syncplay on macOS, it seems that there's just absolutely no communication between mpv and Syncplay. I joined a room and it would not announce a file and it would not sync up the player at all. I had a quick look at how the mpv integration is built, but I was not really able to get a good grasp at what the working logic of it was.

Of course, this doesn't really relate to your problems with VLC, since I don't use it and have even less of a clue as to how that operates. However, I am not really aware of any other fact about macOS that causes the lack of sync other than the player communication. When I first tested Syncplay on OS X (10.9), I could not get VLC or mpv to communicate properly with the client, although VLC would at least do something, even though it seemed to result in lots of seeking and resets quite early.

Since I don't really have an idea as to how to fix Syncplay for my own usage, I decided on Tuesday to start working on my own implementation of the client software using the protocol documentation. I'm also using a different method of communicating with mpv (as far as I can tell), which seems to result in better syncing of the file and playback information. However, I don't think that the implementation is at all portable for other operating systems, Windows in particular. It also might not be just the player integration, as I am rewriting all of the protocol communication as well.

[albertosottile]

I have never experienced these problems with VLC on macOS before updating to 10.12, I am quite surprised that you had with VLC. I used syncplay both with conda and with installed packages (via homebrew or macports) and never had any sync issues with VLC up to macOS 10.11. I even have a packaged .app I made for myself a while ago (syncplay 1.3.0) that works with VLC (up to 2.2.3, did not try 2.2.4 yet) with macOS from 10.9 to 10.11. If you are interested, I can send it to you.

[Hamuko]

Not really even interested, since VLC is a shit player all in all. I was surprised to see this week that I even had it on my computer, seemingly left over from my testing of Syncplay probably around last summer.

But as far as I remember the event, it would actually communicate the file information to the server, the playback would start with the rest of the people, but within a few minutes (at max), there would be tons of speed modifications and skipping. Pretty sure at some point the video just skipped right to the beginning. It was so terrible that we just decided to post "START" in IRC and watch them all independently.

[albertosottile]

This is weird, I wonder if I got lucky or if you had some extra troubles on your system... I am using that .app since February 2015 with no sync issues, even during movies (so 2h+ length), although I have to admit I am using it only with one person and never tried groups.

[albertosottile]

I started digging on this issue (even though I do not have a 10.12 Sierra system to test at the moment) and for now I focused on the '@Variant(' problem. In the pyside 1.2.1 documentation, in the method PySide.QtCore.QSettings.value(key[, defaultValue=None]) there is this warning: http://pyside.github.io/docs/pyside/PySide/QtCore/QSettings.html#PySide.QtCore.PySide.QtCore.QSettings.value

Warning: QSettings.value can return different types (QVariant types) depending on the platform it’s running on, so the safest way to use it is always casting the result to the desired type, e.g.: int(settings.value(“myKey”))

I am writing to the syncplay developers now. It could be possible for you to cast explicitly all the calls of this QSettings.value method in the code? I tried to look at the code and this method is not called that often, but I still have some difficulties in find the right type on my own (thanks Python). If you could make this cast this should solve at least the first bug (caused by this incorrect casting) and maybe also the others, without breaking the support for other platforms.

[Et0h]

Thanks for that research. I'll look into adding proper Variant typing when I next have some free time. In the meantime, it might worth checking out Hamuko's work on an OS X Python 3 alternative client for Syncplay users: https://github.com/Hamuko/Sopu

[Hamuko]

I'd like to point out that my alternative client is far from finished currently. A major feature missing from it currently is the ability to seek the video. But I have used it to watch TV episodes with a friend using the official client quite nicely, so you should at least be able to participate in the viewing.

[albertosottile]

This qt4 on Sierra bug has been reproduced (and patched) by Qt developers, but only for qt5 ( https://github.com/qt/qtbase/commit/764f5bf48cc87f4c72550b853ab93b815454cd48 ). Other developers have successfully backported this patch to qt4 ( https://github.com/mumble-voip/mumble/issues/2638 ). So the next step would be to patch qt4 source code in this way, compile it on 10.12 and see how Syncplay behaves with this patch. Unfortunately, I uninstalled 10.12 precisely because I need a working copy of Syncplay on my system... If anyone else could try if this works, that would be great.

[winneon]

I have a 10.12 system, so I could give it a shot later tonight.

[albertosottile]

In the meantime, I opened an issue on the (custom) homebrew recipe for qt4 on Sierra cited before, maybe the developer can implement this patch in his recipe ( https://github.com/cartr/homebrew-qt4/issues/1 ).

[winneon]

I'm working on backporting this, but the mumble example you linked does not provide a patch for qt4.8, only qt5, so I'm running into a few problems compiling qt with the changes applied. I've contacted the the mumble member assigned to that issue, so hopefully I'll be able to get this resolved fairly quick.

[cartr]

@winneon I suspect https://github.com/mumble-voip/mumble-developers-qt/commit/38ca587a64499707cb375738758430f8d105fc7d is the patch you're looking for.

[winneon]

https://github.com/cartr/homebrew-qt4/commit/cecf34332b379b1341806d3cc6b95b357ad7b4df with that commit has been patched. I'm now having trouble with syncplay finding and using pyside for the GUI, but syncplay works completely fine as a CLI.

[winneon]

Ok, I can confirm with the patched changes at https://github.com/cartr/homebrew-qt4/commit/cecf34332b379b1341806d3cc6b95b357ad7b4df that Syncplay works fine with preliminary testing using mpv, on macOS 10.12.1 Sierra.

The only issue I can find at the moment is the button "Open media file" under File. It opens the file dialog for a split second and then it closes it, perhaps crashing. It doesn't print anything in the console when doing so however.

[albertosottile]

First of all, thanks to @cartr for finding and implementing the right patch in just a few hours! Also, thanks to @winneon for testing it with Syncplay. However, I do not understand if Syncplay is usable or not after this patch. You managed to get into the room, but you could not open a file, apparently, which is similar to the bug I found in the beginning. I thought that bug was caused by the issue you just fixed... Maybe at this point we need further help from Syncplay developers, @Et0h ?

[winneon]

I was able to play a file by directly opening it in mpv, and the stream dialog in Syncplay works fine as well. Every sync function works fine when playing the file, the only problems arise from when Syncplay opens a file dialog itself, perhaps due to a changed API in Sierra.

[albertosottile]

@Et0h I am working on porting Syncplay to qt5 using https://github.com/mottosso/Qt.py . Currently, the app works flawlessly without even installing qt4, but I am experiencing random disconnections from the server with the error "Connection with server timed out". Any suggestions about how to debug this? Could it still be related to qt, or do you think there are issues with other libraries in macOS 10.12? Thanks

[Et0h]

@alby128 I've not encountered that issue on Windows (except with the open file dialogue) so I'm guessing it is some OS X (or OS X implementation) threading/freezing thing, but I don't use OS X so I'm not sure what it is. You can run Syncplay in --debug mode for some debug messages, but I don't know if that'll help.

[albertosottile]

Here there is the debug log corresponding to one of the disconnections experienced by the client. @Et0h Do you have any idea of what it is happening here? Thanks

[19:53:56] VLC did not response in time, so assuming position is 228.797376975 (218.79873+9.99864697456) [19:53:56] client/server << {"State": {"playstate": {"paused": false, "position": 219.77565138685026, "setBy": "Alby2", "doSeek": false}, "ping": {"serverRtt": 0.023860931396484375, "latencyCalculation": 1504547498.892827}}} [19:53:56] Caught attempt to rewind due to time difference with self [19:53:56] Caught attempt to slow down due to time difference with self [19:53:56] client/server >> {"State": {"ping": {"clientRtt": 0.023807048797607422, "clientLatencyCalculation": 1504547636.969482, "latencyCalculation": 1504547498.892827}, "playstate": {"paused": false, "position": 228.79816280220032}}} [19:53:56] client/server << {"State": {"playstate": {"paused": false, "position": 220.77564828740873, "setBy": "Alby2", "doSeek": false}, "ping": {"serverRtt": 0.023860931396484375, "latencyCalculation": 1504547499.892823}}} [19:53:56] Caught attempt to rewind due to time difference with self [19:53:56] Caught attempt to slow down due to time difference with self [19:53:56] client/server >> {"State": {"ping": {"clientRtt": 0.023807048797607422, "clientLatencyCalculation": 1504547636.969638, "latencyCalculation": 1504547499.892823}, "playstate": {"paused": false, "position": 228.79832087371827}}} [19:53:56] client/server << {"State": {"playstate": {"paused": false, "position": 221.77274586190308, "setBy": "Alby", "doSeek": false}, "ping": {"serverRtt": 0.023860931396484375, "latencyCalculation": 1504547500.892855}}} [19:53:56] player >> set-position: 221.784825442 [19:53:56] player >> display-osd: top-right, 3, Rewinded due to time difference with [19:53:56] player >> set-rate: 0.95 [19:53:56] player >> display-osd: top-right, 3, Slowing down due to time difference with [19:53:56] player >> . [19:53:56] player << playstate: playing [19:53:56] player << position: 221.784825 [19:54:06] VLC did not response in time, so assuming position is 231.783201846 (221.784825+9.99837684631) [19:54:06] client/server >> {"State": {"ping": {"clientRtt": 0.023807048797607422, "clientLatencyCalculation": 1504547646.977373, "latencyCalculation": 1504547500.892855}, "playstate": {"paused": false, "position": 231.7832199661255}}} [19:54:06] client/server << {"State": {"playstate": {"paused": false, "position": 222.7727158211621, "setBy": "Alby", "doSeek": false}, "ping": {"serverRtt": 0.023860931396484375, "latencyCalculation": 1504547501.892826}}} [19:54:06] player >> set-position: 222.784795402 [19:54:06] player >> display-osd: top-right, 3, Rewinded due to time difference with [19:54:06] client/server >> {"State": {"ping": {"clientRtt": 0.023807048797607422, "clientLatencyCalculation": 1504547646.981001, "latencyCalculation": 1504547501.892826}, "playstate": {"paused": false, "position": 231.7866517631531}}} [19:54:06] client/server << {"State": {"playstate": {"paused": false, "position": 223.77565019475736, "setBy": "Alby2", "doSeek": false}, "ping": {"serverRtt": 0.023860931396484375, "latencyCalculation": 1504547502.892826}}} [19:54:06] Caught attempt to rewind due to time difference with self [19:54:06] client/server >> {"State": {"ping": {"clientRtt": 0.023807048797607422, "clientLatencyCalculation": 1504547646.981187, "latencyCalculation": 1504547502.892826}, "playstate": {"paused": false, "position": 231.78684178276063}}} [19:54:06] client/server << {"State": {"playstate": {"paused": false, "position": 224.77564018117704, "setBy": "Alby2", "doSeek": false}, "ping": {"serverRtt": 0.023860931396484375, "latencyCalculation": 1504547503.892816}}} [19:54:06] Caught attempt to rewind due to time difference with self [19:54:06] client/server >> {"State": {"ping": {"clientRtt": 0.023807048797607422, "clientLatencyCalculation": 1504547646.981338, "latencyCalculation": 1504547503.892816}, "playstate": {"paused": false, "position": 231.7869917480469}}} [19:54:06] client/server << {"State": {"playstate": {"paused": false, "position": 225.7756463800601, "setBy": "Alby2", "doSeek": false}, "ping": {"serverRtt": 0.023860931396484375, "latencyCalculation": 1504547504.89282}}} [19:54:06] Caught attempt to rewind due to time difference with self [19:54:06] client/server >> {"State": {"ping": {"clientRtt": 0.023807048797607422, "clientLatencyCalculation": 1504547646.981496, "latencyCalculation": 1504547504.89282}, "playstate": {"paused": false, "position": 231.78715077323915}}} [19:54:06] client/server << {"State": {"playstate": {"paused": false, "position": 226.77563326703824, "setBy": "Alby2", "doSeek": false}, "ping": {"serverRtt": 0.023860931396484375, "latencyCalculation": 1504547505.89281}}} [19:54:06] Caught attempt to rewind due to time difference with self [19:54:06] client/server >> {"State": {"ping": {"clientRtt": 0.023807048797607422, "clientLatencyCalculation": 1504547646.981619, "latencyCalculation": 1504547505.89281}, "playstate": {"paused": false, "position": 231.78727475090028}}} [19:54:06] client/server << {"State": {"playstate": {"paused": false, "position": 227.77566426145353, "setBy": "Alby2", "doSeek": false}, "ping": {"serverRtt": 0.023860931396484375, "latencyCalculation": 1504547506.892839}}} [19:54:06] client/server >> {"State": {"ping": {"clientRtt": 0.023807048797607422, "clientLatencyCalculation": 1504547646.981725, "latencyCalculation": 1504547506.892839}, "playstate": {"paused": false, "position": 231.78738084716798}}} [19:54:06] client/server << {"State": {"playstate": {"paused": false, "position": 228.775661162012, "setBy": "Alby2", "doSeek": false}, "ping": {"serverRtt": 0.023860931396484375, "latencyCalculation": 1504547507.892836}}} [19:54:06] client/server >> {"State": {"ping": {"clientRtt": 0.023807048797607422, "clientLatencyCalculation": 1504547646.981828, "latencyCalculation": 1504547507.892836}, "playstate": {"paused": false, "position": 231.78748384399415}}} [19:54:06] player >> . [19:54:06] player << playstate: playing [19:54:06] player << position: 222.784795 [19:54:16] VLC did not response in time, so assuming position is 232.784065201 (222.784795+9.99927020073) [19:54:16] client/server >> {"State": {"ignoringOnTheFly": {"client": 1}, "ping": {"clientRtt": 0.023807048797607422, "clientLatencyCalculation": 1504547656.983047}, "playstate": {"paused": false, "position": 232.7840752143097, "doSeek": true}}} [19:54:16] client/server << {"State": {"playstate": {"paused": false, "position": 229.71056265224314, "setBy": "Alby", "doSeek": false}, "ping": {"serverRtt": 0.023860931396484375, "latencyCalculation": 1504547508.892851}}} [19:54:16] client/server >> {"State": {"ignoringOnTheFly": {"client": 1}, "ping": {"clientRtt": 0.023807048797607422, "clientLatencyCalculation": 1504547656.990258, "latencyCalculation": 1504547508.892851}}} [19:54:16] client/server << {"State": {"playstate": {"paused": false, "position": 230.71055454601145, "setBy": "Alby", "doSeek": false}, "ping": {"serverRtt": 0.023860931396484375, "latencyCalculation": 1504547509.892846}}} [19:54:16] client/server >> {"State": {"ignoringOnTheFly": {"client": 1}, "ping": {"clientRtt": 0.023807048797607422, "clientLatencyCalculation": 1504547656.990486, "latencyCalculation": 1504547509.892846}}} [19:54:16] client/server << {"Set": {"user": {"Alby2": {"room": {"name": "Cucci"}, "event": {"left": true}}}}} [19:54:17] player >> display-osd: top-right, 3, Connection with server lost, attempting to reconnect [19:54:17] player >> .

[albertosottile]

@Et0h And this is the log using mpv instead:

By looking on the notifications in a functioning client, it appears that the affected client disconnected at [16:02:35] and rejoined at 16:03:30. The affected client does not realize that it has lost connection until [16:03:29]. Also, the checks with the mpv player reduce their frequency dramatically during this affected time (going from one each second to a few dozens along a whole minute of "unrecognized downtime").

Any idea of the code that is causing this with both players? Thanks again.

[16:02:10] player << ANS_pause=no [16:02:10] player << ANS_time-pos=283.560000 [16:02:10] client/server << {"State": {"playstate": {"paused": false, "position": 283.603743840352, "setBy": "Alby2", "doSeek": false}, "ping": {"serverRtt": 0.023736953735351562, "clientLatencyCalculation": 1504620130.445074, "latencyCalculation": 1504620001.161748}}} [16:02:10] client/server >> {"State": {"ping": {"clientRtt": 0.0237119197845459, "clientLatencyCalculation": 1504620130.468845, "latencyCalculation": 1504620001.161748}, "playstate": {"paused": false, "position": 283.6149259185791}}} [16:02:10] player >> print_text ANS_pause=${pause} print_text ANS_time-pos=${=time-pos} [16:02:10] player << ANS_pause=no [16:02:10] player << ANS_time-pos=283.640000 [16:02:10] player >> print_text ANS_pause=${pause} print_text ANS_time-pos=${=time-pos} [16:02:10] player << ANS_pause=no [16:02:10] player << ANS_time-pos=283.760000 [16:02:10] player >> print_text ANS_pause=${pause} print_text ANS_time-pos=${=time-pos} [16:02:10] player << ANS_pause=no [16:02:10] player << ANS_time-pos=283.840000 [16:02:10] player >> print_text ANS_pause=${pause} print_text ANS_time-pos=${=time-pos} [16:02:10] player << ANS_pause=no [16:02:10] player << ANS_time-pos=283.960000 [16:02:10] player >> print_text ANS_pause=${pause} print_text ANS_time-pos=${=time-pos} [16:02:10] player << ANS_pause=no [16:02:10] player << ANS_time-pos=284.040000 [16:02:11] player >> print_text ANS_pause=${pause} print_text ANS_time-pos=${=time-pos} [16:02:11] player << ANS_pause=no [16:02:11] player << ANS_time-pos=284.160000 [16:02:11] player >> print_text ANS_pause=${pause} print_text ANS_time-pos=${=time-pos} [16:02:11] player << ANS_pause=no [16:02:11] player << ANS_time-pos=284.240000 [16:02:11] player >> print_text ANS_pause=${pause} print_text ANS_time-pos=${=time-pos} [16:02:11] player << ANS_pause=no [16:02:11] player << ANS_time-pos=284.360000 [16:02:11] player >> print_text ANS_pause=${pause} print_text ANS_time-pos=${=time-pos} [16:02:11] player << ANS_pause=no [16:02:11] player << ANS_time-pos=284.440000 [16:02:11] client/server << {"State": {"playstate": {"paused": false, "position": 284.6037307273302, "setBy": "Alby2", "doSeek": false}, "ping": {"serverRtt": 0.023800134658813477, "clientLatencyCalculation": 1504620131.4450328, "latencyCalculation": 1504620002.161737}}} [16:02:11] client/server >> {"State": {"ping": {"clientRtt": 0.024030208587646484, "clientLatencyCalculation": 1504620131.469139, "latencyCalculation": 1504620002.161737}, "playstate": {"paused": false, "position": 284.59591406822204}}} [16:02:11] player >> print_text ANS_pause=${pause} print_text ANS_time-pos=${=time-pos} [16:02:11] player << ANS_pause=no [16:02:11] player << ANS_time-pos=284.600000 [16:02:21] mpv did not response in time, so assuming position is 294.600673056 (284.6+10.0006730556) [16:02:21] client/server << {"State": {"playstate": {"paused": false, "position": 285.60308838722216, "setBy": "Alby2", "doSeek": false}, "ping": {"serverRtt": 0.023800134658813477, "latencyCalculation": 1504620003.161716}}} [16:02:21] Caught attempt to rewind due to time difference with self [16:02:21] Caught attempt to slow down due to time difference with self [16:02:21] client/server >> {"State": {"ping": {"clientRtt": 0.024030208587646484, "clientLatencyCalculation": 1504620141.4712, "latencyCalculation": 1504620003.161716}, "playstate": {"paused": false, "position": 294.6014641284943}}} [16:02:21] client/server << {"State": {"playstate": {"paused": false, "position": 286.6031084143828, "setBy": "Alby2", "doSeek": false}, "ping": {"serverRtt": 0.023800134658813477, "latencyCalculation": 1504620004.161735}}} [16:02:21] Caught attempt to rewind due to time difference with self [16:02:21] Caught attempt to slow down due to time difference with self [16:02:21] client/server >> {"State": {"ping": {"clientRtt": 0.024030208587646484, "clientLatencyCalculation": 1504620141.471374, "latencyCalculation": 1504620004.161735}, "playstate": {"paused": false, "position": 294.60164103508}}} [16:02:21] client/server << {"State": {"playstate": {"paused": false, "position": 287.6031084143828, "setBy": "Alby2", "doSeek": false}, "ping": {"serverRtt": 0.023800134658813477, "latencyCalculation": 1504620005.161735}}} [16:02:21] Caught attempt to rewind due to time difference with self [16:02:21] Caught attempt to slow down due to time difference with self [16:02:21] client/server >> {"State": {"ping": {"clientRtt": 0.024030208587646484, "clientLatencyCalculation": 1504620141.471517, "latencyCalculation": 1504620005.161735}, "playstate": {"paused": false, "position": 294.60178503990176}}} [16:02:21] client/server << {"State": {"playstate": {"paused": false, "position": 288.6031234347533, "setBy": "Alby2", "doSeek": false}, "ping": {"serverRtt": 0.023800134658813477, "latencyCalculation": 1504620006.161751}}} [16:02:21] Caught attempt to rewind due to time difference with self [16:02:21] Caught attempt to slow down due to time difference with self [16:02:21] client/server >> {"State": {"ping": {"clientRtt": 0.024030208587646484, "clientLatencyCalculation": 1504620141.471651, "latencyCalculation": 1504620006.161751}, "playstate": {"paused": false, "position": 294.6019190311432}}} [16:02:21] client/server << {"State": {"playstate": {"paused": false, "position": 289.6031143748473, "setBy": "Alby2", "doSeek": false}, "ping": {"serverRtt": 0.023800134658813477, "latencyCalculation": 1504620007.161739}}} [16:02:21] Caught attempt to rewind due to time difference with self [16:02:21] Caught attempt to slow down due to time difference with self [16:02:21] client/server >> {"State": {"ping": {"clientRtt": 0.024030208587646484, "clientLatencyCalculation": 1504620141.471789, "latencyCalculation": 1504620007.161739}, "playstate": {"paused": false, "position": 294.6020570755005}}} [16:02:21] client/server << {"State": {"playstate": {"paused": false, "position": 290.6031143748473, "setBy": "Alby2", "doSeek": false}, "ping": {"serverRtt": 0.023800134658813477, "latencyCalculation": 1504620008.16174}}} [16:02:21] Caught attempt to slow down due to time difference with self [16:02:21] client/server >> {"State": {"ping": {"clientRtt": 0.024030208587646484, "clientLatencyCalculation": 1504620141.471908, "latencyCalculation": 1504620008.16174}, "playstate": {"paused": false, "position": 294.6021770000458}}} [16:02:21] client/server << {"State": {"playstate": {"paused": false, "position": 291.60311032173144, "setBy": "Alby2", "doSeek": false}, "ping": {"serverRtt": 0.023800134658813477, "latencyCalculation": 1504620009.161738}}} [16:02:21] Caught attempt to slow down due to time difference with self [16:02:21] client/server >> {"State": {"ping": {"clientRtt": 0.024030208587646484, "clientLatencyCalculation": 1504620141.472025, "latencyCalculation": 1504620009.161738}, "playstate": {"paused": false, "position": 294.60229406356814}}} [16:02:21] client/server << {"State": {"playstate": {"paused": false, "position": 292.6030922019194, "setBy": "Alby2", "doSeek": false}, "ping": {"serverRtt": 0.023800134658813477, "latencyCalculation": 1504620010.161718}}} [16:02:21] Caught attempt to slow down due to time difference with self [16:02:21] client/server >> {"State": {"ping": {"clientRtt": 0.024030208587646484, "clientLatencyCalculation": 1504620141.472139, "latencyCalculation": 1504620010.161718}, "playstate": {"paused": false, "position": 294.60240802764895}}} [16:02:21] client/server << {"State": {"playstate": {"paused": false, "position": 293.6031243884276, "setBy": "Alby2", "doSeek": false}, "ping": {"serverRtt": 0.023800134658813477, "latencyCalculation": 1504620011.16175}}} [16:02:21] client/server >> {"State": {"ping": {"clientRtt": 0.024030208587646484, "clientLatencyCalculation": 1504620141.472243, "latencyCalculation": 1504620011.16175}, "playstate": {"paused": false, "position": 294.60251197814944}}} [16:02:21] client/server << {"State": {"playstate": {"paused": false, "position": 294.6031153285216, "setBy": "Alby2", "doSeek": false}, "ping": {"serverRtt": 0.023800134658813477, "latencyCalculation": 1504620012.161742}}} [16:02:21] client/server >> {"State": {"ping": {"clientRtt": 0.024030208587646484, "clientLatencyCalculation": 1504620141.472346, "latencyCalculation": 1504620012.161742}, "playstate": {"paused": false, "position": 294.6026161670685}}} [16:02:22] client/server << {"State": {"playstate": {"paused": false, "position": 295.7695804925151, "setBy": "Alby", "doSeek": false}, "ping": {"serverRtt": 0.027492046356201172, "clientLatencyCalculation": 1504620142.444849, "latencyCalculation": 1504620013.161739}}} [16:02:22] client/server >> {"State": {"ping": {"clientRtt": 0.0239560604095459, "clientLatencyCalculation": 1504620142.468879, "latencyCalculation": 1504620013.161739}, "playstate": {"paused": false, "position": 295.5991409778595}}} [16:02:22] player >> print_text ANS_pause=${pause} print_text ANS_time-pos=${=time-pos} [16:02:22] player << ANS_pause=no [16:02:22] player << ANS_time-pos=295.600000 [16:02:32] mpv did not response in time, so assuming position is 305.600699043 (295.6+10.0006990433) [16:02:32] client/server << {"State": {"playstate": {"paused": false, "position": 296.56220075521617, "setBy": "Alby", "doSeek": false}, "ping": {"serverRtt": 0.027492046356201172, "latencyCalculation": 1504620014.161732}}} [16:02:32] player >> no-osd set time-pos 296.57411873 [16:02:42] player >> show_text "Rewinded due to time difference with " 3000 1 [16:02:42] Throttling message send, so sleeping for 0.05 [16:02:52] player >> no-osd set speed 0.95 [16:02:52] Throttling message send, so sleeping for 0.05 [16:03:02] player >> show_text "Slowing down due to time difference with " 3000 1 [16:03:02] Throttling message send, so sleeping for 0.05 [16:03:12] player >> print_text ANS_pause=${pause} print_text ANS_time-pos=${=time-pos} [16:03:12] player << ANS_pause=no [16:03:12] player << ANS_time-pos=335.680000 [16:03:22] mpv did not response in time, so assuming position is 345.68067091 (335.68+10.0006709099) [16:03:22] client/server >> {"State": {"ignoringOnTheFly": {"client": 1}, "ping": {"clientRtt": 0.0239560604095459, "clientLatencyCalculation": 1504620202.655803}, "playstate": {"paused": false, "position": 345.68073099136353, "doSeek": true}}} [16:03:22] client/server >> {"State": {"ignoringOnTheFly": {"client": 1}, "ping": {"clientRtt": 0.0239560604095459, "clientLatencyCalculation": 1504620202.660002, "latencyCalculation": 1504620014.161732}}} [16:03:22] player >> print_text ANS_pause=${pause} print_text ANS_time-pos=${=time-pos} [16:03:22] player << ANS_pause=no [16:03:22] player << ANS_time-pos=345.160000 [16:03:29] mpv did not response in time, so assuming position is 352.154667053 (345.16+6.99466705322) [16:03:29] player >> show_text "Connection with server lost, attempting to reconnect" 3000 1 [16:03:29] player >> print_text ANS_pause=${pause} print_text ANS_time-pos=${=time-pos} [16:03:29] player << ANS_pause=no [16:03:29] player << ANS_time-pos=351.880000 [16:03:29] player >> print_text ANS_pause=${pause} print_text ANS_time-pos=${=time-pos} [16:03:29] player << ANS_pause=no [16:03:29] player << ANS_time-pos=351.960000 [16:03:29] Throttling message send, so sleeping for 0.05 [16:03:29] player >> show_text "Attempting to connect to syncplay.pl:8995" 3000 1 [16:03:29] Throttling message send, so sleeping for 0.05 [16:03:29] player >> print_text ANS_pause=${pause} print_text ANS_time-pos=${=time-pos} [16:03:29] player << ANS_pause=no [16:03:29] player << ANS_time-pos=352.120000 [16:03:29] client/server >> {"Hello": {"username": "Alby2", "version": "1.2.255", "room": {"name": "Cucci"}, "realversion": "1.5.0"}} [16:03:29] client/server << {"Set": {"user": {"Alby2": {"room": {"name": "Cucci"}}}}} [16:03:29] Throttling message send, so sleeping for 0.05 [16:03:30] player >> show_text " has joined the room: 'Cucci'" 3000 1 [16:03:30] client/server << {"Set": {"ready": {"username": "Alby2", "isReady": null, "manuallyInitiated": false}}} [16:03:30] Throttling message send, so sleeping for 0.05 [16:03:30] player >> show_text "Not ready: Alby2\n has joined the room: 'Cucci'" 1000 1 [16:03:30] Throttling message send, so sleeping for 0.05 [16:03:30] player >> show_text "Not ready: Alby2\n has joined the room: 'Cucci'" 1000 1 [16:03:30] client/server << {"Set": {"playlistChange": {"files": [], "user": "Alby"}}} [16:03:30] client/server << {"Set": {"playlistIndex": {"index": null, "user": "Alby"}}} [16:03:30] client/server << {"Hello": {"username": "Alby2", "version": "1.5.0", "motd": "\nHello Alby2,\n\nThe Syncplay latest is available from http://syncplay.pl/\n\n", "room": {"name": "Cucci"}, "realversion": "1.4.0"}} [16:03:30] Throttling message send, so sleeping for 0.05 [16:03:30] player >> show_text "Not ready: Alby2\nSuccessfully connected to server" 3000 1 [16:03:30] client/server >> {"Set": {"ready": {"isReady": false, "manuallyInitiated": false}}} [16:03:30] client/server >> {"Set": {"file": {"duration": 1215.84, "name": "Futurama.S07E15.Realta.In.2D.iTALiAN.PDTV.XviD-ACiD.avi", "size": 179329024}}} [16:03:30] client/server >> {"List": null} [16:03:30] Throttling message send, so sleeping for 0.05 [16:03:30] player >> print_text ANS_pause=${pause} print_text ANS_time-pos=${=time-pos} [16:03:30] player << ANS_pause=no [16:03:30] player << ANS_time-pos=352.400000 [16:03:30] Throttling message send, so sleeping for 0.05 [16:03:30] player >> show_text "Not ready: Alby2\nSuccessfully connected to server" 1000 1 [16:03:30] Throttling message send, so sleeping for 0.05 [16:03:30] player >> print_text ANS_pause=${pause} print_text ANS_time-pos=${=time-pos} [16:03:30] player << ANS_pause=no [16:03:30] player << ANS_time-pos=352.520000 [16:03:30] client/server << {"State": {"playstate": {"paused": false, "position": 363.43052249123923, "setBy": "Alby", "doSeek": false}, "ping": {"serverRtt": 0, "latencyCalculation": 1504620080.787315}}} [16:03:30] Throttling message send, so sleeping for 0.05 [16:03:30] player >> no-osd set time-pos 363.430522491 [16:03:30] Not sending setPaused to mpv as state is already False [16:03:30] Throttling message send, so sleeping for 0.05 [16:03:30] player >> no-osd set speed 1.00 [16:03:30] Throttling message send, so sleeping for 0.05 [16:03:30] player >> show_text "Not ready: Alby2\nReverting speed back to normal" 3000 1 [16:03:30] Not sending setPaused to mpv as state is already False [16:03:30] Throttling message send, so sleeping for 0.05 [16:03:30] player >> show_text "Not ready: Alby2\n unpaused" 3000 1 [16:03:30] Throttling message send, so sleeping for 0.05 [16:03:30] player >> print_text ANS_pause=${pause} print_text ANS_time-pos=${=time-pos} [16:03:30] player << ANS_pause=no [16:03:30] player << ANS_time-pos=363.600000 [16:03:30] Throttling message send, so sleeping for 0.05 [16:03:30] player >> show_text "Not ready: Alby2\n unpaused" 1000 1 [16:03:30] client/server >> {"State": {"ping": {"clientRtt": 0, "clientLatencyCalculation": 1504620210.718907, "latencyCalculation": 1504620080.787315}, "playstate": {"paused": false, "position": 363.65152797698977}}} [16:03:30] Throttling message send, so sleeping for 0.05 [16:03:30] player >> print_text ANS_pause=${pause} print_text ANS_time-pos=${=time-pos} [16:03:30] player << ANS_pause=no [16:03:30] player << ANS_time-pos=363.680000

[albertosottile]

Found it. The issues are caused by a macOS specific feature, App Nap https://developer.apple.com/library/content/documentation/Performance/Conceptual/power_efficiency_guidelines_osx/AppNap.html . Every time the system puts the python app in this App Nap mode, all the errors start. Preventing App Nap to affect the python executable is the only way to solve all these issues.

Now, I attempted several ways to prevent App Nap on Syncplay, including packaging the software in a single .app file and experimenting with multiple flags. So far, the only convenient, consistent, and reliable method that I found is to use appnope https://github.com/minrk/appnope . I am not an expert In software licenses, so I do not know if a PR that includes this simple fix is feasible. Using appnope, syncplay is stable on macOS 10.9+, including 10.12. So far, I did not test it on 10.13 betas.

Thank you all for your assistance. @Et0h please let me know what you think about this fix, and if a PR that uses this package is possible. Plus, I am working on creating a standalone .app for Syncplay using py2app (solving multiple other issues listed on this repository) but I need your support for a menubar issue that I encountered, if you are available.

[Et0h]

Thanks for your work investigating this matter. I'll look into what I can next week although as I don't use OS X there is only so much I can contribute.

[albertosottile]

I already fixed it, locally. Now I only need some help from you to understand what the gui code does, before to pack Syncplay in a single .app file (so that it can be distributed on the website). Maybe it would be better if you could give me a way to contact you to further discuss this.

[Et0h]

Closed as the issue should be resolved by https://github.com/Syncplay/syncplay/pull/143 and http://www.albertosottile.it/syncplay/2017/09/08/install-syncplay-on-macos-10-8/