Skip to content
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.

Sign up for GitHub

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

Jump to bottom

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

Closed
Gagnant opened this issue Feb 14, 2020 · 7 comments · Fixed by #4985
Closed

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

Gagnant opened this issue Feb 14, 2020 · 7 comments · Fixed by #4985
Assignees
@wu-hui
Labels
api: firestore
Milestone
6.19.0 - M66

Comments

@Gagnant
Copy link

Gagnant commented Feb 14, 2020

[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
Copy link
Contributor

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
Copy link
Author

Gagnant commented Feb 14, 2020

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
Copy link
Contributor

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
Copy link
Contributor

wu-hui commented Feb 18, 2020

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
Copy link
Author

Gagnant commented Feb 25, 2020

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

In the application, I have an active firestore subscription but delay still persists.
@wu-hui
Copy link
Contributor

wu-hui commented Feb 25, 2020

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.?
@wu-hui wu-hui mentioned this issue Feb 27, 2020
Merged
@wu-hui wu-hui self-assigned this Feb 27, 2020
@wilhuff
Copy link
Contributor

wilhuff commented Mar 3, 2020

This fix should go out with the next release.
@wilhuff wilhuff added this to the 6.19.0 - M66 milestone Mar 3, 2020
@firebase firebase locked and limited conversation to collaborators Apr 3, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
api: firestore
5 participants
@Gagnant @wilhuff @google-oss-bot @wu-hui @rizafran