{"action":"opened","issue":{"url":"https://api.github.com/repos/IRATI/stack/issues/512","labels_url":"https://api.github.com/repos/IRATI/stack/issues/512/labels{/name}","comments_url":"https://api.github.com/repos/IRATI/stack/issues/512/comments","events_url":"https://api.github.com/repos/IRATI/stack/issues/512/events","html_url":"https://github.com/IRATI/stack/issues/512","id":64738851,"number":512,"title":"Enrollment fails after trying to enroll the IPCP with itself, then doing a correct enrollment","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":0,"created_at":"2015-03-27T10:56:18Z","updated_at":"2015-03-27T10:56:18Z","closed_at":null,"body":"Normal over shim-eth-vlan\r\n1) Enroll the IPCP with itself\r\n2) Enroll the IPCP with another IPCP in the DIF --> IPCP crashes\r\n\r\nm.test.pristine.wall1.ilabt.iminds.be\r\n---\r\n\r\nipcm.log\r\n```\r\n3849(1427453546)#netlink-manager (INFO): Netlink socket connected to local port 1 \r\n3849(1427453546)#ipcm (INFO)[create_ipcp]: IPC process test-eth:1:: created [id = 1]\r\n\r\n3849(1427453546)#ipcm (INFO)[assign_to_dif]: Requested DIF assignment of IPC process test-eth:1:: to DIF 300:::\r\n\r\n3849(1427453546)#ipcm.ipcp (INFO)[assign_to_dif_response_event_handler]: DIF assignment operation completed for IPC process test-eth:1:: [success=1]\r\n\r\n3849(1427453546)#ipcm (INFO)[create_ipcp]: IPC process test1.IRATI:1:: created and waiting for initialization[id = 2]\r\n\r\n3849(1427453546)#ipcm.ipcp (INFO)[ipc_process_daemon_initialized_event_handler]: IPC process daemon initialized [id = 2]\r\n\r\n3849(1427453546)#ipcm (INFO)[assign_to_dif]: Requested DIF assignment of IPC process test1.IRATI:1:: to DIF normal.DIF:::\r\n\r\n3849(1427453546)#ipcm.ipcp (INFO)[assign_to_dif_response_event_handler]: DIF assignment operation completed for IPC process test1.IRATI:1:: [success=1]\r\n\r\n3849(1427453546)#ipcm (INFO)[register_at_dif]: Requested DIF registration of IPC process test1.IRATI:1:: at DIF 300::: through IPC process test-eth:1::\r\n\r\n3849(1427453546)#ipcm.ipcp (INFO)[ipcm_register_response_ipcp]: IPC process test1.IRATI:1:: informed about its registration to N-1 DIF 300:::\r\n\r\n3849(1427453578)#ipcm (INFO)[enroll_to_dif]: Requested enrollment of IPC process test1.IRATI:1:: to DIF normal.DIF::: through DIF 300::: and neighbor IPC process test1.IRATI:1::\r\n\r\n3849(1427453578)#ipcm.flow-alloc (INFO)[flow_allocation_requested_local]: IPC process test-eth:1:: requested to allocate flow between test1.IRATI:1:: and test1.IRATI:1::\r\n\r\n3849(1427453578)#ipcm.flow-alloc (INFO)[ipcm_allocate_flow_request_result_handler]: Informing IPC process test-eth:1:: about flow allocation from application test1.IRATI:1:: to application test1.IRATI:1:: in DIF 300::: [success = 1, port-id = 1]\r\n\r\n3849(1427453578)#ipcm.flow-alloc (INFO)[ipcm_allocate_flow_request_result_handler]: Applications test1.IRATI:1:: and test1.IRATI:1:: informed about flow allocation result\r\n\r\n3849(1427453588)#ipcm.flow-alloc (INFO)[deallocate_flow]: Application test1.IRATI:1:: asks IPC process test-eth:1:: to deallocate flow [port-id = 1]\r\n\r\n3849(1427453588)#ipcm.ipcp (ERR)[enroll_to_dif_response_event_handler]: : Error: Enrollment operation of process test1.IRATI:1:: failed\r\n\r\n3849(1427453594)#ipcm (INFO)[enroll_to_dif]: Requested enrollment of IPC process test1.IRATI:1:: to DIF normal.DIF::: through DIF 300::: and neighbor IPC process test2.IRATI:1::\r\n\r\n```\r\n\r\ntest1.IRATI-1.log\r\n```\r\n3853(1427453546)#netlink-manager (INFO): Netlink socket connected to local port 3853 \r\n3853(1427453546)#ipc-process (INFO): Librina initialized\r\n3853(1427453546)#ipc-process (INFO): Pluggable component 'security-manager'/'default' [default] published\r\n3853(1427453546)#ipc-process (INFO): Pluggable component 'flow-allocator'/'default' [default] published\r\n3853(1427453546)#ipc-process (INFO): Pluggable component 'namespace-manager'/'default' [default] published\r\n3853(1427453546)#ipc-process (INFO): Pluggable component 'resource-allocator'/'default' [default] published\r\n3853(1427453546)#ipc-process (INFO): Pluggable component 'routing'/'link-state' [default] published\r\n3853(1427453546)#ipc-process (INFO): Plugin default loaded successfully\r\n3853(1427453546)#rib-daemon (INFO): EventListener subscribed to event 5_N_MINUS_1_FLOW_ALLOCATED\r\n3853(1427453546)#rib-daemon (INFO): EventListener subscribed to event 7_N_MINUS_1_FLOW_DEALLOCATED\r\n3853(1427453546)#rib (INFO): Object with name /daf/management/neighbors, class neighbor set, instance 1 added to the RIB\r\n3853(1427453546)#rib (INFO): Object with name /daf/management/enrollment, class enrollment information, instance 2 added to the RIB\r\n3853(1427453546)#rib (INFO): Object with name /daf/management/operationalStatus, class operationstatus, instance 3 added to the RIB\r\n3853(1427453546)#rib (INFO): Object with name /daf/management/naming/address, class address, instance 4 added to the RIB\r\n3853(1427453546)#rib-daemon (INFO): EventListener subscribed to event 7_N_MINUS_1_FLOW_DEALLOCATED\r\n3853(1427453546)#rib-daemon (INFO): EventListener subscribed to event 5_N_MINUS_1_FLOW_ALLOCATED\r\n3853(1427453546)#rib-daemon (INFO): EventListener subscribed to event 6_N_MINUS_1_FLOW_ALLOCATION_FAILED\r\n3853(1427453546)#rib-daemon (INFO): EventListener subscribed to event 8_NEIGHBOR_DECLARED_DEAD\r\n3853(1427453546)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/difregistrations, class DIF registration set, instance 5 added to the RIB\r\n3853(1427453546)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/nminusoneflows, class nminusone flow set, instance 6 added to the RIB\r\n3853(1427453546)#rib-daemon (INFO): EventListener subscribed to event 0_CONNECTIVITY_TO_NEIGHBOR_LOST\r\n3853(1427453546)#rib (INFO): Object with name /dif/management/flowallocator/directoryforwardingtableentries, class directoryforwardingtableentry set, instance 7 added to the RIB\r\n3853(1427453546)#rib (INFO): Object with name /daf/management/naming/whatevercastnames, class whatname set, instance 8 added to the RIB\r\n3853(1427453546)#rib (INFO): Object with name /dif/resourceallocation/flowallocator/flows, class flow set, instance 9 added to the RIB\r\n3853(1427453546)#rib-daemon (INFO): Starting Management SDU reader ...\r\n3853(1427453546)#rib (INFO): Object with name /dif/management/flowallocator/qoscubes, class qoscube set, instance 10 added to the RIB\r\n3853(1427453546)#rib (INFO): Object with name /dif/ipc/datatransfer/constants, class datatransfercons, instance 11 added to the RIB\r\n3853(1427453546)#ipcp-components (INFO): Policy-set default selected for component security-manager\r\n3853(1427453546)#ipcp-components (INFO): Policy-set default selected for component flow-allocator\r\n3853(1427453546)#ipcp-components (INFO): Policy-set default selected for component namespace-manager\r\n3853(1427453546)#ipcp-components (INFO): Policy-set default selected for component resource-allocator\r\n3853(1427453546)#ipcp-components (INFO): Policy-set link-state selected for component routing\r\n3853(1427453546)#ipc-process (INFO): Initialized IPC Process with name: test1.IRATI, instance 1, id 2 \r\n3853(1427453546)#ipcp-main (INFO): IPC Process name:     test1.IRATI\r\n3853(1427453546)#ipcp-main (INFO): IPC Process instance: 1\r\n3853(1427453546)#ipcp-main (INFO): IPC Process id:       2\r\n3853(1427453546)#ipcp-main (INFO): IPC Manager port:     1\r\n3853(1427453546)#ipcp-main (INFO): IPC Process initialized, executing event loop...\r\n3853(1427453546)#rib (INFO): Object with name /dif/management/pduforwardingtable/linkstate/flowstateobjectgroup, class flowstateobject set, instance 12 added to the RIB\r\n3853(1427453546)#rib-daemon (INFO): EventListener subscribed to event 7_N_MINUS_1_FLOW_DEALLOCATED\r\n3853(1427453546)#rib-daemon (INFO): EventListener subscribed to event 5_N_MINUS_1_FLOW_ALLOCATED\r\n3853(1427453546)#rib-daemon (INFO): EventListener subscribed to event 9_NEIGHBOR_ADDED\r\n3853(1427453546)#rib-daemon (INFO): EventListener subscribed to event 0_CONNECTIVITY_TO_NEIGHBOR_LOST\r\n3853(1427453546)#rib (INFO): Object with name /dif/management/flowallocator/qoscubes/reliable, class qoscube, instance 13 added to the RIB\r\n3853(1427453546)#rib (INFO): Object with name /dif/management/flowallocator/qoscubes/unreliable, class qoscube, instance 14 added to the RIB\r\n3853(1427453546)#rib (INFO): Object with name /difmanagement/watchdog, class watchdog timer, instance 15 added to the RIB\r\n3853(1427453546)#resource-allocator (INFO): IPC Process registered to N-1 DIF 300\r\n3853(1427453546)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/difregistrations/300, class DIF registration, instance 16 added to the RIB\r\n3853(1427453578)#resource-allocator (INFO): Requested the allocation of N-1 flow to application test1.IRATI-1 through DIF 300\r\n3853(1427453578)#rib (INFO): Object with name /dif/resourceallocation/nminusoneflowmanager/nminusoneflows/1, class nminusone flow, instance 17 added to the RIB\r\n3853(1427453578)#rib-daemon (INFO): Event 5_N_MINUS_1_FLOW_ALLOCATED has just happened. Notifying event listeners.\r\n3853(1427453588)#enrollment-task (ERR): An error happened during enrollment of remote IPC Process test1.IRATI-1-- because of Timeout waiting for connect response\r\n3853(1427453588)#enrollment-task (ERR): Problems closing application connection: Cannot close a connection because this CDAP session is currently in 1 state\r\n3853(1427453594)#resource-allocator (INFO): Requested the allocation of N-1 flow to application test2.IRATI-1 through DIF 300\r\n```\r\n\r\ndmesg\r\n```\r\n[ 1239.567761] rina-rnl-utils(DBG): msg at ffff8801b7c25fc0 / msg->attrs at ffff8801b8cbce20\r\n[ 1239.567763] rina-rnl-utils(DBG):   src-ipc-id: 2\r\n[ 1239.567765] rina-rnl-utils(DBG):   dst-ipc-id: 1\r\n[ 1239.567768] rina-ipcp-utils(DBG): Name at ffff8801b7e1c8c0 finalized successfully\r\n[ 1239.567773] rina-ipcp-utils(DBG): Name at ffff8801b7f8c260 finalized successfully\r\n[ 1239.567776] rina-ipcp-utils(DBG): Name at ffff88003743f660 finalized successfully\r\n[ 1239.567781] rina-pidm(DBG): The pidm bitmap find returned id 0 (bad = -1)\r\n[ 1239.567783] rina-pidm(DBG): Bitmap allocation completed successfully (id = 0)\r\n[ 1239.567787] rina-ipcp-utils(DBG): No flags, name comparison will be meaningless ...\r\n[ 1239.567794] rina-rfifo(DBG): FIFO ffff880036ea1b40 created successfully\r\n[ 1239.567797] rina-arp826-arm(DBG): Adding new resolution to the ongoing list\r\n[ 1239.567799] rina-arp826-rxtx(DBG): Sending ARP request\r\n[ 1239.567802] rina-arp826-rxtx(DBG): Growing addresses to 15\r\n[ 1239.567806] rina-arp826-utils(DBG): GPA ffff880036ea1ac0 (15): 0x74657374312E49524154492F312F2F\r\n[ 1239.567808] rina-arp826-utils(DBG): No needs to grow the GPA\r\n[ 1239.567812] rina-arp826-utils(DBG): GPA ffff880036ea19c0 (15): 0x74657374312E49524154492F312F2F\r\n[ 1239.567814] rina-arp826-utils(DBG): No needs to grow the GPA\r\n[ 1239.567816] rina-arp826-rxtx(DBG): Creating an ARP packet\r\n[ 1239.567824] rina-arp826-rxtx(DBG): ARP packet sent successfully\r\n[ 1239.567826] rina-ipcp-utils(DBG): Name at ffff8801b7e1c8c0 finalized successfully\r\n[ 1239.567828] rina-ipcp-utils(DBG): Name at ffff8801b7e1c8c0 destroyed successfully\r\n[ 1239.567830] rina-ipcp-utils(DBG): Name at ffff8801b7f8c260 finalized successfully\r\n[ 1239.567832] rina-ipcp-utils(DBG): Name at ffff8801b7f8c260 destroyed successfully\r\n[ 1239.567834] rina-ipcp-utils(DBG): Name at ffff88003743f660 finalized successfully\r\n[ 1239.567836] rina-ipcp-utils(DBG): Name at ffff88003743f660 destroyed successfully\r\n[ 1239.567838] rina-rnl(DBG): Message 11 handled successfully\r\n[ 1239.568106] rina-arp826-rxtx(DBG): Processing ARP skb ffff880336991b00\r\n[ 1239.568116] rina-arp826-rxtx(DBG): Decoded ARP header:\r\n[ 1239.568118] rina-arp826-rxtx(DBG):   Hardware type           = 0x0001\r\n[ 1239.568120] rina-arp826-rxtx(DBG):   Protocol type           = 0xD1F0\r\n[ 1239.568122] rina-arp826-rxtx(DBG):   Hardware address length = 6\r\n[ 1239.568124] rina-arp826-rxtx(DBG):   Protocol address length = 15\r\n[ 1239.568126] rina-arp826-rxtx(DBG):   Operation               = 0x0002\r\n[ 1239.568128] rina-arp826-rxtx(DBG): We can handle this ARP\r\n[ 1239.568129] rina-arp826-rxtx(DBG): Fetching addresses\r\n[ 1239.568133] rina-arp826-rxtx(DBG): Shrinking as needed\r\n[ 1239.568138] rina-arp826-utils(DBG): GPA ffff88033efbaa20 (15): 0x74657374312E49524154492F312F2F\r\n[ 1239.568140] rina-arp826-utils(DBG): Looking for filler 0x00 in GPA (length = 15)\r\n[ 1239.568142] rina-arp826-utils(DBG): GPA doesn't need to be shrinked ...\r\n[ 1239.568146] rina-arp826-utils(DBG): GPA ffff88033efba680 (15): 0x74657374312E49524154492F312F2F\r\n[ 1239.568148] rina-arp826-utils(DBG): Looking for filler 0x00 in GPA (length = 15)\r\n[ 1239.568150] rina-arp826-utils(DBG): GPA doesn't need to be shrinked ...\r\n[ 1239.568155] rina-rwq(DBG): Work posted on workqueue ffff8803372d7800, please wait ...\r\n[ 1239.568157] rina-arp826-rxtx(DBG): Resolution in progress, please wait ...\r\n[ 1239.568159] rina-arp826-rxtx(DBG): Processing completed successfully\r\n[ 1239.568207] rina-arp826-arm(DBG): In the resolver, looking for handler\r\n[ 1239.568216] rina-arp826-arm(DBG): Gonna browse the list of resolutions now\r\n[ 1239.568223] rina-arp826-arm(DBG): Next entry of the resolutions list\r\n[ 1239.568229] rina-arp826-arm(DBG): Dumping a->sha\r\n[ 1239.568237] rina-arp826-utils(DBG): GHA ffff880036ea1d40: A5:0D:30:90:25:00\r\n[ 1239.568246] rina-arp826-utils(DBG): GHA ffff88033efbab00: A5:0D:30:90:25:00\r\n[ 1239.568249] rina-arp826-arm(DBG): Dumping a->tpa\r\n[ 1239.568254] rina-arp826-utils(DBG): GPA ffff880036ea19a0 (15): 0x74657374312E49524154492F312F2F\r\n[ 1239.568259] rina-arp826-utils(DBG): GPA ffff88033efbaa20 (15): 0x74657374312E49524154492F312F2F\r\n[ 1239.568261] rina-arp826-arm(DBG): Dumping a->spa\r\n[ 1239.568265] rina-arp826-utils(DBG): GPA ffff880036ea1ae0 (15): 0x74657374312E49524154492F312F2F\r\n[ 1239.568269] rina-arp826-utils(DBG): GPA ffff88033efba680 (15): 0x74657374312E49524154492F312F2F\r\n[ 1239.568271] rina-arp826-arm(DBG): Dumping ptype\r\n[ 1239.568273] rina-arp826-arm(DBG): Found an equal resolution\r\n[ 1239.568274] rina-arp826-arm(DBG): Calling the notifier hook\r\n[ 1239.568276] rina-shim-eth-vlan(DBG): Entered the ARP resolve handler of the shim-eth\r\n[ 1239.568284] rina-rfifo(DBG): FIFO ffff880338901800 created successfully\r\n[ 1239.568287] rina-rmt(DBG): N-1 port ffff880337b084c0 created successfully (port-id = 1)\r\n[ 1239.568289] rina-rmt(DBG): Added send queue to rmt instance ffff880338a95300 for port-id 1\r\n[ 1239.568294] rina-rfifo(DBG): FIFO ffff8803373dc380 created successfully\r\n[ 1239.568296] rina-rmt(DBG): N-1 port ffff880337b08a40 created successfully (port-id = 1)\r\n[ 1239.568298] rina-rmt(DBG): Added receive queue to rmt instance ffff880338a95300 for port-id 1\r\n[ 1239.568301] rina-rfifo(DBG): FIFO ffff880036ea1b40 destroyed successfully\r\n[ 1239.568308] rina-rnl-utils(DBG): Result of genlmesg_end: 40\r\n[ 1239.568311] rina-rnl-utils(DBG): Going to send NL unicast message (type = 13, seq-num 5, port = 1)\r\n[ 1239.568322] rina-rnl-utils(DBG): Unicast NL message sent (type = 13, seq-num 5, port = 1)\r\n[ 1239.568324] rina-arp826-arm(DBG): Notifier called, disposing the leftovers\r\n[ 1239.568327] rina-arp826-arm(DBG): Leaving this resolver function\r\n[ 1239.569022] rina-syscalls(DBG): Syscall write management SDU (size = 102, ipcp-id = 2, port-id = 1)\r\n[ 1239.569028] rina-syscalls(DBG): Handling personality hook mgmt_sdu_write\r\n[ 1239.569031] rina-syscalls(DBG): Calling personality hook mgmt_sdu_write\r\n[ 1239.569033] rina-personality-default(DBG): Calling wrapped function\r\n[ 1239.569037] rina-normal-ipc(DBG): Passing SDU to be written to N-1 port 1 from IPC Process 2\r\n[ 1239.569042] rina-serdes(DBG): Serialized version 1, with size 1\r\n[ 1239.569046] rina-rmt(DBG): Gonna send SDU to port-id 1\r\n[ 1239.569048] rina-shim-eth-vlan(DBG): Entered the sdu-write\r\n[ 1239.569056] rina-shim-eth-vlan(DBG): Packet sent\r\n[ 1239.569057] rina-rmt(DBG): Sent and enabling port\r\n[ 1250.091291] rina-rnl(DBG): Dispatching message (skb-in=ffff8801b92e3600, info=ffff8801b84abaf0, attrs=ffff8801b89f1b00)\r\n[ 1250.091295] rina-rnl(DBG): Multiplexing message type 15\r\n[ 1250.091297] rina-rnl(DBG): Fetching handler callback and data\r\n[ 1250.091300] rina-rnl(DBG): Gonna call ffffffffa0407920(ffff880338e442c0, ffff8801b92e3600, ffff8801b84abaf0)\r\n[ 1250.091303] rina-rnl-utils(DBG): RINA Netlink parser started ...\r\n[ 1250.091305] rina-rnl-utils(DBG): msg at ffff8801b7c25140 / msg->attrs at ffff8801b7e1c900\r\n[ 1250.091307] rina-rnl-utils(DBG):   src-ipc-id: 0\r\n[ 1250.091309] rina-rnl-utils(DBG):   dst-ipc-id: 1\r\n[ 1250.091313] rina-rmt(DBG): Destroying N-1 port ffff880337b084c0 (port-id = 1)\r\n[ 1250.091316] rina-rfifo(DBG): FIFO ffff880338901800 destroyed successfully\r\n[ 1250.091319] rina-rmt(DBG): Destroying N-1 port ffff880337b08a40 (port-id = 1)\r\n[ 1250.091322] rina-rfifo(DBG): FIFO ffff8803373dc380 destroyed successfully\r\n[ 1250.091325] rina-pidm(DBG): Bitmap release completed successfully (port_id: 1)\r\n[ 1250.091332] rina-rnl-utils(DBG): Result of genlmesg_end: 32\r\n[ 1250.091334] rina-rnl-utils(DBG): Going to send NL unicast message (type = 16, seq-num 6, port = 1)\r\n[ 1250.091338] rina-rnl-utils(DBG): Unicast NL message sent (type = 16, seq-num 6, port = 1)\r\n[ 1250.091340] rina-rnl(DBG): Message 15 handled successfully\r\n```\r\n"}}