search

openplanet-nl / plugin-manager

In-game plugin manager, installer, and updater.
6 stars 5 forks source link

simultaneously updating a dependency and a dependent plugin can produce incorrect error messages #17

Open XertroV opened 1 year ago

XertroV commented 1 year ago

This situation arose when ppl updated MLFeed and Buffer Time at the same time. I think plugin manager will reload them in a way that means a dependent plugin has a chance to issue an error notification, but then gets reloaded in a way that means no output is generated. This leads to confusion on the part of the user.

Example 1 via AR_Down: https://www.twitch.tv/videos/1654817065?t=00h18m30s Example 2 via JNic: https://www.twitch.tv/videos/1655110358?t=00h10m12s

I'm happy to look at a patch if you like. I guess that it's just a matter of unloading in the right order, then updating dependencies, then updating dependents.

codecat commented 1 year ago

It would be good to see the log of this, and perhaps some reproduce steps (eg. install old versions & click update). The log should say the order in which plugins are loaded.

XertroV commented 1 year ago

Reproduction steps:

  1. ensure auto updating disabled in plugin manager settings
  2. have MLHook installed in Plugins/ already
  3. TM is closed
  4. Download MLFeed 0.3.7 and Buffer Time 1.0.7 and put them in Plugins/
  5. Start TM
  6. wait for initialization so logs are clean
  7. press update all

image

FYI my plan to avoid this in upcoming versions is just to sleep for a second before notifying the user about a missing dependency. That is hopefully enough time.

Filtered log corresponding to the above (with a bit more included)

