subprocess.Popen() output to logging.StreamHandler()

S

sven _

Version: Python 2.5.1 (r251:54863, Mar 7 2008, 04:10:12)

My goal is to have stdout and stderr written to a logging handler.
This code does not work:

# START
import logging, subprocess
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)
subprocess.call(['ls', '-la'], 0, None, None, ch, ch)
# END

Traceback (most recent call last):
File "log.py", line 5, in <module>
subprocess.call(['ls', '-la'], 0, None, None, ch, ch)
File "/usr/lib/python2.5/subprocess.py", line 443, in call
return Popen(*popenargs, **kwargs).wait()
File "/usr/lib/python2.5/subprocess.py", line 586, in __init__
errread, errwrite) = self._get_handles(stdin, stdout, stderr)
File "/usr/lib/python2.5/subprocess.py", line 941, in _get_handles
c2pwrite = stdout.fileno()
AttributeError: StreamHandler instance has no attribute 'fileno'


This is because subprocess.Popen() expects file descriptors to write
to, and logging.StreamHandler() does not supply it. The StreamHandler
could supply its own stdout file descriptor, but then Popen() would
write directly to that file, bypassing all the logging fluff.

A possible solution would be to make a named pipe (os.mkfifo()), have
Popen() write to that, and then have some horrendous hack run select()
or similar on the fifo to read from it and finally pass it to
StreamHandler.

Are there better solutions?

sven
 
T

Thomas Dimson

Version: Python 2.5.1 (r251:54863, Mar  7 2008, 04:10:12)

My goal is to have stdout and stderr written to a logging handler.
This code does not work:

# START
import logging, subprocess
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)
subprocess.call(['ls', '-la'], 0, None, None, ch, ch)
# END

Traceback (most recent call last):
  File "log.py", line 5, in <module>
   subprocess.call(['ls', '-la'], 0, None, None, ch, ch)
  File "/usr/lib/python2.5/subprocess.py", line 443, in call
   return Popen(*popenargs, **kwargs).wait()
  File "/usr/lib/python2.5/subprocess.py", line 586, in __init__
   errread, errwrite) = self._get_handles(stdin, stdout, stderr)
  File "/usr/lib/python2.5/subprocess.py", line 941, in _get_handles
   c2pwrite = stdout.fileno()
AttributeError: StreamHandler instance has no attribute 'fileno'

This is because subprocess.Popen() expects file descriptors to write
to, and logging.StreamHandler() does not supply it. The StreamHandler
could supply its own stdout file descriptor, but then Popen() would
write directly to that file, bypassing all the logging fluff.

A possible solution would be to make a named pipe (os.mkfifo()), have
Popen() write to that, and then have some horrendous hack run select()
or similar on the fifo to read from it and finally pass it to
StreamHandler.

Are there better solutions?

sven


What is wrong with doing something like:

import logging, subprocess
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)

s = subprocess.Popen( ['ls','-la'], stdout=subprocess.PIPE )
while 1:
ch.info( s.stdout.readline() )
if s.poll() == None:
break

Perhaps not the most efficient or clean solution, but that is how I
usually do it (note: I didn't test the above code).

-Thomas Dimson
 
G

Gerard Flanagan

Version: Python 2.5.1 (r251:54863, Mar 7 2008, 04:10:12)

My goal is to have stdout and stderr written to a logging handler.
This code does not work:

# START
import logging, subprocess
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)
subprocess.call(['ls', '-la'], 0, None, None, ch, ch)
# END

Traceback (most recent call last):
File "log.py", line 5, in <module>
subprocess.call(['ls', '-la'], 0, None, None, ch, ch)
File "/usr/lib/python2.5/subprocess.py", line 443, in call
return Popen(*popenargs, **kwargs).wait()
File "/usr/lib/python2.5/subprocess.py", line 586, in __init__
errread, errwrite) = self._get_handles(stdin, stdout, stderr)
File "/usr/lib/python2.5/subprocess.py", line 941, in _get_handles
c2pwrite = stdout.fileno()
AttributeError: StreamHandler instance has no attribute 'fileno'

This is because subprocess.Popen() expects file descriptors to write
to, and logging.StreamHandler() does not supply it. The StreamHandler
could supply its own stdout file descriptor, but then Popen() would
write directly to that file, bypassing all the logging fluff.

A possible solution would be to make a named pipe (os.mkfifo()), have
Popen() write to that, and then have some horrendous hack run select()
or similar on the fifo to read from it and finally pass it to
StreamHandler.

Are there better solutions?

sven


When you create a StreamHandler, it is associated with a particular
stream, eg. sys.stdout. So when you log an event, the handler picks
it up and writes it to the stream. But you seem to think that the
reverse situation is true - when something is written to the stream
(from an arbitrary source) then the StreamHandler instance will pick
it up. This isn't the case - it doesn't work both ways.

I think the only solution is to specifically log each line that you
get back from Popen, as suggested by Thomas Dimson. You would perhaps
like something like the code below to work but it doesn't (well, it
runs, but the output of the subprocess call bypasses the
Streamhandler). But then, maybe this is sufficient for you - as
you've seen, you can't set the stdout of the subprocess to the
StreamHandler, but you can set it to the Streamhandler's stream (if it
has a fileno) -

subprocess.call('svn info', stdout=ch.stream)
OR
subprocess.call('svn info', stdout=ch.stream.fileno())

--------------------------------------------------------

import sys
import logging
import subprocess

ECHO_FORMAT = '%(levelname)-8s %(message)s'

class ReverseReverseStreamHandler(logging.StreamHandler):

def __init__(self, strm):
logging.StreamHandler.__init__(self, strm)
self.fileno = strm.fileno

def write(self, msg):
print 'This is never called!'
for line in msg.splitlines():
self.emit(logging.LogRecord(None, None, "", 0, line, (),
None, None))

root = logging.getLogger()

console = ReverseReverseStreamHandler(sys.stdout)

formatter = logging.Formatter(ECHO_FORMAT)
console.setFormatter(formatter)
root.addHandler(console)
root.setLevel(logging.DEBUG)

logging.info('---------')

subprocess.call('svn info', stdout=console)

logging.info('---------')
 
G

Gerard Flanagan

Version: Python 2.5.1 (r251:54863, Mar 7 2008, 04:10:12)
My goal is to have stdout and stderr written to a logging handler.
This code does not work: [...]
Are there better solutions?

When you create a StreamHandler, it is associated with a particular
stream, eg. sys.stdout. So when you log an event, the handler picks
it up and writes it to the stream. But you seem to think that...

[snip didacticism]

Rereading your post, I think I've just told you what you already
knew...

Never mind.

G.
 
V

Vinay Sajip

Version: Python 2.5.1 (r251:54863, Mar 7 2008, 04:10:12)

My goal is to have stdout and stderr written to alogginghandler.
This code does not work:

# START
importlogging, subprocess
ch =logging.StreamHandler()
ch.setLevel(logging.DEBUG)
subprocess.call(['ls', '-la'], 0, None, None, ch, ch)
# END

Traceback (most recent call last):
File "log.py", line 5, in <module>
subprocess.call(['ls', '-la'], 0, None, None, ch, ch)
File "/usr/lib/python2.5/subprocess.py", line 443, in call
return Popen(*popenargs, **kwargs).wait()
File "/usr/lib/python2.5/subprocess.py", line 586, in __init__
errread, errwrite) = self._get_handles(stdin, stdout, stderr)
File "/usr/lib/python2.5/subprocess.py", line 941, in _get_handles
c2pwrite = stdout.fileno()
AttributeError: StreamHandler instance has no attribute 'fileno'

This is because subprocess.Popen() expects file descriptors to write
to, andlogging.StreamHandler() does not supply it. The StreamHandler
could supply its own stdout file descriptor, but then Popen() would
write directly to that file, bypassing all theloggingfluff.

A possible solution would be to make a named pipe (os.mkfifo()), have
Popen() write to that, and then have some horrendous hack run select()
or similar on the fifo to read from it and finally pass it to
StreamHandler.

Are there better solutions?

sven

Thomas was almost right, but not quite - you can't call info on a
Handler instance, only on a Logger instance. The following script:

import logging
import subprocess

logging.basicConfig(level=logging.INFO) # will log to stderr of this
script

s = subprocess.Popen( ['ls','-la'], stdout=subprocess.PIPE )
while 1:
line = s.stdout.readline()
exitcode = s.poll()
if (not line) and (exitcode is not None):
break
line = line[:-1]
logging.info("%s", line)

produces the following output:

INFO:root:total 204
INFO:root:drwxr-xr-x 35 vinay vinay 4096 2008-04-10 18:06 .
INFO:root:drwxr-xr-x 3 root root 4096 2008-03-22 07:09 ..
INFO:root:-rw------- 1 vinay vinay 685 2008-04-10
17:26 .bash_history
INFO:root:-rw-r--r-- 1 vinay vinay 220 2008-03-22 07:09 .bash_logout
INFO:root:-rw-r--r-- 1 vinay vinay 2327 2008-03-22 07:09 .bashrc
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-04-05 02:21 .bluefish
INFO:root:drwxr-xr-x 3 vinay vinay 4096 2008-03-22 07:18 .cache
INFO:root:drwxr-xr-x 5 vinay vinay 4096 2008-03-22 07:32 .config
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-03-22 07:17 Desktop
INFO:root:-rw------- 1 vinay vinay 28 2008-04-10 00:33 .dmrc
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-03-22 07:17 Documents
INFO:root:-rw------- 1 vinay vinay 16 2008-03-22 07:17 .esd_auth
INFO:root:lrwxrwxrwx 1 vinay vinay 26 2008-03-22 07:09 Examples -> /
usr/share/example-content
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-04-10 00:21 .fontconfig
INFO:root:drwx------ 4 vinay vinay 4096 2008-04-10 17:23 .gconf
INFO:root:drwx------ 2 vinay vinay 4096 2008-04-10 17:43 .gconfd
INFO:root:-rw-r----- 1 vinay vinay 0 2008-03-24 19:13 .gksu.lock
INFO:root:drwx------ 9 vinay vinay 4096 2008-04-10 00:31 .gnome2
INFO:root:drwx------ 2 vinay vinay 4096 2008-03-22
07:17 .gnome2_private
INFO:root:drwx------ 2 vinay vinay 4096 2008-04-10 00:33 .gnupg
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-04-10
00:33 .gstreamer-0.10
INFO:root:-rw-r--r-- 1 vinay vinay 108 2008-04-10 00:33 .gtk-
bookmarks
INFO:root:dr-x------ 2 vinay vinay 0 2008-04-10 00:33 .gvfs
INFO:root:-rw------- 1 vinay vinay 167 2008-04-10
00:33 .ICEauthority
INFO:root:drwxr-xr-x 3 vinay vinay 4096 2008-03-22 07:18 .local
INFO:root:drwx------ 3 vinay vinay 4096 2008-03-22 07:18 .metacity
INFO:root:drwx------ 4 vinay vinay 4096 2008-03-24 19:13 .mozilla
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-03-22 07:17 Music
INFO:root:drwxr-xr-x 3 vinay vinay 4096 2008-04-10 00:31 .nautilus
INFO:root:drwxr-xr-x 3 vinay vinay 4096 2008-04-05 02:09 .netbeans
INFO:root:drwxr-xr-x 3 vinay vinay 4096 2008-04-05 02:09 .netbeans-
registration
INFO:root:drwx------ 3 vinay vinay 4096 2008-04-05
02:15 .openoffice.org2
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-03-22 07:17 Pictures
INFO:root:-rw-r--r-- 1 vinay vinay 566 2008-03-22 07:09 .profile
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-03-22 07:17 Public
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-03-22 08:01 .pulse
INFO:root:-rw------- 1 vinay vinay 256 2008-03-22 07:17 .pulse-
cookie
INFO:root:-rw-r--r-- 1 vinay vinay 1973 2008-04-10 18:06 .recently-
used.xbel
INFO:root:drwx------ 2 vinay vinay 4096 2008-03-22 07:17 .ssh
INFO:root:drwxr-xr-x 3 vinay vinay 4096 2008-04-05 02:09 .subversion
INFO:root:-rw-r--r-- 1 vinay vinay 0 2008-03-22
07:34 .sudo_as_admin_successful
INFO:root:drwxr-xr-x 4 vinay vinay 4096 2008-03-22 09:10 .sudoku
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-03-22 07:17 Templates
INFO:root:-rw-r--r-- 1 vinay vinay 297 2008-04-10 18:06 test.py
INFO:root:-rw-r--r-- 1 vinay vinay 291 2008-04-10 18:06 test.py~
INFO:root:-rwxr--r-- 1 vinay vinay 75 2008-03-22 07:33 update
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-03-22 08:22 .update-
manager-core
INFO:root:drwx------ 2 vinay vinay 4096 2008-03-22 07:18 .update-
notifier
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-03-22 07:17 Videos
INFO:root:drwxr-xr-x 7 vinay vinay 4096 2007-10-08 14:56 vmware-tools-
distrib
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-04-07 00:19 .wapi
INFO:root:-rw------- 1 vinay vinay 121 2008-04-10 00:33 .Xauthority
INFO:root:-rw-r--r-- 1 vinay vinay 146 2008-04-09
21:33 .xscreensaver-getimage.cache
INFO:root:-rw-r--r-- 1 vinay vinay 5102 2008-04-10 17:31 .xsession-
errors
vinay@zeta-hardy:~$ python test.py | more
INFO:root:total 204
INFO:root:drwxr-xr-x 35 vinay vinay 4096 2008-04-10 18:07 .
INFO:root:drwxr-xr-x 3 root root 4096 2008-03-22 07:09 ..
INFO:root:-rw------- 1 vinay vinay 685 2008-04-10
17:26 .bash_history
INFO:root:-rw-r--r-- 1 vinay vinay 220 2008-03-22 07:09 .bash_logout
INFO:root:-rw-r--r-- 1 vinay vinay 2327 2008-03-22 07:09 .bashrc
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-04-05 02:21 .bluefish
INFO:root:drwxr-xr-x 3 vinay vinay 4096 2008-03-22 07:18 .cache
INFO:root:drwxr-xr-x 5 vinay vinay 4096 2008-03-22 07:32 .config
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-03-22 07:17 Desktop
INFO:root:-rw------- 1 vinay vinay 28 2008-04-10 00:33 .dmrc
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-03-22 07:17 Documents
INFO:root:-rw------- 1 vinay vinay 16 2008-03-22 07:17 .esd_auth
INFO:root:lrwxrwxrwx 1 vinay vinay 26 2008-03-22 07:09 Examples -> /
usr/share/example-content
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-04-10 00:21 .fontconfig
INFO:root:drwx------ 4 vinay vinay 4096 2008-04-10 17:23 .gconf
INFO:root:drwx------ 2 vinay vinay 4096 2008-04-10 17:43 .gconfd
INFO:root:-rw-r----- 1 vinay vinay 0 2008-03-24 19:13 .gksu.lock
INFO:root:drwx------ 9 vinay vinay 4096 2008-04-10 00:31 .gnome2
INFO:root:drwx------ 2 vinay vinay 4096 2008-03-22
07:17 .gnome2_private
INFO:root:drwx------ 2 vinay vinay 4096 2008-04-10 00:33 .gnupg
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-04-10
00:33 .gstreamer-0.10
INFO:root:-rw-r--r-- 1 vinay vinay 108 2008-04-10 00:33 .gtk-
bookmarks
INFO:root:dr-x------ 2 vinay vinay 0 2008-04-10 00:33 .gvfs
INFO:root:-rw------- 1 vinay vinay 167 2008-04-10
00:33 .ICEauthority
INFO:root:drwxr-xr-x 3 vinay vinay 4096 2008-03-22 07:18 .local
INFO:root:drwx------ 3 vinay vinay 4096 2008-03-22 07:18 .metacity
INFO:root:drwx------ 4 vinay vinay 4096 2008-03-24 19:13 .mozilla
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-03-22 07:17 Music
INFO:root:drwxr-xr-x 3 vinay vinay 4096 2008-04-10 00:31 .nautilus
INFO:root:drwxr-xr-x 3 vinay vinay 4096 2008-04-05 02:09 .netbeans
INFO:root:drwxr-xr-x 3 vinay vinay 4096 2008-04-05 02:09 .netbeans-
registration
INFO:root:drwx------ 3 vinay vinay 4096 2008-04-05
02:15 .openoffice.org2
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-03-22 07:17 Pictures
INFO:root:-rw-r--r-- 1 vinay vinay 566 2008-03-22 07:09 .profile
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-03-22 07:17 Public
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-03-22 08:01 .pulse
INFO:root:-rw------- 1 vinay vinay 256 2008-03-22 07:17 .pulse-
cookie
INFO:root:-rw-r--r-- 1 vinay vinay 1973 2008-04-10 18:07 .recently-
used.xbel
INFO:root:drwx------ 2 vinay vinay 4096 2008-03-22 07:17 .ssh
INFO:root:drwxr-xr-x 3 vinay vinay 4096 2008-04-05 02:09 .subversion
INFO:root:-rw-r--r-- 1 vinay vinay 0 2008-03-22
07:34 .sudo_as_admin_successful
INFO:root:drwxr-xr-x 4 vinay vinay 4096 2008-03-22 09:10 .sudoku
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-03-22 07:17 Templates
INFO:root:-rw-r--r-- 1 vinay vinay 339 2008-04-10 18:07 test.py
INFO:root:-rw-r--r-- 1 vinay vinay 303 2008-04-10 18:07 test.py~
INFO:root:-rwxr--r-- 1 vinay vinay 75 2008-03-22 07:33 update
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-03-22 08:22 .update-
manager-core
INFO:root:drwx------ 2 vinay vinay 4096 2008-03-22 07:18 .update-
notifier
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-03-22 07:17 Videos
INFO:root:drwxr-xr-x 7 vinay vinay 4096 2007-10-08 14:56 vmware-tools-
distrib
INFO:root:drwxr-xr-x 2 vinay vinay 4096 2008-04-07 00:19 .wapi
INFO:root:-rw------- 1 vinay vinay 121 2008-04-10 00:33 .Xauthority
INFO:root:-rw-r--r-- 1 vinay vinay 146 2008-04-09
21:33 .xscreensaver-getimage.cache
INFO:root:-rw-r--r-- 1 vinay vinay 5102 2008-04-10 17:31 .xsession-
errors

You should be able to adapt this to your specific requirement.

Regards,

Vinay Sajip

N.B. This test was run using Python 2.5.2 on Ubuntu Hardy Heron
(beta):

Python 2.5.2 (r252:60911, Apr 8 2008, 21:49:41)
[GCC 4.2.3 (Ubuntu 4.2.3-2ubuntu7)] on linux2
 
S

svensven

Thomas said:
>> My goal is to have stdout and stderr written to a logging handler.
>> This code does not work:
>>
>> # START
>> import logging, subprocess
>> ch = logging.StreamHandler()
>> ch.setLevel(logging.DEBUG)
>> subprocess.call(['ls', '-la'], 0, None, None, ch, ch)
>> # END
>
> What is wrong with doing something like:
>
> import logging, subprocess
> ch = logging.StreamHandler()
> ch.setLevel(logging.DEBUG)
>
> s = subprocess.Popen( ['ls','-la'], stdout=subprocess.PIPE )
> while 1:
> ch.info( s.stdout.readline() )
> if s.poll() == None:
> break
>
> Perhaps not the most efficient or clean solution, but that is how I
> usually do it (note: I didn't test the above code).

Thanks, Thomas. That was actually far less messy than I had imagined.
I got it to work -- almost work -- using this code:

import logging, subprocess
logger = logging.getLogger("simple_example")
logger.setLevel(logging.DEBUG)
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)
formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s -
%(message)s")
ch.setFormatter(formatter)
logger.addHandler(ch)
s = subprocess.Popen(["ping", "-c", "5", "127.0.0.1"],
stdout=subprocess.PIPE, bufsize=1024)
while s.poll() == None:
logger.info( s.stdout.readline().strip() )

