Hauptmenü

DBlog Error

Begonnen von wuast94, 27 November 2017, 17:59:56

Vorheriges Thema - Nächstes Thema

wuast94

Habe mein dblog auf asyncMode gestellt und mit DbRep ein dump gemacht .. seit dem kommt im dblog folgender state:
DBD::mysql::st execute_array failed: executing 1198 generated 2 errors at ./FHEM/93_DbLog.pm line 1859.
, DBD::mysql::st execute_array failed: executing 1198 generated 1 errors at ./FHEM/93_DbLog.pm line 1895.


in den beiden zeilen im modul steht folgendes:
line 1859 ($tuples, $rows) = $sth_ih->execute_array( { ArrayTupleStatus => \my @tuple_status } );
line 1895 ($tuples, $rows) = $sth_uc->execute_array( { ArrayTupleStatus => \my @tuple_status } );


und als ganzer auszug der beiden code lines:
# insert into history
  eval {$dbh->begin_work();};  # issue:  begin_work failed: Turning off AutoCommit failed
  if ($@) {
      Log3($name, 2, "DbLog $name -> Error start transaction for history - $@");
  }
  eval {
      if (lc($DbLogType) =~ m(history) ) {
          ($tuples, $rows) = $sth_ih->execute_array( { ArrayTupleStatus => \my @tuple_status } );
  if($tuples && $rows == $ceti) {
      Log3 $hash->{NAME}, 5, "DbLog $name -> $rows of $ceti events inserted into table history".($usepkh?" using PK on columns $pkh":"");
  } else {
      for my $tuple (0..$#row_array) {
      my $status = $tuple_status[$tuple];
  $status = 0 if($status eq "0E0");
  next if($status);         # $status ist "1" wenn insert ok
  Log3 $hash->{NAME}, 3, "DbLog $name -> Insert into history rejected".($usepkh?" (possible PK violation) ":" ")."- TS: $timestamp[$tuple], Device: $device[$tuple], Event: $event[$tuple]";
  }
  }
      }
  };
 
  if ($@) {
      Log3 $hash->{NAME}, 2, "DbLog $name -> Error table history - $@";
  $errorh = $@;
      eval {$dbh->rollback() if(!$dbh->{AutoCommit});};  # issue Turning on AutoCommit failed
  if ($@) {
          Log3($name, 2, "DbLog $name -> Error rollback history - $@");
      }
      $rowlback = $rowlist;
  } else {
      eval {$dbh->commit() if(!$dbh->{AutoCommit});};    # issue Turning on AutoCommit failed
      if ($@) {
          Log3($name, 2, "DbLog $name -> Error commit history - $@");
      }
  }
 
  # update or insert current
  eval {$dbh->begin_work();};  # issue:  begin_work failed: Turning off AutoCommit failed
  if ($@) {
      Log3($name, 2, "DbLog $name -> Error start transaction for current - $@");
  }
  eval {
  if (lc($DbLogType) =~ m(current) ) {
          ($tuples, $rows) = $sth_uc->execute_array( { ArrayTupleStatus => \my @tuple_status } );
  if($tuples && $rows == $ceti) {
      Log3 $hash->{NAME}, 5, "DbLog $name -> $rows of $ceti events updated in table current".($usepkc?" using PK on columns $pkc":"");
  } elsif ($tuples && $rows >= $ceti) {
      Log3 $hash->{NAME}, 5, "DbLog $name -> $ceti events inserted or replaced in table current".($usepkc?" using PK on columns $pkc":"");
  } else {
      $doins = 1;
  $ceti = 0;
  for my $tuple (0..$#device) {
      my $status = $tuple_status[$tuple];
      $status = 0 if($status eq "0E0");
      next if($status);         # $status ist "1" wenn update ok
      $ceti++;
      Log3 $hash->{NAME}, 5, "DbLog $name -> Failed to update in current, try to insert - TS: $timestamp[$tuple], Device: $device[$tuple], Reading: $reading[$tuple], Status = $status";
      push(@timestamp_cur, "$timestamp[$tuple]");
              push(@device_cur, "$device[$tuple]");   
              push(@type_cur, "$type[$tuple]"); 
              push(@event_cur, "$event[$tuple]"); 
              push(@reading_cur, "$reading[$tuple]");
              push(@value_cur, "$value[$tuple]");
              push(@unit_cur, "$unit[$tuple]");
      }
  }
 
  if ($doins) {
      # events die nicht in Tabelle current updated wurden, werden in current neu eingefügt
      $sth_ic->bind_param_array(1, [@timestamp_cur]);
              $sth_ic->bind_param_array(2, [@device_cur]);
              $sth_ic->bind_param_array(3, [@type_cur]);
              $sth_ic->bind_param_array(4, [@event_cur]);
              $sth_ic->bind_param_array(5, [@reading_cur]);
              $sth_ic->bind_param_array(6, [@value_cur]);
              $sth_ic->bind_param_array(7, [@unit_cur]);
             
  ($tuples, $rows) = $sth_ic->execute_array( { ArrayTupleStatus => \my @tuple_status } );
  if($tuples && $rows == $ceti) {
          Log3 $hash->{NAME}, 5, "DbLog $name -> $rows of $ceti events inserted into table current".($usepkc?" using PK on columns $pkc":"");
      } else {
      for my $tuple (0..$#device_cur) {
          my $status = $tuple_status[$tuple];
          $status = 0 if($status eq "0E0");
          next if($status);         # $status ist "1" wenn insert ok
          Log3 $hash->{NAME}, 2, "DbLog $name -> Insert into current rejected - TS: $timestamp[$tuple], Device: $device_cur[$tuple], Reading: $reading_cur[$tuple], Status = $status";
      }
      }
          }
  }
  };

  if ($@) {
      Log3 $hash->{NAME}, 2, "DbLog $name -> Error table current - $@";
  $errorc = $@;
      eval {$dbh->rollback() if(!$dbh->{AutoCommit});};  # issue Turning on AutoCommit failed
  if ($@) {
          Log3($name, 2, "DbLog $name -> Error rollback current - $@");
      }
  } else {
      eval {$dbh->commit() if(!$dbh->{AutoCommit});};    # issue Turning on AutoCommit failed
      if ($@) {
          Log3($name, 2, "DbLog $name -> Error commit current - $@");
      }
  }
 
  $dbh->disconnect();
Zigbee  Temp+Luftdruck+Humi Bewegungsmeldern Tür Kontakte, Klingel, TV, Denon, Schaltbare Steckdosen mit leistungsmessung, und weiteres

Homeassistant mit Nodered

DS_Starter

#1
Mach mal bitte ein list deines Dblog-Devices und einen Verbose 5 Log-Auszug (NUR das DbLog Device auf verbose 5 setzen).

Interessant ist der Teil ab bzw. bis:


2017.11.27 18:27:13.035 5: DbLog LogDB -> ################################################################
2017.11.27 18:27:13.036 5: DbLog LogDB -> ###      New database processing cycle - asynchronous        ###
2017.11.27 18:27:13.036 5: DbLog LogDB -> ################################################################
2017.11.27 18:27:13.037 5: DbLog LogDB -> MemCache contains 17 entries to process
......

2017.11.27 18:27:13.287 5: DbLog LogDB -> DbLog_PushAsync finished
2017.11.27 18:27:13.290 5: DbLog LogDB -> Start DbLog_PushAsyncDone


Edit: -> new databse cycle

Grüße,
Heiko
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

wuast94

#2
list:
Internals:
   COLUMNS    field length used for Device: 64, Type: 64, Event: 512, Reading: 64, Value: 128, Unit: 32
   CONFIGURATION ./contrib/dblog/db.conf
   DEF        ./contrib/dblog/db.conf .*:(cpu_freq|cpu_temp|eth0|eth0_diff|ram|4.ACTUAL_TEMPERATURE|4.BATTERY_STATE|4.SET_TEMPERATURE|4.VALVE_STATE|temperature|pressure|humidity|energy|power|state).*
   MODE       asynchronous
   MODEL      MYSQL
   NAME       logdb
   NR         30
   NTFY_ORDER 50-logdb
   PID        17
   REGEXP     .*:(cpu_freq|cpu_temp|eth0|eth0_diff|ram|4.ACTUAL_TEMPERATURE|4.BATTERY_STATE|4.SET_TEMPERATURE|4.VALVE_STATE|temperature|pressure|humidity|energy|power|state).*
   STATE      connected
   TYPE       DbLog
   UTF8       0
   VERSION    2.22.13
   dbconn     mysql:database=fhem;host=mysql;port=3306
   dbuser     fhemuser
   HELPER:
     COLSET     1
     DEVICECOL  64
     EVENTCOL   512
     READINGCOL 64
     TYPECOL    64
     UNITCOL    32
     VALUECOL   128
     RUNNING_PID:
       abortFn    DbLog_PushAsyncAborted
arg logdb|ewig lange zeichenkette

bc_pid     1643
       finishFn   DbLog_PushAsyncDone
       fn         DbLog_PushAsync
       pid        1675
       telnet     telnetPort_127.0.0.1_59840
       timeout    86400
       abortArg:
   Helper:
     DBLOG:
       state:
         logdb:
           TIME       1511801632.8392
           VALUE      1089 cache rows exported to ./log/cache_logdb_2017-11-27_17-53-52
   READINGS:
     2017-11-27 19:02:48   CacheUsage      2
     2017-11-27 19:02:48   NextSync        2017-11-27 19:03:48 or if CacheUsage 50 reached
     2017-11-19 12:22:16   countCurrent    13
     2017-11-19 12:22:16   countHistory    11284
     2017-11-27 17:53:52   lastCachefile   ./log/cache_logdb_2017-11-27_17-53-52 export successful
     2017-11-27 19:02:48   state           connected
   cache:
     index      3420750
     memcache:
       3420749    2017-11-27 19:02:48|Strom_Gesamt|DUMMY|energy: 720.58|energy|720.58|
       3420750    2017-11-27 19:02:48|Strom_Addi|AT|state: Next: 19:02:53|state|Next|19:02:53
Attributes:
   DbLogType  Current/History
   asyncMode  1
   cacheLimit 50
   group      Logging
   room       Log
   syncInterval 60
   verbose    5


Fhem log:
2017.11.27 19:05:05 5 : DbLog logdb -> Start DbLog_PushAsyncDone
2017.11.27 19:05:05 4 : DbLog logdb -> ################################################################
2017.11.27 19:05:05 4 : DbLog logdb -> ### start of new Logcycle ###
2017.11.27 19:05:05 4 : DbLog logdb -> ################################################################
2017.11.27 19:05:05 4 : DbLog logdb -> amount of events received: 1 for device: logdb
2017.11.27 19:05:05 4 : DbLog logdb -> check Device: logdb , Event: state: DBD::mysql::st execute_array failed: executing 4414 generated 2 errors at ./FHEM/93_DbLog.pm line 1859. , DBD::mysql::st execute_array failed: executing 4414 generated 1 errors at ./FHEM/93_DbLog.pm line 1895.
2017-11-27 19:05:05 DbLog logdb DBD::mysql::st execute_array failed: executing 4414 generated 2 errors at ./FHEM/93_DbLog.pm line 1859. , DBD::mysql::st execute_array failed: executing 4414 generated 1 errors at ./FHEM/93_DbLog.pm line 1895.
2017.11.27 19:05:05 5 : DbLog logdb -> DbLog_PushAsyncDone finished


EDIT: Ich mache alle 30 Min mal n exportCache nopurge .. nur so für die sicherheit :D da ich jetzt erst mal schlafen muss :D
Zigbee  Temp+Luftdruck+Humi Bewegungsmeldern Tür Kontakte, Klingel, TV, Denon, Schaltbare Steckdosen mit leistungsmessung, und weiteres

Homeassistant mit Nodered

DS_Starter

Das ist noch nicht der richtige Logauszug.

Ich bräuchte die Daten ab:

Zitat
2017.11.27 18:27:13.035 5: DbLog LogDB -> ################################################################
2017.11.27 18:27:13.036 5: DbLog LogDB -> ###      New database processing cycle - asynchronous        ###
2017.11.27 18:27:13.036 5: DbLog LogDB -> ################################################################[/b]

Also "New database processing cycle - asynchronous".

Setze dir auch mal das Attr excludeDevs = TYPE=DbLog.

Und keine Angst, diese Meldung ist mit ziemlicher Sicherheit nichts kritisches, die DB loggt sicher fröhlich vor sich hin.
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

wuast94

2017.11.28 14:18:27 5: DbLog logdb -> ################################################################
2017.11.28 14:18:27 5: DbLog logdb -> ###      New database processing cycle - asynchronous        ###
2017.11.28 14:18:27 5: DbLog logdb -> ################################################################
2017.11.28 14:18:27 5: DbLog logdb -> MemCache contains 200 entries to process
2017.11.28 14:18:27 5: DbLog logdb -> MemCache contains: 2017-11-28 14:18:22|Strom_Gesamt|DUMMY|power: 174.2|power|174.2|
2017.11.28 14:18:27 5: DbLog logdb -> MemCache contains: 2017-11-28 14:18:22|Strom_Gesamt|DUMMY|energy: 723.07|energy|723.07|
2017.11.28 14:18:27 5: DbLog logdb -> MemCache contains: 2017-11-28 14:18:22|Strom_Addi|AT|state: Next: 14:18:27|state|Next|14:18:27
2017.11.28 14:18:27 5: DbLog logdb -> MemCache contains: 2017-11-28 14:18:17|Strom_Gesamt|DUMMY|energy: 723.07|energy|723.07|
2017.11.28 14:18:27 5: DbLog logdb -> MemCache contains: 2017-11-28 14:18:17|Strom_Addi|AT|state: Next: 14:18:22|state|Next|14:18:22
2017.11.28 14:18:27 5: DbLog logdb -> MemCache contains: 2017-11-28 14:18:12|Strom_Gesamt|DUMMY|power: 173.5|power|173.5|

und so weiter ....

2017.11.28 14:18:27 5: DbLog logdb -> DbLog_PushAsync called with timeout: 86400
2017.11.28 14:18:27 4: DbLog logdb -> ################################################################
2017.11.28 14:18:27 4: DbLog logdb -> ###              start of new Logcycle                       ###
2017.11.28 14:18:27 4: DbLog logdb -> ################################################################
2017.11.28 14:18:27 4: DbLog logdb -> amount of events received: 1 for device: Strom_Gesamt
2017.11.28 14:18:27 4: DbLog logdb -> check Device: Strom_Gesamt , Event: energy: 723.07
2017.11.28 14:18:27 4: DbLog logdb -> added event - Timestamp: 2017-11-28 14:18:27, Device: Strom_Gesamt, Type: DUMMY, Event: energy: 723.07, Reading: energy, Value: 723.07, Unit:
2017.11.28 14:18:27 4: DbLog logdb -> ################################################################
2017.11.28 14:18:27 4: DbLog logdb -> ###              start of new Logcycle                       ###
2017.11.28 14:18:27 4: DbLog logdb -> ################################################################
2017.11.28 14:18:27 4: DbLog logdb -> amount of events received: 1 for device: Strom_Addi
2017.11.28 14:18:27 4: DbLog logdb -> check Device: Strom_Addi , Event: state: Next: 14:18:32
2017.11.28 14:18:27 4: DbLog logdb -> added event - Timestamp: 2017-11-28 14:18:27, Device: Strom_Addi, Type: AT, Event: state: Next: 14:18:32, Reading: state, Value: Next, Unit: 14:18:32
2017.11.28 14:18:27 5: DbLog logdb -> Start DbLog_PushAsync
2017.11.28 14:18:27 5: DbLog logdb -> DbLogType is: Current/History
2017.11.28 14:18:27 5: DbLog logdb -> Primary Key used in fhem.history: none
2017.11.28 14:18:27 5: DbLog logdb -> Primary Key used in fhem.current: none
2017.11.28 14:18:27 5: DbLog logdb -> processing event Timestamp: 2017-11-28 14:18:22, Device: Strom_Gesamt, Type: DUMMY, Event: power: 174.2, Reading: power, Value: 174.2, Unit:
2017.11.28 14:18:27 5: DbLog logdb -> processing event Timestamp: 2017-11-28 14:18:22, Device: Strom_Gesamt, Type: DUMMY, Event: energy: 723.07, Reading: energy, Value: 723.07, Unit:
2017.11.28 14:18:27 5: DbLog logdb -> processing event Timestamp: 2017-11-28 14:18:22, Device: Strom_Addi, Type: AT, Event: state: Next: 14:18:27, Reading: state, Value: Next, Unit: 14:18:27
2017.11.28 14:18:27 5: DbLog logdb -> processing event Timestamp: 2017-11-28 14:18:17, Device: Strom_Gesamt, Type: DUMMY, Event: energy: 723.07, Reading: energy, Value: 723.07, Unit:
2017.11.28 14:18:27 5: DbLog logdb -> processing event Timestamp: 2017-11-28 14:18:17, Device: Strom_Addi, Type: AT, Event: state: Next: 14:18:22, Reading: state, Value: Next, Unit: 14:18:22
2017.11.28 14:18:27 5: DbLog logdb -> processing event Timestamp: 2017-11-28 14:18:12, Device: Strom_Gesamt, Type: DUMMY, Event: power: 173.5, Reading: power, Value: 173.5, Unit:

...  und so weiter


da ist am ende auch nix von:
2017.11.27 18:27:13.287 5: DbLog LogDB -> DbLog_PushAsync finished
2017.11.27 18:27:13.290 5: DbLog LogDB -> Start DbLog_PushAsyncDone

wie du sagtest

das einzige was er macht  ist die fhem.log bei mir über nacht knapp 8gb groß werden lassen :D
Zigbee  Temp+Luftdruck+Humi Bewegungsmeldern Tür Kontakte, Klingel, TV, Denon, Schaltbare Steckdosen mit leistungsmessung, und weiteres

Homeassistant mit Nodered

wuast94

jetzt habe ich glaube ich mehr gefunden:

2017.11.28 14:14:22 4: DbLog logdb -> ################################################################
2017.11.28 14:14:22 4: DbLog logdb -> ###              start of new Logcycle                       ###
2017.11.28 14:14:22 4: DbLog logdb -> ################################################################
2017.11.28 14:14:22 4: DbLog logdb -> amount of events received: 1 for device: Strom_Gesamt
2017.11.28 14:14:22 4: DbLog logdb -> check Device: Strom_Gesamt , Event: power: 175.5
2017.11.28 14:14:22 4: DbLog logdb -> added event - Timestamp: 2017-11-28 14:14:22, Device: Strom_Gesamt, Type: DUMMY, Event: power: 175.5, Reading: power, Value: 175.5, Unit:
2017.11.28 14:14:22 5: DbLog logdb -> Number of cache entries reached cachelimit 50 - start database sync.
2017.11.28 14:14:22 5: DbLog logdb -> ################################################################
2017.11.28 14:14:22 5: DbLog logdb -> ###      New database processing cycle - asynchronous        ###
2017.11.28 14:14:22 5: DbLog logdb -> ################################################################
2017.11.28 14:14:22 5: DbLog logdb -> MemCache contains 50 entries to process
2017.11.28 14:14:22 5: DbLog logdb -> MemCache contains: 2017-11-28 14:13:57|dblog_DbRep|DBREP|state: connected|state|connected|
2017.11.28 14:14:22 5: DbLog logdb -> MemCache contains: 2017-11-28 14:13:59|GZ_Strom_PC|ZWAVE|power: 146.0 W|power|146.0|W

... gekürzt

2017.11.28 14:14:22 5: DbLog logdb -> MemCache contains: 2017-11-28 14:13:57|Strom_Gesamt|DUMMY|power: 64.7|power|64.7|
2017.11.28 14:14:22 5: DbLog logdb -> MemCache contains: 2017-11-28 14:13:57|Strom_Gesamt|DUMMY|energy: 720.58|energy|720.58|
2017.11.28 14:14:22 5: DbLog logdb -> MemCache contains: 2017-11-28 14:13:57|Strom_Addi|AT|state: Next: 14:14:02|state|Next|14:14:02
2017.11.28 14:14:22 5: DbLog logdb -> DbLog_PushAsync called with timeout: 86400
2017.11.28 14:14:22 4: DbLog logdb -> ################################################################
2017.11.28 14:14:22 4: DbLog logdb -> ###              start of new Logcycle                       ###
2017.11.28 14:14:22 4: DbLog logdb -> ################################################################
2017.11.28 14:14:22 4: DbLog logdb -> amount of events received: 1 for device: Strom_Gesamt
2017.11.28 14:14:22 4: DbLog logdb -> check Device: Strom_Gesamt , Event: energy: 720.58
2017.11.28 14:14:22 4: DbLog logdb -> added event - Timestamp: 2017-11-28 14:14:22, Device: Strom_Gesamt, Type: DUMMY, Event: energy: 720.58, Reading: energy, Value: 720.58, Unit:
2017.11.28 14:14:22 4: DbLog logdb -> ################################################################
2017.11.28 14:14:22 4: DbLog logdb -> ###              start of new Logcycle                       ###
2017.11.28 14:14:22 4: DbLog logdb -> ################################################################
2017.11.28 14:14:22 4: DbLog logdb -> amount of events received: 1 for device: Strom_Addi
2017.11.28 14:14:22 4: DbLog logdb -> check Device: Strom_Addi , Event: state: Next: 14:14:27
2017.11.28 14:14:22 4: DbLog logdb -> added event - Timestamp: 2017-11-28 14:14:22, Device: Strom_Addi, Type: AT, Event: state: Next: 14:14:27, Reading: state, Value: Next, Unit: 14:14:27
2017.11.28 14:14:22 5: DbLog logdb -> Start DbLog_PushAsync
2017.11.28 14:14:22 5: DbLog logdb -> DbLogType is: Current/History
2017.11.28 14:14:22 5: DbLog logdb -> Primary Key used in fhem.history: none
2017.11.28 14:14:22 5: DbLog logdb -> Primary Key used in fhem.current: none
2017.11.28 14:14:22 5: DbLog logdb -> processing event Timestamp: 2017-11-28 14:13:57, Device: dblog_DbRep, Type: DBREP, Event: state: connected, Reading: state, Value: connected, Unit:
2017.11.28 14:14:22 5: DbLog logdb -> processing event Timestamp: 2017-11-28 14:13:59, Device: GZ_Strom_PC, Type: ZWAVE, Event: power: 146.0 W, Reading: power, Value: 146.0, Unit: W
2017.11.28 14:14:22 5: DbLog logdb -> processing event Timestamp: 2017-11-28 14:14:00, Device: GZ_Strom_PC, Type: ZWAVE, Event: power: 148.4 W, Reading: power, Value: 148.4, Unit: W
2017.11.28 14:14:22 5: DbLog logdb -> processing event Timestamp: 2017-11-28 14:14:01, Device: GZ_Strom_PC, Type: ZWAVE, Event: power: 146.7 W, Reading: power, Value: 146.7, Unit: W

... gekürzt

2017.11.28 14:14:22 5: DbLog logdb -> processing event Timestamp: 2017-11-28 14:13:57, Device: denon, Type: DENON_AVR, Event: stateAV: off, Reading: stateAV, Value: off, Unit:
2017.11.28 14:14:22 5: DbLog logdb -> processing event Timestamp: 2017-11-28 14:13:57, Device: Strom_Gesamt, Type: DUMMY, Event: power: 64.7, Reading: power, Value: 64.7, Unit:
2017.11.28 14:14:22 5: DbLog logdb -> processing event Timestamp: 2017-11-28 14:13:57, Device: Strom_Gesamt, Type: DUMMY, Event: energy: 720.58, Reading: energy, Value: 720.58, Unit:
2017.11.28 14:14:22 5: DbLog logdb -> processing event Timestamp: 2017-11-28 14:13:57, Device: Strom_Addi, Type: AT, Event: state: Next: 14:14:02, Reading: state, Value: Next, Unit: 14:14:02
2017.11.28 14:14:22 5: DbLog logdb -> 50 of 50 events inserted into table history
2017.11.28 14:14:22 5: DbLog logdb -> Failed to update in current, try to insert - TS: 2017-11-28 14:14:03, Device: d_ccu, Reading: state, Status = 0
2017.11.28 14:14:22 5: DbLog logdb -> Failed to update in current, try to insert - TS: 2017-11-28 14:14:04, Device: d_ccu_rpc, Reading: state, Status = 0
2017.11.28 14:14:22 5: DbLog logdb -> Failed to update in current, try to insert - TS: 2017-11-28 14:14:12, Device: d_ccu, Reading: state, Status = 0
2017.11.28 14:14:22 5: DbLog logdb -> 3 of 3 events inserted into table current
2017.11.28 14:14:22 5: DbLog logdb -> DbLog_PushAsync finished
2017.11.28 14:14:22 5: DbLog logdb -> Start DbLog_PushAsyncDone
Zigbee  Temp+Luftdruck+Humi Bewegungsmeldern Tür Kontakte, Klingel, TV, Denon, Schaltbare Steckdosen mit leistungsmessung, und weiteres

Homeassistant mit Nodered

DS_Starter

#6
Ja, das sieht doch alles sehr gut und auch fehlerfrei aus.

Zitatdas einzige was er macht  ist die fhem.log bei mir über nacht knapp 8gb groß werden lassen :D
verbose 4/5 produziert schon mächtig Daten. Schalte das nur kurz für die Analyse an.

Jetzt habe ich anhand deiner Daten auch das gesehen worum es mir ging:

Zitat
2017.11.28 14:14:22 5: DbLog logdb -> ################################################################
2017.11.28 14:14:22 5: DbLog logdb -> ###      New database processing cycle - asynchronous        ###
2017.11.28 14:14:22 5: DbLog logdb -> ################################################################
2017.11.28 14:14:22 5: DbLog logdb -> MemCache contains 50 entries to process
Hier siehst du dass 50 Einträge für den Insert in die DB (besser Tabelle history) anstehen. Auch in die Tabelle current sofern das mit dem Attribur DbLogType eingeschaltet wurde.

Und weiter unten siehst du dann ebenfalls:
Zitat
2017.11.28 14:14:22 5: DbLog logdb -> processing event Timestamp: 2017-11-28 14:13:57, Device: Strom_Addi, Type: AT, Event: state: Next: 14:14:02, Reading: state, Value: Next, Unit: 14:14:02
2017.11.28 14:14:22 5: DbLog logdb -> 50 of 50 events inserted into table history
Es wurden die 50 Einträge in die Tabelle history eingefügt.

Diese Einträge:
Zitat
2017.11.28 14:14:22 5: DbLog logdb -> Failed to update in current, try to insert - TS: 2017-11-28 14:14:03, Device: d_ccu, Reading: state, Status = 0
2017.11.28 14:14:22 5: DbLog logdb -> Failed to update in current, try to insert - TS: 2017-11-28 14:14:04, Device: d_ccu_rpc, Reading: state, Status = 0
2017.11.28 14:14:22 5: DbLog logdb -> Failed to update in current, try to insert - TS: 2017-11-28 14:14:12, Device: d_ccu, Reading: state, Status = 0
2017.11.28 14:14:22 5: DbLog logdb -> 3 of 3 events inserted into table current
sind auch keine Fehler, sondern sagen nur aus dass die Datensätze in current zunächst upgedatet werden sollten, aber da es diese nicht gab wurden sie hinzugefügt.

Tja, läuft alles, kann man nichts machen.  :)

Hast du das Attribut excludeDevs = TYPE=DbLog gesetzt ?
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

wuast94

#7
das attribut habe ich gesetzt ja :)
attr logdb excludeDevs TYPE=DbLog

das problem ist das er diese eben nicht in die datenbank schreibt .. ich sehe es auch daran das meine ganzen graphen leer sind .. sie zeigen wenn ich zurück gehe noch dinge an aber seit diesem fehler sind keine daten mehr geschrieben worden

Sprich das LESEN aus der Db funktioniert noch - das schreiben des Caches jedoch nicht mehr nach dem ich ein MySQL dump mache

Die 50 kommen ja vom attribut cacheLimit damit nach 50 gesammelten einträgen in die db geschrieben wird und genau das probiert er ja auch .. abert schafft es leider nicht

Zigbee  Temp+Luftdruck+Humi Bewegungsmeldern Tür Kontakte, Klingel, TV, Denon, Schaltbare Steckdosen mit leistungsmessung, und weiteres

Homeassistant mit Nodered

DS_Starter

Ja moment ... das Attribut

attr logdb excludeDevs TYPE=DbLog

bewirkt lediglich dass die EIGENEN Events des DbLog-Devices, sofern es welche gibt, nicht in der DB gespeichert werden. Das will man gewöhnlich auch nicht.
Alle anderen Events gelangen gemäß DEF weiterhin in den Cache und dann in die DB.

Ich mache zum Beispiel täglich von 4 DB's Dumps mit DbRep und das läuft,läuft,läuft ....  :D

Mit welchem Befehl dumpst du die DB genau, es gibt ja clientside und serverside ?
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

DS_Starter

Einen Tipp hätte ich noch.
Setze im DbLog doch mal  "set <name> reopen x" bevor du mit DbRep den Dump anfertigst."x" wären dann die Sekundne die der Dump braucht bis er fertig ist, also z.B. 1800 für eine halbe Stunde.
Während dieser Zeit baut sich der cache auf und wird weggeschrieben wenn die reopen-Zeit abgelaufen ist.

Du kannst dir mit listcache den cache während der Zeit immer mal anschauen.
Berichte mal wie das dann bei dir ausschaut.
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

wuast94

ich mache das backup clientside.

und das mit dem reopen wird auch nix .. die verbindung wird ja korrekt aufgebaut :) (Graphen laden noch alle wenn ich raus zoome oder zurück gehe in den tagen)

Das Problem liegt da wo er anfängt den aufgebaute cache wieder in die db zu schreiben .. da kommt der fehler.
Zigbee  Temp+Luftdruck+Humi Bewegungsmeldern Tür Kontakte, Klingel, TV, Denon, Schaltbare Steckdosen mit leistungsmessung, und weiteres

Homeassistant mit Nodered

DS_Starter

#11
Hmm, da kann ich dir eigentlich nur anbieten dass ich das bei mir mal versuche nachzustellen.
Wie schon gesagt, ich mache täglich beide Typen der Dumps mit mehreren Datenbanken und habe noch nie etwas negatives, auch nicht diesen beschriebenen Fehler, bemerkt.

Mach mir bitte noch ein List des beteiligten DbRep-Devices, vom DbLog hast du ja eingangs schon geschrieben.

Wie lange läuft denn der Dump ?

Grüße
Heiko
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

wuast94

hier das list:
Internals:
   DATABASE   fhem
   DEF        logdb
   LASTCMD    dumpMySQL
   NAME       dblog_DbRep
   NOTIFYDEV  global,dblog_DbRep
   NR         82
   NTFY_ORDER 50-dblog_DbRep
   ROLE       Client
   STATE      Warning - Database backup finished but command after dump not successful
   TYPE       DbRep
   UTF8       0
   VERSION    6.0.0
   HELPER:
     DBLOGDEVICE logdb
   Helper:
     DBLOG:
       state:
         logdb:
           TIME       1512010834.67878
           VALUE      Warning - Database backup finished but command after dump not successful
   READINGS:
     2017-11-30 04:00:34   DumpFileCreated ./log/fhem_2017_11_30_04_00.sql
     2017-11-30 04:00:34   DumpFileCreatedSize 125106828
     2017-11-30 04:00:34   DumpFilesDeleted fhem_2017_11_29_04_00.sql
     2017-11-30 04:00:34   DumpRowsCurrrent 50
     2017-11-30 04:00:34   DumpRowsHistory 690950
     2017-11-30 04:00:34   errortext       Please define WEB_Pushover first
     2017-11-30 04:00:34   state           Warning - Database backup finished but command after dump not successful
   dbloghash:
     COLUMNS    field length used for Device: 64, Type: 64, Event: 512, Reading: 64, Value: 128, Unit: 32
     CONFIGURATION ./contrib/dblog/db.conf
     DEF        ./contrib/dblog/db.conf .*:(cpu_freq|cpu_temp|eth0|eth0_diff|ram|4.ACTUAL_TEMPERATURE|4.BATTERY_STATE|4.SET_TEMPERATURE|4.VALVE_STATE|temperature|pressure|humidity|energy|power|DumpRowsCurrrent|DumpRowsHistory|state).*
     MODE       asynchronous
     MODEL      MYSQL
     NAME       logdb
     NR         30
     NTFY_ORDER 50-logdb
     PID        8
     REGEXP     .*:(cpu_freq|cpu_temp|eth0|eth0_diff|ram|4.ACTUAL_TEMPERATURE|4.BATTERY_STATE|4.SET_TEMPERATURE|4.VALVE_STATE|temperature|pressure|humidity|energy|power|DumpRowsCurrrent|DumpRowsHistory|state).*
     STATE      Commit already running - resync at NextSync
     TYPE       DbLog
     UTF8       0
     VERSION    2.22.14
     dbconn     mysql:database=fhem;host=mysql;port=3306
     dbuser     fhemuser
     HELPER:
       COLSET     1
       DEVICECOL  64
       EVENTCOL   512
       OLDSTATE   Commit already running - resync at NextSync
       READINGCOL 64
       TYPECOL    64
       UNITCOL    32
       VALUECOL   128
       RUNNING_PID:
         abortFn    DbLog_PushAsyncAborted
         arg       


wenn du magst kann man sich da auch privat mal zusammen setzten und mit teamviewer oder ähnlichen das bei mir direkt angucken
Zigbee  Temp+Luftdruck+Humi Bewegungsmeldern Tür Kontakte, Klingel, TV, Denon, Schaltbare Steckdosen mit leistungsmessung, und weiteres

Homeassistant mit Nodered

DS_Starter

Jetzt habe ich den Dump mal ausgeführt und genauer hingeschaut wie der Cache sich verhält.
Bei mir ist es so dass während des Dumps die Datenbank normal weitergeschrieben wird !

D.h. der Cache baut sich nur bis zur Zeit bzw. Volumengrenze auf und wird dann weggeschrieben.
Bei dir ist das nicht so, ich sehe das an dem DbLog State:

ZitatSTATE      Commit already running - resync at NextSync

Diese Meldung kommt immer dann wenn ein vorhergehender Schreibprozess noch nicht abgeschloosen ist wenn ein neuer beginnen soll.
D.h. bei dir wartet ein Schreibprozess bis der Dump fertig ist. Das ist ungewöhnlich, denn ein Leseprozess (Dump) sollte kein Tabellenlock verursachen nach meinem Kenntnisstand.

Die Meldung an sich ist auch nicht schlimm, die Daten bleiben im Cache und werden gewöhnlich weggeschrieben wenn die DB/Tabelle wieder offen ist. So funktioniert es bei mir tadellos.

Ich habe jetzt die Vermutung dass deine DB nicht mit einem globalen Autocommit läuft. Das ist ein Serverparameter der soviel ich weiß per default auf ON steht. Kann aber sein dass es hier versionsabhängige Unterschiede gibt.

Du siehst es mit DbRep:
get <name> dbvars

Dann den Datensatz suchen:

VAR_autocommit

Schreib mal was da angedruckt wird.

Ungeachtet dessen habe ich dir mal eine DbLog-Version angehängt, die ein Autocommit für die Session erzwingt.
Probiere es bitte mal damit aus.

Ansonsten würde mich interessieren wie sich ein serverSide Dump verhält.

Zitatwenn du magst kann man sich da auch privat mal zusammen setzten und mit teamviewer oder ähnlichen das bei mir direkt angucken
Auch das wäre möglich, schauen wir mal ...

Grüße
Heiko
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

wuast94

soo .. habe erstmal nachgeschaut wegen dem VAR_autocommit was auf ON steht

dann habe ich meine 93_DbLog.pm gegen deine getauscht und es passiert immer noch genau das selbe .. er schreibt die Daten sauber weg bis zu dem Moment wo ich den dumb mache und ab da ist ende im Gelände.

warum schaffe eig immer ich die Leute auf trab zu halten mit Fehlern die sonst niemand triggert ? :P :D aber danke das du dir so viel zeit nimmst :)
Zigbee  Temp+Luftdruck+Humi Bewegungsmeldern Tür Kontakte, Klingel, TV, Denon, Schaltbare Steckdosen mit leistungsmessung, und weiteres

Homeassistant mit Nodered