MqttService keep working even if subscription is cancelled

[sargentin]

MqttService keep working even if subscription is cancelled

[minbi]

Hi @sargentin ,

We will investigate shutting down the service when the last subscription is cancelled.
Thanks for your report.

[sargentin]

Ok thx !

[dy08]

Hello,
Do we have some progress regarding this issue?

[mllrmat]

I have the same problem. Is there a solution?

[mllrmat]

Can I somehow help with the investigation on this issue? The status has not been changed for 3 month now. This is a blocking issue with a huge security issue.

As the issue #25 has been closed I am adding some concerns here: A user is logged in via cognito user pools on one device and starts a subscription. Signs out. Signs in to another device and . In this scenario the first device is still receiving the subscription updates.

It is not only about cancel the subscription on mqtt level when the last appsync subscription has been canceled, but always when a subscription is canceled on appsync level. As the subscriptions can be for different data types and therefore need authentication to be received by a client. At the moment I do not have control over cancelling the subscriptions at all.

[minbi]

Hi @mllrmat ,

I understand your concern. The connections are not currently being terminated when the subscription is cancelled. They do released the callback and free the memory that the callback was holding onto.

[scb01]

@mllrmat @dy08 @sargentin

Sorry for the delay on this issue - we have identified a fix and are in the process of testing it. I am hoping to include it in the next rev of the SDK. Will post back here once I have confirmation.

[scb01]

@mllrmat @dy08 @sargentin
The latest version of the SDK 2.7.0 contains a fix for this issue. Please try this on your side and let us know how it goes.

[yhkwon44]

It shows it is not fixed.

I test it by attaching button and just call " subscriptionWatcher.cancel(); "
the subscription is not called but mqttservice keep working

my log here: (look bolded text)
2018-11-21 14:03:07.116 27824-27824/com.jfouhamazip.messengers.example I/TEST: destroy
2018-11-21 14:03:07.116 27824-27824/com.jfouhamazip.messengers.example I/TEST: call subscriptionWatcher.cancel
2018-11-21 14:03:07.117 27824-27824/com.jfouhamazip.messengers.example V/RealSubscriptionManager: Subscription Infrastructure: Number of SubscriptionObjects for topic [680761677709/omxhqeqhubgrfco5qpdgb55vma/subscribeToCommand/f244b2fc62f46eed5d7c178ccfcd9733ead10a3aac52eb6e311020294891e38c] is 0. Unsubscribing at the MQTT Level...
2018-11-21 14:03:07.118 27824-27824/com.jfouhamazip.messengers.example V/RealSubscriptionManager: Subscription Infrastructure: MQTT Client has no active topics. Disconnecting...
2018-11-21 14:03:07.119 27824-27824/com.jfouhamazip.messengers.example V/MqttSubscriptionClient: Closing MQTT client [7cwdlwocxvdkrcpkzkt3vpk2vy
2018-11-21 14:03:07.541 27824-28376/com.jfouhamazip.messengers.example D/AlarmPingSender: Unregister alarmreceiver to MqttService7cwdlwocxvdkrcpkzkt3vpk2vy
2018-11-21 14:03:07.541 27824-27824/com.jfouhamazip.messengers.example V/MqttSubscriptionClient: Subscription Infrastructure: Errror [현재 클라이언트가 연결을 끊는 중 (32102)] when disconnecting from topic [680761677709/omxhqeqhubgrfco5qpdgb55vma/subscribeToCommand/f244b2fc62f46eed5d7c178ccfcd9733ead10a3aac52eb6e311020294891e38c]
2018-11-21 14:03:07.547 27824-27824/com.jfouhamazip.messengers.example D/MqttSubscriptionClient: Subscription Infrastructure: Successfully closed the connection. Client ID [7cwdlwocxvdkrcpkzkt3vpk2vy]
2018-11-21 14:03:07.547 27824-27824/com.jfouhamazip.messengers.example V/MqttSubscriptionClient: Subscription Infrastructure: client connection lost for client [7cwdlwocxvdkrcpkzkt3vpk2vy]
2018-11-21 14:03:07.547 27824-27824/com.jfouhamazip.messengers.example V/MqttSubscriptionClient: Subscription Infrastructure: Transmitting client connection lost for client [7cwdlwocxvdkrcpkzkt3vpk2vy]
2018-11-21 14:03:07.547 27824-27824/com.jfouhamazip.messengers.example V/RealSubscriptionManager: Subscription Infrastructure: onError called
2018-11-21 14:03:07.547 27824-27824/com.jfouhamazip.messengers.example V/RealSubscriptionManager: Subscription Infrastructure: Disconnect received. Unexpected - Initiating reconnect sequence.
2018-11-21 14:03:07.549 27824-28818/com.jfouhamazip.messengers.example V/RealSubscriptionManager: Subscription Infrastructure: Initiating reconnect sequence
2018-11-21 14:03:07.549 27824-28818/com.jfouhamazip.messengers.example V/RealSubscriptionManager: Subscription Infrastructure: Sleeping for [0] seconds
2018-11-21 14:03:30.583 27824-27824/com.jfouhamazip.messengers.example D/AlarmPingSender: Sending Ping at:1542776610583
2018-11-21 14:03:30.595 27824-27824/com.jfouhamazip.messengers.example D/AlarmPingSender: Schedule next alarm at 1542776640595
2018-11-21 14:03:30.595 27824-27824/com.jfouhamazip.messengers.example D/AlarmPingSender: Alarm scheule using setExactAndAllowWhileIdle, next: 30000
2018-11-21 14:03:30.964 27824-28378/com.jfouhamazip.messengers.example D/AlarmPingSender: Success. Release lock(MqttService.client.fvxb7vakffbwbifzaq34fpeeva):1542776610963
2018-11-21 14:03:31.587 27824-27824/com.jfouhamazip.messengers.example D/AlarmPingSender: Sending Ping at:1542776611587
2018-11-21 14:03:31.597 27824-27824/com.jfouhamazip.messengers.example D/AlarmPingSender: Schedule next alarm at 1542776641597
2018-11-21 14:03:31.597 27824-27824/com.jfouhamazip.messengers.example D/AlarmPingSender: Alarm scheule using setExactAndAllowWhileIdle, next: 30000
2018-11-21 14:03:31.611 27824-27824/com.jfouhamazip.messengers.example D/AlarmPingSender: Sending Ping at:1542776611611
2018-11-21 14:03:31.619 27824-27824/com.jfouhamazip.messengers.example D/AlarmPingSender: Schedule next alarm at 1542776641619
2018-11-21 14:03:31.619 27824-27824/com.jfouhamazip.messengers.example D/AlarmPingSender: Alarm scheule using setExactAndAllowWhileIdle, next: 30000
2018-11-21 14:03:31.633 27824-27824/com.jfouhamazip.messengers.example D/AlarmPingSender: Sending Ping at:1542776611633
2018-11-21 14:03:31.639 27824-27824/com.jfouhamazip.messengers.example D/AlarmPingSender: Schedule next alarm at 1542776641639
2018-11-21 14:03:31.639 27824-27824/com.jfouhamazip.messengers.example D/AlarmPingSender: Alarm scheule using setExactAndAllowWhileIdle, next: 30000
2018-11-21 14:03:31.999 27824-28365/com.jfouhamazip.messengers.example D/AlarmPingSender: Success. Release lock(MqttService.client.rgzjmxy7nnenfgk3u2mgvimioy):1542776611999
2018-11-21 14:03:32.000 27824-28372/com.jfouhamazip.messengers.example D/AlarmPingSender: Success. Release lock(MqttService.client.vy3bbwao4jgbnopwphxsh62spy):1542776612000
2018-11-21 14:03:32.006 27824-28366/com.jfouhamazip.messengers.example D/AlarmPingSender: Success. Release lock(MqttService.client.fwtlebohcfb3lclkv54vmwyqqu):1542776612006

[scb01]

@yhkwon44

Looking through the log you posted, here are my findings.

1. At the beginning of the log, before you called the cancel method, you have 5 MQTT clients in total, with ClientIDs (7cwdlwocxvdkrcpkzkt3vpk2vy, fvxb7vakffbwbifzaq34fpeeva, rgzjmxy7nnenfgk3u2mgvimioy, vy3bbwao4jgbnopwphxsh62spy, fwtlebohcfb3lclkv54vmwyqqu)
2. When you call Cancel, the logic unsubscribes from the MQTT level and disconnects the MQTT Connection when it determines that there no remaining subscriptions on that client
3. The log message "V/RealSubscriptionManager: Subscription Infrastructure: Disconnect received. Unexpected - Initiating reconnect sequence" is misleading ( I will be changing the log messages in the next version to clarify). What it really means that the connection received a connection close or error message and it will check to make sure a reconnection is needed.
4. From the logs, I don't see the connection being recreated - When a connection is created, you should expect to see the following log message - "Attempting to make [1] MQTT clients]" and that is not present.
5. The rest of logs show the ping messages for the other 4 connections (fvxb7vakffbwbifzaq34fpeeva, rgzjmxy7nnenfgk3u2mgvimioy, vy3bbwao4jgbnopwphxsh62spy, fwtlebohcfb3lclkv54vmwyqqu)

Can you provide some more context about your application, number of subscriptions, code snippets etc to help debug further? You can also look at this test where I setup 6 subscriptions and cancel them

aws-mobile-appsync-sdk-android/aws-android-sdk-appsync-tests/src/androidTest/java/com/amazonaws/mobileconnectors/appsync/AWSAppSyncQueryInstrumentationTest.java

Line 237 in 7f8490c

public void testMultipleSubscriptionsWithIAM() {

[scb01]

@yhkwon44

Closing as there has been no response. Please feel free to open this item if you are still encountering issues.