{"action":"created","issue":{"url":"https://api.github.com/repos/IRATI/stack/issues/523","labels_url":"https://api.github.com/repos/IRATI/stack/issues/523/labels{/name}","comments_url":"https://api.github.com/repos/IRATI/stack/issues/523/comments","events_url":"https://api.github.com/repos/IRATI/stack/issues/523/events","html_url":"https://github.com/IRATI/stack/issues/523","id":65437017,"number":523,"title":"Normal over normal over shim HV: Enrollment 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":"open","locked":false,"assignee":null,"milestone":null,"comments":3,"created_at":"2015-03-31T12:13:48Z","updated_at":"2015-04-01T08:41:59Z","closed_at":null,"body":"vm1\r\n---\r\n\r\nAda-1.log\r\n```\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#netlink-manager (DBG): Netlink Manager constructor called, with netlink pid = 2558\r\n2558(1427803613)#netlink-manager (INFO): Netlink socket connected to local port 2558 \r\n2558(1427803613)#netlink-manager (DBG): Generic Netlink RINA family id: 22\r\n2558(1427803613)#core (DBG): Initialized Netlink Manager\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#concurrency (DBG): Condition variable created successfully\r\n2558(1427803613)#core (DBG): Initialized event queue\r\n2558(1427803613)#core (DBG): Started Netlink Message reader thread\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#ipc-process (INFO): Librina initialized\r\n2558(1427803613)#core (DBG): Waiting for message 2558\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#ipc-process (INFO): Pluggable component 'security-manager'/'default' [default] published\r\n2558(1427803613)#ipc-process (INFO): Pluggable component 'flow-allocator'/'default' [default] published\r\n2558(1427803613)#ipc-process (INFO): Pluggable component 'namespace-manager'/'default' [default] published\r\n2558(1427803613)#ipc-process (INFO): Pluggable component 'resource-allocator'/'default' [default] published\r\n2558(1427803613)#ipc-process (INFO): Pluggable component 'routing'/'link-state' [default] published\r\n2558(1427803613)#ipc-process (INFO): Plugin default loaded successfully\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#rib-daemon (INFO): EventListener subscribed to event 5_N_MINUS_1_FLOW_ALLOCATED\r\n2558(1427803613)#rib-daemon (INFO): EventListener subscribed to event 7_N_MINUS_1_FLOW_DEALLOCATED\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#rib (INFO): Object with name /daf/management/neighbors, class neighbor set, instance 1 added to the RIB\r\n2558(1427803613)#rib (INFO): Object with name /daf/management/enrollment, class enrollment information, instance 2 added to the RIB\r\n2558(1427803613)#rib (INFO): Object with name /daf/management/operationalStatus, class operationstatus, instance 3 added to the RIB\r\n2558(1427803613)#rib (INFO): Object with name /daf/management/naming/address, class address, instance 4 added to the RIB\r\n2558(1427803613)#rib-daemon (INFO): EventListener subscribed to event 7_N_MINUS_1_FLOW_DEALLOCATED\r\n2558(1427803613)#rib-daemon (INFO): EventListener subscribed to event 5_N_MINUS_1_FLOW_ALLOCATED\r\n2558(1427803613)#rib-daemon (INFO): EventListener subscribed to event 6_N_MINUS_1_FLOW_ALLOCATION_FAILED\r\n2558(1427803613)#rib-daemon (INFO): EventListener subscribed to event 8_NEIGHBOR_DECLARED_DEAD\r\n2558(1427803613)#rib-daemon (INFO): Starting Management SDU reader ...\r\n2558(1427803613)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n2558(1427803613)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/difregistrations, class DIF registration set, instance 5 added to the RIB\r\n2558(1427803613)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/nminusoneflows, class nminusone flow set, instance 6 added to the RIB\r\n2558(1427803613)#rib-daemon (INFO): EventListener subscribed to event 0_CONNECTIVITY_TO_NEIGHBOR_LOST\r\n2558(1427803613)#rib (INFO): Object with name /dif/management/flowallocator/directoryforwardingtableentries, class directoryforwardingtableentry set, instance 7 added to the RIB\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#rib (INFO): Object with name /daf/management/naming/whatevercastnames, class whatname set, instance 8 added to the RIB\r\n2558(1427803613)#rib (INFO): Object with name /dif/resourceallocation/flowallocator/flows, class flow set, instance 9 added to the RIB\r\n2558(1427803613)#rib (INFO): Object with name /dif/management/flowallocator/qoscubes, class qoscube set, instance 10 added to the RIB\r\n2558(1427803613)#rib (INFO): Object with name /dif/ipc/datatransfer/constants, class datatransfercons, instance 11 added to the RIB\r\n2558(1427803613)#ipcp-components (INFO): Policy-set default selected for component security-manager\r\n2558(1427803613)#ipcp-components (INFO): Policy-set default selected for component flow-allocator\r\n2558(1427803613)#ipcp-components (INFO): Policy-set default selected for component namespace-manager\r\n2558(1427803613)#ipcp-components (INFO): Policy-set default selected for component resource-allocator\r\n2558(1427803613)#ipcp-components (INFO): Policy-set link-state selected for component routing\r\n2558(1427803613)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 41_IPCP_INIT; Sport: 2558; Dport: 1; Seqnum: 0; Notification; SIPCP: 3; DIPCP: 0\r\n2558(1427803613)#ipc-process (INFO): Initialized IPC Process with name: Ada, instance 1, id 3 \r\n2558(1427803613)#ipcp-main (INFO): IPC Process name:     Ada\r\n2558(1427803613)#ipcp-main (INFO): IPC Process instance: 1\r\n2558(1427803613)#ipcp-main (INFO): IPC Process id:       3\r\n2558(1427803613)#ipcp-main (INFO): IPC Manager port:     1\r\n2558(1427803613)#ipcp-main (INFO): IPC Process initialized, executing event loop...\r\n2558(1427803613)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 1_ASSIGN_TO_DIF_REQ; Sport: 1; Dport: 2558; Seqnum: 4; Request; SIPCP: 0; DIPCP: 3 \r\n2558(1427803613)#core (DBG): Added event of type 12_ASSIGN_TO_DIF_REQUEST and sequence number 4 to events queue\r\n2558(1427803613)#core (DBG): Waiting for message 2558\r\n2558(1427803613)#event-loop (DBG): Got event of type 12_ASSIGN_TO_DIF_REQUEST and sequence number 4\r\n2558(1427803613)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 2_ASSIGN_TO_DIF_RESP; Sport: 0; Dport: 2558; Seqnum: 1427803614; Response; SIPCP: 3; DIPCP: 0 \r\n2558(1427803613)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 1_ASSIGN_TO_DIF_REQ; Sport: 2558; Dport: 0; Seqnum: 1427803614; Request; SIPCP: 3; DIPCP: 3\r\n2558(1427803613)#core (DBG): Added event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 1427803614 to events queue\r\n2558(1427803613)#core (DBG): Waiting for message 2558\r\n2558(1427803613)#event-loop (DBG): Got event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 1427803614\r\n2558(1427803613)#ipc-process (DBG): The kernel processed successfully the Assign to DIF request\r\n2558(1427803613)#rib-daemon (DBG): Configuration set: 5\r\n2558(1427803613)#resource-allocator (DBG): DIF configuration set 5\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#timer (DBG): Timer with ID 18826256 started\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#rib (INFO): Object with name /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup, class flowstateobject set, instance 12 added to the RIB\r\n2558(1427803613)#rib-daemon (INFO): EventListener subscribed to event 7_N_MINUS_1_FLOW_DEALLOCATED\r\n2558(1427803613)#rib-daemon (INFO): EventListener subscribed to event 5_N_MINUS_1_FLOW_ALLOCATED\r\n2558(1427803613)#rib-daemon (INFO): EventListener subscribed to event 9_NEIGHBOR_ADDED\r\n2558(1427803613)#rib-daemon (INFO): EventListener subscribed to event 0_CONNECTIVITY_TO_NEIGHBOR_LOST\r\n2558(1427803613)#namespace-manager (DBG): DIF configuration set: 5\r\n2558(1427803613)#security-manager (DBG): Set dif configuration: 5\r\n2558(1427803613)#rib (INFO): Object with name /dif/management/flowallocator/qoscubes/unreliablewithflowcontrol, class qoscube, instance 13 added to the RIB\r\n2558(1427803613)#rib (INFO): Object with name /dif/management/flowallocator/qoscubes/reliablewithflowcontrol, class qoscube, instance 14 added to the RIB\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#concurrency (DBG): Lockable created successfully\r\n2558(1427803613)#timer (DBG): Timer with ID 18830512 started\r\n2558(1427803613)#rib (INFO): Object with name /difmanagement/watchdog, class watchdog timer, instance 15 added to the RIB\r\n2558(1427803613)#enrollment-task (DBG): Started Neighbors enroller thread\r\n2558(1427803613)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 2_ASSIGN_TO_DIF_RESP; Sport: 2558; Dport: 1; Seqnum: 4; Response; SIPCP: 3; DIPCP: 0\r\n2558(1427803613)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 5_DIF_REG_NOT; Sport: 1; Dport: 2558; Seqnum: 0; Notification; SIPCP: 0; DIPCP: 3 \r\n2558(1427803613)#core (DBG): Added event of type 18_DIF_REGISTRATION_NOTIFICATION and sequence number 0 to events queue\r\n2558(1427803613)#core (DBG): Waiting for message 2558\r\n2558(1427803613)#event-loop (DBG): Got event of type 18_DIF_REGISTRATION_NOTIFICATION and sequence number 0\r\n2558(1427803613)#resource-allocator (INFO): IPC Process registered to N-1 DIF test-normal.DIF\r\n2558(1427803613)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/difregistrations/test-normal.DIF, class DIF registration, instance 16 added to the RIB\r\n2558(1427803865)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 22_QUERY_RIB_REQ; Sport: 1; Dport: 2558; Seqnum: 8; Request; SIPCP: 0; DIPCP: 3 \r\n2558(1427803865)#core (DBG): Added event of type 19_QUERY_RIB and sequence number 8 to events queue\r\n2558(1427803865)#core (DBG): Waiting for message 2558\r\n2558(1427803865)#event-loop (DBG): Got event of type 19_QUERY_RIB and sequence number 8\r\n2558(1427803865)#rib-daemon (DBG): Object name: /daf/management/enrollment\r\n2558(1427803865)#rib-daemon (DBG): Object name: /daf/management/naming/address\r\n2558(1427803865)#rib-daemon (DBG): Object name: /daf/management/naming/whatevercastnames\r\n2558(1427803865)#rib-daemon (DBG): Object name: /daf/management/neighbors\r\n2558(1427803865)#rib-daemon (DBG): Object name: /daf/management/operationalStatus\r\n2558(1427803865)#rib-daemon (DBG): Object name: /dif/ipc/datatransfer/constants\r\n2558(1427803865)#rib-daemon (DBG): Object name: /dif/management/flowallocator/directoryforwardingtableentries\r\n2558(1427803865)#rib-daemon (DBG): Object name: /dif/management/flowallocator/qoscubes\r\n2558(1427803865)#rib-daemon (DBG): Object name: /dif/management/flowallocator/qoscubes/reliablewithflowcontrol\r\n2558(1427803865)#rib-daemon (DBG): Object name: /dif/management/flowallocator/qoscubes/unreliablewithflowcontrol\r\n2558(1427803865)#rib-daemon (DBG): Object name: /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup\r\n2558(1427803865)#rib-daemon (DBG): Object name: /dif/resourceallocation/flowallocator/flows\r\n2558(1427803865)#rib-daemon (DBG): Object name: /dif/resourceallocation/nminusoneflowmanager/difregistrations\r\n2558(1427803865)#rib-daemon (DBG): Object name: /dif/resourceallocation/nminusoneflowmanager/difregistrations/test-normal.DIF\r\n2558(1427803865)#rib-daemon (DBG): Object name: /dif/resourceallocation/nminusoneflowmanager/nminusoneflows\r\n2558(1427803865)#rib-daemon (DBG): Object name: /difmanagement/watchdog\r\n2558(1427803865)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 23_QUERY_RIB_RESP; Sport: 2558; Dport: 1; Seqnum: 8; Response; SIPCP: 3; DIPCP: 0\r\n2558(1427803865)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 25_DUMP_FT_REQ; Sport: 2558; Dport: 0; Seqnum: 1427803615; Request; SIPCP: 3; DIPCP: 3\r\n2558(1427803865)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 26_DUMP_FT_RESP; Sport: 0; Dport: 2558; Seqnum: 1427803615; Response; SIPCP: 3; DIPCP: 0 \r\n2558(1427803865)#core (DBG): Added event of type 34_DUMP_FT_RESPONSE and sequence number 1427803615 to events queue\r\n2558(1427803865)#core (DBG): Waiting for message 2558\r\n2558(1427803865)#event-loop (DBG): Got event of type 34_DUMP_FT_RESPONSE and sequence number 1427803615\r\n2558(1427803865)#ipc-process (INFO): Contents of the PDU Forwarding Table: \r\n\r\n2558(1427803920)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 7_ENROLL_TO_DIF_REQ; Sport: 1; Dport: 2558; Seqnum: 9; Request; SIPCP: 0; DIPCP: 3 \r\n2558(1427803920)#core (DBG): Added event of type 16_ENROLL_TO_DIF_REQUEST and sequence number 9 to events queue\r\n2558(1427803920)#core (DBG): Waiting for message 2558\r\n2558(1427803920)#event-loop (DBG): Got event of type 16_ENROLL_TO_DIF_REQUEST and sequence number 9\r\n2558(1427803920)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 42_APP_ALLOC_FLOW_REQ; Sport: 2558; Dport: 1; Seqnum: 1427803616; Request; SIPCP: 3; DIPCP: 0\r\n2558(1427803920)#resource-allocator (INFO): Requested the allocation of N-1 flow to application Knuth-1 through DIF test-normal.DIF\r\n2558(1427803920)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 43_APP_ALLOC_FLOW_REQ_RES; Sport: 1; Dport: 2558; Seqnum: 1427803616; Response; SIPCP: 0; DIPCP: 3 \r\n2558(1427803920)#core (DBG): Added event of type 1_ALLOCATE_FLOW_REQUEST_RESULT and sequence number 1427803616 to events queue\r\n2558(1427803920)#core (DBG): Waiting for message 2558\r\n2558(1427803920)#event-loop (DBG): Got event of type 1_ALLOCATE_FLOW_REQUEST_RESULT and sequence number 1427803616\r\n2558(1427803920)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/nminusoneflows/2, class nminusone flow, instance 17 added to the RIB\r\n2558(1427803920)#rib-daemon (INFO): Event 5_N_MINUS_1_FLOW_ALLOCATED has just happened. Notifying event listeners.\r\n2558(1427803920)#concurrency (DBG): Lockable created successfully\r\n2558(1427803920)#concurrency (DBG): Lockable created successfully\r\n2558(1427803920)#timer (DBG): Timer with ID 18797216 started\r\n2558(1427803920)#concurrency (DBG): Lockable created successfully\r\n2558(1427803920)#enrollment-task (DBG): Created a new Enrollment state machine for remote IPC process: Knuth-1--\r\n2558(1427803920)#concurrency (DBG): Lockable created successfully\r\n2558(1427803920)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n2558(1427803920)#rib-daemon (DBG): Sent CDAP message of size 88 through port-id 2: \r\n0_M_CONNECT\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\nVersion: 1\r\n\r\n2558(1427803920)#cdap-manager (DBG): Waiting timeout 180000 to receive a connection response\r\n2558(1427803920)#concurrency (DBG): Lockable created successfully\r\n2558(1427803920)#concurrency (DBG): Lockable created successfully\r\n2558(1427803920)#timer (DBG): Timer with ID 18826912 started\r\n2558(1427803920)#routing-ps-link-state (DBG): flow allocation waiting for enrollment\r\n2558(1427803920)#cdap-manager (DBG): Connection response received\r\n2558(1427803920)#timer (DBG): Waiting for the timer 18826912 to join\r\n2558(1427803920)#timer (DBG): Timer with ID 18826912 ended\r\n2558(1427803920)#rib-daemon (DBG): Received CDAP message through portId 2: \r\n1_M_CONNECT_R\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\nResult: 0\r\nVersion: 1\r\n\r\n2558(1427803920)#enrollment-task (DBG): Received M_CONNECT_R cdapMessage from portId 2\r\n2558(1427803920)#application (DBG): IPCManager.getRegisteredApplications called\r\n2558(1427803920)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n2558(1427803920)#rib-daemon (DBG): Sent CDAP message of size 131 through port-id 2: \r\n14_M_START\r\nInvoke id: 1\r\nObject class: enrollment information\r\nObject name: /daf/management/enrollment\r\nObject value: 0x7f2364003330\r\nScope: 0\r\n\r\n2558(1427803920)#enrollment-task (DBG): Sent a M_START Message to portid: 2\r\n2558(1427803920)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n2558(1427803930)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 48_APP_FLOW_DEALLOC_NOT; Sport: 1; Dport: 2558; Seqnum: 0; Notification; SIPCP: 0; DIPCP: 3 \r\n2558(1427803930)#core (DBG): Added event of type 6_FLOW_DEALLOCATED and sequence number 0 to events queue\r\n2558(1427803930)#core (DBG): Waiting for message 2558\r\n2558(1427803930)#event-loop (DBG): Got event of type 6_FLOW_DEALLOCATED and sequence number 0\r\n2558(1427803930)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/nminusoneflows/2, class nminusone flow, instance 17 removed from the RIB\r\n2558(1427803930)#rib-daemon (INFO): Event 7_N_MINUS_1_FLOW_DEALLOCATED has just happened. Notifying event listeners.\r\n2558(1427803930)#enrollment-task (DBG): Removing enrollment state machine associated to Knuth 2\r\n2558(1427803930)#enrollment-task (INFO): The flow supporting the CDAP session identified by 2 has been deallocated.\r\n2558(1427803930)#enrollment-task (INFO): Ignoring neighbor Knuth because we don't have an N-1 DIF in common\r\n2558(1427803930)#timer (DBG): Waiting for the timer 18797216 to join\r\n2558(1427803930)#timer (DBG): Timer with ID 18797216 ended\r\n2558(1427803930)#enrollment-task (ERR): An error happened during enrollment of remote IPC Process Knuth-1-- because of Timeout waiting for start response\r\n2558(1427803930)#enrollment-task (DBG): Removing enrollment state machine associated to Knuth 2\r\n2558(1427803930)#enrollment-task (ERR): Could not find the enrollment state machine associated to neighbor Knuth and portId 2\r\n```\r\n\r\nipcm.log\r\n```\r\n2548(1427803613)#concurrency (DBG): Lockable created successfully\r\n2548(1427803613)#netlink-manager (DBG): Netlink Manager constructor called, with netlink pid = 1\r\n2548(1427803613)#netlink-manager (INFO): Netlink socket connected to local port 1 \r\n2548(1427803613)#netlink-manager (DBG): Generic Netlink RINA family id: 22\r\n2548(1427803613)#core (DBG): Initialized Netlink Manager\r\n2548(1427803613)#concurrency (DBG): Lockable created successfully\r\n2548(1427803613)#concurrency (DBG): Condition variable created successfully\r\n2548(1427803613)#core (DBG): Initialized event queue\r\n2548(1427803613)#core (DBG): Started Netlink Message reader thread\r\n2548(1427803613)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 28_IPCM_PRESENT; Sport: 1; Dport: 0; Seqnum: 0; Notification; SIPCP: 0; DIPCP: 0\r\n2548(1427803613)#core (DBG): Waiting for message 1\r\n2548(1427803613)#ipcm (DBG): IPC Manager daemon initialized\r\n2548(1427803613)#ipcm (DBG):        installation path: /usr/local/irati/bin\r\n2548(1427803613)#ipcm (DBG):        library path: /usr/local/irati/lib\r\n2548(1427803613)#ipcm (DBG):        log folder: /usr/local/irati/var/log\r\n2548(1427803613)#ipcm (DBG): Starting main I/O loop...\r\n2548(1427803613)#ipcm.console (DBG): Console starts [fd=5]\r\n\r\n2548(1427803613)#ipcm.scripting (DBG): script starts\r\n2548(1427803613)#concurrency (DBG): Lockable created successfully\r\n2548(1427803613)#concurrency (DBG): Condition variable created successfully\r\n2548(1427803613)#concurrency (DBG): Lockable created successfully\r\n2548(1427803613)#concurrency (DBG): Condition variable created successfully\r\n2548(1427803613)#syscalls (DBG): Gonna call syscall SYS_createIPCProcess (317)\r\n2548(1427803613)#concurrency (DBG): Read/Write Lockable created successfully\r\n2548(1427803613)#ipcm (INFO)[create_ipcp]: IPC process test-shim-hv.IPCP:1:: created [id = 1]\r\n\r\n2548(1427803613)#concurrency (DBG): Lockable created successfully\r\n2548(1427803613)#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\n2548(1427803613)#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\n2548(1427803613)#core (DBG): Added event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 1 to events queue\r\n2548(1427803613)#core (DBG): Waiting for message 1\r\n2548(1427803613)#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\n2548(1427803613)#ipcm (DBG): Got event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 1\r\n2548(1427803613)#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\n2548(1427803613)#syscalls (DBG): Gonna call syscall SYS_createIPCProcess (317)\r\n2548(1427803613)#ipc-manager (DBG): Craeted a new IPC Process with pid = 2552\r\n2548(1427803613)#concurrency (DBG): Read/Write Lockable created successfully\r\n2548(1427803613)#concurrency (DBG): Lockable created successfully\r\n2548(1427803613)#ipcm (INFO)[create_ipcp]: IPC process test-normal-1.IPCP:1:: created and waiting for initialization[id = 2]\r\n\r\n2552(1427803613)#ipc-manager (DBG): New OS Process created, executing IPC Process ...\r\n2552(1427803613)#ipc-manager (DBG): argv[0]: /usr/local/irati/bin/ipcp\r\n2548(1427803613)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 41_IPCP_INIT; Sport: 2552; Dport: 1; Seqnum: 0; Notification; SIPCP: 2; DIPCP: 0 \r\n2548(1427803613)#core (DBG): Added event of type 28_IPC_PROCESS_DAEMON_INITIALIZED and sequence number 0 to events queue\r\n2548(1427803613)#core (DBG): Waiting for message 1\r\n2548(1427803613)#ipcm (DBG): Got event of type 28_IPC_PROCESS_DAEMON_INITIALIZED and sequence number 0\r\n2548(1427803613)#ipcm.ipcp (INFO)[ipc_process_daemon_initialized_event_handler]: IPC process daemon initialized [id = 2]\r\n\r\n2548(1427803613)#concurrency (DBG): Lockable created successfully\r\n2548(1427803613)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 1_ASSIGN_TO_DIF_REQ; Sport: 1; Dport: 2552; Seqnum: 2; Request; SIPCP: 0; DIPCP: 2\r\n2548(1427803613)#ipcm (INFO)[assign_to_dif]: Requested DIF assignment of IPC process test-normal-1.IPCP:1:: to DIF test-normal.DIF:::\r\n\r\n2548(1427803613)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 2_ASSIGN_TO_DIF_RESP; Sport: 2552; Dport: 1; Seqnum: 2; Response; SIPCP: 2; DIPCP: 0 \r\n2548(1427803613)#core (DBG): Added event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 2 to events queue\r\n2548(1427803613)#core (DBG): Waiting for message 1\r\n2548(1427803613)#ipcm (DBG): Got event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 2\r\n2548(1427803613)#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\n2548(1427803613)#concurrency (DBG): Lockable created successfully\r\n2548(1427803613)#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\n2548(1427803613)#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\n2548(1427803613)#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\n2548(1427803613)#core (DBG): Added event of type 23_IPCM_REGISTER_APP_RESPONSE and sequence number 3 to events queue\r\n2548(1427803613)#core (DBG): Waiting for message 1\r\n2548(1427803613)#ipcm (DBG): Got event of type 23_IPCM_REGISTER_APP_RESPONSE and sequence number 3\r\n2548(1427803613)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 5_DIF_REG_NOT; Sport: 1; Dport: 2552; Seqnum: 0; Notification; SIPCP: 0; DIPCP: 2\r\n2548(1427803613)#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\n2548(1427803613)#syscalls (DBG): Gonna call syscall SYS_createIPCProcess (317)\r\n2548(1427803613)#ipc-manager (DBG): Craeted a new IPC Process with pid = 2558\r\n2548(1427803613)#concurrency (DBG): Read/Write Lockable created successfully\r\n2548(1427803613)#concurrency (DBG): Lockable created successfully\r\n2548(1427803613)#ipcm (INFO)[create_ipcp]: IPC process Ada:1:: created and waiting for initialization[id = 3]\r\n\r\n2558(1427803613)#ipc-manager (DBG): New OS Process created, executing IPC Process ...\r\n2558(1427803613)#ipc-manager (DBG): argv[0]: /usr/local/irati/bin/ipcp\r\n2548(1427803613)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 41_IPCP_INIT; Sport: 2558; Dport: 1; Seqnum: 0; Notification; SIPCP: 3; DIPCP: 0 \r\n2548(1427803613)#core (DBG): Added event of type 28_IPC_PROCESS_DAEMON_INITIALIZED and sequence number 0 to events queue\r\n2548(1427803613)#core (DBG): Waiting for message 1\r\n2548(1427803613)#ipcm (DBG): Got event of type 28_IPC_PROCESS_DAEMON_INITIALIZED and sequence number 0\r\n2548(1427803613)#ipcm.ipcp (INFO)[ipc_process_daemon_initialized_event_handler]: IPC process daemon initialized [id = 3]\r\n\r\n2548(1427803613)#concurrency (DBG): Lockable created successfully\r\n2548(1427803613)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 1_ASSIGN_TO_DIF_REQ; Sport: 1; Dport: 2558; Seqnum: 4; Request; SIPCP: 0; DIPCP: 3\r\n2548(1427803613)#ipcm (INFO)[assign_to_dif]: Requested DIF assignment of IPC process Ada:1:: to DIF fantastic.DIF:::\r\n\r\n2548(1427803613)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 2_ASSIGN_TO_DIF_RESP; Sport: 2558; Dport: 1; Seqnum: 4; Response; SIPCP: 3; DIPCP: 0 \r\n2548(1427803613)#core (DBG): Added event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 4 to events queue\r\n2548(1427803613)#core (DBG): Waiting for message 1\r\n2548(1427803613)#ipcm (DBG): Got event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 4\r\n2548(1427803613)#ipcm.ipcp (INFO)[assign_to_dif_response_event_handler]: DIF assignment operation completed for IPC process Ada:1:: [success=1]\r\n\r\n2548(1427803613)#concurrency (DBG): Lockable created successfully\r\n2548(1427803613)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 18_IPCM_REG_APP_REQ; Sport: 1; Dport: 2552; Seqnum: 5; Request; SIPCP: 0; DIPCP: 2\r\n2548(1427803613)#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\n2548(1427803613)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 19_ICPM_REG_APP_RESP; Sport: 2552; Dport: 1; Seqnum: 5; Response; SIPCP: 2; DIPCP: 0 \r\n2548(1427803613)#core (DBG): Added event of type 23_IPCM_REGISTER_APP_RESPONSE and sequence number 5 to events queue\r\n2548(1427803613)#core (DBG): Waiting for message 1\r\n2548(1427803613)#ipcm (DBG): Got event of type 23_IPCM_REGISTER_APP_RESPONSE and sequence number 5\r\n2548(1427803613)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 5_DIF_REG_NOT; Sport: 1; Dport: 2558; Seqnum: 0; Notification; SIPCP: 0; DIPCP: 3\r\n2548(1427803613)#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\n2548(1427803613)#concurrency (DBG): Lockable created successfully\r\n2548(1427803613)#concurrency (DBG): Condition variable created successfully\r\n2548(1427803613)#concurrency (DBG): Lockable created successfully\r\n2548(1427803613)#concurrency (DBG): Condition variable created successfully\r\n2548(1427803613)#concurrency (DBG): Lockable created successfully\r\n2548(1427803613)#concurrency (DBG): Condition variable created successfully\r\n2548(1427803613)#ipcm.scripting (DBG): script stops\r\n2548(1427803650)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 12_IPCM_ALLOC_FLOW_RESP_ARR; Sport: 0; Dport: 1; Seqnum: 1; Request; SIPCP: 1; DIPCP: 0 \r\n2548(1427803650)#core (DBG): Added event of type 0_FLOW_ALLOCATION_REQUESTED and sequence number 1 to events queue\r\n2548(1427803650)#core (DBG): Waiting for message 1\r\n2548(1427803650)#ipcm (DBG): Got event of type 0_FLOW_ALLOCATION_REQUESTED and sequence number 1\r\n2548(1427803650)#concurrency (DBG): Lockable created successfully\r\n2548(1427803650)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 44_APP_ALLOC_FLOW_REQ_ARR; Sport: 1; Dport: 2552; Seqnum: 6; Request; SIPCP: 0; DIPCP: 2\r\n2548(1427803650)#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\n2548(1427803650)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 45_APP_ALLOC_FLOW_RESP; Sport: 2552; Dport: 1; Seqnum: 6; Response; SIPCP: 2; DIPCP: 0 \r\n2548(1427803650)#core (DBG): Added event of type 2_ALLOCATE_FLOW_RESPONSE and sequence number 6 to events queue\r\n2548(1427803650)#core (DBG): Waiting for message 1\r\n2548(1427803650)#ipcm (DBG): Got event of type 2_ALLOCATE_FLOW_RESPONSE and sequence number 6\r\n2548(1427803650)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 14_IPCM_ALLOC_FLOW_RESP; Sport: 1; Dport: 0; Seqnum: 1; Response; SIPCP: 2; DIPCP: 1\r\n2548(1427803650)#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 = 1]\r\n\r\n2548(1427803837)#concurrency (DBG): Lockable created successfully\r\n2548(1427803837)#concurrency (DBG): Condition variable created successfully\r\n2548(1427803837)#concurrency (DBG): Lockable created successfully\r\n2548(1427803837)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 22_QUERY_RIB_REQ; Sport: 1; Dport: 2552; Seqnum: 7; Request; SIPCP: 0; DIPCP: 2\r\n2548(1427803837)#ipcm (INFO)[query_rib]: Requested query RIB of IPC process test-normal-1.IPCP:1::\r\n\r\n2548(1427803837)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 23_QUERY_RIB_RESP; Sport: 2552; Dport: 1; Seqnum: 7; Response; SIPCP: 2; DIPCP: 0 \r\n2548(1427803837)#core (DBG): Added event of type 27_QUERY_RIB_RESPONSE and sequence number 7 to events queue\r\n2548(1427803837)#core (DBG): Waiting for message 1\r\n2548(1427803837)#ipcm (DBG): Got event of type 27_QUERY_RIB_RESPONSE and sequence number 7\r\n2548(1427803837)#ipcm.misc (INFO)[query_rib_response_event_handler]: Query RIB operation completed for IPC process test-normal-1.IPCP:1::\r\n\r\n2548(1427803865)#concurrency (DBG): Lockable created successfully\r\n2548(1427803865)#concurrency (DBG): Condition variable created successfully\r\n2548(1427803865)#concurrency (DBG): Lockable created successfully\r\n2548(1427803865)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 22_QUERY_RIB_REQ; Sport: 1; Dport: 2558; Seqnum: 8; Request; SIPCP: 0; DIPCP: 3\r\n2548(1427803865)#ipcm (INFO)[query_rib]: Requested query RIB of IPC process Ada:1::\r\n\r\n2548(1427803865)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 23_QUERY_RIB_RESP; Sport: 2558; Dport: 1; Seqnum: 8; Response; SIPCP: 3; DIPCP: 0 \r\n2548(1427803865)#core (DBG): Added event of type 27_QUERY_RIB_RESPONSE and sequence number 8 to events queue\r\n2548(1427803865)#core (DBG): Waiting for message 1\r\n2548(1427803865)#ipcm (DBG): Got event of type 27_QUERY_RIB_RESPONSE and sequence number 8\r\n2548(1427803865)#ipcm.misc (INFO)[query_rib_response_event_handler]: Query RIB operation completed for IPC process Ada:1::\r\n\r\n2548(1427803920)#concurrency (DBG): Lockable created successfully\r\n2548(1427803920)#concurrency (DBG): Condition variable created successfully\r\n2548(1427803920)#concurrency (DBG): Lockable created successfully\r\n2548(1427803920)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 7_ENROLL_TO_DIF_REQ; Sport: 1; Dport: 2558; Seqnum: 9; Request; SIPCP: 0; DIPCP: 3\r\n2548(1427803920)#ipcm (INFO)[enroll_to_dif]: Requested enrollment of IPC process Ada:1:: to DIF fantastic.DIF::: through DIF test-normal.DIF::: and neighbor IPC process Knuth:1::\r\n\r\n2548(1427803920)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 42_APP_ALLOC_FLOW_REQ; Sport: 2558; Dport: 1; Seqnum: 1427803616; Request; SIPCP: 3; DIPCP: 0 \r\n2548(1427803920)#core (DBG): Added event of type 0_FLOW_ALLOCATION_REQUESTED and sequence number 1427803616 to events queue\r\n2548(1427803920)#core (DBG): Waiting for message 1\r\n2548(1427803920)#ipcm (DBG): Got event of type 0_FLOW_ALLOCATION_REQUESTED and sequence number 1427803616\r\n2548(1427803920)#concurrency (DBG): Lockable created successfully\r\n2548(1427803920)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 11_IPCM_ALLOC_FLOW_REQ; Sport: 1; Dport: 2552; Seqnum: 10; Request; SIPCP: 3; DIPCP: 2\r\n2548(1427803920)#ipcm.flow-alloc (INFO)[flow_allocation_requested_local]: IPC process test-normal-1.IPCP:1:: requested to allocate flow between Ada:1:: and Knuth:1::\r\n\r\n2548(1427803920)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 13_IPCM_ALLOC_FLOW_REQ_RES; Sport: 2552; Dport: 1; Seqnum: 10; Response; SIPCP: 2; DIPCP: 0 \r\n2548(1427803920)#core (DBG): Added event of type 26_IPCM_ALLOCATE_FLOW_RESULT and sequence number 10 to events queue\r\n2548(1427803920)#core (DBG): Waiting for message 1\r\n2548(1427803920)#ipcm (DBG): Got event of type 26_IPCM_ALLOCATE_FLOW_RESULT and sequence number 10\r\n2548(1427803920)#ipcm.flow-alloc (INFO)[ipcm_allocate_flow_request_result_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 = 2]\r\n\r\n2548(1427803920)#ipc-manager (DBG): ApplicationManager::flowAllocated called\r\n2548(1427803920)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 43_APP_ALLOC_FLOW_REQ_RES; Sport: 1; Dport: 2558; Seqnum: 1427803616; Response; SIPCP: 0; DIPCP: 3\r\n2548(1427803920)#ipcm.flow-alloc (INFO)[ipcm_allocate_flow_request_result_handler]: Applications Ada:1:: and Knuth:1:: informed about flow allocation result\r\n\r\n2548(1427803930)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 17_IPCM_FLOW_DEALLOC_NOT; Sport: 2552; Dport: 1; Seqnum: 0; Notification; SIPCP: 2; DIPCP: 0 \r\n2548(1427803930)#core (DBG): Added event of type 6_FLOW_DEALLOCATED and sequence number 0 to events queue\r\n2548(1427803930)#core (DBG): Waiting for message 1\r\n2548(1427803930)#ipcm (DBG): Got event of type 6_FLOW_DEALLOCATED and sequence number 0\r\n2548(1427803930)#ipc-manager (DBG): ApplicationManager::flowDeallocatedRemotely called\r\n2548(1427803930)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 48_APP_FLOW_DEALLOC_NOT; Sport: 1; Dport: 2558; Seqnum: 0; Notification; SIPCP: 0; DIPCP: 3\r\n2548(1427803930)#ipcm.flow-alloc (INFO)[flow_deallocated_event_handler]: IPC process test-normal-1.IPCP:1:: and local application Ada:1:: informed that flow with port-id 2 has been deallocated remotely \r\n\r\n```\r\n\r\ntest-normal-1.IPCP-1.log\r\n```\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#netlink-manager (DBG): Netlink Manager constructor called, with netlink pid = 2552\r\n2552(1427803613)#netlink-manager (INFO): Netlink socket connected to local port 2552 \r\n2552(1427803613)#netlink-manager (DBG): Generic Netlink RINA family id: 22\r\n2552(1427803613)#core (DBG): Initialized Netlink Manager\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#concurrency (DBG): Condition variable created successfully\r\n2552(1427803613)#core (DBG): Initialized event queue\r\n2552(1427803613)#core (DBG): Started Netlink Message reader thread\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#ipc-process (INFO): Librina initialized\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#core (DBG): Waiting for message 2552\r\n2552(1427803613)#ipc-process (INFO): Pluggable component 'security-manager'/'default' [default] published\r\n2552(1427803613)#ipc-process (INFO): Pluggable component 'flow-allocator'/'default' [default] published\r\n2552(1427803613)#ipc-process (INFO): Pluggable component 'namespace-manager'/'default' [default] published\r\n2552(1427803613)#ipc-process (INFO): Pluggable component 'resource-allocator'/'default' [default] published\r\n2552(1427803613)#ipc-process (INFO): Pluggable component 'routing'/'link-state' [default] published\r\n2552(1427803613)#ipc-process (INFO): Plugin default loaded successfully\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#rib-daemon (INFO): EventListener subscribed to event 5_N_MINUS_1_FLOW_ALLOCATED\r\n2552(1427803613)#rib-daemon (INFO): EventListener subscribed to event 7_N_MINUS_1_FLOW_DEALLOCATED\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#rib (INFO): Object with name /daf/management/neighbors, class neighbor set, instance 1 added to the RIB\r\n2552(1427803613)#rib (INFO): Object with name /daf/management/enrollment, class enrollment information, instance 2 added to the RIB\r\n2552(1427803613)#rib (INFO): Object with name /daf/management/operationalStatus, class operationstatus, instance 3 added to the RIB\r\n2552(1427803613)#rib-daemon (INFO): Starting Management SDU reader ...\r\n2552(1427803613)#rib (INFO): Object with name /daf/management/naming/address, class address, instance 4 added to the RIB\r\n2552(1427803613)#rib-daemon (INFO): EventListener subscribed to event 7_N_MINUS_1_FLOW_DEALLOCATED\r\n2552(1427803613)#rib-daemon (INFO): EventListener subscribed to event 5_N_MINUS_1_FLOW_ALLOCATED\r\n2552(1427803613)#rib-daemon (INFO): EventListener subscribed to event 6_N_MINUS_1_FLOW_ALLOCATION_FAILED\r\n2552(1427803613)#rib-daemon (INFO): EventListener subscribed to event 8_NEIGHBOR_DECLARED_DEAD\r\n2552(1427803613)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/difregistrations, class DIF registration set, instance 5 added to the RIB\r\n2552(1427803613)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/nminusoneflows, class nminusone flow set, instance 6 added to the RIB\r\n2552(1427803613)#rib-daemon (INFO): EventListener subscribed to event 0_CONNECTIVITY_TO_NEIGHBOR_LOST\r\n2552(1427803613)#rib (INFO): Object with name /dif/management/flowallocator/directoryforwardingtableentries, class directoryforwardingtableentry set, instance 7 added to the RIB\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#rib (INFO): Object with name /daf/management/naming/whatevercastnames, class whatname set, instance 8 added to the RIB\r\n2552(1427803613)#rib (INFO): Object with name /dif/resourceallocation/flowallocator/flows, class flow set, instance 9 added to the RIB\r\n2552(1427803613)#rib (INFO): Object with name /dif/management/flowallocator/qoscubes, class qoscube set, instance 10 added to the RIB\r\n2552(1427803613)#rib (INFO): Object with name /dif/ipc/datatransfer/constants, class datatransfercons, instance 11 added to the RIB\r\n2552(1427803613)#ipcp-components (INFO): Policy-set default selected for component security-manager\r\n2552(1427803613)#ipcp-components (INFO): Policy-set default selected for component flow-allocator\r\n2552(1427803613)#ipcp-components (INFO): Policy-set default selected for component namespace-manager\r\n2552(1427803613)#ipcp-components (INFO): Policy-set default selected for component resource-allocator\r\n2552(1427803613)#ipcp-components (INFO): Policy-set link-state selected for component routing\r\n2552(1427803613)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n2552(1427803613)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 41_IPCP_INIT; Sport: 2552; Dport: 1; Seqnum: 0; Notification; SIPCP: 2; DIPCP: 0\r\n2552(1427803613)#ipc-process (INFO): Initialized IPC Process with name: test-normal-1.IPCP, instance 1, id 2 \r\n2552(1427803613)#ipcp-main (INFO): IPC Process name:     test-normal-1.IPCP\r\n2552(1427803613)#ipcp-main (INFO): IPC Process instance: 1\r\n2552(1427803613)#ipcp-main (INFO): IPC Process id:       2\r\n2552(1427803613)#ipcp-main (INFO): IPC Manager port:     1\r\n2552(1427803613)#ipcp-main (INFO): IPC Process initialized, executing event loop...\r\n2552(1427803613)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 1_ASSIGN_TO_DIF_REQ; Sport: 1; Dport: 2552; Seqnum: 2; Request; SIPCP: 0; DIPCP: 2 \r\n2552(1427803613)#core (DBG): Added event of type 12_ASSIGN_TO_DIF_REQUEST and sequence number 2 to events queue\r\n2552(1427803613)#core (DBG): Waiting for message 2552\r\n2552(1427803613)#event-loop (DBG): Got event of type 12_ASSIGN_TO_DIF_REQUEST and sequence number 2\r\n2552(1427803613)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 2_ASSIGN_TO_DIF_RESP; Sport: 0; Dport: 2552; Seqnum: 1427803614; Response; SIPCP: 2; DIPCP: 0 \r\n2552(1427803613)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 1_ASSIGN_TO_DIF_REQ; Sport: 2552; Dport: 0; Seqnum: 1427803614; Request; SIPCP: 2; DIPCP: 2\r\n2552(1427803613)#core (DBG): Added event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 1427803614 to events queue\r\n2552(1427803613)#core (DBG): Waiting for message 2552\r\n2552(1427803613)#event-loop (DBG): Got event of type 13_ASSIGN_TO_DIF_RESPONSE and sequence number 1427803614\r\n2552(1427803613)#ipc-process (DBG): The kernel processed successfully the Assign to DIF request\r\n2552(1427803613)#rib-daemon (DBG): Configuration set: 16\r\n2552(1427803613)#resource-allocator (DBG): DIF configuration set 16\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#timer (DBG): Timer with ID 20018384 started\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#rib (INFO): Object with name /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup, class flowstateobject set, instance 12 added to the RIB\r\n2552(1427803613)#rib-daemon (INFO): EventListener subscribed to event 7_N_MINUS_1_FLOW_DEALLOCATED\r\n2552(1427803613)#rib-daemon (INFO): EventListener subscribed to event 5_N_MINUS_1_FLOW_ALLOCATED\r\n2552(1427803613)#rib-daemon (INFO): EventListener subscribed to event 9_NEIGHBOR_ADDED\r\n2552(1427803613)#rib-daemon (INFO): EventListener subscribed to event 0_CONNECTIVITY_TO_NEIGHBOR_LOST\r\n2552(1427803613)#namespace-manager (DBG): DIF configuration set: 16\r\n2552(1427803613)#security-manager (DBG): Set dif configuration: 16\r\n2552(1427803613)#rib (INFO): Object with name /dif/management/flowallocator/qoscubes/unreliablewithflowcontrol, class qoscube, instance 13 added to the RIB\r\n2552(1427803613)#rib (INFO): Object with name /dif/management/flowallocator/qoscubes/reliablewithflowcontrol, class qoscube, instance 14 added to the RIB\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#concurrency (DBG): Lockable created successfully\r\n2552(1427803613)#timer (DBG): Timer with ID 20018976 started\r\n2552(1427803613)#rib (INFO): Object with name /difmanagement/watchdog, class watchdog timer, instance 15 added to the RIB\r\n2552(1427803613)#enrollment-task (DBG): Started Neighbors enroller thread\r\n2552(1427803613)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 2_ASSIGN_TO_DIF_RESP; Sport: 2552; Dport: 1; Seqnum: 2; Response; SIPCP: 2; DIPCP: 0\r\n2552(1427803613)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 5_DIF_REG_NOT; Sport: 1; Dport: 2552; Seqnum: 0; Notification; SIPCP: 0; DIPCP: 2 \r\n2552(1427803613)#core (DBG): Added event of type 18_DIF_REGISTRATION_NOTIFICATION and sequence number 0 to events queue\r\n2552(1427803613)#core (DBG): Waiting for message 2552\r\n2552(1427803613)#event-loop (DBG): Got event of type 18_DIF_REGISTRATION_NOTIFICATION and sequence number 0\r\n2552(1427803613)#resource-allocator (INFO): IPC Process registered to N-1 DIF test-shim-hv.DIF\r\n2552(1427803613)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/difregistrations/test-shim-hv.DIF, class DIF registration, instance 16 added to the RIB\r\n2552(1427803613)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 18_IPCM_REG_APP_REQ; Sport: 1; Dport: 2552; Seqnum: 5; Request; SIPCP: 0; DIPCP: 2 \r\n2552(1427803613)#core (DBG): Added event of type 7_APPLICATION_REGISTRATION_REQUEST and sequence number 5 to events queue\r\n2552(1427803613)#core (DBG): Waiting for message 2552\r\n2552(1427803613)#event-loop (DBG): Got event of type 7_APPLICATION_REGISTRATION_REQUEST and sequence number 5\r\n2552(1427803613)#namespace-manager (INFO): Successfully registered application Ada-1-- with IPC Process id 2s\r\n2552(1427803613)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 19_ICPM_REG_APP_RESP; Sport: 2552; Dport: 1; Seqnum: 5; Response; SIPCP: 2; DIPCP: 0\r\n2552(1427803613)#namespace-manager (DBG): Added entry to DFT: Ada:1::\r\nIPC Process address: 16\r\nTimestamp: 0\r\n\r\n2552(1427803613)#rib (INFO): Object with name /dif/management/flowallocator/directoryforwardingtableentries/Ada-1--, class directoryforwardingtableentry, instance 17 added to the RIB\r\n2552(1427803650)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 44_APP_ALLOC_FLOW_REQ_ARR; Sport: 1; Dport: 2552; Seqnum: 6; Request; SIPCP: 0; DIPCP: 2 \r\n2552(1427803650)#core (DBG): Added event of type 0_FLOW_ALLOCATION_REQUESTED and sequence number 6 to events queue\r\n2552(1427803650)#core (DBG): Waiting for message 2552\r\n2552(1427803650)#event-loop (DBG): Got event of type 0_FLOW_ALLOCATION_REQUESTED and sequence number 6\r\n2552(1427803650)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 45_APP_ALLOC_FLOW_RESP; Sport: 2552; Dport: 1; Seqnum: 6; Response; SIPCP: 2; DIPCP: 0\r\n2552(1427803650)#resource-allocator (INFO): Accepted new flow from IPC Process test-normal-2.IPCP-1\r\n2552(1427803650)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/nminusoneflows/1, class nminusone flow, instance 18 added to the RIB\r\n2552(1427803650)#rib-daemon (INFO): Event 5_N_MINUS_1_FLOW_ALLOCATED has just happened. Notifying event listeners.\r\n2552(1427803650)#routing-ps-link-state (DBG): flow allocation waiting for enrollment\r\n2552(1427803650)#concurrency (DBG): Lockable created successfully\r\n2552(1427803650)#cdap-manager (DBG): Created a new CDAP session for port 1\r\n2552(1427803650)#rib-daemon (DBG): Received CDAP message through portId 1: \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\n2552(1427803650)#enrollment-task (DBG): Received M_CONNECT CDAP message from port-id 1\r\n2552(1427803650)#concurrency (DBG): Lockable created successfully\r\n2552(1427803650)#concurrency (DBG): Lockable created successfully\r\n2552(1427803650)#timer (DBG): Timer with ID -402640032 started\r\n2552(1427803650)#concurrency (DBG): Lockable created successfully\r\n2552(1427803650)#enrollment-task (DBG): Created a new Enrollment state machine for remote IPC process: test-normal-2.IPCP-1-Management-\r\n2552(1427803650)#enrollment-task (DBG): Authenticating IPC process test-normal-2.IPCP-1 ...\r\n2552(1427803650)#enrollment-task (DBG): Authentication successful, deciding if new member can join the DIF...\r\n2552(1427803650)#security-manager-ps-default (DBG): Allowing IPC Process test-normal-2.IPCP to join the DIF\r\n2552(1427803650)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n2552(1427803650)#rib-daemon (DBG): Sent CDAP message of size 116 through port-id 1: \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\n2552(1427803650)#enrollment-task (DBG): M_CONNECT_R sent to portID 1. Waiting for start enrollment request message\r\n2552(1427803650)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n2552(1427803650)#rib-daemon (DBG): Received CDAP message through portId 1: \r\n14_M_START\r\nInvoke id: 1\r\nObject class: enrollment information\r\nObject name: /daf/management/enrollment\r\nObject value: 0x7fd3e8003ce0\r\nScope: 0\r\n\r\n2552(1427803650)#rib (DBG): Remote operation 14 called on object /daf/management/enrollment\r\n2552(1427803650)#enrollment-task (DBG): Remote IPC Process address: 17\r\n2552(1427803650)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n2552(1427803650)#rib-daemon (DBG): Sent CDAP message of size 106 through port-id 1: \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\n2552(1427803650)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n2552(1427803650)#rib-daemon (DBG): Sent CDAP message of size 176 through port-id 1: \r\n4_M_CREATE\r\nObject class: directoryforwardingtableentry set\r\nObject name: /dif/management/flowallocator/directoryforwardingtableentries\r\nObject value: 0x7fd3e8003430\r\nScope: 0\r\n\r\n2552(1427803650)#application (DBG): IPCManager.getRegisteredApplications called\r\n2552(1427803650)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n2552(1427803650)#rib-daemon (DBG): Sent CDAP message of size 144 through port-id 1: \r\n4_M_CREATE\r\nObject class: neighbor set\r\nObject name: /daf/management/neighbors\r\nObject value: 0x7fd3e8003430\r\nScope: 0\r\n\r\n2552(1427803650)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n2552(1427803650)#rib-daemon (DBG): Sent CDAP message of size 132 through port-id 1: \r\n16_M_STOP\r\nInvoke id: 1\r\nObject class: enrollment information\r\nObject name: /daf/management/enrollment\r\nObject value: 0x7fd3e8003430\r\nScope: 0\r\n\r\n2552(1427803650)#enrollment-task (DBG): Waiting for stop enrollment response message\r\n2552(1427803650)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n2552(1427803650)#rib-daemon (DBG): Received CDAP message through portId 1: \r\n4_M_CREATE\r\nObject class: directoryforwardingtableentry set\r\nObject name: /dif/management/flowallocator/directoryforwardingtableentries\r\nObject value: 0x7fd3e8003ce0\r\nScope: 0\r\n\r\n2552(1427803650)#rib (DBG): Remote operation 4 called on object /dif/management/flowallocator/directoryforwardingtableentries\r\n2552(1427803650)#namespace-manager (DBG): Added entry to DFT: Knuth:1::\r\nIPC Process address: 17\r\nTimestamp: 0\r\n\r\n2552(1427803650)#rib (INFO): Object with name /dif/management/flowallocator/directoryforwardingtableentries/Knuth-1--, class directoryforwardingtableentry, instance 19 added to the RIB\r\n2552(1427803650)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n2552(1427803650)#rib-daemon (DBG): Received CDAP message through portId 1: \r\n17_M_STOP_R\r\nInvoke id: 1\r\nResult: 0\r\n\r\n2552(1427803650)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n2552(1427803650)#rib-daemon (DBG): Sent CDAP message of size 106 through port-id 1: \r\n14_M_START\r\nObject class: operationstatus\r\nObject name: /daf/management/operationalStatus\r\nScope: 0\r\n\r\n2552(1427803650)#timer (DBG): Waiting for the timer -402640032 to join\r\n2552(1427803651)#timer (DBG): Timer with ID -402640032 ended\r\n2552(1427803651)#application (DBG): IPCManager.getRegisteredApplications called\r\n2552(1427803651)#rib (INFO): Object with name /daf/management/neighbors/test-normal-2.IPCP, class neighbor, instance 20 added to the RIB\r\n2552(1427803651)#rib-daemon (INFO): Event 9_NEIGHBOR_ADDED has just happened. Notifying event listeners.\r\n2552(1427803651)#routing-ps-link-state (INFO): There was an allocation flow event waiting for enrollment, launching it\r\n2552(1427803651)#rib (INFO): Object with name /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup/16-17, class flowstateobject, instance 21 added to the RIB\r\n2552(1427803651)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n2552(1427803651)#rib-daemon (DBG): Sent CDAP message of size 160 through port-id 1: \r\n12_M_WRITE\r\nObject class: flowstateobject set\r\nObject name: /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup\r\nObject value: 0x7fd3e8003430\r\nScope: 0\r\n\r\n2552(1427803651)#enrollment-task (INFO): Remote IPC Process enrolled!\r\n2552(1427803651)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n2552(1427803651)#rib-daemon (DBG): Received CDAP message through portId 1: \r\n12_M_WRITE\r\nObject class: flowstateobject set\r\nObject name: /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup\r\nObject value: 0x7fd3e8003ce0\r\nScope: 0\r\n\r\n2552(1427803651)#rib (DBG): Remote operation 12 called on object /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup\r\n2552(1427803651)#routing-ps-link-state (DBG): Update objects from DB launched\r\n2552(1427803651)#routing-ps-link-state (DBG): New object added\r\n2552(1427803651)#rib (INFO): Object with name /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup/17-16, class flowstateobject, instance 22 added to the RIB\r\n2552(1427803651)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n2552(1427803651)#routing-ps-link-state (DBG): Processing flow state object: /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup/16-17\r\n2552(1427803651)#routing-ps-link-state (DBG): Processing flow state object: /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup/17-16\r\n2552(1427803651)#routing-ps-link-state (DBG): Added entry to routing table: destination 17, next-hop 17\r\n2552(1427803651)#resource-allocator-ps-default (DBG): Got 1 entries in the routing table\r\n2552(1427803651)#resource-allocator-ps-default (DBG): Processing entry for destination 17\r\n2552(1427803651)#resource-allocator-ps-default (DBG): Next hop address 17\r\n2552(1427803651)#resource-allocator-ps-default (DBG): N-1 port-id: 1\r\n2552(1427803651)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 24_MODIFY_FT_REQ; Sport: 2552; Dport: 0; Seqnum: 1427803615; Request; SIPCP: 2; DIPCP: 2\r\n2552(1427803651)#routing-ps-link-state (DBG): Propagation: Check modified object /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup/16-17 with age 0 and status 1\r\n2552(1427803651)#routing-ps-link-state (DBG): Propagation: Check modified object /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup/17-16 with age 0 and status 1\r\n2552(1427803733)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n2552(1427803733)#rib-daemon (DBG): Sent CDAP message of size 95 through port-id 1: \r\n8_M_READ\r\nInvoke id: 1\r\nObject class: watchdog timer\r\nObject name: /difmanagement/watchdog\r\nScope: 0\r\n\r\n2552(1427803733)#rib-daemon (DBG): Received CDAP message through portId 1: \r\n9_M_READ_R\r\nInvoke id: 1\r\nObject class: watchdog timer\r\nObject name: /difmanagement/watchdog\r\nObject value: 0x7fd3e8004050\r\nResult: 0\r\n\r\n2552(1427803733)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n2552(1427803793)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n2552(1427803793)#rib-daemon (DBG): Sent CDAP message of size 95 through port-id 1: \r\n8_M_READ\r\nInvoke id: 1\r\nObject class: watchdog timer\r\nObject name: /difmanagement/watchdog\r\nScope: 0\r\n\r\n2552(1427803793)#rib-daemon (DBG): Received CDAP message through portId 1: \r\n9_M_READ_R\r\nInvoke id: 1\r\nObject class: watchdog timer\r\nObject name: /difmanagement/watchdog\r\nObject value: 0x7fd3e8003d70\r\nResult: 0\r\n\r\n2552(1427803793)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n2552(1427803837)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 22_QUERY_RIB_REQ; Sport: 1; Dport: 2552; Seqnum: 7; Request; SIPCP: 0; DIPCP: 2 \r\n2552(1427803837)#core (DBG): Added event of type 19_QUERY_RIB and sequence number 7 to events queue\r\n2552(1427803837)#core (DBG): Waiting for message 2552\r\n2552(1427803837)#event-loop (DBG): Got event of type 19_QUERY_RIB and sequence number 7\r\n2552(1427803837)#rib-daemon (DBG): Object name: /daf/management/enrollment\r\n2552(1427803837)#rib-daemon (DBG): Object name: /daf/management/naming/address\r\n2552(1427803837)#rib-daemon (DBG): Object name: /daf/management/naming/whatevercastnames\r\n2552(1427803837)#rib-daemon (DBG): Object name: /daf/management/neighbors\r\n2552(1427803837)#rib-daemon (DBG): Object name: /daf/management/neighbors/test-normal-2.IPCP\r\n2552(1427803837)#rib-daemon (DBG): Object name: /daf/management/operationalStatus\r\n2552(1427803837)#rib-daemon (DBG): Object name: /dif/ipc/datatransfer/constants\r\n2552(1427803837)#rib-daemon (DBG): Object name: /dif/management/flowallocator/directoryforwardingtableentries\r\n2552(1427803837)#rib-daemon (DBG): Object name: /dif/management/flowallocator/directoryforwardingtableentries/Ada-1--\r\n2552(1427803837)#rib-daemon (DBG): Object name: /dif/management/flowallocator/directoryforwardingtableentries/Knuth-1--\r\n2552(1427803837)#rib-daemon (DBG): Object name: /dif/management/flowallocator/qoscubes\r\n2552(1427803837)#rib-daemon (DBG): Object name: /dif/management/flowallocator/qoscubes/reliablewithflowcontrol\r\n2552(1427803837)#rib-daemon (DBG): Object name: /dif/management/flowallocator/qoscubes/unreliablewithflowcontrol\r\n2552(1427803837)#rib-daemon (DBG): Object name: /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup\r\n2552(1427803837)#rib-daemon (DBG): Object name: /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup/16-17\r\n2552(1427803837)#rib-daemon (DBG): Object name: /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup/17-16\r\n2552(1427803837)#rib-daemon (DBG): Object name: /dif/resourceallocation/flowallocator/flows\r\n2552(1427803837)#rib-daemon (DBG): Object name: /dif/resourceallocation/nminusoneflowmanager/difregistrations\r\n2552(1427803837)#rib-daemon (DBG): Object name: /dif/resourceallocation/nminusoneflowmanager/difregistrations/test-shim-hv.DIF\r\n2552(1427803837)#rib-daemon (DBG): Object name: /dif/resourceallocation/nminusoneflowmanager/nminusoneflows\r\n2552(1427803837)#rib-daemon (DBG): Object name: /dif/resourceallocation/nminusoneflowmanager/nminusoneflows/1\r\n2552(1427803837)#rib-daemon (DBG): Object name: /difmanagement/watchdog\r\n2552(1427803837)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 23_QUERY_RIB_RESP; Sport: 2552; Dport: 1; Seqnum: 7; Response; SIPCP: 2; DIPCP: 0\r\n2552(1427803837)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 25_DUMP_FT_REQ; Sport: 2552; Dport: 0; Seqnum: 1427803616; Request; SIPCP: 2; DIPCP: 2\r\n2552(1427803837)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 26_DUMP_FT_RESP; Sport: 0; Dport: 2552; Seqnum: 1427803616; Response; SIPCP: 2; DIPCP: 0 \r\n2552(1427803837)#core (DBG): Added event of type 34_DUMP_FT_RESPONSE and sequence number 1427803616 to events queue\r\n2552(1427803837)#core (DBG): Waiting for message 2552\r\n2552(1427803837)#event-loop (DBG): Got event of type 34_DUMP_FT_RESPONSE and sequence number 1427803616\r\n2552(1427803837)#ipc-process (INFO): Contents of the PDU Forwarding Table: \r\nAddress: 17; QoS-id: 1; Port-ids: 1; \r\n\r\n2552(1427803853)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n2552(1427803853)#rib-daemon (DBG): Sent CDAP message of size 95 through port-id 1: \r\n8_M_READ\r\nInvoke id: 1\r\nObject class: watchdog timer\r\nObject name: /difmanagement/watchdog\r\nScope: 0\r\n\r\n2552(1427803853)#rib-daemon (DBG): Received CDAP message through portId 1: \r\n9_M_READ_R\r\nInvoke id: 1\r\nObject class: watchdog timer\r\nObject name: /difmanagement/watchdog\r\nObject value: 0x7fd3e8004010\r\nResult: 0\r\n\r\n2552(1427803853)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n2552(1427803913)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n2552(1427803913)#rib-daemon (DBG): Sent CDAP message of size 95 through port-id 1: \r\n8_M_READ\r\nInvoke id: 1\r\nObject class: watchdog timer\r\nObject name: /difmanagement/watchdog\r\nScope: 0\r\n\r\n2552(1427803913)#rib-daemon (DBG): Received CDAP message through portId 1: \r\n9_M_READ_R\r\nInvoke id: 1\r\nObject class: watchdog timer\r\nObject name: /difmanagement/watchdog\r\nObject value: 0x7fd3e8003d50\r\nResult: 0\r\n\r\n2552(1427803913)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n2552(1427803920)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 11_IPCM_ALLOC_FLOW_REQ; Sport: 1; Dport: 2552; Seqnum: 10; Request; SIPCP: 3; DIPCP: 2 \r\n2552(1427803920)#core (DBG): Added event of type 0_FLOW_ALLOCATION_REQUESTED and sequence number 10 to events queue\r\n2552(1427803920)#core (DBG): Waiting for message 2552\r\n2552(1427803920)#event-loop (DBG): Got event of type 0_FLOW_ALLOCATION_REQUESTED and sequence number 10\r\n2552(1427803920)#syscalls (DBG): Gonna call syscall SYS_allocatePortId (321)\r\n2552(1427803920)#flow-allocator (DBG): Got assigned port-id 2\r\n2552(1427803920)#concurrency (DBG): Lockable created successfully\r\n2552(1427803920)#concurrency (DBG): Lockable created successfully\r\n2552(1427803920)#timer (DBG): Timer with ID 20017888 started\r\n2552(1427803920)#concurrency (DBG): Lockable created successfully\r\n2552(1427803920)#concurrency (DBG): Lockable created successfully\r\n2552(1427803920)#concurrency (DBG): Lockable created successfully\r\n2552(1427803920)#timer (DBG): Timer with ID 19980752 started\r\n2552(1427803920)#flow-allocator (DBG): Created flow allocator instance to manage the flow identified by portId 2 \r\n2552(1427803920)#flow-allocator-ps-default (DBG): Selected qos cube with name unreliablewithflowcontrol\r\n2552(1427803920)#flow-allocator (DBG): Generated flow object\r\n2552(1427803920)#flow-allocator (DBG): The directory forwarding table returned address 17\r\n2552(1427803920)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 29_CREATE_EFCP_CONN_REQ; Sport: 2552; Dport: 0; Seqnum: 1427803617; Request; SIPCP: 2; DIPCP: 2\r\n2552(1427803920)#flow-allocator (DBG): Requested the creation of a connection to the kernel, for flow with port-id 2\r\n2552(1427803920)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 30_CREATE_EFCP_CONN_RESP; Sport: 0; Dport: 2552; Seqnum: 1427803617; Response; SIPCP: 2; DIPCP: 0 \r\n2552(1427803920)#core (DBG): Added event of type 30_CREATE_EFCP_CONN_RESPONSE and sequence number 1427803617 to events queue\r\n2552(1427803920)#core (DBG): Waiting for message 2552\r\n2552(1427803920)#event-loop (DBG): Got event of type 30_CREATE_EFCP_CONN_RESPONSE and sequence number 1427803617\r\n2552(1427803920)#flow-allocator (DBG): Created connection with cep-id 0\r\n2552(1427803920)#syscalls (DBG): Gonna call syscall SYS_writeManagementSDU (324)\r\n2552(1427803920)#rib-daemon (DBG): Sent A-Data CDAP message to address 17: \r\n4_M_CREATE\r\nInvoke id: 1\r\nObject class: flow\r\nObject name: /dif/resourceallocation/flowallocator/flows/16-2\r\nObject value: 0x130df30\r\nScope: 0\r\n\r\n2552(1427803920)#rib-daemon (DBG): Received A-Data CDAP message from address 17 : \r\n5_M_CREATE_R\r\nInvoke id: 1\r\nObject class: flow\r\nObject name: /dif/resourceallocation/flowallocator/flows/16-2\r\nObject value: 0x7fd3e8004f10\r\nResult: 0\r\n\r\n2552(1427803920)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 33_UPDATE_EFCP_CONN_REQ; Sport: 2552; Dport: 0; Seqnum: 1427803618; Request; SIPCP: 2; DIPCP: 2\r\n2552(1427803920)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n2552(1427803920)#netlink-manager (DBG): NL msg RX. Fam: 22; Opcode: 34_UPDATE_EFCP_CONN_RES; Sport: 0; Dport: 2552; Seqnum: 1427803618; Response; SIPCP: 2; DIPCP: 0 \r\n2552(1427803920)#core (DBG): Added event of type 31_UPDATE_EFCP_CONN_RESPONSE and sequence number 1427803618 to events queue\r\n2552(1427803920)#core (DBG): Waiting for message 2552\r\n2552(1427803920)#event-loop (DBG): Got event of type 31_UPDATE_EFCP_CONN_RESPONSE and sequence number 1427803618\r\n2552(1427803920)#rib (INFO): Object with name /dif/resourceallocation/flowallocator/flows/16-2, class flow, instance 23 added to the RIB\r\n2552(1427803920)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 13_IPCM_ALLOC_FLOW_REQ_RES; Sport: 2552; Dport: 1; Seqnum: 10; Response; SIPCP: 2; DIPCP: 0\r\n2552(1427803930)#rib-daemon (DBG): Received A-Data CDAP message from address 17 : \r\n6_M_DELETE\r\nObject class: flow\r\nObject name: /dif/resourceallocation/flowallocator/flows/16-2\r\nScope: 0\r\n\r\n2552(1427803930)#rib (DBG): Remote operation 6 called on object /dif/resourceallocation/flowallocator/flows/16-2\r\n2552(1427803930)#netlink-manager (DBG): NL msg TX. Fam: 22; Opcode: 17_IPCM_FLOW_DEALLOC_NOT; Sport: 2552; Dport: 1; Seqnum: 0; Notification; SIPCP: 2; DIPCP: 0\r\n2552(1427803930)#syscalls (DBG): Gonna call syscall SYS_readManagementSDU (323)\r\n2552(1427803935)#rib (INFO): Object with name /dif/resourceallocation/flowallocator/flows/16-2, class flow, instance 23 removed from the RIB\r\n2552(1427803935)#syscalls (DBG): Gonna call syscall SYS_deallocatePortId (322)\r\n2552(1427803935)#timer (DBG): Waiting for the timer 19980752 to join\r\n2552(1427803936)#timer (DBG): Timer with ID 19980752 ended\r\n2552(1427803936)#timer (DBG): Waiting for the timer 20017888 to join\r\n2552(1427803936)#timer (DBG): Timer with ID 20017888 ended\r\n```\r\n\r\ndmesg\r\n```\r\n[    0.549985] Write protecting the kernel read-only data: 6144k\r\n[    0.551538] Freeing unused kernel memory: 360K (ffff8800013a6000 - ffff880001400000)\r\n[    0.553115] Freeing unused kernel memory: 448K (ffff880001590000 - ffff880001600000)\r\n[    0.572201] udevd[56]: starting version 175\r\n[    0.598119] SCSI subsystem initialized\r\n[    0.598199] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11\r\n[    0.609882] libata version 3.00 loaded.\r\n[    0.610258] ata_piix 0000:00:01.1: version 2.13\r\n[    0.611826] e1000: Intel(R) PRO/1000 Network Driver - version 7.3.21-k8-NAPI\r\n[    0.611828] e1000: Copyright (c) 1999-2006 Intel Corporation.\r\n[    0.615734] scsi0 : ata_piix\r\n[    0.616649] scsi1 : ata_piix\r\n[    0.616708] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc060 irq 14\r\n[    0.616710] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc068 irq 15\r\n[    0.617744] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 10\r\n[    0.630145] Floppy drive(s): fd0 is 1.44M\r\n[    0.645165] FDC 0 is a S82078B\r\n[    0.772555] ata2.01: NODEV after polling detection\r\n[    0.772857] ata2.00: ATAPI: QEMU DVD-ROM, 2.0.50, max UDMA/100\r\n[    0.773501] ata2.00: configured for MWDMA2\r\n[    0.774077] ata1.01: NODEV after polling detection\r\n[    0.774387] ata1.00: ATA-7: QEMU HARDDISK, 2.0.50, max UDMA/100\r\n[    0.774389] ata1.00: 20971520 sectors, multi 16: LBA48 \r\n[    0.774896] ata1.00: configured for MWDMA2\r\n[    0.775029] scsi 0:0:0:0: Direct-Access     ATA      QEMU HARDDISK    2.0. PQ: 0 ANSI: 5\r\n[    0.775699] scsi 1:0:0:0: CD-ROM            QEMU     QEMU DVD-ROM     2.0. PQ: 0 ANSI: 5\r\n[    0.972370] e1000 0000:00:03.0 eth0: (PCI:33MHz:32-bit) 00:0a:0a:0a:0a:99\r\n[    0.972376] e1000 0000:00:03.0 eth0: Intel(R) PRO/1000 Network Connection\r\n[    0.982074] sd 0:0:0:0: [sda] 20971520 512-byte logical blocks: (10.7 GB/10.0 GiB)\r\n[    0.982365] sd 0:0:0:0: [sda] Write Protect is off\r\n[    0.982369] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00\r\n[    0.982446] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA\r\n[    0.984519]  sda: sda1 sda2 < sda5 >\r\n[    0.985181] sr0: scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray\r\n[    0.985184] cdrom: Uniform CD-ROM driver Revision: 3.20\r\n[    0.985406] sd 0:0:0:0: [sda] Attached SCSI disk\r\n[    0.985839] sr 1:0:0:0: Attached scsi CD-ROM sr0\r\n[    0.987915] sd 0:0:0:0: Attached scsi generic sg0 type 0\r\n[    0.987968] sr 1:0:0:0: Attached scsi generic sg1 type 5\r\n[    1.138700] device-mapper: uevent: version 1.0.3\r\n[    1.138791] device-mapper: ioctl: 4.27.0-ioctl (2013-10-30) initialised: dm-devel@redhat.com\r\n[    1.143683] random: lvm urandom read with 27 bits of entropy available\r\n[    1.403140] PM: Starting manual resume from disk\r\n[    1.403146] PM: Hibernation image partition 254:1 present\r\n[    1.403148] PM: Looking for hibernation image.\r\n[    1.403780] PM: Image not found (code -22)\r\n[    1.403786] PM: Hibernation image not present or could not be loaded.\r\n[    1.452187] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)\r\n[    1.488213] tsc: Refined TSC clocksource calibration: 2400.108 MHz\r\n[    2.488699] Switched to clocksource tsc\r\n[    2.659946] udevd[333]: starting version 175\r\n[    2.869361] random: nonblocking pool is initialized\r\n[    3.220274] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input2\r\n[    3.220282] ACPI: Power Button [PWRF]\r\n[    3.232911] microcode: CPU0 sig=0x663, pf=0x1, revision=0x1\r\n[    3.254709] microcode: CPU1 sig=0x663, pf=0x1, revision=0x1\r\n[    3.254804] microcode: Microcode Update Driver: v2.00 <tigran@aivazian.fsnet.co.uk>, Peter Oruba\r\n[    3.381481] input: PC Speaker as /devices/platform/pcspkr/input/input3\r\n[    3.428682] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0\r\n[    3.455367] virtio-pci 0000:00:04.0: irq 40 for MSI/MSI-X\r\n[    3.455402] virtio-pci 0000:00:04.0: irq 41 for MSI/MSI-X\r\n[    3.456076] vmpi_test_init completed\r\n[    3.456081] vmpi_provider_register: Provider 1:0 registered\r\n[    3.456083] vmpi_init completed\r\n[    3.456354] virtio_mpi_probe completed\r\n[    3.566220] Error: Driver 'pcspkr' is already registered, aborting...\r\n[    3.603804] parport_pc 00:04: reported by Plug and Play ACPI\r\n[    3.604059] parport0: PC-style at 0x378, irq 7 [PCSPP,TRISTATE]\r\n[    4.454277] EXT4-fs (dm-0): re-mounted. Opts: (null)\r\n[    4.472046] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input4\r\n[    4.629714] EXT4-fs (dm-0): re-mounted. Opts: errors=remount-ro\r\n[    4.786751] loop: module loaded\r\n[    5.239018] Adding 471036k swap on /dev/mapper/vm1-swap_1.  Priority:-1 extents:1 across:471036k \r\n[    6.372304] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready\r\n[    6.698992] RPC: Registered named UNIX socket transport module.\r\n[    6.698996] RPC: Registered udp transport module.\r\n[    6.698998] RPC: Registered tcp transport module.\r\n[    6.699000] RPC: Registered tcp NFSv4.1 backchannel transport module.\r\n[    6.715252] FS-Cache: Loaded\r\n[    6.733493] FS-Cache: Netfs 'nfs' registered for caching\r\n[    6.804309] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).\r\n[    7.899852] Clocksource tsc unstable (delta = -411679622 ns)\r\n[    7.900059] Switched to clocksource hpet\r\n[    8.882120] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX\r\n[    8.882886] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready\r\n[  405.255544] rina-personality(INFO): Default personality set to 'default'\r\n[  405.281391] rina-ipcp-factories(INFO): Factory 'shim-hv' registered successfully\r\n[  405.281395] rina-shim-hv(INFO): Shim for Hypervisors support loaded\r\n[  405.288775] rina-ipcp-factories(INFO): Factory 'normal-ipc' registered successfully\r\n[  405.297143] rina-ps-factory(INFO): policy-set 'default' published successfully\r\n[  405.297146] rina-rina-default-plugin(INFO): RMT default policy set loaded successfully\r\n[  405.297147] rina-ps-factory(INFO): policy-set 'default' published successfully\r\n[  405.297149] rina-rina-default-plugin(INFO): DTP default policy set loaded successfully\r\n[  405.297150] rina-ps-factory(INFO): policy-set 'default' published successfully\r\n[  405.297152] rina-rina-default-plugin(INFO): DTCP default policy set loaded successfully\r\n[  411.113214] rina-kipcm(INFO): IPC Manager started. It is listening at NL port-id 1\r\n[  411.216993] rina-rnl-utils(ERR): Missing code in net/rina/rnl-utils.c:1265\r\n[  411.217507] rina-rnl-utils(ERR): Missing code in net/rina/rnl-utils.c:1323\r\n[  411.238192] rina-rnl-utils(ERR): Missing code in net/rina/rnl-utils.c:1265\r\n[  411.238667] rina-rnl-utils(ERR): Missing code in net/rina/rnl-utils.c:1323\r\n```"},"comment":{"url":"https://api.github.com/repos/IRATI/stack/issues/comments/88395315","html_url":"https://github.com/IRATI/stack/issues/523#issuecomment-88395315","issue_url":"https://api.github.com/repos/IRATI/stack/issues/523","id":88395315,"user":{"login":"edugrasa","id":325005,"avatar_url":"https://avatars.githubusercontent.com/u/325005?v=3","gravatar_id":"","url":"https://api.github.com/users/edugrasa","html_url":"https://github.com/edugrasa","followers_url":"https://api.github.com/users/edugrasa/followers","following_url":"https://api.github.com/users/edugrasa/following{/other_user}","gists_url":"https://api.github.com/users/edugrasa/gists{/gist_id}","starred_url":"https://api.github.com/users/edugrasa/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/edugrasa/subscriptions","organizations_url":"https://api.github.com/users/edugrasa/orgs","repos_url":"https://api.github.com/users/edugrasa/repos","events_url":"https://api.github.com/users/edugrasa/events{/privacy}","received_events_url":"https://api.github.com/users/edugrasa/received_events","type":"User","site_admin":false},"created_at":"2015-04-01T08:41:59Z","updated_at":"2015-04-01T08:41:59Z","body":"@vmaffione this issue should be closed after merging pull request https://github.com/IRATI/stack/pull/526\r\nRegardless of the fixes in there, it has to be taken into account that EFCP has to be properly configured with a correct value of Max PDU lifetime, otherwise it will not work well."}}