Firestore transaction fails after long delay when wifi network is changed in background

[Gagnant]

[REQUIRED] Step 1: Describe your environment

• Xcode version: 11.3 (11C29)
• Firebase SDK version: 6.9.0
• Firebase Component: Firestore
• Component version: 6.9.0
• Installation method: Carthage

[REQUIRED] Step 2: Describe the problem

After changing a wifi network in the background and then executing firestore transaction in the foreground, it fails after a noticeable delay of ~20 seconds. After that, transactions are executed as regular.

Steps to reproduce:

1. Move the app to the background.
2. Change wifi network.
3. Return to the application (move to foreground).
4. Execute firestore transaction.

Observed Results:

The first transaction fails with a timeout error after ~20 seconds. After that, transactions are executed as regular.

Expected Results:

Transaction succeeds after a short delay.

Relevant Code:

2020-02-13 17:07:18.547536+0200 xxx [1317:296953] dnssd_clientstub read_all(7) DEFUNCT
2020-02-13 17:07:18.913236+0200 xxx [1317:298728] 6.9.0 - [Firebase/Analytics][I-ACS033003] Scheduling user engagement timer
2020-02-13 17:07:18.913635+0200 xxx [1317:298728] 6.9.0 - [Firebase/Analytics][I-ACS002002] Engagement timer scheduled to fire in approx. (s): 3600
2020-02-13 17:07:23.475445+0200 xxx [1317:298326] Change device property transaction started!
2020-02-13 17:07:41.729386+0200 xxx [1317:297210] dnssd_clientstub write_all(20) DEFUNCT
2020-02-13 17:07:41.729653+0200 xxx [1317:297210] dnssd_clientstub deliver_request ERROR: write_all(20, 65 bytes) failed
2020-02-13 17:07:41.729892+0200 xxx [1317:297210] dnssd_clientstub write_all(20) DEFUNCT
2020-02-13 17:07:41.731598+0200 xxx [1317:298326] Change device property transaction failed!
2020-02-13 17:07:41.734143+0200 xxx [1317:298325] 6.9.0 - [Firebase/Firestore][I-FST000001] GrpcStream('282517330'): operation of type 1 failed
2020-02-13 17:07:41.734526+0200 xxx [1317:298325] 6.9.0 - [Firebase/Firestore][I-FST000001] GrpcStream('282517330'): finishing the underlying call
2020-02-13 17:07:41.735600+0200 xxx [1317:298325] 6.9.0 - [Firebase/Firestore][I-FST000001] GrpcStream('282517330'): fast finishing 0 completion(s)
2020-02-13 17:07:41.736226+0200 xxx [1317:298325] 6.9.0 - [Firebase/Firestore][I-FST000001] GrpcStream('282507a80'): operation of type 1 failed
2020-02-13 17:07:41.736332+0200 xxx [1317:298325] 6.9.0 - [Firebase/Firestore][I-FST000001] GrpcStream('282507a80'): finishing the underlying call
2020-02-13 17:07:41.736616+0200 xxx [1317:298325] 6.9.0 - [Firebase/Firestore][I-FST000001] GrpcStream('282507a80'): fast finishing 0 completion(s)
2020-02-13 17:07:41.737334+0200 xxx [1317:298325] 6.9.0 - [Firebase/Firestore][I-FST000001] GrpcStream('282517330'): finishing and notifying observers
2020-02-13 17:07:41.737646+0200 xxx [1317:298325] 6.9.0 - [Firebase/Firestore][I-FST000001] GrpcStream('282517330'): shutting down; completions: 0, is finished: true
2020-02-13 17:07:41.738134+0200 xxx [1317:298325] 6.9.0 - [Firebase/Firestore][I-FST000001] GrpcStream('282517330'): fast finishing 0 completion(s)
2020-02-13 17:07:41.738465+0200 xxx [1317:298325] 6.9.0 - [Firebase/Firestore][I-FST000001] WatchStream (135f065e8) Stream error: 'Unavailable: Operation timed out'
2020-02-13 17:07:41.738927+0200 xxx [1317:298325] 6.9.0 - [Firebase/Firestore][I-FST000001] GrpcStream('282517330'): destroying stream
2020-02-13 17:07:41.739487+0200 xxx [1317:298325] 6.9.0 - [Firebase/Firestore][I-FST000001] WatchStream (135f065e8) backoff
2020-02-13 17:07:41.739712+0200 xxx [1317:298325] 6.9.0 - [Firebase/Firestore][I-FST000001] GrpcStream('282507a80'): finishing and notifying observers
2020-02-13 17:07:41.739985+0200 xxx [1317:298325] 6.9.0 - [Firebase/Firestore][I-FST000001] GrpcStream('282507a80'): shutting down; completions: 0, is finished: true
2020-02-13 17:07:41.740589+0200 xxx [1317:298325] 6.9.0 - [Firebase/Firestore][I-FST000001] GrpcStream('282507a80'): fast finishing 0 completion(s)
2020-02-13 17:07:41.740759+0200 xxx [1317:298325] 6.9.0 - [Firebase/Firestore][I-FST000001] RPC BatchGetDocuments completed. Error: 14: Operation timed out
2020-02-13 17:07:41.740922+0200 xxx [1317:298325] 6.9.0 - [Firebase/Firestore][I-FST000001] RPC BatchGetDocuments returned headers (whitelisted):
2020-02-13 17:07:41.741095+0200 xxx [1317:298325] 6.9.0 - [Firebase/Firestore][I-FST000001] GrpcStream('282507a80'): destroying stream
2020-02-13 17:07:41.741454+0200 xxx [1317:298325] 6.9.0 - [Firebase/Firestore][I-FST000001] WatchStream (135f065e8) start

