IR Commands gets hanging in queue

[Hunter]

I have the following issue. I control the airco systems with two irtrans LAN devices (in two separated rooms).
It's just working great, but after a random time (hours or days) it stops sending IR signals.

The irclient64 application executes correctly and seams to send the command to irserver64 daemon process (done this for example at 15:00). But in the logging I don't see for example the following part appearing:
2011-08-07 18:23:54.416 IRTRANS TCP/IP Socket connection request
2011-08-07 18:23:54.428 IRTRANS TCP/IP Client 0 accepted from 127.0.0.1
2011-08-07 18:23:54.431 Netcommand Size: 112/112
2011-08-07 18:23:54.431 Netcommand: 1 [0]
2011-08-07 18:23:54.431 Send [0] airco_lg - power_off [0 - B:0 M:0x0 LED: Default]
2011-08-07 18:23:54.433 Send Status 8 - 8 [0]
2011-08-07 18:23:54.433 Client [0] disconnect

The strange thing is, when one of the devices receives a random IR signal. The IR command which seems to hanging in a sort of queue inside the IRServer daemon process, is sended immediately. This can be minutes/hours/days later than the IRclient64 application has sent the command to the IRserver daemon process. At that moment the above section appears in the logging.

I start irserver with the following options:
-timestamp -learned_only -logfile /var/log/irserver.log -loglevel 4 -pidfile /var/run/irserver64.pid -daemon 192.168.202.240;192.168.202.241

To send IR command with irclient64 with the following options:
localhost airco_lg power_off 0 0
or
localhost airco_lg power_22_hi_on 0 0

Complete logging:
2011-08-07 06:26:27.553 Init Server Socket done
2011-08-07 06:26:27.553 IRServer64 Version 6.08.18
2011-08-07 06:26:27.553 Init Events done
2011-08-07 06:26:27.614 Name : IRTrans LAN
2011-08-07 06:26:27.614 Version: E6.03.32
2011-08-07 06:26:27.614 FW SNo : 40988
2011-08-07 06:26:27.614 Capab : Power On; Dual Transmitter Drivers; IR Database; 128KB IR Flash;
2011-08-07 06:26:27.614 FW Cap : 0x83186351
2011-08-07 06:26:27.614 FW Cap2: 0x95a1c67
2011-08-07 06:26:27.614 USB SNo: 00-22-3e-02-01-b8
2011-08-07 06:26:27.614 Node : 192.168.202.240

2011-08-07 06:26:27.614 Name : IRTrans LAN
2011-08-07 06:26:27.614 Version: E6.03.32
2011-08-07 06:26:27.614 FW SNo : 40989
2011-08-07 06:26:27.614 Capab : Power On; Dual Transmitter Drivers; IR Database; 128KB IR Flash;
2011-08-07 06:26:27.614 FW Cap : 0x83186351
2011-08-07 06:26:27.614 FW Cap2: 0x95a1c67
2011-08-07 06:26:27.614 USB SNo: 00-22-3e-02-01-b9
2011-08-07 06:26:27.614 Node : 192.168.202.241

2011-08-07 06:26:27.614 Init communication ...
2011-08-07 06:26:27.616 [ 0]: IRTrans LAN : IR VER: E6.03.32 ETH VER: L1.07.20 SN: 40988
MAC:00-22-3e-02-01-b8 IP Addr: 192.168.202.240
2011-08-07 06:26:27.616 [ 1]: IRTrans LAN : IR VER: E6.03.32 ETH VER: L1.07.20 SN: 40989
MAC:00-22-3e-02-01-b9 IP Addr: 192.168.202.241
2011-08-07 06:26:27.616 Chdir to DB OK
2011-08-07 06:26:27.616 Read routing OK
2011-08-07 06:26:27.616 Read Switches OK
2011-08-07 06:26:27.616 Open DIR: 0
2011-08-07 06:26:27.616 Get Dirent: 104
2011-08-07 06:26:27.629 Remote airco_lg compiled:2011-08-07 06:26:27.629 1 Timings - 2011-08-07 06:26:27.629 116 Commands
2011-08-07 06:26:27.629 Get Dirent: 0
2011-08-07 06:26:27.630 Total: 1 Remotes - 1 Timings - 116 Commands - 0 Calib. Commands
2011-08-07 06:26:27.630 0 Togglec. - 0 CCF Data - 0 CCF RAW - 0 CCF Error
2011-08-07 10:05:53.448 IRTRANS TCP/IP Socket connection request
2011-08-07 10:05:53.448 IRTRANS TCP/IP Client 0 accepted from 127.0.0.1
2011-08-07 10:05:53.448 Netcommand Size: 112/112
2011-08-07 10:05:53.448 Netcommand: 1 [0]
2011-08-07 10:05:53.448 Send [0] airco_lg - power_22_hi_on [0 - B:0 M:0x0 LED: Default]
2011-08-07 10:05:53.449 Send Status 8 - 8 [0]
2011-08-07 10:05:53.450 Client [0] disconnect
2011-08-07 18:23:54.416 IRTRANS TCP/IP Socket connection request
2011-08-07 18:23:54.428 IRTRANS TCP/IP Client 0 accepted from 127.0.0.1
2011-08-07 18:23:54.431 Netcommand Size: 112/112
2011-08-07 18:23:54.431 Netcommand: 1 [0]
2011-08-07 18:23:54.431 Send [0] airco_lg - power_off [0 - B:0 M:0x0 LED: Default]
2011-08-07 18:23:54.433 Send Status 8 - 8 [0]
2011-08-07 18:23:54.433 Client [0] disconnect

