Better user tracking in the logs

[jovandeginste]

I have a few thoughts/requests, I can make separate issues if you think that would be better.

a) It would be great to be able to identify connecting users from the logs by the fingerprint and the comment (the last part) of the public key. Now we only see the user name.

b) I only see the user name when the user does actions. Is the user not authenticated earlier?

c) I think the logs should use the connection_id to be able to trace connections/actions.

d) Somtimes paths are quoted in the logs, sometimes not; this should obviously be consistent :-)
"requested list/stat" entries are not quoted
"fileread requested" is quoted

What I see now:

{"level":"debug","sender":"sftpd","time":"2019-09-05T10:03.56.827","message":"accepted inbound connection, ip: 10.10.10.1:4727"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:03.56.829","message":"connection added, num open connections: 1"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:03.58.496","message":"requested list file for dir: /var/ftp/myuser user: myuser"} 
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.01.497","message":"requested stat for file: /var/ftp/myuser/in user: myuser"} 
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.02.910","message":"requested list file for dir: /var/ftp/myuser/in user: myuser"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.05.315","message":"requested stat for file: /var/ftp/myuser/in/somefile.xlsx user: myuser"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.11.706","message":"fileread requested for path: \"/var/ftp/myuser/in/somefile.xlsx\", user: myuser"}
{"level":"info","sender":"Download","elapsed_ms":57,"size_bytes":704072,"username":"myuser","file_path":"/var/ftp/myuser/in/somefile.xlsx","connection_id":            
"77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","protocol":"SFTP","time":"2019-09-05T10:04.11.763"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.13.278","message":"connection closed, id: 8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.13.279","message":"connection removed, num open connections: 0"}

What I expect to see (more or less):

{"level":"debug","sender":"sftpd","time":"2019-09-05T10:03.56.827","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","message":"accepted inbound connection, ip: 10.10.10.1:4727"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:03.56.829","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","message":"connection added, num open connections: 1"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:03.56.829","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","message":"user authenticated with public key \"jo@desktop\" fingerprint:SHA256:FV3+wlAKGzYy7+J02786fh8N8c06+jga/mdiSOSPT7g"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:03.58.496","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","message":"requested list file for dir: \"/var/ftp/myuser\" user: myuser"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.01.497","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","message":"requested stat for file: \"/var/ftp/myuser/in\" user: myuser"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.02.910","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","message":"requested list file for dir: \"/var/ftp/myuser/in\" user: myuser"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.05.315","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","message":"requested stat for file: \"/var/ftp/myuser/in/somefile.xlsx\" user: myuser"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.11.706","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","message":"fileread requested for path: \"/var/ftp/myuser/in/somefile.xlsx\", user: myuser"}
{"level":"info","sender":"Download","elapsed_ms":57,"size_bytes":704072,"username":"myuser","file_path":"/var/ftp/myuser/in/somefile.xlsx","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","protocol":"SFTP","time":"2019-09-05T10:04.11.763"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.13.278","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","message":"connection closed"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.13.279","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","message":"connection removed, num open connections: 0"}

[drakkan]

I have a few thoughts/requests, I can make separate issues if you think that would be better.

thanks for the suggestions, I'll try to improve the logs

a) It would be great to be able to identify connecting users from the logs by the fingerprint and the comment (the last part) of the public key. Now we only see the user name.

ok

b) I only see the user name when the user does actions. Is the user not authenticated earlier?

I'm a bit busy now and maybe I'm missing something, can you better explain with an example what do you would like to see here? If we add the connection_id in every sftp log maybe the username is not so useful anymore, we can log the username, public keys info and connection_id when the user login, after that if every log contains connection_id you can easily identify the user. Username can be an additional info contained in the generic message log fields.

c) I think the logs should use the connection_id to be able to trace connections/actions.

ok, I'll try to add the connection id where applicable

d) Somtimes paths are quoted in the logs, sometimes not; this should obviously be consistent :-)
"requested list/stat" entries are not quoted
"fileread requested" is quoted

ok

What I see now:

{"level":"debug","sender":"sftpd","time":"2019-09-05T10:03.56.827","message":"accepted inbound connection, ip: 10.10.10.1:4727"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:03.56.829","message":"connection added, num open connections: 1"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:03.58.496","message":"requested list file for dir: /var/ftp/myuser user: myuser"} 
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.01.497","message":"requested stat for file: /var/ftp/myuser/in user: myuser"} 
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.02.910","message":"requested list file for dir: /var/ftp/myuser/in user: myuser"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.05.315","message":"requested stat for file: /var/ftp/myuser/in/somefile.xlsx user: myuser"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.11.706","message":"fileread requested for path: \"/var/ftp/myuser/in/somefile.xlsx\", user: myuser"}
{"level":"info","sender":"Download","elapsed_ms":57,"size_bytes":704072,"username":"myuser","file_path":"/var/ftp/myuser/in/somefile.xlsx","connection_id":            
"77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","protocol":"SFTP","time":"2019-09-05T10:04.11.763"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.13.278","message":"connection closed, id: 8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.13.279","message":"connection removed, num open connections: 0"}

What I expect to see (more or less):

{"level":"debug","sender":"sftpd","time":"2019-09-05T10:03.56.827","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","message":"accepted inbound connection, ip: 10.10.10.1:4727"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:03.56.829","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","message":"connection added, num open connections: 1"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:03.56.829","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","message":"user authenticated with public key \"jo@desktop\" fingerprint:SHA256:FV3+wlAKGzYy7+J02786fh8N8c06+jga/mdiSOSPT7g"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:03.58.496","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","message":"requested list file for dir: \"/var/ftp/myuser\" user: myuser"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.01.497","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","message":"requested stat for file: \"/var/ftp/myuser/in\" user: myuser"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.02.910","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","message":"requested list file for dir: \"/var/ftp/myuser/in\" user: myuser"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.05.315","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","message":"requested stat for file: \"/var/ftp/myuser/in/somefile.xlsx\" user: myuser"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.11.706","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","message":"fileread requested for path: \"/var/ftp/myuser/in/somefile.xlsx\", user: myuser"}
{"level":"info","sender":"Download","elapsed_ms":57,"size_bytes":704072,"username":"myuser","file_path":"/var/ftp/myuser/in/somefile.xlsx","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","protocol":"SFTP","time":"2019-09-05T10:04.11.763"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.13.278","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","message":"connection closed"}
{"level":"debug","sender":"sftpd","time":"2019-09-05T10:04.13.279","connection_id":"8a329a9d77c9b078117ddc27b61654d50ed54b372f41b14ae6155c42bfe30985","message":"connection removed, num open connections: 0"}

[jovandeginste]

@drakkan I think you got what I meant: the connection_id is relevant in every logline, the exact username and other info (public key info eg.) only when the user authenticates. What I meant is that I don't know the sftp protocol, so not sure if the user authenticates for every request, or ...

But your suggestion sounds perfect.

[drakkan]

ok thanks,

for your info the user authenticate only once, so for example if you change the password or the public keys the change will be valid only for the new logged in users.

Initially I wanted to disconnect the logged in users if their auth info were updated using the REST API and or update their connection info (such as quota ecc..) but this is not so easy to do the right way and other servers apply the new info only for new logins too

[jovandeginste]

I think I addressed b, c & d in PR's now; I may look at a tomorrow, unless you beat me to it

[jovandeginste]

However, I'm thinking of also including the username everywhere as a separate field too ... Just for easy grepping. What do you think?

[drakkan]

Basically we are adding more context to the generic loggers and their are becoming more similar to specialized loggers such as TransferLog or CommandLog

https://github.com/drakkan/sftpgo/blob/master/logger/logger.go#L102

I initially added these specialized loggers to allow to extract/parse the more relevant info in an easy way, while the generic loggers were used to log info useful to debug the daemon operations but not so useful to generate/extract a report of the user's activities. The same concept apply to the HTTP logs:

https://github.com/drakkan/sftpgo/blob/master/logger/request_logger.go#L56

Maybe we can add more context to important logs, for example the error ones adding a new log category or adding additional fields to the exisisting ones.

But maybe we are creating a monster :)

[jovandeginste]

I was thinking of adding a pointer to the connection (instead of the connection id), and if the pointer is not nil, adding some relevant info to the log lines.

[drakkan]

I'm not sure that this will work, the logger package is imported everywhere, if you import the sftpd package inside the logger you will probaly introduce a circular dependency

[binou-31]

If you want an IT guys's opinion who work daily with this use case,
Connection_ID or Session_ID or whatever name is, it's just useful information and mandatory to follow clients connections and troubleshoot issues, for the end user support.
I think the Connection_ID should be present in the log from the beginning of the connection with the client until the end of it

Include username everywhere is useless because this Connection_ID does the job.
But this have make me think about an other feature.
It will be very great if we can include metrics about connections, download/upload speed, users, transfer duration, state and others useful metrics for exploitation and support, deliver in JSON with the API in the GO HTTP server, we could effectively monitor the activity of the product with prometheus for example.

[jovandeginste]

@drakkan you are right:

import cycle not allowed
package github.com/drakkan/sftpgo
	imports github.com/drakkan/sftpgo/cmd
	imports github.com/drakkan/sftpgo/api
	imports github.com/drakkan/sftpgo/dataprovider
	imports github.com/drakkan/sftpgo/logger
	imports github.com/drakkan/sftpgo/sftpd
	imports github.com/drakkan/sftpgo/dataprovider
import cycle not allowed
package github.com/drakkan/sftpgo
	imports github.com/drakkan/sftpgo/cmd
	imports github.com/drakkan/sftpgo/api
	imports github.com/drakkan/sftpgo/dataprovider
	imports github.com/drakkan/sftpgo/logger
	imports github.com/drakkan/sftpgo/sftpd
	imports github.com/drakkan/sftpgo/logger

[jovandeginste]

@binou-31 the connection id is required for granular tracing of connections in my opinion, but the username is useful for simple greps without having to do extra lookups... that's a sysadmin's opinion ;) but I'd be happy with the connection id and a log entry stating the user info (which is mostly ready)

[jovandeginste]

I think I implemented (a) too now (see PR #43)

[drakkan]

is there still something missing here?

[jovandeginste]

I don't think anything is missing. I'll close this then.