1. 0.12 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=fix%2Fregister-completed-object&rev=1745e6d569d601fcc3650ef4d243e46c97487012#checks.x86_64-linux.go-unit-tests --print-build-logs
  2. 1.23 s
  3. 1.66 s Building /nix/store/ibzpr9nh877a7qy0hb3g69ljr4p8f497-niks3-go-unit-tests.drv
  4. 1.76 s [niks3-go-unit-tests] Running client tests...
  5. 1.77 s [niks3-go-unit-tests] === RUN TestDoServerRequestAttachesToken
  6. 1.77 s [niks3-go-unit-tests] === PAUSE TestDoServerRequestAttachesToken
  7. 1.77 s [niks3-go-unit-tests] === RUN TestCaseHackSuffix
  8. 1.77 s [niks3-go-unit-tests] === PAUSE TestCaseHackSuffix
  9. 1.77 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR
  10. 1.77 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR
  11. 1.77 s [niks3-go-unit-tests] === RUN TestUploadMultipart_SupersededByPeer
  12. 1.77 s [niks3-go-unit-tests] === PAUSE TestUploadMultipart_SupersededByPeer
  13. 1.77 s [niks3-go-unit-tests] === RUN TestDumpPathMatchesNix
  14. 1.77 s [niks3-go-unit-tests] === PAUSE TestDumpPathMatchesNix
  15. 1.77 s [niks3-go-unit-tests] === RUN TestDumpPathSingleFile
  16. 1.77 s [niks3-go-unit-tests] === PAUSE TestDumpPathSingleFile
  17. 1.77 s [niks3-go-unit-tests] === RUN TestDumpPathWriterError
  18. 1.77 s [niks3-go-unit-tests] === PAUSE TestDumpPathWriterError
  19. 1.77 s [niks3-go-unit-tests] === RUN TestEncodeNixBase32
  20. 1.77 s [niks3-go-unit-tests] === PAUSE TestEncodeNixBase32
  21. 1.77 s [niks3-go-unit-tests] === RUN TestEncodeNixBase32WithRealHash
  22. 1.77 s [niks3-go-unit-tests] === PAUSE TestEncodeNixBase32WithRealHash
  23. 1.77 s [niks3-go-unit-tests] === RUN TestConvertHashToNix32
  24. 1.77 s [niks3-go-unit-tests] === PAUSE TestConvertHashToNix32
  25. 1.77 s [niks3-go-unit-tests] === RUN TestGetStorePathHash
  26. 1.77 s [niks3-go-unit-tests] === PAUSE TestGetStorePathHash
  27. 1.77 s [niks3-go-unit-tests] === RUN TestPathInfoHashCompatibility
  28. 1.77 s [niks3-go-unit-tests] === PAUSE TestPathInfoHashCompatibility
  29. 1.77 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSON
  30. 1.77 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSON
  31. 1.77 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSONMultiplePaths
  32. 1.77 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSONMultiplePaths
  33. 1.77 s [niks3-go-unit-tests] === RUN TestPathInfoCACompatibility
  34. 1.77 s [niks3-go-unit-tests] === PAUSE TestPathInfoCACompatibility
  35. 1.77 s [niks3-go-unit-tests] === RUN TestRateLimiterFeedback
  36. 1.77 s [niks3-go-unit-tests] === PAUSE TestRateLimiterFeedback
  37. 1.77 s [niks3-go-unit-tests] === RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess
  38. 1.77 s [niks3-go-unit-tests] === PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess
  39. 1.77 s [niks3-go-unit-tests] === RUN TestResolveStorePath
  40. 1.77 s [niks3-go-unit-tests] === PAUSE TestResolveStorePath
  41. 1.77 s [niks3-go-unit-tests] === RUN TestDoWithRetry_BodyReplayedViaGetBody
  42. 1.77 s [niks3-go-unit-tests] === PAUSE TestDoWithRetry_BodyReplayedViaGetBody
  43. 1.77 s [niks3-go-unit-tests] === RUN TestShellSplit
  44. 1.77 s [niks3-go-unit-tests] === PAUSE TestShellSplit
  45. 1.77 s [niks3-go-unit-tests] === RUN TestShellSplitErrors
  46. 1.77 s [niks3-go-unit-tests] === PAUSE TestShellSplitErrors
  47. 1.77 s [niks3-go-unit-tests] === RUN TestSetClientTLS
  48. 1.77 s [niks3-go-unit-tests] === PAUSE TestSetClientTLS
  49. 1.77 s [niks3-go-unit-tests] === RUN TestSetClientTLSDoesNotMutateDefaultTransport
  50. 1.77 s [niks3-go-unit-tests] === PAUSE TestSetClientTLSDoesNotMutateDefaultTransport
  51. 1.77 s [niks3-go-unit-tests] === RUN TestSetClientTLSErrors
  52. 1.77 s [niks3-go-unit-tests] === PAUSE TestSetClientTLSErrors
  53. 1.77 s [niks3-go-unit-tests] === RUN TestStaticToken
  54. 1.77 s [niks3-go-unit-tests] === PAUSE TestStaticToken
  55. 1.77 s [niks3-go-unit-tests] === RUN TestFileTokenReadsAndCaches
  56. 1.77 s [niks3-go-unit-tests] === PAUSE TestFileTokenReadsAndCaches
  57. 1.77 s [niks3-go-unit-tests] === RUN TestFileTokenMissing
  58. 1.77 s [niks3-go-unit-tests] === PAUSE TestFileTokenMissing
  59. 1.77 s [niks3-go-unit-tests] === RUN TestFileTokenEmpty
  60. 1.77 s [niks3-go-unit-tests] === PAUSE TestFileTokenEmpty
  61. 1.77 s [niks3-go-unit-tests] === RUN TestScriptTokenNoExpiryRerunsEveryCall
  62. 1.77 s [niks3-go-unit-tests] === PAUSE TestScriptTokenNoExpiryRerunsEveryCall
  63. 1.77 s [niks3-go-unit-tests] === RUN TestScriptTokenCachesUntilRefresh
  64. 1.77 s [niks3-go-unit-tests] === PAUSE TestScriptTokenCachesUntilRefresh
  65. 1.77 s [niks3-go-unit-tests] === RUN TestScriptTokenEmptyToken
  66. 1.77 s [niks3-go-unit-tests] === PAUSE TestScriptTokenEmptyToken
  67. 1.77 s [niks3-go-unit-tests] === RUN TestScriptTokenBadJSON
  68. 1.77 s [niks3-go-unit-tests] === PAUSE TestScriptTokenBadJSON
  69. 1.77 s [niks3-go-unit-tests] === RUN TestScriptTokenScriptFails
  70. 1.77 s [niks3-go-unit-tests] === PAUSE TestScriptTokenScriptFails
  71. 1.77 s [niks3-go-unit-tests] === RUN TestScriptTokenEmptyCommand
  72. 1.77 s [niks3-go-unit-tests] === PAUSE TestScriptTokenEmptyCommand
  73. 1.77 s [niks3-go-unit-tests] === CONT TestDoServerRequestAttachesToken
  74. 1.77 s [niks3-go-unit-tests] === CONT TestFileTokenMissing
  75. 1.77 s [niks3-go-unit-tests] === CONT TestResolveStorePath
  76. 1.77 s [niks3-go-unit-tests] === CONT TestFileTokenReadsAndCaches
  77. 1.77 s [niks3-go-unit-tests] --- PASS: TestFileTokenMissing (0.00s)
  78. 1.77 s [niks3-go-unit-tests] === CONT TestConvertHashToNix32
  79. 1.77 s [niks3-go-unit-tests] === RUN TestConvertHashToNix32/SRI_format_to_Nix32
  80. 1.77 s [niks3-go-unit-tests] === PAUSE TestConvertHashToNix32/SRI_format_to_Nix32
  81. 1.77 s [niks3-go-unit-tests] === CONT TestStaticToken
  82. 1.77 s [niks3-go-unit-tests] --- PASS: TestStaticToken (0.00s)
  83. 1.77 s [niks3-go-unit-tests] === CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess
  84. 1.77 s [niks3-go-unit-tests] --- PASS: TestResolveStorePath (0.00s)
  85. 1.77 s [niks3-go-unit-tests] === CONT TestRateLimiterFeedback
  86. 1.77 s [niks3-go-unit-tests] === CONT TestSetClientTLSErrors
  87. 1.77 s [niks3-go-unit-tests] === RUN TestRateLimiterFeedback/429_enables_limiter
  88. 1.77 s [niks3-go-unit-tests] === PAUSE TestRateLimiterFeedback/429_enables_limiter
  89. 1.77 s [niks3-go-unit-tests] === RUN TestRateLimiterFeedback/503_enables_limiter
  90. 1.77 s [niks3-go-unit-tests] === PAUSE TestRateLimiterFeedback/503_enables_limiter
  91. 1.77 s [niks3-go-unit-tests] === CONT TestSetClientTLSDoesNotMutateDefaultTransport
  92. 1.77 s [niks3-go-unit-tests] 2026/07/18 13:59:29 WARN Rate limiter enabled after throttle name=server-test rate=5
  93. 1.77 s [niks3-go-unit-tests] === CONT TestSetClientTLS
  94. 1.77 s [niks3-go-unit-tests] --- PASS: TestFileTokenReadsAndCaches (0.00s)
  95. 1.77 s [niks3-go-unit-tests] === CONT TestPathInfoCACompatibility
  96. 1.77 s [niks3-go-unit-tests] === CONT TestShellSplitErrors
  97. 1.77 s [niks3-go-unit-tests] --- PASS: TestShellSplitErrors (0.00s)
  98. 1.77 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSONMultiplePaths
  99. 1.77 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths
  100. 1.77 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths
  101. 1.77 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths
  102. 1.77 s [niks3-go-unit-tests] === RUN TestPathInfoCACompatibility/null_ca_field
  103. 1.77 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths
  104. 1.77 s [niks3-go-unit-tests] === CONT TestScriptTokenScriptFails
  105. 1.77 s [niks3-go-unit-tests] === CONT TestShellSplit
  106. 1.77 s [niks3-go-unit-tests] --- PASS: TestShellSplit (0.00s)
  107. 1.77 s [niks3-go-unit-tests] === CONT TestPathInfoHashCompatibility
  108. 1.77 s [niks3-go-unit-tests] === CONT TestScriptTokenEmptyCommand
  109. 1.77 s [niks3-go-unit-tests] --- PASS: TestScriptTokenEmptyCommand (0.00s)
  110. 1.77 s [niks3-go-unit-tests] === CONT TestGetStorePathHash
  111. 1.77 s [niks3-go-unit-tests] === RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)
  112. 1.77 s [niks3-go-unit-tests] === CONT TestScriptTokenBadJSON
  113. 1.77 s [niks3-go-unit-tests] --- PASS: TestDoServerRequestAttachesToken (0.00s)
  114. 1.77 s [niks3-go-unit-tests] === CONT TestScriptTokenNoExpiryRerunsEveryCall
  115. 1.77 s [niks3-go-unit-tests] === RUN TestRateLimiterFeedback/200_does_not_enable_limiter
  116. 1.77 s [niks3-go-unit-tests] === PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter
  117. 1.77 s [niks3-go-unit-tests] === RUN TestRateLimiterFeedback/400_does_not_enable_limiter
  118. 1.77 s [niks3-go-unit-tests] === PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter
  119. 1.77 s [niks3-go-unit-tests] === PAUSE TestPathInfoCACompatibility/null_ca_field
  120. 1.77 s [niks3-go-unit-tests] === CONT TestScriptTokenCachesUntilRefresh
  121. 1.77 s [niks3-go-unit-tests] --- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)
  122. 1.77 s [niks3-go-unit-tests] === CONT TestFileTokenEmpty
  123. 1.77 s [niks3-go-unit-tests] === RUN TestPathInfoCACompatibility/old_string_format_-_text
  124. 1.77 s [niks3-go-unit-tests] === PAUSE TestPathInfoCACompatibility/old_string_format_-_text
  125. 1.77 s [niks3-go-unit-tests] === RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive
  126. 1.77 s [niks3-go-unit-tests] === PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive
  127. 1.77 s [niks3-go-unit-tests] === RUN TestPathInfoCACompatibility/new_structured_format_-_text
  128. 1.77 s [niks3-go-unit-tests] === PAUSE TestPathInfoCACompatibility/new_structured_format_-_text
  129. 1.77 s [niks3-go-unit-tests] === RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method
  130. 1.77 s [niks3-go-unit-tests] === PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method
  131. 1.77 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSON
  132. 1.77 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSON/Nix_format
  133. 1.77 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSON/Nix_format
  134. 1.77 s [niks3-go-unit-tests] === CONT TestDumpPathSingleFile
  135. 1.77 s [niks3-go-unit-tests] --- PASS: TestScriptTokenScriptFails (0.00s)
  136. 1.77 s [niks3-go-unit-tests] === CONT TestEncodeNixBase32WithRealHash
  137. 1.77 s [niks3-go-unit-tests] --- PASS: TestFileTokenEmpty (0.00s)
  138. 1.77 s [niks3-go-unit-tests] === CONT TestDumpPathWriterError
  139. 1.77 s [niks3-go-unit-tests] --- PASS: TestEncodeNixBase32WithRealHash (0.00s)
  140. 1.77 s [niks3-go-unit-tests] === CONT TestEncodeNixBase32
  141. 1.77 s [niks3-go-unit-tests] === RUN TestSetClientTLS/rejects_connection_without_client_cert
  142. 1.77 s [niks3-go-unit-tests] === RUN TestEncodeNixBase32/test_string_hash
  143. 1.77 s [niks3-go-unit-tests] === PAUSE TestSetClientTLS/rejects_connection_without_client_cert
  144. 1.77 s [niks3-go-unit-tests] === RUN TestConvertHashToNix32/already_Nix32_format
  145. 1.77 s [niks3-go-unit-tests] === RUN TestGetStorePathHash/valid_store_path
  146. 1.77 s [niks3-go-unit-tests] === RUN TestSetClientTLSErrors/missing_cert_file
  147. 1.77 s [niks3-go-unit-tests] === CONT TestDoWithRetry_BodyReplayedViaGetBody
  148. 1.77 s [niks3-go-unit-tests] === PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)
  149. 1.77 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSON/Lix_format
  150. 1.77 s [niks3-go-unit-tests] === RUN TestSetClientTLS/succeeds_with_client_cert_and_CA
  151. 1.77 s [niks3-go-unit-tests] === PAUSE TestConvertHashToNix32/already_Nix32_format
  152. 1.77 s [niks3-go-unit-tests] === RUN TestConvertHashToNix32/invalid_format
  153. 1.77 s [niks3-go-unit-tests] --- PASS: TestScriptTokenBadJSON (0.00s)
  154. 1.77 s [niks3-go-unit-tests] === CONT TestUploadMultipart_SupersededByPeer
  155. 1.77 s [niks3-go-unit-tests] === RUN TestPathInfoHashCompatibility/old_string_format_with_colon
  156. 1.77 s [niks3-go-unit-tests] === PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon
  157. 1.77 s [niks3-go-unit-tests] === PAUSE TestConvertHashToNix32/invalid_format
  158. 1.77 s [niks3-go-unit-tests] === RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI
  159. 1.77 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSON/Lix_format
  160. 1.77 s [niks3-go-unit-tests] === RUN TestUploadMultipart_SupersededByPeer/exists
  161. 1.77 s [niks3-go-unit-tests] === PAUSE TestUploadMultipart_SupersededByPeer/exists
  162. 1.77 s [niks3-go-unit-tests] === RUN TestUploadMultipart_SupersededByPeer/missing
  163. 1.77 s [niks3-go-unit-tests] === PAUSE TestUploadMultipart_SupersededByPeer/missing
  164. 1.77 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSON/empty_input
  165. 1.77 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSON/empty_input
  166. 1.77 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSON/whitespace_only
  167. 1.77 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSON/whitespace_only
  168. 1.77 s [niks3-go-unit-tests] === PAUSE TestSetClientTLSErrors/missing_cert_file
  169. 1.77 s [niks3-go-unit-tests] === RUN TestSetClientTLSErrors/missing_key_file
  170. 1.77 s [niks3-go-unit-tests] === PAUSE TestSetClientTLSErrors/missing_key_file
  171. 1.78 s [niks3-go-unit-tests] === RUN TestSetClientTLSErrors/missing_ca_file
  172. 1.78 s [niks3-go-unit-tests] === PAUSE TestEncodeNixBase32/test_string_hash
  173. 1.78 s [niks3-go-unit-tests] === PAUSE TestGetStorePathHash/valid_store_path
  174. 1.78 s [niks3-go-unit-tests] === RUN TestEncodeNixBase32/empty_input
  175. 1.78 s [niks3-go-unit-tests] === PAUSE TestEncodeNixBase32/empty_input
  176. 1.78 s [niks3-go-unit-tests] === PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA
  177. 1.78 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSON/invalid_JSON
  178. 1.78 s [niks3-go-unit-tests] === RUN TestSetClientTLS/preserves_debug_logging_transport
  179. 1.78 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSON/invalid_JSON
  180. 1.78 s [niks3-go-unit-tests] === PAUSE TestSetClientTLS/preserves_debug_logging_transport
  181. 1.78 s [niks3-go-unit-tests] === PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI
  182. 1.78 s [niks3-go-unit-tests] === RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512
  183. 1.78 s [niks3-go-unit-tests] === PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512
  184. 1.78 s [niks3-go-unit-tests] === PAUSE TestSetClientTLSErrors/missing_ca_file
  185. 1.78 s [niks3-go-unit-tests] === RUN TestSetClientTLSErrors/invalid_ca_file
  186. 1.78 s [niks3-go-unit-tests] === PAUSE TestSetClientTLSErrors/invalid_ca_file
  187. 1.78 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths
  188. 1.78 s [niks3-go-unit-tests] 2026/07/18 13:59:29 WARN Rate limiter enabled after throttle name=server-test rate=5
  189. 1.78 s [niks3-go-unit-tests] 2026/07/18 13:59:29 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:45143
  190. 1.78 s [niks3-go-unit-tests] === CONT TestRateLimiterFeedback/400_does_not_enable_limiter
  191. 1.78 s [niks3-go-unit-tests] === CONT TestRateLimiterFeedback/429_enables_limiter
  192. 1.78 s [niks3-go-unit-tests] 2026/07/18 13:59:29 WARN Rate limiter backed off name=server-test rate=5
  193. 1.78 s [niks3-go-unit-tests] 2026/07/18 13:59:29 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:45143
  194. 1.78 s [niks3-go-unit-tests] --- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)
  195. 1.78 s [niks3-go-unit-tests] === CONT TestCaseHackSuffix
  196. 1.78 s [niks3-go-unit-tests] === CONT TestRateLimiterFeedback/200_does_not_enable_limiter
  197. 1.78 s [niks3-go-unit-tests] 2026/07/18 13:59:29 WARN Rate limiter enabled after throttle name=server-test rate=5
  198. 1.78 s [niks3-go-unit-tests] 2026/07/18 13:59:29 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:37661
  199. 1.78 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR
  200. 1.78 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/zero_stays_at_minimum
  201. 1.78 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/zero_stays_at_minimum
  202. 1.78 s [niks3-go-unit-tests] === CONT TestRateLimiterFeedback/503_enables_limiter
  203. 1.78 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths
  204. 1.78 s [niks3-go-unit-tests] 2026/07/18 13:59:29 WARN Rate limiter backed off name=server-test rate=5
  205. 1.78 s [niks3-go-unit-tests] === CONT TestScriptTokenEmptyToken
  206. 1.78 s [niks3-go-unit-tests] === RUN TestGetStorePathHash/basename_without_hyphen_should_error
  207. 1.78 s [niks3-go-unit-tests] === PAUSE TestGetStorePathHash/basename_without_hyphen_should_error
  208. 1.78 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)
  209. 1.78 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)
  210. 1.78 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)
  211. 1.78 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/small_stays_at_minimum
  212. 1.78 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/small_stays_at_minimum
  213. 1.78 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/80_GiB_fits_at_minimum
  214. 1.78 s [niks3-go-unit-tests] === CONT TestDumpPathMatchesNix
  215. 1.78 s [niks3-go-unit-tests] === CONT TestPathInfoCACompatibility/null_ca_field
  216. 1.78 s [niks3-go-unit-tests] === CONT TestPathInfoCACompatibility/new_structured_format_-_text
  217. 1.78 s [niks3-go-unit-tests] === RUN TestGetStorePathHash/hash_with_invalid_characters_should_error
  218. 1.78 s [niks3-go-unit-tests] === PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error
  219. 1.78 s [niks3-go-unit-tests] === RUN TestGetStorePathHash/hash_with_wrong_length_should_error
  220. 1.78 s [niks3-go-unit-tests] === PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error
  221. 1.78 s [niks3-go-unit-tests] === CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method
  222. 1.78 s [niks3-go-unit-tests] === CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive
  223. 1.78 s [niks3-go-unit-tests] === CONT TestConvertHashToNix32/SRI_format_to_Nix32
  224. 1.78 s [niks3-go-unit-tests] === CONT TestConvertHashToNix32/invalid_format
  225. 1.78 s [niks3-go-unit-tests] === CONT TestConvertHashToNix32/already_Nix32_format
  226. 1.78 s [niks3-go-unit-tests] === CONT TestUploadMultipart_SupersededByPeer/missing
  227. 1.78 s [niks3-go-unit-tests] === CONT TestPathInfoCACompatibility/old_string_format_-_text
  228. 1.92 s [niks3-go-unit-tests] --- PASS: TestConvertHashToNix32 (0.00s)
  229. 1.92 s [niks3-go-unit-tests] --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)
  230. 1.92 s [niks3-go-unit-tests] --- PASS: TestConvertHashToNix32/invalid_format (0.00s)
  231. 1.92 s [niks3-go-unit-tests] --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)
  232. 1.92 s [niks3-go-unit-tests] === CONT TestUploadMultipart_SupersededByPeer/exists
  233. 1.92 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum
  234. 1.92 s [niks3-go-unit-tests] === CONT TestEncodeNixBase32/test_string_hash
  235. 1.92 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/115_GiB_needs_larger_parts
  236. 1.92 s [niks3-go-unit-tests] --- PASS: TestPathInfoCACompatibility (0.00s)
  237. 1.92 s [niks3-go-unit-tests] --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)
  238. 1.92 s [niks3-go-unit-tests] --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)
  239. 1.92 s [niks3-go-unit-tests] --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)
  240. 1.92 s [niks3-go-unit-tests] --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)
  241. 1.92 s [niks3-go-unit-tests] --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)
  242. 1.92 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts
  243. 1.92 s [niks3-go-unit-tests] === CONT TestEncodeNixBase32/empty_input
  244. 1.92 s [niks3-go-unit-tests] --- PASS: TestEncodeNixBase32 (0.00s)
  245. 1.92 s [niks3-go-unit-tests] --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)
  246. 1.92 s [niks3-go-unit-tests] --- PASS: TestEncodeNixBase32/empty_input (0.00s)
  247. 1.92 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/1_TiB
  248. 1.92 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/1_TiB
  249. 1.92 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/5_TiB_S3_max_object
  250. 1.92 s [niks3-go-unit-tests] --- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.15s)
  251. 1.92 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/5_TiB_S3_max_object
  252. 1.92 s [niks3-go-unit-tests] === CONT TestSetClientTLS/rejects_connection_without_client_cert
  253. 1.92 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/capped_at_5_GiB
  254. 1.92 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSON/Nix_format
  255. 1.92 s [niks3-go-unit-tests] === CONT TestSetClientTLS/preserves_debug_logging_transport
  256. 1.92 s [niks3-go-unit-tests] --- PASS: TestScriptTokenCachesUntilRefresh (0.15s)
  257. 1.92 s [niks3-go-unit-tests] === CONT TestSetClientTLS/succeeds_with_client_cert_and_CA
  258. 1.92 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/capped_at_5_GiB
  259. 1.92 s [niks3-go-unit-tests] 2026/07/18 13:59:30 WARN Rate limiter enabled after throttle name=server-test rate=5
  260. 1.92 s [niks3-go-unit-tests] 2026/07/18 13:59:30 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:33305
  261. 1.92 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSON/whitespace_only
  262. 1.92 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSON/invalid_JSON
  263. 1.92 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSON/empty_input
  264. 1.92 s [niks3-go-unit-tests] --- PASS: TestDumpPathSingleFile (0.15s)
  265. 1.92 s [niks3-go-unit-tests] === CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)
  266. 1.92 s [niks3-go-unit-tests] === CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI
  267. 1.92 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSON/Lix_format
  268. 1.92 s [niks3-go-unit-tests] 2026/07/18 13:59:30 WARN Rate limiter backed off name=server-test rate=5
  269. 1.92 s [niks3-go-unit-tests] === CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512
  270. 1.92 s [niks3-go-unit-tests] === CONT TestPathInfoHashCompatibility/old_string_format_with_colon
  271. 1.92 s [niks3-go-unit-tests] === CONT TestSetClientTLSErrors/missing_cert_file
  272. 1.92 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSON (0.00s)
  273. 1.92 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)
  274. 1.92 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)
  275. 1.92 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)
  276. 1.92 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSON/empty_input (0.00s)
  277. 1.92 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)
  278. 1.92 s [niks3-go-unit-tests] === CONT TestSetClientTLSErrors/missing_key_file
  279. 1.92 s [niks3-go-unit-tests] === CONT TestSetClientTLSErrors/invalid_ca_file
  280. 1.92 s [niks3-go-unit-tests] --- PASS: TestPathInfoHashCompatibility (0.00s)
  281. 1.92 s [niks3-go-unit-tests] --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)
  282. 1.92 s [niks3-go-unit-tests] --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)
  283. 1.92 s [niks3-go-unit-tests] --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)
  284. 1.92 s [niks3-go-unit-tests] --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)
  285. 1.92 s [niks3-go-unit-tests] === CONT TestSetClientTLSErrors/missing_ca_file
  286. 1.92 s [niks3-go-unit-tests] === CONT TestGetStorePathHash/valid_store_path
  287. 1.92 s [niks3-go-unit-tests] --- PASS: TestRateLimiterFeedback (0.00s)
  288. 1.92 s [niks3-go-unit-tests] --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)
  289. 1.92 s [niks3-go-unit-tests] --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)
  290. 1.92 s [niks3-go-unit-tests] --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)
  291. 1.92 s [niks3-go-unit-tests] --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.15s)
  292. 1.92 s [niks3-go-unit-tests] === CONT TestGetStorePathHash/hash_with_wrong_length_should_error
  293. 1.92 s [niks3-go-unit-tests] === CONT TestGetStorePathHash/basename_without_hyphen_should_error
  294. 1.92 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/zero_stays_at_minimum
  295. 1.92 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/1_TiB
  296. 1.92 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/115_GiB_needs_larger_parts
  297. 1.92 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/80_GiB_fits_at_minimum
  298. 1.92 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/5_TiB_S3_max_object
  299. 1.92 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/small_stays_at_minimum
  300. 1.92 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/capped_at_5_GiB
  301. 1.92 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR (0.15s)
  302. 1.92 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)
  303. 1.92 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/1_TiB (0.00s)
  304. 1.92 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)
  305. 1.92 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)
  306. 1.92 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)
  307. 1.92 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)
  308. 1.92 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)
  309. 1.92 s [niks3-go-unit-tests] --- PASS: TestCaseHackSuffix (0.15s)
  310. 1.92 s [niks3-go-unit-tests] --- PASS: TestScriptTokenEmptyToken (0.15s)
  311. 1.92 s [niks3-go-unit-tests] --- PASS: TestSetClientTLSErrors (0.00s)
  312. 1.92 s [niks3-go-unit-tests] --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)
  313. 1.92 s [niks3-go-unit-tests] --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)
  314. 1.92 s [niks3-go-unit-tests] --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)
  315. 1.92 s [niks3-go-unit-tests] --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)
  316. 1.92 s [niks3-go-unit-tests] === CONT TestGetStorePathHash/hash_with_invalid_characters_should_error
  317. 1.92 s [niks3-go-unit-tests] --- PASS: TestGetStorePathHash (0.00s)
  318. 1.92 s [niks3-go-unit-tests] --- PASS: TestGetStorePathHash/valid_store_path (0.00s)
  319. 1.92 s [niks3-go-unit-tests] --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)
  320. 1.92 s [niks3-go-unit-tests] --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)
  321. 1.92 s [niks3-go-unit-tests] --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)
  322. 1.92 s [niks3-go-unit-tests] --- PASS: TestUploadMultipart_SupersededByPeer (0.00s)
  323. 1.92 s [niks3-go-unit-tests] --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.15s)
  324. 1.92 s [niks3-go-unit-tests] --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)
  325. 1.92 s [niks3-go-unit-tests] 2026/07/18 13:59:30 http: TLS handshake error from 127.0.0.1:41078: remote error: tls: bad certificate
  326. 1.92 s [niks3-go-unit-tests] --- PASS: TestSetClientTLS (0.00s)
  327. 1.92 s [niks3-go-unit-tests] --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.00s)
  328. 1.92 s [niks3-go-unit-tests] --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)
  329. 1.92 s [niks3-go-unit-tests] --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)
  330. 1.93 s [niks3-go-unit-tests] --- PASS: TestDumpPathWriterError (0.16s)
  331. 1.96 s [niks3-go-unit-tests] --- PASS: TestDumpPathMatchesNix (0.19s)
  332. 2.77 s [niks3-go-unit-tests] --- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)
  333. 2.77 s [niks3-go-unit-tests] PASS
  334. 2.77 s [niks3-go-unit-tests] Running server tests...
  335. 2.79 s [niks3-go-unit-tests] The files belonging to this database system will be owned by user "nixbld".
  336. 2.79 s [niks3-go-unit-tests] This user must also own the server process.
  337. 2.79 s [niks3-go-unit-tests]
  338. 2.79 s [niks3-go-unit-tests] The database cluster will be initialized with locale "C".
  339. 2.79 s [niks3-go-unit-tests] The default database encoding has accordingly been set to "SQL_ASCII".
  340. 2.79 s [niks3-go-unit-tests] The default text search configuration will be set to "english".
  341. 2.79 s [niks3-go-unit-tests]
  342. 2.79 s [niks3-go-unit-tests] Data page checksums are enabled.
  343. 2.79 s [niks3-go-unit-tests]
  344. 2.79 s [niks3-go-unit-tests] creating directory /build/postgres317190682/data ... ok
  345. 2.79 s [niks3-go-unit-tests] creating subdirectories ... ok
  346. 2.79 s [niks3-go-unit-tests] selecting dynamic shared memory implementation ... posix
  347. 2.80 s [niks3-go-unit-tests] selecting default "max_connections" ... 100
  348. 2.82 s [niks3-go-unit-tests] selecting default "shared_buffers" ... 128MB
  349. 2.82 s [niks3-go-unit-tests] selecting default time zone ... UTC
  350. 2.82 s [niks3-go-unit-tests] creating configuration files ... ok
  351. 2.90 s [niks3-go-unit-tests] running bootstrap script ... ok
  352. 3.15 s [niks3-go-unit-tests] performing post-bootstrap initialization ... ok
  353. 3.34 s [niks3-go-unit-tests] syncing data to disk ... ok
  354. 3.34 s [niks3-go-unit-tests]
  355. 3.34 s [niks3-go-unit-tests] initdb: warning: enabling "trust" authentication for local connections
  356. 3.34 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.
  357. 3.34 s [niks3-go-unit-tests]
  358. 3.34 s [niks3-go-unit-tests] Success. You can now start the database server using:
  359. 3.34 s [niks3-go-unit-tests]
  360. 3.34 s [niks3-go-unit-tests] pg_ctl -D /build/postgres317190682/data -l logfile start
  361. 3.34 s [niks3-go-unit-tests]
  362. 3.34 s [niks3-go-unit-tests] /build/postgres317190682:5432 - no response
  363. 3.38 s [niks3-go-unit-tests] 2026-07-18 13:59:31.528 UTC [94] LOG: starting PostgreSQL 18.4 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit
  364. 3.39 s [niks3-go-unit-tests] 2026-07-18 13:59:31.535 UTC [94] LOG: listening on Unix socket "/build/postgres317190682/.s.PGSQL.5432"
  365. 3.43 s [niks3-go-unit-tests] 2026-07-18 13:59:31.578 UTC [101] LOG: database system was shut down at 2026-07-18 13:59:31 UTC
  366. 3.45 s [niks3-go-unit-tests] 2026-07-18 13:59:31.592 UTC [103] FATAL: the database system is starting up
  367. 3.45 s [niks3-go-unit-tests] /build/postgres317190682:5432 - rejecting connections
  368. 3.46 s [niks3-go-unit-tests] 2026-07-18 13:59:31.605 UTC [94] LOG: database system is ready to accept connections
  369. 3.72 s [niks3-go-unit-tests] /build/postgres317190682:5432 - accepting connections
  370. 3.72 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware
  371. 3.72 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware
  372. 3.72 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_MTLSProxyHeader
  373. 3.72 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_MTLSProxyHeader
  374. 3.72 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_MTLSBoundSubjects
  375. 3.72 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_MTLSBoundSubjects
  376. 3.72 s [niks3-go-unit-tests] === RUN TestService_ReadAuthMiddleware
  377. 3.72 s [niks3-go-unit-tests] === PAUSE TestService_ReadAuthMiddleware
  378. 3.72 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_OIDC
  379. 3.72 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_OIDC
  380. 3.72 s [niks3-go-unit-tests] === RUN TestCacheConfigHandler
  381. 3.72 s [niks3-go-unit-tests] === PAUSE TestCacheConfigHandler
  382. 3.72 s [niks3-go-unit-tests] === RUN TestCacheStatsHandler
  383. 3.72 s [niks3-go-unit-tests] === PAUSE TestCacheStatsHandler
  384. 3.72 s [niks3-go-unit-tests] === RUN TestClientCADerivations
  385. 3.72 s [niks3-go-unit-tests] === PAUSE TestClientCADerivations
  386. 3.72 s [niks3-go-unit-tests] === RUN TestClientErrorHandling
  387. 3.72 s [niks3-go-unit-tests] === PAUSE TestClientErrorHandling
  388. 3.72 s [niks3-go-unit-tests] === RUN TestClientIntegration
  389. 3.72 s [niks3-go-unit-tests] === PAUSE TestClientIntegration
  390. 3.72 s [niks3-go-unit-tests] === RUN TestClientMultipleUploads
  391. 3.72 s [niks3-go-unit-tests] === PAUSE TestClientMultipleUploads
  392. 3.72 s [niks3-go-unit-tests] === RUN TestClientWithDependencies
  393. 3.72 s [niks3-go-unit-tests] === PAUSE TestClientWithDependencies
  394. 3.72 s [niks3-go-unit-tests] === RUN TestPinProtectsFromGC
  395. 3.72 s [niks3-go-unit-tests] === PAUSE TestPinProtectsFromGC
  396. 3.72 s [niks3-go-unit-tests] === RUN TestGCAdvisoryLockBlocksConcurrentRun
  397. 3.72 s [niks3-go-unit-tests] {"timestamp":"2026-07-18T13:59:31.866992476Z","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(23)"}
  398. 3.73 s [niks3-go-unit-tests]
  399. 3.73 s [niks3-go-unit-tests] thread 'rustfs-worker' (135) panicked at /build/rustfs-1.0.0-beta.7-vendor/source-registry-0/reqwest-0.13.4/src/async_impl/client.rs:2507:38:
  400. 3.73 s [niks3-go-unit-tests] Client::new(): reqwest::Error { kind: Builder, source: General("No CA certificates were loaded from the system") }
  401. 3.73 s [niks3-go-unit-tests] note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
  402. 3.85 s [niks3-go-unit-tests] 2026-07-18 13:59:32.000 UTC [156] ERROR: relation "goose_db_version" does not exist at character 36
  403. 3.85 s [niks3-go-unit-tests] 2026-07-18 13:59:32.000 UTC [156] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  404. 3.87 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20241026095416_initial_model.sql (10.8ms)
  405. 3.88 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20251210153512_drop_unused_gin_index.sql (4.77ms)
  406. 3.89 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20251218171726_add_pins.sql (5.68ms)
  407. 3.89 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20260628120000_add_object_size_and_stats.sql (6.66ms)
  408. 3.89 s [niks3-go-unit-tests] 2026/07/18 13:59:32 goose: successfully migrated database to version: 20260628120000
  409. 3.90 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 1_commit_pending_closure.sql (4.43ms)
  410. 3.90 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 2_object_stats_trigger.sql (4.55ms)
  411. 3.90 s [niks3-go-unit-tests] 2026/07/18 13:59:32 goose: up to current file version: 2
  412. 3.91 s [niks3-go-unit-tests] --- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.25s)
  413. 3.91 s [niks3-go-unit-tests] === RUN TestGCBugBareHashReferences
  414. 3.91 s [niks3-go-unit-tests] === PAUSE TestGCBugBareHashReferences
  415. 3.91 s [niks3-go-unit-tests] === RUN TestGCMetrics
  416. 3.91 s [niks3-go-unit-tests] === PAUSE TestGCMetrics
  417. 3.91 s [niks3-go-unit-tests] === RUN TestGCTaskStore_StartNew
  418. 3.91 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_StartNew
  419. 3.91 s [niks3-go-unit-tests] === RUN TestGCTaskStore_DeduplicateSameParams
  420. 3.91 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_DeduplicateSameParams
  421. 3.91 s [niks3-go-unit-tests] === RUN TestGCTaskStore_ConflictDifferentParams
  422. 3.91 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_ConflictDifferentParams
  423. 3.91 s [niks3-go-unit-tests] === RUN TestGCTaskStore_GetEmpty
  424. 3.91 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_GetEmpty
  425. 3.91 s [niks3-go-unit-tests] === RUN TestGCTaskStore_GetReturnsLatest
  426. 3.91 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_GetReturnsLatest
  427. 3.91 s [niks3-go-unit-tests] === RUN TestGCTaskStore_CompletedAllowsNewTask
  428. 3.91 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_CompletedAllowsNewTask
  429. 3.91 s [niks3-go-unit-tests] === RUN TestGCTaskStore_PhaseUpdates
  430. 3.91 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_PhaseUpdates
  431. 3.91 s [niks3-go-unit-tests] === RUN TestGCTaskStore_Fail
  432. 3.91 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_Fail
  433. 3.91 s [niks3-go-unit-tests] === RUN TestGracefulShutdownDrainsInflight
  434. 3.91 s [niks3-go-unit-tests] === PAUSE TestGracefulShutdownDrainsInflight
  435. 3.91 s [niks3-go-unit-tests] === RUN TestService_healthCheckHandler
  436. 3.91 s [niks3-go-unit-tests] === PAUSE TestService_healthCheckHandler
  437. 3.91 s [niks3-go-unit-tests] === RUN TestGenerateLandingPage
  438. 3.91 s [niks3-go-unit-tests] === PAUSE TestGenerateLandingPage
  439. 3.91 s [niks3-go-unit-tests] === RUN TestNARDeduplicationMetadataUploadBug
  440. 3.91 s [niks3-go-unit-tests] === PAUSE TestNARDeduplicationMetadataUploadBug
  441. 3.91 s [niks3-go-unit-tests] === RUN TestMetricsInventory
  442. 3.91 s [niks3-go-unit-tests] === PAUSE TestMetricsInventory
  443. 3.91 s [niks3-go-unit-tests] === RUN TestService_NativeMTLS
  444. 3.91 s [niks3-go-unit-tests] === PAUSE TestService_NativeMTLS
  445. 3.91 s [niks3-go-unit-tests] === RUN TestServerTLSConfig
  446. 3.91 s [niks3-go-unit-tests] === PAUSE TestServerTLSConfig
  447. 3.91 s [niks3-go-unit-tests] === RUN TestMultipartCleanup
  448. 3.91 s [niks3-go-unit-tests] === PAUSE TestMultipartCleanup
  449. 3.91 s [niks3-go-unit-tests] === RUN TestObjectStatsTrigger
  450. 3.91 s [niks3-go-unit-tests] === PAUSE TestObjectStatsTrigger
  451. 3.91 s [niks3-go-unit-tests] === RUN TestOrphanedObjectsGC
  452. 3.91 s [niks3-go-unit-tests] === PAUSE TestOrphanedObjectsGC
  453. 3.91 s [niks3-go-unit-tests] === RUN TestOrphanedObjectsGCStressTest
  454. 3.91 s [niks3-go-unit-tests] === PAUSE TestOrphanedObjectsGCStressTest
  455. 3.91 s [niks3-go-unit-tests] === RUN TestResurrectedObjectNotDeleted
  456. 3.91 s [niks3-go-unit-tests] === PAUSE TestResurrectedObjectNotDeleted
  457. 3.91 s [niks3-go-unit-tests] === RUN TestParseSingleRange
  458. 3.91 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange
  459. 3.91 s [niks3-go-unit-tests] === RUN TestIsValidCachePath
  460. 3.91 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath
  461. 3.91 s [niks3-go-unit-tests] === RUN TestReadProxyNarinfo
  462. 3.91 s [niks3-go-unit-tests] === PAUSE TestReadProxyNarinfo
  463. 3.91 s [niks3-go-unit-tests] === RUN TestReadProxyNarinfoAlreadyDecompressed
  464. 3.91 s [niks3-go-unit-tests] === PAUSE TestReadProxyNarinfoAlreadyDecompressed
  465. 3.91 s [niks3-go-unit-tests] === RUN TestReadProxyNarStreaming
  466. 3.91 s [niks3-go-unit-tests] === PAUSE TestReadProxyNarStreaming
  467. 3.91 s [niks3-go-unit-tests] === RUN TestReadProxy404
  468. 3.91 s [niks3-go-unit-tests] === PAUSE TestReadProxy404
  469. 3.91 s [niks3-go-unit-tests] === RUN TestReadProxyInvalidPath
  470. 3.91 s [niks3-go-unit-tests] === PAUSE TestReadProxyInvalidPath
  471. 3.91 s [niks3-go-unit-tests] === RUN TestReadProxyHead
  472. 3.91 s [niks3-go-unit-tests] === PAUSE TestReadProxyHead
  473. 3.91 s [niks3-go-unit-tests] === RUN TestReadProxyConditionalGet
  474. 3.91 s [niks3-go-unit-tests] === PAUSE TestReadProxyConditionalGet
  475. 3.91 s [niks3-go-unit-tests] === RUN TestReadProxyRootRedirectsToIndexHTML
  476. 3.91 s [niks3-go-unit-tests] === PAUSE TestReadProxyRootRedirectsToIndexHTML
  477. 3.91 s [niks3-go-unit-tests] === RUN TestReadProxyDisabled
  478. 3.91 s [niks3-go-unit-tests] === PAUSE TestReadProxyDisabled
  479. 3.91 s [niks3-go-unit-tests] === RUN TestReadProxyRangeRequest
  480. 3.91 s [niks3-go-unit-tests] === PAUSE TestReadProxyRangeRequest
  481. 3.91 s [niks3-go-unit-tests] === RUN TestRedundantMultipartUpload
  482. 3.91 s [niks3-go-unit-tests] === PAUSE TestRedundantMultipartUpload
  483. 3.91 s [niks3-go-unit-tests] === RUN TestCompleteMultipartUpload_ErrorButObjectExists
  484. 3.91 s [niks3-go-unit-tests] === PAUSE TestCompleteMultipartUpload_ErrorButObjectExists
  485. 3.91 s [niks3-go-unit-tests] === RUN TestCompletedNarNotReofferedAcrossClosures
  486. 3.91 s [niks3-go-unit-tests] === PAUSE TestCompletedNarNotReofferedAcrossClosures
  487. 3.91 s [niks3-go-unit-tests] === RUN TestService_Rustfstest
  488. 3.91 s [niks3-go-unit-tests] === PAUSE TestService_Rustfstest
  489. 3.91 s [niks3-go-unit-tests] === RUN TestSystemdListenerNotActivated
  490. 3.91 s [niks3-go-unit-tests] --- PASS: TestSystemdListenerNotActivated (0.00s)
  491. 3.91 s [niks3-go-unit-tests] === RUN TestWatchdogBeatsWhenHealthy
  492. 3.93 s [niks3-go-unit-tests] --- PASS: TestWatchdogBeatsWhenHealthy (0.02s)
  493. 3.93 s [niks3-go-unit-tests] === RUN TestWatchdogSkipsWhenUnhealthy
  494. 3.95 s [niks3-go-unit-tests] 2026/07/18 13:59:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  495. 3.97 s [niks3-go-unit-tests] 2026/07/18 13:59:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  496. 3.99 s [niks3-go-unit-tests] 2026/07/18 13:59:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  497. 4.01 s [niks3-go-unit-tests] 2026/07/18 13:59:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  498. 4.03 s [niks3-go-unit-tests] 2026/07/18 13:59:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  499. 4.05 s [niks3-go-unit-tests] 2026/07/18 13:59:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  500. 4.07 s [niks3-go-unit-tests] 2026/07/18 13:59:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  501. 4.09 s [niks3-go-unit-tests] 2026/07/18 13:59:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  502. 4.11 s [niks3-go-unit-tests] 2026/07/18 13:59:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  503. 4.13 s [niks3-go-unit-tests] 2026/07/18 13:59:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  504. 4.13 s [niks3-go-unit-tests] --- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)
  505. 4.13 s [niks3-go-unit-tests] === RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle
  506. 4.13 s [niks3-go-unit-tests] === PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle
  507. 4.13 s [niks3-go-unit-tests] === RUN TestProxyWriteTimeout
  508. 4.13 s [niks3-go-unit-tests] === PAUSE TestProxyWriteTimeout
  509. 4.13 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey
  510. 4.13 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey
  511. 4.13 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectInvalidKeys
  512. 4.13 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectInvalidKeys
  513. 4.13 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectOversizedBody
  514. 4.13 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectOversizedBody
  515. 4.13 s [niks3-go-unit-tests] === RUN TestService_cleanupPendingClosuresHandler
  516. 4.13 s [niks3-go-unit-tests] === PAUSE TestService_cleanupPendingClosuresHandler
  517. 4.13 s [niks3-go-unit-tests] === RUN TestService_createPendingClosureHandler
  518. 4.13 s [niks3-go-unit-tests] === PAUSE TestService_createPendingClosureHandler
  519. 4.13 s [niks3-go-unit-tests] === RUN TestService_verifyS3Integrity
  520. 4.13 s [niks3-go-unit-tests] === PAUSE TestService_verifyS3Integrity
  521. 4.13 s [niks3-go-unit-tests] === RUN TestCompleteMultipartUnregistered
  522. 4.13 s [niks3-go-unit-tests] === PAUSE TestCompleteMultipartUnregistered
  523. 4.13 s [niks3-go-unit-tests] === RUN TestCreatePendingClosure_SmallNARUsesSimplePUT
  524. 4.13 s [niks3-go-unit-tests] === PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT
  525. 4.13 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware
  526. 4.13 s [niks3-go-unit-tests] === CONT TestService_cleanupPendingClosuresHandler
  527. 4.13 s [niks3-go-unit-tests] === CONT TestGCTaskStore_GetReturnsLatest
  528. 4.13 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)
  529. 4.13 s [niks3-go-unit-tests] === CONT TestService_Rustfstest
  530. 4.13 s [niks3-go-unit-tests] === CONT TestReadProxyNarinfo
  531. 4.13 s [niks3-go-unit-tests] === CONT TestRedundantMultipartUpload
  532. 4.13 s [niks3-go-unit-tests] === CONT TestCreatePendingClosure_SmallNARUsesSimplePUT
  533. 4.13 s [niks3-go-unit-tests] === CONT TestCompleteMultipartUnregistered
  534. 4.13 s [niks3-go-unit-tests] === CONT TestService_verifyS3Integrity
  535. 4.13 s [niks3-go-unit-tests] === CONT TestService_createPendingClosureHandler
  536. 4.13 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectOversizedBody
  537. 4.13 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectInvalidKeys
  538. 4.13 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey
  539. 4.13 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/narinfo
  540. 4.13 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/narinfo
  541. 4.13 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/nar_zst
  542. 4.13 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/nar_zst
  543. 4.13 s [niks3-go-unit-tests] === CONT TestProxyWriteTimeout
  544. 4.13 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/nar_xz
  545. 4.13 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/nar_xz
  546. 4.13 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/nar_plain
  547. 4.13 s [niks3-go-unit-tests] === CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle
  548. 4.13 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/nar_plain
  549. 4.13 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/listing
  550. 4.13 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/listing
  551. 4.13 s [niks3-go-unit-tests] === RUN TestProxyWriteTimeout/narinfo
  552. 4.13 s [niks3-go-unit-tests] === PAUSE TestProxyWriteTimeout/narinfo
  553. 4.13 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info
  554. 4.13 s [niks3-go-unit-tests] === RUN TestProxyWriteTimeout/1_GiB_nar
  555. 4.13 s [niks3-go-unit-tests] === PAUSE TestProxyWriteTimeout/1_GiB_nar
  556. 4.13 s [niks3-go-unit-tests] === RUN TestProxyWriteTimeout/10_GiB_nar
  557. 4.13 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/build_log
  558. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/build_log
  559. 4.26 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info
  560. 4.26 s [niks3-go-unit-tests] === PAUSE TestProxyWriteTimeout/10_GiB_nar
  561. 4.26 s [niks3-go-unit-tests] === RUN TestProxyWriteTimeout/unknown_size
  562. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/build_log_home-manager_file
  563. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/build_log_home-manager_file
  564. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/build_log_plus_in_name
  565. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/build_log_plus_in_name
  566. 4.26 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal
  567. 4.26 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal
  568. 4.26 s [niks3-go-unit-tests] === PAUSE TestProxyWriteTimeout/unknown_size
  569. 4.26 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key
  570. 4.26 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key
  571. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/build_log_question_mark
  572. 4.26 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key
  573. 4.26 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key
  574. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/build_log_question_mark
  575. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/build_log_equals
  576. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/build_log_equals
  577. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/realisation
  578. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/realisation
  579. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/realisation_plus_in_output
  580. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/realisation_plus_in_output
  581. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/nix-cache-info
  582. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/nix-cache-info
  583. 4.26 s [niks3-go-unit-tests] === CONT TestParseSingleRange
  584. 4.26 s [niks3-go-unit-tests] === RUN TestParseSingleRange/none
  585. 4.26 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/none
  586. 4.26 s [niks3-go-unit-tests] === RUN TestParseSingleRange/unknown_unit
  587. 4.26 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/unknown_unit
  588. 4.26 s [niks3-go-unit-tests] === RUN TestParseSingleRange/multi-range_ignored
  589. 4.26 s [niks3-go-unit-tests] === CONT TestIsValidCachePath
  590. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/narinfo
  591. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/narinfo
  592. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/narinfo_all_nix_base32_chars
  593. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars
  594. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/nar_zst
  595. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/nar_zst
  596. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/nar_xz
  597. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/index.html
  598. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/index.html
  599. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/narinfo_key,_nar_type
  600. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/narinfo_key,_nar_type
  601. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/nar_key,_narinfo_type
  602. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/nar_key,_narinfo_type
  603. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/listing_key,_narinfo_type
  604. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/listing_key,_narinfo_type
  605. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/traversal
  606. 4.26 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/multi-range_ignored
  607. 4.26 s [niks3-go-unit-tests] === RUN TestParseSingleRange/malformed_no_dash
  608. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/nar_xz
  609. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/traversal
  610. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/traversal_nar
  611. 4.26 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/malformed_no_dash
  612. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/nar_bz2
  613. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/nar_bz2
  614. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/traversal_nar
  615. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/absolute
  616. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/absolute
  617. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/empty_key
  618. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/empty_key
  619. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/unknown_type
  620. 4.26 s [niks3-go-unit-tests] === RUN TestParseSingleRange/malformed_both_empty
  621. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/unknown_type
  622. 4.26 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/malformed_both_empty
  623. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/nar_uncompressed
  624. 4.26 s [niks3-go-unit-tests] === CONT TestResurrectedObjectNotDeleted
  625. 4.26 s [niks3-go-unit-tests] === RUN TestParseSingleRange/malformed_end_before_start
  626. 4.26 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/malformed_end_before_start
  627. 4.26 s [niks3-go-unit-tests] === RUN TestParseSingleRange/closed
  628. 4.26 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/closed
  629. 4.26 s [niks3-go-unit-tests] === RUN TestParseSingleRange/open-ended
  630. 4.26 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/open-ended
  631. 4.26 s [niks3-go-unit-tests] === RUN TestParseSingleRange/end_clamped_to_size
  632. 4.26 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/end_clamped_to_size
  633. 4.26 s [niks3-go-unit-tests] === RUN TestParseSingleRange/suffix
  634. 4.26 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/suffix
  635. 4.26 s [niks3-go-unit-tests] === RUN TestParseSingleRange/suffix_exceeds_size
  636. 4.26 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/suffix_exceeds_size
  637. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/nar_uncompressed
  638. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/ls
  639. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/ls
  640. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/log
  641. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/log
  642. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/realisation
  643. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/realisation
  644. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/nix-cache-info
  645. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/nix-cache-info
  646. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/index.html
  647. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/index.html
  648. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/traversal_parent
  649. 4.26 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/traversal_parent
  650. 4.26 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/traversal_in_middle
  651. 4.26 s [niks3-go-unit-tests] === RUN TestParseSingleRange/single_byte
  652. 4.26 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/single_byte
  653. 4.26 s [niks3-go-unit-tests] === RUN TestParseSingleRange/start_past_EOF
  654. 4.26 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/start_past_EOF
  655. 4.26 s [niks3-go-unit-tests] === RUN TestParseSingleRange/start_far_past_EOF
  656. 4.26 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/start_far_past_EOF
  657. 4.27 s [niks3-go-unit-tests] === CONT TestOrphanedObjectsGCStressTest
  658. 4.27 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/traversal_in_middle
  659. 4.27 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/invalid_char_e
  660. 4.27 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/invalid_char_e
  661. 4.27 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/invalid_char_u
  662. 4.27 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/invalid_char_u
  663. 4.27 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/random_path
  664. 4.27 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/random_path
  665. 4.27 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/empty
  666. 4.27 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/empty
  667. 4.27 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/leading_slash
  668. 4.27 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/leading_slash
  669. 4.27 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/wrong_extension
  670. 4.27 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/wrong_extension
  671. 4.27 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/short_hash
  672. 4.27 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/short_hash
  673. 4.27 s [niks3-go-unit-tests] === CONT TestOrphanedObjectsGC
  674. 4.33 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectOversizedBody/create_pending_closure
  675. 4.33 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure
  676. 4.33 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectOversizedBody/complete_multipart
  677. 4.33 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart
  678. 4.33 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectOversizedBody/request_more_parts
  679. 4.33 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts
  680. 4.33 s [niks3-go-unit-tests] === CONT TestObjectStatsTrigger
  681. 4.57 s [niks3-go-unit-tests] 2026-07-18 13:59:32.716 UTC [200] ERROR: relation "goose_db_version" does not exist at character 36
  682. 4.57 s [niks3-go-unit-tests] 2026-07-18 13:59:32.716 UTC [200] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  683. 4.57 s [niks3-go-unit-tests] 2026-07-18 13:59:32.716 UTC [202] ERROR: relation "goose_db_version" does not exist at character 36
  684. 4.57 s [niks3-go-unit-tests] 2026-07-18 13:59:32.716 UTC [202] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  685. 4.57 s [niks3-go-unit-tests] 2026-07-18 13:59:32.717 UTC [199] ERROR: relation "goose_db_version" does not exist at character 36
  686. 4.57 s [niks3-go-unit-tests] 2026-07-18 13:59:32.717 UTC [199] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  687. 4.57 s [niks3-go-unit-tests] 2026-07-18 13:59:32.717 UTC [201] ERROR: relation "goose_db_version" does not exist at character 36
  688. 4.57 s [niks3-go-unit-tests] 2026-07-18 13:59:32.717 UTC [201] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  689. 4.57 s [niks3-go-unit-tests] 2026-07-18 13:59:32.717 UTC [203] ERROR: relation "goose_db_version" does not exist at character 36
  690. 4.57 s [niks3-go-unit-tests] 2026-07-18 13:59:32.717 UTC [203] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  691. 4.57 s [niks3-go-unit-tests] 2026-07-18 13:59:32.717 UTC [204] ERROR: relation "goose_db_version" does not exist at character 36
  692. 4.57 s [niks3-go-unit-tests] 2026-07-18 13:59:32.717 UTC [204] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  693. 4.61 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20241026095416_initial_model.sql (17.1ms)
  694. 4.68 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20251210153512_drop_unused_gin_index.sql (69.4ms)
  695. 4.69 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20251218171726_add_pins.sql (15.41ms)
  696. 4.70 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20241026095416_initial_model.sql (92.2ms)
  697. 4.70 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20241026095416_initial_model.sql (103.23ms)
  698. 4.71 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20260628120000_add_object_size_and_stats.sql (14.86ms)
  699. 4.71 s [niks3-go-unit-tests] 2026/07/18 13:59:32 goose: successfully migrated database to version: 20260628120000
  700. 4.71 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20251210153512_drop_unused_gin_index.sql (7.57ms)
  701. 4.72 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20241026095416_initial_model.sql (108.61ms)
  702. 4.72 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20251210153512_drop_unused_gin_index.sql (15.38ms)
  703. 4.72 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20241026095416_initial_model.sql (107.81ms)
  704. 4.72 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20241026095416_initial_model.sql (108.77ms)
  705. 4.72 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20251218171726_add_pins.sql (16.45ms)
  706. 4.72 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 1_commit_pending_closure.sql (16.55ms)
  707. 4.73 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20251218171726_add_pins.sql (17.48ms)
  708. 4.73 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20251210153512_drop_unused_gin_index.sql (17.76ms)
  709. 4.73 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20251210153512_drop_unused_gin_index.sql (17.72ms)
  710. 4.73 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20251210153512_drop_unused_gin_index.sql (17.7ms)
  711. 4.74 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 2_object_stats_trigger.sql (13.75ms)
  712. 4.74 s [niks3-go-unit-tests] 2026/07/18 13:59:32 goose: up to current file version: 2
  713. 4.74 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20260628120000_add_object_size_and_stats.sql (13.82ms)
  714. 4.74 s [niks3-go-unit-tests] 2026/07/18 13:59:32 goose: successfully migrated database to version: 20260628120000
  715. 4.74 s [niks3-go-unit-tests] 2026/07/18 13:59:32 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"
  716. 4.74 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware (0.61s)
  717. 4.74 s [niks3-go-unit-tests] === CONT TestMultipartCleanup
  718. 4.74 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20260628120000_add_object_size_and_stats.sql (9.84ms)
  719. 4.74 s [niks3-go-unit-tests] 2026/07/18 13:59:32 goose: successfully migrated database to version: 20260628120000
  720. 4.74 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20251218171726_add_pins.sql (9.69ms)
  721. 4.74 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20251218171726_add_pins.sql (9.74ms)
  722. 4.74 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20251218171726_add_pins.sql (9.71ms)
  723. 4.75 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 1_commit_pending_closure.sql (14.35ms)
  724. 4.76 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20260628120000_add_object_size_and_stats.sql (17.28ms)
  725. 4.76 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20260628120000_add_object_size_and_stats.sql (17.26ms)
  726. 4.76 s [niks3-go-unit-tests] 2026/07/18 13:59:32 goose: successfully migrated database to version: 20260628120000
  727. 4.76 s [niks3-go-unit-tests] 2026/07/18 13:59:32 goose: successfully migrated database to version: 20260628120000
  728. 4.76 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 1_commit_pending_closure.sql (17.31ms)
  729. 4.76 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 20260628120000_add_object_size_and_stats.sql (17.24ms)
  730. 4.76 s [niks3-go-unit-tests] 2026/07/18 13:59:32 goose: successfully migrated database to version: 20260628120000
  731. 4.77 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 2_object_stats_trigger.sql (14.73ms)
  732. 4.77 s [niks3-go-unit-tests] 2026/07/18 13:59:32 goose: up to current file version: 2
  733. 4.77 s [niks3-go-unit-tests] 2026/07/18 13:59:32 INFO Received uploads request method=POST path=/api/pending_closures
  734. 4.78 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 2_object_stats_trigger.sql (15.48ms)
  735. 4.78 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 1_commit_pending_closure.sql (15.44ms)
  736. 4.78 s [niks3-go-unit-tests] 2026/07/18 13:59:32 goose: up to current file version: 2
  737. 4.78 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 1_commit_pending_closure.sql (15.56ms)
  738. 4.78 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 1_commit_pending_closure.sql (15.52ms)
  739. 4.78 s [niks3-go-unit-tests] 2026/07/18 13:59:32 INFO Received complete multipart upload request method=POST path=/api/multipart/complete
  740. 4.78 s [niks3-go-unit-tests] 2026/07/18 13:59:32 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst
  741. 4.78 s [niks3-go-unit-tests] --- PASS: TestCompleteMultipartUnregistered (0.65s)
  742. 4.78 s [niks3-go-unit-tests] === CONT TestServerTLSConfig
  743. 4.78 s [niks3-go-unit-tests] === RUN TestServerTLSConfig/no_client_CA
  744. 4.78 s [niks3-go-unit-tests] === PAUSE TestServerTLSConfig/no_client_CA
  745. 4.78 s [niks3-go-unit-tests] === RUN TestServerTLSConfig/missing_CA_file
  746. 4.78 s [niks3-go-unit-tests] === PAUSE TestServerTLSConfig/missing_CA_file
  747. 4.78 s [niks3-go-unit-tests] === RUN TestServerTLSConfig/not_a_PEM_file
  748. 4.78 s [niks3-go-unit-tests] === PAUSE TestServerTLSConfig/not_a_PEM_file
  749. 4.78 s [niks3-go-unit-tests] === CONT TestService_NativeMTLS
  750. 4.79 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 2_object_stats_trigger.sql (17.54ms)
  751. 4.79 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 2_object_stats_trigger.sql (17.64ms)
  752. 4.79 s [niks3-go-unit-tests] 2026/07/18 13:59:32 goose: up to current file version: 2
  753. 4.79 s [niks3-go-unit-tests] 2026/07/18 13:59:32 goose: up to current file version: 2
  754. 4.79 s [niks3-go-unit-tests] 2026/07/18 13:59:32 OK 2_object_stats_trigger.sql (17.65ms)
  755. 4.79 s [niks3-go-unit-tests] 2026/07/18 13:59:32 goose: up to current file version: 2
  756. 4.80 s [niks3-go-unit-tests] 2026/07/18 13:59:32 INFO Received uploads request method=POST path=/api/pending_closures
  757. 4.80 s [niks3-go-unit-tests] 2026/07/18 13:59:32 INFO Received uploads request method=POST path=/api/pending_closures
  758. 4.80 s [niks3-go-unit-tests] 2026/07/18 13:59:32 INFO Received uploads request method=POST path=/api/pending_closures
  759. 4.80 s [niks3-go-unit-tests] 2026/07/18 13:59:32 INFO Received uploads request method=POST path=/api/pending_closures
  760. 4.80 s [niks3-go-unit-tests] {"timestamp":"2026-07-18T13:59:32.944513209Z","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(26)"}
  761. 4.80 s [niks3-go-unit-tests] 2026/07/18 13:59:32 INFO Received uploads request method=POST path=/api/pending_closures
  762. 4.80 s [niks3-go-unit-tests] --- PASS: TestReadProxyNarinfo (0.67s)
  763. 4.80 s [niks3-go-unit-tests] === CONT TestMetricsInventory
  764. 4.82 s [niks3-go-unit-tests] --- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.69s)
  765. 4.82 s [niks3-go-unit-tests] === CONT TestNARDeduplicationMetadataUploadBug
  766. 4.84 s [niks3-go-unit-tests] 2026-07-18 13:59:32.989 UTC [207] ERROR: relation "goose_db_version" does not exist at character 36
  767. 4.84 s [niks3-go-unit-tests] 2026-07-18 13:59:32.989 UTC [207] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  768. 4.84 s [niks3-go-unit-tests] 2026-07-18 13:59:32.989 UTC [209] ERROR: relation "goose_db_version" does not exist at character 36
  769. 4.84 s [niks3-go-unit-tests] 2026-07-18 13:59:32.989 UTC [209] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  770. 4.85 s [niks3-go-unit-tests] 2026-07-18 13:59:32.989 UTC [210] ERROR: relation "goose_db_version" does not exist at character 36
  771. 4.85 s [niks3-go-unit-tests] 2026-07-18 13:59:32.989 UTC [210] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  772. 4.85 s [niks3-go-unit-tests] 2026-07-18 13:59:32.989 UTC [208] ERROR: relation "goose_db_version" does not exist at character 36
  773. 4.85 s [niks3-go-unit-tests] 2026-07-18 13:59:32.989 UTC [208] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  774. 4.85 s [niks3-go-unit-tests] 2026-07-18 13:59:32.990 UTC [213] ERROR: relation "goose_db_version" does not exist at character 36
  775. 4.85 s [niks3-go-unit-tests] 2026-07-18 13:59:32.990 UTC [213] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  776. 4.93 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20241026095416_initial_model.sql (69.15ms)
  777. 4.93 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20241026095416_initial_model.sql (69.02ms)
  778. 4.94 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20241026095416_initial_model.sql (72.94ms)
  779. 4.94 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251210153512_drop_unused_gin_index.sql (11.53ms)
  780. 4.94 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251210153512_drop_unused_gin_index.sql (11.49ms)
  781. 4.95 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251210153512_drop_unused_gin_index.sql (9.76ms)
  782. 4.96 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Received complete multipart upload request method=POST path=/api/multipart/complete
  783. 4.96 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251218171726_add_pins.sql (18.01ms)
  784. 4.96 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20241026095416_initial_model.sql (29.55ms)
  785. 4.96 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20241026095416_initial_model.sql (29.6ms)
  786. 4.96 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251218171726_add_pins.sql (18.19ms)
  787. 4.96 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251218171726_add_pins.sql (12.5ms)
  788. 4.97 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20260628120000_add_object_size_and_stats.sql (11.37ms)
  789. 4.97 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: successfully migrated database to version: 20260628120000
  790. 4.97 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20260628120000_add_object_size_and_stats.sql (11.54ms)
  791. 4.97 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: successfully migrated database to version: 20260628120000
  792. 4.97 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251210153512_drop_unused_gin_index.sql (11.62ms)
  793. 4.97 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251210153512_drop_unused_gin_index.sql (11.64ms)
  794. 4.98 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20260628120000_add_object_size_and_stats.sql (14.78ms)
  795. 4.98 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: successfully migrated database to version: 20260628120000
  796. 4.98 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 1_commit_pending_closure.sql (11.6ms)
  797. 4.98 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251218171726_add_pins.sql (11.59ms)
  798. 4.98 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251218171726_add_pins.sql (11.57ms)
  799. 4.98 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 1_commit_pending_closure.sql (11.73ms)
  800. 4.99 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Received complete multipart upload request method=POST path=/api/multipart/complete
  801. 4.99 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 1_commit_pending_closure.sql (8.58ms)
  802. 4.99 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MTU5ZWQ5ZTYtZTU2Ni00N2I3LWJhY2QtNDE3ZDFmMGU0MWI3LmQyNTA0OWQyLWVhNzUtNGFhOC04YjVlLTAzMTU4Yzg3ZTVjY3gxNzg0MzgzMTcyOTQ4NjUxMzUy parts=10
  803. 4.99 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  804. 5.00 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20260628120000_add_object_size_and_stats.sql (12.73ms)
  805. 5.00 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 2_object_stats_trigger.sql (12.75ms)
  806. 5.00 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: up to current file version: 2
  807. 5.00 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20260628120000_add_object_size_and_stats.sql (12.74ms)
  808. 5.00 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: successfully migrated database to version: 20260628120000
  809. 5.00 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 2_object_stats_trigger.sql (12.71ms)
  810. 5.00 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: up to current file version: 2
  811. 5.00 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: successfully migrated database to version: 20260628120000
  812. 5.00 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Received uploads request method=POST path=/api/pending_closures
  813. 5.00 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Received cleanup request method=DELETE path=/api/pending_closures
  814. 5.00 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Aborted multipart uploads count=0
  815. 5.00 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Received uploads request method=POST path=/api/pending_closures
  816. 5.00 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Completed upload id=1
  817. 5.00 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000
  818. 5.00 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 2_object_stats_trigger.sql (15.98ms)
  819. 5.00 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: up to current file version: 2
  820. 5.00 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Received uploads request method=POST path=/api/pending_closures
  821. 5.00 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Received uploads request method=POST path=/api/pending_closures
  822. 5.01 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 1_commit_pending_closure.sql (16.2ms)
  823. 5.01 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 1_commit_pending_closure.sql (16.09ms)
  824. 5.02 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Starting cleanup of old closures method=DELETE path=/api/closures
  825. 5.03 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 2_object_stats_trigger.sql (16.23ms)
  826. 5.03 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: up to current file version: 2
  827. 5.03 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 2_object_stats_trigger.sql (16.19ms)
  828. 5.03 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: up to current file version: 2
  829. 5.03 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Received cleanup request method=DELETE path=/api/pending_closures
  830. 5.03 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Aborted multipart uploads count=1
  831. 5.03 s [niks3-go-unit-tests] --- PASS: TestService_Rustfstest (0.90s)
  832. 5.03 s [niks3-go-unit-tests] === CONT TestGenerateLandingPage
  833. 5.03 s [niks3-go-unit-tests] --- PASS: TestGenerateLandingPage (0.00s)
  834. 5.03 s [niks3-go-unit-tests] === CONT TestService_healthCheckHandler
  835. 5.04 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MTU5ZWQ5ZTYtZTU2Ni00N2I3LWJhY2QtNDE3ZDFmMGU0MWI3LmJkNmE5Y2QwLWU4NzctNGU2ZS04YzJkLTM0YTllZWQ2NjM2N3gxNzg0MzgzMTcyOTMxMzk5NjMy parts=12
  836. 5.04 s [niks3-go-unit-tests] --- PASS: TestRedundantMultipartUpload (0.91s)
  837. 5.04 s [niks3-go-unit-tests] === CONT TestGracefulShutdownDrainsInflight
  838. 5.04 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Starting HTTP server address=127.0.0.1:40691
  839. 5.04 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Shutdown signal received, draining in-flight requests timeout=10s
  840. 5.04 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  841. 5.04 s [niks3-go-unit-tests] 2026-07-18 13:59:33.187 UTC [209] ERROR: Closure does not exist: id=1
  842. 5.04 s [niks3-go-unit-tests] 2026-07-18 13:59:33.187 UTC [209] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE
  843. 5.04 s [niks3-go-unit-tests] 2026-07-18 13:59:33.187 UTC [209] STATEMENT: -- name: CommitPendingClosure :exec
  844. 5.04 s [niks3-go-unit-tests] SELECT commit_pending_closure($1::bigint)
  845. 5.04 s [niks3-go-unit-tests]
  846. 5.04 s [niks3-go-unit-tests] --- PASS: TestService_cleanupPendingClosuresHandler (0.91s)
  847. 5.04 s [niks3-go-unit-tests] === CONT TestGCTaskStore_Fail
  848. 5.04 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_Fail (0.00s)
  849. 5.04 s [niks3-go-unit-tests] === CONT TestGCTaskStore_PhaseUpdates
  850. 5.04 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_PhaseUpdates (0.00s)
  851. 5.04 s [niks3-go-unit-tests] === CONT TestGCTaskStore_CompletedAllowsNewTask
  852. 5.04 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)
  853. 5.04 s [niks3-go-unit-tests] === CONT TestClientMultipleUploads
  854. 5.06 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Received complete multipart upload request method=POST path=/api/multipart/complete
  855. 5.09 s [niks3-go-unit-tests] --- PASS: TestObjectStatsTrigger (0.76s)
  856. 5.09 s [niks3-go-unit-tests] === CONT TestGCTaskStore_GetEmpty
  857. 5.09 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_GetEmpty (0.00s)
  858. 5.09 s [niks3-go-unit-tests] === CONT TestGCTaskStore_ConflictDifferentParams
  859. 5.09 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)
  860. 5.09 s [niks3-go-unit-tests] === CONT TestGCTaskStore_DeduplicateSameParams
  861. 5.09 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)
  862. 5.09 s [niks3-go-unit-tests] === CONT TestPinProtectsFromGC
  863. 5.11 s [niks3-go-unit-tests] --- PASS: TestGracefulShutdownDrainsInflight (0.07s)
  864. 5.11 s [niks3-go-unit-tests] === CONT TestClientWithDependencies
  865. 5.12 s [niks3-go-unit-tests] 2026-07-18 13:59:33.269 UTC [225] ERROR: relation "goose_db_version" does not exist at character 36
  866. 5.26 s [niks3-go-unit-tests] 2026-07-18 13:59:33.269 UTC [225] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  867. 5.26 s [niks3-go-unit-tests] 2026-07-18 13:59:33.269 UTC [223] ERROR: relation "goose_db_version" does not exist at character 36
  868. 5.26 s [niks3-go-unit-tests] 2026-07-18 13:59:33.269 UTC [223] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  869. 5.26 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Aborted multipart uploads count=0
  870. 5.26 s [niks3-go-unit-tests] 2026-07-18 13:59:33.271 UTC [224] ERROR: relation "goose_db_version" does not exist at character 36
  871. 5.26 s [niks3-go-unit-tests] 2026-07-18 13:59:33.271 UTC [224] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  872. 5.26 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Received complete multipart upload request method=POST path=/api/multipart/complete
  873. 5.26 s [niks3-go-unit-tests] 2026/07/18 13:59:33 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
  874. 5.26 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20241026095416_initial_model.sql (76.97ms)
  875. 5.26 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Vacuumed table table=pending_closures
  876. 5.26 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Vacuumed table table=pending_objects
  877. 5.26 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20241026095416_initial_model.sql (20.26ms)
  878. 5.26 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251210153512_drop_unused_gin_index.sql (16.65ms)
  879. 5.26 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MTU5ZWQ5ZTYtZTU2Ni00N2I3LWJhY2QtNDE3ZDFmMGU0MWI3LjBjYjk5MDFmLTBmYzEtNDZmZC1iY2Q5LWVlMDg2M2ZhZTYyYngxNzg0MzgzMTczMTU3NzA0OTY1 parts=10
  880. 5.26 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  881. 5.26 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251218171726_add_pins.sql (16.89ms)
  882. 5.26 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20241026095416_initial_model.sql (37.37ms)
  883. 5.26 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251210153512_drop_unused_gin_index.sql (17.12ms)
  884. 5.27 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20260628120000_add_object_size_and_stats.sql (18ms)
  885. 5.28 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: successfully migrated database to version: 20260628120000
  886. 5.28 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251218171726_add_pins.sql (17.91ms)
  887. 5.28 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Completed upload id=1
  888. 5.28 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251210153512_drop_unused_gin_index.sql (18.16ms)
  889. 5.28 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Vacuumed table table=multipart_uploads
  890. 5.28 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Received uploads request method=POST path=/api/pending_closures
  891. 5.30 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 1_commit_pending_closure.sql (21.61ms)
  892. 5.30 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251218171726_add_pins.sql (21.5ms)
  893. 5.30 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20260628120000_add_object_size_and_stats.sql (21.69ms)
  894. 5.30 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: successfully migrated database to version: 20260628120000
  895. 5.30 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Received uploads request method=POST path=/api/pending_closures
  896. 5.30 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo
  897. 5.30 s [niks3-go-unit-tests] 2026/07/18 13:59:33 WARN Found objects in DB but missing from S3, will re-upload count=1
  898. 5.31 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Vacuumed table table=closures
  899. 5.31 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 2_object_stats_trigger.sql (16.95ms)
  900. 5.31 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 1_commit_pending_closure.sql (16.88ms)
  901. 5.31 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: up to current file version: 2
  902. 5.31 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20260628120000_add_object_size_and_stats.sql (16.89ms)
  903. 5.31 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: successfully migrated database to version: 20260628120000
  904. 5.31 s [niks3-go-unit-tests] --- PASS: TestService_verifyS3Integrity (1.18s)
  905. 5.31 s [niks3-go-unit-tests] === CONT TestCacheConfigHandler
  906. 5.31 s [niks3-go-unit-tests] === RUN TestCacheConfigHandler/full_config,_no_issuer
  907. 5.31 s [niks3-go-unit-tests] === PAUSE TestCacheConfigHandler/full_config,_no_issuer
  908. 5.31 s [niks3-go-unit-tests] === RUN TestCacheConfigHandler/no_cache_url_configured
  909. 5.31 s [niks3-go-unit-tests] === PAUSE TestCacheConfigHandler/no_cache_url_configured
  910. 5.31 s [niks3-go-unit-tests] === RUN TestCacheConfigHandler/no_signing_keys
  911. 5.31 s [niks3-go-unit-tests] === PAUSE TestCacheConfigHandler/no_signing_keys
  912. 5.31 s [niks3-go-unit-tests] === RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator
  913. 5.31 s [niks3-go-unit-tests] === PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator
  914. 5.31 s [niks3-go-unit-tests] === CONT TestClientIntegration
  915. 5.32 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Vacuumed table table=objects
  916. 5.32 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000
  917. 5.32 s [niks3-go-unit-tests] --- PASS: TestService_createPendingClosureHandler (1.19s)
  918. 5.33 s [niks3-go-unit-tests] === CONT TestClientErrorHandling
  919. 5.33 s [niks3-go-unit-tests] === RUN TestClientErrorHandling/InvalidStorePath
  920. 5.33 s [niks3-go-unit-tests] === PAUSE TestClientErrorHandling/InvalidStorePath
  921. 5.33 s [niks3-go-unit-tests] === RUN TestClientErrorHandling/InvalidAuthToken
  922. 5.33 s [niks3-go-unit-tests] === PAUSE TestClientErrorHandling/InvalidAuthToken
  923. 5.33 s [niks3-go-unit-tests] === RUN TestClientErrorHandling/ServerNotAvailable
  924. 5.33 s [niks3-go-unit-tests] === PAUSE TestClientErrorHandling/ServerNotAvailable
  925. 5.33 s [niks3-go-unit-tests] === CONT TestClientCADerivations
  926. 5.33 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 1_commit_pending_closure.sql (16.07ms)
  927. 5.33 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 2_object_stats_trigger.sql (16.22ms)
  928. 5.33 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: up to current file version: 2
  929. 5.34 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 2_object_stats_trigger.sql (8.67ms)
  930. 5.34 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: up to current file version: 2
  931. 5.44 s [niks3-go-unit-tests] --- PASS: TestResurrectedObjectNotDeleted (1.18s)
  932. 5.44 s [niks3-go-unit-tests] === CONT TestCacheStatsHandler
  933. 5.46 s [niks3-go-unit-tests] 2026-07-18 13:59:33.609 UTC [236] ERROR: relation "goose_db_version" does not exist at character 36
  934. 5.46 s [niks3-go-unit-tests] 2026-07-18 13:59:33.609 UTC [236] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  935. 5.46 s [niks3-go-unit-tests] 2026-07-18 13:59:33.609 UTC [237] ERROR: relation "goose_db_version" does not exist at character 36
  936. 5.46 s [niks3-go-unit-tests] 2026-07-18 13:59:33.609 UTC [237] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  937. 5.46 s [niks3-go-unit-tests] 2026-07-18 13:59:33.609 UTC [239] ERROR: relation "goose_db_version" does not exist at character 36
  938. 5.46 s [niks3-go-unit-tests] 2026-07-18 13:59:33.609 UTC [239] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  939. 5.46 s [niks3-go-unit-tests] 2026-07-18 13:59:33.609 UTC [235] ERROR: relation "goose_db_version" does not exist at character 36
  940. 5.46 s [niks3-go-unit-tests] 2026-07-18 13:59:33.609 UTC [235] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  941. 5.46 s [niks3-go-unit-tests] 2026-07-18 13:59:33.609 UTC [238] ERROR: relation "goose_db_version" does not exist at character 36
  942. 5.46 s [niks3-go-unit-tests] 2026-07-18 13:59:33.609 UTC [238] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  943. 5.55 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20241026095416_initial_model.sql (18.92ms)
  944. 5.55 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20241026095416_initial_model.sql (19ms)
  945. 5.55 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20241026095416_initial_model.sql (19.01ms)
  946. 5.56 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20241026095416_initial_model.sql (27.03ms)
  947. 5.56 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20241026095416_initial_model.sql (26.83ms)
  948. 5.57 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251210153512_drop_unused_gin_index.sql (16.88ms)
  949. 5.57 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251210153512_drop_unused_gin_index.sql (16.91ms)
  950. 5.58 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251210153512_drop_unused_gin_index.sql (18.32ms)
  951. 5.58 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251210153512_drop_unused_gin_index.sql (18.3ms)
  952. 5.58 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251210153512_drop_unused_gin_index.sql (26.36ms)
  953. 5.60 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251218171726_add_pins.sql (24.94ms)
  954. 5.60 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251218171726_add_pins.sql (15.56ms)
  955. 5.60 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251218171726_add_pins.sql (15.55ms)
  956. 5.60 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251218171726_add_pins.sql (24.97ms)
  957. 5.60 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251218171726_add_pins.sql (15.53ms)
  958. 5.61 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20260628120000_add_object_size_and_stats.sql (12.72ms)
  959. 5.61 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20260628120000_add_object_size_and_stats.sql (12.66ms)
  960. 5.61 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: successfully migrated database to version: 20260628120000
  961. 5.61 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: successfully migrated database to version: 20260628120000
  962. 5.61 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20260628120000_add_object_size_and_stats.sql (12.7ms)
  963. 5.61 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: successfully migrated database to version: 20260628120000
  964. 5.61 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20260628120000_add_object_size_and_stats.sql (12.7ms)
  965. 5.61 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: successfully migrated database to version: 20260628120000
  966. 5.61 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20260628120000_add_object_size_and_stats.sql (12.76ms)
  967. 5.61 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: successfully migrated database to version: 20260628120000
  968. 5.62 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 1_commit_pending_closure.sql (16.08ms)
  969. 5.62 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 1_commit_pending_closure.sql (16.07ms)
  970. 5.62 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 1_commit_pending_closure.sql (16.11ms)
  971. 5.62 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 1_commit_pending_closure.sql (16.01ms)
  972. 5.62 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 1_commit_pending_closure.sql (16.09ms)
  973. 5.64 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 2_object_stats_trigger.sql (15.84ms)
  974. 5.64 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 2_object_stats_trigger.sql (15.9ms)
  975. 5.64 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 2_object_stats_trigger.sql (15.91ms)
  976. 5.64 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: up to current file version: 2
  977. 5.64 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: up to current file version: 2
  978. 5.64 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 2_object_stats_trigger.sql (15.91ms)
  979. 5.64 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: up to current file version: 2
  980. 5.64 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 2_object_stats_trigger.sql (15.9ms)
  981. 5.64 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: up to current file version: 2
  982. 5.64 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: up to current file version: 2
  983. 5.64 s [niks3-go-unit-tests] 2026/07/18 13:59:33 WARN mTLS auth: subject not in bound subjects subject="CN=reader"
  984. 5.64 s [niks3-go-unit-tests] 2026/07/18 13:59:33 WARN mTLS auth: subject not in bound subjects subject="CN=writer"
  985. 5.64 s [niks3-go-unit-tests] --- PASS: TestService_NativeMTLS (0.86s)
  986. 5.64 s [niks3-go-unit-tests] === CONT TestCompletedNarNotReofferedAcrossClosures
  987. 5.64 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Received uploads request method=POST path=/api/pending_closures
  988. 5.64 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Created nix-cache-info in bucket bucket=bucket16
  989. 5.64 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Created nix-cache-info in bucket bucket=bucket17
  990. 5.67 s [niks3-go-unit-tests] --- PASS: TestMetricsInventory (0.87s)
  991. 5.67 s [niks3-go-unit-tests] === CONT TestCompleteMultipartUpload_ErrorButObjectExists
  992. 5.70 s [niks3-go-unit-tests] 2026-07-18 13:59:33.845 UTC [248] ERROR: relation "goose_db_version" does not exist at character 36
  993. 5.70 s [niks3-go-unit-tests] 2026-07-18 13:59:33.845 UTC [248] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  994. 5.70 s [niks3-go-unit-tests] 2026-07-18 13:59:33.845 UTC [247] ERROR: relation "goose_db_version" does not exist at character 36
  995. 5.70 s [niks3-go-unit-tests] 2026-07-18 13:59:33.845 UTC [247] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  996. 5.70 s [niks3-go-unit-tests] 2026-07-18 13:59:33.846 UTC [246] ERROR: relation "goose_db_version" does not exist at character 36
  997. 5.70 s [niks3-go-unit-tests] 2026-07-18 13:59:33.846 UTC [246] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  998. 5.77 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Received cleanup request method=DELETE path=/api/pending_closures
  999. 5.77 s [niks3-go-unit-tests] 2026/07/18 13:59:33 INFO Aborted multipart uploads count=1
  1000. 5.79 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20241026095416_initial_model.sql (81.07ms)
  1001. 5.80 s [niks3-go-unit-tests] --- PASS: TestMultipartCleanup (1.06s)
  1002. 5.80 s [niks3-go-unit-tests] === CONT TestGCTaskStore_StartNew
  1003. 5.80 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_StartNew (0.00s)
  1004. 5.80 s [niks3-go-unit-tests] === CONT TestReadProxyHead
  1005. 5.81 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20241026095416_initial_model.sql (24.42ms)
  1006. 5.81 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20241026095416_initial_model.sql (24.39ms)
  1007. 5.81 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251210153512_drop_unused_gin_index.sql (17.68ms)
  1008. 5.81 s [niks3-go-unit-tests] === NAME TestOrphanedObjectsGC
  1009. 5.81 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:290: GC Test Summary:
  1010. 5.81 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A
  1011. 5.81 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B
  1012. 5.81 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)
  1013. 5.81 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)
  1014. 5.81 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:295: - Total deleted: 10 objects
  1015. 5.81 s [niks3-go-unit-tests] --- PASS: TestOrphanedObjectsGC (1.55s)
  1016. 5.81 s [niks3-go-unit-tests] === CONT TestGCBugBareHashReferences
  1017. 5.83 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251218171726_add_pins.sql (20.4ms)
  1018. 5.83 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251210153512_drop_unused_gin_index.sql (20.71ms)
  1019. 5.83 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251210153512_drop_unused_gin_index.sql (20.8ms)
  1020. 5.84 s [niks3-go-unit-tests] === NAME TestNARDeduplicationMetadataUploadBug
  1021. 5.84 s [niks3-go-unit-tests] metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug202159708/001/store/2r504cdrbzilsiz3x4qzgsc5pklbqkp9-file1.txt
  1022. 5.85 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251218171726_add_pins.sql (16.33ms)
  1023. 5.85 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20251218171726_add_pins.sql (16.24ms)
  1024. 5.85 s [niks3-go-unit-tests] 2026/07/18 13:59:33 OK 20260628120000_add_object_size_and_stats.sql (16.47ms)
  1025. 5.85 s [niks3-go-unit-tests] 2026/07/18 13:59:33 goose: successfully migrated database to version: 20260628120000
  1026. 5.85 s [niks3-go-unit-tests] === NAME TestClientWithDependencies
  1027. 5.85 s [niks3-go-unit-tests] client_integration_test.go:593: Built derivation: /build/TestClientWithDependencies1524235262/001/store/56ky81shlyx36vaq8mzrri6s0pq4q9mh-test-script
  1028. 5.86 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20260628120000_add_object_size_and_stats.sql (17.48ms)
  1029. 5.86 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: successfully migrated database to version: 20260628120000
  1030. 5.86 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20260628120000_add_object_size_and_stats.sql (17.44ms)
  1031. 5.86 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: successfully migrated database to version: 20260628120000
  1032. 5.86 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 1_commit_pending_closure.sql (17.36ms)
  1033. 5.87 s [niks3-go-unit-tests] client_integration_test.go:595: Found 1 dependencies (including self)
  1034. 5.88 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 1_commit_pending_closure.sql (17.46ms)
  1035. 5.88 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 2_object_stats_trigger.sql (17.44ms)
  1036. 5.88 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: up to current file version: 2
  1037. 5.88 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 1_commit_pending_closure.sql (17.5ms)
  1038. 5.89 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Created nix-cache-info in bucket bucket=bucket21
  1039. 5.90 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 2_object_stats_trigger.sql (16.34ms)
  1040. 5.90 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: up to current file version: 2
  1041. 5.90 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 2_object_stats_trigger.sql (16.3ms)
  1042. 5.90 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: up to current file version: 2
  1043. 5.90 s [niks3-go-unit-tests] --- PASS: TestService_healthCheckHandler (0.87s)
  1044. 5.90 s [niks3-go-unit-tests] === CONT TestReadProxyRangeRequest
  1045. 5.90 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Created nix-cache-info in bucket bucket=bucket23
  1046. 5.96 s [niks3-go-unit-tests] 2026-07-18 13:59:34.101 UTC [306] ERROR: relation "goose_db_version" does not exist at character 36
  1047. 5.96 s [niks3-go-unit-tests] 2026-07-18 13:59:34.101 UTC [306] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1048. 5.96 s [niks3-go-unit-tests] 2026-07-18 13:59:34.101 UTC [307] ERROR: relation "goose_db_version" does not exist at character 36
  1049. 5.96 s [niks3-go-unit-tests] 2026-07-18 13:59:34.101 UTC [307] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1050. 5.96 s [niks3-go-unit-tests] 2026-07-18 13:59:34.101 UTC [305] ERROR: relation "goose_db_version" does not exist at character 36
  1051. 5.96 s [niks3-go-unit-tests] 2026-07-18 13:59:34.101 UTC [305] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1052. 6.00 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20241026095416_initial_model.sql (21.6ms)
  1053. 6.00 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20241026095416_initial_model.sql (21.61ms)
  1054. 6.00 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20241026095416_initial_model.sql (21.56ms)
  1055. 6.09 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20251210153512_drop_unused_gin_index.sql (89.61ms)
  1056. 6.09 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20251210153512_drop_unused_gin_index.sql (89.66ms)
  1057. 6.09 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20251210153512_drop_unused_gin_index.sql (89.65ms)
  1058. 6.10 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20251218171726_add_pins.sql (14.39ms)
  1059. 6.10 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20251218171726_add_pins.sql (14.41ms)
  1060. 6.10 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20251218171726_add_pins.sql (14.4ms)
  1061. 6.12 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20260628120000_add_object_size_and_stats.sql (15.39ms)
  1062. 6.12 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20260628120000_add_object_size_and_stats.sql (15.48ms)
  1063. 6.12 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: successfully migrated database to version: 20260628120000
  1064. 6.12 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: successfully migrated database to version: 20260628120000
  1065. 6.12 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20260628120000_add_object_size_and_stats.sql (15.41ms)
  1066. 6.12 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: successfully migrated database to version: 20260628120000
  1067. 6.13 s [niks3-go-unit-tests] === NAME TestClientMultipleUploads
  1068. 6.13 s [niks3-go-unit-tests] client_integration_test.go:338: Created store path 0: /build/TestClientMultipleUploads1705868838/001/store/qzl8pn71mmrwwrwhk1i9alp1lrs0qimn-test-file-0.txt
  1069. 6.14 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 1_commit_pending_closure.sql (17.67ms)
  1070. 6.14 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 1_commit_pending_closure.sql (17.66ms)
  1071. 6.14 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 1_commit_pending_closure.sql (17.63ms)
  1072. 6.14 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received uploads request method=POST path=/api/pending_closures
  1073. 6.15 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 2_object_stats_trigger.sql (16.75ms)
  1074. 6.15 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 2_object_stats_trigger.sql (16.75ms)
  1075. 6.15 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: up to current file version: 2
  1076. 6.15 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: up to current file version: 2
  1077. 6.15 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 2_object_stats_trigger.sql (16.74ms)
  1078. 6.15 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: up to current file version: 2
  1079. 6.15 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)
  1080. 6.15 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading 56ky81shlyx36vaq8mzrri6s0pq4q9mh-test-script (136B)
  1081. 6.16 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign
  1082. 6.16 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Created nix-cache-info in bucket bucket=bucket26
  1083. 6.16 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Signed narinfos id=1 count=1
  1084. 6.16 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading 1 narinfos
  1085. 6.16 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Created nix-cache-info in bucket bucket=bucket24
  1086. 6.16 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1087. 6.17 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Completed upload id=1
  1088. 6.17 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Upload complete. (55ms)
  1089. 6.17 s [niks3-go-unit-tests] === NAME TestClientWithDependencies
  1090. 6.17 s [niks3-go-unit-tests] client_integration_test.go:597: Skipping nix copy test - isolated store (/build/TestClientWithDependencies1524235262/001/store) requires matching store prefix
  1091. 6.17 s [niks3-go-unit-tests] --- PASS: TestClientWithDependencies (1.07s)
  1092. 6.17 s [niks3-go-unit-tests] === CONT TestGCMetrics
  1093. 6.21 s [niks3-go-unit-tests] --- PASS: TestCacheStatsHandler (0.77s)
  1094. 6.21 s [niks3-go-unit-tests] === CONT TestReadProxyDisabled
  1095. 6.22 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received uploads request method=POST path=/api/pending_closures
  1096. 6.23 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)
  1097. 6.23 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading 2r504cdrbzilsiz3x4qzgsc5pklbqkp9-file1.txt (160B)
  1098. 6.23 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign
  1099. 6.23 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Signed narinfos id=1 count=1
  1100. 6.23 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading 1 narinfos
  1101. 6.23 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1102. 6.25 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Completed upload id=1
  1103. 6.25 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Upload complete. (202ms)
  1104. 6.25 s [niks3-go-unit-tests] === NAME TestNARDeduplicationMetadataUploadBug
  1105. 6.25 s [niks3-go-unit-tests] metadata_upload_test.go:54: Retrieved narinfo from S3:
  1106. 6.25 s [niks3-go-unit-tests] StorePath: /build/TestNARDeduplicationMetadataUploadBug202159708/001/store/2r504cdrbzilsiz3x4qzgsc5pklbqkp9-file1.txt
  1107. 6.25 s [niks3-go-unit-tests] URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst
  1108. 6.25 s [niks3-go-unit-tests] Compression: zstd
  1109. 6.25 s [niks3-go-unit-tests] NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf
  1110. 6.25 s [niks3-go-unit-tests] NarSize: 160
  1111. 6.25 s [niks3-go-unit-tests] References:
  1112. 6.25 s [niks3-go-unit-tests] CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf
  1113. 6.25 s [niks3-go-unit-tests] metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)
  1114. 6.25 s [niks3-go-unit-tests] metadata_upload_test.go:55: Decompressed .ls content (64 bytes):
  1115. 6.25 s [niks3-go-unit-tests] {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}
  1116. 6.26 s [niks3-go-unit-tests] === NAME TestClientMultipleUploads
  1117. 6.26 s [niks3-go-unit-tests] client_integration_test.go:338: Created store path 1: /build/TestClientMultipleUploads1705868838/001/store/nqhyacy6adygms0jm4265d0x1k2qhwrh-test-file-1.txt
  1118. 6.26 s [niks3-go-unit-tests] === NAME TestPinProtectsFromGC
  1119. 6.26 s [niks3-go-unit-tests] client_integration_test.go:646: Pinned store path: /build/TestPinProtectsFromGC2944592355/001/store/ya75h956sq5s5gazcyqrzw8vl3jhvanw-pinned-file.txt
  1120. 6.26 s [niks3-go-unit-tests] client_integration_test.go:647: Unpinned store path: /build/TestPinProtectsFromGC2944592355/001/store/0sb8hgcayjyhkgcvqa7l80v22yz8sr6n-unpinned-file.txt
  1121. 6.34 s [niks3-go-unit-tests] 2026-07-18 13:59:34.479 UTC [403] ERROR: relation "goose_db_version" does not exist at character 36
  1122. 6.34 s [niks3-go-unit-tests] 2026-07-18 13:59:34.479 UTC [403] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1123. 6.34 s [niks3-go-unit-tests] 2026-07-18 13:59:34.479 UTC [404] ERROR: relation "goose_db_version" does not exist at character 36
  1124. 6.34 s [niks3-go-unit-tests] 2026-07-18 13:59:34.479 UTC [404] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1125. 6.36 s [niks3-go-unit-tests] === NAME TestClientMultipleUploads
  1126. 6.36 s [niks3-go-unit-tests] client_integration_test.go:338: Created store path 2: /build/TestClientMultipleUploads1705868838/001/store/3jpil889ijndpsggzmqxy7s64r7ygn2x-test-file-2.txt
  1127. 6.36 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20241026095416_initial_model.sql (17.12ms)
  1128. 6.36 s [niks3-go-unit-tests] === NAME TestNARDeduplicationMetadataUploadBug
  1129. 6.36 s [niks3-go-unit-tests] metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug202159708/001/store/k1r4g57sij33rp89s0f4x151nbykpz38-file2.txt
  1130. 6.37 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20241026095416_initial_model.sql (16.59ms)
  1131. 6.38 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20251210153512_drop_unused_gin_index.sql (16.32ms)
  1132. 6.39 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20251210153512_drop_unused_gin_index.sql (18.11ms)
  1133. 6.40 s [niks3-go-unit-tests] === NAME TestClientCADerivations
  1134. 6.40 s [niks3-go-unit-tests] client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations281404499/001/store/bgmy5h5cw9fp1d13izfinl6i0xcmdpkk-ca-test
  1135. 6.41 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20251218171726_add_pins.sql (26.24ms)
  1136. 6.41 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20251218171726_add_pins.sql (15.46ms)
  1137. 6.42 s [niks3-go-unit-tests] === NAME TestClientIntegration
  1138. 6.42 s [niks3-go-unit-tests] client_integration_test.go:276: Created store path: /build/TestClientIntegration3520626137/002/store/vz6rddga69pr9lvd16m4z0rrfdhwnl0s-test-file.txt
  1139. 6.42 s [niks3-go-unit-tests] === NAME TestClientCADerivations
  1140. 6.42 s [niks3-go-unit-tests] client_ca_test.go:139: Found 1 dependencies (including self)
  1141. 6.42 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20260628120000_add_object_size_and_stats.sql (18.27ms)
  1142. 6.42 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: successfully migrated database to version: 20260628120000
  1143. 6.42 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20260628120000_add_object_size_and_stats.sql (18.37ms)
  1144. 6.42 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: successfully migrated database to version: 20260628120000
  1145. 6.43 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received uploads request method=POST path=/api/pending_closures
  1146. 6.44 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 1_commit_pending_closure.sql (16.58ms)
  1147. 6.44 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 1_commit_pending_closure.sql (16.5ms)
  1148. 6.44 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)
  1149. 6.44 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign
  1150. 6.44 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Signed narinfos id=2 count=1
  1151. 6.44 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading 1 narinfos
  1152. 6.44 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete
  1153. 6.46 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received uploads request method=POST path=/api/pending_closures
  1154. 6.46 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 2_object_stats_trigger.sql (17.54ms)
  1155. 6.46 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: up to current file version: 2
  1156. 6.46 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Completed upload id=2
  1157. 6.46 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 2_object_stats_trigger.sql (17.6ms)
  1158. 6.46 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: up to current file version: 2
  1159. 6.46 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Upload complete. (76ms)
  1160. 6.46 s [niks3-go-unit-tests] === NAME TestNARDeduplicationMetadataUploadBug
  1161. 6.46 s [niks3-go-unit-tests] metadata_upload_test.go:76: Retrieved narinfo from S3:
  1162. 6.46 s [niks3-go-unit-tests] StorePath: /build/TestNARDeduplicationMetadataUploadBug202159708/001/store/k1r4g57sij33rp89s0f4x151nbykpz38-file2.txt
  1163. 6.46 s [niks3-go-unit-tests] URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst
  1164. 6.46 s [niks3-go-unit-tests] Compression: zstd
  1165. 6.46 s [niks3-go-unit-tests] NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf
  1166. 6.46 s [niks3-go-unit-tests] NarSize: 160
  1167. 6.46 s [niks3-go-unit-tests] References:
  1168. 6.46 s [niks3-go-unit-tests] CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf
  1169. 6.46 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received uploads request method=POST path=/api/pending_closures
  1170. 6.46 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received uploads request method=POST path=/api/pending_closures
  1171. 6.46 s [niks3-go-unit-tests] metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)
  1172. 6.46 s [niks3-go-unit-tests] metadata_upload_test.go:77: Decompressed .ls content (49 bytes):
  1173. 6.46 s [niks3-go-unit-tests] {"version":1,"root":{"type":"regular","size":44}}
  1174. 6.46 s [niks3-go-unit-tests] --- PASS: TestNARDeduplicationMetadataUploadBug (1.64s)
  1175. 6.46 s [niks3-go-unit-tests] === CONT TestReadProxyRootRedirectsToIndexHTML
  1176. 6.48 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)
  1177. 6.48 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading ya75h956sq5s5gazcyqrzw8vl3jhvanw-pinned-file.txt (128B)
  1178. 6.48 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign
  1179. 6.48 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Signed narinfos id=1 count=1
  1180. 6.48 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading 1 narinfos
  1181. 6.48 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1182. 6.49 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received uploads request method=POST path=/api/pending_closures
  1183. 6.49 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Completed upload id=1
  1184. 6.49 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Upload complete. (208ms)
  1185. 6.50 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received complete multipart upload request method=POST path=/api/multipart/complete
  1186. 6.50 s [niks3-go-unit-tests] {"timestamp":"2026-07-18T13:59:34.644255529Z","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(24)"}
  1187. 6.50 s [niks3-go-unit-tests] {"timestamp":"2026-07-18T13:59:34.644283459Z","level":"ERROR","fields":{"message":"complete_multipart_upload etag err client=Some(\"deadbeef\"), stored=\"\", part_id=1, bucket=bucket27, 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(24)"}
  1188. 6.50 s [niks3-go-unit-tests] 2026/07/18 13:59:34 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=MTU5ZWQ5ZTYtZTU2Ni00N2I3LWJhY2QtNDE3ZDFmMGU0MWI3Ljc5N2VjODk0LTQyMzQtNGYxMS04NzZlLTE1MjQ1MTAzNzJjMngxNzg0MzgzMTc0NjIyMzA5MjA2
  1189. 6.50 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)
  1190. 6.50 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading bgmy5h5cw9fp1d13izfinl6i0xcmdpkk-ca-test (144B)
  1191. 6.50 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign
  1192. 6.50 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Signed narinfos id=1 count=1
  1193. 6.50 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading 1 narinfos
  1194. 6.51 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1195. 6.52 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Completed upload id=1
  1196. 6.52 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Upload complete. (79ms)
  1197. 6.52 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MTU5ZWQ5ZTYtZTU2Ni00N2I3LWJhY2QtNDE3ZDFmMGU0MWI3Ljc5N2VjODk0LTQyMzQtNGYxMS04NzZlLTE1MjQ1MTAzNzJjMngxNzg0MzgzMTc0NjIyMzA5MjA2 parts=1
  1198. 6.52 s [niks3-go-unit-tests] --- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.85s)
  1199. 6.52 s [niks3-go-unit-tests] === CONT TestService_ReadAuthMiddleware
  1200. 6.52 s [niks3-go-unit-tests] === NAME TestClientCADerivations
  1201. 6.52 s [niks3-go-unit-tests] client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations281404499/001/store/bgmy5h5cw9fp1d13izfinl6i0xcmdpkk-ca-test
  1202. 6.52 s [niks3-go-unit-tests] URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst
  1203. 6.52 s [niks3-go-unit-tests] Compression: zstd
  1204. 6.52 s [niks3-go-unit-tests] NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n
  1205. 6.53 s [niks3-go-unit-tests] NarSize: 144
  1206. 6.53 s [niks3-go-unit-tests] References:
  1207. 6.53 s [niks3-go-unit-tests] Deriver: /build/TestClientCADerivations281404499/001/store/77l1w2ygv67akl9nkxv8q31513byi8lm-ca-test.drv
  1208. 6.53 s [niks3-go-unit-tests] CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n
  1209. 6.53 s [niks3-go-unit-tests] client_ca_test.go:185: Checking for realisation files in S3...
  1210. 6.53 s [niks3-go-unit-tests] client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations
  1211. 6.53 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
  1212. 6.54 s [niks3-go-unit-tests] 2026-07-18 13:59:34.686 UTC [666] ERROR: relation "goose_db_version" does not exist at character 36
  1213. 6.54 s [niks3-go-unit-tests] 2026-07-18 13:59:34.686 UTC [666] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1214. 6.54 s [niks3-go-unit-tests] 2026-07-18 13:59:34.686 UTC [665] ERROR: relation "goose_db_version" does not exist at character 36
  1215. 6.54 s [niks3-go-unit-tests] 2026-07-18 13:59:34.686 UTC [665] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1216. 6.54 s [niks3-go-unit-tests] 2026-07-18 13:59:34.687 UTC [629] ERROR: relation "goose_db_version" does not exist at character 36
  1217. 6.54 s [niks3-go-unit-tests] 2026-07-18 13:59:34.687 UTC [629] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1218. 6.54 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received uploads request method=POST path=/api/pending_closures
  1219. 6.56 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
  1220. 6.56 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
  1221. 6.56 s [niks3-go-unit-tests] error: binary cache 's3://bucket26?endpoint=http://localhost:44455&region=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations281404499/001/store'
  1222. 6.56 s [niks3-go-unit-tests] client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 1
  1223. 6.56 s [niks3-go-unit-tests] --- PASS: TestClientCADerivations (1.23s)
  1224. 6.56 s [niks3-go-unit-tests] === CONT TestReadProxyConditionalGet
  1225. 6.57 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received uploads request method=POST path=/api/pending_closures
  1226. 6.58 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received uploads request method=POST path=/api/pending_closures
  1227. 6.61 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received uploads request method=POST path=/api/pending_closures
  1228. 6.63 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)
  1229. 6.63 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)
  1230. 6.63 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading 0sb8hgcayjyhkgcvqa7l80v22yz8sr6n-unpinned-file.txt (128B)
  1231. 6.63 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading vz6rddga69pr9lvd16m4z0rrfdhwnl0s-test-file.txt (152B)
  1232. 6.63 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received uploads request method=POST path=/api/pending_closures
  1233. 6.63 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign
  1234. 6.63 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign
  1235. 6.63 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Signed narinfos id=2 count=1
  1236. 6.63 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Signed narinfos id=1 count=1
  1237. 6.63 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading 1 narinfos
  1238. 6.63 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading 1 narinfos
  1239. 6.63 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete
  1240. 6.63 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1241. 6.64 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20241026095416_initial_model.sql (18.88ms)
  1242. 6.64 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received complete multipart upload request method=POST path=/api/multipart/complete
  1243. 6.64 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Completed upload id=1
  1244. 6.64 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Completed upload id=2
  1245. 6.64 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Upload complete. (199ms)
  1246. 6.64 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Upload complete. (126ms)
  1247. 6.64 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)
  1248. 6.64 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading 3jpil889ijndpsggzmqxy7s64r7ygn2x-test-file-2.txt (160B)
  1249. 6.64 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading nqhyacy6adygms0jm4265d0x1k2qhwrh-test-file-1.txt (160B)
  1250. 6.64 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading qzl8pn71mmrwwrwhk1i9alp1lrs0qimn-test-file-0.txt (160B)
  1251. 6.64 s [niks3-go-unit-tests] === NAME TestClientIntegration
  1252. 6.64 s [niks3-go-unit-tests] client_integration_test.go:292: Retrieved narinfo from S3:
  1253. 6.64 s [niks3-go-unit-tests] StorePath: /build/TestClientIntegration3520626137/002/store/vz6rddga69pr9lvd16m4z0rrfdhwnl0s-test-file.txt
  1254. 6.64 s [niks3-go-unit-tests] URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst
  1255. 6.64 s [niks3-go-unit-tests] Compression: zstd
  1256. 6.64 s [niks3-go-unit-tests] NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1
  1257. 6.64 s [niks3-go-unit-tests] NarSize: 152
  1258. 6.64 s [niks3-go-unit-tests] References:
  1259. 6.64 s [niks3-go-unit-tests] CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1
  1260. 6.64 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign
  1261. 6.64 s [niks3-go-unit-tests] client_integration_test.go:293: Retrieved .ls file from S3 (compressed size: 77 bytes)
  1262. 6.64 s [niks3-go-unit-tests] client_integration_test.go:293: Decompressed .ls content (64 bytes):
  1263. 6.64 s [niks3-go-unit-tests] {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}
  1264. 6.64 s [niks3-go-unit-tests] client_integration_test.go:296: Testing garbage collection...
  1265. 6.64 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Signed narinfos id=3 count=1
  1266. 6.64 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign
  1267. 6.64 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Signed narinfos id=1 count=1
  1268. 6.64 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign
  1269. 6.64 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Signed narinfos id=2 count=1
  1270. 6.64 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Uploading 3 narinfos
  1271. 6.64 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete
  1272. 6.65 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20241026095416_initial_model.sql (34.44ms)
  1273. 6.65 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20241026095416_initial_model.sql (40.33ms)
  1274. 6.65 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20251210153512_drop_unused_gin_index.sql (15.92ms)
  1275. 6.66 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Completed upload id=2
  1276. 6.66 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete
  1277. 6.66 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Starting cleanup of old closures method=DELETE path=/api/closures
  1278. 6.66 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received create pin request method=POST path=/api/pins/myapp
  1279. 6.66 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Garbage collection started
  1280. 6.67 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20251218171726_add_pins.sql (17.22ms)
  1281. 6.67 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20251210153512_drop_unused_gin_index.sql (17.86ms)
  1282. 6.67 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20251210153512_drop_unused_gin_index.sql (17.47ms)
  1283. 6.67 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Completed upload id=3
  1284. 6.67 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1285. 6.67 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MTU5ZWQ5ZTYtZTU2Ni00N2I3LWJhY2QtNDE3ZDFmMGU0MWI3LjMxMzdhNzFhLTdmMjktNDEyYy1hYzIxLWFkZWE2OTJhYWY2ZXgxNzg0MzgzMTc0NjIyMzIxNDI2 parts=12
  1286. 6.67 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Received uploads request method=POST path=/api/pending_closures
  1287. 6.68 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20260628120000_add_object_size_and_stats.sql (17.17ms)
  1288. 6.68 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20251218171726_add_pins.sql (16.99ms)
  1289. 6.68 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: successfully migrated database to version: 20260628120000
  1290. 6.68 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20251218171726_add_pins.sql (16.96ms)
  1291. 6.68 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2944592355/001/store/ya75h956sq5s5gazcyqrzw8vl3jhvanw-pinned-file.txt narinfo_key=ya75h956sq5s5gazcyqrzw8vl3jhvanw.narinfo
  1292. 6.68 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Starting cleanup of old closures method=DELETE path=/api/closures
  1293. 6.68 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Garbage collection started
  1294. 6.69 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Completed upload id=1
  1295. 6.69 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Upload complete. (308ms)
  1296. 6.69 s [niks3-go-unit-tests] --- PASS: TestCompletedNarNotReofferedAcrossClosures (1.05s)
  1297. 6.69 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_OIDC
  1298. 6.69 s [niks3-go-unit-tests] === NAME TestClientMultipleUploads
  1299. 6.69 s [niks3-go-unit-tests] client_integration_test.go:349: Uploaded 3 paths in 330.256104ms
  1300. 6.69 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO OIDC provider initialized name=test
  1301. 6.69 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20260628120000_add_object_size_and_stats.sql (11.24ms)
  1302. 6.69 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 1_commit_pending_closure.sql (11.29ms)
  1303. 6.69 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: successfully migrated database to version: 20260628120000
  1304. 6.69 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20260628120000_add_object_size_and_stats.sql (11.36ms)
  1305. 6.69 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: successfully migrated database to version: 20260628120000
  1306. 6.70 s [niks3-go-unit-tests] --- PASS: TestClientMultipleUploads (1.65s)
  1307. 6.70 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_MTLSBoundSubjects
  1308. 6.70 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 2_object_stats_trigger.sql (9.14ms)
  1309. 6.70 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: up to current file version: 2
  1310. 6.71 s [niks3-go-unit-tests] --- PASS: TestReadProxyHead (0.91s)
  1311. 6.71 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_MTLSProxyHeader
  1312. 6.71 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 1_commit_pending_closure.sql (18.21ms)
  1313. 6.71 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 1_commit_pending_closure.sql (18.24ms)
  1314. 6.72 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 2_object_stats_trigger.sql (7.64ms)
  1315. 6.72 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: up to current file version: 2
  1316. 6.73 s [niks3-go-unit-tests] --- PASS: TestReadProxyRangeRequest (0.83s)
  1317. 6.73 s [niks3-go-unit-tests] === CONT TestReadProxy404
  1318. 6.73 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 2_object_stats_trigger.sql (16.09ms)
  1319. 6.73 s [niks3-go-unit-tests] 2026/07/18 13:59:34 goose: up to current file version: 2
  1320. 6.81 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Aborted multipart uploads count=0
  1321. 6.81 s [niks3-go-unit-tests] 2026/07/18 13:59:34 INFO Aborted multipart uploads count=0
  1322. 6.81 s [niks3-go-unit-tests] 2026-07-18 13:59:34.952 UTC [890] ERROR: relation "goose_db_version" does not exist at character 36
  1323. 6.81 s [niks3-go-unit-tests] 2026-07-18 13:59:34.952 UTC [890] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1324. 6.81 s [niks3-go-unit-tests] 2026-07-18 13:59:34.953 UTC [891] ERROR: relation "goose_db_version" does not exist at character 36
  1325. 6.81 s [niks3-go-unit-tests] 2026-07-18 13:59:34.953 UTC [891] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1326. 6.83 s [niks3-go-unit-tests] 2026/07/18 13:59:34 WARN Force mode enabled - objects will be deleted immediately without grace period
  1327. 6.83 s [niks3-go-unit-tests] 2026/07/18 13:59:34 WARN Force mode enabled - objects will be deleted immediately without grace period
  1328. 6.85 s [niks3-go-unit-tests] 2026/07/18 13:59:34 OK 20241026095416_initial_model.sql (17.85ms)
  1329. 6.89 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20241026095416_initial_model.sql (65.83ms)
  1330. 6.90 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251210153512_drop_unused_gin_index.sql (52.09ms)
  1331. 6.91 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251210153512_drop_unused_gin_index.sql (13.67ms)
  1332. 6.93 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251218171726_add_pins.sql (27.62ms)
  1333. 6.93 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251218171726_add_pins.sql (18.52ms)
  1334. 6.95 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20260628120000_add_object_size_and_stats.sql (26.32ms)
  1335. 6.95 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: successfully migrated database to version: 20260628120000
  1336. 6.95 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20260628120000_add_object_size_and_stats.sql (26.35ms)
  1337. 6.95 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: successfully migrated database to version: 20260628120000
  1338. 6.97 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 1_commit_pending_closure.sql (20.79ms)
  1339. 6.97 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 1_commit_pending_closure.sql (20.77ms)
  1340. 6.99 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 2_object_stats_trigger.sql (13.91ms)
  1341. 6.99 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: up to current file version: 2
  1342. 6.99 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 2_object_stats_trigger.sql (13.9ms)
  1343. 6.99 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: up to current file version: 2
  1344. 7.02 s [niks3-go-unit-tests] 2026-07-18 13:59:35.165 UTC [933] ERROR: relation "goose_db_version" does not exist at character 36
  1345. 7.02 s [niks3-go-unit-tests] 2026-07-18 13:59:35.165 UTC [933] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1346. 7.02 s [niks3-go-unit-tests] 2026-07-18 13:59:35.166 UTC [934] ERROR: relation "goose_db_version" does not exist at character 36
  1347. 7.02 s [niks3-go-unit-tests] 2026-07-18 13:59:35.166 UTC [934] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1348. 7.02 s [niks3-go-unit-tests] 2026-07-18 13:59:35.166 UTC [932] ERROR: relation "goose_db_version" does not exist at character 36
  1349. 7.02 s [niks3-go-unit-tests] 2026-07-18 13:59:35.166 UTC [932] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1350. 7.02 s [niks3-go-unit-tests] --- PASS: TestReadProxyDisabled (0.82s)
  1351. 7.02 s [niks3-go-unit-tests] === CONT TestReadProxyInvalidPath
  1352. 7.06 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20241026095416_initial_model.sql (27.69ms)
  1353. 7.08 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Aborted multipart uploads count=0
  1354. 7.08 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20241026095416_initial_model.sql (36.29ms)
  1355. 7.08 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20241026095416_initial_model.sql (36.32ms)
  1356. 7.08 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251210153512_drop_unused_gin_index.sql (17.95ms)
  1357. 7.08 s [niks3-go-unit-tests] 2026/07/18 13:59:35 WARN Force mode enabled - objects will be deleted immediately without grace period
  1358. 7.08 s [niks3-go-unit-tests] 2026/07/18 13:59:35 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
  1359. 7.08 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Vacuumed table table=pending_closures
  1360. 7.08 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Vacuumed table table=pending_objects
  1361. 7.08 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Vacuumed table table=multipart_uploads
  1362. 7.08 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Vacuumed table table=closures
  1363. 7.08 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Vacuumed table table=objects
  1364. 7.08 s [niks3-go-unit-tests] 2026-07-18 13:59:35.228 UTC [940] ERROR: relation "goose_db_version" does not exist at character 36
  1365. 7.08 s [niks3-go-unit-tests] 2026-07-18 13:59:35.228 UTC [940] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1366. 7.08 s [niks3-go-unit-tests] --- PASS: TestGCMetrics (0.91s)
  1367. 7.08 s [niks3-go-unit-tests] === CONT TestReadProxyNarStreaming
  1368. 7.14 s [niks3-go-unit-tests] --- PASS: TestGCBugBareHashReferences (1.32s)
  1369. 7.14 s [niks3-go-unit-tests] === CONT TestReadProxyNarinfoAlreadyDecompressed
  1370. 7.14 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251218171726_add_pins.sql (60.97ms)
  1371. 7.14 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251210153512_drop_unused_gin_index.sql (61.28ms)
  1372. 7.14 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251210153512_drop_unused_gin_index.sql (61.39ms)
  1373. 7.15 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251218171726_add_pins.sql (11.34ms)
  1374. 7.15 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251218171726_add_pins.sql (11.29ms)
  1375. 7.15 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20260628120000_add_object_size_and_stats.sql (11.54ms)
  1376. 7.15 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: successfully migrated database to version: 20260628120000
  1377. 7.16 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20241026095416_initial_model.sql (18.11ms)
  1378. 7.16 s [niks3-go-unit-tests] 2026/07/18 13:59:35 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
  1379. 7.16 s [niks3-go-unit-tests] 2026/07/18 13:59:35 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
  1380. 7.16 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20260628120000_add_object_size_and_stats.sql (14.4ms)
  1381. 7.16 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: successfully migrated database to version: 20260628120000
  1382. 7.17 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 1_commit_pending_closure.sql (14.33ms)
  1383. 7.17 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20260628120000_add_object_size_and_stats.sql (14.37ms)
  1384. 7.17 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: successfully migrated database to version: 20260628120000
  1385. 7.17 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251210153512_drop_unused_gin_index.sql (14.63ms)
  1386. 7.20 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 1_commit_pending_closure.sql (38.74ms)
  1387. 7.20 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 1_commit_pending_closure.sql (38.74ms)
  1388. 7.20 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 2_object_stats_trigger.sql (38.81ms)
  1389. 7.20 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: up to current file version: 2
  1390. 7.21 s [niks3-go-unit-tests] --- PASS: TestReadProxyConditionalGet (0.65s)
  1391. 7.21 s [niks3-go-unit-tests] === CONT TestProxyWriteTimeout/narinfo
  1392. 7.21 s [niks3-go-unit-tests] === CONT TestProxyWriteTimeout/10_GiB_nar
  1393. 7.21 s [niks3-go-unit-tests] === CONT TestProxyWriteTimeout/1_GiB_nar
  1394. 7.21 s [niks3-go-unit-tests] === CONT TestProxyWriteTimeout/unknown_size
  1395. 7.21 s [niks3-go-unit-tests] --- PASS: TestProxyWriteTimeout (0.13s)
  1396. 7.21 s [niks3-go-unit-tests] --- PASS: TestProxyWriteTimeout/narinfo (0.00s)
  1397. 7.21 s [niks3-go-unit-tests] --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)
  1398. 7.21 s [niks3-go-unit-tests] --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)
  1399. 7.21 s [niks3-go-unit-tests] --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)
  1400. 7.21 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info
  1401. 7.21 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Received uploads request method=POST path=/
  1402. 7.21 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key
  1403. 7.21 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Received complete multipart upload request method=POST path=/
  1404. 7.21 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key
  1405. 7.21 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Received request for more parts method=POST path=/
  1406. 7.21 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal
  1407. 7.21 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251218171726_add_pins.sql (37.73ms)
  1408. 7.21 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Received uploads request method=POST path=/
  1409. 7.21 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectInvalidKeys (0.13s)
  1410. 7.21 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)
  1411. 7.21 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)
  1412. 7.21 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)
  1413. 7.21 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)
  1414. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/narinfo
  1415. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/unknown_type
  1416. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/realisation
  1417. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/realisation_plus_in_output
  1418. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/empty_key
  1419. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/absolute
  1420. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/traversal_nar
  1421. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/build_log_equals
  1422. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/traversal
  1423. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/build_log_question_mark
  1424. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/build_log_plus_in_name
  1425. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/listing_key,_narinfo_type
  1426. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/build_log_home-manager_file
  1427. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/nar_key,_narinfo_type
  1428. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/nar_xz
  1429. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/nar_zst
  1430. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/narinfo_key,_nar_type
  1431. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/index.html
  1432. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/nix-cache-info
  1433. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/build_log
  1434. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/listing
  1435. 7.21 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/nar_plain
  1436. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey (0.13s)
  1437. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/narinfo (0.00s)
  1438. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/unknown_type (0.00s)
  1439. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/realisation (0.00s)
  1440. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)
  1441. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/empty_key (0.00s)
  1442. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/absolute (0.00s)
  1443. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)
  1444. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)
  1445. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/traversal (0.00s)
  1446. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)
  1447. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)
  1448. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)
  1449. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)
  1450. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)
  1451. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/nar_xz (0.00s)
  1452. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/nar_zst (0.00s)
  1453. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)
  1454. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/index.html (0.00s)
  1455. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)
  1456. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/build_log (0.00s)
  1457. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/listing (0.00s)
  1458. 7.21 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/nar_plain (0.00s)
  1459. 7.21 s [niks3-go-unit-tests] === CONT TestParseSingleRange/none
  1460. 7.21 s [niks3-go-unit-tests] === CONT TestParseSingleRange/malformed_both_empty
  1461. 7.21 s [niks3-go-unit-tests] === CONT TestParseSingleRange/closed
  1462. 7.21 s [niks3-go-unit-tests] === CONT TestParseSingleRange/open-ended
  1463. 7.21 s [niks3-go-unit-tests] === CONT TestParseSingleRange/malformed_end_before_start
  1464. 7.21 s [niks3-go-unit-tests] === CONT TestParseSingleRange/start_far_past_EOF
  1465. 7.21 s [niks3-go-unit-tests] === CONT TestParseSingleRange/start_past_EOF
  1466. 7.22 s [niks3-go-unit-tests] === CONT TestParseSingleRange/single_byte
  1467. 7.22 s [niks3-go-unit-tests] === CONT TestParseSingleRange/multi-range_ignored
  1468. 7.22 s [niks3-go-unit-tests] === CONT TestParseSingleRange/malformed_no_dash
  1469. 7.22 s [niks3-go-unit-tests] === CONT TestParseSingleRange/suffix_exceeds_size
  1470. 7.22 s [niks3-go-unit-tests] === CONT TestParseSingleRange/unknown_unit
  1471. 7.22 s [niks3-go-unit-tests] === CONT TestParseSingleRange/suffix
  1472. 7.22 s [niks3-go-unit-tests] === CONT TestParseSingleRange/end_clamped_to_size
  1473. 7.22 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange (0.00s)
  1474. 7.22 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/none (0.00s)
  1475. 7.22 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)
  1476. 7.22 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/closed (0.00s)
  1477. 7.22 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/open-ended (0.00s)
  1478. 7.22 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)
  1479. 7.22 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)
  1480. 7.22 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/start_past_EOF (0.00s)
  1481. 7.22 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/single_byte (0.00s)
  1482. 7.22 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)
  1483. 7.22 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)
  1484. 7.22 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)
  1485. 7.22 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/unknown_unit (0.00s)
  1486. 7.22 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/suffix (0.00s)
  1487. 7.22 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)
  1488. 7.22 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/narinfo
  1489. 7.22 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/wrong_extension
  1490. 7.22 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/leading_slash
  1491. 7.22 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/empty
  1492. 7.22 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/random_path
  1493. 7.22 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/invalid_char_u
  1494. 7.22 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/invalid_char_e
  1495. 7.22 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/traversal_in_middle
  1496. 7.22 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/traversal_parent
  1497. 7.22 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/short_hash
  1498. 7.22 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/index.html
  1499. 7.22 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/nix-cache-info
  1500. 7.22 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/realisation
  1501. 7.22 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/log
  1502. 7.22 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/ls
  1503. 7.22 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/nar_uncompressed
  1504. 7.22 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/nar_bz2
  1505. 7.22 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/nar_xz
  1506. 7.22 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/nar_zst
  1507. 7.22 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/narinfo_all_nix_base32_chars
  1508. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath (0.00s)
  1509. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/narinfo (0.00s)
  1510. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/wrong_extension (0.00s)
  1511. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/leading_slash (0.00s)
  1512. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/empty (0.00s)
  1513. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/random_path (0.00s)
  1514. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)
  1515. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)
  1516. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)
  1517. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/traversal_parent (0.00s)
  1518. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/short_hash (0.00s)
  1519. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/index.html (0.00s)
  1520. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)
  1521. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/realisation (0.00s)
  1522. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/log (0.00s)
  1523. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/ls (0.00s)
  1524. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)
  1525. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)
  1526. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/nar_xz (0.00s)
  1527. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/nar_zst (0.00s)
  1528. 7.22 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)
  1529. 7.22 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectOversizedBody/create_pending_closure
  1530. 7.22 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Received uploads request method=POST path=/
  1531. 7.22 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Vacuumed table table=pending_closures
  1532. 7.22 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Vacuumed table table=pending_closures
  1533. 7.22 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 2_object_stats_trigger.sql (13.34ms)
  1534. 7.22 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: up to current file version: 2
  1535. 7.22 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 2_object_stats_trigger.sql (13.55ms)
  1536. 7.22 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: up to current file version: 2
  1537. 7.22 s [niks3-go-unit-tests] 2026/07/18 13:59:35 WARN mTLS auth: subject not in bound subjects subject="CN=writer"
  1538. 7.22 s [niks3-go-unit-tests] --- PASS: TestService_ReadAuthMiddleware (0.70s)
  1539. 7.22 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectOversizedBody/request_more_parts
  1540. 7.22 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Received request for more parts method=POST path=/
  1541. 7.22 s [niks3-go-unit-tests] --- PASS: TestReadProxyRootRedirectsToIndexHTML (0.76s)
  1542. 7.22 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectOversizedBody/complete_multipart
  1543. 7.22 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Received complete multipart upload request method=POST path=/
  1544. 7.22 s [niks3-go-unit-tests] 2026-07-18 13:59:35.369 UTC [943] ERROR: relation "goose_db_version" does not exist at character 36
  1545. 7.22 s [niks3-go-unit-tests] 2026-07-18 13:59:35.369 UTC [943] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1546. 7.22 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20260628120000_add_object_size_and_stats.sql (13.36ms)
  1547. 7.22 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: successfully migrated database to version: 20260628120000
  1548. 7.24 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 1_commit_pending_closure.sql (15.95ms)
  1549. 7.24 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Vacuumed table table=pending_objects
  1550. 7.24 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Vacuumed table table=pending_objects
  1551. 7.24 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Vacuumed table table=multipart_uploads
  1552. 7.24 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Vacuumed table table=multipart_uploads
  1553. 7.25 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 2_object_stats_trigger.sql (8.67ms)
  1554. 7.25 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: up to current file version: 2
  1555. 7.25 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.54s)
  1556. 7.25 s [niks3-go-unit-tests] === CONT TestServerTLSConfig/no_client_CA
  1557. 7.25 s [niks3-go-unit-tests] === CONT TestServerTLSConfig/not_a_PEM_file
  1558. 7.25 s [niks3-go-unit-tests] === CONT TestServerTLSConfig/missing_CA_file
  1559. 7.25 s [niks3-go-unit-tests] --- PASS: TestServerTLSConfig (0.00s)
  1560. 7.25 s [niks3-go-unit-tests] --- PASS: TestServerTLSConfig/no_client_CA (0.00s)
  1561. 7.25 s [niks3-go-unit-tests] --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)
  1562. 7.25 s [niks3-go-unit-tests] --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)
  1563. 7.25 s [niks3-go-unit-tests] === CONT TestCacheConfigHandler/full_config,_no_issuer
  1564. 7.25 s [niks3-go-unit-tests] === CONT TestCacheConfigHandler/no_signing_keys
  1565. 7.25 s [niks3-go-unit-tests] === CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator
  1566. 7.25 s [niks3-go-unit-tests] === CONT TestCacheConfigHandler/no_cache_url_configured
  1567. 7.25 s [niks3-go-unit-tests] --- PASS: TestCacheConfigHandler (0.00s)
  1568. 7.25 s [niks3-go-unit-tests] --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)
  1569. 7.25 s [niks3-go-unit-tests] --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)
  1570. 7.25 s [niks3-go-unit-tests] --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)
  1571. 7.25 s [niks3-go-unit-tests] --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)
  1572. 7.25 s [niks3-go-unit-tests] === CONT TestClientErrorHandling/InvalidStorePath
  1573. 7.26 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Vacuumed table table=closures
  1574. 7.26 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20241026095416_initial_model.sql (16.07ms)
  1575. 7.26 s [niks3-go-unit-tests] === CONT TestClientErrorHandling/InvalidAuthToken
  1576. 7.26 s [niks3-go-unit-tests] === CONT TestClientErrorHandling/ServerNotAvailable
  1577. 7.27 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Vacuumed table table=closures
  1578. 7.27 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Vacuumed table table=objects
  1579. 7.27 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251210153512_drop_unused_gin_index.sql (16.08ms)
  1580. 7.29 s [niks3-go-unit-tests] 2026-07-18 13:59:35.432 UTC [946] ERROR: relation "goose_db_version" does not exist at character 36
  1581. 7.29 s [niks3-go-unit-tests] 2026-07-18 13:59:35.432 UTC [946] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1582. 7.29 s [niks3-go-unit-tests] 2026-07-18 13:59:35.433 UTC [947] ERROR: relation "goose_db_version" does not exist at character 36
  1583. 7.29 s [niks3-go-unit-tests] 2026-07-18 13:59:35.433 UTC [947] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1584. 7.29 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251218171726_add_pins.sql (16.67ms)
  1585. 7.30 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO Vacuumed table table=objects
  1586. 7.31 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20260628120000_add_object_size_and_stats.sql (15.6ms)
  1587. 7.31 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: successfully migrated database to version: 20260628120000
  1588. 7.32 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20241026095416_initial_model.sql (17.31ms)
  1589. 7.32 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 1_commit_pending_closure.sql (17.86ms)
  1590. 7.32 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20241026095416_initial_model.sql (17.39ms)
  1591. 7.33 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 2_object_stats_trigger.sql (8.12ms)
  1592. 7.33 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: up to current file version: 2
  1593. 7.33 s [niks3-go-unit-tests] --- PASS: TestReadProxy404 (0.61s)
  1594. 7.34 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251210153512_drop_unused_gin_index.sql (17.21ms)
  1595. 7.34 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251210153512_drop_unused_gin_index.sql (17.28ms)
  1596. 7.36 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251218171726_add_pins.sql (16.21ms)
  1597. 7.36 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251218171726_add_pins.sql (16.23ms)
  1598. 7.37 s [niks3-go-unit-tests] 2026-07-18 13:59:35.518 UTC [967] ERROR: relation "goose_db_version" does not exist at character 36
  1599. 7.37 s [niks3-go-unit-tests] 2026-07-18 13:59:35.518 UTC [967] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1600. 7.37 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20260628120000_add_object_size_and_stats.sql (18.34ms)
  1601. 7.38 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: successfully migrated database to version: 20260628120000
  1602. 7.38 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20260628120000_add_object_size_and_stats.sql (18.44ms)
  1603. 7.38 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: successfully migrated database to version: 20260628120000
  1604. 7.46 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 1_commit_pending_closure.sql (81ms)
  1605. 7.46 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 1_commit_pending_closure.sql (80.85ms)
  1606. 7.47 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20241026095416_initial_model.sql (15.13ms)
  1607. 7.47 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 2_object_stats_trigger.sql (15.92ms)
  1608. 7.47 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: up to current file version: 2
  1609. 7.47 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 2_object_stats_trigger.sql (15.91ms)
  1610. 7.47 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: up to current file version: 2
  1611. 7.47 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token
  1612. 7.47 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token
  1613. 7.47 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected
  1614. 7.48 s [niks3-go-unit-tests] 2026/07/18 13:59:35 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"
  1615. 7.48 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected
  1616. 7.48 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected
  1617. 7.48 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected
  1618. 7.48 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured
  1619. 7.48 s [niks3-go-unit-tests] 2026/07/18 13:59:35 WARN mTLS auth: bound subjects configured but subject DN unavailable
  1620. 7.48 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured
  1621. 7.48 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token
  1622. 7.48 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected
  1623. 7.48 s [niks3-go-unit-tests] 2026/07/18 13:59:35 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"
  1624. 7.48 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.78s)
  1625. 7.48 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected
  1626. 7.48 s [niks3-go-unit-tests] 2026/07/18 13:59:35 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]
  1627. 7.48 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured
  1628. 7.48 s [niks3-go-unit-tests] 2026/07/18 13:59:35 INFO OIDC auth successful provider=test
  1629. 7.48 s [niks3-go-unit-tests] 2026/07/18 13:59:35 WARN Authentication failed token_preview=eyJhbGciOi...hW6ArqV0Sg 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]
  1630. 7.48 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_OIDC (0.78s)
  1631. 7.48 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)
  1632. 7.48 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)
  1633. 7.48 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)
  1634. 7.48 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)
  1635. 7.48 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251210153512_drop_unused_gin_index.sql (12.49ms)
  1636. 7.50 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251218171726_add_pins.sql (16.15ms)
  1637. 7.52 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20260628120000_add_object_size_and_stats.sql (18.16ms)
  1638. 7.52 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: successfully migrated database to version: 20260628120000
  1639. 7.53 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 1_commit_pending_closure.sql (16ms)
  1640. 7.55 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 2_object_stats_trigger.sql (13.37ms)
  1641. 7.55 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: up to current file version: 2
  1642. 7.55 s [niks3-go-unit-tests] --- PASS: TestReadProxyInvalidPath (0.53s)
  1643. 7.61 s [niks3-go-unit-tests] 2026-07-18 13:59:35.753 UTC [969] ERROR: relation "goose_db_version" does not exist at character 36
  1644. 7.61 s [niks3-go-unit-tests] 2026-07-18 13:59:35.753 UTC [969] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1645. 7.61 s [niks3-go-unit-tests] 2026-07-18 13:59:35.753 UTC [970] ERROR: relation "goose_db_version" does not exist at character 36
  1646. 7.61 s [niks3-go-unit-tests] 2026-07-18 13:59:35.753 UTC [970] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1647. 7.62 s [niks3-go-unit-tests] 2026/07/18 13:59:35 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
  1648. 7.63 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20241026095416_initial_model.sql (13.31ms)
  1649. 7.64 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20241026095416_initial_model.sql (14.86ms)
  1650. 7.64 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251210153512_drop_unused_gin_index.sql (11.55ms)
  1651. 7.65 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251218171726_add_pins.sql (8.52ms)
  1652. 7.65 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251210153512_drop_unused_gin_index.sql (8.8ms)
  1653. 7.66 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251218171726_add_pins.sql (7.89ms)
  1654. 7.66 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20260628120000_add_object_size_and_stats.sql (8.02ms)
  1655. 7.66 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: successfully migrated database to version: 20260628120000
  1656. 7.66 s [niks3-go-unit-tests] 2026-07-18 13:59:35.807 UTC [1018] ERROR: relation "goose_db_version" does not exist at character 36
  1657. 7.66 s [niks3-go-unit-tests] 2026-07-18 13:59:35.807 UTC [1018] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1658. 7.66 s [niks3-go-unit-tests] 2026-07-18 13:59:35.807 UTC [1019] ERROR: relation "goose_db_version" does not exist at character 36
  1659. 7.66 s [niks3-go-unit-tests] 2026-07-18 13:59:35.807 UTC [1019] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1660. 7.67 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20260628120000_add_object_size_and_stats.sql (7.96ms)
  1661. 7.67 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: successfully migrated database to version: 20260628120000
  1662. 7.67 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 1_commit_pending_closure.sql (7.91ms)
  1663. 7.68 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 1_commit_pending_closure.sql (7.93ms)
  1664. 7.68 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 2_object_stats_trigger.sql (7.95ms)
  1665. 7.68 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: up to current file version: 2
  1666. 7.68 s [niks3-go-unit-tests] --- PASS: TestReadProxyNarStreaming (0.60s)
  1667. 7.68 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20241026095416_initial_model.sql (12.06ms)
  1668. 7.68 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20241026095416_initial_model.sql (12.04ms)
  1669. 7.69 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 2_object_stats_trigger.sql (8.94ms)
  1670. 7.69 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: up to current file version: 2
  1671. 7.69 s [niks3-go-unit-tests] --- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.55s)
  1672. 7.69 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251210153512_drop_unused_gin_index.sql (9.03ms)
  1673. 7.69 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251210153512_drop_unused_gin_index.sql (9.1ms)
  1674. 7.70 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251218171726_add_pins.sql (8.69ms)
  1675. 7.70 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20251218171726_add_pins.sql (8.7ms)
  1676. 7.71 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20260628120000_add_object_size_and_stats.sql (8.16ms)
  1677. 7.71 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: successfully migrated database to version: 20260628120000
  1678. 7.71 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 20260628120000_add_object_size_and_stats.sql (8.24ms)
  1679. 7.71 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: successfully migrated database to version: 20260628120000
  1680. 7.72 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 1_commit_pending_closure.sql (8.73ms)
  1681. 7.72 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 1_commit_pending_closure.sql (8.85ms)
  1682. 7.73 s [niks3-go-unit-tests] 2026/07/18 13:59:35 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=219.768221ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures
  1683. 7.73 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 2_object_stats_trigger.sql (9.11ms)
  1684. 7.73 s [niks3-go-unit-tests] 2026/07/18 13:59:35 OK 2_object_stats_trigger.sql (9.11ms)
  1685. 7.73 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: up to current file version: 2
  1686. 7.73 s [niks3-go-unit-tests] 2026/07/18 13:59:35 goose: up to current file version: 2
  1687. 7.81 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectOversizedBody (0.20s)
  1688. 7.81 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)
  1689. 7.81 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)
  1690. 7.81 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.60s)
  1691. 7.95 s [niks3-go-unit-tests] 2026/07/18 13:59:36 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=424.080317ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures
  1692. 8.01 s [niks3-go-unit-tests] 2026/07/18 13:59:36 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"
  1693. 8.35 s [niks3-go-unit-tests] === NAME TestOrphanedObjectsGCStressTest
  1694. 8.35 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains
  1695. 8.37 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:446: Marked 210 objects for deletion
  1696. 8.37 s [niks3-go-unit-tests] 2026/07/18 13:59:36 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=825.591787ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures
  1697. 8.45 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:509: Stress test completed successfully:
  1698. 8.45 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:510: - Active objects preserved: 20
  1699. 8.45 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:511: - Objects deleted: 210
  1700. 8.45 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:512: - Total GC'd: 210
  1701. 8.45 s [niks3-go-unit-tests] --- PASS: TestOrphanedObjectsGCStressTest (4.19s)
  1702. 8.67 s [niks3-go-unit-tests] 2026/07/18 13:59:36 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=0
  1703. 8.67 s [niks3-go-unit-tests] === NAME TestClientIntegration
  1704. 8.67 s [niks3-go-unit-tests] client_integration_test.go:303: Objects in database after GC:
  1705. 8.67 s [niks3-go-unit-tests] client_integration_test.go:303: Successfully deleted all objects with GC --force
  1706. 8.67 s [niks3-go-unit-tests] --- PASS: TestClientIntegration (3.35s)
  1707. 8.69 s [niks3-go-unit-tests] 2026/07/18 13:59:36 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=0
  1708. 8.69 s [niks3-go-unit-tests] === NAME TestPinProtectsFromGC
  1709. 8.69 s [niks3-go-unit-tests] client_integration_test.go:709: Pin successfully protected closure from garbage collection
  1710. 8.69 s [niks3-go-unit-tests] --- PASS: TestPinProtectsFromGC (3.60s)
  1711. 8.75 s [niks3-go-unit-tests] 2026/07/18 13:59:36 WARN Rate limiter enabled after throttle name=s3-test rate=5
  1712. 8.75 s [niks3-go-unit-tests] 2026/07/18 13:59:36 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."
  1713. 8.75 s [niks3-go-unit-tests] === NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle
  1714. 8.75 s [niks3-go-unit-tests] throttle_test.go:213: Proxy stats: total=15, throttled=10, completeMultipart=10
  1715. 8.75 s [niks3-go-unit-tests] throttle_test.go:215: Rate limiter: enabled=true, rate=5.00
  1716. 8.75 s [niks3-go-unit-tests] --- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.61s)
  1717. 9.20 s [niks3-go-unit-tests] 2026/07/18 13:59:37 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.674097446s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures
  1718. 10.87 s [niks3-go-unit-tests] --- PASS: TestClientErrorHandling (0.00s)
  1719. 11.08 s [niks3-go-unit-tests] --- PASS: TestClientErrorHandling/InvalidStorePath (0.50s)
  1720. 11.08 s [niks3-go-unit-tests] --- PASS: TestClientErrorHandling/InvalidAuthToken (0.75s)
  1721. 11.08 s [niks3-go-unit-tests] --- PASS: TestClientErrorHandling/ServerNotAvailable (3.61s)
  1722. 11.08 s [niks3-go-unit-tests] PASS
  1723. 11.38 s [niks3-go-unit-tests] {"timestamp":"2026-07-18T13:59:39.520754556Z","level":"ERROR","fields":{"message":"Unknown connection IO error:Cancelled","peer_addr":"127.0.0.1:59772"},"target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":973,"threadName":"rustfs-worker","threadId":"ThreadId(27)"}
  1724. 11.42 s [niks3-go-unit-tests] 2026-07-18 13:59:39.567 UTC [94] LOG: received smart shutdown request
  1725. 11.43 s [niks3-go-unit-tests] 2026-07-18 13:59:39.577 UTC [94] LOG: background worker "logical replication launcher" (PID 106) exited with exit code 1
  1726. 11.44 s [niks3-go-unit-tests] 2026-07-18 13:59:39.582 UTC [99] LOG: shutting down
  1727. 11.45 s [niks3-go-unit-tests] 2026-07-18 13:59:39.590 UTC [99] LOG: checkpoint starting: shutdown immediate
  1728. 20.88 s [niks3-go-unit-tests] 2026/07/18 13:59:49 ERROR failed to kill rustfs error="no such process"
  1729. 21.42 s [niks3-go-unit-tests] 2026/07/18 13:59:49 INFO killed rustfs
  1730. 21.43 s [niks3-go-unit-tests] 2026/07/18 13:59:49 ERROR failed to wait for rustfs error="signal: killed"
  1731. 21.47 s [niks3-go-unit-tests] 2026-07-18 13:59:49.614 UTC [99] PANIC: could not fsync file "base/16499/2831": No such file or directory
  1732. 21.77 s [niks3-go-unit-tests] Running OIDC tests...
  1733. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch
  1734. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch
  1735. 21.77 s [niks3-go-unit-tests] === RUN TestAudienceForIssuer
  1736. 21.77 s [niks3-go-unit-tests] === PAUSE TestAudienceForIssuer
  1737. 21.77 s [niks3-go-unit-tests] === RUN TestValidateToken_ValidToken
  1738. 21.77 s [niks3-go-unit-tests] === PAUSE TestValidateToken_ValidToken
  1739. 21.77 s [niks3-go-unit-tests] === RUN TestValidateToken_WrongAudience
  1740. 21.77 s [niks3-go-unit-tests] === PAUSE TestValidateToken_WrongAudience
  1741. 21.77 s [niks3-go-unit-tests] === RUN TestValidateToken_Expired
  1742. 21.77 s [niks3-go-unit-tests] === PAUSE TestValidateToken_Expired
  1743. 21.77 s [niks3-go-unit-tests] === RUN TestValidateToken_BoundClaimsMismatch
  1744. 21.77 s [niks3-go-unit-tests] === PAUSE TestValidateToken_BoundClaimsMismatch
  1745. 21.77 s [niks3-go-unit-tests] === RUN TestValidateToken_BoundSubjectMismatch
  1746. 21.77 s [niks3-go-unit-tests] === PAUSE TestValidateToken_BoundSubjectMismatch
  1747. 21.77 s [niks3-go-unit-tests] === RUN TestValidateToken_MultipleProviders
  1748. 21.77 s [niks3-go-unit-tests] === PAUSE TestValidateToken_MultipleProviders
  1749. 21.77 s [niks3-go-unit-tests] === RUN TestValidateToken_NoMatchingProvider
  1750. 21.77 s [niks3-go-unit-tests] === PAUSE TestValidateToken_NoMatchingProvider
  1751. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch
  1752. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo_foo
  1753. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo_foo
  1754. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo_bar
  1755. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo_bar
  1756. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/*_
  1757. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*_
  1758. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/*_anything
  1759. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*_anything
  1760. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo*_foo
  1761. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo*_foo
  1762. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo*_foobar
  1763. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo*_foobar
  1764. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo*_bar
  1765. 21.77 s [niks3-go-unit-tests] === CONT TestValidateToken_Expired
  1766. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo*_bar
  1767. 21.77 s [niks3-go-unit-tests] === CONT TestValidateToken_ValidToken
  1768. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/*bar_bar
  1769. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*bar_bar
  1770. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/*bar_foobar
  1771. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*bar_foobar
  1772. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/*bar_foo
  1773. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*bar_foo
  1774. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo*bar_foobar
  1775. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo*bar_foobar
  1776. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo*bar_foo123bar
  1777. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo*bar_foo123bar
  1778. 21.77 s [niks3-go-unit-tests] === CONT TestAudienceForIssuer
  1779. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo*bar_foobarbaz
  1780. 21.77 s [niks3-go-unit-tests] --- PASS: TestAudienceForIssuer (0.00s)
  1781. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo*bar_foobarbaz
  1782. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/*/*_foo/bar
  1783. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*/*_foo/bar
  1784. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/*/*_foo
  1785. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*/*_foo
  1786. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/refs/heads/*_refs/heads/main
  1787. 21.77 s [niks3-go-unit-tests] === CONT TestValidateToken_WrongAudience
  1788. 21.77 s [niks3-go-unit-tests] === CONT TestValidateToken_MultipleProviders
  1789. 21.77 s [niks3-go-unit-tests] === CONT TestValidateToken_NoMatchingProvider
  1790. 21.77 s [niks3-go-unit-tests] === CONT TestValidateToken_BoundSubjectMismatch
  1791. 21.77 s [niks3-go-unit-tests] === CONT TestValidateToken_BoundClaimsMismatch
  1792. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/refs/heads/*_refs/heads/main
  1793. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/refs/heads/*_refs/tags/v1.0
  1794. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.0
  1795. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/refs/*/main_refs/heads/main
  1796. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/refs/*/main_refs/heads/main
  1797. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/fo?_foo
  1798. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/fo?_foo
  1799. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/fo?_fo
  1800. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/fo?_fo
  1801. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/fo?_fooo
  1802. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/fo?_fooo
  1803. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/?oo_foo
  1804. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/?oo_foo
  1805. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/?oo_boo
  1806. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/?oo_boo
  1807. 21.77 s [niks3-go-unit-tests] 2026/07/18 13:59:49 INFO OIDC provider initialized name=test
  1808. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main
  1809. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main
  1810. 21.77 s [niks3-go-unit-tests] === RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main
  1811. 21.77 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main
  1812. 21.77 s [niks3-go-unit-tests] 2026/07/18 13:59:49 INFO OIDC provider initialized name=test
  1813. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo_foo
  1814. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main
  1815. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main
  1816. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo*bar_foo123bar
  1817. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/refs/*/main_refs/heads/main
  1818. 21.77 s [niks3-go-unit-tests] 2026/07/18 13:59:49 INFO OIDC provider initialized name=provider1
  1819. 21.77 s [niks3-go-unit-tests] 2026/07/18 13:59:49 INFO OIDC provider initialized name=test
  1820. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo*bar_foobarbaz
  1821. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/?oo_boo
  1822. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/refs/heads/*_refs/heads/main
  1823. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/*/*_foo
  1824. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo*_bar
  1825. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/*/*_foo/bar
  1826. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo*bar_foobar
  1827. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/?oo_foo
  1828. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/fo?_fooo
  1829. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/fo?_fo
  1830. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/*bar_foo
  1831. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/*bar_bar
  1832. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/*_anything
  1833. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/fo?_foo
  1834. 21.77 s [niks3-go-unit-tests] 2026/07/18 13:59:49 INFO OIDC provider initialized name=provider1
  1835. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/refs/heads/*_refs/tags/v1.0
  1836. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo*_foobar
  1837. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo_bar
  1838. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/*bar_foobar
  1839. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/*_
  1840. 21.77 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo*_foo
  1841. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch (0.00s)
  1842. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo_foo (0.00s)
  1843. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)
  1844. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)
  1845. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)
  1846. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)
  1847. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)
  1848. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)
  1849. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*/*_foo (0.00s)
  1850. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/?oo_boo (0.00s)
  1851. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo*_bar (0.00s)
  1852. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)
  1853. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)
  1854. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*bar_foo (0.00s)
  1855. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*bar_bar (0.00s)
  1856. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*_anything (0.00s)
  1857. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/fo?_fooo (0.00s)
  1858. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/?oo_foo (0.00s)
  1859. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/fo?_fo (0.00s)
  1860. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/fo?_foo (0.00s)
  1861. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)
  1862. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo*_foobar (0.00s)
  1863. 21.77 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo_bar (0.00s)
  1864. 21.78 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*bar_foobar (0.00s)
  1865. 21.78 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*_ (0.00s)
  1866. 21.78 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo*_foo (0.00s)
  1867. 21.78 s [niks3-go-unit-tests] 2026/07/18 13:59:49 INFO OIDC provider initialized name=test
  1868. 21.78 s [niks3-go-unit-tests] 2026/07/18 13:59:49 INFO OIDC provider initialized name=test
  1869. 21.78 s [niks3-go-unit-tests] 2026/07/18 13:59:49 INFO OIDC provider initialized name=provider2
  1870. 21.78 s [niks3-go-unit-tests] --- PASS: TestValidateToken_ValidToken (0.00s)
  1871. 21.78 s [niks3-go-unit-tests] --- PASS: TestValidateToken_WrongAudience (0.00s)
  1872. 21.78 s [niks3-go-unit-tests] --- PASS: TestValidateToken_Expired (0.00s)
  1873. 21.78 s [niks3-go-unit-tests] --- PASS: TestValidateToken_NoMatchingProvider (0.00s)
  1874. 21.78 s [niks3-go-unit-tests] --- PASS: TestValidateToken_BoundSubjectMismatch (0.00s)
  1875. 21.78 s [niks3-go-unit-tests] --- PASS: TestValidateToken_BoundClaimsMismatch (0.00s)
  1876. 21.78 s [niks3-go-unit-tests] --- PASS: TestValidateToken_MultipleProviders (0.01s)
  1877. 21.78 s [niks3-go-unit-tests] PASS
  1878. 21.78 s [niks3-go-unit-tests] Running hook tests...
  1879. 21.78 s [niks3-go-unit-tests] === RUN TestSendPathsEmpty
  1880. 21.78 s [niks3-go-unit-tests] === PAUSE TestSendPathsEmpty
  1881. 21.78 s [niks3-go-unit-tests] === RUN TestQueueEnqueueAndFetch
  1882. 21.78 s [niks3-go-unit-tests] === PAUSE TestQueueEnqueueAndFetch
  1883. 21.78 s [niks3-go-unit-tests] === RUN TestQueueDeduplication
  1884. 21.78 s [niks3-go-unit-tests] === PAUSE TestQueueDeduplication
  1885. 21.78 s [niks3-go-unit-tests] === RUN TestQueueRemove
  1886. 21.78 s [niks3-go-unit-tests] === PAUSE TestQueueRemove
  1887. 21.78 s [niks3-go-unit-tests] === RUN TestQueueFetchBatchLimit
  1888. 21.78 s [niks3-go-unit-tests] === PAUSE TestQueueFetchBatchLimit
  1889. 21.78 s [niks3-go-unit-tests] === RUN TestQueueFetchRemoveLifecycle
  1890. 21.78 s [niks3-go-unit-tests] === PAUSE TestQueueFetchRemoveLifecycle
  1891. 21.78 s [niks3-go-unit-tests] === RUN TestQueueConcurrentWriters
  1892. 21.78 s [niks3-go-unit-tests] === PAUSE TestQueueConcurrentWriters
  1893. 21.78 s [niks3-go-unit-tests] === RUN TestServerClientIntegration
  1894. 21.78 s [niks3-go-unit-tests] === PAUSE TestServerClientIntegration
  1895. 21.78 s [niks3-go-unit-tests] === RUN TestServerQueueError
  1896. 21.78 s [niks3-go-unit-tests] === PAUSE TestServerQueueError
  1897. 21.78 s [niks3-go-unit-tests] === RUN TestGetListenerSocketActivation
  1898. 21.78 s [niks3-go-unit-tests] server_test.go:210: === RUN TestGetListenerSocketActivation
  1899. 21.78 s [niks3-go-unit-tests] --- PASS: TestGetListenerSocketActivation (0.00s)
  1900. 21.78 s [niks3-go-unit-tests] PASS
  1901. 21.78 s [niks3-go-unit-tests]
  1902. 21.78 s [niks3-go-unit-tests] --- PASS: TestGetListenerSocketActivation (0.00s)
  1903. 21.78 s [niks3-go-unit-tests] === RUN TestWorkerUploadsAndRemoves
  1904. 21.78 s [niks3-go-unit-tests] === PAUSE TestWorkerUploadsAndRemoves
  1905. 21.78 s [niks3-go-unit-tests] === RUN TestWorkerSkipsGCdPaths
  1906. 21.78 s [niks3-go-unit-tests] === PAUSE TestWorkerSkipsGCdPaths
  1907. 21.78 s [niks3-go-unit-tests] === RUN TestWorkerPrunesClosureDeps
  1908. 21.78 s [niks3-go-unit-tests] === PAUSE TestWorkerPrunesClosureDeps
  1909. 21.78 s [niks3-go-unit-tests] === CONT TestSendPathsEmpty
  1910. 21.78 s [niks3-go-unit-tests] --- PASS: TestSendPathsEmpty (0.00s)
  1911. 21.78 s [niks3-go-unit-tests] === CONT TestQueueFetchRemoveLifecycle
  1912. 21.78 s [niks3-go-unit-tests] === CONT TestQueueConcurrentWriters
  1913. 21.78 s [niks3-go-unit-tests] === CONT TestQueueRemove
  1914. 21.78 s [niks3-go-unit-tests] === CONT TestWorkerUploadsAndRemoves
  1915. 21.78 s [niks3-go-unit-tests] === CONT TestServerQueueError
  1916. 21.78 s [niks3-go-unit-tests] === CONT TestQueueFetchBatchLimit
  1917. 21.78 s [niks3-go-unit-tests] === CONT TestWorkerSkipsGCdPaths
  1918. 21.78 s [niks3-go-unit-tests] === CONT TestServerClientIntegration
  1919. 21.78 s [niks3-go-unit-tests] === CONT TestWorkerPrunesClosureDeps
  1920. 21.78 s [niks3-go-unit-tests] === CONT TestQueueEnqueueAndFetch
  1921. 21.78 s [niks3-go-unit-tests] === CONT TestQueueDeduplication
  1922. 21.78 s [niks3-go-unit-tests] 2026/07/18 13:59:49 ERROR Failed to queue paths error="permission denied" count=1
  1923. 21.78 s [niks3-go-unit-tests] --- PASS: TestServerQueueError (0.00s)
  1924. 21.78 s [niks3-go-unit-tests] --- PASS: TestServerClientIntegration (0.00s)
  1925. 21.89 s [niks3-go-unit-tests] 2026/07/18 13:59:50 INFO Upload queue status pending=2
  1926. 21.89 s [niks3-go-unit-tests] 2026/07/18 13:59:50 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths2674978621/002/nonexistent
  1927. 21.90 s [niks3-go-unit-tests] 2026/07/18 13:59:50 INFO Upload queue status pending=2
  1928. 21.90 s [niks3-go-unit-tests] 2026/07/18 13:59:50 INFO Uploading batch count=2
  1929. 21.90 s [niks3-go-unit-tests] 2026/07/18 13:59:50 INFO Upload queue status pending=2
  1930. 21.90 s [niks3-go-unit-tests] 2026/07/18 13:59:50 INFO Uploading batch count=1
  1931. 21.91 s [niks3-go-unit-tests] 2026/07/18 13:59:50 INFO Uploading batch count=1
  1932. 21.92 s [niks3-go-unit-tests] --- PASS: TestQueueEnqueueAndFetch (0.14s)
  1933. 21.92 s [niks3-go-unit-tests] --- PASS: TestQueueFetchBatchLimit (0.14s)
  1934. 21.95 s [niks3-go-unit-tests] --- PASS: TestQueueDeduplication (0.16s)
  1935. 21.95 s [niks3-go-unit-tests] --- PASS: TestQueueFetchRemoveLifecycle (0.16s)
  1936. 21.95 s [niks3-go-unit-tests] --- PASS: TestQueueRemove (0.16s)
  1937. 21.96 s [niks3-go-unit-tests] --- PASS: TestWorkerSkipsGCdPaths (0.18s)
  1938. 21.97 s [niks3-go-unit-tests] --- PASS: TestWorkerUploadsAndRemoves (0.19s)
  1939. 21.97 s [niks3-go-unit-tests] --- PASS: TestWorkerPrunesClosureDeps (0.19s)
  1940. 25.89 s [niks3-go-unit-tests] --- PASS: TestQueueConcurrentWriters (4.11s)
  1941. 25.95 s [niks3-go-unit-tests] PASS
  1942. 25.95 s [niks3-go-unit-tests:post-build] Uploading to the NixCI staging cache: /nix/store/1r8jnwdi8jf680rcyflvqw27pq1wddl8-niks3-go-unit-tests
  1943. 25.97 s [niks3-go-unit-tests:post-build] warning: 'warn-short-path-literals' is deprecated, use 'lint-short-path-literals = ignore' instead
  1944. 25.97 s [niks3-go-unit-tests:post-build] copying 1 paths...
  1945. 25.97 s [niks3-go-unit-tests:post-build] copying path '/nix/store/1r8jnwdi8jf680rcyflvqw27pq1wddl8-niks3-go-unit-tests' to 'https://cache.staging.nix-ci.com'...
  1946. 26.09 s [niks3-go-unit-tests:post-build] warning: 'warn-short-path-literals' is deprecated, use 'lint-short-path-literals = ignore' instead
  1947. 26.32 s [niks3-go-unit-tests:post-build] copying 1 paths...
  1948. 26.33 s [niks3-go-unit-tests:post-build] copying path '/nix/store/ibzpr9nh877a7qy0hb3g69ljr4p8f497-niks3-go-unit-tests.drv' to 'https://cache.staging.nix-ci.com'...
  1949. 26.50 s Uploaded niks3-go-unit-tests in 544ms
  1950. 26.50 s Progress: 1 of 2 built
  1951. 26.50 s Built niks3-go-unit-tests in 24.8s
  1952. 26.51 s Progress: 2 of 2 built
  1953. 26.51 s /nix/store/1r8jnwdi8jf680rcyflvqw27pq1wddl8-niks3-go-unit-tests
  1954. 26.55 s Build succeeded.
Tail Raw Logs