Jahresrückblick 2025 – unser neuer Blogbeitrag ist online! ✨

[woupi]

Systemdata	Bitte Ausfüllen
Hardwaresystem:	NUC
Arbeitsspeicher:	16GB
Festplattenart:	SSD
Betriebssystem:	Proxmox 7 VM Ubuntu
Node-Version:	---
Nodejs-Version:	v14.21.2
NPM-Version:	6.14.17
Installationsart:	Skript
Funk Hardware	Bluetooth, WLan

Re: [gelöst] verschiedene Zeiten im Log
Re: WP Skript merkwürdige zeitliche Steuerung und log Ausgaben

Ich versuche es jetzt mal hier in dem Unterforum.

Ich habe ein Problem mit den Zeiten im log und offensichtlich auch beim ausführen von blocky skripten.
Das Problem wurde schonmal genau beschrieben (siehe ersten Link) und ich habe alles das, was ich gemacht habe und wie ich das entdeckt habe, in einem anderen Thema schonmal beschrieben (zweiter Link), da wusste ich aber noch nicht, was überhaupt für ein Problem besteht. Ich werde das dann jetzt auf gelöst stellen, damit keine zwei Themen vorhanden sind.

Nun bin ich ein ganzes Stück weiter und bin mir sicher, dass irgendwo unterschiedliche Zeiten sein müssen, nur finden kann ich diese nicht.

Hier erstmal von Proxmox selber:

bernhard@server:~$ timedatectl
               Local time: Sun 2023-04-16 14:57:44 CEST
           Universal time: Sun 2023-04-16 12:57:44 UTC
                 RTC time: Sun 2023-04-16 12:57:44
                Time zone: Europe/Berlin (CEST, +0200)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no

Hier von der VM ubuntu 20.04 und iobroker

xxxxx@iobroker:~$ timedatectl
               Local time: So 2023-04-16 14:55:41 CEST
           Universal time: So 2023-04-16 12:55:41 UTC
                 RTC time: So 2023-04-16 12:55:42
                Time zone: Europe/Berlin (CEST, +0200)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no

Für mich sind die beide gleich und Richtig.

Hier noch ein Teil eines log Files, in dem man die unterschiedlichen Uhrzeiten sieht (Versatz um genau 2 Stunden):

2023-04-16 12:59:58.309 - warn: modbus.0 (1174) Poll error count: 1 code: {"err":"timeout","timeout":5000}
2023-04-16 12:59:58.755 - info: modbus.2 (1204) Disconnected from slave 192.168.1.52
2023-04-16 12:59:59.308 - info: modbus.0 (1174) Disconnected from slave 192.168.1.48
2023-04-16 12:59:59.737 - info: mqtt.0 (1281) Client [HeishaMon] connection closed: timeout
2023-04-16 15:00:00.004 - debug: shuttercontrol.0 (10132) calculate astrodata ...
2023-04-16 15:00:00.004 - debug: shuttercontrol.0 (10132) Sun Azimut: 212.3°
2023-04-16 15:00:00.004 - debug: shuttercontrol.0 (10132) Sun Elevation: 45.1°
2023-04-16 13:00:00.030 - info: host.iobroker instance system.adapter.daswetter.0 started with pid 49996
2023-04-16 15:00:00.678 - info: daswetter.0 (49996) starting. Version 3.1.7 in /opt/iobroker/node_modules/iobroker.daswetter, node: v14.21.3, js-controller: 4.0.24
2023-04-16 15:00:03.040 - warn: telegram.0 (14071) polling_error: EFATAL, EFATAL: Error: read ETIMEDOUT
2023-04-16 13:00:04.085 - info: host.iobroker instance system.adapter.ical.0 started with pid 50011
2023-04-16 13:00:04.905 - info: mqtt.0 (1281) Client [HeishaMon] connected with secret 1681650004904_8946
2023-04-16 13:00:04.920 - info: mqtt.0 (1281) Client [HeishaMon] subscribes on "panasonic_heat_pump/opentherm/#" with regex /^panasonic_heat_pump\.opentherm(\..*)?/
2023-04-16 13:00:04.920 - info: mqtt.0 (1281) Client [HeishaMon] subscribes on "panasonic_heat_pump/opentherm/#" with regex /^mqtt\.0\.panasonic_heat_pump\.opentherm(\..*)?/
2023-04-16 13:00:04.924 - info: mqtt.0 (1281) Client [HeishaMon] subscribes on "panasonic_heat_pump/commands/#" with regex /^panasonic_heat_pump\.commands(\..*)?/
2023-04-16 13:00:04.925 - info: mqtt.0 (1281) Client [HeishaMon] subscribes on "panasonic_heat_pump/commands/#" with regex /^mqtt\.0\.panasonic_heat_pump\.commands(\..*)?/
2023-04-16 13:00:04.925 - info: mqtt.0 (1281) Client [HeishaMon] subscribes on "mqtt.0.panasonic_heat_pump.SendRawValue"
2023-04-16 13:00:05.121 - info: mqtt.0 (1281) Client [HeishaMon] publishOnSubscribe send all known states
2023-04-16 13:00:05.126 - info: mqtt.0 (1281) Client [HeishaMon] publishOnSubscribe send all known states
2023-04-16 13:00:05.127 - info: mqtt.0 (1281) Client [HeishaMon] publishOnSubscribe
2023-04-16 15:00:05.176 - info: ical.0 (50011) starting. Version 1.13.2 in /opt/iobroker/node_modules/iobroker.ical, node: v14.21.3, js-controller: 4.0.24
2023-04-16 13:00:06.456 - warn: shelly.0 (1311) [authEnabled] 192.168.1.161 (shellypro4pm / shellypro4pm-083af27b1970 / shellypro4pm#083af27b1970#1): This device is not protected via restricted login (see adapter documentation for details)
2023-04-16 15:00:06.497 - info: ical.0 (50011) processing URL: Müll https://calendar.google.com/calendar/ical/s.w.bernhard%40gmail.com/private-21faa25aa0eb243313582d9996cb7327/basic.ics
2023-04-16 13:00:06.841 - info: admin.0 (973) <== Disconnect system.user.admin from ::ffff:192.168.1.146 admin
2023-04-16 13:00:08.499 - info: admin.0 (973) ==> Connected system.user.admin from ::ffff:192.168.1.146
2023-04-16 15:00:12.440 - info: ical.0 (50011) Terminated (NO_ERROR): Without reason
2023-04-16 13:00:12.957 - info: host.iobroker instance system.adapter.ical.0 terminated with code 0 (NO_ERROR)
2023-04-16 15:00:17.166 - info: daswetter.0 (49996) still wrong data structure from server received! repaired...
2023-04-16 15:00:20.260 - info: daswetter.0 (49996) Terminated (ADAPTER_REQUESTED_TERMINATION): All data handled, adapter stopped until next scheduled moment
2023-04-16 15:00:20.767 - info: daswetter.0 (49996) cleaned everything up...
2023-04-16 13:00:20.772 - info: host.iobroker instance system.adapter.daswetter.0 terminated with code 11 (ADAPTER_REQUESTED_TERMINATION)
2023-04-16 13:00:58.758 - info: modbus.2 (1204) Connected to slave 192.168.1.52
2023-04-16 13:00:59.310 - info: modbus.0 (1174) Connected to slave 192.168.1.48
2023-04-16 13:01:08.437 - warn: shelly.0 (1311) [authEnabled] 192.168.1.161 (shellypro4pm / shellypro4pm-083af27b1970 / shellypro4pm#083af27b1970#1): This device is not protected via restricted login (see adapter documentation for details)
2023-04-16 13:01:25.428 - warn: shelly.0 (1311) [authEnabled] 192.168.1.161 (shellypro4pm / shellypro4pm-083af27b1970 / shellypro4pm#083af27b1970#1): This device is not protected via restricted login (see adapter documentation for details)
2023-04-16 13:01:42.383 - warn: shelly.0 (1311) [authEnabled] 192.168.1.161 (shellypro4pm / shellypro4pm-083af27b1970 / shellypro4pm#083af27b1970#1): This device is not protected via restricted login (see adapter documentation for details)
2023-04-16 13:01:59.469 - warn: shelly.0 (1311) [authEnabled] 192.168.1.161 (shellypro4pm / shellypro4pm-083af27b1970 / shellypro4pm#083af27b1970#1): This device is not protected via restricted login (see adapter documentation for details)
2023-04-16 13:02:00.023 - info: host.iobroker instance system.adapter.weatherunderground.0 started with pid 50029
2023-04-16 15:02:00.909 - info: weatherunderground.0 (50029) starting. Version 3.4.2 in /opt/iobroker/node_modules/iobroker.weatherunderground, node: v14.21.3, js-controller: 4.0.24
2023-04-16 15:02:06.052 - info: weatherunderground.0 (50029) Terminated (NO_ERROR): Without reason
2023-04-16 13:02:06.604 - info: host.iobroker instance system.adapter.weatherunderground.0 terminated with code 0 (NO_ERROR)
2023-04-16 13:02:16.409 - warn: shelly.0 (1311) [authEnabled] 192.168.1.161 (shellypro4pm / shellypro4pm-083af27b1970 / shellypro4pm#083af27b1970#1): This device is not protected via restricted login (see adapter documentation for details)

Ich hoffe, das mir einer Helfen kann und bedanke mich im Voraus schonmal
VG
Sascha

[paul53]

@woupi sagte: beide gleich und Richtig.

Es gibt noch eine dritte Zeit: Die des OS unter dem der Browser läuft (Log).

[woupi]

@paul53
erstmal Danke für die schnelle Antwort, leider weiß ich nicht was Du genau meinst, bzw wo ich die finde.

[paul53]

@woupi sagte: was Du genau meinst

Der Admin (Tab "Protokolle") wird in einem Browser angezeigt, der unter einem OS läuft, das seine eigenen Uhrzeiteinstellungen hat.

[woupi]

@paul53
Ok,

OS Windos 11
Browser Adge

Ich hoffe, das war richtig, einen log wüsste ich nicht, wie ich daran komme, geht bestimmt auch, weiß aber nicht wie.

[woupi]

@paul53
war das, das was Du wissen wolltest?

[paul53]

@woupi sagte: war das, das was Du wissen wolltest?

Ja.

[woupi]

@paul53

Ok, danke, siehst Du da einen Fehler?

VG
Sascha

[paul53]

@woupi sagte: siehst Du da einen Fehler?

Nein. Habe keine Erklärung dafür, dass die Zeiten links im Log differieren. Vielleicht mal Browser-Refresh und ioBroker neu starten?

[woupi]

@paul53

Schade.

@paul53 sagte in verschiedene Zeiten im Log:

@woupi sagte: siehst Du da einen Fehler?

Nein. Habe keine Erklärung dafür, dass die Zeiten links im Log differieren. Vielleicht mal Browser-Refresh und ioBroker neu starten?

Browser Refresh schon öfters gemacht und iobroker genauso wie proxmox auch schon neu gestartet.

Leider ist um 16:00 statt um 18:00 auch die WP schon wieder 2 Stunden früher ausgegangen. Heute morgen ist sie auch schon 2 Stunden (um 7:00 statt um 9:00Uhr) zu früh gestartet.

Ich bin echt ratlos.

Trotzdem Danke.
Ich hoffe, es kommt noch einer mit einer Zündenden Idee.

VG
Sascha

[paul53]

@woupi sagte: die WP schon wieder 2 Stunden früher ausgegangen.

Wenn die UTC-Zeit wirken würde, müsste sie 2 Stunden später schalten. Was ergibt dieses Test-Skript rechts in der Log-Ausgabe?

[woupi]

@paul53

@paul53 sagte in verschiedene Zeiten im Log:

@woupi sagte: die WP schon wieder 2 Stunden früher ausgegangen.

Wenn die UTC-Zeit wirken würde, müsste sie 2 Stunden später schalten. Was ergibt dieses Test-Skript rechts in der Log-Ausgabe?

2023-04-16 17:30:55.163 - info: javascript.0 (14795) Stop script script.js.common.test
2023-04-16 17:30:58.265 - info: javascript.0 (14795) Start javascript script.js.common.test
2023-04-16 17:30:58.276 - info: javascript.0 (14795) script.js.common.test: 17:30
2023-04-16 17:30:58.276 - info: javascript.0 (14795) script.js.common.test: registered 0 subscriptions, 0 schedules, 0 messages, 0 logs and 0 file subscriptions

[paul53]

@woupi
Das passt, folglich ist das geschilderte Verhalten nicht nachvollziehbar.

[woupi]

@paul53
So sehe ich das auch und ich habe keine Ahnung wo ich noch suchen soll.

Am log ist es aber Nachvollziehbar, den da variieren ja auch die Zeiten.

Nochmal trotzdem Danke, Du hast wenigstens versucht zu Helfen.

Ich werde jetzt nochmal alles runter fahren und neu starten.
Morgen mal sehen, was sie dann macht.

VG
Sascha

[paul53]

@woupi
Wenn 2 Stunden zu früh ausgelöst wird, könnte eine doppelte Wandlung UTC --> CEST vorliegen. Ändert sich das Verhalten, wenn Proxmox auf UTC bleibt?

[woupi]

@paul53 sagte in verschiedene Zeiten im Log:

@woupi
Wenn 2 Stunden zu früh ausgelöst wird, könnte eine doppelte Wandlung UTC --> CEST vorliegen. Ändert sich das Verhalten, wenn Proxmox auf UTC bleibt?

Werde ich mal Probieren.
Jetzt erstmal neu nochmal neu start und morgen abend den log ansehen.

Wenn das dann immer noch so ist, werde ich in Proxmox mal umstellen und dann das gleiche nochmal machen.

VG

[woupi]

@paul53

nachdem ich gestern abend nochmal alle VM's, lxc's und auch Proxmox neu gestartet habe, sind heute alle Zeiten i.O. und auch mein skript ist gelaufen wie es soll.

Schlussendlich habe ich zwischen dem Neustart vor 2 Tagen und gestern, aber nur in der Javascript Instanz unter Astro-Einstellung, den Haken bei Systemeinstellungen verwenden entfernt und statt dessen meine Koordinaten eingegeben. Meine ich zu mindestens.

Trotzdem nochmal ganz lieben Dank für deine Hilfe, der Neustart hat es dann offensichtlich ja gebracht.

VG
Sascha