ständige Datenbankabstrürze "Die Datenbank ist bereits geschlossen"

[saho1]

Hallo,

leider plagen mich seit mehreren Wochen immer wiederkehrende Abstürze der Datenbank des Historian.

Genutzt wird aktuell die Version 2.0.0 beta 4 wohingegen sich das gleiche Fehlerbild unter der Version 1.2.0 gezeigt hat.

Als Zentrale wird RaspberryMatic Version 3.37.8.20181026 (aber auch hier gleiches Fehlerbild unter den Vorgängerversionen des RM) verwendet. Historian läuft auf einem weiteren Raspberry OS wheezy 7 mit aktuellen Updates. Hardware schließe ich aus, da ich SD-Karte wie auch Raspberry getauscht habe.

Wie zeigt sich der Fehler: Nach einer unbestimmten Laufzeit (wenige Stunden bis max 3 Tage) ist die Datenbank nicht mehr erreichbar da sie geschlossen sei. Nach einem Neustart des Historian läuft alles wieder normal bis zum nächsten Crash.

Hier ein Auszug aus dem Fehler log welchen mit FINE angelegt wurde:

Code: Alles auswählen

2018-11-04 14:40:48|FINE   |Call of method 'event' received with parameters [BidCos-RF, IEQ0168XXX:1, WORKING, false]
2018-11-04 14:40:48|FINE   |Sending method result: 
2018-11-04 14:40:48|FINE   |Call of method 'event' received with parameters [BidCos-RF, JEQ0225XXX:1, TEMPERATURE, 20.19999998807907]
2018-11-04 14:40:48|FINE   |Preprocessor: Value change is below delta, event discarded (event: BidCos-RF.JEQ0225XXX:1.TEMPERATURE, Sun Nov 04 14:40:48 CET 2018, 20.19999998807907, 2)
2018-11-04 14:40:48|FINE   |Sending method result: 
2018-11-04 14:40:48|FINE   |Call of method 'event' received with parameters [BidCos-RF, JEQ0225XXX:1, HUMIDITY, 60]
2018-11-04 14:40:48|FINE   |Preprocessor: Value change is below delta, event discarded (event: BidCos-RF.JEQ0225XXX:1.HUMIDITY, Sun Nov 04 14:40:48 CET 2018, 60, 2)
2018-11-04 14:40:48|FINE   |Sending method result: 
2018-11-04 14:40:48|FINE   |Sending method result: [, , ]
2018-11-04 14:40:54|FINE   |Call of method 'system.multicall' received with parameters [[[methodName:event, params:[BidCos-RF, HEQ0130661:2, ADJUSTING_COMMAND, 0]]]]
2018-11-04 14:40:54|FINE   |Call of method 'event' received with parameters [BidCos-RF, HEQ0130XXX:2, ADJUSTING_COMMAND, 0]
2018-11-04 14:40:54|FINE   |Sending method result: 
2018-11-04 14:40:54|FINE   |Sending method result: []
2018-11-04 14:40:54|WARNING|Failed to execute: SELECT * FROM DATA_POINTS WHERE
			INTERFACE=? AND ADDRESS=? AND IDENTIFIER=? because: Die Datenbank ist bereits geschlossen
The database has been closed [90098-197]
2018-11-04 14:40:54|FINE   |Call of method 'system.multicall' received with parameters [[[methodName:event, params:[BidCos-RF, HEQ0130661:2, ADJUSTING_DATA, 0]]]]
2018-11-04 14:40:54|FINE   |Call of method 'event' received with parameters [BidCos-RF, HEQ0130XXX:2, ADJUSTING_DATA, 0]
2018-11-04 14:40:54|FINE   |Sending method result: 
2018-11-04 14:40:54|FINE   |Sending method result: []
2018-11-04 14:40:54|WARNING|Failed to execute: SELECT * FROM DATA_POINTS WHERE
			INTERFACE=? AND ADDRESS=? AND IDENTIFIER=? because: Die Datenbank ist bereits geschlossen
The database has been closed [90098-197]
2018-11-04 14:40:54|SEVERE |Error updating data point storage
2018-11-04 14:40:54|SEVERE |Exception: Die Datenbank ist bereits geschlossen
The database has been closed [90098-197]
2018-11-04 14:40:54|SEVERE |Detail: org.h2.jdbc.JdbcSQLException: Die Datenbank ist bereits geschlossen
The database has been closed [90098-197]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:357)
	at org.h2.message.DbException.get(DbException.java:179)
	at org.h2.message.DbException.get(DbException.java:155)
	at org.h2.message.DbException.get(DbException.java:144)
	at org.h2.engine.Database.checkPowerOff(Database.java:536)
	at org.h2.command.Command.executeQuery(Command.java:228)
	at org.h2.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:114)
	at mdz.ccuhistorian.Database.getDataPoint(Database.groovy:256)
	at mdz.ccuhistorian.ExtendedStorage.getDataPoint(ExtendedStorage.groovy:65)
	at mdz.ccuhistorian.eventprocessing.DataPointStorageUpdater.consume(DataPointStorageUpdater.groovy:43)
	at mdz.ccuhistorian.eventprocessing.DataPointStorageUpdater.consume(DataPointStorageUpdater.groovy)
	at mdz.eventprocessing.BasicProducer.lambda$0(BasicProducer.java:36)
	at mdz.eventprocessing.BasicProducer$$Lambda$2/16387954.run(Unknown Source)
	at mdz.Exceptions.catchToLog(Exceptions.java:74)
	at mdz.eventprocessing.BasicProducer.safeProduce(BasicProducer.java:36)
	at mdz.eventprocessing.BasicProducer.produce(BasicProducer.java:42)
	at mdz.eventprocessing.Buffer.purge(Buffer.java:74)
	at mdz.eventprocessing.Buffer.consume(Buffer.java:65)
	at mdz.eventprocessing.BasicProducer.lambda$0(BasicProducer.java:36)
	at mdz.eventprocessing.BasicProducer$$Lambda$2/16387954.run(Unknown Source)
	at mdz.Exceptions.catchToLog(Exceptions.java:74)
	at mdz.eventprocessing.BasicProducer.safeProduce(BasicProducer.java:36)
	at mdz.eventprocessing.BasicProducer.produce(BasicProducer.java:42)
	at mdz.hc.itf.Manager.sendEvents(Manager.groovy:139)

Der vollständigkeitshalber hier noch die Konfiguration, wobei ich hier keine Fehler vermute:

Code: Alles auswählen

// CCU-Historian Konfiguration
// 
// Hinweise:
// Kommentarzeilen starten mit zwei Schr‰gstrichen (//). Alle Zeichen nach den Schr‰gstrichen
// werden ignoriert. Zeichenketten als Optionswert m¸ssen von einfachen Anf¸hrungszeichen (')
// umschlossen sein. Weitere Informationen sind auch im Abschnitt 3 im Handbuch zu finden.
//
// Liste der zur Verf¸gung stehen Konfigurationsoptionen mit ihren jeweiligen Standardwerten:
//
logSystem.consoleLevel=Level.INFO
logSystem.fileLevel=Level.FINE
//logSystem.fileLevel=Level.WARNING
logSystem.fileName='/opt/ccu-historian/ccu-historian-%g.log'
logSystem.fileLimit=10000000
logSystem.fileCount=10
logSystem.binRpcLevel=Level.FINE
database.dir='/opt/ccu-historian/data'
database.name='history'
database.user='sa'
database.password='ccu-historian'
database.webEnable=true
database.webPort=8082
database.webAllowOthers=true
database.tcpEnable=true
database.tcpPort=9092
database.tcpAllowOthers=true
database.pgEnable=true
database.pgPort=5435
database.pgAllowOthers=true
webServer.port=8080
webServer.dir='/opt/ccu-historian/webapp'
webServer.logLevel=Level.WARNING
webServer.historianAddress='192.168.181.252'
historian.metaCycle=3600000 // 1 Stunde
devices.historianAddress='192.168.181.252'

// Typ der Zentrale: CCU1 oder CCU2
devices.device1.type=CCU2
// IP-Adresse der Zentrale
devices.device1.address='192.168.181.240'

// Falls CUxD verwendet wird, die Kommentarzeichen (//) vor folgender Zeile entfernen:
devices.device1.plugin1.type=CUXD

// Watchdoc
//devices.device1.watchdogProgram='WatchHistorian'
devices.device1.watchdogProgram='HistorianWatchdoc'
devices.device1.watchdogCycle=300000

// Zum Freischalten der Web-Links zu den Beispiel-Web-Seiten, die Kommentarzeichen (//) vor folgenden
// zwei Zeilen entfernen:
webServer.menuLinks.link1.text='Beispiel 1 - Vorjahresvergleich'
webServer.menuLinks.link1.address='/custom/example1.html'

// Desigen PNG 
webServer.trendDesigns.png=new TrendDesign( chart: {
             // Farbe der DiagrammflaÃàche
             backgroundPaint=ChartColor.GRAY
             // Diagramm ohne Legende
             removeLegend()
    }, plot: {
             // Farbe der KurvenflaÃàche
             backgroundPaint=ChartColor.BLACK
      }
)

Hat der SQL-Dienst ein eigenes Log wo man evtl. der Ursache auf die Spur kommen kann?

Die Datenbank zu verlieren wäre nur meine letzte Option, da ich gerne auf die Daten der letzten Jahre zurückgreifen möchte. Zur Ergänzung, die DB haut eine Größe von ca 1,3GB.

Für Tipps oder besser einen Lösungsansatz wäre ich sehr dankbar!

Vielen Dank und schönen Sonntag

Saho

[saho1]

Noch ein Nachtrag zu meinen Beobachtungen.

Nach dem die DB sich verabschiedet hat, ist das Verhalten des Historian unterschiedlich. Meistens läuft Historian weiter (Website), zeigt jedoch keinerlei Datenpunkte mehr an. Bei dem Auszug des o.g. Log war es anders, da hat der Historian ebenfalls den Dienst eingestellt.

Die Datenbank wurde von mir gemäß den Vorgaben vor dem Update auf die neue DB-Version überführt und hat anschließend ohne Störungen funktioniert.

Zur Fehlerbehebung habe ich bereits ein recalc und compact durchgeführt, ohne Änderung des Fehlerbild.

Gruß

Saho

[Mathias]

Ich müsste mal ein umfangreicheres Log vor Dir bekommen:

CCU-Historian stoppen und Konfiguration abändern:

Code: Alles auswählen

logSystem.fileLevel=Level.FINER

Alte Log-Dateien löschen und wieder starten.

Dann bitte per PN oder E-Mail das komplette Log vom Start bis zum Auftreten des Fehlers zuschicken.

Gruß
Mathias

[saho1]

Danke Mathias,

es ist natürlich wie immer. Jetzt läuft die DB schon seit vier Tagen durch.

Ich werde heute mal das LOG löschen, auf FINEST stellen und neu starten. Sobald er abstürzt sende ich dir die LOGs per Email.

Vielen Dank und Gruß

Saho

[saho1]

@Mathias

Ich habe dir ein Dropboxlink zu den LOG-Files gesendet.

Vielen Dank im Voraus!

Saho

[Mathias]

Das Fehlerbild ist sehr diffus.Ich vermute, dass sich ein Defekt in die Datenbank eingeschlichen hat.

Bitte mal einen Datenbank-Export mit der Kommandozeilenoption -createscript erstellen (s.a. Handbuch). Danach die Datenbankdatei löschen (history.mv.db) und mit der Kommandozeilenoption -runscript wieder herstellen.

Falls die Vorgehensweise keinen Erfolg bringt, dann das Reparaturwerkzeug einmal anwenden (s. Forum "Wiederherstellung einer defekten Datenbank").

Gruß
Mathias

[saho1]

Vielen Dank Mathias,

ich werde das probieren und Rückmeldung geben.

Schönen Sonntag

Saho

[saho1]

Hallo Mathias,

ich habe die mittels createscript ein Dump der DB gemacht und nach löschen der history.mv.db diesen wieder per runscript angelegt. bisher läuft es unauffällig.

Ich hatte zuvor eine Sicherung des Data-Verzeichnis gemacht und hier ist mir aufgefallen, dass die ursprüngliche Datei history.mv.db eine Größe von 1,9 GB hat und die mittels Script wiederhergestellte, welche ja gleiche Informationen haben sollte, 879 MB!
Dies ganze obwohl ich erst vor ein paar Tagen ein recalc und compact durchgeführt habe. Mehr als doppelt so groß ist hier mE etwas merkwürdig. Ich kann gerne beide DB zur Verfügung stellen oder bei Hinweis etwas tiefer analysieren um das Thema zu vertiefen.

Gruß

Saho

[Mathias]

Beobachte bitte erst einmal, ob der Fehler nicht bereits durch die Reparatur behoben ist.

Gruß
Mathias

[saho1]

Hier ein Feedback zu dem Thema. Bitte entschuldigt das ich so lange nicht geantwortet habe, aber ich mußte ja erstmal testen ob die DB auch einige Tage durchhält.

Aktuell läuft die Datenbank seit 6 Tagen durch. Die vorgeschlagenen Reparaturversuche haben leider keine Änderung gebracht. Also bin ich weiter auf die Suche gegangen in dem Funktion für Funktion ausgeschaltet habe.

Ich lasse mir per Skript alle 15 Minuten PNG-Dateien auf den auf den Webserver legen um diese auf meinem Wandtablett darzustellen. Diese werden im Verzeichnis /opt/ccu-historian/webapp/cache/ abgelegt.

Hier ein Auszug aus dem Skript welches auf dem rPi des Historian alle 15 Minuten aufgerufen wird:

Code: Alles auswählen

...
performcache verbrauch_heizung_last_week "http://192.168.181.252:8080/query/trend.gy?i=999&d=1W&t=png"
#performcache temp_aussen_last_week "http://localhost:8080/query/trend.gy?i=271&d=1W&t=png" 
performcache temp_aussen_last_week "http://192.168.181.252:8080/query/trend.gy?i=271&d=1W&t=png" 
performcache verbrauch_strom_last_week "http://192.168.181.252:8080/query/trend.gy?i=1032&d=1W&t=png"
performcache strom_leistung_day "http://192.168.181.252:8080/query/trend.gy?i=1025&d=1D&t=png
..."

Der auskommentierte Aufruf ohne feste IP war hier der Übeltäter. Warum erklärt sich mir nicht. Besonders weil dieses Skript bereits seit vielen Monaten seinen Dienst verrichtet hat. Auch hat das Skript ja für mehrer Stunden ohne Probleme funktioniert bis, wie oben beschrieben, die DB nicht mehr erreichbar war. Jedoch seit ich statt "localhost" die IP eingetragen haben läuft die DB durch und ich kann keine Auffälligkeiten feststellen.

In diesem Sinne wünsche ich euch ein schönes Wochenende.

Saho