tests/test_lightningd.py: incorporate everything from old test-basic shell test.

This moves all the non-legacy blackbox testing into python.

Before:
	real	10m18.385s

After:
	real	9m54.877s

Note that this doesn't valgrind the subdaemons: that patch seems to cause
some issues in the python framework which I am still chasing.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

Makefile

@@ -234,10 +234,7 @@ $(HELPER_OBJS) $(CORE_OBJS) $(CORE_TX_OBJS) $(CORE_PROTOBUF_OBJS) $(BITCOIN_OBJS
 test-protocol: test/test_protocol
 	set -e; TMP=`mktemp`; for f in test/commits/*.script; do if ! $(VALGRIND) test/test_protocol < $$f > $$TMP; then echo "test/test_protocol < $$f FAILED" >&2; exit 1; fi; diff -u $$TMP $$f.expected; done; rm $$TMP
 
-# FIXME: check doesn't depend on lightningd-blackbox-tests, since they
-# can't run in parallel with daemon blackbox tests.
 check: test-protocol
-	$(MAKE) lightningd-blackbox-tests
 	$(MAKE) pytest
 
 pytest: daemon/lightningd daemon/lightning-cli lightningd-all

lightningd/pay.c

@@ -59,8 +59,11 @@ void payment_succeeded(struct lightningd *ld, struct htlc_end *dst,
 		       const struct preimage *rval)
 {
 	/* FIXME: dev_htlc will do this! */
-	if (!dst->pay_command)
+	if (!dst->pay_command) {
+		log_debug(ld->log, "Payment succeeded on HTLC %"PRIu64,
+			dst->htlc_id);
 		return;
+	}
 
 	assert(!dst->pay_command->rval);
 	dst->pay_command->rval = tal_dup(dst->pay_command,

lightningd/test/Makefile

@@ -14,25 +14,5 @@ $(LIGHTNINGD_TEST_OBJS): $(LIGHTNINGD_HEADERS) $(LIGHTNINGD_SRC) $(LIGHTNINGD_LI
 
 lightningd/tests: $(LIGHTNINGD_TEST_PROGRAMS:%=unittest/%)
 
-# So far, only basic test.
-lightningd-test-0-basic: lightningd-test-setup-0
-
-lightningd-test-0-%:
-	NO_VALGRIND=$(NO_VALGRIND) VG_TRACE_CHILDREN="--trace-children=yes" VARIANT=0 lightningd/test/test-$*
-
-# We shutdown first in case something is left over.
-lightningd-test-setup-%: lightningd-all daemon/lightning-cli
-	VARIANT=$* daemon/test/scripts/shutdown.sh 2>/dev/null || true
-	VARIANT=$* daemon/test/scripts/setup.sh
-
-lightningd-test-shutdown-0: lightningd-test-0-basic
-	VARIANT=0 daemon/test/scripts/shutdown.sh
-lightningd-test-shutdown-1: lightningd-test-1-basic\ --restart
-	VARIANT=1 daemon/test/scripts/shutdown.sh
-lightningd-test-shutdown-2: lightningd-test-2-basic\ --reconnect
-	VARIANT=2 daemon/test/scripts/shutdown.sh
-
-lightningd-blackbox-tests: lightningd-test-shutdown-0 #lightningd-test-shutdown-1 lightningd-test-shutdown-2
-
 check-source-bolt: $(LIGHTNINGD_TEST_SRC:%=bolt-check/%)
 check-whitespace: $(LIGHTNINGD_TEST_SRC:%=check-whitespace/%)

lightningd/test/test-basic

@@ -1,123 +0,0 @@
-#! /bin/sh -e
-
-# Wherever we are, we want to be in daemon/test dir.
-cd `git rev-parse --show-toplevel`/daemon/test
-
-. scripts/vars.sh
-. scripts/helpers.sh
-
-parse_cmdline 2 "$@"
-setup_lightning 2
-
-start_lightningd 2 lightningd/lightningd
-
-if lcli1 connect localhost $PORT2 $ID1; then
-    echo Connected OK with wrong ID? >&2
-    exit 1
-fi
-
-lcli1 connect localhost $PORT2 $ID2
-
-# Should now be exchanging gossip
-lcli1 getpeers | $FGREP '"condition" : "Exchanging gossip"'
-
-# It should have gone through these steps
-lcli1 getpeers info | $FGREP "Starting handshake as initiator"
-lcli1 getpeers info | $FGREP "Beginning gossip"
-lcli1 getpeers info | $FGREP "Exchanging gossip"
-
-# Both should still be owned by gossip
-lcli1 getpeers | $FGREP '"owner" : "lightningd_gossip"'
-lcli2 getpeers | $FGREP '"owner" : "lightningd_gossip"'
-
-# Add some funds.
-NEWADDR=`lcli1 newaddr | get_field address`
-FUND_INPUT_TXID=`$CLI sendtoaddress $NEWADDR 0.10000002`
-FUND_INPUT_TX=`$CLI getrawtransaction $FUND_INPUT_TXID`
-
-lcli1 addfunds $FUND_INPUT_TX | $FGREP '"satoshis" : 10000002'
-
-# Now fund a channel.
-lcli1 fundchannel $ID2 1000000
-
-# Now wait for it to reach depth
-lcli1 getpeers info | $FGREP "Waiting for our funding tx"
-[ `lcli1 getpeers | get_field msatoshi_to_us` = 1000000000 ]
-[ `lcli1 getpeers | get_field msatoshi_to_them` = 0 ]
-[ `lcli2 getpeers | get_field msatoshi_to_them` = 1000000000 ]
-[ `lcli2 getpeers | get_field msatoshi_to_us` = 0 ]
-
-$CLI generate 10
-check "lcli1 getpeers info | $FGREP 'Funding tx reached depth'"
-check "lcli2 getpeers info | $FGREP 'Funding tx reached depth'"
-
-check "lcli1 getpeers | tr -s '\012\011\" ' ' ' | $FGREP 'condition : Normal operation'"
-check "lcli2 getpeers | tr -s '\012\011\" ' ' ' | $FGREP 'condition : Normal operation'"
-
-SECRET=1de08917a61cb2b62ed5937d38577f6a7bfe59c176781c6d8128018e8b5ccdfd
-RHASH=`lcli1 dev-rhash $SECRET | sed 's/.*"\([0-9a-f]*\)".*/\1/'`
-
-# This is actually dust
-lcli1 dev-newhtlc $ID2 100000 $(( $(blockheight) + 10 )) $RHASH
-check "lcli1 getlog debug | $FGREP 'Sending commit_sig with 0 htlc sigs'"
-
-check "lcli2 getlog debug | $FGREP 'their htlc 0 locked'"
-check "lcli2 getpeers info | $FGREP 'failed htlc 0 code 0x400f'"
-check "lcli1 getpeers info | $FGREP 'htlc 0 failed with code 0x400f'"
-
-# This one isn't dust.
-RHASH=`lcli2 invoice 100000000 testpayment1 | get_field rhash`
-[ `lcli2 listinvoice testpayment1 | get_field complete` = false ]
-
-lcli1 dev-newhtlc $ID2 100000000 $(( $(blockheight) + 10 )) $RHASH
-check "lcli1 getlog debug | $FGREP 'Sending commit_sig with 1 htlc sigs'"
-
-check "lcli2 getlog debug | $FGREP 'Resolving invoice '\'testpayment1\'' with HTLC 1'"
-[ `lcli2 listinvoice testpayment1 | get_field complete` = true ]
-
-check "lcli1 getpeers | get_field msatoshi_to_us | $FGREP -w 900000000"
-[ `lcli1 getpeers | get_field msatoshi_to_us` = 900000000 ]
-[ `lcli1 getpeers | get_field msatoshi_to_them` = 100000000 ]
-[ `lcli2 getpeers | get_field msatoshi_to_them` = 900000000 ]
-[ `lcli2 getpeers | get_field msatoshi_to_us` = 100000000 ]
-
-RHASH=`lcli2 invoice 200000000 testpayment2 | get_field rhash`
-[ `lcli2 listinvoice testpayment2 | get_field complete` = false ]
-
-# Not enough delay.
-if lcli1 sendpay '[ { "msatoshi" : 200000000, "id" : "'$ID2'", "delay" : 3 } ]' $RHASH; then
-    echo Infufficient delay succeeded? >&2
-fi
-
-# Insufficient funds.
-if lcli1 sendpay '[ { "msatoshi" : 199999999, "id" : "'$ID2'", "delay" : 5 } ]' $RHASH; then
-    echo Infufficient funds succeeded? >&2
-fi
-
-# Bad ID.
-if lcli1 sendpay '[ { "msatoshi" : 200000000,, "id" : "'$ID2'", "delay" : 5 } ]' 00000000000000000000000000000000; then
-    echo Bad ID succeeded? >&2
-fi
-
-# This works
-lcli1 sendpay '[ { "msatoshi" : 200000000, "id" : "'$ID2'", "delay" : 5 } ]' $RHASH
-[ `lcli2 listinvoice testpayment2 | get_field complete` = true ]
-
-# This will "succeed", but won't actually send anything (duplicate)
-if lcli1 getlog debug | $FGREP 'json_sendpay: found previous... succeeded'; then
-    echo Already had found previous? >&2
-    exit 1
-fi
-lcli1 sendpay '[ { "msatoshi" : 200000000, "id" : "'$ID2'", "delay" : 5 } ]' $RHASH
-lcli1 getlog debug | $FGREP 'json_sendpay: found previous... succeeded'
-
-# FIXME: test paying via another node, should fail to pay twice.
-
-# Overpay.
-RHASH=`lcli2 invoice 200000000 testpayment3 | get_field rhash`
-lcli1 sendpay '[ { "msatoshi" : 200000001, "id" : "'$ID2'", "delay" : 5 } ]' $RHASH
-
-lcli1 stop
-lcli2 stop
-
-all_ok

tests/test_lightningd.py

@@ -3,6 +3,8 @@ from concurrent import futures
 from hashlib import sha256
 from lightning import LightningRpc, LegacyLightningRpc
 
+import copy
+import json
 import logging
 import os
 import sys
@@ -19,6 +21,8 @@ if os.getenv("TEST_DEBUG", None) != None:
     logging.basicConfig(level=logging.DEBUG, stream=sys.stdout)
 logging.info("Tests running in '%s'", TEST_DIR)
 
+def to_json(arg):
+    return json.loads(json.dumps(arg))
 
 def setupBitcoind():
     global bitcoind
@@ -138,12 +142,112 @@ class LightningDTests(BaseLightningDTests):
     def test_connect(self):
         l1,l2 = self.connect()
 
-        p1 = l1.rpc.getpeer(l2.info['id'])
+        p1 = l1.rpc.getpeer(l2.info['id'], 'info')
-        p2 = l2.rpc.getpeer(l1.info['id'])
+        p2 = l2.rpc.getpeer(l1.info['id'], 'info')
 
         assert p1['condition'] == 'Exchanging gossip'
         assert p2['condition'] == 'Exchanging gossip'
 
+        # It should have gone through these steps
+        assert 'condition: Starting handshake as initiator' in p1['log']
+        assert 'condition: Beginning gossip' in p1['log']
+        assert 'condition: Exchanging gossip' in p1['log']
+
+        # Both should still be owned by gossip
+        assert p1['owner'] == 'lightningd_gossip'
+        assert p2['owner'] == 'lightningd_gossip'
+
+    def test_htlc(self):
+        l1,l2 = self.connect()
+
+        self.fund_channel(l1, l2, 10**6)
+        l1.daemon.wait_for_log('condition: Funding tx reached depth 6')
+        l2.daemon.wait_for_log('condition: Funding tx reached depth 6')
+
+        secret = '1de08917a61cb2b62ed5937d38577f6a7bfe59c176781c6d8128018e8b5ccdfd'
+        rhash = l1.rpc.dev_rhash(secret)['rhash']
+
+        # This is actually dust, and uncalled for.
+        l1.rpc.dev_newhtlc(l2.info['id'], 100000, l1.bitcoin.rpc.getblockcount() + 10, rhash)
+        l1.daemon.wait_for_log('Sending commit_sig with 0 htlc sigs')
+        l2.daemon.wait_for_log('their htlc 0 locked')
+        l2.daemon.wait_for_log('failed htlc 0 code 0x400f')
+        l1.daemon.wait_for_log('htlc 0 failed with code 0x400f')
+
+        # Set up invoice (non-dust, just to test), and pay it.
+        # This one isn't dust.
+        rhash = l2.rpc.invoice(100000000, 'testpayment1')['rhash']
+        assert l2.rpc.listinvoice('testpayment1')[0]['complete'] == False
+
+        l1.rpc.dev_newhtlc(l2.info['id'], 100000000, l1.bitcoin.rpc.getblockcount() + 10, rhash)
+        l1.daemon.wait_for_log('Sending commit_sig with 1 htlc sigs')
+        l2.daemon.wait_for_log('their htlc 1 locked')
+        l2.daemon.wait_for_log("Resolving invoice 'testpayment1' with HTLC 1")
+        assert l2.rpc.listinvoice('testpayment1')[0]['complete'] == True
+        l1.daemon.wait_for_log('Payment succeeded on HTLC 1')
+
+        # Balances should have changed.
+        p1 = l1.rpc.getpeer(l2.info['id'])
+        p2 = l2.rpc.getpeer(l1.info['id'])
+        assert p1['msatoshi_to_us'] == 900000000
+        assert p1['msatoshi_to_them'] == 100000000
+        assert p2['msatoshi_to_us'] == 100000000
+        assert p2['msatoshi_to_them'] == 900000000
+        
+    def test_sendpay(self):
+        l1,l2 = self.connect()
+
+        self.fund_channel(l1, l2, 10**6)
+
+        amt = 200000000
+        rhash = l2.rpc.invoice(amt, 'testpayment2')['rhash']
+        assert l2.rpc.listinvoice('testpayment2')[0]['complete'] == False
+
+        routestep = { 'msatoshi' : amt, 'id' : l2.info['id'], 'delay' : 5}
+
+        # Insufficient funds.
+        rs = copy.deepcopy(routestep)
+        rs['msatoshi'] = rs['msatoshi'] - 1
+        self.assertRaises(ValueError, l1.rpc.sendpay, to_json([rs]), rhash)
+        assert l2.rpc.listinvoice('testpayment2')[0]['complete'] == False
+
+        # Gross overpayment (more than factor of 2)
+        rs = copy.deepcopy(routestep)
+        rs['msatoshi'] = rs['msatoshi'] * 2 + 1
+        self.assertRaises(ValueError, l1.rpc.sendpay, to_json([rs]), rhash)
+        assert l2.rpc.listinvoice('testpayment2')[0]['complete'] == False
+        
+        # Insufficient delay.
+        rs = copy.deepcopy(routestep)
+        rs['delay'] = rs['delay'] - 2
+        self.assertRaises(ValueError, l1.rpc.sendpay, to_json([rs]), rhash)
+        assert l2.rpc.listinvoice('testpayment2')[0]['complete'] == False
+
+        # Bad ID.
+        rs = copy.deepcopy(routestep)
+        rs['id'] = '00000000000000000000000000000000'
+        self.assertRaises(ValueError, l1.rpc.sendpay, to_json([rs]), rhash)
+        assert l2.rpc.listinvoice('testpayment2')[0]['complete'] == False
+
+        # This works.
+        l1.rpc.sendpay(to_json([routestep]), rhash)
+        assert l2.rpc.listinvoice('testpayment2')[0]['complete'] == True
+        
+        # Repeat will "succeed", but won't actually send anything (duplicate)
+        assert not l1.daemon.is_in_log('... succeeded')
+        l1.rpc.sendpay(to_json([routestep]), rhash)
+        l1.daemon.wait_for_log('... succeeded')
+        assert l2.rpc.listinvoice('testpayment2')[0]['complete'] == True
+
+        # Overpaying by "only" a factor of 2 succeeds.
+        rhash = l2.rpc.invoice(amt, 'testpayment3')['rhash']
+        assert l2.rpc.listinvoice('testpayment3')[0]['complete'] == False
+        routestep = { 'msatoshi' : amt * 2, 'id' : l2.info['id'], 'delay' : 5}
+        l1.rpc.sendpay(to_json([routestep]), rhash)
+        assert l2.rpc.listinvoice('testpayment3')[0]['complete'] == True
+
+        # FIXME: test paying via another node, should fail to pay twice.
+
     def test_gossip_jsonrpc(self):
         l1,l2 = self.connect()
 

tests/utils.py

@@ -74,7 +74,19 @@ class TailableProc(object):
                 logging.debug("%s: %s", self.prefix, line.decode().rstrip())
                 self.logs_cond.notifyAll()
         self.running = False
-    
+
+    def is_in_log(self, regex):
+        """Look for `regex` in the logs."""
+
+        ex = re.compile(regex)
+        for l in self.logs:
+            if ex.search(l):
+                logging.debug("Found '%s' in logs", regex)
+                return True
+
+        logging.debug("Did not find '%s' in logs", regex)
+        return False
+
     def wait_for_log(self, regex, offset=1000, timeout=60):
         """Look for `regex` in the logs.