Some tests failing after upgrading to 9.0.1 about app-autoscaler-release

[donacarr]

Failed even increasing the timeout to 10 minutes....

[KevinJCross]

@donacarr sorry about the slow reply. Ive been away for a bit.
We have updated these tests to be able to work in environments with more than 128 mb of ram.
Unfortunately the memory reporting from the NODE applications is not very precise so its taken a bit of trial and error to get this correct.
We know that these tests work with 128 MB of ram and 4G of ram
What settings do you have in the acceptance test config file for node_memory_limit ?
If this is not 128 MB or 4G then we might need to tweak the tests a bit.

To help us a bit more could you please install the the autoscaler cli plugin and run the tests with the environment variable DEBUG=true. This will spit out the metrics reported by the cli at the end of the test surounded by ====== DEBUG ==== . If you could try run it with the tests focused and send us the output this will help us fix the issue.
e.g.

DEBUG=true CONFIG=acceptance_config.json ./bin/test --focus "AutoScaler dynamic policy when scaling by memoryused There is a scale out and scale in policy should scale out and then back in."  --focus "AutoScaler dynamic policy when scaling by memoryutil when memoryutil should scale out and back in" app

[donacarr]

Hi @KevinJCross,

I am using the default 128MB node_memory_limit.

Here are some rlevant debug logs:

  name:              autoscaler-1-dynamic-policy-7f10f5cafe9a4547
  requested state:   started
  routes:            autoscaler-1-dynamic-policy-7f10f5cafe9a4547.xxxxxx
  last uploaded:     Tue 22 Nov 11:00:48 UTC 2022
  stack:             cflinuxfs3
  buildpacks:
        name               version   detect output   buildpack name
        nodejs_buildpack   1.7.73    nodejs          nodejs

  type:           web
  sidecars:
  instances:      1/1
  memory usage:   128M
       state     since                  cpu    memory          disk             details
  #0   running   2022-11-22T11:01:07Z   0.0%   39.7M of 128M   163.7M of 200M


STEP: Use heap 108 mb of heap on app @ 11/22/22 11:01:09.363

cf autoscaling-policy autoscaler-1-dynamic-policy-7f10f5cafe9a4547:
  Retrieving policy for app autoscaler-1-dynamic-policy-7f10f5cafe9a4547...
  {
        "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": 80,
                        "operator": "<",
                        "cool_down_secs": 60,
                        "adjustment": "-1"
                }
        ]
  }


  cf autoscaling-history autoscaler-1-dynamic-policy-7f10f5cafe9a4547:
  Retrieving scaling event history for app autoscaler-1-dynamic-policy-7f10f5cafe9a4547...
  OK

  No event history were found for app autoscaler-1-dynamic-policy-7f10f5cafe9a4547.


  cf autoscaling-metrics autoscaler-1-dynamic-policy-7f10f5cafe9a4547 memoryused:
  Retrieving aggregated memoryused metrics for app autoscaler-1-dynamic-policy-7f10f5cafe9a4547...
  Metrics Name          Value           Timestamp
  memoryused            73MB            2022-11-22T11:05:44Z
  memoryused            73MB            2022-11-22T11:05:04Z
  memoryused            73MB            2022-11-22T11:04:24Z
  memoryused            71MB            2022-11-22T11:03:44Z
  memoryused            72MB            2022-11-22T11:03:04Z
  memoryused            72MB            2022-11-22T11:02:24Z
  memoryused            79MB            2022-11-22T11:01:44Z

  [FAILED] Timed out after 300.001s.
  Expected
      <int>: 1
  to equal
      <int>: 2
  In [It] at: /tmp/build/124e3615/app-autoscaler-bluemix/releases/app-autoscaler-release/src/acceptance/helpers/helpers.go:372 @ 11/22/22 11:06:09.879

for memoryutil :

name:              autoscaler-1-dynamic-policy-4f5948c85d287813
 requested state:   started
 routes:            autoscaler-1-dynamic-policy-4f5948c85d287813.xxxxxx
 last uploaded:     Tue 22 Nov 11:18:47 UTC 2022
 stack:             cflinuxfs3
 buildpacks:
       name               version   detect output   buildpack name
       nodejs_buildpack   1.7.73    nodejs          nodejs

 type:           web
 sidecars:
 instances:      1/1
 memory usage:   128M

 {"result":"success","msg":"using worker to allocate 102MB of heap for 5 minutes"}
 STEP: Wait for scale to 2 instances @ 11/22/22 11:19:10.851
 STEP: Waiting for 2 instances of app: 38f5301c-dc45-429d-a31e-f56552c29bf0 @ 11/22/22 11:19:10.851

cf autoscaling-policy autoscaler-1-dynamic-policy-4f5948c85d287813:
 Retrieving policy for app autoscaler-1-dynamic-policy-4f5948c85d287813...
 {
       "instance_min_count": 1,
       "instance_max_count": 2,
       "scaling_rules": [
               {
                       "metric_type": "memoryutil",
                       "breach_duration_secs": 60,
                       "threshold": 65,
                       "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-1-dynamic-policy-4f5948c85d287813:
 Retrieving scaling event history for app autoscaler-1-dynamic-policy-4f5948c85d287813...
 OK

 No event history were found for app autoscaler-1-dynamic-policy-4f5948c85d287813.


 cf autoscaling-metrics autoscaler-1-dynamic-policy-4f5948c85d287813 memoryused:
 Retrieving aggregated memoryused metrics for app autoscaler-1-dynamic-policy-4f5948c85d287813...
 OK

 No aggregated memoryused metrics were found for app autoscaler-1-dynamic-policy-4f5948c85d287813.


 cf autoscaling-metrics autoscaler-1-dynamic-policy-4f5948c85d287813 memoryutil:
 Retrieving aggregated memoryutil metrics for app autoscaler-1-dynamic-policy-4f5948c85d287813...
 Metrics Name          Value           Timestamp
 memoryutil            51%        2022-11-22T11:24:02Z
 memoryutil            51%        2022-11-22T11:23:22Z
 memoryutil            50%       2022-11-22T11:22:42Z
 memoryutil            50%       2022-11-22T11:22:02Z
 memoryutil            50%       2022-11-22T11:21:22Z
 memoryutil            50%       2022-11-22T11:20:42Z
 memoryutil            50%       2022-11-22T11:20:02Z


[FAILED] Timed out after 300.001s.
 Expected
     <int>: 1
 to equal
     <int>: 2
 In [It] at: /tmp/build/124e3615/app-autoscaler-bluemix/releases/app-autoscaler-release/src/acceptance/helpers/helpers.go:372 @ 11/22/22 11:24:10.852

[KevinJCross]

Do you know which node version it is using ... i.e. in the push of the app is normally has this.
It seems that the node memory usage is different in your setup for some reason. This was tailored for 18.2 I think.
Unfortunately the memory usage changes according to the node version used.
In the first case it should have reached somewhere like 85 mb and in the last one it should have reached 80%.

Either the stats have been harvested incorrectly (Possbly an existing bug) or the app is not operating as expected.
To validate this it might be worth try pushing the app and hitting the endpoints.

There is a rough script to do this (you may need to edit it a bit before running) located in the ./bin/push_test_app.sh
if you login to cf then check the org and space in the script.
try

CONFIG=Your_full_config_location  ./bin/push_test_app.sh 

and this should successfully push the app for you.
Then you can it the app with curl -k https://[your.app.location]/memory/102/10 which should bump the memory up to about 8x mb and then check that curl -k https://[your.app.location]/memory/close the memory goes down below 70mb

I you can confirm the version of node and that the above roughtly works then it might be a bug in the stats collection.

[KevinJCross]

I think we have an issue in our OSS setup that we only see the memory go back down to 76 mb so it was not scalling back down. Yours seem to not get to 80mb so it does not scale up .... Using node here has been super frustrating and we have started creating a new golang app so that the changes in memory are more obvious since in its idle state it only uses 20mb.
This would make the tests easier to develop since using 50% of memory would be easy do to without comming to the point where the test OOMs and gets killed (I think we can only get to 108 mb in node before it crashes).

[KevinJCross]

BTW we are using

5          nodejs_buildpack        cflinuxfs3   true      false    nodejs_buildpack-cflinuxfs3-v1.8.3.zip

[KevinJCross]

Unfortunately the buildpack version might make a difference... even though it should not.

[KevinJCross]

Ive just re-evaluated going back to nodejs v16.
This will not be possible because the memory test needs to be able to use about 3.4G of memory on a 4G environment. Under v16 it struggles to get over 2G and takes about 15mins to get to 2.5G where on v18 it takes less than 1 minute to hold the 3.4G asked for.
Please update your build pack and retry the tests.

[donacarr]

@KevinJCross I retried with latest buildpack but same error

Downloading app package...
     Downloaded app package (49.2K)
     -----> Nodejs Buildpack version 1.8.3
     -----> Installing binaries
     engines.node (package.json): ^18.0.0
     engines.npm (package.json): unspecified (use default)
     -----> Installing node 18.12.1
     Download [https://buildpacks.cloudfoundry.org/dependencies/node/node_18.12.1_linux_x64_cflinuxfs3_62ff5890.tgz]
     Using default npm version: 8.19.2
     -----> Installing yarn 1.22.19
     Download [https://buildpacks.cloudfoundry.org/dependencies/yarn/yarn_1.22.19_linux_noarch_any-stack_32d0e82e.tgz]
     Installed yarn 1.22.19
     -----> Creating runtime environment
     PRO TIP: It is recommended to vendor the application's Node.js dependencies
     Visit http://docs.cloudfoundry.org/buildpacks/node/index.html#vendoring
     NODE_ENV=production
     NODE_OPTIONS=--max_old_space_size=128
     NODE_TLS_REJECT_UNAUTHORIZED=0
     NODE_HOME=/tmp/contents2823102458/deps/0/node
     NODE_MODULES_CACHE=true
     NODE_VERBOSE=false
     NPM_CONFIG_LOGLEVEL=error
     NPM_CONFIG_PRODUCTION=true

Then I tried manually to push a test app like you suggested and the app scaled out and back in in few minutes...
Any idea??

[KevinJCross]

hiya, in 9.2.0 we upped the memory-useage limit from 80 to 87 mb this helped with running the memory used test in another environment. It would probably solve your issue with th memoryused test.
The memory utilisation test looks like it needs some more debugging :/.

It does look like the the app might have restarted. Could you get the logs from the app ?

[KevinJCross]

There is the env var os.Getenv("SKIP_TEARDOWN") == "true" SKIP_TEARDOWN=true which will leave the app around after the tests.

[donacarr]

@KevinJCross even with 9.2.0 no luck but I noted that app crashed with OOM after this command

  [2022-12-07 09:17:54.46 (UTC)]> curl -k -H Expect: -s https://autoscaler-2-dynamic-policy-520df702a38b0f82.xxxxx/memory/108/5 -H X-Cf-App-Instance: 483e3fcd-f2f3-48d6-a5b8-c310f900f9fd:0 -f --connect-timeout 5 --max-time 10 --retry 5 --retry-delay 0 --retry-max-time 15
  {"result":"success","msg":"using worker to allocate 108MB of heap for 5 minutes"}
  STEP: wait for scale to 2 @ 12/07/22 09:17:54.742
  STEP: Waiting for 2 instances of app: 483e3fcd-f2f3-48d6-a5b8-c310f900f9fd @ 12/07/22 09:17:54.742

looking to the events:

2022-12-07T10:18:02.00+0100   app.crash                   autoscaler-2-dynamic-policy-520df702a38b0f82   index: 0, reason: CRASHED, cell_id: 8b04ab79-db34-4d1a-bc68-03a7f7a5a80b, instance: 1483acc2-d50e-4cb0-62ea-9816, exit_description: APP/PROC/WEB: Exited with status 137 (out of memory)
2022-12-07T10:18:02.00+0100   audit.app.process.crash     web                                            index: 0, reason: CRASHED, cell_id: 8b04ab79-db34-4d1a-bc68-03a7f7a5a80b, instance: 1483acc2-d50e-4cb0-62ea-9816, exit_description: APP/PROC/WEB: Exited with status 137 (out of memory)
2022-12-07T10:17:39.00+0100   audit.app.revision.create   [email protected]
2022-12-07T10:17:39.00+0100   audit.app.start             [email protected]

So the autoscaling is not working since app got OOM in both the scenarios

[KevinJCross]

So the autoscaling is not working since app got OOM in both the scenarios

In both of them ... wow.
OK hmmm ... this is now getting really hard as the node memory usage is not consistent in any environment.
Can you try the curl -k -H Expect: -s https://[app domain]/memory/108/5 command yourself to see if it ooms ?
Otherwise Im not sure how to progress this test issue as this limit should be under the set limit for the app deployment that you stated as "128M".

[KevinJCross]

Ive just checked with the OSS acceptance test run for the mem util test. It looks like this when it attempts to use the memory.

curl -k -H Expect: -s https://autoscaler-2-dynamic-policy-dacca05dd9cd0f75.xxx/memory/102/5 -H X-Cf-App-Instance: 6b2ea1df-1d61-47c1-aec0-7442cf62eaed:0 -f --connect-timeout 5 --max-time 10 --retry 5 --retry-delay 0 --retry-max-time 15

Note the 102 not 108 ?
which version of the tests are you running ?

[donacarr]

I am using 9.2.0 and Memoryused test uses 108.
Btw it is curious that on same app when you run the curl manually the app does not get OOM.
So something of wrong happen when the curl is executed programmatically...

[KevinJCross]

Memoryused test uses 108 ... ok ... we can drop this down to 102.

Would you mind tweaking this limit to something that works in ./app/dynamic_policy_test.go Line 39

int64(math.Min(float64(cfg.NodeMemoryLimit-20), 200))

The -20 is an approximation on how much the node environment takes itself so if you can tweak that to something over 20, e.g. -26, that does not oom in the test and we can try make that work with the OSS ci pipeline.

[KevinJCross]

Also to be certain can you get the app logs from the crashing app just to double check its an OOM ?

[donacarr]

it is really OOM

   2022-12-07T12:33:46.33+0100 [APP/PROC/WEB/0] OUT dummy application started
   2022-12-07T12:33:48.08+0100 [CELL/0] OUT Container became healthy
   2022-12-07T12:33:52.94+0100 [RTR/1] OUT autoscaler-1-dynamic-policy-70cefc80e54fcbdc.yyyy - [2022-12-07T11:33:52.820544132Z] "GET /memory/108/5 HTTP/1.1" 200 0 81 "-" "curl/7.64.0" "ddd:50062" "ddddd:61054" x_forwarded_for:"dddd, ffff" x_forwarded_proto:"https" vcap_request_id:"82f1e7c7-5ddc-4b87-6318-79aa3b4f9b28" response_time:0.122911 gorouter_time:0.000708 app_id:"49ae0a3d-0ee2-4055-8d2d-f5407beaac7f" app_index:"0" instance_id:"0f79217f-8acf-48a1-4bae-2b3b" x_cf_routererror:"-" x_global_transaction_id:"405fffce63907a20ac8e68f7" true_client_ip:"-" x_b3_traceid:"6f782d34b0115d9c1c90c8833291e7df" x_b3_spanid:"1c90c8833291e7df" x_b3_parentspanid:"-" b3:"6f782d34b0115d9c1c90c8833291e7df-1c90c8833291e7df"
   2022-12-07T12:33:53.37+0100 [APP/PROC/WEB/0] OUT Mem: new event {"action":"chew","totalMemoryUsage":108,"source":"/memory/:megabytes/:minute"}
   2022-12-07T12:33:54.24+0100 [APP/PROC/WEB/0] ERR Killed
   2022-12-07T12:33:54.25+0100 [APP/PROC/WEB/0] ERR npm notice
   2022-12-07T12:33:54.25+0100 [APP/PROC/WEB/0] ERR npm notice New major version of npm available! 8.19.2 -> 9.1.3
   2022-12-07T12:33:54.25+0100 [APP/PROC/WEB/0] ERR npm notice Changelog: <https://github.com/npm/cli/releases/tag/v9.1.3>
   2022-12-07T12:33:54.25+0100 [APP/PROC/WEB/0] ERR npm notice Run `npm install -g [email protected]` to update!
   2022-12-07T12:33:54.25+0100 [APP/PROC/WEB/0] ERR npm notice
   2022-12-07T12:33:54.27+0100 [APP/PROC/WEB/0] OUT Exit status 137 (out of memory)
   2022-12-07T12:33:54.27+0100 [CELL/SSHD/0] OUT Exit status 0

I had a successfull test with
int64(math.Min(float64(cfg.NodeMemoryLimit-28), 200))

Here is the logs

  2022-12-07T12:54:21.25+0100 [STG/0] OUT Security group rules were updated
   2022-12-07T12:54:21.31+0100 [STG/0] OUT Cell 9fefc2ae-d30b-47c1-ad1f-279dd66551ab successfully created container for instance cc431fc6-a451-47e5-b471-2d16f2875e40
   2022-12-07T12:54:21.72+0100 [STG/0] OUT Downloading app package...
   2022-12-07T12:54:21.79+0100 [STG/0] OUT Downloaded app package (49.3K)
   2022-12-07T12:54:22.02+0100 [STG/0] OUT -----> Nodejs Buildpack version 1.8.3
   2022-12-07T12:54:22.02+0100 [STG/0] OUT -----> Installing binaries
   2022-12-07T12:54:22.02+0100 [STG/0] OUT engines.node (package.json): ^18.0.0
   2022-12-07T12:54:22.02+0100 [STG/0] OUT engines.npm (package.json): unspecified (use default)
   2022-12-07T12:54:22.02+0100 [STG/0] OUT -----> Installing node 18.12.1
   2022-12-07T12:54:22.02+0100 [STG/0] OUT Download [https://buildpacks.cloudfoundry.org/dependencies/node/node_18.12.1_linux_x64_cflinuxfs3_62ff5890.tgz]
   2022-12-07T12:54:26.74+0100 [STG/0] OUT Using default npm version: 8.19.2
   2022-12-07T12:54:26.74+0100 [STG/0] OUT -----> Installing yarn 1.22.19
   2022-12-07T12:54:26.74+0100 [STG/0] OUT Download [https://buildpacks.cloudfoundry.org/dependencies/yarn/yarn_1.22.19_linux_noarch_any-stack_32d0e82e.tgz]
   2022-12-07T12:54:27.24+0100 [STG/0] OUT Installed yarn 1.22.19
   2022-12-07T12:54:27.24+0100 [STG/0] OUT -----> Creating runtime environment
   2022-12-07T12:54:27.24+0100 [STG/0] OUT PRO TIP: It is recommended to vendor the application's Node.js dependencies
   2022-12-07T12:54:27.24+0100 [STG/0] OUT Visit http://docs.cloudfoundry.org/buildpacks/node/index.html#vendoring
   2022-12-07T12:54:27.24+0100 [STG/0] OUT NODE_ENV=production
   2022-12-07T12:54:27.24+0100 [STG/0] OUT NODE_OPTIONS=--max_old_space_size=128
   2022-12-07T12:54:27.24+0100 [STG/0] OUT NODE_TLS_REJECT_UNAUTHORIZED=0
   2022-12-07T12:54:27.24+0100 [STG/0] OUT NODE_HOME=/tmp/contents3817096035/deps/0/node
   2022-12-07T12:54:27.24+0100 [STG/0] OUT NODE_MODULES_CACHE=true
   2022-12-07T12:54:27.24+0100 [STG/0] OUT NODE_VERBOSE=false
   2022-12-07T12:54:27.24+0100 [STG/0] OUT NPM_CONFIG_LOGLEVEL=error
   2022-12-07T12:54:27.24+0100 [STG/0] OUT NPM_CONFIG_PRODUCTION=true
   2022-12-07T12:54:27.24+0100 [STG/0] OUT -----> Building dependencies
   2022-12-07T12:54:27.24+0100 [STG/0] OUT Installing node modules (package.json + package-lock.json)
   2022-12-07T12:54:27.83+0100 [STG/0] OUT (node:53) Warning: Setting the NODE_TLS_REJECT_UNAUTHORIZED environment variable to '0' makes TLS connections and HTTPS requests insecure by disabling certificate verification.
   2022-12-07T12:54:27.83+0100 [STG/0] OUT (Use `node --trace-warnings ...` to show where the warning was created)
   2022-12-07T12:54:29.47+0100 [STG/0] OUT added 65 packages, and audited 66 packages in 2s
   2022-12-07T12:54:29.47+0100 [STG/0] OUT 9 packages are looking for funding
   2022-12-07T12:54:29.48+0100 [STG/0] OUT run `npm fund` for details
   2022-12-07T12:54:29.48+0100 [STG/0] OUT found 0 vulnerabilities
   2022-12-07T12:54:29.48+0100 [STG/0] OUT npm notice
   2022-12-07T12:54:29.48+0100 [STG/0] OUT npm notice New major version of npm available! 8.19.2 -> 9.1.3
   2022-12-07T12:54:29.48+0100 [STG/0] OUT npm notice Changelog: <https://github.com/npm/cli/releases/tag/v9.1.3>
   2022-12-07T12:54:29.48+0100 [STG/0] OUT npm notice Run `npm install -g [email protected]` to update!
   2022-12-07T12:54:29.48+0100 [STG/0] OUT npm notice
   2022-12-07T12:54:30.09+0100 [STG/0] OUT **WARNING** Unmet dependencies don't fail npm install but may cause runtime issues
   2022-12-07T12:54:30.09+0100 [STG/0] OUT See: https://github.com/npm/npm/issues/7494
   2022-12-07T12:54:30.11+0100 [STG/0] OUT Contrast Security no credentials found. Will not write environment files.
   2022-12-07T12:54:30.11+0100 [STG/0] OUT inside Sealights hook
   2022-12-07T12:54:30.11+0100 [STG/0] OUT service is not configured to run with Sealights
   2022-12-07T12:54:39.86+0100 [STG/0] OUT Exit status 0
   2022-12-07T12:54:39.86+0100 [STG/0] OUT Uploading droplet, build artifacts cache...
   2022-12-07T12:54:39.86+0100 [STG/0] OUT Uploading droplet...
   2022-12-07T12:54:39.86+0100 [STG/0] OUT Uploading build artifacts cache...
   2022-12-07T12:54:41.09+0100 [API/4] OUT Creating droplet for app with guid 316d8e4f-7f2a-48d5-9a36-12ab498d031c
   2022-12-07T12:54:42.09+0100 [STG/0] OUT Uploaded build artifacts cache (45.4M)
   2022-12-07T12:54:50.17+0100 [STG/0] OUT Uploaded droplet (45.4M)
   2022-12-07T12:54:50.18+0100 [STG/0] OUT Uploading complete
   2022-12-07T12:54:50.55+0100 [STG/0] OUT Cell 9fefc2ae-d30b-47c1-ad1f-279dd66551ab stopping instance cc431fc6-a451-47e5-b471-2d16f2875e40
   2022-12-07T12:54:50.55+0100 [STG/0] OUT Cell 9fefc2ae-d30b-47c1-ad1f-279dd66551ab destroying container for instance cc431fc6-a451-47e5-b471-2d16f2875e40
   2022-12-07T12:54:51.67+0100 [STG/0] OUT Cell 9fefc2ae-d30b-47c1-ad1f-279dd66551ab successfully destroyed container for instance cc431fc6-a451-47e5-b471-2d16f2875e40
   2022-12-07T12:54:51.92+0100 [API/0] OUT Updated app with guid 316d8e4f-7f2a-48d5-9a36-12ab498d031c ({:droplet_guid=>"d7814869-ed1f-4ee0-8490-4075accce3f5"})
   2022-12-07T12:54:52.03+0100 [API/5] OUT Creating revision for app with guid 316d8e4f-7f2a-48d5-9a36-12ab498d031c
   2022-12-07T12:54:52.14+0100 [API/5] OUT Starting app with guid 316d8e4f-7f2a-48d5-9a36-12ab498d031c
   2022-12-07T12:54:52.38+0100 [CELL/0] OUT Cell 631afb79-3884-40cf-a029-ac6f994579c8 creating container for instance 4dd268ad-b5ad-4e2b-4539-c182
   2022-12-07T12:54:52.98+0100 [CELL/0] OUT Security group rules were updated
   2022-12-07T12:54:53.04+0100 [CELL/0] OUT Cell 631afb79-3884-40cf-a029-ac6f994579c8 successfully created container for instance 4dd268ad-b5ad-4e2b-4539-c182
   2022-12-07T12:54:53.30+0100 [CELL/0] OUT Downloading droplet...
   2022-12-07T12:54:55.90+0100 [CELL/0] OUT Downloaded droplet (45.4M)
   2022-12-07T12:54:55.91+0100 [CELL/0] OUT Starting health monitoring of container
   2022-12-07T12:55:00.22+0100 [APP/PROC/WEB/0] ERR (node:7) Warning: Setting the NODE_TLS_REJECT_UNAUTHORIZED environment variable to '0' makes TLS connections and HTTPS requests insecure by disabling certificate verification.
   2022-12-07T12:55:00.22+0100 [APP/PROC/WEB/0] ERR (Use `node --trace-warnings ...` to show where the warning was created)
   2022-12-07T12:55:00.23+0100 [APP/PROC/WEB/0] OUT > [email protected] start
   2022-12-07T12:55:00.23+0100 [APP/PROC/WEB/0] OUT > node --expose-gc app.js
   2022-12-07T12:55:02.61+0100 [APP/PROC/WEB/0] OUT dummy application started
   2022-12-07T12:55:04.46+0100 [CELL/0] OUT Container became healthy
   2022-12-07T12:56:07.17+0100 [RTR/4] OUT autoscaler-1-dynamic-policy-482c80bad2435109.yyyy - [2022-12-07T11:56:07.138009303Z] "GET /memory/100/5 HTTP/1.1" 200 0 81 "-" "curl/7.64.0" "zzzzzz.ss.ss.s.:40310" "tt.tt..tt.t:61098" x_forwarded_for:"ddd.d.d.d.d., aa.a.aa..a" x_forwarded_proto:"https" vcap_request_id:"9694413c-f70f-4212-7bdc-7b655346353c" response_time:0.032895 gorouter_time:0.000525 app_id:"316d8e4f-7f2a-48d5-9a36-12ab498d031c" app_index:"0" instance_id:"4dd268ad-b5ad-4e2b-4539-c182" x_cf_routererror:"-" x_global_transaction_id:"405fffce63907f57ac9214a7" true_client_ip:"-" x_b3_traceid:"4949f6bdad09925d71abc8c62fd5a9b8" x_b3_spanid:"71abc8c62fd5a9b8" x_b3_parentspanid:"-" b3:"4949f6bdad09925d71abc8c62fd5a9b8-71abc8c62fd5a9b8"
   2022-12-07T12:56:07.50+0100 [APP/PROC/WEB/0] OUT Mem: new event {"action":"chew","totalMemoryUsage":100,"source":"/memory/:megabytes/:minute"}
   2022-12-07T12:56:08.41+0100 [APP/PROC/WEB/0] OUT mem: before allocation memory used: {"rss":68808704,"heapTotal":8679424,"heapUsed":6554536,"external":1913215,"arrayBuffers":26764}
   2022-12-07T12:56:08.41+0100 [APP/PROC/WEB/0] OUT mem: trying to allocate 100 M
   2022-12-07T12:56:08.41+0100 [APP/PROC/WEB/0] OUT mem: memory used array length was 3918  amount of memory used {"rss":102440960,"heapTotal":42233856,"heapUsed":37797144,"external":1985580,"arrayBuffers":94466}
   2022-12-07T12:57:56.95+0100 [API/1] OUT Scaling process: "web"
   2022-12-07T12:57:57.10+0100 [CELL/1] OUT Cell 34ce5f5e-2b87-4ba5-a9aa-5038500cf7fc creating container for instance f49c5d98-2c81-4bb1-4872-7ad8
   2022-12-07T12:57:59.07+0100 [CELL/1] OUT Security group rules were updated
   2022-12-07T12:57:59.17+0100 [CELL/1] OUT Cell 34ce5f5e-2b87-4ba5-a9aa-5038500cf7fc successfully created container for instance f49c5d98-2c81-4bb1-4872-7ad8
   2022-12-07T12:58:00.21+0100 [CELL/1] OUT Downloading droplet...
   2022-12-07T12:58:01.81+0100 [RTR/4] OUT autoscaler-1-dynamic-policy-482c80bad2435109.yyyy - [2022-12-07T11:58:01.768103444Z] "GET /memory/close HTTP/1.1" 200 0 30 "-" "curl/7.64.0" "1tt.yy.tt.tt:30001" "yy.yy.yy.yy:61098" x_forwarded_for:"ff..fff..f.f, ff.f.f.f.f." x_forwarded_proto:"https" vcap_request_id:"9f0bb6e4-21a5-4843-7db3-52eea12d4fa7" response_time:0.046857 gorouter_time:0.000517 app_id:"316d8e4f-7f2a-48d5-9a36-12ab498d031c" app_index:"0" instance_id:"4dd268ad-b5ad-4e2b-4539-c182" x_cf_routererror:"-" x_global_transaction_id:"ab45c7d863907fc9acf770d7" true_client_ip:"-" x_b3_traceid:"65c58caaa42afa495bbb6994b27f0a90" x_b3_spanid:"5bbb6994b27f0a90" x_b3_parentspanid:"-" b3:"65c58caaa42afa495bbb6994b27f0a90-5bbb6994b27f0a90"
   2022-12-07T12:58:01.81+0100 [APP/PROC/WEB/0] OUT Mem: new event {"action":"stop","source":"close"}
   2022-12-07T12:58:04.81+0100 [CELL/1] OUT Downloaded droplet (45.4M)
   2022-12-07T12:58:04.81+0100 [CELL/1] OUT Starting health monitoring of container
   2022-12-07T12:58:14.40+0100 [APP/PROC/WEB/1] ERR (node:7) Warning: Setting the NODE_TLS_REJECT_UNAUTHORIZED environment variable to '0' makes TLS connections and HTTPS requests insecure by disabling certificate verification.
   2022-12-07T12:58:14.40+0100 [APP/PROC/WEB/1] ERR (Use `node --trace-warnings ...` to show where the warning was created)
   2022-12-07T12:58:14.47+0100 [APP/PROC/WEB/1] OUT > [email protected] start
   2022-12-07T12:58:14.47+0100 [APP/PROC/WEB/1] OUT > node --expose-gc app.js
   2022-12-07T12:58:17.41+0100 [APP/PROC/WEB/1] OUT dummy application started
   2022-12-07T12:58:18.07+0100 [CELL/1] OUT Container became healthy
   2022-12-07T13:00:56.79+0100 [API/5] OUT Scaling process: "web"
   2022-12-07T13:00:56.91+0100 [CELL/1] OUT Cell 34ce5f5e-2b87-4ba5-a9aa-5038500cf7fc stopping instance f49c5d98-2c81-4bb1-4872-7ad8
   2022-12-07T13:00:58.10+0100 [API/4] OUT Enqueued job to delete app with guid 316d8e4f-7f2a-48d5-9a36-12ab498d031c
   2022-12-07T13:01:01.47+0100 [CELL/0] OUT Cell 631afb79-3884-40cf-a029-ac6f994579c8 stopping instance 4dd268ad-b5ad-4e2b-4539-c182

[KevinJCross]

ok great ... let me try try this out in a PR on main and maybe we can get this into a release.

[KevinJCross]

Trying this out on a pr to see if it passes through our OSS ci
#1171

[KevinJCross]

Does the memory utilisation tests work ?

[donacarr]

yes ..it worked using same heapsize like before
int64(math.Min(float64(cfg.NodeMemoryLimit-28), 200))

[KevinJCross]

Ok great ... Ive merged the fix and will try get a release out.

[donacarr]

I dont'see here

app-autoscaler-release/src/acceptance/app/dynamic_policy_test.go

Line 76 in 36c2024

heapToUse := int(float32(cfg.NodeMemoryLimit) * 0.8)

heapsize as above

[KevinJCross]

ah ok so meant add that ... hmmm not sure thats going to work since in the 4G environments it wont be enough :/.
Ill add a max of float64(cfg.NodeMemoryLimit-28)

[KevinJCross]

@donacarr Ive merged #1181 in response to you requests... Ill leave this open until you try the next release.

[KevinJCross]

@donacarr Release https://github.com/cloudfoundry/app-autoscaler-release/releases/tag/v9.2.1 is out and should fix you issues

[donacarr]

@KevinJCross even upgrading to 9.2.1 the two tests are still failing randomly
So I added a sleep of 60 secs after

app-autoscaler-release/src/acceptance/app/dynamic_policy_test.go

Line 27 in 31d01fc

StartApp(appName, cfg.CfPushTimeoutDuration())

since I noted that the app as soon started has a memory peak and then stabilizes...
The idea is to attach the scaling policy and call CurlAppInstance() after the sleep.
In this way the tests are working fine...
What do you think?

[donacarr]

Hi @KevinJCross any update?

[joergdw]

Hi @donacarr, thank you for your reminder. We re-open the issue.

[donacarr]

Hi @KevinJCross what do you think of #1059 (comment) ?

[silvestre]

I have rewritten the test app in #1375 which should fix this issue as the memory usage behavior should be more predictable now. (The new test-app is also unit-tested itself, which the old old one was not.).

[silvestre]

With v10.0.3 the acceptance-tests should be fixed. Please reopen in case you still see issues.