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

Clean logs #1252

Merged
merged 56 commits into from
Jun 17, 2022
Merged

Clean logs #1252

merged 56 commits into from
Jun 17, 2022

Conversation

ersonp
Copy link
Contributor

@ersonp ersonp commented Jun 10, 2022

Did you run make format && make check?
yes

Fixes #1234

Changes:

  • Changed repetitive logs to trace
  • Changed Extra-informative logs to debug
  • Added Info logs where needed
  • Fixed some closing logs
  • Set Stdout of proc to Debug
  • Set Stderr of proc to Error
  • Removed logs from apps
  • Changed info logs to fmt.Print in apps
  • Changed error logs to print() in apps
  • Removed unnecessary lock and unlock logs

How to test this PR:

  1. Checkout #skywire-utilities-25
  2. Checkout #dmsg-176
  3. In dmsg in the file go.mod uncomment replace github.com/skycoin/skywire-utilities => ../skywire-utilities and run make dep
  4. In skywire in the file go.mod uncomment replace github.com/skycoin/skywire-utilities => ../skywire-utilities and replace github.com/skycoin/dmsg => ../dmsg and run make dep; make build
  5. Set the log_level in the config to info, debug, and trace and test the functionalities and apps of the visor
  6. Check logs

This commit changes the info logs to debug and deletes the logs from the method readPacket as they are repetative and don't offer much in terms of debugging.
This commit changes the info logs to debug and deletes the logs that are just used to notify about lock and unlock..
This commit changes the info logs to debug and and along with that adds a WithField method to the logs of the methods with the func as the field insted of having the name of the method in the log.
@ersonp ersonp changed the title Clean/logs Clean logs Jun 10, 2022
ersonp added 22 commits June 10, 2022 12:29
This commit changes the info logs to debug and adds a startup finished info log.
This commit fixes the error log by printing it only if the error is not equal to context cancled.
This commit removes the Requesting and Obtained log for summary via RPC as it is a recurring log and is not usefull.
This commit changes the log level of Stdout to Debug and Stderr to Error instead of both being Info.
This commit updates the vpn-client logs by printing the error logs with print() that uses the Stderr to write out the errors.

We also get rid of *logrus.Logger in client as it was also writing logs to Stderr instead of Stdout as we need our non error logs to be.
This commit fixes the error log printed when the RouteGroup is already closed.
@ersonp ersonp marked this pull request as ready for review June 15, 2022 09:08
This commit fixes the entry log in the method RegisterEntry of HTTPClient by adding a String method to the reciever Service which returns a string of the Marshalled struct and also using the String method of the Addr struct inside it.
@jdknives
Copy link
Member

[2022-06-15T16:33:38+02:00] INFO [buildinfo]:  version="v1.0.0-rc5-57-g5087c8a0" built on="2022-06-15T14:33:22Z" commit="5087c8a04000788d2d6745587cb097cb49f75346"
[2022-06-15T16:33:38+02:00] INFO [visor:config]: Reading config from file.
[2022-06-15T16:33:38+02:00] INFO [visor:config]: filepath="skywire-config.json"
[2022-06-15T16:33:38+02:00] INFO [visor:config]: config version: ="v1.0.0-rc5-57-g5087c8a0"
[2022-06-15T16:33:38+02:00] INFO [visor:startup]: Begin startup. public_key=0365e4bb732cdc979e6fd93e74e48f3e6f04df26554928e640e4794834bdf42e9a
[2022-06-15T16:33:46+02:00] INFO [visor]: Serving hypervisor... addr=":8000" tls=false
[2022-06-15T16:33:49+02:00] INFO [stun_client]: NAT Type: Restricted NAT
[2022-06-15T16:33:49+02:00] INFO [stun_client]: Public IP: 194.233.96.200:57759
[2022-06-15T16:33:49+02:00] INFO [visor:startup]: Startup complete.
[2022-06-15T16:33:51+02:00] WARN [public_autoconnect]: Failed to add transport to public visor error="save transport: mt.client.Dial: resolve PK: no entry for this PK" pk=03b5468ac5c19bc4ce14e759ff5f1fb78274a5ed615439f1be7af0da7e29ac4dec type="stcpr"
[2022-06-15T16:33:51+02:00] WARN [public_autoconnect]: Failed to add transport to public visor error="save transport: mt.client.Dial: resolve PK: no entry for this PK" pk=02111387c63780fcb82b6b841cb08b57a08985c466b55999f1a80be3524412bf94 type="stcpr"
^C[2022-06-15T16:33:55+02:00] INFO []: Closing with received signal. signal=interrupt
[2022-06-15T16:33:55+02:00] INFO [visor:shutdown]: Begin shutdown.
2022/06/15 16:33:55 rpc.Serve: accept:accept tcp 127.0.0.1:3435: use of closed network connection
[2022-06-15T16:33:56+02:00] INFO [visor:shutdown]: Shutdown complete. Goodbye! 

