@wojtek This could be done by the reload of a server configuration which we have planned. Do we want anything else? or should we just check if config reload works?

I'd say the idea was to use reloading of configuration. Can we do it partially (i.e. only for mentioned Logging bean)?

@wojtek No, it is possible only to apply a new config as a whole.

In that case I'm not sure we should follow that path (could you say with 100% certainty that changing log level that way would not cause reinitialising for example connection managers)? LoggingBean was just a suggestion. I looked at it and LogManager it's using and it seems it doesn't let flexible addition/removal of loggers so this may complicate things.

On the other hand, we should be able to use logback via slf4j/jul bridge, which allows dynamic adjustment of log configuration (with the downside that it requires shell access for it but that's less of an issue).

Bottomline, I'm leaning towards "won't fix" here, unless you see a sensible solution (ideally without reloading configuration of the whole server).

@wojtek LoggingBean could reload (reconfigure) LogManager and it should work. As for not reloading and reinitializing connection managers, kernel will not create a new instance of a bean if it was already initialized. It will reuse it and apply a new configuration if it will detect that value was changed (AFAIR).

should work :-)

I'm just being cautions in the context of production installations - if we could be 100% certain that this would only reconfigure LogManager and wouldn't affect the rest (only update configuration at best) then this is OK.

I cannot make that guarantee as we have not tested reloading of the configuration.

I cannot make that guarantee as we have not tested reloading of the configuration.

Your first comment finished with: "Do we want anything else? or should we just check if config reload works ?" - so checking if it works seems to be enough?

Though, I'd lean more towards more pin-pointed approach and directly changing LogManager configuration via LoggerBean.

@wojtek I suppose we could "extend" LoggerBean and access it from some ad-hoc command or REST API. This would allow us to modify LogManager settings via LoggerBean while we would not reload configuration. However, I would like to use (internally) the same methods as kernel is using for configuration reload (setters in the LoggerBean). That would confirm that configuration changes from the config file would work as well.

As said during the call: that seems ok, and on top of that REST handler that access LoggerBean.

I've added support for reconfiguration at runtime using ad-hoc command. As we are exposing ad-hocs to the HTTP Admin UI and REST API that will allow us to used it in a flexible way.

To change logging, you have to:

1. Enter package name (full name with tigase. at the beginning)
2. Select logging level

I've prepared also a method in LoggingBean to retrieve current configuration for all configured packages but it is not used anywhere yet. It could easily used to present current configuration before user will change it. More difficult would be presentation of this data, and due to that I've decided not to do that at this point.

NOTE: Currently, we have debug, debugPackets and loggers which are all used to configure logging. At this point, for internal usage by the command, I've decided to remove any existing entry for particular package in any of those settings and just configure logging using loggers. This is done at runtime, so there is no negative impact. However, it would be nice to clean this up in 9.0.0, either by usage of Logback/SLF4J or just by changing those settings so that only one setting would be used at runtime, i.e. we could have just loggers map internally but at startup (and only then) we would collect settings from debug and debugPackets. Having all those settings cause a lot of interactions between them and may lead to the issues in the future.

I assume that disabling logging for particular package is done by configuring it with OFF? Would you mind adding documentation (both adhoc and rest) regarding changing log levels?

I completely agree on simplifying logger configuration. We probably won't have to explicitly use logback/slf4j given #issue #1211 (it's somewhat native JVM slf4j I'd say).

@wojtek Yes, disabling is done with OFF. I'll add documentation.

I completely agree on simplifying logger configuration. We probably won't have to explicitly use logback/slf4j given #issue #1211 (it's somewhat native JVM slf4j I'd say).

As I've mentioned, I do not care what logger we will use, but I would like to have those settings simplified in 9.0.0.

Resulting command doesn't contain (our) typical NOTE with some comment about execution status:

<iq type="set" id="ab0aa" to="message-router@atlantiscity">
<command xmlns="http://jabber.org/protocol/commands" node="logging-set">
<x xmlns="jabber:x:data" type="submit">
<field var="package-name" type="text-single">
<value>tigase.server</value>
</field>
<field var="level" type="list-single">
<value>FINEST</value>
</field>
</x>
</command>
</iq>

