[MAGNOLIA-7896] Generation of CSRF token is too expensive Created: 19/Aug/20  Updated: 29/Oct/21  Resolved: 12/Oct/20

Status: Closed
Project: Magnolia
Component/s: None
Affects Version/s: 6.1.6, 6.2.3
Fix Version/s: 5.7.9, 6.1.7, 6.2.4

Type: Bug Priority: Neutral
Reporter: Jonathan Ayala Assignee: Aleksandr Pchelintcev
Resolution: Fixed Votes: 0
Labels: csrf, maintenance, security
Remaining Estimate: Not Specified
Time Spent: 6h 11m
Original Estimate: Not Specified
Environment:

demopublic


Attachments: PNG File Screenshot 2020-09-30 at 08.00.48.png     PNG File Screenshot 2020-09-30 at 08.09.20.png     PNG File image-2020-10-01-15-40-42-358.png    
Issue Links:
Problem/Incident
Relates
relates to MAGNOLIA-7991 Invalid path for cookie with special ... Closed
relates to MGNLPN-507 Consider an in-memory ip-based cache ... Closed
causality
relation
Template:
Acceptance criteria:
Empty
Task DoD:
[X]* Doc/release notes changes? Comment present?
[X]* Downstream builds green?
[X]* Solution information and context easily available?
[X]* Tests
[X]* FixVersion filled and not yet released
[ ]  Architecture Decision Record (ADR)
Bug DoR:
[X]* Steps to reproduce, expected, and actual results filled
[X]* Affected version filled
Date of First Response:
Epic Link: Support
Sprint: Maintenance 28
Story Points: 3

 Description   

When disabling the country filter, response time gets noticeably slower. This can be reproduced in our demo but not in a local installation with the bundle. 

Steps to reproduce:

  • Execute the following command in order to measure the response time:
    curl -so /dev/null -w '%{time_starttransfer} Seconds \n' https://demopublic.magnolia-cms.com
  • Add configuration property /server/filters/country@enabled with value false in order to disable the filter and execute same command than in step 1.

Expected result: response time is similar or even lower as filter execution is avoided.
Actual result: response time is noticeably higher:

$ curl -so /dev/null -w '%{time_starttransfer} Seconds \n' https://demopublic.magnolia-cms.com/travel 
0.998357 Seconds 

COUNTRY FILTER IS DISABLED

$ curl -so /dev/null -w '%{time_starttransfer} Seconds \n' https://demopublic.magnolia-cms.com/travel 
2.363181 Seconds 


Timebox for investigation: 3 SP

  • Verify findings, can they be used as a solution?
  • Consider potential implications (login page CSRF)


 Comments   
Comment by Roman Kovařík [ 20/Aug/20 ]

Hi jayala

Could you attach an output of an average of at least 100 request per enabled/disable/enabled?
As we've discussed, we can hardly take one request as something measurable as the cache is flushed after any config change.

Roman

Comment by Julius Rabe [ 04/Sep/20 ]

Hi,
is this issue beeing worked on? Can we have an update, pls?

This is a pretty severe issue for us and our clients.

Thanks!

Comment by Jan Haderka [ 30/Sep/20 ]

Here's the script to properly measure response times. To use it:

./ttfb -v -n 5 -c "gzip" http://demopublic.magnolia-cms.com/magnoliaAuthor/travel.html 

Results as of this morning:

COUNTRY ENABLED
$ ./ttfb -v -n 50 -c "gzip" http://demopublic.magnolia-cms.com
DNS lookup: 0.004049 TLS handshake: 0.067520 TTFB including connection: 0.135945 TTFB: .068425 Total time: 0.136160 Total size: 5363
DNS lookup: 0.003101 TLS handshake: 0.062213 TTFB including connection: 0.122872 TTFB: .060659 Total time: 0.122992 Total size: 5363
DNS lookup: 0.003048 TLS handshake: 0.066042 TTFB including connection: 0.127704 TTFB: .061662 Total time: 0.127890 Total size: 5363
DNS lookup: 0.003956 TLS handshake: 0.065874 TTFB including connection: 0.127881 TTFB: .062007 Total time: 0.128136 Total size: 5363
DNS lookup: 0.003799 TLS handshake: 0.068836 TTFB including connection: 0.129382 TTFB: .060546 Total time: 0.129627 Total size: 5363
...

fastest .060546 slowest .068425 median .061662

COUNTRY DISABLED
$ ./ttfb -v -n 50 -c "gzip" http://demopublic.magnolia-cms.com
DNS lookup: 0.003689 TLS handshake: 0.066614 TTFB including connection: 0.127082 TTFB: .060468 Total time: 0.127328 Total size: 5363
DNS lookup: 0.003478 TLS handshake: 0.065938 TTFB including connection: 0.129437 TTFB: .063499 Total time: 0.129598 Total size: 5363
DNS lookup: 0.003444 TLS handshake: 0.066299 TTFB including connection: 0.125704 TTFB: .059405 Total time: 0.125883 Total size: 5363
DNS lookup: 0.003326 TLS handshake: 0.068655 TTFB including connection: 0.132637 TTFB: .063982 Total time: 0.132824 Total size: 5363
DNS lookup: 0.003400 TLS handshake: 0.069760 TTFB including connection: 0.128388 TTFB: .058628 Total time: 0.128557 Total size: 5363
...

fastest .058628 slowest .063982 median .060468

Failed to reproduce the issue. Median of TTFB with enabled filter was 0.061 seconds, with disabled filter it was 0.060 seconds, so pretty much the same. Similar for total transfer time.

The reason for you to perceive the slower response is that after changing configuration, cache is flushed thus for the first time you read the content after the change you get uncached response. Would be the same if you disabled something else.
Not just for this reason, but to eliminate fluctuations in transfer speed of the network and other factors you should always make multiple runs and calculate average or median of the values you receive.

Comment by Julius Rabe [ 30/Sep/20 ]

Really strange you could not reproduce the issue. I was able to reproduce it on Monday 27th September on the 6.2.3 Public Demo!
Unfortunatly your Demo Application https://demopublic.magnolia-cms.com is not working today => 504 Error.

I will reproduce it again once the Demo is up and running again!

I am aware of the caching behaviour and I eliminated this factor as you can see in my tests in the ticket https://jira.magnolia-cms.com/browse/SUPPORT-11669

Comment by Jan Haderka [ 01/Oct/20 ]

Should be running. Since it's public demo, and anyone has access, ppl do some destructive tests on it sometimes, but monitoring system should detect that within minute and bring it back up.

Anyway I tried to even replicate it with bytecheck same as you and also there I see no difference (see attached screenshots).

There is no real difference once the cache is settled down. The only explanation I have for while you consistently see the behaviour and we don't is something related to the infrastructure. Proxy or something else on the way.

Also technically, behind the scene there is no reason why this filter should influence anything, it just either makes country available as a trait for other parts of the system to consume or it doesn't. Since homepage doesn't use any country related p13n segments, it should have no effect on TTFB

Just out of interest, why do you need to switch this filter off?

Comment by Julius Rabe [ 01/Oct/20 ]

I  tried several times to access https://demopublic.magnolia-cms.com between 2 and 8 PM Yesterday and it was always down. I dont think its temporary down. It is also down right now => 503. And also not just for a few minutes

Comment by Julius Rabe [ 01/Oct/20 ]

Ok, the author system is running. I reproduced it there https://demoauthor.magnolia-cms.com

//country filter enabled
jrabe@jrabe-VirtualBox:~$ ./ttfb -v -n 5 -c "gzip" https://demoauthor.magnolia-cms.com
DNS lookup: 0.062442 TLS handshake: 0.139970 TTFB including connection: 0.163753 TTFB: .023783 Total time: 0.163823 Total size: 1406
DNS lookup: 0.004416 TLS handshake: 0.126141 TTFB including connection: 0.148255 TTFB: .022114 Total time: 0.148328 Total size: 1406
DNS lookup: 0.004739 TLS handshake: 0.092055 TTFB including connection: 0.116987 TTFB: .024932 Total time: 0.117056 Total size: 1406
DNS lookup: 0.004538 TLS handshake: 0.080031 TTFB including connection: 0.101929 TTFB: .021898 Total time: 0.102001 Total size: 1406
DNS lookup: 0.013764 TLS handshake: 0.114354 TTFB including connection: 0.137546 TTFB: .023192 Total time: 0.137668 Total size: 1406fastest .021898 slowest .024932 median .023192


//country filter enabled = false
jrabe@jrabe-VirtualBox:~$ ./ttfb -v -n 5 -c "gzip" https://demoauthor.magnolia-cms.com
DNS lookup: 0.013610 TLS handshake: 0.087367 TTFB including connection: 0.510687 TTFB: .423320 Total time: 0.510763 Total size: 1406
DNS lookup: 0.004689 TLS handshake: 0.082069 TTFB including connection: 0.502899 TTFB: .420830 Total time: 0.503114 Total size: 1406
DNS lookup: 0.004211 TLS handshake: 0.088209 TTFB including connection: 0.505070 TTFB: .416861 Total time: 0.505141 Total size: 1406
DNS lookup: 0.004740 TLS handshake: 0.087765 TTFB including connection: 0.512920 TTFB: .425155 Total time: 0.513131 Total size: 1406
DNS lookup: 0.004546 TLS handshake: 0.098541 TTFB including connection: 0.520874 TTFB: .422333 Total time: 0.521363 Total size: 1406fastest .416861 slowest .425155 median .422333

//country filter enabled = false
jrabe@jrabe-VirtualBox:~$ ./ttfb -v -n 5 -c "gzip" https://demoauthor.magnolia-cms.com
DNS lookup: 0.005040 TLS handshake: 0.092739 TTFB including connection: 0.512790 TTFB: .420051 Total time: 0.512859 Total size: 1406
DNS lookup: 0.004583 TLS handshake: 0.087225 TTFB including connection: 0.506759 TTFB: .419534 Total time: 0.506908 Total size: 1406
DNS lookup: 0.004292 TLS handshake: 0.088054 TTFB including connection: 0.506203 TTFB: .418149 Total time: 0.506273 Total size: 1406
DNS lookup: 0.004624 TLS handshake: 0.084524 TTFB including connection: 0.503742 TTFB: .419218 Total time: 0.503814 Total size: 1406
DNS lookup: 0.004413 TLS handshake: 0.094252 TTFB including connection: 0.512024 TTFB: .417772 Total time: 0.512095 Total size: 1406fastest .417772 slowest .420051 median .419218

//country filter enabled = true
jrabe@jrabe-VirtualBox:~$ ./ttfb -v -n 5 -c "gzip" https://demoauthor.magnolia-cms.com
DNS lookup: 0.004678 TLS handshake: 0.083253 TTFB including connection: 0.105964 TTFB: .022711 Total time: 0.106036 Total size: 1406
DNS lookup: 0.005140 TLS handshake: 0.098204 TTFB including connection: 0.129316 TTFB: .031112 Total time: 0.129391 Total size: 1406
DNS lookup: 0.005630 TLS handshake: 0.094915 TTFB including connection: 0.117181 TTFB: .022266 Total time: 0.117261 Total size: 1406
DNS lookup: 0.004379 TLS handshake: 0.091699 TTFB including connection: 0.114987 TTFB: .023288 Total time: 0.115067 Total size: 1406
DNS lookup: 0.005199 TLS handshake: 0.086360 TTFB including connection: 0.109882 TTFB: .023522 Total time: 0.109952 Total size: 1406fastest .022266 slowest .031112 median .023288

I  know that this does not make sense. I debugged it myself for serveral hours without finding any issues. But Magnolia is not my piece of software so, please reopen the ticket and investigate. I still do not get how you cannot reproduce this issue.

Comment by Julius Rabe [ 02/Oct/20 ]

"Just out of interest, why do you need to switch this filter off?"

=> Personalisation made Problems with the 6.1.6 update. We had to remove the country personalisation-trait from the personalization-trait module.

this is also a way to reproduce this issue. And the way we found the bug.
Just remove the country trait.

/modules/personalization-traits/traits/country

And the TTFB will be around 350 ms delayed.

// with country-trait
jrabe@jrabe-VirtualBox:~$ ./ttfb -v -n 5 -c "gzip" https://demoauthor.magnolia-cms.com 
DNS lookup: 0.005010 TLS handshake: 0.088857 TTFB including connection: 0.190888 TTFB: .102031 Total time: 0.190960 Total size: 1406
DNS lookup: 0.009381 TLS handshake: 0.094193 TTFB including connection: 0.131331 TTFB: .037138 Total time: 0.131408 Total size: 1406
DNS lookup: 0.004892 TLS handshake: 0.103949 TTFB including connection: 0.127144 TTFB: .023195 Total time: 0.127217 Total size: 1406
DNS lookup: 0.004715 TLS handshake: 0.115075 TTFB including connection: 0.139360 TTFB: .024285 Total time: 0.139442 Total size: 1406
DNS lookup: 0.004394 TLS handshake: 0.090910 TTFB including connection: 0.116169 TTFB: .025259 Total time: 0.116251 Total size: 1406fastest .023195 slowest .102031 median .025259

//without country-trait
jrabe@jrabe-VirtualBox:~$ ./ttfb -v -n 5 -c "gzip" https://demoauthor.magnolia-cms.com
DNS lookup: 0.004375 TLS handshake: 0.078692 TTFB including connection: 0.581930 TTFB: .503238 Total time: 0.582002 Total size: 1406
DNS lookup: 0.004357 TLS handshake: 0.105282 TTFB including connection: 0.529369 TTFB: .424087 Total time: 0.529425 Total size: 1406
DNS lookup: 0.004869 TLS handshake: 0.083267 TTFB including connection: 0.505659 TTFB: .422392 Total time: 0.505746 Total size: 1406
DNS lookup: 0.009062 TLS handshake: 0.098131 TTFB including connection: 0.522732 TTFB: .424601 Total time: 0.522807 Total size: 1406
DNS lookup: 0.005016 TLS handshake: 0.108801 TTFB including connection: 0.531370 TTFB: .422569 Total time: 0.531444 Total size: 1406fastest .422392 slowest .503238 median .424087

I assume that it should be normal functionality of mangolia to remove a trait or disable a filter via config. Or is it not?

Comment by Jan Haderka [ 05/Oct/20 ]

I assume that it should be normal functionality of mangolia to remove a trait or disable a filter via config. Or is it not?

Sure you can switch it off. I was simply interested in the reason since it is not commonly seen, i was wondering if there were privacy concerns behind the decision or something.

 

Comment by Jan Haderka [ 05/Oct/20 ]

OK so here's what happens.

  • CountryFilter or rather StorageAwareTraitCollector will store resolved country in a session. This behaviour is not unique for CountryFilter, but is same for other filters that resolve/generate traits.
  • CsrfTokenSecurityFilter that is executed down in filter chain will check if session exists if yes, it would return valid token from the session (assuming there is valid token in the session). If it doesn't detect existence of session, it will not create one, to avoid creation of sessions for anonymous requests, and would instead generate new token every request. Again the behaviour as such is not problematic and expected in given situation/purpose.

The issue described in this ticket is caused by combination of disabling the CountryFilter and that being the only filter active when requestor calls the server that creates session. When disabled, session is not created and thus unmasks the real underlying issue which is that CsrfTokenSecurityFilter takes a lot of time to generate token.

The problem is 2 fold:

  • StorageAwareTraitCollector should not be creating session for anonymous user or should not be used in case of anonymous user to avoid storing/sharing data in session from potentially different person.
  • {{CsrfTokenSecurityFilter }}should avoid using BCrypt to generate the token since bcrypt is designed to be computationally expensive, but should instead use different mechanism to generate token to avoid unnecessary use of CPU on the server and slowness of response to the user when token needs to be generated.
Generated at Mon Feb 12 04:27:48 CET 2024 using Jira 9.4.2#940002-sha1:46d1a51de284217efdcb32434eab47a99af2938b.