From 0b73c4636d38f0c69424721d52d0e7752db99c81 Mon Sep 17 00:00:00 2001 From: vthiebaut10 <81188381+vthiebaut10@users.noreply.github.com> Date: Fri, 11 Jun 2021 19:56:04 -0400 Subject: [PATCH] Allow non-admin user processes to log message to ETW / log file (#513) --- contrib/win32/openssh/OpenSSHTestHelper.psm1 | 20 +- contrib/win32/win32compat/inc/unistd.h | 2 + contrib/win32/win32compat/w32-doexec.c | 9 + contrib/win32/win32compat/w32log.c | 52 +++- monitor.c | 41 +++- monitor.h | 4 +- monitor_wrap.c | 13 + .../AuthorizedKeysCommand.Tests.ps1 | 3 + .../Authorized_keys_fileperm.Tests.ps1 | 9 + regress/pesterTests/CertAuth.Tests.ps1 | 2 + .../pesterTests/FileBasedLogging.tests.ps1 | 225 ++++++++++++++++++ regress/pesterTests/SSHDConfig.tests.ps1 | 13 +- sftp-server.c | 53 ++++- sshd.c | 35 ++- 14 files changed, 462 insertions(+), 19 deletions(-) create mode 100644 regress/pesterTests/FileBasedLogging.tests.ps1 diff --git a/contrib/win32/openssh/OpenSSHTestHelper.psm1 b/contrib/win32/openssh/OpenSSHTestHelper.psm1 index b6009cdf7..6687e7f88 100644 --- a/contrib/win32/openssh/OpenSSHTestHelper.psm1 +++ b/contrib/win32/openssh/OpenSSHTestHelper.psm1 @@ -13,8 +13,10 @@ $TestSetupLogFileName = "TestSetupLog.txt" $SSOUser = "sshtest_ssouser" $PubKeyUser = "sshtest_pubkeyuser" $PasswdUser = "sshtest_passwduser" +$AdminUser = "sshtest_adminuser" +$NonAdminUser = "sshtest_nonadminuser" $OpenSSHTestAccountsPassword = "P@ssw0rd_1" -$OpenSSHTestAccounts = $Script:SSOUser, $Script:PubKeyUser, $Script:PasswdUser +$OpenSSHTestAccounts = $Script:SSOUser, $Script:PubKeyUser, $Script:PasswdUser, $Script:AdminUser, $Script:NonAdminUser $SSHDTestSvcName = "sshdTestSvc" $Script:TestDataPath = "$env:SystemDrive\OpenSSHTests" @@ -65,8 +67,11 @@ function Set-OpenSSHTestEnvironment $Global:OpenSSHTestInfo.Add("SSOUser", $SSOUser) # test user with single sign on capability $Global:OpenSSHTestInfo.Add("PubKeyUser", $PubKeyUser) # test user to be used with explicit key for key auth $Global:OpenSSHTestInfo.Add("PasswdUser", $PasswdUser) # test user to be used for password auth + $Global:OpenSSHTestInfo.Add("AdminUser", $AdminUser) # test user to be used for admin logging tests + $Global:OpenSSHTestInfo.Add("NonAdminUser", $NonAdminUser) # test user to be used for non-admin logging tests $Global:OpenSSHTestInfo.Add("TestAccountPW", $OpenSSHTestAccountsPassword) # common password for all test accounts $Global:OpenSSHTestInfo.Add("DebugMode", $DebugMode.IsPresent) # run openssh E2E in debug mode + $Global:OpenSSHTestInfo.Add("DelayTime", 3) # delay between stoppig sshd service and trying to access log files $Script:EnableAppVerifier = -not ($NoAppVerifier.IsPresent) if($Script:WindowsInBox = $true) @@ -209,7 +214,18 @@ WARNING: Following changes will be made to OpenSSH configuration #setup single sign on for ssouser $ssouserProfile = Get-LocalUserProfile -User $SSOUser $Global:OpenSSHTestInfo.Add("SSOUserProfile", $ssouserProfile) - $Global:OpenSSHTestInfo.Add("PubKeyUserProfile", (Get-LocalUserProfile -User $PubKeyUser)) + + $PubKeyUserProfile = Get-LocalUserProfile -User $PubKeyUser + $Global:OpenSSHTestInfo.Add("PubKeyUserProfile", $PubKeyUserProfile) + + $AdminUserProfile = Get-LocalUserProfile -User $AdminUser + $Global:OpenSSHTestInfo.Add("AdminUserProfile", $AdminUserProfile) + + $NonAdminUserProfile = Get-LocalUserProfile -User $NonAdminUser + $Global:OpenSSHTestInfo.Add("NonAdminUserProfile", $NonAdminUserProfile) + + #make $AdminUser admin + net localgroup Administrators $AdminUser /add New-Item -ItemType Directory -Path (Join-Path $ssouserProfile .ssh) -Force -ErrorAction SilentlyContinue | out-null $authorizedKeyPath = Join-Path $ssouserProfile .ssh\authorized_keys diff --git a/contrib/win32/win32compat/inc/unistd.h b/contrib/win32/win32compat/inc/unistd.h index edcad7239..85d9a6c24 100644 --- a/contrib/win32/win32compat/inc/unistd.h +++ b/contrib/win32/win32compat/inc/unistd.h @@ -13,6 +13,8 @@ #define STDOUT_FILENO 1 #define STDERR_FILENO 2 +#define SFTP_SERVER_LOG_FD STDERR_FILENO+1 + int w32_ftruncate(int, off_t); #define ftruncate(a, b) w32_ftruncate((a), (b)) diff --git a/contrib/win32/win32compat/w32-doexec.c b/contrib/win32/win32compat/w32-doexec.c index 25bf2a2a0..e3a94de74 100644 --- a/contrib/win32/win32compat/w32-doexec.c +++ b/contrib/win32/win32compat/w32-doexec.c @@ -401,6 +401,15 @@ int do_exec_windows(struct ssh *ssh, Session *s, const char *command, int pty) { error("posix_spawn initialization failed"); goto cleanup; } + + //Passing the PRIVSEP_LOG_FD (STDERR_FILENO + 2) to sftp-server for logging + if(strstr(exec_command, "sftp-server.exe")) + if (posix_spawn_file_actions_adddup2(&actions, STDERR_FILENO + 2, SFTP_SERVER_LOG_FD) != 0) { + errno = EOTHER; + error("posix_spawn initialization failed"); + goto cleanup; + } + if (posix_spawn(&pid, spawn_argv[0], &actions, NULL, spawn_argv, NULL) != 0) { errno = EOTHER; error("posix_spawn: %s", strerror(errno)); diff --git a/contrib/win32/win32compat/w32log.c b/contrib/win32/win32compat/w32log.c index 93ef08213..b8cf3f9f7 100644 --- a/contrib/win32/win32compat/w32log.c +++ b/contrib/win32/win32compat/w32log.c @@ -40,6 +40,7 @@ #define MSGBUFSIZ 1024 static int logfd = -1; +static int sftp_server_logfd = -1; const char* identity = NULL; int log_facility = 0; @@ -92,11 +93,15 @@ done: void openlog_file() { - if (logfd != -1) + if (strcmp(identity, "sftp-server") == 0 && sftp_server_logfd != -1) return; + if (strcmp(identity, "sftp-server") != 0 && logfd != -1) + return; + wchar_t *logs_dir = L"\\logs\\"; wchar_t module_path[PATH_MAX] = { 0 }, log_file[PATH_MAX + 12] = { 0 }; + wchar_t* tmp_identity = NULL; if (GetModuleFileNameW(NULL, module_path, PATH_MAX) == 0) return; @@ -113,18 +118,37 @@ openlog_file() wchar_t ssh_cfg_path[PATH_MAX] = {0 ,}; wcscat_s(ssh_cfg_path, _countof(ssh_cfg_path), __wprogdata); /* "%programData%" */ wcscat_s(ssh_cfg_path, _countof(ssh_cfg_path), L"\\ssh"); /* "%programData%\\ssh" */ + if (strcmp(identity, "sftp-server") == 0) { + tmp_identity = utf8_to_utf16(identity); + if (!tmp_identity) + goto cleanup; + } + else { + tmp_identity = malloc(wcslen(tail) * sizeof(wchar_t)); + if (!tmp_identity) + goto cleanup; + if (wcsncpy_s(tmp_identity, wcslen(tail), tail + 1, wcslen(tail) - 5) != 0) { + goto cleanup; + } + } if ((wcsncat_s(log_file, PATH_MAX + 12, ssh_cfg_path, wcslen(ssh_cfg_path)) != 0) || (wcsncat_s(log_file, PATH_MAX + 12, logs_dir, 6) != 0) || - (wcsncat_s(log_file, PATH_MAX + 12, tail + 1, wcslen(tail + 1) - 3) != 0 ) || - (wcsncat_s(log_file, PATH_MAX + 12, L"log", 3) != 0)) - return; + (wcsncat_s(log_file, PATH_MAX + 12, tmp_identity, wcslen(tmp_identity)) != 0) || + (wcsncat_s(log_file, PATH_MAX + 12, L".log", 4) != 0)) + goto cleanup; } - errno_t err = _wsopen_s(&logfd, log_file, O_WRONLY | O_CREAT | O_APPEND, SH_DENYNO, S_IREAD | S_IWRITE); - - if (logfd != -1) - SetHandleInformation((HANDLE)_get_osfhandle(logfd), HANDLE_FLAG_INHERIT, 0); + int* fd_ptr = &logfd; + + if (strcmp(identity, "sftp-server") == 0) + fd_ptr = &sftp_server_logfd; + + errno_t err = _wsopen_s(fd_ptr, log_file, O_WRONLY | O_CREAT | O_APPEND, SH_DENYNO, S_IREAD | S_IWRITE); + +cleanup: + if (tmp_identity) + free(tmp_identity); } void @@ -133,8 +157,14 @@ syslog_file(int priority, const char *format, const char *formatBuffer) char msgbufTimestamp[MSGBUFSIZ]; SYSTEMTIME st; int r; + int msg_fd; + + if (strcmp(identity, "sftp-server") == 0) + msg_fd = sftp_server_logfd; + else + msg_fd = logfd; - if (logfd == -1) + if (msg_fd == -1) return; GetLocalTime(&st); @@ -142,11 +172,11 @@ syslog_file(int priority, const char *format, const char *formatBuffer) GetCurrentProcessId(), st.wYear, st.wMonth, st.wDay, st.wHour, st.wMinute, st.wSecond, st.wMilliseconds, formatBuffer); if (r == -1) { - _write(logfd, "_snprintf_s failed.", 20); + _write(msg_fd, "_snprintf_s failed.", 20); return; } msgbufTimestamp[strnlen(msgbufTimestamp, MSGBUFSIZ)] = '\0'; - _write(logfd, msgbufTimestamp, (unsigned int)strnlen(msgbufTimestamp, MSGBUFSIZ)); + _write(msg_fd, msgbufTimestamp, (unsigned int)strnlen(msgbufTimestamp, MSGBUFSIZ)); } void diff --git a/monitor.c b/monitor.c index e7f64981a..e8b8185a4 100644 --- a/monitor.c +++ b/monitor.c @@ -449,15 +449,44 @@ monitor_read_log(struct monitor *pmonitor) fatal_fr(r, "reserve msg"); if (atomicio(read, pmonitor->m_log_recvfd, p, len) != len) fatal_f("log fd read: %s", strerror(errno)); + if ((r = sshbuf_get_u32(logmsg, &level)) != 0 || (r = sshbuf_get_u32(logmsg, &forced)) != 0 || (r = sshbuf_get_cstring(logmsg, &msg, NULL)) != 0) fatal_fr(r, "parse"); - - /* Log it */ + if (log_level_name(level) == NULL) fatal_f("invalid log level %u (corrupted message?)", level); + +#ifdef WINDOWS + char* pname; + u_int sftp_log_level, sftp_log_facility, sftp_log_stderr; + extern int log_stderr; + if ((r = sshbuf_get_cstring(logmsg, &pname, NULL)) != 0) + fatal_fr(r, "parse"); + + if (strcmp(pname, "sftp-server") == 0) { + if ((r = sshbuf_get_u32(logmsg, &sftp_log_level)) != 0 || + (r = sshbuf_get_u32(logmsg, &sftp_log_facility)) != 0 || + (r = sshbuf_get_u32(logmsg, &sftp_log_stderr)) != 0) + fatal_fr(r, "parse"); + } + + /*log it*/ + if (authctxt->authenticated == 0) + sshlogdirect(level, forced, "%s [preauth]", msg); + else { + if (strcmp(pname, "sftp-server") == 0) { + log_init(pname, sftp_log_level, sftp_log_facility, sftp_log_stderr); + sshlogdirect(level, forced, "%s", msg); + log_init("sshd", options.log_level, options.log_facility, log_stderr); + } else + sshlogdirect(level, forced, "%s", msg); + } +#else + /*log it*/ sshlogdirect(level, forced, "%s [preauth]", msg); +#endif sshbuf_free(logmsg); free(msg); @@ -1911,6 +1940,14 @@ monitor_reinit(struct monitor *mon) monitor_openfds(mon, 0); } +#ifdef WINDOWS +void +monitor_reinit_withlogs(struct monitor* mon) +{ + monitor_openfds(mon, 1); +} +#endif + #ifdef GSSAPI int mm_answer_gss_setup_ctx(struct ssh *ssh, int sock, struct sshbuf *m) diff --git a/monitor.h b/monitor.h index 683e5e071..a9562c5f3 100644 --- a/monitor.h +++ b/monitor.h @@ -78,7 +78,9 @@ struct monitor { struct monitor *monitor_init(void); void monitor_reinit(struct monitor *); - +#ifdef WINDOWS +void monitor_reinit_withlogs(struct monitor*); +#endif struct Authctxt; void monitor_child_preauth(struct ssh *, struct monitor *); void monitor_child_postauth(struct ssh *, struct monitor *); diff --git a/monitor_wrap.c b/monitor_wrap.c index 748333c75..9d0f476d2 100644 --- a/monitor_wrap.c +++ b/monitor_wrap.c @@ -100,6 +100,19 @@ mm_log_handler(LogLevel level, int forced, const char *msg, void *ctx) (r = sshbuf_put_u32(log_msg, forced)) != 0 || (r = sshbuf_put_cstring(log_msg, msg)) != 0) fatal_fr(r, "assemble"); + +#ifdef WINDOWS + /* + * Log messages are fowarded to SSHD parent process from + * both sshd children and sftp-server processes. + * Attach progname to the end of the message so that SSHD + * parent process can differentitate between messages + * coming from sshd children and sftp-server. + */ + if (r = sshbuf_put_cstring(log_msg, "sshd") != 0) + fatal_fr(r, "assemble"); +#endif + if ((len = sshbuf_len(log_msg)) < 4 || len > 0xffffffff) fatal_f("bad length %zu", len); POKE_U32(sshbuf_mutable_ptr(log_msg), len - 4); diff --git a/regress/pesterTests/AuthorizedKeysCommand.Tests.ps1 b/regress/pesterTests/AuthorizedKeysCommand.Tests.ps1 index fb58b113b..07278d334 100644 --- a/regress/pesterTests/AuthorizedKeysCommand.Tests.ps1 +++ b/regress/pesterTests/AuthorizedKeysCommand.Tests.ps1 @@ -16,6 +16,7 @@ Describe "E2E scenarios for AuthorizedKeysCommand" -Tags "CI" { $opensshbinpath = $OpenSSHTestInfo['OpenSSHBinPath'] $ssouser = $OpenSSHTestInfo["SSOUser"] $sshdconfig = Join-Path $Global:OpenSSHTestInfo["ServiceConfigDir"] sshd_config + $sshdDelay = $OpenSSHTestInfo["DelayTime"] $testDir = Join-Path $OpenSSHTestInfo["TestDataPath"] $suite if(-not (Test-Path $testDir)) @@ -48,6 +49,7 @@ Describe "E2E scenarios for AuthorizedKeysCommand" -Tags "CI" { Start-SSHDTestDaemon -WorkDir $opensshbinpath -Arguments $sshdArgs -Port $port $o = ssh -p $port test_target echo 1234 Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay $o | Should Be "1234" #check the command is run as AuthorizedKeysCommandUser (gc $kcOutFile).Contains($ssouser) | Should Be $true @@ -64,6 +66,7 @@ Describe "E2E scenarios for AuthorizedKeysCommand" -Tags "CI" { Start-SSHDTestDaemon -WorkDir $opensshbinpath -Arguments $sshdArgs -Port $port $o = ssh -p $port test_target echo 12345 Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay $o | Should Be "12345" #check the command is run as AuthorizedKeysCommandUser (gc $kcOutFile).Contains("nt authority\system") | Should Be $true diff --git a/regress/pesterTests/Authorized_keys_fileperm.Tests.ps1 b/regress/pesterTests/Authorized_keys_fileperm.Tests.ps1 index 76b5cb930..f129d3516 100644 --- a/regress/pesterTests/Authorized_keys_fileperm.Tests.ps1 +++ b/regress/pesterTests/Authorized_keys_fileperm.Tests.ps1 @@ -26,6 +26,7 @@ Describe "Tests for authorized_keys file permission" -Tags "CI" { $ssouserProfile = $OpenSSHTestInfo["SSOUserProfile"] $opensshbinpath = $OpenSSHTestInfo['OpenSSHBinPath'] $sshdconfig = Join-Path $Global:OpenSSHTestInfo["ServiceConfigDir"] sshd_config + $sshdDelay = $OpenSSHTestInfo["DelayTime"] Remove-Item -Path (Join-Path $testDir "*$sshLogName") -Force -ErrorAction SilentlyContinue #skip when the task schedular (*-ScheduledTask) cmdlets does not exist @@ -104,6 +105,7 @@ Describe "Tests for authorized_keys file permission" -Tags "CI" { Start-SSHDTestDaemon -WorkDir $opensshbinpath -Arguments "-d -f $sshdconfig -o `"AuthorizedKeysFile .testssh/authorized_keys`" -E $sshdlog" -Port $port $o = ssh -p $port $ssouser@$server echo 1234 Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay $o | Should Be "1234" } @@ -116,6 +118,7 @@ Describe "Tests for authorized_keys file permission" -Tags "CI" { $o = ssh -p $port $ssouser@$server echo 1234 Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay $o | Should Be "1234" } @@ -127,6 +130,7 @@ Describe "Tests for authorized_keys file permission" -Tags "CI" { Start-SSHDTestDaemon -WorkDir $opensshbinpath -Arguments "-d -f $sshdconfig -o `"AuthorizedKeysFile .testssh/authorized_keys`" -E $sshdlog" -Port $port $o = ssh -p $port $ssouser@$server echo 1234 Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay $o | Should Be "1234" } @@ -138,6 +142,7 @@ Describe "Tests for authorized_keys file permission" -Tags "CI" { Start-SSHDTestDaemon -WorkDir $opensshbinpath -Arguments "-d -f $sshdconfig -o `"AuthorizedKeysFile .testssh/authorized_keys`" -E $sshdlog" -Port $port $o = ssh -p $port $ssouser@$server echo 1234 Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay $o | Should Be "1234" } @@ -153,6 +158,7 @@ Describe "Tests for authorized_keys file permission" -Tags "CI" { Start-SSHDTestDaemon -workDir $opensshbinpath -Arguments "-d -f $sshdconfig -o `"AuthorizedKeysFile .testssh/authorized_keys`" -E $sshdlog" -Port $port $o = ssh -p $port -E $sshlog $ssouser@$server echo 1234 Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay $o | Should Be "1234" } @@ -165,6 +171,7 @@ Describe "Tests for authorized_keys file permission" -Tags "CI" { ssh -p $port -E $sshlog $ssouser@$server echo 1234 $LASTEXITCODE | Should Not Be 0 Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay $sshlog | Should Contain "Permission denied" $sshdlog | Should Contain "Authentication refused." } @@ -182,6 +189,7 @@ Describe "Tests for authorized_keys file permission" -Tags "CI" { ssh -p $port -E $sshlog $ssouser@$server echo 1234 $LASTEXITCODE | Should Not Be 0 Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay $sshlog | Should Contain "Permission denied" $sshdlog | Should Contain "Authentication refused." } @@ -196,6 +204,7 @@ Describe "Tests for authorized_keys file permission" -Tags "CI" { ssh -p $port -E $sshlog $ssouser@$server echo 1234 $LASTEXITCODE | Should Not Be 0 Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay $sshlog | Should Contain "Permission denied" $sshdlog | Should Contain "Authentication refused." } diff --git a/regress/pesterTests/CertAuth.Tests.ps1 b/regress/pesterTests/CertAuth.Tests.ps1 index f1bf9c570..2e6a8e216 100644 --- a/regress/pesterTests/CertAuth.Tests.ps1 +++ b/regress/pesterTests/CertAuth.Tests.ps1 @@ -18,6 +18,7 @@ Describe "E2E scenarios for certificate authentication" -Tags "CI" { $opensshbinpath = $OpenSSHTestInfo['OpenSSHBinPath'] $ssouser = $OpenSSHTestInfo["SSOUser"] $sshdconfig = Join-Path $Global:OpenSSHTestInfo["ServiceConfigDir"] sshd_config + $sshdDelay = $OpenSSHTestInfo["DelayTime"] $testDir = Join-Path $OpenSSHTestInfo["TestDataPath"] $suite if(-not (Test-Path $testDir)) @@ -82,6 +83,7 @@ Describe "E2E scenarios for certificate authentication" -Tags "CI" { Remove-PasswordSetting Stop-SSHDTestDaemon -Port 47004 + sleep $sshdDelay $o | Should Be "2345" #check the command is run as AuthorizedPrincipalsCommandUser (gc $pcOutFile).Contains($ssouser) | Should Be $true diff --git a/regress/pesterTests/FileBasedLogging.tests.ps1 b/regress/pesterTests/FileBasedLogging.tests.ps1 new file mode 100644 index 000000000..dd065af07 --- /dev/null +++ b/regress/pesterTests/FileBasedLogging.tests.ps1 @@ -0,0 +1,225 @@ +If ($PSVersiontable.PSVersion.Major -le 2) {$PSScriptRoot = Split-Path -Parent $MyInvocation.MyCommand.Path} +Import-Module $PSScriptRoot\CommonUtils.psm1 -Force +Import-Module OpenSSHUtils -Force +$tC = 1 +$tI = 0 +$suite = "FileBasedLogging" +Describe "Tests for admin and non-admin file based logs" -Tags "CI" { + BeforeAll { + if($OpenSSHTestInfo -eq $null) + { + Throw "`$OpenSSHTestInfo is null. Please run Set-OpenSSHTestEnvironment to set test environments." + } + + $testDir = "$($OpenSSHTestInfo["TestDataPath"])\$suite" + if( -not (Test-path $testDir -PathType Container)) + { + $null = New-Item $testDir -ItemType directory -Force -ErrorAction SilentlyContinue + } + + $sshLogName = "test.txt" + $sshdLogName = "sshdlog.txt" + $server = $OpenSSHTestInfo["Target"] + $opensshbinpath = $OpenSSHTestInfo['OpenSSHBinPath'] + $nonadminusername = $OpenSSHTestInfo['NonAdminUser'] + $adminusername = $OpenSSHTestInfo['AdminUser'] + $password = $OpenSSHTestInfo['TestAccountPW'] + $port = 47003 + $sshdDelay = $OpenSSHTestInfo["DelayTime"] + Remove-Item -Path (Join-Path $testDir "*$sshLogName") -Force -ErrorAction SilentlyContinue + + <# Setup sshd_config file#> + + $sshdconfig_ori = Join-Path $Global:OpenSSHTestInfo["ServiceConfigDir"] sshd_config + $sshdconfig_custom = Join-Path $Global:OpenSSHTestInfo["ServiceConfigDir"] sshd_config_custom + if (Test-Path $sshdconfig_custom) { + Remove-Item $sshdconfig_custom -Force + } + Copy-Item $sshdconfig_ori $sshdconfig_custom + get-acl $sshdconfig_ori | set-acl $sshdconfig_custom + $content = Get-Content -Path $sshdconfig_custom + $newContent = $content -replace "Subsystem sftp sftp-server.exe -l DEBUG3", "Subsystem sftp sftp-server.exe -l DEBUG3 -f LOCAL0" + $newContent | Set-Content -Path $sshdconfig_custom + + #skip when the task schedular (*-ScheduledTask) cmdlets does not exist + $ts = (get-command get-ScheduledTask -ErrorAction SilentlyContinue) + $skip = $ts -eq $null + if(-not $skip) + { + Stop-SSHDTestDaemon -Port $port + } + if(($platform -eq [PlatformType]::Windows) -and ([Environment]::OSVersion.Version.Major -le 6)) + { + #suppress the firewall blocking dialogue on win7 + netsh advfirewall firewall add rule name="sshd" program="$($OpenSSHTestInfo['OpenSSHBinPath'])\sshd.exe" protocol=any action=allow dir=in + } + } + + AfterEach { $tI++ } + + AfterAll { + if(($platform -eq [PlatformType]::Windows) -and ($psversiontable.BuildVersion.Major -le 6)) + { + netsh advfirewall firewall delete rule name="sshd" program="$($OpenSSHTestInfo['OpenSSHBinPath'])\sshd.exe" protocol=any dir=in + } + } + + + Context "Tests Logs for SSH connections" { + BeforeAll { + $sshdConfigPath = $sshdconfig_custom + Add-PasswordSetting -Pass $password + $tI=1 + } + + BeforeEach { + $sshlog = Join-Path $testDir "$tC.$tI.$sshLogName" + $sshdlog = Join-Path $testDir "$tC.$tI.$sshdLogName" + + if (Test-Path $sshdlog -PathType Leaf) { + Clear-Content $sshdlog + } + + if(-not $skip) + { + Stop-SSHDTestDaemon -Port $port + } + } + + AfterAll { + Remove-PasswordSetting + $tC++ + } + + It "$tC.$tI-Nonadmin SSH Connection" -skip:$skip { + Start-SSHDTestDaemon -WorkDir $opensshbinpath -Arguments "-ddd -f $sshdConfigPath -E $sshdlog" -Port $port + $o = ssh -vvv -p $port -E $sshlog $nonadminusername@$server echo 1234 + $o | Should Be 1234 + Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay + $sshdlog | Should Contain "KEX done \[preauth\]" + $sshdlog | Should Contain "exec_command: echo 1234" + } + + It "$tC.$tI-Admin SSH Connection" -skip:$skip { + Start-SSHDTestDaemon -WorkDir $opensshbinpath -Arguments "-ddd -f $sshdConfigPath -E $sshdlog" -Port $port + $o = ssh -vvv -p $port -E $sshlog $adminusername@$server echo 1234 + $o | Should Be 1234 + Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay + $sshdlog | Should Contain "KEX done \[preauth\]" + $sshdlog | Should Contain "exec_command: echo 1234" + } + } + + Context "Tests Logs for SFTP connections" { + + BeforeAll { + $sshdConfigPath = $sshdconfig_custom + + function Setup-KeyBasedAuth + { + param([string] $Username, [string] $KeyFilePath, [string] $UserProfile) + + $userSSHProfilePath = Join-Path $UserProfile .ssh + + if (-not (Test-Path $userSSHProfilePath -PathType Container)) { + New-Item $userSSHProfilePath -ItemType directory -Force -ErrorAction Stop | Out-Null + } + + $authorizedkeyPath = Join-Path $userSSHProfilePath authorized_keys + + if($OpenSSHTestInfo["NoLibreSSL"]) + { + ssh-keygen.exe -t ed25519 -f $KeyFilePath -Z -P `"`" aes128-ctr + } + else + { + ssh-keygen.exe -t ed25519 -f $KeyFilePath -P `"`" + } + Copy-Item "$keyFilePath.pub" $authorizedkeyPath -Force -ErrorAction SilentlyContinue + Repair-AuthorizedKeyPermission -Filepath $authorizedkeyPath -confirm:$false + } + + $AdminUserProfile = $OpenSSHTestInfo['AdminUserProfile'] + $NonAdminUserProfile = $OpenSSHTestInfo['NonAdminUserProfile'] + + $KeyFileName = $nonadminusername + "_sshtest_fileBasedLog_ed25519" + $NonadminKeyFilePath = Join-Path $testDir $keyFileName + Remove-Item -path "$NonadminKeyFilePath*" -Force -ErrorAction SilentlyContinue + Setup-KeyBasedAuth -Username $nonadminusername -KeyFilePath $NonadminKeyFilePath -UserProfile $NonAdminUserProfile + + $KeyFileName = $adminusername + "_sshtest_fileBasedLog_ed25519" + $AdminKeyFilePath = Join-Path $testDir $keyFileName + Remove-Item -path "$AdminKeyFilePath*" -Force -ErrorAction SilentlyContinue + Setup-KeyBasedAuth -Username $adminusername -KeyFilePath $AdminKeyFilePath -UserProfile $AdminUserProfile + + #create batch file + $commands = +"ls +exit" + $batchFilePath = Join-Path $testDir "$tC.$tI.commands.txt" + Set-Content $batchFilePath -Encoding UTF8 -value $commands + + $tI = 1 + } + + BeforeEach { + Clear-Content "$env:ProgramData\ssh\logs\sftp-server.log" -Force -ErrorAction SilentlyContinue + $sshlog = Join-Path $testDir "$tC.$tI.$sshLogName" + $sshdlog = Join-Path $testDir "$tC.$tI.$sshdLogName" + if (Test-Path $sshdlog -PathType Leaf) { + Clear-Content $sshdlog + } + if(-not $skip) + { + Stop-SSHDTestDaemon -Port $port + } + } + + AfterAll { + Remove-Item -path "$NonadminKeyFilePath*" -Force -ErrorAction SilentlyContinue + Remove-Item -path "$AdminKeyFilePath*" -Force -ErrorAction SilentlyContinue + + $authorized_key = Join-Path .ssh authorized_keys + $AdminAuthKeysPath = Join-Path $AdminUserProfile $authorized_key + $NonAdminAuthKeysPath = Join-Path $NonAdminUserProfile $authorized_key + Remove-Item -path "$AdminAuthKeysPath*" -Force -ErrorAction SilentlyContinue + Remove-Item -path "$NonAdminAuthKeysPath*" -Force -ErrorAction SilentlyContinue + + $tC++ + } + + It "$tC.$tI-Nonadmin SFTP Connection" -skip:$skip { + Start-SSHDTestDaemon -WorkDir $opensshbinpath -Arguments "-ddd -f $sshdConfigPath -E $sshdlog" -Port $port + sftp -P $port -i $NonadminKeyFilePath -b $batchFilePath $nonadminusername@$server + Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay + $sftplog = Join-Path $testDir "$tC.$tI.sftp-server.log" + Copy-Item "$env:ProgramData\ssh\logs\sftp-server.log" $sftplog -Force -ErrorAction SilentlyContinue + + $sshdlog | Should Contain "Accepted publickey for $nonadminusername" + $sshdlog | Should Contain "KEX done \[preauth\]" + $sshdlog | Should Contain "debug2: subsystem request for sftp by user $nonadminusername" + $sftplog | Should Contain "session opened for local user $nonadminusername" + $sftplog | Should Contain "debug3: request 3: opendir" + $sftplog | Should Contain "session closed for local user $nonadminusername" + } + + It "$tC.$tI-Admin SFTP Connection" -skip:$skip { + Start-SSHDTestDaemon -WorkDir $opensshbinpath -Arguments "-ddd -f $sshdConfigPath -E $sshdlog" -Port $port + sftp -P $port -i $AdminKeyFilePath -b $batchFilePath $adminusername@$server + Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay + $sftplog = Join-Path $testDir "$tC.$tI.sftp-server.log" + Copy-Item "$env:ProgramData\ssh\logs\sftp-server.log" $sftplog -Force -ErrorAction SilentlyContinue + + $sshdlog | Should Contain "Accepted publickey for $adminusername" + $sshdlog | Should Contain "KEX done \[preauth\]" + $sshdlog | Should Contain "debug2: subsystem request for sftp by user $adminusername" + $sftplog | Should Contain "session opened for local user $adminusername" + $sftplog | Should Contain "debug3: request 3: opendir" + $sftplog | Should Contain "session closed for local user $adminusername" + } + } +} diff --git a/regress/pesterTests/SSHDConfig.tests.ps1 b/regress/pesterTests/SSHDConfig.tests.ps1 index 761b52003..af7cf92e1 100644 --- a/regress/pesterTests/SSHDConfig.tests.ps1 +++ b/regress/pesterTests/SSHDConfig.tests.ps1 @@ -20,7 +20,8 @@ Describe "Tests of sshd_config" -Tags "CI" { $sshdLogName = "sshdlog.txt" $server = $OpenSSHTestInfo["Target"] $opensshbinpath = $OpenSSHTestInfo['OpenSSHBinPath'] - $port = 47003 + $port = 47003 + $sshdDelay = $OpenSSHTestInfo["DelayTime"] Remove-Item -Path (Join-Path $testDir "*$sshLogName") -Force -ErrorAction SilentlyContinue Add-Type -AssemblyName System.DirectoryServices.AccountManagement @@ -218,6 +219,7 @@ Match User matchuser $o = ssh -p $port $allowUser1@$server echo 1234 Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay $o | Should Be "1234" Remove-UserFromLocalGroup -UserName $allowUser1 -GroupName $allowGroup1 @@ -231,6 +233,7 @@ Match User matchuser $o = ssh -p $port $allowUser2@$server echo 1234 Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay $o | Should Be "1234" Remove-UserFromLocalGroup -UserName $allowUser2 -GroupName $allowGroup1 @@ -243,6 +246,7 @@ Match User matchuser $o = ssh -p $port $allowUser3@$server echo 1234 Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay $o | Should Be "1234" Remove-UserFromLocalGroup -UserName $allowUser3 -GroupName $allowGroup1 @@ -257,6 +261,7 @@ Match User matchuser ssh -p $port -E $sshlog $denyUser1@$server echo 1234 $LASTEXITCODE | Should Not Be 0 Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay $sshdlog | Should Contain "not allowed because listed in DenyUsers" Remove-UserFromLocalGroup -UserName $denyUser1 -GroupName $allowGroup1 @@ -272,6 +277,7 @@ Match User matchuser ssh -p $port -E $sshlog $denyUser2@$server echo 1234 $LASTEXITCODE | Should Not Be 0 Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay $sshdlog | Should Contain "not allowed because listed in DenyUsers" Remove-UserFromLocalGroup -UserName $denyUser2 -GroupName $allowGroup1 @@ -287,6 +293,7 @@ Match User matchuser ssh -p $port -E $sshlog $denyUser3@$server echo 1234 $LASTEXITCODE | Should Not Be 0 Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay $sshdlog | Should Contain "not allowed because not listed in AllowUsers" Remove-UserFromLocalGroup -UserName $denyUser3 -GroupName $allowGroup1 @@ -303,6 +310,7 @@ Match User matchuser ssh -p $port -E $sshlog $localuser1@$server echo 1234 $LASTEXITCODE | Should Not Be 0 Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay $sshdlog | Should Contain "not allowed because a group is listed in DenyGroups" Remove-UserFromLocalGroup -UserName $localuser1 -GroupName $allowGroup1 @@ -319,6 +327,7 @@ Match User matchuser ssh -p $port -E $sshlog $localuser2@$server echo 1234 $LASTEXITCODE | Should Not Be 0 Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay $sshdlog | Should Contain "not allowed because a group is listed in DenyGroups" Remove-UserFromLocalGroup -UserName $localuser2 -GroupName $denyGroup2 @@ -334,6 +343,7 @@ Match User matchuser ssh -p $port -E $sshlog $localuser3@$server echo 1234 $LASTEXITCODE | Should Not Be 0 Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay $sshdlog | Should Contain "not allowed because a group is listed in DenyGroups" Remove-UserFromLocalGroup -UserName $localuser3 -GroupName $denyGroup3 @@ -351,6 +361,7 @@ Match User matchuser $o[1].Contains("randomcommand") | Should Be $true Stop-SSHDTestDaemon -Port $port + sleep $sshdDelay Remove-UserFromLocalGroup -UserName $matchuser -GroupName $allowGroup1 } } diff --git a/sftp-server.c b/sftp-server.c index 9727950ac..095e8d4c6 100644 --- a/sftp-server.c +++ b/sftp-server.c @@ -59,6 +59,10 @@ char *sftp_realpath(const char *, char *); /* sftp-realpath.c */ /* Our verbosity */ static LogLevel log_level = SYSLOG_LEVEL_ERROR; +#ifdef WINDOWS +static SyslogFacility log_facility_g = SYSLOG_FACILITY_AUTH; +int log_stderr_g = 0; +#endif /* Our client */ static struct passwd *pw = NULL; @@ -1641,6 +1645,42 @@ sftp_server_cleanup_exit(int i) _exit(i); } +#ifdef WINDOWS +void +log_handler(LogLevel level, int forced, const char* msg, void* ctx) +{ + #include "atomicio.h" + struct sshbuf* log_msg; + int* log_fd = (int*)ctx; + int r; + size_t len; + + if (*log_fd == -1) + fatal_f("no log channel"); + + if ((log_msg = sshbuf_new()) == NULL) + fatal_f("sshbuf_new failed"); + + if ((r = sshbuf_put_u32(log_msg, 0)) != 0 || /* length; filled below */ + (r = sshbuf_put_u32(log_msg, level)) != 0 || + (r = sshbuf_put_u32(log_msg, forced)) != 0 || + (r = sshbuf_put_cstring(log_msg, msg)) != 0 || + (r = sshbuf_put_cstring(log_msg, __progname)) != 0 || + (r = sshbuf_put_u32(log_msg, log_level)) != 0 || + (r = sshbuf_put_u32(log_msg, log_facility_g)) != 0 || + (r = sshbuf_put_u32(log_msg, log_stderr_g)) != 0) + fatal_fr(r, "assemble"); + if ((len = sshbuf_len(log_msg)) < 4 || len > 0xffffffff) + fatal_f("bad length %zu", len); + POKE_U32(sshbuf_mutable_ptr(log_msg), len - 4); + if (atomicio(vwrite, *log_fd, + sshbuf_mutable_ptr(log_msg), len) != len) + fatal_f("write: %s", strerror(errno)); + sshbuf_free(log_msg); + +} +#endif + static void sftp_server_usage(void) { @@ -1743,7 +1783,18 @@ sftp_server_main(int argc, char **argv, struct passwd *user_pw) } log_init(__progname, log_level, log_facility, log_stderr); - +#ifdef WINDOWS + /* + * SFTP-Server fowards log messages to SSHD System process. + * SSHD system process logs the messages to either ETW or sftp-server.log. + * This allows us to log the messages of both non-admin and admin users. + */ + int log_send_fd = SFTP_SERVER_LOG_FD; + log_facility_g = log_facility; + log_stderr_g = log_stderr; + if (fcntl(log_send_fd, F_SETFD, FD_CLOEXEC) != -1) + set_log_handler(log_handler, (void*)&log_send_fd); +#endif /* * On platforms where we can, avoid making /proc/self/{mem,maps} * available to the user so that sftp access doesn't automatically diff --git a/sshd.c b/sshd.c index 8f0ee04b9..915f3a23b 100644 --- a/sshd.c +++ b/sshd.c @@ -136,7 +136,12 @@ #define PRIVSEP_MONITOR_FD (STDERR_FILENO + 1) #define PRIVSEP_LOG_FD (STDERR_FILENO + 2) #define PRIVSEP_UNAUTH_MIN_FREE_FD (PRIVSEP_LOG_FD + 1) + +#ifdef WINDOWS +#define PRIVSEP_AUTH_MIN_FREE_FD (PRIVSEP_LOG_FD + 1) +#else #define PRIVSEP_AUTH_MIN_FREE_FD (PRIVSEP_MONITOR_FD + 1) +#endif extern char *__progname; @@ -169,7 +174,11 @@ static int inetd_flag = 0; static int no_daemon_flag = 0; /* debug goes to stderr unless inetd_flag is set */ +#ifdef WINDOWS +int log_stderr = 0; +#else static int log_stderr = 0; +#endif /* Saved arguments to main(). */ static char **saved_argv; @@ -878,7 +887,11 @@ privsep_postauth(struct ssh *ssh, Authctxt *authctxt) } /* New socket pair */ +#ifdef WINDOWS + monitor_reinit_withlogs(pmonitor); +#else monitor_reinit(pmonitor); +#endif #ifdef FORK_NOT_SUPPORTED if (!privsep_auth_child) { /* parent */ @@ -887,6 +900,10 @@ privsep_postauth(struct ssh *ssh, Authctxt *authctxt) if (posix_spawn_file_actions_init(&actions) != 0 || posix_spawn_file_actions_adddup2(&actions, io_sock_in, STDIN_FILENO) != 0 || posix_spawn_file_actions_adddup2(&actions, io_sock_out, STDOUT_FILENO) != 0 || +#ifdef WINDOWS + /*Allow authenticated child process to foward log messages to parent for processing*/ + posix_spawn_file_actions_adddup2(&actions, pmonitor->m_log_sendfd, PRIVSEP_LOG_FD) != 0 || +#endif posix_spawn_file_actions_adddup2(&actions, pmonitor->m_recvfd, PRIVSEP_MONITOR_FD) != 0) fatal("posix_spawn initialization failed"); @@ -912,9 +929,25 @@ privsep_postauth(struct ssh *ssh, Authctxt *authctxt) /* child */ close(pmonitor->m_sendfd); close(pmonitor->m_recvfd); - pmonitor->m_recvfd = PRIVSEP_MONITOR_FD; fcntl(pmonitor->m_recvfd, F_SETFD, FD_CLOEXEC); + +#ifdef WINDOWS + /* + * Logs for authenticated child are sent to the monitor + * to be written by parent process runing in SYSTEM. + * That allows logs for non-admin child processes to be + * recorded. + */ + close(pmonitor->m_log_recvfd); + close(pmonitor->m_log_sendfd); + pmonitor->m_log_sendfd = PRIVSEP_LOG_FD; + fcntl(pmonitor->m_log_sendfd, F_SETFD, FD_CLOEXEC); + + /* Arrange for logging to be sent to the monitor */ + set_log_handler(mm_log_handler, pmonitor); +#endif + monitor_recv_keystate(pmonitor); do_setusercontext(authctxt->pw);