[   ScriptRuntime] [10:22:47] [PluginManager]  Plugin cache: Synchronized Dashboard 1.9.4
[   ScriptRuntime] [10:22:47] [PluginManager]  Plugin cache: Synchronized SplitSpeeds 1.0.5
[   ScriptRuntime] [10:22:47] [PluginManager]  Checking for plugin updates..
[   ScriptRuntime] [10:22:47] [PluginManager]  API request: https://openplanet.dev/api/versions?ids=192,49,103,206,144,241,125,69,145,216,146,131,82,162,170,256,134,79,118,99,154,163,255,217,279,71,too-many-ghosts-0.1.0,238,205,158,271,62,225,250,164
[   ScriptRuntime] [10:22:47] [MLFeedRaceData]  registered MLHook event for type: MLHook_Event_RaceStats_PlayerCP
[   ScriptRuntime] [10:22:47] [MLFeedRaceData]  registered MLHook event for type: MLHook_Event_RaceStats_PlayerLeft
[   ScriptRuntime] [10:22:47] [MLFeedRaceData]  registered MLHook event for type: MLHook_Event_RaceStats_PlayerRaceTimes
[   ScriptRuntime] [10:22:47] [MLFeedRaceData]  registered MLHook event for type: MLHook_Event_MLFeedKOs_PlayerStatus
[   ScriptRuntime] [10:22:47] [MLFeedRaceData]  registered MLHook event for type: MLHook_Event_MLFeedKOs_MatchKeyPair
[   ScriptRuntime] [10:22:47] [MLFeedRaceData]  registered MLHook event for type: TMxSM_Race_Record_NewRecord
[   ScriptRuntime] [10:22:47] [MLFeedRaceData]  registered MLHook event for type: MLHook_Event_GhostData
[   ScriptRuntime] [10:22:47] [PluginManager]  Saved PluginCache.json
[   ScriptRuntime] [10:22:48] [PluginManager]  New plugin update available for COTD Buffer Time: 1.0.7 -> 2.1.12
[   ScriptRuntime] [10:22:48] [PluginManager]  New plugin update available for MLFeed: Race Data: 0.3.7 -> 0.3.8
[   ScriptRuntime] [10:23:16] [PluginManager]  Uninstalling plugin COTD Buffer Time
[   ScriptRuntime] [10:23:16] [PluginManager]  Plugin cache: Removed CotdBufferTime
[   ScriptRuntime] [10:23:16] [PluginManager]  Installing plugin with site ID 256 and identifier "CotdBufferTime"
[   ScriptRuntime] [10:23:16] [PluginManager]  Saved PluginCache.json
[   ScriptRuntime] [10:23:18] [PluginManager]  Uninstalling plugin MLFeed: Race Data
[    ScriptEngine] [10:23:18]  Unloading dependent plugin "better-splits-history-dev" of "MLFeedRaceData"
[    ScriptEngine] [10:23:18]  Unloading dependent plugin "players-pbs-dev" of "MLFeedRaceData"
[    ScriptEngine] [10:23:18]  Unloading dependent plugin "race-stats-dev" of "MLFeedRaceData"
[    ScriptEngine] [10:23:18]  Unloading dependent plugin "buffer-time-dev" of "MLFeedRaceData"
[   ScriptRuntime] [10:23:18] [MLFeedRaceData]  _Unload, unloading hooks and removing injected ML
[   ScriptRuntime] [10:23:18] [MLFeedRaceData]  UnregisteredMLHook object for types: MLHook_Event_RaceStats_PlayerCP, MLHook_Event_RaceStats_PlayerLeft, MLHook_Event_RaceStats_PlayerRaceTimes
[   ScriptRuntime] [10:23:18] [MLFeedRaceData]  UnregisteredMLHook object for types: MLHook_Event_MLFeedKOs_PlayerStatus, MLHook_Event_MLFeedKOs_MatchKeyPair
[   ScriptRuntime] [10:23:18] [MLFeedRaceData]  UnregisteredMLHook object for types: TMxSM_Race_Record_NewRecord
[   ScriptRuntime] [10:23:18] [MLFeedRaceData]  UnregisteredMLHook object for types: MLHook_Event_GhostData
[   ScriptRuntime] [10:23:18] [PluginManager]  Plugin cache: Removed MLFeedRaceData
[   ScriptRuntime] [10:23:18] [PluginManager]  Installing plugin with site ID 255 and identifier "MLFeedRaceData"
[   ScriptRuntime] [10:23:18] [PluginManager]  Saved PluginCache.json
[    ScriptEngine] [10:23:20] [PluginManager]  Couldn't find required plugin dependency "MLFeedRaceData" while loading plugin "CotdBufferTime"
[    ScriptEngine] [10:23:20] [PluginManager]  Loaded zipped plugin 'CotdBufferTime' (version 2.1.12)
[    ScriptEngine] [10:23:20] [MLFeedRaceData]  HookGhostData.as (84, 5) : INFO : Compiling void DrawGhost(uint, const MLFeed::GhostInfo@)
[    ScriptEngine] [10:23:20] [MLFeedRaceData]  HookGhostData.as (99, 23) : WARN : Variable 'i' hides another variable of same name in outer scope
[    ScriptEngine] [10:23:20] [MLFeedRaceData]  RaceFeedDemoUI.as (6, 5) : INFO : Compiling void Render()
[    ScriptEngine] [10:23:20] [MLFeedRaceData]  RaceFeedDemoUI.as (58, 31) : WARN : Variable 'i' hides another variable of same name in outer scope
[    ScriptEngine] [10:23:20] [PluginManager]  Loaded zipped plugin 'MLFeedRaceData' (version 0.3.8)
[   ScriptRuntime] [10:23:20] [PluginManager]  Reloading dependent plugin 'CotdBufferTime'
[    ScriptEngine] [10:23:20] [PluginManager]  Loaded zipped plugin 'CotdBufferTime' (version 2.1.12)
[    ScriptEngine] [10:23:20] [PluginManager]  Loaded plugin 'better-splits-history-dev' (version 0.1.0)
[    ScriptEngine] [10:23:20] [PluginManager]  Loaded plugin 'players-pbs-dev' (version 0.1.9)
[    ScriptEngine] [10:23:21] [PluginManager]  Loaded plugin 'race-stats-dev' (version 0.1.0)
[    ScriptEngine] [10:23:21] [PluginManager]  Loaded plugin 'buffer-time-dev' (version 2.1.12)
[   ScriptRuntime] [10:23:21] [CotdBufferTime]  buffer time starting.
[   ScriptRuntime] [10:23:21] [players-pbs-dev]  MLFeed detected: true
[   ScriptRuntime] [10:23:21]  Plugin PluginManager just hung for 620.02 ms!
[   ScriptRuntime] [10:23:21] [MLFeedRaceData]  registered MLHook event for type: MLHook_Event_RaceStats_PlayerCP
[   ScriptRuntime] [10:23:21] [MLFeedRaceData]  registered MLHook event for type: MLHook_Event_RaceStats_PlayerLeft
[   ScriptRuntime] [10:23:21] [MLFeedRaceData]  registered MLHook event for type: MLHook_Event_RaceStats_PlayerRaceTimes
[   ScriptRuntime] [10:23:21] [MLFeedRaceData]  registered MLHook event for type: MLHook_Event_MLFeedKOs_PlayerStatus
[   ScriptRuntime] [10:23:21] [MLFeedRaceData]  registered MLHook event for type: MLHook_Event_MLFeedKOs_MatchKeyPair
[   ScriptRuntime] [10:23:21] [MLFeedRaceData]  registered MLHook event for type: TMxSM_Race_Record_NewRecord
[   ScriptRuntime] [10:23:21] [MLFeedRaceData]  registered MLHook event for type: MLHook_Event_GhostData