Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Reccuring error in my logs "unexpected status code | status_code=403" #8077

Open
johackim opened this issue Nov 19, 2022 · 18 comments
Open

Reccuring error in my logs "unexpected status code | status_code=403" #8077

johackim opened this issue Nov 19, 2022 · 18 comments

Comments

@johackim
Copy link

johackim commented Nov 19, 2022

Bug description

I have a reccuring error in my logs every minutes :

ERR github.com/portainer/portainer/api@v0.0.0-20221011053128-b0938875dc5c/http/client/client.go:94 > unexpected status code | status_code=403

Expected behavior

No errors.

Portainer Logs

ERR github.com/portainer/portainer/api@v0.0.0-20221011053128-b0938875dc5c/http/client/client.go:94 > unexpected status code | status_code=403

Steps to reproduce the issue:

DOMAIN=portainer.example.com IMAGE=portainer/portainer-ee docker stack deploy -c <(curl -so - https://raw.githubusercontent.com/ethibox/awesome-stacks/master/stacks/portainer.yml) portainer

Technical details:

  • Portainer version: portainer/portainer-ee:2.16.1-alpine
  • Docker version (managed by Portainer): 20.10.12
  • Platform (windows/linux): linux
  • Browser: chromium
  • Use Case (delete as appropriate): Using Portainer in a Commercial setup.
  • Have you reviewed our technical documentation and knowledge base? Yes
@tamarahenson
Copy link

@johackim

Thank you for the information. I am going to further investigate.

Interim, an HTTP 403 response code means that a client is forbidden from accessing a valid URL. The server understands the request, but it can't fulfill the request because of client-side issues.

Can you post log snippets from both Portainer Server and Agent for review? What type of hardware is your Swarm cluster running on?

Thanks!

@johackim
Copy link
Author

johackim commented Nov 19, 2022

Hello @tamarahenson,

Here my portainer logs :

portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:11PM INF main.go:582 > encryption key file not present | filename=portainer
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:11PM INF main.go:601 > proceeding without encryption key |
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:11PM INF github.com/portainer/portainer-ee/api/database/boltdb/db.go:125 > loading PortainerDB | filename=portainer.db
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:11PM INF github.com/portainer/portainer-ee/api/datastore/backup.go:151 > creating DB backup |
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:11PM INF github.com/portainer/portainer-ee/api/datastore/backup.go:74 > copying DB file | from=/data/portainer.db to=/data/backups/EE/portainer.db.071.20221119211114
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:11PM INF github.com/portainer/portainer-ee/api/database/boltdb/db.go:125 > loading PortainerDB | filename=portainer.db
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:11PM INF github.com/portainer/portainer-ee/api/datastore/migrate_data.go:121 > migrating database | migrator_version=71 portaineree_db_version=71
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:11PM INF github.com/portainer/portainer-ee/api/datastore/migrate_data.go:139 > migrator_edition=EE portainer_edition=EE store_edition=EE
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:11PM INF github.com/portainer/portainer-ee/api/cloud/cluster_setup.go:77 > starting cloud cluster setup service |
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:11PM INF main.go:558 > instance already has defined environments, skipping the environment defined via CLI |
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 21:11:14 server: Reverse tunnelling enabled
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 21:11:14 server: Fingerprint de:48:e6:0a:1d:f4:0b:b7:fe:97:ac:a5:bc:8f:1b:d1
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 21:11:14 server: Listening on 0.0.0.0:8000...
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:11PM INF main.go:887 > starting Portainer | build_number=24946 go_version=1.19.3 image_tag=linux-amd64-2.16.1 nodejs_version=18.12.1 version=2.16.0 webpack_version=5.65.0 yarn_version=1.22.19
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:11PM INF github.com/portainer/portainer-ee/api/http/server.go:392 > starting HTTPS server | bind_address=:9443
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:11PM INF github.com/portainer/portainer-ee/api/http/server.go:377 > starting HTTP server | bind_address=:9000
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:26PM ERR github.com/portainer/portainer/api@v0.0.0-20221011053128-b0938875dc5c/http/client/client.go:94 > unexpected status code | status_code=403
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:27PM ERR github.com/portainer/portainer/api@v0.0.0-20221011053128-b0938875dc5c/http/client/client.go:94 > unexpected status code | status_code=403
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:27PM ERR github.com/portainer/portainer/api@v0.0.0-20221011053128-b0938875dc5c/http/client/client.go:94 > unexpected status code | status_code=403
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:27PM ERR github.com/portainer/portainer/api@v0.0.0-20221011053128-b0938875dc5c/http/client/client.go:94 > unexpected status code | status_code=403
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:27PM ERR github.com/portainer/portainer/api@v0.0.0-20221011053128-b0938875dc5c/http/client/client.go:94 > unexpected status code | status_code=403
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:27PM ERR github.com/portainer/portainer/api@v0.0.0-20221011053128-b0938875dc5c/http/client/client.go:94 > unexpected status code | status_code=403
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:28PM ERR github.com/portainer/portainer/api@v0.0.0-20221011053128-b0938875dc5c/http/client/client.go:94 > unexpected status code | status_code=403
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:28PM ERR github.com/portainer/portainer/api@v0.0.0-20221011053128-b0938875dc5c/http/client/client.go:94 > unexpected status code | status_code=403
portainer_portainer.1.p2gsg0vu6k9s@frhb65918ds    | 2022/11/19 09:28PM ERR github.com/portainer/portainer/api@v0.0.0-20221011053128-b0938875dc5c/http/client/client.go:94 > unexpected status code | status_code=403

Here my agent logs :

portainer_agent.0.6euwud0ahg91@frhb65918ds    | 2022/11/19 09:09PM INF github.com/portainer/agent/cmd/agent/main.go:79 > agent running on Docker platform |
portainer_agent.0.6euwud0ahg91@frhb65918ds    | 2022/11/19 09:09PM INF github.com/portainer/agent/cmd/agent/main.go:94 > agent running on a Swarm cluster node. Running in cluster mode |
portainer_agent.0.6euwud0ahg91@frhb65918ds    | 2022/11/19 21:09:18 [INFO] serf: EventMemberJoin: frhb65918ds-da6a668853f7 10.0.193.3
portainer_agent.0.6euwud0ahg91@frhb65918ds    | 2022/11/19 09:09PM INF github.com/portainer/agent/edge/registry/server.go:101 > starting registry credential server |
portainer_agent.0.6euwud0ahg91@frhb65918ds    | 2022/11/19 09:09PM INF github.com/portainer/agent/http/server.go:100 > starting Agent API server | api_version=2.16.1 server_addr=0.0.0.0 server_port=9001 use_tls=true
portainer_agent.0.6euwud0ahg91@frhb65918ds    | 2022/11/19 21:25:56 http: TLS handshake error from 10.0.193.6:53124: EOF
portainer_agent.0.6euwud0ahg91@frhb65918ds    | 2022/11/19 21:26:10 http: TLS handshake error from 10.0.193.6:53118: EOF
portainer_agent.0.6euwud0ahg91@frhb65918ds    | 2022/11/19 21:29:30 http: TLS handshake error from 10.0.193.6:59420: EOF
portainer_agent.0.6euwud0ahg91@frhb65918ds    | 2022/11/19 21:31:12 http: TLS handshake error from 10.0.193.6:38986: read tcp 10.0.193.3:9001->10.0.193.6:38986: read: connection reset by peer

Here my hardware config :

  • CPU : AMD Ryzen 9 3900X
  • RAM : 128Go DDR4
  • Operating System: Linux Ubuntu 20.04 - 64Bits
  • RAID Hard Drives: 1x960 Go SSD NVMe M.2
  • GPU Card: GeForce GT710 1Go
  • Docker Swarm

@tamarahenson
Copy link

tamarahenson commented Nov 23, 2022

@johackim

I accidentally reproduced your issue in my cluster. I am trying to connect to an environment via an agent and am receiving context deadline exceeded toasts in the UI when this happens:

Screen Shot 2022-11-22 at 6 10 52 PM

2022/11/23 02:06AM ERR github.com/portainer/portainer/api@v0.0.0-20221011053128-b0938875dc5c/http/client/client.go:94 > unexpected status code | status_code=403
2022/11/23 02:06AM ERR github.com/portainer/portainer/api@v0.0.0-20221011053128-b0938875dc5c/http/client/client.go:94 > unexpected status code | status_code=403
2022/11/23 02:07AM ERR github.com/portainer/portainer/api@v0.0.0-20221011053128-b0938875dc5c/http/client/client.go:94 > unexpected status code | status_code=403

In my case, I had an environment connected to a Portainer server via an Agent. I tried connecting that same environment to a different Portainer server.

Thanks!

@hhromic
Copy link
Contributor

hhromic commented Feb 8, 2023

Hi, I just upgraded from Portainer 2.11.1 to 2.16.2 and experiencing the same issue. The log messages are the same as reported by johackim in this issue. We have 10 Docker Swarm environments.

@My-Random-Thoughts
Copy link

Still happening on 2.19.1.

ERR github.com/portainer/portainer/api@v0.0.0-20230809235847-187ec2aa9a7b/http/client/client.go:92 > unexpected status code | status_code=403

@hsu1943
Copy link

hsu1943 commented Jan 8, 2024

starting Portainer | build_number=35428 go_version=1.20.5 image_tag=linux-amd64-2.19.4 nodejs_version=18.19.0 version=2.19.4 webpack_version=5.88.1 yarn_version=1.22.21

2024/01/08 04:13PM ERR github.com/portainer/portainer/api/http/client/client.go:92 > unexpected status code | status_code=403

@IHappyDayI
Copy link

Same here. I get the error message every time the Portainer browser tab gets focus or loses focus.

@Xav-Pe
Copy link

Xav-Pe commented Feb 20, 2024

Problem still existing.

2024/02/20 12:05PM INF github.com/portainer/portainer-ee/api/docker/images/digest.go:58 > No environment registry credentials found, using anonymous access | image up to date indicator=lscr.io/linuxserver/calibre-web:latest
2024/02/20 12:05PM INF github.com/portainer/portainer-ee/api/docker/images/digest.go:58 > No environment registry credentials found, using anonymous access | image up to date indicator=lscr.io/linuxserver/plex:latest
2024/02/20 12:05PM INF github.com/portainer/portainer-ee/api/docker/images/digest.go:58 > No environment registry credentials found, using anonymous access | image up to date indicator=ghcr.io/linuxserver/tautulli:latest
2024/02/20 12:05PM INF github.com/portainer/portainer-ee/api/docker/images/digest.go:58 > No environment registry credentials found, using anonymous access | image up to date indicator=ghcr.io/home-assistant/home-assistant:stable
2024/02/20 12:23PM ERR github.com/portainer/portainer/api@v0.0.0-20231018222543-8b7436e4d084/http/client/client.go:92 > unexpected status code | status_code=403
2024/02/20 12:23PM ERR github.com/portainer/portainer/api@v0.0.0-20231018222543-8b7436e4d084/http/client/client.go:92 > unexpected status code | status_code=403
2024/02/20 12:23PM ERR github.com/portainer/portainer/api@v0.0.0-20231018222543-8b7436e4d084/http/client/client.go:92 > unexpected status code | status_code=403
2024/02/20 12:25PM ERR github.com/portainer/portainer/api@v0.0.0-20231018222543-8b7436e4d084/http/client/client.go:92 > unexpected status code | status_code=403
2024/02/20 12:25PM ERR github.com/portainer/portainer/api@v0.0.0-20231018222543-8b7436e4d084/http/client/client.go:92 > 

[repeating indefinitely]

@hhromic
Copy link
Contributor

hhromic commented Mar 19, 2024

Sadly, this issue is still present in the recently released Portainer 2.20.0.

2024/03/19 11:37AM ERR github.com/portainer/portainer/api/http/client/client.go:92 > unexpected status code | status_code=403
2024/03/19 11:37AM ERR github.com/portainer/portainer/api/http/client/client.go:92 > unexpected status code | status_code=403
2024/03/19 11:37AM ERR github.com/portainer/portainer/api/http/client/client.go:92 > unexpected status code | status_code=403
2024/03/19 11:37AM ERR github.com/portainer/portainer/api/http/client/client.go:92 > unexpected status code | status_code=403
2024/03/19 11:37AM ERR github.com/portainer/portainer/api/http/client/client.go:92 > unexpected status code | status_code=403
2024/03/19 11:37AM ERR github.com/portainer/portainer/api/http/client/client.go:92 > unexpected status code | status_code=403
2024/03/19 11:38AM ERR github.com/portainer/portainer/api/http/client/client.go:92 > unexpected status code | status_code=403
2024/03/19 11:38AM ERR github.com/portainer/portainer/api/http/client/client.go:92 > unexpected status code | status_code=403
2024/03/19 11:38AM ERR github.com/portainer/portainer/api/http/client/client.go:92 > unexpected status code | status_code=403
2024/03/19 11:38AM ERR github.com/portainer/portainer/api/http/client/client.go:92 > unexpected status code | status_code=403
2024/03/19 11:38AM ERR github.com/portainer/portainer/api/http/client/client.go:92 > unexpected status code | status_code=403

@wsw70
Copy link

wsw70 commented Mar 29, 2024

Sadly, this issue is still present in the recently released Portainer 2.20.0.

I confirm, I was about to file the same bug.

I read the thread above but I am not sure whether there is anything tangible about that bug (whether it is a problem (I do not see any), is there a workaround (if needed), or how to silence it)

@needsmoresalt
Copy link

Sadly, this issue is still present in the recently released Portainer 2.20.0.

I confirm, I was about to file the same bug.

I read the thread above but I am not sure whether there is anything tangible about that bug (whether it is a problem (I do not see any), is there a workaround (if needed), or how to silence it)

It was the same on my end.

2024/04/24 06:50AM ERR github.com/portainer/portainer/api/http/client/client.go:92 > unexpected status code | status_code=403

multiple times from the interval 6:18 am to 6:50 am

I upgraded to 2.20.1 and it fixed the problem. (idk if it stopped cause i updated or if it just stopped outright)

@hhromic
Copy link
Contributor

hhromic commented Apr 25, 2024

I can confirm that this problem is still present in Portainer 2.20.1 😢.

However, I finally found the cause of the issue after modifying Portainer to log the URL in addition to the status code.

2024/04/25 10:03PM ERR github.com/portainer/portainer/api/http/client/client.go:92 > unexpected status code | status_code=403 url=https://api.github.com/repos/portainer/portainer/releases/latest
2024/04/25 10:03PM ERR github.com/portainer/portainer/api/http/client/client.go:92 > unexpected status code | status_code=403 url=https://api.github.com/repos/portainer/portainer/releases/latest
2024/04/25 10:03PM ERR github.com/portainer/portainer/api/http/client/client.go:92 > unexpected status code | status_code=403 url=https://api.github.com/repos/portainer/portainer/releases/latest

As it can be seen there, the URL that causes the sporadic 403 errors is:

https://api.github.com/repos/portainer/portainer/releases/latest

This URL is called by Portainer itself to check if there are newer versions available in GitHub.

Why does it return 403? Because Portainer is calling this URL very frequently, and GitHub is applying rate limiting. If you open a browser with that URL after seeing those 403 errors, you will get the error from GitHub:

{"message":"API rate limit exceeded for X.X.X.X. (But here's the good news: Authenticated requests get a higher rate limit. Check out the documentation for more details.)","documentation_url":"https://docs.github.com/rest/overview/resources-in-the-rest-api#rate-limiting"}

Portainer seems to be calling this URL when you switch windows or tabs in the browser, as you can see this error much more frequently when you do so. This is because the Portainer UI triggers a version check everytime the window/tab regains focus (not a good idea in my opinion and should be considered a bug).

The reason this error does not appear always is because it depends on the state of rate-limiting from Github for your current public IP address. If you leave Portainer for a bit (enough for the rate limiting to be lifted) you will not see these errors until the rate limit is triggered again.

@jamescarppe (or anyone in Portainer Team) does the above help fixing this quite long standing issue? :)

