Venus: [bug] Invalid PoSt error 39, interleaved submitPoSt and commitSector

[travisperson]

Describe the bug

One of the miner nodes (filecoin-1) on the test devnet submitted it's post, but the PoSt failed to apply for being invalid (error 39). This has resulted in the miner getting stuck in that proving period.

https://explorer.test.kittyhawk.wtf/blocks/zDPWYqFCx15455ASzYvqenqzoK9vQ5V5qMMeQLMX4QSgsF8fWoaX

We should figure out exactly why this PoSt was invalid.

[anorth]

For ease of reference:

Block height: 1207
Mined by: t2dtawhlb2q3ibqniattk5zs5rz33hcxvtya562ha

From: t15lt4rgr7n4jijyv4c73y5wpwncpqwazsngujl2a
To: t2dybmykbfsn6awe2k3j6qw6nokjwjbdkaf45yb7q
Nonce: 11
Message params: glkDCYRYwIcwEK6HP6txdgF7oEKhoH83BSPlnXOM7vzphHn4s0ZFDUF/URupIsvFn6d9KK635bZ18iw/HTc5AAPz3HHRp22K6xHZZOR3wuI3WlveUWg3igkuscgITrdlAZEdoovUzwDXyZUuDYAjb1N531Q/4C1dHG/Nc+IwQ5K/jv5zJpJxcmFTdgLztKqSfR4wF4l98YJN3kmaoTBIcuXpP7rRJikVPwgfAjJeAa3iwd7w+wFBN4gAAdu8guzFKIpAG5P27VjAgDWqtVYSScz+J2bKyaSioqhuw47EoYACIWdm1xZ0dmqRI3e/Hxvz1/wQOWVkR3fSgCJwWamKBjqJ10rwP+abibKZXCcEU3Rlgv4NlmaKmX/MvLmztmm49zGmB0RGuFjZFE4sqyiTYJ+yL1gSvC142pxq9t5CpIOpErX8ab/0jxFgeb1K8OSGO9Kho5+m7SXqiduk91hjwUcRhcECQTZl7BZKtQrWXD0EQIBUuppmcy6niEGvcE0iIXK0Nukl3T70WMCuTmBmlzwl2m8VRTxTzvJojluvdI0/zKf+vTm3Litq8nqCMikTzxgSfk835ppffQyt/5K9EB0FPdmCTGr57OMLq7Ch2JuejRK8Ox8s8CVuc9CTJI6pP/60PxgxaUtt3PIQnorf5TKJFNtBvGGi6H3Uq9YCm9WMqmKem2OkCzrcHTY0v3kZLlm4i9txCDS0R7WCgFz4NDz+hmh+oWRjzqqCJz3vi+VDl+LL3KxYrZoTK99L/haFEBTNSVxeHB2NI9pYwIFhIAuAyaOKmPb19raXyCqmN1d24Q62BVtuie01Ylj0fufH892oY22Fn9PWM17qtKydtWfds/D3DcIGouwNVJPuiIB2yeo/NFOpR8yUajg8CKM+sZ4NyhJJIBN24tqxXRMBsexn/7I6nSTwUtlllFwWzYqmjVbCnIi2XTKJDhhq2vgOPBZSStsC6qzl2Gl3qYrUsvcV1/rxPVEj9I4F3hSF8KImxk5sFHcIssbQz89uQ1t9AXQxbNJAxKeTTP+/8EJB9g==
Exit code: 39

[anorth]

Exit code 39 is ErrInvalidPoSt. It's returned only when the RustVerifier.VerifyPoST returns false for IsValid.

The decoded params are:

