Skip to content
This repository has been archived by the owner on Jul 28, 2020. It is now read-only.

Unable to start PCF-Dev environment: Timed out after 3600 seconds. #273

Closed
stalv opened this issue Nov 24, 2017 · 31 comments
Closed

Unable to start PCF-Dev environment: Timed out after 3600 seconds. #273

stalv opened this issue Nov 24, 2017 · 31 comments
Labels
accepted help wanted

Comments

@stalv
Copy link

stalv commented Nov 24, 2017

I'm unable to start PCF-Dev environment on my local linux machine. The command cf dev start failing after 3600 sec timeout.

# cf dev start -m 8096 -s all 
Downloading VM...
Progress: |====================>| 100% 
VM downloaded.
Allocating 8096 MB out of 31958 MB total system memory (18471 MB free).
Importing VM...
Starting VM...
Provisioning VM...
Waiting for services to start...
Timed out after 3600 seconds.
FAILED
Error: failed to provision VM: Process exited with: 1. Reason was:  ().

Virutal machine is up and running and I can ssh to it with cf dev ssh. There is only one suspicious thing in the logs in /var/vcap directory

/var/vcap/monit/monit.log
[UTC Nov 23 16:37:03] info     : 'galera-healthcheck' start: /var/vcap/jobs/mysql/bin/galera-healthch
eck_ctl
[UTC Nov 23 16:38:03] error    : 'galera-healthcheck' failed to start
[UTC Nov 23 16:38:03] info     : 'galera-healthcheck' start action done
[UTC Nov 23 16:38:13] info     : Awakened by User defined signal 1
[UTC Nov 23 16:38:13] error    : 'galera-healthcheck' process is not running
[UTC Nov 23 16:38:13] info     : 'galera-healthcheck' trying to restart
[UTC Nov 23 16:38:13] info     : 'galera-healthcheck' start: /var/vcap/jobs/mysql/bin/galera-healthch
eck_ctl

My system details:
Ubuntu 17.10 x64 4.13.0-16-generic
VirtualBox 5.1.30_Ubuntu r118389
PCF Dev version 0.28.0 (CLI: 5cda315, OVA: 0.547.0)
@cf-gitbot
Copy link

We have created an issue in Pivotal Tracker to manage this. Unfortunately, the Pivotal Tracker project is private so you may be unable to view the contents of the story.

The labels on this github issue will be updated when the story is started.

@sclevine
Copy link
Contributor

Hi @stalv,

Sorry for the delay!

Can you provide more info about the hardware you're running PCF Dev on?

Does it start successfully without -s all?

@stalv
Copy link
Author

stalv commented Dec 18, 2017

Hi @sclevine,
I'm trying to run PCF Dev on desktop workstation with Intel Xeon quad-core CPU and 32 GB RAM. I tried to start it several times with different parameters (simple cf dev start as well) without any success.

@sclevine
Copy link
Contributor

How about with cf dev start -s none?

If you email me ([email protected]) the archive generated by running cf dev debug after a failure, I can examine the logs for you. You may want to ensure nothing sensitive is in the archive.

@justintilson
Copy link

PCF Dev start up fails about 50% of the time for me. Mid-2012 Macbook Pro with 16GB Ram and 2.9GHz

$ cf dev start -s scs
Using existing image.
Allocating 8192 MB out of 16384 MB total system memory (10569 MB free).
Importing VM...
Starting VM...
Provisioning VM...
Waiting for services to start...
7 out of 54 running
7 out of 54 running
7 out of 54 running
7 out of 54 running
37 out of 54 running
52 out of 54 running
54 out of 54 running
FAILED
Error: failed to provision VM: Process exited with: 1. Reason was:  ().

@stalv
Copy link
Author

stalv commented Jan 2, 2018

@sclevine same thing with cf dev start -s none:

➜  ~ cf dev destroy       
[sudo] password for stalv: 
PCF Dev VM has been destroyed.
➜  ~ cf dev start -m 8096 -s none
Using existing image.
Allocating 8096 MB out of 31958 MB total system memory (15263 MB free).
Importing VM...
Starting VM...
Provisioning VM...
Waiting for services to start...
Timed out after 3600 seconds.
FAILED
Error: failed to provision VM: Process exited with: 1. Reason was:  ().

@ghost
Copy link

ghost commented Feb 12, 2018 •
edited by ghost
Loading

Facing similar issues .. any solutions on it ?