The problem is that the .poll() seems to be a bit too agressive, so
the while loop will quit before the process actually finishes. In the
ping example above, it will show the pings, but it will skip the
summary at the end.

The response by Vinay Sajip seems to work just fine, though.

Sven
 
S

svensven

Vinay said:
>
> Thomas was almost right, but not quite - you can't call info on a
> Handler instance, only on a Logger instance. The following script:

Yes, but that was easily fixed. Still there seemed to be a problem
there with the .poll(), since it would think the process ended while
it was actually running. The result was that only some of the command
output was shown.
> import logging
> import subprocess
>
> logging.basicConfig(level=logging.INFO) # will log to stderr of this
> script
>
> s = subprocess.Popen( ['ls','-la'], stdout=subprocess.PIPE )
> while 1:
> line = s.stdout.readline()
> exitcode = s.poll()
> if (not line) and (exitcode is not None):
> break
> line = line[:-1]
> logging.info("%s", line)

This works perfectly, as far as I can tell. You seem to use another
conditional, though.

I'll take a closer look at this tomorrow. Thanks for the clean
solution, Vinay.

sven
 
T

Thomas Dimson

Vinay Sajip wrote:

 >> My goal is to have stdout and stderr written to a logginghandler.
 >
 > Thomas was almost right, but not quite - you can't call info on a
 > Handler instance, only on a Logger instance. The following script:

