Thursday, 15 July 2021

AWS MQTT Python awsiotsdk and awscrt packages fail sporadically with repeating messages in trace logs

I'm following reasonably close to the pub/sub example in the awsiotsdk package. My basic unittests sometimes succeed and sometimes fail.

I enabled trace logging with awscrt.io.init_logging(6, 'stderr')

When I look through the trace logs they look relatively similar up to this line:

[TRACE] [2021-06-16T23:56:36Z] [00007f5fcfbbc640] [mqtt-topic-tree] - tree=0x5565ac073898: Publishing on topic test/unittest

After that point a run that failed starts producing the following output in a loop until my unittest times out after 30 seconds:

[DEBUG] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: resolving host #############-ats.iot.us-west-2.amazonaws.com
[DEBUG] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: resolved record: 34.213.168.191
[DEBUG] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: resolved record: 52.35.137.184
[DEBUG] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: resolved record: 54.148.88.142
[DEBUG] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: resolved record: 34.214.249.117
[DEBUG] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: resolved record: 54.186.43.162
[DEBUG] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: resolved record: 52.38.221.226
[DEBUG] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: resolved record: 54.244.33.231
[DEBUG] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: resolved record: 34.218.88.107
[DEBUG] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: resolved record: 2620:108:700f::23a6:36ae
[DEBUG] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: resolved record: 2620:108:700f::3424:419e
[DEBUG] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: resolved record: 2620:108:700f::22d2:b01f
[DEBUG] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: resolved record: 2620:108:700f::22d7:fa17
[DEBUG] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: resolved record: 2620:108:700f::6415:4c4c
[DEBUG] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: resolved record: 2620:108:700f::2351:30a6
[DEBUG] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: resolved record: 2620:108:700f::3421:1d4e
[DEBUG] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: resolved record: 2620:108:700f::342b:929
[DEBUG] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static, resolving host #############-ats.iot.us-west-2.amazonaws.com successful, returned 16 addresses
[TRACE] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: updating expiry for 34.213.168.191 for host #############-ats.iot.us-west-2.amazonaws.com to 1623887576445112777
[TRACE] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: updating expiry for 52.35.137.184 for host #############-ats.iot.us-west-2.amazonaws.com to 1623887576445112777
[TRACE] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: updating expiry for 54.148.88.142 for host #############-ats.iot.us-west-2.amazonaws.com to 1623887576445112777
[TRACE] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: updating expiry for 34.214.249.117 for host #############-ats.iot.us-west-2.amazonaws.com to 1623887576445112777
[TRACE] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: updating expiry for 54.186.43.162 for host #############-ats.iot.us-west-2.amazonaws.com to 1623887576445112777
[TRACE] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: updating expiry for 52.38.221.226 for host #############-ats.iot.us-west-2.amazonaws.com to 1623887576445112777
[TRACE] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: updating expiry for 54.244.33.231 for host #############-ats.iot.us-west-2.amazonaws.com to 1623887576445112777
[TRACE] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: updating expiry for 34.218.88.107 for host #############-ats.iot.us-west-2.amazonaws.com to 1623887576445112777
[TRACE] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: updating expiry for 2620:108:700f::23a6:36ae for host #############-ats.iot.us-west-2.amazonaws.com to 1623887576445112777
[TRACE] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: updating expiry for 2620:108:700f::3424:419e for host #############-ats.iot.us-west-2.amazonaws.com to 1623887576445112777
[TRACE] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: updating expiry for 2620:108:700f::22d2:b01f for host #############-ats.iot.us-west-2.amazonaws.com to 1623887576445112777
[TRACE] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: updating expiry for 2620:108:700f::22d7:fa17 for host #############-ats.iot.us-west-2.amazonaws.com to 1623887576445112777
[TRACE] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: updating expiry for 2620:108:700f::6415:4c4c for host #############-ats.iot.us-west-2.amazonaws.com to 1623887576445112777
[TRACE] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: updating expiry for 2620:108:700f::2351:30a6 for host #############-ats.iot.us-west-2.amazonaws.com to 1623887576445112777
[TRACE] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: updating expiry for 2620:108:700f::3421:1d4e for host #############-ats.iot.us-west-2.amazonaws.com to 1623887576445112777
[TRACE] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: updating expiry for 2620:108:700f::342b:929 for host #############-ats.iot.us-west-2.amazonaws.com to 1623887576445112777
[TRACE] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: remaining record count for host 7
[TRACE] [2021-06-16T23:52:26Z] [00007fd7ab15b640] [dns] - static: remaining record count for host 8

A run that succeeded continues on from the Publishing on topic test/unittest message with:

[TRACE] [2021-06-16T23:56:36Z] [00007f5fcfbbc640] [mqtt-client] - id=0x5565ac073640: publish received with msg id=1 dup=0 qos=1 retain=0 payload-size=16 topic=test/unittest
[TRACE] [2021-06-16T23:56:36Z] [00007f5fcfbbc640] [mqtt-client] - id=0x5565ac073640: received publish QOS is 1, sending puback
<<<output continues until normal termination>>>

Versions:

  boto3==1.17.96
  awscrt==0.11.22
  awsiotsdk==1.6.0

I created my mqtt connection using:

mqtt_connection_builder.websockets_with_default_aws_signing(
                    endpoint='#############-ats.iot.us-west-2.amazonaws.com',
                    client_bootstrap=client_bootstrap,
                    region=AWS_REGION,
                    credentials_provider=credentials_provider,
                    ca_filepath=f'{self.certs_temp_dir.name}/AmazonRootCA1.pem',
                    on_connection_interrupted=self._on_connection_interrupted,
                    on_connection_resumed=self._on_connection_resumed,
                    client_id=f'test-{uuid.uuid4()}',
                    clean_session=False,
                    keep_alive_secs=6
                )


from AWS MQTT Python awsiotsdk and awscrt packages fail sporadically with repeating messages in trace logs

No comments:

Post a Comment