pdns icon indicating copy to clipboard operation
pdns copied to clipboard
verified publisher icon PowerDNS

Logging of API is not sufficient for troubleshooting

Open Revertron opened this issue 3 years ago • 9 comments

  • Program: Authoritative
  • Issue type: Bug report

Short description

In about a week I've noticed, that Let's Encrypt certificates can't be updated. They have DNS authentication through PowerDNS API. Now I'm trying to investigate the problem, but the logging is insufficient. I've set even loglevel=100, but all I get in the log:

Oct 10 12:34:08 powerdns pdns_server[9935]: [webserver] 198c485b-0582-4fdd-88a3-1d80abddb75d Handling request "/api/v1/servers/localhost/zones/alfis.name"
Oct 10 12:34:08 powerdns pdns_server[9935]: gmysql Connection successful. Connected to database 'powerdns' on 'localhost'.
Oct 10 12:34:08 powerdns pdns_server[9935]: [webserver] 198c485b-0582-4fdd-88a3-1d80abddb75d Error result for "/api/v1/servers/localhost/zones/alfis.name": 500
Oct 10 12:34:08 powerdns pdns_server[9935]: [webserver] 198c485b-0582-4fdd-88a3-1d80abddb75d 192.168.44.70:47122 "GET /api/v1/servers/localhost/zones/alfis.name HTTP/1.1" 500 139

I can't even try to investigate what causes this 500 error. MySQL server is okay, connection to it is okay too as you can see, but there is no data what is going wrong.

Environment

  • Operating system: Debian 11.5
  • Software version: 4.8.0~alpha0+master.457.gf1d64c59a-1pdns.bullseye amd64
  • Software source: PowerDNS repository

Steps to reproduce

  1. Install PowerDNS Authoritative server on Debian 11
  2. Have some troubles that causes error 500 in the API
  3. See that the problem itself doesn't get printed to the logs

Expected behaviour

I would expect some clues to what exactly was wrong with the request processing, what are the errors.

Actual behaviour

There is no cause of the error:

Oct 10 12:34:08 powerdns pdns_server[9935]: [webserver] 198c485b-0582-4fdd-88a3-1d80abddb75d Handling request "/api/v1/servers/localhost/zones/alfis.name"
Oct 10 12:34:08 powerdns pdns_server[9935]: gmysql Connection successful. Connected to database 'powerdns' on 'localhost'.
Oct 10 12:34:08 powerdns pdns_server[9935]: [webserver] 198c485b-0582-4fdd-88a3-1d80abddb75d Error result for "/api/v1/servers/localhost/zones/alfis.name": 500
Oct 10 12:34:08 powerdns pdns_server[9935]: [webserver] 198c485b-0582-4fdd-88a3-1d80abddb75d 192.168.44.70:47122 "GET /api/v1/servers/localhost/zones/alfis.name HTTP/1.1" 500 139

Other information

Revertron avatar Oct 10 '22 10:10 Revertron

Did you see the webserver-loglevel setting? You can set it to detailed.

Habbie avatar Oct 10 '22 10:10 Habbie

Tried it right now. No clues to what is going on:

Oct 10 13:20:17 powerdns pdns_server[16213]: gmysql Connection successful. Connected to database 'powerdns' on 'localhost'.
Oct 10 13:20:17 powerdns pdns_server[16213]: [webserver] 8e568230-bec0-41a0-8bba-0856f61c79f8 Error result for "/api/v1/servers/localhost/zones/alfis.name": 500
Oct 10 13:20:17 powerdns pdns_server[16213]: [webserver] 8e568230-bec0-41a0-8bba-0856f61c79f8 Response details:
Oct 10 13:20:17 powerdns pdns_server[16213]: [webserver] 8e568230-bec0-41a0-8bba-0856f61c79f8  Headers:
Oct 10 13:20:17 powerdns pdns_server[16213]: [webserver] 8e568230-bec0-41a0-8bba-0856f61c79f8   Connection: close
Oct 10 13:20:17 powerdns pdns_server[16213]: [webserver] 8e568230-bec0-41a0-8bba-0856f61c79f8   Content-Length: 21
Oct 10 13:20:17 powerdns pdns_server[16213]: [webserver] 8e568230-bec0-41a0-8bba-0856f61c79f8   Content-Type: text/plain; charset=utf-8
Oct 10 13:20:17 powerdns pdns_server[16213]: [webserver] 8e568230-bec0-41a0-8bba-0856f61c79f8  Full body:
Oct 10 13:20:17 powerdns pdns_server[16213]: [webserver] 8e568230-bec0-41a0-8bba-0856f61c79f8   Internal Server Error
Oct 10 13:20:17 powerdns pdns_server[16213]: [webserver] 8e568230-bec0-41a0-8bba-0856f61c79f8 192.168.44.70:52302 "GET /api/v1/servers/localhost/zones/alfis.name HTTP/1.1" 500 139

Revertron avatar Oct 10 '22 11:10 Revertron

Is the request not logged?

Habbie avatar Oct 31 '22 08:10 Habbie

Is the request not logged?

Sorry - GET generally does not have a body.

I've done some API work recently and I also noticed we should log better.

Habbie avatar Nov 28 '22 13:11 Habbie

Running into this same issue. Is there any way to get around this temporarily?

nikrozman21 avatar Dec 03 '22 18:12 nikrozman21

Same issue here.

The only logs i get is :

Dec 29 16:10:56 bco-pdns-test pdns_server[933]: [webserver] 6866a7d0-97f3-4f0a-a03b-7fc4d0202dbf  Headers:
Dec 29 16:10:56 bco-pdns-test pdns_server[933]: [webserver] 6866a7d0-97f3-4f0a-a03b-7fc4d0202dbf   accept: */*
Dec 29 16:10:56 bco-pdns-test pdns_server[933]: [webserver] 6866a7d0-97f3-4f0a-a03b-7fc4d0202dbf   accept-encoding: gzip, deflate
Dec 29 16:10:56 bco-pdns-test pdns_server[933]: [webserver] 6866a7d0-97f3-4f0a-a03b-7fc4d0202dbf   connection: keep-alive
Dec 29 16:10:56 bco-pdns-test pdns_server[933]: [webserver] 6866a7d0-97f3-4f0a-a03b-7fc4d0202dbf   host: xxx:8082
Dec 29 16:10:56 bco-pdns-test pdns_server[933]: [webserver] 6866a7d0-97f3-4f0a-a03b-7fc4d0202dbf   user-agent: python-requests/2.24.0
Dec 29 16:10:56 bco-pdns-test pdns_server[933]: [webserver] 6866a7d0-97f3-4f0a-a03b-7fc4d0202dbf   x-api-key: test
Dec 29 16:10:56 bco-pdns-test pdns_server[933]: [webserver] 6866a7d0-97f3-4f0a-a03b-7fc4d0202dbf  No body
Dec 29 16:10:56 bco-pdns-test pdns_server[933]: [webserver] 6866a7d0-97f3-4f0a-a03b-7fc4d0202dbf Handling request "/api/v1/servers/localhost/zones/xxx.fr"
Dec 29 16:10:56 bco-pdns-test pdns_server[933]: gmysql Connection successful. Connected to database 'powerdnsdb' on 'xxx'.
Dec 29 16:10:56 bco-pdns-test pdns_server[933]: [webserver] 6866a7d0-97f3-4f0a-a03b-7fc4d0202dbf Error result for "/api/v1/servers/localhost/zones/xxx.fr": 500
Dec 29 16:10:56 bco-pdns-test pdns_server[933]: [webserver] 6866a7d0-97f3-4f0a-a03b-7fc4d0202dbf Response details:
Dec 29 16:10:56 bco-pdns-test pdns_server[933]: [webserver] 6866a7d0-97f3-4f0a-a03b-7fc4d0202dbf  Headers:
Dec 29 16:10:56 bco-pdns-test pdns_server[933]: [webserver] 6866a7d0-97f3-4f0a-a03b-7fc4d0202dbf   Connection: close
Dec 29 16:10:56 bco-pdns-test pdns_server[933]: [webserver] 6866a7d0-97f3-4f0a-a03b-7fc4d0202dbf   Content-Length: 21
Dec 29 16:10:56 bco-pdns-test pdns_server[933]: [webserver] 6866a7d0-97f3-4f0a-a03b-7fc4d0202dbf   Content-Type: text/plain; charset=utf-8
Dec 29 16:10:56 bco-pdns-test pdns_server[933]: [webserver] 6866a7d0-97f3-4f0a-a03b-7fc4d0202dbf  Full body:
Dec 29 16:10:56 bco-pdns-test pdns_server[933]: [webserver] 6866a7d0-97f3-4f0a-a03b-7fc4d0202dbf   Internal Server Error
Dec 29 16:10:56 bco-pdns-test pdns_server[933]: [webserver] 6866a7d0-97f3-4f0a-a03b-7fc4d0202dbf xxx:55738 "GET /api/v1/servers/localhost/zones/xxx.fr HTTP/1.1" 500 139 ```

BTW, it's look more to be a bug rather than an improvement ? These zones was working before to upgrade to 4.7.3. Rollback to 4.6.4 makes API working.

Baptistecottey avatar Dec 29 '22 15:12 Baptistecottey

Did you follow the upgrade guide? It mentions a schema update. https://docs.powerdns.com/authoritative/upgrading.html

Also:

Our GitHub issue tracker is for bug reports and feature requests. Your question looks like a support question. Support questions are handled in our other online communities: IRC and our mailing lists. Please see https://www.powerdns.com/opensource.html for information about those.

omoerbeek avatar Dec 29 '22 15:12 omoerbeek

Did you follow the upgrade guide? It mentions a schema update. https://docs.powerdns.com/authoritative/upgrading.html

Also:

Our GitHub issue tracker is for bug reports and feature requests. Your question looks like a support question. Support questions are handled in our other online communities: IRC and our mailing lists. Please see https://www.powerdns.com/opensource.html for information about those.

You're right. Didn't notice the upgrade guide. I juste read the changelog and didn't notice this change.

Baptistecottey avatar Dec 30 '22 09:12 Baptistecottey

Believed to be fixed by #16040, although there might still be cases for which error 500 will still be returned.

miodvallat avatar Sep 12 '25 11:09 miodvallat