Menu
▾
▴
#278 lirc upgrade 0.9.0->0.9.4: irsend works very unreliably - but only for some remotes
On lirc 0.9.4 for some remote types irblaster works very unreliably (1 from 10 sends is recognized by target equipment).
Issue is regression from 0.9.0 as 0.9.0 in this exactly the same enviroment works perfectly.
bisecting LIRC code gives following result:
[a8ca95] is bad
[5f4b75] is good
Using logging on a8ca95c shows no any errorrs.
Comparing what is sent to kernel shows that working 0.9.0 and not working 0.9.4 are sending practically the same data to kernel (except 1000 gap which is correctly present in 0.9.4 and not present in 0.9.0; but as 0.9.0 is old - lets put aside this as it seems to be 0.9.0 bug).
My enviroment:
OS: MiniMyth2
Kernel: 4.9.8.
Remote is MCE USB remote.
Feb 10 18:47:05 (none) user.info kernel: Registered IR keymap rc-rc6-mce Feb 10 18:47:05 (none) user.info kernel: input: Media Center Ed. eHome Infrared Remote Transceiver (0471:0815) as /devices/pci0000:00/0000:00:1d.1/usb3/3-1/3-1:1.0/rc/rc0/input5 Feb 10 18:47:05 (none) user.info kernel: rc rc0: Media Center Ed. eHome Infrared Remote Transceiver (0471:0815) as /devices/pci0000:00/0000:00:1d.1/usb3/3-1/3-1:1.0/rc/rc0
Kerel module is mceusb.
My lirc options:
[lircd] nodaemon = False driver = default device = /dev/lirc0 output = /var/run/lirc/lircd pidfile = /var/run/lircd.pid plugindir = /usr/lib/lirc/plugins permission = 666 allow-simulate = Yes repeat-max = 600 [lircmd] uinput = False nodaemon = False [modprobe]
My lircd.conf:
begin remote name sharp_46x20e bits 15 flags SPACE_ENC eps 30 aeps 100 one 480 1680 zero 480 560 ptrail 480 gap 10000 repeat_bit 0 frequency 38000 begin codes power_tv 0x41A2 power_tv_r 0x425D tv_vol+ 0x40A2 tv_vol+_r 0x435D tv_vol- 0x42A2 tv_vol-_r 0x415D mute 0x43A3 mute_r 0x405C 1 0x4202 end codes end remote
Thanks for reporting! Questions:
Related
Commit: [a8ca95]
Alec,
1. gap is correctly respected by a8ca95
2. IRSEND issue is definitelly on Sharp TV (model 46E20). I have also Sony amplituner and Samsung TV. Sony and Samsung seems to be working OK.
I, e,, a8ca95 is sending gaps, or?
Somewher in the back of my head there is also somrething about that this error only shows up on a ION-based box whereas it works ok on another. Or do I remember wrong?
EDIT: Have you access to a physical remote of the failing Sharp TV model 46E20 sort?
Last edit: Alec Leamas 2017-04-02
yes. I tested this by setting gap in lircd.conf file to 1000000. And I can confirm - a8ca95 after this gap change sends IR cmmand with multi sec. delay - so for me it looks like gap parameter is honoured.
regarding ION: I verified this issue on ION and i5 NUC and on both platforms issue is present - but on i5 it is much more seldom (ION - 1 per 5..10 sends is bad; i5 1 per 20-50 is bad).
Last edit: Warped 2017-04-03
On 03/04/17 15:30, Warped wrote:
Right. But please write into the bug instead, we need the info there.
--a
I have tired to analyze the code.
First, there the diff for the files irsend.c, lirc_client.h and lirc_client.c are empty. Also, given that he CLI irsend commadn actually triggers lircd in both cases I dont think there are any problems with hhow the command is sent to lircd.
The lircd code basicallu is the send_once() codepath. There are no changes in this code. The header files are moved but otherwise more or less identical.
Bottom line: I have still no clue what differs w r t lircd. For all that I see, there should be no changes. Hpwever, all moved files makes the diff large and hard to read.
Attaching a manual walk-through of the relevant part of the diff [5f4b75] to [a8ca95]. I still cannot see any changes relevant in this context. It's simply about moving files around.
Related
Commit: [5f4b75]
Commit: [a8ca95]
I have tried to analyze the config file. This seems to be a sharp., but a bad one.
The sharp protocol is well-defined. There are 44 sharp remotes registered at lirc-remotes.sf.org, and almost all share the sharp prtocol characteristics. IMHO, you should try to update this config file so it matches the overall understanding how it should be represented. In particular
Since the config file actually looks broken, it might be a bug in 0.9.0 whcih makes it work :) Actually, the config file gap looks way too small.
Alec,
I tried 3 different remotes on 0.9.4 from LIRC remotes repository with types similiar to mine.
All them practically not working (POWER_TV recognized avg. 1 on 10..20 sends).
When I'm looking visually on irblaster LED - for given 10 repeated command sends - on 0.9.4 LED blinking is not 100% predictable while on 0.9.0 is always predictable
Asking irsend with given command + repeat 10 times results:
0.9.0 - series of exactly cyclic and regular 10 blinks (blinks duration and space between them are regular)
0.9.4 - series of some blinks at have similar "speed" like in 0.9.0 but frequently it is randomly interleaved with some blinks which are different and have noticably longer duration between them. This behaviour is unpredictable (sometimes majority blinks are OK, but frequently multiple of them are "slow")
You may see this in small movie (4 series with 10x command):
hxxp://warped.homenet.org/lirc-ticket278.zip
Interesting is that proportion of "fast" blinks to "slow" highly depends on even small differences in one & zero parameters in lircd.conf.
With this conf I have 90% of blinks "slow".
but with this small change I have quite differently working IRSEND: 7..10 blinks are fast and over half of such 10 cmds series is recognized by TV
For me key difference between 0.9.0 and 0.9.4 is this irregularity. It pretends like 0.9.4 has sort of random timing durring sending.
Ah btw: playing with 0.9.4 shows me this "slow" & "fast" blasting is present not only for sharp. I discovered this also on sony aplituner - but it looks like sony can deal with this and still recognizes commands while sharp is much more prone to this "slow" & "fast" blasting.
br
I have been thinking about logging the data to the kernel using a kernel module, stocked on top of a character driver such as lirc. The problem here is that we cannot determine the difference in what sent, including timing, to the kernel. This will take a while, my driver skills are, well, not optimal ;) Stay tuned...
alec,
Maybe I'll try to structure hypothesis we so far have (pls correct me where I'm wrong).
Going backwards on data path:
1.kernel drives MCE USB dongle in a way that IR blasting is somehow randomized (this blinking irregularity) - when compared to 0.9.0
2.indeed we don't know is it result of:
2.1 - kernel received not the same data (compared with 0.9.0)
2.2 - data is OK - but way how we interact with kernel is different thai in 0.9.0
3.this randomization seems to be highly dependent on data sent to kernel (zero and one durations seems to impacting randomization)
p.3 for me highly suggest that p.2.2 is much more probable than p.2.1 (look - i changed zero from 320 to 260 and blasting visual behavior become noticeably different). Is it possible that lirc internal operations on data sent to kernel are so dependent on absolute values in processed data?
so having multiple hypothesis we may develop code/patches/test to eliminate them 1by1.
I would start with most probable for me hypothesis - which is for me: different interaction with kernel (in sence opening lirc device to sending; using differently defined context; different process model params when lirc calls kernel, you-name-it). Look: thing seems to be highly time dependent (zero/one duration matters; ION vs i5 matters)
Probably this may need to selectively move 0.9.4 code interacting with kernel to 0.9.0 level/logic - but I suspect we will probably need to partially do this anyway as final bug fix.
those 3 sharp's lircd.conf from lirc-remotes repository practically are not working with 0.9.4 while with 0.9.0 they works practically 100%. For me this tells that 0.9.4 irsend issue is probably more wide than mine sharp case...
First, for all that I can see the actual codepaths are the same here. The diff is hard to follow, but I cannot see anything but files moved around. Obviously, something is different, but it's seems like the difference is that some code is in a dynamic library instead of the main lircd binary. No idea what this means. And, I might be wrong, and there is s difference.
Secondly, if I manage to write the logging driver wrapper, it will be able of logging all kernel interaction including open, close, read, write and ioctl with timing info, So it should be able to clarify what the changes are, if any.
I don't see any better path right now. One clarifying test would be to use the "good" irsend to send data using a "bad" lircd daemon just to verify that irsend and lirc_client isn't involved in this. At this point, this is an assumption.
Last edit: Alec Leamas 2017-04-04
I have pushed quite a lot of commits... on the very top as of now there is [78e5c9], "Adding a logging module wrapper".
The code is in drivers/irlog. This is a completely independent directory, it has no references to the rest of lirc. The README describes how to build, load and unload the module. Building requires the kernel sources.
With the module loaded, lircd needs to use the new device /dev/irlog0 instead of /dev/lirc0. Doing so, dmesg() should contain a verbose log of all operations with timing.. You might want to patch irlog.c and rebuild it to customize the logging.
I have just made a simplle"works for me" test, so anything is possible. But you should notice if irsend behaves differently using /dev/irlog0. If so, we need to look into that.
Otherwise, the dmesg logs from the "bad" and the "good" version should tell us if there is any difference in the interaction between lircd and the kernel.
And yes, I'm sort of curious... :)
EDIT: ...and [85bcbe]
Related
Commit: [78e5c9]
Commit: [85bcbe]
Last edit: Alec Leamas 2017-04-06
Alec,
I'm attaching log for
Commit: [5f4b75]
Commit: [a8ca95]
Related
Commit: [5f4b75]
Commit: [a8ca95]
Perhaps we're closing in: there seem to be a difference, the bad one polls (actually, select()) more and seems to wait longer before it sends again.
Still, I think we need to refine the logs. First, to get bettter timestamps, can you use dmesg --time-format delta ito avoid debians silly human-readable timestamp default?
Secondly, it would be easier if we got some info in the logs on
I'm a bit in a hurry, If you can patch irlog.c to this end, it's fine. Otherwise I can make a patch, but not right now - other parts of my life (i.. e.., wife) requrires some attention.
Alec,
Unfortunatelly my dmesg not supports --time-format delta :-(
Regarding adding bytes/data into logging - currently playing with programming is a bit pain for me due lack of time to quick learn lirc code/internals (You know - professional life+familly).
sorry for that
Odd, even my debian does. Does it support something else providing better resolution?
I know something about that.... actually, here are no lirc internals involved, though. Wife is busy doing other things so I attach a patch :)
Last edit: Alec Leamas 2017-04-08
Alec,
Pls find logs with enhanced-logging.patch applied.
Hi,
5f4b looks sane, but a8ca looks like it's done with the old irlog?
Also, I made a terrible mistake, and everything looks like write. Could you please use the updated patch attached instead (it's just a string change).
I take this that there is no option providing better resoluion for your dmesg() ?!
ok - here are files produced with new patch.
Here are so many loose ends; feeling confused.
Still I cannot find any actual difference in the code. If you look up the pid of the lircd process using e. g. pgrep lircd what does
lsof -p 4437 | awk '{print $NF}' | grep '.so' | sort | uniq
say, substituing 4437 with the correct pid? Note that this is the pid of the process started by the lircd script, probably named lt-lircd.
What data is lircd receiving? Have you any idea? Is it receiving what's sent on the transmittter LED?
I'm attaching two, untested patches to irlog.c. The first is intended to dump the received data so we can get hold of it. The second might be able to add some detailed time logging, if we cannot sort out the dmesg() issues. They are on top of the current patch.
Last edit: Alec Leamas 2017-04-09
Alec,
My issue with dmesg is probably becasue in my system it is minimal implementation in busybox.
For tests I'm sending to irsend always the same 4 commands to my sharp tv.
I'm attaching log files for current irlog module.
Here is output for lsof on lircd process.
This busybox thing is painful... lsof doesn't show a single library loaded. Are your library not named e. g, liblicr_client.so.X.Y? Or is this lsof from "good" variant, where everythinng is statically linked? IN that case: it's the output from [a8ca95] we need.
[looking into the logs...]
Related
Commit: [a8ca95]
At a closer look that lsof output looks insane. I attach my own lsof for a running lircd. As yiu can see it's mostly libs + a few standard entries. In your case, lircd has open connections rpcbind, X11, mythfrontend and vnc. There is no no library listed. Ate yuo tesing with all of this running?
Alec,
I cross-compiled util-linux and lsof.
I'm attaching logs and lsof outputs
lsof from ga8ca95:
root@FE-IntelNUC:~ # /usr/local/bin/lsof -p 7359 | awk '{print $NF}' | grep '.so' | sort | uniq /lib/ld-linux-x86-64.so.2 /lib/libc.so.6 /lib/libdl.so.2 /lib/libm.so.6 /lib/libpthread.so.0 /lib/librt.so.1 /lib/libutil.so.1 /usr/lib/libasound.so.2 /usr/lib/libftdi.so.1 /usr/lib/libirman.so.0 /usr/lib/liblirc.so.0 /usr/lib/libportaudio.so.2 /usr/lib/libusb-0.1.so.4 /usr/lib/libusb-1.0.so.0and lsof from g5f4b75
root@FE-IntelNUC:~ # /usr/local/bin/lsof -p 7357 | awk '{print $NF}' | grep '.so' | sort | uniq /lib/ld-linux-x86-64.so.2 /lib/libc.so.6 /lib/libdl.so.2 /lib/libm.so.6 /lib/libpthread.so.0 /lib/librt.so.1 /lib/libutil.so.1 /usr/lib/libasound.so.2 /usr/lib/libftdi.so.1 /usr/lib/libirman.so.0 /usr/lib/libportaudio.so.2 /usr/lib/libusb-0.1.so.4 /usr/lib/libusb-1.0.so.0