search

buildstream-migration / bst-staging

GNU Lesser General Public License v2.1
0 stars 0 forks source link

bst build seems to be stuck forever, not downloading anything #615

Open Cynical-Optimist opened 4 years ago

Cynical-Optimist commented 4 years ago

See original issue on GitLab In GitLab by [Gitlab user @bochecha] on Aug 29, 2018, 21:43

Summary

In the freedesktop SDK, we have a desktop-platform-image.bst element:

$ bst build desktop-platform-image.bst
…
[03:49:49][Pull:desktop-platform-image.bst]

It usually takes me about an hour to pull the artifacts for this element (which I already find incredibly slow, but that might be #554).

This time it's been pulling for almost 4 hours though…

Steps to reproduce

This is the first time it happens to me, so I don't think you might reproduce it easily.

But clone the freedesktop-sdk repo then:

$ bst build desktop-platform-image.bst

In case it helps, I'm on revision 4f415382919437f9f0b89037d893c4e6ff25031a from that repo (but I don't think it will help reproduce it).

What is the current bug behavior?

Buildstream is pulling, seemingly forever.

My ~/.cache/buildstream/ is not growing at all.

What is the expected correct behavior?

This should have finished pulling about 3 hours ago.

Relevant logs and/or screenshots

The pull.log is completely unhelpful:

[--:--:--] START   desktop-platform-image.bst: Pull
[--:--:--] LOG     desktop-platform-image.bst: Build environment for element desktop-platform-image.bst

    CFLAGS: -O2 -g -fstack-protector-strong
    CPPFLAGS: -O2 -D_FORTIFY_SOURCE=2
    CXXFLAGS: -O2 -g -fstack-protector-strong
    HOME: /tmp
    LC_ALL: en_US.UTF-8
    LDFLAGS: -fstack-protector-strong -Wl,-z,relro,-z,now
    LOGNAME: tomjon
    PATH: /usr/bin:/bin:/usr/sbin:/sbin
    PYTHON: /usr/bin/python3
    SHELL: /bin/sh
    SOURCE_DATE_EPOCH: '1320937200'
    TERM: dumb
    TZ: UTC
    USER: tomjon
    USERNAME: tomjon
[--:--:--] INFO    desktop-platform-image.bst: Pulling 0743b100 <- https://testcache.codethink.co.uk:11001

Here's a strace of the parent/monitoring Buildstream process:

