RTC 5.0 Git integration, how do I troubleshoot an HTTP 500 error?
Kiran, Kishore,
We are unable to connect to the Jazz RTC server when using the IBM Git pre-receive and post-receive hooks on our Git server.
We are using LDAP (Microsoft Active Directory) to authenticate the Git users. This is also used by the Jazz system.
We have enabled 'LogLevel debug' in the Apache server and put DEBUG_PYT=true in the environment of the pre-receive hook of the project on the Git server.
The UserID is a member of the Jazz project area, we have granted access. We have registered the Git repository.
When we try to do a 'git push origin master' from a client, we get:
$ git push origin master
Username for 'http://<GIT_SERVER_NAME>': <LDAP_USER_ID>
Password for 'http://<LDAP_USER_ID>@<GIT_SERVER_NAME>':
Counting objects: 5, done.
Delta compression using up to 2 threads.
Compressing objects: 100% (2/2), done.
Writing objects: 100% (3/3), 347 bytes | 0 bytes/s, done.
Total 3 (delta 0), reused 0 (delta 0)
remote: oldRev=da2dd03e67e9944355cadd036179186b788ff571 newRev=efaf53d8a1d7a31ba850e1d7a575549be90cac75 refName=refs/heads/master
remote: ('https://<JAZZ_HOST_NAME>/ccm', '101f15feea67494e99ebf424ceb3d899', '<LDAP_USER_ID>', 'da2dd03e67e9944355cadd036179186b788ff571',
'efaf53d8a1d7a31ba850e1d7a575549be90cac75', 'refs/heads/master', None)
remote: ('Checking for Reg exp ', None)
remote: ('Is not a regexp',)
remote: ('In getCommits: ',)
remote: ('Executing command: ', ['git', 'rev-list', 'efaf53d8a1d7a31ba850e1d7a575549be90cac75'])
remote: ('isCommitReachableFrom: ', 'efaf53d8a1d7a31ba850e1d7a575549be90cac75\nda2dd03e67e9944355cadd036179186b788ff571\n')
remote: ('Executing command: ', ['git', 'rev-list', 'da2dd03e67e9944355cadd036179186b788ff571..efaf53d8a1d7a31ba850e1d7a575549be90ca
c75'])
remote: ('In getParamsForPush', ['efaf53d8a1d7a31ba850e1d7a575549be90cac75', ''])
remote: ('Executing command: ', ['git', 'log', '-n 1', '--pretty=format:"%s"', 'efaf53d8a1d7a31ba850e1d7a575549be90cac75'])
remote: ('Executing command: ', ['git', 'log', '-n 1', '--pretty=format:"%cn"', 'efaf53d8a1d7a31ba850e1d7a575549be90cac75'])
remote: ('Executing command: ', ['git', 'log', '-n 1', '--pretty=format:"%ce"', 'efaf53d8a1d7a31ba850e1d7a575549be90cac75'])
remote: ('Executing command: ', ['git', 'log', '-n 1', '--pretty=format:"%cd"', 'efaf53d8a1d7a31ba850e1d7a575549be90cac75'])
remote: ('checking isPushNewBranch',)
remote: ('data: ', 'commitSha1=efaf53d8a1d7a31ba850e1d7a575549be90cac75&commitComment=Test+of+push+with+hooks+Defect+1129&committerN
ame=<LDAP_USER_ID>&committerEmail=%22JeffBirkner%22&remoteRef=refs%2Fheads%2Fmaster&creationDate=%22Tue+May+5+09%3A33%3A43+201
5+-0400%22&gitUser=<LDAP_USER_ID>&repositoryKey=101f15feea67494e99ebf424ceb3d899&baseRevSha1=da2dd03e67e9944355cadd036179186b788ff571&endRev
Sha1=efaf53d8a1d7a31ba850e1d7a575549be90cac75&opHint=commit_add')
remote: HTTP Error 500: Internal Server Error
To http://<GIT_SERVER_NAME>/git/project4dev.git
! [remote rejected] master -> master (pre-receive hook declined)
error: failed to push some refs to 'http://<GIT_SERVER_NAME>/git/project4dev.git'
We are getting this error: 'remote: HTTP Error 500: Internal Server Error'
We checked the log on the system's reverse proxy server:
/cm/IBM/HTTPServer_8500/logs$ cat access_log |grep 05/May/2015:16:21:3
10.2.243.224 - - [05/May/2015:16:21:31 -0400] "GET /ccm/rootservices HTTP/1.1" 200 9006
10.2.243.224 - - [05/May/2015:16:21:31 -0400] "POST /ccm/service/com.ibm.team.git.common.internal.IGitOperationRestService/ValidatePush HTTP/1.1" 401 35
10.2.241.32 - - [05/May/2015:16:21:31 -0400] "POST /ccm/service/com.ibm.team.git.common.internal.IGitOperationInvokeService/ValidatePush HTTP/1.1" 500 -
This is the failure:
10.2.241.32 - - [05/May/2015:16:21:31 -0400] "POST /ccm/service/com.ibm.team.git.common.internal.IGitOperationInvokeService/ValidatePush HTTP/1.1" 500 -
The address 10.2.243.224 is the address of the CCM server.
The address 10.2.241.32 is the address of the Git server.
We believe the pre-receive hook is trying to connect to the RTC server through the Reverse Proxy server.
It looks like the userID (<LDAP_USER_ID>) is being recognized by the pre-receive hook.
Git server appache access_log (times are a bit off)
10.2.244.88 - - [05/May/2015:16:21:10 -0400] "GET /git/project4dev.git/info/refs?service=git-receive-pack HTTP/1.1" 401 381
10.2.244.88 - <LDAP_USER_ID> [05/May/2015:16:21:10 -0400] "GET /git/project4dev.git/info/refs?service=git-receive-pack HTTP/1.1" 200 153
10.2.244.88 - <LDAP_USER_ID> [05/May/2015:16:21:10 -0400] "POST /git/project4dev.git/git-receive-pack HTTP/1.1" 200 1944
Git server appache error_log (times are a bit off)
[Tue May 05 16:21:10.315375 2015] [authz_core:debug] [pid 15644:tid 140240146581248] mod_authz_core.c(809): [client 10.2.244.88:60744] AH01626: authorization result of Require valid-user : denied (no authenticated user yet)
[Tue May 05 16:21:10.315456 2015] [authz_core:debug] [pid 15644:tid 140240146581248] mod_authz_core.c(809): [client 10.2.244.88:60744] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet)
[Tue May 05 16:21:10.316775 2015] [authz_core:debug] [pid 15644:tid 140240136091392] mod_authz_core.c(809): [client 10.2.244.88:60744] AH01626: authorization result of Require valid-user : denied (no authenticated user yet)
[Tue May 05 16:21:10.316808 2015] [authz_core:debug] [pid 15644:tid 140240136091392] mod_authz_core.c(809): [client 10.2.244.88:60744] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet)
[Tue May 05 16:21:10.316854 2015] [authnz_ldap:debug] [pid 15644:tid 140240136091392] mod_authnz_ldap.c(516): [client 10.2.244.88:60744] AH01691: auth_ldap authenticate: using URL ldap://<LDAPSERVER>:389/DC=corp,DC=waters,DC=com?sAMAccountName
[Tue May 05 16:21:10.317767 2015] [ldap:debug] [pid 15644:tid 140240136091392] util_ldap.c(379): AH01278: LDAP: Setting referrals to On.
[Tue May 05 16:21:10.628712 2015] [authnz_ldap:debug] [pid 15644:tid 140240136091392] mod_authnz_ldap.c(613): [client 10.2.244.88:60744] AH01697: auth_ldap authenticate: accepting <LDAP_USER_ID>
[Tue May 05 16:21:10.628779 2015] [authz_core:debug] [pid 15644:tid 140240136091392] mod_authz_core.c(809): [client 10.2.244.88:60744] AH01626: authorization result of Require valid-user : granted
[Tue May 05 16:21:10.628789 2015] [authz_core:debug] [pid 15644:tid 140240136091392] mod_authz_core.c(809): [client 10.2.244.88:60744] AH01626: authorization result of <RequireAny>: granted
[Tue May 05 16:21:10.628964 2015] [authz_core:debug] [pid 15644:tid 140240136091392] mod_authz_core.c(809): [client 10.2.244.88:60744] AH01626: authorization result of Require all granted: granted
[Tue May 05 16:21:10.628980 2015] [authz_core:debug] [pid 15644:tid 140240136091392] mod_authz_core.c(809): [client 10.2.244.88:60744] AH01626: authorization result of <RequireAny>: granted
[Tue May 05 16:21:10.767488 2015] [authz_core:debug] [pid 11866:tid 140240136091392] mod_authz_core.c(809): [client 10.2.244.88:60745] AH01626: authorization result of Require valid-user : denied (no authenticated user yet)
[Tue May 05 16:21:10.767549 2015] [authz_core:debug] [pid 11866:tid 140240136091392] mod_authz_core.c(809): [client 10.2.244.88:60745] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet)
[Tue May 05 16:21:10.767633 2015] [authnz_ldap:debug] [pid 11866:tid 140240136091392] mod_authnz_ldap.c(516): [client 10.2.244.88:60745] AH01691: auth_ldap authenticate: using URL ldap://<LDAPSERVER>:389/DC=corp,DC=waters,DC=com?sAMAccountName
[Tue May 05 16:21:10.767681 2015] [authnz_ldap:debug] [pid 11866:tid 140240136091392] mod_authnz_ldap.c(613): [client 10.2.244.88:60745] AH01697: auth_ldap authenticate: accepting <LDAP_USER_ID>
[Tue May 05 16:21:10.767694 2015] [authz_core:debug] [pid 11866:tid 140240136091392] mod_authz_core.c(809): [client 10.2.244.88:60745] AH01626: authorization result of Require valid-user : granted
[Tue May 05 16:21:10.767703 2015] [authz_core:debug] [pid 11866:tid 140240136091392] mod_authz_core.c(809): [client 10.2.244.88:60745] AH01626: authorization result of <RequireAny>: granted
[Tue May 05 16:21:10.767857 2015] [authz_core:debug] [pid 11866:tid 140240136091392] mod_authz_core.c(809): [client 10.2.244.88:60745] AH01626: authorization result of Require all granted: granted
[Tue May 05 16:21:10.767936 2015] [authz_core:debug] [pid 11866:tid 140240136091392] mod_authz_core.c(809): [client 10.2.244.88:60745] AH01626: authorization result of <RequireAny>: granted
If we remove the hooks on the Git server, we are able to complete the 'push' successfully.
1. How can we determine additional information about why the connection is failing?
2. What do we need to do to get this working?
Jazz System info:
Fully distributed topology, JTS, CCM, QM, RM and RRDI each on their own VM.
All Jazz servers use Webshpere Application Server, version 8.5.0.2
IBM HTTP server acting as a Reverse Proxy on VM, version 8.5.0.2
All Jazz applications are version 5.0GA, 64-bit, with iFix002
DB: Oracle 11.2.0.3.0 on own machine, not a VM
Java: Version that comes with Jazz 5.0GA
All servers run Red Hat Enterprise Linux 6.4, 64-bit
Git server info:
CentOS 6.4 on VM
Apache (Built with SSL): Server version: Apache/2.4.12 (Unix)
Git: git version 1.7.1
OpenSSL: OpenSSL 1.0.1e-fips 11 Feb 2013
Python (Built with SSL): Python 3.3.5