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

EOF on visor shutdown in dmsghttp #1040

Closed
ersonp opened this issue Dec 31, 2021 · 1 comment
Closed

EOF on visor shutdown in dmsghttp #1040

ersonp opened this issue Dec 31, 2021 · 1 comment
Labels
bug Something isn't working

Comments

@ersonp
Copy link
Contributor

ersonp commented Dec 31, 2021

Describe the bug
There is an EOF warning message from public autoconnect and app_discovery retriers on visor shutdown. The issue may be that the retry func runs during the dmsghttp module shutdown process.

Environment information:

  • OS: e.g. Linux
  • Platform: Linux 5.11.0-43-generic x86_64

Steps to Reproduce
Steps to reproduce the behavior:

  1. Run ./skywire-cli config gen -dirt
  2. Change log_level to debug in the config
  3. Run ./skywire-visor -c skywire-config.json and stop the visor with Ctrl+C after stun module is initilized (Might have to try multiple times)
  4. See error

Actual behavior

[2021-12-31T10:24:01+05:30] INFO [4/13] [visor:shutdown:dmsg]: Module stopped cleanly. elapsed=320.701185ms
[2021-12-31T10:24:01+05:30] INFO [3/13] [visor:shutdown:dmsg_http]: Shutting down module...
[2021-12-31T10:24:01+05:30] INFO [dmsg_http:dmsgDC]: Stopped serving client!
[2021-12-31T10:24:01+05:30] INFO [dmsg_http:dmsgDC]: Stopped accepting streams. error="session shutdown" session=024716428e6315d954356e9ad72bea32bb2b41aab5a54a9b5cb4313964016e64d8
[2021-12-31T10:24:01+05:30] INFO [dmsg_http:dmsgDC]: Session closed. error=<nil>
[2021-12-31T10:24:01+05:30] DEBUG ClientSession.DialStream [dmsg_http:dmsgDC]: Stream closed on failure. close_error=<nil> dst_addr=038f751df4af75fb3d51f6693602bfe8289145e633ffdd1e67d686bea595f84d55:80 error="EOF" session=024716428e6315d954356e9ad72bea32bb2b41aab5a54a9b5cb4313964016e64d8
[2021-12-31T10:24:01+05:30] DEBUG ClientSession.DialStream [dmsg_http:dmsgDC]: Stream closed on failure. close_error=<nil> dst_addr=038f751df4af75fb3d51f6693602bfe8289145e633ffdd1e67d686bea595f84d55:80 error="EOF" session=024716428e6315d954356e9ad72bea32bb2b41aab5a54a9b5cb4313964016e64d8
[2021-12-31T10:24:02+05:30] WARN [app_discovery]: Failed to register service entry in discovery. Retrying... appName="skysocks" error="Get "dmsg://038f751df4af75fb3d51f6693602bfe8289145e633ffdd1e67d686bea595f84d55:80/security/nonces/02aa6fc7009d31622705cb3f2feaa8fe0da10c2ae081cf52e7ba7672bf097defad": EOF"
[2021-12-31T10:24:02+05:30] INFO [dmsg_http:dmsgDC]: All sessions closed.
[2021-12-31T10:24:02+05:30] WARN retrier [public_autoconnect]: Get "dmsg://038f751df4af75fb3d51f6693602bfe8289145e633ffdd1e67d686bea595f84d55:80/api/services?quantity=3&type=visor": EOF
[2021-12-31T10:24:02+05:30] WARN retrier [app_discovery]: Get "dmsg://038f751df4af75fb3d51f6693602bfe8289145e633ffdd1e67d686bea595f84d55:80/security/nonces/02aa6fc7009d31622705cb3f2feaa8fe0da10c2ae081cf52e7ba7672bf097defad": EOF appName="skysocks"
[2021-12-31T10:24:02+05:30] DEBUG [dmsg_http:dmsgDC]: Deleting entry. entry=    version: 
        sequence: 0
        registered at: 0
        static public key: 029bc0e047334db0161ca5b26db404d45c520477f321a81d079e46ddefd10f9017
        signature: 
        entry is registered as client. Related info: 
                delegated servers: 
                        024716428e6315d954356e9ad72bea32bb2b41aab5a54a9b5cb4313964016e64d8


[2021-12-31T10:24:02+05:30] DEBUG [dmsg_http:dmsgDC]: Entry Deleted successfully.
[2021-12-31T10:24:02+05:30] INFO [dmsg_http:dmsgDC]: Disconnected from dmsg network. error=<nil>
[2021-12-31T10:24:02+05:30] INFO [3/13] [visor:shutdown:dmsg_http]: Module stopped cleanly. elapsed=50.452952ms
[2021-12-31T10:24:02+05:30] INFO [2/13] [visor:shutdown:event_broadcaster]: Shutting down module...
[2021-12-31T10:24:02+05:30] INFO [2/13] [visor:shutdown:event_broadcaster]: Module stopped cleanly. elapsed=4.552828ms
[2021-12-31T10:24:02+05:30] INFO [1/13] [visor:shutdown:cli.listener]: Shutting down module...
2021/12/31 10:24:02 rpc.Serve: accept:accept tcp 127.0.0.1:3435: use of closed network connection
[2021-12-31T10:24:02+05:30] INFO [1/13] [visor:shutdown:cli.listener]: Module stopped cleanly. elapsed=4.554944ms
[2021-12-31T10:24:02+05:30] INFO [visor:shutdown]: Shutdown complete. Goodbye!
@ersonp ersonp added the bug Something isn't working label Dec 31, 2021
@ersonp
Copy link
Contributor Author

ersonp commented Feb 8, 2022

[2022-02-08T10:17:59+05:30] INFO [dmsg_pty:cli-server]: Cleanly stopped serving.
[2022-02-08T10:17:59+05:30] INFO [6/14] [visor:shutdown:router.serve]: Module stopped cleanly. elapsed=9.397023ms
[2022-02-08T10:17:59+05:30] INFO [5/14] [visor:shutdown:router.serve]: Shutting down module...
[2022-02-08T10:17:59+05:30] INFO [dmsg_pty]: Serve() ended. error=<nil>
[2022-02-08T10:17:59+05:30] INFO [dmsg_pty]: Cleanly stopped serving. error="dmsg error 200 - local entity closed"
[2022-02-08T10:17:59+05:30] INFO [5/14] [visor:shutdown:router.serve]: Module stopped cleanly. elapsed=12.197792ms
[2022-02-08T10:17:59+05:30] INFO [4/14] [visor:shutdown:dmsg]: Shutting down module...
[2022-02-08T10:17:59+05:30] INFO [dmsgC]: Stopped serving client!
[2022-02-08T10:17:59+05:30] INFO [dmsgC]: Stopped accepting streams. error="session shutdown" session=024716428e6315d954356e9ad72bea32bb2b41aab5a54a9b5cb4313964016e64d8
[2022-02-08T10:17:59+05:30] INFO [dmsgC]: Session closed. error=<nil>
[2022-02-08T10:17:59+05:30] WARN github.com/skycoin/skywire/pkg/visor/dmsgtracker.(*Manager).updateAllTrackers [dmsg_trackers]: Removing dmsg client tracker. client_pk=02aa6fc7009d31622705cb3f2feaa8fe0da10c2ae081cf52e7ba7672bf097defad error="EOF"
[2022-02-08T10:17:59+05:30] INFO [dmsgC]: All sessions closed.
[2022-02-08T10:17:59+05:30] INFO [visor]: Dmsg client stopped serving. error="dmsg error 200 - local entity closed"
[2022-02-08T10:17:59+05:30] INFO [transport_manager]: Dmsg client stopped serving. error="dmsg error 200 - local entity closed"
[2022-02-08T10:18:00+05:30] INFO [4/14] [visor:shutdown:dmsg]: Module stopped cleanly. elapsed=523.852656ms
[2022-02-08T10:18:00+05:30] INFO [3/14] [visor:shutdown:dmsg_http]: Shutting down module...
[2022-02-08T10:18:00+05:30] INFO [dmsg_http:dmsgDC]: Stopped serving client!
[2022-02-08T10:18:00+05:30] INFO [dmsg_http:dmsgDC]: Session closed. error=<nil>
[2022-02-08T10:18:00+05:30] INFO [dmsg_http:dmsgDC]: Stopped accepting streams. error="session shutdown" session=024716428e6315d954356e9ad72bea32bb2b41aab5a54a9b5cb4313964016e64d8
[2022-02-08T10:18:00+05:30] INFO [dmsg_http:dmsgDC]: All sessions closed.
[2022-02-08T10:18:00+05:30] INFO [dmsg_http:dmsgDC]: Disconnected from dmsg network. error=<nil>
[2022-02-08T10:18:00+05:30] INFO [3/14] [visor:shutdown:dmsg_http]: Module stopped cleanly. elapsed=25.1559ms
[2022-02-08T10:18:00+05:30] INFO [2/14] [visor:shutdown:cli.listener]: Shutting down module...
2022/02/08 10:18:00 rpc.Serve: accept:accept tcp 127.0.0.1:3435: use of closed network connection
[2022-02-08T10:18:00+05:30] INFO [2/14] [visor:shutdown:cli.listener]: Module stopped cleanly. elapsed=4.610284ms
[2022-02-08T10:18:00+05:30] INFO [1/14] [visor:shutdown:event_broadcaster]: Shutting down module...
[2022-02-08T10:18:00+05:30] INFO [1/14] [visor:shutdown:event_broadcaster]: Module stopped cleanly. elapsed=4.633007ms
[2022-02-08T10:18:00+05:30] INFO [visor:shutdown]: Shutdown complete. Goodbye!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

2 participants