Bug 91191

Summary: APIC error on CPU0: 80 : Illegal register address - AMD A6-3400M APU with Radeon(tm) HD Graphics
Product: ACPI Reporter: abandoned account (abandonedaccountubdprczb8hs)
Component: Power-VideoAssignee: Aaron Lu (aaron.lu)
Status: CLOSED WILL_NOT_FIX    
Severity: low CC: aaron.lu, abandonedaccountubdprczb8hs, icanrealizeum+bugzillakernelorg, lenb
Priority: P1    
Hardware: x86-64   
OS: Linux   
Kernel Version: 3.18-rc2 -> 3.19.0 Subsystem:
Regression: No Bisected commit-id:
Attachments: dmesg 3.19-rc4
dmesg with less cmdline params
current Xorg.0.log
the 3.19-rc5 log
# acpidump
current dmesg, kernel 3.19.0
dmesg with acpi_video=vendor
dmesg with acpi_backlight=vendor

Description abandoned account 2015-01-12 01:16:36 UTC
Created attachment 163241 [details]
dmesg 3.19-rc4

Executing this:
$ setterm --blank force; sleep 5; setterm --blank poke                          
[  619.238107] APIC error on CPU0: 80 : Illegal register address
[  624.320057] APIC error on CPU0: 80 : Illegal register address
shows that error(twice).

This happens earlier in the boot process too, at about seconds 0.6 and 11.

journalctl logs show that this error happened on 3.19-rc3 , and even as back as 3.18.0-rc2-gcac7f24 (I don't have an earlier log than this) and the same is true for those
i2c_outb: 0xa0, timeout at bit #7
errors, but that's probably radeon related(?)

Dmesg log included.


unrelated (skip this):
The reason why I noticed this is because I was unable to wake up my display with 3.19-rc4 kernel (but worked fine so far with 3.19-rc3 one) while in X and after being away from the keyboard for like an hour. I couldn't unblank it by pressing keys and moving mouse, only the SysRq unmount and boot(tested only these 2) keys worked, mouse and any other keys seemed to have no effect and I had tried switching to other consoles Ctrl+Alt+F2 and Ctrl+Alt+Del keys even trying to start new urxvt terminals(via key shortcuts) and typing reboot, and even logging in from virtual consoles  to no effect. I'll report a new bug when I figure out what's the issue with this one.
Comment 1 abandoned account 2015-01-12 01:41:31 UTC
I've reported the unrelated bug(mentioned above ^ in comment #1 ) here: https://bugzilla.kernel.org/show_bug.cgi?id=91201
I'm only mentioning this for consistency purposes.
Comment 2 Len Brown 2015-01-13 02:21:56 UTC
dmesg shows a lot of non-default cmdline params, including forcing on ASPM.
do you still see these errors in the default configuration?
Comment 3 abandoned account 2015-01-13 06:38:13 UTC
Created attachment 163391 [details]
dmesg with less cmdline params

The errors are still there even without those cmdline params. I've still left the logging ones. If I omit apic=debug I might not see the error (haven't tried)

Current cmdline params:

ipv6.disable=1
pnp.debug=1
loglevel=9
log_buf_len=10M
printk.always_kmsg_dump=y
printk.time=y
mminit_loglevel=0
memory_corruption_check=1
fbcon=scrollback:4096k
fbcon=font:ProFont6x11
apic=debug
earlyprintk=vga

Error, same:

APIC error on CPU0: 80 : Illegal register address
Comment 4 abandoned account 2015-01-14 19:40:00 UTC
I have just found out that whenever I press Fn+UpArrow and Fn+DownArrow I get the same error instantly. They are the keys for increase/decrease monitor brightness(backlight).

So maybe it's related to the radeon driver completely?
Comment 5 abandoned account 2015-01-14 20:00:43 UTC
If I am in a virtual console, looks like this:
[   39.233443] APIC error on CPU0: 80 : Illegal register address
[   41.177064] APIC error on CPU0: 80 : Illegal register address
[   43.028550] APIC error on CPU0: 80 : Illegal register address
[   43.616698] APIC error on CPU0: 80 : Illegal register address
[   44.026689] APIC error on CPU0: 80 : Illegal register address
[   44.465847] APIC error on CPU0: 80 : Illegal register address
[   44.855502] APIC error on CPU0: 80 : Illegal register address
[   45.195625] APIC error on CPU0: 80 : Illegal register address

If I am in X, looks like this(only when a change in brightness happens):
[ 1301.472424] pkexec[4579]: pam_unix(polkit-1:session): session opened for user
 root by (uid=1000)
[ 1301.477273] pkexec[4579]: emacs: Executing command [USER=root] [TTY=unknown] 
[CWD=/] [COMMAND=/usr/bin/xfpm-power-backlight-helper --set-brightness 9]
[ 1301.505924] APIC error on CPU0: 80 : Illegal register address
[ 1301.930440] pkexec[4586]: pam_unix(polkit-1:session): session opened for user
 root by (uid=1000)
[ 1301.934708] pkexec[4586]: emacs: Executing command [USER=root] [TTY=unknown] 
[CWD=/] [COMMAND=/usr/bin/xfpm-power-backlight-helper --set-brightness 8]
[ 1301.963893] APIC error on CPU0: 80 : Illegal register address
[ 1302.196348] pkexec[4591]: pam_unix(polkit-1:session): session opened for user
 root by (uid=1000)
[ 1302.197808] pkexec[4591]: emacs: Executing command [USER=root] [TTY=unknown] 
[CWD=/] [COMMAND=/usr/bin/xfpm-power-backlight-helper --set-brightness 9]
[ 1302.231894] APIC error on CPU0: 80 : Illegal register address
[ 1302.418712] pkexec[4596]: pam_unix(polkit-1:session): session opened for user
 root by (uid=1000)
