Add logging.

13 files changed, 126 insertions, 30 deletions

diff --git a/src/livestreamer/__init__.py b/src/livestreamer/__init__.py
index 1369fe5..f8a4fa2 100644
--- a/src/livestreamer/__init__.py
+++ b/src/livestreamer/__init__.py
@@ -1,6 +1,5 @@
-from livestreamer import plugins
-from livestreamer import stream
-from livestreamer.compat import urlparse
+from . import plugins, stream
+from .compat import urlparse
 
 def resolve_url(url):
     parsed = urlparse(url)
@@ -24,3 +23,7 @@ NoPluginError = plugins.NoPluginError
 StreamError = stream.StreamError
 
 plugins.load_plugins(plugins)
+
+__all__ = ["resolve_url", "get_plugins",
+           "PluginError", "NoStreamsError", "NoPluginError",
+           "StreamError"]
diff --git a/src/livestreamer/cli.py b/src/livestreamer/cli.py
index 9dc1098..ee38685 100644
--- a/src/livestreamer/cli.py
+++ b/src/livestreamer/cli.py
@@ -1,8 +1,8 @@
-#!/usr/bin/env python3
-
 import sys, os, argparse, subprocess
 import livestreamer
+
 from livestreamer.compat import input, stdout, is_win32
+from livestreamer.logger import Logger
 
 exampleusage = """
 example usage:
@@ -15,6 +15,8 @@ Stream now playbacks in player (default is VLC).
 
 """
 
+logger = Logger("cli")
+msg_output = sys.stdout
 parser = livestreamer.utils.ArgumentParser(description="CLI program that launches streams from various streaming services in a custom video player",
                                            fromfile_prefix_chars="@",
                                            formatter_class=argparse.RawDescriptionHelpFormatter,
@@ -24,7 +26,8 @@ parser.add_argument("url", help="URL to stream", nargs="?")
 parser.add_argument("stream", help="Stream quality to play, use 'best' for highest quality available", nargs="?")
 
 parser.add_argument("-h", "--help", action="store_true", help="Show this help message and exit")
-parser.add_argument("-l", "--plugins", action="store_true", help="Print all currently installed plugins")
+parser.add_argument("-u", "--plugins", action="store_true", help="Print all currently installed plugins")
+parser.add_argument("-l", "--loglevel", metavar="level", help="Set log level, valid levels: none, error, warning, info, debug", default="info")
 
 playeropt = parser.add_argument_group("player options")
 playeropt.add_argument("-p", "--player", metavar="player", help="Command-line for player, default is 'vlc'", default="vlc")
@@ -47,7 +50,11 @@ def exit(msg):
     sys.exit(("error: {0}").format(msg))
 
 def msg(msg):
-    sys.stdout.write(msg + "\n")
+    msg_output.write(msg + "\n")
+
+def set_msg_output(output):
+    msg_output = output
+    logger.set_output(output)
 
 def write_stream(fd, out, progress):
     written = 0
@@ -60,6 +67,7 @@ def write_stream(fd, out, progress):
         try:
             out.write(data)
         except IOError:
+            logger.error("Error when reading from stream")
             break
 
         written += len(data)
@@ -70,6 +78,7 @@ def write_stream(fd, out, progress):
     if progress and written > 0:
         sys.stderr.write("\n")
 
+    logger.info("Closing stream")
     fd.close()
 
     if out != stdout:
@@ -100,16 +109,21 @@ def output_stream(stream, args):
     progress = False
     out = None
 
+    logger.info("Opening stream {0}", args.stream)
+
     try:
         fd = stream.open()
     except livestreamer.StreamError as err:
         exit(("Could not open stream - {0}").format(err))
 
+    logger.debug("Pre-buffering 8192 bytes")
     try:
         prebuffer = fd.read(8192)
     except IOError:
         exit("Failed to read data from stream")
 
+    logger.debug("Checking output")
+
     if args.output:
         if args.output == "-":
             out = stdout
@@ -128,6 +142,7 @@ def output_stream(stream, args):
             pout = sys.stderr
             perr = sys.stdout
 
+        logger.info("Starting player: {0}", args.player)
         player = subprocess.Popen(cmd, shell=True, stdout=pout, stderr=perr,
                                   stdin=subprocess.PIPE)
         out = player.stdin
@@ -139,6 +154,7 @@ def output_stream(stream, args):
         import msvcrt
         msvcrt.setmode(out.fileno(), os.O_BINARY)
 
+    logger.debug("Writing stream to output")
     out.write(prebuffer)
 
     try:
@@ -152,6 +168,8 @@ def handle_url(args):
     except livestreamer.NoPluginError:
         exit(("No plugin can handle URL: {0}").format(args.url))
 
+    logger.info("Found matching plugin {0} for URL {1}", channel.module, args.url)
+
     try:
         streams = channel.get_streams()
     except livestreamer.StreamError as err:
@@ -197,9 +215,13 @@ def main():
 
     args = parser.parse_args(arglist)
 
+    if args.stdout or args.output == "-":
+        set_msg_output(sys.stderr)
+
     livestreamer.options.set("errorlog", args.errorlog)
     livestreamer.options.set("rtmpdump", args.rtmpdump)
     livestreamer.options.set("jtvcookie", args.jtv_cookie)
+    logger.set_level(args.loglevel)
 
     if args.url:
         handle_url(args)
diff --git a/src/livestreamer/compat.py b/src/livestreamer/compat.py
index a0a055d..5bc1c3c 100644
--- a/src/livestreamer/compat.py
+++ b/src/livestreamer/compat.py
@@ -1,5 +1,3 @@
-#!/usr/bin/env python
-
 import sys, os
 
 is_py2 = (sys.version_info[0] == 2)
@@ -29,3 +27,6 @@ try:
     from urllib.parse import urlparse, parse_qs
 except ImportError:
     from urlparse import urlparse, parse_qs
+
+__all__ = ["is_py2", "is_py3", "is_win32", "input", "stdout", "str",
+           "bytes", "urllib", "urlparse", "parse_qs"]
diff --git a/src/livestreamer/logger.py b/src/livestreamer/logger.py
new file mode 100644
index 0000000..34463b4
--- /dev/null
+++ b/src/livestreamer/logger.py
@@ -0,0 +1,50 @@
+import sys
+
+class Logger(object):
+    Levels = ["none", "error", "warning", "info", "debug"]
+    Format = "[{module}][{level}] {msg}\n"
+
+    output = sys.stdout
+    level = 0
+
+    @classmethod
+    def set_level(cls, level):
+        try:
+            index = Logger.Levels.index(level)
+        except ValueError:
+            return
+
+        cls.level = index
+
+    @classmethod
+    def set_output(cls, output):
+        cls.output = output
+
+    def __init__(self, module):
+        self.module = module
+
+    def msg(self, level, msg, *args):
+        if Logger.level < level or level > len(Logger.Levels):
+            return
+
+        msg = msg.format(*args)
+
+        self.output.write(Logger.Format.format(module=self.module,
+                                               level=Logger.Levels[level],
+                                               msg=msg))
+        self.output.flush()
+
+    def error(self, msg, *args):
+        self.msg(1, msg, *args)
+
+    def warning(self, msg, *args):
+        self.msg(2, msg, *args)
+
+    def info(self, msg, *args):
+        self.msg(3, msg, *args)
+
+    def debug(self, msg, *args):
+        self.msg(4, msg, *args)
+
+
+__all__ = ["Logger"]
diff --git a/src/livestreamer/options.py b/src/livestreamer/options.py
index 51bd30d..ab04bd7 100644
--- a/src/livestreamer/options.py
+++ b/src/livestreamer/options.py
@@ -1,5 +1,3 @@
-#!/usr/bin/env python
-
 options = {
     "rtmpdump": None,
     "errorlog": False,
@@ -13,3 +11,4 @@ def get(key):
     if key in options:
         return options[key]
 
+__all__ = ["get", "set"]
diff --git a/src/livestreamer/plugins/__init__.py b/src/livestreamer/plugins/__init__.py
index c2f9d80..7e91f16 100644
--- a/src/livestreamer/plugins/__init__.py
+++ b/src/livestreamer/plugins/__init__.py
@@ -1,14 +1,15 @@
-#!/usr/bin/env python3
-
 import pkgutil
 import imp
 
+from livestreamer.logger import Logger
+
 plugins_loaded = {}
 
 class Plugin(object):
     def __init__(self, url):
         self.url = url
         self.args = None
+        self.logger = Logger("plugin." + self.module)
 
     @classmethod
     def can_handle_url(self, url):
@@ -49,3 +50,7 @@ def get_plugins():
 
 def register_plugin(name, klass):
     plugins_loaded[name] = klass
+    klass.module = name
+
+__all__ = ["Plugin", "PluginError", "NoStreamsError", "NoPluginError",
+           "load_plugins", "get_plugins", "register_plugin"]
diff --git a/src/livestreamer/plugins/justintv.py b/src/livestreamer/plugins/justintv.py
index 561c1d0..62702c6 100644
--- a/src/livestreamer/plugins/justintv.py
+++ b/src/livestreamer/plugins/justintv.py
@@ -1,5 +1,3 @@
-#!/usr/bin/env python3
-
 from livestreamer.plugins import Plugin, PluginError, NoStreamsError, register_plugin
 from livestreamer.stream import RTMPStream
 from livestreamer.utils import swfverify, urlget
@@ -41,6 +39,7 @@ class JustinTV(Plugin):
 
         metadata["title"] = self._get_node_if_exists(dom, "title")
         metadata["access_guid"] = self._get_node_if_exists(dom, "access_guid")
+        metadata["login"] = self._get_node_if_exists(dom, "login")
 
         return metadata
 
@@ -63,14 +62,22 @@ class JustinTV(Plugin):
             else:
                 return tag
 
+
         chansub = None
         if options.get("jtvcookie"):
+            self.logger.debug("Attempting to authenticate using cookie")
+
             metadata = self._get_metadata(channelname)
             chansub = metadata["access_guid"]
 
+            if "login" in metadata:
+                self.logger.debug("Successfully logged in as {0}", metadata["login"])
+
+
         randomp = int(random.random() * 999999)
         url = self.StreamInfoURL.format(channelname, randomp, chansub)
 
+        self.logger.debug("Fetching stream info")
         data = urlget(url)
 
         # fix invalid xml
@@ -86,6 +93,7 @@ class JustinTV(Plugin):
 
         nodes = dom.getElementsByTagName("nodes")[0]
 
+        self.logger.debug("Verifying SWF: {0}", self.SWFURL)
         swfhash, swfsize = swfverify(self.SWFURL)
 
         for node in nodes.childNodes:
@@ -101,10 +109,13 @@ class JustinTV(Plugin):
                 "live": True
             })
 
+            sname = clean_tag(node.tagName)
+
             if "token" in info:
                 stream.params["jtv"] = info["token"]
+            else:
+                self.logger.warning("No token found for stream {0}, this stream may fail to play", sname)
 
-            sname = clean_tag(node.tagName)
             streams[sname] = stream
 
         return streams
diff --git a/src/livestreamer/plugins/ownedtv.py b/src/livestreamer/plugins/ownedtv.py
index 5501443..418dd07 100644
--- a/src/livestreamer/plugins/ownedtv.py
+++ b/src/livestreamer/plugins/ownedtv.py
@@ -1,5 +1,3 @@
-#!/usr/bin/env python3
-
 from livestreamer.compat import urllib, bytes, str
 from livestreamer.plugins import Plugin, PluginError, NoStreamsError, register_plugin
 from livestreamer.stream import RTMPStream
@@ -35,6 +33,8 @@ class OwnedTV(Plugin):
         return "own3d.tv" in url
 
     def _get_channel_info(self, url):
+        self.logger.debug("Fetching channel info")
+
         data = urlget(url, opener=urlopener)
 
         channelid = None
@@ -65,6 +65,7 @@ class OwnedTV(Plugin):
         if not channelid:
             raise NoStreamsError(self.url)
 
+        self.logger.debug("Fetching stream info")
         data = urlget(self.ConfigURL.format(channelid))
 
         try:
@@ -76,6 +77,7 @@ class OwnedTV(Plugin):
         channels = dom.getElementsByTagName("channels")[0]
         clip = channels.getElementsByTagName("clip")[0]
 
+        self.logger.debug("Verifying SWF: {0}", swfurl)
         swfhash, swfsize = swfverify(swfurl)
 
         for item in clip.getElementsByTagName("item"):
