search

fp7-netide / Engine

App Engine to enable Network App programs to be executed, systematically tested, and refined on a variety of concrete SDN platforms
Eclipse Public License 1.0
10 stars 11 forks source link

LogPub do not send messages in the PUB queue #91

Closed KevinPhemius closed 8 years ago

KevinPhemius commented 8 years ago

We will keep the discussion here.

From what I gathered, the methods OnBackendMessage(Message message, String originId) and OnShimMessage(Message message, String originId) are not called when a new message arrives on the shim/backend.

When you build the LogPub module (with the tests) you can see that the method are called. When you run the demo, the methods are never called.

sergiotamu commented 8 years ago

If those methods are never called, the messages exchanged between the backends and the shim are never sent to the PUB queue on port 5557. One question, how do you know if those methods are called or not during the execution???

KevinPhemius commented 8 years ago

The logs should print that the messages are received.

Kévin

On Mon, Apr 11, 2016 at 3:02 AM -0700, "Sergio Tamurejo" notifications@github.com wrote:

If those methods are never called, the messages exchanged between the backends and the shim are never sent to the PUB queue on port 5557. One question, how do you know is those methods are called or not during the execution???

You are receiving this because you were assigned. Reply to this email directly or view it on GitHub: https://github.com/fp7-netide/Engine/issues/91#issuecomment-208265248

KevinPhemius commented 8 years ago

I have a lot of messages like this in the karaf logs :

2016-04-11 13:31:50,093 | INFO  | pool-9-thread-1  | CompositionManager               | 71 - core.caos - 1.1.0.SNAPSHOT | 510 seconds remaining for [Module [Name=fw,loaderIdentification=ryu-fw.py,CallCondition=null]] module(s) to connect...
2016-04-11 13:31:50,483 | INFO  | tor Receive Loop | ZeroMQBasedConnector             | 70 - core.connectivity - 1.1.0.SNAPSHOT | Data received from 'shim'.
2016-04-11 13:31:50,484 | INFO  | pool-7-thread-1  | CompositionManager               | 71 - core.caos - 1.1.0.SNAPSHOT | CompositionManager received message from shim: OpenFlowMessage [Header=MessageHeader [Version=VERSION_1_2,Type=OPENFLOW,Length=149,ModuleId=0,TransactionId=0,DatapathId=3],Type=PACKET_IN,OFMessage=OFPacketInVer13(xid=0, bufferId=424, totalLen=107, reason=NO_MATCH, tableId=0x0, cookie=0x0000000000000000, match=OFMatchV3Ver13(in_port=3), data=[51, 51, 0, 0, 0, -5, 86, 74, 5, 73, -21, 6, -122, -35, 96, 0, 0, 0, 0, 53, 17, -1, -2, -128, 0, 0, 0, 0, 0, 0, 84, 74, 5, -1, -2, 73, -21, 6, -1, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, -5, 20, -23, 20, -23, 0, 53, -110, 30, 0, 0, 0, 0, 0, 2, 0, 0, 0, 0, 0, 0, 5, 95, 105, 112, 112, 115, 4, 95, 116, 99, 112, 5, 108, 111, 99, 97, 108, 0, 0, 12, 0, 1, 4, 95, 105, 112, 112, -64, 18, 0, 12, 0, 1])]
2016-04-11 13:31:50,484 | ERROR | pool-7-thread-1  | CompositionManager               | 71 - core.caos - 1.1.0.SNAPSHOT | Could not handle incoming message due to configuration error No composition file loaded: OpenFlowMessage [Header=MessageHeader [Version=VERSION_1_2,Type=OPENFLOW,Length=149,ModuleId=0,TransactionId=0,DatapathId=3],Type=PACKET_IN,OFMessage=OFPacketInVer13(xid=0, bufferId=424, totalLen=107, reason=NO_MATCH, tableId=0x0, cookie=0x0000000000000000, match=OFMatchV3Ver13(in_port=3), data=[51, 51, 0, 0, 0, -5, 86, 74, 5, 73, -21, 6, -122, -35, 96, 0, 0, 0, 0, 53, 17, -1, -2, -128, 0, 0, 0, 0, 0, 0, 84, 74, 5, -1, -2, 73, -21, 6, -1, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, -5, 20, -23, 20, -23, 0, 53, -110, 30, 0, 0, 0, 0, 0, 2, 0, 0, 0, 0, 0, 0, 5, 95, 105, 112, 112, 115, 4, 95, 116, 99, 112, 5, 108, 111, 99, 97, 108, 0, 0, 12, 0, 1, 4, 95, 105, 112, 112, -64, 18, 0, 12, 0, 1])]

even though I loaded a composition file with 

netide:loadcomposition /home/user/NetIDE/Engine/core/specification/MinimalSpecification.xml
schwabe commented 8 years ago

Did you check for any errors/log message after loading the sepcification?

KevinPhemius commented 8 years ago

Still got errors

2016-04-11 13:36:26,453 | INFO  | tor Receive Loop | ZeroMQBasedConnector             | 70 - core.connectivity - 1.1.0.SNAPSHOT | Data received from 'shim'.
2016-04-11 13:36:26,453 | INFO  | pool-7-thread-10 | CompositionManager               | 71 - core.caos - 1.1.0.SNAPSHOT | CompositionManager received message from shim: OpenFlowMessage [Header=MessageHeader [Version=VERSION_1_2,Type=OPENFLOW,Length=8,ModuleId=0,TransactionId=0,DatapathId=4],Type=ECHO_REQUEST,OFMessage=OFEchoRequestVer13(xid=0, data=[])]
2016-04-11 13:36:26,454 | ERROR | pool-7-thread-10 | CompositionManager               | 71 - core.caos - 1.1.0.SNAPSHOT | Could not handle incoming message due to configuration error No composition file loaded: OpenFlowMessage [Header=MessageHeader [Version=VERSION_1_2,Type=OPENFLOW,Length=8,ModuleId=0,TransactionId=0,DatapathId=4],Type=ECHO_REQUEST,OFMessage=OFEchoRequestVer13(xid=0, data=[])]
2016-04-11 13:36:27,000 | INFO  | tor Receive Loop | ZeroMQBasedConnector             | 70 - core.connectivity - 1.1.0.SNAPSHOT | Data received from 'backend-ryu-8102'.
2016-04-11 13:36:27,001 | INFO  | tor Receive Loop | BackendManager                   | 70 - core.connectivity - 1.1.0.SNAPSHOT | Data received from backend 'backend-ryu-8102' with moduleId '878'.
2016-04-11 13:36:27,002 | INFO  | tor Receive Loop | BackendManager                   | 70 - core.connectivity - 1.1.0.SNAPSHOT | Received unrequested Message: 'Message [Header=MessageHeader [Version=VERSION_1_2,Type=HEARTBEAT,Length=0,ModuleId=878,TransactionId=0,DatapathId=0],Payload=[]]'. Relaying to shim.
2016-04-11 13:36:27,002 | INFO  | tor Receive Loop | ZeroMQBasedConnector             | 70 - core.connectivity - 1.1.0.SNAPSHOT | Sending to via relay to 'shim'.
2016-04-11 13:36:27,002 | INFO  | tor Receive Loop | ZeroMQBasedConnector             | 70 - core.connectivity - 1.1.0.SNAPSHOT | Sent.

The BackendManager should send the messages to the LogPub too, but it doesn't.

KevinPhemius commented 8 years ago

I had this message

` 2016-04-11 13:31:32,361 | INFO | l for user karaf | ManagementHandler | 73 - core.management - 1.1.0.SNAPSHOT | Set 'compositionSpecification' on 'eu.netide.core.caos' to value '<?xml version="1.0" encoding="utf-8"?>

' ` But no other errors related to the composition.
schwabe commented 8 years ago

That does not look like a composition file. It should print the contents of your xml file. Can you double the pathname you are providing?

KevinPhemius commented 8 years ago

It's the MinimalComposition.xml file in Engine/core/specification/

schwabe commented 8 years ago 
netide-core>netide:loadcomposition /Users/arne/software/netide-engine/core/specification/MinimalSpecification.xml

and the log says

