OWX mit Denkovi USB Busmaster - Problem mit disconnect / reopen

Begonnen von tpm88, 31 Januar 2021, 11:44:54

Vorheriges Thema - Nächstes Thema

tpm88

Hallo pah,

ich betreibe einen Denkovi 1w Busmaster an einem Bus mit vier DS1820 Temperatursensoren.

Das läuft immer ein paar Tage stabil bis ein Disconnect des OWX IODev (Ursache noch ungeklärt) zu folgendem Fehlerbild führt:

OWX Logfile:
2021-01-25_23:48:11 denkovi_OWio DISCONNECTED
2021-01-26_08:36:39 denkovi_OWio CONNECTED                            <--- set denkovi_OWio reopen
2021-01-29_10:13:40 denkovi_OWio DISCONNECTED
2021-01-31_10:07:17 denkovi_OWio CONNECTED                            <--- set denkovi_OWio reopen


FHEM Logfile:
2021.01.25 23:48:11 1: /dev/ttyUSB97 disconnected, waiting to reappear (denkovi_OWio)
2021.01.25 23:48:11 1: OWX_SER::Query denkovi_OWio:  0 of 1 bytes in last attempt and state opened, this is an unrecoverable error
2021.01.25 23:49:11 1: OWX_Init called for bus denkovi_OWio with interface state opened, now going for detect
2021.01.25 23:49:11 1: Cannot init /dev/ttyUSB97, ignoring it (denkovi_OWio)
2021.01.25 23:49:12 1: OWX_SER::Query denkovi_OWio:  0 of 1 bytes in last attempt and state opened, this is an unrecoverable error
2021.01.25 23:49:17 1: OWX_SER::Query denkovi_OWio:  0 of 1 bytes in last attempt and state opened, this is an unrecoverable error
2021.01.25 23:49:18 1: OWX_SER::Query denkovi_OWio:  0 of 1 bytes in last attempt and state opened, this is an unrecoverable error
2021.01.25 23:49:21 1: OWX_SER::Query denkovi_OWio:  0 of 1 bytes in last attempt and state opened, this is an unrecoverable error
2021.01.25 23:49:22 1: OWX_SER::Query denkovi_OWio:  0 of 1 bytes in last attempt and state opened, this is an unrecoverable error
2021.01.25 23:49:25 1: OWX_SER::Query denkovi_OWio:  0 of 1 bytes in last attempt and state opened, this is an unrecoverable error
...


Ein manueller "reopen" bereinigt die Situation wieder:
2021.01.26 08:36:39 1: /dev/ttyUSB97 reappeared (denkovi_OWio)
2021.01.26 08:36:39 3: OWX_Set denkovi_OWio reopen => 0


Wieso verbleibt OWX_SER nach einem Disconnect im State "opened" ? Wird dadurch ein automatischer "reopen" verhindert?

Danke & VG
Tobias

PS: alle OWX Module auf aktuellem Stand, hier noch ein List des OWX-Device:

fhem> list denkovi_OWio
Internals:
   ALARMED    no
   ASYNCHRONOUS 1
   BUSY       0
   DEF        /dev/ttyUSB97
   DeviceName /dev/ttyUSB97
   FD         190
   FUUID      60045015-f33f-2a6d-19af-3851e8a1b9adc789
   INITDONE   1
   INTERFACE
   LASTSEND   1612088398.10724
   NAME       denkovi_OWio
   NR         687
   PARTIAL
   PRESENT    0
   ROM_ID     FF
   STATE      opened
   TYPE       OWX
   interval   300
   timeout    2
   DEVHASH:
     OWX_10_CC858D020800 10.CC858D020800.7D
     denkovi_OWio Busmaster
     hz_ds_RL   10.638C8D020800.F6
     hz_ds_VL   10.9B618D020800.13
     hz_ds_WW   10.FF818D020800.D6
   DEVS:
     10.CC858D020800.7D
     10.638C8D020800.F6
     10.9B618D020800.13
     10.FF818D020800.D6
   QUEUE:
   READINGS:
     2021-01-31 11:19:57   queue           2
     2021-01-31 10:07:17   state           opened
Attributes:
   asynchronous 1
   comment    /dev/serial/by-id/usb-FTDI_FT232R_USB_UART_DAE06Kth-if00-port0
   room       OWX
   verbose    3



Test FHEM Server on RPi, CUL_HM
Prod FHEM Server on Odroid HC1, HM-USB, JeeLink
Devices: diverse HM, IT1500, 1wire, LaCrosse, MQTT

tpm88

Hallo pah,

ich habe jetzt mal einen Blick in den Code von 11_OWX_SER.pm geworfen und habe die u.g. Fehlermeldung zum ersten Mal in Zeile 518 gefunden. Der Block sieht aber fast so aus, als wäre er versehentlich _nicht_ ausdokumentiert??


...
  #if( $numget >= $numexp){
  #  main::Log3 $name, 4, "OWX_SER::Query $name: $numget of $numexp bytes in 2nd attempt and state $state";
  #  return $buffer;
  #-- ultimate failure
  #}else{
    main::Log3 $name, 1,"OWX_SER::Query $name:  $numget of $numexp bytes in last attempt and state $state, this is an unrecoverable error";
    main::DevIo_Disconnected($hash);
    main::InternalTimer(main::gettimeofday()+$timeout, "main::OWX_Ready", $hash,0);
    return "";
  #}


  #--reopen device
  main::Log3 $name, 4, "OWX_SER::Query $name: trying to close and open the device";

  #-- the next two lines are required to avoid a deadlock when the remote end
  #   closes the connection upon DevIo_OpenDev, as e.g. netcat -l <port> does.
  main::DevIo_CloseDev($hash);
  main::DevIo_OpenDev($hash, 0, undef);

  #-- second try to read things - with timeout
  #$buffer .= main::DevIo_SimpleReadWithTimeout($hash, $timeout);
  $buffer .= main::DevIo_SimpleRead($hash);
  $numget  = (defined($buffer))?length($buffer):0;
...


Nach meinem Verständnis führt doch das in Zeile 521 stehende "return" genau dazu, daß der folgende "reopen" und zweite Versuch zum Lesen der Daten eben nicht mehr ausgeführt wird.

Oder irre ich mich?

Danke & Gruß
Tobias
Test FHEM Server on RPi, CUL_HM
Prod FHEM Server on Odroid HC1, HM-USB, JeeLink
Devices: diverse HM, IT1500, 1wire, LaCrosse, MQTT

Prof. Dr. Peter Henning

Öh. Stimmt. Ich kann mich nicht erinnern, wann und warum die Auskommentierung da hineingekommen ist  :(
Sehr peinlich.

Der ursprüngliche Code hatte schon seinen Sinn, sonst hätte ich ihn ja nicht geschrieben...

Allerdings läuft das Modul bei mir astrein, ohne disconnects.

Was tut sich denn mit dem Denkovi, wenn die Auskommentierung weg ist?

LG

pah

tpm88

Hallo pah,

danke für die Bestätigung. Ich habe jetzt mal den ganzen Block auskommentiert, sodaß der Code für reopen und zweiten Versuch beim Lesen bei Fehler greifen kann.

Natürlich ist seither noch kein "disconnect" wieder aufgetreten...

Was mir aber außerdem noch aufgefallen ist. Nach dem Editieren der 11_OWX_SER habe ich einen reload des Moduls gemacht:

fhem> reload 11_OWX_SER
Undefined subroutine &main::OWX_SER_Initialize called at fhem.pl line 2661.


Bei mir läuft folgende Version von fhem.pl
fhem.pl                23471 2021-01-04 19:24:21Z rudolfkoenig

Zeile 2661 ist in folgendem Block in der Funktion CommandReload:

...
    # Get the name of the initialize function. This may differ from the
    # filename as sometimes we live on a FAT fs with wrong case.
    my $fnname = $m;
    foreach my $i (keys %main::) {
      if($i =~ m/^(${m})_initialize$/i) {
        $fnname = $1;
        last;
      }
    }
    &{ "${fnname}_Initialize" }(\%hash);
    $m = $fnname;
    return undef;


Ich bin mir jetzt nicht sicher, ob das wirklich ein Problem ist, oder ob ein reload bei 11_OWX_SER als zweistufiges Modul einfach keine gute Idee ist.

VG
Tobias

Test FHEM Server on RPi, CUL_HM
Prod FHEM Server on Odroid HC1, HM-USB, JeeLink
Devices: diverse HM, IT1500, 1wire, LaCrosse, MQTT

Prof. Dr. Peter Henning

Zitatreload bei 11_OWX_SER als zweistufiges Modul einfach keine gute Idee ist.
So ist es.

Mal abwarten,was sich tut.

LG

pah

tpm88

Zitat von: Prof. Dr. Peter Henning am 06 Februar 2021, 07:21:55
Mal abwarten,was sich tut.

Heute gab es wieder zwei Abbrüche tagsüber - hier die Auszüge aus dem FHEM-Log:

Disconnect 1:

2021.02.07 10:02:33 1: /dev/ttyUSB97 disconnected, waiting to reappear (denkovi_OWio)
2021.02.07 10:02:33 1: OWX_SER::DEBUG 1 - pre reopen
2021.02.07 10:02:33 1: OWX_SER::DEBUG 2 - after reopen
2021.02.07 10:02:33 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at ./FHEM/11_OWX_SER.pm line 541.
2021.02.07 10:02:33 1: OWX_SER::DEBUG 3 - pre giveup
2021.02.07 10:02:33 1: OWX_SER::Query denkovi_OWio:  0 of 1 bytes in last attempt and state opened, this is an unrecoverable error

==> manuell: set denkovi_OWio reopen:

2021.02.07 10:16:15 1: /dev/ttyUSB97 reappeared (denkovi_OWio)
2021.02.07 10:16:15 3: OWX_Set denkovi_OWio reopen => 0
2021.02.07 10:16:15 1: PERL WARNING: Use of uninitialized value in bitwise and (&) at ./FHEM/00_OWX.pm line 941.


Disconnect 2:
2021.02.07 12:42:34 1: /dev/ttyUSB97 disconnected, waiting to reappear (denkovi_OWio)
2021.02.07 12:42:34 1: OWX_SER::DEBUG 1 - pre reopen
2021.02.07 12:42:34 1: OWX_SER::DEBUG 2 - after reopen
2021.02.07 12:42:34 1: OWX_SER::DEBUG 3 - pre giveup
2021.02.07 12:42:34 1: OWX_SER::Query denkovi_OWio:  0 of 1 bytes in last attempt and state opened, this is an unrecoverable error

==> manuell: set denkovi_OWio reopen:

2021.02.07 15:02:13 1: /dev/ttyUSB97 reappeared (denkovi_OWio)
2021.02.07 15:02:13 3: OWX_Set denkovi_OWio reopen => 0


Log vom 1w OWX Busmaster:

2021-02-07_10:02:33 denkovi_OWio DISCONNECTED
2021-02-07_10:16:15 denkovi_OWio CONNECTED
2021-02-07_12:42:34 denkovi_OWio DISCONNECTED
2021-02-07_15:02:13 denkovi_OWio CONNECTED


Nur beim ersten Mal gab es noch die zwei Perl Warnings. Beide Male hat aber leider der unmittelbare "reopen" in der Routine query nicht geholfen. Vermutlich kommt dieser zu schnell. Zumindest wird jetzt aber die Meldung über den "unrecoveryble error" nur noch einmal ausgelöst und nicht wie vorher bei jedem Lesezugriff.

Wie vor der Modifikation auch hat ein späteres manuelles "set reopen" die Kommunikation wieder korrekt aufgesetzt.

Ich hänge unten noch die gesamte von mir modifizierte Routine query an, damit Du die zusätzlich DEBUG-Zeilen nachvollziehen kannst.

VG
Tobias:

Routine query aus 00_OWX_SER.pm:

sub Query ($$) {

  my ($self,$cmd,$numexp) = @_;
  my $hash     = $self->{hash};
  my $name     = $hash->{NAME};
  my $state    = $hash->{STATE};
  my $timeout  = $hash->{timeout};
  my $numget   = 0;
  my $buffer   = "";
  my $try;

  if($state ne "opened") {
    main::Log3 $name, 4, "OWX_SER::Query $name: attempted to write to $state device $name";
    return undef;
  }

  #-- write operation
  main::OWX_WDBGL($name,5,"OWX_SER::Query $name: Sending out",$cmd);
  return undef unless defined(main::DevIo_SimpleWrite($hash, $cmd, 0));

  #-- sleeping for some time
  select(undef,undef,undef,0.04);

  #-- first try to read things
  $buffer = main::DevIo_SimpleRead($hash);
  $numget  = (defined($buffer))?length($buffer):0;

  #-- first try ok
  if( $numget >= $numexp){
    main::Log3 $name, 4, "OWX_SER::Query $name: $numget of $numexp bytes in first attempt and state $state";
    return $buffer;
  #-- several tries to read from slow device
  }elsif( ($numget>0) && ($numget<$numexp) ){
    for($try=0;$try<3;$try++) {
      $buffer .= main::DevIo_SimpleRead($hash);
      $numget  = length($buffer);
      last
        if( $numget>=$numexp );
      select(undef,undef,undef,0.01);
    }
    main::Log3 $name, 5, "OWX_SER::Query $name: $numget of $numexp bytes in attempt $try and state $state"
      if( $numget < $numexp );
    return $buffer
      if( $numget >= $numexp);
  }

  #if( $numget >= $numexp){
  #  main::Log3 $name, 4, "OWX_SER::Query $name: $numget of $numexp bytes in 2nd attempt and state $state";
  #  return $buffer;
  #-- ultimate failure
  #}else{
  # main::Log3 $name, 1,"OWX_SER::Query $name:  $numget of $numexp bytes in last attempt and state $state, this is an unrecoverable error";
  # main::Log3 $name, 1,"OWX_SER::DEBUG 1";
  # main::DevIo_Disconnected($hash);
  # main::InternalTimer(main::gettimeofday()+$timeout, "main::OWX_Ready", $hash,0);
  # main::Log3 $name, 1,"OWX_SER::DEBUG 2";
  # return "";
  # main::Log3 $name, 1,"OWX_SER::DEBUG 3";
  #}

  main::Log3 $name, 1,"OWX_SER::DEBUG 1 - pre reopen";

  #--reopen device
  main::Log3 $name, 4, "OWX_SER::Query $name: trying to close and open the device";

  #-- the next two lines are required to avoid a deadlock when the remote end
  #   closes the connection upon DevIo_OpenDev, as e.g. netcat -l <port> does.
  main::DevIo_CloseDev($hash);
  main::DevIo_OpenDev($hash, 0, undef);

  main::Log3 $name, 1,"OWX_SER::DEBUG 2 - after reopen";

  #-- second try to read things - with timeout
  #$buffer .= main::DevIo_SimpleReadWithTimeout($hash, $timeout);
  $buffer .= main::DevIo_SimpleRead($hash);
  $numget  = (defined($buffer))?length($buffer):0;

  #-- second try ok
  if( $numget >= $numexp){
    main::Log3 $name, 4, "OWX_SER::Query $name: $numget of $numexp bytes after reopening and state $state";
    return $buffer;
  #-- several tries to read from slow device
  }elsif( ($numget>0) && ($numget<$numexp) ){
    for($try=0;$try<4;$try++) {
      $buffer .= main::DevIo_SimpleRead($hash);
      $numget  = length($buffer);
      last
        if( $numget>=$numexp );
      select(undef,undef,undef,0.01);
    }
    main::Log3 $name, 5, "OWX_SER::Query $name: $numget of $numexp bytes in 2nd attempt try $try and state $state"
      if( $numget < $numexp );
  }

  if( $numget >= $numexp){
    main::Log3 $name, 4, "OWX_SER::Query $name: $numget of $numexp bytes in 2nd attempt and state $state";
    return $buffer;
  #-- ultimate failure
  }else{
    main::Log3 $name, 1,"OWX_SER::DEBUG 3 - pre giveup";
    main::Log3 $name, 1,"OWX_SER::Query $name:  $numget of $numexp bytes in last attempt and state $state, this is an unrecoverable error";
    main::DevIo_Disconnected($hash);
    return "";
  }
}
Test FHEM Server on RPi, CUL_HM
Prod FHEM Server on Odroid HC1, HM-USB, JeeLink
Devices: diverse HM, IT1500, 1wire, LaCrosse, MQTT

Prof. Dr. Peter Henning

OK, wird allerdings in den beiden nächsten Wochen nichts mit dem Einbau.

LG

pah

soho24

Hallo Tobias,

auf meinem Raspberry lief nun seit ca. 8 Jahren fhem mit dem one-wire USB Interface problemlos. Seit kurzem habe ich aber auch immer häufiger disconnects. Nach einem kürzlichen Update von fhem funktioniert leider auch das re-connect nicht mehr.
Zunächst möchte ich allerdings erstmal schauen woher das häufige disconnect kommt, das über Jahre hinweg niemals aufgetaucht ist. Da ich an der Raspberry- und Fhem- Konfiguration seit Jahren nichts geändert habe frage ich mich ob es evtl and dem USB-serial-onewire Stick liegen kann.

Weist du inzwischen woher die disconnects bei dir kommen?

Danke und Gruß, Holger
-------------------------------------------
Raspberry Pi - Raspbian
HM LAN - Konfigurationsadapter
SIGNALduino
ConbeeII - deCONZ

tpm88

Zitat von: soho24 am 11 Februar 2021, 21:18:40
Weist du inzwischen woher die disconnects bei dir kommen?

Zuallererst - über einen langen Zeitraum habe ich den gleichen 1w-Bus an einem wemos01 mit ESPeasy betrieben und bin erst vor kurzem auf den Denkovi Bus Master an USB umgestiegen, um die nicht 100% zuverlässige WLAN Verbindung im Keller zu eliminieren.

Reproduzieren kann ich die disconnects nicht - allerdings könnten sie an meinem speziellen Setup liegen:

1wire-Bus --> Denkovi 1w Adapter -> ttyUSB auf RPi  -> ser2net -> LAN -> Odroid hc1 -> socat -> ttyUSB -> OWX(_SER) (FHEM)

Wieso socat, wo pah doch in der CommandRef zu OWX (TCP) ausdrücklich erwähnt, daß es nicht erforderlich ist?

Anfangs hatte ich große Probleme, daß die DS1820 Temperatursensoren überhaupt von OWX gesehen wurden. Meine ersten Versuche, den Busmaster am entfernten RPi über ser2net mittels OWX (TCP) direkt anzusprechen, schlugen komplett fehl. Mit korrekter ser2net Parametrisierung (9600 Bit/s, 8N1) hat sich dann zwar OWX (TCP) mit dem Busmaster verbunden, jedoch eben keine 1w Devices gefunden. Darauß schloß ich (fälschlicherweise), daß die direkte OWX (TCP) Verbindung über den Umweg ser2net nicht funktioniert. Anschließend habe ich mit genausowenig Erfolg die obige Variante mit socat getestet, aber ebenfalls keine Devices gefunden.

Nach weiteren fehlgeschlagenen Tests mit dem Denkovi mit einem einzelnen DS1820 und dem Original Maxim OneWireViewer direkt am Windows Laptop war ich kurz davor, den Busmaster als defekt auszusortieren. Dann erst ist mir der via Jumper zuschaltbare RC Filter aufgefallen. Der DS1820 wurde weder in Jumper Stellung RC Filter on noch off gefunden. Sehr wohl aber nach kompletten Entfernen (!!) des Jumpers ...

Anschließend habe ich den Adapter wieder an den ursprünglichen 1w Bus angeschlossen  - und prompt hat OWX (SER) via ser2net / socat alle angeschlossenen DS1820 gefunden... Froh darüber habe ich an die ursprüngliche Idee - ohne socat - direkt OWX (TCP) zu verwenden gar nicht mehr gedacht.

Lange Rede kurzer Sinn - zwischenzeitlich habe ich wie folgt vereinfacht:

1wire-Bus --> Denkovi 1w Adapter -> ttyUSB  auf RPi -> ser2net -> LAN -> Odroid hc1 ->  OWX(_TCP) FHEM

Das läuft jetzt seit einigen Tagen stabil.

@pah - das erklärt sicher auch, daß mein oben beschriebenes Problem bei dir nie aufgetreten ist.

VG
Tobias
Test FHEM Server on RPi, CUL_HM
Prod FHEM Server on Odroid HC1, HM-USB, JeeLink
Devices: diverse HM, IT1500, 1wire, LaCrosse, MQTT

Prof. Dr. Peter Henning

#9
Zitat1wire-Bus --> Denkovi 1w Adapter -> ttyUSB auf RPi  -> ser2net -> LAN -> Odroid hc1 -> socat -> ttyUSB -> OWX(_SER) (FHEM)

Viel komplizierter geht es nicht - wie ziehst Du Dich morgens an?  8)

LG

pah

tpm88

Zitat von: Prof. Dr. Peter Henning am 14 Februar 2021, 17:03:10
Viel komplizierter geht es nicht - wie ziehst Du Dich morgens an?  8)

Darum habe ich es ja jetzt radikal vereinfacht  ;D

Nein, im Ernst, am gleichen remote Pi hängt auch noch ein Arduino Nano, welcher mittels ArduCounter Sketch den Gas- und Wasserzähler ausliest. Dieses serielle Device reiche ich ebenfalls per ser2net und socat an den FHEM Rechner mit dem ArduCounter Modul weiter. Rock solid... 

VG
Tobias
Test FHEM Server on RPi, CUL_HM
Prod FHEM Server on Odroid HC1, HM-USB, JeeLink
Devices: diverse HM, IT1500, 1wire, LaCrosse, MQTT

Elektron

Hallo zusammen,

Ich möchte das Thema mal wieder hochbringen...

Ich hatte auch ein viele Jahre stabil laufende Installation mit 1-Wire, habe dann mein Raspberry Pi mal neu aufgesetzt und danach fiel mir auf, dass die 1-Wire Anbindung nicht stabil läuft.

Ich kann die Beobachten die meine Vorposter beschrieben haben bestätigen.

- die Werte der Sensoren werden nicht aktualisiert, das Interface steht noch auf ,,opened" aber es können keine Sensoren mehr gelesen werden.
- wenn ich in diesem Zustand anzeigen lasse, welche Devices am Bus sind, bekomme ich keine angezeigt.
- ich kann den Fehler provozieren, wenn ich einen Sensor abfrage der nicht am Bus vorhanden ist.
- mit einem reopen kann ich es wieder temporär ,,heilen".

Kann ich mit weiteren Informationen helfen?

Viele Grüße Michael

Elektron

Hallo zusammen,

Was ich gestern vergessen habe zu erwähnen.
- ich hatte bisher einen USB 1Wire Adapter von Fuchs, den hatte ich in der Vergangenheit immer direkt am RaspberryPi hängen gehabt.
- ich habe den Adapter auch schon über einen aktiven USB Hub versorgt.
- ich habe mir einen neuen 1Wire USB Adapter nach der Anleitung von PAH gebaut.

Alles das führt zum selben Ergebnis.
Wenn ich per dmesg nachsehe, bleibt das USB Device verbunden, sonst wäre ja auch ein set reconnect nicht erfolgreich wenn das USB Device ,,weg" wäre...

Viele Grüße Michael

Prof. Dr. Peter Henning

Keine Ahnung - meine 5 1-Wire Busse, alle mit OWX, laufen stabil.

Davon 4x USB, einer an einem alten CUNO.

LG

pah