build checks.x86_64-linux.go-unit-tests

Reproduce this run
  1. 0.11 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=d0828f309b75bf7f847e794f1920e290d23110d7#checks.x86_64-linux.go-unit-tests --print-build-logs
  2. 1.11 s
  3. 1.68 s Building /nix/store/8xipwkfxjjac5vxawzdhwbglb2z0mbmk-niks3-go-unit-tests.drv
  4. 1.78 s [niks3-go-unit-tests] Running client tests...
  5. 1.79 s [niks3-go-unit-tests] === RUN TestDoServerRequestAttachesToken
  6. 1.79 s [niks3-go-unit-tests] === PAUSE TestDoServerRequestAttachesToken
  7. 1.79 s [niks3-go-unit-tests] === RUN TestCaseHackSuffix
  8. 1.79 s [niks3-go-unit-tests] === PAUSE TestCaseHackSuffix
  9. 1.79 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR
  10. 1.79 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR
  11. 1.79 s [niks3-go-unit-tests] === RUN TestUploadMultipart_SupersededByPeer
  12. 1.79 s [niks3-go-unit-tests] === PAUSE TestUploadMultipart_SupersededByPeer
  13. 1.79 s [niks3-go-unit-tests] === RUN TestDumpPathMatchesNix
  14. 1.79 s [niks3-go-unit-tests] === PAUSE TestDumpPathMatchesNix
  15. 1.79 s [niks3-go-unit-tests] === RUN TestDumpPathSingleFile
  16. 1.79 s [niks3-go-unit-tests] === PAUSE TestDumpPathSingleFile
  17. 1.79 s [niks3-go-unit-tests] === RUN TestDumpPathWriterError
  18. 1.79 s [niks3-go-unit-tests] === PAUSE TestDumpPathWriterError
  19. 1.79 s [niks3-go-unit-tests] === RUN TestEncodeNixBase32
  20. 1.79 s [niks3-go-unit-tests] === PAUSE TestEncodeNixBase32
  21. 1.79 s [niks3-go-unit-tests] === RUN TestEncodeNixBase32WithRealHash
  22. 1.79 s [niks3-go-unit-tests] === PAUSE TestEncodeNixBase32WithRealHash
  23. 1.79 s [niks3-go-unit-tests] === RUN TestConvertHashToNix32
  24. 1.79 s [niks3-go-unit-tests] === PAUSE TestConvertHashToNix32
  25. 1.79 s [niks3-go-unit-tests] === RUN TestGetStorePathHash
  26. 1.79 s [niks3-go-unit-tests] === PAUSE TestGetStorePathHash
  27. 1.79 s [niks3-go-unit-tests] === RUN TestPathInfoHashCompatibility
  28. 1.79 s [niks3-go-unit-tests] === PAUSE TestPathInfoHashCompatibility
  29. 1.79 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSON
  30. 1.79 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSON
  31. 1.79 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSONMultiplePaths
  32. 1.79 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSONMultiplePaths
  33. 1.79 s [niks3-go-unit-tests] === RUN TestPathInfoCACompatibility
  34. 1.79 s [niks3-go-unit-tests] === PAUSE TestPathInfoCACompatibility
  35. 1.79 s [niks3-go-unit-tests] === RUN TestRateLimiterFeedback
  36. 1.79 s [niks3-go-unit-tests] === PAUSE TestRateLimiterFeedback
  37. 1.79 s [niks3-go-unit-tests] === RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess
  38. 1.79 s [niks3-go-unit-tests] === PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess
  39. 1.79 s [niks3-go-unit-tests] === RUN TestResolveStorePath
  40. 1.79 s [niks3-go-unit-tests] === PAUSE TestResolveStorePath
  41. 1.79 s [niks3-go-unit-tests] === RUN TestDoWithRetry_BodyReplayedViaGetBody
  42. 1.79 s [niks3-go-unit-tests] === PAUSE TestDoWithRetry_BodyReplayedViaGetBody
  43. 1.79 s [niks3-go-unit-tests] === RUN TestShellSplit
  44. 1.79 s [niks3-go-unit-tests] === PAUSE TestShellSplit
  45. 1.79 s [niks3-go-unit-tests] === RUN TestShellSplitErrors
  46. 1.79 s [niks3-go-unit-tests] === PAUSE TestShellSplitErrors
  47. 1.79 s [niks3-go-unit-tests] === RUN TestSetClientTLS
  48. 1.79 s [niks3-go-unit-tests] === PAUSE TestSetClientTLS
  49. 1.79 s [niks3-go-unit-tests] === RUN TestSetClientTLSDoesNotMutateDefaultTransport
  50. 1.79 s [niks3-go-unit-tests] === PAUSE TestSetClientTLSDoesNotMutateDefaultTransport
  51. 1.79 s [niks3-go-unit-tests] === RUN TestSetClientTLSErrors
  52. 1.79 s [niks3-go-unit-tests] === PAUSE TestSetClientTLSErrors
  53. 1.79 s [niks3-go-unit-tests] === RUN TestStaticToken
  54. 1.79 s [niks3-go-unit-tests] === PAUSE TestStaticToken
  55. 1.79 s [niks3-go-unit-tests] === RUN TestFileTokenReadsAndCaches
  56. 1.79 s [niks3-go-unit-tests] === PAUSE TestFileTokenReadsAndCaches
  57. 1.79 s [niks3-go-unit-tests] === RUN TestFileTokenMissing
  58. 1.79 s [niks3-go-unit-tests] === PAUSE TestFileTokenMissing
  59. 1.79 s [niks3-go-unit-tests] === RUN TestFileTokenEmpty
  60. 1.79 s [niks3-go-unit-tests] === PAUSE TestFileTokenEmpty
  61. 1.79 s [niks3-go-unit-tests] === RUN TestScriptTokenNoExpiryRerunsEveryCall
  62. 1.79 s [niks3-go-unit-tests] === PAUSE TestScriptTokenNoExpiryRerunsEveryCall
  63. 1.79 s [niks3-go-unit-tests] === RUN TestScriptTokenCachesUntilRefresh
  64. 1.79 s [niks3-go-unit-tests] === PAUSE TestScriptTokenCachesUntilRefresh
  65. 1.79 s [niks3-go-unit-tests] === RUN TestScriptTokenEmptyToken
  66. 1.79 s [niks3-go-unit-tests] === PAUSE TestScriptTokenEmptyToken
  67. 1.79 s [niks3-go-unit-tests] === RUN TestScriptTokenBadJSON
  68. 1.79 s [niks3-go-unit-tests] === PAUSE TestScriptTokenBadJSON
  69. 1.79 s [niks3-go-unit-tests] === RUN TestScriptTokenScriptFails
  70. 1.79 s [niks3-go-unit-tests] === PAUSE TestScriptTokenScriptFails
  71. 1.79 s [niks3-go-unit-tests] === RUN TestScriptTokenEmptyCommand
  72. 1.79 s [niks3-go-unit-tests] === PAUSE TestScriptTokenEmptyCommand
  73. 1.79 s [niks3-go-unit-tests] === CONT TestDoServerRequestAttachesToken
  74. 1.79 s [niks3-go-unit-tests] === CONT TestConvertHashToNix32
  75. 1.79 s [niks3-go-unit-tests] === CONT TestResolveStorePath
  76. 1.79 s [niks3-go-unit-tests] === CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess
  77. 1.79 s [niks3-go-unit-tests] === CONT TestDumpPathSingleFile
  78. 1.79 s [niks3-go-unit-tests] === RUN TestConvertHashToNix32/SRI_format_to_Nix32
  79. 1.79 s [niks3-go-unit-tests] === PAUSE TestConvertHashToNix32/SRI_format_to_Nix32
  80. 1.79 s [niks3-go-unit-tests] === RUN TestConvertHashToNix32/already_Nix32_format
  81. 1.79 s [niks3-go-unit-tests] === PAUSE TestConvertHashToNix32/already_Nix32_format
  82. 1.79 s [niks3-go-unit-tests] === RUN TestConvertHashToNix32/invalid_format
  83. 1.79 s [niks3-go-unit-tests] === PAUSE TestConvertHashToNix32/invalid_format
  84. 1.79 s [niks3-go-unit-tests] === CONT TestConvertHashToNix32/SRI_format_to_Nix32
  85. 1.79 s [niks3-go-unit-tests] === CONT TestEncodeNixBase32
  86. 1.79 s [niks3-go-unit-tests] === CONT TestScriptTokenEmptyToken
  87. 1.79 s [niks3-go-unit-tests] 2026/07/19 10:23:53 WARN Rate limiter enabled after throttle name=server-test rate=5
  88. 1.79 s [niks3-go-unit-tests] === CONT TestConvertHashToNix32/invalid_format
  89. 1.79 s [niks3-go-unit-tests] === CONT TestConvertHashToNix32/already_Nix32_format
  90. 1.79 s [niks3-go-unit-tests] --- PASS: TestConvertHashToNix32 (0.00s)
  91. 1.79 s [niks3-go-unit-tests] --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)
  92. 1.79 s [niks3-go-unit-tests] --- PASS: TestConvertHashToNix32/invalid_format (0.00s)
  93. 1.79 s [niks3-go-unit-tests] --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)
  94. 1.79 s [niks3-go-unit-tests] === CONT TestEncodeNixBase32WithRealHash
  95. 1.79 s [niks3-go-unit-tests] --- PASS: TestEncodeNixBase32WithRealHash (0.00s)
  96. 1.79 s [niks3-go-unit-tests] === CONT TestDumpPathWriterError
  97. 1.79 s [niks3-go-unit-tests] === CONT TestScriptTokenNoExpiryRerunsEveryCall
  98. 1.79 s [niks3-go-unit-tests] --- PASS: TestResolveStorePath (0.00s)
  99. 1.79 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSONMultiplePaths
  100. 1.79 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths
  101. 1.79 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths
  102. 1.79 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths
  103. 1.79 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths
  104. 1.79 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSON
  105. 1.79 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSON/Nix_format
  106. 1.79 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSON/Nix_format
  107. 1.79 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSON/Lix_format
  108. 1.79 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSON/Lix_format
  109. 1.79 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSON/empty_input
  110. 1.79 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSON/empty_input
  111. 1.79 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSON/whitespace_only
  112. 1.79 s [niks3-go-unit-tests] === CONT TestFileTokenMissing
  113. 1.79 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSON/whitespace_only
  114. 1.79 s [niks3-go-unit-tests] === RUN TestParsePathInfoJSON/invalid_JSON
  115. 1.79 s [niks3-go-unit-tests] === CONT TestRateLimiterFeedback
  116. 1.79 s [niks3-go-unit-tests] === PAUSE TestParsePathInfoJSON/invalid_JSON
  117. 1.79 s [niks3-go-unit-tests] === RUN TestRateLimiterFeedback/429_enables_limiter
  118. 1.79 s [niks3-go-unit-tests] === PAUSE TestRateLimiterFeedback/429_enables_limiter
  119. 1.79 s [niks3-go-unit-tests] === RUN TestRateLimiterFeedback/503_enables_limiter
  120. 1.79 s [niks3-go-unit-tests] === PAUSE TestRateLimiterFeedback/503_enables_limiter
  121. 1.79 s [niks3-go-unit-tests] === RUN TestRateLimiterFeedback/200_does_not_enable_limiter
  122. 1.79 s [niks3-go-unit-tests] === PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter
  123. 1.79 s [niks3-go-unit-tests] === RUN TestEncodeNixBase32/test_string_hash
  124. 1.79 s [niks3-go-unit-tests] === PAUSE TestEncodeNixBase32/test_string_hash
  125. 1.79 s [niks3-go-unit-tests] === RUN TestEncodeNixBase32/empty_input
  126. 1.79 s [niks3-go-unit-tests] === PAUSE TestEncodeNixBase32/empty_input
  127. 1.79 s [niks3-go-unit-tests] === CONT TestScriptTokenScriptFails
  128. 1.79 s [niks3-go-unit-tests] === CONT TestScriptTokenEmptyCommand
  129. 1.79 s [niks3-go-unit-tests] === CONT TestUploadMultipart_SupersededByPeer
  130. 1.79 s [niks3-go-unit-tests] --- PASS: TestFileTokenMissing (0.00s)
  131. 1.79 s [niks3-go-unit-tests] --- PASS: TestScriptTokenEmptyCommand (0.00s)
  132. 1.79 s [niks3-go-unit-tests] === RUN TestRateLimiterFeedback/400_does_not_enable_limiter
  133. 1.79 s [niks3-go-unit-tests] === CONT TestScriptTokenBadJSON
  134. 1.79 s [niks3-go-unit-tests] === CONT TestPathInfoCACompatibility
  135. 1.79 s [niks3-go-unit-tests] === CONT TestPathInfoHashCompatibility
  136. 1.79 s [niks3-go-unit-tests] === CONT TestDumpPathMatchesNix
  137. 1.79 s [niks3-go-unit-tests] === CONT TestGetStorePathHash
  138. 1.79 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR
  139. 1.79 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/zero_stays_at_minimum
  140. 1.79 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/zero_stays_at_minimum
  141. 1.79 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/small_stays_at_minimum
  142. 1.79 s [niks3-go-unit-tests] === PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter
  143. 1.79 s [niks3-go-unit-tests] === RUN TestUploadMultipart_SupersededByPeer/exists
  144. 1.79 s [niks3-go-unit-tests] === CONT TestSetClientTLSDoesNotMutateDefaultTransport
  145. 1.79 s [niks3-go-unit-tests] === PAUSE TestUploadMultipart_SupersededByPeer/exists
  146. 1.79 s [niks3-go-unit-tests] === RUN TestUploadMultipart_SupersededByPeer/missing
  147. 1.79 s [niks3-go-unit-tests] === PAUSE TestUploadMultipart_SupersededByPeer/missing
  148. 1.79 s [niks3-go-unit-tests] === RUN TestGetStorePathHash/valid_store_path
  149. 1.79 s [niks3-go-unit-tests] === PAUSE TestGetStorePathHash/valid_store_path
  150. 1.79 s [niks3-go-unit-tests] --- PASS: TestDoServerRequestAttachesToken (0.00s)
  151. 1.79 s [niks3-go-unit-tests] === RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)
  152. 1.79 s [niks3-go-unit-tests] === PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)
  153. 1.79 s [niks3-go-unit-tests] === RUN TestPathInfoHashCompatibility/old_string_format_with_colon
  154. 1.79 s [niks3-go-unit-tests] === PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon
  155. 1.79 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/small_stays_at_minimum
  156. 1.79 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/80_GiB_fits_at_minimum
  157. 1.79 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum
  158. 1.79 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/115_GiB_needs_larger_parts
  159. 1.79 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts
  160. 1.80 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/1_TiB
  161. 1.80 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/1_TiB
  162. 1.80 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/5_TiB_S3_max_object
  163. 1.80 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/5_TiB_S3_max_object
  164. 1.80 s [niks3-go-unit-tests] --- PASS: TestScriptTokenEmptyToken (0.00s)
  165. 1.80 s [niks3-go-unit-tests] --- PASS: TestScriptTokenScriptFails (0.00s)
  166. 1.80 s [niks3-go-unit-tests] === CONT TestCaseHackSuffix
  167. 1.80 s [niks3-go-unit-tests] === CONT TestFileTokenEmpty
  168. 1.80 s [niks3-go-unit-tests] === RUN TestPathInfoCACompatibility/null_ca_field
  169. 1.80 s [niks3-go-unit-tests] === PAUSE TestPathInfoCACompatibility/null_ca_field
  170. 1.80 s [niks3-go-unit-tests] === RUN TestPathInfoCACompatibility/old_string_format_-_text
  171. 1.80 s [niks3-go-unit-tests] === PAUSE TestPathInfoCACompatibility/old_string_format_-_text
  172. 1.80 s [niks3-go-unit-tests] === RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive
  173. 1.80 s [niks3-go-unit-tests] === CONT TestFileTokenReadsAndCaches
  174. 1.80 s [niks3-go-unit-tests] === RUN TestGetStorePathHash/basename_without_hyphen_should_error
  175. 1.80 s [niks3-go-unit-tests] === RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI
  176. 1.80 s [niks3-go-unit-tests] === RUN TestPartSizeForNAR/capped_at_5_GiB
  177. 1.80 s [niks3-go-unit-tests] === PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive
  178. 1.80 s [niks3-go-unit-tests] --- PASS: TestFileTokenEmpty (0.00s)
  179. 1.80 s [niks3-go-unit-tests] === PAUSE TestGetStorePathHash/basename_without_hyphen_should_error
  180. 1.80 s [niks3-go-unit-tests] === RUN TestGetStorePathHash/hash_with_invalid_characters_should_error
  181. 1.80 s [niks3-go-unit-tests] === PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error
  182. 1.80 s [niks3-go-unit-tests] === RUN TestGetStorePathHash/hash_with_wrong_length_should_error
  183. 1.80 s [niks3-go-unit-tests] === PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error
  184. 1.80 s [niks3-go-unit-tests] === RUN TestPathInfoCACompatibility/new_structured_format_-_text
  185. 1.80 s [niks3-go-unit-tests] === PAUSE TestPathInfoCACompatibility/new_structured_format_-_text
  186. 1.80 s [niks3-go-unit-tests] === RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method
  187. 1.80 s [niks3-go-unit-tests] === PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method
  188. 1.80 s [niks3-go-unit-tests] === PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI
  189. 1.80 s [niks3-go-unit-tests] === CONT TestStaticToken
  190. 1.80 s [niks3-go-unit-tests] --- PASS: TestStaticToken (0.00s)
  191. 1.80 s [niks3-go-unit-tests] === CONT TestShellSplitErrors
  192. 1.80 s [niks3-go-unit-tests] --- PASS: TestShellSplitErrors (0.00s)
  193. 1.80 s [niks3-go-unit-tests] === CONT TestSetClientTLS
  194. 1.80 s [niks3-go-unit-tests] === PAUSE TestPartSizeForNAR/capped_at_5_GiB
  195. 1.80 s [niks3-go-unit-tests] === CONT TestSetClientTLSErrors
  196. 1.80 s [niks3-go-unit-tests] === CONT TestScriptTokenCachesUntilRefresh
  197. 1.80 s [niks3-go-unit-tests] === RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512
  198. 1.80 s [niks3-go-unit-tests] === PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512
  199. 1.80 s [niks3-go-unit-tests] === CONT TestShellSplit
  200. 1.80 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths
  201. 1.80 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths
  202. 1.80 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSON/Nix_format
  203. 1.80 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSON/invalid_JSON
  204. 1.80 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSON/whitespace_only
  205. 1.80 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSON/empty_input
  206. 1.80 s [niks3-go-unit-tests] === CONT TestParsePathInfoJSON/Lix_format
  207. 1.80 s [niks3-go-unit-tests] === CONT TestEncodeNixBase32/empty_input
  208. 1.80 s [niks3-go-unit-tests] === CONT TestRateLimiterFeedback/429_enables_limiter
  209. 1.80 s [niks3-go-unit-tests] === CONT TestRateLimiterFeedback/400_does_not_enable_limiter
  210. 1.80 s [niks3-go-unit-tests] === CONT TestRateLimiterFeedback/200_does_not_enable_limiter
  211. 1.89 s [niks3-go-unit-tests] === CONT TestDoWithRetry_BodyReplayedViaGetBody
  212. 1.89 s [niks3-go-unit-tests] === CONT TestEncodeNixBase32/test_string_hash
  213. 1.89 s [niks3-go-unit-tests] === CONT TestRateLimiterFeedback/503_enables_limiter
  214. 1.89 s [niks3-go-unit-tests] --- PASS: TestScriptTokenBadJSON (0.01s)
  215. 1.89 s [niks3-go-unit-tests] --- PASS: TestFileTokenReadsAndCaches (0.00s)
  216. 1.89 s [niks3-go-unit-tests] --- PASS: TestShellSplit (0.00s)
  217. 1.89 s [niks3-go-unit-tests] --- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)
  218. 1.89 s [niks3-go-unit-tests] === RUN TestSetClientTLSErrors/missing_cert_file
  219. 1.89 s [niks3-go-unit-tests] === PAUSE TestSetClientTLSErrors/missing_cert_file
  220. 1.89 s [niks3-go-unit-tests] === RUN TestSetClientTLSErrors/missing_key_file
  221. 1.89 s [niks3-go-unit-tests] === PAUSE TestSetClientTLSErrors/missing_key_file
  222. 1.89 s [niks3-go-unit-tests] === RUN TestSetClientTLSErrors/missing_ca_file
  223. 1.89 s [niks3-go-unit-tests] === PAUSE TestSetClientTLSErrors/missing_ca_file
  224. 1.89 s [niks3-go-unit-tests] === RUN TestSetClientTLSErrors/invalid_ca_file
  225. 1.89 s [niks3-go-unit-tests] === PAUSE TestSetClientTLSErrors/invalid_ca_file
  226. 1.89 s [niks3-go-unit-tests] --- PASS: TestDumpPathSingleFile (0.10s)
  227. 1.89 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)
  228. 1.89 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)
  229. 1.89 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)
  230. 1.89 s [niks3-go-unit-tests] === CONT TestUploadMultipart_SupersededByPeer/exists
  231. 1.89 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSON (0.00s)
  232. 1.89 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)
  233. 1.89 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)
  234. 1.89 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)
  235. 1.89 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSON/empty_input (0.00s)
  236. 1.89 s [niks3-go-unit-tests] --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)
  237. 1.89 s [niks3-go-unit-tests] --- PASS: TestEncodeNixBase32 (0.00s)
  238. 1.89 s [niks3-go-unit-tests] --- PASS: TestEncodeNixBase32/empty_input (0.00s)
  239. 1.89 s [niks3-go-unit-tests] --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)
  240. 1.89 s [niks3-go-unit-tests] === CONT TestUploadMultipart_SupersededByPeer/missing
  241. 1.89 s [niks3-go-unit-tests] --- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.10s)
  242. 1.89 s [niks3-go-unit-tests] 2026/07/19 10:23:53 WARN Rate limiter enabled after throttle name=server-test rate=5
  243. 1.89 s [niks3-go-unit-tests] 2026/07/19 10:23:53 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:41043
  244. 1.89 s [niks3-go-unit-tests] === CONT TestGetStorePathHash/valid_store_path
  245. 1.89 s [niks3-go-unit-tests] === CONT TestGetStorePathHash/hash_with_wrong_length_should_error
  246. 1.89 s [niks3-go-unit-tests] === CONT TestGetStorePathHash/hash_with_invalid_characters_should_error
  247. 1.89 s [niks3-go-unit-tests] === CONT TestGetStorePathHash/basename_without_hyphen_should_error
  248. 1.90 s [niks3-go-unit-tests] === CONT TestPathInfoCACompatibility/null_ca_field
  249. 1.90 s [niks3-go-unit-tests] === CONT TestPathInfoCACompatibility/new_structured_format_-_text
  250. 1.90 s [niks3-go-unit-tests] 2026/07/19 10:23:53 WARN Rate limiter backed off name=server-test rate=5
  251. 1.90 s [niks3-go-unit-tests] 2026/07/19 10:23:53 WARN Rate limiter enabled after throttle name=server-test rate=5
  252. 1.90 s [niks3-go-unit-tests] 2026/07/19 10:23:53 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:44725
  253. 1.90 s [niks3-go-unit-tests] === CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method
  254. 1.90 s [niks3-go-unit-tests] === CONT TestPathInfoCACompatibility/old_string_format_-_text
  255. 1.90 s [niks3-go-unit-tests] === CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive
  256. 1.90 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/zero_stays_at_minimum
  257. 1.90 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/1_TiB
  258. 1.90 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/5_TiB_S3_max_object
  259. 1.90 s [niks3-go-unit-tests] --- PASS: TestPathInfoCACompatibility (0.00s)
  260. 1.90 s [niks3-go-unit-tests] --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)
  261. 1.90 s [niks3-go-unit-tests] --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)
  262. 1.90 s [niks3-go-unit-tests] --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)
  263. 1.90 s [niks3-go-unit-tests] --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)
  264. 1.90 s [niks3-go-unit-tests] --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)
  265. 1.90 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/small_stays_at_minimum
  266. 1.90 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/115_GiB_needs_larger_parts
  267. 1.90 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/capped_at_5_GiB
  268. 1.90 s [niks3-go-unit-tests] === CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512
  269. 1.90 s [niks3-go-unit-tests] === CONT TestPartSizeForNAR/80_GiB_fits_at_minimum
  270. 1.90 s [niks3-go-unit-tests] === CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)
  271. 1.90 s [niks3-go-unit-tests] === CONT TestPathInfoHashCompatibility/old_string_format_with_colon
  272. 1.90 s [niks3-go-unit-tests] === CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI
  273. 1.90 s [niks3-go-unit-tests] === CONT TestSetClientTLSErrors/missing_cert_file
  274. 1.90 s [niks3-go-unit-tests] === CONT TestSetClientTLSErrors/invalid_ca_file
  275. 1.90 s [niks3-go-unit-tests] === CONT TestSetClientTLSErrors/missing_ca_file
  276. 1.90 s [niks3-go-unit-tests] --- PASS: TestPathInfoHashCompatibility (0.00s)
  277. 1.90 s [niks3-go-unit-tests] --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)
  278. 1.90 s [niks3-go-unit-tests] --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)
  279. 1.90 s [niks3-go-unit-tests] --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)
  280. 1.90 s [niks3-go-unit-tests] --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)
  281. 1.90 s [niks3-go-unit-tests] === CONT TestSetClientTLSErrors/missing_key_file
  282. 1.90 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR (0.00s)
  283. 1.90 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)
  284. 1.90 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)
  285. 1.90 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/1_TiB (0.00s)
  286. 1.90 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)
  287. 1.90 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)
  288. 1.90 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)
  289. 1.90 s [niks3-go-unit-tests] --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)
  290. 1.90 s [niks3-go-unit-tests] === RUN TestSetClientTLS/rejects_connection_without_client_cert
  291. 1.90 s [niks3-go-unit-tests] === PAUSE TestSetClientTLS/rejects_connection_without_client_cert
  292. 1.90 s [niks3-go-unit-tests] === RUN TestSetClientTLS/succeeds_with_client_cert_and_CA
  293. 1.90 s [niks3-go-unit-tests] === PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA
  294. 1.90 s [niks3-go-unit-tests] === RUN TestSetClientTLS/preserves_debug_logging_transport
  295. 1.90 s [niks3-go-unit-tests] === PAUSE TestSetClientTLS/preserves_debug_logging_transport
  296. 1.90 s [niks3-go-unit-tests] === CONT TestSetClientTLS/rejects_connection_without_client_cert
  297. 1.90 s [niks3-go-unit-tests] === CONT TestSetClientTLS/preserves_debug_logging_transport
  298. 1.90 s [niks3-go-unit-tests] === CONT TestSetClientTLS/succeeds_with_client_cert_and_CA
  299. 1.90 s [niks3-go-unit-tests] --- PASS: TestSetClientTLSErrors (0.10s)
  300. 1.90 s [niks3-go-unit-tests] --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)
  301. 1.90 s [niks3-go-unit-tests] --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)
  302. 1.90 s [niks3-go-unit-tests] --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)
  303. 1.90 s [niks3-go-unit-tests] --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)
  304. 1.90 s [niks3-go-unit-tests] --- PASS: TestGetStorePathHash (0.00s)
  305. 1.90 s [niks3-go-unit-tests] --- PASS: TestGetStorePathHash/valid_store_path (0.00s)
  306. 1.90 s [niks3-go-unit-tests] --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)
  307. 1.90 s [niks3-go-unit-tests] --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)
  308. 1.90 s [niks3-go-unit-tests] --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)
  309. 1.90 s [niks3-go-unit-tests] --- PASS: TestUploadMultipart_SupersededByPeer (0.00s)
  310. 1.90 s [niks3-go-unit-tests] --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)
  311. 1.90 s [niks3-go-unit-tests] --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)
  312. 1.90 s [niks3-go-unit-tests] 2026/07/19 10:23:53 WARN Rate limiter enabled after throttle name=server-test rate=5
  313. 1.90 s [niks3-go-unit-tests] 2026/07/19 10:23:53 WARN Rate limiter backed off name=server-test rate=5
  314. 1.90 s [niks3-go-unit-tests] 2026/07/19 10:23:53 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:42523
  315. 1.90 s [niks3-go-unit-tests] --- PASS: TestRateLimiterFeedback (0.00s)
  316. 1.90 s [niks3-go-unit-tests] --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.10s)
  317. 1.90 s [niks3-go-unit-tests] --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)
  318. 1.90 s [niks3-go-unit-tests] --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.10s)
  319. 1.90 s [niks3-go-unit-tests] --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.10s)
  320. 1.90 s [niks3-go-unit-tests] 2026/07/19 10:23:53 WARN Rate limiter backed off name=server-test rate=5
  321. 1.90 s [niks3-go-unit-tests] 2026/07/19 10:23:53 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:42523
  322. 1.90 s [niks3-go-unit-tests] 2026/07/19 10:23:53 http: TLS handshake error from 127.0.0.1:35708: remote error: tls: bad certificate
  323. 1.90 s [niks3-go-unit-tests] --- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)
  324. 1.90 s [niks3-go-unit-tests] --- PASS: TestScriptTokenCachesUntilRefresh (0.10s)
  325. 1.90 s [niks3-go-unit-tests] --- PASS: TestSetClientTLS (0.10s)
  326. 1.90 s [niks3-go-unit-tests] --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.00s)
  327. 1.90 s [niks3-go-unit-tests] --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)
  328. 1.90 s [niks3-go-unit-tests] --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)
  329. 1.90 s [niks3-go-unit-tests] --- PASS: TestDumpPathWriterError (0.12s)
  330. 1.91 s [niks3-go-unit-tests] --- PASS: TestCaseHackSuffix (0.12s)
  331. 1.93 s [niks3-go-unit-tests] --- PASS: TestDumpPathMatchesNix (0.14s)
  332. 2.79 s [niks3-go-unit-tests] --- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)
  333. 2.79 s [niks3-go-unit-tests] PASS
  334. 2.79 s [niks3-go-unit-tests] Running server tests...
  335. 2.81 s [niks3-go-unit-tests] The files belonging to this database system will be owned by user "nixbld".
  336. 2.81 s [niks3-go-unit-tests] This user must also own the server process.
  337. 2.81 s [niks3-go-unit-tests]
  338. 2.81 s [niks3-go-unit-tests] The database cluster will be initialized with locale "C".
  339. 2.81 s [niks3-go-unit-tests] The default database encoding has accordingly been set to "SQL_ASCII".
  340. 2.81 s [niks3-go-unit-tests] The default text search configuration will be set to "english".
  341. 2.81 s [niks3-go-unit-tests]
  342. 2.81 s [niks3-go-unit-tests] Data page checksums are enabled.
  343. 2.81 s [niks3-go-unit-tests]
  344. 2.81 s [niks3-go-unit-tests] creating directory /build/postgres379226597/data ... ok
  345. 2.81 s [niks3-go-unit-tests] creating subdirectories ... ok
  346. 2.81 s [niks3-go-unit-tests] selecting dynamic shared memory implementation ... posix
  347. 2.82 s [niks3-go-unit-tests] selecting default "max_connections" ... 100
  348. 2.84 s [niks3-go-unit-tests] selecting default "shared_buffers" ... 128MB
  349. 2.84 s [niks3-go-unit-tests] selecting default time zone ... UTC
  350. 2.84 s [niks3-go-unit-tests] creating configuration files ... ok
  351. 2.93 s [niks3-go-unit-tests] running bootstrap script ... ok
  352. 3.18 s [niks3-go-unit-tests] performing post-bootstrap initialization ... ok
  353. 3.35 s [niks3-go-unit-tests] syncing data to disk ... ok
  354. 3.35 s [niks3-go-unit-tests]
  355. 3.35 s [niks3-go-unit-tests] initdb: warning: enabling "trust" authentication for local connections
  356. 3.35 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.35 s [niks3-go-unit-tests]
  358. 3.35 s [niks3-go-unit-tests] Success. You can now start the database server using:
  359. 3.35 s [niks3-go-unit-tests]
  360. 3.35 s [niks3-go-unit-tests] pg_ctl -D /build/postgres379226597/data -l logfile start
  361. 3.35 s [niks3-go-unit-tests]
  362. 3.40 s [niks3-go-unit-tests] /build/postgres379226597:5432 - no response
  363. 3.43 s [niks3-go-unit-tests] 2026-07-19 10:23:54.914 UTC [96] LOG: starting PostgreSQL 18.4 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit
  364. 3.43 s [niks3-go-unit-tests] 2026-07-19 10:23:54.921 UTC [96] LOG: listening on Unix socket "/build/postgres379226597/.s.PGSQL.5432"
  365. 3.46 s [niks3-go-unit-tests] 2026-07-19 10:23:54.944 UTC [103] LOG: database system was shut down at 2026-07-19 10:23:54 UTC
  366. 3.47 s [niks3-go-unit-tests] 2026-07-19 10:23:54.953 UTC [96] LOG: database system is ready to accept connections
  367. 3.51 s [niks3-go-unit-tests] /build/postgres379226597:5432 - accepting connections
  368. 3.53 s [niks3-go-unit-tests] {"timestamp":"2026-07-19T10:23:55.016918805Z","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(28)"}
  369. 3.54 s [niks3-go-unit-tests]
  370. 3.54 s [niks3-go-unit-tests] thread 'rustfs-worker' (138) panicked at /build/rustfs-1.0.0-beta.7-vendor/source-registry-0/reqwest-0.13.4/src/async_impl/client.rs:2507:38:
  371. 3.54 s [niks3-go-unit-tests] Client::new(): reqwest::Error { kind: Builder, source: General("No CA certificates were loaded from the system") }
  372. 3.54 s [niks3-go-unit-tests] note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
  373. 3.61 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware
  374. 3.61 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware
  375. 3.61 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_MTLSProxyHeader
  376. 3.61 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_MTLSProxyHeader
  377. 3.61 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_MTLSBoundSubjects
  378. 3.61 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_MTLSBoundSubjects
  379. 3.61 s [niks3-go-unit-tests] === RUN TestService_ReadAuthMiddleware
  380. 3.61 s [niks3-go-unit-tests] === PAUSE TestService_ReadAuthMiddleware
  381. 3.61 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_OIDC
  382. 3.61 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_OIDC
  383. 3.61 s [niks3-go-unit-tests] === RUN TestCacheConfigHandler
  384. 3.61 s [niks3-go-unit-tests] === PAUSE TestCacheConfigHandler
  385. 3.61 s [niks3-go-unit-tests] === RUN TestCacheStatsHandler
  386. 3.61 s [niks3-go-unit-tests] === PAUSE TestCacheStatsHandler
  387. 3.61 s [niks3-go-unit-tests] === RUN TestClientCADerivations
  388. 3.61 s [niks3-go-unit-tests] === PAUSE TestClientCADerivations
  389. 3.61 s [niks3-go-unit-tests] === RUN TestClientErrorHandling
  390. 3.61 s [niks3-go-unit-tests] === PAUSE TestClientErrorHandling
  391. 3.61 s [niks3-go-unit-tests] === RUN TestClientIntegration
  392. 3.61 s [niks3-go-unit-tests] === PAUSE TestClientIntegration
  393. 3.61 s [niks3-go-unit-tests] === RUN TestClientMultipleUploads
  394. 3.61 s [niks3-go-unit-tests] === PAUSE TestClientMultipleUploads
  395. 3.61 s [niks3-go-unit-tests] === RUN TestClientWithDependencies
  396. 3.61 s [niks3-go-unit-tests] === PAUSE TestClientWithDependencies
  397. 3.61 s [niks3-go-unit-tests] === RUN TestPinProtectsFromGC
  398. 3.61 s [niks3-go-unit-tests] === PAUSE TestPinProtectsFromGC
  399. 3.61 s [niks3-go-unit-tests] === RUN TestGCAdvisoryLockBlocksConcurrentRun
  400. 3.80 s [niks3-go-unit-tests] 2026-07-19 10:23:55.286 UTC [155] ERROR: relation "goose_db_version" does not exist at character 36
  401. 3.80 s [niks3-go-unit-tests] 2026-07-19 10:23:55.286 UTC [155] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  402. 3.82 s [niks3-go-unit-tests] 2026/07/19 10:23:55 OK 20241026095416_initial_model.sql (8.64ms)
  403. 3.82 s [niks3-go-unit-tests] 2026/07/19 10:23:55 OK 20251210153512_drop_unused_gin_index.sql (4.11ms)
  404. 3.83 s [niks3-go-unit-tests] 2026/07/19 10:23:55 OK 20251218171726_add_pins.sql (4.7ms)
  405. 3.83 s [niks3-go-unit-tests] 2026/07/19 10:23:55 OK 20260628120000_add_object_size_and_stats.sql (4.77ms)
  406. 3.83 s [niks3-go-unit-tests] 2026/07/19 10:23:55 goose: successfully migrated database to version: 20260628120000
  407. 3.84 s [niks3-go-unit-tests] 2026/07/19 10:23:55 OK 1_commit_pending_closure.sql (4.32ms)
  408. 3.84 s [niks3-go-unit-tests] 2026/07/19 10:23:55 OK 2_object_stats_trigger.sql (3.72ms)
  409. 3.84 s [niks3-go-unit-tests] 2026/07/19 10:23:55 goose: up to current file version: 2
  410. 3.84 s [niks3-go-unit-tests] --- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.23s)
  411. 3.84 s [niks3-go-unit-tests] === RUN TestGCBugBareHashReferences
  412. 3.84 s [niks3-go-unit-tests] === PAUSE TestGCBugBareHashReferences
  413. 3.84 s [niks3-go-unit-tests] === RUN TestGCMetrics
  414. 3.84 s [niks3-go-unit-tests] === PAUSE TestGCMetrics
  415. 3.84 s [niks3-go-unit-tests] === RUN TestGCTaskStore_StartNew
  416. 3.84 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_StartNew
  417. 3.84 s [niks3-go-unit-tests] === RUN TestGCTaskStore_DeduplicateSameParams
  418. 3.84 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_DeduplicateSameParams
  419. 3.84 s [niks3-go-unit-tests] === RUN TestGCTaskStore_ConflictDifferentParams
  420. 3.84 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_ConflictDifferentParams
  421. 3.84 s [niks3-go-unit-tests] === RUN TestGCTaskStore_GetEmpty
  422. 3.84 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_GetEmpty
  423. 3.84 s [niks3-go-unit-tests] === RUN TestGCTaskStore_GetReturnsLatest
  424. 3.84 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_GetReturnsLatest
  425. 3.84 s [niks3-go-unit-tests] === RUN TestGCTaskStore_CompletedAllowsNewTask
  426. 3.84 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_CompletedAllowsNewTask
  427. 3.84 s [niks3-go-unit-tests] === RUN TestGCTaskStore_PhaseUpdates
  428. 3.84 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_PhaseUpdates
  429. 3.84 s [niks3-go-unit-tests] === RUN TestGCTaskStore_Fail
  430. 3.84 s [niks3-go-unit-tests] === PAUSE TestGCTaskStore_Fail
  431. 3.84 s [niks3-go-unit-tests] === RUN TestGracefulShutdownDrainsInflight
  432. 3.84 s [niks3-go-unit-tests] === PAUSE TestGracefulShutdownDrainsInflight
  433. 3.84 s [niks3-go-unit-tests] === RUN TestService_healthCheckHandler
  434. 3.84 s [niks3-go-unit-tests] === PAUSE TestService_healthCheckHandler
  435. 3.84 s [niks3-go-unit-tests] === RUN TestGenerateLandingPage
  436. 3.84 s [niks3-go-unit-tests] === PAUSE TestGenerateLandingPage
  437. 3.84 s [niks3-go-unit-tests] === RUN TestNARDeduplicationMetadataUploadBug
  438. 3.84 s [niks3-go-unit-tests] === PAUSE TestNARDeduplicationMetadataUploadBug
  439. 3.84 s [niks3-go-unit-tests] === RUN TestMetricsInventory
  440. 3.84 s [niks3-go-unit-tests] === PAUSE TestMetricsInventory
  441. 3.84 s [niks3-go-unit-tests] === RUN TestService_NativeMTLS
  442. 3.84 s [niks3-go-unit-tests] === PAUSE TestService_NativeMTLS
  443. 3.84 s [niks3-go-unit-tests] === RUN TestServerTLSConfig
  444. 3.84 s [niks3-go-unit-tests] === PAUSE TestServerTLSConfig
  445. 3.84 s [niks3-go-unit-tests] === RUN TestMultipartCleanup
  446. 3.84 s [niks3-go-unit-tests] === PAUSE TestMultipartCleanup
  447. 3.84 s [niks3-go-unit-tests] === RUN TestObjectStatsTrigger
  448. 3.84 s [niks3-go-unit-tests] === PAUSE TestObjectStatsTrigger
  449. 3.84 s [niks3-go-unit-tests] === RUN TestOrphanedObjectsGC
  450. 3.84 s [niks3-go-unit-tests] === PAUSE TestOrphanedObjectsGC
  451. 3.84 s [niks3-go-unit-tests] === RUN TestOrphanedObjectsGCStressTest
  452. 3.84 s [niks3-go-unit-tests] === PAUSE TestOrphanedObjectsGCStressTest
  453. 3.84 s [niks3-go-unit-tests] === RUN TestResurrectedObjectNotDeleted
  454. 3.84 s [niks3-go-unit-tests] === PAUSE TestResurrectedObjectNotDeleted
  455. 3.84 s [niks3-go-unit-tests] === RUN TestParseSingleRange
  456. 3.84 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange
  457. 3.84 s [niks3-go-unit-tests] === RUN TestIsValidCachePath
  458. 3.84 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath
  459. 3.84 s [niks3-go-unit-tests] === RUN TestReadProxyNarinfo
  460. 3.84 s [niks3-go-unit-tests] === PAUSE TestReadProxyNarinfo
  461. 3.84 s [niks3-go-unit-tests] === RUN TestReadProxyNarinfoAlreadyDecompressed
  462. 3.84 s [niks3-go-unit-tests] === PAUSE TestReadProxyNarinfoAlreadyDecompressed
  463. 3.84 s [niks3-go-unit-tests] === RUN TestReadProxyNarStreaming
  464. 3.84 s [niks3-go-unit-tests] === PAUSE TestReadProxyNarStreaming
  465. 3.84 s [niks3-go-unit-tests] === RUN TestReadProxy404
  466. 3.85 s [niks3-go-unit-tests] === PAUSE TestReadProxy404
  467. 3.85 s [niks3-go-unit-tests] === RUN TestReadProxyInvalidPath
  468. 3.85 s [niks3-go-unit-tests] === PAUSE TestReadProxyInvalidPath
  469. 3.85 s [niks3-go-unit-tests] === RUN TestReadProxyHead
  470. 3.85 s [niks3-go-unit-tests] === PAUSE TestReadProxyHead
  471. 3.85 s [niks3-go-unit-tests] === RUN TestReadProxyConditionalGet
  472. 3.85 s [niks3-go-unit-tests] === PAUSE TestReadProxyConditionalGet
  473. 3.85 s [niks3-go-unit-tests] === RUN TestReadProxyRootRedirectsToIndexHTML
  474. 3.85 s [niks3-go-unit-tests] === PAUSE TestReadProxyRootRedirectsToIndexHTML
  475. 3.85 s [niks3-go-unit-tests] === RUN TestReadProxyDisabled
  476. 3.85 s [niks3-go-unit-tests] === PAUSE TestReadProxyDisabled
  477. 3.85 s [niks3-go-unit-tests] === RUN TestReadProxyRangeRequest
  478. 3.85 s [niks3-go-unit-tests] === PAUSE TestReadProxyRangeRequest
  479. 3.85 s [niks3-go-unit-tests] === RUN TestRedundantMultipartUpload
  480. 3.85 s [niks3-go-unit-tests] === PAUSE TestRedundantMultipartUpload
  481. 3.85 s [niks3-go-unit-tests] === RUN TestCompleteMultipartUpload_ErrorButObjectExists
  482. 3.85 s [niks3-go-unit-tests] === PAUSE TestCompleteMultipartUpload_ErrorButObjectExists
  483. 3.85 s [niks3-go-unit-tests] === RUN TestCompletedNarNotReofferedAcrossClosures
  484. 3.85 s [niks3-go-unit-tests] === PAUSE TestCompletedNarNotReofferedAcrossClosures
  485. 3.85 s [niks3-go-unit-tests] === RUN TestPresignedUploadRegisteredBeforeCommit
  486. 3.85 s [niks3-go-unit-tests] === PAUSE TestPresignedUploadRegisteredBeforeCommit
  487. 3.85 s [niks3-go-unit-tests] === RUN TestService_Rustfstest
  488. 3.85 s [niks3-go-unit-tests] === PAUSE TestService_Rustfstest
  489. 3.85 s [niks3-go-unit-tests] === RUN TestSystemdListenerNotActivated
  490. 3.85 s [niks3-go-unit-tests] --- PASS: TestSystemdListenerNotActivated (0.00s)
  491. 3.85 s [niks3-go-unit-tests] === RUN TestWatchdogBeatsWhenHealthy
  492. 3.86 s [niks3-go-unit-tests] --- PASS: TestWatchdogBeatsWhenHealthy (0.02s)
  493. 3.86 s [niks3-go-unit-tests] === RUN TestWatchdogSkipsWhenUnhealthy
  494. 3.88 s [niks3-go-unit-tests] 2026/07/19 10:23:55 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  495. 3.90 s [niks3-go-unit-tests] 2026/07/19 10:23:55 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  496. 3.92 s [niks3-go-unit-tests] 2026/07/19 10:23:55 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  497. 3.94 s [niks3-go-unit-tests] 2026/07/19 10:23:55 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  498. 3.96 s [niks3-go-unit-tests] 2026/07/19 10:23:55 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  499. 3.98 s [niks3-go-unit-tests] 2026/07/19 10:23:55 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  500. 4.00 s [niks3-go-unit-tests] 2026/07/19 10:23:55 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  501. 4.02 s [niks3-go-unit-tests] 2026/07/19 10:23:55 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  502. 4.04 s [niks3-go-unit-tests] 2026/07/19 10:23:55 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  503. 4.06 s [niks3-go-unit-tests] 2026/07/19 10:23:55 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"
  504. 4.06 s [niks3-go-unit-tests] --- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)
  505. 4.06 s [niks3-go-unit-tests] === RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle
  506. 4.07 s [niks3-go-unit-tests] === PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle
  507. 4.07 s [niks3-go-unit-tests] === RUN TestProxyWriteTimeout
  508. 4.07 s [niks3-go-unit-tests] === PAUSE TestProxyWriteTimeout
  509. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey
  510. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey
  511. 4.07 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectInvalidKeys
  512. 4.07 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectInvalidKeys
  513. 4.07 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectOversizedBody
  514. 4.07 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectOversizedBody
  515. 4.07 s [niks3-go-unit-tests] === RUN TestService_cleanupPendingClosuresHandler
  516. 4.07 s [niks3-go-unit-tests] === PAUSE TestService_cleanupPendingClosuresHandler
  517. 4.07 s [niks3-go-unit-tests] === RUN TestService_createPendingClosureHandler
  518. 4.07 s [niks3-go-unit-tests] === PAUSE TestService_createPendingClosureHandler
  519. 4.07 s [niks3-go-unit-tests] === RUN TestService_verifyS3Integrity
  520. 4.07 s [niks3-go-unit-tests] === PAUSE TestService_verifyS3Integrity
  521. 4.07 s [niks3-go-unit-tests] === RUN TestCompleteMultipartUnregistered
  522. 4.07 s [niks3-go-unit-tests] === PAUSE TestCompleteMultipartUnregistered
  523. 4.07 s [niks3-go-unit-tests] === RUN TestCreatePendingClosure_SmallNARUsesSimplePUT
  524. 4.07 s [niks3-go-unit-tests] === PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT
  525. 4.07 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware
  526. 4.07 s [niks3-go-unit-tests] === CONT TestCreatePendingClosure_SmallNARUsesSimplePUT
  527. 4.07 s [niks3-go-unit-tests] === CONT TestObjectStatsTrigger
  528. 4.07 s [niks3-go-unit-tests] === CONT TestGCTaskStore_DeduplicateSameParams
  529. 4.07 s [niks3-go-unit-tests] === CONT TestReadProxyRangeRequest
  530. 4.07 s [niks3-go-unit-tests] === CONT TestGracefulShutdownDrainsInflight
  531. 4.07 s [niks3-go-unit-tests] === CONT TestClientErrorHandling
  532. 4.07 s [niks3-go-unit-tests] === CONT TestMetricsInventory
  533. 4.07 s [niks3-go-unit-tests] === RUN TestClientErrorHandling/InvalidStorePath
  534. 4.07 s [niks3-go-unit-tests] === PAUSE TestClientErrorHandling/InvalidStorePath
  535. 4.07 s [niks3-go-unit-tests] === RUN TestClientErrorHandling/InvalidAuthToken
  536. 4.07 s [niks3-go-unit-tests] === PAUSE TestClientErrorHandling/InvalidAuthToken
  537. 4.07 s [niks3-go-unit-tests] === RUN TestClientErrorHandling/ServerNotAvailable
  538. 4.07 s [niks3-go-unit-tests] === PAUSE TestClientErrorHandling/ServerNotAvailable
  539. 4.07 s [niks3-go-unit-tests] === CONT TestClientErrorHandling/InvalidStorePath
  540. 4.07 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey
  541. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/narinfo
  542. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/narinfo
  543. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/nar_zst
  544. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/nar_zst
  545. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/nar_xz
  546. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/nar_xz
  547. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/nar_plain
  548. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/nar_plain
  549. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/listing
  550. 4.07 s [niks3-go-unit-tests] 2026/07/19 10:23:55 INFO Starting HTTP server address=127.0.0.1:34713
  551. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/listing
  552. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/build_log
  553. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/build_log
  554. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/build_log_home-manager_file
  555. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/build_log_home-manager_file
  556. 4.07 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)
  557. 4.07 s [niks3-go-unit-tests] === CONT TestService_healthCheckHandler
  558. 4.07 s [niks3-go-unit-tests] 2026/07/19 10:23:55 INFO Shutdown signal received, draining in-flight requests timeout=10s
  559. 4.07 s [niks3-go-unit-tests] === CONT TestNARDeduplicationMetadataUploadBug
  560. 4.07 s [niks3-go-unit-tests] === CONT TestMultipartCleanup
  561. 4.07 s [niks3-go-unit-tests] === CONT TestServerTLSConfig
  562. 4.07 s [niks3-go-unit-tests] === RUN TestServerTLSConfig/no_client_CA
  563. 4.07 s [niks3-go-unit-tests] === PAUSE TestServerTLSConfig/no_client_CA
  564. 4.07 s [niks3-go-unit-tests] === RUN TestServerTLSConfig/missing_CA_file
  565. 4.07 s [niks3-go-unit-tests] === PAUSE TestServerTLSConfig/missing_CA_file
  566. 4.07 s [niks3-go-unit-tests] === RUN TestServerTLSConfig/not_a_PEM_file
  567. 4.07 s [niks3-go-unit-tests] === PAUSE TestServerTLSConfig/not_a_PEM_file
  568. 4.07 s [niks3-go-unit-tests] === CONT TestReadProxyDisabled
  569. 4.07 s [niks3-go-unit-tests] === CONT TestService_NativeMTLS
  570. 4.07 s [niks3-go-unit-tests] === CONT TestReadProxyNarStreaming
  571. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/build_log_plus_in_name
  572. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/build_log_plus_in_name
  573. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/build_log_question_mark
  574. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/build_log_question_mark
  575. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/build_log_equals
  576. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/build_log_equals
  577. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/realisation
  578. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/realisation
  579. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/realisation_plus_in_output
  580. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/realisation_plus_in_output
  581. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/nix-cache-info
  582. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/nix-cache-info
  583. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/index.html
  584. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/index.html
  585. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/narinfo_key,_nar_type
  586. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/narinfo_key,_nar_type
  587. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/nar_key,_narinfo_type
  588. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/nar_key,_narinfo_type
  589. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/listing_key,_narinfo_type
  590. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/listing_key,_narinfo_type
  591. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/traversal
  592. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/traversal
  593. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/traversal_nar
  594. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/traversal_nar
  595. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/absolute
  596. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/absolute
  597. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/empty_key
  598. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/empty_key
  599. 4.07 s [niks3-go-unit-tests] === RUN TestIsValidUploadKey/unknown_type
  600. 4.07 s [niks3-go-unit-tests] === PAUSE TestIsValidUploadKey/unknown_type
  601. 4.07 s [niks3-go-unit-tests] === CONT TestReadProxyRootRedirectsToIndexHTML
  602. 4.14 s [niks3-go-unit-tests] --- PASS: TestGracefulShutdownDrainsInflight (0.07s)
  603. 4.14 s [niks3-go-unit-tests] === CONT TestReadProxyConditionalGet
  604. 4.55 s [niks3-go-unit-tests] 2026-07-19 10:23:56.039 UTC [196] ERROR: relation "goose_db_version" does not exist at character 36
  605. 4.55 s [niks3-go-unit-tests] 2026-07-19 10:23:56.039 UTC [196] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  606. 4.56 s [niks3-go-unit-tests] 2026-07-19 10:23:56.042 UTC [197] ERROR: relation "goose_db_version" does not exist at character 36
  607. 4.56 s [niks3-go-unit-tests] 2026-07-19 10:23:56.042 UTC [197] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  608. 4.60 s [niks3-go-unit-tests] 2026-07-19 10:23:56.085 UTC [199] ERROR: relation "goose_db_version" does not exist at character 36
  609. 4.60 s [niks3-go-unit-tests] 2026-07-19 10:23:56.085 UTC [199] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  610. 4.60 s [niks3-go-unit-tests] 2026-07-19 10:23:56.085 UTC [198] ERROR: relation "goose_db_version" does not exist at character 36
  611. 4.60 s [niks3-go-unit-tests] 2026-07-19 10:23:56.085 UTC [198] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  612. 4.60 s [niks3-go-unit-tests] 2026-07-19 10:23:56.086 UTC [201] ERROR: relation "goose_db_version" does not exist at character 36
  613. 4.60 s [niks3-go-unit-tests] 2026-07-19 10:23:56.086 UTC [201] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  614. 4.60 s [niks3-go-unit-tests] 2026-07-19 10:23:56.086 UTC [202] ERROR: relation "goose_db_version" does not exist at character 36
  615. 4.60 s [niks3-go-unit-tests] 2026-07-19 10:23:56.086 UTC [202] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  616. 4.76 s [niks3-go-unit-tests] 2026-07-19 10:23:56.248 UTC [203] ERROR: relation "goose_db_version" does not exist at character 36
  617. 4.76 s [niks3-go-unit-tests] 2026-07-19 10:23:56.248 UTC [203] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  618. 4.78 s [niks3-go-unit-tests] 2026-07-19 10:23:56.248 UTC [200] ERROR: relation "goose_db_version" does not exist at character 36
  619. 4.78 s [niks3-go-unit-tests] 2026-07-19 10:23:56.248 UTC [200] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  620. 4.78 s [niks3-go-unit-tests] 2026-07-19 10:23:56.248 UTC [204] ERROR: relation "goose_db_version" does not exist at character 36
  621. 4.78 s [niks3-go-unit-tests] 2026-07-19 10:23:56.248 UTC [204] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  622. 4.78 s [niks3-go-unit-tests] 2026-07-19 10:23:56.248 UTC [205] ERROR: relation "goose_db_version" does not exist at character 36
  623. 4.78 s [niks3-go-unit-tests] 2026-07-19 10:23:56.248 UTC [205] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  624. 4.78 s [niks3-go-unit-tests] 2026-07-19 10:23:56.252 UTC [208] ERROR: relation "goose_db_version" does not exist at character 36
  625. 4.78 s [niks3-go-unit-tests] 2026-07-19 10:23:56.252 UTC [208] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  626. 4.78 s [niks3-go-unit-tests] 2026-07-19 10:23:56.253 UTC [206] ERROR: relation "goose_db_version" does not exist at character 36
  627. 4.78 s [niks3-go-unit-tests] 2026-07-19 10:23:56.253 UTC [206] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  628. 4.78 s [niks3-go-unit-tests] 2026-07-19 10:23:56.253 UTC [207] ERROR: relation "goose_db_version" does not exist at character 36
  629. 4.78 s [niks3-go-unit-tests] 2026-07-19 10:23:56.253 UTC [207] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  630. 4.78 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20241026095416_initial_model.sql (15.06ms)
  631. 4.78 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20241026095416_initial_model.sql (20.04ms)
  632. 4.78 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20241026095416_initial_model.sql (20.48ms)
  633. 4.79 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20241026095416_initial_model.sql (12.04ms)
  634. 4.79 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20241026095416_initial_model.sql (12.07ms)
  635. 4.79 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20241026095416_initial_model.sql (18.53ms)
  636. 4.79 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251210153512_drop_unused_gin_index.sql (12.61ms)
  637. 4.79 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251210153512_drop_unused_gin_index.sql (12.27ms)
  638. 4.79 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251210153512_drop_unused_gin_index.sql (12.53ms)
  639. 4.80 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20241026095416_initial_model.sql (17.94ms)
  640. 4.80 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20241026095416_initial_model.sql (17.99ms)
  641. 4.80 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20241026095416_initial_model.sql (18.06ms)
  642. 4.80 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20241026095416_initial_model.sql (17.9ms)
  643. 4.80 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20241026095416_initial_model.sql (17.84ms)
  644. 4.80 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20241026095416_initial_model.sql (17.78ms)
  645. 4.80 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251210153512_drop_unused_gin_index.sql (12.33ms)
  646. 4.80 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251210153512_drop_unused_gin_index.sql (12.5ms)
  647. 4.80 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251218171726_add_pins.sql (9.26ms)
  648. 4.80 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251218171726_add_pins.sql (9.26ms)
  649. 4.80 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251218171726_add_pins.sql (9.27ms)
  650. 4.80 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251210153512_drop_unused_gin_index.sql (9.53ms)
  651. 4.81 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251218171726_add_pins.sql (6.1ms)
  652. 4.81 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251218171726_add_pins.sql (5.61ms)
  653. 4.81 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251210153512_drop_unused_gin_index.sql (3.76ms)
  654. 4.81 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251210153512_drop_unused_gin_index.sql (4.25ms)
  655. 4.81 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251210153512_drop_unused_gin_index.sql (6.46ms)
  656. 4.81 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251210153512_drop_unused_gin_index.sql (5.79ms)
  657. 4.81 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251210153512_drop_unused_gin_index.sql (5.76ms)
  658. 4.81 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251210153512_drop_unused_gin_index.sql (4.54ms)
  659. 4.81 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251218171726_add_pins.sql (9.33ms)
  660. 4.81 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20260628120000_add_object_size_and_stats.sql (9.47ms)
  661. 4.81 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20260628120000_add_object_size_and_stats.sql (9.43ms)
  662. 4.81 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20260628120000_add_object_size_and_stats.sql (9.45ms)
  663. 4.81 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: successfully migrated database to version: 20260628120000
  664. 4.81 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: successfully migrated database to version: 20260628120000
  665. 4.81 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: successfully migrated database to version: 20260628120000
  666. 4.82 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20260628120000_add_object_size_and_stats.sql (13.25ms)
  667. 4.82 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20260628120000_add_object_size_and_stats.sql (13.3ms)
  668. 4.82 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: successfully migrated database to version: 20260628120000
  669. 4.82 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: successfully migrated database to version: 20260628120000
  670. 4.82 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251218171726_add_pins.sql (13.15ms)
  671. 4.82 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251218171726_add_pins.sql (12.76ms)
  672. 4.82 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251218171726_add_pins.sql (13.18ms)
  673. 4.82 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251218171726_add_pins.sql (13.26ms)
  674. 4.82 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251218171726_add_pins.sql (13.18ms)
  675. 4.82 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251218171726_add_pins.sql (12.8ms)
  676. 4.83 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 1_commit_pending_closure.sql (13.2ms)
  677. 4.83 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 1_commit_pending_closure.sql (13.18ms)
  678. 4.83 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 1_commit_pending_closure.sql (13.25ms)
  679. 4.83 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20260628120000_add_object_size_and_stats.sql (13.27ms)
  680. 4.83 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: successfully migrated database to version: 20260628120000
  681. 4.83 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 1_commit_pending_closure.sql (12.21ms)
  682. 4.83 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 1_commit_pending_closure.sql (12.23ms)
  683. 4.83 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20260628120000_add_object_size_and_stats.sql (12.21ms)
  684. 4.83 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20260628120000_add_object_size_and_stats.sql (12.19ms)
  685. 4.83 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20260628120000_add_object_size_and_stats.sql (12.22ms)
  686. 4.83 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20260628120000_add_object_size_and_stats.sql (12.08ms)
  687. 4.83 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: successfully migrated database to version: 20260628120000
  688. 4.83 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: successfully migrated database to version: 20260628120000
  689. 4.83 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: successfully migrated database to version: 20260628120000
  690. 4.83 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20260628120000_add_object_size_and_stats.sql (10.27ms)
  691. 4.83 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: successfully migrated database to version: 20260628120000
  692. 4.83 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20260628120000_add_object_size_and_stats.sql (12.12ms)
  693. 4.83 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: successfully migrated database to version: 20260628120000
  694. 4.83 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: successfully migrated database to version: 20260628120000
  695. 4.84 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 2_object_stats_trigger.sql (12.15ms)
  696. 4.84 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 2_object_stats_trigger.sql (10.3ms)
  697. 4.84 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 2_object_stats_trigger.sql (12.17ms)
  698. 4.84 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: up to current file version: 2
  699. 4.84 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: up to current file version: 2
  700. 4.84 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 1_commit_pending_closure.sql (12.09ms)
  701. 4.84 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: up to current file version: 2
  702. 4.84 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Received uploads request method=POST path=/api/pending_closures
  703. 4.84 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Received uploads request method=POST path=/api/pending_closures
  704. 4.84 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 1_commit_pending_closure.sql (12.37ms)
  705. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 2_object_stats_trigger.sql (12.43ms)
  706. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: up to current file version: 2
  707. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 2_object_stats_trigger.sql (12.45ms)
  708. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: up to current file version: 2
  709. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 1_commit_pending_closure.sql (12.27ms)
  710. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 1_commit_pending_closure.sql (12.33ms)
  711. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 1_commit_pending_closure.sql (10.51ms)
  712. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 1_commit_pending_closure.sql (12.39ms)
  713. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 1_commit_pending_closure.sql (12.09ms)
  714. 4.85 s [niks3-go-unit-tests] --- PASS: TestService_healthCheckHandler (0.78s)
  715. 4.85 s [niks3-go-unit-tests] === CONT TestReadProxyHead
  716. 4.85 s [niks3-go-unit-tests] {"timestamp":"2026-07-19T10:23:56.33484608Z","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(29)"}
  717. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 2_object_stats_trigger.sql (10.36ms)
  718. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: up to current file version: 2
  719. 4.85 s [niks3-go-unit-tests] --- PASS: TestReadProxyNarStreaming (0.78s)
  720. 4.85 s [niks3-go-unit-tests] === CONT TestReadProxyInvalidPath
  721. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Created nix-cache-info in bucket bucket=bucket7
  722. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 2_object_stats_trigger.sql (7.57ms)
  723. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: up to current file version: 2
  724. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 2_object_stats_trigger.sql (7.67ms)
  725. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: up to current file version: 2
  726. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 2_object_stats_trigger.sql (7.64ms)
  727. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: up to current file version: 2
  728. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 2_object_stats_trigger.sql (8.07ms)
  729. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: up to current file version: 2
  730. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 2_object_stats_trigger.sql (7.64ms)
  731. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: up to current file version: 2
  732. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 2_object_stats_trigger.sql (8.6ms)
  733. 4.85 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: up to current file version: 2
  734. 4.86 s [niks3-go-unit-tests] 2026/07/19 10:23:56 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"
  735. 4.86 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware (0.79s)
  736. 4.86 s [niks3-go-unit-tests] === CONT TestReadProxy404
  737. 4.86 s [niks3-go-unit-tests] 2026/07/19 10:23:56 WARN mTLS auth: subject not in bound subjects subject="CN=reader"
  738. 4.86 s [niks3-go-unit-tests] 2026/07/19 10:23:56 WARN mTLS auth: subject not in bound subjects subject="CN=writer"
  739. 4.86 s [niks3-go-unit-tests] --- PASS: TestService_NativeMTLS (0.79s)
  740. 4.86 s [niks3-go-unit-tests] === CONT TestGenerateLandingPage
  741. 4.86 s [niks3-go-unit-tests] --- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.79s)
  742. 4.86 s [niks3-go-unit-tests] --- PASS: TestReadProxyConditionalGet (0.72s)
  743. 4.86 s [niks3-go-unit-tests] --- PASS: TestGenerateLandingPage (0.00s)
  744. 4.86 s [niks3-go-unit-tests] === CONT TestClientWithDependencies
  745. 4.86 s [niks3-go-unit-tests] === CONT TestGCTaskStore_StartNew
  746. 4.86 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_StartNew (0.00s)
  747. 4.86 s [niks3-go-unit-tests] === CONT TestGCBugBareHashReferences
  748. 4.86 s [niks3-go-unit-tests] === CONT TestGCMetrics
  749. 4.86 s [niks3-go-unit-tests] --- PASS: TestReadProxyRangeRequest (0.80s)
  750. 4.86 s [niks3-go-unit-tests] === CONT TestPinProtectsFromGC
  751. 4.89 s [niks3-go-unit-tests] --- PASS: TestMetricsInventory (0.83s)
  752. 4.89 s [niks3-go-unit-tests] === CONT TestService_createPendingClosureHandler
  753. 4.91 s [niks3-go-unit-tests] --- PASS: TestObjectStatsTrigger (0.84s)
  754. 4.91 s [niks3-go-unit-tests] === CONT TestCompleteMultipartUnregistered
  755. 4.96 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Received cleanup request method=DELETE path=/api/pending_closures
  756. 4.96 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Aborted multipart uploads count=1
  757. 4.97 s [niks3-go-unit-tests] --- PASS: TestMultipartCleanup (0.90s)
  758. 4.97 s [niks3-go-unit-tests] === CONT TestService_verifyS3Integrity
  759. 4.98 s [niks3-go-unit-tests] === CONT TestGCTaskStore_GetReturnsLatest
  760. 4.98 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)
  761. 4.98 s [niks3-go-unit-tests] === CONT TestGCTaskStore_Fail
  762. 4.98 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_Fail (0.00s)
  763. 4.98 s [niks3-go-unit-tests] === CONT TestGCTaskStore_PhaseUpdates
  764. 4.98 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_PhaseUpdates (0.00s)
  765. 4.98 s [niks3-go-unit-tests] === CONT TestGCTaskStore_CompletedAllowsNewTask
  766. 4.98 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)
  767. 4.98 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectOversizedBody
  768. 5.00 s [niks3-go-unit-tests] === NAME TestNARDeduplicationMetadataUploadBug
  769. 5.00 s [niks3-go-unit-tests] metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug2643583335/001/store/8h71dmpig9y94fpwsyp0p3pr6cqgsisc-file1.txt
  770. 5.11 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectOversizedBody/create_pending_closure
  771. 5.11 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure
  772. 5.11 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectOversizedBody/complete_multipart
  773. 5.11 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart
  774. 5.11 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectOversizedBody/request_more_parts
  775. 5.11 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts
  776. 5.11 s [niks3-go-unit-tests] === CONT TestService_cleanupPendingClosuresHandler
  777. 5.13 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Received uploads request method=POST path=/api/pending_closures
  778. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)
  779. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Uploading 8h71dmpig9y94fpwsyp0p3pr6cqgsisc-file1.txt (160B)
  780. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"
  781. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 WARN Failed to register uploaded object key=8h71dmpig9y94fpwsyp0p3pr6cqgsisc.ls error="server returned 404: 404 page not found\n"
  782. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign
  783. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Signed narinfos id=1 count=1
  784. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Uploading 1 narinfos
  785. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 WARN Failed to register uploaded object key=8h71dmpig9y94fpwsyp0p3pr6cqgsisc.narinfo error="server returned 404: 404 page not found\n"
  786. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  787. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Completed upload id=1
  788. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Upload complete. (113ms)
  789. 5.27 s [niks3-go-unit-tests] === NAME TestNARDeduplicationMetadataUploadBug
  790. 5.27 s [niks3-go-unit-tests] metadata_upload_test.go:54: Retrieved narinfo from S3:
  791. 5.27 s [niks3-go-unit-tests] StorePath: /build/TestNARDeduplicationMetadataUploadBug2643583335/001/store/8h71dmpig9y94fpwsyp0p3pr6cqgsisc-file1.txt
  792. 5.27 s [niks3-go-unit-tests] URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst
  793. 5.27 s [niks3-go-unit-tests] Compression: zstd
  794. 5.27 s [niks3-go-unit-tests] NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf
  795. 5.27 s [niks3-go-unit-tests] NarSize: 160
  796. 5.27 s [niks3-go-unit-tests] References:
  797. 5.27 s [niks3-go-unit-tests] CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf
  798. 5.27 s [niks3-go-unit-tests] metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)
  799. 5.27 s [niks3-go-unit-tests] metadata_upload_test.go:55: Decompressed .ls content (64 bytes):
  800. 5.27 s [niks3-go-unit-tests] {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}
  801. 5.27 s [niks3-go-unit-tests] 2026-07-19 10:23:56.639 UTC [263] ERROR: relation "goose_db_version" does not exist at character 36
  802. 5.27 s [niks3-go-unit-tests] 2026-07-19 10:23:56.639 UTC [263] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  803. 5.27 s [niks3-go-unit-tests] 2026-07-19 10:23:56.639 UTC [319] ERROR: relation "goose_db_version" does not exist at character 36
  804. 5.27 s [niks3-go-unit-tests] 2026-07-19 10:23:56.639 UTC [319] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  805. 5.27 s [niks3-go-unit-tests] 2026-07-19 10:23:56.641 UTC [320] ERROR: relation "goose_db_version" does not exist at character 36
  806. 5.27 s [niks3-go-unit-tests] 2026-07-19 10:23:56.641 UTC [320] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  807. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20241026095416_initial_model.sql (23.07ms)
  808. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20241026095416_initial_model.sql (16.53ms)
  809. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20241026095416_initial_model.sql (16.47ms)
  810. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251210153512_drop_unused_gin_index.sql (9.71ms)
  811. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251210153512_drop_unused_gin_index.sql (16.33ms)
  812. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251210153512_drop_unused_gin_index.sql (15.93ms)
  813. 5.27 s [niks3-go-unit-tests] metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug2643583335/001/store/xhmb7qfhgx25ywsqi35dkyjm1j248sfz-file2.txt
  814. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251218171726_add_pins.sql (53.08ms)
  815. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251218171726_add_pins.sql (54.43ms)
  816. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251218171726_add_pins.sql (54.43ms)
  817. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20260628120000_add_object_size_and_stats.sql (7.6ms)
  818. 5.27 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: successfully migrated database to version: 20260628120000
  819. 5.28 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 1_commit_pending_closure.sql (12.85ms)
  820. 5.28 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20260628120000_add_object_size_and_stats.sql (12.92ms)
  821. 5.28 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: successfully migrated database to version: 20260628120000
  822. 5.28 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20260628120000_add_object_size_and_stats.sql (12.93ms)
  823. 5.28 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: successfully migrated database to version: 20260628120000
  824. 5.28 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 2_object_stats_trigger.sql (6.08ms)
  825. 5.28 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: up to current file version: 2
  826. 5.29 s [niks3-go-unit-tests] --- PASS: TestReadProxyRootRedirectsToIndexHTML (1.22s)
  827. 5.29 s [niks3-go-unit-tests] === CONT TestGCTaskStore_ConflictDifferentParams
  828. 5.29 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)
  829. 5.29 s [niks3-go-unit-tests] === CONT TestGCTaskStore_GetEmpty
  830. 5.29 s [niks3-go-unit-tests] --- PASS: TestGCTaskStore_GetEmpty (0.00s)
  831. 5.29 s [niks3-go-unit-tests] === CONT TestPresignedUploadRegisteredBeforeCommit
  832. 5.29 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 1_commit_pending_closure.sql (12.21ms)
  833. 5.29 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 1_commit_pending_closure.sql (12.2ms)
  834. 5.30 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 2_object_stats_trigger.sql (6.03ms)
  835. 5.30 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: up to current file version: 2
  836. 5.30 s [niks3-go-unit-tests] --- PASS: TestReadProxy404 (0.44s)
  837. 5.30 s [niks3-go-unit-tests] === CONT TestProxyWriteTimeout
  838. 5.30 s [niks3-go-unit-tests] === RUN TestProxyWriteTimeout/narinfo
  839. 5.30 s [niks3-go-unit-tests] === PAUSE TestProxyWriteTimeout/narinfo
  840. 5.30 s [niks3-go-unit-tests] === RUN TestProxyWriteTimeout/1_GiB_nar
  841. 5.30 s [niks3-go-unit-tests] === PAUSE TestProxyWriteTimeout/1_GiB_nar
  842. 5.30 s [niks3-go-unit-tests] === RUN TestProxyWriteTimeout/10_GiB_nar
  843. 5.30 s [niks3-go-unit-tests] === PAUSE TestProxyWriteTimeout/10_GiB_nar
  844. 5.30 s [niks3-go-unit-tests] === RUN TestProxyWriteTimeout/unknown_size
  845. 5.30 s [niks3-go-unit-tests] === PAUSE TestProxyWriteTimeout/unknown_size
  846. 5.30 s [niks3-go-unit-tests] === CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle
  847. 5.31 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 2_object_stats_trigger.sql (16.18ms)
  848. 5.31 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: up to current file version: 2
  849. 5.31 s [niks3-go-unit-tests] --- PASS: TestReadProxyInvalidPath (0.46s)
  850. 5.31 s [niks3-go-unit-tests] === CONT TestService_Rustfstest
  851. 5.31 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Received uploads request method=POST path=/api/pending_closures
  852. 5.32 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)
  853. 5.32 s [niks3-go-unit-tests] 2026/07/19 10:23:56 WARN Failed to register uploaded object key=xhmb7qfhgx25ywsqi35dkyjm1j248sfz.ls error="server returned 404: 404 page not found\n"
  854. 5.32 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign
  855. 5.32 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Signed narinfos id=2 count=1
  856. 5.32 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Uploading 1 narinfos
  857. 5.32 s [niks3-go-unit-tests] 2026/07/19 10:23:56 WARN Failed to register uploaded object key=xhmb7qfhgx25ywsqi35dkyjm1j248sfz.narinfo error="server returned 404: 404 page not found\n"
  858. 5.32 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete
  859. 5.33 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Completed upload id=2
  860. 5.33 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO Upload complete. (58ms)
  861. 5.33 s [niks3-go-unit-tests] === NAME TestNARDeduplicationMetadataUploadBug
  862. 5.33 s [niks3-go-unit-tests] metadata_upload_test.go:76: Retrieved narinfo from S3:
  863. 5.33 s [niks3-go-unit-tests] StorePath: /build/TestNARDeduplicationMetadataUploadBug2643583335/001/store/xhmb7qfhgx25ywsqi35dkyjm1j248sfz-file2.txt
  864. 5.33 s [niks3-go-unit-tests] URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst
  865. 5.33 s [niks3-go-unit-tests] Compression: zstd
  866. 5.33 s [niks3-go-unit-tests] NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf
  867. 5.33 s [niks3-go-unit-tests] NarSize: 160
  868. 5.33 s [niks3-go-unit-tests] References:
  869. 5.33 s [niks3-go-unit-tests] CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf
  870. 5.33 s [niks3-go-unit-tests] metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)
  871. 5.33 s [niks3-go-unit-tests] metadata_upload_test.go:77: Decompressed .ls content (49 bytes):
  872. 5.33 s [niks3-go-unit-tests] {"version":1,"root":{"type":"regular","size":44}}
  873. 5.33 s [niks3-go-unit-tests] --- PASS: TestNARDeduplicationMetadataUploadBug (1.27s)
  874. 5.33 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_OIDC
  875. 5.33 s [niks3-go-unit-tests] 2026/07/19 10:23:56 INFO OIDC provider initialized name=test
  876. 5.39 s [niks3-go-unit-tests] 2026-07-19 10:23:56.872 UTC [358] ERROR: relation "goose_db_version" does not exist at character 36
  877. 5.39 s [niks3-go-unit-tests] 2026-07-19 10:23:56.872 UTC [358] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  878. 5.39 s [niks3-go-unit-tests] 2026-07-19 10:23:56.872 UTC [355] ERROR: relation "goose_db_version" does not exist at character 36
  879. 5.39 s [niks3-go-unit-tests] 2026-07-19 10:23:56.872 UTC [355] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  880. 5.39 s [niks3-go-unit-tests] 2026-07-19 10:23:56.872 UTC [356] ERROR: relation "goose_db_version" does not exist at character 36
  881. 5.39 s [niks3-go-unit-tests] 2026-07-19 10:23:56.872 UTC [356] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  882. 5.39 s [niks3-go-unit-tests] 2026-07-19 10:23:56.873 UTC [357] ERROR: relation "goose_db_version" does not exist at character 36
  883. 5.39 s [niks3-go-unit-tests] 2026-07-19 10:23:56.873 UTC [357] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  884. 5.43 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20241026095416_initial_model.sql (28.42ms)
  885. 5.44 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251210153512_drop_unused_gin_index.sql (6.6ms)
  886. 5.45 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20241026095416_initial_model.sql (35.48ms)
  887. 5.45 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20241026095416_initial_model.sql (35.47ms)
  888. 5.45 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20241026095416_initial_model.sql (35.48ms)
  889. 5.45 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251210153512_drop_unused_gin_index.sql (6.71ms)
  890. 5.45 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251210153512_drop_unused_gin_index.sql (6.79ms)
  891. 5.50 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251218171726_add_pins.sql (54.52ms)
  892. 5.50 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251210153512_drop_unused_gin_index.sql (47.47ms)
  893. 5.50 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251218171726_add_pins.sql (44.35ms)
  894. 5.50 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251218171726_add_pins.sql (44.32ms)
  895. 5.50 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20251218171726_add_pins.sql (8.26ms)
  896. 5.51 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20260628120000_add_object_size_and_stats.sql (15.36ms)
  897. 5.51 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: successfully migrated database to version: 20260628120000
  898. 5.51 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20260628120000_add_object_size_and_stats.sql (11.63ms)
  899. 5.51 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: successfully migrated database to version: 20260628120000
  900. 5.51 s [niks3-go-unit-tests] 2026/07/19 10:23:56 OK 20260628120000_add_object_size_and_stats.sql (11.65ms)
  901. 5.51 s [niks3-go-unit-tests] 2026/07/19 10:23:56 goose: successfully migrated database to version: 20260628120000
  902. 5.52 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 1_commit_pending_closure.sql (6.37ms)
  903. 5.52 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 1_commit_pending_closure.sql (12.95ms)
  904. 5.52 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 1_commit_pending_closure.sql (13.02ms)
  905. 5.52 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20260628120000_add_object_size_and_stats.sql (20.06ms)
  906. 5.52 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: successfully migrated database to version: 20260628120000
  907. 5.53 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 2_object_stats_trigger.sql (12.88ms)
  908. 5.53 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: up to current file version: 2
  909. 5.54 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 1_commit_pending_closure.sql (12.34ms)
  910. 5.54 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 2_object_stats_trigger.sql (12.41ms)
  911. 5.54 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: up to current file version: 2
  912. 5.54 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 2_object_stats_trigger.sql (12.47ms)
  913. 5.54 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: up to current file version: 2
  914. 5.54 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Created nix-cache-info in bucket bucket=bucket18
  915. 5.54 s [niks3-go-unit-tests] --- PASS: TestReadProxyHead (0.70s)
  916. 5.54 s [niks3-go-unit-tests] === CONT TestClientCADerivations
  917. 5.54 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 2_object_stats_trigger.sql (6.87ms)
  918. 5.54 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: up to current file version: 2
  919. 5.62 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Aborted multipart uploads count=0
  920. 5.62 s [niks3-go-unit-tests] 2026/07/19 10:23:57 WARN Force mode enabled - objects will be deleted immediately without grace period
  921. 5.62 s [niks3-go-unit-tests] 2026/07/19 10:23:57 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
  922. 5.67 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Vacuumed table table=pending_closures
  923. 5.67 s [niks3-go-unit-tests] 2026-07-19 10:23:57.156 UTC [401] ERROR: relation "goose_db_version" does not exist at character 36
  924. 5.67 s [niks3-go-unit-tests] 2026-07-19 10:23:57.156 UTC [401] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  925. 5.67 s [niks3-go-unit-tests] 2026-07-19 10:23:57.156 UTC [400] ERROR: relation "goose_db_version" does not exist at character 36
  926. 5.67 s [niks3-go-unit-tests] 2026-07-19 10:23:57.156 UTC [400] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  927. 5.67 s [niks3-go-unit-tests] 2026-07-19 10:23:57.156 UTC [402] ERROR: relation "goose_db_version" does not exist at character 36
  928. 5.67 s [niks3-go-unit-tests] 2026-07-19 10:23:57.156 UTC [402] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  929. 5.67 s [niks3-go-unit-tests] 2026-07-19 10:23:57.156 UTC [398] ERROR: relation "goose_db_version" does not exist at character 36
  930. 5.67 s [niks3-go-unit-tests] 2026-07-19 10:23:57.156 UTC [398] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  931. 5.67 s [niks3-go-unit-tests] 2026-07-19 10:23:57.156 UTC [399] ERROR: relation "goose_db_version" does not exist at character 36
  932. 5.67 s [niks3-go-unit-tests] 2026-07-19 10:23:57.156 UTC [399] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  933. 5.67 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Vacuumed table table=pending_objects
  934. 5.67 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Vacuumed table table=multipart_uploads
  935. 5.67 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Vacuumed table table=closures
  936. 5.67 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Vacuumed table table=objects
  937. 5.67 s [niks3-go-unit-tests] --- PASS: TestGCMetrics (0.81s)
  938. 5.67 s [niks3-go-unit-tests] === CONT TestCacheStatsHandler
  939. 5.68 s [niks3-go-unit-tests] 2026-07-19 10:23:57.166 UTC [427] ERROR: relation "goose_db_version" does not exist at character 36
  940. 5.68 s [niks3-go-unit-tests] 2026-07-19 10:23:57.166 UTC [427] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  941. 5.70 s [niks3-go-unit-tests] 2026-07-19 10:23:57.186 UTC [440] ERROR: relation "goose_db_version" does not exist at character 36
  942. 5.70 s [niks3-go-unit-tests] 2026-07-19 10:23:57.186 UTC [440] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  943. 5.71 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20241026095416_initial_model.sql (20.17ms)
  944. 5.71 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251210153512_drop_unused_gin_index.sql (5.13ms)
  945. 5.72 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20241026095416_initial_model.sql (23.48ms)
  946. 5.72 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20241026095416_initial_model.sql (25.58ms)
  947. 5.72 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20241026095416_initial_model.sql (25.38ms)
  948. 5.72 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20241026095416_initial_model.sql (24.12ms)
  949. 5.73 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251218171726_add_pins.sql (12.82ms)
  950. 5.73 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20241026095416_initial_model.sql (30.6ms)
  951. 5.73 s [niks3-go-unit-tests] === NAME TestClientWithDependencies
  952. 5.73 s [niks3-go-unit-tests] client_integration_test.go:593: Built derivation: /build/TestClientWithDependencies1546905797/001/store/sm4wn4b1zhdv3b5nyh4izxsiyab0v24b-test-script
  953. 5.73 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20241026095416_initial_model.sql (12.11ms)
  954. 5.73 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251210153512_drop_unused_gin_index.sql (11.96ms)
  955. 5.73 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251210153512_drop_unused_gin_index.sql (12.7ms)
  956. 5.73 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251210153512_drop_unused_gin_index.sql (12.75ms)
  957. 5.73 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251210153512_drop_unused_gin_index.sql (12.25ms)
  958. 5.74 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20260628120000_add_object_size_and_stats.sql (12.57ms)
  959. 5.74 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: successfully migrated database to version: 20260628120000
  960. 5.74 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251210153512_drop_unused_gin_index.sql (12.73ms)
  961. 5.74 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251218171726_add_pins.sql (12.45ms)
  962. 5.74 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251218171726_add_pins.sql (12.45ms)
  963. 5.75 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251218171726_add_pins.sql (12.44ms)
  964. 5.75 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251218171726_add_pins.sql (12.43ms)
  965. 5.75 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251210153512_drop_unused_gin_index.sql (12.77ms)
  966. 5.75 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 1_commit_pending_closure.sql (12.45ms)
  967. 5.75 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251218171726_add_pins.sql (12.3ms)
  968. 5.75 s [niks3-go-unit-tests] client_integration_test.go:595: Found 1 dependencies (including self)
  969. 5.76 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20260628120000_add_object_size_and_stats.sql (12.49ms)
  970. 5.76 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: successfully migrated database to version: 20260628120000
  971. 5.76 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251218171726_add_pins.sql (12.35ms)
  972. 5.76 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20260628120000_add_object_size_and_stats.sql (12.55ms)
  973. 5.76 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20260628120000_add_object_size_and_stats.sql (12.52ms)
  974. 5.76 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: successfully migrated database to version: 20260628120000
  975. 5.76 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: successfully migrated database to version: 20260628120000
  976. 5.76 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20260628120000_add_object_size_and_stats.sql (12.52ms)
  977. 5.76 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: successfully migrated database to version: 20260628120000
  978. 5.76 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 2_object_stats_trigger.sql (12.49ms)
  979. 5.76 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: up to current file version: 2
  980. 5.76 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20260628120000_add_object_size_and_stats.sql (12.46ms)
  981. 5.76 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: successfully migrated database to version: 20260628120000
  982. 5.77 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received uploads request method=POST path=/api/pending_closures
  983. 5.77 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received uploads request method=POST path=/api/pending_closures
  984. 5.77 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received uploads request method=POST path=/api/pending_closures
  985. 5.77 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 1_commit_pending_closure.sql (12.4ms)
  986. 5.77 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 1_commit_pending_closure.sql (12.33ms)
  987. 5.77 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20260628120000_add_object_size_and_stats.sql (12.42ms)
  988. 5.77 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 1_commit_pending_closure.sql (12.38ms)
  989. 5.77 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: successfully migrated database to version: 20260628120000
  990. 5.77 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 1_commit_pending_closure.sql (12.4ms)
  991. 5.77 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 1_commit_pending_closure.sql (9.48ms)
  992. 5.78 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 2_object_stats_trigger.sql (6.88ms)
  993. 5.78 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: up to current file version: 2
  994. 5.78 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 2_object_stats_trigger.sql (6.89ms)
  995. 5.78 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 1_commit_pending_closure.sql (6.89ms)
  996. 5.78 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 2_object_stats_trigger.sql (6.9ms)
  997. 5.78 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 2_object_stats_trigger.sql (6.92ms)
  998. 5.78 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: up to current file version: 2
  999. 5.78 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: up to current file version: 2
  1000. 5.78 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: up to current file version: 2
  1001. 5.78 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received uploads request method=POST path=/api/pending_closures
  1002. 5.78 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete
  1003. 5.78 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received cleanup request method=DELETE path=/api/pending_closures
  1004. 5.78 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received uploads request method=POST path=/api/pending_closures
  1005. 5.78 s [niks3-go-unit-tests] 2026/07/19 10:23:57 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst
  1006. 5.78 s [niks3-go-unit-tests] --- PASS: TestCompleteMultipartUnregistered (0.87s)
  1007. 5.78 s [niks3-go-unit-tests] === CONT TestCacheConfigHandler
  1008. 5.78 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Aborted multipart uploads count=0
  1009. 5.78 s [niks3-go-unit-tests] === RUN TestCacheConfigHandler/full_config,_no_issuer
  1010. 5.78 s [niks3-go-unit-tests] === PAUSE TestCacheConfigHandler/full_config,_no_issuer
  1011. 5.78 s [niks3-go-unit-tests] === RUN TestCacheConfigHandler/no_cache_url_configured
  1012. 5.78 s [niks3-go-unit-tests] === PAUSE TestCacheConfigHandler/no_cache_url_configured
  1013. 5.78 s [niks3-go-unit-tests] === RUN TestCacheConfigHandler/no_signing_keys
  1014. 5.78 s [niks3-go-unit-tests] === PAUSE TestCacheConfigHandler/no_signing_keys
  1015. 5.78 s [niks3-go-unit-tests] === RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator
  1016. 5.78 s [niks3-go-unit-tests] === PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator
  1017. 5.78 s [niks3-go-unit-tests] === CONT TestCompleteMultipartUpload_ErrorButObjectExists
  1018. 5.78 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received uploads request method=POST path=/api/pending_closures
  1019. 5.78 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 2_object_stats_trigger.sql (9.76ms)
  1020. 5.78 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: up to current file version: 2
  1021. 5.79 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Created nix-cache-info in bucket bucket=bucket26
  1022. 5.79 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 2_object_stats_trigger.sql (12.46ms)
  1023. 5.79 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: up to current file version: 2
  1024. 5.79 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received uploads request method=POST path=/api/pending_closures
  1025. 5.80 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received uploads request method=POST path=/api/pending_closures
  1026. 5.80 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received cleanup request method=DELETE path=/api/pending_closures
  1027. 5.80 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Aborted multipart uploads count=1
  1028. 5.80 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst
  1029. 5.80 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received uploads request method=POST path=/api/pending_closures
  1030. 5.81 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1031. 5.81 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)
  1032. 5.81 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Uploading sm4wn4b1zhdv3b5nyh4izxsiyab0v24b-test-script (136B)
  1033. 5.81 s [niks3-go-unit-tests] 2026-07-19 10:23:57.296 UTC [400] ERROR: Closure does not exist: id=1
  1034. 5.81 s [niks3-go-unit-tests] 2026-07-19 10:23:57.296 UTC [400] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE
  1035. 5.81 s [niks3-go-unit-tests] 2026-07-19 10:23:57.296 UTC [400] STATEMENT: -- name: CommitPendingClosure :exec
  1036. 5.81 s [niks3-go-unit-tests] SELECT commit_pending_closure($1::bigint)
  1037. 5.81 s [niks3-go-unit-tests]
  1038. 5.81 s [niks3-go-unit-tests] --- PASS: TestService_cleanupPendingClosuresHandler (0.70s)
  1039. 5.81 s [niks3-go-unit-tests] === CONT TestCompletedNarNotReofferedAcrossClosures
  1040. 5.81 s [niks3-go-unit-tests] 2026/07/19 10:23:57 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"
  1041. 5.81 s [niks3-go-unit-tests] 2026/07/19 10:23:57 WARN Failed to register uploaded object key=log/jyq2ppp10z5z0fj28c4l8l8ri88g7xg8-test-script.drv error="server returned 404: 404 page not found\n"
  1042. 5.81 s [niks3-go-unit-tests] --- PASS: TestGCBugBareHashReferences (0.95s)
  1043. 5.81 s [niks3-go-unit-tests] === CONT TestRedundantMultipartUpload
  1044. 5.82 s [niks3-go-unit-tests] --- PASS: TestPresignedUploadRegisteredBeforeCommit (0.53s)
  1045. 5.82 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectInvalidKeys
  1046. 5.82 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info
  1047. 5.82 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info
  1048. 5.82 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal
  1049. 5.82 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal
  1050. 5.82 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key
  1051. 5.82 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key
  1052. 5.82 s [niks3-go-unit-tests] === RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key
  1053. 5.82 s [niks3-go-unit-tests] === PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key
  1054. 5.82 s [niks3-go-unit-tests] === CONT TestClientMultipleUploads
  1055. 5.82 s [niks3-go-unit-tests] 2026-07-19 10:23:57.302 UTC [442] ERROR: relation "goose_db_version" does not exist at character 36
  1056. 5.82 s [niks3-go-unit-tests] 2026-07-19 10:23:57.302 UTC [442] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1057. 5.82 s [niks3-go-unit-tests] 2026/07/19 10:23:57 WARN Failed to register uploaded object key=sm4wn4b1zhdv3b5nyh4izxsiyab0v24b.ls error="server returned 404: 404 page not found\n"
  1058. 5.82 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign
  1059. 5.82 s [niks3-go-unit-tests] 2026-07-19 10:23:57.305 UTC [441] ERROR: relation "goose_db_version" does not exist at character 36
  1060. 5.82 s [niks3-go-unit-tests] 2026-07-19 10:23:57.305 UTC [441] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1061. 5.82 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Signed narinfos id=1 count=1
  1062. 5.82 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Uploading 1 narinfos
  1063. 5.83 s [niks3-go-unit-tests] 2026/07/19 10:23:57 WARN Failed to register uploaded object key=sm4wn4b1zhdv3b5nyh4izxsiyab0v24b.narinfo error="server returned 404: 404 page not found\n"
  1064. 5.83 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1065. 5.84 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20241026095416_initial_model.sql (13.01ms)
  1066. 5.84 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Completed upload id=1
  1067. 5.84 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Upload complete. (66ms)
  1068. 5.85 s [niks3-go-unit-tests] === NAME TestClientWithDependencies
  1069. 5.85 s [niks3-go-unit-tests] client_integration_test.go:597: Skipping nix copy test - isolated store (/build/TestClientWithDependencies1546905797/001/store) requires matching store prefix
  1070. 5.85 s [niks3-go-unit-tests] --- PASS: TestClientWithDependencies (0.99s)
  1071. 5.85 s [niks3-go-unit-tests] === CONT TestClientIntegration
  1072. 5.85 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete
  1073. 5.90 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251210153512_drop_unused_gin_index.sql (60.88ms)
  1074. 5.91 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20241026095416_initial_model.sql (73.58ms)
  1075. 5.91 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251218171726_add_pins.sql (12.77ms)
  1076. 5.92 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251210153512_drop_unused_gin_index.sql (12.81ms)
  1077. 5.92 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete
  1078. 5.93 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20260628120000_add_object_size_and_stats.sql (12.8ms)
  1079. 5.93 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: successfully migrated database to version: 20260628120000
  1080. 5.93 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251218171726_add_pins.sql (12.41ms)
  1081. 5.94 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 1_commit_pending_closure.sql (12.62ms)
  1082. 5.94 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete
  1083. 5.94 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20260628120000_add_object_size_and_stats.sql (9.74ms)
  1084. 5.94 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: successfully migrated database to version: 20260628120000
  1085. 5.95 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 2_object_stats_trigger.sql (9.51ms)
  1086. 5.95 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: up to current file version: 2
  1087. 5.95 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ODZhYzg4MjctMjQ3OS00MGNhLThhNTAtYjkyNjMxOTk4MjE3Ljc0ZmIwZjZkLTgyY2UtNDk4OC1hZjIzLWFiYTBhMGRkNzQ2MHgxNzg0NDU2NjM3MjYwMzg5NDg0 parts=10
  1088. 5.95 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1089. 5.95 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token
  1090. 5.95 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token
  1091. 5.95 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected
  1092. 5.95 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected
  1093. 5.95 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected
  1094. 5.95 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected
  1095. 5.95 s [niks3-go-unit-tests] === RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured
  1096. 5.95 s [niks3-go-unit-tests] === PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured
  1097. 5.95 s [niks3-go-unit-tests] === CONT TestClientErrorHandling/ServerNotAvailable
  1098. 5.95 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 1_commit_pending_closure.sql (12.35ms)
  1099. 5.96 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Completed upload id=1
  1100. 5.96 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000
  1101. 5.96 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received uploads request method=POST path=/api/pending_closures
  1102. 5.97 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 2_object_stats_trigger.sql (12.79ms)
  1103. 5.97 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: up to current file version: 2
  1104. 5.97 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ODZhYzg4MjctMjQ3OS00MGNhLThhNTAtYjkyNjMxOTk4MjE3LjQwNzVkN2M0LTU1ZGEtNDdiOC1iZWQ2LTExMmY4NTdhN2ZmMngxNzg0NDU2NjM3Mjc2NjY0OTkz parts=10
  1105. 5.97 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1106. 5.97 s [niks3-go-unit-tests] --- PASS: TestService_Rustfstest (0.66s)
  1107. 5.97 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_MTLSBoundSubjects
  1108. 5.97 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Starting cleanup of old closures method=DELETE path=/api/closures
  1109. 5.98 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Completed upload id=1
  1110. 5.98 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received uploads request method=POST path=/api/pending_closures
  1111. 5.98 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received uploads request method=POST path=/api/pending_closures
  1112. 5.98 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo
  1113. 5.98 s [niks3-go-unit-tests] 2026/07/19 10:23:57 WARN Found objects in DB but missing from S3, will re-upload count=1
  1114. 5.99 s [niks3-go-unit-tests] --- PASS: TestService_verifyS3Integrity (1.02s)
  1115. 5.99 s [niks3-go-unit-tests] === CONT TestService_ReadAuthMiddleware
  1116. 6.03 s [niks3-go-unit-tests] === NAME TestPinProtectsFromGC
  1117. 6.03 s [niks3-go-unit-tests] client_integration_test.go:646: Pinned store path: /build/TestPinProtectsFromGC2335267816/001/store/7yf8y4zn0y55brdwzazc49bzn81aw9i7-pinned-file.txt
  1118. 6.03 s [niks3-go-unit-tests] client_integration_test.go:647: Unpinned store path: /build/TestPinProtectsFromGC2335267816/001/store/ib58r512jlw8cwqzw97909awvbgjva88-unpinned-file.txt
  1119. 6.10 s [niks3-go-unit-tests] 2026-07-19 10:23:57.583 UTC [519] ERROR: relation "goose_db_version" does not exist at character 36
  1120. 6.10 s [niks3-go-unit-tests] 2026-07-19 10:23:57.583 UTC [519] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1121. 6.10 s [niks3-go-unit-tests] 2026-07-19 10:23:57.584 UTC [518] ERROR: relation "goose_db_version" does not exist at character 36
  1122. 6.10 s [niks3-go-unit-tests] 2026-07-19 10:23:57.584 UTC [518] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1123. 6.13 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20241026095416_initial_model.sql (13.99ms)
  1124. 6.14 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20241026095416_initial_model.sql (17.82ms)
  1125. 6.14 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251210153512_drop_unused_gin_index.sql (16.29ms)
  1126. 6.15 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received uploads request method=POST path=/api/pending_closures
  1127. 6.15 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251210153512_drop_unused_gin_index.sql (12.84ms)
  1128. 6.16 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251218171726_add_pins.sql (13.86ms)
  1129. 6.18 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Aborted multipart uploads count=0
  1130. 6.20 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251218171726_add_pins.sql (53.64ms)
  1131. 6.20 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)
  1132. 6.20 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Uploading 7yf8y4zn0y55brdwzazc49bzn81aw9i7-pinned-file.txt (128B)
  1133. 6.20 s [niks3-go-unit-tests] 2026/07/19 10:23:57 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"
  1134. 6.21 s [niks3-go-unit-tests] 2026/07/19 10:23:57 WARN Failed to register uploaded object key=7yf8y4zn0y55brdwzazc49bzn81aw9i7.ls error="server returned 404: 404 page not found\n"
  1135. 6.21 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign
  1136. 6.21 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Signed narinfos id=1 count=1
  1137. 6.21 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Uploading 1 narinfos
  1138. 6.21 s [niks3-go-unit-tests] 2026/07/19 10:23:57 WARN Failed to register uploaded object key=7yf8y4zn0y55brdwzazc49bzn81aw9i7.narinfo error="server returned 404: 404 page not found\n"
  1139. 6.21 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1140. 6.21 s [niks3-go-unit-tests] 2026/07/19 10:23:57 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
  1141. 6.22 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20260628120000_add_object_size_and_stats.sql (12.78ms)
  1142. 6.22 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: successfully migrated database to version: 20260628120000
  1143. 6.22 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20260628120000_add_object_size_and_stats.sql (58.93ms)
  1144. 6.22 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: successfully migrated database to version: 20260628120000
  1145. 6.22 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Completed upload id=1
  1146. 6.22 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Upload complete. (174ms)
  1147. 6.23 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 1_commit_pending_closure.sql (11.09ms)
  1148. 6.23 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 1_commit_pending_closure.sql (11.1ms)
  1149. 6.23 s [niks3-go-unit-tests] 2026/07/19 10:23:57 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
  1150. 6.23 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 2_object_stats_trigger.sql (6.09ms)
  1151. 6.23 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: up to current file version: 2
  1152. 6.24 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 2_object_stats_trigger.sql (12.24ms)
  1153. 6.24 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: up to current file version: 2
  1154. 6.24 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Vacuumed table table=pending_closures
  1155. 6.24 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Created nix-cache-info in bucket bucket=bucket31
  1156. 6.25 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Vacuumed table table=pending_objects
  1157. 6.27 s [niks3-go-unit-tests] --- PASS: TestCacheStatsHandler (0.60s)
  1158. 6.27 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_MTLSProxyHeader
  1159. 6.28 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Vacuumed table table=multipart_uploads
  1160. 6.28 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received uploads request method=POST path=/api/pending_closures
  1161. 6.30 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)
  1162. 6.30 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Uploading ib58r512jlw8cwqzw97909awvbgjva88-unpinned-file.txt (128B)
  1163. 6.30 s [niks3-go-unit-tests] 2026/07/19 10:23:57 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"
  1164. 6.30 s [niks3-go-unit-tests] 2026/07/19 10:23:57 WARN Failed to register uploaded object key=ib58r512jlw8cwqzw97909awvbgjva88.ls error="server returned 404: 404 page not found\n"
  1165. 6.30 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign
  1166. 6.30 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Signed narinfos id=2 count=1
  1167. 6.30 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Uploading 1 narinfos
  1168. 6.30 s [niks3-go-unit-tests] 2026/07/19 10:23:57 WARN Failed to register uploaded object key=ib58r512jlw8cwqzw97909awvbgjva88.narinfo error="server returned 404: 404 page not found\n"
  1169. 6.30 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete
  1170. 6.30 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Vacuumed table table=closures
  1171. 6.31 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Completed upload id=2
  1172. 6.31 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Upload complete. (70ms)
  1173. 6.31 s [niks3-go-unit-tests] 2026/07/19 10:23:57 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=205.550964ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures
  1174. 6.32 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Vacuumed table table=objects
  1175. 6.32 s [niks3-go-unit-tests] 2026-07-19 10:23:57.808 UTC [652] ERROR: relation "goose_db_version" does not exist at character 36
  1176. 6.32 s [niks3-go-unit-tests] 2026-07-19 10:23:57.808 UTC [652] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1177. 6.32 s [niks3-go-unit-tests] 2026-07-19 10:23:57.808 UTC [720] ERROR: relation "goose_db_version" does not exist at character 36
  1178. 6.32 s [niks3-go-unit-tests] 2026-07-19 10:23:57.808 UTC [720] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1179. 6.32 s [niks3-go-unit-tests] 2026-07-19 10:23:57.809 UTC [719] ERROR: relation "goose_db_version" does not exist at character 36
  1180. 6.32 s [niks3-go-unit-tests] 2026-07-19 10:23:57.809 UTC [719] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1181. 6.32 s [niks3-go-unit-tests] 2026-07-19 10:23:57.809 UTC [654] ERROR: relation "goose_db_version" does not exist at character 36
  1182. 6.32 s [niks3-go-unit-tests] 2026-07-19 10:23:57.809 UTC [654] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1183. 6.32 s [niks3-go-unit-tests] 2026-07-19 10:23:57.809 UTC [651] ERROR: relation "goose_db_version" does not exist at character 36
  1184. 6.32 s [niks3-go-unit-tests] 2026-07-19 10:23:57.809 UTC [651] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1185. 6.32 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000
  1186. 6.33 s [niks3-go-unit-tests] --- PASS: TestService_createPendingClosureHandler (1.43s)
  1187. 6.33 s [niks3-go-unit-tests] === CONT TestClientErrorHandling/InvalidAuthToken
  1188. 6.33 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received create pin request method=POST path=/api/pins/myapp
  1189. 6.34 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20241026095416_initial_model.sql (13.3ms)
  1190. 6.34 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2335267816/001/store/7yf8y4zn0y55brdwzazc49bzn81aw9i7-pinned-file.txt narinfo_key=7yf8y4zn0y55brdwzazc49bzn81aw9i7.narinfo
  1191. 6.35 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Starting cleanup of old closures method=DELETE path=/api/closures
  1192. 6.35 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Garbage collection started
  1193. 6.35 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Aborted multipart uploads count=0
  1194. 6.40 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251210153512_drop_unused_gin_index.sql (58.59ms)
  1195. 6.41 s [niks3-go-unit-tests] 2026/07/19 10:23:57 WARN Force mode enabled - objects will be deleted immediately without grace period
  1196. 6.41 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20241026095416_initial_model.sql (69.87ms)
  1197. 6.41 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20241026095416_initial_model.sql (69.97ms)
  1198. 6.41 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20241026095416_initial_model.sql (69.9ms)
  1199. 6.41 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20241026095416_initial_model.sql (69.89ms)
  1200. 6.41 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251218171726_add_pins.sql (8.18ms)
  1201. 6.42 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251210153512_drop_unused_gin_index.sql (9.76ms)
  1202. 6.42 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251210153512_drop_unused_gin_index.sql (9.78ms)
  1203. 6.42 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251210153512_drop_unused_gin_index.sql (9.81ms)
  1204. 6.42 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251210153512_drop_unused_gin_index.sql (9.76ms)
  1205. 6.43 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20260628120000_add_object_size_and_stats.sql (13.95ms)
  1206. 6.43 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: successfully migrated database to version: 20260628120000
  1207. 6.43 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251218171726_add_pins.sql (13.64ms)
  1208. 6.43 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251218171726_add_pins.sql (13.7ms)
  1209. 6.43 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251218171726_add_pins.sql (13.79ms)
  1210. 6.43 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20251218171726_add_pins.sql (13.75ms)
  1211. 6.44 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 1_commit_pending_closure.sql (12.54ms)
  1212. 6.44 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20260628120000_add_object_size_and_stats.sql (12.54ms)
  1213. 6.44 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: successfully migrated database to version: 20260628120000
  1214. 6.44 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20260628120000_add_object_size_and_stats.sql (12.52ms)
  1215. 6.44 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: successfully migrated database to version: 20260628120000
  1216. 6.44 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20260628120000_add_object_size_and_stats.sql (12.58ms)
  1217. 6.44 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 20260628120000_add_object_size_and_stats.sql (12.59ms)
  1218. 6.44 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: successfully migrated database to version: 20260628120000
  1219. 6.44 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: successfully migrated database to version: 20260628120000
  1220. 6.45 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 2_object_stats_trigger.sql (12.63ms)
  1221. 6.45 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: up to current file version: 2
  1222. 6.45 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Created nix-cache-info in bucket bucket=bucket32
  1223. 6.46 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 1_commit_pending_closure.sql (14.44ms)
  1224. 6.46 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 1_commit_pending_closure.sql (14.44ms)
  1225. 6.46 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 1_commit_pending_closure.sql (14.48ms)
  1226. 6.46 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 1_commit_pending_closure.sql (14.49ms)
  1227. 6.46 s [niks3-go-unit-tests] === NAME TestClientCADerivations
  1228. 6.46 s [niks3-go-unit-tests] client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations326000143/001/store/clmxfdy48l27lc4i6423psp3qd04sgkg-ca-test
  1229. 6.46 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 2_object_stats_trigger.sql (6.1ms)
  1230. 6.46 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: up to current file version: 2
  1231. 6.47 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received uploads request method=POST path=/api/pending_closures
  1232. 6.47 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 2_object_stats_trigger.sql (9.42ms)
  1233. 6.47 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: up to current file version: 2
  1234. 6.47 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 2_object_stats_trigger.sql (9.39ms)
  1235. 6.47 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: up to current file version: 2
  1236. 6.47 s [niks3-go-unit-tests] 2026/07/19 10:23:57 OK 2_object_stats_trigger.sql (9.5ms)
  1237. 6.47 s [niks3-go-unit-tests] 2026/07/19 10:23:57 goose: up to current file version: 2
  1238. 6.47 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received uploads request method=POST path=/api/pending_closures
  1239. 6.47 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received uploads request method=POST path=/api/pending_closures
  1240. 6.47 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Created nix-cache-info in bucket bucket=bucket35
  1241. 6.48 s [niks3-go-unit-tests] client_ca_test.go:139: Found 1 dependencies (including self)
  1242. 6.50 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete
  1243. 6.50 s [niks3-go-unit-tests] {"timestamp":"2026-07-19T10:23:57.982807859Z","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)"}
  1244. 6.50 s [niks3-go-unit-tests] {"timestamp":"2026-07-19T10:23:57.982831049Z","level":"ERROR","fields":{"message":"complete_multipart_upload etag err client=Some(\"deadbeef\"), stored=\"\", part_id=1, bucket=bucket33, 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)"}
  1245. 6.50 s [niks3-go-unit-tests] 2026/07/19 10:23:57 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=ODZhYzg4MjctMjQ3OS00MGNhLThhNTAtYjkyNjMxOTk4MjE3LjdmZjliODhkLTJkM2EtNDYyOS05ODE4LTQwMjFmNjU1NjkzZngxNzg0NDU2NjM3OTU4NjM4ODc0
  1246. 6.50 s [niks3-go-unit-tests] 2026/07/19 10:23:57 INFO Received uploads request method=POST path=/api/pending_closures
  1247. 6.52 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=426.96496ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures
  1248. 6.53 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ODZhYzg4MjctMjQ3OS00MGNhLThhNTAtYjkyNjMxOTk4MjE3LjdmZjliODhkLTJkM2EtNDYyOS05ODE4LTQwMjFmNjU1NjkzZngxNzg0NDU2NjM3OTU4NjM4ODc0 parts=1
  1249. 6.53 s [niks3-go-unit-tests] --- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.75s)
  1250. 6.53 s [niks3-go-unit-tests] === CONT TestParseSingleRange
  1251. 6.53 s [niks3-go-unit-tests] === RUN TestParseSingleRange/none
  1252. 6.53 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/none
  1253. 6.53 s [niks3-go-unit-tests] === RUN TestParseSingleRange/unknown_unit
  1254. 6.53 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/unknown_unit
  1255. 6.53 s [niks3-go-unit-tests] === RUN TestParseSingleRange/multi-range_ignored
  1256. 6.53 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/multi-range_ignored
  1257. 6.53 s [niks3-go-unit-tests] === RUN TestParseSingleRange/malformed_no_dash
  1258. 6.53 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/malformed_no_dash
  1259. 6.53 s [niks3-go-unit-tests] === RUN TestParseSingleRange/malformed_both_empty
  1260. 6.53 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/malformed_both_empty
  1261. 6.53 s [niks3-go-unit-tests] === RUN TestParseSingleRange/malformed_end_before_start
  1262. 6.53 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/malformed_end_before_start
  1263. 6.53 s [niks3-go-unit-tests] === RUN TestParseSingleRange/closed
  1264. 6.53 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/closed
  1265. 6.53 s [niks3-go-unit-tests] === RUN TestParseSingleRange/open-ended
  1266. 6.53 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/open-ended
  1267. 6.53 s [niks3-go-unit-tests] === RUN TestParseSingleRange/end_clamped_to_size
  1268. 6.53 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/end_clamped_to_size
  1269. 6.53 s [niks3-go-unit-tests] === RUN TestParseSingleRange/suffix
  1270. 6.53 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/suffix
  1271. 6.53 s [niks3-go-unit-tests] === RUN TestParseSingleRange/suffix_exceeds_size
  1272. 6.53 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/suffix_exceeds_size
  1273. 6.53 s [niks3-go-unit-tests] === RUN TestParseSingleRange/single_byte
  1274. 6.53 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/single_byte
  1275. 6.53 s [niks3-go-unit-tests] === RUN TestParseSingleRange/start_past_EOF
  1276. 6.53 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/start_past_EOF
  1277. 6.53 s [niks3-go-unit-tests] === RUN TestParseSingleRange/start_far_past_EOF
  1278. 6.53 s [niks3-go-unit-tests] === PAUSE TestParseSingleRange/start_far_past_EOF
  1279. 6.53 s [niks3-go-unit-tests] === CONT TestReadProxyNarinfoAlreadyDecompressed
  1280. 6.53 s [niks3-go-unit-tests] 2026-07-19 10:23:58.021 UTC [756] ERROR: relation "goose_db_version" does not exist at character 36
  1281. 6.54 s [niks3-go-unit-tests] 2026-07-19 10:23:58.021 UTC [756] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1282. 6.54 s [niks3-go-unit-tests] 2026-07-19 10:23:58.021 UTC [757] ERROR: relation "goose_db_version" does not exist at character 36
  1283. 6.54 s [niks3-go-unit-tests] 2026-07-19 10:23:58.021 UTC [757] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1284. 6.55 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received uploads request method=POST path=/api/pending_closures
  1285. 6.56 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20241026095416_initial_model.sql (13.36ms)
  1286. 6.56 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)
  1287. 6.56 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Uploading clmxfdy48l27lc4i6423psp3qd04sgkg-ca-test (144B)
  1288. 6.56 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"
  1289. 6.56 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Failed to register uploaded object key=log/xgdf88773sv8l3q1pab8h0fakwz3fli5-ca-test.drv error="server returned 404: 404 page not found\n"
  1290. 6.56 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Failed to register uploaded object key=clmxfdy48l27lc4i6423psp3qd04sgkg.ls error="server returned 404: 404 page not found\n"
  1291. 6.56 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign
  1292. 6.56 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Signed narinfos id=1 count=1
  1293. 6.56 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Uploading 1 narinfos
  1294. 6.57 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Failed to register uploaded object key=clmxfdy48l27lc4i6423psp3qd04sgkg.narinfo error="server returned 404: 404 page not found\n"
  1295. 6.57 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1296. 6.57 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20241026095416_initial_model.sql (14.52ms)
  1297. 6.57 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20251210153512_drop_unused_gin_index.sql (12.52ms)
  1298. 6.58 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20251218171726_add_pins.sql (10.35ms)
  1299. 6.58 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Completed upload id=1
  1300. 6.58 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20251210153512_drop_unused_gin_index.sql (14.87ms)
  1301. 6.58 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Upload complete. (81ms)
  1302. 6.59 s [niks3-go-unit-tests] === NAME TestClientCADerivations
  1303. 6.59 s [niks3-go-unit-tests] client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations326000143/001/store/clmxfdy48l27lc4i6423psp3qd04sgkg-ca-test
  1304. 6.59 s [niks3-go-unit-tests] URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst
  1305. 6.59 s [niks3-go-unit-tests] Compression: zstd
  1306. 6.59 s [niks3-go-unit-tests] NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n
  1307. 6.59 s [niks3-go-unit-tests] NarSize: 144
  1308. 6.59 s [niks3-go-unit-tests] References:
  1309. 6.59 s [niks3-go-unit-tests] Deriver: /build/TestClientCADerivations326000143/001/store/xgdf88773sv8l3q1pab8h0fakwz3fli5-ca-test.drv
  1310. 6.59 s [niks3-go-unit-tests] CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n
  1311. 6.59 s [niks3-go-unit-tests] client_ca_test.go:185: Checking for realisation files in S3...
  1312. 6.59 s [niks3-go-unit-tests] client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations
  1313. 6.59 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
  1314. 6.60 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20251218171726_add_pins.sql (12.41ms)
  1315. 6.60 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20260628120000_add_object_size_and_stats.sql (12.58ms)
  1316. 6.60 s [niks3-go-unit-tests] 2026/07/19 10:23:58 goose: successfully migrated database to version: 20260628120000
  1317. 6.60 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 1_commit_pending_closure.sql (5.59ms)
  1318. 6.61 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20260628120000_add_object_size_and_stats.sql (11.9ms)
  1319. 6.61 s [niks3-go-unit-tests] 2026/07/19 10:23:58 goose: successfully migrated database to version: 20260628120000
  1320. 6.61 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 2_object_stats_trigger.sql (12.7ms)
  1321. 6.62 s [niks3-go-unit-tests] 2026/07/19 10:23:58 goose: up to current file version: 2
  1322. 6.62 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"
  1323. 6.62 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN mTLS auth: bound subjects configured but subject DN unavailable
  1324. 6.62 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"
  1325. 6.62 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.65s)
  1326. 6.62 s [niks3-go-unit-tests] === CONT TestReadProxyNarinfo
  1327. 6.62 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 1_commit_pending_closure.sql (10.34ms)
  1328. 6.62 s [niks3-go-unit-tests] === NAME TestClientCADerivations
  1329. 6.62 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
  1330. 6.62 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
  1331. 6.62 s [niks3-go-unit-tests] error: binary cache 's3://bucket31?endpoint=http://localhost:46043&region=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations326000143/001/store'
  1332. 6.62 s [niks3-go-unit-tests] client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 1
  1333. 6.62 s [niks3-go-unit-tests] --- PASS: TestClientCADerivations (1.08s)
  1334. 6.62 s [niks3-go-unit-tests] === CONT TestIsValidCachePath
  1335. 6.62 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/narinfo
  1336. 6.62 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/narinfo
  1337. 6.62 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/narinfo_all_nix_base32_chars
  1338. 6.62 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars
  1339. 6.62 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/nar_zst
  1340. 6.62 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/nar_zst
  1341. 6.62 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/nar_xz
  1342. 6.62 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/nar_xz
  1343. 6.62 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/nar_bz2
  1344. 6.62 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/nar_bz2
  1345. 6.62 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/nar_uncompressed
  1346. 6.62 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/nar_uncompressed
  1347. 6.62 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/ls
  1348. 6.62 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/ls
  1349. 6.62 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/log
  1350. 6.62 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/log
  1351. 6.62 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/realisation
  1352. 6.62 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/realisation
  1353. 6.62 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/nix-cache-info
  1354. 6.62 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/nix-cache-info
  1355. 6.62 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/index.html
  1356. 6.62 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/index.html
  1357. 6.62 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/traversal_parent
  1358. 6.62 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/traversal_parent
  1359. 6.62 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/traversal_in_middle
  1360. 6.62 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/traversal_in_middle
  1361. 6.62 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/invalid_char_e
  1362. 6.62 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/invalid_char_e
  1363. 6.62 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/invalid_char_u
  1364. 6.62 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/invalid_char_u
  1365. 6.62 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/random_path
  1366. 6.62 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/random_path
  1367. 6.62 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/empty
  1368. 6.62 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/empty
  1369. 6.62 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/leading_slash
  1370. 6.62 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/leading_slash
  1371. 6.62 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/wrong_extension
  1372. 6.62 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/wrong_extension
  1373. 6.62 s [niks3-go-unit-tests] === RUN TestIsValidCachePath/short_hash
  1374. 6.62 s [niks3-go-unit-tests] === PAUSE TestIsValidCachePath/short_hash
  1375. 6.62 s [niks3-go-unit-tests] === CONT TestOrphanedObjectsGCStressTest
  1376. 6.63 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 2_object_stats_trigger.sql (7.65ms)
  1377. 6.63 s [niks3-go-unit-tests] 2026/07/19 10:23:58 goose: up to current file version: 2
  1378. 6.63 s [niks3-go-unit-tests] 2026-07-19 10:23:58.114 UTC [854] ERROR: relation "goose_db_version" does not exist at character 36
  1379. 6.63 s [niks3-go-unit-tests] 2026-07-19 10:23:58.114 UTC [854] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1380. 6.63 s [niks3-go-unit-tests] 2026-07-19 10:23:58.114 UTC [855] ERROR: relation "goose_db_version" does not exist at character 36
  1381. 6.63 s [niks3-go-unit-tests] 2026-07-19 10:23:58.114 UTC [855] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1382. 6.63 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN mTLS auth: subject not in bound subjects subject="CN=writer"
  1383. 6.63 s [niks3-go-unit-tests] --- PASS: TestService_ReadAuthMiddleware (0.64s)
  1384. 6.63 s [niks3-go-unit-tests] === CONT TestResurrectedObjectNotDeleted
  1385. 6.64 s [niks3-go-unit-tests] === NAME TestClientMultipleUploads
  1386. 6.64 s [niks3-go-unit-tests] client_integration_test.go:338: Created store path 0: /build/TestClientMultipleUploads1553654711/001/store/16n68js4sfz909x801l0baz2662qz3ri-test-file-0.txt
  1387. 6.65 s [niks3-go-unit-tests] === NAME TestClientIntegration
  1388. 6.65 s [niks3-go-unit-tests] client_integration_test.go:276: Created store path: /build/TestClientIntegration1988075681/002/store/n0zm6gf6arrgwxjkhpn92dk0vs9lshvb-test-file.txt
  1389. 6.65 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete
  1390. 6.68 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete
  1391. 6.72 s [niks3-go-unit-tests] === NAME TestClientMultipleUploads
  1392. 6.72 s [niks3-go-unit-tests] client_integration_test.go:338: Created store path 1: /build/TestClientMultipleUploads1553654711/001/store/yp1q1jgyi4458pf27sq24r0spzq5i754-test-file-1.txt
  1393. 6.73 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20241026095416_initial_model.sql (71.72ms)
  1394. 6.73 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20241026095416_initial_model.sql (72.14ms)
  1395. 6.73 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ODZhYzg4MjctMjQ3OS00MGNhLThhNTAtYjkyNjMxOTk4MjE3LjAyMjJiYWIwLWU3YmQtNDU3Yi1iN2I0LWQwYzhkNzZmMzQ2Y3gxNzg0NDU2NjM3OTY1MjE3ODQ4 parts=12
  1396. 6.73 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received uploads request method=POST path=/api/pending_closures
  1397. 6.74 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20251210153512_drop_unused_gin_index.sql (11.4ms)
  1398. 6.74 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20251210153512_drop_unused_gin_index.sql (11.68ms)
  1399. 6.75 s [niks3-go-unit-tests] --- PASS: TestCompletedNarNotReofferedAcrossClosures (0.94s)
  1400. 6.75 s [niks3-go-unit-tests] === CONT TestOrphanedObjectsGC
  1401. 6.75 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20251218171726_add_pins.sql (12.34ms)
  1402. 6.75 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ODZhYzg4MjctMjQ3OS00MGNhLThhNTAtYjkyNjMxOTk4MjE3LmE3Y2Q1MTllLWE4N2EtNDEzOS1hZTVlLTI1ZTg1ZDJiZDhkMHgxNzg0NDU2NjM3OTY1MTc5NTU4 parts=12
  1403. 6.75 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20251218171726_add_pins.sql (12.35ms)
  1404. 6.75 s [niks3-go-unit-tests] --- PASS: TestRedundantMultipartUpload (0.94s)
  1405. 6.75 s [niks3-go-unit-tests] === CONT TestServerTLSConfig/no_client_CA
  1406. 6.75 s [niks3-go-unit-tests] === CONT TestServerTLSConfig/not_a_PEM_file
  1407. 6.75 s [niks3-go-unit-tests] === CONT TestServerTLSConfig/missing_CA_file
  1408. 6.75 s [niks3-go-unit-tests] --- PASS: TestServerTLSConfig (0.00s)
  1409. 6.75 s [niks3-go-unit-tests] --- PASS: TestServerTLSConfig/no_client_CA (0.00s)
  1410. 6.75 s [niks3-go-unit-tests] --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)
  1411. 6.75 s [niks3-go-unit-tests] --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)
  1412. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/narinfo
  1413. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/realisation_plus_in_output
  1414. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/unknown_type
  1415. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/empty_key
  1416. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/absolute
  1417. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/traversal_nar
  1418. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/traversal
  1419. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/listing_key,_narinfo_type
  1420. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/nar_key,_narinfo_type
  1421. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/narinfo_key,_nar_type
  1422. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/index.html
  1423. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/nix-cache-info
  1424. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/build_log_home-manager_file
  1425. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/realisation
  1426. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/build_log_equals
  1427. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/build_log_question_mark
  1428. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/build_log_plus_in_name
  1429. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/nar_plain
  1430. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/build_log
  1431. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/listing
  1432. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/nar_xz
  1433. 6.75 s [niks3-go-unit-tests] === CONT TestIsValidUploadKey/nar_zst
  1434. 6.75 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey (0.00s)
  1435. 6.75 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/narinfo (0.00s)
  1436. 6.75 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)
  1437. 6.75 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/unknown_type (0.00s)
  1438. 6.75 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/empty_key (0.00s)
  1439. 6.75 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/absolute (0.00s)
  1440. 6.75 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)
  1441. 6.75 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/traversal (0.00s)
  1442. 6.75 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)
  1443. 6.76 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)
  1444. 6.76 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)
  1445. 6.76 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/index.html (0.00s)
  1446. 6.76 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)
  1447. 6.76 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)
  1448. 6.76 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/realisation (0.00s)
  1449. 6.76 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)
  1450. 6.76 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)
  1451. 6.76 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)
  1452. 6.76 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/nar_plain (0.00s)
  1453. 6.76 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/build_log (0.00s)
  1454. 6.76 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/listing (0.00s)
  1455. 6.76 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/nar_xz (0.00s)
  1456. 6.76 s [niks3-go-unit-tests] --- PASS: TestIsValidUploadKey/nar_zst (0.00s)
  1457. 6.76 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectOversizedBody/create_pending_closure
  1458. 6.76 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received uploads request method=POST path=/
  1459. 6.76 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20260628120000_add_object_size_and_stats.sql (6.23ms)
  1460. 6.76 s [niks3-go-unit-tests] 2026/07/19 10:23:58 goose: successfully migrated database to version: 20260628120000
  1461. 6.76 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20260628120000_add_object_size_and_stats.sql (12.43ms)
  1462. 6.76 s [niks3-go-unit-tests] 2026/07/19 10:23:58 goose: successfully migrated database to version: 20260628120000
  1463. 6.77 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 1_commit_pending_closure.sql (12.62ms)
  1464. 6.78 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 1_commit_pending_closure.sql (12.97ms)
  1465. 6.78 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 2_object_stats_trigger.sql (12.67ms)
  1466. 6.78 s [niks3-go-unit-tests] 2026/07/19 10:23:58 goose: up to current file version: 2
  1467. 6.79 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 2_object_stats_trigger.sql (12.22ms)
  1468. 6.79 s [niks3-go-unit-tests] 2026/07/19 10:23:58 goose: up to current file version: 2
  1469. 6.79 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.52s)
  1470. 6.79 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectOversizedBody/request_more_parts
  1471. 6.79 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received request for more parts method=POST path=/
  1472. 6.79 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received uploads request method=POST path=/api/pending_closures
  1473. 6.80 s [niks3-go-unit-tests] === NAME TestClientMultipleUploads
  1474. 6.80 s [niks3-go-unit-tests] client_integration_test.go:338: Created store path 2: /build/TestClientMultipleUploads1553654711/001/store/d0m6jrdhj4mzamal23wj5bv5n4az9qrg-test-file-2.txt
  1475. 6.80 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)
  1476. 6.80 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Uploading n0zm6gf6arrgwxjkhpn92dk0vs9lshvb-test-file.txt (152B)
  1477. 6.80 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"
  1478. 6.80 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Failed to register uploaded object key=n0zm6gf6arrgwxjkhpn92dk0vs9lshvb.ls error="server returned 404: 404 page not found\n"
  1479. 6.81 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign
  1480. 6.81 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Signed narinfos id=1 count=1
  1481. 6.81 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Uploading 1 narinfos
  1482. 6.81 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Failed to register uploaded object key=n0zm6gf6arrgwxjkhpn92dk0vs9lshvb.narinfo error="server returned 404: 404 page not found\n"
  1483. 6.81 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1484. 6.81 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Completed upload id=1
  1485. 6.81 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Upload complete. (141ms)
  1486. 6.81 s [niks3-go-unit-tests] === NAME TestClientIntegration
  1487. 6.81 s [niks3-go-unit-tests] client_integration_test.go:292: Retrieved narinfo from S3:
  1488. 6.81 s [niks3-go-unit-tests] StorePath: /build/TestClientIntegration1988075681/002/store/n0zm6gf6arrgwxjkhpn92dk0vs9lshvb-test-file.txt
  1489. 6.81 s [niks3-go-unit-tests] URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst
  1490. 6.81 s [niks3-go-unit-tests] Compression: zstd
  1491. 6.81 s [niks3-go-unit-tests] NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1
  1492. 6.81 s [niks3-go-unit-tests] NarSize: 152
  1493. 6.81 s [niks3-go-unit-tests] References:
  1494. 6.81 s [niks3-go-unit-tests] CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1
  1495. 6.81 s [niks3-go-unit-tests] client_integration_test.go:293: Retrieved .ls file from S3 (compressed size: 77 bytes)
  1496. 6.81 s [niks3-go-unit-tests] client_integration_test.go:293: Decompressed .ls content (64 bytes):
  1497. 6.81 s [niks3-go-unit-tests] {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}
  1498. 6.81 s [niks3-go-unit-tests] client_integration_test.go:296: Testing garbage collection...
  1499. 6.83 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectOversizedBody/complete_multipart
  1500. 6.83 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received complete multipart upload request method=POST path=/
  1501. 6.84 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Starting cleanup of old closures method=DELETE path=/api/closures
  1502. 6.84 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Garbage collection started
  1503. 6.86 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Aborted multipart uploads count=0
  1504. 6.86 s [niks3-go-unit-tests] 2026-07-19 10:23:58.346 UTC [951] ERROR: relation "goose_db_version" does not exist at character 36
  1505. 6.86 s [niks3-go-unit-tests] 2026-07-19 10:23:58.346 UTC [951] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1506. 6.86 s [niks3-go-unit-tests] === CONT TestProxyWriteTimeout/narinfo
  1507. 6.87 s [niks3-go-unit-tests] === CONT TestProxyWriteTimeout/10_GiB_nar
  1508. 6.87 s [niks3-go-unit-tests] === CONT TestProxyWriteTimeout/unknown_size
  1509. 6.87 s [niks3-go-unit-tests] === CONT TestProxyWriteTimeout/1_GiB_nar
  1510. 6.87 s [niks3-go-unit-tests] --- PASS: TestProxyWriteTimeout (0.00s)
  1511. 6.87 s [niks3-go-unit-tests] --- PASS: TestProxyWriteTimeout/narinfo (0.00s)
  1512. 6.87 s [niks3-go-unit-tests] --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)
  1513. 6.87 s [niks3-go-unit-tests] --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)
  1514. 6.87 s [niks3-go-unit-tests] --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)
  1515. 6.87 s [niks3-go-unit-tests] === CONT TestCacheConfigHandler/full_config,_no_issuer
  1516. 6.87 s [niks3-go-unit-tests] === CONT TestCacheConfigHandler/no_signing_keys
  1517. 6.87 s [niks3-go-unit-tests] === CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator
  1518. 6.87 s [niks3-go-unit-tests] === CONT TestCacheConfigHandler/no_cache_url_configured
  1519. 6.87 s [niks3-go-unit-tests] --- PASS: TestCacheConfigHandler (0.00s)
  1520. 6.87 s [niks3-go-unit-tests] --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)
  1521. 6.87 s [niks3-go-unit-tests] --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)
  1522. 6.87 s [niks3-go-unit-tests] --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)
  1523. 6.87 s [niks3-go-unit-tests] --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)
  1524. 6.87 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info
  1525. 6.87 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received uploads request method=POST path=/
  1526. 6.87 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key
  1527. 6.87 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received complete multipart upload request method=POST path=/
  1528. 6.87 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key
  1529. 6.87 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received request for more parts method=POST path=/
  1530. 6.87 s [niks3-go-unit-tests] === CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal
  1531. 6.87 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received uploads request method=POST path=/
  1532. 6.87 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)
  1533. 6.87 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)
  1534. 6.87 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)
  1535. 6.87 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)
  1536. 6.87 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)
  1537. 6.87 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token
  1538. 6.87 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO OIDC auth successful provider=test
  1539. 6.87 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected
  1540. 6.87 s [niks3-go-unit-tests] 2026/07/19 10:23:58 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]
  1541. 6.87 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured
  1542. 6.87 s [niks3-go-unit-tests] === CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected
  1543. 6.87 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Authentication failed token_preview=eyJhbGciOi...mA7G5otmdg 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]
  1544. 6.87 s [niks3-go-unit-tests] === CONT TestParseSingleRange/none
  1545. 6.87 s [niks3-go-unit-tests] === CONT TestParseSingleRange/open-ended
  1546. 6.87 s [niks3-go-unit-tests] === CONT TestParseSingleRange/start_far_past_EOF
  1547. 6.87 s [niks3-go-unit-tests] === CONT TestParseSingleRange/start_past_EOF
  1548. 6.87 s [niks3-go-unit-tests] === CONT TestParseSingleRange/single_byte
  1549. 6.87 s [niks3-go-unit-tests] === CONT TestParseSingleRange/suffix_exceeds_size
  1550. 6.87 s [niks3-go-unit-tests] === CONT TestParseSingleRange/suffix
  1551. 6.87 s [niks3-go-unit-tests] === CONT TestParseSingleRange/end_clamped_to_size
  1552. 6.87 s [niks3-go-unit-tests] === CONT TestParseSingleRange/malformed_both_empty
  1553. 6.87 s [niks3-go-unit-tests] === CONT TestParseSingleRange/closed
  1554. 6.87 s [niks3-go-unit-tests] === CONT TestParseSingleRange/malformed_end_before_start
  1555. 6.87 s [niks3-go-unit-tests] === CONT TestParseSingleRange/multi-range_ignored
  1556. 6.87 s [niks3-go-unit-tests] === CONT TestParseSingleRange/malformed_no_dash
  1557. 6.87 s [niks3-go-unit-tests] === CONT TestParseSingleRange/unknown_unit
  1558. 6.87 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange (0.00s)
  1559. 6.87 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/none (0.00s)
  1560. 6.87 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/open-ended (0.00s)
  1561. 6.87 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)
  1562. 6.87 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/start_past_EOF (0.00s)
  1563. 6.87 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/single_byte (0.00s)
  1564. 6.87 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)
  1565. 6.87 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/suffix (0.00s)
  1566. 6.87 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)
  1567. 6.87 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)
  1568. 6.87 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/closed (0.00s)
  1569. 6.87 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)
  1570. 6.87 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)
  1571. 6.87 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)
  1572. 6.87 s [niks3-go-unit-tests] --- PASS: TestParseSingleRange/unknown_unit (0.00s)
  1573. 6.87 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/narinfo
  1574. 6.87 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/index.html
  1575. 6.87 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/short_hash
  1576. 6.87 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/wrong_extension
  1577. 6.87 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/leading_slash
  1578. 6.87 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/empty
  1579. 6.87 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/random_path
  1580. 6.87 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/invalid_char_u
  1581. 6.87 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/invalid_char_e
  1582. 6.87 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/traversal_in_middle
  1583. 6.87 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/traversal_parent
  1584. 6.87 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/nar_uncompressed
  1585. 6.87 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_OIDC (0.62s)
  1586. 6.87 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)
  1587. 6.87 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)
  1588. 6.87 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)
  1589. 6.87 s [niks3-go-unit-tests] --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)
  1590. 6.87 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/nix-cache-info
  1591. 6.87 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/realisation
  1592. 6.87 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/log
  1593. 6.87 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/ls
  1594. 6.87 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/nar_xz
  1595. 6.87 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/nar_bz2
  1596. 6.87 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/narinfo_all_nix_base32_chars
  1597. 6.87 s [niks3-go-unit-tests] === CONT TestIsValidCachePath/nar_zst
  1598. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath (0.00s)
  1599. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/narinfo (0.00s)
  1600. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/index.html (0.00s)
  1601. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/short_hash (0.00s)
  1602. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/wrong_extension (0.00s)
  1603. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/leading_slash (0.00s)
  1604. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/empty (0.00s)
  1605. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/random_path (0.00s)
  1606. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)
  1607. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)
  1608. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)
  1609. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/traversal_parent (0.00s)
  1610. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)
  1611. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)
  1612. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/realisation (0.00s)
  1613. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/log (0.00s)
  1614. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/ls (0.00s)
  1615. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/nar_xz (0.00s)
  1616. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)
  1617. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)
  1618. 6.87 s [niks3-go-unit-tests] --- PASS: TestIsValidCachePath/nar_zst (0.00s)
  1619. 6.87 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Force mode enabled - objects will be deleted immediately without grace period
  1620. 6.87 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2715 objects-failed-to-delete=0
  1621. 6.90 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20241026095416_initial_model.sql (21.77ms)
  1622. 6.90 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20241026095416_initial_model.sql (43.82ms)
  1623. 6.91 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Vacuumed table table=pending_closures
  1624. 6.92 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20251210153512_drop_unused_gin_index.sql (13.5ms)
  1625. 6.92 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20251210153512_drop_unused_gin_index.sql (13.54ms)
  1626. 6.94 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Vacuumed table table=pending_objects
  1627. 6.94 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Vacuumed table table=multipart_uploads
  1628. 6.94 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20251218171726_add_pins.sql (27.68ms)
  1629. 6.94 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20251218171726_add_pins.sql (27.66ms)
  1630. 6.95 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=742.380147ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures
  1631. 6.95 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Vacuumed table table=closures
  1632. 6.96 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20260628120000_add_object_size_and_stats.sql (12.65ms)
  1633. 6.96 s [niks3-go-unit-tests] 2026/07/19 10:23:58 goose: successfully migrated database to version: 20260628120000
  1634. 6.96 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20260628120000_add_object_size_and_stats.sql (12.63ms)
  1635. 6.96 s [niks3-go-unit-tests] 2026/07/19 10:23:58 goose: successfully migrated database to version: 20260628120000
  1636. 6.96 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Vacuumed table table=objects
  1637. 6.97 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received uploads request method=POST path=/api/pending_closures
  1638. 6.97 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 1_commit_pending_closure.sql (12.32ms)
  1639. 6.97 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 1_commit_pending_closure.sql (12.28ms)
  1640. 6.97 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 2_object_stats_trigger.sql (6.08ms)
  1641. 6.97 s [niks3-go-unit-tests] 2026/07/19 10:23:58 goose: up to current file version: 2
  1642. 6.98 s [niks3-go-unit-tests] --- PASS: TestReadProxyDisabled (2.91s)
  1643. 6.98 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 2_object_stats_trigger.sql (12.39ms)
  1644. 6.98 s [niks3-go-unit-tests] 2026/07/19 10:23:58 goose: up to current file version: 2
  1645. 6.98 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received uploads request method=POST path=/api/pending_closures
  1646. 6.98 s [niks3-go-unit-tests] --- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.46s)
  1647. 6.99 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received uploads request method=POST path=/api/pending_closures
  1648. 6.99 s [niks3-go-unit-tests] 2026-07-19 10:23:58.477 UTC [1054] ERROR: relation "goose_db_version" does not exist at character 36
  1649. 6.99 s [niks3-go-unit-tests] 2026-07-19 10:23:58.477 UTC [1054] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1650. 6.99 s [niks3-go-unit-tests] 2026-07-19 10:23:58.477 UTC [1055] ERROR: relation "goose_db_version" does not exist at character 36
  1651. 6.99 s [niks3-go-unit-tests] 2026-07-19 10:23:58.477 UTC [1055] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1652. 6.99 s [niks3-go-unit-tests] 2026-07-19 10:23:58.477 UTC [1056] ERROR: relation "goose_db_version" does not exist at character 36
  1653. 6.99 s [niks3-go-unit-tests] 2026-07-19 10:23:58.477 UTC [1056] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1654. 6.99 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)
  1655. 6.99 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Uploading yp1q1jgyi4458pf27sq24r0spzq5i754-test-file-1.txt (160B)
  1656. 6.99 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Uploading d0m6jrdhj4mzamal23wj5bv5n4az9qrg-test-file-2.txt (160B)
  1657. 6.99 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Uploading 16n68js4sfz909x801l0baz2662qz3ri-test-file-0.txt (160B)
  1658. 6.99 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"
  1659. 6.99 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"
  1660. 6.99 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"
  1661. 6.99 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Failed to register uploaded object key=d0m6jrdhj4mzamal23wj5bv5n4az9qrg.ls error="server returned 404: 404 page not found\n"
  1662. 7.00 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Failed to register uploaded object key=16n68js4sfz909x801l0baz2662qz3ri.ls error="server returned 404: 404 page not found\n"
  1663. 7.00 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Failed to register uploaded object key=yp1q1jgyi4458pf27sq24r0spzq5i754.ls error="server returned 404: 404 page not found\n"
  1664. 7.00 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign
  1665. 7.00 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Signed narinfos id=1 count=1
  1666. 7.00 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign
  1667. 7.00 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Signed narinfos id=2 count=1
  1668. 7.00 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign
  1669. 7.00 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Signed narinfos id=3 count=1
  1670. 7.00 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Uploading 3 narinfos
  1671. 7.00 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Failed to register uploaded object key=d0m6jrdhj4mzamal23wj5bv5n4az9qrg.narinfo error="server returned 404: 404 page not found\n"
  1672. 7.00 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Failed to register uploaded object key=16n68js4sfz909x801l0baz2662qz3ri.narinfo error="server returned 404: 404 page not found\n"
  1673. 7.00 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Failed to register uploaded object key=yp1q1jgyi4458pf27sq24r0spzq5i754.narinfo error="server returned 404: 404 page not found\n"
  1674. 7.00 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete
  1675. 7.06 s [niks3-go-unit-tests] 2026/07/19 10:23:58 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"
  1676. 7.06 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Completed upload id=1
  1677. 7.06 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete
  1678. 7.07 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20241026095416_initial_model.sql (59.41ms)
  1679. 7.07 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20241026095416_initial_model.sql (66.04ms)
  1680. 7.07 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20241026095416_initial_model.sql (59.33ms)
  1681. 7.07 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Completed upload id=2
  1682. 7.07 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete
  1683. 7.07 s [niks3-go-unit-tests] 2026-07-19 10:23:58.559 UTC [1103] ERROR: relation "goose_db_version" does not exist at character 36
  1684. 7.07 s [niks3-go-unit-tests] 2026-07-19 10:23:58.559 UTC [1103] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC
  1685. 7.07 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20251210153512_drop_unused_gin_index.sql (7.22ms)
  1686. 7.07 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20251210153512_drop_unused_gin_index.sql (7.29ms)
  1687. 7.07 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20251210153512_drop_unused_gin_index.sql (7.43ms)
  1688. 7.08 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Completed upload id=3
  1689. 7.08 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Upload complete. (253ms)
  1690. 7.08 s [niks3-go-unit-tests] === NAME TestClientMultipleUploads
  1691. 7.08 s [niks3-go-unit-tests] client_integration_test.go:349: Uploaded 3 paths in 276.587102ms
  1692. 7.08 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20251218171726_add_pins.sql (6.9ms)
  1693. 7.08 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20251218171726_add_pins.sql (6.86ms)
  1694. 7.08 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20251218171726_add_pins.sql (6.83ms)
  1695. 7.09 s [niks3-go-unit-tests] --- PASS: TestClientMultipleUploads (1.27s)
  1696. 7.09 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20260628120000_add_object_size_and_stats.sql (7.75ms)
  1697. 7.09 s [niks3-go-unit-tests] 2026/07/19 10:23:58 goose: successfully migrated database to version: 20260628120000
  1698. 7.09 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20241026095416_initial_model.sql (10.97ms)
  1699. 7.09 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20260628120000_add_object_size_and_stats.sql (11.3ms)
  1700. 7.09 s [niks3-go-unit-tests] 2026/07/19 10:23:58 goose: successfully migrated database to version: 20260628120000
  1701. 7.09 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20260628120000_add_object_size_and_stats.sql (11.38ms)
  1702. 7.09 s [niks3-go-unit-tests] 2026/07/19 10:23:58 goose: successfully migrated database to version: 20260628120000
  1703. 7.10 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 1_commit_pending_closure.sql (7.11ms)
  1704. 7.10 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 1_commit_pending_closure.sql (7.12ms)
  1705. 7.10 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 1_commit_pending_closure.sql (7.15ms)
  1706. 7.10 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20251210153512_drop_unused_gin_index.sql (7.47ms)
  1707. 7.10 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 2_object_stats_trigger.sql (7.03ms)
  1708. 7.10 s [niks3-go-unit-tests] 2026/07/19 10:23:58 goose: up to current file version: 2
  1709. 7.11 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 2_object_stats_trigger.sql (6.97ms)
  1710. 7.11 s [niks3-go-unit-tests] 2026/07/19 10:23:58 goose: up to current file version: 2
  1711. 7.11 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20251218171726_add_pins.sql (6.76ms)
  1712. 7.11 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 2_object_stats_trigger.sql (7.08ms)
  1713. 7.11 s [niks3-go-unit-tests] 2026/07/19 10:23:58 goose: up to current file version: 2
  1714. 7.11 s [niks3-go-unit-tests] --- PASS: TestReadProxyNarinfo (0.49s)
  1715. 7.12 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 20260628120000_add_object_size_and_stats.sql (10.18ms)
  1716. 7.12 s [niks3-go-unit-tests] 2026/07/19 10:23:58 goose: successfully migrated database to version: 20260628120000
  1717. 7.12 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 1_commit_pending_closure.sql (6.99ms)
  1718. 7.13 s [niks3-go-unit-tests] 2026/07/19 10:23:58 OK 2_object_stats_trigger.sql (4.28ms)
  1719. 7.13 s [niks3-go-unit-tests] 2026/07/19 10:23:58 goose: up to current file version: 2
  1720. 7.16 s [niks3-go-unit-tests] --- PASS: TestResurrectedObjectNotDeleted (0.53s)
  1721. 7.25 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2127 objects-failed-to-delete=0
  1722. 7.26 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Vacuumed table table=pending_closures
  1723. 7.27 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Vacuumed table table=pending_objects
  1724. 7.27 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Vacuumed table table=multipart_uploads
  1725. 7.28 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Vacuumed table table=closures
  1726. 7.29 s [niks3-go-unit-tests] 2026/07/19 10:23:58 INFO Vacuumed table table=objects
  1727. 7.38 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectOversizedBody (0.13s)
  1728. 7.38 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)
  1729. 7.38 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)
  1730. 7.38 s [niks3-go-unit-tests] --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.63s)
  1731. 7.43 s [niks3-go-unit-tests] === NAME TestOrphanedObjectsGC
  1732. 7.43 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:290: GC Test Summary:
  1733. 7.43 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A
  1734. 7.43 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B
  1735. 7.43 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)
  1736. 7.43 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)
  1737. 7.43 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:295: - Total deleted: 10 objects
  1738. 7.43 s [niks3-go-unit-tests] --- PASS: TestOrphanedObjectsGC (0.69s)
  1739. 7.69 s [niks3-go-unit-tests] 2026/07/19 10:23:59 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.682761342s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures
  1740. 8.35 s [niks3-go-unit-tests] 2026/07/19 10:23:59 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2715 objects_failed=0
  1741. 8.35 s [niks3-go-unit-tests] === NAME TestPinProtectsFromGC
  1742. 8.35 s [niks3-go-unit-tests] client_integration_test.go:709: Pin successfully protected closure from garbage collection
  1743. 8.35 s [niks3-go-unit-tests] --- PASS: TestPinProtectsFromGC (3.49s)
  1744. 8.45 s [niks3-go-unit-tests] === NAME TestOrphanedObjectsGCStressTest
  1745. 8.45 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains
  1746. 8.47 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:446: Marked 210 objects for deletion
  1747. 8.55 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:509: Stress test completed successfully:
  1748. 8.56 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:510: - Active objects preserved: 20
  1749. 8.56 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:511: - Objects deleted: 210
  1750. 8.56 s [niks3-go-unit-tests] orphaned_objects_gc_test.go:512: - Total GC'd: 210
  1751. 8.56 s [niks3-go-unit-tests] --- PASS: TestOrphanedObjectsGCStressTest (1.93s)
  1752. 8.84 s [niks3-go-unit-tests] 2026/07/19 10:24:00 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2127 objects_failed=0
  1753. 8.84 s [niks3-go-unit-tests] === NAME TestClientIntegration
  1754. 8.84 s [niks3-go-unit-tests] client_integration_test.go:303: Objects in database after GC:
  1755. 8.84 s [niks3-go-unit-tests] client_integration_test.go:303: Successfully deleted all objects with GC --force
  1756. 8.84 s [niks3-go-unit-tests] --- PASS: TestClientIntegration (2.99s)
  1757. 9.38 s [niks3-go-unit-tests] --- PASS: TestClientErrorHandling (0.00s)
  1758. 9.38 s [niks3-go-unit-tests] --- PASS: TestClientErrorHandling/InvalidStorePath (0.91s)
  1759. 9.38 s [niks3-go-unit-tests] --- PASS: TestClientErrorHandling/InvalidAuthToken (0.74s)
  1760. 9.38 s [niks3-go-unit-tests] --- PASS: TestClientErrorHandling/ServerNotAvailable (3.43s)
  1761. 9.52 s [niks3-go-unit-tests] 2026/07/19 10:24:01 WARN Rate limiter enabled after throttle name=s3-test rate=5
  1762. 9.52 s [niks3-go-unit-tests] 2026/07/19 10:24:01 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."
  1763. 9.52 s [niks3-go-unit-tests] === NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle
  1764. 9.52 s [niks3-go-unit-tests] throttle_test.go:213: Proxy stats: total=15, throttled=10, completeMultipart=10
  1765. 9.52 s [niks3-go-unit-tests] throttle_test.go:215: Rate limiter: enabled=true, rate=5.00
  1766. 9.52 s [niks3-go-unit-tests] --- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.22s)
  1767. 9.52 s [niks3-go-unit-tests] PASS
  1768. 10.02 s [niks3-go-unit-tests] {"timestamp":"2026-07-19T10:24:01.510303623Z","level":"ERROR","fields":{"message":"Unknown connection IO error:Cancelled","peer_addr":"127.0.0.1:51578"},"target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":973,"threadName":"rustfs-worker","threadId":"ThreadId(29)"}
  1769. 10.07 s [niks3-go-unit-tests] 2026-07-19 10:24:01.555 UTC [96] LOG: received smart shutdown request
  1770. 10.12 s [niks3-go-unit-tests] 2026-07-19 10:24:01.603 UTC [96] LOG: background worker "logical replication launcher" (PID 106) exited with exit code 1
  1771. 10.12 s [niks3-go-unit-tests] 2026-07-19 10:24:01.607 UTC [101] LOG: shutting down
  1772. 10.13 s [niks3-go-unit-tests] 2026-07-19 10:24:01.616 UTC [101] LOG: checkpoint starting: shutdown immediate
  1773. 19.53 s [niks3-go-unit-tests] 2026/07/19 10:24:11 ERROR failed to kill rustfs error="no such process"
  1774. 20.07 s [niks3-go-unit-tests] 2026/07/19 10:24:11 INFO killed rustfs
  1775. 20.07 s [niks3-go-unit-tests] 2026/07/19 10:24:11 ERROR failed to wait for rustfs error="signal: killed"
  1776. 20.12 s [niks3-go-unit-tests] 2026-07-19 10:24:11.611 UTC [101] PANIC: could not fsync file "base/17806/3466": No such file or directory
  1777. 20.43 s [niks3-go-unit-tests] Running OIDC tests...
  1778. 20.44 s [niks3-go-unit-tests] === RUN TestGlobMatch
  1779. 20.44 s [niks3-go-unit-tests] === PAUSE TestGlobMatch
  1780. 20.44 s [niks3-go-unit-tests] === RUN TestAudienceForIssuer
  1781. 20.44 s [niks3-go-unit-tests] === PAUSE TestAudienceForIssuer
  1782. 20.44 s [niks3-go-unit-tests] === RUN TestValidateToken_ValidToken
  1783. 20.44 s [niks3-go-unit-tests] === PAUSE TestValidateToken_ValidToken
  1784. 20.44 s [niks3-go-unit-tests] === RUN TestValidateToken_WrongAudience
  1785. 20.44 s [niks3-go-unit-tests] === PAUSE TestValidateToken_WrongAudience
  1786. 20.44 s [niks3-go-unit-tests] === RUN TestValidateToken_Expired
  1787. 20.44 s [niks3-go-unit-tests] === PAUSE TestValidateToken_Expired
  1788. 20.44 s [niks3-go-unit-tests] === RUN TestValidateToken_BoundClaimsMismatch
  1789. 20.44 s [niks3-go-unit-tests] === PAUSE TestValidateToken_BoundClaimsMismatch
  1790. 20.44 s [niks3-go-unit-tests] === RUN TestValidateToken_BoundSubjectMismatch
  1791. 20.44 s [niks3-go-unit-tests] === PAUSE TestValidateToken_BoundSubjectMismatch
  1792. 20.44 s [niks3-go-unit-tests] === RUN TestValidateToken_MultipleProviders
  1793. 20.44 s [niks3-go-unit-tests] === PAUSE TestValidateToken_MultipleProviders
  1794. 20.44 s [niks3-go-unit-tests] === RUN TestValidateToken_NoMatchingProvider
  1795. 20.44 s [niks3-go-unit-tests] === PAUSE TestValidateToken_NoMatchingProvider
  1796. 20.44 s [niks3-go-unit-tests] === CONT TestGlobMatch
  1797. 20.44 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo_foo
  1798. 20.44 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo_foo
  1799. 20.44 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo_bar
  1800. 20.44 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo_bar
  1801. 20.44 s [niks3-go-unit-tests] === RUN TestGlobMatch/*_
  1802. 20.44 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*_
  1803. 20.44 s [niks3-go-unit-tests] === RUN TestGlobMatch/*_anything
  1804. 20.44 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*_anything
  1805. 20.44 s [niks3-go-unit-tests] === CONT TestValidateToken_BoundClaimsMismatch
  1806. 20.56 s [niks3-go-unit-tests] === CONT TestValidateToken_MultipleProviders
  1807. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo*_foo
  1808. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo*_foo
  1809. 20.56 s [niks3-go-unit-tests] === CONT TestValidateToken_WrongAudience
  1810. 20.56 s [niks3-go-unit-tests] === CONT TestValidateToken_ValidToken
  1811. 20.56 s [niks3-go-unit-tests] === CONT TestValidateToken_Expired
  1812. 20.56 s [niks3-go-unit-tests] === CONT TestAudienceForIssuer
  1813. 20.56 s [niks3-go-unit-tests] --- PASS: TestAudienceForIssuer (0.00s)
  1814. 20.56 s [niks3-go-unit-tests] === CONT TestValidateToken_NoMatchingProvider
  1815. 20.56 s [niks3-go-unit-tests] === CONT TestValidateToken_BoundSubjectMismatch
  1816. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo*_foobar
  1817. 20.56 s [niks3-go-unit-tests] 2026/07/19 10:24:11 INFO OIDC provider initialized name=test
  1818. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo*_foobar
  1819. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo*_bar
  1820. 20.56 s [niks3-go-unit-tests] 2026/07/19 10:24:11 INFO OIDC provider initialized name=test
  1821. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo*_bar
  1822. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/*bar_bar
  1823. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*bar_bar
  1824. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/*bar_foobar
  1825. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*bar_foobar
  1826. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/*bar_foo
  1827. 20.56 s [niks3-go-unit-tests] 2026/07/19 10:24:11 INFO OIDC provider initialized name=test
  1828. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*bar_foo
  1829. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo*bar_foobar
  1830. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo*bar_foobar
  1831. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo*bar_foo123bar
  1832. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo*bar_foo123bar
  1833. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/foo*bar_foobarbaz
  1834. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/foo*bar_foobarbaz
  1835. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/*/*_foo/bar
  1836. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*/*_foo/bar
  1837. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/*/*_foo
  1838. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/*/*_foo
  1839. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/refs/heads/*_refs/heads/main
  1840. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/refs/heads/*_refs/heads/main
  1841. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/refs/heads/*_refs/tags/v1.0
  1842. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.0
  1843. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/refs/*/main_refs/heads/main
  1844. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/refs/*/main_refs/heads/main
  1845. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/fo?_foo
  1846. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/fo?_foo
  1847. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/fo?_fo
  1848. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/fo?_fo
  1849. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/fo?_fooo
  1850. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/fo?_fooo
  1851. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/?oo_foo
  1852. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/?oo_foo
  1853. 20.56 s [niks3-go-unit-tests] 2026/07/19 10:24:11 INFO OIDC provider initialized name=provider2
  1854. 20.56 s [niks3-go-unit-tests] 2026/07/19 10:24:11 INFO OIDC provider initialized name=test
  1855. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/?oo_boo
  1856. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/?oo_boo
  1857. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main
  1858. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main
  1859. 20.56 s [niks3-go-unit-tests] === RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main
  1860. 20.56 s [niks3-go-unit-tests] === PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main
  1861. 20.56 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo_foo
  1862. 20.56 s [niks3-go-unit-tests] === CONT TestGlobMatch/*/*_foo/bar
  1863. 20.56 s [niks3-go-unit-tests] === CONT TestGlobMatch/fo?_fooo
  1864. 20.56 s [niks3-go-unit-tests] === CONT TestGlobMatch/fo?_fo
  1865. 20.56 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo*bar_foobarbaz
  1866. 20.56 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo*bar_foo123bar
  1867. 20.56 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo*bar_foobar
  1868. 20.56 s [niks3-go-unit-tests] === CONT TestGlobMatch/*bar_foobar
  1869. 20.56 s [niks3-go-unit-tests] === CONT TestGlobMatch/fo?_foo
  1870. 20.56 s [niks3-go-unit-tests] === CONT TestGlobMatch/refs/*/main_refs/heads/main
  1871. 20.56 s [niks3-go-unit-tests] === CONT TestGlobMatch/refs/heads/*_refs/tags/v1.0
  1872. 20.56 s [niks3-go-unit-tests] === CONT TestGlobMatch/refs/heads/*_refs/heads/main
  1873. 20.85 s [niks3-go-unit-tests] === CONT TestGlobMatch/*/*_foo
  1874. 20.85 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo*_bar
  1875. 20.85 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo*_foobar
  1876. 20.85 s [niks3-go-unit-tests] === CONT TestGlobMatch/*bar_foo
  1877. 20.85 s [niks3-go-unit-tests] 2026/07/19 10:24:11 INFO OIDC provider initialized name=provider1
  1878. 20.85 s [niks3-go-unit-tests] === CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main
  1879. 20.85 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo*_foo
  1880. 20.85 s [niks3-go-unit-tests] === CONT TestGlobMatch/*_anything
  1881. 20.85 s [niks3-go-unit-tests] === CONT TestGlobMatch/?oo_boo
  1882. 20.85 s [niks3-go-unit-tests] 2026/07/19 10:24:11 INFO OIDC provider initialized name=test
  1883. 20.85 s [niks3-go-unit-tests] === CONT TestGlobMatch/?oo_foo
  1884. 20.85 s [niks3-go-unit-tests] === CONT TestGlobMatch/*bar_bar
  1885. 20.85 s [niks3-go-unit-tests] === CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main
  1886. 20.85 s [niks3-go-unit-tests] === CONT TestGlobMatch/*_
  1887. 20.85 s [niks3-go-unit-tests] === CONT TestGlobMatch/foo_bar
  1888. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch (0.00s)
  1889. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo_foo (0.00s)
  1890. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)
  1891. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/fo?_fooo (0.00s)
  1892. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/fo?_fo (0.00s)
  1893. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)
  1894. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)
  1895. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)
  1896. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*bar_foobar (0.00s)
  1897. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/fo?_foo (0.00s)
  1898. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)
  1899. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)
  1900. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)
  1901. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*/*_foo (0.00s)
  1902. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo*_bar (0.00s)
  1903. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo*_foobar (0.00s)
  1904. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*bar_foo (0.00s)
  1905. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)
  1906. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo*_foo (0.00s)
  1907. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*_anything (0.00s)
  1908. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/?oo_boo (0.00s)
  1909. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/?oo_foo (0.00s)
  1910. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*bar_bar (0.00s)
  1911. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)
  1912. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/*_ (0.00s)
  1913. 20.85 s [niks3-go-unit-tests] --- PASS: TestGlobMatch/foo_bar (0.00s)
  1914. 20.85 s [niks3-go-unit-tests] 2026/07/19 10:24:11 INFO OIDC provider initialized name=provider1
  1915. 20.85 s [niks3-go-unit-tests] --- PASS: TestValidateToken_WrongAudience (0.00s)
  1916. 20.85 s [niks3-go-unit-tests] --- PASS: TestValidateToken_ValidToken (0.00s)
  1917. 20.85 s [niks3-go-unit-tests] --- PASS: TestValidateToken_BoundClaimsMismatch (0.00s)
  1918. 20.85 s [niks3-go-unit-tests] --- PASS: TestValidateToken_Expired (0.00s)
  1919. 20.85 s [niks3-go-unit-tests] --- PASS: TestValidateToken_NoMatchingProvider (0.00s)
  1920. 20.85 s [niks3-go-unit-tests] --- PASS: TestValidateToken_BoundSubjectMismatch (0.00s)
  1921. 20.85 s [niks3-go-unit-tests] --- PASS: TestValidateToken_MultipleProviders (0.01s)
  1922. 20.85 s [niks3-go-unit-tests] PASS
  1923. 20.85 s [niks3-go-unit-tests] Running hook tests...
  1924. 20.85 s [niks3-go-unit-tests] === RUN TestSendPathsEmpty
  1925. 20.85 s [niks3-go-unit-tests] === PAUSE TestSendPathsEmpty
  1926. 20.85 s [niks3-go-unit-tests] === RUN TestQueueEnqueueAndFetch
  1927. 20.85 s [niks3-go-unit-tests] === PAUSE TestQueueEnqueueAndFetch
  1928. 20.85 s [niks3-go-unit-tests] === RUN TestQueueDeduplication
  1929. 20.85 s [niks3-go-unit-tests] === PAUSE TestQueueDeduplication
  1930. 20.85 s [niks3-go-unit-tests] === RUN TestQueueRemove
  1931. 20.85 s [niks3-go-unit-tests] === PAUSE TestQueueRemove
  1932. 20.85 s [niks3-go-unit-tests] === RUN TestQueueFetchBatchLimit
  1933. 20.85 s [niks3-go-unit-tests] === PAUSE TestQueueFetchBatchLimit
  1934. 20.85 s [niks3-go-unit-tests] === RUN TestQueueFetchRemoveLifecycle
  1935. 20.85 s [niks3-go-unit-tests] === PAUSE TestQueueFetchRemoveLifecycle
  1936. 20.85 s [niks3-go-unit-tests] === RUN TestQueueConcurrentWriters
  1937. 20.85 s [niks3-go-unit-tests] === PAUSE TestQueueConcurrentWriters
  1938. 20.85 s [niks3-go-unit-tests] === RUN TestServerClientIntegration
  1939. 20.85 s [niks3-go-unit-tests] === PAUSE TestServerClientIntegration
  1940. 20.85 s [niks3-go-unit-tests] === RUN TestServerQueueError
  1941. 20.85 s [niks3-go-unit-tests] === PAUSE TestServerQueueError
  1942. 20.85 s [niks3-go-unit-tests] === RUN TestGetListenerSocketActivation
  1943. 20.85 s [niks3-go-unit-tests] server_test.go:210: === RUN TestGetListenerSocketActivation
  1944. 20.85 s [niks3-go-unit-tests] --- PASS: TestGetListenerSocketActivation (0.00s)
  1945. 20.85 s [niks3-go-unit-tests] PASS
  1946. 20.85 s [niks3-go-unit-tests]
  1947. 20.85 s [niks3-go-unit-tests] --- PASS: TestGetListenerSocketActivation (0.00s)
  1948. 20.85 s [niks3-go-unit-tests] === RUN TestWorkerUploadsAndRemoves
  1949. 20.85 s [niks3-go-unit-tests] === PAUSE TestWorkerUploadsAndRemoves
  1950. 20.85 s [niks3-go-unit-tests] === RUN TestWorkerSkipsGCdPaths
  1951. 20.85 s [niks3-go-unit-tests] === PAUSE TestWorkerSkipsGCdPaths
  1952. 20.85 s [niks3-go-unit-tests] === RUN TestWorkerPrunesClosureDeps
  1953. 20.85 s [niks3-go-unit-tests] === PAUSE TestWorkerPrunesClosureDeps
  1954. 20.85 s [niks3-go-unit-tests] === CONT TestSendPathsEmpty
  1955. 20.85 s [niks3-go-unit-tests] --- PASS: TestSendPathsEmpty (0.00s)
  1956. 20.85 s [niks3-go-unit-tests] === CONT TestQueueFetchRemoveLifecycle
  1957. 20.85 s [niks3-go-unit-tests] === CONT TestQueueConcurrentWriters
  1958. 20.85 s [niks3-go-unit-tests] === CONT TestWorkerPrunesClosureDeps
  1959. 20.85 s [niks3-go-unit-tests] === CONT TestWorkerSkipsGCdPaths
  1960. 20.85 s [niks3-go-unit-tests] === CONT TestServerQueueError
  1961. 20.85 s [niks3-go-unit-tests] === CONT TestServerClientIntegration
  1962. 20.85 s [niks3-go-unit-tests] === CONT TestQueueDeduplication
  1963. 20.85 s [niks3-go-unit-tests] === CONT TestQueueEnqueueAndFetch
  1964. 20.86 s [niks3-go-unit-tests] 2026/07/19 10:24:11 ERROR Failed to queue paths error="permission denied" count=1
  1965. 20.86 s [niks3-go-unit-tests] === CONT TestQueueRemove
  1966. 20.86 s [niks3-go-unit-tests] --- PASS: TestServerQueueError (0.00s)
  1967. 20.86 s [niks3-go-unit-tests] === CONT TestQueueFetchBatchLimit
  1968. 20.86 s [niks3-go-unit-tests] === CONT TestWorkerUploadsAndRemoves
  1969. 20.86 s [niks3-go-unit-tests] --- PASS: TestServerClientIntegration (0.00s)
  1970. 20.86 s [niks3-go-unit-tests] 2026/07/19 10:24:12 INFO Upload queue status pending=2
  1971. 20.86 s [niks3-go-unit-tests] 2026/07/19 10:24:12 INFO Uploading batch count=2
  1972. 20.86 s [niks3-go-unit-tests] 2026/07/19 10:24:12 INFO Upload queue status pending=2
  1973. 20.86 s [niks3-go-unit-tests] 2026/07/19 10:24:12 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths408426355/002/nonexistent
  1974. 20.86 s [niks3-go-unit-tests] 2026/07/19 10:24:12 INFO Upload queue status pending=2
  1975. 20.86 s [niks3-go-unit-tests] 2026/07/19 10:24:12 INFO Uploading batch count=1
  1976. 20.86 s [niks3-go-unit-tests] --- PASS: TestQueueEnqueueAndFetch (0.19s)
  1977. 20.86 s [niks3-go-unit-tests] --- PASS: TestQueueFetchBatchLimit (0.19s)
  1978. 20.86 s [niks3-go-unit-tests] 2026/07/19 10:24:12 INFO Uploading batch count=1
  1979. 20.86 s [niks3-go-unit-tests] --- PASS: TestQueueRemove (0.22s)
  1980. 20.86 s [niks3-go-unit-tests] --- PASS: TestQueueDeduplication (0.25s)
  1981. 20.86 s [niks3-go-unit-tests] --- PASS: TestQueueFetchRemoveLifecycle (0.25s)
  1982. 20.86 s [niks3-go-unit-tests] --- PASS: TestWorkerUploadsAndRemoves (0.25s)
  1983. 20.86 s [niks3-go-unit-tests] --- PASS: TestWorkerPrunesClosureDeps (0.28s)
  1984. 20.86 s [niks3-go-unit-tests] --- PASS: TestWorkerSkipsGCdPaths (0.28s)
  1985. 24.15 s [niks3-go-unit-tests] --- PASS: TestQueueConcurrentWriters (3.70s)
  1986. 24.15 s [niks3-go-unit-tests] PASS
  1987. 24.20 s [niks3-go-unit-tests:post-build] Uploading to the NixCI staging cache: /nix/store/liggxz9whnrhf14k62xng28vn7lwg11j-niks3-go-unit-tests
  1988. 24.24 s [niks3-go-unit-tests:post-build] warning: 'warn-short-path-literals' is deprecated, use 'lint-short-path-literals = ignore' instead
  1989. 24.25 s [niks3-go-unit-tests:post-build] copying 1 paths...
  1990. 24.25 s [niks3-go-unit-tests:post-build] copying path '/nix/store/liggxz9whnrhf14k62xng28vn7lwg11j-niks3-go-unit-tests' to 'https://cache.staging.nix-ci.com'...
  1991. 24.51 s [niks3-go-unit-tests:post-build] warning: 'warn-short-path-literals' is deprecated, use 'lint-short-path-literals = ignore' instead
  1992. 24.75 s [niks3-go-unit-tests:post-build] copying 1 paths...
  1993. 24.80 s [niks3-go-unit-tests:post-build] copying path '/nix/store/8xipwkfxjjac5vxawzdhwbglb2z0mbmk-niks3-go-unit-tests.drv' to 'https://cache.staging.nix-ci.com'...
  1994. 25.33 s Uploaded niks3-go-unit-tests in 1.1s
  1995. 25.33 s Progress: 1 of 2 built
  1996. 25.33 s Built niks3-go-unit-tests in 23.6s
  1997. 25.33 s Progress: 2 of 2 built
  1998. 25.33 s /nix/store/liggxz9whnrhf14k62xng28vn7lwg11j-niks3-go-unit-tests
  1999. 25.38 s Build succeeded.
More Logs Raw Logs

Agent Instructions

Wait for completion, without logs:

curl --netrc -N https://staging.nix-ci.com/gh:NorfairKing:niks3/fix%2Fregister-completed-object/d0828f309b75bf7f847e794f1920e290d23110d7/3f7c4172-4e54-43bc-ad71-ded14955c811/wait

Latest logs, with timestamps (streams while running):

curl --netrc -N https://staging.nix-ci.com/gh:NorfairKing:niks3/fix%2Fregister-completed-object/d0828f309b75bf7f847e794f1920e290d23110d7/3f7c4172-4e54-43bc-ad71-ded14955c811/tail

All logs, with timestamps (available after completion):

curl --netrc https://staging.nix-ci.com/gh:NorfairKing:niks3/fix%2Fregister-completed-object/d0828f309b75bf7f847e794f1920e290d23110d7/3f7c4172-4e54-43bc-ad71-ded14955c811/logs

Raw logs, from the start (no timestamps):

curl --netrc -N https://staging.nix-ci.com/gh:NorfairKing:niks3/fix%2Fregister-completed-object/d0828f309b75bf7f847e794f1920e290d23110d7/3f7c4172-4e54-43bc-ad71-ded14955c811/raw-logs

Content types available for /logs and /tail (use Accept header):

Example:

curl --netrc -H "Accept: text/csv" https://staging.nix-ci.com/gh:NorfairKing:niks3/fix%2Fregister-completed-object/d0828f309b75bf7f847e794f1920e290d23110d7/3f7c4172-4e54-43bc-ad71-ded14955c811/logs

Reproduce locally: https://staging.nix-ci.com/gh:NorfairKing:niks3/fix%2Fregister-completed-object/d0828f309b75bf7f847e794f1920e290d23110d7/3f7c4172-4e54-43bc-ad71-ded14955c811/repro

This page is also available in machine-friendly formats. Request one with the Accept header:

For more instructions, fetch https://staging.nix-ci.com/instructions .