Refactor/Change: use logging / bool --debug +

  Writing everything to single log file.
  --debug is now a bool flag to raise the
  log level from INFO to DEBUG.

.env.example

+DEBUG=1
 ACCOUNT_FILE=./.htaccounts
 COOKIE_DIR=./.htcookies
 LOG_FILE=./logs/results.log
-DEBUG_FILE=./logs/debug.log
 PORT=4040
 HOST=localhost
+TWITTER_AUTH_KEY=AAAAAAAAAAAAAAAAAAAAANRILgAAAAAAnNwIzUejRCOuH5E6I8xnZz4puTs%3D1Zv7ttfk8LF81IUq16cHjhLTvJu4FA33AGWWjCpTnA
+CORS_ALLOW=http://localhost:3000
+GUEST_SESSIONS=3
 MONGO_HOST=localhost
 MONGO_PORT=27017
 MONGO_DB=shadowban-testing
 MONGO_USERNAME=root
 MONGO_PASSWORD=5X-rl[(EMdJKll1|qMDU}5xY<t?F.UEo
-TWITTER_AUTH_KEY=AAAAAAAAAAAAAAAAAAAAANRILgAAAAAAnNwIzUejRCOuH5E6I8xnZz4puTs%3D1Zv7ttfk8LF81IUq16cHjhLTvJu4FA33AGWWjCpTnA
-CORS_HOST=http://localhost:3000
-GUEST_SESSIONS=3

backend.py

@@ -13,8 +13,9 @@ import time
 from aiohttp import web
 from bs4 import BeautifulSoup
 
-from twitter_session import TwitterSession
+from log import *
 from db import connect
+from twitter_session import TwitterSession
 
 log_file = None
 debug_file = None
@@ -22,28 +23,7 @@ db = None
 
 routes = web.RouteTableDef()
 
-def debug(message):
-    if message.endswith('\n') is False:
-        message = message + '\n'
-
-    if debug_file is not None:
-        debug_file.write(message)
-        debug_file.flush()
-    else:
-        print(message)
-
-def log(message):
-    # ensure newline
-    if message.endswith('\n') is False:
-         message = message + '\n'
-
-    if log_file is not None:
-        log_file.write(message)
-        log_file.flush()
-    else:
-        print(message)
-
-def print_session_info(sessions):
+def log_session_info(sessions):
     text = ""
     for session in sessions:
         text += "\n%6d %5d %9d %5d" % (int(session.locked), session.limit, session.remaining, session.reset - int(time.time()))
@@ -52,9 +32,9 @@ def print_session_info(sessions):
 @routes.get('/.stats')
 async def stats(request):
     text = "--- GUEST SESSIONS ---\n\nLocked Limit Remaining Reset"
-    text += print_session_info(TwitterSession.guest_sessions)
+    text += log_session_info(TwitterSession.guest_sessions)
     text += "\n\n\n--- ACCOUNTS ---\n\nLocked Limit Remaining Reset"
-    text += print_session_info(TwitterSession.account_sessions)
+    text += log_session_info(TwitterSession.account_sessions)
     return web.Response(text=text)
 
 @routes.get('/.unlocked/{screen_name}')
@@ -73,14 +53,14 @@ async def unlocked(request):
 async def api(request):
     screen_name = request.match_info['screen_name']
     if screen_name == "wikileaks" and request.query_string != "watch":
-        debug("[wikileaks] Returning last watch result")
+        log.debug("[wikileaks] Returning last watch result")
         db_result = db.get_result_by_screen_name("wikileaks")
         return web.json_response(db_result, headers={"Access-Control-Allow-Origin": args.cors_allow})
     session = TwitterSession.guest_sessions[TwitterSession.test_index % len(TwitterSession.guest_sessions)]
     TwitterSession.test_index += 1
     result = await session.test(screen_name)
     db.write_result(result)
-    log(json.dumps(result) + '\n')
+    log.debug(json.dumps(result) + '\n')
     if (args.cors_allow is not None):
         return web.json_response(result, headers={"Access-Control-Allow-Origin": args.cors_allow})
     else:
@@ -101,69 +81,68 @@ async def login_guests():
         session = TwitterSession()
         TwitterSession.guest_sessions.append(session)
     await asyncio.gather(*[s.login() for s in TwitterSession.guest_sessions])
-    log("Guest sessions created")
+    log.info("%d guest sessions created", len(TwitterSession.guest_sessions))
 
 def ensure_dir(path):
     if os.path.isdir(path) is False:
-        print('Creating directory %s' % path)
+        log.info('Creating directory %s' % path)
         os.mkdir(path)
 
 parser = argparse.ArgumentParser(description='Twitter Shadowban Tester')
 parser.add_argument('--account-file', type=str, default='.htaccounts', help='json file with reference account credentials')
-parser.add_argument('--cookie-dir', type=str, default=None, help='directory for session account storage')
-parser.add_argument('--log', type=str, default=None, help='log file where test results are written to')
+parser.add_argument('--cookie-dir', type=str, default=None, help='directory for session cookies')
+parser.add_argument('--log', type=str, default='./logs/backend.log', help='file to write logs to (default: ./logs/backend.log)')
 parser.add_argument('--daemon', action='store_true', help='run in background')
-parser.add_argument('--debug', type=str, default=None, help='debug log file')
-parser.add_argument('--port', type=int, default=8080, help='port which to listen on')
-parser.add_argument('--host', type=str, default='127.0.0.1', help='hostname/ip which to listen on')
-parser.add_argument('--mongo-host', type=str, default='localhost', help='hostname or IP of mongoDB service to connect to')
-parser.add_argument('--mongo-port', type=int, default=27017, help='port of mongoDB service to connect to')
-parser.add_argument('--mongo-db', type=str, default='tester', help='name of mongo database to use')
+parser.add_argument('--debug', action='store_true', help='show debug log messages')
+parser.add_argument('--port', type=int, default=8080, help='port which to listen on (default: 8080)')
+parser.add_argument('--host', type=str, default='127.0.0.1', help='hostname/ip which to listen on (default:127.0.0.1)')
+parser.add_argument('--mongo-host', type=str, default='localhost', help='hostname or IP of mongoDB service to connect to (default: localhost)')
+parser.add_argument('--mongo-port', type=int, default=27017, help='port of mongoDB service to connect to (default: 27017)')
+parser.add_argument('--mongo-db', type=str, default='tester', help='name of mongo database to use (default: tester)')
 parser.add_argument('--mongo-username', type=str, default=None, help='user with read/write permissions to --mongo-db')
 parser.add_argument('--mongo-password', type=str, default=None, help='password for --mongo-username')
 parser.add_argument('--twitter-auth-key', type=str, default=None, help='auth key for twitter guest session', required=True)
 parser.add_argument('--cors-allow', type=str, default=None, help='value for Access-Control-Allow-Origin header')
-parser.add_argument('--guest-sessions', type=int, default=10, help='number of Twitter guest sessions to use')
+parser.add_argument('--guest-sessions', type=int, default=10, help='number of Twitter guest sessions to use (default: 10)')
 args = parser.parse_args()
 
 TwitterSession.twitter_auth_key = args.twitter_auth_key
 guest_session_pool_size = args.guest_sessions
 
 if (args.cors_allow is None):
-    debug('[CORS] Running without CORS headers')
+    log.warning('[CORS] Running without CORS headers')
 else:
-    debug('[CORS] Allowing requests from: ' + args.cors_allow)
+    log.info('[CORS] Allowing requests from: ' + args.cors_allow)
 
 ensure_dir(args.cookie_dir)
 
+log_dir = os.path.dirname(args.log)
+ensure_dir(log_dir)
+add_file_handler(args.log)
+
 try:
     with open(args.account_file, "r") as f:
         accounts = json.loads(f.read())
 except:
     accounts = []
 
-if args.log is not None:
-    print("Logging test results to %s" % args.log)
-    log_dir = os.path.dirname(args.log)
-    ensure_dir(log_dir)
-    log_file = open(args.log, "a")
-
-if args.debug is not None:
-    print("Logging debug output to %s" % args.debug)
-    debug_dir = os.path.dirname(args.debug)
-    ensure_dir(debug_dir)
-    debug_file = open(args.debug, "a")
+if args.debug is True:
+    set_log_level('debug')
+else:
+    set_log_level('info')
 
 async def close_sessions(app):
-    print("\nClosing %s guest sessions" % len(TwitterSession.guest_sessions))
+    log.info("Closing %s guest sessions" % len(TwitterSession.guest_sessions))
     for session in TwitterSession.guest_sessions:
         await session.close()
 
 async def close_database(app):
     global db
-    print("Closing database connection")
+    log.info("Closing database connection")
     db.close()
 
+    shutdown_logging()
+
 def run():
     global db
     db = connect(

bin/docker-entry.sh

@@ -8,22 +8,6 @@ if [ "$1" != "" ] && [ -f $1 ]; then
   shift
 fi
 
-echo "Starting server..."
-echo "--account-file $ACCOUNT_FILE"
-echo "--cookie-dir $COOKIE_DIR"
-echo "--log $LOG_FILE"
-echo "--debug $DEBUG_FILE"
-echo "--port "$PORT""
-echo "--host "$HOST""
-echo "--mongo-host $MONGO_HOST"
-echo "--mongo-port $MONGO_PORT"
-echo "--mongo-db $MONGO_DB"
-echo "--mongo-username $MONGO_USERNAME"
-echo "--mongo-password --REDACTED--"
-echo "--twitter-auth-key --REDACTED--"
-echo "--cors-allow $CORS_HOST"
-echo "--guest-sessions $GUEST_SESSIONS"
-
 CMD="python3 -u ./backend.py"
 
 if [ "$1" == "mprof" ]; then
@@ -32,11 +16,10 @@ if [ "$1" == "mprof" ]; then
   echo -e "\nRecording memory profile\n"
 fi
 
-$CMD \
+SERVICE_ARGS="\
   --account-file $ACCOUNT_FILE \
   --cookie-dir $COOKIE_DIR \
   --log $LOG_FILE \
-  --debug $DEBUG_FILE \
   --port "$PORT" \
   --host "$HOST" \
   --mongo-host $MONGO_HOST \
@@ -45,5 +28,19 @@ $CMD \
   --mongo-username $MONGO_USERNAME \
   --mongo-password $MONGO_PASSWORD \
   --twitter-auth-key $TWITTER_AUTH_KEY \
-  --cors-allow $CORS_HOST \
-  --guest-sessions $GUEST_SESSIONS
+  --cors-allow $CORS_ALLOW \
+  --guest-sessions $GUEST_SESSIONS \
+"
+
+if [ -n "$DEBUG" ]; then
+  SERVICE_ARGS="$SERVICE_ARGS --debug"
+fi
+
+CMD="$CMD $SERVICE_ARGS $@"
+echo -n "Starting server: "
+if [ -n "$DEBUG" ]; then
+  echo $CMD
+else
+  echo ""
+fi
+$CMD

db.py

@@ -4,14 +4,16 @@ import sys
 from time import sleep
 from pymongo import MongoClient, errors as MongoErrors, DESCENDING
 
+from log import log
+
 class Database:
     def __init__(self, host=None, port=27017, db='tester', username=None, password=None):
         # collection name definitions
         RESULTS_COLLECTION = 'results'
         RATELIMIT_COLLECTION = 'rate-limits'
 
-        print('[mongoDB] Connecting to ' + host + ':' + str(port))
-        print('[mongoDB] Using Database `' + db + '`')
+        log.info('Connecting to ' + host + ':' + str(port))
+        log.info('Using Database `' + db + '`')
         # client and DB
         self.client = MongoClient(host, port, serverSelectionTimeoutMS=3, username=username, password=password)
         self.db = self.client[db]
@@ -40,15 +42,13 @@ class Database:
 
 def connect(host=None, port=27017, db='tester', username=None, password=None):
     if host is None:
-        raise ValueError('[mongoDB] Database constructor needs a `host`name or ip!')
+        raise ValueError('Database constructor needs a `host`name or ip!')
 
     attempt = 0
     max_attempts = 7
     mongo_client = None
 
     while (mongo_client is None):
-        print('[mongoDB|connect] Connecting, ', attempt, '/', max_attempts)
-
         try:
             mongo_client = Database(host=host, port=port, db=db, username=username, password=password)
         except Exception as e:
@@ -57,5 +57,6 @@ def connect(host=None, port=27017, db='tester', username=None, password=None):
 
             sleep(attempt)
             attempt += 1
+            log.warn('Retrying connection, %s/%s', attempt, max_attempts)
 
     return mongo_client

log.py

+import logging
+from logging.handlers import TimedRotatingFileHandler
+
+log_format = '%(asctime)s | %(module)s:%(lineno)d | %(levelname)s: %(message)s'
+logging.basicConfig(format=log_format)
+
+log = logging.getLogger(__name__)
+
+def add_file_handler(filename):
+    handler = TimedRotatingFileHandler(filename=filename, when='midnight')
+    handler.setFormatter(logging.Formatter(fmt=log_format))
+    log.addHandler(handler)
+    log.info('Writing log to %s', filename)
+
+def set_log_level(level):
+    level_upper = level.upper()
+    log.setLevel(getattr(logging, level_upper))
+    log.info('Log level set to %s', level_upper)
+
+def shutdown_logging():
+    logging.shutdown()

twitter_session.py

@@ -2,6 +2,7 @@ import aiohttp
 import time
 import urllib
 
+from log import log
 from statistics import count_sensitives
 from typeahead import test as test_typeahead
 
@@ -50,9 +51,9 @@ class TwitterSession:
             response = await r.json()
         guest_token = response.get("guest_token", None)
         if guest_token is None:
-            debug("Failed to fetch guest token")
-            debug(str(response))
-            debug(str(self._headers))
+            log.debug("Failed to fetch guest token")
+            log.debug(str(response))
+            log.debug(str(self._headers))
         return guest_token
 
     def reset_headers(self):
@@ -68,9 +69,9 @@ class TwitterSession:
     async def refresh_old_token(self):
         if self.username is not None or self.next_refresh is None or time.time() < self.next_refresh:
             return
-        debug("Refreshing token: " + str(self._guest_token))
+        log.debug("Refreshing token: " + str(self._guest_token))
         await self.login_guest()
-        debug("New token: " + str(self._guest_token))
+        log.debug("New token: " + str(self._guest_token))
 
     async def try_close(self):
         if self._session is not None:
@@ -98,7 +99,7 @@ class TwitterSession:
             if cookie_dir is not None:
                 cookie_file = os.path.join(cookie_dir, username)
                 if os.path.isfile(cookie_file):
-                    log("Use cookie file for %s" % username)
+                    log.info("Use cookie file for %s" % username)
                     self._session.cookie_jar.load(cookie_file)
                     login_required = False
 
@@ -116,11 +117,11 @@ class TwitterSession:
                 async with self._session.post('https://twitter.com/sessions', data=form_data, headers=self._headers) as r:
                     response = await r.text()
                     if str(r.url) == "https://twitter.com/":
-                        log("Login of %s successful" % username)
+                        log.info("Login of %s successful" % username)
                     else:
                         store_cookies = False
-                        log("Error logging in %s (%s)" % (username, r.url))
-                        debug("ERROR PAGE\n" + response)
+                        log.info("Error logging in %s (%s)" % (username, r.url))
+                        log.debug("ERROR PAGE\n" + response)
             else:
                 async with self._session.get('https://twitter.com', headers=self._headers) as r:
                     await r.text()
@@ -143,7 +144,7 @@ class TwitterSession:
             async with self._session.get(url, headers=self._headers) as r:
                 result = await r.json()
         except Exception as e:
-            debug("EXCEPTION: " + str(type(e)))
+            log.debug("EXCEPTION: " + str(type(e)))
             if self.username is None:
                 await self.login_guest()
             raise e
@@ -220,8 +221,8 @@ class TwitterSession:
                         obj["ban"] = True
                     return obj
         except:
-            debug('Unexpected Exception:')
-            debug(traceback.format_exc())
+            log.debug('Unexpected Exception:')
+            log.debug(traceback.format_exc())
             return { "error": "EUNKNOWN" }
 
     async def test_barrier(self, user_id, screen_name):
@@ -262,21 +263,21 @@ class TwitterSession:
                 if replied_tweet["reply_count"] > 500:
                     continue
 
-                debug('[' + screen_name + '] Barrier Test: ')
-                debug('[' + screen_name + '] Found:' + tid)
-                debug('[' + screen_name + '] In reply to:' + replied_to_id)
+                log.debug('[' + screen_name + '] Barrier Test: ')
+                log.debug('[' + screen_name + '] Found:' + tid)
+                log.debug('[' + screen_name + '] In reply to:' + replied_to_id)
 
                 reference_session = next_session()
                 reference_session = self
                 if reference_session is None:
-                    debug('No reference session')
+                    log.debug('No reference session')
                     return
 
                 TwitterSession.account_index += 1
 
                 before_barrier = await reference_session.tweet_raw(replied_to_id, 1000)
                 if get_nested(before_barrier, ["globalObjects", "tweets"]) is None:
-                    debug('notweets\n')
+                    log.debug('notweets\n')
                     return
 
                 if tid in self.get_ordered_tweet_ids(before_barrier):
@@ -296,7 +297,7 @@ class TwitterSession:
                     after_barrier = await reference_session.tweet_raw(replied_to_id, 1000, cursor=cursor)
 
                     if get_nested(after_barrier, ["globalObjects", "tweets"]) is None:
-                        debug('retinloop\n')
+                        log.debug('retinloop\n')
                         return
                     ids_after_barrier = self.get_ordered_tweet_ids(after_barrier)
                     if tid in self.get_ordered_tweet_ids(after_barrier):
@@ -304,20 +305,20 @@ class TwitterSession:
                     last_result = after_barrier
 
                 # happens when replied_to_id tweet has been deleted
-                debug('[' + screen_name + '] outer loop return')
+                log.debug('[' + screen_name + '] outer loop return')
                 return { "error": "EUNKNOWN" }
         except:
-            debug('Unexpected Exception in test_barrier:\n')
-            debug(traceback.format_exc())
+            log.debug('Unexpected Exception in test_barrier:\n')
+            log.debug(traceback.format_exc())
             return { "error": "EUNKNOWN" }
 
     async def test(self, username):
         result = {"timestamp": time.time()}
         profile = {}
         profile_raw = await self.profile_raw(username)
-        debug('Testing ' + str(username))
+        log.info('Testing ' + str(username))
         if is_another_error(profile_raw, [50, 63]):
-            debug("Other error:" + str(username))
+            log.debug("Other error:" + str(username))
             raise UnexpectedApiError
 
         try:
@@ -381,19 +382,13 @@ class TwitterSession:
         else:
             result["tests"]["more_replies"] = { "error": "EISGHOSTED"}
 
-        debug('[' + profile['screen_name'] + '] Writing result to DB')
+        log.debug('[' + profile['screen_name'] + '] Writing result to DB')
         return result
 
 
     async def close(self):
         await self._session.close()
 
-def debug(message):
-    print(message)
-
-def log(message):
-    print(message)
-
 def next_session():
     def key(s):
         remaining_time = s.reset - time.time()