[Pki-users] Dogtag TPS wizard - java.lang.NullPointerException on last button

Thu Nov 11 18:20:40 UTC 2010

On 11/11/2010 07:49 AM, Fabian Bertholm wrote:
> Hi,
>
> I tried a second time. Here is the log of the ca and from the tps.
> I skipped pki-kra and pki-tks because there are no log entries after
> the startup and no errors on startup.
> Ath the ca thre is the line:
> [11/Nov/2010:16:25:52][http-9544-Processor21]: RegisterUser: exception
> thrown: java.lang.NullPointerException
> Wher does this come from?
>
> best regards,
> Fabian
>
> pki-subca/debug:
> <next button pressed>
> [11/Nov/2010:16:25:46][http-9545-Processor24]: CMSServlet:service()
> uri = /ca/admin/ca/getDomainXML
> [11/Nov/2010:16:25:46][http-9545-Processor24]: CMSServlet:
> caGetDomainXML start to service.
> [11/Nov/2010:16:25:46][http-9545-Processor24]: GetDomainXML: processing...
> [11/Nov/2010:16:25:46][http-9545-Processor24]: LdapBoundConnFactory: init
> [11/Nov/2010:16:25:46][http-9545-Processor24]:
> LdapBoundConnFactory:doCloning true
> [11/Nov/2010:16:25:46][http-9545-Processor24]: LdapAuthInfo: init()
> [11/Nov/2010:16:25:46][http-9545-Processor24]: LdapAuthInfo: init begins
> [11/Nov/2010:16:25:46][http-9545-Processor24]: LdapAuthInfo: init:
> prompt is Internal LDAP Database
> [11/Nov/2010:16:25:46][http-9545-Processor24]: LdapAuthInfo: init: try
> getting from memory cache
> [11/Nov/2010:16:25:46][http-9545-Processor24]: LdapAuthInfo: init: got
> password from memory
> [11/Nov/2010:16:25:46][http-9545-Processor24]: LdapAuthInfo: init:
> password found for prompt.
> [11/Nov/2010:16:25:46][http-9545-Processor24]: LdapAuthInfo: password
> ok: store in memory cache
> [11/Nov/2010:16:25:46][http-9545-Processor24]: LdapAuthInfo: init ends
> [11/Nov/2010:16:25:46][http-9545-Processor24]: init: before
> makeConnection errorIfDown is false
> [11/Nov/2010:16:25:46][http-9545-Processor24]: makeConnection: errorIfDown false
> [11/Nov/2010:16:25:46][http-9545-Processor24]: Established LDAP
> connection using basic authentication to host localhost port 389 as
> cn=Directory Manager
> [11/Nov/2010:16:25:46][http-9545-Processor24]: initializing with
> mininum 3 and maximum 15 connections to host localhost port 389,
> secure connection, false, authentication type 1
> [11/Nov/2010:16:25:46][http-9545-Processor24]: increasing minimum
> connections by 3
> [11/Nov/2010:16:25:46][http-9545-Processor24]: new total available connections 3
> [11/Nov/2010:16:25:46][http-9545-Processor24]: new number of connections 3
> [11/Nov/2010:16:25:46][http-9545-Processor24]: getConn: mNumConns now 2
> [11/Nov/2010:16:25:46][http-9545-Processor24]: Releasing ldap connection
> [11/Nov/2010:16:25:46][http-9545-Processor24]: returnConn: mNumConns now 3
> [11/Nov/2010:16:25:46][http-9545-Processor24]: CMSServlet: curDate=Thu
> Nov 11 16:25:46 CET 2010 id=caGetDomainXML time=546
> [11/Nov/2010:16:25:50][http-9544-Processor21]: CMSServlet:service()
> uri = /ca/admin/ca/registerUser
> [11/Nov/2010:16:25:50][http-9544-Processor21]: CMSServlet::service()
> param name='certificate' value=''
> [11/Nov/2010:16:25:50][http-9544-Processor21]: CMSServlet::service()
> param name='name' value='Token Processing Subsystem'
> [11/Nov/2010:16:25:50][http-9544-Processor21]: CMSServlet::service()
> param name='auth_hostname' value='pki-server1'
> [11/Nov/2010:16:25:50][http-9544-Processor21]: CMSServlet::service()
> param name='uid' value='TPS-pki-server1-7889'
> [11/Nov/2010:16:25:50][http-9544-Processor21]: CMSServlet::service()
> param name='auth_port' value='9544'
> [11/Nov/2010:16:25:50][http-9544-Processor21]: CMSServlet::service()
> param name='xmlOutput' value='true'
> [11/Nov/2010:16:25:50][http-9544-Processor21]: CMSServlet::service()
> param name='sessionID' value='326321180524051384'
> [11/Nov/2010:16:25:50][http-9544-Processor21]: CMSServlet:
> caRegisterUser start to service.
> [11/Nov/2010:16:25:50][http-9544-Processor21]: UpdateUpdater: processing...
> [11/Nov/2010:16:25:50][http-9544-Processor21]: IP: 192.168.253.35
> [11/Nov/2010:16:25:50][http-9544-Processor21]: AuthMgrName: TokenAuth
> [11/Nov/2010:16:25:50][http-9544-Processor21]: CMSServlet: no client
> certificate found
> [11/Nov/2010:16:25:50][http-9544-Processor21]: TokenAuthentication: start
> [11/Nov/2010:16:25:50][http-9544-Processor21]: TokenAuthentication:
> content=sessionID=326321180524051384&hostname=192.168.253.35
> [11/Nov/2010:16:25:50][http-9544-Processor24]: CMSServlet:service()
> uri = /ca/ee/ca/tokenAuthenticate
> [11/Nov/2010:16:25:50][http-9544-Processor24]: CMSServlet::service()
> param name='hostname' value='192.168.253.35'
> [11/Nov/2010:16:25:50][http-9544-Processor24]: CMSServlet::service()
> param name='sessionID' value='326321180524051384'
> [11/Nov/2010:16:25:50][http-9544-Processor24]: CMSServlet:
> caTokenAuthenticate start to service.
> [11/Nov/2010:16:25:50][http-9544-Processor24]: TokenAuthentication:
> sessionId=326321180524051384
> [11/Nov/2010:16:25:50][http-9544-Processor24]: TokenAuthentication:
> givenHost=192.168.253.35
> [11/Nov/2010:16:25:50][http-9544-Processor24]: TokenAuthentication:
> checking session in the session table
> [11/Nov/2010:16:25:50][http-9544-Processor24]: CMSEngine:
> getPasswordStore(): password store initialized before.
> [11/Nov/2010:16:25:50][http-9544-Processor24]: CMSEngine:
> getPasswordStore(): password store initialized.
> [11/Nov/2010:16:25:51][http-9544-Processor24]: TokenAuthentication:
> found session
> [11/Nov/2010:16:25:51][http-9544-Processor24]: CMSEngine:
> getPasswordStore(): password store initialized before.
> [11/Nov/2010:16:25:51][http-9544-Processor24]: CMSEngine:
> getPasswordStore(): password store initialized.
> [11/Nov/2010:16:25:51][http-9544-Processor24]: TokenAuthentication:
> hostname and givenHost matched
> [11/Nov/2010:16:25:51][http-9544-Processor24]: CMSEngine:
> getPasswordStore(): password store initialized before.
> [11/Nov/2010:16:25:51][http-9544-Processor24]: CMSEngine:
> getPasswordStore(): password store initialized.
> [11/Nov/2010:16:25:51][http-9544-Processor24]: CMSEngine:
> getPasswordStore(): password store initialized before.
> [11/Nov/2010:16:25:51][http-9544-Processor24]: CMSEngine:
> getPasswordStore(): password store initialized.
> [11/Nov/2010:16:25:52][http-9544-Processor24]: TokenAuthenticate
> successfully authenticate
> [11/Nov/2010:16:25:52][http-9544-Processor24]: CMSServlet: curDate=Thu
> Nov 11 16:25:52 CET 2010 id=caTokenAuthenticate time=1292
> [11/Nov/2010:16:25:52][http-9544-Processor21]: TokenAuthentication: status=0
> [11/Nov/2010:16:25:52][http-9544-Processor21]: SessionContext.USER_ID
> admin SessionContext.GROUP_ID Enterprise TPS Administrators
> [11/Nov/2010:16:25:52][http-9544-Processor21]: TokenAuthentication:
> authenticated uid=admin, gid=Enterprise TPS Administrators
> [11/Nov/2010:16:25:52][http-9544-Processor21]: CMSServlet: userid=null
> [11/Nov/2010:16:25:52][http-9544-Processor21]: CMSServlet: in auditSubjectID
> [11/Nov/2010:16:25:52][http-9544-Processor21]: CMSServlet:
> auditSubjectID auditContext {locale=de_DE, groupid=Enterprise TPS
> Administrators, userid=admin, ipAddress=192.168.253.35,
> authManagerId=TokenAuth}
> [11/Nov/2010:16:25:52][http-9544-Processor21]: CMSServlet
> auditSubjectID: subjectID: admin
> [11/Nov/2010:16:25:52][http-9544-Processor21]:
> SignedAuditEventFactory: create()
> message=[AuditEvent=AUTH_SUCCESS][SubjectID=admin][Outcome=Success][AuthMgr=TokenAuth]
> authentication success
>
> [11/Nov/2010:16:25:52][http-9544-Processor21]: RegisterUser
> authentication successful.
> [11/Nov/2010:16:25:52][http-9544-Processor21]: CMSServlet: in auditSubjectID
> [11/Nov/2010:16:25:52][http-9544-Processor21]: CMSServlet:
> auditSubjectID auditContext {locale=de_DE, groupid=Enterprise TPS
> Administrators, userid=admin, ipAddress=192.168.253.35,
> authManagerId=TokenAuth}
> [11/Nov/2010:16:25:52][http-9544-Processor21]: CMSServlet
> auditSubjectID: subjectID: admin
> [11/Nov/2010:16:25:52][http-9544-Processor21]: CMSServlet: in auditGroupID
> [11/Nov/2010:16:25:52][http-9544-Processor21]: CMSServlet:
> auditGroupID auditContext {locale=de_DE, groupid=Enterprise TPS
> Administrators, userid=admin, ipAddress=192.168.253.35,
> authManagerId=TokenAuth}
> [11/Nov/2010:16:25:52][http-9544-Processor21]: CMSServlet
> auditGroupID: groupID: Enterprise TPS Administrators
> [11/Nov/2010:16:25:52][http-9544-Processor21]: checkACLS(): ACLEntry
> expressions= group="Enterprise CA Administrators" || group="Enterprise
> KRA Administrators" || group="Enterprise RA Administrators" ||
> group="Enterprise OCSP Administrators" || group="Enterprise TKS
> Administrators" || group="Enterprise TPS Administrators"
> [11/Nov/2010:16:25:52][http-9544-Processor21]: evaluating expressions:
> group="Enterprise CA Administrators" || group="Enterprise KRA
> Administrators" || group="Enterprise RA Administrators" ||
> group="Enterprise OCSP Administrators" || group="Enterprise TKS
> Administrators" || group="Enterprise TPS Administrators"
> [11/Nov/2010:16:25:52][http-9544-Processor21]: GroupAccessEvaluator:
> evaluate: uid=admin value="Enterprise CA Administrators"
> [11/Nov/2010:16:25:52][http-9544-Processor21]: GroupAccessEvaluator:
> evaluate: authToken gid=Enterprise TPS Administrators
> [11/Nov/2010:16:25:52][http-9544-Processor21]: evaluated expression:
> group="Enterprise CA Administrators" to be false
> [11/Nov/2010:16:25:52][http-9544-Processor21]: GroupAccessEvaluator:
> evaluate: uid=admin value="Enterprise KRA Administrators"
> [11/Nov/2010:16:25:52][http-9544-Processor21]: GroupAccessEvaluator:
> evaluate: authToken gid=Enterprise TPS Administrators
> [11/Nov/2010:16:25:52][http-9544-Processor21]: evaluated expression:
> group="Enterprise KRA Administrators" to be false
> [11/Nov/2010:16:25:52][http-9544-Processor21]: GroupAccessEvaluator:
> evaluate: uid=admin value="Enterprise RA Administrators"
> [11/Nov/2010:16:25:52][http-9544-Processor21]: GroupAccessEvaluator:
> evaluate: authToken gid=Enterprise TPS Administrators
> [11/Nov/2010:16:25:52][http-9544-Processor21]: evaluated expression:
> group="Enterprise RA Administrators" to be false
> [11/Nov/2010:16:25:52][http-9544-Processor21]: GroupAccessEvaluator:
> evaluate: uid=admin value="Enterprise OCSP Administrators"
> [11/Nov/2010:16:25:52][http-9544-Processor21]: GroupAccessEvaluator:
> evaluate: authToken gid=Enterprise TPS Administrators
> [11/Nov/2010:16:25:52][http-9544-Processor21]: evaluated expression:
> group="Enterprise OCSP Administrators" to be false
> [11/Nov/2010:16:25:52][http-9544-Processor21]: GroupAccessEvaluator:
> evaluate: uid=admin value="Enterprise TKS Administrators"
> [11/Nov/2010:16:25:52][http-9544-Processor21]: GroupAccessEvaluator:
> evaluate: authToken gid=Enterprise TPS Administrators
> [11/Nov/2010:16:25:52][http-9544-Processor21]: evaluated expression:
> group="Enterprise TKS Administrators" to be false
> [11/Nov/2010:16:25:52][http-9544-Processor21]: GroupAccessEvaluator:
> evaluate: uid=admin value="Enterprise TPS Administrators"
> [11/Nov/2010:16:25:52][http-9544-Processor21]: GroupAccessEvaluator:
> evaluate: authToken gid=Enterprise TPS Administrators
> [11/Nov/2010:16:25:52][http-9544-Processor21]: evaluated expression:
> group="Enterprise TPS Administrators" to be true
> [11/Nov/2010:16:25:52][http-9544-Processor21]: DirAclAuthz: authorization passed
> [11/Nov/2010:16:25:52][http-9544-Processor21]:
> SignedAuditEventFactory: create()
> message=[AuditEvent=AUTHZ_SUCCESS][SubjectID=admin][Outcome=Success][aclResource=certServer.ca.registerUser][Op=modify]
> authorization success
>
> [11/Nov/2010:16:25:52][http-9544-Processor21]: getConn: mNumConns now 2
> [11/Nov/2010:16:25:52][http-9544-Processor21]: returnConn: mNumConns now 3
> [11/Nov/2010:16:25:52][http-9544-Processor21]:
> SignedAuditEventFactory: create()
> message=[AuditEvent=ROLE_ASSUME][SubjectID=Enterprise TPS
> Administrators][Outcome=Success][Role=Certificate Manager Agents,
> Administrators, Security Domain Administrators, Enterprise CA
> Administrators, Enterprise KRA Administrators, Enterprise OCSP
> Administrators, Enterprise TKS Administrators, Enterprise RA
> Administrators, Enterprise TPS Administrators] assume privileged role
>
> [11/Nov/2010:16:25:52][http-9544-Processor21]: RegisterUser
> authorization successful.
> [11/Nov/2010:16:25:52][http-9544-Processor21]: RegisterUser got
> uid=TPS-pki-server1-7889
> [11/Nov/2010:16:25:52][http-9544-Processor21]: RegisterUser got
> name=Token Processing Subsystem
> [11/Nov/2010:16:25:52][http-9544-Processor21]: RegisterUser got certsString=
> [11/Nov/2010:16:25:52][http-9544-Processor21]: RegisterUser: exception
> thrown: java.lang.NullPointerException
> [11/Nov/2010:16:25:52][http-9544-Processor21]: RegisterUser NOT found
> user by cert
> [11/Nov/2010:16:25:52][http-9544-Processor21]: getConn: mNumConns now 2
> [11/Nov/2010:16:25:52][http-9544-Processor21]: returnConn: mNumConns now 3
> [11/Nov/2010:16:25:52][http-9544-Processor21]: RegisterUser found user
> by uid TPS-pki-server1-7889
> [11/Nov/2010:16:25:52][http-9544-Processor21]: RegisterUser error
> java.lang.NullPointerException
> [11/Nov/2010:16:25:52][http-9544-Processor21]: CMSServlet: curDate=Thu
> Nov 11 16:25:52 CET 2010 id=caRegisterUser time=1685
>
> pki-tps/debug:
> Thu Nov 11 16:25:48 CET 2010 - DonePanel: display
> Thu Nov 11 16:25:48 CET 2010 - DonePanel: register_tps at
> https://pki-server1:9544
> Thu Nov 11 16:25:48 CET 2010 - DonePanel: subsystem CA
> uri=/ca/admin/ca/registerUser
> Thu Nov 11 16:25:48 CET 2010 - DonePanel: Connecting to Security Domain
> Thu Nov 11 16:25:48 CET 2010 - DonePanel: Security Domain Info
> https://pki-server1:9544
> Thu Nov 11 16:25:49 CET 2010 - ReqCertInfo: update got token name =
> NSS Certificate DB
> Thu Nov 11 16:25:50 CET 2010 - DonePanel: Connecting
> Thu Nov 11 16:25:52 CET 2010 - req = HTTP/1.1 200 OK
> Server: Apache-Coyote/1.1
> Content-Type: application/xml
> Content-Length: 126
> Date: Thu, 11 Nov 2010 15:25:52 GMT
> Connection: close
>
> <?xml version="1.0"
> encoding="UTF-8"?><XMLResponse><Status>1</Status><Error>Error:
> Certificate malformed</Error></XMLResponse>
> Subject: CN=pki-server1,OU=pki-subca,O=ST Test SubCA 1 Domain
> Issuer : CN=Certificate Authority,OU=pki-subca,O=ST Test SubCA 1 Domain
> bulk cipher RC4, 128 secret key bits, 128 key bits, status: 1
>
> Thu Nov 11 16:25:53 CET 2010 - DonePanel: result
> <XMLResponse><Status>1</Status><Error>Error: Certificate
> malformed</Error></XMLResponse>
> Thu Nov 11 16:25:53 CET 2010 - DonePanel: register_tps at
> https://pki-server1:13443
> Thu Nov 11 16:25:53 CET 2010 - DonePanel: subsystem TKS
> uri=/tks/admin/tks/registerUser
> Thu Nov 11 16:25:54 CET 2010 - ReqCertInfo: update got token name =
> NSS Certificate DB
> Thu Nov 11 16:25:54 CET 2010 - DonePanel: Connecting
> Thu Nov 11 16:25:55 CET 2010 - req =
> Thu Nov 11 16:25:55 CET 2010 - DonePanel: result
> Thu Nov 11 16:25:55 CET 2010 - DonePanel: KRA available
> Thu Nov 11 16:25:55 CET 2010 - DonePanel: register_tps at
> https://pki-server1:10443
> Thu Nov 11 16:25:55 CET 2010 - DonePanel: subsystem KRA
> uri=/kra/admin/kra/registerUser
> Thu Nov 11 16:25:56 CET 2010 - DonePanel: Connecting to Security Domain
> Thu Nov 11 16:25:56 CET 2010 - DonePanel: Security Domain Info
> https://pki-server1:10443
> Thu Nov 11 16:25:56 CET 2010 - ReqCertInfo: update got token name =
> NSS Certificate DB
> Thu Nov 11 16:25:56 CET 2010 - DonePanel: Connecting
> Thu Nov 11 16:25:58 CET 2010 - req =
> Thu Nov 11 16:25:58 CET 2010 - DonePanel: result
> Thu Nov 11 16:25:58 CET 2010 - DonePanel: Connecting to KRA
>
> pki-tps/error_log:
> [Thu Nov 11 16:25:41 2010] [info] Initial (No.1) HTTPS request
> received for child 59 (server 192
> .168.253.35:7890)
> sh: host:https://pki-server1:9543/-: No such file or directory
> GET /ca/admin/ca/getDomainXML HTTP/1.0
>
> port: 9545
> addr='pki-server1'
> family='2'
> -- SSL3: Server Certificate Validated.
> PR_Write wrote 42 bytes from bigBuf
> bytes: [GET /ca/admin/ca/getDomainXML HTTP/1.0
>
> ]
> do_writes shutting down send socket
> do_writes exiting with (failure = 0)
> connection 1 read 2541 bytes (2541 total).
> these bytes read:
> connection 1 read 2541 bytes total. -----------------------------
> [Thu Nov 11 16:25:48 2010] -e: Use of uninitialized value $status in
> string eq at /var/lib/pki-tps/lib/perl/PKI/TPS/DonePanel.pm line 289.
> certutil: Could not find cert: subsystemCert cert-pki-tps0
> : File not found.
>
> _______________________________________________
> Pki-users mailing list
> Pki-users at redhat.com
> https://www.redhat.com/mailman/listinfo/pki-users
>    
Hi:

It looks like the CA is expecting a certificate blob that should have 
been generated by the tps installer and sent to the ca.

Couple things that may help: You might take a look in the log file:  
/var/lib/pki-tps/error_log. Also make sure you have access to 
/usr/bin/certutil utility.