Create order blows up, unclear condition

[fosterlynn]

Received this trace.

More 4 of 22 [NRP]ERROR (internal IP): Internal Server Error: /accounting/create-order/ Inbox x mailer@nrp.webfactional.com

Jun 30 (4 days ago)

to bob.haugen, me Traceback (most recent call last):

File "/home/nrp/webapps/django/lib/python2.7/django/core/handlers/base.py", line 109, in get_response response = callback(request, _callback_args, *_callback_kwargs)

File "/home/nrp/webapps/django/lib/python2.7/django/contrib/auth/decorators.py", line 20, in _wrapped_view return view_func(request, _args, *_kwargs)

File "/home/nrp/webapps/django/valuenetwork/valuenetwork/valueaccounting/views.py", line 3150, in create_order transfer_date=commit.commitment_date,

UnboundLocalError: local variable 'commit' referenced before assignment

<WSGIRequest path:/accounting/create-order/, GET:<QueryDict: {}>, POST:<QueryDict: {u'due_date': [u'2016-07-01'], u'description': [u'Dani me pidi\xf3 un asado'], u'provider': [u''], u'submit1': [u''], u'exchange_type': [u'2'], u'receiver': [u'6'], u'csrfmiddlewaretoken': [u'hiqMvSQ3NnFhOwEQRj9aSHWhxEQLKNIB']}>, COOKIES:{'csrftoken': 'hiqMvSQ3NnFhOwEQRj9aSHWhxEQLKNIB', 'sessionid': 'fa94e07f50de3d309b2da5474c5d5280'}, META:{'CONTENT_LENGTH': '158', 'CONTENT_TYPE': 'application/x-www-form-urlencoded', 'CSRF_COOKIE': 'hiqMvSQ3NnFhOwEQRj9aSHWhxEQLKNIB', 'DOCUMENT_ROOT': '/usr/local/apache2/htdocs', 'GATEWAY_INTERFACE': 'CGI/1.1', 'HTTPACCEPT': 'text/html,application/xhtml+xml,application/xml;q=0.9,/_;q=0.8', 'HTTP_ACCEPT_ENCODING': 'gzip, deflate', 'HTTP_ACCEPT_LANGUAGE': 'en-US,en;q=0.5', 'HTTP_CONNECTION': 'close', 'HTTP_COOKIE': 'csrftoken=hiqMvSQ3NnFhOwEQRj9aSHWhxEQLKNIB; sessionid=fa94e07f50de3d309b2da5474c5d5280', 'HTTP_DNT': '1', 'HTTP_FORWARDED_REQUEST_URI': '/accounting/create-order/', 'HTTP_HOST': 'nrp.webfactional.com', 'HTTP_HTTPS': 'off', 'HTTP_HTTP_X_FORWARDED_PROTO': 'http', 'HTTP_REFERER': 'http://nrp.webfactional.com/accounting/create-order/', 'HTTP_USER_AGENT': 'Mozilla/5.0 (Windows NT 6.3; WOW64; rv:47.0) Gecko/20100101 Firefox/47.0', 'HTTP_X_FORWARDED_FOR': '190.230.130.47', 'HTTP_X_FORWARDED_HOST': 'nrp.webfactional.com', 'HTTP_X_FORWARDED_PROTO': 'http', 'HTTP_X_FORWARDED_SERVER': 'nrp.webfactional.com', 'HTTP_X_FORWARDED_SSL': 'off', 'PATH_INFO': u'/accounting/create-order/', 'PATH_TRANSLATED': '/home/nrp/webapps/django/valuenetwork/valuenetwork/wsgi.py/accounting/create-order/', 'QUERY_STRING': '', 'REMOTE_ADDR': '127.0.0.1', 'REMOTE_PORT': '49866', 'REQUEST_METHOD': 'POST', 'REQUEST_URI': '/accounting/create-order/', 'SCRIPT_FILENAME': '/home/nrp/webapps/django/valuenetwork/valuenetwork/wsgi.py', 'SCRIPT_NAME': u'', 'SERVER_ADDR': '127.0.0.1', 'SERVER_ADMIN': '[no address given]', 'SERVER_NAME': 'nrp.webfactional.com', 'SERVER_PORT': '80', 'SERVER_PROTOCOL': 'HTTP/1.0', 'SERVER_SIGNATURE': '', 'SERVER_SOFTWARE': 'Apache/2.2.25 (Unix) mod_wsgi/3.5 Python/2.7.11', 'mod_wsgi.application_group': 'web396.webfaction.com|', 'mod_wsgi.callable_object': 'application', 'mod_wsgi.enable_sendfile': '0', 'mod_wsgi.handler_script': '', 'mod_wsgi.input_chunked': '0', 'mod_wsgi.listener_host': '', 'mod_wsgi.listener_port': '14931', 'mod_wsgi.process_group': 'django', 'mod_wsgi.queue_start': '1467322767125636', 'mod_wsgi.request_handler': 'wsgi-script', 'mod_wsgi.script_reloading': '1', 'mod_wsgi.version': (3, 5), 'wsgi.errors': <mod_wsgi.Log object at 0x7fa20a604b30>, 'wsgi.file_wrapper': <built-in method file_wrapper of mod_wsgi.Adapter object at 0x7fa20a71acd8>, 'wsgi.input': <mod_wsgi.Input object at 0x7fa20a613bf0>, 'wsgi.multiprocess': True, 'wsgi.multithread': True, 'wsgi.run_once': False, 'wsgi.url_scheme': 'http', 'wsgi.version': (1, 0)}>

[sqykly]

valuenetwork/valueaccounting/views.py line 3123

oi_commitments = Commitment.objects.filter(order=order)

line 3128

for commit in oi_commitments:

commit is never assigned again. Thus, if there is no Commitment in the DB whose order is the order obtained in line 3068:

order = order_form.save(commit=False)

(that looks a lot like a brand new order is being generated from the form; how is the DB supposed to have commitments for it already?)

then, commit remains None. The intended behavior here is not totally clear to me yet; either commit is not the right variable for initializing cr_xfer.transfer_date, or Commitments.objects.filter(order=order) is intended as never being empty.

Even if the case is the latter, I want to add an assignment to commit after the for loop so no one else has to deal with this when I screw it up myself. But my money is on the former, as there are a bunch of more appropriately scoped variables floating around here that are also Commitments, and many of them have comments about refactorings where they are assigned.

Once that is done, the next explosion will be due to rec_tt.name on line 3149:

name=rec_tt.name + " from " + order.receiver.nick,

(this is a keyword argument initializing the exact same Transfer object as the last bug)

Someone has treated rec_tt rather ambivalently. Line 3143:

rec_tts = exchange.exchange_type.transfer_types_reciprocal()
rec_tt = None
if rec_tts:
    rec_tt = rec_tts[0]

I want to assume that exchange.exchange_type.transfer_types_reciprocal shouldn't turn up empty, but it must have, or we wouldn't see the dancing around assigning to rec_tt.

[bhaugen]

@sqykly that's good detective work! What brings you to do this digging? What sparked your interest? Nobody's worked on this version of this software for more than a year. But there are a couple of forks including one that is looking for developers.

[fosterlynn]

@sqykly thanks!

Or are you connected with Sensorica? They are running this instance.

[sqykly]

I am indeed delighted to be working on this for Sensorica. It's good to know that you both have the time and enthusiasm to respond to issues here, but since I intend to do a lot more digging in the days to come, would you prefer that Sensorica or I fork the project? Otherwise, God willing, I will be blowing up your inbox with digs like this, pull requests, etc.

Also, any input about these two issues? If you haven't been in this code for years and you still know what these variables are supposed to be, I will be very, very impressed. How about a guess at what the "cr" in cr_xfer and cr_commit stands for? Newly created, which they both are as the final steps of the create_order method? The commitment reciprocal, which would explain why line 3143 is accessing exchange.transfer_types.transfer_types_reciprocal and calling things rec_tt and rec_tts?

[bhaugen]

If you're working on this code for Sensorica, I am happy to respond to issues and questions. Or probably anyway. This is the repo that their production system is updated from. And we are not working on it anymore. Whether you fork the repo or not is your choice, but if you want to get your changes into production, you would need to deal with their server. Maybe send an email to the Sensorica google group and we can discuss server updates via email.

THere are a couple of other forks with lots of changes that are in use in other projects, and I have worked on one of them some recently, so I can still understand the code. Will look at your questions and see if I can answer them later today.

[bhaugen]

@sqykly I haven't been able to get to this one today. Need to reproduce it before I give any advice. Nobody in Sensorica ever used that view as far as I can tell. We used to have a regression test for it, but the view broke during some other changes and I think we never fixed it and I disabled the test. If you want to fix it, I'll get some test data and see what it will take. Shouldn't be too bad. But you might also ask Sensorica if anybody cares.

[sqykly]

My understanding of the vision for this version of the NRP is that there will be a lot of new users fumbling about making all manner of neophyte mistakes, typing nonsense into the urls, visiting the site with netscape navigator, browsing from their phone underwater - you know, new user stuff. So it needs to be very fault tolerant, which means I'd rather have no unhandled exceptions anywhere ever, lest we be left with half-formed db entries and all.

My inclination is to see if we can get rid of the view altogether. If it's both potentially problematic and never used, better to put it down.

[bhaugen]

My inclination is to see if we can get rid of the view altogether. If it's both potentially problematic and never used, better to put it down.

That's a Sensorica decision. @TiberiusB ? Think you will ever use customer orders?

If not, the safest thing to do would be to remove the means of access to the feature so it could more easily be restored if plans change.

[sqykly]

Upon closer inspection, the oi_commitments are all added at order.add_customer_order_item on line 3089. This can be prevented in several ways:

• none of the item_forms is valid
• there are no item_forms (probably can't happen)
• none of the item_forms has a non-zero quantity (maybe that makes them invalid anyway, but that will mess it up too)

I'm pretty confident now that this can be fixed by invalidating the order form when there are no valid, non-zero quantity item forms. Fixing.

[sqykly]

Still a bunch of problems there; Sensorica/VerdunNRP now has additional code that will prevent the exception so that my diagnostic functions can figure out what's going on.

[sqykly]

Also if you have free time, right below oi_commitments = Commitment.objects.filter(order=order), there are two parts that create transfers, and I think I'm missing something about the logic.

We get tts = exchange.exchange_type.transfer_types_non_reciprocal() (types, plural) then we only use the first with tt = tts[0]. Apart from definitely crashing if tts is empty anyway despite the if tts:, why are we only making commitments for one transfer type, and why are we sure that [0] is the right one to use if exchange types can have as many transfer types as they want?

Then, further down, we get rec_tt in the same way, as exchange.exchange_type.transfer_types_reciprocal()[0] (more or less), and I have exactly the same questions about that: why just one, and why pick [0]?

[bhaugen]

We don't have any free time today. Maybe tomorrow. But you are working through some code that I wrote way long time ago when Sensorica thought they would get customer orders but nobody knew quite what they wanted. So in that case, I just do the simplest thing that could possibly work and see what happens when people try to use it. That will sometimes leave gaping holes for you as the follow-on maintainer, and I will do my best to help in these cases.

@sqykly Can we do a screenshare maybe some time tomorrow and try to figure this out? If so, suggest some times by email?

[sqykly]

I'm still feeling optimistic that I'll fix this one today. But maybe.

[fosterlynn]

Don't have time right now to look in detail, but something I added later was that the customer order will create a Sale exchange with transfers, and keep the reference back and forth. The code you are talking about sounds like it is part of that.

On Thu, May 17, 2018 at 12:13 PM, sqykly notifications@github.com wrote:

I'm still feeling optimistic that I'll fix this one today. But maybe.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/valnet/valuenetwork/issues/510#issuecomment-389941328, or mute the thread https://github.com/notifications/unsubscribe-auth/ADmeUQmuH8zhJGv3wOEB_yrmKcAFQ_iNks5tza-cgaJpZM4JEmif .

[sqykly]

Not related to the crash exactly, but in case there are issues with orders elsewhere, it looks like the order goes un-exploded in this version. Regardless of the order details, including the empty order (no item with non-zero quantity), any Order produced by the view function produces precisely one Commitment that reprs to <Commitment: receives 1.00 today> (with today being today's date).

[sqykly]

That commitment is for the parent RT, its exchange type is Sale, it has the right Order, its event type is obviously Receive

[sqykly]

Nevermind, I just cracked it. Sorry to bother you both.

[bhaugen]

How did you crack it?

[bhaugen]

But @sqykly if you are getting into order explosions, that is the guts, the deep logic, of economic networks. You are a brave soul. More than you may want to know.

[sqykly]

This explanation is going to run a little long because it took me all day yesterday, so there's a TL;DR at the bottom.

I was tipped off by a combination of factors. First, I wrote additional tests to narrow it down and applied them to all of the post-request DB in each of the failing tests:

• Did any commitments get created? Yes
• Were any of the commitments related to the expected resource type? Yes, every time
• Are all the associations we need to connect the RT and its commitments hooked up right?
  • Were the right event types associated with commitments? Yes, always
  • Can the expected resource type find its own producing process types? It sure can
  • Is there an order, and is it associated with the existing commitments? Yep
  • Is there any Sale exchange in the system? Sure is
  • Are there any commitments using the Sale exchange type? Absolutely
• If everything checks out, but the commitments expected just weren't there, what commitments did get created? Just the one, same every time, as I mentioned before

Then I realized that every test that didn't use the view function passed, explosions and all. So I stared at the view function and every other function it called for a long time tracing each commitment created there through layers of object associations to see what was missing. You were not kidding that this is the deep guts! Luckily, I didn't end up needing to sort through it all.

Though it took longer than I will admit, I circled back and asked what the exactly one commitment meant. Worse, how could it be that the very same commitment was present even in the case I built to test my fix to this exact problem, months ago, which is an order with all of its items having a quantity of 0. The view function has three blocks that generate commitments. One is related to features, which are totally unused, so forget that. One was in a per-item loop with several conditionals, so it could occur any number of times, but the only way the other block could be skipped, I found, is if the function threw an exception between the two blocks, wasn't a POST request, or didn't like its form validity. If it wasn't a POST or it didn't like the form validity, the function couldn't possibly produce any commitments. There was no exception, so that last block must have made the one commitment. Since there was only one, the per-item block must have never produced any. Both blocks are contained in:

if not order_form.is_valid():
    raise UsersFaultError()
elif (iform for iform in item_forms if ifrom.is_valid()):
    # the order form came back valid if we didn't throw
    # at least one item form came back valid if the tuple was populated to enter this block

The per-item loop is further wrapped in:

for form in item_forms:
    # ...
    if form.is_valid(): # this has to happen at least once, or we couldn't get here
        # ...
        qty = form.cleaned_data['quantity']
        if qty:
            # ... here is where we call order.add_order_item to make commitments ...

Now, my fix for #510 was to add 2 things. First, the elif that makes a tuple to make sure there is at least one valid item form, the other being validators=[MinValueValidator(0.01)] in the forms.OrderItemForm.quantity field. But, in the view function, we can see that the order form and at least one order item form report .is_valid() as true in order to produce any commitments, but none of the order item forms could have had both .is_valid() true and .cleaned_data['quantity'] non-zero, or more than one commitment would have been produced.

That makes perfectly fine sense for a variety of scenarios that could make one or all item forms appear to be valid even after the test set them all to 0 quantity. But I also know that none of the item forms reported their quantity as non-zero when the tests unambiguously set the corresponding fields to non-zero numbers, or the innermost if would have let them create their own commitments. I know setting the value of a form field unsuccessfully in WebTest will throw an exception because I spent the previous day getting them, so obviously the fields as described by the test code are showing up in the HTML rendering, but the order item form object in the view function did not end up with that data. That leaves very few conclusions:

TL;DR forms.OrderItemForm sucks.

[bhaugen]

Thanks for the detailed explanation!

TL;DR: you are indeed a brave soul! @sqykly where are you working? What repo and branch? I'd like to look at your fix in context?

[sqykly]

Or, it could be my method of checking all the order item forms is wrong. Ha! There are no tuple-producing expressions like that, only list displays. My bad.

Sensorica/VerdunNRP. Not totally up to date. Gimme a sec and I'll make a commit.

[sqykly]

(why didn't that throw a SyntaxError?!?!?)

[sqykly]

Alright this just became a head-scratcher again. Now the #510 fix works perfectly, but all of the tests that should be creating commitments are dying - though by design. The exceptions in the view function were thrown in to separate problems with the form (always ValidationError) from problems in the DB (always RuntimeError). In this case the order form is fine, but none of the order item forms are is_valid(). Maybe I was right about both problems?

[bhaugen]

Uh-oh, back to the drawing board.

all of the tests that should be creating commitments are dying - though by design.

Like this? https://github.com/Sensorica/VerdunNRP/commit/d20c2695d5487074f6093685ff58d96d40a181f1

Or some other tests?

[sqykly]

Nah. All the internals are fine. I was right both times after all. The list comprehension did need to be fixed, but beyond that, the ID fields have their values disappearing, so the OrderItemForm doesn't know what it's supposed to be looking at. I think.

[bhaugen]

Hmmm, did I create that tuple trying to be a list comprehension? Oooops...but how did it ever work? Or did it ever work?

[sqykly]

That wasn't you; I added it brand new to make sure at least one of the item forms was valid. I have no idea how it didn't cause some kind of error. Outside of a list display expression, foo for foo in bar if foo.baz doesn't make any sense. The only thing I can think of is that it figured I wanted a list, so it made a list, then saw the () and thought I wanted a tuple whose only element is a list? That would rank up there with (old-school non-strict ES5) JavaScript in terms of automagically fixing things so they break later instead of when it would be helpful. The standard is pretty specific about displays needing [] around them, too.

Update: it looks like my original analysis is more or less accurate in all the ways I can test. The rendered HTML form has values for all the important fields such as resource_type_id and quantity, the POST data has them too, OrderItemForm just doesn't bind to the POST data right. I'm thinking these need to go in a formset and let Django figure out how to tell them apart. Does that make sense to you?

[bhaugen]

I'm tied up for the rest of today. Will look at it in the morning.

[bhaugen]

@sqykly

I'm thinking these need to go in a formset and let Django figure out how to tell them apart. Does that make sense to you?

I can't remember why I did not use a formset there. Certainly did in a lot of other places.

However, I just ran create_order in the FairCoop fork and it worked, at least for this order. See code here: https://github.com/FreedomCoop/valuenetwork/blob/master/valuenetwork/valueaccounting/views.py#L3023

The forms appeared to bind via the form.prefix matching the prefix of the POST data. Stupid test data, but here's the order schedule:

[bhaugen]

@sqykly note: I don't know if you can use that code as-is, the FairCoop fork is Django<2, while VerdunNRP is still Django==1.4.22

[sqykly]

If I ever say "Let Django figure it out" again, punch me.

But #510 is now officially licked over at VerdunNRP. I'm down to 2 tests failing (from 4), neither of which is the crash described here. If you're interested, this is what pops out of them:

FAIL: test_create_workflow_order (valuenetwork.valueaccounting.tests.test_orders.OrderTest) Test create_order for a workflow item

Traceback (most recent call last): File "/home/valnet/webapps/verdunnrp/VerdunNRP/valuenetwork/valueaccounting/tests/test_orders.py", line 336, in test_create_workflow_order pcs = self.get_commitment_fault(self.changeable, self.changeable.producing_commitments()) File "/home/valnet/webapps/verdunnrp/VerdunNRP/valuenetwork/valueaccounting/tests/test_orders.py", line 212, in get_commitment_fault self.assertTrue(False, msg='It was something else; commitments produced: %s' % (Commitment.objects.all(),)) AssertionError: It was something else; commitments produced: [<Commitment: make child consumes 6000.00 grandchild 2018-05-11>, <Commitment: make child produces 2000.00 child 2018-05-21>, <Commitment: Seller Give 2000.00 child 2018-05-21 from Unassigned>, <Commitment: receives 1.00 2018-05-21>]

FAIL: test_two_workflow_item_order (valuenetwork.valueaccounting.tests.test_orders.OrderTest) Test create_order for two workflow items

Traceback (most recent call last): File "/home/valnet/webapps/verdunnrp/VerdunNRP/valuenetwork/valueaccounting/tests/test_orders.py", line 380, in test_two_workflow_item_order pcs = self.get_commitment_fault(self.changeable, self.changeable.producing_commitments()) File "/home/valnet/webapps/verdunnrp/VerdunNRP/valuenetwork/valueaccounting/tests/test_orders.py", line 212, in get_commitment_fault self.assertTrue(False, msg='It was something else; commitments produced: %s' % (Commitment.objects.all(),)) AssertionError: It was something else; commitments produced: [<Commitment: make child consumes 6000.00 grandchild 2018-05-11>, <Commitment: make child produces 2000.00 child 2018-05-21>, <Commitment: Seller Give 4000.00 grandchild 2018-05-21 from Unassigned>, <Commitment: Seller Give 2000.00 child 2018-05-21 from Unassigned>, <Commitment: receives 1.00 2018-05-21>]

Those are lists of all commitments produced by the test scenario. The only way for the get_commitment_fault function to throw anything is to give it an empty set of commitments, so in those tests, self.changeable.producing_commitments() is empty. The "it was something else" refers to the list of possible faults I mentioned above; none of those things were wrong.

Since it's not technically related to #510 anymore, I'll keep any further commentary over at Sensorica/VerdunNRP #10