Fehlermeldungen des Archive Handlers während der Startphase

bumaas · 25. Januar 2016 um 15:22

Hallo zusammen,

bei mir startet der IPS Dienst nur sehr sehr zäh. Er benötigt über zwei Minuten bis zum „IPS BETRIEBSBEREIT“.

Auffällig sind die unzähligen (>30.000) Einträge des Archive Handlers im Log-File:

15:02:23 | 00000 | MESSAGE | Kernel               | Creating...
...
15:02:23 | 00000 | MESSAGE | LicensePool          | LiveUpdate: 25.01.2016, 5b10c322063a
...
15:02:29 | 21496 | MESSAGE | Archive Control      | Lese Variablen Aggregationsdaten ... #59950
15:02:29 | 21496 | MESSAGE | Archive Control      | Skipped 1 invalid lines in aggregation year for VariableID #59950
15:02:29 | 21496 | MESSAGE | Archive Control      | Skipped 1 invalid lines in aggregation month for VariableID #59950
15:02:29 | 21496 | MESSAGE | Archive Control      | Skipped 1 invalid lines in aggregation week for VariableID #59950
15:02:29 | 21496 | MESSAGE | Archive Control      | Skipped 1 invalid lines in aggregation day for VariableID #59950
15:02:30 | 21496 | MESSAGE | Archive Control      | Skipped 1 invalid lines in aggregation hour for VariableID #59950
15:02:30 | 21496 | MESSAGE | Archive Control      | Update variable aggregation data... #59950
15:02:30 | 21496 | MESSAGE | Archive Control      | Lese Variablen Aggregationsdaten ... #59593
15:02:30 | 21496 | MESSAGE | Archive Control      | Skipped 6 invalid lines in aggregation year for VariableID #59593
15:02:30 | 21496 | MESSAGE | Archive Control      | Skipped 62 invalid lines in aggregation month for VariableID #59593
15:02:30 | 21496 | MESSAGE | Archive Control      | Skipped 273 invalid lines in aggregation week for VariableID #59593
15:02:30 | 21496 | MESSAGE | Archive Control      | Skipped 1910 invalid lines in aggregation day for VariableID #59593
15:02:31 | 21496 | MESSAGE | Archive Control      | Skipped 45831 invalid lines in aggregation hour for VariableID #59593
15:02:31 | 21496 | MESSAGE | Archive Control      | Update variable aggregation data... #59593
....
15:02:47 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #53107. Expected: 1386882000, Found: 1386885600
15:02:47 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #53107. Expected: 1386932400, Found: 1386936000
15:02:47 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #53107. Expected: 1386975600, Found: 1386979200
15:02:47 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #53107. Expected: 1387807200, Found: 1387810800
15:02:47 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #53107. Expected: 1388412000, Found: 1388415600
15:02:47 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #53107. Expected: 1391608800, Found: 1391612400
15:02:47 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #53107. Expected: 1392015600, Found: 1392019200
...
15:04:37 | 21496 | MESSAGE | Archive Control      | Update variable aggregation data... #10013
15:04:37 | 21496 | MESSAGE | Archive Control      | Lese Variablen Aggregationsdaten ... #25566
15:04:37 | 21496 | MESSAGE | Archive Control      | Update variable aggregation data... #25566
15:04:37 | 21496 | WARNING | Archive Control      | Skipping aggregation update on startup. Downtime gap is too big. Please reaggregate manually
15:04:37 | 21496 | MESSAGE | Archive Control      | Lese Variablen Aggregationsdaten ... #23873
15:04:37 | 21496 | MESSAGE | Archive Control      | Update variable aggregation data... #23873
15:04:37 | 21496 | WARNING | Archive Control      | Skipping aggregation update on startup. Downtime gap is too big. Please reaggregate manually
...
15:04:38 | 00000 | SUCCESS | Kernel               | *** IPS BETRIEBSBEREIT

Kann mir bitte jemand einen Tipp geben, wo ich bei der Fehlersuche beginnen sollte? Ist eventuell die Konvertierung von 3.4 schief gelaufen? Mir scheint es so, als ob mit den Zeitstempeln der Rohdaten etwas nicht stimmt …

Viele Grüße

Burkhard

paresy · 25. Januar 2016 um 15:42

Die „Invalid data for aggregation“ Meldungen, die wahrscheinlich so lange verzögern, gehören noch zum letzten offenen Fehler… Da musst du von ein Update von uns warten

Reaggregierst du nach jedem Starten von IP-Symcon!?

paresy

bumaas · 25. Januar 2016 um 16:01

Kein Problem. Dann lass ich die Baustelle zunächst liegen:)

Momentan noch nicht. Sollte ich im Startscript für alle Variablen von AC_GetAggregationVariables() ein AC_ReAggregateVariable() durchführen?

