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.
Here the displayed properties that we're testing also rely on shops data (including the list of supplied properties), which is now cached for 15 seconds. We clear that cache entry so we can cleanly test only the caching of the properties AMS array.