EDIT: The frequency of calling GitHub API should be fixed, but perhaps it also would be a good idea to add a command-line flag to disable new version checks entirely if desired?

@wsw70
Copy link

wsw70 commented Apr 26, 2024

However, I finally found the cause of the issue (...)

Wow, this is impressive @hhromic - it is not common to see such good bug reports. I will have to get better at digging down

@hhromic
Copy link
Contributor

hhromic commented Apr 27, 2024

Looks like the Portainer team already fixed this in #11679 some days ago (even before my investigation above).
And looks like the fix will be included in the next 2.20.x version and up.

Looking forward to see this annoying bug gone :)

@jamescarppe
Copy link
Member

Yep, someone beat you to the root cause in #11596 so I raised it internally, and the team have a fix in place for our next release. The fix reduces the check frequency to once every 24 hours (except when hard refreshing in the browser), which should mean simply using Portainer should no longer push the rate limit up.

Once the release including this is out we'll loop back to this (and the other) thread to confirm this is fixed, and if so we'll close the issue(s) off.

@jamescarppe
Copy link
Member

We've just released 2.20.3 which includes a fix for the overzealous update checks - are you able to test and confirm whether this has cleared up the log messages?

@Feriman22
Copy link

@jamescarppe in my case these lines are still there:

05/29/2024
08:15:32 AM
2024/05/29 06:15AM INF github.com/portainer/portainer-ee/api/docker/images/digest.go:58 > No environment registry credentials found, using anonymous access | image up to date indicator=docker.io/library/alpine:latest
05/29/2024
08:15:32 AM
2024/05/29 06:15AM INF github.com/portainer/portainer-ee/api/docker/images/digest.go:58 > No environment registry credentials found, using anonymous access | image up to date indicator=docker.io/library/postgres:13
05/29/2024
08:15:32 AM
2024/05/29 06:15AM INF github.com/portainer/portainer-ee/api/docker/images/digest.go:58 > No environment registry credentials found, using anonymous access | image up to date indicator=docker.io/library/nginx:latest
05/29/2024
08:15:32 AM
2024/05/29 06:15AM INF github.com/portainer/portainer-ee/api/docker/images/digest.go:58 > No environment registry credentials found, using anonymous access | image up to date indicator=docker.io/library/postgres:13
05/29/2024
08:15:57 AM
2024/05/29 06:15AM INF github.com/portainer/portainer-ee/api/docker/images/digest.go:58 > No environment registry credentials found, using anonymous access | image up to date indicator=docker.io/serjs/go-socks5-proxy:latest

While using Portainer 2.20.3 EE

@jamescarppe
Copy link
Member

That's a different message so will be a different issue. It's informational so nothing you should be concerned with, but I'll flag it with the team as we might not need to be outputting those on regular log levels.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests