Investigate bug around server dying frequently

[yskhoo]

[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=