Investigate bug around server dying frequently

[ryanjadhav]

If i had to guess its something about socket.io crashing. (we should also monitor our dyno usage per hour)

[yskhoo]

22:23:10 web.1 | debug: setting request GET /socket.io/1/xhr-polling/A48qNhPYH0CEVCBJT-53?t=1361946190533 22:23:10 web.1 | debug: setting poll timeout 22:23:10 web.1 | debug: client authorized for 22:23:10 web.1 | debug: clearing poll timeout 22:23:10 web.1 | debug: xhr-polling writing 1:: 22:23:10 web.1 | debug: set close timeout for client A48qNhPYH0CEVCBJT-53 22:23:13 web.1 | debug: xhr-polling received data packet 5:::{"name":"addUser","args":["sun"]} 22:23:13 web.1 | debug: broadcasting packet 22:23:13 web.1 | debug: clearing poll timeout 22:23:13 web.1 | events.js:71 22:23:13 web.1 | throw arguments[1]; // Unhandled 'error' event 22:23:13 web.1 | ^ 22:23:13 web.1 | Error: socket hang up 22:23:13 web.1 | at createHangUpError (http.js:1360:15) 22:23:13 web.1 | at ServerResponse.OutgoingMessage._writeRaw (http.js:507:26) 22:23:13 web.1 | at ServerResponse.OutgoingMessage._send (http.js:476:15) 22:23:13 web.1 | at ServerResponse.OutgoingMessage.write (http.js:749:16) 22:23:13 web.1 | at XHRPolling.doWrite (/Users/yskhoo/workspace/SingAlongWithMe/node_modules/socket.io/lib/transports/xhr-polling.js:67:17) 22:23:13 web.1 | at XHRPolling.HTTPPolling.write (/Users/yskhoo/workspace/SingAlongWithMe/node_modules/socket.io/lib/transports/http-polling.js:132:8) 22:23:13 web.1 | at XHRPolling.Transport.onDispatch (/Users/yskhoo/workspace/SingAlongWithMe/node_modules/socket.io/lib/transport.js:222:10) 22:23:13 web.1 | at Manager.onDispatch (/Users/yskhoo/workspace/SingAlongWithMe/node_modules/socket.io/lib/manager.js:392:31) 22:23:13 web.1 | at SocketNamespace.packet (/Users/yskhoo/workspace/SingAlongWithMe/node_modules/socket.io/lib/namespace.js:156:16) 22:23:13 web.1 | at Socket.packet (/Users/yskhoo/workspace/SingAlongWithMe/node_modules/socket.io/lib/socket.js:209:56) 22:23:13 web.1 | exited with code 1 22:23:13 system | sending SIGTERM to all processes SIGTERM received

[yskhoo]

22:41:47 web.1 | debug: clearing poll timeout 22:41:47 web.1 | timers.js:103 22:41:47 web.1 | if (!process.listeners('uncaughtException').length) throw e; 22:41:47 web.1 | ^ 22:41:47 web.1 | Error: socket hang up 22:41:47 web.1 | at createHangUpError (http.js:1360:15) 22:41:47 web.1 | at ServerResponse.OutgoingMessage._writeRaw (http.js:507:26) 22:41:47 web.1 | at ServerResponse.OutgoingMessage._send (http.js:476:15) 22:41:47 web.1 | at ServerResponse.OutgoingMessage.write (http.js:749:16) 22:41:47 web.1 | at XHRPolling.doWrite (/Users/yskhoo/workspace/SingAlongWithMe/node_modules/socket.io/lib/transports/xhr-polling.js:67:17) 22:41:47 web.1 | at XHRPolling.HTTPPolling.write (/Users/yskhoo/workspace/SingAlongWithMe/node_modules/socket.io/lib/transports/http-polling.js:132:8) 22:41:47 web.1 | at XHRPolling.Transport.packet (/Users/yskhoo/workspace/SingAlongWithMe/node_modules/socket.io/lib/transport.js:515:15) 22:41:47 web.1 | at Object. (/Users/yskhoo/workspace/SingAlongWithMe/node_modules/socket.io/lib/transports/http-polling.js:79:12) 22:41:47 web.1 | at Object.exports.callback.args.(anonymous function) (/Users/yskhoo/workspace/SingAlongWithMe/node_modules/nodefly/lib/proxy.js:125:18) 22:41:47 web.1 | at Timer.list.ontimeout (timers.js:101:19) 22:41:47 web.1 | exited with code 1 22:41:47 system | sending SIGTERM to all processes

[ryanjadhav]

stopped happening...on heroku and locally for me.

not really sure what happened.

[ryanjadhav]

im marking this closed for now, if it resurfaces we can dig it up again.

[yskhoo]

Found new error logs:

2013-03-03T06:52:43+00:00 app[web.1]: debug: cleared close timeout for client rZ5rwL4Q94Wb52EgAFlg 2013-03-03T06:52:53+00:00 heroku[router]: at=info method=GET path=/socket.io/1/xhr-polling/rZ5rwL4Q94Wb52EgAFlg?t=1362293565243 host=www.justsing.it fwd="50.131.22.126" dyno=web.1 queue=0 wait=0ms connect=2ms service=10008ms status=200 bytes=3 2013-03-03T06:52:54+00:00 app[web.1]: debug: clearing poll timeout 2013-03-03T06:52:54+00:00 app[web.1]: debug: set close timeout for client rZ5rwL4Q94Wb52EgAFlg 2013-03-03T06:52:54+00:00 app[web.1]: debug: xhr-polling closed due to exceeded duration 2013-03-03T06:52:54+00:00 app[web.1]: debug: xhr-polling writing 8:: 2013-03-03T06:53:53+00:00 app[web.1]: info: transport end (close timeout) 2013-03-03T06:53:53+00:00 app[web.1]: debug: fired close timeout for client rZ5rwL4Q94Wb52EgAFlg 2013-03-03T06:53:53+00:00 app[web.1]: debug: discarding transport 2013-03-03T06:56:2 0+00:00 heroku[slugc]: Slug compilation started 2013-03-03T06:56:59+00:00 heroku[api]: Release v34 created by ryan.jadhav@gmail.com 2013-03-03T06:56:59+00:00 heroku[api]: Deploy 45c9c3b by ryan.jadhav@gmail.com 2013-03-03T06:56:59+00:00 heroku[web.1]: State changed from up to starting 2013-03-03T06:56:59+00:00 heroku[slugc]: Slug compilation finished 2013-03-03T06:57:01+00:00 heroku[deployhooks]: Your New Relic account is not activated. Please make sure your agent is running: http://devcenter.heroku.com/articles/newrelic 2013-03-03T06:57:01+00:00 heroku[web.1]: Starting process with command node app 2013-03-03T06:57:03+00:00 app[web.1]: info: socket.io started 2013-03-03T06:57:03+00:00 app[web.1]: Express server listening on port 17057 2013-03-03T06:57:03+00:00 heroku[web.1]: Error R11 (Bad bind) -> Process bound to port 44538, should be 17057 (see environment variable PORT) 2013-03-03T06:57:03+00:00 heroku[web.1]: Stopping process with SIGKILL 2013-03-03T06:57:05+00:00 heroku[web.1]: State changed from starting to crashed 2013-03-03T06:57:05+00:00 heroku[web.1]: Process exited with status 137 2013-03-03T06:57:05+00:00 heroku[web.1]: State changed from crashed to starting 2013-03-03T06:57:05+00:00 heroku[web.1]: Stopping all processes with SIGTERM 2013-03-03T06:57:06+00:00 heroku[web.1]: Process exited with status 1 2013-03-03T06:57:10+00:00 heroku[web.1]: State changed from starting to up 2013-03-03T07:59:45+00:00 heroku[web.1]: Idling 2013-03-03T07:59:49+00:00 heroku[web.1]: Stopping all processes with SIGTERM 2013-03-03T07:59:51+00:00 heroku[web.1]: State changed from up to down 2013-03-03T07:59:51+00:00 heroku[web.1]: Process exited with status 1 2013-03-03T22:54:54+00:00 heroku[web.1]: State changed from down to starting 2013-03-03T22:54:54+00:00 heroku[web.1]: Unidling 2013-03-03T22:54:56+00:00 heroku[web.1]: Starting process with command node app 2013-03-03T22:54:56+00:00 app[web.1]: info: socket.io started 2013-03-03T22:54:57+00:00 app[web.1]: Express server listening on port 15043 2013-03-03T22:54:57+00:00 heroku[web.1]: Stopping process with SIGKILL 2013-03-03T22:54:57+00:00 heroku[web.1]: Error R11 (Bad bind) -> Process bound to port 49151, should be 15043 (see environment variable PORT) 2013-03-03T22:54:58+00:00 heroku[web.1]: Process exited with status 137 2013-03-03T22:54:58+00:00 heroku[web.1]: State changed from starting to crashed 2013-03-03T22:54:58+00:00 heroku[web.1]: State changed from crashed to starting 2013-03-03T22:55:03+00:00 heroku[web.1]: State changed from starting to crashed 2013-03-03T22:55:04+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=GET path=/ host=www.justsing.it fwd="99.190.99.93" dyno= queue= wait= connect= service= status=503 bytes= 2013-03-03T22:55:05+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=GET path=/favicon.ico host=www.justsing.it fwd="99.190.99.93" dyno= queue= wait= connect= service= status=503 bytes= 2013-03-03T22:55:13+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=GET path=/ host=www.justsing.it fwd="99.190.99.93" dyno= queue= wait= connect= service= status=503 bytes= 2013-03-03T22:55:13+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=GET path=/ host=www.justsing.it fwd="99.190.99.93" dyno= queue= wait= connect= service= status=503 bytes= 2013-03-03T22:55:13+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=GET path=/favicon.ico host=www.justsing.it fwd="99.190.99.93" dyno= queue= wait= connect= service= status=503 bytes= 2013-03-03T22:55:22+00:00 heroku[web.1]: State changed from crashed to starting 2013-03-03T22:55:25+00:00 heroku[web.1]: Starting process with command node app 2013-03-03T22:55:27+00:00 app[web.1]: info: socket.io started 2013-03-03T22:55:27+00:00 heroku[web.1]: Error R11 (Bad bind) -> Process bound to port 44109, should be 5864 (see environment variable PORT) 2013-03-03T22:55:27+00:00 heroku[web.1]: Stopping process with SIGKILL 2013-03-03T22:55:28+00:00 heroku[web.1]: Process exited with status 137 2013-03-03T22:55:28+00:00 heroku[web.1]: State changed from starting to crashed ^[[B2013-03-03T22:55:53+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=GET path=/ host=www.justsing.it fwd="99.190.99.93" dyno= queue= wait= connect= service= status=503 bytes= 2013-03-03T22:55:53+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=GET path=/favicon.ico host=www.justsing.it fwd="99.190.99.93" dyno= queue= wait= connect= service= status=503 bytes= 2013-03-03T22:55:57+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=GET path=/favicon.ico host=www.justsing.it fwd="99.190.99.93" dyno= queue= wait= connect= service= status=503 bytes= 2013-03-03T22:55:56+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=GET path=/ host=www.justsing.it fwd="99.190.99.93" dyno= queue= wait= connect= service= status=503 bytes=