(dev/core#316) Fix crash on Memcache systems when session key involves whitespace #12640

xurizaemon · 2018-08-09T21:28:12Z

Overview

As reported @ https://lab.civicrm.org/dev/core/issues/316, there seems to be an issue with Memcache compatibility - keys generated by Cache::cleanKey() permit whitespace, which Memcache does not allow.

This patch addresses the bug and also micro-optimizes some cache logic.

Before

Caching with Memcache does not work -- because the cache-keys used for session-management includes spaces. Report @ https://chat.civicrm.org/civicrm/pl/yo7drhis3pgg3cemfzuctd6ixr
When reading from the cache, cleanKey() is called twice in a row.

After

Hopefully CiviCRM will function with Memcache again. Untested.
When reading from the cache, cleanKey() is called once.

Technical Details

Changes cache keys, so may indicate that we should run a cache reset. (But if caching is sane, that shouldn't be required?)

Comments

Note for reviewing: Since this issue was reported by a user who upgraded to an official release, there's an implication to me that we don't have memcache as part of our test matrix. This would then require manual testing (perhaps by the affected user) to confirm the fix (or I guess inclusion of memcache in our test matrix).

civibot · 2018-08-09T21:28:15Z

(Standard links)

If this is your first pull-request for CiviCRM, please browse CONTRIBUTING.md for information about the development and testing processes.
If you are reviewing this pull-request, you may wish to consult the test sites and the Review Standards (long template, short template).

totten · 2018-08-09T23:41:23Z

(CiviCRM Review Template WORD-1.1)

(r-explain) Pass - I updated the title & description. It may make sense to tweak the "After" once there's been some r-run review.
(r-test)
- Needs work - Could you update CRM_Core_BAO_CacheTest? (Incidentally, the test failure seems to indicate that the cleanKey() patch is filtering whitespace as expected.)
- There's tangential/related test-coverage in tests/phpunit/E2E/Cache/, but the test-box only runs the tests in a stock MySQL-only environment. So I ran them manually and confirmed they pass with Redis, Memcache, and Memcached drivers.
(r-code) Pass
(r-doc) Pass
(r-maint) Pass: Agree with your assessment that tests should be run in more environments. That would be good follow-up project, but it doesn't need to block this PR.
(r-run) Unreviewed: Agree with Chris's comments about this - would be great if @christianwach could try the patch and see if it fixes the problem.
(r-user) Pass
(r-tech) Pass: Any code using cleanKey() necessarily has some constraints with how it can use the cache service, but this code is already using cleanKey(). I don't think tweaking the encoding has a substantive affect on the contract (as perceived by cache-using code).

Regarding this:

Changes cache keys, so may indicate that we should run a cache reset. (But if caching is sane, that shouldn't be required?)

Agree it should be OK as-is. The impact here is changing the effective-key used in memcache for anything involving a space. However, if the effective-key had a space in it before, then it was broken already, and the cache wouldn't be filled. (Update: My comment had a grain of truth... but was wrong/incomplete. The change also impacts non-memcache systems where spaces were fine. Never-the-less, I still think it's safe for the more general/obvious reasons... typical use-case: sysadmin upgrades to a new release with this patch, and the upgrader clears out all manner of caches+sessions per norm. Worst use-case: sysadmin manually applies patch on a non-memcache system... because they're crazy... and it has a momentary, de-facto impact of invalidating some caches+sessions. The old cache-data exists but should cycle out eventually.)

@xurizaemon since this is a recent regression, could you rebase the patch to target the RC branch (5.5)? After we merge it into the RC, then we can follow-up with (a) backport to stable (5.4) and (b) bulk merge-forward to master.

…ibility - https://lab.civicrm.org/dev/core/issues/316 - https://github.com/memcached/memcached/blob/master/doc/protocol.txt

Since this method is performance related and called frequently, no need to recalculate results from preg_replace_callback() with the same inputs.

christianwach · 2018-08-10T11:19:46Z

@xurizaemon Thanks for this - your code almost works 👍

I discovered that $key was still being prefixed by /CiviCRM Session/ even after the cleanKey() method had run. I had to change CiviCRM Session to CiviCRMSession in Container.php (for functionality) and Cache.php (for consistency). Both CiviCRM-Session and CiviCRM_Session produce 500 errors but the pure alphabetic CiviCRMSession works.

xurizaemon · 2018-08-10T11:46:30Z

Have pushed an additional commit that would hopefully catch this ... let me know if that works!

@totten note that the previous changes weren't sufficient 😞

christianwach · 2018-08-10T15:37:43Z

@xurizaemon One further issue I've run into is that Extensions cannot be installed while Memcached is being used:

$Fatal Error Details = array(3) {
  ["message"]=>
  string(19) "Unknown extension: "
  ["code"]=>
  NULL
  ["exception"]=>
  object(CRM_Extension_Exception_MissingException)#6982 (10) {
    ["errorData":"CRM_Core_Exception":private]=>
    array(1) {
      ["error_code"]=>
      int(0)
    }
    ... lots more debugging ...

As you can see, $key is empty in CRM_Extension_Container_Collection::getContainer() - I presume this is as a result of CRM_Extension_Container_Collection::getKeysToContainer() grabbing the containers with:

$k2c = $this->cache->get($this->cacheKey);

FWIW, turning Memcached off allows me to install Extensions.

This is replaces 95b6567. The intent is to have a delimiter every ten chars so that it's easy to read/confirm the length of the string. The delimiter was space, but this became a longer encoded char (`-20`) and threw off the numbers. Switching to dash just gives a different encoded char. To get the counts right, it needs ot be a pass-through char... like underscore.

totten · 2018-08-11T00:20:44Z

Taking @christianwach's confirmation and a quick test I did locally, we've now got two r-run confirmations that this fixes the session thing.

For the r-test problem, I revised the patch for the long string test and pushed up.

@christianwach, I've tried on D7 and WP with 5.5 and haven't been able to replicate the problem with extension activation. I'll try again with 5.4+patch, and maybe we should have another issue for that?

Flagging merge-on-pass.

eileenmcnaughton · 2018-08-11T00:21:48Z

Thanks @xurizaemon for fixing this!

eileenmcnaughton · 2018-08-11T00:22:45Z

@christianwach just as an aside we are digging into adopting Redis off the back of this cache cleanup (which unfortunately stung you) - hopefully we'll do some performance tests soon

christianwach · 2018-08-13T11:39:44Z

Apologies in advance if there's too much debugging info below - I've tried to debug the Install Extension process but I get lost in the intricacies of HTML_QuickForm so I thought dumping everything I can see might help. The problem in CRM_Extension_Container_Collection::getContainer() is that $key is not defined:

Array
(
    [method] => CRM_Extension_Container_Collection::getContainer
    [key] => 
    [k2c] => Array
        (
            [com.iatspayments.civicrm] => civiroot
            [org.civicrm.shoreditch] => default
        )

    [backtrace] => #0 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Extension/Container/Collection.php(111): CRM_Extension_Container_Collection->getContainer(NULL)
#1 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Extension/Mapper.php(185): CRM_Extension_Container_Collection->getPath(NULL)
#2 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Admin/Form/Extensions.php(85): CRM_Extension_Mapper->keyToInfo(NULL)
#3 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Core/Form.php(585): CRM_Admin_Form_Extensions->preProcess()
#4 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Core/StateMachine.php(136): CRM_Core_Form->buildForm()
#5 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Core/QuickForm/Action/Next.php(61): CRM_Core_StateMachine->perform(Object(CRM_Admin_Form_Extensions), 'next', 'Next')
#6 /path/to/wp-content/plugins/civicrm/civicrm/packages/HTML/QuickForm/Controller.php(203): CRM_Core_QuickForm_Action_Next->perform(Object(CRM_Admin_Form_Extensions), 'next')
#7 /path/to/wp-content/plugins/civicrm/civicrm/packages/HTML/QuickForm/Page.php(103): HTML_QuickForm_Controller->handle(Object(CRM_Admin_Form_Extensions), 'next')
#8 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Core/Controller.php(351): HTML_QuickForm_Page->handle('next')
#9 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Core/Page/Basic.php(398): CRM_Core_Controller->run()
#10 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Core/Page/Basic.php(156): CRM_Core_Page_Basic->edit(1, NULL)
#11 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Admin/Page/Extensions.php(121): CRM_Core_Page_Basic->run()
#12 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Core/Invoke.php(309): CRM_Admin_Page_Extensions->run(Array, NULL)
#13 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Core/Invoke.php(84): CRM_Core_Invoke::runItem(Array)
#14 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Core/Invoke.php(52): CRM_Core_Invoke::_invoke(Array)
#15 /path/to/wp-content/plugins/civicrm/civicrm.php(1246): CRM_Core_Invoke::invoke(Array)
#16 [internal function]: CiviCRM_For_WordPress->invoke('')
#17 /path/to/wp-includes/class-wp-hook.php(286): call_user_func_array(Array, Array)
#18 /path/to/wp-includes/class-wp-hook.php(310): WP_Hook->apply_filters('', Array)
#19 /path/to/wp-includes/plugin.php(453): WP_Hook->do_action(Array)
#20 /path/to/wp-admin/admin.php(224): do_action('toplevel_page_C...')
#21 {main}
)

Debugging further up the line in CRM_Admin_Form_Extensions::preProcess() shows the context, though it still doesn't show me exactly why $key is undefined:

Array
(
    [method] => CRM_Admin_Form_Extensions::preProcess
    [key] => 
    [id] => 
    [GET] => Array
        (
            [page] => CiviCRM
            [q] => civicrm/admin/extensions
            [noheader] => 1
        )

    [POST] => Array
        (
            [qfKey] => 926b1c386f5b9c64184e995104741f62_6496
            [_qf_default] => Extensions:next
            [_qf_Extensions_next] => Install
        )

    [REQUEST] => Array
        (
            [page] => CiviCRM
            [q] => civicrm/admin/extensions
            [noheader] => 1
            [qfKey] => 926b1c386f5b9c64184e995104741f62_6496
            [_qf_default] => Extensions:next
            [_qf_Extensions_next] => Install
        )

    [backtrace] => #0 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Core/Form.php(585): CRM_Admin_Form_Extensions->preProcess()
#1 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Core/StateMachine.php(136): CRM_Core_Form->buildForm()
#2 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Core/QuickForm/Action/Next.php(61): CRM_Core_StateMachine->perform(Object(CRM_Admin_Form_Extensions), 'next', 'Next')
#3 /path/to/wp-content/plugins/civicrm/civicrm/packages/HTML/QuickForm/Controller.php(203): CRM_Core_QuickForm_Action_Next->perform(Object(CRM_Admin_Form_Extensions), 'next')
#4 /path/to/wp-content/plugins/civicrm/civicrm/packages/HTML/QuickForm/Page.php(103): HTML_QuickForm_Controller->handle(Object(CRM_Admin_Form_Extensions), 'next')
#5 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Core/Controller.php(351): HTML_QuickForm_Page->handle('next')
#6 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Core/Page/Basic.php(398): CRM_Core_Controller->run()
#7 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Core/Page/Basic.php(156): CRM_Core_Page_Basic->edit(1, NULL)
#8 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Admin/Page/Extensions.php(121): CRM_Core_Page_Basic->run()
#9 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Core/Invoke.php(309): CRM_Admin_Page_Extensions->run(Array, NULL)
#10 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Core/Invoke.php(84): CRM_Core_Invoke::runItem(Array)
#11 /path/to/wp-content/plugins/civicrm/civicrm/CRM/Core/Invoke.php(52): CRM_Core_Invoke::_invoke(Array)
#12 /path/to/wp-content/plugins/civicrm/civicrm.php(1246): CRM_Core_Invoke::invoke(Array)
#13 [internal function]: CiviCRM_For_WordPress->invoke('')
#14 /path/to/wp-includes/class-wp-hook.php(286): call_user_func_array(Array, Array)
#15 /path/to/wp-includes/class-wp-hook.php(310): WP_Hook->apply_filters('', Array)
#16 /path/to/wp-includes/plugin.php(453): WP_Hook->do_action(Array)
#17 /path/to/wp-admin/admin.php(224): do_action('toplevel_page_C...')
#18 {main}
)

Here's what CRM_Admin_Form_Extensions looks like at the above moment:

So, somewhere at some point, the _key property is not being set.

@totten Can you suggest how I might be able to pinpoint what's going on?

christianwach · 2018-08-13T11:48:28Z

@totten A little more info: when Memcached is not being used, the URL sequence is as follows:

The "Install" page is: https://domain.org/wp-admin/admin.php?page=CiviCRM&q=civicrm%2Fadmin%2Fextensions&action=add&id=org.civicrm.shoreditch&key=org.civicrm.shoreditch
The resulting location is: https://domain.org/wp-admin/admin.php?page=CiviCRM&q=civicrm%2Fadmin%2Fextensions&reset=1&action=browse

When Memcached is being used:

The "Install" page is: https://domain.org/wp-admin/admin.php?page=CiviCRM&q=civicrm%2Fadmin%2Fextensions&action=add&id=org.civicrm.shoreditch&key=org.civicrm.shoreditch
The resulting location is: https://domain.org/wp-admin/admin.php?page=CiviCRM&q=civicrm%2Fadmin%2Fextensions

As I said, I'll happily test further given pointers as to where to keep digging.

totten · 2018-08-17T00:39:51Z

I've filed the extension-install issue as https://lab.civicrm.org/dev/core/issues/336

civicrm-builder added the master label Aug 9, 2018

xurizaemon requested a review from totten August 9, 2018 21:28

totten changed the title ~~Gl316 cache key no whitespace~~ (dev/core#316) Fix crash on Memcache systems when session key involves whitespace Aug 9, 2018

xurizaemon changed the base branch from master to 5.5 August 10, 2018 10:18

civicrm-builder added the 5.5 label Aug 10, 2018

xurizaemon added 4 commits August 10, 2018 22:19

Issue civicrm#316: Exclude spaces from cache keys for Memcache compat…

816e59c

…ibility - https://lab.civicrm.org/dev/core/issues/316 - https://github.com/memcached/memcached/blob/master/doc/protocol.txt

Avoid calling Cache::cleanKey() twice in quick succession

972b0e2

Since this method is performance related and called frequently, no need to recalculate results from preg_replace_callback() with the same inputs.

Issue civicrm#316: Update tests for whitespace escaping

41c32af

Issue civicrm#316: Expand cache key test coverage with emoji

8720352

xurizaemon force-pushed the GL316-cache_key_no_whitespace branch from 2278143 to 8720352 Compare August 10, 2018 10:20

Issue civicrm#316: Ensure Container caches have safe prefixes

76e697a

Issue civicrm#316: Update long string cache key test results

95b6567

totten added 2 commits August 10, 2018 12:43

(NFC) CRM_Utils_Cache::create - Update docblock for 'name' param

7c34772

totten added merge on pass and removed master labels Aug 11, 2018

eileenmcnaughton merged commit 0ac8ea7 into civicrm:5.5 Aug 11, 2018

xurizaemon deleted the GL316-cache_key_no_whitespace branch August 11, 2018 10:29

totten mentioned this pull request Aug 13, 2018

(dev/core#316) Fix crash on Memcache systems when session key involves whitespace #12653

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

(dev/core#316) Fix crash on Memcache systems when session key involves whitespace #12640

(dev/core#316) Fix crash on Memcache systems when session key involves whitespace #12640

xurizaemon commented Aug 9, 2018 •

edited by totten

Loading

civibot bot commented Aug 9, 2018

totten commented Aug 9, 2018 •

edited

Loading

christianwach commented Aug 10, 2018

xurizaemon commented Aug 10, 2018 •

edited

Loading

christianwach commented Aug 10, 2018

totten commented Aug 11, 2018

eileenmcnaughton commented Aug 11, 2018

eileenmcnaughton commented Aug 11, 2018

christianwach commented Aug 13, 2018 •

edited

Loading

christianwach commented Aug 13, 2018

totten commented Aug 17, 2018

(dev/core#316) Fix crash on Memcache systems when session key involves whitespace #12640

(dev/core#316) Fix crash on Memcache systems when session key involves whitespace #12640

Conversation

xurizaemon commented Aug 9, 2018 • edited by totten Loading

Overview

Before

After

Technical Details

Comments

civibot bot commented Aug 9, 2018

totten commented Aug 9, 2018 • edited Loading

christianwach commented Aug 10, 2018

xurizaemon commented Aug 10, 2018 • edited Loading

christianwach commented Aug 10, 2018

totten commented Aug 11, 2018

eileenmcnaughton commented Aug 11, 2018

eileenmcnaughton commented Aug 11, 2018

christianwach commented Aug 13, 2018 • edited Loading

christianwach commented Aug 13, 2018

totten commented Aug 17, 2018

xurizaemon commented Aug 9, 2018 •

edited by totten

Loading

totten commented Aug 9, 2018 •

edited

Loading

xurizaemon commented Aug 10, 2018 •

edited

Loading

christianwach commented Aug 13, 2018 •

edited

Loading