Merge pull request #24 from friedkiwi/fix-logging

Implement logging
2024-10-06 19:03:36 +00:00 · 2024-09-24 13:07:28 +00:00 · 2024-09-24 13:07:28 +00:00 · 5025e49e61
commit 5025e49e61
parent a877ff2d4b 3b3b858f4e
7 changed files with 152 additions and 35 deletions
--- a/Cargo.lock
+++ b/Cargo.lock
@ -26,6 +26,55 @@ dependencies = [
 "memchr",
 ]

+[[package]]
+name = "anstream"
+version = "0.6.15"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "64e15c1ab1f89faffbf04a634d5e1962e9074f2741eef6d97f3c4e322426d526"
+dependencies = [
+ "anstyle",
+ "anstyle-parse",
+ "anstyle-query",
+ "anstyle-wincon",
+ "colorchoice",
+ "is_terminal_polyfill",
+ "utf8parse",
+]
+
+[[package]]
+name = "anstyle"
+version = "1.0.8"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "1bec1de6f59aedf83baf9ff929c98f2ad654b97c9510f4e70cf6f661d49fd5b1"
+
+[[package]]
+name = "anstyle-parse"
+version = "0.2.5"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "eb47de1e80c2b463c735db5b217a0ddc39d612e7ac9e2e96a5aed1f57616c1cb"
+dependencies = [
+ "utf8parse",
+]
+
+[[package]]
+name = "anstyle-query"
+version = "1.1.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "6d36fc52c7f6c869915e99412912f22093507da8d9e942ceaf66fe4b7c14422a"
+dependencies = [
+ "windows-sys 0.52.0",
+]
+
+[[package]]
+name = "anstyle-wincon"
+version = "3.0.4"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "5bf74e1b6e971609db8ca7a9ce79fd5768ab6ae46441c572e46cf596f59e57f8"
+dependencies = [
+ "anstyle",
+ "windows-sys 0.52.0",
+]
+
 [[package]]
 name = "async-lock"
 version = "2.8.0"
@ -98,6 +147,12 @@ version = "1.0.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "baf1de4339761588bc0619e3cbc0120ee582ebb74b53b4efbf79117bd2da40fd"

+[[package]]
+name = "colorchoice"
+version = "1.0.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "d3fd119d74b830634cea2a0f58bbd0d54540518a14397557951e79340abc28c0"
+
 [[package]]
 name = "core-foundation"
 version = "0.9.4"
@ -138,6 +193,29 @@ dependencies = [
 "cfg-if",
 ]

+[[package]]
+name = "env_filter"
+version = "0.1.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "4f2c92ceda6ceec50f43169f9ee8424fe2db276791afde7b2cd8bc084cb376ab"
+dependencies = [
+ "log",
+ "regex",
+]
+
+[[package]]
+name = "env_logger"
+version = "0.11.5"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "e13fa619b91fb2381732789fc5de83b45675e882f66623b7d8cb4f643017018d"
+dependencies = [
+ "anstream",
+ "anstyle",
+ "env_filter",
+ "humantime",
+ "log",
+]
+
 [[package]]
 name = "equivalent"
 version = "1.0.1"
@ -362,6 +440,12 @@ version = "1.8.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "d897f394bad6a705d5f4104762e116a75639e470d80901eed05a860a95cb1904"

+[[package]]
+name = "humantime"
+version = "2.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4"
+
 [[package]]
 name = "hyper"
 version = "1.3.1"
@ -442,8 +526,10 @@ dependencies = [
 name = "inv_sig_helper_rust"
 version = "0.1.0"
 dependencies = [
+ "env_logger",
 "futures",
 "lazy-regex",
+ "log",
 "regex",
 "reqwest",
 "rquickjs",
@ -458,6 +544,12 @@ version = "2.9.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "8f518f335dce6725a761382244631d86cf0ccb2863413590b31338feb467f9c3"

+[[package]]
+name = "is_terminal_polyfill"
+version = "1.70.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "7943c866cc5cd64cbc25b2e01621d07fa8eb2a1a23160ee81ce38704e97b8ecf"
+
 [[package]]
 name = "itoa"
 version = "1.0.11"
@ -526,9 +618,9 @@ dependencies = [

 [[package]]
 name = "log"
-version = "0.4.21"
+version = "0.4.22"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "90ed8c1e510134f979dbc4f070f87d4313098b704861a105fe34231c70a3901c"
+checksum = "a7a70ba024b9dc04c27ea2f0c0548feb474ec5c54bba33a7f72f873a39d07b24"

 [[package]]
 name = "memchr"
@ -1215,6 +1307,12 @@ dependencies = [
 "percent-encoding",
 ]

+[[package]]
+name = "utf8parse"
+version = "0.2.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "06abde3611657adf66d383f00b093d7faecc7fa57071cce2578660c9f1010821"
+
 [[package]]
 name = "vcpkg"
 version = "0.2.15"
--- a/Cargo.toml
+++ b/Cargo.toml
@ -14,6 +14,8 @@ lazy-regex = "3.1.0"
 tub = "0.3.7"
 tokio-util = { version = "0.7.10", features=["futures-io", "futures-util", "codec"]}
 futures = "0.3.30"
+log = "0.4.22"
+env_logger = "0.11.5"

 # Compilation optimizations for release builds
 # Increases compile time but typically produces a faster and smaller binary. Suitable for final releases but not for debug builds.
--- a/README.md
+++ b/README.md
@ -93,6 +93,18 @@ The service can run in Unix socket mode (default) or TCP mode:

   If no IP:PORT is given, it defaults to `127.0.0.1:12999`.

+#### Troubleshooting
+
+The log level can be configured using the `RUST_LOG` environment variable. Valid values are:
+
+- error
+- warn
+- info
+- debug
+- trace
+
+The `info` log level is the default setting. Changing this to `debug` will provide detailed logs on each request for additional troubleshooting.
+

 ## Protocol Format

--- a/src/jobs.rs
+++ b/src/jobs.rs
@ -1,6 +1,7 @@
 use futures::SinkExt;
 use rquickjs::{async_with, AsyncContext, AsyncRuntime};
 use std::{num::NonZeroUsize, sync::Arc, thread::available_parallelism, time::SystemTime};
+use log::{debug, error};
 use tokio::{runtime::Handle, sync::Mutex, task::block_in_place};
 use tub::Pool;

@ -164,11 +165,11 @@ pub async fn process_decrypt_n_signature<W>(
                Ok(x) => x,
                Err(n) => {
                    if n.is_exception() {
-                        println!("JavaScript interpreter error (nsig code): {:?}", ctx.catch().as_exception());
+                        error!("JavaScript interpreter error (nsig code): {:?}", ctx.catch().as_exception());
                    } else {
-                        println!("JavaScript interpreter error (nsig code): {}", n);
+                        error!("JavaScript interpreter error (nsig code): {}", n);
                    }
-                    println!("Code: {}", player_info.nsig_function_code.clone());
+                    debug!("Code: {}", player_info.nsig_function_code.clone());
                    writer = cloned_writer.lock().await;
                    let _ = writer.send(OpcodeResponse {
                        opcode: JobOpcode::DecryptNSignature,
@ -192,11 +193,11 @@ pub async fn process_decrypt_n_signature<W>(
            Ok(x) => x,
            Err(n) => {
                if n.is_exception() {
-                    println!("JavaScript interpreter error (nsig code): {:?}", ctx.catch().as_exception());
+                    error!("JavaScript interpreter error (nsig code): {:?}", ctx.catch().as_exception());
                } else {
-                    println!("JavaScript interpreter error (nsig code): {}", n);
+                    error!("JavaScript interpreter error (nsig code): {}", n);
                }
-                println!("Code: {}", call_string.clone());
+                debug!("Code: {}", call_string.clone());
                writer = cloned_writer.lock().await;
                let _ = writer.send(OpcodeResponse {
                    opcode: JobOpcode::DecryptNSignature,
@ -243,11 +244,11 @@ pub async fn process_decrypt_signature<W>(
                Ok(x) => x,
                Err(n) => {
                    if n.is_exception() {
-                        println!("JavaScript interpreter error (sig code): {:?}", ctx.catch().as_exception());
+                        error!("JavaScript interpreter error (sig code): {:?}", ctx.catch().as_exception());
                    } else {
-                        println!("JavaScript interpreter error (sig code): {}", n);
+                        error!("JavaScript interpreter error (sig code): {}", n);
                    }
-                    println!("Code: {}", player_info.sig_function_code.clone());
+                    debug!("Code: {}", player_info.sig_function_code.clone());
                    writer = cloned_writer.lock().await;
                    let _ = writer.send(OpcodeResponse {
                        opcode: JobOpcode::DecryptSignature,
@ -274,11 +275,11 @@ pub async fn process_decrypt_signature<W>(
            Ok(x) => x,
            Err(n) => {
                if n.is_exception() {
-                    println!("JavaScript interpreter error (sig code): {:?}", ctx.catch().as_exception());
+                    error!("JavaScript interpreter error (sig code): {:?}", ctx.catch().as_exception());
                } else {
-                    println!("JavaScript interpreter error (sig code): {}", n);
+                    error!("JavaScript interpreter error (sig code): {}", n);
                }
-                println!("Code: {}", call_string.clone());
+                debug!("Code: {}", call_string.clone());
                writer = cloned_writer.lock().await;
                let _ = writer.send(OpcodeResponse {
                    opcode: JobOpcode::DecryptSignature,
--- a/src/main.rs
+++ b/src/main.rs
@ -9,6 +9,7 @@ use jobs::{process_decrypt_n_signature, process_fetch_update, GlobalState, JobOp
 use opcode::OpcodeDecoder;
 use player::fetch_update;
 use std::{env::args, sync::Arc};
+use env_logger::Env;
 use tokio::{
    fs::remove_file,
    io::{AsyncReadExt, AsyncWrite},
@ -16,6 +17,7 @@ use tokio::{
    sync::Mutex,
 };
 use tokio_util::codec::Framed;
+use log::{info, error, debug};

 use crate::jobs::{
    process_decrypt_signature, process_get_signature_timestamp, process_player_status,
@ -24,11 +26,11 @@ use crate::jobs::{

 macro_rules! loop_main {
    ($i:ident, $s:ident) => {
-        println!("Fetching player");
+        info!("Fetching player");
        match fetch_update($s.clone()).await {
-            Ok(()) => println!("Successfully fetched player"),
+            Ok(()) => info!("Successfully fetched player"),
            Err(x) => {
-                println!("Error occured while trying to fetch the player: {:?}", x);
+                error!("Error occured while trying to fetch the player: {:?}", x);
            }
        }
        loop {
@ -43,6 +45,8 @@ macro_rules! loop_main {
 }
 #[tokio::main]
 async fn main() {
+    env_logger::Builder::from_env(Env::default().default_filter_or("info")).init();
+
    let args: Vec<String> = args().collect();
    let socket_url: &str = match args.get(1) {
        Some(stringref) => stringref,
@ -60,14 +64,14 @@ async fn main() {
        let tcp_socket = match TcpListener::bind(socket_tcp_url).await {
            Ok(x) => x,
            Err(x) => {
-                println!("Error occurred while trying to bind: {}", x);
+                error!("Error occurred while trying to bind: {}", x);
                return;
            }
        };
        loop_main!(tcp_socket, state);
    } else if socket_url == "--test" {
        // TODO: test the API aswell, this only tests the player script extractor
-        println!("Fetching player");
+        info!("Fetching player");
        match fetch_update(state.clone()).await {
            Ok(()) => std::process::exit(0),
            Err(_x) => std::process::exit(-1),
@ -80,7 +84,7 @@ async fn main() {
                    remove_file(socket_url).await;
                    UnixListener::bind(socket_url).unwrap()
                } else {
-                    println!("Error occurred while trying to bind: {}", x);
+                    error!("Error occurred while trying to bind: {}", x);
                    return;
                }
            }
@ -102,7 +106,7 @@ where
    while let Some(opcode_res) = stream.next().await {
        match opcode_res {
            Ok(opcode) => {
-                //println!("Received job: {}", opcode.opcode);
+                debug!("Received job: {}", opcode.opcode);

                match opcode.opcode {
                    JobOpcode::ForceUpdate => {
@ -177,7 +181,7 @@ where
                }
            }
            Err(x) => {
-                println!("I/O error: {:?}", x);
+                error!("I/O error: {:?}", x);
                break;
            }
        }
--- a/src/opcode.rs
+++ b/src/opcode.rs
@ -1,5 +1,5 @@
 use std::io::ErrorKind;
-
+use log::debug;
 use tokio_util::{
    bytes::{Buf, BufMut},
    codec::{Decoder, Encoder},
@ -52,7 +52,7 @@ impl Decoder for OpcodeDecoder {
        &mut self,
        src: &mut tokio_util::bytes::BytesMut,
    ) -> Result<Option<Self::Item>, Self::Error> {
-        //println!("Decoder length: {}", src.len());
+        debug!("Decoder length: {}", src.len());
        if 5 > src.len() {
            return Ok(None);
        }
--- a/src/player.rs
+++ b/src/player.rs
@ -1,5 +1,5 @@
 use std::{sync::Arc, time::SystemTime};
-
+use log::{debug, error, info, warn};
 use regex::Regex;

 use crate::{
@ -25,7 +25,7 @@ pub async fn fetch_update(state: Arc<GlobalState>) -> Result<(), FetchUpdateStat
    let response = match reqwest::get(TEST_YOUTUBE_VIDEO).await {
        Ok(req) => req.text().await.unwrap(),
        Err(x) => {
-            println!("Could not fetch the test video: {}", x);
+            error!("Could not fetch the test video: {}", x);
            return Err(FetchUpdateStatus::CannotFetchTestVideo);
        }
    };
@ -52,11 +52,11 @@ pub async fn fetch_update(state: Arc<GlobalState>) -> Result<(), FetchUpdateStat
        "https://www.youtube.com/s/player/{:08x}/player_ias.vflset/en_US/base.js",
        player_id
    );
-    println!("Fetching player JS URL: {}", player_js_url);
+    info!("Fetching player JS URL: {}", player_js_url);
    let player_javascript = match reqwest::get(player_js_url).await {
        Ok(req) => req.text().await.unwrap(),
        Err(x) => {
-            println!("Could not fetch the player JS: {}", x);
+            error!("Could not fetch the player JS: {}", x);
            return Err(FetchUpdateStatus::CannotFetchPlayerJS);
        }
    };
@ -67,9 +67,9 @@ pub async fn fetch_update(state: Arc<GlobalState>) -> Result<(), FetchUpdateStat
        let nsig_function_array_regex = Regex::new(&nsig_function_array_str).unwrap();
        nsig_function_array_opt = match nsig_function_array_regex.captures(&player_javascript) {
            None => {
-                println!("nsig function array did not work: {}", nsig_function_array_str);
+                warn!("nsig function array did not work: {}", nsig_function_array_str);
                if index == NSIG_FUNCTION_ARRAYS.len() {
-                    println!("!!ERROR!! nsig function array unable to be extracted");
+                    error!("!!ERROR!! nsig function array unable to be extracted");
                    return Err(FetchUpdateStatus::NsigRegexCompileFailed);
                }
                continue;
@ -98,7 +98,7 @@ pub async fn fetch_update(state: Arc<GlobalState>) -> Result<(), FetchUpdateStat
    let nsig_array_context = match Regex::new(&nsig_array_context_regex) {
        Ok(x) => x,
        Err(x) => {
-            println!("Error: nsig regex compilation failed: {}", x);
+            error!("Error: nsig regex compilation failed: {}", x);
            return Err(FetchUpdateStatus::NsigRegexCompileFailed);
        }
    };
@ -128,9 +128,9 @@ pub async fn fetch_update(state: Arc<GlobalState>) -> Result<(), FetchUpdateStat
        let nsig_function_code_regex = Regex::new(&nsig_function_code_regex_str).unwrap();
        nsig_function_code += match nsig_function_code_regex.captures(&player_javascript) {
            None => {
-                println!("nsig function ending did not work: {}", ending);
+                warn!("nsig function ending did not work: {}", ending);
                if index == NSIG_FUNCTION_ENDINGS.len() {
-                    println!("!!ERROR!! nsig function unable to be extracted");
+                    error!("!!ERROR!! nsig function unable to be extracted");
                    return Err(FetchUpdateStatus::NsigRegexCompileFailed);
                }

@ -140,7 +140,7 @@ pub async fn fetch_update(state: Arc<GlobalState>) -> Result<(), FetchUpdateStat
                i.get(1).unwrap().as_str()
            }
        };
-        //println!("got nsig fn code: {}", nsig_function_code);
+        debug!("got nsig fn code: {}", nsig_function_code);
        break;
    }

@ -194,7 +194,7 @@ pub async fn fetch_update(state: Arc<GlobalState>) -> Result<(), FetchUpdateStat
    sig_code += helper_object_body;
    sig_code += sig_function_body;

-    println!("sig code: {}", sig_code);
+    info!("sig code: {}", sig_code);

    // Get signature timestamp
    let signature_timestamp: u64 = REGEX_SIGNATURE_TIMESTAMP