]> git.openstreetmap.org Git - nominatim.git/blob - utils/cron_ipanalyse.py
don't even try heavily penalized searches
[nominatim.git] / 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()