def got_response_collecting(self, stream, request, response):
logging.info("BitTorrent: collecting ... done")
if self.success:
#
# Always measure at the receiver because there is more
# information at the receiver and also to make my friend
# Enrico happier :-P.
# The following is not a bug: it's just that the server
# returns a result using the point of view of the client,
# i.e. upload_speed is _our_ upload speed.
#
m = json.loads(response.body.read())
self.my_side["upload_speed"] = m["upload_speed"]
upload = utils.speed_formatter(m["upload_speed"])
STATE.update("test_progress", "100%", publish=False)
STATE.update("test_upload", upload)
logging.info('BitTorrent: upload speed: %s', upload)
if privacy.collect_allowed(self.my_side):
if DATABASE.readonly:
logging.warning('bittorrent_client: readonly database')
else:
table_bittorrent.insert(DATABASE.connection(), self.my_side)
# Update the upstream channel estimate
target_bytes = int(m["target_bytes"])
if target_bytes > 0:
estimate.UPLOAD = target_bytes
self.final_state = True
stream.close()
def got_response_collecting(self, stream, request, response):
LOG.complete()
if self.success:
#
# Always measure at the receiver because there is more
# information at the receiver and also to make my friend
# Enrico happier :-P.
# The following is not a bug: it's just that the server
# returns a result using the point of view of the client,
# i.e. upload_speed is _our_ upload speed.
#
m = json.loads(response.body.read())
self.my_side["upload_speed"] = m["upload_speed"]
upload = utils.speed_formatter(m["upload_speed"])
STATE.update("test_upload", upload)
if privacy.collect_allowed(self.my_side):
table_bittorrent.insert(DATABASE.connection(), self.my_side)
# Update the upstream channel estimate
target_bytes = int(m["target_bytes"])
if target_bytes > 0:
estimate.UPLOAD = target_bytes
stream.close()
def _periodic_internal(stream):
""" Periodically snap goodput (internal function) """
context = stream.opaque
utime, stime = os.times()[:2]
utimediff = utime - context.snap_utime
stimediff = stime - context.snap_stime
ticks = utils.ticks()
timediff = ticks - context.snap_ticks
bytesdiff = stream.bytes_in - context.snap_count
context.state.setdefault("goodput_snap", []).append(
{
"ticks": ticks,
"bytesdiff": bytesdiff,
"timediff": timediff,
"utimediff": utimediff,
"stimediff": stimediff,
}
)
logging.debug("raw_clnt: utime, stime = %f, %f", utime, stime)
if timediff > 1e-06:
speed = utils.speed_formatter(bytesdiff / timediff)
logging.debug("raw_clnt: goodput_snap: %s", speed)
context.snap_count = stream.bytes_in
context.snap_ticks = ticks
context.snap_utime = utime
context.snap_stime = stime
def main():
assert(len(RANDOMBLOCKS.get_block()) == RANDOMBLOCKS.blocksiz)
assert(RANDOMBLOCKS.get_block() != RANDOMBLOCKS.get_block())
fp, total = RandomBody(RANDOMBLOCKS.blocksiz + 789), 0
while True:
block = fp.read(128)
if not block:
break
total += len(block)
assert(total == RANDOMBLOCKS.blocksiz + 789)
fp = RandomBody(RANDOMBLOCKS.blocksiz + 789)
assert(len(fp.read()) == RANDOMBLOCKS.blocksiz)
assert(fp.tell() == 789)
assert(len(fp.read()) == 789)
fp.seek(7)
begin, total = utils.ticks(), 0
try:
while True:
total += len(RANDOMBLOCKS.get_block())
except KeyboardInterrupt:
print "Interrupt"
print "Speed:", utils.speed_formatter(total/(utils.ticks() - begin))
def main():
''' Unit test for neubot/utils_random.py '''
assert(len(RANDOMBLOCKS.get_block()) == RANDOMBLOCKS.blocksiz)
assert(RANDOMBLOCKS.get_block() != RANDOMBLOCKS.get_block())
filep, total = RandomBody(RANDOMBLOCKS.blocksiz + 789), 0
while True:
block = filep.read(128)
if not block:
break
total += len(block)
assert(total == RANDOMBLOCKS.blocksiz + 789)
filep = RandomBody(RANDOMBLOCKS.blocksiz + 789)
assert(len(filep.read()) == RANDOMBLOCKS.blocksiz)
assert(filep.tell() == 789)
assert(len(filep.read()) == 789)
filep.seek(7)
begin, total = utils.ticks(), 0
while total < 1073741824:
total += len(RANDOMBLOCKS.get_block())
elapsed = utils.ticks() - begin
print('Elapsed: %s' % utils.time_formatter(elapsed))
print('Speed: %s' % utils.speed_formatter(total/elapsed))
def main():
''' Unit test for neubot/utils_random.py '''
assert (len(RANDOMBLOCKS.get_block()) == RANDOMBLOCKS.blocksiz)
assert (RANDOMBLOCKS.get_block() != RANDOMBLOCKS.get_block())
filep, total = RandomBody(RANDOMBLOCKS.blocksiz + 789), 0
while True:
block = filep.read(128)
if not block:
break
total += len(block)
assert (total == RANDOMBLOCKS.blocksiz + 789)
filep = RandomBody(RANDOMBLOCKS.blocksiz + 789)
assert (len(filep.read()) == RANDOMBLOCKS.blocksiz)
assert (filep.tell() == 789)
assert (len(filep.read()) == 789)
filep.seek(7)
begin, total = utils.ticks(), 0
while total < 1073741824:
total += len(RANDOMBLOCKS.get_block())
elapsed = utils.ticks() - begin
print('Elapsed: %s' % utils.time_formatter(elapsed))
print('Speed: %s' % utils.speed_formatter(total / elapsed))
def report(self, *args, **kwargs):
self.poller.sched(self.interval, self.report)
rttavg, rttdetails = self.measure_rtt()
if len(rttdetails) > 0:
rttavg = "%d us" % int(1000000 * rttavg)
self.output.write("\t\t%s\t\t---\t\t---\n" % rttavg)
if len(rttdetails) > 1:
for detail in rttdetails:
detail = "%d us" % int(1000000 * detail)
self.output.write("\t\t %s\t\t---\t\t---\n" % detail)
recvavg, sendavg, percentages = self.measure_speed()
if len(percentages) > 0:
recv, send = (utils.speed_formatter(recvavg),
utils.speed_formatter(sendavg))
self.output.write("\t\t---\t\t%s\t\t%s\n" % (recv, send))
if len(percentages) > 1:
for val in percentages:
val = map(lambda x: "%.2f%%" % x, val)
self.output.write("\t\t---\t\t %s\t\t %s\n" %
(val[0], val[1]))
def _waiting_piece(self, stream, data):
''' Invoked when new data is available '''
# Note: this loop cannot be adapted to process other messages
# easily, as pointed out in <skype_defs.py>.
context = stream.opaque
context.bufferise(data)
context.state['rcvr_data'].append((utils.ticks(), len(data)))
while True:
if context.left > 0:
context.left = context.skip(context.left)
if context.left > 0:
break
elif context.left == 0:
tmp = context.pullup(4)
if not tmp:
break
context.left, = struct.unpack('!I', tmp)
if context.left > MAXRECV:
raise RuntimeError('skype_clnt: PIECE too large')
if not context.ticks:
context.ticks = context.snap_ticks = utils.ticks()
context.count = context.snap_count = stream.bytes_in
context.snap_utime, context.snap_stime = os.times()[:2]
POLLER.sched(1, self._periodic, stream)
if context.left == 0:
logging.debug('< {empty-message}')
logging.info('skype_clnt: skype goodput test... complete')
ticks = utils.ticks()
timediff = ticks - context.ticks
bytesdiff = stream.bytes_in - context.count
context.state['goodput'] = {
'ticks': ticks,
'bytesdiff': bytesdiff,
'timediff': timediff,
}
if timediff > 1e-06:
speed = utils.speed_formatter(bytesdiff / timediff)
logging.info('skype_clnt: goodput: %s', speed)
STATE.update('test_download', speed, publish=0)
STATE.update('test_upload', 'N/A')
self._periodic_internal(stream)
context.state['complete'] = 1
stream.close()
return
else:
raise RuntimeError('skype_clnt: internal error')
stream.recv(MAXRECV, self._waiting_piece)
def _waiting_piece(self, stream, data):
""" Invoked when new data is available """
# Note: this loop cannot be adapted to process other messages
# easily, as pointed out in <raw_defs.py>.
context = stream.opaque
context.bufferise(data)
context.state["rcvr_data"].append((utils.ticks(), len(data)))
while True:
if context.left > 0:
context.left = context.skip(context.left)
if context.left > 0:
break
elif context.left == 0:
tmp = context.pullup(4)
if not tmp:
break
context.left, = struct.unpack("!I", tmp)
if context.left > MAXRECV:
raise RuntimeError("raw_clnt: PIECE too large")
if not context.ticks:
context.ticks = context.snap_ticks = utils.ticks()
context.count = context.snap_count = stream.bytes_in
context.snap_utime, context.snap_stime = os.times()[:2]
POLLER.sched(1, self._periodic, stream)
if context.left == 0:
logging.debug("< {empty-message}")
logging.info("raw_clnt: raw goodput test... complete")
ticks = utils.ticks()
timediff = ticks - context.ticks
bytesdiff = stream.bytes_in - context.count
context.state["goodput"] = {"ticks": ticks, "bytesdiff": bytesdiff, "timediff": timediff}
if timediff > 1e-06:
speed = utils.speed_formatter(bytesdiff / timediff)
logging.info("raw_clnt: goodput: %s", speed)
STATE.update("test_progress", "100%", publish=False)
STATE.update("test_download", speed, publish=0)
STATE.update("test_upload", "N/A")
self._periodic_internal(stream)
context.state["complete"] = 1
stream.close()
return
else:
raise RuntimeError("raw_clnt: internal error")
stream.recv(MAXRECV, self._waiting_piece)
def _periodic_internal(stream):
''' Periodically snap goodput (internal function) '''
context = stream.opaque
utime, stime = os.times()[:2]
utimediff = utime - context.snap_utime
stimediff = stime - context.snap_stime
ticks = utils.ticks()
timediff = ticks - context.snap_ticks
bytesdiff = stream.bytes_in - context.snap_count
context.state.setdefault('goodput_snap', []).append({
'ticks': ticks, 'bytesdiff': bytesdiff, 'timediff': timediff,
'utimediff': utimediff, 'stimediff': stimediff})
logging.debug('skype_clnt: utime, stime = %f, %f', utime, stime)
if timediff > 1e-06:
speed = utils.speed_formatter(bytesdiff / timediff)
logging.debug('skype_clnt: goodput_snap: %s', speed)
context.snap_count = stream.bytes_in
context.snap_ticks = ticks
context.snap_utime = utime
context.snap_stime = stime
def got_choke(self, stream):
#
# The download terminates when we recv CHOKE.
# The code below is adapted from version 1
# code in got_piece().
#
if self.version >= 2:
logging.info('BitTorrent: download ... done')
# Calculate speed
xfered = stream.bytes_recv_tot - self.saved_bytes
elapsed = utils.ticks() - self.saved_ticks
self.dload_speed = xfered/elapsed
# Properly terminate download
self.state = SENT_NOT_INTERESTED
stream.send_not_interested()
download = utils.speed_formatter(self.dload_speed)
logging.info('BitTorrent: download speed: %s', download)
# To next state
if not self.connector_side:
self.complete(stream, self.dload_speed, self.rtt,
self.target_bytes)
else:
STATE.update("test_download", download)
# We MUST NOT fallthru
return
#
# We don't implement CHOKE and we cannot ignore it, since
# that would violate the specification. So we raise an
# exception, which has the side effect that the connection
# will be closed.
#
raise RuntimeError("Unexpected CHOKE message")
def _periodic_internal(stream):
''' Periodically snap goodput (internal function) '''
context = stream.opaque
utime, stime = os.times()[:2]
utimediff = utime - context.snap_utime
stimediff = stime - context.snap_stime
ticks = utils.ticks()
timediff = ticks - context.snap_ticks
bytesdiff = stream.bytes_out - context.snap_count
context.state.setdefault('goodput_snap', []).append({
'ticks': ticks, 'bytesdiff': bytesdiff, 'timediff': timediff,
'utimediff': utimediff, 'stimediff': stimediff})
logging.debug('raw_srvr: utime, stime = %f, %f', utime, stime)
if timediff > 1e-06:
speed = utils.speed_formatter(bytesdiff / timediff)
logging.debug('raw_srvr: goodput_snap: %s', speed)
web100_snap = web100.web100_snap(web100.WEB100_HEADER,
context.web100_dirname)
web100_snap['ticks'] = ticks
context.state.setdefault('web100_snap', []).append(web100_snap)
context.snap_count = stream.bytes_out
context.snap_ticks = ticks
context.snap_utime = utime
context.snap_stime = stime
def _piece_sent(self, stream):
''' Invoked when a message has been sent '''
context = stream.opaque
ticks = utils.ticks()
if ticks - context.ticks < 10:
stream.send(context.message, self._piece_sent)
#logging.debug('> PIECE')
return
logging.info('raw_srvr: raw test... complete')
ticks = utils.ticks()
timediff = ticks - context.ticks
bytesdiff = stream.bytes_out - context.count
context.state['timestamp'] = utils.timestamp()
context.state['goodput'] = {
'ticks': ticks,
'bytesdiff': bytesdiff,
'timediff': timediff,
}
if timediff > 1e-06:
speed = utils.speed_formatter(bytesdiff / timediff)
logging.info('raw_srvr: goodput: %s', speed)
self._periodic_internal(stream)
stream.send(EMPTY_MESSAGE, self._empty_message_sent)
logging.debug('> {empty-message}')
else:
data = ""
return data
def seek(self, offset=0, whence=0):
pass
def tell(self):
return self.total
if __name__ == "__main__":
begin = ticks()
m = "A" * 32768
arc4 = arcfour_new()
count = 0
try:
while True:
e = arc4.encrypt(m)
count += len(m)
except KeyboardInterrupt:
sys.stdout.write("\n")
end = ticks()
speed = count / (end - begin)
speed = speed_formatter(speed)
sys.stdout.write(speed)
sys.stdout.write("\n")
def got_response(self, stream, request, response):
""" Invoked when we receive the response from the server """
if response.code != "200":
logging.warning("dash: invalid response: %s", response.code)
stream.close()
return
new_ticks = utils.ticks()
new_bytes = stream.bytes_recv_tot
new_times = os.times()[:2]
logging.debug("dash: got response - ticks %f, bytes %d, times %s", new_ticks, new_bytes, new_times)
elapsed = new_ticks - self.saved_ticks
received = new_bytes - self.saved_cnt
delta_user_time = new_times[0] - self.saved_times[0]
delta_sys_time = new_times[1] - self.saved_times[1]
if elapsed < 0:
raise RuntimeError("dash: clock going backwards")
logging.debug(
"dash: got response - elaps %f, rcvd %d, user %f, sys %f",
elapsed,
received,
delta_user_time,
delta_sys_time,
)
if self.parent:
result = {
"connect_time": self.rtts[0],
"delta_user_time": delta_user_time,
"delta_sys_time": delta_sys_time,
"elapsed": elapsed,
"elapsed_target": DASH_SECONDS,
"internal_address": stream.myname[0],
"iteration": self.iteration,
"platform": sys.platform,
"rate": self.rate_kbit,
"real_address": self.parent.real_address,
"received": received,
"remote_address": stream.peername[0],
"request_ticks": self.saved_ticks,
"timestamp": utils.timestamp(),
"uuid": self.conf.get("uuid"),
"version": utils_version.NUMERIC_VERSION,
}
self.parent.append_result(result)
self.iteration += 1
#
# TODO it would be nice to also STATE.update() with the dash
# rate, but that change requires also some www changes.
#
STATE.update("test_progress", "%d%%" % ((100 * self.iteration) / DASH_MAX_ITERATION), publish=False)
speed = received / elapsed
self.speed_kbit = (speed * 8) / 1000
STATE.update("test_download", utils.speed_formatter(speed))
logging.info(
"dash: [%2d/%d] rate: %6d Kbit/s, speed: %6d Kbit/s, elapsed: %.3f s",
self.iteration,
DASH_MAX_ITERATION,
self.rate_kbit,
self.speed_kbit,
elapsed,
)
if self.iteration >= DASH_MAX_ITERATION:
logging.debug("dash: done all iteration")
stream.close()
return
#
# If we're adding too much delay, artificially reduce the
# measured speed to let the bottleneck breathe.
#
if elapsed > DASH_SECONDS:
rel_err = 1 - elapsed / DASH_SECONDS
self.speed_kbit += rel_err * self.speed_kbit
if self.speed_kbit < 0:
self.speed_kbit = 100
self.connection_ready(stream)
def update(self):
if self.finished:
return
#
# Decide whether we can transition to the next phase of
# the speedtest or not. Fall through to next request if
# needed, or return to the caller and rewind the stack.
#
ostate = self.state
if not self.state:
self.state = "negotiate"
del QUEUE_HISTORY[:]
elif self.state == "negotiate":
if self.conf.get("speedtest.client.unchoked", False):
logging.info("* speedtest: %s ... authorized to " "take the test\n", self.state)
self.state = "latency"
elif "speedtest.client.queuepos" in self.conf:
queuepos = self.conf["speedtest.client.queuepos"]
logging.info("* speedtest: %s ... waiting in queue, " "pos %s\n", self.state, queuepos)
STATE.update("negotiate", {"queue_pos": queuepos})
QUEUE_HISTORY.append(queuepos)
elif self.state == "latency":
tries = self.conf.get("speedtest.client.latency_tries", 10)
if tries == 0:
# Calculate average latency
latency = self.conf["speedtest.client.latency"]
latency = sum(latency) / len(latency)
self.conf["speedtest.client.latency"] = latency
# Advertise the result
STATE.update("test_progress", "33%", publish=False)
STATE.update("test_latency", utils.time_formatter(latency))
logging.info("* speedtest: %s ... done, %s\n", self.state, utils.time_formatter(latency))
self.state = "download"
else:
self.conf["speedtest.client.latency_tries"] = tries - 1
elif self.state in ("download", "upload"):
if len(self.streams) == self.conf.get("speedtest.client.nconn", 1):
# Calculate average speed
speed = self.conf["speedtest.client.%s" % self.state]
elapsed = max(map(lambda t: t[1], speed)) - min(map(lambda t: t[0], speed))
speed = sum(map(lambda t: t[2], speed)) / elapsed
#
# O(N) loopless adaptation to the channel w/ memory
# TODO bittorrent/peer.py implements an enhanced version
# of this algorithm, with a cap to the max number of
# subsequent tests. In addition to that, the bittorrent
# code also anticipates the update of target_bytes.
#
if elapsed > LO_THRESH:
ESTIMATE[self.state] *= TARGET / elapsed
self.conf["speedtest.client.%s" % self.state] = speed
# Advertise
STATE.update("test_%s" % self.state, utils.speed_formatter(speed), publish=False)
logging.info("* speedtest: %s ... done, %s\n", self.state, utils.speed_formatter(speed))
if self.state == "download":
STATE.update("test_progress", "66%")
self.state = "upload"
else:
STATE.update("test_progress", "100%")
self.state = "collect"
elif elapsed > LO_THRESH / 3:
del self.conf["speedtest.client.%s" % self.state]
ESTIMATE[self.state] *= TARGET / elapsed
else:
del self.conf["speedtest.client.%s" % self.state]
ESTIMATE[self.state] *= 2
else:
# Wait for all pending requests to complete
return
elif self.state == "collect":
logging.info("* speedtest: %s ... done\n", self.state)
self.cleanup()
return
else:
raise RuntimeError("Invalid state")
#
# Perform state transition and run the next phase of the
# speedtest. Not all phases need to employ all the connection
# with the upstream server.
#
if self.state == "negotiate":
ctor, justone = ClientNegotiate, True
elif self.state == "latency":
ctor, justone = ClientLatency, True
elif self.state == "download":
ctor, justone = ClientDownload, False
elif self.state == "upload":
ctor, justone = ClientUpload, False
elif self.state == "collect":
ctor, justone = ClientCollect, True
else:
raise RuntimeError("Invalid state")
if ostate != self.state:
self.child = ctor(self.poller)
self.child.configure(self.conf)
self.child.host_header = self.host_header
if self.state not in ("negotiate", "collect"):
if ostate == "negotiate" and self.state == "latency":
STATE.update("test", "speedtest")
else:
STATE.update(self.state)
logging.info("* speedtest: %s in progress...", self.state)
elif self.state == "negotiate":
logging.info("* speedtest: %s in progress...", self.state)
while self.streams:
#
# Override child Time-To-Connect (TTC) with our TTC
# so for the child it's like it really performed the
# connect(), not us.
#
self.child.rtts = self.rtts
self.child.connection_ready(self.streams.popleft())
if justone:
break
def get_piece_old(self, stream):
''' implements get_piece() for test version 1 '''
# Get next piece
try:
vector = self.sched_req.next()
except StopIteration:
vector = None
if vector:
# Send next piece
index, begin, length = vector[0]
stream.send_request(index, begin, length)
else:
#
# No more pieces: Wait for the pipeline to empty
#
# TODO Check whether it's better to stop the measurement
# when the pipeline starts emptying instead of when it
# becomes empty (maybe it is reasonable to discard when
# it fills and when it empties, isn't it?)
#
self.inflight -= 1
if self.inflight == 0:
xfered = stream.bytes_recv_tot - self.saved_bytes
elapsed = utils.ticks() - self.saved_ticks
speed = xfered/elapsed
logging.info("BitTorrent: downloading %d bytes ... %s",
self.target_bytes, utils.speed_formatter(speed))
#
# Make sure that next test would take about
# TARGET secs, under current conditions.
# We're a bit conservative when the elapsed
# time is small because there is the risk of
# overestimating the available bandwith.
# TODO Don't start from scratch but use speedtest
# estimate (maybe we need to divide it by two
# but I'm not sure at the moment).
#
if elapsed >= LO_THRESH/3:
self.target_bytes = int(self.target_bytes * TARGET/elapsed)
else:
self.target_bytes *= 2
#
# The stopping rule is when the test has run
# for more than LO_THRESH seconds or after some
# number of runs (just to be sure that we can
# not run forever due to unexpected network
# conditions).
#
self.repeat -= 1
if elapsed > LO_THRESH or self.repeat <= 0:
self.dload_speed = speed
self.state = SENT_NOT_INTERESTED
stream.send_not_interested()
if not self.connector_side:
self.complete(stream, self.dload_speed, self.rtt,
self.target_bytes)
else:
download = utils.speed_formatter(self.dload_speed)
STATE.update("test_progress", "50%", publish=False)
STATE.update("test_download", download)
else:
self.saved_ticks = 0
self.make_sched()
self.state = SENT_INTERESTED #XXX
self.got_unchoke(stream)
elif self.inflight < 0:
raise RuntimeError("Inflight became negative")