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

Fabian Bertholm fabeisageek at googlemail.com
Thu Nov 11 15:49:45 UTC 2010 

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.

More information about the Pki-users mailing list