Linknx / Discussion / Open Discussion: logging - some changes in what is logged

I think for better debugging some changes to logging could be done. Take this example:

1) What lacks here is the information on which rule was triggered for evaluation, and how it was evaluated. This is even more important to which values were compared to which. I would suggest something like this:

1292875828 INFO Object : New value on for object kuchnia_wyspa (type: 1.001)
1292875828 INFO Object : New value on for object kuchnia_wyspa_S (type: 1.001)
1292875828 INFO SwitchingObject : SwitchingObject (id=kuchnia_stol_S): Compare value_m='1' to value='1'
1292875828 INFO Rule: Triggered rule 'kuchnia_kinkiet_auto"
1292875828 INFO Condition : ObjectCondition (id='kuchnia_stol_S') evaluated as '1'
1292875828 INFO SwitchingObject : SwitchingObject (id=kuchnia_stol_S): Compare value_m='1' to value='1'
1292875828 INFO Condition : ObjectCondition (id='kuchnia_stol_S') evaluated as '1'
1292875828 INFO SwitchingObject : SwitchingObject (id=kuchnia_wyspa_S): Compare value_m='1' to value='1'
1292875828 INFO Condition : ObjectCondition (id='kuchnia_wyspa_S') evaluated as '1'
1292875828 INFO SwitchingObject : SwitchingObject (id=kuchnia_wyspa_S): Compare value_m='1' to value='1'
1292875828 INFO Condition : ObjectCondition (id='kuchnia_wyspa_S') evaluated as '1'
1292875828 INFO SwitchingObject : SwitchingObject (id=kuchnia_stol_S): Compare value_m='1' to value='1'
1292875828 INFO Condition : ObjectCondition (id='kuchnia_stol_S') evaluated as '1'
1292875828 INFO SwitchingObject : SwitchingObject (id=kuchnia_stol_S): Compare value_m='1' to value='1'
1292875828 INFO Condition : ObjectCondition (id='kuchnia_stol_S') evaluated as '1'
1292875828 INFO Rule: condition for rule ''kuchnia_kinkiet_auto" evaluated as true
1292875828 INFO Action : Execute SetValueAction with value on
1292875828 INFO KnxConnection : write(gad=8963, buf, len=2):
1292875828 INFO Object : New value off for object jadalnia_kinkiety (type: 1.001)
1292875828 INFO Object : New value off for object jadalnia_kinkiety_S (type: 1.001)

I would even go further. At INFO level I would only include the rules level, and at deeper DEBUG level I would include specific value comparisons in the log.

2) in the lines like:

1292875828 INFO Action : Execute SetValueAction with value on

there is no information on which object the action is performed. It should be:

1292875828 INFO Action : Execute SetValueAction for object "kuchnia_okap" with value on

3) in the lines like:

1292875828 INFO KnxConnection : write(gad=8963, buf, len=2):

the gad should be decoded into human understandable form of "4/3/1". I dont expect errors in code in this part of the code which is translating gads, but instead seing what gad is actually written is quite useful. I have created excel sheet for translation but it is making debugging more complicated. This is also usefull for debugging false gad's. You can clearly see that there is a visible delay after writes to wrong addresses in attempt to read their values.

4) In the lines like:

1292875820 INFO Rule : ActionList: Configuring ''

I don't know what should be included between ' signs. Probably rule name is missing here:

1292875820 INFO Rule : ActionList: Configuring for rule 'kuchnia_kinkiet_auto'

5) Every while in the logs there are lines like:

Send request
Read from 0.0.0 to 9/1/150
Send request
Response from 0.0.0 to 9/1/150: 00 00 00
Send request
Read from 0.0.0 to 4/2/2
Send request

I presume this is summarising the KNX bus transfers for the past xxx transmissions. I am not sure what 0.0.0 means. Shoud it be 0/0/0 ? Also timestamps are missing and other indicators which would help filtering in or filtering out those dumps. Or at least It could contain some header that KNX transmission log follows ….. KNX transmission dump end.

There is last <cr> missing and the end of the dump looks like:

Read from 0.0.0 to 4/3/8
Send request
Read from 0.0.0 to 41292875865 INFO Object : New value 1 for object kuchnia_przycisk_off (type: 5.xxx)
1292875865 INFO UIntObject : UIntObject (id=kuchnia_przycisk_off): Compare value_m='1' to value='1'

You can see that the first regular log entry is appended to last KNX dump line.

Ufffff. That's it regarding logging.

Yours

Damago1

logging - some changes in what is logged

Forums

Help

logging - some changes in what is logged

logging - some changes in what is logged

Forums

Help

logging - some changes in what is logged document.SUBSCRIPTION_OPTIONS = { "thing": "topic", "subscribed": false, "url": "subscribe", "icon": { "css": "fa fa-envelope-o" } };

logging - some changes in what is logged