Log command invocation

Use reflection to log the command we are about to execute, both in gitlab-shell and gitlab-sshd. Include the environment, which has all the context we need to understand what the command is expected to do.

Here's an example of the logs in context:

{"correlation_id":"01FHD242ZS3PHN090JVWRKYD9N","level":"info","msg":"server: handleConn: start","remote_addr":"127.0.0.1:49922","time":"2021-10-07T09:42:33Z"}
{"content_length_bytes":860,"correlation_id":"01FHD242ZS3PHN090JVWRKYD9N","duration_ms":139,"level":"info","method":"GET","msg":"Finished HTTP request","status":200,"time":"2021-10-07T09:42:33Z","url":"http://127.0.0.1:3000/api/v4/internal/authorized_keys?key=AAAAB3NzaC1yc2EAAAADAQABAAACAQCv0G42g7jwSGIsyJv1I7zXuEvxFIudvro7qdqLLh4FkstapNvisG7NfLhLNa7gfXJfGFjjexbC7hkSNyzu7MQnRUq%2FFE7z8geMNSigA5V91FnbjmGa%2FF5EeqbUEUflYh3evXFzmhvpvhWZRqvUJCKj%2FrbHTgK7iuu%2FIZpVSrizq6e2F0fadAYELN8wwjXne9kKcKCLMFrFSmCYRb25dUdB%2BWBDZNEBIwOn%2B1D59GZjjbaN8WKpJk185%2FhBGggKZ25DwYJIKBRWJo2NZ509%2FryR0Lvp1a5r7KljiNV0fbqlTm387Fv%2FpfWDjWjuocqKZhXgT%2BEx6DkPCTEFCds8ETNWHF4LHRR47CDgyQW3eclxlwhAbdic618TuV3wQHD7vzLCek20QMmHslXMwpbgXHdbKidOJQxbopphD6pwRUFRRDF41KrD%2BZ7idgUNMH1yv%2FmcHUB30396qYtzkz%2FHVXrP45qLWqqerNdDKJcmXAUsyOe%2Bqa0AI6Nk3sWbMR%2FIagd9j1DxYWt9vs8rO3evqgnvS2HU0%2BxFdvzKZYWAleRIKMQf3gTdXM0jscdY%2BNNXnDIhXzAwnUrZFCcA6BCbtcSno6PLW2cVKl2%2FsPyzjuP4lqQaxi2bky4D4jasI90PfCTFvEsza98Di6oU2Ri8WuoBIpo4BRMzyGIhF0mYDXAGgQ"}
{"channel_type":"session","correlation_id":"01FHD242ZS3PHN090JVWRKYD9N","level":"info","msg":"connection: handle: new channel requested","remote_addr":"127.0.0.1:49922","time":"2021-10-07T09:42:33Z"}
{"correlation_id":"01FHD242ZS3PHN090JVWRKYD9N","level":"debug","msg":"session: handle: entering request loop","time":"2021-10-07T09:42:33Z"}
{"bytesize":299,"correlation_id":"01FHD242ZS3PHN090JVWRKYD9N","level":"debug","msg":"session: handle: request received","time":"2021-10-07T09:42:33Z","type":"pty-req","want_reply":true}
{"bytesize":299,"correlation_id":"01FHD242ZS3PHN090JVWRKYD9N","level":"debug","msg":"session: handle: request processed","should_continue":true,"time":"2021-10-07T09:42:33Z","type":"pty-req","want_reply":true}
{"bytesize":23,"correlation_id":"01FHD242ZS3PHN090JVWRKYD9N","level":"debug","msg":"session: handle: request received","time":"2021-10-07T09:42:33Z","type":"env","want_reply":false}
{"accepted":false,"correlation_id":"01FHD242ZS3PHN090JVWRKYD9N","env_request":{"Name":"LANG","Value":"en_GB.UTF-8"},"level":"debug","msg":"session: handleEnv: processed","time":"2021-10-07T09:42:33Z"}
{"bytesize":23,"correlation_id":"01FHD242ZS3PHN090JVWRKYD9N","level":"debug","msg":"session: handle: request processed","should_continue":true,"time":"2021-10-07T09:42:33Z","type":"env","want_reply":false}
{"bytesize":0,"correlation_id":"01FHD242ZS3PHN090JVWRKYD9N","level":"debug","msg":"session: handle: request received","time":"2021-10-07T09:42:33Z","type":"shell","want_reply":true}
{"command":"*discover.Command","correlation_id":"01FHD242ZS3PHN090JVWRKYD9N","env":{"GitProtocolVersion":"","IsSSHConnection":true,"OriginalCommand":"","RemoteAddr":"127.0.0.1:49922"},"level":"info","msg":"session: handleShell: executing command","time":"2021-10-07T09:42:33Z"}
{"content_length_bytes":49,"correlation_id":"01FHD242ZS3PHN090JVWRKYD9N","duration_ms":128,"level":"info","method":"GET","msg":"Finished HTTP request","status":200,"time":"2021-10-07T09:42:33Z","url":"http://127.0.0.1:3000/api/v4/internal/discover?key_id=11"}
{"correlation_id":"01FHD242ZS3PHN090JVWRKYD9N","level":"info","msg":"session: handleShell: command executed successfully","time":"2021-10-07T09:42:33Z"}
{"correlation_id":"01FHD242ZS3PHN090JVWRKYD9N","exit_status":0,"level":"info","msg":"session: exit: exiting","time":"2021-10-07T09:42:33Z"}
{"bytesize":0,"correlation_id":"01FHD242ZS3PHN090JVWRKYD9N","level":"debug","msg":"session: handle: request processed","should_continue":false,"time":"2021-10-07T09:42:33Z","type":"shell","want_reply":true}
{"correlation_id":"01FHD242ZS3PHN090JVWRKYD9N","level":"debug","msg":"session: handle: exiting request loop","time":"2021-10-07T09:42:33Z"}
{"correlation_id":"01FHD242ZS3PHN090JVWRKYD9N","level":"info","msg":"connection: handle: done","remote_addr":"127.0.0.1:49922","time":"2021-10-07T09:42:33Z"}
{"correlation_id":"01FHD242ZS3PHN090JVWRKYD9N","level":"info","msg":"server: handleConn: done","remote_addr":"127.0.0.1:49922","time":"2021-10-07T09:42:33Z"}

We can see how the discover API call is now contextualised.

Related to #499 (closed)