1. 
   phillipsjk commented at 6:46 pm on June 27, 2014: none

   Problem description:

   On June 21, sending transaction 43f1c3e735560f7b1e4c396a55a2e62d2e83b7c4ed1efc5a7d29358c84ca7807 using “sx sendtx-node” to my bitcoin node running Bitcoind 0.9.1 0.9.2 failed. The log showed the connection, but no errors (default log level) Update: enabling ’net’ debuging also showed no errors (included below) The transaction was considered valid by both “sx validtx” and my bitcoin node when I used bitcoin-cli to send it manually. I came up with 3 possibilities: 1. bug in sx sendtx 2. bug in Bitcoind 3. ISP using DPI to selectively block transactions (but allow initial connection) Update: It appears that option 3 is out (not that it was ever likely) (packet capture: Linked in the first comment.)

   Edit: Bitcoin reported version: “version” : 90100 Package: bitcoin-daemon-0.9.1; FreeBSD 9.2-RELEASE-p3 Sx reported version: ??? “/libbitcoin:2.0.0/: version 60000” pulled from log below.

   Experimental design:

   My plan is to run tcpdump on both hosts while I try to resend the transaction. If the transaction is truly being blocked, it won’t matter that it was sent already. If it goes through, bitcoind should log it as a duplicate.

   Because my Bitcoin node has many connections, I will want to filter as many packets as possible. Because the computer with the sx tools also has several network connections, a similar filter should be used to capture only Bicoin-related packets.

   TCPdump options:

   On Casey (Bitcoin node)

   0tcpdump -i rl0 -p -w jun2014_bc_recv_1Bitcoin.pcap \(host 70.74.233.146 and port 8333\)
   

   On Torchlight (sx client)

   0tcpdump -i eth1 -p -w jun2014_sx_send_1Bitcoin.pcap \(host 66.18.211.158 and port 8333\)
   

   Logs:

   Approximate end-time: Wed Jun 25 11:57:04 MDT 2014

   Bitcoind log

   02014-06-25 17:56:47 receive version message: /libbitcoin:2.0.0/: version 60000, blocks=0, us=10.0.0.1:8333, them=10.0.0.1:8333, pee8
   12014-06-25 17:56:48 CreateNewBlock(): total size 170007
   

   –note: no errors, libbitcoin line cut-off

   sx sendtx log

   0james@torchlight:~/coinjoin$ sx sendtx-node blocked.tx casey.economicprisoner.com
   1DEBUG [network]: s: version (103 bytes)
   2DEBUG [network]: r: version (101 bytes)
   3DEBUG [network]: s: verack (0 bytes)
   4DEBUG [network]: r: verack (0 bytes)
   5sendtx: Sending 43f1c3e735560f7b1e4c396a55a2e62d2e83b7c4ed1efc5a7d29358c84ca7807
   6DEBUG [network]: s: tx (291 bytes)
   7sendtx: Sent 1403719007
   

   Repeated test with more bitcoind debuging:

   Approx start time: Wed Jun 25 19:05:32 MDT 2014

   Approx interesting time: 2014-06-26 01:05:45 accepted connection 70.74.233.146:37540

   Approx end time: Wed Jun 25 19:05:55 MDT 2014

   (trimmed a bit)

    0Bitcoind log:
    12014-06-26 01:05:45 accepted connection 70.74.233.146:37540
    22014-06-26 01:05:45 received: version (103 bytes)
    32014-06-26 01:05:45 send version message: version 70002, blocks=307843, us=66.18
    4.211.158:8333, them=70.74.233.146:37540, peer=70.74.233.146:37540
    52014-06-26 01:05:45 sending: version (101 bytes)
    62014-06-26 01:05:45 sending: verack (0 bytes)
    72014-06-26 01:05:45 receive version message: /libbitcoin:2.0.0/: version 60000,
    8blocks=0, us=10.0.0.1:8333, them=10.0.0.1:8333, peer=70.74.233.146:37540
    92014-06-26 01:05:45 Added time data, samples 18, offset +0 (+0 minutes)
   102014-06-26 01:05:45 received: verack (0 bytes)
   112014-06-26 01:05:45 socket closed
   122014-06-26 01:05:45 disconnecting node 70.74.233.146:37540
   132014-06-26 01:05:46 received: ping (8 bytes)
   142014-06-26 01:05:46 sending: pong (8 bytes)
   152014-06-26 01:05:46 received: inv (37 bytes)
   162014-06-26 01:05:46   got inventory: tx db59504348dcbb6e7c5be759e80e1120997461d7
   17aee06f774f980f26657b4a64  new
   182014-06-26 01:05:46 askfor tx db59504348dcbb6e7c5be759e80e1120997461d7aee06f774f
   19980f26657b4a64   0 (00:00:00)
   202014-06-26 01:05:46 sending getdata: tx db59504348dcbb6e7c5be759e80e1120997461d7
   21aee06f774f980f26657b4a64
   222014-06-26 01:05:46 sending: getdata (37 bytes)
   232014-06-26 01:05:46 received: inv (37 bytes)
   242014-06-26 01:05:46   got inventory: tx db59504348dcbb6e7c5be759e80e1120997461d7
   25aee06f774f980f26657b4a64  new
   262014-06-26 01:05:46 askfor tx db59504348dcbb6e7c5be759e80e1120997461d7aee06f774f
   27980f26657b4a64   1403744745000000 (01:05:45)
   282014-06-26 01:05:46 received: inv (37 bytes)
   292014-06-26 01:05:46   got inventory: tx db59504348dcbb6e7c5be759e80e1120997461d7
   30aee06f774f980f26657b4a64  new
   312014-06-26 01:05:46 askfor tx db59504348dcbb6e7c5be759e80e1120997461d7aee06f774f
   32980f26657b4a64   1403744865000000 (01:07:45)
   332014-06-26 01:05:47 received: tx (761 bytes)
   342014-06-26 01:05:47 received: inv (37 bytes)
   

   Note the size of the first received tx does not match the tx under test (761 bytes > 291 bytes) Edit: finally found the comment edit button!

2. 
   phillipsjk commented at 6:50 pm on June 27, 2014: none

   Screen-shot (nearly 300kB) actual capture is less than 2kB.

   Edit: Packet capture files:

   Receive first transaction (casey): http://phillipsjk.ca/bin/jun2014_bc_recv_1Bitcoin.pcap Send first transaction (torchlight): http://phillipsjk.ca/bin/jun2014_sx_send_1Bitcoin.pcap Receive second transation (casey): http://phillipsjk.ca/bin/jun2014_bc_recv_1ExAmpLE.pcap Send second transaction (torchlight): http://phillipsjk.ca/bin/jun2014_sx_send_1ExAmpLE.pcap Bonus: Sending invalid version of second transaction (torchlight) http://phillipsjk.ca/bin/jun2014_sx_send_1ExAmpLEf.pcap

3. phillipsjk renamed this:
   Transactions is TCP FIN packets appear to be ignored
   Transactions in TCP FIN packets appear to be ignored
   on Jun 27, 2014
4. 
   phillipsjk commented at 10:14 pm on June 29, 2014: none

   Second investigation

   The last report involved re-sending the transaction, even after it was buried in the block-chain. For this report, I will send a new transaction with debugging turned up, and recording the bytes on the wire. That way, I eliminate the possibility that the behavior changes with subsequent sends.

   Note that this appears to be a regression: I had successfully sent a similar transaction approximately one month ago. Unfortunately, during that time, I have upgraded both Bitcoind (from 0.8.6) and the sx tools. My maintenance logs are spotty, though I do try to actually make a habit of taking notes. Maybe I can find version hints in automated logs.

   TCPdump options

   Same as above, with new filenames.

   sx sendtx-node log

   0james@torchlight:~/coinjoin$ sx sendtx-node signed.tx casey.economicprisoner.com
   1DEBUG [network]: s: version (103 bytes)
   2DEBUG [network]: r: version (101 bytes)
   3DEBUG [network]: s: verack (0 bytes)
   4DEBUG [network]: r: verack (0 bytes)
   5sendtx: Sending 183675b1ed865e35dbc874491bde63b62bbad9c9ad1c5794a307c2f1c8f8ef58
   6DEBUG [network]: s: tx (224 bytes)
   7sendtx: Sent 1403993724
   8james@torchlight:~/coinjoin$ sx sendtx-bci signed.tx
   9Transaction Submitted
   

   bitcoind log

   Approximate start-time: Sat Jun 28 16:15:21 MDT 2014

   Approximate interesting time: 2014-06-28 22:15:24 accepted connection 70.74.233.146:40870

   Approximate stop time: Sat Jun 28 16:15:32 MDT 2014

   bitcoin-cli

   After sx sendtx-node:

   0$ bitcoin-cli -datadir=/home/bitcoin -conf=/home/bitcoin/bitcoin.conf \
   1> getrawtransaction "183675b1ed865e35dbc874491bde63b62bbad9c9ad1c5794a307c2f1c8f8ef58"
   2error: {"code":-5,"message":"No information available about transaction"}
   

   After sx sendtx-bci (sends to blockchain.info web interface):

   0$ bitcoin-cli -datadir=/home/bitcoin -conf=/home/bitcoin/bitcoin.conf \
   1> getrawtransaction "183675b1ed865e35dbc874491bde63b62bbad9c9ad1c5794a307c2f1c8f8ef58"
   201000000010778ca848c35297d5afc1eedc4b7832e2de6a2556a394c1e7b0f5635e7c3f143010000008b48304502205e07002585d30b19f912a6c0fe5b6e1413c92e
   3ed314f8ebce6ed887eba42fc16022100f998c06b4aff381c9d78cd7a30a575d3893c7f02efa1bd073725efccfe6e868b014104c3620767bd6e3fa7329939b02010ef
   421c78e2b06bc7c6c7e7d6bff0c381b5517367a0bbd8887ce0554a0a7f5489780069518b3bfb3c48b48c185f145e5f66f0cffffffff0140787d01000000001976a914
   5a33727db1cde4b2af394c15baa770bbc545dc14b88ac00000000
   

   bitcoind log

    02014-06-28 22:15:24 accepted connection 70.74.233.146:40870
    12014-06-28 22:15:24 sending: inv (73 bytes)
    22014-06-28 22:15:24 received: version (103 bytes)
    32014-06-28 22:15:24 send version message: version 70002, blocks=308370, us=66.18.211.158:8333, them=70.74.233.146:40870, peer=70.74.
    4233.146:40870
    52014-06-28 22:15:24 sending: version (101 bytes)
    62014-06-28 22:15:24 sending: verack (0 bytes)
    72014-06-28 22:15:24 receive version message: /libbitcoin:2.0.0/: version 60000, blocks=0, us=10.0.0.1:8333, them=10.0.0.1:8333, peer
    8=70.74.233.146:40870
    92014-06-28 22:15:24 received: inv (73 bytes)
   102014-06-28 22:15:24   got inventory: tx 2de80bd43e4e0e8a605dc58b1c6c3100972e3b0bbfbc3690e4a6a8702924faa2  have
   112014-06-28 22:15:24   got inventory: tx 527aa3f1bee6cdd168547dde87c9ef8e3b9549b1cf429045efa6a4b7083a1b9f  new
   122014-06-28 22:15:24 askfor tx 527aa3f1bee6cdd168547dde87c9ef8e3b9549b1cf429045efa6a4b7083a1b9f   0 (00:00:00)
   132014-06-28 22:15:24 sending getdata: tx 527aa3f1bee6cdd168547dde87c9ef8e3b9549b1cf429045efa6a4b7083a1b9f
   142014-06-28 22:15:24 sending: getdata (37 bytes)
   152014-06-28 22:15:24 received: verack (0 bytes)
   162014-06-28 22:15:24 socket closed
   172014-06-28 22:15:24 disconnecting node 70.74.233.146:40870
   182014-06-28 22:15:24 received: inv (37 bytes)
   192014-06-28 22:15:24   got inventory: tx 527aa3f1bee6cdd168547dde87c9ef8e3b9549b1cf429045efa6a4b7083a1b9f  new
   202014-06-28 22:15:24 askfor tx 527aa3f1bee6cdd168547dde87c9ef8e3b9549b1cf429045efa6a4b7083a1b9f   1403993723000000 (22:15:23)
   212014-06-28 22:15:24 sending: inv (37 bytes)
   222014-06-28 22:15:24 sending: inv (73 bytes)
   232014-06-28 22:15:24 received: inv (37 bytes)
   242014-06-28 22:15:24   got inventory: tx 527aa3f1bee6cdd168547dde87c9ef8e3b9549b1cf429045efa6a4b7083a1b9f  new
   252014-06-28 22:15:24 askfor tx 527aa3f1bee6cdd168547dde87c9ef8e3b9549b1cf429045efa6a4b7083a1b9f   1403993843000000 (22:17:23)
   262014-06-28 22:15:24 received: tx (4541 bytes)
   

   Note: first received tx after connection from torchlight is again the wrong size (4541 > 224 bytes)

5. phillipsjk closed this on Jun 29, 2014

   ---

6. phillipsjk reopened this on Jun 29, 2014

   ---

7. laanwj added the label P2P on Jul 28, 2014
8. laanwj added the label Bug on Jul 28, 2014
9. laanwj added the label Priority Medium on Jul 28, 2014
10. 
    kazcw commented at 6:27 pm on July 28, 2014: contributor

    I’m not sure this is a bitcoind bug. It looks like bitcoind would discard a message if ThreadSocketHandler reads a close and sets fDisconnect before ProcessMessages has read the message, but closing right after a send can cause the data to be discarded at the TCP level anyway; why add guarantees at the application level the transport level won’t reliably uphold?

    Sx needs to ensure the tx has been received before closing the connection, by e.g. send tx -> send ping -> wait for pong -> close.

11. 
    phillipsjk commented at 0:25 am on July 29, 2014: none

    This is the first I heard that the TCP layer will discard data in a FIN packet.

    I Tried searching for “TCP discards data in fin packet” and came up with this as a result: http://stackoverflow.com/questions/8702646/packet-capture-can-a-packet-with-the-fin-flag-also-have-data

    The only answer listed there is that RFC 739 says it is allowed. I believe that RFC also says that stateful fire-walling is not a thing either, so YMMV. (That was the IP RFC)

