Bug 115021

Summary: Boot EC requirement - Hotkeys not functional on Asus X550ZE
Product: ACPI Reporter: Luya Tshimbalanga (luya)
Component: ECAssignee: Lv Zheng (lv.zheng)
Status: CLOSED CODE_FIX    
Severity: normal CC: corentin.chary, lv.zheng, peter, yajo.sk8
Priority: P1    
Hardware: All   
OS: Linux   
See Also: https://bugzilla.kernel.org/show_bug.cgi?id=112531
https://bugzilla.kernel.org/show_bug.cgi?id=119391
Kernel Version: 4.6.4-301.fc24.x86_64 Subsystem:
Regression: No Bisected commit-id:
Bug Depends on: 150811    
Bug Blocks:    
Attachments: acpidump as stated on kernel 4.4.5-300 on Fedora 23
dmidecode from Asus X550ZE
Test dmidecode running Fedora 24
Updated acpidump running kernel 4.6.4 debug enabled
dmesg X550ZE with enabled debug
dmesg X550ZE with enabled debug and annotation
dmesg X550ZE with enabled debug and annotation
dmesg X550ZE with enabled debug
dmesg for kernel v4.7 with acpi debugging enabled, some suspend/resume, no EC activity
Interpretation of port 60/64 accesses on Windows 10 (ps2parser.py < windbg-kd-ioport-60-64.txt)
dmesg for v4.8-rc2-348-g6040e57 + six ACPI EC patches
dmesg for v4.8-rc2-348-g6040e57 + six ACPI EC patches + debug patch
debug patch
230391: dmesg for v4.8-rc2-348-g6040e57 + six ACPI EC patches + debug patch + DSDT override (remove _STA)
[PATCH] ACPI / EC: Add fully functioning ECDT EC
updated dmesg with kernel 4.8.0-rc4
dmesg X550ZE with dyndbg enabled
[PATCH] ACPI / EC: Add fully functioning ECDT EC
[PATCH] ACPI / EC: Add fully functioning ECDT EC
dmesg X550ZE with enabled debug and disabled ath wifi
dmesg boot from X550Z
dmesg result pressing Fn keys on x550z

Description Luya Tshimbalanga 2016-03-20 19:14:46 UTC
Following the suggestion on reporting the bug here, here is the issue related to hotkeys:
https://bugzilla.redhat.com/show_bug.cgi?id=1206862

The problem is outstanding since I brought ASUS X550ZE as none of the hotkeys works on every kernel release.Here is the needed info:

$ modinfo asus-nb-wmi
filename:       /lib/modules/4.4.5-300.fc23.x86_64/kernel/drivers/platform/x86/asus-nb-wmi.ko.xz
alias:          wmi:0B3CBB35-E3C2-45ED-91C2-4C5A6D195D1C
license:        GPL
description:    Asus Notebooks WMI Hotkey Driver
author:         Corentin Chary <corentin.chary@gmail.com>
depends:        asus-wmi
intree:         Y
vermagic:       4.4.5-300.fc23.x86_64 SMP mod_unload 
parm:           wapf:WAPF value (uint)



I: Bus=0019 Vendor=0000 Product=0000 Version=0000
N: Name="Asus WMI hotkeys"
P: Phys=asus-nb-wmi/input0
S: Sysfs=/devices/platform/asus-nb-wmi/input/input16
U: Uniq=
H: Handlers=kbd event9 rfkill 
B: PROP=0
B: EV=100013
B: KEY=80000 0 800000000000 0 0 a1606f00900000 8200027800501000 e000000000000 0
B: MSC=10
Comment 1 Luya Tshimbalanga 2016-03-21 18:14:20 UTC
Created attachment 210121 [details]
acpidump as stated on kernel 4.4.5-300 on Fedora 23

Here is acpidump
Comment 2 Luya Tshimbalanga 2016-03-21 18:16:07 UTC
Created attachment 210131 [details]
dmidecode from Asus X550ZE

Generated from Fedora 23 with kernel 4.4.5-300
Comment 3 Luya Tshimbalanga 2016-07-14 04:57:03 UTC
Created attachment 223821 [details]
Test dmidecode running Fedora 24

Information about unavailability of hotkey function on Asus laptop
Comment 4 Peter Wu 2016-07-22 21:47:18 UTC
About the "wapf" comment from the Redhat bug, it will not have any effect since Linux reports to be Win8 compatible which shortcuts the evaluation:

        Method (_Q0B, 0, NotSerialized) { // _Qxx: EC Query
            P80H = 0x0B
            If ((OSFL () >= 0x0F)) { // true if _OSI("Windows 2012")
                Notify (ASHS, 0x88) // Device-Specific
            } ElseIf ((^^^^ATKD.WAPF & 0x04)) {
                If (ATKP) {
                    ^^^^ATKD.IANE (0x88)
                }
            }
            ...

To help aiding this issue, please install a kernel with the CONFIG_ACPI_DEBUG[1] option enabled (the fedora debug kernels qualify for this). Once booted, enable logging of ACPI method invocations as follows:

echo > /sys/module/acpi/parameters/debug_level 0x200  # ACPI_LV_EXEC
echo > /sys/module/acpi/parameters/debug_layer 0x10   # ACPI_NAMESPACE

Now please press the various Fn key combinations and register which _Qxx methods are invoked according to the dmesg.

 [1]: https://www.kernel.org/doc/Documentation/acpi/debug.txt
Comment 5 Luya Tshimbalanga 2016-07-23 16:42:01 UTC
Created attachment 225571 [details]
Updated acpidump running kernel 4.6.4 debug enabled

Here is an updated acpidump. 
What will be command to enable  _Qxx method?
Comment 6 Luya Tshimbalanga 2016-07-23 16:46:08 UTC
Created attachment 225581 [details]
dmesg X550ZE with enabled debug
Comment 7 Peter Wu 2016-07-24 14:07:03 UTC
The acpidump does not depend on the kernel version, just on the BIOS version. Uploading it again does not help.

Please follow the instructions from comment 4 to obtain the required dmesg. Do not forget to mention which Fn combinations you pressed. Preferably you annotate the dmesg with the keys as in:

(pressed Fn+F1, Brightness up)
[ 1234.567890]    nseval-0227 ns_evaluate           : **** Execute method [\_SB.PCI0.SBRG.EC0._Qxx] at AML address ffffc90000027b60 length 63
...
(pressed Fn+F2, Brightness down)
[ 1238.567890]    nseval-0227 ns_evaluate           : **** Execute method [\_SB.PCI0.SBRG.EC0._Qxx] at AML address ffffc90000027b60 length 63
...
Comment 8 Luya Tshimbalanga 2016-07-24 19:36:07 UTC
I installed fedora kernel-debug ( 4.6.4-301.fc24.x86_64+debug) and followed instruction on comment #4. Looking at the cat report if needed debug is enabled:

# cat /sys/module/acpi/parameters/debug_layer
Description              	Hex        SET
ACPI_UTILITIES           	0x00000001 [ ]
ACPI_HARDWARE            	0x00000002 [ ]
ACPI_EVENTS              	0x00000004 [ ]
ACPI_TABLES              	0x00000008 [ ]
ACPI_NAMESPACE           	0x00000010 [*]
ACPI_PARSER              	0x00000020 [ ]
ACPI_DISPATCHER          	0x00000040 [ ]
ACPI_EXECUTER            	0x00000080 [ ]
ACPI_RESOURCES           	0x00000100 [ ]
ACPI_CA_DEBUGGER         	0x00000200 [ ]
ACPI_OS_SERVICES         	0x00000400 [ ]
ACPI_CA_DISASSEMBLER     	0x00000800 [ ]
ACPI_COMPILER            	0x00001000 [ ]
ACPI_TOOLS               	0x00002000 [ ]
ACPI_BUS_COMPONENT       	0x00010000 [ ]
ACPI_AC_COMPONENT        	0x00020000 [ ]
ACPI_BATTERY_COMPONENT   	0x00040000 [ ]
ACPI_BUTTON_COMPONENT    	0x00080000 [ ]
ACPI_SBS_COMPONENT       	0x00100000 [ ]
ACPI_FAN_COMPONENT       	0x00200000 [ ]
ACPI_PCI_COMPONENT       	0x00400000 [ ]
ACPI_POWER_COMPONENT     	0x00800000 [ ]
ACPI_CONTAINER_COMPONENT 	0x01000000 [ ]
ACPI_SYSTEM_COMPONENT    	0x02000000 [ ]
ACPI_THERMAL_COMPONENT   	0x04000000 [ ]
ACPI_MEMORY_DEVICE_COMPONENT	0x08000000 [ ]
ACPI_VIDEO_COMPONENT     	0x10000000 [ ]
ACPI_PROCESSOR_COMPONENT 	0x20000000 [ ]
ACPI_ALL_DRIVERS         	0xFFFF0000 [ ]
--
debug_layer = 0x00000010 ( * = enabled)


I have this ACPI_CA_DEBUGGER named 0x00000200 instead of ACPI_LV_EXEC. I notice ACPI_EXECUTER 0x00000080 is available. Any input for that?
Comment 9 Luya Tshimbalanga 2016-07-24 19:51:48 UTC
After checking ACPI_Levl, ACPI_LV_EXEC is enabled. Attempting to test all Fn combination ranging fro bightness to audio failed as dmesg shows no input. I noticed _BST seems an equivalent for _Qxx. In contrast, Fn command is working on Windows 10 so I am baffled with that issue.
Comment 10 Peter Wu 2016-07-24 21:41:48 UTC
I am not questioning that it works on Windows 10, but we would like to get it working on Linux. The _BST method is presumably triggered by UPower which periodically updates the battery status and is unrelated.

Since we were unable to obtain a useful "Execute method" debug message, let's try to capture the message "Begin Method Parse/Execute" by enabling these values:

echo > /sys/module/acpi/parameters/debug_level 0x40   # ACPI_LV_PARSE
echo > /sys/module/acpi/parameters/debug_layer 0x20   # ACPI_PARSER

and repeat the Fn key presses. Can you also check if your laptop happens to enable Fn functionality by default? That is, does pressing F1 really trigger "F1" or something like Brightness down?

By the way, I found the appropriate debug_layer by looking into the drivers/acpi/ directory where I found in acpica/psxface.c

#define _COMPONENT          ACPI_PARSER
...
    ACPI_DEBUG_PRINT((ACPI_DB_PARSE, // translates to ACPI_LV_PARSE
        "**** Begin Method Parse/Execute [%4.4s] **** Node=%p Obj=%p\n",
Comment 11 Luya Tshimbalanga 2016-07-25 04:04:52 UTC
As listed 
debug_layer = 0x00000020 ( * = enabled)
debug_level = 0x00000040 (* = enabled)


> Can you also check if your laptop happens to enable Fn functionality by 
> default? That is, does pressing F1 really trigger "F1" or something like 
> Brightness down?

All Fn functionality is enabled by default i.e. F1 triggers "F1". Test done on Gnome Shell.

Here is the resulting dmseg sorted by psxface
11775.710879]   psxface-0154 ps_execute_method     : **** Begin Method Parse/Execute [_BST] **** Node=ffff88043e8b87f8 Obj=ffff88043e8b9678
[11775.721535]   psxface-0244 ps_execute_method     : Method returned ObjDesc=ffff88043e8cf240

The latter seems triggered when attempting to combine Fn+other Fn key.

Thanks for the help.
Comment 12 Luya Tshimbalanga 2016-07-25 12:43:15 UTC
Created attachment 225801 [details]
dmesg X550ZE with enabled debug  and annotation

Resulted dmesg with annotation
Comment 13 Peter Wu 2016-07-25 13:17:04 UTC
This is a quick overview of the keys you mentioned in the logs (F3/F4 were not mentioned):

 Fn+F1, toggle sleep mode
 Fn+F2, toggle Wifi
 Fn+F3, ?
 Fn+F4, ?
 Fn+F5, Brightness down
 Fn+F6, Brightness up
 Fn+F7, disable screen
 Fn+F8, toggle screen laptop/external
 Fn+F9, Toggle touchpad
 Fn+F10, mute
 Fn+F11, Volume down
 Fn+F12, Volume up

Unfortunately the logs do not mention any execution of the _Qxx (or other) methods. It only sporadically mentions _BST (Battery STatus) which is not what we are looking for. Maybe we could trace the acpi_ns_evaluate function with this:

echo > /sys/module/acpi/parameters/debug_level 0x400  # ACPI_LV_NAMES
echo > /sys/module/acpi/parameters/debug_layer 0x10   # ACPI_NAMESPACE

Hopefully this will print something useful like
"_Qxx [0x12345678] Value 0xabcdef12"
Comment 14 Luya Tshimbalanga 2016-07-25 13:40:22 UTC
Created attachment 225811 [details]
dmesg X550ZE with enabled debug  and annotation

With
debug_level = 0x00000400 (* = enabled)
debug_layer = 0x00000010 ( * = enabled)

Sadly, no _Qxx in sight.
Comment 15 Peter Wu 2016-07-25 14:58:39 UTC
Are you sure that these dmesg parts match the annotations? According to the timestamps you are pressing the different keys after delays of 0.1 ms (100 μs). What if you do something like this:

dmesg -w | tail -n+$(dmesg | wc -l) | tee dmesg.txt

This will only write new entries to dmesg.txt (alternatively, use dmesg -C to clear the dmesg before reading it). Try to wait for a second or so between key presses so that the periods are more clear. Try to log off from GNOME while doing this and stop the UPower service to avoid the BST noise.
Comment 16 Luya Tshimbalanga 2016-07-25 18:03:31 UTC
(In reply to Peter Wu from comment #15)
> Are you sure that these dmesg parts match the annotations? According to the
> timestamps you are pressing the different keys after delays of 0.1 ms (100
> μs). What if you do something like this:
> 
> dmesg -w | tail -n+$(dmesg | wc -l) | tee dmesg.txt
> 
> This will only write new entries to dmesg.txt (alternatively, use dmesg -C
> to clear the dmesg before reading it). Try to wait for a second or so
> between key presses so that the periods are more clear. Try to log off from
> GNOME while doing this and stop the UPower service to avoid the BST noise.

After following the instruction, dmesg.txt is empty despite the effort of rechecking again. However, I noticed Fn+F8 got some activity.
Comment 17 Peter Wu 2016-07-26 10:22:15 UTC
(In reply to Luya Tshimbalanga from comment #16)
> (In reply to Peter Wu from comment #15)
> > Are you sure that these dmesg parts match the annotations? According to the
> > timestamps you are pressing the different keys after delays of 0.1 ms (100
> > μs). What if you do something like this:
> > 
> > dmesg -w | tail -n+$(dmesg | wc -l) | tee dmesg.txt
[..]
> After following the instruction, dmesg.txt is empty despite the effort of
> rechecking again. However, I noticed Fn+F8 got some activity.

It is completely empty or is it missing relevant messages? (You have debug_layer and debug_level enabled right?)
Comment 18 Luya Tshimbalanga 2016-07-26 17:17:22 UTC
Created attachment 226531 [details]
dmesg X550ZE with enabled debug

debug_level = 0x00000400 (* = enabled)
debug_layer = 0x00000010 ( * = enabled)
systemctl stop upower

dmesg -w | tail -n+$(dmesg | wc -l) | tee dmesg.txt

looking at initial dmesg.txt, it is completely empty with all Fn+Fn keys input.


I include the newest version after logging out, according to timestamp. it is just noise,
Comment 19 Peter Wu 2016-07-26 21:30:13 UTC
All log entries are from a single second, are there no preceding entries?

Maybe it is easier to debug this over IRC (I'm Lekensteyn at Freenode, UTC+0200).
Comment 20 Luya Tshimbalanga 2016-07-26 22:19:44 UTC
I am opening my IRC account. Name: finalzone(In reply to Peter Wu from comment #19)
> All log entries are from a single second, are there no preceding entries?
> 

Surprisingly none once I cleared all dmseg and started the procedure. I don't know if I missed a step.

> Maybe it is easier to debug this over IRC (I'm Lekensteyn at Freenode,
> UTC+0200).
I'm finalzone at Freenode and going to open the IRC.
Comment 21 Peter Wu 2016-07-29 22:43:15 UTC
The Fn+F3 and Fn+F4 combos are apparently related to control of keyboard backlights (on models that have them), see https://www.asus.com/support/FAQ/1014790/

I see that there are absolutely no ACPI-related events on pressing these keys... will have to investigate this further.

Also interesting is this FAQ on "Hot keys on ASUS notebook are not functional and working" (https://www.asus.com/support/FAQ/1015071/) that documents which software are needed for certain keys:

 Fn+F1, toggle sleep mode
(not mentioned)

 Fn+F2, toggle Wifi
needs ATKACPI + ATK hotkey tool + Asus Wireless Radio Control program
(likely controlling the \_SB.ASHS device, identified by _HID as ATK4001 ("Asus Radio Control Button"))

 Fn+F3, (none, kbd backlight down on others)
 Fn+F4, (none, kbd backlight up on others)

 Fn+F5, Brightness down
 Fn+F6, Brightness up
 Fn+F7, disable screen
 Fn+F8, toggle screen laptop/external
"No need to install any driver or apps"

 Fn+F9, Toggle touchpad
needs ATKACPI + ATK hotkey tool + touchpanel driver

 Fn+F10, mute
 Fn+F11, Volume down
 Fn+F12, Volume up
needs ATKACPI + ATK hotkey tool + audio driver

There are apparently also other keys mentioned on the site and found on the keyboard. One thing not mentioned is Fn+V which seems to open the camera application (https://www.asus.com/support/FAQ/1012794/).


Plotting the interrupt activity over periods of 60 seconds while being idle, hitting Fn and Fn+F1 showed no deviations. (Used https://git.lekensteyn.nl/scripts/tree/rare/watch-intr.py and the related interrupts-graph.py scripts.)


Maybe some ACPI method needs to be called first. Let's see if I can create a fake ACPI device and trace it in QEMU.
Comment 22 Luya Tshimbalanga 2016-07-30 00:31:24 UTC
(In reply to Peter Wu from comment #21)
> The Fn+F3 and Fn+F4 combos are apparently related to control of keyboard
> backlights (on models that have them), see
> https://www.asus.com/support/FAQ/1014790/
> 
> I see that there are absolutely no ACPI-related events on pressing these
> keys... will have to investigate this further.
Which make sense as the X550ZE lacks keyboard backlights.

 
>  Fn+F1, toggle sleep mode
> (not mentioned)
That is strange.

>  Fn+F2, toggle Wifi
> needs ATKACPI + ATK hotkey tool + Asus Wireless Radio Control program
> (likely controlling the \_SB.ASHS device, identified by _HID as ATK4001
> ("Asus Radio Control Button"))
I found an information about that module: 
https://lwn.net/Articles/669275/
https://lwn.net/Articles/667892/

> 
>  Fn+F3, (none, kbd backlight down on others)
>  Fn+F4, (none, kbd backlight up on others)
> 
>  Fn+F5, Brightness down
>  Fn+F6, Brightness up
>  Fn+F7, disable screen
>  Fn+F8, toggle screen laptop/external
> "No need to install any driver or apps"
I noticed an activity with Fn+F8. I will test it at home to see if it does as intended. Other input failed to work even though the available  module is present.


>  Fn+F9, Toggle touchpad
> needs ATKACPI + ATK hotkey tool + touchpanel driver
> 
>  Fn+F10, mute
>  Fn+F11, Volume down
>  Fn+F12, Volume up
> needs ATKACPI + ATK hotkey tool + audio driver
> 

So ATKACPI is not available for Linux kernel. If only there is an initial support written by ASUS...


> There are apparently also other keys mentioned on the site and found on the
> keyboard. One thing not mentioned is Fn+V which seems to open the camera
> application (https://www.asus.com/support/FAQ/1012794/).
Now that you mentioned it, Fn+V is indeed toggling camera. You can see the symbol on lower-left of "V" letter. Fn+C is another one and I don't know its purpose.

> 
> Plotting the interrupt activity over periods of 60 seconds while being idle,
> hitting Fn and Fn+F1 showed no deviations. (Used
> https://git.lekensteyn.nl/scripts/tree/rare/watch-intr.py and the related
> interrupts-graph.py scripts.)
> 
> Maybe some ACPI method needs to be called first. Let's see if I can create a
> fake ACPI device and trace it in QEMU.
Thanks for the input.
Comment 23 Peter Wu 2016-07-30 23:17:45 UTC
You linked the patches to the review of said modules which would be useful if events are actually triggered... I successfully extracted the ATK device from the DSDT and produced a SSDT that could be used with QEMU.

Results are available at
https://github.com/Lekensteyn/acpi-stuff/tree/master/Asus-X550ZE
(see wmi-calls.txt for something readable)

Unfortunately it is not helpful, but I discovered that the EC is not inited... Next attempt for tomorrow.
Comment 24 Peter Wu 2016-07-31 14:36:14 UTC
Created attachment 226991 [details]
dmesg for kernel v4.7 with acpi debugging enabled, some suspend/resume, no EC activity

Related bugs (duplicate?):
hotkey does not work - ASUS ROG G752, G752VT
https://bugzilla.kernel.org/show_bug.cgi?id=112531

Possibly interesting bug:
ASUS Q500A: corrupted kaycodes on dualboot system
https://bugzilla.kernel.org/show_bug.cgi?id=119391

@Luya
For better exposure, could you edit the bug and change the Product and Component fields accordingly?


Further analysis:
\_SB.PCI0.SBRG.EC0._STA always returns Zero (not present, not functional)
Thus EC0._INI is never invoked and ECFL is always Ones (instead of One).
Hmm.. actually, the ACPI revision is newer than 2.0 so ECAV ("EC AVailable") should still return One (the fact that ECFL is Ones does not matter anymore).

The command `grep . /sys/firmware/acpi/interrupts/*`
shows zeroes for all entries even after spamming some keys and some suspend/resume cycles. Weird!

I have attached an unfiltered, full dmesg with ACPI debugging enabled should it be useful.
Comment 25 Luya Tshimbalanga 2016-07-31 16:48:43 UTC
@Peter,
I added the url for both bug reports as it seems affecting recent ASUS laptops. I wonder if it is possible to create a tracker for that purpose.
Comment 26 Luya Tshimbalanga 2016-07-31 17:03:49 UTC
@Peter,
Tracker created on https://bugzilla.kernel.org/show_bug.cgi?id=150811
Comment 27 Peter Wu 2016-08-21 12:23:30 UTC
Finally managed to continue working on this thing. I have setup a Checked/Debug build of Windows 10 with no additional drivers installed after the setup. These EC events were observed:

Fn+F1: _Q0A
Fn+F2: _Q0B (Toggle Wi-Fi)
Fn+F3: _Q0C
Fn+F4: _Q0D
Fn+F5: _Q0E
Fn+F6: _Q0F (triggers also \_SB.PCI0.VGA.LCDD._BCM)
Fn+F7: _Q10
Fn+F8: (none? \WMI0.WQBA was triggered shortly after)
FN+F9: _Q12
Fn+F10: _Q13
Fn+F11: _Q14
Fn+F12: _Q15
Fn+Up: _Q6B
Fn+Down: _Q6C
Fn+Left: _Q6D
Fn+Right: _Q6E
Fn+Enter: _Q6F (on numpad, Calculator)
Fn+V: _Q70 (Camera)
Fn+C: _Q71
Fn+Space: _Q72
Fn: _QD7 (on release, always)

All other keys trigger no events in the AMLI debugger. It is surprising that all keys were already functioning without installing additional drivers.


I uploaded two logs, one (traceoff) was used to determine the above, another (traceon) was created starting early in the boot while parsing the DSDT. The second log can be used to track down what Windows does different.

https://lekensteyn.nl/files/Asus-X550ZE/windbg-kd-acpi-traceoff.txt
https://lekensteyn.nl/files/Asus-X550ZE/windbg-kd-acpi-traceon.txt
https://lekensteyn.nl/files/Asus-X550ZE/

Should it be necessary to track obtain timings, I have a packet capture (102MiB) with the full traffic between the debugger and debugee.

Will be investigating further...
Comment 28 Peter Wu 2016-08-21 15:57:15 UTC
I found some funny behavior. When pressing some Fn key combos (e.g. Fn+7 to turn the screen off), rebooting in Windows results in execution of the action. Looks like there is some buffer that is not processed by Linux?

Perhaps the "7c" lines are significant, here is dmesg limited to serio:
[    4.033642] Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
[    4.056160] i8042: PNP: PS/2 Controller [PNP0303:PS2K,PNP0f13:PS2M] at 0x60,0x64 irq 1,12
[    4.059957] i8042: Detected active multiplexing controller, rev 1.1
[    4.062616] serio: i8042 KBD port at 0x60,0x64 irq 1
[    4.063468] serio: i8042 AUX0 port at 0x60,0x64 irq 12
[    4.064111] serio: i8042 AUX1 port at 0x60,0x64 irq 12
[    4.064893] serio: i8042 AUX2 port at 0x60,0x64 irq 12
[    4.065546] serio: i8042 AUX3 port at 0x60,0x64 irq 12
[    4.072739] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0
[    4.089304] atkbd serio0: Unknown key released (translated set 2, code 0x7c on isa0060/serio0).
[    4.089306] atkbd serio0: Use 'setkeycodes 7c <keycode>' to make it known.
[    4.289656] atkbd serio0: Unknown key released (translated set 2, code 0x7c on isa0060/serio0).
[    4.290128] atkbd serio0: Use 'setkeycodes 7c <keycode>' to make it known.
[    4.493239] atkbd serio0: Unknown key released (translated set 2, code 0x7c on isa0060/serio0).
[    4.494094] atkbd serio0: Use 'setkeycodes 7c <keycode>' to make it known.
[    4.696475] atkbd serio0: Unknown key released (translated set 2, code 0x7c on isa0060/serio0).
[    4.696962] atkbd serio0: Use 'setkeycodes 7c <keycode>' to make it known.
[   21.183447] atkbd serio0: Unknown key released (translated set 2, code 0x7c on isa0060/serio0).
[   21.184254] atkbd serio0: Use 'setkeycodes 7c <keycode>' to make it known.
[   21.387091] atkbd serio0: Unknown key released (translated set 2, code 0x7c on isa0060/serio0).
[   21.387112] atkbd serio0: Use 'setkeycodes 7c <keycode>' to make it known.
[   22.199717] psmouse serio4: elantech: assuming hardware version 4 (with firmware version 0x381f17)
[   22.212703] psmouse serio4: elantech: Synaptics capabilities query result 0x10, 0x14, 0x0e.
[   22.226914] psmouse serio4: elantech: Elan sample query result 0f, 19, 75
[   22.326830] input: ETPS/2 Elantech Touchpad as /devices/platform/i8042/serio4/input/input20
Comment 29 Luya Tshimbalanga 2016-08-21 23:38:44 UTC
I added Corentin in contact as these findings might be useful to imprive asus-nb-wmi. I wonder if he can setup that file for testing purpose.
Comment 30 Peter Wu 2016-08-24 11:00:24 UTC
Created attachment 230001 [details]
Interpretation of port 60/64 accesses on Windows 10 (ps2parser.py < windbg-kd-ioport-60-64.txt)

The "Unknown key released" warning is relative harmless and only happens while probing for devices:
[    3.950341] i8042: [7] MUX error, status is 25, data is fc
(so the data register (I/O port 0x60) now contains "0xfc")

[    3.950342] i8042: [7] fe <- i8042 (interrupt, 2, 12, timeout)
[    3.950522] i8042: [7] 91 -> i8042 (command)             # Route to AUX1:
[    3.950612] i8042: [7] f2 -> i8042 (parameter)           # Identify
[    3.955735] i8042: [9] ** <- i8042 (interrupt, 0, 12, timeout)
(AUX activity (interrupt 12), somehow AUXDATA flag is not set in status register, making it appear like data from the keyboard controller)

[    3.955788] atkbd serio0: Unknown key released (translated set 2, code 0x7c on isa0060/serio0).
[    3.955831] atkbd serio0: Use 'setkeycodes 7c <keycode>' to make it known.
(atkbd reads "fc" (some kind of failure indication?) from data register and masks it with 0x7f, detecting the wrong scan code 0x7c.)


Behavior on Windows 10: pressing Fn (combination) keys does not trigger accesses to the I/O port, so perhaps the UEFI firmware is doing something special. In case it can be helpful, attached is a trace from Windows 10 port 60/64 accesses. Original data and quick script to post-process it:
https://lekensteyn.nl/files/Asus-X550ZE/windbg-kd-ioport-60-64.txt
https://lekensteyn.nl/files/Asus-X550ZE/ps2parser.py

Manual annotation of a Linux dmesg:
https://lekensteyn.nl/files/Asus-X550ZE/new/dmesg-4.8.0-rc2-testing-00348-g6040e57-i8042debug-annotated.txt

I have tried combinations like i8042.nomux=1 i8042.noaux=1 but it does not change the result (Fn keys still trigger *no* ACPI interrupts).


Perhaps it is still an ACPI issue. I have a continuously growing GPE15 count (currently at 11384 while all others are zero). It does not change depending on whether the asus-nb-wmi and/or asus-wmi modules are loaded. Tested with Linux v4.8-rc2-348-g6040e57. This GPE corresponds to the Embedded Controller (as EC0._GPE=0x15). Will have to figure out how these GPEs are exactly handled.
Comment 31 Luya Tshimbalanga 2016-08-24 17:10:47 UTC
(In reply to Peter Wu from comment #30)
> Behavior on Windows 10: pressing Fn (combination) keys does not trigger
> accesses to the I/O port, so perhaps the UEFI firmware is doing something
> special. In case it can be helpful, attached is a trace from Windows 10 port
> 60/64 accesses. Original data and quick script to post-process it:
> https://lekensteyn.nl/files/Asus-X550ZE/windbg-kd-ioport-60-64.txt
> https://lekensteyn.nl/files/Asus-X550ZE/ps2parser.py

I wonder if secure boot is involved in that process.
Comment 32 Lv Zheng 2016-08-25 03:19:11 UTC
Please upload the EC debugging log here.

Either if you have dynamic debugging enabled:
# echo "file ec.c +p" > <debugfs>/dynamic_debug/control

Or uncomment the following line and re-build the kernel:
drivers/acpi/ec.c

/* #define DEBUG */

Moving it to ACPI component before root causing.

Thanks
Lv
Comment 33 Lv Zheng 2016-08-25 03:24:47 UTC
(In reply to Peter Wu from comment #4)> echo > /sys/module/acpi/parameters/debug_level 0x200  # ACPI_LV_EXEC
> echo > /sys/module/acpi/parameters/debug_layer 0x10   # ACPI_NAMESPACE

This debugging facility is not efficient.
Please try AML tracer:
https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/tree/Documentation/acpi/method-tracing.txt

For example, booting the kernel with acpi.trace_state=enable

Thanks
Lv
Comment 34 Lv Zheng 2016-08-25 03:32:31 UTC
Decoded DSDT EC:

    Scope (_SB.PCI0.SBRG)
    {
        Device (EC0)
        {
            Name (_HID, EisaId ("PNP0C09"))  // _HID: Hardware ID
            Name (CRS, ResourceTemplate ()
            {
                IO (Decode16,
                    0x0062,             // Range Minimum
                    0x0062,             // Range Maximum
                    0x00,               // Alignment
                    0x01,               // Length
                    )
                IO (Decode16,
                    0x0066,             // Range Minimum
                    0x0066,             // Range Maximum
                    0x00,               // Alignment
                    0x01,               // Length
                    )
            })
            Method (_CRS, 0, NotSerialized)  // _CRS: Current Resource Settings
            {
                Return (CRS)
            }

            Name (_GPE, 0x15)  // _GPE: General Purpose Events

Decoded ECDT EC:

[024h 0036  12]      Command/Status Register : [Generic Address Structure]
[024h 0036   1]                     Space ID : 01 [SystemIO]
[025h 0037   1]                    Bit Width : 08
[026h 0038   1]                   Bit Offset : 00
[027h 0039   1]         Encoded Access Width : 01 [Byte Access:8]
[028h 0040   8]                      Address : 0000000000000066

[030h 0048  12]                Data Register : [Generic Address Structure]
[030h 0048   1]                     Space ID : 01 [SystemIO]
[031h 0049   1]                    Bit Width : 08
[032h 0050   1]                   Bit Offset : 00
[033h 0051   1]         Encoded Access Width : 01 [Byte Access:8]
[034h 0052   8]                      Address : 0000000000000062

[03Ch 0060   4]                          UID : 00000000
[040h 0064   1]                   GPE Number : 15
[041h 0065  19]                     Namepath : "\_SB.PCI0.SBRG.EC0"

Thanks
Comment 35 Lv Zheng 2016-08-25 07:39:55 UTC
(In reply to Lv Zheng from comment #32)
> Please upload the EC debugging log here.
> 
> Either if you have dynamic debugging enabled:
> # echo "file ec.c +p" > <debugfs>/dynamic_debug/control

Better to use kernel boot parameter dyndbg="file ec.c +p" to capture the result of the first EC status register read.

Thanks
Lv
Comment 36 Peter Wu 2016-08-25 13:20:19 UTC
(In reply to Lv Zheng from comment #33)
> (In reply to Peter Wu from comment #4)> echo >
> /sys/module/acpi/parameters/debug_level 0x200  # ACPI_LV_EXEC
> > echo > /sys/module/acpi/parameters/debug_layer 0x10   # ACPI_NAMESPACE
> 
> This debugging facility is not efficient.
> Please try AML tracer:
> https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/tree/
> Documentation/acpi/method-tracing.txt
> 
> For example, booting the kernel with acpi.trace_state=enable

AFAIK that interface is limited to tracing only one method, it cannot be used to trace all methods under a device unless I am mistaken?

With dyndbg="file ec.c +p" I only see these "EC:" messages:

[    0.615901] ACPI: Added _OSI(Processor Device)
[    0.615907] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.615913] ACPI: Added _OSI(Processor Aggregator Device)
[    0.615925] ACPI : EC: EC description table is found, configuring boot EC
[    0.615946] ACPI : EC: Starting EC
[    0.615947] ACPI : EC: 1: Increase driver
[    0.615948] ACPI : EC: EC started
[    0.620370] ACPI: Executed 1 blocks of module-level executable AML code
[    0.661206] ACPI: [Firmware Bug]: BIOS _OSI(Linux) query ignored
[    0.667907] ACPI : EC: Stopping EC
[    0.667910] ACPI : EC: 0: Decrease driver
[    0.667911] ACPI : EC: EC stopped
[    0.668416] ACPI : EC: Starting EC
[    0.668418] ACPI : EC: 1: Increase driver
[    0.668418] ACPI : EC: EC started
[    0.672503] ACPI: Interpreter enabled
[    0.672578] ACPI: (supports S0 S3 S4 S5)
[    0.672583] ACPI: Using IOAPIC for interrupt routing
...
(no other EC: messages in between, on pressing Fn a continuous flood starts:)
[  302.480879] ACPI : EC: IRQ (3)
[  302.480942] ACPI : EC: EC_SC(R) = 0x20 SCI_EVT=1 BURST=0 CMD=0 IBF=0 OBF=0
[  302.615306] ACPI : EC: IRQ (3)
[  302.615323] ACPI : EC: EC_SC(R) = 0x20 SCI_EVT=1 BURST=0 CMD=0 IBF=0 OBF=0
[  303.116552] ACPI : EC: IRQ (3)
[  303.116568] ACPI : EC: EC_SC(R) = 0x20 SCI_EVT=1 BURST=0 CMD=0 IBF=0 OBF=0
[  303.620366] ACPI : EC: IRQ (3)
[  303.620383] ACPI : EC: EC_SC(R) = 0x20 SCI_EVT=1 BURST=0 CMD=0 IBF=0 OBF=0
[  304.121627] ACPI : EC: IRQ (3)
[  304.121644] ACPI : EC: EC_SC(R) = 0x20 SCI_EVT=1 BURST=0 CMD=0 IBF=0 OBF=0
[  304.626292] ACPI : EC: IRQ (3)
[  304.626309] ACPI : EC: EC_SC(R) = 0x20 SCI_EVT=1 BURST=0 CMD=0 IBF=0 OBF=0
[  305.127615] ACPI : EC: IRQ (3)
[  305.127632] ACPI : EC: EC_SC(R) = 0x20 SCI_EVT=1 BURST=0 CMD=0 IBF=0 OBF=0
[  305.631819] ACPI : EC: IRQ (3)
[  305.631836] ACPI : EC: EC_SC(R) = 0x20 SCI_EVT=1 BURST=0 CMD=0 IBF=0 OBF=0
...
Comment 37 Peter Wu 2016-08-26 00:02:23 UTC
Some "success", EC_DATA(R) matches the _Qxx events (see also comment 27).

# echo > /sys/module/acpi/parameters/ec_event_clearing event
ACPI : EC: Assuming SCI_EVT clearing on EC_SC accesses

# Hold Fn, press and release F3
ACPI : EC: IRQ (3)
ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
ACPI : EC: Command(UNDEF) submitted/blocked
ACPI : EC: Event started
ACPI : EC: 2: Increase command
ACPI : EC: Command(UNDEF) started
ACPI : EC: TASK (3)
ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
ACPI : EC: EC_SC(W) = 0x84
ACPI : EC: IRQ (0)
ACPI : EC: EC_SC(R) = 0x09 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=1
ACPI : EC: EC_DATA(R) = 0x0c
ACPI : EC: Command(UNDEF) completed by hardware
ACPI : EC: Command(UNDEF) stopped
ACPI : EC: 1: Decrease command
ACPI : EC: Event stopped
ACPI : EC: TASK (3)
ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
ACPI : EC: Command(UNDEF) unblocked

# Still hold Fn, press and release F4
ACPI : EC: IRQ (3)
ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
ACPI : EC: Command(UNDEF) submitted/blocked
ACPI : EC: Event started
ACPI : EC: 2: Increase command
ACPI : EC: Command(UNDEF) started
ACPI : EC: TASK (3)
ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
ACPI : EC: EC_SC(W) = 0x84
ACPI : EC: IRQ (1)
ACPI : EC: EC_SC(R) = 0x09 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=1
ACPI : EC: EC_DATA(R) = 0x0d
ACPI : EC: Command(UNDEF) completed by hardware
ACPI : EC: Command(UNDEF) stopped
ACPI : EC: 1: Decrease command
ACPI : EC: Event stopped
ACPI : EC: TASK (3)
ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
ACPI : EC: Command(UNDEF) unblocked

# Release Fn
ACPI : EC: IRQ (3)
ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
ACPI : EC: Command(UNDEF) submitted/blocked
ACPI : EC: Event started
ACPI : EC: 2: Increase command
ACPI : EC: Command(UNDEF) started
ACPI : EC: TASK (3)
ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
ACPI : EC: EC_SC(W) = 0x84
ACPI : EC: IRQ (1)
ACPI : EC: EC_SC(R) = 0x09 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=1
ACPI : EC: EC_DATA(R) = 0xd7
ACPI : EC: Command(UNDEF) completed by hardware
ACPI : EC: Command(UNDEF) stopped
ACPI : EC: 1: Decrease command
ACPI : EC: Event stopped
ACPI : EC: TASK (3)
ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
ACPI : EC: Command(UNDEF) unblocked

For some reason the _Qxx methods themselves are not invoked though. Maybe that is because acpi_ec_register_query_methods is not invoked (and no handlers are registered via acpi_ec_add).

I added some pr_warn to acpi_ec_add and more, but it does not seem to be called at all... that is strange.

Note that I will be returning this device soon, hopefully Luya can assist further in obtaining more debugging information as needed.
Comment 38 Lv Zheng 2016-08-26 01:27:07 UTC
(In reply to Peter Wu from comment #36)
> (In reply to Lv Zheng from comment #33)
> > (In reply to Peter Wu from comment #4)> echo >
> > /sys/module/acpi/parameters/debug_level 0x200  # ACPI_LV_EXEC
> > > echo > /sys/module/acpi/parameters/debug_layer 0x10   # ACPI_NAMESPACE
> > 
> > This debugging facility is not efficient.
> > Please try AML tracer:
> > https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/tree/
> > Documentation/acpi/method-tracing.txt
> > 
> > For example, booting the kernel with acpi.trace_state=enable
> 
> AFAIK that interface is limited to tracing only one method,

This is a fact 2 years ago.

> it cannot be used to trace all methods under a device unless I am mistaken?

You are wrong.
acpi.trace_state=method trace one method.
acpi.trace_state=enable trace all methods.

> 
> With dyndbg="file ec.c +p" I only see these "EC:" messages:
> 
> [    0.615901] ACPI: Added _OSI(Processor Device)
> [    0.615907] ACPI: Added _OSI(3.0 _SCP Extensions)
> [    0.615913] ACPI: Added _OSI(Processor Aggregator Device)
> [    0.615925] ACPI : EC: EC description table is found, configuring boot EC
> [    0.615946] ACPI : EC: Starting EC
> [    0.615947] ACPI : EC: 1: Increase driver
> [    0.615948] ACPI : EC: EC started
> [    0.620370] ACPI: Executed 1 blocks of module-level executable AML code
> [    0.661206] ACPI: [Firmware Bug]: BIOS _OSI(Linux) query ignored
> [    0.667907] ACPI : EC: Stopping EC
> [    0.667910] ACPI : EC: 0: Decrease driver
> [    0.667911] ACPI : EC: EC stopped
> [    0.668416] ACPI : EC: Starting EC
> [    0.668418] ACPI : EC: 1: Increase driver
> [    0.668418] ACPI : EC: EC started
> [    0.672503] ACPI: Interpreter enabled
> [    0.672578] ACPI: (supports S0 S3 S4 S5)
> [    0.672583] ACPI: Using IOAPIC for interrupt routing
> ...
> (no other EC: messages in between, on pressing Fn a continuous flood starts:)
> [  302.480879] ACPI : EC: IRQ (3)
> [  302.480942] ACPI : EC: EC_SC(R) = 0x20 SCI_EVT=1 BURST=0 CMD=0 IBF=0 OBF=0
> [  302.615306] ACPI : EC: IRQ (3)
> [  302.615323] ACPI : EC: EC_SC(R) = 0x20 SCI_EVT=1 BURST=0 CMD=0 IBF=0 OBF=0
> [  303.116552] ACPI : EC: IRQ (3)
> [  303.116568] ACPI : EC: EC_SC(R) = 0x20 SCI_EVT=1 BURST=0 CMD=0 IBF=0 OBF=0
> [  303.620366] ACPI : EC: IRQ (3)
> [  303.620383] ACPI : EC: EC_SC(R) = 0x20 SCI_EVT=1 BURST=0 CMD=0 IBF=0 OBF=0
> [  304.121627] ACPI : EC: IRQ (3)
> [  304.121644] ACPI : EC: EC_SC(R) = 0x20 SCI_EVT=1 BURST=0 CMD=0 IBF=0 OBF=0
> [  304.626292] ACPI : EC: IRQ (3)
> [  304.626309] ACPI : EC: EC_SC(R) = 0x20 SCI_EVT=1 BURST=0 CMD=0 IBF=0 OBF=0
> [  305.127615] ACPI : EC: IRQ (3)
> [  305.127632] ACPI : EC: EC_SC(R) = 0x20 SCI_EVT=1 BURST=0 CMD=0 IBF=0 OBF=0
> [  305.631819] ACPI : EC: IRQ (3)
> [  305.631836] ACPI : EC: EC_SC(R) = 0x20 SCI_EVT=1 BURST=0 CMD=0 IBF=0 OBF=0
> ...

Please upload the full dmesg here.
However, this looks like the known issue that can be fixed by the posted fixes:
https://patchwork.kernel.org/patch/9260899/
https://patchwork.kernel.org/patch/9260873/
https://patchwork.kernel.org/patch/9260877/
https://patchwork.kernel.org/patch/9260937/
https://patchwork.kernel.org/patch/9260891/

Could you also give them a try?

Thanks
Lv
Comment 39 Lv Zheng 2016-08-26 01:30:38 UTC
(In reply to Peter Wu from comment #37)
> Some "success", EC_DATA(R) matches the _Qxx events (see also comment 27).
> 
> # echo > /sys/module/acpi/parameters/ec_event_clearing event
> ACPI : EC: Assuming SCI_EVT clearing on EC_SC accesses

ec_event_clearing=event is not proven to be working.
According to my observation, most of the firmware requires ec_event_clearing=query.
So we won't enable it.

> 
> # Hold Fn, press and release F3
> ACPI : EC: IRQ (3)
> ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
> ACPI : EC: Command(UNDEF) submitted/blocked
> ACPI : EC: Event started
> ACPI : EC: 2: Increase command
> ACPI : EC: Command(UNDEF) started
> ACPI : EC: TASK (3)
> ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
> ACPI : EC: EC_SC(W) = 0x84
> ACPI : EC: IRQ (0)
> ACPI : EC: EC_SC(R) = 0x09 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=1
> ACPI : EC: EC_DATA(R) = 0x0c
> ACPI : EC: Command(UNDEF) completed by hardware
> ACPI : EC: Command(UNDEF) stopped
> ACPI : EC: 1: Decrease command
> ACPI : EC: Event stopped
> ACPI : EC: TASK (3)
> ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
> ACPI : EC: Command(UNDEF) unblocked
> 
> # Still hold Fn, press and release F4
> ACPI : EC: IRQ (3)
> ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
> ACPI : EC: Command(UNDEF) submitted/blocked
> ACPI : EC: Event started
> ACPI : EC: 2: Increase command
> ACPI : EC: Command(UNDEF) started
> ACPI : EC: TASK (3)
> ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
> ACPI : EC: EC_SC(W) = 0x84
> ACPI : EC: IRQ (1)
> ACPI : EC: EC_SC(R) = 0x09 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=1
> ACPI : EC: EC_DATA(R) = 0x0d
> ACPI : EC: Command(UNDEF) completed by hardware
> ACPI : EC: Command(UNDEF) stopped
> ACPI : EC: 1: Decrease command
> ACPI : EC: Event stopped
> ACPI : EC: TASK (3)
> ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
> ACPI : EC: Command(UNDEF) unblocked
> 
> # Release Fn
> ACPI : EC: IRQ (3)
> ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
> ACPI : EC: Command(UNDEF) submitted/blocked
> ACPI : EC: Event started
> ACPI : EC: 2: Increase command
> ACPI : EC: Command(UNDEF) started
> ACPI : EC: TASK (3)
> ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
> ACPI : EC: EC_SC(W) = 0x84
> ACPI : EC: IRQ (1)
> ACPI : EC: EC_SC(R) = 0x09 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=1
> ACPI : EC: EC_DATA(R) = 0xd7
> ACPI : EC: Command(UNDEF) completed by hardware
> ACPI : EC: Command(UNDEF) stopped
> ACPI : EC: 1: Decrease command
> ACPI : EC: Event stopped
> ACPI : EC: TASK (3)
> ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
> ACPI : EC: Command(UNDEF) unblocked
> 
> For some reason the _Qxx methods themselves are not invoked though. Maybe
> that is because acpi_ec_register_query_methods is not invoked (and no
> handlers are registered via acpi_ec_add).
> 
> I added some pr_warn to acpi_ec_add and more, but it does not seem to be
> called at all... that is strange.
> 
> Note that I will be returning this device soon, hopefully Luya can assist
> further in obtaining more debugging information as needed.

Anyway please upload the full dmesg here so that I can also offer correct help.
Comment 40 Peter Wu 2016-08-26 11:17:10 UTC
(In reply to Lv Zheng from comment #38)
[..]
> > it cannot be used to trace all methods under a device unless I am mistaken?
> 
> You are wrong.
> acpi.trace_state=method trace one method.
> acpi.trace_state=enable trace all methods.

"All methods" is globally, it would be nice if there was something like acpi.trace_state=device acpi.trace_device=\_SB.PCI0.SBRG.EC0 to ignore all others. I'll give it a try, hopefully it is less noisy than the global acpi_level/layer thing.

> Please upload the full dmesg here.

I will do for the next test. Note that there are already some dmesg here, in the previous comment I only enabled dyndbg so these were really the only additional lines.

> However, this looks like the known issue that can be fixed by the posted
> fixes:
> https://patchwork.kernel.org/patch/9260899/
> https://patchwork.kernel.org/patch/9260873/
> https://patchwork.kernel.org/patch/9260877/
> https://patchwork.kernel.org/patch/9260937/
> https://patchwork.kernel.org/patch/9260891/
> 
> Could you also give them a try?

I have created a bundle with these patches to make downloading easier (https://patchwork.kernel.org/bundle/Lekensteyn/bug115021/). However, trying to apply it on top of v4.8-rc3ish fails in patch 3. What is the base revision?
I don't see a "acpi_ec_pm" structure (the conflict occurs in ec.c:1706).

git am also fails to apply https://patchwork.kernel.org/patch/9252417/ due to a fuzz of two lines. Do you have a git tree or better reference point?
Comment 41 Peter Wu 2016-08-26 16:19:27 UTC
Created attachment 230351 [details]
dmesg for v4.8-rc2-348-g6040e57 + six ACPI EC patches

I found your patch in linux-next. The attached dmesg uses patches from

https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git/commit/drivers/acpi/ec.c?id=df45db6177f8dde380d44149cca46ad800a00575
https://patchwork.kernel.org/bundle/Lekensteyn/bug115021/

$ git log --oneline --reverse -n7
6040e57 Make the hardened user-copy code depend on having a hardened allocator
e037f2c ACPI / EC: Add PM operations for suspend/resume noirq stage
8661d73 ACPI / EC: Add EC_FLAGS_QUERY_ENABLED to reveal a hidden logic
edae934 ACPI / EC: Fix an issue that SCI_EVT cannot be detected after event is enabled
424ccda ACPI / EC: Add PM operations to improve event handling for resume process
8a01eb6 ACPI / EC: Add PM operations to improve event handling for suspend process
852cf55 ACPI / EC: Enable event freeze mode to improve event handling for suspend process


Unfortunately there is no improvement. Pressing Fn at the 40 seconds point starts the flood. After suspend/resume (117 seconds), the fan spins crazy and somehow IRQ 0 instead of 3 is reported (see logs).

grep . /sys/firmware/acpi/interrupts/* however only shows activity for gpe15.

(After another test, it seems that the event of s/r triggers the high fan speed which persists until poweroff, rebooting is not sufficient. Not pressing Fn before suspend does not affect the result.)
Comment 42 Peter Wu 2016-08-27 00:09:23 UTC
Created attachment 230391 [details]
dmesg for v4.8-rc2-348-g6040e57 + six ACPI EC patches + debug patch

Some other observations:

The EC0._ADR method exists, but always returns 0 (no device present). This prevents the ec driver from registering to the device (which also results in no workqueue for _Qxx evaluations and no call to acpi_ec_add which would call acpi_ec_enable_event in the end).

In a sample of 172 tarballs with an acpidump.txt[0], there were 47 submissions (mostly Asus and Lenovo laptops) that have ECDT, none of the PNP0C09 devices have a _STA method. The laptop in this bug is quite unique in that regard.

An ACPI trace on Windows 10 showed that _STA and _HID were both evaluated, but things like _GPE, _INI and _CRS were not invoked[1].

I have attached a new dmesg with some additional debugging information. (huh, why is ec->handle -1? Something is not initialized?)

 [0]: https://bugs.launchpad.net/lpbugreporter/+bug/752542
 [1]: https://lekensteyn.nl/files/Asus-X550ZE/windbg-kd-acpi-traceon.txt
Comment 43 Peter Wu 2016-08-27 00:09:41 UTC
Created attachment 230401 [details]
debug patch
Comment 44 Peter Wu 2016-08-27 10:37:30 UTC
Created attachment 230451 [details]
230391: dmesg for v4.8-rc2-348-g6040e57 + six ACPI EC patches + debug patch + DSDT override (remove _STA)

With a DSDT override to remove the EC0._STA method, things magically start working... See attached dmesg.

Hopefully this is sufficient information to continue the investigation, I cannot test further since I will be returning the device today, Luya should be able to continue testing though.
Comment 45 Peter Wu 2016-08-27 11:09:18 UTC
So once this ACPI EC bug is fixed, all hotkeys should work.

Fn+F1 (suspend): verified with acpi_listen:
button/sleep SBTN 00000080 00000000
button/sleep PNP0C0E:00 00000080 00000004

Fn+F2 (Toggle wifi): working (verify with rfkill list)
Fn+F3/F4 (keyboard backlight down/up): _Qxx (no-op, kbd has no backlight)
Fn+F5 (br. down): acpi_listen: video/brightnessdown BRTDN 00000087 00000000
Fn+F6 (br. up): acpi_listen: video/brightnessup BRTUP 00000086 00000000
Fn+F7 (display backlight on/off): works
Fn+F8 (toggle monitor): sends Meta+P shortcut (verified with showkey)
Fn+F9 (toggle touchpad): sends keycode 191 (verified with showkey)
Fn+F10 (mute): acpi_listen: button/mute MUTE 00000080 00000000 K
Fn+F11 (volume up): acpi_listen: button/volumedown VOLDN 00000080 00000000 K
Fn+F12 (volume down): acpi_listen: button/volumedown VOLDN 00000080 00000000 K
Fn+V (Camera): keycode 212 (verified with showkey)
Comment 46 Luya Tshimbalanga 2016-08-28 03:12:17 UTC
Thank you Peter for the hard work. I will continue the test and need guidance because this is an uncharted territory for me.
Comment 47 Lv Zheng 2016-08-29 01:20:08 UTC
(In reply to Peter Wu from comment #44)
> Created attachment 230451 [details]
> 230391: dmesg for v4.8-rc2-348-g6040e57 + six ACPI EC patches + debug patch
> + DSDT override (remove _STA)
> 
> With a DSDT override to remove the EC0._STA method, things magically start
> working... See attached dmesg.

Do you mean this:
            Method (_STA, 0, NotSerialized)  // _STA: Status
            {
                Return (Zero)
            }
I have no idea why such thing is left by the BIOS vendor.

It then sounds like that:
The BIOS vendor wants the boot EC to be used instead of the namespace EC.
And the bug shows that the developer of this code cares no about spec compliance, but wants other OSPMs to work as exactly as Windows dose.

I think in Windows, this is automatically ensured and no issue could exist.

But Linux contains different namespace enumeration order than the Windows.
So we have to place an "acpi_ec_dsdt_probe" in order to remove several useless quirks from Linux EC driver.

The only correct fix should be to fix Linux device enumeration.
But that's too big and is beyond this issue.

If we want to work it around, we should do some device enumeration stuff in acpi_ec_dsdt_probe() before invoking acpi_ec_alloc().

Thanks
Lv
Comment 48 Lv Zheng 2016-08-29 01:56:05 UTC
Normally according to the spec, BIOS developers should always first prepare a good DSDT EC. And if the EC is needed to be used during table loading, the developers may provide ECDT EC. So the DSDT EC should always be correct while the ECDT EC may not.

But this bug is reporting a new kind of fact that the ECDT EC could be the correct one while the DSDT EC could be the wrong one. Which sounds like "putting the cart before the horse".

And this code is entirely useless:
            Method (_STA, 0, NotSerialized)  // _STA: Status
            {
                Return (Zero)
            }
So I doubt if this is a real issue or is just a bug created due to white box unit test.

However we'll fix this kind of issue, but I need to say this once about my feelings of seeing such kind of bugs.
IMO, we need to put more efforts on real issues rather than such coverity issues as there are actually many bugs waiting for us to solve.

Thanks
Lv
Comment 49 Lv Zheng 2016-08-29 09:37:37 UTC
Created attachment 231121 [details]
[PATCH] ACPI / EC: Add fully functioning ECDT EC

Please try this patch and upload the full dmesg here.

Thanks
Comment 50 Luya Tshimbalanga 2016-08-30 00:06:11 UTC
Created attachment 231371 [details]
updated dmesg with kernel 4.8.0-rc4

updated dmesg with kernel 4.8.0-rc4
Comment 51 Lv Zheng 2016-08-30 03:03:03 UTC
Hmm, I'll try to improve the fix.
It looks this line is not correct:
1403 	acpi_walk_namespace(ACPI_TYPE_METHOD, ec->handle, 1,
1404 			    acpi_ec_register_query_methods, NULL, ec, NULL);
It looks I should find a correct ec->handle (from ECDT) to be used here.

However, I cannot understand the log, it seems to be warning generated in drivers/net/wireless/ath/ath9k/beacon.c.

It's wireless beacon related, doesn't seem to be related to this bug.
Comment 52 Lv Zheng 2016-08-30 03:14:50 UTC
Hi, Peter

(In reply to Peter Wu from comment #42)
> 
> An ACPI trace on Windows 10 showed that _STA and _HID were both evaluated,
> but things like _GPE, _INI and _CRS were not invoked[1].

How do you achieve this?
Could you upload ACPI trace log here?

Thanks
Comment 53 Luya Tshimbalanga 2016-08-30 03:22:46 UTC
Created attachment 231381 [details]
dmesg X550ZE with dyndbg enabled
Comment 54 Lv Zheng 2016-08-30 04:56:57 UTC
I found this in the AMLI log:
	Line 80: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SBRG.EC0._STA)
	Line 88: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SBRG.EC0._STA)
	Line 1908: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q15)
	Line 1965: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q14)
	Line 1967: AMLI: ffffe00093e3f080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q15)
	Line 1969: AMLI: ffffe0009398b080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q15)
	Line 1971: AMLI: ffffe000943b0080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q15)
	Line 1973: AMLI: ffffe00094a30800: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q14)
	Line 1975: AMLI: ffffe00094c38800: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q14)
	Line 1977: AMLI: ffffe00094989800: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q14)
	Line 1979: AMLI: ffffe00094b5e800: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q14)
	Line 1981: AMLI: ffffe00094b5e800: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q14)
	Line 1983: AMLI: ffffe00094334040: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q15)
	Line 1985: AMLI: ffffe0008c166040: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q15)
	Line 1987: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q15)
	Line 1989: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q15)
	Line 1991: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q14)
	Line 1993: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q14)
	Line 1995: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q15)
	Line 1997: AMLI: ffffe00094b5e800: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q14)
	Line 1999: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q15)
	Line 2001: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q14)
	Line 2003: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q15)
	Line 2005: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q14)
	Line 2007: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q15)
	Line 2009: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q14)
	Line 2011: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q15)
	Line 2013: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q14)
	Line 2015: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q14)
	Line 2017: AMLI: ffffe00094b5e800: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q15)
	Line 2019: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q14)
	Line 2021: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q13)
	Line 2023: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q15)
	Line 2025: AMLI: ffffe00094b5e800: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2027: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q0C)
	Line 2029: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q0D)
	Line 2031: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2045: AMLI: ffffe000949b7800: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q0B)
	Line 2047: AMLI: ffffe00093e84080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q0B)
	Line 2049: AMLI: ffffe000948db800: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2051: AMLI: ffffe00094b5e800: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q0C)
	Line 2053: AMLI: ffffe0008c164040: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q0C)
	Line 2055: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q0D)
	Line 2057: AMLI: ffffe0009400c080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2059: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q0E)
	Line 2061: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q0F)
	Line 2065: AMLI: ffffe00092e3a080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q0F)
	Line 2069: AMLI: ffffe00094b37080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2075: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q10)
	Line 2077: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2079: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q10)
	Line 2081: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2083: AMLI: ffffe00092fa9800: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q10)
	Line 2085: AMLI: ffffe0009407c080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2087: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2089: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2091: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2097: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q10)
	Line 2099: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2205: AMLI: ffffe00094569800: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2211: AMLI: ffffe00094569800: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2213: AMLI: ffffe00093890080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2255: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q12)
	Line 2257: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q12)
	Line 2259: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2261: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2263: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q13)
	Line 2265: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q14)
	Line 2267: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q15)
	Line 2269: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2275: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q72)
	Line 2277: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2279: AMLI: ffffe0008c166040: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q6D)
	Line 2281: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2283: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q6D)
	Line 2285: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q6E)
	Line 2287: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2293: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q6D)
	Line 2295: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2297: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q6B)
	Line 2299: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q6B)
	Line 2301: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q6C)
	Line 2303: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2305: AMLI: ffffe00090617280: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q6F)
	Line 2311: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2328: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q71)
	Line 2330: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q70)
	Line 2332: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2338: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2340: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2384: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2386: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2388: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2402: AMLI: ffffe0008c164040: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2404: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2406: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2408: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q0A)
	Line 2410: AMLI: ffffe0008c166040: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2416: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q10)
	Line 2418: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2420: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2422: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q10)
	Line 2424: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)
	Line 2426: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q14)
	Line 2428: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._QD7)

Intresting thing is:
EC enumeration seems to be a part of the entire enumeration process:
	Line 32: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.S900._STA)
	Line 42: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.BAT0._STA)
	Line 48: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.BAT0._STA)
	Line 74: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SBRG.ECIR._STA)
	Line 76: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SBRG.PS2K._STA)
	Line 78: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SBRG.PS2M._STA)
	Line 80: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SBRG.EC0._STA)
	Line 82: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SBRG.ECIR._STA)
	Line 84: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SBRG.PS2K._STA)
	Line 86: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SBRG.PS2M._STA)
	Line 88: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SBRG.EC0._STA)
	Line 190: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SBRG.PS2K._STA)
	Line 202: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SBRG.PS2K._STA)
	Line 212: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SBRG.PS2M._STA)
	Line 224: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SBRG.PS2M._STA)
	Line 466: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.PB21.HDAU._STA)
	Line 472: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.PB21.HDAU._STA)
	Line 714: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SATA.PRID._STA)
	Line 716: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SATA.SECD._STA)
	Line 718: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SATA.PRT2._STA)
	Line 720: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SATA.ODD8._STA)
	Line 722: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SATA.ODDZ._STA)
	Line 724: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SATA.ODDL._STA)
	Line 726: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SATA.PRID._STA)
	Line 728: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SATA.SECD._STA)
	Line 730: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SATA.PRT2._STA)
	Line 732: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SATA.ODD8._STA)
	Line 740: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SATA.ODDZ._STA)
	Line 742: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SATA.ODDL._STA)
	Line 748: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0.SATA.ODD8._STA)
	Line 1062: AMLI: ffffe0008c092740: EvalNameSpaceObject(\_SB.PCI0._STA)
	Line 1108: AMLI: ffffe000913d8040: EvalNameSpaceObject(\_SB.PCI0._STA)
	Line 1116: AMLI: ffffe0008c113700: EvalNameSpaceObject(\_SB.PCI0.VGA._STA)
	Line 1324: AMLI: ffffe0008c113700: AsyncEvalObject(\_SB.PCI0.VGA._STA)
	Line 1326: AMLI: ffffe0008c126040: AsyncEvalObject(\_SB.PCI0.VGA._STA)
	Line 1328: AMLI: ffffe0008c113700: EvalNameSpaceObject(\_SB.PCI0.VGA._STA)
	Line 1332: AMLI: ffffe0008c113700: EvalNameSpaceObject(\_SB.PCI0.VGA._STA)
	Line 1334: AMLI: ffffe0008c113700: AsyncEvalObject(\_SB.PCI0.SATA.ODD8._STA)
	Line 1340: AMLI: ffffe0008c126040: AsyncEvalObject(\_SB.PCI0.SATA.ODD8._STA)
	Line 1364: AMLI: ffffe0008c113700: AsyncEvalObject(\_SB.PCI0.SBRG.PS2K._STA)
	Line 1366: AMLI: ffffe0008c126040: AsyncEvalObject(\_SB.PCI0.SBRG.PS2K._STA)
	Line 1372: AMLI: ffffe000913cf040: EvalNameSpaceObject(\_SB.PCI0.SBRG.PS2K._STA)
	Line 1374: AMLI: ffffe0008c113700: AsyncEvalObject(\_SB.PCI0.SBRG.PS2M._STA)
	Line 1376: AMLI: ffffe0008c126040: AsyncEvalObject(\_SB.PCI0.SBRG.PS2M._STA)
	Line 1382: AMLI: ffffe0008c113700: AsyncEvalObject(\_SB.PCI0.BAT0._STA)
	Line 1384: AMLI: ffffe0008c126040: AsyncEvalObject(\_SB.PCI0.BAT0._STA)
	Line 1466: AMLI: ffffe0009371a040: EvalNameSpaceObject(\_SB.PCI0.SBRG.PS2M._STA)
	Line 1474: AMLI: ffffe0008c113700: EvalNameSpaceObject(\_SB.PCI0.SATA.ODD8._STA)
	Line 1478: AMLI: ffffe0008c113700: EvalNameSpaceObject(\_SB.PCI0.SATA.ODD8._STA)
	Line 1484: AMLI: ffffe0008c113700: EvalNameSpaceObject(\_SB.PCI0.SBRG.PS2K._STA)
	Line 1486: AMLI: ffffe0008c113700: EvalNameSpaceObject(\_SB.PCI0.SBRG.PS2K._STA)
	Line 1488: AMLI: ffffe0008c113700: EvalNameSpaceObject(\_SB.PCI0.SBRG.PS2M._STA)
	Line 1490: AMLI: ffffe0008c113700: EvalNameSpaceObject(\_SB.PCI0.SBRG.PS2M._STA)
	Line 1492: AMLI: ffffe0009371a040: EvalNameSpaceObject(\_SB.PCI0.BAT0._STA)
	Line 1494: AMLI: ffffe0008c113700: EvalNameSpaceObject(\_SB.PCI0.BAT0._STA)
	Line 1498: AMLI: ffffe0008c113700: EvalNameSpaceObject(\_SB.PCI0.BAT0._STA)
	Line 1594: AMLI: ffffe0008c113700: EvalNameSpaceObject(\_SB.PCI0._STA)
	Line 1600: AMLI: ffffe0008c113700: EvalNameSpaceObject(\_SB.PCI0._STA)
	Line 1602: AMLI: ffffe000913cb040: EvalNameSpaceObject(\_SB.PCI0._STA)
	Line 1604: AMLI: ffffe000913cb040: EvalNameSpaceObject(\_SB.PCI0._STA)
	Line 2039: AMLI: ffffe0008c0a2040: AsyncEvalObject(\_SB.PCI0.SATA.ODD8._STA)
	Line 2043: AMLI: ffffe0008c126040: AsyncEvalObject(\_SB.PCI0.SATA.ODD8._STA)
	Line 2705: AMLI: ffffe0008c093040: AsyncEvalObject(\_SB.PCI0.SATA.ODD8._STA)
	Line 2709: AMLI: ffffe0008c126040: AsyncEvalObject(\_SB.PCI0.SATA.ODD8._STA)
	Line 2713: AMLI: ffffe0009470a080: AsyncEvalObject(\_SB.PCI0.SBRG.PS2K._STA)
	Line 2715: AMLI: ffffe0009470a080: AsyncEvalObject(\_SB.PCI0.SBRG.PS2M._STA)
	Line 2717: AMLI: ffffe0009470a080: AsyncEvalObject(\_SB.PCI0.BAT0._STA)
	Line 2719: AMLI: ffffe0008c126040: AsyncEvalObject(\_SB.PCI0.SBRG.PS2K._STA)
	Line 2721: AMLI: ffffe0008c126040: AsyncEvalObject(\_SB.PCI0.SBRG.PS2M._STA)
	Line 2723: AMLI: ffffe0008c126040: AsyncEvalObject(\_SB.PCI0.BAT0._STA)
	Line 2725: AMLI: ffffe000939f9080: AsyncEvalObject(\_SB.PCI0.SATA.ODD8._STA)
	Line 2729: AMLI: ffffe0008c126040: AsyncEvalObject(\_SB.PCI0.SATA.ODD8._STA)
	Line 2731: AMLI: ffffe0008c0a2040: AsyncEvalObject(\_SB.PCI0.VGA._STA)
	Line 2733: AMLI: ffffe0008c126040: AsyncEvalObject(\_SB.PCI0.VGA._STA)
	Line 2737: AMLI: ffffe0008c093040: AsyncEvalObject(\_SB.PWRB._STA)
	Line 2739: AMLI: ffffe0008c126040: AsyncEvalObject(\_SB.PWRB._STA)
	Line 2741: AMLI: ffffe00094878800: AsyncEvalObject(\_SB.PCI0._STA)
	Line 2743: AMLI: ffffe0008c126040: AsyncEvalObject(\_SB.PCI0._STA)

While in Linux, this matches my understanding - namespace EC should only be used when it is enumerated.
However the enumeration order cannot be ensured to be same between Linux and Windows. And in Linux, users reported on the bugzilla that without enabling EC access availability very early before the namespace initialization, some error logs (though not fatal) could be seen, so Linux prepared a special function (acpi_ec_dsdt_probe) to make EC access availibity ready before enumerating the namespace.

However this report indicates us another gap (except the enumeration order gap):
If the namespace EC (DSDT EC in short) is not ready, EC access availability can be kept using the ECDT EC. In Linux, that requres _Qxx control methods to be registered for the ECDT EC. I have never seen a Linux EC driver version doing this before, _Qxx registration is only invoked in acpi_ec_add(). So this bug indicates a gap for Linux.

In order to register _Qxx for the ECDT EC, the namespace path in ECDT should be correct. As far as I know, there are platforms in the real world reporting bad namespace path in ECDT. I'm not sure if we need to handle this in the fix.

There are also another undetermined issue in the current EC driver - whether there could be 2 ACPI EC device in the namespace? As the fix will touch the code related to the "boot EC", "first EC", it surely will have to consider this. I'm not sure if we need to handle this in the fix.

Though this bug finds the new road for Linux, but it looks it is not so easy to reach the end of the road.

Thanks
Comment 55 Lv Zheng 2016-08-30 04:59:48 UTC
(In reply to Luya Tshimbalanga from comment #53)
> Created attachment 231381 [details]
> dmesg X550ZE with dyndbg enabled

Good! Thanks for the update.
I still cannot see the head of the log because of the ath9k warning.
Is that possible for you to
1. either disable this wifi driver, or
2. enlarge kernel log buffer

Thanks in advance.

Best regards
Lv
Comment 56 Lv Zheng 2016-08-30 06:26:38 UTC
Created attachment 231391 [details]
[PATCH] ACPI / EC: Add fully functioning ECDT EC

Please try the revised version.
I also tested it with customized tables:
1. DSDT is customized to return Zero from EC _STA
2. ECDT is customized to have its ID pointing to _Qxx methods' parent node
I can see _Qxx methods evaluated after applying this patch.

Thanks
Comment 57 Lv Zheng 2016-08-30 06:28:38 UTC
Created attachment 231401 [details]
[PATCH] ACPI / EC: Add fully functioning ECDT EC

Just deprecates old patches in order to make this bugzilla entry cleaner
Comment 58 Lv Zheng 2016-08-30 07:09:07 UTC
Hi, Luya

Please
1. apply attachment 23140 [details]
2. boot the built kernel with the following parameters:
   acpi.trace_state=enable dyndbg="file ec.c +p"
3. dmesg -c > boot.log
4. please try hotkeys and let me know if they are working now
5. demsg -c > test.log
6. upload boot.log and test.log here.

Thanks
Lv
Comment 59 Luya Tshimbalanga 2016-08-30 07:17:30 UTC
Created attachment 231411 [details]
dmesg X550ZE with enabled debug and disabled ath wifi

Based on Peter dmesg, boot parameter below added
modprobe.blacklist=toshiba_wmi,asus_nb_wmi,asus_wmi dyndbg="file ec.c +p" acpi.trace_state=enable
Comment 60 Luya Tshimbalanga 2016-08-30 07:19:05 UTC
I just saw the message after refreshing the browser. I will post the result soon.
Comment 61 Peter Wu 2016-08-30 10:00:51 UTC
(In reply to Lv Zheng from comment #54)
> I found this in the AMLI log:
> Line 80: AMLI: ffffe0008c092740:
> EvalNameSpaceObject(\_SB.PCI0.SBRG.EC0._STA)
> Line 88: AMLI: ffffe0008c092740:
> EvalNameSpaceObject(\_SB.PCI0.SBRG.EC0._STA)
> Line 1908: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q15)
> Line 1965: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q14)
[..]
> However this report indicates us another gap (except the enumeration order
> gap):
> If the namespace EC (DSDT EC in short) is not ready, EC access availability
> can be kept using the ECDT EC. In Linux, that requres _Qxx control methods
> to be registered for the ECDT EC. I have never seen a Linux EC driver
> version doing this before, _Qxx registration is only invoked in
> acpi_ec_add(). So this bug indicates a gap for Linux.

Do note that the _Q15, _Q14 and other methods were only invoked after booting by pressing Fn+F12, Fn+F11, etc. The _STA invocation was part of the enumeration process, but the _Qxx happened long after that.

> There are also another undetermined issue in the current EC driver - whether
> there could be 2 ACPI EC device in the namespace? As the fix will touch the
> code related to the "boot EC", "first EC", it surely will have to consider
> this. I'm not sure if we need to handle this in the fix.

A typical platform has probably only one EC, port 0x62/0x66 cannot really be shared. Maybe this could be improved: at boot you start the EC (from ECDT), but then you stop it again because one is detected in the DSDT. Can't you just detect that the paths are exactly the same and avoid this restart?
Comment 62 Luya Tshimbalanga 2016-08-30 22:43:30 UTC
Created attachment 231501 [details]
dmesg boot from X550Z

Here is the requested boot.log
Comment 63 Luya Tshimbalanga 2016-08-30 22:57:42 UTC
Created attachment 231511 [details]
dmesg result pressing Fn keys on x550z

For the first time, all Fn+key but three (Fn+C, Fn+V and Fn+Space) are working well. I am very excited of the result after looking for so long how to resolve it once for all.

Little do I know ACPI EC makes a lot of difference and that bug led to the discovery of new ACPI EC scheme showing how really behind Linux kernel version is and a bad practice from BIOS vendor. Hopefully that change will unlock the accessibility to other laptop having similar issue.
It will be great the fix makes it on 4.8.0.
Comment 64 Lv Zheng 2016-08-30 23:17:53 UTC
(In reply to Peter Wu from comment #61)
> (In reply to Lv Zheng from comment #54)
> > I found this in the AMLI log:
> > Line 80: AMLI: ffffe0008c092740:
> > EvalNameSpaceObject(\_SB.PCI0.SBRG.EC0._STA)
> > Line 88: AMLI: ffffe0008c092740:
> > EvalNameSpaceObject(\_SB.PCI0.SBRG.EC0._STA)
> > Line 1908: AMLI: fffff800db744780: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q15)
> > Line 1965: AMLI: ffffe00093ecb080: AsyncEvalObject(\_SB.PCI0.SBRG.EC0._Q14)
> [..]
> > However this report indicates us another gap (except the enumeration order
> > gap):
> > If the namespace EC (DSDT EC in short) is not ready, EC access availability
> > can be kept using the ECDT EC. In Linux, that requres _Qxx control methods
> > to be registered for the ECDT EC. I have never seen a Linux EC driver
> > version doing this before, _Qxx registration is only invoked in
> > acpi_ec_add(). So this bug indicates a gap for Linux.
> 
> Do note that the _Q15, _Q14 and other methods were only invoked after
> booting by pressing Fn+F12, Fn+F11, etc. The _STA invocation was part of the
> enumeration process, but the _Qxx happened long after that.

_Qxx surely is not a part of enumeration. :)

> 
> > There are also another undetermined issue in the current EC driver -
> whether
> > there could be 2 ACPI EC device in the namespace? As the fix will touch the
> > code related to the "boot EC", "first EC", it surely will have to consider
> > this. I'm not sure if we need to handle this in the fix.
> 
> A typical platform has probably only one EC, port 0x62/0x66 cannot really be
> shared.

According to the spec, it could be up to 6 ECs in a platform.
And HP has replied us that they have a 2-ECs platform, but we couldn't find that 2-ECs via the acpidump.
IMO, EC could be not only the EC device used in the AML code (let me call it ACPI EC), but also the others (for example, SMI EC).
According to our observation, no 2 ACPI ECs in a platform can be seen.
But we also noticed that: _Qxx are always underneath the EC devices and there seems to be no / or rare EmbeddedControl operation regions out of the scope of the ACPI EC device node.
So this is an undetermined topic.

> Maybe this could be improved: at boot you start the EC (from ECDT),
> but then you stop it again because one is detected in the DSDT. Can't you
> just detect that the paths are exactly the same and avoid this restart?

Sure. We are about to do that, however it requires lots of code to ensure synchronization. So the timing of doing that should be considered.
Comment 65 Lv Zheng 2016-08-30 23:20:12 UTC
(In reply to Luya Tshimbalanga from comment #63)
> Created attachment 231511 [details]
> dmesg result pressing Fn keys on x550z
> 
> For the first time, all Fn+key but three (Fn+C, Fn+V and Fn+Space) are
> working well. I am very excited of the result after looking for so long how
> to resolve it once for all.

Glad to see this fixed.
Let me mark it as resolved.

> 
> Little do I know ACPI EC makes a lot of difference and that bug led to the
> discovery of new ACPI EC scheme showing how really behind Linux kernel
> version is and a bad practice from BIOS vendor.

This the good thing, thanks for your effort.

> Hopefully that change will
> unlock the accessibility to other laptop having similar issue.
> It will be great the fix makes it on 4.8.0.

OK, I'll follow peter's track to ping reporters of other bugs to try this fix.

Thanks
Lv
Comment 66 Luya Tshimbalanga 2016-08-30 23:58:10 UTC
(In reply to Lv Zheng from comment #65)
> (In reply to Luya Tshimbalanga from comment #63)

> > Little do I know ACPI EC makes a lot of difference and that bug led to the
> > discovery of new ACPI EC scheme showing how really behind Linux kernel
> > version is and a bad practice from BIOS vendor.
> 
> This the good thing, thanks for your effort.

Thank you as well for the patch and response and Peter for further investigating the issue. Overall, it is a good team work.

> > Hopefully that change will
> > unlock the accessibility to other laptop having similar issue.
> > It will be great the fix makes it on 4.8.0.
> 
> OK, I'll follow peter's track to ping reporters of other bugs to try this
> fix.

Really appreciated.
Comment 67 Peter Wu 2016-08-31 11:06:16 UTC
(In reply to Lv Zheng from comment #57)
> Created attachment 231401 [details]
> [PATCH] ACPI / EC: Add fully functioning ECDT EC
> 
> Just deprecates old patches in order to make this bugzilla entry cleaner

Shouldn't you reset boot_ec->handle if acpi_set_boot_ec fails?

+	boot_ec->handle = handle;
+	ret = acpi_set_boot_ec(boot_ec, false, true);
+
+error:
+	if (ret)
+		acpi_handle_warn(boot_ec->handle, "cannot handle events\n");
+	return ret;
+}
Comment 68 Lv Zheng 2016-09-01 01:16:06 UTC
(In reply to Peter Wu from comment #67)
> (In reply to Lv Zheng from comment #57)
> > Created attachment 231401 [details]
> > [PATCH] ACPI / EC: Add fully functioning ECDT EC
> > 
> > Just deprecates old patches in order to make this bugzilla entry cleaner
> 
> Shouldn't you reset boot_ec->handle if acpi_set_boot_ec fails?
> 
> +     boot_ec->handle = handle;
> +     ret = acpi_set_boot_ec(boot_ec, false, true);
> +
> +error:
> +     if (ret)
> +             acpi_handle_warn(boot_ec->handle, "cannot handle events\n");
> +     return ret;
> +}

I think no.

If you checked the acpi_ec_add(), it wouldn't reset ec->handle in case enabling of the ec device (acpi_set_boot_ec()) has failed.

So it means several steps of the "state machine of initializing the EC device":
1. obtain gpe/io
2. register address space handler
3. obtain namespace handle

Failure here.

4. register gpe handler
5. register _Qxx handlers
6. start to handle event

So there seems to be no need to reset the handle for now unless there is an explicit requirement.

Thanks
Comment 69 Lv Zheng 2016-09-01 02:04:58 UTC
(In reply to Lv Zheng from comment #68)
> (In reply to Peter Wu from comment #67)
> > (In reply to Lv Zheng from comment #57)
> > > Created attachment 231401 [details]
> > > [PATCH] ACPI / EC: Add fully functioning ECDT EC
> > > 
> > > Just deprecates old patches in order to make this bugzilla entry cleaner
> > 
> > Shouldn't you reset boot_ec->handle if acpi_set_boot_ec fails?
> > 
> > +   boot_ec->handle = handle;
> > +   ret = acpi_set_boot_ec(boot_ec, false, true);
> > +
> > +error:
> > +   if (ret)
> > +           acpi_handle_warn(boot_ec->handle, "cannot handle events\n");
> > +   return ret;
> > +}
> 
> I think no.
> 
> If you checked the acpi_ec_add(), it wouldn't reset ec->handle in case
> enabling of the ec device (acpi_set_boot_ec()) has failed.
> 
> So it means several steps of the "state machine of initializing the EC
> device":
> 1. obtain gpe/io
> 2. register address space handler
> 3. obtain namespace handle
> 
> Failure here.
> 
> 4. register gpe handler
> 5. register _Qxx handlers
> 6. start to handle event
> 
> So there seems to be no need to reset the handle for now unless there is an
> explicit requirement.

Hi, Peter

I found that acpi_ec_add() never sets ec->handle.
This leaves a bug to _DEP support.

I'll take care of this when sending an upstream patch.
Probably should put handle assignment into acpi_set_boot_ec().

I'll do unit test locally, so won't post the patch here.
Please help to take a look at the patch when you see it in the community.
And comment me if you still can see problems.

Thanks in advance
Lv
Comment 71 Luya Tshimbalanga 2016-11-08 02:23:43 UTC
Excellent! Thank you for all efforts!