Issue2778

We should use a standard way to issue log messages, preferably plain Java logging.

Motivation:

1. In several pieces of work over the last year or so I have wanted to insert logging instructions (Py.writeDebug() etc.) but have been deterred from doing so, or from leaving them in place for production, because the cost of creating the messages is borne whether they be issued or no. Modern frameworks are lazy: the message is formatted only if it will be emitted.

2. Start-up time, and performance generally, is a worry, and I think it would help us get a grip on it to be able to issue messages with a time stamp, probably at millisecond resolution. We can easily turn this on using Java logging.

3. Using a standard approach gives our users a control mechanism they (probably) already understand if their application uses logging at all.

Implementation:

I propose to use the plain Java logging framework since it does not add another JAR, appears adequate for our needs, and messages can be diverted by application builders into whatever enterprise framework they use.

We can introduce this inside the current logging methods (Py.writeComment() etc.) with minimal code change, then progressively introduce Java logging in place of such calls to get the laziness advantage. I believe we can arrange to produce messages by default only when we currently produce them. There would be differences in detail in the format and names for levels, and that they would emerge by default on syserr.

I've just noticed I've near-duplicated the near-namesake #2278, although I don't understand the implications of "some widely used instrumentation package" there.

I think I can get this in the beta while we're waiting to resolve the website and other things.

I'm quite liking this correspondence:

>>> for v in range(-2, 8):
...     print v, Py.levelFromVerbosity(v)
...
-2 SEVERE
-1 SEVERE
0 WARNING
1 INFO
2 CONFIG
3 FINE
4 FINER
5 FINEST
6 ALL
7 ALL

These are not all valid levels in Jython, but it seems as good a response as any to other integer values to map them so. We can go the other way too:

>>> for level in (ALL, FINEST, FINER, FINE, CONFIG, INFO, WARNING, SEVERE, OFF):
...     print level, Py.verbosityFromLevel(level)
...
ALL 6
FINEST 5
FINER 4
FINE 3
CONFIG 2
INFO 1
WARNING 0
SEVERE -1
OFF -1

Our default level (no -v flag) is 1 = MESSAGE = INFO, which is also the Java default, so it nicely produces "least surprise". I'm not sure what to do about about OFF.

I've yet to discover at what points I need to use these functions to keep things in sync, but writing them seemed a good starting point. They may not be public in a release.

Interesting observation for the semantics of this: the registry setting python.verbose (if given) overrides the -v option on the command line (currently). This is because the command parser updates Options.verbose as it works, but the registry is only read as the runtime initialises. Here we start verbose, but hen the registry value takes over.

PS jython-trunk> dist\bin\jython -vvv
initializer: 'META-INF/services/org.python.core.JythonInitializer' not found on sun.misc.Launcher$AppClassLoader@45e4d960
initializer: 'META-INF/services/org.python.core.JythonInitializer' not found on sun.misc.Launcher$AppClassLoader@45e4d960
Jython 2.7.2a1+ (default:011472a1af03+, Aug 4 2019, 16:52:04)
[Java HotSpot(TM) 64-Bit Server VM (Oracle Corporation)] on java1.7.0_80
Type "help", "copyright", "credits" or "license" for more information.
>>> from org.python.core import Options
>>> Options.verbose
1
            
A setting made via JUL logging properties is available from the start and -v will adjust relative to that.

I think I've a satisfactory approach to this now.

PS jython-trunk> dist\bin\jython -vv -S
org.python: (FINE) initializer: 'META-INF/services/org.python.core.JythonInitializer' not found on sun.misc.Launcher$AppClassLoader@49aa95c
org.python: (FINE) initializer: 'META-INF/services/org.python.core.JythonInitializer' not found on sun.misc.Launcher$AppClassLoader@49aa95c
org.python: (FINE) *sys-package-mgr*: reading cache, 'C:\Users\Jeff\Documents\Eclipse\jython-trunk\dist\jython-dev.jar'
...
org.python: (FINE) threadstate: no current system state
org.python: (FINE) import: trying org.python.core.exceptions as builtin modules in SysPathJavaLoader
org.python: (CONFIG) import: 'exceptions' as org.python.core.exceptions in builtin modules
Jython 2.7.2a1+ (default:011472a1af03+, Aug 7 2019, 08:31:05)
[Java HotSpot(TM) 64-Bit Server VM (Oracle Corporation)] on java1.7.0_80
<file-top>:
>>> from org.python.core import Py, Options
<single-top>: Py= Options=
org.python: (FINE) import: trying org in packagemanager for path None
...
org.python: (CONFIG) import: 'Options' as java class
>>> Py.getLoggingLevel()
<single-top>: Py
org.python: (FINE) import: trying precompiled C:\Users\Jeff\Documents\Eclipse\jython-trunk\dist\Lib\encodings\__init__$py.class
...
FINE
>>> Options.verbose
<single-top>: Options
3

Although Options.verbose is now deprecated in favour of setting a logging level, it actually works quite well for code that continues to use the legacy methods.

>>> Options.verbose = 1
<single-top>: Options
>>> Py.writeMessage("hello", "world")
org.python: (INFO) hello: world
>>> Py.getLoggingLevel()
INFO
>>> from java.util.logging import Level
>>> Py.setLoggingLevel(Level.CONFIG)
>>> Options.verbose
2
>>> Py.writeComment("hello", "world")
org.python: (CONFIG) hello: world
>>> Py.writeDebug("hello", "world")


However there is a slight wrinkle where a security manager is in force. The best response I can think of is to complain and continue, but it means we don't get to control the  verbosity:

PS jython-trunk> dist\bin\jython -v "-J-Djava.security.manager" "-J-Djava.security.policy=Lib\test\python_home.policy"
org.python: (WARNING) unable to configure console messages: access denied ("java.util.logging.LoggingPermission" "control")
org.python: (WARNING) A security manager prevented a change to the logging level.
Jython 2.7.2a1+ (default:011472a1af03+, Aug 7 2019, 08:31:05)
[Java HotSpot(TM) 64-Bit Server VM (Oracle Corporation)] on java1.7.0_80
Type "help", "copyright", "credits" or "license" for more information.
>>> from org.python.core import Py, Options
>>> Py.writeMessage("hello", "world")
org.python: (INFO) hello: world
>>> Py.writeComment("hello", "world")        # this should come out (because of the -v)
>>> Options.verbose                          # this should be 2 (also because of the -v)
1
>>> Options.verbose = 4                      # you can set it
>>> Py.writeComment("hello", "world")        # and we try to transfer it to a logging level
<single-top>: Py
org.python: (WARNING) A security manager prevented a change to the logging level.
>>> Options.verbose                          # it gets reset consistent with the logging.
1

The substance of this change is in https://hg.python.org/jython/rev/5e3bd2044a51, and subsequent change sets apply it to new areas of the runtime. It co-exists reasonably well with the existing approach, but the intention is that we use logging directly, as for example in these recent changes to the scopes compiler: https://hg.python.org/jython/rev/443426bd426c .

There is still a mixture of old-style and new-style invocation of logging, and some deprecated use of Options.verbose, but essentially this works now.