Running cafe test test_update_secret_with_high_range_unicode_character, getting http 400 error
----------------------------------------------------------------------
Traceback (most recent call last):
File "/Users/step6927/CloudCafe/cloudroast/cloudroast/cloudkeep/barbican/functional/secrets.py", line 890, in test_update_secret_with_high_range_unicode_character
self.assertEqual(payload_resp.status_code, 204)
AssertionError: 400 != 204
Barbican server log shows SecretContentEncodingMustBeBase64: Encoding type must be 'base64' for text-based payloads
This test was successful before the plugin refactor.
Server logs for this transaction:
2014-07-08 22:07:24.482 47555 DEBUG keystoneclient.middleware.auth_token [-] Authenticating user token __call__ /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/keystoneclient/middleware/auth_token.py:666
2014-07-08 22:07:24.483 47555 DEBUG keystoneclient.middleware.auth_token [-] Removing headers from request environment: X-Identity-Status,X-Domain-Id,X-Domain-Name,X-Project-Id,X-Project-Name,X-Project-Domain-Id,X-Project-Domain-Name,X-User-Id,X-User-Name,X-User-Domain-Id,X-User-Domain-Name,X-Roles,X-Service-Catalog,X-User,X-Tenant-Id,X-Tenant-Name,X-Tenant,X-Role _remove_auth_headers /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/keystoneclient/middleware/auth_token.py:725
2014-07-08 22:07:25.093 47555 DEBUG keystoneclient.middleware.auth_token [-] Storing token in cache _cache_put /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/keystoneclient/middleware/auth_token.py:1234
2014-07-08 22:07:25.095 47555 DEBUG keystoneclient.middleware.auth_token [-] Received request from user: 151a2022365643179d6b5c9cbb148925 with project_id : 788c9ea4a057403ba3f334f4de0f9a9f and roles: _member_,admin _build_user_headers /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/keystoneclient/middleware/auth_token.py:1021
2014-07-08 22:07:25.099 47555 DEBUG barbican.api.middleware.context [-] ==== Inserted barbican auth request context: {'user_id': u'151a2022365643179d6b5c9cbb148925', 'user': u'151a2022365643179d6b5c9cbb148925', 'roles': [u'_member_', u'admin'], 'request_id': 'f49342b2-ee22-4688-a120-82af4d80e341', 'tenant_id': u'788c9ea4a057403ba3f334f4de0f9a9f', 'auth_token': 'MIIFPAYJKoZIhvcNAQcCoIIFLTCCBSkCAQExCTAHBgUrDgMCGjCCBBUGCSqGSIb3DQEHAaCCBAYEggQCeyJhY2Nlc3MiOiB7InRva2VuIjogeyJpc3N1ZWRfYXQiOiAiMjAxNC0wNy0wOVQwMzoxNTowMC43Njg2MjEiLCAiZXhwaXJlcyI6ICIyMDE0LTA3LTEwVDAzOjE0OjU5WiIsICJpZCI6ICJwbGFjZWhvbGRlciIsICJ0ZW5hbnQiOiB7ImRlc2NyaXB0aW9uIjogIkRlZmF1bHQgVGVuYW50IiwgImVuYWJsZWQiOiB0cnVlLCAiaWQiOiAiNzg4YzllYTRhMDU3NDAzYmEzZjMzNGY0ZGUwZjlhOWYiLCAibmFtZSI6ICJkZW1vIn19LCAic2VydmljZUNhdGFsb2ciOiBbeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vbG9jYWxob3N0OjgwMDEiLCAicmVnaW9uIjogInJlZ2lvbk9uZSIsICJwdWJsaWNVUkwiOiAiaHR0cDovL2xvY2FsaG9zdDo4MDAwIiwgImlkIjogImY5ZTg3N2E4MDQ5MzQ0YzViODc1OWVlMWQ1OWM2MDBhIn1dLCAiZW5kcG9pbnRzX2xpbmtzIjogW10sICJ0eXBlIjogInZvbHVtZSIsICJuYW1lIjogInN3aWZ0X3Byb3h5In0sIHsiZW5kcG9pbnRzIjogW3siYWRtaW5VUkwiOiAiaHR0cDovL2lhZC1pbnQtYXBpLmNsb3Vka2VlcC5pbzo5MzEyL3YxIiwgInJlZ2lvbiI6ICJyZWdpb25PbmUiLCAicHVibGljVVJMIjogImh0dHA6Ly9pYWQtaW50LWFwaS5jbG91ZGtlZXAuaW86OTMxMS92MSIsICJpZCI6ICJmZjU5OGQ5NTk5NGU0MTA4YTc0ZWZiNjg3NTY3MmZiNCJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJrZXlzdG9yZSIsICJuYW1lIjogImJhcmJpY2FuIn1dLCAidXNlciI6IHsidXNlcm5hbWUiOiAiYWRtaW5fdXNlciIsICJyb2xlc19saW5rcyI6IFtdLCAiaWQiOiAiMTUxYTIwMjIzNjU2NDMxNzlkNmI1YzljYmIxNDg5MjUiLCAicm9sZXMiOiBbeyJuYW1lIjogIl9tZW1iZXJfIn0sIHsibmFtZSI6ICJhZG1pbiJ9XSwgIm5hbWUiOiAiYWRtaW5fdXNlciJ9LCAibWV0YWRhdGEiOiB7ImlzX2FkbWluIjogMCwgInJvbGVzIjogWyI5ZmUyZmY5ZWU0Mzg0YjE4OTRhOTA4NzhkM2U5MmJhYiIsICJkZjFkODMzNjdjZDk0OGE1YjVkOTM1NjdmMjQ3M2IzMCJdfX19MYH-MIH8AgEBMFwwVzELMAkGA1UEBhMCVVMxDjAMBgNVBAgTBVVuc2V0MQ4wDAYDVQQHEwVVbnNldDEOMAwGA1UEChMFVW5zZXQxGDAWBgNVBAMTD3d3dy5leGFtcGxlLmNvbQIBATAHBgUrDgMCGjANBgkqhkiG9w0BAQEFAASBgF5H3rx1pxPIrzJ6EqxMu0seM6eP5RaCM33A3HqraQshruAnfjUga6A4dfncNwg5gDs3k9XdbZFtdAbMlWxTNzXgncvu3-Ymz-x7Uqbzly1L3x6AsyhgXiQDjcQ44lSUOPcja362lLuYY9Zhcl741XkMANodsRHOZ8q9AdMG8y4l', 'project_id': u'788c9ea4a057403ba3f334f4de0f9a9f', 'service_catalog': [{u'endpoints': [{u'adminURL': u'http://localhost:8001', u'region': u'regionOne', u'id': u'f9e877a8049344c5b8759ee1d59c600a', u'publicURL': u'http://localhost:8000'}], u'endpoints_links': [], u'type': u'volume', u'name': u'swift_proxy'}, {u'endpoints': [{u'adminURL': u'http://iad-int-api.cloudkeep.io:9312/v1', u'region': u'regionOne', u'id': u'ff598d95994e4108a74efb6875672fb4', u'publicURL': u'http://iad-int-api.cloudkeep.io:9311/v1'}], u'endpoints_links': [], u'type': u'keystore', u'name': u'barbican'}], 'tenant': u'788c9ea4a057403ba3f334f4de0f9a9f'} ==== process_request /Users/step6927/barbican/barbican/api/middleware/context.py:87
2014-07-08 22:07:25.102 47555 DEBUG barbican.openstack.common.policy [-] Rule secrets:post will be now enforced enforce /Users/step6927/barbican/barbican/openstack/common/policy.py:288
2014-07-08 22:07:25.103 47555 DEBUG barbican.api.controllers.secrets [-] Start on_post for tenant-ID 788c9ea4a057403ba3f334f4de0f9a9f:... on_post /Users/step6927/barbican/barbican/api/controllers/secrets.py:231
2014-07-08 22:07:25.123 47555 DEBUG barbican.model.repositories [-] Getting session... get_session /Users/step6927/barbican/barbican/model/repositories.py:286
2014-07-08 22:07:25.129 47555 INFO sqlalchemy.engine.base.Engine [-] SELECT tenants.id AS tenants_id, tenants.created_at AS tenants_created_at, tenants.updated_at AS tenants_updated_at, tenants.deleted_at AS tenants_deleted_at, tenants.deleted AS tenants_deleted, tenants.status AS tenants_status, tenants.keystone_id AS tenants_keystone_id
FROM tenants
WHERE tenants.keystone_id = ?
2014-07-08 22:07:25.130 47555 INFO sqlalchemy.engine.base.Engine [-] ('788c9ea4a057403ba3f334f4de0f9a9f',)
2014-07-08 22:07:25.132 47555 DEBUG sqlalchemy.engine.base.Engine [-] Col ('tenants_id', 'tenants_created_at', 'tenants_updated_at', 'tenants_deleted_at', 'tenants_deleted', 'tenants_status', 'tenants_keystone_id') __init__ /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/sqlalchemy/engine/base.py:2788
2014-07-08 22:07:25.133 47555 DEBUG sqlalchemy.engine.base.Engine [-] Row (u'ab33cd29-32eb-43ea-978e-35c268edac79', u'2014-07-07 16:41:48.545908', u'2014-07-07 16:41:48.545917', None, 0, u'ACTIVE', u'788c9ea4a057403ba3f334f4de0f9a9f') process_rows /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/sqlalchemy/engine/base.py:3193
2014-07-08 22:07:25.135 47555 DEBUG barbican.model.repositories [-] Begin create from... create_from /Users/step6927/barbican/barbican/model/repositories.py:326
2014-07-08 22:07:25.136 47555 DEBUG barbican.model.repositories [-] Saving entity... create_from /Users/step6927/barbican/barbican/model/repositories.py:338
2014-07-08 22:07:25.150 47555 INFO sqlalchemy.engine.base.Engine [-] BEGIN (implicit)
2014-07-08 22:07:25.152 47555 INFO sqlalchemy.engine.base.Engine [-] INSERT INTO secrets (id, created_at, updated_at, deleted_at, deleted, status, name, expiration, algorithm, bit_length, mode) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
2014-07-08 22:07:25.153 47555 INFO sqlalchemy.engine.base.Engine [-] ('019c2a3b-d12e-4014-8cac-da42a354c5a1', '2014-07-09 03:07:25.152365', '2014-07-09 03:07:25.152407', None, 0, 'ACTIVE', u'beer', None, None, None, None)
2014-07-08 22:07:25.155 47555 INFO sqlalchemy.engine.base.Engine [-] COMMIT
2014-07-08 22:07:25.165 47555 DEBUG barbican.model.repositories [-] Elapsed repo create secret:0.0296061038971 create_from /Users/step6927/barbican/barbican/model/repositories.py:345
2014-07-08 22:07:25.166 47555 DEBUG barbican.model.repositories [-] Begin create from... create_from /Users/step6927/barbican/barbican/model/repositories.py:326
2014-07-08 22:07:25.167 47555 DEBUG barbican.model.repositories [-] Saving entity... create_from /Users/step6927/barbican/barbican/model/repositories.py:338
2014-07-08 22:07:25.169 47555 INFO sqlalchemy.engine.base.Engine [-] BEGIN (implicit)
2014-07-08 22:07:25.171 47555 INFO sqlalchemy.engine.base.Engine [-] INSERT INTO tenant_secret (id, created_at, updated_at, deleted_at, deleted, status, tenant_id, secret_id, role) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?)
2014-07-08 22:07:25.172 47555 INFO sqlalchemy.engine.base.Engine [-] ('7f40233d-0677-4f37-8f1b-7f9124965c6a', '2014-07-09 03:07:25.171167', '2014-07-09 03:07:25.171207', None, 0, 'ACTIVE', u'ab33cd29-32eb-43ea-978e-35c268edac79', '019c2a3b-d12e-4014-8cac-da42a354c5a1', 'admin')
2014-07-08 22:07:25.174 47555 INFO sqlalchemy.engine.base.Engine [-] COMMIT
2014-07-08 22:07:25.177 47555 DEBUG barbican.model.repositories [-] Elapsed repo create secret:0.0110471248627 create_from /Users/step6927/barbican/barbican/model/repositories.py:345
2014-07-08 22:07:25.178 47555 DEBUG barbican.api.controllers.secrets [-] URI to secret is http://localhost:9311/v1/788c9ea4a057403ba3f334f4de0f9a9f/secrets/019c2a3b-d12e-4014-8cac-da42a354c5a1 on_post /Users/step6927/barbican/barbican/api/controllers/secrets.py:248
2014-07-08 22:07:25.180 47555 WARNING barbican.api.middleware.context [-] Unable to retrieve request id from context
{address space usage: 2642104320 bytes/2519MB} {rss usage: 71938048 bytes/68MB} [pid: 47555|app: 0|req: 7/7] 127.0.0.1 () {32 vars in 2279 bytes} [Tue Jul 8 22:07:24 2014] POST /v1/788c9ea4a057403ba3f334f4de0f9a9f/secrets => generated 120 bytes in 699 msecs (HTTP/1.1 201) 3 headers in 203 bytes (2 switches on core 0)
2014-07-08 22:07:25.186 47555 DEBUG keystoneclient.middleware.auth_token [-] Authenticating user token __call__ /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/keystoneclient/middleware/auth_token.py:666
2014-07-08 22:07:25.187 47555 DEBUG keystoneclient.middleware.auth_token [-] Removing headers from request environment: X-Identity-Status,X-Domain-Id,X-Domain-Name,X-Project-Id,X-Project-Name,X-Project-Domain-Id,X-Project-Domain-Name,X-User-Id,X-User-Name,X-User-Domain-Id,X-User-Domain-Name,X-Roles,X-Service-Catalog,X-User,X-Tenant-Id,X-Tenant-Name,X-Tenant,X-Role _remove_auth_headers /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/keystoneclient/middleware/auth_token.py:725
2014-07-08 22:07:25.191 47555 DEBUG keystoneclient.middleware.auth_token [-] Returning cached token _cache_get /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/keystoneclient/middleware/auth_token.py:1124
2014-07-08 22:07:25.193 47555 DEBUG keystoneclient.middleware.auth_token [-] Storing token in cache _cache_put /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/keystoneclient/middleware/auth_token.py:1234
2014-07-08 22:07:25.194 47555 DEBUG keystoneclient.middleware.auth_token [-] Received request from user: 151a2022365643179d6b5c9cbb148925 with project_id : 788c9ea4a057403ba3f334f4de0f9a9f and roles: _member_,admin _build_user_headers /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/keystoneclient/middleware/auth_token.py:1021
2014-07-08 22:07:25.196 47555 DEBUG barbican.api.middleware.context [-] ==== Inserted barbican auth request context: {'user_id': u'151a2022365643179d6b5c9cbb148925', 'user': u'151a2022365643179d6b5c9cbb148925', 'roles': [u'_member_', u'admin'], 'request_id': 'dc4494d9-eae3-48dc-ba78-7c27587067ef', 'tenant_id': u'788c9ea4a057403ba3f334f4de0f9a9f', 'auth_token': 'MIIFPAYJKoZIhvcNAQcCoIIFLTCCBSkCAQExCTAHBgUrDgMCGjCCBBUGCSqGSIb3DQEHAaCCBAYEggQCeyJhY2Nlc3MiOiB7InRva2VuIjogeyJpc3N1ZWRfYXQiOiAiMjAxNC0wNy0wOVQwMzoxNTowMC43Njg2MjEiLCAiZXhwaXJlcyI6ICIyMDE0LTA3LTEwVDAzOjE0OjU5WiIsICJpZCI6ICJwbGFjZWhvbGRlciIsICJ0ZW5hbnQiOiB7ImRlc2NyaXB0aW9uIjogIkRlZmF1bHQgVGVuYW50IiwgImVuYWJsZWQiOiB0cnVlLCAiaWQiOiAiNzg4YzllYTRhMDU3NDAzYmEzZjMzNGY0ZGUwZjlhOWYiLCAibmFtZSI6ICJkZW1vIn19LCAic2VydmljZUNhdGFsb2ciOiBbeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vbG9jYWxob3N0OjgwMDEiLCAicmVnaW9uIjogInJlZ2lvbk9uZSIsICJwdWJsaWNVUkwiOiAiaHR0cDovL2xvY2FsaG9zdDo4MDAwIiwgImlkIjogImY5ZTg3N2E4MDQ5MzQ0YzViODc1OWVlMWQ1OWM2MDBhIn1dLCAiZW5kcG9pbnRzX2xpbmtzIjogW10sICJ0eXBlIjogInZvbHVtZSIsICJuYW1lIjogInN3aWZ0X3Byb3h5In0sIHsiZW5kcG9pbnRzIjogW3siYWRtaW5VUkwiOiAiaHR0cDovL2lhZC1pbnQtYXBpLmNsb3Vka2VlcC5pbzo5MzEyL3YxIiwgInJlZ2lvbiI6ICJyZWdpb25PbmUiLCAicHVibGljVVJMIjogImh0dHA6Ly9pYWQtaW50LWFwaS5jbG91ZGtlZXAuaW86OTMxMS92MSIsICJpZCI6ICJmZjU5OGQ5NTk5NGU0MTA4YTc0ZWZiNjg3NTY3MmZiNCJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJrZXlzdG9yZSIsICJuYW1lIjogImJhcmJpY2FuIn1dLCAidXNlciI6IHsidXNlcm5hbWUiOiAiYWRtaW5fdXNlciIsICJyb2xlc19saW5rcyI6IFtdLCAiaWQiOiAiMTUxYTIwMjIzNjU2NDMxNzlkNmI1YzljYmIxNDg5MjUiLCAicm9sZXMiOiBbeyJuYW1lIjogIl9tZW1iZXJfIn0sIHsibmFtZSI6ICJhZG1pbiJ9XSwgIm5hbWUiOiAiYWRtaW5fdXNlciJ9LCAibWV0YWRhdGEiOiB7ImlzX2FkbWluIjogMCwgInJvbGVzIjogWyI5ZmUyZmY5ZWU0Mzg0YjE4OTRhOTA4NzhkM2U5MmJhYiIsICJkZjFkODMzNjdjZDk0OGE1YjVkOTM1NjdmMjQ3M2IzMCJdfX19MYH-MIH8AgEBMFwwVzELMAkGA1UEBhMCVVMxDjAMBgNVBAgTBVVuc2V0MQ4wDAYDVQQHEwVVbnNldDEOMAwGA1UEChMFVW5zZXQxGDAWBgNVBAMTD3d3dy5leGFtcGxlLmNvbQIBATAHBgUrDgMCGjANBgkqhkiG9w0BAQEFAASBgF5H3rx1pxPIrzJ6EqxMu0seM6eP5RaCM33A3HqraQshruAnfjUga6A4dfncNwg5gDs3k9XdbZFtdAbMlWxTNzXgncvu3-Ymz-x7Uqbzly1L3x6AsyhgXiQDjcQ44lSUOPcja362lLuYY9Zhcl741XkMANodsRHOZ8q9AdMG8y4l', 'project_id': u'788c9ea4a057403ba3f334f4de0f9a9f', 'service_catalog': [{u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://localhost:8001', u'region': u'regionOne', u'id': u'f9e877a8049344c5b8759ee1d59c600a', u'publicURL': u'http://localhost:8000'}], u'type': u'volume', u'name': u'swift_proxy'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://iad-int-api.cloudkeep.io:9312/v1', u'region': u'regionOne', u'id': u'ff598d95994e4108a74efb6875672fb4', u'publicURL': u'http://iad-int-api.cloudkeep.io:9311/v1'}], u'type': u'keystore', u'name': u'barbican'}], 'tenant': u'788c9ea4a057403ba3f334f4de0f9a9f'} ==== process_request /Users/step6927/barbican/barbican/api/middleware/context.py:87
2014-07-08 22:07:25.197 47555 DEBUG barbican.api.controllers.secrets [-] === Creating SecretController === __init__ /Users/step6927/barbican/barbican/api/controllers/secrets.py:59
2014-07-08 22:07:25.198 47555 DEBUG barbican.openstack.common.policy [-] Rule secret:put will be now enforced enforce /Users/step6927/barbican/barbican/openstack/common/policy.py:288
2014-07-08 22:07:25.200 47555 DEBUG barbican.model.repositories [-] Getting session... get_session /Users/step6927/barbican/barbican/model/repositories.py:286
2014-07-08 22:07:25.226 47555 INFO sqlalchemy.engine.base.Engine [-] SELECT secrets.id AS secrets_id, secrets.created_at AS secrets_created_at, secrets.updated_at AS secrets_updated_at, secrets.deleted_at AS secrets_deleted_at, secrets.deleted AS secrets_deleted, secrets.status AS secrets_status, secrets.name AS secrets_name, secrets.expiration AS secrets_expiration, secrets.algorithm AS secrets_algorithm, secrets.bit_length AS secrets_bit_length, secrets.mode AS secrets_mode, encrypted_data_1.id AS encrypted_data_1_id, encrypted_data_1.created_at AS encrypted_data_1_created_at, encrypted_data_1.updated_at AS encrypted_data_1_updated_at, encrypted_data_1.deleted_at AS encrypted_data_1_deleted_at, encrypted_data_1.deleted AS encrypted_data_1_deleted, encrypted_data_1.status AS encrypted_data_1_status, encrypted_data_1.secret_id AS encrypted_data_1_secret_id, encrypted_data_1.kek_id AS encrypted_data_1_kek_id, encrypted_data_1.content_type AS encrypted_data_1_content_type, encrypted_data_1.cypher_text AS encrypted_data_1_cypher_text, encrypted_data_1.kek_meta_extended AS encrypted_data_1_kek_meta_extended
FROM secrets JOIN tenant_secret ON secrets.id = tenant_secret.secret_id JOIN tenants ON tenants.id = tenant_secret.tenant_id LEFT OUTER JOIN encrypted_data AS encrypted_data_1 ON secrets.id = encrypted_data_1.secret_id
WHERE secrets.id = ? AND secrets.deleted = ? AND (secrets.expiration IS NULL OR secrets.expiration > ?) AND tenants.keystone_id = ? AND tenants.deleted = ?
2014-07-08 22:07:25.227 47555 INFO sqlalchemy.engine.base.Engine [-] ('019c2a3b-d12e-4014-8cac-da42a354c5a1', 0, '2014-07-09 03:07:25.201223', '788c9ea4a057403ba3f334f4de0f9a9f', 0)
2014-07-08 22:07:25.234 47555 DEBUG sqlalchemy.engine.base.Engine [-] Col ('secrets_id', 'secrets_created_at', 'secrets_updated_at', 'secrets_deleted_at', 'secrets_deleted', 'secrets_status', 'secrets_name', 'secrets_expiration', 'secrets_algorithm', 'secrets_bit_length', 'secrets_mode', 'encrypted_data_1_id', 'encrypted_data_1_created_at', 'encrypted_data_1_updated_at', 'encrypted_data_1_deleted_at', 'encrypted_data_1_deleted', 'encrypted_data_1_status', 'encrypted_data_1_secret_id', 'encrypted_data_1_kek_id', 'encrypted_data_1_content_type', 'encrypted_data_1_cypher_text', 'encrypted_data_1_kek_meta_extended') __init__ /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/sqlalchemy/engine/base.py:2788
2014-07-08 22:07:25.235 47555 DEBUG sqlalchemy.engine.base.Engine [-] Row (u'019c2a3b-d12e-4014-8cac-da42a354c5a1', u'2014-07-09 03:07:25.152365', u'2014-07-09 03:07:25.152407', None, 0, u'ACTIVE', u'beer', None, None, None, None, None, None, None, None, None, None, None, None, None, None, None) process_rows /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/sqlalchemy/engine/base.py:3193
2014-07-08 22:07:25.239 47555 DEBUG barbican.model.repositories [-] Getting session... get_session /Users/step6927/barbican/barbican/model/repositories.py:286
2014-07-08 22:07:25.243 47555 INFO sqlalchemy.engine.base.Engine [-] SELECT tenants.id AS tenants_id, tenants.created_at AS tenants_created_at, tenants.updated_at AS tenants_updated_at, tenants.deleted_at AS tenants_deleted_at, tenants.deleted AS tenants_deleted, tenants.status AS tenants_status, tenants.keystone_id AS tenants_keystone_id
FROM tenants
WHERE tenants.keystone_id = ?
2014-07-08 22:07:25.244 47555 INFO sqlalchemy.engine.base.Engine [-] ('788c9ea4a057403ba3f334f4de0f9a9f',)
2014-07-08 22:07:25.245 47555 DEBUG sqlalchemy.engine.base.Engine [-] Col ('tenants_id', 'tenants_created_at', 'tenants_updated_at', 'tenants_deleted_at', 'tenants_deleted', 'tenants_status', 'tenants_keystone_id') __init__ /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/sqlalchemy/engine/base.py:2788
2014-07-08 22:07:25.246 47555 DEBUG sqlalchemy.engine.base.Engine [-] Row (u'ab33cd29-32eb-43ea-978e-35c268edac79', u'2014-07-07 16:41:48.545908', u'2014-07-07 16:41:48.545917', None, 0, u'ACTIVE', u'788c9ea4a057403ba3f334f4de0f9a9f') process_rows /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/sqlalchemy/engine/base.py:3193
2014-07-08 22:07:25.252 47555 INFO sqlalchemy.engine.base.Engine [-] SELECT secret_store_metadata.id AS secret_store_metadata_id, secret_store_metadata.created_at AS secret_store_metadata_created_at, secret_store_metadata.updated_at AS secret_store_metadata_updated_at, secret_store_metadata.deleted_at AS secret_store_metadata_deleted_at, secret_store_metadata.deleted AS secret_store_metadata_deleted, secret_store_metadata.status AS secret_store_metadata_status, secret_store_metadata.secret_id AS secret_store_metadata_secret_id, secret_store_metadata."key" AS secret_store_metadata_key, secret_store_metadata.value AS secret_store_metadata_value
FROM secret_store_metadata
WHERE ? = secret_store_metadata.secret_id
2014-07-08 22:07:25.253 47555 INFO sqlalchemy.engine.base.Engine [-] (u'019c2a3b-d12e-4014-8cac-da42a354c5a1',)
2014-07-08 22:07:25.256 47555 DEBUG sqlalchemy.engine.base.Engine [-] Col ('secret_store_metadata_id', 'secret_store_metadata_created_at', 'secret_store_metadata_updated_at', 'secret_store_metadata_deleted_at', 'secret_store_metadata_deleted', 'secret_store_metadata_status', 'secret_store_metadata_secret_id', 'secret_store_metadata_key', 'secret_store_metadata_value') __init__ /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/sqlalchemy/engine/base.py:2788
2014-07-08 22:07:25.257 47555 DEBUG stevedore.extension [-] found extension EntryPoint.parse('store_crypto = barbican.plugin.store_crypto:StoreCryptoAdapterPlugin') _load_plugins /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/stevedore/extension.py:156
2014-07-08 22:07:25.258 47555 DEBUG stevedore.extension [-] found extension EntryPoint.parse('dogtag_crypto = barbican.plugin.dogtag:DogtagPlugin') _load_plugins /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/stevedore/extension.py:156
2014-07-08 22:07:25.259 47555 ERROR barbican.api.controllers [-] Secret update issue seen - Text-based binary secret payloads must specify a content-encoding of 'base64'.
2014-07-08 22:07:25.259 47555 TRACE barbican.api.controllers Traceback (most recent call last):
2014-07-08 22:07:25.259 47555 TRACE barbican.api.controllers File "/Users/step6927/barbican/barbican/api/controllers/__init__.py", line 85, in handler
2014-07-08 22:07:25.259 47555 TRACE barbican.api.controllers return fn(inst, *args, **kwargs)
2014-07-08 22:07:25.259 47555 TRACE barbican.api.controllers File "/Users/step6927/barbican/barbican/api/controllers/__init__.py", line 71, in enforcer
2014-07-08 22:07:25.259 47555 TRACE barbican.api.controllers return fn(inst, *args, **kwargs)
2014-07-08 22:07:25.259 47555 TRACE barbican.api.controllers File "/Users/step6927/barbican/barbican/api/controllers/__init__.py", line 117, in content_types_enforcer
2014-07-08 22:07:25.259 47555 TRACE barbican.api.controllers return fn(inst, *args, **kwargs)
2014-07-08 22:07:25.259 47555 TRACE barbican.api.controllers File "/Users/step6927/barbican/barbican/api/controllers/secrets.py", line 135, in on_put
2014-07-08 22:07:25.259 47555 TRACE barbican.api.controllers secret_model, tenant_model, self.repos)
2014-07-08 22:07:25.259 47555 TRACE barbican.api.controllers File "/Users/step6927/barbican/barbican/plugin/resources.py", line 49, in store_secret
2014-07-08 22:07:25.259 47555 TRACE barbican.api.controllers enforce_text_only=True)
2014-07-08 22:07:25.259 47555 TRACE barbican.api.controllers File "/Users/step6927/barbican/barbican/plugin/util/translations.py", line 48, in normalize_before_encryption
2014-07-08 22:07:25.259 47555 TRACE barbican.api.controllers raise s.SecretContentEncodingMustBeBase64()
2014-07-08 22:07:25.259 47555 TRACE barbican.api.controllers SecretContentEncodingMustBeBase64: Encoding type must be 'base64' for text-based payloads.
2014-07-08 22:07:25.259 47555 TRACE barbican.api.controllers
2014-07-08 22:07:25.262 47555 WARNING barbican.api.middleware.context [-] Unable to retrieve request id from context
{address space usage: 2642104320 bytes/2519MB} {rss usage: 71938048 bytes/68MB} [pid: 47555|app: 0|req: 8/8] 127.0.0.1 () {32 vars in 2359 bytes} [Tue Jul 8 22:07:25 2014] PUT /v1/788c9ea4a057403ba3f334f4de0f9a9f/secrets/019c2a3b-d12e-4014-8cac-da42a354c5a1 => generated 161 bytes in 77 msecs (HTTP/1.1 400) 2 headers in 96 bytes (2 switches on core 0)
2014-07-08 22:07:25.268 47555 DEBUG keystoneclient.middleware.auth_token [-] Authenticating user token __call__ /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/keystoneclient/middleware/auth_token.py:666
2014-07-08 22:07:25.269 47555 DEBUG keystoneclient.middleware.auth_token [-] Removing headers from request environment: X-Identity-Status,X-Domain-Id,X-Domain-Name,X-Project-Id,X-Project-Name,X-Project-Domain-Id,X-Project-Domain-Name,X-User-Id,X-User-Name,X-User-Domain-Id,X-User-Domain-Name,X-Roles,X-Service-Catalog,X-User,X-Tenant-Id,X-Tenant-Name,X-Tenant,X-Role _remove_auth_headers /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/keystoneclient/middleware/auth_token.py:725
2014-07-08 22:07:25.271 47555 DEBUG keystoneclient.middleware.auth_token [-] Returning cached token _cache_get /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/keystoneclient/middleware/auth_token.py:1124
2014-07-08 22:07:25.272 47555 DEBUG keystoneclient.middleware.auth_token [-] Storing token in cache _cache_put /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/keystoneclient/middleware/auth_token.py:1234
2014-07-08 22:07:25.273 47555 DEBUG keystoneclient.middleware.auth_token [-] Received request from user: 151a2022365643179d6b5c9cbb148925 with project_id : 788c9ea4a057403ba3f334f4de0f9a9f and roles: _member_,admin _build_user_headers /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/keystoneclient/middleware/auth_token.py:1021
2014-07-08 22:07:25.276 47555 DEBUG barbican.api.middleware.context [-] ==== Inserted barbican auth request context: {'user_id': u'151a2022365643179d6b5c9cbb148925', 'user': u'151a2022365643179d6b5c9cbb148925', 'roles': [u'_member_', u'admin'], 'request_id': '7aa34285-72bc-48a0-a62a-d1b2c7f9ebec', 'tenant_id': u'788c9ea4a057403ba3f334f4de0f9a9f', 'auth_token': 'MIIFPAYJKoZIhvcNAQcCoIIFLTCCBSkCAQExCTAHBgUrDgMCGjCCBBUGCSqGSIb3DQEHAaCCBAYEggQCeyJhY2Nlc3MiOiB7InRva2VuIjogeyJpc3N1ZWRfYXQiOiAiMjAxNC0wNy0wOVQwMzoxNTowMC43Njg2MjEiLCAiZXhwaXJlcyI6ICIyMDE0LTA3LTEwVDAzOjE0OjU5WiIsICJpZCI6ICJwbGFjZWhvbGRlciIsICJ0ZW5hbnQiOiB7ImRlc2NyaXB0aW9uIjogIkRlZmF1bHQgVGVuYW50IiwgImVuYWJsZWQiOiB0cnVlLCAiaWQiOiAiNzg4YzllYTRhMDU3NDAzYmEzZjMzNGY0ZGUwZjlhOWYiLCAibmFtZSI6ICJkZW1vIn19LCAic2VydmljZUNhdGFsb2ciOiBbeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vbG9jYWxob3N0OjgwMDEiLCAicmVnaW9uIjogInJlZ2lvbk9uZSIsICJwdWJsaWNVUkwiOiAiaHR0cDovL2xvY2FsaG9zdDo4MDAwIiwgImlkIjogImY5ZTg3N2E4MDQ5MzQ0YzViODc1OWVlMWQ1OWM2MDBhIn1dLCAiZW5kcG9pbnRzX2xpbmtzIjogW10sICJ0eXBlIjogInZvbHVtZSIsICJuYW1lIjogInN3aWZ0X3Byb3h5In0sIHsiZW5kcG9pbnRzIjogW3siYWRtaW5VUkwiOiAiaHR0cDovL2lhZC1pbnQtYXBpLmNsb3Vka2VlcC5pbzo5MzEyL3YxIiwgInJlZ2lvbiI6ICJyZWdpb25PbmUiLCAicHVibGljVVJMIjogImh0dHA6Ly9pYWQtaW50LWFwaS5jbG91ZGtlZXAuaW86OTMxMS92MSIsICJpZCI6ICJmZjU5OGQ5NTk5NGU0MTA4YTc0ZWZiNjg3NTY3MmZiNCJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJrZXlzdG9yZSIsICJuYW1lIjogImJhcmJpY2FuIn1dLCAidXNlciI6IHsidXNlcm5hbWUiOiAiYWRtaW5fdXNlciIsICJyb2xlc19saW5rcyI6IFtdLCAiaWQiOiAiMTUxYTIwMjIzNjU2NDMxNzlkNmI1YzljYmIxNDg5MjUiLCAicm9sZXMiOiBbeyJuYW1lIjogIl9tZW1iZXJfIn0sIHsibmFtZSI6ICJhZG1pbiJ9XSwgIm5hbWUiOiAiYWRtaW5fdXNlciJ9LCAibWV0YWRhdGEiOiB7ImlzX2FkbWluIjogMCwgInJvbGVzIjogWyI5ZmUyZmY5ZWU0Mzg0YjE4OTRhOTA4NzhkM2U5MmJhYiIsICJkZjFkODMzNjdjZDk0OGE1YjVkOTM1NjdmMjQ3M2IzMCJdfX19MYH-MIH8AgEBMFwwVzELMAkGA1UEBhMCVVMxDjAMBgNVBAgTBVVuc2V0MQ4wDAYDVQQHEwVVbnNldDEOMAwGA1UEChMFVW5zZXQxGDAWBgNVBAMTD3d3dy5leGFtcGxlLmNvbQIBATAHBgUrDgMCGjANBgkqhkiG9w0BAQEFAASBgF5H3rx1pxPIrzJ6EqxMu0seM6eP5RaCM33A3HqraQshruAnfjUga6A4dfncNwg5gDs3k9XdbZFtdAbMlWxTNzXgncvu3-Ymz-x7Uqbzly1L3x6AsyhgXiQDjcQ44lSUOPcja362lLuYY9Zhcl741XkMANodsRHOZ8q9AdMG8y4l', 'project_id': u'788c9ea4a057403ba3f334f4de0f9a9f', 'service_catalog': [{u'endpoints': [{u'adminURL': u'http://localhost:8001', u'region': u'regionOne', u'id': u'f9e877a8049344c5b8759ee1d59c600a', u'publicURL': u'http://localhost:8000'}], u'endpoints_links': [], u'type': u'volume', u'name': u'swift_proxy'}, {u'endpoints': [{u'adminURL': u'http://iad-int-api.cloudkeep.io:9312/v1', u'region': u'regionOne', u'id': u'ff598d95994e4108a74efb6875672fb4', u'publicURL': u'http://iad-int-api.cloudkeep.io:9311/v1'}], u'endpoints_links': [], u'type': u'keystore', u'name': u'barbican'}], 'tenant': u'788c9ea4a057403ba3f334f4de0f9a9f'} ==== process_request /Users/step6927/barbican/barbican/api/middleware/context.py:87
2014-07-08 22:07:25.277 47555 DEBUG barbican.api.controllers.secrets [-] === Creating SecretController === __init__ /Users/step6927/barbican/barbican/api/controllers/secrets.py:59
2014-07-08 22:07:25.279 47555 DEBUG barbican.openstack.common.policy [-] Rule secret:delete will be now enforced enforce /Users/step6927/barbican/barbican/openstack/common/policy.py:288
2014-07-08 22:07:25.279 47555 DEBUG barbican.model.repositories [-] Getting session... get_session /Users/step6927/barbican/barbican/model/repositories.py:286
2014-07-08 22:07:25.307 47555 INFO sqlalchemy.engine.base.Engine [-] SELECT secrets.id AS secrets_id, secrets.created_at AS secrets_created_at, secrets.updated_at AS secrets_updated_at, secrets.deleted_at AS secrets_deleted_at, secrets.deleted AS secrets_deleted, secrets.status AS secrets_status, secrets.name AS secrets_name, secrets.expiration AS secrets_expiration, secrets.algorithm AS secrets_algorithm, secrets.bit_length AS secrets_bit_length, secrets.mode AS secrets_mode, encrypted_data_1.id AS encrypted_data_1_id, encrypted_data_1.created_at AS encrypted_data_1_created_at, encrypted_data_1.updated_at AS encrypted_data_1_updated_at, encrypted_data_1.deleted_at AS encrypted_data_1_deleted_at, encrypted_data_1.deleted AS encrypted_data_1_deleted, encrypted_data_1.status AS encrypted_data_1_status, encrypted_data_1.secret_id AS encrypted_data_1_secret_id, encrypted_data_1.kek_id AS encrypted_data_1_kek_id, encrypted_data_1.content_type AS encrypted_data_1_content_type, encrypted_data_1.cypher_text AS encrypted_data_1_cypher_text, encrypted_data_1.kek_meta_extended AS encrypted_data_1_kek_meta_extended
FROM secrets JOIN tenant_secret ON secrets.id = tenant_secret.secret_id JOIN tenants ON tenants.id = tenant_secret.tenant_id LEFT OUTER JOIN encrypted_data AS encrypted_data_1 ON secrets.id = encrypted_data_1.secret_id
WHERE secrets.id = ? AND secrets.deleted = ? AND (secrets.expiration IS NULL OR secrets.expiration > ?) AND tenants.keystone_id = ? AND tenants.deleted = ?
2014-07-08 22:07:25.308 47555 INFO sqlalchemy.engine.base.Engine [-] ('019c2a3b-d12e-4014-8cac-da42a354c5a1', 0, '2014-07-09 03:07:25.280384', '788c9ea4a057403ba3f334f4de0f9a9f', 0)
2014-07-08 22:07:25.315 47555 DEBUG sqlalchemy.engine.base.Engine [-] Col ('secrets_id', 'secrets_created_at', 'secrets_updated_at', 'secrets_deleted_at', 'secrets_deleted', 'secrets_status', 'secrets_name', 'secrets_expiration', 'secrets_algorithm', 'secrets_bit_length', 'secrets_mode', 'encrypted_data_1_id', 'encrypted_data_1_created_at', 'encrypted_data_1_updated_at', 'encrypted_data_1_deleted_at', 'encrypted_data_1_deleted', 'encrypted_data_1_status', 'encrypted_data_1_secret_id', 'encrypted_data_1_kek_id', 'encrypted_data_1_content_type', 'encrypted_data_1_cypher_text', 'encrypted_data_1_kek_meta_extended') __init__ /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/sqlalchemy/engine/base.py:2788
2014-07-08 22:07:25.324 47555 DEBUG sqlalchemy.engine.base.Engine [-] Row (u'019c2a3b-d12e-4014-8cac-da42a354c5a1', u'2014-07-09 03:07:25.152365', u'2014-07-09 03:07:25.152407', None, 0, u'ACTIVE', u'beer', None, None, None, None, None, None, None, None, None, None, None, None, None, None, None) process_rows /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/sqlalchemy/engine/base.py:3193
2014-07-08 22:07:25.335 47555 INFO sqlalchemy.engine.base.Engine [-] SELECT secret_store_metadata.id AS secret_store_metadata_id, secret_store_metadata.created_at AS secret_store_metadata_created_at, secret_store_metadata.updated_at AS secret_store_metadata_updated_at, secret_store_metadata.deleted_at AS secret_store_metadata_deleted_at, secret_store_metadata.deleted AS secret_store_metadata_deleted, secret_store_metadata.status AS secret_store_metadata_status, secret_store_metadata.secret_id AS secret_store_metadata_secret_id, secret_store_metadata."key" AS secret_store_metadata_key, secret_store_metadata.value AS secret_store_metadata_value
FROM secret_store_metadata
WHERE ? = secret_store_metadata.secret_id
2014-07-08 22:07:25.336 47555 INFO sqlalchemy.engine.base.Engine [-] (u'019c2a3b-d12e-4014-8cac-da42a354c5a1',)
2014-07-08 22:07:25.340 47555 DEBUG sqlalchemy.engine.base.Engine [-] Col ('secret_store_metadata_id', 'secret_store_metadata_created_at', 'secret_store_metadata_updated_at', 'secret_store_metadata_deleted_at', 'secret_store_metadata_deleted', 'secret_store_metadata_status', 'secret_store_metadata_secret_id', 'secret_store_metadata_key', 'secret_store_metadata_value') __init__ /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/sqlalchemy/engine/base.py:2788
2014-07-08 22:07:25.342 47555 DEBUG stevedore.extension [-] found extension EntryPoint.parse('store_crypto = barbican.plugin.store_crypto:StoreCryptoAdapterPlugin') _load_plugins /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/stevedore/extension.py:156
2014-07-08 22:07:25.343 47555 DEBUG stevedore.extension [-] found extension EntryPoint.parse('dogtag_crypto = barbican.plugin.dogtag:DogtagPlugin') _load_plugins /Users/step6927/.pyenv/versions/newbarbican27/lib/python2.7/site-packages/stevedore/extension.py:156
2014-07-08 22:07:25.344 47555 ERROR barbican.api.controllers [-] Secret deletion failure seen - please contact site administrator.
2014-07-08 22:07:25.344 47555 TRACE barbican.api.controllers Traceback (most recent call last):
2014-07-08 22:07:25.344 47555 TRACE barbican.api.controllers File "/Users/step6927/barbican/barbican/api/controllers/__init__.py", line 85, in handler
2014-07-08 22:07:25.344 47555 TRACE barbican.api.controllers return fn(inst, *args, **kwargs)
2014-07-08 22:07:25.344 47555 TRACE barbican.api.controllers File "/Users/step6927/barbican/barbican/api/controllers/__init__.py", line 71, in enforcer
2014-07-08 22:07:25.344 47555 TRACE barbican.api.controllers return fn(inst, *args, **kwargs)
2014-07-08 22:07:25.344 47555 TRACE barbican.api.controllers File "/Users/step6927/barbican/barbican/api/controllers/secrets.py", line 148, in on_delete
2014-07-08 22:07:25.344 47555 TRACE barbican.api.controllers plugin.delete_secret(secret_model, keystone_id, self.repos)
2014-07-08 22:07:25.344 47555 TRACE barbican.api.controllers File "/Users/step6927/barbican/barbican/plugin/resources.py", line 141, in delete_secret
2014-07-08 22:07:25.344 47555 TRACE barbican.api.controllers .get_plugin_retrieve_delete(secret_metadata.get('plugin_name'))
2014-07-08 22:07:25.344 47555 TRACE barbican.api.controllers File "/Users/step6927/barbican/barbican/plugin/interface/secret_store.py", line 381, in get_plugin_retrieve_delete
2014-07-08 22:07:25.344 47555 TRACE barbican.api.controllers raise SecretStoreSupportedPluginNotFound()
2014-07-08 22:07:25.344 47555 TRACE barbican.api.controllers SecretStoreSupportedPluginNotFound: Secret store plugin not found for requested operation.
2014-07-08 22:07:25.344 47555 TRACE barbican.api.controllers
2014-07-08 22:07:25.348 47555 WARNING barbican.api.middleware.context [-] Unable to retrieve request id from context
{address space usage: 2642104320 bytes/2519MB} {rss usage: 72044544 bytes/68MB} [pid: 47555|app: 0|req: 9/9] 127.0.0.1 () {32 vars in 2354 bytes} [Tue Jul 8 22:07:25 2014] DELETE /v1/788c9ea4a057403ba3f334f4de0f9a9f/secrets/019c2a3b-d12e-4014-8cac-da42a354c5a1 => generated 131 bytes in 81 msecs (HTTP/1.1 500) 2 headers in 106 bytes (2 switches on core 0)
This looks like this was fixed sometime during Juno.