diff --git a/command.py b/command.py index bcfb001..3721529 100644 --- a/command.py +++ b/command.py @@ -15,6 +15,7 @@ import variables as var from librb import radiobrowser from database import Database +log = logging.getLogger("bot") def register_all_commands(bot): bot.register_command(constants.commands('joinme'), cmd_joinme) @@ -52,6 +53,8 @@ def register_all_commands(bot): bot.register_command(constants.commands('drop_database'), cmd_drop_database) def send_multi_lines(bot, lines, text): + global log + msg = "" br = "" for newline in lines: @@ -68,11 +71,15 @@ def send_multi_lines(bot, lines, text): def cmd_joinme(bot, user, text, command, parameter): + global log + bot.mumble.users.myself.move_in( bot.mumble.users[text.actor]['channel_id'], token=parameter) def cmd_user_ban(bot, user, text, command, parameter): + global log + if bot.is_admin(user): if parameter: bot.mumble.users[text.actor].send_text_message(util.user_ban(parameter)) @@ -84,6 +91,8 @@ def cmd_user_ban(bot, user, text, command, parameter): def cmd_user_unban(bot, user, text, command, parameter): + global log + if bot.is_admin(user): if parameter: bot.mumble.users[text.actor].send_text_message(util.user_unban(parameter)) @@ -93,6 +102,8 @@ def cmd_user_unban(bot, user, text, command, parameter): def cmd_url_ban(bot, user, text, command, parameter): + global log + if bot.is_admin(user): if parameter: bot.mumble.users[text.actor].send_text_message(util.url_ban(util.get_url_from_input(parameter))) @@ -104,6 +115,8 @@ def cmd_url_ban(bot, user, text, command, parameter): def cmd_url_unban(bot, user, text, command, parameter): + global log + if bot.is_admin(user): if parameter: bot.mumble.users[text.actor].send_text_message(util.url_unban(util.get_url_from_input(parameter))) @@ -113,6 +126,8 @@ def cmd_url_unban(bot, user, text, command, parameter): def cmd_play(bot, user, text, command, parameter): + global log + if var.playlist.length() > 0: if parameter: if parameter.isdigit() and int(parameter) > 0 and int(parameter) <= len(var.playlist): @@ -131,11 +146,15 @@ def cmd_play(bot, user, text, command, parameter): def cmd_pause(bot, user, text, command, parameter): + global log + bot.pause() bot.send_msg(constants.strings('paused')) def cmd_play_file(bot, user, text, command, parameter): + global log + # if parameter is {index} if parameter.isdigit(): files = util.get_recursive_filelist_sorted(var.music_folder) @@ -145,7 +164,7 @@ def cmd_play_file(bot, user, text, command, parameter): 'path': filename, 'user': user} music = var.playlist.append(music) - logging.info("cmd: add to playlist: " + util.format_debug_song_string(music)) + log.info("cmd: add to playlist: " + util.format_debug_song_string(music)) bot.send_msg(constants.strings('file_added', item=util.format_song_string(music)), text) # if parameter is {path} @@ -161,7 +180,7 @@ def cmd_play_file(bot, user, text, command, parameter): 'path': parameter, 'user': user} music = var.playlist.append(music) - logging.info("cmd: add to playlist: " + util.format_debug_song_string(music)) + log.info("cmd: add to playlist: " + util.format_debug_song_string(music)) bot.send_msg(constants.strings('file_added', item=util.format_song_string(music)), text) return @@ -188,7 +207,7 @@ def cmd_play_file(bot, user, text, command, parameter): 'path': file, 'user': user} music = var.playlist.append(music) - logging.info("cmd: add to playlist: " + util.format_debug_song_string(music)) + log.info("cmd: add to playlist: " + util.format_debug_song_string(music)) msgs.append("{} ({})".format(music['title'], music['path'])) if count != 0: @@ -207,7 +226,7 @@ def cmd_play_file(bot, user, text, command, parameter): 'path': matches[0][1], 'user': user} music = var.playlist.append(music) - logging.info("cmd: add to playlist: " + util.format_debug_song_string(music)) + log.info("cmd: add to playlist: " + util.format_debug_song_string(music)) bot.send_msg(constants.strings('file_added', item=util.format_song_string(music)), text) else: msgs = [ constants.strings('multiple_matches')] @@ -217,6 +236,8 @@ def cmd_play_file(bot, user, text, command, parameter): def cmd_play_file_match(bot, user, text, command, parameter): + global log + music_folder = var.music_folder if parameter: files = util.get_recursive_filelist_sorted(music_folder) @@ -231,7 +252,7 @@ def cmd_play_file_match(bot, user, text, command, parameter): 'path': file, 'user': user} music = var.playlist.append(music) - logging.info("cmd: add to playlist: " + util.format_debug_song_string(music)) + log.info("cmd: add to playlist: " + util.format_debug_song_string(music)) msgs.append("{} ({})".format(music['title'], music['path'])) @@ -248,6 +269,8 @@ def cmd_play_file_match(bot, user, text, command, parameter): def cmd_play_url(bot, user, text, command, parameter): + global log + music = {'type': 'url', # grab the real URL 'url': util.get_url_from_input(parameter), @@ -257,7 +280,7 @@ def cmd_play_url(bot, user, text, command, parameter): music = bot.validate_music(music) if music: music = var.playlist.append(music) - logging.info("cmd: add to playlist: " + util.format_debug_song_string(music)) + log.info("cmd: add to playlist: " + util.format_debug_song_string(music)) bot.send_msg(constants.strings('file_added', item=util.format_song_string(music)), text) if var.playlist.length() == 2: # If I am the second item on the playlist. (I am the next one!) @@ -267,6 +290,8 @@ def cmd_play_url(bot, user, text, command, parameter): def cmd_play_playlist(bot, user, text, command, parameter): + global log + offset = 0 # if you want to start the playlist at a specific index try: offset = int(parameter.split(" ")[-1]) @@ -274,15 +299,17 @@ def cmd_play_playlist(bot, user, text, command, parameter): pass url = util.get_url_from_input(parameter) - logging.debug("cmd: fetching media info from playlist url %s" % url) + log.debug("cmd: fetching media info from playlist url %s" % url) items = media.playlist.get_playlist_info(url=url, start_index=offset, user=user) if len(items) > 0: var.playlist.extend(items) for music in items: - logging.info("cmd: add to playlist: " + util.format_debug_song_string(music)) + log.info("cmd: add to playlist: " + util.format_debug_song_string(music)) def cmd_play_radio(bot, user, text, command, parameter): + global log + if not parameter: all_radio = var.config.items('radio') msg = constants.strings('preconfigurated_radio') @@ -302,26 +329,28 @@ def cmd_play_radio(bot, user, text, command, parameter): 'url': url, 'user': user} var.playlist.append(music) - logging.info("cmd: add to playlist: " + util.format_debug_song_string(music)) + log.info("cmd: add to playlist: " + util.format_debug_song_string(music)) bot.async_download_next() else: bot.send_msg(constants.strings('bad_url')) def cmd_rb_query(bot, user, text, command, parameter): - logging.info('cmd: Querying radio stations') + global log + + log.info('cmd: Querying radio stations') if not parameter: - logging.debug('rbquery without parameter') + log.debug('rbquery without parameter') msg = constants.strings('rb_query_empty') bot.send_msg(msg, text) else: - logging.debug('cmd: Found query parameter: ' + parameter) + log.debug('cmd: Found query parameter: ' + parameter) # bot.send_msg('Searching for stations - this may take some seconds...', text) rb_stations = radiobrowser.getstations_byname(parameter) msg = constants.strings('rb_query_result') msg += '\n' if not rb_stations: - logging.debug('cmd: No matches found for rbquery ' + parameter) + log.debug('cmd: No matches found for rbquery ' + parameter) bot.send_msg('Radio-Browser found no matches for ' + parameter, text) else: for s in rb_stations: @@ -340,7 +369,7 @@ def cmd_rb_query(bot, user, text, command, parameter): bot.send_msg(msg, text) # Shorten message if message too long (stage I) else: - logging.debug('Result too long stage I') + log.debug('Result too long stage I') msg = constants.strings('rb_query_result') + ' (shortened L1)' msg += '\n
!rbplay IDStation NameGenreCodec/BitrateCountry
' for s in rb_stations: @@ -353,7 +382,7 @@ def cmd_rb_query(bot, user, text, command, parameter): bot.send_msg(msg, text) # Shorten message if message too long (stage II) else: - logging.debug('Result too long stage II') + log.debug('Result too long stage II') msg = constants.strings('rb_query_result') + ' (shortened L2)' msg += '!rbplay ID - Station Name' for s in rb_stations: @@ -370,13 +399,15 @@ def cmd_rb_query(bot, user, text, command, parameter): def cmd_rb_play(bot, user, text, command, parameter): - logging.debug('cmd: Play a station by ID') + global log + + log.debug('cmd: Play a station by ID') if not parameter: - logging.debug('rbplay without parameter') + log.debug('rbplay without parameter') msg = constants.strings('rb_play_empty') bot.send_msg(msg, text) else: - logging.debug('cmd: Retreiving url for station ID ' + parameter) + log.debug('cmd: Retreiving url for station ID ' + parameter) rstation = radiobrowser.getstationname_byid(parameter) stationname = rstation[0]['name'] country = rstation[0]['country'] @@ -390,42 +421,50 @@ def cmd_rb_play(bot, user, text, command, parameter): msg += '
!rbplay IDStation Name
' + \ '
IDStation NameGenreCodec/BitrateCountryHomepage
%s%s%s%s/%s%s%s
' \ % (parameter, stationname, genre, codec, bitrate, country, homepage) - logging.debug('cmd: Added station to playlist %s' % stationname) + log.debug('cmd: Added station to playlist %s' % stationname) bot.send_msg(msg, text) url = radiobrowser.geturl_byid(parameter) if url != "-1": - logging.info('cmd: Found url: ' + url) + log.info('cmd: Found url: ' + url) music = {'type': 'radio', 'title': stationname, 'artist': homepage, 'url': url, 'user': user} var.playlist.append(music) - logging.info("cmd: add to playlist: " + util.format_debug_song_string(music)) + log.info("cmd: add to playlist: " + util.format_debug_song_string(music)) bot.async_download_next() else: - logging.info('cmd: No playable url found.') + log.info('cmd: No playable url found.') msg += "No playable url found for this station, please try another station." bot.send_msg(msg, text) def cmd_help(bot, user, text, command, parameter): + global log + bot.send_msg(constants.strings('help'), text) if bot.is_admin(user): bot.send_msg(constants.strings('admin_help'), text) def cmd_stop(bot, user, text, command, parameter): + global log + bot.stop() bot.send_msg(constants.strings('stopped'), text) def cmd_clear(bot, user, text, command, parameter): + global log + bot.clear() bot.send_msg(constants.strings('cleared'), text) def cmd_kill(bot, user, text, command, parameter): + global log + if bot.is_admin(user): bot.pause() bot.exit = True @@ -435,6 +474,8 @@ def cmd_kill(bot, user, text, command, parameter): def cmd_update(bot, user, text, command, parameter): + global log + if bot.is_admin(user): bot.mumble.users[text.actor].send_text_message( constants.strings('start_updating')) @@ -446,24 +487,30 @@ def cmd_update(bot, user, text, command, parameter): def cmd_stop_and_getout(bot, user, text, command, parameter): + global log + bot.stop() if bot.channel: bot.mumble.channels.find_by_name(bot.channel).move_in() def cmd_volume(bot, user, text, command, parameter): + global log + # The volume is a percentage if parameter and parameter.isdigit() and 0 <= int(parameter) <= 100: bot.volume_set = float(float(parameter) / 100) bot.send_msg(constants.strings('change_volume', volume=int(bot.volume_set * 100), user=bot.mumble.users[text.actor]['name']), text) var.db.set('bot', 'volume', str(bot.volume_set)) - logging.info('cmd: volume set to %d' % (bot.volume_set * 100)) + log.info('cmd: volume set to %d' % (bot.volume_set * 100)) else: bot.send_msg(constants.strings('current_volume', volume=int(bot.volume_set * 100)), text) def cmd_ducking(bot, user, text, command, parameter): + global log + if parameter == "" or parameter == "on": bot.is_ducking = True var.db.set('bot', 'ducking', True) @@ -472,7 +519,7 @@ def cmd_ducking(bot, user, text, command, parameter): bot.mumble.callbacks.set_callback(pymumble.constants.PYMUMBLE_CLBK_SOUNDRECEIVED, bot.ducking_sound_received) bot.mumble.set_receive_sound(True) - logging.info('cmd: ducking is on') + log.info('cmd: ducking is on') msg = "Ducking on." bot.send_msg(msg, text) elif parameter == "off": @@ -480,11 +527,13 @@ def cmd_ducking(bot, user, text, command, parameter): bot.mumble.set_receive_sound(False) var.db.set('bot', 'ducking', False) msg = "Ducking off." - logging.info('cmd: ducking is off') + log.info('cmd: ducking is off') bot.send_msg(msg, text) def cmd_ducking_threshold(bot, user, text, command, parameter): + global log + if parameter and parameter.isdigit(): bot.ducking_threshold = int(parameter) var.db.set('bot', 'ducking_threshold', str(bot.ducking_threshold)) @@ -496,6 +545,8 @@ def cmd_ducking_threshold(bot, user, text, command, parameter): def cmd_ducking_volume(bot, user, text, command, parameter): + global log + # The volume is a percentage if parameter and parameter.isdigit() and 0 <= int(parameter) <= 100: bot.ducking_volume = float(float(parameter) / 100) @@ -503,12 +554,14 @@ def cmd_ducking_volume(bot, user, text, command, parameter): volume=int(bot.ducking_volume * 100), user=bot.mumble.users[text.actor]['name']), text) # var.db.set('bot', 'volume', str(bot.volume_set)) var.db.set('bot', 'ducking_volume', str(bot.ducking_volume)) - logging.info('cmd: volume on ducking set to %d' % (bot.ducking_volume * 100)) + log.info('cmd: volume on ducking set to %d' % (bot.ducking_volume * 100)) else: bot.send_msg(constants.strings('current_ducking_volume', volume=int(bot.ducking_volume * 100)), text) def cmd_current_music(bot, user, text, command, parameter): + global log + reply = "" if var.playlist.length() > 0: bot.send_msg(util.format_current_playing()) @@ -518,6 +571,8 @@ def cmd_current_music(bot, user, text, command, parameter): def cmd_skip(bot, user, text, command, parameter): + global log + if var.playlist.length() > 0: bot.stop() bot.launch_music() @@ -527,6 +582,8 @@ def cmd_skip(bot, user, text, command, parameter): def cmd_remove(bot, user, text, command, parameter): + global log + # Allow to remove specific music into the queue with a number if parameter and parameter.isdigit() and int(parameter) > 0 \ and int(parameter) <= var.playlist.length(): @@ -554,12 +611,14 @@ def cmd_remove(bot, user, text, command, parameter): bot.send_msg(constants.strings('removing_item', item=removed['title'] if 'title' in removed else removed['url']), text) - logging.info("cmd: delete from playlist: " + str(removed['path'] if 'path' in removed else removed['url'])) + log.info("cmd: delete from playlist: " + str(removed['path'] if 'path' in removed else removed['url'])) else: bot.send_msg(constants.strings('bad_parameter', command=command)) def cmd_list_file(bot, user, text, command, parameter): + global log + folder_path = var.music_folder files = util.get_recursive_filelist_sorted(folder_path) @@ -586,6 +645,8 @@ def cmd_list_file(bot, user, text, command, parameter): def cmd_queue(bot, user, text, command, parameter): + global log + if len(var.playlist) == 0: msg = constants.strings('queue_empty') bot.send_msg(msg, text) @@ -605,10 +666,14 @@ def cmd_queue(bot, user, text, command, parameter): send_multi_lines(bot, msgs, text) def cmd_random(bot, user, text, command, parameter): + global log + bot.interrupt_playing() var.playlist.randomize() def cmd_repeat(bot, user, text, command, parameter): + global log + repeat = 1 if parameter and parameter.isdigit(): repeat = int(parameter) @@ -619,11 +684,13 @@ def cmd_repeat(bot, user, text, command, parameter): var.playlist.current_index + 1, music ) - logging.info("bot: add to playlist: " + util.format_debug_song_string(music)) + log.info("bot: add to playlist: " + util.format_debug_song_string(music)) bot.send_msg(constants.strings("repeat", song=util.format_song_string(music), n=str(repeat)), text) def cmd_mode(bot, user, text, command, parameter): + global log + if not parameter: bot.send_msg(constants.strings("current_mode", mode=var.playlist.mode), text) return @@ -632,7 +699,7 @@ def cmd_mode(bot, user, text, command, parameter): else: var.db.set('playlist', 'playback_mode', parameter) var.playlist.set_mode(parameter) - logging.info("command: playback mode changed to %s." % parameter) + log.info("command: playback mode changed to %s." % parameter) bot.send_msg(constants.strings("change_mode", mode=var.playlist.mode, user=bot.mumble.users[text.actor]['name']), text) if parameter == "random": @@ -642,6 +709,8 @@ def cmd_mode(bot, user, text, command, parameter): def cmd_drop_database(bot, user, text, command, parameter): + global log + var.db.drop_table() var.db = Database(var.dbfile) bot.send_msg(constants.strings('database_dropped'), text) diff --git a/configuration.default.ini b/configuration.default.ini index d62dd01..14867d6 100644 --- a/configuration.default.ini +++ b/configuration.default.ini @@ -79,6 +79,7 @@ enabled = False is_web_proxified = True listening_addr = 127.0.0.1 listening_port = 8181 +web_logfile = # Set this option to True to enable password protection for the web interface require_auth = False diff --git a/configuration.example.ini b/configuration.example.ini index b490f23..b337313 100644 --- a/configuration.example.ini +++ b/configuration.example.ini @@ -93,6 +93,9 @@ port = 64738 #listening_port = 8181 #is_web_proxified = True +# 'web_logfile': write access logs of the web server into this file. +#web_logfile = + # 'required_auth': Set this to True to enable password protection for the web interface. #require_auth = False #user = diff --git a/interface.py b/interface.py index a17b6b1..4632a1d 100644 --- a/interface.py +++ b/interface.py @@ -56,7 +56,7 @@ class ReverseProxied(object): web = Flask(__name__) - +log = logging.getLogger("bot") def init_proxy(): global web @@ -73,7 +73,7 @@ def check_auth(username, password): def authenticate(): """Sends a 401 response that enables basic auth""" - logging.info("Web Interface login failed.") + global log return Response( 'Could not verify your access level for that URL.\n' 'You have to login with proper credentials', 401, @@ -82,10 +82,11 @@ def authenticate(): def requires_auth(f): @wraps(f) def decorated(*args, **kwargs): + global log auth = request.authorization if var.config.getboolean("webinterface", "require_auth") and (not auth or not check_auth(auth.username, auth.password)): if auth: - logging.info("Web Interface login attempt, user: %s" % auth.username) + log.info("web: Failed login attempt, user: %s" % auth.username) return authenticate() return f(*args, **kwargs) return decorated @@ -148,10 +149,12 @@ def status(): @web.route("/post", methods=['POST']) @requires_auth def post(): + global log + folder_path = var.music_folder if request.method == 'POST': if request.form: - logging.debug("Post request: "+ str(request.form)) + log.debug("web: Post request from %s: %s" % ( request.remote_addr, str(request.form))) if 'add_file_bottom' in request.form and ".." not in request.form['add_file_bottom']: path = var.music_folder + request.form['add_file_bottom'] if os.path.isfile(path): @@ -160,7 +163,7 @@ def post(): 'title' : '', 'user' : 'Remote Control'} item = var.playlist.append(util.get_music_tag_info(item)) - logging.info('web: add to playlist(bottom): ' + util.format_debug_song_string(item)) + log.info('web: add to playlist(bottom): ' + util.format_debug_song_string(item)) elif 'add_file_next' in request.form and ".." not in request.form['add_file_next']: path = var.music_folder + request.form['add_file_next'] @@ -173,7 +176,7 @@ def post(): var.playlist.current_index + 1, item ) - logging.info('web: add to playlist(next): ' + util.format_debug_song_string(item)) + log.info('web: add to playlist(next): ' + util.format_debug_song_string(item)) elif ('add_folder' in request.form and ".." not in request.form['add_folder']) or ('add_folder_recursively' in request.form and ".." not in request.form['add_folder_recursively']): try: @@ -206,7 +209,7 @@ def post(): files = var.playlist.extend(files) for file in files: - logging.info("web: add to playlist: %s" % util.format_debug_song_string(file)) + log.info("web: add to playlist: %s" % util.format_debug_song_string(file)) elif 'add_url' in request.form: @@ -217,7 +220,7 @@ def post(): music = var.botamusique.validate_music(music) if music: var.playlist.append(music) - logging.info("web: add to playlist: " + util.format_debug_song_string(music)) + log.info("web: add to playlist: " + util.format_debug_song_string(music)) if var.playlist.length() == 2: # If I am the second item on the playlist. (I am the next one!) var.botamusique.async_download_next() @@ -226,11 +229,11 @@ def post(): music = var.playlist.append({'type': 'radio', 'path': request.form['add_radio'], 'user': "Remote Control"}) - logging.info("web: add to playlist: " + util.format_debug_song_string(music)) + log.info("web: add to playlist: " + util.format_debug_song_string(music)) elif 'delete_music' in request.form: music = var.playlist[int(request.form['delete_music'])] - logging.info("web: delete from playlist: " + util.format_debug_song_string(music)) + log.info("web: delete from playlist: " + util.format_debug_song_string(music)) if var.playlist.length() >= int(request.form['delete_music']): index = int(request.form['delete_music']) @@ -254,7 +257,7 @@ def post(): elif 'play_music' in request.form: music = var.playlist[int(request.form['play_music'])] - logging.info("web: jump to: " + util.format_debug_song_string(music)) + log.info("web: jump to: " + util.format_debug_song_string(music)) if len(var.playlist) >= int(request.form['play_music']): var.botamusique.interrupt_playing() @@ -263,13 +266,13 @@ def post(): elif 'delete_music_file' in request.form and ".." not in request.form['delete_music_file']: path = var.music_folder + request.form['delete_music_file'] if os.path.isfile(path): - logging.info("web: delete file " + path) + log.info("web: delete file " + path) os.remove(path) elif 'delete_folder' in request.form and ".." not in request.form['delete_folder']: path = var.music_folder + request.form['delete_folder'] if os.path.isdir(path): - logging.info("web: delete folder " + path) + log.info("web: delete folder " + path) shutil.rmtree(path) time.sleep(0.1) @@ -279,15 +282,15 @@ def post(): var.botamusique.interrupt_playing() var.playlist.set_mode("random") var.db.set('playlist', 'playback_mode', "random") - logging.info("web: playback mode changed to random.") + log.info("web: playback mode changed to random.") if action == "one-shot": var.playlist.set_mode("one-shot") var.db.set('playlist', 'playback_mode', "one-shot") - logging.info("web: playback mode changed to one-shot.") + log.info("web: playback mode changed to one-shot.") if action == "repeat": var.playlist.set_mode("repeat") var.db.set('playlist', 'playback_mode', "repeat") - logging.info("web: playback mode changed to repeat.") + log.info("web: playback mode changed to repeat.") elif action == "stop": var.botamusique.stop() elif action == "pause": @@ -302,19 +305,21 @@ def post(): else: var.botamusique.volume_set = 1.0 var.db.set('bot', 'volume', str(var.botamusique.volume_set)) - logging.info("web: volume up to %d" % (var.botamusique.volume_set * 100)) + log.info("web: volume up to %d" % (var.botamusique.volume_set * 100)) elif action == "volume_down": if var.botamusique.volume_set - 0.03 > 0: var.botamusique.volume_set = var.botamusique.volume_set - 0.03 else: var.botamusique.volume_set = 0 var.db.set('bot', 'volume', str(var.botamusique.volume_set)) - logging.info("web: volume up to %d" % (var.botamusique.volume_set * 100)) + log.info("web: volume up to %d" % (var.botamusique.volume_set * 100)) return status() @web.route('/upload', methods=["POST"]) def upload(): + global log + files = request.files.getlist("file[]") if not files: return redirect("./", code=406) @@ -331,10 +336,10 @@ def upload(): elif '../' in targetdir: return redirect("./", code=406) - logging.info('Uploading file:') - logging.info(' - filename: ' + filename) - logging.info(' - targetdir: ' + targetdir) - logging.info(' - mimetype: ' + file.mimetype) + log.info('web: Uploading file from %s:' % request.remote_addr) + log.info('web: - filename: ' + filename) + log.info('web: - targetdir: ' + targetdir) + log.info('web: - mimetype: ' + file.mimetype) if "audio" in file.mimetype: storagepath = os.path.abspath(os.path.join(var.music_folder, targetdir)) @@ -349,7 +354,7 @@ def upload(): return redirect("./", code=500) filepath = os.path.join(storagepath, filename) - logging.info(' - filepath: ' + filepath) + log.info(' - filepath: ' + filepath) if os.path.exists(filepath): return redirect("./", code=406) @@ -362,8 +367,11 @@ def upload(): @web.route('/download', methods=["GET"]) def download(): + global log + if 'file' in request.args: requested_file = request.args['file'] + log.info('web: Download of file %s requested from %s:' % (requested_file, request.remote_addr)) if '../' not in requested_file: folder_path = var.music_folder files = util.get_recursive_filelist_sorted(var.music_folder) @@ -373,7 +381,7 @@ def download(): try: return send_file(filepath, as_attachment=True) except Exception as e: - logging.exception(e) + log.exception(e) abort(404) elif 'directory' in request.args: requested_dir = request.args['directory'] @@ -388,7 +396,7 @@ def download(): try: return send_file(zipfile, as_attachment=True) except Exception as e: - logging.exception(e) + log.exception(e) abort(404) return redirect("./", code=400) diff --git a/media/playlist.py b/media/playlist.py index 9b5ae66..b8d1be4 100644 --- a/media/playlist.py +++ b/media/playlist.py @@ -64,7 +64,7 @@ class PlayList(list): return False self.version += 1 - logging.debug("playlist: Next into the queue") + #logging.debug("playlist: Next into the queue") if self.current_index < len(self) - 1: if self.mode == "one-shot" and self.current_index != -1: diff --git a/media/radio.py b/media/radio.py index cc7bf1b..ae749aa 100644 --- a/media/radio.py +++ b/media/radio.py @@ -19,7 +19,7 @@ def get_radio_server_description(url): response = urllib.request.urlopen(request) data = json.loads(response.read().decode("utf-8")) title_server = data['servertitle'] - logging.info("TITLE FOUND SHOUTCAST: " + title_server) + # logging.info("TITLE FOUND SHOUTCAST: " + title_server) except urllib.error.HTTPError: pass except http.client.BadStatusLine: @@ -40,7 +40,7 @@ def get_radio_server_description(url): title_server = source['server_name'] if 'server_description' in source: title_server += ' - ' + source['server_description'] - logging.info("TITLE FOUND ICECAST: " + title_server) + # logging.info("TITLE FOUND ICECAST: " + title_server) if not title_server: title_server = url except urllib.error.URLError: diff --git a/media/system.py b/media/system.py index af34a29..3048a98 100644 --- a/media/system.py +++ b/media/system.py @@ -1,8 +1,12 @@ import logging import os +log = logging.getLogger("bot") + def get_size_folder(path): + global log + folder_size = 0 for (path, dirs, files) in os.walk(path): for file in files: @@ -12,6 +16,8 @@ def get_size_folder(path): def clear_tmp_folder(path, size): + global log + if size == -1: return elif size == 0: @@ -29,10 +35,10 @@ def clear_tmp_folder(path, size): for idx, file in enumerate(all_files): size_tp += os.path.getsize(file) if int(size_tp / (1024 * 1024)) > size: - logging.info("Cleaning tmp folder") + log.info("Cleaning tmp folder") to_remove = all_files[:idx] print(to_remove) for f in to_remove: - logging.debug("Removing " + f) + log.debug("Removing " + f) os.remove(os.path.join(path, f)) return diff --git a/mumbleBot.py b/mumbleBot.py index b1a5133..e720e7a 100644 --- a/mumbleBot.py +++ b/mumbleBot.py @@ -14,11 +14,11 @@ import argparse import os import os.path import pymumble.pymumble_py3 as pymumble -import interface import variables as var import hashlib import youtube_dl import logging +import logging.handlers import traceback import util @@ -68,8 +68,8 @@ class MumbleBot: version = 5 def __init__(self, args): - - logging.info("bot: botamusique version %d, starting..." % self.version) + self.log = logging.getLogger("bot") + self.log.info("bot: botamusique version %d, starting..." % self.version) signal.signal(signal.SIGINT, self.ctrl_caught) self.cmd_handle = {} self.volume_set = var.config.getfloat('bot', 'volume') @@ -84,11 +84,11 @@ class MumbleBot: self.channel = var.config.get("server", "channel", fallback=None) if args.verbose: - root.setLevel(logging.DEBUG) - logging.debug("Starting in DEBUG loglevel") + self.log.setLevel(logging.DEBUG) + self.log.debug("Starting in DEBUG loglevel") elif args.quiet: - root.setLevel(logging.ERROR) - logging.error("Starting in ERROR loglevel") + self.log.setLevel(logging.ERROR) + self.log.error("Starting in ERROR loglevel") var.user = args.user var.music_folder = util.solve_filepath(var.config.get('bot', 'music_folder')) @@ -106,10 +106,10 @@ class MumbleBot: if var.config.getboolean("webinterface", "enabled"): wi_addr = var.config.get("webinterface", "listening_addr") wi_port = var.config.getint("webinterface", "listening_port") - interface.init_proxy() tt = threading.Thread( target=start_web_interface, name="WebThread", args=(wi_addr, wi_port)) tt.daemon = True + self.log.info('Starting web interface on {}:{}'.format(wi_addr, wi_port)) tt.start() if var.config.getboolean("bot", "auto_check_update"): @@ -184,23 +184,23 @@ class MumbleBot: # Set the CTRL+C shortcut def ctrl_caught(self, signal, frame): - logging.info( + self.log.info( "\nSIGINT caught, quitting, {} more to kill".format(2 - self.nb_exit)) self.exit = True self.pause() if self.nb_exit > 1: - logging.info("Forced Quit") + self.log.info("Forced Quit") sys.exit(0) self.nb_exit += 1 def check_update(self): - logging.debug("update: checking for updates...") + self.log.debug("update: checking for updates...") new_version = util.new_release_version() if new_version > self.version: - logging.info("update: new version %d found, current installed version %d." % (new_version, self.version)) + self.log.info("update: new version %d found, current installed version %d." % (new_version, self.version)) self.send_msg(constants.strings('new_version_found')) else: - logging.debug("update: no new version found.") + self.log.debug("update: no new version found.") def register_command(self, cmd, handle): cmds = cmd.split(",") @@ -208,7 +208,7 @@ class MumbleBot: command = command.strip() if command: self.cmd_handle[command] = handle - logging.debug("bot: command added: " + command) + self.log.debug("bot: command added: " + command) def set_comment(self): self.mumble.users.myself.comment(var.config.get('bot', 'comment')) @@ -240,7 +240,7 @@ class MumbleBot: else: return - logging.info('bot: received command ' + command + ' - ' + parameter + ' by ' + user) + self.log.info('bot: received command ' + command + ' - ' + parameter + ' by ' + user) # Anti stupid guy function if not self.is_admin(user) and not var.config.getboolean('bot', 'allow_other_channel_message') and self.mumble.users[text.actor]['channel_id'] != self.mumble.users.myself['channel_id']: @@ -281,7 +281,7 @@ class MumbleBot: matches.append(cmd) if len(matches) == 1: - logging.info("bot: {:s} matches {:s}".format(command, matches[0])) + self.log.info("bot: {:s} matches {:s}".format(command, matches[0])) command_exc = matches[0] self.cmd_handle[matches[0]](self, user, text, command, parameter) elif len(matches) > 1: @@ -293,7 +293,7 @@ class MumbleBot: except: error_traceback = traceback.format_exc() error = error_traceback.rstrip().split("\n")[-1] - logging.error("bot: command %s failed with error: %s\n" % (command_exc, error_traceback)) + self.log.error("bot: command %s failed with error: %s\n" % (command_exc, error_traceback)) self.send_msg(constants.strings('error_executing_command', command=command_exc, error=error), text) def send_msg(self, msg, text=None): @@ -327,7 +327,7 @@ class MumbleBot: else: music = var.playlist.jump(index) - logging.info("bot: play music " + util.format_debug_song_string(music)) + self.log.info("bot: play music " + util.format_debug_song_string(music)) if music["type"] == "url": # Delete older music is the tmp folder is too big media.system.clear_tmp_folder(var.tmp_folder, var.config.getint('bot', 'tmp_folder_max_size')) @@ -336,10 +336,10 @@ class MumbleBot: if music["ready"] == "downloading": return elif music["ready"] != "yes" or not os.path.exists(music['path']): - logging.info("bot: current music isn't ready, downloading...") + self.log.info("bot: current music isn't ready, downloading...") downloaded_music = self.download_music() if not downloaded_music: - logging.info("bot: removing music from the playlist: %s" % util.format_debug_song_string(music)) + self.log.info("bot: removing music from the playlist: %s" % util.format_debug_song_string(music)) var.playlist.remove(index) return music = downloaded_music @@ -353,7 +353,7 @@ class MumbleBot: elif music["type"] == "radio": uri = music["url"] if 'title' not in music: - logging.info("bot: fetching radio server description") + self.log.info("bot: fetching radio server description") title = media.radio.get_radio_server_description(uri) music["title"] = title @@ -367,7 +367,7 @@ class MumbleBot: command = ("ffmpeg", '-v', ffmpeg_debug, '-nostdin', '-i', uri, '-ac', '1', '-f', 's16le', '-ar', '48000', '-') - logging.info("bot: execute ffmpeg command: " + " ".join(command)) + self.log.debug("bot: execute ffmpeg command: " + " ".join(command)) # The ffmpeg process is a thread # prepare pipe for catching stderr of ffmpeg @@ -391,18 +391,18 @@ class MumbleBot: # Download only if music is not existed if os.path.isfile(mp3): - logging.info("bot: file existed for url %s " % music['url']) + self.log.info("bot: file existed for url %s " % music['url']) music['ready'] = 'yes' return music music = media.url.get_url_info(music) - logging.info("bot: verifying the duration of url %s " % music['url']) + self.log.info("bot: verifying the duration of url %s " % music['url']) if music: if music['duration'] > var.config.getint('bot', 'max_track_duration'): # Check the length, useful in case of playlist, it wasn't checked before) - logging.info( + self.log.info( "the music " + music["url"] + " has a duration of " + music['duration'] + "s -- too long") self.send_msg(constants.strings('too_long')) return False @@ -411,7 +411,7 @@ class MumbleBot: return music else: - logging.error("bot: error while fetching info from the URL") + self.log.error("bot: error while fetching info from the URL") self.send_msg(constants.strings('unable_download')) return False @@ -438,7 +438,7 @@ class MumbleBot: music['ready'] = "downloading" - logging.info("bot: downloading url (%s) %s " % (music['title'], url)) + self.log.info("bot: downloading url (%s) %s " % (music['title'], url)) ydl_opts = "" ydl_opts = { @@ -459,7 +459,7 @@ class MumbleBot: attempts = var.config.getint('bot', 'download_attempts', fallback=2) download_succeed = False for i in range(attempts): - logging.info("bot: download attempts %d / %d" % (i+1, attempts)) + self.log.info("bot: download attempts %d / %d" % (i+1, attempts)) try: ydl.extract_info(url) if os.path.exists(mp3) and os.stat(mp3).st_size > 0: @@ -467,19 +467,19 @@ class MumbleBot: download_succeed = True break else: - logging.error("bot: download failed: file not existed or file size is 0.") + self.log.error("bot: download failed: file not existed or file size is 0.") except: error_traceback = traceback.format_exc() - logging.error("bot: download failed with error:\n %s" % error_traceback) + self.log.error("bot: download failed with error:\n %s" % error_traceback) if not download_succeed: self.send_msg(constants.strings('unable_download')) return False else: - logging.info("bot: music file existed, skip downloading " + mp3) + self.log.info("bot: music file existed, skip downloading " + mp3) music['ready'] = "yes" - logging.info("bot: finished downloading url (%s) %s, saved to %s." % (music['title'], url, music['path'])) + self.log.info("bot: finished downloading url (%s) %s, saved to %s." % (music['title'], url, music['path'])) music = util.get_music_tag_info(music) var.playlist.update(music, index) @@ -488,12 +488,12 @@ class MumbleBot: def async_download_next(self): # Function start if the next music isn't ready # Do nothing in case the next music is already downloaded - logging.debug("bot: Async download next asked ") + self.log.debug("bot: Async download next asked ") if var.playlist.length() > 1 and var.playlist.next_item()['type'] == 'url' \ and (var.playlist.next_item()['ready'] in ["no", "validation"]): th = threading.Thread( target=self.download_music, name="DownloadThread", args=(var.playlist.next_index(),)) - logging.info( + self.log.info( "bot: start downloading item in thread: " + util.format_debug_song_string(var.playlist.next_item())) th.daemon = True th.start() @@ -520,7 +520,7 @@ class MumbleBot: elif music["type"] == "file": uri = var.music_folder + music["path"] if not os.path.exists(uri): - logging.info("bot: music file missed. removing music from the playlist: %s" % util.format_debug_song_string(music)) + self.log.info("bot: music file missed. removing music from the playlist: %s" % util.format_debug_song_string(music)) self.send_msg(constants.strings('file_missed', file=music["path"])) var.playlist.remove(index) return False @@ -551,7 +551,7 @@ class MumbleBot: try: stderr_msg = self.thread_stderr.readline() if stderr_msg: - logging.debug("ffmpeg: " + stderr_msg.strip("\n")) + self.log.debug("ffmpeg: " + stderr_msg.strip("\n")) except: pass @@ -578,7 +578,7 @@ class MumbleBot: if self.exit: if var.config.getboolean('bot', 'save_playlist', fallback=True): - logging.info("bot: save playlist into database") + self.log.info("bot: save playlist into database") var.playlist.save() def volume_cycle(self): @@ -599,7 +599,7 @@ class MumbleBot: def ducking_sound_received(self, user, sound): if audioop.rms(sound.pcm, 2) > self.ducking_threshold: if self.on_ducking is False: - logging.debug("bot: ducking triggered") + self.log.debug("bot: ducking triggered") self.on_ducking = True self.ducking_release = time.time() + 1 # ducking release after 1s @@ -613,7 +613,7 @@ class MumbleBot: self.thread.kill() self.thread = None var.playlist.clear() - logging.info("bot: music stopped. playlist trashed.") + self.log.info("bot: music stopped. playlist trashed.") def stop(self): # stop and move to the next item in the playlist @@ -621,7 +621,7 @@ class MumbleBot: self.interrupt_playing() self.playhead = 0 var.playlist.next() - logging.info("bot: music stopped.") + self.log.info("bot: music stopped.") def interrupt_playing(self): # Kill the ffmpeg thread @@ -637,7 +637,7 @@ class MumbleBot: self.thread = None self.is_pause = True self.song_start_at = -1 - logging.info("bot: music paused at %.2f seconds." % self.playhead) + self.log.info("bot: music paused at %.2f seconds." % self.playhead) def resume(self): self.is_pause = False @@ -656,7 +656,7 @@ class MumbleBot: else: ffmpeg_debug = "warning" - logging.info("bot: resume music at %.2f seconds" % self.playhead) + self.log.info("bot: resume music at %.2f seconds" % self.playhead) uri = "" if music["type"] == "url": @@ -672,7 +672,7 @@ class MumbleBot: if var.config.getboolean('bot', 'announce_current_music'): self.send_msg(util.format_current_playing()) - logging.info("bot: execute ffmpeg command: " + " ".join(command)) + self.log.info("bot: execute ffmpeg command: " + " ".join(command)) # The ffmpeg process is a thread # prepare pipe for catching stderr of ffmpeg pipe_rd, pipe_wd = os.pipe() @@ -688,12 +688,26 @@ class MumbleBot: user.sound.lock.acquire() user.sound.queue.clear() user.sound.lock.release() - logging.debug("bot: pymumble soundqueue cleared.") + self.log.debug("bot: pymumble soundqueue cleared.") def start_web_interface(addr, port): - logging.info('Starting web interface on {}:{}'.format(addr, port)) + global formatter + import interface + + # setup logger + werkzeug_logger = logging.getLogger('werkzeug') + logfile = util.solve_filepath(var.config.get('webinterface', 'web_logfile')) + handler = None + if logfile: + handler = logging.handlers.RotatingFileHandler(logfile, mode='a', maxBytes=10240) # Rotate after 10KB + else: + handler = logging.StreamHandler() + + werkzeug_logger.addHandler(handler) + + interface.init_proxy() interface.web.run(port=port, host=addr) @@ -744,20 +758,20 @@ if __name__ == '__main__': var.db = Database(var.dbfile) # Setup logger - root = logging.getLogger() + bot_logger = logging.getLogger("bot") formatter = logging.Formatter('[%(asctime)s %(levelname)s %(threadName)s] %(message)s', "%b %d %H:%M:%S") - root.setLevel(logging.INFO) + bot_logger.setLevel(logging.INFO) logfile = util.solve_filepath(var.config.get('bot', 'logfile')) - handler = None if logfile: - handler = logging.FileHandler(logfile) + handler = logging.handlers.RotatingFileHandler(logfile, mode='a', maxBytes=10240) # Rotate after 10KB else: - handler = logging.StreamHandler(sys.stdout) + handler = logging.StreamHandler() handler.setFormatter(formatter) - root.addHandler(handler) + bot_logger.addHandler(handler) + var.bot_logger = bot_logger var.playlist = PlayList() # playlist should be initialized after the database var.botamusique = MumbleBot(args) @@ -765,7 +779,7 @@ if __name__ == '__main__': # load playlist if var.config.getboolean('bot', 'save_playlist', fallback=True): - logging.info("bot: load playlist from previous session") + var.bot_logger.info("bot: load playlist from previous session") var.playlist.load() # load playback mode diff --git a/util.py b/util.py index dfe346b..7841dd8 100644 --- a/util.py +++ b/util.py @@ -22,6 +22,8 @@ import base64 import media import media.radio +log = logging.getLogger("bot") + def solve_filepath(path): if not path: return '' @@ -261,17 +263,19 @@ def new_release_version(): return v def update(version): + global log + v = new_release_version() if v > version: - logging.info('update: new version, start updating...') + log.info('update: new version, start updating...') tp = sp.check_output(['/usr/bin/env', 'bash', 'update.sh']).decode() - logging.debug(tp) - logging.info('update: update pip librairies dependancies') + log.debug(tp) + log.info('update: update pip librairies dependancies') tp = sp.check_output([var.config.get('bot', 'pip3_path'), 'install', '--upgrade', '-r', 'requirements.txt']).decode() msg = "New version installed, please restart the bot." else: - logging.info('update: starting update youtube-dl via pip3') + log.info('update: starting update youtube-dl via pip3') tp = sp.check_output([var.config.get('bot', 'pip3_path'), 'install', '--upgrade', 'youtube-dl']).decode() msg = "" if "Requirement already up-to-date" in tp: diff --git a/variables.py b/variables.py index af6f453..473d99c 100644 --- a/variables.py +++ b/variables.py @@ -8,5 +8,7 @@ dbfile = None db = None config = None +bot_logger = None + music_folder = "" tmp_folder = ""