1. 0.10 s $ /nix/store/9ypz3flqsrl5xl495mm8h645gadjsxi1-coreutils-9.11/bin/timeout --kill-after=15s 7200s /nix/store/23zk8sgzamrbmj1fday15szf7f2279s8-nix-2.34.7/bin/nix --extra-experimental-features nix-command --extra-experimental-features flakes --log-format internal-json build --no-link --print-out-paths git+https://github.com/NorfairKing/niks3?ref=main&rev=b306808bf381e7e66e33de1e9446a1be0935f4e3#checks.x86_64-linux.go-unit-tests --print-build-logs
  2. 0.12 s error (ignored): SQLite database '/var/cache/nix-ci-worker/eval-cache-v6/a9373adb9c2e09bf6e6b0b8433c473aa95aed607f8fa6c26078f8d3d37d52fa6.sqlite' is busy
  3. 1.20 s
  4. 1.86 s Downloading cached postgresql-18.4-doc from https://cache.staging.nix-ci.com
  5. 1.86 s Downloading cached niks3-tests from https://cache.staging.nix-ci.com
  6. 1.86 s Downloading cached nlohmann_json from https://cache.staging.nix-ci.com
  7. 1.86 s Downloading cached brotli from https://cache.staging.nix-ci.com
  8. 1.86 s Downloading cached libpsl-0.21.5-dev from https://cache.staging.nix-ci.com
  9. 1.86 s Downloading cached libssh2-1.11.1-dev from https://cache.staging.nix-ci.com
  10. 1.86 s Downloading cached nghttp3-1.16.0-dev from https://cache.staging.nix-ci.com
  11. 1.86 s Downloading cached ngtcp2-1.23.0-dev from https://cache.staging.nix-ci.com
  12. 1.86 s Downloading cached nix from https://cache.staging.nix-ci.com
  13. 1.86 s Downloading cached nix-perl from https://cache.staging.nix-ci.com
  14. 1.86 s Downloading cached numactl-2.0.18-dev from https://cache.staging.nix-ci.com
  15. 1.86 s Downloading cached boehm-gc-8.2.12-dev from https://cache.staging.nix-ci.com
  16. 1.86 s Downloading cached boost-1.89.0-dev from https://cache.staging.nix-ci.com
  17. 1.86 s Downloading cached c-ares from https://cache.staging.nix-ci.com
  18. 1.86 s Downloading cached libidn2-2.3.8-bin from https://cache.staging.nix-ci.com
  19. 1.93 s Downloading cached liburing-2.14-bin from https://cache.staging.nix-ci.com
  20. 1.96 s Downloaded cached brotli (53 KiB) in 98ms
  21. 1.96 s Progress: 0 of 4 built, 1 of 48 downloaded from cache (15 downloading)
  22. 1.96 s Downloaded cached libssh2-1.11.1-dev (83 KiB) in 98ms
  23. 1.96 s Downloading cached acl-2.3.2-dev from https://cache.staging.nix-ci.com
  24. 1.96 s Downloaded cached nghttp3-1.16.0-dev (123 KiB) in 98ms
  25. 1.96 s Progress: 0 of 4 built, 2 of 48 downloaded from cache (15 downloading)
  26. 1.96 s Progress: 0 of 4 built, 3 of 48 downloaded from cache (14 downloading)
  27. 1.96 s Downloading cached attr-2.5.2-dev from https://cache.staging.nix-ci.com
  28. 1.96 s Downloading cached brotli-1.2.0-dev from https://cache.staging.nix-ci.com
  29. 1.96 s Downloaded cached ngtcp2-1.23.0-dev (302 KiB) in 101ms
  30. 1.96 s Progress: 0 of 4 built, 4 of 48 downloaded from cache (15 downloading)
  31. 1.96 s Downloading cached libarchive from https://cache.staging.nix-ci.com
  32. 2.02 s Downloaded cached nlohmann_json (970 KiB) in 160ms
  33. 2.02 s Progress: 0 of 4 built, 5 of 48 downloaded from cache (15 downloading)
  34. 2.02 s Downloading cached libev from https://cache.staging.nix-ci.com
  35. 2.02 s Downloaded cached libpsl-0.21.5-dev (7800 B) in 165ms
  36. 2.02 s Progress: 0 of 4 built, 6 of 48 downloaded from cache (15 downloading)
  37. 2.02 s Downloading cached nix-util-c from https://cache.staging.nix-ci.com
  38. 2.02 s Downloaded cached nix (3.9 MiB) in 166ms
  39. 2.03 s Progress: 0 of 4 built, 7 of 48 downloaded from cache (15 downloading)
  40. 2.04 s Downloaded cached nix-perl (211 KiB) in 177ms
  41. 2.04 s Progress: 0 of 4 built, 8 of 48 downloaded from cache (14 downloading)
  42. 2.06 s Downloaded cached c-ares (276 KiB) in 197ms
  43. 2.06 s Progress: 0 of 4 built, 9 of 48 downloaded from cache (13 downloading)
  44. 2.06 s Downloaded cached libidn2-2.3.8-bin (37 KiB) in 198ms
  45. 2.06 s Progress: 0 of 4 built, 10 of 48 downloaded from cache (12 downloading)
  46. 2.06 s Downloaded cached attr-2.5.2-dev (13 KiB) in 99ms
  47. 2.06 s Downloading cached libidn2-2.3.8-dev from https://cache.staging.nix-ci.com
  48. 2.06 s Downloaded cached acl-2.3.2-dev (8624 B) in 100ms
  49. 2.06 s Progress: 0 of 4 built, 11 of 48 downloaded from cache (12 downloading)
  50. 2.06 s Progress: 0 of 4 built, 12 of 48 downloaded from cache (11 downloading)
  51. 2.06 s Downloaded cached brotli-1.2.0-dev (57 KiB) in 100ms
  52. 2.06 s Progress: 0 of 4 built, 13 of 48 downloaded from cache (10 downloading)
  53. 2.06 s Downloaded cached boehm-gc-8.2.12-dev (256 KiB) in 199ms
  54. 2.06 s Progress: 0 of 4 built, 14 of 48 downloaded from cache (9 downloading)
  55. 2.06 s Downloaded cached liburing-2.14-bin (640 KiB) in 126ms
  56. 2.06 s Progress: 0 of 4 built, 15 of 48 downloaded from cache (8 downloading)
  57. 2.06 s Downloading cached liburing-2.14-dev from https://cache.staging.nix-ci.com
  58. 2.06 s Downloaded cached libarchive (348 KiB) in 101ms
  59. 2.06 s Progress: 0 of 4 built, 16 of 48 downloaded from cache (8 downloading)
  60. 2.06 s Downloading cached libarchive-3.8.8-dev from https://cache.staging.nix-ci.com
  61. 2.08 s Downloaded cached nix-util-c (106 KiB) in 54ms
  62. 2.08 s Progress: 0 of 4 built, 17 of 48 downloaded from cache (8 downloading)
  63. 2.08 s Downloading cached nix-fetchers-c from https://cache.staging.nix-ci.com
  64. 2.08 s Downloading cached nix-main-c from https://cache.staging.nix-ci.com
  65. 2.08 s Downloading cached nix-store-c from https://cache.staging.nix-ci.com
  66. 2.09 s Downloaded cached libev (225 KiB) in 75ms
  67. 2.09 s Progress: 0 of 4 built, 18 of 48 downloaded from cache (10 downloading)
  68. 2.09 s Downloading cached nghttp2 from https://cache.staging.nix-ci.com
  69. 2.13 s Downloaded cached libidn2-2.3.8-dev (15 KiB) in 69ms
  70. 2.13 s Progress: 0 of 4 built, 19 of 48 downloaded from cache (10 downloading)
  71. 2.13 s Downloaded cached liburing-2.14-dev (95 KiB) in 69ms
  72. 2.13 s Progress: 0 of 4 built, 20 of 48 downloaded from cache (9 downloading)
  73. 2.15 s Downloaded cached nix-fetchers-c (66 KiB) in 67ms
  74. 2.15 s Downloaded cached libarchive-3.8.8-dev (91 KiB) in 84ms
  75. 2.15 s Progress: 0 of 4 built, 21 of 48 downloaded from cache (8 downloading)
  76. 2.15 s Progress: 0 of 4 built, 22 of 48 downloaded from cache (7 downloading)
  77. 2.15 s Downloaded cached nix-main-c (16 KiB) in 68ms
  78. 2.15 s Progress: 0 of 4 built, 23 of 48 downloaded from cache (6 downloading)
  79. 2.15 s Downloaded cached nix-store-c (246 KiB) in 68ms
  80. 2.15 s Progress: 0 of 4 built, 24 of 48 downloaded from cache (5 downloading)
  81. 2.15 s Downloading cached nix-expr-c from https://cache.staging.nix-ci.com
  82. 2.15 s Downloaded cached postgresql-18.4-doc (16.5 MiB) in 293ms
  83. 2.15 s Progress: 0 of 4 built, 25 of 48 downloaded from cache (5 downloading)
  84. 2.19 s Downloaded cached nghttp2 (2.6 MiB) in 94ms
  85. 2.19 s Progress: 0 of 4 built, 26 of 48 downloaded from cache (4 downloading)
  86. 2.19 s Downloading cached nghttp2-1.69.0-dev from https://cache.staging.nix-ci.com
  87. 2.20 s Downloaded cached nix-expr-c (402 KiB) in 49ms
  88. 2.20 s Progress: 0 of 4 built, 27 of 48 downloaded from cache (4 downloading)
  89. 2.20 s Downloading cached nix-flake-c from https://cache.staging.nix-ci.com
  90. 2.22 s Downloaded cached nghttp2-1.69.0-dev (241 KiB) in 32ms
  91. 2.22 s Progress: 0 of 4 built, 28 of 48 downloaded from cache (4 downloading)
  92. 2.22 s Downloading cached curl-8.21.0-dev from https://cache.staging.nix-ci.com
  93. 2.23 s Downloaded cached nix-flake-c (146 KiB) in 32ms
  94. 2.23 s Progress: 0 of 4 built, 29 of 48 downloaded from cache (4 downloading)
  95. 2.26 s Downloaded cached curl-8.21.0-dev (275 KiB) in 34ms
  96. 2.26 s Progress: 0 of 4 built, 30 of 48 downloaded from cache (3 downloading)
  97. 2.44 s Downloaded cached niks3-tests (48.1 MiB) in 586ms
  98. 2.44 s Progress: 0 of 4 built, 31 of 48 downloaded from cache (2 downloading)
  99. 2.46 s Downloaded cached numactl-2.0.18-dev (19 KiB) in 603ms
  100. 2.46 s Progress: 0 of 3 built, 32 of 48 downloaded from cache (1 downloading)
  101. 2.46 s Downloading cached postgresql-18.4-dev from https://cache.staging.nix-ci.com
  102. 2.60 s Downloaded cached postgresql-18.4-dev (11.4 MiB) in 136ms
  103. 2.60 s Progress: 0 of 3 built, 33 of 48 downloaded from cache (1 downloading)
  104. 3.09 s Downloaded cached boost-1.89.0-dev (147.1 MiB) in 1.2s
  105. 3.09 s Progress: 0 of 2 built, 34 of 48 downloaded from cache
  106. 3.09 s Downloading cached nix-util-2.34.8-dev from https://cache.staging.nix-ci.com
  107. 3.13 s Downloaded cached nix-util-2.34.8-dev (342 KiB) in 43ms
  108. 3.13 s Progress: 0 of 2 built, 35 of 48 downloaded from cache
  109. 3.13 s Downloading cached nix-store-2.34.8-dev from https://cache.staging.nix-ci.com
  110. 3.13 s Downloading cached nix-util-c-2.34.8-dev from https://cache.staging.nix-ci.com
  111. 3.16 s Downloaded cached nix-util-c-2.34.8-dev (15 KiB) in 32ms
  112. 3.16 s Progress: 0 of 2 built, 36 of 48 downloaded from cache (1 downloading)
  113. 3.17 s Downloaded cached nix-store-2.34.8-dev (425 KiB) in 39ms
  114. 3.17 s Progress: 0 of 2 built, 37 of 48 downloaded from cache
  115. 3.17 s Downloading cached nix-fetchers-2.34.8-dev from https://cache.staging.nix-ci.com
  116. 3.17 s Downloading cached nix-store-c-2.34.8-dev from https://cache.staging.nix-ci.com
  117. 3.20 s Downloaded cached nix-fetchers-2.34.8-dev (34 KiB) in 32ms
  118. 3.20 s Progress: 0 of 2 built, 38 of 48 downloaded from cache (1 downloading)
  119. 3.20 s Downloaded cached nix-store-c-2.34.8-dev (17 KiB) in 32ms
  120. 3.20 s Progress: 0 of 2 built, 39 of 48 downloaded from cache (1 downloading)
  121. 3.20 s Downloading cached nix-expr-2.34.8-dev from https://cache.staging.nix-ci.com
  122. 3.24 s Downloaded cached nix-expr-2.34.8-dev (739 KiB) in 34ms
  123. 3.24 s Progress: 0 of 2 built, 40 of 48 downloaded from cache
  124. 3.24 s Downloading cached nix-expr-c-2.34.8-dev from https://cache.staging.nix-ci.com
  125. 3.24 s Downloading cached nix-flake-2.34.8-dev from https://cache.staging.nix-ci.com
  126. 3.24 s Downloading cached nix-main-2.34.8-dev from https://cache.staging.nix-ci.com
  127. 3.27 s Downloaded cached nix-expr-c-2.34.8-dev (50 KiB) in 32ms
  128. 3.27 s Progress: 0 of 2 built, 41 of 48 downloaded from cache (2 downloading)
  129. 3.27 s Downloading cached nix-fetchers-c-2.34.8-dev from https://cache.staging.nix-ci.com
  130. 3.27 s Downloaded cached nix-main-2.34.8-dev (10 KiB) in 34ms
  131. 3.27 s Progress: 0 of 2 built, 42 of 48 downloaded from cache (2 downloading)
  132. 3.27 s Downloading cached nix-main-c-2.34.8-dev from https://cache.staging.nix-ci.com
  133. 3.28 s Downloaded cached nix-flake-2.34.8-dev (19 KiB) in 37ms
  134. 3.28 s Progress: 0 of 2 built, 43 of 48 downloaded from cache (2 downloading)
  135. 3.28 s Downloading cached nix-cmd-2.34.8-dev from https://cache.staging.nix-ci.com
  136. 3.30 s Downloaded cached nix-main-c-2.34.8-dev (3136 B) in 29ms
  137. 3.30 s Progress: 0 of 2 built, 44 of 48 downloaded from cache (2 downloading)
  138. 3.31 s Downloaded cached nix-cmd-2.34.8-dev (44 KiB) in 30ms
  139. 3.31 s Progress: 0 of 2 built, 45 of 48 downloaded from cache (1 downloading)
  140. 3.40 s Downloaded cached nix-fetchers-c-2.34.8-dev (3264 B) in 128ms
  141. 3.40 s Progress: 0 of 2 built, 46 of 48 downloaded from cache
  142. 3.40 s Downloading cached nix-flake-c-2.34.8-dev from https://cache.staging.nix-ci.com
  143. 3.44 s Downloaded cached nix-flake-c-2.34.8-dev (11 KiB) in 36ms
  144. 3.44 s Progress: 0 of 2 built, 47 of 48 downloaded from cache
  145. 3.44 s Downloading cached nix-2.34.8-dev from https://cache.staging.nix-ci.com
  146. 3.48 s Downloaded cached nix-2.34.8-dev (91 KiB) in 38ms
  147. 3.48 s Progress: 0 of 2 built, 48 of 48 downloaded from cache
  148. 3.59 s Building /nix/store/pjvglmgx4k8v1fgng4daqcmi9q9hf5f5-niks3-go-unit-tests.drv
  149. 3.70 s [niks3-go-unit-tests] Running client tests...
  150. 3.70 s [niks3-go-unit-tests] === RUN TestDoServerRequestAttachesToken
  151. 3.70 s [niks3-go-unit-tests] === PAUSE TestDoServerRequestAttachesToken
  152. 3.70 s [niks3-go-unit-tests] === RUN TestCaseHackSuffix
  153. 3.70 s [niks3-go-unit-tests] === PAUSE TestCaseHackSuffix
  154. 3.70 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR
  155. 3.70 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR
  156. 3.70 s [niks3-go-unit-tests] === RUN TestUploadMultipart_SupersededByPeer
  157. 3.70 s [niks3-go-unit-tests] === PAUSE TestUploadMultipart_SupersededByPeer
  158. 3.70 s [niks3-go-unit-tests] === RUN TestDumpPathMatchesNix
  159. 3.70 s [niks3-go-unit-tests] === PAUSE TestDumpPathMatchesNix
  160. 3.70 s [niks3-go-unit-tests] === RUN TestDumpPathSingleFile
  161. 3.70 s [niks3-go-unit-tests] === PAUSE TestDumpPathSingleFile
  162. 3.70 s [niks3-go-unit-tests] === RUN TestDumpPathWriterError
  163. 3.70 s [niks3-go-unit-tests] === PAUSE TestDumpPathWriterError
  164. 3.70 s [niks3-go-unit-tests] === RUN TestEncodeNixBase32
  165. 3.70 s [niks3-go-unit-tests] === PAUSE TestEncodeNixBase32
  166. 3.70 s [niks3-go-unit-tests] === RUN TestEncodeNixBase32WithRealHash
  167. 3.70 s [niks3-go-unit-tests] === PAUSE TestEncodeNixBase32WithRealHash
  168. 3.70 s [niks3-go-unit-tests] === RUN TestConvertHashToNix32
  169. 3.70 s [niks3-go-unit-tests] === PAUSE TestConvertHashToNix32
  170. 3.70 s [niks3-go-unit-tests] === RUN TestGetStorePathHash
  171. 3.70 s [niks3-go-unit-tests] === PAUSE TestGetStorePathHash
  172. 3.70 s [niks3-go-unit-tests] === RUN TestPathInfoHashCompatibility
  173. 3.70 s [niks3-go-unit-tests] === PAUSE TestPathInfoHashCompatibility
  174. 3.70 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSON
  175. 3.70 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSON
  176. 3.70 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSONMultiplePaths
  177. 3.70 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSONMultiplePaths
  178. 3.70 s [niks3-go-unit-tests] === RUN TestPathInfoCACompatibility
  179. 3.70 s [niks3-go-unit-tests] === PAUSE TestPathInfoCACompatibility
  180. 3.70 s [niks3-go-unit-tests] === RUN TestRateLimiterFeedback
  181. 3.70 s [niks3-go-unit-tests] === PAUSE TestRateLimiterFeedback
  182. 3.70 s [niks3-go-unit-tests] === RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess
  183. 3.70 s [niks3-go-unit-tests] === PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess
  184. 3.70 s [niks3-go-unit-tests] === RUN TestResolveStorePath
  185. 3.70 s [niks3-go-unit-tests] === PAUSE TestResolveStorePath
  186. 3.70 s [niks3-go-unit-tests] === RUN TestDoWithRetry_BodyReplayedViaGetBody
  187. 3.70 s [niks3-go-unit-tests] === PAUSE TestDoWithRetry_BodyReplayedViaGetBody
  188. 3.70 s [niks3-go-unit-tests] === RUN TestShellSplit
  189. 3.70 s [niks3-go-unit-tests] === PAUSE TestShellSplit
  190. 3.70 s [niks3-go-unit-tests] === RUN TestShellSplitErrors
  191. 3.70 s [niks3-go-unit-tests] === PAUSE TestShellSplitErrors
  192. 3.70 s [niks3-go-unit-tests] === RUN TestSetClientTLS
  193. 3.70 s [niks3-go-unit-tests] === PAUSE TestSetClientTLS
  194. 3.70 s [niks3-go-unit-tests] === RUN TestSetClientTLSDoesNotMutateDefaultTransport
  195. 3.70 s [niks3-go-unit-tests] === PAUSE TestSetClientTLSDoesNotMutateDefaultTransport
  196. 3.70 s [niks3-go-unit-tests] === RUN TestSetClientTLSErrors
  197. 3.70 s [niks3-go-unit-tests] === PAUSE TestSetClientTLSErrors
  198. 3.70 s [niks3-go-unit-tests] === RUN TestStaticToken
  199. 3.70 s [niks3-go-unit-tests] === PAUSE TestStaticToken
  200. 3.70 s [niks3-go-unit-tests] === RUN TestFileTokenReadsAndCaches
  201. 3.70 s [niks3-go-unit-tests] === PAUSE TestFileTokenReadsAndCaches
  202. 3.70 s [niks3-go-unit-tests] === RUN TestFileTokenMissing
  203. 3.70 s [niks3-go-unit-tests] === PAUSE TestFileTokenMissing
  204. 3.70 s [niks3-go-unit-tests] === RUN TestFileTokenEmpty
  205. 3.70 s [niks3-go-unit-tests] === PAUSE TestFileTokenEmpty
  206. 3.70 s [niks3-go-unit-tests] === RUN TestScriptTokenNoExpiryRerunsEveryCall
  207. 3.70 s [niks3-go-unit-tests] === PAUSE TestScriptTokenNoExpiryRerunsEveryCall
  208. 3.70 s [niks3-go-unit-tests] === RUN TestScriptTokenCachesUntilRefresh
  209. 3.70 s [niks3-go-unit-tests] === PAUSE TestScriptTokenCachesUntilRefresh
  210. 3.70 s [niks3-go-unit-tests] === RUN TestScriptTokenEmptyToken
  211. 3.70 s [niks3-go-unit-tests] === PAUSE TestScriptTokenEmptyToken
  212. 3.70 s [niks3-go-unit-tests] === RUN TestScriptTokenBadJSON
  213. 3.70 s [niks3-go-unit-tests] === PAUSE TestScriptTokenBadJSON
  214. 3.70 s [niks3-go-unit-tests] === RUN TestScriptTokenScriptFails
  215. 3.70 s [niks3-go-unit-tests] === PAUSE TestScriptTokenScriptFails
  216. 3.70 s [niks3-go-unit-tests] === RUN TestScriptTokenEmptyCommand
  217. 3.70 s [niks3-go-unit-tests] === PAUSE TestScriptTokenEmptyCommand
  218. 3.70 s [niks3-go-unit-tests] === CONT TestDoServerRequestAttachesToken
  219. 3.70 s [niks3-go-unit-tests] === CONT TestResolveStorePath
  220. 3.70 s [niks3-go-unit-tests] === CONT TestFileTokenMissing
  221. 3.70 s [niks3-go-unit-tests] === CONT TestSetClientTLSDoesNotMutateDefaultTransport
  222. 3.70 s [niks3-go-unit-tests] === CONT TestFileTokenReadsAndCaches
  223. 3.70 s [niks3-go-unit-tests] --- PASS: TestResolveStorePath (0.00s)
  224. 3.70 s [niks3-go-unit-tests] === CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess
  225. 3.70 s [niks3-go-unit-tests] --- PASS: TestFileTokenMissing (0.00s)
  226. 3.70 s [niks3-go-unit-tests] === CONT TestRateLimiterFeedback
  227. 3.70 s [niks3-go-unit-tests] === RUN TestRateLimiterFeedback/429_enables_limiter
  228. 3.70 s [niks3-go-unit-tests] === PAUSE TestRateLimiterFeedback/429_enables_limiter
  229. 3.70 s [niks3-go-unit-tests] === RUN TestRateLimiterFeedback/503_enables_limiter
  230. 3.70 s [niks3-go-unit-tests] 2026/07/18 13:56:22 WARN Rate limiter enabled after throttle name=server-test rate=5
  231. 3.70 s [niks3-go-unit-tests] === CONT TestStaticToken
  232. 3.70 s [niks3-go-unit-tests] === PAUSE TestRateLimiterFeedback/503_enables_limiter
  233. 3.70 s [niks3-go-unit-tests] === RUN TestRateLimiterFeedback/200_does_not_enable_limiter
  234. 3.70 s [niks3-go-unit-tests] === PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter
  235. 3.70 s [niks3-go-unit-tests] === CONT TestScriptTokenEmptyToken
  236. 3.70 s [niks3-go-unit-tests] --- PASS: TestStaticToken (0.00s)
  237. 3.70 s [niks3-go-unit-tests] === CONT TestScriptTokenEmptyCommand
  238. 3.70 s [niks3-go-unit-tests] --- PASS: TestScriptTokenEmptyCommand (0.00s)
  239. 3.70 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSONMultiplePaths
  240. 3.70 s [niks3-go-unit-tests] === CONT TestScriptTokenScriptFails
  241. 3.70 s [niks3-go-unit-tests] === CONT TestScriptTokenBadJSON
  242. 3.70 s [niks3-go-unit-tests] === CONT TestScriptTokenNoExpiryRerunsEveryCall
  243. 3.70 s [niks3-go-unit-tests] === CONT TestScriptTokenCachesUntilRefresh
  244. 3.70 s [niks3-go-unit-tests] === CONT TestConvertHashToNix32
  245. 3.70 s [niks3-go-unit-tests] === CONT TestPathInfoHashCompatibility
  246. 3.70 s [niks3-go-unit-tests] === RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)
  247. 3.70 s [niks3-go-unit-tests] === PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)
  248. 3.70 s [niks3-go-unit-tests] === RUN TestConvertHashToNix32/SRI_format_to_Nix32
  249. 3.70 s [niks3-go-unit-tests] === PAUSE TestConvertHashToNix32/SRI_format_to_Nix32
  250. 3.70 s [niks3-go-unit-tests] === CONT TestSetClientTLSErrors
  251. 3.70 s [niks3-go-unit-tests] === RUN TestRateLimiterFeedback/400_does_not_enable_limiter
  252. 3.70 s [niks3-go-unit-tests] === PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter
  253. 3.70 s [niks3-go-unit-tests] === CONT TestGetStorePathHash
  254. 3.70 s [niks3-go-unit-tests] === RUN TestGetStorePathHash/valid_store_path
  255. 3.70 s [niks3-go-unit-tests] === PAUSE TestGetStorePathHash/valid_store_path
  256. 3.70 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths
  257. 3.70 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths
  258. 3.70 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths
  259. 3.70 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths
  260. 3.70 s [niks3-go-unit-tests] --- PASS: TestDoServerRequestAttachesToken (0.00s)
  261. 3.70 s [niks3-go-unit-tests] === CONT TestFileTokenEmpty
  262. 3.70 s [niks3-go-unit-tests] === RUN TestConvertHashToNix32/already_Nix32_format
  263. 3.70 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSON
  264. 3.70 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSON/Nix_format
  265. 3.70 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSON/Nix_format
  266. 3.70 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSON/Lix_format
  267. 3.70 s [niks3-go-unit-tests] === CONT TestPathInfoCACompatibility
  268. 3.70 s [niks3-go-unit-tests] --- PASS: TestFileTokenEmpty (0.00s)
  269. 3.70 s [niks3-go-unit-tests] === RUN TestPathInfoCACompatibility/null_ca_field
  270. 3.70 s [niks3-go-unit-tests] === PAUSE TestPathInfoCACompatibility/null_ca_field
  271. 3.70 s [niks3-go-unit-tests] === CONT TestShellSplit
  272. 3.70 s [niks3-go-unit-tests] --- PASS: TestShellSplit (0.00s)
  273. 3.70 s [niks3-go-unit-tests] === RUN TestPathInfoCACompatibility/old_string_format_-_text
  274. 3.70 s [niks3-go-unit-tests] === CONT TestDumpPathSingleFile
  275. 3.70 s [niks3-go-unit-tests] === PAUSE TestPathInfoCACompatibility/old_string_format_-_text
  276. 3.70 s [niks3-go-unit-tests] === RUN TestSetClientTLSErrors/missing_cert_file
  277. 3.70 s [niks3-go-unit-tests] === RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive
  278. 3.70 s [niks3-go-unit-tests] === PAUSE TestSetClientTLSErrors/missing_cert_file
  279. 3.70 s [niks3-go-unit-tests] === RUN TestSetClientTLSErrors/missing_key_file
  280. 3.70 s [niks3-go-unit-tests] === PAUSE TestSetClientTLSErrors/missing_key_file
  281. 3.70 s [niks3-go-unit-tests] === RUN TestSetClientTLSErrors/missing_ca_file
  282. 3.70 s [niks3-go-unit-tests] === PAUSE TestSetClientTLSErrors/missing_ca_file
  283. 3.70 s [niks3-go-unit-tests] === RUN TestSetClientTLSErrors/invalid_ca_file
  284. 3.70 s [niks3-go-unit-tests] === PAUSE TestSetClientTLSErrors/invalid_ca_file
  285. 3.70 s [niks3-go-unit-tests] === PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive
  286. 3.70 s [niks3-go-unit-tests] === RUN TestPathInfoCACompatibility/new_structured_format_-_text
  287. 3.70 s [niks3-go-unit-tests] === PAUSE TestPathInfoCACompatibility/new_structured_format_-_text
  288. 3.70 s [niks3-go-unit-tests] === RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method
  289. 3.70 s [niks3-go-unit-tests] === CONT TestEncodeNixBase32WithRealHash
  290. 3.70 s [niks3-go-unit-tests] --- PASS: TestEncodeNixBase32WithRealHash (0.00s)
  291. 3.70 s [niks3-go-unit-tests] === CONT TestEncodeNixBase32
  292. 3.70 s [niks3-go-unit-tests] === RUN TestEncodeNixBase32/test_string_hash
  293. 3.70 s [niks3-go-unit-tests] === PAUSE TestEncodeNixBase32/test_string_hash
  294. 3.70 s [niks3-go-unit-tests] === RUN TestEncodeNixBase32/empty_input
  295. 3.70 s [niks3-go-unit-tests] === PAUSE TestEncodeNixBase32/empty_input
  296. 3.70 s [niks3-go-unit-tests] === PAUSE TestConvertHashToNix32/already_Nix32_format
  297. 3.70 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSON/Lix_format
  298. 3.70 s [niks3-go-unit-tests] === RUN TestGetStorePathHash/basename_without_hyphen_should_error
  299. 3.70 s [niks3-go-unit-tests] --- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)
  300. 3.70 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSON/empty_input
  301. 3.70 s [niks3-go-unit-tests] === PAUSE TestGetStorePathHash/basename_without_hyphen_should_error
  302. 3.70 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSON/empty_input
  303. 3.70 s [niks3-go-unit-tests] === RUN TestGetStorePathHash/hash_with_invalid_characters_should_error
  304. 3.70 s [niks3-go-unit-tests] === PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method
  305. 3.70 s [niks3-go-unit-tests] === CONT TestDumpPathWriterError
  306. 3.70 s [niks3-go-unit-tests] === RUN TestPathInfoHashCompatibility/old_string_format_with_colon
  307. 3.70 s [niks3-go-unit-tests] === RUN TestConvertHashToNix32/invalid_format
  308. 3.70 s [niks3-go-unit-tests] === CONT TestUploadMultipart_SupersededByPeer
  309. 3.70 s [niks3-go-unit-tests] === PAUSE TestConvertHashToNix32/invalid_format
  310. 3.70 s [niks3-go-unit-tests] === RUN TestUploadMultipart_SupersededByPeer/exists
  311. 3.70 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSON/whitespace_only
  312. 3.70 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSON/whitespace_only
  313. 3.70 s [niks3-go-unit-tests] === CONT TestDumpPathMatchesNix
  314. 3.70 s [niks3-go-unit-tests] === PAUSE TestUploadMultipart_SupersededByPeer/exists
  315. 3.70 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSON/invalid_JSON
  316. 3.70 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSON/invalid_JSON
  317. 3.70 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR
  318. 3.70 s [niks3-go-unit-tests] === CONT TestCaseHackSuffix
  319. 3.70 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/zero_stays_at_minimum
  320. 3.70 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/zero_stays_at_minimum
  321. 3.70 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/small_stays_at_minimum
  322. 3.70 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/small_stays_at_minimum
  323. 3.70 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/80_GiB_fits_at_minimum
  324. 3.70 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum
  325. 3.70 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/115_GiB_needs_larger_parts
  326. 3.70 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts
  327. 3.70 s [niks3-go-unit-tests] === PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error
  328. 3.70 s [niks3-go-unit-tests] === RUN TestGetStorePathHash/hash_with_wrong_length_should_error
  329. 3.70 s [niks3-go-unit-tests] === PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error
  330. 3.70 s [niks3-go-unit-tests] === CONT TestDoWithRetry_BodyReplayedViaGetBody
  331. 3.70 s [niks3-go-unit-tests] === CONT TestShellSplitErrors
  332. 3.70 s [niks3-go-unit-tests] === CONT TestRateLimiterFeedback/429_enables_limiter
  333. 3.70 s [niks3-go-unit-tests] --- PASS: TestScriptTokenEmptyToken (0.00s)
  334. 3.70 s [niks3-go-unit-tests] === RUN TestUploadMultipart_SupersededByPeer/missing
  335. 3.70 s [niks3-go-unit-tests] === PAUSE TestUploadMultipart_SupersededByPeer/missing
  336. 3.70 s [niks3-go-unit-tests] --- PASS: TestScriptTokenScriptFails (0.00s)
  337. 3.70 s [niks3-go-unit-tests] --- PASS: TestScriptTokenBadJSON (0.00s)
  338. 3.70 s [niks3-go-unit-tests] --- PASS: TestShellSplitErrors (0.00s)
  339. 3.70 s [niks3-go-unit-tests] === CONT TestSetClientTLS
  340. 3.70 s [niks3-go-unit-tests] === CONT TestRateLimiterFeedback/200_does_not_enable_limiter
  341. 3.70 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/1_TiB
  342. 3.70 s [niks3-go-unit-tests] 2026/07/18 13:56:22 WARN Rate limiter enabled after throttle name=server-test rate=5
  343. 3.70 s [niks3-go-unit-tests] 2026/07/18 13:56:22 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:44317
  344. 3.71 s [niks3-go-unit-tests] === PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon
  345. 3.71 s [niks3-go-unit-tests] === RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI
  346. 3.71 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/1_TiB
  347. 3.71 s [niks3-go-unit-tests] === PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI
  348. 3.71 s [niks3-go-unit-tests] === RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512
  349. 3.71 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/5_TiB_S3_max_object
  350. 3.71 s [niks3-go-unit-tests] === PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512
  351. 3.71 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/5_TiB_S3_max_object
  352. 3.71 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/capped_at_5_GiB
  353. 3.71 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/capped_at_5_GiB
  354. 3.71 s [niks3-go-unit-tests] === CONT TestRateLimiterFeedback/400_does_not_enable_limiter
  355. 3.71 s [niks3-go-unit-tests] === CONT TestRateLimiterFeedback/503_enables_limiter
  356. 3.71 s [niks3-go-unit-tests] 2026/07/18 13:56:22 WARN Rate limiter backed off name=server-test rate=5
  357. 3.71 s [niks3-go-unit-tests] === RUN TestSetClientTLS/rejects_connection_without_client_cert
  358. 3.71 s [niks3-go-unit-tests] === PAUSE TestSetClientTLS/rejects_connection_without_client_cert
  359. 3.71 s [niks3-go-unit-tests] === RUN TestSetClientTLS/succeeds_with_client_cert_and_CA
  360. 3.71 s [niks3-go-unit-tests] === PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA
  361. 3.71 s [niks3-go-unit-tests] === RUN TestSetClientTLS/preserves_debug_logging_transport
  362. 3.71 s [niks3-go-unit-tests] === PAUSE TestSetClientTLS/preserves_debug_logging_transport
  363. 3.71 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths
  364. 3.71 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths
  365. 3.71 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)
  366. 3.71 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)
  367. 3.71 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)
  368. 3.71 s [niks3-go-unit-tests] === CONT TestSetClientTLSErrors/missing_cert_file
  369. 3.71 s [niks3-go-unit-tests] === CONT TestSetClientTLSErrors/missing_ca_file
  370. 3.71 s [niks3-go-unit-tests] 2026/07/18 13:56:22 WARN Rate limiter enabled after throttle name=server-test rate=5
  371. 3.71 s [niks3-go-unit-tests] 2026/07/18 13:56:22 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:41909
  372. 3.71 s [niks3-go-unit-tests] === CONT TestSetClientTLSErrors/invalid_ca_file
  373. 3.71 s [niks3-go-unit-tests] === CONT TestSetClientTLSErrors/missing_key_file
  374. 3.71 s [niks3-go-unit-tests] === CONT TestEncodeNixBase32/test_string_hash
  375. 3.71 s [niks3-go-unit-tests] === CONT TestEncodeNixBase32/empty_input
  376. 3.71 s [niks3-go-unit-tests] --- PASS: TestEncodeNixBase32 (0.00s)
  377. 3.71 s [niks3-go-unit-tests] --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)
  378. 3.71 s [niks3-go-unit-tests] --- PASS: TestEncodeNixBase32/empty_input (0.00s)
  379. 3.71 s [niks3-go-unit-tests] === CONT TestPathInfoCACompatibility/null_ca_field
  380. 3.71 s [niks3-go-unit-tests] === CONT TestPathInfoCACompatibility/new_structured_format_-_text
  381. 3.71 s [niks3-go-unit-tests] 2026/07/18 13:56:22 WARN Rate limiter backed off name=server-test rate=5
  382. 3.71 s [niks3-go-unit-tests] 2026/07/18 13:56:22 WARN Rate limiter enabled after throttle name=server-test rate=5
  383. 3.71 s [niks3-go-unit-tests] 2026/07/18 13:56:22 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:33679
  384. 3.71 s [niks3-go-unit-tests] === CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive
  385. 3.72 s [niks3-go-unit-tests] === CONT TestPathInfoCACompatibility/old_string_format_-_text
  386. 3.72 s [niks3-go-unit-tests] === CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method
  387. 3.72 s [niks3-go-unit-tests] === CONT TestConvertHashToNix32/already_Nix32_format
  388. 3.72 s [niks3-go-unit-tests] === CONT TestConvertHashToNix32/SRI_format_to_Nix32
  389. 3.72 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSON/Nix_format
  390. 3.72 s [niks3-go-unit-tests] === CONT TestConvertHashToNix32/invalid_format
  391. 3.72 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSON/whitespace_only
  392. 3.72 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSON/empty_input
  393. 3.72 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSON/Lix_format
  394. 3.72 s [niks3-go-unit-tests] === CONT TestGetStorePathHash/hash_with_wrong_length_should_error
  395. 3.72 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSON/invalid_JSON
  396. 3.72 s [niks3-go-unit-tests] === CONT TestGetStorePathHash/hash_with_invalid_characters_should_error
  397. 3.72 s [niks3-go-unit-tests] === CONT TestGetStorePathHash/valid_store_path
  398. 3.72 s [niks3-go-unit-tests] === CONT TestUploadMultipart_SupersededByPeer/exists
  399. 3.72 s [niks3-go-unit-tests] === CONT TestGetStorePathHash/basename_without_hyphen_should_error
  400. 3.72 s [niks3-go-unit-tests] === CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)
  401. 3.72 s [niks3-go-unit-tests] === CONT TestUploadMultipart_SupersededByPeer/missing
  402. 3.72 s [niks3-go-unit-tests] --- PASS: TestConvertHashToNix32 (0.00s)
  403. 3.72 s [niks3-go-unit-tests] --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)
  404. 3.72 s [niks3-go-unit-tests] --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)
  405. 3.72 s [niks3-go-unit-tests] --- PASS: TestConvertHashToNix32/invalid_format (0.00s)
  406. 3.72 s [niks3-go-unit-tests] --- PASS: TestRateLimiterFeedback (0.00s)
  407. 3.72 s [niks3-go-unit-tests] --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)
  408. 3.72 s [niks3-go-unit-tests] --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s)
  409. 3.72 s [niks3-go-unit-tests] --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)
  410. 3.72 s [niks3-go-unit-tests] --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)
  411. 3.72 s [niks3-go-unit-tests] === CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512
  412. 3.72 s [niks3-go-unit-tests] === CONT TestPathInfoHashCompatibility/old_string_format_with_colon
  413. 3.72 s [niks3-go-unit-tests] 2026/07/18 13:56:22 WARN Rate limiter backed off name=server-test rate=5
  414. 3.72 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/zero_stays_at_minimum
  415. 3.72 s [niks3-go-unit-tests] === CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI
  416. 3.72 s [niks3-go-unit-tests] 2026/07/18 13:56:22 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:33679
  417. 3.72 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/1_TiB
  418. 3.72 s [niks3-go-unit-tests] --- PASS: TestPathInfoCACompatibility (0.00s)
  419. 3.72 s [niks3-go-unit-tests] --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)
  420. 3.72 s [niks3-go-unit-tests] --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)
  421. 3.72 s [niks3-go-unit-tests] --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)
  422. 3.72 s [niks3-go-unit-tests] --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)
  423. 3.72 s [niks3-go-unit-tests] --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)
  424. 3.72 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/80_GiB_fits_at_minimum
  425. 3.72 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/small_stays_at_minimum
  426. 3.72 s [niks3-go-unit-tests] --- PASS: TestGetStorePathHash (0.00s)
  427. 3.72 s [niks3-go-unit-tests] --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)
  428. 3.72 s [niks3-go-unit-tests] --- PASS: TestGetStorePathHash/valid_store_path (0.00s)
  429. 3.72 s [niks3-go-unit-tests] --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)
  430. 3.72 s [niks3-go-unit-tests] --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)
  431. 3.72 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/5_TiB_S3_max_object
  432. 3.72 s [niks3-go-unit-tests] === CONT TestSetClientTLS/rejects_connection_without_client_cert
  433. 3.72 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSON (0.00s)
  434. 3.72 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)
  435. 3.72 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSON/empty_input (0.00s)
  436. 3.72 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)
  437. 3.72 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)
  438. 3.72 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)
  439. 3.72 s [niks3-go-unit-tests] --- PASS: TestPathInfoHashCompatibility (0.01s)
  440. 3.72 s [niks3-go-unit-tests] --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)
  441. 3.72 s [niks3-go-unit-tests] --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)
  442. 3.72 s [niks3-go-unit-tests] --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)
  443. 3.72 s [niks3-go-unit-tests] --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)
  444. 3.72 s [niks3-go-unit-tests] --- PASS: TestSetClientTLSErrors (0.00s)
  445. 3.72 s [niks3-go-unit-tests] --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)
  446. 3.72 s [niks3-go-unit-tests] --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)
  447. 3.72 s [niks3-go-unit-tests] --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)
  448. 3.72 s [niks3-go-unit-tests] --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.01s)
  449. 3.72 s [niks3-go-unit-tests] 2026/07/18 13:56:22 http: TLS handshake error from 127.0.0.1:44286: remote error: tls: bad certificate
  450. 3.72 s [niks3-go-unit-tests] === CONT TestSetClientTLS/preserves_debug_logging_transport
  451. 3.72 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/115_GiB_needs_larger_parts
  452. 3.72 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/capped_at_5_GiB
  453. 3.72 s [niks3-go-unit-tests] === CONT TestSetClientTLS/succeeds_with_client_cert_and_CA
  454. 3.72 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR (0.00s)
  455. 3.72 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)
  456. 3.72 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/1_TiB (0.00s)
  457. 3.72 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)
  458. 3.72 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)
  459. 3.72 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)
  460. 3.72 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)
  461. 3.72 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)
  462. 3.72 s [niks3-go-unit-tests] --- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)
  463. 3.72 s [niks3-go-unit-tests] --- PASS: TestUploadMultipart_SupersededByPeer (0.00s)
  464. 3.72 s [niks3-go-unit-tests] --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)
  465. 3.72 s [niks3-go-unit-tests] --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s)
  466. 3.72 s [niks3-go-unit-tests] --- PASS: TestSetClientTLS (0.01s)
  467. 3.72 s [niks3-go-unit-tests] --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.00s)
  468. 3.72 s [niks3-go-unit-tests] --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)
  469. 3.72 s [niks3-go-unit-tests] --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)
  470. 3.72 s [niks3-go-unit-tests] --- PASS: TestCaseHackSuffix (0.02s)
  471. 3.73 s [niks3-go-unit-tests] --- PASS: TestDumpPathSingleFile (0.03s)
  472. 3.73 s [niks3-go-unit-tests] --- PASS: TestDumpPathWriterError (0.03s)
  473. 3.75 s [niks3-go-unit-tests] --- PASS: TestDumpPathMatchesNix (0.05s)
  474. 3.76 s [niks3-go-unit-tests] --- PASS: TestFileTokenReadsAndCaches (0.06s)
  475. 3.76 s [niks3-go-unit-tests] --- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.06s)
  476. 3.76 s [niks3-go-unit-tests] --- PASS: TestScriptTokenCachesUntilRefresh (0.06s)
  477. 4.70 s [niks3-go-unit-tests] --- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)
  478. 4.70 s [niks3-go-unit-tests] PASS
  479. 5.26 s [niks3-go-unit-tests] Running server tests...
  480. 5.39 s [niks3-go-unit-tests] The files belonging to this database system will be owned by user "nixbld".
  481. 5.39 s [niks3-go-unit-tests] This user must also own the server process.
  482. 5.39 s [niks3-go-unit-tests]
  483. 5.39 s [niks3-go-unit-tests] The database cluster will be initialized with locale "C".
  484. 5.39 s [niks3-go-unit-tests] The default database encoding has accordingly been set to "SQL_ASCII".
  485. 5.39 s [niks3-go-unit-tests] The default text search configuration will be set to "english".
  486. 5.39 s [niks3-go-unit-tests]
  487. 5.39 s [niks3-go-unit-tests] Data page checksums are enabled.
  488. 5.39 s [niks3-go-unit-tests]
  489. 5.39 s [niks3-go-unit-tests] creating directory /build/postgres213714210/data ... ok
  490. 5.39 s [niks3-go-unit-tests] creating subdirectories ... ok
  491. 5.39 s [niks3-go-unit-tests] selecting dynamic shared memory implementation ... posix
  492. 5.39 s [niks3-go-unit-tests] selecting default "max_connections" ... 100
  493. 5.39 s [niks3-go-unit-tests] selecting default "shared_buffers" ... 128MB
  494. 5.39 s [niks3-go-unit-tests] selecting default time zone ... UTC
  495. 5.39 s [niks3-go-unit-tests] creating configuration files ... ok
  496. 5.39 s [niks3-go-unit-tests] running bootstrap script ... ok
  497. 5.62 s [niks3-go-unit-tests] performing post-bootstrap initialization ... ok
  498. 5.96 s [niks3-go-unit-tests] syncing data to disk ... ok
  499. 5.96 s [niks3-go-unit-tests]
  500. 5.96 s [niks3-go-unit-tests] initdb: warning: enabling "trust" authentication for local connections
  501. 5.96 s [niks3-go-unit-tests] initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.
  502. 5.96 s [niks3-go-unit-tests]
  503. 5.96 s [niks3-go-unit-tests] Success. You can now start the database server using:
  504. 5.96 s [niks3-go-unit-tests]
  505. 5.96 s [niks3-go-unit-tests] pg_ctl -D /build/postgres213714210/data -l logfile start
  506. 5.96 s [niks3-go-unit-tests]
  507. 6.01 s [niks3-go-unit-tests] /build/postgres213714210:5432 - no response
  508. 6.01 s [niks3-go-unit-tests] 2026-07-18 13:56:24.711 UTC [99] LOG: starting PostgreSQL 18.4 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit
  509. 6.01 s [niks3-go-unit-tests] 2026-07-18 13:56:24.719 UTC [99] LOG: listening on Unix socket "/build/postgres213714210/.s.PGSQL.5432"
  510. 6.03 s [niks3-go-unit-tests] 2026-07-18 13:56:24.749 UTC [106] LOG: database system was shut down at 2026-07-18 13:56:24 UTC
  511. 6.04 s [niks3-go-unit-tests] 2026-07-18 13:56:24.759 UTC [99] LOG: database system is ready to accept connections
  512. 6.07 s [niks3-go-unit-tests] /build/postgres213714210:5432 - accepting connections
  513. 6.09 s [niks3-go-unit-tests] {"timestamp":"2026-07-18T13:56:24.811495258Z","level":"ERROR","fields":{"message":"list_path_raw: revjob err VolumeNotFound"},"target":"rustfs_ecstore::cache_value::metacache_set","filename":"crates/ecstore/src/cache_value/metacache_set.rs","line_number":486,"threadName":"rustfs-worker","threadId":"ThreadId(16)"}
  514. 6.10 s [niks3-go-unit-tests]
  515. 6.10 s [niks3-go-unit-tests] thread 'rustfs-worker' (131) panicked at /build/rustfs-1.0.0-beta.7-vendor/source-registry-0/reqwest-0.13.4/src/async_impl/client.rs:2507:38:
  516. 6.10 s [niks3-go-unit-tests] Client::new(): reqwest::Error { kind: Builder, source: General("No CA certificates were loaded from the system") }
  517. 6.10 s [niks3-go-unit-tests] note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
  518. 6.17 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware
  519. 6.17 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware
  520. 6.17 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_MTLSProxyHeader
  521. 6.17 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_MTLSProxyHeader
  522. 6.17 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_MTLSBoundSubjects
  523. 6.17 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_MTLSBoundSubjects
  524. 6.17 s [niks3-go-unit-tests] === RUN TestService_ReadAuthMiddleware
  525. 6.17 s [niks3-go-unit-tests] === PAUSE TestService_ReadAuthMiddleware
  526. 6.17 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_OIDC
  527. 6.17 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_OIDC
  528. 6.17 s [niks3-go-unit-tests] === RUN TestCacheConfigHandler
  529. 6.17 s [niks3-go-unit-tests] === PAUSE TestCacheConfigHandler
  530. 6.17 s [niks3-go-unit-tests] === RUN TestCacheStatsHandler
  531. 6.17 s [niks3-go-unit-tests] === PAUSE TestCacheStatsHandler
  532. 6.17 s [niks3-go-unit-tests] === RUN TestClientCADerivations
  533. 6.17 s [niks3-go-unit-tests] === PAUSE TestClientCADerivations
  534. 6.17 s [niks3-go-unit-tests] === RUN TestClientErrorHandling
  535. 6.17 s [niks3-go-unit-tests] === PAUSE TestClientErrorHandling
  536. 6.17 s [niks3-go-unit-tests] === RUN TestClientIntegration
  537. 6.17 s [niks3-go-unit-tests] === PAUSE TestClientIntegration
  538. 6.17 s [niks3-go-unit-tests] === RUN TestClientMultipleUploads
  539. 6.17 s [niks3-go-unit-tests] === PAUSE TestClientMultipleUploads
  540. 6.17 s [niks3-go-unit-tests] === RUN TestClientWithDependencies
  541. 6.17 s [niks3-go-unit-tests] === PAUSE TestClientWithDependencies
  542. 6.17 s [niks3-go-unit-tests] === RUN TestPinProtectsFromGC
  543. 6.17 s [niks3-go-unit-tests] === PAUSE TestPinProtectsFromGC
  544. 6.17 s [niks3-go-unit-tests] === RUN TestGCAdvisoryLockBlocksConcurrentRun
  545. 6.28 s [niks3-go-unit-tests] 2026-07-18 13:56:25.004 UTC [160] ERROR: relation "goose_db_version" does not exist at character 36
  546. 6.28 s [niks3-go-unit-tests] 2026-07-18 13:56:25.004 UTC [160] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  547. 6.30 s [niks3-go-unit-tests] 2026/07/18 13:56:25 OK 20241026095416_initial_model.sql (8.43ms)
  548. 6.31 s [niks3-go-unit-tests] 2026/07/18 13:56:25 OK 20251210153512_drop_unused_gin_index.sql (5.11ms)
  549. 6.31 s [niks3-go-unit-tests] 2026/07/18 13:56:25 OK 20251218171726_add_pins.sql (6.19ms)
  550. 6.32 s [niks3-go-unit-tests] 2026/07/18 13:56:25 OK 20260628120000_add_object_size_and_stats.sql (5.01ms)
  551. 6.32 s [niks3-go-unit-tests] 2026/07/18 13:56:25 goose: successfully migrated database to version: 20260628120000
  552. 6.32 s [niks3-go-unit-tests] 2026/07/18 13:56:25 OK 1_commit_pending_closure.sql (4.74ms)
  553. 6.33 s [niks3-go-unit-tests] 2026/07/18 13:56:25 OK 2_object_stats_trigger.sql (4.94ms)
  554. 6.33 s [niks3-go-unit-tests] 2026/07/18 13:56:25 goose: up to current file version: 2
  555. 6.33 s [niks3-go-unit-tests] --- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.16s)
  556. 6.33 s [niks3-go-unit-tests] === RUN TestGCBugBareHashReferences
  557. 6.33 s [niks3-go-unit-tests] === PAUSE TestGCBugBareHashReferences
  558. 6.33 s [niks3-go-unit-tests] === RUN TestGCMetrics
  559. 6.33 s [niks3-go-unit-tests] === PAUSE TestGCMetrics
  560. 6.33 s [niks3-go-unit-tests] === RUN TestGCTaskStore_StartNew
  561. 6.33 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_StartNew
  562. 6.33 s [niks3-go-unit-tests] === RUN TestGCTaskStore_DeduplicateSameParams
  563. 6.33 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_DeduplicateSameParams
  564. 6.33 s [niks3-go-unit-tests] === RUN TestGCTaskStore_ConflictDifferentParams
  565. 6.33 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_ConflictDifferentParams
  566. 6.33 s [niks3-go-unit-tests] === RUN TestGCTaskStore_GetEmpty
  567. 6.33 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_GetEmpty
  568. 6.33 s [niks3-go-unit-tests] === RUN TestGCTaskStore_GetReturnsLatest
  569. 6.33 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_GetReturnsLatest
  570. 6.33 s [niks3-go-unit-tests] === RUN TestGCTaskStore_CompletedAllowsNewTask
  571. 6.33 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_CompletedAllowsNewTask
  572. 6.33 s [niks3-go-unit-tests] === RUN TestGCTaskStore_PhaseUpdates
  573. 6.33 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_PhaseUpdates
  574. 6.33 s [niks3-go-unit-tests] === RUN TestGCTaskStore_Fail
  575. 6.33 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_Fail
  576. 6.33 s [niks3-go-unit-tests] === RUN TestGracefulShutdownDrainsInflight
  577. 6.33 s [niks3-go-unit-tests] === PAUSE TestGracefulShutdownDrainsInflight
  578. 6.33 s [niks3-go-unit-tests] === RUN TestService_healthCheckHandler
  579. 6.33 s [niks3-go-unit-tests] === PAUSE TestService_healthCheckHandler
  580. 6.33 s [niks3-go-unit-tests] === RUN TestGenerateLandingPage
  581. 6.33 s [niks3-go-unit-tests] === PAUSE TestGenerateLandingPage
  582. 6.33 s [niks3-go-unit-tests] === RUN TestNARDeduplicationMetadataUploadBug
  583. 6.33 s [niks3-go-unit-tests] === PAUSE TestNARDeduplicationMetadataUploadBug
  584. 6.33 s [niks3-go-unit-tests] === RUN TestMetricsInventory
  585. 6.33 s [niks3-go-unit-tests] === PAUSE TestMetricsInventory
  586. 6.33 s [niks3-go-unit-tests] === RUN TestService_NativeMTLS
  587. 6.33 s [niks3-go-unit-tests] === PAUSE TestService_NativeMTLS
  588. 6.33 s [niks3-go-unit-tests] === RUN TestServerTLSConfig
  589. 6.33 s [niks3-go-unit-tests] === PAUSE TestServerTLSConfig
  590. 6.33 s [niks3-go-unit-tests] === RUN TestMultipartCleanup
  591. 6.33 s [niks3-go-unit-tests] === PAUSE TestMultipartCleanup
  592. 6.33 s [niks3-go-unit-tests] === RUN TestObjectStatsTrigger
  593. 6.33 s [niks3-go-unit-tests] === PAUSE TestObjectStatsTrigger
  594. 6.33 s [niks3-go-unit-tests] === RUN TestOrphanedObjectsGC
  595. 6.33 s [niks3-go-unit-tests] === PAUSE TestOrphanedObjectsGC
  596. 6.33 s [niks3-go-unit-tests] === RUN TestOrphanedObjectsGCStressTest
  597. 6.33 s [niks3-go-unit-tests] === PAUSE TestOrphanedObjectsGCStressTest
  598. 6.33 s [niks3-go-unit-tests] === RUN TestResurrectedObjectNotDeleted
  599. 6.33 s [niks3-go-unit-tests] === PAUSE TestResurrectedObjectNotDeleted
  600. 6.33 s [niks3-go-unit-tests] === RUN TestParseSingleRange
  601. 6.33 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange
  602. 6.33 s [niks3-go-unit-tests] === RUN TestIsValidCachePath
  603. 6.33 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath
  604. 6.33 s [niks3-go-unit-tests] === RUN TestReadProxyNarinfo
  605. 6.33 s [niks3-go-unit-tests] === PAUSE TestReadProxyNarinfo
  606. 6.33 s [niks3-go-unit-tests] === RUN TestReadProxyNarinfoAlreadyDecompressed
  607. 6.33 s [niks3-go-unit-tests] === PAUSE TestReadProxyNarinfoAlreadyDecompressed
  608. 6.33 s [niks3-go-unit-tests] === RUN TestReadProxyNarStreaming
  609. 6.33 s [niks3-go-unit-tests] === PAUSE TestReadProxyNarStreaming
  610. 6.33 s [niks3-go-unit-tests] === RUN TestReadProxy404
  611. 6.33 s [niks3-go-unit-tests] === PAUSE TestReadProxy404
  612. 6.33 s [niks3-go-unit-tests] === RUN TestReadProxyInvalidPath
  613. 6.33 s [niks3-go-unit-tests] === PAUSE TestReadProxyInvalidPath
  614. 6.33 s [niks3-go-unit-tests] === RUN TestReadProxyHead
  615. 6.33 s [niks3-go-unit-tests] === PAUSE TestReadProxyHead
  616. 6.33 s [niks3-go-unit-tests] === RUN TestReadProxyConditionalGet
  617. 6.33 s [niks3-go-unit-tests] === PAUSE TestReadProxyConditionalGet
  618. 6.33 s [niks3-go-unit-tests] === RUN TestReadProxyRootRedirectsToIndexHTML
  619. 6.33 s [niks3-go-unit-tests] === PAUSE TestReadProxyRootRedirectsToIndexHTML
  620. 6.33 s [niks3-go-unit-tests] === RUN TestReadProxyDisabled
  621. 6.33 s [niks3-go-unit-tests] === PAUSE TestReadProxyDisabled
  622. 6.33 s [niks3-go-unit-tests] === RUN TestReadProxyRangeRequest
  623. 6.33 s [niks3-go-unit-tests] === PAUSE TestReadProxyRangeRequest
  624. 6.33 s [niks3-go-unit-tests] === RUN TestRedundantMultipartUpload
  625. 6.33 s [niks3-go-unit-tests] === PAUSE TestRedundantMultipartUpload
  626. 6.33 s [niks3-go-unit-tests] === RUN TestCompleteMultipartUpload_ErrorButObjectExists
  627. 6.33 s [niks3-go-unit-tests] === PAUSE TestCompleteMultipartUpload_ErrorButObjectExists
  628. 6.34 s [niks3-go-unit-tests] === RUN TestService_Rustfstest
  629. 6.34 s [niks3-go-unit-tests] === PAUSE TestService_Rustfstest
  630. 6.34 s [niks3-go-unit-tests] === RUN TestSystemdListenerNotActivated
  631. 6.34 s [niks3-go-unit-tests] --- PASS: TestSystemdListenerNotActivated (0.00s)
  632. 6.34 s [niks3-go-unit-tests] === RUN TestWatchdogBeatsWhenHealthy
  633. 6.35 s [niks3-go-unit-tests] --- PASS: TestWatchdogBeatsWhenHealthy (0.02s)
  634. 6.35 s [niks3-go-unit-tests] === RUN TestWatchdogSkipsWhenUnhealthy
  635. 6.37 s [niks3-go-unit-tests] 2026/07/18 13:56:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  636. 6.39 s [niks3-go-unit-tests] 2026/07/18 13:56:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  637. 6.41 s [niks3-go-unit-tests] 2026/07/18 13:56:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  638. 6.43 s [niks3-go-unit-tests] 2026/07/18 13:56:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  639. 6.45 s [niks3-go-unit-tests] 2026/07/18 13:56:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  640. 6.47 s [niks3-go-unit-tests] 2026/07/18 13:56:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  641. 6.49 s [niks3-go-unit-tests] 2026/07/18 13:56:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  642. 6.51 s [niks3-go-unit-tests] 2026/07/18 13:56:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  643. 6.53 s [niks3-go-unit-tests] 2026/07/18 13:56:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  644. 6.55 s [niks3-go-unit-tests] 2026/07/18 13:56:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  645. 6.55 s [niks3-go-unit-tests] --- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)
  646. 6.55 s [niks3-go-unit-tests] === RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle
  647. 6.55 s [niks3-go-unit-tests] === PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle
  648. 6.55 s [niks3-go-unit-tests] === RUN TestProxyWriteTimeout
  649. 6.55 s [niks3-go-unit-tests] === PAUSE TestProxyWriteTimeout
  650. 6.55 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey
  651. 6.55 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey
  652. 6.56 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectInvalidKeys
  653. 6.56 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectInvalidKeys
  654. 6.56 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectOversizedBody
  655. 6.56 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectOversizedBody
  656. 6.56 s [niks3-go-unit-tests] === RUN TestService_cleanupPendingClosuresHandler
  657. 6.56 s [niks3-go-unit-tests] === PAUSE TestService_cleanupPendingClosuresHandler
  658. 6.56 s [niks3-go-unit-tests] === RUN TestService_createPendingClosureHandler
  659. 6.56 s [niks3-go-unit-tests] === PAUSE TestService_createPendingClosureHandler
  660. 6.56 s [niks3-go-unit-tests] === RUN TestService_verifyS3Integrity
  661. 6.56 s [niks3-go-unit-tests] === PAUSE TestService_verifyS3Integrity
  662. 6.56 s [niks3-go-unit-tests] === RUN TestCompleteMultipartUnregistered
  663. 6.56 s [niks3-go-unit-tests] === PAUSE TestCompleteMultipartUnregistered
  664. 6.56 s [niks3-go-unit-tests] === RUN TestCreatePendingClosure_SmallNARUsesSimplePUT
  665. 6.56 s [niks3-go-unit-tests] === PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT
  666. 6.56 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware
  667. 6.56 s [niks3-go-unit-tests] === CONT TestMultipartCleanup
  668. 6.56 s [niks3-go-unit-tests] === CONT TestReadProxyDisabled
  669. 6.56 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectInvalidKeys
  670. 6.56 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info
  671. 6.56 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info
  672. 6.56 s [niks3-go-unit-tests] === CONT TestResurrectedObjectNotDeleted
  673. 6.56 s [niks3-go-unit-tests] === CONT TestReadProxyHead
  674. 6.56 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal
  675. 6.56 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal
  676. 6.56 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key
  677. 6.56 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key
  678. 6.56 s [niks3-go-unit-tests] === CONT TestReadProxyInvalidPath
  679. 6.56 s [niks3-go-unit-tests] === CONT TestReadProxy404
  680. 6.56 s [niks3-go-unit-tests] === CONT TestReadProxyNarStreaming
  681. 6.56 s [niks3-go-unit-tests] === CONT TestGCTaskStore_StartNew
  682. 6.56 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_StartNew (0.00s)
  683. 6.56 s [niks3-go-unit-tests] === CONT TestNARDeduplicationMetadataUploadBug
  684. 6.56 s [niks3-go-unit-tests] === CONT TestServerTLSConfig
  685. 6.56 s [niks3-go-unit-tests] === RUN TestServerTLSConfig/no_client_CA
  686. 6.56 s [niks3-go-unit-tests] === PAUSE TestServerTLSConfig/no_client_CA
  687. 6.56 s [niks3-go-unit-tests] === RUN TestServerTLSConfig/missing_CA_file
  688. 6.56 s [niks3-go-unit-tests] === CONT TestService_NativeMTLS
  689. 6.56 s [niks3-go-unit-tests] === CONT TestMetricsInventory
  690. 6.56 s [niks3-go-unit-tests] === CONT TestReadProxyNarinfoAlreadyDecompressed
  691. 6.56 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key
  692. 6.56 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key
  693. 6.56 s [niks3-go-unit-tests] === CONT TestGenerateLandingPage
  694. 6.56 s [niks3-go-unit-tests] === PAUSE TestServerTLSConfig/missing_CA_file
  695. 6.56 s [niks3-go-unit-tests] === RUN TestServerTLSConfig/not_a_PEM_file
  696. 6.56 s [niks3-go-unit-tests] === PAUSE TestServerTLSConfig/not_a_PEM_file
  697. 6.56 s [niks3-go-unit-tests] === CONT TestService_healthCheckHandler
  698. 6.56 s [niks3-go-unit-tests] --- PASS: TestGenerateLandingPage (0.00s)
  699. 6.56 s [niks3-go-unit-tests] === CONT TestGracefulShutdownDrainsInflight
  700. 6.56 s [niks3-go-unit-tests] 2026/07/18 13:56:25 INFO Starting HTTP server address=127.0.0.1:46307
  701. 6.56 s [niks3-go-unit-tests] 2026/07/18 13:56:25 INFO Shutdown signal received, draining in-flight requests timeout=10s
  702. 6.63 s [niks3-go-unit-tests] --- PASS: TestGracefulShutdownDrainsInflight (0.07s)
  703. 6.63 s [niks3-go-unit-tests] === CONT TestGCTaskStore_Fail
  704. 6.63 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_Fail (0.00s)
  705. 6.63 s [niks3-go-unit-tests] === CONT TestGCTaskStore_PhaseUpdates
  706. 6.63 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_PhaseUpdates (0.00s)
  707. 6.63 s [niks3-go-unit-tests] === CONT TestGCTaskStore_CompletedAllowsNewTask
  708. 6.63 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)
  709. 6.63 s [niks3-go-unit-tests] === CONT TestGCTaskStore_GetReturnsLatest
  710. 6.63 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)
  711. 6.63 s [niks3-go-unit-tests] === CONT TestGCTaskStore_GetEmpty
  712. 6.63 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_GetEmpty (0.00s)
  713. 6.63 s [niks3-go-unit-tests] === CONT TestGCTaskStore_ConflictDifferentParams
  714. 6.63 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)
  715. 6.63 s [niks3-go-unit-tests] === CONT TestGCTaskStore_DeduplicateSameParams
  716. 6.63 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)
  717. 6.63 s [niks3-go-unit-tests] === CONT TestParseSingleRange
  718. 6.63 s [niks3-go-unit-tests] === RUN TestParseSingleRange/none
  719. 6.63 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/none
  720. 6.63 s [niks3-go-unit-tests] === RUN TestParseSingleRange/unknown_unit
  721. 6.63 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/unknown_unit
  722. 6.63 s [niks3-go-unit-tests] === RUN TestParseSingleRange/multi-range_ignored
  723. 6.63 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/multi-range_ignored
  724. 6.63 s [niks3-go-unit-tests] === RUN TestParseSingleRange/malformed_no_dash
  725. 6.63 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/malformed_no_dash
  726. 6.63 s [niks3-go-unit-tests] === RUN TestParseSingleRange/malformed_both_empty
  727. 6.63 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/malformed_both_empty
  728. 6.63 s [niks3-go-unit-tests] === RUN TestParseSingleRange/malformed_end_before_start
  729. 6.63 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/malformed_end_before_start
  730. 6.63 s [niks3-go-unit-tests] === RUN TestParseSingleRange/closed
  731. 6.63 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/closed
  732. 6.63 s [niks3-go-unit-tests] === RUN TestParseSingleRange/open-ended
  733. 6.63 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/open-ended
  734. 6.63 s [niks3-go-unit-tests] === RUN TestParseSingleRange/end_clamped_to_size
  735. 6.63 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/end_clamped_to_size
  736. 6.63 s [niks3-go-unit-tests] === RUN TestParseSingleRange/suffix
  737. 6.63 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/suffix
  738. 6.63 s [niks3-go-unit-tests] === RUN TestParseSingleRange/suffix_exceeds_size
  739. 6.63 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/suffix_exceeds_size
  740. 6.63 s [niks3-go-unit-tests] === RUN TestParseSingleRange/single_byte
  741. 6.63 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/single_byte
  742. 6.63 s [niks3-go-unit-tests] === RUN TestParseSingleRange/start_past_EOF
  743. 6.63 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/start_past_EOF
  744. 6.63 s [niks3-go-unit-tests] === RUN TestParseSingleRange/start_far_past_EOF
  745. 6.63 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/start_far_past_EOF
  746. 6.63 s [niks3-go-unit-tests] === CONT TestReadProxyRootRedirectsToIndexHTML
  747. 7.27 s [niks3-go-unit-tests] 2026-07-18 13:56:25.989 UTC [202] ERROR: relation "goose_db_version" does not exist at character 36
  748. 7.27 s [niks3-go-unit-tests] 2026-07-18 13:56:25.989 UTC [202] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  749. 7.28 s [niks3-go-unit-tests] 2026-07-18 13:56:26.004 UTC [204] ERROR: relation "goose_db_version" does not exist at character 36
  750. 7.28 s [niks3-go-unit-tests] 2026-07-18 13:56:26.004 UTC [204] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  751. 7.28 s [niks3-go-unit-tests] 2026-07-18 13:56:26.004 UTC [203] ERROR: relation "goose_db_version" does not exist at character 36
  752. 7.28 s [niks3-go-unit-tests] 2026-07-18 13:56:26.004 UTC [203] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  753. 7.29 s [niks3-go-unit-tests] 2026-07-18 13:56:26.005 UTC [205] ERROR: relation "goose_db_version" does not exist at character 36
  754. 7.29 s [niks3-go-unit-tests] 2026-07-18 13:56:26.005 UTC [205] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  755. 7.29 s [niks3-go-unit-tests] 2026-07-18 13:56:26.011 UTC [206] ERROR: relation "goose_db_version" does not exist at character 36
  756. 7.29 s [niks3-go-unit-tests] 2026-07-18 13:56:26.011 UTC [206] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  757. 7.29 s [niks3-go-unit-tests] 2026-07-18 13:56:26.014 UTC [207] ERROR: relation "goose_db_version" does not exist at character 36
  758. 7.30 s [niks3-go-unit-tests] 2026-07-18 13:56:26.014 UTC [207] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  759. 7.30 s [niks3-go-unit-tests] 2026-07-18 13:56:26.015 UTC [209] ERROR: relation "goose_db_version" does not exist at character 36
  760. 7.30 s [niks3-go-unit-tests] 2026-07-18 13:56:26.015 UTC [209] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  761. 7.30 s [niks3-go-unit-tests] 2026-07-18 13:56:26.016 UTC [210] ERROR: relation "goose_db_version" does not exist at character 36
  762. 7.30 s [niks3-go-unit-tests] 2026-07-18 13:56:26.016 UTC [210] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  763. 7.30 s [niks3-go-unit-tests] 2026-07-18 13:56:26.017 UTC [208] ERROR: relation "goose_db_version" does not exist at character 36
  764. 7.30 s [niks3-go-unit-tests] 2026-07-18 13:56:26.017 UTC [208] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  765. 7.30 s [niks3-go-unit-tests] 2026-07-18 13:56:26.017 UTC [212] ERROR: relation "goose_db_version" does not exist at character 36
  766. 7.30 s [niks3-go-unit-tests] 2026-07-18 13:56:26.017 UTC [212] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  767. 7.30 s [niks3-go-unit-tests] 2026-07-18 13:56:26.018 UTC [214] ERROR: relation "goose_db_version" does not exist at character 36
  768. 7.30 s [niks3-go-unit-tests] 2026-07-18 13:56:26.018 UTC [214] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  769. 7.30 s [niks3-go-unit-tests] 2026-07-18 13:56:26.019 UTC [213] ERROR: relation "goose_db_version" does not exist at character 36
  770. 7.30 s [niks3-go-unit-tests] 2026-07-18 13:56:26.019 UTC [213] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  771. 7.30 s [niks3-go-unit-tests] 2026-07-18 13:56:26.019 UTC [211] ERROR: relation "goose_db_version" does not exist at character 36
  772. 7.30 s [niks3-go-unit-tests] 2026-07-18 13:56:26.019 UTC [211] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  773. 7.31 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20241026095416_initial_model.sql (19.44ms)
  774. 7.31 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20241026095416_initial_model.sql (17.73ms)
  775. 7.32 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20241026095416_initial_model.sql (10.95ms)
  776. 7.32 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251210153512_drop_unused_gin_index.sql (11.99ms)
  777. 7.32 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20241026095416_initial_model.sql (12.21ms)
  778. 7.32 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20241026095416_initial_model.sql (14.61ms)
  779. 7.32 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251210153512_drop_unused_gin_index.sql (9.79ms)
  780. 7.33 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251218171726_add_pins.sql (9.24ms)
  781. 7.33 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20241026095416_initial_model.sql (13.42ms)
  782. 7.33 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20241026095416_initial_model.sql (12.86ms)
  783. 7.33 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251210153512_drop_unused_gin_index.sql (7.95ms)
  784. 7.33 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20241026095416_initial_model.sql (13.87ms)
  785. 7.33 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20241026095416_initial_model.sql (13.18ms)
  786. 7.33 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20241026095416_initial_model.sql (13.94ms)
  787. 7.33 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20241026095416_initial_model.sql (13.74ms)
  788. 7.33 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251210153512_drop_unused_gin_index.sql (7.24ms)
  789. 7.33 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20241026095416_initial_model.sql (13.97ms)
  790. 7.33 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251218171726_add_pins.sql (8.34ms)
  791. 7.33 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20241026095416_initial_model.sql (16.97ms)
  792. 7.33 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251210153512_drop_unused_gin_index.sql (8.54ms)
  793. 7.34 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251210153512_drop_unused_gin_index.sql (7.62ms)
  794. 7.34 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251210153512_drop_unused_gin_index.sql (7.55ms)
  795. 7.34 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251210153512_drop_unused_gin_index.sql (7.53ms)
  796. 7.34 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251218171726_add_pins.sql (7.63ms)
  797. 7.34 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20260628120000_add_object_size_and_stats.sql (8.77ms)
  798. 7.34 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251210153512_drop_unused_gin_index.sql (8.37ms)
  799. 7.34 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: successfully migrated database to version: 20260628120000
  800. 7.34 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251218171726_add_pins.sql (7.66ms)
  801. 7.34 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251210153512_drop_unused_gin_index.sql (7.66ms)
  802. 7.34 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251210153512_drop_unused_gin_index.sql (7.97ms)
  803. 7.34 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251210153512_drop_unused_gin_index.sql (8.49ms)
  804. 7.35 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251218171726_add_pins.sql (21.02ms)
  805. 7.35 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20260628120000_add_object_size_and_stats.sql (21.23ms)
  806. 7.35 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: successfully migrated database to version: 20260628120000
  807. 7.35 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251210153512_drop_unused_gin_index.sql (21.25ms)
  808. 7.36 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 1_commit_pending_closure.sql (20.36ms)
  809. 7.36 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251218171726_add_pins.sql (20.43ms)
  810. 7.36 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251218171726_add_pins.sql (20.35ms)
  811. 7.36 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251218171726_add_pins.sql (20.34ms)
  812. 7.36 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251218171726_add_pins.sql (20.45ms)
  813. 7.36 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251218171726_add_pins.sql (20.43ms)
  814. 7.36 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20260628120000_add_object_size_and_stats.sql (20.45ms)
  815. 7.36 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: successfully migrated database to version: 20260628120000
  816. 7.36 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251218171726_add_pins.sql (20.47ms)
  817. 7.36 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251218171726_add_pins.sql (20.36ms)
  818. 7.36 s [niks3-go-unit-tests] 2026-07-18 13:56:26.077 UTC [215] ERROR: relation "goose_db_version" does not exist at character 36
  819. 7.36 s [niks3-go-unit-tests] 2026-07-18 13:56:26.077 UTC [215] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  820. 7.36 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20260628120000_add_object_size_and_stats.sql (8.14ms)
  821. 7.36 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: successfully migrated database to version: 20260628120000
  822. 7.36 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 1_commit_pending_closure.sql (8.12ms)
  823. 7.36 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20260628120000_add_object_size_and_stats.sql (24.54ms)
  824. 7.36 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: successfully migrated database to version: 20260628120000
  825. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20260628120000_add_object_size_and_stats.sql (8.67ms)
  826. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: successfully migrated database to version: 20260628120000
  827. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 2_object_stats_trigger.sql (8.95ms)
  828. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: up to current file version: 2
  829. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20260628120000_add_object_size_and_stats.sql (8.73ms)
  830. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20260628120000_add_object_size_and_stats.sql (8.76ms)
  831. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: successfully migrated database to version: 20260628120000
  832. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20260628120000_add_object_size_and_stats.sql (8.91ms)
  833. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: successfully migrated database to version: 20260628120000
  834. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20260628120000_add_object_size_and_stats.sql (8.8ms)
  835. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: successfully migrated database to version: 20260628120000
  836. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 1_commit_pending_closure.sql (8.68ms)
  837. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20260628120000_add_object_size_and_stats.sql (8.88ms)
  838. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: successfully migrated database to version: 20260628120000
  839. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20260628120000_add_object_size_and_stats.sql (8.86ms)
  840. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: successfully migrated database to version: 20260628120000
  841. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251218171726_add_pins.sql (12.93ms)
  842. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: successfully migrated database to version: 20260628120000
  843. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Received uploads request method=POST path=/api/pending_closures
  844. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 1_commit_pending_closure.sql (8.97ms)
  845. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 1_commit_pending_closure.sql (9.03ms)
  846. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 2_object_stats_trigger.sql (9.01ms)
  847. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: up to current file version: 2
  848. 7.37 s [niks3-go-unit-tests] --- PASS: TestService_healthCheckHandler (0.81s)
  849. 7.37 s [niks3-go-unit-tests] === CONT TestReadProxyConditionalGet
  850. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 1_commit_pending_closure.sql (8.57ms)
  851. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 1_commit_pending_closure.sql (8.72ms)
  852. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 2_object_stats_trigger.sql (8.75ms)
  853. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: up to current file version: 2
  854. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 1_commit_pending_closure.sql (9ms)
  855. 7.38 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 1_commit_pending_closure.sql (9.09ms)
  856. 7.38 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 1_commit_pending_closure.sql (9.03ms)
  857. 7.38 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 1_commit_pending_closure.sql (9.11ms)
  858. 7.38 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 1_commit_pending_closure.sql (9.17ms)
  859. 7.38 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20260628120000_add_object_size_and_stats.sql (8.99ms)
  860. 7.38 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: successfully migrated database to version: 20260628120000
  861. 7.38 s [niks3-go-unit-tests] --- PASS: TestReadProxyInvalidPath (0.82s)
  862. 7.38 s [niks3-go-unit-tests] === CONT TestService_createPendingClosureHandler
  863. 7.38 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 2_object_stats_trigger.sql (8.92ms)
  864. 7.38 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 2_object_stats_trigger.sql (8.91ms)
  865. 7.38 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: up to current file version: 2
  866. 7.38 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: up to current file version: 2
  867. 7.38 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20241026095416_initial_model.sql (12.7ms)
  868. 7.38 s [niks3-go-unit-tests] 2026/07/18 13:56:26 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"
  869. 7.38 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware (0.83s)
  870. 7.38 s [niks3-go-unit-tests] === CONT TestCreatePendingClosure_SmallNARUsesSimplePUT
  871. 7.38 s [niks3-go-unit-tests] 2026/07/18 13:56:26 WARN mTLS auth: subject not in bound subjects subject="CN=reader"
  872. 7.38 s [niks3-go-unit-tests] 2026/07/18 13:56:26 WARN mTLS auth: subject not in bound subjects subject="CN=writer"
  873. 7.38 s [niks3-go-unit-tests] --- PASS: TestService_NativeMTLS (0.82s)
  874. 7.38 s [niks3-go-unit-tests] === CONT TestCompleteMultipartUnregistered
  875. 7.39 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 2_object_stats_trigger.sql (13.23ms)
  876. 7.39 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 2_object_stats_trigger.sql (13.59ms)
  877. 7.39 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: up to current file version: 2
  878. 7.39 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: up to current file version: 2
  879. 7.39 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 2_object_stats_trigger.sql (13.26ms)
  880. 7.39 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: up to current file version: 2
  881. 7.39 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 2_object_stats_trigger.sql (13.22ms)
  882. 7.39 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 1_commit_pending_closure.sql (13.22ms)
  883. 7.39 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: up to current file version: 2
  884. 7.39 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 2_object_stats_trigger.sql (13.7ms)
  885. 7.39 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: up to current file version: 2
  886. 7.39 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 2_object_stats_trigger.sql (13.23ms)
  887. 7.39 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: up to current file version: 2
  888. 7.39 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 2_object_stats_trigger.sql (13.28ms)
  889. 7.39 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: up to current file version: 2
  890. 7.40 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251210153512_drop_unused_gin_index.sql (15.79ms)
  891. 7.41 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 2_object_stats_trigger.sql (17.75ms)
  892. 7.41 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: up to current file version: 2
  893. 7.41 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251218171726_add_pins.sql (17.76ms)
  894. 7.43 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20260628120000_add_object_size_and_stats.sql (17.71ms)
  895. 7.43 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: successfully migrated database to version: 20260628120000
  896. 7.44 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 1_commit_pending_closure.sql (7.38ms)
  897. 7.45 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 2_object_stats_trigger.sql (8.56ms)
  898. 7.45 s [niks3-go-unit-tests] 2026/07/18 13:56:26 goose: up to current file version: 2
  899. 7.47 s [niks3-go-unit-tests] --- PASS: TestReadProxyDisabled (0.92s)
  900. 7.47 s [niks3-go-unit-tests] === CONT TestService_verifyS3Integrity
  901. 7.47 s [niks3-go-unit-tests] --- PASS: TestReadProxy404 (0.92s)
  902. 7.47 s [niks3-go-unit-tests] === CONT TestReadProxyNarinfo
  903. 7.47 s [niks3-go-unit-tests] {"timestamp":"2026-07-18T13:56:26.194877801Z","level":"ERROR","fields":{"message":"system path read failed","path_kind":"data_usage","operation":"read_primary","reason":"config_not_found","object":"buckets/.usage.json","error":"Config not found"},"target":"rustfs_ecstore::data_usage","filename":"crates/ecstore/src/data_usage.rs","line_number":126,"threadName":"rustfs-worker","threadId":"ThreadId(27)"}
  904. 7.48 s [niks3-go-unit-tests] --- PASS: TestReadProxyRootRedirectsToIndexHTML (0.85s)
  905. 7.48 s [niks3-go-unit-tests] === CONT TestService_Rustfstest
  906. 7.48 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Created nix-cache-info in bucket bucket=bucket8
  907. 7.48 s [niks3-go-unit-tests] {"timestamp":"2026-07-18T13:56:26.196592392Z","level":"ERROR","fields":{"message":"system path read failed","path_kind":"data_usage","operation":"read_primary","reason":"config_not_found","object":"buckets/.usage.json","error":"Config not found"},"target":"rustfs_ecstore::data_usage","filename":"crates/ecstore/src/data_usage.rs","line_number":126,"threadName":"rustfs-worker","threadId":"ThreadId(27)"}
  908. 7.48 s [niks3-go-unit-tests] --- PASS: TestReadProxyHead (0.92s)
  909. 7.48 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey
  910. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/narinfo
  911. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/narinfo
  912. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/nar_zst
  913. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/nar_zst
  914. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/nar_xz
  915. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/nar_xz
  916. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/nar_plain
  917. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/nar_plain
  918. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/listing
  919. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/listing
  920. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/build_log
  921. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/build_log
  922. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/build_log_home-manager_file
  923. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/build_log_home-manager_file
  924. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/build_log_plus_in_name
  925. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/build_log_plus_in_name
  926. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/build_log_question_mark
  927. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/build_log_question_mark
  928. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/build_log_equals
  929. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/build_log_equals
  930. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/realisation
  931. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/realisation
  932. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/realisation_plus_in_output
  933. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/realisation_plus_in_output
  934. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/nix-cache-info
  935. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/nix-cache-info
  936. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/index.html
  937. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/index.html
  938. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/narinfo_key,_nar_type
  939. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/narinfo_key,_nar_type
  940. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/nar_key,_narinfo_type
  941. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/nar_key,_narinfo_type
  942. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/listing_key,_narinfo_type
  943. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/listing_key,_narinfo_type
  944. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/traversal
  945. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/traversal
  946. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/traversal_nar
  947. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/traversal_nar
  948. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/absolute
  949. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/absolute
  950. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/empty_key
  951. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/empty_key
  952. 7.48 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/unknown_type
  953. 7.48 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/unknown_type
  954. 7.48 s [niks3-go-unit-tests] === CONT TestProxyWriteTimeout
  955. 7.48 s [niks3-go-unit-tests] === RUN TestProxyWriteTimeout/narinfo
  956. 7.48 s [niks3-go-unit-tests] === PAUSE TestProxyWriteTimeout/narinfo
  957. 7.48 s [niks3-go-unit-tests] === RUN TestProxyWriteTimeout/1_GiB_nar
  958. 7.48 s [niks3-go-unit-tests] === PAUSE TestProxyWriteTimeout/1_GiB_nar
  959. 7.48 s [niks3-go-unit-tests] === RUN TestProxyWriteTimeout/10_GiB_nar
  960. 7.48 s [niks3-go-unit-tests] === PAUSE TestProxyWriteTimeout/10_GiB_nar
  961. 7.48 s [niks3-go-unit-tests] === RUN TestProxyWriteTimeout/unknown_size
  962. 7.48 s [niks3-go-unit-tests] === PAUSE TestProxyWriteTimeout/unknown_size
  963. 7.48 s [niks3-go-unit-tests] === CONT TestService_cleanupPendingClosuresHandler
  964. 7.48 s [niks3-go-unit-tests] --- PASS: TestReadProxyNarStreaming (0.92s)
  965. 7.48 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectOversizedBody
  966. 7.48 s [niks3-go-unit-tests] {"timestamp":"2026-07-18T13:56:26.199533384Z","level":"ERROR","fields":{"message":"system path read failed","path_kind":"data_usage","operation":"read_primary","reason":"config_not_found","object":"buckets/.usage.json","error":"Config not found"},"target":"rustfs_ecstore::data_usage","filename":"crates/ecstore/src/data_usage.rs","line_number":126,"threadName":"rustfs-worker","threadId":"ThreadId(23)"}
  967. 7.54 s [niks3-go-unit-tests] --- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.98s)
  968. 7.54 s [niks3-go-unit-tests] === CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle
  969. 7.57 s [niks3-go-unit-tests] --- PASS: TestMetricsInventory (1.02s)
  970. 7.57 s [niks3-go-unit-tests] === CONT TestClientErrorHandling
  971. 7.57 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Received cleanup request method=DELETE path=/api/pending_closures
  972. 7.57 s [niks3-go-unit-tests] === RUN TestClientErrorHandling/InvalidStorePath
  973. 7.57 s [niks3-go-unit-tests] === PAUSE TestClientErrorHandling/InvalidStorePath
  974. 7.57 s [niks3-go-unit-tests] === RUN TestClientErrorHandling/InvalidAuthToken
  975. 7.57 s [niks3-go-unit-tests] === PAUSE TestClientErrorHandling/InvalidAuthToken
  976. 7.57 s [niks3-go-unit-tests] === RUN TestClientErrorHandling/ServerNotAvailable
  977. 7.57 s [niks3-go-unit-tests] === PAUSE TestClientErrorHandling/ServerNotAvailable
  978. 7.57 s [niks3-go-unit-tests] === CONT TestGCMetrics
  979. 7.57 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Aborted multipart uploads count=1
  980. 7.59 s [niks3-go-unit-tests] --- PASS: TestMultipartCleanup (1.04s)
  981. 7.59 s [niks3-go-unit-tests] === CONT TestGCBugBareHashReferences
  982. 7.61 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectOversizedBody/create_pending_closure
  983. 7.61 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure
  984. 7.61 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectOversizedBody/complete_multipart
  985. 7.61 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart
  986. 7.61 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectOversizedBody/request_more_parts
  987. 7.61 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts
  988. 7.61 s [niks3-go-unit-tests] === CONT TestOrphanedObjectsGC
  989. 7.61 s [niks3-go-unit-tests] --- PASS: TestResurrectedObjectNotDeleted (1.05s)
  990. 7.61 s [niks3-go-unit-tests] === CONT TestPinProtectsFromGC
  991. 7.64 s [niks3-go-unit-tests] === NAME TestNARDeduplicationMetadataUploadBug
  992. 7.64 s [niks3-go-unit-tests] metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug1522586550/001/store/vlg8s95820243p8al9nc3r31zh40dkcc-file1.txt
  993. 7.91 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Received uploads request method=POST path=/api/pending_closures
  994. 7.92 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)
  995. 7.92 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Uploading vlg8s95820243p8al9nc3r31zh40dkcc-file1.txt (160B)
  996. 7.92 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign
  997. 7.92 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Signed narinfos id=1 count=1
  998. 7.92 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Uploading 1 narinfos
  999. 7.93 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1000. 7.93 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Completed upload id=1
  1001. 7.93 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Upload complete. (128ms)
  1002. 7.93 s [niks3-go-unit-tests] metadata_upload_test.go:54: Retrieved narinfo from S3:
  1003. 7.93 s [niks3-go-unit-tests] StorePath: /build/TestNARDeduplicationMetadataUploadBug1522586550/001/store/vlg8s95820243p8al9nc3r31zh40dkcc-file1.txt
  1004. 7.93 s [niks3-go-unit-tests] URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst
  1005. 7.93 s [niks3-go-unit-tests] Compression: zstd
  1006. 7.93 s [niks3-go-unit-tests] NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf
  1007. 7.93 s [niks3-go-unit-tests] NarSize: 160
  1008. 7.93 s [niks3-go-unit-tests] References:
  1009. 7.93 s [niks3-go-unit-tests] CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf
  1010. 7.93 s [niks3-go-unit-tests] metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)
  1011. 7.93 s [niks3-go-unit-tests] metadata_upload_test.go:55: Decompressed .ls content (64 bytes):
  1012. 7.93 s [niks3-go-unit-tests] {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}
  1013. 7.99 s [niks3-go-unit-tests] metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug1522586550/001/store/i0s064cwvyfh7q0wrdzyf9b5zpikvbik-file2.txt
  1014. 8.04 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Received uploads request method=POST path=/api/pending_closures
  1015. 8.06 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)
  1016. 8.06 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign
  1017. 8.06 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Signed narinfos id=2 count=1
  1018. 8.06 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Uploading 1 narinfos
  1019. 8.06 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete
  1020. 8.06 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Completed upload id=2
  1021. 8.06 s [niks3-go-unit-tests] 2026/07/18 13:56:26 INFO Upload complete. (56ms)
  1022. 8.07 s [niks3-go-unit-tests] metadata_upload_test.go:76: Retrieved narinfo from S3:
  1023. 8.07 s [niks3-go-unit-tests] StorePath: /build/TestNARDeduplicationMetadataUploadBug1522586550/001/store/i0s064cwvyfh7q0wrdzyf9b5zpikvbik-file2.txt
  1024. 8.07 s [niks3-go-unit-tests] URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst
  1025. 8.07 s [niks3-go-unit-tests] Compression: zstd
  1026. 8.07 s [niks3-go-unit-tests] NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf
  1027. 8.07 s [niks3-go-unit-tests] NarSize: 160
  1028. 8.07 s [niks3-go-unit-tests] References:
  1029. 8.07 s [niks3-go-unit-tests] CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf
  1030. 8.07 s [niks3-go-unit-tests] metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)
  1031. 8.07 s [niks3-go-unit-tests] metadata_upload_test.go:77: Decompressed .ls content (49 bytes):
  1032. 8.07 s [niks3-go-unit-tests] {"version":1,"root":{"type":"regular","size":44}}
  1033. 8.07 s [niks3-go-unit-tests] --- PASS: TestNARDeduplicationMetadataUploadBug (1.51s)
  1034. 8.07 s [niks3-go-unit-tests] === CONT TestOrphanedObjectsGCStressTest
  1035. 8.08 s [niks3-go-unit-tests] 2026-07-18 13:56:26.796 UTC [288] ERROR: relation "goose_db_version" does not exist at character 36
  1036. 8.08 s [niks3-go-unit-tests] 2026-07-18 13:56:26.796 UTC [288] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1037. 8.08 s [niks3-go-unit-tests] 2026-07-18 13:56:26.796 UTC [290] ERROR: relation "goose_db_version" does not exist at character 36
  1038. 8.08 s [niks3-go-unit-tests] 2026-07-18 13:56:26.796 UTC [290] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1039. 8.08 s [niks3-go-unit-tests] 2026-07-18 13:56:26.797 UTC [287] ERROR: relation "goose_db_version" does not exist at character 36
  1040. 8.08 s [niks3-go-unit-tests] 2026-07-18 13:56:26.797 UTC [287] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1041. 8.08 s [niks3-go-unit-tests] 2026-07-18 13:56:26.798 UTC [289] ERROR: relation "goose_db_version" does not exist at character 36
  1042. 8.08 s [niks3-go-unit-tests] 2026-07-18 13:56:26.798 UTC [289] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1043. 8.16 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20241026095416_initial_model.sql (19.26ms)
  1044. 8.17 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20241026095416_initial_model.sql (76.99ms)
  1045. 8.18 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20241026095416_initial_model.sql (35.15ms)
  1046. 8.18 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251210153512_drop_unused_gin_index.sql (18.31ms)
  1047. 8.19 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20241026095416_initial_model.sql (39.9ms)
  1048. 8.20 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251210153512_drop_unused_gin_index.sql (25.35ms)
  1049. 8.21 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251210153512_drop_unused_gin_index.sql (23.96ms)
  1050. 8.21 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251210153512_drop_unused_gin_index.sql (19.27ms)
  1051. 8.26 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251218171726_add_pins.sql (81.33ms)
  1052. 8.28 s [niks3-go-unit-tests] 2026/07/18 13:56:26 OK 20251218171726_add_pins.sql (81.15ms)
  1053. 8.28 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251218171726_add_pins.sql (77.25ms)
  1054. 8.29 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20260628120000_add_object_size_and_stats.sql (12.86ms)
  1055. 8.29 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: successfully migrated database to version: 20260628120000
  1056. 8.29 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20260628120000_add_object_size_and_stats.sql (27.38ms)
  1057. 8.29 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: successfully migrated database to version: 20260628120000
  1058. 8.29 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251218171726_add_pins.sql (84.81ms)
  1059. 8.30 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 1_commit_pending_closure.sql (6.14ms)
  1060. 8.30 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20260628120000_add_object_size_and_stats.sql (12.06ms)
  1061. 8.30 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: successfully migrated database to version: 20260628120000
  1062. 8.30 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20260628120000_add_object_size_and_stats.sql (19.81ms)
  1063. 8.30 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: successfully migrated database to version: 20260628120000
  1064. 8.30 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 1_commit_pending_closure.sql (12.1ms)
  1065. 8.31 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 1_commit_pending_closure.sql (5.67ms)
  1066. 8.36 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 2_object_stats_trigger.sql (56ms)
  1067. 8.36 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: up to current file version: 2
  1068. 8.36 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 1_commit_pending_closure.sql (56.12ms)
  1069. 8.36 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 2_object_stats_trigger.sql (62.24ms)
  1070. 8.36 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: up to current file version: 2
  1071. 8.36 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received uploads request method=POST path=/api/pending_closures
  1072. 8.37 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 2_object_stats_trigger.sql (54.99ms)
  1073. 8.37 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: up to current file version: 2
  1074. 8.37 s [niks3-go-unit-tests] 2026-07-18 13:56:27.085 UTC [389] ERROR: relation "goose_db_version" does not exist at character 36
  1075. 8.37 s [niks3-go-unit-tests] 2026-07-18 13:56:27.085 UTC [389] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1076. 8.37 s [niks3-go-unit-tests] 2026-07-18 13:56:27.085 UTC [390] ERROR: relation "goose_db_version" does not exist at character 36
  1077. 8.37 s [niks3-go-unit-tests] 2026-07-18 13:56:27.085 UTC [390] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1078. 8.37 s [niks3-go-unit-tests] 2026-07-18 13:56:27.085 UTC [388] ERROR: relation "goose_db_version" does not exist at character 36
  1079. 8.37 s [niks3-go-unit-tests] 2026-07-18 13:56:27.085 UTC [388] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1080. 8.37 s [niks3-go-unit-tests] 2026-07-18 13:56:27.088 UTC [391] ERROR: relation "goose_db_version" does not exist at character 36
  1081. 8.37 s [niks3-go-unit-tests] 2026-07-18 13:56:27.088 UTC [391] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1082. 8.37 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete
  1083. 8.37 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 2_object_stats_trigger.sql (11.09ms)
  1084. 8.37 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: up to current file version: 2
  1085. 8.37 s [niks3-go-unit-tests] 2026/07/18 13:56:27 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst
  1086. 8.37 s [niks3-go-unit-tests] --- PASS: TestCompleteMultipartUnregistered (0.99s)
  1087. 8.37 s [niks3-go-unit-tests] === CONT TestClientWithDependencies
  1088. 8.37 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received uploads request method=POST path=/api/pending_closures
  1089. 8.37 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received uploads request method=POST path=/api/pending_closures
  1090. 8.37 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received uploads request method=POST path=/api/pending_closures
  1091. 8.37 s [niks3-go-unit-tests] --- PASS: TestReadProxyConditionalGet (1.00s)
  1092. 8.37 s [niks3-go-unit-tests] === CONT TestObjectStatsTrigger
  1093. 8.37 s [niks3-go-unit-tests] 2026-07-18 13:56:27.093 UTC [392] ERROR: relation "goose_db_version" does not exist at character 36
  1094. 8.37 s [niks3-go-unit-tests] 2026-07-18 13:56:27.093 UTC [392] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1095. 8.37 s [niks3-go-unit-tests] 2026-07-18 13:56:27.094 UTC [393] ERROR: relation "goose_db_version" does not exist at character 36
  1096. 8.37 s [niks3-go-unit-tests] 2026-07-18 13:56:27.094 UTC [393] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1097. 8.37 s [niks3-go-unit-tests] 2026-07-18 13:56:27.094 UTC [397] ERROR: relation "goose_db_version" does not exist at character 36
  1098. 8.37 s [niks3-go-unit-tests] 2026-07-18 13:56:27.094 UTC [397] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1099. 8.37 s [niks3-go-unit-tests] 2026-07-18 13:56:27.094 UTC [396] ERROR: relation "goose_db_version" does not exist at character 36
  1100. 8.37 s [niks3-go-unit-tests] 2026-07-18 13:56:27.094 UTC [396] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1101. 8.38 s [niks3-go-unit-tests] 2026-07-18 13:56:27.096 UTC [395] ERROR: relation "goose_db_version" does not exist at character 36
  1102. 8.38 s [niks3-go-unit-tests] 2026-07-18 13:56:27.096 UTC [395] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1103. 8.39 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20241026095416_initial_model.sql (16.33ms)
  1104. 8.39 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20241026095416_initial_model.sql (16.3ms)
  1105. 8.39 s [niks3-go-unit-tests] === CONT TestClientMultipleUploads
  1106. 8.39 s [niks3-go-unit-tests] --- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.01s)
  1107. 8.40 s [niks3-go-unit-tests] 2026-07-18 13:56:27.117 UTC [402] ERROR: relation "goose_db_version" does not exist at character 36
  1108. 8.40 s [niks3-go-unit-tests] 2026-07-18 13:56:27.117 UTC [402] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1109. 8.40 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20241026095416_initial_model.sql (14.77ms)
  1110. 8.40 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20241026095416_initial_model.sql (14.75ms)
  1111. 8.41 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20241026095416_initial_model.sql (14.99ms)
  1112. 8.41 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20241026095416_initial_model.sql (14.69ms)
  1113. 8.41 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20241026095416_initial_model.sql (14.69ms)
  1114. 8.41 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251210153512_drop_unused_gin_index.sql (15.35ms)
  1115. 8.41 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251210153512_drop_unused_gin_index.sql (15.43ms)
  1116. 8.41 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20241026095416_initial_model.sql (20.78ms)
  1117. 8.41 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20241026095416_initial_model.sql (22.14ms)
  1118. 8.41 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251210153512_drop_unused_gin_index.sql (15.23ms)
  1119. 8.42 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251210153512_drop_unused_gin_index.sql (14.83ms)
  1120. 8.43 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251218171726_add_pins.sql (20.13ms)
  1121. 8.43 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251218171726_add_pins.sql (22.42ms)
  1122. 8.43 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251210153512_drop_unused_gin_index.sql (22.23ms)
  1123. 8.43 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251210153512_drop_unused_gin_index.sql (22.75ms)
  1124. 8.43 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251210153512_drop_unused_gin_index.sql (19.7ms)
  1125. 8.44 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251218171726_add_pins.sql (22.92ms)
  1126. 8.44 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20241026095416_initial_model.sql (22.63ms)
  1127. 8.44 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251218171726_add_pins.sql (23.02ms)
  1128. 8.44 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251210153512_drop_unused_gin_index.sql (21.34ms)
  1129. 8.44 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251210153512_drop_unused_gin_index.sql (23.2ms)
  1130. 8.45 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251218171726_add_pins.sql (15.27ms)
  1131. 8.45 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251218171726_add_pins.sql (15.26ms)
  1132. 8.45 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20260628120000_add_object_size_and_stats.sql (15.43ms)
  1133. 8.45 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: successfully migrated database to version: 20260628120000
  1134. 8.45 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251218171726_add_pins.sql (15.23ms)
  1135. 8.45 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20260628120000_add_object_size_and_stats.sql (15.34ms)
  1136. 8.45 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: successfully migrated database to version: 20260628120000
  1137. 8.45 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20260628120000_add_object_size_and_stats.sql (16.47ms)
  1138. 8.45 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20260628120000_add_object_size_and_stats.sql (16.37ms)
  1139. 8.45 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: successfully migrated database to version: 20260628120000
  1140. 8.45 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251218171726_add_pins.sql (16.37ms)
  1141. 8.45 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251218171726_add_pins.sql (16.35ms)
  1142. 8.45 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: successfully migrated database to version: 20260628120000
  1143. 8.45 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251210153512_drop_unused_gin_index.sql (16.53ms)
  1144. 8.46 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 1_commit_pending_closure.sql (17.47ms)
  1145. 8.46 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20260628120000_add_object_size_and_stats.sql (17.57ms)
  1146. 8.46 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20260628120000_add_object_size_and_stats.sql (17.58ms)
  1147. 8.46 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20260628120000_add_object_size_and_stats.sql (17.5ms)
  1148. 8.46 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 1_commit_pending_closure.sql (17.48ms)
  1149. 8.46 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: successfully migrated database to version: 20260628120000
  1150. 8.46 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: successfully migrated database to version: 20260628120000
  1151. 8.46 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: successfully migrated database to version: 20260628120000
  1152. 8.47 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 1_commit_pending_closure.sql (17.21ms)
  1153. 8.47 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251218171726_add_pins.sql (17.16ms)
  1154. 8.47 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20260628120000_add_object_size_and_stats.sql (17.27ms)
  1155. 8.47 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 1_commit_pending_closure.sql (17.21ms)
  1156. 8.47 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20260628120000_add_object_size_and_stats.sql (17.26ms)
  1157. 8.47 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: successfully migrated database to version: 20260628120000
  1158. 8.47 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: successfully migrated database to version: 20260628120000
  1159. 8.48 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 1_commit_pending_closure.sql (15.74ms)
  1160. 8.48 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 2_object_stats_trigger.sql (15.99ms)
  1161. 8.48 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: up to current file version: 2
  1162. 8.48 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 1_commit_pending_closure.sql (15.81ms)
  1163. 8.48 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 2_object_stats_trigger.sql (15.96ms)
  1164. 8.48 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: up to current file version: 2
  1165. 8.48 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 1_commit_pending_closure.sql (15.84ms)
  1166. 8.48 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received uploads request method=POST path=/api/pending_closures
  1167. 8.49 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 1_commit_pending_closure.sql (16.27ms)
  1168. 8.49 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 1_commit_pending_closure.sql (16.32ms)
  1169. 8.49 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 2_object_stats_trigger.sql (16.42ms)
  1170. 8.49 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: up to current file version: 2
  1171. 8.49 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20260628120000_add_object_size_and_stats.sql (16.39ms)
  1172. 8.49 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: successfully migrated database to version: 20260628120000
  1173. 8.49 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 2_object_stats_trigger.sql (16.37ms)
  1174. 8.49 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: up to current file version: 2
  1175. 8.49 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received cleanup request method=DELETE path=/api/pending_closures
  1176. 8.49 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Aborted multipart uploads count=0
  1177. 8.49 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received uploads request method=POST path=/api/pending_closures
  1178. 8.50 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 2_object_stats_trigger.sql (17.65ms)
  1179. 8.50 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: up to current file version: 2
  1180. 8.50 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 2_object_stats_trigger.sql (17.65ms)
  1181. 8.50 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: up to current file version: 2
  1182. 8.50 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 2_object_stats_trigger.sql (17.63ms)
  1183. 8.50 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: up to current file version: 2
  1184. 8.50 s [niks3-go-unit-tests] --- PASS: TestReadProxyNarinfo (1.02s)
  1185. 8.50 s [niks3-go-unit-tests] === CONT TestRedundantMultipartUpload
  1186. 8.50 s [niks3-go-unit-tests] --- PASS: TestService_Rustfstest (1.02s)
  1187. 8.50 s [niks3-go-unit-tests] === CONT TestClientIntegration
  1188. 8.50 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Created nix-cache-info in bucket bucket=bucket26
  1189. 8.50 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 1_commit_pending_closure.sql (13.1ms)
  1190. 8.50 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 2_object_stats_trigger.sql (13.27ms)
  1191. 8.50 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: up to current file version: 2
  1192. 8.50 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 2_object_stats_trigger.sql (13.27ms)
  1193. 8.50 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: up to current file version: 2
  1194. 8.50 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received uploads request method=POST path=/api/pending_closures
  1195. 8.51 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 2_object_stats_trigger.sql (13.23ms)
  1196. 8.51 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: up to current file version: 2
  1197. 8.52 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received cleanup request method=DELETE path=/api/pending_closures
  1198. 8.52 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Aborted multipart uploads count=1
  1199. 8.53 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete
  1200. 8.53 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1201. 8.53 s [niks3-go-unit-tests] 2026-07-18 13:56:27.251 UTC [391] ERROR: Closure does not exist: id=1
  1202. 8.53 s [niks3-go-unit-tests] 2026-07-18 13:56:27.251 UTC [391] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE
  1203. 8.53 s [niks3-go-unit-tests] 2026-07-18 13:56:27.251 UTC [391] STATEMENT: -- name: CommitPendingClosure :exec
  1204. 8.53 s [niks3-go-unit-tests] SELECT commit_pending_closure($1::bigint)
  1205. 8.53 s [niks3-go-unit-tests]
  1206. 8.53 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete
  1207. 8.53 s [niks3-go-unit-tests] --- PASS: TestService_cleanupPendingClosuresHandler (1.05s)
  1208. 8.53 s [niks3-go-unit-tests] === CONT TestCompleteMultipartUpload_ErrorButObjectExists
  1209. 8.54 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YTNlYzZhMzMtZmM3OC00ZmFiLTllMTQtYTBiZmQ5MTAxZGJkLmZiZTc0NzFlLWQyMjMtNDc0My1iMmFiLTIyMTQxNTFlNDJhMngxNzg0MzgyOTg3MTA0ODM1MDg2 parts=10
  1210. 8.54 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1211. 8.56 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Completed upload id=1
  1212. 8.56 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000
  1213. 8.56 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received uploads request method=POST path=/api/pending_closures
  1214. 8.57 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Starting cleanup of old closures method=DELETE path=/api/closures
  1215. 8.63 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Aborted multipart uploads count=0
  1216. 8.63 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Aborted multipart uploads count=0
  1217. 8.63 s [niks3-go-unit-tests] 2026/07/18 13:56:27 WARN Force mode enabled - objects will be deleted immediately without grace period
  1218. 8.63 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=0
  1219. 8.63 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Vacuumed table table=pending_closures
  1220. 8.64 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Vacuumed table table=pending_objects
  1221. 8.64 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Vacuumed table table=multipart_uploads
  1222. 8.64 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Vacuumed table table=closures
  1223. 8.64 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Vacuumed table table=objects
  1224. 8.64 s [niks3-go-unit-tests] --- PASS: TestGCMetrics (1.06s)
  1225. 8.64 s [niks3-go-unit-tests] === CONT TestReadProxyRangeRequest
  1226. 8.65 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete
  1227. 8.67 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YTNlYzZhMzMtZmM3OC00ZmFiLTllMTQtYTBiZmQ5MTAxZGJkLmUxY2UxOTJhLTI5MmUtNDI5Yy05NTg5LTk0NGU1NjAxYTgwMHgxNzg0MzgyOTg3MjM1MzIyMzkz parts=10
  1228. 8.67 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1229. 8.67 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=2 objects-deleted-after-grace-period=0 objects-failed-to-delete=0
  1230. 8.74 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Completed upload id=1
  1231. 8.74 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Vacuumed table table=pending_closures
  1232. 8.74 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received uploads request method=POST path=/api/pending_closures
  1233. 8.75 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Vacuumed table table=pending_objects
  1234. 8.75 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received uploads request method=POST path=/api/pending_closures
  1235. 8.75 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo
  1236. 8.75 s [niks3-go-unit-tests] 2026/07/18 13:56:27 WARN Found objects in DB but missing from S3, will re-upload count=1
  1237. 8.77 s [niks3-go-unit-tests] --- PASS: TestService_verifyS3Integrity (1.29s)
  1238. 8.77 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_OIDC
  1239. 8.77 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO OIDC provider initialized name=test
  1240. 8.78 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Vacuumed table table=multipart_uploads
  1241. 8.82 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Vacuumed table table=closures
  1242. 8.84 s [niks3-go-unit-tests] === NAME TestPinProtectsFromGC
  1243. 8.84 s [niks3-go-unit-tests] client_integration_test.go:646: Pinned store path: /build/TestPinProtectsFromGC1671256906/001/store/x3s432kl8hk7y8igx2dqfdfwavp1y6z3-pinned-file.txt
  1244. 8.84 s [niks3-go-unit-tests] client_integration_test.go:647: Unpinned store path: /build/TestPinProtectsFromGC1671256906/001/store/c3zn189nj5c95y46l3dk6g1g2xkhks2j-unpinned-file.txt
  1245. 8.84 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Vacuumed table table=objects
  1246. 8.88 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000
  1247. 8.88 s [niks3-go-unit-tests] --- PASS: TestGCBugBareHashReferences (1.28s)
  1248. 8.88 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_MTLSBoundSubjects
  1249. 8.88 s [niks3-go-unit-tests] --- PASS: TestService_createPendingClosureHandler (1.50s)
  1250. 8.88 s [niks3-go-unit-tests] === CONT TestClientCADerivations
  1251. 8.88 s [niks3-go-unit-tests] 2026-07-18 13:56:27.599 UTC [432] ERROR: relation "goose_db_version" does not exist at character 36
  1252. 8.88 s [niks3-go-unit-tests] 2026-07-18 13:56:27.599 UTC [432] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1253. 8.88 s [niks3-go-unit-tests] 2026-07-18 13:56:27.600 UTC [447] ERROR: relation "goose_db_version" does not exist at character 36
  1254. 8.88 s [niks3-go-unit-tests] 2026-07-18 13:56:27.600 UTC [447] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1255. 8.88 s [niks3-go-unit-tests] 2026-07-18 13:56:27.601 UTC [433] ERROR: relation "goose_db_version" does not exist at character 36
  1256. 8.88 s [niks3-go-unit-tests] 2026-07-18 13:56:27.601 UTC [433] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1257. 8.93 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20241026095416_initial_model.sql (27.3ms)
  1258. 8.94 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20241026095416_initial_model.sql (34.38ms)
  1259. 8.94 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20241026095416_initial_model.sql (34.39ms)
  1260. 8.94 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251210153512_drop_unused_gin_index.sql (14.63ms)
  1261. 8.95 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251210153512_drop_unused_gin_index.sql (16.66ms)
  1262. 8.95 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251210153512_drop_unused_gin_index.sql (16.7ms)
  1263. 8.95 s [niks3-go-unit-tests] === NAME TestOrphanedObjectsGC
  1264. 8.95 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:290: GC Test Summary:
  1265. 8.95 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A
  1266. 8.95 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B
  1267. 8.95 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)
  1268. 8.95 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)
  1269. 8.95 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:295: - Total deleted: 10 objects
  1270. 8.95 s [niks3-go-unit-tests] --- PASS: TestOrphanedObjectsGC (1.35s)
  1271. 8.95 s [niks3-go-unit-tests] === CONT TestService_ReadAuthMiddleware
  1272. 8.96 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251218171726_add_pins.sql (17.51ms)
  1273. 8.97 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251218171726_add_pins.sql (16.28ms)
  1274. 8.97 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20251218171726_add_pins.sql (16.38ms)
  1275. 8.98 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20260628120000_add_object_size_and_stats.sql (17.45ms)
  1276. 8.98 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: successfully migrated database to version: 20260628120000
  1277. 8.99 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20260628120000_add_object_size_and_stats.sql (24.55ms)
  1278. 8.99 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: successfully migrated database to version: 20260628120000
  1279. 8.99 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 20260628120000_add_object_size_and_stats.sql (24.54ms)
  1280. 8.99 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: successfully migrated database to version: 20260628120000
  1281. 9.00 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 1_commit_pending_closure.sql (22.32ms)
  1282. 9.01 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 1_commit_pending_closure.sql (14.79ms)
  1283. 9.01 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 1_commit_pending_closure.sql (14.97ms)
  1284. 9.02 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 2_object_stats_trigger.sql (16.88ms)
  1285. 9.02 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: up to current file version: 2
  1286. 9.02 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received uploads request method=POST path=/api/pending_closures
  1287. 9.03 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 2_object_stats_trigger.sql (18.17ms)
  1288. 9.03 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: up to current file version: 2
  1289. 9.03 s [niks3-go-unit-tests] 2026/07/18 13:56:27 OK 2_object_stats_trigger.sql (18.3ms)
  1290. 9.03 s [niks3-go-unit-tests] 2026/07/18 13:56:27 goose: up to current file version: 2
  1291. 9.03 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Created nix-cache-info in bucket bucket=bucket31
  1292. 9.03 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Created nix-cache-info in bucket bucket=bucket32
  1293. 9.04 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)
  1294. 9.04 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Uploading x3s432kl8hk7y8igx2dqfdfwavp1y6z3-pinned-file.txt (128B)
  1295. 9.04 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign
  1296. 9.04 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Signed narinfos id=1 count=1
  1297. 9.04 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Uploading 1 narinfos
  1298. 9.04 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1299. 9.17 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Completed upload id=1
  1300. 9.17 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Upload complete. (303ms)
  1301. 9.24 s [niks3-go-unit-tests] 2026/07/18 13:56:27 INFO Received uploads request method=POST path=/api/pending_closures
  1302. 9.31 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)
  1303. 9.31 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Uploading c3zn189nj5c95y46l3dk6g1g2xkhks2j-unpinned-file.txt (128B)
  1304. 9.43 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign
  1305. 9.43 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Signed narinfos id=2 count=1
  1306. 9.43 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Uploading 1 narinfos
  1307. 9.43 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete
  1308. 9.47 s [niks3-go-unit-tests] --- PASS: TestObjectStatsTrigger (1.09s)
  1309. 9.47 s [niks3-go-unit-tests] === CONT TestCacheStatsHandler
  1310. 9.47 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Completed upload id=2
  1311. 9.47 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Upload complete. (283ms)
  1312. 9.50 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received create pin request method=POST path=/api/pins/myapp
  1313. 9.51 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC1671256906/001/store/x3s432kl8hk7y8igx2dqfdfwavp1y6z3-pinned-file.txt narinfo_key=x3s432kl8hk7y8igx2dqfdfwavp1y6z3.narinfo
  1314. 9.51 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Starting cleanup of old closures method=DELETE path=/api/closures
  1315. 9.51 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Garbage collection started
  1316. 9.57 s [niks3-go-unit-tests] 2026-07-18 13:56:28.285 UTC [503] ERROR: relation "goose_db_version" does not exist at character 36
  1317. 9.57 s [niks3-go-unit-tests] 2026-07-18 13:56:28.285 UTC [503] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1318. 9.57 s [niks3-go-unit-tests] 2026-07-18 13:56:28.285 UTC [502] ERROR: relation "goose_db_version" does not exist at character 36
  1319. 9.57 s [niks3-go-unit-tests] 2026-07-18 13:56:28.285 UTC [502] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1320. 9.61 s [niks3-go-unit-tests] === NAME TestClientMultipleUploads
  1321. 9.61 s [niks3-go-unit-tests] client_integration_test.go:338: Created store path 0: /build/TestClientMultipleUploads193067892/001/store/564m4bzhdm95mwxi5s5a6mby8x2sm29l-test-file-0.txt
  1322. 9.64 s [niks3-go-unit-tests] === NAME TestClientWithDependencies
  1323. 9.64 s [niks3-go-unit-tests] client_integration_test.go:593: Built derivation: /build/TestClientWithDependencies600145612/001/store/cvily1kjgarp703f05gk8z8i50vi8jcq-test-script
  1324. 9.65 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Aborted multipart uploads count=0
  1325. 9.66 s [niks3-go-unit-tests] client_integration_test.go:595: Found 1 dependencies (including self)
  1326. 9.68 s [niks3-go-unit-tests] 2026/07/18 13:56:28 WARN Force mode enabled - objects will be deleted immediately without grace period
  1327. 9.70 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received uploads request method=POST path=/api/pending_closures
  1328. 9.72 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20241026095416_initial_model.sql (45.69ms)
  1329. 9.72 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20241026095416_initial_model.sql (45.59ms)
  1330. 9.72 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)
  1331. 9.72 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Uploading cvily1kjgarp703f05gk8z8i50vi8jcq-test-script (136B)
  1332. 9.72 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign
  1333. 9.72 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Signed narinfos id=1 count=1
  1334. 9.72 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Uploading 1 narinfos
  1335. 9.72 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1336. 9.74 s [niks3-go-unit-tests] === NAME TestClientMultipleUploads
  1337. 9.74 s [niks3-go-unit-tests] client_integration_test.go:338: Created store path 1: /build/TestClientMultipleUploads193067892/001/store/3m1l5k0v2xj36l05wpcar57pi6mcj7rh-test-file-1.txt
  1338. 9.74 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20251210153512_drop_unused_gin_index.sql (20.75ms)
  1339. 9.74 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20251210153512_drop_unused_gin_index.sql (20.75ms)
  1340. 9.75 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20251218171726_add_pins.sql (10.68ms)
  1341. 9.75 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Completed upload id=1
  1342. 9.75 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20251218171726_add_pins.sql (10.67ms)
  1343. 9.75 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Upload complete. (66ms)
  1344. 9.75 s [niks3-go-unit-tests] === NAME TestClientWithDependencies
  1345. 9.75 s [niks3-go-unit-tests] client_integration_test.go:597: Skipping nix copy test - isolated store (/build/TestClientWithDependencies600145612/001/store) requires matching store prefix
  1346. 9.75 s [niks3-go-unit-tests] --- PASS: TestClientWithDependencies (1.38s)
  1347. 9.75 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_MTLSProxyHeader
  1348. 9.85 s [niks3-go-unit-tests] === NAME TestClientMultipleUploads
  1349. 9.85 s [niks3-go-unit-tests] client_integration_test.go:338: Created store path 2: /build/TestClientMultipleUploads193067892/001/store/xkdh2c6fwh7y7wi9fr26qlhd7980a10z-test-file-2.txt
  1350. 9.86 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20260628120000_add_object_size_and_stats.sql (106.26ms)
  1351. 9.86 s [niks3-go-unit-tests] 2026/07/18 13:56:28 goose: successfully migrated database to version: 20260628120000
  1352. 9.86 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20260628120000_add_object_size_and_stats.sql (106.22ms)
  1353. 9.86 s [niks3-go-unit-tests] 2026/07/18 13:56:28 goose: successfully migrated database to version: 20260628120000
  1354. 9.87 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 1_commit_pending_closure.sql (17.36ms)
  1355. 9.87 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 1_commit_pending_closure.sql (17.45ms)
  1356. 9.89 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 2_object_stats_trigger.sql (14.63ms)
  1357. 9.89 s [niks3-go-unit-tests] 2026/07/18 13:56:28 goose: up to current file version: 2
  1358. 9.89 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 2_object_stats_trigger.sql (14.58ms)
  1359. 9.89 s [niks3-go-unit-tests] 2026/07/18 13:56:28 goose: up to current file version: 2
  1360. 9.89 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received uploads request method=POST path=/api/pending_closures
  1361. 9.89 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Created nix-cache-info in bucket bucket=bucket33
  1362. 9.92 s [niks3-go-unit-tests] 2026-07-18 13:56:28.635 UTC [701] ERROR: relation "goose_db_version" does not exist at character 36
  1363. 9.92 s [niks3-go-unit-tests] 2026-07-18 13:56:28.635 UTC [701] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1364. 9.92 s [niks3-go-unit-tests] 2026-07-18 13:56:28.638 UTC [719] ERROR: relation "goose_db_version" does not exist at character 36
  1365. 9.92 s [niks3-go-unit-tests] 2026-07-18 13:56:28.638 UTC [719] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1366. 9.92 s [niks3-go-unit-tests] 2026-07-18 13:56:28.638 UTC [702] ERROR: relation "goose_db_version" does not exist at character 36
  1367. 9.92 s [niks3-go-unit-tests] 2026-07-18 13:56:28.638 UTC [702] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1368. 9.92 s [niks3-go-unit-tests] 2026-07-18 13:56:28.638 UTC [700] ERROR: relation "goose_db_version" does not exist at character 36
  1369. 9.92 s [niks3-go-unit-tests] 2026-07-18 13:56:28.638 UTC [700] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1370. 9.92 s [niks3-go-unit-tests] 2026-07-18 13:56:28.638 UTC [683] ERROR: relation "goose_db_version" does not exist at character 36
  1371. 9.92 s [niks3-go-unit-tests] 2026-07-18 13:56:28.638 UTC [683] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1372. 9.94 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received complete multipart upload request method=POST path=/api/multipart/complete
  1373. 9.94 s [niks3-go-unit-tests] {"timestamp":"2026-07-18T13:56:28.661522321Z","level":"ERROR","fields":{"message":"complete_multipart_upload part error: \"part.1 not found\""},"target":"rustfs_ecstore::set_disk","filename":"crates/ecstore/src/set_disk.rs","line_number":3463,"threadName":"rustfs-worker","threadId":"ThreadId(27)"}
  1374. 9.94 s [niks3-go-unit-tests] {"timestamp":"2026-07-18T13:56:28.661544951Z","level":"ERROR","fields":{"message":"complete_multipart_upload etag err client=Some(\"deadbeef\"), stored=\"\", part_id=1, bucket=bucket34, object=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst"},"target":"rustfs_ecstore::set_disk","filename":"crates/ecstore/src/set_disk.rs","line_number":3534,"threadName":"rustfs-worker","threadId":"ThreadId(27)"}
  1375. 9.94 s [niks3-go-unit-tests] 2026/07/18 13:56:28 WARN CompleteMultipartUpload errored but object exists; treating as success error="One or more of the specified parts could not be found. The part may not have been uploaded, or the specified entity tag may not match the part's entity tag." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YTNlYzZhMzMtZmM3OC00ZmFiLTllMTQtYTBiZmQ5MTAxZGJkLjJkMmIzY2RlLWVkZjgtNDQ0My05MTQ3LTVmMWY0NzA4OTM2MngxNzg0MzgyOTg4NjI4MDg2MjEy
  1376. 9.96 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YTNlYzZhMzMtZmM3OC00ZmFiLTllMTQtYTBiZmQ5MTAxZGJkLjJkMmIzY2RlLWVkZjgtNDQ0My05MTQ3LTVmMWY0NzA4OTM2MngxNzg0MzgyOTg4NjI4MDg2MjEy parts=1
  1377. 9.96 s [niks3-go-unit-tests] --- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.43s)
  1378. 9.96 s [niks3-go-unit-tests] === CONT TestCacheConfigHandler
  1379. 9.96 s [niks3-go-unit-tests] === RUN TestCacheConfigHandler/full_config,_no_issuer
  1380. 9.96 s [niks3-go-unit-tests] === PAUSE TestCacheConfigHandler/full_config,_no_issuer
  1381. 9.96 s [niks3-go-unit-tests] === RUN TestCacheConfigHandler/no_cache_url_configured
  1382. 9.96 s [niks3-go-unit-tests] === PAUSE TestCacheConfigHandler/no_cache_url_configured
  1383. 9.96 s [niks3-go-unit-tests] === RUN TestCacheConfigHandler/no_signing_keys
  1384. 9.96 s [niks3-go-unit-tests] === PAUSE TestCacheConfigHandler/no_signing_keys
  1385. 9.96 s [niks3-go-unit-tests] === RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator
  1386. 9.96 s [niks3-go-unit-tests] === PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator
  1387. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidCachePath
  1388. 9.96 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/narinfo
  1389. 9.96 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/narinfo
  1390. 9.96 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/narinfo_all_nix_base32_chars
  1391. 9.96 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars
  1392. 9.96 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/nar_zst
  1393. 9.96 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/nar_zst
  1394. 9.96 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/nar_xz
  1395. 9.96 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/nar_xz
  1396. 9.96 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/nar_bz2
  1397. 9.96 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/nar_bz2
  1398. 9.96 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/nar_uncompressed
  1399. 9.96 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/nar_uncompressed
  1400. 9.96 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/ls
  1401. 9.96 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/ls
  1402. 9.96 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/log
  1403. 9.96 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/log
  1404. 9.96 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/realisation
  1405. 9.96 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/realisation
  1406. 9.96 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/nix-cache-info
  1407. 9.96 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/nix-cache-info
  1408. 9.96 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/index.html
  1409. 9.96 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/index.html
  1410. 9.96 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/traversal_parent
  1411. 9.96 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/traversal_parent
  1412. 9.96 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/traversal_in_middle
  1413. 9.96 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/traversal_in_middle
  1414. 9.96 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/invalid_char_e
  1415. 9.96 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/invalid_char_e
  1416. 9.96 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/invalid_char_u
  1417. 9.96 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/invalid_char_u
  1418. 9.96 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/random_path
  1419. 9.96 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/random_path
  1420. 9.96 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/empty
  1421. 9.96 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/empty
  1422. 9.96 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/leading_slash
  1423. 9.96 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/leading_slash
  1424. 9.96 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/wrong_extension
  1425. 9.96 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/wrong_extension
  1426. 9.96 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/short_hash
  1427. 9.96 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/short_hash
  1428. 9.96 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info
  1429. 9.96 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received uploads request method=POST path=/
  1430. 9.96 s [niks3-go-unit-tests] === CONT TestServerTLSConfig/no_client_CA
  1431. 9.96 s [niks3-go-unit-tests] === CONT TestServerTLSConfig/not_a_PEM_file
  1432. 9.96 s [niks3-go-unit-tests] === CONT TestServerTLSConfig/missing_CA_file
  1433. 9.96 s [niks3-go-unit-tests] --- PASS: TestServerTLSConfig (0.00s)
  1434. 9.96 s [niks3-go-unit-tests] --- PASS: TestServerTLSConfig/no_client_CA (0.00s)
  1435. 9.96 s [niks3-go-unit-tests] --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)
  1436. 9.96 s [niks3-go-unit-tests] --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)
  1437. 9.96 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key
  1438. 9.96 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received complete multipart upload request method=POST path=/
  1439. 9.96 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key
  1440. 9.96 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received request for more parts method=POST path=/
  1441. 9.96 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal
  1442. 9.96 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received uploads request method=POST path=/
  1443. 9.96 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)
  1444. 9.96 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)
  1445. 9.96 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)
  1446. 9.96 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)
  1447. 9.96 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)
  1448. 9.96 s [niks3-go-unit-tests] === CONT TestParseSingleRange/none
  1449. 9.96 s [niks3-go-unit-tests] === CONT TestParseSingleRange/open-ended
  1450. 9.96 s [niks3-go-unit-tests] === CONT TestParseSingleRange/start_far_past_EOF
  1451. 9.96 s [niks3-go-unit-tests] === CONT TestParseSingleRange/start_past_EOF
  1452. 9.96 s [niks3-go-unit-tests] === CONT TestParseSingleRange/single_byte
  1453. 9.96 s [niks3-go-unit-tests] === CONT TestParseSingleRange/suffix_exceeds_size
  1454. 9.96 s [niks3-go-unit-tests] === CONT TestParseSingleRange/suffix
  1455. 9.96 s [niks3-go-unit-tests] === CONT TestParseSingleRange/end_clamped_to_size
  1456. 9.96 s [niks3-go-unit-tests] === CONT TestParseSingleRange/malformed_both_empty
  1457. 9.96 s [niks3-go-unit-tests] === CONT TestParseSingleRange/closed
  1458. 9.96 s [niks3-go-unit-tests] === CONT TestParseSingleRange/malformed_end_before_start
  1459. 9.96 s [niks3-go-unit-tests] === CONT TestParseSingleRange/multi-range_ignored
  1460. 9.96 s [niks3-go-unit-tests] === CONT TestParseSingleRange/malformed_no_dash
  1461. 9.96 s [niks3-go-unit-tests] === CONT TestParseSingleRange/unknown_unit
  1462. 9.96 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange (0.00s)
  1463. 9.96 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/none (0.00s)
  1464. 9.96 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/open-ended (0.00s)
  1465. 9.96 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)
  1466. 9.96 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/start_past_EOF (0.00s)
  1467. 9.96 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/single_byte (0.00s)
  1468. 9.96 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)
  1469. 9.96 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/suffix (0.00s)
  1470. 9.96 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)
  1471. 9.96 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)
  1472. 9.96 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/closed (0.00s)
  1473. 9.96 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)
  1474. 9.96 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)
  1475. 9.96 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)
  1476. 9.96 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/unknown_unit (0.00s)
  1477. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/narinfo
  1478. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/realisation_plus_in_output
  1479. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/unknown_type
  1480. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/empty_key
  1481. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/absolute
  1482. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/traversal_nar
  1483. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/traversal
  1484. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/listing_key,_narinfo_type
  1485. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/nar_key,_narinfo_type
  1486. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/narinfo_key,_nar_type
  1487. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/index.html
  1488. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/nix-cache-info
  1489. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/build_log_home-manager_file
  1490. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/realisation
  1491. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/build_log_equals
  1492. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/build_log_question_mark
  1493. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/build_log_plus_in_name
  1494. 9.96 s [niks3-go-unit-tests] === CONT TestProxyWriteTimeout/narinfo
  1495. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/nar_zst
  1496. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/build_log
  1497. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/listing
  1498. 9.96 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/nar_xz
  1499. 9.96 s [niks3-go-unit-tests] === CONT TestProxyWriteTimeout/10_GiB_nar
  1500. 9.97 s [niks3-go-unit-tests] === CONT TestProxyWriteTimeout/unknown_size
  1501. 9.97 s [niks3-go-unit-tests] === CONT TestProxyWriteTimeout/1_GiB_nar
  1502. 9.97 s [niks3-go-unit-tests] --- PASS: TestProxyWriteTimeout (0.00s)
  1503. 9.97 s [niks3-go-unit-tests] --- PASS: TestProxyWriteTimeout/narinfo (0.00s)
  1504. 9.97 s [niks3-go-unit-tests] --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)
  1505. 9.97 s [niks3-go-unit-tests] --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)
  1506. 9.97 s [niks3-go-unit-tests] --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)
  1507. 9.97 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/nar_plain
  1508. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey (0.00s)
  1509. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/narinfo (0.00s)
  1510. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)
  1511. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/unknown_type (0.00s)
  1512. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/empty_key (0.00s)
  1513. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/absolute (0.00s)
  1514. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)
  1515. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/traversal (0.00s)
  1516. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)
  1517. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)
  1518. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)
  1519. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/index.html (0.00s)
  1520. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)
  1521. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)
  1522. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/realisation (0.00s)
  1523. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)
  1524. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)
  1525. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)
  1526. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/nar_zst (0.00s)
  1527. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/build_log (0.00s)
  1528. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/listing (0.00s)
  1529. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/nar_xz (0.00s)
  1530. 9.97 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/nar_plain (0.00s)
  1531. 9.97 s [niks3-go-unit-tests] === CONT TestClientErrorHandling/InvalidStorePath
  1532. 9.97 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20241026095416_initial_model.sql (24.82ms)
  1533. 9.97 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20241026095416_initial_model.sql (24.74ms)
  1534. 9.97 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20241026095416_initial_model.sql (24.93ms)
  1535. 9.99 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20241026095416_initial_model.sql (40.9ms)
  1536. 9.99 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20251210153512_drop_unused_gin_index.sql (16.27ms)
  1537. 9.99 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20241026095416_initial_model.sql (41.16ms)
  1538. 9.99 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20251210153512_drop_unused_gin_index.sql (16.27ms)
  1539. 9.99 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20251210153512_drop_unused_gin_index.sql (16.36ms)
  1540. 10.00 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20251218171726_add_pins.sql (15.94ms)
  1541. 10.00 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20251218171726_add_pins.sql (15.99ms)
  1542. 10.00 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20251218171726_add_pins.sql (15.96ms)
  1543. 10.00 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20251210153512_drop_unused_gin_index.sql (16.21ms)
  1544. 10.00 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20251210153512_drop_unused_gin_index.sql (16.14ms)
  1545. 10.02 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20251218171726_add_pins.sql (17.44ms)
  1546. 10.02 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20260628120000_add_object_size_and_stats.sql (17.58ms)
  1547. 10.02 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20260628120000_add_object_size_and_stats.sql (17.54ms)
  1548. 10.02 s [niks3-go-unit-tests] 2026/07/18 13:56:28 goose: successfully migrated database to version: 20260628120000
  1549. 10.02 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20260628120000_add_object_size_and_stats.sql (17.54ms)
  1550. 10.02 s [niks3-go-unit-tests] 2026/07/18 13:56:28 goose: successfully migrated database to version: 20260628120000
  1551. 10.02 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20251218171726_add_pins.sql (17.43ms)
  1552. 10.02 s [niks3-go-unit-tests] 2026/07/18 13:56:28 goose: successfully migrated database to version: 20260628120000
  1553. 10.03 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=0
  1554. 10.03 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received uploads request method=POST path=/api/pending_closures
  1555. 10.04 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 1_commit_pending_closure.sql (14.28ms)
  1556. 10.04 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20260628120000_add_object_size_and_stats.sql (14.29ms)
  1557. 10.04 s [niks3-go-unit-tests] 2026/07/18 13:56:28 goose: successfully migrated database to version: 20260628120000
  1558. 10.04 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 1_commit_pending_closure.sql (14.31ms)
  1559. 10.04 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20260628120000_add_object_size_and_stats.sql (14.38ms)
  1560. 10.04 s [niks3-go-unit-tests] 2026/07/18 13:56:28 goose: successfully migrated database to version: 20260628120000
  1561. 10.04 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 1_commit_pending_closure.sql (14.23ms)
  1562. 10.04 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received uploads request method=POST path=/api/pending_closures
  1563. 10.05 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 1_commit_pending_closure.sql (12.22ms)
  1564. 10.05 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 1_commit_pending_closure.sql (12.18ms)
  1565. 10.05 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 2_object_stats_trigger.sql (12.27ms)
  1566. 10.05 s [niks3-go-unit-tests] 2026/07/18 13:56:28 goose: up to current file version: 2
  1567. 10.05 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 2_object_stats_trigger.sql (12.21ms)
  1568. 10.05 s [niks3-go-unit-tests] 2026/07/18 13:56:28 goose: up to current file version: 2
  1569. 10.05 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 2_object_stats_trigger.sql (12.24ms)
  1570. 10.05 s [niks3-go-unit-tests] 2026/07/18 13:56:28 goose: up to current file version: 2
  1571. 10.05 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Vacuumed table table=pending_closures
  1572. 10.05 s [niks3-go-unit-tests] 2026/07/18 13:56:28 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"
  1573. 10.05 s [niks3-go-unit-tests] 2026/07/18 13:56:28 WARN mTLS auth: bound subjects configured but subject DN unavailable
  1574. 10.05 s [niks3-go-unit-tests] 2026/07/18 13:56:28 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"
  1575. 10.05 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (1.17s)
  1576. 10.05 s [niks3-go-unit-tests] === CONT TestClientErrorHandling/ServerNotAvailable
  1577. 10.05 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Created nix-cache-info in bucket bucket=bucket36
  1578. 10.05 s [niks3-go-unit-tests] --- PASS: TestReadProxyRangeRequest (1.42s)
  1579. 10.05 s [niks3-go-unit-tests] === CONT TestClientErrorHandling/InvalidAuthToken
  1580. 10.06 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received uploads request method=POST path=/api/pending_closures
  1581. 10.07 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 2_object_stats_trigger.sql (18.66ms)
  1582. 10.07 s [niks3-go-unit-tests] 2026/07/18 13:56:28 goose: up to current file version: 2
  1583. 10.07 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 2_object_stats_trigger.sql (18.69ms)
  1584. 10.07 s [niks3-go-unit-tests] 2026/07/18 13:56:28 goose: up to current file version: 2
  1585. 10.07 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received uploads request method=POST path=/api/pending_closures
  1586. 10.07 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token
  1587. 10.07 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token
  1588. 10.07 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected
  1589. 10.07 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected
  1590. 10.07 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected
  1591. 10.07 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected
  1592. 10.07 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured
  1593. 10.07 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured
  1594. 10.07 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectOversizedBody/create_pending_closure
  1595. 10.07 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received uploads request method=POST path=/
  1596. 10.08 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)
  1597. 10.08 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Uploading 564m4bzhdm95mwxi5s5a6mby8x2sm29l-test-file-0.txt (160B)
  1598. 10.08 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Uploading 3m1l5k0v2xj36l05wpcar57pi6mcj7rh-test-file-1.txt (160B)
  1599. 10.08 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Uploading xkdh2c6fwh7y7wi9fr26qlhd7980a10z-test-file-2.txt (160B)
  1600. 10.08 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign
  1601. 10.08 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Signed narinfos id=1 count=1
  1602. 10.08 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign
  1603. 10.08 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Signed narinfos id=2 count=1
  1604. 10.08 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign
  1605. 10.08 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Signed narinfos id=3 count=1
  1606. 10.08 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Uploading 3 narinfos
  1607. 10.08 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete
  1608. 10.08 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Vacuumed table table=pending_objects
  1609. 10.09 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Vacuumed table table=multipart_uploads
  1610. 10.09 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Completed upload id=2
  1611. 10.09 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete
  1612. 10.10 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Vacuumed table table=closures
  1613. 10.10 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received uploads request method=POST path=/api/pending_closures
  1614. 10.11 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Completed upload id=3
  1615. 10.11 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1616. 10.11 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Vacuumed table table=objects
  1617. 10.12 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Completed upload id=1
  1618. 10.12 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Upload complete. (253ms)
  1619. 10.12 s [niks3-go-unit-tests] === NAME TestClientMultipleUploads
  1620. 10.12 s [niks3-go-unit-tests] client_integration_test.go:349: Uploaded 3 paths in 274.628262ms
  1621. 10.13 s [niks3-go-unit-tests] --- PASS: TestClientMultipleUploads (1.73s)
  1622. 10.13 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectOversizedBody/request_more_parts
  1623. 10.13 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received request for more parts method=POST path=/
  1624. 10.13 s [niks3-go-unit-tests] 2026-07-18 13:56:28.849 UTC [773] ERROR: relation "goose_db_version" does not exist at character 36
  1625. 10.13 s [niks3-go-unit-tests] 2026-07-18 13:56:28.849 UTC [773] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1626. 10.13 s [niks3-go-unit-tests] === NAME TestClientIntegration
  1627. 10.13 s [niks3-go-unit-tests] client_integration_test.go:276: Created store path: /build/TestClientIntegration9495799/002/store/r75477vassmvng1rdm64hgapzbiflwbf-test-file.txt
  1628. 10.13 s [niks3-go-unit-tests] 2026-07-18 13:56:28.850 UTC [774] ERROR: relation "goose_db_version" does not exist at character 36
  1629. 10.13 s [niks3-go-unit-tests] 2026-07-18 13:56:28.850 UTC [774] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1630. 10.16 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectOversizedBody/complete_multipart
  1631. 10.16 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO Received complete multipart upload request method=POST path=/
  1632. 10.19 s [niks3-go-unit-tests] === CONT TestCacheConfigHandler/full_config,_no_issuer
  1633. 10.19 s [niks3-go-unit-tests] === CONT TestCacheConfigHandler/no_signing_keys
  1634. 10.19 s [niks3-go-unit-tests] === CONT TestCacheConfigHandler/no_cache_url_configured
  1635. 10.19 s [niks3-go-unit-tests] === CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator
  1636. 10.19 s [niks3-go-unit-tests] --- PASS: TestCacheConfigHandler (0.00s)
  1637. 10.19 s [niks3-go-unit-tests] --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)
  1638. 10.19 s [niks3-go-unit-tests] --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)
  1639. 10.19 s [niks3-go-unit-tests] --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)
  1640. 10.19 s [niks3-go-unit-tests] --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)
  1641. 10.19 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/narinfo
  1642. 10.19 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/index.html
  1643. 10.19 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/nix-cache-info
  1644. 10.19 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/realisation
  1645. 10.19 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/log
  1646. 10.19 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/ls
  1647. 10.20 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/nar_uncompressed
  1648. 10.20 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/nar_bz2
  1649. 10.20 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/nar_xz
  1650. 10.20 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/nar_zst
  1651. 10.20 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/narinfo_all_nix_base32_chars
  1652. 10.20 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/empty
  1653. 10.20 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/traversal_parent
  1654. 10.20 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/random_path
  1655. 10.20 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/invalid_char_u
  1656. 10.20 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/invalid_char_e
  1657. 10.20 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/traversal_in_middle
  1658. 10.20 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/wrong_extension
  1659. 10.20 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/short_hash
  1660. 10.20 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/leading_slash
  1661. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath (0.00s)
  1662. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/narinfo (0.00s)
  1663. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/index.html (0.00s)
  1664. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)
  1665. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/realisation (0.00s)
  1666. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/log (0.00s)
  1667. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/ls (0.00s)
  1668. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)
  1669. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)
  1670. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/nar_xz (0.00s)
  1671. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/nar_zst (0.00s)
  1672. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)
  1673. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/empty (0.00s)
  1674. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/traversal_parent (0.00s)
  1675. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/random_path (0.00s)
  1676. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)
  1677. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)
  1678. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)
  1679. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/wrong_extension (0.00s)
  1680. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/short_hash (0.00s)
  1681. 10.20 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/leading_slash (0.00s)
  1682. 10.20 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token
  1683. 10.20 s [niks3-go-unit-tests] 2026/07/18 13:56:28 INFO OIDC auth successful provider=test
  1684. 10.20 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected
  1685. 10.20 s [niks3-go-unit-tests] 2026/07/18 13:56:28 WARN Authentication failed token_preview=not-a-valid-jwt token_length=15 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]
  1686. 10.20 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured
  1687. 10.20 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected
  1688. 10.20 s [niks3-go-unit-tests] 2026/07/18 13:56:28 WARN Authentication failed token_preview=eyJhbGciOi...SuoQjFj4-w token_length=702 oidc_error="bound claims validation failed: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]
  1689. 10.20 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_OIDC (1.30s)
  1690. 10.20 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)
  1691. 10.20 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)
  1692. 10.20 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)
  1693. 10.20 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)
  1694. 10.23 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20241026095416_initial_model.sql (79.26ms)
  1695. 10.23 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20241026095416_initial_model.sql (79.8ms)
  1696. 10.26 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20251210153512_drop_unused_gin_index.sql (24.85ms)
  1697. 10.26 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20251210153512_drop_unused_gin_index.sql (24.79ms)
  1698. 10.27 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20251218171726_add_pins.sql (15.72ms)
  1699. 10.54 s [niks3-go-unit-tests] 2026/07/18 13:56:28 OK 20251218171726_add_pins.sql (15.77ms)
  1700. 10.54 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 20260628120000_add_object_size_and_stats.sql (8.21ms)
  1701. 10.54 s [niks3-go-unit-tests] 2026/07/18 13:56:29 goose: successfully migrated database to version: 20260628120000
  1702. 10.54 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 20260628120000_add_object_size_and_stats.sql (8.17ms)
  1703. 10.54 s [niks3-go-unit-tests] 2026/07/18 13:56:29 goose: successfully migrated database to version: 20260628120000
  1704. 10.54 s [niks3-go-unit-tests] === NAME TestClientCADerivations
  1705. 10.55 s [niks3-go-unit-tests] client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations2368718488/001/store/bk8p4k5f7lvwvf3pk5z030drm0m5xcdz-ca-test
  1706. 10.55 s [niks3-go-unit-tests] 2026-07-18 13:56:29.003 UTC [888] ERROR: relation "goose_db_version" does not exist at character 36
  1707. 10.55 s [niks3-go-unit-tests] 2026-07-18 13:56:29.003 UTC [888] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1708. 10.55 s [niks3-go-unit-tests] 2026-07-18 13:56:29.003 UTC [887] ERROR: relation "goose_db_version" does not exist at character 36
  1709. 10.55 s [niks3-go-unit-tests] 2026-07-18 13:56:29.003 UTC [887] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1710. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Received uploads request method=POST path=/api/pending_closures
  1711. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Received complete multipart upload request method=POST path=/api/multipart/complete
  1712. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 1_commit_pending_closure.sql (16.23ms)
  1713. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 1_commit_pending_closure.sql (16.31ms)
  1714. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)
  1715. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Uploading r75477vassmvng1rdm64hgapzbiflwbf-test-file.txt (152B)
  1716. 10.55 s [niks3-go-unit-tests] client_ca_test.go:139: Found 1 dependencies (including self)
  1717. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign
  1718. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Signed narinfos id=1 count=1
  1719. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Uploading 1 narinfos
  1720. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1721. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 2_object_stats_trigger.sql (10.24ms)
  1722. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 goose: up to current file version: 2
  1723. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 2_object_stats_trigger.sql (10.43ms)
  1724. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 goose: up to current file version: 2
  1725. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 WARN mTLS auth: subject not in bound subjects subject="CN=writer"
  1726. 10.55 s [niks3-go-unit-tests] --- PASS: TestService_ReadAuthMiddleware (1.35s)
  1727. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YTNlYzZhMzMtZmM3OC00ZmFiLTllMTQtYTBiZmQ5MTAxZGJkLjAyYjc0NjNkLWE4ODUtNDJjOS1iMmJmLWYyOWM2YTYzMTEwNHgxNzg0MzgyOTg4ODA0NDc0NzI2 parts=12
  1728. 10.55 s [niks3-go-unit-tests] --- PASS: TestRedundantMultipartUpload (1.82s)
  1729. 10.55 s [niks3-go-unit-tests] 2026-07-18 13:56:29.040 UTC [937] ERROR: relation "goose_db_version" does not exist at character 36
  1730. 10.55 s [niks3-go-unit-tests] 2026-07-18 13:56:29.040 UTC [937] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1731. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 20241026095416_initial_model.sql (20.42ms)
  1732. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 20241026095416_initial_model.sql (19.9ms)
  1733. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Completed upload id=1
  1734. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Upload complete. (171ms)
  1735. 10.55 s [niks3-go-unit-tests] === NAME TestClientIntegration
  1736. 10.55 s [niks3-go-unit-tests] client_integration_test.go:292: Retrieved narinfo from S3:
  1737. 10.55 s [niks3-go-unit-tests] StorePath: /build/TestClientIntegration9495799/002/store/r75477vassmvng1rdm64hgapzbiflwbf-test-file.txt
  1738. 10.55 s [niks3-go-unit-tests] URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst
  1739. 10.55 s [niks3-go-unit-tests] Compression: zstd
  1740. 10.55 s [niks3-go-unit-tests] NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1
  1741. 10.55 s [niks3-go-unit-tests] NarSize: 152
  1742. 10.55 s [niks3-go-unit-tests] References:
  1743. 10.55 s [niks3-go-unit-tests] CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1
  1744. 10.55 s [niks3-go-unit-tests] client_integration_test.go:293: Retrieved .ls file from S3 (compressed size: 77 bytes)
  1745. 10.55 s [niks3-go-unit-tests] client_integration_test.go:293: Decompressed .ls content (64 bytes):
  1746. 10.55 s [niks3-go-unit-tests] {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}
  1747. 10.55 s [niks3-go-unit-tests] client_integration_test.go:296: Testing garbage collection...
  1748. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 20251210153512_drop_unused_gin_index.sql (17.3ms)
  1749. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 20251210153512_drop_unused_gin_index.sql (15.61ms)
  1750. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Starting cleanup of old closures method=DELETE path=/api/closures
  1751. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Garbage collection started
  1752. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Aborted multipart uploads count=0
  1753. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 20241026095416_initial_model.sql (17.8ms)
  1754. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 20251218171726_add_pins.sql (16.08ms)
  1755. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 20251218171726_add_pins.sql (16.13ms)
  1756. 10.55 s [niks3-go-unit-tests] --- PASS: TestCacheStatsHandler (0.89s)
  1757. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 WARN Force mode enabled - objects will be deleted immediately without grace period
  1758. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 20251210153512_drop_unused_gin_index.sql (17.05ms)
  1759. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Received uploads request method=POST path=/api/pending_closures
  1760. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures
  1761. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 20260628120000_add_object_size_and_stats.sql (16.8ms)
  1762. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 goose: successfully migrated database to version: 20260628120000
  1763. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 20260628120000_add_object_size_and_stats.sql (16.84ms)
  1764. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 goose: successfully migrated database to version: 20260628120000
  1765. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 20251218171726_add_pins.sql (12.07ms)
  1766. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)
  1767. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Uploading bk8p4k5f7lvwvf3pk5z030drm0m5xcdz-ca-test (144B)
  1768. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign
  1769. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Signed narinfos id=1 count=1
  1770. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Uploading 1 narinfos
  1771. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1772. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 1_commit_pending_closure.sql (9.12ms)
  1773. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 1_commit_pending_closure.sql (9.05ms)
  1774. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 20260628120000_add_object_size_and_stats.sql (9.03ms)
  1775. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 goose: successfully migrated database to version: 20260628120000
  1776. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 2_object_stats_trigger.sql (9.82ms)
  1777. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 goose: up to current file version: 2
  1778. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Completed upload id=1
  1779. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 2_object_stats_trigger.sql (9.96ms)
  1780. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 goose: up to current file version: 2
  1781. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Upload complete. (68ms)
  1782. 10.55 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.64s)
  1783. 10.55 s [niks3-go-unit-tests] === NAME TestClientCADerivations
  1784. 10.55 s [niks3-go-unit-tests] client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations2368718488/001/store/bk8p4k5f7lvwvf3pk5z030drm0m5xcdz-ca-test
  1785. 10.55 s [niks3-go-unit-tests] URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst
  1786. 10.55 s [niks3-go-unit-tests] Compression: zstd
  1787. 10.55 s [niks3-go-unit-tests] NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n
  1788. 10.55 s [niks3-go-unit-tests] NarSize: 144
  1789. 10.55 s [niks3-go-unit-tests] References:
  1790. 10.55 s [niks3-go-unit-tests] Deriver: /build/TestClientCADerivations2368718488/001/store/n6by1ilv74121zibja8sfc5ina9w2b60-ca-test.drv
  1791. 10.55 s [niks3-go-unit-tests] CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n
  1792. 10.55 s [niks3-go-unit-tests] client_ca_test.go:185: Checking for realisation files in S3...
  1793. 10.55 s [niks3-go-unit-tests] client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations
  1794. 10.55 s [niks3-go-unit-tests] client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache
  1795. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 1_commit_pending_closure.sql (10.1ms)
  1796. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 OK 2_object_stats_trigger.sql (4.26ms)
  1797. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 goose: up to current file version: 2
  1798. 10.55 s [niks3-go-unit-tests] client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features
  1799. 10.55 s [niks3-go-unit-tests] warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable
  1800. 10.55 s [niks3-go-unit-tests] error: binary cache 's3://bucket36?endpoint=http://localhost:41767&region=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations2368718488/001/store'
  1801. 10.55 s [niks3-go-unit-tests] client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 1
  1802. 10.55 s [niks3-go-unit-tests] --- PASS: TestClientCADerivations (1.54s)
  1803. 10.55 s [niks3-go-unit-tests] 2026/07/18 13:56:29 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=215.844367ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures
  1804. 10.67 s [niks3-go-unit-tests] 2026/07/18 13:56:29 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"
  1805. 10.68 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectOversizedBody (0.13s)
  1806. 10.68 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.03s)
  1807. 10.68 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.03s)
  1808. 10.68 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.61s)
  1809. 10.69 s [niks3-go-unit-tests] 2026/07/18 13:56:29 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=382.214583ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures
  1810. 10.71 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2193 objects-failed-to-delete=0
  1811. 10.73 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Vacuumed table table=pending_closures
  1812. 10.74 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Vacuumed table table=pending_objects
  1813. 10.74 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Vacuumed table table=multipart_uploads
  1814. 10.76 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Vacuumed table table=closures
  1815. 10.78 s [niks3-go-unit-tests] 2026/07/18 13:56:29 INFO Vacuumed table table=objects
  1816. 11.07 s [niks3-go-unit-tests] 2026/07/18 13:56:29 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=804.559149ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures
  1817. 11.41 s [niks3-go-unit-tests] === NAME TestOrphanedObjectsGCStressTest
  1818. 11.42 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains
  1819. 11.43 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:446: Marked 210 objects for deletion
  1820. 11.50 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:509: Stress test completed successfully:
  1821. 11.50 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:510: - Active objects preserved: 20
  1822. 11.50 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:511: - Objects deleted: 210
  1823. 11.50 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:512: - Total GC'd: 210
  1824. 11.50 s [niks3-go-unit-tests] --- PASS: TestOrphanedObjectsGCStressTest (3.43s)
  1825. 11.51 s [niks3-go-unit-tests] 2026/07/18 13:56:30 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=0
  1826. 11.51 s [niks3-go-unit-tests] === NAME TestPinProtectsFromGC
  1827. 11.51 s [niks3-go-unit-tests] client_integration_test.go:709: Pin successfully protected closure from garbage collection
  1828. 11.51 s [niks3-go-unit-tests] --- PASS: TestPinProtectsFromGC (3.91s)
  1829. 11.88 s [niks3-go-unit-tests] 2026/07/18 13:56:30 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.57384879s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures
  1830. 12.35 s [niks3-go-unit-tests] 2026/07/18 13:56:31 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2193 objects_failed=0
  1831. 12.35 s [niks3-go-unit-tests] === NAME TestClientIntegration
  1832. 12.35 s [niks3-go-unit-tests] client_integration_test.go:303: Objects in database after GC:
  1833. 12.35 s [niks3-go-unit-tests] client_integration_test.go:303: Successfully deleted all objects with GC --force
  1834. 12.35 s [niks3-go-unit-tests] --- PASS: TestClientIntegration (3.85s)
  1835. 13.30 s [niks3-go-unit-tests] 2026/07/18 13:56:32 WARN Rate limiter enabled after throttle name=s3-test rate=5
  1836. 13.30 s [niks3-go-unit-tests] 2026/07/18 13:56:32 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."
  1837. 13.30 s [niks3-go-unit-tests] === NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle
  1838. 13.30 s [niks3-go-unit-tests] throttle_test.go:213: Proxy stats: total=15, throttled=10, completeMultipart=10
  1839. 13.30 s [niks3-go-unit-tests] throttle_test.go:215: Rate limiter: enabled=true, rate=5.00
  1840. 13.30 s [niks3-go-unit-tests] --- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.76s)
  1841. 13.45 s [niks3-go-unit-tests] --- PASS: TestClientErrorHandling (0.00s)
  1842. 13.45 s [niks3-go-unit-tests] --- PASS: TestClientErrorHandling/InvalidStorePath (0.45s)
  1843. 13.45 s [niks3-go-unit-tests] --- PASS: TestClientErrorHandling/InvalidAuthToken (0.62s)
  1844. 13.45 s [niks3-go-unit-tests] --- PASS: TestClientErrorHandling/ServerNotAvailable (3.40s)
  1845. 13.45 s [niks3-go-unit-tests] PASS
  1846. 13.98 s [niks3-go-unit-tests] 2026-07-18 13:56:32.701 UTC [99] LOG: received smart shutdown request
  1847. 13.99 s [niks3-go-unit-tests] 2026-07-18 13:56:32.712 UTC [99] LOG: background worker "logical replication launcher" (PID 109) exited with exit code 1
  1848. 14.00 s [niks3-go-unit-tests] 2026-07-18 13:56:32.715 UTC [104] LOG: shutting down
  1849. 14.00 s [niks3-go-unit-tests] 2026-07-18 13:56:32.722 UTC [104] LOG: checkpoint starting: shutdown immediate
  1850. 23.45 s [niks3-go-unit-tests] 2026/07/18 13:56:42 ERROR failed to kill rustfs error="no such process"
  1851. 23.98 s [niks3-go-unit-tests] 2026/07/18 13:56:42 INFO killed rustfs
  1852. 23.98 s [niks3-go-unit-tests] 2026/07/18 13:56:42 ERROR failed to wait for rustfs error="signal: killed"
  1853. 24.01 s [niks3-go-unit-tests] 2026-07-18 13:56:42.726 UTC [104] PANIC: could not fsync file "base/20408/1418": No such file or directory
  1854. 24.33 s [niks3-go-unit-tests] Running OIDC tests...
  1855. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch
  1856. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch
  1857. 24.34 s [niks3-go-unit-tests] === RUN TestAudienceForIssuer
  1858. 24.34 s [niks3-go-unit-tests] === PAUSE TestAudienceForIssuer
  1859. 24.34 s [niks3-go-unit-tests] === RUN TestValidateToken_ValidToken
  1860. 24.34 s [niks3-go-unit-tests] === PAUSE TestValidateToken_ValidToken
  1861. 24.34 s [niks3-go-unit-tests] === RUN TestValidateToken_WrongAudience
  1862. 24.34 s [niks3-go-unit-tests] === PAUSE TestValidateToken_WrongAudience
  1863. 24.34 s [niks3-go-unit-tests] === RUN TestValidateToken_Expired
  1864. 24.34 s [niks3-go-unit-tests] === PAUSE TestValidateToken_Expired
  1865. 24.34 s [niks3-go-unit-tests] === RUN TestValidateToken_BoundClaimsMismatch
  1866. 24.34 s [niks3-go-unit-tests] === PAUSE TestValidateToken_BoundClaimsMismatch
  1867. 24.34 s [niks3-go-unit-tests] === RUN TestValidateToken_BoundSubjectMismatch
  1868. 24.34 s [niks3-go-unit-tests] === PAUSE TestValidateToken_BoundSubjectMismatch
  1869. 24.34 s [niks3-go-unit-tests] === RUN TestValidateToken_MultipleProviders
  1870. 24.34 s [niks3-go-unit-tests] === PAUSE TestValidateToken_MultipleProviders
  1871. 24.34 s [niks3-go-unit-tests] === RUN TestValidateToken_NoMatchingProvider
  1872. 24.34 s [niks3-go-unit-tests] === PAUSE TestValidateToken_NoMatchingProvider
  1873. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch
  1874. 24.34 s [niks3-go-unit-tests] === CONT TestValidateToken_BoundClaimsMismatch
  1875. 24.34 s [niks3-go-unit-tests] === CONT TestValidateToken_BoundSubjectMismatch
  1876. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo_foo
  1877. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo_foo
  1878. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo_bar
  1879. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo_bar
  1880. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/*_
  1881. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*_
  1882. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/*_anything
  1883. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*_anything
  1884. 24.34 s [niks3-go-unit-tests] === CONT TestValidateToken_Expired
  1885. 24.34 s [niks3-go-unit-tests] === CONT TestValidateToken_WrongAudience
  1886. 24.34 s [niks3-go-unit-tests] === CONT TestValidateToken_ValidToken
  1887. 24.34 s [niks3-go-unit-tests] === CONT TestAudienceForIssuer
  1888. 24.34 s [niks3-go-unit-tests] --- PASS: TestAudienceForIssuer (0.00s)
  1889. 24.34 s [niks3-go-unit-tests] === CONT TestValidateToken_MultipleProviders
  1890. 24.34 s [niks3-go-unit-tests] === CONT TestValidateToken_NoMatchingProvider
  1891. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo*_foo
  1892. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo*_foo
  1893. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo*_foobar
  1894. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo*_foobar
  1895. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo*_bar
  1896. 24.34 s [niks3-go-unit-tests] 2026/07/18 13:56:43 INFO OIDC provider initialized name=test
  1897. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo*_bar
  1898. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/*bar_bar
  1899. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*bar_bar
  1900. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/*bar_foobar
  1901. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*bar_foobar
  1902. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/*bar_foo
  1903. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*bar_foo
  1904. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo*bar_foobar
  1905. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo*bar_foobar
  1906. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo*bar_foo123bar
  1907. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo*bar_foo123bar
  1908. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo*bar_foobarbaz
  1909. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo*bar_foobarbaz
  1910. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/*/*_foo/bar
  1911. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*/*_foo/bar
  1912. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/*/*_foo
  1913. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*/*_foo
  1914. 24.34 s [niks3-go-unit-tests] 2026/07/18 13:56:43 INFO OIDC provider initialized name=test
  1915. 24.34 s [niks3-go-unit-tests] 2026/07/18 13:56:43 INFO OIDC provider initialized name=test
  1916. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/refs/heads/*_refs/heads/main
  1917. 24.34 s [niks3-go-unit-tests] 2026/07/18 13:56:43 INFO OIDC provider initialized name=test
  1918. 24.34 s [niks3-go-unit-tests] 2026/07/18 13:56:43 INFO OIDC provider initialized name=test
  1919. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/refs/heads/*_refs/heads/main
  1920. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/refs/heads/*_refs/tags/v1.0
  1921. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.0
  1922. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/refs/*/main_refs/heads/main
  1923. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/refs/*/main_refs/heads/main
  1924. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/fo?_foo
  1925. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/fo?_foo
  1926. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/fo?_fo
  1927. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/fo?_fo
  1928. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/fo?_fooo
  1929. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/fo?_fooo
  1930. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/?oo_foo
  1931. 24.34 s [niks3-go-unit-tests] 2026/07/18 13:56:43 INFO OIDC provider initialized name=provider1
  1932. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/?oo_foo
  1933. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/?oo_boo
  1934. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/?oo_boo
  1935. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main
  1936. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main
  1937. 24.34 s [niks3-go-unit-tests] === RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main
  1938. 24.34 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main
  1939. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo_foo
  1940. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main
  1941. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main
  1942. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo*bar_foobarbaz
  1943. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo*_foobar
  1944. 24.34 s [niks3-go-unit-tests] 2026/07/18 13:56:43 INFO OIDC provider initialized name=provider1
  1945. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo*_foo
  1946. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/*_anything
  1947. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/*_
  1948. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo_bar
  1949. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo*bar_foo123bar
  1950. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/refs/*/main_refs/heads/main
  1951. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/?oo_boo
  1952. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/fo?_fooo
  1953. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/*bar_foo
  1954. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/fo?_fo
  1955. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/refs/heads/*_refs/tags/v1.0
  1956. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/*bar_foobar
  1957. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/fo?_foo
  1958. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/*/*_foo
  1959. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/*bar_bar
  1960. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo*_bar
  1961. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo*bar_foobar
  1962. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/?oo_foo
  1963. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/*/*_foo/bar
  1964. 24.34 s [niks3-go-unit-tests] === CONT TestGlobMatch/refs/heads/*_refs/heads/main
  1965. 24.34 s [niks3-go-unit-tests] --- PASS: TestGlobMatch (0.00s)
  1966. 24.34 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo_foo (0.00s)
  1967. 24.34 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)
  1968. 24.34 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)
  1969. 24.34 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)
  1970. 24.34 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo*_foobar (0.00s)
  1971. 24.34 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo*_foo (0.00s)
  1972. 24.35 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*_anything (0.00s)
  1973. 24.35 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*_ (0.00s)
  1974. 24.35 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo_bar (0.00s)
  1975. 24.35 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)
  1976. 24.35 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)
  1977. 24.35 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/?oo_boo (0.00s)
  1978. 24.35 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/fo?_fooo (0.00s)
  1979. 24.35 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*bar_foo (0.00s)
  1980. 24.35 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/fo?_fo (0.00s)
  1981. 24.35 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)
  1982. 24.35 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*bar_foobar (0.00s)
  1983. 24.35 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/fo?_foo (0.00s)
  1984. 24.35 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*/*_foo (0.00s)
  1985. 24.35 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*bar_bar (0.00s)
  1986. 24.35 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo*_bar (0.00s)
  1987. 24.35 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)
  1988. 24.35 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/?oo_foo (0.00s)
  1989. 24.35 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)
  1990. 24.35 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)
  1991. 24.35 s [niks3-go-unit-tests] 2026/07/18 13:56:43 INFO OIDC provider initialized name=provider2
  1992. 24.35 s [niks3-go-unit-tests] --- PASS: TestValidateToken_WrongAudience (0.00s)
  1993. 24.35 s [niks3-go-unit-tests] --- PASS: TestValidateToken_ValidToken (0.00s)
  1994. 24.35 s [niks3-go-unit-tests] --- PASS: TestValidateToken_Expired (0.00s)
  1995. 24.35 s [niks3-go-unit-tests] --- PASS: TestValidateToken_BoundClaimsMismatch (0.00s)
  1996. 24.35 s [niks3-go-unit-tests] --- PASS: TestValidateToken_BoundSubjectMismatch (0.00s)
  1997. 24.35 s [niks3-go-unit-tests] --- PASS: TestValidateToken_NoMatchingProvider (0.01s)
  1998. 24.35 s [niks3-go-unit-tests] --- PASS: TestValidateToken_MultipleProviders (0.01s)
  1999. 24.35 s [niks3-go-unit-tests] PASS
  2000. 24.96 s [niks3-go-unit-tests] Running hook tests...
  2001. 24.96 s [niks3-go-unit-tests] === RUN TestSendPathsEmpty
  2002. 24.96 s [niks3-go-unit-tests] === PAUSE TestSendPathsEmpty
  2003. 24.96 s [niks3-go-unit-tests] === RUN TestQueueEnqueueAndFetch
  2004. 24.96 s [niks3-go-unit-tests] === PAUSE TestQueueEnqueueAndFetch
  2005. 24.96 s [niks3-go-unit-tests] === RUN TestQueueDeduplication
  2006. 24.96 s [niks3-go-unit-tests] === PAUSE TestQueueDeduplication
  2007. 24.96 s [niks3-go-unit-tests] === RUN TestQueueRemove
  2008. 24.96 s [niks3-go-unit-tests] === PAUSE TestQueueRemove
  2009. 24.96 s [niks3-go-unit-tests] === RUN TestQueueFetchBatchLimit
  2010. 24.96 s [niks3-go-unit-tests] === PAUSE TestQueueFetchBatchLimit
  2011. 24.96 s [niks3-go-unit-tests] === RUN TestQueueFetchRemoveLifecycle
  2012. 24.96 s [niks3-go-unit-tests] === PAUSE TestQueueFetchRemoveLifecycle
  2013. 24.96 s [niks3-go-unit-tests] === RUN TestQueueConcurrentWriters
  2014. 24.96 s [niks3-go-unit-tests] === PAUSE TestQueueConcurrentWriters
  2015. 24.96 s [niks3-go-unit-tests] === RUN TestServerClientIntegration
  2016. 24.96 s [niks3-go-unit-tests] === PAUSE TestServerClientIntegration
  2017. 24.96 s [niks3-go-unit-tests] === RUN TestServerQueueError
  2018. 24.96 s [niks3-go-unit-tests] === PAUSE TestServerQueueError
  2019. 24.96 s [niks3-go-unit-tests] === RUN TestGetListenerSocketActivation
  2020. 25.08 s [niks3-go-unit-tests] server_test.go:210: === RUN TestGetListenerSocketActivation
  2021. 25.08 s [niks3-go-unit-tests] --- PASS: TestGetListenerSocketActivation (0.00s)
  2022. 25.08 s [niks3-go-unit-tests] PASS
  2023. 25.08 s [niks3-go-unit-tests]
  2024. 25.08 s [niks3-go-unit-tests] --- PASS: TestGetListenerSocketActivation (0.12s)
  2025. 25.08 s [niks3-go-unit-tests] === RUN TestWorkerUploadsAndRemoves
  2026. 25.08 s [niks3-go-unit-tests] === PAUSE TestWorkerUploadsAndRemoves
  2027. 25.08 s [niks3-go-unit-tests] === RUN TestWorkerSkipsGCdPaths
  2028. 25.08 s [niks3-go-unit-tests] === PAUSE TestWorkerSkipsGCdPaths
  2029. 25.08 s [niks3-go-unit-tests] === RUN TestWorkerPrunesClosureDeps
  2030. 25.08 s [niks3-go-unit-tests] === PAUSE TestWorkerPrunesClosureDeps
  2031. 25.08 s [niks3-go-unit-tests] === CONT TestSendPathsEmpty
  2032. 25.08 s [niks3-go-unit-tests] --- PASS: TestSendPathsEmpty (0.00s)
  2033. 25.08 s [niks3-go-unit-tests] === CONT TestQueueFetchRemoveLifecycle
  2034. 25.08 s [niks3-go-unit-tests] === CONT TestQueueConcurrentWriters
  2035. 25.08 s [niks3-go-unit-tests] === CONT TestWorkerUploadsAndRemoves
  2036. 25.08 s [niks3-go-unit-tests] === CONT TestQueueRemove
  2037. 25.08 s [niks3-go-unit-tests] === CONT TestServerQueueError
  2038. 25.16 s [niks3-go-unit-tests] === CONT TestWorkerPrunesClosureDeps
  2039. 25.16 s [niks3-go-unit-tests] === CONT TestQueueEnqueueAndFetch
  2040. 25.16 s [niks3-go-unit-tests] === CONT TestQueueFetchBatchLimit
  2041. 25.16 s [niks3-go-unit-tests] === CONT TestQueueDeduplication
  2042. 25.16 s [niks3-go-unit-tests] === CONT TestWorkerSkipsGCdPaths
  2043. 25.16 s [niks3-go-unit-tests] === CONT TestServerClientIntegration
  2044. 25.16 s [niks3-go-unit-tests] 2026/07/18 13:56:43 ERROR Failed to queue paths error="permission denied" count=1
  2045. 25.16 s [niks3-go-unit-tests] --- PASS: TestServerQueueError (0.00s)
  2046. 25.16 s [niks3-go-unit-tests] --- PASS: TestServerClientIntegration (0.00s)
  2047. 25.23 s [niks3-go-unit-tests] 2026/07/18 13:56:43 INFO Upload queue status pending=2
  2048. 25.23 s [niks3-go-unit-tests] 2026/07/18 13:56:43 INFO Uploading batch count=2
  2049. 25.23 s [niks3-go-unit-tests] 2026/07/18 13:56:43 INFO Upload queue status pending=2
  2050. 25.23 s [niks3-go-unit-tests] 2026/07/18 13:56:43 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths4163522898/002/nonexistent
  2051. 25.25 s [niks3-go-unit-tests] 2026/07/18 13:56:43 INFO Upload queue status pending=2
  2052. 25.25 s [niks3-go-unit-tests] 2026/07/18 13:56:43 INFO Uploading batch count=1
  2053. 25.26 s [niks3-go-unit-tests] 2026/07/18 13:56:43 INFO Uploading batch count=1
  2054. 25.28 s [niks3-go-unit-tests] --- PASS: TestQueueEnqueueAndFetch (0.20s)
  2055. 25.29 s [niks3-go-unit-tests] --- PASS: TestQueueFetchBatchLimit (0.21s)
  2056. 25.29 s [niks3-go-unit-tests] --- PASS: TestQueueDeduplication (0.21s)
  2057. 25.31 s [niks3-go-unit-tests] --- PASS: TestQueueFetchRemoveLifecycle (0.23s)
  2058. 25.31 s [niks3-go-unit-tests] --- PASS: TestQueueRemove (0.23s)
  2059. 25.31 s [niks3-go-unit-tests] --- PASS: TestWorkerUploadsAndRemoves (0.24s)
  2060. 25.32 s [niks3-go-unit-tests] --- PASS: TestWorkerPrunesClosureDeps (0.24s)
  2061. 25.35 s [niks3-go-unit-tests] --- PASS: TestWorkerSkipsGCdPaths (0.28s)
  2062. 29.23 s [niks3-go-unit-tests] --- PASS: TestQueueConcurrentWriters (4.16s)
  2063. 29.28 s [niks3-go-unit-tests] PASS
  2064. 29.28 s [niks3-go-unit-tests:post-build] Uploading to the NixCI staging cache: /nix/store/wvf1cvf0c9a0gcjh1cvslwm5cdjcm3bp-niks3-go-unit-tests
  2065. 29.32 s [niks3-go-unit-tests:post-build] warning: 'warn-short-path-literals' is deprecated, use 'lint-short-path-literals = ignore' instead
  2066. 29.33 s [niks3-go-unit-tests:post-build] copying 1 paths...
  2067. 29.33 s [niks3-go-unit-tests:post-build] copying path '/nix/store/wvf1cvf0c9a0gcjh1cvslwm5cdjcm3bp-niks3-go-unit-tests' to 'https://cache.staging.nix-ci.com'...
  2068. 29.45 s [niks3-go-unit-tests:post-build] warning: 'warn-short-path-literals' is deprecated, use 'lint-short-path-literals = ignore' instead
  2069. 29.69 s [niks3-go-unit-tests:post-build] copying 1 paths...
  2070. 29.69 s [niks3-go-unit-tests:post-build] copying path '/nix/store/pjvglmgx4k8v1fgng4daqcmi9q9hf5f5-niks3-go-unit-tests.drv' to 'https://cache.staging.nix-ci.com'...
  2071. 29.86 s Uploaded niks3-go-unit-tests in 581ms
  2072. 29.86 s Progress: 1 of 2 built, 48 of 48 downloaded from cache
  2073. 29.86 s Built niks3-go-unit-tests in 26.2s
  2074. 29.86 s Progress: 2 of 2 built, 48 of 48 downloaded from cache
  2075. 29.86 s /nix/store/wvf1cvf0c9a0gcjh1cvslwm5cdjcm3bp-niks3-go-unit-tests
  2076. 29.92 s Build succeeded.
Tail Raw Logs