GraphQL: Backgrounding iOS App breaks Update and Query

Description

I created a sample Todo Flutter app and initialized following Amplify plugins.

  amplify_api: ^0.6.11
  amplify_auth_cognito: ^0.6.11
  amplify_datastore: ^0.6.11 
  amplify_flutter: ^0.6.11

When I run the app on physical iPhone device, and move the app to the background and wait for ~30s and bring the app back to the foreground, I see these messages in debug log.

dnssd_clientstub read_all(8) DEFUNCT
[VERBOSE-2:FlutterObservatoryPublisher.mm(143)] Could not register as server for FlutterObservatoryPublisher. Check your network settings and relaunch the application.
dnssd_clientstub read_all(11) DEFUNCT
[VERBOSE-2:FlutterObservatoryPublisher.mm(143)] Could not register as server for FlutterObservatoryPublisher. Check your network settings and relaunch the application.

I was able to query and save the data to the backend but I wanted to check if this is ignorable or a real issue. I don't see these messages when running on simulator or run the app without Amplify plugins.

I added more models to schema.graphql, and did the same test(move to background, wait ~30s and bring back to foreground). I see these errors.

[connection] nw_read_request_report [C2] Receive failed with error "Socket is not connected"
[connection] nw_read_request_report [C1] Receive failed with error "Software caused connection abort"
[connection] nw_flow_add_write_request [C1 34.213.155.74:443 failed parent-flow (satisfied (Path is satisfied), interface: en0[802.11], ipv4, dns)] cannot accept write requests
[connection] nw_write_request_report [C1] Send failed with error "Socket is not connected"
36
ConnectionProviderError.connection
[IncomingAsyncSubscriptionEventToAnyModelMapper] Received completion: failure(DataStoreError: Subscription item event failed with error
Caused by:
APIError: Subscription item event failed with error
Caused by:
connection)
[IncomingAsyncSubscriptionEventToAnyModelMapper] Received completion: failure(DataStoreError: Subscription item event failed with error
Caused by:
APIError: Subscription item event failed with error
Caused by:
connection)
2
ConnectionProviderError.connection

What is going on here and what's causing all these error? I'm not doing anything in my app. I just added Amplify plugin and that's it.

Steps to Reproduce

No response

Screenshots

No response

Platforms

[X] iOS
[ ] Android
[ ] Web
[ ] macOS
[ ] Windows
[ ] Linux

Android Device/Emulator API Level

No response

Environment

[✓] Flutter (Channel stable, 3.3.10, on macOS 13.1 22C65 darwin-arm, locale en-US)
[✓] Android toolchain - develop for Android devices (Android SDK version 32.1.0-rc1)
[✓] Xcode - develop for iOS and macOS (Xcode 14.2)
[✓] Chrome - develop for the web
[✓] Android Studio (version 2022.1)
[✓] VS Code (version 1.74.3)
[✓] Connected device (5 available)
[✓] HTTP Host Availability

Dependencies

Dart SDK 2.18.6
Flutter SDK 3.3.10
chummy 1.0.0+1

dependencies:
- amplify_api 0.6.12 [amplify_api_android amplify_api_ios amplify_core amplify_flutter aws_common collection flutter meta plugin_platform_interface]
- amplify_auth_cognito 0.6.12 [amplify_auth_cognito_android amplify_auth_cognito_ios amplify_core aws_common collection flutter meta plugin_platform_interface]
- amplify_datastore 0.6.12 [flutter amplify_datastore_plugin_interface amplify_core plugin_platform_interface meta collection async]
- amplify_flutter 0.6.12 [amplify_core amplify_datastore_plugin_interface amplify_flutter_android amplify_flutter_ios aws_common collection flutter meta plugin_platform_interface]
- cupertino_icons 1.0.5
- flutter 0.0.0 [characters collection material_color_utilities meta vector_math sky_engine]

transitive dependencies:
- amplify_api_android 0.6.12 [flutter]
- amplify_api_ios 0.6.12 [amplify_core flutter]
- amplify_auth_cognito_android 0.6.12 [flutter]
- amplify_auth_cognito_ios 0.6.12 [amplify_core flutter]
- amplify_core 0.6.12 [aws_common collection flutter intl json_annotation meta plugin_platform_interface uuid]
- amplify_datastore_plugin_interface 0.6.12 [amplify_core collection flutter meta]
- amplify_flutter_android 0.6.12 [flutter]
- amplify_flutter_ios 0.6.12 [amplify_core flutter]
- async 2.9.0 [collection meta]
- aws_common 0.1.1 [async collection http meta stream_transform uuid]
- characters 1.2.1
- clock 1.1.1
- collection 1.16.0
- crypto 3.0.2 [typed_data]
- http 0.13.5 [async http_parser meta path]
- http_parser 4.0.2 [collection source_span string_scanner typed_data]
- intl 0.17.0 [clock path]
- json_annotation 4.8.0 [meta]
- material_color_utilities 0.1.5
- meta 1.8.0
- path 1.8.2
- plugin_platform_interface 2.1.3 [meta]
- sky_engine 0.0.99
- source_span 1.9.0 [collection path term_glyph]
- stream_transform 2.1.0
- string_scanner 1.1.1 [source_span]
- term_glyph 1.2.1
- typed_data 1.3.1 [collection]
- uuid 3.0.6 [crypto]
- vector_math 2.1.2

Device

iPhone 12

OS

iOS 16.2

Deployment Method

Amplify CLI

CLI Version

10.6.2

Additional Context

No response

Amplify Config

{ "UserAgent": "aws-amplify-cli/2.0", "Version": "1.0", }

Hi @skim037 - Can you share your app's build method and the calls to Amplify.addPlugin and Amplify.configure?

Hi @Jordan-Nelson

I simplified my code as below.

void _init() async {
  try {
    await _configureAmplify();
    _waitForDataStore();
    setState(() => _isAmplifyConfigured = true);
  } on Exception catch (e) {
    setState(() => _isAmplifyConfigureFailed = true);
  }
}

Future<void> _configureAmplify() async {
  try {
    await Amplify.addPlugins([
      AmplifyAPI(),
      AmplifyAuthCognito(),
      AmplifyDataStore(
        modelProvider: ModelProvider.instance,
      ),  
    ]);
    await Amplify.configure(amplifyconfig);
  } on Exception catch (e) {
    rethrow;
  }
}

void _waitForDataStore() async {  
  await Amplify.DataStore.stop();
  await Amplify.DataStore.clear();
  await Amplify.DataStore.start();

  StreamSubscription dsHub =
    Amplify.Hub.listen([HubChannel.DataStore], (hubEvent) {
  });
  dsHub.onData((data) async {
    if (data.eventName == 'ready') {
      await dsHub.cancel();
    } 
  });
}

@override
Widget build(BuildContext context) {
  return MaterialApp(
    debugShowCheckedModeBanner: false,
    title: appName,
    theme: ThemeData(
      primarySwatch: Colors.blue,
    ),
    home: Container() 
  ); 
}

I think the issue is raised when using DataStore stop, clear, and start.

I did more testing.

When I changed the default authorization mode to Cognito User Pool, backend sync and query is not working as expected after I put the app in the background for 5 minutes. (When using API Key as a default auth mode, things work as expected).

Set up

Set default auth mode to Cognito User Pool

> amplify update api
? Select a setting to edit Authorization modes
? Choose the default authorization type for the API Amazon Cognito User Pool
Use a Cognito user pool configured as a part of this project.
? Configure additional auth types? Yes
? Choose the additional authorization types you want to configure for the API API ke
y, IAM
API key configuration
✔ Enter a description for the API key: · Public Key
✔ After how many days from now the API key should expire (1-365): · 365

Model auth change

changed a model auth to something like this.

type Todo @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

Configure multiAuth strategy

Future<void> configureAmplify() async {
    await Amplify.addPlugins([
      AmplifyAPI(),
      AmplifyAuthCognito(),
      AmplifyDataStore(
        modelProvider: ModelProvider.instance,
        authModeStrategy: AuthModeStrategy.multiAuth
      )
    ]);
    await Amplify.configure(amplifyconfig);
  }

Reproduction Steps

Start the app on physical iPhone device, sign up new user and login
Create a new or update existing Todo item.
Move the app to the background
Wait for 5 minutes. (I kept using the phone to not go to sleep)
Bring the app back to the foreground
Try to update the existing Todo item.

Code used.

  Future<void> _createTodo() async {
    final description = DateTime.now().millisecondsSinceEpoch.toString();
    Todo todo = Todo(id: 'aaa', name: 'aaa', description: description);
    final result = await Amplify.DataStore.query(
        Todo.classType, 
        where: Todo.ID.eq(todo.id));
    if (result.isEmpty) {
      await Amplify.DataStore.save(todo);
      print('Created new Todo. Description $description');
    } else {
      await Amplify.DataStore.save(todo.copyWith(description: description)); 
      print('Updated existing Todo. Description $description');
    }

Behavior I observed

Debug log shows Updated existing Todo. Description 1674748837509, but backend doesn't have the update. Backend sync seems to have stopped.

The following query doesn't work (It works before the app goes to background) var response = await operation.response; doesn't return anything.

Future<List<Todo>> listTodos({required String name}) async {
String graphQLDocument = 
  '''query MyQuery (
    \$name: String!) {

    listTodos(
      filter: {
        name: { eq: \$name },
      }
      limit: 20) {
      nextToken
      items {
        updatedAt
        name
        id
        description
        createdAt
        _version
        _lastChangedAt
        _deleted
      }
    }
  }''';

var operation = Amplify.API.query(
  request: GraphQLRequest<String>(document: graphQLDocument, variables: {
    'name': name
}));

var response = await operation.response;
var todos = jsonDecode(response.data!)['listTodos'];

if (todos['items'] != null && (todos['items'] as List).isNotEmpty) {
  final todoItems = todos['items'] as List;
  List<Todo> result = [];
  for (final todoItem in todoItems) {
    final todo = Todo.fromJson(todoItem);
    result.add(todo);
  }
  return result; 
} else {
  return []; 
} 
}

When I use API Key as a default auth mode and use public auth in the models, I don't see these behaviors. Save and query both seem to work when the app was moved to foreground after 5 minutes in the background. Please take a look and let me know what's going on here. I've been trying for days to figure out why my app gets stuck when it goes to background and this is as much details as I can find myself.

Additional test

When I use API Key as a default auth mode (Cognito User Pool and IAM as additional) and use private auth annotation in the schema model (either IAM or userPools), this issue also happens.

Hi @skim037 sorry to hear you're having this issue.

This is my understanding of your problem:

On an iOS physical device
When default authorization mode is Cognito User Pool OR API Key as a default auth mode (Cognito User Pool and IAM as additional) and use private auth annotation in the schema model (either IAM or userPools)
Backend sync and query is not working as expected after I put the app in the background for 5 minutes. When using API Key as a default auth mode, things work as expected.

Can you please clarify:

Do you encounter this issue on iOS simulator or Android?
You provided logs before for other issues, but what are the logs when you ran your last two tests? Are the following logs you mentioned at the start still being received?

[IncomingAsyncSubscriptionEventToAnyModelMapper] Received completion: failure(DataStoreError: Subscription item event failed with error Caused by: APIError: Subscription item event failed with error

OR

[VERBOSE-2:FlutterObservatoryPublisher.mm(143)] Could not register as server for FlutterObservatoryPublisher. Check your network settings and relaunch the application.

If possible, it would be helpful if you could provide all logs when running your debug test so we can better understand your use case here.

Backend sync and query is not working as expected after I put the app in the background for 5 minutes. When using API Key as a default auth mode, things work as expected.

API Key default auth mode and public annotation works, but API Key default auth mode and Cognito User Pool as additional auth mode also has the same issue when used with private annotation.

Do you encounter this issue on iOS simulator or Android?

It seems to happen on iOS simulator as well.

When the app is moved to background, this log shows up.

[tcp] tcp_input [C1.1.1.1:3] flags=[R] seq=3018786568, ack=0, win=0 state=LAST_ACK rcv_nxt=3018786568, snd_una=1289017085
[tcp] tcp_input [C1.1.1.1:3] flags=[R] seq=3018786568, ack=0, win=0 state=CLOSED rcv_nxt=3018786568, snd_una=1289017085

After 5min, when the app is moved to foreground, this log shows up.

dnssd_clientstub read_all(8) DEFUNCT
[VERBOSE-2:FlutterObservatoryPublisher.mm(143)] Could not register as server for FlutterObservatoryPublisher. Check your network settings and relaunch the application.
dnssd_clientstub read_all(11) DEFUNCT
[VERBOSE-2:FlutterObservatoryPublisher.mm(143)] Could not register as server for FlutterObservatoryPublisher. Check your network settings and relaunch the application.
[RealtimeConnectionProvider] Realtime connection is stale, disconnecting.
10
ConnectionProviderError.connection
[connection] nw_read_request_report [C3] Receive failed with error "Socket is not connected"
ConnectionProviderError.connection
[connection] nw_read_request_report [C2] Receive failed with error "Software caused connection abort"

When tried to save a Todo item, this log shows up

ConnectionProviderError.connection
2
Encoder Foundation.(unknown context at $1caafb8f8).__JSONEncoder
Successfully saved model: FlutterSerializedModel(values: ["__typename": Amplify.JSONValue.string("Todo"), "description": Amplify.JSONValue.string("1675127354492"), "createdAt": Amplify.JSONValue.null, "id": Amplify.JSONValue.string("aaa"), "updatedAt": Amplify.JSONValue.null, "name": Amplify.JSONValue.string("aaa")], _modelName: "Todo")
flutter: Created new TodoOne. Description 1675127354492

It shows my log Created TodoOne..., but backend doesn't have this record.

When I try to query a Todo record, the request gets stuck at var response = await operation.response;

Implementation

These implementations work before app was moved to background for 5 minutes.

Future<void> _createTodoOne() async {
    final description = DateTime.now().millisecondsSinceEpoch.toString();
    Todo todo = Todo(id: 'aaa', name: 'aaa', description: description);
    final result = await Amplify.DataStore.query(
        Todo.classType, 
        where: Todo.ID.eq(todo.id));
    if (result.isEmpty) {
      await Amplify.DataStore.save(todo);
      print('Created new TodoOne. Description $description');
    } else {
      await Amplify.DataStore.save(todo.copyWith(description: description)); 
      print('Updated existing TodoOne. Description $description');
    }
}

Future<List<Todo>> listTodos({required String name}) async {
    String graphQLDocument = 
      '''query MyQuery (
        \$name: String!) {

        listTodos(
          filter: {
            name: { eq: \$name },
          }
          limit: 20) {
          nextToken
          items {
            updatedAt
            name
            id
            description
            createdAt
            _version
            _lastChangedAt
            _deleted
          }
        }
      }''';

    var operation = Amplify.API.query(
      request: GraphQLRequest<String>(document: graphQLDocument, variables: {
        'name': name
    }));

    var response = await operation.response;
    var todos = jsonDecode(response.data!)['listTodoOnes'];

    if (todos['items'] != null && (todos['items'] as List).isNotEmpty) {
      final todoItems = todos['items'] as List;
      List<Todo> result = [];
      for (final todoItem in todoItems) {
        final todo = Todo.fromJson(todoItem);
        result.add(todo);
      }
      return result; 
    } else {
      return []; 
    } 
  }

Hi @skim037 I haven't been able to replicate your issue on an iOS simulator or physical iphone.

Setup:

I used your Todo model with same auth rules except for iam.

I used authenticator and setup auth default as API Key and Cognito User Pools.

Datastore is setup as multiauth.

Testing:

I call query Todo and call save Todo using a hardcoded id (so the same Todo is saved to each time).

When I put the app in background for 5 minutes, I get some errors but it recovers:

APIError: Subscription item event failed with error
Caused by:
connection

Beginning initial sync

I call query and save Todo freely and nothing hangs and the new Todo is synced and saved to cloud.

Thoughts:

Are you using the Authenticator plugin to manage your user's sign in flow ?

Perhaps it could be because iam is configured as well so I can add that later and see if it's still working.

Hi @fjnoyp That's interesting. I tried for both IAM and Cognito Pool and they all run into the same issue. Yes I'm usingamplify_authenticator: ^0.2.4 for sign in flow. Could you also check if you are using latest versions of Flutter, Amplify CLI and plugins?

Hi @fjnoyp

I had many other models in my app so I tried removing all models and tested with just the Todo model and I didn't face this issue like you. So it seems like the number of models has something to do with this issue as well. Below is the schema.graphql I used to reproduce this issue. And again, if I'm using { allow: public} only, I do not see this issue.

# This "input" configures a global authorization rule to enable public access to
# all models in this schema. Learn more about authorization rules here: https://docs.amplify.aws/cli/graphql/authorization-rules

type Todo @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TodoA @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TodoB @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TodoC @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TodoD @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TodoE @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TodoF @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TodoG @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TodoH @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TodoI @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TodoJ @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TodoK @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TestA @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TestB @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TestC @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TestD @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TestE @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TestF @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TestG @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TestH @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TestI @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

type TestJ @model @auth(rules: [
  { allow: private, provider: userPools },
  { allow: private, provider: iam }
]) {
  id: ID!
  name: String!
  description: String
}

Hi @skim037 thanks for the extra information here.

So it sounds like you also don't get the issue when just using one model like I did. I can update my schema.graphql to use all the models you provided here and see if I get the error.

Hi @skim037 I am still unable to reproduce on simulator or iPhone device.

I added iam auth. I also added all of the models defined in your schema.graphql file provided above.

I test via two simple query and save methods:

  Future<void> queryTodo() async {
    print('querying todos');
    final todos = await Amplify.DataStore.query(Todo.classType);
    for (final todo in todos) {
      print(todo);
    }
  }

  Future<void> saveTodo() async {
    print('saving todo');
    final description = DateTime.now().millisecondsSinceEpoch.toString();
    Todo todo = Todo(id: 'aaa', name: 'aaa', description: description);
    await Amplify.DataStore.save(todo);
  }

I do not make the following calls like you did though. Why did you add them beforehand?


void _waitForDataStore() async {  
  await Amplify.DataStore.stop();
  await Amplify.DataStore.clear();
  await Amplify.DataStore.start();

There is a previous issue in which calling these methods can disrupt Datastore: https://github.com/aws-amplify/amplify-flutter/issues/1479

Furthermore, while you call _waitForDataStore you don't actually await that call or do anything with the Datastore hubEvent 'ready'. This means if you query or save, the operations to stop/clear/start could still be running. The fact you get this issue when having many other models would also make those operations slower thereby increasing the chance you were trying to call query/save while Datastore wasn't ready.

When/how do you call save/query when brining the app to foreground afterwards?

Hi @fjnoyp I'm not sure why you are not experiencing the same issue. _waitForDataStore is only executed once when the app first starts.

I attached the full log from Xcode when running the app on iPhone device.

2023-02-07 20:08:10.468409: First todo write when the app is started. It was successful. 2023-02-07 20:11:54.992015: App was brought to foreground after backgrounding for couple of minutes. I see bunch of Socket is not connected and ConnectionProviderError.connection 2023-02-07 20:12:17.639439: Second todo write triggered. The log says item was updated but the update is not reflected in the backend.

2023-02-07 20:07:50.595879+0900 Runner[15783:909676] [SceneConfiguration] Info.plist contained no UIScene configuration dictionary (looking for configuration named "(no name)")
2023-02-07 20:07:50.595932+0900 Runner[15783:909676] [SceneConfiguration] Info.plist contained no UIScene configuration dictionary (looking for configuration named "(no name)")
2023-02-07 20:07:50.698221+0900 Runner[15783:909676] Metal GPU Frame Capture Enabled
2023-02-07 20:07:50.698349+0900 Runner[15783:909676] Metal API Validation Enabled
2023-02-07 20:07:50.798972+0900 Runner[15783:909933] flutter: The Dart VM service is listening on http://127.0.0.1:58031/vllqgkv_1aA=/
Amplify configured with DataStore plugin
2023-02-07 20:07:51.334243+0900 Runner[15783:909676] [Amplify] Configuring
2023-02-07 20:07:51.363502+0900 Runner[15783:909676] [awsAPIPlugin] Configure finished
2023-02-07 20:07:51.364839+0900 Runner[15783:909676] [Amplify] No plugin found for configuration key `awsS3StoragePlugin`. Add a plugin for that key.
DataStorePlugin successfully initialized
Successfully stopped datastore cloud syncing
Successfully cleared the store
Successfully started datastore cloud syncing
2023-02-07 20:07:52.912434+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:52.942221+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:52.970395+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:52.998984+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:53.029057+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:53.062913+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:53.091935+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:53.142150+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:53.170125+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:53.198994+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:53.227096+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:53.254914+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:53.283710+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:53.312197+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:53.341519+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:53.370061+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:53.399641+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:53.429680+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:53.459214+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:53.487922+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:53.517246+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:53.546338+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received subscription: PassthroughSubject
2023-02-07 20:07:54.581086+0900 Runner[15783:909939] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.587238+0900 Runner[15783:909917] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.588055+0900 Runner[15783:909910] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.588425+0900 Runner[15783:909910] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.598167+0900 Runner[15783:909917] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.613175+0900 Runner[15783:909913] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.621690+0900 Runner[15783:909917] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.632066+0900 Runner[15783:909910] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.650793+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.678384+0900 Runner[15783:909910] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.694795+0900 Runner[15783:909910] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.720953+0900 Runner[15783:909939] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.732764+0900 Runner[15783:909910] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.739096+0900 Runner[15783:909916] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.741122+0900 Runner[15783:909940] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.744517+0900 Runner[15783:909910] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.749609+0900 Runner[15783:909939] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.761993+0900 Runner[15783:909939] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.773999+0900 Runner[15783:909939] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.776616+0900 Runner[15783:909910] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.818044+0900 Runner[15783:909913] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.825640+0900 Runner[15783:909913] [IncomingAsyncSubscriptionEventToAnyModelMapper] connectionState now connected
2023-02-07 20:07:54.831293+0900 Runner[15783:909940] [AWSInitialSyncOrchestrator] Beginning initial sync
2023-02-07 20:07:54.835710+0900 Runner[15783:909955] [InitialSyncOperation] Beginning sync for TodoF
2023-02-07 20:07:54.835745+0900 Runner[15783:909940] [InitialSyncOperation] Beginning sync for TodoH
2023-02-07 20:07:54.835898+0900 Runner[15783:909914] [InitialSyncOperation] Beginning sync for TestE
2023-02-07 20:07:54.836103+0900 Runner[15783:909956] [InitialSyncOperation] Beginning sync for TodoG
2023-02-07 20:07:54.836109+0900 Runner[15783:909916] [InitialSyncOperation] Beginning sync for TestA
2023-02-07 20:07:54.836115+0900 Runner[15783:909917] [InitialSyncOperation] Beginning sync for TestD
2023-02-07 20:07:54.836193+0900 Runner[15783:909941] [InitialSyncOperation] Beginning sync for TestH
2023-02-07 20:07:54.836218+0900 Runner[15783:909918] [InitialSyncOperation] Beginning sync for TestF
2023-02-07 20:07:54.836225+0900 Runner[15783:909939] [InitialSyncOperation] Beginning sync for TestB
2023-02-07 20:07:54.836370+0900 Runner[15783:909938] [InitialSyncOperation] Beginning sync for TestG
2023-02-07 20:07:54.836450+0900 Runner[15783:909953] [InitialSyncOperation] Beginning sync for TodoD
2023-02-07 20:07:54.836472+0900 Runner[15783:909954] [InitialSyncOperation] Beginning sync for TodoE
2023-02-07 20:07:54.836523+0900 Runner[15783:909950] [InitialSyncOperation] Beginning sync for TodoA
2023-02-07 20:07:54.836748+0900 Runner[15783:909948] [InitialSyncOperation] Beginning sync for TestJ
2023-02-07 20:07:54.836875+0900 Runner[15783:909947] [InitialSyncOperation] Beginning sync for TestI
2023-02-07 20:07:54.836993+0900 Runner[15783:909910] [InitialSyncOperation] Beginning sync for TestC
2023-02-07 20:07:54.837040+0900 Runner[15783:909949] [InitialSyncOperation] Beginning sync for Todo
2023-02-07 20:07:54.837266+0900 Runner[15783:909952] [InitialSyncOperation] Beginning sync for TodoC
2023-02-07 20:07:54.837403+0900 Runner[15783:909951] [InitialSyncOperation] Beginning sync for TodoB
2023-02-07 20:07:54.838230+0900 Runner[15783:909957] [InitialSyncOperation] Beginning sync for TodoI
2023-02-07 20:07:54.839801+0900 Runner[15783:909960] [InitialSyncOperation] Beginning sync for TodoJ
2023-02-07 20:07:54.842424+0900 Runner[15783:909963] [InitialSyncOperation] Beginning sync for TodoK
Encoder Foundation.(unknown context at $1b4bef8f8).__JSONEncoder
2023-02-07 20:07:55.680311+0900 Runner[15783:909947] [RemoteSyncEngine] Successfully finished sync
Unhandled DataStoreHubEvent: DataStore.syncStarted 
Encoder Foundation.(unknown context at $1b4bef8f8).__JSONEncoder
Encoder Foundation.(unknown context at $1b4bef8f8).__JSONEncoder
Successfully saved model: FlutterSerializedModel(values: ["createdAt": Amplify.JSONValue.null, "name": Amplify.JSONValue.string("aaa"), "__typename": Amplify.JSONValue.string("Todo"), "description": Amplify.JSONValue.string("1675768090432"), "updatedAt": Amplify.JSONValue.null, "id": Amplify.JSONValue.string("aaa")], _modelName: "Todo")
2023-02-07 20:08:10.468409+0900 Runner[15783:909919] flutter: Updated existing Todo. Description 1675768090432
Encoder Foundation.(unknown context at $1b4bef8f8).__JSONEncoder
Failed to parse the event DataStoreError: No decoder found for model named MutationEvent
Recovery suggestion: There is no decoder registered for the model named MutationEvent. Register models with `ModelRegistry.register(modelName:)` at startup.
2023-02-07 20:08:53.014557+0900 Runner[15783:910058] [tcp] tcp_input [C1.1.1.1:3] flags=[R] seq=1542589979, ack=0, win=0 state=LAST_ACK rcv_nxt=1542589979, snd_una=3603639253
2023-02-07 20:08:53.015612+0900 Runner[15783:910058] [tcp] tcp_input [C1.1.1.1:3] flags=[R] seq=1542589979, ack=0, win=0 state=CLOSED rcv_nxt=1542589979, snd_una=3603639253
2023-02-07 20:11:54.992015+0900 Runner[15783:909676] dnssd_clientstub read_all(8) DEFUNCT
2023-02-07 20:11:54.992158+0900 Runner[15783:909676] [VERBOSE-2:FlutterObservatoryPublisher.mm(130)] Could not register as server for FlutterObservatoryPublisher. Check your network settings and relaunch the application.
2023-02-07 20:11:55.005385+0900 Runner[15783:910325] [connection] nw_flow_add_write_request [C2 p6jcyxawgvei7aqutazuor7yoa.appsync-realtime-api.us-west-2.amazonaws.com:443 failed parent-flow (satisfied (Path is satisfied), interface: en0[802.11], ipv4, dns)] cannot accept write requests
2023-02-07 20:11:55.005474+0900 Runner[15783:910325] [connection] nw_write_request_report [C2] Send failed with error "Socket is not connected"
2023-02-07 20:11:55.006408+0900 Runner[15783:910325] [] nw_endpoint_flow_fillout_data_transfer_snapshot copy_info() returned NULL
2023-02-07 20:11:55.006452+0900 Runner[15783:910325] [connection] nw_connection_copy_connected_local_endpoint_block_invoke [C2] Connection has no connected path
2023-02-07 20:11:55.006529+0900 Runner[15783:910325] [connection] nw_connection_copy_connected_remote_endpoint_block_invoke [C2] Connection has no connected path
2023-02-07 20:11:55.008433+0900 Runner[15783:910325] [connection] nw_flow_add_write_request [C3 p6jcyxawgvei7aqutazuor7yoa.appsync-api.us-west-2.amazonaws.com:443 failed parent-flow (satisfied (Path is satisfied), interface: en0[802.11], ipv4, dns)] cannot accept write requests
2023-02-07 20:11:55.008545+0900 Runner[15783:910325] [connection] nw_write_request_report [C3] Send failed with error "Socket is not connected"
2023-02-07 20:11:55.008699+0900 Runner[15783:910325] [connection] nw_flow_add_write_request [C3 p6jcyxawgvei7aqutazuor7yoa.appsync-api.us-west-2.amazonaws.com:443 failed parent-flow (satisfied (Path is satisfied), interface: en0[802.11], ipv4, dns)] cannot accept write requests
2023-02-07 20:11:55.008774+0900 Runner[15783:910325] [connection] nw_write_request_report [C3] Send failed with error "Socket is not connected"
2023-02-07 20:11:55.008932+0900 Runner[15783:910325] [] nw_endpoint_flow_fillout_data_transfer_snapshot copy_info() returned NULL
2023-02-07 20:11:55.009014+0900 Runner[15783:910325] [connection] nw_connection_copy_connected_local_endpoint_block_invoke [C3] Connection has no connected path
2023-02-07 20:11:55.009573+0900 Runner[15783:910325] [connection] nw_connection_copy_connected_remote_endpoint_block_invoke [C3] Connection has no connected path
2023-02-07 20:11:55.013170+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.013450+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.013573+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.013671+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.013796+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.013910+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.014023+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.014126+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.014246+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.014485+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.014650+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.014856+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.015017+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.015229+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.015429+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.015632+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.015816+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.016184+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.016282+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.016379+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.016471+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.016655+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.016919+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.017723+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.017914+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.018091+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.018673+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.018775+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.018896+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.019116+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.019232+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.019395+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.019591+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.020229+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.020342+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.021494+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.021618+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.021704+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.021767+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.021879+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.022000+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.022141+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.022235+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.022349+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.022468+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.022611+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.022682+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.022777+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.022902+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.022986+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.023049+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.023359+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.023488+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.023549+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.023722+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.023782+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.023849+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.023904+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.024030+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.024146+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.024206+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.024455+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.024520+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.024574+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.024629+0900 Runner[15783:910058] ConnectionProviderError.connection
2023-02-07 20:11:55.024722+0900 Runner[15783:910058] ConnectionProviderError.connection
Encoder Foundation.(unknown context at $1b4bef8f8).__JSONEncoder
Encoder Foundation.(unknown context at $1b4bef8f8).__JSONEncoder
Successfully saved model: FlutterSerializedModel(values: ["__typename": Amplify.JSONValue.string("Todo"), "createdAt": Amplify.JSONValue.null, "name": Amplify.JSONValue.string("aaa"), "description": Amplify.JSONValue.string("1675768337610"), "id": Amplify.JSONValue.string("aaa"), "updatedAt": Amplify.JSONValue.null], _modelName: "Todo")
2023-02-07 20:12:17.639439+0900 Runner[15783:909919] flutter: Updated existing Todo. Description 1675768337610
Encoder Foundation.(unknown context at $1b4bef8f8).__JSONEncoder
Encoder Foundation.(unknown context at $1b4bef8f8).__JSONEncoder
Successfully saved model: FlutterSerializedModel(values: ["name": Amplify.JSONValue.string("aaa"), "id": Amplify.JSONValue.string("aaa"), "updatedAt": Amplify.JSONValue.null, "description": Amplify.JSONValue.string("1675768432601"), "__typename": Amplify.JSONValue.string("Todo"), "createdAt": Amplify.JSONValue.null], _modelName: "Todo")
2023-02-07 20:13:52.621836+0900 Runner[15783:909919] flutter: Updated existing Todo. Description 1675768432601

Save operation

  Future<void> _createTodo() async {
    final description = DateTime.now().millisecondsSinceEpoch.toString();
    Todo todo = Todo(id: 'aaa', name: 'aaa', description: description);
    final result = await Amplify.DataStore.query(
        Todo.classType, 
        where: Todo.ID.eq(todo.id));
    if (result.isEmpty) {
      await Amplify.DataStore.save(todo);
      print('Created new Todo. Description $description');
    } else {
      await Amplify.DataStore.save(todo.copyWith(description: description)); 
      print('Updated existing Todo. Description $description');
    } 
  }

This issue seems pretty related. https://github.com/awslabs/aws-mobile-appsync-sdk-ios/issues/396

@skim037 I was able to reproduce this. In my example, I was able to mitigate the issue by stopping/starting DataStore when backgrounding/foregrounding the app with the WidgetsBindingObserver API and code like this:

  @override
  void didChangeAppLifecycleState(AppLifecycleState state) {
    switch (state) {
      case AppLifecycleState.resumed:
        print('resumed');
        Amplify.DataStore.start();
        break;
      case AppLifecycleState.inactive:
      case AppLifecycleState.paused:
      case AppLifecycleState.detached:
        print("app in bg");
        Amplify.DataStore.stop();
        break;
    }
  }

However, this workaround is generally not required so I'm going to do a little more investigation to see if there might be another issue here.

Also noting that I tried updating amplify-flutter to use 1.29.0 of amplify-swift in v1 track which has a fix for datastore reconnect but it did not seem to fix the issue.

As amplify-swift states: DataStore doesn't work in iOS background mode. In flight HTTP requests that cannot finish within 5 seconds or so when app entered background will be terminated which causes the exceptions. Hence, this issue should not be a bug, a feature request is more appropriate.

aws-amplify / amplify-flutter