Golang glog.Debugf函数代码示例

// receiver() reads data from the network, and writes the data into the incoming buffer
func (this *service) receiver() {
	defer func() {
		// Let's recover from panic
		if r := recover(); r != nil {
			glog.Errorf("(%s) Recovering from panic: %v", this.cid(), r)
		}

		this.wgStopped.Done()

		glog.Debugf("(%s) Stopping receiver", this.cid())
	}()

	glog.Debugf("(%s) Starting receiver", this.cid())

	this.wgStarted.Done()

	switch conn := this.conn.(type) {
	case net.Conn:
		//glog.Debugf("server/handleConnection: Setting read deadline to %d", time.Second*time.Duration(this.keepAlive))
		keepAlive := time.Second * time.Duration(this.keepAlive)
		r := timeoutReader{
			d:    keepAlive + (keepAlive / 2),
			conn: conn,
		}

		for {
			_, err := this.in.ReadFrom(r)

			if err != nil {
				if err != io.EOF {
					glog.Errorf("(%s) error reading from connection: %v", this.cid(), err)
				}
				return
			}
		}

	//case *websocket.Conn:
	//	glog.Errorf("(%s) Websocket: %v", this.cid(), ErrInvalidConnectionType)

	default:
		glog.Errorf("(%s) %v", this.cid(), ErrInvalidConnectionType)
	}
}

func AddWebsocketHandler(urlPattern string, uri string) error {
	glog.Debugf("AddWebsocketHandler urlPattern=%s, uri=%s", urlPattern, uri)
	u, err := url.Parse(uri)
	if err != nil {
		glog.Errorf("surgemq/main: %v", err)
		return err
	}

	h := func(ws *websocket.Conn) {
		WebsocketTcpProxy(ws, u.Scheme, u.Host)
	}
	http.Handle(urlPattern, websocket.Handler(h))
	return nil
}

func startFanPublisher(t testing.TB, cid int, wg *sync.WaitGroup) {
	now := time.Now()

	runClientTest(t, cid, wg, func(svc *service.Client) {
		select {
		case <-done:
		case <-time.After(time.Second * time.Duration(subscribers)):
			glog.Infof("(surgemq%d) Timed out waiting for subscribe response", cid)
			return
		}

		cnt := messages
		sent := 0

		payload := make([]byte, size)
		msg := message.NewPublishMessage()
		msg.SetTopic(topic)
		msg.SetQoS(qos)

		for i := 0; i < cnt; i++ {
			binary.BigEndian.PutUint32(payload, uint32(cid*cnt+i))
			msg.SetPayload(payload)

			err := svc.Publish(msg, nil)
			if err != nil {
				break
			}
			sent++
		}

		since := time.Since(now).Nanoseconds()

		statMu.Lock()
		totalSent += int64(sent)
		totalSentTime += int64(since)
		if since > sentSince {
			sentSince = since
		}
		statMu.Unlock()

		glog.Debugf("(surgemq%d) Sent %d messages in %d ns, %d ns/msg, %d msgs/sec", cid, sent, since, int(float64(since)/float64(cnt)), int(float64(sent)/(float64(since)/float64(time.Second))))

		select {
		case <-done2:
		case <-time.Tick(time.Second * time.Duration(nap*publishers)):
			glog.Errorf("Timed out waiting for messages to be received.")
		}
	})
}

// sender() writes data from the outgoing buffer to the network
func (this *service) sender() {
	defer func() {
		// Let's recover from panic
		if r := recover(); r != nil {
			glog.Errorf("(%s) Recovering from panic: %v", this.cid(), r)
		}

		this.wgStopped.Done()

		glog.Debugf("(%s) Stopping sender", this.cid())
	}()

	glog.Debugf("(%s) Starting sender", this.cid())

	this.wgStarted.Done()

	switch conn := this.conn.(type) {
	case net.Conn:
		for {
			_, err := this.out.WriteTo(conn)

			if err != nil {
				if err != io.EOF {
					glog.Errorf("(%s) error writing data: %v", this.cid(), err)
				}
				return
			}
		}

	//case *websocket.Conn:
	//	glog.Errorf("(%s) Websocket not supported", this.cid())

	default:
		glog.Errorf("(%s) Invalid connection type", this.cid())
	}
}

