Re: SciTokens

6 views
Skip to first unread message

Paul-Niklas Kramp

unread,
Oct 2, 2019, 8:03:36 AM10/2/19
to Jeff Gaynor, dis...@scitokens.org

Hi Jeff,

first of all thank you for the docker project, I will set it up to look for crucial differences.

Regarding my setup:
I will try to attach as many details as I can.
Regarding your suggestion with the truststore:
I had already configured a truststore in the tomcat server.xml:
         <Connector port="8443" protocol="HTTP/1.1" SSLEnabled="true"
                     URIEncoding="UTF-8"
                     maxThreads="150" scheme="https" secure="true"
                     keystoreFile="${user.home}/certs/cacerts.jks"
                     keystorePass="changeit"
                     truststoreFile="${user.home}/certs/truststore.jks"
                     truststorePass="changeit"
                     truststoreType="JKS"
                     clientAuth="false" sslProtocol="TLS" />

I have now added your suggestion below to the scitoken-client.xml:
    <ssl useJavaTrustStore="true">
      <trustStore>
        <path>/usr/share/tomcat/certs/truststore.jks</path>
        <password><![CDATA[changeit]]></password>
        <type>JKS</type>
      </trustStore>
    </ssl>


The keystore and truststore match, see below:
The keystore on the server:
[root@tokenIssuer tomcat]# keytool -list -keystore certs/cacerts.jks
Enter keystore password: 
Keystore type: PKCS12
Keystore provider: SUN

Your keystore contains 1 entry

tomcat, Oct 1, 2019, PrivateKeyEntry,
Certificate fingerprint (SHA1): 8C:B7:52:59:0D:94:B1:95:6A:03:91:A9:32:B1:B4:95:7A:7B:15:91

The truststore on the client:

[root@client tomcat]# keytool -list -keystore certs/truststore.jks
Enter keystore password: 
Keystore type: jks
Keystore provider: SUN

Your keystore contains 1 entry

tomcat, Oct 2, 2019, trustedCertEntry,
Certificate fingerprint (SHA1): 8C:B7:52:59:0D:94:B1:95:6A:03:91:A9:32:B1:B4:95:7A:7B:15:91

However, the error "Error invoking client" remains.

Now, to the errors:
Regarding logging:
When I enable logging on the client with the following, I do not get more detailed messages (see client.conf for full client config):
  <client name="scitokens-client" debug="trace">
    <logging
      logFileName="/var/log/tomcat/scitokens-client"
      logName="scitokens-client"
      logSize="100000"
      logFileCount="2"
      debug="true"
    />
   ...
When I enable logging on the server(see server.conf), I get an error (see attached file "exception").

When requesting a token, the process fails with the error "Error invoking client", thrown here.
Any idea how I misconfigured the logging?
I have attached screenshots of the request, as well as the initial registration.
Is there any possibly related information missing?

Thank you,
Paul



clientregistration.png
exception
client.conf
server.conf
errorpage.png
request.png
delegation.png

Jeff Gaynor

unread,
Oct 4, 2019, 9:20:56 AM10/4/19
to dis...@scitokens.org
Aha! It seems you may have a slightly older version of the SciTokens war. In the server configuration, add a MyProxy element (this won't be used), so

<server name="scitoken-server"
         <!-- stuff -->
       >
   <myproxy host="localhost" port="7512"/>
  <!-- rest of stuff -->
/>

We are going to release a new version shortly so this is just a quick fix until then. See if this helps.


Jeff
--
You received this message because you are subscribed to the Google Groups "SciTokens Discussion" group.
To unsubscribe from this group and stop receiving emails from it, send an email to discuss+u...@scitokens.org.
To view this discussion on the web visit https://groups.google.com/a/scitokens.org/d/msgid/discuss/d44a9d08-6128-10a8-c4e2-ec6c74f3d94d%40gsi.de.


Paul-Niklas Kramp

unread,
Oct 4, 2019, 11:58:50 AM10/4/19
to dis...@scitokens.org

Hi Jeff,

I included what you mentioned, still the same error.

I didn't get to deploy the docker project yet, as yesterday was a national holiday and I today had other issues.

My project can be found here by the way.
Regarding the version: I have now upgraded to the 1.2a-1 release, and also tried the 1.1 release.
I previously used the 1.2a release candidate.

I have just seen that the cacerts.jks is a PKCS12 keystore, while the truststore is a jks keystore. Could that cause it?
I will investigate on monday.

Furthermore, do you have any input on logging? Why it just doesn't get enabled?

Thanks and have a nice weekend,
Paul



Jeff Gaynor

unread,
Oct 7, 2019, 12:10:20 PM10/7/19
to Paul-Niklas Kramp, dis...@scitokens.org
I am actually on vacation for this week, but I will be able to look at this tonight for a bit. Just so you know.

Jeff
--
You received this message because you are subscribed to the Google Groups "SciTokens Discussion" group.
To unsubscribe from this group and stop receiving emails from it, send an email to discuss+u...@scitokens.org.

Jeff Gaynor

unread,
Oct 7, 2019, 9:01:23 PM10/7/19
to Paul-Niklas Kramp, dis...@scitokens.org


On 10/4/19 10:58 AM, Paul-Niklas Kramp wrote:

Hi Jeff,

I included what you mentioned, still the same error.

I didn't get to deploy the docker project yet, as yesterday was a national holiday and I today had other issues.

My project can be found here by the way.

Looks ok,... but... it looks like you have put your client secret into a public git repository. You should not do that. Remember that there is exactly one copy of this on Earth and you have it. We do not even store the secret, but merely a hash of it.  Posting publicly is bad. This is probably ok until you get it working, then the normal way to get a new secret is that you have to register a new client and approve it.


Regarding the version: I have now upgraded to the 1.2a-1 release, and also tried the 1.1 release.
I previously used the 1.2a release candidate.

I have just seen that the cacerts.jks is a PKCS12 keystore, while the truststore is a jks keystore. Could that cause it?
I will investigate on monday.

cacerts MUST be a JKS -- Java does not know how to do read anything else natively. However, you should not need to specify this in your connector unless you have added certs to it.


Furthermore, do you have any input on logging? Why it just doesn't get enabled?

Your catalina.out should have a lot of debug information in it. Setting debug=trace sends a lot of output to catalina.out since this is the most reliable way to capture certain types of information (if for instance, if there is a problem with the logger itself.) Have you looked there? If there is nothing, then check /var/log/messages (assuming you are on a unix system.) Perhaps tomcat logging is being sent elsewhere?


Jeff


Thanks and have a nice weekend,
Paul



On 02/10/2019 18:50, Jeff Gaynor wrote:
Aha! It seems you may have a slightly older version of the SciTokens war. In the server configuration, add a MyProxy element (this won't be used), so

<server name="scitoken-server"
         <!-- stuff -->
       >
   <myproxy host="localhost" port="7512"/>
  <!-- rest of stuff -->
/>

We are going to release a new version shortly so this is just a quick fix until then. See if this helps.


Jeff

--
You received this message because you are subscribed to the Google Groups "SciTokens Discussion" group.
To unsubscribe from this group and stop receiving emails from it, send an email to discuss+u...@scitokens.org.

Paul-Niklas Kramp

unread,
Oct 9, 2019, 10:27:26 AM10/9/19
to dis...@scitokens.org

Hi Jeff,

I managed to enable logging by editing the /usr/share/tomcat/conf/logging.properties, apparently this was previously overwriting the settings in the client-config.xml.

The error:
Oct  9 14:14:49 localhost server: 2019-10-09T14:14:49.819Z STStartRequest WARN: in POST, raw content = application/x-www-form-urlencoded
Oct  9 14:14:49 localhost server: 2019-10-09T14:14:49.820Z STStartRequest WARN: checking encoding, next = application/x-www-form-urlencoded
Oct  9 14:14:49 localhost server: 2019-10-09T14:14:49.821Z STStartRequest WARN: checking encoding, gotOne = true
Oct  9 14:14:49 localhost server: 2019-10-09T14:14:49.821Z STStartRequest WARN: encoding ok, starting doIt()
Oct  9 14:14:49 localhost server: STStartRequest: scopes in CE= [email, edu.uiuc.ncsa.myproxy.getcert, openid, profile]
Oct  9 14:14:49 localhost server: STStartRequest: scopes = read:/public
Oct  9 14:14:49 localhost server: STStartRequest: setting scopes to [read:/public]
Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.672Z ATServer2 TRACE: getting access token, use http header for token? false
Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.971Z MyTrustManager WARN: .checkServerDN: Configured serverDN has CN = localhost
Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.971Z MyTrustManager WARN: .checkServerDN: Configured serverDN check failed.
Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.972Z MyTrustManager WARN: .checkServerDN: Checking cert CN against hostname
Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.972Z MyTrustManager WARN: .checkServerDN: Configured host = https://tokenissuer.vagrant.test:8443/scitokens-server/token
Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.972Z MyTrustManager WARN: .checkServerDN: host=CN? false
Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.972Z MyTrustManager WARN: common name ="tokenissuer.vagrant.test" does not match host from reverse lookup = "https://tokenissuer.vagrant.test:8443/scitokens-server/token"
Oct  9 14:14:55 localhost server: javax.net.ssl.SSLHandshakeException: java.security.cert.CertificateException: No trust manager accepted the server

I wondered where "https://tokenissuer.vagrant.test:8443/scitokens-server/token" as a resolved name came from, and looked at where the host was actually set.
I looked at the mytrustmanager and saw that the line here would resolve it to tokenissuer.vagrant.test
I also looked at other potential places where that host would be set, in the HostUtil for example.
I extracted the code and tested it myself, and also received tokenissuer.vagrant.test as a result.

Do you have an idea where else the host Configured host = https://tokenissuer.vagrant.test:8443/scitokens-server/token is set?

Thanks,
Paul

PS: I am aware of the secret


Jeff Gaynor

unread,
Oct 9, 2019, 8:57:52 PM10/9/19
to Paul-Niklas Kramp, dis...@scitokens.org
On 10/9/19 9:27 AM, Paul-Niklas Kramp wrote:

Hi Jeff,

I managed to enable logging by editing the /usr/share/tomcat/conf/logging.properties, apparently this was previously overwriting the settings in the client-config.xml.

Interesting. I will note this in the release notes. We have had trouble in the past with logging properties files in strange locations.


The error:
Oct  9 14:14:49 localhost server: 2019-10-09T14:14:49.819Z STStartRequest WARN: in POST, raw content = application/x-www-form-urlencoded
Oct  9 14:14:49 localhost server: 2019-10-09T14:14:49.820Z STStartRequest WARN: checking encoding, next = application/x-www-form-urlencoded
Oct  9 14:14:49 localhost server: 2019-10-09T14:14:49.821Z STStartRequest WARN: checking encoding, gotOne = true
Oct  9 14:14:49 localhost server: 2019-10-09T14:14:49.821Z STStartRequest WARN: encoding ok, starting doIt()
Oct  9 14:14:49 localhost server: STStartRequest: scopes in CE= [email, edu.uiuc.ncsa.myproxy.getcert, openid, profile]
Oct  9 14:14:49 localhost server: STStartRequest: scopes = read:/public
Oct  9 14:14:49 localhost server: STStartRequest: setting scopes to [read:/public]
Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.672Z ATServer2 TRACE: getting access token, use http header for token? false
Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.971Z MyTrustManager WARN: .checkServerDN: Configured serverDN has CN = localhost

So this means that your server thinks that the host cert should be "localhost" which is ok

Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.971Z MyTrustManager WARN: .checkServerDN: Configured serverDN check failed.
Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.972Z MyTrustManager WARN: .checkServerDN: Checking cert CN against hostname
Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.972Z MyTrustManager WARN: .checkServerDN: Configured host = https://tokenissuer.vagrant.test:8443/scitokens-server/token

This means that when the lookup is done, this is returned as the name of the system -- this entire address, not just the host name.

Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.972Z MyTrustManager WARN: .checkServerDN: host=CN? false
Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.972Z MyTrustManager WARN: common name ="tokenissuer.vagrant.test" does not match host from reverse lookup = "https://tokenissuer.vagrant.test:8443/scitokens-server/token"

These two strings (tokenissuer.vagrant.test, on the cert) have to match (https://to... from the lookup in, e.g. /etc/hosts) as strings. How is the system listed in DNS? I see no place in any of the configuration you sent that has this, so the issue is outside of the server.

Oct  9 14:14:55 localhost server: javax.net.ssl.SSLHandshakeException: java.security.cert.CertificateException: No trust manager accepted the server

I wondered where "https://tokenissuer.vagrant.test:8443/scitokens-server/token" as a resolved name came from, and looked at where the host was actually set.
I looked at the mytrustmanager and saw that the line here would resolve it to tokenissuer.vagrant.test
I also looked at other potential places where that host would be set, in the HostUtil for example.
I extracted the code and tested it myself, and also received tokenissuer.vagrant.test as a result.

Do you have an idea where else the host Configured host = https://tokenissuer.vagrant.test:8443/scitokens-server/token is set?

If you really want to, there is a way to over-ride the host name in the configuration with the serverDN tag:

http://grid.ncsa.illinois.edu/myproxy/oauth/server/dtd/server-dtd-service-tag.xhtml

(All of these still work for SciTokens) So for instance,

<service name="blah"
         serverDN="CN=tokenissuer.vagrant.test"
         .....

The original purpose of this tag was to allow for load-balancing setups.  It is also a very useful thing for self-signed certs (use "CN=localhost").  This ought to get you up and running until you can figure out where the bad address is coming from.

Jeff

Paul-Niklas Kramp

unread,
Oct 10, 2019, 8:23:28 AM10/10/19
to dis...@scitokens.org
Hi Jeff,

thank you.


The error:
Oct  9 14:14:49 localhost server: 2019-10-09T14:14:49.819Z STStartRequest WARN: in POST, raw content = application/x-www-form-urlencoded
Oct  9 14:14:49 localhost server: 2019-10-09T14:14:49.820Z STStartRequest WARN: checking encoding, next = application/x-www-form-urlencoded
Oct  9 14:14:49 localhost server: 2019-10-09T14:14:49.821Z STStartRequest WARN: checking encoding, gotOne = true
Oct  9 14:14:49 localhost server: 2019-10-09T14:14:49.821Z STStartRequest WARN: encoding ok, starting doIt()
Oct  9 14:14:49 localhost server: STStartRequest: scopes in CE= [email, edu.uiuc.ncsa.myproxy.getcert, openid, profile]
Oct  9 14:14:49 localhost server: STStartRequest: scopes = read:/public
Oct  9 14:14:49 localhost server: STStartRequest: setting scopes to [read:/public]
Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.672Z ATServer2 TRACE: getting access token, use http header for token? false
Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.971Z MyTrustManager WARN: .checkServerDN: Configured serverDN has CN = localhost

So this means that your server thinks that the host cert should be "localhost" which is ok
Why is that?

Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.971Z MyTrustManager WARN: .checkServerDN: Configured serverDN check failed.
Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.972Z MyTrustManager WARN: .checkServerDN: Checking cert CN against hostname
Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.972Z MyTrustManager WARN: .checkServerDN: Configured host = https://tokenissuer.vagrant.test:8443/scitokens-server/token

This means that when the lookup is done, this is returned as the name of the system -- this entire address, not just the host name.
Is that intended or just the observed behaviour? When I use the methods (the HostUtil and Mytrustmanager line) mentioned below (copied into my own little java program), it results only in tokenissuer.vagrant.test.


Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.972Z MyTrustManager WARN: .checkServerDN: host=CN? false
Oct  9 14:14:54 localhost server: 2019-10-09T14:14:54.972Z MyTrustManager WARN: common name ="tokenissuer.vagrant.test" does not match host from reverse lookup = "https://tokenissuer.vagrant.test:8443/scitokens-server/token"

These two strings (tokenissuer.vagrant.test, on the cert) have to match (https://to... from the lookup in, e.g. /etc/hosts) as strings. How is the system listed in DNS? I see no place in any of the configuration you sent that has this, so the issue is outside of the server.
DNS is done via a vagrant plugin, which when using dig hands out the correct address/hostname.
The /etc/hosts on the client side is also configured so that
127.0.0.1    client.vagrant.test    client
172.16.1.201 tokenissuer.vagrant.test
on the server side:
127.0.0.1       tokenissuer.vagrant.test        tokenissuer

Note that whatever I enter there (I have tried a multitude of things, e.g. leaving this out of the hosts file and solely leaving it to the dns), the reverse lookup result is always "https://tokenissuer.vagrant.test:8443/scitokens-server/token"

When I disable DNS and only use the /etc/hosts file: Setting nothing, I of course get tokenissuer.vagrant.test: Name or service not known.
When I add 172.16.1.201 tokenissuer.vagrant.test, the error again notes "https://tokenissuer.vagrant.test:8443/scitokens-server/token"

I assume that should not be? Because this result can never be the same as the CN in the cert.

Oct  9 14:14:55 localhost server: javax.net.ssl.SSLHandshakeException: java.security.cert.CertificateException: No trust manager accepted the server

I wondered where "https://tokenissuer.vagrant.test:8443/scitokens-server/token" as a resolved name came from, and looked at where the host was actually set.
I looked at the mytrustmanager and saw that the line here would resolve it to tokenissuer.vagrant.test
I also looked at other potential places where that host would be set, in the HostUtil for example.
I extracted the code and tested it myself, and also received tokenissuer.vagrant.test as a result.

Do you have an idea where else the host Configured host = https://tokenissuer.vagrant.test:8443/scitokens-server/token is set?

If you really want to, there is a way to over-ride the host name in the configuration with the serverDN tag:

http://grid.ncsa.illinois.edu/myproxy/oauth/server/dtd/server-dtd-service-tag.xhtml

(All of these still work for SciTokens) So for instance,

<service name="blah"
         serverDN="CN=tokenissuer.vagrant.test"
         .....

I have tried that, and nothing seems to change.
  <service name="scitokens-server"
    serverDN="CN=tokenissuer.vagrant.test"
The log still states:
Oct 10 11:31:35 localhost server: 2019-10-10T11:31:35.063Z MyTrustManager WARN: .checkServerDN: Configured serverDN has CN = localhost


The original purpose of this tag was to allow for load-balancing setups.  It is also a very useful thing for self-signed certs (use "CN=localhost").  This ought to get you up and running until you can figure out where the bad address is coming from.

I have set the CAs CN to localhost and get:
Oct 10 11:56:13 localhost server: javax.net.ssl.SSLException: Certificate for <tokenissuer.vagrant.test> doesn't match common name of the certificate subject: localhost


I will try to investigate how the reverse lookup sets the incorrect value.
Cheers,
Paul

Paul-Niklas Kramp

unread,
Oct 10, 2019, 11:01:34 AM10/10/19
to dis...@scitokens.org
Hi again,

little additional info that I am not sure will help:
The serviceUri in the client seems to be the value that is "resolved".
Changing this to the ip instead of the hostname or modifying the path is
shown in the error line

Oct 10 12:42:35 localhost server: 2019-10-10T12:42:35.419Z
MyTrustManager WARN: .checkServerDN: Configured host =
https://172.16.1.201:8443/scitokens-server/token
Oct 10 12:42:35 localhost server: 2019-10-10T12:42:35.419Z
MyTrustManager WARN: common name ="tokenissuer.vagrant.test" does not
match host from reverse lookup =
"https://172.16.1.201:8443/scitokens-server/token"

Apparently, the name is not really resolved?
Or the resolved value is afterwards modified?

Because when there is no DNS, the name tokenissuer.vagrant.test cannot
be resolved.
Therefore with DNS, for the connection attempt, the name is correctly
resolved.

But for the cert check, it is not.

Maybe it gives you an idea?

Cheers,
Paul

Jeff Gaynor

unread,
Oct 14, 2019, 9:03:00 PM10/14/19
to Paul-Niklas Kramp, dis...@scitokens.org
I have perhaps found the issue and fixed it. Please get the most recent draft release of the scitokens-client.war at


and see if this fixes your issue.

Jeff
--
You received this message because you are subscribed to the Google Groups "SciTokens Discussion" group.
To unsubscribe from this group and stop receiving emails from it, send an email to discuss+u...@scitokens.org.

Paul-Niklas Kramp

unread,
Oct 15, 2019, 6:58:42 AM10/15/19
to Jeff Gaynor, dis...@scitokens.org

Hi Jeff,

it is working now! The name is resolved correctly.

Thanks a lot!

Paul

Reply all
Reply to author
Forward
0 new messages