sendEvent message size/quota exceeded errors not reported

[bragma]

Context

• OS and version used: Windows 10

• Node.js version: v10.13.0

• npm version: 6.4.1

• list of installed packages: +-- azure-iot-device@1.9.3 | +-- azure-iot-common@1.9.3 | | -- getos@3.1.1 | |-- async@2.6.1 | | -- lodash@4.17.11 deduped | +-- azure-iot-http-base@1.9.3 | | +-- azure-iot-common@1.9.3 deduped | | +-- debug@3.2.6 deduped | |-- uuid@3.3.2 deduped | +-- azure-storage@2.10.2 | | +-- browserify-mime@1.2.9 | | +-- extend@3.0.2 | | +-- json-edm-parser@0.1.2 | | | -- jsonparse@1.2.0 | | +-- md5.js@1.3.4 | | | +-- hash-base@3.0.4 | | | | +-- inherits@2.0.3 deduped | | | |-- safe-buffer@5.1.2 deduped | | | -- inherits@2.0.3 | | +-- readable-stream@2.0.6 | | | +-- core-util-is@1.0.2 | | | +-- inherits@2.0.3 deduped | | | +-- isarray@1.0.0 | | | +-- process-nextick-args@1.0.7 | | | +-- string_decoder@0.10.31 | | |-- util-deprecate@1.0.2 | | +-- request@2.88.0 | | | +-- aws-sign2@0.7.0 | | | +-- aws4@1.8.0 | | | +-- caseless@0.12.0 | | | +-- combined-stream@1.0.7 | | | | -- delayed-stream@1.0.0 | | | +-- extend@3.0.2 deduped | | | +-- forever-agent@0.6.1 | | | +-- form-data@2.3.3 | | | | +-- asynckit@0.4.0 | | | | +-- combined-stream@1.0.7 deduped | | | |-- mime-types@2.1.22 deduped | | | +-- har-validator@5.1.3 | | | | +-- ajv@6.10.0 | | | | | +-- fast-deep-equal@2.0.1 | | | | | +-- fast-json-stable-stringify@2.0.0 | | | | | +-- json-schema-traverse@0.4.1 | | | | | -- uri-js@4.2.2 | | | | |-- punycode@2.1.1 | | | | -- har-schema@2.0.0 | | | +-- http-signature@1.2.0 | | | | +-- assert-plus@1.0.0 | | | | +-- jsprim@1.4.1 | | | | | +-- assert-plus@1.0.0 deduped | | | | | +-- extsprintf@1.3.0 | | | | | +-- json-schema@0.2.3 | | | | |-- verror@1.10.0 | | | | | +-- assert-plus@1.0.0 deduped | | | | | +-- core-util-is@1.0.2 deduped | | | | | -- extsprintf@1.3.0 deduped | | | |-- sshpk@1.16.1 | | | | +-- asn1@0.2.4 | | | | | -- safer-buffer@2.1.2 deduped | | | | +-- assert-plus@1.0.0 deduped | | | | +-- bcrypt-pbkdf@1.0.2 | | | | |-- tweetnacl@0.14.5 deduped | | | | +-- dashdash@1.14.1 | | | | | -- assert-plus@1.0.0 deduped | | | | +-- ecc-jsbn@0.1.2 | | | | | +-- jsbn@0.1.1 deduped | | | | |-- safer-buffer@2.1.2 deduped | | | | +-- getpass@0.1.7 | | | | | -- assert-plus@1.0.0 deduped | | | | +-- jsbn@0.1.1 | | | | +-- safer-buffer@2.1.2 | | | |-- tweetnacl@0.14.5 | | | +-- is-typedarray@1.0.0 | | | +-- isstream@0.1.2 | | | +-- json-stringify-safe@5.0.1 | | | +-- mime-types@2.1.22 | | | | -- mime-db@1.38.0 | | | +-- oauth-sign@0.9.0 | | | +-- performance-now@2.1.0 | | | +-- qs@6.5.2 | | | +-- safe-buffer@5.1.2 | | | +-- tough-cookie@2.4.3 | | | | +-- psl@1.1.31 | | | |-- punycode@1.4.1 | | | +-- tunnel-agent@0.6.0 | | | | -- safe-buffer@5.1.2 deduped | | |-- uuid@3.3.2 deduped | | +-- underscore@1.8.3 | | +-- uuid@3.3.2 deduped | | +-- validator@9.4.1 | | +-- xml2js@0.2.8 | | | -- sax@0.5.8 | |-- xmlbuilder@9.0.7 | +-- debug@3.2.6 | | -- ms@2.1.1 | +-- lodash@4.17.11 | +-- machina@4.0.2 | |-- lodash@4.17.11 deduped | -- traverse@0.6.6 -- azure-iot-device-mqtt@1.9.3 +-- azure-iot-common@1.9.3 deduped +-- azure-iot-device@1.9.3 deduped +-- azure-iot-mqtt-base@1.9.3 | +-- azure-iot-common@1.9.3 deduped | +-- debug@3.2.6 deduped | +-- machina@4.0.2 deduped | -- mqtt@2.18.8 | +-- commist@1.1.0 | | +-- leven@2.1.0 | |-- minimist@1.2.0 deduped | +-- concat-stream@1.6.2 | | +-- buffer-from@1.1.1 | | +-- inherits@2.0.3 deduped | | +-- readable-stream@2.3.6 | | | +-- core-util-is@1.0.2 deduped | | | +-- inherits@2.0.3 deduped | | | +-- isarray@1.0.0 deduped | | | +-- process-nextick-args@2.0.0 | | | +-- safe-buffer@5.1.2 deduped | | | +-- string_decoder@1.1.1 | | | | -- safe-buffer@5.1.2 deduped | | |-- util-deprecate@1.0.2 deduped | | -- typedarray@0.0.6 | +-- end-of-stream@1.4.1 | |-- once@1.4.0 | | -- wrappy@1.0.2 | +-- es6-map@0.1.5 | | +-- d@1.0.0 | | |-- es5-ext@0.10.48 deduped | | +-- es5-ext@0.10.48 | | | +-- es6-iterator@2.0.3 deduped | | | +-- es6-symbol@3.1.1 deduped | | | -- next-tick@1.0.0 | | +-- es6-iterator@2.0.3 | | | +-- d@1.0.0 deduped | | | +-- es5-ext@0.10.48 deduped | | |-- es6-symbol@3.1.1 deduped | | +-- es6-set@0.1.5 | | | +-- d@1.0.0 deduped | | | +-- es5-ext@0.10.48 deduped | | | +-- es6-iterator@2.0.3 deduped | | | +-- es6-symbol@3.1.1 deduped | | | -- event-emitter@0.3.5 deduped | | +-- es6-symbol@3.1.1 | | | +-- d@1.0.0 deduped | | |-- es5-ext@0.10.48 deduped | | -- event-emitter@0.3.5 | | +-- d@1.0.0 deduped | |-- es5-ext@0.10.48 deduped | +-- help-me@1.1.0 | | +-- callback-stream@1.1.0 | | | +-- inherits@2.0.3 deduped | | | -- readable-stream@2.0.6 deduped | | +-- glob-stream@6.1.0 | | | +-- extend@3.0.2 deduped | | | +-- glob@7.1.3 | | | | +-- fs.realpath@1.0.0 | | | | +-- inflight@1.0.6 | | | | | +-- once@1.4.0 deduped | | | | |-- wrappy@1.0.2 deduped | | | | +-- inherits@2.0.3 deduped | | | | +-- minimatch@3.0.4 | | | | | -- brace-expansion@1.1.11 | | | | | +-- balanced-match@1.0.0 | | | | |-- concat-map@0.0.1 | | | | +-- once@1.4.0 deduped | | | | -- path-is-absolute@1.0.1 | | | +-- glob-parent@3.1.0 | | | | +-- is-glob@3.1.0 | | | | |-- is-extglob@2.1.1 | | | | -- path-dirname@1.0.2 | | | +-- is-negated-glob@1.0.0 | | | +-- ordered-read-streams@1.0.1 | | | |-- readable-stream@2.0.6 deduped | | | +-- pumpify@1.5.1 | | | | +-- duplexify@3.7.1 deduped | | | | +-- inherits@2.0.3 deduped | | | | -- pump@2.0.1 | | | | +-- end-of-stream@1.4.1 deduped | | | |-- once@1.4.0 deduped | | | +-- readable-stream@2.3.6 | | | | +-- core-util-is@1.0.2 deduped | | | | +-- inherits@2.0.3 deduped | | | | +-- isarray@1.0.0 deduped | | | | +-- process-nextick-args@2.0.0 | | | | +-- safe-buffer@5.1.2 deduped | | | | +-- string_decoder@1.1.1 | | | | | -- safe-buffer@5.1.2 deduped | | | |-- util-deprecate@1.0.2 deduped | | | +-- remove-trailing-separator@1.1.0 | | | +-- to-absolute-glob@2.0.2 | | | | +-- is-absolute@1.0.0 | | | | | +-- is-relative@1.0.0 | | | | | | -- is-unc-path@1.0.0 | | | | | |-- unc-path-regex@0.1.2 | | | | | -- is-windows@1.0.2 | | | |-- is-negated-glob@1.0.0 deduped | | | -- unique-stream@2.3.1 | | | +-- json-stable-stringify-without-jsonify@1.0.1 | | |-- through2-filter@3.0.0 | | | +-- through2@2.0.5 deduped | | | -- xtend@4.0.1 deduped | | +-- through2@2.0.5 | | | +-- readable-stream@2.3.6 | | | | +-- core-util-is@1.0.2 deduped | | | | +-- inherits@2.0.3 deduped | | | | +-- isarray@1.0.0 deduped | | | | +-- process-nextick-args@2.0.0 | | | | +-- safe-buffer@5.1.2 deduped | | | | +-- string_decoder@1.1.1 | | | | |-- safe-buffer@5.1.2 deduped | | | | -- util-deprecate@1.0.2 deduped | | |-- xtend@4.0.1 deduped | | -- xtend@4.0.1 deduped | +-- inherits@2.0.3 deduped | +-- minimist@1.2.0 | +-- mqtt-packet@5.6.0 | | +-- bl@1.2.2 | | | +-- readable-stream@2.3.6 | | | | +-- core-util-is@1.0.2 deduped | | | | +-- inherits@2.0.3 deduped | | | | +-- isarray@1.0.0 deduped | | | | +-- process-nextick-args@2.0.0 | | | | +-- safe-buffer@5.1.2 deduped | | | | +-- string_decoder@1.1.1 | | | | |-- safe-buffer@5.1.2 deduped | | | | -- util-deprecate@1.0.2 deduped | | |-- safe-buffer@5.1.2 deduped | | +-- inherits@2.0.3 deduped | | +-- process-nextick-args@2.0.0 | | -- safe-buffer@5.1.2 deduped | +-- pump@3.0.0 | | +-- end-of-stream@1.4.1 deduped | |-- once@1.4.0 deduped | +-- readable-stream@2.3.6 | | +-- core-util-is@1.0.2 deduped | | +-- inherits@2.0.3 deduped | | +-- isarray@1.0.0 deduped | | +-- process-nextick-args@2.0.0 | | +-- safe-buffer@5.1.2 deduped | | +-- string_decoder@1.1.1 | | | -- safe-buffer@5.1.2 deduped | |-- util-deprecate@1.0.2 deduped | +-- reinterval@1.1.0 | +-- split2@2.2.0 | | -- through2@2.0.5 deduped | +-- websocket-stream@5.1.2 | | +-- duplexify@3.7.1 | | | +-- end-of-stream@1.4.1 deduped | | | +-- inherits@2.0.3 deduped | | | +-- readable-stream@2.0.6 deduped | | |-- stream-shift@1.0.0 | | +-- inherits@2.0.3 deduped | | +-- readable-stream@2.3.6 | | | +-- core-util-is@1.0.2 deduped | | | +-- inherits@2.0.3 deduped | | | +-- isarray@1.0.0 deduped | | | +-- process-nextick-args@2.0.0 | | | +-- safe-buffer@5.1.2 deduped | | | +-- string_decoder@1.1.1 | | | | -- safe-buffer@5.1.2 deduped | | |-- util-deprecate@1.0.2 deduped | | +-- safe-buffer@5.1.2 deduped | | +-- ws@3.3.3 | | | +-- async-limiter@1.0.0 | | | +-- safe-buffer@5.1.2 deduped | | | -- ultron@1.1.1 | |-- xtend@4.0.1 deduped | -- xtend@4.0.1 +-- debug@3.2.6 deduped +-- machina@4.0.2 deduped -- uuid@3.3.2

• cloned repo: NO

Description of the issue:

mqtt.sendEvent does not call the specified callback if the message size is larger than the max accepted by IoT Hub. In my code I am using a race between sendEvent (promisified) and a timeout promise. I've noticed that in some cases it always times out and found the root cause to be sendEvent not notifying anything if the supplied message is too large. This should never happen as it can break external logic.

Notice that NoRetry should not be involved, since this sent attempt will never succeed.

UPDATED: This also seems to happen if the Hub daily quota of messages has been exceeded.

Code sample exhibiting the issue:

'use strict';
var connectionString = 'MYHUBCONNECTIONSTRING';

var Mqtt = require('azure-iot-device-mqtt').Mqtt;
var DeviceClient = require('azure-iot-device').Client;
var Message = require('azure-iot-device').Message;

var client = DeviceClient.fromConnectionString(connectionString, Mqtt);

// Print results.
function printResultFor(op) {
  return function printResult(err, res) {
    if (err) console.log(op + ' error: ' + err.toString());
    if (res) console.log(op + ' status: ' + res.constructor.name);
  };
}

var msgCount = 240;

// Create a message and send it to the IoT hub every second
setInterval(function(){
  var data = JSON.stringify({ data: 'x'.repeat(1024 * msgCount) });
  console.log("Message length: ", data.length);

  var message = new Message(data);

  client.sendEvent(message, printResultFor('send'));

  msgCount++;
}, 1000);

