Open mikebucher opened 8 months ago
Is this a duplicate of #8992?
Seems similar, going to rebase and see if it works now
Update: error still happens, but it seems like only for our self-hosted packages:
updater | Updating project [/home/dependabot/dependabot-updater/repo/test/DependencyInjectionTest.csproj]
updater | Running for SDK-style project
updater | Package [**self-hosted-package**] Does not exist as a dependency in [/home/dependabot/dependabot-updater/repo/test/DependencyInjectionTest.csproj].
updater | Update complete.
updater | 2024/02/26 08:13:42 INFO <job_791941480> [Transport] Sending envelope with items [event] 3ac4c30b22a74ff297abd7be2760fd1e to Sentry
proxy | 2024/02/26 08:13:42 [505] POST https://sentry.io:443/api/1451818/envelope/
updater | 2024/02/26 08:13:42 ERROR <job_791941480> Error processing **self-hosted-package** (Dependabot::DependabotError)
updater | 2024/02/26 08:13:42 ERROR <job_791941480> FileUpdater failed
updater | 2024/02/26 08:13:42 ERROR <job_791941480> /home/dependabot/dependabot-updater/lib/dependabot/dependency_change_builder.rb:69:in `run'
updater | 2024/02/26 08:13:42 ERROR <job_791941480> /home/dependabot/dependabot-updater/vendor/ruby/3.1.0/gems/sorbet-runtime-0.5.11193/lib/types/private/methods/call_validation_2_7.rb:59:in `bind_call'
updater | 2024/02/26 08:13:42 ERROR <job_791941480> /home/dependabot/dependabot-updater/vendor/ruby/3.1.0/gems/sorbet-runtime-0.5.11193/lib/types/private/methods/call_validation_2_7.rb:59:in `block in create_validator_method_fast0'
updater | 2024/02/26 08:13:42 ERROR <job_791941480> /home/dependabot/dependabot-updater/lib/dependabot/dependency_change_builder.rb:42:in `create_from'
updater | 2024/02/26 08:13:42 ERROR <job_791941480> /home/dependabot/dependabot-updater/vendor/ruby/3.1.0/gems/sorbet-runtime-0.5.11193/lib/types/private/methods/call_validation.rb:169:in `bind_call'
updater | 2024/02/26 08:13:42 ERROR <job_791941480> /home/dependabot/dependabot-updater/vendor/ruby/3.1.0/gems/sorbet-runtime-0.5.11193/lib/types/private/methods/call_validation.rb:169:in `validate_call_skip_block_type'
updater | 2024/02/26 08:13:42 ERROR <job_791941480> /home/dependabot/dependabot-updater/vendor/ruby/3.1.0/gems/sorbet-runtime-0.5.11193/lib/types/private/methods/call_validation.rb:111:in `block in create_validator_slow_skip_block_type'
updater | 2024/02/26 08:13:42 ERROR <job_791941480> /home/dependabot/dependabot-updater/lib/dependabot/updater/group_update_creation.rb:114:in `create_change_for'
updater | 2024/02/26 08:13:42 ERROR <job_791941480> /home/dependabot/dependabot-updater/lib/dependabot/updater/group_update_creation.rb:72:in `block in compile_all_dependency_changes_for'
updater | 2024/02/26 08:13:42 ERROR <job_791941480> /home/dependabot/dependabot-updater/lib/dependabot/updater/group_update_creation.rb:38:in `each'
updater | 2024/02/26 08:13:42 ERROR <job_791941480> /home/dependabot/dependabot-updater/lib/dependabot/updater/group_update_creation.rb:38:in `compile_all_dependency_changes_for'
updater | 2024/02/26 08:13:42 ERROR <job_791941480> /home/dependabot/dependabot-updater/lib/dependabot/updater/operations/refresh_group_update_pull_request.rb:116:in `dependency_change'
updater | 2024/02/26 08:13:42 ERROR <job_791941480> /home/dependabot/dependabot-updater/lib/dependabot/updater/operations/refresh_group_update_pull_request.rb:99:in `perform'
updater | 2024/02/26 08:13:42 ERROR <job_791941480> /home/dependabot/dependabot-updater/lib/dependabot/updater.rb:45:in `run'
updater | 2024/02/26 08:13:42 ERROR <job_791941480> /home/dependabot/dependabot-updater/lib/dependabot/update_files_command.rb:43:in `perform_job'
updater | 2024/02/26 08:13:42 ERROR <job_791941480> /home/dependabot/dependabot-updater/lib/dependabot/base_command.rb:36:in `run'
updater | 2024/02/26 08:13:42 ERROR <job_791941480> bin/update_files.rb:24:in `<main>'
For the 3 PRs it creates, dependabot fails with the above error once, and times out twice
Is this issue still happening? The unknown error getting reported is kind of a catch-all where the first part of the NuGet updater thought it could update a package, but one of the later steps failed to do the actual update.
If it is still happening, is there a public repo with a public package feed that displays this issue? It's much easier to diagnose when I can run it locally.
@brettfo I have reproduced this in my private repository. My edge case is that I am using ManagePackageVersionsCentrally
with .net 8 and I have some nuget packages defined in my Directory.Packages.props
file, which are not actually used in any of my code. Dependabot tried updating nuget packages which isn't used and this is my assumption for this error occurring.
My dependabot file:
updates:
- package-ecosystem: "nuget"
directory: "/"
schedule:
interval: "daily"
groups:
version-dependencies:
applies-to: version-updates
patterns:
- "*"
exclude-patterns:
- "Redacted.*"
security-dependencies:
applies-to: security-updates
patterns:
- "*"
exclude-patterns:
- "Redacted.*"
My error log:
proxy | 2024/09/25 08:36:58 [481] GET [https://api.nuget.org:443/v3/registration5-gz-semver2/fluentassertions/index.json](https://api.nuget.org/v3/registration5-gz-semver2/fluentassertions/index.json)
proxy | 2024/09/25 08:36:59 [481] 200 [https://api.nuget.org:443/v3/registration5-gz-semver2/fluentassertions/index.json](https://api.nuget.org/v3/registration5-gz-semver2/fluentassertions/index.json)
updater | 2024/09/25 08:36:59 INFO <job_890698798> Filtered out 10 pre-release versions
proxy | 2024/09/25 08:36:59 [487] GET [https://api.nuget.org:443/v3-flatcontainer/fluentassertions/6.11.0/fluentassertions.nuspec](https://api.nuget.org/v3-flatcontainer/fluentassertions/6.11.0/fluentassertions.nuspec)
proxy | 2024/09/25 08:36:59 [487] 200 [https://api.nuget.org:443/v3-flatcontainer/fluentassertions/6.11.0/fluentassertions.nuspec](https://api.nuget.org/v3-flatcontainer/fluentassertions/6.11.0/fluentassertions.nuspec)
updater | 2024/09/25 08:36:59 INFO <job_890698798> Latest version is 6.12.1
updater | 2024/09/25 08:36:59 INFO <job_890698798> Requirements to unlock all
2024/09/25 08:36:59 INFO <job_890698798> Requirements update strategy
updater | Finding updated dependencies for FluentAssertions.
proxy | 2024/09/25 08:36:59 [489] GET [https://api.nuget.org:443/v3-flatcontainer/fluentassertions/6.12.1/fluentassertions.nuspec](https://api.nuget.org/v3-flatcontainer/fluentassertions/6.12.1/fluentassertions.nuspec)
proxy | 2024/09/25 08:36:59 [489] 200 [https://api.nuget.org:443/v3-flatcontainer/fluentassertions/6.12.1/fluentassertions.nuspec](https://api.nuget.org/v3-flatcontainer/fluentassertions/6.12.1/fluentassertions.nuspec)
proxy | 2024/09/25 08:36:59 [491] GET [https://api.nuget.org:443/v3-flatcontainer/system.threading.tasks.extensions/4.5.0/system.threading.tasks.extensions.nuspec](https://api.nuget.org/v3-flatcontainer/system.threading.tasks.extensions/4.5.0/system.threading.tasks.extensions.nuspec)
proxy | 2024/09/25 08:36:59 [491] 200 [https://api.nuget.org:443/v3-flatcontainer/system.threading.tasks.extensions/4.5.0/system.threading.tasks.extensions.nuspec](https://api.nuget.org/v3-flatcontainer/system.threading.tasks.extensions/4.5.0/system.threading.tasks.extensions.nuspec)
proxy | 2024/09/25 08:36:59 [493] GET [https://api.nuget.org:443/v3-flatcontainer/system.configuration.configurationmanager/4.4.0/system.configuration.configurationmanager.nuspec](https://api.nuget.org/v3-flatcontainer/system.configuration.configurationmanager/4.4.0/system.configuration.configurationmanager.nuspec)
proxy | 2024/09/25 08:36:59 [493] 200 [https://api.nuget.org:443/v3-flatcontainer/system.configuration.configurationmanager/4.4.0/system.configuration.configurationmanager.nuspec](https://api.nuget.org/v3-flatcontainer/system.configuration.configurationmanager/4.4.0/system.configuration.configurationmanager.nuspec)
updater | 2024/09/25 08:36:59 INFO <job_890698798> Updating FluentAssertions from 6.11.0 to 6.12.1
proxy | 2024/09/25 08:36:59 [495] POST /update_jobs/890698798/record_update_job_unknown_error
proxy | 2024/09/25 08:36:59 [495] 204 /update_jobs/890698798/record_update_job_unknown_error
proxy | 2024/09/25 08:36:59 [497] POST /update_jobs/890698798/record_update_job_error
proxy | 2024/09/25 08:36:59 [497] 204 /update_jobs/890698798/record_update_job_error
proxy | 2024/09/25 08:36:59 [499] POST /update_jobs/890698798/increment_metric
proxy | 2024/09/25 08:36:59 [499] 204 /update_jobs/890698798/increment_metric
proxy | 2024/09/25 08:36:59 [501] POST /update_jobs/890698798/record_update_job_unknown_error
proxy | 2024/09/25 08:36:59 [501] 204 /update_jobs/890698798/record_update_job_unknown_error
updater | 2024/09/25 08:36:59 ERROR <job_890698798> Error processing FluentAssertions (Dependabot::DependabotError)
updater | 2024/09/25 08:36:59 ERROR <job_890698798> FileUpdater failed
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/lib/dependabot/dependency_change_builder.rb:73:in `run'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/call_validation_2_7.rb:59:in `bind_call'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/call_validation_2_7.rb:59:in `block in create_validator_method_fast0'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/lib/dependabot/dependency_change_builder.rb:44:in `create_from'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/call_validation.rb:167:in `bind_call'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/call_validation.rb:167:in `validate_call_skip_block_type'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/call_validation.rb:109:in `block in create_validator_slow_skip_block_type'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/lib/dependabot/updater/group_update_creation.rb:175:in `create_change_for'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/call_validation_2_7.rb:1187:in `bind_call'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/call_validation_2_7.rb:1187:in `block in create_validator_method_medium4'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/lib/dependabot/updater/group_update_creation.rb:100:in `block in compile_all_dependency_changes_for'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/lib/dependabot/updater/group_update_creation.rb:62:in `each'
updater | 2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/lib/dependabot/updater/group_update_creation.rb:62:in `compile_all_dependency_changes_for'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/call_validation.rb:270:in `bind_call'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/call_validation.rb:270:in `validate_call'
updater | 2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/_methods.rb:277:in `block in _on_method_added'
updater | 2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/lib/dependabot/updater/operations/create_group_update_pull_request.rb:97:in `dependency_change'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/call_validation.rb:270:in `bind_call'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/call_validation.rb:270:in `validate_call'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/_methods.rb:277:in `block in _on_method_added'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/lib/dependabot/updater/operations/create_group_update_pull_request.rb:61:in `perform'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/call_validation.rb:270:in `bind_call'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/call_validation.rb:270:in `validate_call'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/_methods.rb:277:in `block in _on_method_added'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/lib/dependabot/updater/operations/group_update_all_versions.rb:117:in `run_grouped_update_for'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/call_validation.rb:270:in `bind_call'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/call_validation.rb:270:in `validate_call'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/_methods.rb:277:in `block in _on_method_added'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/lib/dependabot/updater/operations/group_update_all_versions.rb:103:in `block in run_grouped_dependency_updates'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/lib/dependabot/updater/operations/group_update_all_versions.rb:102:in `each'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/lib/dependabot/updater/operations/group_update_all_versions.rb:102:in `run_grouped_dependency_updates'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/call_validation.rb:270:in `bind_call'
updater | 2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/call_validation.rb:270:in `validate_call'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/_methods.rb:277:in `block in _on_method_added'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/lib/dependabot/updater/operations/group_update_all_versions.rb:64:in `perform'
updater | 2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/call_validation.rb:270:in `bind_call'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/call_validation.rb:270:in `validate_call'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/sorbet-runtime-0.5.11444/lib/types/private/methods/_methods.rb:277:in `block in _on_method_added'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/lib/dependabot/updater.rb:45:in `run'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/lib/dependabot/update_files_command.rb:44:in `block in perform_job'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/opentelemetry-api-1.2.3/lib/opentelemetry/trace/tracer.rb:37:in `block in in_span'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/opentelemetry-api-1.2.3/lib/opentelemetry/trace.rb:70:in `block in with_span'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/opentelemetry-api-1.2.3/lib/opentelemetry/context.rb:87:in `with_value'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/opentelemetry-api-1.2.3/lib/opentelemetry/trace.rb:70:in `with_span'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/vendor/ruby/3.3.0/gems/opentelemetry-api-1.2.3/lib/opentelemetry/trace/tracer.rb:37:in `in_span'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/lib/dependabot/update_files_command.rb:18:in `perform_job'
2024/09/25 08:36:59 ERROR <job_890698798> /home/dependabot/dependabot-updater/lib/dependabot/base_command.rb:37:in `run'
2024/09/25 08:36:59 ERROR <job_890698798> bin/update_files.rb:46:in `<main>'
updater | 2024/09/25 08:37:00 INFO <job_890698798> Nothing to update for Dependency Group: 'version-dependencies'
updater | 2024/09/25 08:37:00 INFO <job_890698798> Found no dependencies to update after filtering allowed updates in /
proxy | 2024/09/25 08:37:00 [503] PATCH /update_jobs/890698798/mark_as_processed
proxy | 2024/09/25 08:37:00 [503] 204 /update_jobs/890698798/mark_as_processed
updater | 2024/09/25 08:37:00 INFO <job_890698798> Finished job processing
updater | 2024/09/25 08:37:00 INFO Results:
Dependabot encountered '3' error(s) during execution, please check the logs for more details.
+--------------------------------------------+
| Dependencies failed to update |
+----------------------------+---------------+
| Azure.Storage.Files.Shares | unknown_error |
| Datadog.Trace | unknown_error |
| FluentAssertions | unknown_error |
+----------------------------+---------------+
Thank you for the logs, they were really helpful. The issue here is that the concept of a transitive dependency as dependabot-core understands it doesn't map to MSBuild/NuGet, primarily because MSBuild can navigate between arbitrary directories. A secondary issue is that there are really 3 types of transitive dependencies with NuGet: (1) a csproj imports a package that depends on another package, (2) a csproj references another csproj that references a package, and (3) a csproj references another csproj that imports a package that references another package, but dependabot-core only calls dependencies top-level or not.
We're currently working on a rewrite of transitive dependency handling, but it's a large feature so we don't have an ETA yet.
Is there an existing issue for this?
Package ecosystem
nuget
Package manager version
No response
Language version
.net 8.0.100
Manifest location and content before the Dependabot update
No response
dependabot.yml content
Updated dependency
No response
What you expected to see, versus what you actually saw
Dependabot fails to update some packages, throwing a unknown_error. This only happens for 5 packages in this repository, the rest work fine, and happens with both privately hosted and public packages. We are getting the same errors in another repository as well. Below I posted the log for one of the public ones. The error log seems the same for all packages where this unknown_error occurs. We use central package versioning, and have only seen this error show up more recently, as we have just started migrating teams over to GitHub from ADO.
Native package manager behavior
No response
Images of the diff or a link to the PR, issue, or logs
Smallest manifest that reproduces the issue
No response