History: Restart alle paar Minuten - Downgrade geht nicht
-
Die Situation wird eher schlimmer.
Der ioBroker war anscheinend gerade wieder einmal mit einem Neustart des history-Adapters beschäftigt, als ich meinen Rechner hochgefahren habe. Anscheinend hat der firefox dann versucht, einige FLOT-Charts zu aktualisieren, was schon monetalang so geht. Diesmal führt das aber zum Totalabsturz von ioBroker. Wie kann ich aus dem logfile erkennen, was den Absturz verursacht hat?
! ````
.279 - [32minfo[39m: history.0 enabled logging of data.0.motion.Hobby-doorCounterUntilMidnight
2018-03-09 18:55:39.280 - [32minfo[39m: history.0 enabled logging of data.0.motion.Hobby-doorCounter
2018-03-09 18:55:39.280 - [32minfo[39m: history.0 enabled logging of data.0.motion.Hobby-DoorClosed
2018-03-09 18:56:29.511 - [31merror[39m: uncaught exception: Maximum call stack size exceeded
2018-03-09 18:56:29.544 - [31merror[39m: RangeError: Maximum call stack size exceeded
at Client.onerror (/opt/iobroker/node_modules/socket.io/lib/client.js:213:24)
at Client.ondata (/opt/iobroker/node_modules/socket.io/lib/client.js:178:10)
at emitOne (events.js:96:13)
at Socket.emit (events.js:188:7)
at Socket.onPacket (/opt/iobroker/node_modules/engine.io/lib/socket.js:102:14)
at emitOne (events.js:96:13)
at WebSocket.emit (events.js:188:7)
at WebSocket.Transport.onPacket (/opt/iobroker/node_modules/engine.io/lib/transport.js:105:8)
at WebSocket.Transport.onData (/opt/iobroker/node_modules/engine.io/lib/transport.js:116:8)
at WebSocket.onData (/opt/iobroker/node_modules/engine.io/lib/transports/websocket.js:79:30)
2018-03-09 18:56:29.563 - [32minfo[39m: iobroker _restart
2018-03-09 18:56:33.230 - [32minfo[39m: iobroker Starting node restart.js
2018-03-09 18:56:33.238 - [32minfo[39m: iobroker exit 0
2018-03-09 18:56:33.241 - [32minfo[39m: host.orangepiplus2e received SIGTERM
2018-03-09 18:56:37.473 - [32minfo[39m: host.orangepiplus2e received SIGTERM
2018-03-09 18:56:41.130 - [32minfo[39m: host.orangepiplus2e force terminating
2018-03-09 18:56:41.132 - [32minfo[39m: Adapter admin still running
2018-03-09 18:56:41.134 - [32minfo[39m: Adapter hm-rpc still running
2018-03-09 18:56:41.136 - [32minfo[39m: Adapter hm-rega still running
2018-03-09 18:56:41.139 - [32minfo[39m: Adapter web still running
2018-03-09 18:56:41.140 - [32minfo[39m: Adapter hm-rpc still running
2018-03-09 18:56:41.142 - [32minfo[39m: Adapter socketio still running
2018-03-09 18:56:41.144 - [32minfo[39m: Adapter history still running
2018-03-09 18:56:41.145 - [32minfo[39m: Adapter terminal still running
2018-03-09 18:56:41.146 - [32minfo[39m: Adapter email still running
2018-03-09 18:56:41.147 - [32minfo[39m: Adapter javascript still running
2018-03-09 18:56:41.148 - [32minfo[39m: Adapter opi still running
2018-03-09 18:56:41.148 - [32minfo[39m: Adapter mihome-vacuum still running
2018-03-09 18:56:41.149 - [32minfo[39m: Adapter tradfri still running
2018-03-09 18:56:41.150 - [32minfo[39m: Adapter simple-api still running
2018-03-09 18:56:41.151 - [32minfo[39m: Adapter sonoff still running
2018-03-09 18:56:41.152 - [32minfo[39m: Adapter rflink still running
2018-03-09 18:56:41.152 - [32minfo[39m: Adapter nut still running
2018-03-09 18:56:50.733 - [32minfo[39m: host.orangepiplus2e iobroker.js-controller version 1.2.3 js-controller starting
2018-03-09 18:56:50.767 - [32minfo[39m: host.orangepiplus2e Copyright (c) 2014-2017 bluefox, 2014 hobbyquaker
2018-03-09 18:56:50.771 - [32minfo[39m: host.orangepiplus2e hostname: orangepiplus2e, node: v6.13.0
2018-03-09 18:56:50.776 - [32minfo[39m: host.orangepiplus2e ip addresses: 192.168.1.25 fe80::bc84:ceff:fea9:244
2018-03-09 18:56:50.987 - [32minfo[39m: host.orangepiplus2e inMem-states listening on port 9000
2018-03-09 18:56:51.947 - [32minfo[39m: host.orangepiplus2e inMem-objects listening on port 9001
2018-03-09 18:56:51.991 - [32minfo[39m: host.orangepiplus2e InMemoryDB connected
2018-03-09 18:56:52.087 - [32minfo[39m: host.orangepiplus2e 30 instances found
2018-03-09 18:56:52.159 - [32minfo[39m: host.orangepiplus2e starting 17 instances
2018-03-09 18:56:52.270 - [32minfo[39m: host.orangepiplus2e instance system.adapter.admin.0 started with pid 26750
2018-03-09 18:56:56.193 - [32minfo[39m: host.orangepiplus2e instance system.adapter.hm-rpc.0 started with pid 26756
2018-03-09 18:56:56.776 - [32minfo[39m: admin.0 starting. Version 2.0.9 in /opt/iobroker/node_modules/iobroker.admin, node: v6.13.0
2018-03-09 18:56:56.882 - [32minfo[39m: admin.0 requesting all states
2018-03-09 18:56:56.892 - [32minfo[39m: admin.0 requesting all objects
2018-03-09 18:57:00.671 - [32minfo[39m: host.orangepiplus2e instance system.adapter.hm-rega.0 started with pid 26766
2018-03-09 18:57:01.741 - [32minfo[39m: hm-rpc.0 starting. Version 1.5.1 in /opt/iobroker/node_modules/iobroker.hm-rpc, node: v6.13.0
2018-03-09 18:57:02.718 - [32minfo[39m: admin.0 received all states
2018-03-09 18:57:03.072 - [32minfo[39m: hm-rpc.0 xmlrpc server is trying to listen on 192.168.1.25:2001
2018-03-09 18:57:03.080 - [32minfo[39m: hm-rpc.0 xmlrpc client is trying to connect to 192.168.1.24:2001 with ["http://192.168.1.25:2001","hm-rpc.0"]
2018-03-09 18:57:03.248 - [32minfo[39m: hm-rpc.0 xmlrpc <- system.listMethods ["hm-rpc.0"]
2018-03-09 18:57:03.307 - [32minfo[39m: hm-rpc.0 xmlrpc <- listDevices ["hm-rpc.0"]
2018-03-09 18:57:03.417 - [32minfo[39m: hm-rpc.0 xmlrpc -> 398 devices
2018-03-09 18:57:04.202 - [32minfo[39m: host.orangepiplus2e instance system.adapter.web.0 started with pid 26780
2018-03-09 18:57:04.487 - [32minfo[39m: hm-rpc.0 Connected
2018-03-09 18:57:05.519 - [32minfo[39m: admin.0 received all objects
2018-03-09 18:57:03.668 - [32minfo[39m: hm-rega.0 starting. Version 1.7.0 in /opt/iobroker/node_modules/iobroker.hm-rega, node: v6.13.0
2018-03-09 18:57:03.719 - [32minfo[39m: hm-rega.0 subscribe hm-rpc.0.BidCoS-RF.49.PRESS_SHORT
2018-03-09 18:57:05.847 - [32minfo[39m: hm-rega.0 ReGaHSS 192.168.1.24 up
2018-03-09 18:57:05.950 - [32minfo[39m: hm-rega.0 time difference local-ccu 1s
2018-03-09 18:57:06.160 - [32minfo[39m: hm-rega.0 added/updated 3 favorites to enum.favorites
2018-03-09 18:57:06.021 - [32minfo[39m: admin.0 http server listening on port 8081
2018-03-09 18:57:06.023 - [32minfo[39m: admin.0 Use link "http://localhost:8081" to configure.
2018-03-09 18:57:06.557 - [32minfo[39m: admin.0 Change log subscriber state: true
2018-03-09 18:57:06.579 - [32minfo[39m: hm-rega.0 system.adapter.admin.0: logging true
2018-03-09 18:57:06.599 - [32minfo[39m: admin.0 system.adapter.admin.0: logging true
2018-03-09 18:57:06.623 - [32minfo[39m: hm-rega.0 added/updated functions to enum.functions
2018-03-09 18:57:06.632 - [32minfo[39m: hm-rpc.0 system.adapter.admin.0: logging true
2018-03-09 18:57:06.891 - [32minfo[39m: admin.0 Request actual repository...
2018-03-09 18:57:07.102 - [32minfo[39m: hm-rega.0 added/updated rooms to enum.rooms
2018-03-09 18:57:07.371 - [32minfo[39m: host.orangepiplus2e Update repository "default" under "http://download.iobroker.net/sources-dist.json"
2018-03-09 18:57:08.571 - [32minfo[39m: host.orangepiplus2e instance system.adapter.hm-rpc.1 started with pid 26786
2018-03-09 18:57:10.637 - [32minfo[39m: web.0 starting. Version 2.1.9 in /opt/iobroker/node_modules/iobroker.web, node: v6.13.0
2018-03-09 18:57:11.454 - [32minfo[39m: web.0 simpleAPI server listening on port 8082
2018-03-09 18:57:11.461 - [32minfo[39m: web.0 Allow states only when user is owner: false
2018-03-09 18:57:12.017 - [32minfo[39m: web.0 socket.io server listening on port 8082
2018-03-09 18:57:12.038 - [32minfo[39m: web.0 http server listening on port 8082
2018-03-09 18:57:12.223 - [32minfo[39m: host.orangepiplus2e instance system.adapter.socketio.0 started with pid 26796
2018-03-09 18:57:12.254 - [32minfo[39m: web.0 2018-03-09T17:57:12.253Z Connected system.user.admin
2018-03-09 18:57:12.383 - [32minfo[39m: admin.0 Repository received successfully.
2018-03-09 18:57:12.292 - [32minfo[39m: web.0 2018-03-09T17:57:12.291Z Connected system.user.admin
2018-03-09 18:57:12.305 - [32minfo[39m: web.0 2018-03-09T17:57:12.305Z Connected system.user.admin
2018-03-09 18:57:12.319 - [32minfo[39m: web.0 2018-03-09T17:57:12.318Z Connected system.user.admin
2018-03-09 18:57:12.330 - [32minfo[39m: web.0 2018-03-09T17:57:12.330Z Connected system.user.admin
2018-03-09 18:57:12.344 - [32minfo[39m: web.0 2018-03-09T17:57:12.343Z Connected system.user.admin
2018-03-09 18:57:12.378 - [32minfo[39m: web.0 2018-03-09T17:57:12.370Z Connected system.user.admin
2018-03-09 18:57:12.469 - [32minfo[39m: web.0 2018-03-09T17:57:12.469Z Connected system.user.admin
2018-03-09 18:57:12.605 - [32minfo[39m: web.0 2018-03-09T17:57:12.605Z Connected system.user.admin
2018-03-09 18:57:12.675 - [32minfo[39m: web.0 2018-03-09T17:57:12.674Z Connected system.user.admin
2018-03-09 18:57:12.877 - [32minfo[39m: web.0 2018-03-09T17:57:12.877Z Connected system.user.admin
2018-03-09 18:57:12.990 - [32minfo[39m: web.0 2018-03-09T17:57:12.988Z Connected system.user.admin
2018-03-09 18:57:13.086 - [32minfo[39m: hm-rega.0 got 142 programs
2018-03-09 18:57:12.906 - [32minfo[39m: hm-rpc.1 starting. Version 1.5.1 in /opt/iobroker/node_modules/iobroker.hm-rpc, node: v6.13.0
2018-03-09 18:57:13.386 - [32minfo[39m: web.0 2018-03-09T17:57:13.385Z Connected system.user.admin
2018-03-09 18:57:13.907 - [32minfo[39m: web.0 2018-03-09T17:57:13.907Z Connected system.user.admin
2018-03-09 18:57:13.945 - [32minfo[39m: hm-rega.0 added/updated 142 programs
2018-03-09 18:57:14.134 - [32minfo[39m: web.0 2018-03-09T17:57:14.134Z Connected system.user.admin
2018-03-09 18:57:14.352 - [32minfo[39m: web.0 2018-03-09T17:57:14.351Z Connected system.user.admin
2018-03-09 18:57:13.947 - [32minfo[39m: hm-rega.0 deleted 0 programs
2018-03-09 18:57:14.605 - [32minfo[39m: web.0 2018-03-09T17:57:14.604Z Connected system.user.admin
2018-03-09 18:57:14.617 - [32minfo[39m: web.0 2018-03-09T17:57:14.617Z Connected system.user.admin
2018-03-09 18:57:14.670 - [32minfo[39m: web.0 2018-03-09T17:57:14.669Z Connected system.user.admin
2018-03-09 18:57:14.765 - [32minfo[39m: web.0 2018-03-09T17:57:14.764Z Connected system.user.admin
2018-03-09 18:57:15.147 - [32minfo[39m: web.0 2018-03-09T17:57:15.147Z Connected system.user.admin
2018-03-09 18:57:15.346 - [32minfo[39m: web.0 2018-03-09T17:57:15.345Z Connected system.user.admin
2018-03-09 18:57:15.917 - [32minfo[39m: web.0 2018-03-09T17:57:15.916Z Connected system.user.admin
2018-03-09 18:57:16.343 - [32minfo[39m: web.0 2018-03-09T17:57:16.342Z Connected system.user.admin
2018-03-09 18:57:16.374 - [32minfo[39m: web.0 2018-03-09T17:57:16.374Z Connected system.user.admin
2018-03-09 18:57:17.218 - [32minfo[39m: host.orangepiplus2e instance system.adapter.history.0 started with pid 26806
2018-03-09 18:57:17.297 - [32minfo[39m: web.0 2018-03-09T17:57:17.296Z Connected system.user.admin
2018-03-09 18:57:17.982 - [32minfo[39m: hm-rega.0 got 129 variables
2018-03-09 18:57:18.204 - [32minfo[39m: web.0 2018-03-09T17:57:18.203Z Connected system.user.admin
2018-03-09 18:57:18.571 - [32minfo[39m: hm-rpc.1 binrpc server is trying to listen on 192.168.1.25:8701
2018-03-09 18:57:18.593 - [32minfo[39m: hm-rpc.1 binrpc client is trying to connect to 192.168.1.24:8701 with ["xmlrpc_bin://192.168.1.25:8701","hm-rpc.1"]
2018-03-09 18:57:18.628 - [32minfo[39m: hm-rega.0 added/updated 129 variables
2018-03-09 18:57:18.630 - [32minfo[39m: hm-rega.0 deleted 0 variables
2018-03-09 18:57:18.636 - [32minfo[39m: hm-rega.0 request state values
2018-03-09 18:57:20.772 - [32minfo[39m: host.orangepiplus2e instance system.adapter.terminal.0 started with pid 26812
2018-03-09 18:57:21.994 - [32minfo[39m: hm-rega.0 got state values
2018-03-09 18:57:22.043 - [32minfo[39m: socketio.0 starting. Version 1.8.6 in /opt/iobroker/node_modules/iobroker.socketio, node: v6.13.0
2018-03-09 18:57:22.434 - [32minfo[39m: socketio.0 socket.io server listening on port 8084
2018-03-09 18:57:24.894 - [32minfo[39m: hm-rpc.1 binrpc -> listDevices 237
2018-03-09 18:57:28.811 - [31merror[39m: history.0 no connection to objects DB
2018-03-09 18:57:29.109 - [32minfo[39m: host.orangepiplus2e instance system.adapter.email.0 started with pid 26826
2018-03-09 18:57:29.209 - [32minfo[39m: admin.0 Unsubscribe from all states, except system's, because over 3 seconds the number of events is over 200 (in last second 0)
2018-03-09 18:57:30.171 - [32minfo[39m: host.orangepiplus2e instance system.adapter.javascript.0 started with pid 26832
2018-03-09 18:57:31.534 - [32minfo[39m: hm-rpc.1 new CUxD devices/channels after filter: 0
2018-03-09 18:57:31.546 - [32minfo[39m: hm-rpc.1 Connected
2018-03-09 18:57:32.322 - [32minfo[39m: host.orangepiplus2e instance system.adapter.opi.0 started with pid 26838
2018-03-09 18:57:34.669 - [32minfo[39m: history.0 starting. Version 1.6.1 in /opt/iobroker/node_modules/iobroker.history, node: v6.13.0
2018-03-09 18:57:34.512 - [32minfo[39m: terminal.0 starting. Version 0.1.2 in /opt/iobroker/node_modules/iobroker.terminal, node: v6.13.0
2018-03-09 18:57:36.248 - [32minfo[39m: terminal.0 http server listening on port 8088
2018-03-09 18:57:36.380 - [32minfo[39m: host.orangepiplus2e instance system.adapter.mihome-vacuum.0 started with pid 26848
2018-03-09 18:57:36.479 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.updated
2018-03-09 18:57:36.563 - [32minfo[39m: web.0 2018-03-09T17:57:36.562Z Connected system.user.admin
2018-03-09 18:57:37.978 - [32minfo[39m: email.0 starting. Version 1.0.2 in /opt/iobroker/node_modules/iobroker.email, node: v6.13.0
2018-03-09 18:57:39.575 - [32minfo[39m: web.0 2018-03-09T17:57:39.574Z Connected system.user.admin
2018-03-09 18:57:40.140 - [32minfo[39m: hm-rega.0 renamed hm-rpc.0.MEQ0783837.0.UPDATE_PENDING_ALARM to "Inhlator-HM-MOD-EM-8 MEQ0783837:0.UPDATE_PENDING_ALARM"
2018-03-09 18:57:40.261 - [32minfo[39m: host.orangepiplus2e instance system.adapter.tradfri.0 started with pid 26858
2018-03-09 18:57:40.929 - [32minfo[39m: opi.0 starting. Version 0.1.1 in /opt/iobroker/node_modules/iobroker.opi, node: v6.13.0
2018-03-09 18:57:44.692 - [32minfo[39m: host.orangepiplus2e instance system.adapter.simple-api.0 started with pid 26868
2018-03-09 18:57:36.484 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.0.INSTALL_MODE
2018-03-09 18:57:36.487 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.LEVEL
2018-03-09 18:57:36.490 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.PRESS_LONG
2018-03-09 18:57:36.493 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.PRESS_SHORT
2018-03-09 18:57:36.494 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.2.LEVEL
2018-03-09 18:57:36.497 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.2.PRESS_LONG
2018-03-09 18:57:36.500 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.2.PRESS_SHORT
2018-03-09 18:57:36.503 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.3.LEVEL
2018-03-09 18:57:36.505 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.3.PRESS_LONG
2018-03-09 18:57:36.551 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.3.PRESS_SHORT
2018-03-09 18:57:36.564 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.4.LEVEL
2018-03-09 18:57:36.578 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.4.PRESS_LONG
2018-03-09 18:57:36.580 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.4.PRESS_SHORT
2018-03-09 18:57:36 -
Bin jetzt auf history 1.6.1
Das Problem ist immer noch da.
Interessanterweise wird jeder Datenpunkt nach jedem Restart mehrfach enabled. Beispiel der log-Anzeige im Log-Fenster des Admin:
history.0 2018-03-10 12:06:00.858 info enabled logging of data.0.motion.Hobby-DoorClosed history.0 2018-03-10 12:06:00.858 info enabled logging of data.0.motion.Hobby-DoorClosed history.0 2018-03-10 12:06:00.858 info enabled logging of data.0.motion.Hobby-DoorClosed history.0 2018-03-10 12:06:00.858 info enabled logging of data.0.motion.Hobby-DoorClosed history.0 2018-03-10 12:06:00.857 info enabled logging of data.0.motion.Hobby-DoorClosed history.0 2018-03-10 12:06:00.857 info enabled logging of data.0.motion.Hobby-DoorClosed history.0 2018-03-10 12:06:00.857 info enabled logging of data.0.motion.Hobby-DoorClosedJeder Datenpunkt wird also 6mal enabled. Habe den Eindruck, daß bei jedem history Neustart 2 enables dazu kommen.
Im Logfile ist das aber gar nicht zu sehen, da wird jeder Datenpunkt nur einmal enabled. Hier aus dem Logfile:
2018-03-10 12:05:52.921 - [32minfo[39m: history.0 enabled logging of data.0.motion.Hobby-doorCounterToday 2018-03-10 12:05:52.922 - [32minfo[39m: history.0 enabled logging of data.0.motion.Hobby-doorCounterUntilMidnight 2018-03-10 12:05:52.923 - [32minfo[39m: history.0 enabled logging of data.0.motion.Hobby-doorCounter 2018-03-10 12:05:52.924 - [32minfo[39m: history.0 enabled logging of data.0.motion.Hobby-DoorClosed 2018-03-10 12:06:37.904 - [32minfo[39m: web.0 2018-03-10T11:06:37.903Z Connected system.user.adminAuch die Zeiten zwischen Admin-Log und Logfile differieren leicht.
Das System wird für meine Zwecke immer unbrauchbarer. Was kann ich tun, um dem Bösewicht auf die Spur zu kommen?
-
Da ich wahrscheinlich (vielleicht) vis als letztes vor den Instabilitäten upgedatet haeb und auch nicht mehr downgraden kann, habe ich mal für den vis loglevel debug gestellt. Dabei ergab sich:
host.orangepiplus2e 2018-03-10 14:42:38.031 info instance system.adapter.vis.0 terminated while should be started once Caught 2018-03-10 14:42:38.030 error by controller[1]: 2018-03-10 14:42:35.744 - debug: vis.0 statesDB connected Caught 2018-03-10 14:42:38.027 error by controller[0]: 2018-03-10 14:42:35.633 - debug: vis.0 objectDB connected vis.0 2018-03-10 14:42:36.176 info vis license is OK. vis.0 2018-03-10 14:42:35.869 info starting. Version 1.1.1 in /opt/iobroker/node_modules/iobroker.vis, node: v6.13.1 vis.0 2018-03-10 14:42:35.740 debug statesDB connected vis.0 2018-03-10 14:42:35.613 debug objectDB connected host.orangepiplus2e 2018-03-10 14:42:32.736 info object change system.adapter.vis.0 host.orangepiplus2e 2018-03-10 14:42:28.725 info object change system.adapter.vis.0Warum gibt es jetzt 2 controller?
npm 3.10.10
node 6.13.1
iobroker.js-controller version 1.2.3
-
Bin mir da gar nicht so sicher, dass das 2 controller sind.
ich tippe da eher auf durchnummerierung der catch
Gruß
Rainer
-
Wer löst denn den Neustart des history adapters aus? Der history selbs oder der controller? ob es was hilft, wenn ich den controller upgrade oder downgrade?
-
Habe heute morgen die HM-Adapter downgegraded. Seither "nur" 2 broken connects mit restart des history gehabt.
Hatte vor dem letzten Restart history mal auf "debug gestellt"
!
2018-03-11 17:04:31.068 - [34mdebug[39m: history.0 Min-Delta reached hm-rega.0.27467, last-value=101, new-value=102, ts=1520784267737 2018-03-11 17:04:31.797 - [33mwarn[39m: history.0 Reconnection to DB. 2018-03-11 17:04:31.917 - [33mwarn[39m: history.0 Reconnection to DB. 2018-03-11 17:04:31.950 - [34mdebug[39m: history.0 statesDB connected 2018-03-11 17:04:32.002 - [34mdebug[39m: history.0 statesDB connected 2018-03-11 17:04:32.102 - [32minfo[39m: history.0 starting. Version 1.5.3 in /opt/iobroker/node_modules/iobroker.history, node: v6.13.1 2018-03-11 17:04:32.125 - [32minfo[39m: history.0 starting. Version 1.5.3 in /opt/iobroker/node_modules/iobroker.history, node: v6.13.1 2018-03-11 17:04:32.954 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.updated 2018-03-11 17:04:32.956 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.0.INSTALL_MODE !Was ist die history.0 states DB und wo liegt die? Und warum kommen diese Meldungen immer doppelt? -
Jetzt wird im debug-mode jedes empfangene Datum dreifach eingetragen:
history.0 2018-03-12 03:50:09.095 debug value not changed hm-rpc.1.CUX9000007.1.STATE, last-value=2, new-value=2, ts=1520823009084 history.0 2018-03-12 03:50:09.095 debug value not changed hm-rpc.1.CUX9000007.1.STATE, last-value=2, new-value=2, ts=1520823009084 history.0 2018-03-12 03:50:09.093 debug value not changed hm-rpc.1.CUX9000007.1.STATE, last-value=2, new-value=2, ts=1520823009084 history.0 2018-03-12 03:50:09.062 debug value not changed hm-rpc.1.CUX9000009.1.STATE, last-value=1, new-value=1, ts=1520823009050 history.0 2018-03-12 03:50:09.062 debug value not changed hm-rpc.1.CUX9000009.1.STATE, last-value=1, new-value=1, ts=1520823009050 history.0 2018-03-12 03:50:09.060 debug value not changed hm-rpc.1.CUX9000009.1.STATE, last-value=1, new-value=1, ts=1520823009050Dann gab es noch sowas
!
2018-03-11 10:45:29.180 - [34mdebug[39m: history.0 Min-Delta ignored because no number hm-rpc.0.JEQ012345678.1.MOTION, last-value=true, new-value=false, ts=1520761529168 2018-03-11 10:45:34.007 - [32minfo[39m: web.0 2018-03-11T09:45:34.006Z Connected system.user.admin 2018-03-11 10:45:34.149 - [34mdebug[39m: history.0 use parallel requests 2018-03-11 10:45:34.188 - [34mdebug[39m: history.0 use parallel requests 2018-03-11 10:45:34.214 - [34mdebug[39m: history.0 got 1 datapoints for data.0.Lock.FrontDoor.rfid.alive 2018-03-11 10:45:34.218 - [34mdebug[39m: history.0 after getCachedData: length = 1, isFull=false 2018-03-11 10:45:34.318 - [34mdebug[39m: history.0 after getFileData: cacheData.length = 1, fileData.length = 408 2018-03-11 10:45:34.331 - [34mdebug[39m: history.0 Send: 408 values in: 121ms 2018-03-11 10:45:34.335 - [34mdebug[39m: history.0 sendTo "getHistory" to system.adapter.web.0 from system.adapter.history.0 2018-03-11 10:45:34.820 - [34mdebug[39m: history.0 got 0 datapoints for hm-rpc.1.CUX9000007.1.STATE 2018-03-11 10:45:34.850 - [34mdebug[39m: history.0 got 1 datapoints for hm-rpc.1.CUX9000009.1.STATE 2018-03-11 10:45:34.953 - [34mdebug[39m: history.0 Send: 218 of: 508 in: 804ms 2018-03-11 10:45:34.955 - [34mdebug[39m: history.0 sendTo "getHistory" to system.adapter.web.0 from system.adapter.history.0 2018-03-11 10:45:34.971 - [34mdebug[39m: history.0 Send: 171 of: 269 in: 783ms 2018-03-11 10:45:34.972 - [34mdebug[39m: history.0 sendTo "getHistory" to system.adapter.web.0 from system.adapter.history.0 ! -
Bin jetzt nach heftigen downgraden und Pausieren einiger Adapter auf einem restart von history pro Tag. Nach einigen Restarts gibt es aber generelle Probleme. So geht es also nicht weiter.
Möchte demnächst das System neu aufsetzen, möglichst in einen Zustand, bei dem ein reconnect der DB keinen restart von History auslöst und möglichst wenige reconnects auftreten.
Welche Konfigurationen (node, npm, js-controller, admin, history, HM-adapter etc.) laufen stabil? Kann mir jemand Tipps geben?
-
Hi,
bei mir läuft alles auf latest und stabil!
Ich verstehe einige Dinge aus deinem Log nicht. An sich sollte es nie vorkommen das Adapterinstanzen parallel mehrfach laufen. Das stellt an sich der js-controller sicher.
Also überhaupt das da zwei History-Instanzen laufen ist komisch. Das wäre aber das einzige was in meinen Augen das doppellogging erklären würde. Nur mal um sicherzugehen: Die Logs hier kommen aus dem Admin oder aus dem "echten Logfile"? Wenn Admin - zeigt das echter Logfile das gleiche? (Nicht das Admin Müll anzeigt).
Ich denke nicht das Versionsänderungen hier helfen werden - das kann an sich alles gar nicht sein
Ich hätte malversucht alle Adapter auszuschalten. Dann iobroker neustarten, Log ansehen, dann die wichtigen Adapter und History starten - eins nach dem anderen und immer wieder log beobachten. Und am besten History auf Debug lassen.
-
Vielen Dank!
Ich verstehe es leider auch nicht.
Logfile zeigt immer nur einen History-enabled Eintrag pro Datenpunkt.
Im Admin-Log Window werden aber nach history Neustart eine immer wachsende Zahl von History enabled pro Datenpunkt gezeigt.
Das scheint auch plausibel, weil mit jedem Neustart die ganze enable Prozedur länger dauert und nauch einigen Neustarts gar nicht mehr ganz durchläuft.
-
oookkkkk …wenn das Logfile nur eins anzeigt dann ist es eher ein Thema vom Admin bzw vom "streamed logging handling für Admin".
Das Logfile auf Platte hat hier "mehr recht" als die Admin-Anzeige
Welche Version js-controler? Welche Version Admin?
-
Admin ist
2018-03-21 10:16:38.917 - [32minfo[39m: admin.0 starting. Version 2.0.9 in /opt/iobroker/node_modules/iobroker.admin, node: v6.13.1Controller
`2018-03-21 10:16:32.839 - [32minfo[39m: host.orangepiplus2e iobroker.js-controller version 1.2.3 js-controller starting[/code]` Habe jetzt mal nur das Nötigste am Laufen. Das erste History enablen geht immer flott, bei Folgeaktionen dauert es immer lämnger. Hatte auch schon früher ab und an ein reconnect DB, aber ohne den history Neustart. Wenn Du sagst, daß Dein "neuestes" System stabil läuft, dann kann ich mal eine nächtliche Neuinstallation wagen. Bin immer nur unsicher welches node, npm etc mit was kompatibel ist und wie man dann das richtige zusammenbekommt. Die udate / upgrade -Feinheiten sind mir noch immer fremd. Liegt wohl daran, dass ich mich bisher nicht wirklich damit beschäftigt habe - weil ich es auch nicht wirklich musste. -
Beim Einschalten von web meldet sich history und sagt etwas von "parallel requests". Hat das was zu bedeuten?
!
2018-03-21 10:39:16.980 - [32minfo[39m: web.0 2018-03-21T09:39:16.980Z Connected system.user.admin 2018-03-21 10:39:16.991 - [32minfo[39m: web.0 2018-03-21T09:39:16.990Z Connected system.user.admin 2018-03-21 10:39:17.317 - [34mdebug[39m: history.0 use parallel requests 2018-03-21 10:39:17.375 - [34mdebug[39m: history.0 use parallel requests 2018-03-21 10:39:17.401 - [34mdebug[39m: history.0 use parallel requests 2018-03-21 10:39:17.423 - [34mdebug[39m: history.0 use parallel requests 2018-03-21 10:39:17.475 - [34mdebug[39m: history.0 use parallel requests 2018-03-21 10:39:17.529 - [34mdebug[39m: history.0 use parallel requests 2018-03-21 10:39:17.602 - [34mdebug[39m: history.0 use parallel requests 2018-03-21 10:39:17.824 - [32minfo[39m: web.0 2018-03-21T09:39:17.824Z Connected system.user.admin 2018-03-21 10:39:17.875 - [32minfo[39m: web.0 2018-03-21T09:39:17.875Z Connected system.user.admin 2018-03-21 10:39:17.899 - [32minfo[39m: web.0 2018-03-21T09:39:17.899Z Connected system.user.admin 2018-03-21 10:39:18.026 - [32minfo[39m: web.0 2018-03-21T09:39:18.025Z Connected system.user.admin 2018-03-21 10:39:18.189 - [32minfo[39m: web.0 2018-03-21T09:39:18.188Z Connected system.user.admin 2018-03-21 10:39:18.281 - [32minfo[39m: web.0 2018-03-21T09:39:18.280Z Connected system.user.admin 2018-03-21 10:39:18.396 - [34mdebug[39m: history.0 use parallel requests 2018-03-21 10:39:18.333 - [32minfo[39m: web.0 2018-03-21T09:39:18.333Z Connected system.user.admin 2018-03-21 10:39:18.689 - [32minfo[39m: web.0 2018-03-21T09:39:18.689Z Connected system.user.admin 2018-03-21 10:39:18.991 - [34mdebug[39m: history.0 got 1 datapoints for data.0.Ofi.heating.WC.H-rel !
Web is so konfiguriert! ````
IP: IPv4 0.0.0
Port: 8082
Verschlüsselung(HTTPS): No
Authentifikation: No
Puffer: No
Socket.IO Instanz (Optional): integriert (Wird von Rickshaw oder Vis benutzt)
Nur Web-Sockets: no
Eingebautes 'Simple-API': yes (Gehe aber mit meinen ESP8266 direkt über simple API-Port)
Laufen unter Anwender: AdminNach einiger zeit: >! ```` 2018-03-21 10:39:20.862 - [34mdebug[39m: history.0 sendTo "getHistory" to system.adapter.web.0 from system.adapter.history.0 2018-03-21 10:39:20.866 - [34mdebug[39m: history.0 got 0 datapoints for data.0.heating.Keller-See.H-rel 2018-03-21 10:39:20.868 - [34mdebug[39m: history.0 after getCachedData: length = 0, isFull=false 2018-03-21 10:39:20.950 - [34mdebug[39m: history.0 after getFileData: cacheData.length = 0, fileData.length = 412 2018-03-21 10:39:20.953 - [34mdebug[39m: history.0 Send: 395 values in: 87ms 2018-03-21 10:39:20.955 - [34mdebug[39m: history.0 sendTo "getHistory" to system.adapter.web.0 from system.adapter.history.0 2018-03-21 10:39:20.999 - [34mdebug[39m: history.0 use parallel requests 2018-03-21 10:39:21.044 - [34mdebug[39m: history.0 use parallel requests 2018-03-21 10:39:21.104 - [34mdebug[39m: history.0 use parallel requests 2018-03-21 10:39:21.134 - [34mdebug[39m: history.0 use parallel requests 2018-03-21 10:39:21.180 - [34mdebug[39m: history.0 got 1 datapoints for hm-rpc.1.CUX9002005.0.RSSI_PEER >! ```` -
Admin ist
2018-03-21 10:16:38.917 - [32minfo[39m: admin.0 starting. Version 2.0.9 in /opt/iobroker/node_modules/iobroker.admin, node: v6.13.1Controller
`2018-03-21 10:16:32.839 - [32minfo[39m: host.orangepiplus2e iobroker.js-controller version 1.2.3 js-controller starting[/code]` Habe jetzt mal nur das Nötigste am Laufen. Alles stable Versionen, von daher sollte es keinerlei Probleme haben. ~~[quote]~~ Das erste History enablen geht immer flott, bei Folgeaktionen dauert es immer lämnger. Wie oft schaltest DU das einund aus? :-) Or jetzt zum testen? ~~[quote]~~ Hatte auch schon früher ab und an ein reconnect DB, aber ohne den history Neustart. Das Reconnect weist an sich darauf hin das ggf zuviel Last auf dem System ist. Diese "States-DB" ist eine "in-memory-DB" auf Port 900x und wird vom jscontroller bereitgestellt. Darüber bekommt der Adapter Zugriff auf die States inkl. Updates und so. Ein "Reconnect" heisst dasdie Verbindung weg war und das sollte an sich nicht vorkommen. ~~[quote]~~ Wenn Du sagst, daß Dein "neuestes" System stabil läuft, dann kann ich mal eine nächtliche Neuinstallation wagen. ` ` Das "neuestes" hast Du reingemogelt ... Mein System hab ich vor 2 Jahren installiert und seitdem nur geupdatet ... Das System läuft aber auf dem Latest Repo und nicht "Stable". ~~[quote]~~ Bin immer nur unsicher welches node, npm etc mit was kompatibel ist und wie man dann das richtige zusammenbekommt. ` ` Es sei denn DU brauchst spezielle Adapter ist nodejs 4.x mit npm 3 (was da standard ist) immer noch passend. Node 6 geht auch. node 8 ist grenzwertig :-) Nodejs 4 ist noch bis April offiziell supported, dann sollte man Richtung nodejs 6 gehen. (oder halt 8) ` ` ` ` ``` ` -
Beim Einschalten von web meldet sich history und sagt etwas von "parallel requests". Hat das was zu bedeuten? `
Das sind "getHistory"-Abfragen von flot/riskshaw. "parallel requests" heisst an der Stelle das zur Verarbeiten und Sammeln der Statistikdaten mehrere Threads verwendet werden - ist aber nur zur Datenaufbereitung.
Wieviele Datenpunkte hast Du aktiv im History-Adapter?
-
Danke, ein paar hundert, HM komplett. Das aber schon lange und die Zahl hat sich in jüngster Zeit kaum erhöht.
Bin unterwegs, schaue heute Abend nach der Zahl
-
Wie geht es denn dem System so? Bedenke das "History" das ganze in JSON-Files auf die Platte legt und ggf immer das ganze File neu schreibt wenn Daten dazukommen. Das ist recht viel "I/O", was sich ggf dann in CPU-Auslastung ausdrückt.
Die Alternativen wie SQL oder InfluxDB sind ab einer gewissen Größe vorzuziehen
-
Bis vor der letzten Updaterunde ging es dem System entspannt und jetzt auch noch - wenn nicht gerade die history-enable Geschichte einsetzt oder sich gerade hochschaukelt.
CPU-Auslastung zwischen 0.05 bis 0.5 selten mehr im Normalbetrieb.
Die "reconnect DB" gab es wie gesagt früher auch ab und an aber ohne Folgeaktionen seitens history.
Zur Zahl der subscibierten items: Die HM-Adapter habe ich seinerseits alle global subscribiert. Das läuft schon lange so. Dann noch einige Werte von diversen ESP8266 über simpleApi, wenig tradfri, Xiami robovac, seit einiger Zeit ein wenig sonoff und vielleicht 15 RFLink Geräte.
Habe jetzt im Logfile die Anzahl Zeilen der history-enable events gezählt.
Beim ersten Durchlauf waren es um 7700 und beim zweiten um 11617 Zeilen.
Ich habe ersten nicht verstanden warum es so viele sind (so viele Geräte habe ich nicht) und warum die Zahl von Durchlauf zu Durchlauf schwankt.
Die History-Daten werden auf eine 32GB SSD geschoben, die via USB-Sata-Adapter angebunden ist. Ist aber schon geraume Zeit so und war bis zur letzten update session auch stabil.
Pro Tag werden normalerweise 5 bis 6 MByte history-Daten erzeugt. Das geht schon geraume Zeit so problemlos.
Mit MySQL und Influx kenne ich mich noch gar nicht aus.
Wenn mein PC läuft sind oft 20 browser Tabs mit FLOT-Diagrammen auf. Da sieht man dann nach dem Hochfahren aus dem Resume mode auch mal 70 "Connected system.user.admin" im Logfile, die der Frefox wohl im Hintergrund generiert.
-
Und das ist im echten Logfile auch alles so mit mehreren Enabled und allem ?! Oder ist da alles einmal und ok ?
-
Danke für Deine Geduld.
Aus dem Logfile (/opt/iobroker/log/iobroker.log.2018-03-20) eines Starts von gestern. Das ist das kleinste history-enable Ereignis der letzten Tage was ich auf die Schnelle finden konnte. history-log war da noch auf info.
Startet mit
!
2018-03-20 09:44:23.139 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.0.INSTALL_MODE 2018-03-20 09:44:23.145 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.LEVEL 2018-03-20 09:44:23.148 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.PRESS_LONG 2018-03-20 09:44:23.150 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.PRESS_SHORT 2018-03-20 09:44:23.195 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.2.LEVEL 2018-03-20 09:44:23.198 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.2.PRESS_LONG 2018-03-20 09:44:23.205 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.2.PRESS_SHORT 2018-03-20 09:44:23.212 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.3.LEVEL 2018-03-20 09:44:23.220 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.3.PRESS_LONG 2018-03-20 09:44:23.226 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.3.PRESS_SHORT 2018-03-20 09:44:23.255 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.4.LEVEL 2018-03-20 09:44:23.269 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.4.PRESS_LONG 2018-03-20 09:44:23.272 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.4.PRESS_SHORT !endet mit
!
2018-03-20 09:44:31.558 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_5.SWITCH_07 2018-03-20 09:44:31.559 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_5.SWITCH_0a 2018-03-20 09:44:31.560 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_5.SWITCH_0e 2018-03-20 09:44:31.562 - [32minfo[39m: history.0 enabled logging of data.0.motion.Hobby-doorCounterToday 2018-03-20 09:44:31.563 - [32minfo[39m: history.0 enabled logging of data.0.motion.Hobby-doorCounterUntilMidnight 2018-03-20 09:44:31.564 - [32minfo[39m: history.0 enabled logging of data.0.motion.Hobby-doorCounter 2018-03-20 09:44:31.565 - [32minfo[39m: history.0 enabled logging of data.0.motion.Hobby-DoorClosed 2018-03-20 09:44:31.566 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_6.SWITCH_07 2018-03-20 09:44:31.568 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_6.SWITCH_0a 2018-03-20 09:44:31.569 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_6.SWITCH_0e 2018-03-20 09:44:31.570 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_8.SWITCH_07 2018-03-20 09:44:31.571 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_8.SWITCH_0e 2018-03-20 09:44:31.573 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_8.SWITCH_0a !
auf Zeite 3846, gezählt mit notepad++Also keine unmittelbaren Doppelungen und läuft rasch durch.
Habe eine Stichprobe von 10 Zeilen auf Doppelungen untersucht
Ausbeute:
! ```
2018-03-20 09:44:29.745 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.IEQ0243774.0.CONFIG_PENDING_ALARM[/code]
...
~~[code]~~2018-03-20 09:44:25.683 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.IEQ0243774.0.CONFIG_PENDING [/code]
