Fail2ban support

[matt335672]

This follows on from conversations with @MikoyChinese in #1946 and @hubeny in #1973. Both of these users want the IP address of a failed login logged for use with fail2ban, which seems to make sense to me.

The stumbling block I had with this, is that the client_ip string from g_write_ip_address() contains more than just an IP address, so just logging that may introduce a dependency on the form of the output from that function. It seems to make sense to me to just log the IP address, and mark the log message as being a potential external dependency with a comment.

This PR makes the following changes over two commits.

The first commit renames g_write_ip_address() as g_write_client_description() and changes all the member variables using this value from client_ip to connection_description. This makes maintainers less likely to trip over client_ip not being an IP address at all (which I've done myself in the past).

The second commit adds a function to extract the IP address from the connection description for places where an actual IP address is required. These are:-

1. Messages intended for fail2ban
2. A chunk of code in session.c where we can match sessions based in IP address if that's selected in the policy. This code isn't used by default. Interestingly, there's a bug in the original where it fails with IPv6 addresses.

There's a change to xrdp_client_info here (member rename), but AFAICT there's no impact on xorgxrdp.

@MikoyChinese, @hubeny - if any of you are in a position to test this, please do.

[matt335672]

Example output string from sesman. This is an IPV6 development build.

20210827-12:53:48] [INFO ] [scp_v0_process(scp_v0.c:167)] Username or password error for user: testuser from ::ffff:10.1.2.3

[metalefty]

BTW, is it possible to log port knocking to RDP port?

Port knocking I mean here is a little bit different from the common use. I meant just connecting to 3389/tcp and disconnecting quickly without sending any credentials.

[metalefty]

20210827-12:53:48] [INFO ] [scp_v0_process(scp_v0.c:167)] Username or password error for user: testuser from ::ffff:10.1.2.3

I'm fine with this log format but I'm also fine with a more machine-friendly format. Because the log is intended to be parsed by fail2ban, right?

For example:

[20210827-12:53:48] [INFO ] [scp_v0_process(scp_v0.c:167)] AUTHFAIL: time=$unixtime; username=%s; clientaddr=%s

[timriker]

These log entries should go out to syslog, right? So I don't think a datestamp is required. syslog will datestamp them. A short version would be nice. This should suffice as neither username nor address should contain spaces.

[Date] hostname xrdp[process id]: AUTHFAIL user=%s ip=%s

The message could come from xrdp, or sessman or wherever it's detected.
If username is going to be optional, it might make sense to put the ip=first.

These might warrant separate tickets, or perhaps there already are tickets:

It would be nice to only get the setup stuff like cert and cipher information on first startup, not for every connection:

Using default X.509 certificate: /etc/xrdp/cert.pem
Using default X.509 key file: /etc/xrdp/key.pem

It would be nice to log the username here:

[20211022-12:17:15] [INFO ] xrdp_wm_log_msg: login successful for display 10

or here:

[20211022-12:17:17] [INFO ] lib_mod_log_peer: xrdp_pid=2924488 connected to X11rdp_pid=2924505 X11rdp_uid= X11rdp_gid= client_ip= client_port=1053

The uid will suffice, but the username would be nice.

Thanks!

[matt335672]

Thanks @metalefty, @timriker

I've attempted to address the above with an additional commit.

Log message is now as follows. This is from a development build, so there's additional info on the function raising the error whoich wouldn't be in a production build:-

xrdp-sesman.log

[20211025-11:09:32] [INFO ] [scp_v0_process(scp_v0.c:167)] AUTHFAIL: user=testuser ip=::ffff:172.19.73.183 time=1635156572

syslog

Oct 25 11:09:32 xrdp-test xrdp-sesman[13319]: [INFO ] [scp_v0_process(scp_v0.c:167)] AUTHFAIL: user=testuser ip=::ffff:172.19.73.183 time=1635156572

I've added the UNIX time as @metalefty suggests. I take your @timriker that the message is timestamped, but that's in local time, whereas the timestamp is in UTC. My system is currently one hour ahead of UTC :-

$ date -d @1635156572
Mon 25 Oct 11:09:32 BST 2021

The cert connection stuff is left on every connection for the simple reason that if xrdp is running for days, the required information for the connection could be challenging to find.

I like the suggestion of adding the username to the log message for login success or failure as suggested. Since I'm there, I've also removed a display of 0, as this has proved to be confusing to user in the past

fail message (display and xrdp log)

[20211025-11:29:28] [INFO ] [add_string_to_logwindow(xrdp_wm.c:2057)] login failed for user testuser

success message (xrdp.log)

[20211025-11:32:09] [INFO ] [xrdp_wm_log_msg(xrdp_wm.c:2166)] xrdp_wm_log_msg: login successful for user testuser on display 11

