civilizeddev
commented
10 months ago How to reproduce with DBeaver Community
Airbyte is too heavy, so it might be better to reproduce the issue with a simpler DB client, like DBeaver for instance.
brew install dbeaver-communityWhen you click 'Test tunnel configuration', even if the password is incorrect, as long as the SSHID is accurate, it returns a normal response. This isn't normal either.
When you click 'Test connection', it attempts to connect, but the following error occurs.
(The debugging log below is something I added by modifying the code.)
time="2023-11-01T04:46:46Z" level=info msg="Setting log level" log_level=trace
time="2023-11-01T04:46:46Z" level=info msg="ssh server listening" addr=":2222"
time="2023-11-01T04:47:20Z" level=trace msg="trying to use password authentication" sshid=ubuntu@[SSHID (redacted)]
time="2023-11-01T04:47:20Z" level=info msg="using password authentication method to connect the client to agent" sshid=ubuntu@[SSHID (redacted)]
time="2023-11-01T04:47:21Z" level=debug msg="connection between server and agent is not established yet"
henrybarreto
Description
Background
I am using a database migration tool called Airbyte. I intend to access the database in the private network as shown in the diagram below by forming an SSH tunnel through ShellHub and via ShellHub agent.
Problem
Learn more
``` Internal message: io.airbyte.commons.exceptions.ConnectionErrorException: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 10002ms. Failure origin: source Failure type: config_error ```Stacktrace
``` io.airbyte.commons.exceptions.ConnectionErrorException: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 10002ms. at io.airbyte.db.jdbc.DefaultJdbcDatabase.getMetaData(DefaultJdbcDatabase.java:87) at io.airbyte.integrations.source.postgres.PostgresSource.createDatabase(PostgresSource.java:315) at io.airbyte.integrations.source.postgres.PostgresSource.createDatabase(PostgresSource.java:121) at io.airbyte.integrations.source.relationaldb.AbstractDbSource.check(AbstractDbSource.java:85) at io.airbyte.integrations.source.postgres.PostgresSource.check(PostgresSource.java:702) at io.airbyte.integrations.base.ssh.SshTunnel.sshWrap(SshTunnel.java:270) at io.airbyte.integrations.base.ssh.SshWrappedSource.check(SshWrappedSource.java:54) at io.airbyte.integrations.base.IntegrationRunner.runInternal(IntegrationRunner.java:148) at io.airbyte.integrations.base.IntegrationRunner.run(IntegrationRunner.java:123) at io.airbyte.integrations.source.postgres.PostgresSource.main(PostgresSource.java:683) Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 10002ms. at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:696) at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:181) at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:146) at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:100) at io.airbyte.db.jdbc.DefaultJdbcDatabase.getMetaData(DefaultJdbcDatabase.java:78) ... 9 more Caused by: org.postgresql.util.PSQLException: Connection to 127.0.0.1:36247 refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections. at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:319) at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:49) at org.postgresql.jdbc.PgConnection.Logs
``` 2023-11-01 03:33:29 i.a.w.t.TemporalAttemptExecution(get):124 - Docker volume job log path: /tmp/workspace/1cf4099a-53ca-454d-91c1-39d15b591d21/0/logs.log 2023-11-01 03:33:29 i.a.w.t.TemporalAttemptExecution(get):129 - Executing worker wrapper. Airbyte version: 0.50.29 2023-11-01 03:33:29 i.a.a.c.AirbyteApiClient(retryWithJitterThrows):290 - Attempt 0 to save workflow id for cancellation 2023-11-01 03:33:29 i.a.c.i.LineGobbler(voidCall):149 - 2023-11-01 03:33:29 i.a.c.EnvConfigs(getEnvOrDefault):1228 - Using default value for environment variable SIDECAR_KUBE_CPU_LIMIT: '2.0' 2023-11-01 03:33:29 i.a.c.i.LineGobbler(voidCall):149 - ----- START CHECK ----- 2023-11-01 03:33:29 i.a.c.EnvConfigs(getEnvOrDefault):1228 - Using default value for environment variable SOCAT_KUBE_CPU_LIMIT: '2.0' 2023-11-01 03:33:29 i.a.c.i.LineGobbler(voidCall):149 - 2023-11-01 03:33:29 i.a.c.EnvConfigs(getEnvOrDefault):1228 - Using default value for environment variable SIDECAR_KUBE_CPU_REQUEST: '0.1' 2023-11-01 03:33:29 i.a.c.EnvConfigs(getEnvOrDefault):1228 - Using default value for environment variable SOCAT_KUBE_CPU_REQUEST: '0.1' 2023-11-01 03:33:29 i.a.c.EnvConfigs(getEnvOrDefault):1228 - Using default value for environment variable LAUNCHDARKLY_KEY: '' 2023-11-01 03:33:29 i.a.c.i.LineGobbler(voidCall):149 - Checking if airbyte/source-postgres:3.1.7 exists... 2023-11-01 03:33:29 i.a.w.p.DockerProcessFactory(create):143 - Creating docker container = source-postgres-check-1cf4099a-53ca-454d-91c1-39d15b591d21-0-xazys with resources io.airbyte.config.ResourceRequirements@10f23d9c[cpuRequest=,cpuLimit=,memoryRequest=,memoryLimit=,additionalProperties={}] and allowedHosts null 2023-11-01 03:33:29 i.a.c.i.LineGobbler(voidCall):149 - airbyte/source-postgres:3.1.7 was found locally. 2023-11-01 03:33:29 i.a.w.p.DockerProcessFactory(create):196 - Preparing command: docker run --rm --init -i -w /data/1cf4099a-53ca-454d-91c1-39d15b591d21/0 --log-driver none --name source-postgres-check-1cf4099a-53ca-454d-91c1-39d15b591d21-0-xazys --network host -v airbyte_workspace:/data -v /tmp/airbyte_local:/local -e DEPLOYMENT_MODE=OSS -e WORKER_CONNECTOR_IMAGE=airbyte/source-postgres:3.1.7 -e AUTO_DETECT_SCHEMA=true -e LAUNCHDARKLY_KEY= -e SOCAT_KUBE_CPU_REQUEST=0.1 -e SOCAT_KUBE_CPU_LIMIT=2.0 -e USE_STREAM_CAPABLE_STATE=true -e FIELD_SELECTION_WORKSPACES= -e WORKER_ENVIRONMENT=DOCKER -e AIRBYTE_ROLE= -e APPLY_FIELD_SELECTION=false -e WORKER_JOB_ATTEMPT=0 -e OTEL_COLLECTOR_ENDPOINT=http://host.docker.internal:4317 -e FEATURE_FLAG_CLIENT=config -e AIRBYTE_VERSION=0.50.29 -e WORKER_JOB_ID=1cf4099a-53ca-454d-91c1-39d15b591d21 airbyte/source-postgres:3.1.7 check --config source_config.json 2023-11-01 03:33:29 i.a.w.i.VersionedAirbyteStreamFactory(create):177 - Reading messages from protocol version 0.2.0 2023-11-01 03:33:31 i.a.w.i.VersionedAirbyteStreamFactory(internalLog):312 - INFO i.a.i.s.p.PostgresSource(main):682 starting source: class io.airbyte.integrations.source.postgres.PostgresSource 2023-11-01 03:33:31 i.a.w.i.VersionedAirbyteStreamFactory(internalLog):312 - INFO i.a.i.b.IntegrationCliParser(parseOptions):126 integration args: {check=null, config=source_config.json} 2023-11-01 03:33:31 i.a.w.i.VersionedAirbyteStreamFactory(internalLog):312 - INFO i.a.i.b.IntegrationRunner(runInternal):130 Running integration: io.airbyte.integrations.base.ssh.SshWrappedSource 2023-11-01 03:33:31 i.a.w.i.VersionedAirbyteStreamFactory(internalLog):312 - INFO i.a.i.b.IntegrationRunner(runInternal):131 Command: CHECK 2023-11-01 03:33:31 i.a.w.i.VersionedAirbyteStreamFactory(internalLog):312 - INFO i.a.i.b.IntegrationRunner(runInternal):132 Integration config: IntegrationConfig{command=CHECK, configPath='source_config.json', catalogPath='null', statePath='null'} 2023-11-01 03:33:32 i.a.w.i.VersionedAirbyteStreamFactory(internalLog):309 - WARN c.n.s.JsonMetaSchema(newValidator):278 Unknown keyword groups - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword 2023-11-01 03:33:32 i.a.w.i.VersionedAirbyteStreamFactory(internalLog):309 - WARN c.n.s.JsonMetaSchema(newValidator):278 Unknown keyword order - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword 2023-11-01 03:33:32 i.a.w.i.VersionedAirbyteStreamFactory(internalLog):309 - WARN c.n.s.JsonMetaSchema(newValidator):278 Unknown keyword group - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword 2023-11-01 03:33:32 i.a.w.i.VersionedAirbyteStreamFactory(internalLog):309 - WARN c.n.s.JsonMetaSchema(newValidator):278 Unknown keyword airbyte_secret - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword 2023-11-01 03:33:32 i.a.w.i.VersionedAirbyteStreamFactory(internalLog):309 - WARN c.n.s.JsonMetaSchema(newValidator):278 Unknown keyword always_show - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword 2023-11-01 03:33:32 i.a.w.i.VersionedAirbyteStreamFactory(internalLog):309 - WARN c.n.s.JsonMetaSchema(newValidator):278 Unknown keyword display_type - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword 2023-11-01 03:33:32 i.a.w.i.VersionedAirbyteStreamFactory(internalLog):312 - INFO i.a.i.b.s.SshTunnel(getInstance):204 Starting connection with method: SSH_PASSWORD_AUTH 2023-11-01 03:33:33 i.a.w.i.VersionedAirbyteStreamFactory(internalLog):312 - INFO o.a.s.c.u.s.AbstractSecurityProviderRegistrar(getOrCreateProvider):112 getOrCreateProvider(EdDSA) created instance of net.i2p.crypto.eddsa.EdDSASecurityProvider 2023-11-01 03:33:33 i.a.w.i.VersionedAirbyteStreamFactory(internalLog):312 - INFO o.a.s.c.i.DefaultIoServiceFactoryFactory(getIoServiceProvider):71 Using MinaServiceFactoryFactory 2023-11-01 03:33:33 i.a.w.i.VersionedAirbyteStreamFactory(internalLog):309 - WARN o.a.s.c.k.StaticServerKeyVerifier(handleAcceptance):59 Server at shellhub.xxx.xxx/x.x.x.x:22 presented unverified RSA key: SHA256:vhHKg9OLlLbUICa0HRdop7hCG6VoKgG6Xtmr9BDK1UQ 2023-11-01 03:33:33 i.a.w.i.VersionedAirbyteStreamFactory(internalLog):312 - INFO i.a.i.b.s.SshTunnel(openTunnel):367 Established tunneling session to y.y.y.y:5432. Port forwarding started on /127.0.0.1:36247 2023-11-01 03:33:33 i.a.w.i.VersionedAirbyteStreamFactory(internalLog):312 - INFO i.a.i.s.p.PostgresUtils(isCdc):61 using CDC: false 2023-11-01 03:33:33 i.a.w.i.VersionedAirbyteStreamFactory(internalLog):312 - INFO i.a.i.s.p.PostgresSource(toSslJdbcParamInternal):719 DISABLED toSslJdbcParam disable 2023-11-01 03:33:33 i.a.w.i.VersionedAirbyteStreamFactory(internalLog):312 - INFO c.z.h.HikariDataSource(What I have found
I traced the source code to track the SSH tunneling connection process of the Shellhub SSH server and followed the path leading up to DefaultTCPIPHandler.
The problem arises from these codes. What's odd is that in the
DefaultTCPIPHandlerflow, I can only find the 'metadata restore' and cannot locate where the 'metadata store' takes place.https://github.com/shellhub-io/shellhub/blob/0674b42c6b9372e8fa3745861d113baad034bac9/ssh/server/channels/tcpip.go#L52-L56
https://github.com/shellhub-io/shellhub/blob/0674b42c6b9372e8fa3745861d113baad034bac9/ssh/server/channels/tcpip.go#L60-L65
I discovered that the code for 'metadata store' only executes when connecting through the SSH session flow.
https://github.com/shellhub-io/shellhub/blob/0674b42c6b9372e8fa3745861d113baad034bac9/ssh/server/handler/ssh.go#L170
https://github.com/shellhub-io/shellhub/blob/0674b42c6b9372e8fa3745861d113baad034bac9/ssh/server/handler/ssh.go#L185
Please check if there's anything I might have missed.
Thank you.
Edition
Community
Version
v0.13.0-rc.11