implement ping

[conanoc]

• 현재 dev-ping 만 구현되어 있음. lightningd/dev_ping.c 참고.
• spec: https://github.com/lightningnetwork/lightning-rfc/blob/master/01-messaging.md#control-messages
• pong 은 구현되어 있고 분석 필요. WIRE_PONG 사용되는 곳: channel.c, gossip.c, connect.c

[conanoc]

WIP: f0264b0

위 커밋 적용하고 로그를 보면 아래와 같음.

• 상대 peer는 1분 단위로 ping을 보내고 있음. 아마도 LND.
• 30초 단위로 ping timer가 fire되지만 maybe_send_ping() 에서 ping 메시지는 보내지 않음. peer_recently_active()가 true이기 때문인데, 원인은 빈번한 channel_update 때문임. LND에서 30초 단위로 channel_update를 보내고 있는듯함.

2018-08-14T09:24:55.967Z lightningd(84049): lightning_channeld-02c77326b69065901942aae6a19939d8428065071da0b2504c3d40504275e4b43c chan #5: ping timer fired!
2018-08-14T09:24:57.848Z lightning_gossipd(84069): Received channel_update for channel 1297420:79:1(1) now ACTIVE was ACTIVE (from subdaemon)
2018-08-14T09:24:57.852Z lightning_gossipd(84069): Received channel_update for channel 1296054:26:0(1) now ACTIVE was ACTIVE (from subdaemon)
2018-08-14T09:24:57.853Z lightning_gossipd(84069): Received channel_update for channel 1383215:1590:0(0) now ACTIVE was ACTIVE (from subdaemon)
2018-08-14T09:25:25.926Z lightning_gossipd(84069): got ping from remote ======
2018-08-14T09:25:25.970Z lightningd(84049): lightning_channeld-02c77326b69065901942aae6a19939d8428065071da0b2504c3d40504275e4b43c chan #5: ping timer fired!
2018-08-14T09:25:27.820Z lightning_gossipd(84069): Received channel_update for channel 1346741:10:1(1) now DISABLED was ACTIVE (from subdaemon)
2018-08-14T09:25:27.820Z lightning_gossipd(84069): Received channel_update for channel 1296054:26:0(1) now ACTIVE was ACTIVE (from subdaemon)
2018-08-14T09:25:27.822Z lightning_gossipd(84069): Received channel_update for channel 1297420:79:1(1) now ACTIVE was ACTIVE (from subdaemon)
2018-08-14T09:25:55.970Z lightningd(84049): lightning_channeld-02c77326b69065901942aae6a19939d8428065071da0b2504c3d40504275e4b43c chan #5: ping timer fired!
2018-08-14T09:25:57.819Z lightning_gossipd(84069): Received channel_update for channel 1297420:79:1(1) now ACTIVE was ACTIVE (from subdaemon)
2018-08-14T09:25:57.823Z lightning_gossipd(84069): Received channel_update for channel 1381513:3257:0(1) now ACTIVE was ACTIVE (from subdaemon)
2018-08-14T09:25:57.824Z lightning_gossipd(84069): Received channel_update for channel 1296054:26:0(1) now ACTIVE was ACTIVE (from subdaemon)
2018-08-14T09:26:25.944Z lightning_gossipd(84069): got ping from remote ======
2018-08-14T09:26:25.973Z lightningd(84049): lightning_channeld-02c77326b69065901942aae6a19939d8428065071da0b2504c3d40504275e4b43c chan #5: ping timer fired!
2018-08-14T09:26:27.818Z lightning_gossipd(84069): Received channel_update for channel 1297420:79:1(1) now ACTIVE was ACTIVE (from subdaemon)
2018-08-14T09:26:27.823Z lightning_gossipd(84069): Received channel_update for channel 1296054:26:0(1) now ACTIVE was ACTIVE (from subdaemon)
2018-08-14T09:26:27.823Z lightning_gossipd(84069): Received channel_update for channel 1346741:10:1(1) now DISABLED was DISABLED (from subdaemon)
2018-08-14T09:26:55.973Z lightningd(84049): lightning_channeld-02c77326b69065901942aae6a19939d8428065071da0b2504c3d40504275e4b43c chan #5: ping timer fired!
2018-08-14T09:26:57.818Z lightning_gossipd(84069): Received channel_update for channel 1297420:79:1(1) now ACTIVE was ACTIVE (from subdaemon)
2018-08-14T09:26:57.818Z lightning_gossipd(84069): Received channel_update for channel 1296054:26:0(1) now ACTIVE was ACTIVE (from subdaemon)

