{"action":"closed","issue":{"url":"https://api.github.com/repos/IRATI/stack/issues/522","labels_url":"https://api.github.com/repos/IRATI/stack/issues/522/labels{/name}","comments_url":"https://api.github.com/repos/IRATI/stack/issues/522/comments","events_url":"https://api.github.com/repos/IRATI/stack/issues/522/events","html_url":"https://github.com/IRATI/stack/issues/522","id":65414847,"number":522,"title":"Normal over normal over shim HV: Enrollment succeeded, rina-echo-time fails","user":{"login":"sandervrijders","id":1212456,"avatar_url":"https://avatars.githubusercontent.com/u/1212456?v=3","gravatar_id":"","url":"https://api.github.com/users/sandervrijders","html_url":"https://github.com/sandervrijders","followers_url":"https://api.github.com/users/sandervrijders/followers","following_url":"https://api.github.com/users/sandervrijders/following{/other_user}","gists_url":"https://api.github.com/users/sandervrijders/gists{/gist_id}","starred_url":"https://api.github.com/users/sandervrijders/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/sandervrijders/subscriptions","organizations_url":"https://api.github.com/users/sandervrijders/orgs","repos_url":"https://api.github.com/users/sandervrijders/repos","events_url":"https://api.github.com/users/sandervrijders/events{/privacy}","received_events_url":"https://api.github.com/users/sandervrijders/received_events","type":"User","site_admin":false},"labels":[],"state":"closed","locked":false,"assignee":null,"milestone":null,"comments":3,"created_at":"2015-03-31T10:07:28Z","updated_at":"2015-04-15T08:20:06Z","closed_at":"2015-04-15T08:20:06Z","body":"vm1\r\n---\r\n\r\nAda-1.log\r\n```\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#netlink-manager (DBG): Netlink Manager constructor called, with netlink pid = 4209\r\n4209(1427796254)#netlink-manager (INFO): Netlink socket connected to local port 4209 \r\n4209(1427796254)#netlink-manager (DBG): Generic Netlink RINA family id: 22\r\n4209(1427796254)#core (DBG): Initialized Netlink Manager\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#concurrency (DBG): Condition variable created successfully\r\n4209(1427796254)#core (DBG): Initialized event queue\r\n4209(1427796254)#core (DBG): Started Netlink Message reader thread\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#ipc-process (INFO): Librina initialized\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#core (DBG): Waiting for message 4209\r\n4209(1427796254)#ipc-process (INFO): Pluggable component 'security-manager'/'default' [default] published\r\n4209(1427796254)#ipc-process (INFO): Pluggable component 'flow-allocator'/'default' [default] published\r\n4209(1427796254)#ipc-process (INFO): Pluggable component 'namespace-manager'/'default' [default] published\r\n4209(1427796254)#ipc-process (INFO): Pluggable component 'resource-allocator'/'default' [default] published\r\n4209(1427796254)#ipc-process (INFO): Pluggable component 'routing'/'link-state' [default] published\r\n4209(1427796254)#ipc-process (INFO): Plugin default loaded successfully\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#rib-daemon (INFO): EventListener subscribed to event 5_N_MINUS_1_FLOW_ALLOCATED\r\n4209(1427796254)#rib-daemon (INFO): EventListener subscribed to event 7_N_MINUS_1_FLOW_DEALLOCATED\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#rib (INFO): Object with name /daf/management/neighbors, class neighbor set, instance 1 added to the RIB\r\n4209(1427796254)#rib (INFO): Object with name /daf/management/enrollment, class enrollment information, instance 2 added to the RIB\r\n4209(1427796254)#rib (INFO): Object with name /daf/management/operationalStatus, class operationstatus, instance 3 added to the RIB\r\n4209(1427796254)#rib (INFO): Object with name /daf/management/naming/address, class address, instance 4 added to the RIB\r\n4209(1427796254)#rib-daemon (INFO): EventListener subscribed to event 7_N_MINUS_1_FLOW_DEALLOCATED\r\n4209(1427796254)#rib-daemon (INFO): EventListener subscribed to event 5_N_MINUS_1_FLOW_ALLOCATED\r\n4209(1427796254)#rib-daemon (INFO): EventListener subscribed to event 6_N_MINUS_1_FLOW_ALLOCATION_FAILED\r\n4209(1427796254)#rib-daemon (INFO): EventListener subscribed to event 8_NEIGHBOR_DECLARED_DEAD\r\n4209(1427796254)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/difregistrations, class DIF registration set, instance 5 added to the RIB\r\n4209(1427796254)#rib-daemon (INFO): Starting Management SDU reader ...\r\n4209(1427796254)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/nminusoneflows, class nminusone flow set, instance 6 added to the RIB\r\n4209(1427796254)#rib-daemon (INFO): EventListener subscribed to event 0_CONNECTIVITY_TO_NEIGHBOR_LOST\r\n4209(1427796254)#rib (INFO): Object with name /dif/management/flowallocator/directoryforwardingtableentries, class directoryforwardingtableentry set, instance 7 added to the RIB\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#rib (INFO): Object with name /daf/management/naming/whatevercastnames, class whatname set, instance 8 added to the RIB\r\n4209(1427796254)#rib (INFO): Object with name /dif/resourceallocation/flowallocator/flows, class flow set, instance 9 added to the RIB\r\n4209(1427796254)#rib (INFO): Object with name /dif/management/flowallocator/qoscubes, class qoscube set, instance 10 added to the RIB\r\n4209(1427796254)#rib (INFO): Object with name /dif/ipc/datatransfer/constants, class datatransfercons, instance 11 added to the RIB\r\n4209(1427796254)#ipcp-components (INFO): Policy-set default selected for component security-manager\r\n4209(1427796254)#ipcp-components (INFO): Policy-set default selected for component flow-allocator\r\n4209(1427796254)#ipcp-components (INFO): Policy-set default selected for component namespace-manager\r\n4209(1427796254)#ipcp-components (INFO): Policy-set default selected for component resource-allocator\r\n4209(1427796254)#ipcp-components (INFO): Policy-set link-state selected for component routing\r\n4209(1427796254)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n4209(1427796254)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 41_IPCP_INIT; Sport: 4209; Dport: 1; Seqnum: 0; Notification; SIPCP: 3; DIPCP: 0\r\n4209(1427796254)#ipc-process (INFO): Initialized IPC Process with name: Ada, instance 1, id 3 \r\n4209(1427796254)#ipcp-main (INFO): IPC Process name:     Ada\r\n4209(1427796254)#ipcp-main (INFO): IPC Process instance: 1\r\n4209(1427796254)#ipcp-main (INFO): IPC Process id:       3\r\n4209(1427796254)#ipcp-main (INFO): IPC Manager port:     1\r\n4209(1427796254)#ipcp-main (INFO): IPC Process initialized, executing event loop...\r\n4209(1427796254)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 1_ASSIGN_TO_DIF_REQ; Sport: 1; Dport: 4209; Seqnum: 4; Request; SIPCP: 0; DIPCP: 3 \r\n4209(1427796254)#core (DBG): Added event of type 12_ASSIGN_TO_DIF_REQUEST and sequence number 4 to events queue\r\n4209(1427796254)#core (DBG): Waiting for message 4209\r\n4209(1427796254)#event-loop (DBG): Got event of type 12_ASSIGN_TO_DIF_REQUEST and sequence number 4\r\n4209(1427796254)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 2_ASSIGN_TO_DIF_RESP; Sport: 0; Dport: 4209; Seqnum: 1427796255; Response; SIPCP: 3; DIPCP: 0 \r\n4209(1427796254)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 1_ASSIGN_TO_DIF_REQ; Sport: 4209; Dport: 0; Seqnum: 1427796255; Request; SIPCP: 3; DIPCP: 3\r\n4209(1427796254)#core (DBG): Added event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 1427796255 to events queue\r\n4209(1427796254)#core (DBG): Waiting for message 4209\r\n4209(1427796254)#event-loop (DBG): Got event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 1427796255\r\n4209(1427796254)#ipc-process (DBG): The kernel processed successfully the Assign to DIF request\r\n4209(1427796254)#rib-daemon (DBG): Configuration set: 5\r\n4209(1427796254)#resource-allocator (DBG): DIF configuration set 5\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#timer (DBG): Timer with ID 37192720 started\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#rib (INFO): Object with name /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup, class flowstateobject set, instance 12 added to the RIB\r\n4209(1427796254)#rib-daemon (INFO): EventListener subscribed to event 7_N_MINUS_1_FLOW_DEALLOCATED\r\n4209(1427796254)#rib-daemon (INFO): EventListener subscribed to event 5_N_MINUS_1_FLOW_ALLOCATED\r\n4209(1427796254)#rib-daemon (INFO): EventListener subscribed to event 9_NEIGHBOR_ADDED\r\n4209(1427796254)#rib-daemon (INFO): EventListener subscribed to event 0_CONNECTIVITY_TO_NEIGHBOR_LOST\r\n4209(1427796254)#namespace-manager (DBG): DIF configuration set: 5\r\n4209(1427796254)#security-manager (DBG): Set dif configuration: 5\r\n4209(1427796254)#rib (INFO): Object with name /dif/management/flowallocator/qoscubes/unreliablewithflowcontrol, class qoscube, instance 13 added to the RIB\r\n4209(1427796254)#rib (INFO): Object with name /dif/management/flowallocator/qoscubes/reliablewithflowcontrol, class qoscube, instance 14 added to the RIB\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#concurrency (DBG): Lockable created successfully\r\n4209(1427796254)#timer (DBG): Timer with ID 37196976 started\r\n4209(1427796254)#rib (INFO): Object with name /difmanagement/watchdog, class watchdog timer, instance 15 added to the RIB\r\n4209(1427796254)#enrollment-task (DBG): Started Neighbors enroller thread\r\n4209(1427796254)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 2_ASSIGN_TO_DIF_RESP; Sport: 4209; Dport: 1; Seqnum: 4; Response; SIPCP: 3; DIPCP: 0\r\n4209(1427796254)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 5_DIF_REG_NOT; Sport: 1; Dport: 4209; Seqnum: 0; Notification; SIPCP: 0; DIPCP: 3 \r\n4209(1427796254)#core (DBG): Added event of type 18_DIF_REGISTRATION_NOTIFICATION and sequence number 0 to events queue\r\n4209(1427796254)#core (DBG): Waiting for message 4209\r\n4209(1427796254)#event-loop (DBG): Got event of type 18_DIF_REGISTRATION_NOTIFICATION and sequence number 0\r\n4209(1427796254)#resource-allocator (INFO): IPC Process registered to N-1 DIF test-normal.DIF\r\n4209(1427796254)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/difregistrations/test-normal.DIF, class DIF registration, instance 16 added to the RIB\r\n4209(1427796281)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 44_APP_ALLOC_FLOW_REQ_ARR; Sport: 1; Dport: 4209; Seqnum: 7; Request; SIPCP: 0; DIPCP: 3 \r\n4209(1427796281)#core (DBG): Added event of type 0_FLOW_ALLOCATION_REQUESTED and sequence number 7 to events queue\r\n4209(1427796281)#core (DBG): Waiting for message 4209\r\n4209(1427796281)#event-loop (DBG): Got event of type 0_FLOW_ALLOCATION_REQUESTED and sequence number 7\r\n4209(1427796281)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 45_APP_ALLOC_FLOW_RESP; Sport: 4209; Dport: 1; Seqnum: 7; Response; SIPCP: 3; DIPCP: 0\r\n4209(1427796281)#resource-allocator (INFO): Accepted new flow from IPC Process Knuth-1\r\n4209(1427796281)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/nminusoneflows/5, class nminusone flow, instance 17 added to the RIB\r\n4209(1427796281)#rib-daemon (INFO): Event 5_N_MINUS_1_FLOW_ALLOCATED has just happened. Notifying event listeners.\r\n4209(1427796281)#routing-ps-link-state (DBG): flow allocation waiting for enrollment\r\n4209(1427796281)#concurrency (DBG): Lockable created successfully\r\n4209(1427796281)#cdap-manager (DBG): Created a new CDAP session for port 5\r\n4209(1427796281)#rib-daemon (DBG): Received CDAP message through portId 5: \r\n0_M_CONNECT\r\nAbstract syntax: 115\r\nAuthentication mechanism: 0\r\nSource AP name: Knuth\r\nSource AP instance: 1\r\nSource AE name: Management\r\nDestination AP name: Ada\r\nDestination AP instance: 1\r\nDestination AE name: Management\r\nInvoke id: 1\r\nVersion: 1\r\n\r\n4209(1427796281)#enrollment-task (DBG): Received M_CONNECT CDAP message from port-id 5\r\n4209(1427796281)#concurrency (DBG): Lockable created successfully\r\n4209(1427796281)#concurrency (DBG): Lockable created successfully\r\n4209(1427796281)#timer (DBG): Timer with ID 402666208 started\r\n4209(1427796281)#concurrency (DBG): Lockable created successfully\r\n4209(1427796281)#enrollment-task (DBG): Created a new Enrollment state machine for remote IPC process: Knuth-1-Management-\r\n4209(1427796281)#enrollment-task (DBG): Authenticating IPC process Knuth-1 ...\r\n4209(1427796281)#enrollment-task (DBG): Authentication successful, deciding if new member can join the DIF...\r\n4209(1427796281)#security-manager-ps-default (DBG): Allowing IPC Process Knuth to join the DIF\r\n4209(1427796281)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n4209(1427796281)#rib-daemon (DBG): Sent CDAP message of size 88 through port-id 5: \r\n1_M_CONNECT_R\r\nAbstract syntax: 115\r\nAuthentication mechanism: 0\r\nSource AP name: Ada\r\nSource AP instance: 1\r\nSource AE name: Management\r\nDestination AP name: Knuth\r\nDestination AP instance: 1\r\nDestination AE name: Management\r\nInvoke id: 1\r\nResult: 0\r\nVersion: 1\r\n\r\n4209(1427796281)#enrollment-task (DBG): M_CONNECT_R sent to portID 5. Waiting for start enrollment request message\r\n4209(1427796281)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n4209(1427796282)#rib-daemon (DBG): Received CDAP message through portId 5: \r\n14_M_START\r\nInvoke id: 1\r\nObject class: enrollment information\r\nObject name: /daf/management/enrollment\r\nObject value: 0x7f4918003c40\r\nScope: 0\r\n\r\n4209(1427796282)#rib (DBG): Remote operation 14 called on object /daf/management/enrollment\r\n4209(1427796282)#enrollment-task (DBG): Remote IPC Process address: 6\r\n4209(1427796282)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n4209(1427796282)#rib-daemon (DBG): Sent CDAP message of size 106 through port-id 5: \r\n15_M_START_r\r\nInvoke id: 1\r\nObject class: enrollment information\r\nObject name: /daf/management/enrollment\r\nResult: 0\r\n\r\n4209(1427796282)#enrollment-task (DBG): No DFT entries to be sent\r\n4209(1427796282)#application (DBG): IPCManager.getRegisteredApplications called\r\n4209(1427796282)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n4209(1427796282)#rib-daemon (DBG): Sent CDAP message of size 128 through port-id 5: \r\n4_M_CREATE\r\nObject class: neighbor set\r\nObject name: /daf/management/neighbors\r\nObject value: 0x7f4918003a00\r\nScope: 0\r\n\r\n4209(1427796282)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n4209(1427796282)#rib-daemon (DBG): Sent CDAP message of size 131 through port-id 5: \r\n16_M_STOP\r\nInvoke id: 1\r\nObject class: enrollment information\r\nObject name: /daf/management/enrollment\r\nObject value: 0x7f4918003a00\r\nScope: 0\r\n\r\n4209(1427796282)#enrollment-task (DBG): Waiting for stop enrollment response message\r\n4209(1427796282)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n4209(1427796282)#rib-daemon (DBG): Received CDAP message through portId 5: \r\n17_M_STOP_R\r\nInvoke id: 1\r\nResult: 0\r\n\r\n4209(1427796282)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n4209(1427796282)#rib-daemon (DBG): Sent CDAP message of size 106 through port-id 5: \r\n14_M_START\r\nObject class: operationstatus\r\nObject name: /daf/management/operationalStatus\r\nScope: 0\r\n\r\n4209(1427796282)#timer (DBG): Waiting for the timer 402666208 to join\r\n4209(1427796282)#timer (DBG): Timer with ID 402666208 ended\r\n4209(1427796282)#application (DBG): IPCManager.getRegisteredApplications called\r\n4209(1427796282)#rib (INFO): Object with name /daf/management/neighbors/Knuth, class neighbor, instance 18 added to the RIB\r\n4209(1427796282)#rib-daemon (INFO): Event 9_NEIGHBOR_ADDED has just happened. Notifying event listeners.\r\n4209(1427796282)#routing-ps-link-state (INFO): There was an allocation flow event waiting for enrollment, launching it\r\n4209(1427796282)#rib (INFO): Object with name /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup/5-6, class flowstateobject, instance 19 added to the RIB\r\n4209(1427796282)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n4209(1427796282)#rib-daemon (DBG): Sent CDAP message of size 160 through port-id 5: \r\n12_M_WRITE\r\nObject class: flowstateobject set\r\nObject name: /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup\r\nObject value: 0x7f4918003010\r\nScope: 0\r\n\r\n4209(1427796282)#enrollment-task (INFO): Remote IPC Process enrolled!\r\n4209(1427796282)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n4209(1427796282)#rib-daemon (DBG): Received CDAP message through portId 5: \r\n12_M_WRITE\r\nObject class: flowstateobject set\r\nObject name: /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup\r\nObject value: 0x7f4918003e30\r\nScope: 0\r\n\r\n4209(1427796282)#rib (DBG): Remote operation 12 called on object /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup\r\n4209(1427796282)#routing-ps-link-state (DBG): Update objects from DB launched\r\n4209(1427796282)#routing-ps-link-state (DBG): New object added\r\n4209(1427796282)#rib (INFO): Object with name /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup/6-5, class flowstateobject, instance 20 added to the RIB\r\n4209(1427796282)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n4209(1427796283)#routing-ps-link-state (DBG): Processing flow state object: /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup/5-6\r\n4209(1427796283)#routing-ps-link-state (DBG): Processing flow state object: /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup/6-5\r\n4209(1427796283)#routing-ps-link-state (DBG): Added entry to routing table: destination 6, next-hop 6\r\n4209(1427796283)#resource-allocator-ps-default (DBG): Got 1 entries in the routing table\r\n4209(1427796283)#resource-allocator-ps-default (DBG): Processing entry for destination 6\r\n4209(1427796283)#resource-allocator-ps-default (DBG): Next hop address 6\r\n4209(1427796283)#resource-allocator-ps-default (DBG): N-1 port-id: 5\r\n4209(1427796283)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 24_MODIFY_FT_REQ; Sport: 4209; Dport: 0; Seqnum: 1427796256; Request; SIPCP: 3; DIPCP: 3\r\n4209(1427796283)#routing-ps-link-state (DBG): Propagation: Check modified object /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup/5-6 with age 1 and status 1\r\n4209(1427796283)#routing-ps-link-state (DBG): Propagation: Check modified object /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup/6-5 with age 1 and status 1\r\n4209(1427796358)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 11_IPCM_ALLOC_FLOW_REQ; Sport: 1; Dport: 4209; Seqnum: 8; Request; SIPCP: 0; DIPCP: 3 \r\n4209(1427796358)#core (DBG): Added event of type 0_FLOW_ALLOCATION_REQUESTED and sequence number 8 to events queue\r\n4209(1427796358)#core (DBG): Waiting for message 4209\r\n4209(1427796358)#event-loop (DBG): Got event of type 0_FLOW_ALLOCATION_REQUESTED and sequence number 8\r\n4209(1427796358)#syscalls (DBG): Gonna call syscall SYS_allocatePortId (321)\r\n4209(1427796358)#flow-allocator (DBG): Got assigned port-id 6\r\n4209(1427796358)#concurrency (DBG): Lockable created successfully\r\n4209(1427796358)#concurrency (DBG): Lockable created successfully\r\n4209(1427796358)#timer (DBG): Timer with ID 37197008 started\r\n4209(1427796358)#concurrency (DBG): Lockable created successfully\r\n4209(1427796358)#concurrency (DBG): Lockable created successfully\r\n4209(1427796358)#concurrency (DBG): Lockable created successfully\r\n4209(1427796358)#timer (DBG): Timer with ID 37197040 started\r\n4209(1427796358)#flow-allocator (DBG): Created flow allocator instance to manage the flow identified by portId 6 \r\n4209(1427796358)#flow-allocator-ps-default (DBG): Selected qos cube with name unreliablewithflowcontrol\r\n4209(1427796358)#flow-allocator (DBG): Generated flow object\r\n4209(1427796358)#flow-allocator (DBG): The directory forwarding table returned address 0\r\n4209(1427796358)#flow-allocator (ERR): Problems allocating flow: Could not find entry in DFT for application rina.apps.echotime.server:1::\r\n4209(1427796358)#timer (DBG): Waiting for the timer 37197040 to join\r\n4209(1427796358)#timer (DBG): Timer with ID 37197040 ended\r\n4209(1427796358)#timer (DBG): Waiting for the timer 37197008 to join\r\n4209(1427796359)#timer (DBG): Timer with ID 37197008 ended\r\n4209(1427796359)#syscalls (DBG): Gonna call syscall SYS_deallocatePortId (322)\r\n4209(1427796359)#syscalls (ERR): Syscall deallocate port id failed: -1\r\n4209(1427796359)#flow-allocator (ERR): Problems releasing port-id 6: Problems requesting the allocation/deallocation of a port-id\r\n4209(1427796359)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 13_IPCM_ALLOC_FLOW_REQ_RES; Sport: 4209; Dport: 1; Seqnum: 8; Response; SIPCP: 3; DIPCP: 0\r\n4209(1427796374)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n4209(1427796374)#rib-daemon (DBG): Sent CDAP message of size 95 through port-id 5: \r\n8_M_READ\r\nInvoke id: 1\r\nObject class: watchdog timer\r\nObject name: /difmanagement/watchdog\r\nScope: 0\r\n\r\n```\r\n\r\nipcm.log\r\n```\r\n4199(1427796254)#concurrency (DBG): Lockable created successfully\r\n4199(1427796254)#netlink-manager (DBG): Netlink Manager constructor called, with netlink pid = 1\r\n4199(1427796254)#netlink-manager (INFO): Netlink socket connected to local port 1 \r\n4199(1427796254)#netlink-manager (DBG): Generic Netlink RINA family id: 22\r\n4199(1427796254)#core (DBG): Initialized Netlink Manager\r\n4199(1427796254)#concurrency (DBG): Lockable created successfully\r\n4199(1427796254)#concurrency (DBG): Condition variable created successfully\r\n4199(1427796254)#core (DBG): Initialized event queue\r\n4199(1427796254)#core (DBG): Started Netlink Message reader thread\r\n4199(1427796254)#core (DBG): Waiting for message 1\r\n4199(1427796254)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 28_IPCM_PRESENT; Sport: 1; Dport: 0; Seqnum: 0; Notification; SIPCP: 0; DIPCP: 0\r\n4199(1427796254)#ipcm (DBG): IPC Manager daemon initialized\r\n4199(1427796254)#ipcm (DBG):        installation path: /usr/local/irati/bin\r\n4199(1427796254)#ipcm (DBG):        library path: /usr/local/irati/lib\r\n4199(1427796254)#ipcm (DBG):        log folder: /usr/local/irati/var/log\r\n4199(1427796254)#ipcm (DBG): Starting main I/O loop...\r\n4199(1427796254)#ipcm.console (DBG): Console starts [fd=5]\r\n\r\n4199(1427796254)#ipcm.scripting (DBG): script starts\r\n4199(1427796254)#concurrency (DBG): Lockable created successfully\r\n4199(1427796254)#concurrency (DBG): Condition variable created successfully\r\n4199(1427796254)#concurrency (DBG): Lockable created successfully\r\n4199(1427796254)#concurrency (DBG): Condition variable created successfully\r\n4199(1427796254)#syscalls (DBG): Gonna call syscall SYS_createIPCProcess (317)\r\n4199(1427796254)#concurrency (DBG): Read/Write Lockable created successfully\r\n4199(1427796254)#ipcm (INFO)[create_ipcp]: IPC process test-shim-hv.IPCP:1:: created [id = 1]\r\n\r\n4199(1427796254)#concurrency (DBG): Lockable created successfully\r\n4199(1427796254)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 2_ASSIGN_TO_DIF_RESP; Sport: 0; Dport: 1; Seqnum: 1; Response; SIPCP: 1; DIPCP: 0 \r\n4199(1427796254)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 1_ASSIGN_TO_DIF_REQ; Sport: 1; Dport: 0; Seqnum: 1; Request; SIPCP: 0; DIPCP: 1\r\n4199(1427796254)#core (DBG): Added event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 1 to events queue\r\n4199(1427796254)#core (DBG): Waiting for message 1\r\n4199(1427796254)#ipcm (INFO)[assign_to_dif]: Requested DIF assignment of IPC process test-shim-hv.IPCP:1:: to DIF test-shim-hv.DIF:::\r\n\r\n4199(1427796254)#ipcm (DBG): Got event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 1\r\n4199(1427796254)#ipcm.ipcp (INFO)[assign_to_dif_response_event_handler]: DIF assignment operation completed for IPC process test-shim-hv.IPCP:1:: [success=1]\r\n\r\n4199(1427796254)#syscalls (DBG): Gonna call syscall SYS_createIPCProcess (317)\r\n4199(1427796254)#ipc-manager (DBG): Craeted a new IPC Process with pid = 4203\r\n4199(1427796254)#concurrency (DBG): Read/Write Lockable created successfully\r\n4199(1427796254)#concurrency (DBG): Lockable created successfully\r\n4199(1427796254)#ipcm (INFO)[create_ipcp]: IPC process test-normal-1.IPCP:1:: created and waiting for initialization[id = 2]\r\n\r\n4203(1427796254)#ipc-manager (DBG): New OS Process created, executing IPC Process ...\r\n4203(1427796254)#ipc-manager (DBG): argv[0]: /usr/local/irati/bin/ipcp\r\n4199(1427796254)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 41_IPCP_INIT; Sport: 4203; Dport: 1; Seqnum: 0; Notification; SIPCP: 2; DIPCP: 0 \r\n4199(1427796254)#core (DBG): Added event of type 28_IPC_PROCESS_DAEMON_INITIALIZED and sequence number 0 to events queue\r\n4199(1427796254)#core (DBG): Waiting for message 1\r\n4199(1427796254)#ipcm (DBG): Got event of type 28_IPC_PROCESS_DAEMON_INITIALIZED and sequence number 0\r\n4199(1427796254)#ipcm.ipcp (INFO)[ipc_process_daemon_initialized_event_handler]: IPC process daemon initialized [id = 2]\r\n\r\n4199(1427796254)#concurrency (DBG): Lockable created successfully\r\n4199(1427796254)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 1_ASSIGN_TO_DIF_REQ; Sport: 1; Dport: 4203; Seqnum: 2; Request; SIPCP: 0; DIPCP: 2\r\n4199(1427796254)#ipcm (INFO)[assign_to_dif]: Requested DIF assignment of IPC process test-normal-1.IPCP:1:: to DIF test-normal.DIF:::\r\n\r\n4199(1427796254)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 2_ASSIGN_TO_DIF_RESP; Sport: 4203; Dport: 1; Seqnum: 2; Response; SIPCP: 2; DIPCP: 0 \r\n4199(1427796254)#core (DBG): Added event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 2 to events queue\r\n4199(1427796254)#core (DBG): Waiting for message 1\r\n4199(1427796254)#ipcm (DBG): Got event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 2\r\n4199(1427796254)#ipcm.ipcp (INFO)[assign_to_dif_response_event_handler]: DIF assignment operation completed for IPC process test-normal-1.IPCP:1:: [success=1]\r\n\r\n4199(1427796254)#concurrency (DBG): Lockable created successfully\r\n4199(1427796254)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 18_IPCM_REG_APP_REQ; Sport: 1; Dport: 0; Seqnum: 3; Request; SIPCP: 0; DIPCP: 1\r\n4199(1427796254)#ipcm (INFO)[register_at_dif]: Requested DIF registration of IPC process test-normal-1.IPCP:1:: at DIF test-shim-hv.DIF::: through IPC process test-shim-hv.IPCP:1::\r\n\r\n4199(1427796254)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 19_ICPM_REG_APP_RESP; Sport: 0; Dport: 1; Seqnum: 3; Response; SIPCP: 1; DIPCP: 0 \r\n4199(1427796254)#core (DBG): Added event of type 23_IPCM_REGISTER_APP_RESPONSE and sequence number 3 to events queue\r\n4199(1427796254)#core (DBG): Waiting for message 1\r\n4199(1427796254)#ipcm (DBG): Got event of type 23_IPCM_REGISTER_APP_RESPONSE and sequence number 3\r\n4199(1427796254)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 5_DIF_REG_NOT; Sport: 1; Dport: 4203; Seqnum: 0; Notification; SIPCP: 0; DIPCP: 2\r\n4199(1427796254)#ipcm.ipcp (INFO)[ipcm_register_response_ipcp]: IPC process test-normal-1.IPCP:1:: informed about its registration to N-1 DIF test-shim-hv.DIF:::\r\n\r\n4199(1427796254)#syscalls (DBG): Gonna call syscall SYS_createIPCProcess (317)\r\n4199(1427796254)#ipc-manager (DBG): Craeted a new IPC Process with pid = 4209\r\n4199(1427796254)#concurrency (DBG): Read/Write Lockable created successfully\r\n4199(1427796254)#concurrency (DBG): Lockable created successfully\r\n4199(1427796254)#ipcm (INFO)[create_ipcp]: IPC process Ada:1:: created and waiting for initialization[id = 3]\r\n\r\n4209(1427796254)#ipc-manager (DBG): New OS Process created, executing IPC Process ...\r\n4209(1427796254)#ipc-manager (DBG): argv[0]: /usr/local/irati/bin/ipcp\r\n4199(1427796254)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 41_IPCP_INIT; Sport: 4209; Dport: 1; Seqnum: 0; Notification; SIPCP: 3; DIPCP: 0 \r\n4199(1427796254)#core (DBG): Added event of type 28_IPC_PROCESS_DAEMON_INITIALIZED and sequence number 0 to events queue\r\n4199(1427796254)#core (DBG): Waiting for message 1\r\n4199(1427796254)#ipcm (DBG): Got event of type 28_IPC_PROCESS_DAEMON_INITIALIZED and sequence number 0\r\n4199(1427796254)#ipcm.ipcp (INFO)[ipc_process_daemon_initialized_event_handler]: IPC process daemon initialized [id = 3]\r\n\r\n4199(1427796254)#concurrency (DBG): Lockable created successfully\r\n4199(1427796254)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 1_ASSIGN_TO_DIF_REQ; Sport: 1; Dport: 4209; Seqnum: 4; Request; SIPCP: 0; DIPCP: 3\r\n4199(1427796254)#ipcm (INFO)[assign_to_dif]: Requested DIF assignment of IPC process Ada:1:: to DIF fantastic.DIF:::\r\n\r\n4199(1427796254)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 2_ASSIGN_TO_DIF_RESP; Sport: 4209; Dport: 1; Seqnum: 4; Response; SIPCP: 3; DIPCP: 0 \r\n4199(1427796254)#core (DBG): Added event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 4 to events queue\r\n4199(1427796254)#core (DBG): Waiting for message 1\r\n4199(1427796254)#ipcm (DBG): Got event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 4\r\n4199(1427796254)#ipcm.ipcp (INFO)[assign_to_dif_response_event_handler]: DIF assignment operation completed for IPC process Ada:1:: [success=1]\r\n\r\n4199(1427796254)#concurrency (DBG): Lockable created successfully\r\n4199(1427796254)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 18_IPCM_REG_APP_REQ; Sport: 1; Dport: 4203; Seqnum: 5; Request; SIPCP: 0; DIPCP: 2\r\n4199(1427796254)#ipcm (INFO)[register_at_dif]: Requested DIF registration of IPC process Ada:1:: at DIF test-normal.DIF::: through IPC process test-normal-1.IPCP:1::\r\n\r\n4199(1427796254)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 19_ICPM_REG_APP_RESP; Sport: 4203; Dport: 1; Seqnum: 5; Response; SIPCP: 2; DIPCP: 0 \r\n4199(1427796254)#core (DBG): Added event of type 23_IPCM_REGISTER_APP_RESPONSE and sequence number 5 to events queue\r\n4199(1427796254)#core (DBG): Waiting for message 1\r\n4199(1427796254)#ipcm (DBG): Got event of type 23_IPCM_REGISTER_APP_RESPONSE and sequence number 5\r\n4199(1427796254)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 5_DIF_REG_NOT; Sport: 1; Dport: 4209; Seqnum: 0; Notification; SIPCP: 0; DIPCP: 3\r\n4199(1427796254)#ipcm.ipcp (INFO)[ipcm_register_response_ipcp]: IPC process Ada:1:: informed about its registration to N-1 DIF test-normal.DIF:::\r\n\r\n4199(1427796254)#concurrency (DBG): Lockable created successfully\r\n4199(1427796254)#concurrency (DBG): Condition variable created successfully\r\n4199(1427796254)#concurrency (DBG): Lockable created successfully\r\n4199(1427796254)#concurrency (DBG): Condition variable created successfully\r\n4199(1427796254)#concurrency (DBG): Lockable created successfully\r\n4199(1427796254)#concurrency (DBG): Condition variable created successfully\r\n4199(1427796254)#ipcm.scripting (DBG): script stops\r\n4199(1427796255)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 12_IPCM_ALLOC_FLOW_RESP_ARR; Sport: 0; Dport: 1; Seqnum: 2; Request; SIPCP: 1; DIPCP: 0 \r\n4199(1427796255)#core (DBG): Added event of type 0_FLOW_ALLOCATION_REQUESTED and sequence number 2 to events queue\r\n4199(1427796255)#core (DBG): Waiting for message 1\r\n4199(1427796255)#ipcm (DBG): Got event of type 0_FLOW_ALLOCATION_REQUESTED and sequence number 2\r\n4199(1427796255)#concurrency (DBG): Lockable created successfully\r\n4199(1427796255)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 44_APP_ALLOC_FLOW_REQ_ARR; Sport: 1; Dport: 4203; Seqnum: 6; Request; SIPCP: 0; DIPCP: 2\r\n4199(1427796255)#ipcm.flow-alloc (INFO)[flow_allocation_requested_remote]: Arrived request for flow allocation between test-normal-1.IPCP:1:: and test-normal-2.IPCP:1::\r\n\r\n4199(1427796255)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 45_APP_ALLOC_FLOW_RESP; Sport: 4203; Dport: 1; Seqnum: 6; Response; SIPCP: 2; DIPCP: 0 \r\n4199(1427796255)#core (DBG): Added event of type 2_ALLOCATE_FLOW_RESPONSE and sequence number 6 to events queue\r\n4199(1427796255)#core (DBG): Waiting for message 1\r\n4199(1427796255)#ipcm (DBG): Got event of type 2_ALLOCATE_FLOW_RESPONSE and sequence number 6\r\n4199(1427796255)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 14_IPCM_ALLOC_FLOW_RESP; Sport: 1; Dport: 0; Seqnum: 2; Response; SIPCP: 2; DIPCP: 1\r\n4199(1427796255)#ipcm.flow-alloc (INFO)[allocate_flow_response_event_handler]: : Informing IPC process test-shim-hv.IPCP:1:: about flow allocation from application test-normal-1.IPCP:1:: to application test-normal-2.IPCP:1:: in DIF test-shim-hv.DIF::: [success = 1, port-id = 4]\r\n\r\n4199(1427796281)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 12_IPCM_ALLOC_FLOW_RESP_ARR; Sport: 4203; Dport: 1; Seqnum: 1427796258; Request; SIPCP: 2; DIPCP: 0 \r\n4199(1427796281)#core (DBG): Added event of type 0_FLOW_ALLOCATION_REQUESTED and sequence number 1427796258 to events queue\r\n4199(1427796281)#core (DBG): Waiting for message 1\r\n4199(1427796281)#ipcm (DBG): Got event of type 0_FLOW_ALLOCATION_REQUESTED and sequence number 1427796258\r\n4199(1427796281)#concurrency (DBG): Lockable created successfully\r\n4199(1427796281)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 44_APP_ALLOC_FLOW_REQ_ARR; Sport: 1; Dport: 4209; Seqnum: 7; Request; SIPCP: 0; DIPCP: 3\r\n4199(1427796281)#ipcm.flow-alloc (INFO)[flow_allocation_requested_remote]: Arrived request for flow allocation between Ada:1:: and Knuth:1::\r\n\r\n4199(1427796281)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 45_APP_ALLOC_FLOW_RESP; Sport: 4209; Dport: 1; Seqnum: 7; Response; SIPCP: 3; DIPCP: 0 \r\n4199(1427796281)#core (DBG): Added event of type 2_ALLOCATE_FLOW_RESPONSE and sequence number 7 to events queue\r\n4199(1427796281)#core (DBG): Waiting for message 1\r\n4199(1427796281)#ipcm (DBG): Got event of type 2_ALLOCATE_FLOW_RESPONSE and sequence number 7\r\n4199(1427796281)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 14_IPCM_ALLOC_FLOW_RESP; Sport: 1; Dport: 4203; Seqnum: 1427796258; Response; SIPCP: 3; DIPCP: 2\r\n4199(1427796281)#ipcm.flow-alloc (INFO)[allocate_flow_response_event_handler]: : Informing IPC process test-normal-1.IPCP:1:: about flow allocation from application Ada:1:: to application Knuth:1:: in DIF test-normal.DIF::: [success = 1, port-id = 5]\r\n\r\n4199(1427796358)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 42_APP_ALLOC_FLOW_REQ; Sport: 5266; Dport: 1; Seqnum: 1427796359; Request; SIPCP: 0; DIPCP: 0 \r\n4199(1427796358)#core (DBG): Added event of type 0_FLOW_ALLOCATION_REQUESTED and sequence number 1427796359 to events queue\r\n4199(1427796358)#core (DBG): Waiting for message 1\r\n4199(1427796358)#ipcm (DBG): Got event of type 0_FLOW_ALLOCATION_REQUESTED and sequence number 1427796359\r\n4199(1427796358)#concurrency (DBG): Lockable created successfully\r\n4199(1427796358)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 11_IPCM_ALLOC_FLOW_REQ; Sport: 1; Dport: 4209; Seqnum: 8; Request; SIPCP: 0; DIPCP: 3\r\n4199(1427796358)#ipcm.flow-alloc (INFO)[flow_allocation_requested_local]: IPC process Ada:1:: requested to allocate flow between rina.apps.echotime.client:1:: and rina.apps.echotime.server:1::\r\n\r\n4199(1427796359)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 13_IPCM_ALLOC_FLOW_REQ_RES; Sport: 4209; Dport: 1; Seqnum: 8; Response; SIPCP: 3; DIPCP: 0 \r\n4199(1427796359)#core (DBG): Added event of type 26_IPCM_ALLOCATE_FLOW_RESULT and sequence number 8 to events queue\r\n4199(1427796359)#core (DBG): Waiting for message 1\r\n4199(1427796359)#ipcm (DBG): Got event of type 26_IPCM_ALLOCATE_FLOW_RESULT and sequence number 8\r\n4199(1427796359)#ipcm.flow-alloc (INFO)[ipcm_allocate_flow_request_result_handler]: Informing IPC process Ada:1:: about flow allocation from application rina.apps.echotime.client:1:: to application rina.apps.echotime.server:1:: in DIF fantastic.DIF::: [success = 0, port-id = 6]\r\n\r\n4199(1427796359)#ipc-manager (DBG): ApplicationManager::flowAllocated called\r\n4199(1427796359)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 27_SOCK_CLOSED_NOT; Sport: 0; Dport: 1; Seqnum: 0; Notification; SIPCP: 0; DIPCP: 0 \r\n4199(1427796359)#core (DBG): NL socket at port 5266 is closed\r\n4199(1427796359)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 43_APP_ALLOC_FLOW_REQ_RES; Sport: 1; Dport: 5266; Seqnum: 1427796359; Response; SIPCP: 0; DIPCP: 0\r\n4199(1427796359)#ipcm.flow-alloc (INFO)[ipcm_allocate_flow_request_result_handler]: Applications rina.apps.echotime.client:1:: and rina.apps.echotime.server:1:: informed about flow allocation result\r\n\r\n4199(1427796359)#core (DBG): Added event of type 22_OS_PROCESS_FINALIZED and sequence number 0 to events queue\r\n4199(1427796359)#core (DBG): Waiting for message 1\r\n4199(1427796359)#ipcm (DBG): Got event of type 22_OS_PROCESS_FINALIZED and sequence number 0\r\n4199(1427796359)#ipcm.app (INFO)[os_process_finalized_handler]: Application rina.apps.echotime.client:1::terminated\r\n\r\n```\r\n\r\ntest-normal-1.IPCP-1.log\r\n```\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#netlink-manager (DBG): Netlink Manager constructor called, with netlink pid = 4203\r\n4203(1427796254)#netlink-manager (INFO): Netlink socket connected to local port 4203 \r\n4203(1427796254)#netlink-manager (DBG): Generic Netlink RINA family id: 22\r\n4203(1427796254)#core (DBG): Initialized Netlink Manager\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#concurrency (DBG): Condition variable created successfully\r\n4203(1427796254)#core (DBG): Initialized event queue\r\n4203(1427796254)#core (DBG): Started Netlink Message reader thread\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#ipc-process (INFO): Librina initialized\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#core (DBG): Waiting for message 4203\r\n4203(1427796254)#ipc-process (INFO): Pluggable component 'security-manager'/'default' [default] published\r\n4203(1427796254)#ipc-process (INFO): Pluggable component 'flow-allocator'/'default' [default] published\r\n4203(1427796254)#ipc-process (INFO): Pluggable component 'namespace-manager'/'default' [default] published\r\n4203(1427796254)#ipc-process (INFO): Pluggable component 'resource-allocator'/'default' [default] published\r\n4203(1427796254)#ipc-process (INFO): Pluggable component 'routing'/'link-state' [default] published\r\n4203(1427796254)#ipc-process (INFO): Plugin default loaded successfully\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#rib-daemon (INFO): EventListener subscribed to event 5_N_MINUS_1_FLOW_ALLOCATED\r\n4203(1427796254)#rib-daemon (INFO): EventListener subscribed to event 7_N_MINUS_1_FLOW_DEALLOCATED\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#rib (INFO): Object with name /daf/management/neighbors, class neighbor set, instance 1 added to the RIB\r\n4203(1427796254)#rib (INFO): Object with name /daf/management/enrollment, class enrollment information, instance 2 added to the RIB\r\n4203(1427796254)#rib (INFO): Object with name /daf/management/operationalStatus, class operationstatus, instance 3 added to the RIB\r\n4203(1427796254)#rib-daemon (INFO): Starting Management SDU reader ...\r\n4203(1427796254)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n4203(1427796254)#rib (INFO): Object with name /daf/management/naming/address, class address, instance 4 added to the RIB\r\n4203(1427796254)#rib-daemon (INFO): EventListener subscribed to event 7_N_MINUS_1_FLOW_DEALLOCATED\r\n4203(1427796254)#rib-daemon (INFO): EventListener subscribed to event 5_N_MINUS_1_FLOW_ALLOCATED\r\n4203(1427796254)#rib-daemon (INFO): EventListener subscribed to event 6_N_MINUS_1_FLOW_ALLOCATION_FAILED\r\n4203(1427796254)#rib-daemon (INFO): EventListener subscribed to event 8_NEIGHBOR_DECLARED_DEAD\r\n4203(1427796254)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/difregistrations, class DIF registration set, instance 5 added to the RIB\r\n4203(1427796254)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/nminusoneflows, class nminusone flow set, instance 6 added to the RIB\r\n4203(1427796254)#rib-daemon (INFO): EventListener subscribed to event 0_CONNECTIVITY_TO_NEIGHBOR_LOST\r\n4203(1427796254)#rib (INFO): Object with name /dif/management/flowallocator/directoryforwardingtableentries, class directoryforwardingtableentry set, instance 7 added to the RIB\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#rib (INFO): Object with name /daf/management/naming/whatevercastnames, class whatname set, instance 8 added to the RIB\r\n4203(1427796254)#rib (INFO): Object with name /dif/resourceallocation/flowallocator/flows, class flow set, instance 9 added to the RIB\r\n4203(1427796254)#rib (INFO): Object with name /dif/management/flowallocator/qoscubes, class qoscube set, instance 10 added to the RIB\r\n4203(1427796254)#rib (INFO): Object with name /dif/ipc/datatransfer/constants, class datatransfercons, instance 11 added to the RIB\r\n4203(1427796254)#ipcp-components (INFO): Policy-set default selected for component security-manager\r\n4203(1427796254)#ipcp-components (INFO): Policy-set default selected for component flow-allocator\r\n4203(1427796254)#ipcp-components (INFO): Policy-set default selected for component namespace-manager\r\n4203(1427796254)#ipcp-components (INFO): Policy-set default selected for component resource-allocator\r\n4203(1427796254)#ipcp-components (INFO): Policy-set link-state selected for component routing\r\n4203(1427796254)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 41_IPCP_INIT; Sport: 4203; Dport: 1; Seqnum: 0; Notification; SIPCP: 2; DIPCP: 0\r\n4203(1427796254)#ipc-process (INFO): Initialized IPC Process with name: test-normal-1.IPCP, instance 1, id 2 \r\n4203(1427796254)#ipcp-main (INFO): IPC Process name:     test-normal-1.IPCP\r\n4203(1427796254)#ipcp-main (INFO): IPC Process instance: 1\r\n4203(1427796254)#ipcp-main (INFO): IPC Process id:       2\r\n4203(1427796254)#ipcp-main (INFO): IPC Manager port:     1\r\n4203(1427796254)#ipcp-main (INFO): IPC Process initialized, executing event loop...\r\n4203(1427796254)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 1_ASSIGN_TO_DIF_REQ; Sport: 1; Dport: 4203; Seqnum: 2; Request; SIPCP: 0; DIPCP: 2 \r\n4203(1427796254)#core (DBG): Added event of type 12_ASSIGN_TO_DIF_REQUEST and sequence number 2 to events queue\r\n4203(1427796254)#core (DBG): Waiting for message 4203\r\n4203(1427796254)#event-loop (DBG): Got event of type 12_ASSIGN_TO_DIF_REQUEST and sequence number 2\r\n4203(1427796254)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 2_ASSIGN_TO_DIF_RESP; Sport: 0; Dport: 4203; Seqnum: 1427796255; Response; SIPCP: 2; DIPCP: 0 \r\n4203(1427796254)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 1_ASSIGN_TO_DIF_REQ; Sport: 4203; Dport: 0; Seqnum: 1427796255; Request; SIPCP: 2; DIPCP: 2\r\n4203(1427796254)#core (DBG): Added event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 1427796255 to events queue\r\n4203(1427796254)#core (DBG): Waiting for message 4203\r\n4203(1427796254)#event-loop (DBG): Got event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 1427796255\r\n4203(1427796254)#ipc-process (DBG): The kernel processed successfully the Assign to DIF request\r\n4203(1427796254)#rib-daemon (DBG): Configuration set: 16\r\n4203(1427796254)#resource-allocator (DBG): DIF configuration set 16\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#timer (DBG): Timer with ID 36721872 started\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#rib (INFO): Object with name /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup, class flowstateobject set, instance 12 added to the RIB\r\n4203(1427796254)#rib-daemon (INFO): EventListener subscribed to event 7_N_MINUS_1_FLOW_DEALLOCATED\r\n4203(1427796254)#rib-daemon (INFO): EventListener subscribed to event 5_N_MINUS_1_FLOW_ALLOCATED\r\n4203(1427796254)#rib-daemon (INFO): EventListener subscribed to event 9_NEIGHBOR_ADDED\r\n4203(1427796254)#rib-daemon (INFO): EventListener subscribed to event 0_CONNECTIVITY_TO_NEIGHBOR_LOST\r\n4203(1427796254)#namespace-manager (DBG): DIF configuration set: 16\r\n4203(1427796254)#security-manager (DBG): Set dif configuration: 16\r\n4203(1427796254)#rib (INFO): Object with name /dif/management/flowallocator/qoscubes/unreliablewithflowcontrol, class qoscube, instance 13 added to the RIB\r\n4203(1427796254)#rib (INFO): Object with name /dif/management/flowallocator/qoscubes/reliablewithflowcontrol, class qoscube, instance 14 added to the RIB\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#concurrency (DBG): Lockable created successfully\r\n4203(1427796254)#timer (DBG): Timer with ID 36722464 started\r\n4203(1427796254)#rib (INFO): Object with name /difmanagement/watchdog, class watchdog timer, instance 15 added to the RIB\r\n4203(1427796254)#enrollment-task (DBG): Started Neighbors enroller thread\r\n4203(1427796254)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 2_ASSIGN_TO_DIF_RESP; Sport: 4203; Dport: 1; Seqnum: 2; Response; SIPCP: 2; DIPCP: 0\r\n4203(1427796254)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 5_DIF_REG_NOT; Sport: 1; Dport: 4203; Seqnum: 0; Notification; SIPCP: 0; DIPCP: 2 \r\n4203(1427796254)#core (DBG): Added event of type 18_DIF_REGISTRATION_NOTIFICATION and sequence number 0 to events queue\r\n4203(1427796254)#core (DBG): Waiting for message 4203\r\n4203(1427796254)#event-loop (DBG): Got event of type 18_DIF_REGISTRATION_NOTIFICATION and sequence number 0\r\n4203(1427796254)#resource-allocator (INFO): IPC Process registered to N-1 DIF test-shim-hv.DIF\r\n4203(1427796254)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/difregistrations/test-shim-hv.DIF, class DIF registration, instance 16 added to the RIB\r\n4203(1427796254)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 18_IPCM_REG_APP_REQ; Sport: 1; Dport: 4203; Seqnum: 5; Request; SIPCP: 0; DIPCP: 2 \r\n4203(1427796254)#core (DBG): Added event of type 7_APPLICATION_REGISTRATION_REQUEST and sequence number 5 to events queue\r\n4203(1427796254)#core (DBG): Waiting for message 4203\r\n4203(1427796254)#event-loop (DBG): Got event of type 7_APPLICATION_REGISTRATION_REQUEST and sequence number 5\r\n4203(1427796254)#namespace-manager (INFO): Successfully registered application Ada-1-- with IPC Process id 2s\r\n4203(1427796254)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 19_ICPM_REG_APP_RESP; Sport: 4203; Dport: 1; Seqnum: 5; Response; SIPCP: 2; DIPCP: 0\r\n4203(1427796254)#namespace-manager (DBG): Added entry to DFT: Ada:1::\r\nIPC Process address: 16\r\nTimestamp: 0\r\n\r\n4203(1427796254)#rib (INFO): Object with name /dif/management/flowallocator/directoryforwardingtableentries/Ada-1--, class directoryforwardingtableentry, instance 17 added to the RIB\r\n4203(1427796255)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 44_APP_ALLOC_FLOW_REQ_ARR; Sport: 1; Dport: 4203; Seqnum: 6; Request; SIPCP: 0; DIPCP: 2 \r\n4203(1427796255)#core (DBG): Added event of type 0_FLOW_ALLOCATION_REQUESTED and sequence number 6 to events queue\r\n4203(1427796255)#core (DBG): Waiting for message 4203\r\n4203(1427796255)#event-loop (DBG): Got event of type 0_FLOW_ALLOCATION_REQUESTED and sequence number 6\r\n4203(1427796255)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 45_APP_ALLOC_FLOW_RESP; Sport: 4203; Dport: 1; Seqnum: 6; Response; SIPCP: 2; DIPCP: 0\r\n4203(1427796255)#resource-allocator (INFO): Accepted new flow from IPC Process test-normal-2.IPCP-1\r\n4203(1427796255)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/nminusoneflows/4, class nminusone flow, instance 18 added to the RIB\r\n4203(1427796255)#rib-daemon (INFO): Event 5_N_MINUS_1_FLOW_ALLOCATED has just happened. Notifying event listeners.\r\n4203(1427796255)#routing-ps-link-state (DBG): flow allocation waiting for enrollment\r\n4203(1427796255)#concurrency (DBG): Lockable created successfully\r\n4203(1427796255)#cdap-manager (DBG): Created a new CDAP session for port 4\r\n4203(1427796255)#rib-daemon (DBG): Received CDAP message through portId 4: \r\n0_M_CONNECT\r\nAbstract syntax: 115\r\nAuthentication mechanism: 0\r\nSource AP name: test-normal-2.IPCP\r\nSource AP instance: 1\r\nSource AE name: Management\r\nDestination AP name: test-normal-1.IPCP\r\nDestination AP instance: 1\r\nDestination AE name: Management\r\nInvoke id: 1\r\nVersion: 1\r\n\r\n4203(1427796255)#enrollment-task (DBG): Received M_CONNECT CDAP message from port-id 4\r\n4203(1427796255)#concurrency (DBG): Lockable created successfully\r\n4203(1427796255)#concurrency (DBG): Lockable created successfully\r\n4203(1427796255)#timer (DBG): Timer with ID 1275081568 started\r\n4203(1427796255)#concurrency (DBG): Lockable created successfully\r\n4203(1427796255)#enrollment-task (DBG): Created a new Enrollment state machine for remote IPC process: test-normal-2.IPCP-1-Management-\r\n4203(1427796255)#enrollment-task (DBG): Authenticating IPC process test-normal-2.IPCP-1 ...\r\n4203(1427796255)#enrollment-task (DBG): Authentication successful, deciding if new member can join the DIF...\r\n4203(1427796255)#security-manager-ps-default (DBG): Allowing IPC Process test-normal-2.IPCP to join the DIF\r\n4203(1427796255)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n4203(1427796255)#rib-daemon (DBG): Sent CDAP message of size 116 through port-id 4: \r\n1_M_CONNECT_R\r\nAbstract syntax: 115\r\nAuthentication mechanism: 0\r\nSource AP name: test-normal-1.IPCP\r\nSource AP instance: 1\r\nSource AE name: Management\r\nDestination AP name: test-normal-2.IPCP\r\nDestination AP instance: 1\r\nDestination AE name: Management\r\nInvoke id: 1\r\nResult: 0\r\nVersion: 1\r\n\r\n4203(1427796255)#enrollment-task (DBG): M_CONNECT_R sent to portID 4. Waiting for start enrollment request message\r\n4203(1427796255)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n4203(1427796255)#rib-daemon (DBG): Received CDAP message through portId 4: \r\n14_M_START\r\nInvoke id: 1\r\nObject class: enrollment information\r\nObject name: /daf/management/enrollment\r\nObject value: 0x7f154c003ce0\r\nScope: 0\r\n\r\n4203(1427796255)#rib (DBG): Remote operation 14 called on object /daf/management/enrollment\r\n4203(1427796255)#enrollment-task (DBG): Remote IPC Process address: 17\r\n4203(1427796255)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n4203(1427796255)#rib-daemon (DBG): Sent CDAP message of size 106 through port-id 4: \r\n15_M_START_r\r\nInvoke id: 1\r\nObject class: enrollment information\r\nObject name: /daf/management/enrollment\r\nResult: 0\r\n\r\n4203(1427796255)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n4203(1427796255)#rib-daemon (DBG): Sent CDAP message of size 176 through port-id 4: \r\n4_M_CREATE\r\nObject class: directoryforwardingtableentry set\r\nObject name: /dif/management/flowallocator/directoryforwardingtableentries\r\nObject value: 0x7f154c003430\r\nScope: 0\r\n\r\n4203(1427796255)#application (DBG): IPCManager.getRegisteredApplications called\r\n4203(1427796255)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n4203(1427796255)#rib-daemon (DBG): Sent CDAP message of size 144 through port-id 4: \r\n4_M_CREATE\r\nObject class: neighbor set\r\nObject name: /daf/management/neighbors\r\nObject value: 0x7f154c003430\r\nScope: 0\r\n\r\n4203(1427796255)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n4203(1427796255)#rib-daemon (DBG): Sent CDAP message of size 132 through port-id 4: \r\n16_M_STOP\r\nInvoke id: 1\r\nObject class: enrollment information\r\nObject name: /daf/management/enrollment\r\nObject value: 0x7f154c003430\r\nScope: 0\r\n\r\n4203(1427796255)#enrollment-task (DBG): Waiting for stop enrollment response message\r\n4203(1427796255)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n4203(1427796255)#rib-daemon (DBG): Received CDAP message through portId 4: \r\n4_M_CREATE\r\nObject class: directoryforwardingtableentry set\r\nObject name: /dif/management/flowallocator/directoryforwardingtableentries\r\nObject value: 0x7f154c003ce0\r\nScope: 0\r\n\r\n4203(1427796255)#rib (DBG): Remote operation 4 called on object /dif/management/flowallocator/directoryforwardingtableentries\r\n4203(1427796255)#namespace-manager (DBG): Added entry to DFT: Knuth:1::\r\nIPC Process address: 17\r\nTimestamp: 0\r\n\r\n4203(1427796255)#rib (INFO): Object with name /dif/management/flowallocator/directoryforwardingtableentries/Knuth-1--, class directoryforwardingtableentry, instance 19 added to the RIB\r\n4203(1427796255)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n4203(1427796255)#rib-daemon (DBG): Received CDAP message through portId 4: \r\n17_M_STOP_R\r\nInvoke id: 1\r\nResult: 0\r\n\r\n4203(1427796255)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n4203(1427796255)#rib-daemon (DBG): Sent CDAP message of size 106 through port-id 4: \r\n14_M_START\r\nObject class: operationstatus\r\nObject name: /daf/management/operationalStatus\r\nScope: 0\r\n\r\n4203(1427796255)#timer (DBG): Waiting for the timer 1275081568 to join\r\n4203(1427796256)#timer (DBG): Timer with ID 1275081568 ended\r\n4203(1427796256)#application (DBG): IPCManager.getRegisteredApplications called\r\n4203(1427796256)#rib (INFO): Object with name /daf/management/neighbors/test-normal-2.IPCP, class neighbor, instance 20 added to the RIB\r\n4203(1427796256)#rib-daemon (INFO): Event 9_NEIGHBOR_ADDED has just happened. Notifying event listeners.\r\n4203(1427796256)#routing-ps-link-state (INFO): There was an allocation flow event waiting for enrollment, launching it\r\n4203(1427796256)#rib (INFO): Object with name /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup/16-17, class flowstateobject, instance 21 added to the RIB\r\n4203(1427796256)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n4203(1427796256)#rib-daemon (DBG): Sent CDAP message of size 160 through port-id 4: \r\n12_M_WRITE\r\nObject class: flowstateobject set\r\nObject name: /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup\r\nObject value: 0x7f154c003430\r\nScope: 0\r\n\r\n4203(1427796256)#enrollment-task (INFO): Remote IPC Process enrolled!\r\n4203(1427796256)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n4203(1427796256)#rib-daemon (DBG): Received CDAP message through portId 4: \r\n12_M_WRITE\r\nObject class: flowstateobject set\r\nObject name: /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup\r\nObject value: 0x7f154c003ce0\r\nScope: 0\r\n\r\n4203(1427796256)#rib (DBG): Remote operation 12 called on object /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup\r\n4203(1427796256)#routing-ps-link-state (DBG): Update objects from DB launched\r\n4203(1427796256)#routing-ps-link-state (DBG): New object added\r\n4203(1427796256)#rib (INFO): Object with name /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup/17-16, class flowstateobject, instance 22 added to the RIB\r\n4203(1427796256)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n4203(1427796256)#routing-ps-link-state (DBG): Propagation: Check modified object /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup/16-17 with age 0 and status 1\r\n4203(1427796256)#routing-ps-link-state (DBG): Propagation: Check modified object /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup/17-16 with age 0 and status 1\r\n4203(1427796256)#routing-ps-link-state (DBG): Processing flow state object: /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup/16-17\r\n4203(1427796256)#routing-ps-link-state (DBG): Processing flow state object: /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup/17-16\r\n4203(1427796256)#routing-ps-link-state (DBG): Added entry to routing table: destination 17, next-hop 17\r\n4203(1427796256)#resource-allocator-ps-default (DBG): Got 1 entries in the routing table\r\n4203(1427796256)#resource-allocator-ps-default (DBG): Processing entry for destination 17\r\n4203(1427796256)#resource-allocator-ps-default (DBG): Next hop address 17\r\n4203(1427796256)#resource-allocator-ps-default (DBG): N-1 port-id: 4\r\n4203(1427796256)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 24_MODIFY_FT_REQ; Sport: 4203; Dport: 0; Seqnum: 1427796256; Request; SIPCP: 2; DIPCP: 2\r\n4203(1427796281)#rib-daemon (DBG): Received A-Data CDAP message from address 17 : \r\n4_M_CREATE\r\nInvoke id: 1\r\nObject class: flow\r\nObject name: /dif/resourceallocation/flowallocator/flows/17-5\r\nObject value: 0x7f154c003ce0\r\nScope: 0\r\n\r\n4203(1427796281)#rib (DBG): Remote operation 4 called on object /dif/resourceallocation/flowallocator/flows/17-5\r\n4203(1427796281)#rib (DBG): Looking for parent object, with name /dif/resourceallocation/flowallocator/flows\r\n4203(1427796281)#syscalls (DBG): Gonna call syscall SYS_allocatePortId (321)\r\n4203(1427796281)#flow-allocator (DBG): The destination application process is reachable through me. Assigning the local port-id 5 to the flow\r\n4203(1427796281)#concurrency (DBG): Lockable created successfully\r\n4203(1427796281)#concurrency (DBG): Lockable created successfully\r\n4203(1427796281)#timer (DBG): Timer with ID 1275096128 started\r\n4203(1427796281)#concurrency (DBG): Lockable created successfully\r\n4203(1427796281)#concurrency (DBG): Lockable created successfully\r\n4203(1427796281)#concurrency (DBG): Lockable created successfully\r\n4203(1427796281)#timer (DBG): Timer with ID 1275096096 started\r\n4203(1427796281)#flow-allocator (DBG): Created flow allocator instance to manage the flow identified by portId 5 \r\n4203(1427796281)#flow-allocator (DBG): Create flow request received: * State: 1\r\n* Is this IPC Process the requestor of the flow? 0\r\n* Max create flow retries: 1\r\n* Hop count: 3\r\n* Source AP Naming Info: Knuth:1::\r\n* Source address: 17\r\n* Source port id: 5\r\n* Destination AP Naming Info: Ada:1::dres: \r\n* Destination port id: \r\n* Connection ids of the connection supporting this flow: +\r\nSrc CEP-id 0; Dest CEP-id 0; Qos-id 1\r\n* Index of the current active connection for this flow: 0\r\n\r\n4203(1427796281)#flow-allocator (DBG): Target application IPC Process id is 3\r\n4203(1427796281)#security-manager-ps-default (DBG): Accepting flow from remote application Knuth-1--\r\n4203(1427796281)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 31_CREATE_EFCP_CONN_ARR; Sport: 4203; Dport: 0; Seqnum: 1427796257; Request; SIPCP: 2; DIPCP: 2\r\n4203(1427796281)#flow-allocator (DBG): Requested the creation of a connection to the kernel to support flow with port-id 5\r\n4203(1427796281)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n4203(1427796281)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 32_CREATE_EFCP_CONN_RES; Sport: 0; Dport: 4203; Seqnum: 1427796257; Response; SIPCP: 2; DIPCP: 0 \r\n4203(1427796281)#core (DBG): Added event of type 32_CREATE_EFCP_CONN_RESULT and sequence number 1427796257 to events queue\r\n4203(1427796281)#core (DBG): Waiting for message 4203\r\n4203(1427796281)#event-loop (DBG): Got event of type 32_CREATE_EFCP_CONN_RESULT and sequence number 1427796257\r\n4203(1427796281)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 12_IPCM_ALLOC_FLOW_RESP_ARR; Sport: 4203; Dport: 1; Seqnum: 1427796258; Request; SIPCP: 2; DIPCP: 0\r\n4203(1427796281)#flow-allocator (DBG): Informed IPC Manager about incoming flow allocation request, got handle: 1427796258d\r\n4203(1427796281)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 14_IPCM_ALLOC_FLOW_RESP; Sport: 1; Dport: 4203; Seqnum: 1427796258; Response; SIPCP: 3; DIPCP: 2 \r\n4203(1427796281)#core (DBG): Added event of type 2_ALLOCATE_FLOW_RESPONSE and sequence number 1427796258 to events queue\r\n4203(1427796281)#core (DBG): Waiting for message 4203\r\n4203(1427796281)#event-loop (DBG): Got event of type 2_ALLOCATE_FLOW_RESPONSE and sequence number 1427796258\r\n4203(1427796281)#flow-allocator (DBG): Local application invoked allocate response with seq num 1427796258d and result 0, \r\n4203(1427796281)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n4203(1427796281)#rib-daemon (DBG): Sent A-Data CDAP message to address 17: \r\n5_M_CREATE_R\r\nInvoke id: 1\r\nObject class: flow\r\nObject name: /dif/resourceallocation/flowallocator/flows/17-5\r\nObject value: 0x2304070\r\nResult: 0\r\n\r\n4203(1427796281)#rib (INFO): Object with name /dif/resourceallocation/flowallocator/flows/17-5, class flow, instance 23 added to the RIB\r\n4203(1427796374)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n4203(1427796374)#rib-daemon (DBG): Sent CDAP message of size 95 through port-id 4: \r\n8_M_READ\r\nInvoke id: 1\r\nObject class: watchdog timer\r\nObject name: /difmanagement/watchdog\r\nScope: 0\r\n\r\n4203(1427796374)#rib-daemon (DBG): Received CDAP message through portId 4: \r\n9_M_READ_R\r\nInvoke id: 1\r\nObject class: watchdog timer\r\nObject name: /difmanagement/watchdog\r\nObject value: 0x7f154c004010\r\nResult: 0\r\n\r\n4203(1427796374)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n```\r\n\r\ndmesg\r\n```\r\n[    0.633040] FDC 0 is a S82078B\r\n[    0.934695] e1000 0000:00:03.0 eth0: (PCI:33MHz:32-bit) 00:0a:0a:0a:0a:99\r\n[    0.934702] e1000 0000:00:03.0 eth0: Intel(R) PRO/1000 Network Connection\r\n[    0.935272] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 10\r\n[    0.936877] ata_piix 0000:00:01.1: version 2.13\r\n[    0.939207] scsi0 : ata_piix\r\n[    0.939487] scsi1 : ata_piix\r\n[    0.939554] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc060 irq 14\r\n[    0.939556] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc068 irq 15\r\n[    1.092820] ata1.01: NODEV after polling detection\r\n[    1.093219] ata1.00: ATA-7: QEMU HARDDISK, 2.0.50, max UDMA/100\r\n[    1.093222] ata1.00: 20971520 sectors, multi 16: LBA48 \r\n[    1.093841] ata1.00: configured for MWDMA2\r\n[    1.094055] scsi 0:0:0:0: Direct-Access     ATA      QEMU HARDDISK    2.0. PQ: 0 ANSI: 5\r\n[    1.096698] ata2.01: NODEV after polling detection\r\n[    1.097093] ata2.00: ATAPI: QEMU DVD-ROM, 2.0.50, max UDMA/100\r\n[    1.097711] ata2.00: configured for MWDMA2\r\n[    1.098772] scsi 1:0:0:0: CD-ROM            QEMU     QEMU DVD-ROM     2.0. PQ: 0 ANSI: 5\r\n[    1.112301] sd 0:0:0:0: [sda] 20971520 512-byte logical blocks: (10.7 GB/10.0 GiB)\r\n[    1.112534] sd 0:0:0:0: [sda] Write Protect is off\r\n[    1.112538] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00\r\n[    1.112620] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA\r\n[    1.114760]  sda: sda1 sda2 < sda5 >\r\n[    1.115575] sd 0:0:0:0: [sda] Attached SCSI disk\r\n[    1.116929] sr0: scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray\r\n[    1.116932] cdrom: Uniform CD-ROM driver Revision: 3.20\r\n[    1.117724] sr 1:0:0:0: Attached scsi CD-ROM sr0\r\n[    1.121752] sd 0:0:0:0: Attached scsi generic sg0 type 0\r\n[    1.121811] sr 1:0:0:0: Attached scsi generic sg1 type 5\r\n[    1.302239] device-mapper: uevent: version 1.0.3\r\n[    1.302504] device-mapper: ioctl: 4.27.0-ioctl (2013-10-30) initialised: dm-devel@redhat.com\r\n[    1.306461] random: lvm urandom read with 32 bits of entropy available\r\n[    1.948269] tsc: Refined TSC clocksource calibration: 2400.112 MHz\r\n[    2.158003] PM: Starting manual resume from disk\r\n[    2.158007] PM: Hibernation image partition 254:1 present\r\n[    2.158008] PM: Looking for hibernation image.\r\n[    2.158617] PM: Image not found (code -22)\r\n[    2.158620] PM: Hibernation image not present or could not be loaded.\r\n[    2.200493] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)\r\n[    2.948619] Switched to clocksource tsc\r\n[    3.408204] udevd[340]: starting version 175\r\n[    3.562227] random: nonblocking pool is initialized\r\n[    3.961074] parport_pc 00:04: reported by Plug and Play ACPI\r\n[    3.961285] parport0: PC-style at 0x378, irq 7 [PCSPP,TRISTATE]\r\n[    3.996506] input: PC Speaker as /devices/platform/pcspkr/input/input2\r\n[    4.056295] microcode: CPU0 sig=0x663, pf=0x1, revision=0x1\r\n[    4.069999] microcode: CPU1 sig=0x663, pf=0x1, revision=0x1\r\n[    4.070231] microcode: Microcode Update Driver: v2.00 <tigran@aivazian.fsnet.co.uk>, Peter Oruba\r\n[    4.111061] virtio-pci 0000:00:04.0: irq 40 for MSI/MSI-X\r\n[    4.111096] virtio-pci 0000:00:04.0: irq 41 for MSI/MSI-X\r\n[    4.111635] vmpi_test_init completed\r\n[    4.111639] vmpi_provider_register: Provider 1:0 registered\r\n[    4.111641] vmpi_init completed\r\n[    4.111902] virtio_mpi_probe completed\r\n[    4.202473] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0\r\n[    4.226902] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input3\r\n[    4.226995] ACPI: Power Button [PWRF]\r\n[    4.298020] Error: Driver 'pcspkr' is already registered, aborting...\r\n[    5.070045] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input4\r\n[    5.142430] EXT4-fs (dm-0): re-mounted. Opts: (null)\r\n[    5.319725] EXT4-fs (dm-0): re-mounted. Opts: errors=remount-ro\r\n[    5.411699] loop: module loaded\r\n[    6.191586] Clocksource tsc unstable (delta = -243423139 ns)\r\n[    6.191736] Switched to clocksource hpet\r\n[    6.446082] Adding 471036k swap on /dev/mapper/vm1-swap_1.  Priority:-1 extents:1 across:471036k \r\n[    8.111224] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready\r\n[    8.139321] RPC: Registered named UNIX socket transport module.\r\n[    8.139325] RPC: Registered udp transport module.\r\n[    8.139327] RPC: Registered tcp transport module.\r\n[    8.139328] RPC: Registered tcp NFSv4.1 backchannel transport module.\r\n[    8.155906] FS-Cache: Loaded\r\n[    8.182568] FS-Cache: Netfs 'nfs' registered for caching\r\n[    8.252873] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).\r\n[   10.450767] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX\r\n[   10.451382] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready\r\n[   33.118494] rina-personality(INFO): Default personality set to 'default'\r\n[   33.143407] rina-ipcp-factories(INFO): Factory 'shim-hv' registered successfully\r\n[   33.143411] rina-shim-hv(INFO): Shim for Hypervisors support loaded\r\n[   33.152138] rina-ipcp-factories(INFO): Factory 'normal-ipc' registered successfully\r\n[   33.167606] rina-ps-factory(INFO): policy-set 'default' published successfully\r\n[   33.167609] rina-rina-default-plugin(INFO): RMT default policy set loaded successfully\r\n[   33.167610] rina-ps-factory(INFO): policy-set 'default' published successfully\r\n[   33.167612] rina-rina-default-plugin(INFO): DTP default policy set loaded successfully\r\n[   33.167613] rina-ps-factory(INFO): policy-set 'default' published successfully\r\n[   33.167615] rina-rina-default-plugin(INFO): DTCP default policy set loaded successfully\r\n[   44.158326] rina-kipcm(INFO): IPC Manager started. It is listening at NL port-id 1\r\n[   44.246099] rina-rnl-utils(ERR): Missing code in net/rina/rnl-utils.c:1265\r\n[   44.246573] rina-rnl-utils(ERR): Missing code in net/rina/rnl-utils.c:1323\r\n[   44.273082] rina-rnl-utils(ERR): Missing code in net/rina/rnl-utils.c:1265\r\n[   44.273488] rina-rnl-utils(ERR): Missing code in net/rina/rnl-utils.c:1323\r\n[  168.074546] rina-normal-ipc(ERR): Could not find flow 3 to deallocate\r\n[  168.074991] rina-kipcm(ERR): Failed deallocate flow request for port id: 3\r\n[  200.608475] rina-rnl(WARN): IPC Manager process has been destroyed\r\n[  205.059048] rina-kipcm(INFO): IPC Manager started. It is listening at NL port-id 1\r\n[  205.074328] rina-rnl-utils(ERR): Missing code in net/rina/rnl-utils.c:1265\r\n[  205.074668] rina-rnl-utils(ERR): Missing code in net/rina/rnl-utils.c:1323\r\n[  205.088531] rina-rnl-utils(ERR): Missing code in net/rina/rnl-utils.c:1265\r\n[  205.088982] rina-rnl-utils(ERR): Missing code in net/rina/rnl-utils.c:1323\r\n[  310.417069] rina-normal-ipc(ERR): Could not find flow 6 to deallocate\r\n[  310.417515] rina-kipcm(ERR): Failed deallocate flow request for port id: 6\r\n```\r\n"}}