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 from datetime import datetime, timedelta
  13 from collections import defaultdict
  14
  15 #
  16 # DEFAULT SETTINGS
  17 #
  18 # Copy into settings/ip_blcoks.conf and adapt as required.
  19 #
  20 BASEDIR = os.path.normpath(os.path.join(os.path.realpath(__file__), '../..'))
  21 BLOCKEDFILE= BASEDIR + '/settings/ip_blocks.map'
  22 LOGFILE= BASEDIR + '/log/restricted_ip.log'
  23
  24 # space-separated list of IPs that are never banned
  25 WHITELIST = ''
  26 # space-separated list of IPs manually blocked
  27 BLACKLIST = ''
  28 # user-agents that should be blocked from bulk mode
  29 # (matched with startswith)
  30 UA_BLOCKLIST = ()
  31
  32 # time before a automatically blocked IP is allowed back
  33 BLOCKCOOLOFF_PERIOD=timedelta(hours=1)
  34 # quiet time before an IP is released from the bulk pool
  35 BULKCOOLOFF_PERIOD=timedelta(minutes=15)
  36
  37 BULKLONG_LIMIT=8000
  38 BULKSHORT_LIMIT=2000
  39 BLOCK_UPPER=19000
  40 BLOCK_LOWER=4000
  41 BLOCK_LOADFAC=380
  42 BULK_LOADFAC=160
  43 BULK_LOWER=1500
  44 MAX_BULK_IPS=85
  45
  46 #
  47 # END OF DEFAULT SETTINGS
  48 #
  49
  50 try:
  51     with open(BASEDIR + "/settings/ip_blocks.conf") as f:
  52         code = compile(f.read(), BASEDIR + "/settings/ip_blocks.conf", 'exec')
  53         exec(code, global_vars, local_vars)
  54 except IOError:
  55     pass
  56
  57 BLOCK_LIMIT = BLOCK_LOWER
  58
  59
  60 format_pat= re.compile('(?P<ip>[(\d\.)]+) - - \[(?P<time>.*?)\] "(?P<query>.*?)" (?P<return>\d+) (?P<bytes>\d+) "(?P<referer>.*?)" "(?P<ua>.*?)"')
  61 time_pat= re.compile('[(\d\.)]+ - - \[(?P<time>[^\]]*?)\] ')
  62
  63 logtime_pat = "%d/%b/%Y:%H:%M:%S %z"
  64
  65 class LogEntry:
  66     def __init__(self, logline):
  67         e = format_pat.match(logline)
  68         if e is None:
  69             raise ValueError("Invalid log line:", logline)
  70         e = e.groupdict()
  71         self.ip = e['ip']
  72         self.date = datetime.strptime(e['time'], logtime_pat).replace(tzinfo=None)
  73         qp = e['query'].split(' ', 2)
  74         if len(qp) < 2:
  75             self.request = None
  76             self.query = None
  77         else:
  78             self.query = qp[1]
  79             if qp[0] == 'OPTIONS':
  80                 self.request = None
  81             else:
  82                 if qp[1].startswith('/search'):
  83                     self.request = 'S'
  84                 elif qp[1].startswith('/reverse'):
  85                     self.request = 'R'
  86                 elif qp[1].startswith('/details'):
  87                     self.request = 'D'
  88                 else:
  89                     self.request = None
  90         self.query = e['query']
  91         self.retcode = int(e['return'])
  92         self.referer = e['referer'] if e['referer'] != '-' else None
  93         self.ua = e['ua'] if e['ua'] != '-' else None
  94
  95     def get_log_time(logline):
  96         e = format_pat.match(logline)
  97         if e is None:
  98             return None
  99         e = e.groupdict()
 100         return datetime.strptime(e['time'], logtime_pat).replace(tzinfo=None)
 101
 102
 103 class LogFile:
 104     """ An apache log file, unpacked. """
 105
 106     def __init__(self, filename):
 107         self.fd = open(filename)
 108         self.len = os.path.getsize(filename)
 109
 110     def __del__(self):
 111         self.fd.close()
 112
 113     def seek_next(self, abstime):
 114         self.fd.seek(abstime)
 115         self.fd.readline()
 116         l = self.fd.readline()
 117         return LogEntry.get_log_time(l) if l is not None else None
 118
 119     def seek_to_date(self, target):
 120         date1 = self.seek_next(0)
 121         if date1 > target:
 122             return False
 123         curseek = 2*1024*1024
 124         curdate = self.seek_next(curseek)
 125         if curdate is None:
 126             raise RuntimeError("Cannot seek to %d" % curseek)
 127         while abs((target - curdate).total_seconds()) > 1.0:
 128             bps = curseek / ((curdate - date1).total_seconds())
 129             curseek += (target - curdate).total_seconds() * bps
 130             if curseek < 0:
 131                 curseek = 0
 132             elif curseek > self.len:
 133                 curseek = self.len - bps
 134             curdate = self.seek_next(curseek)
 135             if curdate is None:
 136                 raise RuntimeError("Cannot see to %d" % curseek)
 137         return True
 138
 139     def loglines(self):
 140         for l in self.fd:
 141             yield LogEntry(l)
 142
 143 class BlockList:
 144
 145     def __init__(self):
 146         self.whitelist = set(WHITELIST.split()) if WHITELIST else set()
 147         self.blacklist = set(BLACKLIST.split()) if BLACKLIST else set()
 148         self.prevblocks = set()
 149         self.prevbulks = set()
 150
 151         try:
 152             fd = open(BLOCKEDFILE)
 153             for line in fd:
 154                 ip, typ = line.strip().split(' ')
 155                 if ip not in self.blacklist:
 156                     if typ == 'block':
 157                         prevblocks.add(ip)
 158                     elif typ == 'bulk':
 159                         prevbulks.add(ip)
 160             fd.close()
 161         except IOError:
 162             pass #ignore non-existing file
 163
 164
 165 class IPstats:
 166
 167     def __init__(self):
 168         self.short_total = 0
 169         self.short_api = 0
 170         self.long_total = 0
 171         self.long_api = 0
 172         self.bad_ua = False
 173
 174     def add_long(self, logentry):
 175         self.long_total += 1
 176         if logentry.request is not None:
 177             self.long_api += 1
 178         if not self.bad_ua:
 179             if logentry.ua is None:
 180                 self.bad_ua = True
 181
 182     def add_short(self, logentry):
 183         self.short_total += 1
 184         if logentry.request is not None:
 185             self.short_api += 1
 186         self.add_long(logentry)
 187
 188     def new_state(self, was_blocked, was_bulked):
 189         if was_blocked:
 190             # deblock only if the IP has been really quiet
 191             # (properly catches the ones that simply ignore the HTTP error)
 192             return None if self.long_total < 5 else 'block'
 193         if self.long_api > BLOCK_UPPER or self.short_api > BLOCK_UPPER / 3:
 194                 # client totally overdoing it
 195                 return 'block'
 196         if was_bulked:
 197             if self.short_total < 5:
 198                 # client has stopped, debulk
 199                 return None
 200             if self.long_api > BLOCK_LIMIT or self.short_api > BLOCK_LIMIT / 3:
 201                 # client is still hammering us, block
 202                 return 'emblock'
 203             return 'bulk'
 204
 205         if self.long_api > BULKLONG_LIMIT or self.short_api > BULKSHORT_LIMIT:
 206             if self.bad_ua:
 207                 return 'uablock' # bad useragent
 208             return 'bulk'
 209
 210         return None
 211
 212
 213
 214 if __name__ == '__main__':
 215     if len(sys.argv) < 2:
 216         print("Usage: %s logfile startdate" % sys.argv[0])
 217         sys.exit(-1)
 218
 219     if len(sys.argv) == 2:
 220         dt = datetime.now() - BLOCKCOOLOFF_PERIOD
 221     else:
 222         dt = datetime.strptime(sys.argv[2], "%Y-%m-%d %H:%M:%S")
 223
 224     if os.path.getsize(sys.argv[1]) < 2*1030*1024:
 225         sys.exit(0) # not enough data
 226
 227     lf = LogFile(sys.argv[1])
 228     if not lf.seek_to_date(dt):
 229         sys.exit(0)
 230
 231     bl = BlockList()
 232
 233     shortstart = dt + BLOCKCOOLOFF_PERIOD - BULKCOOLOFF_PERIOD
 234     notlogged = bl.whitelist | bl.blacklist
 235
 236     stats = defaultdict(IPstats)
 237
 238     for l in lf.loglines():
 239         if l.ip not in notlogged:
 240             stats[l.ip].add_long(l)
 241         if l.date > shortstart:
 242             break
 243
 244     total200 = 0
 245     for l in lf.loglines():
 246         if l.ip not in notlogged:
 247             stats[l.ip].add_short(l)
 248         if l.request is not None and l.retcode == 200:
 249             total200 += 1
 250
 251     # adapt limits according to CPU and DB load
 252     fd = open("/proc/loadavg")
 253     cpuload = int(float(fd.readline().split()[2]))
 254     fd.close()
 255     dbload = total200 / BULKCOOLOFF_PERIOD.total_seconds()
 256
 257     numbulks = len(bl.prevbulks)
 258     BLOCK_LIMIT = max(BLOCK_LIMIT, BLOCK_UPPER - BLOCK_LOADFAC * (dbload - 75))
 259     BULKLONG_LIMIT = max(BULK_LOWER, BULKLONG_LIMIT - BULK_LOADFAC * (cpuload - 14))
 260     if numbulks > MAX_BULK_IPS:
 261         BLOCK_LIMIT = max(3600, BLOCK_LOWER - (numbulks - MAX_BULK_IPS)*10)
 262     # if the bulk pool is still empty, clients will be faster, avoid having
 263     # them blocked in this case
 264     if numbulks < 10:
 265         BLOCK_LIMIT = 2*BLOCK_UPPER
 266
 267
 268     # collecting statistics
 269     unblocked = []
 270     debulked = []
 271     bulked = []
 272     blocked = []
 273     uablocked = []
 274     emblocked = []
 275     # write out new state file
 276     fd = open(BLOCKEDFILE, 'w')
 277     for k,v in stats.items():
 278         wasblocked = k in bl.prevblocks
 279         wasbulked = k in bl.prevbulks
 280         state = v.new_state(wasblocked, wasbulked)
 281         if state is not None:
 282             if state == 'uablock':
 283                 uablocked.append(k)
 284                 state = 'block'
 285             elif state == 'emblock':
 286                 emblocked.append(k)
 287                 state = 'block'
 288             elif state == 'block':
 289                 if not wasblocked:
 290                     blocked.append(k)
 291             elif state == 'bulk':
 292                 if not wasbulked:
 293                     bulked.append(k)
 294             fd.write("%s %s\n" % (k, state))
 295         else:
 296             if wasblocked:
 297                 unblocked.append(k)
 298             elif wasbulked:
 299                 debulked.append(k)
 300     for i in bl.blacklist:
 301         fd.write("%s ban\n" % k)
 302     fd.close()
 303
 304     # TODO write logs (need to collect some statistics)
 305     logstr = datetime.now().strftime('%Y-%m-%d %H:%M') + ' %s %s\n'
 306     fd = open(LOGFILE, 'a')
 307     if unblocked:
 308         fd.write(logstr % ('unblocked:', ', '.join(unblocked)))
 309     if debulked:
 310         fd.write(logstr % (' debulked:', ', '.join(debulked)))
 311     if bulked:
 312         fd.write(logstr % ('new bulks:', ', '.join(bulked)))
 313     if emblocked:
 314         fd.write(logstr % ('dir.block:', ', '.join(emblocked)))
 315     if uablocked:
 316         fd.write(logstr % (' ua block:', ', '.join(uablocked)))
 317     if blocked:
 318         fd.write(logstr % ('new block:', ', '.join(blocked)))
 319     fd.close()