digitaltrails / vdu_controls

VDU controls - a control panel for monitor brightness/contrast/...
GNU General Public License v3.0
123 stars 4 forks source link

Apply scheduled preset when monitor goes back on #96

Open jpbaril opened 1 month ago

jpbaril commented 1 month ago

Hi,

I tested this for a couple days and it seems that if a monitor was off at the time of a scheduled preset then when the monitor goes back on the appropriate preset will not be applied.

I don't know if it's a bug or just not a feature currently implemented but that would definitely be a nice addition so to never have to manually apply a preset.

digitaltrails commented 1 month ago

What are the circumstances:

What version of vdu_controls (listed in the About dialog)?

Is vdu_controls being used with ddcutil-service or just the ddcutil command?

Which of the following describes your situation?

  1. The desktop actively being used on one or more monitors, and an additional monitor is powered up.
  2. Desktop locked/sleeping with all monitors in DPMS sleep.
  3. PC suspended/hibernating and now waking up.
  4. PC powered off and now being restarted.

Case 1 is covered if vdu_controls is ddcutil-service, the preset that was last due will be restored. If not using the service, pressing the refresh button also restores the preset that was last due.

Case 2 was covered by looping the attempt to restore until it succeeds. This seems to still be working for a brief test just now. Possibly there may issues if the repeat drags on across midnight (local time), when the schedule updates (but I think that was tested). But changes to the handling of concurrency may also give room for new bugs.

Definitely forgot about 3, that would depend on what Qt does about its timer jobs when the PC wakes up. Hibernate/suspend is not something I use, so I hadn't even thought about it. If the Qt timers don't cover it, I should probably reimplement with code that checks if a preset is due or overdue and fires it.

Case 4 is similar to case one, on startup the preset that was last due will be restored. This code may be potentially be repurposed to cover more cases, such as case 3.

jpbaril commented 1 month ago

To be honest I don't quite understand these case descriptions. What usually happens is that I manually power off my monitor or that the screensaver launches. Few hours later I either power on the monitor or simply logs back in from the lock screen. My computer never goes to sleep.

I have 2.1.1. I was using ddcutil command but installed ddcutil-service today. Does not seem to have made a difference.

In fact, I just logged back in to type this answer and it did not apply my "night" preset as it should. Weirdly enough, it even went back to "noon" preset even though it had correctly applied earlier my "evening" preset (as monitor was on at that moment).

digitaltrails commented 1 month ago

OK, so this is more like case 2. Presumably the screen saver is sending the monitors into power saving, which is somewhat similar to turning them off (but not quite).

Anyway, I'm not seeing a similar behaviour. I have seen wacky behaviour if the system locale (e.g. NZ, AU, CN) and GPS coordinates don't match, but then the solar elevation chart would also look wrong.

What happens if you restart vdu_controls - does it kick in the right preset?

Perhaps consult your logs, presumably the systemd journal or stdout/stderr depending on how you are running vdu_controls or whether you have enabled the syslog logging.

Does the log contains any errors of interest.

In my case, if ddcutil-service is running, within a minute or so of powering up a monitor, I would expect to see:

ddcutil-service[3109]: Poll signal event - connected 1 ...

And shortly after, vdu_controls should log:

Received display_change D-Bus signal message.arguments()=...
Connected VDUs event DdcEventType.DISPLAY_CONNECTED flags=0 ...
...
Configuring application (reconfiguring=True)...
...
Scheduling presets reconfiguring=True
...
Restoring preset 'test' because its scheduled to be active at this time (2024-10-19 16:56:00.986289+13:00).
...

You could tar/zip up the logs and attach them here (remove anything sensitive logged by other processes).

Plus tar/zip up and attach your config directory.

digitaltrails commented 1 month ago
  1. Are you using more than one monitor?
  2. If yes, is this happening when only one of the two is turned off?
jpbaril commented 1 month ago

If I restart vdu_controls then the right preset always kicks in. Using only one monitor.

I'll check the logs tonight.

jpbaril commented 1 month ago

Here are some logs for anything "vdu" or "ddcutil". Weird thing I notice is that while the screen was off vdu_controls did try to apply the "sunset" preset at 17:54, yet when I turned on the screen at 18:12, the incorrect preset was applied.

oct 19 17:54:00 blackbox-ng vdu_controls.desktop[44497]: 17:54:00 INFO: Activating scheduled preset Sunset transition=False
oct 19 17:54:00 blackbox-ng vdu_controls.desktop[44497]: 17:54:00 INFO: Restored Sunset, elapsed: 0.56 seconds 1 VCP-changes
oct 19 18:11:56 blackbox-ng vdu_controls.desktop[44497]: qt.qpa.wayland: Creating a fake screen in order for Qt not to crash
oct 19 18:12:01 blackbox-ng ddcutil-service[17470]: Poll signal event - dpms changed to awake 1 AP///////wAQrG/QTFFDMCUZAQSlNx...
oct 19 18:12:01 blackbox-ng vdu_controls.desktop[44497]: 18:12:01 INFO: Received display_change D-Bus signal message.arguments()=['AP///////wAQrG/QTFFDMCUZAQSlNx94PkRVqVVNnSYPUFSlSwCzANEAcU+pQIGAd4ABAQEBVl4AoKCgKVAwIDUAKTchAAAaAAAA/wBZS0ZXUDU5OTBDUUwKAAAA/ABERUxMIFUyNTE1SAogAAAA/QA4Vh5xHgEKICAgICAgAUE=', 0, 0] id(self)=138257661195712
oct 19 18:12:01 blackbox-ng vdu_controls.desktop[44497]: 18:12:01 INFO: Connected VDUs event DdcEventType.DPMS_AWAKE flags=0 AP///////wAQrG/QTFFDMCUZAQSlNx...
oct 19 18:12:01 blackbox-ng vdu_controls.desktop[44497]: 18:12:01 INFO: Refresh commences - acquired application_lock external_event=True
oct 19 18:12:01 blackbox-ng vdu_controls.desktop[44497]: 18:12:01 INFO: Found intialization-preset for DELL_U2515H_YKFWP5990CQL
oct 19 18:12:02 blackbox-ng vdu_controls.desktop[44497]: 18:12:02 INFO: Restored DELL U2515H YKFWP5990CQL, elapsed: 0.56 seconds 1 VCP-changes
oct 19 18:12:02 blackbox-ng vdu_controls.desktop[44497]: 18:12:02 INFO: Restored initialization-preset DELL U2515H YKFWP5990CQL
digitaltrails commented 1 month ago

