Bug 1581580 - [upgrade] ASB unable to migrate all extracted credentials
Summary: [upgrade] ASB unable to migrate all extracted credentials
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Service Broker
Version: 3.10.0
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: ---
: 3.10.0
Assignee: Jason Montleon
QA Contact: Zihan Tang
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-05-23 06:52 UTC by Zihan Tang
Modified: 2018-07-30 19:16 UTC (History)
8 users (show)

Fixed In Version:
Doc Type: No Doc Update
Doc Text:
undefined
Clone Of:
Environment:
Last Closed: 2018-07-30 19:16:18 UTC
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2018:1816 None None None 2018-07-30 19:16:38 UTC

Description Zihan Tang 2018-05-23 06:52:09 UTC
Description of problem:
when upgrade v3.9 to v3.10.
Task 'Migrate from etcd to CustomResources' failed at ' unable to migrate all extracted credentials' 

Version-Release number of selected component (if applicable):
openshift-ansible-3.10.0-0.50.0

How reproducible:
always

Steps to Reproduce:
1. install OCP v3.9 , 
2. provision postgresql(with binding) +mediawiki in project1, provision postgresql+2binding in project2.
3. upgrade to v3.10

Actual results:
upgrade failed.
Play:     Upgrade Service Catalog
     Task:     Fail out because the ASB etcd to CRD migration was unsuccessful
     Message:  The migration from etcd to CustomResourceDefinitions was not successful, aborting upgrade of the ansible service broker.

asb pod:
# oc get pod 
NAME                       READY     STATUS              RESTARTS   AGE
asb-1-gsqph                1/1       Running             0          37m
asb-etcd-1-ftmqm           1/1       Running             0          1m
asb-etcd-1-rftmr           0/1       Evicted             0          3h

asb-etcd-migration-2245v   0/1       Error     0          26m
.......
it generate a lot of asb-etcd-migration** pod even after the upgrade job completed
[root@qe-zitang-39up-master-etcd-1 ~]# oc get pod  | wc -l
355
[root@qe-zitang-39up-master-etcd-1 ~]# oc get pod  | wc -l
368

# oc log -f asb-1-gsqph
log is DEPRECATED and will be removed in a future version. Use logs instead.
Using config file mounted to /etc/ansible-service-broker/config.yaml
============================================================
==           Starting Ansible Service Broker...           ==
============================================================
2018/05/23 06:03:34 Unable to get log.logfile from config
[2018-05-23T06:03:34.362Z] [NOTICE] - Initializing clients...
[2018-05-23T06:03:34.363Z] [INFO] - == ETCD CX ==
[2018-05-23T06:03:34.363Z] [INFO] - EtcdHost: asb-etcd.openshift-ansible-service-broker.svc
[2018-05-23T06:03:34.363Z] [INFO] - EtcdPort: 2379
[2018-05-23T06:03:34.363Z] [INFO] - Endpoints: [https://asb-etcd.openshift-ansible-service-broker.svc:2379]
[2018-05-23T06:03:34.38Z] [INFO] - Etcd Version [Server: 3.2.18, Cluster: 3.2.0]
[2018-05-23T06:03:34.392Z] [INFO] - OpenShift version: v3.10.0-0.50.0
[2018-05-23T06:03:34.397Z] [INFO] - Kubernetes version: v1.10.0+b81c8f8
[2018-05-23T06:03:34.397Z] [INFO] - == REGISTRY CX == 
[2018-05-23T06:03:34.397Z] [INFO] - Name: rh
[2018-05-23T06:03:34.397Z] [INFO] - Type: rhcc
[2018-05-23T06:03:34.397Z] [INFO] - Url: https://registry.access.redhat.com
[2018-05-23T06:03:34.397Z] [INFO] - == REGISTRY CX == 
[2018-05-23T06:03:34.398Z] [INFO] - Name: localregistry
[2018-05-23T06:03:34.398Z] [INFO] - Type: local_openshift
[2018-05-23T06:03:34.398Z] [INFO] - Url: 
[2018-05-23T06:03:34.398Z] [INFO] - Initiating Recovery Process
[2018-05-23T06:03:34.398Z] [INFO] - Listening for provision messages
[2018-05-23T06:03:34.398Z] [INFO] - Listening for deprovision messages
[2018-05-23T06:03:34.398Z] [INFO] - Listening for binding messages
[2018-05-23T06:03:34.398Z] [INFO] - Listening for update messages
[2018-05-23T06:03:34.398Z] [INFO] - Listening for binding messages
[2018-05-23T06:03:34.4Z] [INFO] - Recovery complete
[2018-05-23T06:03:34.4Z] [NOTICE] - recover called
[2018-05-23T06:03:34.4Z] [INFO] - Broker configured to bootstrap on startup
[2018-05-23T06:03:34.4Z] [INFO] - Attempting bootstrap...
[2018-05-23T06:03:34.4Z] [INFO] - AnsibleBroker::Bootstrap
[2018-05-23T06:03:36.196Z] [INFO] - Validating specs...
[2018-05-23T06:03:36.196Z] [NOTICE] - All specs passed validation!
[2018-05-23T06:03:36.516Z] [INFO] - Validating specs...
[2018-05-23T06:03:36.517Z] [NOTICE] - All specs passed validation!
[2018-05-23T06:03:36.532Z] [NOTICE] - Broker successfully bootstrapped on startup
[2018-05-23T06:03:37.199Z] [NOTICE] - Listening on https://[::]:1338
[2018-05-23T06:03:37.199Z] [NOTICE] - Ansible Service Broker Starting
[2018-05-23T06:04:52.223Z] [INFO] - AnsibleBroker::Catalog
10.128.0.1 - - [23/May/2018:06:04:52 +0000] "GET /ansible-service-broker/v2/catalog HTTP/1.1" 200 31690
[2018-05-23T06:04:53.247Z] [INFO] - AnsibleBroker::Catalog
10.128.0.1 - - [23/May/2018:06:04:53 +0000] "GET /ansible-service-broker/v2/catalog HTTP/1.1" 200 31690
[2018-05-23T06:13:36.532Z] [INFO] - Broker configured to refresh specs every 10m0s seconds
[2018-05-23T06:13:36.532Z] [INFO] - Attempting bootstrap at 2018-05-23 06:13:36.532536283 +0000 UTC
[2018-05-23T06:13:36.532Z] [INFO] - AnsibleBroker::Bootstrap
[2018-05-23T06:13:38.393Z] [INFO] - Validating specs...
[2018-05-23T06:13:38.393Z] [NOTICE] - All specs passed validation!
[2018-05-23T06:13:38.693Z] [INFO] - Validating specs...
[2018-05-23T06:13:38.693Z] [NOTICE] - All specs passed validation!
[2018-05-23T06:13:38.708Z] [NOTICE] - Broker successfully bootstrapped
[2018-05-23T06:20:10.465Z] [INFO] - AnsibleBroker::Catalog
10.128.0.1 - - [23/May/2018:06:20:10 +0000] "GET /ansible-service-broker/v2/catalog HTTP/1.1" 200 31690
[2018-05-23T06:23:36.532Z] [INFO] - Broker configured to refresh specs every 10m0s seconds
[2018-05-23T06:23:36.532Z] [INFO] - Attempting bootstrap at 2018-05-23 06:23:36.532607646 +0000 UTC
[2018-05-23T06:23:36.532Z] [INFO] - AnsibleBroker::Bootstrap
[2018-05-23T06:23:38.143Z] [INFO] - Validating specs...
[2018-05-23T06:23:38.143Z] [NOTICE] - All specs passed validation!
[2018-05-23T06:23:38.442Z] [INFO] - Validating specs...
[2018-05-23T06:23:38.442Z] [NOTICE] - All specs passed validation!
[2018-05-23T06:23:38.456Z] [NOTICE] - Broker successfully bootstrapped


The pod log of migration:
# oc logs -f asb-etcd-migration-gqb7f 
time="2018-05-23T06:05:03Z" level=info msg="etcd configuration: {asb-etcd.openshift-ansible-service-broker.svc /var/run/secrets/kubernetes.io/serviceaccount/service-ca.crt /var/run/asb-etcd-auth/client.crt /var/run/asb-etcd-auth/client.key 2379}"
time="2018-05-23T06:05:03Z" level=info msg="== ETCD CX =="
time="2018-05-23T06:05:03Z" level=info msg="EtcdHost: asb-etcd.openshift-ansible-service-broker.svc"
time="2018-05-23T06:05:03Z" level=info msg="EtcdPort: 2379"
time="2018-05-23T06:05:03Z" level=info msg="Endpoints: [https://asb-etcd.openshift-ansible-service-broker.svc:2379]"
2018/05/23 06:05:03 Dao::BatchGetRaw
2018/05/23 06:05:03 Successfully loaded [ 4 ] objects from etcd dir [ /spec ]
2018/05/23 06:05:03 Batch idx [ 0 ] -> [ 73ead67495322cc462794387fa9884f5 ]
2018/05/23 06:05:03 Batch idx [ 1 ] -> [ 2c259ddd8059b9bc65081e07bf20058f ]
2018/05/23 06:05:03 Batch idx [ 2 ] -> [ 03b69500305d9859bb9440d9f9023784 ]
2018/05/23 06:05:03 Batch idx [ 3 ] -> [ d5915e05b253df421efe6e41fb6a66ba ]
2018/05/23 06:05:03 set spec: 73ead67495322cc462794387fa9884f5
2018/05/23 06:05:03 set spec: 2c259ddd8059b9bc65081e07bf20058f
2018/05/23 06:05:03 set spec: 03b69500305d9859bb9440d9f9023784
2018/05/23 06:05:03 set spec: d5915e05b253df421efe6e41fb6a66ba
2018/05/23 06:05:03 Dao::BatchGetRaw
2018/05/23 06:05:03 Successfully loaded [ 3 ] objects from etcd dir [ /service_instance ]
2018/05/23 06:05:03 set service instance: 2e782145-398a-412e-8f36-c4ebd3d0d169
2018/05/23 06:05:03 set service instance: c63bbb58-2807-464d-bebb-e7a1053923e4
2018/05/23 06:05:03 set service instance: bdbda3b5-7fde-40cc-9d5c-8f09d10f4d03
2018/05/23 06:05:03 Dao::BatchGetRaw
2018/05/23 06:05:03 Successfully loaded [ 3 ] objects from etcd dir [ /bind_instance ]
2018/05/23 06:05:03 set binding instance: 2f3a9503-2230-4447-8911-f09f0985c142
2018/05/23 06:05:03 set binding instance: a6805d95-f41d-4378-895a-ebe337477b0a
2018/05/23 06:05:03 set binding instance: 03f07398-c313-4cda-925c-aaf32bae9a7f
2018/05/23 06:05:04 Dao::BatchGetRaw
2018/05/23 06:05:04 Successfully loaded [ 1 ] objects from etcd dir [ /state/2e782145-398a-412e-8f36-c4ebd3d0d169/job ]
2018/05/23 06:05:04 set job state for instance: 2e782145-398a-412e-8f36-c4ebd3d0d169 token: e850dfc2-d763-4c3d-a87e-f3ad2146133e
2018/05/23 06:05:04 Dao::BatchGetRaw
2018/05/23 06:05:04 Successfully loaded [ 1 ] objects from etcd dir [ /state/c63bbb58-2807-464d-bebb-e7a1053923e4/job ]
2018/05/23 06:05:04 set job state for instance: c63bbb58-2807-464d-bebb-e7a1053923e4 token: 835aeaf2-2cf2-40a7-bc70-f60c9063e9bc
2018/05/23 06:05:04 Dao::BatchGetRaw
2018/05/23 06:05:04 Successfully loaded [ 1 ] objects from etcd dir [ /state/bdbda3b5-7fde-40cc-9d5c-8f09d10f4d03/job ]
2018/05/23 06:05:04 set job state for instance: bdbda3b5-7fde-40cc-9d5c-8f09d10f4d03 token: 4a2e7581-bfcf-4994-b69c-9776cc22b3d7
2018/05/23 06:05:05 Dao::DeleteBindInstance -> [ 2f3a9503-2230-4447-8911-f09f0985c142 ]
2018/05/23 06:05:05 Dao::DeleteBindInstance -> [ a6805d95-f41d-4378-895a-ebe337477b0a ]
2018/05/23 06:05:05 Dao::DeleteBindInstance -> [ 03f07398-c313-4cda-925c-aaf32bae9a7f ]
time="2018-05-23T06:05:05Z" level=info msg="reverted saved binding instances"
2018/05/23 06:05:05 Dao::DeleteServiceInstance -> [ 2e782145-398a-412e-8f36-c4ebd3d0d169 ]
2018/05/23 06:05:06 Dao::DeleteServiceInstance -> [ c63bbb58-2807-464d-bebb-e7a1053923e4 ]
2018/05/23 06:05:06 Dao::DeleteServiceInstance -> [ bdbda3b5-7fde-40cc-9d5c-8f09d10f4d03 ]
time="2018-05-23T06:05:06Z" level=info msg="reverted service instances"
2018/05/23 06:05:06 Dao::DeleteSpec-> [ 73ead67495322cc462794387fa9884f5 ]
2018/05/23 06:05:06 Dao::DeleteSpec-> [ 2c259ddd8059b9bc65081e07bf20058f ]
2018/05/23 06:05:06 Dao::DeleteSpec-> [ 03b69500305d9859bb9440d9f9023784 ]
2018/05/23 06:05:07 Dao::DeleteSpec-> [ d5915e05b253df421efe6e41fb6a66ba ]
time="2018-05-23T06:05:07Z" level=info msg="reverted saved specs - exiting now - migration failed"
panic: Unable to migrate all extracted credentials - 100: Key not found (/extracted_credentials/2f3a9503-2230-4447-8911-f09f0985c142) [270]

goroutine 1 [running]:
main.main()
	/builddir/build/BUILD/ansible-service-broker-1.2.12/cmd/migration/main.go:247 +0x2e42

data in etcd:
#eta ls /extracted_credentials
/extracted_credentials/c63bbb58-2807-464d-bebb-e7a1053923e4
/extracted_credentials/bdbda3b5-7fde-40cc-9d5c-8f09d10f4d03
/extracted_credentials/2e782145-398a-412e-8f36-c4ebd3d0d169


Expected results:
upgrage succeed.

Additional info:

Comment 1 Zihan Tang 2018-05-23 06:54:10 UTC
ASB haven't upgrade succeed still now, so add TestBlocker tag

Comment 2 Zhang Cheng 2018-05-23 07:33:13 UTC
This bug is blocking all upgrade testing in asb side.

Comment 6 Zihan Tang 2018-05-28 09:55:18 UTC
verified 
asb version: 1.2.14
openshift-ansible-3.10.0-0.53.0

Comment 8 errata-xmlrpc 2018-07-30 19:16:18 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:1816


Note You need to log in before you can comment on or make changes to this bug.