search

tinglesoftware / dependabot-azure-devops

Tools for updating dependencies in Azure DevOps repositories using https://dependabot.com
MIT License
201 stars 66 forks source link

V2 task taking over an hour when using npm private registry. Log files are huge #1441

Open eli-gc opened 3 weeks ago

eli-gc commented 3 weeks ago

Describe the bug I recently migrated to the V2 task and it is timing out after my timeout limit (60 minutes). Using the V1 task only takes 3 minutes. It seems for every package, it prints out the entire contents of the yarn lock file. I'm not sure if the performance issues are related to that but the log file is huge, 134.2 MB.

Categorization

Configurations Pipeline:


    steps:
      - task: GoTool@0
        inputs:
          version: 1.23.0 

      - task: dependabot@2
        inputs:
          useConfigFile: true
          setAutoComplete: true
          mergeStrategy: '1'
          gitHubConnection: 'github.com_SabareeshGC'
          milestone: 12347
        env:
          NPM_TOKEN: $(System.AccessToken)

dependabot.yml

registries:
  npm-data-module:
    type: npm-registry
    url: https://pkgs.dev.azure.com/guidedchoice/_packaging/data-projections/npm/registry/
    token: ${{NPM_TOKEN}}
updates:
  - package-ecosystem: "npm"
    # Files stored in `app` directory
    directory: "/"
    schedule:
      interval: "daily"
    milestone: 12347
    target-branch: "dev"
    versioning-strategy: auto
    registries: 
      - npm-data-module

Logs and screenshots Logs in the beginning of the run. I had to truncate the {"data"} section because it exceeded the character limit. I think this part is potentially causing my poor performance. It seems to be printing all of the yarn.lock or something. 


==============================================================================
Task         : Dependabot
Description  : Automatically update dependencies and vulnerabilities in your code using [Dependabot CLI](https://github.com/dependabot/cli)
go: downloading github.com/opencontainers/image-spec v1.1.0
go: downloading github.com/moby/sys/user v0.1.0
go: downloading github.com/opencontainers/go-digest v1.0.0
go: downloading github.com/gogo/protobuf v1.3.2
go: downloading github.com/distribution/reference v0.6.0
go: downloading go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.52.0
go: downloading go.opentelemetry.io/otel/trace v1.27.0
go: downloading go.opentelemetry.io/otel v1.27.0
go: downloading github.com/felixge/httpsnoop v1.0.4
go: downloading go.opentelemetry.io/otel/metric v1.27.0
go: downloading github.com/go-logr/stdr v1.2.2
go: downloading github.com/go-logr/logr v1.4.2

Processing job from '/tmp/dependabot-jobs/update-0-npm_and_yarn-all/job.yaml'
/root/go/bin/dependabot update --file /tmp/dependabot-jobs/update-0-npm_and_yarn-all/job.yaml --output /tmp/dependabot-jobs/update-0-npm_and_yarn-all/scenario.yaml --provider azure --local /mnt/data-disk/gcadmin/agent1/37/s
    cli | 2024/10/29 16:45:04 pulling image: ghcr.io/github/dependabot-update-job-proxy/dependabot-update-job-proxy:latest
    cli | 2024/10/29 16:45:05 using image ghcr.io/github/dependabot-update-job-proxy/dependabot-update-job-proxy:latest at sha256:4f808dfd8f35a9fb1d8e557bea7a2b0f72d5b663f9a7446288292faa5e905042
    cli | 2024/10/29 16:45:05 pulling image: ghcr.io/dependabot/dependabot-updater-npm
    cli | 2024/10/29 16:45:26 using image ghcr.io/dependabot/dependabot-updater-npm at sha256:5fec5a1aaccb06d782f29d6ef7a286b36d787a4e9ff27244f36c0a513212c9a4
  proxy | 2024/10/29 16:45:35 proxy starting, commit: 41881abec5bb353fbea347b2394f90fb7f78881e
  proxy | 2024/10/29 16:45:35 Listening (:1080)
updater | Reinitialized existing Git repository in /home/dependabot/dependabot-updater/repo/.git/
updater | HEAD detached at origin/8476efca2ac5c8cbc4e82dd23ba2d76083bbb1c9
updater | nothing to commit, working tree clean
updater | Updating certificates in /etc/ssl/certs...
updater | rehash: warning: skipping ca-certificates.crt,it does not contain exactly one certificate or CRL
updater | 1 added, 0 removed; done.
updater | Running hooks in /etc/ca-certificates/update.d...
updater | done.
updater | 2024/10/29 16:45:41 INFO <job_update_0_npm_and_yarn_all> Starting job processing
updater | 2024/10/29 16:45:41 INFO <job_update_0_npm_and_yarn_all> Job definition: {"job":{"package-manager":"npm_and_yarn","allowed-updates":[{"dependency-type":"all"}],"debug":false,"dependency-groups":[],"dependencies":null,"dependency-group-to-refresh":null,"existing-pull-requests":[],"existing-group-pull-requests":[],"experiments":null,"ignore-conditions":[],"lockfile-only":false,"requirements-update-strategy":null,"security-advisories":[],"security-updates-only":false,"source":{"provider":"azure","repo":"***/***/_git/***","directory":"/","branch":"dev","hostname":"***","api-endpoint":"https://***:/"},"update-subdependencies":true,"updating-a-pull-request":false,"vendor-dependencies":false,"reject-external-code":false,"repo-private":false,"commit-message-options":null,"credentials-metadata":[{"host":"***","type":"git_source"},{"host":"github.com","type":"git_source"},{"registry":"pkgs.***/***/_packaging/data-projections/npm/registry/","type":"npm_registry"}],"max-updater-run-time":0}}
updater | 2024/10/29 16:45:41 INFO <job_update_0_npm_and_yarn_all> Guessed version info "yarn" : "1"
updater | 2024/10/29 16:45:41 INFO <job_update_0_npm_and_yarn_all> Base commit SHA: 8476efca2ac5c8cbc4e82dd23ba2d76083bbb1c9
updater | 2024/10/29 16:45:41 INFO <job_update_0_npm_and_yarn_all> Finished job processing
updater | 2024/10/29 16:45:45 INFO <job_update_0_npm_and_yarn_all> Starting job processing
  proxy | 2024/10/29 16:45:46 [001] POST http://host.docker.internal:45033/update_jobs/update_0_npm_and_yarn_all/update_dependency_list
{"data":{"dependencies":[{"name":"@***/data-modules","requirements":[{"file":"package.json","groups":["dependencies"],"requirement":"^0.2.611","source":{"type":"registry","url":"https://pkgs.***/***/_packaging/data-projections/npm/registry"}}],"version":"0.2.611"},{"name":"@aesop-fables/containr","requirements":[{"file":"package.json","groups":["dependencies"],"requirement":"^0.5.3","source":{"type":"registry","url":"https://pkgs.***/***/_packaging/data-projections/npm/registry"}}],"version":"0.5.3"},{"name":"@aesop-fables/containr-axios","requirements":[{"file":"package.json","groups":["dependencies"],"requirement":"^0.3.6","source":{"type":"registry","url":"https://pkgs.***/***/_packaging/data-projections/npm/registry"}}],"version":"0.3.6"},{"name":"@aesop-fables/containr-react","requirements":[{"file":"package.json","groups":["dependencies"],"requirement":"^0.4.1","source":...,"dependency_files":["/package.json","/yarn.lock"]},"type":"update_dependency_list"}
  proxy | 2024/10/29 16:45:46 [001] 200 http://host.docker.internal:45033/update_jobs/update_0_npm_and_yarn_all/update_dependency_list
  proxy | 2024/10/29 16:45:46 [002] POST http://host.docker.internal:45033/update_jobs/update_0_npm_and_yarn_all/increment_metric
{"data":{"metric":"updater.started","tags":{"operation":"group_update_all_versions"}},"type":"increment_metric"}
  proxy | 2024/10/29 16:45:46 [002] 200 http://host.docker.internal:45033/update_jobs/update_0_npm_and_yarn_all/increment_metric
updater | 2024/10/29 16:45:46 INFO <job_update_0_npm_and_yarn_all> Starting update job for ***/***/_git/***```
eli-gc commented 3 weeks ago

By the way, this is an Azure Artifact feed and I am using Yarn Berry, v4.5.1, I also tried 3.8.6 with no avail.

rhyskoedijk commented 3 weeks ago

@eli-gc thanks for the report. Are you able to upload a minimal reproduction repo for this? or attach a copy of your packages.json and yarn.lock so that we can reproduce the issue?

It seems for every package, it prints out the entire contents of the yarn lock file

I too wish this could be disabled as it does cause a lot of log noise, but unfortunately this is not configurable within Dependabot CLI, so it cannot be hidden currently. This was not so much of an issue in V1 because it did not use Dependabot CLI (which caused other issues).

it is hard to say if the volume of logs is the performance issue or the contents of your package/lock file is. If you are able to provide a copy, I will investigate further.

eli-gc commented 3 weeks ago

Let me check if I can post those. There is actually only 1 package that is hosted in our private Azure artifact feed, the rest are all public packages. If there is a way to only search the private feed for the one package and grab the others from public sources, maybe I could test that.

rhyskoedijk commented 3 weeks ago

Let me check if I can post those

If it helps, I really only need the dependencies section of your package.json and yarn.lock; This should be enough to reproduce the issue.

If there is a way to only search the private feed for the one package and grab the others from public sources, maybe I could test that.

There certainly is, but that is something you would need to configure in your project source files, not Dependabot. Here is an example of how this could be done:

In the same directory as your package.json, create a .npmrc file with:

registry=https://registry.npmjs.org/ # by default, fetch packages from the public feed
@myorg:registry=https://pkgs.dev.azure.com/myorg/_packaging/myfeed/npm/registry/ # for anything in the "myorg" namespace, fetch packages from my private feed

Then in your package.json you would do:

{
  "dependencies": {
    "@myorg/my-private-package": "~1.0",
    "node": "~22.0"
  }
}

When running yarn install, node would be fetched from the public feed, my-private-package would be fetched from your private feed. If you already have a yarn.lock, you'd need to delete/rebuild it for this to take effect.

eli-gc commented 3 weeks ago

I'll try those changes, thanks!

Here is the packages.json I am using, the only private package we use is the @3nickels/data-modules.

"dependencies": { "@3nickels/data-modules": "^0.2.610", "@aesop-fables/containr": "^0.6.1", "@aesop-fables/containr-axios": "^0.3.6", "@aesop-fables/containr-react": "^0.4.1", "@aesop-fables/scrinium": "^0.11.11", "@bwjohns4/react-native-draggable-flatlist": "^4.0.1-patch", "@expo/vector-icons": "^14.0.4", "@invertase/react-native-apple-authentication": "^2.4.0", "@notifee/react-native": "^9.1.2", "@react-native-async-storage/async-storage": "^1.24.0", "@react-native-clipboard/clipboard": "^1.14.2", "@react-native-community/datetimepicker": "^7.6.3", "@react-native-community/netinfo": "11.4.1", "@react-native-community/slider": "^4.5.4", "@react-native-firebase/app": "^21.2.0", "@react-native-firebase/messaging": "^21.2.0", "@react-native-google-signin/google-signin": "^13.1.0", "@react-navigation/bottom-tabs": "^6.6.1", "@react-navigation/drawer": "^6.7.2", "@react-navigation/native": "^6.1.18", "@react-navigation/stack": "^6.4.1", "@rneui/base": "^4.0.0-rc.8", "@rneui/themed": "^4.0.0-rc.8", "async-mutex": "^0.5.0", "axios": "^1.7.7", "axios-logger": "2.8.1", "axios-retry": "^4.5.0", "buffer": "^6.0.3", "dayjs": "^1.11.13", "events": "^3.3.0", "expo": "^51.0.37", "expo-font": "^12.0.10", "expo-image-loader": "~4.7.0", "expo-modules-core": "^1.12.25", "expo-secure-store": "^13.0.2", "final-form": "^4.20.10", "intl": "^1.2.5", "jail-monkey": "^2.8.0", "jetifier": "^2.0.0", "jwt-decode": "^3.1.2", "lodash": "^4.17.21", "moment": "^2.30.1", "obfuscator-io-metro-plugin": "^2.1.3", "prop-types": "^15.8.1", "query-string": "^7.1.3", "react": "18.3.1", "react-dom": "18.3.1", "react-error-boundary": "^4.1.2", "react-final-form": "^6.5.9", "react-moment": "^1.1.3", "react-native": "0.75.4", "react-native-actions-sheet": "^0.9.7", "react-native-bars": "^2.4.3", "react-native-biometrics": "^3.0.1", "react-native-blob-util": "0.19.11", "react-native-bootsplash": "^5.5.3", "react-native-cheerio": "^1.0.0-rc.4", "react-native-config": "^1.5.3", "react-native-confirmation-code-field": "^7.4.0", "react-native-device-info": "^10.14.0", "react-native-draggable-flatlist": "^4.0.1", "react-native-elements": "^3.4.3", "react-native-fs": "^2.20.0", "react-native-gesture-handler": "^2.20.1", "react-native-google-places-autocomplete": "2.5.6", "react-native-gradle-plugin": "^0.71.19", "react-native-iap": "^12.15.5", "react-native-image-picker": "^7.1.2", "react-native-in-app-review": "^4.3.3", "react-native-keyboard-aware-scroll-view": "^0.9.5", "react-native-linear-gradient": "^2.8.3", "react-native-mmkv": "^2.12.2", "react-native-notifications": "^5.1.0", "react-native-orientation-locker": "^1.7.0", "react-native-paper": "^5.12.5", "react-native-pdf": "6.7.5", "react-native-permissions": "^4.1.5", "react-native-plaid-link-sdk": "11.8.2", "react-native-reanimated": "^3.16.1", "react-native-restart": "^0.0.27", "react-native-safe-area-context": "4.11.1", "react-native-screens": "^3.34.0", "react-native-share": "10.2.1", "react-native-svg": "15.8.0", "react-native-svg-transformer": "^1.5.0", "react-native-toast-message": "^2.2.1", "react-native-typewriter": "^0.7.0", "react-native-vector-icons": "^10.2.0", "react-native-video": "^6.7.0", "react-native-webview": "13.12.3", "react-native-windows": "^0.75.6", "reflect-metadata": "^0.2.2", "rxjs": "7.8.1", "victory-native": "^36.9.2", "yup": "^1.4.0" }, "devDependencies": { "@babel/core": "^7.25.8", "@babel/plugin-proposal-decorators": "^7.25.7", "@babel/preset-env": "^7.25.8", "@babel/runtime": "^7.25.9", "@jeremybarbet/apple-api-types": "^1.4.1", "@react-native/babel-preset": "0.75.4", "@react-native/eslint-config": "0.75.4", "@react-native/metro-config": "0.75.4", "@react-native/typescript-config": "0.75.4", "@types/color": "^3.0.6", "@types/jest": "^29.5.13", "@types/jwt-encode": "^1.0.3", "@types/lodash": "^4.17.12", "@types/react": "~18.3.11", "@types/react-dom": "~18.3.1", "@types/react-native-typewriter": "^0.7.4", "@types/react-native-video": "^5.0.20", "@typescript-eslint/eslint-plugin": "^7.18.0", "@typescript-eslint/parser": "^7.18.0", "babel-jest": "^29.7.0", "babel-plugin-transform-remove-console": "^6.9.4", "eslint": "^8.57.1", "eslint-config-prettier": "^8.10.0", "eslint-plugin-ft-flow": "^2.0.3", "eslint-plugin-prettier": "^4.2.1", "eslint-plugin-react": "^7.37.1", "husky": "^8.0.3", "jest": "29.7.0", "jest-mock-extended": "^3.0.7", "jwt-encode": "^1.0.1", "lint-staged": "^13.3.0", "patch-package": "^7.0.2", "prettier": "^2.8.8", "react-native-codegen": "^0.71.6", "react-test-renderer": "18.3.1", "ts-jest": "29.2.5", "typescript": "~5.3.3" }, "resolutions": { "@react-native/assets-registry": "0.74.83", "@react-native/gradle-plugin": "0.75.4" }, "engines": { "node": ">=18" }, "private": true, "lint-staged": { "*.{js,jsx,json,ts,tsx,md,html,css}": [ "prettier --write", "yarn lint" ] }, "name": "nickels", "version": "1.22.19", "packageManager": "yarn@4.5.1" `

eli-gc commented 3 weeks ago

Here is the yarn.lock file. yarn.lock.zip

eli-gc commented 2 weeks ago

After looking at the logs again, it seems like it is just repeating itself. I can see GET to the same package multiple times. Don't really see any errors in the logs though so I'm not sure why it is retrying.

epicstar commented 1 week ago

I am getting the same yarn looping behavior.... I want to move to v2 because I also fetch nuget dependencies from ADO Artifacts.....

I guess the good news is that once the 60 minute timeout of the pipeline kicked in, PRs were created. I do wonder why the yarn dependabot logic is running too much though.

eli-gc commented 1 week ago

Oh interesting, I don't even get PRs created.

epicstar commented 1 week ago 
registries:
  npm-data-module:
    type: npm-registry
    url: https://pkgs.dev.azure.com/guidedchoice/_packaging/data-projections/npm/registry/
    token: ${{NPM_TOKEN}}

I wager your problem is on the token.

It might need to be:

[...]
    token: ${{ORGANIZATION}}:${{NPM_TOKEN}}

Looks like your organization is guidedchoice.

But note this doesn't solve the looping behavior which the original issue is about.

eli-gc commented 1 week ago

@epicstar the README says to use PAT:${{ NPM_TOKEN }} for access tokens. I tried that to no avail.

  # Artifactory private feed using PAT
  artifactory:
    type: nuget-feed
    url: https://artifactory.com/api/nuget/v3/myfeed
    token: PAT:${{ MY_DEPENDABOT_ARTIFACTORY_PAT }}
epicstar commented 3 days ago

Yes, that works for nuget feeds, but the README isn't explicit about how to authenticate on Azure NPM feeds since the authentication isn't merely PAT Token based on the NPM feeds.

And for more info: https://github.com/yarnpkg/berry/issues/316#issuecomment-1378520569

I understand that these are instructions on yarn berry's .yarnrc.yml and not dependabot. I could be wrong.

eli-gc commented 3 days ago

I actually do have that in my .yarnrc.yml, but maybe I need to put it in my dependabot config as well. I'll give that a try. Thanks for the suggestion.

eli-gc commented 3 days ago

Tried it but didn't seem to make a difference. Still just takes forever and times out after an hour.

epicstar commented 3 days ago

Yup, mine ran today and I got the same issue... This time no PRs made.

epicstar commented 3 days ago

bad_dependabot_logs.txt

For people interested in my log file...

rhyskoedijk commented 10 hours ago

Just an update on this, I haven't managed to reproduce the issue yet, but do want to mention that there are known issues reported in dependabot-core around NPM updates stalling and causing timeouts that you might want to contribute to if you believe they are related. See:

This issue is still on my radar to look in to, but there is no obvious or straight forward fix, so progress is slow. I do plan on reducing the verbosity of the logs for non-debug builds, but I am very confident that the size of the logs is not the root cause of the issue or the reason why it takes so long. For context, I have projects that generate logs of around 300K lines (50mb+) and they complete well under 1 hour, so I assume this is an issue within the NPM updater, not the logging mechenism.