2016-04-11 14:05:44,788 | INFO  | rint Extender: 1 | CompositionManager               | 71 - core.caos - 1.1.0.SNAPSHOT | Accepted new CompositionSpecification '<?xml version="1.0" encoding="utf-8"?>
<CompositionSpecification  xmlns="http://netide.eu/schemas/compositionspecification/v1">
  <Modules>
    <Module id="fw" loaderIdentification="ryu-fw.py"/>
  </Modules>
</CompositionSpecification>'.
2016-04-11 14:05:44,789 | INFO  | rint Extender: 1 | CompositionManager               | 71 - core.caos - 1.1.0.SNAPSHOT | Set composition finished.
2016-04-11 14:05:44,789 | INFO  | pool-10-thread-1 | CompositionManager               | 71 - core.caos - 1.1.0.SNAPSHOT | Waiting for required modules to connect, [Module [Name=fw,loaderIdentification=ryu-fw.py,CallCondition=null]] left...
KevinPhemius commented 8 years ago

I loaded another specification:

2016-04-11 14:11:10,665 | INFO | l for user karaf | ManagementHandler | 73 - core.management - 1.1.0.SNAPSHOT | Set 'compositionSpecification' on 'eu.netide.core.caos' to value '<?xml version="1.0" encoding="utf-8"?>

' 2016-04-11 14:11:10,833 | INFO | rint Extender: 2 | CompositionManager | 71 - core.caos - 1.1.0.SNAPSHOT | ShimManager set. 2016-04-11 14:11:10,834 | INFO | rint Extender: 2 | CompositionManager | 71 - core.caos - 1.1.0.SNAPSHOT | BackendManager set. 2016-04-11 14:11:11,037 | INFO | rint Extender: 2 | CompositionManager | 71 - core.caos - 1.1.0.SNAPSHOT | Accepted new CompositionSpecification ' '. 2016-04-11 14:11:11,038 | INFO | rint Extender: 2 | CompositionManager | 71 - core.caos - 1.1.0.SNAPSHOT | Set composition finished. 2016-04-11 14:11:11,038 | INFO | rint Extender: 2 | CompositionManager | 71 - core.caos - 1.1.0.SNAPSHOT | Unsupported message bypass activated. 2016-04-11 14:11:11,046 | INFO | pool-15-thread-1 | CompositionManager | 71 - core.caos - 1.1.0.SNAPSHOT | Waiting for required modules to connect, [Module [Name=fw,loaderIdentification=ryu-fw.py,CallCondition=null], Module [Name=appA,loaderIdentification=appA.py,CallCondition=null], Module [Name=appB,loaderIdentification=appB.py,CallCondition=null], Module [Name=lb,loaderIdentification=loadbalancer.jar,CallCondition=CallCondition [Events=[PACKET_IN],IN_PORT=-1,ETH_TYPE=UNDEFINED,ETH_SRC=UNDEFINED,ETH_DST=UNDEFINED,IP_PROTO=HOPOPT,IPV4_SRC=UNDEFINED,IPV4_DST=UNDEFINED,IPV6_SRCUNDEFINED,IPV6_DST=UNDEFINED,TCP_SRC=-1,TCP_DST=-1,UDP_SRC=-1,UDP_DST=-1]], Module [Name=log,loaderIdentification=logger.py,CallCondition=null]] left... 2016-04-11 14:11:11,274 | INFO | tor Receive Loop | ZeroMQBasedConnector | 70 - core.connectivity - 1.1.0.SNAPSHOT | Data received from 'shim'.
sergiotamu commented 8 years ago

@KevinPhemius which applications are you running?? a Firewall + a SimpleSwitch application??.

KevinPhemius commented 8 years ago

So here is the setup:

  1. Launch the core with bin/karaf clean
  2. Add the netide repo
  3. feature install core
  4. load specification with netide:loadcomposition
  5. Launch the ryu shim
  6. Launch mininet
  7. Launch the ryu backend (with firewall and L2 switch)

The composition is correctly loaded (I see the printed xml content) bu I still have the error that no composition is loaded. I think it's because of this error

