Subcloud-group delete request through CLI is throwing exception in DCmanager-api logs

Bug #1999901 reported by Karla Felix
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
StarlingX
Fix Released
Low
Karla Felix

Bug Description

Brief Description

subcloud-group delete request through CLI throws exception in dcmanager-api logs.

subcloud-group delete request through Rest is showing proper logs in dcmanager-api logs.

Severity

Standard

Steps to Reproduce

Automation:

Manual:

    Send a POST through CLI and verify log in dcmanager-api log

[sysadmin@controller-1 ~(keystone_admin)]$ dcmanager subcloud-group add --name pvtest
+------------------------+----------------------------+
| Field | Value |
+------------------------+----------------------------+
| id | 3 |
| name | pvtest |
| description | No description provided |
| update apply type | parallel |
| max parallel subclouds | 2 |
| created_at | 2022-12-07 15:26:17.456044 |
| updated_at | None |
+------------------------+----------------------------+
[sysadmin@controller-1 ~(keystone_admin)]$ dcmanager subcloud-group list
+----+---------+-------------------------+
| id | name | description |
+----+---------+-------------------------+
| 1 | Default | Default Subcloud Group |
| 3 | pvtest | No description provided |
+----+---------+-------------------------+

sysadmin@controller-1:~$ tail -f /var/log/dcmanager/dcmanager-api.log
2022-12-07 15:26:17.458 3015231 INFO dcmanager.common.context.auditor [req-a0243334-e51d-4289-831a-edc06d6a7e63 58a68a1f4b3b409e96b7bd497179c926 - - default default] Request id is not in request, setting it to an auto generated id.
2022-12-07 15:26:17.459 3015231 INFO dcmanager.common.context.auditor [req-c762ee77-0bfb-4b3d-ad27-bed61261817e 58a68a1f4b3b409e96b7bd497179c926 583e9d8122df43a7885cac46384fe26c - - -] fd01:305::2 "POST /v1.0/subcloud-groups/ HTTP/1.0" status: 200 len: 195 time: 0.00487518310546875 POST: {'name': 'pvtest', 'description': 'No description provided', 'update_apply_type': 'parallel', 'max_parallel_subclouds': 2} host:[fd01:305::2]:8119 agent:python-requests/2.25.1 user: admin tenant: admin domain: Default

2. Send a PATCH through CLI and verify log in dcmanager-api log

[sysadmin@controller-1 ~(keystone_admin)]$ dcmanager subcloud-group update pvtest --description pvtest
+------------------------+----------------------------+
| Field | Value |
+------------------------+----------------------------+
| id | 3 |
| name | pvtest |
| description | pvtest |
| update apply type | parallel |
| max parallel subclouds | 2 |
| created_at | 2022-12-07 15:26:17.456044 |
| updated_at | 2022-12-07 15:27:42.608832 |
+------------------------+----------------------------+
[sysadmin@controller-1 ~(keystone_admin)]$ dcmanager subcloud-group list
+----+---------+------------------------+
| id | name | description |
+----+---------+------------------------+
| 1 | Default | Default Subcloud Group |
| 3 | pvtest | pvtest |
+----+---------+------------------------+

sysadmin@controller-1:~$ tail -f /var/log/dcmanager/dcmanager-api.log
2022-12-07 15:27:42.610 3015232 INFO dcmanager.common.context.auditor [req-c5816bd5-3b87-4940-94cf-ad06b4a1aca8 58a68a1f4b3b409e96b7bd497179c926 - - default default] Request id is not in request, setting it to an auto generated id.
2022-12-07 15:27:42.610 3015232 INFO dcmanager.common.context.auditor [req-bd733413-56f5-4312-9546-c343dbb8c46e 58a68a1f4b3b409e96b7bd497179c926 583e9d8122df43a7885cac46384fe26c - - -] fd01:305::2 "PATCH /v1.0/subcloud-groups/pvtest HTTP/1.0" status: 200 len: 202 time: 0.009521722793579102 POST: {'description': 'pvtest'} host:[fd01:305::2]:8119 agent:python-requests/2.25.1 user: admin tenant: admin domain: Default

