Uploaded image for project: 'Migration Toolkit for Virtualization'
  1. Migration Toolkit for Virtualization
  2. MTV-1457

Event watcher crashes on error handling

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Duplicate
    • Icon: Undefined Undefined
    • 2.7.0
    • 2.6.6
    • Inventory
    • False
    • None
    • False
    • Moderate

      The following crash is seen on inventory when adding vSphere provider:

      2024-09-12T01:08:59.048110202Z panic: runtime error: invalid memory address or nil pointer dereference
      2024-09-12T01:08:59.048110202Z [signal SIGSEGV: segmentation violation code=0x1 addr=0x40 pc=0x1586bda]
      2024-09-12T01:08:59.048110202Z
      2024-09-12T01:08:59.048110202Z goroutine 340 [running]:
      2024-09-12T01:08:59.048110202Z github.com/konveyor/forklift-controller/pkg/lib/inventory/web.(*Client).Watch.func1(0xc000a70820)
      2024-09-12T01:08:59.048110202Z  /remote-source/app/pkg/lib/inventory/web/client.go:269 +0xba
      2024-09-12T01:08:59.048110202Z github.com/konveyor/forklift-controller/pkg/lib/inventory/web.(*WatchReader).Repair(0xc000a70820)
      2024-09-12T01:08:59.048110202Z  /remote-source/app/pkg/lib/inventory/web/client.go:358 +0x56
      2024-09-12T01:08:59.048110202Z github.com/konveyor/forklift-controller/pkg/lib/inventory/web.(*Watch).Repair(0xc00010a568)
      2024-09-12T01:08:59.048110202Z  /remote-source/app/pkg/lib/inventory/web/client.go:458 +0x25
      2024-09-12T01:08:59.048110202Z github.com/konveyor/forklift-controller/pkg/controller/watch/handler.(*Handler).Error(0xc00092c0c0, 0x8?, {0x3682960?, 0x4fa76a0?})
      2024-09-12T01:08:59.048110202Z  /remote-source/app/pkg/controller/watch/handler/handler.go:96 +0x145
      2024-09-12T01:08:59.048110202Z github.com/konveyor/forklift-controller/pkg/lib/inventory/web.(*WatchReader).start.func1()
      2024-09-12T01:08:59.048110202Z  /remote-source/app/pkg/lib/inventory/web/client.go:403 +0x23c
      2024-09-12T01:08:59.048110202Z created by github.com/konveyor/forklift-controller/pkg/lib/inventory/web.(*WatchReader).start in goroutine 309
      2024-09-12T01:08:59.048110202Z  /remote-source/app/pkg/lib/inventory/web/client.go:383 +0x67
      2024-09-12T01:08:59.055545963Z panic: runtime error: invalid memory address or nil pointer dereference
      2024-09-12T01:08:59.055545963Z [signal SIGSEGV: segmentation violation code=0x1 addr=0x40 pc=0x1586bda]

      /pkg/lib/inventory/web/client.go

         235    // Watch a resource.
         236    func (r *Client) Watch(url string, resource interface{}, h EventHandler) (status int, w *Watch, err error) {
         237        url = r.patchURL(url)
         238        dialer := websocket.Dialer{
         239            HandshakeTimeout: 45 * time.Second,
         240            Proxy:            http.ProxyFromEnvironment,
         241        }
         242        if ht, cast := r.Transport.(*http.Transport); cast {
         243            dialer.TLSClientConfig = ht.TLSClientConfig
         244        }
         245        options := []string{""}
         246        if h.Options().Snapshot {
         247            options = []string{WatchSnapshot}
         248        }
         249        header := http.Header{
         250            WatchHeader: options,
         251        }
         252        for k, v := range r.Header {
         253            header[k] = v
         254        }
         255        post := func(w *WatchReader) (pStatus int, pErr error) {
         256            socket, response, pErr := dialer.Dial(url, header)
         257            if response != nil {
         258                pStatus = response.StatusCode
         259                switch pStatus {
         260                case http.StatusOK,
         261                    http.StatusSwitchingProtocols:
         262                    pStatus = http.StatusOK
         263                default:
         264                    pErr = nil
         265                    return
         266                }
         267            }
         268    
         269            defer response.Body.Close()     <---- null pointer here

      Note where are not checking for response == nil.

      It should be a StatusOK response with no Body, or null response. 

       

      Where is this coming from?

      pkg/controller/watch/handler/handler.go
          86    // Watch error.
          87    // Repair the watch.
          88    func (r *Handler) Error(w *libweb.Watch, err error) {
          89        log.Info(
          90            "event: error.",
          91            "id",
          92            r.id,
          93            "error",
          94            err.Error())
          95        if !r.ended {
          96            _ = w.Repair()         <--------- got an error
          97        }
          98    }
      }
       
      

      Which are these logs just before the crash

      2024-09-12T01:08:59.037335692Z {"level":"info","ts":"2024-09-12 01:08:59.037","logger":"watch","msg":"event: error.","id":1,"error":"websocket: close 1006 (abnormal closure): unexpected EOF"}
      2024-09-12T01:08:59.037422382Z {"level":"info","ts":"2024-09-12 01:08:59.037","logger":"watch","msg":"event: error.","id":3,"error":"websocket: close 1006 (abnormal closure): unexpected EOF"}
      2024-09-12T01:08:59.037422382Z {"level":"info","ts":"2024-09-12 01:08:59.037","logger":"watch","msg":"event: error.","id":2,"error":"websocket: close 1006 (abnormal closure): unexpected EOF"}
      2024-09-12T01:08:59.040656730Z {"level":"debug","ts":"2024-09-12 01:08:59.040","logger":"watch","msg":"event: ended.","id":2}
      2024-09-12T01:08:59.040670953Z {"level":"debug","ts":"2024-09-12 01:08:59.040","logger":"watch","msg":"event: ended.","id":3}

      Next one in the stack, we would be coming from 

      /pkg/lib/inventory/web/client.go
         375    // Dispatch events.
         376    func (r *WatchReader) start() {
         377        if r.started {
         378            return
         379        }
         380        r.resetLog()
         381        r.started = true
         382        r.done = false
         383        go func() {
         384            defer func() {
         385                _ = r.webSocket.Close()
         386                r.started = false
         387                r.done = true
         388                r.handler.End()
         389                r.log.V(3).Info("reader stopped.")
         390            }()
         391            r.log.V(3).Info("reader started.")
         392            for {
         393                event := Event{
         394                    Resource: r.clone(r.resource),
         395                    Updated:  r.clone(r.resource),
         396                }
         397                err := r.webSocket.ReadJSON(&event)
         398                if err != nil {
         399                    if r.done {
         400                        break
         401                    }
         402                    time.Sleep(time.Second * 3)
         403                    r.handler.Error(&Watch{reader: r}, err)       <----------
         404                    continue
         405                }
      

      So essentially, it seems our watch for events (Create/Update/Delete) gets the connection closed abruptly, and we crash on error handling.

              mnecas@redhat.com Martin Necas
              rhn-support-gveitmic Germano Veit Michel
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Created:
                Updated:
                Resolved: