Various logging improvements in the apiserver

[mjs]

This change contains a bunch of small improvements to the logs generated by API connections and logins. These are all things that have been annoying me for a long time. The goal was to remove unnecessary noise, use more appropriate log levels and provide more useful information.

The logs for a typical client API connection and request now look like:

15:10:58 DEBUG juju.apiserver [C] API connection from [fdc1:e6b1:6aac:99f5::1]:49268
15:10:58 DEBUG juju.apiserver <- [C]  {"request-id":1,"type":"Admin","version":3,"request":"Login","params":"'params redacted'"}
15:10:58 DEBUG juju.apiserver model login: user admin has "superuser" for controller; "admin" for model 0022f951-cdc1-4825-89c9-65401a79fcaf
15:10:58 DEBUG juju.apiserver -> [C]  24.159374ms {"request-id":1,"response":"'body redacted'"} Admin[""].Login
15:10:58 DEBUG juju.apiserver <- [C] user-admin {"request-id":2,"type":"Client","version":1,"request":"FullStatus","params":"'params redacted'"}
15:10:58 DEBUG juju.apiserver.client Applications: map[]
15:10:58 DEBUG juju.apiserver -> [C] user-admin 5.778893ms {"request-id":2,"response":"'body redacted'"} Client[""].FullStatus
15:10:58 DEBUG juju.rpc error closing codec: write tcp [fdc1:e6b1:6aac:99f5:216:3eff:fef4:29a5]:17070->[fdc1:e6b1:6aac:99f5::1]:49268: write: broken pipe
15:10:58 DEBUG juju.apiserver [C] user-admin API connection terminated after 33.984974ms

The start of an agent connection now looks like:

15:06:26 DEBUG juju.apiserver [4] API connection from 127.0.0.1:36982
15:06:26 DEBUG juju.apiserver <- [4]  {"request-id":1,"type":"Admin","version":3,"request":"Login","params":"'params redacted'"}
15:06:26 DEBUG juju.apiserver model login: machine-0 for 84d520ed-b406-48b3-8381-66600e37200a
15:06:26 DEBUG juju.apiserver -> [4]  39.275183ms {"request-id":1,"response":"'body redacted'"} Admin[""].Login
15:06:26 DEBUG juju.apiserver <- [4] machine-0 {"request-id":2,"type":"Agent","version":2,"request":"GetEntities","params":"'params redacted'"}
15:06:26 DEBUG juju.apiserver -> [4] machine-0 409.488µs {"request-id":2,"response":"'body redacted'"} Agent[""].GetEntities

---

rpc: Reduce codec close error log level

It's quite common for close of the codec to return a "broken pipe"
error. It happens for even API request from the client because the
client typically closing the connection after making a single API
request. There is no need to include these at INFO every time.

---

apiserver/observer: Reduce API conn log levels

The start and end of every API connection was being logged at INFO. This
is not generally useful to the average user and is strange when view
logs at INFO because all you see is "API connection from ... ", followed
by "API connection terminated..." with nothing in between.

These messages have been lowered to DEBUG so that they're at the same
level as the other API handling log output.

---

apiserver: Stop logging host ports

For some reason we are logging the API server host ports as part of
every login. This isn't useful and just adds noise to the logs.

---

apiserver: Rearrange login logs

Removed logging during model validation/state lookup in favour of more
dense log lines post Login. This results in one less log line for user
logins and more informative log lines for all login types.

---

apiserver: Removed debuglog handler log output

It's not terribly important to know that this handler has started.

QA

Examined API server logs to see expected, improved log output.

[mjs]

$$merge$$

[jujubot]

Status: merge request accepted. Url: http://juju-ci.vapour.ws:8080/job/github-merge-juju