3. Send a DELETE through CLI and verify log in dcmanager-api log

[sysadmin@controller-1 ~(keystone_admin)]$ dcmanager subcloud-group delete pvtest
[sysadmin@controller-1 ~(keystone_admin)]$ dcmanager subcloud-group list
+----+---------+------------------------+
| id | name | description |
+----+---------+------------------------+
| 1 | Default | Default Subcloud Group |
+----+---------+------------------------+

sysadmin@controller-1:~$ tail -f /var/log/dcmanager/dcmanager-api.log
022-12-07 15:28:27.573 3015232 INFO dcmanager.common.context.auditor [req-b87e67cc-1de2-4664-8099-f9cfb6c6cca5 58a68a1f4b3b409e96b7bd497179c926 - - default default] Request id is not in request, setting it to an auto generated id.
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor [req-b87e67cc-1de2-4664-8099-f9cfb6c6cca5 58a68a1f4b3b409e96b7bd497179c926 - - default default] Exception in AuditLoggingHook on event 'after': simplejson.errors.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor Traceback (most recent call last):
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor File "/usr/lib/python3/dist-packages/dcmanager/common/context.py", line 255, in after
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor self.__after(state)
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor File "/usr/lib/python3/dist-packages/dcmanager/common/context.py", line 221, in __after
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor json_post_data(state))
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor File "/usr/lib/python3/dist-packages/dcmanager/common/context.py", line 214, in json_post_data
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor if not hasattr(rest_state.request, 'json'):
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor File "/usr/lib/python3/dist-packages/pecan/core.py", line 52, in __getattribute__
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor return WebObRequest.__getattribute__(self, name)
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor File "/usr/lib/python3/dist-packages/webob/request.py", line 715, in _json_body__get
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor return json.loads(self.body.decode(self.charset))
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor File "/usr/lib/python3/dist-packages/simplejson/__init__.py", line 525, in loads
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor return _default_decoder.decode(s)
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor File "/usr/lib/python3/dist-packages/simplejson/decoder.py", line 370, in decode
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor obj, end = self.raw_decode(s)
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor File "/usr/lib/python3/dist-packages/simplejson/decoder.py", line 400, in raw_decode
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor return self.scan_once(s, idx=_w(s, idx).end())
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor simplejson.errors.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

Expected Behavior

DELETE request should not throw exception in logs

Actual Behavior

[sysadmin@controller-1 ~(keystone_admin)]$ dcmanager subcloud-group delete pvtest
[sysadmin@controller-1 ~(keystone_admin)]$ dcmanager subcloud-group list
+----+---------+------------------------+
| id | name | description |
+----+---------+------------------------+
| 1 | Default | Default Subcloud Group |
+----+---------+------------------------+

sysadmin@controller-1:~$ tail -f /var/log/dcmanager/dcmanager-api.log
022-12-07 15:28:27.573 3015232 INFO dcmanager.common.context.auditor [req-b87e67cc-1de2-4664-8099-f9cfb6c6cca5 58a68a1f4b3b409e96b7bd497179c926 - - default default] Request id is not in request, setting it to an auto generated id.
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor [req-b87e67cc-1de2-4664-8099-f9cfb6c6cca5 58a68a1f4b3b409e96b7bd497179c926 - - default default] Exception in AuditLoggingHook on event 'after': simplejson.errors.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor Traceback (most recent call last):
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor File "/usr/lib/python3/dist-packages/dcmanager/common/context.py", line 255, in after
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor self.__after(state)
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor File "/usr/lib/python3/dist-packages/dcmanager/common/context.py", line 221, in __after
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor json_post_data(state))
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor File "/usr/lib/python3/dist-packages/dcmanager/common/context.py", line 214, in json_post_data
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor if not hasattr(rest_state.request, 'json'):
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor File "/usr/lib/python3/dist-packages/pecan/core.py", line 52, in __getattribute__
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor return WebObRequest.__getattribute__(self, name)
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor File "/usr/lib/python3/dist-packages/webob/request.py", line 715, in _json_body__get
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor return json.loads(self.body.decode(self.charset))
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor File "/usr/lib/python3/dist-packages/simplejson/__init__.py", line 525, in loads
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor return _default_decoder.decode(s)
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor File "/usr/lib/python3/dist-packages/simplejson/decoder.py", line 370, in decode
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor obj, end = self.raw_decode(s)
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor File "/usr/lib/python3/dist-packages/simplejson/decoder.py", line 400, in raw_decode
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor return self.scan_once(s, idx=_w(s, idx).end())
2022-12-07 15:28:27.573 3015232 ERROR dcmanager.common.context.auditor simplejson.errors.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

Reproducibility

Reproducible

System Configuration

DC lab WP_3_7

Load info (eg: 2022-03-10_20-00-07)

sysadmin@controller-1:~$ cat /etc/build.info
SW_VERSION="22.12"
BUILD_TARGET="Host Installer"
BUILD_TYPE="Formal"
BUILD_ID="2022-12-05_22-00-07"
BUILD_NUMBER="30"
BUILD_DATE="2022-12-06 03:00:07 +0000"
sysadmin@controller-1:~$ kubectl version
WARNING: This version information is deprecated and will be replaced with the output from kubectl version --short. Use --output=yaml|json to get the full version.
Client Version: version.Info{Major:"1", Minor:"24", GitVersion:"v1.24.4", GitCommit:"95ee5ab382d64cfe6c28967f36b53970b8374491", GitTreeState:"archive", BuildDate:"2022-12-06T03:51:11Z", GoVersion:"go1.18.5", Compiler:"gc", Platform:"linux/amd64"}
Kustomize Version: v4.5.4
Server Version: version.Info{Major:"1", Minor:"24", GitVersion:"v1.24.4", GitCommit:"95ee5ab382d64cfe6c28967f36b53970b8374491", GitTreeState:"clean", BuildDate:"2022-08-17T18:47:37Z", GoVersion:"go1.18.5", Compiler:"gc", Platform:"linux/amd64"}
sysadmin@controller-1:~$

Last Pass

New testcase

Timestamp/Logs

Alarms

NA

Test Activity

Regression Testing

Workaround

NA

Changed in starlingx:
status: New → In Progress
Karla Felix (kkarolin)
Changed in starlingx:
assignee: nobody → Karla Felix (kkarolin)
Ghada Khalil (gkhalil)
Changed in starlingx:
importance: Undecided → Low
tags: added: stx.8.0 stx.distcloud
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to distcloud (master)

Reviewed: https://review.opendev.org/c/starlingx/distcloud/+/867777
Committed: https://opendev.org/starlingx/distcloud/commit/b056a514c8cb4f63ea30c90dd50abe18ff19edfd
Submitter: "Zuul (22348)"
Branch: master

commit b056a514c8cb4f63ea30c90dd50abe18ff19edfd
Author: Karla Felix <email address hidden>
Date: Thu Dec 15 07:30:47 2022 -0300

    Ignore JSON decode error in request log.

    For DELETE requests with no request body or "Content-Length" field, the
    expected return value for "hasattr(rest_state.request, 'json')" would be
    False and for "rest_state.request.json" would be an empty string.
    Instead, what occurs is that both "hasattr(rest_state.request, 'json')"
    and "rest_state.request.json" are throwing JSON decode exceptions in
    this case. This change adds tolerance for this exception. This is done
    because it is not known all the possible request conditions that may
    cause this exception to be thrown.

    Test Plan:

    PASS: Send a delete request through the CLI to subcloud-group and
           verify if any exception shows up dcmanager-api logs.

    Closes-Bug: 1999901
    Change-Id: I58af3f4711d6caf840e188fb4690f2bde219d79a
    Signed-off-by: Karla Felix <email address hidden>

Changed in starlingx:
status: In Progress → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.