Issue1808

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.

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.

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$

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.

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.

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).

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")

@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?

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?

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.

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?

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.

The libs are only updated for 2.7b1 as they depend on ASM 4.0 - so this may only be fixed there.

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)

###########

Alan, sounds good to me. Are you sure it isn't needed in 2.7 in some cases?

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.

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.

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.

Pending for over a year, time to close