search

gravitational / teleport

The easiest, and most secure way to access and protect all of your infrastructure.
https://goteleport.com
GNU Affero General Public License v3.0
17.62k stars 1.76k forks source link

AWS RDS Discovery fails with invalid parameter in AWS API Request #17533

Closed sklirg closed 1 year ago

sklirg commented 2 years ago

Expected behavior:

Starting a Teleport Node which runs the db_service for AWS RDS Discovery should work and find databases.

Current behavior:

Starting a Teleport Node with db_service prints a stack trace on boot saying:

teleport[32435]: ERROR REPORT:
teleport[32435]: Original Error: *awserr.requestError InvalidParameterValue: Unrecognized engine name: aurora
teleport[32435]: status code: 400, request id: *snip*
teleport[32435]: Stack Trace:
teleport[32435]: /go/src/github.com/gravitational/teleport/lib/srv/db/cloud/watchers/rds.go:169 github.com/gravitational/teleport/lib/srv/db/cloud/watchers.(*rdsAuroraClustersFetcher)
teleport[32435]: /go/src/github.com/gravitational/teleport/lib/srv/db/cloud/watchers/watcher.go:120 github.com/gravitational/teleport/lib/srv/db/cloud/watchers.(*Watcher).fetchAndSend
teleport[32435]: /go/src/github.com/gravitational/teleport/lib/srv/db/cloud/watchers/watcher.go:104 github.com/gravitational/teleport/lib/srv/db/cloud/watchers.(*Watcher).Start
teleport[32435]: /opt/go/src/runtime/asm_amd64.s:1571 runtime.goexit
teleport[32435]: User Message: InvalidParameterValue: Unrecognized engine name: aurora
teleport[32435]: status code: 400, request id: *snip*] watchers/watcher.go:129

Bug details:

systemd[1]: Stopping Teleport SSH Node Service...
teleport[8981]: 2022-10-18T09:31:54Z INFO [PROC:1]    Got signal "terminated", exiting immediately. pid:8981.1 service/signals.go:83
systemd[1]: Stopped Teleport SSH Node Service.
systemd[1]: Started Teleport SSH Node Service.
teleport[9762]: 2022-10-18T09:31:54Z DEBU [SQLITE]    Connected to: file:%2Fvar%2Flib%2Fteleport%2Fproc%2Fsqlite.db?_busy_timeout=10000&_sync=FULL&_txlock=immediate, poll stream period: 1s lite/lite.go:246
teleport[9762]: 2022-10-18T09:31:54Z DEBU [SQLITE]    journal_mode=delete, synchronous=2, busy_timeout=10000 lite/lite.go:293
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Adding service to supervisor. pid:9762.1 service:readyz.monitor service/supervisor.go:207
teleport[9762]: 2022-10-18T09:31:54Z INFO [PROC:1]    Service diag is creating new listener on 127.0.0.1:3000. pid:9762.1 service/signals.go:212
teleport[9762]: 2022-10-18T09:31:54Z INFO [DIAG:1]    Starting diagnostic service on 127.0.0.1:3000. pid:9762.1 service/service.go:2703
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Adding service to supervisor. pid:9762.1 service:diagnostic.service service/supervisor.go:207
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Adding service to supervisor. pid:9762.1 service:diagnostic.shutdown service/supervisor.go:207
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Adding service to supervisor. pid:9762.1 service:register.node service/supervisor.go:207
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Adding service to supervisor. pid:9762.1 service:ssh.node service/supervisor.go:207
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Adding service to supervisor. pid:9762.1 service:ssh.shutdown service/supervisor.go:207
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Adding service to supervisor. pid:9762.1 service:register.db service/supervisor.go:207
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Adding service to supervisor. pid:9762.1 service:db.init service/supervisor.go:207
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Adding service to supervisor. pid:9762.1 service:common.rotate service/supervisor.go:207
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Adding service to supervisor. pid:9762.1 service:register.instance service/supervisor.go:207
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Adding service to supervisor. pid:9762.1 service:instance.init service/supervisor.go:207
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    No signal pipe to import, must be first Teleport process. pid:9762.1 service/service.go:1113
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Service has started. pid:9762.1 service:readyz.monitor service/supervisor.go:268
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Service has started. pid:9762.1 service:register.db service/supervisor.go:268
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Service has started. pid:9762.1 service:register.node service/supervisor.go:268
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Service has started. pid:9762.1 service:diagnostic.service service/supervisor.go:268
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Service has started. pid:9762.1 service:diagnostic.shutdown service/supervisor.go:268
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Service has started. pid:9762.1 service:db.init service/supervisor.go:268
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Service has started. pid:9762.1 service:common.rotate service/supervisor.go:268
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Service has started. pid:9762.1 service:register.instance service/supervisor.go:268
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Service has started. pid:9762.1 service:instance.init service/supervisor.go:268
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Service has started. pid:9762.1 service:ssh.node service/supervisor.go:268
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Service has started. pid:9762.1 service:ssh.shutdown service/supervisor.go:268
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Connected state: never updated. pid:9762.1 service/connect.go:237
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Connected state: never updated. pid:9762.1 service/connect.go:237
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Connected state: never updated. pid:9762.1 service/connect.go:237
teleport[9762]: 2022-10-18T09:31:54Z INFO [PROC:1]    Connecting to the cluster example-teleport with TLS client certificate. pid:9762.1 service/connect.go:256
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Attempting to connect to Auth Server directly. auth-addrs:[teleport.example.dev:443] pid:9762.1 service/connect.go:1052
teleport[9762]: 2022-10-18T09:31:54Z INFO [PROC:1]    Connecting to the cluster example-teleport with TLS client certificate. pid:9762.1 service/connect.go:256
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Attempting to connect to Auth Server directly. auth-addrs:[teleport.example.dev:443] pid:9762.1 service/connect.go:1052
teleport[9762]: 2022-10-18T09:31:54Z INFO [PROC:1]    Connecting to the cluster example-teleport with TLS client certificate. pid:9762.1 service/connect.go:256
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Attempting to connect to Auth Server directly. auth-addrs:[teleport.example.dev:443] pid:9762.1 service/connect.go:1052
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Failed to connect to Auth Server directly. auth-addrs:[teleport.example.dev:443] pid:9762.1 service/connect.go:1058
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Attempting to discover reverse tunnel address. auth-addrs:[teleport.example.dev:443] pid:9762.1 service/connect.go:1067
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Attempting to connect to Auth Server through tunnel. auth-addrs:[teleport.example.dev:443] pid:9762.1 service/connect.go:1069
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Failed to connect to Auth Server directly. auth-addrs:[teleport.example.dev:443] pid:9762.1 service/connect.go:1058
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Attempting to discover reverse tunnel address. auth-addrs:[teleport.example.dev:443] pid:9762.1 service/connect.go:1067
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Attempting to connect to Auth Server through tunnel. auth-addrs:[teleport.example.dev:443] pid:9762.1 service/connect.go:1069
teleport[9762]: 2022-10-18T09:31:54Z DEBU             Attempting GET teleport.example.dev:443/webapi/find webclient/webclient.go:115
teleport[9762]: 2022-10-18T09:31:54Z DEBU             Attempting GET teleport.example.dev:443/webapi/find webclient/webclient.go:115
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Failed to connect to Auth Server directly. auth-addrs:[teleport.example.dev:443] pid:9762.1 service/connect.go:1058
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Attempting to discover reverse tunnel address. auth-addrs:[teleport.example.dev:443] pid:9762.1 service/connect.go:1067
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Attempting to connect to Auth Server through tunnel. auth-addrs:[teleport.example.dev:443] pid:9762.1 service/connect.go:1069
teleport[9762]: 2022-10-18T09:31:54Z DEBU             Attempting GET teleport.example.dev:443/webapi/find webclient/webclient.go:115
teleport[9762]: 2022-10-18T09:31:54Z DEBU             Attempting GET teleport.example.dev:443/webapi/find webclient/webclient.go:115
teleport[9762]: 2022-10-18T09:31:54Z DEBU             Attempting GET teleport.example.dev:443/webapi/find webclient/webclient.go:115
teleport[9762]: 2022-10-18T09:31:54Z DEBU             Attempting GET teleport.example.dev:443/webapi/find webclient/webclient.go:115
teleport[9762]: 2022-10-18T09:31:54Z DEBU [HTTP:PROX] No proxy set in environment, returning direct dialer. proxy/proxy.go:296
teleport[9762]: 2022-10-18T09:31:54Z DEBU [HTTP:PROX] No proxy set in environment, returning direct dialer. proxy/proxy.go:296
teleport[9762]: 2022-10-18T09:31:54Z DEBU [HTTP:PROX] No proxy set in environment, returning direct dialer. proxy/proxy.go:296
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Connected to Auth Server through tunnel. auth-addrs:[teleport.example.dev:443] pid:9762.1 service/connect.go:1083
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Connected client: Identity(Instance, cert(60270730-6425-493f-b462-ceaaec60fcb3.example-teleport issued by example-teleport:267433341790791834760895412702658808193),trust root(example-teleport:267433341790791834760895412702658808193)) pid:9762.1 service/connect.go:202
teleport[9762]: 2022-10-18T09:31:54Z INFO [PROC:1]    Instance: features loaded from auth server: Kubernetes:true App:true DB:true OIDC:true SAML:true AccessControls:true AdvancedAccessWorkflows:true HSM:true Desktop:true  pid:9762.1 service/connect.go:90
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Broadcasting event. event:InstanceIdentity pid:9762.1 service/supervisor.go:376
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Service is completed and removed. pid:9762.1 service:register.instance service/supervisor.go:245
teleport[9762]: 2022-10-18T09:31:54Z DEBU [INSTANCE:] Received event "InstanceIdentity". pid:9762.1 service/service.go:2089
teleport[9762]: 2022-10-18T09:31:54Z INFO [INSTANCE:] Successfully registered instance client. pid:9762.1 service/service.go:2101
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Broadcasting event. event:InstanceReady pid:9762.1 service/supervisor.go:376
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Service is completed and removed. pid:9762.1 service:instance.init service/supervisor.go:245
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Connected to Auth Server through tunnel. auth-addrs:[teleport.example.dev:443] pid:9762.1 service/connect.go:1083
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Connected client: Identity(Node, cert(60270730-6425-493f-b462-ceaaec60fcb3.example-teleport issued by example-teleport:267433341790791834760895412702658808193),trust root(example-teleport:267433341790791834760895412702658808193)) pid:9762.1 service/connect.go:202
teleport[9762]: 2022-10-18T09:31:54Z INFO [PROC:1]    Node: features loaded from auth server: Kubernetes:true App:true DB:true OIDC:true SAML:true AccessControls:true AdvancedAccessWorkflows:true HSM:true Desktop:true  pid:9762.1 service/connect.go:90
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Broadcasting event. event:SSHIdentity pid:9762.1 service/supervisor.go:376
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Service is completed and removed. pid:9762.1 service:register.node service/supervisor.go:245
teleport[9762]: 2022-10-18T09:31:54Z DEBU [NODE:1]    Received event "SSHIdentity". pid:9762.1 service/service.go:2134
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Creating in-memory backend for [node]. pid:9762.1 service/service.go:1857
teleport[9762]: 2022-10-18T09:31:54Z DEBU             Attempting GET teleport.example.dev:443/webapi/find webclient/webclient.go:115
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Connected to Auth Server through tunnel. auth-addrs:[teleport.example.dev:443] pid:9762.1 service/connect.go:1083
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Connected client: Identity(Db, cert(60270730-6425-493f-b462-ceaaec60fcb3.example-teleport issued by example-teleport:267433341790791834760895412702658808193),trust root(example-teleport:267433341790791834760895412702658808193)) pid:9762.1 service/connect.go:202
teleport[9762]: 2022-10-18T09:31:54Z INFO [PROC:1]    Db: features loaded from auth server: Kubernetes:true App:true DB:true OIDC:true SAML:true AccessControls:true AdvancedAccessWorkflows:true HSM:true Desktop:true  pid:9762.1 service/connect.go:90
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Broadcasting event. event:DatabasesIdentity pid:9762.1 service/supervisor.go:376
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Service is completed and removed. pid:9762.1 service:register.db service/supervisor.go:245
teleport[9762]: 2022-10-18T09:31:54Z DEBU [DB:SERVIC] Received event "DatabasesIdentity". pid:9762.1 service/db.go:58
teleport[9762]: 2022-10-18T09:31:54Z DEBU [PROC:1]    Creating in-memory backend for [db:service]. pid:9762.1 service/service.go:1857
teleport[9762]: 2022-10-18T09:31:54Z DEBU [HTTP:PROX] No proxy set in environment, returning direct dialer. proxy/proxy.go:296
teleport[9762]: 2022-10-18T09:31:54Z DEBU             Attempting GET teleport.example.dev:443/webapi/find webclient/webclient.go:115
teleport[9762]: 2022-10-18T09:31:54Z DEBU [HTTP:PROX] No proxy set in environment, returning direct dialer. proxy/proxy.go:296
teleport[9762]: 2022-10-18T09:31:54Z INFO [NODE:1:CA] Cache "node" first init succeeded. cache/cache.go:725
teleport[9762]: 2022-10-18T09:31:54Z DEBU [BPF]       Enhanced session recording is not enabled, skipping. bpf/bpf.go:127
teleport[9762]: 2022-10-18T09:31:54Z DEBU [RESTRICTE] Restricted session is not enabled, skipping. restrictedsession/restricted.go:95
teleport[9762]: 2022-10-18T09:31:54Z DEBU [NODE:1]    Starting watch. pid:9762.1 resource-kind:lock services/watcher.go:183
teleport[9762]: 2022-10-18T09:31:54Z DEBU [SSH:NODE]  Supported ciphers: ["aes128-gcm@openssh.com" "chacha20-poly1305@openssh.com" "aes128-ctr" "aes192-ctr" "aes256-ctr"]. sshutils/server.go:221
teleport[9762]: 2022-10-18T09:31:55Z DEBU [SSH:NODE]  Supported KEX algorithms: ["curve25519-sha256" "curve25519-sha256@libssh.org" "ecdh-sha2-nistp256" "ecdh-sha2-nistp384" "ecdh-sha2-nistp521" "diffie-hellman-group14-sha256"]. sshutils/server.go:231
teleport[9762]: 2022-10-18T09:31:55Z DEBU [SSH:NODE]  Supported MAC algorithms: ["hmac-sha2-256-etm@openssh.com" "hmac-sha2-256"]. sshutils/server.go:241
teleport[9762]: 2022-10-18T09:31:55Z INFO [DB:SERVIC] Cache "db" first init succeeded. cache/cache.go:725
teleport[9762]: 2022-10-18T09:31:55Z INFO [NODE]      debug -> starting control-stream based heartbeat. regular/sshserver.go:802
teleport[9762]: 2022-10-18T09:31:55Z INFO [AUDIT:1]   Creating directory /var/lib/teleport/log. pid:9762.1 service/service.go:2452
teleport[9762]: 2022-10-18T09:31:55Z INFO [AUDIT:1]   Setting directory /var/lib/teleport/log owner to 0:4. pid:9762.1 service/service.go:2461
teleport[9762]: 2022-10-18T09:31:55Z INFO [AUDIT:1]   Creating directory /var/lib/teleport/log/upload. pid:9762.1 service/service.go:2452
teleport[9762]: 2022-10-18T09:31:55Z INFO [AUDIT:1]   Setting directory /var/lib/teleport/log/upload owner to 0:4. pid:9762.1 service/service.go:2461
teleport[9762]: 2022-10-18T09:31:55Z INFO [AUDIT:1]   Creating directory /var/lib/teleport/log/upload/streaming. pid:9762.1 service/service.go:2452
teleport[9762]: 2022-10-18T09:31:55Z INFO [AUDIT:1]   Setting directory /var/lib/teleport/log/upload/streaming owner to 0:4. pid:9762.1 service/service.go:2461
teleport[9762]: 2022-10-18T09:31:55Z INFO [AUDIT:1]   Creating directory /var/lib/teleport/log/upload/streaming/default. pid:9762.1 service/service.go:2452
teleport[9762]: 2022-10-18T09:31:55Z INFO [AUDIT:1]   Setting directory /var/lib/teleport/log/upload/streaming/default owner to 0:4. pid:9762.1 service/service.go:2461
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Adding service to supervisor. pid:9762.1 service:fileuploader.service service/supervisor.go:207
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Adding service to supervisor. pid:9762.1 service:fileuploader.shutdown service/supervisor.go:207
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Adding service to supervisor. pid:9762.1 service:fileuploadcompleter.service service/supervisor.go:207
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Adding service to supervisor. pid:9762.1 service:fileuploadcompleter.shutdown service/supervisor.go:207
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROXY:AGE] Starting agent pool 60270730-6425-493f-b462-ceaaec60fcb3.example-teleport.example-teleport... cluster:example-teleport reversetunnel/agentpool.go:240
teleport[9762]: 2022-10-18T09:31:55Z INFO [NODE:1]    Service is starting in tunnel mode. pid:9762.1 service/service.go:2363
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Broadcasting event. event:NodeReady pid:9762.1 service/supervisor.go:376
teleport[9762]: 2022-10-18T09:31:55Z INFO [AUDIT:1]   Creating directory /var/lib/teleport/log. pid:9762.1 service/service.go:2452
teleport[9762]: 2022-10-18T09:31:55Z INFO [AUDIT:1]   Setting directory /var/lib/teleport/log owner to 0:4. pid:9762.1 service/service.go:2461
teleport[9762]: 2022-10-18T09:31:55Z INFO [AUDIT:1]   Creating directory /var/lib/teleport/log/upload. pid:9762.1 service/service.go:2452
teleport[9762]: 2022-10-18T09:31:55Z INFO [AUDIT:1]   Setting directory /var/lib/teleport/log/upload owner to 0:4. pid:9762.1 service/service.go:2461
teleport[9762]: 2022-10-18T09:31:55Z INFO [AUDIT:1]   Creating directory /var/lib/teleport/log/upload/streaming. pid:9762.1 service/service.go:2452
teleport[9762]: 2022-10-18T09:31:55Z INFO [AUDIT:1]   Setting directory /var/lib/teleport/log/upload/streaming owner to 0:4. pid:9762.1 service/service.go:2461
teleport[9762]: 2022-10-18T09:31:55Z INFO [AUDIT:1]   Creating directory /var/lib/teleport/log/upload/streaming/default. pid:9762.1 service/service.go:2452
teleport[9762]: 2022-10-18T09:31:55Z INFO [AUDIT:1]   Setting directory /var/lib/teleport/log/upload/streaming/default owner to 0:4. pid:9762.1 service/service.go:2461
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Adding service to supervisor. pid:9762.1 service:fileuploader.service service/supervisor.go:207
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Adding service to supervisor. pid:9762.1 service:fileuploader.shutdown service/supervisor.go:207
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Adding service to supervisor. pid:9762.1 service:fileuploadcompleter.service service/supervisor.go:207
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Adding service to supervisor. pid:9762.1 service:fileuploadcompleter.shutdown service/supervisor.go:207
teleport[9762]: 2022-10-18T09:31:55Z DEBU [DB:SERVIC] Starting database resource watcher. db/watcher.go:71
teleport[9762]: 2022-10-18T09:31:55Z DEBU             Initializing AWS session for region REGION. common/cloud.go:223
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROXY:AGE] Starting agent pool 60270730-6425-493f-b462-ceaaec60fcb3.example-teleport.example-teleport... cluster:example-teleport reversetunnel/agentpool.go:240
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Adding service to supervisor. pid:9762.1 service:db.stop service/supervisor.go:207
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Broadcasting event. event:DatabasesReady pid:9762.1 service/supervisor.go:376
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Broadcasting mapped event. in:DatabasesReady out:EventMapping(in=[InstanceReady NodeReady DatabasesReady], out=TeleportReady) pid:9762.1 service/supervisor.go:401
teleport[9762]: 2022-10-18T09:31:55Z INFO [DB:SERVIC] Database service has successfully started: []. pid:9762.1 service/db.go:283
teleport[9762]: 2022-10-18T09:31:55Z INFO [PROC:1]    The new service has started successfully. Starting syncing rotation status with period 10m0s. pid:9762.1 service/connect.go:671
teleport[9762]: 2022-10-18T09:31:55Z DEBU             Attempting GET teleport.example.dev:443/webapi/find webclient/webclient.go:115
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Service has started. pid:9762.1 service:fileuploader.service service/supervisor.go:268
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Service has started. pid:9762.1 service:fileuploader.shutdown service/supervisor.go:268
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Service has started. pid:9762.1 service:fileuploadcompleter.service service/supervisor.go:268
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Service has started. pid:9762.1 service:fileuploadcompleter.shutdown service/supervisor.go:268
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Service has started. pid:9762.1 service:fileuploader.service service/supervisor.go:268
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Service has started. pid:9762.1 service:fileuploader.shutdown service/supervisor.go:268
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Service has started. pid:9762.1 service:fileuploadcompleter.service service/supervisor.go:268
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Service has started. pid:9762.1 service:fileuploadcompleter.shutdown service/supervisor.go:268
teleport[9762]: 2022-10-18T09:31:55Z DEBU [DB:SERVIC] Starting watch. pid:9762.1 resource-kind:lock services/watcher.go:183
teleport[9762]: 2022-10-18T09:31:55Z DEBU [DB:SERVIC] Starting watch. resource-kind:db services/watcher.go:183
teleport[9762]: 2022-10-18T09:31:55Z DEBU             Initializing AWS session for region . common/cloud.go:223
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Teleport component "db:service" has started. pid:9762.1 service/state.go:115
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Service has started. pid:9762.1 service:db.stop service/supervisor.go:268
teleport[9762]: 2022-10-18T09:31:55Z INFO [IAM]       Started IAM configurator service. cloud/iam.go:114
teleport[9762]: 2022-10-18T09:31:55Z DEBU [CLOUDUSER] Starting cloud users service. users/users.go:147
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROC:1]    Teleport component "node" has started. pid:9762.1 service/state.go:115
teleport[9762]: 2022-10-18T09:31:55Z DEBU [DB:SERVIC] Reconciling 0 current resources with 0 new resources. services/reconciler.go:102
teleport[9762]: 2022-10-18T09:31:55Z DEBU [WATCHER:C] Starting cloud databases watcher. watchers/watcher.go:103
teleport[9762]: 2022-10-18T09:31:55Z DEBU             'teleport-service' group not found, not deleting users srv/usermgmt.go:278
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROXY:AGE] Runtime config: tunnel_strategy: agent_mesh connection_count: 1 cluster:example-teleport reversetunnel/agentpool.go:317
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROXY:AGE] Starting agent {teleport.example.dev:443 tcp } leaseID:1 target:teleport.example.dev:443 cluster:example-teleport reversetunnel/agent.go:285
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROXY:AGE] Changing state initial -> connecting. leaseID:1 target:teleport.example.dev:443 cluster:example-teleport reversetunnel/agent.go:273
teleport[9762]: 2022-10-18T09:31:55Z DEBU [HTTP:PROX] No proxy set in environment, returning direct dialer. proxy/proxy.go:296
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROXY:AGE] Runtime config: tunnel_strategy: agent_mesh connection_count: 1 cluster:example-teleport reversetunnel/agentpool.go:317
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROXY:AGE] Starting agent {teleport.example.dev:443 tcp } leaseID:1 target:teleport.example.dev:443 cluster:example-teleport reversetunnel/agent.go:285
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROXY:AGE] Changing state initial -> connecting. leaseID:1 target:teleport.example.dev:443 cluster:example-teleport reversetunnel/agent.go:273
teleport[9762]: 2022-10-18T09:31:55Z DEBU [HTTP:PROX] No proxy set in environment, returning direct dialer. proxy/proxy.go:296
teleport[9762]: 2022-10-18T09:31:55Z DEBU [HTTP:PROX] No proxy set in environment, returning direct dialer. proxy/proxy.go:296
teleport[9762]: 2022-10-18T09:31:55Z DEBU [WATCHER:C] Skipping fetcher rdsDBInstancesFetcher(Region=REGION, Labels=map[environment:[qa] teleport-access:[true]]). error:[
teleport[9762]: ERROR REPORT:
teleport[9762]: Original Error: *trace.AccessDeniedError AccessDenied: User: arn:aws:sts::ACCOUNT_ID:assumed-role/example-teleport-qa-db-agent/i-0b69627bdae090b67 is not authorized to perform: rds:DescribeDBInstances on resource: arn:aws:rds:REGION:ACCOUNT_ID:db:* because no identity-based policy allows the rds:DescribeDBInstances action
teleport[9762]: status code: 403, request id: 008a4e08-0269-4e4e-9ea5-c345d246ded1
teleport[9762]: Stack Trace:
teleport[9762]: /go/src/github.com/gravitational/teleport/lib/srv/db/cloud/watchers/rds.go:84 github.com/gravitational/teleport/lib/srv/db/cloud/watchers.(*rdsDBInstancesFetcher).Get
teleport[9762]: /go/src/github.com/gravitational/teleport/lib/srv/db/cloud/watchers/watcher.go:120 github.com/gravitational/teleport/lib/srv/db/cloud/watchers.(*Watcher).fetchAndSend
teleport[9762]: /go/src/github.com/gravitational/teleport/lib/srv/db/cloud/watchers/watcher.go:104 github.com/gravitational/teleport/lib/srv/db/cloud/watchers.(*Watcher).Start
teleport[9762]: /opt/go/src/runtime/asm_amd64.s:1571 runtime.goexit
teleport[9762]: User Message: AccessDenied: User: arn:aws:sts::ACCOUNT_ID:assumed-role/example-teleport-qa-db-agent/i-0b69627bdae090b67 is not authorized to perform: rds:DescribeDBInstances on resource: arn:aws:rds:REGION:ACCOUNT_ID:db:* because no identity-based policy allows the rds:DescribeDBInstances action
teleport[9762]: status code: 403, request id: 008a4e08-0269-4e4e-9ea5-c345d246ded1] watchers/watcher.go:125
teleport[9762]: 2022-10-18T09:31:55Z ERRO [WATCHER:C] rdsAuroraClustersFetcher(Region=REGION, Labels=map[environment:[qa] teleport-access:[true]]) failed. error:[
teleport[9762]: ERROR REPORT:
teleport[9762]: Original Error: *awserr.requestError InvalidParameterValue: Unrecognized engine name: aurora
teleport[9762]: status code: 400, request id: ab301d3d-3666-420b-9878-77bd4bb99972
teleport[9762]: Stack Trace:
teleport[9762]: /go/src/github.com/gravitational/teleport/lib/srv/db/cloud/watchers/rds.go:169 github.com/gravitational/teleport/lib/srv/db/cloud/watchers.(*rdsAuroraClustersFetcher).Get
teleport[9762]: /go/src/github.com/gravitational/teleport/lib/srv/db/cloud/watchers/watcher.go:120 github.com/gravitational/teleport/lib/srv/db/cloud/watchers.(*Watcher).fetchAndSend
teleport[9762]: /go/src/github.com/gravitational/teleport/lib/srv/db/cloud/watchers/watcher.go:104 github.com/gravitational/teleport/lib/srv/db/cloud/watchers.(*Watcher).Start
teleport[9762]: /opt/go/src/runtime/asm_amd64.s:1571 runtime.goexit
teleport[9762]: User Message: InvalidParameterValue: Unrecognized engine name: aurora
teleport[9762]: status code: 400, request id: ab301d3d-3666-420b-9878-77bd4bb99972] watchers/watcher.go:129
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROXY:AGE] Changing state connecting -> connected. leaseID:1 target:teleport.example.dev:443 cluster:example-teleport reversetunnel/agent.go:273
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROXY:AGE] Active agent count: 1 cluster:example-teleport reversetunnel/agentpool.go:442
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROXY:AGE] Active agent count: 1 cluster:example-teleport reversetunnel/agentpool.go:442
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROXY:AGE] Discovery request channel opened: teleport-discovery. leaseID:1 target:teleport.example.dev:443 cluster:example-teleport reversetunnel/agent.go:593
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROXY:AGE] handleDiscovery requests channel. leaseID:1 target:teleport.example.dev:443 cluster:example-teleport reversetunnel/agent.go:616
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROXY:AGE] Received discovery request: [ff4e37c0-dbc2-4e95-823b-6ab93ca2f5b0] leaseID:1 target:teleport.example.dev:443 cluster:example-teleport reversetunnel/agent.go:644
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROXY:AGE] Changing state connecting -> connected. leaseID:1 target:teleport.example.dev:443 cluster:example-teleport reversetunnel/agent.go:273
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROXY:AGE] Active agent count: 1 cluster:example-teleport reversetunnel/agentpool.go:442
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROXY:AGE] Active agent count: 1 cluster:example-teleport reversetunnel/agentpool.go:442
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROXY:AGE] Discovery request channel opened: teleport-discovery. leaseID:1 target:teleport.example.dev:443 cluster:example-teleport reversetunnel/agent.go:593
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROXY:AGE] handleDiscovery requests channel. leaseID:1 target:teleport.example.dev:443 cluster:example-teleport reversetunnel/agent.go:616
teleport[9762]: 2022-10-18T09:31:55Z DEBU [PROXY:AGE] Received discovery request: [ff4e37c0-dbc2-4e95-823b-6ab93ca2f5b0] leaseID:1 target:teleport.example.dev:443 cluster:example-teleport reversetunnel/agent.go:644
teleport[9762]: 2022-10-18T09:32:55Z DEBU [PROXY:AGE] Ping -> XXX:443. leaseID:1 target:teleport.example.dev:443 cluster:example-teleport reversetunnel/agent.go:548
teleport[9762]: 2022-10-18T09:32:55Z DEBU [PROXY:AGE] Ping -> XXX:443. leaseID:1 target:teleport.example.dev:443 cluster:example-teleport reversetunnel/agent.go:548
teleport[9762]: 2022-10-18T09:33:55Z DEBU [PROXY:AGE] Ping -> XXX:443. leaseID:1 target:teleport.example.dev:443 cluster:example-teleport reversetunnel/agent.go:548
teleport[9762]: 2022-10-18T09:33:55Z DEBU [PROXY:AGE] Ping -> XXX:443. leaseID:1 target:teleport.example.dev:443 cluster:example-teleport reversetunnel/agent.go:548

Note that there is an IAM "not allowed" in the debug logs because we don't allow Teleport to describe DB Instances, but it does have permission to describe DB Clusters.

I think this might be because the filter query tries using the value aurora for engine value, which fails in the AWS CLI as well:

aws rds describe-db-clusters --filters Name=engine,Values=aurora

An error occurred (InvalidParameterValue) when calling the DescribeDBClusters operation: Unrecognized engine name: aurora

In the same way as a non-existing engine fails:

aws rds describe-db-clusters --filters Name=engine,Values=not-a-valid-engine

An error occurred (InvalidParameterValue) when calling the DescribeDBClusters operation: Unrecognized engine name: not-a-valid-engine

But for example Values=aurora-postgresql works fine.

This "aurora" value comes from here: https://github.com/gravitational/teleport/blob/master/lib/services/database.go#L1009, and it might be something AWS has recently removed?

EDIT: Related to the previous statement, the following API query does not list "aurora" as a DB engine:

aws rds describe-db-engine-versions | jq '.DBEngineVersions[].Engine' | sort | uniq
"aurora-mysql"
"aurora-postgresql"
"custom-sqlserver-ee"
"custom-sqlserver-se"
"custom-sqlserver-web"
"mariadb"
"mysql"
"neptune"
"oracle-ee"
"oracle-ee-cdb"
"oracle-se2"
"oracle-se2-cdb"
"postgres"
"sqlserver-ee"
"sqlserver-ex"
"sqlserver-se"
"sqlserver-web"

EDIT2: This seems to be specific to some regions... e.g. eu-north-1.

sklirg commented 2 years ago

I patched our teleport installation with:

diff --git a/lib/srv/db/cloud/watchers/rds.go b/lib/srv/db/cloud/watchers/rds.go
index 4a1e6f16c..30a113a46 100644
--- a/lib/srv/db/cloud/watchers/rds.go
+++ b/lib/srv/db/cloud/watchers/rds.go
@@ -272,7 +272,6 @@ func auroraFilters() []*rds.Filter {
        return []*rds.Filter{{
                Name: aws.String("engine"),
                Values: aws.StringSlice([]string{
-                       services.RDSEngineAurora,
                        services.RDSEngineAuroraMySQL,
                        services.RDSEngineAuroraPostgres}),
        }}

to resolve this error. I don't think this is a perfect fix as "aurora" seems to be a valid engine in other AWS regions than the one we use.

One possible workaround could be to do a check of valid engines through describe-db-engine-versions, and only include the ones matching what's listed in services.RDSEngineAurora* when querying for the databases. This incurs another API request per database request/poll, though. Maybe it could be kept in memory to avoid the extra request for every poll.

GavinFrazar commented 2 years ago 
aws rds describe-db-clusters --filters Name=engine,Values=aurora

An error occurred (InvalidParameterValue) when calling the DescribeDBClusters operation: Unrecognized engine name: aurora

I can't reproduce this with any region, including --region=eu-north-1.

I have a branch that queries DescribeDBEngineVersions so we only include available engines. The unfortunate thing is that this requires multiple calls (or I can switch to the paginated version), because it returns ~270 engine versions in us-west-1, 100 results max in each response - I haven't checked other regions. I don't think I can filter for just the engines we care about because that could lead to the same problem you had in the first place. I think we'll need to cache this result.

Note that "aurora" corresponds to MySQL 5.6, which reaches end of life in February 2023: https://docs.aws.amazon.com/AmazonRDS/latest/AuroraUserGuide/Aurora.MySQL56.EOL.html

sklirg commented 2 years ago

I see the same behaviour now. Previously, as described, this would result in an API response returning an error. However, now, it instead returns an empty list:

❯ aws rds describe-db-clusters --filters Name=engine,Values=aurora
{
    "DBClusters": []
}

A non-existing engine still returns an error:

❯ aws rds describe-db-clusters --filters Name=engine,Values=not-a-valid-engine

An error occurred (InvalidParameterValue) when calling the DescribeDBClusters operation: Unrecognized engine name: not-a-valid-engine

I think it would make sense to implement the change you're talking about, but consider if it could be conditionally enabled.

The cases where it would make sense to enable it would be e.g.: 1) in configuration 2) based on if the API request fails initially or not (i.e. if the API request fails (with an invalid engine), then switch to listing all and then filtering for the wanted ones). This would do "the best of both worlds", but it would increase (code) complexity.

