Use log/slog for logging

[stevapple]

This is the first of a series of more aggressive (i.e. most likely breaking) changes to sshmux to make it more extensive. log/slog is a structured logging library introduced in Go 1.21, and the previous usage of LogChannel is a static case for structural logging. Migrating to log/slog will allow us to log with more precise control over different contexts, without the burden of managing a struct for each case.

For this specific pitch, all behavioral changes are addictive, and has been verified by local testing.

$ socat UDP-LISTEN:5556 STDOUT
{"time":"2024-08-16T16:34:29.643656851+08:00","level":"INFO","msg":"SSH proxy session","connect_time":1723797269,"remote_ip":"127.0.0.1:46362","client_type":"SSH","username":"yrchen","host_ip":"127.0.0.1:2333","authenticated":true,"disconnect_time":1723797269}
{"time":"2024-08-16T16:34:29.936682302+08:00","level":"INFO","msg":"SSH proxy session","connect_time":1723797269,"remote_ip":"127.0.0.22:43741","client_type":"SSH","username":"yrchen","host_ip":"127.0.0.1:2333","authenticated":true,"disconnect_time":1723797269}
{"time":"2024-08-16T16:34:30.240921622+08:00","level":"INFO","msg":"SSH proxy session","connect_time":1723797270,"remote_ip":"127.0.0.1:46370","client_type":"SSH","username":"yrchen","host_ip":"127.0.0.1:2332","authenticated":true,"disconnect_time":1723797270}
{"time":"2024-08-16T16:34:30.550123375+08:00","level":"INFO","msg":"SSH proxy session","connect_time":1723797270,"remote_ip":"127.0.0.22:54985","client_type":"SSH","username":"yrchen","host_ip":"127.0.0.1:2332","authenticated":true,"disconnect_time":1723797270}

Follow-up for this pitch including integrating OpenTelemetry Logging support via OpenTelemetry SLog Log Bridge.

[stevapple]

@iBug Any thoughts? I didn’t know how Vlab infrastructure handles the log so I’m trying to keep it semantically identical based on JSON specifications.

If possible we should eliminate such workarounds eventually.

[iBug]

how Vlab infrastructure handles the log

We have a ~30-line Python listener that receives these JSON-over-UDP packets and writes them to a MySQL database so that we have connection statistics when we need them. This is certainly room for improvement, such as writing them to a text file and let Python (or another log-to-DB program) follow it with inotify.

You have the freedom of designing the new output method and format, as long as it's reasonably easy to parse and follow real-time.

[iBug]

I just pushed a small patch 6b75357 that changed a few fields of LogMessage so it's actually working (it didn't until now). I hope this isn't too hard to integrates.

Also, extra fields that log/slog generate by default don't interfere. The Python script explicitly picks desired keys for insertion into the DB. Here's the snippet:

def parse_log(msg_json):
    remote_ip = msg_json['remote_ip']
    host_ip = msg_json['host_ip']
    client_type = msg_json['client_type']
    authenticated = msg_json['authenticated']
    username = msg_json['username']
    if client_type == "SSH":
        # Drop username as it's not student ID for SSH
        username = ""
    connect_timestamp = msg_json['connect_time']
    disconnect_timestamp = msg_json['disconnect_time']
    connect_time = datetime.datetime.fromtimestamp(connect_timestamp).strftime('%Y-%m-%d %H:%M:%S')
    disconnect_time = datetime.datetime.fromtimestamp(disconnect_timestamp).strftime('%Y-%m-%d %H:%M:%S')
    return (remote_ip, host_ip, client_type, authenticated, username, connect_time, disconnect_time)

For the database column types, authenticated is tinyint(1) (i.e. boolean), both times are datetime and the rest are all varchar, with an id bigint auto_increment.

These are just for reference and I'll handle the Python part myself.

[stevapple]

Would you mind if we send the (dis)connection time in a String like this:

2024-08-16T16:28:54.151946098+08:00

[stevapple]

Would you mind if we send the (dis)connection time in a String like this:

2024-08-16T16:28:54.151946098+08:00

Delayed for the OpenTelemetry update… I would like to do a whole refresh, including changes to keys that should be absolutely breaking.

[iBug]

Would you mind

See #8 (comment):

You have the freedom of designing the new output method and format, as long as it's reasonably easy to parse and follow real-time.

My recommendation is do whatever you find suitable for now. I'll review the new format before merging or deploying, and then discuss if there is any inconvenience for us.

[stevapple]

Get it. I would still tend to avoid breaking changes for a smooth upgrade experience. All these compatibility codes shall be safely removed when we reached a point (seemingly v0.1).

This PR is ready in its current state. The logging part is of lower priority for me than authentication so further improvements shall be done after other parts are settled.

[stevapple]

Ping @iBug