New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Push may wait forever #260
Comments
We have created an issue in Pivotal Tracker to manage this. You can view the current status of your issue at: https://www.pivotaltracker.com/story/show/78345520. |
With See #200 CC |
We have our timeouts set to the 15 minute default. |
@fraenkel CLI team did an exploratory charter on timeouts. For details talk to @JesseTAlford or me. A summary of the situation is that push does not error out if staging takes more time than allocated in the CF_STAGING_TIMEOUT var. Instead it is assumed that the app is now starting and the timeout "flows over" into the health_check_timeout. As @drich10 points out in https://www.pivotaltracker.com/story/show/83422654, the code shows that this is intentionally written this way so it's not a bug. However, I can see a clear need for an error to be raised at the end of CF_STAGING_TIMEOUT if we are unable to definitively determine that staging is completed. Not raising that error forces you to wait x time where x=(CF_STAGING_TIMEOUT + health_check_timeout) to find out staging failed. New story for throwing error when app staging is not complete before CF_STAGING_TIMEOUT is https://www.pivotaltracker.com/story/show/83802536 Closing this issue, but please reopen if the need arises |
I did a push which never actually timed-out.
I did get a stack dump so you can easily see where the problem is. I think there is a more general issue with the staging/starting time out since they don't cover all the HTTP calls that are being made.
Here is a complete dump, but you can see that many threads have been blocked for more than 16 minutes.
goroutine 0 [idle]:
runtime.mach_semaphore_wait()
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/runtime/sys_darwin_amd64.s:395 +0xb
runtime.semasleep(0xffffffffffffffff)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/runtime/os_darwin.c:415 +0xa1
runtime.notesleep(0x113df90)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/runtime/lock_sema.c:165 +0xd8
stopm()
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/runtime/proc.c:954 +0xe0
exitsyscall0(0xc2085e2120)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/runtime/proc.c:1699 +0xd6
runtime.mcall(0x2c4f7)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/runtime/asm_amd64.s:181 +0x4b
goroutine 16 [select, 20 minutes]:
net/http.(_persistConn).roundTrip(0xc208366580, 0xc2088b2670, 0x0, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/net/http/transport.go:1015 +0x6db
net/http.(_Transport).RoundTrip(0xc20810a200, 0xc208144d00, 0xad, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/net/http/transport.go:208 +0x49a
net/http.send(0xc208144d00, 0x125e180, 0xc20810a200, 0xc208366420, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/net/http/client.go:195 +0x43d
net/http.(_Client).send(0xc20816b350, 0xc208144d00, 0x6b, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/net/http/client.go:118 +0x15b
net/http.(_Client).doFollowingRedirects(0xc20816b350, 0xc208144d00, 0xeb7498, 0x0, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/net/http/client.go:343 +0x97f
net/http.(_Client).Do(0xc20816b350, 0xc208144d00, 0x0, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/net/http/client.go:153 +0x193
github.com/cloudfoundry/cli/cf/net.Gateway.doRequest(0x125f278, 0xc208248af0, 0xeb7160, 0x1, 0x12a05f200, 0x0, 0x0, 0x0, 0x125ef30, 0xc20837a4e0, ...)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/net/gateway.go:397 +0xcb
github.com/cloudfoundry/cli/cf/net.Gateway.doRequestAndHandlerError(0x125f278, 0xc208248af0, 0xeb7160, 0x1, 0x12a05f200, 0x0, 0x0, 0x0, 0x125ef30, 0xc20837a4e0, ...)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/net/gateway.go:376 +0x6d
github.com/cloudfoundry/cli/cf/net.Gateway.doRequestHandlingAuth(0x125f278, 0xc208248af0, 0xeb7160, 0x1, 0x12a05f200, 0x0, 0x0, 0x0, 0x125ef30, 0xc20837a4e0, ...)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/net/gateway.go:347 +0x184
github.com/cloudfoundry/cli/cf/net.Gateway.performRequestForResponseBytes(0x125f278, 0xc208248af0, 0xeb7160, 0x1, 0x12a05f200, 0x0, 0x0, 0x0, 0x125ef30, 0xc20837a4e0, ...)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/net/gateway.go:225 +0xf7
github.com/cloudfoundry/cli/cf/net.Gateway.PerformPollingRequestForJSONResponse(0x125f278, 0xc208248af0, 0xeb7160, 0x1, 0x12a05f200, 0x0, 0x0, 0x0, 0x125ef30, 0xc20837a4e0, ...)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/net/gateway.go:268 +0x2a9
github.com/cloudfoundry/cli/cf/net.Gateway.createUpdateOrDeleteResource(0x125f278, 0xc208248af0, 0xeb7160, 0x1, 0x12a05f200, 0x0, 0x0, 0x0, 0x125ef30, 0xc20837a4e0, ...)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/net/gateway.go:178 +0x26d
github.com/cloudfoundry/cli/cf/net.Gateway.UpdateResource(0x125f278, 0xc208248af0, 0xeb7160, 0x1, 0x12a05f200, 0x0, 0x0, 0x0, 0x125ef30, 0xc20837a4e0, ...)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/net/gateway.go:121 +0xe3
github.com/cloudfoundry/cli/cf/api.CloudControllerApplicationRepository.Update(0x125ef30, 0xc20837a4e0, 0x125f278, 0xc208248af0, 0xeb7160, 0x1, 0x12a05f200, 0x0, 0x0, 0x0, ...)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/api/applications.go:82 +0x449
github.com/cloudfoundry/cli/cf/api.(_CloudControllerApplicationRepository).Update(0xc208110e70, 0xc208101650, 0x24, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
:22 +0x116
github.com/cloudfoundry/cli/cf/commands/application.func·004(0xc208101650, 0x24, 0xc2085e9746, 0x6, 0x0, 0x0, 0x0, 0x0, 0x400, 0xc2081017a0, ...)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/commands/application/start.go:130 +0x601
github.com/cloudfoundry/cli/cf/commands/application.(_Start).ApplicationWatchStaging(0xc208047830, 0xc208101650, 0x24, 0xc2085e9746, 0x6, 0x0, 0x0, 0x0, 0x0, 0x400, ...)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/commands/application/start.go:146 +0x1f1
github.com/cloudfoundry/cli/cf/commands/application.(_Start).ApplicationStart(0xc208047830, 0xc208101650, 0x24, 0xc2085e9746, 0x6, 0x0, 0x0, 0x0, 0x0, 0x400, ...)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/commands/application/start.go:131 +0x255
github.com/cloudfoundry/cli/cf/commands/application.(_Push).restart(0xc2082348c0, 0xc208101650, 0x24, 0xc2085e9746, 0x6, 0x0, 0x0, 0x0, 0x0, 0x400, ...)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/commands/application/push.go:285 +0x1dc
github.com/cloudfoundry/cli/cf/commands/application.(_Push).Run(0xc2082348c0, 0xc2080453f0)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/commands/application/push.go:141 +0xa0a
github.com/cloudfoundry/cli/cf/command_runner.ConcreteRunner.RunCmdByName(0x1262190, 0xc208357650, 0x12621c0, 0xc208032700, 0x60cbd0, 0x4, 0xc2080453f0, 0x0, 0x0)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/command_runner/runner.go:48 +0x4bb
github.com/cloudfoundry/cli/cf/command_runner.(_ConcreteRunner).RunCmdByName(0xc2080b2620, 0x60cbd0, 0x4, 0xc2080453f0, 0x0, 0x0)
:1 +0xc1
github.com/cloudfoundry/cli/cf/app.func·003(0xc2080453f0)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/app/app.go:109 +0x58
github.com/codegangsta/cli.Command.Run(0x60cbd0, 0x4, 0x60c3b0, 0x1, 0xc2080be420, 0x15a, 0xc2081a84c0, 0x31, 0x0, 0x0, ...)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/Godeps/_workspace/src/github.com/codegangsta/cli/command.go:101 +0xc6f
github.com/codegangsta/cli.(_App).Run(0xc20804f080, 0xc20800e000, 0x3, 0x3, 0x0, 0x0)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/Godeps/_workspace/src/github.com/codegangsta/cli/app.go:125 +0x941
main.main()
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/main/main.go:74 +0x500
goroutine 19 [finalizer wait, 20 minutes]:
runtime.park(0x15d60, 0x113ad98, 0x1139849)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/runtime/proc.c:1369 +0x89
runtime.parkunlock(0x113ad98, 0x1139849)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/runtime/proc.c:1385 +0x3b
runfinq()
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/runtime/mgc0.c:2644 +0xcf
runtime.goexit()
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/runtime/proc.c:1445
goroutine 311 [syscall, 23 minutes]:
os/signal.loop()
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/os/signal/signal_unix.go:21 +0x1e
created by os/signal.init·1
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/os/signal/signal_unix.go:27 +0x32
goroutine 1185 [syscall, 23 minutes]:
runtime.goexit()
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/runtime/proc.c:1445
goroutine 1252 [sleep]:
time.Sleep(0xf4240)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/runtime/time.goc:39 +0x31
github.com/cloudfoundry/cli/cf/api.(_LoggregatorLogsRepository).bufferMessages(0xc20810eae0, 0xc20863bec0, 0xc2088d1440)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/api/logs.go:103 +0xb2
github.com/cloudfoundry/cli/cf/api.(_LoggregatorLogsRepository).TailLogsFor(0xc20810eae0, 0xc208101650, 0x24, 0xc2088d1430, 0xc2088d1440, 0x0, 0x0)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/api/logs.go:87 +0x2f7
github.com/cloudfoundry/cli/cf/commands/application.Start.tailStagingLogs(0x125ec88, 0xc208060eb0, 0x125ef30, 0xc20837a4e0, 0x1260f00, 0xc2080bc500, 0x0, 0x0, 0x125fc50, 0xc208110e70, ...)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/commands/application/start.go:190 +0xff
created by github.com/cloudfoundry/cli/cf/commands/application.(*Start).ApplicationWatchStaging
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/commands/application/start.go:139 +0x16c
goroutine 1253 [chan receive, 20 minutes]:
github.com/cloudfoundry/cli/cf/commands/application.func·005()
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/commands/application/start.go:141 +0x44
created by github.com/cloudfoundry/cli/cf/commands/application.(*Start).ApplicationWatchStaging
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/tmp/cli_gopath/src/github.com/cloudfoundry/cli/cf/commands/application/start.go:143 +0x1a8
goroutine 1255 [IO wait, 7 minutes]:
net.runtime_pollWait(0x1263810, 0x72, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/runtime/netpoll.goc:146 +0x66
net.(_pollDesc).Wait(0xc20864bb80, 0x72, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/net/fd_poll_runtime.go:84 +0x46
net.(_pollDesc).WaitRead(0xc20864bb80, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/net/fd_poll_runtime.go:89 +0x42
net.(_netFD).Read(0xc20864bb20, 0xc208c22000, 0x1000, 0x1000, 0x0, 0x1255618, 0x23)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/net/fd_unix.go:242 +0x34c
net.(_conn).Read(0xc20813ddd0, 0xc208c22000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/net/net.go:122 +0xe7
crypto/tls.(_block).readFromUntil(0xc2081716b0, 0x1263a48, 0xc20813ddd0, 0x5, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/crypto/tls/conn.go:451 +0xd9
crypto/tls.(_Conn).readRecord(0xc20866eb00, 0x17, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/crypto/tls/conn.go:536 +0x1ff
crypto/tls.(_Conn).Read(0xc20866eb00, 0xc208c23000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/crypto/tls/conn.go:901 +0x16a
bufio.(_Reader).fill(0xc208618c00)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/bufio/bufio.go:97 +0x1b3
bufio.(_Reader).Read(0xc208618c00, 0xc208a2c1a0, 0x2, 0x8, 0x2, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/bufio/bufio.go:175 +0x230
github.com/gorilla/websocket.(_Conn).readFull(0xc2087f3590, 0xc208a2c1a0, 0x2, 0x8, 0x0, 0x0)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/Godeps/_workspace/src/github.com/gorilla/websocket/conn.go:524 +0xb0
github.com/gorilla/websocket.(_Conn).advanceFrame(0xc2087f3590, 0xc20863bf10, 0x0, 0x0)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/Godeps/_workspace/src/github.com/gorilla/websocket/conn.go:548 +0x166
github.com/gorilla/websocket.(_Conn).NextReader(0xc2087f3590, 0x0, 0x0, 0x0, 0x0, 0x0)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/Godeps/_workspace/src/github.com/gorilla/websocket/conn.go:688 +0x77
github.com/gorilla/websocket.(_Conn).ReadMessage(0xc2087f3590, 0xc20863bec0, 0x0, 0x0, 0x0, 0x0, 0x0)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/Godeps/_workspace/src/github.com/gorilla/websocket/conn.go:751 +0x6e
github.com/cloudfoundry/loggregator_consumer.(_consumer).listenForMessages(0xc208066b80, 0xc20863bec0, 0x0, 0x0)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/Godeps/_workspace/src/github.com/cloudfoundry/loggregator_consumer/consumer.go:308 +0x89
github.com/cloudfoundry/loggregator_consumer.func·001()
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/Godeps/_workspace/src/github.com/cloudfoundry/loggregator_consumer/consumer.go:116 +0x64
created by github.com/cloudfoundry/loggregator_consumer.(*consumer).Tail
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/Godeps/_workspace/src/github.com/cloudfoundry/loggregator_consumer/consumer.go:117 +0x23d
goroutine 1254 [sleep]:
time.Sleep(0x5d21dba00)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/runtime/time.goc:39 +0x31
github.com/cloudfoundry/loggregator_consumer.(_consumer).sendKeepAlive(0xc208066b80, 0x5d21dba00)
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/Godeps/_workspace/src/github.com/cloudfoundry/loggregator_consumer/consumer.go:298 +0x92
created by github.com/cloudfoundry/loggregator_consumer.(_consumer).Tail
/Users/fraenkel/go/src/github.com/cloudfoundry/cli/Godeps/_workspace/src/github.com/cloudfoundry/loggregator_consumer/consumer.go:112 +0x207
goroutine 1260 [select, 20 minutes]:
net/http.(_persistConn).writeLoop(0xc208366580)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/net/http/transport.go:885 +0x38f
created by net/http.(_Transport).dialConn
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/net/http/transport.go:601 +0x957
goroutine 1259 [IO wait, 20 minutes]:
net.runtime_pollWait(0x12638c0, 0x72, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/runtime/netpoll.goc:146 +0x66
net.(_pollDesc).Wait(0xc208c49640, 0x72, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/net/fd_poll_runtime.go:84 +0x46
net.(_pollDesc).WaitRead(0xc208c49640, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/net/fd_poll_runtime.go:89 +0x42
net.(_netFD).Read(0xc208c495e0, 0xc208c52000, 0x1000, 0x1000, 0x0, 0x1255618, 0x23)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/net/fd_unix.go:242 +0x34c
net.(_conn).Read(0xc20813df80, 0xc208c52000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/net/net.go:122 +0xe7
crypto/tls.(_block).readFromUntil(0xc20816bcb0, 0x1263a48, 0xc20813df80, 0x5, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/crypto/tls/conn.go:451 +0xd9
crypto/tls.(_Conn).readRecord(0xc20866f600, 0x17, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/crypto/tls/conn.go:536 +0x1ff
crypto/tls.(_Conn).Read(0xc20866f600, 0xc208c53000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/crypto/tls/conn.go:901 +0x16a
net/http.noteEOFReader.Read(0x126c4f8, 0xc20866f600, 0xc2083665d8, 0xc208c53000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/net/http/transport.go:1203 +0x72
net/http.(_noteEOFReader).Read(0xc2088d2b60, 0xc208c53000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
:124 +0xca
bufio.(_Reader).fill(0xc208c5e2a0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/bufio/bufio.go:97 +0x1b3
bufio.(_Reader).Peek(0xc208c5e2a0, 0x1, 0x0, 0x0, 0x0, 0x0, 0x0)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/bufio/bufio.go:132 +0x101
net/http.(_persistConn).readLoop(0xc208366580)
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/net/http/transport.go:782 +0x95
created by net/http.(_Transport).dialConn
/usr/local/Cellar/go/1.3.1/libexec/src/pkg/net/http/transport.go:600 +0x93f
The text was updated successfully, but these errors were encountered: