dzVents: Logfile has less info Topic is solved

[Kedi]

Logging before 2024.5 was like:

Code: Select all

2024-07-06 21:31:00.545  Status: dzVents: Info: VWH: ------ Start external script: verwarming wand.lua:, trigger: "at *:31 between 10:00 and 22:00"
2024-07-06 21:31:00.546  Status: dzVents: Info: VWH: ------ Finished verwarming wand.lua

Here you could see that the script has been running and how long it took to run.
Now the logging is only and always the same:

Code: Select all

Status: EventSystem: Script event triggered: /home/pi/domoticz/dzVents/runtime/dzVents.lua

The above 2 lines of start and finish could be pressed in 1 line, but it should contain the name of the script and trigger that ran.
But I prefer 2 lines so running time could be measured.

[gizmocuz]

That's not entirely correct as you can see from your logs.

The only time you see the duration of your logs is when this script took too much time to finish.
(Unless you count the time between the two log lines. which is like a millisecond for the script above)

Lots of things regarding dzVents logging has been changed.

LOG_INFO is now handled as normal internal info log messages
LOG_STATUS is now handled as normal internal status log messages
LOG_ERROR is now handled as normal internal staus log messages

LOG_DEBUG, is handled as info, but when you specify this log level in your script as minimum level, you will see the execution info.

I also added a dzVents 'Logging' example. (create a new dzVents script with the + button and choose the logging example)

I don't know how many scripts you have, or what the triggers are, but I have plenty!
Because I also have to handle P1 electric values which update every 5 seconds here, I get tons of log messages, even if the script itself is not doing anything, the -----start and ----finish are always shown.

For this reason, there is now also an option under Settings->Other->dzVents to specify the 'Log Level', default this is Info+Status+Errors+Exceution_Info, I have set this to Info,Status,Errors for now (and will set it to Status,Errors later.

If you want to log something in your script you add log lines (see the Logging example), and you can specify the minimum log level.
For instance if you set this to LOG_ERROR like

Code: Select all

logging = {
    level = domoticz.LOG_ERROR,
    marker = "my_script"
},

And you log something with

Code: Select all

dz.log('Hey, I'm a log line!!!')

Or

Code: Select all

		domoticz.log('INFO log line!', domoticz.LOG_INFO)
		domoticz.log('STATUS log line!', domoticz.LOG_STATUS)	

All these messages are not displayed

This is displayed:

Code: Select all

domoticz.log('ERROR log line!', domoticz.LOG_ERROR)

If you do not specify a log level, the status will be domoticz.LOG_INFO

If you want to debug your start/finished or other debug lines, set the level to domoticz.LOG_DEBUG

You can also always force a log with domoticz.LOG_FORCE

[waltervl]

And set in menu setup - settings, tab other, the dzVents logging to including execution info.

Edit: also play with the new dzvents logging template.

[Kedi]

I prevent massive logging of the P1 meter by disable info logging on the hardware of P1 Smart Meter USB.
I tried several logging settings, but I stand with my comment that the line with "/home/pi/domoticz/dzVents/runtime/dzVents.lua" is useless.
And I kindly ask you to replace that at least with the name of the script that starts or ends the run.
Currently I have no clue from the logging what script is running at what time.
And if I want timing of the script running, I will take care of that myself in the future in the script. Pity that that has gone.

[willemd]

I agree a useful message has been replaced by a useless message:
It used to be :
Status: dzVents: Info: energy cost calc: ------ Start internal script: energy cost calc: Device: "Electricity P1 meter (Homewizard P1 meter)", Index: 1
and now it is
Status: EventSystem: Script event triggered: /home/pi/domoticz/dzVents/runtime/dzVents.lua
which is the same for every script triggered. Totally useless.

From the anwer it is not clear how I can get the usefull message back.
Do I understand correctly that I have to put my own log message in every single script now ?
And if I have to put in my own log statement in the script, how can I then suppress the useless message? I tried different logging settings but these useless messages are still there.

I normally use

Code: Select all

	
	logging = {
		level = domoticz.LOG_INFO,
		marker = 'energy cost calc',
	},

to ensure that the run-trigger is in the log file
and then use specific log statements if I want other internal script info or values to be logged as well.

[waltervl]

You can set the basic dzvents logging level in menu setup - settings, tab other.

If you want to deviate from that default logging level add the log level setting in the script. If no log level setting in the script it will take the default log level.

[waltervl]

Code: Select all

 --This example shows you how to work with various log levels
--
-- The script is triggered by a dummy switch called 'test'
--
-- when no log level is specified, the level is taken from the default application settings (dzVents)
--
-- when you specify LOG_STATUS as minimum log level, no logs will be displayed when using LOG_INFO or LOG_DEBUG
--
-- Order is: LOG_DEBUG, LOG_INFO, LOG_STATUS, LOG_ERROR
--
-- LOG_DEBUG will also cause Execution Info to be displayed (start/finished)
--
return {
	on = {
		devices = {
			'test'
		}
	},
	logging = {
		marker = 'log_script',
		level = domoticz.LOG_DEBUG
	},
	execute = function(domoticz, device)
		domoticz.log('INFO log line!', domoticz.LOG_INFO)
		domoticz.log('STATUS log line!', domoticz.LOG_STATUS)
		domoticz.log('ERROR log line!', domoticz.LOG_ERROR)
		domoticz.log('DEBUG log line!', domoticz.LOG_DEBUG)
	end
}

Also check the default setting in menu Setup - Settings, tab Other

Screenshot_20240708-013833.png (45.55 KiB) Viewed 2058 times

[McMelloW]

@Waltervl.
Thanks for this example log-script, very helpful

[waltervl]

This log test script is the new template you can choose to when creating a new dzvents script in the event editor. Credits go to @gizmocuz....

[Kedi]

That test/demo log script is clear to me and the changes too. And it works OK too.
BUT I stand by my remark that that line is useless, and it would be nice to have at least 1 line back which states which script is triggered and by what trigger.
The LOG_DEBUG it self is far too much logging.

[janpep]

Finnaly I had the logging in a logical way as I wanted it.
Just (gereral) INFO, when I wanted it. And more DEBUG information when set to DEBUG and always the errors (general setting).

So, curious and full of fear I immediately went to the example script.
- With level set to INFO, I get STATUS log line! + ERROR log line!
- With level set to STATUS, I get STATUS log line! + ERROR log line!
- With level set to DEBUG, I get STATUS log line! + ERROR log line!

The effect of all my existing log settings now seems to be reduced to:

Code: Select all

2024-07-07 21:30:04.473 Status: EventSystem: Script event triggered: /path-to/domoticz/dzVents/runtime/dzVents.lua

I think I am going crazy. What goes wrong here?

Perhaps it is very clear if you have already been working on it to make it this way. But I think these kind of changes could better be introduced 'a little' more, so that you realize that you have to figure out a lot again and do a lot again when you perform this update!

[waltervl]

I think I am going crazy. What goes wrong here?

Check your dzvents global logging settings at menu Setup -Settings, tab Other. But for me it all works as expected.

Screenshot_20240708-013833.png (45.55 KiB) Viewed 2056 times

[HansieNL]

If I add domoticz.log('FORCE log line!', domoticz.LOG_FORCE) to the test script and switch off/on the switch I don't see the line in the log.
Am I missing something or should I see the line?

[Kedi]

No, you are not missing something. I have the same. That line is not logged.

[gizmocuz]

@Kedi, I have to guess that message you see was always present, as I did not add any additional logging.
And what is LOG_DEBUG showing you 'more' than was previously not there? It should display everything (info/status/error, internal exec info)
Use this when you are creating a script, when finished set it to something else

I and Walter asked several times now to select a specific log level in the application settings and no one mentioned if they specified this level.
Without this it is hard to debug the issue.

There is also another setting 'Log event script triggers', is that enabled or disabled?

When you did that, and you used the supplied 'Logging' example, did that work correctly?

Is this with a dzVents script, or Lua or Python?

If it is a Lua or Python plugin, could you post a small example to test against (I only work with dzVents/Blockly)

Did you compile Domoticz yourself or are you using the binary? (Just making sure it is not compiled in Debug mode)

[Kedi]

Yes, that message was always present, but it is now the only message.
Big domoticz log files, don't bother me. My log is every day between 15-20 Mb (it is on a tmpfs), but I use logrotate every day.
I did use several times different settings in Setup -> Settings -> Other
My favorite setting is the setting: Info, Status, Errors, Execution Info as a default.
90 % of my scripts are dzVents, and I am talking about dzVents scripts here are 'external' scripts in /home/pi/domoticz/scripts/dzVents/scripts
In every dzVents script I have:

Code: Select all

    logging =
    {   marker = 'AutoOff',
        level = domoticz.LOG_INFO,
--      level = domoticz.LOG_DEBUG,
    },

So I could quickly switch to DEBUG if needed ( marker is of course different in every script )
I am under the impression that that should give me the info I need.
The rest (internal dzVents) is working as described. But that is not the problem it is the info that is missing.
And I really mis info which script was triggered and what the trigger was.
I used the Internal Logging example -> FORCE is missing.
I did not compile myself, it was the original 2024.5 version.

[gizmocuz]

Finnaly I had the logging in a logical way as I wanted it.
Just (gereral) INFO, when I wanted it. And more DEBUG information when set to DEBUG and always the errors (general setting).

So, curious and full of fear I immediately went to the example script.
- With level set to INFO, I get STATUS log line! + ERROR log line!
- With level set to STATUS, I get STATUS log line! + ERROR log line!
- With level set to DEBUG, I get STATUS log line! + ERROR log line!

The effect of all my existing log settings now seems to be reduced to:

Code: Select all

2024-07-07 21:30:04.473 Status: EventSystem: Script event triggered: /path-to/domoticz/dzVents/runtime/dzVents.lua

I think I am going crazy. What goes wrong here?

Perhaps it is very clear if you have already been working on it to make it this way. But I think these kind of changes could better be introduced 'a little' more, so that you realize that you have to figure out a lot again and do a lot again when you perform this update!

I guess your previous Domoticz update was ~6 months ago?

Previously all script logging (Info, Status, Error, Debug) where all displayed as 'Info' in the real Domoticz log(file/window), now these are really handled as they should be, Status script messages as logged as status, errors as errors.
Yahooo... great! Thanks team!

Second issue, having a system myself with lots of dzVents scripts that where being 'triggered' every 5 seconds was flooding the log with tens of -----start / ----finished log messages a minute.
Scripts where being called but nothing needed to be done internally (if/then/else checks) so this was needless to log these 'LOG_MODULE_EXEC_INFO' messages.
If something was needed to be done in my scripts and I want a log message, I added a log line.

So, the idea rose to have a global way of turning this off. Hence the new Log Levels in the application settings. The default level (when you install Domoticz new) is still Info+Status+Error+Exec_Info. It is possible some users did change this level previously and they experience a different log level.

But still, if you set this to Status+Error, you can override this in your script

This is also explained in the dzVents manual that can be found on our WIKI (logging = { … } (optional))

And this is also why a new example template is available called 'Logging' that you can use as tutorial.

The idea is to remove/mark all "logging = { … } (optional)" in your scripts when the script is finished so the application default level will apply.
When you need extensive script logging you can use LOG_DEBUG there

[waltervl]

With default log level in settings
info,status,error,execution info
and no log level defined I get below with the test script.

When I set LOG_INFO in the script I get no execution lines (as expected)

Code: Select all

 2024-07-08 08:10:55.976 Status: User: admin (IP: 192.168.1.58) initiated a switch command (107/Test/On)
2024-07-08 08:10:55.979 Dummy: Light/Switch (Test)
2024-07-08 08:10:56.007 dzVents: Handling events for: "Test", value: "On"
2024-07-08 08:10:56.007 dzVents: log_script: ------ Start internal script: logging_test: Device: "Test (Dummy)", Index: 107
2024-07-08 08:10:56.007 dzVents: log_script: INFO log line!
2024-07-08 08:10:56.007 Status: dzVents: log_script: STATUS log line!
2024-07-08 08:10:56.007 Error: dzVents: log_script: ERROR log line!
2024-07-08 08:10:56.007 dzVents: log_script: ------ Finished logging_test 

[gizmocuz]

If I add domoticz.log('FORCE log line!', domoticz.LOG_FORCE) to the test script and switch off/on the switch I don't see the line in the log.
Am I missing something or should I see the line?

Sorry about that, your right! This has been corrected now in the latest stable/beta version.

[Kedi]

I understand that it is a done case.
But please remove the line, it makes no sense.

Code: Select all

Status: EventSystem: Script event triggered: /home/pi/domoticz/dzVents/runtime/dzVents.lua