gRPC python streaming calls to `SendPayment` and `SendToRoute` behaving weird when following documentation

ranchalp commented 5 years ago

Background

The lnd gRPC reference website does not show an example that works for for SendPayment and SendToRoute using python's gRPC. Consequently, there is no valid example. The tutorials are also not showing examples for streaming objects using python's RPC in the case of SendPayment and SendToRoute, while it is recommended to use the streaming functions rather than the sync ones. Seems to me as though the line that invokes yield [...] should suspend execution until called again(which would fix the whole thing), but it is not what happens in reality.

Your environment

version of lnd lnd version 0.5.1-beta commit=v0.5.1-beta
which operating system (uname -a on *Nix) Linux despatx 4.13.0-36-generic Ubuntu
version of btcd, bitcoind, or other backend btcd version 0.12.0-beta
any other relevant environment details protobuf (3.6.1) grpcio (1.16.1) grpcio-tools (1.16.1)

Steps to reproduce

Following the example, created the following code on a simnet with only 4 nodes and 3 channels: Alice-Bob-Charlie-Dave. The purpose is to test payments from Dave to Alice:

import codecs, grpc, os
import rpc_pb2 as ln, rpc_pb2_grpc as lnrpc
import constants
import string
import random
import datetime

# Due to updated ECDSA generated tls.cert we need to let gprc know that
# we need to use that cipher suite otherwise there will be a handhsake
# error when we communicate with the lnd rpc server.
os.environ["GRPC_SSL_CIPHER_SUITES"] = 'HIGH+ECDSA'

# Lnd cert is at ~/.lnd/tls.cert on Linux and
# ~/Library/Application Support/Lnd/tls.cert on Mac
cert = open(os.path.expanduser([...]), 'rb').read()
creds = grpc.ssl_channel_credentials(cert)
channel = grpc.secure_channel([DAVE_RPC], creds)
stub = lnrpc.LightningStub(channel)
# Lnd admin macaroon is at ~/.lnd/admin.macaroon on Linux and
# ~/Library/Application Support/Lnd/admin.macaroon on Mac
with open(os.path.expanduser([...]), 'rb') as f:
    macaroon_bytes = f.read()
    macaroon = codecs.encode(macaroon_bytes, 'hex')

def request_generator():
        # Initialization code here.
        dest=[ALICE_PUBKEY]
    payment_hash=[...]
        fee_limit = [...]
        # for i in range (0,100):
        while True:

            # Parameters here can be set as arguments to the generator.
            request = ln.SendRequest(
                dest_string=dest,
                amt=5000,
                payment_hash_string=payment_hash,
                fee_limit=fee_limit,
            )
            print "yielding i:",i,", hash:", payment_hash
            yield request
            # Do things between iterations here.
            # payment_hash=get_random_hash()
request_iterable = request_generator()

for i in range(0,10):
    print datetime.datetime.now(), "calling:"
    response =next(stub.SendPayment(request_iterable, metadata=[('macaroon', macaroon)]),None)
    print datetime.datetime.now(), "i:",i," response: ",response

Bear in mind that I changed for response in stub... for for i in range (0,10) and then making use of next in order to prevent an infinite loop. This code, while working, seems to call too many times to the generator for what I believe should be just one call per iteration in the for (see here).

If I, however, remove the while True, and just perform one call:

[...]
        # while True:
            # Parameters here can be set as arguments to the generator.
        request = ln.SendRequest(
            dest_string=dest,
            amt=5000,
            payment_hash_string=payment_hash,
            fee_limit=fee_limit,
        )
        print "yielding i:",i,", hash:", payment_hash
        yield request
    time.sleep(4*60)
[...]

the result is then incorrect:

>>> v={}; execfile('testing-streaming.py',v)
v={}; execfile('testing-streaming.py',v)
2018-12-14 16:15:50.477836 calling:
yielding i: 0 , hash: 256790603ab86bf61ab8c226dfe804eea3fe86325ca64f41a43712d385b2ac63
2018-12-14 16:15:50.480716 i: 0  response:  None
2018-12-14 16:15:50.480749 calling:
2018-12-14 16:15:50.482344 i: 1  response:  None
2018-12-14 16:15:50.482383 calling:
2018-12-14 16:15:50.483425 i: 2  response:  None
2018-12-14 16:15:50.483449 calling:
2018-12-14 16:15:50.484399 i: 3  response:  None
2018-12-14 16:15:50.484460 calling:
2018-12-14 16:15:50.486288 i: 4  response:  None
2018-12-14 16:15:50.486338 calling:
2018-12-14 16:15:50.486936 i: 5  response:  None
2018-12-14 16:15:50.486972 calling:
2018-12-14 16:15:50.490041 i: 6  response:  None
2018-12-14 16:15:50.490093 calling:
2018-12-14 16:15:50.490794 i: 7  response:  None
2018-12-14 16:15:50.490841 calling:
2018-12-14 16:15:50.491697 i: 8  response:  None
2018-12-14 16:15:50.491743 calling:
2018-12-14 16:15:50.492533 i: 9  response:  None

However, if I make this one call last longer by, for example, putting it to sleep for a few mins, then the result is correct (at least during the first call, but users typically only want to call once):

        # while True:
            # Parameters here can be set as arguments to the generator.
        request = ln.SendRequest(
            dest_string=dest,
            amt=5000,
            payment_hash_string=payment_hash,
            fee_limit=fee_limit,
        )
        print "yielding i:",i,", hash:", payment_hash
        yield request
    time.sleep(4*60)

result:

v={}; execfile('testing-streaming.py',v)
v={}; execfile('testing-streaming.py',v)
2018-12-14 16:20:09.129369 calling:
2018-12-14 16:20:09.582667 i: 0  response:  payment_error: "unable to route payment to destination: TemporaryChannelFailure(update=(*lnwire.ChannelUpdate)(0xc42330c0a0)({\n Signature: (lnwire.Sig) (len=64 cap=64) {\n  00000000  f6 fa 30 6a a2 8e 30 11  4c 51 3f 11 a8 2c ef 31  |..0j..0.LQ?..,.1|\n  00000010  dc 71 9d 4e b9 e3 ee 76  07 ba 25 08 99 24 5e 51  |.q.N...v..%..$^Q|\n  00000020  0d 5a f4 a3 df 98 2b 88  23 2d 50 e5 7c 37 e3 4d  |.Z....+.#-P.|7.M|\n  00000030  9c 2f 21 89 8a ed bb 89  3b 62 62 57 af 3f ec 58  |./!.....;bbW.?.X|\n },\n ChainHash: (chainhash.Hash) (len=32 cap=32) 683e86bd5c6d110d91b94b97137ba6bfe02dbbdb8e3dff722a669b5d69d77af6,\n ShortChannelID: (lnwire.ShortChannelID) 28610:1:0,\n Timestamp: (uint32) 1544799580,\n Flags: (lnwire.ChanUpdateFlag) 1,\n TimeLockDelta: (uint16) 144,\n HtlcMinimumMsat: (lnwire.MilliSatoshi) 1000 mSAT,\n BaseFee: (uint32) 1000,\n FeeRate: (uint32) 1,\n ExtraOpaqueData: ([]uint8) <nil>\n})\n)"

Seems like one needs to .lock() the request_iterable until response.running()==False, but it is not said anywhere throughout the tutorials and documentation. Why is yield called more than once per call to SendPayment? Also, why does time.sleep(4*60) (or lock()) have any impact on the outcome of the execution outside of it?. Why does the documentation have a While True: and for response instub.SendPayment(...)`?.

Actual behaviour

This is straight-forward in javascript with the on(...) methods, and the example for javascript shows it very well, but in python, either it is not as straight-forward, or it is not shown as straight-forward in the tutorial, or both (I personally do not know so I am currently just adding time.sleep(...) after yield to guaranteeing getting the proper value). As far as I know, yield should suspend, but it is not the case.

Roasbeef commented 5 years ago

I don't consider this an issue with lnd and more an issue with the dev site tutorials. As a result, I think this issue belongs at https://github.com/lightninglabs/lightning-dev-site. It may even be an issue with the library itself as well (or just the way it's using async I/O in python).

ranchalp commented 5 years ago

Perhaps I did not express properly. Even when not following the documentation, and using generators the only way they are supposed to be used in python (to the best of my knowledge), the code works. It might be a problem with python but it impacts in the usage of the gRPC. In any case, I found the dodgy workaround that I mentioned so until further notice I will use that.

lightningnetwork / lnd