Add logging to the `decrypt` function to trace unhandled data

[convenient]

Logging

This resolves https://github.com/genecommerce/module-encryption-key-manager/issues/7

This module provides a mechanism to log the source for each call to decrypt. This will produce a lot of data as the magento system configuration is encrypted so each request will trigger a log write.

It is recommended to enable this logging after you have handled the re-encryption of all data in your system, but before you invalidate the old keys. This will give you an indication that you have properly handled everything, because if you see a log written it will tell you that something has been missed and where to go to find the source of the issue.

php bin/magento config:set --lock-env dev/debug/gene_encryption_manager_enable_decrypt_logging 1
php bin/magento config:set --lock-env dev/debug/gene_encryption_manager_only_log_old_decrypts 1

Example

[2024-07-18T12:56:06.736197+00:00] main.INFO: gene encryption manager - legacy decryption {"trace_id":"29dbea682f3e24653ad5233c871848a2","trace":"|#0 vendor/magento/framework/Interception/Interceptor.php(146): Gene\\EncryptionKeyManager\\Plugin\\LogDecrypts->afterDecrypt()|#1 vendor/magento/framework/Interception/Interceptor.php(153): Magento\\Framework\\Encryption\\Encryptor\\Interceptor->Magento\\Framework\\Interception\\{closure}()|#2 generated/code/Magento/Framework/Encryption/Encryptor/Interceptor.php(23): Magento\\Framework\\Encryption\\Encryptor\\Interceptor->___callPlugins()|#3 phar://vendor/n98/magerun2-dist/n98-magerun2/src/N98/Magento/Command/Developer/DecryptCommand.php(63): Magento\\Framework\\Encryption\\Encryptor\\Interceptor->decrypt()|#4 phar://vendor/n98/magerun2-dist/n98-magerun2/vendor/symfony/console/Command/Command.php(298): N98\\Magento\\Command\\Developer\\decryptCommand->execute()|#5 phar://vendor/n98/magerun2-dist/n98-magerun2/src/N98/Magento/Command/AbstractMagentoCommand.php(249): Symfony\\Component\\Console\\Command\\Command->run()|#6 phar://vendor/n98/magerun2-dist/n98-magerun2/vendor/symfony/console/Application.php(1058): N98\\Magento\\Command\\AbstractMagentoCommand->run()|#7 phar://vendor/n98/magerun2-dist/n98-magerun2/vendor/symfony/console/Application.php(301): Symfony\\Component\\Console\\Application->doRunCommand()|#8 phar://vendor/n98/magerun2-dist/n98-magerun2/src/N98/Magento/Application.php(256): Symfony\\Component\\Console\\Application->doRun()|#9 phar://vendor/n98/magerun2-dist/n98-magerun2/vendor/symfony/console/Application.php(171): N98\\Magento\\Application->doRun()|#10 phar://vendor/n98/magerun2-dist/n98-magerun2/src/N98/Magento/Application.php(364): Symfony\\Component\\Console\\Application->run()|#11 vendor/n98/magerun2-dist/n98-magerun2(8): N98\\Magento\\Application->run()|#12 vendor/bin/n98-magerun2(120): include('...')|#13 {main}"} []

[peterjaap]

Awesome, this looks great!

Maybe we can hash the content of the JSON trace so we can avoid having duplicate entries for exactly the same trace?

[convenient]

@peterjaap I've generated an ID for the specific trace, i'm not sure varying it by the input arguments make sense as it'll be the same table/codepath that needs reviewed?

Doing some kind of hashing and object caching would only prevent the log being written in the scenario where the same value is being decrypted multiple times within the same process, and even then that seems not the usual case, because the full stack trace would likely be moving along and changing anyway?

[peterjaap]

I think this is a good first iteration. Maybe along the way we can identify how to improve it. But why would you think the full stack trace would be "moving along and changing" ?

[convenient]

@peterjaap because its the full stack trace, from index.php so it would vary depending on the specific line of code and what calls it? I may just be being silly, but I cant think of many scenarios where the exact same trace would be triggered numerous times from the one request 🤔

I'll pull this in as a first pass, any PRs to improve upon this after very much welcome.