Versions Compared

Old Version 5

changes.mady.by.user Unknown User (praveen.v)

Saved on

compared with

New Version Current

changes.mady.by.user Unknown User (praveen.v)

Saved on

Key

  • This line was added.
  • This line was removed.
  • Formatting was changed.


Table of Contents

Why we need notifications?

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

Module and component

...

RDKB Logger

The

...

RDK logger is

...

a general-purpose logging mechanism used in RDK-B

...

  • By default, the system will look for /etc/debug.ini.
  • rdklogctrl can be used at runtime.

During Boot-up 

...

, utilizing log4c for formatting and supporting multiple log levels for different modules. Each component’s log level is read from the debug.ini configuration file during initialization. Implemented as a shared library, components must link to this library to include logging functionality.

When the unit boots up, each RDK-B component

...

initializes the logger and

...

starts logging into the corresponding log file

...

based on the log level set for the component

...

. This setup enables component-wise logging across RDK-B modules.

Enable/Disable notifications 

...

  • Notifications are enabled by default, and the levels can be referred to in /etc/debug.ini.
  • Using rdklogctrl, we can enable/disable the logs from any module integrated with rdklogger

Notification levels 

Log levels and notifications

Loge levelsDescription
RDK_LOG_DEBUGInformation that is diagnostically helpful to people more than just developers.
RDK_LOG_ERRORAny error which is fatal to the operation but not the service (cant open a file, missing data, etc)
RDK_LOG_FATALAny error that is forcing a shutdown of the service or application to prevent data loss (or further data loss), reserve these only for the most heinous errors and situations where there is guaranteed to have been data corruption or loss.
RDK_LOG_INFOGenerally useful information to log (service start/stop, configuration assumptions, etc).
RDK_LOG_NOTICEAnything that largely superfluous for application-level logging.

RDK_LOG_TRACE1,

RDK_LOG_TRACE2,...

Only when it would be "tracing" the code and trying to find one part of a function specifically.
RDK_LOG_WARNAnything that can potentially cause application oddities, but for which the application automatically recovering.

debug.ini

    • Logs from different components can be logged into separate files based on the "SEPARATE.LOGFILE.SUPPORT" variable.

    • It also contains entries for each component log levels. Log levels can be controlled independently for each module.

      Example: LOG.RDK.<component name> = ALL, FATAL, ERROR WARNING, NOTICE, INFO, DEBUG

    • For the modules not having entries in configuration file, log level is set to default log levels. (Currently this is set to LOG.RDK.DEFAULT = ERROR in debug.ini)
    • “rdkb_debug.ini” files are parsed by rdk_logger_init() function for loading all the components entry.

rdklogctrl

  • rdklogctrl
  • ./etc/debug.ini
  • rdklogctrl <app_name> <module_name> <loglevel>
    1. To add a new log level - rdklogctrl CcspWifiSsp LOG.RDK.WIFI DEBUG
    2. To remove the existing Log level - rdklogctrl CcspWifiSsp LOG.RDK.WIFI ~DEBUG
  • The default log levels set for components are FATAL,ERROR,WARN,NOTICE,INFO.
  • Log levels can be controlled independently for each module.

...

    1. LOG.RDK.WIFI ~DEBUG

rdklogctrl usage 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

...

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>>

...


  • Change the log level during runtime

...

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

Changing lan mode (PAM)

  • Enabling Logger and Log levelModule: PAM. By default, the logs are enabled with below log levels

LOG.RDK.PAM = FATAL ERROR WARNING NOTICE INFO

...

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


  • Cange Change the log level during runtime
rdklogctrl CcspPandMSsp LOG.RDK.PAM DEBUG

...