I suspect that there's a problem in the irserver process. How to solve this issue?

[IRTrans]

Hmm, very strange.

We do have lots of customers using the SW on a LINUX system but so far I have not seen this problem.

First of all I would suggest that you update the SW to the latest version of the irserver.

IRTrans

[Hunter]

As you can see at the logging, I use already the latest version.
2011-08-07 06:26:27.553 IRServer64 Version 6.08.18

It happens also with previous versions. I tried the latest version, but problem still exist.

[IRTrans]

Sorry, I mixed the FW version with the SW version.

Regarding your problem: I have no idea what might cause that. We do have many customers using the LINUX irserver in big installations around the clock. However, I have not seen this problem so far. Therefore I don't think it is a SW problem. In our testing here I did not see it either. That means it will be nearly impossible for us to trace that down. It might also be a network problem or driver problem.

If you have IRTrans devices with IRDB you can upload your IR codes and send them directly.

IRTrans

[Hunter]

Maybe other customers restart daemon process more frequently or use frequently a remote device to send IR signals, than the problem does not appear. The issue appears after hours or even after days. Before that it's just working fine. And when it appears, than I have to generate a random IR signal and it can working again for days. Or I have to restart the irserver process.
I don't have network/driver issues.
When sending directly to the devices, then I don't have the logging option. I need the logging of the irserver.

[IRTrans]

We do have several customers that use the IRTrans devices in broadcasting applications. They have the irserver running for weeks and never receive any IR codes at all.

I will try if I can reproduce that here on our test system.

IRTrans

[IRTrans]

Some more thoughts on your problem:

If the irclient terminates without an error message the server will surely have processed the request. If it is not processed there is no status sent back to the irclient process and the irclient process will run into a timeout error after some time. If sending does not work there would be an error message, too. As those are TCP requests with information going back and forth in both directions they cannot hang in a queue. When they are not processed in time there will always be a timeout with an error message.

I rather think that there is just a problem with the logfile being written at a later time. That can be caused by the OS buffering writes to the logfile.

IRTrans

[Hunter]

The irclient executed correctly and exit without any error. No time out occurred.

timeline to explain more what's happening when it's going wrong:
1. irclient send correctly the command for device "1" to the irserver.
2. irserver will not log the received command. I can't check if command is also sent to device. I'm going to snif the network traffic to see if it does or not.
The device "1" does not send the IR signal. I'm very sure about that!
3. device "2" (or "1") receives an random IR signal and send the IR code to irserver. Random IR signal can be from a remote device or switching on a TL-lamp (it produced some random IR signals).
4. irserver receives IR code from device "2" (or "1") and start sending the command (from step 1) to device "1".
5. device "1" receives command to send IR signal and send the IR signal.

Between step 1 and 4 can take hours. Between step 3,4 and 5 is microseconds.
So why does it react and go further when step 3 occurred? I can't explain why. But I can reproduce this every time when the issue occurred.

[IRTrans]

In the meantime I have tested that here on our system for more than 36 hours.

So far everything works fine.

IRTrans

[IRTrans]

Test time running: 75h.

Working perfectly.

IRTrans