Immediate "close" after "getMessages" on some accounts

[vu0tran]

For some email accounts, I've been running into something bizarre. When you send a "getMessages" command after listening to "newMessage" event, the websocket decides to close itself with a 1011 error.

When I do the "getMessages" command without the hook to "newMessage", it seems to be fine.

Any tips on how I can debug this or where to look?

[:send, "getMessages", {:account=>"xxxxxxxxx@gmail.com", :ids=>["INBOX!596995877?42082"], :properties=>["raw", "uid"]}]

[:close, #<Faye::WebSocket::API::CloseEvent:0x00000001e0fc08 @type="close", @code=1011, @reason="", @bubbles=false, @cancelable=false, @current_target=#<Faye::WebSocket::Client:0x00000002b765b8 @url="ws://192.168.50.2:8080/workers", @ready_state=3, @listeners={"open"=>[#<Proc:0x000000017bb320@switchboard.rb:15>], "message"=>[#<Proc:0x000000017baf60@switchboard.rb:74>], "error"=>[#<Proc:0x000000017badf8@switchboard.rb:123>], "close"=>[#<Proc:0x000000017ba920@switchboard.rb:127>]}, @driver=#<WebSocket::Driver::Client:0x00000002b9a670 @listeners={"open"=>[#<Proc:0x000000017b6cd0@/var/lib/gems/1.9.1/gems/faye-websocket-0.10.2/lib/faye/websocket/api.rb:39>], "message"=>[#<Proc:0x000000017b6a00@/var/lib/gems/1.9.1/gems/faye-websocket-0.10.2/lib/faye/websocket/api.rb:40>], "close"=>[#<Proc:0x000000017b6848@/var/lib/gems/1.9.1/gems/faye-websocket-0.10.2/lib/faye/websocket/api.rb:41>], "error"=>[#<Proc:0x000000017b63c0@/var/lib/gems/1.9.1/gems/faye-websocket-0.10.2/lib/faye/websocket/api.rb:43>]}, @socket=#<Faye::WebSocket::Client:0x00000002b765b8 ...>, @reader=#<WebSocket::Driver::StreamReader:0x00000002b9e1a8 @buffer="\x88\x02\x03\xF3", @offset=4>, @options={:max_length=>nil, :protocols=>nil, :masking=>true}, @max_length=67108863, @headers={"connection"=>"Upgrade", "upgrade"=>"websocket", "sec-websocket-accept"=>"k6NDeMpRpaiq6OBFYTNpUoMbZKY="}, @queue=[], @ready_state=3, @extensions=#<WebSocket::Extensions:0x00000002b847d0 @rsv3=nil, @rsv2=nil, @rsv1=nil, @by_name={}, @in_order=[], @sessions=[], @index={}>, @stage=5, @masking=true, @protocols=[], @require_masking=nil, @ping_callbacks={}, @key="SNjaCjvYHirOeH07bzSPuQ==", @accept="k6NDeMpRpaiq6OBFYTNpUoMbZKY=", @http=#<WebSocket::HTTP::Response:0x000000017afbd8 @buffer=[], @headers={"connection"=>"Upgrade", "upgrade"=>"websocket", "sec-websocket-accept"=>"k6NDeMpRpaiq6OBFYTNpUoMbZKY="}, @stage=2, @code=101>, @pathname="/workers", @status=101, @frame=nil, @message=nil>, @ping=nil, @ping_id=0, @buffered_amount=0, @secure=false, @origin_tls={}, @socket_tls={}, @stream=#<Faye::WebSocket::Client::Connection::EM_CONNECTION_CLASS:0x000000017bbd98 @signature=2, @parent=#<Faye::WebSocket::Client:0x00000002b765b8 ...>>, @close_params=["", 1011]>, @target=#<Faye::WebSocket::Client:0x00000002b765b8 @url="ws://192.168.50.2:8080/workers", @ready_state=3, @listeners={"open"=>[#<Proc:0x000000017bb320@switchboard.rb:15>], "message"=>[#<Proc:0x000000017baf60@switchboard.rb:74>], "error"=>[#<Proc:0x000000017badf8@switchboard.rb:123>], "close"=>[#<Proc:0x000000017ba920@switchboard.rb:127>]}, @driver=#<WebSocket::Driver::Client:0x00000002b9a670 @listeners={"open"=>[#<Proc:0x000000017b6cd0@/var/lib/gems/1.9.1/gems/faye-websocket-0.10.2/lib/faye/websocket/api.rb:39>], "message"=>[#<Proc:0x000000017b6a00@/var/lib/gems/1.9.1/gems/faye-websocket-0.10.2/lib/faye/websocket/api.rb:40>], "close"=>[#<Proc:0x000000017b6848@/var/lib/gems/1.9.1/gems/faye-websocket-0.10.2/lib/faye/websocket/api.rb:41>], "error"=>[#<Proc:0x000000017b63c0@/var/lib/gems/1.9.1/gems/faye-websocket-0.10.2/lib/faye/websocket/api.rb:43>]}, @socket=#<Faye::WebSocket::Client:0x00000002b765b8 ...>, @reader=#<WebSocket::Driver::StreamReader:0x00000002b9e1a8 @buffer="\x88\x02\x03\xF3", @offset=4>, @options={:max_length=>nil, :protocols=>nil, :masking=>true}, @max_length=67108863, @headers={"connection"=>"Upgrade", "upgrade"=>"websocket", "sec-websocket-accept"=>"k6NDeMpRpaiq6OBFYTNpUoMbZKY="}, @queue=[], @ready_state=3, @extensions=#<WebSocket::Extensions:0x00000002b847d0 @rsv3=nil, @rsv2=nil, @rsv1=nil, @by_name={}, @in_order=[], @sessions=[], @index={}>, @stage=5, @masking=true, @protocols=[], @require_masking=nil, @ping_callbacks={}, @key="SNjaCjvYHirOeH07bzSPuQ==", @accept="k6NDeMpRpaiq6OBFYTNpUoMbZKY=", @http=#<WebSocket::HTTP::Response:0x000000017afbd8 @buffer=[], @headers={"connection"=>"Upgrade", "upgrade"=>"websocket", "sec-websocket-accept"=>"k6NDeMpRpaiq6OBFYTNpUoMbZKY="}, @stage=2, @code=101>, @pathname="/workers", @status=101, @frame=nil, @message=nil>, @ping=nil, @ping_id=0, @buffered_amount=0, @secure=false, @origin_tls={}, @socket_tls={}, @stream=#<Faye::WebSocket::Client::Connection::EM_CONNECTION_CLASS:0x000000017bbd98 @signature=2, @parent=#<Faye::WebSocket::Client:0x00000002b765b8 ...>>, @close_params=["", 1011]>, @event_phase=2>]

[vu0tran]

2016-01-11 10:08:57 =ERROR REPORT====
** Generic server <0.324.0> terminating 
** Last message in was {ssl,{sslsocket,{gen_tcp,#Port<0.3052>,tls_connection,undefined},<0.326.0>},<<"ccess)\r\n">>}
** When Server state == {state,{sslsocket,{gen_tcp,#Port<0.3052>,tls_connection,undefined},<0.326.0>},{ssl,<<"imap.gmail.com">>,993,[],5000},[{cmds,[{cmd,{call,{login,{xoauth2,<<"xxxxxxx@gmail.com">>,{<<"1/2p2uKL2i09cNWepQOQM7_7NiP_cpXJ4TCAVv-5vYYCY">>,<<"google">>}}}}}]},{post_init_callback,#Fun<switchboard.0.122082165>}],10,{<<>>,{atom,<<"Su">>}},{[],[none,<<"selected.">>,<<"INBOX">>,']',<<"READ-WRITE">>,'[',<<"OK">>,<<"C9">>]},{1,{<<"C9">>,{cmd,{select,<<"INBOX">>},[{dispatch,#Fun<imap.8.100085555>}]},nil,nil}}}
** Reason for termination == 
** {function_clause,[{imap,churn_buffer,[{state,{sslsocket,{gen_tcp,#Port<0.3052>,tls_connection,undefined},<0.326.0>},{ssl,<<"imap.gmail.com">>,993,[],5000},[{cmds,[{cmd,{call,{login,{xoauth2,<<"xxxxxx@gmail.com">>,{<<"1/2p2uKL2i09cNWepQOQM7_7NiP_cpXJ4TCAVv-5vYYCY">>,<<"google">>}}}}}]},{post_init_callback,#Fun<switchboard.0.122082165>}],10,{<<>>,none},{[],[]},{0,nil}},[]],[{file,"src/imap.erl"},{line,605}]},{imap,handle_info,2,[{file,"src/imap.erl"},{line,517}]},{gen_server,handle_msg,5,[{file,"gen_server.erl"},{line,599}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,239}]}]}

2016-01-11 10:08:57 =CRASH REPORT====
  crasher:
    initial call: imap:init/1
    pid: <0.324.0>
    registered_name: []
    exception exit: {{function_clause,[{imap,churn_buffer,[{state,{sslsocket,{gen_tcp,#Port<0.3052>,tls_connection,undefined},<0.326.0>},{ssl,<<"imap.gmail.com">>,993,[],5000},[{cmds,[{cmd,{call,{login,{xoauth2,<<"xxxxxx@gmail.com">>,{<<"1/2p2uKL2i09cNWepQOQM7_7NiP_cpXJ4TCAVv-5vYYCY">>,<<"google">>}}}}}]},{post_init_callback,#Fun<switchboard.0.122082165>}],10,{<<>>,none},{[],[]},{0,nil}},[]],[{file,"src/imap.erl"},{line,605}]},{imap,handle_info,2,[{file,"src/imap.erl"},{line,517}]},{gen_server,handle_msg,5,[{file,"gen_server.erl"},{line,599}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,239}]}]},[{gen_server,terminate,6,[{file,"gen_server.erl"},{line,746}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,239}]}]}
    ancestors: [<0.239.0>,switchboard_accounts_sup,switchboard_sup,<0.113.0>]
    messages: [{'$gen_cast',{cmd,{uid,{fetch,[42082],[<<"BODY.PEEK[]">>]}},[{dispatch,#Fun<imap.8.100085555>}]}}]
    links: [<0.239.0>]
    dictionary: []
    trap_exit: false
    status: running
    heap_size: 987
    stack_size: 27
    reductions: 17038
  neighbours:

2016-01-11 10:30:55.434 [error] <0.115.0> Ranch listener switchboard_cowboy had connection process started with cowboy_protocol:start_link/4 at <0.225.0> exit with reason: {[{reason,{badmatch,{<<"error">>,[{<<"type">>,{function_clause,[{switchboard_jmap,fetch_properties,[<<"INBOX!596995877">>,{flags,[[<<"\\Answered">>,<<"\\Flagged">>,<<"\\Draft">>,<<"\\Deleted">>,<<"\\Seen">>,<<"$Forwarded">>,<<"$Junk">>,<<"$MailFlagBit0">>,<<"$NotJunk">>,<<"$NotPhishing">>,<<"$Phishing">>,<<"Forwarded">>,<<"Junk">>,<<"JunkRecorded">>,<<"NotJunk">>]]},[<<"raw">>,<<"uid">>]],[{file,"src/switchboard_jmap.erl"},{line,620}]},{switchboard_jmap,'-get_messages/3-lc$^1/1-1-',3,[{file,"src/switchboard_jmap.erl"},{line,515}]},{switchboard_jmap,'-get_messages/3-fun-1-',5,[{file,"src/switchboard_jmap.erl"},{line,515}]},{switchboard_jmap,get_messages,3,[{file,"src/switchboard_jmap.erl"},{line,507}]},{switchboard,with_imap,2,[{file,"src/switchboard.erl"},{line,216}]},{switchboard_jmap,call,2,[{file,"src/switchboard_jmap.erl"},{line,388}]},{switchboard_workers,call_all,3,[{file,"src/switchboard_workers.erl"},{line,165}]},{switchboard_workers,websocket_handle,3,[{file,"src/switchboard_workers.erl"},{line,99}]}]}},{<<"method">>,<<"getMessages">>},{<<"arguments">>,[{<<"ids">>,[<<"INBOX!596995877?42082">>]},{<<"properties">>,[<<"raw">>,<<"uid">>]}]}],undefined}}},{mfa,{switchboard_workers,websocket_handle,3}},{stacktrace,[{switchboard_workers,call_all,3,[{file,"src/switchboard_workers.erl"},{line,164}]},{switchboard_workers,websocket_handle,3,[{file,"src/switchboard_workers.erl"},{line,99}]},{cowboy_websocket,handler_call,7,[{file,"src/cowboy_websocket.erl"},{line,588}]},{cowboy_protocol,execute,4,[{file,"src/cowboy_protocol.erl"},{line,442}]}]},{msg,{text,<<"[[\"getMessages\",{\"account\":\"xxxxxx@gmail.com\",\"ids\":[\"INBOX!596995877?42082\"],\"properties\":[\"raw\",\"uid\"]}]]">>}},{req,[{socket,#Port<0.2045>},{transport,ranch_tcp},{connection,keepalive},{pid,<0.225.0>},{method,<<"GET">>},{version,'HTTP/1.1'},{peer,{{192,168,50,2},57414}},{host,<<"192.168.50.2">>},{host_info,undefined},{port,8080},{path,<<"/workers">>},{path_info,undefined},{qs,<<>>},{qs_vals,undefined},{bindings,[]},{headers,[{<<"host">>,<<"192.168.50.2:8080">>},{<<"upgrade">>,<<"websocket">>},{<<"connection">>,<<"Upgrade">>},{<<"sec-websocket-key">>,<<"d2xO/kYq+DVt+BaXErAkSw==">>},{<<"sec-websocket-version">>,<<"13">>}]},{p_headers,[{<<"upgrade">>,[<<"websocket">>]},{<<"connection">>,[<<"upgrade">>]}]},{cookies,undefined},{meta,[{websocket_version,13},{websocket_compress,false}]},{body_state,waiting},{buffer,<<>>},{multipart,undefined},{resp_compress,false},{resp_state,done},{resp_headers,[]},{resp_body,<<>>},{onresponse,undefined}]},{state,{state}}],[{cowboy_protocol,execute,4,[{file,"src/cowboy_protocol.erl"},{line,442}]}]}

[jtmoulia]

Very helpful error report -- on it.

[vu0tran]

Thanks. There were also some other crashes. They look a bit different. Not sure if they're related?

2016-01-21 21:30:50 =ERROR REPORT====
Ranch listener switchboard_cowboy had connection process started with cowboy_protocol:start_link/4 at <0.246.0> exit with reason: {[{reason,{badmatch,{<<"error">>,[{<<"type">>,{{badmatch,{error,timeout}},[{switchboard_jmap,'-get_messages/3-fun-1-',5,[{file,"src/switchboard_jmap.erl"},{line,510}]},{switchboard_jmap,get_messages,3,[{file,"src/switchboard_jmap.erl"},{line,507}]},{switchboard,with_imap,2,[{file,"src/switchboard.erl"},{line,216}]},{switchboard_jmap,call,2,[{file,"src/switchboard_jmap.erl"},{line,388}]},{switchboard_workers,call_all,3,[{file,"src/switchboard_workers.erl"},{line,165}]},{switchboard_workers,websocket_handle,3,[{file,"src/switchboard_workers.erl"},{line,99}]},{cowboy_websocket,handler_call,7,[{file,"src/cowboy_websocket.erl"},{line,588}]},{cowboy_protocol,execute,4,[{file,"src/cowboy_protocol.erl"},{line,442}]}]}},{<<"method">>,<<"getMessages">>},{<<"arguments">>,[{<<"ids">>,[<<"INBOX!3?131964">>]},{<<"properties">>,[<<"raw">>,<<"uid">>]}]}],undefined}}},{mfa,{switchboard_workers,websocket_handle,3}},{stacktrace,[{switchboard_workers,call_all,3,[{file,"src/switchboard_workers.erl"},{line,164}]},{switchboard_workers,websocket_handle,3,[{file,"src/switchboard_workers.erl"},{line,99}]},{cowboy_websocket,handler_call,7,[{file,"src/cowboy_websocket.erl"},{line,588}]},{cowboy_protocol,execute,4,[{file,"src/cowboy_protocol.erl"},{line,442}]}]},{msg,{text,<<"[[\"getMessages\",{\"account\":\"xxxxxxx@gmail.com\",\"ids\":[\"INBOX!3?131964\"],\"properties\":[\"raw\",\"uid\"]}]]">>}},{req,[{socket,#Port<0.3023>},{transport,ranch_tcp},{connection,keepalive},{pid,<0.246.0>},{method,<<"GET">>},{version,'HTTP/1.1'},{peer,{{192,168,50,2},55091}},{host,<<"192.168.50.2">>},{host_info,undefined},{port,8080},{path,<<"/workers">>},{path_info,undefined},{qs,<<>>},{qs_vals,undefined},{bindings,[]},{headers,[{<<"host">>,<<"192.168.50.2:8080">>},{<<"upgrade">>,<<"websocket">>},{<<"connection">>,<<"Upgrade">>},{<<"sec-websocket-key">>,<<"oadcr65AkM3nzrZeUSvEbg==">>},{<<"sec-websocket-version">>,<<"13">>}]},{p_headers,[{<<"upgrade">>,[<<"websocket">>]},{<<"connection">>,[<<"upgrade">>]}]},{cookies,undefined},{meta,[{websocket_version,13},{websocket_compress,false}]},{body_state,waiting},{buffer,<<>>},{multipart,undefined},{resp_compress,false},{resp_state,done},{resp_headers,[]},{resp_body,<<>>},{onresponse,undefined}]},{state,{state}}],[{cowboy_protocol,execute,4,[{file,"src/cowboy_protocol.erl"},{line,442}]}]}
2016-01-21 21:31:05 =SUPERVISOR REPORT====
     Supervisor: {<0.227.0>,switchboard_accounts}
     Context:    child_terminated
     Reason:     normal
     Offender:   [{pid,<0.228.0>},{name,active},{mfargs,{imap,start_link,[{ssl,<<"imap.gmail.com">>,993},[{cmds,[{cmd,{call,{login,{xoauth2,<<"xxxxxx@gmail.com">>,{<<"1/ZY5I9wJ18_gv-_qTf8fDaa0XW6RZBbeLD04Otmz0qro">>,<<"google">>}}}}}]},{post_init_callback,#Fun<switchboard.0.122082165>}]]}},{restart_type,permanent},{shutdown,5000},{child_type,worker}]

[jtmoulia]

Going to break that into a new issue, though it might very well be a timeout caused by the original error killing the imap process.

@vu0tran Do the processes restart after this? Does the email monitoring restart?

[vu0tran]

I'm far from competent in Erlang, but as far as I know, Switchboard still can process other accounts. For that one account, it seems like it's dead and does not restart. I have to manually reconnect again and send a watch command again (Which then crashes in the same way when a new email is received).

If you'd like, feel free to email me at vu0tran@gmail.com and we can debug real time via Slack or something. I can provide you with the account credentials and show you how to repro it.

[jtmoulia]

Great! I'll have more time tomorrow in the morning, and I'll send you a message round then.

On Jan 21, 2016, 2:22 PM, at 2:22 PM, Vu Tran notifications@github.com wrote:

I'm far from competent in Erlang, but as far as I know, Switchboard still can process other accounts. For that one account, it seems like it's dead and does not restart. I have to manually reconnect again and send a watch command again (Which then crashes in the same way when a new email is received).

If you'd like, feel free to email me at vu0tran@gmail.com and we can debug real time via Slack or something. I can provide you with the account credentials and show you how to repro it.

---

Reply to this email directly or view it on GitHub: https://github.com/thusfresh/switchboard/issues/55#issuecomment-173733118

[leostera]

I came here to comment that churn_buffer(State, []) -> State; wasn't defined anywhere, and that's how I patched our switchboard, only to find you had worked on it too!

Thanks for that.

[jtmoulia]

Heyo, yeah, this has been lurking. Hopefully churn_buffer won't see an empty list as a second argument anymore, that was an error from parsing. :pray: