mumbleBot.py

   1 #!/usr/bin/env python3
   2 # -*- coding: utf-8 -*-
   3
   4 import threading
   5 import time
   6 import sys
   7 import math
   8 import signal
   9 import configparser
  10 import audioop
  11 import subprocess as sp
  12 import argparse
  13 import os
  14 import os.path
  15 import pymumble.pymumble_py3 as pymumble
  16 import variables as var
  17 import hashlib
  18 import youtube_dl
  19 import logging
  20 import logging.handlers
  21 import traceback
  22 from packaging import version
  23
  24 import util
  25 import command
  26 import constants
  27 from database import SettingsDatabase, MusicDatabase
  28 import media.url
  29 import media.file
  30 import media.radio
  31 import media.system
  32 from media.playlist import BasePlaylist
  33 from media.cache import MusicCache
  34
  35
  36 class MumbleBot:
  37     version = '5.2'
  38
  39     def __init__(self, args):
  40         self.log = logging.getLogger("bot")
  41         self.log.info("bot: botamusique version %s, starting..." % self.version)
  42         signal.signal(signal.SIGINT, self.ctrl_caught)
  43         self.cmd_handle = {}
  44         self.volume_set = var.config.getfloat('bot', 'volume')
  45         if var.db.has_option('bot', 'volume'):
  46             self.volume_set = var.db.getfloat('bot', 'volume')
  47
  48         self.volume = self.volume_set
  49
  50         if args.channel:
  51             self.channel = args.channel
  52         else:
  53             self.channel = var.config.get("server", "channel", fallback=None)
  54
  55         if args.verbose:
  56             self.log.setLevel(logging.DEBUG)
  57             self.log.debug("Starting in DEBUG loglevel")
  58         elif args.quiet:
  59             self.log.setLevel(logging.ERROR)
  60             self.log.error("Starting in ERROR loglevel")
  61
  62         var.user = args.user
  63         var.music_folder = util.solve_filepath(var.config.get('bot', 'music_folder'))
  64         var.tmp_folder = util.solve_filepath(var.config.get('bot', 'tmp_folder'))
  65         var.is_proxified = var.config.getboolean(
  66             "webinterface", "is_web_proxified")
  67         self.exit = False
  68         self.nb_exit = 0
  69         self.thread = None
  70         self.thread_stderr = None
  71         self.is_pause = False
  72         self.pause_at_id = ""
  73         self.playhead = -1
  74         self.song_start_at = -1
  75         #self.download_threads = []
  76         self.wait_for_downloading = False # flag for the loop are waiting for download to complete in the other thread
  77
  78         if var.config.getboolean("webinterface", "enabled"):
  79             wi_addr = var.config.get("webinterface", "listening_addr")
  80             wi_port = var.config.getint("webinterface", "listening_port")
  81             tt = threading.Thread(
  82                 target=start_web_interface, name="WebThread", args=(wi_addr, wi_port))
  83             tt.daemon = True
  84             self.log.info('Starting web interface on {}:{}'.format(wi_addr, wi_port))
  85             tt.start()
  86
  87         if var.config.getboolean("bot", "auto_check_update"):
  88             th = threading.Thread(target=self.check_update, name="UpdateThread")
  89             th.daemon = True
  90             th.start()
  91
  92         if args.host:
  93             host = args.host
  94         else:
  95             host = var.config.get("server", "host")
  96
  97         if args.port:
  98             port = args.port
  99         else:
 100             port = var.config.getint("server", "port")
 101
 102         if args.password:
 103             password = args.password
 104         else:
 105             password = var.config.get("server", "password")
 106
 107         if args.channel:
 108             self.channel = args.channel
 109         else:
 110             self.channel = var.config.get("server", "channel")
 111
 112         if args.certificate:
 113             certificate = args.certificate
 114         else:
 115             certificate = util.solve_filepath(var.config.get("server", "certificate"))
 116
 117         if args.tokens:
 118             tokens = args.tokens
 119         else:
 120             tokens = var.config.get("server", "tokens")
 121             tokens = tokens.split(',')
 122
 123         if args.user:
 124             self.username = args.user
 125         else:
 126             self.username = var.config.get("bot", "username")
 127
 128         self.mumble = pymumble.Mumble(host, user=self.username, port=port, password=password, tokens=tokens,
 129                                       debug=var.config.getboolean('debug', 'mumbleConnection'), certfile=certificate)
 130         self.mumble.callbacks.set_callback(pymumble.constants.PYMUMBLE_CLBK_TEXTMESSAGERECEIVED, self.message_received)
 131
 132         self.mumble.set_codec_profile("audio")
 133         self.mumble.start()  # start the mumble thread
 134         self.mumble.is_ready()  # wait for the connection
 135         self.set_comment()
 136         self.mumble.users.myself.unmute()  # by sure the user is not muted
 137         if self.channel:
 138             self.mumble.channels.find_by_name(self.channel).move_in()
 139         self.mumble.set_bandwidth(200000)
 140
 141         self.is_ducking = False
 142         self.on_ducking = False
 143         self.ducking_release = time.time()
 144
 145         if not var.db.has_option("bot", "ducking") and var.config.getboolean("bot", "ducking", fallback=False)\
 146                 or var.config.getboolean("bot", "ducking"):
 147             self.is_ducking = True
 148             self.ducking_volume = var.config.getfloat("bot", "ducking_volume", fallback=0.05)
 149             self.ducking_volume = var.db.getfloat("bot", "ducking_volume", fallback=self.ducking_volume)
 150             self.ducking_threshold = var.config.getfloat("bot", "ducking_threshold", fallback=5000)
 151             self.ducking_threshold = var.db.getfloat("bot", "ducking_threshold", fallback=self.ducking_threshold)
 152             self.mumble.callbacks.set_callback(pymumble.constants.PYMUMBLE_CLBK_SOUNDRECEIVED, \
 153                                                self.ducking_sound_received)
 154             self.mumble.set_receive_sound(True)
 155
 156         # Debug use
 157         self._loop_status = 'Idle'
 158         self._display_rms = False
 159         self._max_rms = 0
 160
 161     # Set the CTRL+C shortcut
 162     def ctrl_caught(self, signal, frame):
 163
 164         self.log.info(
 165             "\nSIGINT caught, quitting, {} more to kill".format(2 - self.nb_exit))
 166         self.exit = True
 167         self.pause()
 168         if self.nb_exit > 1:
 169             self.log.info("Forced Quit")
 170             sys.exit(0)
 171         self.nb_exit += 1
 172
 173         if var.config.getboolean('bot', 'save_playlist', fallback=True) \
 174                     and var.config.get("bot", "save_music_library", fallback=True):
 175             self.log.info("bot: save playlist into database")
 176             var.playlist.save()
 177
 178     def check_update(self):
 179         self.log.debug("update: checking for updates...")
 180         new_version = util.new_release_version()
 181         if version.parse(new_version) > version.parse(self.version):
 182             self.log.info("update: new version %s found, current installed version %s." % (new_version, self.version))
 183             self.send_msg(constants.strings('new_version_found'))
 184         else:
 185             self.log.debug("update: no new version found.")
 186
 187     def register_command(self, cmd, handle, no_partial_match=False, access_outside_channel=False):
 188         cmds = cmd.split(",")
 189         for command in cmds:
 190             command = command.strip()
 191             if command:
 192                 self.cmd_handle[command] = { 'handle': handle,
 193                                              'partial_match': not no_partial_match,
 194                                              'access_outside_channel': access_outside_channel}
 195                 self.log.debug("bot: command added: " + command)
 196
 197     def set_comment(self):
 198         self.mumble.users.myself.comment(var.config.get('bot', 'comment'))
 199
 200     # =======================
 201     #         Message
 202     # =======================
 203
 204     # All text send to the chat is analysed by this function
 205     def message_received(self, text):
 206         message = text.message.strip()
 207         user = self.mumble.users[text.actor]['name']
 208
 209         if var.config.getboolean('commands', 'split_username_at_space'):
 210             # in can you use https://github.com/Natenom/mumblemoderator-module-collection/tree/master/os-suffixes ,
 211             # you want to split the username
 212             user = user.split()[0]
 213
 214         if message[0] in var.config.get('commands', 'command_symbol'):
 215             # remove the symbol from the message
 216             message = message[1:].split(' ', 1)
 217
 218             # use the first word as a command, the others one as  parameters
 219             if len(message) > 0:
 220                 command = message[0].lower()
 221                 parameter = ''
 222                 if len(message) > 1:
 223                     parameter = message[1].rstrip()
 224             else:
 225                 return
 226
 227             self.log.info('bot: received command ' + command + ' - ' + parameter + ' by ' + user)
 228
 229             # Anti stupid guy function
 230             if not self.is_admin(user) and not var.config.getboolean('bot', 'allow_private_message') and text.session:
 231                 self.mumble.users[text.actor].send_text_message(
 232                     constants.strings('pm_not_allowed'))
 233                 return
 234
 235             for i in var.db.items("user_ban"):
 236                 if user.lower() == i[0]:
 237                     self.mumble.users[text.actor].send_text_message(
 238                         constants.strings('user_ban'))
 239                     return
 240
 241             if parameter:
 242                 for i in var.db.items("url_ban"):
 243                     if util.get_url_from_input(parameter.lower()) == i[0]:
 244                         self.mumble.users[text.actor].send_text_message(
 245                             constants.strings('url_ban'))
 246                         return
 247
 248
 249             command_exc = ""
 250             try:
 251                 if command in self.cmd_handle:
 252                     command_exc = command
 253
 254                     if not self.cmd_handle[command]['access_outside_channel'] \
 255                             and not self.is_admin(user) \
 256                             and not var.config.getboolean('bot', 'allow_other_channel_message') \
 257                             and self.mumble.users[text.actor]['channel_id'] != self.mumble.users.myself['channel_id']:
 258                         self.mumble.users[text.actor].send_text_message(
 259                             constants.strings('not_in_my_channel'))
 260                         return
 261
 262                     self.cmd_handle[command]['handle'](self, user, text, command, parameter)
 263                 else:
 264                     # try partial match
 265                     cmds = self.cmd_handle.keys()
 266                     matches = []
 267                     for cmd in cmds:
 268                         if cmd.startswith(command) and self.cmd_handle[cmd]['partial_match']:
 269                             matches.append(cmd)
 270
 271                     if len(matches) == 1:
 272                         self.log.info("bot: {:s} matches {:s}".format(command, matches[0]))
 273                         command_exc = matches[0]
 274
 275                         if not self.cmd_handle[command]['access_outside_channel'] \
 276                                 and not self.is_admin(user) \
 277                                 and not var.config.getboolean('bot', 'allow_other_channel_message') \
 278                                 and self.mumble.users[text.actor]['channel_id'] != self.mumble.users.myself[
 279                             'channel_id']:
 280                             self.mumble.users[text.actor].send_text_message(
 281                                 constants.strings('not_in_my_channel'))
 282                             return
 283
 284                         self.cmd_handle[command_exc]['handle'](self, user, text, command_exc, parameter)
 285                     elif len(matches) > 1:
 286                         self.mumble.users[text.actor].send_text_message(
 287                             constants.strings('which_command', commands="<br>".join(matches)))
 288                     else:
 289                         self.mumble.users[text.actor].send_text_message(
 290                             constants.strings('bad_command', command=command))
 291             except:
 292                 error_traceback = traceback.format_exc()
 293                 error = error_traceback.rstrip().split("\n")[-1]
 294                 self.log.error("bot: command %s failed with error: %s\n" % (command_exc, error_traceback))
 295                 self.send_msg(constants.strings('error_executing_command', command=command_exc, error=error), text)
 296
 297     def send_msg(self, msg, text=None):
 298         msg = msg.encode('utf-8', 'ignore').decode('utf-8')
 299         # text if the object message, contain information if direct message or channel message
 300         if not text or not text.session:
 301             own_channel = self.mumble.channels[self.mumble.users.myself['channel_id']]
 302             own_channel.send_text_message(msg)
 303         else:
 304             self.mumble.users[text.actor].send_text_message(msg)
 305
 306     def is_admin(self, user):
 307         list_admin = var.config.get('bot', 'admin').rstrip().split(';')
 308         if user in list_admin:
 309             return True
 310         else:
 311             return False
 312
 313     # =======================
 314     #   Launch and Download
 315     # =======================
 316
 317     def launch_music(self):
 318         if var.playlist.is_empty():
 319             return
 320         assert self.wait_for_downloading == False
 321
 322         music_wrapper = var.playlist.current_item()
 323         uri = music_wrapper.uri()
 324
 325         self.log.info("bot: play music " + music_wrapper.format_debug_string())
 326
 327         if var.config.getboolean('bot', 'announce_current_music'):
 328             self.send_msg(music_wrapper.format_current_playing())
 329
 330         if var.config.getboolean('debug', 'ffmpeg'):
 331             ffmpeg_debug = "debug"
 332         else:
 333             ffmpeg_debug = "warning"
 334
 335         command = ("ffmpeg", '-v', ffmpeg_debug, '-nostdin', '-i',
 336                    uri, '-ac', '1', '-f', 's16le', '-ar', '48000', '-')
 337         self.log.debug("bot: execute ffmpeg command: " + " ".join(command))
 338
 339         # The ffmpeg process is a thread
 340         # prepare pipe for catching stderr of ffmpeg
 341         pipe_rd, pipe_wd = os.pipe()
 342         util.pipe_no_wait(pipe_rd) # Let the pipe work in non-blocking mode
 343         self.thread_stderr = os.fdopen(pipe_rd)
 344         self.thread = sp.Popen(command, stdout=sp.PIPE, stderr=pipe_wd, bufsize=480)
 345         self.is_pause = False
 346         self.song_start_at = -1
 347         self.playhead = 0
 348         self.last_volume_cycle_time = time.time()
 349
 350     def async_download_next(self):
 351         # Function start if the next music isn't ready
 352         # Do nothing in case the next music is already downloaded
 353         self.log.debug("bot: Async download next asked ")
 354         while var.playlist.next_item() and var.playlist.next_item().type in ['url', 'url_from_playlist']:
 355             # usually, all validation will be done when adding to the list.
 356             # however, for performance consideration, youtube playlist won't be validate when added.
 357             # the validation has to be done here.
 358             next = var.playlist.next_item()
 359             if next.validate():
 360                 if not next.is_ready():
 361                     next.async_prepare()
 362                 break
 363             else:
 364                 var.playlist.remove_by_id(next.id)
 365                 var.cache.free_and_delete(next.id)
 366
 367
 368     # =======================
 369     #          Loop
 370     # =======================
 371
 372     # Main loop of the Bot
 373     def loop(self):
 374         raw_music = ""
 375         while not self.exit and self.mumble.is_alive():
 376
 377             while self.thread and self.mumble.sound_output.get_buffer_size() > 0.5 and not self.exit:
 378                 # If the buffer isn't empty, I cannot send new music part, so I wait
 379                 self._loop_status = 'Wait for buffer %.3f' % self.mumble.sound_output.get_buffer_size()
 380                 time.sleep(0.01)
 381
 382             if self.thread:
 383                 # I get raw from ffmpeg thread
 384                 # move playhead forward
 385                 self._loop_status = 'Reading raw'
 386                 if self.song_start_at == -1:
 387                     self.song_start_at = time.time() - self.playhead
 388                 self.playhead = time.time() - self.song_start_at
 389
 390                 raw_music = self.thread.stdout.read(480)
 391
 392                 try:
 393                     stderr_msg = self.thread_stderr.readline()
 394                     if stderr_msg:
 395                         self.log.debug("ffmpeg: " + stderr_msg.strip("\n"))
 396                 except:
 397                     pass
 398
 399                 if raw_music:
 400                     # Adjust the volume and send it to mumble
 401                     self.volume_cycle()
 402                     self.mumble.sound_output.add_sound(
 403                         audioop.mul(raw_music, 2, self.volume))
 404                 else:
 405                     time.sleep(0.1)
 406             else:
 407                 time.sleep(0.1)
 408
 409             if not self.is_pause and (self.thread is None or not raw_music):
 410                 # ffmpeg thread has gone. indicate that last song has finished. move to the next song.
 411                 if not self.wait_for_downloading:
 412                     if var.playlist.next():
 413                         current = var.playlist.current_item()
 414                         if current.validate():
 415                             if current.is_ready():
 416                                 self.launch_music()
 417                                 self.async_download_next()
 418                             else:
 419                                 self.log.info("bot: current music isn't ready, start downloading.")
 420                                 self.wait_for_downloading = True
 421                                 current.async_prepare()
 422                                 self.send_msg(constants.strings('download_in_progress', item=current.format_short_string()))
 423                         else:
 424                             var.playlist.remove_by_id(current.id)
 425                             var.cache.free_and_delete(current.id)
 426                     else:
 427                         self._loop_status = 'Empty queue'
 428                 else:
 429                     current = var.playlist.current_item()
 430                     if current:
 431                         if current.is_ready():
 432                             self.wait_for_downloading = False
 433                             self.launch_music()
 434                             self.async_download_next()
 435                         elif current.is_failed():
 436                             var.playlist.remove_by_id(current.id)
 437                         else:
 438                             self._loop_status = 'Wait for downloading'
 439                     else:
 440                         self.wait_for_downloading = False
 441
 442         while self.mumble.sound_output.get_buffer_size() > 0:
 443             # Empty the buffer before exit
 444             time.sleep(0.01)
 445         time.sleep(0.5)
 446
 447         if self.exit:
 448             self._loop_status = "exited"
 449             if var.config.getboolean('bot', 'save_playlist', fallback=True) \
 450                     and var.config.get("bot", "save_music_library", fallback=True):
 451                 self.log.info("bot: save playlist into database")
 452                 var.playlist.save()
 453
 454     def volume_cycle(self):
 455         delta = time.time() - self.last_volume_cycle_time
 456
 457         if self.on_ducking and self.ducking_release < time.time():
 458             self._clear_pymumble_soundqueue()
 459             self.on_ducking = False
 460             self._max_rms = 0
 461
 462         if delta > 0.001:
 463             if self.is_ducking and self.on_ducking:
 464                 self.volume = (self.volume - self.ducking_volume) * math.exp(- delta / 0.2) + self.ducking_volume
 465             else:
 466                 self.volume = self.volume_set - (self.volume_set - self.volume) * math.exp(- delta / 0.5)
 467
 468         self.last_volume_cycle_time = time.time()
 469
 470     def ducking_sound_received(self, user, sound):
 471         rms = audioop.rms(sound.pcm, 2)
 472         self._max_rms = max(rms, self._max_rms)
 473         if self._display_rms:
 474             if rms < self.ducking_threshold:
 475                 print('%6d/%6d  ' % (rms, self._max_rms) + '-'*int(rms/200), end='\r')
 476             else:
 477                 print('%6d/%6d  ' % (rms, self._max_rms) + '-'*int(self.ducking_threshold/200) \
 478                       + '+'*int((rms - self.ducking_threshold)/200), end='\r')
 479
 480         if rms > self.ducking_threshold:
 481             if self.on_ducking is False:
 482                 self.log.debug("bot: ducking triggered")
 483                 self.on_ducking = True
 484             self.ducking_release = time.time() + 1 # ducking release after 1s
 485
 486     # =======================
 487     #      Play Control
 488     # =======================
 489
 490     def clear(self):
 491         # Kill the ffmpeg thread and empty the playlist
 492         if self.thread:
 493             self.thread.kill()
 494             self.thread = None
 495         var.playlist.clear()
 496         self.log.info("bot: music stopped. playlist trashed.")
 497
 498     def stop(self):
 499         self.interrupt()
 500         self.is_pause = True
 501         self.log.info("bot: music stopped.")
 502
 503     def interrupt(self):
 504         # Kill the ffmpeg thread
 505         if self.thread:
 506             self.thread.kill()
 507             self.thread = None
 508         self.song_start_at = -1
 509         self.playhead = 0
 510
 511     def pause(self):
 512         # Kill the ffmpeg thread
 513         if self.thread:
 514             self.pause_at_id = var.playlist.current_item().id
 515             self.thread.kill()
 516             self.thread = None
 517         self.is_pause = True
 518         self.song_start_at = -1
 519         self.log.info("bot: music paused at %.2f seconds." % self.playhead)
 520
 521     def resume(self):
 522         self.is_pause = False
 523
 524         if var.playlist.current_index == -1:
 525             var.playlist.next()
 526
 527         music_wrapper = var.playlist.current_item()
 528
 529         if not music_wrapper or not music_wrapper.id == self.pause_at_id or not music_wrapper.is_ready():
 530             self.playhead = 0
 531             return
 532
 533         if var.config.getboolean('debug', 'ffmpeg'):
 534             ffmpeg_debug = "debug"
 535         else:
 536             ffmpeg_debug = "warning"
 537
 538         self.log.info("bot: resume music at %.2f seconds" % self.playhead)
 539
 540         uri = music_wrapper.uri()
 541
 542         command = ("ffmpeg", '-v', ffmpeg_debug, '-nostdin', '-ss', "%f" % self.playhead, '-i',
 543                    uri, '-ac', '1', '-f', 's16le', '-ar', '48000', '-')
 544
 545
 546         if var.config.getboolean('bot', 'announce_current_music'):
 547             self.send_msg(var.playlist.current_item().format_current_playing())
 548
 549         self.log.info("bot: execute ffmpeg command: " + " ".join(command))
 550         # The ffmpeg process is a thread
 551         # prepare pipe for catching stderr of ffmpeg
 552         pipe_rd, pipe_wd = os.pipe()
 553         util.pipe_no_wait(pipe_rd) # Let the pipe work in non-blocking mode
 554         self.thread_stderr = os.fdopen(pipe_rd)
 555         self.thread = sp.Popen(command, stdout=sp.PIPE, stderr=pipe_wd, bufsize=480)
 556         self.last_volume_cycle_time = time.time()
 557         self.pause_at_id = ""
 558
 559
 560     # TODO: this is a temporary workaround for issue #44 of pymumble.
 561     def _clear_pymumble_soundqueue(self):
 562         for id, user in self.mumble.users.items():
 563             user.sound.lock.acquire()
 564             user.sound.queue.clear()
 565             user.sound.lock.release()
 566         self.log.debug("bot: pymumble soundqueue cleared.")
 567
 568
 569
 570 def start_web_interface(addr, port):
 571     global formatter
 572     import interface
 573
 574     # setup logger
 575     werkzeug_logger = logging.getLogger('werkzeug')
 576     logfile = util.solve_filepath(var.config.get('webinterface', 'web_logfile'))
 577     handler = None
 578     if logfile:
 579         handler = logging.handlers.RotatingFileHandler(logfile, mode='a', maxBytes=10240) # Rotate after 10KB
 580     else:
 581         handler = logging.StreamHandler()
 582
 583     werkzeug_logger.addHandler(handler)
 584
 585     interface.init_proxy()
 586     interface.web.env = 'development'
 587     interface.web.run(port=port, host=addr)
 588
 589
 590 if __name__ == '__main__':
 591     parser = argparse.ArgumentParser(
 592         description='Bot for playing music on Mumble')
 593
 594     # General arguments
 595     parser.add_argument("--config", dest='config', type=str, default='configuration.ini',
 596                         help='Load configuration from this file. Default: configuration.ini')
 597     parser.add_argument("--db", dest='db', type=str,
 598                         default=None, help='database file. Default: database.db')
 599
 600     parser.add_argument("-q", "--quiet", dest="quiet",
 601                         action="store_true", help="Only Error logs")
 602     parser.add_argument("-v", "--verbose", dest="verbose",
 603                         action="store_true", help="Show debug log")
 604
 605     # Mumble arguments
 606     parser.add_argument("-s", "--server", dest="host",
 607                         type=str, help="Hostname of the Mumble server")
 608     parser.add_argument("-u", "--user", dest="user",
 609                         type=str, help="Username for the bot")
 610     parser.add_argument("-P", "--password", dest="password",
 611                         type=str, help="Server password, if required")
 612     parser.add_argument("-T", "--tokens", dest="tokens",
 613                         type=str, help="Server tokens, if required")
 614     parser.add_argument("-p", "--port", dest="port",
 615                         type=int, help="Port for the Mumble server")
 616     parser.add_argument("-c", "--channel", dest="channel",
 617                         type=str, help="Default channel for the bot")
 618     parser.add_argument("-C", "--cert", dest="certificate",
 619                         type=str, default=None, help="Certificate file")
 620
 621     args = parser.parse_args()
 622
 623     config = configparser.ConfigParser(interpolation=None, allow_no_value=True)
 624     parsed_configs = config.read([util.solve_filepath('configuration.default.ini'), util.solve_filepath(args.config)],
 625                                  encoding='utf-8')
 626     var.dbfile = args.db if args.db is not None else util.solve_filepath(
 627         config.get("bot", "database_path", fallback="database.db"))
 628
 629     if len(parsed_configs) == 0:
 630         logging.error('Could not read configuration from file \"{}\"'.format(args.config))
 631         sys.exit()
 632
 633     var.config = config
 634     var.db = SettingsDatabase(var.dbfile)
 635
 636     # Setup logger
 637     bot_logger = logging.getLogger("bot")
 638     formatter = logging.Formatter('[%(asctime)s %(levelname)s %(threadName)s] %(message)s', "%b %d %H:%M:%S")
 639     bot_logger.setLevel(logging.INFO)
 640
 641     logfile = util.solve_filepath(var.config.get('bot', 'logfile'))
 642     handler = None
 643     if logfile:
 644         handler = logging.handlers.RotatingFileHandler(logfile, mode='a', maxBytes=10240) # Rotate after 10KB
 645     else:
 646         handler = logging.StreamHandler()
 647
 648     handler.setFormatter(formatter)
 649     bot_logger.addHandler(handler)
 650     var.bot_logger = bot_logger
 651
 652     if var.config.get("bot", "save_music_library", fallback=True):
 653         var.music_db = MusicDatabase(var.dbfile)
 654     else:
 655         var.music_db = MusicDatabase(":memory:")
 656
 657     var.cache = MusicCache(var.music_db)
 658
 659     # load playback mode
 660     playback_mode = None
 661     if var.db.has_option("playlist", "playback_mode"):
 662         playback_mode = var.db.get('playlist', 'playback_mode')
 663     else:
 664         playback_mode = var.config.get('bot', 'playback_mode', fallback="one-shot")
 665
 666     if playback_mode in ["one-shot", "repeat", "random", "autoplay"]:
 667         var.playlist = media.playlist.get_playlist(playback_mode)
 668     else:
 669         raise KeyError("Unknown playback mode '%s'" % playback_mode)
 670
 671     var.bot = MumbleBot(args)
 672     command.register_all_commands(var.bot)
 673
 674     if var.config.get("bot", "refresh_cache_on_startup", fallback=True)\
 675             or not var.db.has_option("dir_cache", "files"):
 676         var.cache.build_dir_cache(var.bot)
 677     else:
 678         var.cache.load_dir_cache(var.bot)
 679
 680     # load playlist
 681     if var.config.getboolean('bot', 'save_playlist', fallback=True):
 682         var.bot_logger.info("bot: load playlist from previous session")
 683         var.playlist.load()
 684
 685     # Start the main loop.
 686     var.bot.loop()