The first five lines of logs can be simplified. No need to say we are reading config from file as its default behavior. Since visor and config version are the same, we can omit the second log of the version. Can print a log line if we update the config. Config path and version can be printed on the same line imo.

@jdknives
Copy link
Member

I would also update documentation in the wiki with the new log level. Are we getting the debug logs in the hypervisor log endpoint or just info?

@ersonp
Copy link
Contributor Author

ersonp commented Jun 15, 2022

I would also update documentation in the wiki with the new log level. Are we getting the debug logs in the hypervisor log endpoint or just info?

Yes, will update the wiki with the new log level.
And as for the second part if I understood you correctly, currently the hypervisor logs from chi are as info but as mentioned my @mrpalide that should be moved to debug and I'll work on it as soon as I fix some other issues.

@ersonp
Copy link
Contributor Author

ersonp commented Jun 15, 2022

[2022-06-15T16:33:38+02:00] INFO [buildinfo]:  version="v1.0.0-rc5-57-g5087c8a0" built on="2022-06-15T14:33:22Z" commit="5087c8a04000788d2d6745587cb097cb49f75346"
[2022-06-15T16:33:38+02:00] INFO [visor:config]: Reading config from file.
[2022-06-15T16:33:38+02:00] INFO [visor:config]: filepath="skywire-config.json"
[2022-06-15T16:33:38+02:00] INFO [visor:config]: config version: ="v1.0.0-rc5-57-g5087c8a0"
[2022-06-15T16:33:38+02:00] INFO [visor:startup]: Begin startup. public_key=0365e4bb732cdc979e6fd93e74e48f3e6f04df26554928e640e4794834bdf42e9a
[2022-06-15T16:33:46+02:00] INFO [visor]: Serving hypervisor... addr=":8000" tls=false
[2022-06-15T16:33:49+02:00] INFO [stun_client]: NAT Type: Restricted NAT
[2022-06-15T16:33:49+02:00] INFO [stun_client]: Public IP: 194.233.96.200:57759
[2022-06-15T16:33:49+02:00] INFO [visor:startup]: Startup complete.
[2022-06-15T16:33:51+02:00] WARN [public_autoconnect]: Failed to add transport to public visor error="save transport: mt.client.Dial: resolve PK: no entry for this PK" pk=03b5468ac5c19bc4ce14e759ff5f1fb78274a5ed615439f1be7af0da7e29ac4dec type="stcpr"
[2022-06-15T16:33:51+02:00] WARN [public_autoconnect]: Failed to add transport to public visor error="save transport: mt.client.Dial: resolve PK: no entry for this PK" pk=02111387c63780fcb82b6b841cb08b57a08985c466b55999f1a80be3524412bf94 type="stcpr"
^C[2022-06-15T16:33:55+02:00] INFO []: Closing with received signal. signal=interrupt
[2022-06-15T16:33:55+02:00] INFO [visor:shutdown]: Begin shutdown.
2022/06/15 16:33:55 rpc.Serve: accept:accept tcp 127.0.0.1:3435: use of closed network connection
[2022-06-15T16:33:56+02:00] INFO [visor:shutdown]: Shutdown complete. Goodbye! 

The first five lines of logs can be simplified. No need to say we are reading config from file as its default behavior. Since visor and config version are the same, we can omit the second log of the version. Can print a log line if we update the config. Config path and version can be printed on the same line imo.

The version log

[2022-06-15T16:33:38+02:00] INFO [buildinfo]:  version="v1.0.0-rc5-57-g5087c8a0" built on="2022-06-15T14:33:22Z" commit="5087c8a04000788d2d6745587cb097cb49f75346"

Fixed the first part but about the Config path and version being on the same line, I think it is better to keep them separate as the version is in the build info and the config path is basically the config info.

This commit fixes the vpn-client not working issue that was introduced by the commit 920461c since it passed eventSub to the appclient before running eventSub.OnTCPDial and eventSub.OnTCPClose which caused the vpn-client to not work as intended.

We fix it by running them first before passing the eventSub to app.NewClient.
This commit adds a condition to use the logger middleware in chi only when the log level is either debug or trace.
@jdknives jdknives merged commit afed86e into skycoin:develop Jun 17, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants