IPython.parallel logging cleanup

* prevent log propagation (fixes duplicate messages on ipcluster exit)
* hook up util.signal_children log message to running application

IPython/parallel/apps/baseapp.py

@@ -1,241 +1,245 b''
 #!/usr/bin/env python
 # encoding: utf-8
 """
 The Base Application class for IPython.parallel apps
 
 Authors:
 
 * Brian Granger
 * Min RK
 
 """
 
 #-----------------------------------------------------------------------------
 #  Copyright (C) 2008-2011  The IPython Development Team
 #
 #  Distributed under the terms of the BSD License.  The full license is in
 #  the file COPYING, distributed as part of this software.
 #-----------------------------------------------------------------------------
 
 #-----------------------------------------------------------------------------
 # Imports
 #-----------------------------------------------------------------------------
 
 from __future__ import with_statement
 
 import os
 import logging
 import re
 import sys
 
 from subprocess import Popen, PIPE
 
 from IPython.core import release
 from IPython.core.crashhandler import CrashHandler
 from IPython.core.application import (
     BaseIPythonApplication,
     base_aliases as base_ip_aliases,
     base_flags as base_ip_flags
 )
 from IPython.utils.path import expand_path
 
 from IPython.utils.traitlets import Unicode, Bool, Instance, Dict, List
 
 #-----------------------------------------------------------------------------
 # Module errors
 #-----------------------------------------------------------------------------
 
 class PIDFileError(Exception):
     pass
 
 
 #-----------------------------------------------------------------------------
 # Crash handler for this application
 #-----------------------------------------------------------------------------
 
 class ParallelCrashHandler(CrashHandler):
     """sys.excepthook for IPython itself, leaves a detailed report on disk."""
 
     def __init__(self, app):
         contact_name = release.authors['Min'][0]
         contact_email = release.authors['Min'][1]
         bug_tracker = 'http://github.com/ipython/ipython/issues'
         super(ParallelCrashHandler,self).__init__(
             app, contact_name, contact_email, bug_tracker
         )
 
 
 #-----------------------------------------------------------------------------
 # Main application
 #-----------------------------------------------------------------------------
 base_aliases = {}
 base_aliases.update(base_ip_aliases)
 base_aliases.update({
     'profile-dir' : 'ProfileDir.location',
     'work-dir' : 'BaseParallelApplication.work_dir',
     'log-to-file' : 'BaseParallelApplication.log_to_file',
     'clean-logs' : 'BaseParallelApplication.clean_logs',
     'log-url' : 'BaseParallelApplication.log_url',
 })
 
 base_flags = {
     'log-to-file' : (
         {'BaseParallelApplication' : {'log_to_file' : True}},
         "send log output to a file"
     )
 }
 base_flags.update(base_ip_flags)
 
 class BaseParallelApplication(BaseIPythonApplication):
     """The base Application for IPython.parallel apps
     
     Principle extensions to BaseIPyythonApplication:
     
     * work_dir
     * remote logging via pyzmq
     * IOLoop instance
     """
 
     crash_handler_class = ParallelCrashHandler
     
     def _log_level_default(self):
         # temporarily override default_log_level to INFO
         return logging.INFO
 
     work_dir = Unicode(os.getcwdu(), config=True,
         help='Set the working dir for the process.'
     )
     def _work_dir_changed(self, name, old, new):
         self.work_dir = unicode(expand_path(new))
 
     log_to_file = Bool(config=True,
         help="whether to log to a file")
 
     clean_logs = Bool(False, config=True,
         help="whether to cleanup old logfiles before starting")
 
     log_url = Unicode('', config=True,
         help="The ZMQ URL of the iplogger to aggregate logging.")
 
     def _config_files_default(self):
         return ['ipcontroller_config.py', 'ipengine_config.py', 'ipcluster_config.py']
     
     loop = Instance('zmq.eventloop.ioloop.IOLoop')
     def _loop_default(self):
         from zmq.eventloop.ioloop import IOLoop
         return IOLoop.instance()
 
     aliases = Dict(base_aliases)
     flags = Dict(base_flags)
     
     def initialize(self, argv=None):
         """initialize the app"""
         super(BaseParallelApplication, self).initialize(argv)
         self.to_work_dir()
         self.reinit_logging()
         
     def to_work_dir(self):
         wd = self.work_dir
         if unicode(wd) != os.getcwdu():
             os.chdir(wd)
             self.log.info("Changing to working dir: %s" % wd)
         # This is the working dir by now.
         sys.path.insert(0, '')
 
     def reinit_logging(self):
         # Remove old log files
         log_dir = self.profile_dir.log_dir
         if self.clean_logs:
             for f in os.listdir(log_dir):
                 if re.match(r'%s-\d+\.(log|err|out)'%self.name,f):
                     os.remove(os.path.join(log_dir, f))
         if self.log_to_file:
             # Start logging to the new log file
             log_filename = self.name + u'-' + str(os.getpid()) + u'.log'
             logfile = os.path.join(log_dir, log_filename)
             open_log_file = open(logfile, 'w')
         else:
             open_log_file = None
         if open_log_file is not None:
             self.log.removeHandler(self._log_handler)
             self._log_handler = logging.StreamHandler(open_log_file)
             self._log_formatter = logging.Formatter("[%(name)s] %(message)s")
             self._log_handler.setFormatter(self._log_formatter)
             self.log.addHandler(self._log_handler)
+        # do not propagate log messages to root logger
+        # ipcluster app will sometimes print duplicate messages during shutdown
+        # if this is 1 (default):
+        self.log.propagate = False
 
     def write_pid_file(self, overwrite=False):
         """Create a .pid file in the pid_dir with my pid.
 
         This must be called after pre_construct, which sets `self.pid_dir`.
         This raises :exc:`PIDFileError` if the pid file exists already.
         """
         pid_file = os.path.join(self.profile_dir.pid_dir, self.name + u'.pid')
         if os.path.isfile(pid_file):
             pid = self.get_pid_from_file()
             if not overwrite:
                 raise PIDFileError(
                     'The pid file [%s] already exists. \nThis could mean that this '
                     'server is already running with [pid=%s].' % (pid_file, pid)
                 )
         with open(pid_file, 'w') as f:
             self.log.info("Creating pid file: %s" % pid_file)
             f.write(repr(os.getpid())+'\n')
 
     def remove_pid_file(self):
         """Remove the pid file.
 
         This should be called at shutdown by registering a callback with
         :func:`reactor.addSystemEventTrigger`. This needs to return
         ``None``.
         """
         pid_file = os.path.join(self.profile_dir.pid_dir, self.name + u'.pid')
         if os.path.isfile(pid_file):
             try:
                 self.log.info("Removing pid file: %s" % pid_file)
                 os.remove(pid_file)
             except:
                 self.log.warn("Error removing the pid file: %s" % pid_file)
 
     def get_pid_from_file(self):
         """Get the pid from the pid file.
 
         If the  pid file doesn't exist a :exc:`PIDFileError` is raised.
         """
         pid_file = os.path.join(self.profile_dir.pid_dir, self.name + u'.pid')
         if os.path.isfile(pid_file):
             with open(pid_file, 'r') as f:
                 s = f.read().strip()
                 try:
                     pid = int(s)
                 except:
                     raise PIDFileError("invalid pid file: %s (contents: %r)"%(pid_file, s))
                 return pid
         else:
             raise PIDFileError('pid file not found: %s' % pid_file)
     
     def check_pid(self, pid):
         if os.name == 'nt':
             try:
                 import ctypes
                 # returns 0 if no such process (of ours) exists
                 # positive int otherwise
                 p = ctypes.windll.kernel32.OpenProcess(1,0,pid)
             except Exception:
                 self.log.warn(
                     "Could not determine whether pid %i is running via `OpenProcess`. "
                     " Making the likely assumption that it is."%pid
                 )
                 return True
             return bool(p)
         else:
             try:
                 p = Popen(['ps','x'], stdout=PIPE, stderr=PIPE)
                 output,_ = p.communicate()
             except OSError:
                 self.log.warn(
                     "Could not determine whether pid %i is running via `ps x`. "
                     " Making the likely assumption that it is."%pid
                 )
                 return True
             pids = map(int, re.findall(r'^\W*\d+', output, re.MULTILINE))
             return pid in pids

IPython/parallel/util.py

@@ -1,461 +1,463 b''
 """some generic utilities for dealing with classes, urls, and serialization
 
 Authors:
 
 * Min RK
 """
 #-----------------------------------------------------------------------------
 #  Copyright (C) 2010-2011  The IPython Development Team
 #
 #  Distributed under the terms of the BSD License.  The full license is in
 #  the file COPYING, distributed as part of this software.
 #-----------------------------------------------------------------------------
 
 #-----------------------------------------------------------------------------
 # Imports
 #-----------------------------------------------------------------------------
 
 # Standard library imports.
 import logging
 import os
 import re
 import stat
 import socket
 import sys
 from signal import signal, SIGINT, SIGABRT, SIGTERM
 try:
     from signal import SIGKILL
 except ImportError:
     SIGKILL=None
 
 try:
     import cPickle
     pickle = cPickle
 except:
     cPickle = None
     import pickle
 
 # System library imports
 import zmq
 from zmq.log import handlers
 
 # IPython imports
+from IPython.config.application import Application
 from IPython.utils.pickleutil import can, uncan, canSequence, uncanSequence
 from IPython.utils.newserialized import serialize, unserialize
 from IPython.zmq.log import EnginePUBHandler
 
 #-----------------------------------------------------------------------------
 # Classes
 #-----------------------------------------------------------------------------
 
 class Namespace(dict):
     """Subclass of dict for attribute access to keys."""
     
     def __getattr__(self, key):
         """getattr aliased to getitem"""
         if key in self.iterkeys():
             return self[key]
         else:
             raise NameError(key)
 
     def __setattr__(self, key, value):
         """setattr aliased to setitem, with strict"""
         if hasattr(dict, key):
             raise KeyError("Cannot override dict keys %r"%key)
         self[key] = value
     
 
 class ReverseDict(dict):
     """simple double-keyed subset of dict methods."""
     
     def __init__(self, *args, **kwargs):
         dict.__init__(self, *args, **kwargs)
         self._reverse = dict()
         for key, value in self.iteritems():
             self._reverse[value] = key
     
     def __getitem__(self, key):
         try:
             return dict.__getitem__(self, key)
         except KeyError:
             return self._reverse[key]
     
     def __setitem__(self, key, value):
         if key in self._reverse:
             raise KeyError("Can't have key %r on both sides!"%key)
         dict.__setitem__(self, key, value)
         self._reverse[value] = key
     
     def pop(self, key):
         value = dict.pop(self, key)
         self._reverse.pop(value)
         return value
     
     def get(self, key, default=None):
         try:
             return self[key]
         except KeyError:
             return default
 
 #-----------------------------------------------------------------------------
 # Functions
 #-----------------------------------------------------------------------------
 
 def asbytes(s):
     """ensure that an object is ascii bytes"""
     if isinstance(s, unicode):
         s = s.encode('ascii')
     return s
 
 def validate_url(url):
     """validate a url for zeromq"""
     if not isinstance(url, basestring):
         raise TypeError("url must be a string, not %r"%type(url))
     url = url.lower()
     
     proto_addr = url.split('://')
     assert len(proto_addr) == 2, 'Invalid url: %r'%url
     proto, addr = proto_addr
     assert proto in ['tcp','pgm','epgm','ipc','inproc'], "Invalid protocol: %r"%proto
     
     # domain pattern adapted from http://www.regexlib.com/REDetails.aspx?regexp_id=391
     # author: Remi Sabourin
     pat = re.compile(r'^([\w\d]([\w\d\-]{0,61}[\w\d])?\.)*[\w\d]([\w\d\-]{0,61}[\w\d])?$')
     
     if proto == 'tcp':
         lis = addr.split(':')
         assert len(lis) == 2, 'Invalid url: %r'%url
         addr,s_port = lis
         try:
             port = int(s_port)
         except ValueError:
             raise AssertionError("Invalid port %r in url: %r"%(port, url))
         
         assert addr == '*' or pat.match(addr) is not None, 'Invalid url: %r'%url
         
     else:
         # only validate tcp urls currently
         pass
     
     return True
 
 
 def validate_url_container(container):
     """validate a potentially nested collection of urls."""
     if isinstance(container, basestring):
         url = container
         return validate_url(url)
     elif isinstance(container, dict):
         container = container.itervalues()
     
     for element in container:
         validate_url_container(element)
 
 
 def split_url(url):
     """split a zmq url (tcp://ip:port) into ('tcp','ip','port')."""
     proto_addr = url.split('://')
     assert len(proto_addr) == 2, 'Invalid url: %r'%url
     proto, addr = proto_addr
     lis = addr.split(':')
     assert len(lis) == 2, 'Invalid url: %r'%url
     addr,s_port = lis
     return proto,addr,s_port
     
 def disambiguate_ip_address(ip, location=None):
     """turn multi-ip interfaces '0.0.0.0' and '*' into connectable
     ones, based on the location (default interpretation of location is localhost)."""
     if ip in ('0.0.0.0', '*'):
         try:
             external_ips = socket.gethostbyname_ex(socket.gethostname())[2]
         except (socket.gaierror, IndexError):
             # couldn't identify this machine, assume localhost
             external_ips = []
         if location is None or location in external_ips or not external_ips:
             # If location is unspecified or cannot be determined, assume local
             ip='127.0.0.1'
         elif location:
             return location
     return ip
 
 def disambiguate_url(url, location=None):
     """turn multi-ip interfaces '0.0.0.0' and '*' into connectable
     ones, based on the location (default interpretation is localhost).
     
     This is for zeromq urls, such as tcp://*:10101."""
     try:
         proto,ip,port = split_url(url)
     except AssertionError:
         # probably not tcp url; could be ipc, etc.
         return url
     
     ip = disambiguate_ip_address(ip,location)
     
     return "%s://%s:%s"%(proto,ip,port)
 
 def serialize_object(obj, threshold=64e-6):
     """Serialize an object into a list of sendable buffers.
     
     Parameters
     ----------
     
     obj : object
         The object to be serialized
     threshold : float
         The threshold for not double-pickling the content.
         
     
     Returns
     -------
     ('pmd', [bufs]) :
         where pmd is the pickled metadata wrapper,
         bufs is a list of data buffers
     """
     databuffers = []
     if isinstance(obj, (list, tuple)):
         clist = canSequence(obj)
         slist = map(serialize, clist)
         for s in slist:
             if s.typeDescriptor in ('buffer', 'ndarray') or s.getDataSize() > threshold:
                 databuffers.append(s.getData())
                 s.data = None
         return pickle.dumps(slist,-1), databuffers
     elif isinstance(obj, dict):
         sobj = {}
         for k in sorted(obj.iterkeys()):
             s = serialize(can(obj[k]))
             if s.typeDescriptor in ('buffer', 'ndarray') or s.getDataSize() > threshold:
                 databuffers.append(s.getData())
                 s.data = None
             sobj[k] = s
         return pickle.dumps(sobj,-1),databuffers
     else:
         s = serialize(can(obj))
         if s.typeDescriptor in ('buffer', 'ndarray') or s.getDataSize() > threshold:
             databuffers.append(s.getData())
             s.data = None
         return pickle.dumps(s,-1),databuffers
             
         
 def unserialize_object(bufs):
     """reconstruct an object serialized by serialize_object from data buffers."""
     bufs = list(bufs)
     sobj = pickle.loads(bufs.pop(0))
     if isinstance(sobj, (list, tuple)):
         for s in sobj:
             if s.data is None:
                 s.data = bufs.pop(0)
         return uncanSequence(map(unserialize, sobj)), bufs
     elif isinstance(sobj, dict):
         newobj = {}
         for k in sorted(sobj.iterkeys()):
             s = sobj[k]
             if s.data is None:
                 s.data = bufs.pop(0)
             newobj[k] = uncan(unserialize(s))
         return newobj, bufs
     else:
         if sobj.data is None:
             sobj.data = bufs.pop(0)
         return uncan(unserialize(sobj)), bufs
 
 def pack_apply_message(f, args, kwargs, threshold=64e-6):
     """pack up a function, args, and kwargs to be sent over the wire
     as a series of buffers. Any object whose data is larger than `threshold`
     will not have their data copied (currently only numpy arrays support zero-copy)"""
     msg = [pickle.dumps(can(f),-1)]
     databuffers = [] # for large objects
     sargs, bufs = serialize_object(args,threshold)
     msg.append(sargs)
     databuffers.extend(bufs)
     skwargs, bufs = serialize_object(kwargs,threshold)
     msg.append(skwargs)
     databuffers.extend(bufs)
     msg.extend(databuffers)
     return msg
 
 def unpack_apply_message(bufs, g=None, copy=True):
     """unpack f,args,kwargs from buffers packed by pack_apply_message()
     Returns: original f,args,kwargs"""
     bufs = list(bufs) # allow us to pop
     assert len(bufs) >= 3, "not enough buffers!"
     if not copy:
         for i in range(3):
             bufs[i] = bufs[i].bytes
     cf = pickle.loads(bufs.pop(0))
     sargs = list(pickle.loads(bufs.pop(0)))
     skwargs = dict(pickle.loads(bufs.pop(0)))
     # print sargs, skwargs
     f = uncan(cf, g)
     for sa in sargs:
         if sa.data is None:
             m = bufs.pop(0)
             if sa.getTypeDescriptor() in ('buffer', 'ndarray'):
                 # always use a buffer, until memoryviews get sorted out
                 sa.data = buffer(m)
                 # disable memoryview support
                 # if copy:
                 #     sa.data = buffer(m)
                 # else:
                 #     sa.data = m.buffer
             else:
                 if copy:
                     sa.data = m
                 else:
                     sa.data = m.bytes
     
     args = uncanSequence(map(unserialize, sargs), g)
     kwargs = {}
     for k in sorted(skwargs.iterkeys()):
         sa = skwargs[k]
         if sa.data is None:
             m = bufs.pop(0)
             if sa.getTypeDescriptor() in ('buffer', 'ndarray'):
                 # always use a buffer, until memoryviews get sorted out
                 sa.data = buffer(m)
                 # disable memoryview support
                 # if copy:
                 #     sa.data = buffer(m)
                 # else:
                 #     sa.data = m.buffer
             else:
                 if copy:
                     sa.data = m
                 else:
                     sa.data = m.bytes
 
         kwargs[k] = uncan(unserialize(sa), g)
     
     return f,args,kwargs
 
 #--------------------------------------------------------------------------
 # helpers for implementing old MEC API via view.apply
 #--------------------------------------------------------------------------
 
 def interactive(f):
     """decorator for making functions appear as interactively defined.
     This results in the function being linked to the user_ns as globals()
     instead of the module globals().
     """
     f.__module__ = '__main__'
     return f
 
 @interactive
 def _push(ns):
     """helper method for implementing `client.push` via `client.apply`"""
     globals().update(ns)
 
 @interactive
 def _pull(keys):
     """helper method for implementing `client.pull` via `client.apply`"""
     user_ns = globals()
     if isinstance(keys, (list,tuple, set)):
         for key in keys:
             if not user_ns.has_key(key):
                 raise NameError("name '%s' is not defined"%key)
         return map(user_ns.get, keys)
     else:
         if not user_ns.has_key(keys):
             raise NameError("name '%s' is not defined"%keys)
         return user_ns.get(keys)
 
 @interactive
 def _execute(code):
     """helper method for implementing `client.execute` via `client.apply`"""
     exec code in globals()
 
 #--------------------------------------------------------------------------
 # extra process management utilities
 #--------------------------------------------------------------------------
 
 _random_ports = set()
 
 def select_random_ports(n):
     """Selects and return n random ports that are available."""
     ports = []
     for i in xrange(n):
         sock = socket.socket()
         sock.bind(('', 0))
         while sock.getsockname()[1] in _random_ports:
             sock.close()
             sock = socket.socket()
             sock.bind(('', 0))
         ports.append(sock)
     for i, sock in enumerate(ports):
         port = sock.getsockname()[1]
         sock.close()
         ports[i] = port
         _random_ports.add(port)
     return ports
 
 def signal_children(children):
     """Relay interupt/term signals to children, for more solid process cleanup."""
     def terminate_children(sig, frame):
-        logging.critical("Got signal %i, terminating children..."%sig)
+        log = Application.instance().log
+        log.critical("Got signal %i, terminating children..."%sig)
         for child in children:
             child.terminate()
         
         sys.exit(sig != SIGINT)
         # sys.exit(sig)
     for sig in (SIGINT, SIGABRT, SIGTERM):
         signal(sig, terminate_children)
 
 def generate_exec_key(keyfile):
     import uuid
     newkey = str(uuid.uuid4())
     with open(keyfile, 'w') as f:
         # f.write('ipython-key ')
         f.write(newkey+'\n')
     # set user-only RW permissions (0600)
     # this will have no effect on Windows
     os.chmod(keyfile, stat.S_IRUSR|stat.S_IWUSR)
 
 
 def integer_loglevel(loglevel):
     try:
         loglevel = int(loglevel)
     except ValueError:
         if isinstance(loglevel, str):
             loglevel = getattr(logging, loglevel)
     return loglevel
 
 def connect_logger(logname, context, iface, root="ip", loglevel=logging.DEBUG):
     logger = logging.getLogger(logname)
     if any([isinstance(h, handlers.PUBHandler) for h in logger.handlers]):
         # don't add a second PUBHandler
         return
     loglevel = integer_loglevel(loglevel)
     lsock = context.socket(zmq.PUB)
     lsock.connect(iface)
     handler = handlers.PUBHandler(lsock)
     handler.setLevel(loglevel)
     handler.root_topic = root
     logger.addHandler(handler)
     logger.setLevel(loglevel)
 
 def connect_engine_logger(context, iface, engine, loglevel=logging.DEBUG):
     logger = logging.getLogger()
     if any([isinstance(h, handlers.PUBHandler) for h in logger.handlers]):
         # don't add a second PUBHandler
         return
     loglevel = integer_loglevel(loglevel)
     lsock = context.socket(zmq.PUB)
     lsock.connect(iface)
     handler = EnginePUBHandler(engine, lsock)
     handler.setLevel(loglevel)
     logger.addHandler(handler)
     logger.setLevel(loglevel)
     return logger
 
 def local_logger(logname, loglevel=logging.DEBUG):
     loglevel = integer_loglevel(loglevel)
     logger = logging.getLogger(logname)
     if any([isinstance(h, logging.StreamHandler) for h in logger.handlers]):
         # don't add a second StreamHandler
         return
     handler = logging.StreamHandler()
     handler.setLevel(loglevel)
     logger.addHandler(handler)
     logger.setLevel(loglevel)
     return logger