A few thoughts/questions:

  1. It appears Sunny was successfully restored at 17:54:00.
  2. If the monitor was off at 17:54:00, I would have expected the restore to error and periodically retry. It's possible this VDU is responding when it is off, some VDU's appear to do that, but they are not actually responding, I would need to add code to cope with that.
  3. Does the initialization-preset DELL U2515H YKFWP5990CQL include setting the brightness? The DELL U2515H YKFWP5990CQL restore is triggered by the DPMS event when the monitor comes back online.
  4. I had recently add initialization-presets as a replacement for failed monitor NVRAM, or to restore settings not held in NVRAM. I'm curious as to why you might need them?
  5. I would have thought the refresh at 18:12:01 would have also restored Sunny, but maybe not if the number of monitors did not change - that might be something I need to fix.
  6. KDE6 onward also alters/restores brightness when the desktop is unlocked, it also dims the monitors under some circumstances. There's a notice at the top of the vdu_controls README.MD concerning KDE6. I'm not sure the note covers every way KDE might alter brightness.
jpbaril commented 1 month ago

For the "initialization-preset", well I really don't understand what it does. I added it because in a recent version I was proposed to create it and I thought that maybe it would help with my issue. So, I understand that I should delete it. I don't use KDE, I use Gnome.

digitaltrails commented 1 month ago

Yes, delete it. If the initialization-preset includes a brightness, it will be overriding the scheduled preset whenever the monitor powers-up (and maybe also on wakeup for some monitors). The initialization-preset is intended to help with VDU's that have broken NVRAM and can't save their own settings - a Preset that gets triggered when the monitor powers up.

From your log it looks like vdu_controls "thinks" it successfully already restored Sunset at 17:54. If the monitor was actually not on at that time, that would probably mean the monitor was still accepting, but not applying commands. For my own monitors, if they were off at 17:54, there would be an error and vdu_controls would keep trying until eventually succeeding at 18:12:01.

So it looks like I might need to add some code to handle such a case. The problem is that not knowing whether Sunset has been properly restored means vdu_controls may keep restoring it each time the monitor wakes, and this may tread on any manual changes the user makes in between the sleeps.

digitaltrails commented 1 month ago

Could we sample your logs now that the _initializationpreset has been removed. Perhaps turn on the debugging setting to get more info.

It's quite difficult to understand how a set_vcp can succeed if the monitor is off. Part of the process of restoring a Preset is to perform get_vcp calls to see if it has set all the required values have been met. The restoration should error if the monitor setting does not stick. But if the monitor is behaving badly, I guess anything is possible.

I may have to add a special option, 'hard-dpms', that would treat a DPMS event as requiring a total reconfiguration - which is what happens when more monitors are hot-plugged. But this may not work if I'm misunderstanding the problem.

jpbaril commented 1 month ago

Logs since late last night from the moment I activated debug setting.