PoStProofs [[135 48 16 174 135 63 171 113 118 1 123 160 66 161 160 127 55 5 35 229 157 115 140 238 252 233 132 121 248 179 70 69 13 65 127 81 27 169 34 203 197 159 167 125 40 174 183 229 182 117 242 44 63 29 55 57 0 3 243 220 113 209 167 109 138 235 17 217 100 228 119 194 226 55 90 91 222 81 104 55 138 9 46 177 200 8 78 183 101 1 145 29 162 139 212 207 0 215 201 149 46 13 128 35 111 83 121 223 84 63 224 45 93 28 111 205 115 226 48 67 146 191 142 254 115 38 146 113 114 97 83 118 2 243 180 170 146 125 30 48 23 137 125 241 130 77 222 73 154 161 48 72 114 229 233 63 186 209 38 41 21 63 8 31 2 50 94 1 173 226 193 222 240 251 1 65 55 136 0 1 219 188 130 236 197 40 138 64 27 147 246 237] [128 53 170 181 86 18 73 204 254 39 102 202 201 164 162 162 168 110 195 142 196 161 128 2 33 103 102 215 22 116 118 106 145 35 119 191 31 27 243 215 252 16 57 101 100 71 119 210 128 34 112 89 169 138 6 58 137 215 74 240 63 230 155 137 178 153 92 39 4 83 116 101 130 254 13 150 102 138 153 127 204 188 185 179 182 105 184 247 49 166 7 68 70 184 88 217 20 78 44 171 40 147 96 159 178 47 88 18 188 45 120 218 156 106 246 222 66 164 131 169 18 181 252 105 191 244 143 17 96 121 189 74 240 228 134 59 210 161 163 159 166 237 37 234 137 219 164 247 88 99 193 71 17 133 193 2 65 54 101 236 22 74 181 10 214 92 61 4 64 128 84 186 154 102 115 46 167 136 65 175 112 77 34 33 114 180 54 233 37 221 62 244] [174 78 96 102 151 60 37 218 111 21 69 60 83 206 242 104 142 91 175 116 141 63 204 167 254 189 57 183 46 43 106 242 122 130 50 41 19 207 24 18 126 79 55 230 154 95 125 12 173 255 146 189 16 29 5 61 217 130 76 106 249 236 227 11 171 176 161 216 155 158 141 18 188 59 31 44 240 37 110 115 208 147 36 142 169 63 254 180 63 24 49 105 75 109 220 242 16 158 138 223 229 50 137 20 219 65 188 97 162 232 125 212 171 214 2 155 213 140 170 98 158 155 99 164 11 58 220 29 54 52 191 121 25 46 89 184 139 219 113 8 52 180 71 181 130 128 92 248 52 60 254 134 104 126 161 100 99 206 170 130 39 61 239 139 229 67 151 226 203 220 172 88 173 154 19 43 223 75 254 22 133 16 20 205 73 92 94 28 29 141 35 218] [129 97 32 11 128 201 163 138 152 246 245 246 182 151 200 42 166 55 87 118 225 14 182 5 91 110 137 237 53 98 88 244 126 231 199 243 221 168 99 109 133 159 211 214 51 94 234 180 172 157 181 103 221 179 240 247 13 194 6 162 236 13 84 147 238 136 128 118 201 234 63 52 83 169 71 204 148 106 56 60 8 163 62 177 158 13 202 18 73 32 19 118 226 218 177 93 19 1 177 236 103 255 178 58 157 36 240 82 217 101 148 92 22 205 138 166 141 86 194 156 136 182 93 50 137 14 24 106 218 248 14 60 22 82 74 219 2 234 172 229 216 105 119 169 138 212 178 247 21 215 250 241 61 81 35 244 142 5 222 20 133 240 162 38 198 78 108 20 119 8 178 198 208 207 207 110 67 91 125 1 116 49 108 210 64 196 167 147 76 255 191 240]]
Done []

[anorth]

I reset my chain in order to observe the logs as my node validated that message. No new info tho:
INFO consensus.: ApplyMessage failed: PoSt proof did not validate SignedMessage cid=[zDPWYqFCw1fmZ9aQPBq66e6uCrnSfAh8zHxfasUQ79sWTrbPGN3f]: { "meteredMessage": { "message": { "to": "t2dybmykbfsn6awe2k3j6qw6nokjwjbdkaf45yb7q", "from": "t15lt4rgr7n4jijyv4c73y5wpwncpqwazsngujl2a", "nonce": "11", "value": "0", "method": "submitPoSt", "params": "glkDCYRYwIcwEK6HP6txdgF7oEKhoH83BSPlnXOM7vzphHn4s0ZFDUF/URupIsvFn6d9KK635bZ18iw/HTc5AAPz3HHRp22K6xHZZOR3wuI3WlveUWg3igkuscgITrdlAZEdoovUzwDXyZUuDYAjb1N531Q/4C1dHG/Nc+IwQ5K/jv5zJpJxcmFTdgLztKqSfR4wF4l98YJN3kmaoTBIcuXpP7rRJikVPwgfAjJeAa3iwd7w+wFBN4gAAdu8guzFKIpAG5P27VjAgDWqtVYSScz+J2bKyaSioqhuw47EoYACIWdm1xZ0dmqRI3e/Hxvz1/wQOWVkR3fSgCJwWamKBjqJ10rwP+abibKZXCcEU3Rlgv4NlmaKmX/MvLmztmm49zGmB0RGuFjZFE4sqyiTYJ+yL1gSvC142pxq9t5CpIOpErX8ab/0jxFgeb1K8OSGO9Kho5+m7SXqiduk91hjwUcRhcECQTZl7BZKtQrWXD0EQIBUuppmcy6niEGvcE0iIXK0Nukl3T70WMCuTmBmlzwl2m8VRTxTzvJojluvdI0/zKf+vTm3Litq8nqCMikTzxgSfk835ppffQyt/5K9EB0FPdmCTGr57OMLq7Ch2JuejRK8Ox8s8CVuc9CTJI6pP/60PxgxaUtt3PIQnorf5TKJFNtBvGGi6H3Uq9YCm9WMqmKem2OkCzrcHTY0v3kZLlm4i9txCDS0R7WCgFz4NDz+hmh+oWRjzqqCJz3vi+VDl+LL3KxYrZoTK99L/haFEBTNSVxeHB2NI9pYwIFhIAuAyaOKmPb19raXyCqmN1d24Q62BVtuie01Ylj0fufH892oY22Fn9PWM17qtKydtWfds/D3DcIGouwNVJPuiIB2yeo/NFOpR8yUajg8CKM+sZ4NyhJJIBN24tqxXRMBsexn/7I6nSTwUtlllFwWzYqmjVbCnIi2XTKJDhhq2vgOPBZSStsC6qzl2Gl3qYrUsvcV1/rxPVEj9I4F3hSF8KImxk5sFHcIssbQz89uQ1t9AXQxbNJAxKeTTP+/8EJB9g==" }, "gasPrice": "0.000000000000000001", "gasLimit": "300" }, "signature": "HsePDeQT7Z/9ST9hY3Jp91zyIRSdOTzXkfQEfd137VYGC0boA1X4HcVrxMo284CputOXDMf0AEmEsXZNd1VfNAE=" } processor.go:336

