F5Networks / f5-bigip-runtime-init

Apache License 2.0
14 stars 15 forks source link

script fails due to delay loading telemetry streaming package #51

Closed thepowercoders closed 1 year ago

thepowercoders commented 1 year ago

DETAILS:

Cloud: Microsoft Azure Offer: f5-big-ip-byol Plan: f5-big-ltm-1slot-byol Image: f5-networks:f5-big-ip-byol:f5-big-ltm-1slot-byol:latest SKU: Standard DS2 v2 (2 vcpus, 7 GiB memory) runtime version: f5-bigip-runtime-init-1.6.0-1.gz.run

ISSUE:

Intermittent failure of script when trying to load TS rpm.

Script has the following configuration in extension_packages / install_operations:

extension_packages:
  install_operations:
    - extensionType: do
      extensionVersion: 1.36.0
      extensionUrl: file:///var/config/rest/downloads/f5-declarative-onboarding-1.36.0-4.noarch.rpm
    - extensionType: as3
      extensionVersion: 3.43.0
      extensionUrl: file:///var/config/rest/downloads/f5-appsvcs-3.43.0-2.noarch.rpm 
    - extensionType: ts
      extensionVersion: 1.32.0
      extensionUrl: file:///var/config/rest/downloads/f5-telemetry-1.32.0-2.noarch.rpm

DO and AS3 RPMs load fine. However, TS errors due to a timeout in bigip-runtime-init waiting for the rpm to be installed. Logs are shown below - timings are as follows:

09:20:22 - installs package and gets a 202 reply with status "INSTALL" (and running task ID)

If I manually load TS in the GUI, it takes about 15 seconds to load into the device so guessing the time allocated here (20 seconds) is not enough. I'm using the following Azure SKU: Standard DS2 v2 (2 vcpus, 7 GiB memory) which is an approved SKU for the LTM/DNS image (Good) which I am using (ref: https://clouddocs.f5.com/cloud/public/v1/matrix.html#microsoft-azure)

LOGS:

2023-03-01T09:20:22.084Z [9361]: info: Installing - ts 1.32.0
2023-03-01T09:20:22.086Z [9361]: silly: Making request: POST http://localhost:8100/mgmt/shared/iapp/package-management-tasks verifyTls: true
2023-03-01T09:20:22.117Z [9361]: silly: Request response: 202 {"packageFilePath":"/var/config/rest/downloads/f5-telemetry-1.32.0-2.noarch.rpm","operation":"INSTALL","id":"79391202-b3b1-4f79-a775-e48d8e3fdc1d","s
tatus":"CREATED","userReference":{"link":"https://localhost/mgmt/shared/authz/users/admin"},"identityReferences":[{"link":"https://localhost/mgmt/shared/authz/users/admin"}],"ownerMachineId":"bdd0c5fd-5f24-40ce-
9639-ed51724af80d","generation":1,"lastUpdateMicros":1677662422091495,"kind":"shared:iapp:package-management-tasks:iapppackagemanagementtaskstate","selfLink":"https://localhost/mgmt/shared/iapp/package-managemen
t-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d"}
2023-03-01T09:20:22.122Z [9361]: silly: Making request: GET http://localhost:8100/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d verifyTls: true
2023-03-01T09:20:22.146Z [9361]: silly: Request response: 200 {"packageFilePath":"/var/config/rest/downloads/f5-telemetry-1.32.0-2.noarch.rpm","operation":"INSTALL","id":"79391202-b3b1-4f79-a775-e48d8e3fdc1d","s
tatus":"STARTED","startTime":"2023-03-01T01:20:22.095-0800","userReference":{"link":"https://localhost/mgmt/shared/authz/users/admin"},"identityReferences":[{"link":"https://localhost/mgmt/shared/authz/users/adm
in"}],"ownerMachineId":"bdd0c5fd-5f24-40ce-9639-ed51724af80d","generation":2,"lastUpdateMicros":1677662422094847,"kind":"shared:iapp:package-management-tasks:iapppackagemanagementtaskstate","selfLink":"https://l
ocalhost/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d"}
2023-03-01T09:20:24.152Z [9361]: silly: Making request: GET http://localhost:8100/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d verifyTls: true
2023-03-01T09:20:24.170Z [9361]: silly: Request response: 200 {"packageFilePath":"/var/config/rest/downloads/f5-telemetry-1.32.0-2.noarch.rpm","operation":"INSTALL","id":"79391202-b3b1-4f79-a775-e48d8e3fdc1d","s
tatus":"STARTED","startTime":"2023-03-01T01:20:22.095-0800","userReference":{"link":"https://localhost/mgmt/shared/authz/users/admin"},"identityReferences":[{"link":"https://localhost/mgmt/shared/authz/users/adm
in"}],"ownerMachineId":"bdd0c5fd-5f24-40ce-9639-ed51724af80d","generation":2,"lastUpdateMicros":1677662422094847,"kind":"shared:iapp:package-management-tasks:iapppackagemanagementtaskstate","selfLink":"https://l
ocalhost/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d"}
2023-03-01T09:20:26.193Z [9361]: silly: Making request: GET http://localhost:8100/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d verifyTls: true
2023-03-01T09:20:26.203Z [9361]: silly: Request response: 200 {"packageFilePath":"/var/config/rest/downloads/f5-telemetry-1.32.0-2.noarch.rpm","operation":"INSTALL","id":"79391202-b3b1-4f79-a775-e48d8e3fdc1d","s
tatus":"STARTED","startTime":"2023-03-01T01:20:22.095-0800","userReference":{"link":"https://localhost/mgmt/shared/authz/users/admin"},"identityReferences":[{"link":"https://localhost/mgmt/shared/authz/users/adm
in"}],"ownerMachineId":"bdd0c5fd-5f24-40ce-9639-ed51724af80d","generation":2,"lastUpdateMicros":1677662422094847,"kind":"shared:iapp:package-management-tasks:iapppackagemanagementtaskstate","selfLink":"https://l
ocalhost/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d"}
2023-03-01T09:20:28.225Z [9361]: silly: Making request: GET http://localhost:8100/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d verifyTls: true
2023-03-01T09:20:28.236Z [9361]: silly: Request response: 200 {"packageFilePath":"/var/config/rest/downloads/f5-telemetry-1.32.0-2.noarch.rpm","operation":"INSTALL","id":"79391202-b3b1-4f79-a775-e48d8e3fdc1d","s
tatus":"STARTED","startTime":"2023-03-01T01:20:22.095-0800","userReference":{"link":"https://localhost/mgmt/shared/authz/users/admin"},"identityReferences":[{"link":"https://localhost/mgmt/shared/authz/users/adm
in"}],"ownerMachineId":"bdd0c5fd-5f24-40ce-9639-ed51724af80d","generation":2,"lastUpdateMicros":1677662422094847,"kind":"shared:iapp:package-management-tasks:iapppackagemanagementtaskstate","selfLink":"https://l
ocalhost/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d"}
2023-03-01T09:20:30.263Z [9361]: silly: Making request: GET http://localhost:8100/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d verifyTls: true
2023-03-01T09:20:30.638Z [9361]: silly: Request response: 200 {"packageFilePath":"/var/config/rest/downloads/f5-telemetry-1.32.0-2.noarch.rpm","operation":"INSTALL","id":"79391202-b3b1-4f79-a775-e48d8e3fdc1d","s
tatus":"STARTED","startTime":"2023-03-01T01:20:22.095-0800","userReference":{"link":"https://localhost/mgmt/shared/authz/users/admin"},"identityReferences":[{"link":"https://localhost/mgmt/shared/authz/users/adm
in"}],"ownerMachineId":"bdd0c5fd-5f24-40ce-9639-ed51724af80d","generation":2,"lastUpdateMicros":1677662422094847,"kind":"shared:iapp:package-management-tasks:iapppackagemanagementtaskstate","selfLink":"https://l
ocalhost/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d"}
2023-03-01T09:20:32.643Z [9361]: silly: Making request: GET http://localhost:8100/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d verifyTls: true
2023-03-01T09:20:33.896Z [9361]: silly: Request response: 200 {"packageFilePath":"/var/config/rest/downloads/f5-telemetry-1.32.0-2.noarch.rpm","operation":"INSTALL","id":"79391202-b3b1-4f79-a775-e48d8e3fdc1d","s
tatus":"STARTED","startTime":"2023-03-01T01:20:22.095-0800","userReference":{"link":"https://localhost/mgmt/shared/authz/users/admin"},"identityReferences":[{"link":"https://localhost/mgmt/shared/authz/users/adm
in"}],"ownerMachineId":"bdd0c5fd-5f24-40ce-9639-ed51724af80d","generation":2,"lastUpdateMicros":1677662422094847,"kind":"shared:iapp:package-management-tasks:iapppackagemanagementtaskstate","selfLink":"https://l
ocalhost/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d"}
2023-03-01T09:20:35.920Z [9361]: silly: Making request: GET http://localhost:8100/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d verifyTls: true
2023-03-01T09:20:35.930Z [9361]: silly: Request response: 200 {"packageFilePath":"/var/config/rest/downloads/f5-telemetry-1.32.0-2.noarch.rpm","operation":"INSTALL","id":"79391202-b3b1-4f79-a775-e48d8e3fdc1d","s
tatus":"STARTED","startTime":"2023-03-01T01:20:22.095-0800","userReference":{"link":"https://localhost/mgmt/shared/authz/users/admin"},"identityReferences":[{"link":"https://localhost/mgmt/shared/authz/users/adm
in"}],"ownerMachineId":"bdd0c5fd-5f24-40ce-9639-ed51724af80d","generation":2,"lastUpdateMicros":1677662422094847,"kind":"shared:iapp:package-management-tasks:iapppackagemanagementtaskstate","selfLink":"https://l
ocalhost/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d"}
2023-03-01T09:20:37.933Z [9361]: silly: Making request: GET http://localhost:8100/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d verifyTls: true
2023-03-01T09:20:37.943Z [9361]: silly: Request response: 200 {"packageFilePath":"/var/config/rest/downloads/f5-telemetry-1.32.0-2.noarch.rpm","operation":"INSTALL","id":"79391202-b3b1-4f79-a775-e48d8e3fdc1d","s
tatus":"STARTED","startTime":"2023-03-01T01:20:22.095-0800","userReference":{"link":"https://localhost/mgmt/shared/authz/users/admin"},"identityReferences":[{"link":"https://localhost/mgmt/shared/authz/users/adm
in"}],"ownerMachineId":"bdd0c5fd-5f24-40ce-9639-ed51724af80d","generation":2,"lastUpdateMicros":1677662422094847,"kind":"shared:iapp:package-management-tasks:iapppackagemanagementtaskstate","selfLink":"https://l
ocalhost/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d"}
2023-03-01T09:20:39.944Z [9361]: silly: Making request: GET http://localhost:8100/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d verifyTls: true
2023-03-01T09:20:39.953Z [9361]: silly: Request response: 200 {"packageFilePath":"/var/config/rest/downloads/f5-telemetry-1.32.0-2.noarch.rpm","operation":"INSTALL","id":"79391202-b3b1-4f79-a775-e48d8e3fdc1d","s
tatus":"STARTED","startTime":"2023-03-01T01:20:22.095-0800","userReference":{"link":"https://localhost/mgmt/shared/authz/users/admin"},"identityReferences":[{"link":"https://localhost/mgmt/shared/authz/users/adm
in"}],"ownerMachineId":"bdd0c5fd-5f24-40ce-9639-ed51724af80d","generation":2,"lastUpdateMicros":1677662422094847,"kind":"shared:iapp:package-management-tasks:iapppackagemanagementtaskstate","selfLink":"https://l
ocalhost/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d"}
2023-03-01T09:20:41.975Z [9361]: silly: Making request: GET http://localhost:8100/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d verifyTls: true
2023-03-01T09:20:41.985Z [9361]: silly: Request response: 200 {"packageFilePath":"/var/config/rest/downloads/f5-telemetry-1.32.0-2.noarch.rpm","operation":"INSTALL","id":"79391202-b3b1-4f79-a775-e48d8e3fdc1d","s
tatus":"STARTED","startTime":"2023-03-01T01:20:22.095-0800","userReference":{"link":"https://localhost/mgmt/shared/authz/users/admin"},"identityReferences":[{"link":"https://localhost/mgmt/shared/authz/users/adm
in"}],"ownerMachineId":"bdd0c5fd-5f24-40ce-9639-ed51724af80d","generation":2,"lastUpdateMicros":1677662422094847,"kind":"shared:iapp:package-management-tasks:iapppackagemanagementtaskstate","selfLink":"https://l
ocalhost/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d"}
2023-03-01T09:20:44.007Z [9361]: silly: Making request: GET http://localhost:8100/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d verifyTls: true
2023-03-01T09:20:44.017Z [9361]: silly: Request response: 200 {"packageFilePath":"/var/config/rest/downloads/f5-telemetry-1.32.0-2.noarch.rpm","operation":"INSTALL","id":"79391202-b3b1-4f79-a775-e48d8e3fdc1d","s
tatus":"STARTED","startTime":"2023-03-01T01:20:22.095-0800","userReference":{"link":"https://localhost/mgmt/shared/authz/users/admin"},"identityReferences":[{"link":"https://localhost/mgmt/shared/authz/users/adm
in"}],"ownerMachineId":"bdd0c5fd-5f24-40ce-9639-ed51724af80d","generation":2,"lastUpdateMicros":1677662422094847,"kind":"shared:iapp:package-management-tasks:iapppackagemanagementtaskstate","selfLink":"https://l
ocalhost/mgmt/shared/iapp/package-management-tasks/79391202-b3b1-4f79-a775-e48d8e3fdc1d"}
2023-03-01T09:20:46.483Z [9361]: error: Max count exceeded, last response: undefined
2023-03-01T09:20:46.491Z [9361]: info: Sending F5 Teem report for failure case.
shyawnkarim commented 1 year ago

Can you try deploying with instance type, Standard_D8s_v4, and let us know if you are still getting these errors?

When installing extensions, more vCPUs and memory are needed. For example, this deployment uses three extensions and deploys the larger instance type by default, as seen here.

thepowercoders commented 1 year ago

Hi - okay I tested with D8s. First time it failed, then passed a couple of times - then failed again. It seems a little better but still no use as it's too unreliable. I've checked the CPU and memory using top for the running system and there does not appear to be any issue with low memory or cpu. I've also done a lot of testing with removing the packages and then re-running the init script to reinstall them. Again, sometimes there is a failure depending on if the F5 is 'busy' with other tasks but generally it works every time on re-run.

I think the underlying issue is that the RPM files are getting bigger each time, but the wait count for install is fixed at 20 seconds. Telemetry streaming RPM has grown from 8.5MB in v1.1 to 20MB in the current version. Would it be possible to just allow a configuration value for the wait/retry time for the packages to cope with transient delays like there is the HTTP_RETRY parm?

thepowercoders commented 1 year ago

Hi - just an update on this. I've noticed a particular issue with a delay after AS3 is loaded. I also see that once loaded, AS3 then automatically requests and downloads Service Discovery RPM. I therefore switched my script so that telemetry was being downloaded first and AS3 last, and this seems to have improved the script processing - I am getting no failures so far.

I would also recommend you look into the logic of the bigip-runtime-init script. As you see in the logs, it is timing out even though the task is returning a "STARTED" status - indicating that the bigip has started processing the task. I don't really see why the script would time out this state so quickly... Surely wait until the task gives another status such as "FAILED" before bailing out, or until the task itself times out in restnoded (which I presume it does eventually).

shyawnkarim commented 1 year ago

Thanks for these additional details. A ticket, internal ID EC-147, has been created for engineering to look into.

mikeshimkus commented 1 year ago

Hi @antonywm, assuming you aren't using our ARM templates to deploy, can you share the user data script you're using to download, install, and run runtime init? Also, which version of BIG-IP are you using?

The extension installation delay can be configured in the controls block, or using an environment variable: https://github.com/F5Networks/f5-bigip-runtime-init#controls

Also, the iControl REST services used by AT packages have a separate bucket of memory and timeout values that usually need to be tweaked using db variables before mcpd starts up (which is why you wouldn't necessarily see an impact using top). You can see how they are used in our templates here: https://github.com/F5Networks/f5-azure-arm-templates-v2/blob/d5082fac3322d1c24e2112613f2b6cc042f0573f/examples/modules/bigip-standalone/bigip.json#L254

Please add these to your user data if not already present, and let us know how it goes.

these are valid in all versions of BIG-IP

/usr/bin/setdb provision.extramb 1000 /usr/bin/setdb restjavad.useextramb true

these are available on 14.1.4.4, 15.1.4.1, 16.1.2 and later

/usr/bin/setdb iapplxrpm.timeout 300 /usr/bin/setdb icrd.timeout 180 /usr/bin/setdb restjavad.timeout 180 /usr/bin/setdb restnoded.timeout 180

(Issue EC-147 mentioned above is for adding these variables to the runtime init examples/documentation)

thepowercoders commented 1 year ago

Hi @mikeshimkus - my onboard script is here. It's from your example one, just modified a bit as we pull the rpm's and DO scripts from azure storage. bigip version is 16.1.3.3.

I did see the extension delay parm but this is just the delay BETWEEN installing the extensions, not the delay waiting for the install task to complete. I also found the parm "HTTP_RETRY" detailed here which I thought would fix the issue, but it didn't seem to do anything when I tested it.

VM is provisioned through Terraform so there is some parameterization in my template too. I run 'provision.extramb 500' already so let me expand that to 1000 and also add the timeout extensions.

mikeshimkus commented 1 year ago

@thepowercoders We just released a new version of Runtime Init: https://github.com/F5Networks/f5-bigip-runtime-init/releases/tag/1.6.1

It adds the db variables and fixes a few other issues you may have run into. Let me know if this helps.

thepowercoders commented 1 year ago

this seems to be more stable now and I am getting successful runs of the script. Thank you!