Immich•2y ago

Map error after upgrade to 1.55.

Hi all, I've upgraded to 1.55. The map link doesn't work, got an error like the screenshot. On logs on immich_server, got this :

[Nest] 1  - 05/09/2023, 12:47:15 PM   ERROR [ExpressAdapter] Premature close
Error [ERR_STREAM_PREMATURE_CLOSE]: Premature close
    at new NodeError (node:internal/errors:372:5)
    at ServerResponse.onclose (node:internal/streams/end-of-stream:142:30)
    at ServerResponse.emit (node:events:539:35)
    at Socket.onServerResponseClose (node:_http_server:236:23)
    at Socket.emit (node:events:539:35)
    at TCP.<anonymous> (node:net:709:12)
[Nest] 1  - 05/09/2023, 12:47:15 PM   ERROR [ExpressAdapter] Premature close
Error [ERR_STREAM_PREMATURE_CLOSE]: Premature close
    at new NodeError (node:internal/errors:372:5)
    at ServerResponse.onclose (node:internal/streams/end-of-stream:142:30)
    at ServerResponse.emit (node:events:539:35)
    at Socket.onServerResponseClose (node:_http_server:236:23)
    at Socket.emit (node:events:539:35)
    at TCP.<anonymous> (node:net:709:12)

[Nest] 1  - 05/09/2023, 12:47:15 PM   ERROR [ExpressAdapter] Premature close
Error [ERR_STREAM_PREMATURE_CLOSE]: Premature close
    at new NodeError (node:internal/errors:372:5)
    at ServerResponse.onclose (node:internal/streams/end-of-stream:142:30)
    at ServerResponse.emit (node:events:539:35)
    at Socket.onServerResponseClose (node:_http_server:236:23)
    at Socket.emit (node:events:539:35)
    at TCP.<anonymous> (node:net:709:12)
[Nest] 1  - 05/09/2023, 12:47:15 PM   ERROR [ExpressAdapter] Premature close
Error [ERR_STREAM_PREMATURE_CLOSE]: Premature close
    at new NodeError (node:internal/errors:372:5)
    at ServerResponse.onclose (node:internal/streams/end-of-stream:142:30)
    at ServerResponse.emit (node:events:539:35)
    at Socket.onServerResponseClose (node:_http_server:236:23)
    at Socket.emit (node:events:539:35)
    at TCP.<anonymous> (node:net:709:12)

If you have some clues 😉 thanks

26 Replies

bo0tzz•2y ago

That error isn't related to the map and can be ignored. Can you post the full logs of all the containers?

OuafnicOOP•2y ago

sure immich_microservices :

[Nest] 1  - 05/09/2023, 12:44:55 PM     LOG [NestFactory] Starting Nest application...
[Nest] 1  - 05/09/2023, 12:44:55 PM     LOG [InstanceLoader] TypeOrmModule dependencies initialized +342ms
[Nest] 1  - 05/09/2023, 12:44:55 PM     LOG [InstanceLoader] BullModule dependencies initialized +2ms
[Nest] 1  - 05/09/2023, 12:44:55 PM     LOG [InstanceLoader] ConfigHostModule dependencies initialized +6ms
[Nest] 1  - 05/09/2023, 12:44:55 PM     LOG [InstanceLoader] DiscoveryModule dependencies initialized +2ms
[Nest] 1  - 05/09/2023, 12:44:55 PM     LOG [InstanceLoader] ConfigModule dependencies initialized +47ms
[Nest] 1  - 05/09/2023, 12:44:55 PM     LOG [InstanceLoader] BullModule dependencies initialized +2ms
[Nest] 1  - 05/09/2023, 12:44:55 PM     LOG [InstanceLoader] BullModule dependencies initialized +3ms
[Nest] 1  - 05/09/2023, 12:44:56 PM     LOG [InstanceLoader] TypeOrmCoreModule dependencies initialized +960ms
[Nest] 1  - 05/09/2023, 12:44:56 PM     LOG [InstanceLoader] TypeOrmModule dependencies initialized +2ms
[Nest] 1  - 05/09/2023, 12:44:56 PM     LOG [InstanceLoader] TypeOrmModule dependencies initialized +2ms

[Nest] 1  - 05/09/2023, 12:44:55 PM     LOG [NestFactory] Starting Nest application...
[Nest] 1  - 05/09/2023, 12:44:55 PM     LOG [InstanceLoader] TypeOrmModule dependencies initialized +342ms
[Nest] 1  - 05/09/2023, 12:44:55 PM     LOG [InstanceLoader] BullModule dependencies initialized +2ms
[Nest] 1  - 05/09/2023, 12:44:55 PM     LOG [InstanceLoader] ConfigHostModule dependencies initialized +6ms
[Nest] 1  - 05/09/2023, 12:44:55 PM     LOG [InstanceLoader] DiscoveryModule dependencies initialized +2ms
[Nest] 1  - 05/09/2023, 12:44:55 PM     LOG [InstanceLoader] ConfigModule dependencies initialized +47ms
[Nest] 1  - 05/09/2023, 12:44:55 PM     LOG [InstanceLoader] BullModule dependencies initialized +2ms
[Nest] 1  - 05/09/2023, 12:44:55 PM     LOG [InstanceLoader] BullModule dependencies initialized +3ms
[Nest] 1  - 05/09/2023, 12:44:56 PM     LOG [InstanceLoader] TypeOrmCoreModule dependencies initialized +960ms
[Nest] 1  - 05/09/2023, 12:44:56 PM     LOG [InstanceLoader] TypeOrmModule dependencies initialized +2ms
[Nest] 1  - 05/09/2023, 12:44:56 PM     LOG [InstanceLoader] TypeOrmModule dependencies initialized +2ms

and

[Nest] 1  - 05/09/2023, 12:44:56 PM    WARN [MetadataExtractionProcessor] Reverse geocoding is enabled
[Nest] 1  - 05/09/2023, 12:44:56 PM     LOG [MetadataExtractionProcessor] Initializing Reverse Geocoding
[Nest] 1  - 05/09/2023, 12:44:57 PM     LOG [InstanceLoader] InfraModule dependencies initialized +140ms
[Nest] 1  - 05/09/2023, 12:44:57 PM     LOG [InstanceLoader] DomainModule dependencies initialized +2ms
[Nest] 1  - 05/09/2023, 12:44:57 PM     LOG [InstanceLoader] MicroservicesModule dependencies initialized +3ms
[Nest] 1  - 05/09/2023, 12:44:57 PM     LOG [NestApplication] Nest application successfully started +113ms
[Nest] 1  - 05/09/2023, 12:44:57 PM     LOG [ImmichMicroservice] Running Immich Microservices in PRODUCTION environment - version 1.55.0 - Listening on port: 3002
[Nest] 1  - 05/09/2023, 12:45:29 PM     LOG [MetadataExtractionProcessor] Reverse Geocoding Initialized

[Nest] 1  - 05/09/2023, 12:44:56 PM    WARN [MetadataExtractionProcessor] Reverse geocoding is enabled
[Nest] 1  - 05/09/2023, 12:44:56 PM     LOG [MetadataExtractionProcessor] Initializing Reverse Geocoding
[Nest] 1  - 05/09/2023, 12:44:57 PM     LOG [InstanceLoader] InfraModule dependencies initialized +140ms
[Nest] 1  - 05/09/2023, 12:44:57 PM     LOG [InstanceLoader] DomainModule dependencies initialized +2ms
[Nest] 1  - 05/09/2023, 12:44:57 PM     LOG [InstanceLoader] MicroservicesModule dependencies initialized +3ms
[Nest] 1  - 05/09/2023, 12:44:57 PM     LOG [NestApplication] Nest application successfully started +113ms
[Nest] 1  - 05/09/2023, 12:44:57 PM     LOG [ImmichMicroservice] Running Immich Microservices in PRODUCTION environment - version 1.55.0 - Listening on port: 3002
[Nest] 1  - 05/09/2023, 12:45:29 PM     LOG [MetadataExtractionProcessor] Reverse Geocoding Initialized

OuafnicOOP•2y ago

immich_server

message.txt

jrasm91•2y ago

Logs from immich-web? Try restarting the immich-proxy

OuafnicOOP•2y ago

immich_web

Listening on 0.0.0.0:3000

Listening on 0.0.0.0:3000

same after restarting immich-proxy immich_machine_learning

INFO:     Started server process [1]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     Uvicorn running on http://0.0.0.0:3003 (Press CTRL+C to quit)

INFO:     Started server process [1]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     Uvicorn running on http://0.0.0.0:3003 (Press CTRL+C to quit)

immich-postgres

PostgreSQL Database directory appears to contain a database; Skipping initialization

2023-05-09 12:44:44.506 UTC [1] LOG:  starting PostgreSQL 14.7 (Debian 14.7-1.pgdg110+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2023-05-09 12:44:44.506 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2023-05-09 12:44:44.507 UTC [1] LOG:  listening on IPv6 address "::", port 5432
2023-05-09 12:44:44.527 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2023-05-09 12:44:44.554 UTC [28] LOG:  database system was shut down at 2023-05-09 12:44:31 UTC
2023-05-09 12:44:44.589 UTC [1] LOG:  database system is ready to accept connections

PostgreSQL Database directory appears to contain a database; Skipping initialization

2023-05-09 12:44:44.506 UTC [1] LOG:  starting PostgreSQL 14.7 (Debian 14.7-1.pgdg110+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2023-05-09 12:44:44.506 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2023-05-09 12:44:44.507 UTC [1] LOG:  listening on IPv6 address "::", port 5432
2023-05-09 12:44:44.527 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2023-05-09 12:44:44.554 UTC [28] LOG:  database system was shut down at 2023-05-09 12:44:31 UTC
2023-05-09 12:44:44.589 UTC [1] LOG:  database system is ready to accept connections

Redis seems good don't see anything 🤔 I've check .env and docker-compose, seems the same between 1.54 and 1.55

MicheI•2y ago

What happens if you go to yourdomain.com/api/asset/map-marker? Or check the browser logs when going to the map page

OuafnicOOP•2y ago

got a 504 time out 🤔

MicheI•2y ago

How many assets do you have?

OuafnicOOP•2y ago

above 72K got an haproxy on front of the immich server; but no filtering or curious things on the configuration maybe I can check some timeout

bo0tzz•2y ago

The code for getting the map markers is pretty inefficient right now, so a timeout isn't unlikely

OuafnicOOP•2y ago

ok 🙂 I know immich is in big development, but trying to feedback if I can (i'm not a dev, but a sysadmin)

bo0tzz•2y ago

We already have a PR open to improve that performance, so we'll hopefully get that out soon

OuafnicOOP•2y ago

I've changed the defaults timeout of haproxy, to 60s, in place of 30s the api is now responding testing the map again.. it's working 🙂 so it's just my conf, maybe too slow for this number of assets

bo0tzz•2y ago

Does the map page take a long time to load then? Because we'd like it to be performant of course :)

OuafnicOOP•2y ago

above 45sec I'm running immich in a KVM, with 8GB memory and 4 vcpus but seems hard with this number of assets and the cpu is quite old 😉

bo0tzz•2y ago

On the next version it should be faster at least, we'll be interested to know by how much

OuafnicOOP•2y ago

I can tell after the next version

MicheI•2y ago

Would you be willing to run an SQL query on your database to identify a potential performance issue?

OuafnicOOP•2y ago

sure you have specifics hardware requirement for immich ?

MicheI•2y ago

explain analyze
select
    count(*)
from
    "assets"
left join "exif" on
    "exif"."assetId" = "assets"."id"
where
    "assets"."resizePath" is not null
    and "assets"."isVisible"
    and "exif"."latitude" is not null
    and "exif"."longitude" is not null;

explain analyze
select
    count(*)
from
    "assets"
left join "exif" on
    "exif"."assetId" = "assets"."id"
where
    "assets"."resizePath" is not null
    and "assets"."isVisible"
    and "exif"."latitude" is not null
    and "exif"."longitude" is not null;

OuafnicOOP•2y ago

---------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Finalize Aggregate  (cost=5893.49..5893.50 rows=1 width=8) (actual time=133.384..139.437 rows=1 loops=1)
   ->  Gather  (cost=5893.38..5893.49 rows=1 width=8) (actual time=132.936..139.424 rows=2 loops=1)
         Workers Planned: 1
         Workers Launched: 1
         ->  Partial Aggregate  (cost=4893.38..4893.39 rows=1 width=8) (actual time=125.894..125.897 rows=1 loops=2)
               ->  Nested Loop  (cost=0.42..4892.39 rows=396 width=0) (actual time=0.151..124.256 rows=3324 loops=2)
                     ->  Parallel Seq Scan on exif  (cost=0.00..2395.57 rows=401 width=16) (actual time=0.022..26.540 rows=3324 loops=2)
                           Filter: ((latitude IS NOT NULL) AND (longitude IS NOT NULL))
                           Rows Removed by Filter: 32646
                     ->  Index Scan using "PK_da96729a8b113377cfb6a62439c" on assets  (cost=0.42..6.23 rows=1 width=16) (actual time=0.027..0.027 rows=1 loops=6647)
                           Index Cond: (id = exif."assetId")
                           Filter: (("resizePath" IS NOT NULL) AND "isVisible")
 Planning Time: 4.687 ms
 Execution Time: 139.731 ms
(14 rows)

---------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Finalize Aggregate  (cost=5893.49..5893.50 rows=1 width=8) (actual time=133.384..139.437 rows=1 loops=1)
   ->  Gather  (cost=5893.38..5893.49 rows=1 width=8) (actual time=132.936..139.424 rows=2 loops=1)
         Workers Planned: 1
         Workers Launched: 1
         ->  Partial Aggregate  (cost=4893.38..4893.39 rows=1 width=8) (actual time=125.894..125.897 rows=1 loops=2)
               ->  Nested Loop  (cost=0.42..4892.39 rows=396 width=0) (actual time=0.151..124.256 rows=3324 loops=2)
                     ->  Parallel Seq Scan on exif  (cost=0.00..2395.57 rows=401 width=16) (actual time=0.022..26.540 rows=3324 loops=2)
                           Filter: ((latitude IS NOT NULL) AND (longitude IS NOT NULL))
                           Rows Removed by Filter: 32646
                     ->  Index Scan using "PK_da96729a8b113377cfb6a62439c" on assets  (cost=0.42..6.23 rows=1 width=16) (actual time=0.027..0.027 rows=1 loops=6647)
                           Index Cond: (id = exif."assetId")
                           Filter: (("resizePath" IS NOT NULL) AND "isVisible")
 Planning Time: 4.687 ms
 Execution Time: 139.731 ms
(14 rows)

bo0tzz•2y ago

Fwiw I'd expect most of the trouble to be in the map call that's in assetservice atm

MicheI•2y ago

Yeah I think you're right, the query doesn't even take a second while the request is reported to take about 45 seconds We are missing indexes on latitude and longitude though

OuafnicOOP•2y ago

yes, 45s to 70s, according some retries I can test other queries if needed

MicheI•2y ago

No need thank you though

bo0tzz•2y ago

Added a note for this on the perf pr https://github.com/immich-app/immich/pull/2382#discussion_r1188624986

GitHub

feat(web): Global map performance optimizations by matthinc · Pull ...

A collection of little improvements to the map's performance: Use array instead of map in /asset/map-marker response: Less descriptive but much smaller { "id": ..., "lat":...

Gaming

Programming

Map error after upgrade to 1.55.

Did you find this page helpful?