Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Log window #4109

Merged
merged 21 commits into from Apr 4, 2023
Merged

Log window #4109

merged 21 commits into from Apr 4, 2023

Conversation

uiryuu
Copy link
Member

@uiryuu uiryuu commented Dec 1, 2022


Description:
Add a new Log window to view logs easily. Users can easily open log window by CMD+Shift+L

Screenshot:
image

@uiryuu
Copy link
Member Author

uiryuu commented Dec 1, 2022

Update: fixed. See https://stackoverflow.com/questions/17022751/nsimage-has-opacity-when-used-with-nsvaluetransformer


Issue to be investigated:
telegram-cloud-photo-size-5-6075727747457593837-y
The indicator image is transparent in the TableView, the same image is opaque in the MenuItem.

@uiryuu uiryuu requested a review from lhc70000 December 1, 2022 23:39
iina/Base.lproj/PlaylistViewController.xib Outdated Show resolved Hide resolved
iina/Extensions.swift Outdated Show resolved Hide resolved
iina/InitialWindowController.swift Outdated Show resolved Hide resolved
iina/LogWindowController.swift Outdated Show resolved Hide resolved
iina/LogWindowController.swift Outdated Show resolved Hide resolved
iina/LogWindowController.swift Outdated Show resolved Hide resolved
iina/LogWindowController.swift Outdated Show resolved Hide resolved
iina/Logger.swift Show resolved Hide resolved
iina/PrefAdvancedViewController.swift Outdated Show resolved Hide resolved
@saagarjha
Copy link
Member

Haven't looked at the code yet but is this something that we need a keyboard shortcut for? I don't expect it to be activated all that often…

@svobs
Copy link
Contributor

svobs commented Dec 3, 2022 via email

Copy link
Contributor

@low-batt low-batt left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I pulled this PR locally, built and tested.

I suggest holding up merging this PR until the major fixes to the preferences panel in PR 4107 are merged. Have a look at that PR. Note the questions from @svobs here. See if you agree with my answers.

The log window is not updating for me. New logs are not shown. I tried closing the window and then showing it again and it still did not display the latest logs. Saving the log only saved the what was being displayed.

I would make the log level only filter the log messages being displayed. Saving the log messages to a file should save all messages. We already have issues with users not supplying enough information. Do we want users to send us logs that only contain error level messages with zero context?

Not always, but in a number of issues the mpv log is more helpful than the IINA log. Unfortunate that log is not covered.

As this screenshot shows there are two names for the new window, Log Window and Log Viewer:
pr-4109

I'd prefer Log Viewer.

iina/LogWindowController.swift Outdated Show resolved Hide resolved
iina/LogWindowController.swift Outdated Show resolved Hide resolved
@low-batt
Copy link
Contributor

low-batt commented Dec 5, 2022

Found a regression. With this PR the keyboard shortcut under the Playback menu for the A-B Loop item is missing if the key bindings are set to VLC Default as VLC uses ⇧⌘L, which is now assigned to the Log Window menu item.

@uiryuu
Copy link
Member Author

uiryuu commented Dec 6, 2022

The log window is not updating for me. New logs are not shown. I tried closing the window and then showing it again and it still did not display the latest logs.

@low-batt Can you explain what's your current log level setting and how you reproduce this?

@uiryuu
Copy link
Member Author

uiryuu commented Dec 6, 2022

@saagarjha @low-batt @svobs For the shortcut, you can assume that ⇧⌘L is just a placeholder. We can discuss whether we are going to have a shortcut for that and what shortcut to be used.

I would make the log level only filter the log messages being displayed. Saving the log messages to a file should save all messages. We already have issues with users not supplying enough information. Do we want users to send us logs that only contain error level messages with zero context?

I definitely want all users to provide the full verbose logs when they submit an issue, however that means we are forcing all the users to have verbose logs, which wastes their electricity and storage. (Currently verbose logs contains a lot of spam of syncUI stuff.) This is the reason we must give the user the ability to change the log level.

I agree that saving logs should save all the logs available, but please notice that this also obey the log level setting: if the user selects debug level, then the verbose logs are not available (but all debug level logs should be saved). The reason why I did this is because I thought that for some advanced users, they can filter the logs by subsystem and log level and only send relevant logs to us. But now I think about that, even if they want to do that, they can also copy from the filtered logs.

@uiryuu
Copy link
Member Author

uiryuu commented Dec 8, 2022

Not always, but in a number of issues the mpv log is more helpful than the IINA log. Unfortunate that log is not covered.

@low-batt The log window is able to catch up mpv logs, however, due to our mpv log level is too high ("warn"), there's hardly any log from mpv. I've lowered the mpv log level to "debug", so hopefully you can see the mpv log in the log viewer now.

@low-batt
Copy link
Contributor

low-batt commented Dec 8, 2022

Sorry I'm slow to respond. Lots going on.

I just pulled the latest commit and rebuilt. I started IINA using Xcode. The welcome window came up. I ignored it. I selected Window/Log Viewer. The Log Viewer window came up and showed the log level as Debug. Checking preferences and it is also set to Debug.

The window filled with log messages. I don't see a level? Is that what the green circle is?

I see lots of mpv log messages now. I guess we changed things so mpv debug message are now in the IINA log? That was not what I expected when I commented about the lack of support for mpv. I was expecting the separate mpv log to be preserved. Maybe just because I am used to it being separate.

I then went to the welcome window and started playing a video. The log window does not change. The last message shown is:

21:22:23.354 [mpv][d] [cplayer] debug: Run command: enable-section, flags=64, args=[name="input_forced_stats", flags="allow-hide-cursor+allow-vo-dragging"]

The last log message shown in the Xcode console right now has a timestamp of 21:37:57.670. The log window has not changed and still shows the above message as the last message. What is really surprising is that if I close the Log Viewer and then reopen it I still don't see the new log messages.

The Xcode console output seems to be missing some newlines as all this shows as one message:

21:37:57.670 [mpv][d] [cplayer] debug: Run command: seek, flags=64, args=[target="27.699838", flags="absolute-percent+exact", legacy="unused"]21:37:57.723 [mpv][d] [ffmpeg/video] debug: h264: Reinit context to 688x448, pix_fmt: videotoolbox_vld21:37:57.723 [mpv][d] [cplayer] debug: Run command: seek, flags=64, args=[target="27.629573", flags="absolute-percent+exact", legacy="unused"]21:37:57.729 [mpv][d] [cplayer] debug: Run command: seek, flags=64, args=[target="27.559308", flags="absolute-percent+exact", legacy="unused"]21:37:57.734 [mpv][d] [cplayer] debug: Run command: seek, flags=64, args=[target="22.400200", flags="absolute-percent+exact", legacy="unused"]21:37:57.742 [mpv][d] [cplayer] debug: Run command: seek, flags=64, args=[target="19.326410", flags="absolute-percent+exact", legacy="unused"]21:37:57.752 [mpv][d] [cplayer] debug: Run command: seek, flags=64, args=[target="18.371284", flags="absolute-percent+exact", legacy="unused"]21:37:57.766 [mpv][d] [cplayer] debug: Run command: seek, flags=64, args=[target="18.230755", flags="absolute-percent+exact", legacy="unused"]21:37:57.775 [mpv][d] [cplayer] debug: Run command: seek, flags=64, args=[target="18.160490", flags="absolute-percent+exact", legacy="unused"]21:37:58.094 [mpv][d] [cplayer] debug: Run command: seek, flags=64, args=[target="18.160490", flags="absolute-percent+exact", legacy="unused"]21:37:58.094 [mpv][d] [ffmpeg/video] debug: h264: Reinit context to 688x448, pix_fmt: videotoolbox_vld21:37:58.100 [mpv][d] [cplayer] debug: starting video playback21:37:58.112 [mpv][d] [ffmpeg/video] debug: h264: Reinit context to 688x448, pix_fmt: videotoolbox_vld21:37:58.134 [mpv][d] [cplayer] debug: starting video playback21:37:58.140 [player0][d] Playback restarted

On the allowing changing of the log level, I wasn't thinking about Debug vs. Verbose. Fine to let users toggle between those. And yes, Verbose logs too much be used as a default. What I was worried about is users to turning in a log file that only has warnings and errors. Even restricting the log messages to subsystem is a problem. The log message subsystems are not coded with that in mind. Many times I have had users provide a just a short clip from log files that cuts off the critical information that is needed.

@lhc70000
Copy link
Member

lhc70000 commented Dec 8, 2022

Not always, but in a number of issues the mpv log is more helpful than the IINA log. Unfortunate that log is not covered.

@low-batt The log window is able to catch up mpv logs, however, due to our mpv log level is too high ("warn"), there's hardly any log from mpv. I've lowered the mpv log level to "debug", so hopefully you can see the mpv log in the log viewer now.

Do we need to use the debug level by default? I hope it's adjustable. Perhaps you can delete the line that sets the mpv log level so that it will be consistent with user's settings.

@svobs
Copy link
Contributor

svobs commented Dec 8, 2022

Just throwing my 2¢ into the bucket. I've been relying on the libmpv log stream to support Lua script keybindings, and can vouch that it has been totally reliable at "debug" level. It would be great if it could be totally included inside the IINA log.

But also, to give more context, the log event stream (for lack of a better description) is a totally separate mechanism than the current mpv.log file, which mpv itself is responsible for creating and appending to. Both mechanisms can be configured independently, including log level. Here's a summary of the levels using mpv's descriptions:

  case no = 0  // - disable absolutely all messages
  case fatal   // - critical/aborting errors
  case error   // - simple errors
  case warn    // - possible problems
  case info    // - informational message
  case verbose // - noisy informational message
  case debug   // - very noisy technical information
  case trace   // - extremely noisy

Despite its description, I found that their debug level is not very noisy - not even as much as IINA's debug level. I haven't noticed any performance penalty for leaving it at that level. However the jump to trace is huge, and the mpv team has suggested that it may even cause deadlocks or stability issues and probably should be avoided.

@low-batt
Copy link
Contributor

Issue #3560 is a hang in the mpv logger. It is some sort of thread race condition. Hard to reproduce. I am able to reproduce a hang if I add the mpv option msg-level with the value all=trace in Advanced preferences. I desk checked the mpv logger source code for lock problems but could not spot a problem.

@svobs
Copy link
Contributor

svobs commented Dec 23, 2022

I pulled this and tried it out, and traced through the code a bit. It looks pretty nice! I hadn't realized it would be a fully formatted NSTableView. But I also saw that it doesn't update after the log window is opened.

Looks like you are using Cocoa Bindings (NSArrayController) to handle the table data. I think you will want to use NSTableViewDataSource instead. It's a little bit more of a hassle to set up, but you will probably need the extra control it provides, and it will be somewhat easier because logs data is append-only.

I also worry about the performance of NSTableView when the log starts getting long. Can it even hold 10,000 rows? Can it hold 100,000 rows? I can't find specific data although it seems like there are lots of developers disappointed in it. Is Cocoa Bindings smart enough to figure out that you only want to add 1 row for each Logger.log(), or is it going to reload the whole table each time?

@uiryuu
Copy link
Member Author

uiryuu commented Mar 22, 2023

@svobs

Looks like you are using Cocoa Bindings (NSArrayController) to handle the table data. I think you will want to use NSTableViewDataSource instead.

The reason why I chose NSArrayController over NSTableViewDataSource is because I found the filterPredicate provided by NSArrayController is very handy in our use case.

Is Cocoa Bindings smart enough to figure out that you only want to add 1 row for each Logger.log(), or is it going to reload the whole table each time?

Although I might be wrong, but I'm pretty sure that NSArrayController won't reload the whole table every time the data changes.

Anyway, I'd prefer cleaner code, but if we observe performance issue, we can optimize it later.

- Rename Log Window to Log Viewer
- Save logs now saves all available logs instead of filtered logs
Add a map from mpv's log level to iina's log level
@uiryuu

This comment was marked as outdated.

Copy link
Contributor

@low-batt low-batt left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Would be nice if the list of subsystems was in alphabetical order. The list of subsystems sometimes contains duplicate names as can be seen here with hdr listed twice:

pr4109-dups

I'm still having the same problem of the log window not updating once it is displayed. Even if I dismiss the log window and then bring it back up again it still does not show the latest log messages. However the list of subsystems is getting updated. After the log window was open I opened another file which created a second player. As can be seen here I was able to filter the list selecting player1 and yet no messages were displayed:

pr4109-blank

When I start IINA now without logging enabled I see lots of messages from mpv to the Xcode console. Initially that confused me because I saw messages that looked like something was wrong. That is just because I was not used to seeing debug messages from mpv which is due to the change in MPVController that changes the default mpv log level from warn to debug. There are two reasons why I don't think we want to do that by default. A lot of logging systems I've seen are not efficient in avoiding work when the log level is high, but there is no log file. Messages are fully prepared and then thrown away in some logging systems I've seen. Have we checked to see if raising the mpv level when no log file has been specified incurs additional overhead?

The other concern is issue #3560. IINA hung during startup. Inside mpv code blocked on the mpv logger's lock. This seemed to be introduced when IINA upgraded to mpv 0.34.0. I confirmed mpv had made changes to their logger related to locks. I desk checked the mpv logger code and was unable to spot a path where the code might fail to unlock a lock. I tried hard to reproduce the hang with the mpv player and never did get mpv to hang. Although still difficult to reproduce I was able to reproduce the problem by setting msg-level to all=trace in Advanced settings.

Testing that to make sure we can still set the mpv log level that way with these changes IINA hung upon startup. Not in the same place as with issue #3560, but same issue of not being able to obtain a mpv logger lock. I captured the process sample below. I tried again and IINA started up fine. I will test mpv 0.35.1 when I get a chance. Anyway, my takeaway is that we need to be cautious about raising the mpv log level.

Process sample:
Analysis of sampling IINA (pid 47054) every 1 millisecond
Process:         IINA [47054]
Path:            /Users/USER/Library/Developer/Xcode/DerivedData/iina-caydzgleiqupoxbtitkkfadxksfs/Build/Products/Debug/IINA.app/Contents/MacOS/IINA
Load Address:    0x100b98000
Identifier:      com.colliderli.iina
Version:         1.3.1 (133)
Code Type:       ARM64
Platform:        macOS
Parent Process:  debugserver [47055]

Date/Time:       2023-04-02 14:46:34.084 -0400
Launch Time:     2023-04-02 14:46:04.063 -0400
OS Version:      macOS 13.3 (22E252)
Report Version:  7
Analysis Tool:   /usr/bin/sample

Physical footprint:         76.2M
Physical footprint (peak):  77.1M
Idle exit:                  untracked
----

Call graph:
    2371 Thread_1199483   DispatchQueue_1: com.apple.main-thread  (serial)
    + 2371 start  (in dyld) + 2236  [0x184933f28]
    +   2371 main  (in IINA) + 12  [0x100dbcd20]  AppDelegate.swift:24
    +     2371 NSApplicationMain  (in AppKit) + 880  [0x187f529a8]
    +       2371 -[NSApplication run]  (in AppKit) + 500  [0x187f7b57c]
    +         2371 -[NSApplication _handleEvent:]  (in AppKit) + 60  [0x1883040f0]
    +           2371 -[NSApplication(NSEvent) sendEvent:]  (in AppKit) + 424  [0x1880b3c74]
    +             2371 +[_NSTrackingAreaManager routeEnterExitEvent:]  (in AppKit) + 236  [0x1885128b8]
    +               2371 +[_NSTrackingAreaAKManager routeEnterExitEvent:]  (in AppKit) + 92  [0x188533150]
    +                 2371 -[NSWindow(NSEventRouting) sendEvent:]  (in AppKit) + 284  [0x1880b4d9c]
    +                   2371 -[NSWindow(NSEventRouting) _reallySendEvent:isDelayedEvent:]  (in AppKit) + 152  [0x1880b5008]
    +                     2371 -[_NSTrackingAreaAKManager routeEnterExitEvent:]  (in AppKit) + 196  [0x1885379e4]
    +                       2371 -[_NSTrackingAreaAKManager _updateActiveTrackingAreasForWindowLocation:modifierFlags:]  (in AppKit) + 3968  [0x188537740]
    +                         2371 -[NSTrackingArea _dispatchMouseEntered:]  (in AppKit) + 124  [0x1881255f8]
    +                           2371 @objc MainWindowController.mouseEntered(with:)  (in IINA) + 52  [0x100d05330]  <compiler-generated>:0
    +                             2371 MainWindowController.mouseEntered(with:)  (in IINA) + 840  [0x100d04cd0]  MainWindowController.swift:942
    +                               2371 MainWindowController.showUI()  (in IINA) + 428  [0x100d14f00]  MainWindowController.swift:1694
    +                                 2371 PlayerCore.syncUITime()  (in IINA) + 216  [0x100fba0e0]  PlayerCore.swift:1610
    +                                   2371 PlayerCore.syncUI(_:)  (in IINA) + 1944  [0x100fbace4]  PlayerCore.swift:1635
    +                                     2371 MPVController.getFlag(_:)  (in IINA) + 540  [0x100ffc430]  MPVController.swift:591
    +                                       2371 mpv_get_property  (in libmpv.1.dylib) + 92  [0x102699464]
    +                                         2371 mp_dispatch_lock  (in libmpv.1.dylib) + 216  [0x102681c90]
    +                                           2371 _pthread_cond_wait  (in libsystem_pthread.dylib) + 1232  [0x101b61b6c]
    +                                             2371 __psynch_cvwait  (in libsystem_kernel.dylib) + 8  [0x184c4f710]
    2371 Thread_1199535   DispatchQueue_238: IINAPlayerCoreTask  (serial)
    + 2371 start_wqthread  (in libsystem_pthread.dylib) + 8  [0x101b67a6c]
    +   2371 _pthread_wqthread  (in libsystem_pthread.dylib) + 288  [0x101b5fcc8]
    +     2371 _dispatch_workloop_worker_thread  (in libdispatch.dylib) + 1060  [0x101f50954]
    +       2371 _dispatch_lane_invoke  (in libdispatch.dylib) + 424  [0x101f40d8c]
    +         2371 _dispatch_lane_serial_drain  (in libdispatch.dylib) + 980  [0x101f3fd20]
    +           2371 _dispatch_client_callout  (in libdispatch.dylib) + 20  [0x101f3699c]
    +             2371 _dispatch_call_block_and_release  (in libdispatch.dylib) + 32  [0x101f34e30]
    +               2371 thunk for @escaping @callee_guaranteed () -> ()  (in IINA) + 48  [0x100bc39f4]  <compiler-generated>:0
    +                 2371 closure #3 in PlayerCore.fileStarted(path:)  (in IINA) + 496  [0x100fb4670]  PlayerCore.swift:1386
    +                   2371 PlayerCore.autoLoadFilesInCurrentFolder(ticket:)  (in IINA) + 92  [0x100fb8cd0]  PlayerCore.swift:1546
    +                     2371 AutoFileMatcher.startMatching()  (in IINA) + 2020  [0x100cb0ac4]  AutoFileMatcher.swift:339
    +                       2371 AutoFileMatcher.addFilesToPlaylist()  (in IINA) + 3788  [0x100ca9350]  AutoFileMatcher.swift:128
    +                         2371 PlayerCore.addToPlaylist(_:silent:)  (in IINA) + 76  [0x100fa9ffc]  PlayerCore.swift:951
    +                           2371 PlayerCore._addToPlaylist(_:)  (in IINA) + 472  [0x100fa9f88]  PlayerCore.swift:947
    +                             2371 MPVController.command(_:args:checkError:returnValueCallback:)  (in IINA) + 1032  [0x100ff8c2c]  MPVController.swift:510
    +                               2371 run_client_command  (in libmpv.1.dylib) + 276  [0x102698d0c]
    +                                 2371 run_command  (in libmpv.1.dylib) + 448  [0x10269bc50]
    +                                   2371 mp_cmd_dump  (in libmpv.1.dylib) + 88  [0x1026798e8]
    +                                     2371 mp_msg  (in libmpv.1.dylib) + 28  [0x10264ac0c]
    +                                       2371 mp_msg_va  (in libmpv.1.dylib) + 152  [0x102649b9c]
    +                                         2371 _pthread_mutex_firstfit_lock_slow  (in libsystem_pthread.dylib) + 248  [0x101b63c98]
    +                                           2371 _pthread_mutex_firstfit_lock_wait  (in libsystem_pthread.dylib) + 96  [0x101b63d6c]
    +                                             2371 __psynch_mutexwait  (in libsystem_kernel.dylib) + 8  [0x184c4ebc8]
    2371 Thread_1199545: mpv/mpv core
    + 2371 thread_start  (in libsystem_pthread.dylib) + 8  [0x101b67a78]
    +   2371 _pthread_start  (in libsystem_pthread.dylib) + 148  [0x101b5d55c]
    +     2371 core_thread  (in libmpv.1.dylib) + 72  [0x102697f1c]
    +       2371 mp_play_files  (in libmpv.1.dylib) + 3332  [0x1026b0f6c]
    +         2371 open_demux_reentrant  (in libmpv.1.dylib) + 280  [0x1026b23bc]
    +           2371 mp_idle  (in libmpv.1.dylib) + 108  [0x1026bb7b8]
    +             2371 mp_wait_events  (in libmpv.1.dylib) + 80  [0x1026b8ca8]
    +               2371 mp_dispatch_queue_process  (in libmpv.1.dylib) + 296  [0x102681ad0]
    +                 2371 _pthread_cond_wait  (in libsystem_pthread.dylib) + 1232  [0x101b61b6c]
    +                   2371 __psynch_cvwait  (in libsystem_kernel.dylib) + 8  [0x184c4f710]
    2371 Thread_1199546: mpv/log-file
    + 2371 thread_start  (in libsystem_pthread.dylib) + 8  [0x101b67a78]
    +   2371 _pthread_start  (in libsystem_pthread.dylib) + 148  [0x101b5d55c]
    +     2371 log_file_thread  (in libmpv.1.dylib) + 120  [0x10264ab38]
    +       2371 _pthread_cond_wait  (in libsystem_pthread.dylib) + 1232  [0x101b61b6c]
    +         2371 __psynch_cvwait  (in libsystem_kernel.dylib) + 8  [0x184c4f710]
    2371 Thread_1199547: mpv/lua script (ytdl_hook)
    + 2371 thread_start  (in libsystem_pthread.dylib) + 8  [0x101b67a78]
    +   2371 _pthread_start  (in libsystem_pthread.dylib) + 148  [0x101b5d55c]
    +     2371 script_thread  (in libmpv.1.dylib) + 32  [0x1026bd728]
    +       2371 run_script  (in libmpv.1.dylib) + 100  [0x1026bd6a4]
    +         2371 lua_cpcall  (in libluajit-5.1.2.dylib) + 28  [0x1029a74d0]
    +           2371 lj_BC_FUNCC  (in libluajit-5.1.2.dylib) + 44  [0x10299a838]
    +             2371 lua_pcall  (in libluajit-5.1.2.dylib) + 148  [0x1029a7490]
    +               2371 lj_BC_FUNCC  (in libluajit-5.1.2.dylib) + 44  [0x10299a838]
    +                 2371 load_scripts  (in libmpv.1.dylib) + 376  [0x1026b3444]
    +                   2371 lj_BC_FUNCC  (in libluajit-5.1.2.dylib) + 44  [0x10299a838]
    +                     2371 lua_pcall  (in libluajit-5.1.2.dylib) + 148  [0x1029a7490]
    +                       2371 lj_BC_FUNCC  (in libluajit-5.1.2.dylib) + 44  [0x10299a838]
    +                         2371 script_raw_wait_event  (in libmpv.1.dylib) + 120  [0x1026b3970]
    +                           2371 mpv_wait_event  (in libmpv.1.dylib) + 420  [0x10269811c]
    +                             2371 wait_wakeup  (in libmpv.1.dylib) + 88  [0x1026977b4]
    +                               2371 _pthread_cond_wait  (in libsystem_pthread.dylib) + 1232  [0x101b61b6c]
    +                                 2371 __psynch_cvwait  (in libsystem_kernel.dylib) + 8  [0x184c4f710]
    2371 Thread_1199548: mpv/lua script (stats)
    + 2371 thread_start  (in libsystem_pthread.dylib) + 8  [0x101b67a78]
    +   2371 _pthread_start  (in libsystem_pthread.dylib) + 148  [0x101b5d55c]
    +     2371 script_thread  (in libmpv.1.dylib) + 32  [0x1026bd728]
    +       2371 run_script  (in libmpv.1.dylib) + 100  [0x1026bd6a4]
    +         2371 lua_cpcall  (in libluajit-5.1.2.dylib) + 28  [0x1029a74d0]
    +           2371 lj_BC_FUNCC  (in libluajit-5.1.2.dylib) + 44  [0x10299a838]
    +             2371 lua_pcall  (in libluajit-5.1.2.dylib) + 148  [0x1029a7490]
    +               2371 lj_BC_FUNCC  (in libluajit-5.1.2.dylib) + 44  [0x10299a838]
    +                 2371 load_scripts  (in libmpv.1.dylib) + 376  [0x1026b3444]
    +                   2371 lj_BC_FUNCC  (in libluajit-5.1.2.dylib) + 44  [0x10299a838]
    +                     2371 lua_pcall  (in libluajit-5.1.2.dylib) + 148  [0x1029a7490]
    +                       2371 lj_BC_FUNCC  (in libluajit-5.1.2.dylib) + 44  [0x10299a838]
    +                         2371 script_raw_wait_event  (in libmpv.1.dylib) + 120  [0x1026b3970]
    +                           2371 mpv_wait_event  (in libmpv.1.dylib) + 420  [0x10269811c]
    +                             2371 wait_wakeup  (in libmpv.1.dylib) + 88  [0x1026977b4]
    +                               2371 _pthread_cond_wait  (in libsystem_pthread.dylib) + 1232  [0x101b61b6c]
    +                                 2371 __psynch_cvwait  (in libsystem_kernel.dylib) + 8  [0x184c4f710]
    2371 Thread_1199549: mpv/lua script (console)
    + 2371 thread_start  (in libsystem_pthread.dylib) + 8  [0x101b67a78]
    +   2371 _pthread_start  (in libsystem_pthread.dylib) + 148  [0x101b5d55c]
    +     2371 script_thread  (in libmpv.1.dylib) + 32  [0x1026bd728]
    +       2371 run_script  (in libmpv.1.dylib) + 100  [0x1026bd6a4]
    +         2371 lua_cpcall  (in libluajit-5.1.2.dylib) + 28  [0x1029a74d0]
    +           2371 lj_BC_FUNCC  (in libluajit-5.1.2.dylib) + 44  [0x10299a838]
    +             2371 lua_pcall  (in libluajit-5.1.2.dylib) + 148  [0x1029a7490]
    +               2371 lj_BC_FUNCC  (in libluajit-5.1.2.dylib) + 44  [0x10299a838]
    +                 2371 load_scripts  (in libmpv.1.dylib) + 376  [0x1026b3444]
    +                   2371 lj_BC_FUNCC  (in libluajit-5.1.2.dylib) + 44  [0x10299a838]
    +                     2371 lua_pcall  (in libluajit-5.1.2.dylib) + 148  [0x1029a7490]
    +                       2371 lj_BC_FUNCC  (in libluajit-5.1.2.dylib) + 44  [0x10299a838]
    +                         2371 script_raw_wait_event  (in libmpv.1.dylib) + 120  [0x1026b3970]
    +                           2371 mpv_wait_event  (in libmpv.1.dylib) + 420  [0x10269811c]
    +                             2371 wait_wakeup  (in libmpv.1.dylib) + 88  [0x1026977b4]
    +                               2371 _pthread_cond_wait  (in libsystem_pthread.dylib) + 1232  [0x101b61b6c]
    +                                 2371 __psynch_cvwait  (in libsystem_kernel.dylib) + 8  [0x184c4f710]
    2371 Thread_1199551: mpv/ipc socket listener
    + 2371 thread_start  (in libsystem_pthread.dylib) + 8  [0x101b67a78]
    +   2371 _pthread_start  (in libsystem_pthread.dylib) + 148  [0x101b5d55c]
    +     2371 ipc_thread  (in libmpv.1.dylib) + 368  [0x10267ef48]
    +       2371 poll  (in libsystem_kernel.dylib) + 8  [0x184c54834]
    2371 Thread_1199552: caulk.messenger.shared:17
    + 2371 thread_start  (in libsystem_pthread.dylib) + 8  [0x101b67a78]
    +   2371 _pthread_start  (in libsystem_pthread.dylib) + 148  [0x101b5d55c]
    +     2371 caulk::thread_proxy<std::tuple<caulk::thread::attributes, void (caulk::concurrent::details::worker_thread::*)(), std::tuple<caulk::concurrent::details::worker_thread*>>>(void*)  (in caulk) + 96  [0x18e2a9bc8]
    +       2371 caulk::concurrent::details::worker_thread::run()  (in caulk) + 36  [0x18e2a9ed8]
    +         2371 caulk::semaphore::timed_wait(double)  (in caulk) + 212  [0x18e2aa024]
    +           2371 semaphore_wait_trap  (in libsystem_kernel.dylib) + 8  [0x184c4be90]
    2371 Thread_1199566: com.apple.NSEventThread
    + 2371 thread_start  (in libsystem_pthread.dylib) + 8  [0x101b67a78]
    +   2371 _pthread_start  (in libsystem_pthread.dylib) + 148  [0x101b5d55c]
    +     2371 _NSEventThread  (in AppKit) + 172  [0x1880b2508]
    +       2371 CFRunLoopRunSpecific  (in CoreFoundation) + 612  [0x184d6858c]
    +         2342 __CFRunLoopRun  (in CoreFoundation) + 1208  [0x184d69198]
    +         ! 2341 __CFRunLoopServiceMachPort  (in CoreFoundation) + 160  [0x184d6a8b8]
    +         ! : 2341 mach_msg  (in libsystem_kernel.dylib) + 24  [0x184c4c290]
    +         ! :   2341 mach_msg_overwrite  (in libsystem_kernel.dylib) + 604  [0x184c54b78]
    +         ! :     2341 mach_msg2_internal  (in libsystem_kernel.dylib) + 80  [0x184c5e240]
    +         ! :       2341 mach_msg2_trap  (in libsystem_kernel.dylib) + 8  [0x184c4bf14]
    +         ! 1 __CFRunLoopServiceMachPort  (in CoreFoundation) + 180  [0x184d6a8cc]
    +         !   1 voucher_mach_msg_adopt  (in libdispatch.dylib) + 156  [0x101f66548]
    +         29 __CFRunLoopRun  (in CoreFoundation) + 2240  [0x184d695a0]
    +           29 __CFRunLoopDoSource1  (in CoreFoundation) + 520  [0x184d6abc0]
    +             29 __CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE1_PERFORM_FUNCTION__  (in CoreFoundation) + 60  [0x184d6aca0]
    +               29 __CFMachPortPerform  (in CoreFoundation) + 248  [0x184d9a2d0]
    +                 29 MessageHandler(__CFMachPort*, void*, long, void*)  (in HIToolbox) + 60  [0x18e5a92f0]
    +                   21 PullEventsFromWindowServerOnConnection(unsigned int, unsigned char, __CFMachPortBoost*)  (in HIToolbox) + 60  [0x18e5a9368]
    +                   : 21 SLEventCreateNextEvent  (in SkyLight) + 16  [0x189aa94ac]
    +                   :   21 SLSGetNextEventRecordInternal  (in SkyLight) + 344  [0x189cafee0]
    +                   :     19 CGSSnarfAndDispatchDatagrams  (in SkyLight) + 160  [0x18997477c]
    +                   :     | 19 mach_msg  (in libsystem_kernel.dylib) + 24  [0x184c4c290]
    +                   :     |   19 mach_msg_overwrite  (in libsystem_kernel.dylib) + 604  [0x184c54b78]
    +                   :     |     19 mach_msg2_internal  (in libsystem_kernel.dylib) + 80  [0x184c5e240]
    +                   :     |       19 mach_msg2_trap  (in libsystem_kernel.dylib) + 8  [0x184c4bf14]
    +                   :     2 CGSSnarfAndDispatchDatagrams  (in SkyLight) + 2740  [0x189975190]
    +                   :       2 dispatch_async  (in libdispatch.dylib) + 300  [0x101f3c780]
    +                   :         2 _dispatch_introspection_queue_item_enqueue_hook  (in libdispatch.dylib) + 56  [0x101f7642c]
    +                   :           2 gcd_queue_item_enqueue_hook  (in libBacktraceRecording.dylib) + 248,256  [0x101ba5f90,0x101ba5f98]
    +                   8 PullEventsFromWindowServerOnConnection(unsigned int, unsigned char, __CFMachPortBoost*)  (in HIToolbox) + 312  [0x18e5a9464]
    +                     8 SLEventCreateNextEvent  (in SkyLight) + 16  [0x189aa94ac]
    +                       8 SLSGetNextEventRecordInternal  (in SkyLight) + 344  [0x189cafee0]
    +                         6 CGSSnarfAndDispatchDatagrams  (in SkyLight) + 160  [0x18997477c]
    +                         | 6 mach_msg  (in libsystem_kernel.dylib) + 24  [0x184c4c290]
    +                         |   6 mach_msg_overwrite  (in libsystem_kernel.dylib) + 604  [0x184c54b78]
    +                         |     6 mach_msg2_internal  (in libsystem_kernel.dylib) + 80  [0x184c5e240]
    +                         |       6 mach_msg2_trap  (in libsystem_kernel.dylib) + 8  [0x184c4bf14]
    +                         2 CGSSnarfAndDispatchDatagrams  (in SkyLight) + 2740  [0x189975190]
    +                           2 dispatch_async  (in libdispatch.dylib) + 300  [0x101f3c780]
    +                             2 _dispatch_introspection_queue_item_enqueue_hook  (in libdispatch.dylib) + 56  [0x101f7642c]
    +                               2 gcd_queue_item_enqueue_hook  (in libBacktraceRecording.dylib) + 248  [0x101ba5f90]
    2371 Thread_1199612: mpv/opener
    + 2371 thread_start  (in libsystem_pthread.dylib) + 8  [0x101b67a78]
    +   2371 _pthread_start  (in libsystem_pthread.dylib) + 148  [0x101b5d55c]
    +     2371 open_demux_thread  (in libmpv.1.dylib) + 108  [0x1026b21a0]
    +       2371 demux_open_url  (in libmpv.1.dylib) + 788  [0x102652204]
    +         2371 open_given_type  (in libmpv.1.dylib) + 952  [0x1026572d4]
    +           2371 av_log  (in libavutil.56.dylib) + 24  [0x102029148]
    +             2371 mp_msg_av_log_callback  (in libmpv.1.dylib) + 624  [0x102646520]
    +               2371 mp_msg  (in libmpv.1.dylib) + 28  [0x10264ac0c]
    +                 2371 mp_msg_va  (in libmpv.1.dylib) + 836  [0x102649e48]
    +                   2371 _pthread_cond_wait  (in libsystem_pthread.dylib) + 1232  [0x101b61b6c]
    +                     2371 __psynch_cvwait  (in libsystem_kernel.dylib) + 8  [0x184c4f710]
    2307 Thread_1199514
    + 2305 start_wqthread  (in libsystem_pthread.dylib) + 8  [0x101b67a6c]
    + ! 2296 _pthread_wqthread  (in libsystem_pthread.dylib) + 364  [0x101b5fd14]
    + ! : 2296 __workq_kernreturn  (in libsystem_kernel.dylib) + 8  [0x184c4dbc8]
    + ! 9 _pthread_wqthread  (in libsystem_pthread.dylib) + 288  [0x101b5fcc8]
    + !   8 _dispatch_workloop_worker_thread  (in libdispatch.dylib) + 416  [0x101f506d0]
    + !   | 7 _dispatch_event_loop_merge  (in libdispatch.dylib) + 148  [0x101f621a8]
    + !   | + 2 _dispatch_queue_wakeup  (in libdispatch.dylib) + 744  [0x101f44288]
    + !   | + ! 2 _dispatch_introspection_queue_item_enqueue_hook  (in libdispatch.dylib) + 56  [0x101f7642c]
    + !   | + !   1 gcd_queue_item_enqueue_hook  (in libBacktraceRecording.dylib) + 44  [0x101ba5ec4]
    + !   | + !   : 1 ___chkstk_darwin  (in libsystem_pthread.dylib) + 0  [0x101b67a7c]
    + !   | + !   1 gcd_queue_item_enqueue_hook  (in libBacktraceRecording.dylib) + 8  [0x101ba5ea0]
    + !   | + 1 _dispatch_kevent_drain  (in libdispatch.dylib) + 232  [0x101f6233c]
    + !   | + 1 _dispatch_kevent_merge  (in libdispatch.dylib) + 176  [0x101f6451c]
    + !   | + 1 _dispatch_lane_push  (in libdispatch.dylib) + 0  [0x101f44bf4]
    + !   | + 1 _dispatch_queue_wakeup  (in libdispatch.dylib) + 0  [0x101f43fa0]
    + !   | + 1 _dispatch_source_merge_evt  (in libdispatch.dylib) + 0  [0x101f5634c]
    + !   | 1 _dispatch_event_loop_merge  (in libdispatch.dylib) + 124  [0x101f62190]
    + !   |   1 _platform_memmove  (in libsystem_platform.dylib) + 0  [0x184cba6a0]
    + !   1 _dispatch_workloop_worker_thread  (in libdispatch.dylib) + 460  [0x101f506fc]
    + 2 start_wqthread  (in libsystem_pthread.dylib) + 0  [0x101b67a64]
    731 Thread_1199887
    + 731 start_wqthread  (in libsystem_pthread.dylib) + 8  [0x101b67a6c]
    +   731 _pthread_wqthread  (in libsystem_pthread.dylib) + 364  [0x101b5fd14]
    +     731 __workq_kernreturn  (in libsystem_kernel.dylib) + 8  [0x184c4dbc8]
    61 Thread_1199514   DispatchQueue_556: glmtl.ioSurfaceNotifierQueue  (serial)
    + 61 start_wqthread  (in libsystem_pthread.dylib) + 8  [0x101b67a6c]
    +   61 _pthread_wqthread  (in libsystem_pthread.dylib) + 288  [0x101b5fcc8]
    +     61 _dispatch_workloop_worker_thread  (in libdispatch.dylib) + 1060  [0x101f50954]
    +       61 _dispatch_lane_invoke  (in libdispatch.dylib) + 424  [0x101f40d8c]
    +         60 _dispatch_lane_serial_drain  (in libdispatch.dylib) + 372  [0x101f3fac0]
    +         ! 60 _dispatch_source_invoke  (in libdispatch.dylib) + 1724  [0x101f55584]
    +         !   41 _dispatch_continuation_pop  (in libdispatch.dylib) + 496  [0x101f3a134]
    +         !   : 40 _dispatch_introspection_queue_item_dequeue_hook  (in libdispatch.dylib) + 56  [0x101f76688]
    +         !   : | 36 gcd_queue_item_dequeue_hook  (in libBacktraceRecording.dylib) + 312,292,...  [0x101ba63fc,0x101ba63e8,...]
    +         !   : | 3 gcd_queue_item_dequeue_hook  (in libBacktraceRecording.dylib) + 308  [0x101ba63f8]
    +         !   : | + 3 __gcd_queue_item_dequeue_hook_block_invoke  (in libBacktraceRecording.dylib) + 0,8  [0x101ba6b70,0x101ba6b78]
    +         !   : | 1 gcd_queue_item_dequeue_hook  (in libBacktraceRecording.dylib) + 88  [0x101ba631c]
    +         !   : |   1 is_interesting_event  (in libBacktraceRecording.dylib) + 268  [0x101ba69ac]
    +         !   : |     1 _platform_strcmp  (in libsystem_platform.dylib) + 172  [0x184cb7c3c]
    +         !   : 1 _dispatch_introspection_queue_item_dequeue_hook  (in libdispatch.dylib) + 44  [0x101f7667c]
    +         !   :   1 _dispatch_introspection_continuation_get_info  (in libdispatch.dylib) + 640  [0x101f751e4]
    +         !   17 _dispatch_continuation_pop  (in libdispatch.dylib) + 816  [0x101f3a274]
    +         !   : 17 _dispatch_client_callout  (in libdispatch.dylib) + 20  [0x101f3699c]
    +         !   :   10 dispatch_mig_server  (in libdispatch.dylib) + 288  [0x101f5d0f0]
    +         !   :   | 10 mach_msg  (in libsystem_kernel.dylib) + 24  [0x184c4c290]
    +         !   :   |   10 mach_msg_overwrite  (in libsystem_kernel.dylib) + 604  [0x184c54b78]
    +         !   :   |     10 mach_msg2_internal  (in libsystem_kernel.dylib) + 80  [0x184c5e240]
    +         !   :   |       10 mach_msg2_trap  (in libsystem_kernel.dylib) + 8  [0x184c4bf14]
    +         !   :   2 dispatch_mig_server  (in libdispatch.dylib) + 128  [0x101f5d050]
    +         !   :   | 1 __bzero  (in libsystem_platform.dylib) + 24  [0x184cba388]
    +         !   :   | 1 _platform_memset  (in libsystem_platform.dylib) + 140  [0x184cba45c]
    +         !   :   2 dispatch_mig_server  (in libdispatch.dylib) + 172  [0x101f5d07c]
    +         !   :   | 2 _platform_memset  (in libsystem_platform.dylib) + 140  [0x184cba45c]
    +         !   :   2 dispatch_mig_server  (in libdispatch.dylib) + 436  [0x101f5d184]
    +         !   :   | 2 _IODispatchCalloutWithDispatch  (in IOKit) + 44  [0x187e149a0]
    +         !   :   |   2 IODispatchCalloutFromCFMessage  (in IOKit) + 348  [0x187e14b0c]
    +         !   :   |     2 iosurfaceUseCountIsZeroCallback(void*, unsigned int, unsigned long long, unsigned long long)  (in AppleMetalOpenGLRenderer) + 0,64  [0x128535ab8,0x128535af8]
    +         !   :   1 dispatch_mig_server  (in libdispatch.dylib) + 0  [0x101f5cfd0]
    +         !   2 _dispatch_continuation_pop  (in libdispatch.dylib) + 0,176  [0x101f39f44,0x101f39ff4]
    +         1 _dispatch_lane_serial_drain  (in libdispatch.dylib) + 300  [0x101f3fa78]
    3 Thread_1199514   DispatchQueue_14: com.apple.root.default-qos.overcommit  (concurrent)
      3 start_wqthread  (in libsystem_pthread.dylib) + 8  [0x101b67a6c]
        3 _pthread_wqthread  (in libsystem_pthread.dylib) + 288  [0x101b5fcc8]
          1 _dispatch_workloop_worker_thread  (in libdispatch.dylib) + 556  [0x101f5075c]
          ! 1 _dispatch_introspection_queue_item_dequeue  (in libdispatch.dylib) + 28  [0x101f76614]
          1 _dispatch_workloop_worker_thread  (in libdispatch.dylib) + 1060  [0x101f50954]
          ! 1 _dispatch_lane_invoke  (in libdispatch.dylib) + 776  [0x101f40eec]
          1 _dispatch_workloop_worker_thread  (in libdispatch.dylib) + 3036  [0x101f5110c]
            1 _dispatch_event_loop_leave_deferred  (in libdispatch.dylib) + 0  [0x101f6264c]

Total number in stack (recursive counted multiple, when >=5):
        12       lj_BC_FUNCC  (in libluajit-5.1.2.dylib) + 44  [0x10299a838]
        9       _pthread_start  (in libsystem_pthread.dylib) + 148  [0x101b5d55c]
        9       thread_start  (in libsystem_pthread.dylib) + 8  [0x101b67a78]
        7       __psynch_cvwait  (in libsystem_kernel.dylib) + 0  [0x184c4f708]
        7       _pthread_cond_wait  (in libsystem_pthread.dylib) + 1232  [0x101b61b6c]
        6       lua_pcall  (in libluajit-5.1.2.dylib) + 148  [0x1029a7490]
        5       start_wqthread  (in libsystem_pthread.dylib) + 8  [0x101b67a6c]

Sort by top of stack, same collapsed (when >= 5):
        __psynch_cvwait  (in libsystem_kernel.dylib)        16597
        __workq_kernreturn  (in libsystem_kernel.dylib)        3027
        mach_msg2_trap  (in libsystem_kernel.dylib)        2376
        __psynch_mutexwait  (in libsystem_kernel.dylib)        2371
        poll  (in libsystem_kernel.dylib)        2371
        semaphore_wait_trap  (in libsystem_kernel.dylib)        2371
        gcd_queue_item_dequeue_hook  (in libBacktraceRecording.dylib)        36
        gcd_queue_item_enqueue_hook  (in libBacktraceRecording.dylib)        5

@low-batt
Copy link
Contributor

low-batt commented Apr 2, 2023

Since I raised the issue of the mpv logger hang, I decided I should go ahead and see if I could reproduce that under mpv 0.35.1 with the mpv log level set to trace. Good news on that front. I was unable to reproduce the hang with a quite a bit of trying. Of course you never know with elusive problems like this, but maybe it has been fixed.

- Fix duplicated subsystems could appear
- Fix binding issues
- Revert mpv log level to warn
@uiryuu uiryuu requested a review from low-batt April 3, 2023 07:04
Copy link
Contributor

@low-batt low-batt left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I tested under macOS 13.3 and macOS 10.15.7. Worked fine. There are two issues that must be addressed. This is going to be a great addition.

The label Subsystem is missing a :. It should end in a colon like the Level: label.

GitHub is reporting merge conflicts in AppDelegate.

Some additional thoughts…

How do we make it clear to users that the Level setting in the Log Viewer window is merely a filter on what is shown in the window and does not have any effect on what log messages are emitted. For that users have to figure out that they must change the Log level setting found in Advanced settings. I'm worried users will miss this important difference between those controls.

The column headers are not clickable, which makes sense as there is no need to support sorting, the provided filters should be good enough. This means the column headers should be static text, just like the labels for the pop-up buttons. When you hover over the label Subsystem and click, absolutely nothing happens. I would expect the column titles to behave the same way. They do not. When you click you get an animation like you do for a control that performs an action in response to the click.

When you horizontally expand the window another column appears at the end of the table as shown in the screen shot below. Is there some maximum size on the Message column that prevents it from expanding to fill the window?

pr4109-extra-column

- Add `:` after Subsystem the label
- Enlarge the maximum length of the last column
- Add AutosaveName to the window so that it remembers last open size
- Internalization
@uiryuu
Copy link
Member Author

uiryuu commented Apr 4, 2023

The label Subsystem is missing a :. It should end in a colon like the Level: label.

Fixed.

GitHub is reporting merge conflicts in AppDelegate.

Will address that later

For that users have to figure out that they must change the Log level setting found in Advanced settings. I'm worried users will miss this important difference between those controls.

I currently don't have a very good solution to this. This is certainly one thing we can further improve after merging.

This means the column headers should be static text, just like the labels for the pop-up buttons. When you hover over the label Subsystem and click, absolutely nothing happens. I would expect the column titles to behave the same way. They do not. When you click you get an animation like you do for a control that performs an action in response to the click.

I didn't find any settings/API to disable the click animation on the table header. Can you find an example of NSTableView with unclickable headers?

When you horizontally expand the window another column appears at the end of the table as shown in the screen shot below. Is there some maximum size on the Message column that prevents it from expanding to fill the window?

I set this max value to 1000... Fixed by enlarging this value a lot.

Besides, I also added the AutosaveName for the window, so that it can remember window size when last opened. Our playback history window also lacks that, will add it in separate commit tho.

@uiryuu uiryuu self-assigned this Apr 4, 2023
Copy link
Contributor

@low-batt low-batt left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Built and tested. Looks good to me.

@low-batt
Copy link
Contributor

low-batt commented Apr 4, 2023

On the "clickable" headers. When I click on the table column header Rule in LittleSnitch I don't see that animation. It might be that they are using a custom header and are intercepting mouseDown and not passing it up. Not sure.

This was just a little UI nit I thought I'd point out. That and the "extra" column can be seen in other IINA tables. Glad you were able to effectively suppress that blank column.

@uiryuu uiryuu merged commit d161baa into develop Apr 4, 2023
2 checks passed
@uiryuu uiryuu deleted the log-window branch April 4, 2023 03:25
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

5 participants