Allow non-admin user processes to make changes to the log file

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

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))
 

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));

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 @@ syslog_etw(int priority, const char *format, const char *formatBuffer)
 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,20 +157,26 @@ 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);
 	r = _snprintf_s(msgbufTimestamp, sizeof(msgbufTimestamp), _TRUNCATE, "%d %04d-%02d-%02d %02d:%02d:%02d.%03d %s\n",
 		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

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)

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 *);

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);

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

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."            
         }

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