Windows-Auto-Night-Mode icon indicating copy to clipboard operation
Windows-Auto-Night-Mode copied to clipboard
verified publisher icon AutoDarkMode

"TimeSwitchModule" after "BatteryStatusChanged" triggering (Script issue)

Open boredwz opened this issue 2 years ago • 5 comments

Description

Sometimes, after BatteryStatusChanged, TimeSwitchModule is also triggered (with weird params), which leads to duplication of scripts.

  • Automatic theme switch: disabled
  • Device unplugged Dark Theme switch: enabled

2023-10-13 15:38:33 | Info | ThemeManager.UpdateTheme: dark theme switch performed, source: BatteryStatusChanged

2023-10-13 15:38:36 | Info | ThemeManager.UpdateTheme: dark theme switch performed, source: TimeSwitchModule, sunset: 01/01/0001 12:00:00 am

My script detected the duplicate and returned ## MULTI ##:

2023-10-13 15:38:38 | Info | ScriptHandler.Launch: ===== scripts_loader (ANY) ====='s output: ##### MULTI #####

How often does this happen? It seems more like random thing. Maybe about once in ten times.

Expected Behavior

No response

Log Data

2023-10-13 15:38:28 | Info | SystemEventHandler.PowerManager_BatteryStatusChanged: battery discharging, enabling dark mode 
2023-10-13 15:38:28 | Info | ComponentManager.GetComponentsToUpdate: components queued for update: [ScriptSwitch] 
2023-10-13 15:38:28 | Info | ThemeManager.UpdateTheme: dwm management: full refresh requested by user 
2023-10-13 15:38:28 | Info | ScriptHandler.Launch: running ===== scripts_loader (ANY) =====: "powershell" "-ExecutionPolicy" "Bypass" "-File" ".\#scripts_loader.ps1" "Dark" 
2023-10-13 15:38:33 | Info | Tm2Handler.SetTheme: applied theme ADMUnmanagedDark, from origin: C:\Users\wz\AppData\Local\Microsoft\Windows\Themes\dark.theme directly via IThemeManager2 
2023-10-13 15:38:33 | Info | ThemeManager.UpdateTheme: dark theme switch performed, source: BatteryStatusChanged 
2023-10-13 15:38:36 | Info | ComponentManager.GetComponentsToUpdate: components queued for update: [ScriptSwitch] 
2023-10-13 15:38:36 | Info | ThemeManager.UpdateTheme: dwm management: no refresh required 
2023-10-13 15:38:36 | Info | ScriptHandler.Launch: running ===== scripts_loader (ANY) =====: "powershell" "-ExecutionPolicy" "Bypass" "-File" ".\#scripts_loader.ps1" "Dark" 
2023-10-13 15:38:36 | Info | ThemeManager.UpdateTheme: dark theme switch performed, source: TimeSwitchModule, sunset: 01/01/0001 12:00:00 am 
2023-10-13 15:38:38 | Info | ScriptHandler.Launch: ===== scripts_loader (ANY) ====='s output: ##### MULTI ##### 
2023-10-13 15:38:38 | Info | ScriptSwitch.HandleSwitch: update info - previous: Light, now: Dark 
2023-10-13 15:38:38 | Info | ScriptHandler.Launch: ===== scripts_loader (ANY) ====='s output: SUCCESS: The process "explorer.exe" with PID 4624 has been terminated.
2023-10-13 15:38:38 | Info | ScriptSwitch.HandleSwitch: update info - previous: Light, now: Dark

Commit Hash, Version and Windows Build

  • Commit: cf7a0fe
  • Service/App: 10.4.1.1
  • Updater: 3.1.4
  • Shell: 1.3.3.0
  • .Net: 7.0.5
  • Windows: 19045.3448

Screenshots / Videos

No response

boredwz avatar Oct 13 '23 19:10 boredwz

Hm yes, that doesn't seem right. Disabling automatic theme switch should also disable the time switch module.

You mentioned this happens randomly? The only location where we would produce such an event is here https://github.com/AutoDarkMode/Windows-Auto-Night-Mode/blob/cf7a0fefd8b51edc8d4868acd3abe06880113362/AutoDarkModeSvc/Governors/TimeSwitchGovernor.cs#L67

Which shouldn't be active on disabled automatic switch.

Could you please upload the entire log and your config file? I need to check if the time switch governor is active.

Spiritreader avatar Oct 23 '23 20:10 Spiritreader

You mentioned this happens randomly?

As far as I understood, this happens when the BatteryStatusChanged is triggered and the theme switches to dark.

service.log AllowedSources: [Any] - so my script was launched from any trigger

config.yaml 

AutoThemeSwitchingEnabled: true
Governor: Default
Autostart:
  Validate: false
WindowsThemeMode:
  Enabled: true
  DarkThemePath: C:\Users\wz\AppData\Local\Microsoft\Windows\Themes\dark.theme
  LightThemePath: C:\Users\wz\AppData\Local\Microsoft\Windows\Themes\light.theme
  MonitorActiveTheme: false
  ApplyFlags: []
AppsSwitch:
  Enabled: true
  Component:
    Mode: Switch
SystemSwitch:
  Enabled: true
  Component:
    Mode: Switch
    TaskbarSwitchDelay: 1200
    TaskbarColorOnAdaptive: false
    TaskbarColorWhenNonAdaptive: Light
    DWMPrevalenceSwitch: false
    DWMPrevalenceEnableTheme: Light
TouchKeyboardSwitch:
  Enabled: false
  Component: {}
ColorizationSwitch:
  Enabled: false
  Component:
    LightHex: ''
    DarkHex: ''
    LightAutoColorization: false
    DarkAutoColorization: false
ColorFilterSwitch:
  Enabled: false
  Component: {}
OfficeSwitch:
  Enabled: false
  Component:
    Mode: Switch
    LightTheme: 0
    DarkTheme: 4
CursorSwitch:
  Enabled: false
  Component:
    CursorsLight: 
    CursorsDark: 
Sunrise: 2023-10-20T08:30:00.0000000
Sunset: 2023-10-20T18:20:00.0000000
Location:
  PollingCooldownTimeSpan: 1.00:00:00
  Enabled: false
  UseGeolocatorService: true
  SunsetOffsetMin: 0
  SunriseOffsetMin: 0
  CustomLat: 0
  CustomLon: 0
Tunable:
  BatterySliderDefaultValue: 25
  DisableEnergySaverOnThemeSwitch: false
  UseLogonTask: false
  Debug: true
  Trace: false
  DebugTimerMessage: false
  ShowTrayIcon: true
  AlwaysFullDwmRefresh: true
  UICulture: en
GPUMonitoring:
  Enabled: false
  Threshold: 30
  Samples: 1
ProcessBlockList:
  ProcessNames: []
  Enabled: false
Events:
  DarkThemeOnBattery: true
  Win10AllowLockscreenSwitch: true
Notifications:
  OnAutoThemeSwitching: true
  OnSkipNextSwitch: true
AutoSwitchNotify:
  Enabled: false
  GracePeriodMinutes: 5
Hotkeys:
  Enabled: false
  ForceLight: 
  ForceDark: 
  NoForce: 
  ToggleTheme: 
  TogglePostpone: 
  ToggleAutoThemeSwitch: 
IdleChecker:
  Enabled: false
  Threshold: 5
WallpaperSwitch:
  Enabled: false
  Component:
    TypeLight: Individual
    TypeDark: Individual
    Position: Fill
    GlobalWallpaper:
      Light: 
      Dark: 
    SolidColors:
      Light: '#FFFFFF'
      Dark: '#000000'
    Monitors: []
Updater:
  AutoInstall: false
  Enabled: true
  Silent: false
  DaysBetweenUpdateCheck: 7
  CheckOnStart: false
  VersionQueryUrl: https://raw.githubusercontent.com/AutoDarkMode/AutoDarkModeVersion/master/version-beta.yaml
  DownloadBaseUrl: 
  ZipCustomUrl: 
  HashCustomUrl:

Here's a part where I tested AC plug-unplug and it worked as it should:

