Transactions in TCP FIN packets appear to be ignored #4432
Description
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)
tcpdump -i rl0 -p -w jun2014_bc_recv_1Bitcoin.pcap \(host 70.74.233.146 and port 8333\)
On Torchlight (sx client)
tcpdump -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
2014-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
2014-06-25 17:56:48 CreateNewBlock(): total size 170007
--note: no errors, libbitcoin line cut-off
sx sendtx log
james@torchlight:~/coinjoin$ sx sendtx-node blocked.tx casey.economicprisoner.com
DEBUG [network]: s: version (103 bytes)
DEBUG [network]: r: version (101 bytes)
DEBUG [network]: s: verack (0 bytes)
DEBUG [network]: r: verack (0 bytes)
sendtx: Sending 43f1c3e735560f7b1e4c396a55a2e62d2e83b7c4ed1efc5a7d29358c84ca7807
DEBUG [network]: s: tx (291 bytes)
sendtx: 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)
Bitcoind log:
2014-06-26 01:05:45 accepted connection 70.74.233.146:37540
2014-06-26 01:05:45 received: version (103 bytes)
2014-06-26 01:05:45 send version message: version 70002, blocks=307843, us=66.18
.211.158:8333, them=70.74.233.146:37540, peer=70.74.233.146:37540
2014-06-26 01:05:45 sending: version (101 bytes)
2014-06-26 01:05:45 sending: verack (0 bytes)
2014-06-26 01:05:45 receive version message: /libbitcoin:2.0.0/: version 60000,
blocks=0, us=10.0.0.1:8333, them=10.0.0.1:8333, peer=70.74.233.146:37540
2014-06-26 01:05:45 Added time data, samples 18, offset +0 (+0 minutes)
2014-06-26 01:05:45 received: verack (0 bytes)
2014-06-26 01:05:45 socket closed
2014-06-26 01:05:45 disconnecting node 70.74.233.146:37540
2014-06-26 01:05:46 received: ping (8 bytes)
2014-06-26 01:05:46 sending: pong (8 bytes)
2014-06-26 01:05:46 received: inv (37 bytes)
2014-06-26 01:05:46 got inventory: tx db59504348dcbb6e7c5be759e80e1120997461d7
aee06f774f980f26657b4a64 new
2014-06-26 01:05:46 askfor tx db59504348dcbb6e7c5be759e80e1120997461d7aee06f774f
980f26657b4a64 0 (00:00:00)
2014-06-26 01:05:46 sending getdata: tx db59504348dcbb6e7c5be759e80e1120997461d7
aee06f774f980f26657b4a64
2014-06-26 01:05:46 sending: getdata (37 bytes)
2014-06-26 01:05:46 received: inv (37 bytes)
2014-06-26 01:05:46 got inventory: tx db59504348dcbb6e7c5be759e80e1120997461d7
aee06f774f980f26657b4a64 new
2014-06-26 01:05:46 askfor tx db59504348dcbb6e7c5be759e80e1120997461d7aee06f774f
980f26657b4a64 1403744745000000 (01:05:45)
2014-06-26 01:05:46 received: inv (37 bytes)
2014-06-26 01:05:46 got inventory: tx db59504348dcbb6e7c5be759e80e1120997461d7
aee06f774f980f26657b4a64 new
2014-06-26 01:05:46 askfor tx db59504348dcbb6e7c5be759e80e1120997461d7aee06f774f
980f26657b4a64 1403744865000000 (01:07:45)
2014-06-26 01:05:47 received: tx (761 bytes)
2014-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!