Fix log timestamp in forwarder-vpp for [cmd:vpp] printouts

[ljkiraly]

Expected Behavior

The timestamp should show the time when the given event has happened.

Current Behavior

Any log printout line tagged by [cmd:vpp] have the same timestamp.

Failure Information (for bugs)

In vpphelper the Stdout and Stderr for vpp are set to be log.Entry(ctx).Writer(). The timestamp will get a value at this initialization and remains the same. So maybe the logrus callback behave strangely.

Steps to Reproduce

Context

Failure Logs

Log extract:

Mar  8 08:45:00.552ESC[36m [INFO] [cmd:/bin/forwarder] ESC[0mlocal vpp is being used
Mar  8 08:45:00.552ESC[36m [INFO] [cmd:/bin/forwarder] [duration:435.38µs] ESC[0mcompleted phase 2: run vpp and get a connection to it
...
Mar  8 08:45:00.573ESC[37m [DEBU] ESC[0m/var/run/vpp/api.sock was created after 20.81241ms
Mar  8 08:45:00.552ESC[36m [INFO] [cmd:vpp] ESC[0mvpp[42]: buffer: numa[0] falling back to non-hugepage backed buffer pool 
...
Mar  8 08:45:00.552ESC[36m [INFO] [cmd:vpp] ESC[0mvpp[42]: vat-plug/load: vat_plugin_register: oddbuf plugin not loaded...
Mar  8 08:45:01.355ESC[37m [DEBU] ESC[0msuccessfully connected to /var/run/vpp/api.sock after 781.711316ms and 680 attempts
...
Mar  8 08:45:32.613ESC[37m [TRAC] [id:ed6bf227-b854-4994-80e2-bc18ad31417e] [type:networkService] ESC[0m(51)                                                   ⎆ sdk-vpp/pkg/networkservice/up/upClient.Req
uest()
Mar  8 08:45:00.552ESC[36m [INFO] [cmd:vpp] ESC[0mvpp[42]: vl_api_want_interface_events_t_handler:1635: pid 34: already enabled...
Mar  8 08:45:32.614ESC[37m [TRAC] [id:ed6bf227-b854-4994-80e2-bc18ad31417e] [type:networkService] ESC[0m(52)                                                    ⎆ sdk-vpp/pkg/networkservice/connectioncontext/mtu/mtuClient.Request()
...
Mar  8 09:27:24.968ESC[37m [TRAC] [id:ed6bf227-b854-4994-80e2-bc18ad31417e] [type:networkService] ESC[0m(28)                            ⎆ sdk-vpp/pkg/networkservice/mechanisms/kernel/kerneltap/kernelTapS
erver.Close()
Mar  8 08:45:00.552ESC[36m [INFO] [cmd:vpp] ESC[0mvpp[42]: capo_sw_interface_add_del:103: unconfiguring policies for if 5 deleted

[d-uzlov]

The time is burned into the logger here:
https://github.com/edwarnicke/vpphelper/blob/3e6797de32c36a2eac2ac30e0932d04dc796fc6d/start.go#L58
The Entry function either creates a new logger with static time:
https://github.com/edwarnicke/log/blob/ff71e47b16bd1e8dba3101543203e628b02d70d0/context.go#L60
Or pulls the logger from the context.
But the only way to put the logger into context uses the same function that sets the static time for the logger:
https://github.com/edwarnicke/log/blob/ff71e47b16bd1e8dba3101543203e628b02d70d0/context.go#L32-L34
And there is not way change parameters of the logger in the context.

I'm not sure what would be a better fix here.

1. Patch log library
   I don't know why we set a static time when creating a logger. I think it may be a good idea to avoid setting the static time.

2. Patch vpphelper library
   If it turns out that we really do need to use a static time there for some other use cases, then we need to patch the StartAndDialContext function to use a logger without static time.

I don't think there is any way to fix it without touching the code of these libraries.

[denis-tingaikin]

@ljkiraly Should be fixed in v1.9.0

Could you please check?

[ljkiraly]

Works fine. Closing now.
Thank you!