feat: api-trace
[govpp.git] / core / connection.go
1 // Copyright (c) 2017 Cisco and/or its affiliates.
2 //
3 // Licensed under the Apache License, Version 2.0 (the "License");
4 // you may not use this file except in compliance with the License.
5 // You may obtain a copy of the License at:
6 //
7 //     http://www.apache.org/licenses/LICENSE-2.0
8 //
9 // Unless required by applicable law or agreed to in writing, software
10 // distributed under the License is distributed on an "AS IS" BASIS,
11 // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12 // See the License for the specific language governing permissions and
13 // limitations under the License.
14
15 package core
16
17 import (
18         "errors"
19         "fmt"
20         "path"
21         "reflect"
22         "sync"
23         "sync/atomic"
24         "time"
25
26         logger "github.com/sirupsen/logrus"
27
28         "git.fd.io/govpp.git/adapter"
29         "git.fd.io/govpp.git/api"
30         "git.fd.io/govpp.git/codec"
31 )
32
33 const (
34         DefaultReconnectInterval    = time.Second / 2 // default interval between reconnect attempts
35         DefaultMaxReconnectAttempts = 3               // default maximum number of reconnect attempts
36 )
37
38 var (
39         RequestChanBufSize      = 100 // default size of the request channel buffer
40         ReplyChanBufSize        = 100 // default size of the reply channel buffer
41         NotificationChanBufSize = 100 // default size of the notification channel buffer
42 )
43
44 var (
45         HealthCheckProbeInterval = time.Second            // default health check probe interval
46         HealthCheckReplyTimeout  = time.Millisecond * 250 // timeout for reply to a health check probe
47         HealthCheckThreshold     = 2                      // number of failed health checks until the error is reported
48         DefaultReplyTimeout      = time.Second            // default timeout for replies from VPP
49 )
50
51 // ConnectionState represents the current state of the connection to VPP.
52 type ConnectionState int
53
54 const (
55         // Connected represents state in which the connection has been successfully established.
56         Connected ConnectionState = iota
57
58         // NotResponding represents a state where the VPP socket accepts messages but replies are received with delay,
59         // or not at all. GoVPP treats this state internally the same as disconnected.
60         NotResponding
61
62         // Disconnected represents state in which the VPP socket is closed and the connection is considered dropped.
63         Disconnected
64
65         // Failed represents state in which the reconnecting failed after exceeding maximum number of attempts.
66         Failed
67 )
68
69 func (s ConnectionState) String() string {
70         switch s {
71         case Connected:
72                 return "Connected"
73         case NotResponding:
74                 return "NotResponding"
75         case Disconnected:
76                 return "Disconnected"
77         case Failed:
78                 return "Failed"
79         default:
80                 return fmt.Sprintf("UnknownState(%d)", s)
81         }
82 }
83
84 // ConnectionEvent is a notification about change in the VPP connection state.
85 type ConnectionEvent struct {
86         // Timestamp holds the time when the event has been created.
87         Timestamp time.Time
88
89         // State holds the new state of the connection at the time when the event has been created.
90         State ConnectionState
91
92         // Error holds error if any encountered.
93         Error error
94 }
95
96 // Connection represents a shared memory connection to VPP via vppAdapter.
97 type Connection struct {
98         vppClient adapter.VppAPI // VPP binary API client
99
100         maxAttempts int           // interval for reconnect attempts
101         recInterval time.Duration // maximum number of reconnect attempts
102
103         vppConnected uint32 // non-zero if the adapter is connected to VPP
104
105         connChan chan ConnectionEvent // connection status events are sent to this channel
106
107         codec        MessageCodec                      // message codec
108         msgIDs       map[string]uint16                 // map of message IDs indexed by message name + CRC
109         msgMapByPath map[string]map[uint16]api.Message // map of messages indexed by message ID which are indexed by path
110
111         maxChannelID uint32              // maximum used channel ID (the real limit is 2^15, 32-bit is used for atomic operations)
112         channelsLock sync.RWMutex        // lock for the channels map
113         channels     map[uint16]*Channel // map of all API channels indexed by the channel ID
114
115         subscriptionsLock sync.RWMutex                  // lock for the subscriptions map
116         subscriptions     map[uint16][]*subscriptionCtx // map od all notification subscriptions indexed by message ID
117
118         pingReqID   uint16 // ID if the ControlPing message
119         pingReplyID uint16 // ID of the ControlPingReply message
120
121         lastReplyLock sync.Mutex // lock for the last reply
122         lastReply     time.Time  // time of the last received reply from VPP
123
124         msgControlPing      api.Message
125         msgControlPingReply api.Message
126
127         apiTrace *trace // API tracer (disabled by default)
128 }
129
130 func newConnection(binapi adapter.VppAPI, attempts int, interval time.Duration) *Connection {
131         if attempts == 0 {
132                 attempts = DefaultMaxReconnectAttempts
133         }
134         if interval == 0 {
135                 interval = DefaultReconnectInterval
136         }
137
138         c := &Connection{
139                 vppClient:           binapi,
140                 maxAttempts:         attempts,
141                 recInterval:         interval,
142                 connChan:            make(chan ConnectionEvent, NotificationChanBufSize),
143                 codec:               codec.DefaultCodec,
144                 msgIDs:              make(map[string]uint16),
145                 msgMapByPath:        make(map[string]map[uint16]api.Message),
146                 channels:            make(map[uint16]*Channel),
147                 subscriptions:       make(map[uint16][]*subscriptionCtx),
148                 msgControlPing:      msgControlPing,
149                 msgControlPingReply: msgControlPingReply,
150                 apiTrace: &trace{
151                         list: make([]*api.Record, 0),
152                         mux:  &sync.Mutex{},
153                 },
154         }
155         binapi.SetMsgCallback(c.msgCallback)
156         return c
157 }
158
159 // Connect connects to VPP API using specified adapter and returns a connection handle.
160 // This call blocks until it is either connected, or an error occurs.
161 // Only one connection attempt will be performed.
162 func Connect(binapi adapter.VppAPI) (*Connection, error) {
163         // create new connection handle
164         c := newConnection(binapi, DefaultMaxReconnectAttempts, DefaultReconnectInterval)
165
166         // blocking attempt to connect to VPP
167         if err := c.connectVPP(); err != nil {
168                 return nil, err
169         }
170
171         return c, nil
172 }
173
174 // AsyncConnect asynchronously connects to VPP using specified VPP adapter and returns the connection handle
175 // and ConnectionState channel. This call does not block until connection is established, it
176 // returns immediately. The caller is supposed to watch the returned ConnectionState channel for
177 // Connected/Disconnected events. In case of disconnect, the library will asynchronously try to reconnect.
178 func AsyncConnect(binapi adapter.VppAPI, attempts int, interval time.Duration) (*Connection, chan ConnectionEvent, error) {
179         // create new connection handle
180         c := newConnection(binapi, attempts, interval)
181
182         // asynchronously attempt to connect to VPP
183         go c.connectLoop()
184
185         return c, c.connChan, nil
186 }
187
188 // connectVPP performs blocking attempt to connect to VPP.
189 func (c *Connection) connectVPP() error {
190         log.Debug("Connecting to VPP..")
191
192         // blocking connect
193         if err := c.vppClient.Connect(); err != nil {
194                 return err
195         }
196         log.Debugf("Connected to VPP")
197
198         if err := c.retrieveMessageIDs(); err != nil {
199                 if err := c.vppClient.Disconnect(); err != nil {
200                         log.Debugf("disconnecting vpp client failed: %v", err)
201                 }
202                 return fmt.Errorf("VPP is incompatible: %v", err)
203         }
204
205         // store connected state
206         atomic.StoreUint32(&c.vppConnected, 1)
207
208         return nil
209 }
210
211 // Disconnect disconnects from VPP API and releases all connection-related resources.
212 func (c *Connection) Disconnect() {
213         if c == nil {
214                 return
215         }
216         if c.vppClient != nil {
217                 c.disconnectVPP()
218         }
219 }
220
221 // disconnectVPP disconnects from VPP in case it is connected.
222 func (c *Connection) disconnectVPP() {
223         if atomic.CompareAndSwapUint32(&c.vppConnected, 1, 0) {
224                 log.Debug("Disconnecting from VPP..")
225
226                 if err := c.vppClient.Disconnect(); err != nil {
227                         log.Debugf("Disconnect from VPP failed: %v", err)
228                 }
229                 log.Debug("Disconnected from VPP")
230         }
231 }
232
233 func (c *Connection) NewAPIChannel() (api.Channel, error) {
234         return c.newAPIChannel(RequestChanBufSize, ReplyChanBufSize)
235 }
236
237 func (c *Connection) NewAPIChannelBuffered(reqChanBufSize, replyChanBufSize int) (api.Channel, error) {
238         return c.newAPIChannel(reqChanBufSize, replyChanBufSize)
239 }
240
241 // NewAPIChannelBuffered returns a new API channel for communication with VPP via govpp core.
242 // It allows to specify custom buffer sizes for the request and reply Go channels.
243 func (c *Connection) newAPIChannel(reqChanBufSize, replyChanBufSize int) (*Channel, error) {
244         if c == nil {
245                 return nil, errors.New("nil connection passed in")
246         }
247
248         // create new channel
249         chID := uint16(atomic.AddUint32(&c.maxChannelID, 1) & 0x7fff)
250         channel := newChannel(chID, c, c.codec, c, reqChanBufSize, replyChanBufSize)
251
252         // store API channel within the client
253         c.channelsLock.Lock()
254         c.channels[chID] = channel
255         c.channelsLock.Unlock()
256
257         // start watching on the request channel
258         go c.watchRequests(channel)
259
260         return channel, nil
261 }
262
263 // releaseAPIChannel releases API channel that needs to be closed.
264 func (c *Connection) releaseAPIChannel(ch *Channel) {
265         log.WithFields(logger.Fields{
266                 "channel": ch.id,
267         }).Debug("API channel released")
268
269         // delete the channel from channels map
270         c.channelsLock.Lock()
271         delete(c.channels, ch.id)
272         c.channelsLock.Unlock()
273 }
274
275 // connectLoop attempts to connect to VPP until it succeeds.
276 // Then it continues with healthCheckLoop.
277 func (c *Connection) connectLoop() {
278         var reconnectAttempts int
279
280         // loop until connected
281         for {
282                 if err := c.vppClient.WaitReady(); err != nil {
283                         log.Debugf("wait ready failed: %v", err)
284                 }
285                 if err := c.connectVPP(); err == nil {
286                         // signal connected event
287                         c.sendConnEvent(ConnectionEvent{Timestamp: time.Now(), State: Connected})
288                         break
289                 } else if reconnectAttempts < c.maxAttempts {
290                         reconnectAttempts++
291                         log.Warnf("connecting failed (attempt %d/%d): %v", reconnectAttempts, c.maxAttempts, err)
292                         time.Sleep(c.recInterval)
293                 } else {
294                         c.sendConnEvent(ConnectionEvent{Timestamp: time.Now(), State: Failed, Error: err})
295                         return
296                 }
297         }
298
299         // we are now connected, continue with health check loop
300         c.healthCheckLoop()
301 }
302
303 // healthCheckLoop checks whether connection to VPP is alive. In case of disconnect,
304 // it continues with connectLoop and tries to reconnect.
305 func (c *Connection) healthCheckLoop() {
306         // create a separate API channel for health check probes
307         ch, err := c.newAPIChannel(1, 1)
308         if err != nil {
309                 log.Error("Failed to create health check API channel, health check will be disabled:", err)
310                 return
311         }
312
313         var (
314                 sinceLastReply time.Duration
315                 failedChecks   int
316         )
317
318         // send health check probes until an error or timeout occurs
319         for {
320                 // sleep until next health check probe period
321                 time.Sleep(HealthCheckProbeInterval)
322
323                 if atomic.LoadUint32(&c.vppConnected) == 0 {
324                         // Disconnect has been called in the meantime, return the healthcheck - reconnect loop
325                         log.Debug("Disconnected on request, exiting health check loop.")
326                         return
327                 }
328
329                 // try draining probe replies from previous request before sending next one
330                 select {
331                 case <-ch.replyChan:
332                         log.Debug("drained old probe reply from reply channel")
333                 default:
334                 }
335
336                 // send the control ping request
337                 ch.reqChan <- &vppRequest{msg: c.msgControlPing}
338
339                 for {
340                         // expect response within timeout period
341                         select {
342                         case vppReply := <-ch.replyChan:
343                                 err = vppReply.err
344
345                         case <-time.After(HealthCheckReplyTimeout):
346                                 err = ErrProbeTimeout
347
348                                 // check if time since last reply from any other
349                                 // channel is less than health check reply timeout
350                                 c.lastReplyLock.Lock()
351                                 sinceLastReply = time.Since(c.lastReply)
352                                 c.lastReplyLock.Unlock()
353
354                                 if sinceLastReply < HealthCheckReplyTimeout {
355                                         log.Warnf("VPP health check probe timing out, but some request on other channel was received %v ago, continue waiting!", sinceLastReply)
356                                         continue
357                                 }
358                         }
359                         break
360                 }
361
362                 if err == ErrProbeTimeout {
363                         failedChecks++
364                         log.Warnf("VPP health check probe timed out after %v (%d. timeout)", HealthCheckReplyTimeout, failedChecks)
365                         if failedChecks > HealthCheckThreshold {
366                                 // in case of exceeded failed check threshold, assume VPP unresponsive
367                                 log.Errorf("VPP does not responding, the health check exceeded threshold for timeouts (>%d)", HealthCheckThreshold)
368                                 c.sendConnEvent(ConnectionEvent{Timestamp: time.Now(), State: NotResponding})
369                                 break
370                         }
371                 } else if err != nil {
372                         // in case of error, assume VPP disconnected
373                         log.Errorf("VPP health check probe failed: %v", err)
374                         c.sendConnEvent(ConnectionEvent{Timestamp: time.Now(), State: Disconnected, Error: err})
375                         break
376                 } else if failedChecks > 0 {
377                         // in case of success after failed checks, clear failed check counter
378                         failedChecks = 0
379                         log.Infof("VPP health check probe OK")
380                 }
381         }
382
383         // cleanup
384         ch.Close()
385         c.disconnectVPP()
386
387         // we are now disconnected, start connect loop
388         c.connectLoop()
389 }
390
391 func getMsgNameWithCrc(x api.Message) string {
392         return getMsgID(x.GetMessageName(), x.GetCrcString())
393 }
394
395 func getMsgID(name, crc string) string {
396         return name + "_" + crc
397 }
398
399 func getMsgFactory(msg api.Message) func() api.Message {
400         return func() api.Message {
401                 return reflect.New(reflect.TypeOf(msg).Elem()).Interface().(api.Message)
402         }
403 }
404
405 // GetMessageID returns message identifier of given API message.
406 func (c *Connection) GetMessageID(msg api.Message) (uint16, error) {
407         if c == nil {
408                 return 0, errors.New("nil connection passed in")
409         }
410         pkgPath := c.GetMessagePath(msg)
411         msgID, err := c.vppClient.GetMsgID(msg.GetMessageName(), msg.GetCrcString())
412         if err != nil {
413                 return 0, err
414         }
415         if pathMsgs, pathOk := c.msgMapByPath[pkgPath]; !pathOk {
416                 c.msgMapByPath[pkgPath] = make(map[uint16]api.Message)
417                 c.msgMapByPath[pkgPath][msgID] = msg
418         } else if _, msgOk := pathMsgs[msgID]; !msgOk {
419                 c.msgMapByPath[pkgPath][msgID] = msg
420         }
421         if _, ok := c.msgIDs[getMsgNameWithCrc(msg)]; ok {
422                 return msgID, nil
423         }
424         c.msgIDs[getMsgNameWithCrc(msg)] = msgID
425         return msgID, nil
426 }
427
428 // LookupByID looks up message name and crc by ID.
429 func (c *Connection) LookupByID(path string, msgID uint16) (api.Message, error) {
430         if c == nil {
431                 return nil, errors.New("nil connection passed in")
432         }
433         if msg, ok := c.msgMapByPath[path][msgID]; ok {
434                 return msg, nil
435         }
436         return nil, fmt.Errorf("unknown message ID %d for path '%s'", msgID, path)
437 }
438
439 // GetMessagePath returns path for the given message
440 func (c *Connection) GetMessagePath(msg api.Message) string {
441         return path.Dir(reflect.TypeOf(msg).Elem().PkgPath())
442 }
443
444 // retrieveMessageIDs retrieves IDs for all registered messages and stores them in map
445 func (c *Connection) retrieveMessageIDs() (err error) {
446         t := time.Now()
447
448         msgsByPath := api.GetRegisteredMessages()
449
450         var n int
451         for pkgPath, msgs := range msgsByPath {
452                 for _, msg := range msgs {
453                         msgID, err := c.GetMessageID(msg)
454                         if err != nil {
455                                 if debugMsgIDs {
456                                         log.Debugf("retrieving message ID for %s.%s failed: %v",
457                                                 pkgPath, msg.GetMessageName(), err)
458                                 }
459                                 continue
460                         }
461                         n++
462
463                         if c.pingReqID == 0 && msg.GetMessageName() == c.msgControlPing.GetMessageName() {
464                                 c.pingReqID = msgID
465                                 c.msgControlPing = reflect.New(reflect.TypeOf(msg).Elem()).Interface().(api.Message)
466                         } else if c.pingReplyID == 0 && msg.GetMessageName() == c.msgControlPingReply.GetMessageName() {
467                                 c.pingReplyID = msgID
468                                 c.msgControlPingReply = reflect.New(reflect.TypeOf(msg).Elem()).Interface().(api.Message)
469                         }
470
471                         if debugMsgIDs {
472                                 log.Debugf("message %q (%s) has ID: %d", msg.GetMessageName(), getMsgNameWithCrc(msg), msgID)
473                         }
474                 }
475                 log.WithField("took", time.Since(t)).
476                         Debugf("retrieved IDs for %d messages (registered %d) from path %s", n, len(msgs), pkgPath)
477         }
478
479         return nil
480 }
481
482 func (c *Connection) sendConnEvent(event ConnectionEvent) {
483         select {
484         case c.connChan <- event:
485         default:
486                 log.Warn("Connection state channel is full, discarding value.")
487         }
488 }
489
490 // Trace gives access to the API trace interface
491 func (c *Connection) Trace() api.Trace {
492         return c.apiTrace
493 }
494
495 // trace records api message
496 func (c *Connection) trace(msg api.Message, chId uint16, t time.Time, isReceived bool) {
497         if atomic.LoadInt32(&c.apiTrace.isEnabled) == 0 {
498                 return
499         }
500         entry := &api.Record{
501                 Message:    msg,
502                 Timestamp:  t,
503                 IsReceived: isReceived,
504                 ChannelID:  chId,
505         }
506         c.apiTrace.mux.Lock()
507         c.apiTrace.list = append(c.apiTrace.list, entry)
508         c.apiTrace.mux.Unlock()
509 }