Final stage of pipeline deploying to Pantheon using image from quay.io Exceeds Build Time

[Mark Jovanovich]

I inherited a codebase designed and built by a professional 3rd party firm and am responsible for routine drupal updates. Codebase is in bitbucket, site is hosted on Pantheon.

I did my first branch/update/pull request, which triggered a pipeline to deploy to Pantheon. The pipeline times out (30 mins, set in .yml) on the final stage, "Deploy to Pantheon". The stage should have 5 steps but times out on the first step, "Build Setup", though the "build" tab shows "17s" next to it. The final line of code is 

"Images used:

build : quay.io/pantheon-public/build-tools-ci@sha256:46194163d4d308919f212a34e9fd8e9d348f0eb9cc548ab824f692e9e0dc0880

"

here is the complete output of the "docker" tab in pipelines:

cat: can't open '/proc/net/ip6_tables_names': No such file or directory

3

ip: can't find $TERMINUS_ENVice 'nf_tables'

4

lsmod: /proc/modules: No such file or directory

5

modprobe: can't change directory to '/lib/modules': No such file or directory

6

ip: can't find $TERMINUS_ENVice 'ip_tables'

7

lsmod: /proc/modules: No such file or directory

8

modprobe: can't change directory to '/lib/modules': No such file or directory

9

iptables v1.8.10 (legacy)

10

time="2024-07-25T19:43:59.903862066Z" level=info msg="Starting up"

11

time="2024-07-25T19:43:59.905154292Z" level=info msg="User namespaces: ID ranges will be mapped to subuid/subgid ranges of: dockremap"

12

time="2024-07-25T19:43:59.911748734Z" level=warning msg="Binding to IP address without --tlsverify is insecure and gives root access on this machine to everyone who has access to your network." host="tcp://0.0.0.0:2375"

13

time="2024-07-25T19:43:59.911794361Z" level=warning msg="Binding to an IP address, even on localhost, can also give access to scripts run in a browser. Be safe out there!" host="tcp://0.0.0.0:2375"

14

time="2024-07-25T19:44:00.911959106Z" level=warning msg="Binding to an IP address without --tlsverify is deprecated. Startup is intentionally being slowed down to show this message" host="tcp://0.0.0.0:2375"

15

time="2024-07-25T19:44:00.912037278Z" level=warning msg="Please consider generating tls certificates with client validation to prevent exposing unauthenticated root access to your network" host="tcp://0.0.0.0:2375"

16

time="2024-07-25T19:44:00.912053955Z" level=warning msg="You can override this by explicitly specifying '--tls=false' or '--tlsverify=false'" host="tcp://0.0.0.0:2375"

17

time="2024-07-25T19:44:00.912066052Z" level=warning msg="Support for listening on TCP without authentication or explicit intent to run without authentication will be removed in the next release" host="tcp://0.0.0.0:2375"

18

time="2024-07-25T19:44:15.917788674Z" level=info msg="containerd not running, starting managed containerd"

19

time="2024-07-25T19:44:15.921266079Z" level=info msg="started new containerd process" address=/var/run/docker/containerd/containerd.sock module=libcontainerd pid=43

20

time="2024-07-25T19:44:16.057568660Z" level=info msg="starting containerd" revision=7c3aca7a610df76212171d200ca3811ff6096eb8 version=v1.7.13

21

time="2024-07-25T19:44:16.097916995Z" level=info msg="loading plugin \"io.containerd.event.v1.exchange\"..." type=io.containerd.event.v1

22

time="2024-07-25T19:44:16.097987287Z" level=info msg="loading plugin \"io.containerd.internal.v1.opt\"..." type=io.containerd.internal.v1

23

time="2024-07-25T19:44:16.098050842Z" level=warning msg="failed to load plugin io.containerd.internal.v1.opt" error="mkdir /opt/containerd: read-only file system"

24

time="2024-07-25T19:44:16.098069629Z" level=info msg="loading plugin \"io.containerd.warning.v1.deprecations\"..." type=io.containerd.warning.v1

25

time="2024-07-25T19:44:16.098095875Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.blockfile\"..." type=io.containerd.snapshotter.v1

26

time="2024-07-25T19:44:16.098240396Z" level=info msg="skip loading plugin \"io.containerd.snapshotter.v1.blockfile\"..." error="no scratch file generator: skip plugin" type=io.containerd.snapshotter.v1

27

time="2024-07-25T19:44:16.098260869Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.$TERMINUS_ENVmapper\"..." type=io.containerd.snapshotter.v1

28

time="2024-07-25T19:44:16.098280389Z" level=warning msg="failed to load plugin io.containerd.snapshotter.v1.$TERMINUS_ENVmapper" error="$TERMINUS_ENVmapper not configured"

29

time="2024-07-25T19:44:16.098294677Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.native\"..." type=io.containerd.snapshotter.v1

30

time="2024-07-25T19:44:16.098427991Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.overlayfs\"..." type=io.containerd.snapshotter.v1

31

time="2024-07-25T19:44:16.098765302Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.aufs\"..." type=io.containerd.snapshotter.v1

32

time="2024-07-25T19:44:16.102928608Z" level=info msg="skip loading plugin \"io.containerd.snapshotter.v1.aufs\"..." error="aufs is not supported (modprobe aufs failed: exit status 1 \"ip: can't find $TERMINUS_ENVice 'aufs'\\nlsmod: /proc/modules: No such file or directory\\nmodprobe: can't change directory to '/lib/modules': No such file or directory\\n\"): skip plugin" type=io.containerd.snapshotter.v1

33

time="2024-07-25T19:44:16.102970282Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.zfs\"..." type=io.containerd.snapshotter.v1

34

time="2024-07-25T19:44:16.103238402Z" level=info msg="skip loading plugin \"io.containerd.snapshotter.v1.zfs\"..." error="path /var/lib/docker/165536.165536/containerd/daemon/io.containerd.snapshotter.v1.zfs must be a zfs filesystem to be used with the zfs snapshotter: skip plugin" type=io.containerd.snapshotter.v1

35

time="2024-07-25T19:44:16.103256231Z" level=info msg="loading plugin \"io.containerd.content.v1.content\"..." type=io.containerd.content.v1

36

time="2024-07-25T19:44:16.103466762Z" level=info msg="loading plugin \"io.containerd.metadata.v1.bolt\"..." type=io.containerd.metadata.v1

37

time="2024-07-25T19:44:16.103522265Z" level=warning msg="could not use snapshotter $TERMINUS_ENVmapper in metadata plugin" error="$TERMINUS_ENVmapper not configured"

38

time="2024-07-25T19:44:16.103539597Z" level=info msg="metadata content store policy set" policy=shared

39

time="2024-07-25T19:44:16.186475357Z" level=info msg="loading plugin \"io.containerd.gc.v1.scheduler\"..." type=io.containerd.gc.v1

40

time="2024-07-25T19:44:16.186592457Z" level=info msg="loading plugin \"io.containerd.differ.v1.walking\"..." type=io.containerd.differ.v1

41

time="2024-07-25T19:44:16.186624660Z" level=info msg="loading plugin \"io.containerd.lease.v1.manager\"..." type=io.containerd.lease.v1

42

time="2024-07-25T19:44:16.186708044Z" level=info msg="loading plugin \"io.containerd.streaming.v1.manager\"..." type=io.containerd.streaming.v1

43

time="2024-07-25T19:44:16.186769641Z" level=info msg="loading plugin \"io.containerd.runtime.v1.linux\"..." type=io.containerd.runtime.v1

44

time="2024-07-25T19:44:16.187083765Z" level=info msg="loading plugin \"io.containerd.monitor.v1.cgroups\"..." type=io.containerd.monitor.v1

45

time="2024-07-25T19:44:16.189343357Z" level=info msg="loading plugin \"io.containerd.runtime.v2.task\"..." type=io.containerd.runtime.v2

46

time="2024-07-25T19:44:16.189735922Z" level=info msg="loading plugin \"io.containerd.runtime.v2.shim\"..." type=io.containerd.runtime.v2

47

time="2024-07-25T19:44:16.189779539Z" level=info msg="loading plugin \"io.containerd.sandbox.store.v1.local\"..." type=io.containerd.sandbox.store.v1

48

time="2024-07-25T19:44:16.189842157Z" level=info msg="loading plugin \"io.containerd.sandbox.controller.v1.local\"..." type=io.containerd.sandbox.controller.v1

49

time="2024-07-25T19:44:16.189886810Z" level=info msg="loading plugin \"io.containerd.service.v1.containers-service\"..." type=io.containerd.service.v1

50

time="2024-07-25T19:44:16.189914022Z" level=info msg="loading plugin \"io.containerd.service.v1.content-service\"..." type=io.containerd.service.v1

51

time="2024-07-25T19:44:16.189974207Z" level=info msg="loading plugin \"io.containerd.service.v1.diff-service\"..." type=io.containerd.service.v1

52

time="2024-07-25T19:44:16.190003342Z" level=info msg="loading plugin \"io.containerd.service.v1.images-service\"..." type=io.containerd.service.v1

53

time="2024-07-25T19:44:16.190082009Z" level=info msg="loading plugin \"io.containerd.service.v1.introspection-service\"..." type=io.containerd.service.v1

54

time="2024-07-25T19:44:16.190113669Z" level=info msg="loading plugin \"io.containerd.service.v1.namespaces-service\"..." type=io.containerd.service.v1

55

time="2024-07-25T19:44:16.190191829Z" level=info msg="loading plugin \"io.containerd.service.v1.snapshots-service\"..." type=io.containerd.service.v1

56

time="2024-07-25T19:44:16.190220179Z" level=info msg="loading plugin \"io.containerd.service.v1.tasks-service\"..." type=io.containerd.service.v1

57

time="2024-07-25T19:44:16.190285205Z" level=info msg="loading plugin \"io.containerd.grpc.v1.containers\"..." type=io.containerd.grpc.v1

58

time="2024-07-25T19:44:16.190328872Z" level=info msg="loading plugin \"io.containerd.grpc.v1.content\"..." type=io.containerd.grpc.v1

59

time="2024-07-25T19:44:16.190354170Z" level=info msg="loading plugin \"io.containerd.grpc.v1.diff\"..." type=io.containerd.grpc.v1

60

time="2024-07-25T19:44:16.190416835Z" level=info msg="loading plugin \"io.containerd.grpc.v1.events\"..." type=io.containerd.grpc.v1

61

time="2024-07-25T19:44:16.190448287Z" level=info msg="loading plugin \"io.containerd.grpc.v1.images\"..." type=io.containerd.grpc.v1

62

time="2024-07-25T19:44:16.190507315Z" level=info msg="loading plugin \"io.containerd.grpc.v1.introspection\"..." type=io.containerd.grpc.v1

63

time="2024-07-25T19:44:16.190562790Z" level=info msg="loading plugin \"io.containerd.grpc.v1.leases\"..." type=io.containerd.grpc.v1

64

time="2024-07-25T19:44:16.190710477Z" level=info msg="loading plugin \"io.containerd.grpc.v1.namespaces\"..." type=io.containerd.grpc.v1

65

time="2024-07-25T19:44:16.190740295Z" level=info msg="loading plugin \"io.containerd.grpc.v1.sandbox-controllers\"..." type=io.containerd.grpc.v1

66

time="2024-07-25T19:44:16.190838625Z" level=info msg="loading plugin \"io.containerd.grpc.v1.sandboxes\"..." type=io.containerd.grpc.v1

67

time="2024-07-25T19:44:16.190863972Z" level=info msg="loading plugin \"io.containerd.grpc.v1.snapshots\"..." type=io.containerd.grpc.v1

68

time="2024-07-25T19:44:16.190934785Z" level=info msg="loading plugin \"io.containerd.grpc.v1.streaming\"..." type=io.containerd.grpc.v1

69

time="2024-07-25T19:44:16.190971081Z" level=info msg="loading plugin \"io.containerd.grpc.v1.tasks\"..." type=io.containerd.grpc.v1

70

time="2024-07-25T19:44:16.191047830Z" level=info msg="loading plugin \"io.containerd.transfer.v1.local\"..." type=io.containerd.transfer.v1

71

time="2024-07-25T19:44:16.191087405Z" level=info msg="loading plugin \"io.containerd.grpc.v1.transfer\"..." type=io.containerd.grpc.v1

72

time="2024-07-25T19:44:16.191153485Z" level=info msg="loading plugin \"io.containerd.grpc.v1.version\"..." type=io.containerd.grpc.v1

73

time="2024-07-25T19:44:16.191184050Z" level=info msg="loading plugin \"io.containerd.internal.v1.restart\"..." type=io.containerd.internal.v1

74

time="2024-07-25T19:44:16.192299599Z" level=info msg="loading plugin \"io.containerd.tracing.processor.v1.otlp\"..." type=io.containerd.tracing.processor.v1

75

time="2024-07-25T19:44:16.192352169Z" level=info msg="skip loading plugin \"io.containerd.tracing.processor.v1.otlp\"..." error="no OpenTelemetry endpoint: skip plugin" type=io.containerd.tracing.processor.v1

76

time="2024-07-25T19:44:16.192376289Z" level=info msg="loading plugin \"io.containerd.internal.v1.tracing\"..." type=io.containerd.internal.v1

77

time="2024-07-25T19:44:16.192456379Z" level=info msg="skipping tracing processor initialization (no tracing plugin)" error="no OpenTelemetry endpoint: skip plugin"

78

time="2024-07-25T19:44:16.193469569Z" level=info msg="loading plugin \"io.containerd.grpc.v1.healthcheck\"..." type=io.containerd.grpc.v1

79

time="2024-07-25T19:44:16.193516776Z" level=info msg="loading plugin \"io.containerd.nri.v1.nri\"..." type=io.containerd.nri.v1

80

time="2024-07-25T19:44:16.193546301Z" level=info msg="NRI interface is disabled by configuration."

81

time="2024-07-25T19:44:16.194909605Z" level=info msg=serving... address=/var/run/docker/containerd/containerd-debug.sock

82

time="2024-07-25T19:44:16.196338985Z" level=info msg=serving... address=/var/run/docker/containerd/containerd.sock.ttrpc

83

time="2024-07-25T19:44:16.196860705Z" level=info msg=serving... address=/var/run/docker/containerd/containerd.sock

84

time="2024-07-25T19:44:16.197097226Z" level=info msg="containerd successfully booted in 0.141672s"

85

time="2024-07-25T19:44:16.933430367Z" level=warning msg="unable to modify root key limit, number of containers could be limited by this quota: open /proc/sys/kernel/keys/root_maxkeys: no such file or directory"

86

time="2024-07-25T19:44:16.934303536Z" level=info msg="User namespaces: ID ranges will be mapped to subuid/subgid ranges of: dockremap"

87

time="2024-07-25T19:44:17.006166146Z" level=info msg="[graphdriver] trying configured driver: overlay2"

88

time="2024-07-25T19:44:17.120612705Z" level=info msg="Loading containers: start."

89

time="2024-07-25T19:44:17.127744795Z" level=warning msg="Running modprobe bridge br_netfilter failed with message: ip: can't find $TERMINUS_ENVice 'bridge'\nlsmod: /proc/modules: No such file or directory\nip: can't find $TERMINUS_ENVice 'br_netfilter'\nlsmod: /proc/modules: No such file or directory\nmodprobe: can't change directory to '/lib/modules': No such file or directory\n, error: exit status 1"

90

time="2024-07-25T19:44:17.233055325Z" level=info msg="Loading containers: done."

91

time="2024-07-25T19:44:17.273554447Z" level=warning msg="WARNING: API is accessible on http://0.0.0.0:2375 without encryption.\n Access to the remote API is equivalent to root access on the host. Refer\n to the 'Docker daemon attack surface' section in the documentation for\n more information: https://docs.docker.com/go/attack-surface/"

92

time="2024-07-25T19:44:17.273602876Z" level=warning msg="WARNING: bridge-nf-call-iptables is disabled"

93

time="2024-07-25T19:44:17.273615462Z" level=warning msg="WARNING: bridge-nf-call-ip6tables is disabled"

94

time="2024-07-25T19:44:17.273652680Z" level=info msg="Docker daemon" commit=fce6e0c containerd-snapshotter=false storage-driver=overlay2 version=25.0.2

95

time="2024-07-25T19:44:17.278060755Z" level=info msg="Daemon has completed initialization"

96

time="2024-07-25T19:44:17.315697179Z" level=info msg="API listen on /var/run/docker.sock"

97

time="2024-07-25T19:44:17.315740912Z" level=info msg="API listen on [::]:2375"

98"

Pipelines directs me to the following troubleshooting page: https://confluence.atlassian.com/bbkb/troubleshooting-bitbucket-pipelines-1141505226.html#TroubleshootingBitbucketPipelines-scenario4

It recommends running it locally with a docker, explained here: 

https://confluence.atlassian.com/bbkb/debug-pipelines-locally-with-docker-1167698072.html

This process does not work for me, however. It breaks down on Step 3. Specifically, when I copy pasta the build command, I get the following error "

Step 3/3 : COPY ./localDebugRepo /localDebugRepo COPY failed: file not found in build context or excluded by .dockerignore: stat localDebugRepo: file does not exist" 

despite following the preceding instructions seemingly to a 'T'. So now I'm stuck and can't follow the troubleshooting steps.

Can someone please help? How do I resolve the time out and get the pipeline to complete? Secondly, how do I resolve the local docker troubleshoot problem?

THANKS

[Mark Jovanovich · Accepted solution]

We eventually solved this one. I believe it was because the Repository Settings did not have a proper matching SSH Key pair with Pantheon AND we needed to create a new Pantheon Machine Token (for Terminus) and assign the token as a variable in Bitbucket under Repository Variables as it was named in the pipeline YAML ("$TERMINUS_TOKEN").

[Theodora Boudale]

Hi Mark and welcome to the community!

If I understand correctly, there is a certain step in a Pipelines build that gets stuck in the Build Setup and no command from that step's script gets executed. Is that correct?

Can you please provide the following info so I can better help you:

• Open this build in Bitbucket Cloud's website, ensure that the tab Build is selected, and then click the icon Download raw from the top right corner. Open the file on your computer, sanitize private/sensitive data (if any) and then share the content here.
• Share the definition of this step from your bitbucket-pipelines.yml file.
• If you have an image definition at the top of your bitbucket-pipelines.yml file for all steps, and it is a public Docker image, please share the definition for that as well (so I can see if I can run a build with this image as a build container).

With regards to the local troubleshooting problem, the error mentions that the directory ./localDebugRepo cannot be found. The guide assumes that the directory of the clone of your repo is named localDebugRepo; if it is different, you should change the name. The clone directory should also be in the same directory as the Dockerfile in Step 2.

Apart from that though, the guide cannot be used when you use a docker service in your build, because the step will need access to a Docker daemon.

Kind regards,
Theodora

[Mark Jovanovich]

Thank you so much for the reply, Theodora. Here is the raw contents as requested:

+ umask 000

+ GIT_LFS_SKIP_SMUDGE=1 retry 6 git clone --branch="$TERMINUS_ENVelop" --depth 50 https://x-token-auth:$REPOSITORY_OAUTH_ACCESS_TOKEN@bitbucket.org/$BITBUCKET_REPO_FULL_NAME.git $BUILD_DIR
Cloning into '/opt/atlassian/pipelines/agent/build'...

+ git reset --hard b9ed86c7f65319ddea7fc89b4cdba6b6327f77c1
HEAD is now at b9ed86c Merged in release/CCA-1-perform-first-core-update (pull request #111)

+ git config user.name bitbucket-pipelines

+ git config user.email commits-noreply@bitbucket.org

+ git config push.default current

+ git config http.${BITBUCKET_GIT_HTTP_ORIGIN}.proxy http://localhost:29418/

+ git remote set-url origin http://bitbucket.org/$BITBUCKET_REPO_FULL_NAME

+ git reflog expire --expire=all --all

+ echo ".bitbucket/pipelines/generated" >> .git/info/exclude

+ chmod 777 $BUILD_DIR

Artifact ".bashrc": Downloading
Artifact ".bashrc": Downloaded 622 B in 0 seconds
Artifact ".bashrc": Extracting
Artifact ".bashrc": Extracted in 0 seconds
Artifact "web/**": Downloading
Artifact "web/**": Downloaded 48.2 MiB in 1 seconds
Artifact "web/**": Extracting
Artifact "web/**": Extracted in 4 seconds
Artifact "vendor/**": Downloading
Artifact "vendor/**": Downloaded 8.9 MiB in 0 seconds
Artifact "vendor/**": Extracting
Artifact "vendor/**": Extracted in 0 seconds
Artifact "web/themes/custom/**": Downloading
Artifact "web/themes/custom/**": Downloaded 35.7 MiB in 1 seconds
Artifact "web/themes/custom/**": Extracting
Artifact "web/themes/custom/**": Extracted in 3 seconds

Cache "docker: docker.tar": Downloading
Cache "docker: docker.tar": Not found

Default variables:
BITBUCKET_BRANCH
BITBUCKET_BUILD_NUMBER
BITBUCKET_CLONE_DIR
BITBUCKET_COMMIT
BITBUCKET_GIT_HTTP_ORIGIN
BITBUCKET_GIT_SSH_ORIGIN
BITBUCKET_PIPELINE_UUID
BITBUCKET_PROJECT_KEY
BITBUCKET_PROJECT_UUID
BITBUCKET_REPO_FULL_NAME
BITBUCKET_REPO_IS_PRIVATE
BITBUCKET_REPO_OWNER
BITBUCKET_REPO_OWNER_UUID
BITBUCKET_REPO_SLUG
BITBUCKET_REPO_UUID
BITBUCKET_SSH_KEY_FILE
BITBUCKET_STEP_RUN_NUMBER
BITBUCKET_STEP_TRIGGERER_UUID
BITBUCKET_STEP_UUID
BITBUCKET_WORKSPACE
CI
DOCKER_HOST
PIPELINES_JWT_TOKEN

Repository variables:
CI_BRANCH
HEROKU_API_KEY
PATTERN_LAB_THEME_PATH
TERMINUS_ENV
TERMINUS_SITE
TERMINUS_TOKEN

Images used:
build : quay.io/pantheon-public/build-tools-ci@sha256:46194163d4d308919f212a34e9fd8e9d348f0eb9cc548ab824f692e9e0dc0880

I'm afraid I do not know specifically what you are asking for from the yml file. Is it this?

 - step:

      name: Deploy to Pantheon

      services:

        - docker

      caches:

        - docker

      script:

        - *bash_env_export

        - *bash_env_source

        - ./.ci/deploy/pantheon/dev

      artifacts:

        - web/**

        - vendor/**

        - web/themes/custom/cmu/pattern_lab/**

image: quay.io/pantheon-public/build-tools-ci:8.x-php8.1

options:

  max-time: 30

[Theodora Boudale]

Hi Mark,

Thank you for all the info.

I don't think the issue is related to the Docker image from quay.io, as I was able to run a Pipelines step with this image. Even when my step times out, I can still see the command that is executed in the build log.

We would need to access this build and check additional logs from our side to figure out what is happening, and we can only do this if we have a support ticket. Would it be ok with you if I create a support ticket on your behalf, so that you share the URL of that build and one of my colleagues investigates? The support ticket will be visible to you and Atlassian staff, so anything you post there won't be publicly visible.

Kind regards,
Theodora

[Mark Jovanovich]

That would be great. Let me know what you need from me.

Many thanks!

[Theodora Boudale]

Hi Mark,

I have created a support ticket on your behalf. You should have received an email with a link to the ticket and you can also see the ticket listed here:

• https://support.atlassian.com/requests/

Please leave a reply in the ticket providing the URL of the failed build/step so my colleague who will work on it can investigate.

Please feel free to let me know if you have any questions!

Kind regards,
Theodora