Skip to content

Commit

Permalink
plugins/pay: add paystatus command to get gory details of payments.
Browse files Browse the repository at this point in the history 
Signed-off-by: Rusty Russell <[email protected]>
  • Loading branch information
@rustyrussell @cdecker
rustyrussell authored and cdecker committed Jan 17, 2019
1 parent 5201c75 commit 3f8dd7a
Show file tree
Hide file tree
Showing 3 changed files with 241 additions and 32 deletions.
166 changes: 159 additions & 7 deletions plugins/pay.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@
#include <common/type_to_string.h>
#include <gossipd/gossip_constants.h>
#include <plugins/libplugin.h>
#include <stdio.h>

/* Public key of this node. */
static struct pubkey my_id;
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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);
}
Expand Down Expand Up @@ -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);
Expand All @@ -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);
Expand Down Expand Up @@ -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;
Expand All @@ -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
}
};

Expand Down
56 changes: 32 additions & 24 deletions tests/test_misc.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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')
Expand Down Expand Up @@ -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')
Expand All @@ -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)
Expand Down Expand Up @@ -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')
Expand Down
51 changes: 50 additions & 1 deletion tests/test_pay.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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:
Expand All @@ -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
Expand All @@ -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'],
Expand All @@ -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,
Expand All @@ -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]

0 comments on commit 3f8dd7a

Please sign in to comment.