IR Commands gets hanging in queue

[Hunter]

I also tested again multiple times. within 24 hours I got the problem 3 times....

A little part of the debug logging of the irserver can be found below.
At 12:26:58.142 the irclient sent the command power_22_hi_on to the irserver and irserver sent it to the device and device sent IR signal; Works just fine
Between 12:26:58.144 and 22:52:21.128 some IR signals were detected (switching on monitor, TL-lamp, just some random IR signals); still no problem
At 20:00:00 irclient sent the command power_off to the irserver, irclient exit code is 0, no time delay occurred. irserver received it (checked with tcpdump). irserver does NOT log it at that time, also does NOT sent tcp packet to ir device.
At 22:52:21.128 a tl-lamp switched on and this produced a random IR signal. the ir device sent this to the irserver and irserver logs this. Immediately after that the ir server is logging and sending the ir command which was given at 20:00:00. ir device receives the command at that moment and send the IR signal.
So why does the irserver delay (almost 3 hours) the command until it was triggered by a random IR signal?
I've already looked at the source code, but I can't figure out right now why this happens.

2011-08-14 12:26:58.142 IRTRANS TCP/IP Socket connection request
2011-08-14 12:26:58.142 IRTRANS TCP/IP Client 0 accepted from 127.0.0.1
2011-08-14 12:26:58.143 Netcommand Size: 112/112
2011-08-14 12:26:58.143 Netcommand: 1 [0]
2011-08-14 12:26:58.143 Send [0] airco_lg - power_22_hi_on [0 - B:0 M:0x0 LED: Default]
2011-08-14 12:26:58.143 TIME CNT: 0
2011-08-14 12:26:58.143 TIME : 0 8512 4200
2011-08-14 12:26:58.143 TIME : 1 592 504
2011-08-14 12:26:58.143 TIME : 2 600 1584
2011-08-14 12:26:58.143 TIME : 3 0 0
2011-08-14 12:26:58.143 TIME : 4 0 0
2011-08-14 12:26:58.143 TIME : 5 0 0
2011-08-14 12:26:58.143 TIME : 6 0 0
2011-08-14 12:26:58.143 TIME : 7 0 0
2011-08-14 12:26:58.143 T.REP : 0
2011-08-14 12:26:58.143 REP/MODE: 1 1
2011-08-14 12:26:58.143 FREQ : 38
2011-08-14 12:26:58.143 DATA : S10001000000000000111010010110
2011-08-14 12:26:58.143 LEN : 30
2011-08-14 12:26:58.143 ADR : 0
2011-08-14 12:26:58.143 MASK : 65535
2011-08-14 12:26:58.143 Total Code Len: 57 ms
2011-08-14 12:26:58.144 Send Status 8 - 8 [0]
2011-08-14 12:26:58.144 Client [0] disconnect
2011-08-14 13:28:34.467 [1.0]: LEN: 31 DC696A6666B66666977777778452301
2011-08-14 16:25:27.396 [1.0]: LEN: 2 S0
2011-08-14 16:25:27.790 [1.0]: LEN: 2 00
2011-08-14 16:25:27.845 [1.0]: LEN: 2 00
2011-08-14 16:25:28.306 [1.0]: LEN: 68 22202222222222222222222222222222222222221435667988BCCAEEDDDFFFHHHHGG
2011-08-14 16:25:28.453 [1.0]: LEN: 2 00
2011-08-14 22:52:21.128 [0.0]: LEN: 21 523F100G4D1690B7C8AE0
2011-08-14 22:52:21.129 IRTRANS TCP/IP Socket connection request
2011-08-14 22:52:21.129 IRTRANS TCP/IP Client 0 accepted from 127.0.0.1
2011-08-14 22:52:21.130 Netcommand Size: 112/112
2011-08-14 22:52:21.130 Netcommand: 1 [0]
2011-08-14 22:52:21.130 Send [0] airco_lg - power_off [0 - B:0 M:0x0 LED: Default]
2011-08-14 22:52:21.130 TIME CNT: 0
2011-08-14 22:52:21.130 TIME : 0 8512 4200
2011-08-14 22:52:21.130 TIME : 1 592 504
2011-08-14 22:52:21.130 TIME : 2 600 1584
2011-08-14 22:52:21.130 TIME : 3 0 0
2011-08-14 22:52:21.130 TIME : 4 0 0
2011-08-14 22:52:21.130 TIME : 5 0 0
2011-08-14 22:52:21.130 TIME : 6 0 0
2011-08-14 22:52:21.130 TIME : 7 0 0
2011-08-14 22:52:21.130 T.REP : 0
2011-08-14 22:52:21.130 REP/MODE: 1 1
2011-08-14 22:52:21.130 FREQ : 38
2011-08-14 22:52:21.130 DATA : S10001000110000000000010100010
2011-08-14 22:52:21.130 LEN : 30
2011-08-14 22:52:21.130 ADR : 0
2011-08-14 22:52:21.130 MASK : 65535
2011-08-14 22:52:21.130 Total Code Len: 55 ms
2011-08-14 22:52:21.141 Send Status 8 - 8 [0]
2011-08-14 22:52:21.141 Client [0] disconnect

[IRTrans]

My test is running for 4.5 days now.

So far it is working fine.

I still do not understand why the client returns but norhing is sent. When the request is not processed by the server there will be an error or timeout from the irclient.

IRTrans

[Hunter]

The client does sent it correctly to server (seen within tcpdumps). But server do not sent it to the IR device until a random IR signal has been received from IR device (doesn't matter which one). But this behavior happens only after some time the server is running.

[IRTrans]

Do you have a chance to test it with a different network card in your LINUX server?

The irserver is running in an event loop waiting for different things to happen. It looks like the network driver sometimes does not issue the network connection event correctly. The other events (e.g. data arrives from the IRTrans device) seem to work correctly.

As everything is working correctly on our machine and also in several hundred customer installations I don't think that this is an error in the irserver itself.

IRTrans

[Hunter]

It's a virtual machine. And if there was a problem with the network driver, then I had a very big issue (i've 500 servers running in this configuration without any issues).

[IRTrans]

Especially on virtual machines I have already seen some strange things happening.

Maybe no other application you are running is using the event handling in this form. Furthermore the host running the virtual machines does influence that, too as the network packets are forwarded from the physical interface first.

I have no idea what to fix here as the problem does not happen on any other system.

IRTrans

[IRTrans]

I have added a new debug output to the irserver. It shows if the SELECT Call waiting for external events returns or not.

If it does not return it is a driver/OS/Virtualization problem, if it returns it is a irserver problem.

Please send us an email to info@irtrans.de and we will send you the irserver version.

IRTrans

[ocgltd]

I just posted a potentially related problem. I too run irserver on (Linux 64 bit) a virtual machine - vsphere.

The first IR commands sends, but subsequent ones do not. Even though the log shows sent, they don't seem to go out. Not sure if it's the SAME problem...but I wanted to offer that as another clue