oct 20 00:20:38 blackbox-ng ddcutil-service[17470]: Poll signal event - dpms changed to awake 1 AP///////wAQrG/QTFFDMCUZAQSlNx...
oct 20 00:20:38 blackbox-ng vdu_controls.desktop[44497]: 00:20:38 INFO: Received display_change D-Bus signal message.arguments()=['AP///////wAQrG/QTFFDMCUZAQSlNx94PkRVqVVNnSYPUFSlSwCzANEAcU+pQIGAd4ABAQEBVl4AoKCgKVAwIDUAKTchAAAaAAAA/wBZS0ZXUDU5OTBDUUwKAAAA/ABERUxMIFUyNTE1SAogAAAA/QA4Vh5xHgEKICAgICAgAUE=', 0, 0] id(self)=138257661195712
oct 20 00:20:38 blackbox-ng vdu_controls.desktop[44497]: 00:20:38 INFO: Connected VDUs event DdcEventType.DPMS_AWAKE flags=0 AP///////wAQrG/QTFFDMCUZAQSlNx...
oct 20 00:20:38 blackbox-ng vdu_controls.desktop[44497]: 00:20:38 INFO: Refresh commences - acquired application_lock external_event=True
oct 20 00:28:34 blackbox-ng vdu_controls.desktop[44497]: qt.qpa.wayland: Wayland does not support QWindow::requestActivate()
oct 20 00:28:45 blackbox-ng vdu_controls.desktop[44497]: 00:28:45 INFO: Wrote config to /home/jpbaril/.config/vdu_controls/vdu_controls.conf
oct 20 00:28:45 blackbox-ng vdu_controls.desktop[44497]: 00:28:45 INFO: Reloading config: /home/jpbaril/.config/vdu_controls/vdu_controls.conf
oct 20 00:28:45 blackbox-ng vdu_controls.desktop[44497]: 00:28:45 INFO: Using config file '/home/jpbaril/.config/vdu_controls/vdu_controls.conf'
oct 20 00:28:45 blackbox-ng vdu_controls.desktop[44497]: 00:28:45 INFO: Reconfiguring due to settings change.
oct 20 00:28:45 blackbox-ng vdu_controls.desktop[44497]: 00:28:45 INFO: Configuring application (reconfiguring=True)...
oct 20 00:28:45 blackbox-ng vdu_controls.desktop[44497]: 00:28:45 DEBUG: configure: try to obtain application_configuration_lock
oct 20 00:28:45 blackbox-ng vdu_controls.desktop[44497]: 00:28:45 DEBUG: Holding application_configuration_lock
oct 20 00:28:45 blackbox-ng vdu_controls.desktop[44497]: 00:28:45 INFO: PresetTransitionWorker stopped on request
oct 20 00:28:45 blackbox-ng vdu_controls.desktop[44497]: 00:28:45 DEBUG: Enabled callback for VDU-connectivity-change D-Bus signals
oct 20 00:28:45 blackbox-ng ddcutil-service[17470]: Property ServiceEmitSignals is deprecated, please use ServiceEmitConnectivitySignals
oct 20 00:28:45 blackbox-ng ddcutil-service[17470]: ServiceEmitConnectivitySignals set property to enabled
oct 20 00:28:45 blackbox-ng ddcutil-service[17470]: ServiceEmitConnectivitySignals ddcutil-service polling every 30 seconds
oct 20 00:28:45 blackbox-ng vdu_controls.desktop[44497]: 00:28:45 INFO: ddcutil version (1, 4, 1) (dynamic-sleep=False) - interface 1.0.11 (D-Bus ddcutil-service - libddcutil)
oct 20 00:28:45 blackbox-ng vdu_controls.desktop[44497]: 00:28:45 DEBUG: Detecting connected monitors, looping detection until it stabilises.
oct 20 00:28:45 blackbox-ng vdu_controls.desktop[44497]: 00:28:45 DEBUG: checking possible IDs for display 1
oct 20 00:28:45 blackbox-ng vdu_controls.desktop[44497]: 00:28:45 DEBUG: Unique key for vdu_number='1' manufacturer='DEL' is (model_name='DELL_U2515H' main_id='YKFWP5990CQL')
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: checking possible IDs for display 1
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: Unique key for vdu_number='1' manufacturer='DEL' is (model_name='DELL_U2515H' main_id='YKFWP5990CQL')
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 INFO: Number of detected monitors is stable at 1 (loop=2)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 INFO: Initializing controls for vdu_number='1' vdu_model_name='DELL_U2515H' self.vdu_stable_id='DELL_U2515H_YKFWP5990CQL'
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: checking for config file '/home/jpbaril/.config/vdu_controls/DELL_U2515H_YKFWP5990CQL.conf'
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 INFO: Using config file '/home/jpbaril/.config/vdu_controls/DELL_U2515H_YKFWP5990CQL.conf'
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: config: DELL_U2515H_YKFWP5990CQL.conf [metadata] version = 2.1.0
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: config: DELL_U2515H_YKFWP5990CQL.conf [metadata] timestamp = 2024-10-10 21:20:08.186584-04:00
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: config: DELL_U2515H_YKFWP5990CQL.conf [vdu-controls-widgets] brightness = yes
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: config: DELL_U2515H_YKFWP5990CQL.conf [vdu-controls-widgets] contrast = yes
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: config: DELL_U2515H_YKFWP5990CQL.conf [vdu-controls-widgets] audio-volume = no
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: config: DELL_U2515H_YKFWP5990CQL.conf [vdu-controls-widgets] audio-mute = no
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: config: DELL_U2515H_YKFWP5990CQL.conf [vdu-controls-widgets] audio-treble = no
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: config: DELL_U2515H_YKFWP5990CQL.conf [vdu-controls-widgets] audio-bass = no
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: config: DELL_U2515H_YKFWP5990CQL.conf [vdu-controls-widgets] audio-mic-volume = no
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: config: DELL_U2515H_YKFWP5990CQL.conf [vdu-controls-widgets] input-source = no
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: config: DELL_U2515H_YKFWP5990CQL.conf [vdu-controls-widgets] power-mode = no
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: config: DELL_U2515H_YKFWP5990CQL.conf [vdu-controls-widgets] osd-language = no
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: config: DELL_U2515H_YKFWP5990CQL.conf [vdu-controls-widgets] color-preset = no
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: config: DELL_U2515H_YKFWP5990CQL.conf [vdu-controls-widgets] color-temperature = yes
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: config: DELL_U2515H_YKFWP5990CQL.conf [vdu-controls-widgets] enable-vcp-codes =
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: config: DELL_U2515H_YKFWP5990CQL.conf [ddcutil-parameters] sleep-multiplier = 0.0
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: config: DELL_U2515H_YKFWP5990CQL.conf [ddcutil-parameters] ddcutil-extra-args =
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: config: DELL_U2515H_YKFWP5990CQL.conf [ddcutil-capabilities] capabilities-override = Model: U2515H
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: MCCS version: 2.1
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: Commands:
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Op Code: 01 (VCP Request)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Op Code: 02 (VCP Response)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Op Code: 03 (VCP Set)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Op Code: 07 (Timing Request)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Op Code: 0C (Save Settings)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Op Code: E3 (Capabilities Reply)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Op Code: F3 (Capabilities Request)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: VCP Features:
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: 02 (New control value)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: 04 (Restore factory defaults)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: 05 (Restore factory brightness/contrast defaults)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: 08 (Restore color defaults)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: 10 (Brightness)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: 12 (Contrast)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: 14 (Select color preset)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:       Values:
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          04: 5000 K
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          0b: User 1
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          05: 6500 K
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          06: 7500 K
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          08: 9300 K
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          09: 10000 K
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          0c: User 2
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: 16 (Video gain: Red)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: 18 (Video gain: Green)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: 1A (Video gain: Blue)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: 52 (Active control)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: 60 (Input Source)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:       Values:
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          0f: DisplayPort-1
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          10: DisplayPort-2
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          11: HDMI-1
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          12: HDMI-2
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: AA (Screen Orientation)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:       Values:
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          01: 0 degrees
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          02: 90 degrees
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          04: 270 degrees
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: AC (Horizontal frequency)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: AE (Vertical frequency)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: B2 (Flat panel sub-pixel layout)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: B6 (Display technology type)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: C6 (Application enable key)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: C8 (Display controller type)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: C9 (Display firmware level)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: D6 (Power mode)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:       Values:
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          01: DPM: On,  DPMS: Off
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          04: DPM: Off, DPMS: Off
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          05: Write only value to turn off display
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: DC (Display Mode)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:       Values:
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          00: Standard/Default mode
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          02: Mixed
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          03: Movie
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:          05: Games
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: DF (VCP Version)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: E0 (Manufacturer specific feature)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: E1 (Manufacturer specific feature)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: E2 (Manufacturer specific feature)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:       Values: 00 01 02 04 14 19 0C 0D 0F 10 11 13 (interpretation unavailable)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: F0 (Manufacturer specific feature)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:       Values: 00 08 (interpretation unavailable)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: F1 (Manufacturer specific feature)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:       Values: 01 02 (interpretation unavailable)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: F2 (Manufacturer specific feature)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]:    Feature: FD (Manufacturer specific feature)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: Removed DELL_U2515H_YKFWP5990CQL audio-volume - not supported by VDU
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: Removed DELL_U2515H_YKFWP5990CQL audio-mute - not supported by VDU
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: Removed DELL_U2515H_YKFWP5990CQL audio-treble - not supported by VDU
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: Removed DELL_U2515H_YKFWP5990CQL audio-bass - not supported by VDU
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: Removed DELL_U2515H_YKFWP5990CQL audio-mic-volume - not supported by VDU
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: Removed DELL_U2515H_YKFWP5990CQL osd-language - not supported by VDU
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: Removed DELL_U2515H_YKFWP5990CQL color-temperature - not supported by VDU
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: Reading preset file '/home/jpbaril/.config/vdu_controls/Preset_Sunset.conf'
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: Reading preset file '/home/jpbaril/.config/vdu_controls/Preset_Morning.conf'
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: Reading preset file '/home/jpbaril/.config/vdu_controls/Preset_Evening.conf'
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: Reading preset file '/home/jpbaril/.config/vdu_controls/Preset_Winter_sun_zenith.conf'
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG:  hint_height=221 available_height=952 self.minimumHeight()=241
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: SingletonDialog exists SettingsEditor True
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 DEBUG: configure: released application_configuration_lock
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 INFO: Scheduling presets reconfiguring=True
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 INFO: Scheduled preset 'Morning' for 2024-10-20 07:26:47.655261-04:00 in 418 minutes SolarElevationKey(direction='eastern-sky', elevation=1)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 INFO: Scheduled preset 'Winter sun zenith' for 2024-10-20 09:37:47.655261-04:00 in 549 minutes SolarElevationKey(direction='eastern-sky', elevation=21)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 INFO: Scheduled preset 'Sunset' for 2024-10-20 17:51:47.655261-04:00 in 1043 minutes SolarElevationKey(direction='western-sky', elevation=0)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 INFO: Scheduled preset 'Evening' for 2024-10-20 18:49:47.655261-04:00 in 1101 minutes SolarElevationKey(direction='western-sky', elevation=-10)
oct 20 00:28:47 blackbox-ng vdu_controls.desktop[44497]: 00:28:47 INFO: Completed configuring application
oct 20 00:29:18 blackbox-ng ddcutil-service[17470]: Poll signal event - dpms changed to asleep 1 AP///////wAQrG/QTFFDMCUZAQSlNx...
oct 20 00:29:18 blackbox-ng vdu_controls.desktop[44497]: 00:29:18 INFO: Received display_change D-Bus signal message.arguments()=['AP///////wAQrG/QTFFDMCUZAQSlNx94PkRVqVVNnSYPUFSlSwCzANEAcU+pQIGAd4ABAQEBVl4AoKCgKVAwIDUAKTchAAAaAAAA/wBZS0ZXUDU5OTBDUUwKAAAA/ABERUxMIFUyNTE1SAogAAAA/QA4Vh5xHgEKICAgICAgAUE=', 1, 0] id(self)=138257481727248
oct 20 00:29:18 blackbox-ng vdu_controls.desktop[44497]: 00:29:18 INFO: Connected VDUs event DdcEventType.DPMS_ASLEEP flags=0 AP///////wAQrG/QTFFDMCUZAQSlNx...
oct 20 07:26:47 blackbox-ng vdu_controls.desktop[44497]: 07:26:47 INFO: Activating scheduled preset Morning transition=False
oct 20 07:26:47 blackbox-ng vdu_controls.desktop[44497]: 07:26:47 DEBUG: restore_preset: try to obtain application_configuration_lock
oct 20 07:26:47 blackbox-ng vdu_controls.desktop[44497]: 07:26:47 DEBUG: restore_preset: holding application_configuration_lock
oct 20 07:26:47 blackbox-ng vdu_controls.desktop[44497]: 07:26:47 DEBUG: Reading preset file '/home/jpbaril/.config/vdu_controls/Preset_Morning.conf'
oct 20 07:26:47 blackbox-ng vdu_controls.desktop[44497]: 07:26:47 DEBUG: WorkerThread: init PresetTransitionWorker from thread_pid()=44497
oct 20 07:26:47 blackbox-ng vdu_controls.desktop[44497]: 07:26:47 DEBUG: TransitionWorker: init preset.name='Morning' immediately=True
oct 20 07:26:47 blackbox-ng vdu_controls.desktop[44497]: 07:26:47 DEBUG: restore_preset: released application_configuration_lock
oct 20 07:26:47 blackbox-ng vdu_controls.desktop[44497]: 07:26:47 DEBUG: WorkerThread: class_name='PresetTransitionWorker' running in thread_pid()=134208 <bound method PresetTransitionWorker._perform_transition of <__main__.PresetTransitionWorker object at 0x7dbe998b4b00>>
oct 20 07:26:48 blackbox-ng vdu_controls.desktop[44497]: 07:26:48 DEBUG: set_vcp: vdu_number='1' vcp_code='10' new_value=40
oct 20 07:26:48 blackbox-ng vdu_controls.desktop[44497]: 07:26:48 DEBUG: set_vcp signals vcp_value_changed: DELL_U2515H_YKFWP5990CQL vcp_code='10' 40 VcpOrigin.TRANSIENT
oct 20 07:26:48 blackbox-ng vdu_controls.desktop[44497]: 07:26:48 DEBUG: SingletonDialog exists AboutDialog False
oct 20 07:26:48 blackbox-ng vdu_controls.desktop[44497]: 07:26:48 DEBUG: About dialog - no refresh - not visible
oct 20 07:26:48 blackbox-ng vdu_controls.desktop[44497]: 07:26:48 DEBUG: respond vdu_stable_id='DELL_U2515H_YKFWP5990CQL' vcp_code='10' value=40 VcpOrigin.TRANSIENT
oct 20 07:26:48 blackbox-ng vdu_controls.desktop[44497]: 07:26:48 INFO: Restored Morning, elapsed: 0.96 seconds 1 VCP-changes
oct 20 07:26:48 blackbox-ng vdu_controls.desktop[44497]: 07:26:48 DEBUG: WorkerThread: class_name='PresetTransitionWorker' terminating thread_pid()=134208
oct 20 09:37:47 blackbox-ng vdu_controls.desktop[44497]: 09:37:47 INFO: Activating scheduled preset Winter sun zenith transition=False
oct 20 09:37:47 blackbox-ng vdu_controls.desktop[44497]: 09:37:47 DEBUG: restore_preset: try to obtain application_configuration_lock
oct 20 09:37:47 blackbox-ng vdu_controls.desktop[44497]: 09:37:47 DEBUG: restore_preset: holding application_configuration_lock
oct 20 09:37:47 blackbox-ng vdu_controls.desktop[44497]: 09:37:47 DEBUG: Reading preset file '/home/jpbaril/.config/vdu_controls/Preset_Winter_sun_zenith.conf'
oct 20 09:37:47 blackbox-ng vdu_controls.desktop[44497]: 09:37:47 DEBUG: WorkerThread: init PresetTransitionWorker from thread_pid()=44497
oct 20 09:37:47 blackbox-ng vdu_controls.desktop[44497]: 09:37:47 DEBUG: TransitionWorker: init preset.name='Winter sun zenith' immediately=True
oct 20 09:37:47 blackbox-ng vdu_controls.desktop[44497]: 09:37:47 DEBUG: restore_preset: released application_configuration_lock
oct 20 09:37:47 blackbox-ng vdu_controls.desktop[44497]: 09:37:47 DEBUG: WorkerThread: class_name='PresetTransitionWorker' running in thread_pid()=137946 <bound method PresetTransitionWorker._perform_transition of <__main__.PresetTransitionWorker object at 0x7dbe998b4f80>>
oct 20 09:37:47 blackbox-ng vdu_controls.desktop[44497]: 09:37:47 DEBUG: set_vcp: vdu_number='1' vcp_code='10' new_value=100
oct 20 09:37:47 blackbox-ng vdu_controls.desktop[44497]: 09:37:47 DEBUG: set_vcp signals vcp_value_changed: DELL_U2515H_YKFWP5990CQL vcp_code='10' 100 VcpOrigin.TRANSIENT
oct 20 09:37:47 blackbox-ng vdu_controls.desktop[44497]: 09:37:47 DEBUG: SingletonDialog exists AboutDialog False
oct 20 09:37:47 blackbox-ng vdu_controls.desktop[44497]: 09:37:47 DEBUG: About dialog - no refresh - not visible
oct 20 09:37:47 blackbox-ng vdu_controls.desktop[44497]: 09:37:47 DEBUG: respond vdu_stable_id='DELL_U2515H_YKFWP5990CQL' vcp_code='10' value=100 VcpOrigin.TRANSIENT
oct 20 09:37:47 blackbox-ng vdu_controls.desktop[44497]: 09:37:47 INFO: Restored Winter sun zenith, elapsed: 0.56 seconds 1 VCP-changes
oct 20 09:37:47 blackbox-ng vdu_controls.desktop[44497]: 09:37:47 DEBUG: WorkerThread: class_name='PresetTransitionWorker' terminating thread_pid()=137946
oct 20 10:41:44 blackbox-ng vdu_controls.desktop[44497]: qt.qpa.wayland: Creating a fake screen in order for Qt not to crash
oct 20 10:42:07 blackbox-ng ddcutil-service[17470]: Poll signal event - dpms changed to awake 1 AP///////wAQrG/QTFFDMCUZAQSlNx...
oct 20 10:42:07 blackbox-ng vdu_controls.desktop[44497]: 10:42:07 INFO: Received display_change D-Bus signal message.arguments()=['AP///////wAQrG/QTFFDMCUZAQSlNx94PkRVqVVNnSYPUFSlSwCzANEAcU+pQIGAd4ABAQEBVl4AoKCgKVAwIDUAKTchAAAaAAAA/wBZS0ZXUDU5OTBDUUwKAAAA/ABERUxMIFUyNTE1SAogAAAA/QA4Vh5xHgEKICAgICAgAUE=', 0, 0] id(self)=138257481727248
oct 20 10:42:07 blackbox-ng vdu_controls.desktop[44497]: 10:42:07 INFO: Connected VDUs event DdcEventType.DPMS_AWAKE flags=0 AP///////wAQrG/QTFFDMCUZAQSlNx...
oct 20 10:42:07 blackbox-ng vdu_controls.desktop[44497]: 10:42:07 DEBUG: WorkerThread: init WorkerThread from thread_pid()=44497
oct 20 10:42:07 blackbox-ng vdu_controls.desktop[44497]: 10:42:07 DEBUG: WorkerThread: class_name='WorkerThread' running in thread_pid()=139972 <function VduAppController.start_refresh.<locals>.update_from_vdu at 0x7dbe94157ec0>
oct 20 10:42:07 blackbox-ng vdu_controls.desktop[44497]: 10:42:07 INFO: Refresh commences - acquired application_lock external_event=True
oct 20 10:42:07 blackbox-ng vdu_controls.desktop[44497]: 10:42:07 DEBUG: checking possible IDs for display 1
oct 20 10:42:07 blackbox-ng vdu_controls.desktop[44497]: 10:42:07 DEBUG: Unique key for vdu_number='1' manufacturer='DEL' is (model_name='DELL_U2515H' main_id='YKFWP5990CQL')
oct 20 10:42:08 blackbox-ng vdu_controls.desktop[44497]: 10:42:08 DEBUG: WorkerThread: class_name='WorkerThread' terminating thread_pid()=139972
oct 20 10:42:08 blackbox-ng vdu_controls.desktop[44497]: 10:42:08 DEBUG: Refresh - update UI view external_event=True
oct 20 10:42:43 blackbox-ng vdu_controls.desktop[44497]: 10:42:43 DEBUG: SingletonDialog exists PresetsDialog True
oct 20 10:42:43 blackbox-ng vdu_controls.desktop[44497]: 10:42:43 DEBUG: SingletonDialog show existing PresetsDialog
oct 20 10:42:43 blackbox-ng vdu_controls.desktop[44497]: qt.qpa.wayland: Wayland does not support QWindow::requestActivate()

I just logged in for the first time this morning few minutes ago (10:42) and the correct setting did apply. Looks like the combination of no initialization_preset + ddcutil-service might make it work as expected in the end. So, maybe there is no bug and no need to change the code. I'll continue to monitor my... monitor and report back.

jpbaril commented 1 month ago

In the last few days it seemed that everything was finally working perfectly. But today after I turned on my monitor and unlocked my session then the screen brightness was not adjusted and VDU_controls is still stuck on my 'night' preset.

Here are the logs for when I turned one the monitor few minutes ago.

oct 23 12:52:23 blackbox-ng vdu_controls.desktop[3431]: qt.qpa.wayland: Creating a fake screen in order for Qt not to crash
oct 23 12:52:30 blackbox-ng ddcutil-service[3936]: Poll signal event - dpms changed to awake 1 AP///////wAQrG/QTFFDMCUZAQSlNx...
oct 23 12:52:30 blackbox-ng vdu_controls.desktop[3431]: 12:52:30 INFO: Received display_change D-Bus signal message.arguments()=['AP///////wAQrG/QTFFDMCUZAQSlNx94PkRVqVVNnSYPUFSlSwCzANEAcU+pQIGAd4ABAQEBVl4AoKCgKVAwIDUAKTchAAAaAAAA/wBZS0ZXUDU5OTBDUUwKAAAA/ABERUxMIFUyNTE1SAogAAAA/QA4Vh5xHgEKICAgICAgAUE=', 0, 0] id(self)=128651785746000
oct 23 12:52:30 blackbox-ng vdu_controls.desktop[3431]: 12:52:30 INFO: Connected VDUs event DdcEventType.DPMS_AWAKE flags=0 AP///////wAQrG/QTFFDMCUZAQSlNx...
oct 23 12:52:30 blackbox-ng vdu_controls.desktop[3431]: 12:52:30 DEBUG: WorkerThread: init WorkerThread from thread_pid()=3431
oct 23 12:52:30 blackbox-ng vdu_controls.desktop[3431]: 12:52:30 DEBUG: WorkerThread: class_name='WorkerThread' running in thread_pid()=306472 <function VduAppController.start_refresh.<locals>.update_from_vdu at 0x750206035760>
oct 23 12:52:30 blackbox-ng vdu_controls.desktop[3431]: 12:52:30 INFO: Refresh commences - acquired application_lock external_event=True
oct 23 12:52:31 blackbox-ng vdu_controls.desktop[3431]: 12:52:31 DEBUG: checking possible IDs for display 1
oct 23 12:52:31 blackbox-ng vdu_controls.desktop[3431]: 12:52:31 DEBUG: Unique key for vdu_number='1' manufacturer='DEL' is (model_name='DELL_U2515H' main_id='YKFWP5990CQL')
oct 23 12:52:31 blackbox-ng vdu_controls.desktop[3431]: 12:52:31 DEBUG: WorkerThread: class_name='WorkerThread' terminating thread_pid()=306472
oct 23 12:52:31 blackbox-ng vdu_controls.desktop[3431]: 12:52:31 DEBUG: Refresh - update UI view external_event=True
digitaltrails commented 1 month ago

What time was the preset scheduled to change? What was logged around the time of the change?

jpbaril commented 1 month ago

Two presets should have applied: one at 7:27 (1° East) and one at 9:39 (21° East). There is no log at all around these times.

digitaltrails commented 1 month ago

There is no log at all around these times.

Was the machine powered off prior to, or at, these times?

Was there any vdu_controls logging prior to oct 23 12:52:23?

There may be a bug in identifying the preset that should be active at this time, but I'm not yet sure. I need to do more analysis and testing. But I'm not sure it explains the situation if the machine was on the whole time.

The existing code assumes that that it can trust its internal view of what has been changed in each VDU. It may be that this is not true. So as a second line of approach, I may look to reinitialize schedule state when DPMS state changes.

I need to be a bit careful, I don't want to repeat the mistakes of KDE6 where they are doing unexpected brightness changes due to assuming they know the state of the VDUs.

jpbaril commented 1 month ago

Was the machine powered off prior to, or at, these times?

No.

Was there any vdu_controls logging prior to oct 23 12:52:23?

They were at 1:46 when I suppose "screensaver" (shutting off the monitor) kicked in:

oct 23 01:46:31 blackbox-ng ddcutil-service[3936]: Poll signal event - dpms changed to asleep 1 AP///////wAQrG/QTFFDMCUZAQSlNx...
oct 23 01:46:31 blackbox-ng vdu_controls.desktop[3431]: 01:46:31 INFO: Received display_change D-Bus signal message.arguments()=['AP///////wAQrG/QTFFDMCUZAQSlNx94PkRVqVVNnSYPUFSlSwCzANEAcU+pQIGAd4ABAQEBVl4AoKCgKVAwIDUAKTchAAAaAAAA/wBZS0ZXUDU5OTBDUUwKAAAA/ABERUxMIFUyNTE1SAogAAAA/QA4Vh5xHgEKICAgICAgAUE=', 1, 0] id(self)=128651785746000
oct 23 01:46:31 blackbox-ng vdu_controls.desktop[3431]: 01:46:31 INFO: Connected VDUs event DdcEventType.DPMS_ASLEEP flags=0 AP///////wAQrG/QTFFDMCUZAQSlNx...
digitaltrails commented 1 month ago

That's weird, I would have expected to see schedule activation info messages at the set times. I would also have expected to info message about the scheduling of presets for the new day just after midnight.

I wonder if the Qt QTimer mechanism, or associated threads, can fail? Maybe I need to add code to check this somehow.

Platform issue? What Linux distro are you running? Presumably you're running the distro's KDE and Qt.

jpbaril commented 1 month ago

Ubuntu 24.10 (Gnome)

digitaltrails commented 1 month ago

I leaning toward treating the symptoms: assume threading or threading-coding errors exist, and should be automatically recovered from.

Question: after your system enters this state, but is no longer sleeping, if you do nothing, do later schedule presets get activated on time? The reason I ask, is that would indicate that the entire schedule isn't working. In which case, not only do I have to activate the expected preset, but I have to reinitialise the entire schedule (which is in some ways is simpler).

digitaltrails commented 1 month ago

Note to self: on DPMS wake, check the schedule times of presets, if they are not in the current day, then reschedule them all. The existing scheduling code will then also activate the appropriate preset. (This will be more economical that doing the scheduling regardless.)

Suspicion is that the daily reschedule is not always occuring.

digitaltrails commented 1 month ago

Suspicion is that the daily reschedule is not always occuring.

More notes:

Rewrite the single-shot QTimer change of day code. Use a subthread that periodically wakes up and checks for an out of date schedule or missing schedule. This should work across hibernate or anything else that keeps the app from firing a timer. During scheduling, also restore the preset that should be active at that time (if necessary).

This is a bit uglier: the app will keep waking up. The app is already waking up in the Qt event-loop, maybe we could piggyback off the Qt event-loop and not have another thread. (Is it possible something can lock out event-loop activity?)

jpbaril commented 1 month ago

Question: after your system enters this state, but is no longer sleeping, if you do nothing, do later schedule presets get activated on time? The reason I ask, is that would indicate that the entire schedule isn't working. In which case, not only do I have to activate the expected preset, but I have to reinitialise the entire schedule (which is in some ways is simpler).

Yesterday, when the preset was not correctly applied on waking up the computer I had to manually apply the correct preset but I noticed that later in the day the subsequent presets also did not get applied too. I had to completely close vdu_controls app and restart it. This morning the presets correctly got applied.

Logs since October 23 midnight: vdu_controls-logs.txt

digitaltrails commented 1 month ago

I noticed that later in the day the subsequent presets also did not get applied too. I had to completely close vdu_controls app and restart it. This morning the presets correctly got applied.

Kind of good news. My suspicions about maybe the schedule not being renewed at start-of-day seem to be correct. Which is just as well because I've begun a re-write of how the schedule gets renewed.

Thanks for the log. It looks like nothing was logged prior to 1:46, the schedule renews at around midnight. Also no schedule events were logged. [EDIT - I see the logs roll into a new day - I will keep reading... could be very interesting.]

I'm still coding and testing, I may push up a new version to truck later today or tomorrow. It will check what Preset should be active on any DPMS wakeup. It will also change how start-of-day is detected to something like what I described in my notes above.

What I'm still pondering, is how much to trust QTimer events? I think repeating timers seem trustworthy. I may add more boilerplate to check that the timer is actually running. The question is where/how to I detect that the timers have failed (what can I trust to run). Perhaps if the user presses refresh or on DPMS wakeup.

digitaltrails commented 1 month ago

This is interesting:

oct 23 23:59:59 blackbox-ng vdu_controls.desktop[336965]: 23:59:59 INFO: Scheduling presets reconfiguring=True

The above scheduling didn't schedule anything, where as the one below did:

oct 24 12:54:54 blackbox-ng vdu_controls.desktop[336965]: 12:54:54 INFO: Scheduling presets reconfiguring=True
oct 24 12:54:54 blackbox-ng vdu_controls.desktop[336965]: 12:54:54 INFO: Scheduled preset 'Coucher soleil' for 2024-10-24 17:44:54.271687-04:00 in 290 minutes SolarElevationKey(direction='western-sky', elevation=0)
oct 24 12:54:54 blackbox-ng vdu_controls.desktop[336965]: 12:54:54 INFO: Scheduled preset 'Soir' for 2024-10-24 18:43:54.271687-04:00 in 349 minutes SolarElevationKey(direction='western-sky', elevation=-10)

That's probably a bug in my code.

jpbaril commented 1 month ago

Even though I had always disabled power management so that my computer does not go to sleep, I just learned by experiencing it that newest Ubuntu and or Gnome do enable some power management... Maybe that does affect vdu_controls in the end.

digitaltrails commented 1 month ago

23:59:59 INFO: Scheduling presets

The timer is firing 1 second early, which means it will schedule for the wrong day. All Presets will be ineligible because there schedule time has already past.

The exact time might be a bit random, so some days this would happen at 00:00:?? other days at 23:59:??.

So perhaps I can trust the timers to fire, but not exactly on time. There is an option to make them more precise, but in this instance it's probably just easier/safer to do some kind of rounding-up.

OK - reverse back some of the mornings work. I'll try and rig up a test to confirm the above.

digitaltrails commented 1 month ago

Even though I had always disabled power management so that my computer does not go to sleep, I just learned by experiencing it that newest Ubuntu and or Gnome do enable some power management... Maybe that does affect vdu_controls in the end.

I will probably add a test somewhere that checks that the schedule is in place. That will be simpler than trusting a re-write of the current QTimer. I need to check if QTimers survive hibernate - I just read a suggestion that single-shot timers may survive, and currently this is a single shot timer that is replaced each day.

digitaltrails commented 1 month ago

76cc2fe will activate the preset that should be active now, or there isn't one, the last one that should have been active yesterday.

4cee91a the schedule-update now happens at 30 seconds after midnight. This hasn't been tested on a real end-of-day rollover. Might do something more precise, but this is a quick fix for now.

Still pondering what to do about hibernate.

jpbaril commented 1 month ago

Preset correctly applied today. FYI, logs since I launched yesterday's newest version. vdu-controls_logs_2024-10-25.txt

digitaltrails commented 1 month ago

Preset correctly applied today. FYI, logs since I launched yesterday's newest version.

Thanks for the new log. It looks like the new code is working, the timer again fired at 23:59:59 and the code corrected to the following day.

23:59:59 INFO: Scheduling presets, altering 2024-10-24 23:59:59.563409-04:00 to correct day 2024-10-25 00:00:00-04:00
oct 24 23:59:59 blackbox-ng vdu_controls.desktop[407631]: 23:59:59 INFO: Scheduling presets for 2024-10-25 00:00:00-04:00 reconfiguring=True
oct 24 23:59:59 blackbox-ng vdu_controls.desktop[407631]: 23:59:59 INFO: Scheduled preset 'Matin' for 2024-10-25 07:34:00-04:00 in 454 minutes SolarElevationKey(direction='eastern-sky', elevation=1)
oct 24 23:59:59 blackbox-ng vdu_controls.desktop[407631]: 23:59:59 INFO: Scheduled preset 'Zenith soleil hiver' for 2024-10-25 09:49:00-04:00 in 589 minutes SolarElevationKey(direction='eastern-sky', elevation=21)
oct 24 23:59:59 blackbox-ng vdu_controls.desktop[407631]: 23:59:59 INFO: Scheduled preset 'Coucher soleil' for 2024-10-25 17:44:00-04:00 in 1064 minutes SolarElevationKey(direction='western-sky', elevation=0)
oct 24 23:59:59 blackbox-ng vdu_controls.desktop[407631]: 23:59:59 INFO: Scheduled preset 'Soir' for 2024-10-25 18:42:00-04:00 in 1122 minutes SolarElevationKey(direc

I've reversed out some of the other changes so as not to interfere with changes made manually by the user. But I left in a sanity check, on DPMS wake, if there is no schedule and there should be, then rescheduling is performed and the appropriate Preset is restored.

digitaltrails commented 1 month ago

Your Presets appear to have French names. Are you using the translations enabled setting to pick up the the translation via locale settings? When enabled the LC_ALL and LANGUAGE environment variables determine the translation (providing the translations are installed).

LC_ALL=fr_FR LANGUAGE=fr_FR vdu_controls

The reason I ask is that in the last release I stopped updating the translations. The translations are from DeepL and google-translate. No one has complained about their phrasing or grammer, so I assumed no one was using them. I'm happy to update them, but only if they are in use.

jpbaril commented 1 month ago

They have French names because I labelled them as so since I speak French.

digitaltrails commented 1 month ago

They have French names because I labelled them as so since I speak French.

I guessed that. I thought I'd ask if you are also using the setting translations enabled?

Because:

The reason I ask is that in the last release I stopped updating the translations.

jpbaril commented 1 month ago

No, not using it (and had not noticed it anyway).

digitaltrails commented 1 month ago

No, not using it (and had not noticed it anyway).

OK, thanks. I'll continue to not update the translations until someone complains, or I run out of things to do on a rainy day.

jpbaril commented 1 month ago

Preset did NOT get correctly applied today. Logs since my previous log file. vdu-controls_logs_2024-10-26.txt

digitaltrails commented 1 month ago

It looks like the timer did not trigger at midnight. I wonder how that could happen. It seems like there is more than one issue at play. Fixing the 23:59:59 aspect of the problem has only addressed one of them. Back to: maybe the system was in some kind of sleep/hibernate; or maybe I can't trust this timer (which raises the issue of what can I trust).

oct 25 23:43:54 blackbox-ng vdu_controls.desktop[407631]: 23:43:54 INFO: activate_overdue_preset: searching schedule for preset that should be active now...
oct 25 23:43:54 blackbox-ng vdu_controls.desktop[407631]: 23:43:54 INFO: activate_overdue_preset: skipped - already active Soir
oct 26 02:37:20 blackbox-ng ddcutil-service[3936]: Poll signal event - dpms changed to asleep 1 AP///////wAQrG/QTFFDMCUZAQSlNx...
oct 26 02:37:20 blackbox-ng vdu_controls.desktop[407631]: 02:37:20 INFO: Received display_change D-Bus signal message.arguments()=['AP///////wAQrG/

Are you running the latest code? I added check_preset_schedule() call at https://github.com/digitaltrails/vdu_controls/blob/42c42e0f6b826b84c6a8687a43ffc910ac6b7992/vdu_controls.py#L7710

I thought it would trigger on the DPMS wake, but it hasn't logged anything.

jpbaril commented 1 month ago

Oh, I had not noticed you made more changes yesterday. I was still on version of two days ago. I now downloaded version of commit 42c42e0 and will report back.

digitaltrails commented 1 month ago

Oh, I had not noticed you made more changes yesterday.

Sorry, I probably should have noted it here.

digitaltrails commented 3 weeks ago

According to this answer:

https://stackoverflow.com/questions/8229916/how-system-timers-timer-behave-in-wpf-application-after-hibernate-and-sleep

If vdu_controls is ever put into hibernation, any long run qtimer will be delayed by the amount of time slept. A sleep of n ms becomes n + h where h is the amount of time spent hibernating. I need to stop using qtimers for the daily re-scheduling and for the time of solar activated changes.

I need to implement a polling scheduler that wakes every minute or so and checks if it's past time to trigger events in an event queue. Some events need to override other events in the queue, for example, only the most recently due solar elevation change should apply.

The easiest way to implement this would be to mirror the qtimer interface so the existing code doesn't require refactoring.

jpbaril commented 3 weeks ago

So far so good. (still on commit https://github.com/digitaltrails/vdu_controls/commit/42c42e0f6b826b84c6a8687a43ffc910ac6b7992) vdu-controls_logs_2024-10-31.txt I think I could then close this issue.

digitaltrails commented 3 weeks ago

I think I could then close this issue.

Please leave it open, I have a bit more work to do.

I've done some searching on how hibernate affects QTimers (see https://github.com/digitaltrails/vdu_controls/issues/96#issuecomment-2448165194). Basically QtTimers are delayed by the length of each hibernate and will trigger late. This creates issues for those using ddcutil-command (rather than ddcutil-service) - because there is no DPMS wake event possible when using ddcutil-command.

I'm going to reimplement the scheduler using a loop and short-sleep approach so I can trigger when HH:MM:SS match (where as the QTimers trigger after ms delays).

So, for now, you're good to go with ddcutil-service and the DPMS-wake event, but I will rework to cover those using ddcutil-command.

jpbaril commented 3 weeks ago

Ok. BTW, I would make it clearer in the documentation what are the benefits of using the ddcutil-service vs the ddcutil command, i.e. that it will make the scheduling more robust in the context of power management services. I had read that the ddcutil-service was "faster and more responsive than the older command-based implementation" but honestly that's intangible and it seemed to work good enough without it so I thought "Why bother installing an additional component if it already works good enough?". Now I know a big advantage but back then it was not obvious.

digitaltrails commented 3 weeks ago

Ok. BTW, I would make it clearer in the documentation what are the benefits of using the ddcutil-service vs the ddcutil command, i.e. that it will make the scheduling more robust in the context of power management services. I had read that the ddcutil-service was "faster and more responsive than the older command-based implementation" but honestly that's intangible and it seemed to work good enough without it so I thought "Why bother installing an additional component if it already works good enough?". Now I know a big advantage but back then it was not obvious.

I hope to make scheduling work well for both. But it's worth documenting that ddcutil-service is the only one that reacts to DPMS-Wake - will do so.

digitaltrails commented 2 weeks ago

I've reimplemented the Preset scheduler. The new code wakes every minute and checks the YYYY/MM/DD HH:MM:SS datetime. This replaces the Qtimer based implementation that scheduled presets in milliseconds, which broke if hibernation stopped the QTimer millisecond countdown.

All the previous fixes and complexities had either been removed or implemented in a different way.

When it wakes periodically, or after PC power-up, or after PC wake-up, the behaviour of the scheduler is to always find and restore the most recently overdue preset based on wallclock time. If there is not yet an overdue preset, the scheduler finds the last preset from the previous day. (By overdue I mean a Preset scheduled for a time less than or equal to now).

This new implementation does not rely on DPMS events to detect/fix hibernation delays. It just checks the wall-clock every minute, so it will automatically recover after hibernation (or power-outage or vdu_controls not running).