[RTFACT-14477] Artifactory 5.4+ tries to access its own server via http only Created: 28/Jun/17  Updated: 10/Apr/18  Resolved: 29/Jun/17

Status: Resolved
Project: Artifactory Binary Repository
Component/s: Access Server
Affects Version/s: 4.12.2, 5.4.0, 5.4.1
Fix Version/s: 5.4.2

Type: Bug Priority: High
Reporter: Arturo Aparicio Assignee: Yossi Shaul
Resolution: Fixed Votes: 0
Labels: None

Sub-Tasks:
Key
Summary
Type
Status
Assignee
RTFACT-14857 Access server doesn't use https url Sub-task Will Not Implement  
Assigned QA: Mor Iluz (Inactive)

 Description   

Artifactory 5.4+ tries to access its own server via http only. This will fail if:

1. Tomcat is configured to only serve HTTPS content
2. Tomcat is configured to serve HTTP and HTTPS content on different ports

This prevents Artifactory from starting up.

Error

2017-06-21 16:49:34,795 [art-init] [INFO ] (o.a.s.a.AccessServiceImpl:233) - Waiting for access server...
2017-06-21 16:50:34,816 [art-init] [ERROR] (o.a.w.s.ArtifactoryContextConfigListener:97) - Application could not be initialized: Waiting for access server to respond timed-out after 60000 milliseconds.
java.lang.reflect.InvocationTargetException: null

or

2018-03-27 19:22:47,267 bin [art-init] [ERROR] (o.a.w.s.ArtifactoryContextConfigListener:99) - Application could not be initialized: HTTP response status 302:Found
java.lang.reflect.InvocationTargetException: null

Workaround

The property artifactory.access.client.serverUrl.override (in $ARTIFACTORY_HOME/etc/artifactory.system.properties of each node) can be set to override the access URL artifactory tries to contact. If using HTTPS (with a valid certificate that Artifactory itself recognizes), you would set it like this:

artifactory.access.client.serverUrl.override=https://<VALID_URL>:<PORT>/access

Another property that need to be added to the $ARTIFACTORY_HOME/etc/artifactory.system.properties is the following

artifactory.access.server.bundled=true

Specifically if the URL was node1 and the port was 8443, it would look like this:

artifactory.access.client.serverUrl.override=https://node1:8443/access

Alternatively, Tomcat can be set to use non-ssl (HTTP) and a reverse proxy on the same server could be used to handle the ssl traffic.



 Comments   
Comment by Stefan Endrullis [ 25/Jul/17 ]

I upgraded artifactory from 5.3.2 to 5.4.5 and now I get the same error as reported here. I tried to fix it via the mentioned workaround but it did not work for me.

My artifactory is running inside a tomcat 6 instance located on a Debian 9 and was installed via aptitude using the repository from jfrog:

deb https://jfrog.bintray.com/artifactory-debs/ jessie main

This is my artifactory.log:

                _   _  __           _                      ____   _____ _____
     /\        | | (_)/ _|         | |                    / __ \ / ____/ ____|
    /  \   _ __| |_ _| |_ __ _  ___| |_ ___  _ __ _   _  | |  | | (___| (___
   / /\ \ | '__| __| |  _/ _` |/ __| __/ _ \| '__| | | | | |  | |\___ \\___ \
  / ____ \| |  | |_| | || (_| | (__| || (_) | |  | |_| | | |__| |____) |___) |
 /_/    \_\_|   \__|_|_| \__,_|\___|\__\___/|_|   \__, |  \____/|_____/_____/
 Version:  5.4.5                                   __/ |
 Revision: 50405900                               |___/
 Artifactory Home: '/usr/share/tomcat6/.artifactory'

2017-07-25 14:42:15,168 [art-init] [INFO ] (o.a.s.ArtifactoryApplicationContext:433) - Artifactory application context set to NOT READY by refresh
2017-07-25 14:42:15,169 [art-init] [INFO ] (o.a.s.ArtifactoryApplicationContext:213) - Refreshing Artifactory: startup date [Tue Jul 25 14:42:15 CEST 2017]; root of context hierarchy
2017-07-25 14:42:20,497 [art-init] [INFO ] (o.a.s.d.DbServiceImpl:188) - Database: MySQL 5.6.30-1~bpo8+1. Driver: MySQL Connector Java mysql-connector-java-5.1.42 ( Revision: ${revinfo.commit} )
2017-07-25 14:42:20,497 [art-init] [INFO ] (o.a.s.d.DbServiceImpl:190) - Connection URL: jdbc:mysql://localhost:3306/artifactory?characterEncoding=UTF-8&elideSetAutoCommits=true
2017-07-25 14:42:21,677 [art-init] [INFO ] (o.j.s.b.p.t.BinaryProviderClassScanner:76) - Added 'blob' from jar:file:/var/lib/tomcat6/webapps/artifactory/WEB-INF/lib/artifactory-storage-db-5.4.5.jar!/
2017-07-25 14:42:21,687 [art-init] [INFO ] (o.j.s.b.p.t.BinaryProviderClassScanner:76) - Added 'empty, external-file, external-wrapper, file-system, cache-fs, retry' from jar:file:/var/lib/tomcat6/webapps/artifactory/WEB-INF/lib/binary-store-core-2.0.14.jar!/
2017-07-25 14:42:25,020 [art-init] [INFO ] (o.a.s.ArtifactorySchedulerFactoryBean:647) - Starting Quartz Scheduler now
2017-07-25 14:42:25,304 [art-init] [INFO ] (o.a.s.ArtifactoryApplicationContext:220) - Artifactory context starting up 38 Spring Beans...
2017-07-25 14:42:25,360 [art-init] [INFO ] (o.a.d.r.CentralConfigReader:78) - The current Artifactory config schema namespace is 'http://artifactory.jfrog.org/xsd/2.0.5' The provided config does not seem to be compliant with it.
2017-07-25 14:42:25,404 [art-init] [INFO ] (o.a.d.r.CentralConfigReader:58) - Converting artifactory.config.xml version from 'v203' to 'v205'
2017-07-25 14:42:25,424 [art-init] [INFO ] (o.a.v.c.v.AccessTokenSettingsRenameToAccessClientSettingsConverter:19) - Starting to convert AccessTokenSettings to AccessClientSettings
2017-07-25 14:42:25,425 [art-init] [INFO ] (o.a.v.c.v.AccessTokenSettingsRenameToAccessClientSettingsConverter:42) - Finished to convert AccessTokenSettings to AccessClientSettings
2017-07-25 14:42:25,425 [art-init] [INFO ] (o.a.v.c.v.YumEnableFilelistsIndexingForExistingLocalReposConverter:19) - Starting The Yum local repositories conversion, to enable existing local repositories to calculate filelists.xml 
2017-07-25 14:42:25,429 [art-init] [INFO ] (o.a.v.c.v.YumEnableFilelistsIndexingForExistingLocalReposConverter:23) - Finish The Yum local repositories conversion, to enable existing local repositories to calculate filelists.xml 
2017-07-25 14:42:26,192 [art-init] [INFO ] (o.a.d.r.CentralConfigReader:78) - The current Artifactory config schema namespace is 'http://artifactory.jfrog.org/xsd/2.0.5' The provided config does not seem to be compliant with it.
2017-07-25 14:42:26,225 [art-init] [INFO ] (o.a.d.r.CentralConfigReader:58) - Converting artifactory.config.xml version from 'v203' to 'v205'
2017-07-25 14:42:26,260 [art-init] [INFO ] (o.a.v.c.v.AccessTokenSettingsRenameToAccessClientSettingsConverter:19) - Starting to convert AccessTokenSettings to AccessClientSettings
2017-07-25 14:42:26,260 [art-init] [INFO ] (o.a.v.c.v.AccessTokenSettingsRenameToAccessClientSettingsConverter:42) - Finished to convert AccessTokenSettings to AccessClientSettings
2017-07-25 14:42:26,261 [art-init] [INFO ] (o.a.v.c.v.YumEnableFilelistsIndexingForExistingLocalReposConverter:19) - Starting The Yum local repositories conversion, to enable existing local repositories to calculate filelists.xml 
2017-07-25 14:42:26,274 [art-init] [INFO ] (o.a.v.c.v.YumEnableFilelistsIndexingForExistingLocalReposConverter:23) - Finish The Yum local repositories conversion, to enable existing local repositories to calculate filelists.xml 
2017-07-25 14:42:26,596 [art-init] [INFO ] (o.a.s.a.ArtifactoryAccessClientConfigStore:472) - Using Access Server URL: http://localhost:8080/access (bundled) source: detected
2017-07-25 14:42:26,956 [art-init] [INFO ] (o.a.s.a.AccessServiceImpl:233) - Waiting for access server...
2017-07-25 14:43:26,964 [art-init] [ERROR] (o.a.w.s.ArtifactoryContextConfigListener:97) - Application could not be initialized: Waiting for access server to respond timed-out after 60000 milliseconds.
java.lang.reflect.InvocationTargetException: null
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[na:1.8.0_131]
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[na:1.8.0_131]
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_131]
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_131]
        at org.artifactory.webapp.servlet.ArtifactoryContextConfigListener.configure(ArtifactoryContextConfigListener.java:222) ~[artifactory-web-application-5.4.5.jar:na]
        at org.artifactory.webapp.servlet.ArtifactoryContextConfigListener.access$2(ArtifactoryContextConfigListener.java:184) ~[artifactory-web-application-5.4.5.jar:na]
        at org.artifactory.webapp.servlet.ArtifactoryContextConfigListener$1.run(ArtifactoryContextConfigListener.java:93) ~[artifactory-web-application-5.4.5.jar:na]
Caused by: org.springframework.beans.factory.BeanInitializationException: Failed to initialize bean 'org.artifactory.security.access.AccessService'.; nested exception is java.lang.IllegalStateException: Waiting for access server to respond timed-out after 60000 milliseconds.
        at org.artifactory.spring.ArtifactoryApplicationContext.refresh(ArtifactoryApplicationContext.java:230) ~[artifactory-core-5.4.5.jar:na]
        at org.artifactory.spring.ArtifactoryApplicationContext.<init>(ArtifactoryApplicationContext.java:114) ~[artifactory-core-5.4.5.jar:na]
        ... 7 common frames omitted
Caused by: java.lang.IllegalStateException: Waiting for access server to respond timed-out after 60000 milliseconds.
        at org.artifactory.security.access.AccessServiceImpl.waitForAccessServer(AccessServiceImpl.java:258) ~[artifactory-core-5.4.5.jar:na]
        at org.artifactory.security.access.AccessServiceImpl.initAccessService(AccessServiceImpl.java:225) ~[artifactory-core-5.4.5.jar:na]
        at org.artifactory.security.access.AccessServiceImpl.initIfNeeded(AccessServiceImpl.java:216) ~[artifactory-core-5.4.5.jar:na]
        at org.artifactory.security.access.AccessServiceImpl.init(AccessServiceImpl.java:211) ~[artifactory-core-5.4.5.jar:na]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_131]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_131]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_131]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_131]
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317) ~[spring-aop-4.1.5.RELEASE.jar:4.1.5.RELEASE]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) ~[spring-aop-4.1.5.RELEASE.jar:4.1.5.RELEASE]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.1.5.RELEASE.jar:4.1.5.RELEASE]
        at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99) ~[spring-tx-4.1.5.RELEASE.jar:4.1.5.RELEASE]
        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281) ~[spring-tx-4.1.5.RELEASE.jar:4.1.5.RELEASE]
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) ~[spring-tx-4.1.5.RELEASE.jar:4.1.5.RELEASE]
        at org.artifactory.storage.fs.lock.aop.LockingAdvice.invoke(LockingAdvice.java:76) ~[artifactory-storage-common-5.4.5.jar:na]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.1.5.RELEASE.jar:4.1.5.RELEASE]
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207) ~[spring-aop-4.1.5.RELEASE.jar:4.1.5.RELEASE]
        at com.sun.proxy.$Proxy62.init(Unknown Source) ~[na:na]
        at org.artifactory.spring.ArtifactoryApplicationContext.refresh(ArtifactoryApplicationContext.java:228) ~[artifactory-core-5.4.5.jar:na]
        ... 8 common frames omitted
2017-07-25 14:43:28,249 [http-127.0.0.1-8080-3] [ERROR] (o.a.w.s.ArtifactoryFilter:188) - Artifactory failed to initialize: Context is null

Is this still the same bug?
How can I get more information about why artifactory could not be initialized?

Comment by Stefan Endrullis [ 25/Jul/17 ]

For the moment I went back to version 5.3.2, since I need a running system.

Comment by Ryan Goodwin [ 06/Feb/18 ]

Still happening in 5.4.6. I enabled the workaround and the service started up once. Upon next restart the same failure. I've tried every permutation of the service url/ip/localhost. All failing. Good thing this was on a test system.

