likyh commented on issue #4486:
URL:
https://github.com/apache/incubator-devlake/issues/4486#issuecomment-1448218352
Error start from here. It seems starrocks run parallel and got error
```
{"log":"time=\"2023-02-28 11:12:09\" level=info msg=\" [pipeline service]
[pipeline #4125] [task #4314] [LoadData] load sprint_summary to starrocks
success\"\n","stream":"stdout","time":"2023-02-28T11:12:09.985188818Z"}
{"log":"time=\"2023-02-28 11:12:09\" level=info msg=\" [pipeline service]
[pipeline #4125] [task #4314] finished step: 1 /
1\"\n","stream":"stdout","time":"2023-02-28T11:12:09.985914871Z"}
{"log":"time=\"2023-02-28 11:12:09\" level=info
msg=\"\u001b[31;1m/go/pkg/mod/gorm.io/[email protected]/callbacks.go:134
\u001b[35;1mERROR: could not serialize access due to concurrent update
(SQLSTATE 40001)\n","stream":"stdout","time":"2023-02-28T11:12:09.987364882Z"}
{"log":"\u001b[0m\u001b[33m[1.209ms] \u001b[34;1m[rows:0]\u001b[0m UPDATE
\"_devlake_tasks\" SET \"progress\"=1.000000,\"updated_at\"='2023-02-28
11:12:09.985' WHERE \"id\" =
4314\"\n","stream":"stdout","time":"2023-02-28T11:12:09.987375653Z"}
{"log":"time=\"2023-02-28 11:12:09\" level=error msg=\"failed to update
progress\n","stream":"stdout","time":"2023-02-28T11:12:09.98737968Z"}
{"log":"\u0009caused by: ERROR: could not serialize access due to concurrent
update (SQLSTATE
40001)\n","stream":"stdout","time":"2023-02-28T11:12:09.98738296Z"}
{"log":"\u0009Wraps: (2) ERROR: could not serialize access due to concurrent
update (SQLSTATE
40001)\n","stream":"stdout","time":"2023-02-28T11:12:09.987385951Z"}
{"log":"\u0009Error types: (1) *hintdetail.withDetail (2)
*pgconn.PgError\"\n","stream":"stdout","time":"2023-02-28T11:12:09.987389076Z"}
{"log":"time=\"2023-02-28 11:12:09\" level=info msg=\" [task service] run
task #4315 in background
\"\n","stream":"stdout","time":"2023-02-28T11:12:09.989749658Z"}
{"log":"time=\"2023-02-28 11:12:09\" level=info msg=\" [pipeline service]
[pipeline #4125] [task #4315] start executing task:
4315\"\n","stream":"stdout","time":"2023-02-28T11:12:09.990781713Z"}
```
但同时又因为似乎一个错误，会让这个数据库连接后续的查询都报错，同时RunPipelineInQueue时，查询出错也会开始运行pipeline，就会造成部分404的错误。
And another 2 issues found here. It seems this db connection will always
raise error after the first error. And then, the pipeline will run unexpect
when err != nil in RunPipelineInQueue. It cause a part of 404 error in
`RunPipelineInQueue`.
```
{"log":"time=\"2023-02-28 11:12:28\" level=info msg=\" [pipeline service]
[pipeline #4125] [task #4315] [DbtConverter] The DBT project run
ended.\"\n","stream":"stdout","time":"2023-02-28T11:12:28.45354534Z"}
{"log":"time=\"2023-02-28 11:12:28\" level=info msg=\" [pipeline service]
[pipeline #4125] [task #4315] finished step: 2 /
2\"\n","stream":"stdout","time":"2023-02-28T11:12:28.453985982Z"}
{"log":"time=\"2023-02-28 11:12:28\" level=info
msg=\"\u001b[31;1m/go/pkg/mod/gorm.io/[email protected]/callbacks.go:134
\u001b[35;1mERROR: current transaction is aborted, commands ignored until end
of transaction block (SQLSTATE
25P02)\n","stream":"stdout","time":"2023-02-28T11:12:28.454333818Z"}
{"log":"\u001b[0m\u001b[33m[0.263ms] \u001b[34;1m[rows:0]\u001b[0m UPDATE
\"_devlake_tasks\" SET \"finished_at\"='2023-02-28
11:12:28.453',\"message\"='',\"spent_seconds\"=19,\"status\"='TASK_COMPLETED',\"updated_at\"='2023-02-28
11:12:28.453' WHERE \"id\" =
4315\"\n","stream":"stdout","time":"2023-02-28T11:12:28.454341779Z"}
{"log":"time=\"2023-02-28 11:12:28\" level=error msg=\" [pipeline service]
[pipeline #4125] [task #4315] failed to finalize task status into db (task
succeeded)\n","stream":"stdout","time":"2023-02-28T11:12:28.454388069Z"}
{"log":"\u0009caused by: ERROR: current transaction is aborted, commands
ignored until end of transaction block (SQLSTATE
25P02)\n","stream":"stdout","time":"2023-02-28T11:12:28.454395434Z"}
{"log":"\u0009Wraps: (2) ERROR: current transaction is aborted, commands
ignored until end of transaction block (SQLSTATE
25P02)\n","stream":"stdout","time":"2023-02-28T11:12:28.454399338Z"}
{"log":"\u0009Error types: (1) *hintdetail.withDetail (2)
*pgconn.PgError\"\n","stream":"stdout","time":"2023-02-28T11:12:28.454402926Z"}
{"log":"time=\"2023-02-28 11:12:28\" level=info msg=\" [pipeline service]
[pipeline #4125] pipeline finished in 2611879 ms:
\u003cnil\u003e\"\n","stream":"stdout","time":"2023-02-28T11:12:28.454710332Z"}
{"log":"time=\"2023-02-28 11:12:28\" level=error msg=\" [pipeline service]
compute pipeline status
failed\n","stream":"stdout","time":"2023-02-28T11:12:28.456164056Z"}
{"log":"\u0009caused by: unexpected status, did you call
computePipelineStatus at a wrong
timing?\"\n","stream":"stdout","time":"2023-02-28T11:12:28.456172624Z"}
{"log":"time=\"2023-02-28 11:12:28\" level=error msg=\" [pipeline service]
failed to run pipeline
4125\n","stream":"stdout","time":"2023-02-28T11:12:28.456176397Z"}
{"log":"\u0009caused by: unexpected status, did you call
computePipelineStatus at a wrong
timing?\"\n","stream":"stdout","time":"2023-02-28T11:12:28.456180121Z"}
{"log":"time=\"2023-02-28 11:12:28\" level=info msg=\" [pipeline service]
finish pipeline #4125, now runningParallelLabels is
[]\"\n","stream":"stdout","time":"2023-02-28T11:12:28.456184881Z"}
{"log":"time=\"2023-02-28 11:12:29\" level=info msg=\" [pipeline service]
acquire lock\"\n","stream":"stdout","time":"2023-02-28T11:12:29.393738136Z"}
{"log":"time=\"2023-02-28 11:12:29\" level=info msg=\" [pipeline service]
get lock and wait next
pipeline\"\n","stream":"stdout","time":"2023-02-28T11:12:29.393760778Z"}
{"log":"time=\"2023-02-28 11:12:29\" level=info msg=\" [pipeline service]
run pipeline, 4126, now running runningParallelLabels are
[parallel/lake_data_sync]\"\n","stream":"stdout","time":"2023-02-28T11:12:29.393802505Z"}
{"log":"time=\"2023-02-28 11:12:29\" level=info
msg=\"\u001b[31;1m/go/pkg/mod/gorm.io/[email protected]/callbacks.go:134
\u001b[35;1mERROR: current transaction is aborted, commands ignored until end
of transaction block (SQLSTATE
25P02)\n","stream":"stdout","time":"2023-02-28T11:12:29.394136196Z"}
{"log":"\u001b[0m\u001b[33m[0.249ms] \u001b[34;1m[rows:0]\u001b[0m SELECT *
FROM \"_devlake_pipelines\" WHERE id = 4126 ORDER BY
\"_devlake_pipelines\".\"id\" LIMIT
1\"\n","stream":"stdout","time":"2023-02-28T11:12:29.39414404Z"}
{"log":"time=\"2023-02-28 11:12:29\" level=error msg=\" [pipeline service]
failed to run pipeline
4126\n","stream":"stdout","time":"2023-02-28T11:12:29.394170689Z"}
{"log":"\u0009caused by: error getting the pipeline from database
(500)\n","stream":"stdout","time":"2023-02-28T11:12:29.394194042Z"}
{"log":"\u0009Wraps: (2) ERROR: current transaction is aborted, commands
ignored until end of transaction block (SQLSTATE
25P02)\n","stream":"stdout","time":"2023-02-28T11:12:29.394198765Z"}
{"log":"\u0009Wraps: (3) ERROR: current transaction is aborted, commands
ignored until end of transaction block (SQLSTATE
25P02)\n","stream":"stdout","time":"2023-02-28T11:12:29.394202444Z"}
{"log":"\u0009Error types: (1) *hintdetail.withDetail (2)
*hintdetail.withDetail (3)
*pgconn.PgError\"\n","stream":"stdout","time":"2023-02-28T11:12:29.394206222Z"}
{"log":"time=\"2023-02-28 11:12:29\" level=info msg=\" [pipeline service]
finish pipeline #4126, now runningParallelLabels is
[]\"\n","stream":"stdout","time":"2023-02-28T11:12:29.394210156Z"}
```
Other 404 raised when querying pipelines after they was created. Maybe it
was causeed by the pipeline not creating success in transcation. Like pipeline
4131:
```
{"log":"time=\"2023-02-28 11:40:00\" level=info msg=\" [blueprint] Run new
cron job successfully, pipeline id:
4131\"\n","stream":"stdout","time":"2023-02-28T11:40:00.006176123Z"}
{"log":"time=\"2023-02-28 11:40:00\" level=info msg=\" [pipeline service]
acquire lock\"\n","stream":"stdout","time":"2023-02-28T11:40:00.719512261Z"}
{"log":"time=\"2023-02-28 11:40:00\" level=info msg=\" [pipeline service]
get lock and wait next
pipeline\"\n","stream":"stdout","time":"2023-02-28T11:40:00.719533655Z"}
{"log":"time=\"2023-02-28 11:40:00\" level=info msg=\" [pipeline service]
run pipeline, 4131, now running runningParallelLabels are
[parallel/lake_data_sync
parallel/ee_dimension_sync]\"\n","stream":"stdout","time":"2023-02-28T11:40:00.719537648Z"}
{"log":"time=\"2023-02-28 11:40:00\" level=error msg=\" [pipeline service]
failed to run pipeline
4131\n","stream":"stdout","time":"2023-02-28T11:40:00.719996726Z"}
{"log":"\u0009caused by: pipeline not found
(404)\"\n","stream":"stdout","time":"2023-02-28T11:40:00.720018266Z"}
{"log":"time=\"2023-02-28 11:40:00\" level=info msg=\" [pipeline service]
finish pipeline #4131, now runningParallelLabels is
[parallel/lake_data_sync]\"\n","stream":"stdout","time":"2023-02-28T11:40:00.72002179Z"}
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
