Add timestamp to debug log

[uchagani]

I've requested a similar feature before but now I'm asking for timestamps to be added to at least the debug logs.

I've trying to isolate a problem with bringing up machines and have isolated a port forwarding issue. However I can't isolate to a single place in the log file because it everything is going by so fast. I'd like to be able to compare timestamps from when I see the error and what is happening in the logs.

[sethvargo]

@uchagani how would having timestamps help solve this issue? Maybe I am misunderstanding, but the logs should be sequential.

[uchagani]

I'm using vagrant as part of a CI Build/Deploy/Test cycle. I am noticing a strange behavior in one of the apps I am testing where, when another vagrant box is spun up, the port-forwarding of the new box, causes a network glitch in boxes that are already spun up.

I'm trying to narrow down where in the vagrant log this is happening. I already have timestamps from my app regarding the crash and i wanted to line that up with the vagrant log to see what exactly in vagrant is causing the problem.

[philippe-granet]

Add this at start of your Vagrantfile, it helps me:

$out_file = File.new('debug.log', 'w')
def $stdout.write string
    log_datas=string
    if log_datas.gsub(/\r?\n/, "") != ''
        log_datas=::Time.now.strftime("%d/%m/%Y %T")+" "+log_datas.gsub(/\r\n/, "\n")
    end
    super log_datas
    $out_file.write log_datas
    $out_file.flush
end
def $stderr.write string
    log_datas=string
    if log_datas.gsub(/\r?\n/, "") != ''
        log_datas=::Time.now.strftime("%d/%m/%Y %T")+" "+log_datas.gsub(/\r\n/, "\n")
    end
    super log_datas
    $out_file.write log_datas
    $out_file.flush
end

It gives me (console + debug.log) :

24/10/2015 13:37:50 ==> default: Attempting graceful shutdown of VM...
24/10/2015 13:38:11 ==> default: Checking if box 'ubuntu/trusty64' is up to date...
24/10/2015 13:38:13 ==> default: Clearing any previously set forwarded ports...
24/10/2015 13:38:16 ==> default: Clearing any previously set network interfaces...
24/10/2015 13:38:17 ==> default: Preparing network interfaces based on configuration...
24/10/2015 13:38:17     default: Adapter 1: nat
24/10/2015 13:38:17 ==> default: Forwarding ports...
24/10/2015 13:38:17     default: 9991 => 9993 (adapter 1)
24/10/2015 13:38:17     default: 22 => 2222 (adapter 1)
24/10/2015 13:38:17 ==> default: Running 'pre-boot' VM customizations...
24/10/2015 13:38:17 ==> default: Booting VM...
24/10/2015 13:38:21 ==> default: Waiting for machine to boot. This may take a few minutes...
24/10/2015 13:38:21     default: SSH address: 127.0.0.1:2222
24/10/2015 13:38:21     default: SSH username: vagrant
24/10/2015 13:38:21     default: SSH auth method: private key
24/10/2015 13:38:28     default: Warning: Remote connection disconnect. Retrying...
24/10/2015 13:38:40 ==> default: Machine booted and ready!

[mcandre]

Solid feature idea, maybe submit a PR?

[philippe-granet]

See PR #9175

[gustavomcarmo]

Great @philippe-granet !!!

I've just improved your solution placing the code in a different file called timestamp-logger.rb and adding just one line of code at the start of my Vagrantfile: load 'timestamp-logger.rb'

[philippe-granet]

A PR has been merged : #9269

[briancain]

I'm going to go ahead and close this now that #9269 has been merged. Thanks!

[hashibot]

I'm going to lock this issue because it has been closed for 30 days ⏳. This helps our maintainers find and focus on the active issues.

If you have found a problem that seems similar to this, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.