No Audit log messages when the ldap user has an invalid serial number during key recovery using externalReg

[pki-bot]

This issue was migrated from Pagure Issue #3184. Originally filed by dmoluguw (@SilleBille) on 2020-06-30 13:00:34:

• Assigned to nobody

---

Description of problem:

No Audit log messages when the ldap user has an invalid serial number during key recovery using externalReg

Version-Release number of selected component (if applicable):

pki-tps-10.4.1-10.el7pki.x86_64

How reproducible:

always

Steps to Reproduce:

1. Perfoem a token enrollment to recover cert/keys onto a token using the following ldap user

dn: uid=pkiuser2,ou=people,dc=pki-ca-Aug11-CA
objectClass: person
objectClass: organizationalPerson
objectClass: inetorgperson
objectClass: top
objectClass: extensibleobject
cn: pkiuser2
sn: pkiuser2
uid: pkiuser2
givenName: pkiuser2
mail: pkiuser2@example.org
firstname: pkiuser2
userPassword:: e1NTSEE1MTJ9SVNIV2MrS3BrSlp0V0FaUlhoMllwYVBwdCsrblFYNUpHQXFZZDl
 UNTNJVEl0Qm10bDBXUjRuVzcrVUJEVE9mcG5iNlFKa1Vpd3RKdUxyL013ZkZKYldJeUtSdWtlSGtF
tokenType: externalRegAddToToken
certstoadd: 160089323,ca1
certstoadd: 15210359,ca1,23,kra1

15210359 serial number does not exist in CA

Actual results:

Enrollment fails but audit log has no failure messages

0.http-bio-25080-exec-2 - [22/Aug/2017:10:00:20 EDT] [14] [6] [AuditEvent=TOKEN_OP_REQUEST][IP=10.13.129.49][CUID=40906145C7622419280B][MSN=FF%FF%FF%FF%][Outcome=success][OP=enroll][AppletVersion=1.4.58768072] token processor op request made
0.http-bio-25080-exec-2 - [22/Aug/2017:10:00:25 EDT] [14] [6] [AuditEvent=TOKEN_AUTH_SUCCESS][IP=10.13.129.49][SubjectID=pkiuser2][CUID=40906145C7622419280B][MSN=FF%FF%FF%FF%][Outcome=success][OP=enroll][tokenType=null][AppletVersion=1.4.58768072][AuthMgr=ldap1] token authentication success

Expected results:

Additional info:

debug log messages

[22/Aug/2017:10:00:28][http-bio-25080-exec-2]: In LdapBoundConnFactory::getConn()
[22/Aug/2017:10:00:28][http-bio-25080-exec-2]: masterConn is connected: true
[22/Aug/2017:10:00:28][http-bio-25080-exec-2]: getConn: conn is connected true
[22/Aug/2017:10:00:28][http-bio-25080-exec-2]: getConn: mNumConns now 2
[22/Aug/2017:10:00:28][http-bio-25080-exec-2]: LDAPDatabase: adding cn=20170822100028249000.23,ou=Activities,o=pki-tps-Aug11-TPS
[22/Aug/2017:10:00:28][http-bio-25080-exec-2]: returnConn: mNumConns now 3
[22/Aug/2017:10:00:28][http-bio-25080-exec-2]: TPSSession.process: Message processing failed: TPSEnrollProcessor.enroll: externalRegRecover: TPSEnrollProcessor.enroll: externalRegRecover returned: recoverStatus=STATUS_ERROR_RECOVERY_FAILED
[22/Aug/2017:10:00:28][http-bio-25080-exec-2]: TPSConnection.write: Writing: s=42&msg_type=13&operation=1&result=1&message=9
[22/Aug/2017:10:00:28][http-bio-25080-exec-2]: TPSSession.process: leaving: result: 1 status: STATUS_ERROR_BAD_STATUS