search

openv / vcontrold

:fire: vcontrold Daemon for control and logging of Viessmann® type heating devices
https://github.com/openv/openv/wiki
GNU General Public License v3.0
101 stars 54 forks source link

using setaddr causes vcontrold crash P300 and 20C8 #66

Open oriziena opened 4 years ago

oriziena commented 4 years ago

hi,

I checked things multiple times but as soon as I try to use setaddr I am receiving 'Received SIGPIPE' and vcontrold is repeating that message unlimited times.

pls find attached the vito.xml and vcontrold.xml(see next post...)

vcontrold -V                                                                                                                                               

vcontrold version 0.98.9-2-g09b789e

version should be latest...

This happens with following example:

sudo /usr/local/bin/vclient  -h 127.0.0.1 -p 3002  -c 'detail getVitoBetriebsartHK1,debug on,getVitoBetriebsartHK1'
detail getVitoBetriebsartHK1:
getVitoBetriebsartHK1: SEND 00 01 23 01 01;RECV 1 BA
    Unit: BetriebsArt (BA)
      Type: enum
      Get-Calc: (null)
                                        Set-Calc: (null)
     Einheit: (null)
      Enum Bytes: 00 Text: WW
      Enum Bytes: 01 Text: RED
      Enum Bytes: 02 Text: NORM
      Enum Bytes: 04 Text: H+WW FS
      Enum Bytes: 03 Text: H+WW
      Enum Bytes: 05 Text: ABSCHALT
      Enum Bytes: <default> Text: UNKNOWN
debug on:

getVitoBetriebsartHK1:
DEBUG:Wed May 13 15:38:36 2020 : Command: getVitoBetriebsartHK1
DEBUG:Wed May 13 15:38:36 2020 : Process 29827 tries to aquire lock
DEBUG:Wed May 13 15:38:36 2020 : Process 29827 got lock
DEBUG:Wed May 13 15:38:36 2020 : >FRAMER: open device /dev/ttyUSB0 ProtocolID 41
DEBUG:Wed May 13 15:38:36 2020 : Configuring serial interface /dev/ttyUSB0
DEBUG:Wed May 13 15:38:36 2020 : >SENT: 04
DEBUG:Wed May 13 15:38:38 2020 : <RECV: len=1 05 (1920.0 ms)
DEBUG:Wed May 13 15:38:38 2020 : <RECV: received 05
DEBUG:Wed May 13 15:38:38 2020 : >FRAMER: framer_reset_actaddr framer_current_addr = FRAMER_LINK_STATUS(05) (was FFFF)
DEBUG:Wed May 13 15:38:38 2020 : >FRAMER: closed
DEBUG:Wed May 13 15:38:38 2020 : >SENT: 16
DEBUG:Wed May 13 15:38:38 2020 : >SENT: 00
DEBUG:Wed May 13 15:38:38 2020 : >SENT: 00
DEBUG:Wed May 13 15:38:38 2020 : <RECV: len=1 06 (10.0 ms)
DEBUG:Wed May 13 15:38:38 2020 : <RECV: received 06
DEBUG:Wed May 13 15:38:38 2020 : >FRAMER: framer_reset_actaddr framer_current_addr = FRAMER_NO_ADDR (was FE05)
DEBUG:Wed May 13 15:38:38 2020 : >FRAMER: opened
DEBUG:Wed May 13 15:38:38 2020 : >SENT: 41
DEBUG:Wed May 13 15:38:38 2020 : >SENT: 05
DEBUG:Wed May 13 15:38:38 2020 : >SENT: 00
DEBUG:Wed May 13 15:38:38 2020 : >SENT: 01
DEBUG:Wed May 13 15:38:38 2020 : >SENT: 23
DEBUG:Wed May 13 15:38:38 2020 : >SENT: 01
DEBUG:Wed May 13 15:38:38 2020 : >SENT: 01
DEBUG:Wed May 13 15:38:38 2020 : >SENT: 2B
DEBUG:Wed May 13 15:38:38 2020 : <RECV: len=1 06 (20.0 ms)
DEBUG:Wed May 13 15:38:38 2020 : <RECV: received 06
DEBUG:Wed May 13 15:38:38 2020 : >FRAMER: framer_set_actaddr framer_current_addr = 0123 (was FFFF)
DEBUG:Wed May 13 15:38:38 2020 : >FRAMER: Command send
DEBUG:Wed May 13 15:38:38 2020 : >FRAMER: no preset result
DEBUG:Wed May 13 15:38:38 2020 : <RECV: len=1 41 (10.0 ms)
DEBUG:Wed May 13 15:38:38 2020 : <RECV: received 41
DEBUG:Wed May 13 15:38:38 2020 : <RECV: len=1 06 (0.0 ms)
DEBUG:Wed May 13 15:38:38 2020 : <RECV: received 06
DEBUG:Wed May 13 15:38:38 2020 : <RECV: len=1 01 (0.0 ms)
DEBUG:Wed May 13 15:38:38 2020 : <RECV: len=1 01 (0.0 ms)
DEBUG:Wed May 13 15:38:38 2020 : <RECV: len=1 23 (0.0 ms)
DEBUG:Wed May 13 15:38:38 2020 : <RECV: len=1 01 (10.0 ms)
DEBUG:Wed May 13 15:38:38 2020 : <RECV: len=1 01 (0.0 ms)
DEBUG:Wed May 13 15:38:38 2020 : <RECV: len=1 04 (0.0 ms)
DEBUG:Wed May 13 15:38:38 2020 : <RECV: len=1 31 (10.0 ms)
DEBUG:Wed May 13 15:38:38 2020 : <RECV: received 01 01 23 01 01 04 31
DEBUG:Wed May 13 15:38:38 2020 : >FRAMER: framer_reset_actaddr framer_current_addr = FRAMER_NO_ADDR (was 0123)
DEBUG:Wed May 13 15:38:38 2020 : 04 -> H+WW FS
DEBUG:Wed May 13 15:38:38 2020 : H+WW FS
H+WW FS

when I try to set this e.g. to WW only:

sudo /usr/local/bin/vclient  -h 127.0.0.1 -p 3002  -c 'detail setVitoBetriebsartHK1,debug on,setVitoBetriebsartHK1 WW'
[28066] Wed May 13 10:55:28 2020 : timeout wait:vctrld>
[28066] Wed May 13 10:55:28 2020 : Error communicating with the server

log output:

[23675] Wed May 13 10:36:45 2020 : >SENT: 04
[23675] Wed May 13 10:36:45 2020 : <RECV: len=1 06 (10.0 ms)
[23675] Wed May 13 10:36:45 2020 : Received SIGPIPE
[23675] Wed May 13 10:36:45 2020 : Received SIGPIPE
[23675] Wed May 13 10:36:45 2020 : Received SIGPIPE
[23675] Wed May 13 10:36:45 2020 : Received SIGPIPE
[23675] Wed May 13 10:36:45 2020 : Received SIGPIPE
[23675] Wed May 13 10:36:45 2020 : Received SIGPIPE
[23675] Wed May 13 10:36:45 2020 : Received SIGPIPE

greetings and thanks for tips and help! ori

oriziena commented 4 years ago

vcontrold.txt vito.txt

oriziena commented 4 years ago

strange...

switched protocol to KW2 ... but now i am getting SIGPIPE whenever I manually request a value ...

e.g. command:

sudo /usr/local/bin/vclient  -h 127.0.0.1 -p 3002  -c 'detail getVitoBetriebsartHK1,debug on,getVitoBetriebsartHK1'
detail getVitoBetriebsartHK1:
getVitoBetriebsartHK1: SEND 04;WAIT 05;SEND 01 F7 23 01 01;RECV 1 BA
    RECV Timeout: 4000 ms
    Retry: 3
    Unit: BetriebsArt (BA)
      Type: enum
      Get-Calc: (null)
                                        Set-Calc: (null)
     Einheit: (null)
      Enum Bytes: 00 Text: WW
      Enum Bytes: 01 Text: RED
      Enum Bytes: 02 Text: NORM
      Enum Bytes: 04 Text: H+WW FS
      Enum Bytes: 03 Text: H+WW
      Enum Bytes: 05 Text: ABSCHALT
      Enum Bytes: <default> Text: UNKNOWN
debug on:

getVitoBetriebsartHK1:
DEBUG:Wed May 13 16:40:31 2020 : Command: getVitoBetriebsartHK1
DEBUG:Wed May 13 16:40:31 2020 : Process 22126 tries to aquire lock
DEBUG:Wed May 13 16:40:38 2020 : Process 22126 got lock
DEBUG:Wed May 13 16:40:38 2020 : >FRAMER: open device /dev/ttyUSB0 ProtocolID 00
DEBUG:Wed May 13 16:40:38 2020 : Configuring serial interface /dev/ttyUSB0
DEBUG:Wed May 13 16:40:38 2020 : >SENT: 04
DEBUG:Wed May 13 16:40:38 2020 : >FRAMER: no preset result
DEBUG:Wed May 13 16:40:38 2020 : Waiting for 05
DEBUG:Wed May 13 16:40:40 2020 : <RECV: 05 (2000.0 ms)
DEBUG:Wed May 13 16:40:40 2020 : >SENT: 01
DEBUG:Wed May 13 16:40:40 2020 : >SENT: F7
DEBUG:Wed May 13 16:40:40 2020 : >SENT: 23
DEBUG:Wed May 13 16:40:40 2020 : >SENT: 01
DEBUG:Wed May 13 16:40:40 2020 : >SENT: 01
DEBUG:Wed May 13 16:40:40 2020 : >FRAMER: no preset result
DEBUG:Wed May 13 16:40:40 2020 : <RECV: len=1 04 (20.0 ms)
DEBUG:Wed May 13 16:40:40 2020 : <RECV: received 04
DEBUG:Wed May 13 16:40:40 2020 : 04 -> H+WW FS
DEBUG:Wed May 13 16:40:40 2020 : H+WW FS
H+WW FS

