#168 "repeat code without last_code received" when pressing buttons on irtoy2

[Bob Ham]

Hi there,

I've compiled lirc 0.9.3a, flashed my irtoy2 with the latest firmware, v22, and successfully recorded my remote using irrecord. However, when I start lircd, run irw and press some buttons, I get a notice in syslog: "repeat code without last_code received". Here is a trace log:

Jan 15 19:25:42 myrtle lircd-0.9.3a[22760]: Info: Initial device: /dev/ttyACM0
Jan 15 19:25:42 myrtle lircd-0.9.3a[22760]: Info: Initial device: /dev/ttyACM0
Jan 15 19:25:42 myrtle lircd-0.9.3a[22760]: Warning: Running as root
Jan 15 19:25:42 myrtle lircd-0.9.3a[22760]: Debug: started server socket
Jan 15 19:25:42 myrtle lircd-0.9.3a[22760]: Debug: parsing remote
Jan 15 19:25:42 myrtle lircd-0.9.3a[22760]: Info: Using remote: testage.
Jan 15 19:25:42 myrtle lircd-0.9.3a[22760]: Debug: lengths: 108213 108213 23020 96401
Jan 15 19:25:42 myrtle lircd-0.9.3a[22760]: Debug: config file read
Jan 15 19:25:42 myrtle lircd-0.9.3a[22761]: Notice: lircd(irtoy) ready, using /var/run/lirc/lircd
Jan 15 19:25:45 myrtle lircd-0.9.3a[22761]: Debug: registering local client
Jan 15 19:25:45 myrtle lircd-0.9.3a[22761]: Notice: accepted new client on /var/run/lirc/lircd
Jan 15 19:25:45 myrtle lircd-0.9.3a[22761]: Debug: irtoy_getversion: Got version V222
Jan 15 19:25:45 myrtle lircd-0.9.3a[22761]: Debug: irtoy_reset: Got protocol S01
Jan 15 19:25:45 myrtle lircd-0.9.3a[22761]: Debug: Version hw 2, sw 22, protocol 1
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: irtoy_raw_rec
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: new signal after large space
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 1000000
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: trying "testage" remote
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: decode: enter
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: sync
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 8981
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: header
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 4565
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 575
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 575
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 575
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 1685
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 1663
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 1685
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 575
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 1663
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 1685
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 575
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 575
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 1685
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 1685
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 511
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 575
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 575
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 575
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 1663
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 1685
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 1685
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 1685
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 1663
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 1706
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 554
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 1685
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: code: f940bf
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 42175
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: decode: 1
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: found: OK
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: 60f110 0 0 0 0 1 1 0 0 1
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: irtoy_raw_rec
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: trying "testage" remote
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: decode: enter
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: sync
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 8981
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 2303
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: readdata 1 533
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Notice: repeat code without last_code received
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: decode: 0
Jan 15 19:25:48 myrtle lircd-0.9.3a[22761]: Debug: decoding failed for all remotes
Jan 15 19:25:50 myrtle lircd-0.9.3a[22761]: Debug: irtoy_raw_rec
Jan 15 19:25:50 myrtle lircd-0.9.3a[22761]: Debug: readdata 0 1000000
Jan 15 19:25:50 myrtle lircd-0.9.3a[22761]: Debug: trying "testage" remote
Jan 15 19:25:50 myrtle lircd-0.9.3a[22761]: Debug: decode: enter
Jan 15 19:25:50 myrtle lircd-0.9.3a[22761]: Debug: sync
Jan 15 19:25:50 myrtle lircd-0.9.3a[22761]: Debug: failed on header
Jan 15 19:25:50 myrtle lircd-0.9.3a[22761]: Debug: decode: 0
Jan 15 19:25:50 myrtle lircd-0.9.3a[22761]: Debug: decoding failed for all remotes

[Bob Ham]

I should add that irw reports nothing after the notice.

[Bob Ham]

This appears to be specific to the remote; other remotes work OK

[Bengt Martensson]

Please attach your lircd.conf, state the brand of device and remote, and tell us exactly what signal(s) caused the misbehavior and which ones were ok. In particular, exactly what signal corresponds to the trace?

[Bob Ham]

The remote is an unidentified control for the Mele A1000G Quad:

http://img.dxcdn.com/productimages/sku_225850_7.jpg

The trace was for the button labelled "OK". You can actually see that it successfully finds the right button in the trace: "Debug: found: OK". Other buttons are likewise found successfully. Unfortunately, none of the buttons end up working.

I have two lircd.conf files, the one for the above trace is a minimal one I created for testing. The other is a full configuration with each button. They are attached.

[Bengt Martensson]

What happens with the "OK" signal is roughly this: First the payload portion of a NEC signal, device 9, subdevice 159, function code 2 arrives, and decodes properly. The next three durations constitutes the "ditto" portion of NEC1 (on around 9000 microseconds, off 2200, on 570, last silence missing). Then your Lirc bails out.

If it really is NEC1 signals we are dealing with, the 0xFFFFFFFF stuff at the end of the command lines is senseless. You can try to re-capture your remote with IrScrutinizer, and see how it identifies the signals, and generate your lircd.conf with that. (You can use IrToy with IrToy, FW version 2.2 which you have.) Or just a quick shot: delete the 0xFFFFFFFF stuff.

[Bob Ham]

Removing the 0xFFFFFFFF has made it work fine now, thanks.

[Bengt Martensson]

... so the problem is located to irrecord, which generated a useless file.

[Alec Leamas]

Indeed. @Bob: What kernel are you running on (what says uname -a?)

[Bob Ham]

What kernel are you running on

rah@myrtle:~$ uname -a
Linux myrtle 4.4.0-linux-latest-98 #6 SMP PREEMPT Sat Jan 16 20:47:18 GMT 2016 x86_64 GNU/Linux

I'm not sure what difference the kernel would make though, the kernel driver involved is for the standard ttyACM port.

[Alec Leamas]

The kernel driver is affected by https://bugzilla.redhat.com/show_bug.cgi?id=1260862, unsure as to if it has any relevance for this. I assume you cannot test such an old kernel as 3.17.4 ?!

[Bengt Martensson]

The kernel driver is not involved; the IrToy driver reads /dev/ttyACMn (n = 0,1,2,...). This is a "normal serial port". (In IrScrutinizer, our "beloved" RXTX is involved...)

[Alec Leamas]

So, the problem is irrecord. Despite settings bits=32 in the header it emits 64 bits data definitions with bogus trailing 32 bits.

Problem can partly be reproduced using irsimsend/irsimreceive which fails with original file but runs OK with the trailing garbage removed. This is a bug - the decoding should not care about anything but the 32 bits in the data.

The other side is what caused irrecord to write the trailng ones.

[Akkana Peck]

Seeing this on an up-to-date copy of Raspbian Stretch. I hit the same "repeat code without last_code received" message (in /var/log/messages) when trying to run irw on a conf file I'd just generated with irrecord, and irw never sees any button presses. I don't see any 0xFFFFFFFF stuff in the file, but it does say bits 32 while having codes like 0x00FD00FF 0xBED8F1BC. A conf file I generated under Raspbian Jessie works (I may have run it through lirc-old2new; I had trouble telling which files that script actually modified). I'll attach both the nonworking version, generated on Stretch, and the working one, generated on the older Jessie. This is for a generic remote that was shipped with a DingMai Arduino kit.

[Akkana Peck]

Apparently I can only post one attachment per comment. That was the working version that came from Jessie. Here's the one generated with the newer lirc on stretch.

[Source Doctor]

Thank you, @Bob Ham for reporting this and @Alec Leamas for deducing the 64 bit problem. I confirm that the same problem occurred with:

$ lircd -v
lircd 0.9.4c

$ uname -a
Linux myth-raspberry 4.9.73-v7+ #1072 SMP Sun Dec 31 19:37:41 GMT 2017 armv7l GNU/Linux

$ cat /etc/issue
Raspbian GNU/Linux 9 \n \l

From /etc/lirc/lirc_options.conf:

driver = default
device = /dev/lirc0
output = /var/run/lirc/lircd

Modules loaded:

lirc_rpi                9032  3
lirc_dev               10583  1 lirc_rpi
rc_core                24377  1 lirc_dev

Processes running:

root       307  0.0  0.2   4208  2148 ?        Ss   09:03   0:00 /usr/bin/irexec /etc/lirc/irexec.lircrc
root       444  0.0  0.5   7192  3780 ?        Ss   09:03   0:00 /usr/sbin/lircd --nodaemon
root       445  0.0  0.3   4284  2364 ?        Ss   09:03   0:00 /usr/sbin/lircd-uinput

IR receiver:Velleman VMA317 1838 IR INFRARED 37.9 kHz RECEIVER connected to GPIO pin 18 (12 physical)

My remote control is from a WD TV Live.

When I recorded signals with irrecord, I got:

  begin codes
      KEY_POWER                0x219E48B7 0x7E825B6C
      KEY_HOME                 0x219E609F 0x7E825B6C
      KEY_UP                   0x219EA05F 0x7E825B6C
      KEY_LEFT                 0x219EE01F 0x7E825B6C
      KEY_ENTER                0x219E10EF 0x7E825B6C
      KEY_RIGHT                0x219E906F 0x7E825B6C
      KEY_DOWN                 0x219E00FF 0x7E825B6C
      KEY_BACK                 0x219ED827 0x7E825B6C
      KEY_STOP                 0x219E20DF 0x7E825B6C
      KEY_OPTION               0x219E58A7 0x7E825B6C
      KEY_REWIND               0x219EF807 0x7E825B6C
      KEY_PLAYPAUSE            0x219E50AF 0x7E825B6C
      KEY_FASTFORWARD          0x219E7887 0x7E825B6C
      KEY_PREVIOUS             0x219E40BF 0x7E825B6C
      KEY_NEXT                 0x219E807F 0x7E825B6C
      KEY_SEARCH               0x219EF00F 0x7E825B6C
      KEY_EJECTCD              0x219E08F7 0x7E825B6C
  end codes

After installing this configuration file at /etc/lirc/lircd.conf.d and rebooting, irw produced no output, though I could see using strace that my /usr/sbin/lircd --nodaemon process was reading data from /dev/lirc0. Removing the 0x7E825B6C codes from each of the above lines and rebooting caused irw to begin showing the key values in the left column above when I pressed the corresponding buttons on my WD TV Live remote control.