Odmin
August 27, 2019, 10:31pm
1
After upgrade to version v0.19.0 I got this issue:
2019-08-27T21:27:30.284924386Z 2019-08-27T21:27:30.284Z INFO Configuration loaded from: /app/config/config.yaml
2019-08-27T21:27:30.301735626Z 2019-08-27T21:27:30.301Z INFO Operator email: xxxx@xxxx
2019-08-27T21:27:30.301739330Z 2019-08-27T21:27:30.301Z INFO operator wallet: 0xXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
2019-08-27T21:27:30.947142174Z 2019-08-27T21:27:30.946Z INFO version running on version v0.19.0
2019-08-27T21:27:30.949180483Z 2019-08-27T21:27:30.949Z INFO db.migration Latest Version {"version": 18}
2019-08-27T21:27:30.949954034Z 2019-08-27T21:27:30.949Z INFO Node 12LcaN37vw6V3HSm7c9zrLQEWBgDFTzmm6FFihWQoLrmfNtbygq started
2019-08-27T21:27:30.949956478Z 2019-08-27T21:27:30.949Z INFO Public server started on [::]:28967
2019-08-27T21:27:30.949956964Z 2019-08-27T21:27:30.949Z INFO Private server started on 127.0.0.1:7778
2019-08-27T21:27:30.949957425Z 2019-08-27T21:27:30.949Z INFO bandwidth Performing bandwidth usage rollups
2019-08-27T21:27:30.958393304Z 2019-08-27T21:27:30.958Z INFO orders.118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW sending {"count": 126}
2019-08-27T21:27:30.958395203Z 2019-08-27T21:27:30.958Z INFO orders.12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs sending {"count": 15}
2019-08-27T21:27:30.958395555Z 2019-08-27T21:27:30.958Z INFO orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6 sending {"count": 22}
2019-08-27T21:27:30.958395799Z 2019-08-27T21:27:30.958Z INFO orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S sending {"count": 19}
2019-08-27T21:27:30.973580126Z 2019-08-27T21:27:30.973Z INFO piecestore:monitor Remaining Bandwidth {"bytes": 398478298667520}
2019-08-27T21:27:31.059447398Z 2019-08-27T21:27:31.059Z INFO piecestore upload started {"Piece ID": "DEOPDJENNFYEU5KPRJ75TU2S6TPSMSJXPNW3Y4WCYKGDA7LKTDAA", "SatelliteID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW",
"Action": "PUT"}
2019-08-27T21:27:31.094661906Z 2019-08-27T21:27:31.094Z INFO version running on version v0.19.0
2019-08-27T21:27:31.215704913Z 2019-08-27T21:27:31.215Z ERROR orders.12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs gRPC client error when receiveing new order settlements {"error": "order: failed to receive settlement response: rpc error: code = Unknown desc = pq: duplicate key value violates unique constraint \"used_serials_pkey\"", "errorVerbose": "order: failed to receive settlement response: rpc error: code = Unknown desc = pq: duplicate key value violates unique constraint \"used_serials_pkey\"\n\tstorj.io/storj/storagenode/orders.(*Service).settle:301\n\tstorj.io/storj/storagenode/orders.(*Service).Settle:190\n\tstorj.io/storj/storagenode/orders.(*Service).sendOrders.func2:169\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2019-08-27T21:27:31.215795735Z 2019-08-27T21:27:31.215Z INFO orders.12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs finished
2019-08-27T21:27:31.215798247Z 2019-08-27T21:27:31.215Z ERROR orders.12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs failed to settle orders {"error": "order: failed to receive settlement response: rpc error: code = Unknown desc = pq: duplicate key value violates unique constraint \"used_serials_pkey\"", "errorVerbose": "order: failed to receive settlement response: rpc error: code = Unknown desc = pq: duplicate key value violates unique constraint \"used_serials_pkey\"\n\tstorj.io/storj/storagenode/orders.(*Service).settle:301\n\tstorj.io/storj/storagenode/orders.(*Service).Settle:190\n\tstorj.io/storj/storagenode/orders.(*Service).sendOrders.func2:169\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2019-08-27T21:27:31.405347145Z 2019-08-27T21:27:31.404Z ERROR orders.118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW gRPC client error when receiveing new order settlements {"error": "order: failed to receive settlement response: rpc error: code = Unknown desc = pq: duplicate key value violates unique constraint \"used_serials_pkey\"", "errorVerbose": "order: failed to receive settlement response: rpc error: code = Unknown desc = pq: duplicate key value violates unique constraint \"used_serials_pkey\"\n\tstorj.io/storj/storagenode/orders.(*Service).settle:301\n\tstorj.io/storj/storagenode/orders.(*Service).Settle:190\n\tstorj.io/storj/storagenode/orders.(*Service).sendOrders.func2:169\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2019-08-27T21:27:31.405349319Z 2019-08-27T21:27:31.405Z INFO orders.118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW finished
2019-08-27T21:27:31.405350459Z 2019-08-27T21:27:31.405Z ERROR orders.118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW failed to settle orders {"error": "order: failed to receive settlement response: rpc error: code = Unknown desc = pq: duplicate key value violates unique constraint \"used_serials_pkey\"", "errorVerbose": "order: failed to receive settlement response: rpc error: code = Unknown desc = pq: duplicate key value violates unique constraint \"used_serials_pkey\"\n\tstorj.io/storj/storagenode/orders.(*Service).settle:301\n\tstorj.io/storj/storagenode/orders.(*Service).Settle:190\n\tstorj.io/storj/storagenode/orders.(*Service).sendOrders.func2:169\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2019-08-27T21:27:31.588119203Z 2019-08-27T21:27:31.587Z ERROR orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S gRPC client error when receiveing new order settlements {"error": "order: failed to receive settlement response: rpc error: code = Unknown desc = pq: duplicate key value violates unique constraint \"used_serials_pkey\"", "errorVerbose": "order: failed to receive settlement response: rpc error: code = Unknown desc = pq: duplicate key value violates unique constraint \"used_serials_pkey\"\n\tstorj.io/storj/storagenode/orders.(*Service).settle:301\n\tstorj.io/storj/storagenode/orders.(*Service).Settle:190\n\tstorj.io/storj/storagenode/orders.(*Service).sendOrders.func2:169\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2019-08-27T21:27:31.588237928Z 2019-08-27T21:27:31.588Z INFO orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S finished
2019-08-27T21:27:31.588239807Z 2019-08-27T21:27:31.588Z ERROR orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S failed to settle orders {"error": "order: failed to receive settlement response: rpc error: code = Unknown desc = pq: duplicate key value violates unique constraint \"used_serials_pkey\"", "errorVerbose": "order: failed to receive settlement response: rpc error: code = Unknown desc = pq: duplicate key value violates unique constraint \"used_serials_pkey\"\n\tstorj.io/storj/storagenode/orders.(*Service).settle:301\n\tstorj.io/storj/storagenode/orders.(*Service).Settle:190\n\tstorj.io/storj/storagenode/orders.(*Service).sendOrders.func2:169\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2019-08-27T21:27:32.217913813Z 2019-08-27T21:27:32.217Z ERROR orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6 gRPC client error when receiveing new order settlements {"error": "order: failed to receive settlement response: rpc error: code = Unknown desc = pq: duplicate key value violates unique constraint \"used_serials_pkey\"", "errorVerbose": "order: failed to receive settlement response: rpc error: code = Unknown desc = pq: duplicate key value violates unique constraint \"used_serials_pkey\"\n\tstorj.io/storj/storagenode/orders.(*Service).settle:301\n\tstorj.io/storj/storagenode/orders.(*Service).Settle:190\n\tstorj.io/storj/storagenode/orders.(*Service).sendOrders.func2:169\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2019-08-27T21:27:32.218030958Z 2019-08-27T21:27:32.217Z INFO orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6 finished
2019-08-27T21:27:32.218032799Z 2019-08-27T21:27:32.217Z ERROR orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6 failed to settle orders {"error": "order: failed to receive settlement response: rpc error: code = Unknown desc = pq: duplicate key value violates unique constraint \"used_serials_pkey\"", "errorVerbose": "order: failed to receive settlement response: rpc error: code = Unknown desc = pq: duplicate key value violates unique constraint \"used_serials_pkey\"\n\tstorj.io/storj/storagenode/orders.(*Service).settle:301\n\tstorj.io/storj/storagenode/orders.(*Service).Settle:190\n\tstorj.io/storj/storagenode/orders.(*Service).sendOrders.func2:169\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2019-08-27T21:27:33.862738126Z 2019-08-27T21:27:33.862Z INFO piecestore uploaded {"Piece ID": "DEOPDJENNFYEU5KPRJ75TU2S6TPSMSJXPNW3Y4WCYKGDA7LKTDAA", "SatelliteID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW",
"Action": "PUT"}
2 Likes
Thank you for issue report. This problem is now top priority for us.
2 Likes
Odmin
August 28, 2019, 7:40am
3
Glad to help and keep network helthly
Alexey
August 28, 2019, 9:11pm
4
kajar9
August 29, 2019, 2:24pm
5
Same issue here. I thought it happened after a power outage, but this started to happen on my second node too after graceful restart (proper stop storagenode, restart, start storagenode etc.). (Second server).
Database PRAGMA integrity checks come out OK on DB
Hi @Alexey !@xyphos10 posted, I don’t see such kind of errors after some time after node restart but following error still present2019-08-29T12:07:21.582+0300 ERROR orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6 failed to settle orders {"error": "order: failed to receive settlement response: rpc error: code = Unknown desc = pq: duplicate key value violates unique constraint \"used_serials_pkey\"", "errorVerbose": "order: failed to receive settlement response: rpc error: code = Unknown desc = pq: duplicate key value violates unique constraint \"used_serials_pkey\"\n\tstorj.io/storj/storagenode/orders.(*Service).settle:301\n\tstorj.io/storj/storagenode/orders.(*Service).Settle:190\n\tstorj.io/storj/storagenode/orders.(*Service).sendOrders.func2:169\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
Alexey
August 29, 2019, 7:07pm
7
I tried to separate errors between types. It could be easily tracked.ERROR nodestats:cache Get disk space usage query failed {"error": "database is locked
bota87
August 29, 2019, 2:33pm
8
Hi to all,
after the last update i found some new error in the log
gRPC client when sending new orders settlements
gRPC client error when receiveing new order settlements
failed to settle orders
Log details
2019-08-29T13:32:51.982Z INFO version running on version v0.19.0tstorj.io/storj/storagenode/orders.(*Service ).settle.func2:274\n\tgolang.org/x/sync/errgroup.(*Group ).Go.func1:57”, “request”: {“limit”:{“serial_number”:“LL2WHOH75RAGPBGHKIKUFB3LDA”,“satellite_id”:“118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW”,“uplink_public_key”:{},“storage_node_id”:“1h2dUWBQuZ9ivG5v97Zb8SXjd4g2TEyG74o3ixtiFpDS8RqM5j”,“piece_id”:“KQGVABZZQ77PDAWDASRVKLZ4LRWFDY5DTNWN2AC56M7CLBVHOSZQ”,“limit”:2317056,“action”:2,“piece_expiration”:“0001-01-01T00:00:00Z”,“order_expiration”:“2019-09-04T00:36:20.796173046Z”,“order_creation”:“2019-08-28T00:36:20.836405696Z”,“satellite_signature”:“MEUCIEXXgySB6PvM+svBqaKQ1bCOGwwWRLNjcR2eR3MAbMVFAiEA6/SRaxAv0ZNDiBo+IuI/g1YhtDAjSOrzlkCvexd0Bak=”,“satellite_address”:{“address”:“satellite.stefan-benten.de:7777 ”}},“order”:{“serial_number”:“LL2WHOH75RAGPBGHKIKUFB3LDA”,“amount”:2316800,“uplink_signature”:“Scdrnpvv5y6eb7CV0+s/8jvbR+xYeRdpzK8bmKT++1ZV4Q8Cwy0I0ZcukrVq/sJ6gpZ5Z7P75aR/UU7JYcr5CA==”}}}tstorj.io/storj/storagenode/orders.(*Service ).settle:301\n\tstorj.io/storj/storagenode/orders.(*Service ).Settle:190\n\tstorj.io/storj/storagenode/orders.(*Service ).sendOrders.func2:169\n\tgolang.org/x/sync/errgroup.(*Group ).Go.func1:57”}tstorj.io/storj/storagenode/orders.(*Service ).settle.func2:274\n\tgolang.org/x/sync/errgroup.(*Group ).Go.func1:57\n— order: failed to receive settlement response: rpc error: code = Unknown desc = pq: duplicate key value violates unique constraint “used_serials_pkey”\n\tstorj.io/storj/storagenode/orders.(*Service ).settle:301\n\tstorj.io/storj/storagenode/orders.(*Service ).Settle:190\n\tstorj.io/storj/storagenode/orders.(*Service ).sendOrders.func2:169\n\tgolang.org/x/sync/errgroup.(*Group ).Go.func1:57”}tstorj.io/storj/storagenode/orders.(*Service ).settle:301\n\tstorj.io/storj/storagenode/orders.(*Service ).Settle:190\n\tstorj.io/storj/storagenode/orders.(*Service ).sendOrders.func2:169\n\tgolang.org/x/sync/errgroup.(*Group ).Go.func1:57”}tstorj.io/storj/storagenode/orders.(*Service ).settle:301\n\tstorj.io/storj/storagenode/orders.(*Service ).Settle:190\n\tstorj.io/storj/storagenode/orders.(*Service ).sendOrders.func2:169\n\tgolang.org/x/sync/errgroup.(*Group ).Go.func1:57”}
Dylan
August 29, 2019, 2:54pm
9
Hey @bota87 and welcome to the forums! Thank you for your log, it seems this issue has came up recently: https://forum.storj.io/t/pq-duplicate-key-value-violates-unique-constraint-used-serials-pkey-after-upgrade-to-v0-19-0/1273
The team is looking into it and hope to have an explanation and solution to this soon
1 Like
Odmin
August 30, 2019, 12:10pm
10
After update to version v0.19.5 issue is gone:
Summary
2019-08-30T12:09:07.750363177Z 2019-08-30T12:09:07.750Z INFO version running on version v0.19.5
2019-08-30T12:09:07.751743485Z 2019-08-30T12:09:07.751Z INFO db.migration Latest Version {"version": 18}
2019-08-30T12:09:07.752182975Z 2019-08-30T12:09:07.752Z INFO Node 12LcaN37vw6V3HSm7c9zrLQEWBgDFTzmm6FFihWQoLrmfNtbygq started
2019-08-30T12:09:07.752184530Z 2019-08-30T12:09:07.752Z INFO Public server started on [::]:28967
2019-08-30T12:09:07.752185051Z 2019-08-30T12:09:07.752Z INFO Private server started on 127.0.0.1:7778
2019-08-30T12:09:07.753010752Z 2019-08-30T12:09:07.752Z INFO bandwidth Performing bandwidth usage rollups
2019-08-30T12:09:07.761276394Z 2019-08-30T12:09:07.761Z INFO orders.118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW sending {"count": 8}
2019-08-30T12:09:07.761417641Z 2019-08-30T12:09:07.761Z INFO orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6 sending {"count": 4}
2019-08-30T12:09:07.761418692Z 2019-08-30T12:09:07.761Z INFO orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S sending {"count": 2}
2019-08-30T12:09:07.761913299Z 2019-08-30T12:09:07.761Z INFO orders.12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs sending {"count": 2}
2019-08-30T12:09:07.779227734Z 2019-08-30T12:09:07.779Z INFO piecestore:monitor Remaining Bandwidth {"bytes": 398451713843968}
2019-08-30T12:09:07.895190719Z 2019-08-30T12:09:07.895Z INFO version running on version v0.19.5
2019-08-30T12:09:08.030163871Z 2019-08-30T12:09:08.030Z INFO orders.12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs finished
2019-08-30T12:09:08.069910353Z 2019-08-30T12:09:08.069Z INFO orders.118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW finished
2019-08-30T12:09:08.397394220Z 2019-08-30T12:09:08.397Z INFO orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S finished
2019-08-30T12:09:09.085515339Z 2019-08-30T12:09:09.085Z INFO orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6 finished
2019-08-30T12:09:29.627705842Z 2019-08-30T12:09:29.627Z INFO piecestore download started {"Piece ID": "IIEM5EVGUJKNL5GU6BXFYEJP6ZIZ6XOKOZIQFGXEWOSRL5ZTT5EQ", "SatelliteID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET_AUDIT"}
2019-08-30T12:09:30.217861941Z 2019-08-30T12:09:30.217Z INFO piecestore downloaded {"Piece ID": "IIEM5EVGUJKNL5GU6BXFYEJP6ZIZ6XOKOZIQFGXEWOSRL5ZTT5EQ", "SatelliteID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET_AUDIT"}
kajar9
August 30, 2019, 3:55pm
11
I don’t know if it’s completely related, but this is basically similar error I occasionally get:
ERROR orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6 failed to settle orders {"error": "order: failed to receive settlement response: rpc error: code = Unavailable desc = transport is closing", "errorVerbose": "order: failed to receive settlement response: rpc error: code = Unavailable desc = transport is closing\n\tstorj.io/storj/storagenode/orders.(*Service).settle:310\n\tstorj.io/storj/storagenode/orders.(*Service).Settle:190\n\tstorj.io/storj/storagenode/orders.(*Service).sendOrders.func2:169\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
Dylan
August 30, 2019, 6:03pm
13
An explination of this issue can be found here:
Let me add a bit explaination about the current network state.
With v0.19.0 we introduced a lot of database performance improvement. One of them was batching the order receiver. In our tests the order receiver worked just fine but in production there is a good chance that a storage node is loosing the connection while submitting orders. In the next our the storage node will try to resend the order but the satellite already has it. That was the database error we have seen.
The error message its…
