Added logging to almost everything here

src/controller/mainController.py

@@ -35,6 +35,7 @@ class Controller(object):
 		self.window.vol_slider.SetValue(player.player.volume)
 		# Shows window.
 		utils.call_threaded(updater.do_update)
+		log.debug("Music DL is ready")
 		self.window.Show()
 
 	def get_status_info(self):
@@ -52,6 +53,7 @@ class Controller(object):
 
 	def connect_events(self):
 		""" connects all widgets to their corresponding events."""
+		log.debug("Binding events...")
 		widgetUtils.connect_event(self.window.search, widgetUtils.BUTTON_PRESSED, self.on_search)
 		widgetUtils.connect_event(self.window.list, widgetUtils.LISTBOX_ITEM_ACTIVATED, self.on_activated)
 		widgetUtils.connect_event(self.window.list, widgetUtils.KEYPRESS, self.on_keypress)
@@ -166,11 +168,13 @@ class Controller(object):
 
 	def on_download(self, *args, **kwargs):
 		item = self.results[self.window.get_item()]
+		log.debug("Starting requested download: {0} (using extractor: {1})".format(item.title, self.extractor.name))
 		f = "{0}.mp3".format(item.title)
 		if item.download_url == "":
 			item.get_download_url()
 		path = self.window.get_destination_path(f)
 		if path != None:
+			log.debug("User has requested the following path: {0}".format(path,))
 			if self.extractor.needs_transcode == True: # Send download to vlc based transcoder
 				utils.call_threaded(player.player.transcode_audio, item, path)
 			else:
@@ -192,6 +196,7 @@ class Controller(object):
 			self.window.time_slider.SetValue(progress)
 
 	def on_close(self, event):
+		log.debug("Exiting...")
 		self.timer.Stop()
 		pub.unsubscribe(self.on_download_finished, "download_finished")
 		event.Skip()
@@ -234,6 +239,7 @@ class Controller(object):
 			self.extractor = zaycev.interface()
 		elif extractor == "":
 			return
+		log.debug("Started search for {0} (selected extractor: {1})".format(text, self.extractor.name))
 		self.window.list.Clear()
 		self.change_status(_(u"Searching {0}... ").format(text))
 		self.extractor.search(text)

src/controller/player.py

@@ -8,7 +8,7 @@ from pubsub import pub
 from utils import call_threaded
 
 player = None
-log = logging.getLogger("player")
+log = logging.getLogger("controller.player")
 
 def setup():
 	global player
@@ -27,9 +27,11 @@ class audioPlayer(object):
 		self.shuffle = False
 		self.instance = vlc.Instance()
 		self.player = self.instance.media_player_new()
+		log.debug("Media player instantiated.")
 		self.event_manager = self.player.event_manager()
 		self.event_manager.event_attach(vlc.EventType.MediaPlayerEndReached, self.end_callback)
 		self.event_manager.event_attach(vlc.EventType.MediaPlayerEncounteredError, self.playback_error)
+		log.debug("Bound media playback events.")
 
 	def play(self, item):
 		self.stopped = True
@@ -37,6 +39,7 @@ class audioPlayer(object):
 			self.is_working = True
 			if item.download_url == "":
 				item.get_download_url()
+			log.debug("playing {0}...".format(item.download_url,))
 			self.stream_new = self.instance.media_new(item.download_url)
 			self.player.set_media(self.stream_new)
 			if self.player.play() == -1:
@@ -109,6 +112,7 @@ class audioPlayer(object):
 		""" Converts given item to mp3. This method will be available when needed automatically."""
 		if item.download_url == "":
 			item.get_download_url()
+		log.debug("Download started: filename={0}, url={1}".format(path, item.download_url))
 		temporary_filename = "chunk_{0}".format(random.randint(0,2000000))
 		temporary_path = os.path.join(os.path.dirname(path), temporary_filename)
 		# Let's get a new VLC instance for transcoding this file.
@@ -128,6 +132,7 @@ class audioPlayer(object):
 				break
 		transcoder.release()
 		os.rename(temporary_path, path)
+		log.debug("Download finished sucsessfully.")
 		pub.sendMessage("download_finished", file=os.path.basename(path))
 
 	def playback_error(self, event):

src/extractors/baseFile.py

@@ -16,10 +16,7 @@ class song(object):
 		self.download_url = ""
 
 	def format_track(self):
-		if self.size != 0:
+		return self.extractor.format_track(self)
-			return "{0}. {1}. {2}".format(self.title, self.duration, self.size)
-		else:
-			return "{0} {1}".format(self.title, self.duration)
 
 	def get_download_url(self):
 		self.download_url = self.extractor.get_download_url(self.url)

src/extractors/mailru.py

@@ -7,18 +7,23 @@ except ImportError:
 	import urllib as urlparse
 import requests
 import youtube_dl
+import logging
 from bs4 import BeautifulSoup
 from . import baseFile
 
+log = logging.getLogger("extractors.mail.ru")
+
 class interface(object):
 
 	def __init__(self):
 		self.results = []
 		self.name = "mailru"
 		self.needs_transcode = False
+		log.debug("Started extraction service for mail.ru music")
 
 	def search(self, text, page=1):
 		site = 'https://my.mail.ru/music/search/%s' % (text)
+		log.debug("Retrieving data from {0}...".format(site,))
 		r = requests.get(site)
 		soup = BeautifulSoup(r.text, 'html.parser')
 		search_results = soup.find_all("div", {"class": "songs-table__row__col songs-table__row__col--title title songs-table__row__col--title-hq-similar resize"})
@@ -31,13 +36,19 @@ class interface(object):
 #			print(data)
 			s.url = u"https://my.mail.ru"+urlparse.quote(data[0].__dict__["attrs"]["href"])
 			self.results.append(s)
+		log.debug("{0} results found.".format(len(self.results)))
 
 	def get_download_url(self, url):
-		ydl = youtube_dl.YoutubeDL({'quiet': True, 'format': 'bestaudio/best', 'outtmpl': u'%(id)s%(ext)s'})
+		log.debug("Getting download URL for {0}".format(url,))
+		ydl = youtube_dl.YoutubeDL({'quiet': True, 'no_warnings': True, 'logger': log, 'format': 'bestaudio/best', 'outtmpl': u'%(id)s%(ext)s'})
 		with ydl:
 			result = ydl.extract_info(url, download=False)
 			if 'entries' in result:
 				video = result['entries'][0]
 			else:
 				video = result
+		log.debug("Download URL: {0}".format(video["url"],))
 		return video["url"]
+
+	def format_track(self, item):
+		return item.title

src/extractors/vk.py

@@ -1,6 +1,7 @@
 # -*- coding: utf-8 -*-
 from __future__ import unicode_literals    # at top of module
 import requests
+import logging
 try:
 	import urllib.parse as urlparse
 except ImportError:
@@ -9,6 +10,7 @@ from .import baseFile
 from update.utils import seconds_to_string
 
 api_endpoint = "https://api-2.datmusic.xyz"
+log = logging.getLogger("extractors.vk.com")
 
 class interface(object):
 
@@ -16,19 +18,27 @@ class interface(object):
 		self.results = []
 		self.name = "vk"
 		self.needs_transcode = False
+		log.debug("started extraction service for {0}".format(self.name,))
 
 	def search(self, text, page=1):
 		self.results = []
 		url = "{0}/search?q={1}".format(api_endpoint, text)
+		log.debug("Retrieving data from {0}...".format(url,))
 		search_results = requests.get(url)
 		search_results = search_results.json()["data"]
 		for i in search_results:
 			s = baseFile.song(self)
 			s.title = i["title"]
+			s.artist = i["artist"]
 			# URRL is not needed here as download_url is already provided. So let's skip that part.
 			s.duration = seconds_to_string(i["duration"])
 			s.download_url = i["stream"]
 			self.results.append(s)
+		log.debug("{0} results found.".format(len(self.results)))
 
 	def get_download_url(self, url):
+		log.debug("This function has been called but does not apply to this module.")
 		return None
+
+	def format_track(self, item):
+		return "{0}. {1}".format(item.artist, item.title)

src/extractors/youtube.py

@@ -2,6 +2,7 @@
 from __future__ import unicode_literals    # at top of module
 import isodate
 import youtube_dl
+import logging
 from googleapiclient.discovery import build
 from googleapiclient.errors import HttpError
 from .import baseFile
@@ -11,16 +12,20 @@ DEVELOPER_KEY = "AIzaSyCU_hvZJEjLlAGAnlscquKEkE8l0lVOfn0"
 YOUTUBE_API_SERVICE_NAME = "youtube"
 YOUTUBE_API_VERSION = "v3"
 
+log = logging.getLogger("extractors.youtube.com")
+
 class interface(object):
 
 	def __init__(self):
 		self.results = []
 		self.name = "youtube"
 		self.needs_transcode = True
+		log.debug("started extraction service for {0}".format(self.name,))
 
 	def search(self, text, page=1):
 		type = "video"
 		max_results = 20
+		log.debug("Retrieving data from Youtube...")
 		youtube = build(YOUTUBE_API_SERVICE_NAME, YOUTUBE_API_VERSION, developerKey=DEVELOPER_KEY)
 		search_response = youtube.search().list(q=text, part="id,snippet", maxResults=max_results, type=type).execute()
 		self.results = []
@@ -35,13 +40,19 @@ class interface(object):
 		ssr = youtube.videos().list(id=",".join(ids), part="contentDetails", maxResults=1).execute()
 		for i in range(len(self.results)):
 			self.results[i].duration = seconds_to_string(isodate.parse_duration(ssr["items"][i]["contentDetails"]["duration"]).total_seconds())
+		log.debug("{0} results found.".format(len(self.results)))
 
 	def get_download_url(self, url):
-		ydl = youtube_dl.YoutubeDL({'quiet': True, 'format': 'bestaudio/best', 'outtmpl': u'%(id)s%(ext)s'})
+		log.debug("Getting download URL for {0}".format(url,))
+		ydl = youtube_dl.YoutubeDL({'quiet': True, 'no_warnings': True, 'logger': log, 'format': 'bestaudio/best', 'outtmpl': u'%(id)s%(ext)s'})
 		with ydl:
 			result = ydl.extract_info(url, download=False)
 			if 'entries' in result:
 				video = result['entries'][0]
 			else:
 				video = result
+		log.debug("Download URL: {0}".format(video["url"],))
 		return video["url"]
+
+	def format_track(self, item):
+		return "{0} {1}".format(item.title, item.duration)

src/extractors/zaycev.py

@@ -4,18 +4,23 @@ from __future__ import unicode_literals    # at top of module
 import re
 import json
 import requests
+import logging
 from bs4 import BeautifulSoup
 from . import baseFile
 
+log = logging.getLogger("extractors.zaycev.net")
+
 class interface(object):
 
 	def __init__(self):
 		self.results = []
 		self.name = "zaycev"
 		self.needs_transcode = False
+		log.debug("Started extraction service for zaycev.net")
 
 	def search(self, text, page=1):
 		site = 'http://go.mail.ru/zaycev?q=%s&page=%s' % (text, page)
+		log.debug("Retrieving data from {0}...".format(site,))
 		r = requests.get(site)
 		soup = BeautifulSoup(r.text, 'html.parser')
 		D = r'длительность.(\d+\:\d+\:\d+)'
@@ -32,8 +37,14 @@ class interface(object):
 			s.size = self.hd[i]["size"]
 			s.bitrate = self.hd[i]["bitrate"]
 			self.results.append(s)
+		log.debug("{0} results found.".format(len(self.results)))
 
 	def get_download_url(self, url):
+		log.debug("Getting download URL for {0}".format(url,))
 		soups = BeautifulSoup(requests.get(url).text, 'html.parser')
 		data = json.loads(requests.get('http://zaycev.net' + soups.find('div', {'class':"musicset-track"}).get('data-url')).text)
+		log.debug("Download URL: {0}".format(data["url"]))
 		return data["url"]
+
+	def format_track(self, item):
+		return "{0}. {1}. {2}".format(item.title, item.duration, item.size)

src/main.py

@@ -4,12 +4,12 @@ import os
 import logging
 import storage
 import traceback
+import sys
 storage.setup()
 logging.basicConfig(filename=os.path.join(storage.data_directory, "info.log"), level=logging.DEBUG, filemode="w")
 sys.excepthook = lambda x, y, z: logging.critical(''.join(traceback.format_exception(x, y, z)))
 log = logging.getLogger("main")
 log.debug("Logger initialized. Saving debug to {0}".format(storage.data_directory,))
-import sys
 log.debug("Using Python version {0}".format(sys.version,))
 if sys.version[0] == "2":
 	if hasattr(sys, "frozen"):

src/utils.py

@@ -49,11 +49,13 @@ class RepeatingTimer(threading.Thread):
 					log.exception("Execution failed. Function: %r args: %r and kwargs: %r" % (self.function, self.args, self.kwargs))
 
 def download_file(url, local_filename):
+	log.debug("Download started: filename={0}, url={1}".format(local_filename, url))
 	r = requests.get(url, stream=True)
 	pub.sendMessage("change_status", status=_(u"Downloading {0}.").format(local_filename,))
 	total_length = r.headers.get("content-length")
 	dl = 0
 	total_length = int(total_length)
+	log.debug("Downloading file of {0} bytes".format(total_length))
 	with open(local_filename, 'wb') as f:
 		for chunk in r.iter_content(chunk_size=64): 
 			if chunk: # filter out keep-alive new chunks
@@ -63,4 +65,5 @@ def download_file(url, local_filename):
 				msg = _(u"Downloading {0} ({1}%).").format(os.path.basename(local_filename), done)
 				pub.sendMessage("change_status", status=msg)
 	pub.sendMessage("download_finished", file=os.path.basename(local_filename))
+	log.debug("Download finished successfully")
 	return local_filename