2023-10-22 10:34:36 | Info | SystemEventHandler.PowerManager_BatteryStatusChanged: battery discharging, enabling dark mode 
2023-10-22 10:34:36 | Info | ComponentManager.GetComponentsToUpdate: components queued for update: [SystemSwitchThemeFile, ScriptSwitch] 
2023-10-22 10:34:36 | Info | SystemSwitchThemeFile.SwitchSystemTheme: update info - previous: Light/NoAccent, pending: Dark/NoAccent, mode: Switch, accent: no 
2023-10-22 10:34:36 | Info | ThemeManager.UpdateTheme: dwm management: full refresh requested by user 
2023-10-22 10:34:36 | Info | ScriptHandler.Launch: running scripts_loader: "powershell" "-ExecutionPolicy" "Bypass" "-File" ".\#scripts_loader.ps1" "Dark" 
2023-10-22 10:34:36 | Info | Tm2Handler.SetTheme: applied theme ADMUnmanagedDark, from origin: C:\Users\wz\AppData\Local\Microsoft\Windows\Themes\dark.theme directly via IThemeManager2
2023-10-22 10:34:36 | Info | ThemeManager.UpdateTheme: dark theme switch performed, source: BatteryStatusChanged
2023-10-22 10:34:39 | Info | ScriptSwitch.HandleSwitch: update info - previous: Light, now: Dark 
2023-10-22 10:38:23 | Info | ComponentManager.GetComponentsToUpdate: components queued for update: [SystemSwitchThemeFile, ScriptSwitch] 
2023-10-22 10:38:23 | Info | SystemSwitchThemeFile.SwitchSystemTheme: update info - previous: Dark/NoAccent, pending: Light/NoAccent, mode: Switch, accent: no
2023-10-22 10:38:23 | Info | ThemeManager.UpdateTheme: dwm management: full refresh requested by user 
2023-10-22 10:38:23 | Info | ScriptHandler.Launch: running scripts_loader: "powershell" "-ExecutionPolicy" "Bypass" "-File" ".\#scripts_loader.ps1" "Light" 
2023-10-22 10:38:25 | Info | Tm2Handler.SetTheme: applied theme ADMUnmanagedLight, from origin: C:\Users\wz\AppData\Local\Microsoft\Windows\Themes\light.theme directly via IThemeManager2 
2023-10-22 10:38:25 | Info | ThemeManager.UpdateTheme: light theme switch performed, source: BatteryStatusChanged 
2023-10-22 10:38:27 | Info | ScriptSwitch.HandleSwitch: update info - previous: Dark, now: Light 
2023-10-22 10:38:50 | Info | SystemEventHandler.PowerManager_BatteryStatusChanged: battery discharging, enabling dark mode 
2023-10-22 10:38:50 | Info | ComponentManager.GetComponentsToUpdate: components queued for update: [SystemSwitchThemeFile, ScriptSwitch] 
2023-10-22 10:38:50 | Info | SystemSwitchThemeFile.SwitchSystemTheme: update info - previous: Light/NoAccent, pending: Dark/NoAccent, mode: Switch, accent: no 
2023-10-22 10:38:50 | Info | ThemeManager.UpdateTheme: dwm management: full refresh requested by user 
2023-10-22 10:38:50 | Info | ScriptHandler.Launch: running scripts_loader: "powershell" "-ExecutionPolicy" "Bypass" "-File" ".\#scripts_loader.ps1" "Dark" 
2023-10-22 10:38:52 | Info | Tm2Handler.SetTheme: applied theme ADMUnmanagedDark, from origin: C:\Users\wz\AppData\Local\Microsoft\Windows\Themes\dark.theme directly via IThemeManager2 
2023-10-22 10:38:52 | Info | ThemeManager.UpdateTheme: dark theme switch performed, source: BatteryStatusChanged 
2023-10-22 10:38:54 | Info | ScriptSwitch.HandleSwitch: update info - previous: Light, now: Dark

boredwz avatar Oct 23 '23 22:10 boredwz

Automatic theme switch: disabled

Your config and the logs say otherwise:

AutoThemeSwitchingEnabled: true

2023-10-23 02:50:43 | Info | TimeSwitchGovernor.EnableHook: time switch governor selected

Your auto switch is enabled. Which means that the time switch module and the battery event can overlap, causing the behavior you observed.

The duplicate trigger is most likely a race condition where ADM hasn't updated the internal state yet after the battery event triggers, and the timer events fire just so.

I've introduced a guard on the battery event that should prevent the governor modules from invoking a switch when a battery trigger event happens.

Spiritreader avatar Oct 24 '23 11:10 Spiritreader

Your auto switch is enabled

Yes, yes, it's my bad. I forgot that I had enabled AutoThemeSwitchingEnabled, and this log was displaying information with AutoThemeSwitchingEnabled: true.

But this does not cancel the fact that the bug exists, and perhaps this will fix the situation:

The duplicate trigger is most likely a race condition where ADM hasn't updated the internal state yet after the battery event triggers, and the timer events fire just so. I've introduced a guard on the battery event that should prevent the governor modules from invoking a switch when a battery trigger event happens.

boredwz avatar Oct 25 '23 08:10 boredwz

Is the guard working?

Spiritreader avatar Apr 24 '24 20:04 Spiritreader