Changed logging to Twisted logging

airpnp/AirPlayService.py

@@ -22,7 +22,6 @@
 
 import platform
 import uuid
-import logging
 
 from datetime import datetime
 from urlparse import urlparse, parse_qsl
@@ -31,11 +30,10 @@
 from twisted.internet.protocol import Protocol, Factory
 from twisted.application.service import MultiService
 from twisted.application.internet import TCPServer
+from twisted.python import log
 from httplib import HTTPMessage
 from cStringIO import StringIO
 
-log = logging.getLogger('airpnp.airplayservice')
-
 __all__ = ["BaseAirPlayRequest", "AirPlayService", "AirPlayProtocolHandler"]
 
 class Request(object):
@@ -53,7 +51,7 @@ class AirPlayProtocolBase(Protocol):
     request = None
 
     def connectionMade(self):
-        log.info('AirPlay connection from %r', (self.transport.getPeer(), ))
+        log.msg('AirPlay connection from %r', (self.transport.getPeer(), ))
 
     def dataReceived(self, data):
         if self.request is None:
@@ -90,15 +88,9 @@ def dataReceived(self, data):
             # reset the buffer to only contain the body part
             r.buffer = body
 
-            log.debug('Received AirPlay headers, uri = %s, content-length = %d'
-                      % (r.uri, r.content_length))
-
         if not r.headers is None and len(r.buffer) == r.content_length:
             r.body = r.buffer
-            log.debug('Received entire AirPlay message, body length = %d, processing...' 
-                      % (len(r.body), ))
             self.process_message(r)
-
             self.request = None
 
     def process_message(self, request):
@@ -215,8 +207,8 @@ def _process(self, request):
             content = content % (service.deviceid, service.features, service.model)
             answer = self.create_request(200, "Content-Type: text/x-apple-plist+xml", content)
         else:
-            log.error("ERROR: AirPlay - Unable to handle request \"%s\"" %
-                      (self.uri))
+            log.msg("ERROR: AirPlay - Unable to handle request \"%s\"" %
+                    (self.uri))
             answer = self.create_request(404)
 
         if(answer is not ""):
@@ -254,6 +246,7 @@ class AirPlayFactory(Factory):
 
     def __init__(self, service):
         self.service = service
+        self.noisy = False
 
 
 class AirPlayService(MultiService):
@@ -281,10 +274,10 @@ def __init__(self, name=None, host="0.0.0.0", port=22555):
 
     def startService(self):
         MultiService.startService(self)
-        log.info("AirPlayService '%s' is running at %s:%d" % (self.name_, self.host,
-                                                              self.port))
+        log.msg("AirPlayService '%s' is running at %s:%d" % (self.name_, self.host,
+                                                             self.port))
     def stopService(self):
-        log.info("AirPlayService '%s' was stopped" % (self.name_, ))
+        log.msg("AirPlayService '%s' was stopped" % (self.name_, ))
         return MultiService.stopService(self)
 
     def get_scrub(self):

airpnp/airpnp.tac

@@ -26,21 +26,8 @@
 # ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
 # POSSIBILITY OF SUCH DAMAGE.
 
-import logging
-import logging.config
-import os.path
-
-RCFILE = os.path.expanduser('~/.airpnprc')
-
-# Must configure logging before importing other modules
-if os.path.isfile(RCFILE):
-    logging.config.fileConfig(RCFILE)
-else:
-    logging.basicConfig(level='INFO')
-
 from bridge import BridgeServer
 from twisted.application.service import Application
 
 application = Application('airpnp')
 BridgeServer().setServiceParent(application)
-

airpnp/bridge.py

@@ -26,10 +26,10 @@
 # ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
 # POSSIBILITY OF SUCH DAMAGE.
 
-import logging
 from device_discovery import DeviceDiscoveryService
 from AirPlayService import AirPlayService
 from util import hms_to_sec, sec_to_hms
+from twisted.python import log
 
 
 MEDIA_RENDERER_DEVICE_TYPE = 'urn:schemas-upnp-org:device:MediaRenderer:1'
@@ -41,8 +41,6 @@
 CN_MGR_SERVICE = 'urn:upnp-org:serviceId:ConnectionManager'
 AVT_SERVICE = 'urn:upnp-org:serviceId:AVTransport'
 