2016-04-11 14:22:30,460 | ERROR | pool-7-thread-2  | CompositionManager               | 71 - core.caos - 1.1.0.SNAPSHOT | An exception occurred while handling shim message.
java.util.NoSuchElementException: No value present
    at java.util.Optional.get(Optional.java:135)[:1.8.0_45-internal]
    at eu.netide.core.connectivity.BackendManager.getModuleId(BackendManager.java:156)[70:core.connectivity:1.1.0.SNAPSHOT]
    at Proxyb7e0973e_262d_4f13_9b37_006d81d1017b.getModuleId(Unknown Source)[:]
    at Proxy3e6f53b1_b12a_4572_943f_506ce202aa41.getModuleId(Unknown Source)[:]
    at eu.netide.core.caos.CompositionManager.OnShimMessage(CompositionManager.java:130)[71:core.caos:1.1.0.SNAPSHOT]
    at Proxy163a2566_c83d_4035_bbcf_651db2955aa4.OnShimMessage(Unknown Source)[:]
    at Proxya341d72d_dcba_4d4b_b519_cbc1526bcf97.OnShimMessage(Unknown Source)[:]
    at eu.netide.core.connectivity.ShimManager.lambda$OnDataReceived$0(ShimManager.java:68)[70:core.connectivity:1.1.0.SNAPSHOT]
    at eu.netide.core.connectivity.ShimManager$$Lambda$20/422785079.run(Unknown Source)[70:core.connectivity:1.1.0.SNAPSHOT]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_45-internal]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_45-internal]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_45-internal]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_45-internal]
    at java.lang.Thread.run(Thread.java:745)[:1.8.0_45-internal]
KevinPhemius commented 8 years ago 
netide-core>netide:listmodules 
   Id                 Name              Backend Last message (s ago)
   40             Firewall     backend-ryu-9749                    -
  555         SimpleSwitch     backend-ryu-9749                    -
  895     backend-ryu-9749     backend-ryu-9749                 0.42
    -                 shim                    -                 0.40
ElisaRojas commented 8 years ago

Hi @KevinPhemius , for the SW+FW you should use this file: https://github.com/fp7-netide/Engine/blob/master/core/specification/DpidPartitionABCW.xml

KevinPhemius commented 8 years ago

Thank you @ElisaRojas , the backend and shim are connected. Still the On[Shim|Backend]Message() methods of the LogPub aren't called.

schwabe commented 8 years ago

The reason is very simple. I cannot find anywhere in the code that you actually register as a listener for the Shim or Backend message:

Compare with the blueprint.xml of caos:

    <service ref="compositionManager"
             interface="eu.netide.core.api.IShimMessageListener"/>

Your logpub module seem to be missing that code.

KevinPhemius commented 8 years ago

I added this in the blueprint

<pre>
<service ref="logpub"
              interface="eu.netide.core.api.IShimMessageListener"/>
     <service ref="logpub"
              interface="eu.netide.core.api.IBackendMessageListener"/
</pre>

it was in the previous version but was squashed during a commit.

sergiotamu commented 8 years ago

Hello @KevinPhemius ,

I cannot see anything, what did you add??

KevinPhemius commented 8 years ago

Had some network problems. Just pushed it now.

schwabe commented 8 years ago

@KevinPhemius if that fixes the problem (it looks good when looking with a debuger at the core in IntelliJ) just close the issue.

KevinPhemius commented 8 years ago

It doesn't fix the issue. I fix the shimManager and backendManager in the LogPub code. The log shows that they are set. But still no messages seen by the LogPub.

schwabe commented 8 years ago

It does for me. Adding breakpoints on OnBackendMessage and OnShimMessage in the LogPub shows me that they are called. Can you try the same in your configuration? (If you have an IDE setup). Or if you have no IDE with debug capabilities add log messages in that methods.

KevinPhemius commented 8 years ago

I added the log messages, rebuilt the logpub bundle and relaunched everything but it doesn't show anything. @sergiotamu does it work for you?

edit: my karaf didn't print DEBUG logs. The method are indeed called.

schwabe commented 8 years ago

@KevinPhemius that is why I prefer breakpoints. I am closing the issue since that part is at least working

sergiotamu commented 8 years ago

Hello @KevinPhemius and @schwabe,

Yes, For me it is also working! =)

Best Regards, Sergio.

KevinPhemius commented 8 years ago

@sergiotamu you have messages in the PUB queue from the LogPub?

sergiotamu commented 8 years ago

Yes, I have messages in PUB queue, because the logger now is able to print messages into a console.