[pid   450] epoll_wait(577, [], 2, 1000) = 0
[pid   450] ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
[pid   450] write(2, "\33[1G\33[A", 7)  = 7
[pid   450] ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
[pid   450] write(2, "\33[K", 3)        = 3
[pid   450] ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
[pid   450] write(2, "\33[1G\33[A", 7)  = 7
[pid   450] ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
[pid   450] write(2, "\33[K", 3)        = 3
[pid   450] ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
[pid   450] write(2, "\33[1G\33[A", 7)  = 7
[pid   450] ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
[pid   450] write(2, "\33[K", 3)        = 3
[pid   450] ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
[pid   450] write(2, "\33[1G\33[A", 7)  = 7
[pid   450] ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
[pid   450] write(2, "\33[K", 3)        = 3
[pid   450] ioctl(1, TIOCGWINSZ, {ws_row=54, ws_col=238, ws_xpixel=0, ws_ypixel=0}) = 0
[pid   450] ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
[pid   450] write(2, "\n", 1)           = 1
[pid   450] ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
[pid   450] write(2, "\n", 1)           = 1
[pid   450] ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
[pid   450] write(2, "\n", 1)           = 1
[pid   450] ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
[pid   450] write(2, "\n", 1)           = 1
[pid   450] ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
[pid   450] write(2, "\33[1G\33[A", 7)  = 7
[pid   450] ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
[pid   450] write(2, "\33[1G\33[A", 7)  = 7
[pid   450] ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
[pid   450] write(2, "\33[1G\33[A", 7)  = 7
[pid   450] ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
[pid   450] write(2, "\33[1G\33[A", 7)  = 7
[pid   450] write(2, "\33[36m\33[2m=====================================================================================================\33[0m \33[33m03\33[0m\33[36m\33[2m:\33[0m\33[33m43\33[0m\33[36m\33[2m:\33[0m\33[33m48\33[0m \33[33mfreedesktop-sdk\33[0m \33[36m\33[2m(\33[0m\33[33m283\33[0m\33[36m\33[2m/\33[0m\33[33m283\33[0m\33[36m\33[2m)\33[0m \33[36m\33[2m=====================================================================================================\33[0m\n\33[36m\33[2m                                                                                               \33[0m \33[36m\33[2m(\33[0m\33[33mPulled\33[0m\33[36m\33[2m:\33[0m\33[32m0\33[0m \33[33m0\33[0m \33[31m\33[2m0\33[0m\33[36m\33[2m)\33[0m\33[36m\33[2m\342\206\222 \33[0m\33[36m\33[2m(\33[0m\33[33mFetched\33[0m\33[36m\33[2m:\33[0m\33[32m0\33[0m \33[33m0\33[0m \33[31m\33[2m0\33[0m\33[36m\33[2m)\33[0m\33[36m\33[2m\342\206\222 \33[0m\33[36m\33[2m(\33[0m\33[33mBuilt\33[0m\33[36m\33[2m:\33[0m\33[32m0\33[0m \33[33m0\33[0m \33[31m\33[2m0\33[0m\33[36m\33[2m)\33[0m \33[36m\33[2m                                                                                               \33[0m\n\33[36m\33[2m                                                                                                          \33[0m \33[36m\33[2m~~~~~ \33[0m\33[33mActive Tasks\33[0m\33[36m\33[2m ~~~~~\33[0m \33[36m\33[2m                                                                                                          \33[0m\n", 1216) = 1216
[pid   450] write(2, "\33[36m\33[2m[\33[0m\33[33m03\33[0m\33[36m\33[2m:\33[0m\33[33m43\33[0m\33[36m\33[2m:\33[0m\33[33m43\33[0m\33[36m\33[2m]\33[0m\33[36m\33[2m[\33[0m\33[33mPull\33[0m\33[36m\33[2m:\33[0m\33[33mdesktop-platform-image.bst\33[0m\33[36m\33[2m]\33[0m\n", 180) = 180
[pid   450] epoll_wait(577, [], 2, 1000) = 0

That just repeats over and over again.

Now here's what the child process says:

strace: Process 467 attached with 6 threads
[pid  3900] epoll_wait(592,  <unfinished ...>
[pid   479] futex(0x7f56cafdfd08, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid   470] restart_syscall(<... resuming interrupted futex ...> <unfinished ...>
[pid   469] futex(0x55d4e5dd225c, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid   468] futex(0x7f56b8001c40, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, 0xffffffff <unfinished ...>
[pid   467] futex(0x55d4e5e2fda0, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, 0xffffffff <unfinished ...>
[pid  3900] <... epoll_wait resumed> [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42952, tv_nsec=553847158}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574862, tv_nsec=312915411}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574862, tv_nsec=313068944}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42952, tv_nsec=554313789}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42952, tv_nsec=554378159}) = 0
[pid  3900] epoll_wait(592, [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42952, tv_nsec=756074305}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574862, tv_nsec=515118649}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574862, tv_nsec=515283032}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42952, tv_nsec=756537448}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42952, tv_nsec=756630777}) = 0
[pid  3900] epoll_wait(592, [], 100, 200) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42952, tv_nsec=957267584}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574862, tv_nsec=716266948}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574862, tv_nsec=716349317}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42952, tv_nsec=957573896}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42952, tv_nsec=957634828}) = 0
[pid  3900] epoll_wait(592,  <unfinished ...>
[pid   470] <... restart_syscall resumed> ) = -1 ETIMEDOUT (Connection timed out)
[pid   470] futex(0x7f56cafdfd20, FUTEX_WAKE_PRIVATE, 1) = 0
[pid   470] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42952, tv_nsec=966982872}) = 0
[pid   470] futex(0x7f56cafdfd08, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=281336784} <unfinished ...>
[pid  3900] <... epoll_wait resumed> [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42953, tv_nsec=159237022}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574862, tv_nsec=918273828}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574862, tv_nsec=918413206}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42953, tv_nsec=159667521}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42953, tv_nsec=159725325}) = 0
[pid  3900] epoll_wait(592,  <unfinished ...>
[pid   470] <... futex resumed> )       = -1 ETIMEDOUT (Connection timed out)
[pid   470] futex(0x7f56cafdfd20, FUTEX_WAKE_PRIVATE, 1) = 0
[pid   470] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42953, tv_nsec=248865120}) = 0
[pid   470] futex(0x7f56cafdfd08, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid   479] <... futex resumed> )       = 0
[pid   470] <... futex resumed> )       = 1
[pid   479] futex(0x7f56cafdfd20, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid   470] futex(0x7f56cafdfd20, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid   479] <... futex resumed> )       = -1 EAGAIN (Resource temporarily unavailable)
[pid   470] <... futex resumed> )       = 0
[pid   479] futex(0x7f56cafdfd20, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid   470] epoll_wait(585,  <unfinished ...>
[pid   479] <... futex resumed> )       = 0
[pid   470] <... epoll_wait resumed> [], 100, 0) = 0
[pid   479] clock_gettime(CLOCK_MONOTONIC,  <unfinished ...>
[pid   470] clock_gettime(CLOCK_MONOTONIC,  <unfinished ...>
[pid   479] <... clock_gettime resumed> {tv_sec=42953, tv_nsec=249155613}) = 0
[pid   470] <... clock_gettime resumed> {tv_sec=42953, tv_nsec=249165006}) = 0
[pid   479] futex(0x7f56cafdfd0c, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=718216856} <unfinished ...>
[pid   470] futex(0x7f56cafdfd0c, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  3900] <... epoll_wait resumed> [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42953, tv_nsec=361308759}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574863, tv_nsec=120233918}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574863, tv_nsec=120304649}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42953, tv_nsec=361525667}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42953, tv_nsec=361576966}) = 0
[pid  3900] epoll_wait(592, [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42953, tv_nsec=563196792}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574863, tv_nsec=322225664}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574863, tv_nsec=322368653}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42953, tv_nsec=563637681}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42953, tv_nsec=563721832}) = 0
[pid  3900] epoll_wait(592, [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42953, tv_nsec=765308659}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574863, tv_nsec=524263751}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574863, tv_nsec=524397966}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42953, tv_nsec=765615429}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42953, tv_nsec=765666480}) = 0
[pid  3900] epoll_wait(592, [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42953, tv_nsec=967233001}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574863, tv_nsec=726217804}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574863, tv_nsec=726362406}) = 0
[pid   479] <... futex resumed> )       = -1 ETIMEDOUT (Connection timed out)
[pid  3900] clock_gettime(CLOCK_MONOTONIC,  <unfinished ...>
[pid   479] futex(0x7f56cafdfd20, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  3900] <... clock_gettime resumed> {tv_sec=42953, tv_nsec=967643351}) = 0
[pid   479] <... futex resumed> )       = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42953, tv_nsec=967843041}) = 0
[pid   479] clock_gettime(CLOCK_MONOTONIC,  <unfinished ...>
[pid  3900] epoll_wait(592,  <unfinished ...>
[pid   479] <... clock_gettime resumed> {tv_sec=42953, tv_nsec=967952846}) = 0
[pid   479] futex(0x7f56cafdfd0c, FUTEX_WAIT_PRIVATE, 0, {tv_sec=1, tv_nsec=307743} <unfinished ...>
[pid  3900] <... epoll_wait resumed> [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42954, tv_nsec=169579315}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574863, tv_nsec=928542058}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574863, tv_nsec=928705124}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42954, tv_nsec=169997524}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42954, tv_nsec=170106394}) = 0
[pid  3900] epoll_wait(592, [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42954, tv_nsec=371817841}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574864, tv_nsec=130856791}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574864, tv_nsec=130961008}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42954, tv_nsec=372224593}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42954, tv_nsec=372307521}) = 0
[pid  3900] epoll_wait(592, [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42954, tv_nsec=573811298}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574864, tv_nsec=332769017}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574864, tv_nsec=332871439}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42954, tv_nsec=574108449}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42954, tv_nsec=574165746}) = 0
[pid  3900] epoll_wait(592, [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42954, tv_nsec=775737461}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574864, tv_nsec=534704587}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574864, tv_nsec=534793153}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42954, tv_nsec=776082798}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42954, tv_nsec=776181926}) = 0
[pid  3900] epoll_wait(592,  <unfinished ...>
[pid   479] <... futex resumed> )       = -1 ETIMEDOUT (Connection timed out)
[pid   479] futex(0x7f56cafdfd20, FUTEX_WAKE_PRIVATE, 1) = 0
[pid   479] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42954, tv_nsec=968898710}) = 0
[pid   479] futex(0x7f56cafdfd0c, FUTEX_WAIT_PRIVATE, 0, {tv_sec=1, tv_nsec=360379} <unfinished ...>
[pid  3900] <... epoll_wait resumed> [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42954, tv_nsec=977769923}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574864, tv_nsec=736712021}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574864, tv_nsec=736773885}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42954, tv_nsec=978022119}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42954, tv_nsec=978103045}) = 0
[pid  3900] epoll_wait(592, [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42955, tv_nsec=179670046}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574864, tv_nsec=938625814}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574864, tv_nsec=938699092}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42955, tv_nsec=179929925}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42955, tv_nsec=179979719}) = 0
[pid  3900] epoll_wait(592, [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42955, tv_nsec=381605547}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574865, tv_nsec=140619640}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574865, tv_nsec=140745095}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42955, tv_nsec=381977292}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42955, tv_nsec=382057562}) = 0
[pid  3900] epoll_wait(592, [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42955, tv_nsec=583535714}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574865, tv_nsec=342503042}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574865, tv_nsec=342588845}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42955, tv_nsec=583905796}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42955, tv_nsec=584036353}) = 0
[pid  3900] epoll_wait(592, [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42955, tv_nsec=785730249}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574865, tv_nsec=544723737}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574865, tv_nsec=544875816}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42955, tv_nsec=786136399}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42955, tv_nsec=786247668}) = 0
[pid  3900] epoll_wait(592,  <unfinished ...>
[pid   479] <... futex resumed> )       = -1 ETIMEDOUT (Connection timed out)
[pid   479] futex(0x7f56cafdfd20, FUTEX_WAKE_PRIVATE, 1) = 0
[pid   479] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42955, tv_nsec=970016652}) = 0
[pid   479] futex(0x7f56cafdfd0c, FUTEX_WAIT_PRIVATE, 0, {tv_sec=1, tv_nsec=244351} <unfinished ...>
[pid  3900] <... epoll_wait resumed> [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42955, tv_nsec=987950829}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574865, tv_nsec=746982198}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574865, tv_nsec=747131639}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42955, tv_nsec=988425325}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42955, tv_nsec=988534437}) = 0
[pid  3900] epoll_wait(592, [], 100, 200) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42956, tv_nsec=189262032}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574865, tv_nsec=948301052}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574865, tv_nsec=948426614}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42956, tv_nsec=189694018}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42956, tv_nsec=189782689}) = 0
[pid  3900] epoll_wait(592, [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42956, tv_nsec=391345157}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574866, tv_nsec=150305493}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574866, tv_nsec=150525641}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42956, tv_nsec=391798861}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42956, tv_nsec=391869161}) = 0
[pid  3900] epoll_wait(592, [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42956, tv_nsec=593431645}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574866, tv_nsec=352406528}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574866, tv_nsec=352643467}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42956, tv_nsec=593916480}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42956, tv_nsec=593992537}) = 0
[pid  3900] epoll_wait(592, [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42956, tv_nsec=795623188}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574866, tv_nsec=554618958}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574866, tv_nsec=554712443}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42956, tv_nsec=795950704}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42956, tv_nsec=796042604}) = 0
[pid  3900] epoll_wait(592,  <unfinished ...>
[pid   479] <... futex resumed> )       = -1 ETIMEDOUT (Connection timed out)
[pid   479] futex(0x7f56cafdfd20, FUTEX_WAKE_PRIVATE, 1) = 0
[pid   479] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42956, tv_nsec=970979139}) = 0
[pid   479] futex(0x7f56cafdfd0c, FUTEX_WAIT_PRIVATE, 0, {tv_sec=1, tv_nsec=345254} <unfinished ...>
[pid  3900] <... epoll_wait resumed> [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42956, tv_nsec=997773789}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574866, tv_nsec=756907197}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574866, tv_nsec=757115082}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42956, tv_nsec=998747466}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42956, tv_nsec=998871606}) = 0
[pid  3900] epoll_wait(592, [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42957, tv_nsec=200510042}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574866, tv_nsec=959458801}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574866, tv_nsec=959547055}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42957, tv_nsec=200777358}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42957, tv_nsec=200838923}) = 0
[pid  3900] epoll_wait(592, [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42957, tv_nsec=402414884}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574867, tv_nsec=161393375}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574867, tv_nsec=161492426}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42957, tv_nsec=402756392}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42957, tv_nsec=402836764}) = 0
[pid  3900] epoll_wait(592, [], 100, 201) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42957, tv_nsec=604306880}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574867, tv_nsec=363195854}) = 0
[pid  3900] clock_gettime(CLOCK_REALTIME, {tv_sec=1535574867, tv_nsec=363255871}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42957, tv_nsec=604464669}) = 0
[pid  3900] clock_gettime(CLOCK_MONOTONIC, {tv_sec=42957, tv_nsec=604512129}) = 0
[pid  3900] epoll_wait(592, ^Cstrace: Process 467 detached
strace: Process 468 detached
strace: Process 469 detached
strace: Process 470 detached
strace: Process 479 detached
strace: Process 3900 detached
 <detached ...>

That also seems to be repeating, but much faster.

The child process doesn't seem to be downloading anything at all.

Other relevant information

This is with Buildstream 1.1.7.

Cynical-Optimist commented 4 years ago

In GitLab by [Gitlab user @bochecha] on Aug 29, 2018, 21:46

changed the description

Cynical-Optimist commented 4 years ago

In GitLab by [Gitlab user @tristanvb] on Dec 10, 2018, 10:43

[Gitlab user @bochecha], since this incident, we have implemented a few fixes to the local and remote cache expiry, and also implemented the batch file upload/download optimizations, and we haven't seen this kind of hang in bst pull tasks in a while.

Can you confirm whether you still see this hang happening or not ? Otherwise will will close this in the near future...

Cynical-Optimist commented 4 years ago

In GitLab by [Gitlab user @bochecha] on Jan 8, 2019, 21:59

[Gitlab user @tristanvb] somehow I wasn't notified for your comment, and I just randomly stumbled upon it. :confused:

I assume you mean it's been fixed in master?

I'm using 1.2.3, and just now it happened again: just now, bst has been pulling desktop/llvm6.bst (from Freedesktop SDK) for 1h 15min. My ~/.cache/buildstream hasn't grown at all for the past 25 minutes.

Cynical-Optimist commented 4 years ago

In GitLab by [Gitlab user @valentindavid] on Jan 25, 2019, 15:38

This is happening now repetitively on Freedesktop SDK builders.

Cynical-Optimist commented 4 years ago

In GitLab by [Gitlab user @valentindavid] on Jan 25, 2019, 16:02

The x86 builders are in the US. The cache server is in Netherlands.

Cynical-Optimist commented 4 years ago

In GitLab by [Gitlab user @valentindavid] on Jan 25, 2019, 16:31

The issue with Freedesktop SDK builders was probably not related. We figured out that the bandwidth between the machines was little.

Cynical-Optimist commented 4 years ago

In GitLab by [Gitlab user @abderrahimk] on Jul 2, 2020, 10:55

mentioned in merge request !1979