Docker ENV ACTIVEMQ_HOST ignored

The handling of the environment variables ACTIVEMQ_HOST and ACTIVEMQ_PORT is unreliable.

For example, take the ship composition (https://github.com/MSG134/IVCT_Compositions/blob/master/Shipsim/pi-docker-compose.yml). If you change the ACTIVEMQ_HOST value, the new value is completely ignored. Actually, it turns out to be hardwired to activemq. If I remove the environment variable, then I expect the default localhost. This is not the case either.

In addition this causes a problem on Kubernetes, where the containers in a pod address each other with localhost. Now I need to set the hostname of the pod to activemq to work around the problems.

Expected behavior for all Framework containers should be:

if ACTIVEMQ_HOST is set, then this value is used
if ACTIVEMQ_HOST is not set, then by default the value localhost is used
if ACTIVEMQ_PORT is set, then this value is used
if ACTIVEMQ_PORT is not set, then by default the value 61616 is used

as mentioned in #129, the environment parameters ACTIVEMQ_HOST and _PORT are no longer used. Instead we are using the names messaging.host and messaging.port. This was done, because there have other places that used the names "messaging...." and we wanted to have only one name for one thing.

I tried the following settings in the .yml file, and it seems to work:

    messaging.host: activemq
    messaging.port: 61616

instead of using

     ACTIVEMQ_HOST: activemq
     ACTIVEMQ_PORT: 61616

I justed tested this on the HelloWorld composition for the TC runner. I replaced

     ACTIVEMQ_HOST: activemq
     ACTIVEMQ_PORT: 61616

    messaging.host: activemq
    messaging.port: 61616

But the result is the same, the stacktrace still appears:

tc-runner_1                     | 10:09:00,793 |-ERROR in ch.qos.logback.classic.net.JMSTopicAppender[JMS] - Error while activating options for appender named [JMS]. javax.jms.JMSException: Could not connect to broker URL: tcp://localhost:61616. Reason: java.net.ConnectException: Connection refused (Connection refused)
tc-runner_1                     |       at javax.jms.JMSException: Could not connect to broker URL: tcp://localhost:61616. Reason: java.net.ConnectException: Connection refused (Connection refused)
tc-runner_1                     |       at      at org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:36)
tc-runner_1                     |       at      at org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnection(ActiveMQConnectionFactory.java:360)
tc-runner_1                     |       at      at org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnection(ActiveMQConnectionFactory.java:305)
...

There also is java.naming.provider.url=tcp\://localhost\:61616 defined in the configuration wiki. What is this used for? I changed this to use activemq, but made no difference.

The convention for environment variables is to use capitals. We break this with this solution.

I found the problem. It is causes by using a '.' in the environment variable name. This is fine for windows, but not for linux. I will change that back by using the old name ACTIVEMQ_HOST and ACTIVEMQ_PORT.

ACTIVEMQ_USER, ACTIVEMQ_PASSWORD, ACTIVEMQ_HOST, ACTIVEMQ_PORT

no changes in docker configuration needed.

ACTIVEMQ_USER and ACTIVEMQ_PASSWORD are currently not documented on the wiki page (https://github.com/MSG134/IVCT_Framework/wiki/IVCT_Configuration). Could you add the information there too?

I need to reopen this issue, since there is still is a problem with the ACTIVEMQ_HOST setting for the TC Runner.

If do not specificy ACTIVEMQ_HOST (so it will default to localhost), then the TC Runner still uses tcp://activemq:61616.

Any chance due to the file JMSTestRunner_logback.xml ?

Attached the docker compose file and the .env file. This issue stops me from running the IVCT.

Stack trace:

tc-runner_1              |      at javax.jms.JMSException: Could not connect to broker URL: tcp://activemq:61616. Reason: java.net.UnknownHostException: activemq
tc-runner_1              |      at      at org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:36)
gui_1                    | 28-Feb-2019 19:17:56.027 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/docs]
gui_1                    | 28-Feb-2019 19:17:56.036 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/docs] has finished in [9] ms
gui_1                    | 28-Feb-2019 19:17:56.045 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
gui_1                    | 28-Feb-2019 19:17:56.062 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["ajp-nio-8009"]
gui_1                    | 28-Feb-2019 19:17:56.066 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 29206 ms
tc-runner_1              |      at      at org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnection(ActiveMQConnectionFactory.java:360)
tc-runner_1              |      at      at org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnection(ActiveMQConnectionFactory.java:305)
tc-runner_1              |      at      at org.apache.activemq.ActiveMQConnectionFactory.createTopicConnection(ActiveMQConnectionFactory.java:279)
tc-runner_1              |      at      at ch.qos.logback.classic.net.JMSTopicAppender.start(JMSTopicAppender.java:104)
tc-runner_1              |      at      at ch.qos.logback.core.joran.action.AppenderAction.end(AppenderAction.java:96)
tc-runner_1              |      at      at ch.qos.logback.core.joran.spi.Interpreter.callEndAction(Interpreter.java:317)
tc-runner_1              |      at      at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:196)
tc-runner_1              |      at      at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:182)
tc-runner_1              |      at      at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:62)
tc-runner_1              |      at      at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:149)
tc-runner_1              |      at      at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:135)
tc-runner_1              |      at      at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:99)
tc-runner_1              |      at      at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:49)
tc-runner_1              |      at      at de.fraunhofer.iosb.messaginghelpers.LogConfigurationHelper.configureLogging(LogConfigurationHelper.java:45)
tc-runner_1              |      at      at de.fraunhofer.iosb.testrunner.JMSTestRunner.<init>(JMSTestRunner.java:83)
tc-runner_1              |      at      at de.fraunhofer.iosb.testrunner.JMSTestRunner.main(JMSTestRunner.java:65)
tc-runner_1              | Caused by: java.net.UnknownHostException: activemq
tc-runner_1              |      at      at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:184)
tc-runner_1              |      at      at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
tc-runner_1              |      at      at java.net.Socket.connect(Socket.java:589)
tc-runner_1              |      at      at org.apache.activemq.transport.tcp.TcpTransport.connect(TcpTransport.java:501)
tc-runner_1              |      at      at org.apache.activemq.transport.tcp.TcpTransport.doStart(TcpTransport.java:464)
tc-runner_1              |      at      at org.apache.activemq.util.ServiceSupport.start(ServiceSupport.java:55)
tc-runner_1              |      at      at org.apache.activemq.transport.AbstractInactivityMonitor.start(AbstractInactivityMonitor.java:168)
tc-runner_1              |      at      at org.apache.activemq.transport.InactivityMonitor.start(InactivityMonitor.java:50)
tc-runner_1              |      at      at org.apache.activemq.transport.TransportFilter.start(TransportFilter.java:58)
tc-runner_1              |      at      at org.apache.activemq.transport.WireFormatNegotiator.start(WireFormatNegotiator.java:72)
tc-runner_1              |      at      at org.apache.activemq.transport.TransportFilter.start(TransportFilter.java:58)
tc-runner_1              |      at      at org.apache.activemq.transport.TransportFilter.start(TransportFilter.java:58)
tc-runner_1              |      at      at org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnection(ActiveMQConnectionFactory.java:340)
tc-runner_1              |      at      ... 15 common frames omitted
tc-runner_1              | 19:17:36,709 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
tc-runner_1              | 19:17:36,714 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE]
tc-runner_1              | 19:17:36,798 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - No compression will be used
tc-runner_1              | 19:17:36,799 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - Will use the pattern ./logs/LogSinkTest.%d{yyyy-MM-dd}.%i.log for the active file
tc-runner_1              | 19:17:36,803 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@38bc8ab5 - The date pattern is 'yyyy-MM-dd' from file name pattern './logs/LogSinkTest.%d{yyyy-MM-dd}.%i.log'.
tc-runner_1              | 19:17:36,803 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@38bc8ab5 - Roll-over at midnight.
tc-runner_1              | 19:17:36,811 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@38bc8ab5 - Setting initial period to Thu Feb 28 19:17:36 GMT 2019
tc-runner_1              | 19:17:36,813 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
tc-runner_1              | 19:17:36,836 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Active log file name: ./logs/LogSinkTest.log
tc-runner_1              | 19:17:36,836 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - File property is set to [./logs/LogSinkTest.log]
tc-runner_1              | 19:17:36,842 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
tc-runner_1              | 19:17:36,842 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
tc-runner_1              | 19:17:36,846 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
tc-runner_1              | 19:17:36,849 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
tc-runner_1              | 19:17:36,849 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@6b57696f - Propagating INFO level on Logger[ROOT] onto the JUL framework
tc-runner_1              | 19:17:36,849 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[ROOT]
tc-runner_1              | 19:17:36,850 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
tc-runner_1              | 19:17:36,850 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [JMS] to Logger[ROOT]
tc-runner_1              | 19:17:36,850 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [de.fraunhofer.iosb] to INFO
tc-runner_1              | 19:17:36,850 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@6b57696f - Propagating INFO level on Logger[de.fraunhofer.iosb] onto the JUL framework
tc-runner_1              | 19:17:36,850 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
tc-runner_1              | 19:17:36,850 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@687080dc - Registering current configuration as safe fallback point
tc-runner_1              |
i

pi-ivct.zip

You are right. Unfortunately, there are currently two different strategies where the activemq host is specified. One is the “default/properties/environment” chain of providing the value, and the other which is still in use, is the JMS/logback configuration, based on the JMSTestRunner_logback.xml file. I need to find a way to better synchronize those two places. Any ideas are welcome. But that does not explain your issue, because that is only relevant to creating the protocol files for the test case logging.

What I do not understand is, why your tc-runner-1 is trying to connect to activemq !

Because I would assume it will try to connect to localhost, as in the IVCT.properties file, there is no setting for ACTIVEMQ_HOST=activemq (you still have the old setting messaging.host=activemq, but that should be ignored since the version from last November). So, the fallback is localhost. I just tested that with my configuration.

Secondly, I do not understand why the tc-runner-1 is not able to connect to activemq, because in your composition file, that is the name of the activemq service and the runner should find that one!

The settings in IVCT_Framework/RuntimeConfig/IVCT.properties should be like:

#ActiveMQ settings
ACTIVEMQ_USER=admin
ACTIVEMQ_PASSWORD=password
ACTIVEMQ_HOST=localhost
ACTIVEMQ_PORT=61616

This would be the setting to use localhost as ACTIVEMQ, but again, in your composition I assume that would be activemq.

Reran a test with the MaK RTI. Got the log furhter below. In this run the runner attempts to connect to localhost, where activemq has been configured in the docker-compose file. I do not understand the difference with earlier runs, but this matches I think the previous comment. The logback.xml file has indeed localhost still configured. Maybe fix this by changing the value by running a script at startup.

The IVCT properties are:

~/conf # pwd
/root/conf
~/conf # more IVCT.properties
#IVCT Properties File
#Mon May 08 14:06:01 CEST 2017
RTI_ID=pRTI
IVCT_SUT_HOME_ID=/root/conf/IVCTsut
IVCT_TS_HOME_ID=/root/conf/TestSuites
IVCT_BADGE_HOME_ID=/root/conf/Badges

ivctcommander.queue=commands

messaging.user=admin
messaging.password=admin
messaging.host=activemq
messaging.port=61616
jmstestrunner.queue=commands
~/conf #

bergtwvd@app-docker05:~/tests/ivct$ docker logs d32bc779181c
LRC: Version: vtmak/lrc:4.5f-alpine-v0.1
LRC: Copyright (C) TNO 2018 (www.tno.nl)
LRC: No pre-wait initialization performed
LRC: No master address provided; no wait on master
LRC: No sleep period provided
LRC: Set FEDERATIONNAME=TheWorld
LRC: Perform post-wait initialization: /root/lrc/postwait.sh
LRC: Set MAK_RTIEXECHOST=rtiexec
LRC: Set MAK_RTIEXECPORT=4000
LRC: Found interface 172.19.0.6 for host rtiexec with IP address 172.19.0.5
LRC: Set RTI_networkInterfaceAddr to 172.19.0.6
LRC: Set RTI_tcpNetworkInterfaceAddr to 172.19.0.6
LRC: Set RTI_tcpForwarderAddr to rtiexec
LRC: Set RTI_tcpPort to 4000
LRC: Set RTI_udpPort to 4000
LRC: Post-wait Initialization completed
LRC: Exec: /root/application/start.sh
Starting the Dockerized IVCT Test Case Engine
20:44:03.734 [main] DEBUG nato.ivct.commander.Factory - /root/conf/ exists
20:44:03.743 [main] DEBUG nato.ivct.commander.Factory - /root/conf/ is directory
20:44:03.744 [main] INFO  nato.ivct.commander.Factory - Properties file loaded
20:44:03.746 [main] INFO  nato.ivct.commander.Factory - Environment Variable ACTIVEMQ_HOST = activemq found
20:44:03.749 [main] INFO  nato.ivct.commander.Factory - Properties used: {ACTIVEMQ_HOST=activemq, messaging.user=admin, RTI_ID=pRTI, IVCT_TS_HOME_ID=/root/conf/TestSuites, jmstestrunner.queue=commands, messaging.password=admin, IVCT_SUT_HOME_ID=/root/conf/IVCTsut, messaging.host=activemq, IVCT_BADGE_HOME_ID=/root/conf/Badges, messaging.port=61616, ivctcommander.queue=commands}
20:44:03.837 [main] INFO  d.f.i.m.PropertyBasedClientSetup - initConnection: connect to activemq please wait...
20:44:04.191 [main] DEBUG o.a.activemq.util.ThreadPoolUtils - Shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@6bf256fa[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0] is shutdown: true and terminated: true took: 0.001 seconds.
20:44:04.192 [main] DEBUG o.a.a.transport.tcp.TcpTransport - Stopping transport tcp://activemq:61616
20:44:04.201 [main] DEBUG o.a.a.thread.TaskRunnerFactory - Initialized TaskRunnerFactory[ActiveMQ Task] using ExecutorService: java.util.concurrent.ThreadPoolExecutor@668bc3d5[Running, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0]
20:44:04.203 [ActiveMQ Task-1] DEBUG o.a.a.transport.tcp.TcpTransport - Closed socket Socket[unconnected]
20:44:04.204 [main] DEBUG o.a.activemq.util.ThreadPoolUtils - Forcing shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@668bc3d5[Running, pool size = 1, active threads = 0, queued tasks = 0, completed tasks = 1]
20:44:09.213 [main] DEBUG o.a.a.transport.WireFormatNegotiator - Sending: WireFormatInfo { version=11, properties={TcpNoDelayEnabled=true, SizePrefixDisabled=false, CacheSize=1024, StackTraceEnabled=true, CacheEnabled=true, TightEncodingEnabled=true, MaxFrameSize=9223372036854775807, Host=activemq, MaxInactivityDuration=30000, MaxInactivityDurationInitalDelay=10000}, magic=[A,c,t,i,v,e,M,Q]}
20:44:09.395 [ActiveMQ Transport: tcp://activemq/172.19.0.3:61616@49948] DEBUG o.a.a.transport.InactivityMonitor - Using min of local: WireFormatInfo { version=11, properties={TcpNoDelayEnabled=true, SizePrefixDisabled=false, CacheSize=1024, StackTraceEnabled=true, CacheEnabled=true, TightEncodingEnabled=true, MaxFrameSize=9223372036854775807, Host=activemq, MaxInactivityDuration=30000, MaxInactivityDurationInitalDelay=10000}, magic=[A,c,t,i,v,e,M,Q]} and remote: WireFormatInfo { version=12, properties={TcpNoDelayEnabled=true, SizePrefixDisabled=false, CacheSize=1024, ProviderName=ActiveMQ, StackTraceEnabled=true, PlatformDetails=JVM: 1.8.0_131, 25.131-b11, Oracle Corporation, OS: Linux, 3.13.0-123-generic, amd64, CacheEnabled=true, TightEncodingEnabled=true, MaxFrameSize=104857600, MaxInactivityDuration=30000, MaxInactivityDurationInitalDelay=10000, ProviderVersion=5.14.5}, magic=[A,c,t,i,v,e,M,Q]}
20:44:09.408 [ActiveMQ Transport: tcp://activemq/172.19.0.3:61616@49948] DEBUG o.a.a.transport.WireFormatNegotiator - Received WireFormat: WireFormatInfo { version=12, properties={TcpNoDelayEnabled=true, SizePrefixDisabled=false, CacheSize=1024, ProviderName=ActiveMQ, StackTraceEnabled=true, PlatformDetails=JVM: 1.8.0_131, 25.131-b11, Oracle Corporation, OS: Linux, 3.13.0-123-generic, amd64, CacheEnabled=true, TightEncodingEnabled=true, MaxFrameSize=104857600, MaxInactivityDuration=30000, MaxInactivityDurationInitalDelay=10000, ProviderVersion=5.14.5}, magic=[A,c,t,i,v,e,M,Q]}
20:44:09.408 [ActiveMQ Transport: tcp://activemq/172.19.0.3:61616@49948] DEBUG o.a.a.transport.WireFormatNegotiator - tcp://activemq/172.19.0.3:61616@49948 before negotiation: OpenWireFormat{version=11, cacheEnabled=false, stackTraceEnabled=false, tightEncodingEnabled=false, sizePrefixDisabled=false, maxFrameSize=9223372036854775807}
20:44:09.409 [ActiveMQ Transport: tcp://activemq/172.19.0.3:61616@49948] DEBUG o.a.a.transport.WireFormatNegotiator - tcp://activemq/172.19.0.3:61616@49948 after negotiation: OpenWireFormat{version=11, cacheEnabled=true, stackTraceEnabled=true, tightEncodingEnabled=true, sizePrefixDisabled=false, maxFrameSize=104857600}
20:44:09.503 [main] INFO  d.f.i.m.PropertyBasedClientSetup - initConnection: connect to activemq OK
20:44:03,473 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
20:44:03,473 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
20:44:03,473 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.xml]
20:44:03,493 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Setting up default configuration.
20:44:09,847 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
20:44:09,861 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeFilter scanning period to 2 minutes
20:44:09,861 |-INFO in ReconfigureOnChangeFilter{invocationCounter=15} - Will scan for changes in [[/root/application/TC.exec-1.0.1/lib/JMSTestRunner_logback.xml]] every 120 seconds.
20:44:09,861 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Adding ReconfigureOnChangeFilter as a turbo filter
20:44:09,862 |-INFO in ch.qos.logback.classic.joran.action.LoggerContextListenerAction - Adding LoggerContextListener of type [ch.qos.logback.classic.jul.LevelChangePropagator] to the object stack
20:44:09,891 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@7a187f14 - Propagating DEBUG level on Logger[ROOT] onto the JUL framework
20:44:09,897 |-INFO in ch.qos.logback.classic.joran.action.LoggerContextListenerAction - Starting LoggerContextListener
20:44:09,897 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.net.JMSTopicAppender]
20:44:09,899 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [JMS]
20:44:09,938 |-WARN in Logger[org.apache.activemq.util.ThreadPoolUtils] - No appenders present in context [default] for logger [org.apache.activemq.util.ThreadPoolUtils].
20:44:09,945 |-ERROR in ch.qos.logback.classic.net.JMSTopicAppender[JMS] - Error while activating options for appender named [JMS]. javax.jms.JMSException: Could not connect to broker URL: tcp://localhost:61616. Reason: java.net.ConnectException: Connection refused (Connection refused)
        at javax.jms.JMSException: Could not connect to broker URL: tcp://localhost:61616. Reason: java.net.ConnectException: Connection refused (Connection refused)
        at      at org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:36)
        at      at org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnection(ActiveMQConnectionFactory.java:360)
        at      at org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnection(ActiveMQConnectionFactory.java:305)
        at      at org.apache.activemq.ActiveMQConnectionFactory.createTopicConnection(ActiveMQConnectionFactory.java:279)
        at      at ch.qos.logback.classic.net.JMSTopicAppender.start(JMSTopicAppender.java:104)
        at      at ch.qos.logback.core.joran.action.AppenderAction.end(AppenderAction.java:96)
        at      at ch.qos.logback.core.joran.spi.Interpreter.callEndAction(Interpreter.java:317)
        at      at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:196)
        at      at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:182)
        at      at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:62)
        at      at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:149)
        at      at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:135)
        at      at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:99)
        at      at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:49)
        at      at de.fraunhofer.iosb.messaginghelpers.LogConfigurationHelper.configureLogging(LogConfigurationHelper.java:45)
        at      at de.fraunhofer.iosb.testrunner.JMSTestRunner.<init>(JMSTestRunner.java:83)
        at      at de.fraunhofer.iosb.testrunner.JMSTestRunner.main(JMSTestRunner.java:65)
Caused by: java.net.ConnectException: Connection refused (Connection refused)
        at      at java.net.PlainSocketImpl.socketConnect(Native Method)
        at      at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
        at      at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
        at      at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
        at      at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
        at      at java.net.Socket.connect(Socket.java:589)
        at      at org.apache.activemq.transport.tcp.TcpTransport.connect(TcpTransport.java:501)
        at      at org.apache.activemq.transport.tcp.TcpTransport.doStart(TcpTransport.java:464)
        at      at org.apache.activemq.util.ServiceSupport.start(ServiceSupport.java:55)
        at      at org.apache.activemq.transport.AbstractInactivityMonitor.start(AbstractInactivityMonitor.java:168)
        at      at org.apache.activemq.transport.InactivityMonitor.start(InactivityMonitor.java:50)
        at      at org.apache.activemq.transport.TransportFilter.start(TransportFilter.java:58)
        at      at org.apache.activemq.transport.WireFormatNegotiator.start(WireFormatNegotiator.java:72)
        at      at org.apache.activemq.transport.TransportFilter.start(TransportFilter.java:58)
        at      at org.apache.activemq.transport.TransportFilter.start(TransportFilter.java:58)
        at      at org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnection(ActiveMQConnectionFactory.java:340)
        at      ... 15 common frames omitted
20:44:09,945 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
20:44:09,947 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE]
20:44:10,011 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - No compression will be used
20:44:10,013 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - Will use the pattern ./logs/LogSinkTest.%d{yyyy-MM-dd}.%i.log for the active file
20:44:10,016 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@1a8a8f7c - The date pattern is 'yyyy-MM-dd' from file name pattern './logs/LogSinkTest.%d{yyyy-MM-dd}.%i.log'.
20:44:10,016 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@1a8a8f7c - Roll-over at midnight.
20:44:10,021 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@1a8a8f7c - Setting initial period to Fri Apr 05 20:44:10 GMT 2019
20:44:10,022 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
20:44:10,041 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Active log file name: ./logs/LogSinkTest.log
20:44:10,041 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - File property is set to [./logs/LogSinkTest.log]
20:44:10,042 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
20:44:10,042 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
20:44:10,046 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
20:44:10,048 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
20:44:10,048 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@7a187f14 - Propagating INFO level on Logger[ROOT] onto the JUL framework
20:44:10,048 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[ROOT]
20:44:10,048 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
20:44:10,048 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [JMS] to Logger[ROOT]
20:44:10,048 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [de.fraunhofer.iosb] to INFO
20:44:10,048 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@7a187f14 - Propagating INFO level on Logger[de.fraunhofer.iosb] onto the JUL framework
20:44:10,049 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
20:44:10,049 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@2353b3e6 - Registering current configuration as safe fallback point

That is because the TC.exec now uses "localhost" also als default for the logback/acticeMq configuration file in https://github.com/MSG134/IVCT_Framework/blob/development/TC.exec/src/conf/JMSTestRunner_logback.xml I changed that from "activemq" to "localhost" because of your earlier comment.

As said before, the problem is, that logback uses its own xml configuration file, to configure the log-adapter configuration for the activeMq. I'm currently changing that code, so that we are not using the logback configuration for any activeMq setings, but to use the Command module in order to forward logging events from TC.exec to the reporter and to the GUI.

In the meantime, you need to configure JMSTestRunner_logback.xml with the activeMq host you want to use.

And please note, your IVCT.properties file still uses the old messaging.user=admin values with the '.' This is not working on linux, and we changed these values (see my earlier comment above). Currently this is no problem for you, because you are using the environment variables to overwrite - it is just to avoid confusion.

I got slightly worried about your comment on the IVCT.properties file.

The container build tool (Travis) uses the one in the IVCT_Framework repository, under RuntimeConfig (https://github.com/MSG134/IVCT_Framework/blob/development/RuntimeConfig/IVCT.properties). This indeed used the "old format". I noticed that Peter created this directory, probably to get Travis going. Are you working from another repository?

We are usually working on the IVCT_Runtime repository. But I think it is helpful to have one minimalistic runtime version for the docker build inside the Framework, as Pieter created it.

I have now reworked the log message transfer from the TC.exec to the LogSink, by replacing the logback-to-activemq mapping by a new Command called CmdSendLogMsg and CmdLogMsgListener. That should solve this configuration issue where the activemq host was also configured within a logback xml file.

If that is working for you, we can close this issue

I reran the following composition, where I deliberately used the name activemq2 to see where what goes wrong. docker-compose.txt

The output is: compose-output.txt

From the output you can see:

tc_runner:

appears to pick up the property activemq2 and connect to activemq at line 126.
However, it later still uses localhost at line 159 to connect to activemq. Hence the connect stracktrace.

logsink:

appears to pick up the property activemq2 and connect to activemq.

GUI:

no activemq related messages in the log.

There is also the issue of the IVCT_Framework/RuntimeConfig/IVCT.properties. This file shows up under /root/conf (tc_runner), with its own property settings. I guess that the content of this file needs to be sync-ed with the IVCT_Runtime repository version of the same file?

See: runnerconfig.txt

So, inconclusive :-).

there have been some configuration artifacts within some logback configuration files. I hope I have cleaned all of them. At least it works in my docker build environment.

Tested against Release 2.0

After updating the docker-compose.yml under https://github.com/IVCTool/IVCT_Compositions/tree/master/ivct-pitch needs to use image ivct/ts-hla-encoding-rules:development-2.0.0, the TC Runner fails to start, because it looks for the host activemq to connect to. The IVCT.properties file shows activemq. By default this should be localhost (see env vars at https://github.com/IVCTool/IVCT_Framework/wiki/IVCT-TC-Runner-Application-image).

Setting the environment variable ACTIVEMQ_HOST to localhost has no effect.

Seems to be fixed in the latest build. So, I close the issue.

IVCTool / IVCT_Framework

Docker ENV ACTIVEMQ_HOST ignored #148