Invalid txn blockchain_txn_poc_receipts_v1 : {error,receipt_not_in_order}

[ricopt5]

On some occasions, it seems that the poc receipt transaction fails validation with a "receipt_not_in_order" result.

My hotspot successfully created a challenge

2022-01-28 09:38:09.577 1 [info] <0.1642.0>@miner_poc_statem:handle_targeting:{501,21} poc_v11 challenger: "112HY5Zp3Y7HfPZCoUNDADKNi5ocmd1MRUquZzyVVe2etsi9B8BZ", challenger_loc: 631509043397114367
2022-01-28 09:38:09.578 1 [info] <0.1642.0>@miner_poc_statem:handle_targeting:{502,21} poc_v11 target found "11y7GC7aZKQA6VE8xYA5oUzqpsADkdG7qYxbQ9i43iMhx2Hcrap", challenging, target_rand_state: {#{bits => 64,jump => #Fun<rand.12.92093067>,next => #Fun<rand.11.92093067>,type => exs1024s,weak_low_bits => 3},{[12248768710089631116,5962802624868120102,8738738059487337370,11046422425564788658,508611572285395164,16477060273154653525],[16990026294625387656,15979145558033464078,2243952131655622263,11361632731991980284,6352120237642634819,1987790409006718857,8341293130616454848,5456822457627643337,11408638906051800844,10598803547301101214]}}
2022-01-28 09:38:09.683 1 [info] <0.1642.0>@miner_poc_statem:handle_challenging:{540,5} starting blockchain_poc_path:build in <0.8846.5>
2022-01-28 09:38:09.685 1 [info] <0.8846.5>@miner_poc_statem:handle_challenging:{536,35} poc_v11 Path: [<<0,127,102,102,45,100,248,162,98,154,195,161,76,241,179,226,203,183,180,221,216,215,98,126,115,184,29,112,187,135,49,195,201>>]
2022-01-28 09:38:09.685 1 [info] <0.1642.0>@miner_poc_statem:handle_challenging:{549,13} path created [<<0,127,102,102,45,100,248,162,98,154,195,161,76,241,179,226,203,183,180,221,216,215,98,126,115,184,29,112,187,135,49,195,201>>]
2022-01-28 09:38:09.690 1 [info] <0.1642.0>@miner_poc_statem:handle_challenging:{556,13} onion of length 42 created <<224,128,0,17,238,169,126,189,246,248,232,79,43,88,117,137,251,29,77,106,162,13,16,193,2,60,83,206,194,93,120,159,22,169,167,54,249,64,224,161,174,248>>
2022-01-28 09:38:09.692 1 [error] <0.1642.0>@miner_poc_statem:send_onion:{1003,13} failed to dial 1st hotspot ("/p2p/11y7GC7aZKQA6VE8xYA5oUzqpsADkdG7qYxbQ9i43iMhx2Hcrap"): not_found
2022-01-28 09:38:20.204 1 [info] <0.8857.5>@miner_onion_handler:init:{52,5} started miner_onion_handler client
2022-01-28 09:38:20.340 1 [info] <0.1511.0>@libp2p_transport_tcp:record_observed_addr:{1056,21} peer "/p2p/11y7GC7aZKQA6VE8xYA5oUzqpsADkdG7qYxbQ9i43iMhx2Hcrap" informed us of our observed address "/ip4/168.182.226.25/tcp/49424"
2022-01-28 09:38:20.347 1 [info] <0.1642.0>@miner_poc_statem:send_onion:{1000,13} onion sent
2022-01-28 09:38:20.348 1 [info] <0.8857.5>@miner_onion_handler:handle_info:{78,5} client sending data: <<224,128,0,17,238,169,126,189,246,248,232,79,43,88,117,137,251,29,77,106,162,13,16,193,2,60,83,206,194,93,120,159,22,169,167,54,249,64,224,161,174,248>>

Here's the challenge: https://explorer.helium.com/txns/WMB5Z805vpniUhIhWLVhG399aPQuksObm40FL5s5BnE

And after the 20 blocks timeout it tried to submit the poc transaction but failed.

2022-01-28 09:58:33.443 1 [error] <0.10044.5>@blockchain_txn_poc_receipts_v1:validate:{1125,48} receipt not in order <<0,127,102,102,45,100,248,162,98,154,195,161,76,241,179,226,203,183,180,221,216,215,98,126,115,184,29,112,187,135,49,195,201>> /= <<0,165,65,203,147,95,169,69,110,28,13,78,96,236,112,245,82,126,138,126,253,220,70,223,62,155,38,234,142,191,55,212,127>>
2022-01-28 09:58:33.444 1 [warning] <0.1604.0>@blockchain_txn:separate_res:{377,13} invalid txn blockchain_txn_poc_receipts_v1 : {error,receipt_not_in_order} / type=poc_receipts_v1 hash="122j6tStu86DwRF1LfaW5kPUqT13dpFbJe67YqozcK767zcvWva" challenger="cold-sable-snake" onion="1zxhQxot8ZUNmxttLZj7cAvuHh6QszzmMTMvK7kN5wDa4PPeaj" path:
type=element challengee: rough-blonde-sheep, receipt: type=receipt gateway: rough-blonde-sheep timestamp: 1643362700453045454 signal: 0 snr: 0.0 freq: 0.0 origin: p2p, tx_power: 18
witnesses: type=witness gateway: "early-infrared-hamster" timestamp: 1643362703417044941 signal: -114 snr: -21.0 freq 868.5
type=witness gateway: "fit-quartz-orangutan" timestamp: 1643362703940192588 signal: -70 snr: 6.0 freq 868.5
type=witness gateway: "hot-purple-terrier" timestamp: 1643362703450132761 signal: -122 snr: -8.800000190734863 freq 868.5

I wonder why the validation code generated a different beaconer <<0,165,65,203,147,95,169,69,110,28,13,78,96,236,112,245,82,126,138,126,253,220,70,223,62,155,38,234,142,191,55,212,127>> than the one that was challenged <<0,127,102,102,45,100,248,162,98,154,195,161,76,241,179,226,203,183,180,221,216,215,98,126,115,184,29,112,187,135,49,195,201>>

Here's the complete log
console.log.0.zip

[fishpepper]

I started to see those in September, maybe this can help to pinpoint the issue. Not sure if they cause any real trouble, though.
See #1072

[ricopt5]

It may explain part (the other part is p2p issues and maybe other issues) of why we have a discrepancy between created challenges and poc receipts.
Not long ago, it was at a 1/2 ratio, but since the 23rd it's been decreasing and it's now at a 1/3 ratio, meaning only 1/3 of created challenges have a corresponding poc receipt. (I can also see my hotspot rewards decreasing since the 23rd)

I've looked at the code and I can't figure out why this is happening as the challengee target code is deterministic and the correct ledger (the one at the time of the challenge) is being passed on at the time of validation, so the challengee at the time of validation should be the same as the one targeted at the time of the challenge, but it seems sometimes they aren't.

[n5qm]

Here is another example if it is valuable...

2022-01-27 17:44:22.956 1 [error] <0.29763.16>@blockchain_txn_poc_receipts_v1:validate:{1125,48} receipt not in order <<0,214,9,234,112,209,31,57,181,35,109,195,157,82,117,170,209,1,196,241,47,42,10,170,161,174,27,40,133,217,57,219,219>> /= <<0,164,23,163,146,90,163,162,32,52,149,210,200,26,243,120,95,224,92,188,86,41,137,78,105,64,128,106,220,141,23,221,32>>
2022-01-27 17:44:22.978 1 [warning] <0.1618.0>@blockchain_txn:separate_res:{377,13} invalid txn blockchain_txn_poc_receipts_v1 : {error,receipt_not_in_order} / type=poc_receipts_v1 hash="1VkbKp7tPcQSiRaDFjzSoVwnLE83LS6AZqF1A9ajzUeaysUpEE" challenger="urban-red-peacock" onion="1d8nNyqFuJYc7Boi67G46DVCmR92Q53hPgyVe5H87kiVMRbrmq" path:
type=element challengee: curved-blonde-goose, receipt: type=receipt gateway: curved-blonde-goose timestamp: 1643304582990267802 signal: 0 snr: 0.0 freq: 0.0 origin: p2p, tx_power: 10
witnesses: type=witness gateway: "sleepy-butter-rooster" timestamp: 1643304588003450322 signal: -114 snr: -11.0 freq 867.2999877929688
type=witness gateway: "hot-foggy-eagle" timestamp: 1643304586392968094 signal: -119 snr: -4.0 freq 867.2999877929688
type=witness gateway: "bright-chili-mustang" timestamp: 1643304587998679197 signal: -126 snr: -21.200000762939453 freq 867.2999877929688
type=witness gateway: "skinny-chartreuse-caribou" timestamp: 1643304588023822992 signal: -125 snr: -20.5 freq 867.2999877929688
type=witness gateway: "funny-satin-scallop" timestamp: 1643304586398766672 signal: -126 snr: -17.0 freq 867.2999877929688
type=witness gateway: "immense-cinnabar-cyborg" timestamp: 1643304588000047486 signal: -118 snr: -8.5 freq 867.2999877929688
type=witness gateway: "quaint-mossy-chameleon" timestamp: 1643304586466166303 signal: -118 snr: -13.0 freq 867.2999877929688
type=witness gateway: "magnificent-grape-tuna" timestamp: 1643304588000090457 signal: -129 snr: -20.5 freq 867.2999877929688
type=witness gateway: "quaint-merlot-walrus" timestamp: 1643304587991523575 signal: -126 snr: -12.5 freq 867.2999877929688
type=witness gateway: "cuddly-cloth-crane" timestamp: 1643304586906106633 signal: -129 snr: -13.5 freq 867.2999877929688
type=witness gateway: "teeny-laurel-pig" timestamp: 1643304587999406908 signal: -116 snr: -18.5 freq 867.2999877929688
type=witness gateway: "soft-pastel-ape" timestamp: 1643304586038686095 signal: -117 snr: -12.199999809265137 freq 867.2999877929688
type=witness gateway: "rural-ceramic-giraffe" timestamp: 1643304586466855195 signal: -112 snr: -8.800000190734863 freq 867.2999877929688
type=witness gateway: "cold-tartan-elk" timestamp: 1643304587991308726 signal: -133 snr: -20.5 freq 867.2999877929688
type=witness gateway: "festive-misty-osprey" timestamp: 1643304587994937247 signal: -134 snr: -20.5 freq 867.2999877929688
type=witness gateway: "colossal-fuchsia-gecko" timestamp: 1643304588108271193 signal: -117 snr: -16.0 freq 867.2999877929688
type=witness gateway: "fun-pebble-rook" timestamp: 1643304586565911366 signal: -110 snr: -8.5 freq 867.2999877929688
type=witness gateway: "dandy-tawny-koala" timestamp: 1643304588020096319 signal: -125 snr: -22.0 freq 867.2999877929688
2022-01-27 17:44:22.978 1 [info] <0.1618.0>@blockchain_txn:validate:{294,5} valid: [], invalid: [{blockchain_txn_poc_receipts_v1,1}]
2022-01-27 17:44:22.979 1 [info] <0.1618.0>@blockchain_txn_mgr:process_invalid_txn:{578,5} txn declared invalid with reason {error,{invalid,receipt_not_in_order}}, removing from cache and invoking callback: <<65,72,179,76,154,239,221,252,188,52,105,195,57,185,5,91,13,90,45,18,196,108,184,40,113,204,155,176,224,244,166,204>>
2022-01-27 17:44:23.244 1 [info] <0.1656.0>@miner_poc_statem:waiting:{415,5} PoC receipt submission result {error,{invalid,receipt_not_in_order}}

[mzakes]

Seems it is happening still...

2022-04-02 19:59:53.768 8 [error] <0.12936.2>@blockchain_txn_poc_receipts_v1:validate:{1125,48} receipt not in order <<0,84,24,135,235,32,47,96,2,178,171,119,153,39,89,166,160,91,181,200,245,30,31,144,32,75,77,182,238,102,247,34,98>> /= <<0,62,5,166,128,216,56,30,22,168,151,153,71,69,60,215,131,196,11,238,30,175,246,169,105,29,199,249,71,96,166,213,127>> 2022-04-02 19:59:53.784 8 [warning] <0.1817.0>@blockchain_txn:separate_res:{377,13} invalid txn blockchain_txn_poc_receipts_v1 : {error,receipt_not_in_order} / type=poc_receipts_v1 hash="1rgvYeB2NDEKUvWLLcaSvYXjzN5wVPyJwfQ4bb88w8VugqYr52"

[meowshka]

Receipt not in order error you're seeing is an issue with the validator disagreeing with the the submitter of the transaction (the challenger) on validity of the transaction. We're looking at the issue but need to understand why the ledgers disagree. Please follow Official Helium Community Discord for the latest updates: https://discord.gg/DXUsTAHJ