Bad deal with postgres error
frodrigo opened this issue · 3 comments
frodrigo commented
Time to time I got this mixed output from imposm run. It comes from PostgreSQL error. It look like one import still running after an error on PostgreSQL. But next update start away way.
[Feb 7 09:02:54] [4h16m0s] C: 0/s 0/s (0) N: 3100/s 0/s (30422) W: 500/s 0/s (185811)
[Feb 7 09:02:54] [11h4m42s] C: 0/s 0/s (0) N: 2700/s 0/s (30422) W: 600/s 0/s (185811)[Feb 7 09:02:55] [7h17m40s] C: 0/s 0/s (0) N: 2700/s 0/s (30422) W: 400/s 0/s (185811)
[Feb 7 09:02:55] [8h16m27s] C: 0/s 0/s (0) N: 2800/s 0/s (30422) W: 500/s 0/s (185811)
[Feb 7 09:02:55] [22m53s] C: 0/s 0/s (0) N: 2700/s 0/s (30422) W: 500/s 0/s (185811) R
[Feb 7 09:02:55] [3h13m33s] C: 0/s 0/s (0) N: 2800/s 0/s (30422) W: 500/s 0/s (185811)
[Feb 7 09:02:55] [2h17m14s] C: 0/s 0/s (0) N: 2700/s 0/s (30422) W: 600/s 0/s (185811)
[Feb 7 09:02:55] [10h11m43s] C: 0/s 0/s (0) N: 2700/s 0/s (30422) W: 500/s 0/s (185811
[Feb 7 09:02:55] [1h22m6s] C: 0/s 0/s (0) N: 2700/s 0/s (30422) W: 500/s 0/s (185811)
[Feb 7 09:02:55] [9h11m55s] C: 0/s 0/s (0) N: 2700/s 0/s (30422) W: 500/s 0/s (185811)
[Feb 7 09:02:55] [5h15m13s] C: 0/s 0/s (0) N: 2600/s 0/s (30422) W: 500/s 0/s (185811)
[Feb 7 09:02:55] [14h49m47s] C: 0/s 0/s (0) N: 3200/s 0/s (30422) W: 500/s 0/s (185811
[Feb 7 09:02:55] [13h54m52s] C: 0/s 0/s (0) N: 2600/s 0/s (30422) W: 500/s 0/s (185811
[Feb 7 09:02:55] [11h57m34s] C: 0/s 0/s (0) N: 2700/s 0/s (30422) W: 500/s 0/s (185811
[Feb 7 09:02:55] [6h13m15s] C: 0/s 0/s (0) N: 2600/s 0/s (30422) W: 500/s 0/s (185811)
[Feb 7 09:02:55] [12h57m40s] C: 0/s 0/s (0) N: 3000/s 0/s (30422) W: 500/s 0/s (185811
[Feb 7 09:02:55] [4h16m0s] C: 0/s 0/s (0) N: 3100/s 0/s (30422) W: 500/s 0/s (185811)
[Feb 7 09:02:55] [11h4m43s] C: 0/s 0/s (0) N: 2700/s 0/s (30422) W: 600/s 0/s (185811)
[Feb 7 09:02:55] [7h17m41s] C: 0/s 0/s (0) N: 2700/s 0/s (30422) W: 400/s 0/s (185811)
[Feb 7 09:02:55] [8h16m28s] C: 0/s 0/s (0) N: 2800/s 0/s (30422) W: 500/s 0/s (185811)
[Feb 7 09:02:55] [22m53s] C: 0/s 0/s (0) N: 2700/s 0/s (30422) W: 500/s 0/s (185811) R
[Feb 7 09:02:55] [3h13m33s] C: 0/s 0/s (0) N: 2800/s 0/s (30422) W: 500/s 0/s (185811)
[Feb 7 09:02:55] [2h17m14s] C: 0/s 0/s (0) N: 2700/s 0/s (30422) W: 600/s 0/s (185811)
[Feb 7 09:02:55] [10h11m44s] C: 0/s 0/s (0) N: 2700/s 0/s (30422) W: 500/s 0/s (185811
[Feb 7 09:02:55] [1h22m7s] C: 0/s 0/s (0) N: 2700/s 0/s (30422) W: 500/s 0/s (185811)
[Feb 7 09:02:55] [9h11m56s] C: 0/s 0/s (0) N: 2700/s 0/s (30422) W: 500/s 0/s (185811)
[Feb 7 09:02:55] [5h15m13s] C: 0/s 0/s (0) N: 2600/s 0/s (30422) W: 500/s 0/s (185811)
[Feb 7 09:02:55] [14h49m47s] C: 0/s 0/s (0) N: 3200/s 0/s (30422) W: 500/s 0/s (185811
[Feb 7 09:02:55] [13h54m52s] C: 0/s 0/s (0) N: 2600/s 0/s (30422) W: 500/s 0/s (185811
[Feb 7 09:02:55] [11h57m34s] C: 0/s 0/s (0) N: 2700/s 0/s (30422) W: 500/s 0/s (185811
[Feb 7 09:02:55] [6h13m16s] C: 0/s 0/s (0) N: 2600/s 0/s (30422) W: 500/s 0/s (185811)
[Feb 7 09:02:55] [12h57m40s] C: 0/s 0/s (0) N: 3000/s 0/s (30422) W: 500/s 0/s (185811[Feb 7 09:02:55] [4h16m1s] C: 0/s 0/s (0) N: 3100/s 0/s (30422) W: 500/s 0/s (185811)
[Feb 7 09:02:55] [11h4m43s] C: 0/s 0/s (0) N: 2700/s 0/s (30422) W: 600/s 0/s (185811)
[Feb 7 09:02:56] [7h17m41s] C: 0/s 0/s (0) N: 2700/s 0/s (30422) W: 400/s 0/s (185811)
[Feb 7 09:02:56] [8h16m28s] C: 0/s 0/s (0) N: 2800/s 0/s (30422) W: 500/s 0/s (185811)
[Feb 7 09:02:56] [22m54s] C: 0/s 0/s (0) N: 2700/s 0/s (30422) W: 500/s 0/s (185811) R
[Feb 7 09:02:56] [3h13m34s] C: 0/s 0/s (0) N: 2800/s 0/s (30422) W: 500/s 0/s (185811) R
frodrigo commented
Failed process seem to be still here, doing some thing.
How to reproduce
imposm import \
-config config.json \
-mapping imposm.yaml \
-read andorra-200325.osm.pbf \
-overwritecache \
-write \
-diff \
-cachedir ./cache \
-diffdir ./diff \
-connection postgis://fred@localhost/fred \
-deployproduction
psql <<EOF
CREATE OR REPLACE FUNCTION osm_ways_fail() RETURNS trigger AS
\$BODY\$
BEGIN
RAISE 'Planned fail.';
END;
\$BODY\$
language plpgsql;
CREATE CONSTRAINT TRIGGER osm_ways_fail
AFTER INSERT ON osm_ways
INITIALLY DEFERRED
FOR EACH ROW
EXECUTE PROCEDURE osm_ways_fail();
EOF
imposm run \
-config config.json \
-mapping imposm.yaml \
-cachedir ./cache \
-diffdir ./diff \
-connection postgis://fred@localhost/fred
Log
$ imposm run -config config.json -mapping imposm.yaml -cachedir ./cache -diffdir ./diff -connection postgis://fred@localhost/fred
[Mar 30 15:06:08] [INFO] Replication URL: http://download.geofabrik.de/europe/andorra-updates/
[Mar 30 15:06:08] [INFO] Replication interval: 24h0m0s
[Mar 30 15:06:08] [INFO] [replication] Processing sequence 2561
[Mar 30 15:06:08] [INFO] [replication] Downloading diff file from http://download.geofabrik.de/europe/andorra-updates/000/002/561.state.txt
[Mar 30 15:06:08] [INFO] [replication] Downloading diff file from http://download.geofabrik.de/europe/andorra-updates/000/002/561.osc.gz
[Mar 30 15:06:08] [INFO] [replication] Processing sequence 2562
[Mar 30 15:06:08] [INFO] [replication] Downloading diff file from http://download.geofabrik.de/europe/andorra-updates/000/002/562.state.txt
[Mar 30 15:06:08] [INFO] [replication] Downloading diff file from http://download.geofabrik.de/europe/andorra-updates/000/002/562.osc.gz
[Mar 30 15:06:08] [INFO] [replication] Processing sequence 2563
[Mar 30 15:06:08] [INFO] [replication] Downloading diff file from http://download.geofabrik.de/europe/andorra-updates/000/002/563.state.txt
[Mar 30 15:06:08] [INFO] [replication] Downloading diff file from http://download.geofabrik.de/europe/andorra-updates/000/002/563.osc.gz
[Mar 30 15:06:08] [INFO] [diff] Parsing changes, updating cache and removing elements took: 11.703351ms
[Mar 30 15:06:08] [INFO] [ 0s] C: 0/s (9) N: 0/s (0) W: 0/s (4) R: 0/s (2)
[Mar 30 15:06:08] [INFO] [PostGIS] Updating generalized tables took: 21.405µs
[Mar 30 15:06:08] [INFO] [diff] Processing diff/000/002/561.osc.gz took: 35.833687ms
[Mar 30 15:06:08] [INFO] importing #2561 till 2020-03-25 21:59:02 +0000 UTC took: 36.671743ms
[Mar 30 15:06:08] [ERR] pq: Planned fail.
[Mar 30 15:06:08] [INFO] retrying in 2s
[Mar 30 15:06:09] [ 0s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:09] [ 1s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:10] [ 1s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:10] [ 2s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:10] [INFO] [diff] Parsing changes, updating cache and removing elements took: 35.130978ms
[Mar 30 15:06:10] [INFO] [ 0s] C: 0/s (9) N: 0/s (0) W: 0/s (4) R: 0/s (2)
[Mar 30 15:06:10] [INFO] [PostGIS] Updating generalized tables took: 29.131µs
[Mar 30 15:06:10] [INFO] [diff] Processing diff/000/002/561.osc.gz took: 64.545926ms
[Mar 30 15:06:10] [INFO] importing #2561 till 2020-03-25 21:59:02 +0000 UTC took: 64.754092ms
[Mar 30 15:06:10] [ERR] pq: Planned fail.
[Mar 30 15:06:10] [INFO] retrying in 4s
[Mar 30 15:06:11] [ 2s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:11] [ 0s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:11] [ 3s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:11] [ 1s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:12] [ 3s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:12] [ 1s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:12] [ 4s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:12] [ 2s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:13] [ 4s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:13] [ 2s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:13] [ 5s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:13] [ 3s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:14] [ 5s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:14] [ 3s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:14] [ 6s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:14] [ 4s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:14] [INFO] [diff] Parsing changes, updating cache and removing elements took: 25.761932ms
[Mar 30 15:06:14] [INFO] [ 0s] C: 0/s (9) N: 0/s (0) W: 0/s (4) R: 0/s (2)
[Mar 30 15:06:14] [INFO] [PostGIS] Updating generalized tables took: 29.399µs
[Mar 30 15:06:14] [INFO] [diff] Processing diff/000/002/561.osc.gz took: 50.465934ms
[Mar 30 15:06:14] [INFO] importing #2561 till 2020-03-25 21:59:02 +0000 UTC took: 50.843773ms
[Mar 30 15:06:14] [ERR] pq: Planned fail.
[Mar 30 15:06:14] [INFO] retrying in 8s
[Mar 30 15:06:15] [ 6s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:15] [ 4s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:15] [ 0s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:15] [ 7s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:15] [ 5s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:15] [ 1s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:16] [ 7s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:16] [ 5s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:16] [ 1s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:16] [ 8s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
^C[Mar 30 15:06:16] [ 6s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R:
[Mar 30 15:06:16] [ 2s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:17] [ 8s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:17] [ 6s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:17] [ 2s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:17] [ 9s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:17] [ 7s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:17] [ 3s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:18] [ 9s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:18] [ 7s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:18] [ 3s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:18] [ 10s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:18] [ 8s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:18] [ 4s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:19] [ 10s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:19] [ 8s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:19] [ 4s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:19] [ 11s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:19] [ 9s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:19] [ 5s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:20] [ 11s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:20] [ 9s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:20] [ 5s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:20] [ 12s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:20] [ 10s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:20] [ 6s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:21] [ 12s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:21] [ 10s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:21] [ 6s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:21] [ 13s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:21] [ 11s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:21] [ 7s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:22] [ 13s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:22] [ 11s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:22] [ 7s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:22] [ 14s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:22] [ 12s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:22] [ 8s] C: 0/s 0/s (0) N: 0/s 0/s (8) W: 0/s 0/s (5) R: 0/
[Mar 30 15:06:22] [INFO] [diff] Parsing changes, updating cache and removing elements took: 19.19232ms
[Mar 30 15:06:22] [INFO] [ 0s] C: 0/s (9) N: 0/s (0) W: 0/s (4) R: 0/s (2)
[Mar 30 15:06:22] [INFO] [PostGIS] Updating generalized tables took: 22.518µs
[Mar 30 15:06:22] [INFO] [diff] Processing diff/000/002/561.osc.gz took: 40.564471ms
[Mar 30 15:06:22] [INFO] importing #2561 till 2020-03-25 21:59:02 +0000 UTC took: 41.298764ms
[Mar 30 15:06:22] [INFO] Exiting. (SIGTERM/SIGINT/SIGHUB)
frodrigo commented
Issue seem solved with version 0.10. I need to confirm.
frodrigo commented
No. Issue is still here, but not visible when you play with puppet data. Update have to be longer than a minute now to see the duplicate lines.