@metalefty - I've looked into your port knocking issue. It can be done, but it would be logged in the xrdp.log rather than the sesman.log. Also, determining whether any data has been sent on the connection is going to need a few other changes. Maybe logging a total incoming PDU count could be useful information. What do you think?

[timriker]

Seems to me that if a user wants timezone info in their logs, they should add it in syslog and not configure every application to also log timestamps.

What error message is shown on dropped connections when no username has been sent?

[metalefty]

If you want to rely on Syslog timestamp, you can do that. Simply ignore the timestamp.

I think the UNIX timestamp is easier to convert sometimes. The timestamp is for development / debug purposes.

[matt335672]

The UNIX time is also consistent between systems which is important if you're trying to work out exactly when something happened to your network, and you don't have centralised logging. Also, but less importantly, for one hour each year, a local timestamp is ambiguous and cannot be used for this purpose.

@timriker - nothing that useful is logged at the moment if a connection is lost before the initial negotiation is completed. Here are the current messages geneated in the xrdp log for an unprivileged nmap port scan:-

[20211026-09:25:59] [INFO ] [g_sck_accept(os_calls.c:1384)] Socket 12: AF_INET6 connection received from ::ffff:aaa.bbb.ccc.ddd port 47314
[20211026-09:25:59] [INFO ] [xrdp_rdp_read_config(xrdp_rdp.c:225)] Using default X.509 certificate: /etc/xrdp/cert.pem
[20211026-09:25:59] [INFO ] [xrdp_rdp_read_config(xrdp_rdp.c:257)] Using default X.509 key file: /etc/xrdp/key.pem
[20211026-09:25:59] [ERROR] [libxrdp_force_read(libxrdp.c:135)] libxrdp_force_read: header read error
[20211026-09:25:59] [ERROR] [xrdp_iso_incoming(xrdp_iso.c:488)] [ITU-T X.224] Connection Sequence: CR-TPDU (Connection Request) failed
[20211026-09:25:59] [ERROR] [xrdp_sec_incoming(xrdp_sec.c:2769)] xrdp_sec_incoming: xrdp_iso_incoming failed
[20211026-09:25:59] [ERROR] [xrdp_rdp_incoming(xrdp_rdp.c:917)] xrdp_rdp_incoming: xrdp_sec_incoming failed
[20211026-09:25:59] [ERROR] [xrdp_process_main_loop(xrdp_process.c:302)] xrdp_process_main_loop: libxrdp_process_incoming failed
[20211026-09:25:59] [ERROR] [xrdp_iso_send(xrdp_iso.c:638)] xrdp_iso_send: trans_write_copy_s failed
[20211026-09:25:59] [ERROR] [xrdp_mcs_disconnect(xrdp_mcs.c:1422)] Sending [ITU T.125] DisconnectProviderUltimatum failed

[timriker]

The UNIX time is also consistent between systems which is important if you're trying to work out exactly when something happened to your network, and you don't have centralised logging. Also, but less importantly, for one hour each year, a local timestamp is ambiguous and cannot be used for this purpose.

The traditional syslog has these issues. Fortunately, this is easily remedied. As documented in rsyslog.conf for example, just comment out the indicated line to get output like this:

2021-10-26T10:46:38.267926-06:00 A-LE2009442 postfix/master[737]: terminating on signal 15
2021-10-26T10:46:39.270729-06:00 A-LE2009442 postfix/master[10551]: daemon started -- version 3.4.13, configuration /etc/postfix

Human readable, unambiguous AND more precise than a unix timestamp.

@timriker - nothing that useful is logged at the moment if a connection is lost before the initial negotiation is completed. Here are the current messages generated in the xrdp log for an unprivileged nmap port scan:-

It would be nice to have something logged at the same level as a login failure to indicate a dropped connection and the client IP. The client port might be useful in some cases.

Thanks!

[matt335672]

I don't think either of us is arguing that syslog can't be configured to do what you want. Provided, of course, that you've actually configured it to do so before the event. In which case you can simply ignore the timestamp provided in the message. It's hardly an expensive addition.

As regards the logging improvement, this could do with a bit more analysis as it's more work than it appears to be at first.

Surprisingly, the Microsoft client also drops the connection mid-way through a startup if it feels the need to prompt the user regarding a TLS certificate or similar. If the user is happy to proceed a new connection attempt is started. So we'd need to determine that as a special case as I'd certainly regard that as normal operation.

Another issue of course, is that this logging will only detect a rudimentary TCP port scan where the initial SYN-SYN-ACK handshake completes. More sophisticated scans cannot be detected at the application level at all. This nmap command produces no xrdp logging on my test system, nor would I be able to make it do so from within the application:-

sudo nmap -sS -p3389 xrdp-test.test.lan

I'll move this to a separate issue I think, and we can keep this PR focussed on the changes it currently contains.

[metalefty]

Is there anything to do on this?