[addons] Less debug log entries when accessing settings #17822

matthuisman · 2020-05-08T01:10:02Z

Description

If there is a service add-on running a loop that accesses the addon settings, it can quickly fill up the debug log with essentially non-helpful messages.

"failed to find definition for setting {}. Creating a setting on-the-fly..."
This shows if the add-on has removed a setting but the user still has that setting in their userdata.
They can't do anything about that and neither can the author. So can we stop logging about it?

"CSettingsManager: requested setting ({}) was not found" is still logged when a setting isn't actually in the settings.xml but tried to access via the add-on.

"loading setting values"
Do we need to know this? - it logs if this fails anyway.

"loading setting definitions"
Same as above.

Yes, its only debug messages.
But users use debug log to find issues.
So the less "bloat" of unneeded messages - the easier to find their issue.

Motivation and Context

How Has This Been Tested?

Screenshots (if appropriate):

Types of change

Bug fix (non-breaking change which fixes an issue)
Clean up (non-breaking change which removes non-working, unmaintained functionality)
Improvement (non-breaking change which improves existing functionality)
New feature (non-breaking change which adds functionality)
Breaking change (fix or feature that will cause existing functionality to change)
Cosmetic change (non-breaking change that doesn't touch code)
None of the above (please explain below)

Checklist:

My code follows the Code Guidelines of this project
My change requires a change to the documentation, either Doxygen or wiki
I have updated the documentation accordingly
I have read the Contributing document
I have added tests to cover my change
All new and existing tests passed

garbear

If log spam is identified in a loop, then removing it makes usually sense.

matthuisman · 2020-05-08T21:18:32Z

Back port to Leia possible?
I can PR for that?

enen92 · 2020-05-08T21:33:16Z

xbmc/addons/settings/AddonSettings.cpp

@@ -683,8 +676,6 @@ std::shared_ptr<CSettingCategory> CAddonSettings::ParseOldCategoryElement(uint32

 bool CAddonSettings::InitializeFromOldSettingDefinitions(const CXBMCTinyXML& doc)
 {
-  m_logger->debug("trying to load setting definitions from old format...");


Maybe keep this one and encourage add-on developers to migrate to the new settings format? If we remove this on v20 we should probably advise in v19

Is there anywhere the warning could go that only shows once per addon call? Currently it shows every time a setting is read.

I think still best to remove. As having it puts it in all users logs (not just devs). An addon dev should be familiar with changes and be reading the forum posts in regards to depreciations etc. Eg. There is no warning in 18 about python2 being depreciated in 19? But most addon devs I'm sure are quite aware by now

It should only show when loading the settings for an add-on. It shouldn't show on every access to the setting from the same script. Otherwise something else is wrong. But I agree that it is logged out too often especially for non-service add-ons. But for debugging setting issues it's still important information to know that Kodi tries to load old style settings.

So if we can find a way to show it once for every add-on with settings that's ok with me.

Ill double check when it's getting logged.

Could leave in 19 and remove from 18 (if back port)?

Maybe keep this one and encourage add-on developers to migrate to the new settings format?

are there any guidelines?
the last time i made a conversion (last year) attempt i noticed a lack of ability to run "actions" with python add-on

I see this logged all the time and my addons use the new setting format. Does it default to checking the old format first?

For add-ons using the old settings style logging should look like this:

loading setting definitions trying to load setting definitions from old format...

For add-ons using the new settings style logging should look like this:

loading setting definitions

Apologies, you are correct. I had mixed up Leia (old settings) vs Matrix (new settings).

Rechi · 2020-05-09T09:38:50Z

xbmc/addons/settings/AddonSettings.cpp

@@ -684,7 +677,7 @@ std::shared_ptr<CSettingCategory> CAddonSettings::ParseOldCategoryElement(uint32
 bool CAddonSettings::InitializeFromOldSettingDefinitions(const CXBMCTinyXML& doc)
 {
  m_logger->debug("trying to load setting definitions from old format...");
-
+  


Please remove the white space at the end of the line.

oops, my editor adds that on new lines.
Removed now

@matthuisman any chance you want to quickly fix this up so we can get it merged when you have some time.

The whitespace? It is already fixed :)

@fuzzard oops - your right - now should be fixed 👍

cheers mate. ill merge it when jenkins finishes

KarellenX · 2020-05-10T20:17:20Z

Thanks @matthuisman I have raised this log spam issue a number of times previously. Will make the logs easier to read and smaller for the paste sites.

matthuisman · 2020-05-10T21:22:36Z

another thing I need to look into

$ADDON[addon_id 32035] doesn't work for lvalues in settings.xml
Maybe does in new settings though?

I reuse a lot of settings / language strings from a common add-on.
Nice not having to duplicate language strings between them.

Trying to keep a single add-on code working over all kodi versions is getting tricky.
I think the settings.xml changes will break that :(

Be nice if we could ship a settings.old.xml or something to keep backwards compatible :)

phunkyfish

@matthuisman I think the statement you are removing is primarily printed when you have a setting in your settings.xml which is not used by the addon. The logging is verbose if you have extra unused settings. But then maybe it should be.

I only see the settings loaded one time in the log in matrix.

matthuisman · 2020-05-10T21:33:14Z

it shows if you had a setting in the userdata settings.xml but not in the addons setting.xml
eg. an old setting that has been removed by the add-on author.

You can test by just adding a setting in settings.xml
Go into add-on and set it.
Then remove that setting from the settings.xml

we should be able to remove old settings and not spam the log?
If the setting is no longer in the addons setting.xml - it should be removed from the userdata?

phunkyfish · 2020-05-10T21:36:42Z

I thinks that’s reasonable. And maybe create a backup and then remove the older settings. At least the user still has access to the data then.

matthuisman · 2020-05-10T22:19:03Z

addons shouldn't be manually editing the userdata settings.xml and having to parse xml to remove old settings?

Its fine if that old setting sits there - but it shouldn't start spamming the log.
There is nothing the user / developer can do about it - so why warn about it?

If a setting is in userdata settings.xml and not in add-on settings.xml - then it should just ignore it.

For the user to get rid of that message, they need to manually open the userdata settings.xml and remove the entry for that old setting. Thats not very friendly?

I think the main problem is the verobosity of the logging.
Debug logging in Kodi should probably be actually a higher up level

If the addon tries to get a setting that doesn't exist anymore, we still get the
"CSettingsManager: requested setting ({}) was not found" log message - which is fine.

Montellese · 2020-05-11T04:29:19Z

another thing I need to look into

$ADDON[addon_id 32035] doesn't work for lvalues in settings.xml
Maybe does in new settings though?

I don't think that will work since I didn't even know it was possible.

Montellese · 2020-05-11T04:32:08Z

it shows if you had a setting in the userdata settings.xml but not in the addons setting.xml
eg. an old setting that has been removed by the add-on author.

You can test by just adding a setting in settings.xml
Go into add-on and set it.
Then remove that setting from the settings.xml

we should be able to remove old settings and not spam the log?
If the setting is no longer in the addons setting.xml - it should be removed from the userdata?

IIRC the reason I added this log message in the first place was because someone pointed out that with the old settings it must be possible to create settings which don't exist in the add-on's settings.xml. Back then I didn't think that this was a good idea (what do we have settings.xml for then?) so I added this log. But it seems like this also happens when removing a previously existing setting from settings.xml which is a perfectly valid use case.

matthuisman · 2020-05-11T04:38:58Z

I don't think that will work since I didn't even know it was possible.

Yeh, I only found you could do it for most of the labels the other day.
Was pretty happy with that (I hate duplication)
Especially with language strings - as they can have translations.
So nice to reuse the common strings if possible.
Be nice if it worked everywhere though.
Surely we could pipe the lvalues through the same code that the label goes through to get the same behaviour. I can take a look :)

You still get the "CSettingsManager: requested setting ({}) was not found" if you try to access a setting that isn't in the settings.xml. Thats fine. That tells the dev - oh, I better add in the setting

fuzzard · 2020-08-27T00:06:26Z

@Montellese You ok with this to merge in its current state?

fuzzard

Doesn't show as fixed, did you push it?

… settings

phunkyfish · 2020-08-27T09:01:07Z

jenkins build this please

phunkyfish requested a review from Montellese May 8, 2020 08:54

phunkyfish added v19 Matrix Component: Settings Component: Logging Type: Cleanup non-breaking change which removes non-working or unmaintained functionality labels May 8, 2020

garbear approved these changes May 8, 2020

View reviewed changes

enen92 reviewed May 8, 2020

View reviewed changes

Rechi reviewed May 9, 2020

View reviewed changes

phunkyfish reviewed May 10, 2020

View reviewed changes

z3ntu mentioned this pull request Jun 17, 2020

Cannot load settings from kodi jellyfin/jellyfin-kodi#116

Closed

Montellese approved these changes Aug 27, 2020

View reviewed changes

fuzzard reviewed Aug 27, 2020

View reviewed changes

these log messages can quickly fill a debug log if accessing multiple…

5537272

… settings

fuzzard added this to the Matrix 19.0-alpha 2 milestone Aug 27, 2020

fuzzard merged commit bc01e01 into xbmc:master Aug 27, 2020

matthuisman deleted the quiet_addon_settings branch September 3, 2020 21:10

piejanssens mentioned this pull request Apr 6, 2021

What is Yelo doing here every 10s? add-ons/plugin.video.yelo#42

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[addons] Less debug log entries when accessing settings #17822

[addons] Less debug log entries when accessing settings #17822

matthuisman commented May 8, 2020 •

edited

Loading

garbear left a comment

matthuisman commented May 8, 2020

enen92 May 8, 2020

matthuisman May 8, 2020 •

edited

Loading

Montellese May 8, 2020

matthuisman May 8, 2020

CastagnaIT May 9, 2020

phunkyfish May 10, 2020

Montellese May 10, 2020

phunkyfish May 10, 2020

Rechi May 9, 2020

matthuisman May 9, 2020

fuzzard Aug 27, 2020

matthuisman Aug 27, 2020

matthuisman Aug 27, 2020

fuzzard Aug 27, 2020

KarellenX commented May 10, 2020 •

edited

Loading

matthuisman commented May 10, 2020 •

edited

Loading

phunkyfish left a comment

matthuisman commented May 10, 2020

phunkyfish commented May 10, 2020

matthuisman commented May 10, 2020 •

edited

Loading

Montellese commented May 11, 2020

Montellese commented May 11, 2020

matthuisman commented May 11, 2020

fuzzard commented Aug 27, 2020

fuzzard left a comment

phunkyfish commented Aug 27, 2020

[addons] Less debug log entries when accessing settings #17822

[addons] Less debug log entries when accessing settings #17822

Conversation

matthuisman commented May 8, 2020 • edited Loading

Description

Motivation and Context

How Has This Been Tested?

Screenshots (if appropriate):

Types of change

Checklist:

garbear left a comment

Choose a reason for hiding this comment

matthuisman commented May 8, 2020

Choose a reason for hiding this comment

matthuisman May 8, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

KarellenX commented May 10, 2020 • edited Loading

matthuisman commented May 10, 2020 • edited Loading

phunkyfish left a comment

Choose a reason for hiding this comment

matthuisman commented May 10, 2020

phunkyfish commented May 10, 2020

matthuisman commented May 10, 2020 • edited Loading

Montellese commented May 11, 2020

Montellese commented May 11, 2020

matthuisman commented May 11, 2020

fuzzard commented Aug 27, 2020

fuzzard left a comment

Choose a reason for hiding this comment

phunkyfish commented Aug 27, 2020

matthuisman commented May 8, 2020 •

edited

Loading

matthuisman May 8, 2020 •

edited

Loading

KarellenX commented May 10, 2020 •

edited

Loading

matthuisman commented May 10, 2020 •

edited

Loading

matthuisman commented May 10, 2020 •

edited

Loading