_ _ __ _ _ _
/\ | | (_)/ _| | | | | | | /\
/ \ _ _| | | | __ _ __| | ___ _ __ _ _ | |__| | / \
/ /\ \ | '_| __| | _/ _` |/ __| __/ _ | '_| | | | | __ | / /\ \
/ ____ | | | || | || (| | (_| || () | | | |_| | | | | |/ ____ \
// __| _||| _,|__|___/|| _, | || |// _\
Version: 5.4.6 __/ |
Revision: 50406900 |___/
Artifactory Home: '/var/lib/artifactory'
Artifactory data dir: '/mnt/artifactory/cluster_home/ha-data'
HA Node ID: 'XXXX'

2018-02-06 05:28:47,580 [art-init] [INFO ] (o.a.s.ArtifactoryApplicationContext:433) - Artifactory application context set to NOT READY by refresh
2018-02-06 05:28:47,581 [art-init] [INFO ] (o.a.s.ArtifactoryApplicationContext:213) - Refreshing Artifactory: startup date [Tue Feb 06 05:28:47 UTC 2018]; root of context hierarchy
2018-02-06 05:28:54,585 [art-init] [INFO ] (o.a.s.d.DbServiceImpl:188) - Database: PostgreSQL 9.4.15. Driver: PostgreSQL Native Driver PostgreSQL 9.4.1212
2018-02-06 05:28:54,586 [art-init] [INFO ] (o.a.s.d.DbServiceImpl:190) - Connection URL: jdbc:postgresql://my.ip.address:6432/artifactory
2018-02-06 05:28:55,588 [art-init] [INFO ] (o.j.s.b.p.t.BinaryProviderClassScanner:76) - Added 'empty, external-file, external-wrapper, file-system, cache-fs, retry' from jar:file:/var/lib/artifactory/tomcat/webapps/artifactory/WEB-INF/lib/binary-store-core-2.0.14.jar!/
2018-02-06 05:28:55,591 [art-init] [INFO ] (o.j.s.b.p.t.BinaryProviderClassScanner:76) - Added 'blob' from jar:file:/var/lib/artifactory/tomcat/webapps/artifactory/WEB-INF/lib/artifactory-storage-db-5.4.6.jar!/
2018-02-06 05:28:55,717 [art-init] [INFO ] (o.j.s.b.p.t.BinaryProviderClassScanner:76) - Added 'eventual, eventual-cluster, google-storage, hdfs, s3Old, s3, sharding, sharding-cluster, state-aware, azure-blob-storage' from jar:file:/var/lib/artifactory/tomcat/webapps/artifactory/WEB-INF/lib/artifactory-addon-filestore-5.4.6.jar!/
2018-02-06 05:28:55,721 [art-init] [INFO ] (o.j.s.b.p.t.BinaryProviderClassScanner:76) - Added 'remote' from jar:file:/var/lib/artifactory/tomcat/webapps/artifactory/WEB-INF/lib/binary-store-client-2.0.14.jar!/
2018-02-06 05:29:01,386 [art-init] [INFO ] (o.a.s.ArtifactorySchedulerFactoryBean:647) - Starting Quartz Scheduler now
2018-02-06 05:29:01,509 [art-init] [INFO ] (o.a.s.ArtifactoryApplicationContext:220) - Artifactory context starting up 48 Spring Beans...
2018-02-06 05:29:02,015 [art-init] [INFO ] (o.a.s.a.ArtifactoryAccessClientConfigStore:472) - Using Access Server URL: http://localhost:8081/access (bundled) source: detected
2018-02-06 05:29:02,041 [art-init] [INFO ] (o.a.s.a.AccessServiceImpl:233) - Waiting for access server...
2018-02-06 05:30:02,214 [art-init] [ERROR] (o.a.w.s.ArtifactoryContextConfigListener:97) - Application could not be initialized: Waiting for access server to respond timed-out after 60158 milliseconds.
java.lang.reflect.InvocationTargetException: null
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[na:1.8.0_144]
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[na:1.8.0_144]
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_144]
at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_144]
at org.artifactory.webapp.servlet.ArtifactoryContextConfigListener.configure(ArtifactoryContextConfigListener.java:222) ~[artifactory-web-application-5.4.6.jar:na]
at org.artifactory.webapp.servlet.ArtifactoryContextConfigListener.access$2(ArtifactoryContextConfigListener.java:184) ~[artifactory-web-application-5.4.6.jar:na]
at org.artifactory.webapp.servlet.ArtifactoryContextConfigListener$1.run(ArtifactoryContextConfigListener.java:93) ~[artifactory-web-application-5.4.6.jar:na]
Caused by: org.springframework.beans.factory.BeanInitializationException: Failed to initialize bean 'org.artifactory.security.access.AccessService'.; nested exception is java.lang.IllegalStateException: Waiting for access server to respond timed-out after 60158 milliseconds.

Comment by Guillaume Michaud [ 05/Mar/18 ]

At Amadeus, we are experiencing the same issue then the one described by Ryan while trying to upgrade from Artifactory 5.2.1 to Artifactory 5.4.6; can you confirm this issue is resolved?

Generated at Tue Apr 07 08:01:11 UTC 2020 using Jira 8.5.3#805003-sha1:b4933e02eaff29a49114274fe59e1f99d9d963d7.