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

log missing during core start/stop #2976

Open
povsister opened this issue Apr 17, 2024 · 1 comment
Open

log missing during core start/stop #2976

povsister opened this issue Apr 17, 2024 · 1 comment

Comments

@povsister
Copy link

What version of V2Ray are you using?

master build
V2Ray 5.15.1 (V2Fly, a community-driven edition of V2Ray.) Custom (go1.22.2 linux/amd64)

What's your scenario of using V2Ray?

Not related

What problems have you encountered?

logs are missing during v2ray-core starting / stopping.

What's your expectation?

Completed log output should be sent and processed by log handler during starting / stopping.

Please attach your configuration here

{
  "log": {
    "loglevel": "debug"
  }
}

Server configuration:

// Not related

Client configuration:

// Not related

Logs output got during stop

No debug logs output when I hit Ctrl-C

2024/04/17 13:51:45 [Debug] app/dns: domain fonts.gstatic.com will use DNS in order: [UDP:116.228.111.118:53 DOH//1.1.1.1] [TypeA]
2024/04/17 13:51:45 [Debug] app/dns: UDP:116.228.111.118:53 querying DNS for: fonts.gstatic.com.
2024/04/17 13:51:45 [Debug] transport/internet/udp: dispatch request to: udp:116.228.111.118:53
2024/04/17 13:51:45 [Debug] transport/internet/udp: UDP original destination: udp:192.168.87.9:53
2024/04/17 13:51:45 [Debug] [3389796255] proxy/dokodemo: processing connection from: 192.168.87.1:40438
2024/04/17 13:51:45 [Info] [3389796255] proxy/dokodemo: received request for 192.168.87.1:40438
2024/04/17 13:51:45 [Info] [3389796255] app/dispatcher: taking detour [dns-out] for [udp:192.168.87.9:53]
2024/04/17 13:51:45 [Info] [3389796255] proxy/dns: handling DNS traffic to udp:192.168.87.9:53
2024/04/17 13:51:45 192.168.87.1:40438 accepted udp:192.168.87.9:53 [dns-out]
2024/04/17 13:51:45 [Info] app/dns: UDP:116.228.111.118:53 got answer: fonts.gstatic.com. TypeA -> [203.208.50.162] 2.203529ms
2024/04/17 13:51:45 [Debug] app/dns: UDP:116.228.111.118:53 updating IP records for domain:fonts.gstatic.com.
2024/04/17 13:51:45 [Debug] transport/internet/udp: UDP original destination: udp:192.168.87.9:53
2024/04/17 13:51:45 [Debug] [1341554531] proxy/dokodemo: processing connection from: 192.168.87.1:53992
2024/04/17 13:51:45 [Info] [1341554531] proxy/dokodemo: received request for 192.168.87.1:53992
2024/04/17 13:51:45 [Info] [1341554531] app/dispatcher: taking detour [dns-out] for [udp:192.168.87.9:53]
2024/04/17 13:51:45 [Info] [1341554531] proxy/dns: handling DNS traffic to udp:192.168.87.9:53
2024/04/17 13:51:45 192.168.87.1:53992 accepted udp:192.168.87.9:53 [dns-out]
2024/04/17 13:51:46 [Debug] app/dnscircuit/ospf: received 192.168.87.1->224.0.0.5 OSPFv2 | Link State Acknowledgment | PacketLength: 44
AreaId: 0 | RouterId: 192.168.87.1
LSAcknowledgement Content:
  {LSAge:1 LSType:5 LinkStateID:2899947008 AdvRouter:3232257801 LSSeqNumber:2147483649 LSChecksum:49626 Length:36 LSOptions:2}
^C2024/04/17 13:51:46 [Debug] app/log: Logger closing // <--- This is where I hit Ctrl-C
root@debianpov:~#

Logs output expected during stop

Expection: Debug logs during stopping should still be printed when I hit Ctrl-C.

This is done by commenting log app close

2024/04/17 13:55:13 [Debug] transport/internet/udp: UDP original destination: udp:104.25.62.106:443
2024/04/17 13:55:13 [Debug] [467673545] proxy/dokodemo: processing connection from: 218.81.220.135:60025
2024/04/17 13:55:13 [Info] [467673545] proxy/dokodemo: received request for 218.81.220.135:60025
2024/04/17 13:55:13 [Warning] [467673545] app/dispatcher: default route for udp:104.25.62.106:443
2024/04/17 13:55:13 [Info] [467673545] proxy/freedom: opening connection to udp:104.25.62.106:443
2024/04/17 13:55:13 218.81.220.135:60025 accepted udp:104.25.62.106:443 [direct]
2024/04/17 13:55:13 [Debug] transport/internet/udp: UDP original destination: udp:192.168.87.9:53
2024/04/17 13:55:13 [Debug] [3741104488] proxy/dokodemo: processing connection from: 192.168.87.1:42201
2024/04/17 13:55:13 [Info] [3741104488] proxy/dokodemo: received request for 192.168.87.1:42201
2024/04/17 13:55:13 [Info] [3741104488] app/dispatcher: taking detour [dns-out] for [udp:192.168.87.9:53]
2024/04/17 13:55:13 [Info] [3741104488] proxy/dns: handling DNS traffic to udp:192.168.87.9:53
2024/04/17 13:55:13 192.168.87.1:42201 accepted udp:192.168.87.9:53 [dns-out]
2024/04/17 13:55:13 [Debug] app/dnscircuit/ospf: received 192.168.87.1->224.0.0.5 OSPFv2 | Link State Acknowledgment | PacketLength: 84
AreaId: 0 | RouterId: 192.168.87.1
LSAcknowledgement Content:
  {LSAge:1 LSType:5 LinkStateID:1746484736 AdvRouter:3232257801 LSSeqNumber:2147483649 LSChecksum:6138 Length:36 LSOptions:2}
  {LSAge:1 LSType:5 LinkStateID:1746484480 AdvRouter:3232257801 LSSeqNumber:2147483649 LSChecksum:8944 Length:36 LSOptions:2}
  {LSAge:1 LSType:5 LinkStateID:2890097152 AdvRouter:3232257801 LSSeqNumber:2147483649 LSChecksum:6247 Length:36 LSOptions:2}
^C2024/04/17 13:55:13 [Debug] app/log: Logger closing // <--- This is where I hit Ctrl-C
2024/04/17 13:55:13 [Info] transport/internet/udp: failed to read UDP msg > read udp 127.0.0.1:12345: use of closed network connection
2024/04/17 13:55:13 [Debug] app/dnscircuit/ospf: flushing 4 self-originated external LSAs before shutting down
2024/04/17 13:55:13 [Debug] app/dnscircuit/ospf: area 0 is pre-maturing LSA({LSType:5 LinkStateId:3030619648 AdvRouter:3232257801})
2024/04/17 13:55:13 [Debug] app/dnscircuit/ospf: area 0 is pre-maturing LSA({LSType:5 LinkStateId:1746484736 AdvRouter:3232257801})
2024/04/17 13:55:13 [Debug] app/dnscircuit/ospf: area 0 is pre-maturing LSA({LSType:5 LinkStateId:1746484480 AdvRouter:3232257801})
2024/04/17 13:55:13 [Debug] app/dnscircuit/ospf: area 0 is pre-maturing LSA({LSType:5 LinkStateId:2890097152 AdvRouter:3232257801})
2024/04/17 13:55:13 [Debug] app/dnscircuit/ospf: area 0 flushing 1 self-originated LSAs before shutting down
2024/04/17 13:55:13 [Debug] app/dnscircuit/ospf: area 0 is pre-maturing LSA({LSType:1 LinkStateId:3232257801 AdvRouter:3232257801})
2024/04/17 13:55:13 [Debug] app/dnscircuit/ospf: sent via interface ens192 192.168.87.9->224.0.0.6 OSPFv2 | Link State Update | PacketLength: 172
AreaId: 0 | RouterId: 192.168.87.9
LSUpdate Content:
  NumOfLSAs: 4
  LSAheader: {LSAge:3600 LSType:5 LinkStateID:3030619648 AdvRouter:3232257801 LSSeqNumber:2147483649 LSChecksum:60661 Length:36 LSOptions:2}
LSAContent: {NetworkMask:4294967040  ExternalBit:128 Metric:10000 ForwardingAddress:0 ExternalRouteTag: 0}
  LSAheader: {LSAge:3600 LSType:5 LinkStateID:1746484736 AdvRouter:3232257801 LSSeqNumber:2147483649 LSChecksum:6138 Length:36 LSOptions:2}
LSAContent: {NetworkMask:4294967040  ExternalBit:128 Metric:10000 ForwardingAddress:0 ExternalRouteTag: 0}
  LSAheader: {LSAge:3600 LSType:5 LinkStateID:1746484480 AdvRouter:3232257801 LSSeqNumber:2147483649 LSChecksum:8944 Length:36 LSOptions:2}
LSAContent: {NetworkMask:4294967040  ExternalBit:128 Metric:10000 ForwardingAddress:0 ExternalRouteTag: 0}
  LSAheader: {LSAge:3600 LSType:5 LinkStateID:2890097152 AdvRouter:3232257801 LSSeqNumber:2147483649 LSChecksum:6247 Length:36 LSOptions:2}
LSAContent: {NetworkMask:4294967040  ExternalBit:128 Metric:10000 ForwardingAddress:0 ExternalRouteTag: 0}
2024/04/17 13:55:13 [Debug] app/dnscircuit/ospf: sent via interface ens192 192.168.87.9->224.0.0.6 OSPFv2 | Link State Update | PacketLength: 64
AreaId: 0 | RouterId: 192.168.87.9
LSUpdate Content:
  NumOfLSAs: 1
  LSAheader: {LSAge:3600 LSType:1 LinkStateID:3232257801 AdvRouter:3232257801 LSSeqNumber:2147483650 LSChecksum:50785 Length:36 LSOptions:2}
LSAContent: {Flags:2 Links:1 Routers:[{Type:2 LinkId:3232257793 LinkData: 3232257801 Metric:10 TOSNum:0 TOSs:[]}]}
2024/04/17 13:55:14 [Debug] app/dnscircuit/ospf: received 192.168.87.1->224.0.0.5 OSPFv2 | Link State Acknowledgment | PacketLength: 124
AreaId: 0 | RouterId: 192.168.87.1
LSAcknowledgement Content:
  {LSAge:3600 LSType:5 LinkStateID:3030619648 AdvRouter:3232257801 LSSeqNumber:2147483649 LSChecksum:60661 Length:36 LSOptions:2}
  {LSAge:3600 LSType:5 LinkStateID:1746484736 AdvRouter:3232257801 LSSeqNumber:2147483649 LSChecksum:6138 Length:36 LSOptions:2}
  {LSAge:3600 LSType:5 LinkStateID:1746484480 AdvRouter:3232257801 LSSeqNumber:2147483649 LSChecksum:8944 Length:36 LSOptions:2}
  {LSAge:3600 LSType:5 LinkStateID:2890097152 AdvRouter:3232257801 LSSeqNumber:2147483649 LSChecksum:6247 Length:36 LSOptions:2}
  {LSAge:3600 LSType:1 LinkStateID:3232257801 AdvRouter:3232257801 LSSeqNumber:2147483650 LSChecksum:50785 Length:36 LSOptions:2}
2024/04/17 13:55:14 [Debug] app/dnscircuit/ospf: exiting ens192 runSendLoop
2024/04/17 13:55:14 [Debug] app/dnscircuit/ospf: exiting ens192 runReadDispatchLoop
2024/04/17 13:55:15 [Debug] app/dnscircuit/ospf: exiting ens192 runReadLoop
root@debianpov:~#
@povsister
Copy link
Author

From what I've seen, this is caused by improper sequence of starting / stopping features, as log is designed to be a plugable feature too.
I am considering add an interface like IsLogHandlerApp in log handler registry, to help core tell which app "looks like" a log handler, then it can explicitly manipulate the sequence during start and stop.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@povsister