search

PowerDNS / pdns

PowerDNS Authoritative, PowerDNS Recursor, dnsdist
https://www.powerdns.com/
GNU General Public License v2.0
3.62k stars 903 forks source link

Logging of API is not sufficient for troubleshooting #12079

Open Revertron opened 1 year ago

Revertron commented 1 year ago

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

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

Habbie commented 1 year ago

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

Revertron commented 1 year ago

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
Habbie commented 1 year ago

Is the request not logged?

Habbie commented 1 year ago

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.

nikrozman21 commented 1 year ago

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

Baptistecottey commented 1 year ago

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.
omoerbeek commented 1 year ago

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.

Baptistecottey commented 1 year ago

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.