Console log of the issue:

C:\Devel\iot>node send-size.js
Message length:  245771
send status: MessageEnqueued
Message length:  246795
send status: MessageEnqueued
...
Message length:  260107
send status: MessageEnqueued
Message length:  261131
send status: MessageEnqueued
Message length:  262155 <-- NO MORE CALLBACKS
Message length:  263179
Message length:  264203
Message length:  265227
Message length:  266251

AB#7366638

[pierreca]

Thanks for reporting this. it definitely sounds like a bug. We'll try to set up a repro and comment if we have more questions.

[pierreca]

On initial investigation it looks like the service bluntly disconnects the client when the message is too big, without giving a proper error. At that point the retry logic kicks in, which is why you're not getting notified until much later (probably around 4 or 5 minutes later).

When using MQTT I'm not sure there is a mechanism for the service to notify the client which type of error is causing the disconnection. I need to dig into it a little bit more to figure out if there's anything "hidden" in the MQTT library that we should pay attention to to help us detect that (either an error, or some client-side validation...).

we generally shy away from client-side validation because it's a very good way to have the SDK and the service capabilities diverge. This being said nothing prevents you from testing this on your end.

I will have a chat with the service team to see if this is something we can address and update this issue accordingly.

[bragma]

Thanks. Considering how often services are updated, it's ok to try to avoid client-side checks, but then server-side errors must be properly reported. If this is not possible, it will be in some cases force the client to check that. In this specific case, no retry will fix it until something times out. In our code, where retry is disabled and sendEvent races with our timeout timer, we totally missed the problem until we noticed the missing data on the server side. Some way of detecting the error could have helped out a lot.

[pierreca]

Considering how often services are updated, it's ok to try to avoid client-side checks, but then server-side errors must be properly reported. If this is not possible, it will be in some cases force the client to check that

I agree with that and just had a talk with the service team. There's no way for them to signal us what error caused the disconnect, which means we need a client side check. I also looked at mqtt.js features and it doesn't seem like they have a mechanism to check/limit message size.

To get around the problem you faced, we're going to have to build it directly into the SDK itself. I'll add this to our backlog and check if other SDKs do it.

[pierreca]

FYI I'm working on a small PR on the mqttjs/mqtt-packet project. This is where the code that compute the packet size resides and I think it'd be dangerous to duplicate this in our SDK. I'm going to see if they would be OK with accepting an additional feature that allows for client-side packet size checking.

One of the reason they may not accept this is that it collides with new MQTT 5 features that allow this sort of limitations as part of the protocol, when the device first connect. MQTT 5 also has error codes in the PUBACK which would allow to return an error type. Therefore there are no guarantees that they will accept this PR. if they refuse, we can always reconsider adding packet-size computation into the SDK

Last but not least, a friend from the service team suggested to use Azure Monitoring to check for errors on the service side. A device probably wouldn't connect to Azure Monitoring but your service application could and then it could diagnose why a device is failing to send messages (doesn't help the dev experience on the device but at least offers the IoT solution developer an option).

By the way, quota exceeded is an error that the SDK won't be able to cover and for which the service will just disconnect the device. This is the appropriate service behavior in MQTT (see the last line of section 3.3.5 of the MQTT specification)

All in all I guess we just have to live with the limitations of the transport protocol. AMQP is a tad more complicated and heavy weight but does enable richer error handling.

[pierreca]

update - the fix is bigger than expected (needs at least 3PRs in different repos) so I'm considering a different way of doing it (ie expose an API to compute the packet size on mqtt-packet rather than bubble up errors and add configuration APIs on mqtt.js)

[anthonyvercolano]

This is an issue that we won't fix in the current implementation of the SDK.

[anthonyvercolano]

Does not actually seem closed. Trying again