Crash due to PlayerCore.active being called outside the main thread

[svobs]

System and IINA version:

• macOS 13.1
• IINA 1.3.1 branched from develop: (commit: e49b53d5a66c48d24e4e3e1c8e1ca0d64703a615)

Expected behavior:

Continued operation

Actual behavior:

IINA crashes. See crash report.

Crash report:

23:40:39.915 [iina][d] IINA 1.3.1 Build 133
23:40:39.917 [iina][d] Copyright © 2017-2022
23:40:39.917 [iina][d] Collider LI, et al.
23:40:39.917 [iina][d] Released under GPLv3.
23:40:39.917 [iina][d] FFmpeg 4.4.2
23:40:39.917 [iina][d]   libavcodec 58.134.100
23:40:39.917 [iina][d]   libavformat 58.76.100
23:40:39.917 [iina][d]   libavutil 56.70.100
23:40:39.917 [iina][d]   libswscale 5.9.100
23:40:39.919 [iina][d] Built Mar 6, 2023 at 23:40:31 from branch pr-custom-thumbnail-width, commit fa3f4925f676660fe7b016fdaaac4841b6f99ee7
23:40:39.919 [iina][d] App will launch
23:40:39.920 [iina][d] Got arguments ["-NSDocumentRevisionsDebugMode", "YES"]
23:40:39.920 [iina][d] IINA arguments: []
23:40:39.920 [iina][d] Filenames from arguments: []
IINA 1.3.1 Build 133
This binary is not intended for being used as a command line tool. Please use the bundled iina-cli.
Please ignore this message if you are running in a debug environment.
23:40:39.951 [iina][d] App launched
23:40:39.953 [iina][d] Loading key bindings
23:40:39.957 [iina][d] Set key bindings (73 mappings)
2023-03-06 23:40:39.975069-0800 IINA[35347:6376387] [logging] open flag(s) 0x01000000 are reserved for VFS use and do not affect behaviour when passed to sqlite3_open_v2
2023-03-06 23:40:39.975430-0800 IINA[35347:6376387] [logging-persist] cannot open file at line 46922 of [554764a6e7]
2023-03-06 23:40:39.975459-0800 IINA[35347:6376387] [logging-persist] os_unix.c:46922: (0) open(/private/var/db/DetachedSignatures) - Undefined error: 0
23:40:40.073 [player0][d] Set path to /Users/msvoboda/Library/Developer/Xcode/DerivedData/iina-grzduggqfjjfcydnuwtxyrqljxlb/Build/Products/Debug/IINA.app/Contents/MacOS:/Applications/Xcode.app/Contents/Developer/usr/bin:/usr/bin:/bin:/usr/sbin:/sbin
2023-03-06 23:40:40.100383-0800 IINA[35347:6376000] [plugin] AddInstanceForFactory: No factory registered for id <CFUUID 0x600001590840> F8BB1C28-BAE8-11D6-9C31-00039315CD46
23:40:40.124 [iina][d] Using mpv 0.34.1
23:40:40.124 [iina][d] Setting up MediaPlayer integration
23:40:40.124 [player0][d] Track list changed
23:40:40.125 [player0][d] Track list changed
2023-03-06 23:40:40.207530-0800 IINA[35347:6376000] Metal API Validation Enabled
23:40:45.030 [player0][d] Open URL: file:///Users/msvoboda/LocalHome/Downloads/output2.mp4
23:40:45.030 [player0][d] Opening /Users/msvoboda/LocalHome/Downloads/output2.mp4 in main window
23:40:45.075 [player0][v] Syncing UI time
23:40:45.188 [iina][d] Created OpenGL pixel format with [__C._CGLPixelFormatAttribute(rawValue: 5), __C._CGLPixelFormatAttribute(rawValue: 96), __C._CGLPixelFormatAttribute(rawValue: 99), __C._CGLPixelFormatAttribute(rawValue: 12800), __C._CGLPixelFormatAttribute(rawValue: 73), __C._CGLPixelFormatAttribute(rawValue: 101), __C._CGLPixelFormatAttribute(rawValue: 0)]
23:40:45.196 [iina][d] Falling back to nominal display refresh rate: 120.0 from 0.0
23:40:45.204 [iina][d] window!.screen: "Built-in Retina Display" visible frame (62.0, 0.0, 1666.0, 1079.0) EDR: {supports=true maxPotential=16.0 maxCurrent=1.0}
23:40:45.204 [iina][d] NSScreen.main: "Built-in Retina Display" visible frame (62.0, 0.0, 1666.0, 1079.0) EDR: {supports=true maxPotential=16.0 maxCurrent=1.0}
23:40:45.204 [iina][d] NSScreen.screens[0]: "Built-in Retina Display" visible frame (62.0, 0.0, 1666.0, 1079.0) EDR: {supports=true maxPotential=16.0 maxCurrent=1.0}
23:40:45.204 [iina][d] MainWindowLastPosition (526.0, 0.0) matched: "Built-in Retina Display" visible frame (62.0, 0.0, 1666.0, 1079.0) EDR: {supports=true maxPotential=16.0 maxCurrent=1.0}
23:40:45.364 [player0][d] File started
23:40:45.365 [player0][d] Track list changed
23:40:45.380 [player0][d] Started auto load
23:40:45.381 [fmatcher][d] **Start matching
23:40:45.382 [fmatcher][d] Getting all media files...
23:40:45.407 [fmatcher][d] Got all media files, video=7, audio=0
23:40:45.411 [player0][v] Syncing UI time
23:40:45.413 [player0][d] File loaded
23:40:45.413 [player0][d] Track list changed
23:40:45.421 [player0][v] Syncing UI time
23:40:45.426 [fmatcher][d] Getting all sub files...
23:40:45.428 [fmatcher][d] Searching subtitles from 10 directories...
23:40:45.450 [player0][v] Syncing UI time
23:40:45.452 [player0][v] Syncing UI time
23:40:45.462 [player0][v] Syncing UI time
23:40:45.470 [player0][v] Syncing UI time
23:40:45.477 [player0][v] Syncing UI time
23:40:45.484 [player0][v] Syncing UI time
23:40:45.493 [player0][v] Syncing UI time
23:40:45.501 [player0][v] Syncing UI time
23:40:45.509 [player0][v] Syncing UI time
23:40:45.517 [player0][v] Syncing UI time
23:40:45.526 [player0][v] Syncing UI time
23:40:45.534 [player0][v] Syncing UI time
23:40:45.536 [fmatcher][d] Got 0 subtitles
23:40:45.536 [fmatcher][d] Adding files to playlist
23:40:45.536 [fmatcher][d] Grouping video files...
23:40:45.536 [fgroup][d] Start grouping 7 files
23:40:45.537 [fgroup][v] Try group files, prefix=, count=7
23:40:45.537 [fgroup][v] Stop groupping, maxSubGroup=2
23:40:45.537 [fmatcher][d] Finished with 1 groups
23:40:45.537 [fmatcher][d] Grouping sub files...
23:40:45.537 [fgroup][d] Start grouping 0 files
23:40:45.537 [fgroup][v] Try group files, prefix=, count=0
23:40:45.537 [fgroup][v] Contents count < 3, skipped
23:40:45.537 [fmatcher][d] Finished with 1 groups
23:40:45.537 [fmatcher][d] Matching video and sub series...
23:40:45.537 [fmatcher][d] Calculated editing distance
23:40:45.537 [fmatcher][d] Finished matching.
23:40:45.542 [fmatcher][d] No matched sub for this file
23:40:45.542 [fmatcher][d] Force matching unmatched videos, video=7, sub=0...
23:40:45.542 [player0][v] Syncing UI time
23:40:45.542 [fmatcher][d] **Finished matching
23:40:45.550 [player0][v] Syncing UI time
23:40:45.559 [player0][v] Syncing UI time
23:40:45.567 [player0][v] Syncing UI time
23:40:45.577 [player0][v] Syncing UI time
23:40:45.578 [player0][v] Syncing UI playlist
23:40:45.578 [player0][v] Syncing UI time
23:40:45.966 [player0][d] Reloading thumbnails
23:40:45.966 [player0][d] Video's height is longer than its width; adjusting thumbnail width to 444
23:40:45.968 [player0][d] Generating new thumbnails, width=444
23:40:45.968 [player0][d] Playback restarted
=================================================================
Main Thread Checker: UI API called on a background thread: -[NSApplication mainWindow]
PID: 35347, TID: 6376428, Thread name: (none), Queue name: com.colliderli.iina.controller, QoS: 25
Backtrace:
4   IINA                                0x00000001052cee18 $s4IINA10PlayerCoreC6activeACvgZ + 272
5   IINA                                0x00000001052cece4 $s4IINA10PlayerCoreC10lastActiveACvgZ + 132
6   IINA                                0x00000001052f35dc $s4IINA21NowPlayingInfoManagerC06updateD05state9withTitleySo05MPNowC13PlaybackStateVSg_SbtFZ + 520
7   IINA                                0x00000001052f69a4 $s4IINA10PlayerCoreC17playbackRestartedyyF + 804
8   IINA                                0x00000001053447f8 $s4IINA13MPVControllerC11handleEvent33_AA8C985EFDB89116DD68AB87EEE66A73LLyySPySo9mpv_eventVGSgF + 9164
9   IINA                                0x00000001053421e0 $s4IINA13MPVControllerC10readEvents33_AA8C985EFDB89116DD68AB87EEE66A73LLyyFyycfU_ + 520
10  IINA                                0x0000000104f10554 $sIeg_IeyB_TR + 48
11  libdispatch.dylib                   0x0000000106164ecc _dispatch_call_block_and_release + 32
12  libdispatch.dylib                   0x00000001061669d4 _dispatch_client_callout + 20
13  libdispatch.dylib                   0x000000010616fd74 _dispatch_lane_serial_drain + 984
14  libdispatch.dylib                   0x0000000106170dcc _dispatch_lane_invoke + 432
15  libdispatch.dylib                   0x0000000106180990 _dispatch_workloop_worker_thread + 1064
16  libsystem_pthread.dylib             0x0000000105ecbd28 _pthread_wqthread + 288
17  libsystem_pthread.dylib             0x0000000105ed3a7c start_wqthread + 8
2023-03-06 23:40:45.976977-0800 IINA[35347:6376428] [reports] Main Thread Checker: UI API called on a background thread: -[NSApplication mainWindow]
PID: 35347, TID: 6376428, Thread name: (none), Queue name: com.colliderli.iina.controller, QoS: 25
Backtrace:
4   IINA                                0x00000001052cee18 $s4IINA10PlayerCoreC6activeACvgZ + 272
5   IINA                                0x00000001052cece4 $s4IINA10PlayerCoreC10lastActiveACvgZ + 132
6   IINA                                0x00000001052f35dc $s4IINA21NowPlayingInfoManagerC06updateD05state9withTitleySo05MPNowC13PlaybackStateVSg_SbtFZ + 520
7   IINA                                0x00000001052f69a4 $s4IINA10PlayerCoreC17playbackRestartedyyF + 804
8   IINA                                0x00000001053447f8 $s4IINA13MPVControllerC11handleEvent33_AA8C985EFDB89116DD68AB87EEE66A73LLyySPySo9mpv_eventVGSgF + 9164
9   IINA                                0x00000001053421e0 $s4IINA13MPVControllerC10readEvents33_AA8C985EFDB89116DD68AB87EEE66A73LLyyFyycfU_ + 520
10  IINA                                0x0000000104f10554 $sIeg_IeyB_TR + 48
11  libdispatch.dylib                   0x0000000106164ecc _dispatch_call_block_and_release + 32
12  libdispatch.dylib                   0x00000001061669d4 _dispatch_client_callout + 20
13  libdispatch.dylib                   0x000000010616fd74 _dispatch_lane_serial_drain + 984
14  libdispatch.dylib                   0x0000000106170dcc _dispatch_lane_invoke + 432
15  libdispatch.dylib                   0x0000000106180990 _dispatch_workloop_worker_thread + 1064
16  libsystem_pthread.dylib             0x0000000105ecbd28 _pthread_wqthread + 288
17  libsystem_pthread.dylib             0x0000000105ed3a7c start_wqthread + 8
23:40:51.441 [player0][v] Syncing UI time

