exp/services/recoverysigner: add basic logs

[leighmcculloch]

PR Checklist

PR Structure

• This PR has reasonably narrow scope (if not, break it down into smaller PRs).
• This PR avoids mixing refactoring changes with feature changes (split into two PRs
  otherwise).
• This PR's title starts with name of package that is most changed in the PR, ex.
  services/friendbot, or all or doc if the changes are broad or impact many
  packages.

Thoroughness

• This PR adds tests for the most critical parts of the new functionality or fixes.
• I've updated any docs (developer docs, .md
  files, etc... affected by this change). Take a look in the docs folder for a given service,
  like this one.

Release planning

• I've updated the relevant CHANGELOG (here for Horizon) if
  needed with deprecations, added features, breaking changes, and DB schema changes.
• I've decided if this PR requires a new major/minor version according to
  semver, or if it's mainly a patch change. The PR is targeted at the next
  release branch if it's not a patch change.

What

Add basic logs for each action the service can perform that describe what's happening to help with identifying issues. Also fixes logs so that all existing logs carry the request ID and account ID for the current request.

Why

This is a young service and we're likely to run into issues that we will need logs to help us debug.

Close #2358

Known limitations

1. The logs don't give visibility into exactly which authentication methods have been validated which seems like a pretty important thing to log to me. That's going to take a bit of work to add because the application code doesn't interact with the database identifiers for each authentication method and so I need to do some refactoring to add that.

2. The logs might be a little verbose for a service that runs at scale, but I think in the early days this will help and we can always pare the logs back once we identify which are useful.

Examples

These are some examples of what the logs look like:

Registering a new account

INFO[2020-05-07T13:43:42.385-07:00] starting request                              host="localhost:8001" ip="127.0.0.1:52854" method=POST path=/accounts/GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 pid=47458 req=devenv-0/Ec2Vvw7LV3-000003 subsys=http
INFO[2020-05-07T13:43:42.386-07:00] Request to register account.                  account=GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 pid=47458 req=devenv-0/Ec2Vvw7LV3-000003
INFO[2020-05-07T13:43:42.386-07:00] Request validation failed.                    account=GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 pid=47458 req=devenv-0/Ec2Vvw7LV3-000003
INFO[2020-05-07T13:43:42.386-07:00] finished request                              bytes=53 duration=1.1468ms method=POST path=/accounts/GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 pid=47458 req=devenv-0/Ec2Vvw7LV3-000003 status=400 subsys=http

INFO[2020-05-07T13:44:27.443-07:00] starting request                              host="localhost:8001" ip="127.0.0.1:52856" method=POST path=/accounts/GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 pid=47458 req=devenv-0/Ec2Vvw7LV3-000004 subsys=http
INFO[2020-05-07T13:44:27.443-07:00] Request to register account.                  account=GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 pid=47458 req=devenv-0/Ec2Vvw7LV3-000004
INFO[2020-05-07T13:44:27.461-07:00] Account registered.                           account=GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 auth_methods_count=1 identities_count=1 pid=47458 req=devenv-0/Ec2Vvw7LV3-000004
INFO[2020-05-07T13:44:27.461-07:00] finished request                              bytes=201 duration=18.3943ms method=POST path=/accounts/GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 pid=47458 req=devenv-0/Ec2Vvw7LV3-000004 status=200 subsys=http

Getting an account

INFO[2020-05-07T13:47:14.236-07:00] starting request                              host="localhost:8001" ip="127.0.0.1:52866" method=GET path=/accounts/GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 pid=47458 req=devenv-0/Ec2Vvw7LV3-000006 subsys=http                                                                                                                                                    INFO[2020-05-07T13:47:14.236-07:00] Request to get account.                       account=GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 pid=47458 req=devenv-0/Ec2Vvw7LV3-000006
INFO[2020-05-07T13:47:14.238-07:00] Authorized with self: false.                  account=GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 pid=47458 req=devenv-0/Ec2Vvw7LV3-000006
INFO[2020-05-07T13:47:14.238-07:00] Authorized with stellar_address.              account=GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 pid=47458 req=devenv-0/Ec2Vvw7LV3-000006
INFO[2020-05-07T13:47:14.238-07:00] Authorized: true.                             account=GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 pid=47458 req=devenv-0/Ec2Vvw7LV3-000006
INFO[2020-05-07T13:47:14.238-07:00] Getting account.                              account=GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 pid=47458 req=devenv-0/Ec2Vvw7LV3-000006
INFO[2020-05-07T13:47:14.238-07:00] finished request                              bytes=230 duration=2.1827ms method=GET path=/accounts/GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 pid=47458 req=devenv-0/Ec2Vvw7LV3-000006 status=200 subsys=http

Signing a transaction

INFO[2020-05-07T13:54:12.637-07:00] starting request                              host="localhost:8001" ip="127.0.0.1:52902" method=POST path=/accounts/GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7/sign pid=53075 req=devenv-0/9Kzzm4wGyN-000004 subsys=http
INFO[2020-05-07T13:54:12.637-07:00] Request to sign transaction.                  account=GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 pid=53075 req=devenv-0/9Kzzm4wGyN-000004
INFO[2020-05-07T13:54:12.640-07:00] Authorized with self: false.                  account=GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 pid=53075 req=devenv-0/9Kzzm4wGyN-000004
INFO[2020-05-07T13:54:12.640-07:00] Authorized with stellar_address.              account=GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 pid=53075 req=devenv-0/9Kzzm4wGyN-000004
INFO[2020-05-07T13:54:12.640-07:00] Authorized: true.                             account=GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 pid=53075 req=devenv-0/9Kzzm4wGyN-000004
INFO[2020-05-07T13:54:12.641-07:00] Signing transaction.                          account=GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 pid=53075 req=devenv-0/9Kzzm4wGyN-000004 transaction_hash=e4bf5d3d7bda23091b1691ee429f0384606c918d12b80d873dd7a74c4a04e605
INFO[2020-05-07T13:54:12.641-07:00] Transaction signed.                           account=GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7 pid=53075 req=devenv-0/9Kzzm4wGyN-000004 transaction_hash=e4bf5d3d7bda23091b1691ee429f0384606c918d12b80d873dd7a74c4a04e605
INFO[2020-05-07T13:54:12.641-07:00] finished request                              bytes=242 duration=3.837ms method=POST path=/accounts/GAOGUZ55OPA2M5LMU6TMC5H546XFRMAJB3JS6IFVQ4QMGDAKI3VL5QF7/sign pid=53075 req=devenv-0/9Kzzm4wGyN-000004 status=200 subsys=http

[howardtw]

LGTM though it contains a little bit of refactoring.

I wonder whether logging Authorized: true. when a request pass authorization check at all endpoint is too redundant given that it should be clear that the request passes the auth before we serve it.