Issue1808

classification
Title: The logging module will throw exceptions when '%{process}d' is used in formatting string because os.getpid() is not implemented in Jython
Type: crash Severity: major
Components: Core Versions: Jython 2.5
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: amak Nosy List: amak, fwierzbicki, irmen, otmarhumbel, whistler11783, zyasoft
Priority: normal Keywords:

Created on 2011-10-11.23:21:24 by whistler11783, last changed 2014-07-01.04:11:46 by zyasoft.

Messages
msg6668 (view) Author: Robert Scrimo (whistler11783) Date: 2011-10-11.23:21:24
With Jython 2.5.2(final)...which throws the exception unexpectedly...

-bash-3.00$ jython
Jython 2.5.2 (Release_2_5_2:7206, Mar 2 2011, 23:12:06)
[Java HotSpot(TM) Server VM (Sun Microsystems Inc.)] on java1.6.0_18
Type "help", "copyright", "credits" or "license" for more information.
>>> import logging.handlers as LH
>>> import logging
>>> log_file='/tmp/spam.log'
>>> lhandler = LH.TimedRotatingFileHandler(log_file, when='D', interval=7, backupCount=4)
>>> root_logger = logging.getLogger('')
>>> root_logger.setLevel(logging.DEBUG)
>>> formatter = logging.Formatter('%(asctime)s:%(process)d %(levelname)s %(message)s', "%Y%m%d%H%M%S")
>>> lhandler.setFormatter(formatter)
>>> root_logger.addHandler(lhandler)
>>> logging.debug('asdasdasddsdad')
Traceback (most recent call last):
  File "/jython2.5.2/Lib/logging/__init__.py", line 744, in emit
    msg = self.format(record)
  File "/jython2.5.2/Lib/logging/__init__.py", line 630, in format
    return fmt.format(record)
  File "/jython2.5.2/Lib/logging/__init__.py", line 421, in format
    s = self._fmt % record.__dict__
TypeError: int argument required
>>> exit()

This is unexpected.

Example using Python 2.4.6...This works as expected...

Python 2.4.6 (#1, Dec 13 2009, 23:43:51) [C] on sunos5
Type "help", "copyright", "credits" or "license" for more information.
>>> import logging
>>> import logging.handlers as LH
>>> log_file='/tmp/spam.log'
>>> lhandler = LH.TimedRotatingFileHandler(log_file, when='D', interval=7, backupCount=4)
>>> root_logger = logging.getLogger('')
>>> root_logger.setLevel(logging.DEBUG)
>>> formatter = logging.Formatter('%(asctime)s:%(process)d %(levelname)s %(message)s', "%Y%m%d%H%M%S")
>>> lhandler.setFormatter(formatter)
>>> root_logger.addHandler(lhandler)
>>> logging.debug('asdasdasddsdad')
>>> ^D

And another example using Python 2.6.2...which also works fine...

Python 2.6.2 (r262:71600, Aug 11 2009, 07:38:25)
[GCC 4.3.3] on sunos5
Type "help", "copyright", "credits" or "license" for more information.
>>> import logging
>>> import logging.handlers as LH
>>> log_file='/tmp/spam.log'
>>> lhandler = LH.TimedRotatingFileHandler(log_file, when='D', interval=7, backupCount=4)
>>> root_logger = logging.getLogger('')
>>> root_logger.setLevel(logging.DEBUG)
>>> formatter = logging.Formatter('%(asctime)s:%(process)d %(levelname)s %(message)s', "%Y%m%d%H%M%S")
>>> lhandler.setFormatter(formatter)
>>> root_logger.addHandler(lhandler)
>>> logging.debug('asdasdasddsdad')
>>> exit()
-bash-3.00$

The version of Jython I am using:
-bash-3.00$ jython
Jython 2.5.2 (Release_2_5_2:7206, Mar 2 2011, 23:12:06)
[Java HotSpot(TM) Server VM (Sun Microsystems Inc.)] on java1.6.0_18
Type "help", "copyright", "credits" or "license" for more information.
>>> import sys
>>> import platform
>>> print sys.version_info
(2, 5, 2, 'final', 0)
>>> print platform.uname()
('Java', 'host.notimportant.com', '1.6.0_18', 'Java HotSpot(TM) Server VM, 16.0-b13, Sun Microsystems Inc.', '', '')

Let me know if you need any other information.
msg6669 (view) Author: Robert Scrimo (whistler11783) Date: 2011-10-12.19:26:00
I know it is probably obvious but I wanted to also add that I believe the problem with all of the logging handlers is going to be because of a much more fundamental issue with the string format operator(%) used in this particular way. As per the error, TypeError: int argument required, yielded from executing this code:
s = self._fmt % record.__dict__

Just my two cents.
msg6670 (view) Author: Robert Scrimo (whistler11783) Date: 2011-10-12.20:53:01
Okay...I did a little poking around in the logging code. As it turns out because os.getpid() is not implemented in Jython the value for 'process' in the format string is None which causes the formatting to fail because format operator is looking for a number to format.

The logging module does not handle None correctly for formatting the process because it always is an integer in Python because os.getpid() is implemented...The format suggestion for process is '%{process}d'.

What bugs me is that a check is in the code to set process to None if os.getPid() is not implemented but a None value causes an exception in the formatting operation if you use the suggested formatting for process which is '%{process}d'.  

To workaround this issue in Jython the format suggestion for process should be '%{process}s' if you want to re-use your code between Jython and Python(like me)

See output for evidence:
>>> import logging
>>> import logging.handlers as LH
>>> log_file='/tmp/spam.txt'
>>> lhandler = LH.TimedRotatingFileHandler(log_file, when='D', interval=7, backupCount=4)
>>> root_logger = logging.getLogger('')
>>> root_logger.setLevel(logging.DEBUG)
>>> formatter = logging.Formatter('%(asctime)s:%(process)d %(levelname)s %(message)s', "%Y%m%d%H%M%S")
>>> lhandler.setFormatter(formatter)
>>> root_logger.addHandler(lhandler)
>>> logging.debug('sdasddsadadas')
Inspecting the record.__dict__ shows...
{'exc_text': None, 'filename': '<stdin>', 'thread': 2L, 'exc_info': None, 'threadName': u'MainThread', 'msecs': 571.0000991821289, 'args': (), 'created': 1318450970.571, 'levelname': 'DEBUG', 'lineno': 1, 'module': '<stdin>', 'name': 'root', 'levelno': 10, 'pathname': '<stdin>', 'process': None, 'msg': 'sdasddsadadas', 'relativeCreated': 96216.00008010864, 'funcName': '<module>'}
Traceback (most recent call last):
  File "/jython2.5.2/Lib/logging/__init__.py", line 745, in emit
    msg = self.format(record)
  File "/jython2.5.2/Lib/logging/__init__.py", line 631, in format
    return fmt.format(record)
  File "/jython2.5.2/Lib/logging/__init__.py", line 422, in format
    s = self._fmt % record.__dict__
TypeError: int argument required
>>> import os
>>> os.getpid()
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
AttributeError: 'module' object has no attribute 'getpid'
>>> dir(os)
['EX_OK', 'F_OK', 'O_APPEND', 'O_CREAT', 'O_EXCL', 'O_RDONLY', 'O_RDWR', 'O_SYNC', 'O_TRUNC', 'O_WRONLY', 'R_OK', 'SEEK_CUR', 'SEEK_END', 'SEEK_SET', 'W_OK', 'X_OK', '__all__', '__doc__', '__file__', '__name__', '_exists', '_exit', '_get_exports_list', '_get_shell_commands', '_name', '_native_posix', '_posix_impl', '_wrap_close', 'access', 'altsep', 'chdir', 'chmod', 'chown', 'close', 'curdir', 'defpath', 'devnull', 'environ', 'errno', 'error', 'extsep', 'fdatasync', 'fdopen', 'fsync', 'ftruncate', 'getcwd', 'getcwdu', 'getegid', 'getenv', 'geteuid', 'getgid', 'getlogin', 'getpgrp', 'getppid', 'getuid', 'isatty', 'kill', 'lchmod', 'lchown', 'linesep', 'link', 'listdir', 'lseek', 'lstat', 'makedirs', 'mkdir', 'name', 'open', 'pardir', 'path', 'pathsep', 'popen', 'popen2', 'popen3', 'popen4', 'putenv', 'read', 'readlink', 'remove', 'removedirs', 'rename', 'renames', 'rmdir', 'sep', 'setpgrp', 'setsid', 'stat', 'stat_result', 'strerror', 'symlink', 'sys', 'system', 'unlink', 'unsetenv', 'urandom', 'utime', 'wait', 'waitpid', 'walk', 'write']
>>> exit()
 
A workaround until os.getpid() is implemented is use format '%{process}s' instead of the suggestion of '%{process}d' in the format string.

e.g.:
>>> import logging
>>> import logging.handlers as LH
>>> log_file='/tmp/spam.txt'
>>> lhandler = LH.TimedRotatingFileHandler(log_file, when='D', interval=7, backupCount=4)
>>> root_logger = logging.getLogger('')
>>> root_logger.setLevel(logging.DEBUG)
>>> formatter = logging.Formatter('%(asctime)s:%(process)s %(levelname)s %(message)s', "%Y%m%d%H%M%S")
>>> lhandler.setFormatter(formatter)
>>> root_logger.addHandler(lhandler)
>>> logging.debug('sdsddsdsdsd')
>>> exit()
-bash-3.00$ cat /tmp/spam.txt
20111012143723:None DEBUG sdsddsdsdsd
-bash-3.00$
msg6671 (view) Author: Irmen de Jong (irmen) Date: 2011-10-12.22:22:13
Very strange: my Jythons all got os.getpid().
Checked on the official 2.5.2 releases on linux and windows.

It ran your logging code without errors.
msg6675 (view) Author: Robert Scrimo (whistler11783) Date: 2011-10-13.06:33:56
What's wierd is that os.getpid() is not implemented on Solaris or it has to do with Java 1.6.0-18 or Java 1.6.0 in general on Solaris or OpenJDK VM vs HotSpot VM?  Being that I have standard Java HotSpot VM from the source(Oracle), regardless, whether or not this function is available is not reliable in Jython and the logging module is using os.getpid().  And in these cases where for some mystic reason the os.getpid() function is not implemented, on specific platforms and/or Java versions, phase of the moon and/or tides ;), the way it is handled in the logging module really needs to be more robust. But I digress. 

This is obviously a bug in the Python logging module but due the lack of os.getpid() in some Jython implementation(s), other than linux and windows, is exposing this issue. This is something that may need to be addressed in some way, even if that be by documentation or figuring out how to implement os.getpid() on all Jython platforms or at a minimum an os.getpid() function that returns -1 would at least would fill this hole(this would be a last resort).

This problem seems specific to Jython because of the possibility of os.getpid() being missing. Otherwise, the logging module would have been fixed in Python a long time ago.
msg6715 (view) Author: Irmen de Jong (irmen) Date: 2011-11-06.23:43:38
Just discovered that on my mac (OSX 10.5, jdk 1.5) the os.getpid() functions is missing as well.
Turned out this is because several functions in the posix module are hidden when the posix implementation "is not native" (whatever that means, it is decided by a library call into jnr-posix.jar).
msg6832 (view) Author: Alan Kennedy (amak) Date: 2012-03-19.18:37:36
There are several solutions for getting the process ID suggested on this blog post.

http://blog.igorminar.com/2007/03/how-java-application-can-discover-its.html

One promising approach is to set a java System property on the command line that starts jython, e.g.

"""
2. Using shell script in addition to Java properties Start your app with a shellscript like this:

exec java -Dpid=$$ -jar /Applications/bsh-2.0b4.jar

then in java code call:

System.getProperty("pid");
"""

you could then monkeypatch the os module like so

>>> import java
>>> import os
>>> os.getpid = lambda: java.lang.System.getProperty("pid")
msg6835 (view) Author: Irmen de Jong (irmen) Date: 2012-03-19.19:03:07
@amak: looks nice, but I guess you can't depend on that, not everyone will use the default shellscript to invoke jython. Also is there a windows-equivalent?
msg7013 (view) Author: Alan Kennedy (amak) Date: 2012-04-01.17:56:57
Adding Oti.

Oti, is there any way that we can get the process id of the JVM process running jython, in a platform independent way?
msg7034 (view) Author: Alan Kennedy (amak) Date: 2012-04-06.21:08:18
OK, I found another workaround that should work.

Before you use your logging code, execute the following

###########

import os

if not hasattr(os, 'getpid'):
    from java.lang.management import ManagementFactory
    _getpid = lambda: int(ManagementFactory.getRuntimeMXBean().name.split("@")[0])
    setattr(os, "getpid", _getpid)

###########

Please let me know if this works for you.
msg7035 (view) Author: Alan Kennedy (amak) Date: 2012-04-06.21:25:26
See also this thread, which discusses failure to load native functionality as the cause for the missing getpid() functionality

http://sourceforge.net/mailarchive/forum.php?thread_name=F7108FD2EAB507FBC66C27FA%40[192.168.1.2]&forum_name=jython-users

Perhaps you can also try jython -vv to see which Posix implementation is being loaded on the systems with problems?
msg7666 (view) Author: Alan Kennedy (amak) Date: 2013-02-11.22:40:21
Now that all of the jnr and jffi jars have been updated to the latest versions, these issues *should* be fixed (barring dynamic loading problems due to misconfiguration).

Please can you test with the latest 2.5.4rc1 or 2.7b1? Thanks.
msg7765 (view) Author: Frank Wierzbicki (fwierzbicki) Date: 2013-02-25.21:55:35
The libs are only updated for 2.7b1 as they depend on ASM 4.0 - so this may only be fixed there.
msg7768 (view) Author: Alan Kennedy (amak) Date: 2013-02-25.22:12:21
OK, if it's just for 2.5, I'm tempted to apply this fix, since getpid() is a common requirement for all kinds of things.

###########

import os

if not hasattr(os, 'getpid'):
    from java.lang.management import ManagementFactory
    _getpid = lambda: int(ManagementFactory.getRuntimeMXBean().name.split("@")[0])
    setattr(os, "getpid", _getpid)

###########
msg7770 (view) Author: Frank Wierzbicki (fwierzbicki) Date: 2013-02-25.22:22:14
Alan, sounds good to me. Are you sure it isn't needed in 2.7 in some cases?
msg7773 (view) Author: Alan Kennedy (amak) Date: 2013-02-25.22:59:51
The issue is definitely fixed for me in 2.7, running on Windows 2003.

Jython 2.7b1+ (default:a30708945630, Feb 25 2013, 08:48:40)
[Java HotSpot(TM) Client VM (Sun Microsystems Inc.)] on java1.6.0_29
Type "help", "copyright", "credits" or "license" for more information.
>>> import os
>>> os.getpid()
1100
>>>

How about 2.7 other platforms? Linux? MacOS?

I'm looking at 2.5 now.
msg7774 (view) Author: Alan Kennedy (amak) Date: 2013-02-25.23:07:57
Definitely fixed in 2.5 head, probably because of this update

http://hg.python.org/jython/rev/a113ab4287fc?revcount=120

Jython 2.5.4 (2.5:ce225289358a, Feb 25 2013, 22:54:38)
[Java HotSpot(TM) Client VM (Sun Microsystems Inc.)] on java1.5.0_22
Type "help", "copyright", "credits" or "license" for more information.
>>> import os
>>> os.getpid()
3192
>>>

Again need to check on Linux and MacOS, at least.

Can all posters on this issue please check the latest jython Jython 2.5.4rc 1? (Which was built after the relevant fix).

I consider this issue fixed, but will leave it open for others to demonstrate otherwise.
msg7818 (view) Author: Frank Wierzbicki (fwierzbicki) Date: 2013-02-26.22:03:27
I'll mark it fixed but leave it open for others to disagree for a little while. If no one chimes in for a few weeks we should just close it.
msg8858 (view) Author: Jim Baker (zyasoft) Date: 2014-07-01.04:11:46
Pending for over a year, time to close
History
Date User Action Args
2014-07-01 04:11:46zyasoftsetstatus: open -> closed
nosy: + zyasoft
messages: + msg8858
2013-02-26 22:03:27fwierzbickisetresolution: fixed
messages: + msg7818
2013-02-25 23:07:57amaksetmessages: + msg7774
2013-02-25 22:59:51amaksetmessages: + msg7773
2013-02-25 22:22:14fwierzbickisetmessages: + msg7770
2013-02-25 22:12:21amaksetmessages: + msg7768
2013-02-25 21:55:35fwierzbickisetpriority: normal
nosy: + fwierzbicki
messages: + msg7765
versions: + Jython 2.5, - 2.5.2
2013-02-11 22:40:21amaksetmessages: + msg7666
2012-04-06 21:25:26amaksetmessages: + msg7035
2012-04-06 21:08:19amaksetassignee: amak
messages: + msg7034
2012-04-01 17:56:57amaksetnosy: + otmarhumbel
messages: + msg7013
2012-03-19 19:03:07irmensetmessages: + msg6835
2012-03-19 18:37:36amaksetnosy: + amak
messages: + msg6832
2011-11-06 23:43:38irmensetmessages: + msg6715
2011-10-13 06:33:57whistler11783setmessages: + msg6675
2011-10-12 22:22:13irmensetnosy: + irmen
messages: + msg6671
2011-10-12 20:54:07whistler11783settitle: All logging.handlers will throw exceptions when '%{process}d' is used in formatting string because os.getpid() is not implemented in Jython -> The logging module will throw exceptions when '%{process}d' is used in formatting string because os.getpid() is not implemented in Jython
2011-10-12 20:53:01whistler11783setmessages: + msg6670
severity: critical -> major
title: logging.handlers.TimedRotatingFileHandler throws exception when emit called -> All logging.handlers will throw exceptions when '%{process}d' is used in formatting string because os.getpid() is not implemented in Jython
2011-10-12 19:26:01whistler11783setmessages: + msg6669
2011-10-12 19:14:00whistler11783settype: behaviour -> crash
2011-10-12 19:13:28whistler11783settype: behaviour
2011-10-11 23:21:24whistler11783create