Broken dedup of unsupported packets causes key update churn

[andrewgdotcom]

I finally managed to catch specific examples of key-update churn in the process of being propagated across my test network. Here are the contents of a particular key on two different nodes, one just updated and one not yet updated:

 {"md5": "745d2a1014c7489d00b20809490bcfdc", "length": 607, "packet": {"tag": 6, "data": "xsBNBD4nkHsUBACGiw22DBYrC6Svmd0kll3VRG6h75reoIAHRJ+DIc61YUW1HjcwWj3Lw43iu00/TxbRz9pHVPLanRaIus5uv32GhU3rVfoanM3LsfKMszxz0gA/aPIXHTlOYqzc8/4+BcDrA3dmWSAurv+Q5GjVij9ShlsOy1ft690d8yPjeTUKzwADBQP/a6ksTL0TThzWtgAfYfboWgvdMyjZGCQ67A4pMwvR3xuSw1hkkwhMxj79UiDgn0UWnb9Ck6tnt3fImhAEkZiGvw99833ZuJ8jQZoNIT+y6SykD7wnES8HZAELatwA3rurpW47ezsrZmyXG2d3l5mRFkexU5CFoRjN2qPbNhru2es=", "parsed": false}, "algorithm": {"code": 0, "name": "unk(#0)"}, "bitLength": 0, "longKeyID": "864469ccea5b31e8", "shortKeyID": "ea5b31e8", "fingerprint": "d3dcb78aa839005e510fa5d3864469ccea5b31e8", "unsupported": [{"tag": 2, "data": "wsBvBBMUAwAXBQI+J5B7BQsHCgMEAxUDAgMWAgECF4AACgkQhkRpzOpbMegZjAP/acWUNyMFSKwohfYA74SM9xFUsQ/OjYwiZG9F/CHG2AaxZLJyDrbGLgsH4v0DSqQaA7cE49chCmmgWFaWw2xTnkv8415s+CNGWm00v6NzHCKKB65qvCmI/a7gMNXzQujHLsQuOIqDwxfAflMMJUMu6x3C8245mU21tMT9bOyMGpgD/itWdKLjgZ3/CDz0o08wd8SxigqPMD7digW3Zo/EaE2Ahcsucgpc1RiINQJCiYZ1AWRnahmepxrPZKLDzGNkYWTeZPwhib6v/PX/XEikx9hVJ1llmOHSw3Xy143sgKGR0WD0NWHcCA+3UqiU9tUTUNQ3CwlZdckIJtC6mTIQALeH", "parsed": false}], "neverExpires": true}

 {"md5": "8d7b679f0ad495ec1543dbea55621ec1", "length": 572, "packet": {"tag": 6, "data": "xsBNBD4nkHsUBACGiw22DBYrC6Svmd0kll3VRG6h75reoIAHRJ+DIc61YUW1HjcwWj3Lw43iu00/TxbRz9pHVPLanRaIus5uv32GhU3rVfoanM3LsfKMszxz0gA/aPIXHTlOYqzc8/4+BcDrA3dmWSAurv+Q5GjVij9ShlsOy1ft690d8yPjeTUKzwADBQP/a6ksTL0TThzWtgAfYfboWgvdMyjZGCQ67A4pMwvR3xuSw1hkkwhMxj79UiDgn0UWnb9Ck6tnt3fImhAEkZiGvw99833ZuJ8jQZoNIT+y6SykD7wnES8HZAELatwA3rurpW47ezsrZmyXG2d3l5mRFkexU5CFoRjN2qPbNhru2es=", "parsed": false}, "algorithm": {"code": 0, "name": "unk(#0)"}, "bitLength": 0, "longKeyID": "864469ccea5b31e8", "shortKeyID": "ea5b31e8", "fingerprint": "d3dcb78aa839005e510fa5d3864469ccea5b31e8", "unsupported": [{"tag": 2, "data": "wsBvBBMUAwAXBQI+J5B7BQsHCgMEAxUDAgMWAgECF4AACgkQhkRpzOpbMegZjAP/acWUNyMFSKwohfYA74SM9xFUsQ/OjYwiZG9F/CHG2AaxZLJyDrbGLgsH4v0DSqQaA7cE49chCmmgWFaWw2xTnkv8415s+CNGWm00v6NzHCKKB65qvCmI/a7gMNXzQujHLsQuOIqDwxfAflMMJUMu6x3C8245mU21tMT9bOyMGpgD/itWdKLjgZ3/CDz0o08wd8SxigqPMD7digW3Zo/EaE2Ahcsucgpc1RiINQJCiYZ1AWRnahmepxrPZKLDzGNkYWTeZPwhib6v/PX/XEikx9hVJ1llmOHSw3Xy143sgKGR0WD0NWHcCA+3UqiU9tUTUNQ3CwlZdckIJtC6mTIQALeH", "parsed": false}, {"tag": 2, "data": "wsBvBBMUAwAXBQI+J5B7BQsHCgMEAxUDAgMWAgECF4AACgkQhkRpzOpbMegZjAP/acWUNyMFSKwohfYA74SM9xFUsQ/OjYwiZG9F/CHG2AaxZLJyDrbGLgsH4v0DSqQaA7cE49chCmmgWFaWw2xTnkv8415s+CNGWm00v6NzHCKKB65qvCmI/a7gMNXzQujHLsQuOIqDwxfAflMMJUMu6x3C8245mU21tMT9bOyMGpgD/itWdKLjgZ3/CDz0o08wd8SxigqPMD7digW3Zo/EaE2Ahcsucgpc1RiINQJCiYZ1AWRnahmepxrPZKLDzGNkYWTeZPwhib6v/PX/XEikx9hVJ1llmOHSw3Xy143sgKGR0WD0NWHcCA+3UqiU9tUTUNQ3CwlZdckIJtC6mTIQALeH", "parsed": false}], "neverExpires": true}

