travis_fold:start:worker_info [0K[33;1mWorker information[0m hostname: af29ad15-eaaf-417a-9efc-343dfb197fa9@1.worker-n2-com-779d777f7b-rxlft.gce-production-1 version: 6.2.22 https://github.com/travis-ci/worker/tree/858cb91994a513269f2fe9782c15fc113e966231 instance: travis-job-7b6fe8e8-4f41-4671-abdf-7b1a3216d147 travis-ci-ubuntu-1804-1706776257-3d36ff62 (via amqp) startup: 7.105320112s travis_fold:end:worker_info [0Ktravis_time:start:01a0c2b8 [0Ktravis_time:end:01a0c2b8:start=1709112761213258509,finish=1709112761407927805,duration=194669296,event=no_world_writable_dirs [0Ktravis_time:start:09ba6be0 [0Ktravis_time:end:09ba6be0:start=1709112761410767830,finish=1709112761418121378,duration=7353548,event=agent [0Ktravis_time:start:01fea310 [0Ktravis_time:end:01fea310:start=1709112761420965344,finish=1709112761422873570,duration=1908226,event=check_unsupported [0Ktravis_time:start:0bd70bcc [0Ktravis_fold:start:system_info [0K[33;1mBuild system information[0m Build language: ruby Build dist: bionic Build id: 269163833 Job id: 618439210 Runtime kernel version: 5.4.0-1106-gcp travis-build version: f3de9fb7 [34m[1mBuild image provisioning date and time[0m Thu Feb 1 09:04:40 UTC 2024 [34m[1mOperating System Details[0m Distributor ID: Ubuntu Description: Ubuntu 18.04.6 LTS Release: 18.04 Codename: bionic [34m[1mSystemd Version[0m systemd 237 [34m[1mCookbooks Version[0m 4a0cff6 https://github.com/travis-ci/travis-cookbooks/tree/4a0cff6 [34m[1mgit version[0m git version 2.43.0 [34m[1mbash version[0m GNU bash, version 4.4.20(1)-release (x86_64-pc-linux-gnu) [34m[1mgcc version[0m gcc (Ubuntu 7.5.0-3ubuntu1~18.04) 7.5.0 [34m[1mdocker version[0m Client: Version: 20.10.21 API version: 1.41 Go version: go1.18.1 Git commit: 20.10.21-0ubuntu1~18.04.3 Built: Thu Apr 27 05:50:21 2023 OS/Arch: linux/amd64 Context: default Experimental: true Server: Engine: Version: 20.10.21 API version: 1.41 (minimum version 1.12) Go version: go1.18.1 Git commit: 20.10.21-0ubuntu1~18.04.3 Built: Thu Apr 27 05:36:22 2023 OS/Arch: linux/amd64 Experimental: false containerd: Version: 1.6.12-0ubuntu1~18.04.1 GitCommit: runc: Version: 1.1.4-0ubuntu1~18.04.2 GitCommit: docker-init: Version: 0.19.0 GitCommit: [34m[1mclang version[0m clang version 16.0.0 [34m[1mjq version[0m jq-1.7 [34m[1mbats version[0m Bats 0.4.0 [34m[1mshellcheck version[0m 0.9.0 [34m[1mshfmt version[0m v3.7.0 [34m[1mccache version[0m 3.4.1 [34m[1mcmake version[0m cmake version 3.26.3 [34m[1mheroku version[0m heroku/8.7.1 linux-x64 node-v16.19.0 [34m[1mimagemagick version[0m Version: ImageMagick 6.9.7-4 Q16 x86_64 20170114 http://www.imagemagick.org [34m[1mmd5deep version[0m 4.4 [34m[1mmercurial version[0m version 5.3 [34m[1mmysql version[0m mysql Ver 14.14 Distrib 5.7.42, for Linux (x86_64) using EditLine wrapper [34m[1mopenssl version[0m OpenSSL 1.1.1 11 Sep 2018 [34m[1mpacker version[0m 1.9.4 [34m[1mpostgresql client version[0m psql (PostgreSQL) 11.20 (Ubuntu 11.20-1.pgdg18.04+1) [34m[1mragel version[0m Ragel State Machine Compiler version 6.10 March 2017 [34m[1msudo version[0m 1.8.21p2 [34m[1mgzip version[0m gzip 1.6 [34m[1mzip version[0m Zip 3.0 [34m[1mvim version[0m VIM - Vi IMproved 8.0 (2016 Sep 12, compiled Apr 18 2023 09:20:34) [34m[1miptables version[0m iptables v1.6.1 [34m[1mcurl version[0m curl 7.58.0 (x86_64-pc-linux-gnu) libcurl/7.58.0 OpenSSL/1.1.1 zlib/1.2.11 libidn2/2.0.4 libpsl/0.19.1 (+libidn2/2.0.4) nghttp2/1.30.0 librtmp/2.3 [34m[1mwget version[0m GNU Wget 1.19.4 built on linux-gnu. [34m[1mrsync version[0m rsync version 3.1.2 protocol version 31 [34m[1mgimme version[0m v1.5.4 [34m[1mnvm version[0m 0.39.7 [34m[1mperlbrew version[0m /home/travis/perl5/perlbrew/bin/perlbrew - App::perlbrew/0.95 [34m[1mphpenv version[0m rbenv 1.2.0 [34m[1mrvm version[0m rvm 1.29.12 (latest) by Michal Papis, Piotr Kuczynski, Wayne E. Seguin [https://rvm.io] [34m[1mdefault ruby version[0m ruby 2.7.6p219 (2022-04-12 revision c9c2245c0a) [x86_64-linux] [34m[1mdefault python version[0m Python 3.7.17 [34m[1mElasticSearch version[0m 7.16.3 [34m[1mInstalled Firefox version[0m firefox 63.0.1 [34m[1mMongoDB version[0m MongoDB 4.4.28 [34m[1mPhantomJS version[0m 2.1.1 [34m[1mPre-installed PostgreSQL versions[0m 9.3.25 9.4.26 9.5.25 9.6.24 [34m[1mRedis version[0m redis-server 7.2.4 [34m[1mPre-installed Go versions[0m 1.11.1 [34m[1mmvn version[0m Apache Maven 3.9.4 (dfbb324ad4a7c8fb0bf182e6d91b0ae20e3d2dd9) [34m[1mgradle version[0m Gradle 8.3! [34m[1mlein version[0m Leiningen 2.11.1 on Java 11.0.21 OpenJDK 64-Bit Server VM [34m[1mPre-installed Node.js versions[0m v10.24.1 v12.22.12 v14.21.3 v16.15 v16.15.1 v16.20.2 v18.19.0 v20.11.0 v4.9.1 v6.17.1 v8.17.0 [34m[1mphpenv versions[0m system 7.1 7.1.33 7.2 * 7.2.27 (set by /home/travis/.phpenv/version) 7.3 7.3.14 7.4 7.4.2 hhvm-stable hhvm [34m[1mcomposer --version[0m Composer version 1.9.2 2020-01-14 16:30:31 [34m[1mPre-installed Ruby versions[0m ruby-2.5.9 ruby-2.7.6 ruby-3.1.2 travis_fold:end:system_info [0K travis_time:end:0bd70bcc:start=1709112761425938241,finish=1709112761436869476,duration=10931235,event=show_system_info [0Ktravis_time:start:0015bad4 [0Ktravis_time:end:0015bad4:start=1709112761439690060,finish=1709112761459432852,duration=19742792,event=rm_riak_source [0Ktravis_time:start:11b04f94 [0Ktravis_time:end:11b04f94:start=1709112761462252261,finish=1709112761467521408,duration=5269147,event=fix_rwky_redis [0Ktravis_time:start:0d810a6c [0Ktravis_time:end:0d810a6c:start=1709112761470416772,finish=1709112762192056957,duration=721640185,event=wait_for_network [0Ktravis_time:start:0ef8da19 [0Ktravis_time:end:0ef8da19:start=1709112762194841150,finish=1709112762525746314,duration=330905164,event=update_apt_keys [0Ktravis_time:start:036a0fec [0Ktravis_time:end:036a0fec:start=1709112762528837349,finish=1709112762580330708,duration=51493359,event=fix_hhvm_source [0Ktravis_time:start:05db648c [0Ktravis_time:end:05db648c:start=1709112762583179953,finish=1709112762585551975,duration=2372022,event=update_mongo_arch [0Ktravis_time:start:1186004f [0Ktravis_time:end:1186004f:start=1709112762588183703,finish=1709112762626745116,duration=38561413,event=fix_sudo_enabled_trusty [0Ktravis_time:start:02b952e8 [0Ktravis_time:end:02b952e8:start=1709112762629635198,finish=1709112762631543343,duration=1908145,event=update_glibc [0Ktravis_time:start:02cc20a8 [0Ktravis_time:end:02cc20a8:start=1709112762634123513,finish=1709112762641110281,duration=6986768,event=clean_up_path [0Ktravis_time:start:091e4e6c [0Ktravis_time:end:091e4e6c:start=1709112762643754185,finish=1709112762651898955,duration=8144770,event=fix_resolv_conf [0Ktravis_time:start:0635a804 [0Ktravis_time:end:0635a804:start=1709112762654533993,finish=1709112762679430357,duration=24896364,event=fix_etc_hosts [0Ktravis_time:start:02889a92 [0Ktravis_time:end:02889a92:start=1709112762682161746,finish=1709112762690027871,duration=7866125,event=fix_mvn_settings_xml [0Ktravis_time:start:0ede72a2 [0Ktravis_time:end:0ede72a2:start=1709112762692757747,finish=1709112762701276663,duration=8518916,event=no_ipv6_localhost [0Ktravis_time:start:22acaef4 [0Ktravis_time:end:22acaef4:start=1709112762703934711,finish=1709112762705854395,duration=1919684,event=fix_etc_mavenrc [0Ktravis_time:start:001d1cf3 [0KOK travis_time:end:001d1cf3:start=1709112762708489093,finish=1709112763081143693,duration=372654600,event=fix_perforce_key [0Ktravis_time:start:04ce1788 [0Ktravis_time:end:04ce1788:start=1709112763084165376,finish=1709112763086820503,duration=2655127,event=fix_wwdr_certificate [0Ktravis_time:start:139f5778 [0Ktravis_time:end:139f5778:start=1709112763089672505,finish=1709112763163004381,duration=73331876,event=put_localhost_first [0Ktravis_time:start:006b035e [0Ktravis_time:end:006b035e:start=1709112763165720615,finish=1709112763168661816,duration=2941201,event=home_paths [0Ktravis_time:start:1935143e [0Ktravis_time:end:1935143e:start=1709112763171306449,finish=1709112763183302889,duration=11996440,event=disable_initramfs [0Ktravis_time:start:01b6180b [0Ktravis_time:end:01b6180b:start=1709112763186113472,finish=1709112763331590029,duration=145476557,event=disable_ssh_roaming [0Ktravis_time:start:18eea54f [0Ktravis_time:end:18eea54f:start=1709112763334328306,finish=1709112763336321743,duration=1993437,event=debug_tools [0Ktravis_time:start:039b6b50 [0Ktravis_time:end:039b6b50:start=1709112763338980143,finish=1709112763341722811,duration=2742668,event=uninstall_oclint [0Ktravis_time:start:044423a8 [0Ktravis_time:end:044423a8:start=1709112763344299443,finish=1709112763346776507,duration=2477064,event=rvm_use [0Ktravis_time:start:0f10f850 [0Ktravis_time:end:0f10f850:start=1709112763349441742,finish=1709112763356801725,duration=7359983,event=rm_etc_boto_cfg [0Ktravis_time:start:02e2eff2 [0Ktravis_time:end:02e2eff2:start=1709112763359356216,finish=1709112763361860525,duration=2504309,event=rm_oraclejdk8_symlink [0Ktravis_time:start:2c94ecac [0Ktravis_time:end:2c94ecac:start=1709112763364530276,finish=1709112763460101799,duration=95571523,event=enable_i386 [0Ktravis_time:start:1fc5a91c [0Ktravis_time:end:1fc5a91c:start=1709112763463012725,finish=1709112763466621971,duration=3609246,event=update_rubygems [0Ktravis_time:start:21d3a983 [0Ktravis_time:end:21d3a983:start=1709112763469029211,finish=1709112764285981614,duration=816952403,event=ensure_path_components [0Ktravis_time:start:0a9f4caf [0Ktravis_time:end:0a9f4caf:start=1709112764288869355,finish=1709112764290717077,duration=1847722,event=redefine_curl [0Ktravis_time:start:052c9d67 [0Ktravis_time:end:052c9d67:start=1709112764293190470,finish=1709112764294942444,duration=1751974,event=nonblock_pipe [0Ktravis_time:start:18c624d5 [0Ktravis_time:end:18c624d5:start=1709112764297321779,finish=1709112770330170065,duration=6032848286,event=apt_get_update [0Ktravis_time:start:0c257fa3 [0Ktravis_time:end:0c257fa3:start=1709112770333028496,finish=1709112770335026461,duration=1997965,event=deprecate_xcode_64 [0Ktravis_time:start:0b979015 [0Ktravis_time:end:0b979015:start=1709112770337582992,finish=1709112774268039177,duration=3930456185,event=update_heroku [0Ktravis_time:start:07300a55 [0Ktravis_time:end:07300a55:start=1709112774270937675,finish=1709112774273083769,duration=2146094,event=shell_session_update [0Ktravis_time:start:0023ec86 [0Ktravis_fold:start:docker_mtu_and_registry_mirrors [0Ktravis_fold:end:docker_mtu_and_registry_mirrors [0Ktravis_time:end:0023ec86:start=1709112774275839123,finish=1709112776586897151,duration=2311058028,event=set_docker_mtu_and_registry_mirrors [0Ktravis_time:start:0e471b86 [0Ktravis_fold:start:resolvconf [0Ktravis_fold:end:resolvconf [0Ktravis_time:end:0e471b86:start=1709112776590348056,finish=1709112776657673221,duration=67325165,event=resolvconf [0Ktravis_time:start:03d7bd0a [0Ktravis_time:end:03d7bd0a:start=1709112776662271021,finish=1709112776806760842,duration=144489821,event=maven_central_mirror [0Ktravis_time:start:020ead6a [0Ktravis_time:end:020ead6a:start=1709112776809612863,finish=1709112776895334505,duration=85721642,event=maven_https [0Ktravis_fold:start:apt [0Ktravis_time:start:0659a1d7 [0K$ travis_apt_get_update travis_time:end:0659a1d7:start=1709112776898884917,finish=1709112789081987515,duration=12183102598,event=prepare [0K[33;1mInstalling APT Packages[0m [33;1mPostgreSQL package is detected. Stopping postgresql service. See https://github.com/travis-ci/travis-ci/issues/5737 for more information.[0m $ sudo systemctl stop postgresql travis_time:start:17e56d46 [0K$ sudo -E apt-get -yq --no-install-suggests --no-install-recommends $(travis_apt_get_options) install postgresql-11 postgresql-client-11 Reading package lists... Building dependency tree... Reading state information... postgresql-11 is already the newest version (11.20-1.pgdg18.04+1). postgresql-client-11 is already the newest version (11.20-1.pgdg18.04+1). postgresql-client-11 set to manually installed. The following package was automatically installed and is no longer required: libgeos-3.6.2 Use 'sudo apt autoremove' to remove it. 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. travis_time:end:17e56d46:start=1709112789121533091,finish=1709112789859681152,duration=738148061,event=prepare [0Ktravis_fold:end:apt [0Ktravis_time:start:1b3faaee [0Ktravis_fold:start:services [0Ktravis_fold:end:services [0Ktravis_time:end:1b3faaee:start=1709112789862935939,finish=1709112792868871019,duration=3005935080,event=services [0Ktravis_time:start:005d3dc2 [0Ktravis_time:end:005d3dc2:start=1709112792872083575,finish=1709112792874202492,duration=2118917,event=fix_ps4 [0Ktravis_fold:start:postgresql [0Ktravis_time:start:0e2d1660 [0K$ travis_setup_postgresql 11 [33;1mStarting PostgreSQL v11[0K sudo systemctl start postgresql@11-main travis_time:end:0e2d1660:start=1709112792877105798,finish=1709112796045716091,duration=3168610293,event=prepare [0Ktravis_fold:end:postgresql [0Ktravis_time:start:00c15f30 [0K travis_fold:start:git.checkout [0Ktravis_time:start:12c33f00 [0Ktravis_time:end:12c33f00:start=1709112796052020169,finish=1709112796056809115,duration=4788946,event=checkout [0Ktravis_time:start:05fa417c [0K$ git clone --depth=50 --branch=ga-test280224 https://github.com/travis-ci/marginalia.git travis-ci/marginalia Cloning into 'travis-ci/marginalia'... remote: Enumerating objects: 525, done.[K remote: Counting objects: 0% (1/525)[K remote: Counting objects: 1% (6/525)[K remote: Counting objects: 2% (11/525)[K remote: Counting objects: 3% (16/525)[K remote: Counting objects: 4% (21/525)[K remote: Counting objects: 5% (27/525)[K remote: Counting objects: 6% (32/525)[K remote: Counting objects: 7% (37/525)[K remote: Counting objects: 8% (42/525)[K remote: Counting objects: 9% (48/525)[K remote: Counting objects: 10% (53/525)[K remote: Counting objects: 11% (58/525)[K remote: Counting objects: 12% (63/525)[K remote: Counting objects: 13% (69/525)[K remote: Counting objects: 14% (74/525)[K remote: Counting objects: 15% (79/525)[K remote: Counting objects: 16% (84/525)[K remote: Counting objects: 17% (90/525)[K remote: Counting objects: 18% (95/525)[K remote: Counting objects: 19% (100/525)[K remote: Counting objects: 20% (105/525)[K remote: Counting objects: 21% (111/525)[K remote: Counting objects: 22% (116/525)[K remote: Counting objects: 23% (121/525)[K remote: Counting objects: 24% (126/525)[K remote: Counting objects: 25% (132/525)[K remote: Counting objects: 26% (137/525)[K remote: Counting objects: 27% (142/525)[K remote: Counting objects: 28% (147/525)[K remote: Counting objects: 29% (153/525)[K remote: Counting objects: 30% (158/525)[K remote: Counting objects: 31% (163/525)[K remote: Counting objects: 32% (168/525)[K remote: Counting objects: 33% (174/525)[K remote: Counting objects: 34% (179/525)[K remote: Counting objects: 35% (184/525)[K remote: Counting objects: 36% (189/525)[K remote: Counting objects: 37% (195/525)[K remote: Counting objects: 38% (200/525)[K remote: Counting objects: 39% (205/525)[K remote: Counting objects: 40% (210/525)[K remote: Counting objects: 41% (216/525)[K remote: Counting objects: 42% (221/525)[K remote: Counting objects: 43% (226/525)[K remote: Counting objects: 44% (231/525)[K remote: Counting objects: 45% (237/525)[K remote: Counting objects: 46% (242/525)[K remote: Counting objects: 47% (247/525)[K remote: Counting objects: 48% (252/525)[K remote: Counting objects: 49% (258/525)[K remote: Counting objects: 50% (263/525)[K remote: Counting objects: 51% (268/525)[K remote: Counting objects: 52% (273/525)[K remote: Counting objects: 53% (279/525)[K remote: Counting objects: 54% (284/525)[K remote: Counting objects: 55% (289/525)[K remote: Counting objects: 56% (294/525)[K remote: Counting objects: 57% (300/525)[K remote: Counting objects: 58% (305/525)[K remote: Counting objects: 59% (310/525)[K remote: Counting objects: 60% (315/525)[K remote: Counting objects: 61% (321/525)[K remote: Counting objects: 62% (326/525)[K remote: Counting objects: 63% (331/525)[K remote: Counting objects: 64% (336/525)[K remote: Counting objects: 65% (342/525)[K remote: Counting objects: 66% (347/525)[K remote: Counting objects: 67% (352/525)[K remote: Counting objects: 68% (357/525)[K remote: Counting objects: 69% (363/525)[K remote: Counting objects: 70% (368/525)[K remote: Counting objects: 71% (373/525)[K remote: Counting objects: 72% (378/525)[K remote: Counting objects: 73% (384/525)[K remote: Counting objects: 74% (389/525)[K remote: Counting objects: 75% (394/525)[K remote: Counting objects: 76% (399/525)[K remote: Counting objects: 77% (405/525)[K remote: Counting objects: 78% (410/525)[K remote: Counting objects: 79% (415/525)[K remote: Counting objects: 80% (420/525)[K remote: Counting objects: 81% (426/525)[K remote: Counting objects: 82% (431/525)[K remote: Counting objects: 83% (436/525)[K remote: Counting objects: 84% (441/525)[K remote: Counting objects: 85% (447/525)[K remote: Counting objects: 86% (452/525)[K remote: Counting objects: 87% (457/525)[K remote: Counting objects: 88% (462/525)[K remote: Counting objects: 89% (468/525)[K remote: Counting objects: 90% (473/525)[K remote: Counting objects: 91% (478/525)[K remote: Counting objects: 92% (483/525)[K remote: Counting objects: 93% (489/525)[K remote: Counting objects: 94% (494/525)[K remote: Counting objects: 95% (499/525)[K remote: Counting objects: 96% (504/525)[K remote: Counting objects: 97% (510/525)[K remote: Counting objects: 98% (515/525)[K remote: Counting objects: 99% (520/525)[K remote: Counting objects: 100% (525/525)[K remote: Counting objects: 100% (525/525), done.[K remote: Compressing objects: 0% (1/274)[K remote: Compressing objects: 1% (3/274)[K remote: Compressing objects: 2% (6/274)[K remote: Compressing objects: 3% (9/274)[K remote: Compressing objects: 4% (11/274)[K remote: Compressing objects: 5% (14/274)[K remote: Compressing objects: 6% (17/274)[K remote: Compressing objects: 7% (20/274)[K remote: Compressing objects: 8% (22/274)[K remote: Compressing objects: 9% (25/274)[K remote: Compressing objects: 10% (28/274)[K remote: Compressing objects: 11% (31/274)[K remote: Compressing objects: 12% (33/274)[K remote: Compressing objects: 13% (36/274)[K remote: Compressing objects: 14% (39/274)[K remote: Compressing objects: 15% (42/274)[K remote: Compressing objects: 16% (44/274)[K remote: Compressing objects: 17% (47/274)[K remote: Compressing objects: 18% (50/274)[K remote: Compressing objects: 19% (53/274)[K remote: Compressing objects: 20% (55/274)[K remote: Compressing objects: 21% (58/274)[K remote: Compressing objects: 22% (61/274)[K remote: Compressing objects: 23% (64/274)[K remote: Compressing objects: 24% (66/274)[K remote: Compressing objects: 25% (69/274)[K remote: Compressing objects: 26% (72/274)[K remote: Compressing objects: 27% (74/274)[K remote: Compressing objects: 28% (77/274)[K remote: Compressing objects: 29% (80/274)[K remote: Compressing objects: 30% (83/274)[K remote: Compressing objects: 31% (85/274)[K remote: Compressing objects: 32% (88/274)[K remote: Compressing objects: 33% (91/274)[K remote: Compressing objects: 34% (94/274)[K remote: Compressing objects: 35% (96/274)[K remote: Compressing objects: 36% (99/274)[K remote: Compressing objects: 37% (102/274)[K remote: Compressing objects: 38% (105/274)[K remote: Compressing objects: 39% (107/274)[K remote: Compressing objects: 40% (110/274)[K remote: Compressing objects: 41% (113/274)[K remote: Compressing objects: 42% (116/274)[K remote: Compressing objects: 43% (118/274)[K remote: Compressing objects: 44% (121/274)[K remote: Compressing objects: 45% (124/274)[K remote: Compressing objects: 46% (127/274)[K remote: Compressing objects: 47% (129/274)[K remote: Compressing objects: 48% (132/274)[K remote: Compressing objects: 49% (135/274)[K remote: Compressing objects: 50% (137/274)[K remote: Compressing objects: 51% (140/274)[K remote: Compressing objects: 52% (143/274)[K remote: Compressing objects: 53% (146/274)[K remote: Compressing objects: 54% (148/274)[K remote: Compressing objects: 55% (151/274)[K remote: Compressing objects: 56% (154/274)[K remote: Compressing objects: 57% (157/274)[K remote: Compressing objects: 58% (159/274)[K remote: Compressing objects: 59% (162/274)[K remote: Compressing objects: 60% (165/274)[K remote: Compressing objects: 61% (168/274)[K remote: Compressing objects: 62% (170/274)[K remote: Compressing objects: 63% (173/274)[K remote: Compressing objects: 64% (176/274)[K remote: Compressing objects: 65% (179/274)[K remote: Compressing objects: 66% (181/274)[K remote: Compressing objects: 67% (184/274)[K remote: Compressing objects: 68% (187/274)[K remote: Compressing objects: 69% (190/274)[K remote: Compressing objects: 70% (192/274)[K remote: Compressing objects: 71% (195/274)[K remote: Compressing objects: 72% (198/274)[K remote: Compressing objects: 73% (201/274)[K remote: Compressing objects: 74% (203/274)[K remote: Compressing objects: 75% (206/274)[K remote: Compressing objects: 76% (209/274)[K remote: Compressing objects: 77% (211/274)[K remote: Compressing objects: 78% (214/274)[K remote: Compressing objects: 79% (217/274)[K remote: Compressing objects: 80% (220/274)[K remote: Compressing objects: 81% (222/274)[K remote: Compressing objects: 82% (225/274)[K remote: Compressing objects: 83% (228/274)[K remote: Compressing objects: 84% (231/274)[K remote: Compressing objects: 85% (233/274)[K remote: Compressing objects: 86% (236/274)[K remote: Compressing objects: 87% (239/274)[K remote: Compressing objects: 88% (242/274)[K remote: Compressing objects: 89% (244/274)[K remote: Compressing objects: 90% (247/274)[K remote: Compressing objects: 91% (250/274)[K remote: Compressing objects: 92% (253/274)[K remote: Compressing objects: 93% (255/274)[K remote: Compressing objects: 94% (258/274)[K remote: Compressing objects: 95% (261/274)[K remote: Compressing objects: 96% (264/274)[K remote: Compressing objects: 97% (266/274)[K remote: Compressing objects: 98% (269/274)[K remote: Compressing objects: 99% (272/274)[K remote: Compressing objects: 100% (274/274)[K remote: Compressing objects: 100% (274/274), done.[K Receiving objects: 0% (1/525) Receiving objects: 1% (6/525) Receiving objects: 2% (11/525) Receiving objects: 3% (16/525) Receiving objects: 4% (21/525) Receiving objects: 5% (27/525) Receiving objects: 6% (32/525) Receiving objects: 7% (37/525) Receiving objects: 8% (42/525) Receiving objects: 9% (48/525) Receiving objects: 10% (53/525) Receiving objects: 11% (58/525) Receiving objects: 12% (63/525) Receiving objects: 13% (69/525) Receiving objects: 14% (74/525) Receiving objects: 15% (79/525) Receiving objects: 16% (84/525) Receiving objects: 17% (90/525) Receiving objects: 18% (95/525) Receiving objects: 19% (100/525) Receiving objects: 20% (105/525) Receiving objects: 21% (111/525) Receiving objects: 22% (116/525) Receiving objects: 23% (121/525) Receiving objects: 24% (126/525) Receiving objects: 25% (132/525) Receiving objects: 26% (137/525) Receiving objects: 27% (142/525) Receiving objects: 28% (147/525) Receiving objects: 29% (153/525) Receiving objects: 30% (158/525) Receiving objects: 31% (163/525) Receiving objects: 32% (168/525) Receiving objects: 33% (174/525) Receiving objects: 34% (179/525) Receiving objects: 35% (184/525) Receiving objects: 36% (189/525) Receiving objects: 37% (195/525) Receiving objects: 38% (200/525) Receiving objects: 39% (205/525) Receiving objects: 40% (210/525) Receiving objects: 41% (216/525) Receiving objects: 42% (221/525) Receiving objects: 43% (226/525) Receiving objects: 44% (231/525) Receiving objects: 45% (237/525) Receiving objects: 46% (242/525) Receiving objects: 47% (247/525) Receiving objects: 48% (252/525) Receiving objects: 49% (258/525) Receiving objects: 50% (263/525) Receiving objects: 51% (268/525) Receiving objects: 52% (273/525) Receiving objects: 53% (279/525) Receiving objects: 54% (284/525) Receiving objects: 55% (289/525) Receiving objects: 56% (294/525) Receiving objects: 57% (300/525) Receiving objects: 58% (305/525) Receiving objects: 59% (310/525) Receiving objects: 60% (315/525) Receiving objects: 61% (321/525) Receiving objects: 62% (326/525) remote: Total 525 (delta 260), reused 478 (delta 222), pack-reused 0[K Receiving objects: 63% (331/525) Receiving objects: 64% (336/525) Receiving objects: 65% (342/525) Receiving objects: 66% (347/525) Receiving objects: 67% (352/525) Receiving objects: 68% (357/525) Receiving objects: 69% (363/525) Receiving objects: 70% (368/525) Receiving objects: 71% (373/525) Receiving objects: 72% (378/525) Receiving objects: 73% (384/525) Receiving objects: 74% (389/525) Receiving objects: 75% (394/525) Receiving objects: 76% (399/525) Receiving objects: 77% (405/525) Receiving objects: 78% (410/525) Receiving objects: 79% (415/525) Receiving objects: 80% (420/525) Receiving objects: 81% (426/525) Receiving objects: 82% (431/525) Receiving objects: 83% (436/525) Receiving objects: 84% (441/525) Receiving objects: 85% (447/525) Receiving objects: 86% (452/525) Receiving objects: 87% (457/525) Receiving objects: 88% (462/525) Receiving objects: 89% (468/525) Receiving objects: 90% (473/525) Receiving objects: 91% (478/525) Receiving objects: 92% (483/525) Receiving objects: 93% (489/525) Receiving objects: 94% (494/525) Receiving objects: 95% (499/525) Receiving objects: 96% (504/525) Receiving objects: 97% (510/525) Receiving objects: 98% (515/525) Receiving objects: 99% (520/525) Receiving objects: 100% (525/525) Receiving objects: 100% (525/525), 73.44 KiB | 2.45 MiB/s, done. Resolving deltas: 0% (0/260) Resolving deltas: 1% (3/260) Resolving deltas: 2% (6/260) Resolving deltas: 3% (8/260) Resolving deltas: 4% (11/260) Resolving deltas: 5% (13/260) Resolving deltas: 6% (16/260) Resolving deltas: 7% (19/260) Resolving deltas: 8% (21/260) Resolving deltas: 9% (24/260) Resolving deltas: 10% (26/260) Resolving deltas: 11% (29/260) Resolving deltas: 12% (32/260) Resolving deltas: 13% (34/260) Resolving deltas: 14% (37/260) Resolving deltas: 15% (39/260) Resolving deltas: 16% (42/260) Resolving deltas: 17% (45/260) Resolving deltas: 18% (47/260) Resolving deltas: 19% (50/260) Resolving deltas: 20% (52/260) Resolving deltas: 21% (55/260) Resolving deltas: 22% (58/260) Resolving deltas: 23% (60/260) Resolving deltas: 24% (63/260) Resolving deltas: 25% (65/260) Resolving deltas: 26% (68/260) Resolving deltas: 27% (71/260) Resolving deltas: 28% (73/260) Resolving deltas: 29% (76/260) Resolving deltas: 30% (78/260) Resolving deltas: 31% (81/260) Resolving deltas: 32% (84/260) Resolving deltas: 33% (86/260) Resolving deltas: 34% (89/260) Resolving deltas: 35% (91/260) Resolving deltas: 36% (94/260) Resolving deltas: 37% (97/260) Resolving deltas: 38% (99/260) Resolving deltas: 39% (102/260) Resolving deltas: 40% (104/260) Resolving deltas: 41% (107/260) Resolving deltas: 42% (110/260) Resolving deltas: 43% (112/260) Resolving deltas: 44% (115/260) Resolving deltas: 45% (117/260) Resolving deltas: 46% (120/260) Resolving deltas: 47% (123/260) Resolving deltas: 48% (125/260) Resolving deltas: 49% (128/260) Resolving deltas: 50% (130/260) Resolving deltas: 51% (133/260) Resolving deltas: 52% (136/260) Resolving deltas: 53% (138/260) Resolving deltas: 54% (141/260) Resolving deltas: 55% (143/260) Resolving deltas: 56% (146/260) Resolving deltas: 57% (149/260) Resolving deltas: 58% (151/260) Resolving deltas: 59% (154/260) Resolving deltas: 60% (156/260) Resolving deltas: 61% (159/260) Resolving deltas: 62% (162/260) Resolving deltas: 63% (164/260) Resolving deltas: 64% (167/260) Resolving deltas: 65% (169/260) Resolving deltas: 66% (172/260) Resolving deltas: 67% (175/260) Resolving deltas: 68% (177/260) Resolving deltas: 69% (180/260) Resolving deltas: 70% (182/260) Resolving deltas: 71% (185/260) Resolving deltas: 72% (188/260) Resolving deltas: 73% (190/260) Resolving deltas: 74% (193/260) Resolving deltas: 75% (195/260) Resolving deltas: 76% (198/260) Resolving deltas: 77% (201/260) Resolving deltas: 78% (203/260) Resolving deltas: 79% (206/260) Resolving deltas: 80% (208/260) Resolving deltas: 81% (211/260) Resolving deltas: 82% (214/260) Resolving deltas: 83% (216/260) Resolving deltas: 84% (219/260) Resolving deltas: 85% (221/260) Resolving deltas: 86% (224/260) Resolving deltas: 87% (227/260) Resolving deltas: 88% (229/260) Resolving deltas: 89% (232/260) Resolving deltas: 90% (234/260) Resolving deltas: 91% (237/260) Resolving deltas: 92% (240/260) Resolving deltas: 93% (242/260) Resolving deltas: 94% (245/260) Resolving deltas: 95% (247/260) Resolving deltas: 96% (250/260) Resolving deltas: 97% (253/260) Resolving deltas: 98% (255/260) Resolving deltas: 99% (258/260) Resolving deltas: 100% (260/260) Resolving deltas: 100% (260/260), done. travis_time:end:05fa417c:start=1709112796059898690,finish=1709112796510310233,duration=450411543,event=checkout [0K$ cd travis-ci/marginalia $ git checkout -qf b0ca5dbf9e0e535bd94725c0f40c4c553aed3343 travis_fold:end:git.checkout [0K travis_time:end:05fa417c:start=1709112796059898690,finish=1709112796515823786,duration=455925096,event=checkout [0Ktravis_time:start:1026e4b4 [0K [33;1mSetting environment variables from .travis.yml[0m $ export MARGINALIA_DB_PORT=5432 $ export MARGINALIA_LOG_FILE=/var/log/postgresql/postgresql-11-main.log travis_time:end:1026e4b4:start=1709112796518773700,finish=1709112796524557327,duration=5783627,event=env [0Ktravis_fold:start:rvm [0Ktravis_time:start:03c52080 [0K$ rvm get head Downloading https://get.rvm.io [32mDownloading https://raw.githubusercontent.com/rvm/rvm/master/binscripts/rvm-installer.asc[0m [0m[32mVerifying /home/travis/.rvm/archives/rvm-installer.asc[0m [0mgpg: Signature made Tue 21 Feb 2023 11:35:16 PM UTC gpg: using RSA key 7D2BAF1CF37B13E2069D6956105BD0E739499BDB gpg: Good signature from "Piotr Kuczynski <piotr.kuczynski@gmail.com>" [unknown] gpg: WARNING: This key is not certified with a trusted signature! gpg: There is no indication that the signature belongs to the owner. Primary key fingerprint: 7D2B AF1C F37B 13E2 069D 6956 105B D0E7 3949 9BDB [32mGPG verified '/home/travis/.rvm/archives/rvm-installer'[0m [0mDownloading https://github.com/rvm/rvm/archive/master.tar.gz [32mUpgrading the RVM installation in /home/travis/.rvm/[0m [0m RVM PATH line found in /home/travis/.mkshrc /home/travis/.profile /home/travis/.zshrc. [33m RVM PATH line not found for Bash, rerun this command with '--auto-dotfiles' flag to fix it.[0m [0m RVM sourcing line found in /home/travis/.profile /home/travis/.bashrc /home/travis/.zlogin. [32mUpgrade of RVM in /home/travis/.rvm/ is complete.[0m [0m [32m[33mThanks for installing RVM ðŸ™[0m Please consider donating to our open collective to help us maintain RVM. 👉 Donate: [34mhttps://opencollective.com/rvm/donate[0m [0m [0m[32mRVM reloaded![0m [0mtravis_time:end:03c52080:start=1709112796532204531,finish=1709112799362799256,duration=2830594725,event= [0Ktravis_time:start:014080da [0K$ rvm use 3.2.2 --install --binary --fuzzy curl: (22) The requested URL returned error: 404 [33mRequired ruby-3.2.2 is not installed - installing.[0m [0mcurl: (22) The requested URL returned error: 404 Searching for binary rubies, this might take some time. Found remote file https://rubies.travis-ci.org/ubuntu/18.04/x86_64/ruby-3.2.2.tar.bz2 Checking requirements for ubuntu. Requirements installation successful. ruby-3.2.2 - #configure ruby-3.2.2 - #download % Total % Received % Xferd Average Speed Time Time Time Current Dload Upload Total Spent Left Speed 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 0 0 0 0 0 0 0 0 --:--:-- 0:00:01 --:--:-- 0 0 0 0 0 0 0 0 0 --:--:-- 0:00:01 --:--:-- 0 82 29.2M 82 24.0M 0 0 12.3M 0 0:00:02 0:00:01 0:00:01 12.3M 100 29.2M 100 29.2M 0 0 14.3M 0 0:00:02 0:00:02 --:--:-- 59.2M [33mNo checksum for downloaded archive, recording checksum in user configuration.[0m [0mruby-3.2.2 - #validate archive ruby-3.2.2 - #extract ruby-3.2.2 - #validate binary ruby-3.2.2 - #setup ruby-3.2.2 - #gemset created /home/travis/.rvm/gems/ruby-3.2.2@global [32mruby-3.2.2 - #importing gemset /home/travis/.rvm/gemsets/global.gems[0m|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.. [32mruby-3.2.2 - #generating global wrappers[0m|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/. [32mruby-3.2.2 - #uninstalling gem rubygems-bundler-1.4.5[0m|/. ruby-3.2.2 - #gemset created /home/travis/.rvm/gems/ruby-3.2.2 [32mruby-3.2.2 - #importing gemset /home/travis/.rvm/gemsets/default.gems[0m|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\. [32mruby-3.2.2 - #generating default wrappers[0m|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-\|/-.|/-\|/-\|.-\|/-. Using /home/travis/.rvm/gems/ruby-3.2.2 travis_time:end:014080da:start=1709112799367040976,finish=1709112821282924315,duration=21915883339,event= [0Ktravis_fold:end:rvm [0K $ export BUNDLE_GEMFILE=$PWD/Gemfile travis_fold:start:ruby.versions [0K$ ruby --version ruby 3.2.2 (2023-03-30 revision e51014f9c0) [x86_64-linux] $ rvm --version rvm 1.29.12-next (master) by Michal Papis, Piotr Kuczynski, Wayne E. Seguin [https://rvm.io] $ bundle --version Bundler version 2.4.10 $ gem --version 3.4.10 travis_fold:end:ruby.versions [0K travis_fold:start:before_install [0Ktravis_time:start:0e44393e [0K$ bash -c "yes | gem uninstall -i /home/travis/.rvm/gems/ruby-3.2.0@global rake" Gem 'rake' is not installed travis_time:end:0e44393e:start=1709112821705256368,finish=1709112821869627788,duration=164371420,event=before_install [0Ktravis_fold:end:before_install [0Ktravis_fold:start:install.bundler [0Ktravis_time:start:2db5b0bd [0K$ bundle install --jobs=3 --retry=3 Fetching gem metadata from https://rubygems.org/....... Resolving dependencies... [32mFetching rake 13.1.0[0m [32mInstalling rake 13.1.0[0m [32mFetching base64 0.2.0[0m [32mFetching bigdecimal 3.1.6[0m [32mFetching concurrent-ruby 1.2.3[0m [32mInstalling base64 0.2.0[0m [32mFetching connection_pool 2.4.1[0m [32mInstalling bigdecimal 3.1.6 with native extensions[0m [32mInstalling concurrent-ruby 1.2.3[0m [32mInstalling connection_pool 2.4.1[0m Using ruby2_keywords 0.0.5 [32mFetching minitest 5.18.1[0m [32mFetching mutex_m 0.2.0[0m [32mInstalling minitest 5.18.1[0m [32mFetching timeout 0.4.1[0m [32mInstalling mutex_m 0.2.0[0m Using bundler 2.4.10 [32mFetching pg 1.5.5[0m [32mInstalling timeout 0.4.1[0m Using power_assert 2.0.3 [32mFetching drb 2.2.0[0m [32mInstalling drb 2.2.0[0m [32mFetching mocha 2.1.0[0m [32mInstalling pg 1.5.5 with native extensions[0m [32mInstalling mocha 2.1.0[0m [32mFetching i18n 1.14.1[0m [32mInstalling i18n 1.14.1[0m [32mFetching tzinfo 2.0.6[0m [32mInstalling tzinfo 2.0.6[0m [32mFetching test-unit 3.6.2[0m [32mInstalling test-unit 3.6.2[0m [32mFetching activesupport 7.1.3.2[0m [32mFetching sequel 5.77.0[0m [32mInstalling activesupport 7.1.3.2[0m [32mInstalling sequel 5.77.0[0m [32mFetching activemodel 7.1.3.2[0m [32mInstalling activemodel 7.1.3.2[0m [32mFetching activerecord 7.1.3.2[0m [32mInstalling activerecord 7.1.3.2[0m Using marginalia 1.5.0 from source at `.` [32mBundle complete! 7 Gemfile dependencies, 22 gems now installed.[0m [32mUse `bundle info [gemname]` to see where a bundled gem is installed.[0m travis_time:end:2db5b0bd:start=1709112821874880655,finish=1709112837940481188,duration=16065600533,event=install [0Ktravis_fold:end:install.bundler [0K travis_fold:start:before_script [0Ktravis_time:start:0e80bf07 [0K$ sudo chmod 0644 $MARGINALIA_LOG_FILE travis_time:end:0e80bf07:start=1709112837945416453,finish=1709112837954349498,duration=8933045,event=before_script [0Ktravis_fold:end:before_script [0Ktravis_time:start:00b01cf8 [0K$ bundle exec rake db:reset test:postgresql set -e; for file in $(find test -type f -name '*_test.rb'); do MARGINALIA_LOG_FILE=/var/log/postgresql/postgresql-11-main.log MARGINALIA_DB_PORT=5432 ruby -Ilib -Itest $file; done EXEC "SET log_statement = 'all';\n" EXEC COMMENT: "/**/" EXEC "DROP TABLE IF EXISTS posts;\n" EXEC COMMENT: "/**/" EXEC "CREATE TABLE posts (\n id INTEGER,\n title VARCHAR\n);\n" EXEC COMMENT: "/**/" Run options: --seed 948 # Running: QUERY "select * from posts;" Q COMMENT: "/*adapter:pg,app:query*/" .EXEC "INSERT INTO POSTS VALUES (1, 'My Title')" EXEC COMMENT: "/*adapter:pg,app:crud.insert*/" EXEC "UPDATE posts\nSET id = 2\nwhere id = 1\n" EXEC COMMENT: "/*adapter:pg,app:crud.update*/" EXEC "DELETE FROM POSTS where id = 2" EXEC COMMENT: "/*adapter:pg,app:crud.delete*/" .PREP "INSERT INTO posts (id, title) VALUES ($1, $2)" PREP COMMENT: "/*adapter:pg,app:prepare*/" .EXEC "select * from posts;" EXEC COMMENT: "/*adapter:pg,app:foobar*/" .A.EXEC "select * from posts;" AE COMMENT: "/*adapter:pg,app:async_exec*/" .A.QUERY "select * from posts;" AQ COMMENT: "/*adapter:pg,app:async_query*/" . Finished in 0.005965s, 1005.8200 runs/s, 1341.0933 assertions/s. 6 runs, 8 assertions, 0 failures, 0 errors, 0 skips Run options: --seed 50938 # Running: .. Finished in 0.000972s, 2056.5806 runs/s, 3084.8710 assertions/s. 2 runs, 3 assertions, 0 failures, 0 errors, 0 skips A.EXEC "SET client_min_messages TO 'warning'" AE COMMENT: "/**/" A.EXEC "SET standard_conforming_strings = on" AE COMMENT: "/**/" A.EXEC "SET intervalstyle = iso_8601" AE COMMENT: "/**/" A.EXEC "SET SESSION timezone TO 'UTC'" AE COMMENT: "/**/" QUERY ";" Q COMMENT: "/**/" A.EXEC "SET log_statement = 'all';\n" AE COMMENT: "/**/" A.EXEC "DROP TABLE IF EXISTS posts;\n" AE COMMENT: "/**/" -- create_table("posts", {:force=>true}) A.EXEC "SHOW max_identifier_length" AE COMMENT: "/**/" A.EXEC "DROP TABLE IF EXISTS \"posts\"" AE COMMENT: "/**/" A.EXEC "CREATE TABLE \"posts\" (\"id\" bigserial primary key, \"title\" character varying)" AE COMMENT: "/**/" -> 0.0069s A.EXEC "SELECT c.relname FROM pg_class c LEFT JOIN pg_namespace n ON n.oid = c.relnamespace WHERE n.nspname = ANY (current_schemas(false)) AND c.relname = 'schema_migrations' AND c.relkind IN ('r','p')" AE COMMENT: "/**/" A.EXEC "CREATE TABLE \"schema_migrations\" (\"version\" character varying NOT NULL PRIMARY KEY)" AE COMMENT: "/**/" A.EXEC "SELECT c.relname FROM pg_class c LEFT JOIN pg_namespace n ON n.oid = c.relnamespace WHERE n.nspname = ANY (current_schemas(false)) AND c.relname = 'ar_internal_metadata' AND c.relkind IN ('r','p')" AE COMMENT: "/**/" A.EXEC "CREATE TABLE \"ar_internal_metadata\" (\"key\" character varying NOT NULL PRIMARY KEY, \"value\" character varying, \"created_at\" timestamp(6) NOT NULL, \"updated_at\" timestamp(6) NOT NULL)" AE COMMENT: "/**/" Run options: --seed 26920 # Running: EA.EXEC "SELECT a.attname, format_type(a.atttypid, a.atttypmod),\n pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod,\n c.collname, col_description(a.attrelid, a.attnum) AS comment,\n attidentity AS identity,\n '' as attgenerated\n FROM pg_attribute a\n LEFT JOIN pg_attrdef d ON a.attrelid = d.adrelid AND a.attnum = d.adnum\n LEFT JOIN pg_type t ON a.atttypid = t.oid\n LEFT JOIN pg_collation c ON a.attcollation = c.oid AND a.attcollation <> t.typcollation\n WHERE a.attrelid = '\"posts\"'::regclass\n AND a.attnum > 0 AND NOT a.attisdropped\n ORDER BY a.attnum\n" AE COMMENT: "/*adapter:active_record,app:crud.insert*/" A.EXEC "SELECT c.relname FROM pg_class c LEFT JOIN pg_namespace n ON n.oid = c.relnamespace WHERE n.nspname = ANY (current_schemas(false)) AND c.relkind IN ('r','v','m','p','f')" AE COMMENT: "/*adapter:active_record,app:crud.insert*/" A.EXEC "SELECT a.attname\n FROM (\n SELECT indrelid, indkey, generate_subscripts(indkey, 1) idx\n FROM pg_index\n WHERE indrelid = '\"posts\"'::regclass\n AND indisprimary\n ) i\n JOIN pg_attribute a\n ON a.attrelid = i.indrelid\n AND a.attnum = i.indkey[i.idx]\n ORDER BY i.idx\n" AE COMMENT: "/*adapter:active_record,app:crud.insert*/" A.EXEC "BEGIN" AE COMMENT: "/*adapter:active_record,app:crud.insert*/" A.EXEC "COMMIT" AE COMMENT: "/*adapter:active_record,app:crud.insert*/" A.EXEC "SHOW search_path" AE COMMENT: "/*adapter:active_record,app:crud.update*/" PREP "SELECT \"posts\".* FROM \"posts\" WHERE \"posts\".\"id\" = $1 LIMIT $2" PREP COMMENT: "/*adapter:active_record,app:crud.update*/" A.EXEC "BEGIN" AE COMMENT: "/*adapter:active_record,app:crud.update*/" A.EXEC "COMMIT" AE COMMENT: "/*adapter:active_record,app:crud.update*/" A.EXEC "BEGIN" AE COMMENT: "/*adapter:active_record,app:crud.delete*/" A.EXEC "COMMIT" AE COMMENT: "/*adapter:active_record,app:crud.delete*/" . Finished in 0.023228s, 86.1019 runs/s, 129.1528 assertions/s. 1) Error: ActiveRecordMarginaliaTest#test_configuring_application: RuntimeError: Expected to find string /*adapter:active_record,app:customapp*/ in file /var/log/postgresql/postgresql-11-main.log /home/travis/build/travis-ci/marginalia/test/test_helpers.rb:10:in `file_contains_string' test/active_record/query_comments_test.rb:70:in `test_configuring_application' 2 runs, 3 assertions, 0 failures, 1 errors, 0 skips rake aborted! Command failed with status (1): [set -e; for file in $(find test -type f -name '*_test.rb'); do MARGINALIA_LOG_FILE=/var/log/postgresql/postgresql-11-main.log MARGINALIA_DB_PORT=5432 ruby -Ilib -Itest $file; done] /home/travis/build/travis-ci/marginalia/Rakefile:15:in `block (2 levels) in <top (required)>' /home/travis/.rvm/gems/ruby-3.2.2/gems/rake-13.1.0/exe/rake:27:in `<top (required)>' /home/travis/.rvm/gems/ruby-3.2.2/bin/ruby_executable_hooks:22:in `eval' /home/travis/.rvm/gems/ruby-3.2.2/bin/ruby_executable_hooks:22:in `<main>' Tasks: TOP => test:postgresql (See full trace by running task with --trace) travis_time:end:00b01cf8:start=1709112837958946965,finish=1709112839925806750,duration=1966859785,event=script [0K[31;1mThe command "bundle exec rake db:reset test:postgresql" exited with 1.[0m travis_time:start:0f02f5da [0K$ cat $MARGINALIA_LOG_FILE 2024-02-28 09:33:13.555 UTC [4951] LOG: listening on IPv4 address "127.0.0.1", port 5432 2024-02-28 09:33:13.555 UTC [4951] LOG: listening on IPv4 address "127.0.1.1", port 5432 2024-02-28 09:33:13.555 UTC [4951] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432" 2024-02-28 09:33:13.575 UTC [4960] LOG: database system was shut down at 2024-02-01 08:57:39 UTC 2024-02-28 09:33:13.579 UTC [4951] LOG: database system is ready to accept connections 2024-02-28 09:33:14.114 UTC [4968] [unknown]@[unknown] LOG: incomplete startup packet 2024-02-28 09:33:15.719 UTC [4981] postgres@postgres ERROR: role "travis" already exists 2024-02-28 09:33:15.719 UTC [4981] postgres@postgres STATEMENT: CREATE ROLE travis SUPERUSER CREATEDB CREATEROLE INHERIT LOGIN; 2024-02-28 09:33:58.849 UTC [9458] travis@marginalia_test LOG: statement: DROP TABLE IF EXISTS posts; /**/ 2024-02-28 09:33:58.851 UTC [9458] travis@marginalia_test LOG: statement: CREATE TABLE posts ( id INTEGER, title VARCHAR ); /**/ 2024-02-28 09:33:58.859 UTC [9458] travis@marginalia_test LOG: statement: select * from posts; /*adapter:pg,app:query*/ 2024-02-28 09:33:58.860 UTC [9458] travis@marginalia_test LOG: statement: INSERT INTO POSTS VALUES (1, 'My Title') /*adapter:pg,app:crud.insert*/ 2024-02-28 09:33:58.860 UTC [9458] travis@marginalia_test LOG: statement: UPDATE posts SET id = 2 where id = 1 /*adapter:pg,app:crud.update*/ 2024-02-28 09:33:58.861 UTC [9458] travis@marginalia_test LOG: statement: DELETE FROM POSTS where id = 2 /*adapter:pg,app:crud.delete*/ 2024-02-28 09:33:58.862 UTC [9458] travis@marginalia_test LOG: execute statement1: INSERT INTO posts (id, title) VALUES ($1, $2) /*adapter:pg,app:prepare*/ 2024-02-28 09:33:58.862 UTC [9458] travis@marginalia_test DETAIL: parameters: $1 = '100', $2 = 'Welcome Tessa!' 2024-02-28 09:33:58.862 UTC [9458] travis@marginalia_test LOG: statement: select * from posts; /*adapter:pg,app:foobar*/ 2024-02-28 09:33:58.863 UTC [9458] travis@marginalia_test LOG: statement: select * from posts; /*adapter:pg,app:async_exec*/ 2024-02-28 09:33:58.863 UTC [9458] travis@marginalia_test LOG: statement: select * from posts; /*adapter:pg,app:async_query*/ 2024-02-28 09:33:59.867 UTC [9476] travis@marginalia_test LOG: statement: DROP TABLE IF EXISTS posts; /**/ 2024-02-28 09:33:59.872 UTC [9476] travis@marginalia_test LOG: statement: SHOW max_identifier_length /**/ 2024-02-28 09:33:59.873 UTC [9476] travis@marginalia_test LOG: statement: DROP TABLE IF EXISTS "posts" /**/ 2024-02-28 09:33:59.873 UTC [9476] travis@marginalia_test LOG: statement: CREATE TABLE "posts" ("id" bigserial primary key, "title" character varying) /**/ 2024-02-28 09:33:59.877 UTC [9476] travis@marginalia_test LOG: statement: SELECT c.relname FROM pg_class c LEFT JOIN pg_namespace n ON n.oid = c.relnamespace WHERE n.nspname = ANY (current_schemas(false)) AND c.relname = 'schema_migrations' AND c.relkind IN ('r','p') /**/ 2024-02-28 09:33:59.878 UTC [9476] travis@marginalia_test LOG: statement: CREATE TABLE "schema_migrations" ("version" character varying NOT NULL PRIMARY KEY) /**/ 2024-02-28 09:33:59.880 UTC [9476] travis@marginalia_test LOG: statement: SELECT c.relname FROM pg_class c LEFT JOIN pg_namespace n ON n.oid = c.relnamespace WHERE n.nspname = ANY (current_schemas(false)) AND c.relname = 'ar_internal_metadata' AND c.relkind IN ('r','p') /**/ 2024-02-28 09:33:59.881 UTC [9476] travis@marginalia_test LOG: statement: CREATE TABLE "ar_internal_metadata" ("key" character varying NOT NULL PRIMARY KEY, "value" character varying, "created_at" timestamp(6) NOT NULL, "updated_at" timestamp(6) NOT NULL) /**/ 2024-02-28 09:33:59.883 UTC [9476] travis@marginalia_test LOG: execute <unnamed>: SELECT * FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = $1 ORDER BY "ar_internal_metadata"."key" ASC LIMIT 1 2024-02-28 09:33:59.883 UTC [9476] travis@marginalia_test DETAIL: parameters: $1 = 'environment' 2024-02-28 09:33:59.885 UTC [9476] travis@marginalia_test LOG: execute <unnamed>: INSERT INTO "ar_internal_metadata" ("key", "value", "created_at", "updated_at") VALUES ('environment', 'test', '2024-02-28 09:33:59.884893', '2024-02-28 09:33:59.884899') RETURNING "key" 2024-02-28 09:33:59.895 UTC [9476] travis@marginalia_test LOG: execute <unnamed>: SELECT "posts".* FROM "posts" 2024-02-28 09:33:59.896 UTC [9476] travis@marginalia_test LOG: statement: SELECT a.attname, format_type(a.atttypid, a.atttypmod), pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod, c.collname, col_description(a.attrelid, a.attnum) AS comment, attidentity AS identity, '' as attgenerated FROM pg_attribute a LEFT JOIN pg_attrdef d ON a.attrelid = d.adrelid AND a.attnum = d.adnum LEFT JOIN pg_type t ON a.atttypid = t.oid LEFT JOIN pg_collation c ON a.attcollation = c.oid AND a.attcollation <> t.typcollation WHERE a.attrelid = '"posts"'::regclass AND a.attnum > 0 AND NOT a.attisdropped ORDER BY a.attnum /*adapter:active_record,app:crud.insert*/ 2024-02-28 09:33:59.899 UTC [9476] travis@marginalia_test LOG: statement: SELECT c.relname FROM pg_class c LEFT JOIN pg_namespace n ON n.oid = c.relnamespace WHERE n.nspname = ANY (current_schemas(false)) AND c.relkind IN ('r','v','m','p','f') /*adapter:active_record,app:crud.insert*/ 2024-02-28 09:33:59.900 UTC [9476] travis@marginalia_test LOG: statement: SELECT a.attname FROM ( SELECT indrelid, indkey, generate_subscripts(indkey, 1) idx FROM pg_index WHERE indrelid = '"posts"'::regclass AND indisprimary ) i JOIN pg_attribute a ON a.attrelid = i.indrelid AND a.attnum = i.indkey[i.idx] ORDER BY i.idx /*adapter:active_record,app:crud.insert*/ 2024-02-28 09:33:59.906 UTC [9476] travis@marginalia_test LOG: statement: BEGIN /*adapter:active_record,app:crud.insert*/ 2024-02-28 09:33:59.906 UTC [9476] travis@marginalia_test LOG: execute <unnamed>: INSERT INTO "posts" ("title") VALUES ($1) RETURNING "id" 2024-02-28 09:33:59.906 UTC [9476] travis@marginalia_test DETAIL: parameters: $1 = 'foo' 2024-02-28 09:33:59.907 UTC [9476] travis@marginalia_test LOG: statement: COMMIT /*adapter:active_record,app:crud.insert*/ 2024-02-28 09:33:59.909 UTC [9476] travis@marginalia_test LOG: statement: SHOW search_path /*adapter:active_record,app:crud.update*/ 2024-02-28 09:33:59.910 UTC [9476] travis@marginalia_test LOG: execute a1: SELECT "posts".* FROM "posts" WHERE "posts"."id" = $1 LIMIT $2 /*adapter:active_record,app:crud.update*/ 2024-02-28 09:33:59.910 UTC [9476] travis@marginalia_test DETAIL: parameters: $1 = '1', $2 = '1' 2024-02-28 09:33:59.911 UTC [9476] travis@marginalia_test LOG: statement: BEGIN /*adapter:active_record,app:crud.update*/ 2024-02-28 09:33:59.911 UTC [9476] travis@marginalia_test LOG: execute <unnamed>: UPDATE "posts" SET "title" = $1 WHERE "posts"."id" = $2 2024-02-28 09:33:59.911 UTC [9476] travis@marginalia_test DETAIL: parameters: $1 = 'bar', $2 = '1' 2024-02-28 09:33:59.911 UTC [9476] travis@marginalia_test LOG: statement: COMMIT /*adapter:active_record,app:crud.update*/ 2024-02-28 09:33:59.912 UTC [9476] travis@marginalia_test LOG: execute a1: SELECT "posts".* FROM "posts" WHERE "posts"."id" = $1 LIMIT $2 /*adapter:active_record,app:crud.update*/ 2024-02-28 09:33:59.912 UTC [9476] travis@marginalia_test DETAIL: parameters: $1 = '1', $2 = '1' 2024-02-28 09:33:59.912 UTC [9476] travis@marginalia_test LOG: statement: BEGIN /*adapter:active_record,app:crud.delete*/ 2024-02-28 09:33:59.913 UTC [9476] travis@marginalia_test LOG: execute <unnamed>: DELETE FROM "posts" WHERE "posts"."id" = $1 2024-02-28 09:33:59.913 UTC [9476] travis@marginalia_test DETAIL: parameters: $1 = '1' 2024-02-28 09:33:59.913 UTC [9476] travis@marginalia_test LOG: statement: COMMIT /*adapter:active_record,app:crud.delete*/ travis_time:end:0f02f5da:start=1709112839930515292,finish=1709112839935403572,duration=4888280,event=script [0K[32;1mThe command "cat $MARGINALIA_LOG_FILE" exited with 0.[0m Done. Your build exited with 1.