Delay task logs

configs/config.json.example

@@ -200,7 +200,8 @@
           "enabled": true,
           "lure_attraction": true,
           "lure_max_distance": 2000,
-          "walker": "StepWalker"
+          "walker": "StepWalker",
+          "log_interval": 5
         }
       },
       {

configs/config.json.map.example

@@ -432,7 +432,8 @@
         "config": {
             "enabled": true,
             "lure_attraction": true,
-            "lure_max_distance": 2000
+            "lure_max_distance": 2000,
+            "log_interval": 5
         }
       },
       {

configs/config.json.optimizer.example

@@ -247,7 +247,8 @@
         "config": {
             "enabled": true,
             "lure_attraction": true,
-            "lure_max_distance": 2000
+            "lure_max_distance": 2000,
+            "log_interval": 5
         }
       },
       {

configs/config.json.pokemon.example

@@ -185,7 +185,8 @@
         "config":{
           "enabled": true,
           "lure_attraction": true,
-          "lure_max_distance": 2000
+          "lure_max_distance": 2000,
+          "log_interval": 5
         }
       },
       {

docs/configuration_files.md

@@ -136,7 +136,30 @@ The behaviors of the bot are configured via the `tasks` key in the `config.json`
 * CollectLevelUpReward
   * `collect_reward`: Default `True` | Collect level up rewards.
   * `level_limit`: Default `-1` | Bot will stop automatically after trainer reaches level limit. Set to `-1` to disable.
-
+* All tasks
+  * `log_interval`: Default `0` | Minimum seconds interval before next log of the current task will be printed
+
+
+### Specify a custom log_interval for specific task
+
+  ```
+    {
+      "type": "MoveToFort",
+      "config": {
+        "enabled": true,
+        "lure_attraction": true,
+        "lure_max_distance": 2000,
+        "walker": "StepWalker",
+        "log_interval": 5
+      }
+    }
+   ```
+
+   Result:
+
+    2016-08-26 11:43:18,199 [MoveToFort] [INFO] [moving_to_fort] Moving towards pokestop ... - 0.07km
+    2016-08-26 11:43:23,641 [MoveToFort] [INFO] [moving_to_fort] Moving towards pokestop ... - 0.06km
+    2016-08-26 11:43:28,198 [MoveToFort] [INFO] [moving_to_fort] Moving towards pokestop ... - 0.05km
 
 ### Example configuration:
 [[back to top](#table-of-contents)]

pokemongo_bot/base_task.py

@@ -1,5 +1,7 @@
 import logging
 
+import time
+
 
 class BaseTask(object):
   TASK_API_VERSION = 1
@@ -17,6 +19,7 @@ def __init__(self, bot, config):
     self._validate_work_exists()
     self.logger = logging.getLogger(type(self).__name__)
     self.enabled = config.get('enabled', True)
+    self.last_log_time = time.time()
     self.initialize()
 
   def _validate_work_exists(self):
@@ -27,13 +30,17 @@ def _validate_work_exists(self):
   def emit_event(self, event, sender=None, level='info', formatted='', data={}):
     if not sender:
       sender=self
-    self.bot.event_manager.emit(
-      event,
-      sender=sender,
-      level=level,
-      formatted=formatted,
-      data=data
-    )
+
+    # Print log only if X seconds are passed from last log
+    if (time.time() - self.last_log_time) > self.config.get('log_interval', 0):
+      self.last_log_time = time.time()
+      self.bot.event_manager.emit(
+        event,
+        sender=sender,
+        level=level,
+        formatted=formatted,
+        data=data
+      )
 
   def initialize(self):
     pass

pokemongo_bot/test/log_interval_test.py

@@ -0,0 +1,62 @@
+import unittest
+from datetime import timedelta, datetime
+from time import sleep
+
+from mock import patch, MagicMock
+
+from pokemongo_bot.cell_workers import MoveToFort
+from tests import FakeBot
+
+
+class LogDelayTestCase(unittest.TestCase):
+
+    config = {
+          "enabled": 'true',
+          "lure_attraction": 'true',
+          "lure_max_distance": 2000,
+          "walker": "StepWalker",
+          "log_interval": 3
+      }
+
+    def setUp(self):
+        self.bot = FakeBot()
+        self.bot.event_manager = MagicMock()
+        self.worker = MoveToFort(self.bot, self.config)
+
+    def test_read_correct_delay_config(self):
+        self.worker.config['log_interval'] = 3
+        self.assertEqual(self.config.get('log_interval'), 3)
+
+    def test_log_with_no_delay(self):
+        self.worker.config['log_interval'] = 3
+        # All those call should not happen cause without any delay between each other
+        self.worker.emit_event('moving_to_fort', formatted="just an example")
+        self.worker.emit_event('moving_to_fort', formatted="just an example")
+
+        # Let's try to subtract 2 of 3 sec and see if event_manager.emit() get no call at all
+        self.worker.last_log_time -= 2
+        self.worker.emit_event('moving_to_fort', formatted="just an example")
+        self.worker.emit_event('moving_to_fort', formatted="just an example")
+
+        self.assertEqual(self.bot.event_manager.emit.call_count, 0)
+        assert not self.bot.event_manager.emit.called
+
+    def test_correct_delay_wait(self):
+
+        self.worker.config['log_interval'] = 2
+
+        # to avoid use sleep() function here, we subtract expected log_interval to last_log_time
+        self.worker.last_log_time -= self.worker.config['log_interval']
+
+        for number_of_checks in range(10):
+            self.worker.emit_event('moving_to_fort', formatted="just an example")
+            self.worker.last_log_time -= 2
+
+        self.assertEqual(self.bot.event_manager.emit.call_count, 10)
+
+        # i think should be better assert in this way, but can't get it working
+        # assert self.bot.event_manager.emit.assert_any_call('moving_to_fort',
+        #                                                    sender=None,
+        #                                                    level='info',
+        #                                                    formatted="just an example",data={})
+