Beefy Boxes and Bandwidth Generously Provided by pair Networks
Just another Perl shrine

Test::WWW::Selenium webdriver output

by technojosh (Priest)
on Sep 27, 2011 at 15:57 UTC ( #928109=perlquestion: print w/replies, xml ) Need Help??
technojosh has asked for the wisdom of the Perl Monks concerning the following question:

I am suspicious that this will end up being a Selenium question, not a Perl question...

My problem is: when I run my Perl code, that uses the Test::WWW::Selenium module, I get two different flavors of output. It is just random, I'll run the code once and get output like:

Note in the examples below, they have the same "start" and "end" points, but the second is much more verbose
Grabbing values from screen... ok 302 - highlight, id=Code ok 303 - highlight, id=Employee_Period_StartDate ok 304 - highlight, id=Employee_Period_EndDate ok 305 - highlight, id=Period_StartDate ok 306 - highlight, id=Period_EndDate ok 307 - highlight, id=Note $VAR1 = { 'NOTE' => '', 'START' => '9/1/2009 12:00:00 AM', 'COMEND' => '', 'COMSTART' => '9/22/2011', 'END' => '', 'REP' => 'RS01' }; ok 308 - open, /scs/Rep/ ok 309 - wait_for_page_to_load, 30000 1..309

Then I'll run it immediately again, and get output like:

Grabbing values from screen... 09:43:31.491 INFO - Command request: highlight[id=Code, ] on session 7 +a5eadabd33643b79f9de1f227547a18 09:43:31.554 INFO - Got result: OK on session 7a5eadabd33643b79f9de1f2 +27547a18 ok 302 - highlight, id=Code 09:43:31.554 INFO - Command request: getValue[id=Code, ] on session 7a +5eadabd33643b79f9de1f227547a18 09:43:31.632 INFO - Got result: OK,RS01 on session 7a5eadabd33643b79f9 +de1f227547a18 09:43:31.632 INFO - Command request: highlight[id=Employee_Period_Star +tDate, ] on session 7a5eadabd33643b79f9de1f227547a18 09:43:31.710 INFO - Got result: OK on session 7a5eadabd33643b79f9de1f2 +27547a18 ok 303 - highlight, id=Employee_Period_StartDate 09:43:31.710 INFO - Command request: getValue[id=Employee_Period_Start +Date, ] on session 7a5eadabd33643b79f9de1f227547a18 09:43:31.788 INFO - Got result: OK,9/1/2009 12:00:00 AM on session 7a5 +eadabd33643b79f9de1f227547a18 09:43:31.788 INFO - Command request: highlight[id=Employee_Period_EndD +ate, ] on session 7a5eadabd33643b79f9de1f227547a18 09:43:31.835 INFO - Got result: OK on session 7a5eadabd33643b79f9de1f2 +27547a18 ok 304 - highlight, id=Employee_Period_EndDate 09:43:31.835 INFO - Command request: getValue[id=Employee_Period_EndDa +te, ] on session 7a5eadabd33643b79f9de1f227547a18 09:43:31.882 INFO - Got result: OK, on session 7a5eadabd33643b79f9de1f +227547a18 09:43:31.897 INFO - Command request: highlight[id=Period_StartDate, ] +on session 7a5eadabd33643b79f9de1f227547a18 09:43:31.976 INFO - Got result: OK on session 7a5eadabd33643b79f9de1f2 +27547a18 ok 305 - highlight, id=Period_StartDate 09:43:31.991 INFO - Command request: getValue[id=Period_StartDate, ] o +n session 7a5eadabd33643b79f9de1f227547a18 09:43:32.054 INFO - Got result: OK,9/22/2011 on session 7a5eadabd33643 +b79f9de1f227547a18 09:43:32.054 INFO - Command request: highlight[id=Period_EndDate, ] on + session 7a5eadabd33643b79f9de1f227547a18 09:43:32.116 INFO - Got result: OK on session 7a5eadabd33643b79f9de1f2 +27547a18 ok 306 - highlight, id=Period_EndDate 09:43:32.132 INFO - Command request: getValue[id=Period_EndDate, ] on +session 7a5eadabd33643b79f9de1f227547a18 09:43:32.194 INFO - Got result: OK, on session 7a5eadabd33643b79f9de1f +227547a18 09:43:32.194 INFO - Command request: highlight[id=Note, ] on session 7 +a5eadabd33643b79f9de1f227547a18 09:43:32.241 INFO - Got result: OK on session 7a5eadabd33643b79f9de1f2 +27547a18 ok 307 - highlight, id=Note 09:43:32.241 INFO - Command request: getValue[id=Note, ] on session 7a +5eadabd33643b79f9de1f227547a18 09:43:32.288 INFO - Got result: OK, on session 7a5eadabd33643b79f9de1f +227547a18 $VAR1 = { 'NOTE' => '', 'START' => '9/1/2009 12:00:00 AM', 'COMEND' => '', 'COMSTART' => '9/22/2011', 'END' => '', 'REP' => 'RS01' }; 09:43:34.288 INFO - Command request: open[/scs/Rep/, ] on session 7a5e +adabd33643b79f9de1f227547a18 09:43:35.303 INFO - Got result: OK on session 7a5eadabd33643b79f9de1f2 +27547a18 ok 308 - open, /scs/Rep/ 09:43:35.303 INFO - Command request: waitForPageToLoad[30000, ] on ses +sion 7a5eadabd33643b79f9de1f227547a18 09:43:35.366 INFO - Got result: OK on session 7a5eadabd33643b79f9de1f2 +27547a18 ok 309 - wait_for_page_to_load, 30000 09:43:35.366 INFO - Command request: testComplete[, ] on session 7a5ea +dabd33643b79f9de1f227547a18 09:43:35.694 INFO - Got result: OK on session 7a5eadabd33643b79f9de1f2 +27547a18 09:43:35.694 INFO - Command request: shutDownSeleniumServer[, ] on ses +sion null 09:43:35.694 INFO - Shutdown command received 09:43:35.694 INFO - Got result: OK on session null 09:43:35.694 INFO - initiating shutdown 1..309

I would really like to be able to get the "1st" kind of output, every time. It is much cleaner, and I can see the tests and their outcomes without treading through tons of "info" lines. Obviously I could write an easy wrapper for this to parse out the "info" lines, but I don't think "code running and parsing test code's output" is a very elegant solution. The test code is "working perfectly" in that it runs my tests and reports the results accurately. I just want the cleaner variety of output. Any help is greatly appreciated!

Here is a simple Test::WWW::Selenium script of mine that has the issue. (all of my selenium code does this...)
#!C:/Perl/bin/perl.exe use strict; use warnings; use Time::HiRes qw(sleep); use Test::WWW::Selenium; use Test::More "no_plan"; use Test::Exception; use lib 'C:/Scripts/module'; use SeleniumSDK; my $sdk = SeleniumSDK->new(); # Get arguments # Process args from command line my $url = $ARGV[0] || 'http://testserver/scs/'; my $browser = $ARGV[1] || "*iexplore"; if ($ARGV[0] eq '?' || $ARGV[0] eq 'help') { print "\nUsage: Please enter a URL to test!\n"; exit; } my $sel = $sdk->StartSelenium( $browser, $url ); $sel->open_ok("/scs"); $sel->window_maximize(); # TEST CODE GOES HERE $sel->click_ok("link=Sales Reps"); $sel->wait_for_page_to_load_ok("30000"); # parse source my @source = split(/\n/, $sel->get_html_source()); # REP LINKS my @repUrl = (); print "\nREP LINKS:\n\n"; sleep(1); foreach my $s ( @source ) { chomp $s; next unless $s =~ /href/; next unless $s =~ /Rep\/Edit/; my $href = substr( $s, index($s,'href=')+6, index($s,'">Edit') - (index($s,'href=')+6) ); print "** ".$href."\n"; push(@repUrl, $href); } use Data::Dumper; my %Rep = (); my $c = 0; foreach my $url ( @repUrl ) { $sel->open_ok($url); print "\nGrabbing values from screen...\n"; # Get values and add to hash $sel->highlight_ok('id=Code'); $Rep{$c}->{REP} = $sel->get_value('id=Code'); $sel->highlight_ok('id=Employee_Period_StartDate'); $Rep{$c}->{START} = $sel->get_value('id=Employee_Period_StartDate' +); $sel->highlight_ok('id=Employee_Period_EndDate'); $Rep{$c}->{END} = $sel->get_value('id=Employee_Period_EndDate'); $sel->highlight_ok('id=Period_StartDate'); $Rep{$c}->{COMSTART} = $sel->get_value('id=Period_StartDate'); $sel->highlight_ok('id=Period_EndDate'); $Rep{$c}->{COMEND} = $sel->get_value('id=Period_EndDate'); $sel->highlight_ok('id=Note'); $Rep{$c}->{NOTE} = $sel->get_value('id=Note'); sleep(1); print Dumper($Rep{$c}); sleep(1); $sel->open_ok("/scs/Rep/"); $sel->wait_for_page_to_load_ok("30000"); $c++; } # END TEST CODE $sdk->KillSelenium($sel);

The 'SeleniumSDK' module is referenced above, and since I think the way I spawn my webdriver might be part of my issue, below are the relevant methods from that module:

sub StartSelenium { my ($self, $browser, $site) = @_; system( 1, "java", "-jar", $self->{_Selenium} ); my $sel = Test::WWW::Selenium->new( host => 'localhost', port => 4444, browser => $browser, browser_url => $site ); $sel->start(); return $sel; } sub KillSelenium { my ($self, $sel) = @_; $sel->stop(); $sel->do_command('shutDownSeleniumServer'); return 1; }

Replies are listed 'Best First'.
Re: Test::WWW::Selenium webdriver output
by onelesd (Pilgrim) on Sep 28, 2011 at 00:27 UTC

    Selenium supports setting the log level in the GUI; set the log level to 'Error'. You can probably set it via your script as well, try Google-ing it.

      Thats it. Searching the api I found:


      It must be called after a page has been opened. I'm still curious why, without explicitly setting this, you get different "log level" behaviors. No matter, my question is answered!


      I was barking up the wrong tree entirely, and my solution is a Perl solution :) The 'set_browser_log_level' method is not the one I wanted, it only concerns the UI and I run mostly on the command line or some flavor of a console. No no, the selenium webdriver, the .jar file you must launch to run a selenium test is my culprit.
      I was starting the webdriver with a system call in my code. This would show output from the webdriver right along with the output from my test code. By spawning a secondary process under a separate (possibly hidden) console, I can keep the output I want and divert the "INFO" stuff from the selenium webdriver to a secondary place (or ideally, I'll just find a way to suppress it altogether.. any help there would still be appreciated!)

Log In?

What's my password?
Create A New User
Node Status?
node history
Node Type: perlquestion [id://928109]
Approved by planetscape
and all is quiet...

How do I use this? | Other CB clients
Other Users?
Others cooling their heels in the Monastery: (2)
As of 2017-02-20 23:12 GMT
Find Nodes?
    Voting Booth?
    Before electricity was invented, what was the Electric Eel called?

    Results (304 votes). Check out past polls.