[Proftpd-user] mod_sql backend error: could not lookup local user ID

[Oli Kessler]

Hi all

We got strange errors recently with SFTP transfers:

* All users are in a postgreSQL DB
* A user has a quota of 100 MB (mod_quotatab_sql)
* In an authenticated session, the user uploads a file test1.bin of 60 MB successfully
* The user then uploads a file test2.bin of 50 MB which is denied correctly (quota issue)
* The user uploads the first file test1.bin again (trying to overwrite), gets denied when the 100MB is reached due to the temporary file
* Repeating the former process 4 to 5 times results in a server error and disconnection and leaves the temporary file ".in.test1.bin." in the directory * subsequent sessions can not upload/overwrite this file again due to the temporary file

The errors are (error log):

ProFTPD terminating (signal 11)
mod_sql/4.3: unrecoverable backend error: (mod_sql_postgres/4.0.4) could not look up local user ID 1001: No such file or directory#012
mod_sql/4.3: check the SQLLogFile for more details

In the STP log:

2017-05-17 18:04:58,843 mod_sftp/0.9.9[19535]: error writing to '/.in.test1.bin.': Operation not permitted
2017-05-17 18:05:08,497 mod_sftp/0.9.9[19535]: + Session key exchange: ecdh-sha2-nistp256
2017-05-17 18:05:08,497 mod_sftp/0.9.9[19535]: + Session server hostkey: ssh-dss
2017-05-17 18:05:08,497 mod_sftp/0.9.9[19535]: + Session client-to-server encryption: aes128-ctr
2017-05-17 18:05:08,497 mod_sftp/0.9.9[19535]: + Session server-to-client encryption: aes128-ctr
2017-05-17 18:05:08,497 mod_sftp/0.9.9[19535]: + Session client-to-server MAC: hmac-md5
2017-05-17 18:05:08,497 mod_sftp/0.9.9[19535]: + Session server-to-client MAC: hmac-md5
2017-05-17 18:05:08,497 mod_sftp/0.9.9[19535]: + Session client-to-server compression: none
2017-05-17 18:05:08,497 mod_sftp/0.9.9[19535]: + Session server-to-client compression: none
2017-05-17 18:05:08,503 mod_sftp/0.9.9[19535]: aborting 1 unclosed file handle


There is no information in the SQLLogFile about any errors, just normal lookups for users, logging to the DB etc.

I did not find the string "could not look up local user ID" in the sources of mod_sql or mod_sql_postgres.

Any ideas what this error "could not look up local user ID 1001: No such file or directory#012" means and where it comes from?

Cheers
-ok


$> proftpd -V

Compile-time Settings:
Version: 1.3.5d (maint)
Platform: LINUX [Linux 3.13.0-112-generic x86_64]
Built: Wed Feb 15 2017 14:49:06 CET
Built With:
configure '--prefix=/opt/cargo' '--enable-auth-pam=no' '--disable-ident' '--enable-facl' '--enable-cap' '--enable-nls' '--enable-shared=no' '--enable-static=yes' '--enable-dso=no' '--enable-openssl' '--enable-ctrls' '--enable-timeout-idle=300' '--enable-timeout-stalled=1800' '--enable-pcre' '--with-modules=mod_charset:mod_sql:mod_sftp_sql:mod_sftp:mod_sql_postgres:mod_quotatab:mod_quotatab_sql:mod_unique_id:mod_tls:mod_wrap2:mod_wrap2_sql:mod_sql_passwd:mod_ctrls_admin:mod_ban:mod_clamav:mod_diskuse:mod_exec:mod_deflate:mod_snmp:mod_copy:mod_geoip:mod_ifsession' 'CC=cc' 'CFLAGS=-fstack-protector-all'

CFLAGS: -fstack-protector-all -Wall
LDFLAGS: -L$(top_srcdir)/lib -L/usr/lib
LIBS: -lpcreposix -lpcre -lssl -lcrypto -lssl -lcrypto -lcap -lGeoIP -lssl -lm -lpq -lcrypto -lz -lsupp -lcrypt -ldl

Files:
Configuration File:
/opt/cargo/etc/proftpd.conf
Pid File:
/var/run/proftpd.pid
Scoreboard File:
/opt/cargo/var/proftpd.scoreboard

Features:
- Autoshadow support
+ Controls support
+ curses support
- Developer support
- DSO support
+ IPv6 support
+ Largefile support
- Lastlog support
- Memcache support
+ ncurses support
+ NLS support
+ OpenSSL support
+ PCRE support
+ POSIX ACL support
+ Shadow file support
+ Sendfile support
+ Trace support

Tunable Options:
PR_TUNABLE_BUFFER_SIZE = 1024
PR_TUNABLE_DEFAULT_RCVBUFSZ = 8192
PR_TUNABLE_DEFAULT_SNDBUFSZ = 8192
PR_TUNABLE_GLOBBING_MAX_MATCHES = 100000
PR_TUNABLE_GLOBBING_MAX_RECURSION = 8
PR_TUNABLE_HASH_TABLE_SIZE = 40
PR_TUNABLE_NEW_POOL_SIZE = 512
PR_TUNABLE_SCOREBOARD_BUFFER_SIZE = 80
PR_TUNABLE_SCOREBOARD_SCRUB_TIMER = 30
PR_TUNABLE_SELECT_TIMEOUT = 30
PR_TUNABLE_TIMEOUTIDENT = 10
PR_TUNABLE_TIMEOUTIDLE = 300
PR_TUNABLE_TIMEOUTLINGER = 30
PR_TUNABLE_TIMEOUTLOGIN = 300
PR_TUNABLE_TIMEOUTNOXFER = 300
PR_TUNABLE_TIMEOUTSTALLED = 1800
PR_TUNABLE_XFER_SCOREBOARD_UPDATES = 10

[Oli Kessler]

Hi all

We just switched to 1.3.5e due to http://bugs.proftpd.org/show_bug.cgi?id=4288 and did not see this behaviour again so far.

Might those errors be related to this?

Cheers
-ok

Post by Oli Kessler
Hi all
* All users are in a postgreSQL DB
* A user has a quota of 100 MB (mod_quotatab_sql)
* In an authenticated session, the user uploads a file test1.bin of 60 MB successfully
* The user then uploads a file test2.bin of 50 MB which is denied correctly (quota issue)
* The user uploads the first file test1.bin again (trying to overwrite), gets denied when the 100MB is reached due to the temporary file
* Repeating the former process 4 to 5 times results in a server error and disconnection and leaves the temporary file ".in.test1.bin." in the directory * subsequent sessions can not upload/overwrite this file again due to the temporary file
ProFTPD terminating (signal 11)
mod_sql/4.3: unrecoverable backend error: (mod_sql_postgres/4.0.4) could not look up local user ID 1001: No such file or directory#012
mod_sql/4.3: check the SQLLogFile for more details
2017-05-17 18:04:58,843 mod_sftp/0.9.9[19535]: error writing to '/.in.test1.bin.': Operation not permitted
2017-05-17 18:05:08,497 mod_sftp/0.9.9[19535]: + Session key exchange: ecdh-sha2-nistp256
2017-05-17 18:05:08,497 mod_sftp/0.9.9[19535]: + Session server hostkey: ssh-dss
2017-05-17 18:05:08,497 mod_sftp/0.9.9[19535]: + Session client-to-server encryption: aes128-ctr
2017-05-17 18:05:08,497 mod_sftp/0.9.9[19535]: + Session server-to-client encryption: aes128-ctr
2017-05-17 18:05:08,497 mod_sftp/0.9.9[19535]: + Session client-to-server MAC: hmac-md5
2017-05-17 18:05:08,497 mod_sftp/0.9.9[19535]: + Session server-to-client MAC: hmac-md5
2017-05-17 18:05:08,497 mod_sftp/0.9.9[19535]: + Session client-to-server compression: none
2017-05-17 18:05:08,497 mod_sftp/0.9.9[19535]: + Session server-to-client compression: none
2017-05-17 18:05:08,503 mod_sftp/0.9.9[19535]: aborting 1 unclosed file handle
There is no information in the SQLLogFile about any errors, just normal lookups for users, logging to the DB etc.
I did not find the string "could not look up local user ID" in the sources of mod_sql or mod_sql_postgres.
Any ideas what this error "could not look up local user ID 1001: No such file or directory#012" means and where it comes from?
Cheers
-ok
$> proftpd -V
Version: 1.3.5d (maint)
Platform: LINUX [Linux 3.13.0-112-generic x86_64]
Built: Wed Feb 15 2017 14:49:06 CET
configure '--prefix=/opt/cargo' '--enable-auth-pam=no' '--disable-ident' '--enable-facl' '--enable-cap' '--enable-nls' '--enable-shared=no' '--enable-static=yes' '--enable-dso=no' '--enable-openssl' '--enable-ctrls' '--enable-timeout-idle=300' '--enable-timeout-stalled=1800' '--enable-pcre' '--with-modules=mod_charset:mod_sql:mod_sftp_sql:mod_sftp:mod_sql_postgres:mod_quotatab:mod_quotatab_sql:mod_unique_id:mod_tls:mod_wrap2:mod_wrap2_sql:mod_sql_passwd:mod_ctrls_admin:mod_ban:mod_clamav:mod_diskuse:mod_exec:mod_deflate:mod_snmp:mod_copy:mod_geoip:mod_ifsession' 'CC=cc' 'CFLAGS=-fstack-protector-all'
CFLAGS: -fstack-protector-all -Wall
LDFLAGS: -L$(top_srcdir)/lib -L/usr/lib
LIBS: -lpcreposix -lpcre -lssl -lcrypto -lssl -lcrypto -lcap -lGeoIP -lssl -lm -lpq -lcrypto -lz -lsupp -lcrypt -ldl
/opt/cargo/etc/proftpd.conf
/var/run/proftpd.pid
/opt/cargo/var/proftpd.scoreboard
- Autoshadow support
+ Controls support
+ curses support
- Developer support
- DSO support
+ IPv6 support
+ Largefile support
- Lastlog support
- Memcache support
+ ncurses support
+ NLS support
+ OpenSSL support
+ PCRE support
+ POSIX ACL support
+ Shadow file support
+ Sendfile support
+ Trace support
PR_TUNABLE_BUFFER_SIZE = 1024
PR_TUNABLE_DEFAULT_RCVBUFSZ = 8192
PR_TUNABLE_DEFAULT_SNDBUFSZ = 8192
PR_TUNABLE_GLOBBING_MAX_MATCHES = 100000
PR_TUNABLE_GLOBBING_MAX_RECURSION = 8
PR_TUNABLE_HASH_TABLE_SIZE = 40
PR_TUNABLE_NEW_POOL_SIZE = 512
PR_TUNABLE_SCOREBOARD_BUFFER_SIZE = 80
PR_TUNABLE_SCOREBOARD_SCRUB_TIMER = 30
PR_TUNABLE_SELECT_TIMEOUT = 30
PR_TUNABLE_TIMEOUTIDENT = 10
PR_TUNABLE_TIMEOUTIDLE = 300
PR_TUNABLE_TIMEOUTLINGER = 30
PR_TUNABLE_TIMEOUTLOGIN = 300
PR_TUNABLE_TIMEOUTNOXFER = 300
PR_TUNABLE_TIMEOUTSTALLED = 1800
PR_TUNABLE_XFER_SCOREBOARD_UPDATES = 10
------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot
_______________________________________________
Unsubscribe problems?
http://www.proftpd.org/list-unsub.html

[TJ Saunders]

Post by Oli Kessler
There is no information in the SQLLogFile about any errors, just normal
lookups for users, logging to the DB etc.
I did not find the string "could not look up local user ID" in the
sources of mod_sql or mod_sql_postgres.
Any ideas what this error "could not look up local user ID 1001: No such
file or directory#012" means and where it comes from?

Could you provide the proftpd.conf you're using, particularly the
mod_sftp and mod_sql configurations, please? That configuration will
help narrow down the possibilities...

Do you happen to see/encounter this issue when using ProFTPD 1.3.6?

Cheers,
TJ

[Oli Kessler]

Hi all

Below are the relevant configuration fragments we use.

The update to 1.3.5e did not really help, we still see the issue.
We can not currently deploy 1.3.6 on this production system.

Some notes to our configuration
* Users are all in the postgres DB, no OS users
* We use HiddenStore
* We use fake user and group information
* SQLUserInfo uses custom queries per virtual host to allow service specific lookups

Thanks for your support.

Cheers
-ok


<Global>
...

HiddenStores on
AllowStoreRestart off
DeleteAbortedStores on

# hide real ID, GID and file modes - "~" will use the current users data
DirFakeGroup on "~"
DirFakeUser on "~"
DirFakeMode 0640

SQLBackend postgres
SQLConnectInfo ......
AuthOrder mod_sql.c
SQLAuthenticate users
SQLPasswordEngine on

SQLNamedQuery get-user-salt SELECT "u.password_salt from users u where char_length('%{0}') >= 2 AND \
(select case(select cast(value as boolean) from configurables where name = 'ignore_case_on_login') when true then lower(u.login) else u.login end) = \
(select case(select cast(value as boolean) from configurables where name = 'ignore_case_on_login') when true then lower('%{0}') else '%{0}' end) \
OR (lower(u.email) = lower('%{0}'))"
SQLPasswordUserSalt sql:/get-user-salt
SQLAuthTypes SHA512

# we will use high UID/GID values
SQLMinUserUID 1000
SQLDefaultGID 1000
SQLMinUserGID 1000
SQLDefaultUID 1000

# get group information from the DB
SQLGroupInfo custom:/get-group-by-name/get-group-by-id/get-group-by-member/get-all-groupnames/get-all-groups
SQLNamedQuery get-group-by-name SELECT "g.name, g.system_id, u.login from groups g, users u, groups_users ug where \
u.id = ug.user_id and g.id = ug.group_id and g.name = '%{0}'"
SQLNamedQuery get-group-by-id SELECT "g.name, g.system_id, u.login from groups g, users u, groups_users ug where \
u.id = ug.user_id and g.id = ug.group_id and g.system_id = '%{0}'"
SQLNamedQuery get-group-by-member SELECT "g.name, g.system_id, u.login from groups g, users u, groups_users ug where \
u.id = ug.user_id and g.id = ug.group_id and u.login = '%{0}'"
SQLNamedQuery get-all-groupnames SELECT "g.name from groups g"
SQLNamedQuery get-all-groups SELECT "g.name, g.system_id, u.login from groups g, users u, groups_users ug where \
u.id = ug.user_id and g.id = ug.group_id"

# get user information from the DB
SQLUserInfo custom:/get-user-by-name/get-user-by-id/get-user-names/get-all-users

# get_user_by_name is defined in the virtual servers!

SQLNamedQuery get-user-by-id SELECT "u.login, u.encrypted_password, u.system_id, g.system_id, u.home, \
'/bin/bash' from users u, groups g, groups_users ug where u.id = ug.user_id and g.id = ug.group_id and u.system_id ='%{0}'"
SQLNamedQuery get-user-names SELECT "u.login from users u"
SQLNamedQuery get-all-users SELECT "u.login ,u.encrypted_password, u.system_id, g.system_id, u.home, \
'/bin/bash' from users u, groups g, groups_users ug where u.id = ug.user_id and g.id = ug.group_id"

</Global>

# ============================
# SFTP - own virtual host for different port
# http://www.proftpd.org/docs/contrib/mod_sftp.html
# ============================
<IfModule mod_sftp.c>
<VirtualHost X.X.X.X>
ServerName "CargoSFTP"
Port 22
AuthOrder mod_sql.c
SFTPEngine on

# needs services SFTP
SQLNamedQuery get-user-by-name SELECT "u.login, u.encrypted_password, u.system_id, g.system_id, u.home, \
'/bin/bash' from users u, groups g, groups_users ug, services s, activated_services us \
where char_length('%U') >= 2 AND u.id = ug.user_id and g.id = ug.group_id and s.id = us.service_id and us.user_id = u.id AND (\
(select case(select cast(value as boolean) from configurables where name = 'ignore_case_on_login') when true then lower(u.login) else u.login end) = \
(select case(select cast(value as boolean) from configurables where name = 'ignore_case_on_login') when true then lower('%U') else '%U' end) OR \
lower(u.email) = lower('%U')) \
AND s.name = 'SFTP' and u.is_locked = false and u.is_admin = false"

# allow public key
SQLNamedQuery get-user-authorized-keys SELECT "u.public_key FROM users u, services s, activated_services us \
where char_length('%U') >= 2 AND u.id = us.user_id and s.id = us.service_id AND s.name = 'SFTP' and u.is_locked = false and u.is_admin = false AND \
(select case(select cast(value as boolean) from configurables where name = 'ignore_case_on_login') when true then lower(u.login) else u.login end) = \
(select case(select cast(value as boolean) from configurables where name = 'ignore_case_on_login') when true then lower('%U') else '%U' end) OR \
lower(u.email) = lower('%U')"
SFTPAuthorizedUserKeys sql:/get-user-authorized-keys
SFTPCompression delayed
SFTPHostKey /opt/cargo/etc/ssh_dsa_host_key-sftp
SFTPLog /var/log/sftp.log
MaxLoginAttempts 6

# ignore permission setting triggered by the client
# and disable the KEXINIT optimization at the cost of latency (some client do not like it)
SFTPOptions IgnoreSFTPUploadPerms IgnoreSCPUploadPerms PessimisticKexinit

# Only support SFTP protocol version 1 through 3 for WinSCP and CuteFTP
SFTPClientMatch WinSCP|ClientSftp sftpProtocolVersion 1-3
SFTPClientMatch ".*WS_FTP.*" channelWindowSize 32MB

# Ubuntu sends LC_MESSAGES and gets denied otherwise
SFTPAcceptEnv LC_MESSAGES LANG LOGINUSER

SFTPDigests hmac-md5 hmac-sha1 hmac-sha2-256 hmac-sha2-512 hmac-ripemd160 hmac-sha1-96 hmac-md5-96
</VirtualHost>
</IfModule>

Post by TJ Saunders

Post by Oli Kessler
There is no information in the SQLLogFile about any errors, just normal
lookups for users, logging to the DB etc.
I did not find the string "could not look up local user ID" in the
sources of mod_sql or mod_sql_postgres.
Any ideas what this error "could not look up local user ID 1001: No such
file or directory#012" means and where it comes from?

Could you provide the proftpd.conf you're using, particularly the
mod_sftp and mod_sql configurations, please? That configuration will
help narrow down the possibilities...
Do you happen to see/encounter this issue when using ProFTPD 1.3.6?
Cheers,
TJ
------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot
_______________________________________________
Unsubscribe problems?
http://www.proftpd.org/list-unsub.html

[TJ Saunders]

Post by Oli Kessler
Below are the relevant configuration fragments we use.

Thanks!

Does your configuration use "DefaultRoot ~" or somesuch for your logins
as well?

The "could not look up local user ID" error string is coming from libpq,
the Postgres client library. There are only a few places where this
string is used in their source code, e.g.:

https://git.postgresql.org/gitweb/?p=postgresql.git;a=blob;f=src/interfaces/libpq/fe-auth.c;h=f4397afc64901bd30bdfafb7489e544e4d078def;hb=HEAD#l1055

In all the cases I found, the libpq code is attempting to resolve the
UID using the system files (such as /etc/passwd) to a name. If this
happens _after_ the initial authentication has succeeded, AND a
chroot(2) has occurred, then those attempts to resolve the UID will
fail. (And perhaps that is where the SIGSEGV ("signal 11") happens as
well; many libraries do not react well to operating in a chroot.)

Thus if you *are* using "DefaultRoot ~", as an experiment, you might
disable that and see if it helps/changes your use case.

In the mean time, I'll be trying to reproduce this behavior locally;
there may be _other_ issues involved that lead to the problematic
behavior.

Cheers,
TJ