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

dmsghttp log server i/o deadline reached #1804

Open
0pcom opened this issue Apr 9, 2024 · 0 comments
Open

dmsghttp log server i/o deadline reached #1804

0pcom opened this issue Apr 9, 2024 · 0 comments
Labels
breaking issue breaks critical functionality bug Something isn't working dmsg issue of dmsg client, connection, or dmsghttp-config telemetrics transport bandwidth & survey collection

Comments

@0pcom
Copy link
Collaborator

0pcom commented Apr 9, 2024

when performing a similar test as the one described in #1803 ; it became apparent that the dmsghttp log server is not an accurate indicator of the visor being connected to dmsg.

Here is the test which was performed

$ _mypk="$(skywire cli visor pk)" ; skywire cli proxy list -c US -v v1.3.19 | while read _pk ; do echo $_pk ;  curl -sLx socks5h:https://127.0.0.1:4445 https://${_pk}.dmsg/health ; echo ; skywire svc tps add -p -t dmsg -1 $_pk -2 ${_mypk} ; _tpid="$(skywire svc tps list -1 $_pk | jq '.[].ID' | tr -d '"' | head -n1)" ; [[ ${_tpid} != "" ]] && skywire svc tps rm -p -1 $_pk -i $_tpid ; done

All the public keys checked should be of the same version, v1.3.19 and all should respond over dmsghttp to /health checks. However, occasionally results were returned such as this

031f16af33f3674cc2830dce745f8c3213a124d1d1d4938d4558752c8939a8780d
Failed to connect to HTTP server
{
  "ID": "b93fb0ef-0283-04af-b2ad-fac20d881ef8",
  "Local": "031f16af33f3674cc2830dce745f8c3213a124d1d1d4938d4558752c8939a8780d",
  "Remote": "0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c",
  "Type": "dmsg"
}
{
  "Result": true
}

As should be apparent, that visor is connected to dmsg because it responded correctly to the transport setup and takedown request. The dmsghttp log server is, at the same time, unresponsive.

Another check of that visor's /health with dmsgcurl

 skywire dmsg curl -l debug dmsg:https://031f16af33f3674cc2830dce745f8c3213a124d1d1d4938d4558752c8939a8780d:80/health
[2024-04-09T08:57:39.29633081-05:00] DEBUG disc.NewHTTP [dmsgcurl]: Created HTTP client. addr="https://dmsgd.skywire.skycoin.com"
[2024-04-09T08:57:39.296413808-05:00] DEBUG [dmsgcurl]: Connecting to dmsg network... dmsg_disc="https://dmsgd.skywire.skycoin.com" public_key="03dc0cc11fb022f96d20962e89f1871736a3690f32c90706a48e8008681d7fdc88"
[2024-04-09T08:57:39.296508226-05:00] DEBUG [dmsg_client]: Discovering dmsg servers...
[2024-04-09T08:57:39.8061407-05:00] DEBUG [dmsg_client]: Dialing session... remote_pk=0326978f5a53aff537dbb47fed58b1f123af3b00132d365f1309a14db4168dcff7
[2024-04-09T08:57:40.307592762-05:00] DEBUG [dmsg_client]: Serving session. remote_pk=0326978f5a53aff537dbb47fed58b1f123af3b00132d365f1309a14db4168dcff7
[2024-04-09T08:57:40.307637338-05:00] DEBUG [dmsgcurl]: Dmsg network ready.
[2024-04-09T08:58:00.843082584-05:00] DEBUG ClientSession.DialStream [dmsg_client]: Stream closed on failure. close_error=<nil> dst_addr=031f16af33f3674cc2830dce745f8c3213a124d1d1d4938d4558752c8939a8780d:80 error="i/o deadline reached" session=0326978f5a53aff537dbb47fed58b1f123af3b00132d365f1309a14db4168dcff7
[2024-04-09T08:58:00.843188591-05:00] ERROR [dmsgcurl]: error="failed to connect to HTTP server: Get "dmsg:https://031f16af33f3674cc2830dce745f8c3213a124d1d1d4938d4558752c8939a8780d:80/health": i/o deadline reached"
[2024-04-09T08:58:00.843338565-05:00] DEBUG [dmsg_client]: Stopped serving client!
[2024-04-09T08:58:00.843397403-05:00] DEBUG [dmsg_client]: Stopped accepting streams. error="session shutdown" session=0326978f5a53aff537dbb47fed58b1f123af3b00132d365f1309a14db4168dcff7
[2024-04-09T08:58:00.843546798-05:00] DEBUG [dmsg_client]: Session closed. error=<nil>
[2024-04-09T08:58:00.843582033-05:00] DEBUG [dmsg_client]: All sessions closed.
[2024-04-09T08:58:01.085427795-05:00] DEBUG [dmsg_client]: Deleting entry. entry=	version: 0.0.1
	sequence: 0
	registered at: 1712671060064820069
	static public key: 03dc0cc11fb022f96d20962e89f1871736a3690f32c90706a48e8008681d7fdc88
	signature: e906163ed29264c133d95e2d07597b4208ebab39fb36c6924fb6349bf95043c903eec2d606beb371c5568da7d4ec941dd6fff789abd5f0334df23879f4d3f5c400
	entry is registered as client. Related info: 
		delegated servers: 
			0326978f5a53aff537dbb47fed58b1f123af3b00132d365f1309a14db4168dcff7


[2024-04-09T08:58:01.327718526-05:00] DEBUG [dmsg_client]: Entry Deleted successfully.
[2024-04-09T08:58:01.327757387-05:00] DEBUG [dmsgcurl]: Disconnected from dmsg network. error=<nil>

The error from above:

[2024-04-09T08:58:00.843188591-05:00] ERROR [dmsgcurl]: error="failed to connect to HTTP server: Get "dmsg:https://031f16af33f3674cc2830dce745f8c3213a124d1d1d4938d4558752c8939a8780d:80/health": i/o deadline reached"

Is not an uncommon one to the transport bandwidth and survey collection process, many of such errors can be seen at https://fiber.skywire.dev/log-collection

@0pcom 0pcom added bug Something isn't working breaking issue breaks critical functionality telemetrics transport bandwidth & survey collection dmsg issue of dmsg client, connection, or dmsghttp-config labels Apr 9, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
breaking issue breaks critical functionality bug Something isn't working dmsg issue of dmsg client, connection, or dmsghttp-config telemetrics transport bandwidth & survey collection
Projects
None yet
Development

No branches or pull requests

1 participant