search

tag1consulting / goose

Load testing framework, inspired by Locust
https://tag1.com/goose
Apache License 2.0
807 stars 70 forks source link

intermittent: "thread 'main' panicked at 'attempt to subtract with overflow', /home/elijah/Projects/goose/src/metrics.rs:2801" #492

Closed ElijahLynn closed 1 year ago

ElijahLynn commented 2 years ago

Seeing this panic intermittently, with command cargo run --example va -- --host https://va-gov-cms.ddev.site --report-file report-file.html --running-metrics 5. It doesn't happen consistently but happens quite a bit right now. I did modify the Umami example a decent amount and copied to ./examples/va/.

thread 'main' panicked at 'attempt to subtract with overflow', /home/elijah/Projects/goose/src/metrics.rs:2801
 GET static asset         |        5.82 |          1 |         124 |          5                                                                                                                                                                                                        
 POST auth /node/%/edit   |        2074 |      2,074 |       2,074 |      2,074                                                                                                   
 POST auth /user/login    |        1347 |        848 |       1,663 |      1,000                                                                                                   
 -------------------------+-------------+------------+-------------+-----------                                                                                                   
 Aggregated               |       18.30 |          1 |       2,118 |          5                                                                                                   
 ------------------------------------------------------------------------------                                                                                                   
 Name                     |                                        Status codes                                                                                                   
 ------------------------------------------------------------------------------                                                                                                   
 GET anon /coronavirus-.. |                                           181 [200]                                                                                                   
 GET auth /node/%/edit    |                                             5 [200]                                                                                                   
 GET auth /user/login     |                                             4 [200]                                                                                                   
 GET static asset         |                                         1,118 [200]                                                                                                   
 POST auth /node/%/edit   |                                             1 [200]                                                                                                   
 POST auth /user/login    |                                             4 [200]                                                                                                   
 -------------------------+----------------------------------------------------                                                                                                   
 Aggregated               |                                         1,313 [200]                                                                                                   

All 8 users hatched, resetting metrics (disable with --no-reset-metrics).                                                                                                         

23:34:40 [INFO] entering GooseAttack phase: Maintain                                                                                                                              
23:34:40 [INFO] set_failure: https://va-gov-cms.ddev.site/user/login: title not found: elijah.lynn@va.gov                                                                         
thread 'main' panicked at 'attempt to subtract with overflow', /home/elijah/Projects/goose/src/metrics.rs:2801:17                                                                 
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace                                                                                                     
23:34:41 [WARN] "/core/assets/vendor/modernizr/modernizr.min.js": error sending request for url (https://va-gov-cms.ddev.site/core/assets/vendor/modernizr/modernizr.min.js?v=3.11.7): error trying to connect: dns error: cancelled
23:34:41 [WARN] "/core/misc/modernizr-additional-tests.js": error sending request for url (https://va-gov-cms.ddev.site/core/misc/modernizr-additional-tests.js?v=3.11.7): error trying to connect: dns error: cancelled
23:34:41 [WARN] "/sites/default/files/js/js_KWaBJDA6zIUpQWjEJtzKgtxh6MMO3rwhx8zlHWVG8mo.js": error sending request for url (https://va-gov-cms.ddev.site/sites/default/files/js/js_KWaBJDA6zIUpQWjEJtzKgtxh6MMO3rwhx8zlHWVG8mo.js): error trying to connect: dns error: cancelled
23:34:41 [WARN] "/sites/default/files/js/js_QUZqYY7yaxyhsmzU_G7TQvvT-GFdvtEIQxYk65aKJAU.js": error sending request for url (https://va-gov-cms.ddev.site/sites/default/files/js/js_QUZqYY7yaxyhsmzU_G7TQvvT-GFdvtEIQxYk65aKJAU.js): error trying to connect: dns error: cancelled
23:34:41 [WARN] "/sites/default/files/css/css_-AvdDCeHeCDT5vXFFgWOrj6MRl0oR--toMn5QS8EzyE.css": error sending request for url (https://va-gov-cms.ddev.site/sites/default/files/css/css_-AvdDCeHeCDT5vXFFgWOrj6MRl0oR--toMn5QS8EzyE.css): error trying to connect: dns error: cancelled
23:34:41 [WARN] "/sites/default/files/css/css_MkReaKJMpANTXjLazgQ5OkKJ7BX1_Jn5monro61qzp4.css": error sending request for url (https://va-gov-cms.ddev.site/sites/default/files/css/css_MkReaKJMpANTXjLazgQ5OkKJ7BX1_Jn5monro61qzp4.css): error trying to connect: dns error: cancelled
23:34:41 [WARN] "/coronavirus-veteran-frequently-asked-questions": error sending request for url (https://va-gov-cms.ddev.site/coronavirus-veteran-frequently-asked-questions): error trying to connect: dns error: cancelled
23:34:41 [WARN] "/coronavirus-veteran-frequently-asked-questions": error sending request for url (https://va-gov-cms.ddev.site/coronavirus-veteran-frequently-asked-questions): error trying to connect: dns error: cancelled
23:34:41 [WARN] "/coronavirus-veteran-frequently-asked-questions": error sending request for url (https://va-gov-cms.ddev.site/coronavirus-veteran-frequently-asked-questions): error trying to connect: dns error: cancelled

Just ran it with RUST_BACKTRACE=1 and got more but I'm not seeing it to be related to Goose just yet:

All 8 users hatched, resetting metrics (disable with --no-reset-metrics).                                                                                                                                                                                                          

23:51:50 [INFO] entering GooseAttack phase: Maintain                                                                                                                                                                                                                               
23:51:50 [INFO] set_failure: https://va-gov-cms.ddev.site/user/login: title not found: elijah.lynn@va.gov                                                                                                                                                                          
thread 'main' panicked at 'attempt to subtract with overflow', /home/elijah/Projects/goose/src/metrics.rs:2801:17                                                                                                                                                                  
stack backtrace:                                                                                                                                                                                                                                                                   
   0: rust_begin_unwind                                                                                                                                                                                                                                                            
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:584:5                                                                                                                                                                                 
   1: core::panicking::panic_fmt                                                                                                                                                                                                                                                   
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:143:14                                                                                                                                                                               
   2: core::panicking::panic                                                                                                                                                                                                                                                       
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:48:5                                                                                                                                                                                 
   3: goose::metrics::<impl goose::GooseAttack>::record_request_metric::{{closure}}                                                                                                                                                                                                
             at /home/elijah/Projects/goose/src/metrics.rs:2801:17                                                                                                                                                                                                                 
   4: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll                                                                                                                                                                                           
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/future/mod.rs:84:19                                                                                                                                                                               
   5: goose::metrics::<impl goose::GooseAttack>::receive_metrics::{{closure}}                                                                                                                                                                                                      
             at /home/elijah/Projects/goose/src/metrics.rs:2878:68                                                                                                                                                                                                                 
   6: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll                                                                                                                                                                                           
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/future/mod.rs:84:19                                                                                                                                                                               
   7: goose::metrics::<impl goose::GooseAttack>::sync_metrics::{{closure}}                                                                                                                                                                                                         
             at /home/elijah/Projects/goose/src/metrics.rs:2671:87                                                                                                                                                                                                                 
   8: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll                                                                                                                                                                                           
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/future/mod.rs:84:19                                                                                                                                                                               
   9: goose::GooseAttack::start_attack::{{closure}}                                                                                                                                                                                                                                
             at /home/elijah/Projects/goose/src/lib.rs:1945:66                                                                                                                                                                                                                     
  10: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll                                                                                                                                                                                           
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/future/mod.rs:84:19                                                                                                                                                                               
  11: goose::GooseAttack::execute::{{closure}}                                                                                                                                                                                                                                     
             at /home/elijah/Projects/goose/src/lib.rs:982:43                                                                                                                                                                                                                      
  12: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll                                                                                                                                                                                           
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/future/mod.rs:84:19                                                                                                                                                                               
  13: va::main::{{closure}}                                                                                                                                                                                                                                                        
             at ./va/main.rs:39:19                                                                                                                                                                                                                                                 
  14: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll                                                                                                                                                                                           
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/future/mod.rs:84:19                                                                                                                                                                               
  15: tokio::park::thread::CachedParkThread::block_on::{{closure}}                                                                                                                                                                                                                 
             at /home/elijah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.15.0/src/park/thread.rs:263:54                                                                                                                                                                
  16: tokio::coop::with_budget::{{closure}}                                                                                                                                                                                                                                        
             at /home/elijah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.15.0/src/coop.rs:102:9                                                                                                                                                                        
  17: std::thread::local::LocalKey<T>::try_with                                                                                                                                                                                                                                    
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/thread/local.rs:413:16                                                                                                                                                                             
  18: std::thread::local::LocalKey<T>::with                                                                                                                                                                                                                                        
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/thread/local.rs:389:9                                                                                                                                                                              
  19: tokio::coop::with_budget                                                                                                                                                                                                                                                     
             at /home/elijah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.15.0/src/coop.rs:95:5                                                                                                                                                                         
  20: tokio::coop::budget                                                                                                                                                                                                                                                          
             at /home/elijah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.15.0/src/coop.rs:72:5                                                                                                                                                                         
  21: tokio::park::thread::CachedParkThread::block_on                                                                                                                                                                                                                              
             at /home/elijah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.15.0/src/park/thread.rs:263:31                                                                                                                                                                
  22: tokio::runtime::enter::Enter::block_on                                                                                                                                                                                                                                       
             at /home/elijah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.15.0/src/runtime/enter.rs:151:13                                                                                                                                                              
  23: tokio::runtime::thread_pool::ThreadPool::block_on                                                                                                                                                                                                                            
             at /home/elijah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.15.0/src/runtime/thread_pool/mod.rs:77:9
  24: tokio::runtime::Runtime::block_on
             at /home/elijah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.15.0/src/runtime/mod.rs:463:43
  25: va::main
             at ./va/main.rs:42:5
  26: core::ops::function::FnOnce::call_once
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/ops/function.rs:227:5
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
23:51:51 [WARN] "/core/assets/vendor/modernizr/modernizr.min.js": error sending request for url (https://va-gov-cms.ddev.site/core/assets/vendor/modernizr/modernizr.min.js?v=3.11.7): error trying to connect: dns error: cancelled
23:51:51 [WARN] "/core/misc/modernizr-additional-tests.js": error sending request for url (https://va-gov-cms.ddev.site/core/misc/modernizr-additional-tests.js?v=3.11.7): error trying to connect: dns error: cancelled
23:51:51 [WARN] "/sites/default/files/js/js_KWaBJDA6zIUpQWjEJtzKgtxh6MMO3rwhx8zlHWVG8mo.js": error sending request for url (https://va-gov-cms.ddev.site/sites/default/files/js/js_KWaBJDA6zIUpQWjEJtzKgtxh6MMO3rwhx8zlHWVG8mo.js): error trying to connect: dns error: cancelled

When it is successful it outputs:

All 8 users hatched, resetting metrics (disable with --no-reset-metrics).  

22:06:38 [INFO] entering GooseAttack phase: Maintain                       
22:06:43 [INFO] printing running metrics after 5 seconds...
ElijahLynn commented 2 years ago

So it appears that when it panicks, the user login title not found. 

23:45:30 [INFO] set_failure: https://va-gov-cms.ddev.site/user/login: title not found: elijah.lynn@va.gov
ElijahLynn commented 2 years ago

So it appears that when it panicks, the user login title not found.

23:45:30 [INFO] set_failure: https://va-gov-cms.ddev.site/user/login: title not found: elijah.lynn@va.gov

I'll try with less users load to see if maybe it is a legitimate application issue. If it is we may be able to better handle that error though.

ElijahLynn commented 2 years ago

It appears it had to do with the edit transaction and the titles maybe not matching with final_url and self.raw.url. Not 100% yet though.

ElijahLynn commented 2 years ago

Gonna close this for now and rubber duck it again when I get back to needing to load test /edit/%, as right now I just need authd GETs.

jeremyandrews commented 2 years ago

In GooseRequestMetricAggregate fail_count is an unsigned integer. The assumption is that fail_count will only be decremented if it was previously incremented.

Your error at metrics.rs line 2801 suggests that a fail_count is being decremented that wasn't ever incremented.

Updates to metrics would happen due to calls to GooseUser::set_failure. The set_failure function should be called with the already-recorded request, do you have logic that's re-using a GooseRequestMetric?

ElijahLynn commented 2 years ago

Thanks, I can't recreate anymore as I wiped that code. But if/when I see this again I'll get some more info based on your suggestions.

update: Oh, note to self, this was when I was trying to adapt the "edit" Umami code to our example. This was in the Goose repo, not using goose-eggs in our application repo.

jeremyandrews commented 2 years ago

I've tried to duplicate but have been unable. For this to panic, you're running without --release, something I rarely do. I've tried causing a variety of errors while running --example umami without using --release but I've been unable to trigger a panic.

@slashrsm @LionsAd While I can't duplicate this, a "solution" would be to convert fail_count to a signed integer. That said: nearest I can tell this can only happen when we're incorrectly modifying metrics (specifically, by passing the wrong GooseRequestMetric to set_failure(). Is it better to panic when there's negative metrics? Or to display them?

jeremyandrews commented 1 year ago

I remain unable to duplicate, and per my notes above this seems to be a mis-use of internal structures. Closing. Feel free to re-open if you can provide more info on duplicating or disagree with my analysis above.

ElijahLynn commented 1 year ago

Thanks @jeremyandrews, I am not on that project anymore so won't be able to tinker with that right now. I think it is good to close for now.