fix data races in proxy server
[govpp.git] / core / request_handler.go
index fd6d100..ddd5307 100644 (file)
@@ -23,13 +23,15 @@ import (
        logger "github.com/sirupsen/logrus"
 )
 
+var ReplyChannelTimeout = time.Millisecond * 100
+
 var (
        ErrNotConnected = errors.New("not connected to VPP, ignoring the request")
        ErrProbeTimeout = errors.New("probe reply not received within timeout period")
 )
 
 // watchRequests watches for requests on the request API channel and forwards them as messages to VPP.
-func (c *Connection) watchRequests(ch *channel) {
+func (c *Connection) watchRequests(ch *Channel) {
        for {
                select {
                case req, ok := <-ch.reqChan:
@@ -39,68 +41,63 @@ func (c *Connection) watchRequests(ch *channel) {
                                c.releaseAPIChannel(ch)
                                return
                        }
-                       c.processRequest(ch, req)
-
-               case req := <-ch.notifSubsChan:
-                       // new request on the notification subscribe channel
-                       c.processSubscriptionRequest(ch, req)
+                       if err := c.processRequest(ch, req); err != nil {
+                               sendReplyError(ch, req, err)
+                       }
                }
        }
 }
 
 // processRequest processes a single request received on the request channel.
-func (c *Connection) processRequest(ch *channel, req *vppRequest) error {
+func (c *Connection) processRequest(ch *Channel, req *vppRequest) error {
        // check whether we are connected to VPP
-       if atomic.LoadUint32(&c.connected) == 0 {
+       if atomic.LoadUint32(&c.vppConnected) == 0 {
                err := ErrNotConnected
                log.Errorf("processing request failed: %v", err)
-               sendReplyError(ch, req, err)
                return err
        }
 
        // retrieve message ID
        msgID, err := c.GetMessageID(req.msg)
        if err != nil {
-               err = fmt.Errorf("unable to retrieve message ID: %v", err)
                log.WithFields(logger.Fields{
                        "msg_name": req.msg.GetMessageName(),
                        "msg_crc":  req.msg.GetCrcString(),
                        "seq_num":  req.seqNum,
-               }).Error(err)
-               sendReplyError(ch, req, err)
-               return err
+                       "error":    err,
+               }).Errorf("failed to retrieve message ID")
+               return fmt.Errorf("unable to retrieve message ID: %v", err)
        }
 
        // encode the message into binary
        data, err := c.codec.EncodeMsg(req.msg, msgID)
        if err != nil {
-               err = fmt.Errorf("unable to encode the messge: %v", err)
                log.WithFields(logger.Fields{
                        "channel":  ch.id,
                        "msg_id":   msgID,
                        "msg_name": req.msg.GetMessageName(),
                        "seq_num":  req.seqNum,
-               }).Error(err)
-               sendReplyError(ch, req, err)
-               return err
+                       "error":    err,
+               }).Errorf("failed to encode message: %#v", req.msg)
+               return fmt.Errorf("unable to encode the message: %v", err)
        }
 
-       // get context
        context := packRequestContext(ch.id, req.multi, req.seqNum)
+
        if log.Level == logger.DebugLevel { // for performance reasons - logrus does some processing even if debugs are disabled
                log.WithFields(logger.Fields{
                        "channel":  ch.id,
                        "context":  context,
                        "is_multi": req.multi,
                        "msg_id":   msgID,
-                       "msg_name": req.msg.GetMessageName(),
                        "msg_size": len(data),
                        "seq_num":  req.seqNum,
-               }).Debug(" -> Sending a message to VPP.")
+                       "msg_crc":  req.msg.GetCrcString(),
+               }).Debugf("==> govpp send: %s: %+v", req.msg.GetMessageName(), req.msg)
        }
 
        // send the request to VPP
-       err = c.vpp.SendMsg(context, data)
+       err = c.vppClient.SendMsg(context, data)
        if err != nil {
                err = fmt.Errorf("unable to send the message: %v", err)
                log.WithFields(logger.Fields{
@@ -108,13 +105,12 @@ func (c *Connection) processRequest(ch *channel, req *vppRequest) error {
                        "msg_id":  msgID,
                        "seq_num": req.seqNum,
                }).Error(err)
-               sendReplyError(ch, req, err)
                return err
        }
 
        if req.multi {
                // send a control ping to determine end of the multipart response
-               pingData, _ := c.codec.EncodeMsg(msgControlPing, c.pingReqID)
+               pingData, _ := c.codec.EncodeMsg(c.msgControlPing, c.pingReqID)
 
                log.WithFields(logger.Fields{
                        "channel":  ch.id,
@@ -122,9 +118,9 @@ func (c *Connection) processRequest(ch *channel, req *vppRequest) error {
                        "msg_id":   c.pingReqID,
                        "msg_size": len(pingData),
                        "seq_num":  req.seqNum,
-               }).Debug(" -> Sending a control ping to VPP.")
+               }).Debug("--> sending control ping")
 
-               if err := c.vpp.SendMsg(context, pingData); err != nil {
+               if err := c.vppClient.SendMsg(context, pingData); err != nil {
                        log.WithFields(logger.Fields{
                                "context": context,
                                "msg_id":  msgID,
@@ -137,10 +133,7 @@ func (c *Connection) processRequest(ch *channel, req *vppRequest) error {
 }
 
 // msgCallback is called whenever any binary API message comes from VPP.
-func (c *Connection) msgCallback(msgID uint16, context uint32, data []byte) {
-       connLock.RLock()
-       defer connLock.RUnlock()
-
+func (c *Connection) msgCallback(msgID uint16, data []byte) {
        if c == nil {
                log.Warn("Already disconnected, ignoring the message.")
                return
@@ -157,13 +150,8 @@ func (c *Connection) msgCallback(msgID uint16, context uint32, data []byte) {
        // - replies that don't have context as first field (comes as zero)
        // - events that don't have context at all (comes as non zero)
        //
-       msgContext, err := c.codec.DecodeMsgContext(data, msg)
-       if err == nil {
-               if context != msgContext {
-                       log.Debugf("different context was decoded from message (%d -> %d)", context, msgContext)
-                       context = msgContext
-               }
-       } else {
+       context, err := c.codec.DecodeMsgContext(data, msg)
+       if err != nil {
                log.Errorf("decoding context failed: %v", err)
        }
 
@@ -172,12 +160,12 @@ func (c *Connection) msgCallback(msgID uint16, context uint32, data []byte) {
                log.WithFields(logger.Fields{
                        "context":  context,
                        "msg_id":   msgID,
-                       "msg_name": msg.GetMessageName(),
                        "msg_size": len(data),
                        "channel":  chanID,
                        "is_multi": isMulti,
                        "seq_num":  seqNum,
-               }).Debug(" <- Received a message from VPP.")
+                       "msg_crc":  msg.GetCrcString(),
+               }).Debugf("<== govpp recv: %s", msg.GetMessageName())
        }
 
        if context == 0 || c.isNotificationMessage(msgID) {
@@ -202,11 +190,12 @@ func (c *Connection) msgCallback(msgID uint16, context uint32, data []byte) {
        // treat this as a last part of the reply
        lastReplyReceived := isMulti && msgID == c.pingReplyID
 
-       // send the data to the channel
+       // send the data to the channel, it needs to be copied,
+       // because it will be freed after this function returns
        sendReply(ch, &vppReply{
                msgID:        msgID,
                seqNum:       seqNum,
-               data:         data,
+               data:         append([]byte(nil), data...),
                lastReceived: lastReplyReceived,
        })
 
@@ -218,11 +207,11 @@ func (c *Connection) msgCallback(msgID uint16, context uint32, data []byte) {
 
 // sendReply sends the reply into the go channel, if it cannot be completed without blocking, otherwise
 // it logs the error and do not send the message.
-func sendReply(ch *channel, reply *vppReply) {
+func sendReply(ch *Channel, reply *vppReply) {
        select {
        case ch.replyChan <- reply:
                // reply sent successfully
-       case <-time.After(time.Millisecond * 100):
+       case <-time.After(ReplyChannelTimeout):
                // receiver still not ready
                log.WithFields(logger.Fields{
                        "channel": ch,
@@ -232,10 +221,68 @@ func sendReply(ch *channel, reply *vppReply) {
        }
 }
 
-func sendReplyError(ch *channel, req *vppRequest, err error) {
+func sendReplyError(ch *Channel, req *vppRequest, err error) {
        sendReply(ch, &vppReply{seqNum: req.seqNum, err: err})
 }
 
+// isNotificationMessage returns true if someone has subscribed to provided message ID.
+func (c *Connection) isNotificationMessage(msgID uint16) bool {
+       c.subscriptionsLock.RLock()
+       defer c.subscriptionsLock.RUnlock()
+
+       _, exists := c.subscriptions[msgID]
+       return exists
+}
+
+// sendNotifications send a notification message to all subscribers subscribed for that message.
+func (c *Connection) sendNotifications(msgID uint16, data []byte) {
+       c.subscriptionsLock.RLock()
+       defer c.subscriptionsLock.RUnlock()
+
+       matched := false
+
+       // send to notification to each subscriber
+       for _, sub := range c.subscriptions[msgID] {
+               log.WithFields(logger.Fields{
+                       "msg_name": sub.event.GetMessageName(),
+                       "msg_id":   msgID,
+                       "msg_size": len(data),
+               }).Debug("Sending a notification to the subscription channel.")
+
+               event := sub.msgFactory()
+               if err := c.codec.DecodeMsg(data, event); err != nil {
+                       log.WithFields(logger.Fields{
+                               "msg_name": sub.event.GetMessageName(),
+                               "msg_id":   msgID,
+                               "msg_size": len(data),
+                       }).Errorf("Unable to decode the notification message: %v", err)
+                       continue
+               }
+
+               // send the message into the go channel of the subscription
+               select {
+               case sub.notifChan <- event:
+                       // message sent successfully
+               default:
+                       // unable to write into the channel without blocking
+                       log.WithFields(logger.Fields{
+                               "msg_name": sub.event.GetMessageName(),
+                               "msg_id":   msgID,
+                               "msg_size": len(data),
+                       }).Warn("Unable to deliver the notification, reciever end not ready.")
+               }
+
+               matched = true
+       }
+
+       if !matched {
+               log.WithFields(logger.Fields{
+                       "msg_id":   msgID,
+                       "msg_size": len(data),
+               }).Info("No subscription found for the notification message.")
+       }
+}
+
 // +------------------+-------------------+-----------------------+
 // | 15b = channel ID | 1b = is multipart | 16b = sequence number |
 // +------------------+-------------------+-----------------------+