Steps to reproduce:

I was testing thumbnail generation/display, but in this case I had launched the pr-custom-thumbnail-width branch from Xcode, then dragged & dropped a 9:16 video I had generated onto the Welcome Window, and as soon as it opened I tried to hover over the play slider in an attempt to display a thumbnail. (Probably unrelated, but it was stuttering at the start of the video, and I didn't wait for it to calm down. I've noticed that it does that for me occasionally. Probably should track that down at some point).

How often does this happen?

It's the only time it ever happened, but I think I see the problem because I've stumbled onto in before.

The static properties in PlayerCore (PlayerCore.lastActive, PlayerCore.active, etc) are a bit dangerous because it's not obvious that they can access UI code and thus trigger this exception (especially since it doesn't seem to always get triggered). It's probably related to another nasty trap in the code which I've noticed: just by accessing the NSWindow object for MainWindowController, you run the risk of actually opening the window. I haven't dug in to how exactly this happens, but it can result in a black window being opened named "Window". I'm just speculating that this is the UI code which tried to run, but I think it's clear that these static PlayerCore methods should be shored up so that they aren't accessed outside the main thread.

[low-batt]

Want me to take this one?

It is on my list to refactor code in MPVController to drastically reduce the amount of work performed using the controller queue's thread and instead queue most work to the main thread.

A lot of the work being done is small. I don't see a reason to be doing this work on the background thread other than a little bit of overhead to queue it to the main thread. Performing work on this background thread is causing data races accessing the information stored in PlaybackInfo. If that can be normalized to only be accessed by the main thread then we can avoid the need to add locks.

Quite a few places in MPVController already have to queue work to the main thread due to use of AppKit UI methods, such as displaying an OSD message.

I've fixed some problems in NowPlayingInfoManager. I'm vaguely remembering something about this problem. Can't say yet if this is a regression or not.

[svobs]

Want me to take this one?

@low-batt yes that would be great! The MPVController itself isn't in my preferred realm of focus at the moment.

A lot of the work being done is small. I don't see a reason to be doing this work on the background thread other than a little bit of overhead to queue it to the main thread. Performing work on this background thread is causing data races accessing the information stored in PlaybackInfo. If that can be normalized to only be accessed by the main thread then we can avoid the need to add locks.

This makes a lot of sense. It might be a nice clean line of separation if the mpv objects were parsed into IINA objects before being sent to some handler on the main thread. It might be great to move a lot of that logic out of MPVController and into more specialized classes, and let MPVController focus on its job of communicating with mpv.

One more thought on the subject of PlayerCore.lastActive: it would be good to start thinking about ways to decouple PlayerCore from MainWindowController. There is a lot of stuff in PlayerCore relating to media metadata, especially thumbnails and playlists, which should do the majority of their processing on background threads, but requiring everything to go through the main thread so often is a recipe for pileup (and might be one reason for these freak sporadic hiccups in playback some users are reporting.)

[low-batt]

I've added this crash to my list. Will get to it soon.

Not certain which playback hiccups you are referring to. If it is a IINA 1.3.1 regression it is likely to due to the regression the fix in PR #4055 addresses. The attempt in 1.3.1 to fix a different data race without using locking did not work. Not sure of all the ways that might manifest because with my Macs things worked, except for the issue with switching from music to video. The usual problem with fixes to threading. An incorrect fix may just happen to work in the developer's environment.

I'm used to independent classes and dependency injection. There is an awful lot of tight coupling and exposed internals in the current code. However, I'm not in favor of trying to refactor code to address that at the moment, due to priorities and not wanting to trigger merge conflicts with the many outstanding PRs. I want to first get to a point where IINA passes the checks that can be run with developer tools. I tracked down and fixed a bunch of memory leaks already. I've not checked lately to see where we are at with regards to leaks. I am working on fixing data races identified by TSan. I'm very glad you are tracking down and fixing the UI constraint issues.

[svobs]

Not certain which playback hiccups you are referring to. If it is a IINA 1.3.1 regression it is likely to due to the regression the fix in PR #4055 addresses.

I took a look at that but it is completely outside my expertise 🤧 Regarding playback hiccups, I don't keep a spreadsheet anymore but I took a look at the last few pages of seemingly related defects.... Issue #4153 sounds like a hardware driver is to blame(?). Issues #4154 and #4176 are likely due to confusion caused by seek keyframes. Very concerning are #4212 and #4159, and can't rule out lock contention on IINA's part. Although the "hiccups" I was referring to above were something I've seen occasionally when opening a video. The video seems to stop and start 10-15 times over the course of ~2 seconds before clearing. It seems like it's only been a problem for vertical HDR videos, but I need to do more work to isolate it...

When I see code that looks structurally unsafe, rather than painfully troubleshooting the existing code and all its corner cases (and in doing so, becoming more mentally invested in the existing code), I'd rather just refactor it right away, and eliminate the hazards via improved design, and then see if the bugs are still present. I admit this decision has never been met with enthusiasm when I presented it 😎 and for obvious reasons; there is definite risk in any new solution.

Sorry - started to go a bit of a tangent there. There isn't a pressing need to refactor MPVController, I will concede. But I've been trying to make some progress on (1) restoring window state across launches & (2) improving video geometry handling, but it looks like both are made a lot more difficult by the haphazard way in which windows are opened, so I'm planning to make a case for that. So many things to fix! Yeah I agree that memory leaks are a concern, but stability & correctness need to come first.

[low-batt]

I'm actually working on issue #4153 right now. There are a number of things that effect seeking performance, but the regression is likely due to my change that tried to avoid wasting CPU while paused. Turns out the display link needs to be running when seeking or mpv is unhappy.

I'm not sure what #4154 and #4176 are reporting, so I've not looked into those.

Issue #4212 has a fix pending. A regression caused by trying to not waste CPU when the OSC is hidden. If the Mac has a Touch Bar then the OSD is always visible.

I just responded to issue #4159. That is likely an upstream issue.

Not liking the sounds of this:

The video seems to stop and start 10-15 times over the course of ~2 seconds before clearing

I'm a bit worried that is due to the display link thread being shutdown. Keep an eye out for that one.

We need to get these outstanding PRs merged and then do a lot of testing of the develop branch.

On the refactoring question. At work I too have been the one pushing for refactoring and getting frowny faces. There is good reason for that. Hidden in the messy code is usually odd code that fixes a problem. It is easy to loose such fixes during a refactoring. And if threading is not correct even a proper refactoring may just happen to change the timing and introduce a problem.

At the moment I think IINA first needs to get out a release that addresses the regressions, before doing much refactoring.

[low-batt]

The problem was very reproducible for me by dragging and dropping a video file to the welcome window when running under Xcode.

[low-batt]

The fix for this issue has been merged into the IINA develop branch. Once the fix has been included in an official release this issue will be closed.

Should you wish to confirm the fix is working and do not have the ability to build IINA from the sources in the develop branch, at some point a new unsigned nightly build will be available for download. If you encounter a regression in a nightly build that has not been reported please enter an issue for it and be sure to indicate the problem was found in a nightly build.

[low-batt]

IINA 1.3.2 contains the fix for this issue.