Add the time we received and resolved a forwarding to `listforwards` #2528

cdecker · 2019-04-03T20:04:27Z

This adds a received_time timestamp to incoming HTLCs and adds both a received_time and resolved_timetimestamp to the channelforwarded_payments`. This allows us to see how long an HTLC was pending before it was resolved (with a granularity of seconds).

If desired we could probably change the granularity to milliseconds, but I wanted to try this first since #2491 only talks about an absolute time.

Fixes #2491

trueptolemy · 2019-04-04T07:07:13Z

wallet/wallet.c

@@ -2594,6 +2611,8 @@ const struct forwarding *wallet_forwarded_payments_get(struct wallet *w,

 		cur->channel_in.u64 = sqlite3_column_int64(stmt, 4);
 		cur->channel_out.u64 = sqlite3_column_int64(stmt, 5);
+		cur->received_time = sqlite3_column_int64(stmt, 6);
+		cur->resolved_time = sqlite3_column_int64(stmt, 7);


Hi! In the FORWARD_OFFERED case, we store resolved_time with NULL. There should handle this case.
BTW, may I ask you a question: what does FORWARD_OFFERED mean?

I'm trying to add local failcode #2524 , maybe I should add a new forward status: FORWARD_FAILED_LOCAL and also set resolved_time with NULL.

FORWARD_OFFERED means that the forward was received, and potentially forwarded, but wasn't resolved yet. The state machine looks like this:

FORWARD_OFFERED --------> FORWARD_SETTLED \----> FORWARD_FAILED

FORWARD_OFFERED therefore is the initial state for all forwards, while FORWARD_SETTLED and FORWARD_FAILED are the terminal states for those. Hence we only set the resolved_time once we reach a terminal state.

Thanks for your explain :)

m-schmoock

concept ACK

There could be a simple testcase that does a chained routing of i.e. 10 hops (so the processing takes a bit longer than a second):

After a payment the test could iterate through the chain and check that result of lxyz.rpc.listforwards() received_time and resolved_time is actually increasing or equal along the chain.
On an intentionally failed payment somewhere along the route received_time is increasing but 'resolved_time' is epxceted to be (question:) not a number ? (see @trueptolemy 's comment)
resolved_time should always >= received_time when status is settled
...

m-schmoock · 2019-04-04T09:13:56Z

Makefile

@@ -47,7 +47,7 @@ endif

 ifeq ($(COMPAT),1)
 # We support compatibility with pre-0.6.
-COMPAT_CFLAGS=-DCOMPAT_V052=1 -DCOMPAT_V060=1 -DCOMPAT_V061=1 -DCOMPAT_V062=1
+COMPAT_CFLAGS=-DCOMPAT_V052=1 -DCOMPAT_V060=1 -DCOMPAT_V061=1 -DCOMPAT_V062=1 -DCOMPAT_V070=1


Maybe I'm captain obvious, but the Makefile only sets these preprocessor variables if COMPAT is also 1. Currently, this causes a problem with Travis runner 3, where DCOMPAT_V070 is not defined at all: https://travis-ci.org/ElementsProject/lightning/jobs/515380339
Proposed solution (without being in the know of Travis internals and why it didnt fail for other COMPAT vairables):

ifeq ($(COMPAT),1) # We support compatibility with pre-0.6. COMPAT_CFLAGS=-DCOMPAT_V052=1 -DCOMPAT_V060=1 -DCOMPAT_V061=1 -DCOMPAT_V062=1 -DCOMPAT_V070=1 else COMPAT_CFLAGS=-DCOMPAT_V052=0 -DCOMPAT_V060=0 -DCOMPAT_V061=0 -DCOMPAT_V062=0 -DCOMPAT_V070=0 endif

Correct, I added a fixup using #ifdef :-)

m-schmoock · 2019-04-04T09:32:43Z

lightningd/peer_htlcs.c

@@ -1902,6 +1902,17 @@ static void listforwardings_add_forwardings(struct json_stream *response, struct
 				     cur->fee,
 				     "fee", "fee_msat");
 		json_add_string(response, "status", forward_status_name(cur->status));
+#if COMPAT_V070


Or change to, and do not set to 0 :D

#ifdef COMPAT_V070

cdecker · 2019-04-04T09:44:36Z

On an intentionally failed payment somewhere along the route received_time is increasing but 'resolved_time' is epxceted to be (question:) not a number ? (see @trueptolemy 's comment)

I added an if-statement that only adds resolved_time once it was actually resolved, not 0 :-)

m-schmoock · 2019-04-04T12:41:40Z

ACK 10d749a (but squash the fixups)

rustyrussell · 2019-04-05T22:18:57Z

nsec granularity please!

m-schmoock · 2019-04-06T08:35:59Z

nsec granularity please!

Yes, higher resolution would be better if we want to trace stuff in local test cases etc.
@rustyrussell Typo? milliseconds or nanoseconds?

rustyrussell · 2019-04-08T00:10:00Z

It's fairly easy to have sub-microsecond network latency between peers, so I'd think that micro or nanoseconds are necessary. If we store in a 64 bit value as nanoseconds since 1970, we don't get in any trouble for another 200+ years anyway (500+ if we allow unsigned). But it's up to the implementer.

rustyrussell

"Time is hard". We should probably display the JSON as two fields: start in seconds (ie. 6 or 9 decimal places), and duration in seconds. But time isn't stable, and can go backwards, especially across reboots. So using received and resolved times is probably clearest.

cdecker · 2019-04-08T19:30:12Z

Nanoseconds sounds excessive, but can do :-)

cdecker · 2019-04-10T13:47:32Z

If we store in a 64 bit value as nanoseconds since 1970, we don't get in any trouble for another 200+ years anyway (500+ if we allow unsigned). But it's up to the implementer.

We are storing as u64 anyway, so that's not an issue. Just felt trivial to use ts.tv_sec directly. I'll change this to use nsec then ^^

Signed-off-by: Christian Decker <[email protected]>

The timestamps are UNIX-Timestamps with 3 decimal places, even though we have the timestamp with nanosecond granularity. This is deliberate choice not to over overload the users :-) Signed-off-by: Christian Decker <[email protected]>

We'd like to display the receive and resolution times in the forwardings table. In order to remember the receive time we need to store it in the DB along with the other information. Signed-off-by: Christian Decker <[email protected]>

Signed-off-by: Christian Decker <[email protected]>

cdecker · 2019-04-10T18:00:55Z

Ok, rebased and squashed.

I also switched to storing the nsec timestamps in the DB (with some helpers) and display the timestamp with 3 significant digits in the JSON output.

Ping @rustyrussell and @m-schmoock 😉

kristapsk · 2019-04-10T18:14:03Z

This allows also calculate fees earned in a specific time period, like lncli feereport which has day_fee_sum, week_fee_sum, month_fee_sum, if I understand it correctly (didn't test myself).

cdecker · 2019-04-10T18:40:23Z

This allows also calculate fees earned in a specific time period, like lncli feereport which has day_fee_sum, week_fee_sum, month_fee_sum, if I understand it correctly (didn't test myself).

It should indeed, yes. Would you like to implement something like this? A neat little table channel x date_bucket seems like it could be nice.

kristapsk · 2019-04-10T19:40:12Z

Yes, I could. You mean like a built-in feature or as a plug-in?

A neat little table channel x date_bucket seems like it could be nice.

You mean like not only total fees collected but also fees collected per channel?

Btw I already have a shell script, that calculates summaries for fees collected per channel. But so far I only could get total fees, not the fees in a specific time period.

rustyrussell · 2019-04-10T23:46:13Z

BTW, our general philosophy should be to expose all the data, and let plugins sort it out. We have a few cases where we public summary data, and it's never quite the right thing, but we're committed to it for backwards compat reasons.

rustyrussell

Ack 6013e53

kristapsk · 2019-04-10T23:56:50Z

Doing it as a plugin was my first idea too and I will go that way unless somebody here tells me to do otherwise and integrate that functionality directly into C-lightning code.

cdecker added wallet json-rpc forwarding labels Apr 3, 2019

cdecker self-assigned this Apr 3, 2019

cdecker requested review from rustyrussell and m-schmoock April 3, 2019 20:04

trueptolemy reviewed Apr 4, 2019

View reviewed changes

m-schmoock approved these changes Apr 4, 2019

View reviewed changes

m-schmoock reviewed Apr 4, 2019

View reviewed changes

trueptolemy mentioned this pull request Apr 4, 2019

Store failcode of local forward failure into DB (completed) #2524

Merged

rustyrussell requested changes Apr 8, 2019

View reviewed changes

cdecker added 5 commits April 10, 2019 19:58

db: Add timestamp primitives so we can store them in the DB

2aa8dcc

Signed-off-by: Christian Decker <[email protected]>

wallet: Record the received_time and resolved_time for HTLCs

2c61a90

Signed-off-by: Christian Decker <[email protected]>

json-rpc: Include received and resolved time to listforward result

6013e53

Signed-off-by: Christian Decker <[email protected]>

cdecker force-pushed the issue-2491 branch from 2dc1f47 to 6013e53 Compare April 10, 2019 17:59

rustyrussell approved these changes Apr 10, 2019

View reviewed changes

rustyrussell merged commit 27afc80 into ElementsProject:master Apr 10, 2019

trueptolemy mentioned this pull request May 25, 2019

store timestamp in forwards #2434

Closed

kristapsk mentioned this pull request Jun 22, 2021

c-lightning: fix crash when resolved_time missing in forwards prusnak/suez#17

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add the time we received and resolved a forwarding to `listforwards` #2528

Add the time we received and resolved a forwarding to `listforwards` #2528

cdecker commented Apr 3, 2019

trueptolemy Apr 4, 2019

cdecker Apr 4, 2019 •

edited

Loading

trueptolemy Apr 4, 2019

m-schmoock left a comment

m-schmoock Apr 4, 2019

cdecker Apr 4, 2019

m-schmoock Apr 4, 2019

cdecker commented Apr 4, 2019

m-schmoock commented Apr 4, 2019

rustyrussell commented Apr 5, 2019

m-schmoock commented Apr 6, 2019

rustyrussell commented Apr 8, 2019

rustyrussell left a comment

cdecker commented Apr 8, 2019

cdecker commented Apr 10, 2019

cdecker commented Apr 10, 2019

kristapsk commented Apr 10, 2019

cdecker commented Apr 10, 2019

kristapsk commented Apr 10, 2019

rustyrussell commented Apr 10, 2019

rustyrussell left a comment

kristapsk commented Apr 10, 2019

Add the time we received and resolved a forwarding to listforwards #2528

Add the time we received and resolved a forwarding to listforwards #2528

Conversation

cdecker commented Apr 3, 2019

trueptolemy Apr 4, 2019

Choose a reason for hiding this comment

cdecker Apr 4, 2019 • edited Loading

Choose a reason for hiding this comment

trueptolemy Apr 4, 2019

Choose a reason for hiding this comment

m-schmoock left a comment

Choose a reason for hiding this comment

m-schmoock Apr 4, 2019

Choose a reason for hiding this comment

cdecker Apr 4, 2019

Choose a reason for hiding this comment

m-schmoock Apr 4, 2019

Choose a reason for hiding this comment

cdecker commented Apr 4, 2019

m-schmoock commented Apr 4, 2019

rustyrussell commented Apr 5, 2019

m-schmoock commented Apr 6, 2019

rustyrussell commented Apr 8, 2019

rustyrussell left a comment

Choose a reason for hiding this comment

cdecker commented Apr 8, 2019

cdecker commented Apr 10, 2019

cdecker commented Apr 10, 2019

kristapsk commented Apr 10, 2019

cdecker commented Apr 10, 2019

kristapsk commented Apr 10, 2019

rustyrussell commented Apr 10, 2019

rustyrussell left a comment

Choose a reason for hiding this comment

kristapsk commented Apr 10, 2019

Add the time we received and resolved a forwarding to `listforwards` #2528

Add the time we received and resolved a forwarding to `listforwards` #2528

cdecker Apr 4, 2019 •

edited

Loading