2018-02-12T05:29:48.30-0800 [CELL/0] OUT Starting health monitoring of container
2018-02-12T05:30:46.94-0800 [APP/PROC/WEB/0] ERR trusting certificate at api.local.pcfdev.io:443 failed due to java.u
.concurrent.TimeoutException
2018-02-12T05:30:47.20-0800 [APP/PROC/WEB/0] ERR java.util.concurrent.TimeoutException
2018-02-12T05:30:47.45-0800 [APP/PROC/WEB/0] ERR at java.util.concurrent.FutureTask.get(FutureTask.java:205)
2018-02-12T05:30:47.48-0800 [APP/PROC/WEB/0] ERR at io.pivotal.springcloud.ssl.SslCertificateTruster.getUntrusted
tificateInternal(SslCertificateTruster.java:90)
2018-02-12T05:30:47.48-0800 [APP/PROC/WEB/0] ERR at io.pivotal.springcloud.ssl.SslCertificateTruster.getUntrusted
tificate(SslCertificateTruster.java:66)
2018-02-12T05:30:47.48-0800 [APP/PROC/WEB/0] ERR at io.pivotal.springcloud.ssl.SslCertificateTruster.trustCertifi
eInternal(SslCertificateTruster.java:121)
2018-02-12T05:30:47.48-0800 [APP/PROC/WEB/0] ERR at io.pivotal.springcloud.ssl.CloudFoundryCertificateTruster.tru
ertificatesInternal(CloudFoundryCertificateTruster.java:44)
2018-02-12T05:30:47.48-0800 [APP/PROC/WEB/0] ERR at io.pivotal.springcloud.ssl.CloudFoundryCertificateTruster.tru
ertificates(CloudFoundryCertificateTruster.java:32)
2018-02-12T05:30:47.48-0800 [APP/PROC/WEB/0] ERR at io.pivotal.springcloud.ssl.CloudFoundryCertificateTruster.(CloudFoundryCertificateTruster.java:77)
2018-02-12T05:30:47.48-0800 [APP/PROC/WEB/0] ERR at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native
thod)
2018-02-12T05:30:47.48-0800 [APP/PROC/WEB/0] ERR at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeC
tructorAccessorImpl.java:62)
2018-02-12T05:30:47.48-0800 [APP/PROC/WEB/0] ERR at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Del
tingConstructorAccessorImpl.java:45)
2018-02-12T05:30:47.48-0800 [APP/PROC/WEB/0] ERR at java.lang.reflect.Constructor.newInstance(Constructor.java:42

@shanedeeodonnell
Copy link

shanedeeodonnell commented Feb 17, 2018 •
edited
Loading

Just started happening after most recent MacOS update (10.13.3). It was working fine until then.
I have tried all suggestions so far.

55 out of 56 running
Timed out after 3600 seconds.
FAILED
Error: failed to provision VM: Process exited with: 1. Reason was: ().

Virtualbox 5.2.6
pcfdev-v0.26+PCF1.10-osx
iMac: Late 2012, 3.4Gh i7, 32 GB memory.

@carolmorneau
Copy link

Virtualbox 5.1.14
PCF Dev version 0.28.0 (CLI: 5cda315, OVA: 0.547.0)
MacOS 10.12.6

cf dev start
...
57 out of 58 running
57 out of 58 running
57 out of 58 running
Timed out after 3600 seconds.
FAILED
Error: failed to provision VM: Process exited with: 1. Reason was:  ().

SSHing inside with cf dev ssh and looking at the monit processes, I see

Process 'syslog_drain_binder' Execution failed

Looking at the log file:

/var/vcap/sys/log/syslog_drain_binder/syslog_drain_binder.log

I see this certificate error continuously

2018/02/17 19:54:47 Starting pprof server on: 127.0.0.1:37955
panic: x509: certificate has expired or is not yet valid

goroutine 1 [running]:
panic(0xa34b80, 0xc420224280)
	/var/vcap/data/packages/golang1.7/c5de560ab1578122cd22032249fb7f1f287768d4/src/runtime/panic.go:500 +0x1a1
main.main()
	/var/vcap/data/compile/syslog_drain_binder/loggregator/src/syslog_drain_binder/main.go:55 +0xbd5

@firasag
Copy link

firasag commented Feb 18, 2018 •
edited
Loading

Appreciate if someone can point to a solution for this problem. Started seeing this behavior a couple of days ago. Running on:
MacBook pro Mid 2015.
VirtualBox version 5.2.6 r120293 (Qt5.6.3)

$ cf dev version
PCF Dev version 0.28.0 (CLI: 5cda315, OVA: 0.547.0)

$ cf dev destroy
PCF Dev VM has been destroyed.
$ cf dev start
Using existing image.
Allocating 4096 MB out of 16384 MB total system memory (11078 MB free).
Importing VM...
Starting VM...
Provisioning VM...
Waiting for services to start...
7 out of 58 running
7 out of 58 running
7 out of 58 running
7 out of 58 running
13 out of 58 running
39 out of 58 running 
46 out of 58 running
55 out of 58 running
57 out of 58 running
57 out of 58 running
57 out of 58 running
57 out of 58 running
57 out of 58 running
...
57 out of 58 running
Timed out after 3600 seconds.
FAILED
Error: failed to provision VM: Process exited with: 1. Reason was: ().

@SnehaKumari22
Copy link

SnehaKumari22 commented Feb 19, 2018 •
edited
Loading

Same issue. Started seeing the same issue a couple of days ago.
Timed out after 3600 seconds. FAILED Error: failed to provision VM: Process exited with: 1. Reason was: ().
Running on:
Windows 10 machine.
VirtualBox version 5.2.6
Any solutions yet?
Even though the provisioning of VM failed message was displayed the VM was running in virtual box and I was able to login using the cf login -a api.local.pcfdev.io --skip-ssl-validation and perform all cf commands. The difference was that the system org was not listed on using cf orgs command. Only pcfdev-org was listed. Rest all command were working fine.

@menza12
Copy link

menza12 commented Feb 19, 2018 •
edited
Loading

I started the services successful once, since then the service provisioning stops at 55 services (0.26) or 57 services (0.28).
Windows 10 enterprise (creators update installed)
Virtualbox 5.2.6
8 core
16 GB RAM

any help appreciated
pcfdev-debug.zip

... debug output (cf dev debug) is attached

@cicnavi
Copy link

cicnavi commented Feb 19, 2018

Hi, I'm having the same problem as @firasag ... It used to work (around 20 days ago), but in the mean time I've applied Windows 10 updates (not sure if that is the reason, just saying...). Today I tried to start it again, and it timed out.

I'm running:

  • Windows 10 (Version10.0.16299 Build 16299, I've applied Windows 10 updates few days ago).
  • VirtualBox version 5.2.6
  • PCF Dev version 0.28.0 (CLI: 5cda315, OVA: 0.547.0)
$ cf dev start
Using existing image.
Allocating 4096 MB out of 32647 MB total system memory (21679 MB free).
Importing VM...
Starting VM...
Provisioning VM...
Waiting for services to start...
7 out of 58 running
...
13 out of 58 running
39 out of 58 running 
46 out of 58 running
55 out of 58 running
57 out of 58 running
57 out of 58 running
57 out of 58 running
...
57 out of 58 running
Timed out after 3600 seconds.
FAILED
Error: failed to provision VM: Process exited with: 1. Reason was: ().

@xPerdev
Copy link

xPerdev commented Feb 19, 2018

MacBook Pro (13-inch, Late 2016)/Intel Core i7 2,4 GHz dual-core/16Gb Memory/ 500 Gb SSD
VirtualBox Version 5.2.6 r120293 (Qt5.6.3)
PCF Dev version 0.28.0 (CLI: 5cda315, OVA: 0.547.0)

All was running fine last week, but since yesterday (February 18th, 2018) it fails to complete startup as only 57 of 58 services will start.

$ cf dev start
Using existing image.
Allocating 4096 MB out of 16384 MB total system memory (12274 MB free).
Importing VM...
Starting VM...
Provisioning VM...
Waiting for services to start...
7 out of 58 running
7 out of 58 running
7 out of 58 running
7 out of 58 running
35 out of 58 running
39 out of 58 running
55 out of 58 running
57 out of 58 running
…
57 out of 58 running
Timed out after 3600 seconds.
FAILED
Error: failed to provision VM: Process exited with: 1. Reason was:  ().

Gathering log files using cf dev debug command and ssh’ing into the virtual machine teaches me that it’s the service syslog_drain_binder that doesn’t start because its certificate (/var/vcap/jobs/syslog_drain_binder/config/certs/syslogdrainbinder.crt) expired on Feb 15 22:35:39 2018 GMT

As such it seems we need to update the certificate to make it work again.

The information in the logs that lead me to this conclusion are below:

/var/pcfdev/provision.log

----------- STARTING pre-start-execution at Mon Feb 19 07:58:22 UTC 2018 --------------
     2 2018-02-19 07:58:33 ----- pre-start execution script: pre-start completed with error code 0
     3 2018-02-19 07:58:33 ----- pre-start execution script: completed pre-start execution
     4 + start_services mariadb_ctrl galera-healthcheck
     5 + for service in '$@'
     6 + /var/vcap/bosh/bin/monit start mariadb_ctrl
     7 + for service in '$@'
     8 + /var/vcap/bosh/bin/monit start galera-healthcheck
     9 + for service in '$@'
    10 + grep -q running
    11 + grep mariadb_ctrl
    12 + monit_summary
    13 ++ /var/vcap/bosh/bin/monit summary
    14 + output='The Monit daemon 5.2.5 uptime: 0m
    15
    16 Process '\''pcfdev-api'\''                not monitored
    17 Process '\''pcfdev-nginx'\''              not monitored
    18 Process '\''vxlan-policy-agent'\''        not monitored
    19 Process '\''uaa'\''                       not monitored
    20 Process '\''tps_listener'\''              not monitored
    21 Process '\''tps_watcher'\''               not monitored
    22 Process '\''tcp_router'\''                not monitored
    23 Process '\''tcp_emitter'\''               not monitored
    24 Process '\''syslog_drain_binder'\''       not monitored
    25 Process '\''syslog-configurator'\''       not monitored
    26 Process '\''stager'\''                    not monitored
    27 Process '\''ssh_proxy'\''                 not monitored
    28 Process '\''silk-daemon'\''               not monitored
    29 Process '\''silk-controller'\''           not monitored
    30 Process '\''routing-api'\''               not monitored
    31 Process '\''route_registrar'\''           not monitored
    32 Process '\''route_emitter'\''             not monitored
    33 Process '\''rep'\''                       not monitored
    34 Process '\''rabbitmq-server'\''           not monitored
    35 Process '\''rabbitmq-broker'\''           not monitored
    36 Process '\''policy-server'\''             not monitored
    37 Process '\''nsync_listener'\''            not monitored
    38 Process '\''nsync_bulker'\''              not monitored
    39 Process '\''netmon'\''                    not monitored
    40 Process '\''nats'\''                      not monitored
    41 Process '\''mariadb_ctrl'\''              not monitored - start pending
    42 Process '\''galera-healthcheck'\''        not monitored - start pending
    43 Process '\''gra-log-purger-executable'\'' not monitored
    44 Process '\''cluster_health_logger'\''     not monitored
    45 Process '\''metron_agent'\''              not monitored
    46 Process '\''loggregator_trafficcontroller'\'' not monitored
    47 Process '\''localdriver'\''               not monitored
    48 Process '\''localbroker'\''               not monitored
    49 Process '\''gorouter'\''                  not monitored
    50 Process '\''garden'\''                    not monitored
    51 Process '\''file_server'\''               not monitored
    52 Process '\''etcd'\''                      not monitored
    53 Process '\''etcd_consistency_checker'\''  not monitored
    54 Process '\''doppler'\''                   not monitored
    55 Process '\''consul_agent'\''              not monitored
    56 Process '\''cloud_controller_worker_1'\'' not monitored
    57 Process '\''cloud_controller_ng'\''       not monitored
    58 Process '\''cloud_controller_worker_local_1'\'' not monitored
    59 Process '\''cloud_controller_worker_local_2'\'' not monitored
    60 Process '\''nginx_cc'\''                  not monitored
    61 Process '\''cloud_controller_clock'\''    not monitored
    62 Process '\''process-watcher'\''           not monitored
    63 Process '\''process-destroyer'\''         not monitored
    64 Process '\''cf-redis-broker'\''           not monitored
    65 Process '\''broker-nginx'\''              not monitored
    66 Process '\''cf-mysql-broker'\''           not monitored
    67 Process '\''quota-enforcer'\''            not monitored
    68 Process '\''cc_uploader'\''               not monitored
    69 Process '\''blobstore_nginx'\''           not monitored
    70 Process '\''blobstore_url_signer'\''      not monitored
    71 Process '\''bbs'\''                       not monitored
    72 Process '\''auctioneer'\''                not monitored
    73 System '\''system_localhost'\''           not monitored'
    74 + [[ The Monit daemon 5.2.5 uptime: 0m
…
+ for service in '$(stopped_services)'
 17977 + /var/vcap/bosh/bin/monit start pcfdev-api
 17978 + for service in '$(stopped_services)'
 17979 + /var/vcap/bosh/bin/monit start pcfdev-nginx
 17980 + for service in '$(stopped_services)'
 17981 + /var/vcap/bosh/bin/monit start vxlan-policy-agent
 17982 + for service in '$(stopped_services)'
 17983 + /var/vcap/bosh/bin/monit start tps_listener
 17984 + for service in '$(stopped_services)'
 17985 + /var/vcap/bosh/bin/monit start tps_watcher
 17986 + for service in '$(stopped_services)'
 17987 + /var/vcap/bosh/bin/monit start tcp_router
 17988 + for service in '$(stopped_services)'
 17989 + /var/vcap/bosh/bin/monit start tcp_emitter
 17990 + for service in '$(stopped_services)'
 17991 + /var/vcap/bosh/bin/monit start syslog_drain_binder
 17992 + for service in '$(stopped_services)'
 17993 + /var/vcap/bosh/bin/monit start syslog-configurator
 17994 + for service in '$(stopped_services)'
 17995 + /var/vcap/bosh/bin/monit start stager
 17996 + for service in '$(stopped_services)'
 17997 + /var/vcap/bosh/bin/monit start ssh_proxy
 17998 + for service in '$(stopped_services)'
 17999 + /var/vcap/bosh/bin/monit start silk-daemon
 18000 + for service in '$(stopped_services)'
 18001 + /var/vcap/bosh/bin/monit start silk-controller
 18002 + for service in '$(stopped_services)'
 18003 + /var/vcap/bosh/bin/monit start routing-api
 18004 + for service in '$(stopped_services)'
 18005 + /var/vcap/bosh/bin/monit start route_registrar
 18006 + for service in '$(stopped_services)'
 18007 + /var/vcap/bosh/bin/monit start route_emitter
 18008 + for service in '$(stopped_services)'
 18009 + /var/vcap/bosh/bin/monit start rep
 18010 + for service in '$(stopped_services)'
 18011 + /var/vcap/bosh/bin/monit start rabbitmq-server
 18012 + for service in '$(stopped_services)'
 18013 + /var/vcap/bosh/bin/monit start rabbitmq-broker
 18014 + for service in '$(stopped_services)'
 18015 + /var/vcap/bosh/bin/monit start policy-server
 18016 + for service in '$(stopped_services)'
 18017 + /var/vcap/bosh/bin/monit start nsync_listener
 18018 + for service in '$(stopped_services)'
 18019 + /var/vcap/bosh/bin/monit start nsync_bulker
 18020 + for service in '$(stopped_services)'
 18021 + /var/vcap/bosh/bin/monit start netmon
 18022 + for service in '$(stopped_services)'
 18023 + /var/vcap/bosh/bin/monit start nats
 18024 + for service in '$(stopped_services)'
 18025 + /var/vcap/bosh/bin/monit start gra-log-purger-executable
 18026 + for service in '$(stopped_services)'
 18027 + /var/vcap/bosh/bin/monit start cluster_health_logger
 18028 + for service in '$(stopped_services)'
 18029 + /var/vcap/bosh/bin/monit start metron_agent
 18030 + for service in '$(stopped_services)'
 18031 + /var/vcap/bosh/bin/monit start loggregator_trafficcontroller
 18032 + for service in '$(stopped_services)'
 18033 + /var/vcap/bosh/bin/monit start localdriver
 18034 + for service in '$(stopped_services)'
 18035 + /var/vcap/bosh/bin/monit start localbroker
 18036 + for service in '$(stopped_services)'
 18037 + /var/vcap/bosh/bin/monit start gorouter
 18038 + for service in '$(stopped_services)'
 18039 + /var/vcap/bosh/bin/monit start file_server
 18040 + for service in '$(stopped_services)'
 18041 + /var/vcap/bosh/bin/monit start etcd_consistency_checker
 18042 + for service in '$(stopped_services)'
 18043 + /var/vcap/bosh/bin/monit start doppler
 18044 + for service in '$(stopped_services)'
 18045 + /var/vcap/bosh/bin/monit start cloud_controller_worker_1
 18046 + for service in '$(stopped_services)'
 18047 + /var/vcap/bosh/bin/monit start cloud_controller_ng
 18048 + for service in '$(stopped_services)'
 18049 + /var/vcap/bosh/bin/monit start cloud_controller_worker_local_1
 18050 + for service in '$(stopped_services)'
 18051 + /var/vcap/bosh/bin/monit start cloud_controller_worker_local_2
 18052 + for service in '$(stopped_services)'
 18053 + /var/vcap/bosh/bin/monit start nginx_cc
 18054 + for service in '$(stopped_services)'
 18055 + /var/vcap/bosh/bin/monit start cloud_controller_clock
 18056 + for service in '$(stopped_services)'
 18057 + /var/vcap/bosh/bin/monit start process-watcher
 18058 + for service in '$(stopped_services)'
 18059 + /var/vcap/bosh/bin/monit start process-destroyer
 18060 + for service in '$(stopped_services)'
 18061 + /var/vcap/bosh/bin/monit start cf-redis-broker
 18062 + for service in '$(stopped_services)'
 18063 + /var/vcap/bosh/bin/monit start broker-nginx
 18064 + for service in '$(stopped_services)'
 18065 + /var/vcap/bosh/bin/monit start cf-mysql-broker
 18066 + for service in '$(stopped_services)'
 18067 + /var/vcap/bosh/bin/monit start quota-enforcer
 18068 + for service in '$(stopped_services)'
 18069 + /var/vcap/bosh/bin/monit start cc_uploader
 18070 + for service in '$(stopped_services)'
 18071 + /var/vcap/bosh/bin/monit start blobstore_nginx
 18072 + for service in '$(stopped_services)'
 18073 + /var/vcap/bosh/bin/monit start blobstore_url_signer
 18074 + for service in '$(stopped_services)'
 18075 + /var/vcap/bosh/bin/monit start auctioneer
 18076 + for service in '$(stopped_services)'
 18077 + /var/vcap/bosh/bin/monit start system_localhost
 18078 ++ total_services
 18079 ++ monit_summary
 18080 ++ grep -E '^(Process|File|System)'
 18081 ++ wc -l
 18082 +++ /var/vcap/bosh/bin/monit summary
 18083 ++ output='The Monit daemon 5.2.5 uptime: 2m
 18084
 18085 Process '\''pcfdev-api'\''                initializing
 18086 Process '\''pcfdev-nginx'\''              initializing
 18087 Process '\''vxlan-policy-agent'\''        not monitored - start pending
 18088 Process '\''uaa'\''                       running
 18089 Process '\''tps_listener'\''              not monitored - start pending
 18090 Process '\''tps_watcher'\''               not monitored - start pending
 18091 Process '\''tcp_router'\''                not monitored - start pending
 18092 Process '\''tcp_emitter'\''               not monitored - start pending
 18093 Process '\''syslog_drain_binder'\''       not monitored - start pending
 18094 Process '\''syslog-configurator'\''       not monitored - start pending
 18095 Process '\''stager'\''                    not monitored - start pending
 18096 Process '\''ssh_proxy'\''                 not monitored - start pending
 18097 Process '\''silk-daemon'\''               not monitored - start pending
 18098 Process '\''silk-controller'\''           not monitored - start pending
 18099 Process '\''routing-api'\''               not monitored - start pending
 18100 Process '\''route_registrar'\''           not monitored - start pending
 18101 Process '\''route_emitter'\''             not monitored - start pending
 18102 Process '\''rep'\''                       not monitored - start pending
 18103 Process '\''rabbitmq-server'\''           not monitored - start pending
 18104 Process '\''rabbitmq-broker'\''           not monitored - start pending
 18105 Process '\''policy-server'\''             not monitored - start pending
 18106 Process '\''nsync_listener'\''            not monitored - start pending
 18107 Process '\''nsync_bulker'\''              not monitored - start pending
 18108 Process '\''netmon'\''                    not monitored - start pending
 18109 Process '\''nats'\''                      not monitored - start pending
 18110 Process '\''mariadb_ctrl'\''              running
 18111 Process '\''galera-healthcheck'\''        running
 18112 Process '\''gra-log-purger-executable'\'' not monitored - start pending
 18113 Process '\''cluster_health_logger'\''     not monitored - start pending
 18114 Process '\''metron_agent'\''              not monitored - start pending
 18115 Process '\''loggregator_trafficcontroller'\'' not monitored - start pending
 18116 Process '\''localdriver'\''               not monitored - start pending
 18117 Process '\''localbroker'\''               not monitored - start pending
 18118 Process '\''gorouter'\''                  not monitored - start pending
 18119 Process '\''garden'\''                    running
 18120 Process '\''file_server'\''               not monitored - start pending
 18121 Process '\''etcd'\''                      running
 18122 Process '\''etcd_consistency_checker'\''  not monitored - start pending
 18123 Process '\''doppler'\''                   not monitored - start pending
 18124 Process '\''consul_agent'\''              running
 18125 Process '\''cloud_controller_worker_1'\'' not monitored - start pending
 18126 Process '\''cloud_controller_ng'\''       not monitored - start pending
 18127 Process '\''cloud_controller_worker_local_1'\'' not monitored - start pending
 18128 Process '\''cloud_controller_worker_local_2'\'' not monitored - start pending
 18129 Process '\''nginx_cc'\''                  not monitored - start pending
 18130 Process '\''cloud_controller_clock'\''    not monitored - start pending
 18131 Process '\''process-watcher'\''           not monitored - start pending
 18132 Process '\''process-destroyer'\''         not monitored - start pending
 18133 Process '\''cf-redis-broker'\''           not monitored - start pending
 18134 Process '\''broker-nginx'\''              not monitored - start pending
 18135 Process '\''cf-mysql-broker'\''           not monitored - start pending
 18136 Process '\''quota-enforcer'\''            not monitored - start pending
 18137 Process '\''cc_uploader'\''               not monitored - start pending
 18138 Process '\''blobstore_nginx'\''           not monitored - start pending
 18139 Process '\''blobstore_url_signer'\''      not monitored - start pending
 18140 Process '\''bbs'\''                       running
 18141 Process '\''auctioneer'\''                not monitored - start pending
 18142 System '\''system_localhost'\''           not monitored - start pending'
 18143 ++ [[ The Monit daemon 5.2.5 uptime: 2m
…
Process 'pcfdev-api'                initializing
 24704 Process 'pcfdev-nginx'              initializing
 24705 Process 'vxlan-policy-agent'        initializing
 24706 Process 'uaa'                       running
 24707 Process 'tps_listener'              initializing
 24708 Process 'tps_watcher'               initializing
 24709 Process 'tcp_router'                initializing
 24710 Process 'tcp_emitter'               initializing
 24711 Process 'syslog_drain_binder'       initializing
 24712 Process 'syslog-configurator'       initializing - start pending
 24713 Process 'stager'                    not monitored - start pending
 24714 Process 'ssh_proxy'                 not monitored - start pending
 24715 Process 'silk-daemon'               not monitored - start pending
 24716 Process 'silk-controller'           not monitored - start pending
 24717 Process 'routing-api'               not monitored - start pending
 24718 Process 'route_registrar'           not monitored - start pending
 24719 Process 'route_emitter'             not monitored - start pending
 24720 Process 'rep'                       not monitored - start pending
 24721 Process 'rabbitmq-server'           not monitored - start pending
 24722 Process 'rabbitmq-broker'           not monitored - start pending
 24723 Process 'policy-server'             not monitored - start pending
 24724 Process 'nsync_listener'            not monitored - start pending
 24725 Process 'nsync_bulker'              not monitored - start pending
 24726 Process 'netmon'                    not monitored - start pending
 24727 Process 'nats'                      not monitored - start pending
 24728 Process 'mariadb_ctrl'              running
 24729 Process 'galera-healthcheck'        running
 24730 Process 'gra-log-purger-executable' not monitored - start pending
 24731 Process 'cluster_health_logger'     not monitored - start pending
 24732 Process 'metron_agent'              not monitored - start pending
 24733 Process 'loggregator_trafficcontroller' not monitored - start pending
 24734 Process 'localdriver'               not monitored - start pending
 24735 Process 'localbroker'               not monitored - start pending
 24736 Process 'gorouter'                  not monitored - start pending
 24737 Process 'garden'                    running
 24738 Process 'file_server'               not monitored - start pending
 24739 Process 'etcd'                      running
 24740 Process 'etcd_consistency_checker'  not monitored - start pending
 24741 Process 'doppler'                   not monitored - start pending
 24742 Process 'consul_agent'              running
 24743 Process 'cloud_controller_worker_1' not monitored - start pending
 24744 Process 'cloud_controller_ng'       not monitored - start pending
 24745 Process 'cloud_controller_worker_local_1' not monitored - start pending
 24746 Process 'cloud_controller_worker_local_2' not monitored - start pending
 24747 Process 'nginx_cc'                  not monitored - start pending
 24748 Process 'cloud_controller_clock'    not monitored - start pending
 24749 Process 'process-watcher'           not monitored - start pending
 24750 Process 'process-destroyer'         initializing - start pending
 24751 Process 'cf-redis-broker'           not monitored - start pending
 24752 Process 'broker-nginx'              not monitored - start pending
 24753 Process 'cf-mysql-broker'           not monitored - start pending
 24754 Process 'quota-enforcer'            not monitored - start pending
 24755 Process 'cc_uploader'               not monitored - start pending
 24756 Process 'blobstore_nginx'           not monitored - start pending
 24757 Process 'blobstore_url_signer'      not monitored - start pending
 24758 Process 'bbs'                       running
 24759 Process 'auctioneer'                not monitored - start pending
 24760 System 'system_localhost'           not monitored - start pending = *\e\r\r\o\r\ \c\o\n\n\e\c\t\i\n\g\ \t\o\ \t\h\e\ \m\o\n\i\t\ \d\a\e\m\o\n* ]]
 24761 ++ echo 'The Monit daemon 5.2.5 uptime: 2m
…
74827 Process '\''pcfdev-api'\''                running
 74828 Process '\''pcfdev-nginx'\''              running
 74829 Process '\''vxlan-policy-agent'\''        Does not exist
 74830 Process '\''uaa'\''                       running
 74831 Process '\''tps_listener'\''              running
 74832 Process '\''tps_watcher'\''               running
 74833 Process '\''tcp_router'\''                running
 74834 Process '\''tcp_emitter'\''               running
 74835 Process '\''syslog_drain_binder'\''       Execution failed
 74836 Process '\''syslog-configurator'\''       running
 74837 Process '\''stager'\''                    running
 74838 Process '\''ssh_proxy'\''                 running
 74839 Process '\''silk-daemon'\''               not monitored
 74840 Process '\''silk-controller'\''           initializing
 74841 Process '\''routing-api'\''               initializing
 74842 Process '\''route_registrar'\''           initializing
 74843 Process '\''route_emitter'\''             initializing
 74844 Process '\''rep'\''                       initializing
 74845 Process '\''rabbitmq-server'\''           initializing
 74846 Process '\''rabbitmq-broker'\''           initializing
 74847 Process '\''policy-server'\''             initializing
 74848 Process '\''nsync_listener'\''            initializing
 74849 Process '\''nsync_bulker'\''              initializing
 74850 Process '\''netmon'\''                    initializing
 74851 Process '\''nats'\''                      initializing
 74852 Process '\''mariadb_ctrl'\''              running
 74853 Process '\''galera-healthcheck'\''        running
 74854 Process '\''gra-log-purger-executable'\'' initializing
 74855 Process '\''cluster_health_logger'\''     initializing
 74856 Process '\''metron_agent'\''              initializing
 74857 Process '\''loggregator_trafficcontroller'\'' initializing
 74858 Process '\''localdriver'\''               initializing
 74859 Process '\''localbroker'\''               initializing
 74860 Process '\''gorouter'\''                  initializing
 74861 Process '\''garden'\''                    running
 74862 Process '\''file_server'\''               initializing
 74863 Process '\''etcd'\''                      running
 74864 Process '\''etcd_consistency_checker'\''  initializing
 74865 Process '\''doppler'\''                   initializing
 74866 Process '\''consul_agent'\''              running
 74867 Process '\''cloud_controller_worker_1'\'' initializing
 74868 Process '\''cloud_controller_ng'\''       initializing
 74869 Process '\''cloud_controller_worker_local_1'\'' initializing
 74870 Process '\''cloud_controller_worker_local_2'\'' initializing
 74871 Process '\''nginx_cc'\''                  initializing
 74872 Process '\''cloud_controller_clock'\''    initializing
 74873 Process '\''process-watcher'\''           initializing
 74874 Process '\''process-destroyer'\''         initializing
 74875 Process '\''cf-redis-broker'\''           initializing
 74876 Process '\''broker-nginx'\''              initializing
 74877 Process '\''cf-mysql-broker'\''           initializing
 74878 Process '\''quota-enforcer'\''            initializing
 74879 Process '\''cc_uploader'\''               initializing
 74880 Process '\''blobstore_nginx'\''           initializing
 74881 Process '\''blobstore_url_signer'\''      initializing
 74882 Process '\''bbs'\''                       running
 74883 Process '\''auctioneer'\''                initializing
 74884 System '\''system_localhost'\''           initializing'
 74885 ++ [[ The Monit daemon 5.2.5 uptime: 7m
…
90848 Process '\''pcfdev-api'\''                running
 90849 Process '\''pcfdev-nginx'\''              running
 90850 Process '\''vxlan-policy-agent'\''        running
 90851 Process '\''uaa'\''                       running
 90852 Process '\''tps_listener'\''              running
 90853 Process '\''tps_watcher'\''               running
 90854 Process '\''tcp_router'\''                running
 90855 Process '\''tcp_emitter'\''               running
 90856 Process '\''syslog_drain_binder'\''       not monitored
 90857 Process '\''syslog-configurator'\''       running
 90858 Process '\''stager'\''                    running
 90859 Process '\''ssh_proxy'\''                 running
 90860 Process '\''silk-daemon'\''               Does not exist
 90861 Process '\''silk-controller'\''           running
 90862 Process '\''routing-api'\''               running
 90863 Process '\''route_registrar'\''           Does not exist
 90864 Process '\''route_emitter'\''             Does not exist
 90865 Process '\''rep'\''                       Does not exist
 90866 Process '\''rabbitmq-server'\''           running
 90867 Process '\''rabbitmq-broker'\''           running
 90868 Process '\''policy-server'\''             running
 90869 Process '\''nsync_listener'\''            running
 90870 Process '\''nsync_bulker'\''              running
 90871 Process '\''netmon'\''                    running
 90872 Process '\''nats'\''                      running
 90873 Process '\''mariadb_ctrl'\''              running
 90874 Process '\''galera-healthcheck'\''        running
 90875 Process '\''gra-log-purger-executable'\'' running
 90876 Process '\''cluster_health_logger'\''     running
 90877 Process '\''metron_agent'\''              running
 90878 Process '\''loggregator_trafficcontroller'\'' running
 90879 Process '\''localdriver'\''               running
 90880 Process '\''localbroker'\''               running
 90881 Process '\''gorouter'\''                  running
 90882 Process '\''garden'\''                    running
 90883 Process '\''file_server'\''               running
 90884 Process '\''etcd'\''                      running
 90885 Process '\''etcd_consistency_checker'\''  running
 90886 Process '\''doppler'\''                   running
 90887 Process '\''consul_agent'\''              running
 90888 Process '\''cloud_controller_worker_1'\'' Does not exist
 90889 Process '\''cloud_controller_ng'\''       Does not exist
 90890 Process '\''cloud_controller_worker_local_1'\'' Does not exist
 90891 Process '\''cloud_controller_worker_local_2'\'' Does not exist
 90892 Process '\''nginx_cc'\''                  initializing
 90893 Process '\''cloud_controller_clock'\''    running
 90894 Process '\''process-watcher'\''           running
 90895 Process '\''process-destroyer'\''         running
 90896 Process '\''cf-redis-broker'\''           running
 90897 Process '\''broker-nginx'\''              running
 90898 Process '\''cf-mysql-broker'\''           Execution failed
 90899 Process '\''quota-enforcer'\''            initializing
 90900 Process '\''cc_uploader'\''               running
 90901 Process '\''blobstore_nginx'\''           running
 90902 Process '\''blobstore_url_signer'\''      running
 90903 Process '\''bbs'\''                       running
 90904 Process '\''auctioneer'\''                running
90905 System '\''system_localhost'\''           running'
 90906 ++ [[ The Monit daemon 5.2.5 uptime: 8m
…
672913 Process '\''pcfdev-api'\''                running
672914 Process '\''pcfdev-nginx'\''              running
672915 Process '\''vxlan-policy-agent'\''        running
672916 Process '\''uaa'\''                       running
672917 Process '\''tps_listener'\''              running
672918 Process '\''tps_watcher'\''               running
672919 Process '\''tcp_router'\''                running
672920 Process '\''tcp_emitter'\''               running
672921 Process '\''syslog_drain_binder'\''       not monitored
672922 Process '\''syslog-configurator'\''       running
672923 Process '\''stager'\''                    running
672924 Process '\''ssh_proxy'\''                 running
672925 Process '\''silk-daemon'\''               running
672926 Process '\''silk-controller'\''           running
672927 Process '\''routing-api'\''               running
672928 Process '\''route_registrar'\''           running
672929 Process '\''route_emitter'\''             running
672930 Process '\''rep'\''                       running
672931 Process '\''rabbitmq-server'\''           running
672932 Process '\''rabbitmq-broker'\''           running
672933 Process '\''policy-server'\''             running
672934 Process '\''nsync_listener'\''            running
672935 Process '\''nsync_bulker'\''              running
672936 Process '\''netmon'\''                    running
672937 Process '\''nats'\''                      running
672938 Process '\''mariadb_ctrl'\''              running
672939 Process '\''galera-healthcheck'\''        running
672940 Process '\''gra-log-purger-executable'\'' running
672941 Process '\''cluster_health_logger'\''     running
672942 Process '\''metron_agent'\''              running
672943 Process '\''loggregator_trafficcontroller'\'' running
672944 Process '\''localdriver'\''               running
672945 Process '\''localbroker'\''               running
672946 Process '\''gorouter'\''                  running
672947 Process '\''garden'\''                    running
672948 Process '\''file_server'\''               running
672949 Process '\''etcd'\''                      running
672950 Process '\''etcd_consistency_checker'\''  running
672951 Process '\''doppler'\''                   running
672952 Process '\''consul_agent'\''              running
672953 Process '\''cloud_controller_worker_1'\'' running
672954 Process '\''cloud_controller_ng'\''       running
672955 Process '\''cloud_controller_worker_local_1'\'' running
672956 Process '\''cloud_controller_worker_local_2'\'' running
672957 Process '\''nginx_cc'\''                  running
672958 Process '\''cloud_controller_clock'\''    running
672959 Process '\''process-watcher'\''           running
672960 Process '\''process-destroyer'\''         running
672961 Process '\''cf-redis-broker'\''           running
672962 Process '\''broker-nginx'\''              running
672963 Process '\''cf-mysql-broker'\''           running
672964 Process '\''quota-enforcer'\''            running
672965 Process '\''cc_uploader'\''               running
672966 Process '\''blobstore_nginx'\''           running
672967 Process '\''blobstore_url_signer'\''      running
672968 Process '\''bbs'\''                       running
672969 Process '\''auctioneer'\''                running
672970 System '\''system_localhost'\''           running'
672971 + started=57
672972 + [[ 57 -lt 58 ]]
672973 + counter=3392
672974 + [[ 32 = 0 ]]
672975 + sleep 1

/var/vcap/monit/monit.log

[UTC Feb 19 08:00:33] info     : start service 'syslog_drain_binder' on user request
[UTC Feb 19 08:00:33] info     : monit daemon at 4562 awakened
…
[UTC Feb 19 08:01:06] info     : 'syslog_drain_binder' start: /var/vcap/jobs/syslog_drain_binder/bin/syslog_drain_binder_ctl
[UTC Feb 19 08:01:06] info     : 'syslog_drain_binder' start action done
…
[UTC Feb 19 08:06:53] error    : 'syslog_drain_binder' process is not running
[UTC Feb 19 08:06:53] info     : 'syslog_drain_binder' trying to restart
[UTC Feb 19 08:06:53] info     : 'syslog_drain_binder' start: /var/vcap/jobs/syslog_drain_binder/bin/syslog_drain_binder_ctl
[UTC Feb 19 08:07:23] error    : 'syslog_drain_binder' failed to start
…
UTC Feb 19 10:55:46] error    : 'syslog_drain_binder' process is not running
[UTC Feb 19 10:55:46] info     : 'syslog_drain_binder' trying to restart
[UTC Feb 19 10:55:46] info     : 'syslog_drain_binder' start: /var/vcap/jobs/syslog_drain_binder/bin/syslog_drain_binder_ctl
[UTC Feb 19 10:56:16] error    : 'syslog_drain_binder' failed to start

var/vcap/sys/log/syslog_drain_binder/syslog_drain_binder.log

2018/02/19 08:01:07 Starting pprof server on: 127.0.0.1:39516
panic: x509: certificate has expired or is not yet valid

goroutine 1 [running]:
panic(0xa34b80, 0xc4201c8190)
        /var/vcap/data/packages/golang1.7/c5de560ab1578122cd22032249fb7f1f287768d4/src/runtime/panic.go:500 +0x1a1
main.main()
        /var/vcap/data/compile/syslog_drain_binder/loggregator/src/syslog_drain_binder/main.go:55 +0xbd5
2018/02/19 08:04:59 Starting pprof server on: 127.0.0.1:43004
panic: x509: certificate has expired or is not yet valid

vcap@agent-id-pcfdev-0:/var/vcap/jobs/syslog_drain_binder/config/certs$ ls
etcd-ca.crt  etcd-client.crt  etcd-client.key  mutual_tls_ca.crt  syslogdrainbinder.crt  syslogdrainbinder.key

vcap@agent-id-pcfdev-0:/var/vcap/jobs/syslog_drain_binder/config/certs$  openssl x509 -in syslogdrainbinder.crt -text -noout
Certificate:
    Data:
        Version: 3 (0x2)
        Serial Number: 16412547589211907925 (0xe3c51513322b6755)
    Signature Algorithm: sha1WithRSAEncryption
        Issuer: CN=*.service.cf.internal, C=US, ST=New-York, L=New York, O=Pivotal, OU=PCF Dev/[email protected]
        Validity
            Not Before: Feb 15 22:35:39 2017 GMT
            Not After : Feb 15 22:35:39 2018 GMT
        Subject: CN=*.service.cf.internal, C=US, ST=New-York, L=New York, O=Pivotal, OU=PCF Dev/[email protected]
        Subject Public Key Info:
            Public Key Algorithm: rsaEncryption
                Public-Key: (2048 bit)
                Modulus:
                    00:c3:8f:42:50:89:9e:27:64:f1:72:c3:d1:3c:ac:
                    19:44:52:27:7e:41:04:26:8a:3c:65:0b:54:45:a4:
                    94:ee:67:cc:fe:bc:27:6d:67:63:fd:68:50:47:67:
                    03:57:79:70:98:76:ed:4d:83:ea:06:7a:3c:43:7b:
                    46:c6:53:9a:9c:a0:14:e4:10:6b:16:dc:f0:82:b1:
                    f3:a6:9c:90:8e:87:0a:ad:d6:c2:20:c0:f7:62:09:
                    30:cb:de:74:fa:c6:59:43:68:1b:a8:7f:a8:0c:22:
                    44:2a:37:4d:d5:7a:d7:37:f2:d2:6a:81:77:16:b5:
                    5f:46:a5:81:44:0e:64:25:07:93:a4:7e:0d:16:c2:
                    4e:15:d0:c9:95:bb:30:dc:9f:9c:d6:f5:b9:bc:34:
                    dd:e1:e9:79:24:f1:32:f6:26:d2:4f:fe:11:b6:2d:
                    85:e6:35:87:f3:09:92:58:9d:10:4c:13:c3:9c:a0:
                    c3:c2:9c:c6:8c:1c:08:58:dd:26:36:aa:56:03:e1:
                    35:90:8d:4e:e0:3a:19:4a:c8:40:9f:61:07:f2:87:
                    a4:79:a6:89:e8:1e:de:97:aa:e5:14:19:83:f1:1f:
                    a0:35:2d:45:b5:5d:e5:5d:73:ee:df:b6:3b:e2:20:
                    05:31:0a:05:8e:72:ce:be:12:47:12:bd:b5:d1:c4:
                    9f:e3
                Exponent: 65537 (0x10001)
        X509v3 extensions:
            X509v3 Subject Key Identifier:
                51:52:F9:01:4D:9F:A3:7F:46:A8:F3:95:6E:AC:D3:10:BF:64:09:75
            X509v3 Authority Key Identifier:
                keyid:51:52:F9:01:4D:9F:A3:7F:46:A8:F3:95:6E:AC:D3:10:BF:64:09:75
                DirName:/CN=*.service.cf.internal/C=US/ST=New-York/L=New York/O=Pivotal/OU=PCF Dev/[email protected]
                serial:E3:C5:15:13:32:2B:67:55

            X509v3 Basic Constraints:
                CA:TRUE
    Signature Algorithm: sha1WithRSAEncryption
         64:d7:d2:77:c9:f3:1b:d0:31:02:fc:10:43:94:75:32:1a:fb:
         ec:2e:bd:0f:55:b6:46:b5:84:fb:ab:11:e4:a8:e4:01:17:3d:
         64:ab:ae:5a:78:db:93:f0:3d:06:48:cc:ba:81:f1:7a:e1:c4:
         4f:a7:70:3b:6b:c3:5f:79:8b:12:a3:29:ee:7c:c1:cc:68:c2:
         84:ce:56:23:4b:23:46:c0:37:31:c9:1c:2f:79:0e:f0:e1:07:
         97:f4:49:d1:08:17:ff:25:07:42:f5:b2:08:b3:d2:28:24:08:
         0d:1e:11:19:1e:7c:dd:9e:de:fa:35:7d:61:27:ec:3c:49:54:
         e0:8b:9c:dd:42:49:eb:bf:ec:2b:a0:a6:d2:b4:ac:b6:47:9a:
         b1:9d:6d:5b:3e:0b:7a:02:d3:28:13:73:3f:65:48:fe:0c:d4:
         2f:53:7c:04:71:36:ac:5a:ec:6f:0d:43:a1:65:fa:0e:33:44:
         5d:53:1a:47:29:0a:7e:e8:f3:ee:80:4e:7d:8b:fc:60:fd:59:
         b9:dc:5a:c0:43:af:b8:4e:7e:b0:e6:38:ed:58:1b:33:1f:c3:
         b1:16:4c:83:fa:62:a1:2a:c8:7f:0e:47:d5:91:7b:e7:6e:71:
         d1:99:a1:2c:40:16:e7:5a:48:72:80:3c:2c:dd:2d:58:4f:cf:
         ef:4d:90:70
vcap@agent-id-pcfdev-0:/var/vcap/jobs/syslog_drain_binder/config/certs$

@menza12
Copy link

menza12 commented Feb 19, 2018 •
edited
Loading

Ah, great analysis of the problem. So best solution IMHO is to create a new VM including a new certificate, run cf dev destroy and then start over.

@aibondarenko
Copy link

aibondarenko commented Feb 19, 2018 •
edited
Loading

Hi there,
i'm trying to run cf dev start on my Ubuntu 16.04 LTS with 15,6 GiB RAM and Intel® Core™ i7-7700 CPU @ 3.60GHz × 8,
i'm also get the:

"...
Provisioning VM...
Waiting for services to start...
Timed out after 3600 seconds.
FAILED
Error: failed to provision VM: Process exited with: 1. Reason was: ()."

in my /var/vcap/monit/monit.log i have:
[UTC Feb 19 11:37:42] error : 'galera-healthcheck' process is not running
[UTC Feb 19 11:37:42] info : 'galera-healthcheck' trying to restart
[UTC Feb 19 11:37:42] info : 'galera-healthcheck' start: /var/vcap/jobs/mysql/bin/galera-healthcheck_ctl
[UTC Feb 19 11:38:42] error : 'galera-healthcheck' failed to start
[UTC Feb 19 11:38:52] error : 'galera-healthcheck' process is not running
[UTC Feb 19 11:38:52] info : 'galera-healthcheck' trying to restart
[UTC Feb 19 11:38:52] info : 'galera-healthcheck' start: /var/vcap/jobs/mysql/bin/galera-healthcheck_ctl
[UTC Feb 19 11:39:52] error : 'galera-healthcheck' failed to start

and folder /var/vcap/sys/log/syslog_drain_binder is empty.

pcfdev-debug.tar.gz

@firasag
Copy link

firasag commented Feb 19, 2018

@sclevine Can you look at this please?
Thanks.

@sclevine
Copy link
Contributor

We are very aware of this issue. I will provide an update here after the holiday weekend, once I have a chance to chat with the team.

@menza12
Copy link

menza12 commented Feb 19, 2018

holiday?

@Marcel2267
Copy link

Marcel2267 commented Feb 19, 2018 •
edited
Loading

Having the same problem here on a Windows 10 machine.

It starts the services and repeats in the end "57 out of 58 running" until it times out.

In the past it was enough to destroy the old VM and create a new one to fix the problem temporarily. This doesn't work anymore.

Computer was not changed, no windows updates. I updated from PCF dev 27 to version 28, still the same result.

I would be really thankfull for every help/fix because I'm reliant at PCF dev at the moment and really need to get it working again.

Update: Downgraded to version 24. Now it runs. But would be really nice to have some help/fixes to use the actual version again :).

@sclevine
Copy link
Contributor

@menza12 https://en.wikipedia.org/wiki/Presidents_Day

@Marcel2267 We're hoping to cut a patch release that fixes this issue and release the first alpha of the rewrite (with a functional BOSH director + native hypervisor support!) this week.

@infamousjoeg
Copy link

cf dev destroy

@izgeri
Copy link

izgeri commented Feb 20, 2018

@sclevine can you post here with an update on when this is expected to be resolved? PCF Dev is pretty handy, and the alternatives are not as easy to use. Thanks :)

@ssisil
Copy link
Contributor

ssisil commented Feb 20, 2018

@izgeri - we are currently working on the patch. @sclevine or I will provide an update here and in the readme when the patch is available. Thanks for bearing with us!

@ssisil
Copy link
Contributor

ssisil commented Feb 22, 2018

Fixed in v0.29

@ssisil ssisil closed this as completed Feb 22, 2018
@aibondarenko
Copy link

aibondarenko commented Feb 22, 2018 •
edited
Loading

Issue still persists when deploying v0.29

$ ./pcfdev-v0.29.0+PCF1.11.0-linux
Plugin successfully upgraded. Current version: 0.29.0. For more info run: cf dev help

$ cf dev start
Downloading VM...
Progress: |====================>| 100%
VM downloaded.
Allocating 4096 MB out of 15924 MB total system memory (14943 MB free).
Importing VM...
Starting VM...
Provisioning VM...
Waiting for services to start...

looking into /var/vcap/monit/monit.log:
[UTC Feb 22 11:35:41] error : monit: no status available -- the monit daemon is not running [UTC Feb 22 11:35:42] error : monit: no status available -- the monit daemon is not running [UTC Feb 22 11:35:43] error : monit: no status available -- the monit daemon is not running [UTC Feb 22 08:35:45] error : monit: no status available -- the monit daemon is not running [UTC Feb 22 08:35:46] error : monit: no status available -- the monit daemon is not running [UTC Feb 22 08:35:47] error : monit: no status available -- the monit daemon is not running [UTC Feb 22 08:35:48] error : monit: no status available -- the monit daemon is not running [UTC Feb 22 08:35:49] info : Starting monit daemon with http interface at [127.0.0.1:2822] [UTC Feb 22 08:35:49] info : Starting monit HTTP server at [127.0.0.1:2822] [UTC Feb 22 08:35:49] info : monit HTTP server started [UTC Feb 22 08:35:49] info : 'system_localhost' Monit started [UTC Feb 22 08:36:12] info : start service 'mariadb_ctrl' on user request [UTC Feb 22 08:36:12] info : monit daemon at 4528 awakened [UTC Feb 22 08:36:12] info : Awakened by User defined signal 1 [UTC Feb 22 08:36:12] info : 'mariadb_ctrl' start: /var/vcap/jobs/mysql/bin/mariadb_ctl [UTC Feb 22 08:36:12] info : start service 'galera-healthcheck' on user request [UTC Feb 22 08:36:12] info : monit daemon at 4528 awakened [UTC Feb 22 08:36:23] info : 'mariadb_ctrl' start action done [UTC Feb 22 08:36:23] info : 'galera-healthcheck' start: /var/vcap/jobs/mysql/bin/galera-healthcheck_ctl [UTC Feb 22 08:37:23] error : 'galera-healthcheck' failed to start [UTC Feb 22 08:37:23] info : 'galera-healthcheck' start action done [UTC Feb 22 08:37:23] info : Awakened by User defined signal 1 [UTC Feb 22 08:37:23] error : 'galera-healthcheck' process is not running [UTC Feb 22 08:37:23] info : 'galera-healthcheck' trying to restart [UTC Feb 22 08:37:23] info : 'galera-healthcheck' start: /var/vcap/jobs/mysql/bin/galera-healthcheck_ctl [UTC Feb 22 08:38:23] error : 'galera-healthcheck' failed to start [UTC Feb 22 08:38:33] error : 'galera-healthcheck' process is not running [UTC Feb 22 08:38:33] info : 'galera-healthcheck' trying to restart [UTC Feb 22 08:38:33] info : 'galera-healthcheck' start: /var/vcap/jobs/mysql/bin/galera-healthcheck_ctl [UTC Feb 22 08:39:33] error : 'galera-healthcheck' failed to start [UTC Feb 22 08:39:43] error : 'galera-healthcheck' process is not running [UTC Feb 22 08:39:43] info : 'galera-healthcheck' trying to restart [UTC Feb 22 08:39:43] info : 'galera-healthcheck' start: /var/vcap/jobs/mysql/bin/galera-healthcheck_ctl [UTC Feb 22 08:40:43] error : 'galera-healthcheck' failed to start [UTC Feb 22 08:40:53] error : 'galera-healthcheck' process is not running [UTC Feb 22 08:40:53] info : 'galera-healthcheck' trying to restart [UTC Feb 22 08:40:53] info : 'galera-healthcheck' start: /var/vcap/jobs/mysql/bin/galera-healthcheck_ctl [UTC Feb 22 08:41:53] error : 'galera-healthcheck' failed to start [UTC Feb 22 08:42:03] error : 'galera-healthcheck' process is not running [UTC Feb 22 08:42:03] info : 'galera-healthcheck' trying to restart [UTC Feb 22 08:42:03] info : 'galera-healthcheck' start: /var/vcap/jobs/mysql/bin/galera-healthcheck_ctl [UTC Feb 22 08:43:03] error : 'galera-healthcheck' failed to start [UTC Feb 22 08:43:13] error : 'galera-healthcheck' process is not running [UTC Feb 22 08:43:13] info : 'galera-healthcheck' trying to restart [UTC Feb 22 08:43:13] info : 'galera-healthcheck' start: /var/vcap/jobs/mysql/bin/galera-healthcheck_ctl

also linked result of cf dev debug call:
pcfdev-debug.tar.gz

@ssisil, @sclevine please, take a look at the logs..

@ekcasey
Copy link
Contributor

ekcasey commented Feb 22, 2018

@aibondarenko

It looks like your galera-healthcheck process failed to start. We haven't seen this issue with v0.29 yet. Would you mind cf dev sshing into the vm and looking at /var/vcap/sys/log/galera-healthcheck/galera-healthcheck.stderr.log and /var/vcap/sys/log/galera-healthcheck/galera-healthcheck.stdout.log. These logs will help us debug the issue.

Also, is this error consistent every time you cf dev start?

@aibondarenko
Copy link

aibondarenko commented Feb 22, 2018 •
edited
Loading

Also, is this error consistent every time you cf dev start?

Yes, i've tried a couple of times.

These logs will help us debug the issue.

I think i can get logs only after holidays, on monday..

@akoranne
Copy link

Thank you for the new version. I was able to get it working.
Love the speed on cf push. It still took a long time to start.
But deploying an app goes really fast. Love it!

@aibondarenko
Copy link

aibondarenko commented Feb 26, 2018 •
edited
Loading

$ cat /var/vcap/sys/log/galera-healthcheck/galera-healthcheck.stdout.log

{"timestamp":"1519629333.416443825","source":"Galera Healthcheck","message":"Galera Healthcheck.Opened DB connection","log_level":1,"data":{"dbHost":"0.0.0.0","dbPort":3306,"dbUser":"galera-healthcheck"}} {"timestamp":"1519629333.416599989","source":"Galera Healthcheck","message":"Galera Healthcheck.Serving healthcheck endpoint","log_level":1,"data":{"url":"http://0.0.0.0:9200/"}} {"timestamp":"1519629333.416669369","source":"Galera Healthcheck","message":"Galera Healthcheck.Attempting to GET endpoint...","log_level":1,"data":{"url":"http://0.0.0.0:9200/"}} {"timestamp":"1519629333.420529366","source":"Galera Healthcheck","message":"Galera Healthcheck.GET endpoint failed, retrying...","log_level":1,"data":{"err":{"Op":"Get","URL":"http://0.0.0.0:9200/","Err":{}},"url":"http://0.0.0.0:9200/"}} {"timestamp":"1519629343.422592878","source":"Galera Healthcheck","message":"Galera Healthcheck.GET endpoint failed, retrying...","log_level":1,"data":{"err":{"Op":"Get","URL":"http://0.0.0.0:9200/","Err":{}},"url":"http://0.0.0.0:9200/"}} {"timestamp":"1519629353.495323420","source":"Galera Healthcheck","message":"Galera Healthcheck.GET endpoint failed, retrying...","log_level":1,"data":{"err":{"Op":"Get","URL":"http://0.0.0.0:9200/","Err":{}},"url":"http://0.0.0.0:9200/"}} {"timestamp":"1519629363.500431061","source":"Galera Healthcheck","message":"Galera Healthcheck.Initialization failed: Coudn't GET endpoint","log_level":3,"data":{"error":"Get http://0.0.0.0:9200/: http: error connecting to proxy http://192.168.11.1:3128: dial tcp 192.168.11.1:3128: getsockopt: connection refused","retries":0,"trace":"goroutine 6 [running]:\ngithub.com/cloudfoundry-incubator/galera-healthcheck/vendor/code.cloudfoundry.org/lager.(*logger).Fatal(0xc420016300, 0x78d407, 0x2b, 0x9038e0, 0xc42017a300, 0xc4201ca018, 0x1, 0x1)\n\t/var/vcap/packages/galera-healthcheck/src/github.com/cloudfoundry-incubator/galera-healthcheck/vendor/code.cloudfoundry.org/lager/logger.go:131 +0xc7\nmain.main.func1(0x909c20, 0xc420016300, 0xc4200cdc40, 0x14, 0xc420011720, 0xc420094f00)\n\t/var/vcap/packages/galera-healthcheck/src/github.com/cloudfoundry-incubator/galera-healthcheck/main.go:112 +0x100e\ncreated by main.main\n\t/var/vcap/packages/galera-healthcheck/src/github.com/cloudfoundry-incubator/galera-healthcheck/main.go:141 +0xe20\n","url":"http://0.0.0.0:9200/"}} {"timestamp":"1519629403.844105959","source":"Galera Healthcheck","message":"Galera Healthcheck.Opened DB connection","log_level":1,"data":{"dbHost":"0.0.0.0","dbPort":3306,"dbUser":"galera-healthcheck"}} {"timestamp":"1519629403.844160795","source":"Galera Healthcheck","message":"Galera Healthcheck.Serving healthcheck endpoint","log_level":1,"data":{"url":"http://0.0.0.0:9200/"}} {"timestamp":"1519629403.844226837","source":"Galera Healthcheck","message":"Galera Healthcheck.Attempting to GET endpoint...","log_level":1,"data":{"url":"http://0.0.0.0:9200/"}} {"timestamp":"1519629403.844918966","source":"Galera Healthcheck","message":"Galera Healthcheck.GET endpoint failed, retrying...","log_level":1,"data":{"err":{"Op":"Get","URL":"http://0.0.0.0:9200/","Err":{}},"url":"http://0.0.0.0:9200/"}} {"timestamp":"1519629413.851252794","source":"Galera Healthcheck","message":"Galera Healthcheck.GET endpoint failed, retrying...","log_level":1,"data":{"err":{"Op":"Get","URL":"http://0.0.0.0:9200/","Err":{}},"url":"http://0.0.0.0:9200/"}} {"timestamp":"1519629423.861242056","source":"Galera Healthcheck","message":"Galera Healthcheck.GET endpoint failed, retrying...","log_level":1,"data":{"err":{"Op":"Get","URL":"http://0.0.0.0:9200/","Err":{}},"url":"http://0.0.0.0:9200/"}} {"timestamp":"1519629433.861534357","source":"Galera Healthcheck","message":"Galera Healthcheck.Initialization failed: Coudn't GET endpoint","log_level":3,"data":{"error":"Get http://0.0.0.0:9200/: http: error connecting to proxy http://192.168.11.1:3128: dial tcp 192.168.11.1:3128: getsockopt: connection refused","retries":0,"trace":"goroutine 6 [running]:\ngithub.com/cloudfoundry-incubator/galera-healthcheck/vendor/code.cloudfoundry.org/lager.(*logger).Fatal(0xc420016300, 0x78d407, 0x2b, 0x9038e0, 0xc420164d20, 0xc4201a8000, 0x1, 0x1)\n\t/var/vcap/packages/galera-healthcheck/src/github.com/cloudfoundry-incubator/galera-healthcheck/vendor/code.cloudfoundry.org/lager/logger.go:131 +0xc7\nmain.main.func1(0x909c20, 0xc420016300, 0xc4200cdc20, 0x14, 0xc4200116f0, 0xc420094f00)\n\t/var/vcap/packages/galera-healthcheck/src/github.com/cloudfoundry-incubator/galera-healthcheck/main.go:112 +0x100e\ncreated by main.main\n\t/var/vcap/packages/galera-healthcheck/src/github.com/cloudfoundry-incubator/galera-healthcheck/main.go:141 +0xe20\n","url":"http://0.0.0.0:9200/"}} {"timestamp":"1519629473.284442663","source":"Galera Healthcheck","message":"Galera Healthcheck.Opened DB connection","log_level":1,"data":{"dbHost":"0.0.0.0","dbPort":3306,"dbUser":"galera-healthcheck"}} {"timestamp":"1519629473.284554958","source":"Galera Healthcheck","message":"Galera Healthcheck.Serving healthcheck endpoint","log_level":1,"data":{"url":"http://0.0.0.0:9200/"}} {"timestamp":"1519629473.284676313","source":"Galera Healthcheck","message":"Galera Healthcheck.Attempting to GET endpoint...","log_level":1,"data":{"url":"http://0.0.0.0:9200/"}} {"timestamp":"1519629473.288128853","source":"Galera Healthcheck","message":"Galera Healthcheck.GET endpoint failed, retrying...","log_level":1,"data":{"err":{"Op":"Get","URL":"http://0.0.0.0:9200/","Err":{}},"url":"http://0.0.0.0:9200/"}} {"timestamp":"1519629483.290256739","source":"Galera Healthcheck","message":"Galera Healthcheck.GET endpoint failed, retrying...","log_level":1,"data":{"err":{"Op":"Get","URL":"http://0.0.0.0:9200/","Err":{}},"url":"http://0.0.0.0:9200/"}} {"timestamp":"1519629493.292359591","source":"Galera Healthcheck","message":"Galera Healthcheck.GET endpoint failed, retrying...","log_level":1,"data":{"err":{"Op":"Get","URL":"http://0.0.0.0:9200/","Err":{}},"url":"http://0.0.0.0:9200/"}} {"timestamp":"1519629503.292645454","source":"Galera Healthcheck","message":"Galera Healthcheck.Initialization failed: Coudn't GET endpoint","log_level":3,"data":{"error":"Get http://0.0.0.0:9200/: http: error connecting to proxy http://192.168.11.1:3128: dial tcp 192.168.11.1:3128: getsockopt: connection refused","retries":0,"trace":"goroutine 6 [running]:\ngithub.com/cloudfoundry-incubator/galera-healthcheck/vendor/code.cloudfoundry.org/lager.(*logger).Fatal(0xc420016300, 0x78d407, 0x2b, 0x9038e0, 0xc420186300, 0xc42002a180, 0x1, 0x1)\n\t/var/vcap/packages/galera-healthcheck/src/github.com/cloudfoundry-incubator/galera-healthcheck/vendor/code.cloudfoundry.org/lager/logger.go:131 +0xc7\nmain.main.func1(0x909c20, 0xc420016300, 0xc4200cdc60, 0x14, 0xc420011720, 0xc420094f00)\n\t/var/vcap/packages/galera-healthcheck/src/github.com/cloudfoundry-incubator/galera-healthcheck/main.go:112 +0x100e\ncreated by main.main\n\t/var/vcap/packages/galera-healthcheck/src/github.com/cloudfoundry-incubator/galera-healthcheck/main.go:141 +0xe20\n","url":"http://0.0.0.0:9200/"}}

$ cat /var/vcap/sys/log/galera-healthcheck/galera-healthcheck.stderr.log

panic: Get http://0.0.0.0:9200/: http: error connecting to proxy http://192.168.11.1:3128: dial tcp 192.168.11.1:3128: getsockopt: connection refused

goroutine 6 [running]: panic(0x726660, 0xc42017a300) /var/vcap/data/packages/golang/c9a99ecdee290e15198713da72db3d5d78743f96/src/runtime/panic.go:500 +0x1a1 github.com/cloudfoundry-incubator/galera-healthcheck/vendor/code.cloudfoundry.org/lager.(*logger).Fatal(0xc420016300, 0x78d407, 0x2b, 0x9038e0, 0xc42017a300, 0xc4201ca018, 0x1, 0x1) /var/vcap/packages/galera-healthcheck/src/github.com/cloudfoundry-incubator/galera-healthcheck/vendor/code.cloudfoundry.org/lager/logger.go:152 +0x41c main.main.func1(0x909c20, 0xc420016300, 0xc4200cdc40, 0x14, 0xc420011720, 0xc420094f00) /var/vcap/packages/galera-healthcheck/src/github.com/cloudfoundry-incubator/galera-healthcheck/main.go:112 +0x100e created by main.main /var/vcap/packages/galera-healthcheck/src/github.com/cloudfoundry-incubator/galera-healthcheck/main.go:141 +0xe20 panic: Get http://0.0.0.0:9200/: http: error connecting to proxy http://192.168.11.1:3128: dial tcp 192.168.11.1:3128: getsockopt: connection refused

goroutine 6 [running]: panic(0x726660, 0xc420164d20) /var/vcap/data/packages/golang/c9a99ecdee290e15198713da72db3d5d78743f96/src/runtime/panic.go:500 +0x1a1 github.com/cloudfoundry-incubator/galera-healthcheck/vendor/code.cloudfoundry.org/lager.(*logger).Fatal(0xc420016300, 0x78d407, 0x2b, 0x9038e0, 0xc420164d20, 0xc4201a8000, 0x1, 0x1) /var/vcap/packages/galera-healthcheck/src/github.com/cloudfoundry-incubator/galera-healthcheck/vendor/code.cloudfoundry.org/lager/logger.go:152 +0x41c main.main.func1(0x909c20, 0xc420016300, 0xc4200cdc20, 0x14, 0xc4200116f0, 0xc420094f00) /var/vcap/packages/galera-healthcheck/src/github.com/cloudfoundry-incubator/galera-healthcheck/main.go:112 +0x100e created by main.main /var/vcap/packages/galera-healthcheck/src/github.com/cloudfoundry-incubator/galera-healthcheck/main.go:141 +0xe20

My host machine is proxyed via cntlm, which is sitting on 3128 port.
192.168.11.1 is the address of created vboxnet0 network.
It seems to be some misconfiguration between pcfdev instance and my proxy settings...

@aibondarenko
Copy link

Submitted new issue (#300), since it seems to be proxy-related.

@dgcarlso3 dgcarlso3 mentioned this issue Mar 14, 2018
Closed
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
accepted help wanted
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests