Intents in FAILED state (Optical Test)

When adding host or point intents, the intent state goes to FAILED state immediately. Here is the log when point intents are added:

2015-06-02 13:22:51,502 | INFO | h for user karaf | command | 131 - org.apache.karaf.log.command - 3.0.3 | Sending CLI command: 'add-point-intent of:0000ffffffff0001/1 of:0000ffffffff0005/1'
2015-06-02 13:22:51,683 | INFO | event-dispatch-0 | OpticalPathProvisioner | 174 - org.onosproject.onos-app-optical - 1.2.0.SNAPSHOT | Intent PointToPointIntent{id=0x0, key=0x0, appId=DefaultApplicationId

{id=2, name=org.onosproject.cli}, priority=100, resources=[], selector=DefaultTrafficSelector{criteria=[ETH_TYPE{ethType=800}]}, treatment=DefaultTrafficTreatment{immediate=[], deferred=[], transition=None, cleared=false, metadata=null}, ingress=ConnectPoint{elementId=of:0000ffffffff0001, portNumber=1}, egress=ConnectPoint{elementId=of:0000ffffffff0005, portNumber=1}, constraints=[LinkTypeConstraint{inclusive=false, types=[OPTICAL]}]} failed, calling optical path provisioning app.
2015-06-02 13:22:52,024 | INFO | ew I/O worker #5 | LinkManager | 77 - org.onosproject.onos-core-net - 1.2.0.SNAPSHOT | Link DefaultLinkDescription{src=ConnectPoint{elementId=of:0000ffffffff0001, portNumber=2}, dst=ConnectPoint{elementId=of:0000ffffffff0005, portNumber=3}, type=DIRECT} detected
2015-06-02 13:22:52,036 | INFO | nos-topo-build-7 | TopologyManager | 77 - org.onosproject.onos-core-net - 1.2.0.SNAPSHOT | Topology DefaultTopology{time=1833005828810, creationTime=1433265772035, computeCost=795956, clusters=1, devices=16, links=47} changed
2015-06-02 13:23:01,966 | INFO | h for user karaf | command | 131 - org.apache.karaf.log.command - 3.0.3 | Sending CLI command: 'add-point-intent of:0000ffffffff0005/1 of:0000ffffffff0001/1'
2015-06-02 13:23:02,128 | INFO | event-dispatch-0 | OpticalPathProvisioner | 174 - org.onosproject.onos-app-optical - 1.2.0.SNAPSHOT | Intent PointToPointIntent{id=0x6, key=0x6, appId=DefaultApplicationId{id=2, name=org.onosproject.cli}

, priority=100, resources=[], selector=DefaultTrafficSelector{criteria=[ETH_TYPE

{ethType=800}]}, treatment=DefaultTrafficTreatment{immediate=[], deferred=[], transition=None, cleared=false, metadata=null}, ingress=ConnectPoint{elementId=of:0000ffffffff0005, portNumber=1}, egress=ConnectPoint{elementId=of:0000ffffffff0001, portNumber=1}, constraints=[LinkTypeConstraint{inclusive=false, types=[OPTICAL]}]} failed, calling optical path provisioning app.
2015-06-02 13:23:02,143 | ERROR | -intent-worker-4 | ConsistentDeviceResourceStore | 79 - org.onosproject.onos-core-dist - 1.2.0.SNAPSHOT | Exception thrown, rolling back
java.lang.Exception: Port already allocated OchPort{element=of:0000ffffffffff09, number=11, isEnabled=true, type=OCH, signalType=ODU4, isTunable=true, lambda=OchSignal{gridType=DWDM, channelSpacing=CHL_100GHZ, spacingMultiplier=1, slotGranularity=1}}
at org.onosproject.store.resource.impl.ConsistentDeviceResourceStore.allocatePorts(ConsistentDeviceResourceStore.java:131)[79:org.onosproject.onos-core-dist:1.2.0.SNAPSHOT]
at org.onosproject.net.resource.impl.DeviceResourceManager.requestPorts(DeviceResourceManager.java:62)[77:org.onosproject.onos-core-net:1.2.0.SNAPSHOT]
at org.onosproject.net.intent.impl.compiler.OpticalConnectivityIntentCompiler.compile(OpticalConnectivityIntentCompiler.java:117)[77:org.onosproject.onos-core-net:1.2.0.SNAPSHOT]
at org.onosproject.net.intent.impl.compiler.OpticalConnectivityIntentCompiler.compile(OpticalConnectivityIntentCompiler.java:69)[77:org.onosproject.onos-core-net:1.2.0.SNAPSHOT]
at org.onosproject.net.intent.impl.CompilerRegistry.compile(CompilerRegistry.java:82)[77:org.onosproject.onos-core-net:1.2.0.SNAPSHOT]
at org.onosproject.net.intent.impl.IntentManager$InternalIntentProcessor.compile(IntentManager.java:383)[77:org.onosproject.onos-core-net:1.2.0.SNAPSHOT]
at org.onosproject.net.intent.impl.phase.Compiling.execute(Compiling.java:57)[77:org.onosproject.onos-core-net:1.2.0.SNAPSHOT]
at org.onosproject.net.intent.impl.phase.IntentWorker.call(IntentWorker.java:48)[77:org.onosproject.onos-core-net:1.2.0.SNAPSHOT]
at org.onosproject.net.intent.impl.phase.IntentWorker.call(IntentWorker.java:27)[77:org.onosproject.onos-core-net:1.2.0.SNAPSHOT]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_25]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_25]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_25]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_25]
2015-06-02 13:23:02,145 | INFO | event-dispatch-0 | OpticalPathProvisioner | 174 - org.onosproject.onos-app-optical - 1.2.0.SNAPSHOT | Intent OpticalConnectivityIntent{id=0x7, key=0x7, appId=DefaultApplicationId{id=25, name=org.onosproject.optical}, priority=100, resources=[], src=ConnectPoint{elementId=of:0000ffffffffff09, portNumber=11}, dst=ConnectPoint{elementId=of:0000ffffffffff01, portNumber=10}, signalType=ODU4} failed, calling optical path provisioning app.

….

2015-06-02 13:25:28,679 | ERROR | -intent-worker-5 | ConsistentDeviceResourceStore | 79 - org.onosproject.onos-core-dist - 1.2.0.SNAPSHOT | Exception thrown, rolling back
java.lang.Exception: Port already allocated OchPort{element=of:0000ffffffffff01, number=11, isEnabled=true, type=OCH, signalType=ODU4, isTunable=true, lambda=OchSignal{gridType=DWDM, channelSpacing=CHL_100GHZ, spacingMultiplier=1, slotGranularity=1}}
at org.onosproject.store.resource.impl.ConsistentDeviceResourceStore.allocatePorts(ConsistentDeviceResourceStore.java:131)[79:org.onosproject.onos-core-dist:1.2.0.SNAPSHOT]
at org.onosproject.net.resource.impl.DeviceResourceManager.requestPorts(DeviceResourceManager.java:62)[77:org.onosproject.onos-core-net:1.2.0.SNAPSHOT]
at org.onosproject.net.intent.impl.compiler.OpticalConnectivityIntentCompiler.compile(OpticalConnectivityIntentCompiler.java:117)[77:org.onosproject.onos-core-net:1.2.0.SNAPSHOT]
at org.onosproject.net.intent.impl.compiler.OpticalConnectivityIntentCompiler.compile(OpticalConnectivityIntentCompiler.java:69)[77:org.onosproject.onos-core-net:1.2.0.SNAPSHOT]
at org.onosproject.net.intent.impl.CompilerRegistry.compile(CompilerRegistry.java:82)[77:org.onosproject.onos-core-net:1.2.0.SNAPSHOT]
at org.onosproject.net.intent.impl.IntentManager$InternalIntentProcessor.compile(IntentManager.java:383)[77:org.onosproject.onos-core-net:1.2.0.SNAPSHOT]
at org.onosproject.net.intent.impl.phase.Compiling.execute(Compiling.java:57)[77:org.onosproject.onos-core-net:1.2.0.SNAPSHOT]
at org.onosproject.net.intent.impl.phase.IntentWorker.call(IntentWorker.java:48)[77:org.onosproject.onos-core-net:1.2.0.SNAPSHOT]
at org.onosproject.net.intent.impl.phase.IntentWorker.call(IntentWorker.java:27)[77:org.onosproject.onos-core-net:1.2.0.SNAPSHOT]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_25]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_25]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_25]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_25]

2015-06-02 13:25:28,680 | WARN | ice-installer-31 | IntentManager | 77 - org.onosproject.onos-core-net - 1.2.0.SNAPSHOT | Failed withdrawal: 0x0 PointToPointIntent{id=0x0, key=0x0, appId=DefaultApplicationId{id=2, name=org.onosproject.cli}, priority=100, resources=[], selector=DefaultTrafficSelector{criteria=[ETH_TYPE{ethType=800}

]}, treatment=DefaultTrafficTreatment

{immediate=[], deferred=[], transition=None, cleared=false, metadata=null}, ingress=ConnectPoint{elementId=of:0000ffffffff0001, portNumber=1}, egress=ConnectPoint{elementId=of:0000ffffffff0005, portNumber=1}, constraints=[LinkTypeConstraint{inclusive=false, types=[OPTICAL]}]} on FlowRuleOperations{stages=[[FlowRuleOperation{rule=DefaultFlowRule{id=1d00001bbbe88b, deviceId=of:0000ffffffff0005, priority=123, selector=[ETH_TYPE{ethType=800}, IN_PORT{port=2}], treatment=[OUTPUT{port=1}], tableId=0, created=1433265837139, payLoad=null}, type=ADD}]]}
2015-06-02 13:25:28,681 | WARN | ice-installer-20 | IntentManager | 77 - org.onosproject.onos-core-net - 1.2.0.SNAPSHOT | Failed withdrawal: 0x9 OpticalConnectivityIntent{id=0x9, key=0x9, appId=DefaultApplicationId{id=25, name=org.onosproject.optical}, priority=100, resources=[], src=ConnectPoint{elementId=of:0000ffffffffff01, portNumber=11}, dst=ConnectPoint{elementId=of:0000ffffffffff09, portNumber=10}, signalType=ODU4} on FlowRuleOperations{stages=[[FlowRuleOperation{rule=DefaultFlowRule{id=1d0000cc371f6e, deviceId=of:0000ffffffffff09, priority=100, selector=[IN_PORT{port=50}, OchSignalTypeCriterion{signalType=FIXED_GRID}, OchSignalCriterion{lambda=OchSignal{gridType=DWDM, channelSpacing=CHL_50GHZ, spacingMultiplier=1, slotGranularity=8}}], treatment=[OUTPUT{port=10}], tableId=0, created=1433265834072, payLoad=null}, type=ADD}]]}
2015-06-02 13:25:28,692 | WARN | vice-installer-3 | IntentManager | 77 - org.onosproject.onos-core-net - 1.2.0.SNAPSHOT | Failed withdrawal: 0x0 PointToPointIntent{id=0x0, key=0x0, appId=DefaultApplicationId{id=2, name=org.onosproject.cli}, priority=100, resources=[], selector=DefaultTrafficSelector{criteria=[ETH_TYPE{ethType=800}]}, treatment=DefaultTrafficTreatment{immediate=[], deferred=[], transition=None, cleared=false, metadata=null}

, ingress=ConnectPoint

{elementId=of:0000ffffffff0001, portNumber=1}

, egress=ConnectPoint

{elementId=of:0000ffffffff0005, portNumber=1}

, constraints=[LinkTypeConstraint

{inclusive=false, types=[OPTICAL]}

]} on FlowRuleOperations{stages=[[FlowRuleOperation{rule=DefaultFlowRule{id=1d00001eecc766, deviceId=of:0000ffffffff0001, priority=123, selector=[ETH_TYPE

{ethType=800}

, IN_PORT

{port=1}

], treatment=[OUTPUT

{port=3}

], tableId=0, created=1433265837139, payLoad=null}, type=ADD}]]}
2015-06-02 13:25:30,111 | WARN | d wheel timer #2 | OpenFlowPacketProvider | 164 - org.onosproject.onos-of-provider-packet - 1.2.0.SNAPSHOT | Device of:0000ffffffff0004 isn't available?