spring-cloud-dataflow: Stream Deployments Fail on OSX

Question

I am unable to deploy and execute a basic http | log stream following the getting-started stream guide:

wget https://raw.githubusercontent.com/spring-cloud/spring-cloud-dataflow/2.1.0.RELEASE/spring-cloud-dataflow-server/docker-compose.yml;
export DATAFLOW_VERSION=2.1.0.RELEASE;
export SKIPPER_VERSION=2.0.2.RELEASE;
docker-compose up;
open http://localhost:9393/dashboard/#/streams/create;
echo "Then, create a stream via text input: `http | log`"
echo "Then, deploy the stream. The deployment fails with exit code 137."

I get the green "Successfully deployed stream definition". The status shows as "Deploying", but it never fully deploys. There are no ERROR messages in the logs, in the UI, or in the network requests.

Here is the console output of docker-compose up after I deploy the stream.

skipper              | 2019-05-24 22:31:53.363  INFO 1 --- [io-7577-exec-10] o.s.s.support.LifecycleObjectSupport     : started UPGRADE UPGRADE_DEPLOY_TARGET_APPS_SUCCEED UPGRADE_DEPLOY_TARGET_APPS UPGRADE_START UPGRADE_DELETE_SOURCE_APPS UPGRADE_CHECK_TARGET_APPS UPGRADE_WAIT_TARGET_APPS UPGRADE_CANCEL UPGRADE_DEPLOY_TARGET_APPS_FAILED UPGRADE_CHECK_CHOICE UPGRADE_EXIT INSTALL INSTALL_INSTALL INSTALL_EXIT ERROR DELETE DELETE_DELETE DELETE_EXIT ROLLBACK ROLLBACK_START ROLLBACK_EXIT_INSTALL ROLLBACK_EXIT ROLLBACK_EXIT_UPGRADE ROLLBACK_CHOICE INITIAL ERROR_JUNCTION  /  / uuid=f1ca31f2-ddcf-4203-88c8-de367c104151 / id=http-log-ingest-5
skipper              | 2019-05-24 22:31:53.504  INFO 1 --- [eTaskExecutor-1] o.s.c.s.s.s.StateMachineConfiguration    : Entering state ObjectState [getIds()=[INITIAL], getClass()=class org.springframework.statemachine.state.ObjectState, hashCode()=1038812346, toString()=AbstractState [id=INITIAL, pseudoState=org.springframework.statemachine.state.DefaultPseudoState@12280a0a, deferred=[], entryActions=[], exitActions=[org.springframework.cloud.skipper.server.statemachine.ResetVariablesAction@6fd12c5], stateActions=[], regions=[], submachine=null]]
skipper              | 2019-05-24 22:31:53.540  INFO 1 --- [eTaskExecutor-3] o.s.c.s.s.s.StateMachineConfiguration    : Entering state StateMachineState [getIds()=[INSTALL], toString()=AbstractState [id=INSTALL, pseudoState=null, deferred=[], entryActions=[], exitActions=[], stateActions=[], regions=[], submachine=INSTALL_INSTALL INSTALL_EXIT  /  / uuid=fbcafd74-2879-4e86-81da-8372a5be31be / id=http-log-ingest-5], getClass()=class org.springframework.statemachine.state.StateMachineState]
skipper              | 2019-05-24 22:31:53.576  INFO 1 --- [eTaskExecutor-3] o.s.c.s.s.s.StateMachineConfiguration    : Entering state ObjectState [getIds()=[INSTALL_INSTALL], getClass()=class org.springframework.statemachine.state.ObjectState, hashCode()=1643670584, toString()=AbstractState [id=INSTALL_INSTALL, pseudoState=org.springframework.statemachine.state.DefaultPseudoState@12493450, deferred=[], entryActions=[org.springframework.cloud.skipper.server.statemachine.InstallInstallAction@149debbb], exitActions=[], stateActions=[], regions=[], submachine=null]]
skipper              | 2019-05-24 22:31:54.117  INFO 1 --- [eTaskExecutor-3] o.s.c.d.spi.local.LocalAppDeployer       : Preparing to run an application from org.springframework.cloud.stream.app:log-sink-kafka:jar:2.1.1.RELEASE. This may take some time if the artifact must be downloaded from a remote host.
skipper              | 2019-05-24 22:31:54.179  INFO 1 --- [eTaskExecutor-3] o.s.c.d.spi.local.LocalAppDeployer       : Command to be executed: /opt/openjdk/bin/java -jar /root/.m2/repository/org/springframework/cloud/stream/app/log-sink-kafka/2.1.1.RELEASE/log-sink-kafka-2.1.1.RELEASE.jar
skipper              | 2019-05-24 22:31:54.203  INFO 1 --- [eTaskExecutor-3] o.s.c.d.spi.local.LocalAppDeployer       : Deploying app with deploymentId http-log-ingest-5.log-v1 instance 0.
skipper              |    Logs will be in /tmp/spring-cloud-deployer-3633167379998955348/http-log-ingest-5-1558737114000/http-log-ingest-5.log-v1
skipper              | 2019-05-24 22:31:54.310  INFO 1 --- [eTaskExecutor-3] o.s.c.d.spi.local.LocalAppDeployer       : Preparing to run an application from org.springframework.cloud.stream.app:http-source-kafka:jar:2.1.0.RELEASE. This may take some time if the artifact must be downloaded from a remote host.
skipper              | 2019-05-24 22:31:54.312  INFO 1 --- [eTaskExecutor-3] o.s.c.d.spi.local.LocalAppDeployer       : Command to be executed: /opt/openjdk/bin/java -jar /root/.m2/repository/org/springframework/cloud/stream/app/http-source-kafka/2.1.0.RELEASE/http-source-kafka-2.1.0.RELEASE.jar
skipper              | 2019-05-24 22:31:54.313  INFO 1 --- [eTaskExecutor-3] o.s.c.d.spi.local.LocalAppDeployer       : Deploying app with deploymentId http-log-ingest-5.http-v1 instance 0.
skipper              |    Logs will be in /tmp/spring-cloud-deployer-3633167379998955348/http-log-ingest-5-1558737114208/http-log-ingest-5.http-v1
skipper              | 2019-05-24 22:31:54.369  INFO 1 --- [eTaskExecutor-3] o.s.s.support.LifecycleObjectSupport     : stopped org.springframework.statemachine.support.DefaultStateMachineExecutor@2c9d52c5
skipper              | 2019-05-24 22:31:54.370  INFO 1 --- [eTaskExecutor-3] o.s.s.support.LifecycleObjectSupport     : stopped INSTALL_INSTALL INSTALL_EXIT  /  / uuid=fbcafd74-2879-4e86-81da-8372a5be31be / id=http-log-ingest-5
skipper              | 2019-05-24 22:31:54.371  INFO 1 --- [eTaskExecutor-3] o.s.c.s.s.s.StateMachineConfiguration    : Entering state ObjectState [getIds()=[INITIAL], getClass()=class org.springframework.statemachine.state.ObjectState, hashCode()=1038812346, toString()=AbstractState [id=INITIAL, pseudoState=org.springframework.statemachine.state.DefaultPseudoState@12280a0a, deferred=[], entryActions=[], exitActions=[org.springframework.cloud.skipper.server.statemachine.ResetVariablesAction@6fd12c5], stateActions=[], regions=[], submachine=null]]
skipper              | 2019-05-24 22:31:54.372  INFO 1 --- [eTaskExecutor-3] o.s.c.s.s.s.SkipperStateMachineService   : setting future value org.springframework.cloud.skipper.domain.Release@279e0d49
skipper              | 2019-05-24 22:31:54.373  INFO 1 --- [eTaskExecutor-3] o.s.s.support.LifecycleObjectSupport     : started org.springframework.statemachine.support.DefaultStateMachineExecutor@2c9d52c5
skipper              | 2019-05-24 22:31:54.373  INFO 1 --- [eTaskExecutor-3] o.s.s.support.LifecycleObjectSupport     : started INSTALL_INSTALL INSTALL_EXIT  /  / uuid=fbcafd74-2879-4e86-81da-8372a5be31be / id=http-log-ingest-5
mysql_1              | 2019-05-24T22:32:45.648870Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4662ms. The settings might not be optimal. (flushed=2 and evicted=0, during the time.)
zookeeper_1          | [2019-05-24 22:32:52,733] INFO Expiring session 0x10001d6560e0001, timeout of 6000ms exceeded (org.apache.zookeeper.server.ZooKeeperServer)
mysql_1              | 2019-05-24T22:33:08.378945Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 7338ms. The settings might not be optimal. (flushed=1 and evicted=0, during the time.)
mysql_1              | 2019-05-24T22:33:24.272169Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5118ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
zookeeper_1          | [2019-05-24 22:33:28,644] INFO Processed session termination for sessionid: 0x10001d6560e0001 (org.apache.zookeeper.server.PrepRequestProcessor)
kafka_1              | [2019-05-24 22:33:40,709] INFO [GroupMetadataManager brokerId=1001] Removed 0 expired offsets in 2216 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
kafka_1              | [2019-05-24 22:33:49,359] WARN Client session timed out, have not heard from server in 58623ms for sessionid 0x10001d6560e0001 (org.apache.zookeeper.ClientCnxn)
kafka_1              | [2019-05-24 22:33:56,611] TRACE [Controller id=1001] Checking need to trigger auto leader balancing (kafka.controller.KafkaController)
kafka_1              | [2019-05-24 22:34:06,529] DEBUG [Controller id=1001] Preferred replicas by broker Map(1001 -> Map(__consumer_offsets-22 -> Vector(1001), __consumer_offsets-30 -> Vector(1001), __consumer_offsets-8 -> Vector(1001), __consumer_offsets-21 -> Vector(1001), __consumer_offsets-4 -> Vector(1001), __consumer_offsets-27 -> Vector(1001), __consumer_offsets-7 -> Vector(1001), __consumer_offsets-9 -> Vector(1001), __consumer_offsets-46 -> Vector(1001), http-ingest-log-4.http-0 -> Vector(1001), __consumer_offsets-25 -> Vector(1001), __consumer_offsets-35 -> Vector(1001), __consumer_offsets-41 -> Vector(1001), __consumer_offsets-33 -> Vector(1001), __consumer_offsets-23 -> Vector(1001), __consumer_offsets-49 -> Vector(1001), __consumer_offsets-47 -> Vector(1001), __consumer_offsets-16 -> Vector(1001), __consumer_offsets-28 -> Vector(1001), __consumer_offsets-31 -> Vector(1001), __consumer_offsets-36 -> Vector(1001), __consumer_offsets-42 -> Vector(1001), __consumer_offsets-3 -> Vector(1001), __consumer_offsets-18 -> Vector(1001), __consumer_offsets-37 -> Vector(1001), http-ingest-log-3.http-0 -> Vector(1001), __consumer_offsets-15 -> Vector(1001), __consumer_offsets-24 -> Vector(1001), __consumer_offsets-38 -> Vector(1001), __consumer_offsets-17 -> Vector(1001), __consumer_offsets-48 -> Vector(1001), __confluent.support.metrics-0 -> Vector(1001), __consumer_offsets-19 -> Vector(1001), __consumer_offsets-11 -> Vector(1001), __consumer_offsets-13 -> Vector(1001), __consumer_offsets-2 -> Vector(1001), __consumer_offsets-43 -> Vector(1001), __consumer_offsets-6 -> Vector(1001), __consumer_offsets-14 -> Vector(1001), __consumer_offsets-20 -> Vector(1001), __consumer_offsets-0 -> Vector(1001), __consumer_offsets-44 -> Vector(1001), __consumer_offsets-39 -> Vector(1001), __consumer_offsets-12 -> Vector(1001), __consumer_offsets-45 -> Vector(1001), __consumer_offsets-1 -> Vector(1001), __consumer_offsets-5 -> Vector(1001), __consumer_offsets-26 -> Vector(1001), __consumer_offsets-29 -> Vector(1001), __consumer_offsets-34 -> Vector(1001), __consumer_offsets-10 -> Vector(1001), __consumer_offsets-32 -> Vector(1001), __consumer_offsets-40 -> Vector(1001))) (kafka.controller.KafkaController)
kafka_1              | [2019-05-24 22:34:11,269] DEBUG [Controller id=1001] Topics not in preferred replica for broker 1001 Map() (kafka.controller.KafkaController)
kafka_1              | [2019-05-24 22:34:11,993] TRACE [Controller id=1001] Leader imbalance ratio for broker 1001 is 0.0 (kafka.controller.KafkaController)
kafka_1              | [2019-05-24 22:34:23,483] INFO Client session timed out, have not heard from server in 58623ms for sessionid 0x10001d6560e0001, closing socket connection and attempting reconnect (org.apache.zookeeper.ClientCnxn)
mysql_1              | 2019-05-24T22:35:19.628193Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4049ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
...
(several minutes later)
...
dataflow-server exited with code 137

I get the same behavior when swapping out different parts of the stack; for example RabbitMQ for Kafka/Zookeeper, Postgres for MySQL.

My local stack:

OSX 10.14
Java openjdk 11.0.2
Docker engine 18.09.2
Docker Compose 1.23.2
Docker Machine 0.16.1

score 1 · Accepted Answer · answered May 28 '19 at 16:26

1

dataflow-server was failing silently due to memory issues. I raised the docker memory limit to 16 GB and stream deployment worked, but the "Runtime" page (http://localhost:9393/dashboard/#/runtime/apps) is still inaccessible. Separate issue tho!

answered May 28 '19 at 16:26

JJ Zabkar

3,792
7
45
65

score 0 · Answer 2 · answered May 27 '19 at 15:35

0

The Docker Compose console won't include the exact reasoning as to what failed and why.

When the stream is deploying, you could view the application logs with the following command.

docker exec -it skipper tail -f /path/from/stdout/textbox/in/dashboard

That would indicate whether or not the applications start and specific reasoning, which would help in troubleshooting.

answered May 27 '19 at 15:35

Sabby Anandan

5,636
2
12
21

hello, I was trying this but when I use this command it just removes the directory I am pointing at in the cmd.exe window. Does this command move the stdout file somewhere on my machine or should it be displaying something in the command prompt? – Kachopsticks Feb 14 '20 at 15:17

score 0 · Answer 3 · answered Feb 14 '20 at 16:56

To build on Sabby Anandans answer, if you want to get the logs for a specific cloud stream application, I found that you can mount the volume for the skipper server. I believe when running on docker, all of the spring data flow stream applications write logs out to a tmp directory. If you open up the application that failed to deploy it will tell you where it logs out the file. It should be something like...

/tmp/[RANDOM ID]/[NAME OF APPLICATION PLUS RUN VERSION]/stdout_0.log

So if you just mount a volume for the tmp folder to your skipper container, it should write out the logs. Make sure you mount to skipper-server and not dataflow-server. Dataflow-server also writes to this directory but it does not write the logs.

In my docker-compose.yml file, under skipper-server:

volumes:
  - C:\dataflow\output\logs:/tmp

So after restarting my dataflow server by doing a docker-compose up, I was able to get logs out for my failing application at...

C:\dataflow\output\logs\1581698212231\streamName.applicationName-v1\

spring-cloud-dataflow: Stream Deployments Fail on OSX

3 Answers3