Homogenize timestamps in log files

[lukeis]

Originally reported on Google Code with ID 4950

Hello,

Selenium can produce lots of information in different places. Unfortunately, it's not
always easy to cross-check events in log files since they are not using the same timestamp
format. For example, the '-log' command line parameter will produce a log file like
this:

16:41:09.020 WARN [11] org.openqa.grid.internal.BaseRemoteProxy - session ext. key
b1170a6a-e31d-493b-b9cc-7efd5318d830 has TIMED OUT due to client inactivity and will
be released.
16:41:09.147 WARN [11] org.openqa.grid.selenium.proxy.DefaultRemoteProxy - Error releasing
the resources on timeout for session ext. key b1170a6a-e31d-493b-b9cc-7efd5318d830

This format unfortunately does not contain the date itself, but just the time a message
was logged. This is the same for the standard output stream:

adding browserName=firefox,maxInstances=3,platform=UNIX
16:34:53.936 INFO - using the json request : {"class":"org.openqa.grid.common.RegistrationRequest","capabilities":[{"platform":"UNIX","browserName":"firefox","maxInstances":"3"}],"configuration":{"port":XXXX,"host":"XXX.XXX.XXX.XXX","hubHost":"localhost","registerCycle":60000,"hub":"http://localhost:XXXX/grid/register","log":"/var/log/selenium/node.debug.log","url":"http://XXX.XXX.XXX.XXX:XXXX","remoteHost":"http://XXX.XXX.XXX.XXX:XXXX","register":true,"nodePolling":60000,"proxy":"org.openqa.grid.selenium.proxy.DefaultRemoteProxy","maxSession":5,"browser":"browserName=firefox,maxInstances=3,platform=UNIX","role":"webdriver","hubPort":XXXX}}
16:34:53.947 INFO - starting auto register thread. Will try to register every 60000
ms.
16:34:53.950 INFO - Registering the node to hub :http://localhost:XXXX/grid/register
16:35:40.145 INFO - Executing: [new session: {platform=ANY, firefox_profile_name=Selenium,
browserName=firefox}] at URL: /session)
16:35:54.061 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@5abd09e8
at URL: /status)

The standard error stream seems to have another format:

Dec 27, 2012 4:33:15 PM org.openqa.grid.selenium.GridLauncher main
INFO: Launching a selenium grid server
2012-12-27 16:33:36.018:INFO:osjs.Server:jetty-7.x.y-SNAPSHOT
2012-12-27 16:33:36.117:INFO:osjsh.ContextHandler:started o.s.j.s.ServletContextHandler{/,null}
2012-12-27 16:33:36.137:INFO:osjs.AbstractConnector:Started SocketConnector@0.0.0.0:XXXX

In this example, the last 3 lines begins with a timestamp which has the right format
(i.e. a date and a time). However, the first line has a completely different timestamp
format (i.e. 'Dec 27, 2012 4:33:15 PM').

Note the following could show up in the standard error stream when launching a grid
node:

Dec 27, 2012 4:33:15 PM org.openqa.grid.selenium.GridLauncher main
INFO: Launching a selenium grid node
16:47:57.445 WARN - Exception thrown
org.openqa.selenium.NoSuchElementException: Unable to locate element: {"method":"css
selector","selector":".highslide-body"}
Command duration or timeout: 635 milliseconds
For documentation on this error, please visit: http://seleniumhq.org/exceptions/no_such_element.html

As you can see, we have here again a timestamp with only the time (on the third line).

Not sure if this is feasible, but the 'webdriver.firefox.logfile' option currently
instructs the FirefoxDriver to redirect the output to a file without any timestamp
at all:

Xlib:  extension "RANDR" missing on display ":99.0".
*** LOG addons.xpi: startup
*** LOG addons.xpi: checkForChanges
*** LOG addons.xpi: No changes found

(firefox-bin:22713): GLib-GObject-WARNING **: /scratch/build-area/glib2.0-2.24.2/gobject/gsignal.c:1149:
unable to lookup signal "text-insert" for non instantiatable type `AtkText'

It would be great to have full timestamp in that file too.

Note this issue is probably related to issue #3103 (Clarify Java logging).

Reported by simpleentrepreneur on 2012-12-27 16:30:22

[lukeis]

It is hardly possible to homogenize timestamps without revising logging as the whole
because log messages format is defined by a logging framework, not selenium.

Reported by barancev on 2013-01-20 18:49:45

• Status changed: Duplicate
• Labels removed: Status-Untriaged
• Merged into: #3103

[lukeis]

Reported by luke.semerau on 2015-09-17 18:16:31

• Labels added: Restrict-AddIssueComment-Commit