There's no way we can create an order_cycle_schedules if the schedule
doesn't have an id, which we can't get if to persist it we need an OC
first, which in turn, will create an order_cycle_schedules.
Rails 4 introduced "automagically" modified cache keys, that included a digest in the key on any cache entry related to views. This is not what we want at all, fixed here with the `skip_digest: true` option.
Mocking these objects is working differently in Rails 4, and utilising `#and_call_original` helped to ensure different parts of the codebase were receiving the correct response objects (AR relations, etc).
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.
