Page MenuHomeSoftware Heritage

Mirror: unexpected closed connection to the pg server
Open, HighPublic

Description

2021-04-01T15:03:30.450387347Z swh_storage.1.yjtfpr7ambpm@libra    | ERROR:root:server closed the connection unexpectedly
2021-04-01T15:03:30.450408112Z swh_storage.1.yjtfpr7ambpm@libra    | 	This probably means the server terminated abnormally
2021-04-01T15:03:30.450411279Z swh_storage.1.yjtfpr7ambpm@libra    | 	before or while processing the request.
2021-04-01T15:03:30.450413362Z swh_storage.1.yjtfpr7ambpm@libra    | Traceback (most recent call last):
2021-04-01T15:03:30.450415681Z swh_storage.1.yjtfpr7ambpm@libra    |   File "/usr/lib/python3/dist-packages/flask/app.py", line 1813, in full_dispatch_request
2021-04-01T15:03:30.450418532Z swh_storage.1.yjtfpr7ambpm@libra    |     rv = self.dispatch_request()
2021-04-01T15:03:30.450421400Z swh_storage.1.yjtfpr7ambpm@libra    |   File "/usr/lib/python3/dist-packages/flask/app.py", line 1799, in dispatch_request
2021-04-01T15:03:30.450425006Z swh_storage.1.yjtfpr7ambpm@libra    |     return self.view_functions[rule.endpoint](**req.view_args)
2021-04-01T15:03:30.450428523Z swh_storage.1.yjtfpr7ambpm@libra    |   File "<decorator-gen-66>", line 2, in snapshot_add
2021-04-01T15:03:30.450432037Z swh_storage.1.yjtfpr7ambpm@libra    |   File "/usr/lib/python3/dist-packages/swh/core/api/negotiation.py", line 147, in _negotiate
2021-04-01T15:03:30.450442880Z swh_storage.1.yjtfpr7ambpm@libra    |     return f.negotiator(*args, **kwargs)
2021-04-01T15:03:30.450445071Z swh_storage.1.yjtfpr7ambpm@libra    |   File "/usr/lib/python3/dist-packages/swh/core/api/negotiation.py", line 81, in __call__
2021-04-01T15:03:30.450447152Z swh_storage.1.yjtfpr7ambpm@libra    |     result = self.func(*args, **kwargs)
2021-04-01T15:03:30.450449052Z swh_storage.1.yjtfpr7ambpm@libra    |   File "/usr/lib/python3/dist-packages/swh/core/api/__init__.py", line 458, in _f
2021-04-01T15:03:30.450451042Z swh_storage.1.yjtfpr7ambpm@libra    |     return obj_meth(**kw)
2021-04-01T15:03:30.450452891Z swh_storage.1.yjtfpr7ambpm@libra    |   File "/usr/lib/python3/dist-packages/swh/storage/metrics.py", line 24, in d
2021-04-01T15:03:30.450454795Z swh_storage.1.yjtfpr7ambpm@libra    |     return f(*a, **kw)
2021-04-01T15:03:30.450456584Z swh_storage.1.yjtfpr7ambpm@libra    |   File "/usr/lib/python3/dist-packages/swh/storage/metrics.py", line 77, in d
2021-04-01T15:03:30.450458525Z swh_storage.1.yjtfpr7ambpm@libra    |     r = f(*a, **kw)
2021-04-01T15:03:30.450460347Z swh_storage.1.yjtfpr7ambpm@libra    |   File "/usr/lib/python3/dist-packages/swh/core/db/common.py", line 62, in _meth
2021-04-01T15:03:30.450462416Z swh_storage.1.yjtfpr7ambpm@libra    |     return meth(self, *args, db=db, cur=cur, **kwargs)
2021-04-01T15:03:30.450464345Z swh_storage.1.yjtfpr7ambpm@libra    |   File "/usr/lib/python3/dist-packages/swh/storage/postgresql/storage.py", line 749, in snapshot_add
2021-04-01T15:03:30.450466376Z swh_storage.1.yjtfpr7ambpm@libra    |     if not db.snapshot_exists(snapshot.id, cur):
2021-04-01T15:03:30.450468238Z swh_storage.1.yjtfpr7ambpm@libra    |   File "/usr/lib/python3/dist-packages/swh/storage/postgresql/db.py", line 217, in snapshot_exists
2021-04-01T15:03:30.450470142Z swh_storage.1.yjtfpr7ambpm@libra    |     cur.execute("""SELECT 1 FROM snapshot where id=%s""", (snapshot_id,))
2021-04-01T15:03:30.450472137Z swh_storage.1.yjtfpr7ambpm@libra    | psycopg2.OperationalError: server closed the connection unexpectedly
2021-04-01T15:03:30.450473982Z swh_storage.1.yjtfpr7ambpm@libra    | 	This probably means the server terminated abnormally
2021-04-01T15:03:30.450475866Z swh_storage.1.yjtfpr7ambpm@libra    | 	before or while processing the request.
2021-04-01T15:03:30.450479655Z swh_storage.1.yjtfpr7ambpm@libra    |

Context:

ii  python3-swh.core        0.12.0-1~swh1~bpo10+1 all          Software Heritage core utilities
ii  python3-swh.journal     0.7.1-1~swh1~bpo10+1  all          Software Heritage Journal utilities
ii  python3-swh.model       2.3.0-1~swh1~bpo10+1  all          Software Heritage data model
ii  python3-swh.objstorage  0.2.2-1~swh1~bpo10+1  all          Software Heritage Object Storage
ii  python3-swh.scheduler   0.10.0-1~swh1~bpo10+1 all          Software Heritage Scheduler
ii  python3-swh.storage     0.27.0-1~swh1~bpo10+1 all          Software Heritage storage utilities

