v16.0 transactions with provided work not processing correctly #1181
Comments
|
@PlasmaPower Can you bisect this ? |
|
It may be due to #832 but that was merged before V16 |
|
Should be fixed with #1560 Please reopen if issue persists after 18.0 release |
|
I am having the same issue has described above. Steps to reproduce the issue:
Describe the results you received: Note: No completed RPC log was found. Describe the results you expected: Additional information you deem important (e.g. issue happens only occasionally): I also have confirmed with Dotcom and mitche50 that they are experiencing the same issue on their node setups. |
|
@silverstar194 is sideband upgrade completed? (store_version 13 in RPC version) |
|
Yes, the complete messages were logged. @SergiySW |
|
@SergiySW Yes looks like it. Must have double checked wrong transaction when writing |
Description of bug:
When processing a send or receive with provided work, transactions are taking longer than expected.
Steps to reproduce the issue:
Describe the results you received:
Generating the Send RPC command:
[2018-09-12 20:05:38.890604]: 0x7ee510132ad0 {"destination": "XXX", "work": "XXX", "amount": "XXX", "source": "XXX", "wallet": "XXX", "action": "send", "id": "XXX"}
Send RPC command processed, over 2.5 minutes later
[2018-09-12 20:08:09.727416]: RPC request 0x7ee510132ad0 completed in: 150836888 microseconds
Describe the results you expected:
A send RPC command with provided work should be processed immediately
Additional information you deem important (e.g. issue happens only occasionally):
This only happens with v16.0. I have tested on the same node with v15.2 and v16.0 and v15.2 works as expected.
Environment:
Production Nano Twitter Tip Bot
Digital Ocean droplet - docker node v16.0
uname -a "Linux nanotipbot.com 4.4.0-134-generic #160-Ubuntu SMP Wed Aug 15 14:58:00 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux"
logs
[2018-09-12 20:05:38.890604]: 0x7ee510132ad0 {"destination": "xrb_1u3bya9eiyk7f3me8wnamo7tskiramyk61gagt9ojndfiwn9pwwp41m74k5c", "work": "88fa9d6a9528eaa3", "amount": "1000000000000000000000000000000", "source": "xrb_164a8pzjypa3yhbro4i8orzbg867itmujf5it18xu9e6wefp3mbe13949dm6", "wallet": "XXX", "action": "send", "id": "tip-10399682952466063370"}
[2018-09-12 20:05:40.774385]: Found a representative at [::ffff:193.31.24.222]:7075
[2018-09-12 20:05:44.369012]: Found a representative at [::ffff:181.49.94.157]:49234
[2018-09-12 20:05:49.096226]: Found a representative at [::ffff:13.115.243.152]:33436
[2018-09-12 20:05:58.140015]: Found a representative at [::ffff:88.111.139.1]:3049
[2018-09-12 20:05:58.140359]: Found a representative at [::ffff:104.131.38.127]:7075
[2018-09-12 20:05:58.356930]: Found a representative at [::ffff:206.189.18.189]:3755
[2018-09-12 20:06:00.809696]: Found a representative at [::ffff:139.59.255.136]:7075
[2018-09-12 20:06:01.745823]: 0x7ee514146330 {"action":"version"}
[2018-09-12 20:06:01.746605]: RPC request 0x7ee514146330 completed in: 836 microseconds
[2018-09-12 20:06:02.142245]: 0x7ee520408610 {"action":"version"}
[2018-09-12 20:06:02.142406]: RPC request 0x7ee520408610 completed in: 205 microseconds
[2018-09-12 20:06:03.121804]: 0x7ee514017f00 {"action":"block_count"}
[2018-09-12 20:06:03.121978]: RPC request 0x7ee514017f00 completed in: 223 microseconds
[2018-09-12 20:06:03.204868]: 0x7ee520408610 {"action":"peers"}
[2018-09-12 20:06:03.213021]: RPC request 0x7ee520408610 completed in: 8199 microseconds
[2018-09-12 20:06:03.215041]: 0x7ee520037b60 {"action":"account_balance","account":"xrb_17wmwpg65neuh8u84f99e6nxcf48znusb437efwaafta7rtpy4n9h6io79xj"}
[2018-09-12 20:06:03.215799]: RPC request 0x7ee520037b60 completed in: 826 microseconds
[2018-09-12 20:06:03.217242]: 0x7ee520408610 {"action":"account_info","account":"xrb_17wmwpg65neuh8u84f99e6nxcf48znusb437efwaafta7rtpy4n9h6io79xj","representative":"true","weight":"true"}
[2018-09-12 20:06:03.218314]: RPC request 0x7ee520408610 completed in: 1135 microseconds
[2018-09-12 20:06:03.220711]: 0x7ee51411b340 {"action":"account_weight","account":"xrb_17wmwpg65neuh8u84f99e6nxcf48znusb437efwaafta7rtpy4n9h6io79xj"}
[2018-09-12 20:06:03.220847]: RPC request 0x7ee51411b340 completed in: 174 microseconds
[2018-09-12 20:06:03.470713]: 0x7ee520408610 {"action":"block_count"}
[2018-09-12 20:06:03.471714]: RPC request 0x7ee520408610 completed in: 1095 microseconds
[2018-09-12 20:06:03.550623]: 0x7ee51429c780 {"action":"peers"}
[2018-09-12 20:06:03.558610]: RPC request 0x7ee51429c780 completed in: 8035 microseconds
[2018-09-12 20:06:03.563509]: 0x7ee510146330 {"action":"account_balance","account":"xrb_17wmwpg65neuh8u84f99e6nxcf48znusb437efwaafta7rtpy4n9h6io79xj"}
[2018-09-12 20:06:03.563686]: RPC request 0x7ee510146330 completed in: 217 microseconds
[2018-09-12 20:06:03.566231]: 0x7ee5182364e0 {"action":"account_info","account":"xrb_17wmwpg65neuh8u84f99e6nxcf48znusb437efwaafta7rtpy4n9h6io79xj","representative":"true","weight":"true"}
[2018-09-12 20:06:03.566428]: RPC request 0x7ee5182364e0 completed in: 235 microseconds
[2018-09-12 20:06:03.568227]: 0x7ee518148960 {"action":"account_weight","account":"xrb_17wmwpg65neuh8u84f99e6nxcf48znusb437efwaafta7rtpy4n9h6io79xj"}
[2018-09-12 20:06:03.568379]: RPC request 0x7ee518148960 completed in: 186 microseconds
[2018-09-12 20:06:07.429745]: Found a representative at [::ffff:138.68.155.230]:7075
[2018-09-12 20:06:07.723277]: Found a representative at [::ffff:188.226.156.108]:2002
[2018-09-12 20:06:08.980140]: Found a representative at [::ffff:34.221.239.10]:7075
[2018-09-12 20:06:09.271767]: Found a representative at [::ffff:139.162.73.168]:7075
[2018-09-12 20:06:10.047847]: Found a representative at [::ffff:81.169.176.251]:2002
[2018-09-12 20:06:10.201880]: Block D689FA05D9EE622E71CD5FDDA80AE85B8F147242E31E058E07FADB377447E6BE was republished to peers
[2018-09-12 20:06:10.202790]: Block 6A925103D7C942EA90525630E10BEC44C9957E22AAD49F0A7FFF4A3919F61CA5 was republished to peers
[2018-09-12 20:06:17.189914]: Found a representative at [::ffff:213.252.244.134]:7075
[2018-09-12 20:06:26.212764]: Block BA5BA5D0B01169BD149804C23E1F8AD34A64A0D0A5B8EE736C0C7C0915DEE10B was republished to peers
[2018-09-12 20:06:26.683890]: Found a representative at [::ffff:54.37.129.86]:7075
[2018-09-12 20:06:27.882409]: Found a representative at [::ffff:138.68.155.230]:2003
[2018-09-12 20:06:34.654686]: 0x7ee5101b0770 {"action":"version"}
[2018-09-12 20:06:34.655689]: RPC request 0x7ee5101b0770 completed in: 1533 microseconds
[2018-09-12 20:06:34.737183]: 0x7ee51012c670 {"action":"block_count"}
[2018-09-12 20:06:34.737409]: RPC request 0x7ee51012c670 completed in: 302 microseconds
[2018-09-12 20:06:34.799578]: 0x7ee51429c780 {"action":"peers"}
[2018-09-12 20:06:34.807574]: RPC request 0x7ee51429c780 completed in: 8045 microseconds
[2018-09-12 20:06:34.810527]: 0x7ee5100f6e40 {"action":"account_balance","account":"xrb_17wmwpg65neuh8u84f99e6nxcf48znusb437efwaafta7rtpy4n9h6io79xj"}
[2018-09-12 20:06:34.811922]: RPC request 0x7ee5100f6e40 completed in: 1444 microseconds
[2018-09-12 20:06:34.814143]: 0x7ee51823e640 {"action":"account_info","account":"xrb_17wmwpg65neuh8u84f99e6nxcf48znusb437efwaafta7rtpy4n9h6io79xj","representative":"true","weight":"true"}
[2018-09-12 20:06:34.815139]: RPC request 0x7ee51823e640 completed in: 1043 microseconds
[2018-09-12 20:06:34.817234]: 0x7ee5141afa50 {"action":"account_weight","account":"xrb_17wmwpg65neuh8u84f99e6nxcf48znusb437efwaafta7rtpy4n9h6io79xj"}
[2018-09-12 20:06:34.817394]: RPC request 0x7ee5141afa50 completed in: 203 microseconds
[2018-09-12 20:06:40.113350]: Found a representative at [::ffff:206.189.20.214]:2003
[2018-09-12 20:06:41.261971]: Found a representative at [::ffff:94.16.114.235]:2002
[2018-09-12 20:06:42.218810]: Block A455EFF3BD545C615799E68D1566B0A92FE6236D2E3BDA5653365B16E8F36F99 was republished to peers
[2018-09-12 20:06:42.219415]: Block 015069F670950F600AC16D560E40EEC17B052A80355944A1CFCD02F08D36AC64 was republished to peers
[2018-09-12 20:06:43.830350]: Found a representative at [::ffff:192.34.56.173]:7075
[2018-09-12 20:06:44.094262]: Found a representative at [::ffff:45.55.215.151]:7075
[2018-09-12 20:06:44.623517]: Error sending frontier pair: Connection reset by peer
[2018-09-12 20:06:47.834789]: Found a representative at [::ffff:5.189.153.111]:5807
[2018-09-12 20:06:58.225663]: Block BDD862599ADBB49F0B50393D4BC4021E2FECB2F9298D1F4BC13F97FD780E2B6B was republished to peers
[2018-09-12 20:06:58.227659]: Block D6C11EC7ED42D7D1CD72CD66F652A92CDAD1C31F96243029786FF6AF2BCA2CBA was republished to peers
[2018-09-12 20:06:58.278969]: Found a representative at [::ffff:94.16.114.235]:7075
[2018-09-12 20:06:58.308072]: Found a representative at [::ffff:159.69.25.154]:1024
[2018-09-12 20:06:58.777086]: Found a representative at [::ffff:209.97.177.29]:7075
[2018-09-12 20:07:00.505225]: Found a representative at [::ffff:159.65.230.193]:7075
[2018-09-12 20:07:08.446534]: Found a representative at [::ffff:165.227.233.79]:7075
[2018-09-12 20:07:09.672886]: 0x7ee514146330 {"action":"version"}
[2018-09-12 20:07:09.673863]: RPC request 0x7ee514146330 completed in: 1402 microseconds
[2018-09-12 20:07:09.743281]: 0x7ee5100f6e40 {"action":"block_count"}
[2018-09-12 20:07:09.743509]: RPC request 0x7ee5100f6e40 completed in: 301 microseconds
[2018-09-12 20:07:09.796618]: 0x7ee5181c2cd0 {"action":"peers"}
[2018-09-12 20:07:09.804567]: RPC request 0x7ee5181c2cd0 completed in: 7998 microseconds
[2018-09-12 20:07:09.806586]: 0x7ee51012c670 {"action":"account_balance","account":"xrb_17wmwpg65neuh8u84f99e6nxcf48znusb437efwaafta7rtpy4n9h6io79xj"}
[2018-09-12 20:07:09.807862]: RPC request 0x7ee51012c670 completed in: 1332 microseconds
[2018-09-12 20:07:09.808884]: 0x7ee51411b340 {"action":"account_info","account":"xrb_17wmwpg65neuh8u84f99e6nxcf48znusb437efwaafta7rtpy4n9h6io79xj","representative":"true","weight":"true"}
[2018-09-12 20:07:09.810507]: RPC request 0x7ee51411b340 completed in: 1659 microseconds
[2018-09-12 20:07:09.811706]: 0x7ee5181c2cd0 {"action":"account_weight","account":"xrb_17wmwpg65neuh8u84f99e6nxcf48znusb437efwaafta7rtpy4n9h6io79xj"}
[2018-09-12 20:07:09.811891]: RPC request 0x7ee5181c2cd0 completed in: 220 microseconds
[2018-09-12 20:07:12.419514]: Found a representative at [::ffff:181.49.95.144]:21787
[2018-09-12 20:07:13.366780]: Found a representative at [::ffff:139.59.31.249]:7075
[2018-09-12 20:07:13.404449]: Found a representative at [::ffff:139.59.31.249]:2002
[2018-09-12 20:07:14.242586]: Block 646FE5792A7E63736E8E772EEB541A425A267605FB93351F609BACD18CB4FDE5 was republished to peers
[2018-09-12 20:07:19.468853]: Found a representative at [::ffff:206.189.18.189]:7075
[2018-09-12 20:07:27.810549]: Found a representative at [::ffff:165.227.17.17]:3314
[2018-09-12 20:07:28.118600]: Found a representative at [::ffff:51.15.198.200]:5152
[2018-09-12 20:07:28.158092]: Found a representative at [::ffff:51.15.198.200]:5305
[2018-09-12 20:07:28.185353]: Found a representative at [::ffff:18.207.125.92]:2002
[2018-09-12 20:07:28.251165]: Found a representative at [::ffff:81.169.176.251]:7075
[2018-09-12 20:07:30.252178]: Block CFF57F85A0376E3EE0378F67A944938B39EC0B416E551DE25AB807F37A30416C was republished to peers
[2018-09-12 20:07:31.797032]: Found a representative at [::ffff:162.241.236.41]:1992
[2018-09-12 20:07:35.507700]: Found a representative at [::ffff:35.224.233.216]:7075
[2018-09-12 20:07:37.536654]: Found a representative at [::ffff:165.227.33.236]:1024
[2018-09-12 20:07:41.896118]: 0x7ee5101b0770 {"action":"version"}
[2018-09-12 20:07:41.898908]: RPC request 0x7ee5101b0770 completed in: 4023 microseconds
[2018-09-12 20:07:41.976545]: 0x7ee5181e0730 {"action":"block_count"}
[2018-09-12 20:07:41.976715]: RPC request 0x7ee5181e0730 completed in: 217 microseconds
[2018-09-12 20:07:42.074456]: 0x7ee51429c780 {"action":"peers"}
[2018-09-12 20:07:42.090830]: RPC request 0x7ee51429c780 completed in: 16430 microseconds
[2018-09-12 20:07:42.093490]: 0x7ee510146330 {"action":"account_balance","account":"xrb_17wmwpg65neuh8u84f99e6nxcf48znusb437efwaafta7rtpy4n9h6io79xj"}
[2018-09-12 20:07:42.095014]: RPC request 0x7ee510146330 completed in: 1661 microseconds
[2018-09-12 20:07:42.097056]: 0x7ee51022c8f0 {"action":"account_info","account":"xrb_17wmwpg65neuh8u84f99e6nxcf48znusb437efwaafta7rtpy4n9h6io79xj","representative":"true","weight":"true"}
[2018-09-12 20:07:42.098098]: RPC request 0x7ee51022c8f0 completed in: 1087 microseconds
[2018-09-12 20:07:42.099622]: 0x7ee5141afa50 {"action":"account_weight","account":"xrb_17wmwpg65neuh8u84f99e6nxcf48znusb437efwaafta7rtpy4n9h6io79xj"}
[2018-09-12 20:07:42.099749]: RPC request 0x7ee5141afa50 completed in: 163 microseconds
[2018-09-12 20:07:42.859110]: Found a representative at [::ffff:192.34.56.173]:2005
[2018-09-12 20:07:42.859621]: Found a representative at [::ffff:192.34.56.173]:2005
[2018-09-12 20:07:43.046059]: Found a representative at [::ffff:163.172.179.193]:7075
[2018-09-12 20:07:46.009517]: Unable to connect to work_peer ::ffff:50.99.86.126 7080: Connection timed out (110)
[2018-09-12 20:07:46.261911]: Block D0E0D6EEDDFA9359039AE8369A86AE3219839764AF924F6EB36FB04293F81F0E was republished to peers
[2018-09-12 20:07:46.262438]: Block E3293EB5414E149345FBDF2FE49B8157554076F94495B12C805E5C4706BF67D2 was republished to peers
[2018-09-12 20:07:47.158404]: Found a representative at [::ffff:45.32.246.108]:7075
[2018-09-12 20:07:47.594721]: Found a representative at [::ffff:5.189.153.111]:7075
[2018-09-12 20:07:49.229834]: Found a representative at [::ffff:51.15.54.95]:7075
[2018-09-12 20:07:49.246564]: Found a representative at [::ffff:145.239.82.14]:7075
[2018-09-12 20:07:50.616911]: Found a representative at [::ffff:181.49.93.98]:7109
[2018-09-12 20:07:58.508074]: Reserved sender ::ffff:172.17.0.1
[2018-09-12 20:07:59.129601]: Found a representative at [::ffff:81.169.174.237]:7075
[2018-09-12 20:07:59.851552]: Found a representative at [::ffff:35.224.233.216]:4449
[2018-09-12 20:08:00.595365]: Found a representative at [::ffff:165.227.17.17]:7075
[2018-09-12 20:08:02.275845]: Block E304C20B7E10EBA790448849AD7955A96D57B39BD27AC643130B596DAF12CB02 was republished to peers
[2018-09-12 20:08:02.276370]: Block FF47505D9CB11EF3EE608CE89274C8A24F53DB8B4D407FEF83551811E588D46B was republished to peers
[2018-09-12 20:08:02.276852]: Block 976ACB45A4980637AE41856DD370685BBAA02530F96D5C0078C53A85957A305A was republished to peers
[2018-09-12 20:08:05.195087]: Found a representative at [::ffff:188.226.156.108]:7075
[2018-09-12 20:08:05.338485]: Found a representative at [::ffff:213.136.77.150]:17071
[2018-09-12 20:08:05.658491]: Found a representative at [::ffff:213.252.244.134]:1024
[2018-09-12 20:08:08.386967]: Found a representative at [::ffff:139.162.205.25]:2003
[2018-09-12 20:08:09.707501]: Work generation complete: 150998465 us
[2018-09-12 20:08:09.727416]: RPC request 0x7ee510132ad0 completed in: 150836888 microseconds
NOTE: in this specific logging example, a work peer was being used. This work peer was down, which caused me to notice that the generated work from an external source was not being used. When rolled back to 15.2, the provided work was used. Also, when work_peer was removed, the work was still not being used on v16.0.
The text was updated successfully, but these errors were encountered: