Server crashes after job runs #1322

TonyGiorgio · 2022-10-22T17:23:48Z

Component

server

Describe the bug

After I run a simple rust test job, the server crashes because of Write called after Handler finished.

This is a new instance, trying to follow the docs as much as possible, on a digital ocean docker container instance.

System Info

version:

source	"https://github.com/woodpecker-ci/woodpecker"
version	"0.15.5"

docker-compose:

version: '3'

services:
  woodpecker-server:
    image: woodpeckerci/woodpecker-server:latest
    restart: always
    ports:
      - 8000:8000
      - 9000:9000
      - 80:80
      - 443:443
    volumes:
      - woodpecker-server-data:/var/lib/woodpecker/
    environment:
      - WOODPECKER_OPEN=true
      - WOODPECKER_HOST=https://omitted
      - WOODPECKER_AGENT_SECRET=omitted
      - WOODPECKER_GITEA=true
      - WOODPECKER_GITEA_URL=omitted
      - WOODPECKER_GITEA_CLIENT=omitted
      - WOODPECKER_GITEA_SECRET=omitted
      - WOODPECKER_LETS_ENCRYPT=true

  woodpecker-agent:
    image: woodpeckerci/woodpecker-agent:latest
    command: agent
    restart: always
    depends_on:
      - woodpecker-server
    volumes:
      - /var/run/docker.sock:/var/run/docker.sock
    environment:
      - WOODPECKER_SERVER=woodpecker-server:9000
      - WOODPECKER_AGENT_SECRET=omitted
      - WOODPECKER_MAX_PROCS=4

volumes:
  woodpecker-server-data:

.woodpecker.yml:

pipeline:
  test:
    image: rust
    commands:
      - cd rust-folder
      - cargo test

Additional context

root@docker-ubuntu-c-2-4gib-nyc1-01:~# docker-compose up -d                                                                                                                                   
Recreating root_woodpecker-server_1 ... done                                                                                                                                                  
Recreating root_woodpecker-agent_1  ... done                                                                                                                                                  
root@docker-ubuntu-c-2-4gib-nyc1-01:~# docker-compose logs -f                                                                                                                                 
Attaching to root_woodpecker-agent_1, root_woodpecker-server_1                                                                                                                                
woodpecker-server_1  | {"time":"2022-10-22T17:10:12Z","message":"LogLevel = warn"}                                                                                                            
woodpecker-agent_1   | {"level":"error","error":"io: read/write on closed pipe","time":"2022-10-22T17:10:42Z","message":"copy limited logStream part"}                                        
woodpecker-agent_1   | {"level":"error","error":"rpc error: code = Unavailable desc = closing transport due to: connection error: desc = \"error reading from server: EOF\", received prior go
away: code: ENHANCE_YOUR_CALM, debug data: \"too_many_pings\"","time":"2022-10-22T17:11:13Z","message":"grpc error: wait(): code: Unavailable: rpc error: code = Unavailable desc = closing tr
ansport due to: connection error: desc = \"error reading from server: EOF\", received prior goaway: code: ENHANCE_YOUR_CALM, debug data: \"too_many_pings\""}                                 
woodpecker-agent_1   | {"level":"error","error":"io: read/write on closed pipe","time":"2022-10-22T17:12:47Z","message":"copy limited logStream part"}
woodpecker-agent_1   | {"level":"error","error":"Error response from daemon: Cannot kill container: 0_1428886657477204797_clone: Container acdb5d89928689be75e01b1dee62be669f5d36332a0dddc10bf
fd0710f9e3972 is not running","time":"2022-10-22T17:12:47Z","message":"could not kill container '0_1428886657477204797_clone'"}
woodpecker-agent_1   | {"level":"error","error":"Error response from daemon: Cannot kill container: 0_1428886657477204797_step_0: Container cf3fa3e9941773b78245901ae8c3e69613851625d5ea4f6ca0
0ab13d8cc83a14 is not running","time":"2022-10-22T17:12:47Z","message":"could not kill container '0_1428886657477204797_stage_0'"}
woodpecker-server_1  | panic: Write called after Handler finished
woodpecker-server_1  | 
woodpecker-server_1  | goroutine 189 [running]:
woodpecker-server_1  | net/http.(*http2responseWriter).write(0xc00045d500?, 0xc000678688?, {0x0?, 0xf93260?, 0x102a820?}, {0x10e7646?, 0xc0000120d8?})
woodpecker-server_1  |  /usr/local/go/src/net/http/h2_bundle.go:6431 +0x150
woodpecker-server_1  | net/http.(*http2responseWriter).WriteString(0xc0006786c0?, {0x10e7646?, 0xc0000120d8?})
woodpecker-server_1  |  /usr/local/go/src/net/http/h2_bundle.go:6424 +0x2e
woodpecker-server_1  | io.WriteString({0x7fd7d37bed98, 0xc0000120d8}, {0x10e7646, 0x18})
woodpecker-server_1  |  /usr/local/go/src/io/io.go:312 +0x5d
woodpecker-server_1  | github.com/gin-gonic/gin.(*responseWriter).WriteString(0xc0006d8400, {0x10e7646, 0x18})
woodpecker-server_1  |  /woodpecker/src/github.com/woodpecker-ci/woodpecker/vendor/github.com/gin-gonic/gin/response_writer.go:85 +0x7b
woodpecker-server_1  | io.WriteString({0x7fd7d3fefa18, 0xc0006d8400}, {0x10e7646, 0x18})
woodpecker-server_1  |  /usr/local/go/src/io/io.go:312 +0x5d
woodpecker-server_1  | github.com/woodpecker-ci/woodpecker/server/api.LogStreamSSE.func2()
woodpecker-server_1  |  /woodpecker/src/github.com/woodpecker-ci/woodpecker/server/api/stream.go:199 +0x192
woodpecker-server_1  | created by github.com/woodpecker-ci/woodpecker/server/api.LogStreamSSE
woodpecker-server_1  |  /woodpecker/src/github.com/woodpecker-ci/woodpecker/server/api/stream.go:179 +0x59b
woodpecker-agent_1   | {"level":"error","error":"rpc error: code = Unavailable desc = error reading from server: EOF","time":"2022-10-22T17:12:48Z","message":"grpc error: wait(): code: Unava
ilable: rpc error: code = Unavailable desc = error reading from server: EOF"}

Validations

Read the Contributing Guidelines.
Read the docs.
Check that there isn't already an issue that reports the same bug to avoid creating a duplicate.
Check that this is a concrete bug. For Q&A join our Discord Chat Server or the Matrix room.

The text was updated successfully, but these errors were encountered:

qwerty287 · 2022-10-22T19:09:30Z

Did everything work in the backend? Means does your pipeline ran correctly?

This looks like something you can actually ignore if everything works. I can look for a solution though.

TonyGiorgio · 2022-10-22T19:29:18Z

Okay so yeah with the restart: always docker-compose configuration, it does end up being okay and it says the job succeeds. I think the website just crashes for a few seconds in the meantime?

qwerty287 · 2022-10-23T06:37:05Z

This crash only affects a HTP request. If it crashes within responding to a request, it shouldn't crash completely, but print the message. Did it really crash or is there just this message? ("Crash" means it exits after printing the stacktrace)

6543 · 2022-10-23T10:45:25Z

Is it posible to test next ?

PS: please backup db as downgrade is not posible

TonyGiorgio · 2022-10-24T14:15:26Z

Did it really crash or is there just this message?

It really crashed. If I didn't have the docker restart always up, the webpage would also be down and the agent is in a loop trying to connect to the server.

Is it posible to test next ?

Test what?

qwerty287 · 2022-10-24T14:58:20Z

Test the next version of woodpecker which is the latest master branch. You can just update the docker tag to next.

sb-child · 2022-12-12T13:29:12Z

Hello, I also meet this problem:
server logs:

wpconf-woodpecker-server-1  | 12:47PM DBG woodpecker/src/github.com/woodpecker-ci/woodpecker/server/router/middleware/logger.go:45 > ip=10.7.0.1 latency=2.74847 method=GET path=/api/repos/sbchild/mirror-bot/logs/66/2 status=200 user-agent="Mozilla/5.0 (X11; Linux x86_64; rv:107.0) Gecko/20100101 Firefox/107.0"
wpconf-woodpecker-server-1  | 12:47PM TRC woodpecker/src/github.com/woodpecker-ci/woodpecker/server/router/router.go:38 > [GET] /stream/logs/sbchild/mirror-bot/65/1
wpconf-woodpecker-server-1  | 12:47PM DBG woodpecker/src/github.com/woodpecker-ci/woodpecker/server/router/middleware/session/repo.go:132 > sbchild granted &{UserID:1 RepoID:29 Repo:<nil> Pull:true Push:true Admin:true Synced:1670847533 Created:1670614231 Updated:1670847533} permission to sbchild/mirror-bot
wpconf-woodpecker-server-1  | 12:47PM DBG woodpecker/src/github.com/woodpecker-ci/woodpecker/server/api/stream.go:172 > log stream: connection opened
wpconf-woodpecker-server-1  | 12:47PM ERR woodpecker/src/github.com/woodpecker-ci/woodpecker/server/api/stream.go:197 > tail of logs failed error="stream: not found"
wpconf-woodpecker-server-1  | 12:47PM DBG woodpecker/src/github.com/woodpecker-ci/woodpecker/server/api/stream.go:177 > log stream: connection closed
wpconf-woodpecker-server-1  | 12:47PM DBG woodpecker/src/github.com/woodpecker-ci/woodpecker/server/router/middleware/logger.go:45 > ip=10.7.0.1 latency=3.968839 method=GET path=/stream/logs/sbchild/mirror-bot/65/1 status=200 user-agent="Mozilla/5.0 (X11; Linux x86_64; rv:107.0) Gecko/20100101 Firefox/107.0"
wpconf-woodpecker-server-1  | 12:47PM TRC woodpecker/src/github.com/woodpecker-ci/woodpecker/server/router/router.go:38 > [GET] /stream/logs/sbchild/mirror-bot/66/1
wpconf-woodpecker-server-1  | 12:47PM DBG woodpecker/src/github.com/woodpecker-ci/woodpecker/server/router/middleware/session/repo.go:132 > sbchild granted &{UserID:1 RepoID:29 Repo:<nil> Pull:true Push:true Admin:true Synced:1670847533 Created:1670614231 Updated:1670847533} permission to sbchild/mirror-bot
wpconf-woodpecker-server-1  | 12:47PM DBG woodpecker/src/github.com/woodpecker-ci/woodpecker/server/api/stream.go:172 > log stream: connection opened
wpconf-woodpecker-server-1  | 12:47PM TRC woodpecker/src/github.com/woodpecker-ci/woodpecker/server/api/stream.go:185 > pubsub subscribe recover return: <nil>
wpconf-woodpecker-server-1  | 12:47PM DBG woodpecker/src/github.com/woodpecker-ci/woodpecker/server/api/stream.go:177 > log stream: connection closed
wpconf-woodpecker-server-1  | 12:47PM DBG woodpecker/src/github.com/woodpecker-ci/woodpecker/server/router/middleware/logger.go:45 > ip=10.7.0.1 latency=399.464527 method=GET path=/stream/logs/sbchild/mirror-bot/66/1 status=200 user-agent="Mozilla/5.0 (X11; Linux x86_64; rv:107.0) Gecko/20100101 Firefox/107.0"
wpconf-woodpecker-server-1  | panic: Write called after Handler finished
wpconf-woodpecker-server-1  | 
wpconf-woodpecker-server-1  | goroutine 266 [running]:
wpconf-woodpecker-server-1  | net/http.(*http2responseWriter).write(0xc000080780?, 0xc00064fe88?, {0x0?, 0x1141600?, 0x11f2ac0?}, {0x12be30f?, 0xc0000124d0?})
wpconf-woodpecker-server-1  |   /usr/local/go/src/net/http/h2_bundle.go:6431 +0x150
wpconf-woodpecker-server-1  | net/http.(*http2responseWriter).WriteString(0xc00064fec0?, {0x12be30f?, 0xc0000124d0?})
wpconf-woodpecker-server-1  |   /usr/local/go/src/net/http/h2_bundle.go:6424 +0x2e
wpconf-woodpecker-server-1  | io.WriteString({0x7fd600b56c38, 0xc0000124d0}, {0x12be30f, 0x18})
wpconf-woodpecker-server-1  |   /usr/local/go/src/io/io.go:312 +0x5d
wpconf-woodpecker-server-1  | github.com/gin-gonic/gin.(*responseWriter).WriteString(0xc000755300, {0x12be30f, 0x18})
wpconf-woodpecker-server-1  |   /woodpecker/src/github.com/woodpecker-ci/woodpecker/vendor/github.com/gin-gonic/gin/response_writer.go:85 +0x7b
wpconf-woodpecker-server-1  | io.WriteString({0x7fd600af0a58, 0xc000755300}, {0x12be30f, 0x18})
wpconf-woodpecker-server-1  |   /usr/local/go/src/io/io.go:312 +0x5d
wpconf-woodpecker-server-1  | github.com/woodpecker-ci/woodpecker/server/api.LogStreamSSE.func2()
wpconf-woodpecker-server-1  |   /woodpecker/src/github.com/woodpecker-ci/woodpecker/server/api/stream.go:200 +0x192
wpconf-woodpecker-server-1  | created by github.com/woodpecker-ci/woodpecker/server/api.LogStreamSSE
wpconf-woodpecker-server-1  |   /woodpecker/src/github.com/woodpecker-ci/woodpecker/server/api/stream.go:180 +0x59b

Woodpecker version: next-a3f4f305

The panic may be caused after a pipeline outputs colored texts like this: echo -e "\033[0;31mtest\033[0m"

But after I tried to reproduce this problem, the problem went away by itself, even if I reverted the changes back to before.

My .woodpecker.yml looks like this:

pipeline:
  test:
    image: alpine
    commands:
      - ./print-some-colored-text.sh

print-some-colored-text.sh with execute permissions:

#!/bin/sh
echo -e "\033[0;31mtest\033[0m"

Can you try?

waldner · 2023-02-06T20:05:01Z

Can reproduce with high reliability with the following pipeline:

pipeline:
  run_tests:
    image: python:3.10
    commands:
      - echo -e "\033[0;31mtest1\033[0m"
      - echo -e "\033[0;32mtest2\033[0m"
      - echo -e "\033[0;33mtest3\033[0m"
      - echo -e "\033[0;34mtest4\033[0m"
      - echo -e "\033[0;35mtest5\033[0m"
      - echo -e "\033[0;36mtest6\033[0m"

server and agent version:

woodpecker-server   | {"level":"info","time":"2023-02-06T19:49:05Z","message":"Starting Woodpecker server with version 'next-fe97d37c'"}

EDIT: removing the escape sequences seems to fix it, however there are still warnings in the agent's log:

woodpecker-agent-1  | {"level":"error","error":"io: read/write on closed pipe","time":"2023-02-06T20:07:57Z","message":"copy limited logStream part"}
woodpecker-agent-1  | {"level":"error","error":"io: read/write on closed pipe","time":"2023-02-06T20:07:58Z","message":"copy limited logStream part"}

6543 · 2023-02-15T17:14:26Z

well it should not be possible to crash the server with any log output ...

6543 · 2023-03-16T03:53:23Z

@waldner I can not reproduce the issue at next-9c8c610c or next-54fe1c20

6543 · 2023-03-16T03:56:01Z

{"level":"error","error":"io: read/write on closed pipe

should be fixed by #1616 and is unrelated ...

6543 · 2023-06-06T12:30:21Z

Schould be fixed by #1802

TonyGiorgio added the pending:bug label Oct 22, 2022

qwerty287 added the feedback this needs feedback label Oct 27, 2022

6543 added bug Something isn't working server and removed pending:bug feedback this needs feedback labels Dec 23, 2022

6543 added this to the 1.0.0 milestone Dec 23, 2022

6543 closed this as completed Jun 6, 2023

6543 mentioned this issue Jun 6, 2023

Rework log streaming and related functions #1802

Merged

14 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Server crashes after job runs #1322

Server crashes after job runs #1322

TonyGiorgio commented Oct 22, 2022 •

edited

Loading

qwerty287 commented Oct 22, 2022

TonyGiorgio commented Oct 22, 2022

qwerty287 commented Oct 23, 2022 •

edited

Loading

6543 commented Oct 23, 2022

TonyGiorgio commented Oct 24, 2022

qwerty287 commented Oct 24, 2022

sb-child commented Dec 12, 2022

waldner commented Feb 6, 2023 •

edited

Loading

6543 commented Feb 15, 2023

6543 commented Mar 16, 2023

6543 commented Mar 16, 2023

6543 commented Jun 6, 2023

Server crashes after job runs #1322

Server crashes after job runs #1322

Comments

TonyGiorgio commented Oct 22, 2022 • edited Loading

Component

Describe the bug

System Info

Additional context

Validations

qwerty287 commented Oct 22, 2022

TonyGiorgio commented Oct 22, 2022

qwerty287 commented Oct 23, 2022 • edited Loading

6543 commented Oct 23, 2022

TonyGiorgio commented Oct 24, 2022

qwerty287 commented Oct 24, 2022

sb-child commented Dec 12, 2022

waldner commented Feb 6, 2023 • edited Loading

6543 commented Feb 15, 2023

6543 commented Mar 16, 2023

6543 commented Mar 16, 2023

6543 commented Jun 6, 2023

TonyGiorgio commented Oct 22, 2022 •

edited

Loading

qwerty287 commented Oct 23, 2022 •

edited

Loading

waldner commented Feb 6, 2023 •

edited

Loading