Bug 963

Summary: sudo-io logging causes rsync to hang
Product: Sudo Reporter: mathews.dennis
Component: SudoAssignee: Todd C. Miller <Todd.Miller>
Status: RESOLVED FIXED    
Severity: normal    
Priority: normal    
Version: 1.9.5   
Hardware: IBM   
OS: AIX   

Description mathews.dennis 2021-02-09 20:26:55 MST
All our servers have sudo io logging enabled. 
But rsync to these servers hang after some data is transferred and never completes, unless sudo-io logging is turned off.

I've tried disabling sudo-io logging for rsync, but that doesn't help. Completely disabling sudo-io logging allows rsync to complete without issues.
 
Cmnd_Alias NOLOG_OUT_CMDS = REBOOT, /usr/bin/sudoreplay, /opt/freeware/bin/sudoreplay, /usr/bin/find, /usr/bin/ps, /usr/sbin/lsof, /usr/bin/rsync, /usr/bin/tail, /usr/bin/less, /usr/bin/more, /usr/bin/pg, /usr/bin/dsmc, /usr/openv/netbackup/bin/bp*, /usr/bin/save, /usr/bin/savefs, /usr/bin/recover

Defaults log_input, log_output, ignore_iolog_errors
Defaults iolog_dir=/var/log/sudo-io/%{user}_%{runas_user}, maxseq=370
Defaults log_year, logfile=/var/log/sudo.log, !loglinelen
Defaults:NOLOG_USERS !log_input, !log_output
Defaults:NOLOG_OUT_USERS !log_output
Defaults!NOLOG_OUT_CMDS !log_output

Rsync and Sudo are both rpms from the IBM AIX Toolbox:

sudo -V
Sudo version 1.9.5p2
Sudoers policy plugin version 1.9.5p2
Sudoers file grammar version 48
Sudoers I/O plugin version 1.9.5p2
Sudoers audit plugin version 1.9.5p2

rsync -V
rsync  version 3.2.3  protocol version 31
Copyright (C) 1996-2020 by Andrew Tridgell, Wayne Davison, and others.
Web site: https://rsync.samba.org/
Capabilities:
    64-bit files, 64-bit inums, 64-bit timestamps, 64-bit long ints,
    socketpairs, hardlinks, hardlink-specials, symlinks, no IPv6, atimes,
    batchfiles, inplace, append, ACLs, no xattrs, optional protect-args,
    iconv, no symtimes, no prealloc, stop-at, no crtimes
Optimizations:
    no SIMD, no asm, openssl-crypto
Checksum list:
    md5 md4 none
Compress list:
    lz4 zlibx zlib none
Comment 1 Todd C. Miller 2021-02-10 06:18:03 MST
Can you give an example of how you are running rsync?  I'm guessing it is via ssh but more information would be helpful.
Comment 2 mathews.dennis 2021-02-11 05:21:39 MST
Yes we're running an ssh using Sudo on the target.
Here is an rsync command taken from one of our scripts:

rsync -avzS -e "/usr/bin/ssh -q -o pubkeyauthentication=no -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null" --rsync-path="sudo rsync" --delete /source_dir user@server:/dest_dir
Comment 3 mathews.dennis 2021-08-06 03:44:25 MDT
here are some more logs which hopefully helps:


# --------- These rsync processes hang on the target host.
root@hostxxxxxxxx [/root]# ps -ef|grep rsync
userXXXXX  9503014 16253296   0 19:14:53      -  0:00 sudo rsync --server -vlogDtprSze.iLsfxC --delete . /patches/aix/soefileshare
    root 11469104  9503014   0 19:14:53      -  0:00 rsync --server -vlogDtprSze.iLsfxC --delete . /patches/aix/soefileshare
userXXXXX 16253296        1   0 19:14:52      -  0:00 sudo rsync --server -vlogDtprSze.iLsfxC --delete . /patches/aix/soefileshare
    root 18350580 11207086   0 19:37:47 pts/18  0:00 grep rsync
    root 23527862 11469104   0 19:14:53      -  0:00 rsync --server -vlogDtprSze.iLsfxC --delete . /patches/aix/soefileshare
root@hostxxxxxxxx [/root]#

# -------------- Relevant sudo-io log files
root@hostxxxxxxxx [/root]# find /var/log/sudo-io/userXXXXX_root/00/00/52 -mtime -1 -ls
64544    1 drwx------  2 root      system         256 Aug  6 19:14 /var/log/sudo-io/userXXXXX_root/00/00/52
64545    1 -rw-------  1 root      system         136 Aug  6 19:14 /var/log/sudo-io/userXXXXX_root/00/00/52/log
64641    2 -rw-------  1 root      system        1362 Aug  6 19:14 /var/log/sudo-io/userXXXXX_root/00/00/52/log.json
64546 2304 -rw-------  1 root      system     2359296 Aug  6 19:14 /var/log/sudo-io/userXXXXX_root/00/00/52/stdin
64551    0 -rw-------  1 root      system           0 Aug  6 19:14 /var/log/sudo-io/userXXXXX_root/00/00/52/timing
64549    0 -rw-------  1 root      system           0 Aug  6 19:14 /var/log/sudo-io/userXXXXX_root/00/00/52/ttyin

root@hostxxxxxxxx [/root]# cat /var/log/sudo-io/userXXXXX_root/00/00/52/log
1628241293:userXXXXX:root::unknown:24:80
/home/userXXXXX
/usr/bin/rsync --server -vlogDtprSze.iLsfxC --delete . /patches/aix/soefileshare


root@hostxxxxxxxx [/root]# cat /var/log/sudo-io/userXXXXX_root/00/00/52/log.json
{
    "timestamp": {
        "seconds": 1628241293,
        "nanoseconds": 672847000
    },
    "submituser": "userXXXXX",
    "command": "/usr/bin/rsync",
    "runuser": "root",
    "submithost": "hostxxxxxxxx",
    "submitcwd": "/home/userXXXXX",
    "runuid": 0,
    "columns": 80,
    "lines": 24,
    "runargv": [
        "rsync",
        "--server",
        "-vlogDtprSze.iLsfxC",
        "--delete",
        ".",
        "/patches/aix/soefileshare"
    ],
    "runenv": [
        "PATH=/usr/bin:/etc:/usr/sbin:/usr/ucb:/usr/bin/X11:/sbin:/usr/java5/jre/bin:/usr/java5/bin",
        "TZ=EET-10EETDT,M10.1.0/02,M4.1.0/03",
        "LANG=en_AU.8859-15",
        "LOCPATH=/usr/lib/nls/loc",
        "NLSPATH=/usr/lib/nls/msg/%L/%N:/usr/lib/nls/msg/en_US.8859-15/%N:/usr/lib/nls/msg/%L/%N.cat:/usr/lib/nls/msg/en_US.8859-15/%N.cat:/usr/lib/nls/msg/%l.%c/%N:/usr/lib/nls/msg/%l.%c/%N.cat",
        "LC__FASTMSG=true",
        "ODMDIR=/etc/objrepos",
        "CLCMD_PASSTHRU=1",
        "MAIL=/var/spool/mail/userXXXXX",
        "LOGIN=root",
        "LOGNAME=root",
        "USER=root",
        "HOME=/root",
        "SHELL=/usr/bin/ksh",
        "TERM=unknown",
        "SUDO_COMMAND=/usr/bin/rsync --server -vlogDtprSze.iLsfxC --delete . /patches/aix/soefileshare",
        "SUDO_USER=userXXXXX",
        "SUDO_UID=80000572",
        "SUDO_GID=80000572"
    ]
}
Comment 4 Todd C. Miller 2022-06-06 20:12:48 MDT
I finally had a chance to reproduce this on an AIX machine (it wasn't reproducible on other systems).  The problem is that writes to the output pipe are returning EAGAIN after a while, even though poll() or select() say the pipe is writable.  Sudo was not handling this correctly and neglected to re-enabled the write event.  So once it got in this state the sudo process would basically wait forever.

I just committed a fix for this but unfortunately it did not make it into sudo 1.9.11 (it will be in the next release).
https://www.sudo.ws/repos/sudo/rev/0006cb6531f4
Comment 5 Todd C. Miller 2022-06-08 10:46:07 MDT
This is fixed in sudo 1.9.11p1