Beefy Boxes and Bandwidth Generously Provided by pair Networks
Keep It Simple, Stupid
 
PerlMonks  

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; }

Comment on Test::WWW::Selenium webdriver output
Select or Download Code
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:

      $sel->set_browser_log_level('error');

      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!

      UPDATE:

      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?
Username:
Password:

What's my password?
Create A New User
Node Status?
node history
Node Type: perlquestion [id://928109]
Approved by planetscape
help
Chatterbox?
and the web crawler heard nothing...

How do I use this? | Other CB clients
Other Users?
Others browsing the Monastery: (5)
As of 2015-07-28 05:08 GMT
Sections?
Information?
Find Nodes?
Leftovers?
    Voting Booth?

    The top three priorities of my open tasks are (in descending order of likelihood to be worked on) ...









    Results (252 votes), past polls