We can see that the second node's copy has a duplicate packet in the unsupported (i.e. Others) area. Widening our search we see all such churny keys (to a mild degree of confidence) are either v3 keys, v4 keys with elGamal-sig primary algos, or keys with no keyid in their self-sigs. This makes sense as these are the most likely sources of unsupported packets.

It is not immediately clear why dedup isn't working; investigations continue.

(Note also that the length fields are complete fiction)

[andrewgdotcom]

By adding a couple of logging lines to Merge() it quickly becomes clear that during certain recons, the number of Other packets on susceptible keys is doubled, while on others it is (correctly) reduced (again). If dedup is broken, packets will naturally be doubled as the merge strategy is to concatenate both versions of the key together and then dedup the results.

msg="DEBUG Other packets increased from 1<<1 (2) -> 2 on fp(eb62debe0b8224caf8e440807b2c2057)" 
msg="DEBUG contents = [0xc0018812c0 0xc001880fc0]" 
msg="DEBUG Other packets increased from 7<<7 (14) -> 14 on fp(535f480a0d3e4a38a811b1afbe08c8b0)" 
msg="DEBUG contents = [0xc001ab5680 0xc001ab56c0 0xc001ab5700 0xc001ab5740 0xc001ab5780 0xc001ab5800 0xc001ab5840 0xc001ab42c0 0xc001ab4340 0xc001ab4380 0xc001ab43c0 0xc001ab4440 0xc001ab44c0 0xc001ab4500]" 
msg=upsert inserted=0 label="recon :11370" remoteAddr=192.168.80.10:55840 unchanged=98 updated=2 

It is interesting to note however, that:

• if packet numbers are doubled they are doubled exactly - if one Other packet on a key is duplicated, they all are
• during any given sync cycle, either all(*) merges result in Other-doubling, or all result in correct dedup (but see below)
• for any given peer, either all sync cycles are doubling or none are
• peers with larger diffs are more likely to be doubling

I found a small number of exceptions to (*) above, where a few keys were correctly deduped during a doubling cycle, and in all such cases the number of packets was not halved:

msg="Number of unrecognised packets DECREASED from 47 to 24 on fp(837381669d1a319c5fdd827adeeabbd4bb30ce35)" 
msg="Number of unrecognised packets DECREASED from 3 to 2 on fp(5972c48224c1e7e62aa0275d1150ee33c1a000b0)" 
msg="Number of unrecognised packets DECREASED from 12 to 8 on fp(d299cc38d0cfebf83ad79b1821c8fb858c71493f)" 

After further investigation it turns out that the uuid() function is not stable when called on Other packets:

