search

braverhealth / phoenix-socket-dart

Cross-platform and stream-based implementation of Phoenix Sockets
https://pub.dev/packages/phoenix_socket
BSD 3-Clause "New" or "Revised" License
74 stars 37 forks source link

heartbeatMessage throws on connection drop #5

Closed hamann closed 3 years ago

hamann commented 3 years ago

I updated from 0.3.3 to 0.4.2 yesterday and when I kill the backend I now get 

WebSocketChannelException: HttpException: Connection closed before full header was received, uri = http://127.0.0.1:4000/socket/websocket?api_token=[REDACTED]&vsn=2.0.0

Callstack

PhoenixSocket._sendHeartbeat (/usr/local/Caskroom/flutter/1.20.4/flutter/.pub-cache/hosted/pub.dartlang.org/phoenix_socket-0.4.2/lib/src/socket.dart:418)
<asynchronous gap> (Unknown Source:0)
PhoenixSocket.connect.<anonymous closure> (/usr/local/Caskroom/flutter/1.20.4/flutter/.pub-cache/hosted/pub.dartlang.org/phoenix_socket-0.4.2/lib/src/socket.dart:209)
_rootRun (dart:async/zone.dart:1182)
_rootRun (dart:async/zone.dart:0)
_CustomZone.run (dart:async/zone.dart:1093)
PhoenixSocket.connect (/usr/local/Caskroom/flutter/1.20.4/flutter/.pub-cache/hosted/pub.dartlang.org/phoenix_socket-0.4.2/lib/src/socket.dart:192)
<asynchronous gap> (Unknown Source:0)
PhoenixSocket._delayedReconnect (/usr/local/Caskroom/flutter/1.20.4/flutter/.pub-cache/hosted/pub.dartlang.org/phoenix_socket-0.4.2/lib/src/socket.dart:541)
<asynchronous gap> (Unknown Source:0)
PhoenixSocket._onSocketClosed (/usr/local/Caskroom/flutter/1.20.4/flutter/.pub-cache/hosted/pub.dartlang.org/phoenix_socket-0.4.2/lib/src/socket.dart:496)
PhoenixSocket._onSocketClosed (/usr/local/Caskroom/flutter/1.20.4/flutter/.pub-cache/hosted/pub.dartlang.org/phoenix_socket-0.4.2/lib/src/socket.dart:0)
_rootRun (dart:async/zone.dart:1182)
_rootRun (dart:async/zone.dart:0)
_CustomZone.run (dart:async/zone.dart:1093)
_CustomZone.bindCallback.<anonymous closure> (dart:async/zone.dart:1021)
_rootRun (dart:async/zone.dart:1182)
_rootRun (dart:async/zone.dart:0)
_CustomZone.run (dart:async/zone.dart:1093)
_CustomZone.runGuarded (dart:async/zone.dart:997)
_BufferingStreamSubscription._sendDone.sendDone (dart:async/stream_impl.dart:410)
_BufferingStreamSubscription._sendDone (dart:async/stream_impl.dart:420)
_BufferingStreamSubscription._close (dart:async/stream_impl.dart:305)
_ForwardingStream._handleDone (dart:async/stream_pipe.dart:101)
_ForwardingStreamSubscription._handleDone (dart:async/stream_pipe.dart:165)
_ForwardingStreamSubscription._handleDone (dart:async/stream_pipe.dart:0)
_rootRun (dart:async/zone.dart:1182)
_rootRun (dart:async/zone.dart:0)
_CustomZone.run (dart:async/zone.dart:1093)
_CustomZone.runGuarded (dart:async/zone.dart:997)
_BufferingStreamSubscription._sendDone.sendDone (dart:async/stream_impl.dart:410)
_BufferingStreamSubscription._sendDone (dart:async/stream_impl.dart:420)
_BufferingStreamSubscription._close (dart:async/stream_impl.dart:305)
_ForwardingStream._handleDone (dart:async/stream_pipe.dart:101)
_ForwardingStreamSubscription._handleDone (dart:async/stream_pipe.dart:165)
_ForwardingStreamSubscription._handleDone (dart:async/stream_pipe.dart:0)
_rootRun (dart:async/zone.dart:1182)
_rootRun (dart:async/zone.dart:0)
_CustomZone.run (dart:async/zone.dart:1093)
_CustomZone.runGuarded (dart:async/zone.dart:997)
_BufferingStreamSubscription._sendDone.sendDone (dart:async/stream_impl.dart:410)
_BufferingStreamSubscription._sendDone (dart:async/stream_impl.dart:420)
_BufferingStreamSubscription._close (dart:async/stream_impl.dart:305)
_SyncStreamControllerDispatch._sendDone (dart:async/stream_controller.dart:816)
_StreamController._closeUnchecked (dart:async/stream_controller.dart:671)
_StreamController.close (dart:async/stream_controller.dart:664)
_StreamController.close (dart:async/stream_controller.dart:0)
_rootRun (dart:async/zone.dart:1182)
_rootRun (dart:async/zone.dart:0)
_CustomZone.run (dart:async/zone.dart:1093)
_FutureListener.handleWhenComplete (dart:async/future_impl.dart:167)
Future._propagateToListeners.handleWhenCompleteCallback (dart:async/future_impl.dart:666)
Future._propagateToListeners (dart:async/future_impl.dart:722)
Future._completeWithValue (dart:async/future_impl.dart:529)
Future._asyncCompleteWithValue.<anonymous closure> (dart:async/future_impl.dart:567)
_rootRun (dart:async/zone.dart:1190)
_rootRun (dart:async/zone.dart:0)
_CustomZone.run (dart:async/zone.dart:1093)
_CustomZone.runGuarded (dart:async/zone.dart:997)
_CustomZone.bindCallbackGuarded.<anonymous closure> (dart:async/zone.dart:1037)
_microtaskLoop (dart:async/schedule_microtask.dart:41)
_startMicrotaskLoop (dart:async/schedule_microtask.dart:50)
_startMicrotaskLoop (dart:async/schedule_microtask.dart:0)
matehat commented 3 years ago

Thanks for the report, should be fixed with df8cee766dea3090748ccf03d29ac6e2a69eb810, and released in 0.4.3.

hamann commented 3 years ago

Unfortunately I'm still getting the same exception with 0.4.3

Logs:

flutter: 2020-10-25 21:22:46.494376 FINE phoenix_socket.socket - [phoenix_socket] Heartbeat completed
flutter: 2020-10-25 21:22:46.500151 INFO phoenix_socket.socket - Socket open
flutter: 2020-10-25 21:22:55.424059 INFO phoenix_socket.socket - Socket closed with reason  and code 1005
flutter: 2020-10-25 21:22:55.424827 FINE phoenix_socket.socket - Trigger channel exceptions on 1 channels
flutter: 2020-10-25 21:22:55.425535 FINE phoenix_socket.channel.user - Receiving error on channel
### PhoenixException: PhoenixException: socket closed
flutter: 2020-10-25 21:22:55.426664 WARNING phoenix_socket.channel.user - Got error on channel
### PhoenixException: PhoenixException: socket closed
flutter: 2020-10-25 21:22:55.737833 SEVERE phoenix_socket.socket - Error on socket
### WebSocketChannelException: WebSocketChannelException: WebSocketChannelException: HttpException: Connection closed before full header was received, uri = http://127.0.0.1:4000/socket/websocket?api_token=SFMyNTY.g2gDYQFuBgBrftRcdQFiAAFRgA.E1_gPO_lHXBwZmeOoIad4QUAXB2a_8rn0VwInqncz5k&vsn=2.0.0
#0      new IOWebSocketChannel._withoutSocket.<anonymous closure>
package:web_socket_channel/io.dart:84
#1      _invokeErrorHandler (dart:async/async_error.dart:16:24)
#2      _HandleErrorStream._handleError (dart:async/stream_pipe.dart:282:9)
#3      _ForwardingStreamSubscription._handleError (dart:async/stream_pipe.dart:161:13)
#4      _rootRunBinary (dart:async/zone.dart:1214:47)
#5      _CustomZone.runBinary (dart:async/zone.dart:1107:19)
#6      _CustomZone.runBinaryGuarded (dart:async/zone.dart:1013:7)
#7      _BufferingStreamSubscription._sendError.sendError (dart:async/stream_impl.dart:376:15)
#8      _Bufferin<…>
flutter: 2020-10-25 21:22:55.738331 FINE phoenix_socket.socket - Trigger channel exceptions on 1 channels
flutter: 2020-10-25 21:22:55.738551 FINE phoenix_socket.channel.user - Receiving error on channel
### PhoenixException: WebSocketChannelException: WebSocketChannelException: HttpException: Connection closed before full header was received, uri = http://127.0.0.1:4000/socket/websocket?api_token=SFMyNTY.g2gDYQFuBgBrftRcdQFiAAFRgA.E1_gPO_lHXBwZmeOoIad4QUAXB2a_8rn0VwInqncz5k&vsn=2.0.0
flutter: 2020-10-25 21:22:55.738850 INFO phoenix_socket.socket - Socket closed with reason null and code null
flutter: 2020-10-25 21:22:55.739028 FINE phoenix_socket.socket - Trigger channel exceptions on 1 channels
flutter: 2020-10-25 21:22:55.739312 FINE phoenix_socket.channel.user - Receiving error on channel
### PhoenixException: PhoenixException: socket closed
Bildschirmfoto 2020-10-25 um 21 23 01

Call stack

PhoenixSocket._sendHeartbeat (/usr/local/Caskroom/flutter/1.20.4/flutter/.pub-cache/hosted/pub.dartlang.org/phoenix_socket-0.4.3/lib/src/socket.dart:419)
<asynchronous gap> (Unknown Source:0)
PhoenixSocket.connect.<anonymous closure> (/usr/local/Caskroom/flutter/1.20.4/flutter/.pub-cache/hosted/pub.dartlang.org/phoenix_socket-0.4.3/lib/src/socket.dart:210)
_rootRun (dart:async/zone.dart:1182)
_rootRun (dart:async/zone.dart:0)
_CustomZone.run (dart:async/zone.dart:1093)
PhoenixSocket.connect (/usr/local/Caskroom/flutter/1.20.4/flutter/.pub-cache/hosted/pub.dartlang.org/phoenix_socket-0.4.3/lib/src/socket.dart:193)
<asynchronous gap> (Unknown Source:0)
PhoenixSocket._delayedReconnect (/usr/local/Caskroom/flutter/1.20.4/flutter/.pub-cache/hosted/pub.dartlang.org/phoenix_socket-0.4.3/lib/src/socket.dart:554)
<asynchronous gap> (Unknown Source:0)
PhoenixSocket._onSocketClosed (/usr/local/Caskroom/flutter/1.20.4/flutter/.pub-cache/hosted/pub.dartlang.org/phoenix_socket-0.4.3/lib/src/socket.dart:509)
PhoenixSocket._onSocketClosed (/usr/local/Caskroom/flutter/1.20.4/flutter/.pub-cache/hosted/pub.dartlang.org/phoenix_socket-0.4.3/lib/src/socket.dart:0)
_rootRun (dart:async/zone.dart:1182)
_rootRun (dart:async/zone.dart:0)
_CustomZone.run (dart:async/zone.dart:1093)
_CustomZone.bindCallback.<anonymous closure> (dart:async/zone.dart:1021)
_rootRun (dart:async/zone.dart:1182)
_rootRun (dart:async/zone.dart:0)
_CustomZone.run (dart:async/zone.dart:1093)
_CustomZone.runGuarded (dart:async/zone.dart:997)
_BufferingStreamSubscription._sendDone.sendDone (dart:async/stream_impl.dart:410)
_BufferingStreamSubscription._sendDone (dart:async/stream_impl.dart:420)
_BufferingStreamSubscription._close (dart:async/stream_impl.dart:305)
_ForwardingStream._handleDone (dart:async/stream_pipe.dart:101)
_ForwardingStreamSubscription._handleDone (dart:async/stream_pipe.dart:165)
_ForwardingStreamSubscription._handleDone (dart:async/stream_pipe.dart:0)
_rootRun (dart:async/zone.dart:1182)
_rootRun (dart:async/zone.dart:0)
_CustomZone.run (dart:async/zone.dart:1093)
_CustomZone.runGuarded (dart:async/zone.dart:997)
_BufferingStreamSubscription._sendDone.sendDone (dart:async/stream_impl.dart:410)
_BufferingStreamSubscription._sendDone (dart:async/stream_impl.dart:420)
_BufferingStreamSubscription._close (dart:async/stream_impl.dart:305)
_ForwardingStream._handleDone (dart:async/stream_pipe.dart:101)
_ForwardingStreamSubscription._handleDone (dart:async/stream_pipe.dart:165)
_ForwardingStreamSubscription._handleDone (dart:async/stream_pipe.dart:0)
_rootRun (dart:async/zone.dart:1182)
_rootRun (dart:async/zone.dart:0)
_CustomZone.run (dart:async/zone.dart:1093)
_CustomZone.runGuarded (dart:async/zone.dart:997)
_BufferingStreamSubscription._sendDone.sendDone (dart:async/stream_impl.dart:410)
_BufferingStreamSubscription._sendDone (dart:async/stream_impl.dart:420)
_BufferingStreamSubscription._close (dart:async/stream_impl.dart:305)
_SyncStreamControllerDispatch._sendDone (dart:async/stream_controller.dart:816)
_StreamController._closeUnchecked (dart:async/stream_controller.dart:671)
_StreamController.close (dart:async/stream_controller.dart:664)
_StreamController.close (dart:async/stream_controller.dart:0)
_rootRun (dart:async/zone.dart:1182)
_rootRun (dart:async/zone.dart:0)
_CustomZone.run (dart:async/zone.dart:1093)
_FutureListener.handleWhenComplete (dart:async/future_impl.dart:167)
Future._propagateToListeners.handleWhenCompleteCallback (dart:async/future_impl.dart:666)
Future._propagateToListeners (dart:async/future_impl.dart:722)
Future._completeWithValue (dart:async/future_impl.dart:529)
Future._asyncCompleteWithValue.<anonymous closure> (dart:async/future_impl.dart:567)
_rootRun (dart:async/zone.dart:1190)
_rootRun (dart:async/zone.dart:0)
_CustomZone.run (dart:async/zone.dart:1093)
_CustomZone.runGuarded (dart:async/zone.dart:997)
_CustomZone.bindCallbackGuarded.<anonymous closure> (dart:async/zone.dart:1037)
_microtaskLoop (dart:async/schedule_microtask.dart:41)
_startMicrotaskLoop (dart:async/schedule_microtask.dart:50)
_startMicrotaskLoop (dart:async/schedule_microtask.dart:0)
matehat commented 3 years ago

Ok, I’ll dig into it ASAP 

matehat commented 3 years ago

Can you retry the same scenario when using the master branch directly?

 dependencies:   
     phoenix_socket:
       git:
         url: git://github.com/matehat/phoenix-socket-dart.git
         ref: master
hamann commented 3 years ago

Thanks, that looks much better

flutter: 2020-10-26 17:38:28.850366 FINE phoenix_socket.socket - [phoenix_socket] Heartbeat completed
flutter: 2020-10-26 17:38:58.850027 FINE phoenix_socket.socket - [phoenix_socket] Heartbeat completed
flutter: 2020-10-26 17:39:17.142897 INFO phoenix_socket.socket - Socket closed with reason  and code 1005
flutter: 2020-10-26 17:39:17.143592 FINE phoenix_socket.socket - Trigger channel exceptions on 1 channels
flutter: 2020-10-26 17:39:17.144857 FINE phoenix_socket.channel.user - Receiving error on channel
### PhoenixException: PhoenixException: socket closed
flutter: 2020-10-26 17:39:17.146353 WARNING phoenix_socket.channel.user - Got error on channel
### PhoenixException: PhoenixException: socket closed
flutter: 2020-10-26 17:39:17.458004 SEVERE phoenix_socket.socket - Error on socket
### WebSocketChannelException: WebSocketChannelException: WebSocketChannelException: HttpException: Connection closed before full header was received, uri = http://127.0.0.1:4000/socket/websocket?api_token=SFMyNTY.g2gDYQFuBgBrftRcdQFiAAFRgA.E1_gPO_lHXBwZmeOoIad4QUAXB2a_8rn0VwInqncz5k&vsn=2.0.0
#0      new IOWebSocketChannel._withoutSocket.<anonymous closure>
package:web_socket_channel/io.dart:84
#1      _invokeErrorHandler (dart:async/async_error.dart:16:24)
#2      _HandleErrorStream._handleError (dart:async/stream_pipe.dart:282:9)
#3      _ForwardingStreamSubscription._handleError (dart:async/stream_pipe.dart:161:13)
#4      _rootRunBinary (dart:async/zone.dart:1214:47)
#5      _CustomZone.runBinary (dart:async/zone.dart:1107:19)
#6      _CustomZone.runBinaryGuarded (dart:async/zone.dart:1013:7)
#7      _BufferingStreamSubscription._sendError.sendError (dart:async/stream_impl.dart:376:15)
#8      _Bufferin<…>
flutter: 2020-10-26 17:39:17.458627 FINE phoenix_socket.socket - Trigger channel exceptions on 1 channels
flutter: 2020-10-26 17:39:17.458765 FINE phoenix_socket.channel.user - Receiving error on channel
### PhoenixException: WebSocketChannelException: WebSocketChannelException: HttpException: Connection closed before full header was received, uri = http://127.0.0.1:4000/socket/websocket?api_token=SFMyNTY.g2gDYQFuBgBrftRcdQFiAAFRgA.E1_gPO_lHXBwZmeOoIad4QUAXB2a_8rn0VwInqncz5k&vsn=2.0.0
flutter: 2020-10-26 17:39:17.459173 INFO phoenix_socket.socket - Socket closed with reason null and code null
flutter: 2020-10-26 17:39:17.459390 FINE phoenix_socket.socket - Trigger channel exceptions on 1 channels
flutter: 2020-10-26 17:39:17.459546 FINE phoenix_socket.channel.user - Receiving error on channel
### PhoenixException: PhoenixException: socket closed
flutter: 2020-10-26 17:39:17.460272 SEVERE phoenix_socket.socket - [phoenix_socket] Heartbeat message failed with error
### WebSocketChannelException: WebSocketChannelException: WebSocketChannelException: HttpException: Connection closed before full header was received, uri = http://127.0.0.1:4000/socket/websocket?api_token=SFMyNTY.g2gDYQFuBgBrftRcdQFiAAFRgA.E1_gPO_lHXBwZmeOoIad4QUAXB2a_8rn0VwInqncz5k&vsn=2.0.0
#0      new IOWebSocketChannel._withoutSocket.<anonymous closure>
package:web_socket_channel/io.dart:84
#1      _invokeErrorHandler (dart:async/async_error.dart:16:24)
#2      _HandleErrorStream._handleError (dart:async/stream_pipe.dart:282:9)
#3      _ForwardingStreamSubscription._handleError (dart:async/stream_pipe.dart:161:13)
#4      _rootRunBinary (dart:async/zone.dart:1214:47)
#5      _CustomZone.runBinary (dart:async/zone.dart:1107:19)
#6      _CustomZone.runBinaryGuarded (dart:async/zone.dart:1013:7)
#7      _BufferingStreamSubscription._sendError.sendError (dart:async/strea<…>
flutter: 2020-10-26 17:39:17.460733 FINE phoenix_socket.socket - Trigger channel exceptions on 1 channels
flutter: 2020-10-26 17:39:17.462510 FINE phoenix_socket.channel.user - Receiving error on channel
### PhoenixException: WebSocketChannelException: WebSocketChannelException: HttpException: Connection closed before full header was received, uri = http://127.0.0.1:4000/socket/websocket?api_token=SFMyNTY.g2gDYQFuBgBrftRcdQFiAAFRgA.E1_gPO_lHXBwZmeOoIad4QUAXB2a_8rn0VwInqncz5k&vsn=2.0.0
flutter: 2020-10-26 17:39:17.462920 INFO phoenix_socket.socket - Socket open
flutter: 2020-10-26 17:39:17.464868 WARNING phoenix_socket.push.user - Catched error for push 24
### PhoenixException: PhoenixException: socket closed
flutter: 2020-10-26 17:39:17.763120 INFO phoenix_socket.socket - Socket open
flutter: 2020-10-26 17:39:17.768263 SEVERE phoenix_socket.socket - Error on socket

This seems to continue every few hundred milliseconds until the backend is up again, so quite often

#7      _BufferingStreamSubscription._sendError.sendError (dart:async/strea<…>
flutter: 2020-10-26 17:39:45.131616 FINE phoenix_socket.socket - Trigger channel exceptions on 1 channels
flutter: 2020-10-26 17:39:45.132966 FINE phoenix_socket.channel.user - Receiving error on channel
### PhoenixException: WebSocketChannelException: WebSocketChannelException: HttpException: Connection closed before full header was received, uri = http://127.0.0.1:4000/socket/websocket?api_token=SFMyNTY.g2gDYQFuBgBrftRcdQFiAAFRgA.E1_gPO_lHXBwZmeOoIad4QUAXB2a_8rn0VwInqncz5k&vsn=2.0.0
flutter: 2020-10-26 17:39:45.134203 INFO phoenix_socket.socket - Socket open
flutter: 2020-10-26 17:39:45.134999 WARNING phoenix_socket.push.user - Catched error for push 114
### PhoenixException: PhoenixException: socket closed
flutter: 2020-10-26 17:39:45.433218 INFO phoenix_socket.socket - Socket open
flutter: 2020-10-26 17:39:45.589519 INFO phoenix_socket.socket - Socket closed with reason  and code 1005
flutter: 2020-10-26 17:39:45.589750 FINE phoenix_socket.socket - Trigger channel exceptions on 1 channels
flutter: 2020-10-26 17:39:45.589964 FINE phoenix_socket.channel.user - Receiving error on channel
### PhoenixException: PhoenixException: socket closed
flutter: 2020-10-26 17:39:45.590316 WARNING phoenix_socket.channel.user - Got error on channel
### PhoenixException: PhoenixException: socket closed
flutter: 2020-10-26 17:39:45.590855 SHOUT websocket_connection - Received error on Channel user, trying to reconnect
[VERBOSE-2:ui_dart_state.cc(177)] Unhandled Exception: PhoenixException: socket closed
[VERBOSE-2:ui_dart_state.cc(177)] Unhandled Exception: PhoenixException: socket closed
flutter: 2020-10-26 17:39:45.940097 FINE phoenix_socket.socket - [phoenix_socket] Heartbeat completed
flutter: 2020-10-26 17:39:45.940396 INFO phoenix_socket.socket - Socket open
flutter: 2020-10-26 17:40:15.943237 FINE phoenix_socket.socket - [phoenix_socket] Heartbeat completed
flutter: 2020-10-26 17:40:45.944813 FINE phoenix_socket.socket - [phoenix_socket] Heartbeat completed
flutter: 2020-10-26 17:41:15.941894 FINE phoenix_socket.socket - [phoenix_socket] Heartbeat completed
flutter: 2020-10-26 17:41:45.945788 FINE phoenix_socket.socket - [phoenix_socket] Heartbeat completed
flutter: 2020-10-26 17:42:15.940171 FINE phoenix_socket.socket - [phoenix_socket] Heartbeat completed
flutter: 2020-10-26 17:42:45.943771 FINE phoenix_socket.socket - [phoenix_socket] Heartbeat completed

Should it join the previous joined channels again? Because currently it does not.

hamann commented 3 years ago

I didn't specify the reconnectDelay as part of the socket options, so I would expect the defaults to be applied

https://github.com/matehat/phoenix-socket-dart/blob/8570a748f67c18f36db6ef43e624698dafe4fab9/lib/src/socket_options.dart#L22-L31

Am I wrong? Should we care about this in another issue?

matehat commented 3 years ago

Yes, please file another issue 🙂

Thanks again!