#28 second try works for a blocked host

pending-fixed
danta
PAM Module (12)
5
2012-11-12
2012-09-03
No

Hello,
each second authentication for blocked gost work but it shouldn't!

latest version 5.0.0

setup with default config

tail -f /var/log/auth.log
Sep 3 15:54:18 bioinfws14 pam-abl[21452]: Blocking access from xxx to service sshd, user alex
Sep 3 15:54:18 bioinfws14 sshd[21452]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=xxx user=alex
Sep 3 15:54:20 bioinfws14 sshd[21452]: Failed password for alex from 192.168.10.134 port 43508 ssh2
Sep 3 15:54:27 bioinfws14 pam-abl[21452]: Operation not permitted (1) while opening the database environment
Sep 3 15:54:27 bioinfws14 pam-abl[21452]: Operation not permitted (1) while Creating database environment.
Sep 3 15:54:27 bioinfws14 pam-abl[21452]: The database environment could not be opened
Sep 3 15:54:27 bioinfws14 sshd[21452]: pam_unix(sshd:account): account alex has password changed in future
Sep 3 15:54:27 bioinfws14 sshd[21452]: Accepted password for alex from 192.168.10.134 port 43508 ssh2
Sep 3 15:54:27 bioinfws14 sshd[21452]: pam_unix(sshd:session): session opened for user alex by (uid=0)
Sep 3 15:54:29 bioinfws14 sshd[21580]: Received disconnect from 192.168.10.134: 11: disconnected by user
Sep 3 15:54:29 bioinfws14 sshd[21452]: pam_unix(sshd:session): session closed for user alex
Sep 3 15:54:29 bioinfws14 sshd[21452]: PAM 1 more authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=xxx user=alex

#pam_abl
Failed users:
alex (3)
Blocked based on rule [*]
root (1)
Not blocking
toor (2)
Not blocking
Failed hosts:
xxx (6)
Blocked based on rule [*]

what else information can I provide?

Thank you,
Alex

Discussion

  • danta
    danta
    2012-09-03

    • assigned_to: nobody --> danta
     
  • danta
    danta
    2012-09-03

    Apparently it has some problems opening the db: "Operation not permitted (1) while opening the database environment". I guess it has something to do with file permissions maybe. Although that doesn't explain why it sometimes fails.
    As I understand you correctly when a user/host is blocked the next attempt is blocked but a following attempt is not.

    Could you retest with debug on? Just add "debug" to the pam-abl line in the pam config file for your service. And send me the output please.

    Could you give me a list of all the db files and their permissions. (all files under "/var/lib/abl" if you use the default config)
    If you don't mind can you sent me a copy of your db environment? (all files in the db_home dir and the databases itself)

    Does sshd run as root?

    What Berkeley db version do you use?

    Can you run the test executable and sent me the output?

    Are there a lot of authentications the moment you get "Operation not permitted (1) while opening the database environment" in the logs?

    On what filesystem are the databases located? Berkeley db uses file locks to implement locking. Perhaps something goes wrong there.

    Best regards,
    Lode

     
  • /var/log/auth in debug mode

     
    Attachments
  • >As I understand you correctly when a user/host is blocked the next attempt
    >is blocked but a following attempt is not.

    Exactly,

    >Could you retest with debug on? Just add "debug" to the pam-abl line in the
    >pam config file for your service. And send me the output please.
    I've attached file pam_abl_debug.txt

    in the begining the user alex wasn't blacklisted, so I mistyped password a few times to blacklist the host.
    after that I tried to login again with the correct pass and was blocked but the next attempt was successfull.

    list of files with the permissions:

    /var/lib/abl 755,

    /var/lib/abl# ls -l
    total 900
    -rw-r----- 1 root root 24576 Sep 4 14:15 __db.001
    -rw-r----- 1 root root 212992 Sep 4 14:15 __db.002
    -rw-r----- 1 root root 270336 Sep 4 14:15 __db.003
    -rw-r----- 1 root root 163840 Sep 4 14:15 __db.004
    -rw-r----- 1 root root 811008 Sep 4 14:15 __db.005
    -rw-r----- 1 root root 49152 Sep 4 14:15 __db.006
    -rw-r----- 1 root root 50 Sep 4 14:15 __db.register
    -rw------- 1 root root 16384 Sep 4 14:15 hosts.db
    -rw-r----- 1 root root 10485760 Sep 4 14:15 log.0000000001
    -rw------- 1 root root 16384 Sep 4 14:15 users.db

    sshd is started as root, but chaild process is unprivileged ( userid )
    pstree -us 860
    init───sshd─┬─sshd───bash
    ├─sshd───bash───pstree
    └─sshd───sshd(alex)───bash

    db version is 5.1.25.
    this box has almost no traffic and authentications attempts I was testing it on an internal workstation.

    filesystem is ext4
    / type ext4 (rw,noatime,nodiratime,errors=remount-ro,user_xattr,acl,barrier=1,data=ordered) (it's an ssd)

    I'll attach another file with pam-abl_test output

    thank you,
    Alex

     
  • output of pam-abl_test binary

     
    Attachments
  • /var/lib/abl/ files

     
    Attachments
  • danta
    danta
    2012-09-04

    To be honest, I have no idea what goes wrong. Everything you gave me looks ok. (I wasn't able to check the db files, because I only have a x64 build). The test succeed, so the db should work.

    When I have some more time (probably in the weekend), I'll try to fully reproduce your problem (32 bit machine, ext4, sshd, ...).
    Can you give me your ssh pam config?

    Can you reproduce the problem using another service? Or using pam-tester or something similar? (If you want I can give you the source of the tool I use to test my pam configs)

    If it's not to much trouble, can you strace sshd for me while the problem occurs and send me the log?
    Because apparently a EPERM is returned and I have no idea if it's caused by libdb or by the underlying glibc.

    Best regards,
    Lode

     
  • danta
    danta
    2012-09-04

    • labels: --> PAM Module
     
  • Sorry for the late answer,
    I had no time to look on this problem. I'll try to find some time on the weekend/beginning of the week.

    I tried to compile new pam_abl code on debian squeeze.
    but than I got the following result:

    cmake ../
    -- The C compiler identification is GNU
    -- The CXX compiler identification is GNU
    -- Check for working C compiler: /usr/bin/gcc
    -- Check for working C compiler: /usr/bin/gcc -- works
    -- Detecting C compiler ABI info
    -- Detecting C compiler ABI info - done
    -- Check for working CXX compiler: /usr/bin/c++
    -- Check for working CXX compiler: /usr/bin/c++ -- works
    -- Detecting CXX compiler ABI info
    -- Detecting CXX compiler ABI info - done
    -- Found PAM: /usr/lib/libpam.so;/usr/lib/libpam_misc.so;/usr/lib/libpamc.so
    -- Configuring done
    -- Generating done
    -- Build files have been written to: /data/packages/pam-abl/libpam-abl/xxx
    myhost:/data/packages/pam-abl/libpam-abl/xxx# make
    Scanning dependencies of target pam-abl_bin
    [ 4%] Building C object CMakeFiles/pam-abl_bin.dir/config.c.o
    /data/packages/pam-abl/libpam-abl/config.c: In function ‘parse_arg’:
    /data/packages/pam-abl/libpam-abl/config.c:97: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/config.c:97: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/config.c:97: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/config.c:97: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/config.c:97: warning: will never be executed
    [ 8%] Building C object CMakeFiles/pam-abl_bin.dir/dbfun.c.o
    [ 12%] Building C object CMakeFiles/pam-abl_bin.dir/log.c.o
    [ 16%] Building C object CMakeFiles/pam-abl_bin.dir/pam_abl.c.o
    /data/packages/pam-abl/libpam-abl/pam_abl.c: In function ‘runCommand’:
    /data/packages/pam-abl/libpam-abl/pam_abl.c:126: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/pam_abl.c: In function ‘whitelistMatch’:
    /data/packages/pam-abl/libpam-abl/pam_abl.c:444: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/pam_abl.c:447: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/pam_abl.c:447: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/pam_abl.c:413: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/pam_abl.c:418: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/pam_abl.c:421: warning: will never be executed
    [ 20%] Building C object CMakeFiles/pam-abl_bin.dir/rule.c.o
    [ 24%] Building C object CMakeFiles/pam-abl_bin.dir/typefun.c.o
    [ 28%] Building C object CMakeFiles/pam-abl_bin.dir/tools.c.o
    /data/packages/pam-abl/libpam-abl/tools.c: In function ‘doshow’:
    /data/packages/pam-abl/libpam-abl/tools.c:258: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/tools.c: In function ‘main’:
    /data/packages/pam-abl/libpam-abl/tools.c:751: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/tools.c:751: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/tools.c:751: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/tools.c:751: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/tools.c:751: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/tools.c:753: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/tools.c:753: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/tools.c:753: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/tools.c:753: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/tools.c:753: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/tools.c:755: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/tools.c:755: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/tools.c:755: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/tools.c:755: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/tools.c:755: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/tools.c:757: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/tools.c:757: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/tools.c:757: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/tools.c:757: warning: will never be executed
    /data/packages/pam-abl/libpam-abl/tools.c:757: warning: will never be executed
    Linking C executable pam_abl
    /usr/bin/ld: cannot find -llibdb
    collect2: ld returned 1 exit status
    make[2]: *** [pam_abl] Error 1
    make[1]: *** [CMakeFiles/pam-abl_bin.dir/all] Error 2
    make: *** [all] Error 2

    I don't know what is wrong there, libdb 4.8 is installed .
    ls -l /usr/lib/libdb.so
    lrwxrwxrwx 1 root root 12 Feb 2 2011 /usr/lib/libdb.so -> libdb-4.8.so

    Do you have any hint for this issue?

    Best regards,
    Alex

     
  • Hello,

    a bit more information:

    this is my pam file for sshd

    /etc/pam.d/sshd
    auth required pam_env.so # [1]
    auth required pam_env.so envfile=/etc/default/locale
    auth required pam_abl.so config=/etc/security/pam_abl.conf debug
    auth [success=2 default=ignore] pam_unix.so nullok_secure
    auth [success=1 default=ignore] pam_ldap.so use_first_pass
    auth requisite pam_deny.so
    auth required pam_permit.so
    account required pam_nologin.so
    ..
    <skip>

    I tried the following config but got the same result:

    auth required pam_env.so # [1]
    auth required pam_env.so envfile=/etc/default/locale
    auth required pam_abl.so config=/etc/security/pam_abl.conf debug
    auth sufficient pam_unix.so nullok_secure

    So within the same ssh session:

    ssh alex@host_w_abl
    alex@host_w_abl's password:
    Permission denied, please try again.
    alex@host_w_abl's password:
    Welcome to Ubuntu 12.04.1 LTS (GNU/Linux 3.2.0-26-generic x86_64)

    second attempt was successfull.

    on the host with pam_abl
    /var/log/auth.log

    Sep 8 12:46:38 host_w_abl sshd[11325]: Received disconnect from 192.168.194.134: 11: disconnected by user
    Sep 8 12:46:38 host_w_abl sshd[11186]: pam_unix(sshd:session): session closed for user alex
    Sep 8 12:46:38 host_w_abl sshd[11186]: PAM 1 more authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=myhost.mydomain user=alex
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: debug = 1
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: db_home = /var/lib/abl
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: host_db = /var/lib/abl/hosts.db
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: host_rule = *:5/1h
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: host_purge = 86400
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: host_blk_cmd = logger block host %h
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: user_db = /var/lib/abl/users.db
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: user_rule = *:3/1h
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: user_purge = 86400
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: user_blk_cmd = logger block user %u
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: lower limit = 1000
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: upper limit = 1200
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: str[0x7fc7f1933710] = user_whitelist=danta;chris
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: str[0x7fc7f19336d0] = host_whitelist=1.1.1.1/24;2.1.1.1
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: str[0x7fc7f19336a0] = limits=1000-1200
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: str[0x7fc7f1935ca0] = user_blk_cmd=logger block user %u
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: str[0x7fc7f1935c60] = user_clr_cmd=logger clear user %u
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: str[0x7fc7f1935c20] = host_blk_cmd=logger block host %h
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: str[0x7fc7f1935be0] = host_clr_cmd=logger clear host %h
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: str[0x7fc7f1935bb0] = user_rule=*:3/1h
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: str[0x7fc7f1935b90] = user_purge=1d
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: str[0x7fc7f1935b60] = user_db=/var/lib/abl/users.db
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: str[0x7fc7f1935b30] = host_rule=*:5/1h
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: str[0x7fc7f1935b10] = host_purge=1d
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: str[0x7fc7f1935ae0] = host_db=/var/lib/abl/hosts.db
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: str[0x7fc7f191ff30] = db_home=/var/lib/abl
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: state opened
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: state opened
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: Check myhost.mydomain/sshd against *:5/1h(1)
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: Name part matches, **rp = ':'
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: Match!
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: Name matched, next char is ':'
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: matchperiod(0x7fc7f1939530, 3, '5/1h')
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: count is 5, **rp='/'
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: period is 3600, **rp='#000'
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: Checking 5/3600
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: howmany(3600) = 3
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: Check alex/sshd against *:3/1h(1)
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: Name part matches, **rp = ':'
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: Match!
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: Name matched, next char is ':'
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: matchperiod(0x7fc7f1939530, 3, '3/1h')
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: count is 3, **rp='/'
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: period is 3600, **rp='#000'
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: Checking 3/3600
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: howmany(3600) = 3
    Sep 8 12:46:56 host_w_abl pam-abl[11604]: Blocking access from myhost.mydomain to service sshd, user alex
    Sep 8 12:46:56 host_w_abl sshd[11604]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=myhost.mydomain user=alex
    Sep 8 12:46:58 host_w_abl sshd[11604]: Failed password for alex from 192.168.194.134 port 33262 ssh2
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: debug = 1
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: db_home = /var/lib/abl
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: host_db = /var/lib/abl/hosts.db
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: host_rule = *:5/1h
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: host_purge = 86400
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: host_blk_cmd = logger block host %h
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: user_db = /var/lib/abl/users.db
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: user_rule = *:3/1h
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: user_purge = 86400
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: user_blk_cmd = logger block user %u
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: lower limit = 1000
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: upper limit = 1200
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: str[0x7fc7f193cf80] = user_whitelist=danta;chris
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: str[0x7fc7f19598a0] = host_whitelist=1.1.1.1/24;2.1.1.1
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: str[0x7fc7f193cf50] = limits=1000-1200
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: str[0x7fc7f196cbe0] = user_blk_cmd=logger block user %u
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: str[0x7fc7f1959a10] = user_clr_cmd=logger clear user %u
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: str[0x7fc7f1979080] = host_blk_cmd=logger block host %h
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: str[0x7fc7f1979040] = host_clr_cmd=logger clear host %h
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: str[0x7fc7f1979010] = user_rule=*:3/1h
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: str[0x7fc7f194f9f0] = user_purge=1d
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: str[0x7fc7f1978fe0] = user_db=/var/lib/abl/users.db
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: str[0x7fc7f1978fb0] = host_rule=*:5/1h
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: str[0x7fc7f19525b0] = host_purge=1d
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: str[0x7fc7f1978f80] = host_db=/var/lib/abl/hosts.db
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: str[0x7fc7f1978f50] = db_home=/var/lib/abl
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: Operation not permitted (1) while opening the database environment
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: Operation not permitted (1) while Creating database environment.
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: The database environment could not be opened
    Sep 8 12:47:03 host_w_abl sshd[11604]: pam_unix(sshd:account): account alex has password changed in future
    Sep 8 12:47:03 host_w_abl sshd[11604]: Accepted password for alex from 192.168.194.134 port 33262 ssh2
    Sep 8 12:47:03 host_w_abl pam-abl[11604]: In cleanup, err is 20000000
    Sep 8 12:47:03 host_w_abl sshd[11604]: pam_unix(sshd:session): session opened for user alex by (uid=0)

    a connection to the host spawns 2 sshd processes:

    root 14504 13948 0 13:12 ? 00:00:00 sshd: root@pts/2
    root 15005 13948 0 13:17 ? 00:00:00 sshd: testabl [priv]
    sshd 15006 15005 0 13:17 ? 00:00:00 sshd: testabl [net]

    the strace logs will be attached as:
    strace_sshd_15005.log
    strace_sshd_15006.log

    the main process doesn't seem to do much according strace output. it's similar to the following:

    select(8, [3 4], NULL, NULL, NULL) = 1 (in [3])
    accept(3, {sa_family=AF_INET, sin_port=htons(33568), sin_addr=inet_addr("192.168.194.134")}, [16]) = 5
    fcntl(5, F_GETFL) = 0x2 (flags O_RDWR)
    pipe([6, 7]) = 0
    socketpair(PF_FILE, SOCK_STREAM, 0, [8, 9]) = 0
    clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f6dce4a3a90) = 15756
    close(7) = 0
    write(8, "\0\0\2\263\0", 5) = 5
    write(8, "\0\0\2\252\n\n\n\nPort 22\n\n\n\nProtocol 2\n\nH"..., 690) = 690
    close(8) = 0
    close(9) = 0
    close(5) = 0
    select(8, [3 4 6], NULL, NULL, NULL) = 1 (in [6])
    close(6) = 0
    select(8, [3 4], NULL, NULL, NULL <unfinished ...>

    >Can you reproduce the problem using another service? Or using pam-tester or
    >something similar? (If you want I can give you the source of the tool I use
    >to test my pam configs)

    When I tried it with the login I received the following output:
    #login
    host_w_abl login: root

    Login incorrect
    pam-abl: DB_REGISTER limits processes to one open DB_ENV handle per environment
    I think this is related to :
    Operation not permitted (1) while opening the database environment".

    Best regards,
    Alex

     
  • strace 4 sshd

     
    Attachments
  • danta
    danta
    2012-09-09

    k, didn't have that much time as I expected, so I just played around with the sshd pam config of my fileserver. Not exactly the same filesystem, berkeley db, ... as you, but it's the best I could do with so little time.

    I could reproduce something that looks like your problem (the symptoms look the same, but the error message is different, although I also get the "DB_REGISTER limits processes to one open DB_ENV handle per environment" message), so I just need your help to be sure it's exactly the same.
    My sshd pam config is based on what you gave me and the default provided by ubuntu:

    # PAM configuration for the Secure Shell service
    auth required pam_env.so # [1]
    auth required pam_env.so envfile=/etc/default/locale
    auth required /home/danta/pam-abl/cmake_build/pam-abl.so config=/tmp/pam-abl/pam_abl.conf
    auth [success=1 default=ignore] pam_unix.so nullok_secure
    auth requisite pam_deny.so
    auth required pam_permit.so
    account required pam_nologin.so
    # Standard Un*x authentication.
    @include common-auth
    # Disallow non-root logins when /etc/nologin exists.
    account required pam_nologin.so
    # Uncomment and edit /etc/security/access.conf if you need to set complex
    # access limits that are hard to express in sshd_config.
    # account required pam_access.so
    # Standard Un*x authorization.
    @include common-account
    # Standard Un*x session setup and teardown.
    @include common-session
    # Print the message of the day upon successful login.
    session optional pam_motd.so # [1]
    # Print the status of the user's mailbox upon successful login.
    session optional pam_mail.so standard noenv # [1]
    # Set up user limits from /etc/security/limits.conf.
    session required pam_limits.so
    # Set up SELinux capabilities (need modified pam)
    # session required pam_selinux.so multiple
    # Standard Un*x password updating.
    @include common-password

    My pam-abl config is:
    db_home=/tmp/pam-abl
    host_db=/tmp/pam-abl/hosts.db
    host_purge=1d
    host_rule=*:2/1h
    user_db=/tmp/pam-abl/users.db
    user_purge=1d
    user_rule=*:2/1h
    limits=1000-1200

    When I want to start an ssh connection I get 3 attempts to authenticate:
    first attempt: wrong password => login failed
    second attempt: wrong password => login failed
    thirth attempt: wrong password => login failed

    If I get the list of blocked users I notice that only one failed attempt is logged. If at any time in these attempts I type in the correct password, login succeeds.
    Given the config I should already be blocked (only two failed attempts our allowed), but this is not the case. If I try to reconnect I get another three attempts:
    first attempt: wrong password => login failed
    second attempt: wrong password => login failed
    thirth attempt: wrong password => login failed

    If I now get the list of blocked users I notice that we now have two failed login attempts for my username. If at any time in these attempts I type in the correct password, login succeeds.

    Only when I now try to reconnect I'm always blocked by pam_abl, even if I use the correct password.

    Does this describe your problem?

    If you want to build pam-abl from source and make can't find your libdb, you can always override the loacation where he looks for it. For example I use the following command to build pam-abl:
    cmake -DDB_INCLUDE_DIR=/db-5.3.15/include/ -DDB_LINK_DIR=/db-5.3.15/lib/ -DDB_LIBRARY=db-5.3 ../

    Btw: thanks for all the time and effort you have put into answering all my questions.
    Best regards,
    Lode

     
  • Petr Písař
    Petr Písař
    2012-09-12

    I'm giving a try to pam_abl-0.5.0 wit db-4.8.30 and I have similar problem.

    My configutaion is:

    #debug
    db_home=/var/lib/abl
    host_db=/var/lib/abl/hosts.db
    host_purge=30d
    host_rule=*:5/1h
    user_db=/var/lib/abl/users.db
    user_purge=30d
    user_rule=!*:5/1h

    My openssh-5.9_p1 server is configured:

    UsePAM yes
    PasswordAuthentication yes
    ChallengeResponseAuthentication no

    and it/PAM allows three consequent attempts an SSH session.

    First failure does not touch database nor log anything into syslog about pam_abl. Second attempt creates empty database (if no database files existed before) and logs the messages about not permitted operation and that the environment could not be opened. Third attempt stores a failure into database but does not log anything about pam_abl into syslog. Result is counter increased by one in the database for the user and the host.

    strace of sshd from second attempt follows.

    -- Petr

    open("/var/lib/abl/DB_CONFIG", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)
    stat64("/var/tmp", {st_mode=S_IFDIR|S_ISVTX|0777, st_size=4096, ...}) = 0
    open("/var/lib/abl/__db.register", O_RDWR|O_CREAT|O_LARGEFILE, 0660) = 11
    fcntl64(11, F_GETFD) = 0
    fcntl64(11, F_SETFD, FD_CLOEXEC) = 0
    fcntl64(11, F_SETLKW64, {type=F_WRLCK, whence=SEEK_SET, start=1, len=1}, 0xbffb1418) = 0
    fstat64(11, {st_mode=S_IFREG|0640, st_size=50, ...}) = 0
    read(11, " 18572\n", 25) = 25
    write(2, "pam-abl", 7) = 7
    write(2, ": ", 2) = 2
    write(2, "DB_REGISTER limits processes to one open DB_ENV handle per environment", 70) = 70
    write(2, "\n", 1) = 1
    close(11) = 0
    time(NULL) = 1347475204
    socket(PF_FILE, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 11
    connect(11, {sa_family=AF_FILE, sun_path="/dev/log"}, 110) = -1 EPROTOTYPE (Protocol wrong type for socket)
    close(11) = 0
    socket(PF_FILE, SOCK_STREAM|SOCK_CLOEXEC, 0) = 11
    connect(11, {sa_family=AF_FILE, sun_path="/dev/log"}, 110) = 0
    send(11, "<83>Sep 12 20:40:04 pam-abl[18572]: Operation not permitted (1) while opening the database environment\0", 103, MSG_NOSIGNAL) = 103
    close(11) = 0
    time(NULL) = 1347475204
    socket(PF_FILE, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 11
    connect(11, {sa_family=AF_FILE, sun_path="/dev/log"}, 110) = -1 EPROTOTYPE (Protocol wrong type for socket)
    close(11) = 0
    socket(PF_FILE, SOCK_STREAM|SOCK_CLOEXEC, 0) = 11
    connect(11, {sa_family=AF_FILE, sun_path="/dev/log"}, 110) = 0
    send(11, "<83>Sep 12 20:40:04 pam-abl[18572]: Operation not permitted (1) while Creating database environment.\0", 101, MSG_NOSIGNAL) = 101
    close(11) = 0
    time(NULL) = 1347475204
    socket(PF_FILE, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 11
    connect(11, {sa_family=AF_FILE, sun_path="/dev/log"}, 110) = -1 EPROTOTYPE (Protocol wrong type for socket)
    close(11) = 0
    socket(PF_FILE, SOCK_STREAM|SOCK_CLOEXEC, 0) = 11
    connect(11, {sa_family=AF_FILE, sun_path="/dev/log"}, 110) = 0
    send(11, "<84>Sep 12 20:40:04 pam-abl[18572]: The database environment could not be opened\0", 81, MSG_NOSIGNAL) = 81
    close(11) = 0

     
  • Petr Písař
    Petr Písař
    2012-09-12

    And indeed the DB warning looks like a bug in DB. There <https://forums.oracle.com/forums/thread.jspa?threadID=616763> is 4 years old thread with Oracle support and DB-11g2 changelog mentions similar bug (#18535) as resolved.

     
  • Petr Písař
    Petr Písař
    2012-09-12

    To provide complete diagnosis, I can confirm my issue #2936696 from 0.4.1 now behaves like described in this initial comment. That means even if pam_abl tool reports the host is blocked, first attempt in a session fails properly, but second and third ones pass and I am able to log in with correct password.

     
  • Ok,
    I think I have a clear view on the problem now, and have some ideas on how to fix it. Just don't know yet if they are feasible.

    To solve your problem in the meanwhile, I have a workaround:
    If you set "MaxAuthTries" in your sshd_config to 1, you limit the number of attempts per connection to 1. This should solve the problem.

    Following text is a more technical description of the problem:
    When an application (sshd for example) wants to authenticate a user, it opens a pam_handle and calls authenticate. If pam_abl is needed, we are loaded into memory and we are asked to authenticate the user. In that case we open our db environment and check if the user/host is blocked or not. When authentication finishes, we are asked to cleanup, at which point we look at the authentication result and log it into the db if needed.
    Apparently sshd uses the same pam_handle between the attempts, in which case we are asked multiple times to authenticate a user. Resulting in us trying to open the same db environment multiple times (that's when you see the "The database environment could not be opened" message). Because cleanup is only called when all the attempts have been tried, we only log one failure instead of three.
    I hope this little text explains what goes wrong.

     
  • danta
    danta
    2012-11-12

    Sorry for the long pause. The fix has made it to the git repository, don't know yet when I'm going to release it.

    It took so long because the fix brought up another minor problem that isn't that easy fixed.
    An auth failure is now logged when the pam auth code ends or when a next attempt is evaluated.
    So in the worst case scenario a hacker could open multiple connections and auth once on each one of them and keep the connection open, resulting in no failures logged. Not really practical though because sshd and other deamons usually limit the number of unauthenticated connections from a host, but it's still something I would like to see fixed.

     
  • danta
    danta
    2012-11-12

    • status: open --> pending-fixed