Test failed due to premature clearing of xA in ProveOVHdr - Re-open

[bkgoodman]

Could not re-open Issue #20

I just got another failure.

I did notice that you added the defer clear - but never removed the old Runtime Finalizer. It appears as though the finalizer cleared in the case I ran:

*** SIGN OVHPROOF with key RSA2048 Fingerprint: 1dc0424e52b976c298d2988ee973541b2ae1be46822a5b1222827f19ade94987
*** FINALIZER CLEARING!!!!
*** FINALIZER CLEARING!!!!
*** VERIFY OVHPROOF with key RSA2048 Fingerprint: 1dc0424e52b976c298d2988ee973541b2ae1be46822a5b1222827f19ade94987
*** KeyExchangeA Set to [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
defer clear(proveOVHdr.Payload.Val.KeyExchangeA)
... is still in sendHelloDevice, but...

    runtime.SetFinalizer(proof, func(proof *cose.Sign1Tag[ovhProof, []byte]) {
            fmt.Printf("*** FINALIZER CLEARING!!!!\n")
            clear(proof.Payload.Val.KeyExchangeA)
    })

... is still in proveOVHHdr.

[ben-krieger]

The finalizer shouldn't be removed, because it is used to ensure that whatever the transport implementation, the value is cleared in memory after use. Generally this is after the transport performs CBOR marshaling. For proveOVHdr, this is important in (s *TO2Server) proveOVHdr.

In the case of fdotest, the mock transport actually reuses the in-memory type. Before #21, this type would go out of scope at the end of a function (sendHelloDevice) that created a key exchange session, even though that key exchange session referenced the xA byte slice. This meant that whenever the finalizer ran, it would modify an internal field of the key exchange session - breaking crypto operations.

However, now that the key exchange session uses a copy (bytes.Clone) of the xA byte slice, it doesn't matter when the finalizer runs. There shouldn't be any way for it to run before bytes.Clone, since that function call references the proveOVHdr value.

Are you sure it's the exact same error occurring?

[ben-krieger]

By spec:

deferred functions are executed after any result parameters are set by that return statement but before the function returns to its caller

[bkgoodman]

Are you sure it's the exact same error occurring?

Yes, definitely. Those are fresh copy/pastes from my verry recent test. Note - this is actually running on a different machine than my previous ones.

[ben-krieger]

I reproduced this:

*** SIGN OVHPROOF with key ECDSA NIST P-384 / secp384r1 Fingerprint: 3c17f9c6745612df003060699c8780cd62d4f077acd8385139fb6b355116ecea
*** ProveOVH is {Header:{Protected:map[1:-35] Unprotected:map[256:[38 102 48 129 27 147 134 74 71 176 180 245 254 244 9 112] 257:ECDSA NIST P-384 / secp384r1 Fingerprint: ac8f05b5ad4b3eace58966835935c7322e7e6e5d14faf92bedb2130db1fe4e21 258:ECDSA NIST P-384 / secp384r1 Fingerprint: 3c17f9c6745612df003060699c8780cd62d4f077acd8385139fb6b355116ecea]} Payload:0xc0001fd680 Signature:[82 197 240 206 51 205 224 149 168 118 230 191 136 247 212 242 39 115 247 255 208 57 28 30 171 228 239 49 252 84 239 174 199 64 168 58 43 83 187 81 240 26 196 65 70 106 74 168 101 53 69 253 24 215 15 42 222 142 182 198 231 73 61 202 28 5 181 57 168 71 229 68 218 5 75 132 22 110 141 167 169 102 35 204 80 119 118 221 160 11 153 211 139 245 33 50]}
*** KeyExchangeA Set to [0 48 120 68 171 89 3 142 4 223 252 217 7 59 93 232 73 115 186 7 21 42 9 54 220 183 131 201 191 154 67 46 222 149 60 45 49 186 82 108 47 217 183 17 186 206 209 86 178 60 0 48 152 164 251 251 30 105 152 247 124 149 92 134 212 199 227 228 129 110 253 123 198 220 135 234 25 18 215 188 122 157 10 165 160 222 31 2 214 22 8 17 51 37 171 194 214 183 94 166 0 48 252 197 7 1 168 245 143 89 120 214 104 168 253 211 54 174 231 62 95 97 199 70 209 47 96 43 185 110 122 168 139 211 17 240 153 44 96 128 70 193 28 30 59 69 81 153 195 169]
    transport.go:90: Response 61: 18([h'a1013822', {256: h'266630811b93864a47b0b4f5fef40970', 257: [11, 1, h'3076301006072a8648ce3d020106052b810400220362000424b5ad722abeee164728404ade3b7c9d7dfd9fe552399e958659c6778df6fe156c9cab2f63bc5de854866c1d58aa755bd4eef77cb499bd7be3645eab7bc4d9f0eb9fe5b33550dd975f44abcf7b0aa826caaf4cdb3e8aa7d23175df219b658a61'], 258: [11, 2, [h'308201a83082012ea0030201020202014d300a06082a8648ce3d040303301f311d301b0603550403131444656c6567617465496e7465726d6564696174653020170d3234313230333137333435355a180f32303534303632393137333435355a3017311530130603550403130c44656c6567617465436572743076301006072a8648ce3d020106052b81040022036200040a963b5b6ed49612a01edeb72fa502a8cc98625503767fb6d92d197400a3e293424ecf9987920dce2873079fa0979bcb024b09770f8c4405d399ca3d403e0cf8458bd54bbd2ed8b0c3aa45dd668b37d9d5ef87834894ad0a8fb8c0e3f91b8d8fa3433041300e0603551d0f0101ff04040302078030210603551d25041a3018060a2b0601040182e51c0301060a2b0601040182e51c0303300c0603551d130101ff04023000300a06082a8648ce3d040303036800306502301a04473fde6ef76c50ee8d7efcd65ebac96aed91600e8aea9a79c050f92e31ed6ee330cfc3b4e63c6b5148136b8cb1960231009264b049ae36398c5e6206d1530bfa4760ca6a7898bd85659576d2bc79997e1ad30d9a9485c9d81c911d91753e148e66', h'308201c930820150a003020102020200de300a06082a8648ce3d0403033017311530130603550403130c44656c6567617465526f6f743020170d3234313230333137333435355a180f32303534303632393137333435355a301f311d301b0603550403131444656c6567617465496e7465726d6564696174653076301006072a8648ce3d020106052b8104002203620004171c199836592aeaa7dd5487a48acfe3262a330ab6ab5292a5c3a658bb0e41d59bfa4f465f9b58b5b14c5d44fdc7748c3b005905356f4f681a7f83fb1bad139afb8d0ac53c785cf874025f316bb01cafa28bb836e5a203abaa25a7d42c628c3da3653063300e0603551d0f0101ff04040302028430210603551d25041a3018060a2b0601040182e51c0301060a2b0601040182e51c0303300f0603551d130101ff040530030101ff301d0603551d0e04160414fa3c99e8e8b94f63356232919ada7f088088e797300a06082a8648ce3d0403030367003064023021c0e93416f5e1f7a2fa30a6177e138b38de28f12fe1527eed6a71395827b34fc276412f8550308a29695a4050defef602305f4af4575884aa44176745b48684f97edcab85af6b422e69fec179362ae1aa1a9173d8c9c8f8917edace72e6c5ab10e3', h'308201c230820147a00302010202016f300a06082a8648ce3d0403033017311530130603550403130c44656c6567617465526f6f743020170d3234313230333137333435355a180f32303534303632393137333435355a3017311530130603550403130c44656c6567617465526f6f743076301006072a8648ce3d020106052b810400220362000424b5ad722abeee164728404ade3b7c9d7dfd9fe552399e958659c6778df6fe156c9cab2f63bc5de854866c1d58aa755bd4eef77cb499bd7be3645eab7bc4d9f0eb9fe5b33550dd975f44abcf7b0aa826caaf4cdb3e8aa7d23175df219b658a61a3653063300e0603551d0f0101ff04040302028430210603551d25041a3018060a2b0601040182e51c0301060a2b0601040182e51c0303300f0603551d130101ff040530030101ff301d0603551d0e041604144e9efe7fd969832aa85fc2edd09382bae9622e5f300a06082a8648ce3d0403030369003066023100e2e9fe36e3ac97b7c2a84d21983f1c522f8c8d23b6fa6abb8bb02f9601d91572a5df86b5e59799d7fbc7ae199a55f613023100c0b053d0aae4fe1e795beba51f99f339c6c4006d416f80df27cd1c41605170f974c7b9405f72dc70e8997fa1d0a35078']]}, h'8958d3861865502171732ff006a74067122faa7fbe9f91806b746573745f646576696365830b0158783076301006072a8648ce3d020106052b810400220362000424b5ad722abeee164728404ade3b7c9d7dfd9fe552399e958659c6778df6fe156c9cab2f63bc5de854866c1d58aa755bd4eef77cb499bd7be3645eab7bc4d9f0eb9fe5b33550dd975f44abcf7b0aa826caaf4cdb3e8aa7d23175df219b658a6182382a583032c2867e4c30abf0ac7901a4e963f85ae43dcce8d8a6297f97d3ace876cd04cc413007668ccc8ac8c32e5306f1e949890082065830bb0662aa1705eed4401820a09f473de5e50d071f7c94241ed9c6086502de0b41d972ba8509abe280f84d38bf058d87025087e295fd4a786934c2d94ed1fb609c4382382240589600307844ab59038e04dffcd9073b5de84973ba07152a0936dcb783c9bf9a432ede953c2d31ba526c2fd9b711baced156b23c003098a4fbfb1e6998f77c955c86d4c7e3e4816efd7bc6dc87ea1912d7bc7a9d0aa5a0de1f02d61608113325abc2d6b75ea60030fcc50701a8f58f5978d668a8fdd336aee73e5f61c746d12f602bb96e7aa88bd311f0992c608046c11c1e3b455199c3a982382a5830edafdbb5f06dbd1612d49c017065ad612a604c9c6bd3ce453fa763ed92683f8f3b013ead3a71191f278e57e52753d4e219ffff40', h'52c5f0ce33cde095a876e6bf88f7d4f22773f7ffd0391c1eabe4ef31fc54efaec740a83a2b53bb51f01ac441466a4aa8653545fd18d70f2ade8eb6c6e7493dca1c05b539a847e544da054b84166e8da7a96623cc507776dda00b99d38bf52132'])
*** FINALIZER CLEARING!!!!
*** FINALIZER CLEARING!!!!
*** DELEGATE Key proveOVHdr ECDSA NIST P-384 / secp384r1 Fingerprint: 3c17f9c6745612df003060699c8780cd62d4f077acd8385139fb6b355116ecea
*** Use DELEGATE Key: &{0x92b030 1629464305042763842479817120113207779297229860464712441835220309313840915290922291792750052860064382508642808077259 352942420144349342919016825373997789891805573019570364728692621346745315540336364966816820337894490946882470907279}
*** VERIFY OVHPROOF with key ECDSA NIST P-384 / secp384r1 Fingerprint: 3c17f9c6745612df003060699c8780cd62d4f077acd8385139fb6b355116ecea
*** KeyExchangeA Set to [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
*** ProveOVH is {Sign1:{Header:{Protected:map[1:-35] Unprotected:map[256:[38 102 48 129 27 147 134 74 71 176 180 245 254 244 9 112] 257:[11 1 [48 118 48 16 6 7 42 134 72 206 61 2 1 6 5 43 129 4 0 34 3 98 0 4 36 181 173 114 42 190 238 22 71 40 64 74 222 59 124 157 125 253 159 229 82 57 158 149 134 89 198 119 141 246 254 21 108 156 171 47 99 188 93 232 84 134 108 29 88 170 117 91 212 238 247 124 180 153 189 123 227 100 94 171 123 196 217 240 235 159 229 179 53 80 221 151 95 68 171 207 123 10 168 38 202 175 76 219 62 138 167 210 49 117 223 33 155 101 138 97]] 258:[11 2 [[48 130 1 168 48 130 1 46 160 3 2 1 2 2 2 1 77 48 10 6 8 42 134 72 206 61 4 3 3 48 31 49 29 48 27 6 3 85 4 3 19 20 68 101 108 101 103 97 116 101 73 110 116 101 114 109 101 100 105 97 116 101 48 32 23 13 50 52 49 50 48 51 49 55 51 52 53 53 90 24 15 50 48 53 52 48 54 50 57 49 55 51 52 53 53 90 48 23 49 21 48 19 6 3 85 4 3 19 12 68 101 108 101 103 97 116 101 67 101 114 116 48 118 48 16 6 7 42 134 72 206 61 2 1 6 5 43 129 4 0 34 3 98 0 4 10 150 59 91 110 212 150 18 160 30 222 183 47 165 2 168 204 152 98 85 3 118 127 182 217 45 25 116 0 163 226 147 66 78 207 153 135 146 13 206 40 115 7 159 160 151 155 203 2 75 9 119 15 140 68 5 211 153 202 61 64 62 12 248 69 139 213 75 189 46 216 176 195 170 69 221 102 139 55 217 213 239 135 131 72 148 173 10 143 184 192 227 249 27 141 143 163 67 48 65 48 14 6 3 85 29 15 1 1 255 4 4 3 2 7 128 48 33 6 3 85 29 37 4 26 48 24 6 10 43 6 1 4 1 130 229 28 3 1 6 10 43 6 1 4 1 130 229 28 3 3 48 12 6 3 85 29 19 1 1 255 4 2 48 0 48 10 6 8 42 134 72 206 61 4 3 3 3 104 0 48 101 2 48 26 4 71 63 222 110 247 108 80 238 141 126 252 214 94 186 201 106 237 145 96 14 138 234 154 121 192 80 249 46 49 237 110 227 48 207 195 180 230 60 107 81 72 19 107 140 177 150 2 49 0 146 100 176 73 174 54 57 140 94 98 6 209 83 11 250 71 96 202 106 120 152 189 133 101 149 118 210 188 121 153 126 26 211 13 154 148 133 201 216 28 145 29 145 117 62 20 142 102] [48 130 1 201 48 130 1 80 160 3 2 1 2 2 2 0 222 48 10 6 8 42 134 72 206 61 4 3 3 48 23 49 21 48 19 6 3 85 4 3 19 12 68 101 108 101 103 97 116 101 82 111 111 116 48 32 23 13 50 52 49 50 48 51 49 55 51 52 53 53 90 24 15 50 48 53 52 48 54 50 57 49 55 51 52 53 53 90 48 31 49 29 48 27 6 3 85 4 3 19 20 68 101 108 101 103 97 116 101 73 110 116 101 114 109 101 100 105 97 116 101 48 118 48 16 6 7 42 134 72 206 61 2 1 6 5 43 129 4 0 34 3 98 0 4 23 28 25 152 54 89 42 234 167 221 84 135 164 138 207 227 38 42 51 10 182 171 82 146 165 195 166 88 187 14 65 213 155 250 79 70 95 155 88 181 177 76 93 68 253 199 116 140 59 0 89 5 53 111 79 104 26 127 131 251 27 173 19 154 251 141 10 197 60 120 92 248 116 2 95 49 107 176 28 175 162 139 184 54 229 162 3 171 170 37 167 212 44 98 140 61 163 101 48 99 48 14 6 3 85 29 15 1 1 255 4 4 3 2 2 132 48 33 6 3 85 29 37 4 26 48 24 6 10 43 6 1 4 1 130 229 28 3 1 6 10 43 6 1 4 1 130 229 28 3 3 48 15 6 3 85 29 19 1 1 255 4 5 48 3 1 1 255 48 29 6 3 85 29 14 4 22 4 20 250 60 153 232 232 185 79 99 53 98 50 145 154 218 127 8 128 136 231 151 48 10 6 8 42 134 72 206 61 4 3 3 3 103 0 48 100 2 48 33 192 233 52 22 245 225 247 162 250 48 166 23 126 19 139 56 222 40 241 47 225 82 126 237 106 113 57 88 39 179 79 194 118 65 47 133 80 48 138 41 105 90 64 80 222 254 246 2 48 95 74 244 87 88 132 170 68 23 103 69 180 134 132 249 126 220 171 133 175 107 66 46 105 254 193 121 54 42 225 170 26 145 115 216 201 200 248 145 126 218 206 114 230 197 171 16 227] [48 130 1 194 48 130 1 71 160 3 2 1 2 2 1 111 48 10 6 8 42 134 72 206 61 4 3 3 48 23 49 21 48 19 6 3 85 4 3 19 12 68 101 108 101 103 97 116 101 82 111 111 116 48 32 23 13 50 52 49 50 48 51 49 55 51 52 53 53 90 24 15 50 48 53 52 48 54 50 57 49 55 51 52 53 53 90 48 23 49 21 48 19 6 3 85 4 3 19 12 68 101 108 101 103 97 116 101 82 111 111 116 48 118 48 16 6 7 42 134 72 206 61 2 1 6 5 43 129 4 0 34 3 98 0 4 36 181 173 114 42 190 238 22 71 40 64 74 222 59 124 157 125 253 159 229 82 57 158 149 134 89 198 119 141 246 254 21 108 156 171 47 99 188 93 232 84 134 108 29 88 170 117 91 212 238 247 124 180 153 189 123 227 100 94 171 123 196 217 240 235 159 229 179 53 80 221 151 95 68 171 207 123 10 168 38 202 175 76 219 62 138 167 210 49 117 223 33 155 101 138 97 163 101 48 99 48 14 6 3 85 29 15 1 1 255 4 4 3 2 2 132 48 33 6 3 85 29 37 4 26 48 24 6 10 43 6 1 4 1 130 229 28 3 1 6 10 43 6 1 4 1 130 229 28 3 3 48 15 6 3 85 29 19 1 1 255 4 5 48 3 1 1 255 48 29 6 3 85 29 14 4 22 4 20 78 158 254 127 217 105 131 42 168 95 194 237 208 147 130 186 233 98 46 95 48 10 6 8 42 134 72 206 61 4 3 3 3 105 0 48 102 2 49 0 226 233 254 54 227 172 151 183 194 168 77 33 152 63 28 82 47 140 141 35 182 250 106 187 139 176 47 150 1 217 21 114 165 223 134 181 229 151 153 215 251 199 174 25 154 85 246 19 2 49 0 192 176 83 208 170 228 254 30 121 91 235 165 31 153 243 57 198 196 0 109 65 111 128 223 39 205 28 65 96 81 112 249 116 199 185 64 95 114 220 112 232 153 127 161 208 163 80 120]]]]} Payload:0xc00045e300 Signature:[82 197 240 206 51 205 224 149 168 118 230 191 136 247 212 242 39 115 247 255 208 57 28 30 171 228 239 49 252 84 239 174 199 64 168 58 43 83 187 81 240 26 196 65 70 106 74 168 101 53 69 253 24 215 15 42 222 142 182 198 231 73 61 202 28 5 181 57 168 71 229 68 218 5 75 132 22 110 141 167 169 102 35 204 80 119 118 221 160 11 153 211 139 245 33 50]}}
    transport.go:56: Request 255: [101, 61, "TO2.ProveOVHdr payload signature verification failed: cryptographic verification failed", 1733247296, null]

I'm not sure what's going on, though. #21 was clearly not the fix for this particular problem (yet made it rarer?), because it wasn't the key exchange which was failing.

Two things are unusual:

1. Why is the finalizer logging twice?
2. What is clearing the proveOVHdr in sendHelloDevice, which is parsed from bytes?

My initial guesses are:

1. Resurrection? I changed the print statement and verified that the finalizing value was a different pointer.
2. This must be slice reuse in the CBOR encoder and decoder... but that can't be, because the bytes.Buffer makes a copy of all write input.

[bkgoodman]

What is clearing the proveOVHdr in sendHelloDevice, which is parsed from bytes?

proveOVHdr is not being cleared - ONLY KeyExchangeA is. Which makes sense - as that is what the finalizer does.

Stick a panic in the finalizer to stacktrace?

[ben-krieger]

What is clearing the proveOVHdr in sendHelloDevice, which is parsed from bytes?

proveOVHdr is not being cleared - ONLY KeyExchangeA is. Which makes sense - as that is what the finalizer does.

Stick a panic in the finalizer to stacktrace?

But that proveOVHdr var does not have a finalizer set. The finalizer is only set on the proof var in the (*TO2Server).proveOVHdr method.

I added these logs at the end of (*fdotest.Transport).Send:

	respType, resp := responder.Respond(ctx, msgType, &msgBody)
	t.T.Logf("Response 1 %d: %v", respType, tryDebugNotation(resp))
	t.token, _ = t.Tokens.TokenFromContext(ctx)
	t.prevMsg = msgType

	var respBody bytes.Buffer
	if err := cbor.NewEncoder(&respBody).Encode(resp); err != nil {
		return 0, nil, err
	}
	respDebug, _ := cdn.FromCBOR(respBody.Bytes())
	t.T.Logf("Response 2 %d: %v", respType, respDebug)

	return respType, io.NopCloser(&respBody), nil

And observed "Response 2" containing a sequence of null bytes within it corresponding to the KeyExchange A. However, the "Response 1" line had the correct CDN output.

The resp value is an empty interface holding the proof value which has a finalizer. Somehow this finalizer is getting called between the two Logf lines, despite resp still clearly being in scope.

[ben-krieger]

Weirdly, I can't trigger it by sticking a bunch of runtime.GC() calls inside the (*fdotest.Transport).Send method.

And more weirdly, adding runtime.KeepAlive(resp) after cbor.NewEncoder(&respBody).Encode(resp) seems to fix the data race completely. I'll keep running the test loop.

If confirmed, it means that the finalizer is sometimes running inside the CBOR encoding function!

[ben-krieger]

@bkgoodman Please try with the 1-line fix from #26. I'll keep a test loop running for an hour as well.

[ben-krieger]

I accidentally ran the tests for 5.5 hours. Calling it fixed. 😛