Switch to stdlib log

config/config.example.yml

@@ -289,7 +289,7 @@ https_only: false
 ## Logging Verbosity. This is overridden if "-l LEVEL" or
 ## "--log-level=LEVEL" are passed on the command line.
 ##
-## Accepted values: All, Trace, Debug, Info, Warn, Error, Fatal, Off
+## Accepted values: Trace, Debug, Info, Notice, Warn, Error, Fatal, None
 ## Default: Info
 ##
 #log_level: Info

shard.lock

@@ -10,23 +10,23 @@ shards:
 
   backtracer:
     git: https://github.com/sija/backtracer.cr.git
-    version: 1.2.2
+    version: 1.2.4
 
   db:
     git: https://github.com/crystal-lang/crystal-db.git
     version: 0.13.1
 
   exception_page:
     git: https://github.com/crystal-loot/exception_page.git
-    version: 0.4.1
+    version: 0.5.0
 
   http_proxy:
     git: https://github.com/mamantoha/http_proxy.git
     version: 0.10.3
 
   kemal:
     git: https://github.com/kemalcr/kemal.git
-    version: 1.6.0
+    version: 1.7.2
 
   pg:
     git: https://github.com/will/crystal-pg.git

shard.yml

@@ -17,7 +17,7 @@ dependencies:
     version: ~> 0.21.0
   kemal:
     github: kemalcr/kemal
-    version: ~> 1.6.0
+    version: ~> 1.7.2
   protodec:
     github: iv-org/protodec
     version: ~> 0.1.5

spec/parsers_helper.cr

@@ -8,7 +8,6 @@ require "spectator"
 
 require "../src/invidious/exceptions"
 require "../src/invidious/helpers/macros"
-require "../src/invidious/helpers/logger"
 require "../src/invidious/helpers/utils"
 
 require "../src/invidious/videos"
@@ -19,9 +18,6 @@ require "../src/invidious/helpers/serialized_yt_data"
 require "../src/invidious/yt_backend/extractors"
 require "../src/invidious/yt_backend/extractors_utils"
 
-OUTPUT = File.open(File::NULL, "w")
-LOGGER = Invidious::LogHandler.new(OUTPUT, LogLevel::Off)
-
 def load_mock(file) : Hash(String, JSON::Any)
   file = File.join(__DIR__, "..", "mocks", file + ".json")
   content = File.read(file)

src/invidious.cr

@@ -15,7 +15,6 @@
 # along with this program.  If not, see <http://www.gnu.org/licenses/>.
 
 require "digest/md5"
-require "file_utils"
 
 # Require kemal, then our own overrides
 require "kemal"
@@ -30,6 +29,7 @@ require "xml"
 require "yaml"
 require "compress/zip"
 require "protodec/utils"
+require "log"
 
 require "./invidious/database/*"
 require "./invidious/database/migrations/*"
@@ -128,8 +128,8 @@ Kemal.config.extra_options do |parser|
   parser.on("-o OUTPUT", "--output=OUTPUT", "Redirect output (default: #{CONFIG.output})") do |output|
     CONFIG.output = output
   end
-  parser.on("-l LEVEL", "--log-level=LEVEL", "Log level, one of #{LogLevel.values} (default: #{CONFIG.log_level})") do |log_level|
-    CONFIG.log_level = LogLevel.parse(log_level)
+  parser.on("-l LEVEL", "--log-level=LEVEL", "Log level, one of #{Log::Severity.values} (default: #{CONFIG.log_level})") do |log_level|
+    CONFIG.log_level = Log::Severity.parse(log_level)
   end
   parser.on("-k", "--colorize", "Colorize logs") do
     CONFIG.colorize_logs = true
@@ -146,11 +146,23 @@ end
 
 Kemal::CLI.new ARGV
 
-if CONFIG.output.upcase != "STDOUT"
-  FileUtils.mkdir_p(File.dirname(CONFIG.output))
+Log.setup do |c|
+  colorize = CONFIG.colorize_logs
+  output = CONFIG.output
+
+  backend = Log::IOBackend.new(formatter: Invidious::Logger.formatter(colorize))
+  if output.upcase != "STDOUT"
+    Dir.mkdir_p(File.dirname(output))
+    io = File.open(output, "wb")
+    colorize = false
+    backend = Log::IOBackend.new(io, formatter: Invidious::Logger.formatter(colorize))
+    puts("File output enabled in config, logs will being saved in '#{output}'")
+  end
+
+  c.bind "*", CONFIG.log_level, backend
+  c.bind "db.*", :none, backend
+  c.bind "http.*", :none, backend
 end
-OUTPUT = CONFIG.output.upcase == "STDOUT" ? STDOUT : File.open(CONFIG.output, mode: "a")
-LOGGER = Invidious::LogHandler.new(OUTPUT, CONFIG.log_level, CONFIG.colorize_logs)
 
 # Check table integrity
 Invidious::Database.check_integrity(CONFIG)
@@ -244,11 +256,13 @@ add_handler FilteredCompressHandler.new
 add_handler APIHandler.new
 add_handler AuthHandler.new
 add_handler DenyFrame.new
+# Turn off default Kemal logging since we are using our own one based on Kemal::RequestLogHandler
+Kemal.config.logging = false
+add_handler Invidious::RequestLogHandler.new
 add_context_storage_type(Array(String))
 add_context_storage_type(Preferences)
 add_context_storage_type(Invidious::User)
 
-Kemal.config.logger = LOGGER
 Kemal.config.app_name = "Invidious"
 
 # Use in kemal's production mode.

src/invidious/channels/channels.cr

@@ -156,18 +156,18 @@ def get_channel(id) : InvidiousChannel
 end
 
 def fetch_channel(ucid, pull_all_videos : Bool)
-  LOGGER.debug("fetch_channel: #{ucid}")
-  LOGGER.trace("fetch_channel: #{ucid} : pull_all_videos = #{pull_all_videos}")
+  Log.debug { "fetch_channel: #{ucid}" }
+  Log.trace { "fetch_channel: #{ucid} : pull_all_videos = #{pull_all_videos}" }
 
   namespaces = {
     "yt"      => "http://www.youtube.com/xml/schemas/2015",
     "media"   => "http://search.yahoo.com/mrss/",
     "default" => "http://www.w3.org/2005/Atom",
   }
 
-  LOGGER.trace("fetch_channel: #{ucid} : Downloading RSS feed")
+  Log.trace { "fetch_channel: #{ucid} : Downloading RSS feed" }
   rss = YT_POOL.client &.get("/feeds/videos.xml?channel_id=#{ucid}").body
-  LOGGER.trace("fetch_channel: #{ucid} : Parsing RSS feed")
+  Log.trace { "fetch_channel: #{ucid} : Parsing RSS feed" }
   rss = XML.parse(rss)
 
   author = rss.xpath_node("//default:feed/default:title", namespaces)
@@ -184,7 +184,7 @@ def fetch_channel(ucid, pull_all_videos : Bool)
     auto_generated = true
   end
 
-  LOGGER.trace("fetch_channel: #{ucid} : author = #{author}, auto_generated = #{auto_generated}")
+  Log.trace { "fetch_channel: #{ucid} : author = #{author}, auto_generated = #{auto_generated}" }
 
   channel = InvidiousChannel.new({
     id:         ucid,
@@ -194,10 +194,10 @@ def fetch_channel(ucid, pull_all_videos : Bool)
     subscribed: nil,
   })
 
-  LOGGER.trace("fetch_channel: #{ucid} : Downloading channel videos page")
+  Log.trace { "fetch_channel: #{ucid} : Downloading channel videos page" }
   videos, continuation = IV::Channel::Tabs.get_videos(channel)
 
-  LOGGER.trace("fetch_channel: #{ucid} : Extracting videos from channel RSS feed")
+  Log.trace { "fetch_channel: #{ucid} : Extracting videos from channel RSS feed" }
   rss.xpath_nodes("//default:feed/default:entry", namespaces).each do |entry|
     video_id = entry.xpath_node("yt:videoId", namespaces).not_nil!.content
     title = entry.xpath_node("default:title", namespaces).not_nil!.content
@@ -241,17 +241,17 @@ def fetch_channel(ucid, pull_all_videos : Bool)
       views:              views,
     })
 
-    LOGGER.trace("fetch_channel: #{ucid} : video #{video_id} : Updating or inserting video")
+    Log.trace { "fetch_channel: #{ucid} : video #{video_id} : Updating or inserting video" }
 
     # We don't include the 'premiere_timestamp' here because channel pages don't include them,
     # meaning the above timestamp is always null
     was_insert = Invidious::Database::ChannelVideos.insert(video)
 
     if was_insert
-      LOGGER.trace("fetch_channel: #{ucid} : video #{video_id} : Inserted, updating subscriptions")
+      Log.trace { "fetch_channel: #{ucid} : video #{video_id} : Inserted, updating subscriptions" }
       NOTIFICATION_CHANNEL.send(VideoNotification.from_video(video))
     else
-      LOGGER.trace("fetch_channel: #{ucid} : video #{video_id} : Updated")
+      Log.trace { "fetch_channel: #{ucid} : video #{video_id} : Updated" }
     end
   end
 

src/invidious/config.cr

@@ -73,6 +73,7 @@ end
 
 class Config
   include YAML::Serializable
+  CLog = ::Log.for(self)
 
   class CompanionConfig
     include YAML::Serializable
@@ -93,8 +94,8 @@ class Config
   property feed_threads : Int32 = 1
   # Log file path or STDOUT
   property output : String = "STDOUT"
-  # Default log level, valid YAML values are ints and strings, see src/invidious/helpers/logger.cr
-  property log_level : LogLevel = LogLevel::Info
+  # Default log level, valid YAML values are ints and strings, see https://crystal-lang.org/api/1.17.1/Log/Severity.html#enum-members
+  property log_level : Log::Severity = Log::Severity::Info
   # Enables colors in logs. Useful for debugging purposes
   property colorize_logs : Bool = false
   # Database configuration with separate parameters (username, hostname, etc)
@@ -244,43 +245,43 @@ class Config
 
             # Exit on fail
             if !success
-                puts %(Config.{{ivar.id}} failed to parse #{env_value} as {{ivar.type}})
+                CLog.fatal { %({{ivar.id}} failed to parse #{env_value} as {{ivar.type}}) }
                 exit(1)
             end
         end
 
         # Warn when any config attribute is set to "CHANGE_ME!!"
         if config.{{ivar.id}} == "CHANGE_ME!!"
-          puts "Config: The value of '#{ {{ivar.stringify}} }' needs to be changed!!"
+          CLog.fatal { "The value of '#{ {{ivar.stringify}} }' needs to be changed!!" }
           exit(1)
         end
     {% end %}
 
     if config.invidious_companion.present?
       # invidious_companion and signature_server can't work together
       if config.signature_server
-        puts "Config: You can not run inv_sig_helper and invidious_companion at the same time."
+        CLog.fatal { "You can not run inv_sig_helper and invidious_companion at the same time." }
         exit(1)
       elsif config.invidious_companion_key.empty?
-        puts "Config: Please configure a key if you are using invidious companion."
+        CLog.fatal { "Please configure a key if you are using invidious companion." }
         exit(1)
       elsif config.invidious_companion_key == "CHANGE_ME!!"
-        puts "Config: The value of 'invidious_companion_key' needs to be changed!!"
+        CLog.fatal { "The value of 'invidious_companion_key' needs to be changed!!" }
         exit(1)
       elsif config.invidious_companion_key.size != 16
-        puts "Config: The value of 'invidious_companion_key' needs to be a size of 16 characters."
+        CLog.fatal { "The value of 'invidious_companion_key' needs to be a size of 16 characters." }
         exit(1)
       end
     elsif config.signature_server
-      puts("WARNING: inv-sig-helper is deprecated. Please switch to Invidious companion: https://docs.invidious.io/companion-installation/")
+      CLog.warn { "inv-sig-helper is deprecated. Please switch to Invidious companion: https://docs.invidious.io/companion-installation/" }
     else
-      puts("WARNING: Invidious companion is required to view and playback videos. For more information see https://docs.invidious.io/companion-installation/")
+      CLog.warn { "Invidious companion is required to view and playback videos. For more information see https://docs.invidious.io/companion-installation/" }
     end
 
     # HMAC_key is mandatory
     # See: https://github.com/iv-org/invidious/issues/3854
     if config.hmac_key.empty?
-      puts "Config: 'hmac_key' is required/can't be empty"
+      CLog.fatal { "'hmac_key' is required/can't be empty" }
       exit(1)
     end
 
@@ -296,25 +297,25 @@ class Config
           path: db.dbname,
         )
       else
-        puts "Config: Either database_url or db.* is required"
+        CLog.fatal { "Either database_url or db.* is required" }
         exit(1)
       end
     end
 
     # Check if the socket configuration is valid
     if sb = config.socket_binding
       if sb.path.ends_with?("/") || File.directory?(sb.path)
-        puts "Config: The socket path " + sb.path + " must not be a directory!"
+        CLog.fatal { "The socket path " + sb.path + " must not be a directory!" }
         exit(1)
       end
       d = File.dirname(sb.path)
       if !File.directory?(d)
-        puts "Config: Socket directory " + sb.path + " does not exist or is not a directory!"
+        CLog.fatal { "Socket directory " + sb.path + " does not exist or is not a directory!" }
         exit(1)
       end
       p = sb.permissions.to_i?(base: 8)
       if !p || p < 0 || p > 0o777
-        puts "Config: Socket permissions must be an octal between 0 and 777!"
+        CLog.fatal { "Socket permissions must be an octal between 0 and 777!" }
         exit(1)
       end
     end

src/invidious/database/base.cr

@@ -2,6 +2,7 @@ require "pg"
 
 module Invidious::Database
   extend self
+  Log = ::Log.for(self)
 
   # Checks table integrity
   #
@@ -33,7 +34,7 @@ module Invidious::Database
     return # TODO
 
     if !PG_DB.query_one?("SELECT true FROM pg_type WHERE typname = $1", enum_name, as: Bool)
-      LOGGER.info("check_enum: CREATE TYPE #{enum_name}")
+      Log.info { "check_enum: CREATE TYPE #{enum_name}" }
 
       PG_DB.using_connection do |conn|
         conn.as(PG::Connection).exec_all(File.read("config/sql/#{enum_name}.sql"))
@@ -46,7 +47,7 @@ module Invidious::Database
     begin
       PG_DB.exec("SELECT * FROM #{table_name} LIMIT 0")
     rescue ex
-      LOGGER.info("check_table: check_table: CREATE TABLE #{table_name}")
+      Log.info { "check_table: CREATE TABLE #{table_name}" }
 
       PG_DB.using_connection do |conn|
         conn.as(PG::Connection).exec_all(File.read("config/sql/#{table_name}.sql"))
@@ -66,7 +67,7 @@ module Invidious::Database
       if name != column_array[i]?
         if !column_array[i]?
           new_column = column_types.select(&.starts_with?(name))[0]
-          LOGGER.info("check_table: ALTER TABLE #{table_name} ADD COLUMN #{new_column}")
+          Log.info { "check_table: ALTER TABLE #{table_name} ADD COLUMN #{new_column}" }
           PG_DB.exec("ALTER TABLE #{table_name} ADD COLUMN #{new_column}")
           next
         end
@@ -84,29 +85,29 @@ module Invidious::Database
 
             # There's a column we didn't expect
             if !new_column
-              LOGGER.info("check_table: ALTER TABLE #{table_name} DROP COLUMN #{column_array[i]}")
+              Log.info { "check_table: ALTER TABLE #{table_name} DROP COLUMN #{column_array[i]}" }
               PG_DB.exec("ALTER TABLE #{table_name} DROP COLUMN #{column_array[i]} CASCADE")
 
               column_array = get_column_array(PG_DB, table_name)
               next
             end
 
-            LOGGER.info("check_table: ALTER TABLE #{table_name} ADD COLUMN #{new_column}")
+            Log.info { "check_table: ALTER TABLE #{table_name} ADD COLUMN #{new_column}" }
             PG_DB.exec("ALTER TABLE #{table_name} ADD COLUMN #{new_column}")
 
-            LOGGER.info("check_table: UPDATE #{table_name} SET #{column_array[i]}_new=#{column_array[i]}")
+            Log.info { "check_table: UPDATE #{table_name} SET #{column_array[i]}_new=#{column_array[i]}" }
             PG_DB.exec("UPDATE #{table_name} SET #{column_array[i]}_new=#{column_array[i]}")
 
-            LOGGER.info("check_table: ALTER TABLE #{table_name} DROP COLUMN #{column_array[i]} CASCADE")
+            Log.info { "check_table: ALTER TABLE #{table_name} DROP COLUMN #{column_array[i]} CASCADE" }
             PG_DB.exec("ALTER TABLE #{table_name} DROP COLUMN #{column_array[i]} CASCADE")
 
-            LOGGER.info("check_table: ALTER TABLE #{table_name} RENAME COLUMN #{column_array[i]}_new TO #{column_array[i]}")
+            Log.info { "check_table: ALTER TABLE #{table_name} RENAME COLUMN #{column_array[i]}_new TO #{column_array[i]}" }
             PG_DB.exec("ALTER TABLE #{table_name} RENAME COLUMN #{column_array[i]}_new TO #{column_array[i]}")
 
             column_array = get_column_array(PG_DB, table_name)
           end
         else
-          LOGGER.info("check_table: ALTER TABLE #{table_name} DROP COLUMN #{column_array[i]} CASCADE")
+          Log.info { "check_table: ALTER TABLE #{table_name} DROP COLUMN #{column_array[i]} CASCADE" }
           PG_DB.exec("ALTER TABLE #{table_name} DROP COLUMN #{column_array[i]} CASCADE")
         end
       end
@@ -116,7 +117,7 @@ module Invidious::Database
 
     column_array.each do |column|
       if !struct_array.includes? column
-        LOGGER.info("check_table: ALTER TABLE #{table_name} DROP COLUMN #{column} CASCADE")
+        Log.info { "check_table: ALTER TABLE #{table_name} DROP COLUMN #{column} CASCADE" }
         PG_DB.exec("ALTER TABLE #{table_name} DROP COLUMN #{column} CASCADE")
       end
     end

src/invidious/database/migrator.cr

@@ -14,12 +14,12 @@ class Invidious::Database::Migrator
       .each do |migration|
         next if versions.includes?(migration.version)
 
-        puts "Running migration: #{migration.class.name}"
+        Log.info { "Running migration: #{migration.class.name}" }
         migration.migrate
         ran_migration = true
       end
 
-    puts "No migrations to run." unless ran_migration
+    Log.info { "No migrations to run." } unless ran_migration
   end
 
   def pending_migrations? : Bool