<iq type="result" id="ab0aa" to="admin@atlantiscity/1204607085-tigase-1" from="message-router@atlantiscity">
<command xmlns="http://jabber.org/protocol/commands" node="logging-set" status="completed">
<x xmlns="jabber:x:data" type="result"/>
</command>
</iq>

But more importantly - after executing above, no additional logging was produced in logs/tigase.log.*.

In my opinion having "Note" for success is pointless. Same as having an error with form being sent back describing an error - it should be XMPP stanza error with a text description. I would suggest to leave it without Note and in 9.0.0 rework ad-hoc commands to properly return errors with stanzas of type error and contain proper status which indicates that ad-hoc is still being executed or was completed. Moving those commands from Groovy to Java would be a good moment to do that.

I found an issue with reconfiguration of loggers already configured in config.tdsl file and fixed that.

OK, I tested it some more and... it doesn't work for me. But only if I specify tigase. subpackage without Class. So specifying tigase works, and specifying tigase.server.xmppsession.SessionManager works as well, but specifying tigase.server or tigase.io doesn't yield any effect. I added additional debug (was appropriate either way as it affects configuration) but it only added to the confusion. The configuration feed to the LogManager is correct (or at least looks like that):

[2020-10-02 20:11:53:434] [CONFIG  ] [  in_20-message-router ] LoggingBean.setPackageLoggingLevel(): Setting log level for package: tigase.server to ALL
[2020-10-02 20:11:53:438] [CONFIG  ] [  in_20-message-router ] LoggingBean.lambda$beanConfigurationChanged$23(): Setting log level for loggerName: tigase.kernel.core.Kernel to: {level=CONFIG}
[2020-10-02 20:11:53:438] [CONFIG  ] [  in_20-message-router ] LoggingBean.lambda$beanConfigurationChanged$23(): Setting log level for loggerName: tigase.server to: {level=ALL}
[2020-10-02 20:11:53:438] [CONFIG  ] [  in_20-message-router ] LoggingBean.lambda$beanConfigurationChanged$23(): Setting log level for loggerName: tigase to: {useParentHandlers=true}
[2020-10-02 20:11:53:443] [CONFIG  ] [  in_20-message-router ] LoggingBean.beanConfigurationChanged(): Initialised LogManager with configuration: .level=CONFIG
tigase.kernel.core.Kernel.level=CONFIG
tigase.server.level=ALL
tigase.useParentHandlers=true
java.util.logging.FileHandler.formatter=tigase.util.log.LogFormatter
java.util.logging.FileHandler.level=ALL
java.util.logging.FileHandler.count=5
java.util.logging.FileHandler.limit=10000000
java.util.logging.FileHandler.pattern=logs/tigase.log
java.util.logging.FileHandler.append=true
java.util.logging.ConsoleHandler.formatter=tigase.util.log.LogFormatter
java.util.logging.ConsoleHandler.level=WARNING
handlers=java.util.logging.ConsoleHandler java.util.logging.FileHandler

But nothing from tigase.server is logged.

Adding debug = [ 'server' ] to the TDSL configuration yields virtually same configuration:

[2020-10-02 20:18:39:783] [CONFIG  ] [                  main ] LoggingBean.lambda$beanConfigurationChanged$23(): Setting log level for loggerName: tigase.kernel.core.Kernel to: {
level=CONFIG}
[2020-10-02 20:18:39:784] [CONFIG  ] [                  main ] LoggingBean.lambda$beanConfigurationChanged$23(): Setting log level for loggerName: tigase to: {useParentHandlers=t
rue}
[2020-10-02 20:18:39:789] [CONFIG  ] [                  main ] LoggingBean.beanConfigurationChanged(): Initialised LogManager with configuration: .level=CONFIG
tigase.server.level=ALL
tigase.kernel.core.Kernel.level=CONFIG
tigase.useParentHandlers=true
java.util.logging.FileHandler.formatter=tigase.util.log.LogFormatter
java.util.logging.FileHandler.level=ALL
java.util.logging.FileHandler.count=5
java.util.logging.FileHandler.limit=10000000
java.util.logging.FileHandler.pattern=logs/tigase.log
java.util.logging.FileHandler.append=true
java.util.logging.ConsoleHandler.formatter=tigase.util.log.LogFormatter
java.util.logging.ConsoleHandler.level=WARNING
handlers=java.util.logging.ConsoleHandler java.util.logging.FileHandler

Which works just fine.

I'll check it also with the next nightly, but I'd blame it on the JUL weirdness and the feature itself working.

In my opinion having "Note" for success is pointless. Same as having an error with form being sent back describing an error - it should be XMPP stanza error with a text description. I would suggest to leave it without Note and in 9.0.0 rework ad-hoc commands to properly return errors with stanzas of type error and contain proper status which indicates that ad-hoc is still being executed or was completed. Moving those commands from Groovy to Java would be a good moment to do that.

Agreed. AFAIR I tried to return proper errors for ad-hocs in the past but reverted the change because... quite a lot of clients weren't able to handle it properly (Psi, I'm looking at you!). Let's not be hold back by those (and at the most report that to the developers). This should also simplify/make more sane REST API.

Discussion split out to: #issue #1214

Just an idea, maybe we should follow and idea from https://www.forward.com.au/javaProgramming/javaGuiTips/javaLoggingDebugging.html to use Logging.currentConfiguration() to retrieve actual configuration and we will be able to check what was actually applied? Maybe this way we would know what is wrong?

I think I may have an "idea" what is wrong with our config. Maybe that is just "stupid" but in the first example (produced by adhoc) class level configuration is applied before package level configuration and in the second on (which works) package level configuration is before class level configuration. This is just a wild guess but... maybe we should sort those entries before creating a property file? I'm not aware of a requirement like that in JUL but who knows.

As stated at http://tutorials.jenkov.com/java-logging/configuration.html:

Note: Configuration properties are applied in the sequence they are listed in the config file. That means, that you should configure parent Logger's before child Logger's. Otherwise the configuration of the parent Logger will override that of the child Logger.

Well, it turns out the answer is in the javadocs of LogManager.html.readConfiguration():

This readConfiguration method should only be used for initializing the configuration during LogManager initialization or used with the "java.util.logging.config.class" property. When this method is called after loggers have been created, and the "java.util.logging.config.class" system property is not set, all existing loggers will be reset. Then any existing loggers that have a level property specified in the new configuration stream will be set to the specified log level. To properly update the logging configuration, use the updateConfiguration(java.util.function.Function) or updateConfiguration(java.io.InputStream, java.util.function.Function) methods instead.

I added ordering on loggers (still relevant) and applied configuration suggested in LogManager.html.updateConfiguration():

Replace all properties with the new configuration except the handler property to configure Logger's handler that is not root logger:

(k) -> k.endsWith(".handlers")
          ? ((o, n) -> (o == null ? n : o))
          : ((o, n) -> n)

And it seems to be working fine ( @andrzej.wojcik please do take a look if it looks ok). I wonder how it was working previously as, according to the documentation, it shouldn't have…

Original message:

Just an idea, maybe we should follow and idea from https://www.forward.com.au/javaProgramming/javaGuiTips/javaLoggingDebugging.html to use Logging.currentConfiguration() to retrieve actual configuration and we will be able to check what was actually applied? Maybe this way we would know what is wrong?

During startup:

[2020-10-05 18:59:18:087] [CONFIG  ] [                  main ] LoggingBean.lambda$beanConfigurationChanged$21(): Setting log level for loggerName: tigase.kernel.core.Kernel to: {level=CONFIG}
[2020-10-05 18:59:18:088] [CONFIG  ] [                  main ] LoggingBean.lambda$beanConfigurationChanged$21(): Setting log level for loggerName: tigase to: {useParentHandlers=true}
[2020-10-05 18:59:18:091] [CONFIG  ] [                  main ] LoggingBean.beanConfigurationChanged(): Initialised LogManager with configuration: .level=CONFIG
tigase.server.level=ALL
tigase.kernel.core.Kernel.level=CONFIG
tigase.useParentHandlers=true
java.util.logging.FileHandler.formatter=tigase.util.log.LogFormatter
java.util.logging.FileHandler.level=ALL
java.util.logging.FileHandler.count=5
java.util.logging.FileHandler.limit=10000000
java.util.logging.FileHandler.pattern=logs/tigase.log
java.util.logging.FileHandler.append=true
java.util.logging.ConsoleHandler.formatter=tigase.util.log.LogFormatter
java.util.logging.ConsoleHandler.level=WARNING
handlers=java.util.logging.ConsoleHandler java.util.logging.FileHandler

LoggerName:'tigase.server.Bootstrap'
    Level:CONFIG  set by parent:''
    Filter:none set
    ResourceBundleName: none set
    Handlers: set by parent:''
             Handler:java.util.logging.ConsoleHandler Level:WARNING Formatter:tigase.util.log.LogFormatter
             Handler:java.util.logging.FileHandler Level:ALL Formatter:tigase.util.log.LogFormatter
…

Reconfiguring for package tigase.io:

[2020-10-05 19:00:31:131] [CONFIG  ] [  in_20-message-router ] LoggingBean.setPackageLoggingLevel(): Setting log level for package: tigase.io to FINEST
[2020-10-05 19:00:31:133] [CONFIG  ] [  in_20-message-router ] LoggingBean.lambda$beanConfigurationChanged$21(): Setting log level for loggerName: tigase.kernel.core.Kernel to: {level=CONFIG}
[2020-10-05 19:00:31:133] [CONFIG  ] [  in_20-message-router ] LoggingBean.lambda$beanConfigurationChanged$21(): Setting log level for loggerName: tigase to: {useParentHandlers=true}
[2020-10-05 19:00:31:133] [CONFIG  ] [  in_20-message-router ] LoggingBean.lambda$beanConfigurationChanged$21(): Setting log level for loggerName: tigase.io to: {level=FINEST}
[2020-10-05 19:00:31:145] [CONFIG  ] [  in_20-message-router ] LoggingBean.beanConfigurationChanged(): Initialised LogManager with configuration: .level=CONFIG
tigase.server.level=ALL
tigase.kernel.core.Kernel.level=CONFIG
tigase.useParentHandlers=true
tigase.io.level=FINEST
java.util.logging.FileHandler.formatter=tigase.util.log.LogFormatter
java.util.logging.FileHandler.level=ALL
java.util.logging.FileHandler.count=5
java.util.logging.FileHandler.limit=10000000
java.util.logging.FileHandler.pattern=logs/tigase.log
java.util.logging.FileHandler.append=true
java.util.logging.ConsoleHandler.formatter=tigase.util.log.LogFormatter
java.util.logging.ConsoleHandler.level=WARNING
handlers=java.util.logging.ConsoleHandler java.util.logging.FileHandler

And only now the tool reports correct parent/level ("set by parent"):

LoggerName:'tigase.server.Command'
    Level:ALL  set by parent:'tigase.server'
    Filter:none set
    ResourceBundleName: none set
    Handlers: set by parent:''
             Handler:java.util.logging.ConsoleHandler Level:WARNING Formatter:tigase.util.log.LogFormatter
             Handler:java.util.logging.FileHandler Level:ALL Formatter:tigase.util.log.LogFormatter

But not for the currently reconfigured package:

LoggerName:'tigase.io.SSLContextContainer'
    Level:CONFIG  set by parent:''
    Filter:none set
    ResourceBundleName: none set
    Handlers: set by parent:''
             Handler:java.util.logging.ConsoleHandler Level:WARNING Formatter:tigase.util.log.LogFormatter
             Handler:java.util.logging.FileHandler Level:ALL Formatter:tigase.util.log.LogFormatter

I thought that As noted above, loggers created in classes are not visable in the current configuration until their class is loaded. This means the best place to call System.out.println(au.com.forward.logging.Logging.currentConfiguration()); is at the end of the application main() or in the exit code after all the classes have been loaded. but subsequent changes doesn't affect packages being configured.

~~I'm starting to suspect that tigase.useParentHandlers=true may be at play, but from my tests it doesn't seem it's location affects loging in any way.~~

Note: Configuration properties are applied in the sequence they are listed in the config file. That means, that you should configure parent Logger's before child Logger's. Otherwise the configuration of the parent Logger will override that of the child Logger.

This is interesting, but in each run the most-parent-item is always first. What's curious is that the tool doesn't report any parent set for class from that particular package that was being configured.

The change looks OK and if it works (even just after startup) then I would say that we have everything what we wanted.