Skip to content

BR: Fix racy log #2783

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
Merged
merged 1 commit into from
Jun 20, 2019
Merged

BR: Fix racy log #2783

merged 1 commit into from
Jun 20, 2019

Conversation

oncilla
Copy link
Contributor

@oncilla oncilla commented Jun 20, 2019 •
edited by kormat
Loading

The border router prints the socket to the logs, whil parts can still
be modified by another go routine. This shows up during race detection.

Most of the logged information is pointers, which is not really useful.
This PR reduces the logged information and makes sure no race condition
occur.

Before:

2019-06-20 12:21:21.468642+0000 [DBUG] Setting up new local socket. bind=[127.0.0.17]:31008
2019-06-20 12:21:21.468693+0000 [DBUG] Done setting up new local socket. conn=[127.0.0.17]:31008
2019-06-20 12:21:21.468699+0000 [DBUG] Setting up new external socket. intf="&{Id:11 IFAddr:TopoBRAddr{IPv4:{PublicOverlay: [127.0.0.5]:50000 BindOverlay: <nil>},Overlay: UDP/IPv4} RemoteAddr:[127.0.0.4]:50000 RemoteIA:1-ff00:0:110 BW:1000 MTU:1280 Type:parent}"
2019-06-20 12:21:21.468754+0000 [DBUG] Done setting up new external socket. intf="&{Id:11 IFAddr:TopoBRAddr{IPv4:{PublicOverlay: [127.0.0.5]:50000 BindOverlay: <nil>},Overlay: UDP/IPv4} RemoteAddr:[127.0.0.4]:50000 RemoteIA:1-ff00:0:110 BW:1000 MTU:1280 Type:parent}"
2019-06-20 12:21:21.468790+0000 [INFO] Sock routines started addr=[127.0.0.17]:31008
2019-06-20 12:21:21.468795+0000 [INFO] Sock routines started addr=[127.0.0.17]:31008
2019-06-20 12:21:21.468798+0000 [INFO] Sock routines started addr=[127.0.0.5]:50000
2019-06-20 12:21:21.468801+0000 [INFO] Sock routines started addr=[127.0.0.5]:50000
2019-06-20 12:21:21.468813+0000 [INFO] posixInput starting addr=[127.0.0.17]:31008
2019-06-20 12:21:21.468846+0000 [INFO] posixOutput starting addr=[127.0.0.5]:50000
2019-06-20 12:21:21.468854+0000 [DBUG] handleSock starting sock="{Ring:0xc000168240 Conn:0xc0001b2900 Dir:External Ifid:11 Labels:map[sock:intf:11] Reader:0xc1d410 Writer:0xc1d470 Type:posix stop:0xc0001b6900 readerStopped:0xc0001b6960 writerStopped:0xc0001b69c0 running:true started:true}"
2019-06-20 12:21:21.468807+0000 [DBUG] handleSock starting sock="{Ring:0xc00016dec0 Conn:0xc0001b2680 Dir:Local Ifid:0 Labels:map[sock:loc] Reader:0xc1d410 Writer:0xc1d470 Type:posix stop:0xc0001b6480 readerStopped:0xc0001b6660 writerStopped:0xc0001b6720 running:true started:true}"
2019-06-20 12:21:21.468834+0000 [INFO] posixInput starting addr=[127.0.0.5]:50000
2019-06-20 12:21:21.468838+0000 [INFO] posixOutput starting addr=[127.0.0.17]:31008

Now:

2019-06-20 12:20:44.841055+0000 [DBUG] Setting up new local socket. bind=[127.0.0.17]:31008
2019-06-20 12:20:44.841277+0000 [DBUG] Done setting up new local socket. conn=[127.0.0.17]:31008
2019-06-20 12:20:44.841316+0000 [DBUG] Setting up new external socket. intf="&{Id:11 IFAddr:TopoBRAddr{IPv4:{PublicOverlay: [127.0.0.5]:50000 BindOverlay: <nil>},Overlay: UDP/IPv4} RemoteAddr:[127.0.0.4]:50000 RemoteIA:1-ff00:0:110 BW:1000 MTU:1280 Type:parent}"
2019-06-20 12:20:44.841558+0000 [DBUG] Done setting up new external socket. intf="&{Id:11 IFAddr:TopoBRAddr{IPv4:{PublicOverlay: [127.0.0.5]:50000 BindOverlay: <nil>},Overlay: UDP/IPv4} RemoteAddr:[127.0.0.4]:50000 RemoteIA:1-ff00:0:110 BW:1000 MTU:1280 Type:parent}"
2019-06-20 12:20:44.842080+0000 [INFO] Sock routines started addr=[127.0.0.17]:31008 dir=Local ifid=0 type=posix
2019-06-20 12:20:44.842105+0000 [DBUG] handleSock starting addr=[127.0.0.17]:31008
2019-06-20 12:20:44.842231+0000 [INFO] posixOutput starting addr=[127.0.0.17]:31008
2019-06-20 12:20:44.842093+0000 [INFO] posixInput starting addr=[127.0.0.17]:31008
2019-06-20 12:20:44.842221+0000 [INFO] Sock routines started addr=[127.0.0.17]:31008 dir=Local ifid=0 type=posix
2019-06-20 12:20:44.842586+0000 [INFO] posixInput starting addr=[127.0.0.5]:50000
2019-06-20 12:20:44.842663+0000 [DBUG] handleSock starting addr=[127.0.0.5]:50000
2019-06-20 12:20:44.842654+0000 [INFO] Sock routines started addr=[127.0.0.5]:50000 dir=External ifid=11 type=posix
2019-06-20 12:20:44.842925+0000 [INFO] Sock routines started addr=[127.0.0.5]:50000 dir=External ifid=11 type=posix
2019-06-20 12:20:44.842994+0000 [INFO] posixOutput starting addr=[127.0.0.5]:50000

Partially addresses #2774

This change is Reviewable

@oncilla
BR: Fix racy log
04e37f8 
The border router prints the socket to the logs, whil parts can still
be modified by another go routine. This shows up during race detection.

Most of the logged information is pointers, which is not really useful.
This PR reduces the logged information and makes sure no race condition
occur.

Before:
````
2019-06-20 12:21:21.468642+0000 [DBUG] Setting up new local socket. bind=[127.0.0.17]:31008
2019-06-20 12:21:21.468693+0000 [DBUG] Done setting up new local socket. conn=[127.0.0.17]:31008
2019-06-20 12:21:21.468699+0000 [DBUG] Setting up new external socket. intf="&{Id:11 IFAddr:TopoBRAddr{IPv4:{PublicOverlay: [127.0.0.5]:50000 BindOverlay: <nil>},Overlay: UDP/IPv4} RemoteAddr:[127.0.0.4]:50000 RemoteIA:1-ff00:0:110 BW:1000 MTU:1280 Type:parent}"
2019-06-20 12:21:21.468754+0000 [DBUG] Done setting up new external socket. intf="&{Id:11 IFAddr:TopoBRAddr{IPv4:{PublicOverlay: [127.0.0.5]:50000 BindOverlay: <nil>},Overlay: UDP/IPv4} RemoteAddr:[127.0.0.4]:50000 RemoteIA:1-ff00:0:110 BW:1000 MTU:1280 Type:parent}"
2019-06-20 12:21:21.468790+0000 [INFO] Sock routines started addr=[127.0.0.17]:31008
2019-06-20 12:21:21.468795+0000 [INFO] Sock routines started addr=[127.0.0.17]:31008
2019-06-20 12:21:21.468798+0000 [INFO] Sock routines started addr=[127.0.0.5]:50000
2019-06-20 12:21:21.468801+0000 [INFO] Sock routines started addr=[127.0.0.5]:50000
2019-06-20 12:21:21.468813+0000 [INFO] posixInput starting addr=[127.0.0.17]:31008
2019-06-20 12:21:21.468846+0000 [INFO] posixOutput starting addr=[127.0.0.5]:50000
2019-06-20 12:21:21.468854+0000 [DBUG] handleSock starting sock="{Ring:0xc000168240 Conn:0xc0001b2900 Dir:External Ifid:11 Labels:map[sock:intf:11] Reader:0xc1d410 Writer:0xc1d470 Type:posix stop:0xc0001b6900 readerStopped:0xc0001b6960 writerStopped:0xc0001b69c0 running:true started:true}"
2019-06-20 12:21:21.468807+0000 [DBUG] handleSock starting sock="{Ring:0xc00016dec0 Conn:0xc0001b2680 Dir:Local Ifid:0 Labels:map[sock:loc] Reader:0xc1d410 Writer:0xc1d470 Type:posix stop:0xc0001b6480 readerStopped:0xc0001b6660 writerStopped:0xc0001b6720 running:true started:true}"
2019-06-20 12:21:21.468834+0000 [INFO] posixInput starting addr=[127.0.0.5]:50000
2019-06-20 12:21:21.468838+0000 [INFO] posixOutput starting addr=[127.0.0.17]:31008
````

Now:
````
2019-06-20 12:20:44.841055+0000 [DBUG] Setting up new local socket. bind=[127.0.0.17]:31008
2019-06-20 12:20:44.841277+0000 [DBUG] Done setting up new local socket. conn=[127.0.0.17]:31008
2019-06-20 12:20:44.841316+0000 [DBUG] Setting up new external socket. intf="&{Id:11 IFAddr:TopoBRAddr{IPv4:{PublicOverlay: [127.0.0.5]:50000 BindOverlay: <nil>},Overlay: UDP/IPv4} RemoteAddr:[127.0.0.4]:50000 RemoteIA:1-ff00:0:110 BW:1000 MTU:1280 Type:parent}"
2019-06-20 12:20:44.841558+0000 [DBUG] Done setting up new external socket. intf="&{Id:11 IFAddr:TopoBRAddr{IPv4:{PublicOverlay: [127.0.0.5]:50000 BindOverlay: <nil>},Overlay: UDP/IPv4} RemoteAddr:[127.0.0.4]:50000 RemoteIA:1-ff00:0:110 BW:1000 MTU:1280 Type:parent}"
2019-06-20 12:20:44.842080+0000 [INFO] Sock routines started addr=[127.0.0.17]:31008 dir=Local ifid=0 type=posix
2019-06-20 12:20:44.842105+0000 [DBUG] handleSock starting addr=[127.0.0.17]:31008
2019-06-20 12:20:44.842231+0000 [INFO] posixOutput starting addr=[127.0.0.17]:31008
2019-06-20 12:20:44.842093+0000 [INFO] posixInput starting addr=[127.0.0.17]:31008
2019-06-20 12:20:44.842221+0000 [INFO] Sock routines started addr=[127.0.0.17]:31008 dir=Local ifid=0 type=posix
2019-06-20 12:20:44.842586+0000 [INFO] posixInput starting addr=[127.0.0.5]:50000
2019-06-20 12:20:44.842663+0000 [DBUG] handleSock starting addr=[127.0.0.5]:50000
2019-06-20 12:20:44.842654+0000 [INFO] Sock routines started addr=[127.0.0.5]:50000 dir=External ifid=11 type=posix
2019-06-20 12:20:44.842925+0000 [INFO] Sock routines started addr=[127.0.0.5]:50000 dir=External ifid=11 type=posix
2019-06-20 12:20:44.842994+0000 [INFO] posixOutput starting addr=[127.0.0.5]:50000

````

Partially addresses scionproto#2774

wip
@oncilla oncilla added the BR label Jun 20, 2019
@oncilla oncilla added this to the Q2S3 milestone Jun 20, 2019
@oncilla oncilla requested a review from sgmonroy June 20, 2019 12:33
@oncilla oncilla mentioned this pull request Jun 20, 2019
Closed
sgmonroy
sgmonroy approved these changes Jun 20, 2019
View reviewed changes
Copy link
Contributor

@sgmonroy sgmonroy left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewed 2 of 2 files at r1.
Reviewable status: :shipit: complete! all files reviewed, all discussions resolved

@oncilla oncilla merged commit ac30535 into scionproto:master Jun 20, 2019
@oncilla oncilla deleted the pub-br-race branch June 20, 2019 14:46
lukedirtwalker added a commit to lukedirtwalker/scion that referenced this pull request Apr 30, 2020
@lukedirtwalker
topogen: pre-allocate addresses (scionproto#2783)
5648644 
We want to change the topology format in the future
and for this change we will need the IP address of a service in the generate functions.
This is a preparation PR for this.

We first register all the addresses we will need, then generate the addresses, then generate the services.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
1 more reviewer

@sgmonroy sgmonroy sgmonroy approved these changes

Reviewers whose approvals may not affect merge requirements
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
Q2S3
Development

Successfully merging this pull request may close these issues.
2 participants
@oncilla @sgmonroy