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.

Sign up for GitHub

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

Jump to bottom

Clean up logging #1234

Closed
jdknives opened this issue May 27, 2022 · 0 comments
Closed

Clean up logging #1234

jdknives opened this issue May 27, 2022 · 0 comments
Labels
enhancement New feature or request

Comments

@jdknives
Copy link
Member

Feature description

We currently log various events to INFO that either could be scrapped completely or should be under DEBUG. This is currently a generic log output if INFO is enabled:

[2022-05-27T20:26:43+03:00] INFO [buildinfo]:  version="v0.6.0-438-g89b22ba8" built on="2022-05-27T11:54:52Z" commit="89b22ba8f9b21f7c51ec51f4c5f72fcb01a23f75"
[2022-05-27T20:26:43+03:00] INFO [visor:config]: Reading config from file.
[2022-05-27T20:26:43+03:00] INFO [visor:config]: filepath="skywire-config.json"
[2022-05-27T20:26:43+03:00] INFO [visor:config]: config version: ="v0.6.0-438-g89b22ba8"
[2022-05-27T20:26:43+03:00] INFO [visor:startup]: Begin startup. public_key=02050e01749af8e487c320203363b260cb27c1481e92225f4ab40e8d0c0b0648b2
[2022-05-27T20:26:43+03:00] INFO [hypervisor]: Starting
[2022-05-27T20:26:43+03:00] INFO [visor]: Starting
[2022-05-27T20:26:43+03:00] INFO [stcpr]: Starting
[2022-05-27T20:26:43+03:00] INFO [transports]: Starting
[2022-05-27T20:26:43+03:00] INFO [router]: Starting
[2022-05-27T20:26:43+03:00] INFO [stun_client]: Starting
[2022-05-27T20:26:43+03:00] INFO [dmsg_http]: Starting
[2022-05-27T20:26:43+03:00] INFO [stcp]: Starting
[2022-05-27T20:26:43+03:00] INFO [dmsg_http]: Initialized in 1.763µs (2.836µs with dependencies)
[2022-05-27T20:26:43+03:00] INFO [discovery]: Starting
[2022-05-27T20:26:43+03:00] INFO [sudph]: Starting
[2022-05-27T20:26:43+03:00] INFO [hypervisors]: Starting
[2022-05-27T20:26:43+03:00] INFO [uptime_tracker]: Starting
[2022-05-27T20:26:43+03:00] INFO [cli]: Starting
[2022-05-27T20:26:43+03:00] INFO [dmsg]: Starting
[2022-05-27T20:26:43+03:00] INFO [address_resolver]: Starting
[2022-05-27T20:26:43+03:00] INFO [address_resolver]: Remote UDP server: "ar.skywire.dev:30178"
[2022-05-27T20:26:43+03:00] INFO [public_visor]: Starting
[2022-05-27T20:26:43+03:00] INFO [updater]: Starting
[2022-05-27T20:26:43+03:00] INFO [updater]: Initialized in 3.216µs (3.667µs with dependencies)
[2022-05-27T20:26:43+03:00] INFO [dmsg_ctrl]: Starting
[2022-05-27T20:26:43+03:00] INFO [discovery]: Initialized in 19.506µs (21.239µs with dependencies)
[2022-05-27T20:26:43+03:00] INFO [dmsg_pty]: Starting
[2022-05-27T20:26:43+03:00] INFO [public_autoconnect]: Starting
[2022-05-27T20:26:43+03:00] INFO [launcher]: Starting
[2022-05-27T20:26:43+03:00] INFO [transport_setup]: Starting
[2022-05-27T20:26:43+03:00] INFO [event_broadcaster]: Starting
[2022-05-27T20:26:43+03:00] INFO [transport]: Starting
[2022-05-27T20:26:43+03:00] INFO [event_broadcaster]: Initialized in 3.066µs (3.346µs with dependencies)
[2022-05-27T20:26:43+03:00] INFO [address_resolver]: Initialized in 374.497µs (376.31µs with dependencies)
[2022-05-27T20:26:43+03:00] INFO [dmsg]: Initialized in 84.137µs (493.167µs with dependencies)
[2022-05-27T20:26:43+03:00] INFO [hypervisors]: Initialized in 1.863µs (559.871µs with dependencies)
[2022-05-27T20:26:43+03:00] INFO [dmsgC]: Discovering dmsg servers...
[2022-05-27T20:26:43+03:00] INFO [dmsg_pty]: Initialized in 590.789µs (869.808µs with dependencies)
[2022-05-27T20:26:43+03:00] INFO [cli]: Initialized in 2.340474ms (2.341006ms with dependencies)
[2022-05-27T20:26:43+03:00] INFO [uptime_tracker]: Initialized in 601.271241ms (601.275509ms with dependencies)
[2022-05-27T20:26:43+03:00] INFO [transport]: Initialized in 629.371533ms (629.425102ms with dependencies)
[2022-05-27T20:26:43+03:00] INFO [transport_manager]: Serving stcpr network
[2022-05-27T20:26:43+03:00] INFO [transport_manager]: transport manager is serving.
[2022-05-27T20:26:43+03:00] INFO [transport_manager]: listening on network: stcpr
[2022-05-27T20:26:43+03:00] INFO [stcpr]: Initialized in 93.063µs (630.189045ms with dependencies)
[2022-05-27T20:26:43+03:00] INFO [public_autoconnect]: Initialized in 31.969µs (629.599507ms with dependencies)
[2022-05-27T20:26:43+03:00] INFO [dmsgC]: Connecting to the dmsg network... timeout=20s
[2022-05-27T20:26:43+03:00] INFO [transport_manager]: Serving stcp network
[2022-05-27T20:26:43+03:00] INFO [transport_manager]: listening on network: stcp
[2022-05-27T20:26:43+03:00] INFO [stcp]: Initialized in 168.293µs (630.289791ms with dependencies)
[2022-05-27T20:26:43+03:00] INFO [stcp]: listening on addr: [::]:7777
[2022-05-27T20:26:43+03:00] INFO [transport_setup]: Initialized in 1.613943ms (631.410958ms with dependencies)
[2022-05-27T20:26:43+03:00] INFO [transport_setup]: Connecting to the dmsg network. local_pk=02050e01749af8e487c320203363b260cb27c1481e92225f4ab40e8d0c0b0648b2
[2022-05-27T20:26:43+03:00] INFO [router]: Starting router
[2022-05-27T20:26:43+03:00] INFO [router]: Initialized in 2.753272ms (632.959679ms with dependencies)
[2022-05-27T20:26:43+03:00] INFO [stcpr]: Not binding STCPR: no public IP address found
[2022-05-27T20:26:43+03:00] INFO [launcher]: Initialized in 7.785205ms (641.2214ms with dependencies)
[2022-05-27T20:26:43+03:00] INFO [dmsgC]: Dialing session... remote_pk=024716428e6315d954356e9ad72bea32bb2b41aab5a54a9b5cb4313964016e64d8
[2022-05-27T20:26:43+03:00] INFO [proc_manager]: Accepted proc conn. hello="{"proc_key":"6cae664643cc4fa9b2e28f8ce4fdac97"}" remote=127.0.0.1:51784
[2022-05-27T20:26:43+03:00] INFO (STDOUT) [proc:skychat:6cae664643cc4fa9b2e28f8ce4fdac97]: Version "v0.6.0-438-g89b22ba8" built on "2022-05-27T11:54:44Z" against commit "89b22ba8f9b21f7c51ec51f4c5f72fcb01a23f75"
[2022-05-27T20:26:43+03:00] INFO [proc:skychat:6cae664643cc4fa9b2e28f8ce4fdac97]: Associated and serving proc conn.
[2022-05-27T20:26:43+03:00] INFO [proc:skychat:6cae664643cc4fa9b2e28f8ce4fdac97]: Request processed. _elapsed="22.151µs" _method="SetDetailedStatus" _received="8:26PM" input=0xc00040e500
[2022-05-27T20:26:43+03:00] INFO (STDOUT) [proc:skysocks:1909f12806dd4aff9e703643cfb7db3b]: Version "v0.6.0-438-g89b22ba8" built on "2022-05-27T11:54:44Z" against commit "89b22ba8f9b21f7c51ec51f4c5f72fcb01a23f75"
[2022-05-27T20:26:43+03:00] INFO [proc_manager]: Accepted proc conn. hello="{"proc_key":"1909f12806dd4aff9e703643cfb7db3b"}" remote=127.0.0.1:51786
[2022-05-27T20:26:43+03:00] INFO [proc:skychat:6cae664643cc4fa9b2e28f8ce4fdac97]: Request processed. _elapsed="3.000232ms" _method="Listen" _received="8:26PM" input=02050e01749af8e487c320203363b260cb27c1481e92225f4ab40e8d0c0b0648b2:1 output=0xc00041a186
[2022-05-27T20:26:43+03:00] INFO [proc:skysocks:1909f12806dd4aff9e703643cfb7db3b]: Associated and serving proc conn.
[2022-05-27T20:26:43+03:00] INFO [proc:skysocks:1909f12806dd4aff9e703643cfb7db3b]: Request processed. _elapsed="2.536409ms" _method="Listen" _received="8:26PM" input=02050e01749af8e487c320203363b260cb27c1481e92225f4ab40e8d0c0b0648b2:3 output=0xc00078416e
[2022-05-27T20:26:43+03:00] INFO (STDOUT) [proc:skychat:6cae664643cc4fa9b2e28f8ce4fdac97]: Successfully started skychat.Serving HTTP on:8001Accepting skychat conn...Calling app RPC Accept
[2022-05-27T20:26:43+03:00] INFO (STDOUT) [proc:skysocks:1909f12806dd4aff9e703643cfb7db3b]: Starting serving proxy server
[2022-05-27T20:26:43+03:00] INFO [proc:skysocks:1909f12806dd4aff9e703643cfb7db3b]: Request processed. _elapsed="29.435µs" _method="SetDetailedStatus" _received="8:26PM" input=0xc00038a090
[2022-05-27T20:26:43+03:00] INFO (STDOUT) [proc:skysocks:1909f12806dd4aff9e703643cfb7db3b]: Calling app RPC Accept
[2022-05-27T20:26:43+03:00] INFO [address_resolver]: Connected to address resolver. STCPR/SUDPH services are available.
[2022-05-27T20:26:44+03:00] INFO [public_visor]: Initialized in 1.092647297s (1.722418403s with dependencies)
[2022-05-27T20:26:44+03:00] INFO [dmsgC]: Serving session. remote_pk=024716428e6315d954356e9ad72bea32bb2b41aab5a54a9b5cb4313964016e64d8
[2022-05-27T20:26:44+03:00] INFO [transport_setup]: Connected! local_pk=02050e01749af8e487c320203363b260cb27c1481e92225f4ab40e8d0c0b0648b2
[2022-05-27T20:26:44+03:00] INFO [dmsgC]: Connected to the dmsg network. timeout=20s
[2022-05-27T20:26:44+03:00] INFO [visor]: Initialized in 1.483µs (1.725853255s with dependencies)
[2022-05-27T20:26:44+03:00] INFO [transport_setup]: starting listener dmsg_port=47
[2022-05-27T20:26:44+03:00] INFO [transport_manager]: Serving dmsg network
[2022-05-27T20:26:44+03:00] INFO [visor]: Initializing hypervisor
[2022-05-27T20:26:44+03:00] INFO [transport_setup]: Accepting dmsg streams. dmsg_port=47
[2022-05-27T20:26:44+03:00] INFO [transport_manager]: listening on network: dmsg
[2022-05-27T20:26:44+03:00] INFO [visor]: Serving RPC client over dmsg. addr=02050e01749af8e487c320203363b260cb27c1481e92225f4ab40e8d0c0b0648b2:46
[2022-05-27T20:26:44+03:00] INFO [dmsg_ctrl]: Initialized in 1.107634231s (1.737310741s with dependencies)
[2022-05-27T20:26:44+03:00] INFO [visor]: Serving hypervisor... addr=":8000" tls=false
[2022-05-27T20:26:44+03:00] INFO [visor]: Hypervisor initialized
[2022-05-27T20:26:44+03:00] INFO [hypervisor]: Initialized in 12.037547ms (1.743493475s with dependencies)
[2022-05-27T20:26:50+03:00] INFO [transport_manager]: recv transport request: type(dmsg) remote(0218905f5d9079bab0b62985a05bd162623b193e948e17e7b719133f2c60b92093)
[2022-05-27T20:26:50+03:00] INFO [tp:021890]: Serving. remote_pk=0218905f5d9079bab0b62985a05bd162623b193e948e17e7b719133f2c60b92093 tp_id=b264c743-2e35-0f86-8126-48cda5afc6ec tp_index=1
[2022-05-27T20:26:50+03:00] INFO [transport_manager]: accepted tp: type(dmsg) remote(0218905f5d9079bab0b62985a05bd162623b193e948e17e7b719133f2c60b92093) tpID(b264c743-2e35-0f86-8126-48cda5afc6ec) new(true)
[2022-05-27T20:26:52+03:00] WARN [tp:021890]: Failed to read packet, closing transport error="EOF" src="read_loop"
[2022-05-27T20:26:52+03:00] INFO [tp:021890]: Stopped serving. remaining_tps=0 remote_pk=0218905f5d9079bab0b62985a05bd162623b193e948e17e7b719133f2c60b92093 tp_id=b264c743-2e35-0f86-8126-48cda5afc6ec tp_index=1
[2022-05-27T20:26:53+03:00] INFO [stun_client]: NAT Type: Restricted NAT
[2022-05-27T20:26:53+03:00] INFO [stun_client]: Public IP: 45.82.33.160:52363
[2022-05-27T20:26:53+03:00] INFO [stun_client]: Initialized in 10.162135434s (10.162135744s with dependencies)
[2022-05-27T20:26:53+03:00] INFO [transport_manager]: Serving sudph network
[2022-05-27T20:26:53+03:00] INFO [transport_manager]: listening on network: sudph
[2022-05-27T20:26:53+03:00] INFO [sudph]: Binding
[2022-05-27T20:26:53+03:00] INFO [sudph]: Initialized in 4.493721ms (10.168098939s with dependencies)
[2022-05-27T20:26:53+03:00] INFO [transports]: Initialized in 551ns (10.170490799s with dependencies)
[2022-05-27T20:26:53+03:00] INFO [address_resolver]: SUDPH Local port: 38591
[2022-05-27T20:26:53+03:00] INFO [sudph]: Successfully bound sudph to port 38591
[2022-05-27T20:26:53+03:00] INFO [sudph]: listening on addr: [::]:38591
[2022-05-27T20:26:53+03:00] INFO [public_autoconnect]: Fetching public visors
[2022-05-27T20:26:53+03:00] INFO [stcpr]: Dialing PK 02df18ba2accf1797e9ed46c0d3ead8a88b05740ba3c25df7d4f0d0d7b3009738d
[2022-05-27T20:26:54+03:00] INFO [stcpr]: Resolved PK 02df18ba2accf1797e9ed46c0d3ead8a88b05740ba3c25df7d4f0d0d7b3009738d to visor data {194.5.192.160 false {33233 [127.0.0.1 194.5.192.160 ::1]}}
[2022-05-27T20:26:54+03:00] INFO [stcpr]: Performing handshake with 194.5.192.160:33233
[2022-05-27T20:26:54+03:00] INFO [stcpr]: Sent handshake to 194.5.192.160:33233, local addr 02050e01749af8e487c320203363b260cb27c1481e92225f4ab40e8d0c0b0648b2:49153, remote addr 02df18ba2accf1797e9ed46c0d3ead8a88b05740ba3c25df7d4f0d0d7b3009738d:45
[2022-05-27T20:26:54+03:00] INFO [transport_manager]: saved transport: remote(02df18ba2accf1797e9ed46c0d3ead8a88b05740ba3c25df7d4f0d0d7b3009738d) type(stcpr) tpID(2a5f91a0-215d-0ae9-9e55-0f80a4769fe4)
[2022-05-27T20:26:54+03:00] INFO [tp:02df18]: Serving. remote_pk=02df18ba2accf1797e9ed46c0d3ead8a88b05740ba3c25df7d4f0d0d7b3009738d tp_id=2a5f91a0-215d-0ae9-9e55-0f80a4769fe4 tp_index=1

Of these, I could see the config version and path maybe being relevant to the user. A message when startup has been completed could also be relevant as well as the hypervisorUI address. Other than that I think we should only display warnings and errors. All the module initialization details are completely irrelevant to the user of Skywire and can be safely deleted or moved to DEBUG.

Is your feature request related to a problem? Please describe.
Log output is overwhelming without much substance.

Describe the solution you'd like
Move most of the logs to DEBUG or delete them. Targets for deletion

  • time of module initialization
  • module initialization statements
@jdknives jdknives added the enhancement New feature or request label May 27, 2022
This was referenced Jun 10, 2022
Merged
Merged
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
enhancement New feature or request
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@jdknives