Skip to content
Eduard Grasa edited this page Jun 9, 2021 · 12 revisions

Table of Contents

1. Logging System
    1.1 User space daemons
    1.2 Kernel components
2. Specific situations
    2.1 Loading the Kernel modules
    2.2 IPCM Daemon startup
    2.3 Creation of an IPC Process
    2.4 Assignment of an IPC Process to a DIF
    2.5 Registration of an IPC Process to an N-1 DIF

1. Logging system

1.1 User space Daemons

The log files of user space daemons are located at the path specified in the main IPCM configuration file, within the "localConfiguration" section.

"localConfiguration" : {
    "installationPath" : "//bin",
    "libraryPath" : "//lib",
    "logPath" : "//var/log",
    "consoleSocket" : "//var/run/ipcm-console.sock",
    "system-name" : "tor1",
    "pluginsPaths" : ["//lib/rinad/ipcp"]
  },

For each IPC Process Daemon there will be a log file called (process name)-(process instance).log (for example test1.IRATI.DIF-1.log). The IPC Manager Daemon logs are stored in the log file called ipcm.log.

The default logging level is "INFO", but this level can be changed via the "-l" flag when launching the IPC Manager Daemon. For instance:

ipcm -c /etc/ipcm.conf -l DEBUG

1.2 Kernel components

The kernel components log their output to the system log (accessible in /var/log/messages or /var/log/syslog).

2. Specific situations

2.1 Loading the kernel modules

Upon successful loading of the IRATI kernel modules, you should see the following logs by inspecting /var/log/syslog.

Jun  9 10:40:39 tor2 kernel: [ 4203.948011] rina_irati_core: loading out-of-tree module taints kernel.
Jun  9 10:40:39 tor2 kernel: [ 4203.948256] rina_irati_core: module verification failed: signature and/or required key missing - tainting kernel
Jun  9 10:40:39 tor2 kernel: [ 4203.959465] rina-pidm(INFO): Instance initialized successfully (2047 port-ids)
Jun  9 10:40:39 tor2 kernel: [ 4203.959515] rina-core(INFO): IRATI RINA implementation v1.4.1 initialized
Jun  9 10:40:39 tor2 kernel: [ 4203.959516] rina-core(INFO): Don't panic ...
Jun  9 10:40:39 tor2 kernel: [ 4203.961024] rina-ps-factory(INFO): policy-set 'default' published successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.961025] rina-rina-default-plugin(INFO): RMT default policy set loaded successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.961026] rina-ps-factory(INFO): policy-set 'default' published successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.961026] rina-rina-default-plugin(INFO): DTP default policy set loaded successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.961027] rina-ps-factory(INFO): policy-set 'default' published successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.961027] rina-rina-default-plugin(INFO): DTCP default policy set loaded successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.961028] rina-ps-factory(INFO): policy-set 'default' published successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.961029] rina-rina-default-plugin(INFO): Delimiting default policy set loaded successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.961029] rina-ps-factory(INFO): policy-set 'default' published successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.961030] rina-rina-default-plugin(INFO): PFF default policy set loaded successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.961030] rina-ps-factory(INFO): policy-set 'default' published successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.961031] rina-rina-default-plugin(INFO): SDU Protection default Crypto policy set loaded successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.961031] rina-ps-factory(INFO): policy-set 'CRC32' published successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.961032] rina-rina-default-plugin(INFO): SDU Protection default error check policy set loaded successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.961032] rina-ps-factory(INFO): policy-set 'default' published successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.961033] rina-rina-default-plugin(INFO): SDU Protection default TTL policy set loaded successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.962811] rina-ipcp-factories(INFO): Factory 'normal-ipc' registered successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.964800] rina-arp826-tables(INFO): ARP826 tables initialized successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.964838] rina-arp826-arm(INFO): ARM initialized successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.964839] rina-arp826-core(INFO): ARP826 Initialized successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.966042] rina-shim-eth-vlan(INFO): shim-eth-vlan initialized
Jun  9 10:40:39 tor2 kernel: [ 4203.966043] rina-ipcp-factories(INFO): Factory 'shim-eth-vlan' registered successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.966046] rina-shim-eth-vlan(INFO): Shim Wifi AP/STA initialized
Jun  9 10:40:39 tor2 kernel: [ 4203.966046] rina-ipcp-factories(INFO): Factory 'shim-wifi-ap' registered successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.966048] rina-shim-eth-vlan(INFO): Shim Wifi AP/STA initialized
Jun  9 10:40:39 tor2 kernel: [ 4203.966049] rina-ipcp-factories(INFO): Factory 'shim-wifi-sta' registered successfully
Jun  9 10:40:39 tor2 kernel: [ 4203.967619] rina-shim-tcp-udp(INFO): shim-tcp-udp initialized
Jun  9 10:40:39 tor2 kernel: [ 4203.967620] rina-ipcp-factories(INFO): Factory 'shim-tcp-udp' registered successfully 

2.2 IPCM Daemon startup

You should see the following messages in the ipcm.log file:

58553(1623235388)#librina.core (DBG): Initialized IRTI Ctrl Manager
58553(1623235388)#ipcm (DBG): IPC Manager daemon initialized
58553(1623235388)#ipcm (DBG):        installation path: //bin
58553(1623235388)#ipcm (DBG):        library path: //lib
58553(1623235388)#ipcm (DBG):        log folder: //var/log
58553(1623235388)#ipcm-catalog (INFO): Catalog: found manifest sm-auth-psoc.manifest
58553(1623235388)#ipcm-catalog (INFO): Catalog: found manifest sm-example.manifest
58553(1623235388)#ipcm-catalog (INFO): Catalog: found manifest nsm-address-change.manifest
58553(1623235388)#ipcm-catalog (INFO): Catalog: found manifest sm-passwd.manifest
58553(1623235388)#ipcm-catalog (INFO): Catalog: found manifest default.manifest
58553(1623235388)#ipcm-catalog (INFO): Catalog: found manifest fare.manifest
58553(1623235388)#ipcm-catalog (INFO): Catalog: found manifest sm-cbac.manifest
58553(1623235388)#ipcm-catalog (INFO): Catalog: found manifest rina-default-plugin.manifest
58553(1623235388)#ipcm.dif-allocator (ERR): Unrecognized DIF Allocator type: , using default
58553(1623235388)#ipcm.dif-allocator (INFO): DIF Directory file: /etc/da.map
58553(1623235388)#rinad.rina-configuration (WARN): Cannot open apps to DIF mappings file
58553(1623235388)#ipcm.dif-allocator (DBG): Application to DIF mappings

58553(1623235388)#ipcm.dif-template-manager (INFO): Template folder: /etc
58553(1623235388)#ipcm.dif-template-manager (DBG): Found DIF template file called: eth2.dif
58553(1623235388)#ipcm (DBG): Starting main I/O loop...
58553(1623235388)#ipcm.dif-template-manager (DBG): Found DIF template file called: normal.dif
58553(1623235388)#ipcm.dif-template-manager (DBG): Found DIF template file called: eth3.dif
58553(1623235388)#ipcm.dif-template-manager (DBG): Found DIF template file called: internal.dif
58553(1623235388)#ipcm.dif-template-manager (DBG): Found DIF template file called: eth1.dif
58553(1623235388)#ipcm.dif-template-manager (INFO): Added or modified DIF template called: eth2.dif
58553(1623235388)#ipcm.dif-template-manager (INFO): Added or modified DIF template called: normal.dif
58553(1623235388)#ipcm.dif-template-manager (INFO): Added or modified DIF template called: eth3.dif
58553(1623235388)#ipcm.dif-template-manager (INFO): Added or modified DIF template called: internal.dif
58553(1623235388)#ipcm.dif-template-manager (INFO): Added or modified DIF template called: eth1.dif
58553(1623235388)#ipcm.dif-template-manager (WARN): Default DIF template not present 

2.3 Creation of an IPC Process

You should see the following messages in the ipcm.log file:

58553(1623235388)#librina.ipc-manager (DBG): Craeted a new IPC Process with pid = 58565
58565(1623235388)#librina.ipc-manager (DBG): New OS Process created, executing IPC Process ...
58553(1623235388)#unix.console (DBG): Console starts [fd=5]

58553(1623235388)#ipcm.os-process-listener (DBG): OS Process monitor started, opening NL socket
58553(1623235388)#ipcm.dif-template-manager (DBG): DIF Template monitor started, monitoring folder /etc
58553(1623235388)#ipcm (INFO)[create_ipcp]: IPC process tor2.normal.DIF:1:: created and waiting for initialization[id = 4]

58553(1623235388)#librina.core (DBG): Added event of type(49) 49_CREATE_IPCP_RESPONSE and sequence number 4 to events queue
58553(1623235388)#ipcm (DBG): Got event of type 49_CREATE_IPCP_RESPONSE and sequence number 4
58553(1623235388)#ipcm.ipcp (INFO)[ipc_process_create_response_event_handler]: IPC process kernel components of [id = 4] created

58553(1623235388)#librina.core (DBG): Added event of type(26) 26_IPC_PROCESS_DAEMON_INITIALIZED and sequence number 0 to events queue
58553(1623235388)#ipcm (DBG): Got event of type 26_IPC_PROCESS_DAEMON_INITIALIZED and sequence number 0
58553(1623235388)#ipcm.ipcp (INFO)[ipc_process_daemon_initialized_event_handler]: IPC process daemon initialized [id = 4]

58553(1623235388)#ipcm-catalog (INFO): Plugin 'rina-default-plugin' successfully loaded
58553(1623235388)#ipcm (INFO)[plugin_load]: Issued plugin-load to IPC process tor2.normal.DIF:1::

58553(1623235388)#librina.core (DBG): Added event of type(38) 38_PLUGIN_LOAD_RESPONSE and sequence number 4 to events queue
58553(1623235388)#ipcm (DBG): Got event of type 38_PLUGIN_LOAD_RESPONSE and sequence number 4
58553(1623235388)#ipcm.policies (INFO)[ipc_process_plugin_load_response_handler]: plugin-load-op [plugin=default, load=1] completed on IPC process tor2.normal.DIF:1:: [success=1]

58553(1623235388)#ipcm-catalog (INFO): Plugin 'default' successfully loaded
58553(1623235388)#ipcm-catalog (WARN): Catalog does not contain a policy-set called default for component errc
58553(1623235388)#ipcm-catalog (WARN): Failed to load policy-set errc/default
58553(1623235388)#ipcm (INFO)[assign_to_dif]: Requested DIF assignment of IPC process tor2.normal.DIF:1:: to DIF normal.DIF::: 

You should also see the following messages on the IPC Process Daemon log file (tor2.normal.DIF-1.log in this example):

