Bug 1950914

For verification follow the the steps from lukasjuhrich in the upstream issue https://pagure.io/freeipa/issue/6587


- reset all failed units (I did killall ipa-otpd). Be sure none are running.
- setting nsslapd-idletimeout to 60 (or less perhaps)
- systemctl restart dirsrv.target
- kinit -T $ARMOR someuser
- wait 60s (or whatever)

To change nsslapd-idletimeout:

ldapmodify -x -D 'cn=directory manager' -W

dn: cn=config
changetype: modify
replace: nsslapd-idletimeout:
nsslapd-idletimeout: 60
<empty>
^D

In the report the ipa-otpd process ends with:

Mar 31 21:28:58 myhost ipa-otpd[2322932]: lukasjuhrich: response sent: Access-Accept
Mar 31 21:29:58 myhost ipa-otpd[2322932]:     bind.c:088: Input/output error: IO error received on bind socket
Mar 31 21:29:58 myhost systemd[1]: ipa-otpd: Main process exited, code=exited, status=1/FAILURE
Mar 31 21:29:58 myhost systemd[1]: ipa-otpd: Failed with result 'exit-code'.

With this change the process ends with:

Jul 22 13:42:03 ipa.example.test ipa-otpd[1800810]: tuser1: response sent: Access-Accept
Jul 22 13:43:33 ipa.example.test ipa-otpd[1800810]:     bind.c:088: Input/output error: IO error received on bind socket: Can't contact LDAP server
Jul 22 13:43:33 ipa.example.test systemd[1]: ipa-otpd: Succeeded.

So same error message, different result value.

You'll notice that in the reporter's testing the process ended exactly 60s after the auth success. In my test it was 90s. I can't account for that.

Verified using :

2021-07-28T11:39:33+0000 ok: [master.ipa.test] => (item=ipa-server) =>
2021-07-28T11:39:33+0000   msg:
2021-07-28T11:39:33+0000   - arch: x86_64
2021-07-28T11:39:33+0000     epoch: null
2021-07-28T11:39:33+0000     name: ipa-server
2021-07-28T11:39:33+0000     release: 1.module+el8.5.0+11410+91a33fe4
2021-07-28T11:39:33+0000     source: rpm
2021-07-28T11:39:33+0000     version: 4.9.5

2021-07-28T11:52:54+0000 ============================= test session starts ==============================
...
...
2021-07-28T12:03:56+0000 ipatests/test_integration/test_otp.py::TestOTPToken::test_otp_auth_ind PASSED [ 14%]
2021-07-28T12:04:27+0000 ipatests/test_integration/test_otp.py::TestOTPToken::test_hopt PASSED    [ 28%]
2021-07-28T12:04:47+0000 ipatests/test_integration/test_otp.py::TestOTPToken::test_totp PASSED    [ 42%]
2021-07-28T12:05:13+0000 ipatests/test_integration/test_otp.py::TestOTPToken::test_otptoken_sync PASSED [ 57%]
2021-07-28T12:06:13+0000 ipatests/test_integration/test_otp.py::TestOTPToken::test_2fa_enable_single_prompt PASSED [ 71%]
2021-07-28T12:07:11+0000 ipatests/test_integration/test_otp.py::TestOTPToken::test_2fa_disable_single_prompt PASSED [ 85%]
2021-07-28T12:09:51+0000 ipatests/test_integration/test_otp.py::TestOTPToken::test_check_otpd_after_idle_timeout PASSED [100%]
2021-07-28T12:09:51+0000
2021-07-28T12:09:51+0000 ------------------ generated xml file: /tmp/wp/twd/junit.xml -------------------
2021-07-28T12:09:51+0000 ------------- generated html file: file:///tmp/wp/twd/report.html --------------
2021-07-28T12:09:51+0000 ========================= 7 passed in 1022.19 seconds ==========================

Verified using nightly compose:

(A) runner.log 
2021-07-30T07:15:30+0000 TASK [List installed IPA packages version] *************************************
2021-07-30T07:15:30+0000 ok: [master.ipa.test] => (item=ipa-server) => 
2021-07-30T07:15:30+0000   msg:
2021-07-30T07:15:30+0000   - arch: x86_64
2021-07-30T07:15:30+0000     epoch: null
2021-07-30T07:15:30+0000     name: ipa-server
2021-07-30T07:15:30+0000     release: 4.module+el8.5.0+11912+1b4496cf
2021-07-30T07:15:30+0000     source: rpm
2021-07-30T07:15:30+0000     version: 4.9.6

(B) test-result.txt.gz

test_check_otpd_after_idle_timeout from test_integration/test_otp.py

2021-07-30T07:18:34+0000 ============================= test session starts ==============================
2021-07-30T07:18:34+0000 platform linux -- Python 3.6.8, pytest-3.10.1, py-1.10.0, pluggy-0.13.1 -- /usr/bin/python3
2021-07-30T07:18:34+0000 cachedir: .pytest_cache
2021-07-30T07:18:34+0000 metadata: {'Python': '3.6.8', 'Platform': 'Linux-4.18.0-324.el8.x86_64-x86_64-with-redhat-8.5-Ootpa', 'Packages': {'pytest': '3.10.1', 'py': '1.10.0', 'pluggy': '0.13.1'}, 'Plugins': {'metadata': '1.11.0', 'html': '1.22.1', 'multihost': '3.0', 'sourceorder': '0.5'}}
2021-07-30T07:18:34+0000 rootdir: /tmp/wp/freeipa, inifile: tox.ini
2021-07-30T07:18:34+0000 plugins: metadata-1.11.0, html-1.22.1, multihost-3.0, sourceorder-0.5
2021-07-30T07:18:34+0000 collecting ... collected 7 items
2021-07-30T07:18:34+0000 
2021-07-30T07:27:32+0000 ipatests/test_integration/test_otp.py::TestOTPToken::test_otp_auth_ind PASSED [ 14%]
2021-07-30T07:27:47+0000 ipatests/test_integration/test_otp.py::TestOTPToken::test_hopt PASSED    [ 28%]
2021-07-30T07:27:59+0000 ipatests/test_integration/test_otp.py::TestOTPToken::test_totp PASSED    [ 42%]
2021-07-30T07:28:14+0000 ipatests/test_integration/test_otp.py::TestOTPToken::test_otptoken_sync PASSED [ 57%]
2021-07-30T07:28:50+0000 ipatests/test_integration/test_otp.py::TestOTPToken::test_2fa_enable_single_prompt PASSED [ 71%]
2021-07-30T07:29:28+0000 ipatests/test_integration/test_otp.py::TestOTPToken::test_2fa_disable_single_prompt PASSED [ 85%]
2021-07-30T07:31:41+0000 ipatests/test_integration/test_otp.py::TestOTPToken::test_check_otpd_after_idle_timeout PASSED [100%]
2021-07-30T07:31:41+0000 
2021-07-30T07:31:41+0000 ------------------ generated xml file: /tmp/wp/twd/junit.xml -------------------
2021-07-30T07:31:41+0000 ------------- generated html file: file:///tmp/wp/twd/report.html --------------
2021-07-30T07:31:41+0000 =============================== warnings summary ===============================

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (ipa bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2021:4230