search

labrad / servers

LabRAD servers
24 stars 21 forks source link

Scala DirectEthernet Not Detecting Boards (Unlike Delphi Version) #232

Closed jwenner closed 9 years ago

jwenner commented 9 years ago

When I use the Delphi DirectEthernet server, I am able to detect the connected DACs/ADCs, while when I use the scala DirectEthernet server (current master), no boards are detected. Tracebacks in next 2 comments (for distinguishability).

In addition, with the Delphi version, I could see the following info:

jwenner commented 9 years ago

Delphi log messages:

From ghz_fpga_server:

C:\labrad-servers\servers\GHzDACs>ghz_fpga_server.py
2015-10-06 14:09:22-0700 [-] Log opened.
2015-10-06 14:09:22-0700 [-] Starting factory <__main__.FPGAServer instance at 0
x0546AC10>
2015-10-06 14:09:22-0700 [Uninitialized] connected to 127.0.0.1:7682
2015-10-06 14:09:22-0700 [ServerProtocol,client] GHz FPGAs starting...
2015-10-06 14:09:22-0700 [ServerProtocol,client] Refreshing client connection...

2015-10-06 14:09:22-0700 [ServerProtocol,client] Loading board group definitions
 from registry...
2015-10-06 14:09:22-0700 [ServerProtocol,client] Board group definitions loaded.

2015-10-06 14:09:22-0700 [ServerProtocol,client] Board group definitions ok.
2015-10-06 14:09:22-0700 [ServerProtocol,client] Adapter "Vince Direct Ethernet"
 (port 3) does not exist. Group will not be added.
2015-10-06 14:09:22-0700 [ServerProtocol,client] Adapter "hercules_direct_ethern
et" (port 2) does not exist. Group will not be added.
2015-10-06 14:09:22-0700 [ServerProtocol,client] Adapter "santo_direct_ethernet"
 (port 0) does not exist. Group will not be added.
2015-10-06 14:09:22-0700 [ServerProtocol,client] Adapter "DR Direct Ethernet" (p
ort 0) does not exist. Group will not be added.
2015-10-06 14:09:22-0700 [ServerProtocol,client] Adapter "ivan_direct_ethernet"
(port 0) does not exist. Group will not be added.
2015-10-06 14:09:22-0700 [ServerProtocol,client] Adapter "runningman_direct_ethe
rnet" (port 1) does not exist. Group will not be added.
2015-10-06 14:09:22-0700 [ServerProtocol,client] Board groups to be added: set([
('rottmayer_direct_ethernet', 2L)])
2015-10-06 14:09:22-0700 [ServerProtocol,client] Board groups to be removed: set
([])
2015-10-06 14:09:22-0700 [ServerProtocol,client] Creating board group "rottmayer
": server="rottmayer_direct_ethernet", port=2
ERROR:root:timeout exception: (0) Operation timed out [payload=None]
ERROR:root:timeout exception: (0) Operation timed out [payload=None]
2015-10-06 14:09:24-0700 [ServerProtocol,client] Devices detected on board group
 "rottmayer":
2015-10-06 14:09:24-0700 [ServerProtocol,client]   rottmayer DAC 53
2015-10-06 14:09:24-0700 [ServerProtocol,client]   rottmayer DAC 59
2015-10-06 14:09:24-0700 [ServerProtocol,client]   rottmayer ADC 2
2015-10-06 14:09:24-0700 [ServerProtocol,client]   rottmayer ADC 3
2015-10-06 14:09:24-0700 [ServerProtocol,client] connecting to DAC board: 00:01:
CA:AA:00:35 (build #8)
2015-10-06 14:09:24-0700 [ServerProtocol,client] connecting to DAC board: 00:01:
CA:AA:00:3B (build #8)
2015-10-06 14:09:24-0700 [ServerProtocol,client] connecting to ADC board: 00:01:
CA:AA:01:02 (build #7)
2015-10-06 14:09:24-0700 [ServerProtocol,client] connecting to ADC board: 00:01:
CA:AA:01:03 (build #7)
2015-10-06 14:09:24-0700 [ServerProtocol,client] GHz FPGAs now serving

Upon trying direct_ethernet.adapters:

In [9]: de.adapters()
Out[9]: [(0L, "Network adapter 'Intel(R) I210 Gigabit Network Connection' on loc
al host"), (1L, "Network adapter 'Intel(R) I210 Gigabit Network Connection' on l
ocal host"), (2L, "Network adapter 'Intel(R) I210 Gigabit Network Connection' on
 local host")]

Direct ethernet server info: delphide

jwenner commented 9 years ago

Scala log messages:

From DirectEthernet:

14:25:35.024 [main] WARN  org.pcap4j.util.PropertiesLoader - [org/pcap4j/pcap4j.
properties] Could not get value by org.pcap4j.af.inet, use default value: null
14:25:35.026 [main] WARN  org.pcap4j.util.PropertiesLoader - [org/pcap4j/pcap4j.
properties] Could not get value by org.pcap4j.af.inet6, use default value: null
14:25:35.026 [main] WARN  org.pcap4j.util.PropertiesLoader - [org/pcap4j/pcap4j.
properties] Could not get value by org.pcap4j.af.packet, use default value: null

14:25:35.026 [main] WARN  org.pcap4j.util.PropertiesLoader - [org/pcap4j/pcap4j.
properties] Could not get value by org.pcap4j.af.link, use default value: null
14:25:35.030 [main] INFO  org.pcap4j.core.Pcaps - 3 NIF(s) found.
14:25:35.037 [main] WARN  org.pcap4j.util.PropertiesLoader - [org/pcap4j/pcap4j.
properties] Could not get value by org.pcap4j.dlt.raw, use default value: null
14:25:35.324 [main] INFO  o.l.ethernet.server.DirectEthernet - Now serving...
14:25:47.977 [EthernetBus-listenThread-\Device\NPF_{E16868FB-E5CD-47E4-94A0-A508
A289FB41}] INFO  org.pcap4j.core.Pcaps - 3 NIF(s) found.
14:25:47.979 [EthernetBus-listenThread-\Device\NPF_{E16868FB-E5CD-47E4-94A0-A508
A289FB41}] INFO  org.pcap4j.core.PcapHandle - Starting loop.
14:25:53.607 [EthernetBus-listenThread-\Device\NPF_{E16868FB-E5CD-47E4-94A0-A508
A289FB41}] WARN  o.p.packet.factory.PacketFactories - java.lang.NoClassDefFoundE
rror:org/pcap4j/packet/factory/PacketFactoryBinder

From ghz_fpgas:

C:\labrad-servers\servers\GHzDACs>ghz_fpga_server.py
2015-10-06 14:25:47-0700 [-] Log opened.
2015-10-06 14:25:47-0700 [-] Starting factory <__main__.FPGAServer instance at 0
x053CFC10>
2015-10-06 14:25:47-0700 [Uninitialized] connected to 127.0.0.1:7682
2015-10-06 14:25:47-0700 [ServerProtocol,client] GHz FPGAs starting...
2015-10-06 14:25:47-0700 [ServerProtocol,client] Refreshing client connection...

2015-10-06 14:25:47-0700 [ServerProtocol,client] Loading board group definitions
 from registry...
2015-10-06 14:25:47-0700 [ServerProtocol,client] Board group definitions loaded.

2015-10-06 14:25:47-0700 [ServerProtocol,client] Board group definitions ok.
2015-10-06 14:25:47-0700 [ServerProtocol,client] Adapter "Vince Direct Ethernet"
 (port 3) does not exist. Group will not be added.
2015-10-06 14:25:47-0700 [ServerProtocol,client] Adapter "hercules_direct_ethern
et" (port 2) does not exist. Group will not be added.
2015-10-06 14:25:47-0700 [ServerProtocol,client] Adapter "santo_direct_ethernet"
 (port 0) does not exist. Group will not be added.
2015-10-06 14:25:47-0700 [ServerProtocol,client] Adapter "DR Direct Ethernet" (p
ort 0) does not exist. Group will not be added.
2015-10-06 14:25:47-0700 [ServerProtocol,client] Adapter "ivan_direct_ethernet"
(port 0) does not exist. Group will not be added.
2015-10-06 14:25:47-0700 [ServerProtocol,client] Adapter "runningman_direct_ethe
rnet" (port 1) does not exist. Group will not be added.
2015-10-06 14:25:47-0700 [ServerProtocol,client] Board groups to be added: set([
('rottmayer_direct_ethernet', 2L)])
2015-10-06 14:25:47-0700 [ServerProtocol,client] Board groups to be removed: set
([])
2015-10-06 14:25:47-0700 [ServerProtocol,client] Creating board group "rottmayer
": server="rottmayer_direct_ethernet", port=2
ERROR:root:timeout exception: (0) java.util.concurrent.TimeoutException: Futures
 timed out after [1 second]
        at scala.concurrent.impl.Promise$DefaultPromise.ready(Promise.scala:219)

        at scala.concurrent.impl.Promise$DefaultPromise.result(Promise.scala:223
)
        at scala.concurrent.Await$$anonfun$result$1.apply(package.scala:190)
        at scala.concurrent.impl.ExecutionContextImpl$DefaultThreadFactory$$anon
$2$$anon$4.block(ExecutionContextImpl.scala:48)
        at scala.concurrent.forkjoin.ForkJoinPool.managedBlock(ForkJoinPool.java
:3640)
        at scala.concurrent.impl.ExecutionContextImpl$DefaultThreadFactory$$anon
$2.blockOn(ExecutionContextImpl.scala:45)
        at scala.concurrent.Await$.result(package.scala:190)
        at org.labrad.ethernet.server.Awaitable.await(PacketQueue.scala:32)
        at org.labrad.ethernet.server.PacketQueue.await(PacketQueue.scala:99)
        at org.labrad.ethernet.server.EthernetContext.collect(DirectEthernet.sca
la:170)
        at org.labrad.ethernet.server.EthernetContext.read(DirectEthernet.scala:
182)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
        at java.lang.reflect.Method.invoke(Unknown Source)
        at scala.reflect.runtime.JavaMirrors$JavaMirror$JavaVanillaMethodMirror1
.jinvokeraw(JavaMirrors.scala:373)
        at scala.reflect.runtime.JavaMirrors$JavaMirror$JavaMethodMirror.jinvoke
(JavaMirrors.scala:339)
        at scala.reflect.runtime.JavaMirrors$JavaMirror$JavaVanillaMethodMirror.
apply(JavaMirrors.scala:355)
        at org.labrad.SettingHandler$$anonfun$org$labrad$SettingHandler$$invoke$
1.apply(SettingHandler.scala:187)
        at org.labrad.SettingHandler$$anonfun$org$labrad$SettingHandler$$invoke$
1.apply(SettingHandler.scala:185)
        at scala.Function1$$anonfun$andThen$1.apply(Function1.scala:52)
        at scala.Function1$$anonfun$andThen$1.apply(Function1.scala:52)
        at org.labrad.SettingHandler$$anon$1.apply(SettingHandler.scala:197)
        at org.labrad.SettingHandler$$anon$1.apply(SettingHandler.scala:195)
        at org.labrad.Reflect$$anonfun$15$$anonfun$apply$4$$anonfun$apply$5.appl
y(reflect.scala:48)
        at org.labrad.Reflect$$anonfun$15$$anonfun$apply$4$$anonfun$apply$5.appl
y(reflect.scala:48)
        at scala.Option.map(Option.scala:146)
        at org.labrad.Reflect$$anonfun$15$$anonfun$apply$4.apply(reflect.scala:4
8)
        at org.labrad.Reflect$$anonfun$15$$anonfun$apply$4.apply(reflect.scala:4
7)
        at org.labrad.Server$$anonfun$org$labrad$Server$$handleRequest$1$$anonfu
n$apply$7.apply(Server.scala:174)
        at org.labrad.Server$$anonfun$org$labrad$Server$$handleRequest$1$$anonfu
n$apply$7.apply(Server.scala:159)
        at org.labrad.Server$.handle(Server.scala:218)
        at org.labrad.Server$$anonfun$org$labrad$Server$$handleRequest$1.apply(S
erver.scala:159)
        at org.labrad.Server$$anonfun$org$labrad$Server$$handleRequest$1.apply(S
erver.scala:159)
        at org.labrad.util.AsyncSemaphore$$anonfun$map$1.apply(AsyncSemaphore.sc
ala:83)
        at org.labrad.util.AsyncSemaphore$$anonfun$map$1.apply(AsyncSemaphore.sc
ala:82)
        at scala.util.Success$$anonfun$map$1.apply(Try.scala:237)
        at scala.util.Try$.apply(Try.scala:192)
        at scala.util.Success.map(Try.scala:237)
        at scala.concurrent.Future$$anonfun$map$1.apply(Future.scala:235)
        at scala.concurrent.Future$$anonfun$map$1.apply(Future.scala:235)
        at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:32)
        at scala.concurrent.impl.ExecutionContextImpl$AdaptedForkJoinTask.exec(E
xecutionContextImpl.scala:121)
        at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
        at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool
.java:1339)
        at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:19
79)
        at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThre
ad.java:107)
 [payload=None]
ERROR:root:timeout exception: (0) java.util.concurrent.TimeoutException: Futures
 timed out after [1 second]
        at scala.concurrent.impl.Promise$DefaultPromise.ready(Promise.scala:219)

        at scala.concurrent.impl.Promise$DefaultPromise.result(Promise.scala:223
)
        at scala.concurrent.Await$$anonfun$result$1.apply(package.scala:190)
        at scala.concurrent.impl.ExecutionContextImpl$DefaultThreadFactory$$anon
$2$$anon$4.block(ExecutionContextImpl.scala:48)
        at scala.concurrent.forkjoin.ForkJoinPool.managedBlock(ForkJoinPool.java
:3640)
        at scala.concurrent.impl.ExecutionContextImpl$DefaultThreadFactory$$anon
$2.blockOn(ExecutionContextImpl.scala:45)
        at scala.concurrent.Await$.result(package.scala:190)
        at org.labrad.ethernet.server.Awaitable.await(PacketQueue.scala:32)
        at org.labrad.ethernet.server.PacketQueue.await(PacketQueue.scala:99)
        at org.labrad.ethernet.server.EthernetContext.collect(DirectEthernet.sca
la:170)
        at org.labrad.ethernet.server.EthernetContext.read(DirectEthernet.scala:
182)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
        at java.lang.reflect.Method.invoke(Unknown Source)
        at scala.reflect.runtime.JavaMirrors$JavaMirror$JavaVanillaMethodMirror1
.jinvokeraw(JavaMirrors.scala:373)
        at scala.reflect.runtime.JavaMirrors$JavaMirror$JavaMethodMirror.jinvoke
(JavaMirrors.scala:339)
        at scala.reflect.runtime.JavaMirrors$JavaMirror$JavaVanillaMethodMirror.
apply(JavaMirrors.scala:355)
        at org.labrad.SettingHandler$$anonfun$org$labrad$SettingHandler$$invoke$
1.apply(SettingHandler.scala:187)
        at org.labrad.SettingHandler$$anonfun$org$labrad$SettingHandler$$invoke$
1.apply(SettingHandler.scala:185)
        at scala.Function1$$anonfun$andThen$1.apply(Function1.scala:52)
        at scala.Function1$$anonfun$andThen$1.apply(Function1.scala:52)
        at org.labrad.SettingHandler$$anon$1.apply(SettingHandler.scala:197)
        at org.labrad.SettingHandler$$anon$1.apply(SettingHandler.scala:195)
        at org.labrad.Reflect$$anonfun$15$$anonfun$apply$4$$anonfun$apply$5.appl
y(reflect.scala:48)
        at org.labrad.Reflect$$anonfun$15$$anonfun$apply$4$$anonfun$apply$5.appl
y(reflect.scala:48)
        at scala.Option.map(Option.scala:146)
        at org.labrad.Reflect$$anonfun$15$$anonfun$apply$4.apply(reflect.scala:4
8)
        at org.labrad.Reflect$$anonfun$15$$anonfun$apply$4.apply(reflect.scala:4
7)
        at org.labrad.Server$$anonfun$org$labrad$Server$$handleRequest$1$$anonfu
n$apply$7.apply(Server.scala:174)
        at org.labrad.Server$$anonfun$org$labrad$Server$$handleRequest$1$$anonfu
n$apply$7.apply(Server.scala:159)
        at org.labrad.Server$.handle(Server.scala:218)
        at org.labrad.Server$$anonfun$org$labrad$Server$$handleRequest$1.apply(S
erver.scala:159)
        at org.labrad.Server$$anonfun$org$labrad$Server$$handleRequest$1.apply(S
erver.scala:159)
        at org.labrad.util.AsyncSemaphore$$anonfun$map$1.apply(AsyncSemaphore.sc
ala:83)
        at org.labrad.util.AsyncSemaphore$$anonfun$map$1.apply(AsyncSemaphore.sc
ala:82)
        at scala.util.Success$$anonfun$map$1.apply(Try.scala:237)
        at scala.util.Try$.apply(Try.scala:192)
        at scala.util.Success.map(Try.scala:237)
        at scala.concurrent.Future$$anonfun$map$1.apply(Future.scala:235)
        at scala.concurrent.Future$$anonfun$map$1.apply(Future.scala:235)
        at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:32)
        at scala.concurrent.impl.ExecutionContextImpl$AdaptedForkJoinTask.exec(E
xecutionContextImpl.scala:121)
        at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
        at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool
.java:1339)
        at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:19
79)
        at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThre
ad.java:107)
 [payload=None]
2015-10-06 14:25:49-0700 [ServerProtocol,client] No devices detected on board gr
oup "rottmayer".
2015-10-06 14:25:49-0700 [ServerProtocol,client] GHz FPGAs now serving

From direct_ethernet.adapters():

In [11]: de.adapters()
Out[11]: [(0L, '\\Device\\NPF_{2EC9358D-FB28-40BD-889C-A563E1EDF2BC}'), (1L, '\\
Device\\NPF_{DCA5F99D-4F68-4015-85A2-C11DAF09EB6F}'), (2L, '\\Device\\NPF_{E1686
8FB-E5CD-47E4-94A0-A508A289FB41}')]

Note that the MAC addresses of all three adapters are 0C-C4-7A-0C-01-8x for x in [4,5,6].

maffoo commented 9 years ago

After working with @jwenner on this, we tracked it down to the fact that the packet capture threads in the scala direct ethernet server are being started lazily the first time listen is called. When the ghz_fpga_server sends its discovery packet it calls listen and then immediately sends packets out to all possible mac addresses. As a result, the responses from the boards race against the packet capture thread startup, and the first autodetection tends to fail. If we subsequently restart the fpga server, then the packet capture threads are already running and the autodetection works fine. If we change the server to start the threads immediately when the server runs, then autodetection works fine, no matter the order in which fpga and ethernet servers are started. This is very likely the issue behind #134 as well.