// Subscribe with QoS 1, publish with QoS 0. So the client should receive all the
// messages as QoS 0.
func TestServiceSub1Pub0(t *testing.T) {
	runClientServerTests(t, func(svc *Client) {
		done := make(chan struct{})
		done2 := make(chan struct{})

		count := 0

		sub := newSubscribeMessage(1)
		svc.Subscribe(sub,
			func(msg, ack message.Message, err error) error {
				close(done)
				return nil
			},
			func(msg *message.PublishMessage) error {
				assertPublishMessage(t, msg, 0)

				count++

				if count == 10 {
					glog.Debugf("got 10 pub0")
					close(done2)
				}

				return nil
			})

		select {
		case <-done:
		case <-time.After(time.Millisecond * 100):
			require.FailNow(t, "Timed out waiting for subscribe response")
		}

		msg := newPublishMessage(0, 0)

		for i := uint16(0); i < 10; i++ {
			svc.Publish(msg, nil)
		}

		select {
		case <-done2:
			require.Equal(t, 10, count)

		case <-time.After(time.Millisecond * 100):
			require.FailNow(t, "Timed out waiting for publish messages")
		}

	})
}

func TestParseIPv4Success(t *testing.T) {
	for i, ip := range ips {
		glog.Debugf("Parsing %d %s", i, ip)
		res, err := Parse(ip)
		require.NoError(t, err)

		m := make(map[[4]byte]bool)

		for _, ip2 := range res {
			var tmp [4]byte
			copy(tmp[:], ip2.To4())
			m[tmp] = true
		}

		require.Equal(t, results[i], m)
	}
}

// For SUBSCRIBE message, we should add subscriber, then send back SUBACK
func (this *service) processSubscribe(msg *message.SubscribeMessage) error {
	resp := message.NewSubackMessage()
	resp.SetPacketId(msg.PacketId())

	// Subscribe to the different topics
	var retcodes []byte

	topics := msg.Topics()
	qos := msg.Qos()

	this.rmsgs = this.rmsgs[0:0]

	for i, t := range topics {
		rqos, err := this.topicsMgr.Subscribe(t, qos[i], &this.onpub)
		if err != nil {
			return err
		}
		this.sess.AddTopic(string(t), qos[i])

		retcodes = append(retcodes, rqos)

		// yeah I am not checking errors here. If there's an error we don't want the
		// subscription to stop, just let it go.
		this.topicsMgr.Retained(t, &this.rmsgs)
		glog.Debugf("(%s) topic = %s, retained count = %d", this.cid(), string(t), len(this.rmsgs))
	}

	if err := resp.AddReturnCodes(retcodes); err != nil {
		return err
	}

	if _, err := this.writeMessage(resp); err != nil {
		return err
	}

	for _, rm := range this.rmsgs {
		if err := this.publish(rm, nil); err != nil {
			glog.Errorf("service/processSubscribe: Error publishing retained message: %v", err)
			return err
		}
	}

	return nil
}

func TestEnglishVocOutput(t *testing.T) {
	inscan, infile := openFile("voc.txt")
	outscan, outfile := openFile("output.txt")
	defer infile.Close()
	defer outfile.Close()

	for inscan.Scan() {
		if !outscan.Scan() {
			break
		}

		word := inscan.Text()
		expect := outscan.Text()
		//glog.Debugf("word=%q, expect=%q", word, expect)
		actual := Stem(word)
		if actual != expect {
			glog.Debugf("word=%q, actual=%q != expect=%q", word, actual, expect)
		}
		assert.Equal(t, expect, actual)
	}
}

// readMessage() reads and copies a message from the buffer. The buffer bytes are
// committed as a result of the read.
func (this *service) readMessage(mtype message.MessageType, total int) (message.Message, int, error) {
	var (
		b   []byte
		err error
		n   int
		msg message.Message
	)

	if this.in == nil {
		err = ErrBufferNotReady
		return nil, 0, err
	}

	if len(this.intmp) < total {
		this.intmp = make([]byte, total)
	}

	// Read until we get total bytes
	l := 0
	for l < total {
		n, err = this.in.Read(this.intmp[l:])
		l += n
		glog.Debugf("read %d bytes, total %d", n, l)
		if err != nil {
			return nil, 0, err
		}
	}

	b = this.intmp[:total]

	msg, err = mtype.New()
	if err != nil {
		return msg, 0, err
	}

	n, err = msg.Decode(b)
	return msg, n, err
}

// processor() reads messages from the incoming buffer and processes them
func (this *service) processor() {
	defer func() {
		// Let's recover from panic
		if r := recover(); r != nil {
			//glog.Errorf("(%s) Recovering from panic: %v", this.cid(), r)
		}

		this.wgStopped.Done()
		this.stop()

		//glog.Debugf("(%s) Stopping processor", this.cid())
	}()

	glog.Debugf("(%s) Starting processor", this.cid())

	this.wgStarted.Done()

	for {
		// 1. Find out what message is next and the size of the message
		mtype, total, err := this.peekMessageSize()
		if err != nil {
			//if err != io.EOF {
			glog.Errorf("(%s) Error peeking next message size: %v", this.cid(), err)
			//}
			return
		}

		msg, n, err := this.peekMessage(mtype, total)
		if err != nil {
			//if err != io.EOF {
			glog.Errorf("(%s) Error peeking next message: %v", this.cid(), err)
			//}
			return
		}

		//glog.Debugf("(%s) Received: %s", this.cid(), msg)

		this.inStat.increment(int64(n))

		// 5. Process the read message
		err = this.processIncoming(msg)
		if err != nil {
			if err != errDisconnect {
				glog.Errorf("(%s) Error processing %s: %v", this.cid(), msg.Name(), err)
			} else {
				return
			}
		}

		// 7. We should commit the bytes in the buffer so we can move on
		_, err = this.in.ReadCommit(total)
		if err != nil {
			if err != io.EOF {
				glog.Errorf("(%s) Error committing %d read bytes: %v", this.cid(), total, err)
			}
			return
		}

		// 7. Check to see if done is closed, if so, exit
		if this.isDone() && this.in.Len() == 0 {
			return
		}

		//if this.inStat.msgs%1000 == 0 {
		//	glog.Debugf("(%s) Going to process message %d", this.cid(), this.inStat.msgs)
		//}
	}
}

func (this *service) processAcked(ackq *sessions.Ackqueue) {
	for _, ackmsg := range ackq.Acked() {
		// Let's get the messages from the saved message byte slices.
		msg, err := ackmsg.Mtype.New()
		if err != nil {
			glog.Errorf("process/processAcked: Unable to creating new %s message: %v", ackmsg.Mtype, err)
			continue
		}

		if _, err := msg.Decode(ackmsg.Msgbuf); err != nil {
			glog.Errorf("process/processAcked: Unable to decode %s message: %v", ackmsg.Mtype, err)
			continue
		}

		ack, err := ackmsg.State.New()
		if err != nil {
			glog.Errorf("process/processAcked: Unable to creating new %s message: %v", ackmsg.State, err)
			continue
		}

		if _, err := ack.Decode(ackmsg.Ackbuf); err != nil {
			glog.Errorf("process/processAcked: Unable to decode %s message: %v", ackmsg.State, err)
			continue
		}

		//glog.Debugf("(%s) Processing acked message: %v", this.cid(), ack)

		// - PUBACK if it's QoS 1 message. This is on the client side.
		// - PUBREL if it's QoS 2 message. This is on the server side.
		// - PUBCOMP if it's QoS 2 message. This is on the client side.
		// - SUBACK if it's a subscribe message. This is on the client side.
		// - UNSUBACK if it's a unsubscribe message. This is on the client side.
		switch ackmsg.State {
		case message.PUBREL:
			// If ack is PUBREL, that means the QoS 2 message sent by a remote client is
			// releassed, so let's publish it to other subscribers.
			if err = this.onPublish(msg.(*message.PublishMessage)); err != nil {
				glog.Errorf("(%s) Error processing ack'ed %s message: %v", this.cid(), ackmsg.Mtype, err)
			}

		case message.PUBACK, message.PUBCOMP, message.SUBACK, message.UNSUBACK, message.PINGRESP:
			glog.Debugf("process/processAcked: %s", ack)
			// If ack is PUBACK, that means the QoS 1 message sent by this service got
			// ack'ed. There's nothing to do other than calling onComplete() below.

			// If ack is PUBCOMP, that means the QoS 2 message sent by this service got
			// ack'ed. There's nothing to do other than calling onComplete() below.

			// If ack is SUBACK, that means the SUBSCRIBE message sent by this service
			// got ack'ed. There's nothing to do other than calling onComplete() below.

			// If ack is UNSUBACK, that means the SUBSCRIBE message sent by this service
			// got ack'ed. There's nothing to do other than calling onComplete() below.

			// If ack is PINGRESP, that means the PINGREQ message sent by this service
			// got ack'ed. There's nothing to do other than calling onComplete() below.

			err = nil

		default:
			glog.Errorf("(%s) Invalid ack message type %s.", this.cid(), ackmsg.State)
			continue
		}

		// Call the registered onComplete function
		if ackmsg.OnComplete != nil {
			onComplete, ok := ackmsg.OnComplete.(OnCompleteFunc)
			if !ok {
				glog.Errorf("process/processAcked: Error type asserting onComplete function: %v", reflect.TypeOf(ackmsg.OnComplete))
			} else if onComplete != nil {
				if err := onComplete(msg, ack, nil); err != nil {
					glog.Errorf("process/processAcked: Error running onComplete(): %v", err)
				}
			}
		}
	}
}

func (this *service) processIncoming(msg message.Message) error {
	var err error = nil

	switch msg := msg.(type) {
	case *message.PublishMessage:
		// For PUBLISH message, we should figure out what QoS it is and process accordingly
		// If QoS == 0, we should just take the next step, no ack required
		// If QoS == 1, we should send back PUBACK, then take the next step
		// If QoS == 2, we need to put it in the ack queue, send back PUBREC
		err = this.processPublish(msg)

	case *message.PubackMessage:
		// For PUBACK message, it means QoS 1, we should send to ack queue
		this.sess.Pub1ack.Ack(msg)
		this.processAcked(this.sess.Pub1ack)

	case *message.PubrecMessage:
		// For PUBREC message, it means QoS 2, we should send to ack queue, and send back PUBREL
		if err = this.sess.Pub2out.Ack(msg); err != nil {
			break
		}

		resp := message.NewPubrelMessage()
		resp.SetPacketId(msg.PacketId())
		_, err = this.writeMessage(resp)

	case *message.PubrelMessage:
		// For PUBREL message, it means QoS 2, we should send to ack queue, and send back PUBCOMP
		if err = this.sess.Pub2in.Ack(msg); err != nil {
			break
		}

		this.processAcked(this.sess.Pub2in)

		resp := message.NewPubcompMessage()
		resp.SetPacketId(msg.PacketId())
		_, err = this.writeMessage(resp)

	case *message.PubcompMessage:
		// For PUBCOMP message, it means QoS 2, we should send to ack queue
		if err = this.sess.Pub2out.Ack(msg); err != nil {
			break
		}

		this.processAcked(this.sess.Pub2out)

	case *message.SubscribeMessage:
		// For SUBSCRIBE message, we should add subscriber, then send back SUBACK
		return this.processSubscribe(msg)

	case *message.SubackMessage:
		// For SUBACK message, we should send to ack queue
		this.sess.Suback.Ack(msg)
		this.processAcked(this.sess.Suback)

	case *message.UnsubscribeMessage:
		// For UNSUBSCRIBE message, we should remove subscriber, then send back UNSUBACK
		return this.processUnsubscribe(msg)

	case *message.UnsubackMessage:
		// For UNSUBACK message, we should send to ack queue
		this.sess.Unsuback.Ack(msg)
		this.processAcked(this.sess.Unsuback)

	case *message.PingreqMessage:
		// For PINGREQ message, we should send back PINGRESP
		resp := message.NewPingrespMessage()
		_, err = this.writeMessage(resp)

	case *message.PingrespMessage:
		this.sess.Pingack.Ack(msg)
		this.processAcked(this.sess.Pingack)

	case *message.DisconnectMessage:
		// For DISCONNECT message, we should quit
		this.sess.Cmsg.SetWillFlag(false)
		return errDisconnect

	default:
		return fmt.Errorf("(%s) invalid message type %s.", this.cid(), msg.Name())
	}

	if err != nil {
		glog.Debugf("(%s) Error processing acked message: %v", this.cid(), err)
	}

	return err
}

// FIXME: The order of closing here causes panic sometimes. For example, if receiver
// calls this, and closes the buffers, somehow it causes buffer.go:476 to panid.
func (this *service) stop() {
	defer func() {
		// Let's recover from panic
		if r := recover(); r != nil {
			glog.Errorf("(%s) Recovering from panic: %v", this.cid(), r)
		}
	}()

	doit := atomic.CompareAndSwapInt64(&this.closed, 0, 1)
	if !doit {
		return
	}

	// Close quit channel, effectively telling all the goroutines it's time to quit
	if this.done != nil {
		glog.Debugf("(%s) closing this.done", this.cid())
		close(this.done)
	}

	// Close the network connection
	if this.conn != nil {
		glog.Debugf("(%s) closing this.conn", this.cid())
		this.conn.Close()
	}

	this.in.Close()
	this.out.Close()

	// Wait for all the goroutines to stop.
	this.wgStopped.Wait()

	glog.Debugf("(%s) Received %d bytes in %d messages.", this.cid(), this.inStat.bytes, this.inStat.msgs)
	glog.Debugf("(%s) Sent %d bytes in %d messages.", this.cid(), this.outStat.bytes, this.outStat.msgs)

	// Unsubscribe from all the topics for this client, only for the server side though
	if !this.client && this.sess != nil {
		topics, _, err := this.sess.Topics()
		if err != nil {
			glog.Errorf("(%s/%d): %v", this.cid(), this.id, err)
		} else {
			for _, t := range topics {
				if err := this.topicsMgr.Unsubscribe([]byte(t), &this.onpub); err != nil {
					glog.Errorf("(%s): Error unsubscribing topic %q: %v", this.cid(), t, err)
				}
			}
		}
	}

	// Publish will message if WillFlag is set. Server side only.
	if !this.client && this.sess.Cmsg.WillFlag() {
		glog.Infof("(%s) service/stop: connection unexpectedly closed. Sending Will.", this.cid())
		this.onPublish(this.sess.Will)
	}

	// Remove the client topics manager
	if this.client {
		topics.Unregister(this.sess.ID())
	}

	// Remove the session from session store if it's suppose to be clean session
	if this.sess.Cmsg.CleanSession() && this.sessMgr != nil {
		this.sessMgr.Del(this.sess.ID())
	}

	this.conn = nil
	this.in = nil
	this.out = nil
}

func startMeshClient(t testing.TB, cid int, wg *sync.WaitGroup) {
	runClientTest(t, cid, wg, func(svc *service.Client) {
		done2 := make(chan struct{})

		cnt := messages
		expected := publishers * cnt

		received := 0
		sent := 0

		now := time.Now()
		since := time.Since(now).Nanoseconds()

		sub := newSubscribeMessage("test", 0)
		svc.Subscribe(sub,
			func(msg, ack message.Message, err error) error {
				subs := atomic.AddInt64(&subdone, 1)
				if subs == int64(publishers) {
					close(done)
				}
				return nil
			},
			func(msg *message.PublishMessage) error {
				if received == 0 {
					now = time.Now()
				}

				received++
				//glog.Debugf("(surgemq%d) messages received=%d", cid, received)
				since = time.Since(now).Nanoseconds()

				if received == expected {
					close(done2)
				}

				return nil
			})

		select {
		case <-done:
		case <-time.After(time.Second * time.Duration(publishers)):
			glog.Infof("(surgemq%d) Timed out waiting for subscribe response", cid)
			return
		}

		payload := make([]byte, size)
		msg := message.NewPublishMessage()
		msg.SetTopic(topic)
		msg.SetQoS(qos)

		go func() {
			now := time.Now()

			for i := 0; i < cnt; i++ {
				binary.BigEndian.PutUint32(payload, uint32(cid*cnt+i))
				msg.SetPayload(payload)

				err := svc.Publish(msg, nil)
				if err != nil {
					break
				}
				sent++
			}

			since := time.Since(now).Nanoseconds()

			statMu.Lock()
			totalSent += int64(sent)
			totalSentTime += int64(since)
			if since > sentSince {
				sentSince = since
			}
			statMu.Unlock()

			glog.Debugf("(surgemq%d) Sent %d messages in %d ns, %d ns/msg, %d msgs/sec", cid, sent, since, int(float64(since)/float64(cnt)), int(float64(sent)/(float64(since)/float64(time.Second))))
		}()

		select {
		case <-done2:
		case <-time.Tick(time.Second * time.Duration(nap*publishers)):
			glog.Errorf("Timed out waiting for messages to be received.")
		}

		statMu.Lock()
		totalRcvd += int64(received)
		totalRcvdTime += int64(since)
		if since > rcvdSince {
			rcvdSince = since
		}
		statMu.Unlock()

		glog.Debugf("(surgemq%d) Received %d messages in %d ns, %d ns/msg, %d msgs/sec", cid, received, since, int(float64(since)/float64(cnt)), int(float64(received)/(float64(since)/float64(time.Second))))
	})
}

func startFanSubscribers(t testing.TB, cid int, wg *sync.WaitGroup) {
	now := time.Now()

	runClientTest(t, cid, wg, func(svc *service.Client) {
		cnt := messages * publishers
		received := 0
		since := time.Since(now).Nanoseconds()

		sub := newSubscribeMessage("test", 0)
		svc.Subscribe(sub,
			func(msg, ack message.Message, err error) error {
				subs := atomic.AddInt64(&subdone, 1)
				if subs == int64(subscribers) {
					now = time.Now()
					close(done)
				}
				return nil
			},
			func(msg *message.PublishMessage) error {
				if received == 0 {
					now = time.Now()
				}

				received++
				//glog.Debugf("(surgemq%d) messages received=%d", cid, received)
				since = time.Since(now).Nanoseconds()

				if received == cnt {
					rcvd := atomic.AddInt64(&rcvdone, 1)
					if rcvd == int64(subscribers) {
						close(done2)
					}
				}

				return nil
			})

		select {
		case <-done:
		case <-time.After(time.Second * time.Duration(subscribers)):
			glog.Infof("(surgemq%d) Timed out waiting for subscribe response", cid)
			return
		}

		select {
		case <-done2:
		case <-time.Tick(time.Second * time.Duration(nap*publishers)):
			glog.Errorf("Timed out waiting for messages to be received.")
		}

		statMu.Lock()
		totalRcvd += int64(received)
		totalRcvdTime += int64(since)
		if since > rcvdSince {
			rcvdSince = since
		}
		statMu.Unlock()

		glog.Debugf("(surgemq%d) Received %d messages in %d ns, %d ns/msg, %d msgs/sec", cid, received, since, int(float64(since)/float64(cnt)), int(float64(received)/(float64(since)/float64(time.Second))))
	})
}