utils/cron_ipanalyse.py

   1 #!/usr/bin/python3
   2 #
   3 # Search apache logs for high-bandwith users and create a list of suspicious IPs.
   4 # There are three states: bulk, block, ban. The first are bulk requesters
   5 # that need throtteling, the second bulk requesters that have overdone it
   6 # and the last manually banned IPs.
   7 #
   8
   9 import re
  10 import os
  11 import sys
  12 import subprocess
  13 from datetime import datetime, timedelta
  14 from collections import defaultdict
  15
  16 #
  17 # DEFAULT SETTINGS
  18 #
  19 # Copy into settings/ip_blcoks.conf and adapt as required.
  20 #
  21 BASEDIR = os.path.normpath(os.path.join(os.path.realpath(__file__), '../..'))
  22 BLOCKEDFILE= BASEDIR + '/settings/ip_blocks.map'
  23 LOGFILE= BASEDIR + '/log/restricted_ip.log'
  24
  25 # space-separated list of IPs that are never banned
  26 WHITELIST = ''
  27 # space-separated list of IPs manually blocked
  28 BLACKLIST = ''
  29 # user-agents that should be blocked from bulk mode
  30 # (matched with startswith)
  31 UA_BLOCKLIST = ()
  32
  33 # time before a automatically blocked IP is allowed back
  34 BLOCKCOOLOFF_DELTA=timedelta(hours=1)
  35 # quiet time before an IP is released from the bulk pool
  36 BULKCOOLOFF_DELTA=timedelta(minutes=15)
  37 # time to check if new accesses appear despite being blocked
  38 BLOCKCHECK_DELTA=timedelta(minutes=1)
  39
  40 BULKLONG_LIMIT=8000
  41 BULKSHORT_LIMIT=2000
  42 BLOCK_UPPER=19000
  43 BLOCK_LOWER=4000
  44 BLOCK_LOADFAC=380
  45 BULK_LOADFAC=160
  46 BULK_LOWER=1500
  47 MAX_BULK_IPS=85
  48
  49 #
  50 # END OF DEFAULT SETTINGS
  51 #
  52
  53 try:
  54     with open(BASEDIR + "/settings/ip_blocks.conf") as f:
  55         code = compile(f.read(), BASEDIR + "/settings/ip_blocks.conf", 'exec')
  56         exec(code)
  57 except IOError:
  58     pass
  59
  60 BLOCK_LIMIT = BLOCK_LOWER
  61
  62 time_regex = r'(?P<t_day>\d\d)/(?P<t_month>[A-Za-z]+)/(?P<t_year>\d\d\d\d):(?P<t_hour>\d\d):(?P<t_min>\d\d):(?P<t_sec>\d\d) [+-]\d\d\d\d'
  63
  64 format_pat= re.compile(r'(?P<ip>[a-f\d\.:]+) - - \['+ time_regex + r'] "(?P<query>.*?)" (?P<return>\d+) (?P<bytes>\d+) "(?P<referer>.*?)" "(?P<ua>.*?)"')
  65 time_pat= re.compile(r'[a-f\d:\.]+ - - \[' + time_regex + '\] ')
  66
  67 logtime_pat = "%d/%b/%Y:%H:%M:%S %z"
  68
  69 MONTHS = { 'Jan' : 1, 'Feb' : 2, 'Mar' : 3, 'Apr' : 4, 'May' : 5, 'Jun' : 6,
  70            'Jul' : 7, 'Aug' : 8, 'Sep' : 9, 'Oct' : 10, 'Nov' : 11, 'Dec' : 12 }
  71
  72 class LogEntry:
  73     def __init__(self, logline):
  74         e = format_pat.match(logline)
  75         if e is None:
  76             raise ValueError("Invalid log line:", logline)
  77         e = e.groupdict()
  78         self.ip = e['ip']
  79         self.date = datetime(int(e['t_year']), MONTHS[e['t_month']], int(e['t_day']),
  80                              int(e['t_hour']), int(e['t_min']), int(e['t_sec']))
  81         qp = e['query'].split(' ', 2)
  82         if len(qp) < 2:
  83             self.request = None
  84             self.query = None
  85         else:
  86             self.query = qp[1]
  87             if qp[0] == 'OPTIONS':
  88                 self.request = None
  89             else:
  90                 if '/?' in qp[1]:
  91                     self.request = 'S'
  92                 elif '/search' in qp[1]:
  93                     self.request = 'S'
  94                 elif '/reverse' in qp[1]:
  95                     self.request = 'R'
  96                 elif '/details' in qp[1]:
  97                     self.request = 'D'
  98                 elif '/lookup' in qp[1]:
  99                     self.request = 'L'
 100                 else:
 101                     self.request = None
 102         self.query = e['query']
 103         self.retcode = int(e['return'])
 104         self.referer = e['referer'] if e['referer'] != '-' else None
 105         self.ua = e['ua'] if e['ua'] != '-' else None
 106
 107     def get_log_time(logline):
 108         e = format_pat.match(logline)
 109         if e is None:
 110             return None
 111         e = e.groupdict()
 112         #return datetime.strptime(e['time'], logtime_pat).replace(tzinfo=None)
 113         return datetime(int(e['t_year']), MONTHS[e['t_month']], int(e['t_day']),
 114                              int(e['t_hour']), int(e['t_min']), int(e['t_sec']))
 115
 116
 117 class LogFile:
 118     """ An apache log file, unpacked. """
 119
 120     def __init__(self, filename):
 121         self.fd = open(filename)
 122         self.len = os.path.getsize(filename)
 123
 124     def __del__(self):
 125         self.fd.close()
 126
 127     def seek_next(self, abstime):
 128         self.fd.seek(abstime)
 129         self.fd.readline()
 130         l = self.fd.readline()
 131         return LogEntry.get_log_time(l) if l is not None else None
 132
 133     def seek_to_date(self, target):
 134         # start position for binary search
 135         fromseek = 0
 136         fromdate = self.seek_next(0)
 137         if fromdate > target:
 138             return True
 139         # end position for binary search
 140         toseek = -100
 141         while -toseek < self.len:
 142             todate = self.seek_next(self.len + toseek)
 143             if todate is not None:
 144                 break
 145             toseek -= 100
 146         if todate is None or todate < target:
 147             return False
 148         toseek = self.len + toseek
 149
 150
 151         while True:
 152             bps = (toseek - fromseek) / (todate - fromdate).total_seconds()
 153             newseek = fromseek + int((target - fromdate).total_seconds() * bps)
 154             newdate = self.seek_next(newseek)
 155             if newdate is None:
 156                 return False;
 157             error = abs((target - newdate).total_seconds())
 158             if error < 1:
 159                 return True
 160             if newdate > target:
 161                 toseek = newseek
 162                 todate = newdate
 163                 oldfromseek = fromseek
 164                 fromseek = toseek - error * bps
 165                 while True:
 166                     if fromseek <= oldfromseek:
 167                         fromseek = oldfromseek
 168                         fromdate = self.seek_next(fromseek)
 169                         break
 170                     fromdate = self.seek_next(fromseek)
 171                     if fromdate < target:
 172                         break;
 173                     bps *=2
 174                     fromseek -= error * bps
 175             else:
 176                 fromseek = newseek
 177                 fromdate = newdate
 178                 oldtoseek = toseek
 179                 toseek = fromseek + error * bps
 180                 while True:
 181                     if toseek > oldtoseek:
 182                         toseek = oldtoseek
 183                         todate = self.seek_next(toseek)
 184                         break
 185                     todate = self.seek_next(toseek)
 186                     if todate > target:
 187                         break
 188                     bps *=2
 189                     toseek += error * bps
 190             if toseek - fromseek < 500:
 191                 return True
 192
 193
 194     def loglines(self):
 195         for l in self.fd:
 196             try:
 197                 yield LogEntry(l)
 198             except ValueError:
 199                 pass # ignore invalid lines
 200
 201 class BlockList:
 202
 203     def __init__(self):
 204         self.whitelist = set(WHITELIST.split()) if WHITELIST else set()
 205         self.blacklist = set(BLACKLIST.split()) if BLACKLIST else set()
 206         self.prevblocks = set()
 207         self.prevbulks = set()
 208
 209         try:
 210             fd = open(BLOCKEDFILE)
 211             for line in fd:
 212                 ip, typ = line.strip().split(' ')
 213                 if ip not in self.blacklist:
 214                     if typ == 'block':
 215                         self.prevblocks.add(ip)
 216                     elif typ == 'bulk':
 217                         self.prevbulks.add(ip)
 218             fd.close()
 219         except IOError:
 220             pass #ignore non-existing file
 221
 222
 223 class IPstats:
 224
 225     def __init__(self):
 226         self.redirected = 0
 227         self.short_total = 0
 228         self.short_api = 0
 229         self.long_total = 0
 230         self.long_api = 0
 231         self.block_total = 0
 232         self.bad_ua = False
 233
 234     def add_long(self, logentry):
 235         self.long_total += 1
 236         if logentry.retcode == 301:
 237             return
 238         if logentry.request is not None:
 239             self.long_api += 1
 240         if not self.bad_ua:
 241             if logentry.ua is None:
 242                 self.bad_ua = True
 243
 244     def add_short(self, logentry):
 245         self.short_total += 1
 246         if logentry.retcode == 301:
 247             self.redirected += 1
 248             return
 249         if logentry.request is not None:
 250             self.short_api += 1
 251         self.add_long(logentry)
 252
 253     def add_block(self, logentry):
 254         self.block_total += 1
 255
 256     def ignores_warnings(self, wasblocked):
 257         return self.block_total > 5 or (wasblocked and self.redirected > 5)
 258
 259     def new_state(self, was_blocked, was_bulked):
 260         if was_blocked:
 261             # deblock only if the IP has been really quiet
 262             # (properly catches the ones that simply ignore the HTTP error)
 263             return None if self.long_total < 20 else 'block'
 264         if self.long_api > BLOCK_UPPER \
 265             or self.short_api > BLOCK_UPPER / 3 \
 266             or (self.redirected > 100 and self.short_total == self.redirected):
 267                 # client totally overdoing it
 268                 return 'block'
 269         if was_bulked:
 270             if self.short_total < 20:
 271                 # client has stopped, debulk
 272                 return None
 273             if self.long_api > BLOCK_LIMIT or self.short_api > BLOCK_LIMIT / 3:
 274                 # client is still hammering us, block
 275                 return 'emblock'
 276             return 'bulk'
 277
 278         if self.long_api > BULKLONG_LIMIT or self.short_api > BULKSHORT_LIMIT:
 279             #if self.bad_ua:
 280             #    return 'uablock' # bad useragent
 281             return 'bulk'
 282
 283         return None
 284
 285
 286
 287 if __name__ == '__main__':
 288     if len(sys.argv) < 2:
 289         print("Usage: %s logfile startdate" % sys.argv[0])
 290         sys.exit(-1)
 291
 292     if len(sys.argv) == 2:
 293         dt = datetime.now() - BLOCKCOOLOFF_DELTA
 294     else:
 295         dt = datetime.strptime(sys.argv[2], "%Y-%m-%d %H:%M:%S")
 296
 297     if os.path.getsize(sys.argv[1]) < 2*1030*1024:
 298         sys.exit(0) # not enough data
 299
 300     lf = LogFile(sys.argv[1])
 301     if not lf.seek_to_date(dt):
 302         sys.exit(0)
 303
 304     bl = BlockList()
 305
 306     shortstart = dt + BLOCKCOOLOFF_DELTA - BULKCOOLOFF_DELTA
 307     blockstart = dt + BLOCKCOOLOFF_DELTA - BLOCKCHECK_DELTA
 308     notlogged = bl.whitelist | bl.blacklist
 309
 310     stats = defaultdict(IPstats)
 311
 312     for l in lf.loglines():
 313         if l.ip not in notlogged:
 314             stats[l.ip].add_long(l)
 315         if l.date > shortstart:
 316             break
 317
 318     total200 = 0
 319     for l in lf.loglines():
 320         if l.ip not in notlogged:
 321             stats[l.ip].add_short(l)
 322         if l.request is not None and l.retcode == 200:
 323             total200 += 1
 324         if l.date > blockstart and l.retcode in (403, 429):
 325             stats[l.ip].add_block(l)
 326
 327     # adapt limits according to CPU and DB load
 328     fd = open("/proc/loadavg")
 329     cpuload = int(float(fd.readline().split()[2]))
 330     fd.close()
 331     # check the number of excess connections to apache
 332     dbcons = int(subprocess.check_output("netstat -s | grep 'connections established' | sed 's:^\s*::;s: .*::'", shell=True))
 333     fpms = int(subprocess.check_output('ps -Af | grep php-fpm | wc -l', shell=True))
 334     dbload = max(0, dbcons - fpms)
 335
 336     numbulks = len(bl.prevbulks)
 337     BLOCK_LIMIT = max(BLOCK_LIMIT, BLOCK_UPPER - BLOCK_LOADFAC * dbload)
 338     BULKLONG_LIMIT = max(BULK_LOWER, BULKLONG_LIMIT - BULK_LOADFAC * cpuload)
 339     if numbulks > MAX_BULK_IPS:
 340         BLOCK_LIMIT = max(3600, BLOCK_LOWER - (numbulks - MAX_BULK_IPS)*10)
 341     # if the bulk pool is still empty, clients will be faster, avoid having
 342     # them blocked in this case
 343     if numbulks < 10:
 344         BLOCK_UPPER *= 2
 345         BLOCK_LIMIT = BLOCK_UPPER
 346
 347
 348     # collecting statistics
 349     unblocked = []
 350     debulked = []
 351     bulked = []
 352     blocked = []
 353     uablocked = []
 354     emblocked = []
 355     # write out new state file
 356     fd = open(BLOCKEDFILE, 'w')
 357     for k,v in stats.items():
 358         wasblocked = k in bl.prevblocks
 359         wasbulked = k in bl.prevbulks
 360         state = v.new_state(wasblocked, wasbulked)
 361         if state is not None:
 362             if state == 'uablock':
 363                 uablocked.append(k)
 364                 state = 'block'
 365             elif state == 'emblock':
 366                 emblocked.append(k)
 367                 state = 'block'
 368             elif state == 'block':
 369                 if not wasblocked:
 370                     blocked.append(k)
 371             elif state == 'bulk':
 372                 if not wasbulked:
 373                     bulked.append(k)
 374             fd.write("%s %s\n" % (k, state))
 375         else:
 376             if wasblocked:
 377                 unblocked.append(k)
 378             elif wasbulked:
 379                 debulked.append(k)
 380     for i in bl.blacklist:
 381         fd.write("%s ban\n" % i)
 382     fd.close()
 383
 384     # TODO write logs (need to collect some statistics)
 385     logstr = datetime.now().strftime('%d/%b/%Y:%H:%M:%S') + ' %s %s\n'
 386     fd = open(LOGFILE, 'a')
 387     if unblocked:
 388         fd.write(logstr % ('unblocked:', ', '.join(unblocked)))
 389     if debulked:
 390         fd.write(logstr % (' debulked:', ', '.join(debulked)))
 391     if bulked:
 392         fd.write(logstr % ('new bulks:', ', '.join(bulked)))
 393     if emblocked:
 394         fd.write(logstr % ('dir.block:', ', '.join(emblocked)))
 395     if uablocked:
 396         fd.write(logstr % (' ua block:', ', '.join(uablocked)))
 397     if blocked:
 398         fd.write(logstr % ('new block:', ', '.join(blocked)))
 399     for k,v in stats.items():
 400         if v.ignores_warnings(k in bl.prevblocks) and k not in notlogged and ':' not in k:
 401             fd.write(logstr % ('Warning ignored:', k))
 402     fd.close()