openssh unix dev - Sep 2021 - Aw: Re: Howto log multiple sftpd instances with their chroot shared via NFS

Jochen, are you sure that you see the real sftp user session detailed activity
log, e.g.

internal-sftp[27918]: session opened for local user <username> from
[1.2.3.4]
internal-sftp[27918]: open "/in/file.dat" flags WRITE,CREATE,TRUNCATE
mode 0666

etc. and not just the sshd auth log, e.g.

sftpd[4772]: Accepted publickey for <username> from 1.2.3.4 port 45504
ssh2

? With Ubuntu 18.04.1 LTS and it's shipped OpenSSH 7.6p1-4ubuntu0.5 I can
not get any sftp session logging when having only an empty /dev directory under
the user's chroot directory, without it's "log" file.

I wonder if it would be a bug or a feature if you can manage to get sftp session
logging without /dev/log in the sftp user's chroot dir?
What CentOS and OpenSSH version do you have exactly?
What could be the difference of the CentOS OpenSSH? Do you have special starting
options?

Peter,
> I think that works specifically because *no* new process is created
> when using internal-sftp as opposed to executing the sftp-server binary.
For every sftp subsystem login (here with user "sftp_nagios"), I see a
new sftpd process created:

First login:

ps auxww |grep sftp
root      4192  0.0  0.1  72304  6512 ?        Ss   11:01   0:00 /usr/sbin/sftpd
-D -f /etc/sftpd/sftpd_config
root      4590  0.2  0.1  74736  6632 ?        Ss   11:05   0:00 sftpd:
sftp_nagios [priv]
sftp_na+  4592  0.0  0.0  74736  3432 ?        S    11:05   0:00 sftpd:
sftp_nagios at notty
sftp_na+  4593  0.0  0.0  74736  3108 ?        Ss   11:05   0:00 sftpd:
sftp_nagios at internal-sftp

Then logout and login again, second login:

ps auxww |grep sftp
root      4192  0.0  0.1  72304  6512 ?        Ss   11:01   0:00 /usr/sbin/sftpd
-D -f /etc/sftpd/sftpd_config
root      4630  0.5  0.1  74736  6596 ?        Ss   11:05   0:00 sftpd:
sftp_nagios [priv]
sftp_na+  4632  0.0  0.0  74736  3552 ?        S    11:05   0:00 sftpd:
sftp_nagios at notty
sftp_na+  4633  0.0  0.0  74736  3164 ?        Ss   11:05   0:00 sftpd:
sftp_nagios at internal-sftp

> Gesendet: Sonntag, 26. September 2021 um 22:20 Uhr
> Von: "Peter Stuge" <peter at stuge.se>
> An: openssh-unix-dev at mindrot.org
> Betreff: Re: Howto log multiple sftpd instances with their chroot shared
via NFS
>
> Jochen Bern wrote:
> > OK. This is a behavior I see (and use) on a CentOS SFTP server, but I
> > have no idea how portable it is to other distribs, so just give it a
try:
> >
> > > # egrep '^[^#]*( mand|sftp)' /etc/ssh/sshd_config
> > > Subsystem       sftp    internal-sftp
> > > Match group mandanten
> > >         ForceCommand internal-sftp -l INFO -u 0077
> >
> >
> > > # ls -al ~lvinq4/dev
> > > insgesamt 0
> > > drwx--x---. 2 root mandanten  6 20. Mai 17:25 .
> > > drwxr-x---. 5 root mandanten 54 24. Aug 15:38 ..
> >
> > As you can see, the chroots have an *empty* /dev subdir, but logging
> > *still works*, apparently because the chrooted process just keeps
using
> > the system-central /dev/log it opened *before* chroot()ing.
>
> I think that works specifically because *no* new process is created
> when using internal-sftp as opposed to executing the sftp-server binary.
>
> If syslog-ng can be made to reliably route internal-sftp messages to
> user-specific log files then this approach would work well in
Hildegard's
> setup and would be a lot more pleasant than messing with LD_PRELOAD.
>
>
> //Peter
> _______________________________________________
> openssh-unix-dev mailing list
> openssh-unix-dev at mindrot.org
> https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev
>

On 29.09.21 11:18, Hildegard Meier wrote:
> Jochen, are you sure that you see the real sftp user session detailed
activity log, e.g.
> 
> internal-sftp[27918]: session opened for local user <username> from
[1.2.3.4]
> internal-sftp[27918]: open "/in/file.dat" flags
WRITE,CREATE,TRUNCATE mode 0666
> 
> etc. and not just the sshd auth log, e.g.
> 
> sftpd[4772]: Accepted publickey for <username> from 1.2.3.4 port
45504 ssh2
Considering that I'm the one who gets to debug both customers' 
connectivity *and* concurrent-file-operations problems, I'm *quite* sure 
of that. :-)
> sshd[27049]: Accepted publickey for [REDACTED] from [REDACTED] port 54343
ssh2: RSA SHA256:[REDACTED]
> sshd[27049]: pam_unix(sshd:session): session opened for user [REDACTED] by
(uid=0)
> sshd[27049]: session opened for local user [REDACTED] from [REDACTED]
[postauth]
> sshd[27049]: sent status No such file [postauth]
> sshd[27049]: sent status No such file [postauth]
> sshd[27049]: open "[REDACTED]" flags WRITE,CREATE,TRUNCATE mode
0666 [postauth]
> sshd[27049]: close "[REDACTED]" bytes read 0 written 5870358
[postauth]
> sshd[27049]: session closed for local user [REDACTED] from [REDACTED]
[postauth]
> sshd[27049]: pam_unix(sshd:session): session closed for user [REDACTED]
- all from today's /var/log/messages .
> I wonder if it would be a bug or a feature if you can manage to get sftp
> session logging without /dev/log in the sftp user's chroot dir?
I'm in the dark whether that behavior is *intended* (and if so, by whom 
exactly), hence my reluctance to openly recommend my setup to others ...
> What CentOS and OpenSSH version do you have exactly?
Current CentOS 7 with its genuine OpenSSH package 
(openssh-7.4p1-21.el7.x86_64).
> Do you have special starting options?
Various hardened settings, but the only ones I'd *expect* to affect 
*logging* in *any* way would be:
> SyslogFacility AUTHPRIV
> UsePAM yes	# That's why there's messages from PAM in the log above
> UsePrivilegeSeparation sandbox
> Subsystem	sftp	internal-sftp
> Match group mandanten
>         PermitTTY no
>         ForceCommand internal-sftp -l INFO -u 0077
>> If a newly-started syslogd on server A does
>> indeed REMOVE AND RECREATE the /dev/log sockets,
> 
> If /dev dir under sftp user's chroot dir exists but there is no
"log" file in it, it gets created by syslog-ng.
> It is never removed afterwards.
If a .../dev/log is created within the .../dev/ directory *on the NFS 
share*, and never removed, that means that all the .../dev/log's there 
are were created *ONCE* by whichever syslogd got restarted *first* after 
the user was created, correct? But still only the syslogd restarted 
*last*, no matter whether on the same server or the other, gets that 
user's log messages? I'm getting a murder mystery vibe here ...

Regards,
-- 
Jochen Bern
Systemingenieur

Binect GmbH
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 3449 bytes
Desc: S/MIME Cryptographic Signature
URL:
<http://lists.mindrot.org/pipermail/openssh-unix-dev/attachments/20210929/1eb6b4ff/attachment-0001.p7s>

Hi Hildegard,

Hildegard Meier wrote:
> > I think that works specifically because *no* new process is created
> > when using internal-sftp as opposed to executing the sftp-server
binary.
> 
> For every sftp subsystem login (here with user "sftp_nagios"), I
> see a new sftpd process created:
..
> root      4192  0.0  0.1  72304  6512 ?        Ss   11:01   0:00
/usr/sbin/sftpd -D -f /etc/sftpd/sftpd_config
> root      4590  0.2  0.1  74736  6632 ?        Ss   11:05   0:00 sftpd:
sftp_nagios [priv]
> sftp_na+  4592  0.0  0.0  74736  3432 ?        S    11:05   0:00 sftpd:
sftp_nagios at notty
> sftp_na+  4593  0.0  0.0  74736  3108 ?        Ss   11:05   0:00 sftpd:
sftp_nagios at internal-sftp
Thanks, yes, you're correct that there are new processes. I should
have written different, refering to sshd vs. sftp-server:

sshd creates one child process for each incoming TCP connection (4590)
and after authentication it creates another child process (4592) which
runs as the authenticated user to handle the session, and then the
sftp subsystem channel is handled by yet another child process (4593).

These processes all run (different parts of) sshd, they do not
execute any other program, when using internal-sftp not even 4593.

This is relevant because as mentioned there is then no point where
sshd executes the sftp-server binary, so also no opportunity to use
LD_PRELOAD only for SFTP. All of sftp-server is built into sshd,
specifically to enable internal-sftp, with the great benefit that no
sftp-server binary is needed inside the chroot.

My thought was still wrong though. It could have been relevant for
the syslog() socket because that is closed automatically on exec()
and not on fork(), but sshd re-opens the syslog() socket right after
fork() so the internal-sftp vs. sftp-server makes no difference for
logging, only for LD_PRELOAD convenience.


Hildegard Meier wrote:
> Jochen Bern wrote:
> > If a newly-started syslogd on server A does
> > indeed REMOVE AND RECREATE the /dev/log sockets,
> 
> If /dev dir under sftp user's chroot dir exists but there is no
"log"
> file in it, it gets created by syslog-ng. It is never removed afterwards.
I had forgotten: AF_UNIX bind() to a filesystem address only succeeds
if the socket inode does not already exist in the filesystem.

So syslog-ng does what all AF_UNIX socket servers must: it unlinks the
socket from the filesystem first, so that a new socket inode can be
created by bind().

Jochen identified the problem.


Jochen Bern wrote:
> (The difference being that the socket itself would not have to store any 
> additional state about the open FDs pointing to it, which I doubt it has 
> any capacity for.)
The inode itself doesn't store anything, the kernel just maps the
filesystem inode to its socket object. Since the inode created by
daemon B means nothing within the kernel on system A, connecting to
that inode now also visible on system A doesn't reach daemon A.


Jochen Bern wrote:
> If that theory holds, then all we'd need to do is to force both 
> syslogd's to use *pre-existing* sockets instead ...
That's unfortunately not possible.


Hildegard Meier wrote:
> I think both the LD_PRELOAD and overlay fs approach are too
> complicated and hacky for me.
Fair enough, and overlayfs is only possible with a Linux NFS server.

There aren't very many other solutions:


* A patch to change SFTP logging

The attached patch adds an -E option to sftp-server (as exists for sshd)
to log to a specific file. With -E /sftp.log on the internal-sftp command
line in sshd_config on both servers they would then both log to a file in
the user's home directory. Beware of write contention on that log file
when the same user is connected to both servers.

Ensure that the file exists before using this configuration. Make file
ownership root:user and mode 620 if the user shouldn't be able to read it.

The patch is small, but until an equivalent is accepted in OpenSSH,
if ever, it requires maintaining a local package.

Note that as proposed this patch only works with a regular file, not
a syslog socket. Supporting a socket is of course possible but requires
a larger patch re-implementing much of syslog(). I can write that if
it would be accepted into OpenSSH.


* Add -e to the internal-sftp command line and create a custom parser

Because internal-sftp is still the sshd process this log message
parser must be connected already to the initial sshd stderr and must
handle anything that can be output on stderr by any sshd child process,
not just SFTP messages, making this alternative less attractive.


Kind regards

//Peter
-------------- next part --------------
A non-text attachment was scrubbed...
Name: 0001-Add-E-log_file-option-to-sftp-server.patch
Type: text/x-diff
Size: 2288 bytes
Desc: not available
URL:
<http://lists.mindrot.org/pipermail/openssh-unix-dev/attachments/20210930/9b40e2d4/attachment.bin>

Small clarification:

Hildegard Meier wrote:
> ps auxww |grep sftp
> root      4192  0.0  0.1  72304  6512 ?        Ss   11:01   0:00
/usr/sbin/sftpd -D -f /etc/sftpd/sftpd_config
> root      4590  0.2  0.1  74736  6632 ?        Ss   11:05   0:00 sftpd:
sftp_nagios [priv]
> sftp_na+  4592  0.0  0.0  74736  3432 ?        S    11:05   0:00 sftpd:
sftp_nagios at notty
> sftp_na+  4593  0.0  0.0  74736  3108 ?        Ss   11:05   0:00 sftpd:
sftp_nagios at internal-sftp
4192 /usr/sbin/sftpd is likely unrelated to OpenSSH.
I guess that this is a TLS FTP server.
Try  ps fax  to see process relationships.

The "sftpd:" prefix for the sshd processes may be related to SELinux;
nothing in OpenSSH is called sftpd, except the "sftpd_t" SELinux
context.


//Peter

I'm staring at this thread, and all of this complexity, and trying to
figure out "why are you hurting yourself doing this"? In the amount of
time burned trying to integrate hundreds of NFS mounts and chroot cage
configurations, you could have "vsftpd" to support FTPS rather than
SFTP, gotten clean isolated upload and download cages without having
to embed /dev/log in the chroot cages, enabled much simpler and stable
automounting, and spent the rest of the time on the lobbying effort
necessary to convince your user community to switch to FTPS enabled
clients.

Unless you have some compelling need for SSH key based access, why are
you spending these cycles on this work?