[rizafran]

Hi @Gagnant, looks like you're using an older version of Firebase SDK. Could you please try updating it to the latest version and let me know if you'd still encounter the issue?

[Gagnant]

Hi @rizafran ,
updated to latest version but the problem still persists.

2020-02-14 16:39:09.094207+0200 xxx[2456:649748] 6.17.0 - [Firebase/Analytics][I-ACS002002] Engagement timer scheduled to fire in approx. (s): 3600
2020-02-14 16:39:10.675161+0200 xxx[2456:649630] Transaction started!
2020-02-14 16:39:26.763682+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d6f9f0'): operation of type 1 failed
2020-02-14 16:39:26.763791+0200 xxx[2456:649651] dnssd_clientstub write_all(24) DEFUNCT
2020-02-14 16:39:26.764042+0200 xxx[2456:649651] dnssd_clientstub deliver_request ERROR: write_all(24, 65 bytes) failed
2020-02-14 16:39:26.764178+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d6f9f0'): finishing the underlying call
2020-02-14 16:39:26.764228+0200 xxx[2456:649651] dnssd_clientstub write_all(24) DEFUNCT
2020-02-14 16:39:26.766823+0200 xxx[2456:649630] Transaction failed!
2020-02-14 16:39:26.766976+0200 xxx[2456:649634] Transaction failed!
2020-02-14 16:39:26.769450+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d6f9f0'): fast finishing 0 completion(s)
2020-02-14 16:39:26.770585+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d42640'): operation of type 1 failed
2020-02-14 16:39:26.771627+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d42640'): finishing the underlying call
2020-02-14 16:39:26.771941+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d42640'): fast finishing 0 completion(s)
2020-02-14 16:39:26.772051+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d7c6c0'): operation of type 1 failed
2020-02-14 16:39:26.774015+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d7c6c0'): finishing the underlying call
2020-02-14 16:39:26.774131+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d7c6c0'): fast finishing 0 completion(s)
2020-02-14 16:39:26.774806+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d6f9f0'): finishing and notifying observers
2020-02-14 16:39:26.775181+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d6f9f0'): shutting down; completions: 0, is finished: true
2020-02-14 16:39:26.775533+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d6f9f0'): fast finishing 0 completion(s)
2020-02-14 16:39:26.775979+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] WatchStream (10922eaa8) Stream error: 'Unavailable: Operation timed out'
2020-02-14 16:39:26.776488+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d6f9f0'): destroying stream
2020-02-14 16:39:26.777298+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] WatchStream (10922eaa8) backoff
2020-02-14 16:39:26.777483+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d42640'): finishing and notifying observers
2020-02-14 16:39:26.777610+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d42640'): shutting down; completions: 0, is finished: true
2020-02-14 16:39:26.778477+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d42640'): fast finishing 0 completion(s)
2020-02-14 16:39:26.779100+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] RPC BatchGetDocuments completed. Error: 14: Operation timed out
2020-02-14 16:39:26.779373+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] RPC BatchGetDocuments returned headers (whitelisted):
2020-02-14 16:39:26.779518+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d42640'): destroying stream
2020-02-14 16:39:26.779957+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d7c6c0'): finishing and notifying observers
2020-02-14 16:39:26.780623+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d7c6c0'): shutting down; completions: 0, is finished: true
2020-02-14 16:39:26.780696+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d7c6c0'): fast finishing 0 completion(s)
2020-02-14 16:39:26.780744+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] RPC BatchGetDocuments completed. Error: 14: Operation timed out
2020-02-14 16:39:26.780792+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] RPC BatchGetDocuments returned headers (whitelisted):
2020-02-14 16:39:26.781000+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] GrpcStream('280d7c6c0'): destroying stream
2020-02-14 16:39:26.781124+0200 xxx[2456:650116] 6.17.0 - [Firebase/Firestore][I-FST000001] WatchStream (10922eaa8) start

[rizafran]

Thanks for letting me know, @Gagnant. I'll try to replicate this on my end and I'll inform you once I have an update.

[wu-hui]

Hi @Gagnant

We are aware of this issue, and have a potential fix that we are looking into.

In the meantime, you can probably use a walkaround of keep a Firestore listen active, this would trigger the code that monitors connection status, and should fix this the issue.

Please let me know if this did not work for you.

[Gagnant]

Hi @wu-hui, thank you for the suggestion!

In the application, I have an active firestore subscription but delay still persists.

[wu-hui]

Sorry, apparently I had some misunderstanding when I made the suggestion. I am looking into this now.

Can you provide a more detailed description though? Specifically, did you do anything before 1. Move the app to the background.?