-log = logging.getLogger("airpnp.bridge-server")
-
 
 class BridgeServer(DeviceDiscoveryService):
 
@@ -53,14 +51,14 @@ def __init__(self):
                                         [MEDIA_RENDERER_DEVICE_TYPE])
 
     def on_device_found(self, device):
-        log.info('Found device %s with base URL %s' % (device,
-                                                       device.get_base_url()))
+        log.msg('Found device %s with base URL %s' % (device,
+                                                      device.get_base_url()))
         avc = AVControlPoint(device, port=self._find_port())
         avc.setName(device.UDN)
         avc.setServiceParent(self)
 
     def on_device_removed(self, device):
-        log.info('Lost device %s' % (device, ))
+        log.msg('Lost device %s' % (device, ))
         avc = self.getServiceNamed(device.UDN)
         avc.disownServiceParent()
 
@@ -95,28 +93,28 @@ def get_scrub(self):
         if not self._uri is None:
             duration = hms_to_sec(posinfo['TrackDuration'])
             position = hms_to_sec(posinfo['RelTime'])
-            log.debug(('get_scrub -> GetPositionInfo -> %s, %s -> ' +
-                      'returning %f, %f') % (posinfo['TrackDuration'],
-                                             posinfo['RelTime'], duration,
-                                             position))
+            log.msg(('get_scrub -> GetPositionInfo -> %s, %s -> ' +
+                     'returning %f, %f') % (posinfo['TrackDuration'],
+                                            posinfo['RelTime'], duration,
+                                            position))
 
             if not self._position_pct is None:
                 self._try_seek_pct(duration, position)
 
             return duration, position
         else:
-            log.debug('get_scrub -> (no URI) -> returning 0.0, 0.0')
+            log.msg('get_scrub -> (no URI) -> returning 0.0, 0.0')
             return 0.0, 0.0
 
     def is_playing(self):
         if self._uri is not None:
             state = self._get_current_transport_state()
             playing = state == 'PLAYING'
-            log.debug('is_playing -> GetTransportInfo -> %s -> returning %r' %
-                      (state, playing))
+            log.msg('is_playing -> GetTransportInfo -> %s -> returning %r' %
+                    (state, playing))
             return playing
         else:
-            log.debug('is_playing -> (no URI) -> returning False')
+            log.msg('is_playing -> (no URI) -> returning False')
             return False
 
     def _get_current_transport_state(self):
@@ -127,19 +125,19 @@ def _get_current_transport_state(self):
     def set_scrub(self, position):
         if self._uri is not None:
             hms = sec_to_hms(position)
-            log.debug('set_scrub (%f) -> Seek (%s)' % (position, hms))
+            log.msg('set_scrub (%f) -> Seek (%s)' % (position, hms))
             self._avtransport.Seek(InstanceID=self._instance_id,
                                    Unit='REL_TIME', Target=hms)
         else:
-            log.debug('set_scrub (%f) -> (no URI) -> saved for later' %
-                      (position, ))
+            log.msg('set_scrub (%f) -> (no URI) -> saved for later' %
+                    (position, ))
 
             # save the position so that we can user it later to seek
             self._pre_scrub = position
 
     def play(self, location, position):
-        log.debug('play (%s, %f) -> SetAVTransportURI + Play' % (location,
-                                                                 position))
+        log.msg('play (%s, %f) -> SetAVTransportURI + Play' % (location,
+                                                               position))
 
         # start loading of media, also set the URI to indicate that
         # we're playing
@@ -153,7 +151,7 @@ def play(self, location, position):
 
         # if we have a saved scrub position, seek now
         if not self._pre_scrub is None:
-            log.debug('Seeking based on saved scrub position')
+            log.msg('Seeking based on saved scrub position')
             self.set_scrub(self._pre_scrub)
 
             # clear it because we have used it
@@ -165,13 +163,13 @@ def play(self, location, position):
 
     def stop(self, info):
         if self._uri is not None:
-            log.debug('stop -> Stop')
+            log.msg('stop -> Stop')
             self._avtransport.Stop(InstanceID=self._instance_id)
 
             # clear the URI to indicate that we don't play anymore
             self._uri = None
         else:
-            log.debug('stop -> (no URI) -> ignored')
+            log.msg('stop -> (no URI) -> ignored')
 
     def reverse(self, info):
         pass
