SelfTest returns 503 but actually passes

[kaustriaf5]

ISSUE TYPE

Bug Report

AS3 BUILD/ VERSION

f5-appsvcs-3.5

BIGIP VERSION

BIG-IP 13.1.1.0.0.4

SUMMARY

Error on self test:
Reported by:
@malbertus
@ColinHeathman
From this issue 23

See details below

STEPS TO REPRODUCE

Restart restnoded
tmsh restart /sys service restnoded

POST to https://{{host}}/mgmt/shared/appsvcs/selftest using a service account (not admin)

EXPECTED RESULTS

Self test suite passes

ACTUAL RESULTS

{"message":"POST http://admin:XXXXXX@localhost:8100/mgmt/shared/appsvcs/declare submit tests response=503 body={\"code\":503,\"declarationFullId\":\"\",\"message\":\"Device localhost configuration operation in progress for (urn:uuid:5cff22e8-d3d1-6056-8577-b0b193f812eb), please try again in 2 minutes\"}","level":"error"}

Reported by @malbertus From this issue 23:

I'm having a similar issue, though now it's urn:uuid:5cff22e8-d3d1-6056-8577-b0b193f812eb causing the 500 response instead of TEST_AS3_Basics. Coincidentally, this is the ID given to the Declaration Using All Properties appendix so I assume that the intent is to create and delete this declaration after posting to the selftest api.

Problem seems to be how long it takes to create and delete this selftest declaration as the 500 response is given 60 seconds after initial POST, yet the declaration appears to be created and deleted successfully a few seconds after the timeout, which suggests the selftest passes.

This is with 3.5

Mon, 22 Oct 2018 06:09:53 GMT - fine: [appsvcs] {"message":"probe target 'localhost'","level":"debug"}
Mon, 22 Oct 2018 06:09:53 GMT - fine: [appsvcs] {"message":"found F5 device at http://admin:@localhost:8100 port 8100","level":"debug"}
Mon, 22 Oct 2018 06:09:53 GMT - info: [appsvcs] {"message":"modules provisioned: ltm","level":"info"}
Mon, 22 Oct 2018 06:09:53 GMT - info: [appsvcs] {"message":"target device is BIG-IP version 13.1.1.0.0.4","level":"info"}
Mon, 22 Oct 2018 06:09:54 GMT - info: [appsvcs] {"message":"cloud libraries installed: true","level":"info"}
Mon, 22 Oct 2018 06:09:54 GMT - fine: [appsvcs] {"message":"got transaction lock; fetch previous decl","level":"debug"}
Mon, 22 Oct 2018 06:09:54 GMT - fine: [appsvcs] {"message":"did not get age 0 declaration","level":"debug"}
Mon, 22 Oct 2018 06:09:54 GMT - fine: [appsvcs] {"message":"found no stored declaration","level":"debug"}
Mon, 22 Oct 2018 06:09:54 GMT - fine: [appsvcs] {"message":"validating declaration having id urn:uuid:5cff22e8-d3d1-6056-8577-b0b193f812eb|AS3_Basics","level":"debug"}
<SNIP>
Mon, 22 Oct 2018 06:10:55 GMT - info: [appsvcs] {"message":"Error: Device localhost configuration operation in progress for (urn:uuid:5cff22e8-d3d1-6056-8577-b0b193f812eb), please try again in 2 minutes","stack":["Error: Device localhost configuration operation in progress for (urn:uuid:5cff22e8-d3d1-6056-8577-b0b193f812eb), please try again in 2 minutes","/var/config/rest/iapps/f5-appsvcs/nodejs/declarationRequestHandler.js:1389:37","process._tickCallback (node.js:438:9)"],"level":"info"}
Mon, 22 Oct 2018 06:10:55 GMT - severe: [appsvcs] {"message":"POST http://admin:XXXXXX@localhost:8100/mgmt/shared/appsvcs/declare submit tests response=503 body={\"code\":503,\"declarationFullId\":\"\",\"message\":\"Device localhost configuration operation in progress for (urn:uuid:5cff22e8-d3d1-6056-8577-b0b193f812eb), please try again in 2 minutes\"}","level":"error"}
Mon, 22 Oct 2018 06:10:55 GMT - severe: [ErrorHandlingModule] RestOperation failed: "/shared/appsvcs/selftest". {"error":{"code":500,"message":"POST http://admin:XXXXXX@localhost:8100/mgmt/shared/appsvcs/declare submit tests response=503 body={\"code\":503,\"declarationFullId\":\"\",\"message\":\"Device localhost configuration operation in progress for (urn:uuid:5cff22e8-d3d1-6056-8577-b0b193f812eb), please try again in 2 minutes\"}","innererror":{"referer":"restnoded","originalRequestBody":"\"{}\"","errorStack":[]}}}
<SNIP>
Mon, 22 Oct 2018 06:10:59 GMT - fine: [appsvcs] {"message":"deployed= 5 good 0 bad 5 changes","level":"debug"}
Mon, 22 Oct 2018 06:10:59 GMT - fine: [appsvcs] {"message":"5 changes, save current declaration for later","level":"debug"}
Mon, 22 Oct 2018 06:10:59 GMT - fine: [appsvcs] {"message":"purge stored decls in excess of 0","level":"debug"}
Mon, 22 Oct 2018 06:10:59 GMT - fine: [appsvcs] {"message":"unlocking transaction","level":"debug"}
<FINISH>

[kaustriaf5]

This should be fixed in 3.7. Operations that take more than 45 seconds are going to return an async task ID instead of framework timing out.