My device driver doesn't survive DCERouter reload - [Solved]

[bulek]

Hi,

I've written device driver for my home automation system in Perl (and learned a lot about LMCE). But currently have problems ,cause my device driver doesn't survive DCERouter reload - it actually dies few minutes after reload...

Can I conclude from DCERouter's log what caused ending of tcp connection ?

Anyone with more experiences ?

Selected lines from DCERouter's log :

05   03/30/08 10:30:05.594      Starting log rotation... <0x772c1b90>
05   03/30/08 10:30:05.595      Going to rotate logs... <0x92af8b90>
05   03/30/08 10:30:05.595      Going to rotate logs... <0x912f5b90>
05   03/30/08 10:30:05.596      Going to rotate logs... <0x8faf2b90>
05   03/30/08 10:30:05.597      Going to rotate logs... <0x8e2efb90>
05   03/30/08 10:30:05.598      Going to rotate logs... <0x8b2e9b90>
05   03/30/08 10:30:05.600      Going to rotate logs... <0x89ae6b90>
05   03/30/08 10:30:05.602      Going to rotate logs... <0x862dfb90>
05   03/30/08 10:30:05.602      Going to rotate logs... <0x84adcb90>
05   03/30/08 10:30:05.603      Going to rotate logs... <0x832d9b90>
05   03/30/08 10:30:05.604      Going to rotate logs... <0x812d5b90>
05   03/30/08 10:30:05.608      Going to rotate logs... <0x7fad2b90>
05   03/30/08 10:30:05.611      Going to rotate logs... <0x7e2cfb90>
05   03/30/08 10:30:05.614      Going to rotate logs... <0x7caccb90>
05   03/30/08 10:30:05.598      Going to rotate logs... <0x8caecb90>
05   03/30/08 10:30:05.602      Going to rotate logs... <0x882e3b90>
05   03/30/08 10:30:05.614      Socket::SendData sendbytes==0 <0x772c1b90>
05   03/30/08 10:30:05.629      Socket::SendMessage *failed to send* type 7 id 10 from 0 to 77 <0x772c1b90>
05   03/30/08 10:30:05.632      Socket::ReceiveData 0x8e42348 failed, bytes left 0 start: 2490000 1: 0 1b: 0 2: 0 2b: 0 m_Socket: 185 Incoming_Conn Socket 185 192.168.0.1EVENT 84 <0x63a9ab90>
05   03/30/08 10:30:05.632      Socket::ReceiveString2 ReceiveData failed m_Socket: -1 Incoming_Conn Socket 185 192.168.0.1EVENT 84 <0x63a9ab90>
05   03/30/08 10:30:05.632      TCPIP: Closing connection to 84 (Router Dev #0) 0x8e42348 m_Socket: -1 <0x63a9ab90>
05   03/30/08 10:30:05.632      Router::RemoveAndDeleteSocket 0x8e42348 84 <0x63a9ab90>

05   03/30/08 10:30:05.687      Socket::ReceiveData 0x8effba0 failed, bytes left 0 start: 2530000 1: 0 1b: 0 2: 0 2b: 0 m_Socket: 156 Incoming_Conn Socket 156 192.168.0.53 <0x772c1b90>
05   03/30/08 10:30:05.687      Socket::ReceiveString2 ReceiveData failed m_Socket: -1 Incoming_Conn Socket 156 192.168.0.53 <0x772c1b90>
05   03/30/08 10:30:05.688      TCPIP: Closing connection to -1003 (Router Dev #0) 0x8effba0 m_Socket: -1 <0x772c1b90>
05   03/30/08 10:30:05.688      Router::RemoveAndDeleteSocket 0x8effba0 -1003 <0x772c1b90>

Thanks in advance,

regards,

Bulek.

[danielk]

bulek we can't really help you debug without your patch with the new device + documentation of the DB changes so we can reproduce the problem.

[hari]

is your device handled by appserver? I assume that behavior is as designed, the DCErouter restarts devices at quick reload. Maybe it closes sockets, too..

best regards,
Hari

[bulek]

Hi,

thanks for responses...

Danielk: my driver is currently written in Perl and at the moment a mess. But I'm trying to figure out, why DCERouter closes socket to my device. I bet I'm doing something wrong in my implementation - but what I'd like to see or understand is a brief explanation in log why DCERouter decides to close socket....

Hari: I have implemented pretty much what is needed on restart. It goes like this :
1. DCERouter sends Close command - that means that all connected device drivers should clear sockets and die
2. on restart, DCERouter or better Launch Manager will start devices back again (all over from start)
3. During operation of device, DCERouter sends PING command to check whether device is alive and if it is - it responds with PONG. But I'm still not sure on which one to send this PONG response on outgoing socket or on incoming socket, from where PING got...

I had smaller problem with not sending PONG on right socket, but I guess I fixed that at that time....

Is there any other limitation, why would DCERouter close connection ?

Is it possible to see this from DCERouter's log or any other logs ?

05   03/30/08 10:30:05.614      Socket::SendData sendbytes==0 <0x772c1b90>
05   03/30/08 10:30:05.629      Socket::SendMessage *failed to send* type 7 id 10 from 0 to 77 <0x772c1b90>
05   03/30/08 10:30:05.632      Socket::ReceiveData 0x8e42348 failed, bytes left 0 start: 2490000 1: 0 1b: 0 2: 0 2b: 0 m_Socket: 185 Incoming_Conn Socket 185 192.168.0.1EVENT 84 <0x63a9ab90>
05   03/30/08 10:30:05.632      Socket::ReceiveString2 ReceiveData failed m_Socket: -1 Incoming_Conn Socket 185 192.168.0.1EVENT 84 <0x63a9ab90>
05   03/30/08 10:30:05.632      TCPIP: Closing connection to 84 (Router Dev #0) 0x8e42348 m_Socket: -1 <0x63a9ab90>
05   03/30/08 10:30:05.632      Router::RemoveAndDeleteSocket 0x8e42348 84 <0x63a9ab90>

ID of my device driver is 84 and those lines in the middle mention this socket closing. I jsut wonder if I can get any more info on why DCERouter decides to do that....

Thanks in advance,

regards,

Bulek.

[bulek]

Hi,

It happened again and it seems it happens after logs rotate :

05   04/08/08 7:35:25.306      Going to rotate logs... <0x96ae1b90>
05   04/08/08 7:35:25.313      Going to rotate logs... <0x93adbb90>
05   04/08/08 7:35:25.313      Going to rotate logs... <0x90ad5b90>
05   04/08/08 7:35:25.314      Going to rotate logs... <0x8d2ceb90>
05   04/08/08 7:35:25.314      Going to rotate logs... <0x8bacbb90>
05   04/08/08 7:35:25.306      Going to rotate logs... <0x952deb90>
05   04/08/08 7:35:25.313      Going to rotate logs... <0x982e4b90>
05   04/08/08 7:35:25.576      Going to rotate logs... <0x882c4b90>
05   04/08/08 7:35:25.320      Going to rotate logs... <0x89ac7b90>
05   04/08/08 7:35:25.576      Going to rotate logs... <0x832bab90>
05   04/08/08 7:35:25.576      Going to rotate logs... <0x84abdb90>
05   04/08/08 7:35:25.314      Going to rotate logs... <0x8ead1b90>
05   04/08/08 7:35:25.313      Going to rotate logs... <0x922d8b90>
05   04/08/08 7:35:25.348      Socket::ReceiveData 0xa5b9e5c8 failed, bytes left 0 start: 39870000 1: 0 1b: 0 2: 0 2b: 0 m_Socket: 144 Incoming_Conn Socket 144 192.168.0.1EVENT 84 <0x79aa7b90>
05   04/08/08 7:35:25.612      Socket::ReceiveString2 ReceiveData failed m_Socket: -1 Incoming_Conn Socket 144 192.168.0.1EVENT 84 <0x79aa7b90>
05   04/08/08 7:35:25.612      TCPIP: Closing connection to 84 (Router Dev #0) 0xa5b9e5c8 m_Socket: -1 <0x79aa7b90>
05   04/08/08 7:35:25.612      Router::RemoveAndDeleteSocket 0xa5b9e5c8 84 <0x79aa7b90>
05   04/08/08 7:35:25.344      Socket::ReceiveData 0xa5bd0bb8 failed, bytes left 0 start: 39880000 1: 0 1b: 0 2: 0 2b: 0 m_Socket: 164 Incoming_Conn Socket 164 192.168.0.1 <0x6b0e9b90>
05   04/08/08 7:35:25.612      Socket::ReceiveString2 ReceiveData failed m_Socket: -1 Incoming_Conn Socket 164 192.168.0.1 <0x6b0e9b90>
05   04/08/08 7:35:25.612      TCPIP: Closing connection to -1003 (Router Dev #0) 0xa5bd0bb8 m_Socket: -1 <0x6b0e9b90>
05   04/08/08 7:35:25.612      Router::RemoveAndDeleteSocket 0xa5bd0bb8 -1003 <0x6b0e9b90>

Any idea what happens on log rotation and how could this be related to closing down my driver ?

Thanks in advance,

regards,

Bulek.

[bulek]

Hi,

I got a problem in my code. I always thought that PING/PONG is the only mechanism that needs to be implemented in device driver to stay connected... But there is also LOG Rotate command, that DCERouter sends to all connected devices and expects OK response...

I didn't handle that message in my device and DCERouter closed it....

I received this :

LMCE_REC : 0 84 7 11   

84 is ID of my devicec driver, 7 means System Command and 11 is log rotate command.

You must response imediately with "OK" on same socket as you received this command, otherwise Route will close socket....

HTH,

regards,

Bulek.

[ddamron]

Bulek,

What type of Home Automation devices are you using?

[bulek]

Bulek,

What type of Home Automation devices are you using?

Automation system from Cybrotech :

http://www.cybrotech.co.uk/index.php?lang=en&module=ctlgcat&action=cat&id=50

I chosed them cause they offered tight cooperation in goal of supporting higher level systems like LMCE. I'm also developing wireless zigbee extension for this system...

It's based on Canbus...

HTH,

regards,

Bulek.

[ddamron]

Nice equipment!

Bulek,

What type of Home Automation devices are you using?

Automation system from Cybrotech :

http://www.cybrotech.co.uk/index.php?lang=en&module=ctlgcat&action=cat&id=50

I chosed them cause they offered tight cooperation in goal of supporting higher level systems like LMCE. I'm also developing wireless zigbee extension for this system...

It's based on Canbus...

HTH,

regards,

Bulek.