samemory / homebridge-eufy-security

Work in progress
Apache License 2.0
97 stars 14 forks source link

[Bug]: [BETA] [ERR_SOCKET_DGRAM_NOT_RUNNING] Error that makes HB restart every time stream stops #321

Closed njuart closed 2 years ago

njuart commented 2 years ago

What happened?

Hi, while testing BETA I experience this error [ERR_SOCKET_DGRAM_NOT_RUNNING]. It makes HB restart every time I stop stream within Home app. As I've put Eufy plugin in child bridge, it restart only child bridge, so it helps a bit. As I recall, this issue is present since earliest BETA and was also reported by other users. Can you please have a look? Thx in advance for this amazing plugin!

Device Type

Indoor Camera (Supported)

Plugin Version

beta (Best Effort)

HomeBridge Version

v1.3.x (Supported)

NodeJS Version

v16 (Supported)

Operating System

Raspbian 10+ (Supported)

Relevant log output

[03/01/2022, 18:35:56] [homebridge-eufy-security] Eufy camera Starting video stream: 1280 x 720, 30 fps, 299 kbps (AAC-eld)
[03/01/2022, 18:36:05] [homebridge-eufy-security] Eufy camera Eufy Station stopped the stream. Stopping stream.
[03/01/2022, 18:36:05] [homebridge-eufy-security] Eufy camera Stopped video stream.
[03/01/2022, 18:36:05] [homebridge-eufy-security] Eufy camera Error occurred closing socket: Error [ERR_SOCKET_DGRAM_NOT_RUNNING]: Not running
[03/01/2022, 18:36:05] [homebridge-eufy-security] Eufy camera Stopped video stream.
Error: read ECONNRESET
    at Pipe.onStreamRead (node:internal/stream_base_commons:220:20)
[03/01/2022, 18:36:06] [homebridge-eufy-security] Child bridge process ended
[03/01/2022, 18:36:06] [homebridge-eufy-security] Process Ended. Code: 1, Signal: null
[03/01/2022, 18:36:13] [homebridge-eufy-security] Restarting Process...
github-actions[bot] commented 2 years ago

Did you check this Common Issues pages ?

lenoxys commented 2 years ago

can you enable debug ? while doing the test ? https://github.com/samemory/homebridge-eufy-security/wiki/Basic-Troubleshooting#debug-mode

njuart commented 2 years ago

can you enable debug ? while doing the test ? https://github.com/samemory/homebridge-eufy-security/wiki/Basic-Troubleshooting#debug-mode

Done, it's log since stream starts and until I stop it

homebridge.log.txt

schliemann commented 2 years ago

I'm experiencing the same. Tried to tinker around with it myself without succeeding.

The refactoring you have made, @lenoxys, is however very nice.

schliemann commented 2 years ago

Got another idea. Will test tonight.

lenoxys commented 2 years ago

the timeout is hardcoded within @bropat lib https://github.com/bropat/eufy-security-client/blob/master/src/eufysecurity.ts#L38

It could be nice if we can change that.

I've open a request https://github.com/bropat/eufy-security-client/issues/96

bropat commented 2 years ago

@lenoxys

That is wrong. This is the default value.

See here

njuart commented 2 years ago

Will gladly help to test if needed

lenoxys commented 2 years ago

Sorry miss the function !! thanks for your feedback !!

schliemann commented 2 years ago

To fix the stream you have to unpipe the readable stream in UniversalStream.ts. To have the reference in the close method the stream has to be saved as a variable on the NamePipeStream class.

this.stream.unpipe();

            import net from 'net'
            import fs from 'fs'
            import os from 'os'
            import { Readable } from 'stream';

            let counter = 0

            export class NamePipeStream {
                private server;
                private sock_id;
                private log;
                public url;
                private stream: Readable;

                constructor(stream, onSocket, log) {
                    this.log = log;
                    this.stream = stream;
                    let path

                    this.sock_id = ++counter

                    const osType = os.type()
                    if (osType === 'Windows_NT') {
                        path = '\\\\.\\pipe\\stream' + (++counter)
                        this.url = path
                    } else {
                        path = './' + (++counter) + '.sock'
                        this.url = 'unix:' + path
                    }

                    try {
                        fs.statSync(path)
                        fs.unlinkSync(path)
                    } catch (err) { }
                    this.server = net.createServer(onSocket)
                    stream.on('finish', () => {
                        this.server.close()
                    })

                     this.server.on('error', (err: Error) => {
                         this.log.error('Error in NamePipe', err.message, err.stack);
                     });

                     this.server.on('close', (err: Error) => {
                        this.log.error('Error in NamePipe', err.message, err.stack);
                    });

                    this.server.listen(path)
                }
                close() {
                    this.log.info('Trying to close NamePipeStream.')
                    if (this.server)
                    {
                        this.stream.unpipe();

                        this.server.close();
                        this.log.info('Closed NamePipeStream')
                    }
                }
            }

            export function StreamInput(stream, log) {
                return new NamePipeStream(stream, socket => stream.pipe(socket), log)
            }

            export function StreamOutput(stream, log) {
                return new NamePipeStream(stream, socket => socket.pipe(stream), log)
            }

image

🎉

schliemann commented 2 years ago

Also we should add a null guard on:

                 this.server.on('error', (err: Error) => {
                     this.log.error('Error in NamePipe', err.message, err.stack);
                 });

to this:

                 this.server.on('error', (err: Error) => {
                     this.log.error('Error in NamePipe', err?.message, err?.stack);
                 });

For some reason sometimes the stream throws an error where the error object is null or undefined.

schliemann commented 2 years ago

@lenoxys Do you want me to make the change or would you like to test yourself?

lenoxys commented 2 years ago

Let me test

lenoxys commented 2 years ago

yes indeed it's better that way !

schliemann commented 2 years ago

@lenoxys

In the below code we have a problem however. Here we never unpipe our namedPipeStreams. Resulting in the same error as previously. Line 509 will break things.

https://github.com/samemory/homebridge-eufy-security/blob/7584d96b4a9a21baa260f8ec96342d5d7e83d939/src/accessories/streamingDelegate.ts#L498-L513

schliemann commented 2 years ago

We could of course add both uAudioStream and uVideoStream to the activeSession and just call stopStream directly every time. Just can't seem to make it work.

schliemann commented 2 years ago

@lenoxys Or we should find another way to gracefully stop the namePibeStream instead. Because we can never ensure that the stream won't end before we close our pipe.

If the station stops the stream this error will always bubble through and kill our process.

Unless we catch the error on the NamePibeStream

https://medium.com/developers-arena/streams-piping-and-their-error-handling-in-nodejs-c3fd818530b6

lenoxys commented 2 years ago

We could of course add both uAudioStream and uVideoStream to the activeSession and just call stopStream directly every time. Just can't seem to make it work.

Would be proper approach at least if we rely on other thing

schliemann commented 2 years ago

@lenoxys If you change the pipe here:

https://github.com/samemory/homebridge-eufy-security/blob/e38d24a8ffd1e77dcc63fff9712910f7ff3c209f/src/accessories/UniversalStream.ts#L63

to this: return new NamePipeStream(stream, socket => stream.pipe(socket).on('error', function(e){log.error(e)}), who, log)

We no longer break hard on econnreset. This is probably a good idea since it is not in our control.

Example of caught econnreset:

image

schliemann commented 2 years ago

Maybe the pipe creation should also be moved into the class instead of through the constructor. And then on error should call close?

schliemann commented 2 years ago

I have some changes I will test later tonight regarding the UniversalStream.

lenoxys commented 2 years ago

Maybe the pipe creation should also be moved into the class instead of through the constructor. And then on error should call close?

agree this need to be rewrite with cleaner manner. I was using this part from @bropat script :

https://github.com/bropat/ioBroker.eufy-security/blob/master/src/lib/video.ts#L14-L65

But we should avoid passing a function into argument of a function.

lenoxys commented 2 years ago

I have some changes I will test later tonight regarding the UniversalStream.

I let you follow this part I will be off couple of week. thanks for your help on this !

schliemann commented 2 years ago

@lenoxys Can you test the changes to the beta streaming before we make a new version with the workflow?

Update - Ah. Nevermind. Can see that the workflow starts automatically.

schliemann commented 2 years ago

@njuart Would you be able to test beta v1.1.1-beta.14?

njuart commented 2 years ago

@njuart Would you be able to test beta v1.1.1-beta.14?

Sure, with pleasure 👍

njuart commented 2 years ago

@njuart Would you be able to test beta v1.1.1-beta.14?

Just checked latest beta.14, great news @schliemann ! HB doesn't crash and restart anymore after closing stream. Video is a bit laggy, sound is present. I also see this in logs:

[07/01/2022, 10:32:14] [homebridge-eufy-security] Eufy camera Starting video stream: 1280 x 720, 30 fps, 299 kbps (AAC-eld) [07/01/2022, 10:32:23] [homebridge-eufy-security] Stopping session with id: 0ddec022-cec3-44a9-afc8-36019e907688 [07/01/2022, 10:32:23] [homebridge-eufy-security] Eufy camera Eufy Station stopped the stream. Stopping stream. [07/01/2022, 10:32:23] [homebridge-eufy-security] Stopping session with id: 131b8a1c-10b5-4887-989d-4f977128f4ab [07/01/2022, 10:32:23] [homebridge-eufy-security] No session to stop. [07/01/2022, 10:32:23] [homebridge-eufy-security] Eufy camera Eufy Station stopped the stream. Stopping stream. [07/01/2022, 10:32:23] [homebridge-eufy-security] Stopping session with id: e06ddeda-0995-4bfc-8dab-b124cd9a067a [07/01/2022, 10:32:23] [homebridge-eufy-security] No session to stop. [07/01/2022, 10:32:23] [homebridge-eufy-security] Eufy camera Eufy Station stopped the stream. Stopping stream. [07/01/2022, 10:32:23] [homebridge-eufy-security] Stopping session with id: d210ffa7-4d67-4781-bbd4-cbfa4b638b45 [07/01/2022, 10:32:23] [homebridge-eufy-security] No session to stop. [07/01/2022, 10:32:23] [homebridge-eufy-security] Eufy camera Eufy Station stopped the stream. Stopping stream. [07/01/2022, 10:32:23] [homebridge-eufy-security] Stopping session with id: 0ddec022-cec3-44a9-afc8-36019e907688 [07/01/2022, 10:32:23] [homebridge-eufy-security] Eufy camera Stopped video stream. [07/01/2022, 10:32:23] [homebridge-eufy-security] Eufy camera Stopped video stream. [07/01/2022, 10:32:23] [homebridge-eufy-security] Eufy camera Error occurred closing socket: Error [ERR_SOCKET_DGRAM_NOT_RUNNING]: Not running [07/01/2022, 10:32:23] [homebridge-eufy-security] Connection closed by Eufy station. [07/01/2022, 10:32:23] [homebridge-eufy-security] ErrorCode ECONNRESET

schliemann commented 2 years ago

Perfect. There is obviously room for some logging cleanup :). But I will not prioritize this at the moment.

njuart commented 2 years ago

Perfect. There is obviously room for some logging cleanup :). But I will not prioritize this at the moment.

Thx for the efforts! 🤝 Since we're discussing stream here, is there any way I can increase streaming quality (or play with it to adjust)? Currently It looks pixelated a bit (comparing to regular web stream).

schliemann commented 2 years ago

@njuart Difficult for me to say. I agree it is a little bit pixelated. It might be the way we use ffmpeg. I would think that the stream from the client library is not the issue - since there is no issue on Bropat's github regarding the stream quality.

njuart commented 2 years ago

@schliemann Also noticed that stream is live for about 10-15 seconds, then image freezes and after another 10-15 seconds it shows No response.

schliemann commented 2 years ago

@schliemann Also noticed that stream is live for about 10-15 seconds, then image freezes and after another 10-15 seconds it shows No response.

Interesting. Mine will run for the maximum periode of 30 seconds and the the station kills it as expected.

https://user-images.githubusercontent.com/10818044/148524067-d08b1d6d-8229-4d63-85cf-d05be29fd761.MOV

fullphat commented 2 years ago

I don't know if it helps (I have the floodlight cam), but I've just swapped to the latest beta and I had to manually change the video codec in streamingDelegate.js to "copy". After doing this, local streaming works fine for me.

schliemann commented 2 years ago

@fullphat Can you try and add a logger line and print the this.videoConfig.vcodec you have when trying to start a stream. I am wondering why you don't have copy already.

fullphat commented 2 years ago

Done!

I get "undefined" in the log output.

schliemann commented 2 years ago

Ok. I'll add a null check then. But would you mind making an issue with bropat, as well?

fullphat commented 2 years ago

Yes, of course. What do I need to tell him?

schliemann commented 2 years ago

Yes, of course. What do I need to tell him?

Wait. It might be our plugin. Let me have a look.

schliemann commented 2 years ago

Yes, of course. What do I need to tell him?

Wait. It might be our plugin. Let me have a look.

@fullphat It's our bug. For some reason the floodlight doesn't like codec libx264. I'll put in copy later tonight.

schliemann commented 2 years ago

@fullphat Can't get my doorbell to work with 'copy'. Can you share your code-snippet?

schliemann commented 2 years ago

Ah. Problem is probably that the codec for the doorbell is not H.264 based.

Set the codec used for encoding video sent to HomeKit, must be H.264-based. You can change to a hardware accelerated video codec with this option, if one is available. (Default: libx264)

schliemann commented 2 years ago

@fullphat

Can you try and replace the following in your code and see if streaming works:

       const vcodec  = this.videoConfig.vcodec || 'libx264';

with this:

        let vcodec = '';
        switch(streamData.metadata.videoCodec) {
            case VideoCodec.H264:
                vcodec = 'copy';
                break;
            case VideoCodec.H265:
            case VideoCodec.UNKNOWN:
                vcodec = 'libx264';
                break;
        }
fullphat commented 2 years ago

My code snippet is:

            // const vcodec = this.videoConfig.vcodec || 'libx264';
            const vcodec = 'copy';
            this.log.debug('vcodec:', this.videoConfig.vcodec);

But I appreciate this will probably break everything else! 😄

I tried your code, but I get this in the log:

[1/8/2022, 9:16:30 AM] [EufySecurity-1.1.1-beta.14] DEBUG: videoConfig->vcodec: undefined
[1/8/2022, 9:16:30 AM] [EufySecurity-1.1.1-beta.14] DEBUG: streamData->metadata->videoCodec: -1
(node:59117) UnhandledPromiseRejectionWarning: ReferenceError: VideoCodec is not defined
    at StreamingDelegate.startStream (/usr/local/lib/node_modules/homebridge-eufy-security/src/accessories/streamingDelegate.ts:400:20)
    at processTicksAndRejections (internal/process/task_queues.js:95:5)
(Use `node --trace-warnings ...` to show where the warning was created)

Where should the VideoCodec enum be defined? I don't seem to have that...

schliemann commented 2 years ago

@fullphat Ah. Probably forgot an import to give you as well. Will find it.

schliemann commented 2 years ago

import { Station, Camera, PropertyName, StreamMetadata, VideoCodec } from 'eufy-security-client';

fullphat commented 2 years ago

Where do I paste this line? I tried putting it at the top of streamingDelegate.js, but I just get a syntax error.

schliemann commented 2 years ago

https://github.com/samemory/homebridge-eufy-security/blob/7adf974ec5fd1f7840b6055110edbf2ad5c6586e/src/accessories/streamingDelegate.ts#L30

schliemann commented 2 years ago

Odd. It should already be there. Can you confirm you have it?

fullphat commented 2 years ago

This is what I have - note I'm using the Beta.14 plugin:

"use strict";
var __importDefault = (this && this.__importDefault) || function (mod) {
    return (mod && mod.__esModule) ? mod : { "default": mod };
};
Object.defineProperty(exports, "__esModule", { value: true });
exports.StreamingDelegate = void 0;
const child_process_1 = require("child_process");
const dgram_1 = require("dgram");
const ffmpeg_for_homebridge_1 = __importDefault(require("ffmpeg-for-homebridge"));
const pick_port_1 = __importDefault(require("pick-port"));
const ffmpeg_1 = require("./ffmpeg");
const eufy_security_client_1 = require("eufy-security-client");
const UniversalStream_1 = require("./UniversalStream");
const fs_1 = require("fs");
const util_1 = require("util");
const readFileAsync = (0, util_1.promisify)(fs_1.readFile), SnapshotUnavailablePath = require.resolve('../../media/Snapshot-Unavailable.png');
class StreamingDelegate {
    constructor(platform, device, cameraConfig, api, hap) {
        // keep track of sessions
        this.pendingSessions = new Map();
        this.ongoingSessions = new Map();
        this.timeouts = new Map();
        this.log = platform.log;
        this.hap = hap;
        this.platform = platform;
        this.device = device;
        this.cameraName = device.getName();
        this.unbridge = false;
        this.videoConfig = cameraConfig.videoConfig;
        this.videoProcessor = ffmpeg_for_homebridge_1.default || 'ffmpeg';
        api.on("shutdown" /* SHUTDOWN */, () => {
            for (const session in this.ongoingSessions) {
                this.stopStream(session);
            }
        });
schliemann commented 2 years ago

Well. The codec resides in this require. I'm not an expert on how require importing works.

const eufy_security_client_1 = require("eufy-security-client");