Gruß

Burkhard

paresy · 25. Januar 2016 um 16:04

Lieber dieses Skript: Datenbankwiederherstellung IP-Symcon :: Automatisierungssoftware

paresy

bumaas · 2. März 2016 um 11:10

Die meisten Fehlermeldungen des Archive Handlers sind inzwischen verschwunden.

Es gibt bei mir jedoch noch immer Einträge (zur Zeit 83) der folgenden Art:

10:41:55 | 21496 | MESSAGE | Archive Control      | Erstelle...
10:41:55 | 21496 | MESSAGE | Archive Control      | Generating DST timestamps...
10:41:57 | 21496 | MESSAGE | Archive Control      | Lese Variablen Aggregationsdaten ... #59638
10:41:57 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #59638. Expected: 1456858800, Found: 1456858259
...
10:41:57 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #57937. Expected: 1456858800, Found: 1456858466
...
10:41:57 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #57075. Expected: 1456858800, Found: 1456858256

Gruß

Burkhard

bumaas · 16. August 2016 um 12:08

Auch mit der aktuellen Testversion treten sporadisch weiterhin Fehlermeldungen dieser Art auf:

11:34:01 | 21496 | MESSAGE | Archive Control      | Lese Variablen Aggregationsdaten ... #35410
11:34:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation month for VariableID #35410. Expected: 1464732000, Found: 1467324000
11:34:01 | 21496 | MESSAGE | Archive Control      | Skipped 1 invalid lines in aggregation month for VariableID #35410
11:34:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation week for VariableID #35410. Expected: 1462140000, Found: 1462744800
11:34:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation week for VariableID #35410. Expected: 1463349600, Found: 1467583200
11:34:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation week for VariableID #35410. Expected: 1468188000, Found: 1467583200
11:34:01 | 21496 | MESSAGE | Archive Control      | Skipped 12 invalid lines in aggregation week for VariableID #35410
11:34:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #35410. Expected: 1460757600, Found: 1461016800
11:34:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #35410. Expected: 1461103200, Found: 1461967200
11:34:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #35410. Expected: 1462053600, Found: 1463004000
11:34:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #35410. Expected: 1463090400, Found: 1467842400
11:34:01 | 21496 | MESSAGE | Archive Control      | Skipped 113 invalid lines in aggregation day for VariableID #35410
11:34:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #35410. Expected: 1460649600, Found: 1460653200
11:34:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #35410. Expected: 1460682000, Found: 1460685600
11:34:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #35410. Expected: 1460710800, Found: 1460714400
11:34:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #35410. Expected: 1460721600, Found: 1460725200
11:34:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #35410. Expected: 1460757600, Found: 1460761200
11:34:01 | 21496 | MESSAGE | Archive Control      | Skipped 770 invalid lines in aggregation hour for VariableID #35410
11:34:01 | 21496 | MESSAGE | Archive Control      | Skipped 588 more lines with continuity issues in aggregation hour for VariableID #35410
11:34:01 | 21496 | MESSAGE | Archive Control      | Update variable aggregation data... #35410

Ich konnte bislang nicht herausfinden, wodurch sie ausgelöst werden.

Abhilfe schafft nur ein Reaggregieren der betroffenen Variable(n).

Gruß

Burkhard

bumaas · 27. August 2016 um 11:43

Gibt es hierfür eine Erklärung?

Die Variable 35410 macht noch immer Probleme und muss immer wieder neu aggregiert werden.

11:31:55 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation month for VariableID #35410. Expected: 1464732000, Found: 1467324000
11:31:55 | 21496 | MESSAGE | Archive Control      | Skipped 1 invalid lines in aggregation month for VariableID #35410
11:31:55 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation week for VariableID #35410. Expected: 1462140000, Found: 1462744800
11:31:55 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation week for VariableID #35410. Expected: 1463349600, Found: 1467583200
11:31:55 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation week for VariableID #35410. Expected: 1468188000, Found: 1467583200
11:31:55 | 21496 | MESSAGE | Archive Control      | Skipped 13 invalid lines in aggregation week for VariableID #35410
11:31:55 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #35410. Expected: 1460757600, Found: 1461016800
11:31:55 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #35410. Expected: 1461103200, Found: 1461967200
11:31:55 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #35410. Expected: 1462053600, Found: 1463004000
11:31:55 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #35410. Expected: 1463090400, Found: 1467842400
11:31:55 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #35410. Expected: 1471384800, Found: 1471471200
11:31:55 | 21496 | MESSAGE | Archive Control      | Skipped 120 invalid lines in aggregation day for VariableID #35410
11:31:55 | 21496 | MESSAGE | Archive Control      | Skipped 5 more lines with continuity issues in aggregation day for VariableID #35410
11:31:55 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #35410. Expected: 1460649600, Found: 1460653200
11:31:55 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #35410. Expected: 1460682000, Found: 1460685600
11:31:55 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #35410. Expected: 1460710800, Found: 1460714400
11:31:55 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #35410. Expected: 1460721600, Found: 1460725200
11:31:55 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #35410. Expected: 1460757600, Found: 1460761200
11:31:55 | 21496 | MESSAGE | Archive Control      | Skipped 897 invalid lines in aggregation hour for VariableID #35410
11:31:55 | 21496 | MESSAGE | Archive Control      | Skipped 690 more lines with continuity issues in aggregation hour for VariableID #35410

Gruß

Burkhard

paresy · 2. September 2016 um 09:15

Ich habe das auf unserem Test-System auch schon ab und zu beobachtet. Aber bisher habe ich keine Idee wann das passiert.

paresy

bumaas · 24. Mai 2017 um 10:03

Gibt es hier schon neue Erkenntnisse?

Auch im aktuellen Beta Stand habe ich noch immer sporadische Fehlermeldungen vom Archive Handler:


08:11:00 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation month for VariableID #35410. Expected: 1464732000 (2016-06-01T00:00:00+02:00), Found: 1467324000 (2016-07-01T00:00:00+02:00)
08:11:00 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation month for VariableID #35410. Expected: 1470002400 (2016-08-01T00:00:00+02:00), Found: 1472680800 (2016-09-01T00:00:00+02:00)
08:11:00 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation month for VariableID #35410. Expected: 1475272800 (2016-10-01T00:00:00+02:00), Found: 1477954800 (2016-11-01T00:00:00+01:00)
08:11:00 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation month for VariableID #35410. Expected: 1480546800 (2016-12-01T00:00:00+01:00), Found: 1483225200 (2017-01-01T00:00:00+01:00)
08:11:00 | 21496 | MESSAGE | Archive Control      | Skipped 7 invalid lines in aggregation month for VariableID #35410
08:11:00 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation week for VariableID #35410. Expected: 1462140000 (2016-05-02T00:00:00+02:00), Found: 1462744800 (2016-05-09T00:00:00+02:00)
08:11:00 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation week for VariableID #35410. Expected: 1463349600 (2016-05-16T00:00:00+02:00), Found: 1467583200 (2016-07-04T00:00:00+02:00)
08:11:00 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation week for VariableID #35410. Expected: 1468188000 (2016-07-11T00:00:00+02:00), Found: 1474236000 (2016-09-19T00:00:00+02:00)
08:11:00 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation week for VariableID #35410. Expected: 1474840800 (2016-09-26T00:00:00+02:00), Found: 1478473200 (2016-11-07T00:00:00+01:00)
08:11:00 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation week for VariableID #35410. Expected: 1479078000 (2016-11-14T00:00:00+01:00), Found: 1483916400 (2017-01-09T00:00:00+01:00)
08:11:00 | 21496 | MESSAGE | Archive Control      | Skipped 49 invalid lines in aggregation week for VariableID #35410
08:11:00 | 21496 | MESSAGE | Archive Control      | Skipped 6 more lines with continuity issues in aggregation week for VariableID #35410
08:11:00 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #35410. Expected: 1460757600 (2016-04-16T00:00:00+02:00), Found: 1461016800 (2016-04-19T00:00:00+02:00)
08:11:00 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #35410. Expected: 1461103200 (2016-04-20T00:00:00+02:00), Found: 1461967200 (2016-04-30T00:00:00+02:00)
08:11:00 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #35410. Expected: 1462053600 (2016-05-01T00:00:00+02:00), Found: 1463004000 (2016-05-12T00:00:00+02:00)
08:11:00 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #35410. Expected: 1463090400 (2016-05-13T00:00:00+02:00), Found: 1467842400 (2016-07-07T00:00:00+02:00)
08:11:00 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #35410. Expected: 1467928800 (2016-07-08T00:00:00+02:00), Found: 1474322400 (2016-09-20T00:00:00+02:00)
08:11:00 | 21496 | MESSAGE | Archive Control      | Skipped 388 invalid lines in aggregation day for VariableID #35410
08:11:00 | 21496 | MESSAGE | Archive Control      | Skipped 9 more lines with continuity issues in aggregation day for VariableID #35410
08:11:00 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #35410. Expected: 1460649600 (2016-04-14T18:00:00+02:00), Found: 1460653200 (2016-04-14T19:00:00+02:00)
08:11:00 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #35410. Expected: 1460682000 (2016-04-15T03:00:00+02:00), Found: 1460685600 (2016-04-15T04:00:00+02:00)
08:11:00 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #35410. Expected: 1460710800 (2016-04-15T11:00:00+02:00), Found: 1460714400 (2016-04-15T12:00:00+02:00)
08:11:00 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #35410. Expected: 1460721600 (2016-04-15T14:00:00+02:00), Found: 1460725200 (2016-04-15T15:00:00+02:00)
08:11:00 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation hour for VariableID #35410. Expected: 1460757600 (2016-04-16T00:00:00+02:00), Found: 1460761200 (2016-04-16T01:00:00+02:00)
08:11:00 | 21496 | MESSAGE | Archive Control      | Skipped 4464 invalid lines in aggregation hour for VariableID #35410
08:11:00 | 21496 | MESSAGE | Archive Control      | Skipped 3147 more lines with continuity issues in aggregation hour for VariableID #35410

