dawarich
dawarich copied to clipboard
Freika
Problem with importing large GPX from PhoneTrack
Describe the bug I 'd like to migrate my tracks from PhoneTrack to Dawarich. PhoneTrack export is pretty large 469.8 MiB. Unfortunately, import request eventual (after ~10 minutes) end with empty response or "422 Unprocessable Content" and 0 imported points.
Version 0.21.2
To Reproduce Steps to reproduce the behavior:
- Just import try import large GPX file.
Expected behavior Points should be imported
Logs App logs:
Environment: development
dawarich_db (10.89.0.16:5432) open
Fetching rubygems-update-3.5.7.gem
Successfully installed rubygems-update-3.5.7
Installing RubyGems 3.5.7
Successfully built RubyGem
Name: bundler
Version: 2.5.7
File: bundler-2.5.7.gem
Bundler 2.5.7 installed
RubyGems 3.5.7 installed
Regenerating binstubs
Regenerating plugins
------------------------------------------------------------------------------
RubyGems installed the following executables:
/usr/local/bin/gem
/usr/local/bin/bundle
/usr/local/bin/bundler
RubyGems system software updated
Fetching bundler-2.5.9.gem
Successfully installed bundler-2.5.9
1 gem installed
A new release of RubyGems is available: 3.5.7 → 3.6.2!
Run `gem update --system 3.6.2` to update your installation.
Database dawarich_development already exists, skipping creation...
PostgreSQL is ready. Running database migrations...
[dotenv] Set �[36mDATABASE_PORT�[0m
[dotenv] Loaded �[33m.env.development�[0m
2025-01-01T18:23:00.166Z pid=35 tid=45r INFO: Sidekiq 7.3.7 connecting to Redis with options {:size=>10, :pool_name=>"internal", :url=>"redis://dawarich_redis:6379/0"}
I, [2025-01-01T18:23:00.166956 #35] INFO -- : Enqueued Cache::CleaningJob (Job ID: 5197d6ef-9723-4726-b326-afaf65590937) to Sidekiq(default)
I, [2025-01-01T18:23:00.167106 #35] INFO -- : ↳ config/environment.rb:10:in `<main>'
I, [2025-01-01T18:23:00.167525 #35] INFO -- : Enqueued Cache::PreheatingJob (Job ID: cb2d060c-55fd-4bbe-b85a-927fb85e1f56) to Sidekiq(default)
I, [2025-01-01T18:23:00.167887 #35] INFO -- : ↳ config/environment.rb:13:in `<main>'
D, [2025-01-01T18:23:00.387092 #35] DEBUG -- : �[1m�[36mActiveRecord::SchemaMigration Load (0.6ms)�[0m �[1m�[34mSELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC�[0m
D, [2025-01-01T18:23:00.444656 #35] DEBUG -- : �[1m�[36mActiveRecord::SchemaMigration Load (3.8ms)�[0m �[1m�[34mSELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC�[0m
Running DATA migrations...
[dotenv] Set �[36mDATABASE_PORT�[0m
[dotenv] Loaded �[33m.env.development�[0m
2025-01-01T18:23:01.163Z pid=64 tid=4b4 INFO: Sidekiq 7.3.7 connecting to Redis with options {:size=>10, :pool_name=>"internal", :url=>"redis://dawarich_redis:6379/0"}
I, [2025-01-01T18:23:01.164257 #64] INFO -- : Enqueued Cache::CleaningJob (Job ID: c806b9ac-717a-4345-85d2-3fac4ef6c2c4) to Sidekiq(default)
I, [2025-01-01T18:23:01.164413 #64] INFO -- : ↳ config/environment.rb:10:in `<main>'
I, [2025-01-01T18:23:01.164684 #64] INFO -- : Enqueued Cache::PreheatingJob (Job ID: 835e5eaf-33ed-44d3-bfd5-9a90cbeff5aa) to Sidekiq(default)
I, [2025-01-01T18:23:01.165035 #64] INFO -- : ↳ config/environment.rb:13:in `<main>'
D, [2025-01-01T18:23:01.250533 #64] DEBUG -- : �[1m�[35m (0.1ms)�[0m �[1m�[34mSELECT pg_try_advisory_lock(1212213197400985920)�[0m
D, [2025-01-01T18:23:01.252762 #64] DEBUG -- : �[1m�[36mDataMigrate::DataSchemaMigration Load (0.7ms)�[0m �[1m�[34mSELECT "data_migrations"."version" FROM "data_migrations" ORDER BY "data_migrations"."version" ASC�[0m
D, [2025-01-01T18:23:01.254854 #64] DEBUG -- : �[1m�[36mActiveRecord::InternalMetadata Load (0.5ms)�[0m �[1m�[34mSELECT * FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = $1 ORDER BY "ar_internal_metadata"."key" ASC LIMIT 1�[0m [[nil, "environment"]]
D, [2025-01-01T18:23:01.255236 #64] DEBUG -- : �[1m�[35m (0.1ms)�[0m �[1m�[34mSELECT pg_advisory_unlock(1212213197400985920)�[0m
D, [2025-01-01T18:23:01.260008 #64] DEBUG -- : �[1m�[36mDataMigrate::DataSchemaMigration Load (0.1ms)�[0m �[1m�[34mSELECT "data_migrations"."version" FROM "data_migrations" ORDER BY "data_migrations"."version" ASC�[0m
Running seeds...
[dotenv] Set �[36mDATABASE_PORT�[0m
[dotenv] Loaded �[33m.env.development�[0m
2025-01-01T18:23:01.944Z pid=80 tid=4ao INFO: Sidekiq 7.3.7 connecting to Redis with options {:size=>10, :pool_name=>"internal", :url=>"redis://dawarich_redis:6379/0"}
I, [2025-01-01T18:23:01.945535 #80] INFO -- : Enqueued Cache::CleaningJob (Job ID: a6da4281-1b62-4120-a969-3bcd42699ddb) to Sidekiq(default)
I, [2025-01-01T18:23:01.945711 #80] INFO -- : ↳ config/environment.rb:10:in `<main>'
I, [2025-01-01T18:23:01.946024 #80] INFO -- : Enqueued Cache::PreheatingJob (Job ID: 30abc484-7831-4a93-b643-5462fe79905c) to Sidekiq(default)
I, [2025-01-01T18:23:01.946338 #80] INFO -- : ↳ config/environment.rb:13:in `<main>'
D, [2025-01-01T18:23:02.043045 #80] DEBUG -- : �[1m�[36mActiveRecord::SchemaMigration Load (3.0ms)�[0m �[1m�[34mSELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC�[0m
D, [2025-01-01T18:23:02.077561 #80] DEBUG -- : �[1m�[36mUser Exists? (0.2ms)�[0m �[1m�[34mSELECT 1 AS one FROM "users" LIMIT $1�[0m [["LIMIT", 1]]
Starting Foreman with Procfile.dev...
�[36m18:23:02 web.1 | �[0mstarted with pid 101
�[36m18:23:02 web.1 | �[0m=> Booting Puma
�[36m18:23:02 web.1 | �[0m=> Rails 8.0.1 application starting in development
�[36m18:23:02 web.1 | �[0m=> Run `bin/rails server --help` for more startup options
�[36m18:23:02 web.1 | �[0m[dotenv] Set �[36mDATABASE_PORT�[0m
�[36m18:23:02 web.1 | �[0m[dotenv] Loaded �[33m.env.development�[0m
�[36m18:23:02 web.1 | �[0m2025-01-01T18:23:02.963Z pid=101 tid=3q9 INFO: Sidekiq 7.3.7 connecting to Redis with options {:size=>10, :pool_name=>"internal", :url=>"redis://dawarich_redis:6379/0"}
�[36m18:23:02 web.1 | �[0mI, [2025-01-01T18:23:02.964690 #101] INFO -- : Enqueued Cache::CleaningJob (Job ID: 2a4ddf7a-2d93-4403-8400-cd33be73271d) to Sidekiq(default)
�[36m18:23:02 web.1 | �[0mI, [2025-01-01T18:23:02.964834 #101] INFO -- : ↳ config/environment.rb:10:in `<main>'
�[36m18:23:02 web.1 | �[0mI, [2025-01-01T18:23:02.965146 #101] INFO -- : Enqueued Cache::PreheatingJob (Job ID: c1a927ab-c531-4666-8e87-388d253fab33) to Sidekiq(default)
�[36m18:23:02 web.1 | �[0mI, [2025-01-01T18:23:02.965521 #101] INFO -- : ↳ config/environment.rb:13:in `<main>'
�[36m18:23:02 web.1 | �[0m[101] Puma starting in cluster mode...
�[36m18:23:02 web.1 | �[0m[101] * Puma version: 6.5.0 ("Sky's Version")
�[36m18:23:02 web.1 | �[0m[101] * Ruby version: ruby 3.3.4 (2024-07-09 revision be1089c8ec) +YJIT [x86_64-linux-musl]
�[36m18:23:02 web.1 | �[0m[101] * Min threads: 5
�[36m18:23:02 web.1 | �[0m[101] * Max threads: 5
�[36m18:23:02 web.1 | �[0m[101] * Environment: development
�[36m18:23:02 web.1 | �[0m[101] * Master PID: 101
�[36m18:23:02 web.1 | �[0m[101] * Workers: 2
�[36m18:23:02 web.1 | �[0m[101] * Restarts: (✔) hot (✖) phased
�[36m18:23:02 web.1 | �[0m[101] * Preloading application
�[36m18:23:02 web.1 | �[0m[101] * Listening on http://[::]:3000
�[36m18:23:02 web.1 | �[0m[101] Use Ctrl-C to stop
�[36m18:23:02 web.1 | �[0m[101] - Worker 0 (PID: 115) booted in 0.0s, phase: 0
�[36m18:23:02 web.1 | �[0m[101] - Worker 1 (PID: 119) booted in 0.0s, phase: 0
�[36m18:23:03 web.1 | �[0mD, [2025-01-01T18:23:03.132246 #115] DEBUG -- : �[1m�[36mActiveRecord::SchemaMigration Load (2.5ms)�[0m �[1m�[34mSELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC�[0m
�[36m18:23:03 web.1 | �[0mI, [2025-01-01T18:23:03.291193 #115] INFO -- : {"method":"GET","path":"/imports","format":"html","controller":"ImportsController","action":"index","status":0,"allocations":3484,"duration":5.01,"view":0.0,"db":0.0}
�[36m18:23:03 web.1 | �[0mD, [2025-01-01T18:23:03.344754 #115] DEBUG -- : Rendering layout layouts/application.html.erb
�[36m18:23:03 web.1 | �[0mD, [2025-01-01T18:23:03.344826 #115] DEBUG -- : Rendering devise/sessions/new.html.erb within layouts/application
�[36m18:23:03 web.1 | �[0mI, [2025-01-01T18:23:03.967348 #115] INFO -- : {"method":"GET","path":"/users/sign_in","format":"html","controller":"Devise::SessionsController","action":"new","status":200,"allocations":351661,"duration":661.87,"view":629.39,"db":4.86}
�[36m18:23:04 web.1 | �[0mD, [2025-01-01T18:23:04.085171 #119] DEBUG -- : �[1m�[36mActiveRecord::SchemaMigration Load (3.3ms)�[0m �[1m�[34mSELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC�[0m
�[36m18:23:04 web.1 | �[0mI, [2025-01-01T18:23:04.291813 #115] INFO -- : {"method":null,"path":null,"format":null,"params":{},"controller":"ApplicationCable::Connection","action":"connect","status":200,"allocations":783,"duration":2.13}
�[36m18:23:04 web.1 | �[0mI, [2025-01-01T18:23:04.294078 #115] INFO -- : {"method":null,"path":null,"format":null,"params":{},"controller":"ApplicationCable::Connection","action":"disconnect","status":200,"allocations":20,"duration":0.04}
�[36m18:23:04 web.1 | �[0mI, [2025-01-01T18:23:04.746519 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":1574,"duration":3.1,"view":0.14,"db":0.0}
�[36m18:23:06 web.1 | �[0mD, [2025-01-01T18:23:06.798917 #119] DEBUG -- : Rendering layout layouts/application.html.erb
�[36m18:23:06 web.1 | �[0mD, [2025-01-01T18:23:06.799015 #119] DEBUG -- : Rendering devise/passwords/new.html.erb within layouts/application
�[36m18:23:07 web.1 | �[0mI, [2025-01-01T18:23:07.036423 #119] INFO -- : {"method":"GET","path":"/users/password/new","format":"html","controller":"Devise::PasswordsController","action":"new","status":200,"allocations":167711,"duration":268.14,"view":239.3,"db":4.75}
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.026922 #119] DEBUG -- : �[1m�[36mUser Load (1.3ms)�[0m �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."email" = $1 ORDER BY "users"."id" ASC LIMIT $2�[0m [["email", "[email protected]"], ["LIMIT", 1]]
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.027895 #119] DEBUG -- : ↳ app/controllers/application_controller.rb:11:in `unread_notifications'
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.161783 #119] DEBUG -- : �[1m�[36mTRANSACTION (0.1ms)�[0m �[1m�[35mBEGIN�[0m
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.162046 #119] DEBUG -- : ↳ app/controllers/application_controller.rb:11:in `unread_notifications'
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.162551 #119] DEBUG -- : �[1m�[36mUser Update (0.8ms)�[0m �[1m�[33mUPDATE "users" SET "updated_at" = $1, "sign_in_count" = $2, "current_sign_in_at" = $3, "last_sign_in_at" = $4, "current_sign_in_ip" = $5, "last_sign_in_ip" = $6 WHERE "users"."id" = $7�[0m [["updated_at", "2025-01-01 18:23:09.160860"], ["sign_in_count", 7], ["current_sign_in_at", "2025-01-01 18:23:09.160544"], ["last_sign_in_at", "2025-01-01 13:50:27.558439"], ["current_sign_in_ip", "::ffff:10.89.0.17"], ["last_sign_in_ip", "::ffff:10.89.0.14"], ["id", 1]]
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.162748 #119] DEBUG -- : ↳ app/controllers/application_controller.rb:11:in `unread_notifications'
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.166261 #119] DEBUG -- : �[1m�[36mTRANSACTION (3.2ms)�[0m �[1m�[35mCOMMIT�[0m
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.166416 #119] DEBUG -- : ↳ app/controllers/application_controller.rb:11:in `unread_notifications'
�[36m18:23:09 web.1 | �[0mI, [2025-01-01T18:23:09.175677 #119] INFO -- : {"method":"POST","path":"/users/sign_in","format":"turbo_stream","controller":"Devise::SessionsController","action":"create","status":303,"allocations":13241,"duration":154.75,"view":0.0,"db":6.25,"location":"http://localhost:3000/imports"}
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.183256 #119] DEBUG -- : �[1m�[36mUser Load (0.3ms)�[0m �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2�[0m [["id", 1], ["LIMIT", 1]]
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.183552 #119] DEBUG -- : ↳ app/controllers/application_controller.rb:11:in `unread_notifications'
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.203794 #119] DEBUG -- : Rendering layout layouts/application.html.erb
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.203834 #119] DEBUG -- : Rendering imports/index.html.erb within layouts/application
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.207889 #119] DEBUG -- : �[1m�[36mImport Exists? (0.4ms)�[0m �[1m�[34mSELECT 1 AS one FROM "imports" WHERE "imports"."user_id" = $1 LIMIT $2 OFFSET $3�[0m [["user_id", 1], ["LIMIT", 1], ["OFFSET", 0]]
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.208171 #119] DEBUG -- : ↳ app/views/imports/index.html.erb:21
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.208822 #119] DEBUG -- : �[1m�[36mImport Count (0.2ms)�[0m �[1m�[34mSELECT COUNT(*) FROM "imports" WHERE "imports"."user_id" = $1�[0m [["user_id", 1]]
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.209066 #119] DEBUG -- : ↳ app/views/imports/index.html.erb:35
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.212206 #119] DEBUG -- : �[1m�[36mImport Load (0.4ms)�[0m �[1m�[34mSELECT "imports"."id", "imports"."name", "imports"."source", "imports"."created_at", "imports"."points_count" FROM "imports" WHERE "imports"."user_id" = $1 ORDER BY "imports"."created_at" DESC LIMIT $2 OFFSET $3�[0m [["user_id", 1], ["LIMIT", 25], ["OFFSET", 0]]
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.212375 #119] DEBUG -- : ↳ app/views/imports/index.html.erb:53
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.259150 #119] DEBUG -- : �[1m�[36mPoint Count (0.8ms)�[0m �[1m�[34mSELECT COUNT(*) FROM "points" WHERE "points"."import_id" = $1 AND "points"."reverse_geocoded_at" IS NOT NULL�[0m [["import_id", 8]]
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.259310 #119] DEBUG -- : ↳ app/models/import.rb:19:in `reverse_geocoded_points_count'
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.260113 #119] DEBUG -- : �[1m�[36mPoint Count (0.1ms)�[0m �[1m�[34mSELECT COUNT(*) FROM "points" WHERE "points"."import_id" = $1 AND "points"."reverse_geocoded_at" IS NOT NULL�[0m [["import_id", 2]]
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.260245 #119] DEBUG -- : ↳ app/models/import.rb:19:in `reverse_geocoded_points_count'
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.264895 #119] DEBUG -- : �[1m�[36mPoint Count (0.3ms)�[0m �[1m�[34mSELECT COUNT(*) FROM "points" WHERE "points"."import_id" = $1 AND "points"."reverse_geocoded_at" IS NOT NULL�[0m [["import_id", 1]]
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.265034 #119] DEBUG -- : ↳ app/models/import.rb:19:in `reverse_geocoded_points_count'
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.280574 #119] DEBUG -- : �[1m�[36mNotification Load (2.2ms)�[0m �[1m�[34mSELECT "notifications".* FROM "notifications" WHERE "notifications"."user_id" = $1 AND "notifications"."read_at" IS NULL ORDER BY "notifications"."created_at" DESC�[0m [["user_id", 1]]
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.280991 #119] DEBUG -- : ↳ app/views/shared/_navbar.html.erb:72
�[36m18:23:09 web.1 | �[0mI, [2025-01-01T18:23:09.287538 #119] INFO -- : {"method":"GET","path":"/imports","format":"turbo_stream","controller":"ImportsController","action":"index","status":200,"allocations":43852,"duration":100.11,"view":71.57,"db":11.02}
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.313466 #115] DEBUG -- : �[1m�[36mUser Load (0.8ms)�[0m �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2�[0m [["id", 1], ["LIMIT", 1]]
�[36m18:23:09 web.1 | �[0mD, [2025-01-01T18:23:09.314438 #115] DEBUG -- : ↳ app/channels/application_cable/connection.rb:14:in `find_verified_user'
�[36m18:23:09 web.1 | �[0mI, [2025-01-01T18:23:09.315237 #115] INFO -- : {"method":null,"path":null,"format":null,"params":{},"controller":"ApplicationCable::Connection","action":"connect","status":200,"allocations":3066,"duration":5.12}
�[36m18:23:09 web.1 | �[0mI, [2025-01-01T18:23:09.318614 #115] INFO -- : {"method":null,"path":null,"format":null,"params":null,"controller":"NotificationsChannel","action":"subscribe","status":200,"allocations":154,"duration":0.15}
�[36m18:23:09 web.1 | �[0mI, [2025-01-01T18:23:09.319895 #115] INFO -- : {"method":null,"path":null,"format":null,"params":null,"controller":"ImportsChannel","action":"subscribe","status":200,"allocations":123,"duration":0.11}
�[36m18:23:09 web.1 | �[0mI, [2025-01-01T18:23:09.319225 #115] INFO -- : {"method":null,"path":null,"format":null,"params":null,"controller":"NotificationsChannel","action":"subscribe","status":200,"allocations":108,"duration":0.31}
�[36m18:23:09 web.1 | �[0mI, [2025-01-01T18:23:09.318830 #115] INFO -- : {"method":null,"path":null,"format":null,"params":null,"controller":"PointsChannel","action":"subscribe","status":200,"allocations":123,"duration":0.1}
�[36m18:23:09 web.1 | �[0mI, [2025-01-01T18:23:09.320119 #115] INFO -- : {"method":null,"path":null,"format":null,"params":null,"controller":"ImportsChannel","action":"subscribe","status":200,"allocations":108,"duration":0.08}
�[36m18:23:10 web.1 | �[0mD, [2025-01-01T18:23:10.909573 #119] DEBUG -- : �[1m�[36mUser Load (0.4ms)�[0m �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2�[0m [["id", 1], ["LIMIT", 1]]
�[36m18:23:10 web.1 | �[0mD, [2025-01-01T18:23:10.909822 #119] DEBUG -- : ↳ app/controllers/application_controller.rb:11:in `unread_notifications'
�[36m18:23:10 web.1 | �[0mD, [2025-01-01T18:23:10.923098 #119] DEBUG -- : �[1m�[36mVisit Count (0.4ms)�[0m �[1m�[34mSELECT COUNT(*) FROM "visits" WHERE "visits"."user_id" = $1 AND "visits"."status" = $2�[0m [["user_id", 1], ["status", 0]]
�[36m18:23:10 web.1 | �[0mD, [2025-01-01T18:23:10.923236 #119] DEBUG -- : ↳ app/controllers/visits_controller.rb:17:in `index'
�[36m18:23:10 web.1 | �[0mD, [2025-01-01T18:23:10.924626 #119] DEBUG -- : Rendering layout layouts/application.html.erb
�[36m18:23:10 web.1 | �[0mD, [2025-01-01T18:23:10.924651 #119] DEBUG -- : Rendering visits/index.html.erb within layouts/application
�[36m18:23:10 web.1 | �[0mD, [2025-01-01T18:23:10.927954 #119] DEBUG -- : �[1m�[36mVisit Exists? (0.1ms)�[0m �[1m�[34mSELECT 1 AS one FROM "visits" WHERE "visits"."user_id" = $1 AND "visits"."status" = $2 LIMIT $3 OFFSET $4�[0m [["user_id", 1], ["status", 1], ["LIMIT", 1], ["OFFSET", 0]]
�[36m18:23:10 web.1 | �[0mD, [2025-01-01T18:23:10.928202 #119] DEBUG -- : ↳ app/views/visits/index.html.erb:45
�[36m18:23:10 web.1 | �[0mD, [2025-01-01T18:23:10.937774 #119] DEBUG -- : �[1m�[36mNotification Load (0.1ms)�[0m �[1m�[34mSELECT "notifications".* FROM "notifications" WHERE "notifications"."user_id" = $1 AND "notifications"."read_at" IS NULL ORDER BY "notifications"."created_at" DESC�[0m [["user_id", 1]]
�[36m18:23:10 web.1 | �[0mD, [2025-01-01T18:23:10.937986 #119] DEBUG -- : ↳ app/views/shared/_navbar.html.erb:72
�[36m18:23:10 web.1 | �[0mI, [2025-01-01T18:23:10.943016 #119] INFO -- : {"method":"GET","path":"/visits","format":"html","controller":"VisitsController","action":"index","status":200,"allocations":21766,"duration":35.18,"view":18.49,"db":2.35}
�[36m18:23:15 web.1 | �[0mI, [2025-01-01T18:23:15.779382 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":272,"duration":0.69,"view":0.06,"db":0.0}
�[36m18:23:26 web.1 | �[0mI, [2025-01-01T18:23:26.564393 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.84,"view":0.23,"db":0.0}
�[36m18:23:37 web.1 | �[0mI, [2025-01-01T18:23:37.727844 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.45,"view":0.06,"db":0.0}
�[36m18:23:48 web.1 | �[0mI, [2025-01-01T18:23:48.632511 #115] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":345,"duration":1.31,"view":0.08,"db":0.0}
�[36m18:23:59 web.1 | �[0mI, [2025-01-01T18:23:59.834394 #115] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":271,"duration":0.74,"view":0.07,"db":0.0}
�[36m18:24:10 web.1 | �[0mI, [2025-01-01T18:24:10.635634 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.85,"view":0.16,"db":0.0}
�[36m18:24:21 web.1 | �[0mI, [2025-01-01T18:24:21.779151 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.47,"view":0.06,"db":0.0}
�[36m18:24:32 web.1 | �[0mI, [2025-01-01T18:24:32.583261 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.46,"view":0.06,"db":0.0}
�[36m18:24:38 web.1 | �[0mD, [2025-01-01T18:24:38.776830 #119] DEBUG -- : �[1m�[36mUser Load (0.4ms)�[0m �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2�[0m [["id", 1], ["LIMIT", 1]]
�[36m18:24:38 web.1 | �[0mD, [2025-01-01T18:24:38.777074 #119] DEBUG -- : ↳ app/controllers/application_controller.rb:11:in `unread_notifications'
�[36m18:24:38 web.1 | �[0mD, [2025-01-01T18:24:38.779667 #119] DEBUG -- : Rendering layout layouts/application.html.erb
�[36m18:24:38 web.1 | �[0mD, [2025-01-01T18:24:38.779905 #119] DEBUG -- : Rendering imports/new.html.erb within layouts/application
�[36m18:24:39 web.1 | �[0mD, [2025-01-01T18:24:39.070298 #119] DEBUG -- : �[1m�[36mNotification Load (0.8ms)�[0m �[1m�[34mSELECT "notifications".* FROM "notifications" WHERE "notifications"."user_id" = $1 AND "notifications"."read_at" IS NULL ORDER BY "notifications"."created_at" DESC�[0m [["user_id", 1]]
�[36m18:24:39 web.1 | �[0mD, [2025-01-01T18:24:39.070760 #119] DEBUG -- : ↳ app/views/shared/_navbar.html.erb:72
�[36m18:24:39 web.1 | �[0mI, [2025-01-01T18:24:39.072165 #119] INFO -- : {"method":"GET","path":"/imports/new","format":"html","controller":"ImportsController","action":"new","status":200,"allocations":18768,"duration":296.75,"view":293.05,"db":1.12}
�[36m18:24:43 web.1 | �[0mI, [2025-01-01T18:24:43.578590 #115] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":1.45,"view":0.64,"db":0.0}
�[36m18:24:46 web.1 | �[0mD, [2025-01-01T18:24:46.549701 #115] DEBUG -- : �[1m�[36mUser Load (0.3ms)�[0m �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2�[0m [["id", 1], ["LIMIT", 1]]
�[36m18:24:46 web.1 | �[0mD, [2025-01-01T18:24:46.549912 #115] DEBUG -- : ↳ app/controllers/application_controller.rb:11:in `unread_notifications'
�[36m18:24:46 web.1 | �[0mD, [2025-01-01T18:24:46.571727 #115] DEBUG -- : Rendering layout layouts/application.html.erb
�[36m18:24:46 web.1 | �[0mD, [2025-01-01T18:24:46.571758 #115] DEBUG -- : Rendering imports/index.html.erb within layouts/application
�[36m18:24:46 web.1 | �[0mD, [2025-01-01T18:24:46.575598 #115] DEBUG -- : �[1m�[36mImport Exists? (0.3ms)�[0m �[1m�[34mSELECT 1 AS one FROM "imports" WHERE "imports"."user_id" = $1 LIMIT $2 OFFSET $3�[0m [["user_id", 1], ["LIMIT", 1], ["OFFSET", 0]]
�[36m18:24:46 web.1 | �[0mD, [2025-01-01T18:24:46.575890 #115] DEBUG -- : ↳ app/views/imports/index.html.erb:21
�[36m18:24:46 web.1 | �[0mD, [2025-01-01T18:24:46.576312 #115] DEBUG -- : �[1m�[36mImport Count (0.1ms)�[0m �[1m�[34mSELECT COUNT(*) FROM "imports" WHERE "imports"."user_id" = $1�[0m [["user_id", 1]]
�[36m18:24:46 web.1 | �[0mD, [2025-01-01T18:24:46.576748 #115] DEBUG -- : ↳ app/views/imports/index.html.erb:35
�[36m18:24:46 web.1 | �[0mD, [2025-01-01T18:24:46.583932 #115] DEBUG -- : �[1m�[36mImport Load (0.4ms)�[0m �[1m�[34mSELECT "imports"."id", "imports"."name", "imports"."source", "imports"."created_at", "imports"."points_count" FROM "imports" WHERE "imports"."user_id" = $1 ORDER BY "imports"."created_at" DESC LIMIT $2 OFFSET $3�[0m [["user_id", 1], ["LIMIT", 25], ["OFFSET", 0]]
�[36m18:24:46 web.1 | �[0mD, [2025-01-01T18:24:46.584344 #115] DEBUG -- : ↳ app/views/imports/index.html.erb:53
�[36m18:24:46 web.1 | �[0mD, [2025-01-01T18:24:46.614523 #115] DEBUG -- : �[1m�[36mPoint Count (2.9ms)�[0m �[1m�[34mSELECT COUNT(*) FROM "points" WHERE "points"."import_id" = $1 AND "points"."reverse_geocoded_at" IS NOT NULL�[0m [["import_id", 8]]
�[36m18:24:46 web.1 | �[0mD, [2025-01-01T18:24:46.614747 #115] DEBUG -- : ↳ app/models/import.rb:19:in `reverse_geocoded_points_count'
�[36m18:24:46 web.1 | �[0mD, [2025-01-01T18:24:46.615906 #115] DEBUG -- : �[1m�[36mPoint Count (0.1ms)�[0m �[1m�[34mSELECT COUNT(*) FROM "points" WHERE "points"."import_id" = $1 AND "points"."reverse_geocoded_at" IS NOT NULL�[0m [["import_id", 2]]
�[36m18:24:46 web.1 | �[0mD, [2025-01-01T18:24:46.616070 #115] DEBUG -- : ↳ app/models/import.rb:19:in `reverse_geocoded_points_count'
�[36m18:24:46 web.1 | �[0mD, [2025-01-01T18:24:46.616909 #115] DEBUG -- : �[1m�[36mPoint Count (0.1ms)�[0m �[1m�[34mSELECT COUNT(*) FROM "points" WHERE "points"."import_id" = $1 AND "points"."reverse_geocoded_at" IS NOT NULL�[0m [["import_id", 1]]
�[36m18:24:46 web.1 | �[0mD, [2025-01-01T18:24:46.617035 #115] DEBUG -- : ↳ app/models/import.rb:19:in `reverse_geocoded_points_count'
�[36m18:24:46 web.1 | �[0mD, [2025-01-01T18:24:46.629563 #115] DEBUG -- : �[1m�[36mNotification Load (2.0ms)�[0m �[1m�[34mSELECT "notifications".* FROM "notifications" WHERE "notifications"."user_id" = $1 AND "notifications"."read_at" IS NULL ORDER BY "notifications"."created_at" DESC�[0m [["user_id", 1]]
�[36m18:24:46 web.1 | �[0mD, [2025-01-01T18:24:46.629717 #115] DEBUG -- : ↳ app/views/shared/_navbar.html.erb:72
�[36m18:24:46 web.1 | �[0mI, [2025-01-01T18:24:46.635879 #115] INFO -- : {"method":"GET","path":"/imports","format":"html","controller":"ImportsController","action":"index","status":200,"allocations":42907,"duration":82.18,"view":53.74,"db":9.59}
�[36m18:24:51 web.1 | �[0mD, [2025-01-01T18:24:51.639819 #115] DEBUG -- : �[1m�[36mUser Load (0.4ms)�[0m �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2�[0m [["id", 1], ["LIMIT", 1]]
�[36m18:24:51 web.1 | �[0mD, [2025-01-01T18:24:51.640020 #115] DEBUG -- : ↳ app/controllers/application_controller.rb:11:in `unread_notifications'
�[36m18:24:51 web.1 | �[0mD, [2025-01-01T18:24:51.652557 #115] DEBUG -- : �[1m�[36mTRANSACTION (0.2ms)�[0m �[1m�[35mBEGIN�[0m
�[36m18:24:51 web.1 | �[0mD, [2025-01-01T18:24:51.652838 #115] DEBUG -- : ↳ app/controllers/imports_controller.rb:26:in `block in create'
�[36m18:24:51 web.1 | �[0mD, [2025-01-01T18:24:51.653411 #115] DEBUG -- : �[1m�[36mImport Create (1.6ms)�[0m �[1m�[32mINSERT INTO "imports" ("name", "user_id", "source", "created_at", "updated_at", "raw_points", "doubles", "processed", "raw_data", "points_count") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10) RETURNING "id"�[0m [["name", "Telefon.gpx"], ["user_id", 1], ["source", 4], ["created_at", "2025-01-01 18:24:51.646125"], ["updated_at", "2025-01-01 18:24:51.646125"], ["raw_points", 0], ["doubles", 0], ["processed", 0], ["raw_data", nil], ["points_count", 0]]
�[36m18:24:51 web.1 | �[0mD, [2025-01-01T18:24:51.653624 #115] DEBUG -- : ↳ app/controllers/imports_controller.rb:26:in `block in create'
�[36m18:24:51 web.1 | �[0mD, [2025-01-01T18:24:51.662779 #115] DEBUG -- : �[1m�[36mTRANSACTION (3.7ms)�[0m �[1m�[35mCOMMIT�[0m
�[36m18:24:51 web.1 | �[0mD, [2025-01-01T18:24:51.662908 #115] DEBUG -- : ↳ app/controllers/imports_controller.rb:26:in `block in create'
�[36m18:24:54 web.1 | �[0mI, [2025-01-01T18:24:54.718543 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.42,"view":0.06,"db":0.0}
�[36m18:25:04 web.1 | �[0mI, [2025-01-01T18:25:04.892918 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.42,"view":0.06,"db":0.0}
�[36m18:25:15 web.1 | �[0mI, [2025-01-01T18:25:15.773383 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.59,"view":0.07,"db":0.0}
�[36m18:25:26 web.1 | �[0mI, [2025-01-01T18:25:26.087781 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.45,"view":0.06,"db":0.0}
�[36m18:25:36 web.1 | �[0mI, [2025-01-01T18:25:36.782818 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.37,"view":0.05,"db":0.0}
�[36m18:25:47 web.1 | �[0mI, [2025-01-01T18:25:47.622607 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.62,"view":0.06,"db":0.0}
�[36m18:25:58 web.1 | �[0mI, [2025-01-01T18:25:58.670452 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.52,"view":0.06,"db":0.0}
�[36m18:26:09 web.1 | �[0mI, [2025-01-01T18:26:09.627610 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.59,"view":0.21,"db":0.0}
�[36m18:26:20 web.1 | �[0mI, [2025-01-01T18:26:20.774209 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.53,"view":0.06,"db":0.0}
�[36m18:26:31 web.1 | �[0mI, [2025-01-01T18:26:31.671668 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.44,"view":0.06,"db":0.0}
�[36m18:26:42 web.1 | �[0mI, [2025-01-01T18:26:42.619758 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.5,"view":0.07,"db":0.0}
�[36m18:26:53 web.1 | �[0mI, [2025-01-01T18:26:53.740360 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.41,"view":0.06,"db":0.0}
�[36m18:27:04 web.1 | �[0mI, [2025-01-01T18:27:04.578489 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.46,"view":0.06,"db":0.0}
�[36m18:27:15 web.1 | �[0mI, [2025-01-01T18:27:15.622146 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.92,"view":0.49,"db":0.0}
�[36m18:27:26 web.1 | �[0mI, [2025-01-01T18:27:26.579189 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.43,"view":0.06,"db":0.0}
�[36m18:27:37 web.1 | �[0mI, [2025-01-01T18:27:37.821324 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.41,"view":0.06,"db":0.0}
�[36m18:27:48 web.1 | �[0mI, [2025-01-01T18:27:48.674304 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.42,"view":0.06,"db":0.0}
�[36m18:27:59 web.1 | �[0mI, [2025-01-01T18:27:59.567058 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.86,"view":0.45,"db":0.0}
�[36m18:28:10 web.1 | �[0mI, [2025-01-01T18:28:10.831162 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":1.65,"view":0.06,"db":0.0}
�[36m18:28:21 web.1 | �[0mI, [2025-01-01T18:28:21.570949 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.52,"view":0.06,"db":0.0}
�[36m18:28:32 web.1 | �[0mI, [2025-01-01T18:28:32.826968 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.4,"view":0.06,"db":0.0}
�[36m18:28:43 web.1 | �[0mI, [2025-01-01T18:28:43.818686 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.72,"view":0.36,"db":0.0}
�[36m18:28:54 web.1 | �[0mI, [2025-01-01T18:28:54.575293 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":3.15,"view":0.62,"db":0.0}
�[36m18:29:05 web.1 | �[0mI, [2025-01-01T18:29:05.667932 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.74,"view":0.06,"db":0.0}
�[36m18:29:16 web.1 | �[0mI, [2025-01-01T18:29:16.666997 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.61,"view":0.25,"db":0.0}
�[36m18:29:27 web.1 | �[0mI, [2025-01-01T18:29:27.570868 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":2.49,"view":0.07,"db":0.0}
�[36m18:29:38 web.1 | �[0mI, [2025-01-01T18:29:38.625648 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.42,"view":0.06,"db":0.0}
�[36m18:29:49 web.1 | �[0mI, [2025-01-01T18:29:49.727733 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.78,"view":0.17,"db":0.0}
�[36m18:30:00 web.1 | �[0mI, [2025-01-01T18:30:00.575852 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.79,"view":0.06,"db":0.0}
�[36m18:30:11 web.1 | �[0mI, [2025-01-01T18:30:11.675421 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.54,"view":0.07,"db":0.0}
�[36m18:30:22 web.1 | �[0mI, [2025-01-01T18:30:22.582057 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.38,"view":0.05,"db":0.0}
�[36m18:30:33 web.1 | �[0mI, [2025-01-01T18:30:33.669048 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.41,"view":0.06,"db":0.0}
�[36m18:30:44 web.1 | �[0mI, [2025-01-01T18:30:44.726911 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.4,"view":0.06,"db":0.0}
�[36m18:30:55 web.1 | �[0mI, [2025-01-01T18:30:55.578579 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.4,"view":0.06,"db":0.0}
�[36m18:31:06 web.1 | �[0mI, [2025-01-01T18:31:06.625734 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.4,"view":0.06,"db":0.0}
�[36m18:31:17 web.1 | �[0mI, [2025-01-01T18:31:17.574794 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.39,"view":0.06,"db":0.0}
�[36m18:31:28 web.1 | �[0mI, [2025-01-01T18:31:28.631283 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.49,"view":0.06,"db":0.0}
�[36m18:31:39 web.1 | �[0mI, [2025-01-01T18:31:39.778219 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.52,"view":0.07,"db":0.0}
�[36m18:31:43 web.1 | �[0mD, [2025-01-01T18:31:43.322704 #115] DEBUG -- : �[1m�[36mTRANSACTION (0.0ms)�[0m �[1m�[35mBEGIN�[0m
�[36m18:31:43 web.1 | �[0mD, [2025-01-01T18:31:43.323013 #115] DEBUG -- : ↳ app/controllers/imports_controller.rb:40:in `block in create'
�[36m18:31:54 web.1 | �[0mD, [2025-01-01T18:31:54.347337 #115] DEBUG -- : �[1m�[36mImport Update (3293.0ms)�[0m �[1m�[33mUPDATE "imports" SET "updated_at" = $1, "raw_data" = $2 WHERE "imports"."id" = $3�[0m [["updated_at", "2025-01-01 18:31:40.324162"], ["raw_data", (very long string, probably just gpx file content)
�[36m18:31:55 web.1 | �[0mD, [2025-01-01T18:31:54.583978 #115] DEBUG -- : ↳ app/controllers/imports_controller.rb:40:in `block in create'
�[36m18:31:55 web.1 | �[0mD, [2025-01-01T18:31:55.023721 #115] DEBUG -- : �[1m�[36mTRANSACTION (439.2ms)�[0m �[1m�[31mROLLBACK�[0m
�[36m18:31:55 web.1 | �[0mD, [2025-01-01T18:31:55.023921 #115] DEBUG -- : ↳ app/controllers/imports_controller.rb:40:in `block in create'
�[36m18:31:55 web.1 | �[0mD, [2025-01-01T18:31:55.029088 #115] DEBUG -- : �[1m�[36mImport Load (3.5ms)�[0m �[1m�[34mSELECT "imports".* FROM "imports" WHERE "imports"."user_id" = $1 AND "imports"."name" = $2�[0m [["user_id", 1], ["name", "Telefon.gpx"]]
�[36m18:31:55 web.1 | �[0mD, [2025-01-01T18:31:55.030153 #115] DEBUG -- : ↳ app/controllers/imports_controller.rb:48:in `rescue in create'
�[36m18:31:55 web.1 | �[0mD, [2025-01-01T18:31:55.033266 #115] DEBUG -- : �[1m�[36mTRANSACTION (0.1ms)�[0m �[1m�[35mBEGIN�[0m
�[36m18:31:55 web.1 | �[0mD, [2025-01-01T18:31:55.033706 #115] DEBUG -- : ↳ app/controllers/imports_controller.rb:48:in `rescue in create'
�[36m18:31:55 web.1 | �[0mD, [2025-01-01T18:31:55.037868 #115] DEBUG -- : �[1m�[36mPoint Load (2.0ms)�[0m �[1m�[34mSELECT "points".* FROM "points" WHERE "points"."import_id" = $1�[0m [["import_id", 50]]
�[36m18:31:55 web.1 | �[0mD, [2025-01-01T18:31:55.038154 #115] DEBUG -- : ↳ app/controllers/imports_controller.rb:48:in `rescue in create'
�[36m18:31:55 web.1 | �[0mD, [2025-01-01T18:31:55.040100 #115] DEBUG -- : �[1m�[36mImport Destroy (0.2ms)�[0m �[1m�[31mDELETE FROM "imports" WHERE "imports"."id" = $1�[0m [["id", 50]]
�[36m18:31:55 web.1 | �[0mD, [2025-01-01T18:31:55.040576 #115] DEBUG -- : ↳ app/controllers/imports_controller.rb:48:in `rescue in create'
�[36m18:31:55 web.1 | �[0mD, [2025-01-01T18:31:55.044803 #115] DEBUG -- : �[1m�[36mTRANSACTION (3.8ms)�[0m �[1m�[35mCOMMIT�[0m
�[36m18:31:55 web.1 | �[0mD, [2025-01-01T18:31:55.044990 #115] DEBUG -- : ↳ app/controllers/imports_controller.rb:48:in `rescue in create'
�[36m18:31:55 web.1 | �[0mI, [2025-01-01T18:31:55.047098 #115] INFO -- : {"method":"POST","path":"/imports","format":"turbo_stream","controller":"ImportsController","action":"create","status":422,"allocations":1427932702,"duration":423411.13,"view":0.0,"db":3754.39,"location":"http://localhost:3000/imports/new"}
�[36m18:32:01 web.1 | �[0mI, [2025-01-01T18:32:01.786674 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.43,"view":0.05,"db":0.0}
�[36m18:32:12 web.1 | �[0mI, [2025-01-01T18:32:12.839198 #115] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":272,"duration":1.18,"view":0.31,"db":0.0}
�[36m18:32:23 web.1 | �[0mI, [2025-01-01T18:32:23.620704 #115] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":271,"duration":0.59,"view":0.06,"db":0.0}
�[36m18:32:34 web.1 | �[0mI, [2025-01-01T18:32:34.621931 #115] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.48,"view":0.05,"db":0.0}
�[36m18:32:45 web.1 | �[0mI, [2025-01-01T18:32:45.575668 #115] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.59,"view":0.11,"db":0.0}
�[36m18:32:56 web.1 | �[0mI, [2025-01-01T18:32:56.721386 #115] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.52,"view":0.06,"db":0.0}
�[36m18:33:07 web.1 | �[0mI, [2025-01-01T18:33:07.729940 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.83,"view":0.06,"db":0.0}
�[36m18:33:17 web.1 | �[0mI, [2025-01-01T18:33:17.926701 #115] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.92,"view":0.06,"db":0.0}
�[36m18:33:28 web.1 | �[0mI, [2025-01-01T18:33:28.562920 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.56,"view":0.06,"db":0.0}
�[36m18:33:39 web.1 | �[0mI, [2025-01-01T18:33:39.570729 #115] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.4,"view":0.05,"db":0.0}
�[36m18:33:50 web.1 | �[0mI, [2025-01-01T18:33:50.771431 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":270,"duration":0.84,"view":0.41,"db":0.0}
�[36m18:34:01 web.1 | �[0mI, [2025-01-01T18:34:01.574279 #119] INFO -- : {"method":"GET","path":"/api/v1/health","format":"*/*","controller":"Api::V1::HealthController","action":"index","status":200,"allocations":272,"duration":0.99,"view":0.08,"db":0.0}
Additional context I remove all memory limits and used postgres config from: https://github.com/Freika/dawarich/issues/129#issuecomment-2454034410
Split from: https://github.com/Freika/dawarich/issues/129
sidekin:
Environment: development
dawarich_db (10.89.0.16:5432) open
Fetching rubygems-update-3.5.7.gem
Successfully installed rubygems-update-3.5.7
Installing RubyGems 3.5.7
Successfully built RubyGem
Name: bundler
Version: 2.5.7
File: bundler-2.5.7.gem
Bundler 2.5.7 installed
RubyGems 3.5.7 installed
Regenerating binstubs
Regenerating plugins
------------------------------------------------------------------------------
RubyGems installed the following executables:
/usr/local/bin/gem
/usr/local/bin/bundle
/usr/local/bin/bundler
RubyGems system software updated
Fetching bundler-2.5.9.gem
Successfully installed bundler-2.5.9
1 gem installed
A new release of RubyGems is available: 3.5.7 → 3.6.2!
Run `gem update --system 3.6.2` to update your installation.
Database dawarich_development already exists, skipping creation...
PostgreSQL is ready. Running database migrations...
[dotenv] Set �[36mDATABASE_PORT�[0m
[dotenv] Loaded �[33m.env.development�[0m
2025-01-01T18:23:00.537Z pid=39 tid=45n INFO: Sidekiq 7.3.7 connecting to Redis with options {:size=>10, :pool_name=>"internal", :url=>"redis://dawarich_redis:6379/0"}
I, [2025-01-01T18:23:00.537804 #39] INFO -- : Enqueued Cache::CleaningJob (Job ID: 85a9d80d-0a48-4aba-a862-688c8a814816) to Sidekiq(default)
I, [2025-01-01T18:23:00.537951 #39] INFO -- : ↳ config/environment.rb:10:in `<main>'
I, [2025-01-01T18:23:00.538379 #39] INFO -- : Enqueued Cache::PreheatingJob (Job ID: 979efbba-3ad5-4349-a8c2-947779dc1a28) to Sidekiq(default)
I, [2025-01-01T18:23:00.538690 #39] INFO -- : ↳ config/environment.rb:13:in `<main>'
D, [2025-01-01T18:23:00.760664 #39] DEBUG -- : �[1m�[36mActiveRecord::SchemaMigration Load (0.5ms)�[0m �[1m�[34mSELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC�[0m
D, [2025-01-01T18:23:00.810097 #39] DEBUG -- : �[1m�[36mActiveRecord::SchemaMigration Load (4.7ms)�[0m �[1m�[34mSELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC�[0m
Running DATA migrations...
[dotenv] Set �[36mDATABASE_PORT�[0m
[dotenv] Loaded �[33m.env.development�[0m
2025-01-01T18:23:01.529Z pid=68 tid=4b8 INFO: Sidekiq 7.3.7 connecting to Redis with options {:size=>10, :pool_name=>"internal", :url=>"redis://dawarich_redis:6379/0"}
I, [2025-01-01T18:23:01.529737 #68] INFO -- : Enqueued Cache::CleaningJob (Job ID: b335f387-ca3a-4c6e-a0ed-9358937f64fb) to Sidekiq(default)
I, [2025-01-01T18:23:01.529882 #68] INFO -- : ↳ config/environment.rb:10:in `<main>'
I, [2025-01-01T18:23:01.530147 #68] INFO -- : Enqueued Cache::PreheatingJob (Job ID: 81ee480c-b78b-4cdf-af99-d4794bac55a4) to Sidekiq(default)
I, [2025-01-01T18:23:01.530463 #68] INFO -- : ↳ config/environment.rb:13:in `<main>'
D, [2025-01-01T18:23:01.620596 #68] DEBUG -- : �[1m�[35m (0.0ms)�[0m �[1m�[34mSELECT pg_try_advisory_lock(1212213197400985920)�[0m
D, [2025-01-01T18:23:01.622795 #68] DEBUG -- : �[1m�[36mDataMigrate::DataSchemaMigration Load (0.7ms)�[0m �[1m�[34mSELECT "data_migrations"."version" FROM "data_migrations" ORDER BY "data_migrations"."version" ASC�[0m
D, [2025-01-01T18:23:01.624943 #68] DEBUG -- : �[1m�[36mActiveRecord::InternalMetadata Load (0.5ms)�[0m �[1m�[34mSELECT * FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = $1 ORDER BY "ar_internal_metadata"."key" ASC LIMIT 1�[0m [[nil, "environment"]]
D, [2025-01-01T18:23:01.625349 #68] DEBUG -- : �[1m�[35m (0.1ms)�[0m �[1m�[34mSELECT pg_advisory_unlock(1212213197400985920)�[0m
D, [2025-01-01T18:23:01.630560 #68] DEBUG -- : �[1m�[36mDataMigrate::DataSchemaMigration Load (0.1ms)�[0m �[1m�[34mSELECT "data_migrations"."version" FROM "data_migrations" ORDER BY "data_migrations"."version" ASC�[0m
Running seeds...
[dotenv] Set �[36mDATABASE_PORT�[0m
[dotenv] Loaded �[33m.env.development�[0m
2025-01-01T18:23:02.354Z pid=84 tid=4as INFO: Sidekiq 7.3.7 connecting to Redis with options {:size=>10, :pool_name=>"internal", :url=>"redis://dawarich_redis:6379/0"}
I, [2025-01-01T18:23:02.355304 #84] INFO -- : Enqueued Cache::CleaningJob (Job ID: 964850bd-7433-41fe-83f7-620ec8b887a3) to Sidekiq(default)
I, [2025-01-01T18:23:02.355493 #84] INFO -- : ↳ config/environment.rb:10:in `<main>'
I, [2025-01-01T18:23:02.355781 #84] INFO -- : Enqueued Cache::PreheatingJob (Job ID: 02b0bb7a-3bcc-40fe-8db1-fd3104a82fd4) to Sidekiq(default)
I, [2025-01-01T18:23:02.356075 #84] INFO -- : ↳ config/environment.rb:13:in `<main>'
D, [2025-01-01T18:23:02.450040 #84] DEBUG -- : �[1m�[36mActiveRecord::SchemaMigration Load (2.4ms)�[0m �[1m�[34mSELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC�[0m
D, [2025-01-01T18:23:02.484089 #84] DEBUG -- : �[1m�[36mUser Exists? (0.3ms)�[0m �[1m�[34mSELECT 1 AS one FROM "users" LIMIT $1�[0m [["LIMIT", 1]]
[dotenv] Set �[36mDATABASE_PORT�[0m
[dotenv] Loaded �[33m.env.development�[0m
2025-01-01T18:23:03.432Z pid=100 tid=3uw INFO: Sidekiq 7.3.7 connecting to Redis with options {:size=>10, :pool_name=>"internal", :url=>"redis://dawarich_redis:6379/0"}
I, [2025-01-01T18:23:03.475741 #100] INFO -- : Enqueued Cache::CleaningJob (Job ID: 3b6619cf-dffc-490d-95ea-04b58e8b4369) to Sidekiq(default)
I, [2025-01-01T18:23:03.475889 #100] INFO -- : ↳ config/environment.rb:10:in `<top (required)>'
I, [2025-01-01T18:23:03.476125 #100] INFO -- : Enqueued Cache::PreheatingJob (Job ID: 350aac5a-bec5-40e9-b40f-48f8eed418b2) to Sidekiq(default)
I, [2025-01-01T18:23:03.476424 #100] INFO -- : ↳ config/environment.rb:13:in `<top (required)>'
�[31m
�[1;37m m,
�[1;37m `$b
�[1;37m .ss, $$: .,d$
�[1;37m `$$P,d$P' .,md$P"'
�[1;37m ,$$$$$b�[30m/�[1;37mmd$$$P^'
�[1;37m .d$$$$$$�[30m/�[1;37m$$$P'
�[1;37m $$^' `"�[30m/�[1;37m$$$' �[1;31m____ _ _ _ _
�[1;37m $: �[30m'�[1;37m,$$: �[1;31m / ___|(_) __| | ___| | _(_) __ _
�[1;37m `b :$$ �[1;31m \___ \| |/ _` |/ _ \ |/ / |/ _` |
�[1;37m $$: �[1;31m ___) | | (_| | __/ <| | (_| |
�[1;37m $$ �[1;31m|____/|_|\__,_|\___|_|\_\_|\__, |
�[1;37m .d$$ �[1;31m |_|
�[0m
�[0m
2025-01-01T18:23:03.476Z pid=100 tid=3uw INFO: Booted Rails 8.0.1 application in development environment
2025-01-01T18:23:03.476Z pid=100 tid=3uw INFO: Running in ruby 3.3.4 (2024-07-09 revision be1089c8ec) +YJIT [x86_64-linux-musl]
2025-01-01T18:23:03.476Z pid=100 tid=3uw INFO: See LICENSE and the LGPL-3.0 for licensing details.
2025-01-01T18:23:03.476Z pid=100 tid=3uw INFO: Upgrade to Sidekiq Pro for more features and support: https://sidekiq.org
2025-01-01T18:23:03.476Z pid=100 tid=3uw INFO: Sidekiq 7.3.7 connecting to Redis with options {:size=>10, :pool_name=>"default", :url=>"redis://dawarich_redis:6379/0"}
2025-01-01T18:23:03.624Z pid=100 tid=3uw INFO: Starting processing, hit Ctrl-C to stop
2025-01-01T18:23:03.653Z pid=100 tid=i1s class=Cache::CleaningJob jid=0f6cff7d3cf21a70310627f6 INFO: start
2025-01-01T18:23:03.655Z pid=100 tid=hzs class=Cache::CleaningJob jid=ea0f3d84d9e97488e18f8c3b INFO: start
2025-01-01T18:23:03.655Z pid=100 tid=hw4 class=Cache::PreheatingJob jid=fb8e7a655171211e46b50adb INFO: start
2025-01-01T18:23:03.655Z pid=100 tid=i04 class=Cache::PreheatingJob jid=90fcf4b8b564565821d18b1a INFO: start
2025-01-01T18:23:03.656Z pid=100 tid=i0g class=Cache::CleaningJob jid=0ca8c3bac105d2e562e246ae INFO: start
2025-01-01T18:23:03.654Z pid=100 tid=i4g class=Cache::CleaningJob jid=25bb8808fb785ede72bdda2d INFO: start
2025-01-01T18:23:03.655Z pid=100 tid=i2k class=Cache::CleaningJob jid=97fdb2182fb7a60d72655a4b INFO: start
2025-01-01T18:23:03.653Z pid=100 tid=i5w class=Cache::PreheatingJob jid=231104bf2aeae1d46d3ee5c8 INFO: start
2025-01-01T18:23:03.656Z pid=100 tid=i14 class=Cache::PreheatingJob jid=d30c654d3e9ce65d95a7f55c INFO: start
2025-01-01T18:23:03.655Z pid=100 tid=hzg class=Cache::PreheatingJob jid=a8cdc30823eb96eff783ec48 INFO: start
I, [2025-01-01T18:23:03.704930 #100] INFO -- : Performing Cache::CleaningJob (Job ID: 0f2c0fb4-239f-41e0-8ca0-79139f0331bc) from Sidekiq(default) enqueued at 2025-01-01T13:49:06.054507892Z
I, [2025-01-01T18:23:03.705919 #100] INFO -- : Performing Cache::CleaningJob (Job ID: 8bc98f73-457a-4938-ac72-f379512c6e06) from Sidekiq(default) enqueued at 2025-01-01T13:49:30.705090588Z
I, [2025-01-01T18:23:03.705997 #100] INFO -- : Performing Cache::PreheatingJob (Job ID: 9b9e34af-0b2a-4d2d-bc00-8509156980a0) from Sidekiq(default) enqueued at 2025-01-01T13:49:06.916825552Z
I, [2025-01-01T18:23:03.716560 #100] INFO -- : Performing Cache::PreheatingJob (Job ID: f9b122d3-222d-4f82-975e-801f4a6c38d6) from Sidekiq(default) enqueued at 2025-01-01T13:49:06.055724044Z
I, [2025-01-01T18:23:03.712341 #100] INFO -- : Performing Cache::CleaningJob (Job ID: c8c13a84-2784-48f0-857a-d29ac5d22ddc) from Sidekiq(default) enqueued at 2025-01-01T13:49:29.715273272Z
I, [2025-01-01T18:23:03.712442 #100] INFO -- : Performing Cache::CleaningJob (Job ID: 8c2f9339-8269-4231-a2c7-de66ca715859) from Sidekiq(default) enqueued at 2025-01-01T13:49:06.915817738Z
I, [2025-01-01T18:23:03.714538 #100] INFO -- : Performing Cache::CleaningJob (Job ID: f6a9da4f-a981-4e50-94fc-f2c8729ce9c1) from Sidekiq(default) enqueued at 2025-01-01T13:49:07.726036892Z
I, [2025-01-01T18:23:03.714598 #100] INFO -- : Performing Cache::PreheatingJob (Job ID: 2819df0e-96ae-463a-8501-bb897ea9ec10) from Sidekiq(default) enqueued at 2025-01-01T13:49:29.716636194Z
I, [2025-01-01T18:23:03.706062 #100] INFO -- : Performing Cache::PreheatingJob (Job ID: 26561f5e-ec9d-415a-b4c2-502773958116) from Sidekiq(default) enqueued at 2025-01-01T13:49:07.727174845Z
I, [2025-01-01T18:23:03.718060 #100] INFO -- : Performing Cache::PreheatingJob (Job ID: 3b045324-4ddf-4e98-957a-abb43c72af8b) from Sidekiq(default) enqueued at 2025-01-01T13:49:30.706211142Z
I, [2025-01-01T18:23:03.746079 #100] INFO -- : Cleaning cache...
I, [2025-01-01T18:23:03.746409 #100] INFO -- : Cleaning cache...
I, [2025-01-01T18:23:03.746142 #100] INFO -- : Cleaning cache...
I, [2025-01-01T18:23:03.767854 #100] INFO -- : Cleaning cache...
I, [2025-01-01T18:23:03.769091 #100] INFO -- : Cleaning cache...
D, [2025-01-01T18:23:03.939172 #100] DEBUG -- : �[1m�[36mUser Load (16.3ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:03.940284 #100] DEBUG -- : ↳ app/jobs/cache/preheating_job.rb:7:in `perform'
D, [2025-01-01T18:23:03.940814 #100] DEBUG -- : �[1m�[36mUser Load (19.1ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:03.942671 #100] DEBUG -- : ↳ app/services/cache/clean.rb:19:in `delete_years_tracked_cache'
D, [2025-01-01T18:23:03.940986 #100] DEBUG -- : �[1m�[36mUser Load (19.5ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:03.943780 #100] DEBUG -- : ↳ app/services/cache/clean.rb:19:in `delete_years_tracked_cache'
D, [2025-01-01T18:23:03.941090 #100] DEBUG -- : �[1m�[36mUser Load (14.3ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:03.944156 #100] DEBUG -- : ↳ app/services/cache/clean.rb:19:in `delete_years_tracked_cache'
D, [2025-01-01T18:23:03.942382 #100] DEBUG -- : �[1m�[36mUser Load (12.5ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:03.944471 #100] DEBUG -- : ↳ app/jobs/cache/preheating_job.rb:7:in `perform'
D, [2025-01-01T18:23:03.942457 #100] DEBUG -- : �[1m�[36mUser Load (18.2ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:03.953845 #100] DEBUG -- : ↳ app/jobs/cache/preheating_job.rb:7:in `perform'
D, [2025-01-01T18:23:03.941028 #100] DEBUG -- : �[1m�[36mUser Load (16.9ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:03.954981 #100] DEBUG -- : ↳ app/jobs/cache/preheating_job.rb:7:in `perform'
D, [2025-01-01T18:23:03.942423 #100] DEBUG -- : �[1m�[36mUser Load (11.3ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:03.955661 #100] DEBUG -- : ↳ app/services/cache/clean.rb:19:in `delete_years_tracked_cache'
D, [2025-01-01T18:23:03.941154 #100] DEBUG -- : �[1m�[36mUser Load (8.2ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:03.956988 #100] DEBUG -- : ↳ app/jobs/cache/preheating_job.rb:7:in `perform'
D, [2025-01-01T18:23:03.940895 #100] DEBUG -- : �[1m�[36mUser Load (20.1ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:03.957358 #100] DEBUG -- : ↳ app/services/cache/clean.rb:19:in `delete_years_tracked_cache'
I, [2025-01-01T18:23:03.962071 #100] INFO -- : Cache cleaned
I, [2025-01-01T18:23:03.963230 #100] INFO -- : Performed Cache::CleaningJob (Job ID: 8bc98f73-457a-4938-ac72-f379512c6e06) from Sidekiq(default) in 256.38ms
2025-01-01T18:23:03.965Z pid=100 tid=hzs class=Cache::CleaningJob jid=ea0f3d84d9e97488e18f8c3b elapsed=0.31 INFO: done
I, [2025-01-01T18:23:03.965304 #100] INFO -- : Cache cleaned
I, [2025-01-01T18:23:03.966270 #100] INFO -- : Performed Cache::CleaningJob (Job ID: 8c2f9339-8269-4231-a2c7-de66ca715859) from Sidekiq(default) in 253.85ms
2025-01-01T18:23:03.966Z pid=100 tid=i0g class=Cache::CleaningJob jid=0ca8c3bac105d2e562e246ae elapsed=0.31 INFO: done
I, [2025-01-01T18:23:03.965453 #100] INFO -- : Cache cleaned
I, [2025-01-01T18:23:03.969687 #100] INFO -- : Performed Cache::CleaningJob (Job ID: 0f2c0fb4-239f-41e0-8ca0-79139f0331bc) from Sidekiq(default) in 264.94ms
2025-01-01T18:23:03.972Z pid=100 tid=i1s class=Cache::CleaningJob jid=0f6cff7d3cf21a70310627f6 elapsed=0.319 INFO: done
I, [2025-01-01T18:23:03.962225 #100] INFO -- : Cache cleaned
I, [2025-01-01T18:23:03.974854 #100] INFO -- : Performed Cache::CleaningJob (Job ID: c8c13a84-2784-48f0-857a-d29ac5d22ddc) from Sidekiq(default) in 262.53ms
2025-01-01T18:23:03.972Z pid=100 tid=hzs class=Cache::CleaningJob jid=8e07266bc7b0b2b00e111ef4 INFO: start
I, [2025-01-01T18:23:03.966587 #100] INFO -- : Cache cleaned
I, [2025-01-01T18:23:03.978191 #100] INFO -- : Performed Cache::CleaningJob (Job ID: f6a9da4f-a981-4e50-94fc-f2c8729ce9c1) from Sidekiq(default) in 263.66ms
2025-01-01T18:23:03.975Z pid=100 tid=i0g class=Cache::PreheatingJob jid=78ceda154a8bb69087876573 INFO: start
2025-01-01T18:23:03.975Z pid=100 tid=i4g class=Cache::CleaningJob jid=25bb8808fb785ede72bdda2d elapsed=0.321 INFO: done
2025-01-01T18:23:03.978Z pid=100 tid=i1s class=Cache::CleaningJob jid=a765fbc699616b381f77a7b4 INFO: start
2025-01-01T18:23:03.978Z pid=100 tid=i2k class=Cache::CleaningJob jid=97fdb2182fb7a60d72655a4b elapsed=0.323 INFO: done
2025-01-01T18:23:03.983Z pid=100 tid=i4g class=Cache::PreheatingJob jid=76944e47ff9c48db5a1cbb35 INFO: start
2025-01-01T18:23:03.984Z pid=100 tid=i2k class=Cache::CleaningJob jid=388fe00caa79c1161497895f INFO: start
I, [2025-01-01T18:23:03.990714 #100] INFO -- : Performed Cache::PreheatingJob (Job ID: 9b9e34af-0b2a-4d2d-bc00-8509156980a0) from Sidekiq(default) in 284.7ms
2025-01-01T18:23:03.992Z pid=100 tid=i04 class=Cache::PreheatingJob jid=90fcf4b8b564565821d18b1a elapsed=0.337 INFO: done
2025-01-01T18:23:03.994Z pid=100 tid=i04 class=Cache::PreheatingJob jid=081e823f895c342b0871679f INFO: start
I, [2025-01-01T18:23:04.064861 #100] INFO -- : Performing Cache::CleaningJob (Job ID: 755192f5-9080-4ece-82b7-aa4b53e7a76e) from Sidekiq(default) enqueued at 2025-01-01T13:49:31.504051114Z
I, [2025-01-01T18:23:04.065270 #100] INFO -- : Cleaning cache...
I, [2025-01-01T18:23:04.067096 #100] INFO -- : Performing Cache::PreheatingJob (Job ID: 6171197f-c806-44aa-af81-a3d97bede220) from Sidekiq(default) enqueued at 2025-01-01T13:49:31.505264936Z
I, [2025-01-01T18:23:04.067945 #100] INFO -- : Performing Cache::CleaningJob (Job ID: 9a47ba1f-e39d-4e72-a9cb-80e43fe6b5c4) from Sidekiq(default) enqueued at 2025-01-01T13:49:32.548361471Z
I, [2025-01-01T18:23:04.068397 #100] INFO -- : Cleaning cache...
D, [2025-01-01T18:23:04.070013 #100] DEBUG -- : �[1m�[36mUser Load (3.1ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:04.070843 #100] DEBUG -- : ↳ app/services/cache/clean.rb:19:in `delete_years_tracked_cache'
D, [2025-01-01T18:23:04.071005 #100] DEBUG -- : �[1m�[36mUser Load (3.1ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:04.071695 #100] DEBUG -- : ↳ app/jobs/cache/preheating_job.rb:7:in `perform'
D, [2025-01-01T18:23:04.072369 #100] DEBUG -- : �[1m�[36mUser Load (3.1ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:04.073048 #100] DEBUG -- : ↳ app/services/cache/clean.rb:19:in `delete_years_tracked_cache'
I, [2025-01-01T18:23:04.070180 #100] INFO -- : Performing Cache::PreheatingJob (Job ID: f45f7f2b-90bd-4ec1-b11e-9ba404d4421b) from Sidekiq(default) enqueued at 2025-01-01T13:49:32.549634783Z
I, [2025-01-01T18:23:04.071433 #100] INFO -- : Cache cleaned
I, [2025-01-01T18:23:04.086727 #100] INFO -- : Performed Cache::CleaningJob (Job ID: 755192f5-9080-4ece-82b7-aa4b53e7a76e) from Sidekiq(default) in 22.11ms
2025-01-01T18:23:04.087Z pid=100 tid=hzs class=Cache::CleaningJob jid=8e07266bc7b0b2b00e111ef4 elapsed=0.115 INFO: done
I, [2025-01-01T18:23:04.073342 #100] INFO -- : Cache cleaned
I, [2025-01-01T18:23:04.087579 #100] INFO -- : Performed Cache::CleaningJob (Job ID: 9a47ba1f-e39d-4e72-a9cb-80e43fe6b5c4) from Sidekiq(default) in 19.65ms
2025-01-01T18:23:04.087Z pid=100 tid=i1s class=Cache::CleaningJob jid=a765fbc699616b381f77a7b4 elapsed=0.11 INFO: done
I, [2025-01-01T18:23:04.071840 #100] INFO -- : Performing Cache::CleaningJob (Job ID: 5197d6ef-9723-4726-b326-afaf65590937) from Sidekiq(default) enqueued at 2025-01-01T18:23:00.165901410Z
I, [2025-01-01T18:23:04.088471 #100] INFO -- : Cleaning cache...
2025-01-01T18:23:04.088Z pid=100 tid=hzs class=Cache::CleaningJob jid=5e19bc99e9b7fc73db921c26 INFO: start
D, [2025-01-01T18:23:04.088099 #100] DEBUG -- : �[1m�[36mUser Load (1.6ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:04.092405 #100] DEBUG -- : ↳ app/jobs/cache/preheating_job.rb:7:in `perform'
2025-01-01T18:23:04.093Z pid=100 tid=i1s class=Cache::PreheatingJob jid=a574999c7ef83b7b22517d0c INFO: start
D, [2025-01-01T18:23:04.093496 #100] DEBUG -- : �[1m�[36mUser Load (4.5ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:04.094225 #100] DEBUG -- : ↳ app/services/cache/clean.rb:19:in `delete_years_tracked_cache'
I, [2025-01-01T18:23:04.094531 #100] INFO -- : Cache cleaned
I, [2025-01-01T18:23:04.094636 #100] INFO -- : Performed Cache::CleaningJob (Job ID: 5197d6ef-9723-4726-b326-afaf65590937) from Sidekiq(default) in 22.81ms
2025-01-01T18:23:04.095Z pid=100 tid=i2k class=Cache::CleaningJob jid=388fe00caa79c1161497895f elapsed=0.11 INFO: done
I, [2025-01-01T18:23:04.095363 #100] INFO -- : Performing Cache::PreheatingJob (Job ID: cb2d060c-55fd-4bbe-b85a-927fb85e1f56) from Sidekiq(default) enqueued at 2025-01-01T18:23:00.167413950Z
2025-01-01T18:23:04.097Z pid=100 tid=i2k class=Cache::CleaningJob jid=b197c80ee55c8a636a1e0520 INFO: start
D, [2025-01-01T18:23:04.097634 #100] DEBUG -- : �[1m�[36mUser Load (1.6ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:04.097865 #100] DEBUG -- : ↳ app/jobs/cache/preheating_job.rb:7:in `perform'
I, [2025-01-01T18:23:04.131927 #100] INFO -- : Performing Cache::CleaningJob (Job ID: 85a9d80d-0a48-4aba-a862-688c8a814816) from Sidekiq(default) enqueued at 2025-01-01T18:23:00.536904794Z
I, [2025-01-01T18:23:04.132903 #100] INFO -- : Cleaning cache...
I, [2025-01-01T18:23:04.132049 #100] INFO -- : Performing Cache::PreheatingJob (Job ID: 979efbba-3ad5-4349-a8c2-947779dc1a28) from Sidekiq(default) enqueued at 2025-01-01T18:23:00.538246805Z
D, [2025-01-01T18:23:04.134954 #100] DEBUG -- : �[1m�[36mUser Load (1.2ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:04.136965 #100] DEBUG -- : ↳ app/services/cache/clean.rb:19:in `delete_years_tracked_cache'
D, [2025-01-01T18:23:04.135894 #100] DEBUG -- : �[1m�[36mUser Load (0.6ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:04.137744 #100] DEBUG -- : ↳ app/jobs/cache/preheating_job.rb:7:in `perform'
I, [2025-01-01T18:23:04.137563 #100] INFO -- : Cache cleaned
I, [2025-01-01T18:23:04.138666 #100] INFO -- : Performed Cache::CleaningJob (Job ID: 85a9d80d-0a48-4aba-a862-688c8a814816) from Sidekiq(default) in 6.38ms
2025-01-01T18:23:04.139Z pid=100 tid=hzs class=Cache::CleaningJob jid=5e19bc99e9b7fc73db921c26 elapsed=0.051 INFO: done
I, [2025-01-01T18:23:04.138937 #100] INFO -- : Performing Cache::CleaningJob (Job ID: c806b9ac-717a-4345-85d2-3fac4ef6c2c4) from Sidekiq(default) enqueued at 2025-01-01T18:23:01.163386852Z
I, [2025-01-01T18:23:04.142573 #100] INFO -- : Cleaning cache...
2025-01-01T18:23:04.144Z pid=100 tid=hzs class=Cache::PreheatingJob jid=b4a2d3d2a0c358710866e927 INFO: start
D, [2025-01-01T18:23:04.145430 #100] DEBUG -- : �[1m�[36mUser Load (1.0ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:04.145616 #100] DEBUG -- : ↳ app/services/cache/clean.rb:19:in `delete_years_tracked_cache'
I, [2025-01-01T18:23:04.146311 #100] INFO -- : Cache cleaned
I, [2025-01-01T18:23:04.146395 #100] INFO -- : Performed Cache::CleaningJob (Job ID: c806b9ac-717a-4345-85d2-3fac4ef6c2c4) from Sidekiq(default) in 7.47ms
2025-01-01T18:23:04.146Z pid=100 tid=i2k class=Cache::CleaningJob jid=b197c80ee55c8a636a1e0520 elapsed=0.049 INFO: done
2025-01-01T18:23:04.147Z pid=100 tid=i2k class=Cache::CleaningJob jid=274ff3bad385201ba7ea8da6 INFO: start
I, [2025-01-01T18:23:04.180076 #100] INFO -- : Performing Cache::PreheatingJob (Job ID: 835e5eaf-33ed-44d3-bfd5-9a90cbeff5aa) from Sidekiq(default) enqueued at 2025-01-01T18:23:01.164578114Z
D, [2025-01-01T18:23:04.181655 #100] DEBUG -- : �[1m�[36mUser Load (0.6ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:04.181913 #100] DEBUG -- : ↳ app/jobs/cache/preheating_job.rb:7:in `perform'
I, [2025-01-01T18:23:04.183082 #100] INFO -- : Performing Cache::CleaningJob (Job ID: b335f387-ca3a-4c6e-a0ed-9358937f64fb) from Sidekiq(default) enqueued at 2025-01-01T18:23:01.528969792Z
I, [2025-01-01T18:23:04.183414 #100] INFO -- : Cleaning cache...
D, [2025-01-01T18:23:04.185826 #100] DEBUG -- : �[1m�[36mUser Load (0.7ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:04.186514 #100] DEBUG -- : ↳ app/services/cache/clean.rb:19:in `delete_years_tracked_cache'
I, [2025-01-01T18:23:04.187072 #100] INFO -- : Cache cleaned
I, [2025-01-01T18:23:04.187194 #100] INFO -- : Performed Cache::CleaningJob (Job ID: b335f387-ca3a-4c6e-a0ed-9358937f64fb) from Sidekiq(default) in 4.12ms
2025-01-01T18:23:04.187Z pid=100 tid=i2k class=Cache::CleaningJob jid=274ff3bad385201ba7ea8da6 elapsed=0.04 INFO: done
2025-01-01T18:23:04.188Z pid=100 tid=i2k class=Cache::PreheatingJob jid=6a87a12ee47247616630039f INFO: start
I, [2025-01-01T18:23:04.211155 #100] INFO -- : Performing Cache::PreheatingJob (Job ID: 81ee480c-b78b-4cdf-af99-d4794bac55a4) from Sidekiq(default) enqueued at 2025-01-01T18:23:01.530043015Z
D, [2025-01-01T18:23:04.212690 #100] DEBUG -- : �[1m�[36mUser Load (0.5ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:04.212973 #100] DEBUG -- : ↳ app/jobs/cache/preheating_job.rb:7:in `perform'
D, [2025-01-01T18:23:04.416140 #100] DEBUG -- : �[1m�[36mPoint Pluck (370.8ms)�[0m �[1m�[34mSELECT "points"."timestamp" FROM "points" WHERE "points"."user_id" = $1�[0m [["user_id", 1]]
D, [2025-01-01T18:23:04.416443 #100] DEBUG -- : ↳ app/models/user.rb:70:in `block in years_tracked'
I, [2025-01-01T18:23:06.315798 #100] INFO -- : Performed Cache::PreheatingJob (Job ID: 2819df0e-96ae-463a-8501-bb897ea9ec10) from Sidekiq(default) in 2601.2ms
2025-01-01T18:23:06.316Z pid=100 tid=i5w class=Cache::PreheatingJob jid=231104bf2aeae1d46d3ee5c8 elapsed=2.663 INFO: done
2025-01-01T18:23:06.316Z pid=100 tid=i5w class=Cache::CleaningJob jid=41f08d901fcabd3b0791b12c INFO: start
D, [2025-01-01T18:23:06.521901 #100] DEBUG -- : �[1m�[36mPoint Pluck (2482.0ms)�[0m �[1m�[34mSELECT "points"."timestamp" FROM "points" WHERE "points"."user_id" = $1�[0m [["user_id", 1]]
D, [2025-01-01T18:23:06.522189 #100] DEBUG -- : ↳ app/models/user.rb:70:in `block in years_tracked'
I, [2025-01-01T18:23:08.532494 #100] INFO -- : Performed Cache::PreheatingJob (Job ID: 3b045324-4ddf-4e98-957a-abb43c72af8b) from Sidekiq(default) in 4815.34ms
2025-01-01T18:23:08.532Z pid=100 tid=hzg class=Cache::PreheatingJob jid=a8cdc30823eb96eff783ec48 elapsed=4.878 INFO: done
2025-01-01T18:23:08.536Z pid=100 tid=hzg class=Cache::PreheatingJob jid=2af557c1c8dce045ac5868a5 INFO: start
D, [2025-01-01T18:23:08.718842 #100] DEBUG -- : �[1m�[36mPoint Pluck (4673.2ms)�[0m �[1m�[34mSELECT "points"."timestamp" FROM "points" WHERE "points"."user_id" = $1�[0m [["user_id", 1]]
D, [2025-01-01T18:23:08.720116 #100] DEBUG -- : ↳ app/models/user.rb:70:in `block in years_tracked'
D, [2025-01-01T18:23:09.575892 #100] DEBUG -- : �[1m�[36mPoint Pluck (5534.8ms)�[0m �[1m�[34mSELECT "points"."timestamp" FROM "points" WHERE "points"."user_id" = $1�[0m [["user_id", 1]]
D, [2025-01-01T18:23:09.668370 #100] DEBUG -- : ↳ app/models/user.rb:70:in `block in years_tracked'
I, [2025-01-01T18:23:12.454006 #100] INFO -- : Performed Cache::PreheatingJob (Job ID: f9b122d3-222d-4f82-975e-801f4a6c38d6) from Sidekiq(default) in 8737.43ms
2025-01-01T18:23:12.554Z pid=100 tid=i14 class=Cache::PreheatingJob jid=d30c654d3e9ce65d95a7f55c elapsed=8.898 INFO: done
I, [2025-01-01T18:23:12.748517 #100] INFO -- : Performed Cache::PreheatingJob (Job ID: 26561f5e-ec9d-415a-b4c2-502773958116) from Sidekiq(default) in 9042.46ms
2025-01-01T18:23:12.749Z pid=100 tid=hw4 class=Cache::PreheatingJob jid=fb8e7a655171211e46b50adb elapsed=9.094 INFO: done
2025-01-01T18:23:12.749Z pid=100 tid=i14 class=Cache::CleaningJob jid=21738c2f6ab2062196226033 INFO: start
2025-01-01T18:23:12.749Z pid=100 tid=hw4 class=Cache::PreheatingJob jid=fc374fd8be1c6589111161bb INFO: start
D, [2025-01-01T18:23:13.029260 #100] DEBUG -- : �[1m�[36mPoint Pluck (8937.2ms)�[0m �[1m�[34mSELECT "points"."timestamp" FROM "points" WHERE "points"."user_id" = $1�[0m [["user_id", 1]]
D, [2025-01-01T18:23:13.029560 #100] DEBUG -- : ↳ app/models/user.rb:70:in `block in years_tracked'
I, [2025-01-01T18:23:15.129509 #100] INFO -- : Performed Cache::PreheatingJob (Job ID: 6171197f-c806-44aa-af81-a3d97bede220) from Sidekiq(default) in 11062.42ms
2025-01-01T18:23:15.230Z pid=100 tid=i0g class=Cache::PreheatingJob jid=78ceda154a8bb69087876573 elapsed=11.255 INFO: done
D, [2025-01-01T18:23:15.287762 #100] DEBUG -- : �[1m�[36mPoint Pluck (11190.3ms)�[0m �[1m�[34mSELECT "points"."timestamp" FROM "points" WHERE "points"."user_id" = $1�[0m [["user_id", 1]]
D, [2025-01-01T18:23:15.288289 #100] DEBUG -- : ↳ app/models/user.rb:70:in `block in years_tracked'
2025-01-01T18:23:15.793Z pid=100 tid=i0g class=Cache::CleaningJob jid=a70ea1b039a492e2be212be2 INFO: start
I, [2025-01-01T18:23:17.167062 #100] INFO -- : Performed Cache::PreheatingJob (Job ID: f45f7f2b-90bd-4ec1-b11e-9ba404d4421b) from Sidekiq(default) in 13096.89ms
2025-01-01T18:23:17.167Z pid=100 tid=i4g class=Cache::PreheatingJob jid=76944e47ff9c48db5a1cbb35 elapsed=13.184 INFO: done
2025-01-01T18:23:17.177Z pid=100 tid=i4g class=Cache::PreheatingJob jid=0f1cfae0f400e4e71ca0b3b7 INFO: start
D, [2025-01-01T18:23:17.400387 #100] DEBUG -- : �[1m�[36mPoint Pluck (13300.9ms)�[0m �[1m�[34mSELECT "points"."timestamp" FROM "points" WHERE "points"."user_id" = $1�[0m [["user_id", 1]]
D, [2025-01-01T18:23:17.400758 #100] DEBUG -- : ↳ app/models/user.rb:70:in `block in years_tracked'
I, [2025-01-01T18:23:19.330408 #100] INFO -- : Performed Cache::PreheatingJob (Job ID: cb2d060c-55fd-4bbe-b85a-927fb85e1f56) from Sidekiq(default) in 15235.06ms
2025-01-01T18:23:19.331Z pid=100 tid=i04 class=Cache::PreheatingJob jid=081e823f895c342b0871679f elapsed=15.337 INFO: done
2025-01-01T18:23:19.332Z pid=100 tid=i04 class=Cache::CleaningJob jid=3cb315f7fd9fe2d6d9b0812a INFO: start
I, [2025-01-01T18:23:19.351027 #100] INFO -- : Performing Cache::CleaningJob (Job ID: a6da4281-1b62-4120-a969-3bcd42699ddb) from Sidekiq(default) enqueued at 2025-01-01T18:23:01.944659690Z
I, [2025-01-01T18:23:19.352909 #100] INFO -- : Cleaning cache...
D, [2025-01-01T18:23:19.355176 #100] DEBUG -- : �[1m�[36mUser Load (0.7ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:19.355429 #100] DEBUG -- : ↳ app/services/cache/clean.rb:19:in `delete_years_tracked_cache'
I, [2025-01-01T18:23:19.355852 #100] INFO -- : Cache cleaned
I, [2025-01-01T18:23:19.356453 #100] INFO -- : Performed Cache::CleaningJob (Job ID: a6da4281-1b62-4120-a969-3bcd42699ddb) from Sidekiq(default) in 5.67ms
2025-01-01T18:23:19.356Z pid=100 tid=i5w class=Cache::CleaningJob jid=41f08d901fcabd3b0791b12c elapsed=13.04 INFO: done
I, [2025-01-01T18:23:19.357809 #100] INFO -- : Performing Cache::PreheatingJob (Job ID: 30abc484-7831-4a93-b643-5462fe79905c) from Sidekiq(default) enqueued at 2025-01-01T18:23:01.945889842Z
2025-01-01T18:23:19.357Z pid=100 tid=i5w class=Cache::PreheatingJob jid=18d4c1f7fa2ffdbbf55129a1 INFO: start
D, [2025-01-01T18:23:19.360059 #100] DEBUG -- : �[1m�[36mUser Load (1.0ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:19.360275 #100] DEBUG -- : ↳ app/jobs/cache/preheating_job.rb:7:in `perform'
I, [2025-01-01T18:23:19.376296 #100] INFO -- : Performing Cache::CleaningJob (Job ID: 964850bd-7433-41fe-83f7-620ec8b887a3) from Sidekiq(default) enqueued at 2025-01-01T18:23:02.354554998Z
I, [2025-01-01T18:23:19.376652 #100] INFO -- : Cleaning cache...
I, [2025-01-01T18:23:19.377453 #100] INFO -- : Performing Cache::PreheatingJob (Job ID: 02b0bb7a-3bcc-40fe-8db1-fd3104a82fd4) from Sidekiq(default) enqueued at 2025-01-01T18:23:02.355656901Z
D, [2025-01-01T18:23:19.378331 #100] DEBUG -- : �[1m�[36mUser Load (1.0ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:19.378608 #100] DEBUG -- : ↳ app/services/cache/clean.rb:19:in `delete_years_tracked_cache'
I, [2025-01-01T18:23:19.378964 #100] INFO -- : Cache cleaned
I, [2025-01-01T18:23:19.379311 #100] INFO -- : Performed Cache::CleaningJob (Job ID: 964850bd-7433-41fe-83f7-620ec8b887a3) from Sidekiq(default) in 3.05ms
2025-01-01T18:23:19.379Z pid=100 tid=i14 class=Cache::CleaningJob jid=21738c2f6ab2062196226033 elapsed=6.63 INFO: done
D, [2025-01-01T18:23:19.379237 #100] DEBUG -- : �[1m�[36mUser Load (1.2ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:19.380215 #100] DEBUG -- : ↳ app/jobs/cache/preheating_job.rb:7:in `perform'
D, [2025-01-01T18:23:19.622073 #100] DEBUG -- : �[1m�[36mPoint Pluck (15475.9ms)�[0m �[1m�[34mSELECT "points"."timestamp" FROM "points" WHERE "points"."user_id" = $1�[0m [["user_id", 1]]
D, [2025-01-01T18:23:19.622363 #100] DEBUG -- : ↳ app/models/user.rb:70:in `block in years_tracked'
I, [2025-01-01T18:23:21.434874 #100] INFO -- : Performed Cache::PreheatingJob (Job ID: 979efbba-3ad5-4349-a8c2-947779dc1a28) from Sidekiq(default) in 17302.83ms
2025-01-01T18:23:21.435Z pid=100 tid=i1s class=Cache::PreheatingJob jid=a574999c7ef83b7b22517d0c elapsed=17.342 INFO: done
I, [2025-01-01T18:23:21.436284 #100] INFO -- : Performing Cache::CleaningJob (Job ID: 2a4ddf7a-2d93-4403-8400-cd33be73271d) from Sidekiq(default) enqueued at 2025-01-01T18:23:02.963825940Z
I, [2025-01-01T18:23:21.436587 #100] INFO -- : Cleaning cache...
I, [2025-01-01T18:23:21.437952 #100] INFO -- : Performing Cache::PreheatingJob (Job ID: c1a927ab-c531-4666-8e87-388d253fab33) from Sidekiq(default) enqueued at 2025-01-01T18:23:02.964994173Z
D, [2025-01-01T18:23:21.441279 #100] DEBUG -- : �[1m�[36mUser Load (4.0ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:21.441673 #100] DEBUG -- : ↳ app/services/cache/clean.rb:19:in `delete_years_tracked_cache'
I, [2025-01-01T18:23:21.443035 #100] INFO -- : Cache cleaned
I, [2025-01-01T18:23:21.443116 #100] INFO -- : Performed Cache::CleaningJob (Job ID: 2a4ddf7a-2d93-4403-8400-cd33be73271d) from Sidekiq(default) in 6.91ms
2025-01-01T18:23:21.443Z pid=100 tid=i0g class=Cache::CleaningJob jid=a70ea1b039a492e2be212be2 elapsed=5.65 INFO: done
D, [2025-01-01T18:23:21.443621 #100] DEBUG -- : �[1m�[36mUser Load (2.5ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:21.443852 #100] DEBUG -- : ↳ app/jobs/cache/preheating_job.rb:7:in `perform'
I, [2025-01-01T18:23:21.450540 #100] INFO -- : Performing Cache::CleaningJob (Job ID: 3b6619cf-dffc-490d-95ea-04b58e8b4369) from Sidekiq(default) enqueued at 2025-01-01T18:23:03.475410037Z
I, [2025-01-01T18:23:21.450853 #100] INFO -- : Cleaning cache...
D, [2025-01-01T18:23:21.451576 #100] DEBUG -- : �[1m�[36mUser Load (0.3ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:21.451742 #100] DEBUG -- : ↳ app/services/cache/clean.rb:19:in `delete_years_tracked_cache'
I, [2025-01-01T18:23:21.452572 #100] INFO -- : Cache cleaned
I, [2025-01-01T18:23:21.452627 #100] INFO -- : Performed Cache::CleaningJob (Job ID: 3b6619cf-dffc-490d-95ea-04b58e8b4369) from Sidekiq(default) in 2.58ms
2025-01-01T18:23:21.452Z pid=100 tid=i04 class=Cache::CleaningJob jid=3cb315f7fd9fe2d6d9b0812a elapsed=2.121 INFO: done
I, [2025-01-01T18:23:21.457072 #100] INFO -- : Performing Cache::PreheatingJob (Job ID: 350aac5a-bec5-40e9-b40f-48f8eed418b2) from Sidekiq(default) enqueued at 2025-01-01T18:23:03.476033103Z
D, [2025-01-01T18:23:21.457781 #100] DEBUG -- : �[1m�[36mUser Load (0.2ms)�[0m �[1m�[34mSELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1�[0m [["LIMIT", 1000]]
D, [2025-01-01T18:23:21.457953 #100] DEBUG -- : ↳ app/jobs/cache/preheating_job.rb:7:in `perform'
D, [2025-01-01T18:23:21.802210 #100] DEBUG -- : �[1m�[36mPoint Pluck (17616.5ms)�[0m �[1m�[34mSELECT "points"."timestamp" FROM "points" WHERE "points"."user_id" = $1�[0m [["user_id", 1]]
D, [2025-01-01T18:23:21.802478 #100] DEBUG -- : ↳ app/models/user.rb:70:in `block in years_tracked'
I, [2025-01-01T18:23:23.629811 #100] INFO -- : Performed Cache::PreheatingJob (Job ID: 835e5eaf-33ed-44d3-bfd5-9a90cbeff5aa) from Sidekiq(default) in 19449.77ms
2025-01-01T18:23:23.630Z pid=100 tid=hzs class=Cache::PreheatingJob jid=b4a2d3d2a0c358710866e927 elapsed=19.485 INFO: done
D, [2025-01-01T18:23:23.949804 #100] DEBUG -- : �[1m�[36mPoint Pluck (19734.9ms)�[0m �[1m�[34mSELECT "points"."timestamp" FROM "points" WHERE "points"."user_id" = $1�[0m [["user_id", 1]]
D, [2025-01-01T18:23:23.950041 #100] DEBUG -- : ↳ app/models/user.rb:70:in `block in years_tracked'
I, [2025-01-01T18:23:25.743520 #100] INFO -- : Performed Cache::PreheatingJob (Job ID: 81ee480c-b78b-4cdf-af99-d4794bac55a4) from Sidekiq(default) in 21532.4ms
2025-01-01T18:23:25.744Z pid=100 tid=i2k class=Cache::PreheatingJob jid=6a87a12ee47247616630039f elapsed=21.556 INFO: done
D, [2025-01-01T18:23:26.146361 #100] DEBUG -- : �[1m�[36mPoint Pluck (6773.1ms)�[0m �[1m�[34mSELECT "points"."timestamp" FROM "points" WHERE "points"."user_id" = $1�[0m [["user_id", 1]]
D, [2025-01-01T18:23:26.146640 #100] DEBUG -- : ↳ app/models/user.rb:70:in `block in years_tracked'
I, [2025-01-01T18:23:27.998015 #100] INFO -- : Performed Cache::PreheatingJob (Job ID: 30abc484-7831-4a93-b643-5462fe79905c) from Sidekiq(default) in 8640.22ms
2025-01-01T18:23:27.998Z pid=100 tid=hzg class=Cache::PreheatingJob jid=2af557c1c8dce045ac5868a5 elapsed=19.462 INFO: done
D, [2025-01-01T18:23:28.314743 #100] DEBUG -- : �[1m�[36mPoint Pluck (6865.9ms)�[0m �[1m�[34mSELECT "points"."timestamp" FROM "points" WHERE "points"."user_id" = $1�[0m [["user_id", 1]]
D, [2025-01-01T18:23:28.315031 #100] DEBUG -- : ↳ app/models/user.rb:70:in `block in years_tracked'
I, [2025-01-01T18:23:30.139202 #100] INFO -- : Performed Cache::PreheatingJob (Job ID: c1a927ab-c531-4666-8e87-388d253fab33) from Sidekiq(default) in 8701.43ms
2025-01-01T18:23:30.139Z pid=100 tid=i4g class=Cache::PreheatingJob jid=0f1cfae0f400e4e71ca0b3b7 elapsed=12.962 INFO: done
D, [2025-01-01T18:23:30.466470 #100] DEBUG -- : �[1m�[36mPoint Pluck (11083.1ms)�[0m �[1m�[34mSELECT "points"."timestamp" FROM "points" WHERE "points"."user_id" = $1�[0m [["user_id", 1]]
D, [2025-01-01T18:23:30.466675 #100] DEBUG -- : ↳ app/models/user.rb:70:in `block in years_tracked'
I, [2025-01-01T18:23:32.416000 #100] INFO -- : Performed Cache::PreheatingJob (Job ID: 02b0bb7a-3bcc-40fe-8db1-fd3104a82fd4) from Sidekiq(default) in 13038.55ms
2025-01-01T18:23:32.416Z pid=100 tid=hw4 class=Cache::PreheatingJob jid=fc374fd8be1c6589111161bb elapsed=19.666 INFO: done
D, [2025-01-01T18:23:32.603637 #100] DEBUG -- : �[1m�[36mPoint Pluck (11144.8ms)�[0m �[1m�[34mSELECT "points"."timestamp" FROM "points" WHERE "points"."user_id" = $1�[0m [["user_id", 1]]
D, [2025-01-01T18:23:32.603821 #100] DEBUG -- : ↳ app/models/user.rb:70:in `block in years_tracked'
I, [2025-01-01T18:23:34.438820 #100] INFO -- : Performed Cache::PreheatingJob (Job ID: 350aac5a-bec5-40e9-b40f-48f8eed418b2) from Sidekiq(default) in 12981.75ms
2025-01-01T18:23:34.440Z pid=100 tid=i5w class=Cache::PreheatingJob jid=18d4c1f7fa2ffdbbf55129a1 elapsed=15.082 INFO: done
Hi,
maybe i have/had a similar issue when uploading larger gpx files (one was 10 mb, the other one was 16 mb). In my case i uploaded several gpx files (with smaller ones) with these to large ones. The issue was, that they appeared under imports, but they werent processed ("imports/imported points" stayed zero). This for the large, but also the small, files i uploaded.
Sidekiq had a large queue but wasnt changing really. What I remember is that all entries (import/stats,.. was != zero and latency was >3000 (for all if i remember right). Import size was 5 to 6.
I removed the two large files - nothing happened. Then i restarted the docker container and it started to process the data: Sidekiq/queue went quite fast down to zero. In the statistics page the "total distance" increased
Thx Malte
Please update to the most recent version and try again, background jobs processing library was replaced