@@ -181,24 +179,24 @@ def rate(self, speed):
             if (int(float(speed)) >= 1):
                 state = self._get_current_transport_state()
                 if not state == 'PLAYING' and not state == 'TRANSITIONING':
-                    log.debug('rate(%r) -> Play' % (speed, ))
+                    log.msg('rate(%r) -> Play' % (speed, ))
                     self._avtransport.Play(InstanceID=self._instance_id,
                                            Speed='1')
                 else:
-                    log.debug('rate(%r) -> ignored due to state %s' % (speed,
-                                                                       state))
+                    log.msg('rate(%r) -> ignored due to state %s' % (speed,
+                                                                     state))
 
                 if not self._position_pct is None:
                     duration, pos = self.get_scrub()
                     self._try_seek_pct(duration, pos)
             else:
-                log.debug('rate(%r) -> Pause' % (speed, ))
+                log.msg('rate(%r) -> Pause' % (speed, ))
                 self._avtransport.Pause(InstanceID=self._instance_id)
 
     def _try_seek_pct(self, duration, position):
         if duration > 0:
-            log.debug(('Has duration %f, can calculate position from ' +
-                      'percentage %f') % (duration, self._position_pct))
+            log.msg(('Has duration %f, can calculate position from ' +
+                     'percentage %f') % (duration, self._position_pct))
             targetoffset = duration * self._position_pct
 
             # clear the position percentage now that we've used it

airpnp/device.py

@@ -26,7 +26,6 @@
 # ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
 # POSSIBILITY OF SUCH DAMAGE.
 
-import logging
 import new
 from upnp import SoapMessage, SoapError, ns
 from urlparse import urljoin
@@ -36,8 +35,6 @@
     'Service',
 ]
 
-log = logging.getLogger("airpnp.device")
-
 # Mandatory XML attributes for a device
 DEVICE_ATTRS = ['deviceType', 'friendlyName', 'manufacturer',
                 'modelName', 'modelNumber', 'UDN']
@@ -47,8 +44,6 @@
 SERVICE_ATTRS = ['serviceType', 'serviceId', 'SCPDURL',
                  'controlURL', 'eventSubURL']
 
-log = logging.getLogger('airpnp.device')
-
 
 def find_elements(element, namespace, path):
     """Find elements based on path relative to an element.
@@ -87,7 +82,6 @@ def add_xml_attrs(obj, element, namespace, attrs):
             raise ValueError('Missing attribute: %s' % (attr, ))
         else:
             val = val.strip()
-            log.debug('Setting attribute %s with value %s' % (attr, val))
             setattr(obj, attr, val)
 
 
@@ -196,7 +190,6 @@ def initialize(self, scpd_element, soap_sender):
     def _add_actions(self, element, soap_sender):
         for action in find_elements(element, ns.service, 'actionList/action'):
             act = Action(self._device, action, soap_sender)
-            log.debug('Adding action with name %s' % (act.name, ))
             method = new.instancemethod(act, self, self.__class__)
             setattr(self, act.name, method)
 
@@ -222,8 +215,6 @@ def _add_arguments(self, element):
             self._arguments.append(Argument(argument))
 
     def __call__(self, service, **kwargs):
-        log.debug('Sending SOAP message for action %s, args = %r' %
-                  (self.name, kwargs))
         msg = SoapMessage(service.serviceType, self.name)
 
         # arrange the arguments by direction

airpnp/device_builder.py

@@ -26,18 +26,17 @@
 # ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
 # POSSIBILITY OF SUCH DAMAGE.
 
-import logging
 from util import split_usn, fetch_url
 from xml.etree import ElementTree
 from device import Device
+from twisted.python import log
 
 __all__ = [
     'AsyncDeviceBuilder',
     'DeviceEvent',
     'DeviceContainer',
 ]
 
-log = logging.getLogger("airpnp.device-builder")
 
 class DeviceContainer(object):
 
@@ -244,8 +243,7 @@ def _create_device(self, container):
                 # rejected device, back to main thread
                 self.reactor.callFromThread(self._device_rejected, container)
         except BaseException, err:
-            log.error('An error occurred while creating a Device object: %s' %
-                      (err, ))
+            log.err(err, 'Failed to create Device object')
             # error, back to main thread
             self.reactor.callFromThread(self._device_error, err, container)