【NSQ】问题排查及源码阅读

TangLyan
332 阅读11分钟

在接手项目之前，我还没有机会接触过NSQ这个组件。项目中采用了NSQ作为消息队列。最近，由于一次部署架构上的调整遇到了一些问题，因此我仔细阅读了NSQ相关的源代码，并把学习到的内容记录了下来。

希望这些笔记能对你有所帮助！

NSQ

golang实现的消息队列中间件，包含了三个核心的名称定义：

  • topic：消息发布的主题；
  • channel：一个主题可拥有一个或若干个通道，每个通道接收一个主题的所有消息的副本；
  • Message：二进制消息；

数据流图如下：

官网

官网

从图中可知：消息是通过 topic-->channels组播的方式，每个channel都收到同一份topic的副本。而单个channel存在多个消费者的情况下，会平均发送给消费者，即每个消费者都收到部分消息。

组件

第一次了解到nsq的时候，组件比较多，所以服务的相关端口也比较多：

  • nsqd：负责接收客户端消息，将消息排队存到磁盘上以及向消费者发送消息的守护进程，默认端口：tcp/4150,http/4151,https/4152,。
  • nsqlookupd：管理集群拓扑信息的守护进程，客户端通过nsqlookupd来发现特定的主题nsqd生产者，默认端口：tcp/4160, http/4161。
  • nsqadmin：Web UI，用于实时查看聚合的集群统计信息并执行各种管理任务，默认端口：http/4171。

问题产生

老架构每个机房内部都部署独立的nsq三个组件。新的机房的建设过程中，引入部分架构部署优化的需求，如将nsq部署到云端侧，如图：

画板

画板

其中服务都通过域名连接nsqlookupd，然后通过nsqlookupd返回的nsqd建立连接进行消费。

当服务配置修改后，发现服务无法消费的情况。

既然没法消费，先从日志中定位，想着如果没有连上，程序一定会打印错误日志。但排查过程中：

  1. 发现日志没有输出；
  2. 由于安全管控，无法登录nsqadmin上查看topic连接信息；
  3. 另外一个topic一直输出404（初步假设连接已经连上）。

不出意外，意外来了，一头雾水，只能查看代码内部的nsq消费逻辑。坑爹的来了：在代码内部，如果nsq没有连接上，使用的是fmt.println进行日志打印。

所以直接登录到容器内部，因为了解了这个程序内部存在逻辑处理存在分布式锁，所以可以通过手动再启动一个进程查看具体问题。

正好看到:

连接超时了，而马赛克中IP地址为云端内网IP地址，那么原因如下：

画板

画板

服务通过http的方式，从云端nsqlookupd获取的nsqd的地址，而返回给服务的是云端内网ip地址。机房1服务A无法通过nsqd内网ip地址连接，导致连接超时。

解决方式

通过查看nsqd的启动参数：

-broadcast-address string
    address that will be registered with lookupd (defaults to the OS hostname) (default "yourhost.local")

也就是说，lookupd返回的是nsqd填写的广播地址。将其也修改成域名即可。

历史相似问题

redis cluster也有相似问题，跨区域无法访问分片集群，在redis官网也说明：

Currently, Redis Cluster does not support NATted environments and in general environments where IP addresses or TCP ports are remapped.

目前，Redis Cluster 不支持 NAT 环境，也不支持 IP 地址或 TCP 端口重新映射的一般环境。

问题解决了，nsq是golang编写，以下为nsq的源码阅读总结。

场景验证

# 启动nsqlookupd 
./nsqlookupd
# 启动nsqd
./nsqd --lookupd-tcp-address=127.0.0.1:4160

通过tmux打开四分屏模式可以看到，启动程序后续后，向nsq topic发送消息，会触发nsqd向lookupd注册topic以及nsqd的信息；

通过http接口向lookupd查询topic所在的nsqd地址：

curl -XGET "http://127.0.0.1:4161/lookup?topic=reattach_disk" |python3 -m json.tool 

可知，lookupd确实是返回broadcast_address给客户端进行连接；

源码阅读

nsqd注册流程

nsqd代码使用go-svc作为程序模版，其启动函数为：Start()

启动流程包括：

画板

画板

从trace.log中可以看到具体流程，通过查看Lookup的goroutine id 可以获取该函数跟踪日志，缩减如下：

msg=->github.com/nsqio/nsq/nsqd.(*NSQD).lookupLoop gid=10 params=""
msg=**->github.com/nsqio/nsq/nsqd.in gid=10 params="#0: 127.0.0.1:4160, #1: [], "
# 输出日志
msg=**->github.com/nsqio/nsq/nsqd.(*NSQD).logf gid=10 params="#1: LOOKUP(%s): adding peer, #2: [127.0.0.1:4160], "
msg=****->github.com/nsqio/nsq/internal/lg.Logf gid=10 params="#0: &{outMu:{state:0 sema:0} out:0xc000114028 prefix:{_:[] _:{} v:0xc000112930} flag:{_:{} v:7} isDiscard:{_:{} v:0}}, #3: LOOKUP(%s): adding peer, #4: [127.0.0.1:4160], "
# 创建连接回调函数
msg=**->github.com/nsqio/nsq/nsqd.connectCallback gid=10 params="#0: &{clientIDSequence:0 RWMutex:{w:{state:0 sema:0} writerSem:0 readerSem:0 readerCount:{_:{} v:0} readerWait:{_:{} v:0}} ctx:0xc0001000f0 ctxCancel:0x4912e0 opts:{v:0xc00016c780} dl:0xc00011e6d8 isLoading:0 isExiting:0 errValue:{v:{err:<nil>}} startTime:{wall:13961419027149343692 ext:833805 loc:0xaeb340} topicMap:map[reattach_disk:0xc0001ce000] lookupPeers:{v:[]} tcpServer:0xc000116fc0 tcpListener:0xc00013a700 httpListener:0xc00013a740 httpsListener:<nil> tlsConfig:<nil> clientTLSConfig:0xc000106d00 poolSize:0 notifyChan:0xc000102180 optsNotificationChan:0xc0001021e0 exitChan:0xc000102120 waitGroup:{WaitGroup:{noCopy:{} state:{_:{} _:{} v:21474836480} sema:0}} ci:0xc000112ab0}, #1: levi-dev, "
msg=**<-github.com/nsqio/nsq/nsqd.connectCallback gid=10
# 创建连接对象
msg=**->github.com/nsqio/nsq/nsqd.newLookupPeer gid=10 params="#0: 127.0.0.1:4160, #2: github.com/nsqio/nsq/nsqd.(*NSQD).logf-fm, #3: github.com/nsqio/nsq/nsqd.connectCallback.func1, "
msg=**<-github.com/nsqio/nsq/nsqd.newLookupPeer gid=10
msg=**->github.com/nsqio/nsq/nsqd.(*lookupPeer).Command gid=10 params="#0: <nil>, "
msg=****->github.com/nsqio/nsq/nsqd.(*lookupPeer).Connect gid=10 params=""
msg=******->github.com/nsqio/nsq/nsqd.(*NSQD).logf gid=10 params="#1: LOOKUP connecting to %s, #2: [127.0.0.1:4160], "
msg=********->github.com/nsqio/nsq/internal/lg.Logf gid=10 params="#0: &{outMu:{state:0 sema:0} out:0xc000114028 prefix:{_:[] _:{} v:0xc000112930} flag:{_:{} v:7} isDiscard:{_:{} v:0}}, #3: LOOKUP connecting to %s, #4: [127.0.0.1:4160], "
msg=********<-github.com/nsqio/nsq/internal/lg.Logf gid=10
msg=******<-github.com/nsqio/nsq/nsqd.(*NSQD).logf gid=10
# 开始连接
msg=****<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Connect gid=10
# 使用V1协议连接
msg=****->github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10 params="#0:   V1, "
msg=****<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10
# 封装认证命令
msg=****->github.com/nsqio/nsq/nsqd.(*lookupPeer).Command gid=10 params="#0: IDENTIFY, "
msg=******->github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10 params="#0: IDENTIFY, "
msg=******<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10
msg=******->github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10 params="#0: \n, "
msg=******<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10
msg=******->github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10 params="#0: \x00\x00\x00i, "
msg=******<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10
msg=******->github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10 params="#0: {"broadcast_address":"levi-dev","hostname":"levi-dev","http_port":4151,"tcp_port":4150,"version":"1.3.0"}, "
msg=******<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10
# 获取返回Response
msg=******->github.com/nsqio/nsq/nsqd.readResponseBounded gid=10 params="#0: 127.0.0.1:4160, "
msg=********->github.com/nsqio/nsq/nsqd.(*lookupPeer).Read gid=10 params="#0: \x00\x00\x00\x00, "
msg=********<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Read gid=10
msg=********->github.com/nsqio/nsq/nsqd.(*lookupPeer).Read gid=10 params="#0: \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00, "
 msg=********<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Read gid=10
 msg=******<-github.com/nsqio/nsq/nsqd.readResponseBounded gid=10
 msg=****<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Command gid=10
# 输出连接日志
msg=****->github.com/nsqio/nsq/nsqd.(*NSQD).logf gid=10 params="#1: LOOKUPD(%s): peer info %+v, #2: [127.0.0.1:4160 {%!s(int=4160) %!s(int=4161) 1.3.0 levi-dev}], "
msg=******->github.com/nsqio/nsq/internal/lg.Logf gid=10 params="#0: &{outMu:{state:0 sema:0} out:0xc000114028 prefix:{_:[] _:{} v:0xc000112930} flag:{_:{} v:7} isDiscard:{_:{} v:0}}, #3: LOOKUPD(%s): peer info %+v, #4: [127.0.0.1:4160 {%!s(int=4160) %!s(int=4161) 1.3.0 levi-dev}], "
# 开始注册Topic
msg=****->github.com/nsqio/nsq/nsqd.(*NSQD).logf gid=10 params="#1: LOOKUPD(%s): %s, #2: [127.0.0.1:4160 REGISTER reattach_disk], "
msg=******->github.com/nsqio/nsq/internal/lg.Logf gid=10 params="#0: &{outMu:{state:0 sema:0} out:0xc000114028 prefix:{_:[] _:{} v:0xc000112930} flag:{_:{} v:7} isDiscard:{_:{} v:0}}, #3: LOOKUPD(%s): %s, #4: [127.0.0.1:4160 REGISTER reattach_disk], "
# 创建Topic 命令发送到Lookupd
msg=****->github.com/nsqio/nsq/nsqd.(*lookupPeer).Command gid=10 params="#0: REGISTER reattach_disk, "
msg=******->github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10 params="#0: REGISTER, "
msg=******<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10
msg=******->github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10 params="#0:  , "
msg=******<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10
msg=******->github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10 params="#0: reattach_disk, "
msg=******<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10
msg=******->github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10 params="#0: \n, "
msg=******<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10
# 获取返回响应体
msg=******->github.com/nsqio/nsq/nsqd.readResponseBounded gid=10 params="#0: 127.0.0.1:4160, "
msg=********->github.com/nsqio/nsq/nsqd.(*lookupPeer).Read gid=10 params="#0: \x00\x00\x00\x00, "
msg=********<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Read gid=10
msg=********->github.com/nsqio/nsq/nsqd.(*lookupPeer).Read gid=10 params="#0: \x00\x00, "
msg=********<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Read gid=10
msg=******<-github.com/nsqio/nsq/nsqd.readResponseBounded gid=10
msg=****<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Command gid=10
msg=**<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Command gid=10

# 定时发送Ping
msg=**<-github.com/nsqio/nsq/nsqd.(*NSQD).logf gid=10
msg=**->github.com/nsqio/nsq/nsqd.(*lookupPeer).Command gid=10 params="#0: PING, "
msg=****->github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10 params="#0: PING, "
msg=****<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10
msg=****->github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10 params="#0: \n, "
msg=****<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Write gid=10
# 获取返回响应体
msg=****->github.com/nsqio/nsq/nsqd.readResponseBounded gid=10 params="#0: 127.0.0.1:4160, "
msg=******->github.com/nsqio/nsq/nsqd.(*lookupPeer).Read gid=10 params="#0: \x00\x00\x00\x00, "
msg=******<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Read gid=10
msg=******->github.com/nsqio/nsq/nsqd.(*lookupPeer).Read gid=10 params="#0: \x00\x00, "
msg=******<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Read gid=10
msg=****<-github.com/nsqio/nsq/nsqd.readResponseBounded gid=10
msg=**<-github.com/nsqio/nsq/nsqd.(*lookupPeer).Command gid=10
msg=****->github.com/nsqio/nsq/internal/lg.Logf gid=10 params="#0: &{outMu:{state:0 sema:0} out:0xc000114028 prefix:{_:[] _:{} v:0xc000112930} flag:{_:{} v:7} isDiscard:{_:{} v:0}}, #3: LOOKUPD(%s): sending heartbeat, #4: [127.0.0.1:4160], "

nslookupd处理流程

nsqlookupd与nsqd的框架相似，也是从：Start()->lookupd.Main()开始入手：

画板

画板

从Nsqd的注册流程，可以看出nsq内部封装了TCP协议，并且集群间使用V1的协议进行通信。

TcpServer代码如下：

func TCPServer(listener net.Listener, handler TCPHandler, logf lg.AppLogFunc) error {
    logf(lg.INFO, "TCP: listening on %s", listener.Addr())

    var wg sync.WaitGroup

    for {
        // 接受客户端请求
        clientConn, err := listener.Accept()
        //... 省略错误判断
        wg.Add(1)
        // 创建goroutine进行处理
        go func() {
            // 调用handle处理客户端连接（长轮询）
            handler.Handle(clientConn)
            wg.Done()
        }()
    }

    // wait to return until all handler goroutines complete
    wg.Wait()

    logf(lg.INFO, "TCP: closing %s", listener.Addr())

    return nil
}


# TcpServer.go
func (p *tcpServer) Handle(conn net.Conn) {
    # 初次连接输出日志
 p.nsqlookupd.logf(LOG_INFO, "TCP: new client(%s)", conn.RemoteAddr())
    # 获取tcp中前4个字节
 buf := make([]byte, 4)
 _, err := io.ReadFull(conn, buf)
 if err != nil {
 }
    // 判断使用的协议
 protocolMagic := string(buf)
 p.nsqlookupd.logf(LOG_INFO, "CLIENT(%s): desired protocol magic '%s'",
  conn.RemoteAddr(), protocolMagic)
 var prot protocol.Protocol
 switch protocolMagic {
 case "  V1":
  prot = &LookupProtocolV1{nsqlookupd: p.nsqlookupd}
 default:
  protocol.SendResponse(conn, []byte("E_BAD_PROTOCOL"))
  conn.Close()
  p.nsqlookupd.logf(LOG_ERROR, "client(%s) bad protocol magic '%s'",
   conn.RemoteAddr(), protocolMagic)
  return
 }
    // 保存当前连接
 client := prot.NewClient(conn)
 p.conns.Store(conn.RemoteAddr(), client)
    // 调用时间循环
 err = prot.IOLoop(client)
 if err != nil {
  p.nsqlookupd.logf(LOG_ERROR, "client(%s) - %s", conn.RemoteAddr(), err)
 }
 p.conns.Delete(conn.RemoteAddr())
 client.Close()
}

最终连接成功后，调用了func (p *LookupProtocolV1) IOLoop（）函数来进行数据的处理：

func (p *LookupProtocolV1) IOLoop(c protocol.Client) error {
    // ....
 client := c.(*ClientV1)
 reader := bufio.NewReader(client)
    // 循环来进行数据的处理以及响应
 for {
  line, err = reader.ReadString('\n')
  if err != nil {
   break
  }

  // .....
  var response []byte
        // 执行客户端发送的命令类型
  response, err = p.Exec(client, reader, params)
  if err != nil {
   continue
  }
        // 正确响应,发送给客户端
  if response != nil {
   _, err = protocol.SendResponse(client, response)
   // ....
  }
 }
    // 客户端退出
 p.nsqlookupd.logf(LOG_INFO, "PROTOCOL(V1): [%s] exiting ioloop", client)
 if client.peerInfo != nil {
  registrations := p.nsqlookupd.DB.LookupRegistrations(client.peerInfo.id)
  for _, r := range registrations {
   if removed, _ := p.nsqlookupd.DB.RemoveProducer(r, client.peerInfo.id); removed {
    p.nsqlookupd.logf(LOG_INFO, "DB: client(%s) UNREGISTER category:%s key:%s subkey:%s",
     client, r.Category, r.Key, r.SubKey)
   }
  }
 }
 return err
}

func (p *LookupProtocolV1) Exec(client *ClientV1, reader *bufio.Reader, params []string) ([]byte, error) {
 switch params[0] {
 case "PING":
  return p.PING(client, params)
 case "IDENTIFY":
  return p.IDENTIFY(client, reader, params[1:])
 case "REGISTER":
  return p.REGISTER(client, reader, params[1:])
 case "UNREGISTER":
  return p.UNREGISTER(client, reader, params[1:])
 }
 return nil, protocol.NewFatalClientErr(nil, "E_INVALID", fmt.Sprintf("invalid command %s", params[0]))
}

客户端连接成功，注册topic时会将topic存入到DB中，而这个DB对象最终来一个map。

nsqd数据存储在什么地方？

官网中给出，使用Http就可以往topic中发送消息，那么顺着可以查看到链路：

画板

画板

最终找到：

func writeMessageToBackend(msg *Message, bq BackendQueue) error {
    // sync.Pool 
 buf := bufferPoolGet()
 defer bufferPoolPut(buf)
    // 将msg写入到Buf中
 _, err := msg.WriteTo(buf)
 if err != nil {
  return err
 }
 return bq.Put(buf.Bytes())
}

对于bq定位为：diskQueue，nsq内部设计的硬盘队列，将数据存放到磁盘文件中。

func (d *diskQueue) Put(data []byte) error {
 d.RLock()
 defer d.RUnlock()

 if d.exitFlag == 1 {
  return errors.New("exiting")
 }

 d.writeChan <- data
 return <-d.writeResponseChan
}

这里有个疑问：往通道中写入上了读锁？？

另外Channel对象也实现了DiskQueue作为后端存储。

学习总结

  1. Tcp自定义协议的使用。 在nsq中客户端，服务器均是采用TCP长连接的方式进行通信。
  2. 通过goanalysis往nsq源码上打上trace函数后，能够快速的定位到接口类型背后的实际对象。
  3. 其底层实现的DiskQueue 800行源码，后续如果有相同的需求可以拿过来直接用。
avatar
文章
阅读
粉丝