12. 
    kazcw commented at 0:41 am on July 29, 2014: contributor

    TCP stacks that implement half-duplex close (notably, Linux’s) may discard unread data when close() is called [http://www.freesoft.org/CIE/RFC/1122/99.htm].
13. 
    phillipsjk commented at 1:21 am on July 29, 2014: none

    If the close at the TCP level happens before the data of the FIN packet is processed, that is a bug.

    In your bug report against sx tools you mention that the Bitcoind node may want to send more information to the client. That is still possible with a half-open connection, but not if the client’s stack did a half-duplex close as described in the link.

    According to that link, data is only aggressively discarded after seeing a RST packet.

14. 
    kazcw commented at 1:37 am on July 29, 2014: contributor

    The RST packet is sent by the host discarding data to indicate that data has been discarded.

    We could be careful not to call close() with any unread data, and to continue processing certain messages even after fDisconnect is set (or delay setting fDisconnect). Those would probably be positive changes, because they’d prevent losing a tx sent by a terminating node every once in a while.

    Such a behavior change would not really affect what one-shot clients like sx would need to do, assuming they’ll want to support existing versions of bitcoind. Even if everyone running bitcoind upgraded to a new version compatible with push-and-run, sx should use the ping approach to see if the tx has been rejected.

15. 
    kazcw commented at 1:44 am on July 29, 2014: contributor

    After looking at it some more, I don’t think we’re calling close() when there could be pending data in this case; the lost messages due to disconnect must just be due to the fDisconnect check in ProcessMessages.
16. 
    laanwj commented at 6:37 am on July 29, 2014: member

    With TCP, close() should not result in loss of information. You can close the connection immediately after sending data, and the other end will be able receive all the data. This is because of states such as CLOSE_WAIT, in which a connection lingers as ‘zombie’ for a while making sure that everything was sent.

    Otherwise, HTTP servers (for ex.) would have to keep open the connection to wait whether the client has got everything. This is luckily handled by the OS.

    So my guess is that there is some bug/race in bitcoind here.

17. 
    kazcw commented at 7:08 am on July 29, 2014: contributor

    I think there’s a fDisconnect race where: 1: ThreadSocketHandler pushes data into vRecvMsg 2a: ProcessMessages checks vRecvMsg, or aborts if fDisconnect 2b: the other end closes the socket, so ThreadSocketHandler reads 0 bytes and sets fDisconnect

    Either 2a or 2b can happen first; if 2b is first, messages not yet processed will be discarded. This race has probably been overlooked because there is no point in handling many messages from a node that is shutting down and there’s only a limited window at the end of a connection when messages would be lost, but some should still be handled (addr, tx, block, alert, reject).

18. 
    sipa commented at 6:05 pm on January 23, 2017: member

    @theuni Is this fixed since #9441?
19. 
    theuni commented at 8:35 pm on January 23, 2017: member

    @sipa No, as I’m not sure what behavior would be considered “fixed” here.

    We obviously don’t process an arbitrarily long message queue after a node has disconnected, but it makes sense to guarantee some depth, to allow for use-cases like nodes that would like to connect, push a tx, and disconnect.

    So.. maybe process a single message after remote disconnect?

20. laanwj removed the label Priority Medium on Apr 25, 2017
21. 
    phillipsjk commented at 1:11 pm on July 17, 2017: none

    What I was expecting was that the data in the last packet would processed. In the absence of jumbo frames or fragmentation, this would be generally limited to 1460 bytes.

Contributors
phillipsjk kazcw laanwj sipa theuni

Labels
Bug P2P