search

dependabot / dependabot-core

🤖 Dependabot's core logic for creating update PRs.
https://docs.github.com/en/code-security/dependabot
MIT License
4.72k stars 1.02k forks source link

Dependabot frequently failing to raise PR for pub packages #7223

Open cpswan opened 1 year ago

cpswan commented 1 year ago

Is there an existing issue for this?

Package ecosystem

pub

Package manager version

NA

Language version

2.19.6

Manifest location and content before the Dependabot update

/packages/at_secondary_server/pubspec.yaml

dependabot.yml content

version: 2
enable-beta-ecosystems: true
updates:
  # Maintain dependencies for GitHub Actions
  - package-ecosystem: "github-actions"
    directory: "/"
    schedule:
      interval: "daily"
  - package-ecosystem: "docker"
    directory: "/tools/build_secondary"
    schedule:
      interval: "daily"
  - package-ecosystem: "docker"
    directory: "/tools/build_virtual_environment/ve"
    schedule:
      interval: "daily"
  - package-ecosystem: "docker"
    directory: "/tools/build_virtual_environment/ve_base"
    schedule:
      interval: "daily"     
  - package-ecosystem: "docker"
    directory: "/packages/at_root_server"
    schedule:
      interval: "daily"
  - package-ecosystem: "pub"
    directory: "/packages/at_secondary_server"
    schedule:
      interval: "daily"
  - package-ecosystem: "pip"
    directory: "/tools" # Location of package manifests
    schedule:
      interval: "daily"

Updated dependency

Dependency From version To version
collection 1.17.0 1.17.1
basic_utils 5.4.2 5.5.4
meta 1.8.0 1.9.1
args 2.3.1 2.4.0

What you expected to see, versus what you actually saw

I'd expect to see a PR for the dependencies that need to be updated. Instead the logs show that a PR couldn't be raised:

They conclude with:

updater | 2023/05/03 10:40:54 INFO Results:
updater | Dependabot encountered '4' error(s) during execution, please check the logs for more details.
updater | +-------------------------------+
updater | | Dependencies failed to update |
updater | +---------------+---------------+
updater | | collection    | unknown_error |
updater | | basic_utils   | unknown_error |
updater | | meta          | unknown_error |
updater | | args          | unknown_error |
updater | +---------------+---------------+

and on the way show ERROR block for each dependency like:

updater | 2023/05/03 10:40:17 ERROR <job_656542567> Error processing collection (Dependabot::ApiError)
updater | 2023/05/03 10:40:17 ERROR <job_656542567> {"errors":[{"status":500,"title":"Internal Server Error"}]}
updater | 2023/05/03 10:40:17 ERROR <job_656542567> /home/dependabot/dependabot-updater/lib/dependabot/api_client.rb:30:in `create_pull_request'
updater | 2023/05/03 10:40:17 ERROR <job_656542567> /home/dependabot/dependabot-updater/lib/dependabot/service.rb:31:in `create_pull_request'
updater | 2023/05/03 10:40:17 ERROR <job_656542567> /home/dependabot/dependabot-updater/lib/dependabot/updater/operations/update_all_versions.rb:250:in `create_pull_request'
updater | 2023/05/03 10:40:17 ERROR <job_656542567> /home/dependabot/dependabot-updater/lib/dependabot/updater/operations/update_all_versions.rb:134:in `check_and_create_pull_request'
updater | 2023/05/03 10:40:17 ERROR <job_656542567> /home/dependabot/dependabot-updater/lib/dependabot/updater/operations/update_all_versions.rb:65:in `check_and_create_pr_with_error_handling'
updater | 2023/05/03 10:40:17 ERROR <job_656542567> /home/dependabot/dependabot-updater/lib/dependabot/updater/operations/update_all_versions.rb:34:in `block in perform'
updater | 2023/05/03 10:40:17 ERROR <job_656542567> /home/dependabot/dependabot-updater/lib/dependabot/updater/operations/update_all_versions.rb:34:in `each'
updater | 2023/05/03 10:40:17 ERROR <job_656542567> /home/dependabot/dependabot-updater/lib/dependabot/updater/operations/update_all_versions.rb:34:in `perform'
updater | 2023/05/03 10:40:17 ERROR <job_656542567> /home/dependabot/dependabot-updater/lib/dependabot/updater.rb:72:in `run'
updater | 2023/05/03 10:40:17 ERROR <job_656542567> /home/dependabot/dependabot-updater/lib/dependabot/update_files_command.rb:38:in `perform_job'
updater | 2023/05/03 10:40:17 ERROR <job_656542567> /home/dependabot/dependabot-updater/lib/dependabot/base_command.rb:52:in `run'
updater | 2023/05/03 10:40:17 ERROR <job_656542567> bin/update_files.rb:23:in `<main>'

Native package manager behavior

NA

Images of the diff or a link to the PR, issue, or logs

Logs are at https://gist.github.com/cpswan/9884347c0cddc7e29b6bb5bf9113fd45

Smallest manifest that reproduces the issue

No response

jakecoffman commented 1 year ago

@cpswan I just pushed a fix for this on the server. Can you run the job again and verify it works now? Thanks!

cpswan commented 1 year ago

Thanks for the quick response @jakecoffman

It's still saying Dependabot encountered an unknown error Dependabot failed to update your dependencies because an unexpected error occurred. See the logs for more details., but I'm seeing far less evidence of errors in the logs (new gist). No sign of a PR though :(

There's also another dependency needing updating since yesterday, and better reporting of the changes that should be happening:

updater | +------------------------------------------------+
updater | |      Changes to Dependabot Pull Requests       |
updater | +---------+--------------------------------------+
updater | | created | args ( from 2.3.1 to 2.4.1 )         |
updater | | created | crypto ( from 3.0.2 to 3.0.3 )       |
updater | | created | collection ( from 1.17.0 to 1.17.1 ) |
updater | | created | basic_utils ( from 5.4.2 to 5.5.4 )  |
updater | | created | meta ( from 1.8.0 to 1.9.1 )         |
updater | +---------+--------------------------------------+
jakecoffman commented 1 year ago

@cpswan thanks for checking, looks like it made more progress. I made another change if you want to try again. I think this time it should put up some PRs. 🤞

cpswan commented 1 year ago

Thanks @jakecoffman the overnight run beat me to it...

This time I see a green tick before Dependabot encountered an unknown error rather than the usual red triangle, which is a bit weird. But still no PR.

image

I've put the latest logs in another gist, though once again they don't have much to say about what went wrong in raising the PR.

jakecoffman commented 1 year ago

Dependabot is receiving the following error from GitHub when it tries to put up the PR:

422 - tree.path contains a malformed path component

I ran the Dependabot CLI to diagnose further: dependabot update pub atsign-foundation/at_server --directory /packages/at_root_server -o out.yml

In the out.yml the symlink mentioned here seems to be included in the update even though the symlink itself didn't change, just the contents of the file that it points to.

That's probably a bug in Dependabot's Pub implementation we'll have to sort out.

cpswan commented 1 year ago

Thanks @jakecoffman

I just tried running that myself.

I'm not seeing anything in out.yml that references the symlink, which should be well out of scope given that it's in a different directory:

input:
    job:
        package-manager: pub
        allowed-updates:
            - update-type: all
        source:
            provider: github
            repo: atsign-foundation/at_server
            directory: /packages/at_root_server
            commit: e1e05fa53172f5584c009d4cc652c6e359612370
output:
    - type: record_update_job_error
      expect:
        data:
            error-type: unknown_error
            error-details: {}
    - type: mark_as_processed
      expect:
        data:
            base-commit-sha: e1e05fa53172f5584c009d4cc652c6e359612370

I'm also not seeing anything in the logs related to the symlink, but there are a bunch of ERRORs towards the end:

updater | 2023/05/09 10:24:12 ERROR private method `select' called for nil:NilClass
updater |
updater |                            select { |c| c["type"] == "git_source" }.
updater |                            ^^^^^^
updater | 2023/05/09 10:24:12 ERROR /home/dependabot/common/lib/dependabot/shared_helpers.rb:217:in `configure_git_to_use_https_with_credentials'
updater | 2023/05/09 10:24:12 ERROR /home/dependabot/common/lib/dependabot/shared_helpers.rb:180:in `with_git_configured'
updater | 2023/05/09 10:24:12 ERROR /home/dependabot/pub/lib/dependabot/pub/helpers.rb:186:in `block in run_dependency_services'
updater | 2023/05/09 10:24:12 ERROR /home/dependabot/common/lib/dependabot/shared_helpers.rb:49:in `block in in_a_temporary_directory'
updater | 2023/05/09 10:24:12 ERROR /home/dependabot/common/lib/dependabot/shared_helpers.rb:49:in `chdir'
updater | 2023/05/09 10:24:12 ERROR /home/dependabot/common/lib/dependabot/shared_helpers.rb:49:in `in_a_temporary_directory'
updater | 2023/05/09 10:24:12 ERROR /home/dependabot/pub/lib/dependabot/pub/helpers.rb:179:in `run_dependency_services'
updater | 2023/05/09 10:24:12 ERROR /home/dependabot/pub/lib/dependabot/pub/helpers.rb:33:in `dependency_services_list'
updater | 2023/05/09 10:24:12 ERROR /home/dependabot/pub/lib/dependabot/pub/file_parser.rb:30:in `list'
updater | 2023/05/09 10:24:12 ERROR /home/dependabot/pub/lib/dependabot/pub/file_parser.rb:17:in `parse'
updater | 2023/05/09 10:24:12 ERROR /home/dependabot/dependabot-updater/lib/dependabot/dependency_snapshot.rb:97:in `parse_files!'
updater | 2023/05/09 10:24:12 ERROR /home/dependabot/dependabot-updater/lib/dependabot/dependency_snapshot.rb:91:in `initialize'
updater | 2023/05/09 10:24:12 ERROR /home/dependabot/dependabot-updater/lib/dependabot/dependency_snapshot.rb:21:in `new'
updater | 2023/05/09 10:24:12 ERROR /home/dependabot/dependabot-updater/lib/dependabot/dependency_snapshot.rb:21:in `create_from_job_definition'
updater | 2023/05/09 10:24:12 ERROR /home/dependabot/dependabot-updater/lib/dependabot/update_files_command.rb:16:in `perform_job'
updater | 2023/05/09 10:24:12 ERROR /home/dependabot/dependabot-updater/lib/dependabot/base_command.rb:52:in `run'
updater | 2023/05/09 10:24:12 ERROR bin/update_files.rb:23:in `<main>'
  proxy | 2023/05/09 10:24:13 [479] POST http://host.docker.internal:45309/update_jobs/cli/record_update_job_error
{"data":{"error-type":"unknown_error","error-details":null},"type":"record_update_job_error"}
  proxy | 2023/05/09 10:24:13 [479] 200 http://host.docker.internal:45309/update_jobs/cli/record_update_job_error
  proxy | 2023/05/09 10:24:13 [480] PATCH http://host.docker.internal:45309/update_jobs/cli/mark_as_processed
{"data":{"base-commit-sha":"e1e05fa53172f5584c009d4cc652c6e359612370"},"type":"mark_as_processed"}
  proxy | 2023/05/09 10:24:13 [480] 200 http://host.docker.internal:45309/update_jobs/cli/mark_as_processed
updater | 2023/05/09 10:24:13 INFO Finished job processing
updater | 2023/05/09 10:24:13 INFO Results:
updater | Dependabot encountered '1' error(s) during execution, please check the logs for more details.
updater | +---------------+
updater | |    Errors     |
updater | +---------------+
updater | | unknown_error |
updater | +---------------+
  proxy | 2023/05/09 10:24:15 1/239 calls cached (0%)

FYI the symlink is there because we use some of the config metadata from pubspec.yaml in our tests, and don't want to maintain duplicate copies of the same file in the repo.

jakecoffman commented 1 year ago

That error was due to running jobs without credentials in the CLI. I fixed it in #7277, so if you pull a new version of the pub updater it should work: docker pull ghcr.io/dependabot/dependabot-updater-pub:latest

It looks like the issue here is Pub considers all pubspecs under the directory that is configured: https://github.com/dependabot/dependabot-core/blob/03069cc49e07fb3b658b0a5f1bda900171d1889f/pub/lib/dependabot/pub/file_fetcher.rb#L27

So we should filter out symlinks since they're either already covered by the glob, or they're outside the directory and shouldn't be considered. I can fix that up soon.

cpswan commented 1 year ago

Some progress... I'm now seeing clean runs with the dependabot CLI and in Dependency Graph > Dependabot.

But, no PR actually raised. So it's still silently failing somewhere.

sigurdm commented 1 year ago

@cpswan Has this improved since https://github.com/dependabot/dependabot-core/pull/7265 was deployed?

cpswan commented 1 year ago

@sigurdm sadly no improvement. The logs conclude in a way that suggests that PRs have been raised:

updater | 2023/06/02 01:11:39 INFO Results:
updater | +------------------------------------------------+
updater | |      Changes to Dependabot Pull Requests       |
updater | +---------+--------------------------------------+
updater | | created | collection ( from 1.17.0 to 1.17.2 ) |
updater | | created | crypto ( from 3.0.2 to 3.0.3 )       |
updater | | created | meta ( from 1.8.0 to 1.9.1 )         |
updater | | created | yaml ( from 3.1.1 to 3.1.2 )         |
updater | | created | basic_utils ( from 5.4.2 to 5.5.4 )  |
updater | +---------+--------------------------------------+

But no actual PRs:

image

sigurdm commented 1 year ago

@jeffwidman not sure I understand those logs. Does this look like a problem with the pub integration?

cpswan commented 1 year ago

Error reporting seems to have improved :) Rather than an unknown error I now see:

Dependabot failed to create a pull request
Dependabot ran into an issue when attempting to create the pull request

Dependabot encountered the following error:

POST https://api.github.com/repos/atsign-foundation/at_server/git/trees: 422 - tree.path contains a malformed path component // See: https://docs.github.com/rest/git/trees#create-a-tree
abdulapopoola commented 1 year ago

Thanks @cpswan ; yes we're working on improving and surfacing actionable error messages. I hope this helps!

cpswan commented 6 months ago

After adding groups to my dependabot.yml it looks like things are working when they weren't before.

image

But there's no actual PR from that run :(

Full logs in this gist: 825091200.log

The pub section of my dependabot.yml now look like this:

  - package-ecosystem: "pub"
    directories:
      - "/packages/at_root_server"
      - "/packages/at_secondary_server"
    schedule:
      interval: "daily"
    groups:
      pub:
        patterns:
          - "*"
cpswan commented 6 months ago

Extra weirdness... in the time it took me to write the comment above (which was already an hour after the Dependabot run), the status has now changed to failed.

Nothing new in the logs, but I do see this:

Dependabot ran into an issue when attempting to create the pull request

Dependabot encountered the following error:

POST https://api.github.com/repos/atsign-foundation/at_server/git/trees: 422 - tree.path contains a malformed path component // See: https://docs.github.com/rest/git/trees#create-a-tree
[Troubleshoot Dependabot errors](https://docs.github.com/github/managing-security-vulnerabilities/troubleshooting-dependabot-errors)

image

image

I'm guessing something took over an hour to time out, and then that eventually propagated back to the Dependency graph insights.

tarasmadan commented 1 week ago

Hi all. Are any updates coming? I'm experiencing the very similar symptoms. More data:

  1. Symptoms.
  2. Config 
    version: 2
updates:
- package-ecosystem: gomod
directory: "/"
schedule:
interval: monthly
open-pull-requests-limit: 10
commit-message:
prefix: "mod:"
assignees:
- "tarasmadan"
groups:
stable-enough:
  patterns:
    - "*"
  exclude-patterns:
    - "mockery"
    - "golangci"
    - "appengine"