Die formatierten Zeitstempel habe ich zur besseren Analyse hinzugefügt.

Man sieht, dass nur die Uhrzeiten zum jeweiligen Zeitwechsel betroffen sind. Ich hoffe, das hilft weiter.

Gruß

Burkhard

paresy · 24. Mai 2017 um 10:11

Leider noch nicht. Ich habe mal aber einen offizielle Bugreport dran gehängt, damit wir das Problem besser tracken können.

paresy

larson · 8. August 2017 um 15:27

HILFE: kann nach dem Update auf Version 4.3 nicht mehr auf Symcon zugreifen Folgendes steht seit dem Update im Logfile:

1007 · 8. August 2017 um 15:33

[QUOTE=larson;332733]HILFE: kann nach dem Update auf Version 4.3 nicht mehr auf Symcon zugreifen Folgendes steht seit dem Update im Logfile:

Warte mal ab bis alle Variablen „durch“ sind

Gesendet von iPad mit Tapatalk

Dr.Niels · 8. August 2017 um 15:34

Die Fehlermeldungen besagen, dass einige Zeitstempel falsch gesetzt sind. Das kann gut sein, da Symcon in vorherigen Versionen die Zeitstempel ein bisschen lockerer genommen hat. Das ist aber mit einer Reaggregation eigentlich wieder in Ordnung.

Allerdings sollte das nicht das Starten von IP-Symcon beeinflussen. Wie genau wirkt sich das denn bei dir aus? Auf was für einem System ist dein Symcon installiert? Und gibt es vielleicht noch weitere interessante Einträge in der Logfile?

bumaas · 16. Februar 2018 um 11:17

Ich erhalte wieder beim Starten von IP-Symcon 131 Fehlermeldungen der Art:

	Line 1983: 16.02.2018 10:48:00 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #44964. Expected: 1517785200, Found: 1517871600
	Line 1986: 16.02.2018 10:48:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #21744. Expected: 1517785200, Found: 1517871600
	Line 1989: 16.02.2018 10:48:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #44574. Expected: 1517785200, Found: 1517871600
	Line 1992: 16.02.2018 10:48:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #44454. Expected: 1517785200, Found: 1517871600
	Line 1995: 16.02.2018 10:48:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #17621. Expected: 1517785200, Found: 1517871600
	Line 1998: 16.02.2018 10:48:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #40189. Expected: 1517785200, Found: 1517871600
	Line 2001: 16.02.2018 10:48:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #44422. Expected: 1517785200, Found: 1517871600
	Line 2006: 16.02.2018 10:48:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #43746. Expected: 1517785200, Found: 1517871600
	Line 2011: 16.02.2018 10:48:01 | 21496 | MESSAGE | Archive Control      | Invalid data for aggregation day for VariableID #43495. Expected: 1517785200, Found: 1517871600

Es ist immer der gleiche Zeitstempel, der bemängelt wird.

echo 'Expected: ' . date(DATE_RFC822, 1517785200).PHP_EOL;
echo 'Found:    ' . date(DATE_RFC822, 1517871600);

ergibt:

Expected: Mon, 05 Feb 18 00:00:00 +0100
Found:    Tue, 06 Feb 18 00:00:00 +0100

Das Starten wird nicht beeinflusst, es ist scheinbar nur eine Unschönheit. Es ist ein Windows System. Weitere interessante Logfileeinträge habe ich in diesem Zusammenhang nicht gefunden.

Dr.Niels · 19. Februar 2018 um 13:12

Kannst du mir mal eine beliebige Datei mit täglicher Aggregation bereitstellen, die eine Meldung auslöst? Im Code sieht auf einen groben Blick hin alles richtig aus. Bleibt die Meldung bestehen, wenn du reaggregierst oder löst sich das danach auf? Wenn es bestehen bleibt, dann würden mich auch die Rohdaten interessieren.