[MDEV-13893] encryption.innodb-redo-badkey failed in buildbot with page cannot be decrypted Created: 2017-09-22  Updated: 2019-09-13  Resolved: 2019-05-10

Status: Closed
Project: MariaDB Server
Component/s: Encryption, Tests
Affects Version/s: 10.2, 10.3, 10.4
Fix Version/s: 10.2.25, 10.1.41, 10.3.15, 10.4.5

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 2
Labels: None

Issue Links:
Relates
relates to MDEV-12253 Buffer pool blocks are accessed after... Closed
relates to MDEV-12699 Improve crash recovery of corrupted d... Closed

 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2/builds/9687

encryption.innodb-redo-badkey 'cbc,innodb' w2 [ fail ]  Found warnings/errors in server log file!
        Test ended at 2017-09-20 15:48:54
line
2017-09-20 15:48:48 3072805184 [ERROR] InnoDB: The page [page id: space=4, page number=1] in file './test/t1.ibd' cannot be decrypted.
2017-09-20 15:48:48 2939935552 [ERROR] InnoDB: The page [page id: space=4, page number=2] in file './test/t1.ibd' cannot be decrypted.
2017-09-20 15:48:49 2939935552 [Warning] InnoDB: Table in tablespace 4 encrypted. However key management plugin or used key_version 0is not found or used encryption algorithm or method does not match. Can't continue opening the table.
^ Found warnings in /mnt/buildbot/build/mariadb-10.2.9/mysql-test/var/2/log/mysqld.1.err
ok
 
 - saving '/mnt/buildbot/build/mariadb-10.2.9/mysql-test/var/2/log/encryption.innodb-redo-badkey-cbc,innodb/' to '/mnt/buildbot/build/mariadb-10.2.9/mysql-test/var/log/encryption.innodb-redo-badkey-cbc,innodb/'



 Comments   
Comment by Alice Sherepa [ 2017-10-23 ]

http://buildbot.askmonty.org/buildbot/builders/p8-rhel7-bintar-debug/builds/3010/steps/test/logs/stdio

2017-10-20 12:55:39 70367219652752 [ERROR] InnoDB: The page [page id: space=4, page number=1] in file './test/t1.ibd' cannot be decrypted.
2017-10-20 12:55:39 70367219652752 [Note] InnoDB: However key management plugin or used key_version 1 is not found or used encryption algorithm or method does not match.
2017-10-20 12:55:39 70367219652752 [Note] InnoDB: Marking tablespace as missing. You may drop this table or install correct key management plugin and key file.
2017-10-20 12:55:39 70367219652752 [ERROR] InnoDB: The page [page id: space=5, page number=1] in file './test/t2.ibd' cannot be decrypted.
2017-10-20 12:55:39 70367219652752 [Note] InnoDB: However key management plugin or used key_version 1 is not found or used encryption algorithm or method does not match.
2017-10-20 12:55:39 70367219652752 [Note] InnoDB: Marking tablespace as missing. You may drop this table or install correct key management plugin and key file.
2017-10-20 12:55:39 70367091487104 [ERROR] InnoDB: The page [page id: space=4, page number=2] in file './test/t1.ibd' cannot be decrypted.
2017-10-20 12:55:39 70367091487104 [Note] InnoDB: However key management plugin or used key_version 1 is not found or used encryption algorithm or method does not match.
2017-10-20 12:55:39 70367091487104 [Note] InnoDB: Marking tablespace as missing. You may drop this table or install correct key management plugin and key file.
2017-10-20 12:55:39 0x3fff9d7df180  InnoDB: page_zip_decompress 1: 24288 8192
2017-10-20 12:55:39 70367091487104 [ERROR] InnoDB: Unable to decompress ./test/t1.ibd[page id: space=4, page number=3]
2017-10-20 12:55:39 70367091487104 [Note] InnoDB: Row compressed page could be encrypted with key_version 1
2017-10-20 12:55:39 70367091487104 [Note] InnoDB: Page [page id: space=4, page number=3] zip_decompress failure.
2017-10-20 12:55:39 70367091487104 [ERROR] InnoDB: Database page corruption on disk or a failed file read of tablespace test/t1 page [page id: space=4, page number=3]. You may have to recover from a backup.
2017-10-20 12:55:39 70367091487104 [Note] InnoDB: Page dump in ascii and hex (8192 bytes):
 len 8192; hex 2e4650eb00000003ffffffffffffffff00000000001bf3c145bf0000000182b1289c0000000440a1e774dee2743a3a55bba71f8f0eaf3ecc35d9868e3cd4d3c9c70a164703647eab38134bf07f03af64aaca55ec568329d8fa1ebfde6f6ccb1c180920e91024310c5850674f191ba9562fb44b89bbf80e91d9221637c89b0d090ffaaf222c078e1a889f542b6102d8afc9cf9f9fc9cd48162a0c9bc0ef16a9ec1aa184133edcd74efa204c3312785673130587aca816f475cc3d0a24a977c12aecc274087692f85f152e0226bc584ef8bc34fc2ac0822ab4ac7c32e7006270bbed17362d0e71c2072275f6df558df18d322ee7dbd82e95ccb8e282695acd74646563c610b3d450dbf1e9f8ee5a4cb41d2b993e3f598240c264455ece7f323d1aa75c2bdb12a5345d5e646907db758de002af6c69113d982927e60f0d77d5b5b27aec2b88ecd3a738eef2293aa233c767c8746da8c614e8f24810818b43795b2b6c6ca67bb4d01d30e00310ce4c3c633ea30ebc6df6f21294c6b73cd45d6284684cc03621fe6e8c99ea42e69931672635d12489d98bf2249e6b3b3a07d1c2a6386b3e628bd2d61da90ef7c641fe4b7f4508474c1f080d0373231b6c74e68dcd5c86ddd4bcaa6f823c33bb09c90164b6a72f1c96721f7a397b3e25e285cb39e70dd7440e808b3dbbc64a8f88b355d492a68633d75f44cc8240796547b523da345ad2bcd0a2292cbe17b0855292d78923a9445f6b1cf54abb22f9aee08de100c2f8659b78b1897b8590113514c3bc0124d121128bea4efc6a2f951e20d2714e275ece4dc1301beea0fffa767683e20d83f0b7984bd2f30c93b6aa90bca0ea51fbb9105a45c19e459c6fe69f2fde97286aced4df5fb356d8ad9bf4a37f45da0f69c9349b2b58a20002acea58a4acc51cdd0b40ced6bf1f0a8bb8866e94516919dbc02605e37dde3bb5a26831dbe395ad07461861bb593090dd9a89bfa7b1b58fb8b2cb9ca482f9ff81717869821fb14d5bbd5703d3b206ad1a8500cbc6ff42e67d54b70cd827e3a21e50e6899745cb4473cc06d32d6334ca73e4fd3035185eb3edf5b26a207013af9853935cae2878116f2c9f789071de41c3937c2a974fa234ba7199a258bd70fd1edbc63296471f5977391bd1b560916d5319944b515120e7d2ed866cab282d55fae4df24fbfdc497ea7303f749302a7e0248a1418f5c8dfdc2cf8c76bf7187b78e8a5ee1e8d5903a7f51402e9ef7290c96dc9493b4931d48ca1be2a5f60c42abaaecfa3a8cc6198247f4c73cf4581c49303c3c1d44cebcb218648cf7f56aed57790540db3d997ae671e0cdecb9f13fb286be7034db494bf2b8d3caed0a95fea3780076ab164a3945570ee2555c437e6710feb7c807be40b8548f0c17c4abc85a0cebdd1b7c31c9018200bbaf4c40727dc1d6cc4c220e752dfc9a59e1f987f7522129720cec00a18c5232e6dc419fae116c784572c162a0d93fb56bf40d74cc739c53e69cae38261e7eb8977169a1f4d480f201181d35a19a8f039c177904969c420b62c49c95d7db2f37624e5bfae90c76608a7b0de0553dca8089afee7685ac55461f2f9ba6e63f3ac3b0b1d5268c7e64afed8aae62a10a8ed90776947641d942aba508a463d938ec70c2415ccbfed296f9260a09334a3498527d243722a47b4df58b51145fce30f8b03ba3f7a0a364eb0536d921608b70c96381aee84ea90d13c27c95671bc907c5bcb837e67f7a90092d0d88b909a2ced7771c5788288a1a07fe123c85946904b4473274a3c3acfe58ef2153dd96d18624f6726a770eda3fc5f604cf30fe3da6b0a20c912df8185166a71a30b0d6f74e976186fb8e8b5da005b65d38b5d3eb90a080648c745bf003612846d793b89e6710749e8a27e59dd5f7f0f37e9b03e39c7fd56f6c7696f4c36e41b6cb00a2dc1550486678e9daa4c194c031bea9304d5cad9b82751845785e29e2a682491f52ab03c3cf68d21ca29b6ab95c37c15429b95e6742e4d307e11ad1805608804be78dc51f1164aa518262434edb92ab98efd5f38b50b12185d11728ee3f4ad5cee9d4f704667a9065b43eccc3c41c46892a6e89e301140fa81ce7a2b14ad1eed7ed723895dab2b91c6ec16b110f22a3f93900c256c0dc892bacd2ca3a15c5abcbe4b1160899c1cda010a90b8e67eb16fe4ecdc160eb8d02bbd2d3c172c7c5e4194e26f31c14bda529593941fffcf698b2b4e180caa38cdc8ec4a3f030f65dceac22d461128c2ac4fddb9287c6aba4d55e32000c767d2bb5387fd419b268f6ac811dc8aebf6841bf136d8c1c0d8c5a9bd8aeb29ae3d927fa1dc7d631a4ffa5ef099863e3a437b35aad85a6370eee0e27d599bba6a079f1affe4692d94a99dc24ef2c257a14093e9b4c52f7e0ee42c42fcb7cac40b726be63c1d8d8e957898bac6d4bc3fa8e08fefd0a7938c641ddd7c43c2fc938700b44255b666e7584788828c384a33319569954def60666f882c46b53a435819f175deac4a5b06c07f7cc40a0e7f9b43688bbbf77c098b405f6132226363368dfa14fe64f404545d05bca0b07a1d3fc69ad8e575fa870b3eb6537f9cd9dc04628b64036e18c36bfe4d4147e77887ae72130701aed8c62772af53c08820cb066e0e7d64457040be2b4d1498097fff30d88b7efa173315551aca3f478dd127cfd249be00c9050f9c06aa9219511649654aa93429dad7ac3138bc84fdb8e5738e29634549117ca4c723ede34952f629288b450a9e5b4a87358dd5923b9fe74e11490558b886663e9369d0d873d7d1a5f85723bcb53f7b6d89386b47d148332054a178f763cf8ffc09f0a01c5c62895ded1f86e53ca5313b814ab41b69212a341cf36cf37a4112bcc0ec59468c28840eb38ab76d7f5653074a4afd81eda787df093d6cc0f0f12b5aa0dae32ccbef1a486db744d206e132d1c9ee031461078f2892a0bfe8d58efcbd419ac2243f89e61047d089364fe8827c109e5ae92abe247dc16b1cfbdebf21c9460217e8a98e1e81760b5ea45e747a4d3f6b49eaf69126948fdfc397afe0e3b36d2f5910bdef3c9fce1078050017e0170658cd4daeef95e6a88fba7070ad814bc281f8ec36b6c94126ef31b1c24780907870c43b18eeec6a9a78a5b485d728a8ee6c6e30941a37139e779b26eba0e0c8c68311af8874a2566ff21eb4f8edb700550cb2fc01dc1a2b3c6635e14e542c2f5b3422a839966d9d105126f816e8fe037aa52dfc5604adc150fa41b2c6bd73111311bab9c5e8b9efc917b820755a418cd96183f05085f5d183ec2273a56eb5b201a54751c1a825a88ee60fad077e3d156210979682cba9c8ac9c308a119a6ff5fb3e50f4101513f9c931952ecb2180e85d193dd4b26ee055681e4695fd4ee5360129c01ebadfa4af7473d20fd7d91d32a0c4546587c77019b70b4dd56cc465385ca21ae3b982ed9a465eebfb951b667d2ed0d09eb52fdd2df141c75de898ba99ccd2f9033b87697d1eb5626e18958408d3bec8fdb97bce1e004065cfe602ebcd22265a3c8be35d79d71e57c0bda98a85c362ac860d3b594892430c63b36784344165cb44b190656085e28b564956a1d63646e028cf7d51b0d42f7c74c755a89d11410daf1c92a4c5e6a8c521fcd28183416b9a9c614cdc35b5968df911186fb60dc55005555228442a1b23cc4d4064a037768f5b7b35f87cc5db093877627eb35320a28ffbe7deda5445f665b05f9d0e074b8239501f74513844ce40078bf0f3576164979551595f394d9f47a6611f5c3cb565497973dc4a0974fbef6212e6f3a94ff8924d4184d0f83a309688dc5df1384a2484e7202564b7a2b350113e8cf84ac71e2ac4b5de5f46d6f620fce97be3f7cdfb7b13671e0c797647d15fb4c4871dc195311d73e8f7dae3c9550e6b3c19ec113e9b5a60f60d86e9b930811352daefcec50f1e0a3f9d29169b6e46280dab64f761e63e4b682a088287226f1db89144848af088dd74f0119e025db2549db47344fa300b1d4cd873e99da8136424884b73db0d758bf139c80bfa31febc7e91e00462592b531c30d3c3e917245d96702e76e6d0224ce7aff8ac6bc289973a397586cde25a5e0d7f7d288092dd747550f366768735fd3b94e3964c85296ca00f0b1cd0d24bd6a1e21932b145e1d70741f16cf66e6d8f65553147608d8e186a911c967b6e8fccae6749423e89b1920328af65bdadb63bf18953dff10a2130476dddfb5c9bbef8c6c5635db354db38098562e372cc157719e1e269573d2c18854b1777207792b2159834ea13de235ff90f1532a7629a6cd47ec9f9f0e3d0a5e7bd3d2180146fa9980e1edb7599cf74ccc5c5833cbaf8e807fc91fd07d6afdf749572fb385398c62879b105822722d8a0c8929b26865b0b4b5fbc0bd4b0b1ace2695d341e8c880908e8da5260c40b3d5088b7d9d93d012a1f1dcd45affbfed848969bcbccf0b6ce0ece3f3b4c6c29d3488549730ecf70411e2c48a3e00cc1a69ac0a91ff54c271fce44a67fee75acdfc236ff6d55df26b8206b1c82cc91df707e847e678edbe1de6db901e39ce8b988036a48f461510b5878f41f269212b1e2337eb20b92cd68f9e731a0df54a4901234a423ae4fcc9dbb35602130cff75d923f4f0f8809920f867eaeb47a14a751c2441391f3f0eef8d2c7177029cfd5f4a70eedb65261bc96728f5dd438b33bd8581940966b402d8f3ac1be1dc111e9d7c93596abb691237186ee3737d7fbc8ebcd5650b37a82b38b2c0f495cf98246075893651e0ca4e18c09abcfbd3fad3352920a85f35dcb4fa2c277df4de2a0c1bc2e1fc6c49de30cb3900d4b6c0db9d731ee9747fcc6a0cf6759d562db48b107707a96b766ed8f0c961355357d02a9f3231237654c54c21da1a0289082f63aa0cb5773a9143eee757425c17a3e6bbabbd48c086d1295c83a1620c805675f98f07bd00fc0cab8b6cd032a43bb54ae80ba661b0b2ba46adbf30ba18b237bdefbe3f30de04fed480952513c164a2d5d4ed74587cae923ed914113ee746727f0e40331018fbe57a0067a2d1386630e122854ad5661f670101185ded1be91e3d3a03e2e45a451ae4953d3720e20bc9c202d5ed006f88e2ecac9b4893b6795100cb33a893122fea10e2665f69248e7db3ba5253fc37cdc7372a2534f92849ae583036c1044a747dd231362b3cf1072bc9d6f4a1abcd47826a0963e3dae8903cf1ff804fab544524449c8988a3c28a89502dda10a5843301553711abaeb646bdc4ea641c186b25f8fdc216318c4e3f3ae07d13a8006fc4e5296bd680a06ebb6c215dbc61f066d17ba834e100ed5820c5d4d75aeadcf402fb537ef1b87aefafca4166cecc72d55bc76b817d4b7545a43ee618158563b253f7ce9f514370b744b912bc9932b10f4409fe2a0760d9cfa02122ddb3c508dd55045ac825345dfe9a15877226a3417186bcc2a6c15ec4da2f2cfb24cdcfc9f81746679c01a10a162cb4d0da97dc45422e3172c88adceacc6d251982caf121771fc72bec85b91e2dd4e05dce7a1b1b50bf562d6f15aed8d442958aa5789608e33f7a0d77aa273747ae8006a0b3de5e07f447899877ca9e41734e211d6f2967d6af8139a823379eed1c0a1d1a85911ea5764a4aec94e62f0fe9219dba5898e5289989a9d5c124fa3b5bfecd476561b4de49aff6696cc60a4b23d9ed6905e28b28290c1dcc354ebaffcfec45fb000da8cf671dad68b92af7050a9c40093afc29b850b80f733315d83686f7df55848b44b16a53f6e985c3aba40bff8ea1991616f05fed54f35925a47ca7224ab5f0a0a92bbaea3eef7cba527b2897873a51720d71eb21d188dff58d609b832633b39d5bc57e02f45a5cf05ce48ccb05c1aba69e887561fbd61ff09d75641ac7df1950e6125e1903263fee86bc04c4fd725776ca558183d27f40ed7ea3bc5e83fd89cf72ca1f094b66cd698c1938db390e26e56c1369260ffd3b7bebdf8d5c4a5e8fff1c176fc07c5ecbc9da1e0dba65f9a1041629ae3c4a38c39ad4bb99d7e3517ff6e85813bf00ec4f0c6f2efcff845099875a6da25115705973140057cc47d5da5e68e51bc9982c8548ab221aa0a09a9c13f86f3fa44134c0b4a0d932252f6b7dc6bfba065674afe51b5a23e3df7272e954de2975b042df7d37005c0a2bfb8934949ef19364dd28ee3ea5424a0d277cb8532447b7c74f8c67b49cacd79d12c69c37f3d8af5fcb52a835b25719dda8b76fd0b3fa946eb4170d721c2d40ed75ac5ac1687e729c422a098736af7ae147a0e6839b40f3d980e14fe9a147a41091f7daecbd17e617e6f7fd98a7b3ed9f392a6d81fe0816c390fa0ad37c4944667120f4daf7b7cb46a2590ec0bbfd5f16a8171b8712081cdfbda284d8e028085ea0776c1ebdf5d5ddea44cf91db89f97e82c1237a1c16e8506dcf75d672ad9073aedbd88b458b19865d5628c6f5f4994d3d6ee7f83bc7dab986cef71156c77f3eeac15d37d720d5f115fcb97a2acd342c0358cc999a2c2faf2132f50ed78635a406da0413a02f50b002eb79740e9668c3ac16719c72b86f21f7608cb91f145c78f173c44f3f46257a683ca62cef48ef15f07477234088ce8079f7e97da685223ac1c4ed4a9bd172bbe0f868be17632e107d6ba8183f556e8f74a49facea5adcb50ae473b51bfae5ad88650fb80f9a574ecff6520c4bf316f9a7deb73b188cacdfd262624b3c90f7de4ccdb79f363a7f81fa2d644a6c6c13c8d810f1951d214dd664b8af15eebcc0214753ada358c59eaaf8c5444b7610382f65d1e37591f92849853baf75a72f7c44087ef2b7417c658fe98cb2c2c04dc5f34823e7a3b7343ca42f65968362f34a517af10f03003ff539e08af1252dcfe03ffa2eb58f594ca2a9c87e257cfd37aa36b85422b1a602db9674cc9dda9cb6b2f7c180fb3691ac9cfb4f223048859174b69824d5f5dbe560b025af4127c45eeb4cae4307e44ba1b1591aff5cf9cccc0f2d51a3e8620bd2be3808a9e23f0c73591d741243903abf1c0fb4c102eaf3224990f6478bfff11a46f19d5fe02315f0bf330b93dde9536d135b97f1318aef73692055c16b647191d6daa21e6699cb364e4f09e1aead8238e280411f6e4ebf8223dc2b2146993c789b10a055925262061939d5f5ef943396c2b3b50650841825b049d1d4c5efcecdbac015b6188fe888ebad551fd9d384b3517ff460a5e076b65e4bd4eaf93e874dae1979043808329a1dfed753483f96a9abbbcc96543ddb18e3a7c5c2438d0bed42ffdd7e51b3e7a044345892004ec7e28a2266370f13bcd34dd48f30aeeea943d659508aac622b6148c5e1d62eaa66cc2b1a2da4f87d29076c33039be201e3bea69f3ec5d4a1af5e347c64ae991524193eb51d44ae09f020c401ffa37fb411c6396b01db182ed2f53a9d54ddefa12fdb17a06445c8b036225d6c1e66a6de974ed91d6aee8ad96e1416b9f3f8eee122ea9fc86a356e1be34bb74e563a0c6a6ba5c0dea2158b2a03ce160e0a80b8de2a3fa33e293010b0ac41f4d76bb86952d0225788cf79364dcb29d18c4c4cc90b386f9cff2f980caebe5885e919dfb8079e1ff1122afbf48fc262614f2a0bbbc442f178665e72589882ec957bc154a88047449c84ce48afa76244b4ea5eb58c370dfacb05d8dbf2e9af9fbc825644b61e85348b8de9c8b183e4a6c942a17e8e77309857b1f8d5abb229d6adc337040b0b29269bbb0a2e578485c4fbe28541be170c107892e933df1a5ecc2d6bde4c851b4943c128f42f4345bc25de799658aada9d786349a0c3e43fa9f5ae2b1fdfbed6ab3b8980525564361bb6e5e479004c568a4cc9314af2ab8329b7c93c6ba229c87259b40862bd0ff56d0b0396c6e06ff88bf300b52686f87907fe56e3ecad2f7ea5a01fc415bea9ef740b4e05c4210198b599f7d47e09ac141e4f8ebe955d2ad6ff85522d879992b6bcef64279df4b6310e1e1266141512efb03a14518d54740eb3260ee1f581b077a94c4e8ffa471ca31061c501920dcddeefb32d1d587649d759b65b300c89f1664c3d6a6d86a54b2e4dc4ba66add9137cdbb79b91d4a6c7fe5a6ff5bc00a61fb1403db5b01737569312243d626e0a23f5309da78c61e1d5551bf9819088282d17a4485731d08c6afc30f986eb80a1b91dfd34dac5c466145b292dcea79ccb36e2ccfb93ee7f9abd66c460eba7ac2249a4aba73638f977f4e189ac126a7c3ab231db6b4fd09694f79247be03a0ae8b2dfbefc219fb16196e110d7444411c613b0da33381171b6ebb50cb0dc7549bdd4d04381777cc0ba10390e00673c17b0a98b803c7e61b9c5ca31775cc85b1d4f7721fa8c50f59fe6cf5576cac386a35d50f46e522abf2766fc64cc0bb2db4e9838da802dac73bbafa374fe2de2c46463bd59e044eee96cf15b3e8d7497ea9d179a203034196f735eedc32ea275ed6ef9895537e84fab69ab329a9d720ed2bb34a03399bf058eaa2c2d87d25ed548dd6b8f8372f209eee25ad59ff85b6d400da6dcc032ecdb1fcc6105a24976834e518082f42297c45606a453054455aece35e2ea4e2ca2b7a420f8c1a8bce1ce262c9f2debb90dbb3dab5244f6794dbeda25e53c70aa5c5bb33912f3034405595c974fdfacee3710c86ba181f5de3865e31922117edd6826b23722bdda626c100e02c7fa46b0d6a0edcf0a7e95473c7d5fd5de37a9e5cd1c4d53b5d701e2317a1343761816463ea24cf96284ce320cab974d2a35cd9d761029267209ec476a61a10bdd08bf7cfc86ab4861393d156d2419c20f41113527a726b0353ff34f1175c68742b36df6c7b4274b62c2c15a4f790bf0e03aeaf0322e4a03a877d0459bdeabe96d5e91c898721e2ddbb488d9ba3b43c29af0515237ef53d5ea7cb75dece3e3b28b52c146f838b698566c25318217072949df78250175a2ba0576a317cbd1f8fcd833866dc8ad1f2463b879a825643f42a8fd3b6a8d5285588ed34c7c1fbf24dcc08a272e86719170d55e7297704ef69069dbdc0c7b5c9e2cabe9f8df12c141f8311149b5cce3c18f29354c509c936eb4da64e535187e54a91937f3861198a1fffd548fae644996c9b2308d069c231dda77a35e07bcaae1bf608c29d5d6477665252d2b239b8f971f89895d9e5aaea649450751c336c7d612fb1aa4007f11a9b5b5a4f9e9563c9b6d8e62e2319f091fecca7f8c96a9c7d05a936ffa135758497de596f1d47bac99b95b21e77d9cc0452f7d9fee6698401698dd75c94d4a4a968603d77c4d44e4a489f512753dc4c1261797a1c3f5810a5a2ff9319035f3f0288f535a7a2430364d4fe8723a32d85893116653caffd40ce5bc81f736a135d6c037b48176bb37e4745ca5d88b4739978e52d918140a76a349e14f5caae5eeb759a98461a2736a108d403dc032f7cfc858357e5460120853f3c2d7fb70de47be214ff701316dd767506d1694d0020538e30ab6f28eaf292158a1cb315499341e222893ac02d4fcf052d0debb42bce5d0f6238d04b3af7753a25a53c8a6aadf064b6c663a923d4f08db2844c7e01361755612dcc69cc44d2df91d223e4f281240e83983933d8191756c1ba3def0c92d6f1ff6fa5a26370a57c70b1b787058400c558a462689b4b977bb9edbbc945bb8575c52498312324c855c45cc18d53f0a4fcc999d2b6066acabcc82204451fe4a603ba353550fd522f73074797c192d66b8b1be84cafc87832293c2977484de4f08bba4e117db329eab5ff341bd3009396f53757ca9ffe798dec48e6e4b50284576947715fc56ea67683ba1fcde4c8302e935df731ce473d2e4edbb1c3e75e0260a28e2172c87dad744cd5315d140af573f89516dfad67f96c0d17299c1842723113db0726679ebfe994b8b199fe28bb4df5d1760e3ff2cfc0c95acdacbfb1778259870b52e061089061f2330bc28597a8b8aa7e2053d662de0d0a6889ae5a43ff0f3938a439a5a12a09e38b2eca6f505b96ea00a3bb007e8dc58380f69f6b2b67171a818e4998ee8181db8d0e68c4e9184e15215fbe396cffc841d0b8afbb8282d075380a2f5a2147eed6b36c7e90b588dc1a39f669e76c14ec11b817ffd5be8f7e91be27853278c744632911eeae580f44b4600ab5cdf7544bd3967adebb2daa867bfcf0209a6fb144ae521a21357f4cbeea494dbd78894c4cbcac0132e85275091321842707e422741439b3844ceb6062c5f98d156c1b7e8b1925be356292139e595bc4e1e9e60350a566171a4ec2bbd65396183222e1b393aaaa6a20c4d58a03b963b2e6bbfb5657dd6cc5fe130246b9e58213efaf2671311178bc10bf0dffb5f2e198044a301f9a498a395b421b6ebe657be83533690ee6de9472fe48e892d6e5e27de6672e9c2d521732d1641f8342c4d411105f50fe206447faaab5731c694f5050f1bb67d14520b3508d54fc031ff726b469182f96a145add7fcaececd0fad78986248f6933f40b9ad8c113e383792f4016159f4e6672695389e267c1722403f5f84911aac8f1c9f405aae38db90756a6af5f0a5e5edf4f43ac69c98688bbb713ee5ae1b94970fcad6495e7efc0cca3b2d38287d636b2b9b96027ded3bc3ef76c74992d2b001f236fe4ff85c77905da3bcef1a413f1ea128c577b0cda5c60a75f2175aa573981f5ba25aabc1120e57ffd67425c926368c434e6c3a3c4d40b4fabfcd7bc4deff7aef3b88720e55b40e172fbf80933a199762011689dbe1d57d72ce9d6bb98a346182fbdd74466265efc966081964beaf76dde87aecafa8f91171b0231ea219048b3ea5721b4950620d2367a56bee22835bfe6ccc5531863760f730f8aee9f501721d918f852656afc079074b1d3ca2134e43043911093ac3812dcc9969bc96daeaec722258978ed9648a5fb4767cb68c9dd0c6c215cc03440117f2e10a8033ee4273ec890f4aa8160d83f312489827ba3f4c7e93fb3eeb9f2804d7c7d7679fd2f318e8f8477a8aa94d23db2540b3d6e3e674ad8bc5a6f4951683a8c3568c87d7f19baaa8583bc5e2b96026a41d75f191f9a15bc61aff8419a338e33ba211bc7443d29da0d5ef542b439171baabd9cac5e37880f01e5e8749101a3891a4a6c43d2ba79a5e2b33e90c6f01787800c8e26edf091f1c232c4314c2003f8e962213b84583df8aebfe0263d283621b9bf08456e02472f3e6b24115a7a5d6b0f710a11f80475dfa7f74ff058abf8d614a10e710c90e43d90c9db8efd48499e93bdfc4a3054631c8ec69e8053b1a6a0d77e787b4c6f343121ac9ee97c424d81848a4568ec09f0d05ab08dc9945fe0a3b5a017447260d4bf39a960d678e52921fcbf74b2ecabada2bfa85624fd93f4ce23ec48198c8a9ba16fc1a173495f96836f68430e47bfbae17f508b9c87c612f711b5611e229ebae1cb3b0b053b629892b26d9c51e93644120caf2b5dc06947358c484dab484fbe96eec6736a5a34ed952fcfc5b026d8f78ab15ca3a960ba97bb8da9cbfb9052c691bb2d6fba8b665d4fd789ff67eb3cf31d57de70c80b25f84e7e13b666039f15e8f02961d87dfbf68e221a52d62a31bd143f502ce01a70080; asc .FP                     E       (     @  t  t::U      > 5   <      G d~ 8 K    d  U V )     ol       $1 XPgO   V/ K      " 7       ",     T+a         H *           >  N  L3 xVs       u = $ w *  t v  _ . & XN  4 *  *  |2  bp   6- q  "u  U   2.   .     iZ tdec    P     ZL  + >?Y @ dE^  2=  \+   4]^di  u    li = )'   w   z +    8  ): 3 g tm     H   Cy[+ll {   0    L<c>   m      < ]b hL 6! n   B  1g&5 $    $ k;:    8k>b        A K E GL    s# lt   \     o <3    d  /  r z9{>%   9   D   =  J   U    3 _D  @yeG # 4Z    ),    R   # D_k  J "        e x  {   5    $ !   N j/    qN'^ M 0     vv       K          Q   ZE  E o  /  (j   _ V      E  i 4 +X     X      @        n Qi   &  } ;  h1     F a Y0                  qxi   M[ W           B }T   '   P   E Ds   -c4 s  05 ^    j p   S \ (x o, x q A  |* O 4 q  X p    2 G Yw9   ` mS  KQQ     l (-U   $     s  I0*~ H A \     v q    ^    : Q@.  )        H      B    :    G  < X I0<< D    d   j Wy @ = z q     ?   p4 IK         x v  J9EW  U\C~g      @ T      Z    |1      L@r}   L" u-  Y    R!)r     R2  A   lxEr b  ? k  t s S   8& ~  qi        5      y   B b     /7bN[   v` {  U=     v  UF /   ?:    & ~d    b     v vA B    c 8 p A\     &  3J4 R}$7" {M  Q _ 0  ;    d  6 !` p c   N    | g      7  z  -       w W (     <  i  G2t    X !S    $ rjw  ?    0 =     -  Qf  0   N a    ]   ]8      d t[  a(F    g t  '      ~      olv   nA      PHfx      1  0M\   u Ex^)   I R    h    j \7 T) ^gB       V  K     d Q bCN        P !   ( ?J      fz e >    F *n          J    r8     n k  "  9  V   +   :                g   N  `       r    N&     )Y9A                0 ]  " a  *         ^2  v}+ 8    h       hA  m    Z       '    1      c  7 Z   7   '     y   F  J  $ ,%z  > LR   B / | @ & c    W   mK       y8 A   </ 8p D%[fnu x (   3 V T   f   kS 5   ]    l   @    6   w      "&63h  O O@EE [      i  W_ p  e7    F( @6  6    ~w z !0p   bw* <    f   DW     I         s1UQ   x  | $    P  j !  d T  B  z    O  W8  4T   Lr> 4 /b   P    sX Y#  t   U  fc 6   =} _ r; S      }  2 J  v<        (    nS S    A    A 6 7  +    h  @ 8 v  e0t     x}           2      tM n -   1F x  *   X     "C  a }  d  '       G         `!~     `  E G      i iH  9z  ;6           P ~ pe     ^j        (   kl  n   $x    C       [H]r      A q9 y n    h1   J%f ! O  p P /      c^  B   B*  f    o n  7 R  `J     ,k 1 1   ^    {  U     ?  _] > ':V [  Tu   Z  `  w  V! yh,          _   A Q?   R        K&  V  i_  S`      J G=  }  * EFX|w  p  V FS  ! ; .  e   Q g     R     u      / 3 v   V&  X@ ;         \ `.  "e   5  q |    \6* `    $0 ;6xCD \ K  V ^( d j cdn      B  LuZ       *L^j R  ( 4       [Yh     ` U UU" B  <   J wh   _  ]   v' 52 (  }  D_f[    t #   E  L  x  5v IyU      zf    VT  =   O  !.o:   $  M    h      HNr VKz+5      q  K]  mob    ?|   6q   d}  LHq  S  > } < P          ` n    5-   P      i  b   Ov c     (r&    HH    O   % %I G4O      >   6BH  =  X            F%  1  <> rE g  nm $ z    ( s  Xl %       - GU 6ghs_  N9d R       $ j ! + ^ pt   f   US v       g     t #    2  [  c   =     v       lV5 5M   V.7, Wq  & s   T wr y+!Y N = 5   S*v)  G    = ^{    F      Y  L \X3        }j  IW/  9 b   X"r-   ) he      K   &  A       & @    }        Z     i    l        4 T 0       >   i    T q  Jg  Z  #o  ] k    ,     G x       9    6  F     A i!+ #7   ,   s   JI #JB:     V    u #       g  G Ju $A9 ?   ,qw   _Jp  e&  g(  C 3     f           | Yj i 7 n s}     e 7 +8      $`u 6Q  N        5)  _5   ,'}  *     lI 0 9      s  t  j  u V-   w  kvn   a5SW * 21#vT L!     /c   w: C  WB\      H   )\  b  Vu         l 2 ; J   a   F  0   7   ?0      %  d    tX|  >   > Fr  @3    z g  8f0 " J f g   ]    =:   ZE   =7         o     H  yQ  3   /   f_i$ }  RS 7  7*%4 (I X06  Jt} 16+<  +      G j c    <   O TE$D       P-    3 U7    F   d  k%    1 N?: }   o  )k   n l!] a f { 4   X    Z     S~  z   Af  r [ k }KuE >    c S   QCp D    2  D  * `   !"     U Z %4]    r& Aq     ^  /, $     Fg     ,     EB.1r     m%    !w  +    -  ] z  P V-o    B   x   ?z w '7G      ^  G  w  AsN! o)g   9 #7          vJJ   /  !  X  (     $ ;[  Gea  I  il  K#  i   ()   5N    E     g  h *    @ : ) P  s3  6   U  D jS              _ T Y% | "J    +  > | R{(  :Qr q !     `  &3  [ ~  Z\ \         ua     ud    P  ^  &?      rWv U    @ ~  ^    r   Kf i  8 9 & l i&  ;{   \J^    o |^      e    ) <J8       Q   X    O o.   P  Zm Q pYs  W G  ^h    , H "       o? A4    2%/k}    Vt   Z#  rr T )u B }7 \ +  4    d ( > BJ '| S$G  O g        7   _ R 5 W    o    n   r -@ u Z h~r B*  6 z G    @    O  G                  9*m         |IDfq      F Y    _              ( ^ wl      D     ~  #z   Pm u r  s    E   ]V(    M=n  ;       V  >  ]7       z* 4, X   ,/ !2    5      /P   yt  h   q r o! `    \x s O?F%zh< , H   tw#@   y  }  ":   J  r   h  c. }k  ?Un t    Z    s      e    WN  R K      ;     bbK<   L   6:   -dJll       !M d      !GS  X     DKv 8/e  u  (I ; u /|D ~  A|e      M  H#   4< /e  b JQz    ? 9   %-  ? .  YL   ~%| 7 6 T"     t          6    O"0H  t  $    ` % A' ^ L C  K  Y  \    -Q  b   8   ? sY t C :        "I  G    F  _ #   3    Sm [  1  si U kdq     f  6NO     8  A nN  # +!F <x   U Rb  9    3     P  % I                U     Q  `  v ^K   > M  y 8 2    SH?      T=      C   B  ~Q   D4X  N   "f7    M  0   C YP  b+aH   . f + -  }) l3        >    ^4|d   $ >  D            9k   .  : T   /   dE  6"]l f   N  j   n       "   j5n  K NV: jk      *        *? >)0   A  k iR "W  y6M )  LL  8o  /    X          *    baO*   B xf^rX    { T  GD   H  bD  ^  7            VD   4         B ~ w0 W     )   7   )&   .W      A    x  3  ^ -k L  IC ( /CE % y X   xcI   ?   +     ;  RUd6    y LV L 1J   )  <k ) rY  b   m     o     &  y  V   /~        t N  !      ~    O   ]*   R-      d'   1   f     : Q Tt  &     w LN  G   a        - XvI Y [0   fL=jm  K.M  f   |        Zo      @=   7V  $=bn # 0   a  U     (-  HW1  j 0        4   f [)-    6        f `   "I   68 w     j|: 1 kO     G     -       n  tDA a;  3   n P   T  M 8 w       s {        \  u     r    Y l Wl 8j5  F "  vo L  -        ;  7O  ,FF;   N       I~  y   A  5  2 '^    S~     )    + J 9  X    }% T    7/   % Y      m  .     Z$ h4   /B)|E`jE0TEZ  ^.   +zB       b         $Og    ^S     3 /04@U  t    q     ]  ^1 !    k#r+  &   ,  k j     Ts   ] z \   ;]p #  47a dc $  (L    t  \  a  g   v         j     V A     Rzrk S 4  \ht+6 l{Bt ,,          "  : } Y         !   H    <)   #~ =^  u  >;( , o  i f S !pr    P Z+ Wj1|     8f    F;   VC *     (U  4    M   r g   U )w  i             ,      \ <   T   6 M NSQ  J   8a     H  D l #  i 1  z5 {       ]dwfRR  9  q       d Pu 3l}a/  @    [ZO  c    .#        j }  6  5u   Yo G      w   R    i  i  \    h`=w  NJH Q'S L ayz ?X       _?   5  C d   # -  1 e<  @ [  sj ]l {H k ~GE ]  s x -  @ j4     ^ u  F '6      /|   W F   ?<-    {   p   vu  iM  S 0 o(        I A " : -O  -   + ] b8 K: u:% < j  d  c #     L~ 6 Ua- i D    #   $   93   V  =      o  cp |p       X bh K {    E  u $ 1#$ U \  S        j   " E     55P R/s G    k   L  x2)<)wHM    N } )   4      7W   y  H     WiGq_ n v      0. ] 1 G=.N    ^ `  !r } tL 1]   s     g l  )  Br1   &g        ( M  v ?    Z    w Y  R a  a 3       ~ S b   h  ZC  98 9  *   . oP[      ~      k+g    I       h   N !_ 9l  A       u8 /Z!G   l~     9 i l         ~  ' 2x Dc)   X D `    TK  z  -  {    o D R !5 L  IM x LL   2 Ru  ! '  "t 9  L `b    l ~  % 5b   Y[     P f  N   S  2"     j      c    VW l    F      &q1 x          J0  I 9[B n e{ 53i    r H     } g. -R 2 d  B    _P  dG   s iOPP  g E  P T    & i /  E        x bH  ?@    >87   aY  g& 8 &| "@?_       @Z 8  ujj       :   h  q>        I^~   ;-8(}ck+   } ;  v I     6 O \w ]    A?  ( w     u  Z s  [ Z    W  t% &6 CNl:<M@    {   z ; r U   /   :  b      }r  k  4a   tFbe  f  d  v  z     q #     > r IPb #g k " [ l U1 7` 0     r    &V  y K <  NC 9  :  -  i     r"X   d _ v|         D      3 Bs   J      H ' ?L~  >  (    g      Gz  M# %@    t          V       X;   `&  u    [      8 ;   tC     T+C q      x   ^ I  8    =+  ^+3  o xx   n    #,C   ?  "  E      c  b    V $r   A          G]  t     aJ     C         ;    F1  i  ; j w     C      $  H V         E  ;Z tG& K    g R    K.   +  bO ?L >          4  h6  0 {       |a/q V  )      S ) +&    dA       sX       n g6  N R  [ m x   :   {      ,i      e  x  ~  1 }    _   ;f`9 ^       h ! -b   C       ;
InnoDB: End of page dump
2017-10-20 12:55:39 70367219652752 [ERROR] InnoDB: The page [page id: space=6, page number=1] in file './test/t3.ibd' cannot be decrypted.
2017-10-20 12:55:39 70367219652752 [Note] InnoDB: However key management plugin or used key_version 1 is not found or used encryption algorithm or method does not match.
2017-10-20 12:55:39 70367219652752 [Note] InnoDB: Marking tablespace as missing. You may drop this table or install correct key management plugin and key file.
2017-10-20 12:55:39 70367219652752 [ERROR] InnoDB: The page [page id: space=7, page number=1] in file './test/t4.ibd' cannot be decrypted.

Comment by Marko Mäkelä [ 2017-10-31 ]

The test is unnecessarily complex. With appropriate cleanup, the test should fail every time.

The root cause has been filed as
MDEV-12699 Improve crash recovery of corrupted data pages

First, the test should only fail if the encrypted .ibd files were flushed before the first server kill. If they were not flushed, the files would read just fine, because the first page is never encrypted, and subsequent pages would be filled with zero bytes. So, we would happily apply redo logs to the pages and then write the pages with the mismatching encryption key, to cause some trouble on subsequent startup.

The test is also doing unnecessarily many server restarts. We only need one restart. The clean-up below is incomplete. I think that with MDEV-12699 fixed, we should report errors in CHECK TABLE, but should be able to start up InnoDB, because innodb_force_recovery=1 was specified. Without innodb_force_recovery, the InnoDB startup should be refused, but the rest of the server should start up.

diff --git a/mysql-test/suite/encryption/t/innodb-redo-badkey.opt b/mysql-test/suite/encryption/t/innodb-redo-badkey.opt
index 343128e8803..9715e4caa3b 100644
--- a/mysql-test/suite/encryption/t/innodb-redo-badkey.opt
+++ b/mysql-test/suite/encryption/t/innodb-redo-badkey.opt
@@ -2,4 +2,5 @@
 --innodb-encrypt-tables=on
 --innodb-tablespaces-encryption
 --innodb-encryption-threads=2
---innodb-default-encryption-key-id=4
+--innodb-default-encryption-key-id=6
+--file-key-management-filename=$MYSQL_TEST_DIR/std_data/keys2.txt
diff --git a/mysql-test/suite/encryption/t/innodb-redo-badkey.test b/mysql-test/suite/encryption/t/innodb-redo-badkey.test
index be8555584bb..8e6598fac22 100644
--- a/mysql-test/suite/encryption/t/innodb-redo-badkey.test
+++ b/mysql-test/suite/encryption/t/innodb-redo-badkey.test
@@ -5,16 +5,12 @@
 
 call mtr.add_suppression("Plugin 'file_key_management'");
 call mtr.add_suppression("Plugin 'InnoDB' init function returned error.");
-call mtr.add_suppression("InnoDB: The page \\[page id: space=[1-9][0-9]*, page number=[0-9]+\\] in file .*test/t[1-4]\\.ibd cannot be decrypted");
+call mtr.add_suppression("InnoDB: The page \\[page id: space=[1-9][0-9]*, page number=[0-9]+\\] in file '.*test/t[1-4]\\.ibd' cannot be decrypted");
 call mtr.add_suppression("InnoDB: Unable to decompress .*.test.t1\\.ibd\\[page id: space=[1-9][0-9]*, page number=[0-9]+\\]");
 call mtr.add_suppression("InnoDB: Database page corruption on disk or a failed file read of tablespace test/t1 page \\[page id: space=[1-9][0-9]*, page number=[0-9]*\\]");
 call mtr.add_suppression("InnoDB: Plugin initialization aborted");
 call mtr.add_suppression("Plugin 'InnoDB' registration as a STORAGE ENGINE failed");
 
---echo # Restart mysqld --file-key-management-filename=keys2.txt
--- let $restart_parameters=--file-key-management-filename=$MYSQL_TEST_DIR/std_data/keys2.txt
--- source include/restart_mysqld.inc
-
 --echo # Wait max 10 min for key encryption threads to encrypt all spaces
 --let $wait_timeout= 600
 --let $wait_condition=SELECT COUNT(*) = 0 FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION WHERE MIN_KEY_VERSION = 0
@@ -25,14 +21,14 @@ SET GLOBAL innodb_file_format = `Barracuda`;
 SET GLOBAL innodb_file_per_table = ON;
 --enable_warnings
 
-create table t1(a int not null primary key auto_increment, c char(250), b blob, index(b(10))) engine=innodb row_format=compressed encrypted=yes encryption_key_id=4;
+create table t1(a int not null primary key auto_increment, c char(250), b blob, index(b(10))) engine=innodb row_format=compressed encrypted=yes;
 create table t2(a int not null primary key auto_increment, c char(250), b blob, index(b(10))) engine=innodb row_format=compressed;
-create table t3(a int not null primary key auto_increment, c char(250), b blob, index(b(10))) engine=innodb encrypted=yes encryption_key_id=4;
+create table t3(a int not null primary key auto_increment, c char(250), b blob, index(b(10))) engine=innodb encrypted=yes;
 create table t4(a int not null primary key auto_increment, c char(250), b blob, index(b(10))) engine=innodb;
 
 begin;
 --disable_query_log
---let $i = 20
+--let $i = 10
 begin;
 while ($i)
 {
@@ -46,6 +42,13 @@ insert into t3 select * from t1;
 insert into t4 select * from t1;
 commit;
 
+# Ensure that the encrypted pages are flushed into the files.  If we
+# do not do this, crash recovery would happily read empty pages and
+# apply the redo log records, and finally write the pages with the
+# wrong key that has the same key ID.
+FLUSH TABLES t1,t2,t3,t4 FOR EXPORT;
+UNLOCK TABLES;
+
 --source ../../suite/innodb/include/no_checkpoint_start.inc
 
 #
@@ -66,28 +69,16 @@ insert into t2 (c,b) values (repeat('secret7',20), repeat('secret8',6000));
 insert into t3 (c,b) values (repeat('secret9',20), repeat('secre10',6000));
 insert into t4 (c,b) values (repeat('secre11',20), repeat('secre12',6000));
 COMMIT;
-let $cleanup= drop table t1,t2,t3,t4;
---let CLEANUP_IF_CHECKPOINT= $cleanup;
+--let CLEANUP_IF_CHECKPOINT= DROP TABLE t1,t2,t3,t4;
 --source ../../suite/innodb/include/no_checkpoint_end.inc
 
---echo # restart
---error 1
--- source include/start_mysqld.inc
---source include/kill_mysqld.inc
-
-#
-# Now test with innodb-force-recovery=1 i.e. ignore corrupt pages
-#
-
---echo # Restart mysqld --innodb-force-recovery=1
--- let $restart_parameters=--innodb-force-recovery=1
---error 1
--- source include/start_mysqld.inc
+--echo # Restart with a wrong key, but ignore corrupted pages
+--let $restart_parameters=--innodb-force-recovery=1 --file-key-management-filename=$MYSQL_TEST_DIR/std_data/keys.txt
+--source include/start_mysqld.inc
 
---source include/kill_mysqld.inc
+CHECK TABLE t1,t2,t3,t4;
 
---echo # Restart mysqld --file-key-management-filename=keys2.txt
--- let $restart_parameters=--file-key-management-filename=$MYSQL_TEST_DIR/std_data/keys2.txt
--- source include/start_mysqld.inc
+--let $restart_parameters=
+--source include/restart_mysqld.inc
 
-drop table t1, t2,t3,t4;
+DROP TABLE t1,t2,t3,t4;

Comment by Marko Mäkelä [ 2017-10-31 ]

With the above clean-up, the test will fail as follows, on both debug and non-debug during the innodb_force_recovery:

2017-10-31 11:06:35 139816311031552 [Note] InnoDB: However key management plugin or used key_version 1 is not found or used encryption algorithm or method does not match.
2017-10-31 11:06:35 139816311031552 [Note] InnoDB: Marking tablespace as missing. You may drop this table or install correct key management plugin and key file.
2017-10-31 11:06:35 0x7f29858d8700  InnoDB: Assertion failure in file /mariadb/10.2/storage/innobase/log/log0recv.cc line 1263
InnoDB: Failing assertion: !page || (ibool)!!page_is_comp(page) == dict_table_is_comp(index->table)

This reminds me that MDEV-12253 was not really fixed.
A corrupted or non-decryptable page must not be passed to any caller of buf_page_get_gen(). It must be discarded from the buffer pool!
In this case, the caller is recv_parse_or_apply_log_rec_body(), so the fix would have to be implemented in MDEV-12699.
The above message "Marking tablespace as missing" is a false claim. Especially during crash recovery, the table metadata (why say "tablespace"?) will be unavailable before the data dictionary has been loaded.

#7  0x000055af07b106ce in recv_parse_or_apply_log_rec_body (type=MLOG_COMP_REC_UPDATE_IN_PLACE, ptr=0x7f2986f83aa6 "\002\001\a", ptr@entry=0x7f2986f83a98 "", end_ptr=0x7f2986f83bb5 "", space_id=<optimized out>, page_no=3, apply=apply@entry=true, block=0x7f2986dbb638, mtr=0x7f29858d7600) at /mariadb/10.2/storage/innobase/log/log0recv.cc:1261
#8  0x000055af07b11407 in recv_recover_page (just_read_in=just_read_in@entry=true, block=block@entry=0x7f2986dbb638) at /mariadb/10.2/storage/innobase/log/log0recv.cc:1768
#9  0x000055af07c2e38e in buf_page_io_complete (bpage=0x7f2986dbb638, evict=evict@entry=false) at /mariadb/10.2/storage/innobase/buf/buf0buf.cc:6015
#10 0x000055af07c8f0ec in fil_aio_wait (segment=segment@entry=2) at /mariadb/10.2/storage/innobase/fil/fil0fil.cc:5341
#11 0x000055af07bab970 in io_handler_thread (arg=<optimized out>) at /mariadb/10.2/storage/innobase/srv/srv0start.cc:343

Comment by Elena Stepanova [ 2018-10-01 ]

According to marko, this is a representation of the same problem:
http://buildbot.askmonty.org/buildbot/builders/kvm-deb-bionic-amd64/builds/807/steps/mtr/logs/stdio

10.3 9556d56da2a8

encryption.innodb-redo-badkey 'ctr,innodb' w4 [ fail ]
        Test ended at 2018-10-01 09:28:45
 
CURRENT_TEST: encryption.innodb-redo-badkey
 
 
Server [mysqld.1 - pid: 18856, winpid: 18856, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
2018-10-01  9:28:24 0 [Note] /usr/sbin/mysqld (mysqld 10.3.10-MariaDB-1:10.3.10+maria~bionic-log) starting as process 18572 ...
2018-10-01  9:28:24 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4182)
2018-10-01  9:28:24 0 [Warning] Changed limits: max_open_files: 1024  max_connections: 151 (was 151)  table_cache: 421 (was 2000)
2018-10-01  9:28:24 0 [Note] Plugin 'partition' is disabled.
2018-10-01  9:28:24 0 [Note] InnoDB: Using Linux native AIO
2018-10-01  9:28:24 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-10-01  9:28:24 0 [Note] InnoDB: Uses event mutexes
2018-10-01  9:28:24 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2018-10-01  9:28:24 0 [Note] InnoDB: Number of pools: 1
2018-10-01  9:28:24 0 [Note] InnoDB: Using generic crc32 instructions
2018-10-01  9:28:24 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
2018-10-01  9:28:24 0 [Note] InnoDB: Completed initialization of buffer pool
2018-10-01  9:28:24 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2018-10-01  9:28:24 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2018-10-01  9:28:24 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-10-01  9:28:24 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-10-01  9:28:25 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-10-01  9:28:25 0 [Note] InnoDB: Waiting for purge to start
2018-10-01  9:28:25 0 [Note] InnoDB: 10.3.10 started; log sequence number 1642387; transaction id 34
2018-10-01  9:28:25 0 [Note] InnoDB: Creating #1 encryption thread id 140623822690048 total threads 2.
2018-10-01  9:28:25 0 [Note] InnoDB: Creating #2 encryption thread id 140623336175360 total threads 2.
2018-10-01  9:28:25 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/var/4/mysqld.1/data/ib_buffer_pool
2018-10-01  9:28:25 0 [Note] Plugin 'SEQUENCE' is disabled.
2018-10-01  9:28:25 0 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2018-10-01  9:28:25 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2018-10-01  9:28:25 0 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2018-10-01  9:28:25 0 [Note] Plugin 'INNODB_CMP' is disabled.
2018-10-01  9:28:25 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2018-10-01  9:28:25 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2018-10-01  9:28:25 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2018-10-01  9:28:25 0 [Note] Plugin 'FEEDBACK' is disabled.
2018-10-01  9:28:25 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2018-10-01  9:28:25 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2018-10-01  9:28:25 0 [Note] InnoDB: Buffer pool(s) load completed at 181001  9:28:25
2018-10-01  9:28:25 0 [Note] Plugin 'user_variables' is disabled.
2018-10-01  9:28:25 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2018-10-01  9:28:25 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2018-10-01  9:28:25 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2018-10-01  9:28:25 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2018-10-01  9:28:25 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2018-10-01  9:28:25 0 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2018-10-01  9:28:25 0 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2018-10-01  9:28:25 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-startup-interval=20'
2018-10-01  9:28:25 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-first-interval=60'
2018-10-01  9:28:25 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-interval=60'
2018-10-01  9:28:25 0 [Warning] /usr/sbin/mysqld: unknown option '--loose-pam-debug'
2018-10-01  9:28:25 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-debug-sync-timeout=300'
2018-10-01  9:28:25 0 [Note] Server socket created on IP: '127.0.0.1'.
2018-10-01  9:28:25 0 [Note] Reading of all Master_info entries succeded
2018-10-01  9:28:25 0 [Note] Added new Master_info '' to hash table
2018-10-01  9:28:25 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.3.10-MariaDB-1:10.3.10+maria~bionic-log'  socket: '/dev/shm/var/tmp/4/mysqld.1.sock'  port: 16020  mariadb.org binary distribution
2018-10-01  9:28:25 0 [Note] /usr/sbin/mysqld (initiated by: root[root] @ localhost []): Normal shutdown
2018-10-01  9:28:25 0 [Note] Event Scheduler: Purging the queue. 0 events
2018-10-01  9:28:25 0 [Note] InnoDB: FTS optimize thread exiting.
2018-10-01  9:28:25 0 [Note] InnoDB: Starting shutdown...
2018-10-01  9:28:25 0 [Note] InnoDB: Dumping buffer pool(s) to /dev/shm/var/4/mysqld.1/data/ib_buffer_pool
2018-10-01  9:28:25 0 [Note] InnoDB: Instance 0, restricted to 127 pages due to innodb_buf_pool_dump_pct=25
2018-10-01  9:28:25 0 [Note] InnoDB: Buffer pool(s) dump completed at 181001  9:28:25
2018-10-01  9:28:27 0 [Note] InnoDB: Shutdown completed; log sequence number 1643470; transaction id 34
2018-10-01  9:28:27 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-10-01  9:28:27 0 [Note] /usr/sbin/mysqld: Shutdown complete
 
2018-10-01  9:28:28 0 [Note] /usr/sbin/mysqld (mysqld 10.3.10-MariaDB-1:10.3.10+maria~bionic-log) starting as process 18682 ...
2018-10-01  9:28:28 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4182)
2018-10-01  9:28:28 0 [Warning] Changed limits: max_open_files: 1024  max_connections: 151 (was 151)  table_cache: 421 (was 2000)
2018-10-01  9:28:28 0 [Note] Plugin 'partition' is disabled.
2018-10-01  9:28:28 0 [Note] InnoDB: Using Linux native AIO
2018-10-01  9:28:28 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-10-01  9:28:28 0 [Note] InnoDB: Uses event mutexes
2018-10-01  9:28:28 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2018-10-01  9:28:28 0 [Note] InnoDB: Number of pools: 1
2018-10-01  9:28:28 0 [Note] InnoDB: Using generic crc32 instructions
2018-10-01  9:28:28 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
2018-10-01  9:28:28 0 [Note] InnoDB: Completed initialization of buffer pool
2018-10-01  9:28:28 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2018-10-01  9:28:29 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2018-10-01  9:28:29 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-10-01  9:28:29 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-10-01  9:28:29 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-10-01  9:28:29 0 [Note] InnoDB: Waiting for purge to start
2018-10-01  9:28:29 0 [Note] InnoDB: 10.3.10 started; log sequence number 1643470; transaction id 34
2018-10-01  9:28:29 0 [Note] InnoDB: Creating #1 encryption thread id 140253390153472 total threads 2.
2018-10-01  9:28:29 0 [Note] InnoDB: Creating #2 encryption thread id 140253381760768 total threads 2.
2018-10-01  9:28:29 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/var/4/mysqld.1/data/ib_buffer_pool
2018-10-01  9:28:29 0 [Note] InnoDB: Buffer pool(s) load completed at 181001  9:28:29
2018-10-01  9:28:29 0 [Note] Plugin 'SEQUENCE' is disabled.
2018-10-01  9:28:29 0 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2018-10-01  9:28:29 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2018-10-01  9:28:29 0 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2018-10-01  9:28:29 0 [Note] Plugin 'INNODB_CMP' is disabled.
2018-10-01  9:28:29 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2018-10-01  9:28:29 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2018-10-01  9:28:29 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2018-10-01  9:28:29 0 [Note] Plugin 'FEEDBACK' is disabled.
2018-10-01  9:28:29 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2018-10-01  9:28:29 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2018-10-01  9:28:29 0 [Note] Plugin 'user_variables' is disabled.
2018-10-01  9:28:29 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2018-10-01  9:28:29 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2018-10-01  9:28:29 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2018-10-01  9:28:29 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2018-10-01  9:28:29 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2018-10-01  9:28:29 0 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2018-10-01  9:28:29 0 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2018-10-01  9:28:29 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-startup-interval=20'
2018-10-01  9:28:29 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-first-interval=60'
2018-10-01  9:28:29 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-interval=60'
2018-10-01  9:28:29 0 [Warning] /usr/sbin/mysqld: unknown option '--loose-pam-debug'
2018-10-01  9:28:29 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-debug-sync-timeout=300'
2018-10-01  9:28:29 0 [Note] Server socket created on IP: '127.0.0.1'.
2018-10-01  9:28:29 0 [Note] Reading of all Master_info entries succeded
2018-10-01  9:28:29 0 [Note] Added new Master_info '' to hash table
2018-10-01  9:28:29 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.3.10-MariaDB-1:10.3.10+maria~bionic-log'  socket: '/dev/shm/var/tmp/4/mysqld.1.sock'  port: 16020  mariadb.org binary distribution
2018-10-01  9:28:35 0 [Note] /usr/sbin/mysqld (mysqld 10.3.10-MariaDB-1:10.3.10+maria~bionic-log) starting as process 18817 ...
2018-10-01  9:28:35 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4182)
2018-10-01  9:28:35 0 [Warning] Changed limits: max_open_files: 1024  max_connections: 151 (was 151)  table_cache: 421 (was 2000)
2018-10-01  9:28:35 0 [Note] Plugin 'partition' is disabled.
2018-10-01  9:28:35 0 [Note] InnoDB: Using Linux native AIO
2018-10-01  9:28:35 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-10-01  9:28:35 0 [Note] InnoDB: Uses event mutexes
2018-10-01  9:28:35 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2018-10-01  9:28:35 0 [Note] InnoDB: Number of pools: 1
2018-10-01  9:28:35 0 [Note] InnoDB: Using generic crc32 instructions
2018-10-01  9:28:35 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
2018-10-01  9:28:35 0 [Note] InnoDB: Completed initialization of buffer pool
2018-10-01  9:28:35 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2018-10-01  9:28:35 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=2811756
2018-10-01  9:28:35 0 [Note] InnoDB: Starting final batch to recover 197 pages from redo log.
2018-10-01  9:28:35 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2018-10-01  9:28:35 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-10-01  9:28:35 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-10-01  9:28:35 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-10-01  9:28:35 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-10-01  9:28:35 0 [Note] InnoDB: Waiting for purge to start
2018-10-01  9:28:35 0 [Note] InnoDB: 10.3.10 started; log sequence number 3936453; transaction id 49
2018-10-01  9:28:35 0 [Note] InnoDB: Creating #1 encryption thread id 140052910831360 total threads 2.
2018-10-01  9:28:35 0 [Note] InnoDB: Creating #2 encryption thread id 140052902438656 total threads 2.
2018-10-01  9:28:35 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/var/4/mysqld.1/data/ib_buffer_pool
2018-10-01  9:28:35 0 [Note] InnoDB: Buffer pool(s) load completed at 181001  9:28:35
2018-10-01  9:28:35 0 [Note] Plugin 'SEQUENCE' is disabled.
2018-10-01  9:28:35 0 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2018-10-01  9:28:35 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2018-10-01  9:28:35 0 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2018-10-01  9:28:35 0 [Note] Plugin 'INNODB_CMP' is disabled.
2018-10-01  9:28:35 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2018-10-01  9:28:35 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2018-10-01  9:28:35 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2018-10-01  9:28:35 0 [Note] Plugin 'FEEDBACK' is disabled.
2018-10-01  9:28:35 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2018-10-01  9:28:35 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2018-10-01  9:28:35 0 [Note] Plugin 'user_variables' is disabled.
2018-10-01  9:28:35 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2018-10-01  9:28:35 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2018-10-01  9:28:35 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2018-10-01  9:28:35 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2018-10-01  9:28:35 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2018-10-01  9:28:35 0 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2018-10-01  9:28:35 0 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2018-10-01  9:28:35 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-startup-interval=20'
2018-10-01  9:28:35 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-first-interval=60'
2018-10-01  9:28:35 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-interval=60'
2018-10-01  9:28:35 0 [Warning] /usr/sbin/mysqld: unknown option '--loose-pam-debug'
2018-10-01  9:28:35 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-debug-sync-timeout=300'
2018-10-01  9:28:35 0 [Note] Recovering after a crash using tc.log
2018-10-01  9:28:35 0 [Note] Starting crash recovery...
2018-10-01  9:28:35 0 [Note] Crash recovery finished.
2018-10-01  9:28:35 0 [Note] Server socket created on IP: '127.0.0.1'.
2018-10-01  9:28:35 0 [Note] Reading of all Master_info entries succeded
2018-10-01  9:28:35 0 [Note] Added new Master_info '' to hash table
2018-10-01  9:28:35 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.3.10-MariaDB-1:10.3.10+maria~bionic-log'  socket: '/dev/shm/var/tmp/4/mysqld.1.sock'  port: 16020  mariadb.org binary distribution
2018-10-01  9:28:36 0 [Note] /usr/sbin/mysqld (mysqld 10.3.10-MariaDB-1:10.3.10+maria~bionic-log) starting as process 18857 ...
2018-10-01  9:28:36 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4182)
2018-10-01  9:28:36 0 [Warning] Changed limits: max_open_files: 1024  max_connections: 151 (was 151)  table_cache: 421 (was 2000)
2018-10-01  9:28:36 0 [Note] Plugin 'partition' is disabled.
2018-10-01  9:28:36 0 [Note] InnoDB: Using Linux native AIO
2018-10-01  9:28:36 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-10-01  9:28:36 0 [Note] InnoDB: Uses event mutexes
2018-10-01  9:28:36 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2018-10-01  9:28:36 0 [Note] InnoDB: Number of pools: 1
2018-10-01  9:28:36 0 [Note] InnoDB: Using generic crc32 instructions
2018-10-01  9:28:36 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
2018-10-01  9:28:36 0 [Note] InnoDB: Completed initialization of buffer pool
2018-10-01  9:28:36 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2018-10-01  9:28:36 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1645356
2018-10-01  9:28:37 0 [Note] InnoDB: Starting final batch to recover 197 pages from redo log.
2018-10-01  9:28:37 0 [ERROR] InnoDB: The page [page id: space=7, page number=32] in file './test/t3.ibd' cannot be decrypted.
2018-10-01  9:28:37 0 [Note] InnoDB: However key management plugin or used key_version 1 is not found or used encryption algorithm or method does not match.
2018-10-01  9:28:37 0 [Note] InnoDB: Marking tablespace as missing. You may drop this table or install correct key management plugin and key file.
2018-10-01  9:28:37 0 [ERROR] InnoDB: The page [page id: space=7, page number=34] in file './test/t3.ibd' cannot be decrypted.
2018-10-01  9:28:37 0 [Note] InnoDB: However key management plugin or used key_version 1 is not found or used encryption algorithm or method does not match.
2018-10-01  9:28:37 0 [Note] InnoDB: Marking tablespace as missing. You may drop this table or install correct key management plugin and key file.
2018-10-01  9:28:37 0 [ERROR] InnoDB: The page [page id: space=7, page number=33] in file './test/t3.ibd' cannot be decrypted.
2018-10-01  9:28:37 0 [Note] InnoDB: However key management plugin or used key_version 1 is not found or used encryption algorithm or method does not match.
2018-10-01  9:28:37 0 [Note] InnoDB: Marking tablespace as missing. You may drop this table or install correct key management plugin and key file.
2018-10-01  9:28:37 0 [ERROR] InnoDB: The page [page id: space=7, page number=35] in file './test/t3.ibd' cannot be decrypted.
2018-10-01  9:28:37 0 [Note] InnoDB: However key management plugin or used key_version 1 is not found or used encryption algorithm or method does not match.
2018-10-01  9:28:37 0 [Note] InnoDB: Marking tablespace as missing. You may drop this table or install correct key management plugin and key file.
2018-10-01  9:28:37 0 [ERROR] InnoDB: The page [page id: space=7, page number=36] in file './test/t3.ibd' cannot be decrypted.
2018-10-01  9:28:37 0 [Note] InnoDB: However key management plugin or used key_version 1 is not found or used encryption algorithm or method does not match.
2018-10-01  9:28:37 0 [Note] InnoDB: Marking tablespace as missing. You may drop this table or install correct key management plugin and key file.
2018-10-01  9:28:37 0 [ERROR] InnoDB: The page [page id: space=5, page number=1] in file './test/t1.ibd' cannot be decrypted.
2018-10-01  9:28:37 0 [Note] InnoDB: However key management plugin or used key_version 1 is not found or used encryption algorithm or method does not match.
2018-10-01  9:28:37 0 [Note] InnoDB: Marking tablespace as missing. You may drop this table or install correct key management plugin and key file.
2018-10-01  9:28:37 0 [ERROR] InnoDB: The page [page id: space=5, page number=2] in file './test/t1.ibd' cannot be decrypted.
2018-10-01  9:28:37 0 [Note] InnoDB: However key management plugin or used key_version 1 is not found or used encryption algorithm or method does not match.
2018-10-01  9:28:37 0 [Note] InnoDB: Marking tablespace as missing. You may drop this table or install correct key management plugin and key file.
2018-10-01  9:28:37 0 [ERROR] InnoDB: Unable to decompress ./test/t1.ibd[page id: space=5, page number=3]
2018-10-01  9:28:37 0 [Note] InnoDB: Row compressed page could be encrypted with key_version 1
2018-10-01  9:28:37 0 [Note] InnoDB: Page [page id: space=5, page number=3] zip_decompress failure.
2018-10-01  9:28:37 0 [ERROR] InnoDB: Database page corruption on disk or a failed file read of tablespace test/t1 page [page id: space=5, page number=3]. You may have to recover from a backup.
2018-10-01  9:28:37 0 [Note] InnoDB: Page dump in ascii and hex (8192 bytes):
 len 8192; hex 6c69efdd00000003ffffffffffffffff00000000003a95c845bf000000019a2019f500000005498f11c108cb12bc949de72018-10-01  9:28:37 0 [ERROR] InnoDB: The page [page id: space=6, page number=1] in file './test/t2.ibd' cannot be decrypted.
...

2018-10-01 09:28:37 0x7fcffadfd700  InnoDB: Assertion failure in file /home/buildbot/buildbot/build/mariadb-10.3.10/storage/innobase/log/log0recv.cc line 1451
InnoDB: Failing assertion: !page || (ibool)!!page_is_comp(page) == dict_table_is_comp(index->table)
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/
InnoDB: about forcing recovery.
181001  9:28:37 [ERROR] mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
Server version: 10.3.10-MariaDB-1:10.3.10+maria~bionic-log
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=0
max_threads=153
thread_count=0
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63174 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x0 thread_stack 0x49000
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x55e377afb70e]
/usr/sbin/mysqld(handle_fatal_signal+0x5a5)[0x55e37759a655]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x12890)[0x7fd0084ee890]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xc7)[0x7fd007a02e97]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x141)[0x7fd007a04801]
/usr/sbin/mysqld(+0x498be4)[0x55e3772ecbe4]
/usr/sbin/mysqld(+0x920c33)[0x55e377774c33]
/usr/sbin/mysqld(+0x921ac1)[0x55e377775ac1]
/usr/sbin/mysqld(+0xa5117b)[0x55e3778a517b]
/usr/sbin/mysqld(+0xabe099)[0x55e377912099]
/usr/sbin/mysqld(+0x9cc1b0)[0x55e3778201b0]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76db)[0x7fd0084e36db]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7fd007ae588f]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
Writing a core file at /dev/shm/var/4/mysqld.1/data/
----------SERVER LOG END-------------
mysqltest failed but provided no output
The result from queries just before the failure was:
< snip >
begin;
insert into t2 select * from t1;
insert into t3 select * from t1;
insert into t4 select * from t1;
commit;
SET GLOBAL innodb_flush_log_at_trx_commit=1;
begin;
update t1 set c = repeat('secret3', 20);
update t2 set c = repeat('secret4', 20);
update t3 set c = repeat('secret4', 20);
update t4 set c = repeat('secret4', 20);
insert into t1 (c,b) values (repeat('secret5',20), repeat('secret6',6000));
insert into t2 (c,b) values (repeat('secret7',20), repeat('secret8',6000));
insert into t3 (c,b) values (repeat('secret9',20), repeat('secre10',6000));
insert into t4 (c,b) values (repeat('secre11',20), repeat('secre12',6000));
COMMIT;
# Kill the server
# restart
# Kill the server
# Restart mysqld --innodb-force-recovery=1

Comment by Marko Mäkelä [ 2018-10-23 ]

Recently, I have seen frequent failures of this, also with page dumps. Stack traces vary, because redo log is being applied to different pages.

Maybe we should minimize the test, only have a single page in the table, make it dirty and try to recover that page? In that way, the test would not only run faster, but it would also fail in more predictable ways when it is failing.

Comment by Marko Mäkelä [ 2018-11-20 ]

Here is one more different failure from a 10.4-based branch:

2018-11-20 22:42:48 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=154206
2018-11-20 22:42:48 0 [Note] InnoDB: Starting final batch to recover 197 pages from redo log.
2018-11-20 22:42:48 0 [ERROR] InnoDB: The page [page id: space=5, page number=1] in file './test/t1.ibd' cannot be decrypted.
2018-11-20 22:42:48 0 [Note] InnoDB: However key management plugin or used key_version 1 is not found or used encryption algorithm or method does not match.
2018-11-20 22:42:48 0 [Note] InnoDB: Marking tablespace as missing. You may drop this table or install correct key management plugin and key file.
mysqld: /mariadb/10.4/storage/innobase/include/page0zip.ic:242: ulint page_zip_get_trailer_len(const page_zip_des_t*, ulint): Assertion `!page_zip->n_blobs' failed.
#8  0x0000564616828ad5 in page_zip_get_trailer_len (page_zip=0x7f307cf75d00, is_clust=0) at /mariadb/10.4/storage/innobase/include/page0zip.ic:242
#9  0x0000564616828b3b in page_zip_max_ins_size (page_zip=0x7f307cf75d00, is_clust=0) at /mariadb/10.4/storage/innobase/include/page0zip.ic:263
#10 0x0000564616829b99 in ibuf_index_page_calc_free_zip (block=0x7f307cf75ce0) at /mariadb/10.4/storage/innobase/include/ibuf0ibuf.ic:244
#11 0x0000564616829c52 in ibuf_index_page_calc_free (block=0x7f307cf75ce0) at /mariadb/10.4/storage/innobase/include/ibuf0ibuf.ic:275
#12 0x0000564616836207 in ibuf_merge_or_delete_for_page (block=0x7f307cf75ce0, page_id=..., page_size=0x7f307cf75ce8, update_ibuf_bitmap=1) at /mariadb/10.4/storage/innobase/ibuf/ibuf0ibuf.cc:4745
#13 0x0000564616a436d0 in buf_page_io_complete (bpage=0x7f307cf75ce0, dblwr=true, evict=false) at /mariadb/10.4/storage/innobase/buf/buf0buf.cc:6251

Comment by Marko Mäkelä [ 2019-04-30 ]

Even though MDEV-12699 fixed most of this in 10.2+, I think that we should fix this failure by changing the warning message to a note:

10.1 5b035c84567b60c2ca680de96f5179a6

encryption.innodb-redo-badkey 'ctr,innodb_plugin' w1 [ fail ]  Found warnings/errors in server log file!
       Test ended at 2019-04-30 08:45:25
line
2019-04-30  8:45:17 3068614656 [Warning] InnoDB: A doublewrite copy of page 4:1 is corrupted.
^ Found warnings in /mnt/buildbot/build/mariadb-10.1.39/mysql-test/var/1/log/mysqld.1.err
ok

For the primary copy of the page, a warning may be fine. But, I do not think that we should issue warnings regarding doublewrite buffer corruption.

Comment by Elena Stepanova [ 2019-04-30 ]

I still don't understand the purpose of this record, be it a warning or a note. If InnoDB already knows that the primary copy is fine, then why check the redundant one, and if it does need to check on whatever reason, why write about it?
Or, if a redundant one is checked first on whatever reason and found corrupt, InnoDB still doesn't know if it's even needed, so why not to suppress the message until it actually knows whether it was needed, and then it should be either an error (since it's needed but corrupt), or shouldn't be written at all, since nobody cares because the primary one is fine.

Comment by Thirunarayanan Balathandayuthapani [ 2019-05-07 ]

Patch is in bb-10.2-MDEV-13893

Comment by Marko Mäkelä [ 2019-05-09 ]

I think that we should remove this message already in 10.1, even though 10.1 will be more likely to suffer from actual recovery failures due to MDEV-12699.

Comment by Marko Mäkelä [ 2019-05-10 ]

The originally reported message (in the bug title) mostly went away thanks to MDEV-12699, which was not fixed in the 10.1 series. As part of this ticket, we only removed a warning for copies of pages that are corrupted in the doublewrite buffer.

Generated at Thu Feb 08 08:09:11 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.