Yes, but that was easily fixed. Still there seemed to be a problem
there with the .poll(), since it would think the process ended while
it was actually running. The result was that only some of the command
output was shown.

 > import logging
 > import subprocess
 >
 > logging.basicConfig(level=logging.INFO) # will log to stderr of this
 > script
 >
 > s = subprocess.Popen( ['ls','-la'], stdout=subprocess.PIPE )
 > while 1:
 >     line = s.stdout.readline()
 >     exitcode = s.poll()
 >     if (not line) and (exitcode is not None):
 >   break
 >     line = line[:-1]
 >     logging.info("%s", line)

This works perfectly, as far as I can tell. You seem to use another
conditional, though.

I'll take a closer look at this tomorrow. Thanks for the clean
solution, Vinay.

sven

I think what I actually meant was:

s = subprocess.Popen( ['ls','-la'], stdout=subprocess.PIPE )
while 1:
line = s.stdout.readline()
if not line:
break
logging.info( line )

The problem with p.poll() is that the process probably has ended
before you have gotten all the text out of the buffer. Readline will
return a falsy value when the process ends.

Anyway, this post has a lot of responses so I'm sure _something_
works :)
 

Ask a Question

Want to reply to this thread or ask your own question?

You'll need to choose a username for the site, which only take a couple of moments. After that, you can post your question and our members will help you out.

Ask a Question

Members online

Forum statistics

Threads
473,768
Messages
2,569,574
Members
45,048
Latest member
verona

Latest Threads

Top