diff --git a/src/livestreamer/plugins/svtplay.py b/src/livestreamer/plugins/svtplay.py
index 62c7555..d52ae05 100644
--- a/src/livestreamer/plugins/svtplay.py
+++ b/src/livestreamer/plugins/svtplay.py
@@ -1,5 +1,3 @@
-#!/usr/bin/env python
-
 from livestreamer.compat import str
 from livestreamer.plugins import Plugin, PluginError, NoStreamsError, register_plugin
 from livestreamer.stream import RTMPStream
@@ -18,6 +16,8 @@ class SVTPlay(Plugin):
         return "svtplay.se" in url
 
     def _get_channel_id(self, url):
+        self.logger.debug("Fetching channel id")
+
         data = urlget(url)
 
         match = re.search(b'data-json-href="/live/(\d+)"', data)
@@ -30,6 +30,7 @@ class SVTPlay(Plugin):
         if not channelid:
             raise NoStreamsError(self.url)
 
+        self.logger.debug("Fetching stream info")
         data = urlget(self.JSONURL.format(channelid))
 
         try:
@@ -40,6 +41,8 @@ class SVTPlay(Plugin):
         streams = {}
         video = verifyjson(info, "video")
         videos = verifyjson(video, "videoReferences")
+
+        self.logger.debug("Verifying SWF: {0}", self.SWFURL)
         swfhash, swfsize = swfverify(self.SWFURL)
 
         for video in videos:
diff --git a/src/livestreamer/plugins/ustreamtv.py b/src/livestreamer/plugins/ustreamtv.py
index a7b88a7..d7d37f7 100644
--- a/src/livestreamer/plugins/ustreamtv.py
+++ b/src/livestreamer/plugins/ustreamtv.py
@@ -1,5 +1,3 @@
-#!/usr/bin/env python3
-
 from livestreamer.compat import str, bytes
 from livestreamer.plugins import Plugin, PluginError, NoStreamsError, register_plugin
 from livestreamer.stream import RTMPStream
@@ -35,6 +33,7 @@ class UStreamTV(Plugin):
         if not channelid:
             raise NoStreamsError(self.url)
 
+        self.logger.debug("Fetching stream info")
         data = urlget(self.AMFURL.format(channelid))
 
         playpath = get_amf_value(data, "streamName")
diff --git a/src/livestreamer/plugins/youtube.py b/src/livestreamer/plugins/youtube.py
index 804ddbc..398657c 100644
--- a/src/livestreamer/plugins/youtube.py
+++ b/src/livestreamer/plugins/youtube.py
@@ -1,5 +1,3 @@
-#!/usr/bin/env python3
-
 from livestreamer.compat import str, bytes, parse_qs
 from livestreamer.plugins import Plugin, PluginError, NoStreamsError, register_plugin
 from livestreamer.stream import HTTPStream
diff --git a/src/livestreamer/stream.py b/src/livestreamer/stream.py
index a6aac3b..7a7e5bf 100644
--- a/src/livestreamer/stream.py
+++ b/src/livestreamer/stream.py
@@ -1,6 +1,6 @@
-from livestreamer import options
-from livestreamer.utils import urlopen
-from livestreamer.compat import str, is_win32
+from . import options
+from .utils import urlopen
+from .compat import str, is_win32
 
 import os
 import pbs
@@ -81,3 +81,5 @@ class HTTPStream(Stream):
     def open(self):
         return urlopen(self.url)
 
+
+__all__ = ["StreamError", "Stream", "StreamProcess", "RTMPStream", "HTTPStream"]
diff --git a/src/livestreamer/utils.py b/src/livestreamer/utils.py
index dcf1be3..75e7213 100644
--- a/src/livestreamer/utils.py
+++ b/src/livestreamer/utils.py
@@ -1,7 +1,6 @@
-#!/usr/bin/env python3
+from .compat import urllib
+from .plugins import PluginError
 
-from livestreamer.compat import urllib
-from livestreamer.plugins import PluginError
 import hmac, hashlib, zlib, argparse
 
 SWF_KEY = b"Genuine Adobe Flash Player 001"
@@ -63,3 +62,5 @@ def verifyjson(json, key):
         raise PluginError(("Missing '{0}' key in JSON").format(key))
 
     return json[key]
+
+__all__ = ["ArgumentParser", "urlopen", "urlget", "swfverify", "verifyjson"]