victronenergy / dynamic-ess

MIT License
90 stars 7 forks source link

[Bug]: "Error: Data: NaN was not a number" caused by node Schedule 0 to 4: soc #107

Closed andreashackel closed 1 year ago

andreashackel commented 1 year ago

Contact Details

ankawe@gmx.net

VRM portal ID

c0619ab1433b

Country / region

Germany (de)

B max

10.5

TB max

3.5

FB max

4

TG max

0

FG max

3.5

Battery costs

0.05

Buy price

(p+0.00+0.15)*1.19

Sell price

(0.122)*1.19

feed-in possible

None

feed-in control

no

Version

0.1.7

What happened?

Since the installation of version 0.1.7, every day after midnight msg.soc has the value NaN and leads to a message in the debug tab. In the morning there is no error message. My guess is that the error only occurs at hour 0. When I restart Node Red, the error is gone. The screenshot below shows the error situation. For schedule 0 I fixed the error in the 'My extension' function. grafik

When did it happen?

Every day after midnight.

Relevant log output

No response

Screenshots

![DESCRIPTION](LINK.png)
dirkjanfaber commented 1 year ago

It would be interesting to see what the context variable dess.output.SOC contains around that time.

dirkjanfaber commented 1 year ago

Btw I do advise to upgrade to 3.11 (which fixes a few things related to dynamic ESS).

andreashackel commented 1 year ago

After updating to version 3.11, the error still occurs.

dess.output.SOC before NaN occurs:

18.10.2023, 00:00:02[node: debug 25]Schedule 0 : msg : Object
object
topic: "Schedule 0"
soc: 55
feed_in: 0
duration: 3600
start: 1697580000
_msgid: "3d0848543651ce0a"
_event: "node:0a258a4a88409834"
my_dess: object
site: 220168
output: object
from_b: object
to_b: object
from_g: object
to_g: object
b: object
g: object
B: object
SOC: object
0: 34
1: 33
2: 33
3: 33
4: 32
5: 32
6: 26
7: 19
8: 16
9: 15
10: 27
11: 45
12: 63
13: 94
14: 99
15: 99
16: 97
17: 98
18: 94
19: 87
20: 80
21: 73
22: 65
23: 38
24: 55
25: 55
26: 55
27: 55
28: 50
29: 44
30: 36
31: 29
32: 23
33: 19
34: 15
35: 20
36: 22
37: 22
38: 35
39: 40
40: 43
41: 41
42: 31
43: 18
44: 10
45: 10
46: 10
47: 10
C: object
PV: object
p_b: object
p_s: object
g_cost: object
b_cost: object
cost: object
gsmm: object
idle_b: object
feed_in: object
p: object
utc_time: object
schedule: object
warnings: array[0]
options: object
parsed: object
average_price: 0.31449840625000003
price_compared_to_average: "above"
price_offset_percentage: 0.050308025209586965
negative_price: false

The first occurrence of the error:

18.10.2023, 00:03:35[node: debug 27 ]Schedule 0 : msg : Object
{ topic: "Schedule 0", soc: NaN, feed_in: 0, duration: 3600, start: 1697580000 … }
18.10.2023, 00:03:36[node: Schedule 1: soc](https://192.168.178.125:1881/)msg : error
"Error: Data: NaN was not a number"
18.10.2023, 00:03:37[node: Schedule 2: soc](https://192.168.178.125:1881/)msg : error
"Error: Data: NaN was not a number"
18.10.2023, 00:03:38[node: Schedule 3: soc](https://192.168.178.125:1881/)msg : error
"Error: Data: NaN was not a number"
18.10.2023, 00:03:39[node: debug 25] Schedule 0 : msg : Object
object
topic: "Schedule 0"
soc: NaN
feed_in: 0
duration: 3600
start: 1697580000
_msgid: "2666036458bf6b9c"
_event: "node:0a258a4a88409834"
my_dess: object
site: 220168
output: object
from_b: object
to_b: object
from_g: object
to_g: object
b: object
g: object
B: object
SOC: object
0: 55
1: 55
2: 55
3: 55
4: 50
5: 44
6: 36
7: 29
8: 23
9: 19
10: 15
11: 20
12: 22
13: 22
14: 35
15: 40
16: 43
17: 41
18: 31
19: 18
20: 10
21: 10
22: 10
23: 10
C: object
PV: object
p_b: object
p_s: object
g_cost: object
b_cost: object
cost: object
gsmm: object
idle_b: object
feed_in: object
p: object
utc_time: object
schedule: object
warnings: array[0]
options: object
parsed: object
average_price: 0.2956490541666666
price_compared_to_average: "below"
price_offset_percentage: -0.035680324418423524
negative_price: false

The last time the error was shown in the debug tab was 18.10.2023, 00:54:02 and at 18.10.2023, 01:00:01 the error was cleared.

(Edited for readability)

dirkjanfaber commented 1 year ago

Thanks for the info. I am still overlooking the real cause of the problem (and am not that anxious to stay awake late to do the actual debugging during the week). So I've added extra logging on one of my test systems, which I can check tomorrow. To be continued.

dirkjanfaber commented 1 year ago

I forgot to extend the amount of logging the process can do. Adjusted that, so we'll have to wait another day for workable data.

dirkjanfaber commented 1 year ago

Well, that turned out to be an off-by-one error of indexes in arrays vs their length. Anyway, I'll create a new release later today, fixing this and also adding an extra example. Thanks for reporting!