Skip to content

Commit 0b73c46

Browse files
vthiebaut10vthiebaut10
authored
Allow non-admin user processes to log message to ETW / log file (#513)
1 parent 75835a2 commit 0b73c46

14 files changed

+462
-19
lines changed

‎contrib/win32/openssh/OpenSSHTestHelper.psm1

Lines changed: 18 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -13,8 +13,10 @@ $TestSetupLogFileName = "TestSetupLog.txt"
1313
$SSOUser = "sshtest_ssouser"
1414
$PubKeyUser = "sshtest_pubkeyuser"
1515
$PasswdUser = "sshtest_passwduser"
16+
$AdminUser = "sshtest_adminuser"
17+
$NonAdminUser = "sshtest_nonadminuser"
1618
$OpenSSHTestAccountsPassword = "P@ssw0rd_1"
17-
$OpenSSHTestAccounts = $Script:SSOUser, $Script:PubKeyUser, $Script:PasswdUser
19+
$OpenSSHTestAccounts = $Script:SSOUser, $Script:PubKeyUser, $Script:PasswdUser, $Script:AdminUser, $Script:NonAdminUser
1820
$SSHDTestSvcName = "sshdTestSvc"
1921

2022
$Script:TestDataPath = "$env:SystemDrive\OpenSSHTests"
@@ -65,8 +67,11 @@ function Set-OpenSSHTestEnvironment
6567
$Global:OpenSSHTestInfo.Add("SSOUser", $SSOUser) # test user with single sign on capability
6668
$Global:OpenSSHTestInfo.Add("PubKeyUser", $PubKeyUser) # test user to be used with explicit key for key auth
6769
$Global:OpenSSHTestInfo.Add("PasswdUser", $PasswdUser) # test user to be used for password auth
70+
$Global:OpenSSHTestInfo.Add("AdminUser", $AdminUser) # test user to be used for admin logging tests
71+
$Global:OpenSSHTestInfo.Add("NonAdminUser", $NonAdminUser) # test user to be used for non-admin logging tests
6872
$Global:OpenSSHTestInfo.Add("TestAccountPW", $OpenSSHTestAccountsPassword) # common password for all test accounts
6973
$Global:OpenSSHTestInfo.Add("DebugMode", $DebugMode.IsPresent) # run openssh E2E in debug mode
74+
$Global:OpenSSHTestInfo.Add("DelayTime", 3) # delay between stoppig sshd service and trying to access log files
7075

7176
$Script:EnableAppVerifier = -not ($NoAppVerifier.IsPresent)
7277
if($Script:WindowsInBox = $true)
@@ -209,7 +214,18 @@ WARNING: Following changes will be made to OpenSSH configuration
209214
#setup single sign on for ssouser
210215
$ssouserProfile = Get-LocalUserProfile -User $SSOUser
211216
$Global:OpenSSHTestInfo.Add("SSOUserProfile", $ssouserProfile)
212-
$Global:OpenSSHTestInfo.Add("PubKeyUserProfile", (Get-LocalUserProfile -User $PubKeyUser))
217+
218+
$PubKeyUserProfile = Get-LocalUserProfile -User $PubKeyUser
219+
$Global:OpenSSHTestInfo.Add("PubKeyUserProfile", $PubKeyUserProfile)
220+
221+
$AdminUserProfile = Get-LocalUserProfile -User $AdminUser
222+
$Global:OpenSSHTestInfo.Add("AdminUserProfile", $AdminUserProfile)
223+
224+
$NonAdminUserProfile = Get-LocalUserProfile -User $NonAdminUser
225+
$Global:OpenSSHTestInfo.Add("NonAdminUserProfile", $NonAdminUserProfile)
226+
227+
#make $AdminUser admin
228+
net localgroup Administrators $AdminUser /add
213229

214230
New-Item -ItemType Directory -Path (Join-Path $ssouserProfile .ssh) -Force -ErrorAction SilentlyContinue | out-null
215231
$authorizedKeyPath = Join-Path $ssouserProfile .ssh\authorized_keys

‎contrib/win32/win32compat/inc/unistd.h

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,8 @@
1313
#define STDOUT_FILENO 1
1414
#define STDERR_FILENO 2
1515

16+
#define SFTP_SERVER_LOG_FD STDERR_FILENO+1
17+
1618
int w32_ftruncate(int, off_t);
1719
#define ftruncate(a, b) w32_ftruncate((a), (b))
1820

‎contrib/win32/win32compat/w32-doexec.c

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -401,6 +401,15 @@ int do_exec_windows(struct ssh *ssh, Session *s, const char *command, int pty) {
401401
error("posix_spawn initialization failed");
402402
goto cleanup;
403403
}
404+
405+
//Passing the PRIVSEP_LOG_FD (STDERR_FILENO + 2) to sftp-server for logging
406+
if(strstr(exec_command, "sftp-server.exe"))
407+
if (posix_spawn_file_actions_adddup2(&actions, STDERR_FILENO + 2, SFTP_SERVER_LOG_FD) != 0) {
408+
errno = EOTHER;
409+
error("posix_spawn initialization failed");
410+
goto cleanup;
411+
}
412+
404413
if (posix_spawn(&pid, spawn_argv[0], &actions, NULL, spawn_argv, NULL) != 0) {
405414
errno = EOTHER;
406415
error("posix_spawn: %s", strerror(errno));

‎contrib/win32/win32compat/w32log.c

Lines changed: 41 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -40,6 +40,7 @@
4040

4141
#define MSGBUFSIZ 1024
4242
static int logfd = -1;
43+
static int sftp_server_logfd = -1;
4344
const char* identity = NULL;
4445
int log_facility = 0;
4546

@@ -92,11 +93,15 @@ syslog_etw(int priority, const char *format, const char *formatBuffer)
9293
void
9394
openlog_file()
9495
{
95-
if (logfd != -1)
96+
if (strcmp(identity, "sftp-server") == 0 && sftp_server_logfd != -1)
9697
return;
9798

99+
if (strcmp(identity, "sftp-server") != 0 && logfd != -1)
100+
return;
101+
98102
wchar_t *logs_dir = L"\\logs\\";
99103
wchar_t module_path[PATH_MAX] = { 0 }, log_file[PATH_MAX + 12] = { 0 };
104+
wchar_t* tmp_identity = NULL;
100105

101106
if (GetModuleFileNameW(NULL, module_path, PATH_MAX) == 0)
102107
return;
@@ -113,18 +118,37 @@ openlog_file()
113118
wchar_t ssh_cfg_path[PATH_MAX] = {0 ,};
114119
wcscat_s(ssh_cfg_path, _countof(ssh_cfg_path), __wprogdata); /* "%programData%" */
115120
wcscat_s(ssh_cfg_path, _countof(ssh_cfg_path), L"\\ssh"); /* "%programData%\\ssh" */
121+
if (strcmp(identity, "sftp-server") == 0) {
122+
tmp_identity = utf8_to_utf16(identity);
123+
if (!tmp_identity)
124+
goto cleanup;
125+
}
126+
else {
127+
tmp_identity = malloc(wcslen(tail) * sizeof(wchar_t));
128+
if (!tmp_identity)
129+
goto cleanup;
130+
if (wcsncpy_s(tmp_identity, wcslen(tail), tail + 1, wcslen(tail) - 5) != 0) {
131+
goto cleanup;
132+
}
133+
}
116134

117135
if ((wcsncat_s(log_file, PATH_MAX + 12, ssh_cfg_path, wcslen(ssh_cfg_path)) != 0) ||
118136
(wcsncat_s(log_file, PATH_MAX + 12, logs_dir, 6) != 0) ||
119-
(wcsncat_s(log_file, PATH_MAX + 12, tail + 1, wcslen(tail + 1) - 3) != 0 ) ||
120-
(wcsncat_s(log_file, PATH_MAX + 12, L"log", 3) != 0))
121-
return;
137+
(wcsncat_s(log_file, PATH_MAX + 12, tmp_identity, wcslen(tmp_identity)) != 0) ||
138+
(wcsncat_s(log_file, PATH_MAX + 12, L".log", 4) != 0))
139+
goto cleanup;
122140
}
123141

124-
errno_t err = _wsopen_s(&logfd, log_file, O_WRONLY | O_CREAT | O_APPEND, SH_DENYNO, S_IREAD | S_IWRITE);
125-
126-
if (logfd != -1)
127-
SetHandleInformation((HANDLE)_get_osfhandle(logfd), HANDLE_FLAG_INHERIT, 0);
142+
int* fd_ptr = &logfd;
143+
144+
if (strcmp(identity, "sftp-server") == 0)
145+
fd_ptr = &sftp_server_logfd;
146+
147+
errno_t err = _wsopen_s(fd_ptr, log_file, O_WRONLY | O_CREAT | O_APPEND, SH_DENYNO, S_IREAD | S_IWRITE);
148+
149+
cleanup:
150+
if (tmp_identity)
151+
free(tmp_identity);
128152
}
129153

130154
void
@@ -133,20 +157,26 @@ syslog_file(int priority, const char *format, const char *formatBuffer)
133157
char msgbufTimestamp[MSGBUFSIZ];
134158
SYSTEMTIME st;
135159
int r;
160+
int msg_fd;
161+
162+
if (strcmp(identity, "sftp-server") == 0)
163+
msg_fd = sftp_server_logfd;
164+
else
165+
msg_fd = logfd;
136166

137-
if (logfd == -1)
167+
if (msg_fd == -1)
138168
return;
139169

140170
GetLocalTime(&st);
141171
r = _snprintf_s(msgbufTimestamp, sizeof(msgbufTimestamp), _TRUNCATE, "%d %04d-%02d-%02d %02d:%02d:%02d.%03d %s\n",
142172
GetCurrentProcessId(), st.wYear, st.wMonth, st.wDay, st.wHour, st.wMinute, st.wSecond,
143173
st.wMilliseconds, formatBuffer);
144174
if (r == -1) {
145-
_write(logfd, "_snprintf_s failed.", 20);
175+
_write(msg_fd, "_snprintf_s failed.", 20);
146176
return;
147177
}
148178
msgbufTimestamp[strnlen(msgbufTimestamp, MSGBUFSIZ)] = '\0';
149-
_write(logfd, msgbufTimestamp, (unsigned int)strnlen(msgbufTimestamp, MSGBUFSIZ));
179+
_write(msg_fd, msgbufTimestamp, (unsigned int)strnlen(msgbufTimestamp, MSGBUFSIZ));
150180
}
151181

152182
void

‎monitor.c

Lines changed: 39 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -449,15 +449,44 @@ monitor_read_log(struct monitor *pmonitor)
449449
fatal_fr(r, "reserve msg");
450450
if (atomicio(read, pmonitor->m_log_recvfd, p, len) != len)
451451
fatal_f("log fd read: %s", strerror(errno));
452+
452453
if ((r = sshbuf_get_u32(logmsg, &level)) != 0 ||
453454
(r = sshbuf_get_u32(logmsg, &forced)) != 0 ||
454455
(r = sshbuf_get_cstring(logmsg, &msg, NULL)) != 0)
455456
fatal_fr(r, "parse");
456-
457-
/* Log it */
457+
458458
if (log_level_name(level) == NULL)
459459
fatal_f("invalid log level %u (corrupted message?)", level);
460+
461+
#ifdef WINDOWS
462+
char* pname;
463+
u_int sftp_log_level, sftp_log_facility, sftp_log_stderr;
464+
extern int log_stderr;
465+
if ((r = sshbuf_get_cstring(logmsg, &pname, NULL)) != 0)
466+
fatal_fr(r, "parse");
467+
468+
if (strcmp(pname, "sftp-server") == 0) {
469+
if ((r = sshbuf_get_u32(logmsg, &sftp_log_level)) != 0 ||
470+
(r = sshbuf_get_u32(logmsg, &sftp_log_facility)) != 0 ||
471+
(r = sshbuf_get_u32(logmsg, &sftp_log_stderr)) != 0)
472+
fatal_fr(r, "parse");
473+
}
474+
475+
/*log it*/
476+
if (authctxt->authenticated == 0)
477+
sshlogdirect(level, forced, "%s [preauth]", msg);
478+
else {
479+
if (strcmp(pname, "sftp-server") == 0) {
480+
log_init(pname, sftp_log_level, sftp_log_facility, sftp_log_stderr);
481+
sshlogdirect(level, forced, "%s", msg);
482+
log_init("sshd", options.log_level, options.log_facility, log_stderr);
483+
} else
484+
sshlogdirect(level, forced, "%s", msg);
485+
}
486+
#else
487+
/*log it*/
460488
sshlogdirect(level, forced, "%s [preauth]", msg);
489+
#endif
461490

462491
sshbuf_free(logmsg);
463492
free(msg);
@@ -1911,6 +1940,14 @@ monitor_reinit(struct monitor *mon)
19111940
monitor_openfds(mon, 0);
19121941
}
19131942

1943+
#ifdef WINDOWS
1944+
void
1945+
monitor_reinit_withlogs(struct monitor* mon)
1946+
{
1947+
monitor_openfds(mon, 1);
1948+
}
1949+
#endif
1950+
19141951
#ifdef GSSAPI
19151952
int
19161953
mm_answer_gss_setup_ctx(struct ssh *ssh, int sock, struct sshbuf *m)

‎monitor.h

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -78,7 +78,9 @@ struct monitor {
7878

7979
struct monitor *monitor_init(void);
8080
void monitor_reinit(struct monitor *);
81-
81+
#ifdef WINDOWS
82+
void monitor_reinit_withlogs(struct monitor*);
83+
#endif
8284
struct Authctxt;
8385
void monitor_child_preauth(struct ssh *, struct monitor *);
8486
void monitor_child_postauth(struct ssh *, struct monitor *);

‎monitor_wrap.c

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -100,6 +100,19 @@ mm_log_handler(LogLevel level, int forced, const char *msg, void *ctx)
100100
(r = sshbuf_put_u32(log_msg, forced)) != 0 ||
101101
(r = sshbuf_put_cstring(log_msg, msg)) != 0)
102102
fatal_fr(r, "assemble");
103+
104+
#ifdef WINDOWS
105+
/*
106+
* Log messages are fowarded to SSHD parent process from
107+
* both sshd children and sftp-server processes.
108+
* Attach progname to the end of the message so that SSHD
109+
* parent process can differentitate between messages
110+
* coming from sshd children and sftp-server.
111+
*/
112+
if (r = sshbuf_put_cstring(log_msg, "sshd") != 0)
113+
fatal_fr(r, "assemble");
114+
#endif
115+
103116
if ((len = sshbuf_len(log_msg)) < 4 || len > 0xffffffff)
104117
fatal_f("bad length %zu", len);
105118
POKE_U32(sshbuf_mutable_ptr(log_msg), len - 4);

‎regress/pesterTests/AuthorizedKeysCommand.Tests.ps1

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -16,6 +16,7 @@ Describe "E2E scenarios for AuthorizedKeysCommand" -Tags "CI" {
1616
$opensshbinpath = $OpenSSHTestInfo['OpenSSHBinPath']
1717
$ssouser = $OpenSSHTestInfo["SSOUser"]
1818
$sshdconfig = Join-Path $Global:OpenSSHTestInfo["ServiceConfigDir"] sshd_config
19+
$sshdDelay = $OpenSSHTestInfo["DelayTime"]
1920

2021
$testDir = Join-Path $OpenSSHTestInfo["TestDataPath"] $suite
2122
if(-not (Test-Path $testDir))
@@ -48,6 +49,7 @@ Describe "E2E scenarios for AuthorizedKeysCommand" -Tags "CI" {
4849
Start-SSHDTestDaemon -WorkDir $opensshbinpath -Arguments $sshdArgs -Port $port
4950
$o = ssh -p $port test_target echo 1234
5051
Stop-SSHDTestDaemon -Port $port
52+
sleep $sshdDelay
5153
$o | Should Be "1234"
5254
#check the command is run as AuthorizedKeysCommandUser
5355
(gc $kcOutFile).Contains($ssouser) | Should Be $true
@@ -64,6 +66,7 @@ Describe "E2E scenarios for AuthorizedKeysCommand" -Tags "CI" {
6466
Start-SSHDTestDaemon -WorkDir $opensshbinpath -Arguments $sshdArgs -Port $port
6567
$o = ssh -p $port test_target echo 12345
6668
Stop-SSHDTestDaemon -Port $port
69+
sleep $sshdDelay
6770
$o | Should Be "12345"
6871
#check the command is run as AuthorizedKeysCommandUser
6972
(gc $kcOutFile).Contains("nt authority\system") | Should Be $true

‎regress/pesterTests/Authorized_keys_fileperm.Tests.ps1

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@ Describe "Tests for authorized_keys file permission" -Tags "CI" {
2626
$ssouserProfile = $OpenSSHTestInfo["SSOUserProfile"]
2727
$opensshbinpath = $OpenSSHTestInfo['OpenSSHBinPath']
2828
$sshdconfig = Join-Path $Global:OpenSSHTestInfo["ServiceConfigDir"] sshd_config
29+
$sshdDelay = $OpenSSHTestInfo["DelayTime"]
2930
Remove-Item -Path (Join-Path $testDir "*$sshLogName") -Force -ErrorAction SilentlyContinue
3031

3132
#skip when the task schedular (*-ScheduledTask) cmdlets does not exist
@@ -104,6 +105,7 @@ Describe "Tests for authorized_keys file permission" -Tags "CI" {
104105
Start-SSHDTestDaemon -WorkDir $opensshbinpath -Arguments "-d -f $sshdconfig -o `"AuthorizedKeysFile .testssh/authorized_keys`" -E $sshdlog" -Port $port
105106
$o = ssh -p $port $ssouser@$server echo 1234
106107
Stop-SSHDTestDaemon -Port $port
108+
sleep $sshdDelay
107109
$o | Should Be "1234"
108110
}
109111

@@ -116,6 +118,7 @@ Describe "Tests for authorized_keys file permission" -Tags "CI" {
116118

117119
$o = ssh -p $port $ssouser@$server echo 1234
118120
Stop-SSHDTestDaemon -Port $port
121+
sleep $sshdDelay
119122
$o | Should Be "1234"
120123
}
121124

@@ -127,6 +130,7 @@ Describe "Tests for authorized_keys file permission" -Tags "CI" {
127130
Start-SSHDTestDaemon -WorkDir $opensshbinpath -Arguments "-d -f $sshdconfig -o `"AuthorizedKeysFile .testssh/authorized_keys`" -E $sshdlog" -Port $port
128131
$o = ssh -p $port $ssouser@$server echo 1234
129132
Stop-SSHDTestDaemon -Port $port
133+
sleep $sshdDelay
130134
$o | Should Be "1234"
131135
}
132136

@@ -138,6 +142,7 @@ Describe "Tests for authorized_keys file permission" -Tags "CI" {
138142
Start-SSHDTestDaemon -WorkDir $opensshbinpath -Arguments "-d -f $sshdconfig -o `"AuthorizedKeysFile .testssh/authorized_keys`" -E $sshdlog" -Port $port
139143
$o = ssh -p $port $ssouser@$server echo 1234
140144
Stop-SSHDTestDaemon -Port $port
145+
sleep $sshdDelay
141146
$o | Should Be "1234"
142147
}
143148

@@ -153,6 +158,7 @@ Describe "Tests for authorized_keys file permission" -Tags "CI" {
153158
Start-SSHDTestDaemon -workDir $opensshbinpath -Arguments "-d -f $sshdconfig -o `"AuthorizedKeysFile .testssh/authorized_keys`" -E $sshdlog" -Port $port
154159
$o = ssh -p $port -E $sshlog $ssouser@$server echo 1234
155160
Stop-SSHDTestDaemon -Port $port
161+
sleep $sshdDelay
156162
$o | Should Be "1234"
157163
}
158164

@@ -165,6 +171,7 @@ Describe "Tests for authorized_keys file permission" -Tags "CI" {
165171
ssh -p $port -E $sshlog $ssouser@$server echo 1234
166172
$LASTEXITCODE | Should Not Be 0
167173
Stop-SSHDTestDaemon -Port $port
174+
sleep $sshdDelay
168175
$sshlog | Should Contain "Permission denied"
169176
$sshdlog | Should Contain "Authentication refused."
170177
}
@@ -182,6 +189,7 @@ Describe "Tests for authorized_keys file permission" -Tags "CI" {
182189
ssh -p $port -E $sshlog $ssouser@$server echo 1234
183190
$LASTEXITCODE | Should Not Be 0
184191
Stop-SSHDTestDaemon -Port $port
192+
sleep $sshdDelay
185193
$sshlog | Should Contain "Permission denied"
186194
$sshdlog | Should Contain "Authentication refused."
187195
}
@@ -196,6 +204,7 @@ Describe "Tests for authorized_keys file permission" -Tags "CI" {
196204
ssh -p $port -E $sshlog $ssouser@$server echo 1234
197205
$LASTEXITCODE | Should Not Be 0
198206
Stop-SSHDTestDaemon -Port $port
207+
sleep $sshdDelay
199208
$sshlog | Should Contain "Permission denied"
200209
$sshdlog | Should Contain "Authentication refused."
201210
}

‎regress/pesterTests/CertAuth.Tests.ps1

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@ Describe "E2E scenarios for certificate authentication" -Tags "CI" {
1818
$opensshbinpath = $OpenSSHTestInfo['OpenSSHBinPath']
1919
$ssouser = $OpenSSHTestInfo["SSOUser"]
2020
$sshdconfig = Join-Path $Global:OpenSSHTestInfo["ServiceConfigDir"] sshd_config
21+
$sshdDelay = $OpenSSHTestInfo["DelayTime"]
2122

2223
$testDir = Join-Path $OpenSSHTestInfo["TestDataPath"] $suite
2324
if(-not (Test-Path $testDir))
@@ -82,6 +83,7 @@ Describe "E2E scenarios for certificate authentication" -Tags "CI" {
8283
Remove-PasswordSetting
8384

8485
Stop-SSHDTestDaemon -Port 47004
86+
sleep $sshdDelay
8587
$o | Should Be "2345"
8688
#check the command is run as AuthorizedPrincipalsCommandUser
8789
(gc $pcOutFile).Contains($ssouser) | Should Be $true

0 commit comments

Comments
 (0)