[OPENAM-17276] AM recorder does not record anymore Created: 12/Jan/21  Updated: 29/Apr/21  Resolved: 21/Feb/21

Status: Closed
Project: OpenAM
Component/s: debug logging
Affects Version/s: 7.0.0, 7.0.1
Fix Version/s: 7.1.0, 7.0.2

Type: Bug Priority: Major
Reporter: C-Weng C Assignee: C-Weng C
Resolution: Fixed Votes: 0
Labels: EDISON
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Rank: 1|i03acv:
Sprint: AM Sustaining Sprint 82, AM Sustaining Sprint 83
Story Points: 1
Needs backport:
No
Support Ticket IDs:
Verified Version/s:
Needs QA verification:
Yes
Functional tests:
No
Are the reproduction steps defined?:
Yes and I used the same an in the description

 Description   

Bug description

Doing AM recording sometimes unable to record as the status in recording set to true but no active recording exists

How to reproduce the issue

Get a AMADMIN TOKEN and also set the SERVER host.
Do a recording.

curl -s -k \
  -X POST \
  -H "iPlanetDirectoryPro: $TOKEN" \
  -H "X-Requested-With: curl" \
  -H "Content-Type: application/json" -d ' {
  "issueID": 99999,
  "referenceID": "configdump",
  "description": "Troubleshooting config",
  "zipEnable": true,
  "configExport": {
   "enable": true,
   "password": "123456789012",
   "sharePassword": false
  },
  "debugLogs": {
   "debugLevel": "MESSAGE",
   "autoStop": {
    "time":  {
     "timeUnit": "MINUTES",
     "value": 5
    },
    "fileSize": {
     "sizeUnit": "GB",
     "value": 1
    }
   }
  },
  "threadDump" : {
   "enable": true,
   "delay" :  {
    "timeUnit": "SECONDS",
    "value": 5
   }
  }
 }' \
 "$SERVER/openam/json/records?_action=start"

##### Testing

curl 'http://am.lvh.me:8080/openam/json/global-config/realms/Lw' \
  -X 'PUT' \
  -H 'Connection: keep-alive' \
  -H 'Pragma: no-cache' \
  -H 'Cache-Control: no-cache' \
  -H 'accept-api-version: protocol=2.0,resource=1.0' \
  -H 'accept: application/json' \
  -H 'x-requested-with: ForgeRock CREST.js' \
  -H 'User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.141 Safari/537.36' \
  -H 'content-type: application/json' \
  -H 'Origin: http://am.lvh.me:8080' \
  -H 'Referer: http://am.lvh.me:8080/openam/ui-admin/' \
  -H 'Accept-Language: en-GB,en-US;q=0.9,en;q=0.8' \
  -H "iPlanetDirectoryPro: $TOKEN" \
  --data-binary '{"name":"/","active":true,"parentPath":"","aliases":["openam","am.lvh.me","localhost"]}' \
  --compressed \
  --insecure

sleep 5

curl -s -k \
   -X POST \
   -H "iPlanetDirectoryPro: $TOKEN" \
   -H "X-Requested-With: curl" \
   -H "Content-Type: application/json" \
   "$SERVER/openam/json/records?_action=stop"

2. If you check the status

curl -s -k \
   -X POST \
   -H "iPlanetDirectoryPro: $TOKEN" \
   -H "X-Requested-With: curl" \
   -H "Content-Type: application/json" \
   "$SERVER/openam/json/records?_action=status"
echo

and if it is like this

{"recording":true,"record":{"issueID":99999,"referenceID":"configdump","description":"Troubleshooting config","zipEnable":true,"threadDump":{"enable":true,"delay":{"timeUnit":"SECONDS","value":5}},"configExport":{"enable":true,"password":"xxxxxx","sharePassword":false},"debugLogs":{"debugLevel":"message","autoStop":{"time":{"timeUnit":"MILLISECONDS","value":300000},"fileSize":{"sizeUnit":"KB","value":1048576}}},"status":"STOPPED","folder":"/home/am/var/debug/record/99999/configdump/"}}

where the recording state is true but the current record session is stopped.

3. Running the record session will not change things as this record session is not removed

4. I know that this may not be consistently reproduced but this had been seen by multiple instance and different tester (environment).

Expected behaviour
Future recording can be done
Current behaviour
Recording not longer works

Detection of the issue

Checking the recording status will show a stopped but stale AM recording session that is active

curl -s -k \
   -X POST \
   -H "iPlanetDirectoryPro: $TOKEN" \
   -H "X-Requested-With: curl" \
   -H "Content-Type: application/json" \
   "$SERVER/openam/json/records?_action=status"
echo

like

{"recording":true,"record":{"issueID":99999,"referenceID":"configdump","description":"Troubleshooting config","zipEnable":true,"threadDump":{"enable":true,"delay":{"timeUnit":"SECONDS","value":5}},"configExport":{"enable":true,"password":"xxxxxx","sharePassword":false},"debugLogs":{"debugLevel":"message","autoStop":{"time":{"timeUnit":"MILLISECONDS","value":300000},"fileSize":{"sizeUnit":"KB","value":1048576}}},"status":"STOPPED","folder":"/home/am/var/debug/record/99999/configdump/"}}

Work around

AM Recording will not work until AM is restarted. So that means to get logs one may need to manually enable message debug and all those data collection.

Code analysis

When having the ability to consistently replicate this and so it seems that the issues is that when doing a stopRecording the piece of code

        //Set back the debug levels and appenders
        LoggerContext context = (LoggerContext) LoggerFactory.getILoggerFactory();
        for (Logger logger : context.getLoggerList()) {
            Level previousLevel = previousDebugLevel.get(logger.getName());
            logger.setLevel(previousLevel);
            logger.detachAndStopAllAppenders();
             previousAppenders.get(logger.getName()).forEach(logger::addAppender);
       }

throws a NullPointerExcdeption on the previousAppenders.get(LoggerName)
return NULL. The problem is that the issue is not detectable w/o debugger



 Comments   
Comment by Ľubomír Mlích [ 29/Apr/21 ]

I was able to consistently reproduce issue this way in 7.0.1:

  1. install AM
  2. start recording
  3. start recording again with same command
  4. create new realm gb
  5. stop recording

recording did not stop, there was HTTP 500 error instead of expected JSON with information about my request answer. I was not able to do this in 7.0.2-M6, there is always response and starting and stopping recorder always worked.

Command used for step 4 (maybe setting same alias twice is breaking it):

curl "${URL}/json/global-config/realms/gb"   -X 'PUT'   -H 'Connection: keep-alive'   -H 'Pragma: no-cache'   -H 'Cache-Control: no-cache'   -H 'accept-api-version: protocol=2.0,resource=1.0'   -H 'accept: application/json'   -H 'content-type: application/json'   -H "iPlanetDirectoryPro: $ADMINTOKEN"   --data-binary '{"name":"gb","active":true,"parentPath":"/","aliases":["gb","gb"]}' |jq
Comment by Ľubomír Mlích [ 29/Apr/21 ]

probably no more verification, closing

Generated at Sun May 09 08:47:04 UTC 2021 using Jira 8.16.0#816000-sha1:a455b91378454416b49bbc88d03e653cb9815ed5.