msg="DEBUG start contents = &{{{bb3f87e2e63b281eda2d9757576c9d81 6 true false 0 [198 143 3 56 124 252 23 0 0 1 4 0 170 26 107 18 40 165 42 17 7 141 198 7 162 216 113 132 93 112 27 174 40 189 164 207 53 132 9 211 202 166 159 94 65 173 240 168 54 168 105 154 237 10 90 194 48 139 212 36 0 8 206 232 212 249 24 158 169 35 239 39 223 143 208 242 55 199 242 32 17 127 177 209 162 9 178 73 228 117 149 12 30 17 36 145 183 77 19 228 15 23 223 189 24 83 83 127 117 37 127 62 107 251 254 19 58 106 52 4 13 115 73 252 92 250 90 29 252 75 69 22 39 218 191 108 13 177 103 161 0 17 1 0 1]} bb3f87e2e63b281eda2d9757576c9d81 1a761bd0c6fbad72 1a761bd0 2000-01-12 22:11:35 +0000 UTC 0001-01-01 00:00:00 +0000 UTC 1 1024 [] [0xc004c51d40 0xc004c51a80]} 696b8a8bc08c45f5071fb82850eaaf24 883 [] [] []}" 
msg="DEBUG node uuid = bb3f87e2e63b281eda2d9757576c9d81_4169a3e6706e8ebceda3941f3f7d323d" 
msg="DEBUG node uuid = e5qxevp3sbBGvowCE7bYvSHusFqYibn7dJgjLWTd25ip_9327fd41cd96ba66c0602ef1e714d933" 
msg="DEBUG node uuid = 8EwiD5xfTScJ9waXqcFp4AGd5eEG9RYVy4EbzdNZzuEp_9327fd41cd96ba66c0602ef1e714d933" 
msg="DEBUG outer contents = &{{{bb3f87e2e63b281eda2d9757576c9d81 6 true false 0 [198 143 3 56 124 252 23 0 0 1 4 0 170 26 107 18 40 165 42 17 7 141 198 7 162 216 113 132 93 112 27 174 40 189 164 207 53 132 9 211 202 166 159 94 65 173 240 168 54 168 105 154 237 10 90 194 48 139 212 36 0 8 206 232 212 249 24 158 169 35 239 39 223 143 208 242 55 199 242 32 17 127 177 209 162 9 178 73 228 117 149 12 30 17 36 145 183 77 19 228 15 23 223 189 24 83 83 127 117 37 127 62 107 251 254 19 58 106 52 4 13 115 73 252 92 250 90 29 252 75 69 22 39 218 191 108 13 177 103 161 0 17 1 0 1]} bb3f87e2e63b281eda2d9757576c9d81 1a761bd0c6fbad72 1a761bd0 2000-01-12 22:11:35 +0000 UTC 0001-01-01 00:00:00 +0000 UTC 1 1024 [] [0xc004c51d40 0xc004c51a80]} 0bd7ed101270c7b7ee7cb4af6fe11a49 883 [] [] []}" 
msg="DEBUG Other packets increased from 1<<1 -> 2 on fp(18d9c6757579d2ade182b36e2e78f3bb)" 

The uuid is created by this snippet in openpgp/resolve.go:

		uuid := node.uuid() + "_" + hexmd5(node.packet().Packet)

As we can see, there are two packets in the offending key above that have exactly the same MD5 sum (9327fd41cd96ba66c0602ef1e714d933) but different uuid prefixes. These are therefore not being recognised as duplicates of each other. UUID population is identical across the non-primary packet parsers:

			UUID:   scopedDigest([]string{parentID}, uidTag, buf.Bytes()),

however Other packets see different parentIDs depending on context. In openpgp/io.go:

				if signablePacket != nil {
					badParent = signablePacket.uuid()
				} else {
					badParent = pubkey.uuid()
				}
				other, err := ParseOther(badPacket, badParent)

So let's log which branch is taken and what uuid gets passed to ParseOther. Note that the other debug outputs are the node uuids (actually {parent}_{child} uuid pairs, the variable name is misleading) as collected by dedup() (called twice, once on the imported copy and once during merge, and descending recursively to find any signatures) and the contents of the merged key before and after dedup, in the following order:

• badParent(s) of key on the wire
• dedup node uuid(pair)s of key on the wire
• badParent(s) of key in keydb
• start contents of smushed key
• dedup node uuid(pair)s of smushed key (with possible recursive descent)
• final contents of smushed+deduped key

Here's an example of a correctly deduping merge:

msg="DEBUG badParent is signable 11cac3d61bc444704e8549940304a203" 
msg="DEBUG node uuid = 11cac3d61bc444704e8549940304a203_fbc2fba00aa720b58af4c05073b4feea" 
msg="DEBUG node uuid = 2rjC5AwsLE6aYqzC7DkgXmfXPADah13Be4L4wRnomCMG_8d1c7aec1c9e87bf67141f6ce66f7a3b" 
msg="DEBUG badParent is signable 11cac3d61bc444704e8549940304a203" 
msg="DEBUG start contents = &{{{11cac3d61bc444704e8549940304a203 6 true false 0 [198 192 79 3 60 199 105 44 0 0 1 8 0 194 9 156 11 154 19 134 50 76 96 80 226 189 251 37 121 200 234 109 168 54 104 41 247 46 125 70 48 75 231 86 227 120 181 150 62 146 90 152 107 43 220 57 121 44 190 209 31 120 80 217 153 119 4 191 230 15 209 251 84 179 30 205 182 158 160 174 115 70 123 90 65 203 17 238 42 206 222 7 42 134 64 166 25 92 159 112 64 64 228 130 183 18 134 151 200 102 184 184 220 22 8 3 111 232 67 194 45 46 18 108 190 171 198 25 131 250 218 117 140 127 145 225 194 11 23 37 118 162 221 254 188 146 137 151 173 8 228 105 105 11 116 118 216 254 137 84 52 61 157 121 51 241 117 224 13 51 63 22 58 238 108 207 116 30 102 24 200 213 128 80 238 11 233 91 198 174 153 247 150 243 219 83 140 210 41 222 57 45 40 155 211 40 118 248 231 8 205 196 36 239 116 163 163 36 163 56 198 127 245 183 112 252 89 250 116 69 186 51 97 187 223 175 194 199 132 166 100 135 244 36 216 159 217 171 48 14 235 55 34 255 218 179 164 220 21 104 153 34 76 190 160 123 242 198 29 0 17 1 0 1]} 11cac3d61bc444704e8549940304a203 d16c2fb70aebc422 d16c2fb7 2002-04-25 02:25:48 +0000 UTC 0001-01-01 00:00:00 +0000 UTC 1 2048 [] [0xc000bb9bc0 0xc000bb9ac0]} 48d36a4c2954c113e78b4d991709930a 1426 [] [] []}" 
msg="DEBUG node uuid = 11cac3d61bc444704e8549940304a203_fbc2fba00aa720b58af4c05073b4feea" 
msg="DEBUG node uuid = 2rjC5AwsLE6aYqzC7DkgXmfXPADah13Be4L4wRnomCMG_8d1c7aec1c9e87bf67141f6ce66f7a3b" 
msg="DEBUG node uuid = 2rjC5AwsLE6aYqzC7DkgXmfXPADah13Be4L4wRnomCMG_8d1c7aec1c9e87bf67141f6ce66f7a3b" 
msg="DEBUG descending..." 
msg="DEBUG node uuid = 2rjC5AwsLE6aYqzC7DkgXmfXPADah13Be4L4wRnomCMG_8d1c7aec1c9e87bf67141f6ce66f7a3b" 
msg="DEBUG final contents = &{{{11cac3d61bc444704e8549940304a203 6 true false 0 [198 192 79 3 60 199 105 44 0 0 1 8 0 194 9 156 11 154 19 134 50 76 96 80 226 189 251 37 121 200 234 109 168 54 104 41 247 46 125 70 48 75 231 86 227 120 181 150 62 146 90 152 107 43 220 57 121 44 190 209 31 120 80 217 153 119 4 191 230 15 209 251 84 179 30 205 182 158 160 174 115 70 123 90 65 203 17 238 42 206 222 7 42 134 64 166 25 92 159 112 64 64 228 130 183 18 134 151 200 102 184 184 220 22 8 3 111 232 67 194 45 46 18 108 190 171 198 25 131 250 218 117 140 127 145 225 194 11 23 37 118 162 221 254 188 146 137 151 173 8 228 105 105 11 116 118 216 254 137 84 52 61 157 121 51 241 117 224 13 51 63 22 58 238 108 207 116 30 102 24 200 213 128 80 238 11 233 91 198 174 153 247 150 243 219 83 140 210 41 222 57 45 40 155 211 40 118 248 231 8 205 196 36 239 116 163 163 36 163 56 198 127 245 183 112 252 89 250 116 69 186 51 97 187 223 175 194 199 132 166 100 135 244 36 216 159 217 171 48 14 235 55 34 255 218 179 164 220 21 104 153 34 76 190 160 123 242 198 29 0 17 1 0 1]} 11cac3d61bc444704e8549940304a203 d16c2fb70aebc422 d16c2fb7 2002-04-25 02:25:48 +0000 UTC 0001-01-01 00:00:00 +0000 UTC 1 2048 [] [0xc000bb9bc0]} 48d36a4c2954c113e78b4d991709930a 1426 [] [] []}" 

Note that the badParent of both bad packets has been identified as the primary key - a primary key's uuid is always its rfingerprint.

And here's a broken one:

msg="DEBUG badParent is signable gogbKE2oJ9iMdraHqFyoxn63Y1eQqHDZitsY6xXxNhi2" 
msg="DEBUG node uuid = 59cbfe2ce8c50140a44682805f83082c_2df3da08fa855ed59eeb79049582c6bd" 
msg="DEBUG node uuid = gogbKE2oJ9iMdraHqFyoxn63Y1eQqHDZitsY6xXxNhi2_8ba00d693c00a493505ebb0e7f7b94f3" 
msg="DEBUG node uuid = fzpYLq4pGNccCLt3JwYrWGrzWWFWXcaqEMNRaJg7LcT5_3b5dec072efd3a5fbb41e099c85dded2" 
msg="DEBUG badParent is signable 59cbfe2ce8c50140a44682805f83082c" 
msg="DEBUG start contents = &{{{59cbfe2ce8c50140a44682805f83082c 6 true false 0 [198 192 79 3 64 15 145 16 0 0 1 8 0 176 177 242 128 0 112 206 236 195 140 180 151 237 198 9 140 38 111 137 223 103 89 129 207 222 20 19 76 194 177 69 226 83 117 65 250 7 54 111 186 17 112 40 148 124 109 114 189 7 21 37 101 58 9 255 133 220 250 123 94 55 135 56 228 199 75 8 128 152 158 138 205 88 9 2 192 195 1 73 150 88 136 137 38 89 245 109 198 185 193 251 24 37 237 216 98 78 202 10 108 93 112 239 206 211 155 41 11 9 198 246 238 182 22 212 60 84 142 204 93 224 175 219 221 35 9 50 123 50 129 22 98 10 6 203 122 207 52 33 182 111 54 182 177 206 203 154 41 53 64 62 157 88 124 255 173 130 152 250 184 213 137 202 53 221 203 205 87 6 203 155 228 191 148 168 128 152 95 119 150 240 182 231 171 116 121 64 33 166 99 233 208 7 145 189 133 56 180 174 150 172 161 255 20 115 218 165 69 184 77 134 206 42 60 239 212 223 40 14 117 169 168 136 19 194 228 124 96 147 242 37 204 3 132 151 230 78 182 159 45 214 181 139 52 60 171 213 56 58 200 61 196 177 249 148 205 0 17 1 0 1]} 59cbfe2ce8c50140a44682805f83082c dc499f1b4cd38ca3 dc499f1b 2004-01-22 09:00:00 +0000 UTC 0001-01-01 00:00:00 +0000 UTC 1 2048 [] [0xc0055d4400 0xc0055d4100]} 1cc4ace4077c102c79cf5fb53cc32ab1 1369 [] [] []}" 
msg="DEBUG node uuid = 59cbfe2ce8c50140a44682805f83082c_2df3da08fa855ed59eeb79049582c6bd" 
msg="DEBUG node uuid = 6sd4nvGq2SCHWgX6FyTqTFqeWVsBTkwg5xGb7ozxVbMV_3b5dec072efd3a5fbb41e099c85dded2" 
msg="DEBUG node uuid = fzpYLq4pGNccCLt3JwYrWGrzWWFWXcaqEMNRaJg7LcT5_3b5dec072efd3a5fbb41e099c85dded2" 
msg="DEBUG final contents = &{{{59cbfe2ce8c50140a44682805f83082c 6 true false 0 [198 192 79 3 64 15 145 16 0 0 1 8 0 176 177 242 128 0 112 206 236 195 140 180 151 237 198 9 140 38 111 137 223 103 89 129 207 222 20 19 76 194 177 69 226 83 117 65 250 7 54 111 186 17 112 40 148 124 109 114 189 7 21 37 101 58 9 255 133 220 250 123 94 55 135 56 228 199 75 8 128 152 158 138 205 88 9 2 192 195 1 73 150 88 136 137 38 89 245 109 198 185 193 251 24 37 237 216 98 78 202 10 108 93 112 239 206 211 155 41 11 9 198 246 238 182 22 212 60 84 142 204 93 224 175 219 221 35 9 50 123 50 129 22 98 10 6 203 122 207 52 33 182 111 54 182 177 206 203 154 41 53 64 62 157 88 124 255 173 130 152 250 184 213 137 202 53 221 203 205 87 6 203 155 228 191 148 168 128 152 95 119 150 240 182 231 171 116 121 64 33 166 99 233 208 7 145 189 133 56 180 174 150 172 161 255 20 115 218 165 69 184 77 134 206 42 60 239 212 223 40 14 117 169 168 136 19 194 228 124 96 147 242 37 204 3 132 151 230 78 182 159 45 214 181 139 52 60 171 213 56 58 200 61 196 177 249 148 205 0 17 1 0 1]} 59cbfe2ce8c50140a44682805f83082c dc499f1b4cd38ca3 dc499f1b 2004-01-22 09:00:00 +0000 UTC 0001-01-01 00:00:00 +0000 UTC 1 2048 [] [0xc0055d4400 0xc0055d4100]} dd490761f5a9b83d44fe15c2daee968b 1369 [] [] []}" 
hockeypucknewi_1   | time="2022-07-29T17:09:09Z" level=error msg="DEBUG Other packets increased from 1<<1 -> 2 on fp(c28038f50828644a04105c8ec2efbc95)" 

