Bad state: StreamSink is bound to a stream

[jonasfj]

From logs:

2020-07-23 10:12:13.719 CEST
pub: Handling request: https://pub.dev/packages?q=retry
2020-07-23 10:12:16.449 CEST
dartis: Disconnected.
2020-07-23 10:12:16.449 CEST
pub.utils: HTTP GET https://search-dot-dartlang-pub.appspot.com/search?q=retry&tags=-is%3Adiscontinued&offset=0&limit=10
2020-07-23 10:12:16.541 CEST
neat_cache: Connecting to redis
2020-07-23 10:12:16.769 CEST
dartis: Connected to "redis://10.0.0.4:6379".
2020-07-23 10:12:16.971 CEST
dartis: Discarding 13 commands without replies.
2020-07-23 10:12:16.971 CEST
dartis: Disconnected.
2020-07-23 10:12:16.973 CEST
dartis: Attempted to send data after outgoing connection closed.
2020-07-23 10:12:16.973 CEST
dartis: Attempted to send data after outgoing connection closed.
2020-07-23 10:12:16.973 CEST
dartis: Attempted to send data after outgoing connection closed.
2020-07-23 10:12:16.973 CEST
dartis: Attempted to send data after outgoing connection closed.
2020-07-23 10:12:16.973 CEST
dartis: Attempted to send data after outgoing connection closed.
2020-07-23 10:12:16.973 CEST
dartis: Attempted to send data after outgoing connection closed.
2020-07-23 10:12:16.973 CEST
dartis: Attempted to send data after outgoing connection closed.
2020-07-23 10:12:16.974 CEST
dartis: Attempted to send data after outgoing connection closed.
2020-07-23 10:12:16.974 CEST
dartis: Attempted to send data after outgoing connection closed.
2020-07-23 10:12:16.974 CEST
dartis: Attempted to send data after outgoing connection closed.
2020-07-23 10:12:16.974 CEST
dartis: Disconnected.
2020-07-23 10:12:16.975 CEST
dartis: Disconnected.
2020-07-23 10:12:16.975 CEST
dartis: Disconnected.
2020-07-23 10:12:16.975 CEST
dartis: Disconnected.
2020-07-23 10:12:16.976 CEST
dartis: Disconnected.
2020-07-23 10:12:16.976 CEST
dartis: Disconnected.
2020-07-23 10:12:16.976 CEST
dartis: Disconnected.
2020-07-23 10:12:16.977 CEST
dartis: Disconnected.
2020-07-23 10:12:16.977 CEST
dartis: Disconnected.
2020-07-23 10:12:16.978 CEST
dartis: Disconnected.
2020-07-23 10:12:18.363 CEST
dartis: Disconnected.
2020-07-23 10:12:18.364 CEST
dartis: Disconnected.
2020-07-23 10:12:18.366 CEST
dartis: Disconnected.
2020-07-23 10:12:18.367 CEST
dartis: Disconnected.
2020-07-23 10:12:18.382 CEST
dartis: Disconnected.
2020-07-23 10:12:18.396 CEST
dartis: Disconnected.
2020-07-23 10:12:18.399 CEST
dartis: Disconnected.
2020-07-23 10:12:18.401 CEST
dartis: Disconnected.
2020-07-23 10:12:18.402 CEST
dartis: Disconnected.
2020-07-23 10:12:18.403 CEST
dartis: Disconnected.
2020-07-23 10:12:21.965 CEST
pub: Request handler failed

Error:
    Bad state: StreamSink is bound to a stream

Stack:
    dart:io/io_sink.dart 238:7                                    _StreamSinkImpl._controller
    dart:io/io_sink.dart 158:5                                    _StreamSinkImpl.add
    dart:io-patch/socket_patch.dart 1868:38                       _Socket.add
    package:dartis/src/client/connection.dart 101:13              Connection.send
    package:dartis/src/client/dispatcher.dart 29:17               DispatcherBase.send
    package:dartis/src/client/client.dart 199:5                   _ClientDispatcher.dispatch
    package:dartis/src/client/client.dart 171:50                  Client.run
    package:dartis/src/command/module.dart 57:20                  ModuleBase.execute
    package:dartis/src/command/module.dart 50:12                  ModuleBase.run
    package:dartis/src/command/commands.dart 1195:12              Commands.set
    package:neat_cache/src/providers/redis.dart 149:35            RedisCacheProvider.set.<fn>
    package:neat_cache/src/providers/redis.dart 115:22            RedisCacheProvider._withRedis
    package:neat_cache/src/providers/redis.dart 149:7             RedisCacheProvider.set
    package:pub_dev/shared/redis_cache.dart 287:17                _ConnectionRefreshingCacheProvider.set
    package:neat_cache/neat_cache.dart 194:30                     _Entry.set
    package:neat_cache/neat_cache.dart 178:15                     _Entry.get
    package:pub_dev/package/search_adapter.dart 87:45             SearchAdapter._getPackageView
    package:pub_dev/package/search_adapter.dart 111:50            SearchAdapter.getPackageViews.<fn>
    dart:_internal/iterable.dart 417:31                           MappedListIterable.elementAt
    dart:_internal/iterable.dart 346:26                           ListIterator.moveNext
    dart:async/future.dart 395:26                                 Future.wait
    package:pub_dev/package/search_adapter.dart 111:25            SearchAdapter.getPackageViews
    package:pub_dev/package/search_adapter.dart 121:30            SearchAdapter._loadResultForPackages
    package:pub_dev/package/search_adapter.dart 49:12             SearchAdapter.search
    package:stack_trace/src/stack_zone_specification.dart 129:26  StackZoneSpecification._registerUnaryCallback.<fn>.<fn>
    package:stack_trace/src/stack_zone_specification.dart 209:15  StackZoneSpecification._run
    package:stack_trace/src/stack_zone_specification.dart 129:14  StackZoneSpecification._registerUnaryCallback.<fn>
    dart:async/zone.dart 1192:38                                  _rootRunUnary
    dart:async/zone.dart 1085:19                                  _CustomZone.runUnary
    dart:async/future_impl.dart 141:18                            _FutureListener.handleValue
    dart:async/future_impl.dart 682:45                            Future._propagateToListeners.handleValueCallback
    dart:async/future_impl.dart 711:32                            Future._propagateToListeners
    dart:async/future_impl.dart 526:5                             Future._completeWithValue
    dart:async-patch/async_patch.dart 36:15                       _AsyncAwaitCompleter.complete
    dart:async-patch/async_patch.dart 298:13                      _completeOnAsyncReturn
    package:pub_dev/search/search_client.dart                     SearchClient.search
    package:stack_trace/src/stack_zone_specification.dart 129:26  StackZoneSpecification._registerUnaryCallback.<fn>.<fn>
    package:stack_trace/src/stack_zone_specification.dart 209:15  StackZoneSpecification._run
    package:stack_trace/src/stack_zone_specification.dart 129:14  StackZoneSpecification._registerUnaryCallback.<fn>
    dart:async/zone.dart 1192:38                                  _rootRunUnary
    dart:async/zone.dart 1085:19                                  _CustomZone.runUnary
    dart:async/future_impl.dart 141:18                            _FutureListener.handleValue
    dart:async/future_impl.dart 682:45                            Future._propagateToListeners.handleValueCallback
    dart:async/future_impl.dart 711:32                            Future._propagateToListeners
    dart:async/future_impl.dart 526:5                             Future._completeWithValue
    dart:async-patch/async_patch.dart 36:15                       _AsyncAwaitCompleter.complete
    dart:async-patch/async_patch.dart 298:13                      _completeOnAsyncReturn
    package:neat_cache/neat_cache.dart                            _Entry.get
    package:stack_trace/src/stack_zone_specification.dart 129:26  StackZoneSpecification._registerUnaryCallback.<fn>.<fn>
    package:stack_trace/src/stack_zone_specification.dart 209:15  StackZoneSpecification._run
    package:stack_trace/src/stack_zone_specification.dart 129:14  StackZoneSpecification._registerUnaryCallback.<fn>
    dart:async/zone.dart 1192:38                                  _rootRunUnary
    dart:async/zone.dart 1085:19                                  _CustomZone.runUnary
    dart:async/future_impl.dart 141:18                            _FutureListener.handleValue
    dart:async/future_impl.dart 682:45                            Future._propagateToListeners.handleValueCallback
    dart:async/future_impl.dart 711:32                            Future._propagateToListeners
    dart:async/future_impl.dart 526:5                             Future._completeWithValue
    dart:async-patch/async_patch.dart 36:15                       _AsyncAwaitCompleter.complete
    dart:async-patch/async_patch.dart 298:13                      _completeOnAsyncReturn
    package:neat_cache/neat_cache.dart                            _Entry.set
    dart:async-patch/async_patch.dart 86:61                       _asyncErrorWrapperHelper.errorCallback
    package:stack_trace/src/stack_zone_specification.dart 141:26  StackZoneSpecification._registerBinaryCallback.<fn>.<fn>
    package:stack_trace/src/stack_zone_specification.dart 209:15  StackZoneSpecification._run
    package:stack_trace/src/stack_zone_specification.dart 141:14  StackZoneSpecification._registerBinaryCallback.<fn>
    dart:async/zone.dart 1204:38                                  _rootRunBinary
    dart:async/zone.dart 1093:19                                  _CustomZone.runBinary
    dart:async/future_impl.dart 155:20                            _FutureListener.handleError
    dart:async/future_impl.dart 694:47                            Future._propagateToListeners.handleError
    dart:async/future_impl.dart 715:24                            Future._propagateToListeners
    dart:async/future_impl.dart 534:5                             Future._completeError
    dart:async-patch/async_patch.dart 43:15                       _AsyncAwaitCompleter.completeError
    package:neat_cache/src/providers/redis.dart                   RedisCacheProvider._withRedis
    package:stack_trace/src/stack_zone_specification.dart 129:26  StackZoneSpecification._registerUnaryCallback.<fn>.<fn>
    package:stack_trace/src/stack_zone_specification.dart 209:15  StackZoneSpecification._run
    package:stack_trace/src/stack_zone_specification.dart 129:14  StackZoneSpecification._registerUnaryCallback.<fn>
    dart:async/zone.dart 1192:38                                  _rootRunUnary
    dart:async/zone.dart 1085:19                                  _CustomZone.runUnary
    dart:async/future_impl.dart 141:18                            _FutureListener.handleValue
    dart:async/future_impl.dart 682:45                            Future._propagateToListeners.handleValueCallback
    dart:async/future_impl.dart 711:32                            Future._propagateToListeners
    dart:async/future_impl.dart 526:5                             Future._completeWithValue
    dart:async-patch/async_patch.dart 36:15                       _AsyncAwaitCompleter.complete
    dart:async-patch/async_patch.dart 298:13                      _completeOnAsyncReturn
    package:dartis/src/client/connection.dart                     Connection.disconnect
    package:stack_trace/src/stack_zone_specification.dart 129:26  StackZoneSpecification._registerUnaryCallback.<fn>.<fn>
    package:stack_trace/src/stack_zone_specification.dart 209:15  StackZoneSpecification._run
    package:stack_trace/src/stack_zone_specification.dart 129:14  StackZoneSpecification._registerUnaryCallback.<fn>
    dart:async/zone.dart 1192:38                                  _rootRunUnary
    dart:async/zone.dart 1085:19                                  _CustomZone.runUnary
    dart:async/future_impl.dart 141:18                            _FutureListener.handleValue
    dart:async/future_impl.dart 682:45                            Future._propagateToListeners.handleValueCallback
    dart:async/future_impl.dart 711:32                            Future._propagateToListeners
    dart:async/future_impl.dart 526:5                             Future._completeWithValue
    dart:async/future_impl.dart 556:7                             Future._asyncComplete.<fn>
    package:stack_trace/src/stack_zone_specification.dart 209:15  StackZoneSpecification._run
    package:stack_trace/src/stack_zone_specification.dart 119:48  StackZoneSpecification._registerCallback.<fn>
    dart:async/zone.dart 1184:13                                  _rootRun
    dart:async/zone.dart 1077:19                                  _CustomZone.run
    dart:async/zone.dart 979:7                                    _CustomZone.runGuarded
    dart:async/zone.dart 1019:23                                  _CustomZone.bindCallbackGuarded.<fn>
    dart:async/schedule_microtask.dart 43:21                      _microtaskLoop
    dart:async/schedule_microtask.dart 52:5                       _startMicrotaskLoop
    dart:isolate-patch/isolate_patch.dart 118:13                  _runPendingImmediateCallback
    dart:isolate-patch/timer_impl.dart 405:11                     _Timer._runTimers
    dart:isolate-patch/timer_impl.dart 429:5                      _Timer._handleMessage
    dart:isolate-patch/isolate_patch.dart 168:12                  _RawReceivePortImpl._handleMessage

[isoos]

It looks like the exceptions happened between 2020-07-23 10:12:21.974 and 2020-07-23 10:32:39.507. My suspicion is that we had a network issue, as otherwise the library behaves well (including the ~hourly regular reconnects).

While in many case it was failing in a few milliseconds, in other cases it took 30-60+ seconds until the request eventually failed. I think we should limit the operation timeouts for get, set and purge calls. There are a few things to figure out:

• Timeout for each of these requests (e.g. 200ms get, 500ms set and purge?).
• Silent or hard failures for each of these request (I think silent would be better - only logging the failures).
• Should we fall back to in-memory cache? (maybe, on a case-by-case basis? not urgent to implement)

[isoos]

I think we don't see this issue anymore.

[jonasfj]

This issue happened 3 times on October 14th.

[sigurdm]

Here is another stack trace:

Error:
    Bad state: StreamSink is bound to a stream

Stack:
    #0      _StreamSinkImpl.close (dart:io/io_sink.dart:200:7)
    #1      _Socket.close (dart:io-patch/socket_patch.dart:2335:27)
    #2      RespClient.close (package:neat_cache/src/providers/resp.dart:224:21)
    #3      RedisCacheProvider._withResp (package:neat_cache/src/providers/redis.dart:138:24)
    <asynchronous suspension>
    #4      Future.timeout.<anonymous closure> (dart:async/future_impl.dart:944:15)
    <asynchronous suspension>
    #5      _Entry.set (package:neat_cache/neat_cache.dart:194:7)
    <asynchronous suspension>
    #6      _Entry.get (package:neat_cache/neat_cache.dart:178:9)
    <asynchronous suspension>
    #7      apiPackagesHandler (package:pub_dev/frontend/handlers/custom_api.dart:145:16)
    <asynchronous suspension>
    #8      _$PubApiRouter.<anonymous closure> (package:pub_dev/frontend/handlers/pubapi.g.dart:622:26)
    <asynchronous suspension>
    #9      RouterEntry.invoke.<anonymous closure> (package:shelf_router/src/router_entry.dart:107:16)
    <asynchronous suspension>
    #10     RouterEntry.invoke (package:shelf_router/src/router_entry.dart:104:12)
    <asynchronous suspension>
    #11     Router.call (package:shelf_router/src/router.dart:184:26)
    <asynchronous suspension>
    #12     createAppHandler.<anonymous closure> (package:pub_dev/frontend/handlers.dart:69:16)
    <asynchronous suspension>
    #13     _redirectLoopDetectorWrapper.<anonymous closure> (package:pub_dev/shared/handler_helpers.dart:93:16)
    <asynchronous suspension>
    #14     _cspHeaderWrapper.<anonymous closure> (package:pub_dev/shared/handler_helpers.dart:149:16)
    <asynchronous suspension>
    #15     _userAuthWrapper.<anonymous closure>.<anonymous closure> (package:pub_dev/shared/handler_helpers.dart:245:34)
    <asynchronous suspension>
    #16     AccountBackend.withBearerToken (package:pub_dev/account/backend.dart:283:14)
    <asynchronous suspension>
    #17     _userAuthWrapper.<anonymous closure> (package:pub_dev/shared/handler_helpers.dart:244:12)
    <asynchronous suspension>
    #18     _requestContextWrapper.<anonymous closure> (package:pub_dev/shared/handler_helpers.dart:135:25)
    <asynchronous suspension>
    #19     _httpsWrapper.<anonymous closure> (package:pub_dev/shared/handler_helpers.dart:260:25)
    <asynchronous suspension>
    #20     _sanitizeRequestWrapper.<anonymous closure> (package:pub_dev/shared/handler_helpers.dart:228:12)
    <asynchronous suspension>
    #21     _logRequestWrapper.<anonymous closure> (package:pub_dev/shared/handler_helpers.dart:173:14)
    <asynchronous suspension>
    #22     handleRequest (package:shelf/shelf_io.dart:138:16)
    <asynchronous suspension>

[sigurdm]

This is still happening