1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
|
# -*- coding: utf-8 -*-
"""
mirrorcheck command
Poll every active mirror URL we have in the database, grab the 'lastsync' file,
and record details about how long it took and how up to date the mirror is. If
we encounter errors, record those as well.
Usage: ./manage.py mirrorcheck
"""
from collections import deque
from datetime import datetime
from httplib import HTTPException
import logging
import os
from optparse import make_option
from pytz import utc
import re
import socket
import subprocess
import sys
import time
import tempfile
from threading import Thread
import types
from Queue import Queue, Empty
import urllib2
from django.core.management.base import NoArgsCommand
from django.db import transaction
from django.utils.timezone import now
from mirrors.models import MirrorUrl, MirrorLog, CheckLocation
logging.basicConfig(
level=logging.WARNING,
format='%(asctime)s -> %(levelname)s: %(message)s',
datefmt='%Y-%m-%d %H:%M:%S',
stream=sys.stderr)
logger = logging.getLogger()
class Command(NoArgsCommand):
option_list = NoArgsCommand.option_list + (
make_option('-t', '--timeout', dest='timeout', type='float', default=10.0,
help='Timeout value for connecting to URL'),
make_option('-l', '--location', dest='location', type='int',
help='ID of CheckLocation object to use for this run'),
)
help = "Runs a check on all known mirror URLs to determine their up-to-date status."
def handle_noargs(self, **options):
v = int(options.get('verbosity', 0))
if v == 0:
logger.level = logging.ERROR
elif v == 1:
logger.level = logging.WARNING
elif v == 2:
logger.level = logging.DEBUG
timeout = options.get('timeout')
urls = MirrorUrl.objects.select_related('protocol').filter(
mirror__active=True, mirror__public=True)
location = options.get('location', None)
if location:
location = CheckLocation.objects.get(id=location)
family = location.family
monkeypatch_getaddrinfo(family)
if family == socket.AF_INET6:
urls = urls.filter(has_ipv6=True)
elif family == socket.AF_INET:
urls = urls.filter(has_ipv4=True)
pool = MirrorCheckPool(urls, location, timeout)
pool.run()
return 0
def monkeypatch_getaddrinfo(force_family=socket.AF_INET):
'''Force the Python socket module to connect over the designated family;
e.g. socket.AF_INET or socket.AF_INET6.'''
orig = socket.getaddrinfo
def wrapper(host, port, family=0, socktype=0, proto=0, flags=0):
return orig(host, port, force_family, socktype, proto, flags)
socket.getaddrinfo = wrapper
def parse_lastsync(log, data):
'''lastsync file should be an epoch value created by us.'''
try:
parsed_time = datetime.utcfromtimestamp(int(data))
log.last_sync = parsed_time.replace(tzinfo=utc)
except ValueError:
# it is bad news to try logging the lastsync value;
# sometimes we get a crazy-encoded web page.
# if we couldn't parse a time, this is a failure.
log.last_sync = None
log.error = "Could not parse time from lastsync"
log.is_success = False
def check_mirror_url(mirror_url, location, timeout):
url = mirror_url.url + 'lastsync'
logger.info("checking URL %s", url)
log = MirrorLog(url=mirror_url, check_time=now(), location=location)
headers = {'User-Agent': 'archweb/1.0'}
req = urllib2.Request(url, None, headers)
try:
start = time.time()
result = urllib2.urlopen(req, timeout=timeout)
data = result.read()
result.close()
end = time.time()
parse_lastsync(log, data)
log.duration = end - start
logger.debug("success: %s, %.2f", url, log.duration)
except urllib2.HTTPError as e:
if e.code == 404:
# we have a duration, just not a success
end = time.time()
log.duration = end - start
log.is_success = False
log.error = str(e)
logger.debug("failed: %s, %s", url, log.error)
except urllib2.URLError as e:
log.is_success = False
log.error = e.reason
if isinstance(e.reason, types.StringTypes) and \
re.search(r'550.*No such file', e.reason):
# similar to 404 case above, still record duration
end = time.time()
log.duration = end - start
if isinstance(e.reason, socket.timeout):
log.error = "Connection timed out."
elif isinstance(e.reason, socket.error):
log.error = e.reason.args[1]
logger.debug("failed: %s, %s", url, log.error)
except HTTPException as e:
# e.g., BadStatusLine
log.is_success = False
log.error = "Exception in processing HTTP request."
logger.debug("failed: %s, %s", url, log.error)
except socket.timeout as e:
log.is_success = False
log.error = "Connection timed out."
logger.debug("failed: %s, %s", url, log.error)
except socket.error as e:
log.is_success = False
log.error = str(e)
logger.debug("failed: %s, %s", url, log.error)
return log
def check_rsync_url(mirror_url, location, timeout):
url = mirror_url.url + 'lastsync'
logger.info("checking URL %s", url)
log = MirrorLog(url=mirror_url, check_time=now(), location=location)
tempdir = tempfile.mkdtemp()
ipopt = ''
if location:
if location.family == socket.AF_INET6:
ipopt = '--ipv6'
elif location.family == socket.AF_INET:
ipopt = '--ipv4'
lastsync_path = os.path.join(tempdir, 'lastsync')
rsync_cmd = ["rsync", "--quiet", "--contimeout=%d" % timeout,
"--timeout=%d" % timeout, ipopt, url, lastsync_path]
try:
with open(os.devnull, 'w') as devnull:
logger.debug("rsync cmd: %s", ' '.join(rsync_cmd))
proc = subprocess.Popen(rsync_cmd, stdout=devnull,
stderr=subprocess.PIPE)
start = time.time()
_, errdata = proc.communicate()
end = time.time()
log.duration = end - start
if proc.returncode != 0:
logger.debug("error: %s, %s", url, errdata)
log.is_success = False
log.error = errdata.strip()
# look at rsync error code- if we had a command error or timed out,
# don't record a duration as it is misleading
if proc.returncode in (1, 30, 35):
log.duration = None
else:
logger.debug("success: %s, %.2f", url, log.duration)
with open(lastsync_path, 'r') as lastsync:
parse_lastsync(log, lastsync.read())
finally:
if os.path.exists(lastsync_path):
os.unlink(lastsync_path)
os.rmdir(tempdir)
return log
def mirror_url_worker(work, output, location, timeout):
while True:
try:
url = work.get(block=False)
try:
if url.protocol.protocol == 'rsync':
log = check_rsync_url(url, location, timeout)
else:
log = check_mirror_url(url, location, timeout)
output.append(log)
finally:
work.task_done()
except Empty:
return 0
class MirrorCheckPool(object):
def __init__(self, urls, location, timeout=10, num_threads=10):
self.tasks = Queue()
self.logs = deque()
for url in list(urls):
self.tasks.put(url)
self.threads = []
for i in range(num_threads):
thread = Thread(target=mirror_url_worker,
args=(self.tasks, self.logs, location, timeout))
thread.daemon = True
self.threads.append(thread)
@transaction.commit_on_success
def run(self):
logger.debug("starting threads")
for thread in self.threads:
thread.start()
logger.debug("joining on all threads")
self.tasks.join()
logger.debug("processing %d log entries", len(self.logs))
MirrorLog.objects.bulk_create(self.logs)
logger.debug("log entries saved")
# vim: set ts=4 sw=4 et:
|
