Commits

Marc-Alexandre Chan committed 1a2448b

Scheduler logging/error handling, event logging completed

Comments (0)

Files changed (3)

 # - end() - Called upon termination of the event. This can occur between
 #       repetitions, and so run() is NOT called.
 # - handle_exception(exception) - Called upon an exception occurring within an
-#   event. Returns a boolean value -``true`` indicates a handled exception,
-#   ``false`` indicates an exception that could not be handled and that should
+#   event. Returns a boolean value -``True`` indicates a handled exception,
+#   ``False`` indicates an exception that could not be handled and that should
 #   be handled by the scheduler. (A scheduler may handle the exception by
 #   considering the event corrupt and dropping/logging it, or it may re-throw
 #   it). This method must not raise an exception.
 
 
 from minibot import MinibotError
-import minibot.logger
 from minibot.db import Prompt, User, SuggestionThread
 from minibot.util import DateParseMixin, MarkdownMixin, DataFormatMixin,\
     classname, get_reddit_url
 
 # TODO: error handling
 # TODO: repr
-# TODO: use logger resource instead of _evlog
 
 # this is in all superscript (renders equiv. small text) ^(syntax is like this)
 _BOT_MSG = ("^(Having a problem with DailyPromptBot? Want to comment? You can "
 "DailyPromptBot? It's open-source! Here's [the DailyPromptBot "
 "repository](https://bitbucket.org/Laogeodritt/dailypromptbot).)")
 
-#_evlog = minibot.logger.getChild('events')
-
-
 class CommandError(MinibotError):
     """ Abstract base class for Command errors. """
 
         * ``priority`` = 90
 
     """
-    required_res = ['reddit', 'approved', 'config.minibot']
+    required_res = ['reddit', 'approved', 'config.minibot', 'logger']
     start_time = 0
     duration = -1
     interval = 10
         self.reddit = self.res['reddit']
         self.users = self.res['approved']
         self.msg_chunk = self.res['config.minibot'].msg_chunk
+        self.log = self.res['logger']
 
         self.run()
 
             else: # bad message, ignore it
                 # if bad PM, log; don't care about replies/comments though
                 if msg.subreddit is None:
-                    _evlog.info(
+                    self.log.info(
                         ("%s: Ignoring bad PM from %s (%d)"),
                         classname(self), msg.author, msg.id)
                 msg.mark_as_read()
         No validation of the data is performed.
 
         """
-        _evlog.debug('%s: Parsing message %d from %s.',
+        self.log.debug('%s: Parsing message %d from %s.',
             classname(self), msg.id, msg.author)
         msg_data = {}
         text_data = []
         #    raise CommandParseError(
         #            ''.join(["No parameter value in line: \"", line, "\""]))
 
-        _evlog.debug('%s: Parsed argument line: %s = %s',
+        self.log.debug('%s: Parsed argument line: %s = %s',
             classname(self), field_data[0], field_data[1])
 
         return field_data
         data. If the command name is invalid, raises a CommandNameError. If the
         command parameters are invalid or incomplete, raises a
         CommandParametersError (from the command constructor). """
-        _evlog.info('%s: PM %d: building command: %s',
+        self.log.info('%s: PM %d: building command: %s',
             classname(self), msg.id, '; '.join(data))
         if data['action'] in self.cmd_actions.keys():
             CommandClass = self.cmd_actions[data.pop('action')]
         * ``priority`` = 80
 
     """
-    required_res = ['dbsession', 'config.minibot']
-    interval = 5
+    required_res = ['dbsession', 'config.minibot', 'logger']
+    start_time = 0
+    interval = 60
     duration = -1
     priority = 80
 
         pass
 
     def start(self):
+        self.log = self.res['logger']
         self.run()
         return
 
                 filter(Prompt.status == Prompt.STATUS_QUEUED).\
                 order_by(Prompt.post_time)[0:int(self.queue_rate)]:
             if id_ not in queued_id:
-                _evlog.info("%s: Queuing prompt %s at %s", classname(self),
+                self.log.info("%s: Queuing prompt %s at %s", classname(self),
                 id_, t_post.strftime("%Y-%m-%d %H:%M:%S UTC"))
                 new_cmd = PostPromptCommand(id_, t_post)
                 self.owner.queue_event(new_cmd)
         * ``priority`` = 75
 
     """
-    required_res = ['dbsession', 'config.minibot']
-    interval = 5
+    required_res = ['dbsession', 'config.minibot', 'logger']
+    start_time = 0
+    interval = 60
     duration = -1
     priority = 75
 
         pass
 
     def start(self):
+        self.log = self.res['logger']
         self.run()
         return
 
                 filter(SuggestionThread.status==SuggestionThread.STATUS_QUEUED).\
                 order_by(SuggestionThread.time)[0:int(self.queue_rate)]:
             if id_ not in queued_ids:
-                _evlog.info(
+                self.log.info(
                     "%s: Queued thread %s at %s", classname(self),
                     id_, t_post.strftime("%Y-%m-%d %H:%M:%S UTC"))
                 new_cmd = PostSuggestionThreadCommand(id_, t_post)
 
 
 class SuggestionThreadQueueMaintainer(object, DateParseMixin):
-    """ Skeleton event for the Minibot form of the bot. This event checks the
-    current Suggestion Threads queue, and when no suggestion threads are queued,
-    queues one the specified number of days after the previous one, at the
-    time specified (both in the configuration).
+    """ Skeleton event for the Minibot form of the bot. This event checks
+    whether next week's suggestion thread is already queued, and if not,
+    queues one the specified weekday at the specified time (both in the
+    configuration).
 
     Defaults:
         * ``start_time`` = 0 (immediately)
         * ``priority`` = 50
 
         """
-    required_res = ['reddit', 'dbsession', 'config.events']
+    required_res = ['reddit', 'dbsession', 'config.events', 'logger']
     start_time = 0
     duration = -1
     interval = 300
         pass
 
     def start(self):
+        self.log = self.res['logger']
         self.run()
 
     def run(self):
         day_next = dt_now.date() + delta_next
         dt_next = dt_now + delta_next
         dt_next_end = dt_next + timedelta(days=1)
-        _evlog.debug("%s: Checking %s to %s",
+        self.log.debug("%s: Checking %s to %s",
             classname(self), dt_next.strftime("%Y-%m-%d %H:%M:%S"))
 
         # find any thread on the next post date
             new_post_dt = datetime.combine(day_next, post_time)
             new_thread = SuggestionThread(new_post_dt)
             db.add(new_thread)
-            _evlog.info("%s: Added thread for %s to database", classname(self),
+            self.log.info("%s: Added thread for %s to database", classname(self),
             new_post_dt.strftime("%Y-%m-%d %H:%M:%S"))
-            _evlog.debug("%s: %s", classname(self), repr(new_thread))
+            self.log.debug("%s: %s", classname(self), repr(new_thread))
             db.commit()
         else: # if a thread is found on that day, no action to take
             pass
 
     """
     # TODO: Clean up repetition of UpdatePromptCommand & very long methods
-    required_res = ['reddit', 'dbsession', 'config.events', 'config.reddit']
+    required_res = ['reddit', 'dbsession', 'config.events', 'config.reddit',
+                    'logger']
     start_time = 0 # execute ASAP
 
     def __init__(self, msg, **kwargs):
         db     = self.res['dbsession']
         default_time_str = self.res['config.events'].default_time
         target_reddit = self.res['config.reddit'].target
+        self.log = self.res['logger']
 
         ### process default and inferred Prompt attributes ###
         # status
 
         # check approver in User table
         if not db.query(User).filter(User.r_id==r_approver_id).count():
-            _evlog.info(
+            self.log.info(
                 "%s: User %s not found. Adding to database `user` table.",
                 classname(self), approver_name)
             new_user = User(r_approver_id, approver_name)
             db.add(new_user) # set as unregistered by default
         else:
-            _evlog.debug(
+            self.log.debug(
                 "%s: User %s (%s) found in database `user` table.",
                 classname(self), r_approver_id, approver_name)
 
         new_prompt.post_time = post_time
         db.add(new_prompt)
 
-        _evlog.info("%s: Added prompt '%s' (%d) to database queue.",
+        self.log.info("%s: Added prompt '%s' (%d) to database queue.",
             classname(self), self.title, new_prompt.id)
-        _evlog.debug("%s: %s", classname(self), repr(new_prompt))
+        self.log.debug("%s: %s", classname(self), repr(new_prompt))
 
         db.commit()
         self.msg.mark_as_read()
 
-        _evlog.info("%s: Marked message %s as read.",
+        self.log.info("%s: Marked message %s as read.",
             classname(self), self.msg.name)
 
         reply_topic = ''.join([target_reddit, ": Prompt added"])
                 break
             else:
                 continue
-        _evlog.debug("%s: Nearest unqueued date found: %s.",
+        self.log.debug("%s: Nearest unqueued date found: %s.",
             classname(self), current_date.stftime('%Y-%m-%d'))
         return current_date
 
         * ``interval`` = 0
 
     """
-    required_res = ['reddit', 'dbsession']
+    required_res = ['reddit', 'dbsession', 'logger']
     start_time = 0 # execute ASAP
 
     def __init__(self, msg, **kwargs):
         # resources
         reddit = self.res['reddit']
         db     = self.res['dbsession']
+        self.log = self.res['logger']
 
         del_prompt = db.query(Prompt).filter(Prompt.id==self.id).first()
         if del_prompt is None:
                 ''.join(["Prompt ", self.id, " not found."]))
         del_prompt.status = del_prompt.STATUS_REJECTED
 
-        _evlog.info("%s: Removed prompt '%s' (%d) from database queue.",
+        self.log.info("%s: Removed prompt '%s' (%d) from database queue.",
             classname(self), self.title, del_prompt.id)
 
         db.commit()
         self.msg.mark_as_read()
 
-        _evlog.info("%s: Marked message %s as read.",
+        self.log.info("%s: Marked message %s as read.",
                     classname(self), self.msg.name)
 
         reply_title = ''.join([target_reddit, ": Prompt deleted"])
 
     """
     # TODO: Clean up repetition of AddPromptCommand & very long methods
-    required_res = ['reddit', 'dbsession', 'config.events', 'config.reddit']
+    required_res = ['reddit', 'dbsession', 'config.events', 'config.reddit',
+                    'logger']
     start_time = 0 # execute ASAP
 
     def __init__(self, msg, **kwargs):
         db     = self.res['dbsession']
         default_time_str = self.res['config.events'].default_time
         target_reddit = self.res['config.reddit'].target
+        self.log = self.res['logger']
 
         upd_prompt = db.query(Prompt).filter(Prompt.id==self.id).first()
         if upd_prompt is None:
             new_user = User(upd_prompt.r_approver_id, approver_name)
             db.add(new_user) # set as unregistered by default
 
-        _evlog.info(
+        self.log.info(
             "%s: Updated prompt '%s' (%d) in database queue.",
             classname(self), self.title, upd_prompt.id)
-        _evlog.debug("%s: %s", classname(self), repr(upd_prompt))
+        self.log.debug("%s: %s", classname(self), repr(upd_prompt))
 
         db.commit()
         self.msg.mark_as_read()
 
-        _evlog.info("%s: Marked message %s as read.",
+        self.log.info("%s: Marked message %s as read.",
                     classname(self), self.msg.name)
 
         reply_title = ''.join([target_reddit, ": Prompt updated"])
                 break
             else:
                 continue
-        _evlog.debug("%s: Nearest unqueued date found: %s.",
+        self.log.debug("%s: Nearest unqueued date found: %s.",
             classname(self), current_date.stftime('%Y-%m-%d'))
         return current_date
 
         * ``interval`` = 0
 
     """
-    required_res = ['reddit']
+    required_res = ['reddit', 'logger']
     start_time = 0
 
     def __init__(self, user, title, text):
             raise MissingParameterError('Cannot send message without body text.')
 
     def start(self):
+        self.log = self.res['logger']
         self.res['reddit'].compose_message(self.user, self.title, self.text)
-        _evlog.info("%s: Sent PM titled '%s' to %s.", classname(self),
+        self.log.info("%s: Sent PM titled '%s' to %s.", classname(self),
             self.title, self.user)
 
     def run(self):
         * ``interval`` = 0
 
     """
+    required_res = ['logger']
     start_time = 0 # execute ASAP
 
     def __init__(self, source_msg, subject, text):
                 'Cannot send message without body text.')
 
     def start(self):
+        self.log = self.res['logger']
         self.msg.reply(self.text)
-        _evlog.info("%s: Sent Reddit reply to %s from %s.", classname(self),
+        self.log.info("%s: Sent Reddit reply to %s from %s.", classname(self),
             self.msg.name, self.msg.user)
 
     def run(self):
     SHORT_TEXT_LENGTH = 100
     MAX_ENTRIES = 30
     start_time = 0 # execute ASAP
-    required_res = ['reddit', 'dbsession']
+    required_res = ['reddit', 'dbsession', 'logger']
 
     def __init__(self, msg, **kwargs):
         """ Constructor. Keyword arguments are strings defined as per the
         self.limit = max(1, min(self.MAX_ENTRIES, par_limit))
 
     def start(self):
+        self.log = self.res['logger']
         query = self.res['dbsession'].query(Prompt)
 
         if self.ids:
         else: # long list = newlines between entries
             self.msg.reply(u'\n'.join(prompt_list))
 
-        _evlog.info("%s: Sent PM list to %s for prompts %s.",
+        self.log.info("%s: Sent PM list to %s for prompts %s.",
             classname(self), self.msg.author, ', '.join(prompt_ids))
 
         self.msg.mark_as_read()
-        _evlog.info("%s: Marked message %s as read.",
+        self.log.info("%s: Marked message %s as read.",
             classname(self), self.msg.name)
 
     def run(self):
             self.msg = msg
 
     def start(self):
+        self.log = self.res['logger']
         with open('minibot/commands.txt') as help_file:
             self.msg.reply(help_file.read())
-        _evlog.info("%s: Sent help message to",
+        self.log.info("%s: Sent help message to",
             classname(self), self.msg.author)
 
     def run(self):
     SUBMITTER_TEXT = u"Originally suggested by {user}{permalink}."
     SOURCE_ONLY_TEXT = u"Originally suggested at [permalink]({permalink})."
     APPROVER_TEXT  = u"Selected by {approver}."
-    required_res = ['reddit', 'dbsession', 'config.reddit']
+    required_res = ['reddit', 'dbsession', 'config.reddit', 'logger']
 
     def __init__(self, post_id, post_time):
         """ Constructor. Throws MissingParameterError or CommandParameterError
         target = self.res['config.reddit'].target
         reddit = self.res['reddit']
         db = self.res['dbsession']
+        self.log = self.res['logger']
 
         prompt = self.prompt = db.query(Prompt).get(self.post_id)
         if prompt is None:
 
         prompt.r_post_id = r_sub.id
         prompt.status = prompt.STATUS_POSTED
-        _evlog.info("%s: Posted prompt %d to /r/%s", classname(self),
+        self.log.info("%s: Posted prompt %d to /r/%s", classname(self),
             prompt.id, target)
         db.commit()
 
                 "and queue them up for next week or beyond.\n\n"
                 "{text}\n\n"
                 "Please try to avoid repeating suggestions that were already "
-                "posted in the last few weeksâ€we probably already read it "
+                "posted in the last few weeks—we probably already read it "
                 "and either didn't find it interesting enough to post or liked "
                 "it enough to queue it up later on!")
     NAV_MENU = (u"| | | |\n"
                 u"| :-: | :-: | :-: |\n"
-                u"| « {prev} | .:{cur}:. | {next} » |\n"
+                u"| « {prev} | .:{cur}:. | {next} » |\n"
                 u"| | | |\n")
 
-    required_res = ['reddit', 'dbsession', 'config.reddit']
+    required_res = ['reddit', 'dbsession', 'config.reddit', 'logger']
     def __init__(self, post_id, post_time):
         """ Constructor. Throws MissingParameterError or CommandParameterError
         on missing or invalid parameters (respectively). """
         target = self.res['config.reddit'].target
         reddit = self.res['reddit']
         db = self.res['dbsession']
+        self.log = self.res['logger']
 
         thread = self.thread = db.query(SuggestionThread).get(self.post_id)
         self.prev_thread = self._find_prev_thread()
         thread.status = thread.STATUS_ACTIVE
         self._archive_older_threads()
         self._add_link_to_last_thread()
-        _evlog.info("%s: Posted suggestion thread %d to /r/%s", classname(self),
+        self.log.info("%s: Posted suggestion thread %d to /r/%s", classname(self),
             thread.id, target)
         db.commit()
 
                     filter(SuggestionThread.time < prev_end).\
                     order_by(SuggestionThread.time).limit(1).first()
         if thread:
-            _evlog.info("%s: Found previous thread %d (%s) <%s>",
+            self.log.info("%s: Found previous thread %d (%s) <%s>",
                 classname(self), thread.id,
                 thread.time.strftime("%Y-%m-%d %H:%M:%S"),
                 get_reddit_url(thread.r_post_id, self.res['reddit']))
         else:
-            _evlog.warn("%s: No previous week's thread found.", classname(self))
+            self.log.warn("%s: No previous week's thread found.",
+                          classname(self))
         return thread
 
     def _archive_older_threads(self):
                 filter(SuggestionThread.status == self.thread.STATUS_ACTIVE):
             other_thread.status = other_thread.STATUS_ARCHIV
             threads.append(other_thread.r_post_id)
-        _evlog.info("%s: Archived %d other threads: %s", classname(self),
+        self.log.info("%s: Archived %d other threads: %s", classname(self),
             len(threads), ', '.join(threads))
 
     def _add_link_to_last_thread(self):
                                         self.prev_thread.r_post_id,
                                         self.res['reddit'])
             self.prev_thread.text = self.prev_thread.text.replace(
-                ' '.join(['|', curr_date_str, '» |']),
-                ' '.join(['|', self.md_link(curr_date_str, post_url), '» |')])
+                ' '.join(['|', curr_date_str, '» |']),
+                ' '.join(['|', self.md_link(curr_date_str, post_url), '» |')])
 
             r_thread = self.res['reddit'].\
                        get_submission(submission_id=self.prev_thread.r_post_id)
             r_thread.edit(self.prev_thread.text)
-            _evlog.info("%s: Edited navigation link to thread %s in previous "
+            self.log.info("%s: Edited navigation link to thread %s in previous "
                 "thread %s", classname(self), self.thread.r_post_id,
                 self.prev_thread.r_post_id)
 

minibot/eventscheduler.py

 #-------------------------------------------------------------------------------
 
 from minibot import MinibotError
+from minibot.util import classname, log_exc_info
 
 from reddit import Reddit
 
     Scheduler. """
     pass
 
+class AttachedEventError(MinibotError):
+    """ Raised when an Event has already been assigned an owner attribute upon
+    queueing. These Event objects are unsafe to queue into the scheduler, as
+    they have been queued previously and may have already run; hence, the
+    internal state of the Event cannot be guaranteed. """
+    pass
+
 class EventScheduler(object):
     """ Event scheduler. Manages and runs events at specified times and
     repetition intervals. This class acts as the kernel/event scheduler to the
     STATUS_RUNNING = 1  # started, on periodic (interval) runs
     STATUS_ONESHOT = 2  # queued, not started, one-shot event
     STATUS_ENDING  = 3  # queued, runs ending at the given time
+    STATUS_STRING = {STATUS_QUEUED : 'Queued',
+                     STATUS_RUNNING : 'Running',
+                     STATUS_ONESHOT : 'Queued (one-shot)',
+                     STATUS_ENDING : 'Ending'}
 
     def __init__(self, config, reddit, database, logger, **res):
         """ Initialise the Minibot. ``config`` should be an instance of the
         ``minibot.Config`` class with a loaded configuration file, or an
-        instance of a class with the same accessible attributes.
+        instance of a class with the same accessible attributes. ``logger``
+        should be the parent logger to use (EventScheduler will always
+        use the ``scheduler`` child of this logger).
 
         kwargs should be other resource objects that can be made available to
         events. Note that reserved names 'config', 'dbsession', 'reddit',
         self._config = config
         self._reddit = reddit
         self._db     = database
-        self._logger = logger
         self._res    = res
 
         # state
         self._next_run = 0
 
         # components
-        self.logger = logger if logger is not None\
-                        else logging.getLogger('dailyprompt.scheduler')
-
-        # extra processing
-        if not self.pidfile_path.endswith('.pid'):
-            self.pidfile_path += '.pid'
+        self.logger = logger.getChild('scheduler') if logger is not None\
+                        else logging.getLogger('scheduler')
 
         self.__init_validate()
 
                 self._config.reddit.password)
 
         # valid target reddit test
-        if not self._reddit.get_subreddit(self._config.reddit.target):
+        try:
+            self._reddit.get_subreddit(self._config.reddit.target).content_id
+        except Exception:
             raise InvalidRedditError("{} is not a valid reddit".format(
                 self._config.reddit.target))
 
         """ Run the event scheduler. The event scheduler will run until an
         exit or stop request is made by an event, or no more events exist in
         queue. """
+        self.logger.info("%s: Starting event scheduler...", classname(self))
         self._next_run = time.time()
         self._exit_flag = self._stop_flag = False
         while not self._exit_flag and not self._stop_flag and self._queue:
             # update the next run time
             self._next_run += config.minibot.refresh_rate
             # if execution took longer than the refresh rate, do next iter now
-            if time.time() > self._next_run:
-                self._next_run = time.time()
+            now = time.time()
+            if now > self._next_run:
+                self._next_run = now
 
         if self._exit_flag:
             self.exit()
+        elif self._stop_flag:
+            self.logger.info("%s: Stopped the event scheduler.",classname(self))
 
     def _execute_iteration(self):
         """ Execute an iteration. Pops events off the queue and executes them
-        until an event is found which is _not_ supposed to run right now.
+        until an event is found which is scheduled for the future.
 
         Assumes there is at least one item in queue. """
-        # TODO: error handling, logging
         now = self._next_run # get the timestamp for the current iteration
         evtuple = self._queue[0]
         while evtuple[0] <= now:
             del self._queue[0]
-            self._execute_event(*evtuple)
-            self._reschedule_event(*evtuple)
+            try:
+                self._execute_event(*evtuple)
+            except Exception as e:
+                # get exception info
+                event = evtuple[3]
+                basic, src, trace = log_exc_info()
+                self.logger.error("%s: A '%s' was raised by %s",
+                    classname(self), classname(e), classname(event))
+                self.logger.warn(*basic)
+                self.logger.debug(*src)
+                self.logger.debug(*trace)
+
+                # pass exception to event exception handler
+                try: # just in case
+                    is_handled = event.handle_exception(e)
+                except Exception as ehe: # UGH WHYYYYYY
+                    is_handled = False
+                    basic2, src2, trace2 = log_exc_info()
+                    self.logger.error("%s: %s was raised in the exception "
+                        "handler for %s",
+                        classname(self), classname(ehe), repr(event))
+                    self.logger.error(*basic2)
+                    self.logger.debug(*src2)
+                    self.logger.debug(*trace2)
+
+                # let's get back to the original exception...
+                if is_handled: # event recovered from error
+                    self.logger.warn("%s: '%s' handled by %s",
+                        classname(self), classname(e), classname(event))
+                else: # unrecoverable error in event
+                    self.logger.critical("%s: Dropped event due to unhandled "
+                        "exception: %s. This operation is unsafe and may leave "
+                        "open handles or cause errors or instability.",
+                        classname(self), repr(event))
+
+                    # try to clean up
+                    if event.res.get('dbsession', None) is not None:
+                        event.res['dbsession'].rollback()
+                        event.res['dbsession'].close()
+                        del event.res['dbsession']
+                    del event
+                    del evtuple
+
+            else: # if no exception occurs in the exec
+                self._reschedule_event(*evtuple)
             evtuple = self._queue[0]
 
     def _execute_event(self, time, priority, status, event):
-        # TODO: error handling/logging
-        if status == self.STATUS_QUEUED or status == self.STATUS_ONESHOT:
+        if status == self.STATUS_QUEUED:
+            self.logger.info("%s: Starting event: %s",
+                             classname(self), repr(event))
             event.start()
+        elif status == self.STATUS_ONESHOT:
+            self.logger.info("%s: Running one-shot event: %s",
+                             classname(self), repr(event))
+            event.start()
+            event.end()
         elif status == self.STATUS_RUNNING:
             event.run()
         elif status == self.STATUS_ENDING:
+            self.logger.info("%s: Terminating event: %s",
+                             classname(self), repr(event))
             event.end()
 
     def exit(self):
         """ Clean up events and exit the scheduler. This method should be called
         before destroying the EventScheduler or exiting the application. """
-        pass # TODO: exit cleanup
+        self.logger.info("%s: Exiting the event scheduler.", classname(self))
+        self.logger.info("%s: Stopping all events.", classname(self))
+        while self._queue:
+            evtime, evpriority, evstatus, event = self._queue.pop(0)
+            if evstatus == self.STATUS_RUNNING or\
+               evstatus == self.STATUS_ENDING:
+                event.end()
+                del event
+                self.logger.debug("%s: Stopped event: %s",
+                                  classname(self), repr(event))
+            elif evstatus == self.STATUS_QUEUED or\
+                 evstatus == self.STATUS_ONESHOT:
+                del event
+                self.logger.debug("%s: Dropped queued event: %s",
+                                  classname(self), repr(event))
 
     def queue_event(self, event):
-        """ Queues an event for execution. """
+        """ Queues a new event object for execution. The event object should
+        have been newly constructed; an event object that has already been
+        queued or executed may not have a consistent internal state for queueing
+        and starting. """
+        if hasattr(event, 'owner'):
+            raise AttachedEventError(("Cannot queue Event '{}': "
+                "Event is already attached to an EventScheduler. Please only "
+                "queue new events to the scheduler.").format(classname(event)))
+
         self.prepare_event(event)
         if event.interval > 0 and event.duration > 0:
             status = self.STATUS_QUEUED
         else:
             status = self.STATUS_ONESHOT
         self._insert_event(event.start_time, event.priority, status, event)
+        self.logger.info(
+            "%s: Queued event: time=%s, priority=%d, status=%s, event=%s",
+            classname(self),
+            time.strftime('%Y-%m-%d %H:%M:%S',time.localtime(event.start_time)),
+            r_priority, self.STATUS_STRING[r_status], repr(event))
 
     def _insert_event(self, time, priority, status, event):
         """ Insert an event into the appropriate location in a queue. """
     def _reschedule_event(self, time, priority, status, event):
         """ Check whether the event needs to be rescheduled and reschedules it.
         Called during the main loop. """
-        pass # TODO
+        # using _next_run calibrates to the actual iteration runtime, not the
+        # event's expected runtime, and _next_run resets in _execute_iteration()
+        # if it lags behind, so no worries about the reschedules lagging behind
+        # with long-runtime events
+        now = self._next_run
+        r_priority = event.priority
+
+        # refresh resources in the event
+        self.prepare_event(event)
+
+        if status == self.STATUS_QUEUED or status == self.STATUS_RUNNING:
+            r_time = now + event.interval
+            end_time = event.start_time + event.duration
+
+            # if infinite duration or end time is later than next run
+            if event.duration <= 0 or end_time > r_time:
+                r_status = self.STATUS_RUNNING
+            else: # ending
+                r_status = self.STATUS_ENDING
+                r_time   = end_time
+
+            self._insert_event(r_time, r_priority, r_status, event)
+            self.logger.debug(
+                "%s: Requeued event: time=%s, priority=%d, status=%s, event=%s",
+                classname(self),
+                time.strftime('%Y-%m-%d %H:%M:%S', time.localtime(r_time)),
+                r_priority, self.STATUS_STRING[r_status], repr(event))
+
+        # STATUS_ENDING or STATUS_ONESHOT have now ended and cleaned up
+        # so nothing to do there
 
     def prepare_event(self, event):
         """ Prepare a event for entry into the queue. This fills the resources
             self._set_resource(res_name, event.res)
         self._set_timing(event)
 
-    def _set_resource(self, res_name, res_dict):
+    def _set_resource(self, res_name, event):
         """ Set resources to an event's resource dict. If the resource is not
         known, raise a ResourceError. """
         if res_name == 'reddit':
-            res_dict['reddit'] = self._reddit
+            event.res['reddit'] = self._reddit
         elif res_name == 'approved':
-            res_dict['approved'] = self._approved
+            event.res['approved'] = self._approved
         elif res_name == 'logger':
-            res_dict['logger'] = self._logger.getChild('events').\
-                                    getChild()
+            event.res['logger'] = self.logger.getChild('events').\
+                                    getChild(classname(event))
         elif res_name == 'config':
-            res_dict['config'] = self._config
+            event.res['config'] = self._config
         elif res_name.startswith('config.') and\
                 hasattr(config, res_name[7:]):
-            res_dict[res_name] = getattr(self._config, res_name[7:])
+            event.res[res_name] = getattr(self._config, res_name[7:])
         elif (res_name == 'dbsession' and
-                ('dbsession' not in res_dict.keys() or
-                    res_dict['dbession'] is None)):
-            res_dict['dbsession'] = db.get_new_session()
+                ('dbsession' not in event.res.keys() or
+                    event.res['dbession'] is None)):
+            event.res['dbsession'] = db.get_new_session()
+            self.logger.debug('%s: Starting new database session for %s',
+                classname(self), repr(event))
         elif res_name in self._res.keys():
-            res_dict[res_name] = self._res[res_name]
+            event.res[res_name] = self._res[res_name]
         else:
-            raise ResourceError("Unknown resource '{}' requested by {}: {}".
-                format(res_name, event.__class__.__name__, repr(event)))
+            raise ResourceError("Unknown resource '{}' requested by {}".
+                format(res_name, repr(event)))
 
     def _set_timing(self, event):
         """ Set default event timing values if necessary. """
         """ Request that the event scheduler cleans up all events and exits
         on the next iteration. """
         self._exit_flag = True
+        self.log.info("%s: Exit requested", classname(self))
 
     def request_stop(self):
         """ Requests that the event scheduler stop running on the next
         iteration. """
         self._stop_flag = True
+        self.log.info("%s: Stop requested", classname(self))
 
-    # TODO: exception handling inside events (+ handlers in events)
-
-# old stuff
-
-    def postNextPrompt(self):
-        pass
-
-    def checkMessages(self):
-        pass
-
-    def _checkMessage(self):
-        pass
-
-    def addPrompt(self):
-        pass
-
-    def removePrompt(self):
-        pass
-
-    def listPrompts(self):
-        pass
-
-    def handleTerminateSignal(self):
-        pass
-
 import re
 import copy
 
+from sys import exc_info
+from traceback import extract_tb, format_tb
+
+def log_exc_info(self):
+    """ Formats the currently handled exception for logging. Returns a tuple of
+    three tuples, each one a set of arguments to a logging function. The first
+    tuple is general information (message, function, file, line) meant for,
+    error(), the second is the source line meant for debug(), and the last is a
+    full traceback meant for debug(). """
+    eclass, e, etrace = exc_info()
+    efile, eline, efunc, esource = extract_tb(etrace)[-1]
+    basic_info = ("%s: %s raised in '%s', file '%s', line %i",
+                  classname(eclass), str(e), efunc, efile, eline)
+    src_line = ("    %s", esource)
+    traceback = ("Traceback (most recent call last):\n%s",
+                 ''.join(format_tb(etrace)))
+    return (basic_info, src_line, traceback)
+
 def get_reddit_url(id, reddit):
     """ Returns the URL to a reddit submission, given the submission id and a
     Reddit API object. """