tg123/sshpiper

Include pipe name (username?) in upstream connection logs

vholer opened this issue · 3 comments

vholer commented

When connection is being created to upstream server, it would be helpful to have there a selected pipe or downstream connection username in the logs at least on info/error log levels. Otherwise (in Kubernetes jungle) it's hard to track what user is trying to connect and where.

E.g.,

  • valid connection
time="2023-01-05T10:18:00Z" level=debug msg="connection accepted: 10.244.0.1:1604"
time="2023-01-05T10:18:00Z" level=debug msg="next auth methods [publickey]"
time="2023-01-05T10:18:00Z" level=debug msg="downstream 10.244.0.1:1604 is sending public key auth"
time="2023-01-05T10:18:00Z" level=debug msg="connecting to upstream 10.105.229.224:22 with auth [privatekey]"
time="2023-01-05T10:18:00Z" level=info msg="ssh connection pipe created 10.244.0.1:1604 -> 10.105.229.224:22"
time="2023-01-05T10:18:00Z" level=info msg="connection from 10.244.0.1:1604 closed reason: ssh: disconnect, reason 11: disconnected by user"-
  • broken upstream server
time="2023-01-05T10:32:44Z" level=debug msg="connection accepted: 10.244.0.1:9488"
time="2023-01-05T10:32:44Z" level=debug msg="next auth methods [publickey]"
time="2023-01-05T10:32:44Z" level=debug msg="downstream 10.244.0.1:9488 is sending public key auth"
time="2023-01-05T10:32:44Z" level=error msg="cannot create upstream for 10.244.0.1:9488 with public key auth: dial tcp 10.106.114.46:22: connect: connection refused"
time="2023-01-05T10:32:44Z" level=debug msg="next auth methods [publickey]"
time="2023-01-05T10:32:44Z" level=debug msg="connection from 10.244.0.1:9488 establishing failed reason: [ssh: no auth passed yet, dial tcp 10.106.114.46:22: connect: connection refused]"

i.e., we see above only from/to IP addresses.

On the contrary, in case of failed downstream connection (with invalid SSH key or invalid user), this information is already provided on error level:

time="2023-01-05T10:13:30Z" level=error msg="cannot create upstream for 10.244.0.1:25935 with public key auth: rpc error: code = Unknown desc = no matching pipe for username [app1] found"
tg123 commented

added, any suggestion?
logs can be found in e2e section
https://github.com/tg123/sshpiper/actions/runs/3846222972/jobs/6551275314

vholer commented

By greping the logs on (username [,

  • DEBU[0001] next auth methods [password publickey] for downstream 127.0.0.1:60370 (username []) ... logs no username. Probably before very first method is tried, you don't know the username yet? Not sure if it's known for next methods?

Focusing just on logs above on non-debug levels:

  • Valid connection is not covered, would it be possible to log pipe/username here?

    sshpiper/cmd/sshpiperd/daemon.go

    Line 147 in adc5949

    log.Infof("ssh connection pipe created %v -> %v", p.DownstreamConnMeta().RemoteAddr(), p.UpstreamConnMeta().RemoteAddr().String())

  • Upstream server connection problem is now OK.

Thank you!

tg123 commented
  • correct, username is not available when handshake init
  • added to daemon.go