[ 1302.420515] pkexec[4596]: emacs: Executing command [USER=root] [TTY=unknown] 
[CWD=/] [COMMAND=/usr/bin/xfpm-power-backlight-helper --set-brightness 10]
[ 1302.447731] APIC error on CPU0: 80 : Illegal register address
Comment 6 Aaron Lu 2015-01-16 02:56:01 UTC
Please check which backlight interface the X is using in /var/log/Xorg.0.log

Also, if you directly change the brightness file, will such error occur?
# cd /sys/class/backlight/radeon?
# cat max_brightness
# echo a_value_smaller_than_max_brightness > brightness
Comment 7 abandoned account 2015-01-16 05:27:10 UTC
Created attachment 163581 [details]
current Xorg.0.log

I don't see any mention of backlight in Xorg.0.log but I am including it here.
In dmesg however I see something(radeon atom DIG backlight ?) which I paste here:

[    0.197848] device class 'backlight': registering
[    1.360959] [drm] radeon atom DIG backlight initialized
[   11.922760] systemd[1]: Starting system-systemd\x2dbacklight.slice.
[   11.961366] systemd[1]: Created slice system-systemd\x2dbacklight.slice.
[   11.981589] systemd[1]: Starting Load/Save Screen Backlight Brightness of backlight:acpi_video0...
[   12.017303] systemd[1]: Starting Load/Save Screen Backlight Brightness of backlight:radeon_bl0...
[   12.073454] systemd[1]: Started Load/Save Screen Backlight Brightness of backlight:acpi_video0.
[   12.108095] systemd[1]: Started Load/Save Screen Backlight Brightness of backlight:radeon_bl0.
[   15.961722] thinkpad_acpi: Standard ACPI backlight interface available, not loading native one
[   24.992104] pkexec[3949]: emacs: Executing command [USER=root] [TTY=unknown] [CWD=/] [COMMAND=/usr/bin/xfpm-power-backlight-helper --set-brightness-switch 0]
[   34.757180] pkexec[3991]: emacs: Executing command [USER=root] [TTY=unknown] [CWD=/] [COMMAND=/usr/bin/xfpm-power-backlight-helper --set-brightness-switch 1]
[   37.797145] pkexec[4133]: emacs: Executing command [USER=root] [TTY=unknown] [CWD=/] [COMMAND=/usr/bin/xfpm-power-backlight-helper --set-brightness-switch 0]


Interestingly changing brightness as you noted, doesn't generate the errors:
# cd /sys/class/backlight/radeon_bl0/
# cat max_brightness 
255
# echo "200" > brightness
# cat brightness 
200
The brightness was visibly changed, however no errors on dmesg|tail .

Now, there's another brightness which DOES generate the error:
# cd /sys/class/backlight/acpi_video0
# echo '9' > brightness
# dmesg|tail
...
[24951.307524] APIC error on CPU0: 80 : Illegal register address
(the brightness is visibly changed and affected though)

even setting the same value: 9  generates a new error:
# echo '9' > brightness
...
[24951.307524] APIC error on CPU0: 80 : Illegal register address
[24990.043742] APIC error on CPU0: 80 : Illegal register address

Also the acpi_video0/brightness and radeon_bl0/brightness are not sync-ed: if you set one, the other remains as it is, even though both have visible effect on the brightness. I guess this makes some sense.

I guess to answer your question, seems that X uses acpi_video0 (10 steps - check; acpi error - check)

Thank.
Comment 8 abandoned account 2015-01-18 13:44:58 UTC
Got some extra debug:

[ 5054.941313] backlight: set brightness to 9
[ 5054.942356] ACPI : EC: ***** Command(UNDEF) started *****
[ 5054.942363] ACPI : EC: ===== TASK (1) =====
[ 5054.942417] ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
[ 5054.942422] ACPI : EC: EC_SC(W) = 0x80
[ 5054.943099] ACPI : EC: ===== TASK (2) =====
[ 5054.943165] ACPI : EC: EC_SC(R) = 0x0a SCI_EVT=0 BURST=0 CMD=1 IBF=1 OBF=0
[ 5054.945276] ACPI : EC: ===== IRQ (2) =====
[ 5054.945294] ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
[ 5054.945300] ACPI : EC: EC_DATA(W) = 0x7f
[ 5054.945308] ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[ 5054.946302] ACPI : EC: ===== TASK (3) =====
[ 5054.946318] ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[ 5054.948262] ACPI : EC: ===== IRQ (3) =====
[ 5054.948269] ACPI : EC: EC_SC(R) = 0x01 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=1
[ 5054.948275] ACPI : EC: EC_DATA(R) = 0x08
[ 5054.948286] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5054.948306] ACPI : EC: ***** Command(UNDEF) stopped *****
[ 5054.948314] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5054.948554] ACPI : EC: ***** Command(UNDEF) started *****
[ 5054.948559] ACPI : EC: ===== TASK (3) =====
[ 5054.948565] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5054.948569] ACPI : EC: EC_SC(W) = 0x80
[ 5054.949608] ACPI : EC: ===== TASK (1) =====
[ 5054.949627] ACPI : EC: EC_SC(R) = 0x0a SCI_EVT=0 BURST=0 CMD=1 IBF=1 OBF=0
[ 5054.950971] ACPI : EC: ===== IRQ (2) =====
[ 5054.950988] ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
[ 5054.950994] ACPI : EC: EC_DATA(W) = 0x83
[ 5054.951003] ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[ 5054.952942] ACPI : EC: ===== TASK (2) =====
[ 5054.952951] ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[ 5054.953914] ACPI : EC: ===== IRQ (3) =====
[ 5054.953924] ACPI : EC: EC_SC(R) = 0x01 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=1
[ 5054.953930] ACPI : EC: EC_DATA(R) = 0x0a
[ 5054.953942] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5054.953979] ACPI : EC: ***** Command(UNDEF) stopped *****
[ 5054.953987] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5054.954057] ACPI : EC: ***** Command(UNDEF) started *****
[ 5054.954061] ACPI : EC: ===== TASK (3) =====
[ 5054.954096] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5054.954100] ACPI : EC: EC_SC(W) = 0x81
[ 5054.956215] ACPI : EC: ===== TASK (3) =====
[ 5054.956227] ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
[ 5054.956231] ACPI : EC: EC_DATA(W) = 0x83
[ 5054.956633] ACPI : EC: ===== IRQ (2) =====
[ 5054.956643] ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[ 5054.956650] ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[ 5054.958383] ACPI : EC: ===== IRQ (1) =====
[ 5054.958400] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5054.958406] ACPI : EC: EC_DATA(W) = 0x09
[ 5054.958414] ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[ 5054.959668] ACPI : EC: ===== TASK (0) =====
[ 5054.959686] ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[ 5054.961389] ACPI : EC: ===== IRQ (3) =====
[ 5054.961403] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5054.961430] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5054.961453] ACPI : EC: ***** Command(UNDEF) stopped *****
[ 5054.961472] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5054.964767] APIC error on CPU0: 80 : Illegal register address


This is what happens when I do:
# echo '9' > /sys/class/backlight/acpi_video0/brightness

The debug was set priorly by:
# echo 'file drivers/video/backlight/* +p' > /sys/kernel/debug/dynamic_debug/control
# echo 'file drivers/acpi/* +p' > /sys/kernel/debug/dynamic_debug/control

which only has effect when kernel option CONFIG_DYNAMIC_DEBUG=y

Here's when setting brightness back to 10:
echo '10' > /sys/class/backlight/acpi_video0/brightness 

[ 5267.042968] backlight: set brightness to 10
[ 5267.044026] ACPI : EC: ***** Command(UNDEF) started *****
[ 5267.044033] ACPI : EC: ===== TASK (3) =====
[ 5267.044041] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5267.044046] ACPI : EC: EC_SC(W) = 0x80
[ 5267.046440] ACPI : EC: ===== TASK (0) =====
[ 5267.046457] ACPI : EC: EC_SC(R) = 0x0a SCI_EVT=0 BURST=0 CMD=1 IBF=1 OBF=0
[ 5267.047029] ACPI : EC: ===== IRQ (3) =====
[ 5267.047044] ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
[ 5267.047050] ACPI : EC: EC_DATA(W) = 0x7f
[ 5267.047059] ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[ 5267.049904] ACPI : EC: ===== IRQ (3) =====
[ 5267.049921] ACPI : EC: EC_SC(R) = 0x01 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=1
[ 5267.049929] ACPI : EC: EC_DATA(R) = 0x08
[ 5267.049941] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5267.049951] ACPI : EC: ***** Command(UNDEF) stopped *****
[ 5267.049966] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5267.050207] ACPI : EC: ***** Command(UNDEF) started *****
[ 5267.050222] ACPI : EC: ===== TASK (1) =====
[ 5267.050234] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5267.050238] ACPI : EC: EC_SC(W) = 0x80
[ 5267.052852] ACPI : EC: ===== IRQ (3) =====
[ 5267.052862] ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
[ 5267.052866] ACPI : EC: EC_DATA(W) = 0x83
[ 5267.052874] ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[ 5267.056023] ACPI : EC: ===== IRQ (3) =====
[ 5267.056032] ACPI : EC: EC_SC(R) = 0x01 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=1
[ 5267.056038] ACPI : EC: EC_DATA(R) = 0x09
[ 5267.056051] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5267.056089] ACPI : EC: ***** Command(UNDEF) stopped *****
[ 5267.056098] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5267.056239] ACPI : EC: ***** Command(UNDEF) started *****
[ 5267.056244] ACPI : EC: ===== TASK (3) =====
[ 5267.056284] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5267.056288] ACPI : EC: EC_SC(W) = 0x81
[ 5267.058794] ACPI : EC: ===== IRQ (3) =====
[ 5267.058807] ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
[ 5267.058811] ACPI : EC: EC_DATA(W) = 0x83
[ 5267.058819] ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[ 5267.059646] ACPI : EC: ===== TASK (0) =====
[ 5267.059664] ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[ 5267.061636] ACPI : EC: ===== IRQ (3) =====
[ 5267.061656] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5267.061662] ACPI : EC: EC_DATA(W) = 0x0a
[ 5267.061670] ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[ 5267.062916] ACPI : EC: ===== TASK (0) =====
[ 5267.062932] ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[ 5267.064563] ACPI : EC: ===== IRQ (3) =====
[ 5267.064579] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5267.064601] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5267.064647] ACPI : EC: ***** Command(UNDEF) stopped *****
[ 5267.064654] ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[ 5267.067316] APIC error on CPU0: 80 : Illegal register address
Comment 9 abandoned account 2015-01-18 14:15:32 UTC
Ok, I got a lil bit more advanced output:

[  139.386503] [4274] backlight:brightness_store:185: backlight: set brightness to 10
[  139.387632] [4274] acpi:acpi_ec_transaction_unlocked:331: ACPI : EC: ***** Command(RD_EC) started *****
[  139.387641] [4274] acpi:advance_transaction:210: ACPI : EC: ===== TASK (3) =====
[  139.387651] [4274] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 O BF=0
[  139.387659] [4274] acpi:acpi_ec_write_cmd:160: ACPI : EC: EC_SC(W) = 0x80
[  139.390128] <intr> acpi:advance_transaction:210: ACPI : EC: ===== IRQ (3) =====
[  139.390147] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 O BF=0
[  139.390155] <intr> acpi:acpi_ec_write_data:166: ACPI : EC: EC_DATA(W) = 0x7f
[  139.390171] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 O BF=0
[  139.390218] [4274] acpi:advance_transaction:210: ACPI : EC: ===== TASK (3) =====
[  139.390227] [4274] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 O BF=0
[  139.393055] <intr> acpi:advance_transaction:210: ACPI : EC: ===== IRQ (3) =====
[  139.393063] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x01 SCI_EVT=0 BURST=0 CMD=0 IBF=0 O BF=1
[  139.393071] <intr> acpi:acpi_ec_read_data:154: ACPI : EC: EC_DATA(R) = 0x08
[  139.393082] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 O BF=0
[  139.393103] [4274] acpi:acpi_ec_transaction_unlocked:341: ACPI : EC: ***** Command(RD_EC) stopped *****
[  139.393112] [4274] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 O BF=0
[  139.393423] [4274] acpi:acpi_ec_transaction_unlocked:331: ACPI : EC: ***** Command(RD_EC) started *****
[  139.393430] [4274] acpi:advance_transaction:210: ACPI : EC: ===== TASK (3) =====
[  139.393439] [4274] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 O BF=0
[  139.393445] [4274] acpi:acpi_ec_write_cmd:160: ACPI : EC: EC_SC(W) = 0x80
[  139.396256] <intr> acpi:advance_transaction:210: ACPI : EC: ===== IRQ (3) =====
[  139.396265] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 O BF=0
[  139.396270] <intr> acpi:acpi_ec_write_data:166: ACPI : EC: EC_DATA(W) = 0x83
[  139.396280] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 O BF=0
[  139.396696] [4274] acpi:advance_transaction:210: ACPI : EC: ===== TASK (3) =====
[  139.396705] [4274] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 O BF=0
[  139.399165] <intr> acpi:advance_transaction:210: ACPI : EC: ===== IRQ (3) =====
[  139.399184] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x01 SCI_EVT=0 BURST=0 CMD=0 IBF=0 O BF=1
[  139.399193] <intr> acpi:acpi_ec_read_data:154: ACPI : EC: EC_DATA(R) = 0x0a
[  139.399207] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 O BF=0
[  139.399237] [4274] acpi:acpi_ec_transaction_unlocked:341: ACPI : EC: ***** Command(RD_EC) stopped *****
[  139.399245] [4274] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 O BF=0
[  139.399363] [4274] acpi:acpi_ec_transaction_unlocked:331: ACPI : EC: ***** Command(WR_EC) started *****
[  139.399369] [4274] acpi:advance_transaction:210: ACPI : EC: ===== TASK (3) =====
[  139.399424] [4274] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 O BF=0
[  139.399429] [4274] acpi:acpi_ec_write_cmd:160: ACPI : EC: EC_SC(W) = 0x81
[  139.400083] [4274] acpi:advance_transaction:210: ACPI : EC: ===== TASK (3) =====
[  139.400093] [4274] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x0a SCI_EVT=0 BURST=0 CMD=1 IBF=1 O BF=0
[  139.402101] <intr> acpi:advance_transaction:210: ACPI : EC: ===== IRQ (3) =====
[  139.402115] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 O BF=0
[  139.402121] <intr> acpi:acpi_ec_write_data:166: ACPI : EC: EC_DATA(W) = 0x83
[  139.402131] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 O BF=0
[  139.403384] [4274] acpi:advance_transaction:210: ACPI : EC: ===== TASK (3) =====
[  139.403394] [4274] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 O BF=0
[  139.405051] <intr> acpi:advance_transaction:210: ACPI : EC: ===== IRQ (3) =====
[  139.405069] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 O BF=0
[  139.405077] <intr> acpi:acpi_ec_write_data:166: ACPI : EC: EC_DATA(W) = 0x0a
[  139.405087] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 O BF=0
[  139.406807] [4274] acpi:advance_transaction:210: ACPI : EC: ===== TASK (3) =====
[  139.406834] [4274] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 O BF=0
[  139.407944] <intr> acpi:advance_transaction:210: ACPI : EC: ===== IRQ (3) =====
[  139.407962] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 O BF=0
[  139.407994] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 O BF=0
[  139.408060] [4274] acpi:acpi_ec_transaction_unlocked:341: ACPI : EC: ***** Command(WR_EC) stopped *****
[  139.408127] [4274] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 O BF=0
[  139.411346] APIC error on CPU0: 80 : Illegal register address

The above was generated by: echo '10' > /sys/class/backlight/acpi_video0/brightness
(while the brightness was already at 10 before executing)

process 4274 was:
root      4274  0.0  0.0  15924  3652 pts/0    S+   15:05   0:00 -bash
(the one doing the echo command)

The debug was done by, recompiling kernel with(whatever it had before in my prev. comment and) this new line in drivers/acpi/Makefile (to get rid of that UNDEF):

KBUILD_CFLAGS += -DDEBUG


booting in, then executing:
# echo 'file drivers/acpi/* +pflmt' > /sys/kernel/debug/dynamic_debug/control
# echo 'file drivers/video/* +pflmt' > /sys/kernel/debug/dynamic_debug/control
# echo '10' > /sys/class/backlight/acpi_video0/brightness 
# echo $$
4274


Any ideas on what to do next? Thanks.
Comment 10 abandoned account 2015-01-18 14:18:35 UTC
Created attachment 163711 [details]
the 3.19-rc5 log

the dmesg log from my previous comment, forgot to include it.

ideas on what to do(debug?) next are welcome
Comment 11 Aaron Lu 2015-01-19 02:41:15 UTC
acpidump please:
# acpidump > acpidump.txt
Comment 12 abandoned account 2015-01-19 02:55:33 UTC
Created attachment 163741 [details]
# acpidump

yessir
Comment 13 Aaron Lu 2015-02-17 08:13:49 UTC
No idea why. Maybe worth a try to add nox2apic or intremap=off kernel cmdline option.
Comment 14 abandoned account 2015-02-17 21:38:50 UTC
Created attachment 167411 [details]
current dmesg, kernel 3.19.0

tl;dr: no effect.

I tried with nox2apic, then with intremap=off, then with both. (and I made sure it's in effect by grepping /proc/cmdline)

Here's the log with both.

the error persists:
APIC error on CPU0: 80 : Illegal register address
Comment 15 Aaron Lu 2015-02-27 03:18:23 UTC
I have no idea why the ACPI video interface would cause such an error, a work around would be adding acpi_video=vendor to kernel cmdline.
Comment 16 abandoned account 2015-02-27 04:24:44 UTC
Created attachment 168361 [details]
dmesg with acpi_video=vendor

Interestingly the error persists, here's the log as it is now (except a few lines from i8042.debug output)

Unsure if maybe acpi_video=vendor took effect, although I'm sure it's seen in the kernel cmdline (as the dmesg suggests)

I tried to find something in Documentation/ because I was interested to find out what this flag would do.
I see acpi_video_flags  in sysctl/kernel.txt
but I didn't realize it's not acpi_video until now, I'll look more into that, just in case it got renamed(?) or something.
Comment 17 abandoned account 2015-02-27 04:27:09 UTC
nevermind that:
kernel/sysctl_binary.c:	/* KERN_ACPI_VIDEO_FLAGS "acpi_video_flags" no longer used */
Comment 18 abandoned account 2015-02-27 04:28:37 UTC
oh is it acpi_backlight=vendor ? I'll try brb
Comment 19 abandoned account 2015-02-27 04:36:13 UTC
Created attachment 168371 [details]
dmesg with acpi_backlight=vendor

ok if it's 
acpi_backlight=vendor
then, the error shows only once (possibly before that takes effect?)
but Fn+up/down are nolonger able to change brightness and the brightness bar(in xfce4) shows empty.
Comment 20 Aaron Lu 2015-02-27 05:25:00 UTC
Sorry, it's acpi_backlight=vendor. The documentation for it is Documentation/kernel-parameters.txt.

I don't see why this would affect hotkey. With this cmdline option, please show me the output of:
$ ls /sys/class/backlight

And if you run command acpi_listen, when you press the hotkey, is there any message output?
Comment 21 abandoned account 2015-02-27 05:34:12 UTC
cool

$ ls /sys/class/backlight/
ideapad@  radeon_bl0@  thinkpad_screen@

lrwxrwxrwx  1 root root 0 27.02.2015 06:27 ideapad -> ../../devices/pci0000:00/0000:00:14.3/PNP0C09:00/VPC2004:00/backlight/ideapad/
lrwxrwxrwx  1 root root 0 27.02.2015 06:27 radeon_bl0 -> ../../devices/pci0000:00/0000:00:01.0/drm/card0/card0-LVDS-1/radeon_bl0/
lrwxrwxrwx  1 root root 0 27.02.2015 06:28 thinkpad_screen -> ../../devices/virtual/backlight/thinkpad_screen/

hmm that's weird because it works now:

sudo acpi_listen 
video/brightnessup BRTUP 00000086 00000000
video/brightnessdown BRTDN 00000087 00000000
video/brightnessup BRTUP 00000086 00000000
video/brightnessup BRTUP 00000086 00000000
video/brightnessdown BRTDN 00000087 00000000
video/brightnessdown BRTDN 00000087 00000000
video/brightnessdown BRTDN 00000087 00000000
video/brightnessup BRTUP 00000086 00000000
video/brightnessup BRTUP 00000086 00000000
video/brightnessup BRTUP 00000086 00000000
video/brightnessup BRTUP 00000086 00000000

I mean, the bar is full and moving when I press the keys, BUT the brightness doesn't change hmm

I'll try echo-ing next, submitting this comment just in case it locks up(it shouldn't but i'm being safe)
Comment 22 Aaron Lu 2015-02-27 05:37:33 UTC
(In reply to EmanueL Czirai from comment #21)
> cool
> 
> $ ls /sys/class/backlight/
> ideapad@  radeon_bl0@  thinkpad_screen@
> 
> lrwxrwxrwx  1 root root 0 27.02.2015 06:27 ideapad ->
> ../../devices/pci0000:00/0000:00:14.3/PNP0C09:00/VPC2004:00/backlight/
> ideapad/
> lrwxrwxrwx  1 root root 0 27.02.2015 06:27 radeon_bl0 ->
> ../../devices/pci0000:00/0000:00:01.0/drm/card0/card0-LVDS-1/radeon_bl0/
> lrwxrwxrwx  1 root root 0 27.02.2015 06:28 thinkpad_screen ->
> ../../devices/virtual/backlight/thinkpad_screen/
> 
> hmm that's weird because it works now:
> 
> sudo acpi_listen 
> video/brightnessup BRTUP 00000086 00000000
> video/brightnessdown BRTDN 00000087 00000000
> video/brightnessup BRTUP 00000086 00000000
> video/brightnessup BRTUP 00000086 00000000
> video/brightnessdown BRTDN 00000087 00000000
> video/brightnessdown BRTDN 00000087 00000000
> video/brightnessdown BRTDN 00000087 00000000
> video/brightnessup BRTUP 00000086 00000000
> video/brightnessup BRTUP 00000086 00000000
> video/brightnessup BRTUP 00000086 00000000
> video/brightnessup BRTUP 00000086 00000000
> 
> I mean, the bar is full and moving when I press the keys, BUT the brightness
> doesn't change hmm

The X driver should be using a not working interface and that caused problem. I doubt the only interface that works is the radeon one and if it is not picked up by the X driver, the hotkey backlight functionality is broken.
Comment 23 abandoned account 2015-02-27 05:48:56 UTC
the buttons seem to be mapped to 
thinkpad_screen -> ../../devices/virtual/backlight/thinkpad_screen/
because it has 7 brightness levels and this:
# cat */max_brightness 
10
255
7
in /sys/class/backlight

so this would explain why the brightness doesn't change.


If I manually echo into 'brightness' of 'radeon_bl0'
# echo '255' > radeon_bl0/brightness
the only dmesg message is this:
[  724.142445] [5081] backlight:brightness_store:185: backlight: set brightness to 255
and the brightness is visibly changed (from 200 which I had set previously, to 255)

If I manually echo into 'brightness' of 'ideapad' however
# echo '10' > ideapad/brightness 
then the brightness is visibly changed and the 'Illegal register address' error appears (in the middle of the following dmesg messages which also appear as a result of that echo):

[  806.741283] [5081] backlight:brightness_store:185: backlight: set brightness to 10
[  806.741651] [5081] acpi:acpi_ec_transaction_unlocked:331: ACPI : EC: ***** Command(RD_EC) started *****
[  806.741660] [5081] acpi:advance_transaction:210: ACPI : EC: ===== TASK (0) =====
[  806.741717] [5081] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[  806.741724] [5081] acpi:acpi_ec_write_cmd:160: ACPI : EC: EC_SC(W) = 0x80
[  806.743516] [5081] acpi:advance_transaction:210: ACPI : EC: ===== TASK (1) =====
[  806.743582] [5081] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x0a SCI_EVT=0 BURST=0 CMD=1 IBF=1 OBF=0
[  806.744396] <intr> acpi:advance_transaction:210: ACPI : EC: ===== IRQ (3) =====
[  806.744413] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
[  806.744420] <intr> acpi:acpi_ec_write_data:166: ACPI : EC: EC_DATA(W) = 0x83
[  806.744431] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[  806.746765] [5081] acpi:advance_transaction:210: ACPI : EC: ===== TASK (0) =====
[  806.746784] [5081] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[  806.747611] <intr> acpi:advance_transaction:210: ACPI : EC: ===== IRQ (3) =====
[  806.747631] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x01 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=1
[  806.747640] <intr> acpi:acpi_ec_read_data:154: ACPI : EC: EC_DATA(R) = 0x0a
[  806.747668] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[  806.747736] [5081] acpi:acpi_ec_transaction_unlocked:341: ACPI : EC: ***** Command(RD_EC) stopped *****
[  806.747748] [5081] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[  806.747768] [5081] acpi:acpi_ec_transaction_unlocked:331: ACPI : EC: ***** Command(WR_EC) started *****
[  806.747774] [5081] acpi:advance_transaction:210: ACPI : EC: ===== TASK (3) =====
[  806.747782] [5081] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[  806.747788] [5081] acpi:acpi_ec_write_cmd:160: ACPI : EC: EC_SC(W) = 0x81
[  806.750285] <intr> acpi:advance_transaction:210: ACPI : EC: ===== IRQ (3) =====
[  806.750294] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
[  806.750300] <intr> acpi:acpi_ec_write_data:166: ACPI : EC: EC_DATA(W) = 0x83
[  806.750310] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[  806.750528] [5081] acpi:advance_transaction:210: ACPI : EC: ===== TASK (3) =====
[  806.750542] [5081] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[  806.753584] <intr> acpi:advance_transaction:210: ACPI : EC: ===== IRQ (1) =====
[  806.753613] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[  806.753620] <intr> acpi:acpi_ec_write_data:166: ACPI : EC: EC_DATA(W) = 0x0a
[  806.753631] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[  806.753644] [5081] acpi:advance_transaction:210: ACPI : EC: ===== TASK (0) =====
[  806.753672] [5081] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[  806.756684] <intr> acpi:advance_transaction:210: ACPI : EC: ===== IRQ (3) =====
[  806.756704] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[  806.756719] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[  806.756784] [5081] acpi:acpi_ec_transaction_unlocked:341: ACPI : EC: ***** Command(WR_EC) stopped *****
[  806.756813] [5081] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[  806.760342] APIC error on CPU0: 80 : Illegal register address
[  806.763603] [5081] acpi:acpi_ec_transaction_unlocked:331: ACPI : EC: ***** Command(RD_EC) started *****
[  806.763612] [5081] acpi:advance_transaction:210: ACPI : EC: ===== TASK (1) =====
[  806.763643] [5081] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[  806.763650] [5081] acpi:acpi_ec_write_cmd:160: ACPI : EC: EC_SC(W) = 0x80
[  806.766568] <intr> acpi:advance_transaction:210: ACPI : EC: ===== IRQ (3) =====
[  806.766588] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
[  806.766596] <intr> acpi:acpi_ec_write_data:166: ACPI : EC: EC_DATA(W) = 0x75
[  806.766607] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[  806.766688] [5081] acpi:advance_transaction:210: ACPI : EC: ===== TASK (1) =====
[  806.766714] [5081] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[  806.769525] <intr> acpi:advance_transaction:210: ACPI : EC: ===== IRQ (3) =====
[  806.769546] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x01 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=1
[  806.769556] <intr> acpi:acpi_ec_read_data:154: ACPI : EC: EC_DATA(R) = 0x61
[  806.769583] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[  806.769659] [5081] acpi:acpi_ec_transaction_unlocked:341: ACPI : EC: ***** Command(RD_EC) stopped *****
[  806.769669] [5081] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[  806.769686] [5081] acpi:acpi_ec_transaction_unlocked:331: ACPI : EC: ***** Command(WR_EC) started *****
[  806.769692] [5081] acpi:advance_transaction:210: ACPI : EC: ===== TASK (3) =====
[  806.769700] [5081] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[  806.769706] [5081] acpi:acpi_ec_write_cmd:160: ACPI : EC: EC_SC(W) = 0x81
[  806.771771] [5081] acpi:advance_transaction:210: ACPI : EC: ===== TASK (3) =====
[  806.771781] [5081] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x0a SCI_EVT=0 BURST=0 CMD=1 IBF=1 OBF=0
[  806.772535] <intr> acpi:advance_transaction:210: ACPI : EC: ===== IRQ (3) =====
[  806.772552] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
[  806.772558] <intr> acpi:acpi_ec_write_data:166: ACPI : EC: EC_DATA(W) = 0x75
[  806.772567] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[  806.773460] [5081] acpi:advance_transaction:210: ACPI : EC: ===== TASK (2) =====
[  806.773489] [5081] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[  806.775430] <intr> acpi:advance_transaction:210: ACPI : EC: ===== IRQ (3) =====
[  806.775441] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[  806.775448] <intr> acpi:acpi_ec_write_data:166: ACPI : EC: EC_DATA(W) = 0x61
[  806.775457] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[  806.776715] [5081] acpi:advance_transaction:210: ACPI : EC: ===== TASK (2) =====
[  806.776740] [5081] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x02 SCI_EVT=0 BURST=0 CMD=0 IBF=1 OBF=0
[  806.778354] <intr> acpi:advance_transaction:210: ACPI : EC: ===== IRQ (3) =====
[  806.778373] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[  806.778397] <intr> acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0
[  806.778457] [5081] acpi:acpi_ec_transaction_unlocked:341: ACPI : EC: ***** Command(WR_EC) stopped *****
[  806.778477] [5081] acpi:acpi_ec_read_status:146: ACPI : EC: EC_SC(R) = 0x00 SCI_EVT=0 BURST=0 CMD=0 IBF=0 OBF=0


echo-ing into 'thinkpad_screen' has no effect on brightness
# echo '6' > thinkpad_screen/brightness 
[  958.426149] [5081] backlight:brightness_store:185: backlight: set brightness to 6
that's the only message that appears on dmesg


Doesn't this indicate that maybe the issue is within the ideapad_laptop module?
lsmod |grep -i idea
ideapad_laptop         17403  0 
sparse_keymap          12818  1 ideapad_laptop
rfkill                 18121  2 ideapad_laptop,thinkpad_acpi

but I'm assuming(without having checked) that that's the module giving ideapad_acpi in the dmesg:
[   12.086126] driver: 'ideapad_acpi': driver_bound: bound to device 'VPC2004:00'
Comment 24 abandoned account 2015-02-27 05:53:03 UTC
you're right, thinkpad_acpi detected that non-working 8 level brightness (apparently as a side effect of using acpi_backlight=vendor)
(and apparently X picks up on the last one)

lsmod|grep -i thinkpad
thinkpad_acpi          59883  0 
nvram                  13076  1 thinkpad_acpi
rfkill                 18121  2 ideapad_laptop,thinkpad_acpi
led_class              12855  2 rtsx_usb_sdmmc,thinkpad_acpi

[   33.927376] thinkpad_acpi: ThinkPad ACPI Extras v0.25
[   33.927386] thinkpad_acpi: http://ibm-acpi.sf.net/
[   33.927391] thinkpad_acpi: ThinkPad BIOS 54CN18WW, EC unknown
[   33.927395] thinkpad_acpi: Lenovo LENOVO, model Sabine
[   33.927520] bus: 'platform': add driver thinkpad_acpi
[   33.927582] bus: 'platform': add driver thinkpad_hwmon
[   33.927645] Registering platform device 'thinkpad_acpi'. Parent at platform
[   33.927651] device: 'thinkpad_acpi': device_add
[   33.927665] bus: 'platform': add device thinkpad_acpi
[   33.927731] bus: 'platform': driver_probe_device: matched device thinkpad_acp
i with driver thinkpad_acpi
[   33.927737] bus: 'platform': really_probe: probing driver thinkpad_acpi with 
device thinkpad_acpi
[   33.927748] driver: 'thinkpad_acpi': driver_bound: bound to device 'thinkpad_
acpi'
[   33.927760] bus: 'platform': really_probe: bound device thinkpad_acpi to driver thinkpad_acpi
Comment 25 abandoned account 2015-02-27 05:55:26 UTC
If you want to use the thinkpad-acpi backlight brightness control
instead of the generic ACPI video backlight brightness control for some
reason, you should use the acpi_backlight=vendor kernel parameter.

from Documentation/laptops/thinkpad-acpi.txt
Comment 26 abandoned account 2015-02-27 06:05:22 UTC
for consistency I want to say that the reason why Fn+up/down didn't work previously is because I ran 'startx' too soon - I was able to reproduce this and quitting X and rerunning made the keys work again, except ofc they work with the 8 level brightness which has no effect(but this is above already)
Comment 27 Aaron Lu 2015-02-27 06:12:42 UTC
So thinkpad_screen doesn't work, ideapad and acpi_video work but will emit an error message, radeon_bl works and no error message would appear. The best thing would be to ask Xorg driver to use radeon_bl interface instead of any others.

The Xorg log file should contain a line saying which interface it has picked up:
$ grep backlight /var/log/Xorg.0.log
[   193.682] (--) intel(0): found backlight control interface /sys/class/backlight/acpi_video0

There is an example on how to change the backlight interface with Intel card:
"
If neither of those solve the problem, edit or create /etc/X11/xorg.conf.d/20-intel.conf with the following content:

/etc/X11/xorg.conf.d/20-intel.conf

Section "Device"
        Identifier  "card0"
        Driver      "intel"
    Option      "Backlight"  "intel_backlight"
        BusID       "PCI:0:2:0"

EndSection
"

The Driver line is the name of the in use Xorg driver, the "intel_backlight" should be changed to "radeon_bl" and the BusID should be changed accordingly. Can you please try this?
Comment 28 abandoned account 2015-02-27 06:30:55 UTC
The only mention of backlight I get in Xorg.0.log
is
[  1403.198] (WW) RADEON(0): Option "Backlight" is not used
after I add the line:
  Option "Backlight" "radeon_bl"

but maybe because it's radeon instead of intel?

I'll try look into how to set that for radeon, but maybe I should look into that ideapad_acpi more to see if it's the one causing the Illegal... error

Can you tell me how many levels does your specific backlight have? because for me the radeon_bl0 has 255 and I imagine that would change 1 by 1 if I ever get it x to use it instead of the normal 10 levels one.
Comment 29 Aaron Lu 2015-02-27 06:35:42 UTC
(In reply to EmanueL Czirai from comment #28)
> The only mention of backlight I get in Xorg.0.log
> is
> [  1403.198] (WW) RADEON(0): Option "Backlight" is not used
> after I add the line:
>   Option "Backlight" "radeon_bl"
> 
> but maybe because it's radeon instead of intel?

Looks like yes.

> 
> I'll try look into how to set that for radeon, but maybe I should look into
> that ideapad_acpi more to see if it's the one causing the Illegal... error

Blacklist that module to see if the error message is gone with acpi_video interface?

> 
> Can you tell me how many levels does your specific backlight have? because
> for me the radeon_bl0 has 255 and I imagine that would change 1 by 1 if I
> ever get it x to use it instead of the normal 10 levels one.

Don't worry, X will adjust. I've used a intel_backlight interface that has more than 10,000 levels and the GUI will scale it to around 10 levels.
Comment 30 abandoned account 2015-02-27 06:51:42 UTC
Good idea.
I was wrong however:
blacklisting ideapad_laptop does not get rid of the error.
it is apparently using acpi_video0

these are what's left:
lrwxrwxrwx  1 root root 0 27.02.2015 07:44 acpi_video0 -> ../../devices/pci0000:00/0000:00:01.0/backlight/acpi_video0/
lrwxrwxrwx  1 root root 0 27.02.2015 07:44 radeon_bl0 -> ../../devices/pci0000:00/0000:00:01.0/drm/card0/card0-LVDS-1/radeon_bl0/

I also did not use acpi_backlight=vendor this time
Comment 31 abandoned account 2015-02-27 07:03:16 UTC
it actually works with acpi_backlight=vendor  and that blacklisting!

lrwxrwxrwx  1 root root 0 27.02.2015 08:00 radeon_bl0 -> ../../devices/pci0000:00/0000:00:01.0/drm/card0/card0-LVDS-1/radeon_bl0/
lrwxrwxrwx  1 root root 0 27.02.2015 08:00 thinkpad_screen -> ../../devices/virtual/backlight/thinkpad_screen/


there are no Illegal... errors in dmesg!
Comment 32 abandoned account 2015-02-27 07:08:30 UTC
oh wait, it was using the 8 level thinkpad_screen again, and I didn't notice because I was looking only at dmesg spewing ACPI lines without any Illegal inbetween.

But it will work if I manage to get X to use radeon_bl0
(tested again with echo to be sure, still no Illegal...)

this all makes sense because there's no ideapad and no acpi_video0 backlight


To summarize:
with acpi_backlight=vendor   works only if blacklisting ideapad_laptop
without acpi_backlight=vendor  doesn't work even if blacklisting ideapad_laptop

I guess, ideapad_laptop is not the culprit. But something else acpi related.
Comment 33 Aaron Lu 2015-02-27 07:11:16 UTC
(In reply to EmanueL Czirai from comment #32)
> oh wait, it was using the 8 level thinkpad_screen again, and I didn't notice
> because I was looking only at dmesg spewing ACPI lines without any Illegal
> inbetween.
> 
> But it will work if I manage to get X to use radeon_bl0
> (tested again with echo to be sure, still no Illegal...)
> 
> this all makes sense because there's no ideapad and no acpi_video0 backlight
> 
> 
> To summarize:
> with acpi_backlight=vendor   works only if blacklisting ideapad_laptop
> without acpi_backlight=vendor  doesn't work even if blacklisting
> ideapad_laptop
> 
> I guess, ideapad_laptop is not the culprit. But something else acpi related.

I agree.
Comment 34 abandoned account 2015-02-27 07:17:59 UTC
to remove the `thinkpad_screen`
so that this:
`with acpi_backlight=vendor   works only if blacklisting ideapad_laptop`
works with the backlight hotkeys,
what I had to do is:
$ sudo rmmod thinkpad_acpi
then restart X
because blacklisting it just wouldn't work and I've tried all these at once:

blacklist ideapad_laptop                                                        
blacklist thinkpad_acpi
blacklist nvram
blacklist rfkill
blacklist led_class

unsure what loads them by ignoring blacklisting but whatever, this is unrelated.

So what that does is leave only one backlight thingy:
radeon_bl0 -> ../../devices/pci0000:00/0000:00:01.0/drm/card0/card0-LVDS-1/radeon_bl0/
which X picks up, and it's how you said it would be (scaled to 12 levels)

No Illegal... error happening this way.

Thank you for your help thus far Aaron!

(still haven't given up on finding the real issue though)
Comment 35 Aaron Lu 2015-07-30 06:35:20 UTC
It doesn't seem we can get something new so I'll close this bug as WILL_NOT_FIX since we have a workaround.