Merge branch 'master' of github.com:research/chocolate

This commit is contained in:
James Kasten 2012-11-07 14:36:43 -05:00
commit f420b07b9a
11 changed files with 149 additions and 354 deletions

View file

@ -28,4 +28,5 @@ hashcash_expiry = 60*60
extra_name_blacklist = ["eff.org", "www.eff.org"]
# Name of file containing cert chain
cert_chain_file = "chain.pem"
cert_chain_file = "demoCA/cacert.pem"
debug = True

View file

@ -37,8 +37,8 @@ def parse(csr):
return False
def modulusbits(key):
key = str(key)
"""How many bits are in the modulus of this key?"""
key = str(key)
bio = M2Crypto.BIO.MemoryBuffer(key)
pubkey = M2Crypto.RSA.load_pub_key_bio(bio)
return len(pubkey)

View file

@ -14,6 +14,8 @@ chocolate.py - server-side, requires web.py (python-webpy),
build-essential, python-dev, and swig)
probably wants to run under a web server like lighttpd with fastcgi
daemons/{makechallenge,testchallenge,issue,logging}-daemon.py -
daemons to handle back-end implementation of protocol state transitions
chocolate_protocol.proto - protocol definition; needs protobuf-compiler

37
server-ca/TODO Normal file
View file

@ -0,0 +1,37 @@
# The queue mechanism with pending-* is supposed to control
# concurrency issues properly, but this needs verification
# to ensure that there are no possible race conditions.
# Generally, the server process (as distinct from the daemon)
# is not supposed to change sessions at all once they have
# been added to a queue, except for marking them no longer
# live if the server realizes that something bad has happened
# to them. There may be some exceptions, and they should all
# be analyzed for possible races.
# TODO: check sessions' internal evidence for consistency
# with their queue membership (in case of crashes or bugs).
# In particular, check that a session in pending-makechallenge
# does not actually contain any challenges and that a
# session in pending-issue does not actually contain an
# issued cert.
# TODO: write queue rebuilding script that uses sessions'
# internal state to decide which queue they go in (to
# run when starting daemon, in case there was a crash
# that caused a session not to be in any pending queue
# because the daemon was actively working on it during
# the crash); consider marking sessions "dirty" when
# beginning to actually modify their contents in order
# to allow dirty sessions to be deleted after a crash instead
# of placing them back on a queue. Or, we could just
# decide that a crash invalidates each and every pending
# request, period, while still allowing clients to look
# up successfully issued certs.
# NOTE: The daemon enforces its own timeouts, which are
# defined in the ancient() function. These timeouts apply
# to any session that has been placed in a queue and can
# be completely independent of the session timeout policy
# in the server. Being marked as dead at any time by either
# the server or the daemon (due to timeout or error) causes
# a session to be treated as dead by both.

View file

@ -2,6 +2,7 @@
import web, redis, time, binascii, re, urllib2
import CSR
from redis_lock import redis_lock
from trustify.protocol import hashcash
from CSR import M2Crypto
from Crypto import Random
@ -13,6 +14,8 @@ from CONFIG import max_names, max_csr_size, maximum_session_age
from CONFIG import maximum_challenge_age, hashcash_expiry, extra_name_blacklist
from CONFIG import cert_chain_file, debug
poll_interval = 10
try:
chocolate_server_name = open("SERVERNAME").read().rstrip()
except IOError:
@ -81,6 +84,8 @@ class session(object):
if timestamp is None: timestamp = int(time.time())
if not self.exists():
sessions.hset(self.id, "created", timestamp)
sessions.hset(self.id, "lastpoll", 0)
sessions.hset(self.id, "times-tested", 0)
sessions.hset(self.id, "live", True)
sessions.lpush("active-requests", self.id)
else:
@ -101,6 +106,20 @@ class session(object):
def age(self):
return int(time.time()) - int(sessions.hget(self.id, "created"))
def poll_age(self):
return float(time.time()) - float(sessions.hget(self.id, "lastpoll"))
def request_test(self):
"""Ask a daemon to test challenges."""
# There is a race condition between testing for membership and
# adding it, but it's quite difficult to "exploit" and the result
# of triggering it is just that the same session will be scheduled
# for testing twice. We use locking in the daemon to exclude the
# possibility of two daemon processes testing the same session at
# once, and check the session's state before beginning to test it.
if self.id not in sessions.lrange("pending-testchallenge", 0, -1):
sessions.lpush("pending-testchallenge", self.id)
def request_made(self):
"""Has there already been a signing request made in this session?"""
return sessions.hget(self.id, "state") is not None
@ -119,7 +138,6 @@ class session(object):
sessions.hset(self.id, "client-addr", web.ctx.ip)
sessions.hset(self.id, "state", "makechallenge")
sessions.lpush("pending-makechallenge", self.id)
sessions.publish("requests", "makechallenge")
return True
def challenges(self):
@ -141,8 +159,9 @@ class session(object):
self.die(r, r.BadRequest, uri="https://ca.example.com/failures/internalerror")
return
def check_hashcash(self, h):
"""Is the hashcash string h valid for a request to this server?"""
def check_hashcash(self, h, n):
"""Is the hashcash string h valid for a request to this server for
signing n names?"""
if hashcash.check(stamp=h, resource=chocolate_server_name, \
bits=difficulty, check_expiration=hashcash_expiry):
# sessions.sadd returns True upon adding to a set and
@ -225,7 +244,8 @@ class session(object):
self.die(r, r.BadRequest, uri="https://ca.example.com/failures/recipient")
return
# Check hashcash before doing any crypto or database access.
if not m.request.clientpuzzle or not self.check_hashcash(m.request.clientpuzzle):
names = CSR.subject_names(csr)
if not m.request.clientpuzzle or not self.check_hashcash(m.request.clientpuzzle, len(names)):
self.die(r, r.NeedClientPuzzle, uri="https://ca.example.com/failures/hashcash")
return
if self.request_made():
@ -257,7 +277,6 @@ class session(object):
if not CSR.csr_goodkey(csr):
self.die(r, r.UnsafeKey)
return
names = CSR.subject_names(csr)
if len(names) == 0:
self.die(r, r.BadCSR)
return
@ -312,6 +331,19 @@ class session(object):
# If we're in testchallenge, tell the client about the challenges and their
# current status.
if state == "testchallenge":
# If the client claims to have completed some challenges, try to test
# them, if the client hasn't asked us to do so too recently.
if m.completedchallenge:
try:
with redis_lock(sessions, "lock-" + self.id, one_shot=True):
if self.poll_age() < poll_interval:
# Too recent!
pass
else:
sessions.hset(self.id, "lastpoll", time.time())
self.request_test()
except KeyError:
pass
self.send_challenges(m, r)
return
# If we're in done, tell the client about the successfully issued cert.

View file

@ -1,334 +0,0 @@
#!/usr/bin/env python
# This daemon runs on the CA side to look for requests in
# the database that are waiting for actions to be taken:
# generating challenges, testing whether challenges have
# been met, and issuing certs when the challenges have been
# met. The daemon does not communicate with the client at
# all; it just notes changes to request state in the database,
# which the server will inform the client about when the
# client subsequently checks in.
# The queue mechanism with pending-* is supposed to control
# concurrency issues properly, but this needs verification
# to ensure that there are no possible race conditions.
# Generally, the server process (as distinct from the daemon)
# is not supposed to change sessions at all once they have
# been added to a queue, except for marking them no longer
# live if the server realizes that something bad has happened
# to them. There may be some exceptions, and they should all
# be analyzed for possible races.
# TODO: check sessions' internal evidence for consistency
# with their queue membership (in case of crashes or bugs).
# In particular, check that a session in pending-makechallenge
# does not actually contain any challenges and that a
# session in pending-issue does not actually contain an
# issued cert.
# TODO: write queue rebuilding script that uses sessions'
# internal state to decide which queue they go in (to
# run when starting daemon, in case there was a crash
# that caused a session not to be in any pending queue
# because the daemon was actively working on it during
# the crash); consider marking sessions "dirty" when
# beginning to actually modify their contents in order
# to allow dirty sessions to be deleted after a crash instead
# of placing them back on a queue. Or, we could just
# decide that a crash invalidates each and every pending
# request, period, while still allowing clients to look
# up successfully issued certs.
# TODO: implement multithreading to allow several parallel
# worker processes.
#
# NOTE: The daemon enforces its own timeouts, which are
# defined in the ancient() function. These timeouts apply
# to any session that has been placed in a queue and can
# be completely independent of the session timeout policy
# in the server. Being marked as dead at any time by either
# the server or the daemon (due to timeout or error) causes
# a session to be treated as dead by both.
import redis, redis_lock, time, CSR, sys, signal, binascii
from sni_challenge.verify import verify_challenge
from Crypto import Random
r = redis.Redis()
ps = r.pubsub()
issue_lock = redis_lock.redis_lock(r, "issue_lock")
# This lock guards the ability to issue certificates with "openssl ca",
# which has no locking of its own. We don't need locking for the updates
# that the daemon performs on the sessions in the database because the
# queues pending-makechallenge, pending-testchallenge, and pending-issue
# are updated atomically and the daemon only ever acts on sessions that it
# has removed from a queue.
# TODO: in a deployed system, the queue for issuing certs should probably
# be treated a first-come, first-issue fashion, so that a request doesn't
# time out while waiting to acquire the lock just because other requests
# happened to get it first. Another way of putting this is that there
# could be only one thread/process that deals with pending-issue sessions,
# even though there could be many that deal with pending-makechallenge and
# pending-testchallenge. Then we can guarantee that the oldest pending-issue
# requests are dealt with first, which is impossible to guarantee when
# multiple daemons may be opportunistically acquiring this lock.
debug = "debug" in sys.argv
clean_shutdown = False
def signal_handler(a, b):
global clean_shutdown
clean_shutdown = True
r.publish("exit", "clean-exit")
signal.signal(signal.SIGTERM, signal_handler)
signal.signal(signal.SIGINT, signal_handler)
def short(session):
"""Return the first 12 bytes of a session ID, or, for a
challenge ID, the challenge ID with the session ID truncated."""
tmp = session.partition(":")
return tmp[0][:12] + "..." + tmp[1] + tmp[2]
def ancient(session, state):
"""Given that this session is in the specified named state,
decide whether the daemon should forcibly expire it for being too
old, even if no client request has caused the serve to mark the
session as expired. This is most relevant to truly abandoned
sessions that no client ever asks about."""
age = int(time.time()) - int(r.hget(session, "created"))
if state == "makechallenge" and age > 120:
if debug: print "considered", short(session), "ancient"
return True
if state == "testchallenge" and age > 600:
if debug: print "considered", short(session), "ancient"
return True
return False
def random():
"""Return 64 hex digits representing a new 32-byte random number."""
return binascii.hexlify(Random.get_random_bytes(32))
def random_raw():
"""Return 32 random bytes."""
return Random.get_random_bytes(32)
def makechallenge(session):
if r.hget(session, "live") != "True":
# This session has died due to some other reason, like an
# illegal request or timeout, since it entered makechallenge
# state. Consequently, we're not allowed to advance its
# state any further, and it should be removed from the
# pending-requests queue and not pushed into any other queue.
# We don't have to remove it from pending-makechallenge
# because the caller has already done so.
if debug: print "removing expired session", short(session)
r.lrem("pending-requests", session)
return
# Currently only makes challenges of type 0 (DomainValidateSNI)
# This challenge type has three internal data parameters:
# dvsni:nonce, dvsni:r, dvsni:ext
# This challenge type sends three data parameters to the client:
# nonce, y = E(r), ext
#
# Make one challenge for each name. (This one-to-one relationship
# is not an inherent protocol requirement!)
names = r.lrange("%s:names" % session, 0, -1)
if debug: print "%s: new valid request" % session
if debug: print "%s: from requesting client at %s" % (short(session), r.hget(session, "client-addr"))
if debug: print "%s: for %d names: %s" % (short(session), len(names), ", ".join(names))
for i, name in enumerate(names):
challenge = "%s:%d" % (session, i)
r.hset(challenge, "challtime", int(time.time()))
r.hset(challenge, "type", 0) # DomainValidateSNI
r.hset(challenge, "name", name)
r.hset(challenge, "satisfied", False)
r.hset(challenge, "failed", False)
r.hset(challenge, "dvsni:nonce", random())
r.hset(challenge, "dvsni:r", random_raw())
r.hset(challenge, "dvsni:ext", "1.3.3.7")
# Keep accurate count of how many challenges exist in this session.
r.hincrby(session, "challenges", 1)
if debug: print "created new challenge", short(challenge)
if True: # challenges have been created
r.hset(session, "state", "testchallenge")
r.lpush("pending-testchallenge", session)
# TODO: this causes the daemon to immediately attempt to test the
# challenge for completion, with no delay.
r.publish("requests", "testchallenge")
else:
r.lpush("pending-makechallenge", session)
r.publish("requests", "makechallenge")
def testchallenge(session):
if r.hget(session, "live") != "True":
# This session has died due to some other reason, like an
# illegal request or timeout, since it entered testchallenge
# state. Consequently, we're not allowed to advance its
# state any further, and it should be removed from the
# pending-requests queue and not pushed into any other queue.
# We don't have to remove it from pending-testchallenge
# because the caller has already done so.
if debug: print "removing expired session", short(session)
r.lrem("pending-requests", session)
return
# Note that we can push this back into the original queue.
# TODO: need to add a way to make sure we don't test the same
# session too often.
# Conceivably, this could wait until the client announces
# that it has completed the challenges. Information about
# the client's reporting could be stored in the database.
# Then the CA doesn't need to poll prematurely.
all_satisfied = True
for i, name in enumerate(r.lrange("%s:names" % session, 0, -1)):
challenge = "%s:%d" % (session, i)
if debug: print "testing challenge", short(challenge)
challtime = int(r.hget(challenge, "challtime"))
challtype = int(r.hget(challenge, "type"))
name = r.hget(challenge, "name")
satisfied = r.hget(challenge, "satisfied") == "True"
failed = r.hget(challenge, "failed") == "True"
# TODO: check whether this challenge is too old
if not satisfied and not failed:
# if debug: print "challenge", short(challenge), "being tested"
if challtype == 0: # DomainValidateSNI
if debug: print "\tbeginning dvsni test to %s" % name
dvsni_nonce = r.hget(challenge, "dvsni:nonce")
dvsni_r = r.hget(challenge, "dvsni:r")
dvsni_ext = r.hget(challenge, "dvsni:ext")
direct_result, direct_reason = verify_challenge(name, dvsni_r, dvsni_nonce, False)
proxy_result, proxy_reason = verify_challenge(name, dvsni_r, dvsni_nonce, True)
if debug:
print "\t...direct probe: %s (%s)" % (direct_result, direct_reason)
print "\tTor proxy probe: %s (%s)" % (proxy_result, proxy_reason)
if direct_result and proxy_result:
r.hset(challenge, "satisfied", True)
else:
all_satisfied = False
# TODO: distinguish permanent and temporarily failures
# can cause a permanent failure under some conditions, causing
# the session to become dead. TODO: need to articulate what
# those conditions are
else:
# Don't know how to handle this challenge type
all_satisfied = False
elif not satisfied:
if debug: print "\tchallenge was not attempted"
all_satisfied = False
if all_satisfied:
# Challenges all succeeded, so we should prepare to issue
# the requested cert.
# TODO: double-check that there were > 0 challenges,
# so that we don't somehow mistakenly issue a cert in
# response to an empty list of challenges (even though
# the daemon that put this session on the queue should
# also have implicitly guaranteed this).
if debug: print "\t** All challenges satisfied; request %s GRANTED" % short(session)
r.hset(session, "state", "issue")
r.lpush("pending-issue", session)
r.publish("requests", "issue")
else:
# Some challenges are not verified.
# Put this session back on the stack to try to verify again.
r.lpush("pending-testchallenge", session)
# TODO: if we wanted the client to tell us when it believes
# it has completed the challenge, we should take this out and
# have the server publish the message in response to the message
# from the client. Also, the current version will cause the
# server to retest over and over again as fast as it's able.
r.publish("requests", "testchallenge")
def issue(session):
if r.hget(session, "live") != "True":
# This session has died due to some other reason, like an
# illegal request or timeout, since it entered testchallenge
# state. Consequently, we're not allowed to advance its
# state any further, and it should be removed from the
# pending-requests queue and not pushed into any other queue.
# We don't have to remove it from pending-testchallenge
# because the caller has already done so.
#
# Having a session in pending-issue die is a very weird case
# that probably suggests that timeouts are set incorrectly
# or that the client is misbehaving very badly. This means
# that a request passed all of its challenges but the
# session nonetheless died for some reason unrelated to failing
# challenges before the cert could be issued. Normally, this
# should never happen.
#
# TODO: This can definitely happen when there are extremely many
# sessions stuck in testchallenge state compared to the number of
# daemon processes to handle them, because each session in
# testchallenge gets tested once before any daemon gets around to
# issuing the cert. This is a bug.
if debug: print "removing expired (issue-state!?) session", short(session)
r.lrem("pending-requests", session)
return
csr = r.hget(session, "csr")
names = r.lrange("%s:names" % session, 0, -1)
with issue_lock:
cert = CSR.issue(csr, names)
r.hset(session, "cert", cert)
if cert: # once issuing cert succeeded
if debug: print "%s: issued certificate for names: %s" % (short(session), ", ".join(names))
r.hset(session, "state", "done")
r.lpush("pending-done", session)
# TODO: Note that we do not publish a pubsub message when
# the session enters done state, so the daemon will not
# actually act on it. Is that OK?
else: # should not be reached in deployed version
if debug: print "issuing for", short(session), "failed"
r.lpush("pending-issue", session)
r.publish("requests", "issue")
# Dispatch table for how to react to pubsub messages. The key is
# the pubsub message and the value is a tuple of (queue name, function).
# The main loop will look in the specified queue for a pending session,
# and, if it finds one, it will call the specified function on it.
# Since the queue names are systematically related to the message names,
# we could probably remove the queue name field entirely.
dispatch = { "makechallenge": ("pending-makechallenge", makechallenge),
"testchallenge": ("pending-testchallenge", testchallenge),
"issue": ("pending-issue", issue),
"done": ("pending-done", lambda x: None) }
# Main loop: act on queues notified via Redis pubsub mechanism.
# Currently, we ignore the specific details of which queue was
# notified and, upon any notification, repeatedly process a single
# item from each queue until all queues are empty.
ps.subscribe(["requests"])
ps.subscribe(["logs"])
ps.subscribe(["exit"])
for message in ps.listen():
if message["type"] != "message":
continue
if message["channel"] == "logs":
if debug: print message["data"]
continue
if message["channel"] == "exit":
break
if message["channel"] == "requests":
# populated_queue would be used by a more sophisticated scheduler
populated_queue = message["data"]
while True:
inactive = True
for queue in ("makechallenge", "testchallenge", "issue"):
if clean_shutdown:
inactive = True
break
session = r.rpop("pending-" + queue)
if session:
inactive = False
if ancient(session, queue) and queue != "issue":
if debug: print "expiring ancient session", short(session)
r.hset(session, "live", False)
else:
# if debug: print "going to %s for %s" % (queue, short(session))
if queue == "makechallenge": makechallenge(session)
elif queue == "testchallenge": testchallenge(session)
elif queue == "issue": issue(session)
if inactive:
break
if clean_shutdown:
print "daemon exiting cleanly"
break

View file

@ -17,6 +17,11 @@
# implemented, only one process succeds in clearing and acquiring a
# particular expired lock, even "when multiple clients detected an
# expired lock and are trying to release it".
#
# The optional one_shot parameter causes the attempt to acquire the
# lock to instead raise a KeyError exception if someone else is already
# holding a valid lock. This is used in situations where a process
# doesn't insist on doing the actions guarded by the lock.
import time, random
@ -27,9 +32,10 @@ def valid(t):
return float(t) > time.time()
class redis_lock(object):
def __init__(self, redis, lock_name):
def __init__(self, redis, lock_name, one_shot=False):
self.redis = redis
self.lock_name = lock_name
self.one_shot = one_shot
def __enter__(self):
while True:
@ -40,6 +46,8 @@ class redis_lock(object):
# "C4 sends GET lock.foo to check if the lock expired."
existing_lock = self.redis.get(self.lock_name)
if (not existing_lock) or valid(existing_lock):
if self.one_shot:
raise KeyError
# "If it is not, it will sleep for some time and retry from
# the start."
time.sleep(1 + random.random())

View file

@ -68,8 +68,8 @@ def verify_challenge(address, r, nonce, socksify=False):
sni_support.set_sni_ext(conn.ssl, sni_name)
try:
conn.connect((address, 443))
except:
return False, "Connection to SSL Server failed"
except Exception, e:
return False, "Connection to SSL Server failed (%s)" % str(e)
cert_chain = conn.get_peer_cert_chain()

22
server-ca/start_daemons Executable file
View file

@ -0,0 +1,22 @@
#!/bin/sh
# By default, daemons are not being told to exit!
redis-cli del exit
echo "Starting logger daemon..."
nohup ./logging-daemon.py &
# TODO: an attempt to reconstruct or expire sessions from previous
# runs of the daemon should occur here.
echo "Starting issue daemon..."
nohup ./issue-daemon.py &
for instance in a b c
do
echo "Starting testchallenge daemon $instance..."
nohup ./testchallenge-daemon.py &
done
echo "Starting makechallenge daemon..."
nohup ./makechallenge-daemon.py &

7
server-ca/stop_daemons Executable file
View file

@ -0,0 +1,7 @@
#!/bin/sh
redis-cli lpush exit exit
redis-cli publish exit clean-exit
# TODO: sleep a bit and then actually kill the daemon processes if they
# don't exit

View file

@ -175,11 +175,11 @@ def drop_privs():
os.setgroups([])
os.setuid(nobody)
def make_request(server, m, csr, quiet=False):
def make_request(server, m, csr, names, quiet=False):
m.request.recipient = server
m.request.timestamp = int(time.time())
m.request.csr = csr
hashcash_cmd = ["hashcash", "-P", "-m", "-z", "12", "-b", `difficulty`, "-r", server]
hashcash_cmd = ["hashcash", "-P", "-m", "-z", "12", "-b", `difficulty*len(names)`, "-r", server]
if quiet:
hashcash = subprocess.Popen(hashcash_cmd, preexec_fn=drop_privs, shell= False, stdout=subprocess.PIPE, stderr=open("/dev/null", "w")).communicate()[0].rstrip()
else:
@ -297,7 +297,7 @@ def challenge_factory(r, req_filepath, key_filepath, config):
return challenges, dn
def send_request(key_pem, csr_pem, quiet=curses):
def send_request(key_pem, csr_pem, names, quiet=curses):
global server
upstream = "https://%s/chocolate.py" % server
k=chocolatemessage()
@ -305,7 +305,7 @@ def send_request(key_pem, csr_pem, quiet=curses):
init(k)
init(m)
logger.info("Creating request; generating hashcash...")
make_request(server, m, csr_pem, quiet=curses)
make_request(server, m, csr_pem, names, quiet=curses)
sign(key_pem, m)
logger.info("Created request; sending to server...")
logger.debug(m)
@ -445,7 +445,7 @@ def authenticate():
logger.info("Generating key: " + key_file)
logger.info("Creating CSR: " + req_file)
r, k = send_request(key_pem, csr_pem)
r, k = send_request(key_pem, csr_pem, names)
challenges, dn = challenge_factory(r, os.path.abspath(req_file), os.path.abspath(key_file), config)
@ -459,18 +459,38 @@ def authenticate():
for challenge in challenges:
if not challenge.perform(quiet=curses):
# TODO: In this case the client should probably send a failure
# to the server.
logger.fatal("challenge failed")
sys.exit(1)
logger.info("Configured Apache for challenge; waiting for verification...")
logger.debug("waiting 3")
time.sleep(3)
did_it = chocolatemessage()
init(did_it)
did_it.session = r.session
# This will blindly assert that all of the challenges have been
# complied with, by simply copying them from the challenge data
# structure into a new completedchallenge structure. This is
# kind of crude, because the client could instead actually build up
# a completedchallenge structure piece-by-piece as it actually
# complies with challenges (and then send that structure for the
# server to look at). In the existing client, completedchallenge
# is only ever sent once _all_ of the (assumed to be dvsni)
# challenges have been met, and client-side failure to meet any
# challenge is immediately fatal to the client. In the existing
# server, the client's assertion that the client has met any
# (assumed to be dvsni) challenge(s) will result in the server
# scheduling a test of all challenges.
did_it.completedchallenge.extend(r.challenge)
r=decode(do(upstream, k))
r=decode(do(upstream, did_it))
logger.debug(r)
delay = 5
while r.challenge or r.proceed.IsInitialized():
logger.debug("waiting 5")
time.sleep(5)
if r.proceed.IsInitialized():
delay = min(r.proceed.polldelay, 60)
logger.debug("waiting %d" % delay)
time.sleep(delay)
k.session = r.session
r = decode(do(upstream, k))
logger.debug(r)