The fact that this effectively stopped RDS discovery from working at all made Teleport unusable for us for multiple hours until we were able to figure out why, patch it, and build & deploy a patched version.

GavinFrazar commented 2 years ago

I think falling back to listing engines when the API request fails is probably the best approach here and doesn't introduce lots of extra API calls into the happy path of the code. Will get a fix for this in soon

rahulinux commented 1 year ago

Getting the same error on v12, is it merged in the latest version?

smallinsky commented 1 year ago

@rahulinux Yes, This has been released in 11.1.0 and any v12 version should contains this fix.

Getting the same error on v12

Could you post your stack trace ? Also are you sure that you have updated teleport db agent ?

danylomikula commented 1 year ago

@smallinsky @GavinFrazar Hi, the same error here at version 12.1.5

2023-04-04T18:08:32Z WARN [WATCH:AUR] Teleport supports an engine which is unrecognized in this AWS region. Querying engines individually. error:[
ERROR REPORT:
Original Error: *awserr.requestError InvalidParameterValue: Unrecognized engine name: aurora
    status code: 400, request id: **
Stack Trace:
    github.com/gravitational/teleport/lib/srv/discovery/fetchers/db/aws_rds.go:282 github.com/gravitational/teleport/lib/srv/discovery/fetchers/db.getAllDBClusters.func1
    github.com/gravitational/teleport/lib/srv/discovery/fetchers/db/aws_rds.go:330 github.com/gravitational/teleport/lib/srv/discovery/fetchers/db.retryWithIndividualEngineFilters
    github.com/gravitational/teleport/lib/srv/discovery/fetchers/db/aws_rds.go:268 github.com/gravitational/teleport/lib/srv/discovery/fetchers/db.getAllDBClusters
    github.com/gravitational/teleport/lib/srv/discovery/fetchers/db/aws_rds.go:191 github.com/gravitational/teleport/lib/srv/discovery/fetchers/db.(*rdsAuroraClustersFetcher).getAuroraDatabases
    github.com/gravitational/teleport/lib/srv/discovery/fetchers/db/aws_rds.go:181 github.com/gravitational/teleport/lib/srv/discovery/fetchers/db.(*rdsAuroraClustersFetcher).Get
    github.com/gravitational/teleport/lib/srv/discovery/common/watcher.go:116 github.com/gravitational/teleport/lib/srv/discovery/common.(*Watcher).fetchAndSend.func1
    golang.org/x/sync@v0.1.0/errgroup/errgroup.go:75 golang.org/x/sync/errgroup.(*Group).Go.func1
    runtime/asm_amd64.s:1598 runtime.goexit
User Message: InvalidParameterValue: Unrecognized engine name: aurora
    status code: 400, request id: **] labels:map[*:[*]] region:eu-central-1 db/aws_rds.go:337

Helm chart: https://github.com/gravitational/teleport/tree/master/examples/chart/teleport-kube-agent

awsDatabases:
  - types: ["rds"]
    regions: ["eu-central-1"]
    tags:
      "*": "*"
GavinFrazar commented 1 year ago

@DanyloMikula Hi, that is a warning logged when the database service falls back to querying each engine type individually, but it should continue to look for engines: aurora, aurora-mysql, aurora-postgresql, and then ignores and skips the error when it fails for the unrecognized engine aurora.

Are you not seeing any discovered databases?

danylomikula commented 1 year ago

@DanyloMikula Hi, that is a warning logged when the database service falls back to querying each engine type individually, but it should continue to look for engines: aurora, aurora-mysql, aurora-postgresql, and then ignores and skips the error when it fails for the unrecognized engine aurora.

Are you not seeing any discovered databases?

Thanks for the answer, no, there are no problems with database discovery, but these error logs every few minutes are quite annoying, is there any solution, to turn off other database discovery, except those that are configured in agent settings?

GavinFrazar commented 1 year ago

There's no setting, we group all 3 engines as one. @smallinsky should we just move this log message to debug level instead of warning, and only warn if the individual engine retries all fail?

klizhentas commented 1 year ago

@GavinFrazar @smallinsky this error generates support load, so we should fix the error message to debug. Reopening to take care of this.