Diff of the two buildlogs: -- --- b1/build.log 2025-01-08 00:04:27.877014011 +0000 +++ b2/build.log 2025-01-08 00:07:41.216213935 +0000 @@ -1,6 +1,6 @@ I: pbuilder: network access will be disabled during build -I: Current time: Tue Jan 7 12:00:12 -12 2025 -I: pbuilder-time-stamp: 1736294412 +I: Current time: Wed Jan 8 14:04:31 +14 2025 +I: pbuilder-time-stamp: 1736294671 I: Building the build Environment I: extracting base tarball [/var/cache/pbuilder/unstable-reproducible-base.tgz] I: copying local configuration @@ -22,52 +22,84 @@ dpkg-source: info: unpacking mender-connect_2.3.0+ds1-1.debian.tar.xz I: Not using root during the build. I: Installing the build-deps -I: user script /srv/workspace/pbuilder/2777805/tmp/hooks/D02_print_environment starting +I: user script /srv/workspace/pbuilder/1960565/tmp/hooks/D01_modify_environment starting +debug: Running on codethink04-arm64. +I: Changing host+domainname to test build reproducibility +I: Adding a custom variable just for the fun of it... +I: Changing /bin/sh to bash +'/bin/sh' -> '/bin/bash' +lrwxrwxrwx 1 root root 9 Jan 8 00:04 /bin/sh -> /bin/bash +I: Setting pbuilder2's login shell to /bin/bash +I: Setting pbuilder2's GECOS to second user,second room,second work-phone,second home-phone,second other +I: user script /srv/workspace/pbuilder/1960565/tmp/hooks/D01_modify_environment finished +I: user script /srv/workspace/pbuilder/1960565/tmp/hooks/D02_print_environment starting I: set - BUILDDIR='/build/reproducible-path' - BUILDUSERGECOS='first user,first room,first work-phone,first home-phone,first other' - BUILDUSERNAME='pbuilder1' - BUILD_ARCH='arm64' - DEBIAN_FRONTEND='noninteractive' + BASH=/bin/sh + BASHOPTS=checkwinsize:cmdhist:complete_fullquote:extquote:force_fignore:globasciiranges:globskipdots:hostcomplete:interactive_comments:patsub_replacement:progcomp:promptvars:sourcepath + BASH_ALIASES=() + BASH_ARGC=() + BASH_ARGV=() + BASH_CMDS=() + BASH_LINENO=([0]="12" [1]="0") + BASH_LOADABLES_PATH=/usr/local/lib/bash:/usr/lib/bash:/opt/local/lib/bash:/usr/pkg/lib/bash:/opt/pkg/lib/bash:. + BASH_SOURCE=([0]="/tmp/hooks/D02_print_environment" [1]="/tmp/hooks/D02_print_environment") + BASH_VERSINFO=([0]="5" [1]="2" [2]="37" [3]="1" [4]="release" [5]="aarch64-unknown-linux-gnu") + BASH_VERSION='5.2.37(1)-release' + BUILDDIR=/build/reproducible-path + BUILDUSERGECOS='second user,second room,second work-phone,second home-phone,second other' + BUILDUSERNAME=pbuilder2 + BUILD_ARCH=arm64 + DEBIAN_FRONTEND=noninteractive DEB_BUILD_OPTIONS='buildinfo=+all reproducible=+all parallel=12 ' - DISTRIBUTION='unstable' - HOME='/root' - HOST_ARCH='arm64' + DIRSTACK=() + DISTRIBUTION=unstable + EUID=0 + FUNCNAME=([0]="Echo" [1]="main") + GROUPS=() + HOME=/root + HOSTNAME=i-capture-the-hostname + HOSTTYPE=aarch64 + HOST_ARCH=arm64 IFS=' ' - INVOCATION_ID='991f1153460045a28de8ddeb8e0e5a63' - LANG='C' - LANGUAGE='en_US:en' - LC_ALL='C' - MAIL='/var/mail/root' - OPTIND='1' - PATH='/usr/sbin:/usr/bin:/sbin:/bin:/usr/games' - PBCURRENTCOMMANDLINEOPERATION='build' - PBUILDER_OPERATION='build' - PBUILDER_PKGDATADIR='/usr/share/pbuilder' - PBUILDER_PKGLIBDIR='/usr/lib/pbuilder' - PBUILDER_SYSCONFDIR='/etc' - PPID='2777805' - PS1='# ' - PS2='> ' + INVOCATION_ID=52050643c28d4803a3a42fce5b8240a3 + LANG=C + LANGUAGE=nl_BE:nl + LC_ALL=C + MACHTYPE=aarch64-unknown-linux-gnu + MAIL=/var/mail/root + OPTERR=1 + OPTIND=1 + OSTYPE=linux-gnu + PATH=/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/i/capture/the/path + PBCURRENTCOMMANDLINEOPERATION=build + PBUILDER_OPERATION=build + PBUILDER_PKGDATADIR=/usr/share/pbuilder + PBUILDER_PKGLIBDIR=/usr/lib/pbuilder + PBUILDER_SYSCONFDIR=/etc + PIPESTATUS=([0]="0") + POSIXLY_CORRECT=y + PPID=1960565 PS4='+ ' - PWD='/' - SHELL='/bin/bash' - SHLVL='2' - SUDO_COMMAND='/usr/bin/timeout -k 18.1h 18h /usr/bin/ionice -c 3 /usr/bin/nice /usr/sbin/pbuilder --build --configfile /srv/reproducible-results/rbuild-debian/r-b-build.5tc3XPOW/pbuilderrc_XIVP --distribution unstable --hookdir /etc/pbuilder/first-build-hooks --debbuildopts -b --basetgz /var/cache/pbuilder/unstable-reproducible-base.tgz --buildresult /srv/reproducible-results/rbuild-debian/r-b-build.5tc3XPOW/b1 --logfile b1/build.log mender-connect_2.3.0+ds1-1.dsc' - SUDO_GID='109' - SUDO_UID='104' - SUDO_USER='jenkins' - TERM='unknown' - TZ='/usr/share/zoneinfo/Etc/GMT+12' - USER='root' - _='/usr/bin/systemd-run' - http_proxy='http://192.168.101.4:3128' + PWD=/ + SHELL=/bin/bash + SHELLOPTS=braceexpand:errexit:hashall:interactive-comments:posix + SHLVL=3 + SUDO_COMMAND='/usr/bin/timeout -k 24.1h 24h /usr/bin/ionice -c 3 /usr/bin/nice -n 11 /usr/bin/unshare --uts -- /usr/sbin/pbuilder --build --configfile /srv/reproducible-results/rbuild-debian/r-b-build.5tc3XPOW/pbuilderrc_F9Nr --distribution unstable --hookdir /etc/pbuilder/rebuild-hooks --debbuildopts -b --basetgz /var/cache/pbuilder/unstable-reproducible-base.tgz --buildresult /srv/reproducible-results/rbuild-debian/r-b-build.5tc3XPOW/b2 --logfile b2/build.log mender-connect_2.3.0+ds1-1.dsc' + SUDO_GID=109 + SUDO_UID=104 + SUDO_USER=jenkins + TERM=unknown + TZ=/usr/share/zoneinfo/Etc/GMT-14 + UID=0 + USER=root + _='I: set' + http_proxy=http://192.168.101.4:3128 I: uname -a - Linux codethink02-arm64 6.1.0-28-cloud-arm64 #1 SMP Debian 6.1.119-1 (2024-11-22) aarch64 GNU/Linux + Linux i-capture-the-hostname 6.1.0-28-cloud-arm64 #1 SMP Debian 6.1.119-1 (2024-11-22) aarch64 GNU/Linux I: ls -l /bin lrwxrwxrwx 1 root root 7 Nov 22 14:40 /bin -> usr/bin -I: user script /srv/workspace/pbuilder/2777805/tmp/hooks/D02_print_environment finished +I: user script /srv/workspace/pbuilder/1960565/tmp/hooks/D02_print_environment finished -> Attempting to satisfy build-dependencies -> Creating pbuilder-satisfydepends-dummy package Package: pbuilder-satisfydepends-dummy @@ -284,7 +316,7 @@ Get: 149 http://deb.debian.org/debian unstable/main arm64 libglib2.0-bin arm64 2.82.4-1 [123 kB] Get: 150 http://deb.debian.org/debian unstable/main arm64 libglib2.0-dev-bin arm64 2.82.4-1 [52.0 kB] Get: 151 http://deb.debian.org/debian unstable/main arm64 libglib2.0-dev arm64 2.82.4-1 [52.7 kB] -Fetched 98.8 MB in 1s (102 MB/s) +Fetched 98.8 MB in 1s (127 MB/s) Preconfiguring packages ... Selecting previously unselected package libdbus-1-3:arm64. (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 19966 files and directories currently installed.) @@ -787,8 +819,8 @@ Setting up tzdata (2024b-4) ... Current default time zone: 'Etc/UTC' -Local time is now: Wed Jan 8 00:01:14 UTC 2025. -Universal Time is now: Wed Jan 8 00:01:14 UTC 2025. +Local time is now: Wed Jan 8 00:05:09 UTC 2025. +Universal Time is now: Wed Jan 8 00:05:09 UTC 2025. Run 'dpkg-reconfigure tzdata' if you wish to change it. Setting up libsysprof-capture-4-dev:arm64 (47.2-1) ... @@ -923,7 +955,11 @@ Building tag database... -> Finished parsing the build-deps I: Building the package -I: Running cd /build/reproducible-path/mender-connect-2.3.0+ds1/ && env PATH="/usr/sbin:/usr/bin:/sbin:/bin:/usr/games" HOME="/nonexistent/first-build" dpkg-buildpackage -us -uc -b && env PATH="/usr/sbin:/usr/bin:/sbin:/bin:/usr/games" HOME="/nonexistent/first-build" dpkg-genchanges -S > ../mender-connect_2.3.0+ds1-1_source.changes +I: user script /srv/workspace/pbuilder/1960565/tmp/hooks/A99_set_merged_usr starting +Not re-configuring usrmerge for unstable +I: user script /srv/workspace/pbuilder/1960565/tmp/hooks/A99_set_merged_usr finished +hostname: Name or service not known +I: Running cd /build/reproducible-path/mender-connect-2.3.0+ds1/ && env PATH="/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/i/capture/the/path" HOME="/nonexistent/second-build" dpkg-buildpackage -us -uc -b && env PATH="/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/i/capture/the/path" HOME="/nonexistent/second-build" dpkg-genchanges -S > ../mender-connect_2.3.0+ds1-1_source.changes dpkg-buildpackage: info: source package mender-connect dpkg-buildpackage: info: source version 2.3.0+ds1-1 dpkg-buildpackage: info: source distribution unstable @@ -945,45 +981,45 @@ dh_auto_build -O--buildsystem=golang -- \ -ldflags "-X github.com/mendersoftware/mender-connect/config.Version=" cd _build && go install -trimpath -v -p 12 -ldflags "-X github.com/mendersoftware/mender-connect/config.Version=" github.com/mendersoftware/mender-connect github.com/mendersoftware/mender-connect/app github.com/mendersoftware/mender-connect/cli github.com/mendersoftware/mender-connect/client/dbus github.com/mendersoftware/mender-connect/client/dbus/mocks github.com/mendersoftware/mender-connect/client/dbus/test github.com/mendersoftware/mender-connect/client/mender github.com/mendersoftware/mender-connect/client/mender/mocks github.com/mendersoftware/mender-connect/config github.com/mendersoftware/mender-connect/connection github.com/mendersoftware/mender-connect/connectionmanager github.com/mendersoftware/mender-connect/limits/filetransfer github.com/mendersoftware/mender-connect/procps github.com/mendersoftware/mender-connect/session github.com/mendersoftware/mender-connect/session/mocks github.com/mendersoftware/mender-connect/session/model github.com/mendersoftware/mender-connect/shell github.com/mendersoftware/mender-connect/utils -internal/byteorder -internal/goexperiment +internal/goarch +internal/profilerecord internal/godebugs +internal/race internal/goos +internal/byteorder +internal/runtime/syscall internal/unsafeheader -internal/goarch -internal/asan internal/coverage/rtcov -runtime/internal/math +internal/goexperiment internal/cpu -internal/itoa -internal/race +internal/abi +runtime/internal/math +internal/asan runtime/internal/sys -internal/profilerecord +internal/itoa sync/atomic -internal/chacha8rand internal/msan -internal/abi cmp math/bits unicode/utf8 -internal/runtime/syscall unicode +internal/chacha8rand encoding github.com/mendersoftware/go-lib-micro/ws/shell -unicode/utf16 log/internal -github.com/mendersoftware/go-lib-micro/ws crypto/internal/alias -crypto/subtle -container/list -crypto/internal/boring/sig +github.com/mendersoftware/go-lib-micro/ws +unicode/utf16 math +crypto/internal/boring/sig +container/list vendor/golang.org/x/crypto/cryptobyte/asn1 vendor/golang.org/x/crypto/internal/alias -internal/nettrace -github.com/vmihailenco/msgpack/v5/msgpcode +crypto/subtle internal/bytealg +internal/nettrace internal/runtime/atomic +github.com/vmihailenco/msgpack/v5/msgpcode github.com/vmihailenco/tagparser/v2/internal github.com/mendersoftware/go-lib-micro/ws/menderclient github.com/mendersoftware/go-lib-micro/ws/portforward @@ -996,120 +1032,118 @@ internal/weak slices maps -internal/bisect internal/testlog internal/singleflight +internal/bisect runtime/cgo -internal/godebug errors sort +internal/godebug internal/oserror -strconv io -path +strconv +syscall crypto/internal/edwards25519/field -crypto/internal/nistec/fiat +math/rand vendor/golang.org/x/net/dns/dnsmessage +path +crypto/internal/nistec/fiat math/rand/v2 -syscall -math/rand -reflect strings bytes -crypto/internal/randutil hash -crypto -crypto/rc4 +crypto/internal/randutil internal/concurrent crypto/internal/edwards25519 hash/crc32 -crypto/md5 +reflect +crypto +crypto/rc4 unique +crypto/md5 crypto/cipher -github.com/vmihailenco/tagparser/v2/internal/parser vendor/golang.org/x/text/transform +github.com/vmihailenco/tagparser/v2/internal/parser +net/netip bufio -html regexp/syntax net/http/internal/ascii -net/netip +html github.com/vmihailenco/tagparser/v2 net/http/internal/testcert crypto/internal/boring crypto/des crypto/sha1 crypto/aes +crypto/sha512 crypto/hmac crypto/sha256 -crypto/sha512 vendor/golang.org/x/crypto/hkdf time -internal/syscall/unix internal/syscall/execenv +internal/syscall/unix regexp +internal/fmtsort +encoding/binary context io/fs github.com/mendersoftware/go-lib-micro/ws/filetransfer internal/poll -internal/filepathlite -embed -internal/fmtsort -encoding/binary -crypto/internal/nistec -os encoding/base64 vendor/golang.org/x/crypto/chacha20 vendor/golang.org/x/crypto/internal/poly1305 -golang.org/x/sys/unix +internal/filepathlite +embed encoding/pem +golang.org/x/sys/unix vendor/golang.org/x/crypto/chacha20poly1305 +os +crypto/internal/nistec +github.com/mendersoftware/mender-connect/client/dbus/test crypto/ecdh fmt path/filepath io/ioutil vendor/golang.org/x/sys/cpu os/signal +net os/exec vendor/golang.org/x/crypto/sha3 -net -github.com/mendersoftware/mender-connect/client/dbus/test -github.com/mendersoftware/mender-connect/procps -github.com/creack/pty github.com/pkg/errors encoding/json log -net/url flag text/template/parse github.com/russross/blackfriday/v2 github.com/xrash/smetrics +net/url text/tabwriter -os/user github.com/mendersoftware/mender-connect/client/dbus +os/user compress/flate math/big encoding/hex vendor/golang.org/x/text/unicode/bidi vendor/golang.org/x/text/unicode/norm -compress/gzip text/template +compress/gzip vendor/golang.org/x/net/http2/hpack mime vendor/golang.org/x/text/secure/bidirule +github.com/cpuguy83/go-md2man/v2/md2man mime/quotedprintable -github.com/sirupsen/logrus net/http/internal github.com/vmihailenco/msgpack/v5 -github.com/cpuguy83/go-md2man/v2/md2man database/sql/driver +github.com/mendersoftware/mender-connect/procps +github.com/creack/pty +github.com/sirupsen/logrus github.com/davecgh/go-spew/spew -github.com/pmezard/go-difflib/difflib -github.com/stretchr/objx -gopkg.in/yaml.v3 github.com/urfave/cli/v2 -vendor/golang.org/x/net/idna +github.com/pmezard/go-difflib/difflib github.com/go-ozzo/ozzo-validation/v4 -runtime/debug +vendor/golang.org/x/net/idna +github.com/stretchr/objx crypto/rand crypto/elliptic crypto/internal/bigmod @@ -1120,6 +1154,8 @@ crypto/internal/mlkem768 crypto/dsa github.com/mendersoftware/mender-connect/session/model +gopkg.in/yaml.v3 +runtime/debug crypto/rsa vendor/golang.org/x/crypto/cryptobyte crypto/x509/pkix @@ -1127,9 +1163,9 @@ crypto/ecdsa github.com/mendersoftware/mender-connect/config github.com/mendersoftware/mender-connect/limits/filetransfer +net/textproto crypto/x509 vendor/golang.org/x/net/http/httpproxy -net/textproto vendor/golang.org/x/net/http/httpguts mime/multipart crypto/tls @@ -1145,10 +1181,10 @@ github.com/mendersoftware/mender-connect/session github.com/stretchr/testify/mock github.com/mendersoftware/mender-connect/app -github.com/mendersoftware/mender-connect/cli github.com/mendersoftware/mender-connect/client/dbus/mocks github.com/mendersoftware/mender-connect/session/mocks github.com/mendersoftware/mender-connect/client/mender/mocks +github.com/mendersoftware/mender-connect/cli github.com/mendersoftware/mender-connect make[1]: Leaving directory '/build/reproducible-path/mender-connect-2.3.0+ds1' debian/rules override_dh_auto_test @@ -1157,20 +1193,20 @@ --bus-type=system \ --max-wait=600 \ -t dh_auto_test -DBus daemon: unix:path=/tmp/dbus-nVbREd9P2B,guid=76e1333d883c62d7e953b605677dc074 -task-0: Started with PID: 2792114 +DBus daemon: unix:path=/tmp/dbus-HMG3ijvtoj,guid=6da1d871507c1af796c905aa677dc14f +task-0: Started with PID: 1988222 task-0: cd _build && go test -vet=off -v -p 12 github.com/mendersoftware/mender-connect github.com/mendersoftware/mender-connect/app github.com/mendersoftware/mender-connect/cli github.com/mendersoftware/mender-connect/client/dbus github.com/mendersoftware/mender-connect/client/dbus/mocks github.com/mendersoftware/mender-connect/client/dbus/test github.com/mendersoftware/mender-connect/client/mender github.com/mendersoftware/mender-connect/client/mender/mocks github.com/mendersoftware/mender-connect/config github.com/mendersoftware/mender-connect/connection github.com/mendersoftware/mender-connect/connectionmanager github.com/mendersoftware/mender-connect/limits/filetransfer github.com/mendersoftware/mender-connect/procps github.com/mendersoftware/mender-connect/session github.com/mendersoftware/mender-connect/session/mocks github.com/mendersoftware/mender-connect/session/model github.com/mendersoftware/mender-connect/shell github.com/mendersoftware/mender-connect/utils task-0: === RUN TestMainExitCodes task-0: unknown runtime: go1.23.4 task-0: --- PASS: TestMainExitCodes (0.00s) task-0: === RUN TestMainRequiresConfig -task-0: time="2025-01-07T12:02:32-12:00" level=info msg="No configuration files present. Using defaults" -task-0: time="2025-01-07T12:02:32-12:00" level=warning msg="ShellCommand is empty, defaulting to /bin/sh" -task-0: time="2025-01-07T12:02:32-12:00" level=warning msg="ShellArguments is empty, defaulting to [--login]" -task-0: time="2025-01-07T12:02:32-12:00" level=error msg="please provide a user to run the shell as" +task-0: time="2025-01-08T14:05:48+14:00" level=info msg="No configuration files present. Using defaults" +task-0: time="2025-01-08T14:05:48+14:00" level=warning msg="ShellCommand is empty, defaulting to /bin/sh" +task-0: time="2025-01-08T14:05:48+14:00" level=warning msg="ShellArguments is empty, defaulting to [--login]" +task-0: time="2025-01-08T14:05:48+14:00" level=error msg="please provide a user to run the shell as" task-0: --- PASS: TestMainRequiresConfig (0.00s) task-0: PASS -task-0: ok github.com/mendersoftware/mender-connect 0.044s +task-0: ok github.com/mendersoftware/mender-connect 0.027s task-0: ? github.com/mendersoftware/mender-connect/cli [no test files] task-0: ? github.com/mendersoftware/mender-connect/client/dbus/mocks [no test files] task-0: ? github.com/mendersoftware/mender-connect/client/dbus/test [no test files] @@ -1181,41 +1217,44 @@ task-0: daemon_test.go:143: starting mock httpd with websockets task-0: newShellTransaction sendMessage(SpwanShell)= task-0: daemon_test.go:166: read message: type, session_id, data new, c4993deb-26b4-4c58-aaee-fd0c9e694328, -task-0: time="2025-01-07T12:02:32-12:00" level=info msg="mender-connect starting shell command passing process, pid: 2797181" +task-0: time="2025-01-08T14:05:48+14:00" level=info msg="mender-connect starting shell command passing process, pid: 1995946" task-0: newShellTransaction (0) sendMessage=&{Header:{Proto:1 MsgType:new SessionID:c4993deb-26b4-4c58-aaee-fd0c9e694328 Properties:map[status:1]} Body:[83 104 101 108 108 32 115 116 97 114 116 101 100]}, task-0: newShellTransaction (1) sendMessage= task-0: newShellTransaction (2) sendMessage= task-0: newShellTransaction (3) sendMessage= task-0: newShellTransaction (4) sendMessage= -task-0: daemon_test.go:175: read message: type, session_id, data shell, c4993deb-26b4-4c58-aaee-fd0c9e694328, echo newShellTransaction.5655868 > /tmp/TestMenderShellExec2506819832 -task-0: daemon_test.go:182: read message: type, session_id, data shell, undefined-session-id, rm -f /tmp/TestMenderShellExec2506819832 -task-0: time="2025-01-07T12:02:32-12:00" level=error msg="session not found" +task-0: daemon_test.go:175: read message: type, session_id, data shell, c4993deb-26b4-4c58-aaee-fd0c9e694328, echo newShellTransaction.830158 > /tmp/TestMenderShellExec3839954432 +task-0: daemon_test.go:182: read message: type, session_id, data shell, undefined-session-id, rm -f /tmp/TestMenderShellExec3839954432 +task-0: time="2025-01-08T14:05:48+14:00" level=error msg="session not found" task-0: daemon_test.go:185: route message error: session not found task-0: daemon_test.go:189: read message: type, session_id, data shell, c4993deb-26b4-4c58-aaee-fd0c9e694328, thiscommand probably does not exist task-0: daemon_test.go:196: read message: type, session_id, data stop, undefined-session-id, -task-0: time="2025-01-07T12:02:32-12:00" level=error msg="routeMessage: StopShellMessage: session not found for id undefined-session-id" +task-0: time="2025-01-08T14:05:48+14:00" level=error msg="routeMessage: StopShellMessage: session not found for id undefined-session-id" task-0: daemon_test.go:199: route message error: routeMessage: StopShellMessage: session not found for id undefined-session-id task-0: daemon_test.go:203: read message: type, session_id, data stop, c4993deb-26b4-4c58-aaee-fd0c9e694328, -task-0: time="2025-01-07T12:02:36-12:00" level=info msg="session c4993deb-26b4-4c58-aaee-fd0c9e694328 status:0 stopping shell" +task-0: time="2025-01-08T14:05:52+14:00" level=info msg="session c4993deb-26b4-4c58-aaee-fd0c9e694328 status:0 stopping shell" task-0: daemon_test.go:209: checking command execution results -task-0: daemon_test.go:212: checking if /tmp/TestMenderShellExec2506819832 contains newShellTransaction.5655868 -task-0: daemon_test.go:215: got: 'newShellTransaction.5655868' -task-0: --- PASS: TestMenderShellSessionStart (8.05s) +task-0: daemon_test.go:212: checking if /tmp/TestMenderShellExec3839954432 contains newShellTransaction.830158 +task-0: daemon_test.go:215: got: 'newShellTransaction.830158' +task-0: --- PASS: TestMenderShellSessionStart (8.04s) task-0: === RUN TestMenderShellStopByUserId task-0: daemon_test.go:253: starting mock httpd with websockets task-0: newShellStopByUserId starting task-0: (0) newShellStopByUserId sendMessage: task-0: daemon_test.go:278: read message: type, session_id, data new, c4993deb-26b4-4c58-aaee-fd0c9e694328, -task-0: time="2025-01-07T12:02:43-12:00" level=info msg="mender-connect starting shell command passing process, pid: 2797928" +task-0: time="2025-01-08T14:05:58+14:00" level=info msg="mender-connect starting shell command passing process, pid: 1999385" task-0: (1) newShellStopByUserId sendMessage: task-0: (2) newShellStopByUserId sendMessage: -task-0: (3) newShellStopByUserId sendMessage: task-0: daemon_test.go:292: read message: type, session_id, data stop, c4993deb-26b4-4c58-aaee-fd0c9e694328, -task-0: time="2025-01-07T12:02:43-12:00" level=info msg="session c4993deb-26b4-4c58-aaee-fd0c9e694328 status:0 stopping shell" +task-0: (3) newShellStopByUserId sendMessage: +task-0: time="2025-01-08T14:05:58+14:00" level=info msg="session c4993deb-26b4-4c58-aaee-fd0c9e694328 status:0 stopping shell" +task-0: time="2025-01-08T14:05:58+14:00" level=error msg="error reading stdout: read /dev/ptmx: input/output error" +task-0: time="2025-01-08T14:06:03+14:00" level=error msg="session c4993deb-26b4-4c58-aaee-fd0c9e694328, shell pid 1999385, termination error: error waiting for the process: signal: interrupt" +task-0: time="2025-01-08T14:06:03+14:00" level=error msg="process error on exit: error waiting for the process: signal: interrupt" task-0: daemon_test.go:299: read message: type, session_id, data stop, c4993deb-26b4-4c58-aaee-fd0c9e694328, -task-0: time="2025-01-07T12:02:47-12:00" level=error msg="routeMessage: StopShellMessage: session not found for id c4993deb-26b4-4c58-aaee-fd0c9e694328" +task-0: time="2025-01-08T14:06:03+14:00" level=error msg="routeMessage: StopShellMessage: session not found for id c4993deb-26b4-4c58-aaee-fd0c9e694328" task-0: daemon_test.go:302: route message error: routeMessage: StopShellMessage: session not found for id c4993deb-26b4-4c58-aaee-fd0c9e694328 -task-0: --- PASS: TestMenderShellStopByUserId (7.03s) +task-0: --- PASS: TestMenderShellStopByUserId (7.02s) task-0: === RUN TestMenderShellUnknownMessage task-0: daemon_test.go:332: starting mock httpd with websockets task-0: newShellUnknownMessage starting @@ -1226,33 +1265,33 @@ task-0: daemon_test.go:391: starting mock httpd with websockets task-0: newShellMulti: starting task-0: -task-0: daemon_test.go:424: read message: type, session_id, data new, 039edb07-c2ba-41a4-b28d-250bceab5060, -task-0: time="2025-01-07T12:02:50-12:00" level=info msg="mender-connect starting shell command passing process, pid: 2798526" -task-0: daemon_test.go:424: read message: type, session_id, data new, a3ec2f99-68dd-45fc-9a2d-e3b8a9f938c0, -task-0: time="2025-01-07T12:02:50-12:00" level=info msg="mender-connect starting shell command passing process, pid: 2798528" -task-0: daemon_test.go:433: read message: type, session_id, data new, e393c102-8b93-49bb-a19d-30c76ab8fd87, -task-0: time="2025-01-07T12:02:50-12:00" level=error msg="user has too many open sessions" +task-0: daemon_test.go:424: read message: type, session_id, data new, 67d2cfc1-f73b-40ee-9ff2-17d5c985a9bb, +task-0: time="2025-01-08T14:06:06+14:00" level=info msg="mender-connect starting shell command passing process, pid: 2002612" +task-0: daemon_test.go:424: read message: type, session_id, data new, 3f26fde2-11f9-4cdb-9c57-dd7af987cc1a, +task-0: time="2025-01-08T14:06:06+14:00" level=info msg="mender-connect starting shell command passing process, pid: 2002614" +task-0: daemon_test.go:433: read message: type, session_id, data new, 9b3c7e65-cc2e-468d-b1b6-13189677426c, +task-0: time="2025-01-08T14:06:06+14:00" level=error msg="user has too many open sessions" task-0: daemon_test.go:436: route message error: user has too many open sessions -task-0: --- PASS: TestMenderShellSessionLimitPerUser (0.01s) +task-0: --- PASS: TestMenderShellSessionLimitPerUser (0.02s) task-0: === RUN TestMenderShellStopDaemon task-0: --- PASS: TestMenderShellStopDaemon (0.00s) task-0: === RUN TestMenderShellReadMessage task-0: daemon_test.go:502: starting mock httpd with websockets -task-0: --- PASS: TestMenderShellReadMessage (10.00s) +task-0: --- PASS: TestMenderShellReadMessage (10.01s) task-0: === RUN TestMenderShellMaxShellsLimit task-0: daemon_test.go:546: starting mock httpd with websockets task-0: newShellMulti: starting task-0: task-0: newShellMulti: starting task-0: -task-0: daemon_test.go:578: read message: type, session_id, data new, e3e25a5a-2944-41c4-9cfe-f96d0b0e05cb, -task-0: time="2025-01-07T12:03:01-12:00" level=info msg="mender-connect starting shell command passing process, pid: 2799461" -task-0: daemon_test.go:578: read message: type, session_id, data new, 55bd8078-31a8-4cbe-88dd-811ac29e4347, -task-0: time="2025-01-07T12:03:02-12:00" level=info msg="mender-connect starting shell command passing process, pid: 2799491" -task-0: daemon_test.go:587: read message: type, session_id, data new, e643ad7c-2c53-4c4e-b593-3960208425fe, -task-0: time="2025-01-07T12:03:02-12:00" level=error msg="too many shells spawned" +task-0: daemon_test.go:578: read message: type, session_id, data new, 5a42fcd0-0b9c-41e8-a10c-d29b03708cf9, +task-0: time="2025-01-08T14:06:17+14:00" level=info msg="mender-connect starting shell command passing process, pid: 2008049" +task-0: daemon_test.go:578: read message: type, session_id, data new, 911b9add-52b2-4a1e-9107-57d7d054d8b6, +task-0: time="2025-01-08T14:06:18+14:00" level=info msg="mender-connect starting shell command passing process, pid: 2008529" +task-0: daemon_test.go:587: read message: type, session_id, data new, 4bcb005a-d102-4dbf-84d0-b9af74cc0a33, +task-0: time="2025-01-08T14:06:18+14:00" level=error msg="too many shells spawned" task-0: daemon_test.go:590: route message error: too many shells spawned -task-0: --- PASS: TestMenderShellMaxShellsLimit (2.04s) +task-0: --- PASS: TestMenderShellMaxShellsLimit (2.02s) task-0: === RUN TestMenderShellNeedsReconnect task-0: --- PASS: TestMenderShellNeedsReconnect (1.00s) task-0: === RUN TestMenderShellPostEvent @@ -1260,25 +1299,25 @@ task-0: === RUN TestMenderShellReadEvent task-0: --- PASS: TestMenderShellReadEvent (0.00s) task-0: === RUN TestOutputStatus -task-0: time="2025-01-07T12:03:03-12:00" level=info msg="mender-connect daemon vunknown" -task-0: time="2025-01-07T12:03:03-12:00" level=info msg=" status: " -task-0: time="2025-01-07T12:03:03-12:00" level=info msg=" shells: 0/2" -task-0: time="2025-01-07T12:03:03-12:00" level=info msg=" sessions: 4" -task-0: time="2025-01-07T12:03:03-12:00" level=info msg=" id:039edb07-c2ba-41a4-b28d-250bceab5060 status:0 started:Wed Jan 8 00:02:50 +0000 UTC 2025" -task-0: time="2025-01-07T12:03:03-12:00" level=info msg=" expires:Wed Jan 8 00:04:58 +0000 UTC 2025 active:Wed Jan 8 00:02:50 +0000 UTC 2025" -task-0: time="2025-01-07T12:03:03-12:00" level=info msg=" shell:/bin/sh" -task-0: time="2025-01-07T12:03:03-12:00" level=info msg=" id:a3ec2f99-68dd-45fc-9a2d-e3b8a9f938c0 status:0 started:Wed Jan 8 00:02:50 +0000 UTC 2025" -task-0: time="2025-01-07T12:03:03-12:00" level=info msg=" expires:Wed Jan 8 00:04:58 +0000 UTC 2025 active:Wed Jan 8 00:02:50 +0000 UTC 2025" -task-0: time="2025-01-07T12:03:03-12:00" level=info msg=" shell:/bin/sh" -task-0: time="2025-01-07T12:03:03-12:00" level=info msg=" id:e3e25a5a-2944-41c4-9cfe-f96d0b0e05cb status:0 started:Wed Jan 8 00:03:01 +0000 UTC 2025" -task-0: time="2025-01-07T12:03:03-12:00" level=info msg=" expires:Wed Jan 8 00:20:05 +0000 UTC 2025 active:Wed Jan 8 00:03:01 +0000 UTC 2025" -task-0: time="2025-01-07T12:03:03-12:00" level=info msg=" shell:/bin/sh" -task-0: time="2025-01-07T12:03:03-12:00" level=info msg=" id:55bd8078-31a8-4cbe-88dd-811ac29e4347 status:0 started:Wed Jan 8 00:03:02 +0000 UTC 2025" -task-0: time="2025-01-07T12:03:03-12:00" level=info msg=" expires:Wed Jan 8 00:20:06 +0000 UTC 2025 active:Wed Jan 8 00:03:02 +0000 UTC 2025" -task-0: time="2025-01-07T12:03:03-12:00" level=info msg=" shell:/bin/sh" -task-0: time="2025-01-07T12:03:03-12:00" level=info msg=" file-transfer:" -task-0: time="2025-01-07T12:03:03-12:00" level=info msg=" total: tx/rx 0/0" -task-0: time="2025-01-07T12:03:03-12:00" level=info msg=" 1m: tx rx 0.00 0.00 (w)" +task-0: time="2025-01-08T14:06:19+14:00" level=info msg="mender-connect daemon vunknown" +task-0: time="2025-01-08T14:06:19+14:00" level=info msg=" status: " +task-0: time="2025-01-08T14:06:19+14:00" level=info msg=" shells: 0/2" +task-0: time="2025-01-08T14:06:19+14:00" level=info msg=" sessions: 4" +task-0: time="2025-01-08T14:06:19+14:00" level=info msg=" id:67d2cfc1-f73b-40ee-9ff2-17d5c985a9bb status:0 started:Wed Jan 8 00:06:06 +0000 UTC 2025" +task-0: time="2025-01-08T14:06:19+14:00" level=info msg=" expires:Wed Jan 8 00:08:14 +0000 UTC 2025 active:Wed Jan 8 00:06:06 +0000 UTC 2025" +task-0: time="2025-01-08T14:06:19+14:00" level=info msg=" shell:/bin/sh" +task-0: time="2025-01-08T14:06:19+14:00" level=info msg=" id:3f26fde2-11f9-4cdb-9c57-dd7af987cc1a status:0 started:Wed Jan 8 00:06:06 +0000 UTC 2025" +task-0: time="2025-01-08T14:06:19+14:00" level=info msg=" expires:Wed Jan 8 00:08:14 +0000 UTC 2025 active:Wed Jan 8 00:06:06 +0000 UTC 2025" +task-0: time="2025-01-08T14:06:19+14:00" level=info msg=" shell:/bin/sh" +task-0: time="2025-01-08T14:06:19+14:00" level=info msg=" id:5a42fcd0-0b9c-41e8-a10c-d29b03708cf9 status:0 started:Wed Jan 8 00:06:17 +0000 UTC 2025" +task-0: time="2025-01-08T14:06:19+14:00" level=info msg=" expires:Wed Jan 8 00:23:21 +0000 UTC 2025 active:Wed Jan 8 00:06:17 +0000 UTC 2025" +task-0: time="2025-01-08T14:06:19+14:00" level=info msg=" shell:/bin/sh" +task-0: time="2025-01-08T14:06:19+14:00" level=info msg=" id:911b9add-52b2-4a1e-9107-57d7d054d8b6 status:0 started:Wed Jan 8 00:06:18 +0000 UTC 2025" +task-0: time="2025-01-08T14:06:19+14:00" level=info msg=" expires:Wed Jan 8 00:23:22 +0000 UTC 2025 active:Wed Jan 8 00:06:18 +0000 UTC 2025" +task-0: time="2025-01-08T14:06:19+14:00" level=info msg=" shell:/bin/sh" +task-0: time="2025-01-08T14:06:19+14:00" level=info msg=" file-transfer:" +task-0: time="2025-01-08T14:06:19+14:00" level=info msg=" total: tx/rx 0/0" +task-0: time="2025-01-08T14:06:19+14:00" level=info msg=" 1m: tx rx 0.00 0.00 (w)" task-0: --- PASS: TestOutputStatus (0.00s) task-0: === RUN TestTimeToSweepSessions task-0: --- PASS: TestTimeToSweepSessions (4.00s) @@ -1287,7 +1326,7 @@ task-0: === RUN TestDBusEventLoop/token_not_returned_wait_forever task-0: === NAME TestDBusEventLoop task-0: daemon_test.go:797: ok: expected to run forever -task-0: --- PASS: TestDBusEventLoop (16.01s) +task-0: --- PASS: TestDBusEventLoop (16.00s) task-0: --- PASS: TestDBusEventLoop/stopped-gracefully (1.00s) task-0: === RUN TestEventLoop task-0: === RUN TestEventLoop/stopped-gracefully @@ -1303,19 +1342,19 @@ task-0: === NAME TestMessageMainLoop task-0: daemon_test.go:993: ok: expected to run forever task-0: === RUN TestMessageMainLoop/ws-nil-error -task-0: time="2025-01-07T12:03:55-12:00" level=error msg="session a3ec2f99-68dd-45fc-9a2d-e3b8a9f938c0, health check failed, connection with the client lost" -task-0: time="2025-01-07T12:03:55-12:00" level=info msg="session a3ec2f99-68dd-45fc-9a2d-e3b8a9f938c0 status:0 stopping shell" -task-0: time="2025-01-07T12:03:55-12:00" level=error msg="session 039edb07-c2ba-41a4-b28d-250bceab5060, health check failed, connection with the client lost" -task-0: time="2025-01-07T12:03:55-12:00" level=info msg="session 039edb07-c2ba-41a4-b28d-250bceab5060 status:0 stopping shell" -task-0: time="2025-01-07T12:03:59-12:00" level=info msg="session 039edb07-c2ba-41a4-b28d-250bceab5060 successfully stopped" -task-0: time="2025-01-07T12:03:59-12:00" level=info msg="session a3ec2f99-68dd-45fc-9a2d-e3b8a9f938c0 successfully stopped" -task-0: time="2025-01-07T12:04:06-12:00" level=error msg="session e3e25a5a-2944-41c4-9cfe-f96d0b0e05cb, health check failed, connection with the client lost" -task-0: time="2025-01-07T12:04:06-12:00" level=info msg="session e3e25a5a-2944-41c4-9cfe-f96d0b0e05cb status:0 stopping shell" -task-0: time="2025-01-07T12:04:07-12:00" level=error msg="session 55bd8078-31a8-4cbe-88dd-811ac29e4347, health check failed, connection with the client lost" -task-0: time="2025-01-07T12:04:07-12:00" level=info msg="session 55bd8078-31a8-4cbe-88dd-811ac29e4347 status:0 stopping shell" +task-0: time="2025-01-08T14:07:11+14:00" level=error msg="session 3f26fde2-11f9-4cdb-9c57-dd7af987cc1a, health check failed, connection with the client lost" +task-0: time="2025-01-08T14:07:11+14:00" level=info msg="session 3f26fde2-11f9-4cdb-9c57-dd7af987cc1a status:0 stopping shell" +task-0: time="2025-01-08T14:07:11+14:00" level=error msg="session 67d2cfc1-f73b-40ee-9ff2-17d5c985a9bb, health check failed, connection with the client lost" +task-0: time="2025-01-08T14:07:11+14:00" level=info msg="session 67d2cfc1-f73b-40ee-9ff2-17d5c985a9bb status:0 stopping shell" +task-0: time="2025-01-08T14:07:15+14:00" level=info msg="session 3f26fde2-11f9-4cdb-9c57-dd7af987cc1a successfully stopped" +task-0: time="2025-01-08T14:07:15+14:00" level=info msg="session 67d2cfc1-f73b-40ee-9ff2-17d5c985a9bb successfully stopped" +task-0: time="2025-01-08T14:07:22+14:00" level=error msg="session 5a42fcd0-0b9c-41e8-a10c-d29b03708cf9, health check failed, connection with the client lost" +task-0: time="2025-01-08T14:07:22+14:00" level=info msg="session 5a42fcd0-0b9c-41e8-a10c-d29b03708cf9 status:0 stopping shell" +task-0: time="2025-01-08T14:07:23+14:00" level=error msg="session 911b9add-52b2-4a1e-9107-57d7d054d8b6, health check failed, connection with the client lost" +task-0: time="2025-01-08T14:07:23+14:00" level=info msg="session 911b9add-52b2-4a1e-9107-57d7d054d8b6 status:0 stopping shell" task-0: === NAME TestMessageMainLoop task-0: daemon_test.go:993: ok: expected to run forever -task-0: --- PASS: TestMessageMainLoop (30.01s) +task-0: --- PASS: TestMessageMainLoop (30.00s) task-0: --- PASS: TestMessageMainLoop/normal-exit (0.00s) task-0: === RUN TestRun task-0: --- PASS: TestRun (0.00s) @@ -1350,9 +1389,9 @@ task-0: --- PASS: TestRouteMessage/ok,_session_router (0.00s) task-0: --- PASS: TestRouteMessage/error,_session_router (0.00s) task-0: === CONT TestDecreaseSpawnedShellsCount/decrease_by_0_with_0 -task-0: time="2025-01-07T12:04:09-12:00" level=warning msg="can't decrement shellsSpawned count: it is 0." +task-0: time="2025-01-08T14:07:25+14:00" level=warning msg="can't decrement shellsSpawned count: it is 0." task-0: === CONT TestDecreaseSpawnedShellsCount/decrease_by_many_with_0 -task-0: time="2025-01-07T12:04:09-12:00" level=warning msg="can't decrement shellsSpawned count: it is 0." +task-0: time="2025-01-08T14:07:25+14:00" level=warning msg="can't decrement shellsSpawned count: it is 0." task-0: === CONT TestDecreaseSpawnedShellsCount/decrease_by_some_with_many task-0: === CONT TestDecreaseSpawnedShellsCount/decrease_by_many_with_some task-0: === CONT TestDecreaseSpawnedShellsCount/decrease_by_many_with_many @@ -1366,23 +1405,23 @@ task-0: --- PASS: TestDecreaseSpawnedShellsCount/decrease_by_many_with_many (0.00s) task-0: --- PASS: TestDecreaseSpawnedShellsCount/decrease_by_1_with_many (0.00s) task-0: PASS -task-0: ok github.com/mendersoftware/mender-connect/app 96.231s +task-0: ok github.com/mendersoftware/mender-connect/app 96.148s task-0: === RUN TestBusGet -task-0: --- PASS: TestBusGet (0.02s) +task-0: --- PASS: TestBusGet (0.25s) task-0: === RUN TestBusProxyNew task-0: === RUN TestBusProxyNew/ok task-0: === RUN TestBusProxyNew/ko,_wrong_path task-0: -task-0: (process:2797758): GLib-GIO-CRITICAL **: 12:02:41.408: g_dbus_proxy_new_sync: assertion 'g_variant_is_object_path (object_path)' failed -task-0: --- PASS: TestBusProxyNew (0.00s) -task-0: --- PASS: TestBusProxyNew/ok (0.00s) +task-0: (process:1997731): GLib-GIO-CRITICAL **: 14:05:53.796: g_dbus_proxy_new_sync: assertion 'g_variant_is_object_path (object_path)' failed +task-0: --- PASS: TestBusProxyNew (0.01s) +task-0: --- PASS: TestBusProxyNew/ok (0.01s) task-0: --- PASS: TestBusProxyNew/ko,_wrong_path (0.00s) task-0: === RUN TestBusProxyCall task-0: === RUN TestBusProxyCall/ok task-0: === RUN TestBusProxyCall/ko,_already_handled_Hello_message -task-0: --- PASS: TestBusProxyCall (0.00s) +task-0: --- PASS: TestBusProxyCall (0.01s) task-0: --- PASS: TestBusProxyCall/ok (0.00s) -task-0: --- PASS: TestBusProxyCall/ko,_already_handled_Hello_message (0.00s) +task-0: --- PASS: TestBusProxyCall/ko,_already_handled_Hello_message (0.01s) task-0: === RUN TestMainLoop task-0: --- PASS: TestMainLoop (0.10s) task-0: === RUN TestWaitForSignal @@ -1395,19 +1434,19 @@ task-0: === RUN TestError task-0: --- PASS: TestError (0.00s) task-0: PASS -task-0: ok github.com/mendersoftware/mender-connect/client/dbus 0.292s +task-0: ok github.com/mendersoftware/mender-connect/client/dbus 0.501s task-0: === RUN TestNewAuthClientDefaultDBusAPI task-0: --- PASS: TestNewAuthClientDefaultDBusAPI (0.00s) task-0: === RUN TestNewAuthClient task-0: --- PASS: TestNewAuthClient (0.00s) task-0: === RUN TestAuthClientConnect +task-0: === RUN TestAuthClientConnect/error_ProxyNew task-0: === RUN TestAuthClientConnect/ok task-0: === RUN TestAuthClientConnect/error_BusGet -task-0: === RUN TestAuthClientConnect/error_ProxyNew task-0: --- PASS: TestAuthClientConnect (0.00s) +task-0: --- PASS: TestAuthClientConnect/error_ProxyNew (0.00s) task-0: --- PASS: TestAuthClientConnect/ok (0.00s) task-0: --- PASS: TestAuthClientConnect/error_BusGet (0.00s) -task-0: --- PASS: TestAuthClientConnect/error_ProxyNew (0.00s) task-0: === RUN TestAuthClientGetJWTToken task-0: === RUN TestAuthClientGetJWTToken/ok task-0: === RUN TestAuthClientGetJWTToken/error @@ -1421,58 +1460,58 @@ task-0: --- PASS: TestAuthClientFetchJWTToken/ok (0.00s) task-0: --- PASS: TestAuthClientFetchJWTToken/error (0.00s) task-0: === RUN TestAuthClientWaitForJwtTokenStateChange +task-0: === RUN TestAuthClientWaitForJwtTokenStateChange/ok-no-params task-0: === RUN TestAuthClientWaitForJwtTokenStateChange/ok-with-params task-0: === RUN TestAuthClientWaitForJwtTokenStateChange/error -task-0: === RUN TestAuthClientWaitForJwtTokenStateChange/ok-no-params task-0: --- PASS: TestAuthClientWaitForJwtTokenStateChange (0.00s) +task-0: --- PASS: TestAuthClientWaitForJwtTokenStateChange/ok-no-params (0.00s) task-0: --- PASS: TestAuthClientWaitForJwtTokenStateChange/ok-with-params (0.00s) task-0: --- PASS: TestAuthClientWaitForJwtTokenStateChange/error (0.00s) -task-0: --- PASS: TestAuthClientWaitForJwtTokenStateChange/ok-no-params (0.00s) task-0: PASS -task-0: ok github.com/mendersoftware/mender-connect/client/mender 0.061s +task-0: ok github.com/mendersoftware/mender-connect/client/mender 0.046s task-0: === RUN Test_readConfigFile_noFile_returnsError task-0: --- PASS: Test_readConfigFile_noFile_returnsError (0.00s) task-0: === RUN Test_readConfigFile_brokenContent_returnsError -task-0: time="2025-01-07T12:02:41-12:00" level=error msg="Error loading configuration from file: /tmp/mendertest1210546678/mender-connect.conf (Error parsing mender configuration file: invalid character '\"' after object key:value pair)" -task-0: time="2025-01-07T12:02:41-12:00" level=error msg="Error loading configuration from file: /tmp/mendertest1210546678/mender-connect.conf (Error parsing mender configuration file: invalid character '\"' after object key:value pair)" +task-0: time="2025-01-08T14:05:53+14:00" level=error msg="Error loading configuration from file: /tmp/mendertest45828323/mender-connect.conf (Error parsing mender configuration file: invalid character '\"' after object key:value pair)" +task-0: time="2025-01-08T14:05:53+14:00" level=error msg="Error loading configuration from file: /tmp/mendertest45828323/mender-connect.conf (Error parsing mender configuration file: invalid character '\"' after object key:value pair)" task-0: --- PASS: Test_readConfigFile_brokenContent_returnsError (0.00s) task-0: === RUN Test_LoadConfig_correctConfFile_returnsConfiguration -task-0: time="2025-01-07T12:02:41-12:00" level=info msg="Loaded configuration file: /tmp/mendertest3311719258/mender-connect.conf" -task-0: time="2025-01-07T12:02:41-12:00" level=warning msg="ShellCommand is empty, defaulting to /bin/sh" -task-0: time="2025-01-07T12:02:41-12:00" level=warning msg="ShellArguments is empty, defaulting to [--login]" -task-0: time="2025-01-07T12:02:41-12:00" level=warning msg="both ExpireAfter and ExpireAfterIdle specified." -task-0: time="2025-01-07T12:02:41-12:00" level=info msg="Loaded configuration file: /tmp/mendertest3311719258/mender-connect.conf" -task-0: time="2025-01-07T12:02:41-12:00" level=warning msg="ShellCommand is empty, defaulting to /bin/sh" -task-0: time="2025-01-07T12:02:41-12:00" level=warning msg="ShellArguments is empty, defaulting to [--login]" -task-0: time="2025-01-07T12:02:41-12:00" level=warning msg="both ExpireAfter and ExpireAfterIdle specified." -task-0: --- PASS: Test_LoadConfig_correctConfFile_returnsConfiguration (0.00s) +task-0: time="2025-01-08T14:05:53+14:00" level=info msg="Loaded configuration file: /tmp/mendertest4172302335/mender-connect.conf" +task-0: time="2025-01-08T14:05:53+14:00" level=warning msg="ShellCommand is empty, defaulting to /bin/sh" +task-0: time="2025-01-08T14:05:53+14:00" level=warning msg="ShellArguments is empty, defaulting to [--login]" +task-0: time="2025-01-08T14:05:53+14:00" level=warning msg="both ExpireAfter and ExpireAfterIdle specified." +task-0: time="2025-01-08T14:05:53+14:00" level=info msg="Loaded configuration file: /tmp/mendertest4172302335/mender-connect.conf" +task-0: time="2025-01-08T14:05:53+14:00" level=warning msg="ShellCommand is empty, defaulting to /bin/sh" +task-0: time="2025-01-08T14:05:53+14:00" level=warning msg="ShellArguments is empty, defaulting to [--login]" +task-0: time="2025-01-08T14:05:53+14:00" level=warning msg="both ExpireAfter and ExpireAfterIdle specified." +task-0: --- PASS: Test_LoadConfig_correctConfFile_returnsConfiguration (0.01s) task-0: === RUN TestConfigurationMergeSettings -task-0: time="2025-01-07T12:02:41-12:00" level=info msg="Loaded configuration file: fallback.config" -task-0: time="2025-01-07T12:02:41-12:00" level=info msg="Loaded configuration file: main.config" +task-0: time="2025-01-08T14:05:53+14:00" level=info msg="Loaded configuration file: fallback.config" +task-0: time="2025-01-08T14:05:53+14:00" level=info msg="Loaded configuration file: main.config" task-0: --- PASS: TestConfigurationMergeSettings (0.00s) task-0: === RUN Test_LoadConfig_various_errors -task-0: time="2025-01-07T12:02:41-12:00" level=info msg="Loaded configuration file: /tmp/mendertest1866835164/mender-connect.conf" -task-0: time="2025-01-07T12:02:41-12:00" level=warning msg="ShellArguments is empty, defaulting to [--login]" -task-0: time="2025-01-07T12:02:41-12:00" level=info msg="Loaded configuration file: /tmp/mendertest1866835164/mender-connect.conf" -task-0: time="2025-01-07T12:02:41-12:00" level=warning msg="ShellArguments is empty, defaulting to [--login]" -task-0: time="2025-01-07T12:02:41-12:00" level=info msg="Loaded configuration file: /tmp/mendertest1866835164/mender-connect.conf" -task-0: time="2025-01-07T12:02:41-12:00" level=warning msg="ShellArguments is empty, defaulting to [--login]" -task-0: time="2025-01-07T12:02:41-12:00" level=info msg="Loaded configuration file: /tmp/mendertest1866835164/mender-connect.conf" -task-0: time="2025-01-07T12:02:41-12:00" level=warning msg="ShellArguments is empty, defaulting to [--login]" -task-0: time="2025-01-07T12:02:41-12:00" level=info msg="Loaded configuration file: /tmp/mendertest1866835164/mender-connect.conf" -task-0: time="2025-01-07T12:02:41-12:00" level=warning msg="ShellArguments is empty, defaulting to [--login]" -task-0: time="2025-01-07T12:02:41-12:00" level=error msg="ShellCommand /bin/ls is not present in /etc/shells" -task-0: time="2025-01-07T12:02:41-12:00" level=error msg="Error loading configuration from file: /tmp/mendertest1866835164/mender-connect.conf (Error parsing mender configuration file: invalid character '\"' after object key:value pair)" -task-0: time="2025-01-07T12:02:41-12:00" level=error msg="Error loading configuration from file: /tmp/mendertest1866835164/mender-connect.conf (Error parsing config file: json: cannot unmarshal number into Go struct field MenderShellConfigFromFile.ShellCommand of type string)" +task-0: time="2025-01-08T14:05:53+14:00" level=info msg="Loaded configuration file: /tmp/mendertest2868639527/mender-connect.conf" +task-0: time="2025-01-08T14:05:53+14:00" level=warning msg="ShellArguments is empty, defaulting to [--login]" +task-0: time="2025-01-08T14:05:53+14:00" level=info msg="Loaded configuration file: /tmp/mendertest2868639527/mender-connect.conf" +task-0: time="2025-01-08T14:05:53+14:00" level=warning msg="ShellArguments is empty, defaulting to [--login]" +task-0: time="2025-01-08T14:05:53+14:00" level=info msg="Loaded configuration file: /tmp/mendertest2868639527/mender-connect.conf" +task-0: time="2025-01-08T14:05:53+14:00" level=warning msg="ShellArguments is empty, defaulting to [--login]" +task-0: time="2025-01-08T14:05:53+14:00" level=info msg="Loaded configuration file: /tmp/mendertest2868639527/mender-connect.conf" +task-0: time="2025-01-08T14:05:53+14:00" level=warning msg="ShellArguments is empty, defaulting to [--login]" +task-0: time="2025-01-08T14:05:53+14:00" level=info msg="Loaded configuration file: /tmp/mendertest2868639527/mender-connect.conf" +task-0: time="2025-01-08T14:05:53+14:00" level=warning msg="ShellArguments is empty, defaulting to [--login]" +task-0: time="2025-01-08T14:05:53+14:00" level=error msg="ShellCommand /bin/ls is not present in /etc/shells" +task-0: time="2025-01-08T14:05:53+14:00" level=error msg="Error loading configuration from file: /tmp/mendertest2868639527/mender-connect.conf (Error parsing mender configuration file: invalid character '\"' after object key:value pair)" +task-0: time="2025-01-08T14:05:53+14:00" level=error msg="Error loading configuration from file: /tmp/mendertest2868639527/mender-connect.conf (Error parsing config file: json: cannot unmarshal number into Go struct field MenderShellConfigFromFile.ShellCommand of type string)" task-0: --- PASS: Test_LoadConfig_various_errors (0.00s) task-0: === RUN TestConfigurationNeitherFileExistsIsNotError -task-0: time="2025-01-07T12:02:41-12:00" level=info msg="No configuration files present. Using defaults" +task-0: time="2025-01-08T14:05:53+14:00" level=info msg="No configuration files present. Using defaults" task-0: --- PASS: TestConfigurationNeitherFileExistsIsNotError (0.00s) task-0: === RUN TestShellArgumentsEmptyDefaults -task-0: time="2025-01-07T12:02:41-12:00" level=info msg="Loaded configuration file: main.config" -task-0: time="2025-01-07T12:02:41-12:00" level=warning msg="ShellArguments is empty, defaulting to [--login]" -task-0: time="2025-01-07T12:02:41-12:00" level=info msg="Loaded configuration file: main.config" -task-0: time="2025-01-07T12:02:41-12:00" level=info msg="Loaded configuration file: main.config" +task-0: time="2025-01-08T14:05:53+14:00" level=info msg="Loaded configuration file: main.config" +task-0: time="2025-01-08T14:05:53+14:00" level=warning msg="ShellArguments is empty, defaulting to [--login]" +task-0: time="2025-01-08T14:05:53+14:00" level=info msg="Loaded configuration file: main.config" +task-0: time="2025-01-08T14:05:53+14:00" level=info msg="Loaded configuration file: main.config" task-0: --- PASS: TestShellArgumentsEmptyDefaults (0.00s) task-0: === RUN TestServerArgumentsDeprecated task-0: --- PASS: TestServerArgumentsDeprecated (0.00s) @@ -1490,22 +1529,22 @@ task-0: === RUN TestMenderShowVersion task-0: --- PASS: TestMenderShowVersion (0.00s) task-0: PASS -task-0: ok github.com/mendersoftware/mender-connect/config 0.065s +task-0: ok github.com/mendersoftware/mender-connect/config 0.055s task-0: === RUN TestNewConnection task-0: connection_test.go:97: starting mock httpd with websockets -task-0: --- PASS: TestNewConnection (0.01s) +task-0: --- PASS: TestNewConnection (0.00s) task-0: === RUN TestConnection_ReadMessage task-0: connection_test.go:126: starting mock httpd with websockets task-0: connection_test.go:143: read: 'hello' task-0: --- PASS: TestConnection_ReadMessage (1.01s) task-0: === RUN TestConnection_WriteMessage task-0: connection_test.go:149: starting mock httpd with websockets -task-0: --- PASS: TestConnection_WriteMessage (1.01s) +task-0: --- PASS: TestConnection_WriteMessage (1.00s) task-0: === RUN TestConnection_Close task-0: connection_test.go:174: starting mock httpd with websockets -task-0: --- PASS: TestConnection_Close (1.01s) +task-0: --- PASS: TestConnection_Close (1.00s) task-0: PASS -task-0: ok github.com/mendersoftware/mender-connect/connection 3.087s +task-0: ok github.com/mendersoftware/mender-connect/connection 3.093s task-0: === RUN TestGetWriteTimeout task-0: --- PASS: TestGetWriteTimeout (0.00s) task-0: === RUN TestGetWsScheme @@ -1513,26 +1552,26 @@ task-0: === RUN TestConnect task-0: --- PASS: TestConnect (2.01s) task-0: === RUN TestReconnect -task-0: 2025/01/07 12:02:43 [130 163 104 100 114 129 165 112 114 111 116 111 205 0 1 164 98 111 100 121 196 5 100 117 109 109 121] -task-0: 2025/01/07 12:02:43 http: panic serving 127.0.0.1:44980: websocket: close 1006 (abnormal closure): unexpected EOF -task-0: goroutine 8 [running]: +task-0: 2025/01/08 14:05:55 [130 163 104 100 114 129 165 112 114 111 116 111 205 0 1 164 98 111 100 121 196 5 100 117 109 109 121] +task-0: 2025/01/08 14:05:55 http: panic serving 127.0.0.1:43062: websocket: close 1006 (abnormal closure): unexpected EOF +task-0: goroutine 7 [running]: task-0: net/http.(*conn).serve.func1() task-0: /usr/lib/go-1.23/src/net/http/server.go:1947 +0xb0 task-0: panic({0x6eff20?, 0x9d3370?}) task-0: /usr/lib/go-1.23/src/runtime/panic.go:785 +0x124 -task-0: github.com/mendersoftware/mender-connect/connectionmanager.newWebsocketServer.func2({0x7e89b8?, 0x40000bc1c0?}, 0x40000e9b28?) +task-0: github.com/mendersoftware/mender-connect/connectionmanager.newWebsocketServer.func2({0x7e89b8?, 0x40000ba000?}, 0x40001efb28?) task-0: /build/reproducible-path/mender-connect-2.3.0+ds1/_build/src/github.com/mendersoftware/mender-connect/connectionmanager/connectionmanager_test.go:63 +0x180 -task-0: net/http.HandlerFunc.ServeHTTP(0x4000146178?, {0x7e89b8?, 0x40000bc1c0?}, 0x669d04?) +task-0: net/http.HandlerFunc.ServeHTTP(0x40001c6338?, {0x7e89b8?, 0x40000ba000?}, 0x669d04?) task-0: /usr/lib/go-1.23/src/net/http/server.go:2220 +0x38 -task-0: net/http.(*ServeMux).ServeHTTP(0x0?, {0x7e89b8, 0x40000bc1c0}, 0x40000a48c0) +task-0: net/http.(*ServeMux).ServeHTTP(0x0?, {0x7e89b8, 0x40000ba000}, 0x400009e280) task-0: /usr/lib/go-1.23/src/net/http/server.go:2747 +0x1b4 -task-0: net/http.serverHandler.ServeHTTP({0x40000a0d20?}, {0x7e89b8?, 0x40000bc1c0?}, 0x6?) +task-0: net/http.serverHandler.ServeHTTP({0x4000098270?}, {0x7e89b8?, 0x40000ba000?}, 0x6?) task-0: /usr/lib/go-1.23/src/net/http/server.go:3210 +0xbc -task-0: net/http.(*conn).serve(0x40000de240, {0x7e8f28, 0x400011b560}) +task-0: net/http.(*conn).serve(0x40000941b0, {0x7e8f28, 0x4000260030}) task-0: /usr/lib/go-1.23/src/net/http/server.go:2092 +0x4fc -task-0: created by net/http.(*Server).Serve in goroutine 22 +task-0: created by net/http.(*Server).Serve in goroutine 23 task-0: /usr/lib/go-1.23/src/net/http/server.go:3360 +0x3dc -task-0: --- PASS: TestReconnect (2.01s) +task-0: --- PASS: TestReconnect (2.04s) task-0: === RUN TestConnectFailed task-0: --- PASS: TestConnectFailed (0.00s) task-0: === RUN TestCloseFailed @@ -1546,12 +1585,12 @@ task-0: === RUN TestMaxBackoff task-0: --- PASS: TestMaxBackoff (0.00s) task-0: PASS -task-0: ok github.com/mendersoftware/mender-connect/connectionmanager 4.080s +task-0: ok github.com/mendersoftware/mender-connect/connectionmanager 4.088s task-0: === RUN TestGetCounters task-0: --- PASS: TestGetCounters (8.04s) task-0: === RUN TestUpdateCounters -task-0: limits_test.go:160: after 18s; +{24576 24576 1663.3268261488847 1663.3268261488847 {13967788944429421003 8045993484 0x7dc240} {13967788944429421083 8045993564 0x7dc240}} 1663.00 vs 1663.33=0.33 1663.00 vs 1663.33=0.33 -task-0: --- PASS: TestUpdateCounters (20.02s) +task-0: limits_test.go:160: after 18s; +{24576 24576 1663.3268261488847 1663.3268261488847 {13967789150751191824 8038909693 0x7dc240} {13967789150751191984 8038909853 0x7dc240}} 1663.00 vs 1663.33=0.33 1663.00 vs 1663.33=0.33 +task-0: --- PASS: TestUpdateCounters (20.01s) task-0: === RUN TestPermit_PreserveOwnerGroup task-0: --- PASS: TestPermit_PreserveOwnerGroup (0.00s) task-0: === RUN TestPermit_PreserveModes @@ -1613,11 +1652,11 @@ task-0: --- PASS: TestPermit_UploadFile/suid_bit_not_allowed_in_modes (0.00s) task-0: --- PASS: TestPermit_UploadFile/suid_bit_allowed_in_modes (0.00s) task-0: PASS -task-0: ok github.com/mendersoftware/mender-connect/limits/filetransfer 28.116s +task-0: ok github.com/mendersoftware/mender-connect/limits/filetransfer 28.089s task-0: === RUN TestMenderShellProcPs task-0: --- PASS: TestMenderShellProcPs (4.04s) task-0: PASS -task-0: ok github.com/mendersoftware/mender-connect/procps 4.088s +task-0: ok github.com/mendersoftware/mender-connect/procps 4.065s task-0: === RUN TestFileTransferUpload task-0: === PAUSE TestFileTransferUpload task-0: === RUN TestFileTransferDownload @@ -1629,22 +1668,22 @@ task-0: === RUN TestMenderClientHandler task-0: --- PASS: TestMenderClientHandler (0.00s) task-0: === RUN TestRunCommand -task-0: --- PASS: TestRunCommand (0.03s) +task-0: --- PASS: TestRunCommand (0.00s) task-0: === RUN TestPortForwardHandler -task-0: time="2025-01-07T12:02:43-12:00" level=error msg="portForwardHandler(unknown message type\ngithub.com/mendersoftware/mender-connect/session.init\n\t:1\nruntime.doInit1\n\t/usr/lib/go-1.23/src/runtime/proc.go:7290\nruntime.doInit\n\t/usr/lib/go-1.23/src/runtime/proc.go:7257\nruntime.main\n\t/usr/lib/go-1.23/src/runtime/proc.go:254\nruntime.goexit\n\t/usr/lib/go-1.23/src/runtime/asm_arm64.s:1223)" -task-0: time="2025-01-07T12:02:43-12:00" level=info msg="port-forward: new session/c1: tcp/localhost:35951" -task-0: time="2025-01-07T12:02:43-12:00" level=error msg="portForwardHandler(dial tcp 127.0.0.1:35951: connect: connection refused)" -task-0: time="2025-01-07T12:02:43-12:00" level=info msg="port-forward: new session/c1: dummy/localhost:44543" -task-0: time="2025-01-07T12:02:43-12:00" level=error msg="portForwardHandler(unknown protocol: dummy\ngithub.com/mendersoftware/mender-connect/session.(*MenderPortForwarder).Connect\n\t/build/reproducible-path/mender-connect-2.3.0+ds1/_build/src/github.com/mendersoftware/mender-connect/session/portforward.go:74\ngithub.com/mendersoftware/mender-connect/session.(*PortForwardHandler).portForwardHandlerNew\n\t/build/reproducible-path/mender-connect-2.3.0+ds1/_build/src/github.com/mendersoftware/mender-connect/session/portforward.go:276\ngithub.com/mendersoftware/mender-connect/session.(*PortForwardHandler).ServeProtoMsg\n\t/build/reproducible-path/mender-connect-2.3.0+ds1/_build/src/github.com/mendersoftware/mender-connect/session/portforward.go:205\ngithub.com/mendersoftware/mender-connect/session.TestPortForwardHandler\n\t/build/reproducible-path/mender-connect-2.3.0+ds1/_build/src/github.com/mendersoftware/mender-connect/session/portforward_test.go:120\ntesting.tRunner\n\t/usr/lib/go-1.23/src/testing/testing.go:1690\nruntime.goexit\n\t/usr/lib/go-1.23/src/runtime/asm_arm64.s:1223)" -task-0: time="2025-01-07T12:02:43-12:00" level=error msg="portForwardHandler(unknown connection\ngithub.com/mendersoftware/mender-connect/session.init\n\t:1\nruntime.doInit1\n\t/usr/lib/go-1.23/src/runtime/proc.go:7290\nruntime.doInit\n\t/usr/lib/go-1.23/src/runtime/proc.go:7257\nruntime.main\n\t/usr/lib/go-1.23/src/runtime/proc.go:254\nruntime.goexit\n\t/usr/lib/go-1.23/src/runtime/asm_arm64.s:1223)" -task-0: time="2025-01-07T12:02:43-12:00" level=error msg="portForwardHandler(unknown connection\ngithub.com/mendersoftware/mender-connect/session.init\n\t:1\nruntime.doInit1\n\t/usr/lib/go-1.23/src/runtime/proc.go:7290\nruntime.doInit\n\t/usr/lib/go-1.23/src/runtime/proc.go:7257\nruntime.main\n\t/usr/lib/go-1.23/src/runtime/proc.go:254\nruntime.goexit\n\t/usr/lib/go-1.23/src/runtime/asm_arm64.s:1223)" +task-0: time="2025-01-08T14:05:54+14:00" level=error msg="portForwardHandler(unknown message type\ngithub.com/mendersoftware/mender-connect/session.init\n\t:1\nruntime.doInit1\n\t/usr/lib/go-1.23/src/runtime/proc.go:7290\nruntime.doInit\n\t/usr/lib/go-1.23/src/runtime/proc.go:7257\nruntime.main\n\t/usr/lib/go-1.23/src/runtime/proc.go:254\nruntime.goexit\n\t/usr/lib/go-1.23/src/runtime/asm_arm64.s:1223)" +task-0: time="2025-01-08T14:05:54+14:00" level=info msg="port-forward: new session/c1: tcp/localhost:46759" +task-0: time="2025-01-08T14:05:54+14:00" level=error msg="portForwardHandler(dial tcp 127.0.0.1:46759: connect: connection refused)" +task-0: time="2025-01-08T14:05:54+14:00" level=info msg="port-forward: new session/c1: dummy/localhost:37153" +task-0: time="2025-01-08T14:05:54+14:00" level=error msg="portForwardHandler(unknown protocol: dummy\ngithub.com/mendersoftware/mender-connect/session.(*MenderPortForwarder).Connect\n\t/build/reproducible-path/mender-connect-2.3.0+ds1/_build/src/github.com/mendersoftware/mender-connect/session/portforward.go:74\ngithub.com/mendersoftware/mender-connect/session.(*PortForwardHandler).portForwardHandlerNew\n\t/build/reproducible-path/mender-connect-2.3.0+ds1/_build/src/github.com/mendersoftware/mender-connect/session/portforward.go:276\ngithub.com/mendersoftware/mender-connect/session.(*PortForwardHandler).ServeProtoMsg\n\t/build/reproducible-path/mender-connect-2.3.0+ds1/_build/src/github.com/mendersoftware/mender-connect/session/portforward.go:205\ngithub.com/mendersoftware/mender-connect/session.TestPortForwardHandler\n\t/build/reproducible-path/mender-connect-2.3.0+ds1/_build/src/github.com/mendersoftware/mender-connect/session/portforward_test.go:120\ntesting.tRunner\n\t/usr/lib/go-1.23/src/testing/testing.go:1690\nruntime.goexit\n\t/usr/lib/go-1.23/src/runtime/asm_arm64.s:1223)" +task-0: time="2025-01-08T14:05:54+14:00" level=error msg="portForwardHandler(unknown connection\ngithub.com/mendersoftware/mender-connect/session.init\n\t:1\nruntime.doInit1\n\t/usr/lib/go-1.23/src/runtime/proc.go:7290\nruntime.doInit\n\t/usr/lib/go-1.23/src/runtime/proc.go:7257\nruntime.main\n\t/usr/lib/go-1.23/src/runtime/proc.go:254\nruntime.goexit\n\t/usr/lib/go-1.23/src/runtime/asm_arm64.s:1223)" +task-0: time="2025-01-08T14:05:54+14:00" level=error msg="portForwardHandler(unknown connection\ngithub.com/mendersoftware/mender-connect/session.init\n\t:1\nruntime.doInit1\n\t/usr/lib/go-1.23/src/runtime/proc.go:7290\nruntime.doInit\n\t/usr/lib/go-1.23/src/runtime/proc.go:7257\nruntime.main\n\t/usr/lib/go-1.23/src/runtime/proc.go:254\nruntime.goexit\n\t/usr/lib/go-1.23/src/runtime/asm_arm64.s:1223)" task-0: --- PASS: TestPortForwardHandler (0.00s) task-0: === RUN TestPortForwardHandlerSuccessfulConnection -task-0: time="2025-01-07T12:02:45-12:00" level=info msg="port-forward: new session/c1: tcp/localhost:37557" -task-0: time="2025-01-07T12:02:45-12:00" level=info msg="port-forward: new session/c2: tcp/localhost:37557" -task-0: time="2025-01-07T12:02:46-12:00" level=info msg="port-forward: stop session/c1" -task-0: time="2025-01-07T12:02:46-12:00" level=error msg="portForwardHandler(unknown connection\ngithub.com/mendersoftware/mender-connect/session.init\n\t:1\nruntime.doInit1\n\t/usr/lib/go-1.23/src/runtime/proc.go:7290\nruntime.doInit\n\t/usr/lib/go-1.23/src/runtime/proc.go:7257\nruntime.main\n\t/usr/lib/go-1.23/src/runtime/proc.go:254\nruntime.goexit\n\t/usr/lib/go-1.23/src/runtime/asm_arm64.s:1223)" -task-0: --- PASS: TestPortForwardHandlerSuccessfulConnection (3.24s) +task-0: time="2025-01-08T14:05:56+14:00" level=info msg="port-forward: new session/c1: tcp/localhost:37127" +task-0: time="2025-01-08T14:05:57+14:00" level=info msg="port-forward: new session/c2: tcp/localhost:37127" +task-0: time="2025-01-08T14:05:57+14:00" level=info msg="port-forward: stop session/c1" +task-0: time="2025-01-08T14:05:58+14:00" level=error msg="portForwardHandler(unknown connection\ngithub.com/mendersoftware/mender-connect/session.init\n\t:1\nruntime.doInit1\n\t/usr/lib/go-1.23/src/runtime/proc.go:7290\nruntime.doInit\n\t/usr/lib/go-1.23/src/runtime/proc.go:7257\nruntime.main\n\t/usr/lib/go-1.23/src/runtime/proc.go:254\nruntime.goexit\n\t/usr/lib/go-1.23/src/runtime/asm_arm64.s:1223)" +task-0: --- PASS: TestPortForwardHandlerSuccessfulConnection (3.22s) task-0: === RUN TestRouter task-0: === PAUSE TestRouter task-0: === RUN TestRouterRace @@ -1653,36 +1692,38 @@ task-0: === PAUSE TestSessionListen task-0: === RUN TestMenderShellStartStopShell task-0: session_test.go:587: starting mock httpd with websockets -task-0: time="2025-01-07T12:02:46-12:00" level=info msg="mender-connect starting shell command passing process, pid: 2798133" +task-0: time="2025-01-08T14:05:58+14:00" level=info msg="mender-connect starting shell command passing process, pid: 1998886" task-0: session_test.go:631: created session: task-0: id:c4993deb-26b4-4c58-aaee-fd0c9e694328, -task-0: createdAt:Wed Jan 8 00:02:46 +0000 UTC 2025, -task-0: expiresAt:Wed Jan 8 00:19:50 +0000 UTC 2025 -task-0: now:Tue Jan 7 12:02:46 -1200 -12 2025 -task-0: time="2025-01-07T12:02:46-12:00" level=info msg="mender-connect starting shell command passing process, pid: 2798136" -task-0: time="2025-01-07T12:02:46-12:00" level=info msg="session c4993deb-26b4-4c58-aaee-fd0c9e694328 status:0 stopping shell" -task-0: time="2025-01-07T12:02:50-12:00" level=info msg="session c4993deb-26b4-4c58-aaee-fd0c9e694328 status:4 stopping shell" -task-0: time="2025-01-07T12:02:50-12:00" level=info msg="session c4993deb-26b4-4c58-aaee-fd0c9e694328 status:0 stopping shell" -task-0: --- PASS: TestMenderShellStartStopShell (8.07s) +task-0: createdAt:Wed Jan 8 00:05:58 +0000 UTC 2025, +task-0: expiresAt:Wed Jan 8 00:23:02 +0000 UTC 2025 +task-0: now:Wed Jan 8 14:05:58 +1400 +14 2025 +task-0: time="2025-01-08T14:05:58+14:00" level=info msg="mender-connect starting shell command passing process, pid: 1998889" +task-0: time="2025-01-08T14:05:58+14:00" level=info msg="session c4993deb-26b4-4c58-aaee-fd0c9e694328 status:0 stopping shell" +task-0: time="2025-01-08T14:05:58+14:00" level=error msg="error reading stdout: read /dev/ptmx: input/output error" +task-0: time="2025-01-08T14:06:02+14:00" level=error msg="session c4993deb-26b4-4c58-aaee-fd0c9e694328, shell pid 1998886, termination error: error waiting for the process: signal: interrupt" +task-0: time="2025-01-08T14:06:02+14:00" level=info msg="session c4993deb-26b4-4c58-aaee-fd0c9e694328 status:4 stopping shell" +task-0: time="2025-01-08T14:06:02+14:00" level=info msg="session c4993deb-26b4-4c58-aaee-fd0c9e694328 status:0 stopping shell" +task-0: --- PASS: TestMenderShellStartStopShell (8.03s) task-0: === RUN TestMenderShellCommand task-0: session_test.go:680: starting mock httpd with websockets -task-0: time="2025-01-07T12:02:54-12:00" level=info msg="mender-connect starting shell command passing process, pid: 2799181" -task-0: time="2025-01-07T12:02:54-12:00" level=error msg="error reading stdout: read /dev/ptmx: file already closed" +task-0: time="2025-01-08T14:06:06+14:00" level=info msg="mender-connect starting shell command passing process, pid: 2002616" task-0: --- PASS: TestMenderShellCommand (0.03s) task-0: === RUN TestMenderShellShellAlreadyStartedFailedToStart task-0: session_test.go:757: starting mock httpd with websockets -task-0: time="2025-01-07T12:02:54-12:00" level=info msg="mender-connect starting shell command passing process, pid: 2799185" -task-0: time="2025-01-07T12:02:54-12:00" level=error msg="failed to start shell: shell is already running" -task-0: time="2025-01-07T12:02:54-12:00" level=error msg="failed to start shell: fork/exec thatissomethingelse/bin/sh: no such file or directory" -task-0: --- PASS: TestMenderShellShellAlreadyStartedFailedToStart (0.02s) +task-0: time="2025-01-08T14:06:06+14:00" level=error msg="error reading stdout: read /dev/ptmx: file already closed" +task-0: time="2025-01-08T14:06:06+14:00" level=info msg="mender-connect starting shell command passing process, pid: 2002620" +task-0: time="2025-01-08T14:06:06+14:00" level=error msg="failed to start shell: shell is already running" +task-0: time="2025-01-08T14:06:06+14:00" level=error msg="failed to start shell: fork/exec thatissomethingelse/bin/sh: no such file or directory" +task-0: --- PASS: TestMenderShellShellAlreadyStartedFailedToStart (0.03s) task-0: === RUN TestMenderShellSessionExpire -task-0: time="2025-01-07T12:02:54-12:00" level=info msg="mender-connect starting shell command passing process, pid: 2799187" -task-0: --- PASS: TestMenderShellSessionExpire (4.00s) +task-0: time="2025-01-08T14:06:06+14:00" level=info msg="mender-connect starting shell command passing process, pid: 2002623" +task-0: --- PASS: TestMenderShellSessionExpire (4.06s) task-0: === RUN TestMenderShellSessionUpdateWS -task-0: time="2025-01-07T12:02:58-12:00" level=info msg="mender-connect starting shell command passing process, pid: 2799311" -task-0: --- PASS: TestMenderShellSessionUpdateWS (0.02s) +task-0: time="2025-01-08T14:06:10+14:00" level=info msg="mender-connect starting shell command passing process, pid: 2005048" +task-0: --- PASS: TestMenderShellSessionUpdateWS (0.00s) task-0: === RUN TestMenderShellSessionGetByUserId -task-0: --- PASS: TestMenderShellSessionGetByUserId (0.01s) +task-0: --- PASS: TestMenderShellSessionGetByUserId (0.00s) task-0: === RUN TestMenderShellSessionGetById task-0: --- PASS: TestMenderShellSessionGetById (0.00s) task-0: === RUN TestMenderShellDeleteById @@ -1692,37 +1733,37 @@ task-0: === RUN TestMenderSessionTerminateExpired task-0: session_test.go:1142: created session: task-0: id:c4993deb-26b4-4c58-aaee-fd0c9e694328, -task-0: createdAt:Wed Jan 8 00:02:58 +0000 UTC 2025, -task-0: expiresAt:Wed Jan 8 00:03:06 +0000 UTC 2025 -task-0: now:Tue Jan 7 12:02:58 -1200 -12 2025 -task-0: time="2025-01-07T12:02:58-12:00" level=info msg="mender-connect starting shell command passing process, pid: 2799313" -task-0: time="2025-01-07T12:03:14-12:00" level=info msg="session c4993deb-26b4-4c58-aaee-fd0c9e694328 status:0 stopping shell" -task-0: --- PASS: TestMenderSessionTerminateExpired (20.03s) +task-0: createdAt:Wed Jan 8 00:06:10 +0000 UTC 2025, +task-0: expiresAt:Wed Jan 8 00:06:18 +0000 UTC 2025 +task-0: now:Wed Jan 8 14:06:10 +1400 +14 2025 +task-0: time="2025-01-08T14:06:10+14:00" level=info msg="mender-connect starting shell command passing process, pid: 2005050" +task-0: time="2025-01-08T14:06:26+14:00" level=info msg="session c4993deb-26b4-4c58-aaee-fd0c9e694328 status:0 stopping shell" +task-0: --- PASS: TestMenderSessionTerminateExpired (20.01s) task-0: === RUN TestMenderSessionTerminateAll task-0: session_test.go:1194: created session: -task-0: id:5a52e80a-c422-40c3-a843-0f9d0133b5b2, -task-0: createdAt:Wed Jan 8 00:03:18 +0000 UTC 2025, -task-0: expiresAt:Wed Jan 8 00:03:26 +0000 UTC 2025 -task-0: now:Tue Jan 7 12:03:18 -1200 -12 2025 -task-0: time="2025-01-07T12:03:18-12:00" level=info msg="mender-connect starting shell command passing process, pid: 2801807" +task-0: id:1ec890c9-63d1-4e21-bbdd-bdfcff685221, +task-0: createdAt:Wed Jan 8 00:06:30 +0000 UTC 2025, +task-0: expiresAt:Wed Jan 8 00:06:38 +0000 UTC 2025 +task-0: now:Wed Jan 8 14:06:30 +1400 +14 2025 +task-0: time="2025-01-08T14:06:30+14:00" level=info msg="mender-connect starting shell command passing process, pid: 2014369" task-0: session_test.go:1210: created session: -task-0: id:3ad1329d-63ba-47b4-bccd-f335089aef5e, -task-0: createdAt:Wed Jan 8 00:03:18 +0000 UTC 2025, -task-0: expiresAt:Wed Jan 8 00:03:26 +0000 UTC 2025 -task-0: now:Tue Jan 7 12:03:18 -1200 -12 2025 -task-0: time="2025-01-07T12:03:18-12:00" level=info msg="mender-connect starting shell command passing process, pid: 2801809" -task-0: time="2025-01-07T12:03:18-12:00" level=info msg="session 5a52e80a-c422-40c3-a843-0f9d0133b5b2 status:0 stopping shell" -task-0: time="2025-01-07T12:03:22-12:00" level=info msg="session 3ad1329d-63ba-47b4-bccd-f335089aef5e status:0 stopping shell" -task-0: --- PASS: TestMenderSessionTerminateAll (8.05s) +task-0: id:3f7c7228-687d-4d10-99c3-1ee39236fe15, +task-0: createdAt:Wed Jan 8 00:06:30 +0000 UTC 2025, +task-0: expiresAt:Wed Jan 8 00:06:38 +0000 UTC 2025 +task-0: now:Wed Jan 8 14:06:30 +1400 +14 2025 +task-0: time="2025-01-08T14:06:30+14:00" level=info msg="mender-connect starting shell command passing process, pid: 2014372" +task-0: time="2025-01-08T14:06:30+14:00" level=info msg="session 1ec890c9-63d1-4e21-bbdd-bdfcff685221 status:0 stopping shell" +task-0: time="2025-01-08T14:06:34+14:00" level=info msg="session 3f7c7228-687d-4d10-99c3-1ee39236fe15 status:0 stopping shell" +task-0: --- PASS: TestMenderSessionTerminateAll (8.03s) task-0: === RUN TestMenderSessionTerminateIdle task-0: session_test.go:1251: created session: task-0: id:c4993deb-26b4-4c58-aaee-fd0c9e694328, -task-0: createdAt:Wed Jan 8 00:03:26 +0000 UTC 2025, -task-0: expiresAt:Wed Jan 8 00:07:41 +0000 UTC 2025 -task-0: now:Tue Jan 7 12:03:26 -1200 -12 2025 -task-0: time="2025-01-07T12:03:26-12:00" level=info msg="mender-connect starting shell command passing process, pid: 2802681" -task-0: time="2025-01-07T12:03:34-12:00" level=info msg="session c4993deb-26b4-4c58-aaee-fd0c9e694328 status:0 stopping shell" -task-0: --- PASS: TestMenderSessionTerminateIdle (12.04s) +task-0: createdAt:Wed Jan 8 00:06:38 +0000 UTC 2025, +task-0: expiresAt:Wed Jan 8 00:10:53 +0000 UTC 2025 +task-0: now:Wed Jan 8 14:06:38 +1400 +14 2025 +task-0: time="2025-01-08T14:06:38+14:00" level=info msg="mender-connect starting shell command passing process, pid: 2017158" +task-0: time="2025-01-08T14:06:46+14:00" level=info msg="session c4993deb-26b4-4c58-aaee-fd0c9e694328 status:0 stopping shell" +task-0: --- PASS: TestMenderSessionTerminateIdle (12.02s) task-0: === RUN TestMenderSessionTimeNow task-0: --- PASS: TestMenderSessionTimeNow (0.00s) task-0: === CONT TestFileTransferUpload @@ -1835,25 +1876,27 @@ task-0: === PAUSE TestFileTransferDownload/error,_forbidden_to_follow_links task-0: === CONT TestFileTransferDownload/ok task-0: === CONT TestFileTransferUpload/error,_parent_directory_does_not_exist -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="failed to create file: open /tmp/filetransfer-testing2726681747/parent/dir/does/not/exist/for/this/file.0000000200: no such file or directory" +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="failed to create file: open /tmp/filetransfer-testing425193313/parent/dir/does/not/exist/for/this/file.0000000200: no such file or directory" task-0: === CONT TestFileTransferUpload/error,_broken_response_writer -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="failed to respond to client: io: read/write on closed pipe" -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="handler aborted" +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="failed to respond to client: io: read/write on closed pipe" +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="handler aborted" task-0: === CONT TestFileTransferUpload/error,_offset_jumps_beyond_EOF -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="received unexpected chunk offset" +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="received unexpected chunk offset" task-0: === CONT TestFileTransferUpload/error,_chunk_missing_offset -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="invalid file chunk message: missing offset property" +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="invalid file chunk message: missing offset property" task-0: === CONT TestFileTransferUpload/error,_unexpected_ACK_message_from_client +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="received unexpected message type 'ack' during file upload" task-0: === CONT TestFileTransferUpload/error,_fake_error_from_client +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="Received error during upload: something unexpected happened" +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="handler aborted" task-0: === CONT TestFileTransferUpload/error,_path_is_a_directory task-0: === CONT TestFileTransferUpload/error,_file_too_big_upload_denied task-0: === CONT TestFileTransferUpload/ok,_relative_path task-0: === CONT TestSessionListen/error,_write_error -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="failed to write response to client: this is bad!" +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="failed to write response to client: this is bad!" task-0: === CONT TestSessionListen/error,_ping_write_error task-0: === CONT TestSessionListen/error,_session_timeout task-0: === CONT TestSessionListen/error,_bad_protocol_->_close_error -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="session: received error from client: dunno what to do next..." task-0: === CONT TestSessionListen/error,_control_message_not_understood task-0: === CONT TestSessionListen/error,_invalid_handshake_version task-0: === CONT TestSessionListen/error,_malformed_handshake_response @@ -1861,59 +1904,58 @@ task-0: === CONT TestSessionListen/error,_bad_handshake_schema task-0: === CONT TestSessionListen/error,_protocol_version_not_supported task-0: === CONT TestSessionListen/ok,_handshake -task-0: time="2025-01-07T12:03:38-12:00" level=info msg="session: accepting new session with ID: 1234" +task-0: time="2025-01-08T14:06:50+14:00" level=info msg="session: accepting new session with ID: 1234" task-0: === CONT TestSessionListen/ok,_ping/pong_->_close -task-0: time="2025-01-07T12:03:38-12:00" level=info msg="session: closed 1234" +task-0: time="2025-01-08T14:06:50+14:00" level=info msg="session: closed 1234" task-0: === CONT TestFileTransferServeErrors/message_type_not_implemented task-0: === CONT TestFileTransferServeErrors/malformed_error_from_client +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="Error decoding error message from client: msgpack: unexpected code=73 decoding map length" task-0: === CONT TestFileTransferServeErrors/generic_error_from_client -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="received unexpected message type 'ack' during file upload" +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="Received error from client: generic error" task-0: === CONT TestFileTransferServeErrors/got_chunk_but_no_file_transfer_in_progress task-0: === CONT TestFileTransferServeErrors/download_already_in_progress -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="another file transfer is in progress" +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="another file transfer is in progress" task-0: === CONT TestFileTransferServeErrors/invalid_download_request_parameters -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="invalid request parameters: path: cannot be blank." +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="invalid request parameters: path: cannot be blank." task-0: === CONT TestFileTransferServeErrors/malformed_download_request -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="malformed request parameters: msgpack: unexpected code=2f decoding map length" +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="malformed request parameters: msgpack: unexpected code=2f decoding map length" task-0: === CONT TestFileTransferServeErrors/upload_already_in_progress task-0: === CONT TestFileTransferServeErrors/invalid_upload_request_parameters -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="Received error during upload: something unexpected happened" -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="handler aborted" +task-0: --- PASS: TestFileTransferServeErrors (0.00s) +task-0: --- PASS: TestFileTransferServeErrors/malformed_upload_request (0.00s) +task-0: --- PASS: TestFileTransferServeErrors/message_type_not_implemented (0.00s) +task-0: --- PASS: TestFileTransferServeErrors/malformed_error_from_client (0.00s) +task-0: --- PASS: TestFileTransferServeErrors/generic_error_from_client (0.00s) +task-0: --- PASS: TestFileTransferServeErrors/got_chunk_but_no_file_transfer_in_progress (0.00s) +task-0: --- PASS: TestFileTransferServeErrors/download_already_in_progress (0.00s) +task-0: --- PASS: TestFileTransferServeErrors/invalid_download_request_parameters (0.00s) +task-0: --- PASS: TestFileTransferServeErrors/malformed_download_request (0.00s) +task-0: --- PASS: TestFileTransferServeErrors/upload_already_in_progress (0.00s) +task-0: --- PASS: TestFileTransferServeErrors/invalid_upload_request_parameters (0.00s) +task-0: === CONT TestFileTransferStat/error,_invalid_parameters#01 task-0: === CONT TestFileTransferStat/error,_invalid_parameters task-0: === CONT TestFileTransferStat/error,_malformed_schema -task-0: === CONT TestFileTransferStat/error,_invalid_parameters#01 task-0: --- PASS: TestFileTransferStat (0.00s) task-0: --- PASS: TestFileTransferStat/ok (0.00s) +task-0: --- PASS: TestFileTransferStat/error,_invalid_parameters#01 (0.00s) task-0: --- PASS: TestFileTransferStat/error,_invalid_parameters (0.00s) task-0: --- PASS: TestFileTransferStat/error,_malformed_schema (0.00s) -task-0: --- PASS: TestFileTransferStat/error,_invalid_parameters#01 (0.00s) +task-0: === CONT TestFileTransferDownload/error,_forbidden_to_follow_links +task-0: time="2025-01-08T14:06:50+14:00" level=warning msg="file download access denied: forbidden to follow the link" +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="access denied: forbidden to follow the link" +task-0: === CONT TestFileTransferDownload/error,_file_does_not_exist +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="failed to open file for reading: open lets say it does not exist: no such file or directory" task-0: === CONT TestFileTransferDownload/error,_client_error_message -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="received error message from client: ENOSPC" +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="received error message from client: ENOSPC" task-0: === CONT TestFileTransferDownload/error,_client_malformed_error_message -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="received malformed error message from client: aborting" +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="received malformed error message from client: aborting" task-0: === CONT TestFileTransferDownload/error,_unexpected_ack_message -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="received unexpected message type 'file_chunk'; expected 'ack'" +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="received unexpected message type 'file_chunk'; expected 'ack'" task-0: === CONT TestFileTransferDownload/error,_no_offset_in_ack -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="ack message: offset property cannot be blank" +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="ack message: offset property cannot be blank" task-0: === CONT TestFileTransferDownload/error,_bad_ack_data_type -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="invalid offset data type: require int64" +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="invalid offset data type: require int64" task-0: === CONT TestFileTransferDownload/ok,_file_larger_than_window -task-0: === CONT TestFileTransferDownload/error,_forbidden_to_follow_links -task-0: time="2025-01-07T12:03:38-12:00" level=warning msg="file download access denied: forbidden to follow the link" -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="access denied: forbidden to follow the link" -task-0: === CONT TestFileTransferDownload/error,_file_does_not_exist -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="failed to open file for reading: open lets say it does not exist: no such file or directory" -task-0: --- PASS: TestFileTransferDownload (0.00s) -task-0: --- PASS: TestFileTransferDownload/ok (0.00s) -task-0: --- PASS: TestFileTransferDownload/error,_client_error_message (0.00s) -task-0: --- PASS: TestFileTransferDownload/error,_client_malformed_error_message (0.00s) -task-0: --- PASS: TestFileTransferDownload/error,_unexpected_ack_message (0.00s) -task-0: --- PASS: TestFileTransferDownload/error,_no_offset_in_ack (0.00s) -task-0: --- PASS: TestFileTransferDownload/error,_bad_ack_data_type (0.00s) -task-0: --- PASS: TestFileTransferDownload/ok,_file_larger_than_window (0.00s) -task-0: --- PASS: TestFileTransferDownload/error,_forbidden_to_follow_links (0.00s) -task-0: --- PASS: TestFileTransferDownload/error,_file_does_not_exist (0.00s) -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="Error decoding error message from client: msgpack: unexpected code=73 decoding map length" task-0: --- PASS: TestFileTransferUpload (0.00s) task-0: --- PASS: TestFileTransferUpload/error,_parent_directory_does_not_exist (0.00s) task-0: --- PASS: TestFileTransferUpload/error,_broken_response_writer (0.00s) @@ -1925,23 +1967,21 @@ task-0: --- PASS: TestFileTransferUpload/error,_file_too_big_upload_denied (0.00s) task-0: --- PASS: TestFileTransferUpload/ok,_relative_path (0.00s) task-0: --- PASS: TestFileTransferUpload/ok (0.00s) -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="Received error from client: generic error" -task-0: --- PASS: TestFileTransferServeErrors (0.00s) -task-0: --- PASS: TestFileTransferServeErrors/malformed_upload_request (0.00s) -task-0: --- PASS: TestFileTransferServeErrors/got_chunk_but_no_file_transfer_in_progress (0.00s) -task-0: --- PASS: TestFileTransferServeErrors/download_already_in_progress (0.00s) -task-0: --- PASS: TestFileTransferServeErrors/invalid_download_request_parameters (0.00s) -task-0: --- PASS: TestFileTransferServeErrors/malformed_download_request (0.00s) -task-0: --- PASS: TestFileTransferServeErrors/upload_already_in_progress (0.00s) -task-0: --- PASS: TestFileTransferServeErrors/invalid_upload_request_parameters (0.00s) -task-0: --- PASS: TestFileTransferServeErrors/message_type_not_implemented (0.00s) -task-0: --- PASS: TestFileTransferServeErrors/malformed_error_from_client (0.00s) -task-0: --- PASS: TestFileTransferServeErrors/generic_error_from_client (0.01s) -task-0: time="2025-01-07T12:03:38-12:00" level=error msg="failed to ping client: this is bad!" +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="session: received error from client: dunno what to do next..." +task-0: --- PASS: TestFileTransferDownload (0.00s) +task-0: --- PASS: TestFileTransferDownload/ok (0.00s) +task-0: --- PASS: TestFileTransferDownload/error,_forbidden_to_follow_links (0.00s) +task-0: --- PASS: TestFileTransferDownload/error,_file_does_not_exist (0.00s) +task-0: --- PASS: TestFileTransferDownload/error,_client_error_message (0.00s) +task-0: --- PASS: TestFileTransferDownload/error,_client_malformed_error_message (0.00s) +task-0: --- PASS: TestFileTransferDownload/error,_unexpected_ack_message (0.00s) +task-0: --- PASS: TestFileTransferDownload/error,_no_offset_in_ack (0.00s) +task-0: --- PASS: TestFileTransferDownload/error,_bad_ack_data_type (0.00s) +task-0: --- PASS: TestFileTransferDownload/ok,_file_larger_than_window (0.00s) +task-0: time="2025-01-08T14:06:50+14:00" level=error msg="failed to ping client: this is bad!" task-0: --- PASS: TestSessionListen (0.00s) task-0: --- PASS: TestSessionListen/ok (0.00s) task-0: --- PASS: TestSessionListen/error,_write_error (0.00s) -task-0: --- PASS: TestSessionListen/error,_bad_protocol_->_close_error (0.00s) task-0: --- PASS: TestSessionListen/error,_control_message_not_understood (0.00s) task-0: --- PASS: TestSessionListen/error,_invalid_handshake_version (0.00s) task-0: --- PASS: TestSessionListen/error,_malformed_handshake_response (0.00s) @@ -1950,26 +1990,27 @@ task-0: --- PASS: TestSessionListen/error,_protocol_version_not_supported (0.00s) task-0: --- PASS: TestSessionListen/ok,_handshake (0.00s) task-0: --- PASS: TestSessionListen/ok,_ping/pong_->_close (0.00s) -task-0: --- PASS: TestSessionListen/error,_ping_write_error (0.20s) -task-0: --- PASS: TestSessionListen/error,_session_timeout (0.25s) -task-0: time="2025-01-07T12:03:39-12:00" level=error msg="[panic] panicHandler" trace="\n:1.(*panicHandler).ServeProtoMsg\n/build/reproducible-path/mender-connect-2.3.0+ds1/_build/src/github.com/mendersoftware/mender-connect/session/session.go:369.(*Session).ListenAndServe\n/build/reproducible-path/mender-connect-2.3.0+ds1/_build/src/github.com/mendersoftware/mender-connect/session/router.go:56.(*router).startSession\n/usr/lib/go-1.23/src/runtime/asm_arm64.s:1224.goexit" +task-0: --- PASS: TestSessionListen/error,_bad_protocol_->_close_error (0.00s) +task-0: --- PASS: TestSessionListen/error,_ping_write_error (0.21s) +task-0: --- PASS: TestSessionListen/error,_session_timeout (0.26s) +task-0: time="2025-01-08T14:06:51+14:00" level=error msg="[panic] panicHandler" trace="\n:1.(*panicHandler).ServeProtoMsg\n/build/reproducible-path/mender-connect-2.3.0+ds1/_build/src/github.com/mendersoftware/mender-connect/session/session.go:369.(*Session).ListenAndServe\n/build/reproducible-path/mender-connect-2.3.0+ds1/_build/src/github.com/mendersoftware/mender-connect/session/router.go:56.(*router).startSession\n/usr/lib/go-1.23/src/runtime/asm_arm64.s:1224.goexit" task-0: --- PASS: TestRouterRace (1.00s) task-0: PASS -task-0: ok github.com/mendersoftware/mender-connect/session 56.614s +task-0: ok github.com/mendersoftware/mender-connect/session 56.491s task-0: === RUN TestNewMenderShell task-0: --- PASS: TestNewMenderShell (0.00s) task-0: === RUN TestNewMenderShellReadStdIn -task-0: --- PASS: TestNewMenderShellReadStdIn (8.05s) +task-0: --- PASS: TestNewMenderShellReadStdIn (8.01s) task-0: === RUN TestPipeStdout task-0: exec_test.go:156: starting mock httpd with websockets -task-0: time="2025-01-07T12:02:51-12:00" level=error msg="error reading stdout: EOF" -task-0: --- PASS: TestPipeStdout (8.01s) +task-0: time="2025-01-08T14:06:02+14:00" level=error msg="error reading stdout: EOF" +task-0: --- PASS: TestPipeStdout (8.00s) task-0: === RUN TestMenderShellExecShell -task-0: shell_test.go:82: started shell, pid: 2799316 -task-0: shell_test.go:85: FindProcess p: &{2799316 1 {{} {} 1} {{0 0} 0 0 {{} 0} {{} 0}} 13} err: -task-0: --- PASS: TestMenderShellExecShell (4.05s) +task-0: shell_test.go:82: started shell, pid: 2005454 +task-0: shell_test.go:85: FindProcess p: &{2005454 1 {{} {} 1} {{0 0} 0 0 {{} 0} {{} 0}} 13} err: +task-0: --- PASS: TestMenderShellExecShell (4.01s) task-0: PASS -task-0: ok github.com/mendersoftware/mender-connect/shell 20.160s +task-0: ok github.com/mendersoftware/mender-connect/shell 20.064s task-0: === RUN TestFileSize task-0: --- PASS: TestFileSize (0.00s) task-0: === RUN TestFileExists @@ -1985,31 +2026,31 @@ task-0: === RUN TestIsInChroot task-0: --- PASS: TestIsInChroot (0.00s) task-0: === RUN TestNum64 -task-0: === RUN TestNum64/int16 -task-0: === RUN TestNum64/int64 -task-0: === RUN TestNum64/uint32 -task-0: === RUN TestNum64/int task-0: === RUN TestNum64/int32 task-0: === RUN TestNum64/uint task-0: === RUN TestNum64/uint8 task-0: === RUN TestNum64/uint16 -task-0: === RUN TestNum64/uint64 +task-0: === RUN TestNum64/uint32 task-0: === RUN TestNum64/uintptr task-0: === RUN TestNum64/int8 +task-0: === RUN TestNum64/int16 +task-0: === RUN TestNum64/int64 +task-0: === RUN TestNum64/uint64 +task-0: === RUN TestNum64/int task-0: --- PASS: TestNum64 (0.00s) -task-0: --- PASS: TestNum64/int16 (0.00s) -task-0: --- PASS: TestNum64/int64 (0.00s) -task-0: --- PASS: TestNum64/uint32 (0.00s) -task-0: --- PASS: TestNum64/int (0.00s) task-0: --- PASS: TestNum64/int32 (0.00s) task-0: --- PASS: TestNum64/uint (0.00s) task-0: --- PASS: TestNum64/uint8 (0.00s) task-0: --- PASS: TestNum64/uint16 (0.00s) -task-0: --- PASS: TestNum64/uint64 (0.00s) +task-0: --- PASS: TestNum64/uint32 (0.00s) task-0: --- PASS: TestNum64/uintptr (0.00s) task-0: --- PASS: TestNum64/int8 (0.00s) +task-0: --- PASS: TestNum64/int16 (0.00s) +task-0: --- PASS: TestNum64/int64 (0.00s) +task-0: --- PASS: TestNum64/uint64 (0.00s) +task-0: --- PASS: TestNum64/int (0.00s) task-0: PASS -task-0: ok github.com/mendersoftware/mender-connect/utils 0.056s +task-0: ok github.com/mendersoftware/mender-connect/utils 0.039s task-0: Shutting down DBus daemon: Shutdown make[1]: Leaving directory '/build/reproducible-path/mender-connect-2.3.0+ds1' @@ -2056,12 +2097,14 @@ dpkg-buildpackage: info: binary-only upload (no source included) dpkg-genchanges: info: including full source code in upload I: copying local configuration +I: user script /srv/workspace/pbuilder/1960565/tmp/hooks/B01_cleanup starting +I: user script /srv/workspace/pbuilder/1960565/tmp/hooks/B01_cleanup finished I: unmounting dev/ptmx filesystem I: unmounting dev/pts filesystem I: unmounting dev/shm filesystem I: unmounting proc filesystem I: unmounting sys filesystem I: cleaning the build env -I: removing directory /srv/workspace/pbuilder/2777805 and its subdirectories -I: Current time: Tue Jan 7 12:04:26 -12 2025 -I: pbuilder-time-stamp: 1736294666 +I: removing directory /srv/workspace/pbuilder/1960565 and its subdirectories +I: Current time: Wed Jan 8 14:07:40 +14 2025 +I: pbuilder-time-stamp: 1736294860