The obvious difference with the properly deduping example is that the bad packet on the wire has been assigned to a non-primary-key parent packet (the badParent's UUID is not a fingerprint, so must itself be a child), while the one from disk has been assigned to the primary key. This would appear to indicate one of the following:

a. the parent context of Other packets is being lost on (de)serialisation to disk
b. incoming Other packets on the wire are being incorrectly assigned to the wrong parents
c. both of the above

The simple solution may be to simply drop all Other nodes. If we are incapable of handling them correctly, we shouldn't handle them at all.

---

Note also that after a particularly heavy doubling session, a torrent of prefix tree errors appears in the logs (see #170 (comment))

[andrewgdotcom]

This appears to be a duplicate of #9 😬

[andrewgdotcom]

This also appears to be partially caused by the existence of V5 signatures in the dataset, which ProtonMail/go-crypto cannot (yet?) parse.

[andrewgdotcom]

It looks like #9 is a red herring - the duplicate packet handling code introduced there was refactored out ages ago.

[andrewgdotcom]

There's still something off with the parsing of unsupported algorithm types. The offending key in the OP is displayed as an unknown key type unk(#0) even though it is obviously an elgES.

pub unk(#0)0/d3dcb78aa839005e510fa5d3864469ccea5b31e8

Is it worth fixing this? Or should we just drop these keys entirely?

[andrewgdotcom]

It seems this is either caused by, or very closely related to #199. Validating direct sigs made the churn orders of magnitude worse, but only after peering with a node that had freshly restored from dump (and thus had an accurate PTree).

[andrewgdotcom]

So.

It looks like the issue may have been a subtle inconsistency between the ser/de behaviour of OpaquePacketReader and jsonhkp when encountering unexpected packets. Keys coming in on the wire from an SKS peer are parsed via OpaquePacketReader, but keys read from disk are parsed via jsonhkp, and the bad packets were being attached to the key in different places, leading to inconsistent context tagging, which broke the deduper. Dropping bad packets with extreme prejudice (in #135) appears to have cleaned up the vast majority of churn - there are still issues with misplaced good signatures but I will treat them separately in #278.

(I have opened #282 to track the length fields mentioned in the OP)