search

cloudfoundry-attic / cfdev

A fast and easy local Cloud Foundry experience on native hypervisors, powered by LinuxKit with VPNKit
Apache License 2.0
227 stars 64 forks source link

cf dev start fails on the Get request for https://10.144.0.2:25555/info (Macos 10.15.3) #126

Closed sfrevel closed 4 years ago

sfrevel commented 4 years ago

I always get the following error on an Mac with Catalina 10.15.3, with 16GB, and an SSD. But on an other MAC (an older one - also Catalina 10.15.3, 16GB, SSD) everything comes up smoothly?

Fetching info:
  Performing request GET 'https://10.144.0.2:25555/info':
    Performing GET request:
      Retry: Get https://10.144.0.2:25555/info: net/http: TLS handshake timeout

Exit code 1

when I try a curl -v I can see that there is a connect to the IP:PORT and Client Handshake is send but then the timeout. Any Ideas? I'm pretty lost right now what could be the difference. 

cf dev version
CLI: 0.0.17
BUILD: 14 (b36c82e)

cf: v11.2.0
cf-mysql: 36.19.0

We also testet a Mac with 32GB there we get the same error

Creating the VM...
Starting VPNKit...
Waiting for the VM...
Deploying the BOSH Director...
Deploying CF...
  Preparing deployment (2m38s)FAILED
cf dev start: Failed to deploy services: Failed to deploy CF: exit status 1

after searching a little more it seems that the bosh login fails with the same error

eval $(cf dev bosh env)

export BOSH_LOG_LEVEL=debug
sfr:~$ bosh login
[File System] 2020/02/27 09:06:16 DEBUG - Expanding path for '~/.bosh/tmp'
[File System] 2020/02/27 09:06:16 DEBUG - Making dir /Users/xxx/.bosh/tmp with perm 0777
[File System] 2020/02/27 09:06:16 DEBUG - Expanding path for '~/.bosh/config'
[File System] 2020/02/27 09:06:16 DEBUG - Checking if file exists /Users/xxx/.bosh/config
[File System] 2020/02/27 09:06:16 DEBUG - Stat '/Users/xxx/.bosh/config'
[File System] 2020/02/27 09:06:16 DEBUG - Expanding path for '~/.bosh/config'
[File System] 2020/02/27 09:06:16 DEBUG - Checking if file exists /Users/xxx/.bosh/config
[File System] 2020/02/27 09:06:16 DEBUG - Stat '/Users/xxx/.bosh/config'
[director.Factory] 2020/02/27 09:06:16 DEBUG - Using custom root CAs
[httpClient] 2020/02/27 09:06:16 DEBUG - Sending GET request to endpoint 'https://10.144.0.2:25555/info'
[attemptRetryStrategy] 2020/02/27 09:06:16 DEBUG - Making attempt #0 for *httpclient.RequestRetryable
[clientRetryable] 2020/02/27 09:06:16 DEBUG - [requestID=d2d9dd0e-6d66-4d7e-4711-fef0c1d5f5d9] Requesting (attempt=1): Request{ Method: 'GET', URL: 'https://10.144.0.2:25555/info' }
[attemptRetryStrategy] 2020/02/27 09:06:46 DEBUG - Making attempt #1 for *httpclient.RequestRetryable
[clientRetryable] 2020/02/27 09:06:46 DEBUG - [requestID=d2d9dd0e-6d66-4d7e-4711-fef0c1d5f5d9] Requesting (attempt=2): Request{ Method: 'GET', URL: 'https://10.144.0.2:25555/info' }
[attemptRetryStrategy] 2020/02/27 09:07:17 DEBUG - Making attempt #2 for *httpclient.RequestRetryable
[clientRetryable] 2020/02/27 09:07:17 DEBUG - [requestID=d2d9dd0e-6d66-4d7e-4711-fef0c1d5f5d9] Requesting (attempt=3): Request{ Method: 'GET', URL: 'https://10.144.0.2:25555/info' }
[attemptRetryStrategy] 2020/02/27 09:07:47 DEBUG - Making attempt #3 for *httpclient.RequestRetryable
[clientRetryable] 2020/02/27 09:07:47 DEBUG - [requestID=d2d9dd0e-6d66-4d7e-4711-fef0c1d5f5d9] Requesting (attempt=4): Request{ Method: 'GET', URL: 'https://10.144.0.2:25555/info' }
[attemptRetryStrategy] 2020/02/27 09:08:18 DEBUG - Making attempt #4 for *httpclient.RequestRetryable
[clientRetryable] 2020/02/27 09:08:18 DEBUG - [requestID=d2d9dd0e-6d66-4d7e-4711-fef0c1d5f5d9] Requesting (attempt=5): Request{ Method: 'GET', URL: 'https://10.144.0.2:25555/info' }
[CLI] 2020/02/27 09:08:48 ERROR - Fetching info: Performing request GET 'https://10.144.0.2:25555/info': Performing GET request: Retry: Get https://10.144.0.2:25555/info: net/http: TLS handshake timeout
Fetching info:
  Performing request GET 'https://10.144.0.2:25555/info':
    Performing GET request:
      Retry: Get https://10.144.0.2:25555/info: net/http: TLS handshake timeout

Exit code 1
cf-gitbot commented 4 years ago

We have created an issue in Pivotal Tracker to manage this:

https://www.pivotaltracker.com/story/show/171487834

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

aemengo commented 4 years ago

Could you please report the last chunk of logs from: ~/.cfdev/log/deploy-bosh.log

sfrevel commented 4 years ago

Hi aemengo, thxs for your response.

^@^@^@^Ascp: protocol error: unexpected <newline>
^@^@^@^Ascp: protocol error: unexpected <newline>
^@^@^@^Ascp: protocol error: unexpected <newline>
Deployment manifest: '/root/director.yml'
Deployment state: 'state.json'

Started validating
  Validating release 'bosh'... Finished (00:00:01)
  Validating release 'bpm'... Finished (00:00:02)
  Validating release 'os-conf'... Finished (00:00:00)
  Validating release 'bosh-runc-cpi'... Finished (00:00:00)
  Validating cpi release... Finished (00:00:00)
  Validating deployment manifest... Finished (00:00:01)
  Validating stemcell... Finished (00:00:08)
Finished validating (00:00:17)

Started installing CPI
  Compiling package 'runc-cpi/14cee2d6256a9def3f8ce1cb00dabc6484aca9cb'... Finished (00:00:02)
  Installing packages... Finished (00:00:00)
  Rendering job templates... Finished (00:00:00)
  Installing job 'runc_cpi'... Finished (00:00:00)
Finished installing CPI (00:00:03)

Starting registry... Finished (00:00:00)
Uploading stemcell 'bosh-warden-boshlite-ubuntu-xenial-go_agent/170.16'... Skipped [Stemcell already uploaded] (00:00:00)

Started deploying
  Deleting VM 'c64e2379-5162-471b-9648-3c46083a509a'... Finished (00:00:12)
  Creating VM for instance 'bosh/0' from stemcell '1bbad575-e59a-4b45-8da5-886ecdb2cb82'... Finished (00:00:05)
  Waiting for the agent on VM '69fcf6a7-8355-4c26-8c2b-eb10256b427a' to be ready... Finished (00:00:04)
  Attaching disk 'fcceadb7-a4ca-4a27-976a-4e339facb4bd' to VM '69fcf6a7-8355-4c26-8c2b-eb10256b427a'... Finished (00:00:03)
  Rendering job templates... Finished (00:00:12)
  Compiling package 'ruby-2.4-r4/0cdc60ed7fdb326e605479e9275346200af30a25'... Skipped [Package already compiled] (00:00:00)
  Compiling package 'mysql/898f50dde093c366a644964ccb308a5281c226de'... Skipped [Package already compiled] (00:00:00)
  Compiling package 'libpq/0d118c5dd7928f8c057de40b5f8f2d7dde48f6c7'... Skipped [Package already compiled] (00:00:00)
  Compiling package 'bpm-runc/c0b41921c5063378870a7c8867c6dc1aa84e7d85'... Skipped [Package already compiled] (00:00:00)
  Compiling package 'golang/27413c6b5a88ea20a24a9eed74d4b090b7b88331'... Skipped [Package already compiled] (00:00:00)
  Compiling package 'director/c10bed194a653255948f31345bcfbfb87c1d1339'... Skipped [Package already compiled] (00:00:00)
  Compiling package 'postgres-9.4/b34d67da70e0295c09e4f4122e312f64e50896eb'... Skipped [Package already compiled] (00:00:00)
  Compiling package 'verify_multidigest/8fc5d654cebad7725c34bb08b3f60b912db7094a'... Skipped [Package already compiled] (00:00:00)
  Compiling package 'bpm/d139b63561eaa3893976416be9668dea539bf17d'... Skipped [Package already compiled] (00:00:00)
  Compiling package 'nginx/5a68865452a3bdcc233867edbbb59c1e18658f6b'... Skipped [Package already compiled] (00:00:00)
  Compiling package 'gonats/73ec55f11c24dd7c02288cdffa24446023678cc2'... Skipped [Package already compiled] (00:00:00)
  Compiling package 'bosh-gcscli/fce60f2d82653ea7e08c768f077c9c4a738d0c39'... Skipped [Package already compiled] (00:00:00)
  Compiling package 'davcli/f8a86e0b88dd22cb03dec04e42bdca86b07f79c3'... Skipped [Package already compiled] (00:00:00)
  Compiling package 's3cli/3097f27cb9356172c9ae52de945821c4e338c87a'... Skipped [Package already compiled] (00:00:00)
  Compiling package 'runc-cpi/14cee2d6256a9def3f8ce1cb00dabc6484aca9cb'... Finished (00:00:03)
  Compiling package 'health_monitor/c5a852ce964ec9a288577ec50f2092c42efe880f'... Skipped [Package already compiled] (00:00:00)
  Updating instance 'bosh/0'... Finished (00:00:15)
  Waiting for instance 'bosh/0' to be running... Finished (00:00:38)
  Running the post-start scripts 'bosh/0'... Finished (00:00:01)
Finished deploying (00:01:41)

Stopping registry... Finished (00:00:00)
Cleaning up rendered CPI jobs... Finished (00:00:00)

Succeeded
sfrevel commented 4 years ago

OK , we found the problem. The IP 10.144.0.2 was not in the exclude rules of the company firewall network traffic filtering.

May this issue will help someone else...

an 

watch -d "lsof -n -i |grep 25555"

will help to see that the connection is established when cf dev start is running.