New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Crashed in CBLWebSocket #2085

Closed
pasin opened this Issue Mar 3, 2018 · 5 comments

Comments

Projects
None yet
3 participants
@pasin
Contributor

pasin commented Mar 3, 2018

From @sridevi-15:

CouchbaseLiteSwift was compiled with optimization - stepping may behave oddly; variables may not be available.
* thread #16, queue = 'com.apple.NSURLSession-work', stop reason = EXC_BAD_INSTRUCTION (code=EXC_I386_INVOP, subcode=0x0)
    frame #0: 0x00000001132390c0 libdispatch.dylib`_dispatch_sync_wait + 746
    frame #1: 0x000000010f5efced CFNetwork`-[__NSCFTCPIOStreamTask cancel] + 84
  * frame #2: 0x000000010dfc8b50 CouchbaseLiteSwift`::-[CBLWebSocket checkError:](self=<unavailable>, _cmd=<unavailable>, error=domain: "NSPOSIXErrorDomain" - code: 57) at CBLWebSocket.mm:498 [opt]
    frame #3: 0x000000010dfc9259 CouchbaseLiteSwift`::__23-[CBLWebSocket receive]_block_invoke((null)=0x000000010e574170, data=<unavailable>, atEOF=NO, error=<unavailable>) at CBLWebSocket.mm:359 [opt]
    frame #4: 0x000000010f5ec064 CFNetwork`__81-[__NSCFTCPIOStreamTask readDataOfMinLength:maxLength:timeout:completionHandler:]_block_invoke + 302
    frame #5: 0x000000011322b2f7 libdispatch.dylib`_dispatch_call_block_and_release + 12
    frame #6: 0x000000011322c33d libdispatch.dylib`_dispatch_client_callout + 8
    frame #7: 0x0000000113234855 libdispatch.dylib`_dispatch_queue_serial_drain + 1162
    frame #8: 0x00000001132351ea libdispatch.dylib`_dispatch_queue_invoke + 336
    frame #9: 0x0000000113238102 libdispatch.dylib`_dispatch_root_queue_drain + 772
    frame #10: 0x0000000113237da0 libdispatch.dylib`_dispatch_worker_thread3 + 132
    frame #11: 0x00000001136f21ca libsystem_pthread.dylib`_pthread_wqthread + 1387
    frame #12: 0x00000001136f1c4d libsystem_pthread.dylib`start_wqthread + 13

I'm not sure what is causing this. Probably a the _task is released while -cancel is called?

@pasin pasin added this to the 2.0.0 milestone Mar 3, 2018

@pasin pasin added crash! bug P1: high and removed crash! labels Mar 3, 2018

@pasin

This comment has been minimized.

Contributor

pasin commented Mar 3, 2018

@sridevi-15 can you reproduce the issue, and capture all threads' stack traces with bt all at the Xcode console? Please capture client log also.

@pasin pasin self-assigned this Mar 3, 2018

@pasin

This comment has been minimized.

Contributor

pasin commented Mar 4, 2018

I was able to reproduce the issue by running a single push replicator a few times.

BT:

* thread #5, queue = 'com.apple.NSURLSession-work', stop reason = EXC_BAD_INSTRUCTION (code=EXC_I386_INVOP, subcode=0x0)
    frame #0: 0x00000001155a90c0 libdispatch.dylib`_dispatch_sync_wait + 746
    frame #1: 0x00000001146e4ced CFNetwork`-[__NSCFTCPIOStreamTask cancel] + 84
  * frame #2: 0x00000001100d369b CouchbaseLiteSwift`::-[CBLWebSocket checkError:](self=0x0000604000102c70, _cmd="checkError:", error=domain: "NSPOSIXErrorDomain" - code: 57) at CBLWebSocket.mm:498
    frame #3: 0x00000001100d214d CouchbaseLiteSwift`::__23-[CBLWebSocket receive]_block_invoke((null)=0x000000011568a170, data=0x0000000000000000, atEOF=NO, error=domain: "NSPOSIXErrorDomain" - code: 57) at CBLWebSocket.mm:359
    frame #4: 0x00000001146e1064 CFNetwork`__81-[__NSCFTCPIOStreamTask readDataOfMinLength:maxLength:timeout:completionHandler:]_block_invoke + 302
    frame #5: 0x000000011559b2f7 libdispatch.dylib`_dispatch_call_block_and_release + 12
    frame #6: 0x000000011559c33d libdispatch.dylib`_dispatch_client_callout + 8
    frame #7: 0x00000001155a4855 libdispatch.dylib`_dispatch_queue_serial_drain + 1162
    frame #8: 0x00000001155a51ea libdispatch.dylib`_dispatch_queue_invoke + 336
    frame #9: 0x00000001155a8102 libdispatch.dylib`_dispatch_root_queue_drain + 772
    frame #10: 0x00000001155a7da0 libdispatch.dylib`_dispatch_worker_thread3 + 132
    frame #11: 0x0000000115a671ca libsystem_pthread.dylib`_pthread_wqthread + 1387
    frame #12: 0x0000000115a66c4d libsystem_pthread.dylib`start_wqthread + 13
  thread #9, queue = 'WebSocket to localhost:4984 (QOS: UNSPECIFIED)'
    frame #0: 0x0000000115a277c2 libsystem_kernel.dylib`mach_msg_trap + 10
    frame #1: 0x0000000115a26cdc libsystem_kernel.dylib`mach_msg + 60
    frame #2: 0x00000001158ff0cb libsystem_notify.dylib`_notify_server_check + 130
    frame #3: 0x0000000115904723 libsystem_notify.dylib`notify_check + 170
    frame #4: 0x00000001156e2821 libsystem_c.dylib`notify_check_tz + 32
    frame #5: 0x00000001156e240c libsystem_c.dylib`tzsetwall_basic + 43
    frame #6: 0x00000001156e4365 libsystem_c.dylib`localtime_r + 41
    frame #7: 0x00000001159355c0 libsystem_trace.dylib`os_trace_blob_add_localtime + 63
    frame #8: 0x000000011593d8bd libsystem_trace.dylib`_os_log_impl_mirror_to_stderr + 263
    frame #9: 0x000000011593d47b libsystem_trace.dylib`_os_log_impl_flatten_and_send + 5193
    frame #10: 0x000000011593e528 libsystem_trace.dylib`_os_log_with_args_impl + 449
    frame #11: 0x0000000114db696f CoreFoundation`_CFLogvEx3 + 239
    frame #12: 0x0000000110a1630b Foundation`_NSLogv + 104
    frame #13: 0x0000000110a02023 Foundation`NSLog + 132
    frame #14: 0x000000011011bdcd CouchbaseLiteSwift`logCallback(domain=0x00000001105d6db0, level=kC4LogInfo, fmt="CBLWebSocket %s stream closed%s", args=0x0000700002bb0700) at CBLLog.m:46
    frame #15: 0x00000001101a9752 CouchbaseLiteSwift`litecore::LogDomain::vlog(this=0x00000001105d6db0, level=Info, objRef=0, fmt="CBLWebSocket %s stream closed%s", args=0x0000700002bb0950) at Logging.cc:261
    frame #16: 0x00000001101a988d CouchbaseLiteSwift`litecore::LogDomain::vlog(this=0x00000001105d6db0, level=Info, fmt="CBLWebSocket %s stream closed%s", args=0x0000700002bb0950) at Logging.cc:275
    frame #17: 0x00000001101fdf9f CouchbaseLiteSwift`::c4vlog(c4Domain=0x00000001105d6db0, level=kC4LogInfo, fmt="CBLWebSocket %s stream closed%s", args=0x0000700002bb0950) at c4Base.cc:356
    frame #18: 0x000000011011b5d1 CouchbaseLiteSwift`cblLog(domain=0x00000001105d6db0, level=kC4LogInfo, msg=@"CBLWebSocket %s stream closed%s") at CBLLog.m:39
    frame #19: 0x00000001100d3477 CouchbaseLiteSwift`::-[CBLWebSocket streamClosed:](self=0x0000604000102c70, _cmd="streamClosed:", isWrite=NO) at CBLWebSocket.mm:470
    frame #20: 0x00000001100d32c3 CouchbaseLiteSwift`::-[CBLWebSocket URLSession:readClosedForStreamTask:](self=0x0000604000102c70, _cmd="URLSession:readClosedForStreamTask:", session=0x00007fbb9770c0d0, task=0x00007fbb9760cea0) at CBLWebSocket.mm:461
    frame #21: 0x00000001147788df CFNetwork`__67-[NSURLSession delegate_readClosedForStreamTask:completionHandler:]_block_invoke + 34
    frame #22: 0x00000001109c222f Foundation`__NSBLOCKOPERATION_IS_CALLING_OUT_TO_A_BLOCK__ + 7
    frame #23: 0x00000001109c2091 Foundation`-[NSBlockOperation main] + 68
    frame #24: 0x00000001109c054e Foundation`-[__NSOperationInternal _start:] + 778
    frame #25: 0x000000011559c33d libdispatch.dylib`_dispatch_client_callout + 8
    frame #26: 0x00000001155a19f3 libdispatch.dylib`_dispatch_block_invoke_direct + 592
    frame #27: 0x000000011559c33d libdispatch.dylib`_dispatch_client_callout + 8
    frame #28: 0x00000001155a19f3 libdispatch.dylib`_dispatch_block_invoke_direct + 592
    frame #29: 0x00000001155a1783 libdispatch.dylib`dispatch_block_perform + 109
    frame #30: 0x00000001109bc55c Foundation`__NSOQSchedule_f + 342
    frame #31: 0x000000011559c33d libdispatch.dylib`_dispatch_client_callout + 8
    frame #32: 0x00000001155a2754 libdispatch.dylib`_dispatch_continuation_pop + 967
    frame #33: 0x00000001155a0b85 libdispatch.dylib`_dispatch_async_redirect_invoke + 780
    frame #34: 0x00000001155a8102 libdispatch.dylib`_dispatch_root_queue_drain + 772
    frame #35: 0x00000001155a7da0 libdispatch.dylib`_dispatch_worker_thread3 + 132
    frame #36: 0x0000000115a671ca libsystem_pthread.dylib`_pthread_wqthread + 1387
    frame #37: 0x0000000115a66c4d libsystem_pthread.dylib`start_wqthread + 13

Log:

2018-03-03 15:28:14.447166-0800 TestSwiftReplicator[55986:4094522] CouchbaseLite WS Info: CBLWebSocket connecting to localhost:4984...
2018-03-03 15:28:14.456311-0800 TestSwiftReplicator[55986:4094522] CouchbaseLite WS Verbose: CBLWebSocket Sent HTTP request...
2018-03-03 15:28:14.456996-0800 TestSwiftReplicator[55986:4094522] CouchbaseLite WS Verbose: Received 172 bytes of HTTP response
2018-03-03 15:28:14.457257-0800 TestSwiftReplicator[55986:4094522] CouchbaseLite WS Info: CBLWebSocket CONNECTED!
2018-03-03 15:28:14.458082-0800 TestSwiftReplicator[55986:4095019] CouchbaseLite BLIP Verbose: {BLIPIO#10}==> litecore::blip::BLIPIO ->ws:localhost:4984/db/_blipsync
2018-03-03 15:28:14.459570-0800 TestSwiftReplicator[55986:4094509] CouchbaseLite WS Verbose: >>> sending 74 bytes...
2018-03-03 15:28:14.459902-0800 TestSwiftReplicator[55986:4094508] CouchbaseLite WS Verbose:     (...sent 74 bytes)
2018-03-03 15:28:14.460297-0800 TestSwiftReplicator[55986:4095019] CouchbaseLite WS Verbose: <<< received 62 bytes [now 62 pending]
2018-03-03 15:28:14.461996-0800 TestSwiftReplicator[55986:4094509] CouchbaseLite WS Verbose: >>> sending 38 bytes...
2018-03-03 15:28:14.462505-0800 TestSwiftReplicator[55986:4095019] CouchbaseLite WS Verbose:     (...sent 38 bytes)
2018-03-03 15:28:14.462870-0800 TestSwiftReplicator[55986:4094509] CouchbaseLite WS Info: {C4SocketImpl#5}==> litecore::websocket::C4SocketImpl ws:localhost:4984/db/_blipsync
2018-03-03 15:28:14.463093-0800 TestSwiftReplicator[55986:4094509] CouchbaseLite WS Info: {C4SocketImpl#5} Requesting close with status=1000, message='(null)'
2018-03-03 15:28:14.463357-0800 TestSwiftReplicator[55986:4094509] CouchbaseLite WS Verbose: >>> sending 8 bytes...
2018-03-03 15:28:14.463715-0800 TestSwiftReplicator[55986:4095019] CouchbaseLite WS Verbose:     (...sent 8 bytes)
2018-03-03 15:28:14.463924-0800 TestSwiftReplicator[55986:4094509] CouchbaseLite WS Verbose: <<< received 4 bytes [now 4 pending]
2018-03-03 15:28:14.464314-0800 TestSwiftReplicator[55986:4095019] CouchbaseLite WS Info: {C4SocketImpl#5} Close confirmed by peer; disconnecting socket now
2018-03-03 15:28:14.464478-0800 TestSwiftReplicator[55986:4094508] CouchbaseLite WS Info: CBLWebSocket closeSocket requested
2018-03-03 15:28:14.464770-0800 TestSwiftReplicator[55986:4094508] CouchbaseLite WS Verbose: <<< received 0 bytes (EOF) [now 4 pending]
@pasin

This comment has been minimized.

Contributor

pasin commented Mar 4, 2018

From XCode, thread 5 was enqueued from Thread 9 which is the NSURLSession's delegate queue to cancel the stream task.

screenshot

@pasin

This comment has been minimized.

Contributor

pasin commented Mar 4, 2018

From the log and BT, the following happened:

  1. C4Socket requested to close the socket as the replicator is finished.
  2. Write socket and read socket were closed.
  3. Read socket somehow got ENOTCONN error after the socket was closed.
  4. Task was cancelled -> cause the crash.
@pasin

This comment has been minimized.

Contributor

pasin commented Mar 4, 2018

We have the check to ignore ENOTCONN error in -didCloseWithError: (see here) but not in checkError:.

pasin added a commit that referenced this issue Mar 4, 2018

Fix crash when canceling NSURLSession task
- The crash happened when canceling the task after read/write socket was closed.
- In -checkError:, also ignore the ENOTCONN error if there was a request socket close.
- In -readHTTPResponse, also call checkError: the same way as in -receive and -writeAndFree:. This is not directly related to the crash but make the error check going the same path.

#2085

@pasin pasin added review in progress and removed review labels Mar 4, 2018

@djpongh djpongh added the review label Mar 4, 2018

@snej snej closed this in cce5e32 Mar 5, 2018

@djpongh djpongh added the ffc label Sep 25, 2018

@djpongh djpongh modified the milestones: 2.0.0, 2.1.2 Sep 25, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment