Hello,
I was doing some testing sending some files with the dtnsend and dtnreceiver tools and checking if the priority parameter works as intended when I found something weird in my results.
My test consist in sending 5 files: 1, 2, 3, 4, 5.
File 1 has high priority. Files 2, 3 and 4 have normal priority. File 5 has low priority.
First of all, the router which sends the files cannot see the destination node, so the files (bundles) will be stored in this router.
After all 5 bundles are stored in the router I connect it to the other router and start the dtnrecv program, so bundles are transmitted without problem.
Everything seems fine, but after revising the logs I found some weird and it's that the receiver received the bundles in the following order: 4, 5, 1, 2 and 3. The logical order would be 1, 2, 3, 4, 5 so I redo the experiment and now the bundles were received in the following order: 2, 3, 4, 5 and 1, so something weird is happening.
I check the ibrdtn.log of the *sending router*:
*Fri Jan 25 14:21:34 2013 NOTICE: RequeueBundleEvent: Bundle requeued [412438174.57] dtn://node4.dtn/NwDuMTuXnISiKzS (File 1) Fri Jan 25 14:21:34 2013 NOTICE: RequeueBundleEvent: Bundle requeued [412438153.37] dtn://node4.dtn/OEAsZLmtkeeqIgy (File 2) Fri Jan 25 14:21:34 2013 NOTICE: RequeueBundleEvent: Bundle requeued [412438166.49] dtn://node4.dtn/WXGOOyJunVtAeiC (File 3) Fri Jan 25 14:21:34 2013 NOTICE: RequeueBundleEvent: Bundle requeued [412438169.53] dtn://node4.dtn/nQxCZKRvkbbpRXF (File 4) Fri Jan 25 14:21:34 2013 NOTICE: RequeueBundleEvent: Bundle requeued [412438177.61] dtn://node4.dtn/OMImpIWIFglHYcg* (File 5)
Equivalences are:
412438174.57 -> File 1 412438153.37 -> File 2 412438166.49 -> File 3 412438169.53 -> File 4 412438177.61 -> File 5
Here you can see how the bundles are well stored following the priority parameter.
Here is the log at the *receiver router*:
*Fri Jan 25 14:21:33 2013 NOTICE: NodeEvent: Node dtn://node4.dtn available Fri Jan 25 14:21:46 2013 NOTICE: ConnectionEvent: connection up dtn://node4.dtn Fri Jan 25 14:21:46 2013 NOTICE: BundleReceivedEvent: Bundle received [412438169.53] dtn://node4.dtn/**nQxCZKRvkbbpRXF -> dtn://node2.dtn/filetransfer from dtn://node4.dtn (File 4) Fri Jan 25 14:21:46 2013 NOTICE: BundleReceivedEvent: Bundle received [412438177.61] dtn://node4.dtn/OMImpIWIFglHYcg -> dtn://node2.dtn/filetransfer from dtn://node4.dtn (File 5) Fri Jan 25 14:21:46 2013 NOTICE: BundleReceivedEvent: Bundle received [412438174.57] dtn://node4.dtn/NwDuMTuXnISiKzS -> dtn://node2.dtn/filetransfer from dtn://node4.dtn (File 1) Fri Jan 25 14:21:46 2013 NOTICE: BundleReceivedEvent: Bundle received [412438153.37] dtn://node4.dtn/OEAsZLmtkeeqIgy -> dtn://node2.dtn/filetransfer from dtn://node4.dtn (File 2) Fri Jan 25 14:21:48 2013 NOTICE: BundleReceivedEvent: Bundle received [412438166.49] dtn://node4.dtn/WXGOOyJunVtAeiC -> dtn://node2.dtn/filetransfer from dtn://node4.dtn (File 3) Fri Jan 25 14:23:48 2013 NOTICE: ConnectionEvent: connection down dtn://node4.dtn Fri Jan 25 14:29:57 2013 NOTICE: NodeEvent: Node dtn://node4.dtn unavailable *
As you can see, the receiving order was 4, 5, 1, 2, 3 so the bundles are not send following my priority option.
Trying to understand what was happening I researched further the sender log and I find something interesting:
. . *. Fri Jan 25 14:21:36 2013 NOTICE: RequeueBundleEvent: Bundle requeued [412438174.57] dtn://node4.dtn/NwDuMTuXnISiKzS (File 1) Fri Jan 25 14:21:37 2013 NOTICE: RequeueBundleEvent: Bundle requeued [412438153.37] dtn://node4.dtn/OEAsZLmtkeeqIgy (File 2) Fri Jan 25 14:21:38 2013 NOTICE: RequeueBundleEvent: Bundle requeued [412438166.49] dtn://node4.dtn/WXGOOyJunVtAeiC (File 3) Fri Jan 25 14:21:39 2013 NOTICE: RequeueBundleEvent: Bundle requeued [412438169.53] dtn://node4.dtn/nQxCZKRvkbbpRXF (File 4) Fri Jan 25 14:21:40 2013 NOTICE: RequeueBundleEvent: Bundle requeued [412438177.61] dtn://node4.dtn/OMImpIWIFglHYcg (File 5) Fri Jan 25 14:21:41 2013 NOTICE: RequeueBundleEvent: Bundle requeued [412438174.57] dtn://node4.dtn/NwDuMTuXnISiKzS (File 1) Fri Jan 25 14:21:42 2013 NOTICE: RequeueBundleEvent: Bundle requeued [412438153.37] dtn://node4.dtn/OEAsZLmtkeeqIgy (File 2) Fri Jan 25 14:21:43 2013 NOTICE: RequeueBundleEvent: Bundle requeued [412438166.49] dtn://node4.dtn/WXGOOyJunVtAeiC (File 3) Fri Jan 25 14:21:47 2013 NOTICE: ConnectionEvent: connection up dtn://node2.dtn ---> I CONNECT DESTINATION ROUTER Fri Jan 25 14:21:47 2013 DEBUG.5: processing static routing task SearchNextBundleTask: dtn://node2.dtn Fri Jan 25 14:21:47 2013 DEBUG.5: processing neighbor routing task SearchNextBundleTask: dtn://node2.dtn Fri Jan 25 14:21:47 2013 DEBUG.5: got 5 items to transfer to dtn://node2.dtn Fri Jan 25 14:21:47 2013 NOTICE: TransferCompletedEvent: transfer of bundle [412438169.53] dtn://node4.dtn/nQxCZKRvkbbpRXF to dtn://node2.dtn completed (File 4) Fri Jan 25 14:21:47 2013 DEBUG.5: got 4 items to transfer to dtn://node2.dtn Fri Jan 25 14:21:47 2013 NOTICE: TransferCompletedEvent: transfer of bundle [412438177.61] dtn://node4.dtn/OMImpIWIFglHYcg to dtn://node2.dtn completed (File 5) Fri Jan 25 14:21:47 2013 DEBUG.5: processing neighbor routing task SearchNextBundleTask: dtn://node2.dtn Fri Jan 25 14:21:47 2013 DEBUG.5: got 3 items to transfer to dtn://node2.dtn Fri Jan 25 14:21:47 2013 NOTICE: TransferCompletedEvent: transfer of bundle [412438174.57] dtn://node4.dtn/NwDuMTuXnISiKzS to dtn://node2.dtn completed (File 1) . . .*
As you can see here, it seems that the sender router is performing some "periodic checking" with the bundles it has stored when the destination router suddenly connected. When it's connected the sender sends the next bundle in his "periodic checking list" instead of sending the bundle which is the first in the queue and has the highest priority.
It is working as intended or it's a bug?
Thanks in advance