아래는 임시로 peer_recently_active() 체크 안한 경우의 로그:

2018-08-14T09:37:29.780Z lightningd(89238): lightning_channeld-02c77326b69065901942aae6a19939d8428065071da0b2504c3d40504275e4b43c chan #5: ping timer fired!
2018-08-14T09:37:29.965Z lightningd(89238): lightning_channeld-02c77326b69065901942aae6a19939d8428065071da0b2504c3d40504275e4b43c chan #5: got expected pong~~
2018-08-14T09:37:57.820Z lightning_gossipd(89256): Received channel_update for channel 1297420:79:1(1) now ACTIVE was ACTIVE (from subdaemon)
2018-08-14T09:37:57.821Z lightning_gossipd(89256): Received channel_update for channel 1296054:26:0(1) now ACTIVE was ACTIVE (from subdaemon)
2018-08-14T09:37:59.970Z lightningd(89238): lightning_channeld-02c77326b69065901942aae6a19939d8428065071da0b2504c3d40504275e4b43c chan #5: ping timer fired!
2018-08-14T09:38:00.159Z lightningd(89238): lightning_channeld-02c77326b69065901942aae6a19939d8428065071da0b2504c3d40504275e4b43c chan #5: got expected pong~~
2018-08-14T09:38:27.821Z lightning_gossipd(89256): Received channel_update for channel 1296054:26:0(1) now ACTIVE was ACTIVE (from subdaemon)
2018-08-14T09:38:27.825Z lightning_gossipd(89256): Received channel_update for channel 1297420:79:1(1) now ACTIVE was ACTIVE (from subdaemon)
2018-08-14T09:38:27.828Z lightning_gossipd(89256): Received channel_update for channel 1346741:10:1(1) now ACTIVE was ACTIVE (from subdaemon)
2018-08-14T09:38:29.275Z lightning_gossipd(89256): got ping from remote ======
2018-08-14T09:38:30.159Z lightningd(89238): lightning_channeld-02c77326b69065901942aae6a19939d8428065071da0b2504c3d40504275e4b43c chan #5: ping timer fired!
2018-08-14T09:38:30.341Z lightningd(89238): lightning_channeld-02c77326b69065901942aae6a19939d8428065071da0b2504c3d40504275e4b43c chan #5: got expected pong~~
2018-08-14T09:38:57.820Z lightning_gossipd(89256): Received channel_update for channel 1297420:79:1(1) now ACTIVE was ACTIVE (from subdaemon)
2018-08-14T09:38:57.826Z lightning_gossipd(89256): Received channel_update for channel 1296054:26:0(1) now ACTIVE was ACTIVE (from subdaemon)
2018-08-14T09:39:00.345Z lightningd(89238): lightning_channeld-02c77326b69065901942aae6a19939d8428065071da0b2504c3d40504275e4b43c chan #5: ping timer fired!
2018-08-14T09:39:00.533Z lightningd(89238): lightning_channeld-02c77326b69065901942aae6a19939d8428065071da0b2504c3d40504275e4b43c chan #5: got expected pong~~

[conanoc]

PING을 받았을때 30초 이내에 PING이 있었던 경우에 대한 체크는 구현되어 있지 않음. spec 상으로는 아래와 같이 되어 있음.

A node receiving a ping message:

• SHOULD fail the channels if it has received significantly in excess of one ping per 30 seconds.

어느 정도가 "significantly in excess of one ping per 30 seconds" 인지 불분명함. LND에게 30초 이내에 여러번 ping을 보내도 문제는 없는듯함.