Bug 78200

After update to kernel 3.14.2-1-ARCH the corresponding section of the journal is:

May 02 20:32:34 samsung1 systemd[1]: Starting system-systemd\x2dbacklight.slice.
May 02 20:32:34 samsung1 systemd[1]: Created slice system-systemd\x2dbacklight.slice.
May 02 20:32:34 samsung1 systemd[1]: Starting Load/Save Screen Backlight Brightness of backlight:intel_backlight...
May 02 20:32:35 samsung1 kernel: microcode: CPU1 sig=0x6e8, pf=0x20, revision=0x39
May 02 20:32:35 samsung1 kernel: microcode: Microcode Update Driver: v2.00 <tigran@aivazian.fsnet.co.uk>, Peter Oruba
May 02 20:32:35 samsung1 kernel: psmouse serio4: synaptics: Touchpad model: 1, fw: 6.2, id: 0x25a0b1, caps: 0xa04713/0x200000/0x0, board
May 02 20:32:35 samsung1 kernel: input: SynPS/2 Synaptics TouchPad as /devices/platform/i8042/serio4/input/input16
May 02 20:32:35 samsung1 kernel: mousedev: PS/2 mouse device common for all mice
May 02 20:32:35 samsung1 systemd[1]: Started Load/Save RF Kill Switch Status of rfkill0.
May 02 20:32:35 samsung1 systemd[1]: Started Load/Save Screen Backlight Brightness of backlight:intel_backlight.

The screen dims to an unusable, but not quite black, level during the early phases of boot.

If I use the Fn+up arrow key clicked once only the brightness returns to full but a short time later it dims again when the login screen for KDE is presented. I can use the keyboard to again return the brightness to full, and can then login to KDE. At the point where KDE is logged in the screen again dims to unusable, but I can still use the keyboard to set the brightness up again.

I have systemd as a mkinitcpio hook, and I will replace that with udev and base and see if that makes any difference.

Changing mkinicpio made no difference.

I have also tried adding acpi_osi=Linux acpi_backlight=vendor to the kernel line for boot and that makes no difference either.

Also with kernel 3.14.2-1-ARCH after increasing the brightness once logged in to KDE so that I can work the brightness parameters are:

# ls -1 /sys/class/backlight/intel_backlight/*brightness | xargs -I % sh -c "echo % ; cat %"
/sys/class/backlight/intel_backlight/actual_brightness
3793125
/sys/class/backlight/intel_backlight/brightness
14875
/sys/class/backlight/intel_backlight/max_brightness
3793125

May be related to https://bugzilla.kernel.org/show_bug.cgi?id=72491

This sounds like userspace being silly. But can you check to see which commit makes the difference in the kernel? Also a drm.debug=6 should capture the backlight values as they are changed - I guess reporting the pid would help in this case though.

Created attachment 98558 [details]
systemd journal log when booted with drm.debug=6

Responding to comment #5 here is the system log for drm.debug=6 but I was not sure which PID was requested i.e. for which process? I will attach the output of ps -eaf as a file next.

Created attachment 98559 [details]
Output of ps -eaf after logging in to KDE

ps -eaf output to possible provide PID info for the journal log if this helps

Brightness parameters after the two attachments sent are:

$ ls -1 /sys/class/backlight/intel_backlight/*brightness | xargs -I % sh -c "echo % ; cat %"
/sys/class/backlight/intel_backlight/actual_brightness
3544500
/sys/class/backlight/intel_backlight/brightness
13900
/sys/class/backlight/intel_backlight/max_brightness
3793125

I am not set up for kernel bisect and the machine concerned is very slow. It would be nice to know the commit responsible but maybe the other data I posted will help.

(In reply to comment #0)
> I reverted to kernel 3.13.7-1-ARCH and the screen brightness seemed normal
> but an investigation of the systemd journal showed there were errors that
> are relevant to this issue:
> 
> May 02 17:08:49 samsung1 systemd[1]: Starting Load/Save Screen Backlight
> Brightness of backlight:intel_backlight...
> May 02 17:08:49 samsung1 systemd-backlight[191]: Failed to write system
> attribute: Invalid argument
> May 02 17:08:49 samsung1 systemd[1]:
> systemd-backlight@backlight:intel_backlight.service: main process exited,
> code=exited, status=1/FAI
> May 02 17:08:49 samsung1 systemd[1]: Failed to start Load/Save Screen
> Backlight Brightness of backlight:intel_backlight.
> May 02 17:08:49 samsung1 systemd[1]: Unit
> systemd-backlight@backlight:intel_backlight.service entered failed state.

Looking at the systemd source, it seems to me this happens because there's a too high saved value for backlight. I don't know how it got there, but the clamping and error handling don't take this into account. Try removing, uh, the relevant looking files from /var/lib/systemd/backlight/ - there should be file(s) containing the saved values, named with escaped names of the interfaces.

If that doesn't help, try systemd.restore_state=0 on the kernel command line. There may be a way to pass that to systemd directly too, but I'm rather clueless about systemd details. Let us know if that helps.

Finally, please try 3.15-rc kernels; I think there's a fix or two there that haven't propagated to stable kernels yet.

Oh, and the systemd failure to restore the saved backlight value might be the reason 3.13 works for you!

There was a single file in /var/lib/systemd/backlight/ which I deleted - on rebooting the symptoms were the same as before, and the file was recreated.

I also booted with systemd.restore_state=0 on the kernel line, and this did make a difference in that the brightness then remained full until and including when the KDM login greeter was on the screen, but once I entered the user password the screen then dimmed, as before, between entering the login details and the user being logged in to the KDE desktop. Again using the keyboard Fn+up arrow just once restores the brightness.

There was a boot error on the screen during this test with the systemd failure to save/restore but it went past quickly so I will attach the journal log shortly soon after the boot and login.

This was with kernel 3.14.2-1-ARCH.  I had previously built kernel 3.15rc3-1 and tested on the same laptop but it made no difference to the screen dimming issue. (It takes over three hours to build a kernel on that machine and I have no other 32 bit machine to run builds for that architecture.)  So unless there has been commits that might provide a fix since rc3 then I guess that this issue remains unresolved.

I am still not clear if this is a kernel issue or a systemd issue? However the same version of systemd gave a working system for the earlier 3.13 kernels and a broken system with 3.14 and 3.15 so maybe the answer lies in the kernel?

Created attachment 98613 [details]
systemd journal log when systemd.restore_state=0

(In reply to comment #13)
> Created attachment 98613 [details]
> systemd journal log when systemd.restore_state=0

Please do this with drm.debug=0xe module parameter to get useful logging from the driver.

Created attachment 98630 [details]
system log for drm.debug=0xe systemd.restore_state=0

This is with kernel 3.14.2-1 as before

The addition of systemd.restore_state does actually fix the issue - the behaviour of the screen dimming after entering the KDE login info is my fault and due to a file that I had previously set up to execute on KDE login which sets the screen brightness - but the numerical value that goes into the command I have changed to:

echo 3793125  > /sys/class/backlight/intel_backlight/brightness

and this works fine as this value is the same as the max brightness.

The value previously was originally very low, but matched the max brightness parameter that used to be listed in the same directory, and so dimmed the screen - it seems that in one of the recent updates presumably to the kernel the max brightness numerical value increased by over a factor of 20 and therefore the value I had set during KDE login was no longer appropriate.

However during the boot process without the kernel parameter systemd.restore_state=0 the screen still dims to almost black soon after the initial hard drive fsck lines on the screen, so the workaround gets the brightness working through the boot and through the desktop login, but without it the brightness problem remains.

I will upload a new journal log shortly.

Executing the command as root:
echo 3413812  > /sys/class/backlight/intel_backlight/brightness

dims the screen a little as expected.

Created attachment 98633 [details]
system log for drm.debug=0xe systemd.restore_state=0

System log with systemd.restore_state=0 and drm debug which gives normal brightness throughout boot and through to KDE login.

brightness Load/save error was still visible during boot.

This bug is resolved and was indeed due to the script that I had executing during KDE login that set the screen brightness. After changing my kde script and rebooting an appropriate brightness value was stored, and then used at next login.

After making the change to my script and rebooting the brightness no longer exhibited a problem.

Therefore there is no kernel or systemd bug, and I will close this report as resolved.

The problem that led to my confusion was that at some point a kernel update changed the max_brightness value from the driver for my system, but my original script set the brightness at login numerically and this value became inappropriate after the kernel change.  However using the Fn + Up Arrow keys did not reset the value in /sys/class/backlight/intel_backlight/brightness despite the screen becoming normal brightness, and so this low value persisted when systemd saved the current value and restored it at next boot.

Sorry it took me so long to recognise that it was my kde script that was causing the symptoms.

(In reply to comment #18)
> Therefore there is no kernel or systemd bug, and I will close this report as
> resolved.
> 
> The problem that led to my confusion was that at some point a kernel update
> changed the max_brightness value from the driver for my system

This is likely because of the fix

commit b6ab66aa5d376583a17137cbb2d3a728f29acae2
Author: Jani Nikula <jani.nikula@intel.com>
Date:   Tue Feb 25 13:11:47 2014 +0200

    drm/i915: use backlight legacy combination mode also for i915gm/i945gm

which would have that effect, and it matches your platform.

I think you trying different kernel versions with and without that patch lead to systemd saving and then using out of range saved brightness value on 3.13. I think it's a bug in systemd, while it's not the root cause here. I sent a bug report in the disguise of a patch to systemd [1] to fix this:

http://mid.gmane.org/1399453261-31967-1-git-send-email-jani.nikula@intel.com

> However using the Fn + Up
> Arrow keys did not reset the value in
> /sys/class/backlight/intel_backlight/brightness despite the screen becoming
> normal brightness, and so this low value persisted when systemd saved the
> current value and restored it at next boot.

This is probably due to ACPI handling the keys. Depending on the BIOS on your system, it's possible we sync that to the intel_backlight brightness too in recent kernels.

> Sorry it took me so long to recognise that it was my kde script that was
> causing the symptoms.

No worries. Thanks for following up, and I'm glad you figured it out.

Thank you Jani for sending the systemd patch and hopefully that will get followed up.

Patch applied in http://cgit.freedesktop.org/systemd/systemd/commit/?id=0c9d8f1d/

Looking at the link in #21 there is a message "Bad object id: 0c9d8f1d/" - I guess it is a simple error to fix.

(In reply to comment #22)
> Looking at the link in #21 there is a message "Bad object id: 0c9d8f1d/" - I
> guess it is a simple error to fix.

http://cgit.freedesktop.org/systemd/systemd/commit/?id=0c9d8f1d