diff --git a/server-ca/chocolate.py b/server-ca/chocolate.py index 55cf9e973..3cb66a99d 100755 --- a/server-ca/chocolate.py +++ b/server-ca/chocolate.py @@ -233,6 +233,7 @@ class session(object): recipient = m.request.recipient csr = m.request.csr sig = m.request.sig + self.log("new session from %s" % web.ctx.ip) # Check whether we are the intended recipient of the request. Doing this # before the hashcash check is more work for the server but gives a more # helpful error message (because the hashcash will be wrong automatically @@ -314,6 +315,7 @@ class session(object): r.proceed.polldelay = polldelay def handleexistingsession(self, m, r): + self.log("received message from %s" % web.ctx.ip) if m.request.IsInitialized(): self.die(r, r.BadRequest, uri="https://ca.example.com/failures/requestinexistingsession") return diff --git a/server-ca/daemon_common.py b/server-ca/daemon_common.py index 80a0cb146..d612f4c0a 100644 --- a/server-ca/daemon_common.py +++ b/server-ca/daemon_common.py @@ -5,6 +5,9 @@ import time, binascii from Crypto import Random +import redis +log_redis = redis.Redis() + def signal_handler(a, b): global clean_shutdown clean_shutdown = True @@ -27,6 +30,6 @@ def random_raw(): def log(msg, session = None): if session: - r.publish("logs", "%s: %s" % (short(session), msg)) + log_redis.publish("logs", "%s: %s" % (short(session), msg)) else: - r.publish("logs", "%s" % session) + log_redis.publish("logs", "%s" % session) diff --git a/server-ca/issue-daemon.py b/server-ca/issue-daemon.py index de2a36858..2b4cee704 100755 --- a/server-ca/issue-daemon.py +++ b/server-ca/issue-daemon.py @@ -4,7 +4,6 @@ # the database that are waiting for a cert to be issued. import redis, redis_lock, CSR, sys, signal -from sni_challenge.verify import verify_challenge from Crypto import Random r = redis.Redis() @@ -49,12 +48,12 @@ def issue(session): return csr = r.hget(session, "csr") names = r.lrange("%s:names" % session, 0, -1) - log("attempting to issue certificate for names: %s" % join(names), session) + log("attempting to issue certificate for names: %s" % ", ".join(names), session) with issue_lock: cert = CSR.issue(csr, names) r.hset(session, "cert", cert) if cert: # once issuing cert succeeded - log("issued certificate for names: %s" % join(names), session) + log("issued certificate for names: %s" % ", ".join(names), session) r.hset(session, "state", "done") # r.lpush("pending-done", session) else: # should not be reached in deployed version diff --git a/server-ca/logging-daemon.py b/server-ca/logging-daemon.py index 7bbf8f327..a5bcd32b4 100755 --- a/server-ca/logging-daemon.py +++ b/server-ca/logging-daemon.py @@ -26,5 +26,6 @@ for message in ps.listen(): if message["channel"] == "exit": break if clean_shutdown: - print "logging daemon exiting cleanly" + sys.stdout.write("logging daemon exiting cleanly\n") + sys.stdout.flush() break diff --git a/server-ca/makechallenge-daemon.py b/server-ca/makechallenge-daemon.py index 86499fe83..a424962a4 100755 --- a/server-ca/makechallenge-daemon.py +++ b/server-ca/makechallenge-daemon.py @@ -25,7 +25,7 @@ def makechallenge(session): # 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) + log("removing expired session", session) r.lrem("pending-requests", session) return # Currently only makes challenges of type 0 (DomainValidateSNI) @@ -37,9 +37,8 @@ def makechallenge(session): # 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)) + log("new valid request from requesting client at %s" % r.hget(session, "client-addr"), session) + log("for %d names: %s" % (len(names), ", ".join(names)), session) for i, name in enumerate(names): challenge = "%s:%d" % (session, i) r.hset(challenge, "challtime", int(time.time())) @@ -52,7 +51,7 @@ def makechallenge(session): 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) + log("created new challenge %s" % challenge, session) if True: # challenges have been created r.hset(session, "state", "testchallenge") else: diff --git a/server-ca/payment-daemon.py b/server-ca/payment-daemon.py index 28b8416de..4fc6e1976 100755 --- a/server-ca/payment-daemon.py +++ b/server-ca/payment-daemon.py @@ -47,7 +47,7 @@ for message in ps.listen(): if len(session) != 64: continue if session not in r or r.hget(session, "live") != "True": continue if r.hget(session, "state") != "payment": continue - if debug: print "\t** All challenges satisfied; payment received; request %s GRANTED" % short(session) + log("\t** All challenges satisfied; payment received; request GRANTED", session) r.hset(session, "state", "issue") r.lpush("pending-issue", session) continue diff --git a/server-ca/payment.py b/server-ca/payment.py index f500f09f7..767afed24 100755 --- a/server-ca/payment.py +++ b/server-ca/payment.py @@ -30,11 +30,11 @@ class payment(object): def GET(self, session): web.header("Content-type", "text/html") if len(session) != 64 or not all(hexdigit(s) for s in session): - return "Attempt to process payment for invalid session." + return "

Oops!

Attempt to process payment for invalid session." if session not in r or r.hget(session, "live") != "True": - return "Attempt to process payment for invalid session." + return "

Oops!

Attempt to process payment for invalid session." if r.hget(session, "state") != "payment": - return "Attempt to process payment for session not expecting it." + return "

Oops!

Attempt to process payment for session that was not expecting it." r.publish("payments", session) names = r.lrange("%s:names" % session, 0, -1) names_list = '' diff --git a/server-ca/sni_challenge/verify.py b/server-ca/sni_challenge/verify.py index 334b778a6..cc8af96af 100644 --- a/server-ca/sni_challenge/verify.py +++ b/server-ca/sni_challenge/verify.py @@ -68,16 +68,17 @@ def verify_challenge(address, r, nonce, socksify=False): sni_support.set_sni_ext(conn.ssl, sni_name) try: conn.connect((address, 443)) + peername = str(conn.socket.getpeername()) except Exception, e: - return False, "Connection to SSL Server failed (%s)" % str(e) + return False, "Connection to SSL Server failed (%s)" % str(e), peername cert_chain = conn.get_peer_cert_chain() #Ensure certificate chain form is correct if cert_chain is None: - return False, "Client did not provide a certificate" + return False, "Client did not provide a certificate", peername if len(cert_chain) != 1: - return False, "Chocolate client should only include 1 cert" + return False, "Chocolate client should only include 1 cert", peername for i in range(0,cert_chain[0].get_ext_count()): ext = cert_chain[0].get_ext_at(i) @@ -87,11 +88,11 @@ def verify_challenge(address, r, nonce, socksify=False): valid = check_challenge_value(sni_support.get_unknown_value(ext.x509_ext), r) if valid: - return True, "Challenge completed successfully" + return True, "Challenge completed successfully", peername else: - return False, "Certificate extension does not check out" + return False, "Certificate extension does not check out", peername - return False, "Chocolate extension not included in certificate" + return False, "Chocolate extension not included in certificate", peername def main(): #Testing the example sni_challenge @@ -108,10 +109,10 @@ def main(): nonce = binascii.hexlify(nonce) nonce2 = binascii.hexlify(nonce2) - valid, response = verify_challenge("example.com", r, nonce) + valid, response, peername = verify_challenge("example.com", r, nonce) #valid, response = verify_challenge("127.0.0.1", r, nonce) print response - valid, response = verify_challenge("www.example.com", r2, nonce2) + valid, response, peername = verify_challenge("www.example.com", r2, nonce2) #valid, response = verify_challenge("localhost", r2, nonce2) print response if __name__ == "__main__": diff --git a/server-ca/testchallenge-daemon.py b/server-ca/testchallenge-daemon.py index 505dbd657..6221384fb 100755 --- a/server-ca/testchallenge-daemon.py +++ b/server-ca/testchallenge-daemon.py @@ -34,7 +34,7 @@ def testchallenge(session): # 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) + log("removing expired session", session) r.lrem("pending-requests", session) return if r.hget(session, "state") != "testchallenge": @@ -49,7 +49,7 @@ def testchallenge(session): 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) + log("testing challenge %s" % challenge, session) challtime = int(r.hget(challenge, "challtime")) challtype = int(r.hget(challenge, "type")) name = r.hget(challenge, "name") @@ -59,15 +59,14 @@ def testchallenge(session): 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 + log("\tbeginning dvsni test to %s" % name, session) 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) + direct_result, direct_reason, direct_peername = verify_challenge(name, dvsni_r, dvsni_nonce, False) + proxy_result, proxy_reason, proxy_peername = verify_challenge(name, dvsni_r, dvsni_nonce, True) + log("\t...direct probe: %s (%s) to %s" % (direct_result, direct_reason, direct_peername), session) + log("\tTor proxy probe: %s (%s)" % (proxy_result, proxy_reason), session) if direct_result and proxy_result: r.hset(challenge, "satisfied", True) else: @@ -80,7 +79,7 @@ def testchallenge(session): # Don't know how to handle this challenge type all_satisfied = False elif not satisfied: - if debug: print "\tchallenge was not attempted" + log("\tchallenge was not attempted", session) all_satisfied = False if all_satisfied: # Challenges all succeeded, so we should prepare to issue @@ -91,7 +90,7 @@ def testchallenge(session): # the daemon that put this session on the queue should # also have implicitly guaranteed this). if policy.payment_required(session): - if debug: print "\t** All challenges satisfied; request %s NEEDS PAYMENT" % short(session) + log("\t** All challenges satisfied; request NEEDS PAYMENT", session) # Try to get a unique abbreviated ID (10 hex digits) for i in xrange(20): abbreviation = random()[:10] @@ -110,7 +109,7 @@ def testchallenge(session): # instantaneously as soon as the payment system sends a "payments" # pubsub message to the payments daemon. else: - if debug: print "\t** All challenges satisfied; request %s GRANTED" % short(session) + log("\t** All challenges satisfied; request GRANTED", session) r.hset(session, "state", "issue") r.lpush("pending-issue", session) else: