tgorgdotcom / locast2plex

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

Move to logging rather than print statements #91

Open jgsawyers opened 4 years ago

jgsawyers commented 4 years ago

Throwing this out for discussion.... I've been using this on a local branch for awhile now to debug and troubleshoot issues. Rather than using print statements, I'd suggest we move to using logging throughout.

For example, here's what a startup, session start, and session end looks like when converted to logging at a debug level. (This includes -nostats -hide_banner args to ffmpeg to quiet it down a bit as well).

2020-09-17 02:15:28,897:DEBUG   :locast2plex:MainThread - Reading config file from /app directory.
2020-09-17 02:15:28,898:DEBUG   :locast2plex:MainThread - Enumerating config file...
2020-09-17 02:15:28,898:DEBUG   :locast2plex:MainThread - Got option locast_username - *************
2020-09-17 02:15:28,898:DEBUG   :locast2plex:MainThread - Got option locast_password - *************
2020-09-17 02:15:28,898:DEBUG   :locast2plex:MainThread - Got option override_zipcode - *****
2020-09-17 02:15:28,898:DEBUG   :locast2plex:MainThread - Got option plex_accessible_ip - 10.10.12.98
2020-09-17 02:15:28,898:DEBUG   :locast2plex:MainThread - Got option plex_accessible_port - 6077
2020-09-17 02:15:28,898:DEBUG   :locast2plex:MainThread - Got option bytes_per_read - 1152000
2020-09-17 02:15:28,898:DEBUG   :locast2plex:MainThread - Got option tuner_count - 3
2020-09-17 02:15:28,898:DEBUG   :locast2plex:MainThread - Got option reporting_model - HDHR3-US
2020-09-17 02:15:28,898:DEBUG   :locast2plex:MainThread - Got option reporting_firmware_name - hdhomerun3_atsc
2020-09-17 02:15:28,898:DEBUG   :locast2plex:MainThread - Got option reporting_firmware_ver - 20150826
2020-09-17 02:15:28,898:DEBUG   :locast2plex:MainThread - Got option concurrent_listeners - 10
2020-09-17 02:15:28,898:DEBUG   :locast2plex:MainThread - Got option uuid - khmzitov
2020-09-17 02:15:28,898:INFO    :locast2plex:MainThread - Locast2Plex v0.5.2
2020-09-17 02:15:28,899:INFO    :locast2plex:MainThread - Tuner count set to 3
2020-09-17 02:15:28,899:INFO    :locast2plex:MainThread - UUID set to: khmzitov...
2020-09-17 02:15:28,899:INFO    :LocastService:MainThread - Logging into Locast using username *************...
2020-09-17 02:15:29,385:INFO    :LocastService:MainThread - Validating User Info...
2020-09-17 02:15:29,730:INFO    :LocastService:MainThread - User Info obtained.
2020-09-17 02:15:29,730:INFO    :LocastService:MainThread - User didDonate: True
2020-09-17 02:15:29,730:INFO    :LocastService:MainThread - User donationExpire: 2020-09-18 05:33:02
2020-09-17 02:15:29,730:INFO    :LocastService:MainThread - Getting user location...
2020-09-17 02:15:29,731:INFO    :LocastService:MainThread - Getting location via provided zipcode *****
2020-09-17 02:15:30,070:INFO    :LocastService:MainThread - Got location as Phoenix - DMA 753 - Lat\Lon ******\******
2020-09-17 02:15:30,071:INFO    :LocastService:MainThread - Getting list of stations based on DMA...
2020-09-17 02:15:32,146:INFO    :LocastService:MainThread - Loading FCC Stations list...
2020-09-17 02:15:32,380:INFO    :locast2plex:MainThread - Starting device server on 10.10.12.98:6077
2020-09-17 02:15:32,384:INFO    :locast2plex:MainThread - Starting SSDP server...
2020-09-17 02:15:32,384:INFO    :locast2plex:MainThread - Locast2Plex is active and listening...
2020-09-17 02:15:32,394:INFO    :SSDPServer:MainThread - Registering upnp:rootdevice (http://10.10.12.98:6077/device.xml)
2020-09-17 02:15:33,843:DEBUG   :SSDPServer:MainThread - SSDP command M-SEARCH * - from 10.10.12.99:37185
2020-09-17 02:15:33,843:DEBUG   :SSDPServer:MainThread - with headers: {u'host': u'239.255.255.250:1900', u'st': u'upnp:rootdevice', u'mx': u'5', u'man': u'"ssdp:discover"'}.
2020-09-17 02:15:33,843:DEBUG   :SSDPServer:MainThread - Discovery request from (10.10.12.99,37185) for upnp:rootdevice
2020-09-17 02:15:33,843:DEBUG   :SSDPServer:MainThread - Discovery request for upnp:rootdevice
2020-09-17 02:15:33,844:DEBUG   :SSDPServer:MainThread - send discovery response delayed by 4s for uuid:khmzitov::upnp:rootdevice to ('10.10.12.99', 37185)
2020-09-17 02:15:37,849:INFO    :LocastService:Thread-10 - Getting station info for 1571434912373...
2020-09-17 02:15:38,217:INFO    :LocastService:Thread-10 - Determining best video stream for 1571434912373...
2020-09-17 02:15:38,482:INFO    :LocastService:Thread-10 - Found 3 Playlists
2020-09-17 02:15:38,482:INFO    :LocastService:Thread-10 - 1571434912373 will user 1280x720 resolution at 2700000 bps.
2020-09-17 02:15:38,482:INFO    :locast2plex:Thread-10 - 10.10.10.167 - HTTP/1.0 - [17/Sep/2020 02:15:38] "GET /watch/1571434912373 HTTP/1.1" 200 -
2020-09-17 02:15:38,489:DEBUG   :locast2plex:LoggingThread-11 - Starting thread for subprocess logging.
2020-09-17 02:15:39,493:INFO    :locast2plex:Thread-10 - [hls,applehttp @ 0x555bc8b76fc0] Opening 'https://phx.locastnet.org/proxy/phx/src.ts' for reading
2020-09-17 02:15:39,493:INFO    :locast2plex:Thread-10 - [hls,applehttp @ 0x555bc8b76fc0] Opening 'https://phx.locastnet.org/proxy/phx/src.ts' for reading
2020-09-17 02:15:39,494:INFO    :locast2plex:Thread-10 - Input #0, hls,applehttp, from 'https://phx.locastnet.org/proxy/phx/variant/source.m3u8':
2020-09-17 02:15:39,494:INFO    :locast2plex:Thread-10 - Duration: N/A, start: 91773.977956, bitrate: N/A
2020-09-17 02:15:39,494:INFO    :locast2plex:Thread-10 - Program 0
2020-09-17 02:15:39,494:INFO    :locast2plex:Thread-10 - Metadata:
2020-09-17 02:15:39,494:INFO    :locast2plex:Thread-10 - variant_bitrate : 0
2020-09-17 02:15:39,495:INFO    :locast2plex:Thread-10 - Stream #0:0: Video: h264 ([27][0][0][0] / 0x001B), yuv420p, 1280x720 [SAR 1:1 DAR 16:9], Closed Captions, 30 fps, 30 tbr, 90k tbn, 60 tbc
2020-09-17 02:15:39,495:INFO    :locast2plex:Thread-10 - Metadata:
2020-09-17 02:15:39,495:INFO    :locast2plex:Thread-10 - variant_bitrate : 0
2020-09-17 02:15:39,495:INFO    :locast2plex:Thread-10 - Stream #0:1: Audio: aac ([15][0][0][0] / 0x000F), 48000 Hz, stereo, fltp
2020-09-17 02:15:39,495:INFO    :locast2plex:Thread-10 - Metadata:
2020-09-17 02:15:39,495:INFO    :locast2plex:Thread-10 - variant_bitrate : 0
2020-09-17 02:15:39,496:INFO    :locast2plex:Thread-10 - Output #0, mpegts, to 'pipe:1':
2020-09-17 02:15:39,496:INFO    :locast2plex:Thread-10 - Metadata:
2020-09-17 02:15:39,496:INFO    :locast2plex:Thread-10 - encoder         : Lavf58.12.100
2020-09-17 02:15:39,496:INFO    :locast2plex:Thread-10 - Stream #0:0: Video: h264 ([27][0][0][0] / 0x001B), yuv420p, 1280x720 [SAR 1:1 DAR 16:9], q=2-31, 30 fps, 30 tbr, 90k tbn, 90k tbc
2020-09-17 02:15:39,496:INFO    :locast2plex:Thread-10 - Metadata:
2020-09-17 02:15:39,496:INFO    :locast2plex:Thread-10 - variant_bitrate : 0
2020-09-17 02:15:39,497:INFO    :locast2plex:Thread-10 - Stream #0:1: Audio: aac ([15][0][0][0] / 0x000F), 48000 Hz, stereo, fltp
2020-09-17 02:15:39,497:INFO    :locast2plex:Thread-10 - Metadata:
2020-09-17 02:15:39,497:INFO    :locast2plex:Thread-10 - variant_bitrate : 0
2020-09-17 02:15:39,497:INFO    :locast2plex:Thread-10 - Stream mapping:
2020-09-17 02:15:39,497:INFO    :locast2plex:Thread-10 - Stream #0:0 -> #0:0 (copy)
2020-09-17 02:15:39,497:INFO    :locast2plex:Thread-10 - Stream #0:1 -> #0:1 (copy)
2020-09-17 02:15:39,498:INFO    :locast2plex:Thread-10 - Press [q] to stop, [?] for help
2020-09-17 02:15:39,498:INFO    :locast2plex:Thread-10 - [https @ 0x555bc8b81140] Opening 'https://phx.locastnet.org/proxy/phx/src.ts' for reading
2020-09-17 02:15:45,624:INFO    :locast2plex:Thread-10 - [https @ 0x555bc8b81140] Opening 'https://phx.locastnet.org/proxy/phx/src.ts' for reading
2020-09-17 02:15:51,643:INFO    :locast2plex:Thread-10 - [https @ 0x555bc8c14e80] Opening 'https://phx.locastnet.org/proxy/phx/variant/source.m3u8' for reading
2020-09-17 02:15:51,644:INFO    :locast2plex:Thread-10 - [https @ 0x555bc8b81140] Opening 'https://phx.locastnet.org/proxy/phx/src.ts' for reading
2020-09-17 02:16:03,489:INFO    :locast2plex:Thread-10 - [https @ 0x555bc8c14e80] Opening 'https://phx.locastnet.org/proxy/phx/variant/source.m3u8' for reading
2020-09-17 02:16:03,489:INFO    :locast2plex:Thread-10 - [https @ 0x555bc8b81140] Opening 'https://phx.locastnet.org/proxy/phx/src.ts' for reading
2020-09-17 02:16:03,490:INFO    :locast2plex:Thread-10 - [https @ 0x555bc8c14e80] Opening 'https://phx.locastnet.org/proxy/phx/variant/source.m3u8' for reading
2020-09-17 02:16:03,490:INFO    :locast2plex:Thread-10 - [https @ 0x555bc8b81140] Opening 'https://phx.locastnet.org/proxy/phx/src.ts' for reading
2020-09-17 02:16:09,697:INFO    :locast2plex:Thread-10 - Caught broken pipe, terminating ffmpeg.
2020-09-17 02:16:09,698:DEBUG   :locast2plex:Thread-10 - Calling log reader stop...
2020-09-17 02:16:09,698:DEBUG   :locast2plex:Thread-10 - Setting flag to stop logging thread.
2020-09-17 02:16:09,698:DEBUG   :locast2plex:Thread-10 - Calling log reader join...
2020-09-17 02:16:09,715:DEBUG   :locast2plex:LoggingThread-11 - Kill flag recieved, exiting logging thread.
2020-09-17 02:16:09,716:DEBUG   :locast2plex:Thread-10 - Breaking busy loop...
2020-09-17 02:16:09,716:DEBUG   :locast2plex:Thread-10 - Cleanup - ffmpeg process already terminated.
tgorgdotcom commented 4 years ago

I like this plan. Just note that I think we're going to try to upgrade the script to Python 3 first, but this is great -- I've seen some of the logs getting messed up, probably due to thread safety.

deathbybandaid commented 4 years ago

I was just thinking this while I was poking at stuff yesterday. See Draft PR #92

Among other things I'd like to see in a future WebUI, would also be logging visible from a browser.