Bug 1583587 - ASB logs error about could not find instance when deprovision
Summary: ASB logs error about could not find instance when deprovision
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Service Broker
Version: 3.10.0
Hardware: Unspecified
OS: Unspecified
medium
medium
Target Milestone: ---
: 3.11.0
Assignee: Jesus M. Rodriguez
QA Contact: Zihan Tang
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-05-29 10:10 UTC by Zihan Tang
Modified: 2018-10-11 07:20 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Cause: erroneously logging an error message when an item is not found even though it is normal not to be found. Consequence: successful jobs might have an error message logged giving the user concern that there might be a problem when there was none. Fix: changed the logging level from error to debug for the message. it is still a useful message for debugging purposes, but not useful for a production installation which usually has the level set to info or higher. Result: the users will not see an error message when the instance is not found unless there was really a problem.
Clone Of:
Environment:
Last Closed: 2018-10-11 07:20:02 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Bugzilla 1577144 0 medium CLOSED ASB logs error about problem reading job state when deprovision 2021-02-22 00:41:40 UTC
Red Hat Product Errata RHBA-2018:2652 0 None None None 2018-10-11 07:20:30 UTC

Internal Links: 1577144

Description Zihan Tang 2018-05-29 10:10:28 UTC 
Description of problem:
When deprovision ,ASB logs error : 
[2018-05-22T05:55:56.41Z] [ERROR] - Could not find instance 16a03b07-5d71-11e8-8814-0a580a800004 associated with job state 23a48153-246d-4772-884a-d903f8a3fd88 - bundleinstances.automationbroker.io "16a03b07-5d71-11e8-8814-0a580a800004" not found


Version-Release number of selected component (if applicable):
1.2.14

How reproducible:
always
Steps to Reproduce:
1. provision a apb like postgresql 
2. deprovision the serviceinstance ,check the asb  log 

Actual results:
deprovision succeed. but asb logs error:
[2018-05-22T05:55:56.41Z] [ERROR] - Could not find instance 16a03b07-5d71-11e8-8814-0a580a800004 associated with job state 23a48153-246d-4772-884a-d903f8a3fd88 - bundleinstances.automationbroker.io "16a03b07-5d71-11e8-8814-0a580a800004" not found
[2018-05-22T05:55:56.41Z] [WARNING] - unable to find job state: [16a03b07-5d71-11e8-8814-0a580a800004]. error: [bundleinstances.automationbroker.io "16a03b07-5d71-11e8-8814-0a580a800004" not found]

Expected results:
no errors when deprovision 
It's a normal deprovision action and deprovision succeed actually. It's not good to log as ERROR in asb log.

Additional info:
copy from bug https://bugzilla.redhat.com/show_bug.cgi?id=1577144#c6
to trace .
Comment 1 Jesus M. Rodriguez 2018-08-03 22:16:56 UTC 
Before we would log an error during deprovision that we could not find the job state that was deleted during the deprovision.

---
time="2018-08-03T03:24:21Z" level=debug msg="service_id: 1dda1477cace09730bd8ed7a6505607e"
time="2018-08-03T03:24:21Z" level=debug msg="plan_id: 7f4a5e35e4af2beb70076e72fab0b7ff"
time="2018-08-03T03:24:21Z" level=debug msg="operation:  7084f8d1-7937-4f54-89cc-37822632bc5e"
time="2018-08-03T03:24:21Z" level=error msg="Could not find instance 54b7b619-96cc-11e8-9244-0242ac11000a associated with job state 7084f8d1-7937-4f54-89cc-37822632bc5e - bundleinstances.automationbroker.io \"54b7b619-96cc-11e8-9244-0242ac11000a\" not found"
time="2018-08-03T03:24:21Z" level=warning msg="unable to find job state: [54b7b619-96cc-11e8-9244-0242ac11000a]. error: [bundleinstances.automationbroker.io \"54b7b619-96cc-11e8-9244-0242ac11000a\" not found]"
172.17.0.7 - - [03/Aug/2018:03:24:21 +0000] "GET /automation-broker/v2/service_instances/54b7b619-96cc-11e8-9244-0242ac11000a/last_operation?operation=7084f8d1-7937-4f54-89cc-37822632bc5e&plan_id=7f4a5e35e4af2beb70076e72fab0b7ff&service_id=1dda1477cace09730bd8ed7a6505607e HTTP/1.1" 410 37
---

We still log it but now as debug since the information is useful for developers and potentially troubleshooters. But it won't show up on a normal installation of the broker operating normally.

---
time="2018-08-03T22:11:01Z" level=debug msg="service_id: 1dda1477cace09730bd8ed7a6505607e"
time="2018-08-03T22:11:01Z" level=debug msg="plan_id: 7f4a5e35e4af2beb70076e72fab0b7ff"
time="2018-08-03T22:11:01Z" level=debug msg="operation:  f2a632b2-c6e7-4e43-b838-79a38cd56592"
time="2018-08-03T22:11:01Z" level=debug msg="Could not find instance e7b0b163-9769-11e8-8283-0242ac110006 associated with job state f2a632b2-c6e7-4e43-b838-79a38cd56592 - bundleinstances.automationbroker.io \"e7b0b163-9769-11e8-8283-0242ac110006\" not found"
time="2018-08-03T22:11:01Z" level=warning msg="unable to find job state: [e7b0b163-9769-11e8-8283-0242ac110006]. error: [bundleinstances.automationbroker.io \"e7b0b163-9769-11e8-8283-0242ac110006\" not found]"
172.17.0.9 - - [03/Aug/2018:22:11:01 +0000] "GET /automation-broker/v2/service_instances/e7b0b163-9769-11e8-8283-0242ac110006/last_operation?operation=f2a632b2-c6e7-4e43-b838-79a38cd56592&plan_id=7f4a5e35e4af2beb70076e72fab0b7ff&service_id=1dda1477cace09730bd8ed7a6505607e HTTP/1.1" 410 37
---
Comment 2 Jesus M. Rodriguez 2018-08-03 22:17:12 UTC 
Fixed in PR https://github.com/openshift/ansible-service-broker/pull/1030
Comment 4 Zihan Tang 2018-08-09 07:19:56 UTC 
verified.
ASB: 1.3.7
Comment 6 errata-xmlrpc 2018-10-11 07:20:02 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2018:2652
Note You need to log in before you can comment on or make changes to this bug.