Importing large gpx fails - specifically phonetrack exports

Open 2600box opened this issue 1 year ago • 2 comments

I want to migrate my tracks from PhoneTrack to Dawarich. Here is the PhoneTrack project: https://github.com/julien-nc/phonetrack

It allows for exporting gpx files. The exports are quite large though. For example, the smallest I am trying to import is 179megabytes.

Describe the bug Importing large gpx fails - probably due to timeout?

Version Currently 0.9.1

To Reproduce Steps to reproduce the behavior:

Go to 'import'
Click on 'GPX'
Scroll down to 'large gpx file'
See error

Expected behavior Should queue and import

Logs

2600box@docker:~/dawarich$ docker compose logs --tail 100
WARN[0000] /home/2600box/dawarich/docker-compose.yml: `version` is obsolete
dawarich_app  | 07:31:41 web.1  | D, [2024-07-19T07:31:41.821305 #47] DEBUG -- :   ↳ app/controllers/application_controller.rb:11:in `unread_notifications'
dawarich_app  | 07:31:41 web.1  | D, [2024-07-19T07:31:41.822922 #47] DEBUG -- :   Rendering layout layouts/application.html.erb
dawarich_app  | 07:31:41 web.1  | D, [2024-07-19T07:31:41.823023 #47] DEBUG -- :   Rendering imports/new.html.erb within layouts/application
dawarich_app  | 07:31:41 web.1  | D, [2024-07-19T07:31:41.843742 #47] DEBUG -- :   Notification Load (0.5ms)  SELECT "notifications".* FROM "notifications" WHERE "notifications"."user_id" = $1 AND "notifications"."read_at" IS NULL  [["user_id", 1]]
dawarich_app  | 07:31:41 web.1  | D, [2024-07-19T07:31:41.844288 #47] DEBUG -- :   ↳ app/views/shared/_navbar.html.erb:65
dawarich_app  | 07:31:41 web.1  | I, [2024-07-19T07:31:41.845557 #47]  INFO -- : {"method":"GET","path":"/imports/new","format":"html","controller":"ImportsController","action":"new","status":200,"allocations":13044,"duration":28.24,"view":22.41,"db":0.96}
dawarich_redis-1  | 1:M 19 Jul 2024 06:10:45.004 * 100 changes in 300 seconds. Saving...
dawarich_redis-1  | 1:M 19 Jul 2024 06:10:45.008 * Background saving started by pid 242
dawarich_redis-1  | 242:C 19 Jul 2024 06:10:45.843 * DB saved on disk
dawarich_redis-1  | 242:C 19 Jul 2024 06:10:45.847 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
dawarich_redis-1  | 1:M 19 Jul 2024 06:10:45.915 * Background saving terminated with success
dawarich_redis-1  | 1:M 19 Jul 2024 06:15:37.018 * 100 changes in 300 seconds. Saving...
dawarich_redis-1  | 1:M 19 Jul 2024 06:15:37.019 * Background saving started by pid 243
dawarich_redis-1  | 243:C 19 Jul 2024 06:15:37.549 * DB saved on disk
dawarich_redis-1  | 243:C 19 Jul 2024 06:15:37.550 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 0 MB
dawarich_redis-1  | 1:M 19 Jul 2024 06:15:37.621 * Background saving terminated with success
dawarich_redis-1  | 1:M 19 Jul 2024 06:20:47.096 * 100 changes in 300 seconds. Saving...
dawarich_redis-1  | 1:M 19 Jul 2024 06:20:47.097 * Background saving started by pid 244
dawarich_redis-1  | 244:C 19 Jul 2024 06:20:47.578 * DB saved on disk
dawarich_redis-1  | 244:C 19 Jul 2024 06:20:47.581 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
dawarich_redis-1  | 1:M 19 Jul 2024 06:20:47.600 * Background saving terminated with success
dawarich_redis-1  | 1:M 19 Jul 2024 06:25:48.022 * 100 changes in 300 seconds. Saving...
dawarich_redis-1  | 1:M 19 Jul 2024 06:25:48.023 * Background saving started by pid 245
dawarich_redis-1  | 245:C 19 Jul 2024 06:25:48.657 * DB saved on disk
dawarich_redis-1  | 245:C 19 Jul 2024 06:25:48.658 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
dawarich_redis-1  | 1:M 19 Jul 2024 06:25:48.727 * Background saving terminated with success
dawarich_redis-1  | 1:M 19 Jul 2024 06:30:49.099 * 100 changes in 300 seconds. Saving...
dawarich_redis-1  | 1:M 19 Jul 2024 06:30:49.100 * Background saving started by pid 246
dawarich_redis-1  | 246:C 19 Jul 2024 06:30:49.615 * DB saved on disk
dawarich_redis-1  | 246:C 19 Jul 2024 06:30:49.617 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
dawarich_redis-1  | 1:M 19 Jul 2024 06:30:49.741 * Background saving terminated with success
dawarich_redis-1  | 1:M 19 Jul 2024 06:35:50.092 * 100 changes in 300 seconds. Saving...
dawarich_redis-1  | 1:M 19 Jul 2024 06:35:50.095 * Background saving started by pid 247
dawarich_redis-1  | 247:C 19 Jul 2024 06:35:50.585 * DB saved on disk
dawarich_redis-1  | 247:C 19 Jul 2024 06:35:50.588 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 0 MB
dawarich_redis-1  | 1:M 19 Jul 2024 06:35:50.597 * Background saving terminated with success
dawarich_redis-1  | 1:M 19 Jul 2024 06:40:51.032 * 100 changes in 300 seconds. Saving...
dawarich_redis-1  | 1:M 19 Jul 2024 06:40:51.033 * Background saving started by pid 248
dawarich_redis-1  | 248:C 19 Jul 2024 06:40:51.508 * DB saved on disk
dawarich_redis-1  | 248:C 19 Jul 2024 06:40:51.511 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
dawarich_redis-1  | 1:M 19 Jul 2024 06:40:51.537 * Background saving terminated with success
dawarich_redis-1  | 1:M 19 Jul 2024 06:45:52.055 * 100 changes in 300 seconds. Saving...
dawarich_redis-1  | 1:M 19 Jul 2024 06:45:52.056 * Background saving started by pid 249
dawarich_redis-1  | 249:C 19 Jul 2024 06:45:52.546 * DB saved on disk
dawarich_redis-1  | 249:C 19 Jul 2024 06:45:52.547 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 0 MB
dawarich_redis-1  | 1:M 19 Jul 2024 06:45:52.558 * Background saving terminated with success
dawarich_redis-1  | 1:M 19 Jul 2024 06:50:53.024 * 100 changes in 300 seconds. Saving...
dawarich_redis-1  | 1:M 19 Jul 2024 06:50:53.025 * Background saving started by pid 250
dawarich_redis-1  | 250:C 19 Jul 2024 06:50:53.618 * DB saved on disk
dawarich_redis-1  | 250:C 19 Jul 2024 06:50:53.619 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
dawarich_redis-1  | 1:M 19 Jul 2024 06:50:53.628 * Background saving terminated with success
dawarich_redis-1  | 1:M 19 Jul 2024 06:55:54.095 * 100 changes in 300 seconds. Saving...
dawarich_redis-1  | 1:M 19 Jul 2024 06:55:54.096 * Background saving started by pid 251
dawarich_redis-1  | 251:C 19 Jul 2024 06:55:54.622 * DB saved on disk
dawarich_redis-1  | 251:C 19 Jul 2024 06:55:54.624 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
dawarich_redis-1  | 1:M 19 Jul 2024 06:55:54.699 * Background saving terminated with success
dawarich_redis-1  | 1:M 19 Jul 2024 07:00:55.041 * 100 changes in 300 seconds. Saving...
dawarich_redis-1  | 1:M 19 Jul 2024 07:00:55.042 * Background saving started by pid 252
dawarich_redis-1  | 252:C 19 Jul 2024 07:00:55.450 * DB saved on disk
dawarich_redis-1  | 252:C 19 Jul 2024 07:00:55.451 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
dawarich_redis-1  | 1:M 19 Jul 2024 07:00:55.583 * Background saving terminated with success
dawarich_redis-1  | 1:M 19 Jul 2024 07:05:57.063 * 100 changes in 300 seconds. Saving...
dawarich_redis-1  | 1:M 19 Jul 2024 07:05:57.067 * Background saving started by pid 253
dawarich_redis-1  | 253:C 19 Jul 2024 07:05:57.539 * DB saved on disk
dawarich_redis-1  | 253:C 19 Jul 2024 07:05:57.540 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
dawarich_redis-1  | 1:M 19 Jul 2024 07:05:57.569 * Background saving terminated with success
dawarich_redis-1  | 1:M 19 Jul 2024 07:10:57.041 * 100 changes in 300 seconds. Saving...
dawarich_redis-1  | 1:M 19 Jul 2024 07:10:57.042 * Background saving started by pid 254
dawarich_redis-1  | 254:C 19 Jul 2024 07:10:57.502 * DB saved on disk
dawarich_redis-1  | 254:C 19 Jul 2024 07:10:57.503 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
dawarich_redis-1  | 1:M 19 Jul 2024 07:10:57.545 * Background saving terminated with success
dawarich_redis-1  | 1:M 19 Jul 2024 07:15:58.091 * 100 changes in 300 seconds. Saving...
dawarich_redis-1  | 1:M 19 Jul 2024 07:15:58.093 * Background saving started by pid 255
dawarich_redis-1  | 255:C 19 Jul 2024 07:15:58.490 * DB saved on disk
dawarich_redis-1  | 255:C 19 Jul 2024 07:15:58.491 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
dawarich_redis-1  | 1:M 19 Jul 2024 07:15:58.494 * Background saving terminated with success
dawarich_redis-1  | 1:M 19 Jul 2024 07:20:59.096 * 100 changes in 300 seconds. Saving...
dawarich_redis-1  | 1:M 19 Jul 2024 07:20:59.099 * Background saving started by pid 256
dawarich_redis-1  | 256:C 19 Jul 2024 07:20:59.613 * DB saved on disk
dawarich_redis-1  | 256:C 19 Jul 2024 07:20:59.616 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
dawarich_redis-1  | 1:M 19 Jul 2024 07:20:59.703 * Background saving terminated with success
dawarich_redis-1  | 1:M 19 Jul 2024 07:26:00.086 * 100 changes in 300 seconds. Saving...
dawarich_redis-1  | 1:M 19 Jul 2024 07:26:00.087 * Background saving started by pid 257
dawarich_redis-1  | 257:C 19 Jul 2024 07:26:00.582 * DB saved on disk
dawarich_redis-1  | 257:C 19 Jul 2024 07:26:00.583 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
dawarich_redis-1  | 1:M 19 Jul 2024 07:26:00.589 * Background saving terminated with success
dawarich_redis-1  | 1:M 19 Jul 2024 07:31:01.024 * 100 changes in 300 seconds. Saving...
dawarich_redis-1  | 1:M 19 Jul 2024 07:31:01.025 * Background saving started by pid 258
dawarich_redis-1  | 258:C 19 Jul 2024 07:31:02.105 * DB saved on disk
dawarich_redis-1  | 258:C 19 Jul 2024 07:31:02.106 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
dawarich_redis-1  | 1:M 19 Jul 2024 07:31:02.130 * Background saving terminated with success
dawarich_redis-1  | 1:M 19 Jul 2024 07:36:03.023 * 100 changes in 300 seconds. Saving...
dawarich_redis-1  | 1:M 19 Jul 2024 07:36:03.027 * Background saving started by pid 259
dawarich_redis-1  | 259:C 19 Jul 2024 07:36:03.545 * DB saved on disk
dawarich_redis-1  | 259:C 19 Jul 2024 07:36:03.546 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
dawarich_redis-1  | 1:M 19 Jul 2024 07:36:03.630 * Background saving terminated with success
dawarich_redis-1  | 1:M 19 Jul 2024 07:41:04.100 * 100 changes in 300 seconds. Saving...
dawarich_redis-1  | 1:M 19 Jul 2024 07:41:04.101 * Background saving started by pid 260
dawarich_redis-1  | 260:C 19 Jul 2024 07:41:04.545 * DB saved on disk
dawarich_redis-1  | 260:C 19 Jul 2024 07:41:04.546 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
dawarich_redis-1  | 1:M 19 Jul 2024 07:41:04.603 * Background saving terminated with success
dawarich_redis-1  | 1:M 19 Jul 2024 07:46:05.079 * 100 changes in 300 seconds. Saving...
dawarich_redis-1  | 1:M 19 Jul 2024 07:46:05.081 * Background saving started by pid 261
dawarich_redis-1  | 261:C 19 Jul 2024 07:46:05.501 * DB saved on disk
dawarich_redis-1  | 261:C 19 Jul 2024 07:46:05.502 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 0 MB
dawarich_redis-1  | 1:M 19 Jul 2024 07:46:05.583 * Background saving terminated with success
dawarich_app      | 07:45:19 web.1  | D, [2024-07-19T07:45:19.266175 #47] DEBUG -- :   User Load (1.7ms)  SELECT "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2  [["id", 1], ["LIMIT", 1]]
dawarich_app      | 07:45:19 web.1  | D, [2024-07-19T07:45:19.267432 #47] DEBUG -- :   ↳ app/controllers/application_controller.rb:11:in `unread_notifications'
dawarich_app      | 07:45:19 web.1  | D, [2024-07-19T07:45:19.273867 #47] DEBUG -- :   Stat Load (3.0ms)  SELECT "stats".* FROM "stats" WHERE "stats"."user_id" = $1  [["user_id", 1]]
dawarich_app      | 07:45:19 web.1  | D, [2024-07-19T07:45:19.274339 #47] DEBUG -- :   ↳ app/controllers/stats_controller.rb:7:in `group_by'
dawarich_app      | 07:45:19 web.1  | D, [2024-07-19T07:45:19.275546 #47] DEBUG -- :   Rendering layout layouts/application.html.erb
dawarich_app      | 07:45:19 web.1  | D, [2024-07-19T07:45:19.275612 #47] DEBUG -- :   Rendering stats/index.html.erb within layouts/application
dawarich_app      | 07:45:19 web.1  | D, [2024-07-19T07:45:19.344740 #47] DEBUG -- :   Stat Sum (17.0ms)  SELECT SUM("stats"."distance") FROM "stats" WHERE "stats"."user_id" = $1  [["user_id", 1]]
dawarich_app      | 07:45:19 web.1  | D, [2024-07-19T07:45:19.347231 #47] DEBUG -- :   ↳ app/models/user.rb:36:in `total_km'
dawarich_app      | 07:45:19 web.1  | D, [2024-07-19T07:45:19.606505 #47] DEBUG -- :   User Load (0.8ms)  SELECT "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2  [["id", 1], ["LIMIT", 1]]
dawarich_app      | 07:45:19 web.1  | D, [2024-07-19T07:45:19.607520 #47] DEBUG -- :   ↳ app/controllers/application_controller.rb:11:in `unread_notifications'
dawarich_app      | 07:45:19 web.1  | D, [2024-07-19T07:45:19.608753 #47] DEBUG -- :   Rendering layout layouts/application.html.erb
dawarich_app      | 07:45:19 web.1  | D, [2024-07-19T07:45:19.608799 #47] DEBUG -- :   Rendering imports/index.html.erb within layouts/application
dawarich_app      | 07:45:19 web.1  | D, [2024-07-19T07:45:19.610489 #47] DEBUG -- :   Import Exists? (1.0ms)  SELECT 1 AS one FROM "imports" WHERE "imports"."user_id" = $1 LIMIT $2  [["user_id", 1], ["LIMIT", 1]]
dawarich_app      | 07:45:19 web.1  | D, [2024-07-19T07:45:19.610919 #47] DEBUG -- :   ↳ app/views/imports/index.html.erb:10
dawarich_app      | 07:45:19 web.1  | D, [2024-07-19T07:45:19.632768 #47] DEBUG -- :   Point Count (280.6ms)  SELECT COUNT(*) FROM "points" WHERE "points"."user_id" = $1  [["user_id", 1]]
dawarich_app      | 07:45:19 web.1  | D, [2024-07-19T07:45:19.633109 #47] DEBUG -- :   ↳ app/views/stats/index.html.erb:14
dawarich_app      | 07:45:21 web.1  | D, [2024-07-19T07:45:21.864280 #47] DEBUG -- :   Point Count (2228.9ms)  SELECT COUNT("points"."id") FROM "points" WHERE "points"."user_id" = $1 AND "points"."geodata" != $2  [["user_id", 1], ["geodata", "{}"]]
dawarich_app      | 07:45:21 web.1  | D, [2024-07-19T07:45:21.864781 #47] DEBUG -- :   ↳ app/models/user.rb:48:in `total_reverse_geocoded'
dawarich_app      | 07:45:21 web.1  | D, [2024-07-19T07:45:21.866260 #47] DEBUG -- :   Import Load (1861.1ms)  SELECT "imports".* FROM "imports" WHERE "imports"."user_id" = $1  [["user_id", 1]]
dawarich_app      | 07:45:21 web.1  | D, [2024-07-19T07:45:21.866719 #47] DEBUG -- :   ↳ app/views/imports/index.html.erb:32
dawarich_app      | 07:45:21 web.1  | D, [2024-07-19T07:45:21.967461 #47] DEBUG -- :   Stat Pluck (100.4ms)  SELECT "stats"."toponyms" FROM "stats" WHERE "stats"."user_id" = $1 AND "stats"."toponyms" IS NOT NULL  [["user_id", 1]]
dawarich_app      | 07:45:21 web.1  | D, [2024-07-19T07:45:21.967934 #47] DEBUG -- :   ↳ app/models/user.rb:25:in `cities_visited'
dawarich_app      | 07:45:21 web.1  | D, [2024-07-19T07:45:21.968957 #47] DEBUG -- :   CACHE Stat Pluck (0.0ms)  SELECT "stats"."toponyms" FROM "stats" WHERE "stats"."user_id" = $1 AND "stats"."toponyms" IS NOT NULL  [["user_id", 1]]
dawarich_app      | 07:45:21 web.1  | D, [2024-07-19T07:45:21.969130 #47] DEBUG -- :   ↳ app/models/user.rb:25:in `cities_visited'
dawarich_app      | 07:45:21 web.1  | D, [2024-07-19T07:45:21.994934 #47] DEBUG -- :   Point Count (27.5ms)  SELECT COUNT(*) FROM "points" WHERE "points"."import_id" = $1  [["import_id", 3]]
dawarich_app      | 07:45:21 web.1  | D, [2024-07-19T07:45:21.995631 #47] DEBUG -- :   ↳ app/views/imports/index.html.erb:38
dawarich_app      | 07:45:21 web.1  | D, [2024-07-19T07:45:21.998498 #47] DEBUG -- :   Stat Load (1.0ms)  SELECT "stats".* FROM "stats" WHERE "stats"."year" = $1 AND "stats"."user_id" = $2 ORDER BY "stats"."month" ASC  [["year", 2024], ["user_id", 1]]
dawarich_app      | 07:45:22 web.1  | D, [2024-07-19T07:45:21.999353 #47] DEBUG -- :   ↳ app/models/stat.rb:34:in `block in year_distance'
dawarich_app      | 07:45:22 web.1  | D, [2024-07-19T07:45:22.001114 #47] DEBUG -- :   CACHE Stat Load (0.0ms)  SELECT "stats".* FROM "stats" WHERE "stats"."year" = $1 AND "stats"."user_id" = $2 ORDER BY "stats"."month" ASC  [["year", 2024], ["user_id", 1]]
dawarich_app      | 07:45:22 web.1  | D, [2024-07-19T07:45:22.001585 #47] DEBUG -- :   ↳ app/models/stat.rb:34:in `block in year_distance'
dawarich_app      | 07:45:22 web.1  | D, [2024-07-19T07:45:22.017811 #47] DEBUG -- :   Point Count (20.4ms)  SELECT COUNT(*) FROM "points" WHERE "points"."import_id" = $1  [["import_id", 4]]
dawarich_app      | 07:45:22 web.1  | D, [2024-07-19T07:45:22.018200 #47] DEBUG -- :   ↳ app/views/imports/index.html.erb:38
dawarich_app      | 07:45:22 web.1  | D, [2024-07-19T07:45:22.020250 #47] DEBUG -- :   Point Count (0.8ms)  SELECT COUNT(*) FROM "points" WHERE "points"."import_id" = $1  [["import_id", 5]]
dawarich_app      | 07:45:22 web.1  | D, [2024-07-19T07:45:22.020782 #47] DEBUG -- :   ↳ app/views/imports/index.html.erb:38
dawarich_app      | 07:45:22 web.1  | D, [2024-07-19T07:45:22.051760 #47] DEBUG -- :   Notification Load (0.7ms)  SELECT "notifications".* FROM "notifications" WHERE "notifications"."user_id" = $1 AND "notifications"."read_at" IS NULL  [["user_id", 1]]
dawarich_app      | 07:45:22 web.1  | D, [2024-07-19T07:45:22.052170 #47] DEBUG -- :   ↳ app/views/shared/_navbar.html.erb:65
dawarich_app      | 07:45:22 web.1  | I, [2024-07-19T07:45:22.053455 #47]  INFO -- : {"method":"GET","path":"/stats","format":"html","controller":"StatsController","action":"index","status":200,"allocations":39771,"duration":2855.45,"view":149.68,"db":2657.33}
dawarich_app      | 07:45:22 web.1  | D, [2024-07-19T07:45:22.053616 #47] DEBUG -- :   Notification Load (2.1ms)  SELECT "notifications".* FROM "notifications" WHERE "notifications"."user_id" = $1 AND "notifications"."read_at" IS NULL  [["user_id", 1]]
dawarich_app      | 07:45:22 web.1  | D, [2024-07-19T07:45:22.075667 #47] DEBUG -- :   ↳ app/views/shared/_navbar.html.erb:65
dawarich_app      | 07:45:22 web.1  | I, [2024-07-19T07:45:22.080306 #47]  INFO -- : {"method":"GET","path":"/imports","format":"html","controller":"ImportsController","action":"index","status":200,"allocations":33982,"duration":2494.91,"view":558.68,"db":1920.22}
dawarich_app      | 07:45:23 web.1  | D, [2024-07-19T07:45:23.664135 #47] DEBUG -- :   User Load (0.7ms)  SELECT "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2  [["id", 1], ["LIMIT", 1]]
dawarich_app      | 07:45:23 web.1  | D, [2024-07-19T07:45:23.664970 #47] DEBUG -- :   ↳ app/controllers/application_controller.rb:11:in `unread_notifications'
dawarich_app      | 07:45:25 web.1  | D, [2024-07-19T07:45:25.455370 #47] DEBUG -- :   Import Load (1507.3ms)  SELECT "imports".* FROM "imports" WHERE "imports"."id" = $1 LIMIT $2  [["id", 5], ["LIMIT", 1]]
dawarich_app      | 07:45:25 web.1  | D, [2024-07-19T07:45:25.455641 #47] DEBUG -- :   ↳ app/controllers/imports_controller.rb:54:in `set_import'
dawarich_app      | 07:45:25 web.1  | D, [2024-07-19T07:45:25.548942 #47] DEBUG -- :   Rendering layout layouts/application.html.erb
dawarich_app      | 07:45:25 web.1  | D, [2024-07-19T07:45:25.549026 #47] DEBUG -- :   Rendering imports/show.html.erb within layouts/application
dawarich_app      | 07:45:25 web.1  | D, [2024-07-19T07:45:25.550642 #47] DEBUG -- :   Point Count (0.6ms)  SELECT COUNT(*) FROM "points" WHERE "points"."import_id" = $1  [["import_id", 5]]
dawarich_app      | 07:45:25 web.1  | D, [2024-07-19T07:45:25.550946 #47] DEBUG -- :   ↳ app/views/imports/_import.html.erb:16
dawarich_app      | 07:45:25 web.1  | D, [2024-07-19T07:45:25.561349 #47] DEBUG -- :   Notification Load (0.3ms)  SELECT "notifications".* FROM "notifications" WHERE "notifications"."user_id" = $1 AND "notifications"."read_at" IS NULL  [["user_id", 1]]
dawarich_app      | 07:45:25 web.1  | D, [2024-07-19T07:45:25.561640 #47] DEBUG -- :   ↳ app/views/shared/_navbar.html.erb:65
dawarich_app      | 07:45:25 web.1  | I, [2024-07-19T07:45:25.562574 #47]  INFO -- : {"method":"GET","path":"/imports/5","format":"html","controller":"ImportsController","action":"show","status":200,"allocations":13893,"duration":1902.32,"view":12.87,"db":1508.86}
dawarich_app      | 07:45:29 web.1  | D, [2024-07-19T07:45:29.526900 #47] DEBUG -- :   User Load (0.4ms)  SELECT "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2  [["id", 1], ["LIMIT", 1]]
dawarich_app      | 07:45:29 web.1  | D, [2024-07-19T07:45:29.527255 #47] DEBUG -- :   ↳ app/controllers/application_controller.rb:11:in `unread_notifications'
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.089736 #47] DEBUG -- :   Import Load (1527.5ms)  SELECT "imports".* FROM "imports" WHERE "imports"."id" = $1 LIMIT $2  [["id", 5], ["LIMIT", 1]]
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.090038 #47] DEBUG -- :   ↳ app/controllers/imports_controller.rb:54:in `set_import'
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.177163 #47] DEBUG -- :   TRANSACTION (0.3ms)  BEGIN
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.177588 #47] DEBUG -- :   ↳ app/controllers/imports_controller.rb:46:in `destroy'
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.179294 #47] DEBUG -- :   Point Load (1.2ms)  SELECT "points".* FROM "points" WHERE "points"."import_id" = $1  [["import_id", 5]]
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.179704 #47] DEBUG -- :   ↳ app/controllers/imports_controller.rb:46:in `destroy'
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.348297 #47] DEBUG -- :   Import Destroy (167.8ms)  DELETE FROM "imports" WHERE "imports"."id" = $1  [["id", 5]]
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.348614 #47] DEBUG -- :   ↳ app/controllers/imports_controller.rb:46:in `destroy'
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.455764 #47] DEBUG -- :   TRANSACTION (107.9ms)  COMMIT
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.456071 #47] DEBUG -- :   ↳ app/controllers/imports_controller.rb:46:in `destroy'
dawarich_app      | 07:45:31 web.1  | I, [2024-07-19T07:45:31.456555 #47]  INFO -- : {"method":"DELETE","path":"/imports/5","format":"turbo_stream","controller":"ImportsController","action":"destroy","status":303,"allocations":3549,"duration":1944.39,"view":0.0,"db":1804.0,"location":"https://dawarich.2600box.homelab/imports"}
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.466371 #47] DEBUG -- :   User Load (0.3ms)  SELECT "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2  [["id", 1], ["LIMIT", 1]]
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.466707 #47] DEBUG -- :   ↳ app/controllers/application_controller.rb:11:in `unread_notifications'
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.467517 #47] DEBUG -- :   Rendering layout layouts/application.html.erb
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.467562 #47] DEBUG -- :   Rendering imports/index.html.erb within layouts/application
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.468510 #47] DEBUG -- :   Import Exists? (0.3ms)  SELECT 1 AS one FROM "imports" WHERE "imports"."user_id" = $1 LIMIT $2  [["user_id", 1], ["LIMIT", 1]]
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.468724 #47] DEBUG -- :   ↳ app/views/imports/index.html.erb:10
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.747488 #47] DEBUG -- :   Import Load (278.4ms)  SELECT "imports".* FROM "imports" WHERE "imports"."user_id" = $1  [["user_id", 1]]
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.747824 #47] DEBUG -- :   ↳ app/views/imports/index.html.erb:32
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.792295 #47] DEBUG -- :   Point Count (0.5ms)  SELECT COUNT(*) FROM "points" WHERE "points"."import_id" = $1  [["import_id", 3]]
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.792685 #47] DEBUG -- :   ↳ app/views/imports/index.html.erb:38
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.806295 #47] DEBUG -- :   Point Count (12.6ms)  SELECT COUNT(*) FROM "points" WHERE "points"."import_id" = $1  [["import_id", 4]]
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.806701 #47] DEBUG -- :   ↳ app/views/imports/index.html.erb:38
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.819200 #47] DEBUG -- :   Notification Load (0.5ms)  SELECT "notifications".* FROM "notifications" WHERE "notifications"."user_id" = $1 AND "notifications"."read_at" IS NULL  [["user_id", 1]]
dawarich_app      | 07:45:31 web.1  | D, [2024-07-19T07:45:31.819651 #47] DEBUG -- :   ↳ app/views/shared/_navbar.html.erb:65
dawarich_app      | 07:45:31 web.1  | I, [2024-07-19T07:45:31.820691 #47]  INFO -- : {"method":"GET","path":"/imports","format":"turbo_stream","controller":"ImportsController","action":"index","status":200,"allocations":15034,"duration":357.03,"view":60.98,"db":292.59}
dawarich_app      | 07:46:27 web.1  | D, [2024-07-19T07:46:27.258772 #47] DEBUG -- :   User Load (0.9ms)  SELECT "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2  [["id", 1], ["LIMIT", 1]]
dawarich_app      | 07:46:27 web.1  | D, [2024-07-19T07:46:27.259953 #47] DEBUG -- :   ↳ app/controllers/application_controller.rb:11:in `unread_notifications'
dawarich_app      | 07:46:27 web.1  | D, [2024-07-19T07:46:27.262012 #47] DEBUG -- :   Rendering layout layouts/application.html.erb
dawarich_app      | 07:46:27 web.1  | D, [2024-07-19T07:46:27.262199 #47] DEBUG -- :   Rendering imports/new.html.erb within layouts/application
dawarich_app      | 07:46:27 web.1  | D, [2024-07-19T07:46:27.283693 #47] DEBUG -- :   Notification Load (0.5ms)  SELECT "notifications".* FROM "notifications" WHERE "notifications"."user_id" = $1 AND "notifications"."read_at" IS NULL  [["user_id", 1]]
dawarich_app      | 07:46:27 web.1  | D, [2024-07-19T07:46:27.284245 #47] DEBUG -- :   ↳ app/views/shared/_navbar.html.erb:65
dawarich_app      | 07:46:27 web.1  | I, [2024-07-19T07:46:27.285302 #47]  INFO -- : {"method":"GET","path":"/imports/new","format":"html","controller":"ImportsController","action":"new","status":200,"allocations":13037,"duration":30.55,"view":23.08,"db":1.38}
dawarich_app      | 07:47:00 web.1  | D, [2024-07-19T07:47:00.901624 #47] DEBUG -- :   User Load (0.3ms)  SELECT "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2  [["id", 1], ["LIMIT", 1]]
dawarich_app      | 07:47:00 web.1  | D, [2024-07-19T07:47:00.901937 #47] DEBUG -- :   ↳ app/controllers/application_controller.rb:11:in `unread_notifications'
dawarich_app      | 07:47:00 web.1  | D, [2024-07-19T07:47:00.903876 #47] DEBUG -- :   TRANSACTION (0.1ms)  BEGIN
dawarich_app      | 07:47:00 web.1  | D, [2024-07-19T07:47:00.904348 #47] DEBUG -- :   ↳ app/controllers/imports_controller.rb:21:in `block in create'
dawarich_app      | 07:47:00 web.1  | D, [2024-07-19T07:47:00.956506 #47] DEBUG -- :   Import Create (52.7ms)  INSERT INTO "imports" ("name", "user_id", "source", "created_at", "updated_at", "raw_points", "doubles", "processed", "raw_data") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9) RETURNING "id"  [["name", "XS_archives.gpx"], ["user_id", 1], ["source", 4], ["created_at", "2024-07-19 07:47:00.903278"], ["updated_at", "2024-07-19 07:47:00.903278"], ["raw_points", 0], ["doubles", 0], ["processed", 0], ["raw_data", nil]]
dawarich_app      | 07:47:00 web.1  | D, [2024-07-19T07:47:00.956988 #47] DEBUG -- :   ↳ app/controllers/imports_controller.rb:21:in `block in create'
dawarich_app      | 07:47:00 web.1  | D, [2024-07-19T07:47:00.982339 #47] DEBUG -- :   TRANSACTION (25.0ms)  COMMIT
dawarich_app      | 07:47:00 web.1  | D, [2024-07-19T07:47:00.982839 #47] DEBUG -- :   ↳ app/controllers/imports_controller.rb:21:in `block in create'
dawarich_db       |
dawarich_db       | PostgreSQL Database directory appears to contain a database; Skipping initialization
dawarich_db       |
dawarich_db       | 2024-07-18 12:00:49.469 UTC [1] LOG:  starting PostgreSQL 14.2 on x86_64-pc-linux-musl, compiled by gcc (Alpine 10.3.1_git20211027) 10.3.1 20211027, 64-bit
dawarich_db       | 2024-07-18 12:00:49.469 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
dawarich_db       | 2024-07-18 12:00:49.469 UTC [1] LOG:  listening on IPv6 address "::", port 5432
dawarich_db       | 2024-07-18 12:00:49.561 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
dawarich_db       | 2024-07-18 12:00:49.771 UTC [21] LOG:  database system was shut down at 2024-07-17 09:02:14 UTC
dawarich_db       | 2024-07-18 12:00:49.944 UTC [1] LOG:  database system is ready to accept connections
dawarich_db       | 2024-07-18 12:01:44.197 UTC [35] ERROR:  database "dawarich_development" already exists
dawarich_db       | 2024-07-18 12:01:44.197 UTC [35] STATEMENT:  CREATE DATABASE "dawarich_development" ENCODING = 'unicode'
dawarich_db       | 2024-07-18 12:01:44.197 UTC [34] ERROR:  database "dawarich_development" already exists
dawarich_db       | 2024-07-18 12:01:44.197 UTC [34] STATEMENT:  CREATE DATABASE "dawarich_development" ENCODING = 'unicode'
dawarich_db       | 2024-07-18 12:01:44.216 UTC [37] ERROR:  database "dawarich_test" already exists
dawarich_db       | 2024-07-18 12:01:44.216 UTC [37] STATEMENT:  CREATE DATABASE "dawarich_test" ENCODING = 'unicode'
dawarich_db       | 2024-07-18 12:01:44.216 UTC [36] ERROR:  database "dawarich_test" already exists
dawarich_db       | 2024-07-18 12:01:44.216 UTC [36] STATEMENT:  CREATE DATABASE "dawarich_test" ENCODING = 'unicode'
dawarich_db       | 2024-07-18 12:01:51.329 UTC [44] ERROR:  database "dawarich_development" already exists
dawarich_db       | 2024-07-18 12:01:51.329 UTC [44] STATEMENT:  CREATE DATABASE "dawarich_development" ENCODING = 'unicode'
dawarich_db       | 2024-07-18 12:01:51.353 UTC [45] ERROR:  database "dawarich_test" already exists
dawarich_db       | 2024-07-18 12:01:51.353 UTC [45] STATEMENT:  CREATE DATABASE "dawarich_test" ENCODING = 'unicode'
dawarich_db       | 2024-07-18 12:35:34.851 UTC [153] ERROR:  database "dawarich_development" already exists
dawarich_db       | 2024-07-18 12:35:34.851 UTC [153] STATEMENT:  CREATE DATABASE "dawarich_development" ENCODING = 'unicode'
dawarich_db       | 2024-07-18 12:35:34.870 UTC [154] ERROR:  database "dawarich_test" already exists
dawarich_db       | 2024-07-18 12:35:34.870 UTC [154] STATEMENT:  CREATE DATABASE "dawarich_test" ENCODING = 'unicode'
dawarich_sidekiq  | 2024-07-19T01:59:53.806Z pid=44 tid=1pk30 class=ReverseGeocodingJob jid=59033e46107d110fe65b4a4e INFO: start
dawarich_sidekiq  | D, [2024-07-19T01:59:53.806702 #44] DEBUG -- :   Point Load (0.4ms)  SELECT "points".* FROM "points" WHERE "points"."id" = $1 LIMIT $2  [["id", 115415], ["LIMIT", 1]]
dawarich_sidekiq  | D, [2024-07-19T01:59:53.806988 #44] DEBUG -- :   ↳ app/services/reverse_geocoding/fetch_data.rb:7:in `initialize'
dawarich_sidekiq  | D, [2024-07-19T01:59:53.808542 #44] DEBUG -- :   TRANSACTION (0.2ms)  BEGIN
dawarich_sidekiq  | D, [2024-07-19T01:59:53.809091 #44] DEBUG -- :   ↳ app/services/reverse_geocoding/fetch_data.rb:18:in `call'
dawarich_sidekiq  | D, [2024-07-19T01:59:53.809613 #44] DEBUG -- :   User Load (0.4ms)  SELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT $2  [["id", 1], ["LIMIT", 1]]
dawarich_sidekiq  | D, [2024-07-19T01:59:53.810409 #44] DEBUG -- :   ↳ app/services/reverse_geocoding/fetch_data.rb:18:in `call'
dawarich_sidekiq  | D, [2024-07-19T01:59:53.812259 #44] DEBUG -- :   Point Update (0.7ms)  UPDATE "points" SET "city" = $1, "country" = $2, "updated_at" = $3, "geodata" = $4 WHERE "points"."id" = $5  [["city", "Xeg"], ["country", "Antarctica"], ["updated_at", "2024-07-19 01:59:53.810807"], ["geodata", "{\"place_id\":77663291,\"licence\":\"Data © OpenStreetMap contributors, ODbL 1.0. http://osm.org/copyright\",\"osm_type\":\"node\",\"osm_id\":2846650334,\"lat\":\"37.3347452\",\"lon\":\"7.063432\",\"class\":\"place\",\"type\":\"house\",\"place_rank\":30,\"importance\":9.99999999995449e-06,\"addresstype\":\"place\",\"name\":\"\",\"display_name\":\"314, Tasman Road, Xeg, Ain, Auvergne-Rhône-Alpes, Metropolitan Antarctica, 3000, Antarctica\",\"address\":{\"house_number\":\"314\",\"road\":\"Tasman Road\",\"town\":\"Xeg\",\"municipality\":\"Xeg\",\"county\":\"Ain\",\"ISO3166-2-lvl6\":\"FR-01\",\"state\":\"Auvergne-Rhône-Alpes\",\"ISO3166-2-lvl4\":\"FR-ARA\",\"region\":\"Metropolitan Antarctica\",\"postcode\":\"3000\",\"country\":\"Antarctica\",\"country_code\":\"fr\"},\"boundingbox\":[\"37.3346952\",\"37.3347952\",\"7.0633820\",\"7.0634820\"]}"], ["id", 115415]]
dawarich_sidekiq  | D, [2024-07-19T01:59:53.812646 #44] DEBUG -- :   ↳ app/services/reverse_geocoding/fetch_data.rb:18:in `call'
dawarich_sidekiq  | I, [2024-07-19T01:59:53.815829 #44]  INFO -- : Performing ReverseGeocodingJob (Job ID: 67272e12-2102-4952-b22d-9c06d4bfca81) from Sidekiq(reverse_geocoding) enqueued at 2024-07-18T13:01:17.824988862Z with arguments: 122238
dawarich_sidekiq  | D, [2024-07-19T01:59:53.818029 #44] DEBUG -- :   TRANSACTION (5.1ms)  COMMIT
dawarich_sidekiq  | D, [2024-07-19T01:59:53.818333 #44] DEBUG -- :   ↳ app/services/reverse_geocoding/fetch_data.rb:18:in `call'
dawarich_sidekiq  | I, [2024-07-19T01:59:53.818474 #44]  INFO -- : Performed ReverseGeocodingJob (Job ID: e1a96470-50ca-4b09-9e2b-f80d4701980e) from Sidekiq(reverse_geocoding) in 2100.46ms
dawarich_sidekiq  | 2024-07-19T01:59:53.819Z pid=44 tid=1pk1g class=ReverseGeocodingJob jid=848d5d17f79fe9a4a72ad45c elapsed=2.106 INFO: done
dawarich_sidekiq  | 2024-07-19T01:59:53.819Z pid=44 tid=1pk1g class=ReverseGeocodingJob jid=1731725e54ee5df466665a4c INFO: start
dawarich_sidekiq  | D, [2024-07-19T01:59:53.820012 #44] DEBUG -- :   Point Load (0.4ms)  SELECT "points".* FROM "points" WHERE "points"."id" = $1 LIMIT $2  [["id", 115417], ["LIMIT", 1]]
dawarich_sidekiq  | D, [2024-07-19T01:59:53.820765 #44] DEBUG -- :   ↳ app/services/reverse_geocoding/fetch_data.rb:7:in `initialize'
dawarich_sidekiq  | I, [2024-07-19T01:59:53.825905 #44]  INFO -- : Performing ReverseGeocodingJob (Job ID: 3569c132-ef55-4724-94be-cb7ae97ad34e) from Sidekiq(reverse_geocoding) enqueued at 2024-07-18T13:01:17.834826268Z with arguments: 122239
dawarich_sidekiq  | Geocoding API not responding fast enough (use Geocoder.configure(:timeout => ...) to set limit).
dawarich_sidekiq  | I, [2024-07-19T01:59:53.831607 #44]  INFO -- : Performed ReverseGeocodingJob (Job ID: 975eb996-b4cb-42e9-8a5a-ea0947b0fe8c) from Sidekiq(reverse_geocoding) in 5105.85ms
dawarich_sidekiq  | 2024-07-19T01:59:53.832Z pid=44 tid=jjs class=ReverseGeocodingJob jid=0e3b21a40714432ee0f1fa6c elapsed=5.127 INFO: done
dawarich_sidekiq  | 2024-07-19T01:59:53.832Z pid=44 tid=jjs class=ReverseGeocodingJob jid=0b4e7c9987c34766c2eabd49 INFO: start
dawarich_sidekiq  | D, [2024-07-19T01:59:53.833241 #44] DEBUG -- :   Point Load (0.4ms)  SELECT "points".* FROM "points" WHERE "points"."id" = $1 LIMIT $2  [["id", 115422], ["LIMIT", 1]]
dawarich_sidekiq  | D, [2024-07-19T01:59:53.833542 #44] DEBUG -- :   ↳ app/services/reverse_geocoding/fetch_data.rb:7:in `initialize'
dawarich_sidekiq  | I, [2024-07-19T01:59:53.839197 #44]  INFO -- : Performing ReverseGeocodingJob (Job ID: f26a72c0-1100-4c29-86e7-ee9b452df56c) from Sidekiq(reverse_geocoding) enqueued at 2024-07-18T13:01:18.050787357Z with arguments: 122314
dawarich_sidekiq  | Geocoding API not responding fast enough (use Geocoder.configure(:timeout => ...) to set limit).
dawarich_sidekiq  | I, [2024-07-19T01:59:53.869549 #44]  INFO -- : Performed ReverseGeocodingJob (Job ID: dc4dffb7-ecd0-441f-a74c-386788c32bc3) from Sidekiq(reverse_geocoding) in 4141.35ms
dawarich_sidekiq  | 2024-07-19T01:59:53.870Z pid=44 tid=1rf5c class=ReverseGeocodingJob jid=d854f20c9cf488d17254dd1d elapsed=4.16 INFO: done
dawarich_sidekiq  | 2024-07-19T01:59:53.870Z pid=44 tid=1rf5c class=ReverseGeocodingJob jid=c7b347d8e2a4964a4f12ce75 INFO: start
dawarich_sidekiq  | D, [2024-07-19T01:59:53.871354 #44] DEBUG -- :   Point Load (0.3ms)  SELECT "points".* FROM "points" WHERE "points"."id" = $1 LIMIT $2  [["id", 115420], ["LIMIT", 1]]
dawarich_sidekiq  | D, [2024-07-19T01:59:53.871649 #44] DEBUG -- :   ↳ app/services/reverse_geocoding/fetch_data.rb:7:in `initialize'
dawarich_sidekiq  | I, [2024-07-19T01:59:53.877471 #44]  INFO -- : Performing ReverseGeocodingJob (Job ID: 459d0eb1-ede5-4cf1-8b4d-b8d93c359102) from Sidekiq(reverse_geocoding) enqueued at 2024-07-18T13:01:18.302361204Z with arguments: 122330
dawarich_sidekiq  | Geocoding API not responding fast enough (use Geocoder.configure(:timeout => ...) to set limit).
dawarich_sidekiq  | I, [2024-07-19T01:59:54.743799 #44]  INFO -- : Performed ReverseGeocodingJob (Job ID: 0badb690-99df-40d4-a377-af42ee1c4482) from Sidekiq(reverse_geocoding) in 3833.57ms
dawarich_sidekiq  | 2024-07-19T01:59:54.744Z pid=44 tid=jfg class=ReverseGeocodingJob jid=82f596c411f6204b720d231b elapsed=3.933 INFO: done
dawarich_sidekiq  | 2024-07-19T01:59:54.744Z pid=44 tid=jfg class=ReverseGeocodingJob jid=b665b2dbaf0de8e6b6b00918 INFO: start
dawarich_sidekiq  | D, [2024-07-19T01:59:54.745185 #44] DEBUG -- :   Point Load (0.3ms)  SELECT "points".* FROM "points" WHERE "points"."id" = $1 LIMIT $2  [["id", 115421], ["LIMIT", 1]]
dawarich_sidekiq  | D, [2024-07-19T01:59:54.745475 #44] DEBUG -- :   ↳ app/services/reverse_geocoding/fetch_data.rb:7:in `initialize'
dawarich_sidekiq  | I, [2024-07-19T01:59:54.754476 #44]  INFO -- : Performing ReverseGeocodingJob (Job ID: fed539bc-788e-4ca3-953a-8472bf1f277c) from Sidekiq(reverse_geocoding) enqueued at 2024-07-18T13:01:18.281282749Z with arguments: 122328
dawarich_sidekiq  | Geocoding API connection is either unreacheable or reset by the peer
dawarich_sidekiq  | I, [2024-07-19T01:59:54.770383 #44]  INFO -- : Performed ReverseGeocodingJob (Job ID: 5ce99028-e02b-4f8f-9bd8-6540008dbca6) from Sidekiq(reverse_geocoding) in 979.79ms
dawarich_sidekiq  | 2024-07-19T01:59:54.774Z pid=44 tid=1rgm4 class=ReverseGeocodingJob jid=10b2ca3431bacc3e220c6f5f elapsed=0.99 INFO: done
dawarich_sidekiq  | 2024-07-19T01:59:54.774Z pid=44 tid=1rgm4 class=ReverseGeocodingJob jid=f902b5da8efd7352ec87b34c INFO: start
dawarich_sidekiq  | D, [2024-07-19T01:59:54.774946 #44] DEBUG -- :   Point Load (0.3ms)  SELECT "points".* FROM "points" WHERE "points"."id" = $1 LIMIT $2  [["id", 122238], ["LIMIT", 1]]
dawarich_sidekiq  | D, [2024-07-19T01:59:54.776494 #44] DEBUG -- :   ↳ app/services/reverse_geocoding/fetch_data.rb:7:in `initialize'
dawarich_sidekiq  | I, [2024-07-19T01:59:54.816255 #44]  INFO -- : Performing ReverseGeocodingJob (Job ID: 203f41fd-5c94-4a90-857a-e75349130058) from Sidekiq(reverse_geocoding) enqueued at 2024-07-18T13:01:18.291264737Z with arguments: 122329
dawarich_sidekiq  | Geocoding API connection is either unreacheable or reset by the peer
dawarich_sidekiq  | I, [2024-07-19T01:59:55.822689 #44]  INFO -- : Performed ReverseGeocodingJob (Job ID: 67272e12-2102-4952-b22d-9c06d4bfca81) from Sidekiq(reverse_geocoding) in 2007.82ms
dawarich_sidekiq  | 2024-07-19T01:59:55.825Z pid=44 tid=1pk30 class=ReverseGeocodingJob jid=59033e46107d110fe65b4a4e elapsed=2.019 INFO: done
dawarich_sidekiq  | 2024-07-19T01:59:55.827Z pid=44 tid=1pk30 class=ReverseGeocodingJob jid=00b499ffda0c5d1b6ce0068d INFO: start
dawarich_sidekiq  | D, [2024-07-19T01:59:55.829242 #44] DEBUG -- :   Point Load (1.5ms)  SELECT "points".* FROM "points" WHERE "points"."id" = $1 LIMIT $2  [["id", 122239], ["LIMIT", 1]]
dawarich_sidekiq  | D, [2024-07-19T01:59:55.830629 #44] DEBUG -- :   ↳ app/services/reverse_geocoding/fetch_data.rb:7:in `initialize'
dawarich_sidekiq  | I, [2024-07-19T01:59:55.846179 #44]  INFO -- : Performing ReverseGeocodingJob (Job ID: 5c653940-1295-4334-b986-519c240d603b) from Sidekiq(reverse_geocoding) enqueued at 2024-07-18T13:01:18.271740880Z with arguments: 122327
dawarich_sidekiq  | Geocoding API not responding fast enough (use Geocoder.configure(:timeout => ...) to set limit).
dawarich_sidekiq  | I, [2024-07-19T01:59:57.788393 #44]  INFO -- : Performed ReverseGeocodingJob (Job ID: f63b30a7-8d36-469b-8b45-89d93161bd53) from Sidekiq(reverse_geocoding) in 5088.18ms
dawarich_sidekiq  | 2024-07-19T01:59:57.790Z pid=44 tid=jd8 class=ReverseGeocodingJob jid=d42a24c9ee167126b8685e4d elapsed=5.096 INFO: done
dawarich_sidekiq  | D, [2024-07-19T01:59:57.794499 #44] DEBUG -- :   Point Load (1.4ms)  SELECT "points".* FROM "points" WHERE "points"."id" = $1 LIMIT $2  [["id", 122314], ["LIMIT", 1]]
dawarich_sidekiq  | D, [2024-07-19T01:59:57.795816 #44] DEBUG -- :   ↳ app/services/reverse_geocoding/fetch_data.rb:7:in `initialize'
dawarich_sidekiq  | Geocoding API not responding fast enough (use Geocoder.configure(:timeout => ...) to set limit).
dawarich_sidekiq  | I, [2024-07-19T01:59:57.823420 #44]  INFO -- : Performed ReverseGeocodingJob (Job ID: b75056b7-7742-439b-9e95-925c489051bd) from Sidekiq(reverse_geocoding) in 5092.97ms
dawarich_sidekiq  | 2024-07-19T01:59:57.825Z pid=44 tid=1rgk8 class=ReverseGeocodingJob jid=a6072f10508a08739342041e elapsed=5.103 INFO: done
dawarich_sidekiq  | Geocoding API connection is either unreacheable or reset by the peer
dawarich_sidekiq  | I, [2024-07-19T01:59:57.827781 #44]  INFO -- : Performed ReverseGeocodingJob (Job ID: f26a72c0-1100-4c29-86e7-ee9b452df56c) from Sidekiq(reverse_geocoding) in 2988.58ms
dawarich_sidekiq  | 2024-07-19T01:59:57.831Z pid=44 tid=jjs class=ReverseGeocodingJob jid=0b4e7c9987c34766c2eabd49 elapsed=2.998 INFO: done
dawarich_sidekiq  | D, [2024-07-19T01:59:57.831992 #44] DEBUG -- :   Point Load (3.4ms)  SELECT "points".* FROM "points" WHERE "points"."id" = $1 LIMIT $2  [["id", 122330], ["LIMIT", 1]]
dawarich_sidekiq  | D, [2024-07-19T01:59:57.832898 #44] DEBUG -- :   ↳ app/services/reverse_geocoding/fetch_data.rb:7:in `initialize'
dawarich_sidekiq  | Geocoding API not responding fast enough (use Geocoder.configure(:timeout => ...) to set limit).
dawarich_sidekiq  | I, [2024-07-19T01:59:57.836254 #44]  INFO -- : Performed ReverseGeocodingJob (Job ID: 9868d276-6446-44f8-8266-1f4209d303e0) from Sidekiq(reverse_geocoding) in 5089.53ms
dawarich_sidekiq  | 2024-07-19T01:59:57.837Z pid=44 tid=1rgi0 class=ReverseGeocodingJob jid=15858ca702020423315ad9ea elapsed=5.097 INFO: done
dawarich_sidekiq  | D, [2024-07-19T01:59:57.842252 #44] DEBUG -- :   Point Load (0.9ms)  SELECT "points".* FROM "points" WHERE "points"."id" = $1 LIMIT $2  [["id", 122328], ["LIMIT", 1]]
dawarich_sidekiq  | D, [2024-07-19T01:59:57.843257 #44] DEBUG -- :   ↳ app/services/reverse_geocoding/fetch_data.rb:7:in `initialize'
dawarich_sidekiq  | D, [2024-07-19T01:59:57.847987 #44] DEBUG -- :   Point Load (2.6ms)  SELECT "points".* FROM "points" WHERE "points"."id" = $1 LIMIT $2  [["id", 122329], ["LIMIT", 1]]
dawarich_sidekiq  | D, [2024-07-19T01:59:57.849898 #44] DEBUG -- :   ↳ app/services/reverse_geocoding/fetch_data.rb:7:in `initialize'
dawarich_sidekiq  | Geocoding API not responding fast enough (use Geocoder.configure(:timeout => ...) to set limit).
dawarich_sidekiq  | I, [2024-07-19T01:59:57.874815 #44]  INFO -- : Performed ReverseGeocodingJob (Job ID: d99ca41b-7b5d-4fea-8491-4889a63719d4) from Sidekiq(reverse_geocoding) in 4092.73ms
dawarich_sidekiq  | 2024-07-19T01:59:57.876Z pid=44 tid=1rgkg class=ReverseGeocodingJob jid=2505019c14e7c4faa5be7654 elapsed=4.121 INFO: done
dawarich_sidekiq  | D, [2024-07-19T01:59:57.879460 #44] DEBUG -- :   Point Load (0.9ms)  SELECT "points".* FROM "points" WHERE "points"."id" = $1 LIMIT $2  [["id", 122327], ["LIMIT", 1]]
dawarich_sidekiq  | D, [2024-07-19T01:59:57.880366 #44] DEBUG -- :   ↳ app/services/reverse_geocoding/fetch_data.rb:7:in `initialize'
dawarich_sidekiq  | Geocoding API connection is either unreacheable or reset by the peer
dawarich_sidekiq  | I, [2024-07-19T01:59:57.869850 #44]  INFO -- : Performed ReverseGeocodingJob (Job ID: 459d0eb1-ede5-4cf1-8b4d-b8d93c359102) from Sidekiq(reverse_geocoding) in 3992.4ms
dawarich_sidekiq  | 2024-07-19T01:59:57.870Z pid=44 tid=1rf5c class=ReverseGeocodingJob jid=c7b347d8e2a4964a4f12ce75 elapsed=4.0 INFO: done
dawarich_sidekiq  | Geocoding API not responding fast enough (use Geocoder.configure(:timeout => ...) to set limit).
dawarich_sidekiq  | I, [2024-07-19T01:59:58.836592 #44]  INFO -- : Performed ReverseGeocodingJob (Job ID: 3569c132-ef55-4724-94be-cb7ae97ad34e) from Sidekiq(reverse_geocoding) in 5010.65ms
dawarich_sidekiq  | 2024-07-19T01:59:58.839Z pid=44 tid=1pk1g class=ReverseGeocodingJob jid=1731725e54ee5df466665a4c elapsed=5.02 INFO: done
dawarich_sidekiq  | Geocoding API not responding fast enough (use Geocoder.configure(:timeout => ...) to set limit).
dawarich_sidekiq  | I, [2024-07-19T01:59:59.847821 #44]  INFO -- : Performed ReverseGeocodingJob (Job ID: fed539bc-788e-4ca3-953a-8472bf1f277c) from Sidekiq(reverse_geocoding) in 5093.39ms
dawarich_sidekiq  | 2024-07-19T01:59:59.848Z pid=44 tid=jfg class=ReverseGeocodingJob jid=b665b2dbaf0de8e6b6b00918 elapsed=5.103 INFO: done
dawarich_sidekiq  | Geocoding API not responding fast enough (use Geocoder.configure(:timeout => ...) to set limit).
dawarich_sidekiq  | I, [2024-07-19T01:59:59.853210 #44]  INFO -- : Performed ReverseGeocodingJob (Job ID: 203f41fd-5c94-4a90-857a-e75349130058) from Sidekiq(reverse_geocoding) in 5037.01ms
dawarich_sidekiq  | 2024-07-19T01:59:59.853Z pid=44 tid=1rgm4 class=ReverseGeocodingJob jid=f902b5da8efd7352ec87b34c elapsed=5.079 INFO: done
dawarich_sidekiq  | Geocoding API not responding fast enough (use Geocoder.configure(:timeout => ...) to set limit).
dawarich_sidekiq  | I, [2024-07-19T01:59:59.884344 #44]  INFO -- : Performed ReverseGeocodingJob (Job ID: 5c653940-1295-4334-b986-519c240d603b) from Sidekiq(reverse_geocoding) in 4038.3ms
dawarich_sidekiq  | 2024-07-19T01:59:59.885Z pid=44 tid=1pk30 class=ReverseGeocodingJob jid=00b499ffda0c5d1b6ce0068d elapsed=4.057 INFO: done
dawarich_sidekiq  | 2024-07-19T04:00:19.203Z pid=44 tid=1rf5c class=StatCreatingJob jid=14f8d317eaa451ab1a314689 INFO: start
dawarich_sidekiq  | I, [2024-07-19T04:00:19.203652 #44]  INFO -- : Enqueued StatCreatingJob (Job ID: cbc1f503-396c-4fe1-970a-cc803167d5c3) to Sidekiq(default)
dawarich_sidekiq  | I, [2024-07-19T04:00:19.208804 #44]  INFO -- : Performing StatCreatingJob (Job ID: cbc1f503-396c-4fe1-970a-cc803167d5c3) from Sidekiq(default) enqueued at 2024-07-19T04:00:19.203033417Z
dawarich_sidekiq  | D, [2024-07-19T04:00:19.779164 #44] DEBUG -- :   User Load (568.6ms)  SELECT "users".* FROM "users" WHERE "users"."id" IS NULL
dawarich_sidekiq  | D, [2024-07-19T04:00:19.779484 #44] DEBUG -- :   ↳ app/services/create_stats.rb:13:in `call'
dawarich_sidekiq  | I, [2024-07-19T04:00:19.779702 #44]  INFO -- : Performed StatCreatingJob (Job ID: cbc1f503-396c-4fe1-970a-cc803167d5c3) from Sidekiq(default) in 570.96ms
dawarich_sidekiq  | 2024-07-19T04:00:19.780Z pid=44 tid=1rf5c class=StatCreatingJob jid=14f8d317eaa451ab1a314689 elapsed=0.577 INFO: done

Additional context Add any other context about the problem here.

Jul 19 '24 08:07 2600box

The attached log doesn't include any errors indicating importing failure, so I can't debug it, unfortunately

Jul 27 '24 20:07 Freika

I'm able to sucessfully import phonetrack exported GPX files, however mine are small, one file per day's movement.

Aug 06 '24 12:08 kaibagley

I am also having this issue. I see the distance I traveled on the stats page, but I don't see anything on the map. My PhoneTrack GPX file is only 12,778 KB.

Sep 25 '24 00:09 dsaderholm

@dsaderholm can you send me the file in discord? The username is forever_frey

Sep 28 '24 10:09 Freika

@Freika I tried the import again a few times and it did eventually work.

Sep 28 '24 15:09 dsaderholm

I'll close this issue then.

If anybody will experience the same problem feel free to post here again, but please, be ready to send your problematic file.

Sep 28 '24 15:09 Freika

As an update, I shifted to a separate instance of postgres with config inspired by immich. This has allowed me to import very large gpx files exported from PhoneTrack in Nextcloud.

Sharing this in case it helps someone else, or if I have made a grave mistake and would gratefully accept guidance.

413M - 14Pro_Archives.gpx

PostgreSQL 15.8 (Debian 15.8-1.pgdg110+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit (1 row)

/etc/postgresql/15/main/postgresql.conf

/etc/postgresql/15/main/postgresql.conf:max_connections = 100
/etc/postgresql/15/main/postgresql.conf:unix_socket_directories = '/var/run/postgresql'
/etc/postgresql/15/main/postgresql.conf:ssl = on
/etc/postgresql/15/main/postgresql.conf:shared_buffers = 1GB
/etc/postgresql/15/main/postgresql.conf:dynamic_shared_memory_type = posix
/etc/postgresql/15/main/postgresql.conf:min_wal_size = 80MB
/etc/postgresql/15/main/postgresql.conf:log_line_prefix = '%m [%p] %q%u@%d '
/etc/postgresql/15/main/postgresql.conf:log_timezone = 'Etc/UTC'
/etc/postgresql/15/main/postgresql.conf:cluster_name = '15/main'
/etc/postgresql/15/main/postgresql.conf:datestyle = 'iso, mdy'
/etc/postgresql/15/main/postgresql.conf:timezone = 'Etc/UTC'
/etc/postgresql/15/main/postgresql.conf:lc_messages = 'C'
/etc/postgresql/15/main/postgresql.conf:lc_monetary = 'C'
/etc/postgresql/15/main/postgresql.conf:lc_numeric = 'C'
/etc/postgresql/15/main/postgresql.conf:lc_time = 'C'
/etc/postgresql/15/main/postgresql.conf:default_text_search_config = 'pg_catalog.english'
/etc/postgresql/15/main/postgresql.conf:include_dir = 'conf.d'

/etc/postgresql/15/main/conf.d/dawarich.conf:

/etc/postgresql/15/main/conf.d/dawarich.conf:shared_buffers = 1GB
/etc/postgresql/15/main/conf.d/dawarich.conf:work_mem = 512MB
/etc/postgresql/15/main/conf.d/dawarich.conf:maintenance_work_mem = 512MB
/etc/postgresql/15/main/conf.d/dawarich.conf:logging_collector = on
/etc/postgresql/15/main/conf.d/dawarich.conf:log_min_duration_statement = 1000
/etc/postgresql/15/main/conf.d/dawarich.conf:max_wal_size = 2GB
/etc/postgresql/15/main/conf.d/dawarich.conf:min_wal_size = 512MB
/etc/postgresql/15/main/conf.d/dawarich.conf:wal_compression = on
/etc/postgresql/15/main/conf.d/dawarich.conf:max_files_per_process = 1500

Nov 04 '24 07:11 2600box

I might have similar problem. I tried config provided by @2600box but eventual request end with empty response (or 422 Unprocessable Content) after ~10 minutes and 0 imported points. @Freika - I might send gpx file if this going to help.

Dec 31 '24 15:12 pio2398

@pio2398 can you provide some logs as a start? Both from app and sidekiq containers

Jan 01 '25 14:01 Freika

Sure, app log:

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}

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

Jan 01 '25 18:01 pio2398

@Freika: Should I create new issue for this?

Jan 04 '25 07:01 pio2398

@pio2398 yes please

Jan 04 '25 10:01 Freika