At `CapQuantity`'s instantiation time the proxy's order is not yet
initialized, and so `CapQuantity` was checking against nil all the time.
This went unnoticed because the job's specs were not integration-level
tests and were stubbing way too many things.
While doing that we pass stock changes to the service but we
lazy-evaluate them. This way we don't fetch all this data from DB when
it might not be used due to an early return.
Also, this makes it possible to save the stock-related logic for later.
Finally, when changing things to rely on `#initialize_order`'s boolean
return value I noticed though, that we were evaluating
`proxy_order.order` too early. When instantiating the service object it
won't exist yet.
DEPRECATION WARNING: `#deliver` is deprecated and will be removed in Rails 5. Use `#deliver_now` to deliver immediately or `#deliver_later` to deliver through Active Job.
This will hopefully fix our bild. I believe that the underlying issue is
that the logger's test double gets leaked into other examples, as RSpec
tells when running `spec/jobs/` specs.
```
5) SubscriptionPlacementJob performing the job when unplaced proxy_orders exist processes placeable proxy_orders
Failure/Error: JobLogger.logger.info("Placing Order for Proxy Order #{proxy_order.id}")
#<InstanceDouble(Logger) (anonymous)> was originally created in one example but has leaked into another example and can no longer be used. rspec-mocks' doubles are designed to only last for one example, and you need to create a new one in each example you wish to use it for.
# ./app/jobs/subscription_placement_job.rb:31:in `place_order_for'
```
Read more: https://relishapp.com/rspec/rspec-mocks/v/3-4/docs/basics/scope#doubles-cannot-be-reused-in-another-example
For whatever reason the JobLogger keeps its `.logger` being stubbed
after this spec.
There's a bunch of logging bits we need to find out what happened in
`#5294`, the first of which is logging as we are used to for Rails
itself. Turns out we were already logging but the log lines weren't
displayed.
That's because workers have no access to the Rails logger unless we hack
things a bit in the config/initializer. If we want to keep DJ's logs in
a different file, which I think is good for debugging purposes, we need
to diverge from Rails.logger.
However, there's no access to Delayed::Worker.logger in custom job
classes either so there's no way other than mimicking that logger's format
if we want log lines to be consistent.
Now the current logs will see the light like:
```
2020-05-07T14:09:42+0000: [Worker(host:8dc5e7e6f434 pid:1)] Job SubscriptionPlacementJob (id=54) RUNNING
2020-05-07T14:09:42+0000: Placing Order for Proxy Order 1
2020-05-07T14:09:42+0000: Issue in Subscription Order 2: complete
2020-05-07T14:09:42+0000: Placing Order for Proxy Order 7
2020-05-07T14:09:42+0000: Issue in Subscription Order 3: complete
2020-05-07T14:09:43+0000: [Worker(host:8dc5e7e6f434 pid:1)] Job SubscriptionPlacementJob (id=54) COMPLETED after 0.3378
2020-05-07T14:09:43+0000: [Worker(host:8dc5e7e6f434 pid:1)] 1 jobs processed at 2.8054 j/s, 0 failed
```
We'll see if we need to format these messages differently to make them
more greppeable.
