Firebase-ios-sdk: Firestore: Updating a document results in no success or failure callback

Created on 10 Sep 2019  路  25Comments  路  Source: firebase/firebase-ios-sdk

[REQUIRED] Step 2: Describe your environment

  • Xcode version: 10.3
  • Firebase SDK version: 6.2.2
  • Firebase Component: Firestore
  • Component version: 1.3.2

[REQUIRED] Step 3: Describe the problem

When I try to update a document, I get neither a success, or a failure from firebase. I am on a corporate proxy, something is blocked both in our simulators and devices. But we cannot find out why it is blocked, without some type of error. When I connect my sim/devices to the open internet, everything works fine. The corporate network is the issue, but I need a failure to know why.

firestore closed-by-bot no-recent-activity
Source
picture btelintelo

Most helpful comment

Thanks for your logs! The relevant bit seems to be:

GrpcStream('6000015ceb50'): operation of type 2 failed

I reached out internally to see if someone knows how to circumvent this error.

picture schmidt-sebastian on 10 Sep 2019
👍3

All 25 comments

@btelintelo Sorry to hear about your trouble. We are accessing firestore.googleapis.com over HTTP/2 via SSL (port 443). We might be able to figure out what is going on if you provide us with client logs.

Please take a look here for how to enable them: https://firebase.google.com/docs/reference/swift/firebasefirestore/api/reference/Classes/Firestore#enablelogging_:

schmidt-sebastian picture schmidt-sebastian on 10 Sep 2019

One other note, android, on our same corporate network, works fine. And our corporate network is known to block apple urls.

2019-09-09 14:27:54.531563-0400 mobile[24884:6276919] [Client] Remote object proxy returned error: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated.}
2019-09-09 14:27:54.531563-0400 mobile[24884:6275667] [Client] Synchronous remote object proxy returned error: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated.}
2019-09-09 14:27:54.531735-0400 mobile[24884:6275667] [NetworkInfo] Descriptors query returned error: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated.}
2019-09-09 14:27:54.531752-0400 mobile[24884:6276919] [Client] Remote object proxy returned error: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated.}
2019-09-09 14:27:54.532504-0400 mobile[24884:6275957] [Client] Sending selectors failed with: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated.}
2019-09-09 14:27:54.532993-0400 mobile[24884:6275667] [Client] Synchronous remote object proxy returned error: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated.}
2019-09-09 14:27:54.533074-0400 mobile[24884:6276919] [Client] Remote object proxy returned error: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated.}
2019-09-09 14:27:54.533209-0400 mobile[24884:6275667] [NetworkInfo] Descriptors query returned error: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated.}
2019-09-09 14:27:54.532741-0400 mobile[24884:6275957] [Client] Sending selectors failed with: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated.}
2019-09-09 14:27:54.534505-0400 mobile[24884:6275948] 6.7.0 - [Firebase/Firestore][I-FST000001] Initializing. Current user: tlNcfA7ty4ZhHeGFBjhwbADCpzN2
2019-09-09 14:27:54.546029-0400 mobile[24884:6275957] [Client] Sending selectors failed with: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated.}
2019-09-09 14:27:54.546575-0400 mobile[24884:6275667] [Client] Synchronous remote object proxy returned error: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated.}
2019-09-09 14:27:54.546664-0400 mobile[24884:6275948] [Client] Remote object proxy returned error: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated.}
2019-09-09 14:27:54.546720-0400 mobile[24884:6275667] [NetworkInfo] Descriptors query returned error: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated.}
2019-09-09 14:27:54.566248-0400 mobile[24884:6275957] [Client] Sending selectors failed with: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated.}
2019-09-09 14:27:54.645954-0400 mobile[24884:6275948] 6.7.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction Start LevelDB: 0 changes (0 bytes):>
2019-09-09 14:27:54.680386-0400 mobile[24884:6275957] 6.7.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction Start MutationQueue: 0 changes (0 bytes):>
2019-09-09 14:27:54.680529-0400 mobile[24884:6275957] 6.7.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2019-09-09 14:27:54.730384-0400 mobile[24884:6275957] 6.7.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2019-09-09 14:27:54.745849-0400 mobile[24884:6275957] 6.7.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2019-09-09 14:27:54.746111-0400 mobile[24884:6275957] 6.7.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2019-09-09 14:27:54.746613-0400 mobile[24884:6275957] 6.7.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2019-09-09 14:27:54.781085-0400 mobile[24884:6275957] 6.7.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2019-09-09 14:27:54.781345-0400 mobile[24884:6275957] 6.7.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2019-09-09 14:27:54.781472-0400 mobile[24884:6275957] 6.7.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2019-09-09 14:27:54.781600-0400 mobile[24884:6275957] 6.7.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2019-09-09 14:27:54.781783-0400 mobile[24884:6275957] 6.7.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2019-09-09 14:27:54.781913-0400 mobile[24884:6275957] 6.7.0 - [Firebase/Firestore][I-FST000001] WriteStream (7fc55885f1b0) start
2019-09-09 14:27:54.782165-0400 mobile[24884:6275957] 6.7.0 - [Firebase/Auth][I-AUT000002] Token auto-refresh enabled.
2019-09-09 14:27:54.783169-0400 mobile[24884:6275957] 6.7.0 - [Firebase/Auth][I-AUT000004] Token auto-refresh scheduled in 28:42 for the new token.
2019-09-09 14:27:54.783590-0400 mobile[24884:6275957] 6.7.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction Locally write mutations: 3 changes (305 bytes):
  - Put [collection_parent: collection_id=esbg_shopping_sessions] (0 bytes)
  - Put [document_mutation: user_id=tlNcfA7ty4ZhHeGFBjhwbADCpzN2 path=esbg_shopping_sessions/40LJLu1XnSUeZWxy3bPU batch_id=12] (0 bytes)
  - Put [mutation: user_id=tlNcfA7ty4ZhHeGFBjhwbADCpzN2 batch_id=12] (305 bytes)>
2019-09-09 14:27:54.783795-0400 mobile[24884:6275957] 6.7.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NotifyLocalViewChanges: 0 changes (0 bytes):>
2019-09-09 14:27:54.784013-0400 mobile[24884:6275957] 6.7.0 - [Firebase/Firestore][I-FST000001] Creating Firestore stub.
2019-09-09 14:27:54.784094-0400 mobile[24884:6275957] 6.7.0 - [Firebase/Firestore][I-FST000001] roots.pem found in bundle org.cocoapods.gRPCCertificates-Cpp (in parent org.cocoapods.grpcpp)
2019-09-09 14:27:54.880686-0400 mobile[24884:6275957] 6.7.0 - [Firebase/Firestore][I-FST000001] WriteStream (7fc55885f1b0) initial request: <GCFSWriteRequest 0x60000090d980>: {
    database: "projects/kr-5365-esbg-t/databases/(default)"
}
2019-09-09 14:28:10.358439-0400 mobile[24884:6275949] TIC Read Status [6:0x6000012d0cc0]: 1:57
2019-09-09 14:28:10.358611-0400 mobile[24884:6275949] TIC Read Status [6:0x6000012d0cc0]: 1:57
2019-09-09 14:28:10.365108-0400 mobile[24884:6275949] [BoringSSL] nw_protocol_boringssl_get_output_frames(1301) [C6.1:4][0x7fc5527534e0] get output frames failed, state 8196
2019-09-09 14:28:10.365290-0400 mobile[24884:6275949] [BoringSSL] nw_protocol_boringssl_get_output_frames(1301) [C6.1:4][0x7fc5527534e0] get output frames failed, state 8196
2019-09-09 14:28:10.365723-0400 mobile[24884:6275949] TIC Read Status [6:0x0]: 1:57
2019-09-09 14:28:10.365826-0400 mobile[24884:6275949] TIC Read Status [6:0x0]: 1:57
2019-09-09 14:28:10.365917-0400 mobile[24884:6275949] TIC Read Status [6:0x0]: 1:57
2019-09-09 14:28:30.298282-0400 mobile[24884:6278098] Task <279D6460-B4F5-4D2C-AE5B-05CE19EDDA60>.<1> finished with error - code: -999
2019-09-09 14:28:30.298895-0400 mobile[24884:6278040] Task <279D6460-B4F5-4D2C-AE5B-05CE19EDDA60>.<1> HTTP load failed (error code: -999 [1:89])
2019-09-09 14:28:58.580837-0400 mobile[24884:6278491] 6.7.0 - [Firebase/Firestore][I-FST000001] Garbage collection skipped; Cache size 7606 is lower than threshold 104857600
2019-09-09 14:28:58.581139-0400 mobile[24884:6278491] 6.7.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction Collect garbage: 0 changes (0 bytes):>

INFO    Communications [DTXCertManager.m:316-80911-30] default certificate handling2019-09-09 14:30:54.817248-0400 mobile[24884:6281327] 6.7.0 - [Firebase/Firestore][I-FST000001] GrpcStream('6000015ceb50'): operation of type 2 failed
2019-09-09 14:30:54.817540-0400 mobile[24884:6281327] 6.7.0 - [Firebase/Firestore][I-FST000001] GrpcStream('6000015ceb50'): finishing the underlying call
2019-09-09 14:30:54.817630-0400 mobile[24884:6281327] 6.7.0 - [Firebase/Firestore][I-FST000001] GrpcStream('6000015ceb50'): fast finishing 1 completion(s)
2019-09-09 14:30:54.818296-0400 mobile[24884:6281327] 6.7.0 - [Firebase/Firestore][I-FST000001] GrpcStream('6000015ceb50'): finishing and notifying observers
2019-09-09 14:30:54.819018-0400 mobile[24884:6281327] 6.7.0 - [Firebase/Firestore][I-FST000001] GrpcStream('6000015ceb50'): shutting down; completions: 0, is finished: true
2019-09-09 14:30:54.819095-0400 mobile[24884:6281327] 6.7.0 - [Firebase/Firestore][I-FST000001] GrpcStream('6000015ceb50'): fast finishing 0 completion(s)
2019-09-09 14:30:54.819157-0400 mobile[24884:6281327] 6.7.0 - [Firebase/Firestore][I-FST000001] WriteStream (7fc55885f1b0) Stream error
2019-09-09 14:30:54.819204-0400 mobile[24884:6281327] 6.7.0 - [Firebase/Firestore][I-FST000001] GrpcStream('6000015ceb50'): destroying stream
2019-09-09 14:30:54.819968-0400 mobile[24884:6281327] 6.7.0 - [Firebase/Firestore][I-FST000001] WriteStream (7fc55885f1b0) backoff
2019-09-09 14:30:54.831870-0400 mobile[24884:6281327] 6.7.0 - [Firebase/Firestore][I-FST000001] WriteStream (7fc55885f1b0) start
2019-09-09 14:30:54.831958-0400 mobile[24884:6281327] 6.7.0 - [Firebase/Firestore][I-FST000001] WriteStream (7fc55885f1b0) initial request: <GCFSWriteRequest 0x6000009b1180>: {
    database: "projects/kr-5365-esbg-t/databases/(default)"
}
2019-09-09 14:31:30.272502-0400 mobile[24884:6282544] [BoringSSL] nw_protocol_boringssl_get_output_frames(1301) [C10.1:4][0x7fc5525a0c00] get output frames failed, state 8196
2019-09-09 14:31:30.272694-0400 mobile[24884:6282544] [BoringSSL] nw_protocol_boringssl_get_output_frames(1301) [C10.1:4][0x7fc5525a0c00] get output frames failed, state 8196
2019-09-09 14:31:30.273199-0400 mobile[24884:6282544] TIC Read Status [10:0x0]: 1:57
2019-09-09 14:31:30.273304-0400 mobile[24884:6282544] TIC Read Status [10:0x0]: 1:57

INFO    Communications [DTXCertManager.m:316-78611-33] default certificate handling2019-09-09 14:32:00.167014-0400 mobile[24884:6283323] [BoringSSL] nw_protocol_boringssl_get_output_frames(1301) [C43.1:4][0x7fc5527da4a0] get output frames failed, state 8196
2019-09-09 14:32:00.167193-0400 mobile[24884:6283323] [BoringSSL] nw_protocol_boringssl_get_output_frames(1301) [C43.1:4][0x7fc5527da4a0] get output frames failed, state 8196
2019-09-09 14:32:00.167530-0400 mobile[24884:6283323] TIC Read Status [43:0x0]: 1:57
2019-09-09 14:32:00.167614-0400 mobile[24884:6283323] TIC Read Status [43:0x0]: 1:57
btelintelo picture btelintelo on 10 Sep 2019

Thanks for your logs! The relevant bit seems to be:

GrpcStream('6000015ceb50'): operation of type 2 failed

I reached out internally to see if someone knows how to circumvent this error.

schmidt-sebastian picture schmidt-sebastian on 10 Sep 2019
👍3

hello @schmidt-sebastian
Same problem from last 3 days

  • Xcode version: 10.3
  • Firebase SDK version: 5.20.1
  • Firebase Component: Firestore

after successful login update and delete data works fine up to half hour.
after that same problem occurred, completion block not calling while updating data.
also logout not working.

can u help me for this.
i have to update pod for resolved problem?

jeky1990 picture jeky1990 on 11 Sep 2019

For what it is worth, the error is thrown here: https://github.com/firebase/firebase-ios-sdk/blob/03130acf377e8b59e00244dbf1d479edd25e4a1e/Firestore/core/src/firebase/firestore/remote/grpc_stream.cc#L339

schmidt-sebastian picture schmidt-sebastian on 11 Sep 2019

Thank you @schmidt-sebastian for letting us know. I work with @btelintelo on this team and currently facilitating resolving this issue. Do we know a what a type 2 operation is? Was there any more update from the internal team?

sampadakadam picture sampadakadam on 11 Sep 2019

Unfortunately, the log message is not very helpful. A type 2 operation is a write.

schmidt-sebastian picture schmidt-sebastian on 11 Sep 2019

Ah, got it. Is there anything else we can do to provide more debuggable information?

sampadakadam picture sampadakadam on 11 Sep 2019

@sampadakadam From the log, it looks like the write is failing with a "retriable" error, so the stream would attempt to do the write again, after a short backoff. While the stream is retrying, it will not trigger the user callback, which is the behavior you're seeing.

To get to the root cause of the issue, it's necessary to figure out why the write is failing. Unfortunately, the underlying error is missing from the logs. Can you please enable gRPC debug logging, reproduce the issue, and attach the new logs? You would need to define two environment variables like this (see here on how to add an environment variable in XCode):

GRPC_TRACE=tcp,http,call_error
GRPC_VERBOSITY=debug

Here's the gRPC documentation on the topic if you're interested, but the above environment variables should be sufficient. With gRPC logging enabled, the logs should capture the underlying error.

We will make sure the error is captured in our logs, so that enabling gRPC logging would become unnecessary in a future release. Sorry about the inconvenience!

var-const picture var-const on 11 Sep 2019
👍2

Thank you so much. We will get back to you soon.

sampadakadam picture sampadakadam on 11 Sep 2019

@var-const
2019-09-12 11:44:59.873536+0530 Line[370:19210] TIC Read Status [9:0x282e57240]: 1:57
2019-09-12 11:44:59.873786+0530 Line[370:19210] TIC Read Status [9:0x282e57240]: 1:57
2019-09-12 11:44:59.873879+0530 Line[370:19210] TIC Read Status [9:0x282e57240]: 1:57
2019-09-12 11:44:59.887883+0530 Line[370:19210] [BoringSSL] nw_protocol_boringssl_get_output_frames(1301) [C9.1:2][0x1113a0260] get output frames failed, state 8196
2019-09-12 11:44:59.889846+0530 Line[370:19210] [BoringSSL] nw_protocol_boringssl_get_output_frames(1301) [C9.1:2][0x1113a0260] get output frames failed, state 8196
2019-09-12 11:44:59.893466+0530 Line[370:19210] TIC Read Status [9:0x0]: 1:57
2019-09-12 11:44:59.893808+0530 Line[370:19210] TIC Read Status [9:0x0]: 1:57
2019-09-12 11:44:59.894477+0530 Line[370:19210] TIC Read Status [9:0x0]: 1:57
2019-09-12 11:44:59.894612+0530 Line[370:19210] TIC Read Status [9:0x0]: 1:57
2019-09-12 11:45:02.065266+0530 Line[370:19650] [BoringSSL] nw_protocol_boringssl_get_output_frames(1301) [C22.1:2][0x10d6eb110] get output frames failed, state 8196
2019-09-12 11:45:02.070814+0530 Line[370:19650] [BoringSSL] nw_protocol_boringssl_get_output_frames(1301) [C22.1:2][0x10d6eb110] get output frames failed, state 8196
2019-09-12 11:45:02.071634+0530 Line[370:19650] TIC Read Status [22:0x0]: 1:57
2019-09-12 11:45:02.071698+0530 Line[370:19650] TIC Read Status [22:0x0]: 1:57
2019-09-12 11:45:02.082804+0530 Line[370:19652] 5.20.0 - [Firebase/Auth][I-AUT000003] Token auto-refresh re-scheduled in 04:00 because of error on previous refresh attempt.
2019-09-12 11:45:16.510681+0530 Line[370:19739] 5.20.0 - [Firebase/Firestore][I-FST000001] WriteStream (111397ec8) start
2019-09-12 11:45:17.552969+0530 Line[370:19739] 5.20.0 - [Firebase/Firestore][I-FST000001] WriteStream (111397ec8) Stream error: 'Unknown: An internal error has occurred, print and inspect the error details for more information.'
2019-09-12 11:45:17.554947+0530 Line[370:19741] [BoringSSL] nw_protocol_boringssl_get_output_frames(1301) [C23.1:2][0x11139b540] get output frames failed, state 8196
2019-09-12 11:45:17.558440+0530 Line[370:19741] [BoringSSL] nw_protocol_boringssl_get_output_frames(1301) [C23.1:2][0x11139b540] get output frames failed, state 8196
2019-09-12 11:45:17.559865+0530 Line[370:19741] TIC Read Status [23:0x0]: 1:57
2019-09-12 11:45:17.560004+0530 Line[370:19741] TIC Read Status [23:0x0]: 1:57
2019-09-12 11:45:17.561532+0530 Line[370:19739] 5.20.0 - [Firebase/Firestore][I-FST000001] WriteStream (111397ec8) backoff
2019-09-12 11:45:17.561659+0530 Line[370:19739] 5.20.0 - [Firebase/Firestore][I-FST000001] Backing off for 42602 ms (base delay: 60000 ms, delay with jitter: 43657 ms, last attempt: 1055 ms ago)
2019-09-12 11:46:04.370794+0530 Line[370:19738] 5.20.0 - [Firebase/Firestore][I-FST000001] WriteStream (111397ec8) start
2019-09-12 11:46:05.064958+0530 Line[370:19807] [BoringSSL] nw_protocol_boringssl_get_output_frames(1301) [C24.1:2][0x11139e320] get output frames failed, state 8196
2019-09-12 11:46:05.073993+0530 Line[370:19807] [BoringSSL] nw_protocol_boringssl_get_output_frames(1301) [C24.1:2][0x11139e320] get output frames failed, state 8196
2019-09-12 11:46:05.075347+0530 Line[370:19807] TIC Read Status [24:0x0]: 1:57
2019-09-12 11:46:05.075425+0530 Line[370:19807] TIC Read Status [24:0x0]: 1:57
2019-09-12 11:46:05.118343+0530 Line[370:19738] 5.20.0 - [Firebase/Firestore][I-FST000001] WriteStream (111397ec8) Stream error: 'Unknown: An internal error has occurred, print and inspect the error details for more information.'
2019-09-12 11:46:05.118471+0530 Line[370:19738] 5.20.0 - [Firebase/Firestore][I-FST000001] WriteStream (111397ec8) backoff
2019-09-12 11:46:05.118577+0530 Line[370:19738] 5.20.0 - [Firebase/Firestore][I-FST000001] Backing off for 65941 ms (base delay: 60000 ms, delay with jitter: 66645 ms, last attempt: 704 ms ago)

jeky1990 picture jeky1990 on 12 Sep 2019

@var-const Here's the output with the envvars added.

D0912 08:50:48.280969000 123145567051776 ev_posix.cc:174] Using polling engine: poll D0912 08:50:48.285112000 123145567051776 dns_resolver.cc:289] Using native dns resolver D0912 08:50:48.317664000 123145567051776 dns_resolver.cc:242] Start resolving. I0912 08:50:48.768037000 123145564905472 socket_utils_common_posix.cc:319] TCP_USER_TIMEOUT not supported for this platform I0912 08:50:48.768396000 123145564905472 tcp_client_posix.cc:332] CLIENT_CONNECT: ipv4:172.217.7.138:443: asynchronously connecting fd 0x60000099b3a0 I0912 08:51:08.372952000 123145569734656 tcp_client_posix.cc:113] CLIENT_CONNECT: ipv4:172.217.7.138:443: on_alarm: error="No Error" I0912 08:51:08.373831000 123145569734656 tcp_client_posix.cc:150] CLIENT_CONNECT: ipv4:172.217.7.138:443: on_writable: error={"created":"@1568292668.373190000","description":"FD shutdown","file":"/SomePathToOurApp/AppName/Pods/gRPC-Core/src/core/lib/iomgr/ev_poll_posix.cc","file_line":481,"grpc_status":14,"referenced_errors":[{"created":"@1568292668.373065000","description":"connect() timed out","file":"/SomePathToOurApp/AppName/Pods/gRPC-Core/src/core/lib/iomgr/tcp_client_posix.cc","file_line":119}]} I0912 08:51:08.375898000 123145569734656 subchannel.cc:926] Connect failed: {"created":"@1568292668.373190000","description":"Failed to connect to remote host: FD shutdown","file":"/SomePathToOurApp/AppName/Pods/gRPC-Core/src/core/lib/iomgr/ev_poll_posix.cc","file_line":481,"grpc_status":14,"os_error":"Timeout occurred","referenced_errors":[{"created":"@1568292668.373065000","description":"connect() timed out","file":"/SomePathToOurApp/AppName/Pods/gRPC-Core/src/core/lib/iomgr/tcp_client_posix.cc","file_line":119}],"target_address":"ipv4:172.217.7.138:443"} I0912 08:51:08.381898000 123145569734656 socket_utils_common_posix.cc:319] TCP_USER_TIMEOUT not supported for this platform I0912 08:51:08.385599000 123145569734656 tcp_client_posix.cc:332] CLIENT_CONNECT: ipv4:172.217.164.138:443: asynchronously connecting fd 0x60000099fc60 2019-09-12 08:51:20.362835-0400 mobile[2614:22681] TIC Read Status [6:0x600000588f00]: 1:57 2019-09-12 08:51:20.362977-0400 mobile[2614:22681] TIC Read Status [6:0x600000588f00]: 1:57 2019-09-12 08:51:20.369851-0400 mobile[2614:22681] [BoringSSL] nw_protocol_boringssl_get_output_frames(1301) [C6.1:4][0x7f9f1a419e20] get output frames failed, state 8196 2019-09-12 08:51:20.370069-0400 mobile[2614:22681] [BoringSSL] nw_protocol_boringssl_get_output_frames(1301) [C6.1:4][0x7f9f1a419e20] get output frames failed, state 8196 2019-09-12 08:51:20.370621-0400 mobile[2614:22681] TIC Read Status [6:0x0]: 1:57 2019-09-12 08:51:20.370726-0400 mobile[2614:22681] TIC Read Status [6:0x0]: 1:57 2019-09-12 08:51:20.370830-0400 mobile[2614:22681] TIC Read Status [6:0x0]: 1:57 I0912 08:51:28.372836000 123145562759168 tcp_client_posix.cc:113] CLIENT_CONNECT: ipv4:172.217.164.138:443: on_alarm: error="No Error" I0912 08:51:28.373135000 123145562759168 tcp_client_posix.cc:150] CLIENT_CONNECT: ipv4:172.217.164.138:443: on_writable: error={"created":"@1568292688.373083000","description":"FD shutdown","file":"/SomePathToOurApp/AppName/Pods/gRPC-Core/src/core/lib/iomgr/ev_poll_posix.cc","file_line":481,"grpc_status":14,"referenced_errors":[{"created":"@1568292688.372985000","description":"connect() timed out","file":"/SomePathToOurApp/AppName/Pods/gRPC-Core/src/core/lib/iomgr/tcp_client_posix.cc","file_line":119}]} I0912 08:51:28.373318000 123145562759168 subchannel.cc:926] Connect failed: {"created":"@1568292688.373083000","description":"Failed to connect to remote host: FD shutdown","file":"/SomePathToOurApp/AppName/Pods/gRPC-Core/src/core/lib/iomgr/ev_poll_posix.cc","file_line":481,"grpc_status":14,"os_error":"Timeout occurred","referenced_errors":[{"created":"@1568292688.372985000","description":"connect() timed out","file":"/SomePathToOurApp/AppName/Pods/gRPC-Core/src/core/lib/iomgr/tcp_client_posix.cc","file_line":119}],"target_address":"ipv4:172.217.164.138:443"} I0912 08:51:28.373565000 123145562759168 socket_utils_common_posix.cc:319] TCP_USER_TIMEOUT not supported for this platform I0912 08:51:28.373790000 123145562759168 tcp_client_posix.cc:332] CLIENT_CONNECT: ipv4:172.217.13.74:443: asynchronously connecting fd 0x600000906a00

crewshin picture crewshin on 12 Sep 2019
👍1

@var-const @crewshin has updated the logs.

sampadakadam picture sampadakadam on 12 Sep 2019

@var-const
this is wright way to declare
Screenshot 2019-09-13 at 10 53 53 AM
environmental variable

jeky1990 picture jeky1990 on 13 Sep 2019

@var-const
which value i have to set for debug
because after one hour my app is lost connection to firestore.

jeky1990 picture jeky1990 on 13 Sep 2019

@jeky1990 You are having a separate issue. Please create your own thread. Thanks.

crewshin picture crewshin on 13 Sep 2019
👍1

@schmidt-sebastian @var-const Were we able to find debug information from the logs that @crewshin had shared?

sampadakadam picture sampadakadam on 16 Sep 2019

Unfortunately, we don't have a good lead yet. I see two connection attempts in your logs that each time out after 20 seconds. There is one interesting bit ("Failed to connect to remote host: FD shutdown"), but it is not immediately obvious whether this is the result of your connection problem or the reason for it.

For network connectivity issues, we usually ask for a reproduction. Since you mentioned that this only reproduces with your specific network, this will likely not help us solve this issue. For now, I suggest filing an issue with GRPC (https://github.com/grpc/grpc/issue). Regardless, we will let you know if we find a way to help.

schmidt-sebastian picture schmidt-sebastian on 17 Sep 2019
👍1

Opened https://github.com/grpc/grpc/issues/20276

btelintelo picture btelintelo on 17 Sep 2019

Note that this issue bears some resemblance to https://github.com/firebase/firebase-ios-sdk/issues/3763 where the issue was related to API key settings. Can you visit https://console.cloud.google.com/apis/credentials for your project and check the settings for the "iOS key (auto created by Google Service)" entry?

The default is to have "None" and "Don't Restrict Key" checked under "Application Restrictions" and "API restrictions" respectively. If you've changed that, can you try changing it back?

Other avenues of investigation:

  1. Create a brand new project and see if the problem still reproduces (this would definitively rule out project configuration issues).
  2. Use the FirebaseAuth API to directly perform a sign-in and then perform a token refresh by using the getIDTokenResultFolcingRefresh API, passing YES for forcingRefresh. This is essentially what Firestore is trying to do which is failing, so I would expect that it fails for you as well. You can check if there are any additional useful details in the error returned.
mikelehen picture mikelehen on 17 Sep 2019

@mikelehen I see your point there. Is the network call in point 2, network dependent? If yes, could you tell us the url that is hitting and we can try unblocking it?

Also if android-sdk is doing the same, how is it that android emulators able to connect to it behind corporate proxy? It's a baffling issue.

sampadakadam picture sampadakadam on 17 Sep 2019

@sampadakadam I believe the URL will be something like https://securetoken.googleapis.com/v1/token but I'm not 100% sure.

Regarding Android, I'm not sure why it works but not iOS, but if this _is_ related to API restrictions in https://console.cloud.google.com/apis/credentials it's worth noting that your project will have a separate "iOS key" and "Android key" and you may have them configured differently. That could explain the difference. Else, Android and iOS use very different implementations of gRPC so there could be a subtle difference between the requests (headers included, etc.) which your network is interfering with differently. But like I said, I'm not at all sure.

mikelehen picture mikelehen on 17 Sep 2019

I'm marking this needs-info since we have no way to reproduce this. To move forward it would be helpful to answer the questions in https://github.com/firebase/firebase-ios-sdk/issues/3817#issuecomment-532292401.

mikelehen picture mikelehen on 7 Nov 2019


Hey @btelintelo. We need more information to resolve this issue but there hasn't been an update in 7 days. I'm marking the issue as stale and if there are no new updates in the next 3 days I will close it automatically.

If you have more information that will help us get to the bottom of this, just add a comment!

google-oss-bot picture google-oss-bot on 15 Nov 2019


Since there haven't been any recent updates here, I am going to close this issue.

@btelintelo if you're still experiencing this problem and want to continue the discussion just leave a comment here and we are happy to re-open this.

google-oss-bot picture google-oss-bot on 19 Nov 2019
Was this page helpful?
0 / 5 - 0 ratings

Related issues

josemssilva picture josemssilva  路  4Comments
aschuch picture aschuch  路  3Comments
henrymoulton picture henrymoulton  路  3Comments
WillLewis picture WillLewis  路  4Comments
subdan picture subdan  路  3Comments