[BUG] Isues with Macros

[xyphro]

I use the latest Github FW and defined macros which send ALT codes and assigned them to a key. The there are 3 x 30ms delays part of the Macro.
When I press the Macro key slowly again and again it works GREAT.

When I press the Macro key fast twice (or more) the firmware crashes:
Traceback (most recent call last):
File "kmk/kmk_keyboard.py", line 443, in go
File "kmk/kmk_keyboard.py", line 517, in _main_loop
File "kmk/kmk_keyboard.py", line 253, in _process_timeouts
File "kmk/modules/macros.py", line 304, in task
File "kmk/modules/macros.py", line 294, in process_macro_async
File "kmk/modules/macros.py", line 313, in send_key_buffer
File "kmk/kmk_keyboard.py", line 228, in resume_process_key
ValueError: object not in sequence
6359287 kmk.keyboard: cleaning up...
6359289 kmk.keyboard: ...done

Any Idea how to fix?

[xyphro]

Here a complete example. I define here a MACRO in variable MACROTEST and it is added to my keymap.

Steps to reproduce:

• Run the file
• Press the macro key quickly a few times after each other
• Watch CDC uart ouput to see KMK crashing

print("Starting")

import board

from kmk.kmk_keyboard import KMKKeyboard
from kmk.keys import KC
from kmk.scanners import DiodeOrientation
from kmk.modules.macros import Tap, Delay, Press, Release
from kmk.modules.macros import Macros
from kmk.modules.macros import Macros, UnicodeModeIBus, UnicodeModeMacOS, UnicodeModeWinC

#### Initialize keyboard
keyboard = KMKKeyboard()

keyboard.col_pins = (board.GP0,board.GP1,board.GP2, board.GP3, board.GP4, board.GP5, board.GP6, board.GP7, board.GP8, board.GP9, board.GP10, board.GP11, board.GP12, board.GP13, board.GP14, board.GP15, board.GP16, board.GP17)
keyboard.row_pins = (board.GP18, board.GP19, board.GP20, board.GP21, board.GP22, board.GP28)
keyboard.diode_orientation = DiodeOrientation.COL2ROW

macros = Macros(unicode_mode=UnicodeModeWinC)

# define a Macro
MACROTEST = KC.MACRO(
    Press(KC.LALT),
    Delay(30),
    Tap(KC.P0),
    Delay(30),
    Tap(KC.P1),
    Delay(30),
    Tap(KC.P7),
    Delay(30),
    Tap(KC.P6),
    Delay(30),
    Release(KC.LALT),
)


_____ = KC.NO
keyboard.keymap = [
    [KC.ESC   , _____  , KC.F1   , KC.F2, KC.F3 , KC.F4 , KC.F5, KC.F6, KC.F7  , KC.F8 , KC.F9  , KC.F10 , KC.F11 , KC.F12 , KC.PSCR, KC.SLCK, KC.PAUS, MACROTEST,
     KC.GRV   , KC.N1  , KC.N2   , KC.N3, KC.N4 , KC.N5 , KC.N6, KC.N7, KC.N8  , KC.N9 , KC.N0  , KC.MINS, KC.EQL , KC.BSPC, KC.INS , KC.HOME, KC.PGUP, _____,
     KC.TAB   , KC.Q   , KC.W    , KC.E , KC.R  , KC.T  , KC.Y , KC.U , KC.I   , KC.O  , KC.P   , KC.LBRC, KC.RBRC, KC.BSLS, KC.DEL , KC.END , KC.PGDN, _____,
     KC.CLCK  , KC.A   , KC.S    , KC.D , KC.F  , KC.G  , KC.H , KC.J , KC.K   , KC.L  , KC.SCLN, KC.QUOT, KC.ENT , _____  , _____  , _____  , _____  , _____,
     KC.LSFT  , KC.Z   , KC.X    , KC.C , KC.V  , KC.B  , KC.N , KC.M , KC.COMM, KC.DOT, KC.SLSH, _____  , KC.RSFT, _____  , _____  , KC.UP  , _____  , _____, 
     KC.LCTL  , KC.LGUI, KC.LALT , _____, _____ , KC.SPC, _____, _____, _____  , _____ , KC.RALT, _____  , KC.RGUI, KC.RCTL, KC.LEFT, KC.DOWN, KC.RGHT, _____
     ]
]





if __name__ == '__main__':
    keyboard.go()

This is the error code, which I get:
Traceback (most recent call last):
File "kmk/kmk_keyboard.py", line 443, in go
File "kmk/kmk_keyboard.py", line 517, in _main_loop
File "kmk/kmk_keyboard.py", line 253, in _process_timeouts
File "kmk/modules/macros.py", line 304, in task
File "kmk/modules/macros.py", line 294, in process_macro_async
File "kmk/modules/macros.py", line 313, in send_key_buffer
File "kmk/kmk_keyboard.py", line 228, in resume_process_key
ValueError: object not in sequence
1190579 kmk.keyboard: cleaning up...
1190581 kmk.keyboard: ...done

[xyphro]

Another update:
When having tapdance combined with macros the firmware can be brought into a state where it will still poll the matrix and handle incoming HID messages but never send HID codes from keystrokes. The firmware will not crash and still see keypresses and releases as handled, but it simply does hever send any HID message to PC.

How to reproduce.

Define 2 Tapdance buttons with macros:

SC_PLUSMIN    = KC.MACRO(Press(KC.LALT), Tap(KC.P2), Tap(KC.P4), Tap(KC.P1), Release(KC.LALT))
SC_BIGEQUAL   = KC.MACRO(Press(KC.LALT), Tap(KC.P2), Tap(KC.P4), Tap(KC.P2), Release(KC.LALT))
SC_SUM        = KC.MACRO(Press(KC.LALT), Tap(KC.P2), Tap(KC.P2), Tap(KC.P8), Release(KC.LALT))
SC_MICRO      = KC.MACRO(Press(KC.LALT), Tap(KC.P2), Tap(KC.P3), Tap(KC.P0), Release(KC.LALT))

MACRO_KEY_1 = KC.TD( SC_PLUSMIN, SC_BIGEQUAL, )
MACRO_KEY_2 = KC.TD( SC_SUM, SC_MICRO)

Add those 2 macro keys to your keymap.

Then press the 2 buttons simultaneously a few times.

After around 1 to 5 times pressing you will notice that no keycode is sent to PC anymore.
When pressing CAPS on a 2nd connected keyboard, you see the KMK keyboard registering it.
The debug messages still appear to be normal, keypresses/releases are shown.

For me a fix will not be meaningful anymore unless QMK FW shows more severe issues. While a crash would be easier to debug I suspect that the KMK firmware has quite some synchronization issues which might require more fundamental work to fix it.

[xyphro]

OK, could not let it go yet.

This connects to the last pots. When simply holding MACRO_KEY_1 button, I get the same issue. The keyboard gets to exactly the same state where it never sends codes to PC anymore.

I see that the key.state == _ON_HOLD Branch is taken where it returns. This on hold state never seems to get removed somehow, also when the key is released.

Maybe if motivated tomorrow I'll look further.

[xyphro]

Tracked it down.

The issue is in macros.py.

When StopIteration is reached (== macro playback finalized) it is checked if the macro key is still pressed down.
In that case the keystate is set to _ON_HOLD.

If the Keystate is _ON_HOLD and the macro does not have a handler for on hold it will never call release again.

[xyphro]

Last statement. The issue seems fixed when the Stopiteration handling of _ON_PRESS keystate has the exact same contend as _ON_RELEASE case.

Too late for me to judge if this is a proper workaround or creates new sideffects.

PS: It would be good to make some unit tests for such cases.

[xs5871]

Associated thread on zulip:
#general > Isues with Macros

[xyphro]

As I have issues with lost release codes every about 1h of usage (yes I swapped cables) it will take a while until I can confirm this finally fixed, as I went back temporarily to plain vanilla KMK without any macros or any changes to main stack.

Made a rolling error logging module to filesystem first for long term debug and due to the nature of this it will take days to spot and see if it is keymap handling or USB side. Nasty issue :-(

After that is finished I'll integrate back TD MACRO and above fix.

[xs5871]

I'm going to close this issue, as the description and focus keeps shifting.
Feel free to open a new issue, iff you can keep it to an isolated problem or bug. Or even better: ask the community chat for help first and make sure it's not a configuration issue again.

[xyphro]

So you won't fix the bug?

[xyphro]

Was about to generate a long term test environment with analog switches and pc sode hid message parsing, but with that kind of bug handling and closing a bug with analysis behind it without handling I wonder if this is the right project to invest time into.