Bug 1583587

Summary:	ASB logs error about could not find instance when deprovision
Product:	OpenShift Container Platform	Reporter:	Zihan Tang <zitang>
Component:	Service Broker	Assignee:	Jesus M. Rodriguez <jesusr>
Status:	CLOSED ERRATA	QA Contact:	Zihan Tang <zitang>
Severity:	medium	Docs Contact:
Priority:	medium
Version:	3.10.0	CC:	aos-bugs, jmatthew, wsun
Target Milestone:	---
Target Release:	3.11.0
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
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.	Story Points:	---
Clone Of:		Environment:
Last Closed:	2018-10-11 07:20:02 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

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