Acceptance tests started to fail with 10.0.3 about app-autoscaler-release

[silvestre]

Hi, is it possible for you to run

make build-test-app

before running bin/test?

If not, please have a look at the acceptance test package that we also release alongside our BOSH releaes, e.g. https://github.com/cloudfoundry/app-autoscaler-release/releases/download/v10.0.3/app-autoscaler-acceptance-tests-v10.0.3.tgz - it already contains the pre-built app.

[fdalfons]

Hi @silvestre,

it worked.
Since our working dir is /tmp/build/a94a8fe5/comp-repo/releases/app-autoscaler-release/src/acceptance, while the Makefile dealing with the build-test-app target is /tmp/build/a94a8fe5/comp-repo/releases/app-autoscaler-release/Makefile, this is the fix I committed in our code:

pushd ../..
make build-test-app
pushd src/acceptance

Unfortunately the following 2 tests systematically fail:

Summarizing 2 Failures:
  [FAIL] AutoScaler dynamic policy when scaling by memoryused There is a scale out and scale in policy [It] should scale out and then back in. [smoke]
  /tmp/build/a94a8fe5/comp-repo/releases/app-autoscaler-release/src/acceptance/app/dynamic_policy_test.go:54
  [FAIL] AutoScaler dynamic policy when scaling by memoryutil when memoryutil [It] should scale out and back in
  /tmp/build/a94a8fe5/comp-repo/releases/app-autoscaler-release/src/acceptance/app/dynamic_policy_test.go:80

Ran 11 of 12 Specs in 869.429 seconds
FAIL! -- 9 Passed | 2 Failed | 0 Pending | 1 Skipped

That is same issue described in #1059

Do you think should we remove from our script the "workaround" we set up, still in place

sed -i '30itime.Sleep(60 * time.Second)' ./app/dynamic_policy_test.go

and described in #1059 (comment) and re-try?
Or is this a different problem having the same effect?

Thanks and regards.

[silvestre]

Hi @fdalfons,

can you also provide the logs of the test failure itself?

It should have printed additional output during the test run, similar to what Donatello provided in #1059 (comment)

Thanks.

[fdalfons]

Hi @silvestre,

here what you asked for memoryutil:

• [FAILED] [402.052 seconds]
AutoScaler dynamic policy when scaling by memoryutil when memoryutil [It] should scale out and back in
/tmp/build/a94a8fe5/comp-repo/releases/app-autoscaler-release/src/acceptance/app/dynamic_policy_test.go:74
 


 =============== DEBUG ===============
  cf app autoscaler-5-dynamic-policy-7147764eb211a500:
  Showing health and status for app autoscaler-5-dynamic-policy-7147764eb211a500 in org OE_Runtimes_Scaling / space RT_Scaler_Smoke as [email protected]...

  name:              autoscaler-5-dynamic-policy-7147764eb211a500
  requested state:   started
  routes:            autoscaler-5-dynamic-policy-7147764eb211a500.eu-gb.cf.dev.appdomain.cloud
  last uploaded:     Wed 03 May 15:02:43 UTC 2023
  stack:             cflinuxfs4
  buildpacks:        
  	name               version   detect output   buildpack name
  	binary_buildpack   1.1.3     binary          binary

  type:           web
  sidecars:       
  instances:      1/1
  memory usage:   128M
       state     since                  cpu    memory          disk           details
  #0   running   2023-05-03T15:04:06Z   0.3%   19.9M of 128M   13.2M of 32M   


  cf autoscaling-api https://autoscaler.eu-gb.cf.dev.cloud.ibm.com:
  Setting AutoScaler api endpoint to https://autoscaler.eu-gb.cf.dev.cloud.ibm.com...
  OK



  cf autoscaling-policy autoscaler-5-dynamic-policy-7147764eb211a500:
  Retrieving policy for app autoscaler-5-dynamic-policy-7147764eb211a500...
  {
  	"instance_min_count": 1,
  	"instance_max_count": 2,
  	"scaling_rules": [
  		{
  			"metric_type": "memoryutil",
  			"breach_duration_secs": 60,
  			"threshold": 63,
  			"operator": ">=",
  			"cool_down_secs": 60,
  			"adjustment": "+1"
  		},
  		{
  			"metric_type": "memoryutil",
  			"breach_duration_secs": 60,
  			"threshold": 58,
  			"operator": "<",
  			"cool_down_secs": 60,
  			"adjustment": "-1"
  		}
  	]
  }


  cf autoscaling-history autoscaler-5-dynamic-policy-7147764eb211a500:
  Retrieving scaling event history for app autoscaler-5-dynamic-policy-7147764eb211a500...
  OK

  No event history were found for app autoscaler-5-dynamic-policy-7147764eb211a500.


  cf autoscaling-metrics autoscaler-5-dynamic-policy-7147764eb211a500 memoryused:
  Retrieving aggregated memoryused metrics for app autoscaler-5-dynamic-policy-7147764eb211a500...
  OK

  No aggregated memoryused metrics were found for app autoscaler-5-dynamic-policy-7147764eb211a500.


  cf autoscaling-metrics autoscaler-5-dynamic-policy-7147764eb211a500 memoryutil:
  Retrieving aggregated memoryutil metrics for app autoscaler-5-dynamic-policy-7147764eb211a500...
  Metrics Name     	Value     	Timestamp     	
  memoryutil       	16%       	2023-05-03T15:08:33Z     	
  memoryutil       	16%       	2023-05-03T15:07:53Z     	
  memoryutil       	16%       	2023-05-03T15:07:13Z     	
  memoryutil       	16%       	2023-05-03T15:06:33Z     	
  memoryutil       	16%       	2023-05-03T15:05:53Z     	
  memoryutil       	16%       	2023-05-03T15:05:13Z     	
  memoryutil       	          	2023-05-03T15:04:33Z     	


 
 [FAILED] Timed out after 300.002s.
  Expected
      <int>: 1
  to equal
      <int>: 2
  In [It] at: /tmp/build/a94a8fe5/comp-repo/releases/app-autoscaler-release/src/acceptance/app/dynamic_policy_test.go:80 @ 05/03/23 15:08:55.244

  Full Stack Trace
    acceptance/helpers.WaitForNInstancesRunning({0xc00028c090, 0x24}, 0x0?, 0x1?, {0x0, 0x0, 0x0})
    	/tmp/build/a94a8fe5/comp-repo/releases/app-autoscaler-release/src/acceptance/helpers/helpers.go:394 +0x1cd
    acceptance/app_test.glob..func4.4.1.2()
    	/tmp/build/a94a8fe5/comp-repo/releases/app-autoscaler-release/src/acceptance/app/dynamic_policy_test.go:80 +0x147

and here for memoryused:

• [FAILED] [404.225 seconds]
AutoScaler dynamic policy when scaling by memoryused There is a scale out and scale in policy [It] should scale out and then back in. [smoke]
/tmp/build/a94a8fe5/comp-repo/releases/app-autoscaler-release/src/acceptance/app/dynamic_policy_test.go:49




  =============== DEBUG ===============
  cf app autoscaler-3-dynamic-policy-4facf0b0e1d52741:
  Showing health and status for app autoscaler-3-dynamic-policy-4facf0b0e1d52741 in org OE_Runtimes_Scaling / space RT_Scaler_Smoke as [email protected]...

  name:              autoscaler-3-dynamic-policy-4facf0b0e1d52741
  requested state:   started
  routes:            autoscaler-3-dynamic-policy-4facf0b0e1d52741.eu-gb.cf.dev.appdomain.cloud
  last uploaded:     Wed 03 May 15:02:41 UTC 2023
  stack:             cflinuxfs4
  buildpacks:        
  	name               version   detect output   buildpack name
  	binary_buildpack   1.1.3     binary          binary

  type:           web
  sidecars:       
  instances:      1/1
  memory usage:   128M
       state     since                  cpu    memory        disk           details
  #0   running   2023-05-03T15:04:11Z   0.3%   20M of 128M   13.2M of 32M   


  cf autoscaling-api https://autoscaler.eu-gb.cf.dev.cloud.ibm.com:
  Setting AutoScaler api endpoint to https://autoscaler.eu-gb.cf.dev.cloud.ibm.com...
  OK



  cf autoscaling-policy autoscaler-3-dynamic-policy-4facf0b0e1d52741:
  Retrieving policy for app autoscaler-3-dynamic-policy-4facf0b0e1d52741...
  {
  	"instance_min_count": 1,
  	"instance_max_count": 2,
  	"scaling_rules": [
  		{
  			"metric_type": "memoryused",
  			"breach_duration_secs": 60,
  			"threshold": 80,
  			"operator": ">=",
  			"cool_down_secs": 60,
  			"adjustment": "+1"
  		},
  		{
  			"metric_type": "memoryused",
  			"breach_duration_secs": 60,
  			"threshold": 78,
  			"operator": "<",
  			"cool_down_secs": 60,
  			"adjustment": "-1"
  		}
  	]
  }


  cf autoscaling-history autoscaler-3-dynamic-policy-4facf0b0e1d52741:
  Retrieving scaling event history for app autoscaler-3-dynamic-policy-4facf0b0e1d52741...
  OK

  No event history were found for app autoscaler-3-dynamic-policy-4facf0b0e1d52741.


  cf autoscaling-metrics autoscaler-3-dynamic-policy-4facf0b0e1d52741 memoryused:
  Retrieving aggregated memoryused metrics for app autoscaler-3-dynamic-policy-4facf0b0e1d52741...
  Metrics Name     	Value     	Timestamp     	
  memoryused       	21MB      	2023-05-03T15:08:33Z     	
  memoryused       	21MB      	2023-05-03T15:07:53Z     	
  memoryused       	21MB      	2023-05-03T15:07:13Z     	
  memoryused       	21MB      	2023-05-03T15:06:33Z     	
  memoryused       	21MB      	2023-05-03T15:05:53Z     	
  memoryused       	21MB      	2023-05-03T15:05:13Z     	
  memoryused       	          	2023-05-03T15:04:33Z 



  [FAILED] Timed out after 300.000s.
  Expected
      <int>: 1
  to equal
      <int>: 2
  In [It] at: /tmp/build/a94a8fe5/comp-repo/releases/app-autoscaler-release/src/acceptance/app/dynamic_policy_test.go:54 @ 05/03/23 15:08:54.936

  Full Stack Trace
    acceptance/helpers.WaitForNInstancesRunning({0xc0002b44e0, 0x24}, 0x0?, 0x1?, {0x0, 0x0, 0x0})
    	/tmp/build/a94a8fe5/comp-repo/releases/app-autoscaler-release/src/acceptance/helpers/helpers.go:394 +0x1cd
    acceptance/app_test.glob..func4.3.1.2()
    	/tmp/build/a94a8fe5/comp-repo/releases/app-autoscaler-release/src/acceptance/app/dynamic_policy_test.go:54 +0x119

Hope those can help.

[silvestre]

Unfortunately we only see that the app is not allocating any memory in your environment. 🤔

Do you have anything that could be considered "special" in your environment?

I think I'll add a cf logs --recent call to the debug output, maybe this gets us some additional insight why the app is not doing what it is supposed to.

[fdalfons]

Hi @silvestre,

nothing I am aware of.
Do you think it could be a good idea to increase the sleep described in #1059 (comment)?

sed -i '30itime.Sleep(60 * time.Second)' ./app/dynamic_policy_test.go

[thelangley]

Hey, we encountered exactly this and did this in our CONFIG it fixed our issues. I assume we are using lovely fresh buildpacks which make the nodejs apps breach/explode when using higher heaps with lower limits

"node_memory_limit": 512