[anorth]

@laser any insight here?

[laser]

How's it Work Today?

If a proof of spacetime is to be generated for a storage miner actor M1, the go-filecoin node N1 which will run the PoSt-generation routine uses a query message to obtain the current challenge seed for M1. This challenge seed is created by sampling the blockchain for randomness R1 at a block height some number of blocks back from M1's _current_ proving period start block-height. Once it has R1, it calls generate_post through the FFI, passing R1 and a list of replica commitments L1. Once that operation completes, it constructs a submitPoSt message G (which does _not_ include the challenge seed or replica commitments) and places the message into its mempool.

Later, a different go-filecoin node N2 mines a block which includes G. In order to verify G (during processing), it too samples the chain for randomness at a block height some number of blocks back from what it believes to be M1's current proving period start block-height, producing R2. N2 also uses a query message to obtain a list of replica commitments from M1's state to produce L2.

The proof and faults (from the submitPoSt message) and R2 and L2 are passed to the verify_post operation through the FFI, returning a boolean value indicating whether or not the underlying proof system thought that combination of proof/fault/challenge seed were valid.

Possible Failure Modes

Both failure modes I can think of involve R1 != R2, L1 !+ L2, or both.

L1 != L2

When a node processes a submitPoSt message for a storage miner actor, it loads all of that actor's commitments (not the proving set!) into a slice and passes that slice to the verify_post call. If that slice differs in its composition from the slice passed to the generate_post call, the proving system will think that proof is invalid.

As I read the code, I see that the CommitSector method always adds a newly-committed sector to the bit of actor state which the verifying node inspects when creating its verify_post call.

It's my guess that the prover created a submitPoSt message and then, very shortly thereafter, a commitSector message. The verifier received both messages and processed commitSector first, which modified the actor's commitments. The verifier then processes submitPoSt, which sends the additional sector commitment to the verify_post call.

R1 != R2

The second failure mode I can think of involves N1 thinking that M1's proving period start block-height is different than what N2 thinks M1's proving period start block-height to be.

I think this could occur of N1 creates a submitPoSt message towards the very end of M1's proving period. N2 learns about this message after M1's has transitioned to the proving period _after_ the proving period in which the submitPoSt message was generated. This would result in R1 != R2.

Thoughts? Does any of that make sense?

[acruikshank]

I don't think the R1 != R2 scenario is valid. We don't update the miner's ProvingPeriodEnd until the SubmitPoSt goes on chain so it's unlikely that the prover and verifier would be out of sync on this.

It is possible that a chain re-org could cause the chain randomness to differ between the prover and verifier. We currently have our lookback interval set to 3, and I'm pretty sure we've seen re-orgs largerr than 3 tipsets.

That said, I agree L1 != L2 is the most likely scenario for this issue.

[anorth]

What's our action here? The node should be able to sequence its messages with the nonce so this sounds like something fixable.

[anorth]

I think the new spec will address this in actor code. When a miner is challenged (surprise PoSt) any subsequent commitments will be held aside until the PoSt is submitted.

Moving to backlog for tracking until we confirm this.

[anorth]

Obsolete (new actor code)