Issue2896

Jython's command line program uses its own loggers that is separated from normal logging output.  I.e. in file 'org/python/util/jython.java' there is this comment and corresponding code to do what it describes:

    // Make our "org.python" logger do its own output and not propagate to root.

For me, this defeats the whole point of logging: have an overview of what various parts of the application do, and how they do this together (so that I don't have to search for correspondences in timestamps in 10 different output files).

Please either make Jython logging completely like everything else or at least make this configurable so that I can e.g. just set something in environment.

The good reason is that logging in the console command is a replacement for the way we previously produced messages, which was also entirely disconnected from other systems of logging. In the console command, where this code applies, the idea was for log messages to appear much as they had before, by means of a custom format (which you won't like either since it affects all simple logging).

If logging bubbles up to root as well, then with default settings, the ISTR user gets each message twice.

In jython the command-line command, we feel free to do all that because it *is" the application. When Jython is used embedded, it seemed sensible let the messages enter the normal logging hierarchy, and not muck about with the format.

User experience/expectations are important, however. I guess you are using the command line utility to launch your application, but it runs "unobserved", hence the need for logging. JUL is very configurable: you can adjust things to your liking.

PS jython-nightjar> dist\bin\jython
Jython 2.7.3a1-DEV (uncontrolled:+, May 30 2020, 20:41:06)
[Java HotSpot(TM) 64-Bit Server VM (Oracle Corporation)] on java1.8.0_241
Type "help", "copyright", "credits" or "license" for more information.
>>> from java.util.logging import Logger, Level
>>> rootlogger = Logger.getLogger("")
>>> pylogger = Logger.getLogger("org.python")
>>>
>>> rootlogger.warning("Hello")
 WARNING Hello
>>> pylogger.warning("Hello")
org.python WARNING Hello
>>>
>>> pylogger.useParentHandlers
False
>>> pylogger.useParentHandlers = True
>>> pylogger.warning("Hello")
org.python WARNING Hello
org.python WARNING Hello
>>>

This last illustrates what motivated the disconnection: two messages when you only need one, and both in the abbreviated format suited to a console application. But it may have been better to do just one of these things (tweak the format universally and just let messages bubble up, *or* prevent bubbling up and tweak the format just for org.python).

If you choose your own format, Jython won't impose its own:

PS jython-nightjar> dist\bin\jython -D'java.util.logging.SimpleFormatter.format=%1$tl:%1$tM:%1$tS %1$Tp %4$s: %5$s%6$s%n'
Jython 2.7.3a1-DEV (uncontrolled:+, May 30 2020, 20:41:06)
[Java HotSpot(TM) 64-Bit Server VM (Oracle Corporation)] on java1.8.0_241
Type "help", "copyright", "credits" or "license" for more information.
>>> from java.util.logging import Logger
>>> rootlogger = Logger.getLogger("")
>>> pylogger = Logger.getLogger("org.python")
>>> rootlogger.warning("Hello")
8:01:52 AM WARNING: Hello
>>> pylogger.warning("World")
8:02:03 AM WARNING: World

> I guess you are using the command line utility to launch your application, but it runs "unobserved"

I do use the utility to launch the application, but only in a "tool" mode. Normally it is a Web application running in a Web container, but can also be launched separately to execute certain tasks like administration of the database. This way I can easily share code between the main application and various tools: they basically have the same code, just the entry point is different.

Tools do *not* run unobvserved, they are started from command line manually. For output, they reuse logging mechanism: Web applications nearly always write logs, so we already have them implemented. In tools, logs are created normally and additionally, log excerpts (warnings, errors and additionally info from certain categories relevant to that specific tool) is written to the *console*. In this way, Jython logging is getting in the way, by intermixing expected tool output with its own log entries.

The application is quite large and we use perhaps 30-50 libraries in total. Many of them log, some with SLF4J, some with JCL, some with java.util.logging, as Jython. However, we use Log4j bridge to collect everything together, so we receive a single log file out of all of this.

Jython is the only thing that gets in our way and tries to configure logging on its own. Everything else just writes to the logs and lets end user configure it as they see fit (enable/disable levels, decide where log entries go to).

Just to confirm, does the web-service log org.python events as you would hope?

On the *console*, I find the default Java message format unsuitable. I know the date and time already and the line-break makes reading piped output hard. (Until this change, Netty would do that.) For continuity it seemed best that our log messages should be (by default) similar to what they were previously.

So I'm reluctant to change the way it looks, but the way it works could be re-thought. I'd be happy to hear a suggestion how, with the default output as it is, we could make it easier for people who want something else. System properties seem the obvious control mechanism.

> Just to confirm, does the web-service log org.python events as you would hope?
Yes.

> On the *console*, I find the default Java message format unsuitable.
It's not up to Jython to impose it on me. I also use a different format (e.g. no date, only time), but the point is that Jython is part of my logs in this case and its entries should look like all others. Because Jython is ultimately not the highest level and cannot know about other entities adding to the log, or how the highest level (the user) wants it to look like, it should leave configuration alone.  There is a reason I have configuration in 'logback.xml' and everything else plays along.

> I know the date and time already
Our tools can run for hours, so at least time is certainly useful.  Again, Jython is not in the position to decide for everyone who might want to use it.

> So I'm reluctant to change the way it looks, but the way it works could be re-thought. I'd be happy to hear a suggestion how, with the default output as it is, we could make it easier for people who want something else. System properties seem the obvious control mechanism.
At least there should be a way to prevent Jython's configuration or undo what it does.  If you want to keep the current behavior, please at least:
- move everything configuring the logs from static class initialization to an own method;
- call said method only depending on something in system properties (i.e. if certain property is set, don't do anything at all);
- provide a public method to undo all the changes for those who cannot or don't want to use system properties, ideally easily accessible both from Python and Java levels.

Intend to revisit in https://github.com/jython/jython/issues/183