mpbzh / homebridge-plex

Plex plugin for homebridge: https://github.com/nfarina/homebridge
MIT License
58 stars 6 forks source link

Polling interval output filling up logs? #6

Closed ghost closed 6 years ago

ghost commented 6 years ago

I apologize if this is premature, and fully acknowledge that I haven't given my system enough time to prove anything to me one way or the other, but I updated to the latest commit this morning (b542c39bf32fdd90f86003ce12aa8b67c8402b6a) and noticed that with each poll there is a set of lines that get written to the homebridge.log file (which I believe is a capture of stdout?).

For my system, which is a homebridge docker container, the status is being written every 3 seconds (I know I can change this default) to /var/log/homebridge.log. I've been watching the file size grow at ~100KB/hr. Doing some rough (and probably poor) math, I'll be looking at a 15MB log file for each full week the plugin runs. Not the end of the world, but you can see how it'll add up quickly.

I'll keep checking on it over the next day or two to see if these logs rollover, and I know I could setup a cron job or something to periodically clear things out, but I wanted to bring it up for discussion. Thanks!

mpbzh commented 6 years ago

That‘s a very valid point!

I‘ll remove the console output for normal operation and add an option to print them for debugging purposes.

I think homebridge even offers a verbose flag for that.

ghost commented 6 years ago

Awesome. Glad that, at least on the surface, it doesn't sound like I'm crazy. Sorry my skill set doesn't allow for a PR that you can review. Appreciate the updates!

mpbzh commented 6 years ago

So the latest version (1.1.3) kind of fixes this. It introduces a debug config variable (documentation pending, but it's just a boolean named debug in the config object).

If the debug setting is omitted or set to anything falsy, it will only output status changes (Not playing → playing and vice versa) .

Or at least it should. If nothing is playing, nothing gets logged. But if there's an active session matching the filter, it still logs "Plex is playing" every three seconds (or your configured interval, respectively).

I'll fix that with the next release.

ghost commented 6 years ago

So far so good in terms of the log fill. However, I am seeing an error on startup in the homebridge logs, and it appears that all my accessories eventually give up and flip over to "No Response". I say eventually because after the initial update this morning I did a quick check and things were responding, but by the time I got to the office everything was down. Posting the error here for a second look:

/homebridge/node_modules/homebridge-plex/index.js:83
        data.Video.forEach(function (e) {
                   ^
TypeError: Cannot read property 'forEach' of undefined

I'll try to remove, test, reinstall, to verify everything. I'll post my findings as soon as possible.

ghost commented 6 years ago

It looks like I might be having a larger issue with one of my other plugins (or maybe even the docker image used to build my container). I followed the backup and restore instructions for homebridge in an attempt to salvage my setup, but now even if I create an entirely new container without the plex plugin I am still experiencing and issue where homebridge never finishes starting up. It gets to the stage where it loads in accessories and platforms and never really gets beyond that. The error I posted above may still be relevant but I'll need to do some further troubleshooting to get a healthy homebridge instance back up.

ghost commented 6 years ago

Bah, apologies for the multiple updates. I try to toe the line between keeping it relevant and including enough detail so I'm not just saying "it's not working", forcing others to decrypt my issue. Homebridge hangup was definitely caused by another plugin (Nest). Apparently that community is working through some sort of issue with the Nest API... moving on.

After a reinstall of homebridge (without the troubled plugin), I have yet to encounter the error posted above again. I did have an issue with HomeKit (the home app, really) updating the status of the sensor. I could see in the homebridge logs that "Plex is playing" but the home never updated the status of the sensor to "triggered" or "Occupancy Detected: Yes". A force quit of the Home app and relaunch seems to have corrected whatever update issue it was having though and now things seem to be working/updating properly.

I haven't tried testing with any automations (or with the Home app in the background/closed entirely). I assume they will work but I'll try to confirm this afternoon.

mpbzh commented 6 years ago

The error you posted above might happen if Plex does neither return a response with a Video object in it, nor an empty one (which it should).

So it would be interesting to see, what your Plex server actually returns.

mpbzh commented 6 years ago

I just released v1.1.5 which should fix the initial issue.

If your new problem ('forEach' of undefined) persists, please open a new issue for that.

ghost commented 6 years ago

Will do. Thanks!

yetdog commented 6 years ago

I'm actually seeing the same crash, same error in the logs. If nothing is playing on plex, no foul. The second I start streaming something, I get the crash and this in the logs:

Mar 25 20:57:23 pivm homebridge[24449]: /usr/lib/node_modules/homebridge-plex/index.js:83 Mar 25 20:57:23 pivm homebridge[24449]: data.Video.forEach(function (e) { Mar 25 20:57:23 pivm homebridge[24449]: ^ Mar 25 20:57:23 pivm homebridge[24449]: TypeError: Cannot read property 'forEach' of undefined Mar 25 20:57:23 pivm homebridge[24449]: at Request._callback (/usr/lib/node_modules/homebridge-plex/index.js:83:19) Mar 25 20:57:23 pivm homebridge[24449]: at Request.self.callback (/usr/lib/node_modules/homebridge-plex/node_modules/request/request.js:186:22) Mar 25 20:57:23 pivm homebridge[24449]: at emitTwo (events.js:106:13) Mar 25 20:57:23 pivm homebridge[24449]: at Request.emit (events.js:194:7) Mar 25 20:57:23 pivm homebridge[24449]: at Request. (/usr/lib/node_modules/homebridge-plex/node_modules/request/request.js:1163:10) Mar 25 20:57:23 pivm homebridge[24449]: at emitOne (events.js:96:13) Mar 25 20:57:23 pivm homebridge[24449]: at Request.emit (events.js:191:7) Mar 25 20:57:23 pivm homebridge[24449]: at IncomingMessage. (/usr/lib/node_modules/homebridge-plex/node_modules/request/request.js:1085:12) Mar 25 20:57:23 pivm homebridge[24449]: at Object.onceWrapper (events.js:293:19) Mar 25 20:57:23 pivm homebridge[24449]: at emitNone (events.js:91:20) Mar 25 20:57:23 pivm homebridge[24449]: at IncomingMessage.emit (events.js:188:7) Mar 25 20:57:23 pivm homebridge[24449]: at endReadableNT (_stream_readable.js:975:12) Mar 25 20:57:23 pivm homebridge[24449]: at _combinedTickCallback (internal/process/next_tick.js:80:11) Mar 25 20:57:23 pivm homebridge[24449]: at process._tickCallback (internal/process/next_tick.js:104:9) Mar 25 20:57:23 pivm systemd[1]: homebridge.service: main process exited, code=exited, status=1/FAILURE Mar 25 20:57:23 pivm systemd[1]: Unit homebridge.service entered failed state.