tgorgdotcom / locast2plex

A very simple script to connect locast to Plex's live tv/dvr feature.
MIT License
232 stars 43 forks source link

Challenge keeping dockerized server running for more than 24 hours #209

Open marlen125 opened 3 years ago

marlen125 commented 3 years ago

Hello, I'm a bit new to docker and everything else so forgive me being a n00b but other than running [docker log locast2plex] (which reveals a ton of "get /lineup_status.json" commands, how can I see what is causing locast2plex to hang?

It works flawlessly upon a "docker restart locast2plex" but then, after 5 minutes or 5 hours hangs. The server is only running plex and locast2plex (for now...) and is on Ubuntu 20.x

Anyone have any ideas? I'm really excited to ditch cable and our DVR soon for this, if I can keep it up and running...

marlen125 commented 3 years ago

Basically - anyone know where I can pull the logs?

docker log Locast... does not show anything real - just a long list of the get lineup.

Guyverix commented 3 years ago

@marlen125 what does your compose file look like? I have had good luck with this: ` /opt/locast2plex$ cat docker-compose.yml locast2plex: image: tgorg/locast2plex container_name: locast2plex ports:

cahiatt commented 3 years ago

I had a somewhat similar issue. Docker running on a bare metal Windows 2019 server. It could crash in a few hours or overnight.

My issue turned out to be the system backups and folder file history. Seemed Docker did not like ANY type of backup happening on the Hyper-V container or the locast2plex folder when it was running. Once I specifically excluded the Docker image for Hyper-V and the Locast2Plex folders from backups and snapshots I never had another issue. It's been running for a few weeks now without an error.

marlen125 commented 3 years ago

Thanks for the comments back @Guyverix and @cahiatt!

  GNU nano 4.8                                              config.ini
[main]
#uuid=<note: automaticially created if nonexistant>
plex_accessible_ip = 127.0.0.1
locast_username= REDACTED 
locast_password= REDACTED
#disable_ssdp = False
#plex_accessible_port = 6077
#use_old_plex_interface = False
tuner_count = 4
#concurrent_listeners = 10
#cache_dir =
#ffmpeg_path = None
#verbose = False
#bytes_per_read=1152000
#tuner_type = Antenna
#fcc_delay = 43200
#epg_update_frequency = 43200
#epg_update_days = 7
#reporting_model=xxxxxx
#reporting_firmware_name=xxxxxx
#reporting_firmware_ver=xxxxxx

so basically, the file looks fine and the only real change is modifying the tuner count to 4 (which is the max). The computer is a Dell R710 server with 32 gigs of ram and oooodles of CPU running a Raid 6 totaling about 14Tb for storage. No backup tasks are running which I would think would rule out @cahiatt 's theory. The docker image shows it's still running smooth after "x" amount of time but plex can no longer tune a channel. A "docker reboot locast2plex" instantly fixes it...

I'm just at a loss as to why it would work for an unspecified period of time.

FWIW, the server is also rolling records through Zoneminder for some security cameras and its logs appear clean as well with no CPU or RAM flags.

Where else can I look for potential issues if the docker is running but...somehow not responding? Does that get stored anywhere?

Guyverix commented 3 years ago

I have not verified this, but I was under the impression that locast only allowed three streams, not four...

marlen125 commented 3 years ago

I honestly haven't gotten one to work. I could comment out the "max 4". If one inputs 5 (or I tried 10 at first to see what would happen) there, on startup, the logs show the max is 4 so it set it to that.

Guyverix commented 3 years ago

I just dblchecked my running config and the only difference between mine and yours is the uuid is enabled, and my plex is not running on localhost. Can I suggest you enable uuid and use your ethernet IP address instead of localhost and see if that addresses the problem?

cat config.ini [main] plex_accessible_ip = 192.168.15.132 locast_username = EMAIL locast_password = PASS uuid = sthhlnqn

Guyverix commented 3 years ago

also make sure your docker compose file has the passthrough set if you are using the advertised IP address of your docker host: ports:

marlen125 commented 3 years ago

Ill try changing the plex_accessible_IP to the local IP vs 127.0.0.1 and updating the UUID. I'm curious why the UUID didn't update though in the config file - it should've been over-written on first load I would've thought.

At any rate, tried 3 concurrent records. First one recorded 8 minutes, the other two didn't even attempt.

Will update after changing the config file shortly

Guyverix commented 3 years ago

8 minutes? Hmm, thats within the timeout of un-authenticated/ non-pay users. Any chance your password has special characters that Python is interpreting instead of passing for authentication? I dont have logging set up on my container to look at mine, but kinda do wonder if you are seeing an auth issue.

marlen125 commented 3 years ago

So the initial logs inside the Docker show that it does auth successfully (and I've paid fwiw). My password did have a 0 and a ! at the end. I'll try changing that to just text.

Guyverix commented 3 years ago

I do know that ffmpeg gets "twitchy", how stable is your network connection to locast servers? does mtr show fairly low/stable jitter values? I am also in the Seattle area, and have different issues with locast, that I suspect overall are multi-stream related, but have not had time to test further yet.

marlen125 commented 3 years ago

I've rebuilt the docker and, this time, it updated the UUID on its own and stripped out all of the commented variables. (unclear what i did wrong before tho for it to no update uuid). My connection to locast should be pretty solid. I'm on direct fiber to the house with a Ubiquiti Edge router and a couple cisco SG350 switches in between. Speedtests are all pretty solid in the 700+ mbps bi-directional range.

it's now built with my internal ip (192.168.1.179) and I managed to get 20 minutes out of it.

Config File:

  GNU nano 4.8                                              config.ini
[main]
plex_accessible_ip = 192.168.1.179
locast_username = email
locast_password = password, WITHOUT any special characters now
tuner_count = 4
uuid = wmsixxwi

from docker logs locast2plex:

192.168.1.179 - - [19/Feb/2021 23:21:04] "GET /discover.json HTTP/1.0" 200 -
192.168.1.179 - - [19/Feb/2021 23:21:04] "GET /lineup_status.json HTTP/1.0" 200 -

it does that every 2-3 seconds. the last log entry is:

192.168.1.179 - - [19/Feb/2021 23:21:06] "GET /watch/1293 HTTP/1.1" 200 -

192.168.1.179 - - [19/Feb/2021 23:21:07] "GET /discover.json HTTP/1.0" 200 - 

and it just stops updating the logs and nothing will stream.

Guyverix commented 3 years ago

The only difference between yours and mine is specifically the tuner count. Could you comment that out completely and restart the container? From what I am seeing there should be not reason at all for what you are experiencing. Nothing oddball showing up in your plex logs either?

marlen125 commented 3 years ago

Commented out tuner count - logs show it starting with 3 tuners now, rebuilt docker and restarted plex and locast:

Initiating Locast2Plex v0.6.5
Opening and Verifying Configuration File.
/app/config/config.ini
Loading Configuration File: /app/config/config.ini
Tuner count set to 3
Server is set to run on  192.168.1.179:6077
UUID set to: wmsixxwi...
Getting user location...
Getting location via IP Address.
Got external IP 76.226.<##.##>.
Got location as San Francisco - DMA 807 - Lat\Lon 37.978\-122.0311
Logging into Locast using username <MYEMAIL>@gmail.com...
Validating User Info...
User Info obtained.
User didDonate: True
User donationExpire: 2021-02-27 19:50:33
Starting First time Stations refresh...
Checking FCC facilities database for updates.
Cached facilities database is current.
Getting list of stations based on DMA...
Found 52 stations for DMA 807
Starting Stations thread...
Starting device server on 192.168.1.179:6077
Now listening for requests.
Starting SSDP server...
192.168.1.179 - - [21/Feb/2021 23:45:21] "GET /discover.json HTTP/1.0" 200 -
192.168.1.179 - - [21/Feb/2021 23:45:21] "GET /watch/1304 HTTP/1.1" 200 -
192.168.1.179 - - [21/Feb/2021 23:45:22] "GET /lineup_status.json HTTP/1.0" 200 -
192.168.1.179 - - [21/Feb/2021 23:45:23] "GET /discover.json HTTP/1.0" 200 -
192.168.1.179 - - [21/Feb/2021 23:45:23] "GET /lineup_status.json HTTP/1.0" 200 -
192.168.1.179 - - [21/Feb/2021 23:45:26] "GET /discover.json HTTP/1.0" 200 -
192.168.1.179 - - [21/Feb/2021 23:45:27] "GET /lineup_status.json HTTP/1.0" 200 -
Starting First time EPG refresh...
FROM CACHE: /app/cache/807_epg/02-21-2021.json
FROM CACHE: /app/cache/807_epg/02-22-2021.json
Getting station info for 1304...
Determining best video stream for 1304...
FROM CACHE: /app/cache/807_epg/02-23-2021.json
Found 0 Playlists
No variant streams found for this station.  Assuming single stream only.
FROM CACHE: /app/cache/807_epg/02-24-2021.json
FROM CACHE: /app/cache/807_epg/02-25-2021.json
FROM CACHE: /app/cache/807_epg/02-26-2021.json
Starting EPG thread...

The Plex logs are....long. Basically it starts with a ton of Transcoder errors, buffers for a second, and then seems to work for a bit:

Feb 21, 2021 23:45:46.202 [0x7f52397fa700] Error — [Transcoder] [h264 @ 0xf68b00] decode_slice_header error
Feb 21, 2021 23:45:46.202 [0x7f52517fa700] Error — [Transcoder] [h264 @ 0xf68b00] no frame!
Feb 21, 2021 23:45:46.202 [0x7f52537fe700] Error — [Transcoder] [NULL @ 0xf469c0] non-existing PPS 0 referenced
Feb 21, 2021 23:45:46.202 [0x7f52397fa700] Error — [Transcoder] [h264 @ 0xf68b00] non-existing PPS 0 referenced
Feb 21, 2021 23:45:46.203 [0x7f52517fa700] Error — [Transcoder] [h264 @ 0xf68b00] decode_slice_header error
Feb 21, 2021 23:45:46.203 [0x7f52537fe700] Error — [Transcoder] [h264 @ 0xf68b00] no frame!
Feb 21, 2021 23:45:46.203 [0x7f52397fa700] Error — [Transcoder] [NULL @ 0xf469c0] non-existing PPS 0 referenced
Feb 21, 2021 23:45:46.204 [0x7f52517fa700] Error — [Transcoder] [h264 @ 0xf68b00] non-existing PPS 0 referenced
Feb 21, 2021 23:45:46.204 [0x7f52537fe700] Error — [Transcoder] [h264 @ 0xf68b00] decode_slice_header error
Feb 21, 2021 23:45:46.204 [0x7f52397fa700] Error — [Transcoder] [h264 @ 0xf68b00] no frame!
Feb 21, 2021 23:45:46.204 [0x7f52517fa700] Error — [Transcoder] [NULL @ 0xf469c0] non-existing PPS 0 referenced
Feb 21, 2021 23:45:46.205 [0x7f52537fe700] Error — [Transcoder] [h264 @ 0xf68b00] non-existing PPS 0 referenced
Feb 21, 2021 23:45:46.205 [0x7f52397fa700] Error — [Transcoder] [h264 @ 0xf68b00] decode_slice_header error
Feb 21, 2021 23:45:46.205 [0x7f52517fa700] Error — [Transcoder] [h264 @ 0xf68b00] no frame!
Feb 21, 2021 23:45:46.206 [0x7f52537fe700] Error — [Transcoder] [NULL @ 0xf469c0] non-existing PPS 0 referenced
Feb 21, 2021 23:45:46.206 [0x7f52397fa700] Error — [Transcoder] [h264 @ 0xf68b00] non-existing PPS 0 referenced
Feb 21, 2021 23:45:46.206 [0x7f52517fa700] Error — [Transcoder] [h264 @ 0xf68b00] decode_slice_header error
Feb 21, 2021 23:45:46.206 [0x7f52537fe700] Error — [Transcoder] [h264 @ 0xf68b00] no frame!
Feb 21, 2021 23:45:46.832 [0x7f52f952d700] Warning — JobManager: Could not find job for handle 107517
Feb 21, 2021 23:45:46.833 [0x7f52517fa700] Warning — SLOW QUERY: It took 3710.000000 ms to retrieve 0 items.
Feb 21, 2021 23:48:03.162 [0x7f52727fc700] Warning — [Grabber/7.3-4tybi4ffhk582vja2k4i2ts0] SLOW QUERY: It took 350.000000 ms to retrieve 8 items.
Feb 21, 2021 23:48:03.293 [0x7f52727fc700] Warning — [Grabber/7.3-4tybi4ffhk582vja2k4i2ts0] SLOW QUERY: It took 260.000000 ms to retrieve 1 items.

That last line, about the "SLOW QUERY" was a blip on the stream for about 1-2 seconds, then it came back.

Another blip, about 2 minutes later generated this:

Feb 21, 2021 23:54:01.732 [0x7f5252ffd700] Error — [Transcoder] [mpegts @ 0x9efb00] AAC bitstream not in ADTS format and extradata missing
Feb 21, 2021 23:54:01.887 [0x7f52b67fc700] Error — [Transcoder] [AVBSFContext @ 0xfeec80] Error parsing ADTS frame header!
Feb 21, 2021 23:54:01.888 [0x7f52177fe700] Error — [Transcoder] [AVBSFContext @ 0xfeec80] Failed to send packet to filter aac_adtstoasc for stream 0

Once again, it recovered.

I'm going to keep this channel streaming...until it does and will update here. My only thought so far is that the selected channel is SD. Potentially there's a buffer issue with the HD channels?

Will check a HD channel later tonight (after the little one goes to sleep)...hopefully the SD channel will still be streaming and I can keep narrowing it down.

Guyverix commented 3 years ago

You could also try a true HD channel, and see if it is H.265 as well. It MIGHT be transcoding down to H264, but I doubt it. Just another thing to poke at :) I would also really recommend an mtr against the endpoint that is streaming to you just to validate the far end server stability, as well as the path to you.