Nested endpoints fail to commit to Postgres

[adam-codeberg]

When interacting with nested endpoints they appear to have trouble identifying the parents ID

The result is that the data gets inserted into elasticsearch but not postgre.

Steps to reproduce

Use RAML and Schemas provided here /addressbook/

http --session user1 POST :6543/api/contacts name_title='Mr' name_first='Fred' name_last='Flinstone'
http --session user1 POST :6543/api/destinations type='Work'                                                                              
http --session user1 POST :6543/api/contacts/1/emails  address='fred@caveit.com' fk_destination_type='Work'  fk_contact_id='1'

Debug output is as follows

2015-10-10 19:46:58,396 DEBUG [txn.140440433747712][Dummy-3] _transaction.__init__: new transaction
2015-10-10 19:46:58,396 DEBUG [nefertari_sqla.documents][Dummy-3] documents.get_collection: Get collection: AuthUser, {'username': u'system', '_item_request': True, '_limit': 1, '__raise_on_empty': True}
2015-10-10 19:46:58,405 DEBUG [nefertari_sqla.documents][Dummy-3] documents.get_collection: get_collection.query_set: AuthUser (SELECT ramses_authuser._version AS ramses_authuser__version, ramses_authuser.username AS ramses_authuser_username, ramses_authuser.email AS ramses_authuser_email, ramses_authuser.password AS ramses_authuser_password, ramses_authuser.groups AS ramses_authuser_groups FROM ramses_authuser WHERE ramses_authuser.username = %(username_1)s  LIMIT %(param_1)s OFFSET %(param_2)s)
2015-10-10 19:46:58,409 DEBUG [nefertari_sqla.documents][Dummy-3] documents.get_collection: Get collection: Email, {'_item_request': True, '_limit': 1, '__raise_on_empty': True, 'id': 1}
2015-10-10 19:46:58,418 DEBUG [nefertari_sqla.documents][Dummy-3] documents.get_collection: get_collection.query_set: Email (SELECT email._version AS email__version, email.id AS email_id, email.address AS email_address, email.fk_contact_id AS email_fk_contact_id, email.fk_destination_type AS email_fk_destination_type FROM email WHERE email.id = %(id_1)s  LIMIT %(param_1)s OFFSET %(param_2)s)
2015-10-10 19:46:58,422 DEBUG [urllib3.util.retry][Dummy-3] retry.from_int: Converted retries value: False -> Retry(total=False, connect=None, read=None, redirect=0)
2015-10-10 19:46:58,426 DEBUG [urllib3.connectionpool][Dummy-3] connectionpool._make_request: "POST /_bulk HTTP/1.1" 200 121
2015-10-10 19:46:58,426 INFO  [elasticsearch][Dummy-3] base.log_request_success: POST http://localhost:9200/_bulk [status:200 request:0.004s]
2015-10-10 19:46:58,426 DEBUG [elasticsearch][Dummy-3] base.log_request_success: > {"index": {"_type": "Email", "_id": "1", "_index": "licenseapi"}}
{"fk_destination_type": "Work", "_version": 0, "_pk": "1", "contact": null, "fk_contact_id": null, "address": "fred2@caveit.com", "id": 1}

2015-10-10 19:46:58,426 DEBUG [elasticsearch][Dummy-3] base.log_request_success: < {"took":3,"errors":false,"items":[{"index":{"_index":"licenseapi","_type":"Email","_id":"1","_version":1,"status":201}}]}
2015-10-10 19:46:58,427 INFO  [nefertari.elasticsearch][Dummy-3] elasticsearch._bulk_body: Successfully executed 1 Elasticsearch action(s)
2015-10-10 19:46:58,431 DEBUG [txn.140440433747712][Dummy-3] _transaction.abort: abort
2015-10-10 19:46:58,432 ERROR [nefertari.json_httpexceptions][Dummy-3] json_httpexceptions.create_json_response: 400 BAD REQUEST: {"status_code": 400, "explanation": "The server could not comply with the request since it is either malformed or otherwise incorrect.", "message": "Bad or missing param 'contacts_id'", "timestamp": "2015-10-10T08:46:58Z", "title": "Bad Request"}
STACK BEGIN>>
  File "/home/username/.pyenv/versions/project-name/lib/python2.7/site-packages/waitress/task.py", line 74, in handler_thread
    task.service()
  File "/home/username/.pyenv/versions/project-name/lib/python2.7/site-packages/waitress/channel.py", line 337, in service
    task.service()
  File "/home/username/.pyenv/versions/project-name/lib/python2.7/site-packages/waitress/task.py", line 173, in service
    self.execute()
  File "/home/username/.pyenv/versions/project-name/lib/python2.7/site-packages/waitress/task.py", line 392, in execute
    app_iter = self.channel.server.application(env, start_response)
  File "/home/username/.pyenv/versions/project-name/lib/python2.7/site-packages/paste/urlmap.py", line 216, in __call__
    return app(environ, start_response)
  File "/home/username/.pyenv/versions/project-name/lib/python2.7/site-packages/pyramid/router.py", line 242, in __call__
    response = self.invoke_subrequest(request, use_tweens=True)
  File "/home/username/.pyenv/versions/project-name/lib/python2.7/site-packages/pyramid/router.py", line 217, in invoke_subrequest
    response = handle_request(request)
  File "/home/username/.pyenv/versions/project-name/lib/python2.7/site-packages/nefertari/tweens.py", line 21, in timing
    return handler(request)
  File "/home/username/.pyenv/versions/project-name/lib/python2.7/site-packages/nefertari/tweens.py", line 52, in get_tunneling
    return handler(request)
  File "/home/username/.pyenv/versions/project-name/lib/python2.7/site-packages/nefertari/tweens.py", line 101, in cache_control
    response = handler(request)
  File "/home/username/.pyenv/versions/project-name/lib/python2.7/site-packages/pyramid/tweens.py", line 46, in excview_tween
    response = view_callable(exc, request)
  File "/home/username/.pyenv/versions/project-name/lib/python2.7/site-packages/pyramid/config/views.py", line 385, in viewresult_to_response
    result = view(context, request)
  File "/home/username/.pyenv/versions/project-name/lib/python2.7/site-packages/nefertari/view.py", line 375, in key_error_view
    return JHTTPBadRequest("Bad or missing param '%s'" % context.args[0])
  File "/home/username/.pyenv/versions/project-name/lib/python2.7/site-packages/nefertari/json_httpexceptions.py", line 78, in __init__
    create_json_response(self, **kw)
  File "/home/username/.pyenv/versions/project-name/lib/python2.7/site-packages/nefertari/json_httpexceptions.py", line 58, in create_json_response
    msg += '\nSTACK BEGIN>>\n%s\nSTACK END<<' % add_stack()
  File "/home/username/.pyenv/versions/project-name/lib/python2.7/site-packages/nefertari/json_httpexceptions.py", line 26, in add_stack
    return ''.join(traceback.format_stack())

STACK END<<
2015-10-10 19:46:58,434 DEBUG [nefertari.tweens][Dummy-3] tweens.timing: POST (http://localhost:6543/api/contacts/1/emails) request took 0.0384120941162 seconds

Have been mashing face against keyboard for most of the day without success.

[adam-codeberg]

Did some debugging today.

Pyramid function invoke_subrequest in routes.py @LN185 is receiving the expected route instance "Request at 0x2db2490 POST http://localhost:6543/api/contacts/1/emails" but @LN217 "response = handle_request(request)" it returns a 400 response error.

I'm taking a wild guess, but looks like ramses isn't giving the pyramid router the parameters in the format it wants or something.

Worth highlighting, GETs work fine, but POSTs return 400. Maybe the ramses generator.py. I noticed a conditional statement there that cleans the URL for elastic search on POSTs.

[adam-codeberg]

Worked back to LN 162 in "response = view_callable(context, request)" in Pyramids router.py

The exception is behind there somewhere.

[jstoiko]

There is an issue with 2+ (or is it 3+) levels of nesting. This is something we need to work on in a future release. @postatum can you confirm if this is related to a story that's already in our backlog?

[adam-codeberg]

Spent some time yesterday trying to get my head around Ramses workflow. Probably only worked out 40% of it so far. Do you have any docs/notes hidden away that may help?

I'm stuck at the moment, the document dicts look fine. Can't work out why its its failing at the time of processing the _bulk_body as it tries to POST data to the table linked via foreign key.

A wild guess would be that its running the POST against the wrong table, but haven't found the object/variable used in _bulk_body that holds the target table data yet.

[postatum]

@adam-codeberg thanks for reporting the issue. I can confirm that with 2+ objects API nesting it may not work properly.

@jstoiko yes, we have a story related to this issue in our backlog.

[adam-codeberg]

Thanks @postatum any recommendations on which Module (Ramses, Nefertari, Nefertari-SQL) I should focus my efforts in looking at to dig up the cause?

[postatum]

@adam-codeberg to get a meaningful traceback of what is happening, comment this line https://github.com/brandicted/ramses/blob/master/ramses/__init__.py#L21.

When nefertari.view is included, it registers error views, which wrap all errors in JSON responses. Unfortunately for those hacking Ramses this also hides useful tracebacks from console.

[adam-codeberg]

@postatum Thanks for the info, appreciated!

Haven't had much luck solving this one. Hopefully you have more luck than I did.

[adam-codeberg]

@postatum in an effort to narrow down the problem. Has Nefertari + Nefertari_SQL been proven able to manage nested /collection/item/collections? If so I can focus on Ramses. If not then I can focus on Nefertari + _SQL.

[postatum]

hey @adam-codeberg

Has Nefertari + Nefertari_SQL been proven able to manage nested /collection/item/collections?

Nefertari contains of building blocks and it doesn't have any default implementation of DB collections/items fetching(except BaseView.get_collection_es). It is possible to register nested collections using Nefertari, but the views which will implement the logic of getting collection/item will have to be implemented by target project developer. So right now it will be developers' responsibility to make sure Book objects returned by shop/{id}/books belong to Shop with Id=1.

I think the issue here is in Ramses since Ramses implements views. I remember working on nested collection/item GET requests but I didn't have a chance to look into making it work with all requests.

[adam-codeberg]

@postatum thanks so much for the information. That will be a great help. No guarantees I will find the cause, just hope to improve my chances :)

[postatum]

Thanks for help @adam-codeberg :) Feel free to ask if you have more questions.

[adam-codeberg]

I spent some time checking out views.py in Ramses today.

One thing I noticed was that in https://github.com/brandicted/ramses/blob/master/ramses/views.py#L447 "model_cls._nesting_depth" always returns 1

Side note nesting counter appears to start at 1 not 0

"parent_resource.uid" in https://github.com/brandicted/ramses/blob/master/ramses/generators.py#L61 seems to check out and returns the correct relationship.

Was wondering if "model_cls._nesting_depth" is used in an iteration somewhere when applying database changes to a resource. If ramses is failing to iterate to the next resource and uses the same resource twice, it would explain why nefertari cant find contacts_id.

Reference RAML example https://github.com/adam-codeberg/ramses-templates/tree/master/addressbook

Haven't found an iteration of this type yet, I'm looking around to see how "model_cls._nesting_depth" is used in ramses.

[postatum]

@adam-codeberg model_cls._nesting_depth is only used when returning JSON response. It is used in nefertari and nefertari-sqla/mongodb I think.

To see how nested GETs work now you may want to look into get_collection[_es] and get_item[_es] methods of ramses views.

[adam-codeberg]

@postatum I should mention that GETs are working fine with the nested RAML example.

Its POST that is broken.

It succeeds up until towards the end of the POST process. This is where it tries to apply the one to many relationship key to the parent table in postgresql. It fails to find the field "contacts_id". From what I can see/guess, it can't find the "contacts_id" table because it hasn't switched its focus from the child table (emails) to the parent table (contacts). Alternatively the focused table may be None or something.

[adam-codeberg]

@postatum I've exported the ramses request when model.save is invoked, you can check it out here https://www.diffchecker.com/9xe65ywz

If you ignore the different memory references, there's not much difference between them except for matchdict{} so im guessing that matchdict{} is malformed or not being processed correctly.

Let me know if you have any suggestions.

[postatum]

@adam-codeberg please post full error traceback here (with commented include(nefertari.view) when you POST

[adam-codeberg]

@postatum sure, here it is (working/unnested : broken/nested) https://www.diffchecker.com/nvnvobkw

[postatum]

@adam-codeberg I meant a traceback with this line commented https://github.com/brandicted/ramses/blob/master/ramses/__init__.py#L21 Thanks :)

[adam-codeberg]

@postatum yes, sorry about that. Have commented it out and reposted the link https://www.diffchecker.com/nvnvobkw

Forgot about doing that. Its really nice to see the queries instead of digging through classes to get them :)

Looks like the problem is down with the transaction call to sqlalchemy. Maybe it doesn't like a variable its being given?

[postatum]

@adam-codeberg I think you should ipdb here https://github.com/brandicted/ramses/blob/master/ramses/views.py#L184 and look at obj to see if it's looks ok. You can also try saving it manually and/or committing transaction after it to find a place where it fails.

Actually, looks like this is ramses views / nefertari bug.

Part if your recent traceback:

File "/home/adam/.pyenv/versions/cb-software-licensing-system/lib/python2.7/site-packages/pyramid/renderers.py", line 428, in render_view
return self.render_to_response(response, system, request=request)
File "/home/adam/.pyenv/versions/cb-software-licensing-system/lib/python2.7/site-packages/pyramid/renderers.py", line 451, in render_to_response
result = self.render(value, system_values, request=request)
File "/home/adam/.pyenv/versions/cb-software-licensing-system/lib/python2.7/site-packages/pyramid/renderers.py", line 447, in render
result = renderer(value, system_values)
File "/home/adam/.pyenv/versions/cb-software-licensing-system/lib/python2.7/site-packages/nefertari/renderers.py", line 61, in __call__
value = self.run_after_calls(value, system)
File "/home/adam/.pyenv/versions/cb-software-licensing-system/lib/python2.7/site-packages/nefertari/renderers.py", line 160, in run_after_calls
value = call(**dict(request=request, result=value))
File "/home/adam/.pyenv/versions/cb-software-licensing-system/lib/python2.7/site-packages/nefertari/wrappers.py", line 319, in __call__
self._set_object_self(result)
File "/home/adam/.pyenv/versions/cb-software-licensing-system/lib/python2.7/site-packages/nefertari/wrappers.py", line 312, in _set_object_self
resource.uid, **{resource.id_name: obj_pk})

And then traceback goes to url dispatch of Pyramid.

Let me explain this in a few words:

1. Ramses view methods return objects which are then encoded into dicts and various modifiers applied to those dicts like privacy, adding some links and so on. Those "modifiers" are called "after/before calls" in nefertari or more often "wrappers". "Before" calls are called before view method call and "after" calls - after method call. "after" calls also receive view response. You can see default wrappers used here https://github.com/brandicted/nefertari/blob/master/nefertari/view.py#L241
2. To allow returning DB objects from view method instead of Pyramid Response, we have Pyramid renderers defined here https://github.com/brandicted/nefertari/blob/master/nefertari/renderers.py#L74 . They translate returned object into proper HTTP response.

As you can see, traceback goes through "renderers" and "wrappers". From this we assume that response was partially generated and went to "wrappers" where it failed on something related to urldispatch (check rest of full traceback).

[adam-codeberg]

Thanks, that's helpful, I was just exploring the before/after calls in _transactions. I will re-read what you said and drill down some more into it.

Something interesting i found was that, on a failure, TransactionManager.abort() is being called before commit() so something is raising the abort() function before that https://github.com/zopefoundation/transaction/blob/master/transaction/_manager.py#L76

[postatum]

so something is raising the abort()

May be flush(). We flush() transaction on some object actions.

[adam-codeberg]

Solution

Thanks @postatum, your info helped a lot in speeding up the process.

Since this is a nefertari problem I will create the ticket https://github.com/brandicted/nefertari/issues/121

Ok, worked it out now.

wrapper.py failing to provide Pyramid with the right **kwarg key See https://github.com/brandicted/nefertari/blob/master/nefertari/wrappers.py#L312

It hits this part of Pyramid and dies https://github.com/Pylons/pyramid/blob/master/pyramid/url.py#L279 because it cant find the route based on the params given to it. Pyramid needs a key:value in the **kwargs dict for the parent that its not being given. Once I change the wrappers.py line to

resource.uid, **{'contacts_id': 1, resource.id_name: obj_pk})

It works, have confirmed with the postgresql database.

Next step is to find a way to assign the key:value programatically.

[adam-codeberg]

Have completed a programmatic solution, can be found in my fork here https://github.com/adam-codeberg/nefertari/blob/master/nefertari/wrappers.py#L290