Golang log4go.Trace函数代码示例

// Process another node's response to a find_node query.
func (d *DHT) processFindNodeResults(node *remoteNode, resp responseType) {
	totalRecvFindNodeReply.Add(1)

	query, _ := node.pendingQueries[resp.T]

	if resp.R.Nodes != "" {
		for id, address := range parseNodesString(resp.R.Nodes) {
			_, addr, existed, err := d.routingTable.hostPortToNode(address)
			if err != nil {
				l4g.Trace("DHT error parsing node from find_find response: %v", err)
				continue
			}
			// SelfPromotions are more common for find_node. They are
			// happening even for router.bittorrent.com
			if existed {
				l4g.Trace(func() string {
					x := hashDistance(query.ih, InfoHash(node.id))
					return fmt.Sprintf("DHT: DUPE node reference, query %x: %[email protected]%v from %[email protected]%v. Distance: %x.", query.ih, id, address, node.id, addr, x)
				})
				totalDupes.Add(1)
			} else {
				l4g.Trace(func() string {
					x := hashDistance(query.ih, InfoHash(node.id))
					return fmt.Sprintf("DHT: Got new node reference, query %x: %[email protected]%v from %[email protected]%v. Distance: %x.", query.ih, id, address, node.id, addr, x)
				})
				if _, err := d.routingTable.getOrCreateNode(id, addr); err == nil {
					// Using d.findNode() instead of d.findNodeFrom() ensures
					// that only the closest neighbors are looked at.
					d.findNode(string(query.ih))
				}
			}
		}
	}
}

func (d *DHT) replyFindNode(addr *net.UDPAddr, r responseType) {
	totalRecvFindNode.Add(1)
	l4g.Trace(func() string {
		x := hashDistance(InfoHash(r.A.Target), InfoHash(d.nodeId))
		return fmt.Sprintf("DHT find_node. Host: %v , nodeId: %x , target ID: %x , distance to me: %x", addr, r.A.Id, r.A.Target, x)
	})

	node := InfoHash(r.A.Target)
	r0 := map[string]interface{}{"id": d.nodeId}
	reply := replyMessage{
		T: r.T,
		Y: "r",
		R: r0,
	}

	// XXX we currently can't give out the peer contact. Probably requires
	// processing announce_peer.  XXX If there was a total match, that guy
	// is the last.
	neighbors := d.routingTable.lookup(node)
	n := make([]string, 0, kNodes)
	for _, r := range neighbors {
		n = append(n, r.id+r.addressBinaryFormat)
	}
	l4g.Trace("replyFindNode: Nodes only. Giving %d", len(n))
	reply.R["nodes"] = strings.Join(n, "")
	sendMsg(d.conn, addr, reply)
}

func (es *ESocket) handleESRequest(request *ESRequest) (string, error) {

	if es.Running {

		buf := bytes.NewBufferString("sendmsg\n")
		buf.WriteString("call-command: " + request.Req_Com + "\n")
		buf.WriteString("execute-app-name: " + request.Req_App + "\n")
		if request.Req_Arg != "" && len(request.Req_Arg) > 0 {
			buf.WriteString("execute-app-arg: " + request.Req_Arg + "\n")
		}
		buf.WriteString("event-lock: true\n")
		l4g.Trace("SendRequest ---> : \n{%s}\n", buf.String())
		fmt.Fprintf(es.conn, "%s\n", buf.String())

		timeout := CheckTimeout(requestTimeout)
		select {
		case <-timeout:
			return "", errors.New("Timeout : " + request.Req_App)
		case res := <-es.cmd:
			l4g.Trace("Request res : %s", res.Header["Reply-Text"])
			return res.Header["Reply-Text"], nil
		case err := <-es.err:
			return "", err
		}

	} else {
		return "", errors.New("Conn already closed")
	}
}

// newQuery creates a new transaction id and adds an entry to r.pendingQueries.
// It does not set any extra information to the transaction information, so the
// caller must take care of that.
func (r *remoteNode) newQuery(transType string) (transId string) {
	l4g.Trace("newQuery for %x, lastID %v", r.id, r.lastQueryID)
	r.lastQueryID = (r.lastQueryID + 1) % 256
	transId = strconv.Itoa(r.lastQueryID)
	l4g.Trace("... new id %v", r.lastQueryID)
	r.pendingQueries[transId] = &queryType{Type: transType}
	return
}

func (r *MongoPromiseTicketRepository) Add(promise *model.PromiseTicket) error {

	err := r.collection.Insert(&promise)

	if err != nil {
		log.Trace("error while inserting document in Mongo: %v", err)
	} else {
		log.Trace("new document inserted into mongo with id: %v", promise)
	}

	return err
}

func (r *MongoCallbackAttemptRepository) Add(promise *model.CallbackAttempt) error {
	promise.Id = bson.NewObjectId()

	err := r.collection.Insert(&promise)

	if err != nil {
		log.Trace("error while inserting document in Mongo: %v", err)
	} else {
		log.Trace("new document inserted into mongo with id: %v", promise.Id)
	}

	return err
}

// Process another node's response to a find_node query.
func (d *DHT) processFindNodeResults(node *remoteNode, resp responseType) {
	totalRecvFindNodeReply.Add(1)

	query, _ := node.pendingQueries[resp.T]

	if resp.R.Nodes != "" {
		for id, address := range parseNodesString(resp.R.Nodes) {
			_, addr, existed, err := d.routingTable.hostPortToNode(address)
			if err != nil {
				l4g.Trace("DHT error parsing node from find_find response: %v", err)
				continue
			}
			if addr == node.address.String() {
				// SelfPromotions are more common for find_node. They are
				// happening even for router.bittorrent.com
				totalSelfPromotions.Add(1)
				continue
			}
			if existed {
				l4g.Trace(func() string {
					x := hashDistance(query.ih, InfoHash(node.id))
					return fmt.Sprintf("DHT: processFindNodeResults DUPE node reference, query %x: %[email protected]%v from %[email protected]%v. Distance: %x.",
						query.ih, id, address, node.id, node.address, x)
				})
				totalFindNodeDupes.Add(1)
			} else {
				l4g.Trace(func() string {
					x := hashDistance(query.ih, InfoHash(node.id))
					return fmt.Sprintf("DHT: Got new node reference, query %x: %[email protected]%v from %[email protected]%v. Distance: %x.",
						query.ih, id, address, node.id, node.address, x)
				})
				// Includes the node in the routing table and ignores errors.
				//
				// Only continue the search if we really have to.
				_, err := d.routingTable.getOrCreateNode(id, addr)

				if err == nil && d.needMoreNodes() {
					select {
					case d.nodesRequest <- ihReq{query.ih, false}:
					default:
						// Too many find_node commands queued up. Dropping
						// this. The node has already been added to the
						// routing table so we're not losing any
						// information.
					}
				}
			}
		}
	}
}

func (r *routingTable) cleanup() (needPing []*remoteNode) {
	needPing = make([]*remoteNode, 0, 10)
	t0 := time.Now()
	// Needs some serious optimization.
	for addr, n := range r.addresses {
		if addr != n.address.String() {
			l4g.Warn("cleanup: node address mismatches: %v != %v. Deleting node", addr, n.address.String())
			r.kill(n)
			continue
		}
		if addr == "" {
			l4g.Warn("cleanup: found empty address for node %x. Deleting node", n.id)
			r.kill(n)
			continue
		}
		if n.reachable {
			if len(n.pendingQueries) == 0 {
				goto PING
			}
			// Tolerate 2 cleanup cycles.
			if time.Since(n.lastResponseTime) > cleanupPeriod*2+(time.Minute) {
				l4g.Trace("DHT: Old node seen %v ago. Deleting", time.Since(n.lastResponseTime))
				r.kill(n)
				continue
			}
			if time.Since(n.lastResponseTime).Nanoseconds() < cleanupPeriod.Nanoseconds()/2 {
				// Seen recently. Don't need to ping.
				continue
			}

		} else {
			// Not reachable.
			if len(n.pendingQueries) > 2 {
				// Didn't reply to 2 consecutive queries.
				l4g.Trace("DHT: Node never replied to ping. Deleting. %v", n.address)
				r.kill(n)
				continue
			}
		}
	PING:
		needPing = append(needPing, n)
	}
	duration := time.Since(t0)
	// If this pauses the server for too long I may have to segment the cleanup.
	// 2000 nodes: it takes ~12ms
	// 4000 nodes: ~24ms.
	l4g.Info("DHT: Routing table cleanup took %v", duration)
	return needPing
}

func (d *DHT) peersForInfoHash(ih InfoHash) []string {
	peerContacts := d.peerStore.peerContacts(ih)
	if len(peerContacts) > 0 {
		l4g.Trace("replyGetPeers: Giving peers! %x was requested, and we knew %d peers!", ih, len(peerContacts))
	}
	return peerContacts
}

func (es *ESocket) SendCmd(cmd string) (string, error) {

	if es.Running {
		l4g.Debug("Send cmd --> %s", cmd)
		fmt.Fprintf(es.conn, "%s\n\n", cmd)

		timeout := CheckTimeout(requestTimeout)
		select {
		case <-timeout:
			return "", errors.New("Timeout : " + cmd)
		case res := <-es.cmd:
			l4g.Trace("Request res : %s--%s", res.Header["Reply-Text"], res.Header["Channel-Unique-Id"])
			if strings.Contains(res.Header["Reply-Text"], "OK") {
				if len(res.Header["Channel-Unique-Id"]) > 0 {
					return res.Header["Channel-Unique-Id"], nil
				}
				return res.Header["Reply-Text"], nil
			} else {
				return "", errors.New(res.Header["Reply-Text"])
			}
		case err := <-es.err:
			return "", err
		}
	} else {
		return "", errors.New("Conn already closed")
	}

}

// Apply executes a set of sqlite statements, within a transaction. All statements
// will take effect, or none.
func (c *TransactionExecuteCommandSet) Apply(server raft.Server) (interface{}, error) {
	log.Trace("Applying TransactionExecuteCommandSet of size %d", len(c.Stmts))

	commitSuccess := false
	db := server.Context().(*db.DB)
	defer func() {
		if !commitSuccess {
			err := db.RollbackTransaction()
			if err != nil {
				log.Error("Failed to rollback transaction: %s", err.Error)
			}
		}
	}()

	err := db.StartTransaction()
	if err != nil {
		log.Error("Failed to start transaction:", err.Error())
		return nil, err
	}
	for i := range c.Stmts {
		err = db.Execute(c.Stmts[i])
		if err != nil {
			log.Error("Failed to execute statement within transaction", err.Error())
			return nil, err
		}
	}
	err = db.CommitTransaction()
	if err != nil {
		log.Error("Failed to commit transaction:", err.Error())
		return nil, err
	} else {
		commitSuccess = true
	}
	return nil, nil
}

func main() {

	runtime.GOMAXPROCS(runtime.NumCPU())
	//l4g.AddFilter("file", l4g.FINE, l4g.NewFileLogWriter("server.log", false))
	// creates a tcp listener
	l4g.LoadConfiguration("./conf/log4go.xml")
	tcpAddr, err := net.ResolveTCPAddr("tcp4", ":8989")
	checkError(err)
	listener, err := net.ListenTCP("tcp", tcpAddr)
	checkError(err)
	defer l4g.Close()
	// creates a server
	config := &gotcp.Config{
		PacketSendChanLimit:    20,
		PacketReceiveChanLimit: 20,
	}
	srv := gotcp.NewServer(config, &Callback{}, &echo.EchoProtocol{})

	// starts service
	go srv.Start(listener, time.Second)
	l4g.Debug("listening: %s", listener.Addr())
	//log.Println("listening:", listener.Addr())

	// catchs system signal
	chSig := make(chan os.Signal)
	signal.Notify(chSig, syscall.SIGINT, syscall.SIGTERM, syscall.SIGUSR2) //, syscall.SIGINT, syscall.SIGTERM
	l4g.Trace("Signal: %s", <-chSig)
	//log.Println("Signal: ", <-chSig)

	// stops service
	srv.Stop()
}

func main() {
	logger.LoadConfiguration("logging.xml")
	logger.Trace("main start")

	logger.Trace("CPU NUM: %d", runtime.NumCPU())
	runtime.GOMAXPROCS(runtime.NumCPU())

	//static directories
	http.Handle("/css/", http.StripPrefix("/css/", http.FileServer(http.Dir("./css/"))))
	http.Handle("/js/", http.StripPrefix("/js/", http.FileServer(http.Dir("./js/"))))
	http.Handle("/img/", http.StripPrefix("/img/", http.FileServer(http.Dir("./img/"))))

	handler.InitRoutes()

	http.HandleFunc("/", handler.RouteHandler)
	http.ListenAndServe(":8080", nil)
}

func (d *DHT) nodesForInfoHash(ih InfoHash) string {
	n := make([]string, 0, kNodes)
	for _, r := range d.routingTable.lookup(ih) {
		// r is nil when the node was filtered.
		if r != nil {
			binaryHost := r.id + nettools.DottedPortToBinary(r.address.String())
			if binaryHost == "" {
				l4g.Trace("killing node with bogus address %v", r.address.String())
				d.routingTable.kill(r)
			} else {
				n = append(n, binaryHost)
			}
		}
	}
	l4g.Trace("replyGetPeers: Nodes only. Giving %d", len(n))
	return strings.Join(n, "")
}

func (d *DHT) findNodeFrom(r *remoteNode, id string) {
	totalSentFindNode.Add(1)
	ty := "find_node"
	transId := r.newQuery(ty)
	ih := InfoHash(id)
	l4g.Trace("findNodeFrom adding pendingQueries transId=%v ih=%x", transId, ih)
	r.pendingQueries[transId].ih = ih
	queryArguments := map[string]interface{}{
		"id":     d.nodeId,
		"target": id,
	}
	query := queryMessage{transId, "q", ty, queryArguments}
	l4g.Trace(func() string {
		x := hashDistance(InfoHash(r.id), ih)
		return fmt.Sprintf("DHT sending find_node. nodeID: %[email protected]%v, target ID: %x , distance: %x", r.id, r.address, id, x)
	})
	sendMsg(d.conn, r.address, query)
}