Event Timeline

douardda triaged this task as High priority.Fri, Apr 2, 9:47 AM
douardda created this task.

Just got this one below. Note that this occurred just when the replayer actually started to insert object in the storage (before that, since the start of the replayer process, only kafka scaffolding took place for quite some time, around 30mn!)

2021-04-08T09:13:26.878993428Z swh_graph-replayer.1.l4qqau7nbpvm@libra    | Traceback (most recent call last):
2021-04-08T09:13:26.879019349Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |   File "/usr/bin/swh", line 11, in <module>
2021-04-08T09:13:26.879024799Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |     load_entry_point('swh.core==0.13.0', 'console_scripts', 'swh')()
2021-04-08T09:13:26.879028881Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |   File "/usr/lib/python3/dist-packages/swh/core/cli/__init__.py", line 185, in main
2021-04-08T09:13:26.879032938Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |     return swh(auto_envvar_prefix="SWH")
2021-04-08T09:13:26.879036909Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |   File "/usr/lib/python3/dist-packages/click/core.py", line 764, in __call__
2021-04-08T09:13:26.879040550Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |     return self.main(*args, **kwargs)
2021-04-08T09:13:26.879044054Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |   File "/usr/lib/python3/dist-packages/click/core.py", line 717, in main
2021-04-08T09:13:26.879048262Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |     rv = self.invoke(ctx)
2021-04-08T09:13:26.879051901Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |   File "/usr/lib/python3/dist-packages/click/core.py", line 1137, in invoke
2021-04-08T09:13:26.879055622Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |     return _process_result(sub_ctx.command.invoke(sub_ctx))
2021-04-08T09:13:26.879058980Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |   File "/usr/lib/python3/dist-packages/click/core.py", line 1137, in invoke
2021-04-08T09:13:26.879062908Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |     return _process_result(sub_ctx.command.invoke(sub_ctx))
2021-04-08T09:13:26.879066539Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |   File "/usr/lib/python3/dist-packages/click/core.py", line 956, in invoke
2021-04-08T09:13:26.879071263Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |     return ctx.invoke(self.callback, **ctx.params)
2021-04-08T09:13:26.879074678Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |   File "/usr/lib/python3/dist-packages/click/core.py", line 555, in invoke
2021-04-08T09:13:26.879078563Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |     return callback(*args, **kwargs)
2021-04-08T09:13:26.879082209Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |   File "/usr/lib/python3/dist-packages/click/decorators.py", line 17, in new_func
2021-04-08T09:13:26.879086083Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |     return f(get_current_context(), *args, **kwargs)
2021-04-08T09:13:26.879089612Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |   File "/usr/lib/python3/dist-packages/swh/storage/cli.py", line 193, in replay
2021-04-08T09:13:26.879093648Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |     client.process(worker_fn)
2021-04-08T09:13:26.879097217Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |   File "/usr/lib/python3/dist-packages/swh/journal/client.py", line 265, in process
2021-04-08T09:13:26.879100916Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |     batch_processed, at_eof = self.handle_messages(messages, worker_fn)
2021-04-08T09:13:26.879104539Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |   File "/usr/lib/python3/dist-packages/swh/journal/client.py", line 292, in handle_messages
2021-04-08T09:13:26.879108128Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |     worker_fn(dict(objects))
2021-04-08T09:13:26.879111637Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |   File "/usr/lib/python3/dist-packages/swh/storage/replay.py", line 62, in process_replay_objects
2021-04-08T09:13:26.879127904Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |     _insert_objects(object_type, objects, storage)
2021-04-08T09:13:26.879131363Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |   File "/usr/lib/python3/dist-packages/swh/storage/replay.py", line 146, in _insert_objects
2021-04-08T09:13:26.879134735Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |     method(model_objs)
2021-04-08T09:13:26.879137720Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |   File "/usr/lib/python3/dist-packages/swh/core/api/__init__.py", line 181, in meth_
2021-04-08T09:13:26.879141043Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |     return self.post(meth._endpoint_path, post_data)
2021-04-08T09:13:26.879144217Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |   File "/usr/lib/python3/dist-packages/swh/core/api/__init__.py", line 278, in post
2021-04-08T09:13:26.879147302Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |     return self._decode_response(response)
2021-04-08T09:13:26.879151387Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |   File "/usr/lib/python3/dist-packages/swh/core/api/__init__.py", line 354, in _decode_response
2021-04-08T09:13:26.879154636Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |     self.raise_for_status(response)
2021-04-08T09:13:26.879157609Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |   File "/usr/lib/python3/dist-packages/swh/storage/api/client.py", line 29, in raise_for_status
2021-04-08T09:13:26.879160885Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |     super().raise_for_status(response)
2021-04-08T09:13:26.879164166Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |   File "/usr/lib/python3/dist-packages/swh/core/api/__init__.py", line 344, in raise_for_status
2021-04-08T09:13:26.879167511Z swh_graph-replayer.1.l4qqau7nbpvm@libra    |     raise exception from None
2021-04-08T09:13:26.879171188Z swh_graph-replayer.1.l4qqau7nbpvm@libra    | swh.core.api.RemoteException: <RemoteException 500 AdminShutdown: ['terminating connection due to administrator command\nserver closed the connection unexpectedly\n\tThis probably means the server terminated abnormally\n\tbefore or while processing the request.\n']>