iv-org/invidious

[Bug] `DB::MappingException` with `updated` property of `Invidious::User`

wiljateiwaz opened this issue · 13 comments

wiljateiwaz commented

Describe the bug
I updated my instance after reading this PR #5059 because I had the error with YouTube as well. I used the latest built image on quay quay.io/invidious/invidious:2024.11.08-b173d4a

The instance started but the homepage (subscriptions) shows an error, I can't go to any other page.

Steps to Reproduce
Update image in place on docker-composer.yml from 2024.09.16-de918b9 to quay.io/invidious/invidious:2024.11.08-b173d4a with an instance setting location set to Europe/Paris.

Logs

Title: `Invalid location name: Europe/Paris
  deserializing Invidious::User#updated (DB::MappingException)`
Date: `2024-11-08T23:46:52Z`
Route: `/feed/subscriptions`
Version: `2024.11.08-b173d4a @ master`

<details>
<summary>Backtrace</summary>
<p>
   
'''
Invalid location name: Europe/Paris
  deserializing Invidious::User#updated (DB::MappingException)
  from lib/db/src/db/serializable.cr:105:7 in 'read'
  from lib/db/src/db/query_methods.cr:128:9 in 'select!:email'
  from src/invidious/routes/before_all.cr:84:16 in '->'
  from lib/kemal/src/kemal/filter_handler.cr:82:62 in '->'
  from lib/kemal/src/kemal/filter_handler.cr:58:23 in 'call_block_for_path_type'
  from lib/kemal/src/kemal/filter_handler.cr:16:7 in 'call'
  from /usr/share/crystal/src/http/server/handler.cr:30:7 in 'call'
  from /usr/share/crystal/src/http/server/handler.cr:30:7 in 'call_next'
  from src/invidious/helpers/handlers.cr:94:12 in 'call'
  from /usr/share/crystal/src/http/server/handler.cr:30:7 in 'call'
  from /usr/share/crystal/src/http/server/handler.cr:30:7 in 'call'
  from /usr/share/crystal/src/http/server/handler.cr:30:7 in 'call_next'
  from src/ext/kemal_static_file_handler.cr:106:14 in 'call'
  from /usr/share/crystal/src/http/server/handler.cr:30:7 in 'call'
  from /usr/share/crystal/src/http/server/handler.cr:30:7 in 'call'
  from /usr/share/crystal/src/http/server/handler.cr:30:7 in 'call'
  from /usr/share/crystal/src/http/server/request_processor.cr:51:11 in 'handle_client'
  from /usr/share/crystal/src/fiber.cr:141:11 in 'run'
  from ???
Caused by: Invalid location name: Europe/Paris (Time::Location::InvalidLocationNameError)
  from /usr/share/crystal/src/time/location/loader.cr:23:8 in 'load'
  from lib/pg/src/pg/connection.cr:53:7 in '->'
  from /usr/share/crystal/src/hash.cr:1149:15 in 'decode'
  from lib/pg/src/pg/result_set.cr:91:7 in 'read'
  from lib/db/src/db/result_set.cr:85:15 in 'read'
  from lib/db/src/db/serializable.cr:105:7 in 'read'
  from lib/db/src/db/query_methods.cr:128:9 in 'select!:email'
  from src/invidious/routes/before_all.cr:84:16 in '->'
  from lib/kemal/src/kemal/filter_handler.cr:82:62 in '->'
  from lib/kemal/src/kemal/filter_handler.cr:58:23 in 'call_block_for_path_type'
  from lib/kemal/src/kemal/filter_handler.cr:16:7 in 'call'
  from /usr/share/crystal/src/http/server/handler.cr:30:7 in 'call'
  from /usr/share/crystal/src/http/server/handler.cr:30:7 in 'call_next'
  from src/invidious/helpers/handlers.cr:94:12 in 'call'
  from /usr/share/crystal/src/http/server/handler.cr:30:7 in 'call'
  from /usr/share/crystal/src/http/server/handler.cr:30:7 in 'call'
  from /usr/share/crystal/src/http/server/handler.cr:30:7 in 'call_next'
  from src/ext/kemal_static_file_handler.cr:106:14 in 'call'
  from /usr/share/crystal/src/http/server/handler.cr:30:7 in 'call'
  from /usr/share/crystal/src/http/server/handler.cr:30:7 in 'call'
  from /usr/share/crystal/src/http/server/handler.cr:30:7 in 'call'
  from /usr/share/crystal/src/http/server/request_processor.cr:51:11 in 'handle_client'
  from /usr/share/crystal/src/fiber.cr:141:11 in 'run'
  from ???
'''
</p>
</details>

Screenshots
N/D

Additional context
Using docker compose to deploy the instance, with external PostgreSQL database.

inv-sig-helper also shows an error:

inv_sig_helper-1  | [2024-11-05T22:24:11Z ERROR inv_sig_helper_rust::player] Could not fetch the test video: error sending request for url (https://www.youtube.com/watch?v=jNQXAC9IVRw)

and some warnings:

inv_sig_helper-1  | [2024-11-04T21:32:37Z INFO  inv_sig_helper_rust::player] Fetching player JS URL: https://www.youtube.com/s/player/81ef9024/player_ias.vflset/en_US/base.js
inv_sig_helper-1  | [2024-11-04T21:32:37Z WARN  inv_sig_helper_rust::player] nsig function ending did not work: =\s*function(\([\w]+\)\{\s*var\s+[\w\s]+=[\w\.\s]+?\.call\s*\([\w\s$]+?,[\(\)\",\s]+\)[\S\s]*?\}\s*return [\w\.\s$]+?\.call\s*\([\w\s$]+?\s*,[\(\)\",\s]+\)\s*\}\s*;)
inv_sig_helper-1  | [2024-11-04T21:32:37Z INFO  inv_sig_helper_rust::player] sig code: var ICa;var SL={hR:function(a,b){var c=a[0];a[0]=a[b%a.length];a[b%a.length]=c},
inv_sig_helper-1  |     k6:function(a){a.reverse()},
inv_sig_helper-1  |     K9:function(a,b){a.splice(0,b)}};ICa=function(a){a=a.split("");SL.K9(a,2);SL.k6(a,36);SL.hR(a,42);return a.join("")}
inv_sig_helper-1  | [2024-11-05T09:38:25Z INFO  inv_sig_helper_rust::player] Fetching player JS URL: https://www.youtube.com/s/player/4e23410d/player_ias.vflset/en_US/base.js
inv_sig_helper-1  | [2024-11-05T09:38:26Z WARN  inv_sig_helper_rust::player] nsig function ending did not work: =\s*function(\([\w]+\)\{\s*var\s+[\w\s]+=[\w\.\s]+?\.call\s*\([\w\s$]+?,[\(\)\",\s]+\)[\S\s]*?\}\s*return [\w\.\s$]+?\.call\s*\([\w\s$]+?\s*,[\(\)\",\s]+\)\s*\}\s*;)
inv_sig_helper-1  | [2024-11-05T09:38:26Z INFO  inv_sig_helper_rust::player] sig code: var ECa;var RL={Ys:function(a){a.reverse()},
inv_sig_helper-1  |     N3:function(a,b){var c=a[0];a[0]=a[b%a.length];a[b%a.length]=c},
inv_sig_helper-1  |     vz:function(a,b){a.splice(0,b)}};ECa=function(a){a=a.split("");RL.vz(a,1);RL.N3(a,45);RL.N3(a,52);RL.vz(a,3);RL.Ys(a,31);RL.vz(a,3);RL.Ys(a,30);return a.join("")}
inv_sig_helper-1  | [2024-11-05T22:17:19Z INFO  inv_sig_helper_rust::player] Fetching player JS URL: https://www.youtube.com/s/player/81ef9024/player_ias.vflset/en_US/base.js
inv_sig_helper-1  | [2024-11-05T22:17:20Z WARN  inv_sig_helper_rust::player] nsig function ending did not work: =\s*function(\([\w]+\)\{\s*var\s+[\w\s]+=[\w\.\s]+?\.call\s*\([\w\s$]+?,[\(\)\",\s]+\)[\S\s]*?\}\s*return [\w\.\s$]+?\.call\s*\([\w\s$]+?\s*,[\(\)\",\s]+\)\s*\}\s*;)
inv_sig_helper-1  | [2024-11-05T22:17:20Z INFO  inv_sig_helper_rust::player] sig code: var ICa;var SL={hR:function(a,b){var c=a[0];a[0]=a[b%a.length];a[b%a.length]=c},
inv_sig_helper-1  |     k6:function(a){a.reverse()},
inv_sig_helper-1  |     K9:function(a,b){a.splice(0,b)}};ICa=function(a){a=a.split("");SL.K9(a,2);SL.k6(a,36);SL.hR(a,42);return a.join("")}
syeopite commented

By location you mean the region setting in the configs right? Only the following country codes are supported.

AE, AR, AT, AU, AZ, BA, BD, BE, BG, BH, BO, BR, BY, CA, CH, CL, CO, CR,
CY, CZ, DE, DK, DO, DZ, EC, EE, EG, ES, FI, FR, GB, GE, GH, GR, GT, HK,
HN, HR, HU, ID, IE, IL, IN, IQ, IS, IT, JM, JO, JP, KE, KR, KW, KZ, LB,
LI, LK, LT, LU, LV, LY, MA, ME, MK, MT, MX, MY, NG, NI, NL, NO, NP, NZ,
OM, PA, PE, PG, PH, PK, PL, PR, PT, PY, QA, RO, RS, RU, SA, SE, SG, SI,
SK, SN, SV, TH, TN, TR, TW, TZ, UA, UG, US, UY, VE, VN, YE, ZA, ZW
wiljateiwaz commented

I'm not meaning anything, I'm telling what the homepage and the logs of Docker are showing.

I didn't try to put Europe/Paris anywhere, I only changed the image tag and restarted, the error shows up. I know my setting in the config is indeed FR. Hence my concern about a link with the update and an issue that you already closed...

wiljateiwaz commented

Reverting image to quay.io/invidious/invidious:2024.10.30-2e3a7ad, then force refresh the page in the browser's tab work just fine. Except I have again the error related to YouTube:

Youtube API returned error 400 with message:
"Request contains an invalid argument."
syeopite commented

Okay that's strange. I'm assuming the culprit is likely #5034

The updated version of crystal-db we're using seems to have added more places where DB::MappingException is rasied whereas it might've just been silently ignored in the past the actual problem is here #5067 (comment)

Thanks for the report! Apologies about my haste in closing the issue

  • 👍1
krim404 commented

Can confirm, i have a similar issue:

Title: `Invalid location name: Etc/UTC
  deserializing Invidious::User#updated (DB::MappingException)`
Date: `2024-11-09T00:33:04Z`
Route: `/preferences?referer=`
Version: `2024.11.09-b04c1a3 @ (HEAD detached at b04c1a3)`

Invalid location name: Etc/UTC
  deserializing Invidious::User#updated (DB::MappingException)
  from lib/db/src/db/serializable.cr:105:7 in 'initialize:__set_for_db_serializable'
  from src/invidious/user/user.cr:4:3 in 'new'
  from lib/db/src/db/result_set.cr:79:7 in 'read'
  from lib/db/src/db/query_methods.cr:128:9 in 'query_one:as'
  from src/invidious/database/users.cr:207:12 in 'select!:email'
  from src/invidious/routes/before_all.cr:84:16 in 'handle'
  from src/invidious.cr:211:3 in '->'
  from lib/kemal/src/kemal/filter_handler.cr:82:62 in '->'
  from lib/kemal/src/kemal/filter_handler.cr:86:16 in 'call'
  from lib/kemal/src/kemal/filter_handler.cr:58:23 in 'call_block_for_path_type'
  from lib/kemal/src/kemal/filter_handler.cr:16:7 in 'call'
  from /usr/lib/crystal/core/http/server/handler.cr:30:7 in 'call_next'
  from src/invidious/helpers/handlers.cr:157:5 in 'call'
  from /usr/lib/crystal/core/http/server/handler.cr:30:7 in 'call_next'
  from src/invidious/helpers/handlers.cr:94:12 in 'call'
  from /usr/lib/crystal/core/http/server/handler.cr:30:7 in 'call_next'
  from src/invidious/helpers/handlers.cr:146:5 in 'call'
  from /usr/lib/crystal/core/http/server/handler.cr:30:7 in 'call_next'
  from src/invidious/helpers/handlers.cr:70:5 in 'call'
  from /usr/lib/crystal/core/http/server/handler.cr:30:7 in 'call_next'
  from src/ext/kemal_static_file_handler.cr:162:16 in 'call'
  from /usr/lib/crystal/core/http/server/handler.cr:30:7 in 'call_next'
  from lib/kemal/src/kemal/exception_handler.cr:8:7 in 'call'
  from /usr/lib/crystal/core/http/server/handler.cr:30:7 in 'call_next'
  from src/invidious/helpers/logger.cr:21:35 in 'call'
  from /usr/lib/crystal/core/http/server/handler.cr:30:7 in 'call_next'
  from lib/kemal/src/kemal/init_handler.cr:12:7 in 'call'
  from /usr/lib/crystal/core/http/server/request_processor.cr:51:11 in 'process'
  from /usr/lib/crystal/core/http/server.cr:521:5 in 'handle_client'
  from /usr/lib/crystal/core/http/server.cr:451:5 in '->'
  from /usr/lib/crystal/core/fiber.cr:146:11 in 'run'
  from /usr/lib/crystal/core/fiber.cr:98:34 in '->'
  from ???
Caused by: Invalid location name: Etc/UTC (Time::Location::InvalidLocationNameError)
  from /usr/lib/crystal/core/time/location/loader.cr:22 in 'load'
  from lib/pg/src/pg/connection.cr:53:26 in '->'
  from /usr/lib/crystal/core/hash.cr:1173:15 in '[]'
  from lib/pg/src/pg/connection.cr:63:9 in 'time_zone'
  from lib/pg/src/pg/decoder.cr:428:19 in 'decode'
  from lib/pg/src/pg/result_set.cr:91:7 in 'read'
  from lib/db/src/db/result_set.cr:85:15 in 'read'
  from lib/db/src/db/serializable.cr:105:7 in 'initialize:__set_for_db_serializable'
  from src/invidious/user/user.cr:4:3 in 'new'
  from lib/db/src/db/result_set.cr:79:7 in 'read'
  from lib/db/src/db/query_methods.cr:128:9 in 'query_one:as'
  from src/invidious/database/users.cr:207:12 in 'select!:email'
  from src/invidious/routes/before_all.cr:84:16 in 'handle'
  from src/invidious.cr:211:3 in '->'
  from lib/kemal/src/kemal/filter_handler.cr:82:62 in '->'
  from lib/kemal/src/kemal/filter_handler.cr:86:16 in 'call'
  from lib/kemal/src/kemal/filter_handler.cr:58:23 in 'call_block_for_path_type'
  from lib/kemal/src/kemal/filter_handler.cr:16:7 in 'call'
  from /usr/lib/crystal/core/http/server/handler.cr:30:7 in 'call_next'
  from src/invidious/helpers/handlers.cr:157:5 in 'call'
  from /usr/lib/crystal/core/http/server/handler.cr:30:7 in 'call_next'
  from src/invidious/helpers/handlers.cr:94:12 in 'call'
  from /usr/lib/crystal/core/http/server/handler.cr:30:7 in 'call_next'
  from src/invidious/helpers/handlers.cr:146:5 in 'call'
  from /usr/lib/crystal/core/http/server/handler.cr:30:7 in 'call_next'
  from src/invidious/helpers/handlers.cr:70:5 in 'call'
  from /usr/lib/crystal/core/http/server/handler.cr:30:7 in 'call_next'
  from src/ext/kemal_static_file_handler.cr:162:16 in 'call'
  from /usr/lib/crystal/core/http/server/handler.cr:30:7 in 'call_next'
  from lib/kemal/src/kemal/exception_handler.cr:8:7 in 'call'
  from /usr/lib/crystal/core/http/server/handler.cr:30:7 in 'call_next'
  from src/invidious/helpers/logger.cr:21:35 in 'call'
  from /usr/lib/crystal/core/http/server/handler.cr:30:7 in 'call_next'
  from lib/kemal/src/kemal/init_handler.cr:12:7 in 'call'
  from /usr/lib/crystal/core/http/server/request_processor.cr:51:11 in 'process'
  from /usr/lib/crystal/core/http/server.cr:521:5 in 'handle_client'
  from /usr/lib/crystal/core/http/server.cr:451:5 in '->'
  from /usr/lib/crystal/core/fiber.cr:146:11 in 'run'
  from /usr/lib/crystal/core/fiber.cr:98:34 in '->'
  from ???
krim404 commented

i can confirm: reverting #5034 fixes this issue.

syeopite commented

Version v0.27.0 of the pg dependency began parsing the timezone of postgres columns with a type of TIMESTAMPTZ

And for some reason Crystal isn't able to parse the timezone provided

syeopite commented

Please let me know if this patch fixes the problem!

diff --git a/docker/Dockerfile b/docker/Dockerfile
index 3d9323fd..ac0eaa79 100644
--- a/docker/Dockerfile
+++ b/docker/Dockerfile
@@ -1,6 +1,6 @@
 FROM crystallang/crystal:1.12.1-alpine AS builder
 
-RUN apk add --no-cache sqlite-static yaml-static
+RUN apk add --no-cache sqlite-static yaml-static tzdata
 
 ARG release
 
diff --git a/docker/Dockerfile.arm64 b/docker/Dockerfile.arm64
index f054b326..ef47948a 100644
--- a/docker/Dockerfile.arm64
+++ b/docker/Dockerfile.arm64
@@ -1,5 +1,5 @@
 FROM alpine:3.19 AS builder
-RUN apk add --no-cache 'crystal=1.10.1-r0' shards sqlite-static yaml-static yaml-dev libxml2-static zlib-static openssl-libs-static openssl-dev musl-dev xz-static
+RUN apk add --no-cache 'crystal=1.10.1-r0' shards sqlite-static yaml-static yaml-dev libxml2-static zlib-static openssl-libs-static openssl-dev musl-dev xz-static tzdata
 
 ARG release
  • 🎉1
krim404 commented

(cross)compiling right now, will report in a few minutes
edit: no. adding tzdata is not fixing it.

RoiArthurB commented

Edit by SamantazFox: This problem is #5021 and is not related to the problem reported above.

Update on my side, the issue also happens on quay.io/invidious/invidious:2024.10.30-2e3a7ad for me...

invidious-1       | 2024-11-09 02:07:20 UTC [error] YoutubeAPI: Got error 400 when requesting /youtubei/v1/browse
invidious-1       | 2024-11-09 02:07:20 UTC [error] YoutubeAPI: Request contains an invalid argument.
invidious-1       | 2024-11-09 02:07:20 UTC [info] YoutubeAPI: POST data was: {"context" => {"client" => {"hl" => "en", "gl" => "US", "clientName" => "WEB", "clientVersion" => "2.20240814.00.00", "clientScreen" => "WATCH_FULL_SCREEN", "osName" => "Windows", "osVersion" => "10.0", "platform" => "DESKTOP", "visitorData" => "CgtWbmgwWWlxWUdCQSiQyLC2BjIKCgJTRxIEGgAgGg%3D%3D"}}, "continuation" => "4qmFsgKvARIYVUMxb1JUNjUwRVhZOHFDSnJZdDZBQ3hRGmQ4Z1pJR2taNlJBb1lDaFpGWjBsSlFVTm5lVTFCUlRSSWEyZENWVUZCSlRORUVpWUtKREF3TURBd01EQXdMVEF3TURBdE1EQXdNQzB3TURBd0xUQXdNREF3TURBd01EQXdNQmdCmgIsYnJvd3NlLWZlZWRVQzFvUlQ2NTBFWFk4cUNKcll0NkFDeFF2aWRlb3MxMDI%3D"}
invidious-1       | 2024-11-09 02:07:20 UTC [error] RefreshChannelsJob: UC1oRT650EXY8qCJrYt6ACxQ : Could not extract JSON. Youtube API returned error 400 with message:<br>"Request contains an invalid argument."
invidious-1       | 2024-11-09 02:07:20 UTC [error] RefreshChannelsJob: UC1oRT650EXY8qCJrYt6ACxQ fiber : backing off for 00:16:00s

EDIT: But 2024.11.08-b173d4a does work just fine now... 🤪

shiny-comic commented

The error from crystal seems fixed since version 1.12.0.
crystal-lang/crystal#14185

So I built the image with this diff patch and can confirm the error is gone.

diff --git a/docker/Dockerfile.arm64 b/docker/Dockerfile.arm64
index f054b326..3e3bc11e 100644
--- a/docker/Dockerfile.arm64
+++ b/docker/Dockerfile.arm64
@@ -1,5 +1,5 @@
-FROM alpine:3.19 AS builder
-RUN apk add --no-cache 'crystal=1.10.1-r0' shards sqlite-static yaml-static yaml-dev libxml2-static zlib-static openssl-libs-static openssl-dev musl-dev xz-static
+FROM alpine:3.20 AS builder
+RUN apk add --no-cache 'crystal=1.12.2-r0' shards sqlite-static yaml-static yaml-dev libxml2-static zlib-static openssl-libs-static openssl-dev musl-dev xz-static

 ARG release

@@ -32,7 +32,7 @@ RUN if [[ "${release}" == 1 ]] ; then \
         --link-flags "-lxml2 -llzma"; \
     fi

-FROM alpine:3.18
+FROM alpine:3.20
 RUN apk add --no-cache rsvg-convert ttf-opensans tini
 WORKDIR /invidious
 RUN addgroup -g 1000 -S invidious && \

(maybe tzdata is not needed)

EDIT: Sorry this is not able to watch video

EDIT2 : For someone having "Please sign in" error when trying to watch videos,
you need to remove visitor_data and po_token from INVIDIOUS_CONFIG

syeopite commented

From what I understand the tzdata package should allow Crystal to understand etc/utc regardless of the Crystal version.

SamantazFox commented

I understand that Etc/UTC was a problem. But I'm concerned about the database returning Europe/Paris in OP's case. Invidious should always work with UTC times, they're (or at least should) never localized, until used.

Edit: We might have a culprit:

invidious/src/invidious/yt_backend/extractors.cr

Line 76 in b173d4a

published = item_contents.dig?("publishedTimeText", "simpleText").try { |t| decode_date(t.as_s) } || Time.local

Edit2: Actually, more likely these two, given OP's error message:

invidious/src/invidious/database/users.cr

Lines 19 to 23 in b173d4a

if update_on_conflict
request += <<-SQL
ON CONFLICT (email) DO UPDATE
SET updated = $1, subscriptions = $3
SQL

invidious/src/invidious/database/users.cr

Lines 143 to 151 in b173d4a

def clear_notifications(user : User)
request = <<-SQL
UPDATE users
SET notifications = '{}', updated = now()
WHERE email = $1
SQL
PG_DB.exec(request, user.email)
end