Revision 7b804ffb

View differences:

mininet/logging_mod.py
1
# Since StreamHandler automatically adds newlines, define a mod to more easily
2
# support interactive mode when we want it, or errors-only logging for running
3
# unit tests.
4

  
5
from logging import StreamHandler
6
import types
7

  
8
# Modified from python2.5/__init__.py to not require newlines
9
class StreamHandlerNoNewline(StreamHandler):
10

  
11
    def emit(self, record):
12
        """
13
        Emit a record.
14

  
15
        If a formatter is specified, it is used to format the record.
16
        The record is then written to the stream with a trailing newline
17
        [N.B. this may be removed depending on feedback]. If exception
18
        information is present, it is formatted using
19
        traceback.print_exception and appended to the stream.
20
        """
21
        try:
22
            msg = self.format(record)
23
            fs = "%s" # was "%s\n"
24
            if not hasattr(types, "UnicodeType"): #if no unicode support...
25
                self.stream.write(fs % msg)
26
            else:
27
                try:
28
                    self.stream.write(fs % msg)
29
                except UnicodeError:
30
                    self.stream.write(fs % msg.encode("UTF-8"))
31
            self.flush()
32
        except (KeyboardInterrupt, SystemExit):
33
            raise
34
        except:
35
            self.handleError(record)
mininet/mininet.py
73 73
flush = sys.stdout.flush
74 74
from resource import setrlimit, RLIMIT_NPROC, RLIMIT_NOFILE
75 75

  
76
import logging
77
import sys
78

  
79
from logging_mod import StreamHandlerNoNewline
80

  
76 81
DATAPATHS = ['user', 'kernel']
77 82

  
83
LEVELS = {'debug': logging.DEBUG,
84
          'info': logging.INFO,
85
          'warning': logging.WARNING,
86
          'error': logging.ERROR,
87
          'critical': logging.CRITICAL}
88

  
89
# change this to get printouts when running unit tests
90
LOG_LEVEL_DEFAULT = logging.WARNING
91

  
92
#default: "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
93
LOG_MSG_FORMAT = "%(message)s"
94

  
95
lg = None
96

  
97
def setup_logging(loglevel):
98

  
99
    global lg
100

  
101
    # create logger
102
    lg = logging.getLogger("mininet")
103
    lg.setLevel(loglevel)
104
    # create console handler and set level to debug
105
    ch = StreamHandlerNoNewline()
106
    ch.setLevel(loglevel)
107
    # create formatter
108
    formatter = logging.Formatter(LOG_MSG_FORMAT)
109
    # add formatter to ch
110
    ch.setFormatter(formatter)
111
    # add ch to lg
112
    lg.addHandler(ch)
113

  
114

  
78 115
# Utility routines to make it easier to run commands
79 116

  
80 117
def run( cmd ):
......
193 230
      return self.waitOutput()
194 231
   def cmdPrint( self, cmd ):
195 232
      "Call cmd, printing the command and output"
196
      print "***", self.name, ":", cmd
233
      lg.info("*** %s : %s", self.name, cmd)
197 234
      result = self.cmd( cmd )
198
      print result,
235
      lg.info("%s\n", result)
199 236
      return result
200 237
   # Interface management, configuration, and routing
201 238
   def intfName( self, n):
......
306 343
      self.cmd( 'kill %ofprotocol')
307 344
      for intf in self.intfs:
308 345
         quietRun( 'ip link del ' + intf )
309
         sys.stdout.write( '.' ) ; flush()
346
         lg.info('.')
310 347
   def start( self, controller ): 
311 348
      if self.dp is None: self.startUserDatapath( controller )
312 349
      else: self.startKernelDatapath( controller )
......
314 351
      if self.dp is None: self.stopUserDatapath()
315 352
      else: self.stopKernelDatapath()
316 353
   def sendCmd( self, cmd ):
317
      if not self.execed: return Node.sendCmd( self, cmd )
318
      else: print "*** Error:", self.name, "has execed and cannot accept commands"
354
      if not self.execed:
355
          return Node.sendCmd( self, cmd )
356
      else:
357
          lg.error("*** Error: %s has execed and cannot accept commands" %
358
                 self.name)
319 359
   def monitor( self ):
320 360
      if not self.execed: return Node.monitor( self )
321 361
      else: return True, ''
......
351 391
   links = node.cmd( 'ip link show' )
352 392
   if not intf in links:
353 393
      if print_error:
354
          print "*** Error: moveIntf:", intf, "not successfully moved to",
355
          print node.name,":"
394
          lg.error("*** Error: moveIntf: % not successfully moved to %s:\n" %
395
                  (intf, node.name))
356 396
      return False
357 397
   return True
358 398

  
......
363 403
      sleep( retry_delay )
364 404
      tries += 1
365 405
   if tries >= n: 
366
      print "*** gave up after %i retries" % tries; flush()
406
      lg.error("*** gave up after %i retries\n" % tries)
367 407
      exit( 1 )
368 408
   
369 409
def createLink( node1, node2 ):
......
388 428
def dumpNodes( nodes ):
389 429
   "Dump ifconfig of each node."
390 430
   for node in nodes:
391
      print "*** Dumping node", node.name
392
      print node.cmd( 'ip link show' )
393
      print node.cmd( 'route' )
394
   
431
      lg.info("*** Dumping node %s\n" % node.name)
432
      lg.info("%s\n" % node.cmd( 'ip link show' ))
433
      lg.info("%s\n" % node.cmd( 'route' ))
434

  
395 435
def ipGen( A, B, c, d ):
396 436
   "Generate next IP class B IP address, starting at A.B.c.d"
397 437
   while True:
......
432 472
   """Configure a routed control network on controller and switches,
433 473
      for use with the user datapath."""
434 474
   cip = ips.next()
435
   print controller.name, '<->',
475
   lg.info("%s <-> " % controller.name)
436 476
   for switch in switches:
437
      print switch.name, ; flush()
477
      lg.info("%s " % switch.name)
438 478
      sip = ips.next()
439 479
      sintf = switch.intfs[ 0 ]
440 480
      node, cintf = switch.connection[ sintf ]
441 481
      if node != controller:
442
         print "*** Error: switch", switch.name, 
443
         print "not connected to correct controller"
482
         lg.error("*** Error: switch %s not connected to correct controller" %
483
                  switch.name)
444 484
         exit( 1 )
445 485
      controller.setIP( cintf, cip,  '/24' )
446 486
      switch.setIP( sintf, sip, '/24' )
447 487
      controller.setHostRoute( sip, cintf )
448 488
      switch.setHostRoute( cip, sintf )
449
   print
450
   print "*** Testing control network"
489
   lg.info("\n")
490
   lg.info("*** Testing control network\n")
451 491
   while not controller.intfIsUp( controller.intfs[ 0 ] ):
452
      print "*** Waiting for ", controller.intfs[ 0 ], "to come up"
492
      lg.info("*** Waiting for %s to come up\n", controller.intfs[ 0 ])
453 493
      sleep( 1 )
454 494
   for switch in switches:
455 495
      while not switch.intfIsUp( switch.intfs[ 0 ] ):
456
         print "*** Waiting for ", switch.intfs[ 0 ], "to come up"
496
         lg.info("*** Waiting for %s to come up\n" % switch.intfs[ 0 ])
457 497
         sleep( 1 )
458 498
      if pingTest( hosts=[ switch, controller ] ) != 0:
459
         print "*** Error: control network test failed"
499
         lg.error("*** Error: control network test failed\n")
460 500
         exit( 1 )
501
   lg.info("\n")
461 502

  
462 503
def configHosts( hosts, ips ):
463
   "Configure a set of hosts, starting at IP address a.b.c.d"
504
   """Configure a set of hosts, starting at IP address a.b.c.d"""
464 505
   for host in hosts:
465 506
      hintf = host.intfs[ 0 ]
466 507
      host.setIP( hintf, ips.next(), '/24' )
467 508
      host.setDefaultRoute( hintf )
468 509
      # You're low priority, dude!
469 510
      quietRun( 'renice +18 -p ' + `host.pid` )
470
      print host.name, ; flush()
471
   print
472
 
511
      lg.info("%s ", host.name)
512
   lg.info("\n")
513

  
473 514
# Test driver and topologies
474 515

  
475 516
class Network( object ):
476
   "Network topology (and test driver) base class."
517
   """Network topology (and test driver) base class."""
477 518
   def __init__( self,
478 519
      kernel=True, 
479 520
      Controller=Controller, Switch=Switch, 
......
485 526
      # Check for kernel modules
486 527
      modules = quietRun( 'lsmod' )
487 528
      if not kernel and 'tun' not in modules:
488
         print "*** Error: kernel module tun not loaded:",
489
         print " user datapath not supported"
529
         lg.error("*** Error: kernel module tun not loaded:\n")
530
         lg.error(" user datapath not supported\n")
490 531
         exit( 1 )
491 532
      if kernel and 'ofdatapath' not in modules:
492
         print "*** Error: kernel module ofdatapath not loaded:",
493
         print " kernel datapath not supported"
533
         lg.error("*** Error: kernel module ofdatapath not loaded:\n")
534
         lg.error(" kernel datapath not supported\n")
494 535
         exit( 1 )
495 536
      # Create network, but don't start things up yet!
496 537
      self.prepareNet()
......
506 547
         (switches, hosts ) = makeNet()
507 548
         Create a controller here as well."""
508 549
      kernel = self.kernel
509
      if kernel: print "*** Using kernel datapath"
510
      else: print "*** Using user datapath"
511
      print "*** Creating controller"
550
      if kernel:
551
          lg.info("*** Using kernel datapath\n")
552
      else:
553
          lg.info("*** Using user datapath\n")
554
      lg.info("*** Creating controller\n")
512 555
      self.controller = self.Controller( 'c0', kernel=kernel )
513 556
      self.controllers = [ self.controller ]
514
      print "*** Creating network"
557
      lg.info("*** Creating network\n")
515 558
      self.switches, self.hosts = self.makeNet( self.controller )
516
      print
559
      lg.info("\n")
517 560
      if not kernel:
518
         print "*** Configuring control network"
561
         lg.info("*** Configuring control network\n")
519 562
         self.configureControlNetwork()
520
      print "*** Configuring hosts"
563
      lg.info("*** Configuring hosts\n")
521 564
      self.configHosts()
522 565
   def start( self ):
523
      "Start controller and switches"
524
      print "*** Starting controller"
566
      """Start controller and switches\n"""
567
      lg.info("*** Starting controller\n")
525 568
      for controller in self.controllers:
526 569
         controller.start()
527
      print "*** Starting", len( self.switches ), "switches"
570
      lg.info("*** Starting %s switches" % len(self.switches))
528 571
      for switch in self.switches:
529 572
         switch.start( self.controllers[ 0 ] )
530 573
   def stop( self ):
531
      "Stop the controller(s), switches and hosts"
532
      print "*** Stopping hosts"
574
      """Stop the controller(s), switches and hosts\n"""
575
      lg.info("*** Stopping hosts\n")
533 576
      for host in self.hosts: 
534 577
         host.terminate()
535
      print "*** Stopping switches"
578
      lg.info("*** Stopping switches\n")
536 579
      for switch in self.switches:
537
         print switch.name, ; flush()
580
         lg.info("%s" % switch.name)
538 581
         switch.stop()
539
      print
540
      print "*** Stopping controller"
582
      lg.info("\n")
583
      lg.info("*** Stopping controller\n")
541 584
      for controller in self.controllers:
542 585
         controller.stop();
543
      print
544
      print "*** Test complete"
586
      lg.info("*** Test complete\n")
545 587
   def runTest( self, test ):
546
      "Run a given test, called as test( controllers, switches, hosts)"
588
      """Run a given test, called as test( controllers, switches, hosts)"""
547 589
      return test( self.controllers, self.switches, self.hosts )
548 590
   def run( self, test ):
549 591
      """Perform a complete start/test/stop cycle; test is of the form
550 592
         test( controllers, switches, hosts )"""
551 593
      self.start()
552
      print "*** Running test"
594
      lg.info("*** Running test\n")
553 595
      result = self.runTest( test )
554 596
      self.stop()
555 597
      return result
......
582 624
      snames, hnames, dpnames = defaultNames( snames, hnames, dpnames )
583 625
      if ( depth == 0 ):
584 626
         host = Host( hnames.next() )
585
         print host.name, ; flush()
627
         lg.info("%s " % host.name)
586 628
         return host, [], [ host ]
587 629
      dp = dpnames.next() if self.kernel else None
588 630
      switch = Switch( snames.next(), dp )
589 631
      if not self.kernel: createLink( switch, controller )
590
      print switch.name, ; flush()
632
      lg.info("%s " % switch.name)
591 633
      switches, hosts = [ switch ], []
592 634
      for i in range( 0, fanout ):
593 635
         child, slist, hlist = self.treeNet( controller, 
......
599 641
   def makeNet( self, controller ):
600 642
      root, switches, hosts = self.treeNet( controller,
601 643
         self.depth, self.fanout )
644
      lg.info("\n")
602 645
      return switches, hosts
603 646
   
604 647
# Grid network
......
618 661
      kernel = self.kernel
619 662
      rows = []
620 663
      if not self.linear:
621
         print "*** gridNet: creating", n, "x", m, "grid of switches" ; flush()
664
         lg.info("*** gridNet: creating", n, "x", m, "grid of switches")
622 665
      for y in range( 0, m ):
623 666
         row = []
624 667
         for x in range( 0, n ):
......
627 670
            if not kernel: createLink( switch, controller )
628 671
            row.append( switch )
629 672
            switches += [ switch ]
630
            print switch.name, ; flush()
673
            lg.info("%s " % switch.name)
631 674
         rows += [ row ]
632 675
      # Hook up rows
633 676
      for row in rows:
......
640 683
         createLink( h1, row[ 0 ] )
641 684
         createLink( h2, row[ -1 ] )
642 685
         hosts += [ h1, h2 ]
643
         print h1.name, h2.name, ; flush()
686
         lg.info("%s %s" % (h1.name, h2.name))
644 687
      # Return here if we're using this to make a linear network
645 688
      if self.linear: return switches, hosts
646 689
      # Hook up columns
......
655 698
         createLink( h1, rows[ 0 ][ x ] )
656 699
         createLink( h2, rows[ -1 ][ x ] )
657 700
         hosts += [ h1, h2 ]
658
         print h1.name, h2.name, ; flush()
701
         lg.info("%s %s" % (h1.name, h2.name))
659 702
      return switches, hosts
660 703

  
661 704
class LinearNet( GridNet ):
......
671 714
   r = r'(\d+) packets transmitted, (\d+) received'
672 715
   m = re.search( r, pingOutput )
673 716
   if m == None:
674
      print "*** Error: could not parse ping output:", pingOutput
717
      lg.error("*** Error: could not parse ping output: %s\n" % pingOutput)
675 718
      exit( 1 )
676 719
   sent, received  = int( m.group( 1 ) ), int( m.group( 2 ) )
677 720
   return sent, received
......
680 723
   "Test that each host can reach every other host."
681 724
   packets = 0 ; lost = 0
682 725
   for node in hosts:
683
      if verbose: 
684
         print node.name, "->", ; flush()
726
      if verbose:
727
         lg.info("%s -> " % node.name)
685 728
      for dest in hosts: 
686 729
         if node != dest:
687 730
            result = node.cmd( 'ping -c1 ' + dest.IP() )
688 731
            sent, received = parsePing( result )
689 732
            packets += sent
690 733
            if received > sent:
691
               print "*** Error: received too many packets"
692
               print result
734
               lg.error("*** Error: received too many packets")
735
               lg.error("%s" % result)
693 736
               node.cmdPrint( 'route' )
694 737
               exit( 1 )
695 738
            lost += sent - received
696 739
            if verbose: 
697
               print ( dest.name if received else "X" ), ; flush()
698
      if verbose: print
740
               lg.info(("%s " % dest.name) if received else "X ")
741
      if verbose:
742
          lg.info("\n")
699 743
   ploss = 100 * lost/packets
700 744
   if verbose:
701
      print "%d%% packet loss (%d/%d lost)" % ( ploss, lost, packets )
745
      lg.info("%d%% packet loss (%d/%d lost)\n" % ( ploss, lost, packets ))
702 746
      flush()
703 747
   return ploss
704 748

  
......
718 762
   host1, host2 = hosts[ 0 ], hosts[ 1 ]
719 763
   host1.cmd( 'killall -9 iperf') # XXX shouldn't be global killall
720 764
   server = host1.cmd( 'iperf -s &' )
721
   if verbose: print server ; flush()
765
   if verbose:
766
       lg.info("%s" % server)
722 767
   client = host2.cmd( 'iperf -t 5 -c ' + host1.IP() )
723
   if verbose: print client ; flush()
768
   if verbose:
769
       lg.info("%s" % client)
724 770
   server = host1.cmd( 'kill -9 %iperf' )
725
   if verbose: print server; flush()
771
   if verbose:
772
       lg.info("%s" % server)
726 773
   return [ parseIperf( server ), parseIperf( client ) ]
727 774
   
728 775
def iperfTest( controllers, switches, hosts, verbose=False ):
729 776
   "Simple iperf test between two hosts."
730
   if verbose: print "*** Starting ping test"   
777
   if verbose: 
778
       lg.info("*** Starting ping test\n")
731 779
   h0, hN = hosts[ 0 ], hosts[ -1 ]
732
   print "*** iperfTest: Testing bandwidth between", 
733
   print h0.name, "and", hN.name
780
   lg.info("*** iperfTest: Testing bandwidth between")
781
   lg.info("%s and %s\n" % (h0.name, hN.name))
734 782
   result = iperf( [ h0, hN], verbose )
735
   print "*** result:", result
783
   lg.info("*** result: %s\n" % result)
736 784
   return result
737 785

  
738 786
# Simple CLI
......
752 800
   # Commands
753 801
   def help( self, args ):
754 802
      "Semi-useful help for CLI"
755
      print "Available commands are:", self.cmds
756
      print
757
      print "You may also send a command to a node using:"
758
      print "  <node> command {args}"
759
      print "For example:"
760
      print "  mininet> h0 ifconfig"
761
      print
762
      print "The interpreter automatically substitutes IP addresses"
763
      print "for node names, so commands like"
764
      print "  mininet> h0 ping -c1 h1"
765
      print "should work."
766
      print
767
      print "Interactive commands are not really supported yet,"
768
      print "so please limit commands to ones that do not"
769
      print "require user interaction and will terminate"
770
      print "after a reasonable amount of time."
803
      help_str = "Available commands are:" + str(self.cmds) + "\n" + \
804
                 "You may also send a command to a node using:" + \
805
                 "  <node> command {args}" + \
806
                 "For example:" + \
807
                 "  mininet> h0 ifconfig" + \
808
                 "\n" + \
809
                 "The interpreter automatically substitutes IP addresses" + \
810
                 "for node names, so commands like" + \
811
                 "  mininet> h0 ping -c1 h1" + \
812
                 "should work." + \
813
                 "\n" + \
814
                 "Interactive commands are not really supported yet," + \
815
                 "so please limit commands to ones that do not" + \
816
                 "require user interaction and will terminate" + \
817
                 "after a reasonable amount of time."
818
      print(help_str)
819

  
771 820
   def nodes( self, args ):
772 821
      "List available nodes"
773
      print "available nodes are:", [ node.name for node in self.nodelist]
822
      lg.info("available nodes are:\n", [ node.name for node in self.nodelist])
774 823
   def sh( self, args ):
775 824
      "Run an external shell command"
776 825
      call( [ 'sh', '-c' ] + args )
......
778 827
      pingTest( self.controllers, self.switches, self.hosts, verbose=True )
779 828
   def net( self, args ):
780 829
      for switch in self.switches:
781
         print switch.name, "<->",
830
         lg.info("%s <-> ", switch.name)
782 831
         for intf in switch.intfs:
783 832
            node, remoteIntf = switch.connection[ intf ]
784
            print node.name,
785
         print
833
            lg.info("%s" % node.name)
786 834
   def iperf( self, args ):
787 835
      if len( args ) != 2:
788
         print "usage: iperf <h1> <h2>"
836
         lg.error("usage: iperf <h1> <h2>")
789 837
         return
790 838
      for host in args:
791 839
         if host not in self.nodemap:
792
            print "iperf: cannot find host:", host
840
            lg.error("iperf: cannot find host: %s" % host)
793 841
            return
794 842
      iperf( [ self.nodemap[ h ] for h in args ], verbose=True )
795 843
   # Interpreter
796 844
   def run( self ):
797 845
      "Read and execute commands."
798
      print "*** cli: starting"
846
      lg.info("*** cli: starting")
799 847
      while True:
800
         print "mininet> ", ; flush()
848
         lg.info("mininet> ")
801 849
         input = sys.stdin.readline()
802 850
         if input == '': break
803 851
         if input[ -1 ] == '\n': input = input[ : -1 ]
......
814 862
            rest = ' '.join( rest )
815 863
            # Interactive commands don't work yet, and
816 864
            # there are still issues with control-c
817
            print "***", node.name, ": running", rest
865
            lg.error("*** %s: running %s\n" % (node.name, rest))
818 866
            node.sendCmd( rest )
819 867
            while True:
820 868
               try:
821 869
                  done, data = node.monitor()
822
                  print data,
870
                  lg.info("%s\n" % data)
823 871
                  if done: break
824 872
               except KeyboardInterrupt: node.sendInt()
825
            print
826 873
         elif first == '': pass
827 874
         elif first in [ 'exit', 'quit' ]: break
828 875
         elif first == '?': self.help( rest )
829
         else: print "cli: unknown node or command: <", first, ">"
830
      print "*** cli: exiting"
876
         else:
877
            lg.error("cli: unknown node or command: < %s >\n" % first)
878
      lg.info("*** cli: exiting")
831 879
   
832 880
def fixLimits():
833 881
   "Fix ridiculously small resource limits."
......
847 895
   fixLimits()
848 896

  
849 897
if __name__ == '__main__':
898
   level = logging.INFO
899
   if len(sys.argv) > 1:
900
      level_name = sys.argv[1]
901
      level = LEVELS.get(level_name, level)
902
   setup_logging(level)
903
   #lg.basicConfig(level = level, format = LOG_MSG_FORMAT)
904

  
850 905
   init()
851 906
   results = {}
852
   print "*** Welcome to Mininet!"
853
   print "*** Look in examples/ for more examples\n"
854
   print "*** Testing Mininet with kernel and user datapath"
907
   lg.info("*** Welcome to Mininet!\n")
908
   lg.info("*** Look in examples/ for more examples\n\n")
909
   lg.info("*** Testing Mininet with kernel and user datapath\n")
855 910
   for datapath in [ 'kernel', 'user' ]:
856 911
      k = datapath == 'kernel'
857 912
      network = TreeNet( depth=2, fanout=4, kernel=k)
858 913
      result = network.run( pingTestVerbose )
859 914
      results[ datapath ] = result
860
   print "*** Test results:", results
915
   lg.info("*** Test results: %s\n", results)
916
else:
917
   setup_logging(LOG_LEVEL_DEFAULT)
918
   #lg.basicConfig(level = LOG_LEVEL_DEFAULT, format = LOG_MSG_FORMAT)

Also available in: Unified diff