log:

20062] Wed May 13 16:33:27 2020 : TCP socket 3002 opened
[20062] Wed May 13 16:33:39 2020 : Client connected 127.0.0.1:59860 (FD:1)
[20062] Wed May 13 16:33:39 2020 : Child process started with pid 20118
[20118] Wed May 13 16:33:39 2020 : Command: detail getVitoBetriebsartHK2
[20118] Wed May 13 16:33:39 2020 : Command: debug on
[20118] Wed May 13 16:33:39 2020 : Command: getVitoBetriebsartHK2
[20118] Wed May 13 16:33:39 2020 : Process 20118 tries to aquire lock
[20118] Wed May 13 16:33:39 2020 : Process 20118 got lock
[20118] Wed May 13 16:33:39 2020 : >FRAMER: open device /dev/ttyUSB0 ProtocolID 00
[20118] Wed May 13 16:33:39 2020 : Configuring serial interface /dev/ttyUSB0
[20118] Wed May 13 16:33:39 2020 : >SENT: 04
[20118] Wed May 13 16:33:39 2020 : >FRAMER: no preset result
[20118] Wed May 13 16:33:39 2020 : Waiting for 05
[20118] Wed May 13 16:33:39 2020 : <RECV: 05 (170.0 ms)
[20118] Wed May 13 16:33:39 2020 : >SENT: 01
[20118] Wed May 13 16:33:39 2020 : >SENT: F7
[20118] Wed May 13 16:33:39 2020 : >SENT: 33
[20118] Wed May 13 16:33:39 2020 : >SENT: 01
[20118] Wed May 13 16:33:39 2020 : >SENT: 01
[20118] Wed May 13 16:33:39 2020 : >FRAMER: no preset result
[20118] Wed May 13 16:33:39 2020 : <RECV: len=1 00 (20.0 ms)
[20118] Wed May 13 16:33:39 2020 : <RECV: received 00
[20118] Wed May 13 16:33:39 2020 : 00 -> WW
[20118] Wed May 13 16:33:39 2020 : WW
[20118] Wed May 13 16:33:39 2020 : Command: quit
[20118] Wed May 13 16:33:39 2020 : Process 20118 released lock
[20118] Wed May 13 16:33:39 2020 : Received SIGPIPE
[20118] Wed May 13 16:33:39 2020 : Received SIGPIPE
[20118] Wed May 13 16:33:39 2020 : Received SIGPIPE
[20118] Wed May 13 16:33:39 2020 : Received SIGPIPE
[20118] Wed May 13 16:33:39 2020 : Received SIGPIPE
hmueller01 commented 3 years ago

Same problem here. Sometimes it works, sometimes it does not.

If it fails I get a new process with high CPU load (in this case 18417).

ps aux|grep vcont
nobody   18301  0.0  0.5   4996  2692 ?        Ss   17:31   0:00 /usr/local/sbin/vcontrold  
nobody   18417 45.6  0.4   5004  2048 ?        R    17:33   0:07 /usr/local/sbin/vcontrold

vcontrold sets a signal handler here:

        while (1) {
            sockfd = listenToSocket(listenfd, makeDaemon);
            if (signal(SIGPIPE, sigPipeHandler) == SIG_ERR) {

And this is the output we see:

static void sigPipeHandler(int signo)
{
    logIT1(LOG_ERR, "Received SIGPIPE");
    // FIXME: And we do nothing here? Why do we handle it then?
}

I am no expert in this. But for me it looks like we have a problem if two processes try to work on the tty device ...

hmueller01 commented 3 years ago

As far as I tested right now it happens only using vclient. Using telnet I never got a SIGPIPE. Reading here looks like vclient is gone away while vcontrold still tries to write to the socket.

hmueller01 commented 3 years ago

I replaced line 946 in vcontrold.c

if (signal(SIGPIPE, sigPipeHandler) == SIG_ERR) {

by

if (signal(SIGPIPE, SIG_IGN) == SIG_ERR) {

and now it never crashs (even that the source of the problem is not solved).