58565(1623235388)#librina.core (DBG): Initialized IRTI Ctrl Manager
58565(1623235388)#ipcp (DBG): IPCProcessImpl
58565(1623235388)#ipcp[4].ipc-process (INFO): Librina initialized
58565(1623235388)#librina.timer (DBG): Timer with ID -841445104 started
58565(1623235388)#librina.timer (DBG): Timer with ID -841444848 started
58565(1623235388)#librina.timer (DBG): Timer with ID -841431248 started
58565(1623235388)#librina.timer (DBG): Timer with ID -841399680 started
58565(1623235388)#librina.timer (DBG): Timer with ID -841396320 started
58565(1623235388)#librina.timer (DBG): Timer with ID -841395072 started
58565(1623235388)#librina.timer (DBG): Timer with ID -841394368 started
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd96190) with fqn: '/difm' (parent '/')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd96190) with fqn: '/difm', succeeded. Instance id: '1'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd96610) with fqn: '/ipcm' (parent '/')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd96610) with fqn: '/ipcm', succeeded. Instance id: '2'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd8a8c0) with fqn: '/ribd' (parent '/')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd8a8c0) with fqn: '/ribd', succeeded. Instance id: '3'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd96a20) with fqn: '/sdudel' (parent '/')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd96a20) with fqn: '/sdudel', succeeded. Instance id: '4'
58565(1623235388)#internal-events (INFO): EventListener subscribed to event N_MINUS_1_FLOW_ALLOCATED
58565(1623235388)#internal-events (INFO): EventListener subscribed to event N_MINUS_1_FLOW_DEALLOCATED
58565(1623235388)#internal-events (INFO): EventListener subscribed to event N_MINUS_1_FLOW_DEALLOCATED
58565(1623235388)#internal-events (INFO): EventListener subscribed to event N_MINUS_1_FLOW_ALLOCATED
58565(1623235388)#internal-events (INFO): EventListener subscribed to event N_MINUS_1_FLOW_ALLOCATION_FAILED
58565(1623235388)#internal-events (INFO): EventListener subscribed to event NEIGHBOR_DECLARED_DEAD
58565(1623235388)#internal-events (INFO): EventListener subscribed to event ADDRESS_CHANGE
58565(1623235388)#internal-events (INFO): EventListener subscribed to event IPCP_INTERNAL_FLOW_ALLOCATED
58565(1623235388)#internal-events (INFO): EventListener subscribed to event IPCP_INTERNAL_FLOW_DEALLOCATED
58565(1623235388)#internal-events (INFO): EventListener subscribed to event IPCP_INTERNAL_FLOW_ALLOCATION_FAILED
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd97340) with fqn: '/ipcm/irm' (parent '/ipcm')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd97340) with fqn: '/ipcm/irm', succeeded. Instance id: '5'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd97600) with fqn: '/ipcm/irm/udifs' (parent '/ipcm/irm')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd97600) with fqn: '/ipcm/irm/udifs', succeeded. Instance id: '6'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd97860) with fqn: '/ipcm/irm/uregs' (parent '/ipcm/irm')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd97860) with fqn: '/ipcm/irm/uregs', succeeded. Instance id: '7'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd97af0) with fqn: '/ipcm/irm/uflows' (parent '/ipcm/irm')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd97af0) with fqn: '/ipcm/irm/uflows', succeeded. Instance id: '8'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd97e30) with fqn: '/ra' (parent '/')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd97e30) with fqn: '/ra', succeeded. Instance id: '9'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd85cd0) with fqn: '/ra/qoscubes' (parent '/ra')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd85cd0) with fqn: '/ra/qoscubes', succeeded. Instance id: '10'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd98240) with fqn: '/ra/nhopt' (parent '/ra')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd98240) with fqn: '/ra/nhopt', succeeded. Instance id: '11'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd984a0) with fqn: '/ra/pduft' (parent '/ra')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd984a0) with fqn: '/ra/pduft', succeeded. Instance id: '12'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd98720) with fqn: '/rmt' (parent '/')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd98720) with fqn: '/rmt', succeeded. Instance id: '13'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd98980) with fqn: '/rmt/n1flows' (parent '/rmt')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd98980) with fqn: '/rmt/n1flows', succeeded. Instance id: '14'
58565(1623235388)#internal-events (INFO): EventListener subscribed to event N_MINUS_1_FLOW_DEALLOCATED
58565(1623235388)#internal-events (INFO): EventListener subscribed to event N_MINUS_1_FLOW_ALLOCATED
58565(1623235388)#internal-events (INFO): EventListener subscribed to event ADDRESS_CHANGE
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd98cd0) with fqn: '/difm/nsm' (parent '/difm')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd98cd0) with fqn: '/difm/nsm', succeeded. Instance id: '15'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd98f30) with fqn: '/difm/nsm/whatnms' (parent '/difm/nsm')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd98f30) with fqn: '/difm/nsm/whatnms', succeeded. Instance id: '16'
58565(1623235388)#librina.timer (DBG): Timer with ID -841378720 started
58565(1623235388)#internal-events (INFO): EventListener subscribed to event CONNECTIVITY_TO_NEIGHBOR_LOST
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd99290) with fqn: '/difm/nsm/dft' (parent '/difm/nsm')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd99290) with fqn: '/difm/nsm/dft', succeeded. Instance id: '17'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd99900) with fqn: '/fa' (parent '/')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd99900) with fqn: '/fa', succeeded. Instance id: '18'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd99b40) with fqn: '/fa/flows' (parent '/fa')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd99b40) with fqn: '/fa/flows', succeeded. Instance id: '19'
58565(1623235388)#rib (DBG): Added create callback (specific) for class 'Flow' and path '/fa/flows'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd855d0) with fqn: '/dt' (parent '/')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd855d0) with fqn: '/dt', succeeded. Instance id: '20'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd99fe0) with fqn: '/dt/conns' (parent '/dt')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd99fe0) with fqn: '/dt/conns', succeeded. Instance id: '21'
58565(1623235388)#internal-events (INFO): EventListener subscribed to event ADDRESS_CHANGE
58565(1623235388)#internal-events (INFO): EventListener subscribed to event ADDRESS_CHANGE
58565(1623235388)#ipcp[4].normal-ipcp (INFO): Initialized IPC Process with name: tor2.normal.DIF, instance 1, id 4 
58565(1623235388)#ipcp[4] (INFO): IPC Process name:     tor2.normal.DIF
58565(1623235388)#ipcp[4] (INFO): IPC Process instance: 1
58565(1623235388)#ipcp[4] (INFO): IPC Process id:       4
58565(1623235388)#ipcp[4] (INFO): IPC Manager port:     1
58565(1623235388)#ipcp[4] (INFO): IPC Process type:     normal-ipc
58565(1623235388)#ipcp[4] (INFO): IPC Process initialized, executing event loop...
58565(1623235388)#ipcp (DBG): Starting main I/O loop...
58565(1623235388)#librina.core (DBG): Added event of type(37) 37_PLUGIN_LOAD and sequence number 4 to events queue
58565(1623235388)#ipcp[4].ipc-process (DBG): Got event of type 37_PLUGIN_LOAD and sequence number 4
58565(1623235388)#librina.application (INFO): Plugin default loaded successfully
58565(1623235388)#librina.application (INFO): Pluggable component 'security-manager/default' [default] published
58565(1623235388)#librina.application (INFO): Pluggable component 'security-manager/PSOC_authentication-none' [default] published
58565(1623235388)#librina.application (INFO): Pluggable component 'flow-allocator/default' [default] published
58565(1623235388)#librina.application (INFO): Pluggable component 'flow-allocator/RoundRobin' [default] published
58565(1623235388)#librina.application (INFO): Pluggable component 'flow-allocator/qta-ps' [default] published
58565(1623235388)#librina.application (INFO): Pluggable component 'namespace-manager/default' [default] published
58565(1623235388)#librina.application (INFO): Pluggable component 'resource-allocator/default' [default] published
58565(1623235388)#librina.application (INFO): Pluggable component 'enrollment-task/default' [default] published
58565(1623235388)#librina.application (INFO): Pluggable component 'routing/link-state' [default] published
58565(1623235388)#librina.application (INFO): Pluggable component 'routing/static' [default] published

And the following messages in the system log (/var/log/syslog):

Jun  9 10:43:08 tor2 kernel: [ 4353.059207] rina-cidm(INFO): Instance initialized successfully (2047 cep-ids)
Jun  9 10:43:08 tor2 kernel: [ 4353.117629] rina-rmt(INFO): RMT PS to be selected: default
Jun  9 10:43:08 tor2 kernel: [ 4353.117638] rina-rmt-ps-default(WARN): No PS param q_max, setting default
Jun  9 10:43:08 tor2 kernel: [ 4353.117639] rina-rmt(INFO): PFF PS to be selected: default
Jun  9 10:43:08 tor2 kernel: [ 4353.117640] rina-ps-factory(INFO): Policy-set 'default' already selected 

2.4 Assignment of an IPC Process to a DIF

You should see the following messages in the ipcm.log file:

58553(1623235388)#ipcm (INFO)[assign_to_dif]: Requested DIF assignment of IPC process tor2.normal.DIF:1:: to DIF normal.DIF:::

58553(1623235388)#librina.core (DBG): Added event of type(13) 13_ASSIGN_TO_DIF_RESPONSE and sequence number 5 to events queue
58553(1623235388)#ipcm (DBG): Got event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 5
58553(1623235388)#ipcm.ipcp (INFO)[assign_to_dif_response_event_handler]: DIF assignment operation completed for IPC process tor2.normal.DIF:1:: [success=1]

You should also see the following messages on the IPC Process Daemon log file (tor2.normal.DIF-1.log in this example):

58565(1623235388)#librina.core (DBG): Added event of type(12) 12_ASSIGN_TO_DIF_REQUEST and sequence number 5 to events queue
58565(1623235388)#ipcp[4].ipc-process (DBG): Got event of type 12_ASSIGN_TO_DIF_REQUEST and sequence number 5
58565(1623235388)#librina.core (DBG): Added event of type(13) 13_ASSIGN_TO_DIF_RESPONSE and sequence number 1 to events queue
58565(1623235388)#ipcp[4].ipc-process (DBG): Got event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 1
58565(1623235388)#ipcp[4].rib-daemon (DBG): Configuration set: 4
58565(1623235388)#ipcp (INFO): PDUFT Generator policy-set default added to the resource-allocator
58565(1623235388)#ipcp[4].resource-allocator (DBG): DIF configuration set 4
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdda0f80) with fqn: '/ra/qoscubes/id=1' (parent '/ra/qoscubes')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdda0f80) with fqn: '/ra/qoscubes/id=1', succeeded. Instance id: '22'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd9d550) with fqn: '/ra/qoscubes/id=2' (parent '/ra/qoscubes')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd9d550) with fqn: '/ra/qoscubes/id=2', succeeded. Instance id: '23'
58565(1623235388)#librina.application (INFO): Policy-set link-state selected for component routing
58565(1623235388)#internal-events (INFO): EventListener subscribed to event N_MINUS_1_FLOW_DEALLOCATED
58565(1623235388)#internal-events (INFO): EventListener subscribed to event N_MINUS_1_FLOW_ALLOCATED
58565(1623235388)#internal-events (INFO): EventListener subscribed to event NEIGHBOR_ADDED
58565(1623235388)#internal-events (INFO): EventListener subscribed to event CONNECTIVITY_TO_NEIGHBOR_LOST
58565(1623235388)#internal-events (INFO): EventListener subscribed to event ADDRESS_CHANGE
58565(1623235388)#internal-events (INFO): EventListener subscribed to event NEIGHBOR_ADDRESS_CHANGE
58565(1623235388)#librina.timer (DBG): Timer with ID -841361408 started
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd9fb00) with fqn: '/ra/fsos' (parent '/ra')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd9fb00) with fqn: '/ra/fsos', succeeded. Instance id: '24'
58565(1623235388)#ipcp[4].routing-ps-link-state (DBG): Using Dijkstra as routing algorithm
58565(1623235388)#librina.application (INFO): Policy-set default selected for component namespace-manager
58565(1623235388)#ipcp (DBG): IPCPSecurityManager: No Auth policy Set specified, use AUTH-NONE
58565(1623235388)#librina.application (INFO): Policy-set default selected for component security-manager
58565(1623235388)#librina.security-manager (INFO): Authentication policy-set PSOC_authentication-none added to the security-manager
58565(1623235388)#librina.application (INFO): Policy-set default selected for component flow-allocator
58565(1623235388)#librina.timer (DBG): Timer with ID -841356368 started
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd9ed40) with fqn: '/difm/enr' (parent '/difm')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd9ed40) with fqn: '/difm/enr', succeeded. Instance id: '25'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd9fcc0) with fqn: '/difm/enr/neighs' (parent '/difm/enr')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd9fcc0) with fqn: '/difm/enr/neighs', succeeded. Instance id: '26'
58565(1623235388)#rib (DBG): Added create callback (specific) for class 'Neighbor' and path '/difm/enr/neighs'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdda0030) with fqn: '/difm/ops' (parent '/difm')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdda0030) with fqn: '/difm/ops', succeeded. Instance id: '27'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd9de00) with fqn: '/difm/nam' (parent '/difm')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd9de00) with fqn: '/difm/nam', succeeded. Instance id: '28'
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdda2250) with fqn: '/difm/nam/addr' (parent '/difm/nam')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdda2250) with fqn: '/difm/nam/addr', succeeded. Instance id: '29'
58565(1623235388)#librina.application (INFO): Policy-set default selected for component enrollment-task
58565(1623235388)#ipcp[4].enrollment-task (INFO): Could not parse use_reliable_n_flow, using default value: 0
58565(1623235388)#ipcp[4].enrollment-task (INFO): Could not parse peer_discovery_period_ms, using default value: 0
58565(1623235388)#ipcp[4].enrollment-task (INFO): Could not parse max_peer_discovery_attempts, using default value: 2147483647
58565(1623235388)#librina.timer (DBG): Timer with ID -841341344 started
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd8db10) with fqn: '/difm/enr/wd' (parent '/difm/enr')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd8db10) with fqn: '/difm/enr/wd', succeeded. Instance id: '30'
58565(1623235388)#librina.core (DBG): Added event of type(18) 18_DIF_REGISTRATION_NOTIFICATION and sequence number 0 to events queue
58565(1623235388)#ipcp[4].ipc-process (DBG): Got event of type 18_DIF_REGISTRATION_NOTIFICATION and sequence number 0
58565(1623235388)#ipcp[4].resource-allocator (INFO): IPC Process registered to N-1 DIF 200
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdda0590) with fqn: '/ipcm/irm/uregs/dif=200' (parent '/ipcm/irm/uregs')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdda0590) with fqn: '/ipcm/irm/uregs/dif=200', succeeded. Instance id: '31'
58565(1623235388)#librina.core (DBG): Added event of type(18) 18_DIF_REGISTRATION_NOTIFICATION and sequence number 0 to events queue
58565(1623235388)#ipcp[4].ipc-process (DBG): Got event of type 18_DIF_REGISTRATION_NOTIFICATION and sequence number 0
58565(1623235388)#ipcp[4].resource-allocator (INFO): IPC Process registered to N-1 DIF 210
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdda09f0) with fqn: '/ipcm/irm/uregs/dif=210' (parent '/ipcm/irm/uregs')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdda09f0) with fqn: '/ipcm/irm/uregs/dif=210', succeeded. Instance id: '32'

2.5 Register IPC Process to N-1 DIF

You should see the following messages in the ipcm.log file:

58553(1623235388)#ipcm (INFO)[register_at_dif]: Requested DIF registration of IPC process tor2.normal.DIF:1:: at DIF 500::: through IPC process tor2.500:1::

58553(1623235388)#librina.core (DBG): Added event of type(22) 22_IPCM_REGISTER_APP_RESPONSE and sequence number 8 to events queue
58553(1623235388)#ipcm (DBG): Got event of type 22_IPCM_REGISTER_APP_RESPONSE and sequence number 8
58553(1623235388)#ipcm.ipcp (INFO)[ipcm_register_response_ipcp]: IPC process tor2.normal.DIF:1:: informed about its registration to N-1 DIF 500:::

You should also see the following messages on the IPC Process Daemon log file (tor2.normal.DIF-1.log in this example):

58565(1623235388)#librina.core (DBG): Added event of type(18) 18_DIF_REGISTRATION_NOTIFICATION and sequence number 0 to events queue
58565(1623235388)#ipcp[4].ipc-process (DBG): Got event of type 18_DIF_REGISTRATION_NOTIFICATION and sequence number 0
58565(1623235388)#ipcp[4].resource-allocator (INFO): IPC Process registered to N-1 DIF 500
58565(1623235388)#rib (DBG): Starting add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd9f3c0) with fqn: '/ipcm/irm/uregs/dif=500' (parent '/ipcm/irm/uregs')
58565(1623235388)#rib (DBG): Add object operation over RIB(0x5613cdd95a90), of object(0x5613cdd9f3c0) with fqn: '/ipcm/irm/uregs/dif=500', succeeded. Instance id: '33'