• Created by Unknown User (praveen.v), last modified on Oct 09, 2024

You are viewing an old version of this page. View the current version.

Compare with Current View Page History

« Previous Version 2 Next »


Why we need notifications?

  • To ensure whether the value is set properly and updated in the database

Module and component

  • Logging mechanism - RDKB Logger
  • RDKB logger is linked to RDK-B modules to enable component wise logging
  • Component responsible for enabling/disabling notifications: 
    • By default system will look for /etc/debug.ini
    • rdklogctrl can be used in runtime 

During Boot-up 

  • When the RPi boots up, each RDK-B component will be initialized, which in turn will initialize the logger and start logging into the corresponding log file, depending on the log level set for the component in /etc/debug.ini

How enable/disable notifications works?

  • The notifications are enabled by default and the levels can be referred in /etc/debug.ini
  • Using rdklogctrl we can disable the logs from any module which is integrated with rdklogger

Notification levels 

  • Files :
    1. ./etc/debug.ini
    2. rdkb_log4crc configuration files
  • Level for all components can be controlled using “X_RDKCENTRAL-COM_LogLevel”
  • The default log level set toe components are FATAL,ERROR,WARN,NOTICE,INFO.
  • Log levels can be controlled independently for each module

Examples

Changing SSID name

  • Default SSID

root@RaspberryPi-Gateway:~#  dmcli eRT getv Device.WiFi.SSID.1.SSID
CR component name is: eRT.com.cisco.spvtg.ccsp.CR
subsystem_prefix eRT.
getv from/to component(eRT.com.cisco.spvtg.ccsp.wifi): Device.WiFi.SSID.1.SSID
Execution succeed.
Parameter    1 name: Device.WiFi.SSID.1.SSID
               type:     string,    value: RPI_RDKB-AP0

  • Module : Onewifi . By default the logs are enabled with below configuration
  • /etc/debug.ini

LOG.RDK.WIFI = FATAL ERROR WARNING NOTICE INFO

  • Logs 

r

240809-13:51:27.591054 [mod=WIFI, lvl=WARN] [tid=1953]
Subsystem is eRT.
240809-13:51:27.591768 [mod=WIFI, lvl=INFO] [tid=1953] Connect to bus daemon...
240809-13:51:27.591959 [mod=WIFI, lvl=WARN] [tid=1953] RBus is enabled
240809-13:51:27.592057 [mod=WIFI, lvl=INFO] [tid=1953] rbuscore.c:2326 RBus Enabled

240809-13:51:27.592180 [mod=WIFI, lvl=INFO] [tid=1953] connection opened for eRT.com.cisco.spvtg.ccsp.wifi
240809-13:51:27.592388 [mod=WIFI, lvl=INFO] [tid=1953] rbuscore.c:926 Registering method table for object eRT.com.cisco.spvtg.ccsp.wifi

240809-13:51:27.592546 [mod=WIFI, lvl=INFO] [tid=1953] eRT.com.cisco.spvtg.ccsp.wifi start to check eRT.com.cisco.spvtg.ccsp.psm status
240809-13:51:27.596322 [mod=WIFI, lvl=INFO] [tid=1953] eRT.com.cisco.spvtg.ccsp.psm is ready, eRT.com.cisco.spvtg.ccsp.wifi continue
240809-13:51:27.596434 [mod=WIFI, lvl=INFO] [tid=1953] !!! Connected to message bus... bus_handle: 0x0x7f8c018de0 !!!
240809-13:51:28.602883 [mod=WIFI, lvl=INFO] [tid=1953] CcspBaseIf_Register_Event_rbus : rbus_registerEvent called for event: currentSessionIDSignal
240809-13:51:28.620576 [mod=WIFI, lvl=INFO] [tid=1953] rbuscore.c:742 Subscription for _rbus_session_mgr::currentSessionIDSignal is now active.

240809-13:51:28.621396 [mod=WIFI, lvl=WARN] [tid=1953] Register empty object : com.
240809-13:51:28.621487 [mod=WIFI, lvl=WARN] [tid=1953] Register empty object : com.cisco.
240809-13:51:28.621543 [mod=WIFI, lvl=WARN] [tid=1953] Register empty object : com.cisco.spvtg.
240809-13:51:28.621601 [mod=WIFI, lvl=WARN] [tid=1953] Register empty object : com.cisco.spvtg.ccsp.
240809-13:51:28.628362 [mod=WIFI, lvl=WARN] [tid=1953] Data model XML file 1 = TR181-WiFi-USGv2.XML
240809-13:51:28.628910 [mod=WIFI, lvl=WARN] [tid=1953] DM Library module name = CCSP Base Data Model
240809-13:51:28.638364 [mod=WIFI, lvl=WARN] [tid=1953] DM Library module name = COSA_TR181_WiFi_USGv2
240809-13:51:28.638518 [mod=WIFI, lvl=WARN] [tid=1953] Loading DM library libwifi.so...
240809-13:51:28.651047 [mod=WIFI, lvl=WARN] [tid=1953]  RDKB_SYSTEM_BOOT_UP_LOG : CosaWifiInitialize - WiFi initialize.
240809-13:51:29.296945 [mod=WIFI, lvl=INFO] [tid=1953] rbus.c:2771 rbus open for component: WebconfigDML

240809-13:51:29.297285 [mod=WIFI, lvl=INFO] [tid=1953] rbus.c:2847  rbus open (WebconfigDML) success

240809-13:51:29.298751 [mod=WIFI, lvl=INFO] [tid=1621] rbus.c:1018 Consumer=rbus.OneWifi.INBOX.1555 SUBSCRIBED to event=Device.WiFi.WebConfig.Data.Subdoc.North

240809-13:51:29.300330 [mod=WIFI, lvl=INFO] [tid=1953] rbuscore.c:742 Subscription for Device.WiFi.WebConfig.Data.Subdoc.North::Device.WiFi.WebConfig.Data.Subdoc.North is now active.

240809-13:51:29.300482 [mod=WIFI, lvl=INFO] [tid=1953] rbus.c:4786 Device.WiFi.WebConfig.Data.Subdoc.North subscribe retries succeeded

240809-13:51:29.301349 [mod=WIFI, lvl=INFO] [tid=1621] rbus.c:1018 Consumer=rbus.OneWifi.INBOX.1555 SUBSCRIBED to event=Device.WiFi.WebConfig.Data.Init_dml

240809-13:51:29.302305 [mod=WIFI, lvl=INFO] [tid=1953] rbuscore.c:742 Subscription for Device.WiFi.WebConfig.Data.Init_dml::Device.WiFi.WebConfig.Data.Init_dml is now active.

240809-13:51:29.302440 [mod=WIFI, lvl=INFO] [tid=1953] rbus.c:4786 Device.WiFi.WebConfig.Data.Init_dml subscribe retries succeeded

240809-13:51:29.493276 [mod=WIFI, lvl=WARN] [tid=1953]  RDKB_SYSTEM_BOOT_UP_LOG : CosaWifiInitialize - WiFi initialization complete.
240809-13:51:29.493495 [mod=WIFI, lvl=INFO] [tid=1953] rbuscore.c:2326 RBus Enabled

240809-13:51:29.493567 [mod=WIFI, lvl=INFO] [tid=1953] rbus.c:2771 rbus open for component: t2_lib_ccsp-wifi-agent

240809-13:51:29.493853 [mod=WIFI, lvl=INFO] [tid=1953] rbus.c:2847  rbus open (t2_lib_ccsp-wifi-agent) success

240809-13:51:29.496362 [mod=WIFI, lvl=ERROR] [tid=1953] rbus.c:3317 get by t2_lib_ccsp-wifi-agent failed; Received error 17 from RBUS Daemon for the object Telemetry.ReportProfiles.ccsp-wifi-agent.EventMarkerList

  • Changing the SSID

root@RaspberryPi-Gateway:~# dmcli eRT setv Device.WiFi.SSID.1.SSID string RPI_RdkB

CR component name is: eRT.com.cisco.spvtg.ccsp.CR

subsystem_prefix eRT.

setv from/to component(eRT.com.cisco.spvtg.ccsp.wifi): Device.WiFi.SSID.1.SSID

Execution succeed.

  • Logs:

240809-13:51:38.446402 [mod=WIFI, lvl=INFO] [tid=1555] rbus.c:4786 Device.DeviceInfo.X_RDKCENTRAL-COM_xOpsDeviceMgmt.Mesh.Enable subscribe retries succeeded

240809-13:51:46.478663 [mod=WIFI, lvl=INFO] [tid=1709] subscribeSubdocForceReset: [Device.X_RDK_WebConfig.webcfgSubdocForceReset] Component found
240809-13:51:46.478765 [mod=WIFI, lvl=INFO] [tid=1709] subscribeSubdocForceReset: subscribing to event Device.X_RDK_WebConfig.webcfgSubdocForceReset
240809-13:51:46.480941 [mod=WIFI, lvl=INFO] [tid=1709] rbuscore.c:742 Subscription for Device.X_RDK_WebConfig.webcfgSubdocForceReset::Device.X_RDK_WebConfig.webcfgSubdocForceReset is now active.

240809-13:51:46.481080 [mod=WIFI, lvl=INFO] [tid=1709] rbus.c:4786 Device.X_RDK_WebConfig.webcfgSubdocForceReset subscribe retries succeeded

240809-13:51:46.481150 [mod=WIFI, lvl=INFO] [tid=1709] subscribeSubdocForceReset: subscribed to event Device.X_RDK_WebConfig.webcfgSubdocForceReset
240809-13:51:46.481230 [mod=WIFI, lvl=INFO] [tid=1709] subscribeSubdocForceReset: job done
240809-13:55:00.879242 [mod=WIFI, lvl=WARN] [tid=1621] << DslhWmpdoMpaSetParameterValues sending Notification str Device.WiFi.SSID.1.SSID,16,RPI_RdkB,RPI_RDKB-AP0,2 >>
240809-13:55:00.879371 [mod=WIFI, lvl=WARN] [tid=1621] << DslhWmpdoMpaSetParameterValues sending Notification Device.WiFi.SSID.1.SSID,16,RPI_RdkB,RPI_RDKB-AP0,2 >>
240809-13:55:00.879419 [mod=WIFI, lvl=WARN] [tid=1621] << DslhWmpdoMpaSetParameterValues sending Notification ulArraySize 1 >>
240809-13:55:00.879476 [mod=WIFI, lvl=WARN] [tid=1621] DslhObjcoValidate: SSID, bsUpdate = 3

240809-13:55:00.879575 [mod=WIFI, lvl=WARN] [tid=1621] Send all pending notifications 1
240809-13:55:00.879791 [mod=WIFI, lvl=WARN] [tid=1621] Before committing:Device.WiFi.SSID.1.
240809-13:55:00.879819 [mod=WIFI, lvl=WARN] [tid=9545]  Send_Notification_Thread_Func paramCount 1
240809-13:55:00.879846 [mod=WIFI, lvl=WARN] [tid=1621] After committing:Device.WiFi.SSID.1.:0
240809-13:55:00.879896 [mod=WIFI, lvl=WARN] [tid=9545] << Send_Notification_Thread_Func i 0 >>
240809-13:55:00.879985 [mod=WIFI, lvl=WARN] [tid=9545] << str[i] Device.WiFi.SSID.1.SSID,16,RPI_RdkB,RPI_RDKB-AP0,2 >>
240809-13:55:00.883654 [mod=WIFI, lvl=WARN] [tid=9545] << Send_Notification_Thread_Func, now g_isBusy  is not anymore busy, we have notify>>

  • Flow :
    DslhObjcoCommit() -> SSID_Commit() -> CosaDmlWiFiSsidSetCfg() -> wifi_setSSIDName() -> wifi_hostapdWrite() -> cfgChange = TRUE

Change the log level during runtime

root@RaspberryPi-Gateway:~# rdklogctrl OneWifi LOG.RDK.WIFI TRACE1-TRACE9
Sent message to update log level of LOG.RDK.WIFI for OneWifi process


 Changing lan mode (PAM)

  • Enabling Logger and Log level

LOG.RDK.PAM = FATAL ERROR WARNING NOTICE INFO

  • Checking the current Lan mode

dmcli eRT getv Device.X_CISCO_COM_DeviceControl.LanManagementEntry.1.LanMode

CR component name is: eRT.com.cisco.spvtg.ccsp.CR
subsystem_prefix eRT.
getv from/to component(eRT.com.cisco.spvtg.ccsp.pam): Device.X_CISCO_COM_DeviceControl.LanManagementEntry.1.LanMode
Execution succeed.
Parameter    1 name: Device.X_CISCO_COM_DeviceControl.LanManagementEntry.1.LanMode
               type:     string,    value: router

  • Changing the lan mode to bridge-static

root@RaspberryPi-Gateway:~# dmcli eRT setv Device.X_CISCO_COM_DeviceControl.LanManagementEntry.1.LanMode string bridge-static

CR component name is: eRT.com.cisco.spvtg.ccsp.CR

subsystem_prefix eRT.

setv from/to component(eRT.com.cisco.spvtg.ccsp.pam): Device.X_CISCO_COM_DeviceControl.LanManagementEntry.1.LanMode

Execution succeed.

  • Logs:

241009-06:53:25.578466 [mod=PAM, lvl=WARN] [tid=964] << DslhWmpdoMpaSetParameterValues sending Notification str Device.X_CISCO_COM_DeviceControl.LanManagementEntry.1.LanMode,16,bridge-static,router,2 >>
241009-06:53:25.578587 [mod=PAM, lvl=WARN] [tid=964] << DslhWmpdoMpaSetParameterValues sending Notification Device.X_CISCO_COM_DeviceControl.LanManagementEntry.1.LanMode,16,bridge-static,router,2 >>
241009-06:53:25.578636 [mod=PAM, lvl=WARN] [tid=964] << DslhWmpdoMpaSetParameterValues sending Notification ulArraySize 1 >>
241009-06:53:25.578717 [mod=PAM, lvl=WARN] [tid=964] DslhObjcoValidate: LanMode, bsUpdate = 3

241009-06:53:25.578896 [mod=PAM, lvl=WARN] [tid=964] RDKB_LAN_CONFIG_CHANGED: Setting new LanMode value (bridge-dhcp(1),bridge-static(2),router(3),full-bridge-static(4)) as (2)...
241009-06:53:25.579518 [mod=PAM, lvl=WARN] [tid=964] Send all pending notifications 1
241009-06:53:25.579762 [mod=PAM, lvl=WARN] [tid=964] Before committing:Device.X_CISCO_COM_DeviceControl.LanManagementEntry.1.
241009-06:53:25.579784 [mod=PAM, lvl=WARN] [tid=31227]  Send_Notification_Thread_Func paramCount 1
241009-06:53:25.579889 [mod=PAM, lvl=WARN] [tid=31227] << Send_Notification_Thread_Func i 0 >>
241009-06:53:25.579967 [mod=PAM, lvl=WARN] [tid=31227] << str[i] Device.X_CISCO_COM_DeviceControl.LanManagementEntry.1.LanMode,16,bridge-static,router,2 >>
241009-06:53:25.580847 [mod=PAM, lvl=INFO] [tid=964] LanMode:Adv_Bridge_Mode_selected
241009-06:53:25.582140 [mod=PAM, lvl=WARN] [tid=31227] << Send_Notification_Thread_Func, now g_isBusy  is not anymore busy, we have notify>>
241009-06:53:25.590738 [mod=PAM, lvl=WARN] [tid=964] --------- LanMngm_Commit CosaDmlDcResetBr0 1.0.0.254,0.255.255.255>>
241009-06:53:25.594950 [mod=PAM, lvl=WARN] [tid=964] --------- LanMngm_Commit CosaDmlDcResetBr0 <<
241009-06:53:25.595116 [mod=PAM, lvl=WARN] [tid=964] After committing:Device.X_CISCO_COM_DeviceControl.LanManagementEntry.1.:0
241009-06:53:25.656529 [mod=PAM, lvl=WARN] [tid=964] -----DeviceControl_GetParamBoolValue,Trying to get parameter 'ErouterEnable'
241009-06:53:25.656698 [mod=PAM, lvl=WARN] [tid=964] DslhObjcoValidate: ErouterEnable, bsUpdate = 3

241009-06:53:25.658429 [mod=PAM, lvl=WARN] [tid=964] DslhObjcoValidate: Enable, bsUpdate = 3

241009-06:53:25.659793 [mod=PAM, lvl=WARN] [tid=964] Before committing:Device.Bridging.Bridge.1.Port.9.
241009-06:53:25.659920 [mod=PAM, lvl=NOTICE] [tid=964] <HL>SWBrConfirmStructureUpdate port remove member Inx=dmsb.l2net.1.Members.Eth, Val=lbr0
241009-06:53:25.659970 [mod=PAM, lvl=NOTICE] [tid=964] <HL> _COSA_RemoveBPortMember path=dmsb.l2net.1.Members.Eth name=lbr0
241009-06:53:25.660059 [mod=PAM, lvl=NOTICE] [tid=964] <HL> _Psm_GetBPortMemberList path=dmsb.l2net.1.Members.Eth value=NULL
241009-06:53:25.661407 [mod=PAM, lvl=NOTICE] [tid=964] _Psm_GetBPortMemberList: retPsmGet == CCSP_SUCCESS reading dmsb.l2net.1.Members.Eth=
241009-06:53:25.661509 [mod=PAM, lvl=NOTICE] [tid=964] <HL> _COSA_DelToken str= token=lbr0
241009-06:53:25.661554 [mod=PAM, lvl=NOTICE] [tid=964] <HL> _COSA_DelToken Not Found token in Buffer=
241009-06:53:25.661622 [mod=PAM, lvl=NOTICE] [tid=964] <HL>SWBrConfirmStructureUpdate port add member Inx=dmsb.l2net.1.Members.Eth, Val=lbr0
241009-06:53:25.661670 [mod=PAM, lvl=NOTICE] [tid=964] <HL> _COSA_AddBPortMember path=dmsb.l2net.1.Members.Eth name=lbr0
241009-06:53:25.661713 [mod=PAM, lvl=NOTICE] [tid=964] <HL> _Psm_GetBPortMemberList path=dmsb.l2net.1.Members.Eth value=NULL
241009-06:53:25.663032 [mod=PAM, lvl=NOTICE] [tid=964] _Psm_GetBPortMemberList: retPsmGet == CCSP_SUCCESS reading dmsb.l2net.1.Members.Eth=
241009-06:53:25.663137 [mod=PAM, lvl=NOTICE] [tid=964] <HL> _COSA_AddToken new Str=lbr0 after add:lbr0
241009-06:53:25.663181 [mod=PAM, lvl=NOTICE] [tid=964] <HL> _Psm_SetBPortMemberList path=dmsb.l2net.1.Members.Eth value=lbr0
241009-06:53:25.664380 [mod=PAM, lvl=NOTICE] [tid=964] _Psm_SetBPortMemberList: retPsmSet == CCSP_SUCCESS writing dmsb.l2net.1.Members.Eth=lbr0
241009-06:53:25.664465 [mod=PAM, lvl=NOTICE] [tid=964] <HL> _COSA_AddBPortMember new path=dmsb.l2net.1.Members.Eth name=lbr0
241009-06:53:25.664527 [mod=PAM, lvl=NOTICE] [tid=964] <HL> _Psm_AddLinkMembers param_name=dmsb.l2net.1.Members.Link
241009-06:53:25.665632 [mod=PAM, lvl=NOTICE] [tid=964] _Psm_AddLinkMembers: retPsmGet == CCSP_SUCCESS reading dmsb.l2net.1.Members.Link
241009-06:53:25.701156 [mod=PAM, lvl=NOTICE] [tid=964] lanBrPCtlSetEnabled: ioctl(SIOCGIFFLAGS) failed (errno: 19): No such device
241009-06:53:25.713424 [mod=PAM, lvl=NOTICE] [tid=964] <HL> _COSA_GetInterfaceTypeStr
241009-06:53:25.713585 [mod=PAM, lvl=NOTICE] [tid=964] _Psm_SetBPort linkType=Ethernet port->linkType=1
241009-06:53:25.721470 [mod=PAM, lvl=WARN] [tid=964] After committing:Device.Bridging.Bridge.1.Port.9.:0
241009-06:53:25.721574 [mod=PAM, lvl=NOTICE] [tid=964] The notification = 0
241009-06:53:25.722793 [mod=PAM, lvl=WARN] [tid=964] Before committing:Device.X_CISCO_COM_DeviceControl.
241009-06:53:25.722809 [mod=PAM, lvl=INFO] [tid=31281] bridge_mode_wifi_notifier_thread - Mode:2 Radio:true SSID:false
241009-06:53:25.722917 [mod=PAM, lvl=WARN] [tid=964] After committing:Device.X_CISCO_COM_DeviceControl.:0

  • No labels

DISCLAIMER: Please note that the use of the RDK Wiki is subject to its Privacy Policy & Terms of Use. In addition, this Wiki may be accessed by all RDK licensees and their contractors.