ioBroker / ioBroker.javascript

Script engine for JavaScript and Blockly
MIT License
325 stars 120 forks source link

[Bug]: Schedule command seems to be ignored during boot up (each fresh IOBroker start) #1552

Closed Helmut1965 closed 5 months ago

Helmut1965 commented 5 months ago

I'm sure that

Script type

Javascript

The problem

I create the following script for testing: function Test1() { log('In Function','error'); setState('0_userdata.0.Allgemein.TestBoot', 'test', false); }; log('Script Test1 gestartet:','error'); schedule("*/10 * * * * *", Test1 );

Expected behavior: After boot up, the scipt logs a message 'Script Test1 gestartet". Creates a cron schedule which logs a message each 10s with In Function

This works during normal operation. In case the system is booted the script doesn't work like expected. During boot, the log entry "Script Test1 gestartet:" isnn't shown and the schedule statement seems to be ignored. The script is firing the text "In function" more than 1000 times a minute until it's automatically stopped. To solve the problem I have to enter: iobroker restart javascript.0 and all works well.

iobroker.current.log (in debug mode!)

Shutdown at 13:55:35 -> Boot at 13:59:24 2024-04-17 13:55:35.534 - ^[[32minfo^[[39m: javascript.0 (2626) terminating 2024-04-17 13:59:24.355 - ^[[31merror^[[39m: javascript.0 (953) script.js.Technik.Heizung.BootTestScript: In Function 2024-04-17 13:59:24.410 - ^[[31merror^[[39m: javascript.0 (953) script.js.Technik.Heizung.BootTestScript: In Function 2024-04-17 13:59:24.441 - ^[[31merror^[[39m: javascript.0 (953) script.js.Technik.Heizung.BootTestScript: In Function 2024-04-17 13:59:24.475 - ^[[31merror^[[39m: javascript.0 (953) script.js.Technik.Heizung.BootTestScript: In Function 2024-04-17 13:59:24.492 - ^[[31merror^[[39m: javascript.0 (953) script.js.Technik.Heizung.BootTestScript: In Function 2024-04-17 13:59:24.851 - ^[[31merror^[[39m: javascript.0 (953) script.js.Technik.Heizung.BootTestScript: In Function 2024-04-17 13:59:24.870 - ^[[31merror^[[39m: javascript.0 (953) script.js.Technik.Heizung.BootTestScript: In Function 2024-04-17 13:59:24.884 - ^[[31merror^[[39m: javascript.0 (953) script.js.Technik.Heizung.BootTestScript: In Function 2024-04-17 13:59:24.912 - ^[[31merror^[[39m: javascript.0 (953) script.js.Technik.Heizung.BootTestScript: In Function 2024-04-17 13:59:24.956 - ^[[31merror^[[39m: javascript.0 (953) script.js.Technik.Heizung.BootTestScript: In Function fireing same entry more than 1000 times ... 2024-04-17 14:01:16.146 - ^[[31merror^[[39m: javascript.0 (953) script.js.Technik.Heizung.BootTestScript: In Function 2024-04-17 14:01:16.156 - ^[[31merror^[[39m: javascript.0 (953) script.js.Technik.Heizung.BootTestScript: In Function 2024-04-17 14:01:16.168 - ^[[31merror^[[39m: javascript.0 (953) Script script.js.Technik.Heizung.BootTestScript is calling setState more than 1000 times per minute! Stopping Script now! Please check your script! 2024-04-17 14:01:16.169 - ^[[32minfo^[[39m: javascript.0 (953) Stop script script.js.Technik.Heizung.BootTestScript

Just for information: In case I do a adapter restart the log looks completly different it looks like 2024-04-17 14:02:01.560 - ^[[34mdebug^[[39m: javascript.0 (1188) Redis Objects: Use Redis connection: 127.0.0.1:9001 2024-04-17 14:02:01.600 - ^[[34mdebug^[[39m: javascript.0 (1188) Objects client ready ... initialize now 2024-04-17 14:02:01.602 - ^[[34mdebug^[[39m: javascript.0 (1188) Objects create System PubSub Client 2024-04-17 14:02:01.604 - ^[[34mdebug^[[39m: javascript.0 (1188) Objects create User PubSub Client 2024-04-17 14:02:01.649 - ^[[34mdebug^[[39m: javascript.0 (1188) Objects client initialize lua scripts 2024-04-17 14:02:01.658 - ^[[34mdebug^[[39m: javascript.0 (1188) Objects connected to redis: 127.0.0.1:9001 2024-04-17 14:02:01.696 - ^[[34mdebug^[[39m: javascript.0 (1188) Redis States: Use Redis connection: 127.0.0.1:9000 2024-04-17 14:02:01.711 - ^[[34mdebug^[[39m: javascript.0 (1188) States create System PubSub Client 2024-04-17 14:02:01.713 - ^[[34mdebug^[[39m: javascript.0 (1188) States create User PubSub Client 2024-04-17 14:02:01.780 - ^[[34mdebug^[[39m: javascript.0 (1188) States connected to redis: 127.0.0.1:9000 2024-04-17 14:02:01.834 - ^[[34mdebug^[[39m: javascript.0 (1188) Plugin sentry Initialize Plugin (enabled=true) 2024-04-17 14:02:01.837 - ^[[32minfo^[[39m: javascript.0 (1188) Plugin sentry Sentry Plugin disabled for this process because data reporting is disabled on instance 2024-04-17 14:02:02.032 - ^[[32minfo^[[39m: javascript.0 (1188) starting. Version 7.8.0 in /opt/iobroker/node_modules/iobroker.javascript, node: v18.20.2, js-controller: 5.0.19 2024-04-17 14:02:02.103 - ^[[34mdebug^[[39m: javascript.0 (1188) Loaded TypeScript definitions for node: ["node_modules/@types/node/package.json","node_modules/@types/node/index.d.ts","node_modules/@types/node/assert.d.ts","node_modules/@types/node/assert/strict.d.ts","node_modules/@types/node/globals.d.ts","node_modules/@types/node/async_hooks.d.ts","node_modules/@types/node/buffer.d.ts","node_modules/@types/node/child_process.d.ts","node_modules/@types/node/cluster.d.ts","node_modules/@types/node/console.d.ts","node_modules/@types/node/constants.d.ts","node_modules/@types/node/crypto.d.ts","node_modules/@types/node/dgram.d.ts","node_modules/@types/node/diagnostics_channel.d.ts","node_modules/@types/node/dns.d.ts","node_modules/@types/node/dns/promises.d.ts","node_modules/@types/node/domain.d.ts","node_modules/@types/node/dom-events.d.ts","node_modules/@types/node/events.d.ts","node_modules/@types/node/fs.d.ts","node_modules/@types/node/fs/promises.d.ts","node_modules/@types/node/http.d.ts","node_modules/@types/node/http2.d.ts","node_modules/@types/node/https.d.ts","node_modules/@types/node/inspector.d.ts","node_modules/@types/node/module.d.ts","node_modules/@types/node/net.d.ts","node_modules/@types/node/os.d.ts","node_modules/@types/node/path.d.ts","node_modules/@types/node/perf_hooks.d.ts","node_modules/@types/node/process.d.ts","node_modules/@types/node/punycode.d.ts","node_modules/@types/node/querystring.d.ts","node_modules/@types/node/readline.d.ts","node_modules/@types/node/readline/promises.d.ts","node_modules/@types/node/repl.d.ts","node_modules/@types/node/sea.d.ts","node_modules/@types/node/stream.d.ts","node_modules/@types/node/stream/promises.d.ts","node_modules/@types/node/stream/consumers.d.ts","node_modules/@types/node/stream/web.d.ts","node_modules/@types/node/string_decoder.d.ts","node_modules/@types/node/test.d.ts","node_modules/@types/node/timers.d.ts","node_modules/@types/node/timers/promises.d.ts","node_modules/@types/node/tls.d.ts","node_modules/@types/node/trace_events.d.ts","node_modules/@types/node/tty.d.ts","node_modules/@types/node/url.d.ts","node_modules/@types/node/util.d.ts","node_modules/@types/node/v8.d.ts","node_modules/@types/node/vm.d.ts","node_modules/@types/node/wasi.d.ts","node_modules/@types/node/worker_threads.d.ts","node_modules/@types/node/zlib.d.ts","node_modules/@types/node/globals.global.d.ts"] 2024-04-17 14:02:02.126 - ^[[34mdebug^[[39m: javascript.0 (1188) Loaded TypeScript definitions for request: ["node_modules/@types/request/package.json","node_modules/@types/request/index.d.ts"] 2024-04-17 14:02:02.622 - ^[[32minfo^[[39m: javascript.0 (1188) requesting all states 2024-04-17 14:02:02.625 - ^[[32minfo^[[39m: javascript.0 (1188) requesting all objects

Version of nodejs

5.0.19

Version of ioBroker js-controller

v18.20.2

Version of adapter

v7.8.0

Helmut1965 commented 5 months ago

Some colleagues try to reproduce this on there system, they was not able to do so, so I close this here for now and some more investigation of the configuration to find out what cause the problem