php-mqtt/client

SSL connection interrupted

samo9789 opened this issue · 7 comments

Hi,

We have an application checking the status of an IoT device very frequently and forever. ...
Every now and then, we get the message SSL connection interrupted

Thankfully, next run, a new connection is established and the app still works but we are wondering if there could be any feedback on why the connection gets interrupted and if the duration of this connection can be controlled via a setting or something

thank you

Can you show me the code which connects to the broker and checks the status? Sounds like a timeout issue to me.

Sure

Artisan::command('start', function () {
    foreach (Route::getRoutes()->get('POST') as $route) {
        $routesMqtt = explode('/', $route->uri());
        unset($routesMqtt[0]);
        $routesMqtt = implode('/', $routesMqtt);

        Mqtt::subscribe('lockers/' . env('MQTT_CLIENT_ID') . '/' . $routesMqtt, function (string $topic, string $message) use ($route) {
            $message = json_decode($message, true) ?: [];
            if (isset($message['requestId'])) {
                $request = Request::create($route->uri(), 'POST', $message);
                app()->handle($request);
            }
        });
    }

    $lastCheck = Carbon::now();
    $oldStatus = LockersChip::status();
    if (!$oldStatus || !is_array($oldStatus)) {
        Log::critical('Corrupt data format : Init locker -> $oldStatus', [
            'oldStatus' => $oldStatus,
            'class' => 'routes/console.php',
            'time' => Carbon::now()->toISOString()
        ]);
        while (true) {
            $oldStatus = LockersChip::status();
            if ($oldStatus != null && is_array($oldStatus)) {
                break;
            }
        }
    }

    Mqtt::registerLoopEventHandler(function () use (&$lastCheck, &$oldStatus) {
        if (Carbon::now()->diffInMilliseconds($lastCheck) > 200) {
            $currentStatus = LockersChip::status();
            if ($currentStatus != null && is_array($currentStatus)) {
                if ($change = LockersChip::statusDiff($currentStatus, $oldStatus)) {
                    Send::success('lockers/' . env('MQTT_CLIENT_ID') . '/webhook', [
                        'requestId' => null,
                        'success' => true,
                        'body' => $change
                    ], []);

                    $oldStatus = $currentStatus;
                }
            } else {
                Log::critical('Corrupt data format : Check diff status -> $currentStatus', [
                    'currentStatus' => $currentStatus,
                    'class' => 'routes/console.php:registerLoopEventHandler',
                    'time' => Carbon::now()->toISOString()
                ]);
            }
            $lastCheck = Carbon::now();
        }
    });

    Mqtt::loop();
});

We get this error

Message
fread(): SSL: Connection timed out
Level
ERROR
LockerId
2
Exception
{
    "class": "ErrorException",
    "message": "fread(): SSL: Connection timed out",
    "code": 0,
    "file": "/home/pi/Matt/vendor/php-mqtt/client/src/MqttClient.php:1058",
    "trace": [
        "/home/pi/Matt/vendor/php-mqtt/client/src/MqttClient.php:1058",
        "/home/pi/Matt/vendor/php-mqtt/client/src/MqttClient.php:1113",
        "/home/pi/Matt/vendor/php-mqtt/client/src/MqttClient.php:586",
        "/home/pi/Matt/app/Services/Mqtt/Mqtt.php:19",
        "/home/pi/Matt/vendor/laravel/framework/src/Illuminate/Support/Facades/Facade.php:261",
        "/home/pi/Matt/routes/console.php:77",
        "/home/pi/Matt/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php:36",
        "/home/pi/Matt/vendor/laravel/framework/src/Illuminate/Container/Util.php:40",
        "/home/pi/Matt/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php:81",
        "/home/pi/Matt/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php:37",
        "/home/pi/Matt/vendor/laravel/framework/src/Illuminate/Container/Container.php:614",
        "/home/pi/Matt/vendor/laravel/framework/src/Illuminate/Foundation/Console/ClosureCommand.php:55",
        "/home/pi/Matt/vendor/symfony/console/Command/Command.php:288",
        "/home/pi/Matt/vendor/laravel/framework/src/Illuminate/Console/Command.php:121",
        "/home/pi/Matt/vendor/symfony/console/Application.php:974",
        "/home/pi/Matt/vendor/symfony/console/Application.php:291",
        "/home/pi/Matt/vendor/symfony/console/Application.php:167",
        "/home/pi/Matt/vendor/laravel/framework/src/Illuminate/Console/Application.php:92",
        "/home/pi/Matt/vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php:129",
        "/home/pi/Matt/artisan:37"
    ]
}

Sometimes we also get this one but we are not sure the two are linked

Matt
APP  8:58 AM

Message
MQTT [{host}:{port}] [{clientId}] Sending data over the socket to the broker failed.
Level
ERROR
LockerId
2
Host
iot.fr-par.scw.cloud
Port
8883
ClientId
7b6cf628698f3e08f173
Today at 8:58 AM
8:58
Message
[65] Transferring data over socket failed: Sending data over the socket failed. Has it been closed?
Level
ERROR
LockerId
2
Exception
{
    "class": "PhpMqtt\\Client\\Exceptions\\DataTransferException",
    "message": "[65] Transferring data over socket failed: Sending data over the socket failed. Has it been closed?",
    "code": 65,
    "file": "/home/pi/Matt/vendor/php-mqtt/client/src/MqttClient.php:1030",
    "trace": [
        "/home/pi/Matt/vendor/php-mqtt/client/src/MqttClient.php:994",
        "/home/pi/Matt/vendor/php-mqtt/client/src/MqttClient.php:603",
        "/home/pi/Matt/app/Services/Mqtt/Mqtt.php:19",
        "/home/pi/Matt/vendor/laravel/framework/src/Illuminate/Support/Facades/Facade.php:261",
        "/home/pi/Matt/routes/console.php:77",
        "/home/pi/Matt/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php:36",
        "/home/pi/Matt/vendor/laravel/framework/src/Illuminate/Container/Util.php:40",
        "/home/pi/Matt/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php:81",
        "/home/pi/Matt/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php:37",
        "/home/pi/Matt/vendor/laravel/framework/src/Illuminate/Container/Container.php:614",
        "/home/pi/Matt/vendor/laravel/framework/src/Illuminate/Foundation/Console/ClosureCommand.php:55",
        "/home/pi/Matt/vendor/symfony/console/Command/Command.php:288",
        "/home/pi/Matt/vendor/laravel/framework/src/Illuminate/Console/Command.php:121",
        "/home/pi/Matt/vendor/symfony/console/Application.php:974",
        "/home/pi/Matt/vendor/symfony/console/Application.php:291",
        "/home/pi/Matt/vendor/symfony/console/Application.php:167",
        "/home/pi/Matt/vendor/laravel/framework/src/Illuminate/Console/Application.php:92",
        "/home/pi/Matt/vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php:129",
        "/home/pi/Matt/artisan:37"
    ]
}

Thank you

Your approach looks complicated but fine in general. Is there anything in the process (especially within the registerLoopEventHandler callback) that takes multiple seconds to complete?

The errors indicate a timeout, which occurs if the socket to the broker was closed. There can be many reasons for this, some examples:

  • An actual timeout occurred. If e.g. 30 seconds are configured as socket timeout and no ping is sent within this time frame, the socket may be closed by either the client or the broker. The timeout depends both on the client and the server.
    A timeout can occur, if the registered loop event handlers take a very long time to complete (multiple seconds).
  • The broker or a proxy may have closed the connection due to an excess of some kind of rate limit. I'm not familiar with Scaleway, but I doubt this is the case.
  • The broker or a proxy may have closed the connection due to a restart / application update on their end. As I'm not familiar with Scaleway, I cannot tell whether that's the case on a regular basis or not.

Hello,

Offering an other information, the code above is deployed on 6 IoT devices but only one of them randomly produces this error. 5 devices are using ethernet connections, that one is connecting via a 4G key

Could a network error (short interruption, something induced by the 4G) be the cause of this error ?

Thanks for your support !

I'm not really experienced with mobile connections, so I'm not sure how SSL works when e.g. switching between mobile towers. But from my limited knowledge, I'm quite sure connections are transparently switched over, so this shouldn't be an issue on the server side.

However, because mobile connections have higher latency, timeouts could be more frequent - especially with low keep alive intervals. What have you set as keep alive interval and can you easily try increasing it on the mobile client to grant some more tolerance? The latency with 4G should be rather low normally, but that's my best guess right now.

Hi,

Thanks for your answer, we are investigating in that direction. We increased the timeout and we will also see about switching another device to 4G to confirm that this is the root cause.

Thanks for your support !

@samo9789 Do you have any news on this topic? Were you successful by increasing the timeout(s)?