diff --git a/plugins/pay.c b/plugins/pay.c index 85d209180..943734be0 100644 --- a/plugins/pay.c +++ b/plugins/pay.c @@ -7,6 +7,7 @@ #include #include #include +#include /* Public key of this node. */ static struct pubkey my_id; @@ -110,10 +111,23 @@ PRINTF_FMT(2,3) static void attempt_failed_fmt(struct pay_command *pc, const cha } static void attempt_failed_tok(struct pay_command *pc, const char *method, - const char *buf, const jsmntok_t *tok) + const char *buf, const jsmntok_t *errtok) { - attempt_failed_fmt(pc, "Call to %s gave error %.*s", - method, tok->end - tok->start, buf + tok->start); + const jsmntok_t *msg = json_get_member(buf, errtok, "message"); + + if (msg) + attempt_failed_fmt(pc, "%.*sCall to %s:%.*s", + msg->start - errtok->start, + buf + errtok->start, + method, + errtok->end - msg->start, + buf + msg->start); + else + attempt_failed_fmt(pc, + "{ 'message': 'Call to %s failed', %.*s", + method, + errtok->end - errtok->start - 1, + buf + errtok->start + 1); } static struct command_result *start_pay_attempt(struct command *cmd, @@ -146,12 +160,12 @@ static struct command_result *waitsendpay_expired(struct command *cmd, data = tal_strdup(pc, "'attempts': [ "); for (size_t i = 0; i < tal_count(pc->ps->attempts); i++) { if (pc->ps->attempts[i].route) - tal_append_fmt(&data, "%s { 'route': %s,\n 'failure': '%s'\n }", + tal_append_fmt(&data, "%s { 'route': %s,\n 'failure': %s\n }", i == 0 ? "" : ",", pc->ps->attempts[i].route, pc->ps->attempts[i].failure); else - tal_append_fmt(&data, "%s { 'failure': '%s'\n }", + tal_append_fmt(&data, "%s { 'failure': %s\n }", i == 0 ? "" : ",", pc->ps->attempts[i].failure); } @@ -358,7 +372,7 @@ static struct command_result *getroute_done(struct command *cmd, feepercent = ((double)fee) * 100.0 / ((double) pc->msatoshi); if (fee > pc->exemptfee && feepercent > pc->maxfeepercent) { - attempt_failed_fmt(pc, "Route wanted fee of %"PRIu64" msatoshis", fee); + attempt_failed_fmt(pc, "{ 'message': 'Route wanted fee of %"PRIu64" msatoshis' }", fee); if (tal_count(pc->routehints) != 0) return next_routehint(cmd, pc); @@ -369,7 +383,7 @@ static struct command_result *getroute_done(struct command *cmd, } if (delay > pc->maxdelay) { - attempt_failed_fmt(pc, "Route wanted delay %u blocks", delay); + attempt_failed_fmt(pc, "{ 'message': 'Route wanted delay %u blocks' }", delay); if (tal_count(pc->routehints) != 0) return next_routehint(cmd, pc); @@ -764,6 +778,139 @@ static struct command_result *handle_pay(struct command *cmd, " "); } +/* FIXME: Add this to ccan/time? */ +#define UTC_TIMELEN (sizeof("YYYY-mm-ddTHH:MM:SS.nnnZ")) +static void utc_timestring(const struct timeabs *time, char str[UTC_TIMELEN]) +{ + char iso8601_msec_fmt[sizeof("YYYY-mm-ddTHH:MM:SS.%03dZ")]; + + strftime(iso8601_msec_fmt, sizeof(iso8601_msec_fmt), "%FT%T.%%03dZ", + gmtime(&time->ts.tv_sec)); + snprintf(str, UTC_TIMELEN, iso8601_msec_fmt, + (int) time->ts.tv_nsec / 1000000); +} + +static void add_attempt(char **ret, + const struct pay_status *ps, + const struct pay_attempt *attempt) +{ + char timestr[UTC_TIMELEN]; + + utc_timestring(&attempt->start, timestr); + + tal_append_fmt(ret, "{ 'start_time': '%s'," + " 'age_in_seconds': %"PRIu64, + timestr, + time_to_sec(time_between(time_now(), attempt->start))); + if (attempt->result || attempt->failure) { + utc_timestring(&attempt->end, timestr); + tal_append_fmt(ret, ", 'end_time': '%s'" + ", 'duration_in_seconds': %"PRIu64, + timestr, + time_to_sec(time_between(attempt->end, + attempt->start))); + } + if (tal_count(attempt->routehint)) { + tal_append_fmt(ret, ", 'routehint': ["); + for (size_t i = 0; i < tal_count(attempt->routehint); i++) { + tal_append_fmt(ret, "%s{" + " 'id': '%s'," + " 'channel': '%s'," + " 'msatoshi': %"PRIu64"," + " 'delay': %u }", + i == 0 ? "" : ", ", + type_to_string(tmpctx, struct pubkey, + &attempt->routehint[i].pubkey), + type_to_string(tmpctx, + struct short_channel_id, + &attempt->routehint[i].short_channel_id), + route_msatoshi(ps->msatoshi, + attempt->routehint + i, + tal_count(attempt->routehint) - i), + route_cltv(ps->final_cltv, + attempt->routehint + i, + tal_count(attempt->routehint) - i)); + } + tal_append_fmt(ret, "]"); + } + if (tal_count(attempt->excludes)) { + for (size_t i = 0; i < tal_count(attempt->excludes); i++) { + if (i == 0) + tal_append_fmt(ret, ", 'excluded_channels': ["); + else + tal_append_fmt(ret, ", "); + tal_append_fmt(ret, "'%s'", attempt->excludes[i]); + } + tal_append_fmt(ret, "]"); + } + + if (attempt->route) + tal_append_fmt(ret, ", 'route': %s", attempt->route); + + if (attempt->failure) + tal_append_fmt(ret, ", 'failure': %s", attempt->failure); + + if (attempt->result) + tal_append_fmt(ret, ", 'success': %s", attempt->result); + + tal_append_fmt(ret, "}"); +} + +static struct command_result *handle_paystatus(struct command *cmd, + const char *buf, + const jsmntok_t *params) +{ + struct pay_status *ps; + const char *b11str; + char *ret; + bool some = false; + + if (!param(cmd, buf, params, + p_opt("bolt11", param_string, &b11str), + NULL)) + return NULL; + + ret = tal_fmt(cmd, "{ 'pay': ["); + /* FIXME: Index by bolt11 string! */ + list_for_each(&pay_status, ps, list) { + if (b11str && !streq(b11str, ps->bolt11)) + continue; + + if (some) + tal_append_fmt(&ret, ",\n"); + some = true; + + tal_append_fmt(&ret, "{ 'bolt11': '%s'," + " 'msatoshi': %"PRIu64", " + " 'destination': '%s'", + ps->bolt11, ps->msatoshi, ps->dest); + if (ps->desc) + tal_append_fmt(&ret, ", 'description': '%s'", ps->desc); + if (ps->routehint_modifications) + tal_append_fmt(&ret, ", 'routehint_modifications': '%s'", + ps->routehint_modifications); + if (ps->shadow && !streq(ps->shadow, "")) + tal_append_fmt(&ret, ", 'shadow': '%s'", ps->shadow); + if (ps->exclusions) + tal_append_fmt(&ret, ", 'local_exclusions': '%s'", + ps->exclusions); + + assert(tal_count(ps->attempts)); + for (size_t i = 0; i < tal_count(ps->attempts); i++) { + if (i == 0) + tal_append_fmt(&ret, ", 'attempts': ["); + else + tal_append_fmt(&ret, ","); + + add_attempt(&ret, ps, &ps->attempts[i]); + } + tal_append_fmt(&ret, "] }"); + } + tal_append_fmt(&ret, "] }"); + + return command_success(cmd, ret); +} + static void init(struct plugin_conn *rpc) { const char *field; @@ -783,6 +930,11 @@ static const struct plugin_command commands[] = { { "Send payment specified by {bolt11} with {msatoshi}", "Try to send a payment, retrying {retry_for} seconds before giving up", handle_pay + }, { + "paystatus", + "Detail status of attempts to pay {bolt11}, or all", + "Covers both old payments and current ones.", + handle_paystatus } }; diff --git a/tests/test_misc.py b/tests/test_misc.py index d63039f48..ccae4fd89 100644 --- a/tests/test_misc.py +++ b/tests/test_misc.py @@ -234,12 +234,17 @@ def test_htlc_out_timeout(node_factory, bitcoind, executor): l1.daemon.wait_for_log('dev_disconnect: @WIRE_REVOKE_AND_ACK') # Takes 6 blocks to timeout (cltv-final + 1), but we also give grace period of 1 block. - # FIXME: shadow route can add extra blocks! 50% chance of adding 6... - bitcoind.generate_block(5 + 1 + 60 + 1) - # bitcoind.generate_block(5 + 1) - # time.sleep(3) - # assert not l1.daemon.is_in_log('hit deadline') - # bitcoind.generate_block(1) + # shadow route can add extra blocks! + status = only_one(l1.rpc.call('paystatus')['pay']) + if 'shadow' in status: + shadowlen = 6 * status['shadow'].count('Added 6 cltv delay for shadow') + else: + shadowlen = 0 + + bitcoind.generate_block(5 + 1 + shadowlen) + time.sleep(3) + assert not l1.daemon.is_in_log('hit deadline') + bitcoind.generate_block(1) l1.daemon.wait_for_log('Offered HTLC 0 SENT_ADD_ACK_REVOCATION cltv .* hit deadline') l1.daemon.wait_for_log('sendrawtx exit 0') @@ -296,12 +301,15 @@ def test_htlc_in_timeout(node_factory, bitcoind, executor): l1.daemon.wait_for_log('dev_disconnect: -WIRE_REVOKE_AND_ACK') # Deadline HTLC expiry minus 1/2 cltv-expiry delta (rounded up) (== cltv - 3). cltv is 5+1. - # FIXME: shadow route can add extra blocks! 50% chance of adding 6... - shadowlen = 60 - bitcoind.generate_block(2 + shadowlen + 1) - #bitcoind.generate_block(2) - #assert not l2.daemon.is_in_log('hit deadline') - #bitcoind.generate_block(1) + # shadow route can add extra blocks! + status = only_one(l1.rpc.call('paystatus')['pay']) + if 'shadow' in status: + shadowlen = 6 * status['shadow'].count('Added 6 cltv delay for shadow') + else: + shadowlen = 0 + bitcoind.generate_block(2 + shadowlen) + assert not l2.daemon.is_in_log('hit deadline') + bitcoind.generate_block(1) l2.daemon.wait_for_log('Fulfilled HTLC 0 SENT_REMOVE_COMMIT cltv .* hit deadline') l2.daemon.wait_for_log('sendrawtx exit 0') @@ -310,14 +318,13 @@ def test_htlc_in_timeout(node_factory, bitcoind, executor): l1.daemon.wait_for_log(' to ONCHAIN') # L2 will collect HTLC (iff no shadow route) - if shadowlen == 0: - l2.daemon.wait_for_log('Propose handling OUR_UNILATERAL/THEIR_HTLC by OUR_HTLC_SUCCESS_TX .* after 0 blocks') - l2.daemon.wait_for_log('sendrawtx exit 0') - bitcoind.generate_block(1) - l2.daemon.wait_for_log('Propose handling OUR_HTLC_SUCCESS_TX/DELAYED_OUTPUT_TO_US by OUR_DELAYED_RETURN_TO_WALLET .* after 5 blocks') - bitcoind.generate_block(4) - l2.daemon.wait_for_log('Broadcasting OUR_DELAYED_RETURN_TO_WALLET') - l2.daemon.wait_for_log('sendrawtx exit 0') + l2.daemon.wait_for_log('Propose handling OUR_UNILATERAL/THEIR_HTLC by OUR_HTLC_SUCCESS_TX .* after 0 blocks') + l2.daemon.wait_for_log('sendrawtx exit 0') + bitcoind.generate_block(1) + l2.daemon.wait_for_log('Propose handling OUR_HTLC_SUCCESS_TX/DELAYED_OUTPUT_TO_US by OUR_DELAYED_RETURN_TO_WALLET .* after 5 blocks') + bitcoind.generate_block(4) + l2.daemon.wait_for_log('Broadcasting OUR_DELAYED_RETURN_TO_WALLET') + l2.daemon.wait_for_log('sendrawtx exit 0') # Now, 100 blocks it should be both done. bitcoind.generate_block(100) @@ -916,11 +923,12 @@ def test_htlc_send_timeout(node_factory, bitcoind): PAY_ROUTE_NOT_FOUND = 205 assert err.error['code'] == PAY_ROUTE_NOT_FOUND - # FIXME: get payment status. + status = only_one(l1.rpc.call('paystatus')['pay']) + # Temporary channel failure - # assert only_one(err.error['data']['failures'])['failcode'] == 0x1007 - # assert only_one(err.error['data']['failures'])['erring_node'] == l2.info['id'] - # assert only_one(err.error['data']['failures'])['erring_channel'] == chanid2 + assert status['attempts'][0]['failure']['data']['failcode'] == 0x1007 + assert status['attempts'][0]['failure']['data']['erring_node'] == l2.info['id'] + assert status['attempts'][0]['failure']['data']['erring_channel'] == chanid2 # L2 should send ping, but never receive pong so never send commitment. l2.daemon.wait_for_log(r'channeld.*:\[OUT\] 0012') diff --git a/tests/test_pay.py b/tests/test_pay.py index 83e4524ba..87ff61936 100644 --- a/tests/test_pay.py +++ b/tests/test_pay.py @@ -1231,7 +1231,25 @@ def test_pay_routeboost(node_factory, bitcoind): assert only_one(only_one(l1.rpc.decodepay(inv['bolt11'])['routes'])) # Now we should be able to pay it. + start = time.time() l1.rpc.pay(inv['bolt11']) + end = time.time() + + # Status should show all the gory details. + status = l1.rpc.call('paystatus', [inv['bolt11']]) + assert only_one(status['pay'])['bolt11'] == inv['bolt11'] + assert only_one(status['pay'])['msatoshi'] == 10**5 + assert only_one(status['pay'])['destination'] == l4.info['id'] + assert 'description' not in only_one(status['pay']) + assert 'routehint_modifications' not in only_one(status['pay']) + assert 'local_exclusions' not in only_one(status['pay']) + attempt = only_one(only_one(status['pay'])['attempts']) + assert attempt['age_in_seconds'] <= time.time() - start + assert attempt['duration_in_seconds'] <= end - start + assert only_one(attempt['routehint']) + assert only_one(attempt['routehint'])['id'] == l3.info['id'] + assert only_one(attempt['routehint'])['msatoshi'] == 10**5 + 1 + 10**5 // 100000 + assert only_one(attempt['routehint'])['delay'] == 5 + 6 # With dev-route option we can test longer routehints. if DEVELOPER: @@ -1252,6 +1270,10 @@ def test_pay_routeboost(node_factory, bitcoind): 'description': 'test_pay_routeboost2', 'dev-routes': [routel3l4l5]}) l1.rpc.pay(inv['bolt11']) + status = l1.rpc.call('paystatus', [inv['bolt11']]) + assert len(only_one(status['pay'])['attempts']) == 1 + assert 'failure' not in only_one(status['pay'])['attempts'][0] + assert 'success' in only_one(status['pay'])['attempts'][0] # Now test that it falls back correctly to not using routeboost # if it can't route to the node mentioned @@ -1265,6 +1287,15 @@ def test_pay_routeboost(node_factory, bitcoind): 'description': 'test_pay_routeboost3', 'dev-routes': [routel4l3]}) l1.rpc.pay(inv['bolt11']) + status = l1.rpc.call('paystatus', [inv['bolt11']]) + assert len(only_one(status['pay'])['attempts']) == 2 + assert 'failure' in only_one(status['pay'])['attempts'][0] + assert 'success' not in only_one(status['pay'])['attempts'][0] + routehint = only_one(status['pay'])['attempts'][0]['routehint'] + assert [h['channel'] for h in routehint] == [r['short_channel_id'] for r in routel4l3] + assert 'failure' not in only_one(status['pay'])['attempts'][1] + assert 'success' in only_one(status['pay'])['attempts'][1] + assert 'routehint' not in only_one(status['pay'])['attempts'][1] # Similarly if it can route, but payment fails. routel2bad = [{'id': l2.info['id'], @@ -1282,6 +1313,7 @@ def test_pay_routeboost(node_factory, bitcoind): # (Note, this is not public because it's not 6 deep) l3.rpc.connect(l5.info['id'], 'localhost', l5.port) scid35 = l3.fund_channel(l5, 10**6) + l4.stop() routel3l5 = [{'id': l3.info['id'], 'short_channel_id': scid35, 'fee_base_msat': 1000, @@ -1291,4 +1323,21 @@ def test_pay_routeboost(node_factory, bitcoind): 'label': 'test_pay_routeboost5', 'description': 'test_pay_routeboost5', 'dev-routes': [routel3l4l5, routel3l5]}) - l1.rpc.pay(inv['bolt11']) + l1.rpc.pay(inv['bolt11'], description="paying test_pay_routeboost5") + + status = l1.rpc.call('paystatus', [inv['bolt11']]) + assert only_one(status['pay'])['bolt11'] == inv['bolt11'] + assert only_one(status['pay'])['msatoshi'] == 10**5 + assert only_one(status['pay'])['destination'] == l5.info['id'] + assert only_one(status['pay'])['description'] == "paying test_pay_routeboost5" + assert 'routehint_modifications' not in only_one(status['pay']) + assert 'local_exclusions' not in only_one(status['pay']) + attempts = only_one(status['pay'])['attempts'] + + # First failed, second succeeded. + assert len(attempts) == 2 + assert 'success' not in attempts[0] + assert 'success' in attempts[1] + + assert [h['channel'] for h in attempts[0]['routehint']] == [r['short_channel_id'] for r in routel3l4l5] + assert [h['channel'] for h in attempts[1]['routehint']] == [r['short_channel_id'] for r in routel3l5]