The Date/Time in the log files do not reflect the actual clock.Now

[goneall]

Description

When running Trivy for a file system, the log file shows the same timestamp for every log record making it difficult to debug performance problems.

Desired Behavior

Log files where every record records the timestamp at the time the log record was created.

Actual Behavior

Same timestamp for every record

Reproduction Steps

1. Run `trivy  fs --debug --scanners license --format spdx-json`
2. View the logfile results

Target

Filesystem

Scanner

License

Output Format

SPDX

Mode

Standalone

Debug Output

Example snippet from a logfile:


2025-02-09T19:06:56Z	DEBUG	[pom] Fetching	url="http://localhost:8081/repository/maven-central/org/opendaylight/yangtools/bnd-parent/14.0.7/bnd-parent-14.0.7.pom"
2025-02-09T19:06:56Z	DEBUG	[pom] Start parent	artifact="org.opendaylight.odlparent:bnd-parent:14.0.5"
2025-02-09T19:06:56Z	DEBUG	[pom] Fetching	url="http://localhost:8081/repository/maven-central/org/opendaylight/odlparent/bnd-parent/14.0.5/bnd-parent-14.0.5.pom"
2025-02-09T19:06:56Z	DEBUG	[pom] Resolving...	group_id="org.opendaylight.yangtools" artifact_id="bnd-parent" version="14.0.7"
2025-02-09T19:06:56Z	DEBUG	[pom] Fetching	url="http://localhost:8081/repository/maven-central/org/opendaylight/yangtools/bnd-parent/14.0.7/bnd-parent-14.0.7.pom"
2025-02-09T19:06:56Z	DEBUG	[pom] Resolving...	group_id="org.opendaylight.yangtools" artifact_id="bnd-parent" version="14.0.7"
2025-02-09T19:06:56Z	DEBUG	[pom] Fetching	url="http://localhost:8081/repository/maven-central/org/opendaylight/yangtools/bnd-parent/14.0.7/bnd-parent-14.0.7.pom"
2025-02-09T19:06:56Z	DEBUG	[pom] Resolving...	group_id="org.opendaylight.yangtools" artifact_id="bnd-parent" version="14.0.7"
2025-02-09T19:06:56Z	DEBUG	[pom] Fetching	url="http://localhost:8081/repository/maven-central/org/opendaylight/yangtools/bnd-parent/14.0.7/bnd-parent-14.0.7.pom"
2025-02-09T19:06:56Z	DEBUG	[pom] Resolving...	group_id="org.opendaylight.yangtools" artifact_id="bnd-parent" version="14.0.7"
2025-02-09T19:06:56Z	DEBUG	[pom] Fetching	url="http://localhost:8081/repository/maven-central/org/opendaylight/yangtools/bnd-parent/14.0.7/bnd-parent-14.0.7.pom"
2025-02-09T19:06:56Z	DEBUG	[pom] Start parent	artifact="org.opendaylight.odlparent:bnd-parent:14.0.5"

Note that the first and last records have the same timestamp.

### Operating System

Ubuntu

### Version

```bash
Development version - commit 5695eb22dfed672eafacb64a71da8e9bdfbaab87

Also able to duplicate on released versions.

Checklist

• Run trivy clean --all
• Read the troubleshooting

[DmitriyLewen]

Hello @goneall
Thanks for your report!

Log files where every record records the timestamp at the time the log record was created.

Looks like you scan small directory and Trivy manages to parse all files in one second.

I scanned my work dir and got a few seconds:

➜  tmp trivy -d fs .       
2025-02-10T12:05:00+06:00	DEBUG	Default config file "file_path=trivy.yaml" not found, using built in values
2025-02-10T12:05:00+06:00	DEBUG	Cache dir	dir="/Users/dmitriy/Library/Caches/trivy"
...
2025-02-10T12:05:00+06:00	DEBUG	[pom] Start parent	artifact="org.apache.httpcomponents:httpcomponents-client:4.5.13"
2025-02-10T12:05:01+06:00	DEBUG	[pom] Start parent	artifact="org.apache.httpcomponents:httpcomponents-parent:11"
2025-02-10T12:05:01+06:00	DEBUG	[pom] Start parent	artifact="org.apache:apache:21"
...
2025-02-10T12:05:01+06:00	DEBUG	[pom] Adding repository	id="sonatype-nexus-snapshots" url="https://oss.sonatype.org/content/repositories/snapshots"
2025-02-10T12:05:01+06:00	DEBUG	[pom] Start parent	artifact="com.fasterxml.jackson:jackson-base:2.12.1"
2025-02-10T12:05:02+06:00	DEBUG	[pom] Start parent	artifact="com.fasterxml.jackson:jackson-parent:2.12"
2025-02-10T12:05:02+06:00	DEBUG	[pom] Start parent	artifact="com.fasterxml:oss-parent:41"
2025-02-10T12:05:02+06:00	DEBUG	[pom] Exit parent	artifact="com.fasterxml:oss-parent:41"
...
2025-02-10T12:05:02+06:00	DEBUG	[pom] Exit parent	artifact="com.google.code.gson:gson-parent:2.10.1"
2025-02-10T12:05:02+06:00	DEBUG	[pom] Start parent	artifact="com.fasterxml.jackson:jackson-bom:2.16.0"
2025-02-10T12:05:02+06:00	DEBUG	[pom] Start parent	artifact="com.google.errorprone:error_prone_parent:2.11.0"
2025-02-10T12:05:03+06:00	DEBUG	[pom] Start parent	artifact="com.fasterxml.jackson:jackson-bom:2.15.1"
2025-02-10T12:05:03+06:00	DEBUG	[pom] Failed to fetch	url="https://repo.maven.apache.org/maven2/sb_http-client/sb_http-client/4.5.14/sb_http-client-4.5.14.pom" statusCode=404
...
2025-02-10T12:05:07+06:00	DEBUG	[pom] Start parent	artifact="com.fasterxml.jackson.module:jackson-modules-java8:2.15.1"
2025-02-10T12:05:07+06:00	DEBUG	[pom] Adding repository	id="sonatype-nexus-snapshots" url="https://oss.sonatype.org/content/repositories/snapshots"
...

[goneall]

Hi @DmitriyLewen - Thanks for the quick response.

The scan took about 7 minutes and the start and end times were identical.

I also was watching the log real-time and there were several seconds between logs, and they all had identical times.

I was looking through the code to see where the time was generated, and I found the following.

I was trying to figure out where the time is logged - I'm not very familiar with GoLang logging - but this looked somewhat suspicious:

trivy/pkg/log/handler.go

Line 150 in 02ebb4c

// For tests, use the fake clock's time.

[DmitriyLewen]

We use this feature for testing only.

Can you provide a repo to reproduce this case?

[goneall]

I just looked at a much larger scan, and it does show different times. It doesn't line up with what I'm seeing in real-time watching the logs, but it definitely shows different times.

I think we can close this as my misunderstanding.

[goneall]

Did a bit more experimenting, it looks like the logger pauses printing out the lines at times, but the timing is probably correct - so this was indeed my misunderstanding. I'll go ahead and close it.

[goneall]

My misunderstanding on the logging mechanics - closing this as no longer relevant.