[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
Re: [Testbed-admins] Event system questions
> > > If I "Replay Events" in the web interface, I can see my UDP packets.
> What I
> > > have forgotten in order to launch the events when an experiment is
> created /
> > > swapped in?
>
> There is definitely something funny going on here, they should start on
> swapin. I would check the following logs:
>
> /proj/<pid>/exp/<eid>/logs/event-sched.log on ops, which has the event
> scheulder log.
>
> /var/log/emulab/ on the nodes themselves, which should have the logs for
> the traffic generators themselves.
>
When I swapin an experiment, the content of the "event-sched.log" is the
following:
----
/usr/testbed/sbin/event-sched -d -s localhost -k
/proj/tutorial/exp/advanced/tbdata/eventkey tutorial advanced
Agent: __ns_sequence SEQUENCE * * *
Agent: __ns_teardown SEQUENCE * * *
Agent: __ns_timeline TIMELINE * * *
Agent: cbr0 TRAFGEN nodeA pc15 10.0.100.215
Agent: link0 LINK * * *
Agent: link0-nodeA LINK * * *
Agent: link0-nodeA-tracemon LINKTRACE * * *
Agent: link0-nodeB LINK * * *
Agent: link0-nodeB-tracemon LINKTRACE * * *
Agent: linktest LINKTEST * * *
Agent: nodeA NODE nodeA pc15 10.0.100.215
Agent: nodeA-console CONSOLE nodeA pc15 10.0.100.215
Agent: nodeB NODE nodeB pc4 10.0.100.204
Agent: nodeB-console CONSOLE nodeB pc4 10.0.100.204
Agent: ns SIMULATOR * * *
Agent: null0 TRAFGEN nodeB pc4 10.0.100.204
Agent: slothd SLOTHD * * *
Agent: __all_lans GROUP * * *
Agent: __all_tracemon GROUP * * *
Agent: link0-tracemon GROUP * * *
Getting event stream at: 1254758005:377237
0.0 cbr0 TRAFGEN MODIFY 10.0.100.215 PACKETSIZE=500
RATE=100000 INTERVAL=0.005 IPTOS=-1 __ns
_sequence 0x810e180
60.0 cbr0 TRAFGEN START 10.0.100.215 0x8138ac0
70.0 cbr0 TRAFGEN STOP 10.0.100.215 0x8138ce0
----
When I "replay events", the following lines are also added to the content of
the "event-sched.log".
----
Sched: note:0x8138b30 at:20091005_17:53:25.485 now:20091005_17:53:25.485
agent:__ns_sequence START
event_notification_get_int32: could not get int32 attribute "TOKEN" from
notification 0x8138b30
Fire: note:0x8138b30 at:20091005_17:53:25.485 now:20091005_17:53:25.584
agent:__ns_sequence
Fire: note:0x8138b20 at:20091005_17:53:25.584 now:20091005_17:53:25.584
agent:cbr0
Fire: note:0x8138b60 at:20091005_17:53:26.584 now:20091005_17:53:26.585
agent:ns
Fire: note:0x8138b70 at:20091005_17:53:26.584 now:20091005_17:53:26.585
agent:*
log: Mon Oct 5 17:53:26 2009 - Time started
Sched: note:0x8138cc0 at:20091005_17:53:26.586 now:20091005_17:53:26.587
agent:ns COMPLETE
Error occured: Invalid response from server
Fire: note:0x8138b80 at:20091005_17:53:26.584 now:20091005_17:53:26.691
agent:__ns_timeline
Sched: note:0x8138c50 at:20091005_17:54:36.691 now:20091005_17:53:26.691
agent:__ns_timeline COMPLETE
Fire: note:0x8138cc0 at:20091005_17:53:26.586 now:20091005_17:53:26.791
agent:ns
Done: now:20091005_17:53:26.792 CTOKEN=11 ERROR=0
Fire: note:0x8138b60 at:20091005_17:54:26.691 now:20091005_17:54:26.693
agent:cbr0
Fire: note:0x8138b70 at:20091005_17:54:36.691 now:20091005_17:54:36.692
agent:cbr0
Fire: note:0x8138c50 at:20091005_17:54:36.691 now:20091005_17:54:36.692
agent:__ns_timeline
Done: now:20091005_17:54:36.693 CTOKEN=13 ERROR=0
Sched: note:0x8138b70 at:20091005_17:54:36.693 now:20091005_17:54:36.693
agent:__ns_sequence COMPLETE
Fire: note:0x8138b70 at:20091005_17:54:36.693 now:20091005_17:54:36.934
agent:__ns_sequence
Done: now:20091005_17:54:36.935 CTOKEN=9 ERROR=0
----
In fact, the previous "event-sched.log" file is moved to the
"event-sched.log.old" file and a new one is created.
The most interested files in /var/emulab/log are:
- null0-tutorial-advanced.debug (in nodeB)
- cbr0-tutorial-advanced.debug (in nodeA)
But again, these files are only generated when I "replay the events", not
when I swapin the experiment.
File "null0-tutorial-advanced.debug"
----
1254757595.725: trafgen (re)started
Event 1: 1254758006.780 * tutorial/advanced * * TIME * START
1254758006.780: SETUP/WAIT exp=tutorial/advanced
----
File "cbr0-tutorial-advanced.debug"
----
1254757594.142: trafgen (re)started
Event 1: 1254758005.586 * tutorial/advanced * 10.0.100.215 TRAFGEN cbr0
MODIFY PACKETSIZE=500 RATE=100000 INTERVAL=0.005 IPTOS=-1
1254758005.586: MODIFY length=500 bytes, interval=0.005000000 sec
(rate=800.000000 Kbps), iptos=0
Event 2: 1254758006.586 * tutorial/advanced * * TIME * START
1254758007.085: SETUP/WAIT exp=tutorial/advanced
Event 3: 1254758066.675 * tutorial/advanced * 10.0.100.215 TRAFGEN cbr0
START
1254758066.675: START
Event 4: 1254758076.636 * tutorial/advanced * 10.0.100.215 TRAFGEN cbr0 STOP
1254758076.636: WAIT
----
> > > - In the "at" command, how the "0.0 time" is specified? When I "Replay
> > > events", I guess that the "0.0 time" is more or less when I select the
> > > option in the web interface. Could I specify the "0.0 time" at 13:15,
> for
> > > example, and the rest of the "+XX" events are scheduled accordingly?
>
> Time start occurs when all nodes finish booting, and all other times are
> relative to that time. You *should* see a time start event in the event
> scheduler log.
>
If you mean "a time start event" by the following line: "agent:__ns_sequence
START". Yes, I see it but only when I "Replay the events".
To summarize, I still have one main problem: the events are not scheduled
when an experiment is swapin.