search

woodpecker-ci / woodpecker

Woodpecker is a simple, yet powerful CI/CD engine with great extensibility.
https://woodpecker-ci.org
Apache License 2.0
4.2k stars 364 forks source link

SSH runner does not execute, it just seems to disconnect #1524

Closed thedjnK closed 11 months ago

thedjnK commented 1 year ago

Component

agent

Describe the bug

With the changes made as described in https://github.com/woodpecker-ci/woodpecker/issues/1523 by shifting some lines down The SSH agent starts and connects but then seems unable to do anything, journal logs on agent system:

 woodpecker-agent[224863]: {"level":"debug","repo":"myuser/ci-test2","pipeline":"9","id":"169","time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/agent/runner.go:97","message":"received execution"}
 woodpecker-agent[224863]: {"level":"debug","repo":"myuser/ci-test2","pipeline":"9","id":"169","time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/agent/runner.go:111","message":"listen for cancel signal"}
 woodpecker-agent[224863]: {"level":"debug","ID":"169","Repo":"myuser/ci-test2","Pipeline":"9","time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/pipeline/pipeline.go:75","message":"Executing 2 stages, in order of:"}
 woodpecker-agent[224863]: {"level":"debug","ID":"169","Repo":"myuser/ci-test2","Pipeline":"9","Stage":"wp_0_2276890056050444553_clone","Steps":"wp_0_2276890056050444553_clone","time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/pipeline/pipeline.go:85","message":"stage"}
 woodpecker-agent[224863]: {"level":"debug","ID":"169","Repo":"myuser/ci-test2","Pipeline":"9","Stage":"wp_0_2276890056050444553_stage_0","Steps":"wp_0_2276890056050444553_step_0","time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/pipeline/pipeline.go:85","message":"stage"}
 woodpecker-agent[224863]: {"level":"debug","ID":"169","Repo":"myuser/ci-test2","Pipeline":"9","Step":"wp_0_2276890056050444553_clone","time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/pipeline/pipeline.go:157","message":"Prepare"}
 woodpecker-agent[224863]: {"level":"debug","repo":"myuser/ci-test2","pipeline":"9","id":"169","image":"docker.io/woodpeckerci/plugin-git:2.0","stage":"clone","exit_code":0,"exited":false,"time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/agent/tracer.go:51","message":"update step status"}
 woodpecker-agent[224863]: {"level":"debug","repo":"myuser/ci-test2","pipeline":"9","id":"169","image":"docker.io/woodpeckerci/plugin-git:2.0","stage":"clone","exit_code":0,"exited":false,"time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/agent/tracer.go:59","message":"update step status complete"}
 woodpecker-agent[224863]: {"level":"debug","ID":"169","Repo":"myuser/ci-test2","Pipeline":"9","Step":"wp_0_2276890056050444553_clone","time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/pipeline/pipeline.go:184","message":"Executing"}
 woodpecker-agent[224863]: {"level":"debug","ID":"169","Repo":"myuser/ci-test2","Pipeline":"9","Step":"wp_0_2276890056050444553_clone","time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/pipeline/pipeline.go:190","message":"Complete"}
 woodpecker-agent[224863]: {"level":"debug","repo":"myuser/ci-test2","pipeline":"9","id":"169","image":"docker.io/woodpeckerci/plugin-git:2.0","stage":"clone","time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/agent/logger.go:53","message":"log stream opened"}
 woodpecker-agent[224863]: {"level":"debug","repo":"myuser/ci-test2","pipeline":"9","id":"169","image":"docker.io/woodpeckerci/plugin-git:2.0","stage":"clone","time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/agent/logger.go:61","message":"log stream copied"}
 woodpecker-agent[224863]: {"level":"debug","repo":"myuser/ci-test2","pipeline":"9","id":"169","image":"docker.io/woodpeckerci/plugin-git:2.0","stage":"clone","time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/agent/logger.go:77","message":"log stream uploading"}
 woodpecker-agent[224863]: {"level":"debug","repo":"myuser/ci-test2","pipeline":"9","id":"169","image":"docker.io/woodpeckerci/plugin-git:2.0","stage":"clone","time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/agent/logger.go:81","message":"log stream upload complete"}
 woodpecker-agent[224863]: {"level":"debug","repo":"myuser/ci-test2","pipeline":"9","id":"169","image":"docker.io/woodpeckerci/plugin-git:2.0","stage":"clone","time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/agent/logger.go:85","message":"log stream closed"}
 woodpecker-agent[224863]: {"level":"debug","repo":"myuser/ci-test2","pipeline":"9","id":"169","image":"docker.io/woodpeckerci/plugin-git:2.0","stage":"clone","error":"read tcp 192.168.5.100:54050->192.168.5.32:22: use of closed network connection","exit_code":126,"exited":true,"time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/agent/tracer.go:51","message":"update step status"}
 woodpecker-agent[224863]: {"level":"debug","repo":"myuser/ci-test2","pipeline":"9","id":"169","image":"docker.io/woodpeckerci/plugin-git:2.0","stage":"clone","error":"read tcp 192.168.5.100:54050->192.168.5.32:22: use of closed network connection","exit_code":126,"exited":true,"time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/agent/tracer.go:59","message":"update step status complete"}
 woodpecker-agent[224863]: {"level":"debug","ID":"169","Repo":"myuser/ci-test2","Pipeline":"9","Step":"wp_0_2276890056050444553_step_0","time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/pipeline/pipeline.go:157","message":"Prepare"}
 woodpecker-agent[224863]: {"level":"debug","ID":"169","Repo":"myuser/ci-test2","Pipeline":"9","Step":"wp_0_2276890056050444553_step_0","error":"read tcp 192.168.5.100:54050->192.168.5.32:22: use of closed network connection","time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/pipeline/pipeline.go:164","message":"Skipped due to OnFailure=false"}
 woodpecker-agent[224863]: {"level":"error","ID":"169","Repo":"myuser/ci-test2","Pipeline":"9","error":"read tcp 192.168.5.100:54050->192.168.5.32:22: use of closed network connection","time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/pipeline/pipeline.go:90","message":"could not destroy engine"}
 woodpecker-agent[224863]: {"level":"debug","repo":"myuser/ci-test2","pipeline":"9","id":"169","error":"read tcp 192.168.5.100:54050->192.168.5.32:22: use of closed network connection","exit_code":1,"canceled":false,"time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/agent/runner.go:185","message":"pipeline complete"}
 woodpecker-agent[224863]: {"level":"debug","repo":"myuser/ci-test2","pipeline":"9","id":"169","time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/agent/runner.go:187","message":"uploading logs"}
 woodpecker-agent[224863]: {"level":"debug","repo":"myuser/ci-test2","pipeline":"9","id":"169","time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/agent/runner.go:189","message":"uploading logs complete"}
 woodpecker-agent[224863]: {"level":"debug","repo":"myuser/ci-test2","pipeline":"9","id":"169","error":"read tcp 192.168.5.100:54050->192.168.5.32:22: use of closed network connection","exit_code":1,"time":"2023-01-03T22:30:44Z","caller":"github.com/woodpecker-ci/woodpecker/agent/runner.go:194","message":"updating pipeline status"}

Woodpecker log shows only this in red:

Execution errorread tcp 192.168.5.100:54050->192.168.5.32:22: use of closed network connection

SSH server journal shows this:

 dbus-daemon[652]: [system] Activating via systemd: service name='org.freedesktop.home1' unit='dbus-org.freedesktop.home1.service' requested by ':1.68' (uid=0 pid=14585 comm="sshd: *** [priv]")
 dbus-daemon[652]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.home1.service': Unit dbus-org.freedesktop.home1.service not found.
 sshd[14585]: pam_systemd_home(sshd:auth): systemd-homed is not available: Unit dbus-org.freedesktop.home1.service not found.
 audit[14585]: USER_AUTH pid=14585 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_shells,pam_faillock,pam_permit,pam_faillock acct="***" exe="/usr/bin/sshd" hostname=192.168.5.100 addr=192.168.5.100 terminal=ssh res=success'
 kernel: audit: type=1100 audit(1672785409.284:378): pid=14585 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_shells,pam_faillock,pam_permit,pam_faillock acct="***" exe="/usr/bin/sshd" hostname=192.168.5.100 addr=192.168.5.100 terminal=ssh res=success'
 audit[14585]: USER_ACCT pid=14585 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_permit,pam_time acct="***" exe="/usr/bin/sshd" hostname=192.168.5.100 addr=192.168.5.100 terminal=ssh res=success'
 sshd[14585]: Accepted password for *** from 192.168.5.100 port 33788 ssh2
 audit[14585]: CRED_ACQ pid=14585 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_faillock acct="***" exe="/usr/bin/sshd" hostname=192.168.5.100 addr=192.168.5.100 terminal=ssh res=success'
 audit[14585]: SYSCALL arch=c000003e syscall=1 success=yes exit=4 a0=3 a1=7ffd03430540 a2=4 a3=7ffd03430254 items=0 ppid=719 pid=14585 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=31 comm="sshd" exe="/usr/bin/sshd" key=(null)
 audit: PROCTITLE proctitle=737368643A20646973636F7264205B707269765D
 sshd[14585]: pam_unix(sshd:session): session opened for user ***(uid=1000) by (uid=0)
 kernel: audit: type=1101 audit(1672785409.290:379): pid=14585 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_permit,pam_time acct="***" exe="/usr/bin/sshd" hostname=192.168.5.100 addr=192.168.5.100 terminal=ssh res=success'
 kernel: audit: type=1103 audit(1672785409.290:380): pid=14585 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_faillock acct="***" exe="/usr/bin/sshd" hostname=192.168.5.100 addr=192.168.5.100 terminal=ssh res=success'
 kernel: audit: type=1006 audit(1672785409.290:381): pid=14585 uid=0 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=31 res=1
 kernel: audit: type=1300 audit(1672785409.290:381): arch=c000003e syscall=1 success=yes exit=4 a0=3 a1=7ffd03430540 a2=4 a3=7ffd03430254 items=0 ppid=719 pid=14585 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=31 comm="sshd" exe="/usr/bin/sshd" key=(null)
 kernel: audit: type=1327 audit(1672785409.290:381): proctitle=737368643A20646973636F7264205B707269765D
 systemd-logind[659]: New session 31 of user ***.
-- Subject: A new session 31 has been created for user ***
-- Defined-By: systemd
-- Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- Documentation: sd-login(3)
--
-- A new session with the ID 31 has been created for the user ***.
--
-- The leading process of the session is 14585.
 systemd[1]: Started Session 31 of User ***.
-- Subject: A start job for unit session-31.scope has finished successfully
-- Defined-By: systemd
-- Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- A start job for unit session-31.scope has finished successfully.
--
-- The job identifier is 2931.
 audit[14585]: USER_START pid=14585 uid=0 auid=1000 ses=31 msg='op=PAM:session_open grantors=pam_loginuid,pam_keyinit,pam_systemd_home,pam_limits,pam_unix,pam_permit,pam_mail,pam_systemd,pam_env acct="***" exe="/usr/bin/sshd" hostname=192.168.5.100 addr=192.168.5.100 terminal=ssh res=success'
 audit[14587]: CRED_ACQ pid=14587 uid=0 auid=1000 ses=31 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_faillock acct="***" exe="/usr/bin/sshd" hostname=192.168.5.100 addr=192.168.5.100 terminal=ssh res=success'
 kernel: audit: type=1105 audit(1672785409.327:382): pid=14585 uid=0 auid=1000 ses=31 msg='op=PAM:session_open grantors=pam_loginuid,pam_keyinit,pam_systemd_home,pam_limits,pam_unix,pam_permit,pam_mail,pam_systemd,pam_env acct="***" exe="/usr/bin/sshd" hostname=192.168.5.100 addr=192.168.5.100 terminal=ssh res=success'
 kernel: audit: type=1103 audit(1672785409.327:383): pid=14587 uid=0 auid=1000 ses=31 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_faillock acct="***" exe="/usr/bin/sshd" hostname=192.168.5.100 addr=192.168.5.100 terminal=ssh res=success'
 sshd[14585]: pam_unix(sshd:session): session closed for user ***
 audit[14585]: USER_END pid=14585 uid=0 auid=1000 ses=31 msg='op=PAM:session_close grantors=pam_loginuid,pam_keyinit,pam_systemd_home,pam_limits,pam_unix,pam_permit,pam_mail,pam_systemd,pam_env acct="***" exe="/usr/bin/sshd" hostname=192.168.5.100 addr=192.168.5.100 terminal=ssh res=success'
 audit[14585]: CRED_DISP pid=14585 uid=0 auid=1000 ses=31 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_faillock acct="***" exe="/usr/bin/sshd" hostname=192.168.5.100 addr=192.168.5.100 terminal=ssh res=success'
 kernel: audit: type=1106 audit(1672785409.390:384): pid=14585 uid=0 auid=1000 ses=31 msg='op=PAM:session_close grantors=pam_loginuid,pam_keyinit,pam_systemd_home,pam_limits,pam_unix,pam_permit,pam_mail,pam_systemd,pam_env acct="***" exe="/usr/bin/sshd" hostname=192.168.5.100 addr=192.168.5.100 terminal=ssh res=success'
 kernel: audit: type=1104 audit(1672785409.390:385): pid=14585 uid=0 auid=1000 ses=31 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_faillock acct="***" exe="/usr/bin/sshd" hostname=192.168.5.100 addr=192.168.5.100 terminal=ssh res=success'
 systemd[1]: session-31.scope: Deactivated successfully.
-- Subject: Unit succeeded
-- Defined-By: systemd
-- Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- The unit session-31.scope has successfully entered the 'dead' state.
 systemd-logind[659]: Session 31 logged out. Waiting for processes to exit.
 systemd-logind[659]: Removed session 31.
-- Subject: Session 31 has been terminated
-- Defined-By: systemd
-- Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- Documentation: sd-login(3)
--
-- A session with the ID 31 has been terminated.

Actually whilst getting the debug info for this bug it seems it also sometimes shows this error instead:

woodpecker-agent[225222]: {"level":"error","error":"rpc error: code = Unknown desc = Step finished with exitcode 1, Process exited with status 127","time":"2023-01-03T22:35:25Z","caller":"github.com/woodpecker-ci/woodpecker/pipeline/rpc/client_grpc.go:97","message":"grpc error: wait(): code: Unknown: rpc error: code = Unknown desc = Step finished with exitcode 1, Process exited with status 127"}

I've tried both ssh authentication using username and password and authenticated key - same issue.

System Info

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

(git commit ID for build is the latest, f1e9c8416dafb6c236694765d9f7dde9620592da, built on arch linux by using the woodpecker-agent-git aur package)

Additional context

No response

Validations

anbraten commented 11 months ago

The ssh runner will be removed by the next release