Uploaded image for project: 'OpenShift Bugs'
  1. OpenShift Bugs
  2. OCPBUGS-4195

PTP 4.12 Regression - CLOCK REALTIME status is locked when physical interface is down

XMLWordPrintable

    • Important
    • None
    • CNF RAN Sprint 229
    • 1
    • Proposed
    • False
    • Hide

      None

      Show
      None
    • Rel Note for Telco: Not Required

      This is a clone of issue OCPBUGS-3667. The following is the description of the original issue:

      Description of problem:

      When moving interface ens1f0(slave interface) to down the REALTIME clock should move to FREERUN, as you can see in the logs it moves to FREERUN and back to LOCKED.

      Version-Release number of selected component (if applicable):

      4.12.0-0.nightly-2022-10-25-210451
      

      How reproducible:

      always

      Steps to Reproduce:

      1.shutdown physical interface or interface on the switch
      2. check the linux logs and event
      3.see the clock realtime continues
      

      Actual results:

      CLOCK REALTIME is LOCKED  

      Expected results:

      CLOCK REALTIME should be FREERUN

      Additional info:

      ptp4l logs
      c2sys[63149.937]: [ptp4l.0.config] CLOCK_REALTIME phc offset        15 s2 freq  -89659 delay    491
      
      ptp4l[63149.963]: [ptp4l.0.config] master offset         -4 s2 freq   -6503 path delay       539
      
      ptp4l[63149.980]: [ptp4l.1.config] master offset          8 s2 freq  -11545 path delay       515
      
      phc2sys[63149.999]: [ptp4l.0.config] CLOCK_REALTIME phc offset         6 s2 freq  -89664 delay    500
      
      ptp4l[63150.043]: [ptp4l.0.config] timed out while polling for tx timestamp
      
      ptp4l[63150.043]: [ptp4l.0.config] increasing tx_timestamp_timeout may correct this issue, but it is likely caused by a driver bug
      
      ptp4l[63150.043]: [ptp4l.0.config] port 1: send delay request failed
      
      ptp4l[63150.043]: [ptp4l.1.config] master offset          4 s2 freq  -11551 path delay       516
      
      ptp4l[63150.043]: [ptp4l.0.config] port 1: SLAVE to FAULTY on FAULT_DETECTED (FT_UNSPECIFIED)
      
      phc2sys[63150.062]: [ptp4l.0.config] CLOCK_REALTIME phc offset         8 s2 freq  -89660 delay    496
      
      ptp4l[63150.074]: [ptp4l.0.config] port 1: link down
      
      ptp4l[63150.075]: [ptp4l.0.config] selected local clock b49691.fffe.a3f3f0 as best master
      
      ptp4l[63150.075]: [ptp4l.0.config] port 1: assuming the grand master role
      
      ptp4l[63150.075]: [ptp4l.0.config] port 2: assuming the grand master role
      
      ptp4l[63150.075]: [ptp4l.0.config] port 3: assuming the grand master role
      
      ptp4l[63150.075]: [ptp4l.0.config] port 4: assuming the grand master role
      
      ptp4l[63150.107]: [ptp4l.1.config] master offset          2 s2 freq  -11554 path delay       517
      
      phc2sys[63150.124]: [ptp4l.0.config] CLOCK_REALTIME phc offset        -2 s2 freq  -89667 delay    494
      
      ptp4l[63150.171]: [ptp4l.1.config] master offset          2 s2 freq  -11554 path delay       517
      
      phc2sys[63150.187]: [ptp4l.0.config] CLOCK_REALTIME phc offset        30 s2 freq  -89636 delay    434
      
      ptp4l[63150.235]: [ptp4l.1.config] master offset          4 s2 freq  -11550 path delay       517
      
      phc2sys[63150.250]: [ptp4l.0.config] CLOCK_REALTIME phc offset         2 s2 freq  -89655 delay    493
      
      ptp4l[63150.291]: [ptp4l.1.config] master offset          1 s2 freq  -11555 path delay       517
      
      phc2sys[63150.312]: [ptp4l.0.config] CLOCK_REALTIME phc
       

      event logs

      [kni@registry.ran-vcl01 ~]$ oc logs -f --since=1s -n openshift-ptp linuxptp-daemon-gcw4z cloud-event-proxy  
      time="2022-11-15T10:24:34Z" level=info msg="found interface ens1f0 for port id 1 last role SLAVE has currrent role FAULTY"
      
      time="2022-11-15T10:24:34Z" level=info msg="update interface ens1f0 with portid 1 from role SLAVE to  role FAULTY"
      
      time="2022-11-15T10:24:34Z" level=warning msg="event disabled,no action taken(can't send to a desitination): logging new ev
      ent {\n    \"id\": \"8666473b-a817-489f-a2e7-b95c96989587\",\n    \"type\": \"event.sync.ptp-status.ptp-state-change\",\n  
        \"source\": \"/cluster/node/cnfde4.ptp.lab.eng.bos.redhat.com/sync/ptp-status/lock-state\",\n    \"dataContentType\": \"a
      pplication/json\",\n    \"time\": \"2022-11-15T10:24:34.433957217Z\",\n    \"data\": {\n      \"version\": \"v1\",\n      \
      "values\": [\n        {\n          \"resource\": \"/cluster/node/cnfde4.ptp.lab.eng.bos.redhat.com/ens1fx/master\",\n      
          \"dataType\": \"notification\",\n          \"valueType\": \"enumeration\",\n          \"value\": \"HOLDOVER\"\n        
      },\n        {\n          \"resource\": \"/cluster/node/cnfde4.ptp.lab.eng.bos.redhat.com/ens1fx/master\",\n          \"data
      Type\": \"metric\",\n          \"valueType\": \"decimal64.3\",\n          \"value\": \"-4\"\n        }\n      ]\n    }\n  }
      \n"
      
      time="2022-11-15T10:24:34Z" level=debug msg="posting acknowledgment with status: SUCCESS to publisher: http://localhost:908
      5/api/cloudNotifications/v1/dummy"
      
      time="2022-11-15T10:24:34Z" level=debug msg="event source /cluster/node/cnfde4.ptp.lab.eng.bos.redhat.com/sync/ptp-status/l
      ock-state sent to queue to process"
      
      time="2022-11-15T10:24:34Z" level=debug msg="event sent {\n    \"id\": \"33675f92-6472-4d54-9fc5-035e6260e3e7\",\n    \"typ
      e\": \"event.sync.ptp-status.ptp-state-change\",\n    \"source\": \"/cluster/node/cnfde4.ptp.lab.eng.bos.redhat.com/sync/pt
      p-status/lock-state\",\n    \"dataContentType\": \"application/json\",\n    \"time\": \"2022-11-15T10:24:34.433957217Z\",\n
          \"data\": {\n      \"version\": \"v1\",\n      \"values\": [\n        {\n          \"resource\": \"/cluster/node/cnfde4
      .ptp.lab.eng.bos.redhat.com/ens1fx/master\",\n          \"dataType\": \"notification\",\n          \"valueType\": \"enumera
      tion\",\n          \"value\": \"HOLDOVER\"\n        },\n        {\n          \"resource\": \"/cluster/node/cnfde4.ptp.lab.e
      ng.bos.redhat.com/ens1fx/master\",\n          \"dataType\": \"metric\",\n          \"valueType\": \"decimal64.3\",\n       
         \"value\": \"-4\"\n        }\n      ]\n    }\n  }"
      
      time="2022-11-15T10:24:34Z" level=debug msg="event source /cluster/node/cnfde4.ptp.lab.eng.bos.redhat.com/sync/sync-status/
      os-clock-sync-state sent to queue to process"
      
      time="2022-11-15T10:24:34Z" level=debug msg="event sent {\n    \"id\": \"ca80fd3b-fb40-410e-af8a-a80f7afae4f1\",\n    \"typ
      e\": \"event.sync.sync-status.os-clock-sync-state-change\",\n    \"source\": \"/cluster/node/cnfde4.ptp.lab.eng.bos.redhat.
      com/sync/sync-status/os-clock-sync-state\",\n    \"dataContentType\": \"application/json\",\n    \"time\": \"2022-11-15T10:
      24:34.43550296Z\",\n    \"data\": {\n      \"version\": \"v1\",\n      \"values\": [\n        {\n          \"resource\": \"
      /cluster/node/cnfde4.ptp.lab.eng.bos.redhat.com/CLOCK_REALTIME\",\n          \"dataType\": \"notification\",\n          \"v
      alueType\": \"enumeration\",\n          \"value\": \"FREERUN\"\n        },\n        {\n          \"resource\": \"/cluster/n
      ode/cnfde4.ptp.lab.eng.bos.redhat.com/CLOCK_REALTIME\",\n          \"dataType\": \"metric\",\n          \"valueType\": \"de
      cimal64.3\",\n          \"value\": \"6\"\n        }\n      ]\n    }\n  }"
      
      time="2022-11-15T10:24:34Z" level=info msg="call received to close holderover timeout"
      
      time="2022-11-15T10:24:34Z" level=info msg="exiting holdover for interface master"
      
      time="2022-11-15T10:24:34Z" level=warning msg="event disabled,no action taken(can't send to a desitination): logging new ev
      ent {\n    \"id\": \"d4968622-51d7-413a-b86f-41aa78f38627\",\n    \"type\": \"event.sync.sync-status.os-clock-sync-state-ch
      ange\",\n    \"source\": \"/cluster/node/cnfde4.ptp.lab.eng.bos.redhat.com/sync/sync-status/os-clock-sync-state\",\n    \"d
      ataContentType\": \"application/json\",\n    \"time\": \"2022-11-15T10:24:34.43550296Z\",\n    \"data\": {\n      \"version
      \": \"v1\",\n      \"values\": [\n        {\n          \"resource\": \"/cluster/node/cnfde4.ptp.lab.eng.bos.redhat.com/CLOC
      K_REALTIME\",\n          \"dataType\": \"notification\",\n          \"valueType\": \"enumeration\",\n          \"value\": \
      "FREERUN\"\n        },\n        {\n          \"resource\": \"/cluster/node/cnfde4.ptp.lab.eng.bos.redhat.com/CLOCK_REALTIME
      \",\n          \"dataType\": \"metric\",\n          \"valueType\": \"decimal64.3\",\n          \"value\": \"6\"\n        }\
      n      ]\n    }\n  }\n"
      
      time="2022-11-15T10:24:34Z" level=debug msg="posting acknowledgment with status: SUCCESS to publisher: http://localhost:908
      5/api/cloudNotifications/v1/dummy"
      
      time="2022-11-15T10:24:34Z" level=info msg=" publishing event for ( profile bc2) CLOCK_REALTIME with last state FREERUN and
       current clock state LOCKED and offset 8 for ( Max/Min Threshold 100/-100 )"
      
      time="2022-11-15T10:24:34Z" level=debug msg="event source /cluster/node/cnfde4.ptp.lab.eng.bos.redhat.com/sync/sync-status/
      os-clock-sync-state sent to queue to process"
      
      time="2022-11-15T10:24:34Z" level=debug msg="event sent {\n    \"id\": \"ca80fd3b-fb40-410e-af8a-a80f7afae4f1\",\n    \"typ
      e\": \"event.sync.sync-status.os-clock-sync-state-change\",\n    \"source\": \"/cluster/node/cnfde4.ptp.lab.eng.bos.redhat.
      com/sync/sync-status/os-clock-sync-state\",\n    \"dataContentType\": \"application/json\",\n    \"time\": \"2022-11-15T10:
      24:34.452687795Z\",\n    \"data\": {\n      \"version\": \"v1\",\n      \"values\": [\n        {\n          \"resource\": \
      "/cluster/node/cnfde4.ptp.lab.eng.bos.redhat.com/CLOCK_REALTIME\",\n          \"dataType\": \"notification\",\n          \"
      valueType\": \"enumeration\",\n          \"value\": \"LOCKED\"\n        },\n        {\n          \"resource\": \"/cluster/n
      ode/cnfde4.ptp.lab.eng.bos.redhat.com/CLOCK_REALTIME\",\n          \"dataType\": \"metric\",\n          \"valueType\": \"de
      cimal64.3\",\n          \"value\": \"8\"\n        }\n      ]\n    }\n  }"
      
      time="2022-11-15T10:24:34Z" level=warning msg="event disabled,no action taken(can't send to a desitination): logging new ev
      ent {\n    \"id\": \"3edb9d6f-7a8f-43aa-bcdb-b570e1252913\",\n    \"type\": \"event.sync.sync-status.os-clock-sync-state-ch
      ange\",\n    \"source\": \"/cluster/node/cnfde4.ptp.lab.eng.bos.redhat.com/sync/sync-status/os-clock-sync-state\",\n    \"d
      ataContentType\": \"application/json\",\n    \"time\": \"2022-11-15T10:24:34.452687795Z\",\n    \"data\": {\n      \"versio
      n\": \"v1\",\n      \"values\": [\n        {\n          \"resource\": \"/cluster/node/cnfde4.ptp.lab.eng.bos.redhat.com/CLO
      CK_REALTIME\",\n          \"dataType\": \"notification\",\n          \"valueType\": \"enumeration\",\n          \"value\": 
      \"LOCKED\"\n        },\n        {\n          \"resource\": \"/cluster/node/cnfde4.ptp.lab.eng.bos.redhat.com/CLOCK_REALTIME
      \",\n          \"dataType\": \"metric\",\n          \"valueType\": \"decimal64.3\",\n          \"value\": \"8\"\n        }\
      n      ]\n    }\n  }\n"
      
      time="2022-11-15T10:24:34Z" level=debug msg="posting acknowledgment with status: SUCCESS to publisher: http://localhost:908
      5/api/cloudNotifications/v1/dummy"
      
      
      
      
       

       

       

       

       

              aputtur@redhat.com Aneesh Puttur
              openshift-crt-jira-prow OpenShift Prow Bot
              Ofer Bochan Ofer Bochan
              Votes:
              0 Vote for this issue
              Watchers:
              10 Start watching this issue

                Created:
                Updated:
                Resolved: