Crash due to PlayerCore.active being called outside the main thread #4251
Description
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.